Subject: pgsql: Add TAP test for archive_cleanup_command and recovery_end_comman

From: Michael Paquier <[email-masked]>
Date: Thu, 28 Oct 2021 01:50:00 +0000

Add TAP test for archive_cleanup_command and recovery_end_command

This adds tests checking for the execution of both commands.  The
recovery test 002_archiving.pl is nicely adapted to that, as promotion
is triggered already twice there, and even if any of those commands fail
they don't affect recovery or promotion.

A command success is checked using a file generated by an "echo"
command, that should be able to work in all the buildfarm environments,
even Msys (but we'll know soon about that).  Command failure is tested
with an "echo" command that points to a path that does not exist,
scanning the backend logs to make sure that the failure happens.  Both
rely on the backend triggering the commands from the root of the data
folder, making its logic more robust.

Thanks to Neha Sharma for the extra tests on Windows.

Author: Amul Sul, Michael Paquier
Reviewed-by: Andres Freund, Euler Taveira
Discussion: https://postgr.es/m/CAAJ_b95R_c4T5moq30qsybSU=eDzDHm=4SPiAWaiMWc2OW7=[email-masked]

Branch
------
master

Details
-------
https://git.postgresql.org/pg/commitdiff/46dea2419ee7895a4eb3d048317682e6f18a17e1

Modified Files
--------------
src/test/recovery/t/002_archiving.pl | 47 +++++++++++++++++++++++++++++++++++-
1 file changed, 46 insertions(+), 1 deletion(-)

---

From: Michael Paquier <[email-masked]>
Date: Mon, 11 Apr 2022 16:43:26 +0900

On Mon, Apr 11, 2022 at 06:48:58PM +1200, Thomas Munro wrote:
> Sorry for the delay... I got a bit confused about the different things
> going on in this thread but I hope I've got it now:
> 
> 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.

I have seen the thread, and there is a lot in it.  I will try to look
tomorrow at the parts I got involved in.
--
Michael

---

From: Michael Paquier <[email-masked]>
Date: Tue, 12 Apr 2022 12:49:48 +0900

> 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 
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 that's
>> not actually what's happening:
> 
> 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/[email-masked]

All that stuff leads me to the attached.  Thoughts?
--
Michael
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);
 
 # Initialize standby node from backup, fetching WAL from archives
 my $node_standby = 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 => 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 =
-  $node_primary->safe_psql('postgres', "SELECT pg_current_wal_lsn();");
 
 # 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");
 
+# Done after the checkpoint to ensure that the checkpoint gets replayed
+# on the standby.
+my $current_lsn =
+  $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()");
 
@@ -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;
 
+# Wait until the history file has been archived on the archives of the
+# primary once the promotion of the standby completes.
+my $primary_archive = $node_primary->archive_dir;
+my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
+my $attempts     = 0;
+while ($attempts < $max_attempts)
+{
+	last if (-e "$primary_archive/00000002.history");
+
+	# Wait 0.1 second before retrying.
+	usleep(100_000);
+
+	$attempts++;
+}
+
+if ($attempts >= $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 = -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",
 	"RECOVERYXLOG removed after promotion");
