PostgreSQL/Pgpool-II/フェイルオーバー

ストリーミングレプリケーションモードを前提に記述する。

フェイルオーバー †

バックエンドノードへの障害が発生した場合、残りの稼働しているノードで運用を継続する。
障害発生したノードに対するコネクションの切り替え及びバックエンドのプライマリノードの切り替え（failover_commandの実行）機能を提供する。
なお、バックエンドのプライマリノードへの切り替えは、Pgpool2の出口コマンドを使用しなくとも可能である。
任意の外部のプログラムに任せても良い。

 補足 
ただし、Pgpoolが内部で管理するノードのステータス更新と整合性がとれた状態にする必要があるだろう。
Pgpoolのフェイルオーバ処理の中のプライマリノード検出処理のタイミングできちんとプライマリノードが切り替わっているなど。

フェイルオーバーのタイミング †

• ヘルスチェックのタイムアウト
• バックエンドへのコネクション接続エラー
• バックエンドへのread/writeエラー

など

フェイルオーバーの内部動作 †

• フェイルオーバー契機が与えられると、フェイルオーバーリクエストが共有メモリ上の待ち行列に書き込まれる。続いて、フェイルオーバー処理依頼のシグナル（SIGUSR1）が親プロセスに送信される。
  参考register_node_operation_request() - on https://git.postgresql.org/gitweb/?p=pgpool2.git
• フェイルオーバー処理はPgpoolの親プロセスで実行され、以下の関数で行われる。
  参考failover() - on https://git.postgresql.org/gitweb/?p=pgpool2.git

フェイルオーバーの設定 †

• fail_over_on_backend_errorまたはhealth_check_periodの指定（1以上整数）が必要。
  いずれも設定されていない状態で、プライマリノード障害が発生した場合、クライアントからの接続は成功せず以下のエラーとなる。
  

  psql: FATAL:  failed to create a backend 0 connection
  DETAIL:  not executing failover because fail_over_on_backend_error is off

  なお、health_checkは親プロセスからforkしたworkerプロセスで実施される。参考do_health_check_child()
  health_checkがタイムアウトすると、degenerate_backend_set関数が呼ばれフェイルオーバーリクエストが待ち行列に追加され、フェイルオーバー処理を通知するシグナルがpgpoolの親プロセスに送信される。

フェイルオーバープロセス概要 †

failover()関数の処理概要は以下の通りである。（詳細は、ソースコードを参照のこと）

1. 共有メモリの待ち行列にスイッチ中のフラグを立て、待ち行列のリクエスト処理ループに入る。
   1. 待ち行列のセマフォのロック。待ち行列にリクエストがなければ、アンロックして終了。
   2. 待ち行列からリクエストを取り出し、セフォマのアンロック。
   3. リクエストが「CLOSE_IDLE_REQUEST」ならば、すべての子プロセスにSIGUSR1シグナルを送信する。
      （子プロセスは、SIGUSR1シグナルを受信するとアイドル状態のバックエンド接続を閉じる）
   4. watchdogが有効ならば、watchdogにフェイルオーバー処理を通知する。
   5. 待ち行列のリクエストごとに以下の分岐
      • NODE_UP_REQUESTの場合
        ・バックエンドが全てダウンしていないか調べる。
        ・バックエンドのステータスをCON_CONNECT_WAITにセットする。
        ・リクエストがREQ_DETAIL_UPDATEでなければfailback_commandを実行する。
        
      • PROMOTE_NODE_REQUESTの場合
        node_idがVALID_BACKENDでなければループをcontinueする。
      • NODE_DOWN_REQUEST && NODE_QUARANTINE_REQUESTの場合
        プライマリノードがダウンした場合など、このステップを通過する。NODE_QUARANTINE_REQUESTは、watchdogでクォーラムを組んでいる時のリクエスト種別である。ここで、障害でダウンしたデータベースノードを調べる。
   6. 新しいマスタノードを決める。
   7. 待ち行列のリクエストごとに以下の分岐
      
      • ストリーミングレプリケーションかつNODE_UP_REQUESTかつバックエンドが全てダウンしていない場合
        need_to_restart_children = false、partial_restart = false
      • ストリーミングレプリケーションかつ(NODE_DOWN_REQUESTまたはNODE_QUARANTINE_REQUEST)かつREQ_DETAIL_SWITCHOVERでプライマリノードでない場合
        need_to_restart_children = true、partial_restart = true
      • それ以外（プライマリノードダウンはここ）
        すべての子プロセスにシグナルSIGQUITが送信される（すべての子プロセスは終了する）。子プロセス再起動のフラグを立てる。
        need_to_restart_children = true、partial_restart = false
        （ユーザーからのリクエストをacceptする子プロセスがいなくなる。）
   8. 待ち行列のリクエストがNODE_DOWN_REQUESTの場合、failover_commandに指定されたスクリプトを実行する。新しいプライマリノード候補のpromoteが実行される。
   9. 新しいプライマリノードを探索（pg_is_in_recovery()でチェック、探索時間はsearch_primary_node_timeoutパラメータ）
   10. ストリーミングレプリケーションモードの場合、follow_master_commandを実行する。この動作は、プロセスをforkして子プロセスで実行される。
   11. need_to_restart_childrenがtrueであれば、子プロセスの再起動を行なう。need_to_restart_childrenがfalseの場合は、リスタートフラグを立てるだけ。（子プロセス中でセッションが終了したタイミングで再起動される。）
       参考check_restart_request() - on https://git.postgresql.org/gitweb/?p=pgpool2.git
   12. workerにSIGUSR1シグナル（再起動通知）を送信する。
   13. sync_requiredがtrueならば、watchdogのフェイルオーバの終了処理。
2. スイッチフラグを解除。
3. pcpプロセスにSIGUSR2シグナルを送信し、failover/failbackの完了を通知。
4. pcp再起動。

プライマリノードの検出 †

1 secのインターバルでsearch_primary_node_timeoutになるまでpg_is_in_recovery()関数を使ってプライマリノードの検出を試みる。
参考 verify_backend_node_status()

障害ケースとプロセス †

ケース：プライマリノード（プロセス）ダウン＋fail_over_on_backend_error = onの場合 †

<テスト条件>

• プライマリノード（プロセス）ダウン
  • pg_ctl -m i -D pgdata stop
• クライアント
  • psqlで更新クエリを連続実行
• pgpool 3.7RC1
  • num_init_children = 1
  • fail_over_on_backend_error = on
  • health_check_period = 0
• OS
  • Mac OS X
• PostgreSQL
  • 10.0

<実行>

連続クエリ実行中にプライマリノード障害を発生させ、親プロセスにシグナル送信される過程のスタックトレースが以下。
シグナル送信前にブレークポイントを設定している。

* thread #1: tid = 0x89d759, 0x0000000107d9ec63 pgpool`signal_user1_to_parent_with_reason(reason=SIG_FAILOVER_INTERRUPT) + 35 at pgpool_main.c:535, queue = 'com.apple.main-thread', stop reason = breakpoint 24.1
  * frame #0: 0x0000000107d9ec63 pgpool`signal_user1_to_parent_with_reason(reason=SIG_FAILOVER_INTERRUPT) + 35 at pgpool_main.c:535
    frame #1: 0x0000000107d9c4dc pgpool`register_node_operation_request(kind=NODE_DOWN_REQUEST, node_id_set=0x00007fff57e605c0, count=1, flags='\x01') + 460 at pgpool_main.c:508
    frame #2: 0x0000000107d9f458 pgpool`degenerate_backend_set_ex(node_id_set=0x00007fff57e60824, count=1, flags='\x01', error='\0', test_only='\0') + 1720 at pgpool_main.c:1089
    frame #3: 0x0000000107d9ed92 pgpool`degenerate_backend_set(node_id_set=0x00007fff57e60824, count=1, flags='\x01') + 50 at pgpool_main.c:1138
    frame #4: 0x0000000107d9ed54 pgpool`notice_backend_error(node_id=0, flags='\x01') + 148 at pgpool_main.c:988
    frame #5: 0x0000000107dd9ca8 pgpool`new_connection(p=0x00007fc8ec003248) + 792 at pool_connection_pool.c:873
    frame #6: 0x0000000107dd94e1 pgpool`pool_create_cp + 225 at pool_connection_pool.c:248
    frame #7: 0x0000000107dc9c1c pgpool`connect_backend(sp=0x00007fc8ed801f88, frontend=0x00007fc8ed800038) + 44 at child.c:868
    frame #8: 0x0000000107dc6795 pgpool`get_backend_connection(frontend=0x00007fc8ed800038) + 981 at child.c:2326
    frame #9: 0x0000000107dc465a pgpool`do_child(fds=0x00007fc8ebe00620) + 1898 at child.c:337
    frame #10: 0x0000000107d9aac0 pgpool`fork_a_child(fds=0x00007fc8ebe00620, id=0) + 160 at pgpool_main.c:607
    frame #11: 0x0000000107d979c6 pgpool`PgpoolMain(discard_status='\x01', clear_memcache_oidmaps='\0') + 1878 at pgpool_main.c:363
    frame #12: 0x0000000107d95ea8 pgpool`main(argc=9, argv=0x00007fff57e6b7a8) + 2232 at main.c:318
    frame #13: 0x00007fff920465ad libdyld.dylib`start + 1
    frame #14: 0x00007fff920465ad libdyld.dylib`start + 1

notice_backend_error関数の実行後、子プロセスはabortして終了する。参考pool_connection_pool.c#new_connection()

pgpoolのログは以下のとおりである。

2017-11-23 23:11:07: pid 87593: [CHILD:269] LOG:  DB node id: 0 backend pid: 87759 statement: insert into foo_t values(53);
2017-11-23 23:11:07: pid 87593: [CHILD:270] LOCATION:  pool_proto_modules.c:3116
2017-11-23 23:11:07: pid 87593: [CHILD:271] LOG:  DB node id: 0 backend pid: 87759 statement:  DISCARD ALL
2017-11-23 23:11:07: pid 87593: [CHILD:272] LOCATION:  pool_proto_modules.c:3116
2017-11-23 23:11:07: pid 87593: [CHILD:273] LOG:  DB node id: 1 backend pid: 87760 statement:  DISCARD ALL
2017-11-23 23:11:07: pid 87593: [CHILD:274] LOCATION:  pool_proto_modules.c:3116
2017-11-23 23:11:07: pid 87593: [CHILD:275] LOG:  connection closed.
2017-11-23 23:11:07: pid 87593: [CHILD:276] DETAIL:  retry to create new connection pool
2017-11-23 23:11:07: pid 87593: [CHILD:277] LOCATION:  pool_connection_pool.c:149
2017-11-23 23:11:07: pid 87593: [CHILD:278] LOG:  failed to connect to PostgreSQL server by unix domain socket
2017-11-23 23:11:07: pid 87593: [CHILD:279] DETAIL:  connect to "/tmp/.s.PGSQL.11002" failed with error "Undefined error: 0"
2017-11-23 23:11:07: pid 87593: [CHILD:280] LOCATION:  pool_connection_pool.c:522
2017-11-23 23:11:07: pid 87593: [CHILD:281] LOG:  received degenerate backend request for node_id: 0 from pid [87593]
2017-11-23 23:11:07: pid 87593: [CHILD:282] LOCATION:  pgpool_main.c:1053
2017-11-23 23:11:07: pid 87593: [CHILD:283] FATAL:  failed to create a backend connection
2017-11-23 23:11:07: pid 87593: [CHILD:284] DETAIL:  executing failover on backend  <== 子プロセスはabort
2017-11-23 23:11:07: pid 87593: [CHILD:285] LOCATION:  pool_connection_pool.c:876
2017-11-23 23:11:07: pid 87587: [MAIN:17] LOG:  Pgpool-II parent process has received failover request  <== 親プロセスでfailover開始
2017-11-23 23:11:07: pid 87587: [MAIN:18] LOCATION:  pgpool_main.c:1502
2017-11-23 23:11:07: pid 87587: [MAIN:19] LOG:  starting degeneration. shutdown host /tmp(11002)
2017-11-23 23:11:07: pid 87587: [MAIN:20] LOCATION:  pgpool_main.c:1714
2017-11-23 23:11:07: pid 87587: [MAIN:21] LOG:  Restart all children  <== 子プロセスは全てkillされる
2017-11-23 23:11:07: pid 87587: [MAIN:22] LOCATION:  pgpool_main.c:1835
2017-11-23 23:11:07: pid 87587: [MAIN:23] LOG:  execute command: /Users/guest/workspace/pgpool/test/etc/failover.sh 0 /tmp 11002 /Users/guest/workspace/pgpool/test/data0 1 0 /tmp 0 11003 /Users/guest/workspace/pgpool/test/data1
2017-11-23 23:11:07: pid 87587: [MAIN:24] LOCATION:  pgpool_main.c:2795
2017-11-23 23:11:07: pid 87587: [MAIN:25] LOG:  find_primary_node_repeatedly: waiting for finding a primary node
2017-11-23 23:11:07: pid 87587: [MAIN:26] LOCATION:  pgpool_main.c:2967
2017-11-23 23:11:07: pid 87587: [MAIN:27] LOG:  find_primary_node: checking backend no 0
2017-11-23 23:11:07: pid 87587: [MAIN:28] LOCATION:  pgpool_main.c:2910
2017-11-23 23:11:07: pid 87587: [MAIN:29] LOG:  find_primary_node: checking backend no 1
2017-11-23 23:11:07: pid 87587: [MAIN:30] LOCATION:  pgpool_main.c:2910
2017-11-23 23:11:07: pid 87587: [MAIN:31] LOG:  find_primary_node: primary node id is 1
2017-11-23 23:11:07: pid 87587: [MAIN:32] LOCATION:  pgpool_main.c:2940
2017-11-23 23:11:07: pid 87587: [MAIN:33] LOG:  starting follow degeneration. shutdown host /tmp(11002)
2017-11-23 23:11:07: pid 87587: [MAIN:34] LOCATION:  pgpool_main.c:1928
2017-11-23 23:11:07: pid 87587: [MAIN:35] LOG:  failover: 1 follow backends have been degenerated
2017-11-23 23:11:07: pid 87587: [MAIN:36] LOCATION:  pgpool_main.c:1946
=== follow_master_commandを実行するプロセスがforkされる ===
2017-11-23 23:11:07: pid 87587: [MAIN:37] LOG:  failover: set new primary node: 1
2017-11-23 23:11:07: pid 87587: [MAIN:38] LOCATION:  pgpool_main.c:1961
2017-11-23 23:11:07: pid 87587: [MAIN:39] LOG:  failover: set new master node: 1
2017-11-23 23:11:07: pid 87587: [MAIN:40] LOCATION:  pgpool_main.c:1968
=== ここで新しい子プロセスがforkされる ===
failover done. shutdown host /tmp(11002)2017-11-23 23:11:07: pid 87587: [MAIN:41] LOG:  failover done. shutdown host /tmp(11002)
2017-11-23 23:11:07: pid 87587: [MAIN:42] LOCATION:  pgpool_main.c:2074
2017-11-23 23:11:07: pid 87596: [WORKER:1] LOG:  worker process received restart request
2017-11-23 23:11:07: pid 87596: [WORKER:2] LOCATION:  pool_worker_child.c:155
2017-11-23 23:11:07: pid 88001: [UTILITY:1] LOG:  start triggering follow command. <== follow_master_commandが実行される
2017-11-23 23:11:07: pid 88001: [UTILITY:2] LOCATION:  pgpool_main.c:2995
2017-11-23 23:11:07: pid 88001: [UTILITY:3] LOG:  execute command: /Users/guest/workspace/pgpool/test/etc/follow_master.sh 0 /tmp 11002 /Users/guest/workspace/pgpool/test/data0 1 0 /tmp 0 11003 /Users/guest/workspace/pgpool/test/data1
2017-11-23 23:11:07: pid 88001: [UTILITY:4] LOCATION:  pgpool_main.c:2795
2017-11-23 23:11:07: pid 88002: [CHILD:1] LOG:  DB node id: 1 backend pid: 88004 statement: insert into foo_t values(55); <== クエリのリトライ
2017-11-23 23:11:07: pid 88002: [CHILD:2] LOCATION:  pool_proto_modules.c:3116
2017-11-23 23:11:07: pid 88002: [CHILD:3] LOG:  DB node id: 1 backend pid: 88004 statement:  DISCARD ALL
2017-11-23 23:11:07: pid 88002: [CHILD:4] LOCATION:  pool_proto_modules.c:3116

 メモ 

子プロセスはfailover関数の早いうちにSIGQUITシグナルを受信しexitするため、Pgpoolのソケットに対するacceptは実行されない。したがってクライアントは子プロセスが再起動されるまで待ち状態となる。（listenキューのバックログ）

実験 フェイルオーバー処理の途中でPgpoolへコネクション接続があった場合 †

