[pgpool-hackers: 4181] failover_on_backend_shutdown not working

Fri Jul 29 16:05:12 JST 2022

Hello

I am upgrading my PgPool setup from version 4.2.2 to 4.3.2.

I was testing the new parameter that this version introduces - failover_on_backend_shutdown, but it doesn’t seem to work.

My setup is 1 PgPool (4.3.2), 1 primary postgres, 2 replica postgres (all 12.5).

Initially, failover_on_backend_shutdown was turned on, then I turned it off from the config file and did a reload of PgPool.

The option is shown correctly when I query it in runtime:

postgres=# pgpool show failover_on_backend_shutdown;
 failover_on_backend_shutdown
------------------------------
 off
(1 row)

postgres=# show pool_version;
 pool_version
-----------------------
 4.3.2 (tamahomeboshi)
(1 row)

But then I tried turning off the primary instance by using systemctl stop ag_test_01

PgPool recognises that the node has been shutdown with an administrative command but continues to perform a failover anyway.

Please see the logs below (the logs are for node 0 and 2, node 1 was turned off earlier and showed the same behaviour):

2022-07-29 08:51:13 psql [592] LOG: reading and processing packets
2022-07-29 08:51:13 psql [592] DETAIL: postmaster on DB node 0 was shutdown by administrative command
2022-07-29 08:51:13 psql [592] LOCATION: pool_process_query.c:4898
2022-07-29 08:51:13 psql [592] LOG: pool_ssl: "SSL_read": "no SSL error reported"
2022-07-29 08:51:13 psql [592] LOCATION: pool_ssl.c:420
2022-07-29 08:51:13 psql [592] LOG: received degenerate backend request for node_id: 0 from pid [592]
2022-07-29 08:51:13 psql [592] LOCATION: pool_internal_comms.c:147
2022-07-29 08:51:13 psql [592] LOG: signal_user1_to_parent_with_reason(0)
2022-07-29 08:51:13 psql [592] LOCATION: pgpool_main.c:612
2022-07-29 08:51:13 psql [592] LOG: frontend disconnection: session time: 0:04:33.619 user=postgres database=postgres host=ec2-16-16-0-1.eu-north-1.compute.amazonaws.com port=44486
2022-07-29 08:51:13 psql [592] LOCATION: child.c:2045
2022-07-29 08:51:13 main [8] LOG: Pgpool-II parent process received SIGUSR1
2022-07-29 08:51:13 main [8] LOCATION: pgpool_main.c:1293
2022-07-29 08:51:13 main [8] LOG: Pgpool-II parent process has received failover request
2022-07-29 08:51:13 main [8] LOCATION: pgpool_main.c:1358
2022-07-29 08:51:13 main [8] LOG: starting degeneration. shutdown host dbod-ag-test-01.ch(6605)
2022-07-29 08:51:13 main [8] LOCATION: pgpool_main.c:1652
2022-07-29 08:51:13 main [8] LOG: Restart all children
2022-07-29 08:51:13 main [8] LOCATION: pgpool_main.c:1820
2022-07-29 08:51:13 main [8] LOG: execute command: /usr/local/bin/failover.py 0 dbod-ag-test-01.ch 6605 /ORA/dbs03/AG_TEST_01/data 2 dbod-ag-test-03.ch 0 0 6607 /ORA/dbs03/AG_TEST_03/data dbod-ag-test-01.ch 6605
2022-07-29 08:51:13 main [8] LOCATION: pgpool_main.c:2961
2022-07-29 08:51:14 main [8] LOG: find_primary_node_repeatedly: waiting for finding a primary node
2022-07-29 08:51:14 main [8] LOCATION: pgpool_main.c:3418
2022-07-29 08:51:14 main [8] LOG: find_primary_node: primary node is 2
2022-07-29 08:51:14 main [8] LOCATION: pgpool_main.c:3338
2022-07-29 08:51:14 main [8] LOG: starting follow degeneration. shutdown host dbod-ag-test-01.ch(6605)
2022-07-29 08:51:14 main [8] LOCATION: pgpool_main.c:1966
2022-07-29 08:51:14 main [8] LOG: starting follow degeneration. shutdown host dbod-ag-test-02.ch(6606)
2022-07-29 08:51:14 main [8] LOCATION: pgpool_main.c:1966
2022-07-29 08:51:14 main [8] LOG: failover: 2 follow backends have been degenerated
2022-07-29 08:51:14 main [8] LOCATION: pgpool_main.c:1985
2022-07-29 08:51:14 main [8] LOG: failover: set new primary node: 2
2022-07-29 08:51:14 main [8] LOCATION: pgpool_main.c:2012
2022-07-29 08:51:14 main [8] LOG: failover: set new main node: 2
2022-07-29 08:51:14 main [8] LOCATION: pgpool_main.c:2019
2022-07-29 08:51:14 follow_child [643] LOG: start triggering follow command.
2022-07-29 08:51:14 follow_child [643] LOCATION: pgpool_main.c:3480
2022-07-29 08:51:14 follow_child [643] LOG: execute command: /usr/local/bin/follow_primary.sh 0 dbod-ag-test-01.ch 6605 /ORA/dbs03/AG_TEST_01/data 2 dbod-ag-test-03.ch 0 0 6607 /ORA/dbs03/AG_TEST_03/data dbod-ag-test-01.ch 6605
2022-07-29 08:51:14 follow_child [643] LOCATION: pgpool_main.c:2961
failover done. shutdown host dbod-ag-test-01.ch(6605)2022-07-29 08:51:14 main [8] LOG: failover done. shutdown host dbod-ag-test-01.ch(6605)
2022-07-29 08:51:14 main [8] LOCATION: pgpool_main.c:2146
2022-07-29 08:51:14 sr_check_worker [577] LOG: worker process received restart request
2022-07-29 08:51:14 sr_check_worker [577] LOCATION: pool_worker_child.c:167
2022-07-29 08:51:14 follow_child [643] LOG: execute command: /usr/local/bin/follow_primary.sh 1 dbod-ag-test-02.ch 6606 /ORA/dbs03/AG_TEST_02/data 2 dbod-ag-test-03.ch 0 0 6607 /ORA/dbs03/AG_TEST_03/data dbod-ag-test-01.ch 6605
2022-07-29 08:51:14 follow_child [643] LOCATION: pgpool_main.c:2961
2022-07-29 08:51:15 pcp_main [569] LOG: restart request received in pcp child process
2022-07-29 08:51:15 pcp_main [569] LOCATION: pcp_child.c:169
2022-07-29 08:51:15 main [8] LOG: PCP child 569 exits with status 0 in failover()
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2190
2022-07-29 08:51:15 main [8] LOG: fork a new PCP child pid 740 in failover()
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2194
2022-07-29 08:51:15 pcp_main [740] LOG: PCP process: 740 started
2022-07-29 08:51:15 pcp_main [740] LOCATION: pcp_child.c:162
2022-07-29 08:51:15 main [8] LOG: child process with pid: 571 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 572 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 573 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 574 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 575 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 576 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: worker child process with pid: 577 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: fork a new worker child process with pid: 741
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2588
2022-07-29 08:51:15 sr_check_worker [741] LOG: process started
2022-07-29 08:51:15 sr_check_worker [741] LOCATION: pgpool_main.c:729
2022-07-29 08:51:15 main [8] LOG: child process with pid: 578 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 579 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 580 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 581 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 582 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 583 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 584 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 585 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 586 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 587 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 588 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 589 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 590 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 591 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 592 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 593 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 594 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 595 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 596 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 597 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 598 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 599 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 600 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 601 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 602 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 603 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 604 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 605 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 606 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 607 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 608 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 609 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 610 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 611 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 612 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 613 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 614 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 615 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 616 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 617 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 618 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 619 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 620 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 621 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 622 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 623 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 624 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 625 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 626 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 627 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 628 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 629 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 630 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 631 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 632 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 633 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 634 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 635 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 636 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 637 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 638 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 639 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 640 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 641 exits with status 256
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458
2022-07-29 08:51:15 main [8] LOG: child process with pid: 643 exits with status 0
2022-07-29 08:51:15 main [8] LOCATION: pgpool_main.c:2458

Thank you,

Anirudh
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.pgpool.net/pipermail/pgpool-hackers/attachments/20220729/929b9481/attachment-0001.htm>