[pgcluster: 637] Re: pg_restoreをすると、レプリケーションサーバが反応しなくなる

kazunari takahashi kazunari.takahashi ＠ ctc-g.co.jp
2005年 1月 7日 (金) 15:09:20 JST 

三谷様

高橋です．
遅くなりましたが、明けましておめでとうございます．
昨年は大変お世話になりました．
今年も宜しくお願いいたします．

pgcluster-1.0.8bで早速試してみましたが、うまくいかないです．

> 高橋さんから頂いたレプリケーションログを見ると，ダンプされたファイルから
> データ部分が読み込まれておらず，EOFだけが何度も読まれているようです．
> ダンプファイルが壊れているのか，ServerAが悪いのか．．．

クラスタDBを1台にしてリストアすると、問題なく終わるのでダンプファイルが壊れていることはないと思います．
正常に終了する時としない時のレプリケーションログを比べると、

正常終了時には、処理の最後に

DEBUG:read_answer():answer[PGR_QUERY_DONE_NOTICE_CMD]
DEBUG:read_answer():QUERY DONE
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:PGRreturn_result():PGRreturn_result[6]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_unlock[2]
DEBUG:replicate_loop():replicate loop exit

という処理があるのですが、正常に終わらない場合は、

DEBUG:read_answer():answer[PGR_QUERY_DONE_NOTICE_CMD]
DEBUG:read_answer():QUERY DONE
DEBUG:sem_lock[2]

で、処理が終了しています．
今回は、serverBからpg_restoreしてみました．

ちなみに検証環境はsolaris8です．



