public inbox for [email protected]
help / color / mirror / Atom feedFrom: Imseih (AWS), Sami <[email protected]>
To: [email protected] <[email protected]>
Subject: [BUG] Panic due to incorrect missingContrecPtr after promotion
Date: Tue, 22 Feb 2022 19:20:55 +0000
Message-ID: <[email protected]> (raw)
On 13.5 a wal flush PANIC is encountered after a standby is promoted.
With debugging, it was found that when a standby skips a missing continuation record on recovery, the missingContrecPtr is not invalidated after the record is skipped. Therefore, when the standby is promoted to a primary it writes an overwrite_contrecord with an LSN of the missingContrecPtr, which is now in the past. On flush time, this causes a PANIC. From what I can see, this failure scenario can only occur after a standby is promoted.
The overwrite_contrecord was introduced in 13.5 with https://git.postgresql.org/gitweb/?p=postgresql.git;a=commit;h=ff9f111bce24.
Attached is a patch and a TAP test to handle this condition. The patch ensures that an overwrite_contrecord is only created if the missingContrecPtr is ahead of the last wal record.
To reproduce:
Run the new tap test recovery/t/029_overwrite_contrecord_promotion.pl without the attached patch
2022-02-22 18:38:15.526 UTC [31138] LOG: started streaming WAL from primary at 0/2000000 on timeline 1
2022-02-22 18:38:15.535 UTC [31105] LOG: successfully skipped missing contrecord at 0/1FFC620, overwritten at 2022-02-22 18:38:15.136482+00
2022-02-22 18:38:15.535 UTC [31105] CONTEXT: WAL redo at 0/2000028 for XLOG/OVERWRITE_CONTRECORD: lsn 0/1FFC620; time 2022-02-22 18:38:15.136482+00
…
…..
2022-02-22 18:38:15.575 UTC [31103] PANIC: xlog flush request 0/201EC70 is not satisfied --- flushed only to 0/2000088
2022-02-22 18:38:15.575 UTC [31101] LOG: checkpointer process (PID 31103) was terminated by signal 6: Aborted
….
…..
With the patch, running the same tap test succeeds and a PANIC is not observed.
Thanks
Sami Imseih
Amazon Web Services
Attachments:
[application/octet-stream] 0001-Fix-missing-continuation-record-after-standby-promot.patch (6.6K, ../[email protected]/3-0001-Fix-missing-continuation-record-after-standby-promot.patch)
download | inline diff:
From e7c2e425eba642c8e9c379c5fecc4bd5caf28997 Mon Sep 17 00:00:00 2001
From: "Sami Imseih (AWS)" <[email protected]>
Date: Tue, 22 Feb 2022 19:09:36 +0000
Subject: [PATCH 1/1] Fix "missing continuation record" after standby promotion
Fix a condition where a recently promoted standby attempts to
write an OVERWRITE_RECORD with an LSN of the previously read
aborted record.
---
src/backend/access/transam/xlog.c | 16 ++-
...inuation-record-after-standby-promot.patch | 134 ++++++++++++++++++
2 files changed, 149 insertions(+), 1 deletion(-)
create mode 100644 src/test/recovery/0001-Fix-missing-continuation-record-after-standby-promot.patch
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 0d2bd7a357..56c2fdec96 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -5423,11 +5423,25 @@ StartupXLOG(void)
* made it through and start writing after the portion that persisted.
* (It's critical to first write an OVERWRITE_CONTRECORD message, which
* we'll do as soon as we're open for writing new WAL.)
+ *
+ * If the last wal record is ahead of the missing contrecord, this is
+ * a recently promoted primary and we should not write an overwrite
+ * contrecord.
*/
if (!XLogRecPtrIsInvalid(missingContrecPtr))
{
Assert(!XLogRecPtrIsInvalid(abortedRecPtr));
- EndOfLog = missingContrecPtr;
+ if (endOfRecoveryInfo->lastRec < missingContrecPtr)
+ {
+ elog(DEBUG2, "setting end of wal to missing continuation record %X/%X",
+ LSN_FORMAT_ARGS(missingContrecPtr));
+ EndOfLog = missingContrecPtr;
+ }
+ else
+ {
+ elog(DEBUG2, "resetting aborted record");
+ abortedRecPtr = InvalidXLogRecPtr;
+ }
}
/*
diff --git a/src/test/recovery/0001-Fix-missing-continuation-record-after-standby-promot.patch b/src/test/recovery/0001-Fix-missing-continuation-record-after-standby-promot.patch
new file mode 100644
index 0000000000..40d922801b
--- /dev/null
+++ b/src/test/recovery/0001-Fix-missing-continuation-record-after-standby-promot.patch
@@ -0,0 +1,134 @@
+From cb344355facb3e6f793013b0b9998683277f3bd8 Mon Sep 17 00:00:00 2001
+From: "Sami Imseih (AWS)" <[email protected]>
+Date: Tue, 22 Feb 2022 18:59:44 +0000
+Subject: [PATCH 1/1] Fix "missing continuation record" after standby
+ promotion.
+
+Fix a condition where a recently promoted standby attempts to
+write an OVERWRITE_RECORD with an LSN of the previously read
+aborted record.
+---
+ .../t/029_overwrite_contrecord_promotion.pl | 111 ++++++++++++++++++
+ 1 file changed, 111 insertions(+)
+ create mode 100644 src/test/recovery/t/029_overwrite_contrecord_promotion.pl
+
+diff --git a/src/test/recovery/t/029_overwrite_contrecord_promotion.pl b/src/test/recovery/t/029_overwrite_contrecord_promotion.pl
+new file mode 100644
+index 0000000000..ea4ebb32c0
+--- /dev/null
++++ b/src/test/recovery/t/029_overwrite_contrecord_promotion.pl
+@@ -0,0 +1,111 @@
++# Copyright (c) 2021-2022, PostgreSQL Global Development Group
++
++# Tests for resetting the "aborted record" after a promotion.
++
++use strict;
++use warnings;
++
++use FindBin;
++use PostgreSQL::Test::Cluster;
++use PostgreSQL::Test::Utils;
++use Test::More;
++
++# Test: Create a physical replica that's missing the last WAL file,
++# then restart the primary to create a divergent WAL file and observe
++# that the replica resets the "aborted record" after a promotion.
++
++my $node = PostgreSQL::Test::Cluster->new('primary');
++$node->init(allows_streaming => 1);
++# We need these settings for stability of WAL behavior.
++$node->append_conf(
++ 'postgresql.conf', qq(
++autovacuum = off
++wal_keep_size = 1GB
++log_min_messages = DEBUG2
++));
++$node->start;
++
++$node->safe_psql('postgres', 'create table filler (a int, b text)');
++
++# Now consume all remaining room in the current WAL segment, leaving
++# space enough only for the start of a largish record.
++$node->safe_psql(
++ 'postgres', q{
++DO $$
++DECLARE
++ wal_segsize int := setting::int FROM pg_settings WHERE name = 'wal_segment_size';
++ remain int;
++ iters int := 0;
++BEGIN
++ LOOP
++ INSERT into filler
++ select g, repeat(md5(g::text), (random() * 60 + 1)::int)
++ from generate_series(1, 10) g;
++
++ remain := wal_segsize - (pg_current_wal_insert_lsn() - '0/0') % wal_segsize;
++ IF remain < 2 * setting::int from pg_settings where name = 'block_size' THEN
++ RAISE log 'exiting after % iterations, % bytes to end of WAL segment', iters, remain;
++ EXIT;
++ END IF;
++ iters := iters + 1;
++ END LOOP;
++END
++$$;
++});
++
++my $initfile = $node->safe_psql('postgres',
++ 'SELECT pg_walfile_name(pg_current_wal_insert_lsn())');
++$node->safe_psql('postgres',
++ qq{SELECT pg_logical_emit_message(true, 'test 026', repeat('xyzxz', 123456))}
++);
++#$node->safe_psql('postgres', qq{create table foo ()});
++my $endfile = $node->safe_psql('postgres',
++ 'SELECT pg_walfile_name(pg_current_wal_insert_lsn())');
++ok($initfile ne $endfile, "$initfile differs from $endfile");
++
++# Now stop abruptly, to avoid a stop checkpoint. We can remove the tail file
++# afterwards, and on startup the large message should be overwritten with new
++# contents
++$node->stop('immediate');
++
++unlink $node->basedir . "/pgdata/pg_wal/$endfile"
++ or die "could not unlink " . $node->basedir . "/pgdata/pg_wal/$endfile: $!";
++
++# OK, create a standby at this spot.
++$node->backup_fs_cold('backup');
++my $node_standby = PostgreSQL::Test::Cluster->new('standby');
++$node_standby->init_from_backup($node, 'backup', has_streaming => 1);
++
++$node_standby->start;
++$node->start;
++
++$node->safe_psql('postgres',
++ qq{create table foo (a text); insert into foo values ('hello')});
++$node->safe_psql('postgres',
++ qq{SELECT pg_logical_emit_message(true, 'test 026', 'AABBCC')});
++
++my $until_lsn = $node->safe_psql('postgres', "SELECT pg_current_wal_lsn()");
++my $caughtup_query =
++ "SELECT '$until_lsn'::pg_lsn <= pg_last_wal_replay_lsn()";
++$node_standby->poll_query_until('postgres', $caughtup_query)
++ or die "Timed out while waiting for standby to catch up";
++
++ok($node_standby->safe_psql('postgres', 'select * from foo') eq 'hello',
++ 'standby replays past overwritten contrecord');
++
++$ENV{PGDATA} = $node_standby->data_dir;
++$ENV{PGPORT} = $node_standby->port;
++$ENV{PGGHOST} = $node_standby->host;
++system "psql -c 'select pg_promote()'";
++
++# Verify message appears in standby's log
++my $log = slurp_file($node_standby->logfile);
++like(
++ $log,
++ qr[resetting aborted record],
++ "found log line in standby");
++
++$node->stop;
++$node_standby->stop;
++
++done_testing();
+--
+2.32.0
+
--
2.32.0
view thread (4+ messages) latest in thread
reply
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: [email protected]
Cc: [email protected]
Subject: Re: [BUG] Panic due to incorrect missingContrecPtr after promotion
In-Reply-To: <[email protected]>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox