[pgpool-hackers: 4127] invalid degenerate backend request, node id : 2 status: [2] is not valid for failover

[anirudh.goel at cern.ch]

Hello

I had the following setup:
1 pgpool: 4.2.2
3 postgres nodes (all 12.5) - 1 primary, 2 replicas

I turned off both replicas one after the other with a difference of a couple seconds. Failover was performed for one of the replicas but not for the other. For the second replica the healthcheck keeps on failing but it just keeps on performing the healthcheck in an infinite loop. When pgpool attempts the failover of the second replica, I see this error in the logs:

invalid degenerate backend request, node id : 2 status: [2] is not valid for failover

As far as I understand, status [2] is up, so the failover should be performed. Here’s a snippet of the logs:

2022-02-18 16:30:39 dbod-gb031 [63] LOG: reading and processing packets
2022-02-18 16:30:39 dbod-gb031 [63] DETAIL: postmaster on DB node 1 was shutdown by administrative command
2022-02-18 16:30:45 dbod-gb031 [63] LOG: reading and processing packets
2022-02-18 16:30:45 dbod-gb031 [63] DETAIL: postmaster on DB node 2 was shutdown by administrative command
2022-02-18 16:30:49 health_check1 [120] LOG: failed to connect to PostgreSQL server on "dbod-ag-test2.ch:6602", getsockopt() failed
2022-02-18 16:30:49 health_check1 [120] DETAIL: Operation now in progress
2022-02-18 16:30:49 health_check1 [120] ERROR: failed to make persistent db connection
2022-02-18 16:30:49 health_check1 [120] DETAIL: connection to host:"dbod-ag-test2.ch:6602" failed
2022-02-18 16:30:49 health_check1 [120] LOG: health check retrying on DB node: 1 (round:1)
2022-02-18 16:30:51 health_check2 [121] LOG: failed to connect to PostgreSQL server on "dbod-ag-test3.ch:6603", getsockopt() failed
2022-02-18 16:30:51 health_check2 [121] DETAIL: Operation now in progress
2022-02-18 16:30:51 health_check2 [121] ERROR: failed to make persistent db connection
2022-02-18 16:30:51 health_check2 [121] DETAIL: connection to host:"dbod-ag-test3.ch:6603" failed
2022-02-18 16:30:51 health_check2 [121] LOG: health check retrying on DB node: 2 (round:1)
2022-02-18 16:30:51 health_check1 [120] LOG: failed to connect to PostgreSQL server on "dbod-ag-test2.ch:6602", getsockopt() failed
2022-02-18 16:30:51 health_check1 [120] DETAIL: Operation now in progress
2022-02-18 16:30:51 health_check1 [120] ERROR: failed to make persistent db connection
2022-02-18 16:30:51 health_check1 [120] DETAIL: connection to host:"dbod-ag-test2.ch:6602" failed
2022-02-18 16:30:51 health_check1 [120] LOG: health check retrying on DB node: 1 (round:2)
2022-02-18 16:30:51 sr_check_worker [152] LOG: failed to connect to PostgreSQL server on "dbod-ag-test2.ch:6602", getsockopt() failed
2022-02-18 16:30:51 sr_check_worker [152] DETAIL: Operation now in progress
2022-02-18 16:30:51 sr_check_worker [152] ERROR: failed to make persistent db connection
2022-02-18 16:30:51 sr_check_worker [152] DETAIL: connection to host:"dbod-ag-test2.ch:6602" failed
2022-02-18 16:30:51 sr_check_worker [152] LOG: failed to connect to PostgreSQL server on "dbod-ag-test3.ch:6603", getsockopt() failed
2022-02-18 16:30:51 sr_check_worker [152] DETAIL: Operation now in progress
2022-02-18 16:30:51 sr_check_worker [152] ERROR: failed to make persistent db connection
2022-02-18 16:30:51 sr_check_worker [152] DETAIL: connection to host:"dbod-ag-test3.ch:6603" failed
2022-02-18 16:30:53 health_check2 [121] LOG: failed to connect to PostgreSQL server on "dbod-ag-test3.ch:6603", getsockopt() failed
2022-02-18 16:30:53 health_check2 [121] DETAIL: Operation now in progress
2022-02-18 16:30:53 health_check2 [121] ERROR: failed to make persistent db connection
2022-02-18 16:30:53 health_check2 [121] DETAIL: connection to host:"dbod-ag-test3.ch:6603" failed
2022-02-18 16:30:53 health_check2 [121] LOG: health check retrying on DB node: 2 (round:2)
2022-02-18 16:30:53 health_check1 [120] LOG: failed to connect to PostgreSQL server on "dbod-ag-test2.ch:6602", getsockopt() failed
2022-02-18 16:30:53 health_check1 [120] DETAIL: Operation now in progress
2022-02-18 16:30:53 health_check1 [120] ERROR: failed to make persistent db connection
2022-02-18 16:30:53 health_check1 [120] DETAIL: connection to host:"dbod-ag-test2.ch:6602" failed
2022-02-18 16:30:53 health_check1 [120] LOG: health check retrying on DB node: 1 (round:3)
2022-02-18 16:30:55 health_check2 [121] LOG: failed to connect to PostgreSQL server on "dbod-ag-test3.ch:6603", getsockopt() failed
2022-02-18 16:30:55 health_check2 [121] DETAIL: Operation now in progress
2022-02-18 16:30:55 health_check2 [121] ERROR: failed to make persistent db connection
2022-02-18 16:30:55 health_check2 [121] DETAIL: connection to host:"dbod-ag-test3.ch:6603" failed
2022-02-18 16:30:55 health_check2 [121] LOG: health check retrying on DB node: 2 (round:3)
2022-02-18 16:30:55 health_check1 [120] LOG: failed to connect to PostgreSQL server on "dbod-ag-test2.ch:6602", getsockopt() failed
2022-02-18 16:30:55 health_check1 [120] DETAIL: Operation now in progress
2022-02-18 16:30:55 health_check1 [120] ERROR: failed to make persistent db connection
2022-02-18 16:30:55 health_check1 [120] DETAIL: connection to host:"dbod-ag-test2.ch:6602" failed
2022-02-18 16:30:55 health_check1 [120] LOG: health check retrying on DB node: 1 (round:4)
2022-02-18 16:30:57 health_check2 [121] LOG: failed to connect to PostgreSQL server on "dbod-ag-test3.ch:6603", getsockopt() failed
2022-02-18 16:30:57 health_check2 [121] DETAIL: Operation now in progress
2022-02-18 16:30:57 health_check2 [121] ERROR: failed to make persistent db connection
2022-02-18 16:30:57 health_check2 [121] DETAIL: connection to host:"dbod-ag-test3.ch:6603" failed
2022-02-18 16:30:57 health_check2 [121] LOG: health check retrying on DB node: 2 (round:4)
2022-02-18 16:30:57 health_check1 [120] LOG: failed to connect to PostgreSQL server on "dbod-ag-test2.ch:6602", getsockopt() failed
2022-02-18 16:30:57 health_check1 [120] DETAIL: Operation now in progress
2022-02-18 16:30:57 health_check1 [120] ERROR: failed to make persistent db connection
2022-02-18 16:30:57 health_check1 [120] DETAIL: connection to host:"dbod-ag-test2.ch:6602" failed
2022-02-18 16:30:57 health_check1 [120] LOG: health check retrying on DB node: 1 (round:5)
2022-02-18 16:30:59 health_check2 [121] LOG: failed to connect to PostgreSQL server on "dbod-ag-test3.ch:6603", getsockopt() failed
2022-02-18 16:30:59 health_check2 [121] DETAIL: Operation now in progress
2022-02-18 16:30:59 health_check2 [121] ERROR: failed to make persistent db connection
2022-02-18 16:30:59 health_check2 [121] DETAIL: connection to host:"dbod-ag-test3.ch:6603" failed
2022-02-18 16:30:59 health_check2 [121] LOG: health check retrying on DB node: 2 (round:5)
2022-02-18 16:30:59 health_check1 [120] LOG: failed to connect to PostgreSQL server on "dbod-ag-test2.ch:6602", getsockopt() failed
2022-02-18 16:30:59 health_check1 [120] DETAIL: Operation now in progress
2022-02-18 16:30:59 health_check1 [120] ERROR: failed to make persistent db connection
2022-02-18 16:30:59 health_check1 [120] DETAIL: connection to host:"dbod-ag-test2.ch:6602" failed
2022-02-18 16:30:59 health_check1 [120] LOG: health check failed on node 1 (timeout:0)
2022-02-18 16:30:59 health_check1 [120] LOG: received degenerate backend request for node_id: 1 from pid [120]
2022-02-18 16:30:59 main [8] LOG: Pgpool-II parent process has received failover request
2022-02-18 16:30:59 main [8] LOG: starting degeneration. shutdown host dbod-ag-test2.ch(6602)
2022-02-18 16:30:59 main [8] LOG: Do not restart children because we are switching over node id 1 host: dbod-ag-test2.ch port: 6602 and we are in streaming replication mode
2022-02-18 16:30:59 main [8] LOG: execute command: /usr/local/bin/failover.sh 1 dbod-ag-test2.ch 6602 /ORA/dbs03/AG_TEST2/data 0 dbod-ag-test1.ch 0 0 6601 /ORA/dbs03/AG_TEST1/data dbod-ag-test1.ch 6601
2022-02-18 16:30:59 main [8] LOG: failover: set new primary node: 0
2022-02-18 16:30:59 main [8] LOG: failover: set new main node: 0
failover done. shutdown host dbod-ag-test2.ch(6602)2022-02-18 16:30:59 main [8] LOG: failover done. shutdown host dbod-ag-test2.ch(6602)
2022-02-18 16:30:59 sr_check_worker [152] ERROR: Failed to check replication time lag
2022-02-18 16:30:59 sr_check_worker [152] DETAIL: No persistent db connection for the node 1
2022-02-18 16:30:59 sr_check_worker [152] HINT: check sr_check_user and sr_check_password
2022-02-18 16:30:59 sr_check_worker [152] CONTEXT: while checking replication time lag
2022-02-18 16:30:59 sr_check_worker [152] LOG: worker process received restart request
2022-02-18 16:31:00 pcp_main [151] LOG: restart request received in pcp child process
2022-02-18 16:31:00 main [8] LOG: PCP child 151 exits with status 0 in failover()
2022-02-18 16:31:00 main [8] LOG: fork a new PCP child pid 181 in failover()
2022-02-18 16:31:00 main [8] LOG: worker child process with pid: 152 exits with status 256
2022-02-18 16:31:00 pcp_main [181] LOG: PCP process: 181 started
2022-02-18 16:31:00 main [8] LOG: fork a new worker child process with pid: 182
2022-02-18 16:31:00 sr_check_worker [182] LOG: process started
2022-02-18 16:31:00 sr_check_worker [182] LOG: failed to connect to PostgreSQL server on "dbod-ag-test3.ch:6603", getsockopt() failed
2022-02-18 16:31:00 sr_check_worker [182] DETAIL: Operation now in progress
2022-02-18 16:31:00 sr_check_worker [182] ERROR: failed to make persistent db connection
2022-02-18 16:31:00 sr_check_worker [182] DETAIL: connection to host:"dbod-ag-test3.ch:6603" failed
2022-02-18 16:31:01 health_check2 [121] LOG: failed to connect to PostgreSQL server on "dbod-ag-test3.ch:6603", getsockopt() failed
2022-02-18 16:31:01 health_check2 [121] DETAIL: Operation now in progress
2022-02-18 16:31:01 health_check2 [121] ERROR: failed to make persistent db connection
2022-02-18 16:31:01 health_check2 [121] DETAIL: connection to host:"dbod-ag-test3.ch:6603" failed
2022-02-18 16:31:01 health_check2 [121] LOG: health check failed on node 2 (timeout:0)
2022-02-18 16:31:01 health_check2 [121] LOG: invalid degenerate backend request, node id : 2 status: [2] is not valid for failover
2022-02-18 16:31:11 health_check2 [121] LOG: failed to connect to PostgreSQL server on "dbod-ag-test3.ch:6603", getsockopt() failed
2022-02-18 16:31:11 health_check2 [121] DETAIL: Operation now in progress
2022-02-18 16:31:11 health_check2 [121] ERROR: failed to make persistent db connection
2022-02-18 16:31:11 health_check2 [121] DETAIL: connection to host:"dbod-ag-test3.ch:6603" failed
2022-02-18 16:31:11 health_check2 [121] LOG: health check retrying on DB node: 2 (round:1)
2022-02-18 16:31:13 health_check2 [121] LOG: failed to connect to PostgreSQL server on "dbod-ag-test3.ch:6603", getsockopt() failed
2022-02-18 16:31:13 health_check2 [121] DETAIL: Operation now in progress
2022-02-18 16:31:13 health_check2 [121] ERROR: failed to make persistent db connection
2022-02-18 16:31:13 health_check2 [121] DETAIL: connection to host:"dbod-ag-test3.ch:6603" failed
2022-02-18 16:31:13 health_check2 [121] LOG: health check retrying on DB node: 2 (round:2)
2022-02-18 16:31:15 health_check2 [121] LOG: failed to connect to PostgreSQL server on "dbod-ag-test3.ch:6603", getsockopt() failed
2022-02-18 16:31:15 health_check2 [121] DETAIL: Operation now in progress
2022-02-18 16:31:15 health_check2 [121] ERROR: failed to make persistent db connection
2022-02-18 16:31:15 health_check2 [121] DETAIL: connection to host:"dbod-ag-test3.ch:6603" failed
2022-02-18 16:31:15 health_check2 [121] LOG: health check retrying on DB node: 2 (round:3)
2022-02-18 16:31:17 health_check2 [121] LOG: failed to connect to PostgreSQL server on "dbod-ag-test3.ch:6603", getsockopt() failed
2022-02-18 16:31:17 health_check2 [121] DETAIL: Operation now in progress
2022-02-18 16:31:17 health_check2 [121] ERROR: failed to make persistent db connection
2022-02-18 16:31:17 health_check2 [121] DETAIL: connection to host:"dbod-ag-test3.ch:6603" failed
2022-02-18 16:31:17 health_check2 [121] LOG: health check retrying on DB node: 2 (round:4)
2022-02-18 16:31:19 health_check2 [121] LOG: failed to connect to PostgreSQL server on "dbod-ag-test3.ch:6603", getsockopt() failed
2022-02-18 16:31:19 health_check2 [121] DETAIL: Operation now in progress
2022-02-18 16:31:19 health_check2 [121] ERROR: failed to make persistent db connection
2022-02-18 16:31:19 health_check2 [121] DETAIL: connection to host:"dbod-ag-test3.ch:6603" failed
2022-02-18 16:31:19 health_check2 [121] LOG: health check retrying on DB node: 2 (round:5)

Thanks and regards

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