Feedback-ID: i0fe9450f:Fastmail
Date: Tue, 15 Aug 2023 15:11:16 +0900
From: Michael Paquier <michael@paquier.xyz>
To: Thomas Munro <thomas.munro@gmail.com>
Cc: Noah Misch <noah@leadboat.com>, Tom Lane <tgl@sss.pgh.pa.us>,
	Kyotaro Horiguchi <horikyota.ntt@gmail.com>, exclusion@gmail.com,
	pgsql-bugs@lists.postgresql.org
Subject: Re: BUG #17928: Standby fails to decode WAL on termination of primary
Message-ID: <ZNsXBFsFsKcCbP0q@paquier.xyz>
References: <351991.1691800320@sss.pgh.pa.us>
 <20230812211327.GB2326466@rfd.leadboat.com>
 <CA+hUKGKcSyHRppTyGZy7q29E1JVtQKdKCNzY0QARG3gfqpLaXg@mail.gmail.com>
 <20230813033034.GD2326466@rfd.leadboat.com>
 <ZNmMqEXJ6ECTQ0Ys@paquier.xyz>
 <CA+hUKGKWPvSJkQ1De6bjV311Xk+cXU8K7a=71-ypvxJGHom5aA@mail.gmail.com>
 <CA+hUKGLOgGh=9siEhACUsrZEAQPVEQWgn35cggeci0_cNbPSSw@mail.gmail.com>
 <ZNrdQSWe1flOfHN3@paquier.xyz>
 <CA+hUKGLzv=8g3MFwm+TGFu+7koypgmU7qKHni+nrEnuJ8P6eog@mail.gmail.com>
 <ZNrqTmKGnZwz9gPI@paquier.xyz>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="cONQMGqZJa7jouAw"
Content-Disposition: inline
In-Reply-To: <ZNrqTmKGnZwz9gPI@paquier.xyz>
Archived-At: 
 <https://www.postgresql.org/message-id/ZNsXBFsFsKcCbP0q%40paquier.xyz>
Precedence: bulk


--cONQMGqZJa7jouAw
Content-Type: multipart/mixed; boundary="BzrlH3YCI6+voGMz"
Content-Disposition: inline


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

