View Issue Details

IDProjectCategoryView StatusLast Update
0000406Pgpool-IIBugpublic2018-08-06 09:59
ReporterancoronAssigned Tot-ishii 
PrioritynormalSeverityminorReproducibilityalways
Status closedResolutionfixed 
PlatformLinuxOSDebianOS Version9.4
Product Version3.7.4 
Target VersionFixed in Version 
Summary0000406: failover called with old-primary = -1
Descriptionfailover_command parameter "%P" gets set to -1 in case of the primary backend.

I have a setup of three machines, each having PostgreSQL (10) + Pgpool running with streaming replication configured and working in PostgreSQL, Pgpool configured appropriately as well.

Virtual IP is used for pgpool master. Watchdog and health checks are enabled as well.

Now, testing failover, the situation before is as follows:

pcp_node_info:
pg-cluster-01.dev.mycorp.net 5432 2 0.333333 up primary
pg-cluster-02.dev.mycorp.net 5432 2 0.333333 up standby
pg-cluster-03.dev.mycorp.net 5432 2 0.333333 up standby

State from pgpool master log:
2018-06-19T18:33:42+0200 pg-cluster-01 pgpool[42714]: [18-1] LOG: find_primary_node_repeatedly: waiting for finding a primary node
2018-06-19T18:33:42+0200 pg-cluster-01 pgpool[42714]: [19-1] LOG: find_primary_node: checking backend no 0
2018-06-19T18:33:42+0200 pg-cluster-01 pgpool[42714]: [20-1] LOG: find_primary_node: primary node id is 0
2018-06-19T18:33:42+0200 pg-cluster-01 pgpool[42714]: [21-1] LOG: failover: set new primary node: 0
2018-06-19T18:33:42+0200 pg-cluster-01 pgpool[42714]: [22-1] LOG: failover: set new master node: 0

While node-by-node setup of the cluster, I see failback of standby's called correctly, e.g.:
2018-06-19T18:34:32+0200 pg-cluster-01 pgpool[42714]: [30-1] LOG: starting fail back. reconnect host pg-cluster-03.dev.mycorp.net(5432)
2018-06-19T18:34:32+0200 pg-cluster-01 pgpool[42714]: [31-1] LOG: Node 0 is not down (status: 2)
2018-06-19T18:34:32+0200 pg-cluster-01 pgpool[42714]: [32-1] LOG: execute command: /var/lib/postgresql/10/main/failback.sh --failed-node 2 --failed-host pg-cluster-03.dev.mycorp.net --new-master-node 0 --new-master-host pg-cluster-01.dev.mycorp.net --old-master-node 0 --old-primary-node 0


Executed at node pg-cluster-01.dev.mycorp.net:
sudo systemctl stop postgresql

Expected failover to be called with old-primary = 0, but:
2018-06-19T18:38:25+0200 pg-cluster-01 pgpool[42714]: [565-1] LOG: Pgpool-II parent process has received failover request
2018-06-19T18:38:25+0200 pg-cluster-01 pgpool[42714]: [566-1] LOG: starting quarantine. shutdown host pg-cluster-01.dev.mycorp.net(5432)
2018-06-19T18:38:25+0200 pg-cluster-01 pgpool[42714]: [567-1] LOG: Restart all children
2018-06-19T18:38:25+0200 pg-cluster-01 pgpool[42714]: [568-1] LOG: failover: set new primary node: -1
2018-06-19T18:38:25+0200 pg-cluster-01 pgpool[42714]: [569-1] LOG: failover: set new master node: 1
2018-06-19T18:38:25+0200 pg-cluster-01 pgpool[42714]: [570-1] LOG: quarantine done. shutdown host pg-cluster-01.dev.mycorp.net(5432)
...
2018-06-19T18:38:37+0200 pg-cluster-01 pgpool[42714]: [875-1] LOG: Pgpool-II parent process has received failover request
2018-06-19T18:38:37+0200 pg-cluster-01 pgpool[42714]: [876-1] LOG: starting degeneration. shutdown host pg-cluster-01.dev.mycorp.net(5432)
2018-06-19T18:38:37+0200 pg-cluster-01 pgpool[42714]: [877-1] LOG: Do not restart children because we are switching over node id 0 host: pg-cluster-01.dev.mycorp.net port: 5432 and we are in streaming replication mode
2018-06-19T18:38:37+0200 pg-cluster-01 pgpool[42714]: [878-1] LOG: execute command: /var/lib/postgresql/10/main/failover.sh --failed-node 0 --failed-host pg-cluster-01.dev.mycorp.net --new-master-node 1 --new-master-host pg-cluster-02.dev.mycorp.net --old-master-node 1 --old-primary-node -1
2018-06-19T18:38:37+0200 pg-cluster-01 pgpool[42714]: quarantine done. shutdown host pg-cluster-01.dev.mycorp.net(5432)
...
2018-06-19T18:38:37+0200 pg-cluster-01 pgpool[42714]: [882-1] LOG: failover done. shutdown host pg-cluster-01.dev.mycorp.net(5432)


...leading to:
pg-cluster-01.dev.mycorp.net 5432 3 0.333333 quarantine standby
pg-cluster-02.dev.mycorp.net 5432 2 0.333333 up standby
pg-cluster-03.dev.mycorp.net 5432 2 0.333333 up standby


This means that failover scripts written in accordance to the example scripts provided via documentation do not work as expected.
Steps To ReproduceSetup cluster with streaming replication.

Stop primary backend.
Additional Informationpgpool.conf entries:

follow_master_command = '/var/lib/postgresql/10/main/follow-master.sh --failed-node %d --failed-host %h --new-master-node %m --new-master-host %H --old-master-node %M --old-primary-node %P'

failover_command = '/var/lib/postgresql/10/main/failover.sh --failed-node %d --failed-host %h --new-master-node %m --new-master-host %H --old-master-node %M --old-primary-node %P'

failback_command = '/var/lib/postgresql/10/main/failback.sh --failed-node %d --failed-host %h --new-master-node %m --new-master-host %H --old-master-node %M --old-primary-node %P'

Tagsconsensus, failover, quarantine, streaming replication

Activities

ancoron

2018-06-20 02:47

reporter   ~0002050

Reading what I just posted it really looks like the new quarantine functionality gets in the way here and final failover after reaching consensus will never see original values for old-master and old-primary.

t-ishii

2018-06-20 10:21

developer   ~0002051

> Reading what I just posted it really looks like the new quarantine functionality gets in the way here and final failover after reaching consensus will never see original values for old-master and old-primary.

Assuming that you enable (they are enabled by default):
failover_when_quorum_exists
failover_require_consensus
I suspect there are something wrong with primary node detection mechanism in the new new quarantine functionality.
I will look into this...

ancoron

2018-06-21 03:45

reporter   ~0002052

Yes, both options are active:

failover_when_quorum_exists = on
failover_require_consensus = on
allow_multiple_failover_requests_from_node = off

Also, the delay between quarantine and failover is a full healthcheck failure cycle, as it was configured:
health_check_period = 30
health_check_timeout = 20
health_check_max_retries = 10
health_check_retry_delay = 1
connect_timeout = 10000


To a certain degree I can understand the logic of quarantine, resetting the primary as the failed backend apparently was the primary. On the other hand, it would be questionable why quarantine actually sets old primary and new master because as long as there is no consensus (if active), it wouldn't come into effect as only the failover is responsible to promote a standby, or?

t-ishii

2018-06-21 12:48

developer   ~0002055

> Yes, both options are active:
Is it possible for you to try to reproduce the problem with ailover_when_quorum_exists = off and
failover_require_consensus = off?

> On the other hand, it would be questionable why quarantine actually sets old primary and new master because as long as there is no
> consensus (if active), it wouldn't come into effect as only the failover is responsible to promote a standby, or?
I think it's a reasonable argument. I have already ping the author of the functionality and am expecting comment from him.

ancoron

2018-06-21 15:36

reporter   ~0002067

Without consensus, the failover gets called with correct old primary = 0

