[pgcluster: 297] リカバリ中のサービス継続について

fukushima fukushima ＠ verf.co.jp
2004年 5月 26日 (水) 01:14:50 JST 

三谷様

はじめまして、PGClusterを検証させて頂いております、
福島と申します。

レプリケーション機能について、いつくか質問（ご相談）させていただきたく、
宜しくお願いします。

【環境】
バージョン：pgcluster-1.0.6cv14
実機：Solaris9(sparc) 4台
構成：レプリケーション1台、クラスタ3台
	wt001152（マスタクラスタ）
	wt001153（クラスタ）
	wt001154（クラスタ）
	wt001156（レプリケータ）
	wt001159（検証機）

【状況】
・検証機より、insertクエリを1000件（Perlスクリプトにて）wt001153に発行しレプリケーション確認
	→クラスタ3台全てにレプリケーションOK
・上記クエリ中3台目（wt001154）クラスタサーバのpostmasterをkillし、リカバリテスト
	→2台目（wt001153）クラスタは全て連続1000件レプリケーションされるものの、
	　1台目（wt001152）マスタクラスタと3台目（wt001154）クラスタは、
	　rsync後のキューイングが復旧されず

【質問】
上記現象ですが，DEBUGログとソースコードを追いかけてみた結果を以下に示します．
(replicaterのみですが)

  なお，'自プロセスID'と'ファイル:行数'を表示するよう，pgrp/show.c
  (とpgrp/replicate.c, recovery.c, main.cのshow_debugコール部)に
  手を入れています．


【1】 recoveryプロセスのsecond_setup_recoveryまで正常に進行

 DEBUG(16045) send_recovery_packet [recovery.c:706] 2nd master wt001152 - 5432
 DEBUG(16045) send_recovery_packet [recovery.c:708] 2nd target wt001154 - 5432
 DEBUG(16045) send_recovery_packet [recovery.c:710] second_setup_recovery end :1 
 DEBUG(16045) send_recovery_packet [recovery.c:810] wait recovery


【2】 直後の更新クエリから，replicateプロセスでキューイングを開始．
 
 DEBUG(16048) PGRread_packet [replicate.c:2614] read[89] query[                 
                                    insert into id_list values(  '748' )]
 DEBUG(16048) PGRread_packet [replicate.c:1976] query ::                        
                             insert into id_list values(  '748' )
 DEBUG(16048) PGRset_queue [replicate.c:1509] msgsnd header rtn:0
 DEBUG(16048) PGRset_queue [replicate.c:1516] msgsnd query rtn:0
    ※ queryの先頭に53byte程度の空白が入っているのが，少し気になります．動作上
       問題はないと思いますが，メッセージキューの領域が飽和しやすくなるのでは，と．．．


【3】 rsync終了の通知をリカバリプロセスが受信．

 DEBUG(16045) send_recovery_packet [recovery.c:814] recovery main: selected
 DEBUG(16045) pgrecovery_loop [recovery.c:645] recovery accept port 7778
 DEBUG(16045) read_packet [recovery.c:143] receive packet
 DEBUG(16045) read_packet [recovery.c:823] no = 9
 DEBUG(16045) read_packet [recovery.c:824] max_connect = 256
 DEBUG(16045) read_packet [recovery.c:825] port = 5432
 DEBUG(16045) read_packet [recovery.c:826] recoveryPort = 7779
 DEBUG(16045) read_packet [recovery.c:828] hostName = wt001154
 DEBUG(16045) read_packet [recovery.c:830] pg_data = /data/pgcluster/data
 DEBUG(16045) read_packet [recovery.c:685] receive packet no:9
 DEBUG(16045) read_packet [recovery.c:720] last master wt001152 - 5432
 DEBUG(16045) read_packet [recovery.c:722] last target wt001154 - 5432


【4】 master,targetクラスタ名を正しく認識．

 DEBUG(16045) PGRsend_queue [recovery.c:544] master wt001152 - 5432
 DEBUG(16045) PGRget_HostTbl [recovery.c:553] target wt001154 - 5432


【5】 getDBServerTblでmasterが見つからないため，setDBServerTblでmasterとコネクション確立

 DEBUG(16045) PGRsend_replicate_packet_to_server [replicate.c:1161] host(wt001152) : port(5432)
 DEBUG(16045) getDBServerTbl [replicate.c:148] search host is (wt001152)
 DEBUG(16045) getDBServerTbl [replicate.c:164] not found
 DEBUG(16045) setDBServerTbl [replicate.c:185] host:wt001152 dbName:pgctest
 DEBUG(16045) getDBServerTbl [replicate.c:148] search host is (wt001152)
 DEBUG(16045) getDBServerTbl [replicate.c:164] not found
 DEBUG:  InitPostgres
 DEBUG:  StartTransactionCommand
 DEBUG:  ProcessUtility
 DEBUG:  CommitTransactionCommand
 DEBUG:  StartTransactionCommand
 DEBUG:  ProcessQuery
 DEBUG:  ProcessUtility
 DEBUG:  CommitTransactionCommand
 DEBUG(16045) pgr_createConn [replicate.c:330] PQsetdbLogin ok!!