-
-# Check the logs of the standby to see that the commands have failed.
-my $log_contents = slurp_file($node_standby2->logfile, $log_location);
 like(
 	$log_contents,
 	qr/WARNING:.*recovery_end_command/s,

---

From: Michael Paquier <[email-masked]>
Date: Sun, 17 Apr 2022 13:17:32 +0900

On Sun, Apr 17, 2022 at 08:56:33AM +1200, Thomas Munro wrote:
> Under valgrind I got "Undefined subroutine &main::usleep called at
> t/002_archiving.pl line 103" so I added "use Time::HiRes qw(usleep);",
> and now I get past the first 4 tests with your patch, but then
> promotion times out, not sure why:
> 
> +++ tap check in src/test/recovery +++
> t/002_archiving.pl ..
> ok 1 - check content from archives
> ok 2 - archive_cleanup_command executed on checkpoint
> ok 3 - recovery_end_command not executed yet
> # found 00000002.history after 14 attempts
> ok 4 - recovery_end_command executed after promotion
> Bailout called.  Further testing stopped:  command "pg_ctl -D
> /home/tmunro/projects/postgresql/src/test/recovery/tmp_check/t_002_archiving_standby2_data/pgdata
> -l /home/tmunro/projects/postgresql/src/test/recovery/tmp_check/log/002_archiving_standby2.log
> promote" exited with value 1

Hmm.  As far as I can see, aren't you just hitting the 60s timeout of 
pg_ctl here due to the slowness of valgrind?

> Since it's quite painful to run TAP tests under valgrind, I found a
> place to stick a plain old sleep to repro these problems:

Actually, I am wondering how you are patching Cluster.pm to do that.

> Soon I'll push the fix to the slowness that xlogprefetcher.c
> accidentally introduced to continuous archive recovery, ie the problem
> of calling a failing restore_command repeatedly as we approach the end
> of a WAL segment instead of just once every 5 seconds after we run out
> of data, and after that you'll probably need to revert that fix
> locally to repro this.

Okay.  Thanks.  Anyway, I'll do something about that tomorrow (no
room to look at the buildfarm today), and I was thinking about
replacing the while loop I had in the last version of the patch with a
poll_query_until that does a pg_stat_file() with an absolute path to
the history file to avoid the dependency to usleep() in the test,
splitting the fix into two commits as there is more than one problem,
each applying to different branches.
--
Michael

---

From: Michael Paquier <[email-masked]>
Date: Mon, 18 Apr 2022 08:49:17 +0900

On Sun, Apr 17, 2022 at 10:56:08AM -0400, Andrew Dunstan wrote:
> I don't really think it's Cluster.pm's business to deal with that. It
> takes an install path as given either explicitly or implicitly.
> 
> It shouldn't be too hard to get Makefile.global to install valgrind
> wrappers into the tmp_install/bin directory.

Or what gets used in just a wrapper of the contents of bin/ that get
enforced to be first in PATH?
--
Michael

---

From: Michael Paquier <[email-masked]>
Date: Mon, 18 Apr 2022 13:55:13 +0900

> https://www.postgresql.org/message-id/[email-masked]

acf1dd42 has taken care of the failures of this test with skink, and I
have just taken care of the two races in the tests with e61efaf and
1a8b110.  I have left e61efaf out of REL_10_STABLE as the idea of
relying on a poll_query_until() with pg_stat_file() and an absolute
path would not work there, and the branch will be EOL'd soon while
there were no complains with this test for two years.
--
Michael

---

From: Michael Paquier <[email-masked]>
Date: Tue, 19 Apr 2022 11:33:25 +0900

On Tue, Apr 19, 2022 at 09:45:11AM +1200, Thomas Munro wrote:
> Delayed response to the question on how I did that, because it was a 4
> day weekend down here and I got distracted by sunshine...

Happy Easter.

> I think that sort of thing actually worked when I tried it on a
> beefier workstation, but it sent my Thinkpad that "only" has a 16GB of
> RAM into some kind of death spiral.  The way I succeeded was indeed
> using a wrapper script, based on a suggestion from Andres, my
> kludgy-hardcoded-path-assuming implementation of which looked like:
> 
> Yeah, it might be quite neat to find a tool-supported way to do that.

Thanks for the details.  I feared that it was something like that for
the backend.  At least that's better than having valgrind spawn all
the processes kicked by the make command.  :/

> Tangentially, I'd also like to look into making
> PostgreSQL-under-Valgrind work on FreeBSD and macOS, which didn't work
> last time I tried it for reasons that might, I hope, have been fixed
> on the Valgrind side by now.

Okay.

As a side note, skink has cooled down since acf1dd4, and did not
complain either after the additions of e61efaf and 1a8b110.
--
Michael