Feedback-ID: i0fe9450f:Fastmail
Date: Thu, 14 Mar 2024 16:00:44 +0900
From: Michael Paquier <michael@paquier.xyz>
To: David Steele <david@pgmasters.net>
Cc: pgsql-hackers@lists.postgresql.org
Subject: Re: Add basic tests for the low-level backup method.
Message-ID: <ZfKgnG09TRKAnDb6@paquier.xyz>
References: <03e4cf19-fb76-4891-accc-edd429a25b21@pgmasters.net>
 <431ecc5d-8c07-4ee1-b05e-3ca536e606bb@pgmasters.net>
 <ZeAAPW8h1uxvt4Bj@paquier.xyz>
 <4980aba2-9cd4-4bd6-b2e1-e873639ab7ee@pgmasters.net>
 <ZfFEfImMw1gtA9zJ@paquier.xyz>
 <f20fcc82-dadb-478d-beb4-1e2ffb0ace76@pgmasters.net>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="oDmEdP2FhktuUqsq"
Content-Disposition: inline
In-Reply-To: <f20fcc82-dadb-478d-beb4-1e2ffb0ace76@pgmasters.net>
Archived-At: 
 <https://www.postgresql.org/message-id/ZfKgnG09TRKAnDb6%40paquier.xyz>
Precedence: bulk


--oDmEdP2FhktuUqsq
Content-Type: multipart/mixed; boundary="7tEWqKt9g0JlDqbq"
Content-Disposition: inline


--7tEWqKt9g0JlDqbq
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

On Thu, Mar 14, 2024 at 09:12:52AM +1300, David Steele wrote:
> I think you are right that the start message is better since it can only
> appear once when the backup_label is found. The completed message could in
> theory appear after a restart, though the backup_label must have been found
> at some point.

So, I've given a try to this patch with 99b4a63bef94, to note that
sidewinder failed because of a timing issue on Windows: the recovery
of the node without backup_label, expected to fail, would try to
backup the last segment it has replayed, because, as it has no
backup_label, it behaves like the primary.  It would try to use the
same archive location as the primary, leading to a conflict failure on
Windows.  This one was easy to fix, by overwritting postgresql.conf on
the node to not do archiving.

Following that, I've noticed a second race condition: we don't wait
for the segment after pg_switch_wal() to be archived.  This one can be
easily avoided with a poll on pg_stat_archiver.

After that, also because I've initially managed to, cough, forget an
update of meson.build to list the new test, I've noticed a third
failure on Windows for the case of the node that has a backup_label.
Here is one of the failures:
https://cirrus-ci.com/task/5245341683941376

regress_log_042_low_level_backup and
042_low_level_backup_replica_success.log have all the information
needed, that can be summarized like that:
The system cannot find the file specified.
2024-03-14 06:02:37.670 GMT [560][startup] FATAL:  invalid data in file "backup_label"

The first message is something new to me, that seems to point to a
corruption failure of the file system.  Why don't we see something
similar in other tests, then?  Leaving that aside..

The second LOG is something that can be acted on.  I've added some
debugging to the parsing of the backup_label file in the backend, and
noticed that the first fscanf() for START WAL LOCATION is failing
because the last %c is detected as \r rather than \n.  Tweaking the
contents stored from pg_backend_stop() with a sed won't help, because
the issue is that we write the CRLFs with append_to_file, and the
startup process cannot cope with that.  The simplest method I can
think of is to use binmode, as of the attached.

It is the first time that we'd take the contents received from a
BackgroundPsql and write them to a file parsed by the backend, so
perhaps we should try to do that in a more general way, but I'm not
sure how, tbh, and the case of this test is special while adding
handling for \r when reading the backup_label got discussed in the
past but we were OK with what we are doing now on HEAD.

On top of all that, note that I have removed remove_tree as I am not
sure if this would be OK in all the buildfarm animals, added a quit()
for BackgroundPsql, moved queries to use less BackgroundPsql, as well
as a few other things like avoiding the hardcoded segment names.
meson.build is.. Cough.. Updated now.

I am attaching an updated patch with all that fixed, which is stable
in the CI and any tests I've run.  Do you have any comments about
that?
--
Michael

--7tEWqKt9g0JlDqbq
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
	filename="v3-0001-Add-basic-TAP-tests-for-the-low-level-backup-meth.patch"
Content-Transfer-Encoding: quoted-printable

=46rom 5799e7e48f02cd2ed1d8b2afb88001884c173855 Mon Sep 17 00:00:00 2001
=46rom: Michael Paquier <michael@paquier.xyz>
Date: Thu, 14 Mar 2024 15:57:58 +0900
Subject: [PATCH v3] Add basic TAP tests for the low-level backup method

