From: Tom Lane <tgl@sss.pgh.pa.us>
To: Andres Freund <andres@anarazel.de>
cc: Thomas Munro <thomas.munro@gmail.com>,
        Melanie Plageman <melanieplageman@gmail.com>,
        pgsql-hackers@lists.postgresql.org
Subject: Re: Unstable tests for recovery conflict handling
In-reply-to: <447238.1651082925@sss.pgh.pa.us>
References: <E1nca5h-000nN0-6f@gemulon.postgresql.org>
 <394950.1651077914@sss.pgh.pa.us> <447238.1651082925@sss.pgh.pa.us>
Comments: In-reply-to Tom Lane <tgl@sss.pgh.pa.us>
	message dated "Wed, 27 Apr 2022 14:08:45 -0400"
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <2454339.1658858273.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable
Date: Tue, 26 Jul 2022 13:57:53 -0400
Message-ID: <2454340.1658858273@sss.pgh.pa.us>
Archived-At: 
 <https://www.postgresql.org/message-id/2454340.1658858273%40sss.pgh.pa.us>
Precedence: bulk

I wrote:
>> It's been kind of hidden by other buildfarm noise, but
>> 031_recovery_conflict.pl is not as stable as it should be [1][2][3][4].

> After digging around in the code, I think this is almost certainly
> some manifestation of the previously-complained-of problem [1] that
> RecoveryConflictInterrupt is not safe to call in a signal handler,
> leading the conflicting backend to sometimes decide that it's not
> the problem.

I happened to notice that while skink continues to fail off-and-on
in 031_recovery_conflict.pl, the symptoms have changed!  What
we're getting now typically looks like [1]:

[10:45:11.475](0.023s) ok 14 - startup deadlock: lock acquisition is waiti=
ng
Waiting for replication conn standby's replay_lsn to pass 0/33FB8B0 on pri=
mary
done
timed out waiting for match: (?^:User transaction caused buffer deadlock w=
ith recovery.) at t/031_recovery_conflict.pl line 367.

where absolutely nothing happens in the standby log, until we time out:

2022-07-24 10:45:11.452 UTC [1468367][client backend][2/4:0] LOG:  stateme=
nt: SELECT * FROM test_recovery_conflict_table2;
2022-07-24 10:45:11.472 UTC [1468547][client backend][3/2:0] LOG:  stateme=
nt: SELECT 'waiting' FROM pg_locks WHERE locktype =3D 'relation' AND NOT g=
ranted;
2022-07-24 10:48:15.860 UTC [1468362][walreceiver][:0] FATAL:  could not r=
eceive data from WAL stream: server closed the connection unexpectedly

So this is not a case of RecoveryConflictInterrupt doing the wrong thing:
the startup process hasn't detected the buffer conflict in the first
place.  Don't know what to make of that, but I vaguely suspect a test
timing problem.  gull has shown this once as well, although at a different
step in the script [2].

			regards, tom lane

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dskink&dt=3D2=
022-07-24%2007%3A00%3A29
[2] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dgull&dt=3D20=
22-07-23%2009%3A34%3A54