以下のようなケースの場合はどうか検証してみる。それぞれ、デバッガーで停止させて検証してみた。

-- (1)
グローバルステータスをダウンに更新
-- (2)
ダウンしたノードに接続している子プロセスのkill

以下の(1)(2)は、スタンバイノードダウン＋fail_over_on_backend_error = onの場合も同様である。

• (1)の場合
  • グローバルのバックエンドステータス更新前かつ子プロセスにSIGQUITが送信される前にクライアントからのPgpoolへのコネクション接続があった場合、子プロセスはバックエンドの接続に失敗しexitするためクライアントのPgpoolへのコネクション接続は失敗する。
    グローバルのバックエンドステータスはノードダウンのリクエストが通知されるとfailover関数内でCON_DOWNに更新される。（ソース解析と動作からおそらくそうなる）
    参考pool_connection_pool.c#new_connection()
    仮に親プロセスのfailover処理が実行されずグローバルのバックエンドステータスがCON_DOWNに更新されない場合、preforkされている子プロセスはクライアントからPgpoolへのコネクション接続があるたびにバックエンドへのコネクション接続で失敗しexitする。num_init_childrenで設定された子プロセスが全てexitするとacceptする子プロセスがいなくなり、クライアントのPgpoolへのコネクション接続は待ち状態となる（listenキューのバックログ）。
• (2)の場合
  • 途中でEXEC_BAD_ACCESSになってしまう。

    * thread #1: tid = 0x130de1b, 0x000000010ecb7e5c pgpool`connect_backend(sp=0x00007fdc2c803588, frontend=0x00007fdc2c801638) + 652 at child.c:891, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x10)
      * frame #0: 0x000000010ecb7e5c pgpool`connect_backend(sp=0x00007fdc2c803588, frontend=0x00007fdc2c801638) + 652 at child.c:891
        frame #1: 0x000000010ecb4775 pgpool`get_backend_connection(frontend=0x00007fdc2c801638) + 981 at child.c:2326
        frame #2: 0x000000010ecb263a pgpool`do_child(fds=0x00007fdc2be00000) + 1898 at child.c:337
        frame #3: 0x000000010ec88a30 pgpool`fork_a_child(fds=0x00007fdc2be00000, id=3) + 160 at pgpool_main.c:607
        frame #4: 0x000000010ec85936 pgpool`PgpoolMain(discard_status='\x01', clear_memcache_oidmaps='\0') + 1878 at pgpool_main.c:363
        frame #5: 0x000000010ec83e18 pgpool`main(argc=9, argv=0x00007fff50f7d7a8) + 2232 at main.c:318
        frame #6: 0x00007fff920465ad libdyld.dylib`start + 1
        frame #7: 0x00007fff920465ad libdyld.dylib`start + 1

    が、おそらくBugだとは思う。コネクションスロットの参照でNULLポインタへアクセスしているためである。この時、psqlからの接続では以下のようなエラーが返ってくる。

    psql: server closed the connection unexpectedly
    	This probably means the server terminated abnormally
    	before or while processing the request.

    子プロセスが再起動され、DBコネクション接続のグローバルステータスが更新され、ローカルステータスも更新されると正常処理に戻る。
    なお、接続済みのプールされたコネクションも途中でソケットのbrokenチェックがされ、エラーであればcloseされて、またnew_connection()の処理へと進む。

実験 フェイルオーバー処理で新プライマリノードに切り替わらない場合 †

以下のケースではどうか。

failover() // 以下便宜上番号を振る
  1. グローバルステータスをダウンに更新
  2. ダウンしたノードに接続している子プロセスのkill
  3. failover_commandの実行（あれば） <-- 指定しない（新プライマリノードに切り替わらない場合）
  4. プライマリノードの検出
  5. follow_master_commandの実行（あれば）
  6. 子プロセス起動
  7. worker、popの再起動

この場合、負荷分散可能であれば、6番のステップ以降、スタンバイノードで処理が継続できる。
ただし、更新クエリを実行する場合はマスターノードが選択されるが、プライマリノードでないためエラーとなる。
参考 pool_set_node_to_be_sent()

* thread #1: tid = 0x168c4f3, 0x000000010f3c940d pgpool`send_to_where(node=0x00007fba6a8093e8, query="insert into foo_t (id) values (9999);") + 45 at pool_query_context.c:1185, queue = 'com.apple.main-thread', stop reason = step in
  * frame #0: 0x000000010f3c940d pgpool`send_to_where(node=0x00007fba6a8093e8, query="insert into foo_t (id) values (9999);") + 45 at pool_query_context.c:1185
    frame #1: 0x000000010f3c8766 pgpool`pool_where_to_send(query_context=0x00007fba6a022c38, query="insert into foo_t (id) values (9999);", node=0x00007fba6a8093e8) + 710 at pool_query_context.c:449
    frame #2: 0x000000010f3ae768 pgpool`SimpleQuery(frontend=0x00007fba6b800038, backend=0x000000010f85d078, len=38, contents="insert into foo_t (id) values (9999);") + 3528 at pool_proto_modules.c:480
    frame #3: 0x000000010f3b67ee pgpool`ProcessFrontendResponse(frontend=0x00007fba6b800038, backend=0x000000010f85d078) + 1134 at pool_proto_modules.c:2358
    frame #4: 0x000000010f39eb38 pgpool`read_packets_and_process(frontend=0x00007fba6b800038, backend=0x000000010f85d078, reset_request=0, state=0x00007fff5088e374, num_fields=0x00007fff5088e392, cont="\x01\377) + 4168 at pool_process_query.c:4729
    frame #5: 0x000000010f39cd3a pgpool`pool_process_query(frontend=0x00007fba6b800038, backend=0x000000010f85d078, reset_request=0) + 1226 at pool_process_query.c:226
    frame #6: 0x000000010f3967cd pgpool`do_child(fds=0x00007fba69e00000) + 2301 at child.c:383
    frame #7: 0x000000010f36ca40 pgpool`fork_a_child(fds=0x00007fba69e00000, id=1) + 160 at pgpool_main.c:607
    frame #8: 0x000000010f370558 pgpool`failover + 8424 at pgpool_main.c:2024
    frame #9: 0x000000010f36bc1c pgpool`sigusr1_interupt_processor + 1164 at pgpool_main.c:1511
    frame #10: 0x000000010f369d59 pgpool`PgpoolMain(discard_status='\x01', clear_memcache_oidmaps='\0') + 2921 at pgpool_main.c:436
    frame #11: 0x000000010f367e28 pgpool`main(argc=9, argv=0x00007fff508997a8) + 2232 at main.c:318
    frame #12: 0x00007fff920465ad libdyld.dylib`start + 1
    frame #13: 0x00007fff920465ad libdyld.dylib`start + 1

