[pgcluster: 938] リカバリスタート時のエラーおよび複数回クエリ実行の件
Yoshitake Shinohara
yoshi ＠ yyn.jp
2006年 11月 6日 (月) 05:37:08 JST
おはようございます。
篠原と申します。
現在、pgcluster-1.5.0rc9を試用しております。
次の2点の問題が発生しておりますので、設定等問題のある箇所がございましたら
御教授願います。
なお、今回ロードバランサは使用しておりません。
1.リカバリスタート時に次のエラーが吐き出される。
Master ClusterDB
> ERROR: storage sync failed on magnetic disk: Success
Replicator Debug Log
> 2006-11-06 14:08:12 [3247] ERROR:read_packet():unexpected EOF
> 2006-11-06 14:08:12 [3247] DEBUG:pgrecovery_loop():receive packet no:8
> 2006-11-06 14:08:12 [3247] ERROR:pgrecovery_loop():unknown packet.
abort to parse
2.クラスタDBよりクエリを発行すると、一つのクエリが複数実行される。
> template1=# select * from test;
> no | date
> ----+------
> (0 rows)
>
> template1=# insert into test (date) values (now());
> INSERT 0 1
> template1=# select * from test;
> no | date
> ----+----------------------------
> 3 | 2006-11-06 14:09:44.647606
> 4 | 2006-11-06 14:09:44.647606
> (2 rows)
サーバ構成は次のとおりです。
Host:rep01.traction.jp
Culster Recive Port:5432
Culster Recovery Port:7001
Replication Recive Port:8001
Replication Recovery Port:8101
Host:rep02.traction.jp
Culster Recive Port:5432
Culster Recovery Port:7001
Host:rep03.traction.jp
Culster Recive Port:5432
Culster Recovery Port:7001
設定ファイル
rep01:/usr/local/pgsql/etc/pgreplicate.conf
<Cluster_Server_Info>
<Host_Name> rep03.traction.jp </Host_Name>
<Port> 5432 </Port>
<Recovery_Port> 7001 </Recovery_Port>
</Cluster_Server_Info>
<Cluster_Server_Info>
<Host_Name> rep02.traction.jp </Host_Name>
<Port> 5432 </Port>
<Recovery_Port> 7001 </Recovery_Port>
</Cluster_Server_Info>
<Cluster_Server_Info>
<Host_Name> rep01.traction.jp </Host_Name>
<Port> 5432 </Port>
<Recovery_Port> 7001 </Recovery_Port>
</Cluster_Server_Info>
<Host_Name> rep01.traction.jp </Host_Name>
<Replication_Port> 8001 </Replication_Port>
<Recovery_Port> 8101 </Recovery_Port>
<RLOG_Port> 8301 </RLOG_Port>
<Response_Mode> normal </Response_Mode>
<Use_Replication_Log> yes </Use_Replication_Log>
rep01:/usr/local/pgsql/data/cluster.conf
rep02:/usr/local/pgsql/data/cluster.conf
rep03:/usr/local/pgsql/data/cluster.conf
<Replicate_Server_Info>
<Host_Name> rep01.traction.jp </Host_Name>
<Port> 8001 </Port>
<Recovery_Port> 8101 </Recovery_Port>
</Replicate_Server_Info>
<Recovery_Port> 7001 </Recovery_Port>
<Rsync_Path> /usr/bin/rsync </Rsync_Path>
<Rsync_Option> ssh -2 </Rsync_Option>
<Rsync_Compress> yes </Rsync_Compress>
<Pg_Dump_Path> /usr/local/pgsql/bin/pg_dump </Pg_Dump_Path>
<When_Stand_Alone> read_only </When_Stand_Alone>
起動順
rep01:/usr/local/pgsql/bin/pgreplicate -D /usr/local/pgsql/etc/ -vn
rep03:/usr/local/pgsql/bin/pg_ctl -D /usr/local/pgsql/data -o "-i" start
rep02:/usr/local/pgsql/bin/pg_ctl -D /usr/local/pgsql/data -o "-i -R" start
rep01:/usr/local/pgsql/bin/pg_ctl -D /usr/local/pgsql/data -o "-i -R" start
マスタDBログ
postgres ＠ rep03:/usr/local/pgsql/data$ /usr/local/pgsql/bin/pg_ctl -D
/usr/local/pgsql/data -o "-i" start
postmaster starting
LOG: database system was shut down at 2006-11-06 13:58:06 JST
LOG: checkpoint record is at 0/3EB270
LOG: redo record is at 0/3EB270; undo record is at 0/0; shutdown TRUE
LOG: next transaction ID: 1607; next OID: 16391
LOG: next MultiXactId: 1; next MultiXactOffset: 0
LOG: database system is ready
LOG: transaction ID wrap limit is 1073743374, limited by database "template1"
ERROR: storage sync failed on magnetic disk: Success
LOG: transaction ID wrap limit is 1073743442, limited by database "template1"
LOG: transaction ID wrap limit is 1073743442, limited by database "template1"
ERROR: storage sync failed on magnetic disk: Success
LOG: transaction ID wrap limit is 1073743502, limited by database "template1"
LOG: transaction ID wrap limit is 1073743502, limited by database "template1"
ERROR: storage sync failed on magnetic disk: Success
LOG: transaction ID wrap limit is 1073743562, limited by database "template1"
LOG: transaction ID wrap limit is 1073743562, limited by database "template1"
ERROR: storage sync failed on magnetic disk: Success
LOG: transaction ID wrap limit is 1073743622, limited by database "template1"
LOG: transaction ID wrap limit is 1073743622, limited by database "template1"
レプリケータログ
2006-11-06 13:57:48 [3245] DEBUG:PGR_Get_Conf_Data ok
2006-11-06 13:57:48 [3245] DEBUG:LoadBalanceTbl allocate ok
2006-11-06 13:57:48 [3245] DEBUG:PGRget_Conf_Data():CascadeTbl shmget ok
2006-11-06 13:57:48 [3245] DEBUG:PGRget_Conf_Data():CascadeTbl shmat ok
2006-11-06 13:57:48 [3245] DEBUG:PGRget_Conf_Data():CascadeInf shmget ok
2006-11-06 13:57:48 [3245] DEBUG:PGRget_Conf_Data():CascadeInf shmat ok
2006-11-06 13:57:48 [3245] DEBUG:PGRget_Conf_Data():CommitLog shmget ok
2006-11-06 13:57:48 [3245] DEBUG:PGRget_Conf_Data():Commit_Log_Tbl shmat ok
2006-11-06 13:57:48 [3245] DEBUG:PGRget_Conf_Data():RLog Memory Allocation ok
2006-11-06 13:57:48 [3245] DEBUG:registering
(key,value)=(Host_Name,rep03.traction.jp)
2006-11-06 13:57:48 [3245] DEBUG:registering hostname rep03.traction.jp
2006-11-06 13:57:48 [3245] DEBUG:resolved name is 10.0.10.102
2006-11-06 13:57:48 [3245] DEBUG:registering (key,value)=(Port,5432)
2006-11-06 13:57:48 [3245] DEBUG:registering (key,value)=(Recovery_Port,7001)
2006-11-06 13:57:48 [3245] DEBUG:registering
(key,value)=(Host_Name,rep02.traction.jp)
2006-11-06 13:57:48 [3245] DEBUG:registering hostname rep02.traction.jp
2006-11-06 13:57:48 [3245] DEBUG:resolved name is 10.0.10.101
2006-11-06 13:57:48 [3245] DEBUG:registering (key,value)=(Port,5432)
2006-11-06 13:57:48 [3245] DEBUG:registering (key,value)=(Recovery_Port,7001)
2006-11-06 13:57:48 [3245] DEBUG:registering
(key,value)=(Host_Name,rep01.traction.jp)
2006-11-06 13:57:48 [3245] DEBUG:registering hostname rep01.traction.jp
2006-11-06 13:57:48 [3245] DEBUG:resolved name is 10.0.10.100
2006-11-06 13:57:48 [3245] DEBUG:registering (key,value)=(Port,5432)
2006-11-06 13:57:48 [3245] DEBUG:registering (key,value)=(Recovery_Port,7001)
2006-11-06 13:57:48 [3245] DEBUG:registering
(key,value)=(Host_Name,rep01.traction.jp)
2006-11-06 13:57:48 [3245] DEBUG:registering (key,value)=(Replication_Port,8001)
2006-11-06 13:57:48 [3245] DEBUG:registering (key,value)=(Recovery_Port,8101)
2006-11-06 13:57:48 [3245] DEBUG:registering (key,value)=(RLOG_Port,8301)
2006-11-06 13:57:48 [3245] DEBUG:registering (key,value)=(Response_Mode,normal)
2006-11-06 13:57:48 [3245] DEBUG:registering
(key,value)=(Use_Replication_Log,yes)
2006-11-06 13:57:48 [3245] DEBUG:PGRget_Conf_Data():HostTbl shmget ok
2006-11-06 13:57:48 [3245] DEBUG:PGRget_Conf_Data():HostTbl shmat ok
2006-11-06 13:57:48 [3245] DEBUG:Use Replication Log. Start PGR_RLog_Main()
addr.sun_path[/usr/local/pgsql/etc//.s.PGRLOG.8301]
Replicateion_Log->RLog_Sock_Path[/usr/local/pgsql/etc//.s.PGRLOG.8301]
2006-11-06 13:57:48 [3247] DEBUG:PGRrecovery_main():PGRrecovery_main
bind port 8101
2006-11-06 13:57:48 [3245] DEBUG:replicate_main():entering replicate_main
2006-11-06 13:57:48 [3245] DEBUG:replicate_main() 8001 port bind OK
2006-11-06 13:57:48 [3245] DEBUG:cmdSts=N
2006-11-06 13:57:48 [3245] DEBUG:rlog=0
2006-11-06 13:57:48 [3245] DEBUG:port=0
2006-11-06 13:57:48 [3245] DEBUG:pid=0
2006-11-06 13:57:48 [3245] DEBUG:from_host=10.0.10.100
2006-11-06 13:57:48 [3245] DEBUG:dbName=template1
2006-11-06 13:57:48 [3245] DEBUG:userName=postgres
2006-11-06 13:57:48 [3245] DEBUG:recieve sec=0
2006-11-06 13:57:48 [3245] DEBUG:recieve usec=0
2006-11-06 13:57:48 [3245] DEBUG:query_size=61
2006-11-06 13:57:48 [3245] DEBUG:request_id=0
2006-11-06 13:57:48 [3245] DEBUG:replicate_id=0
2006-11-06 13:57:48 [3245] DEBUG:recovery_status=0
2006-11-06 13:57:48 [3245] DEBUG:query=SELECT
PGR_SYSTEM_COMMAND_FUNCTION(1,'10.0.10.100',8001,8101)
2006-11-06 13:57:48 [3245] DEBUG:PGRis_same_host():not same host
2006-11-06 13:57:48 [3245] DEBUG:pgr_createConn():PQsetdbLogin
host[10.0.10.102] port[5432] db[template1] user[postgres]
2006-11-06 13:57:48 [3245] DEBUG:pgr_createConn():Retry. h_errno is
1,reason is 'FATAL: the database system is shutting down
'
2006-11-06 13:57:48 [3245] DEBUG:pgr_createConn():Retry. h_errno is
1,reason is 'FATAL: the database system is shutting down
'
2006-11-06 13:57:48 [3245] DEBUG:pgr_createConn():Retry. h_errno is
1,reason is 'FATAL: the database system is shutting down
'
2006-11-06 13:57:48 [3245] DEBUG:pgr_createConn():Retry. h_errno is
1,reason is 'FATAL: the database system is shutting down
'
2006-11-06 13:57:48 [3245] DEBUG:setTransactionTbl(): 5432 ＠ 10.0.10.102
is not ready
2006-11-06 13:57:48 [3245]
DEBUG:replicate_packet_send_internal():setTransactionTbl failed
2006-11-06 13:57:48 [3245] DEBUG:PGRis_same_host():not same host
2006-11-06 13:57:48 [3245] DEBUG:pgr_createConn():PQsetdbLogin
host[10.0.10.101] port[5432] db[template1] user[postgres]
2006-11-06 13:57:48 [3245] DEBUG:pgr_createConn():Retry. h_errno is
1,reason is 'could not connect to server: Connection refused
Is the server running on host "10.0.10.101" and accepting
TCP/IP connections on port 5432?
'
2006-11-06 13:57:48 [3245] DEBUG:pgr_createConn():Retry. h_errno is
1,reason is 'could not connect to server: Connection refused
Is the server running on host "10.0.10.101" and accepting
TCP/IP connections on port 5432?
'
2006-11-06 13:57:48 [3245] DEBUG:pgr_createConn():Retry. h_errno is
1,reason is 'could not connect to server: Connection refused
Is the server running on host "10.0.10.101" and accepting
TCP/IP connections on port 5432?
'
2006-11-06 13:57:48 [3245] DEBUG:pgr_createConn():Retry. h_errno is
1,reason is 'could not connect to server: Connection refused
Is the server running on host "10.0.10.101" and accepting
TCP/IP connections on port 5432?
'
2006-11-06 13:57:48 [3245] DEBUG:setTransactionTbl(): 5432 ＠ 10.0.10.101
is not ready
2006-11-06 13:57:48 [3245]
DEBUG:replicate_packet_send_internal():setTransactionTbl failed
2006-11-06 13:57:48 [3245] DEBUG:PGRis_same_host():not same host
2006-11-06 13:57:48 [3245] DEBUG:pgr_createConn():PQsetdbLogin
host[10.0.10.100] port[5432] db[template1] user[postgres]
2006-11-06 13:57:48 [3245] DEBUG:pgr_createConn():Retry. h_errno is
1,reason is 'could not connect to server: Connection refused
Is the server running on host "10.0.10.100" and accepting
TCP/IP connections on port 5432?
'
2006-11-06 13:57:49 [3245] DEBUG:pgr_createConn():Retry. h_errno is
1,reason is 'could not connect to server: Connection refused
Is the server running on host "10.0.10.100" and accepting
TCP/IP connections on port 5432?
'
2006-11-06 13:57:49 [3245] DEBUG:pgr_createConn():Retry. h_errno is
1,reason is 'could not connect to server: Connection refused
Is the server running on host "10.0.10.100" and accepting
TCP/IP connections on port 5432?
'
2006-11-06 13:57:49 [3245] DEBUG:pgr_createConn():Retry. h_errno is
1,reason is 'could not connect to server: Connection refused
Is the server running on host "10.0.10.100" and accepting
TCP/IP connections on port 5432?
'
2006-11-06 13:57:49 [3245] DEBUG:setTransactionTbl(): 5432 ＠ 10.0.10.100
is not ready
2006-11-06 13:57:49 [3245]
DEBUG:replicate_packet_send_internal():setTransactionTbl failed
2006-11-06 14:00:54 [3266] DEBUG:PGRread_packet():PG_read_query
returns delete from test.
2006-11-06 14:00:54 [3266] DEBUG:PGRreturn_result():PGRreturn_result[1]
2006-11-06 14:00:54 [3266] DEBUG:PGRreturn_result():128 send
2006-11-06 14:00:54 [3266] DEBUG:PGRread_packet():PG_read_query
returns delete from test.
2006-11-06 14:00:54 [3266] DEBUG:PGRdo_replicate():query :: delete from test
2006-11-06 14:00:54 [3266] DEBUG:cmdSts=Q
2006-11-06 14:00:54 [3266] DEBUG:cmdType=D
2006-11-06 14:00:54 [3266] DEBUG:rlog=0
2006-11-06 14:00:54 [3266] DEBUG:port=5432
2006-11-06 14:00:54 [3266] DEBUG:pid=4054
2006-11-06 14:00:54 [3266] DEBUG:from_host=127.0.0.1
2006-11-06 14:00:54 [3266] DEBUG:dbName=template1
2006-11-06 14:00:54 [3266] DEBUG:userName=postgres
2006-11-06 14:00:54 [3266] DEBUG:recieve sec=1162789254
2006-11-06 14:00:54 [3266] DEBUG:recieve usec=800266
2006-11-06 14:00:54 [3266] DEBUG:query_size=16
2006-11-06 14:00:54 [3266] DEBUG:request_id=1
2006-11-06 14:00:54 [3266] DEBUG:replicate_id=0
2006-11-06 14:00:54 [3266] DEBUG:recovery_status=0
2006-11-06 14:00:54 [3266] DEBUG:query=delete from test
2006-11-06 14:00:54 [3266] DEBUG:sem_lock [1] req
2006-11-06 14:00:54 [3266] DEBUG:sem_lock [1] got it
2006-11-06 14:00:54 [3266] DEBUG:PGRset_rlog():set rlog delete from test
2006-11-06 14:00:54 [3266] DEBUG:PGRset_rlog():PGRsend_lower_cascade failed
2006-11-06 14:00:54 [3266] DEBUG:PGRwrite_rlog():set_query_log
2006-11-06 14:00:54 [3266] DEBUG:pgr_createConn():PQsetdbLogin
host[10.0.10.102] port[5432] db[template1] user[postgres]
2006-11-06 14:00:54 [3266] DEBUG:pgr_createConn():PQsetdbLogin ok!!
2006-11-06 14:00:54 [3266] DEBUG:pgr_createConn():PQsetdbLogin
host[10.0.10.101] port[5432] db[template1] user[postgres]
2006-11-06 14:00:54 [3266] DEBUG:start thread_send_cluster()
2006-11-06 14:00:54 [3266]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(3,1162789254,800266,46,1,2) )
2006-11-06 14:00:54 [3266]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(8,2,0,1) )
2006-11-06 14:00:54 [3266]
DEBUG:send_replicate_packet_to_server():sync_command returns
SYSTEM_COMMAND
2006-11-06 14:00:54 [3266]
DEBUG:send_replicate_packet_to_server():PQexec send :delete from test
2006-11-06 14:00:54 [3266]
DEBUG:send_replicate_packet_to_server():PQexec returns :DELETE 0
2006-11-06 14:00:54 [3266] DEBUG:deleteTransactionTbl():
2006-11-06 14:00:54 [3266] DEBUG:thread_send_cluster():return value
from send_replicate_packet_to_server() is 0
2006-11-06 14:00:54 [3266] DEBUG:deleteTransactionTbl():
2006-11-06 14:00:54 [3266] DEBUG:thread_send_cluster():pthread_exit[0]
2006-11-06 14:00:54 [3266] DEBUG:pgr_createConn():PQsetdbLogin ok!!
2006-11-06 14:00:54 [3266] DEBUG:pgr_createConn():PQsetdbLogin
host[10.0.10.100] port[5432] db[template1] user[postgres]
2006-11-06 14:00:54 [3266] DEBUG:start thread_send_cluster()
2006-11-06 14:00:54 [3266]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(3,1162789254,800266,46,1,2) )
2006-11-06 14:00:54 [3266] DEBUG:pgr_createConn():PQsetdbLogin ok!!
2006-11-06 14:00:54 [3266]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(8,2,0,1) )
2006-11-06 14:00:54 [3266] DEBUG:start thread_send_cluster()
2006-11-06 14:00:54 [3266]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(3,1162789254,800266,46,1,2) )
2006-11-06 14:00:54 [3266]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(8,2,0,1) )
2006-11-06 14:00:54 [3266]
DEBUG:send_replicate_packet_to_server():sync_command returns
SYSTEM_COMMAND
2006-11-06 14:00:54 [3266]
DEBUG:send_replicate_packet_to_server():sync_command returns
SYSTEM_COMMAND
2006-11-06 14:00:54 [3266]
DEBUG:send_replicate_packet_to_server():PQexec send :delete from test
2006-11-06 14:00:54 [3266]
DEBUG:send_replicate_packet_to_server():PQexec returns :DELETE 0
2006-11-06 14:00:54 [3266] DEBUG:deleteTransactionTbl():
2006-11-06 14:00:54 [3266] DEBUG:thread_send_cluster():return value
from send_replicate_packet_to_server() is 0
2006-11-06 14:00:54 [3266] DEBUG:deleteTransactionTbl():
2006-11-06 14:00:54 [3266] DEBUG:thread_send_cluster():pthread_exit[2]
2006-11-06 14:00:54 [3266]
DEBUG:send_replicate_packet_to_server():PQexec send :delete from test
2006-11-06 14:00:54 [3266]
DEBUG:send_replicate_packet_to_server():PQexec returns :DELETE 0
2006-11-06 14:00:54 [3266] DEBUG:deleteTransactionTbl():
2006-11-06 14:00:54 [3266] DEBUG:thread_send_cluster():return value
from send_replicate_packet_to_server() is 0
2006-11-06 14:00:54 [3266] DEBUG:deleteTransactionTbl():
2006-11-06 14:00:54 [3266] DEBUG:thread_send_cluster():pthread_exit[1]
2006-11-06 14:00:54 [3266] DEBUG:unset rlog delete from test
2006-11-06 14:00:54 [3266] DEBUG:PGRsend_lower_cascade recv failed
2006-11-06 14:00:54 [3266] DEBUG:PGRwrite_rlog():delete_query_log
2006-11-06 14:00:54 [3266] DEBUG:get_qurey_log: comparing in log is
771751936,header is 771751936
2006-11-06 14:00:54 [3266] DEBUG:sem_unlock[1]
2006-11-06 14:07:18 [3260] DEBUG:replicate_loop():session closed
2006-11-06 14:07:18 [3260] DEBUG:replicate_loop():replicate loop exit
2006-11-06 14:07:25 [3254] DEBUG:replicate_loop():session closed
2006-11-06 14:07:25 [3254] DEBUG:replicate_loop():replicate loop exit
2006-11-06 14:07:33 [3247] DEBUG:pgrecovery_loop():recovery accept port 8101
2006-11-06 14:07:33 [3247] DEBUG:read_packet():receive packet
2006-11-06 14:07:33 [3247] DEBUG:no = 1
2006-11-06 14:07:33 [3247] DEBUG:max_connect = 100
2006-11-06 14:07:33 [3247] DEBUG:port = 5432
2006-11-06 14:07:33 [3247] DEBUG:recoveryPort = 7001
2006-11-06 14:07:33 [3247] DEBUG:hostName = rep02
2006-11-06 14:07:33 [3247] DEBUG:pg_data = /usr/local/pgsql/data
2006-11-06 14:07:33 [3247] DEBUG:pgrecovery_loop():receive packet no:1
2006-11-06 14:07:33 [3247] DEBUG:pgrecovery_loop():1st master - 0
2006-11-06 14:07:33 [3247] DEBUG:pgrecovery_loop():1st target - 0
2006-11-06 14:07:33 [3247] DEBUG:first_setup_recovery():1st setup target rep02
2006-11-06 14:07:33 [3247] DEBUG:first_setup_recovery():1st setup port 5432
2006-11-06 14:07:33 [3247] DEBUG:first_setup_recovery():add recovery
target to host table
2006-11-06 14:07:33 [3247] DEBUG:first_setup_recovery():set
RECOVERY_PGDATA_REQ packet data
2006-11-06 14:07:33 [3247]
DEBUG:PGRsend_replicate_packet_to_server():host(10.0.10.102) :
port(5432)
2006-11-06 14:07:33 [3247] DEBUG:pgr_createConn():PQsetdbLogin
host[10.0.10.102] port[5432] db[template1] user[postgres]
2006-11-06 14:07:33 [3247] DEBUG:pgr_createConn():PQsetdbLogin ok!!
2006-11-06 14:07:34 [3247]
DEBUG:PGRsend_replicate_packet_to_server():connect db:template1
port:5432 user:postgres host:10.0.10.102 query:VACUUM
2006-11-06 14:07:34 [3247]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(3,0,0,0,1,2) )
2006-11-06 14:07:34 [3247]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(8,0,0,1) )
2006-11-06 14:07:34 [3247]
DEBUG:send_replicate_packet_to_server():sync_command returns
SYSTEM_COMMAND
2006-11-06 14:07:34 [3247]
DEBUG:send_replicate_packet_to_server():PQexec send :VACUUM
2006-11-06 14:07:34 [3247]
DEBUG:send_replicate_packet_to_server():PQexec returns :VACUUM
2006-11-06 14:07:34 [3247] DEBUG:deleteTransactionTbl():
2006-11-06 14:07:34 [3247] DEBUG:first_setup_recovery():send packet to
master rep03.traction.jp recoveryPort 7001
2006-11-06 14:07:34 [3247] DEBUG:first_setup_recovery():wait answer
from master server
2006-11-06 14:07:34 [3247] DEBUG:read_packet():receive packet
2006-11-06 14:07:34 [3247] DEBUG:no = 3
2006-11-06 14:07:34 [3247] DEBUG:max_connect = 100
2006-11-06 14:07:34 [3247] DEBUG:port = 5432
2006-11-06 14:07:34 [3247] DEBUG:recoveryPort = 7001
2006-11-06 14:07:34 [3247] DEBUG:hostName = rep03
2006-11-06 14:07:34 [3247] DEBUG:pg_data = /usr/local/pgsql/data
2006-11-06 14:07:34 [3247] DEBUG:first_setup_recovery():get answer
from master:no[3]
2006-11-06 14:07:34 [3247] DEBUG:pgrecovery_loop():first_setup_recovery end:0
2006-11-06 14:07:36 [3247] DEBUG:read_packet():receive packet
2006-11-06 14:07:36 [3247] DEBUG:no = 5
2006-11-06 14:07:36 [3247] DEBUG:max_connect = 100
2006-11-06 14:07:36 [3247] DEBUG:port = 5432
2006-11-06 14:07:36 [3247] DEBUG:recoveryPort = 7001
2006-11-06 14:07:36 [3247] DEBUG:hostName = rep03.traction.jp
2006-11-06 14:07:36 [3247] DEBUG:pg_data = /usr/local/pgsql/data
2006-11-06 14:07:36 [3247] DEBUG:pgrecovery_loop():receive packet no:5
2006-11-06 14:07:36 [3247] DEBUG:pgrecovery_loop():2nd master
rep03.traction.jp - 5432
2006-11-06 14:07:36 [3247] DEBUG:pgrecovery_loop():2nd target rep02 - 5432
2006-11-06 14:07:36 [3247]
DEBUG:PGRsend_replicate_packet_to_server():host(10.0.10.102) :
port(5432)
2006-11-06 14:07:36 [3247] DEBUG:pgr_createConn():PQsetdbLogin
host[10.0.10.102] port[5432] db[template1] user[postgres]
2006-11-06 14:07:36 [3247] DEBUG:pgr_createConn():PQsetdbLogin ok!!
2006-11-06 14:07:38 [3247]
DEBUG:PGRsend_replicate_packet_to_server():connect db:template1
port:5432 user:postgres host:10.0.10.102 query:VACUUM FULL
2006-11-06 14:07:38 [3247]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(3,0,0,0,1,2) )
2006-11-06 14:07:38 [3247]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(8,0,0,1) )
2006-11-06 14:07:38 [3247]
DEBUG:send_replicate_packet_to_server():sync_command returns
SYSTEM_COMMAND
2006-11-06 14:07:39 [3247]
DEBUG:send_replicate_packet_to_server():PQexec send :VACUUM FULL
2006-11-06 14:07:39 [3247]
DEBUG:send_replicate_packet_to_server():PQexec returns :VACUUM
2006-11-06 14:07:39 [3247] DEBUG:deleteTransactionTbl():
2006-11-06 14:07:39 [3247] DEBUG:read_packet():receive packet
2006-11-06 14:07:39 [3247] DEBUG:no = 7
2006-11-06 14:07:39 [3247] DEBUG:max_connect = 100
2006-11-06 14:07:39 [3247] DEBUG:port = 5432
2006-11-06 14:07:39 [3247] DEBUG:recoveryPort = 7001
2006-11-06 14:07:39 [3247] DEBUG:hostName = rep03
2006-11-06 14:07:39 [3247] DEBUG:pg_data = /usr/local/pgsql/data
2006-11-06 14:07:39 [3247] DEBUG:pgrecovery_loop():second_setup_recovery end :0
2006-11-06 14:07:40 [3247] ERROR:read_packet():unexpected EOF
2006-11-06 14:07:40 [3247] DEBUG:pgrecovery_loop():receive packet no:8
2006-11-06 14:07:40 [3247] ERROR:pgrecovery_loop():unknown packet.
abort to parse
2006-11-06 14:07:40 [3247] DEBUG:pgrecovery_loop():recovery accept port 8101
2006-11-06 14:07:40 [3247] DEBUG:read_packet():receive packet
2006-11-06 14:07:40 [3247] DEBUG:no = 9
2006-11-06 14:07:40 [3247] DEBUG:max_connect = 0
2006-11-06 14:07:40 [3247] DEBUG:port = 0
2006-11-06 14:07:40 [3247] DEBUG:recoveryPort = 0
2006-11-06 14:07:40 [3247] DEBUG:hostName =
2006-11-06 14:07:40 [3247] DEBUG:pg_data =
2006-11-06 14:07:40 [3247] DEBUG:pgrecovery_loop():receive packet no:9
2006-11-06 14:07:40 [3247] DEBUG:pgrecovery_loop():last master
rep03.traction.jp - 5432
2006-11-06 14:07:40 [3247] DEBUG:pgrecovery_loop():last target rep02 - 5432
2006-11-06 14:07:40 [3247] DEBUG:PGRsend_queue():master rep03.traction.jp - 5432
2006-11-06 14:07:40 [3247] DEBUG:PGRsend_queue():target rep02 - 5432
2006-11-06 14:07:40 [3247] DEBUG:PGRsend_queue():send_queue return status 0
2006-11-06 14:07:40 [3247] DEBUG:pgrecovery_loop():recovery accept port 8101
2006-11-06 14:07:40 [3247] DEBUG:read_packet():receive packet
2006-11-06 14:07:40 [3247] DEBUG:no = 11
2006-11-06 14:07:40 [3247] DEBUG:max_connect = 100
2006-11-06 14:07:40 [3247] DEBUG:port = 5432
2006-11-06 14:07:40 [3247] DEBUG:recoveryPort = 7001
2006-11-06 14:07:40 [3247] DEBUG:hostName = rep02
2006-11-06 14:07:40 [3247] DEBUG:pg_data = /usr/local/pgsql/data
2006-11-06 14:07:40 [3247] DEBUG:pgrecovery_loop():receive packet no:11
2006-11-06 14:08:05 [3247] DEBUG:pgrecovery_loop():recovery accept port 8101
2006-11-06 14:08:05 [3247] DEBUG:read_packet():receive packet
2006-11-06 14:08:05 [3247] DEBUG:no = 1
2006-11-06 14:08:05 [3247] DEBUG:max_connect = 100
2006-11-06 14:08:05 [3247] DEBUG:port = 5432
2006-11-06 14:08:05 [3247] DEBUG:recoveryPort = 7001
2006-11-06 14:08:05 [3247] DEBUG:hostName = rep01
2006-11-06 14:08:05 [3247] DEBUG:pg_data = /usr/local/pgsql/data
2006-11-06 14:08:05 [3247] DEBUG:pgrecovery_loop():receive packet no:1
2006-11-06 14:08:05 [3247] DEBUG:pgrecovery_loop():1st master
rep03.traction.jp - 5432
2006-11-06 14:08:05 [3247] DEBUG:pgrecovery_loop():1st target rep02 - 5432
2006-11-06 14:08:05 [3247] DEBUG:first_setup_recovery():1st setup target rep01
2006-11-06 14:08:05 [3247] DEBUG:first_setup_recovery():1st setup port 5432
2006-11-06 14:08:05 [3247] DEBUG:first_setup_recovery():add recovery
target to host table
2006-11-06 14:08:05 [3247] DEBUG:first_setup_recovery():set
RECOVERY_PGDATA_REQ packet data
2006-11-06 14:08:05 [3247]
DEBUG:PGRsend_replicate_packet_to_server():host(10.0.10.102) :
port(5432)
2006-11-06 14:08:05 [3247] DEBUG:pgr_createConn():PQsetdbLogin
host[10.0.10.102] port[5432] db[template1] user[postgres]
2006-11-06 14:08:05 [3247] DEBUG:pgr_createConn():PQsetdbLogin ok!!
2006-11-06 14:08:06 [3247]
DEBUG:PGRsend_replicate_packet_to_server():connect db:template1
port:5432 user:postgres host:10.0.10.102 query:VACUUM
2006-11-06 14:08:06 [3247]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(3,0,0,0,1,2) )
2006-11-06 14:08:06 [3247]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(8,0,0,1) )
2006-11-06 14:08:06 [3247]
DEBUG:send_replicate_packet_to_server():sync_command returns
SYSTEM_COMMAND
2006-11-06 14:08:07 [3247]
DEBUG:send_replicate_packet_to_server():PQexec send :VACUUM
2006-11-06 14:08:07 [3247]
DEBUG:send_replicate_packet_to_server():PQexec returns :VACUUM
2006-11-06 14:08:07 [3247] DEBUG:deleteTransactionTbl():
2006-11-06 14:08:07 [3247] DEBUG:first_setup_recovery():send packet to
master rep03.traction.jp recoveryPort 7001
2006-11-06 14:08:07 [3247] DEBUG:first_setup_recovery():wait answer
from master server
2006-11-06 14:08:07 [3247] DEBUG:read_packet():receive packet
2006-11-06 14:08:07 [3247] DEBUG:no = 3
2006-11-06 14:08:07 [3247] DEBUG:max_connect = 100
2006-11-06 14:08:07 [3247] DEBUG:port = 5432
2006-11-06 14:08:07 [3247] DEBUG:recoveryPort = 7001
2006-11-06 14:08:07 [3247] DEBUG:hostName = rep03
2006-11-06 14:08:07 [3247] DEBUG:pg_data = /usr/local/pgsql/data
2006-11-06 14:08:07 [3247] DEBUG:first_setup_recovery():get answer
from master:no[3]
2006-11-06 14:08:07 [3247] DEBUG:pgrecovery_loop():first_setup_recovery end:0
2006-11-06 14:08:09 [3247] DEBUG:read_packet():receive packet
2006-11-06 14:08:09 [3247] DEBUG:no = 5
2006-11-06 14:08:09 [3247] DEBUG:max_connect = 100
2006-11-06 14:08:09 [3247] DEBUG:port = 5432
2006-11-06 14:08:09 [3247] DEBUG:recoveryPort = 7001
2006-11-06 14:08:09 [3247] DEBUG:hostName = rep03.traction.jp
2006-11-06 14:08:09 [3247] DEBUG:pg_data = /usr/local/pgsql/data
2006-11-06 14:08:09 [3247] DEBUG:pgrecovery_loop():receive packet no:5
2006-11-06 14:08:09 [3247] DEBUG:pgrecovery_loop():2nd master
rep03.traction.jp - 5432
2006-11-06 14:08:09 [3247] DEBUG:pgrecovery_loop():2nd target rep01 - 5432
2006-11-06 14:08:09 [3247]
DEBUG:PGRsend_replicate_packet_to_server():host(10.0.10.102) :
port(5432)
2006-11-06 14:08:09 [3247] DEBUG:pgr_createConn():PQsetdbLogin
host[10.0.10.102] port[5432] db[template1] user[postgres]
2006-11-06 14:08:09 [3247] DEBUG:pgr_createConn():PQsetdbLogin ok!!
2006-11-06 14:08:10 [3247]
DEBUG:PGRsend_replicate_packet_to_server():connect db:template1
port:5432 user:postgres host:10.0.10.102 query:VACUUM FULL
2006-11-06 14:08:10 [3247]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(3,0,0,0,1,2) )
2006-11-06 14:08:10 [3247]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(8,0,0,1) )
2006-11-06 14:08:10 [3247]
DEBUG:send_replicate_packet_to_server():sync_command returns
SYSTEM_COMMAND
2006-11-06 14:08:10 [3247]
DEBUG:send_replicate_packet_to_server():PQexec send :VACUUM FULL
2006-11-06 14:08:10 [3247]
DEBUG:send_replicate_packet_to_server():PQexec returns :VACUUM
2006-11-06 14:08:10 [3247] DEBUG:deleteTransactionTbl():
2006-11-06 14:08:10 [3247] DEBUG:read_packet():receive packet
2006-11-06 14:08:10 [3247] DEBUG:no = 7
2006-11-06 14:08:10 [3247] DEBUG:max_connect = 100
2006-11-06 14:08:10 [3247] DEBUG:port = 5432
2006-11-06 14:08:10 [3247] DEBUG:recoveryPort = 7001
2006-11-06 14:08:10 [3247] DEBUG:hostName = rep03
2006-11-06 14:08:10 [3247] DEBUG:pg_data = /usr/local/pgsql/data
2006-11-06 14:08:10 [3247] DEBUG:pgrecovery_loop():second_setup_recovery end :0
2006-11-06 14:08:12 [3247] ERROR:read_packet():unexpected EOF
2006-11-06 14:08:12 [3247] DEBUG:pgrecovery_loop():receive packet no:8
2006-11-06 14:08:12 [3247] ERROR:pgrecovery_loop():unknown packet.
abort to parse
2006-11-06 14:08:12 [3247] DEBUG:pgrecovery_loop():recovery accept port 8101
2006-11-06 14:08:12 [3247] DEBUG:read_packet():receive packet
2006-11-06 14:08:12 [3247] DEBUG:no = 9
2006-11-06 14:08:12 [3247] DEBUG:max_connect = 0
2006-11-06 14:08:12 [3247] DEBUG:port = 0
2006-11-06 14:08:12 [3247] DEBUG:recoveryPort = 0
2006-11-06 14:08:12 [3247] DEBUG:hostName =
2006-11-06 14:08:12 [3247] DEBUG:pg_data =
2006-11-06 14:08:12 [3247] DEBUG:pgrecovery_loop():receive packet no:9
2006-11-06 14:08:12 [3247] DEBUG:pgrecovery_loop():last master
rep03.traction.jp - 5432
2006-11-06 14:08:12 [3247] DEBUG:pgrecovery_loop():last target rep01 - 5432
2006-11-06 14:08:12 [3247] DEBUG:PGRsend_queue():master rep03.traction.jp - 5432
2006-11-06 14:08:12 [3247] DEBUG:PGRsend_queue():target rep01 - 5432
2006-11-06 14:08:12 [3247] DEBUG:PGRsend_queue():send_queue return status 0
2006-11-06 14:08:12 [3247] DEBUG:pgrecovery_loop():recovery accept port 8101
2006-11-06 14:08:12 [3247] DEBUG:read_packet():receive packet
2006-11-06 14:08:12 [3247] DEBUG:no = 11
2006-11-06 14:08:12 [3247] DEBUG:max_connect = 100
2006-11-06 14:08:12 [3247] DEBUG:port = 5432
2006-11-06 14:08:12 [3247] DEBUG:recoveryPort = 7001
2006-11-06 14:08:12 [3247] DEBUG:hostName = rep01
2006-11-06 14:08:12 [3247] DEBUG:pg_data = /usr/local/pgsql/data
2006-11-06 14:08:12 [3247] DEBUG:pgrecovery_loop():receive packet no:11
2006-11-06 14:09:44 [3311] DEBUG:PGRread_packet():PG_read_query
returns insert into test (date) values (now()).
2006-11-06 14:09:44 [3311] DEBUG:PGRreturn_result():PGRreturn_result[1]
2006-11-06 14:09:44 [3311] DEBUG:PGRreturn_result():128 send
2006-11-06 14:09:44 [3311] DEBUG:PGRread_packet():PG_read_query
returns insert into test (date) values (now()).
2006-11-06 14:09:44 [3311] DEBUG:PGRdo_replicate():query :: insert
into test (date) values (now())
2006-11-06 14:09:44 [3311] DEBUG:cmdSts=Q
2006-11-06 14:09:44 [3311] DEBUG:cmdType=I
2006-11-06 14:09:44 [3311] DEBUG:rlog=0
2006-11-06 14:09:44 [3311] DEBUG:port=5432
2006-11-06 14:09:44 [3311] DEBUG:pid=3310
2006-11-06 14:09:44 [3311] DEBUG:from_host=127.0.0.1
2006-11-06 14:09:44 [3311] DEBUG:dbName=template1
2006-11-06 14:09:44 [3311] DEBUG:userName=postgres
2006-11-06 14:09:44 [3311] DEBUG:recieve sec=1162789784
2006-11-06 14:09:44 [3311] DEBUG:recieve usec=647606
2006-11-06 14:09:44 [3311] DEBUG:query_size=38
2006-11-06 14:09:44 [3311] DEBUG:request_id=1
2006-11-06 14:09:44 [3311] DEBUG:replicate_id=0
2006-11-06 14:09:44 [3311] DEBUG:recovery_status=0
2006-11-06 14:09:44 [3311] DEBUG:query=insert into test (date) values (now())
2006-11-06 14:09:44 [3311] DEBUG:sem_lock [1] req
2006-11-06 14:09:44 [3311] DEBUG:sem_lock [1] got it
2006-11-06 14:09:44 [3311] DEBUG:PGRset_rlog():set rlog insert into
test (date) values (now())
2006-11-06 14:09:44 [3311] DEBUG:PGRset_rlog():PGRsend_lower_cascade failed
2006-11-06 14:09:44 [3311] DEBUG:PGRwrite_rlog():set_query_log
2006-11-06 14:09:44 [3311] DEBUG:pgr_createConn():PQsetdbLogin
host[10.0.10.102] port[5432] db[template1] user[postgres]
2006-11-06 14:09:44 [3311] DEBUG:pgr_createConn():PQsetdbLogin ok!!
2006-11-06 14:09:44 [3311] DEBUG:pgr_createConn():PQsetdbLogin
host[10.0.10.101] port[5432] db[template1] user[postgres]
2006-11-06 14:09:44 [3311] DEBUG:start thread_send_cluster()
2006-11-06 14:09:44 [3311]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(3,1162789784,647606,47,1,3) )
2006-11-06 14:09:44 [3311]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(8,3,0,1) )
2006-11-06 14:09:44 [3311]
DEBUG:send_replicate_packet_to_server():sync_command returns
SYSTEM_COMMAND
2006-11-06 14:09:44 [3311]
DEBUG:send_replicate_packet_to_server():PQexec send :insert into test
(date) values (now())
2006-11-06 14:09:44 [3311]
DEBUG:send_replicate_packet_to_server():PQexec returns :INSERT 0 1
2006-11-06 14:09:44 [3311] DEBUG:deleteTransactionTbl():
2006-11-06 14:09:44 [3311] DEBUG:thread_send_cluster():return value
from send_replicate_packet_to_server() is 0
2006-11-06 14:09:44 [3311] DEBUG:deleteTransactionTbl():
2006-11-06 14:09:44 [3311] DEBUG:thread_send_cluster():pthread_exit[0]
2006-11-06 14:09:44 [3311] DEBUG:pgr_createConn():PQsetdbLogin ok!!
2006-11-06 14:09:44 [3311] DEBUG:pgr_createConn():PQsetdbLogin
host[10.0.10.100] port[5432] db[template1] user[postgres]
2006-11-06 14:09:44 [3311] DEBUG:start thread_send_cluster()
2006-11-06 14:09:44 [3311]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(3,1162789784,647606,47,1,3) )
2006-11-06 14:09:44 [3311]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(8,3,0,1) )
2006-11-06 14:09:44 [3311]
DEBUG:send_replicate_packet_to_server():sync_command returns
SYSTEM_COMMAND
2006-11-06 14:09:44 [3311] DEBUG:pgr_createConn():PQsetdbLogin ok!!
2006-11-06 14:09:44 [3311] DEBUG:same host
2006-11-06 14:09:44 [3311] DEBUG:start thread_send_cluster()
2006-11-06 14:09:44 [3311]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(3,1162789784,647606,47,1,3) )
2006-11-06 14:09:44 [3311]
DEBUG:send_replicate_packet_to_server():sync_command(SELECT
PGR_SYSTEM_COMMAND_FUNCTION(8,3,0,1) )
2006-11-06 14:09:44 [3311]
DEBUG:send_replicate_packet_to_server():sync_command returns
SYSTEM_COMMAND
2006-11-06 14:09:44 [3311]
DEBUG:send_replicate_packet_to_server():PQexec send :insert into test
(date) values (now())
2006-11-06 14:09:44 [3311]
DEBUG:send_replicate_packet_to_server():PQexec returns :INSERT 0 1
2006-11-06 14:09:44 [3311] DEBUG:deleteTransactionTbl():
2006-11-06 14:09:44 [3311] DEBUG:thread_send_cluster():return value
from send_replicate_packet_to_server() is 0
2006-11-06 14:09:44 [3311] DEBUG:deleteTransactionTbl():
2006-11-06 14:09:44 [3311] DEBUG:thread_send_cluster():pthread_exit[1]
2006-11-06 14:09:44 [3311]
DEBUG:send_replicate_packet_to_server():PQexec send :insert into test
(date) values (now())
2006-11-06 14:09:44 [3311]
DEBUG:send_replicate_packet_to_server():PQexec returns :INSERT 0 1
2006-11-06 14:09:44 [3311] DEBUG:deleteTransactionTbl():
2006-11-06 14:09:44 [3311] DEBUG:thread_send_cluster():return value
from send_replicate_packet_to_server() is 0
2006-11-06 14:09:44 [3311] DEBUG:deleteTransactionTbl():
2006-11-06 14:09:44 [3311] DEBUG:thread_send_cluster():pthread_exit[2]
2006-11-06 14:09:44 [3311]
DEBUG:PGRreturn_result():PGRreturn_result[3,1162789784,647606,47,1,3]
2006-11-06 14:09:44 [3311] DEBUG:PGRreturn_result():128 send
2006-11-06 14:09:44 [3311] DEBUG:PGRread_packet():PG_read_query
returns PGR_QUERY_DONE_NOTICE_CMD.
2006-11-06 14:09:44 [3311] DEBUG:read_answer():answer[PGR_QUERY_DONE_NOTICE_CMD]
2006-11-06 14:09:44 [3311] DEBUG:read_answer():QUERY DONE
2006-11-06 14:09:44 [3311] DEBUG:deleteTransactionTbl():
2006-11-06 14:09:44 [3311] DEBUG:end thread_send_source()
2006-11-06 14:09:44 [3311] DEBUG:unset rlog insert into test (date)
values (now())
2006-11-06 14:09:44 [3311] DEBUG:PGRsend_lower_cascade recv failed
2006-11-06 14:09:44 [3311] DEBUG:PGRwrite_rlog():delete_query_log
2006-11-06 14:09:44 [3311] DEBUG:get_qurey_log: comparing in log is
788529152,header is 788529152
2006-11-06 14:09:44 [3311] DEBUG:sem_unlock[1]
2006-11-06 14:16:58 [3247] DEBUG:quick_exit:signo = 2
2006-11-06 14:16:58 [3272] DEBUG:quick_exit:signo = 2
2006-11-06 14:16:58 [3278] DEBUG:quick_exit:signo = 2
2006-11-06 14:16:58 [3266] DEBUG:quick_exit:signo = 2
2006-11-06 14:16:58 [3253] DEBUG:quick_exit:signo = 2
postgres ＠ rep01:/usr/local/pgsql/etc$ 2006-11-06 14:16:58 [3311]
DEBUG:quick_exit:signo = 2
以上、よろしくお願い致します。
--
Traction inc.
Yoshitake Shinohara
yoshi ＠ traction.jp
048-816-3102 / 090-4228-0019
pgcluster メーリングリストの案内