2018-06-20T22:20:42+0200 pgpool[26552]: [497-1] LOG: execute command: /var/lib/postgresql/10/main/failover.sh --failed-node 0 --failed-host pg-cluster-01.dev.mycorp.net --new-master-node 1 --new-master-host pg-cluster-02.dev.mycorp.net --old-master-node 0 --old-primary-node 0
2018-06-20T22:20:43+0200 pgpool[26552]: [498-1] LOG: find_primary_node_repeatedly: waiting for finding a primary node
2018-06-20T22:20:43+0200 pgpool[26552]: [499-1] LOG: find_primary_node: checking backend no 0
2018-06-20T22:20:43+0200 pgpool[26552]: [500-1] LOG: find_primary_node: checking backend no 1
2018-06-20T22:20:43+0200 pgpool[26552]: [501-1] LOG: find_primary_node: primary node id is 1
2018-06-20T22:20:43+0200 pgpool[26552]: [502-1] LOG: starting follow degeneration. shutdown host pg-cluster-01.dev.mycorp.net(5432)
2018-06-20T22:20:43+0200 pgpool[26552]: [503-1] LOG: starting follow degeneration. shutdown host pg-cluster-03.dev.mycorp.net(5432)
2018-06-20T22:20:43+0200 pgpool[26552]: [504-1] LOG: failover: 2 follow backends have been degenerated
2018-06-20T22:20:43+0200 pgpool[26552]: [505-1] LOG: failover: set new primary node: 1
2018-06-20T22:20:43+0200 pgpool[26552]: [506-1] LOG: failover: set new master node: 1
2018-06-20T22:20:43+0200 pgpool[31890]: [505-1] LOG: start triggering follow command.
2018-06-20T22:20:43+0200 pgpool[31890]: [506-1] LOG: execute command: /var/lib/postgresql/10/main/follow-master.sh --failed-node 0 --failed-host pg-cluster-01.dev.mycorp.net --new-master-node 1 --new-master-host pg-cluster-02.dev.mycorp.net --old-master-node 0 --old-primary-node 0

t-ishii

2018-06-25 10:33

developer   ~0002071

That's what I expected. I am sure there's something wrong in the code path when ailover_when_quorum_exists = on and/or
failover_require_consensus = on. Will look into this.

t-ishii

2018-06-25 11:29

developer   ~0002073

ancoron,
Here is a proposed patch to fix the problem. It just prevents the primary node from being set to -1 in quarantine state. As far as I know, we don't need to set it to -1 in this case as you said. Can you please try it out? All regression tests including the watchdog tests have passed here.

watchdog.diff (675 bytes)
diff --git a/src/main/pgpool_main.c b/src/main/pgpool_main.c
index 08e60c4..ecabff3 100644
--- a/src/main/pgpool_main.c
+++ b/src/main/pgpool_main.c
@@ -1907,12 +1907,11 @@ static void failover(void)
 		}
 		else if (reqkind == NODE_QUARANTINE_REQUEST)
 		{
-			/* if the quarantine node was the primary node
-			 * set the newprimary to -1 (invalid)
+			/* if the quarantine node was the primary node,
+			 * skip finding new primary node.
+			 * Otherwise look for new primary.
 			 */
-			if (Req_info->primary_node_id == node_id)
-				new_primary = -1;
-			else
+			if (Req_info->primary_node_id != node_id)
 				new_primary =  find_primary_node_repeatedly();
 		}
 		/*
watchdog.diff (675 bytes)

ancoron

2018-06-27 21:43

reporter   ~0002074

Sorry for the late reply. I just tested with the patch, but got the following behavior for primary failover:

2018-06-27T13:54:21+0200 pgpool[15208]: [121-1] LOG: failed to connect to PostgreSQL server on "pg-cluster-01.dev.mycorp.net:5432", getsockopt() detected error "Connection refused"
2018-06-27T13:54:21+0200 pgpool[15208]: [122-1] LOG: received degenerate backend request for node_id: 0 from pid [15208]
2018-06-27T13:54:21+0200 pgpool[14788]: [71-1] LOG: new IPC connection received
2018-06-27T13:54:21+0200 pgpool[14788]: [72-1] LOG: watchdog received the failover command from local pgpool-II on IPC interface
2018-06-27T13:54:21+0200 pgpool[14788]: [73-1] LOG: watchdog is processing the failover command [DEGENERATE_BACKEND_REQUEST] received from local pgpool-II on IPC interface
2018-06-27T13:54:21+0200 pgpool[14788]: [74-1] LOG: failover requires the majority vote, waiting for consensus
2018-06-27T13:54:21+0200 pgpool[14788]: [74-2] DETAIL: failover request noted
2018-06-27T13:54:21+0200 pgpool[14788]: [75-1] LOG: failover command [DEGENERATE_BACKEND_REQUEST] request from pgpool-II node "pg-cluster-01.dev.mycorp.net:5433 Linux pg-cluster-01" is queued, waiting for the confirmation from other nodes
2018-06-27T13:54:21+0200 pgpool[14785]: [145-1] LOG: child process with pid: 15208 exits with status 256
2018-06-27T13:54:21+0200 pgpool[14785]: [146-1] LOG: fork a new child process with pid: 15265
2018-06-27T13:54:21+0200 pgpool[15193]: [98-1] LOG: new connection received
2018-06-27T13:54:21+0200 pgpool[15193]: [98-2] DETAIL: connecting host=192.168.123.45 port=49736
2018-06-27T13:54:21+0200 pgpool[15193]: [99-1] LOG: failed to connect to PostgreSQL server on "pg-cluster-01.dev.mycorp.net:5432", getsockopt() detected error "Connection refused"
2018-06-27T13:54:21+0200 pgpool[15193]: [100-1] LOG: received degenerate backend request for node_id: 0 from pid [15193]
2018-06-27T13:54:21+0200 pgpool[14788]: [76-1] LOG: new IPC connection received
2018-06-27T13:54:21+0200 pgpool[14788]: [77-1] LOG: watchdog received the failover command from local pgpool-II on IPC interface
2018-06-27T13:54:21+0200 pgpool[14788]: [78-1] LOG: watchdog is processing the failover command [DEGENERATE_BACKEND_REQUEST] received from local pgpool-II on IPC interface
2018-06-27T13:54:21+0200 pgpool[14788]: [79-1] LOG: Duplicate failover request from "pg-cluster-01.dev.mycorp.net:5433 Linux pg-cluster-01" node
2018-06-27T13:54:21+0200 pgpool[14788]: [79-2] DETAIL: request ignored
2018-06-27T13:54:21+0200 pgpool[14788]: [80-1] LOG: failover requires the majority vote, waiting for consensus
2018-06-27T13:54:21+0200 pgpool[14788]: [80-2] DETAIL: failover request noted
2018-06-27T13:54:21+0200 pgpool[14785]: [147-1] LOG: Pgpool-II parent process has received failover request
2018-06-27T13:54:21+0200 pgpool[14788]: [81-1] LOG: new IPC connection received
2018-06-27T13:54:21+0200 pgpool[14788]: [82-1] LOG: received the failover indication from Pgpool-II on IPC interface
2018-06-27T13:54:21+0200 pgpool[14788]: [83-1] LOG: watchdog is informed of failover end by the main process
2018-06-27T13:54:21+0200 pgpool[14785]: [148-1] LOG: starting quarantine. shutdown host pg-cluster-01.dev.mycorp.net(5432)
2018-06-27T13:54:21+0200 pgpool[14785]: [149-1] LOG: Restart all children
2018-06-27T13:54:21+0200 pgpool[14785]: [150-1] LOG: failover: set new primary node: 1868963872
2018-06-27T13:54:21+0200 pgpool[14785]: [151-1] LOG: failover: set new master node: 1
2018-06-27T13:54:21+0200 pgpool[14788]: [84-1] LOG: new IPC connection received
2018-06-27T13:54:21+0200 pgpool[14788]: [85-1] LOG: received the failover indication from Pgpool-II on IPC interface
2018-06-27T13:54:21+0200 pgpool[14788]: [86-1] LOG: watchdog is informed of failover start by the main process
2018-06-27T13:54:21+0200 pgpool[14785]: [152-1] LOG: quarantine done. shutdown host pg-cluster-01.dev.mycorp.net(5432)
2018-06-27T13:54:22+0200 pgpool[15115]: [51-1] LOG: restart request received in pcp child process
2018-06-27T13:54:22+0200 pgpool[14785]: [153-1] LOG: PCP child 15115 exits with status 0 in failover()
2018-06-27T13:54:22+0200 pgpool[14785]: [154-1] LOG: fork a new PCP child pid 15366 in failover()
2018-06-27T13:54:22+0200 pgpool[14785]: [155-1] LOG: child process with pid: 14813 exits with status 0
2018-06-27T13:54:22+0200 pgpool[14785]: [156-1] LOG: child process with pid: 14813 exited with success and will not be restarted

...

2018-06-27T13:54:22+0200 pgpool[14785]: [455-1] WARNING: worker child process with pid: 15367 was terminated by segmentation fault
2018-06-27T13:54:22+0200 pgpool[14785]: [456-1] LOG: fork a new worker child process with pid: 15417
2018-06-27T13:54:22+0200 pgpool[14785]: [457-1] WARNING: worker child process with pid: 15417 was terminated by segmentation fault
2018-06-27T13:54:22+0200 pgpool[14785]: [458-1] LOG: fork a new worker child process with pid: 15418
2018-06-27T13:54:22+0200 pgpool[14785]: [459-1] WARNING: worker child process with pid: 15418 was terminated by segmentation fault
2018-06-27T13:54:22+0200 pgpool[14785]: [460-1] LOG: fork a new worker child process with pid: 15419

...

2018-06-27T13:54:26+0200 pgpool[14785]: [1033-1] WARNING: worker child process with pid: 15707 was terminated by segmentation fault
2018-06-27T13:54:26+0200 pgpool[14785]: [1034-1] LOG: fork a new worker child process with pid: 15708
2018-06-27T13:54:26+0200 pgpool[14788]: [87-1] LOG: watchdog received the failover command from remote pgpool-II node "pg-cluster-02.dev.mycorp.net:5433 Linux pg-cluster-02"
2018-06-27T13:54:26+0200 pgpool[14788]: [88-1] LOG: watchdog is processing the failover command [DEGENERATE_BACKEND_REQUEST] received from pg-cluster-02.dev.mycorp.net:5433 Linux pg-cluster-02
2018-06-27T13:54:26+0200 pgpool[14788]: [89-1] LOG: we have got the consensus to perform the failover
2018-06-27T13:54:26+0200 pgpool[14788]: [89-2] DETAIL: 2 node(s) voted in the favor
2018-06-27T13:54:26+0200 pgpool[14788]: [90-1] LOG: received degenerate backend request for node_id: 0 from pid [14788]
2018-06-27T13:54:26+0200 pgpool[14788]: [91-1] LOG: new IPC connection received
2018-06-27T13:54:26+0200 pgpool[14788]: [92-1] LOG: received the failover indication from Pgpool-II on IPC interface
2018-06-27T13:54:26+0200 pgpool[14788]: [93-1] LOG: watchdog is informed of failover end by the main process
2018-06-27T13:54:26+0200 systemd[1]: pgpool2.service: Main process exited, code=killed, status=11/SEGV
2018-06-27T13:54:26+0200 pgpool[14788]: [94-1] LOG: Watchdog is shutting down
2018-06-27T13:54:26+0200 systemd[1]: pgpool2.service: Unit entered failed state.
2018-06-27T13:54:26+0200 systemd[1]: pgpool2.service: Failed with result 'signal'.

So, sorry, but that patch makes it worse.

After VIP takeover, I could see that indeed, no actual failover occurred and is left in quarantine state:

pg-cluster-01.dev.mycorp.net 5432 3 0.333333 quarantine standby
pg-cluster-02.dev.mycorp.net 5432 2 0.333333 up standby
pg-cluster-03.dev.mycorp.net 5432 2 0.333333 up standby

t-ishii

2018-06-28 09:18

developer   ~0002075

Thank you for the testing. I think we need help from Usama who is the authority of watchdog. Will ping him.

Muhammad Usama

2018-07-02 16:20

developer   ~0002076

Hi

I have pushed the fix for it, You can test it by building from the head of 3.7 branch
https://git.postgresql.org/gitweb/?p=pgpool2.git;a=commitdiff;h=1648cb8c552a19b2f90de1fab120929dd5be06e4

Thanks

Issue History

Date Modified Username Field Change
2018-06-20 02:36 ancoron New Issue
2018-06-20 02:36 ancoron Tag Attached: failover
2018-06-20 02:36 ancoron Tag Attached: streaming replication
2018-06-20 02:47 ancoron Note Added: 0002050
2018-06-20 10:21 t-ishii Note Added: 0002051
2018-06-21 03:45 ancoron Note Added: 0002052
2018-06-21 12:44 t-ishii Assigned To => t-ishii
2018-06-21 12:44 t-ishii Status new => assigned
2018-06-21 12:48 t-ishii Note Added: 0002055
2018-06-21 15:36 ancoron Note Added: 0002067
2018-06-25 10:33 t-ishii Note Added: 0002071
2018-06-25 11:29 t-ishii File Added: watchdog.diff
2018-06-25 11:29 t-ishii Note Added: 0002073
2018-06-25 11:29 t-ishii Status assigned => feedback
2018-06-27 21:43 ancoron Note Added: 0002074
2018-06-27 21:43 ancoron Status feedback => assigned
2018-06-28 09:18 t-ishii Note Added: 0002075
2018-07-02 16:20 Muhammad Usama Status assigned => resolved
2018-07-02 16:20 Muhammad Usama Resolution open => fixed
2018-07-02 16:20 Muhammad Usama Note Added: 0002076
2018-07-05 03:14 ancoron Tag Attached: consensus
2018-07-05 03:14 ancoron Tag Attached: quarantine
2018-08-06 09:59 administrator Status resolved => closed