以下、sqlの実行例である。

$ psql -p 11000 -c "select count(*) from foo_t;" foo
 count 
-------
 10000
(1 row)

$ psql -p 11000 -c "insert into foo_t (id) values (9999);" foo
ERROR:  cannot execute INSERT in a read-only transaction

pgpoolのログも参考に掲載する。

以下は、フェイルオーバー処理実行のログである。

2017-12-02 19:59:43: [MAIN] pid 49506: LOG:  failover: no follow backends are degenerated
2017-12-02 19:59:43: [MAIN] pid 49506: LOCATION:  pgpool_main.c:1944
2017-12-02 19:59:43: [MAIN] pid 49506: LOG:  failover: set new primary node: -1    <-- プライマリノードは検出できず
2017-12-02 19:59:43: [MAIN] pid 49506: LOCATION:  pgpool_main.c:1966
2017-12-02 19:59:43: [MAIN] pid 49506: LOG:  failover: set new master node: 1
2017-12-02 19:59:43: [MAIN] pid 49506: LOCATION:  pgpool_main.c:1973

psqlでクエリを実行した時のログ。

2017-12-02 20:01:17: [CHILD] pid 52617: LOG:  DB node id: 1 backend pid: 53369 statement: select count(*) from foo_t;
2017-12-02 20:01:17: [CHILD] pid 52617: LOCATION:  pool_proto_modules.c:3116
2017-12-02 20:01:17: [CHILD] pid 52617: LOG:  DB node id: 1 backend pid: 53369 statement:  DISCARD ALL
2017-12-02 20:01:17: [CHILD] pid 52617: LOCATION:  pool_proto_modules.c:3116
2017-12-02 20:01:19: [CHILD] pid 52617: LOG:  DB node id: 1 backend pid: 53369 statement: insert into foo_t (id) values (9999);
2017-12-02 20:01:19: [CHILD] pid 52617: LOCATION:  pool_proto_modules.c:3116
2017-12-02 20:01:19: [CHILD] pid 52617: LOG:  pool_send_and_wait: Error or notice message from backend: : DB node id: 1 backend pid: 53369 statement: "insert into foo_t (id) values (9999);" message: "cannot execute INSERT in a read-only transaction"
2017-12-02 20:01:19: [CHILD] pid 52617: LOCATION:  pool_proto_modules.c:3132
2017-12-02 20:01:19: [CHILD] pid 52617: LOG:  DB node id: 1 backend pid: 53369 statement:  DISCARD ALL
2017-12-02 20:01:19: [CHILD] pid 52617: LOCATION:  pool_proto_modules.c:3116

pg_terminate_backend関数の使用について †

Pgpoolでは、pg_terminate_backend関数（kill SIGTERMも同じ）を実行した場合は、通常フェイルオーバーが動作してしまうので注意が必要である。直接データベースサーバに入って、コネクションを終了させたりする場合はフェイルオーバーが起きる。迂闊に実行するとフェイルオーバーが動作して？？となってしまう。

補足ただし、3.6以降？からは、特定の場合ではpg_terminate_backend関数でフェイルオーバーが起きないようになっている。具体的には、pg_terminate_backend関数に定数が渡された場合である。パースツリーからpg_terminate_backend関数の引数に指定された値を保持するConstノードを探している。しかし、pgpool経由でなければ、pgpool側で検出できないので注意。

• process_pg_terminate_backend_func() - on https://git.postgresql.org/gitweb/?p=pgpool2.git
• function_call_walker() - on https://git.postgresql.org/gitweb/?p=pgpool2.git
• http://www.pgpool.net/docs/latest/ja/html/release-3-6.html
• http://www.sraoss.jp/pipermail/pgpool-committers/2017-February/003801.html
• pool_process_query.c#read_packets_and_process()

実験 pg_terminate_backend関数のシチュエーションとフェイルオーバー †

• pgpoolから実行、ただし引数は定数・・・ フェイルオーバーしない

  foo=# select pg_terminate_backend(57261);
   pg_terminate_backend 
  ----------------------
   t
  (1 row)

  pgpool.logは以下。

  2017-12-09 11:31:24: [CHILD] pid 55479: LOG:  found the pg_terminate_backend request for backend pid:57261 on backend node:0
  2017-12-09 11:31:24: [CHILD] pid 55479: DETAIL:  setting the connection flag
  2017-12-09 11:31:24: [CHILD] pid 55479: LOCATION:  pool_proto_modules.c:147
  2017-12-09 11:31:24: [CHILD] pid 55479: LOG:  DB node id: 0 backend pid: 55979 statement: select pg_terminate_backend(57261);
  2017-12-09 11:31:24: [CHILD] pid 55479: LOCATION:  pool_proto_modules.c:3116
  2017-12-09 11:31:24: [CHILD] pid 56655: LOG:  reading and processing packets
  2017-12-09 11:31:24: [CHILD] pid 56655: DETAIL:  postmaster on DB node 0 was shutdown by administrative command
  2017-12-09 11:31:24: [CHILD] pid 56655: LOCATION:  pool_process_query.c:4662
  2017-12-09 11:31:24: [CHILD] pid 56655: FATAL:  connection to postmaster on DB node 0 was lost due to pg_terminate_backend
  2017-12-09 11:31:24: [CHILD] pid 56655: DETAIL:  pg_terminate_backend was called on the backend
  2017-12-09 11:31:24: [CHILD] pid 56655: LOCATION:  pool_process_query.c:4680
  2017-12-09 11:31:24: [CHILD] pid 56655: WARNING:  write on backend 0 failed with error :"Broken pipe"
  2017-12-09 11:31:24: [CHILD] pid 56655: DETAIL:  while trying to write data from offset: 0 wlen: 5
  2017-12-09 11:31:24: [CHILD] pid 56655: LOCATION:  pool_stream.c:678
  2017-12-09 11:31:24: [MAIN] pid 55472: LOG:  child process with pid: 56655 exits with status 256
  2017-12-09 11:31:24: [MAIN] pid 55472: LOCATION:  pgpool_main.c:2370
  2017-12-09 11:31:24: [MAIN] pid 55472: LOG:  fork a new child process with pid: 57362
  2017-12-09 11:31:24: [MAIN] pid 55472: LOCATION:  pgpool_main.c:2477

• pgpoolから実行、ただし引数は定数ではない・・・ フェイルオーバーする

  bar=# select pg_terminate_backend(pid) from pg_stat_activity where pid = 42245;
   pg_terminate_backend 
  ----------------------
   t
  (1 row)

• 直接PostgreSQLから実行 ・・・ フェイルオーバーする

  postgres=# select pg_terminate_backend(43952);
   pg_terminate_backend 
  ----------------------
   t
  (1 row)

• コネクションプールのコネクション（クライアントのセッションはクローズしている）・・・ フェイルオーバーしない

以上、まとめると以下のようになっている。

実験 pg_terminate_backend関数でフェイルオーバーを起こさせるが、failover_commandを指定しない場合 †

この場合、ダウンしたノードのグローバルのバックエンドステータスがCON_DOWNに更新されているため、実際にはプライマリノードが生きていても、プライマリノード検出関数内ではダウンしているものとみなされ（VALID_BACKENDマクロで失敗する）、生きているプライマリノードは検出されない。

参考 pgpool_main.c#find_primary_node()

Pgpoolから見るとプライマリノードはダウンしているように見えるが、

$ psql -p 11000 postgres
postgres=# show pool_nodes;
 node_id | hostname | port  | status | lb_weight |  role   | select_cnt | load_balance_node | replication_delay 
---------+----------+-------+--------+-----------+---------+------------+-------------------+-------------------
 0       | /tmp     | 11002 | down   | 0.500000  | standby | 0          | false             | 0
 1       | /tmp     | 11003 | up     | 0.500000  | standby | 0          | true              | 0
(2 rows)

$ cat log/pgpool_status 
down
up

しかし、実際はプライマリノードは生きている！

 |-+- 01677 guest /Users/guest/workspace/github/pgenv/versions/10.0/bin/postgres -D /Users/guest/workspace/pgpool/test/data0
 | |--= 01678 guest postgres: logger process
 | |--= 01680 guest postgres: checkpointer process
 | |--= 01681 guest postgres: writer process
 | |--= 01682 guest postgres: wal writer process
 | |--= 01683 guest postgres: autovacuum launcher process
 | |--= 01684 guest postgres: archiver process
 | |--= 01685 guest postgres: stats collector process
 | |--= 01686 guest postgres: bgworker: logical replication launcher
 | |--= 01696 guest postgres: wal sender process guest [local] streaming 0/5007900
 | \--= 02039 guest postgres: guest postgres [local] idle
 |-+- 01689 guest /Users/guest/workspace/github/pgenv/versions/10.0/bin/postgres -D /Users/guest/workspace/pgpool/test/data1
 | |--= 01690 guest postgres: logger process
 | |--= 01691 guest postgres: startup process   recovering 000000010000000000000005
 | |--= 01692 guest postgres: checkpointer process
 | |--= 01693 guest postgres: writer process
 | |--= 01694 guest postgres: stats collector process
 | |--= 01695 guest postgres: wal receiver process   streaming 0/5007900
 | \--= 06296 guest postgres: guest postgres [local] idle

pg_terminate_backend関数で指定されたバックエンドIDの検出 †

Pgpoolでは、実行されるクエリのパース結果から、pg_terminate_backend関数が使用されているか否かを検出するようになっている。

参考 pool_proto_modules.c#process_pg_terminate_backend_func()

以下のプロセスとなっている。

• クエリのパース木からpg_terminate_backend関数に指定されている引数（バックエンドpid）を抽出。
  参考pool_select_walker.c#function_call_walker()
• バックエンドpidが見つかれば、pgpoolの子プロセスのコネクションプールからバックエンドpidを探す。
• コネクションプールに見つかれば、コネクション情報にpg_terminate_backend関数から返されるエラーコードを無視するようフラグを立てる。
• クエリコンテキストに対し、特定のノードにクエリを投げるように設定する。

実験ネットワーク一時障害の場合（fail_over_on_backend_error = on） †

この場合どうなるか。一時的に不調であれば、パケットの再送でフェイルオーバしそうな気がする。
結論を言うと、フェイルオーバしなかった（Linux CentOS7/ Mac OS X 10.11.6)
（が、いつもこの結果となるかは分からない）