On Tue, Aug 15, 2023 at 12:00:30PM +0900, Michael Paquier wrote:
> Not sure if that will help, but what I was playing with some stuff in
> the lines of:
> -- Store the length up to page boundary.
> select setting::int - ((pg_current_wal_insert_lsn() - '0/0') %
>   setting::int) as boundary from pg_settings where name =3D 'wal_block_si=
ze'
>   \gset
> -- Generate record up to boundary (56 bytes for base size of the record,
> -- stop at 12 bytes before the end of the page.
> select pg_logical_emit_message(false, '', repeat('a', :boundary - 56 - 12=
));
>=20
> Then by injecting some FF's on the last page written and forcing
> replay I am able to force some of the error code paths, so I guess
> that's what you were basically doing?

I've been spending some extra time on this one and hacked a TAP test
that reliably reproduces the original issue, using a message similar
to what I mentioned in my previous messages.  I guess that we could
use something like that:
2023-08-15 15:07:03.790 JST [8729] LOG:  redo starts at 0/14EA428
2023-08-15 15:07:03.790 JST [8729] FATAL:  invalid memory alloc
request size 4294969740 2023-08-15
15:07:03.791 JST [8726] LOG:  startup process (PID 8729) exited with exit c=
ode 1=20

The proposed patches pass the test, HEAD does not.  We may want to do
more with page boundaries, and more error patterns, but the idea looks
worth exploring more.  At least this can be used to validate patches.

I've noticed while hacking the test that we don't do a XLogFlush()
after inserting the message's record, so we may lose it on crash.
That makes the test unstable except if an extra record is added after
the logical messages.  The attached patch forces that for the sake of
the test, but I'm spawning a different thread as losing this data
looks like a bug to me.
--
Michael

--BzrlH3YCI6+voGMz
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
	filename="0001-Add-test-to-emulate-random-garbage-data-during-WAL-r.patch"
Content-Transfer-Encoding: quoted-printable

=46rom 958130099bc76534031acc4d3f2e94ccbcfa5451 Mon Sep 17 00:00:00 2001
=46rom: Michael Paquier <michael@paquier.xyz>
Date: Tue, 15 Aug 2023 15:09:28 +0900
Subject: [PATCH] Add test to emulate random garbage data during WAL replay,
 doing OOMs

This requires an extra flush wait at the end of LogLogicalMessage() to
make the test stable.
---
 src/backend/replication/logical/message.c |  7 ++-
 src/test/recovery/t/038_wal_invalid.pl    | 69 +++++++++++++++++++++++
 2 files changed, 75 insertions(+), 1 deletion(-)
 create mode 100644 src/test/recovery/t/038_wal_invalid.pl

diff --git a/src/backend/replication/logical/message.c b/src/backend/replic=
ation/logical/message.c
index c5de14afc6..cebe6c5d05 100644
--- a/src/backend/replication/logical/message.c
+++ b/src/backend/replication/logical/message.c
@@ -47,6 +47,7 @@ LogLogicalMessage(const char *prefix, const char *message=
, size_t size,
 				  bool transactional)
 {
 	xl_logical_message xlrec;
+	XLogRecPtr	lsn;
=20
 	/*
 	 * Force xid to be allocated if we're emitting a transactional message.
@@ -71,7 +72,11 @@ LogLogicalMessage(const char *prefix, const char *messag=
e, size_t size,
 	/* allow origin filtering */
 	XLogSetRecordFlags(XLOG_INCLUDE_ORIGIN);
=20
-	return XLogInsert(RM_LOGICALMSG_ID, XLOG_LOGICAL_MESSAGE);
+	lsn =3D XLogInsert(RM_LOGICALMSG_ID, XLOG_LOGICAL_MESSAGE);
+
+	/* Make sure that the message hits disk before leaving */
+	XLogFlush(lsn);
+	return lsn;
 }
=20
 /*
diff --git a/src/test/recovery/t/038_wal_invalid.pl b/src/test/recovery/t/0=
38_wal_invalid.pl
new file mode 100644
index 0000000000..87a6e93734
--- /dev/null
+++ b/src/test/recovery/t/038_wal_invalid.pl
@@ -0,0 +1,69 @@
+
+# Copyright (c) 2021-2023, PostgreSQL Global Development Group
+
+# Test for code paths involving detection of incorrect WAL records.
+
+use strict;
+use warnings;
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Test::More;
+
+# Initialize and start node with wal_level =3D minimal and some
+# configuration aimed at minimizing the WAL activity of the cluster.
+my $node =3D PostgreSQL::Test::Cluster->new('primary');
+$node->init;
+$node->append_conf('postgresql.conf', q[
+wal_level =3D minimal
+autovacuum =3D off
+checkpoint_timeout =3D '30min'
+]);
+$node->start;
+
+# Generate two WAL records that will be used for the follow-up test,
+# using pg_logical_emit_message.  This function returns the end LSN
+# of the record inserted, and the LSN of the first record is what
+# we use to invalidate the beginning of the second record.  This
+# emulates some historical patterns where a record is read on a
+# page read from a recycled segment at the end of WAL.  The second
+# record could be anything, but pg_logical_emit_message() does not
+# impact the cluster consistency.
+my $result =3D $node->safe_psql('postgres',
+  q{SELECT * FROM pg_walfile_name_offset(pg_logical_emit_message(false, 'a=
', 'a'))});
+my ($wal_segment_name, $lsn_offset) =3D split /\|/, $result;
+$lsn_offset =3D int($lsn_offset);
+
+$node->safe_psql('postgres',
+  q{SELECT pg_logical_emit_message(false, 'a', 'a')});
+
+# Shut down the cluster, to replay the previous records.
+$node->stop('immediate');
+
+# Add 4 bytes of garbage at the beginning of the second record, to
+# emulate the case of a recycled page.  The previous offset points
+# at the beginning of the second record's xl_tot_len.
+my $pgdata =3D $node->data_dir;
+
+my $fh;
+open($fh, '+<', "$pgdata/pg_wal/$wal_segment_name")
+    or BAIL_OUT("open failed: $!");
+sysseek($fh, $lsn_offset, 0)
+    or BAIL_OUT("sysseek failed: $!");
+syswrite($fh, pack("L", 0xFFFFFFFF)) or BAIL_OUT("syswrite failed: $!");
+close($fh)
+    or BAIL_OUT("close failed: $!");
+
+# The node should be able to start.
+my $log_location =3D -s $node->logfile;
+$node->start;
+$result =3D $node->safe_psql('postgres', q(SELECT 1));
+is($result, "1", "node is up and running");
+
+# Confirm thatrecovery has finished with the expected error
+my $logfile =3D slurp_file($node->logfile, $log_location);
+ok( $logfile =3D~
+	  qr/LOG: .* invalid magic number 0000 in WAL segment $wal_segment_name/,
+	"recovery completed up to the invalid record"
+);
+
+done_testing();
--=20
2.40.1


--BzrlH3YCI6+voGMz--

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

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

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAmTbFwQACgkQnvQgOdby
QH3M7w/+JiDELY1xQ/GftU37lAZrX4UIFnzcF7ALuf0yM6jJGdXybqbtssstKxg/
Yqrks81ljG6ukyWKvTBUzASBZpmn48ZCFeNBNS8Zu/s9Fh48wGX2w9rZbOebEduu
Ha5vM+U59AEeHn+4PAjBxoaVLARkxbb5FGlX8I8ri3eXgwahvkcP74hnxIAYblne
juSU8gE9YiCkLX3M0ed3DJHBePvegtF8KPDTHuCbc9BwOT3AD0usd57+mpt/r+bR
7Yvmpkr7IHO7qn8hEoNSyP/PanSuT6ZyBGL3BSzFrS9RIyctFOn0sWmeOz0yXs7y
ec3tJkU1XpCYH8RjlgJEMoIrdyJ3dGLqR/+jObBOlk0fpS/II1VS3BYkgYyEYYfs
97BegHvHIlkveJZP3+rOaPvrE/UZNqMIjQx472eo2/7/JpGAtb970jUL8aCFC4gk
4NkKjX9kB194jM66juKBxys3kmskk1SX57CXTcylUewc2nUVhoS3FQLYyA6RYCZw
TE3iR4XwayovutCd8A/qPDs1N6Ycs4lUh6IuX3jSMOqWhYoCYcdWedkeIGn908Bc
Kr06ktQOlcwqHK/6DxJYOsBLAL3njxI4aQFXhKYiftrNmLDmiBqteBDBiCp9otxh
lAQg17rrdXca7ueYAc8zb+l1hsp0rMftxLxXZRrdFKKDVB7GbnA=
=dOxC
-----END PGP SIGNATURE-----

--cONQMGqZJa7jouAw--