[pgsql-jp: 37842] Re: kind mismatch between backends
Hisakazu Nakai
nakai ＠ shinko.co.jp
2006年 12月 22日 (金) 17:02:33 JST
中井です。
お世話になります。
# とても光栄です。
Tatsuo Ishii wrote:
> 石井です．
>
>> 中井です。
>>
>> ありがとうございます。
>
> どういたしまして．
>
>> 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"で，空のクエリを送った
> ときの応答です．なぜこんなものが返ってくるのか...調べてみます．
show pool_status以外なにもしていないときなんです。
kind does not match で直ちに縮退運転に入るわけではないんですね。
> ところで，
>
>> 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するとか，そう
> いう操作はされていないですよね?
少なくともsecondaryでは何もしていません。
master側でpsql接続で検査していただけです。
ハングしたので、master側で、一つずつ子供のプロセスから
kill していきました。汗；
>> 従って、この時点では、データベースに異常があったとはわかりません
>> でした。
>> # 変ですね。
>>
>> エラー行 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しているように見えるのですが...
ドキッ。ps で Idle になっていた psql は kill しましたが、
postmaster には手をつけていません。今、ps で見ても、postmaster は
生きていますし、PID も pgpool より小さい値だし。（未だ、一周していない）
history で確認しましたが、若い PID しか kill していないです。
master at port 9999 is down というは、socket open できなかったという
ことでしょうか。
「secondaryの応答がないので、health check して master が死んでいるから
master を切り離した。」んですね。ますますわからなくなってきました。
>> 追伸：エラーログファイルはopenしぱなっしなんですね。logrotateしようと
>> しましたが、rotateした最新ファイルは空でした。あせりました。
>
> はい，さすがにログに書きにいくたびにopenしたのでは遅すぎますので．
> HUPシグナルか何かでcloseするようなことを考えてみます．
宜しくお願いします。
HUPシグナルの件は急ぎません。
--
-=-=-=-= SHINKO ELECTRIC INDUSTRIES CO., LTD. =-=-=-=-
=-=-=-=- Research & Development Div. -=-=-=-=
-=-=-=-= Infomation Technology Research Dept. =-=-=-=-
=-=-=-=- Name:Hisakazu Nakai TEL:026-263-3922 -=-=-=-=
-=-=-=-= Mail:nakai ＠ shinko.co.jp FAX:026-263-4562 =-=-=-=-
pgsql-jp メーリングリストの案内