Feedback-ID: i0fe9450f:Fastmail
Date: Wed, 21 Jun 2023 14:14:52 +0900
From: Michael Paquier <michael@paquier.xyz>
To: Nathan Bossart <nathandbossart@gmail.com>
Cc: Kyotaro Horiguchi <horikyota.ntt@gmail.com>,
	julian.markwort@cybertec.at, pgsql-hackers@postgresql.org
Subject: Re: [BUG] recovery of prepared transactions during promotion can fail
Message-ID: <ZJKHTPt2wIgDsUoi@paquier.xyz>
References: <743b9b45a2d4013bd90b6a5cba8d6faeb717ee34.camel@cybertec.at>
 <ZI/mnFy2QG4ULkPF@paquier.xyz>
 <20230619.144154.1628674635368115138.horikyota.ntt@gmail.com>
 <ZJADX9pvRpmX8i4G@paquier.xyz>
 <ZJEFj5aqdnTY/KO2@paquier.xyz>
 <20230621043345.GA787473@nathanxps13>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="Rvfe40Pvj5c2946S"
Content-Disposition: inline
In-Reply-To: <20230621043345.GA787473@nathanxps13>
Archived-At: 
 <https://www.postgresql.org/message-id/ZJKHTPt2wIgDsUoi%40paquier.xyz>
Precedence: bulk


--Rvfe40Pvj5c2946S
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable

On Tue, Jun 20, 2023 at 09:33:45PM -0700, Nathan Bossart wrote:
> I've started seen sporadic timeouts for 009_twophase.pl in cfbot, and I'm
> wondering if it's related to this change.
>=20
> 	https://api.cirrus-ci.com/v1/task/4978271838797824/logs/test_world.log
> 	https://api.cirrus-ci.com/v1/task/5477247717474304/logs/test_world.log
> 	https://api.cirrus-ci.com/v1/task/5931749746671616/logs/test_world.log
> 	https://api.cirrus-ci.com/v1/task/6353051175354368/logs/test_world.log
> 	https://api.cirrus-ci.com/v1/task/5687888986243072/logs/test_world.log

Thanks for the poke, missed that.

The logs are enough to know what's happening here.  All the tests
finish after this step:
[02:29:33.169] # Now paris is primary and london is standby
[02:29:33.169] ok 13 - Restore prepared transactions from records with
primary down

Here are some log files:
https://api.cirrus-ci.com/v1/artifact/task/5477247717474304/testrun/build/t=
estrun/recovery/009_twophase/log/009_twophase_london.log
https://api.cirrus-ci.com/v1/artifact/task/5477247717474304/testrun/build/t=
estrun/recovery/009_twophase/log/009_twophase_paris.log

Just after that, we start a previous primary as standby:
# restart old primary as new standby
$cur_standby->enable_streaming($cur_primary);
$cur_standby->start;

And the startup of the node gets stuck as the last partial segment is
now getting renamed, but the other node expects it to be available via
streaming.  From london, which is the new standby starting up:
2023-06-21 02:13:03.421 UTC [24652][walreceiver] LOG:  primary server
contains no more WAL on requested timeline 3
2023-06-21 02:13:03.421 UTC [24652][walreceiver] FATAL:  terminating
walreceiver process due to administrator command=20
2023-06-21 02:13:03.421 UTC [24647][startup] LOG:  new timeline 4
forked off current database system timeline 3 before current recovery
point 0/60000A0

And paris complains about that:
2023-06-21 02:13:03.515 UTC [24661][walsender] [london][4/0:0] LOG:
received replication command: START_REPLICATION 0/6000000 TIMELINE 3=20
2023-06-21 02:13:03.515 UTC [24661][walsender] [london][4/0:0]
STATEMENT:  START_REPLICATION 0/6000000 TIMELINE 3

But that won't connect work as the segment requested is now a partial
one in the primary's pg_wal, still the standby wants it.  Just
restoring the segments won't help much as we don't have anything for
partial segments in the TAP routines yet, so I think that it is better
for now to just undo has_archiving in has_archiving, and tackle the
coverage with a separate test, perhaps only for HEAD.
--
Michael

--Rvfe40Pvj5c2946S
Content-Type: application/pgp-signature; name="signature.asc"

-----BEGIN PGP SIGNATURE-----

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAmSSh0wACgkQnvQgOdby
QH2yIg//eZY8t28xCKlbBtJnzcL+dNhPMfJe40OT86TaF/HhLfmyhmOKzpSv67Rf
OSl7f3Xj04FIw4XQ8OMnXOMCKTi9r8X7lNedILIT9OTia5gN5nItA+tu5rCeJtZU
VDaZ6FF08LyOiAyVvUujAHY80DTbnXmoEbYPfMnz3cv0w0UDzDMYYIVSSXxIkjQg
KdKEQCRKwmxCpfcRJV7htiwz+hop8Fjq0jtQjk/C+oAlPj/nqLo+zlL2poEHvHCN
lpU6G4vFvEcPVnn7puLpSBlyFMfyYHMhB/d1vJ4Q4kTzzdz8BZ4F1Ri34ctEv5f1
lstAAmKisX5inREGhBlIwGRLhL2aUEW8GTnMUaHyuv3yUCppATHYi54hJq3VI8pc
eCdLeM/ZuQu0rMZIUmJv0odDcHunJuoF+3wguIq5lRZha2HXhybQl1VQSQLkJ4DO
e6z++OMEclt/VwOPWIwDEk1PZSJVjmQUHLl6SghvetageZtxGS5X91HY+xyk0Bcb
E7eUnLlUi+YLQHYBp+CaB9yCobvi9RxEUKMNnkoXlNhgnItn0j4f76E4FSieQDt1
7RJtjD/jIwi9L+Gs9HrXfffqDzvxjYlHZAJF3XP3te7OEAJvJYpwp4vDJohmN780
Iw6VaJWD/F+EzhG3bzL16RfymmxkwVP3aLDhRi4+a2ZOco+eEgE=
=y1Fj
-----END PGP SIGNATURE-----

--Rvfe40Pvj5c2946S--