-------------------------------------
クラスタDBが1台の場合のレプリケーションログ(正常終了)
serverAでpg_resotre
------------------------------------
DEBUG:PGRdo_replicate():query :: DROP DATABASE "test"
DEBUG:cmdSts=Q
DEBUG:cmdType=O
DEBUG:port=5432
DEBUG:pid=22703
DEBUG:from_host=serverA
DEBUG:dbName=template1
DEBUG:userName=postgres
DEBUG:recieve sec=1105075102
DEBUG:recieve usec=727583
DEBUG:query_size=20
DEBUG:query=DROP DATABASE "test"
DEBUG:sem_lock[1]
DEBUG:PGRsend_replicate_packet_to_server():host(serverB) : port(5432)
DEBUG:pgr_createConn():PQsetdbLogin host[serverB] port[5432] db[template1] user[postgres]
DEBUG:setTransactionTbl(): 5432 ＠ serverB is not ready
DEBUG:PGRsend_replicate_packet_to_server():setTransactionTbl failed
ERROR:send_packet():PGR_Create_Socket_Connect failed
ERROR:send_packet():PGR_Create_Socket_Connect failed
ERROR:send_packet():PGR_Create_Socket_Connect failed
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:PGRreturn_result():PGRreturn_result[]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_lock[3]
DEBUG:sem_unlock[2]
DEBUG:PGRreturn_result():PGRreturn_result[6]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_unlock[3]
DEBUG:replicate_loop():replicate loop exit
DEBUG:PGRdo_replicate():query :: CREATE DATABASE "test" WITH OWNER = "test"
DEBUG:cmdSts=Q
DEBUG:cmdType=O
DEBUG:port=5432
DEBUG:pid=22719
DEBUG:from_host=serverA
DEBUG:dbName=template1
DEBUG:userName=postgres
DEBUG:recieve sec=1105075127
DEBUG:recieve usec=714676
DEBUG:query_size=42
DEBUG:query=CREATE DATABASE "test" WITH OWNER = "test"
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:PGRreturn_result():PGRreturn_result[6]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_unlock[2]
DEBUG:replicate_loop():replicate loop exit
DEBUG:PGRdo_replicate():query :: BEGIN
DEBUG:cmdSts=T
DEBUG:cmdType=B
DEBUG:port=5432
DEBUG:pid=22729
DEBUG:from_host=serverA
DEBUG:dbName=test
DEBUG:userName=test
DEBUG:recieve sec=1105075152
DEBUG:recieve usec=589595
DEBUG:query_size=5
DEBUG:query=BEGIN
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[3,1105075152,589595,2]
DEBUG:PGRreturn_result():128 send
DEBUG:read_answer():answer[PGR_QUERY_DONE_NOTICE_CMD]
DEBUG:read_answer():QUERY DONE
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:PGRreturn_result():PGRreturn_result[6]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_unlock[2]
DEBUG:PGRdo_replicate():query :: SELECT version()
DEBUG:cmdSts=T
DEBUG:cmdType=S
DEBUG:port=5432
DEBUG:pid=22729
DEBUG:from_host=serverA
DEBUG:dbName=test
DEBUG:userName=test
DEBUG:recieve sec=1105075152
DEBUG:recieve usec=594007
DEBUG:query_size=16
DEBUG:query=SELECT version()
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[]
DEBUG:PGRreturn_result():128 send
DEBUG:read_answer():answer[PGR_QUERY_DONE_NOTICE_CMD]
DEBUG:read_answer():QUERY DONE
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:PGRreturn_result():PGRreturn_result[6]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_unlock[2]
DEBUG:PGRdo_replicate():query :: COMMIT
DEBUG:cmdSts=T
DEBUG:cmdType=E
DEBUG:port=5432
DEBUG:pid=22729
DEBUG:from_host=serverA
DEBUG:dbName=test
DEBUG:userName=test
DEBUG:recieve sec=1105075152
DEBUG:recieve usec=597886
DEBUG:query_size=6
DEBUG:query=COMMIT
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[]
DEBUG:PGRreturn_result():128 send
DEBUG:read_answer():answer[PGR_QUERY_DONE_NOTICE_CMD]
DEBUG:read_answer():QUERY DONE
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:PGRreturn_result():PGRreturn_result[6]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_unlock[2]
DEBUG:PGRdo_replicate():query :: CREATE TABLE test (
    id serial NOT NULL,
    name character varying(20)
)
DEBUG:cmdSts=Q
DEBUG:cmdType=O
DEBUG:port=5432
DEBUG:pid=22729
DEBUG:from_host=serverA
DEBUG:dbName=test
DEBUG:userName=test
DEBUG:recieve sec=1105075152
DEBUG:recieve usec=647958
DEBUG:query_size=76
DEBUG:query=CREATE TABLE test (
    id serial NOT NULL,
    name character varying(20)
)
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:PGRreturn_result():PGRreturn_result[6]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_unlock[2]
DEBUG:PGRdo_replicate():query :: COPY test (id, name) FROM stdin
DEBUG:cmdSts=Q
DEBUG:cmdType=C
DEBUG:port=5432
DEBUG:pid=22729
DEBUG:from_host=serverA
DEBUG:dbName=test
DEBUG:userName=test
DEBUG:recieve sec=1105075152
DEBUG:recieve usec=881494
DEBUG:query_size=31
DEBUG:query=COPY test (id, name) FROM stdin
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[3,1105075152,881494,2]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:sem_unlock[2]
DEBUG:PGRdo_replicate():query ::
DEBUG:cmdSts=C
DEBUG:cmdType=e
DEBUG:port=5432
DEBUG:pid=22729
DEBUG:from_host=serverA
DEBUG:dbName=test
DEBUG:userName=test
DEBUG:recieve sec=1105075152
DEBUG:recieve usec=886047
DEBUG:query_size=27
DEBUG:query=
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:sem_unlock[2]
DEBUG:PGRdo_replicate():query :: SELECT pg_catalog.setval ('test_id_seq', 4, true)
DEBUG:cmdSts=Q
DEBUG:cmdType=S
DEBUG:port=5432
DEBUG:pid=22729
DEBUG:from_host=serverA
DEBUG:dbName=test
DEBUG:userName=test
DEBUG:recieve sec=1105075152
DEBUG:recieve usec=910443
DEBUG:query_size=49
DEBUG:query=SELECT pg_catalog.setval ('test_id_seq', 4, true)
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[3,1105075152,910443,2]
DEBUG:PGRreturn_result():128 send
DEBUG:read_answer():answer[PGR_QUERY_DONE_NOTICE_CMD]
DEBUG:read_answer():QUERY DONE
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:PGRreturn_result():PGRreturn_result[6]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_unlock[2]
DEBUG:replicate_loop():replicate loop exit

-------------------------------------
クラスタDBが2台の場合のレプリケーションログ
serverBでpg_restore
------------------------------------

