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

[ starting a new thread cuz the shared-stats one is way too long ]

Andres Freund <andres@anarazel.de> writes:
> Add minimal tests for recovery conflict handling.

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].

Three of those failures look like

[11:08:46.806](105.129s) ok 1 - buffer pin conflict: cursor with conflicti=
ng pin established
Waiting for replication conn standby's replay_lsn to pass 0/33EF190 on pri=
mary
[12:01:49.614](3182.807s) # poll_query_until timed out executing this quer=
y:
# SELECT '0/33EF190' <=3D replay_lsn AND state =3D 'streaming'
#          FROM pg_catalog.pg_stat_replication
#          WHERE application_name IN ('standby', 'walreceiver')
# expecting this output:
# t
# last actual query output:
# f
# with stderr:
timed out waiting for catchup at t/031_recovery_conflict.pl line 123.

In each of these examples we can see in the standby's log that it
detected the expected buffer pin conflict:

2022-04-27 11:08:46.353 UTC [1961604][client backend][2/2:0] LOG:  stateme=
nt: BEGIN;
2022-04-27 11:08:46.416 UTC [1961604][client backend][2/2:0] LOG:  stateme=
nt: DECLARE test_recovery_conflict_cursor CURSOR FOR SELECT b FROM test_re=
covery_conflict_table1;
2022-04-27 11:08:46.730 UTC [1961604][client backend][2/2:0] LOG:  stateme=
nt: FETCH FORWARD FROM test_recovery_conflict_cursor;
2022-04-27 11:08:47.825 UTC [1961298][startup][1/0:0] LOG:  recovery still=
 waiting after 13.367 ms: recovery conflict on buffer pin
2022-04-27 11:08:47.825 UTC [1961298][startup][1/0:0] CONTEXT:  WAL redo a=
t 0/33E6E80 for Heap2/PRUNE: latestRemovedXid 0 nredirected 0 ndead 1; blk=
ref #0: rel 1663/16385/16386, blk 0

but then nothing happens until the script times out and kills the test.
I think this is showing us a real bug, ie we sometimes fail to cancel
the conflicting query.

The other example [3] looks different:

[01:02:43.582](2.357s) ok 1 - buffer pin conflict: cursor with conflicting=
 pin established
Waiting for replication conn standby's replay_lsn to pass 0/342C000 on pri=
mary
done
[01:02:43.747](0.165s) ok 2 - buffer pin conflict: logfile contains termin=
ated connection due to recovery conflict
[01:02:43.804](0.057s) not ok 3 - buffer pin conflict: stats show conflict=
 on standby
[01:02:43.805](0.000s) =

[01:02:43.805](0.000s) #   Failed test 'buffer pin conflict: stats show co=
nflict on standby'
#   at t/031_recovery_conflict.pl line 295.
[01:02:43.805](0.000s) #          got: '0'
#     expected: '1'

Not sure what to make of that --- could there be a race condition in the
reporting of the conflict?

			regards, tom lane

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dskink&dt=3D2=
022-04-27%2007%3A16%3A51
[2] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dperipatus&dt=
=3D2022-04-21%2021%3A20%3A15
[3] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dmorepork&dt=3D=
2022-04-13%2022%3A45%3A30
[4] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dskink&dt=3D2=
022-04-11%2005%3A40%3A41