[pgpool-general: 7496] Problems with pg_rewind

Emond Papegaaij emond.papegaaij at gmail.com
Mon Apr 12 16:48:26 JST 2021

Hi all,

In our test setup we see frequent failures were a database does not
start properly after a forced failover. In this test we start with a
cluster of 3 pgpool (4.1.4)+pg (12) nodes (every node runs both pgpool
and pg). Node 0 is master+primary and needs to be restarted so we
trigger a forced failover. First we stop and restart pgpool to force
another node in the cluster to become cluster master. Next, we detach
the backend at node 0 and this is where the trouble starts. These log
lines from the server show the steps being executed (I've removed some
to keep it concise):

Apr 11 05:31:51 tkh-server tkh-force-failover: Node 0 status: 5432 1 0.333333 waiting primary 0   2021-04-11 07:31:49
Apr 11 05:31:51 tkh-server tkh-force-failover: Detaching node 0 from
the pgpool cluster
Apr 11 05:31:51 tkh-server tkh-force-failover: pcp_detach_node --
Command Successful
Apr 11 05:31:51 tkh-server tkh-force-failover: Waiting for failover to complete
Apr 11 05:31:55 tkh-server tkh-force-failover: Node 0 status: 5432 3 0.333333 down standby 0   2021-04-11 07:31:52
Apr 11 05:31:55 tkh-server webhook: pg_rewind: source and target
cluster are on the same timeline
Apr 11 05:31:55 tkh-server webhook: pg_rewind: no rewind required
Apr 11 05:31:56 tkh-server webhook: Creating tkh-db ... done
Apr 11 05:31:57 tkh-server tkh-force-failover: Node 0 status: 5432 1 0.333333 waiting standby 160 streaming async
2021-04-11 07:31:56
Apr 11 05:31:57 tkh-server tkh-force-failover: Failover complete

As you can see, pg_rewinds decides that a rewind is not needed.
However, when the database starts, it starts at a replication delay of
160. This is the first indication of something being wrong. After
this, the database is stopped again, some docker packages are being
modified and the database is started again. Now, the database does not
start anymore and reports:

{"log":"2021-04-11 07:32:34.145 CEST [1] LOG:  starting PostgreSQL
12.6 (Debian 12.6-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc
(Debian 8.3.0-6) 8.3.0,
{"log":"2021-04-11 07:32:34.145 CEST [1] LOG:  listening on IPv4
address \"\", port
{"log":"2021-04-11 07:32:34.145 CEST [1] LOG:  listening on IPv6
address \"::\", port
{"log":"2021-04-11 07:32:34.146 CEST [1] LOG:  listening on Unix
socket \"/var/run/postgresql/.s.PGSQL.5432\"\n","stream":"stderr","time":"2021-04-11T05:32:34.147019855Z"}
{"log":"2021-04-11 07:32:34.162 CEST [28] LOG:  database system was
shut down in recovery at 2021-04-11 07:32:07
{"log":"2021-04-11 07:32:34.163 CEST [28] LOG:  entering standby
{"log":"2021-04-11 07:32:34.163 CEST [28] FATAL:  requested timeline 2
is not a child of this server's
{"log":"2021-04-11 07:32:34.163 CEST [28] DETAIL:  Latest checkpoint
is at 0/50354F8 on timeline 1, but in the history of the requested
timeline, the server forked off from that timeline at
{"log":"2021-04-11 07:32:34.164 CEST [1] LOG:  startup process (PID
28) exited with exit code
{"log":"2021-04-11 07:32:34.164 CEST [1] LOG:  aborting startup due to
startup process
{"log":"2021-04-11 07:32:34.166 CEST [1] LOG:  database system is shut

The database (node 1) that now is the primary reports the following in the logs:

{"log":"2021-04-11 07:30:34.303 CEST [1] LOG:  database system is
ready to accept read only
{"log":"2021-04-11 07:30:34.320 CEST [32] LOG:  started streaming WAL
from primary at 0/5000000 on timeline
{"log":"2021-04-11 07:31:51.674 CEST [28] LOG:  received promote
{"log":"2021-04-11 07:31:51.674 CEST [32] FATAL:  terminating
walreceiver process due to administrator
{"log":"2021-04-11 07:31:51.676 CEST [28] LOG:  redo done at
{"log":"2021-04-11 07:31:51.676 CEST [28] LOG:  last completed
transaction was at log time 2021-04-11
{"log":"2021-04-11 07:31:51.681 CEST [28] LOG:  selected new timeline
ID: 2\n","stream":"stderr","time":"2021-04-11T05:31:51.682159124Z"}
{"log":"2021-04-11 07:31:51.798 CEST [28] LOG:  archive recovery
{"log":"2021-04-11 07:31:51.809 CEST [1] LOG:  database system is
ready to accept

>From what I can see, the database on node 0 thinks it is still on
timeline 1, where node 1 is at timeline 2. Why does pg_rewind decide
that a rewind is not required? Could this be a timing issue? Maybe the
rewind is started before node 1 actually started the new timeline? In
other tests we do see a rewind happening and in those cases the
database does start properly. The scripts we used are based on the
examples but modified to our setup. So pgpool_follow_master.sh first
checks if the database is up, then tries a pg_rewind and if this fails
a pg_basebackup. Finally it starts and attaches the node.

Best regards,

More information about the pgpool-general mailing list