There are currently no tests for the low-level backup method where
pg_backup_start() and pg_backup_stop() are involved while taking a
file-system backup.  The tests introduced in this commit rely on a
background psql process to make sure that the backup is taken while the
session doing the SQL start and stop calls remains alive.

Two cases are checked here with the backup taken:
- Recovery without a backup_label, leading to a corrupted state.
- Recovery with a backup_label, with a consistent state reached.
Both cases cross-check some patterns in the logs generated when running
recovery.

Author: David Steele
Discussion: https://postgr.es/m/f20fcc82-dadb-478d-beb4-1e2ffb0ace76@pgmast=
ers.net
---
 src/test/recovery/meson.build               |   1 +
 src/test/recovery/t/042_low_level_backup.pl | 144 ++++++++++++++++++++
 2 files changed, 145 insertions(+)
 create mode 100644 src/test/recovery/t/042_low_level_backup.pl

diff --git a/src/test/recovery/meson.build b/src/test/recovery/meson.build
index c67249500e..b1eb77b1ec 100644
--- a/src/test/recovery/meson.build
+++ b/src/test/recovery/meson.build
@@ -50,6 +50,7 @@ tests +=3D {
       't/039_end_of_wal.pl',
       't/040_standby_failover_slots_sync.pl',
       't/041_checkpoint_at_promote.pl',
+      't/042_low_level_backup.pl',
     ],
   },
 }
diff --git a/src/test/recovery/t/042_low_level_backup.pl b/src/test/recover=
y/t/042_low_level_backup.pl
new file mode 100644
index 0000000000..0a75a8624a
--- /dev/null
+++ b/src/test/recovery/t/042_low_level_backup.pl
@@ -0,0 +1,144 @@
+
+# Copyright (c) 2024, PostgreSQL Global Development Group
+
+# Test low-level backup method by using pg_backup_start() and pg_backup_st=
op()
+# to create backups.
+
+use strict;
+use warnings;
+
+use File::Copy qw(copy);
+use File::Path qw(rmtree);
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Test::More;
+
+# Start primary node with archiving.
+my $node_primary =3D PostgreSQL::Test::Cluster->new('primary');
+$node_primary->init(has_archiving =3D> 1, allows_streaming =3D> 1);
+$node_primary->start;
+
+# Start backup.
+my $backup_name =3D 'backup1';
+my $psql =3D $node_primary->background_psql('postgres');
+
+$psql->query_safe("SET client_min_messages TO WARNING");
+$psql->set_query_timer_restart;
+$psql->query_safe("select pg_backup_start('test label')");
+
+# Copy files.
+my $backup_dir =3D $node_primary->backup_dir . '/' . $backup_name;
+
+PostgreSQL::Test::RecursiveCopy::copypath($node_primary->data_dir,
+	$backup_dir);
+
+# Cleanup some files/paths that should not be in the backup.  There is no
+# attempt to handle all the exclusions done by pg_basebackup here, in part
+# because these are not required, but also to keep the test simple.
+#
+# Also remove pg_control because it needs to be copied later.
+unlink("$backup_dir/postmaster.pid")
+  or BAIL_OUT("unable to unlink $backup_dir/postmaster.pid");
+unlink("$backup_dir/postmaster.opts")
+  or BAIL_OUT("unable to unlink $backup_dir/postmaster.opts");
+unlink("$backup_dir/global/pg_control")
+  or BAIL_OUT("unable to unlink $backup_dir/global/pg_control");
+
+rmtree("$backup_dir/pg_wal")
+  or BAIL_OUT("unable to unlink contents of $backup_dir/pg_wal");
+mkdir("$backup_dir/pg_wal");
+
+# Create a table that will be used to verify that recovery started at the
+# correct location, rather than a location recorded in the control file.
+$node_primary->safe_psql('postgres', "create table canary (id int)");
+
+# Advance the checkpoint location in pg_control past the location where the
+# backup started.  Switch WAL to make it really clear that the location is
+# different and to put the checkpoint in a new WAL segment.
+my $segment_name =3D $node_primary->safe_psql('postgres',
+	"select pg_walfile_name(pg_switch_wal())");
+
+# Ensure that the segment just switched from is archived.  The follow-up
+# tests depend on its presence to begin recovery.
+$node_primary->poll_query_until('postgres',
+	q{SELECT last_archived_wal FROM pg_stat_archiver},
+	$segment_name)
+  or die
+  "Timed out while waiting for archiving of switched segment to finish";
+
+$node_primary->safe_psql('postgres', "checkpoint");
+
+# Copy pg_control last so it contains the new checkpoint.
+copy($node_primary->data_dir . '/global/pg_control',
+	"$backup_dir/global/pg_control")
+  or BAIL_OUT("unable to copy global/pg_control");
+
+# Save the name segment that will be archived by pg_backup_stop().
+# This is copied to the pg_wal directory of the node whose recovery
+# is done without a backup_label.
+my $stop_segment_name =3D $node_primary->safe_psql('postgres',
+	'SELECT pg_walfile_name(pg_current_wal_lsn())');
+
+# Stop backup and get backup_label, the last segment is archived.
+my $backup_label =3D
+  $psql->query_safe("select labelfile from pg_backup_stop()");
+
+$psql->quit;
+
+# Rather than writing out backup_label, try to recover the backup without
+# backup_label to demonstrate that recovery will not work correctly withou=
t it,
+# i.e. the canary table will be missing and the cluster will be corrupted.
+# Provide only the WAL segment that recovery will think it needs.
+#
+# The point of this test is to explicitly demonstrate that backup_label is
+# being used in a later test to get the correct recovery info.
+my $node_replica =3D PostgreSQL::Test::Cluster->new('replica_fail');
+$node_replica->init_from_backup($node_primary, $backup_name);
+$node_replica->append_conf('postgresql.conf', "archive_mode =3D off");
+
+my $canary_query =3D "select count(*) from pg_class where relname =3D 'can=
ary'";
+
+copy(
+	$node_primary->archive_dir . "/$stop_segment_name",
+	$node_replica->data_dir . "/pg_wal/$stop_segment_name"
+) or BAIL_OUT("unable to copy $stop_segment_name");
+
+$node_replica->start;
+
+ok($node_replica->safe_psql('postgres', $canary_query) =3D=3D 0,
+	'canary is missing');
+
+# Check log to ensure that crash recovery was used as there is no
+# backup_label.
+ok( $node_replica->log_contains(
+		'database system was not properly shut down; automatic recovery in progr=
ess'
+	),
+	'verify backup recovery performed with crash recovery');
+
+$node_replica->teardown_node;
+$node_replica->clean_node;
+
+# Save backup_label into the backup directory and recover using the primar=
y's
+# archive.  This time recovery will succeed and the canary table will be
+# present.
+open my $fh, ">>", "$backup_dir/backup_label"
+  or die "could not open backup_label";
+# Binary mode is required for Windows, as the backup_label parsing is not
+# able to cope with CRLFs.
+binmode $fh;
+print $fh $backup_label;
+close $fh;
+
+$node_replica =3D PostgreSQL::Test::Cluster->new('replica_success');
+$node_replica->init_from_backup($node_primary, $backup_name,
+	has_restoring =3D> 1);
+$node_replica->start;
+
+ok($node_replica->safe_psql('postgres', $canary_query) =3D=3D 1,
+	'canary is present');
+
+# Check log to ensure that backup_label was used for recovery.
+ok($node_replica->log_contains('starting backup recovery with redo LSN'),
+	'verify backup recovery performed with backup_label');
+
+done_testing();
--=20
2.43.0


