[pgsql-jp: 37840] Re: kind mismatch between backends
Tatsuo Ishii
ishii ＠ sraoss.co.jp
2006年 12月 22日 (金) 15:06:26 JST
石井です．
> 中井です。
>
> ありがとうございます。
どういたしまして．
> Tatsuo Ishii wrote:
> > とりあえずエラーが発生したときのpgpoolのエラーログを見せていただけます
> > か? また，同じテーブルに関する他の種類のSELECT文ではエラーは出ないの
> > でしょうか?
>
> 必ずエラーが出るわけではないです。
>
> 2006-12-22 08:31:00 LOG: pid 22580: statement: show pool_status
> ;
> 2006-12-22 08:31:01 LOG: pid 22930: statement: RESET ALL
> 2006-12-22 08:31:01 LOG: pid 22930: statement: SET SESSION
> AUTHORIZATION DEFAULT
> 2006-12-22 08:31:01 LOG: pid 22930: statement: DEALLOCATE "S_1"
> 2006-12-22 08:31:01 LOG: pid 22930: statement: DEALLOCATE "S_2"
> 2006-12-22 08:31:14 LOG: pid 22930: statement: RESET ALL
> 2006-12-22 08:31:14 LOG: pid 22930: statement: SET SESSION
> AUTHORIZATION DEFAULT
> 2006-12-22 08:31:14 LOG: pid 22930: statement: DEALLOCATE "S_1"
> 2006-12-22 08:31:14 LOG: pid 22930: statement: DEALLOCATE "S_2"
> 2006-12-22 08:31:22 LOG: pid 22930: statement: RESET ALL
> 2006-12-22 08:31:22 LOG: pid 22930: statement: SET SESSION
> AUTHORIZATION DEFAULT
> 2006-12-22 08:31:22 LOG: pid 22930: statement: DEALLOCATE "S_1"
> 2006-12-22 08:31:22 LOG: pid 22930: statement: DEALLOCATE "S_2"
> 2006-12-22 08:31:39 LOG: pid 22580: statement: RESET ALL
> 2006-12-22 08:31:39 LOG: pid 22580: statement: SET SESSION
> AUTHORIZATION DEFAULT
> 2006-12-22 08:32:12 ERROR: pid 22580: read_kind: kind does not match
> between backends master(82) secondary(69)
> 2006-12-22 08:32:46 LOG: pid 22580: statement: select * from workflow
> 2006-12-22 08:33:14 LOG: pid 22580: statement: RESET ALL
> 2006-12-22 08:33:14 LOG: pid 22580: statement: SET SESSION
> AUTHORIZATION DEFAULT
> 2006-12-22 08:33:36 LOG: pid 22580: statement: select * from workflow
> 2006-12-22 08:33:36 LOG: pid 22580: statement: RESET ALL
> 2006-12-22 08:33:36 LOG: pid 22580: statement: SET SESSION
> AUTHORIZATION DEFAULT
> 2006-12-22 08:34:18 LOG: pid 22930: statement: select * from workflow
> 2006-12-22 08:35:46 ERROR: pid 22930: ProcessFrontendResponse: failed to
> read kind from frontend. fronend abnormally exited
> 2006-12-22 08:35:46 LOG: pid 22930: do_child: exits with status 1 due
> to error
> 2006-12-22 08:37:00 LOG: pid 22580: statement: RESET ALL
> 2006-12-22 08:37:00 LOG: pid 22580: statement: SET SESSION
> AUTHORIZATION DEFAULT
> 2006-12-22 08:37:00 LOG: pid 22580: statement: DEALLOCATE "S_1"
> 2006-12-22 08:37:00 LOG: pid 22580: statement: DEALLOCATE "S_2"
> 2006-12-22 08:39:02 ERROR: pid 22580: pool_check_fd: data is not ready
> tp->tv_sec 5 tp->tp_usec 5000000
> 2006-12-22 08:39:02 ERROR: pid 22580: pool_process_query: secondary data
> is not ready at synchronous point. abort this session
> 2006-12-22 08:39:02 ERROR: pid 22580: pool_process_query: kind does not
> match between backends master(E) secondary( (~'@)
> 2006-12-22 08:39:02 ERROR: pid 22580: health check failed during write.
> master at port 9999 is down
> 2006-12-22 08:39:02 LOG: pid 22580: notice_backend_error: master: 1
> fail over request from pid 22580
> 2006-12-22 08:39:02 LOG: pid 12091: starting degeneration. shutdown
> master host (9999)
> 2006-12-22 08:39:02 LOG: pid 12091: degeneration done. shutdown master
> host (9999)
>
> pid 22580 は、ssh で入って psql でデータベースを検査していた
> ところです。show pool_status; の結果は正常でした。
> 動作チェックで select * を行う前に、最初のエラーメッセージが
> 出ています。でも画面(psql)では、エラーがでませんでした。
これですね．
> 2006-12-22 08:32:12 ERROR: pid 22580: read_kind: kind does not match
> between backends master(82) secondary(69)
82は"R"で，認証要求のパケットです．なのでたぶんこれは正常．secondaryの
69("i")が変ですね．これは"Empty Query Response"で，空のクエリを送った
ときの応答です．なぜこんなものが返ってくるのか...調べてみます．
ところで，
> 2006-12-22 08:37:00 LOG: pid 22580: statement: DEALLOCATE "S_1"
> 2006-12-22 08:37:00 LOG: pid 22580: statement: DEALLOCATE "S_2"
というのがあります．pid 22580はpsqlで接続しているんですよね?このメッセー
ジはprepared queryが使われたことを示していますが，実際使ってますか?
> 何回かやっているうちにハングしてしまいました。
これですね．
> 2006-12-22 08:39:02 ERROR: pid 22580: pool_process_query: secondary data
> is not ready at synchronous point. abort this session
> 2006-12-22 08:39:02 ERROR: pid 22580: pool_process_query: kind does not
> match between backends master(E) secondary( (~'@)
これは，secondaryから応答が返ってこなくなり，タイムアウトしたことを示
しています．確認ですが，secondaryのpostmasterをshutdownするとか，そう
いう操作はされていないですよね?
> 従って、この時点では、データベースに異常があったとはわかりません
> でした。
> # 変ですね。
>
> エラー行 08:39:02 の secondary の kind は化けています。
> この時点でアプリケーションがエラーを返し、アプリケーションのログに
> kind does not smatch が残りました。
> このあとしばらくたってから、エラーメッセージ(08:39:02のもの)メールが
> 届いて気づきました。縮退運転に入るとメールを飛ばすようにしてあるのです。
> 08:32:12の時点では、縮退運転に入っていませんでした。
> # これも変ですね。
これですね．
> 2006-12-22 08:39:02 ERROR: pid 22580: health check failed during write.
> master at port 9999 is down
pgpoolから見ると，masterのhealth checkに失敗しているように見えます．
ログだけ見ると，postmasterをshutdownしているように見えるのですが...
> 宜しくお願いします。
>
> 追伸：エラーログファイルはopenしぱなっしなんですね。logrotateしようと
> しましたが、rotateした最新ファイルは空でした。あせりました。
はい，さすがにログに書きにいくたびにopenしたのでは遅すぎますので．
HUPシグナルか何かでcloseするようなことを考えてみます．
--
Tatsuo Ishii
SRA OSS, Inc. Japan
pgsql-jp メーリングリストの案内