構成は以下の通り。

[app]
192.168.33.10 (primary:11002, standby:11003)
[Pgpool-3.7]
192.168.33.11:11000

パケットを覗いてみよう。ネットワーク正常時とネットワークが一時障害を起こした時のtcpdumpの結果をそれぞれ見てみる。

正常時

(a) pgpool --------------------------> (b) app

1) insert into users (id) select i from generate_series(1, 100000000) as i  --- (a)
2) psql -p 11002 -d postgres -c "select pg_terminate_backend(pid)"  --- (b)

tcpdumpの結果は以下（一部抜粋）

14:51:13.572295 IP 192.168.33.11.52328 > app.11002: Flags [P.], seq 79:156, ack 320, win 123, options [nop,nop,TS val 5509952 ecr 5626402], length 77
E....A@.@.....!...!            ## 1)
.h*.J..m..Q....{.......
.T.@.U."Q...Linsert into users (id) select i from generate_series(1, 100000000) as i. 
14:51:13.613144 IP app.11002 > 192.168.33.11.52328: Flags [.], ack 156, win 114, options [nop,nop,TS val 5626446 ecr 5509952], length 0
E..4..@.@.....!
..!.*..h..Q.J......r.......
.U.N.T.@
14:51:23.256179 IP app.11002 > 192.168.33.11.52328: Flags [P.], seq 320:437, ack 156, win 114, options [nop,nop,TS val 5636089 ecr 5509952], length 117
E.....@.@..+..!                ## 2)
..!.*..h..Q.J......r.......
.U...T.@E...tSFATAL.VFATAL.C57P01.Mterminating connection due to administrator command.Fpostgres.c.L2884.RProcessInterrupts..
14:51:23.257332 IP 192.168.33.11.52328 > app.11002: Flags [P.], seq 156:174, ack 437, win 123, options [nop,nop,TS val 5519638 ecr 5636089], length 18
E..F.B@.@..	..!...!
.h*.J.....Rf...{v......
.T9..U..Q.... DISCARD ALL.
14:51:23.257362 IP app.11002 > 192.168.33.11.52328: Flags [.], ack 174, win 114, options [nop,nop,TS val 5636091 ecr 5519638], length 0
E..4..@.@.....!
..!.*..h..RfJ......r.......
.U...T9.
14:51:23.302272 IP app.11002 > 192.168.33.11.52328: Flags [R.], seq 437, ack 174, win 114, options [nop,nop,TS val 5636135 ecr 5519638], length 0
E..4..@.@.....!          ## ここでRESET
..!.*..h..RfJ......r.......
.V.'.T9.
14:51:23.303289 IP 192.168.33.11.40718 > app.11003: Flags [F.], seq 79, ack 320, win 123, options [nop,nop,TS val 5519684 ecr 5626392], length 0
E..4..@.@.....!...!
..*.K..L...U...{!?.....
.T9D.U..
14:51:23.303954 IP app.11003 > 192.168.33.11.40718: Flags [F.], seq 320, ack 80, win 114, options [nop,nop,TS val 5636137 ecr 5519684], length 0
E..4T!@.@.#=..!
..!.*......UK..M...r.......
.V.).T9D
14:51:23.304327 IP 192.168.33.11.40718 > app.11003: Flags [.], ack 321, win 123, options [nop,nop,TS val 5519685 ecr 5636137], length 0
E..4..@.@.....!...!
..*.K..M...V...{.+.....
.T9E.V.)

一時障害後に復旧

(a) pgpool --------------------------> (b) app

1) insert into users (id) select i from generate_series(1, 100000000) as i  --- (a)
2) firewall-cmd --zone=drop --add-source=192.168.33.10 --- (a)
3) psql -p 11002 -d postgres -c "select pg_terminate_backend(pid)"  --- (b)

tcpdumpの結果は以下（一部抜粋）

