Date: Tue, 12 Apr 2022 12:49:48 +0900
From: Michael Paquier <michael@paquier.xyz>
To: Thomas Munro <thomas.munro@gmail.com>
Cc: Andres Freund <andres@anarazel.de>, Tom Lane <tgl@sss.pgh.pa.us>,
	PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>
Subject: Re: pgsql: Add TAP test for archive_cleanup_command and
 recovery_end_comman
Message-ID: <YlT23IvsXkGuLzFi@paquier.xyz>
References: <E1mfuYK-0004Bn-7O@gemulon.postgresql.org>
 <3385143.1649353230@sss.pgh.pa.us>
 <20220407175210.q44nnrvkovprxo2a@alap3.anarazel.de>
 <3386734.1649354265@sss.pgh.pa.us>
 <20220407181202.7xa573u6e2z5dbdz@alap3.anarazel.de>
 <4015413.1649454951@sss.pgh.pa.us>
 <20220409005910.alw46xqmmgny2sgr@alap3.anarazel.de>
 <CA+hUKGJ-gvLg9vJgMvu62XW-Nsb2Hf40DvqmKdusVeJ7KV-crA@mail.gmail.com>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="fNDN1C94n5OJy+Qd"
Content-Disposition: inline
In-Reply-To: 
 <CA+hUKGJ-gvLg9vJgMvu62XW-Nsb2Hf40DvqmKdusVeJ7KV-crA@mail.gmail.com>
Archived-At: 
 <https://www.postgresql.org/message-id/YlT23IvsXkGuLzFi%40paquier.xyz>
Precedence: bulk


--fNDN1C94n5OJy+Qd
Content-Type: multipart/mixed; boundary="UUKqJhO8SBEXCjwY"
Content-Disposition: inline


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

On Mon, Apr 11, 2022 at 06:48:58PM +1200, Thomas Munro wrote:
> 1.  This test had some pre-existing bugs/races, which hadn't failed
> before due to scheduling, even under Valgrind.  The above changes
> appear to fix those problems.  To Michael for comment.

Yeah, there are two problems here.  From what I can see, ensuring the
execution of archive_cleanup_command on the standby needs the
checkpoint on the primary and the restart point on the standby.  So
pg_current_wal_lsn() should be located after the primary's checkpoint=20
and not before it so as we are sure that the checkpoint records finds
its way to the standby.  That's what Tom mentioned upthread.

The second problem is to make sure that $standby2 sees the promotion
of $standby and its history file, but we also want to recover
00000002.history from some archives to create a RECOVERYHISTORY at
recovery for the purpose of the test.  Switching to a new segment as
proposed by Andres does not seem completely right to me because we are
not 100% sure of the ordering an archive is going to happen, no?  I
think that the logic to create $standby2 from the initial backup of
the primary is right, because there is no 00000002.history in it, but
we also need to be sure that 00000002.history has been archived once
the promotion of $standby is done.  This can be validated thanks to
the logs, actually.

>> What is that second test really testing?
>>
>> # Check the presence of temporary files specifically generated during
>> # archive recovery.  To ensure the presence of the temporary history
>> # file, switch to a timeline large enough to allow a standby to recover
>> # a history file from an archive.  As this requires at least two timeline
>> # switches, promote the existing standby first.  Then create a second
>> # standby based on the promoted one.  Finally, the second standby is
>> # promoted.
>>
>> Note "Then create a second standby based on the promoted one." - but tha=
t's
>> not actually what's happening:
>=20
> 2.  There may also be other problems with the test but those aren't
> relevant to skink's failure, which starts on the 5th test.  To Michael
> for comment.

This comes from df86e52, where we want to recovery a history file that
would be created as RECOVERYHISTORY and make sure that the file gets
removed at the end of recovery.  So $standby2 should choose a new
timeline different from the one of chosen by $standby.  Looking back
at what has been done, it seems to me that the comment is the
incorrect part:
https://www.postgresql.org/message-id/20190930080340.GO2888@paquier.xyz

All that stuff leads me to the attached.  Thoughts?
--
Michael

--UUKqJhO8SBEXCjwY
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment; filename="tap-archiving-michael.patch"
Content-Transfer-Encoding: quoted-printable

diff --git a/src/test/recovery/t/002_archiving.pl b/src/test/recovery/t/002=
_archiving.pl
index c8f5ffbaf0..45aafcb35c 100644
--- a/src/test/recovery/t/002_archiving.pl
+++ b/src/test/recovery/t/002_archiving.pl
@@ -24,6 +24,8 @@ $node_primary->backup($backup_name);
=20
 # Initialize standby node from backup, fetching WAL from archives
 my $node_standby =3D PostgreSQL::Test::Cluster->new('standby');
