Fix race in TAP test 002_archiving.pl when restoring history file

michaelpq · michaelpq · commit 8bcf90c7a67c · 2022-04-18T11:40:14.000+09:00
This test, introduced in df86e52, uses a second standby to check that it is able to remove correctly RECOVERYHISTORY and RECOVERYXLOG at the end of recovery. This standby uses the archives of the primary to restore its contents, with some of the archive's contents coming from the first standby previously promoted. In slow environments, it was possible that the test did not check what it should, as the history file generated by the promotion of the first standby may not be stored yet on the archives the second standby feeds on. So, it could be possible that the second standby selects an incorrect timeline, without restoring a history file at all. This commits adds a wait phase to make sure that the history file required by the second standby is archived before this cluster is created. This relies on poll_query_until() with pg_stat_file() and an absolute path, something not supported in REL_10_STABLE. While on it, this adds a new test to check that the history file has been restored by looking at the logs of the second standby. This ensures that a RECOVERYHISTORY, whose removal needs to be checked, is created in the first place. This should make the test more robust. This test has been introduced by df86e52, but it came in light as an effect of the bug fixed by acf1dd4, where the extra restore_command calls made the test much slower. Reported-by: Andres Freund Discussion: https://postgr.es/m/YlT23IvsXkGuLzFi@paquier.xyz Backpatch-through: 11
diff --git a/src/test/recovery/t/002_archiving.pl b/src/test/recovery/t/002_archiving.pl
@@ -6,7 +6,7 @@
 use warnings;
 use PostgresNode;
 use TestLib;
-use Test::More tests => 3;
+use Test::More tests => 4;
 use File::Copy;
 
 # Initialize primary node, doing archives
@@ -24,6 +24,8 @@
 
 # Initialize standby node from backup, fetching WAL from archives
 my $node_standby = get_new_node('standby');
+# Note that this makes the standby store its contents on the archives
+# of the primary.
 $node_standby->init_from_backup($node_primary, $backup_name,
 	has_restoring => 1);
 $node_standby->append_conf('postgresql.conf',
@@ -58,19 +60,39 @@
 # 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;
 
+# Wait until the history file has been stored on the archives of the
+# primary once the promotion of the standby completes.  This ensures that
+# the second standby created below will be able to restore this file,
+# creating a RECOVERYHISTORY.
+my $primary_archive = $node_primary->archive_dir;
+$caughtup_query =
+  "SELECT size IS NOT NULL FROM pg_stat_file('$primary_archive/00000002.history')";
+$node_primary->poll_query_until('postgres', $caughtup_query)
+  or die "Timed out while waiting for archiving of 00000002.history";
+
 my $node_standby2 = get_new_node('standby2');
 $node_standby2->init_from_backup($node_primary, $backup_name,
 	has_restoring => 1);
 $node_standby2->start;
 
+my $log_location = -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       = slurp_file($node_standby2->logfile, $log_location);
 my $node_standby2_data = $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",
