From: Michael Paquier <michael@paquier.xyz>
To: Thomas Munro <thomas.munro@gmail.com>
Cc: Noah Misch <noah@leadboat.com>
Cc: Tom Lane <tgl@sss.pgh.pa.us>
Cc: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
Cc: exclusion@gmail.com
Cc: pgsql-bugs@lists.postgresql.org
Subject: Re: BUG #17928: Standby fails to decode WAL on termination of primary
Date: Tue, 15 Aug 2023 15:11:16 +0900
Message-ID: <ZNsXBFsFsKcCbP0q@paquier.xyz> (raw)
In-Reply-To: <ZNrqTmKGnZwz9gPI@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>
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 = 'wal_block_size'
> \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));
>
> 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 code 1
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
Attachments:
[text/x-diff] 0001-Add-test-to-emulate-random-garbage-data-during-WAL-r.patch (4.1K, ../ZNsXBFsFsKcCbP0q@paquier.xyz/2-0001-Add-test-to-emulate-random-garbage-data-during-WAL-r.patch)
download | inline diff:
From 958130099bc76534031acc4d3f2e94ccbcfa5451 Mon Sep 17 00:00:00 2001
From: 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/replication/logical/message.cindex 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;
/*
* Force xid to be allocated if we're emitting a transactional message.
@@ -71,7 +72,11 @@ LogLogicalMessage(const char *prefix, const char *message, size_t size,
/* allow origin filtering */
XLogSetRecordFlags(XLOG_INCLUDE_ORIGIN);
- return XLogInsert(RM_LOGICALMSG_ID, XLOG_LOGICAL_MESSAGE);+ lsn = XLogInsert(RM_LOGICALMSG_ID, XLOG_LOGICAL_MESSAGE);++ /* Make sure that the message hits disk before leaving */+ XLogFlush(lsn);+ return lsn;
}
/*
diff --git a/src/test/recovery/t/038_wal_invalid.pl b/src/test/recovery/t/038_wal_invalid.plnew file mode 100644index 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 = minimal and some+# configuration aimed at minimizing the WAL activity of the cluster.+my $node = PostgreSQL::Test::Cluster->new('primary');+$node->init;+$node->append_conf('postgresql.conf', q[+wal_level = minimal+autovacuum = off+checkpoint_timeout = '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 = $node->safe_psql('postgres',+ q{SELECT * FROM pg_walfile_name_offset(pg_logical_emit_message(false, 'a', 'a'))});+my ($wal_segment_name, $lsn_offset) = split /\|/, $result;+$lsn_offset = 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 = $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 = -s $node->logfile;+$node->start;+$result = $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 = slurp_file($node->logfile, $log_location);+ok( $logfile =~+ qr/LOG: .* invalid magic number 0000 in WAL segment $wal_segment_name/,+ "recovery completed up to the invalid record"+);++done_testing();--
2.40.1
[application/pgp-signature] signature.asc (832B, ../ZNsXBFsFsKcCbP0q@paquier.xyz/3-signature.asc)
download
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-bugs@postgresql.org
Cc: michael@paquier.xyz, thomas.munro@gmail.com, noah@leadboat.com, tgl@sss.pgh.pa.us, 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
In-Reply-To: <ZNsXBFsFsKcCbP0q@paquier.xyz>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox