Feedback-ID: i0fe9450f:Fastmail
Date: Mon, 23 Jun 2025 09:28:53 +0900
From: Michael Paquier <michael@paquier.xyz>
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: Alexander Korotkov <aekorotkov@gmail.com>,
	Melanie Plageman <melanieplageman@gmail.com>,
	pgsql-committers@lists.postgresql.org
Subject: Re: pgsql: Improve runtime and output of tests for replication slots
 checkp
Message-ID: <aFifxf0mcnqf2HXK@paquier.xyz>
References: <E1uSOip-002TUa-0p@gemulon.postgresql.org>
 <CAAKRu_ZCOzQpEumLFgG_+iw3FTa+hJ4SRpxzaQBYxxM_ZAzWcA@mail.gmail.com>
 <2542023.1750456985@sss.pgh.pa.us>
 <2585993.1750458298@sss.pgh.pa.us>
 <CAPpHfdsedYNmKDnDuueJor2k8kA+hgEJKFJRf4PhDowdP_A4Bg@mail.gmail.com>
 <CAPpHfdtmLNpswWzk2qQ7-nMBLod2GrRWwMvfb0hc7tQfDD--ZQ@mail.gmail.com>
 <2594452.1750462958@sss.pgh.pa.us>
 <CAPpHfdurV-j_e0pb=UFENAy3tyzxfF+yHveNDNQk2gM82WBU5A@mail.gmail.com>
 <2852529.1750553810@sss.pgh.pa.us>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="xcrv24uG3IrlNE0x"
Content-Disposition: inline
In-Reply-To: <2852529.1750553810@sss.pgh.pa.us>
Archived-At: 
 <https://www.postgresql.org/message-id/aFifxf0mcnqf2HXK%40paquier.xyz>
Precedence: bulk


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

On Sat, Jun 21, 2025 at 08:56:50PM -0400, Tom Lane wrote:
> Hmm.  My theory about what's happening is that we are writing a WAL
> record that spans across a page boundary, and the asynchronous
> immediate-stop request comes in and kills that operation, so that
> the first half of the record is on disk but the second is not.
> (This outcome would obviously be very timing-dependent.)  Then
> we restart the server, and crash recovery copes with that situation
> successfully.  But pg_logical_slot_get_changes() fails to, because
> it's coded in such a way that it will wait forever for the second
> half of the WAL record to appear.
>=20
> The main hole in this theory is: if crash recovery thought that the
> partial record was invalid, wouldn't it set the end-of-WAL position
> to the start of that record?  And shouldn't that stop
> pg_logical_slot_get_changes() from trying to process the partial
> record?  So I'm sure there's some details not quite right about
> this picture.  But maybe it's within hailing distance of the truth.

Obviously pg_logical_slot_get_changes() should not try to read the
record if it's not complete yet.  XLogDecodeNextRecord() may be
trusting too much the LSN given by its caller, though.

>> The new tests just spotted the existing bug.
>=20
> Yeah, that's what I think too.  The unintentional omission of a
> pre-shutdown delay in the 046 test has exposed some pre-existing
> fragility in pg_logical_slot_get_changes().  So I'm not in favor
> of changing 046 till we understand this better.

Yes, better to understand what's going on before changing the test,
and perhaps change 046 so as it provide stable coverage for this case,
even if discovered accidentally.

So, is it only pg_logical_slot_get_changes_guts() that's messed up in
this context, because XLogDecodeNextRecord() is trying to read pages
as it has a logic too permissive?  How did any of you reproduce the
failure?  Just by running the test in a loop?  It is one of these
patterns where a hardcoded sleep should do the trick and help with a
bisect.

By the way, At the bottom of test 046_checkpoint_logical_slot.pl, if
you expect the checkpoint to complete before sending the immediate
shutdown request, I would suggest to use a wait_for_log() based on
"checkpoint complete" or an equivalent loop.  What you are doing in
the test is unstable as written.
--
Michael

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

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

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAmhYn8UACgkQnvQgOdby
QH2pLw/+IAOKvPKBbRgTBB/3d0shPneD1BYLfLWi5shLuHCdYkCUzgYHbbwIYobu
EjwywG7gi1jh7bhxLFjUkSRz1nzLpGGCx2lEWAB1ORqT5pzy+jhrLfer7UtQLtLw
J+lmBxaUaDlZCAPuAZQezFMqP6OtUhL0oVL5HfnIUEWErwpsI0tNNZ3jXs4cMI4a
bQyIUYvpSUWT63Qjhbiew9hyYQ51qanbnGqXP0TQN2XHnTxxX/tateMbbAOD/5UM
Sf184wefVVcJv0+6kjPwtO4Ms+Okhez4nzaSpnPC2FImuSrN7bwXseZunaXgb7Ry
dGu2pGXWTr6pDGOLWvxZyho7HbsSZy8fT0TelqImj1PbatzLB8go4lO/93AYAeIX
ZrRxueLLyUXragvXv8SUp6xlaTTkJ/JX4VoHWAzjcwmGNtVotHjVRqEPpf0T1Qwt
JdOwxOAExYFOmftPv2h3rXDHWvl4nPyVfxYlI4Vg2MdMurGi6tfkyVRF8iG928vu
VdFe5iJxo9RYNqwbCNYAWo6Cw5y74fJweg31LVLWwCprmXzTBNm1UP5p7vvJdnBw
a01Q5iLeGTavlTBgEwXSKNYt+xs4woRsficCmUcNQb3kfln7kvATUPvXcY8XM3FA
BrjV+T5y8OVv0DC30p5pYBOOb2hrrcsb27+ruuAASQtSnuEP/IE=
=57W1
-----END PGP SIGNATURE-----

--xcrv24uG3IrlNE0x--