+# Note that this makes the standby archive its contents on the archives
+# of the primary.
 $node_standby->init_from_backup($node_primary, $backup_name,
 	has_restoring =3D> 1);
 $node_standby->append_conf('postgresql.conf',
@@ -44,13 +46,16 @@ $node_standby->start;
 # Create some content on primary
 $node_primary->safe_psql('postgres',
 	"CREATE TABLE tab_int AS SELECT generate_series(1,1000) AS a");
-my $current_lsn =3D
-  $node_primary->safe_psql('postgres', "SELECT pg_current_wal_lsn();");
=20
 # Note the presence of this checkpoint for the archive_cleanup_command
 # check done below, before switching to a new segment.
 $node_primary->safe_psql('postgres', "CHECKPOINT");
=20
+# Done after the checkpoint to ensure that the checkpoint gets replayed
+# on the standby.
+my $current_lsn =3D
+  $node_primary->safe_psql('postgres', "SELECT pg_current_wal_lsn();");
+
 # Force archiving of WAL file to make it present on primary
 $node_primary->safe_psql('postgres', "SELECT pg_switch_wal()");
=20
@@ -81,10 +86,34 @@ ok( !-f "$data_dir/$recovery_end_command_file",
 # file, switch to a timeline large enough to allow a standby to recover
 # a history file from an archive.  As this requires at least two timeline
 # switches, promote the existing standby first.  Then create a second
-# standby based on the promoted one.  Finally, the second standby is
-# promoted.
+# standby based on the primary, using its archives.  Finally, the second
+# standby is promoted.
 $node_standby->promote;
=20
+# Wait until the history file has been archived on the archives of the
+# primary once the promotion of the standby completes.
+my $primary_archive =3D $node_primary->archive_dir;
+my $max_attempts =3D 10 * $PostgreSQL::Test::Utils::timeout_default;
+my $attempts     =3D 0;
+while ($attempts < $max_attempts)
+{
+	last if (-e "$primary_archive/00000002.history");
+
+	# Wait 0.1 second before retrying.
+	usleep(100_000);
+
+	$attempts++;
+}
+
+if ($attempts >=3D $max_attempts)
+{
+	die "timed out waiting for 00000002.history\n";
+}
+else
+{
+	note "found 00000002.history after $attempts attempts\n"
+}
+
 # recovery_end_command should have been triggered on promotion.
 ok( -f "$data_dir/$recovery_end_command_file",
 	'recovery_end_command executed after promotion');
@@ -108,14 +137,19 @@ my $log_location =3D -s $node_standby2->logfile;
 # Now promote standby2, and check that temporary files specifically
 # generated during archive recovery are removed by the end of recovery.
 $node_standby2->promote;
+
+# Check the logs of the standby to see that the commands have failed.
+my $log_contents =3D slurp_file($node_standby2->logfile, $log_location);
 my $node_standby2_data =3D $node_standby2->data_dir;
+
+like(
+	$log_contents,
+	qr/restored log file "00000002.history" from archive/s,
+	"00000002.history retrieved from the archives");
 ok( !-f "$node_standby2_data/pg_wal/RECOVERYHISTORY",
 	"RECOVERYHISTORY removed after promotion");
 ok( !-f "$node_standby2_data/pg_wal/RECOVERYXLOG",
 	"RECOVERYXLOG removed after promotion");
-
-# Check the logs of the standby to see that the commands have failed.
-my $log_contents =3D slurp_file($node_standby2->logfile, $log_location);
 like(
 	$log_contents,
 	qr/WARNING:.*recovery_end_command/s,

--UUKqJhO8SBEXCjwY--

--fNDN1C94n5OJy+Qd
Content-Type: application/pgp-signature; name="signature.asc"

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

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAmJU9twACgkQnvQgOdby
QH0+vxAAkKg+9S1TkMiN49ibtdp2J7nLELd1mUMjEU7llU7rFzMRTfkgrcdDADjT
7zIKJTfs0XluNTXc07b0Y6XGGCwZci7kk+K6v/OnFgbMgmko6ZlUGdrFvlpHBVuM
9KLkvFIq4Ev3EPr5JIL7pJI96CqEwfJ6iIs1c3khIlQ98RopY5T2H/dzEIubzaeJ
P+vJTryDqev4dnddOrEn45fIYzfaRykt7fmT8OIVl2o5bTXho27Gspn8ZtKVci2U
aUhtM77alQ9qT5I3nBAoaNUR/tTFyvU47x0o+bq+p7NVSKDVxY2V10Ge/urlY+y5
ZPjeY+HojnNI1JK3ZqONESJDmx5KINNifgsezAnqw7oZHN6K7KqCUG7h+KS7oJfW
WisW5FE/ZuwICqydrr5AOzkS+aLQ1uQs95Q/15ngyK3qd20g0DluivC7HUBkkmVO
uLuJZXu4Rn1GjwmWfmnFHZa2m1R3FImPUA3tTWl4NqHp2XP9ZMfKwdvVi3ZqK8Ze
7PvsLtAxtWeySSa1yWEJEE3BztWTn7827zTsQkbbadbHVrWUUooxsF5l4d/tVaUn
GD0QiGu1nkGLw/DYLKRMi+HMIKKBVHC2XXM2Z7/rsvrF3I66ikXBK8855W8bXPbO
P5BolATCw9kex1QuvtA0TArBstNnhep0hVal7LYu7r3K8jDlR2s=
=32n/
-----END PGP SIGNATURE-----

--fNDN1C94n5OJy+Qd--