DEBUG:PGRdo_replicate():query :: CREATE DATABASE "test" WITH OWNER = "test"
DEBUG:cmdSts=Q
DEBUG:cmdType=O
DEBUG:port=5432
DEBUG:pid=23050
DEBUG:from_host=serverA
DEBUG:dbName=template1
DEBUG:userName=postgres
DEBUG:recieve sec=1105075536
DEBUG:recieve usec=308234
DEBUG:query_size=42
DEBUG:query=CREATE DATABASE "test" WITH OWNER = "test"
DEBUG:sem_lock[1]
DEBUG:PGRsend_replicate_packet_to_server():host(serverB) : port(5432)
DEBUG:pgr_createConn():PQsetdbLogin host[serverB] port[5432] db[template1] user[postgres]
DEBUG:pgr_createConn():PQsetdbLogin ok!!
DEBUG:PGRsend_replicate_packet_to_server():connect db:template1 port:5432 user:postgres host:serverB query:CREATE DATABASE "test" WITH OWNER = "test"
DEBUG:PGRsend_replicate_packet_to_server():sync_command(SELECT PGR_SYSTEM_COMMAND_FUNCTION(3,1105075536,308234,2) )
DEBUG:PGRsend_replicate_packet_to_server():PQexec send :CREATE DATABASE "test" WITH OWNER = "test"
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:PGRreturn_result():PGRreturn_result[]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_lock[3]
DEBUG:sem_unlock[2]
DEBUG:PGRreturn_result():PGRreturn_result[6]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_unlock[3]
DEBUG:replicate_loop():replicate loop exit
DEBUG:PGRdo_replicate():query :: BEGIN
DEBUG:cmdSts=T
DEBUG:cmdType=B
DEBUG:port=5432
DEBUG:pid=24252
DEBUG:from_host=serverB
DEBUG:dbName=test
DEBUG:userName=test
DEBUG:recieve sec=1105075624
DEBUG:recieve usec=764755
DEBUG:query_size=5
DEBUG:query=BEGIN
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[3,1105075624,764755,2]
DEBUG:PGRreturn_result():128 send
DEBUG:read_answer():answer[PGR_QUERY_DONE_NOTICE_CMD]
DEBUG:read_answer():QUERY DONE
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:PGRsend_replicate_packet_to_server():host(serverA) : port(5432)
DEBUG:pgr_createConn():PQsetdbLogin host[serverA] port[5432] db[test] user[test]
DEBUG:pgr_createConn():PQsetdbLogin ok!!
DEBUG:PGRsend_replicate_packet_to_server():connect db:test port:5432 user:test host:serverA query:BEGIN
DEBUG:PGRsend_replicate_packet_to_server():sync_command(SELECT PGR_SYSTEM_COMMAND_FUNCTION(3,1105075624,764755,2) )
DEBUG:PGRsend_replicate_packet_to_server():PQexec send :BEGIN
DEBUG:sem_lock[3]
DEBUG:sem_unlock[2]
DEBUG:PGRreturn_result():PGRreturn_result[6]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_unlock[3]
DEBUG:PGRdo_replicate():query :: SELECT version()
DEBUG:cmdSts=T
DEBUG:cmdType=S
DEBUG:port=5432
DEBUG:pid=24252
DEBUG:from_host=serverB
DEBUG:dbName=test
DEBUG:userName=test
DEBUG:recieve sec=1105075624
DEBUG:recieve usec=919943
DEBUG:query_size=16
DEBUG:query=SELECT version()
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[]
DEBUG:PGRreturn_result():128 send
DEBUG:read_answer():answer[PGR_QUERY_DONE_NOTICE_CMD]
DEBUG:read_answer():QUERY DONE
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:PGRsend_replicate_packet_to_server():host(serverA) : port(5432)
DEBUG:PGRsend_replicate_packet_to_server():connect db:test port:5432 user:test host:serverA qu
ery:SELECT version()
DEBUG:PGRsend_replicate_packet_to_server():PQexec send :SELECT version()
DEBUG:sem_lock[3]
DEBUG:sem_unlock[2]
DEBUG:PGRreturn_result():PGRreturn_result[6]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_unlock[3]
DEBUG:PGRdo_replicate():query :: COMMIT
DEBUG:cmdSts=T
DEBUG:cmdType=E
DEBUG:port=5432
DEBUG:pid=24252
DEBUG:from_host=serverB
DEBUG:dbName=test
DEBUG:userName=test
DEBUG:recieve sec=1105075624
DEBUG:recieve usec=927093
DEBUG:query_size=6
DEBUG:query=COMMIT
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[]
DEBUG:PGRreturn_result():128 send
DEBUG:read_answer():answer[PGR_QUERY_DONE_NOTICE_CMD]
DEBUG:read_answer():QUERY DONE
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:PGRsend_replicate_packet_to_server():host(serverA) : port(5432)
DEBUG:PGRsend_replicate_packet_to_server():connect db:test port:5432 user:test host:serverA qu
ery:COMMIT
DEBUG:PGRsend_replicate_packet_to_server():PQexec send :COMMIT
DEBUG:sem_lock[3]
DEBUG:sem_unlock[2]
DEBUG:PGRreturn_result():PGRreturn_result[6]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_unlock[3]
DEBUG:PGRdo_replicate():query :: CREATE TABLE test (
    id serial NOT NULL,
    name character varying(20)
)
DEBUG:cmdSts=Q
DEBUG:cmdType=O
DEBUG:port=5432
DEBUG:pid=24252
DEBUG:from_host=serverB
DEBUG:dbName=test
DEBUG:userName=test
DEBUG:recieve sec=1105075624
DEBUG:recieve usec=981294
DEBUG:query_size=76
DEBUG:query=CREATE TABLE test (
    id serial NOT NULL,
    name character varying(20)
)
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:PGRsend_replicate_packet_to_server():host(serverA) : port(5432)
DEBUG:pgr_createConn():PQsetdbLogin host[serverA] port[5432] db[test] user[test]
DEBUG:pgr_createConn():PQsetdbLogin ok!!
DEBUG:PGRsend_replicate_packet_to_server():connect db:test port:5432 user:test host:serverA qu
ery:CREATE TABLE test (
    id serial NOT NULL,
    name character varying(20)
)
DEBUG:PGRsend_replicate_packet_to_server():sync_command(SELECT PGR_SYSTEM_COMMAND_FUNCTION(3,110
5075624,981294,2) )
NOTICE:  CREATE TABLE will create implicit sequence 'test_id_seq' for SERIAL column 'test.id'
DEBUG:PGRsend_replicate_packet_to_server():PQexec send :CREATE TABLE test (
    id serial NOT NULL,
    name character varying(20)
)
DEBUG:sem_lock[3]
DEBUG:sem_unlock[2]
DEBUG:PGRreturn_result():PGRreturn_result[6]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_unlock[3]
DEBUG:PGRdo_replicate():query :: COPY test (id, name) FROM stdin
DEBUG:cmdSts=Q
DEBUG:cmdType=C
DEBUG:port=5432
DEBUG:pid=24252
DEBUG:from_host=serverB
DEBUG:dbName=test
DEBUG:userName=test
DEBUG:recieve sec=1105075625
DEBUG:recieve usec=465008
DEBUG:query_size=31
DEBUG:query=COPY test (id, name) FROM stdin
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[3,1105075625,465008,2]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:PGRsend_replicate_packet_to_server():host(serverA) : port(5432)
DEBUG:PGRsend_replicate_packet_to_server():connect db:test port:5432 user:test host:serverA query:COPY test (id, name) FROM stdin
DEBUG:PGRsend_replicate_packet_to_server():sync_command(SELECT PGR_SYSTEM_COMMAND_FUNCTION(3,1105075625,465008,2) )
DEBUG:PGRsend_replicate_packet_to_server():PQexec send :COPY test (id, name) FROM stdin
DEBUG:sem_lock[3]
DEBUG:sem_unlock[2]
DEBUG:sem_unlock[3]
DEBUG:PGRdo_replicate():query ::
DEBUG:cmdSts=C
DEBUG:cmdType=e
DEBUG:port=5432
DEBUG:pid=24252
DEBUG:from_host=serverB
DEBUG:dbName=test
DEBUG:userName=test
DEBUG:recieve sec=1105075625
DEBUG:recieve usec=486300
DEBUG:query_size=27
DEBUG:query=
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[]
DEBUG:PGRreturn_result():128 send
DEBUG:sem_lock[2]
DEBUG:sem_unlock[1]
DEBUG:PGRsend_replicate_packet_to_server():host(serverA) : port(5432)
DEBUG:PGRsend_replicate_packet_to_server():connect db:test port:5432 user:test host:serverA query:
DEBUG:PGRdo_replicate():query :: SELECT pg_catalog.setval ('test_id_seq', 4, true)
DEBUG:cmdSts=Q
DEBUG:cmdType=S
DEBUG:port=5432
DEBUG:pid=24252
DEBUG:from_host=serverB
DEBUG:dbName=test
DEBUG:userName=test
DEBUG:recieve sec=1105075715
DEBUG:recieve usec=563267
DEBUG:query_size=49
DEBUG:query=SELECT pg_catalog.setval ('test_id_seq', 4, true)
DEBUG:sem_lock[1]
DEBUG:PGRreturn_result():PGRreturn_result[3,1105075715,563267,2]
DEBUG:PGRreturn_result():128 send
DEBUG:read_answer():answer[PGR_QUERY_DONE_NOTICE_CMD]
DEBUG:read_answer():QUERY DONE
DEBUG:sem_lock[2]





-------------------------------------
pg_restoreの後にクエリーを投げると．．
------------------------------------

DEBUG:PGRdo_replicate():query :: insert into test (name) VALUES ('bbb')
DEBUG:cmdSts=Q
DEBUG:cmdType=I
DEBUG:port=5432
DEBUG:pid=24688
DEBUG:from_host=serverB
DEBUG:dbName=test
DEBUG:userName=test
DEBUG:recieve sec=1105076261
DEBUG:recieve usec=313528
DEBUG:query_size=38
DEBUG:query=insert into test (name) VALUES ('bbb')
DEBUG:sem_lock[1]

が繰り返される．




高橋 一成 <kazunari.takahashi ＠ ctc-g.co.jp>

pgcluster メーリングリストの案内