【6】 以下のメッセージが出て，insert失敗(Solaris環境のみ発現)．

 DEBUG(16045) insertDBServerTbl [replicate.c:1257] send_replicate_packet_to_server query=                   
                                  insert into id_list values(  '748' )Mode
 DEBUG(16045) insertDBServerTbl [replicate.c:1270] db:pgctest port:5432 user:postgres host:wt001152 query:                   
                                  insert into id_list values(  '748' )Mode
 DEBUG(16045) insertDBServerTbl [replicate.c:1280] sync_command(SELECT PGR_SYSTEM_COMMAND_FUNCTION(3,1085048789,0) )
 cmd type[I]
 DEBUG:  StartTransactionCommand
 DEBUG:  CommitTransactionCommand
 DEBUG:  StartTransactionCommand
 DEBUG:  AbortCurrentTransaction
 type[I]
 DEBUG(16045) insertDBServerTbl [replicate.c:1344] PQexec send :                    
                                  insert into id_list values(  '748' )Mode
 DEBUG(16045) insertDBServerTbl [replicate.c:1422] PQexec end

  ※ insert文の最後に'Mode'という文字列がついているようです．
     Linux環境では，'Mode'はついておらず，masterへのinsertが成功しています．
       ちなみに，1byte長いinsert文で実験したら，'ode'がinsert文の最後につきました．
       'ode'の後がNull終端されていると推測し，更に3byte長いinsert文で実験したら
       masterへのinsertが成功しました．


【7】 AbortCurrentTransactionが出力されているが，リカバリ処理は
      続行している模様(targetへinsert発行)．

 DEBUG(16045) PGRsend_replicate_packet_to_server [replicate.c:1161] host(wt001154) : port(5432)


【8】 targetのアドレス取得に失敗し，コネクションを確立できず
      リカバリ処理が異常終了している模様．(Solaris，Linux共に発現)

 DEBUG(16045) getDBServerTbl [replicate.c:148] search host is (wt001154)
 DEBUG(16045) getDBServerTbl [replicate.c:153] search host(-1744721728):port(5432):db(pgctest)
 DEBUG(16045) getDBServerTbl [replicate.c:164] not found
 DEBUG(16045) setDBServerTbl [replicate.c:185] host:wt001154 dbName:pgctest
 DEBUG(16045) getDBServerTbl [replicate.c:148] search host is (wt001154)
 DEBUG(16045) getDBServerTbl [replicate.c:153] search host(-1744721728):port(5432):db(pgctest)
 DEBUG(16045) getDBServerTbl [replicate.c:164] not found
 ERROR(16045) pgr_createConn [replicate.c:313] PQsetdbLogin failed. close socket!!
 ERROR(16045) pgr_createConn [replicate.c:313] PQsetdbLogin failed. close socket!!
 ERROR(16045) pgr_createConn [replicate.c:313] PQsetdbLogin failed. close socket!!
 ERROR(16045) pgr_createConn [replicate.c:313] PQsetdbLogin failed. close socket!!
 ERROR(16045) pgr_createConn [replicate.c:313] PQsetdbLogin failed. close socket!!
 ERROR(16045) pgr_createConn [replicate.c:325] dbPersistLogin  timeout
 ERROR(16045) pgr_createConn [replicate.c:215] pgr_createConn failed
 ERROR(16045) write_log_file [replicate.c:1233] setDBServerTbl failed
 ERROR(16045) write_log_file [recovery.c:606] PGRsend_replicate_packet_to_server to target error
 DEBUG(16045) write_log_file [recovery.c:624] send_queue return status -1
 ERROR(16045) write_log_file [recovery.c:737] PGRsend_queue failed
 DEBUG(16045) PGRsend_load_balance_packet [recovery.c:810] wait recovery

    ※ pgrp/replicate.c:153行目 のデバッグログに出力されるsearch対象のtargetアドレスが
       master[wt001152]のアドレスになっていますが，target[wt001154]を
       特定できない現象と関連があるでしょうか？


Linux（Redhat8）環境でも同様な環境にて検証いたしましたが、上記のような類似した
現象が発生しております。
更新系の連続運用（対障害性）について重きをおき検証していますが、三谷様の方でも
このような検証実績はございますでしょうか。。。

以上、長くなりましたが宜しくお願い致します。

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