14:11:02.944794 IP 192.168.33.11.52325 > app.11002: Flags [P.], seq 79:156, ack 320, win 123, options [nop,nop,TS val 3099327 ecr 3215775], length 77
E.....@.@.\-..!...!      ## 1)
.e*...P..T2....{_......
./J..1..Q...Linsert into users (id) select i from generate_series(1, 100000000) as i.
14:11:02.985263 IP app.11002 > 192.168.33.11.52325: Flags [.], ack 156, win 114, options [nop,nop,TS val 3215818 ecr 3099327], length 0
E..4 '@.@.W7..!
..!.*..e.T2...P....r.......
.1.../J.
14:11:17.827996 IP app.11002 > 192.168.33.11.52325: Flags [P.], seq 320:437, ack 156, win 114, options [nop,nop,TS val 3230661 ecr 3099327], length 117
E... (@.@.V...!          ## 2) 3)
..!.*..e.T2...P....r.......
.1K../J.E...tSFATAL.VFATAL.C57P01.Mterminating connection due to administrator command.Fpostgres.c.L2884.RProcessInterrupts..
14:11:17.856230 IP app.11002 > 192.168.33.11.52325: Flags [F.], seq 437, ack 156, win 114, options [nop,nop,TS val 3230689 ecr 3099327], length 0
E..4 )@.@.W5..!          ## FINを送信
..!.*..e.T3p..P....r.......
.1K../J.
14:11:18.071413 IP app.11002 > 192.168.33.11.52325: Flags [FP.], seq 320:437, ack 156, win 114, options [nop,nop,TS val 3230905 ecr 3099327], length 117
E... *@.@.V...!          ## 相手に届かず再送
..!.*..e.T2...P....r.......
.1L../J.E...tSFATAL.VFATAL.C57P01.Mterminating connection due to administrator command.Fpostgres.c.L2884.RProcessInterrupts..
14:11:18.479243 IP app.11002 > 192.168.33.11.52325: Flags [FP.], seq 320:437, ack 156, win 114, options [nop,nop,TS val 3231312 ecr 3099327], length 117
E... +@.@.V...!
..!.*..e.T2...P....r.......
.1NP./J.E...tSFATAL.VFATAL.C57P01.Mterminating connection due to administrator command.Fpostgres.c.L2884.RProcessInterrupts..
14:11:19.294382 IP app.11002 > 192.168.33.11.52325: Flags [FP.], seq 320:437, ack 156, win 114, options [nop,nop,TS val 3232128 ecr 3099327], length 117
E... ,@.@.V...!
..!.*..e.T2...P....r.......
.1Q../J.E...tSFATAL.VFATAL.C57P01.Mterminating connection due to administrator command.Fpostgres.c.L2884.RProcessInterrupts..
14:11:20.922377 IP app.11002 > 192.168.33.11.52325: Flags [FP.], seq 320:437, ack 156, win 114, options [nop,nop,TS val 3233756 ecr 3099327], length 117
E... -@.@.V...!
..!.*..e.T2...P....r.......
.1W../J.E...tSFATAL.VFATAL.C57P01.Mterminating connection due to administrator command.Fpostgres.c.L2884.RProcessInterrupts..
14:11:24.174385 IP app.11002 > 192.168.33.11.52325: Flags [FP.], seq 320:437, ack 156, win 114, options [nop,nop,TS val 3237008 ecr 3099327], length 117
E... .@.@.V...!
..!.*..e.T2...P....r.......
.1d../J.E...tSFATAL.VFATAL.C57P01.Mterminating connection due to administrator command.Fpostgres.c.L2884.RProcessInterrupts..
14:11:30.686421 IP app.11002 > 192.168.33.11.52325: Flags [FP.], seq 320:437, ack 156, win 114, options [nop,nop,TS val 3243520 ecr 3099327], length 117
E... /@.@.V...!
..!.*..e.T2...P....r.......
.1~../J.E...tSFATAL.VFATAL.C57P01.Mterminating connection due to administrator command.Fpostgres.c.L2884.RProcessInterrupts..
14:11:30.687614 IP 192.168.33.11.52325 > app.11002: Flags [P.], seq 156:174, ack 438, win 123, options [nop,nop,TS val 3127068 ecr 3243520], length 18
E..F..@.@.\g..!...!      ## PgpoolがDICARD ALLを投げるが、
.e*...P..T3q...{t......
./...1~.Q.... DISCARD ALL.
14:11:30.687642 IP app.11002 > 192.168.33.11.52325: Flags [R], seq 3545510769, win 0, length 0
E..(..@.@.yX..!          ## バックエンドプロセスは終了しているのでRESET
..!.*..e.T3q....P....T..
14:11:30.688021 IP 192.168.33.11.52325 > app.11002: Flags [P.], seq 174:179, ack 438, win 123, options [nop,nop,TS val 3127069 ecr 3243520], length 5
E..9..@.@.\s..!...!      ## Xでセッション終了命令がpgpoolから飛んでくるが、
.e*...Q..T3q...{%Y.....
./...1~.X....
14:11:30.688060 IP app.11002 > 192.168.33.11.52325: Flags [R], seq 3545510769, win 0, length 0
E..(..@.@.yW..!          ## バックエンドは終了しているのでRESET
..!.*..e.T3q....P....T..
14:11:30.688293 IP 192.168.33.11.40715 > app.11003: Flags [P.], seq 79:84, ack 320, win 123, options [nop,nop,TS val 3127069 ecr 3215775], length 5
E..9N.@.@.(\..!...!      ## スタンバイのバックエンドプロセスにX命令で終了
..*..;..."d ...{.......
./...1..X....
14:11:30.688610 IP 192.168.33.11.40715 > app.11003: Flags [F.], seq 84, ack 320, win 123, options [nop,nop,TS val 3127069 ecr 3215775], length 0
E..4N.@.@.(`..!...! 
..*..;..."d ...{*......
./...1..
14:11:30.688850 IP app.11003 > 192.168.33.11.40715: Flags [F.], seq 320, ack 85, win 114, options [nop,nop,TS val 3243522 ecr 3127069], length 0
E..4sz@.@.....!
..!.*...."d .;.....r.......
.1~../..
14:11:30.688992 IP 192.168.33.11.40715 > app.11003: Flags [.], ack 321, win 123, options [nop,nop,TS val 3127070 ecr 3243522], length 0
E..4N.@.@.(_..!...!
..*..;..."d!...{.0.....
./...1~.

pg_cancel_backend関数の使用について †

この関数を使用しても、Pgpool-IIのフェイルオーバは発生しない。PostgreSQL側では、QueryCancelPendingフラグが立ち、キャンセル可能なポイントでトランザクションがキャンセルされる。ただし、キャンセルはPostgreSQL側でコマンド実行中の場合である。

参考

• StatementCancelHandler() - https://git.postgresql.org/gitweb/?p=postgresql.git;a=shortlog;h=refs/heads/REL_10_STABLE
• ProcessInterrupts() - https://git.postgresql.org/gitweb/?p=postgresql.git;a=shortlog;h=refs/heads/REL_10_STABLE

参考リンク †

• Pgpool-II内部情報セミナー 第1回 -  http://www.pgpool.net/pgpool-web/contrib_docs/pgpool-II-internal-1.pdf 
• socket
  • http://cs.ecs.baylor.edu/~donahoo/practical/CSockets/TCPRST.pdf
  • http://itdoc.hitachi.co.jp/manuals/3000/30003D7030/TCPI0193.HTM
  • http://www.kt.rim.or.jp/~ksk/sock-faq/unix-socket-faq-ja-2.html