2014年3月23日から28日までErogameScapeに接続できない事象が発生いたしました。
当時は大変ご迷惑をおかけいたしました。
※私が海外に行くたびに障害が発生するのはなぜなんでしょうか…
ちなみに先日8日間ドイツに行って参りましたが、今回は大丈夫でした…ドキドキです…
調査の結果、障害を発生させたスクリプトはつきとめたのですが、なぜそのスクリプトが悪いのかの原因は分かりませんでした。
以下に当時起こった事象を記しておきます。
ErogameScapeはpgpoolを使っています。
PostgreSQLは物理的なサーバー2台に配置していて冗長化されています。
3月22日5時30分、pgpoolにおいて、DB node 0が切り離されました。
3月23日5時30分、pgpoolにおいて、DB node 1が切り離されました。
この時のPostgreSQLのログは以下の通りです。
PostgreSQLのログを確認すると以下のような記録がありました。
この事象は必ず5時30分に起きるので、この時刻付近に起動するスクリプトが原因だと思いましたが、私が旅行中の出来事ですので、何も変更していません…
当時、その時刻に動いていそうなスクリプトは2つありました。
そのスクリプトを試しに止めて見ると事象が発生しなくなりました。
え?なんで?というのが正直な気持ちでした。
そこでPostgreSQLのログをもっと詳細にとりつつ、pgpoolもデバッグモードで起動して、ログを確認しました。
※ErogameScapeは小さいサービスですが、それでもすごい大量のログを吐くのでドキドキでした。
PostgreSQLのログは以下の通りです。
pgpoolのログは以下の通りです。
しかし、このスクリプトを普通に起動すると正常に動作が完了します。
なぜ5時20分に起動すると18秒後にBEGINしたまま止まるのか…原因が分かりませんでした。
100%再現するので何かと競合しているのですが、当時何もいじっていないので見当がつかず現在に至っています。
結局、そのスクリプトは「まあ、毎日動かさなくてもいいから、私が手動で動かせばいいかー」というものでしたので、気がついたら手動で動かしております。
大変ご迷惑をおかけいたしました。
今後ともよろしくお願いします。
当時は大変ご迷惑をおかけいたしました。
※私が海外に行くたびに障害が発生するのはなぜなんでしょうか…
ちなみに先日8日間ドイツに行って参りましたが、今回は大丈夫でした…ドキドキです…
調査の結果、障害を発生させたスクリプトはつきとめたのですが、なぜそのスクリプトが悪いのかの原因は分かりませんでした。
以下に当時起こった事象を記しておきます。
ErogameScapeはpgpoolを使っています。
PostgreSQLは物理的なサーバー2台に配置していて冗長化されています。
3月22日5時30分、pgpoolにおいて、DB node 0が切り離されました。
2014-03-22 05:30:01 LOG: pid 32311: postmaster on DB node 0 was shutdown by administrative command 2014-03-22 05:30:01 LOG: pid 32311: degenerate_backend_set: 0 fail over request from pid 32311 2014-03-22 05:30:01 LOG: pid 20333: starting degeneration. shutdown host erogamescape14(5432) 2014-03-22 05:30:01 LOG: pid 20333: Restart all children 2014-03-22 05:30:01 LOG: pid 20333: failover: set new primary node: -1 2014-03-22 05:30:01 LOG: pid 20333: failover: set new master node: 1 2014-03-22 05:30:02 LOG: pid 20333: failover done. shutdown host erogamescape14(5432) 2014-03-22 05:30:02 LOG: pid 29718: worker process received restart request 2014-03-22 05:30:03 LOG: pid 29717: pcp child process received restart request 2014-03-22 05:30:03 LOG: pid 20333: PCP child 29717 exits with status 256 in failover() 2014-03-22 05:30:03 LOG: pid 20333: fork a new PCP child pid 4058 in failover() 2014-03-22 05:30:03 LOG: pid 20333: worker child 29718 exits with status 256 2014-03-22 05:30:03 LOG: pid 20333: fork a new worker child pid 4059
3月23日5時30分、pgpoolにおいて、DB node 1が切り離されました。
2014-03-23 05:30:01 LOG: pid 2306: postmaster on DB node 1 was shutdown by administrative command 2014-03-23 05:30:01 LOG: pid 2306: degenerate_backend_set: 1 fail over request from pid 2306 2014-03-23 05:30:01 LOG: pid 20333: starting degeneration. shutdown host erogamescape13(5432) 2014-03-23 05:30:01 ERROR: pid 20333: failover_handler: no valid DB node found 2014-03-23 05:30:01 LOG: pid 20333: Restart all children 2014-03-23 05:30:01 LOG: pid 20333: failover: set new primary node: -1 2014-03-23 05:30:01 LOG: pid 20333: failover done. shutdown host erogamescape13(5432) 2014-03-23 05:30:01 LOG: pid 4059: worker process received restart request 2014-03-23 05:30:02 LOG: pid 4058: pcp child process received restart request 2014-03-23 05:30:02 LOG: pid 20333: PCP child 4058 exits with status 256 in failover() 2014-03-23 05:30:02 LOG: pid 20333: fork a new PCP child pid 4518 in failover() 2014-03-23 05:30:02 LOG: pid 20333: worker child 4059 exits with status 256 2014-03-23 05:30:02 LOG: pid 20333: fork a new worker child pid 4519nodeが2つとも切り離されちゃっているので、ApacheからPostgreSQLに接続できなくなってサービス中断です。
この時のPostgreSQLのログは以下の通りです。
DB node 0にあたるPostgreSQLのログ < 2014-03-22 05:30:01.538 JST >FATAL: terminating connection due to administrator command DB node 1にあたるPostgreSQLのログ < 2014-03-23 05:30:01.492 JST >FATAL: terminating connection due to administrator command何かがコネクションを解放しています。
PostgreSQLのログを確認すると以下のような記録がありました。
[root@erogamescape14 ap2]# cat /var/lib/pgsql/9.3/data/pg_log/postgresql-Fri.log | grep " 05:30:01" < 2014-03-28 05:30:01.268 JST > user=nobody p=7416 LOG: statement: DISCARD ALL < 2014-03-28 05:30:01.334 JST > user=nobody p=7416 LOG: statement: DISCARD ALL < 2014-03-28 05:30:01.472 JST > user=[unknown] p=7439 LOG: connection received: host=192.168.0.14 port=34851 < 2014-03-28 05:30:01.745 JST > user=nobody p=7062 LOG: statement: DISCARD ALL < 2014-03-28 05:30:01.754 JST > user=[unknown] p=7471 LOG: connection received: host=192.168.0.13 port=43955 < 2014-03-28 05:30:01.755 JST > user=[unknown] p=7472 LOG: connection received: host=[local] < 2014-03-28 05:30:01.755 JST > user=nobody p=7471 LOG: connection authorized: user=nobody database=ap2 < 2014-03-28 05:30:01.756 JST > user=ap2 p=7472 LOG: connection authorized: user=ap2 database=ap2 < 2014-03-28 05:30:01.757 JST > user=ap2 p=7472 LOG: statement: SELECT pg_terminate_backend(pid) < 2014-03-28 05:30:01.784 JST > user=nobody p=5117 LOG: disconnection: session time: 0:09:58.828 user=nobody database=ap2 host=192.168.0.13 port=43902 < 2014-03-28 05:30:01.794 JST > user=nobody p=7196 LOG: disconnection: session time: 0:02:11.888 user=nobody database=ap2 host=192.168.0.14 port=59202 < 2014-03-28 05:30:01.797 JST > user=nobody p=6216 LOG: disconnection: session time: 0:05:02.909 user=nobody database=ap2 host=192.168.0.14 port=54374 < 2014-03-28 05:30:01.844 JST > user=nobody p=7166 LOG: disconnection: session time: 0:02:22.012 user=nobody database=ap2 host=192.168.0.14 port=58929 < 2014-03-28 05:30:01.845 JST > user=nobody p=7217 LOG: disconnection: session time: 0:02:09.908 user=nobody database=ap2 host=192.168.0.14 port=59242赤字のSELECT文が実行されたので、pgpoolにおいてDB nodeが切り離されたことが確認されました。誰がSELECT pg_terminate_backend(pid)を実行しているのかが分かりません。
この事象は必ず5時30分に起きるので、この時刻付近に起動するスクリプトが原因だと思いましたが、私が旅行中の出来事ですので、何も変更していません…
当時、その時刻に動いていそうなスクリプトは2つありました。
そのスクリプトを試しに止めて見ると事象が発生しなくなりました。
え?なんで?というのが正直な気持ちでした。
そこでPostgreSQLのログをもっと詳細にとりつつ、pgpoolもデバッグモードで起動して、ログを確認しました。
※ErogameScapeは小さいサービスですが、それでもすごい大量のログを吐くのでドキドキでした。
PostgreSQLのログは以下の通りです。
< 2014-03-30 05:20:01.385 JST > user=[unknown] p=18477 LOG: connection received: host=192.168.0.14 port=35869 < 2014-03-30 05:20:01.386 JST > user=ap2 p=18477 LOG: connection authorized: user=ap2 database=ap2 < 2014-03-30 05:20:01.393 JST > user=ap2 p=18477 LOG: statement: < 2014-03-30 05:20:01.620 JST > user=ap2 p=18477 LOG: statement: BEGIN < 2014-03-30 05:20:01.621 JST > user=ap2 p=18477 LOG: statement: < 2014-03-30 05:20:01.622 JST > user=ap2 p=18477 LOG: statement: < 2014-03-30 05:20:01.623 JST > user=ap2 p=18477 LOG: statement: < 2014-03-30 05:20:01.624 JST > user=ap2 p=18477 LOG: statement: COMMIT < 2014-03-30 05:20:01.625 JST > user=ap2 p=18477 LOG: statement: BEGIN < 2014-03-30 05:20:01.626 JST > user=ap2 p=18477 LOG: statement: < 2014-03-30 05:20:01.626 JST > user=ap2 p=18477 LOG: statement: < 2014-03-30 05:20:01.627 JST > user=ap2 p=18477 LOG: statement: < 2014-03-30 05:20:01.628 JST > user=ap2 p=18477 LOG: statement: COMMIT 以下略 < 2014-03-30 05:20:18.793 JST > user=ap2 p=18477 LOG: statement: BEGIN < 2014-03-30 05:20:18.798 JST > user=ap2 p=18477 LOG: statement: < 2014-03-30 05:20:18.798 JST > user=ap2 p=18477 LOG: statement: < 2014-03-30 05:30:01.948 JST > user=[unknown] p=20374 LOG: connection received: host=[local] < 2014-03-30 05:30:01.949 JST > user=ap2 p=20374 LOG: connection authorized: user=ap2 database=ap2 < 2014-03-30 05:30:01.950 JST > user=ap2 p=20374 LOG: statement: SELECT pg_terminate_backend(pid) < 2014-03-30 05:30:02.008 JST > user=ap2 p= FATAL: terminating connection due to administrator command < 2014-03-30 05:30:02.008 JST > user=ap2 p=18477 LOG: disconnection: session time: 0:10:00.623 user=ap2 database=ap2 host=192.168.0.14 port=35869 < 2014-03-30 05:30:02.009 JST > user=nobody p=20018 LOG: disconnection: session time: 0:04:27.115 user=nobody database=ap2 host=192.168.0.14 port=46445 < 2014-03-30 05:30:02.009 JST > user=nobody p=19999 LOG: disconnection: session time: 0:04:38.157 user=nobody database=ap2 host=192.168.0.14 port=460265時20分18秒にBEGINではじまったトランザクションが終わらないっぽくて、おそらく…pgpoolが何かを検知してSELECT pg_terminate_backend(pid)を発行しています。その結果、pgpoolからPostgreSQLが切り離されます。
pgpoolのログは以下の通りです。
2014-03-30 05:30:02 LOG: pid 21726: postmaster on DB node 1 was shutdown by administrative command
2014-03-30 05:30:02 LOG: pid 21726: degenerate_backend_set: 1 fail over request from pid 21726
2014-03-30 05:30:02 LOG: pid 27495: starting degeneration. shutdown host erogamescape13(5432)
2014-03-30 05:30:02 LOG: pid 27495: Restart all children
2014-03-30 05:30:02 LOG: pid 27495: failover: set new primary node: -1
2014-03-30 05:30:02 LOG: pid 27495: failover: set new master node: 0
2014-03-30 05:30:02 LOG: pid 27800: worker process received restart request
2014-03-30 05:30:02 LOG: pid 27495: failover done. shutdown host erogamescape13(5432)
2014-03-30 05:30:03 LOG: pid 27799: pcp child process received restart request
2014-03-30 05:30:03 LOG: pid 27495: PCP child 27799 exits with status 256 in failover()
2014-03-30 05:30:03 LOG: pid 27495: fork a new PCP child pid 24558 in failover()
2014-03-30 05:30:03 LOG: pid 27495: worker child 27800 exits with status 256
2014-03-30 05:30:03 LOG: pid 27495: fork a new worker child pid 24559
2014-03-30 05:32:00 LOG: pid 24454: pool_send_and_wait: Error or notice message from backend: : DB node id: 0 backend pid: 25060 statement:
5時20分に開始するスクリプトはBEGINしてCOMMITしてを繰り返すスクリプトでしたので、このスクリプトが原因だ!と分かりました。しかし、このスクリプトを普通に起動すると正常に動作が完了します。
なぜ5時20分に起動すると18秒後にBEGINしたまま止まるのか…原因が分かりませんでした。
100%再現するので何かと競合しているのですが、当時何もいじっていないので見当がつかず現在に至っています。
結局、そのスクリプトは「まあ、毎日動かさなくてもいいから、私が手動で動かせばいいかー」というものでしたので、気がついたら手動で動かしております。
大変ご迷惑をおかけいたしました。
今後ともよろしくお願いします。