--7tEWqKt9g0JlDqbq--

--oDmEdP2FhktuUqsq
Content-Type: application/pgp-signature; name="signature.asc"

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

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAmXyoJwACgkQnvQgOdby
QH3P9Q/8ChBHysif17d7iFS8gHlH3rpmNjyLH/bou4xJP3OQTLly1SAGTEsh+r3Q
3rJhnYsZEFoB19iQcglPJVY7k/xU515Vdmc/+ilQfWwh/QABe/eiIKsOl7by2oiT
p0au3XR8n00t45zmr4mWdGtV723a9gx2dzLess+/eiPx+5UAaNVm6j+3TU4NOOsy
4ItBO22gHC7rPbVElc560RcyslnRDU+q3HT2QpChP0hezNsM58Kh1j79mEuqNaQn
IVFm4BtoaqgxzrB91A5W5fyEaukpz73ies2TsMdsGtC8RbIfbQn0rSrEh/QHr3bh
677owiy4ZKj3/quON5mlPqmBpLuQslwuglrtzgHBCXPhIOm2MifrLGtAxx3PtFNE
7FRM/brfNvAp4NZ2Ejfz4vdLZt4GNDGCQ61tPZIIIPQXMEwKKzeFi7EcoXj52aFn
Oq0ZPfwZIcHGCCTvP2riAnKRUzQkG0es2AJ2C+Nng4ewwNSHPJhItHklQizJLsIb
v5hUBv/RnZriv1ODczsREtRfOzqQDOTO68jJhN+YJP89oJ3mNAAsA1o9Mylc9ouA
7fRb1iJlQbr9qJRYrNXPZx5HBcb7KN1tyNSPnzl4EBBL288zVDQiYJJsr982Tdz4
gXXzORR64Gpv9bnfeEV7MFRB1ZE96B/o+Ypxv5E+nZxc6HiLlAc=
=Zr42
-----END PGP SIGNATURE-----

--oDmEdP2FhktuUqsq--