From: Michael Paquier <michael@paquier.xyz>
To: Thomas Munro <thomas.munro@gmail.com>
Cc: Sergei Kornilov <sk@zsrv.org>
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, pgsql-bugs@lists.postgresql.org, Fujii Masao <masao.fujii@oss.nttdata.com>
Subject: Re: BUG #17928: Standby fails to decode WAL on termination of primary
Date: Tue, 12 Sep 2023 10:01:21 +0900
Message-ID: <ZP+4YYrPZk0GFlc3@paquier.xyz> (raw)
In-Reply-To: <ZPaq3KwARVHWzune@paquier.xyz>
References: <ZPQdHY4WDR+2ejwq@paquier.xyz>
<222191693740067@6mha55xjikky5vne.iva.yp-c.yandex.net>
<CA+hUKG+jFN64gKVGcmfNTekqWn3cemRx99-B8DDBaDyzWnfpkw@mail.gmail.com>
<ZPVU9FwENbnO6Q++@paquier.xyz>
<CA+hUKGLcT4ttqts4ow1=ZF9c+AwU=YfovfPs=r-Y2n0G-BunFA@mail.gmail.com>
<ZPWHHj0cbcKl1x7L@paquier.xyz>
<CA+hUKG+cap7=Tnf-oRAU2jH6dVxcuygNfyL42afU6UYKaw7pTg@mail.gmail.com>
<ZPaeUimGAzhYVEn9@paquier.xyz>
<CA+hUKGJV1Ow_S86Fj25J_orojXkn4WPeARyY8-Xr88c85rJHEQ@mail.gmail.com>
<ZPaq3KwARVHWzune@paquier.xyz>
On Tue, Sep 05, 2023 at 01:13:16PM +0900, Michael Paquier wrote:
> Right. Let's wait for a bit and see if there are any comments on this
> point. With 16.0 in sight next week, I'd like to propose that we move
> on with this issue once next week's tag is pushed.
Hearing nothing, I have applied the backpatch of 0668719801 to 12~14.
Please find attached the remaining patches for all the stable
branches.
Thomas, would you prefer handling that yourself once 16.0 is tagged
with a last round of checks? Or should I? (Still need to edit the
commit message a bit..)
--
Michael
From ea7a54c827f18b56796189c0e9d36224e6a32a84 Mon Sep 17 00:00:00 2001
From: Thomas Munro <thomas.munro@gmail.com>
Date: Mon, 14 Aug 2023 17:06:42 +1200
Subject: [PATCH v6] Don't trust unvalidated xl_tot_len.
xl_tot_len comes first in a WAL record. Usually we don't trust it to be
the true length until we've validated the record header. If the record
header was split across two pages, previously we wouldn't do the
validation until after we'd already tried to allocate enough memory to
hold the record, which was bad because it might actually be garbage
bytes from a recycled WAL file, so we could try to allocate a lot of
memory. Release 15 made it worse.
Since 70b4f82a4b5, we'd at least generate an end-of-WAL condition if the
garbage 4 byte value happened to be > 1GB, but we'd still try to
allocate up to 1GB of memory bogusly otherwise. That was an
improvement, but unfortunately release 15 tries to allocate another
object before that, so you could get a FATAL error and recovery could
fail.
We can fix both variants of the problem more fundamentally using
pre-existing page-level validation, if we just re-order some logic.
The new order of operations in the split-header case defers all memory
allocation based on xl_tot_len until we've read the following page. At
that point we know that its first few bytes are not recycled data, by
checking its xlp_pageaddr, and that its xlp_rem_len agrees with
xl_tot_len on the preceding page. That is strong evidence that
xl_tot_len was truly the start of a record that was logged.
This problem was most likely to occur on a standby, because
walreceiver.c recycles WAL files without zeroing out trailing regions of
each page. We should fix that too, but that wouldn't protect us from
rare crash scenarios where the trailing zeroes don't make it to disk.
Back-patch to 15. We might decide to back-patch a variant of this
to older branches with more study, but the symptoms there (bogus large
allocation) are less severe.
Author: Thomas Munro <thomas.munro@gmail.com>
Author: Michael Paquier <michael@paquier.xyz>
Reported-by: Alexander Lakhin <exclusion@gmail.com>
Reviewed-by: Noah Misch <noah@leadboat.com> (the idea, not the code)
Reviewed-by: Michael Paquier <michael@paquier.xyz>
Reviewed-by: Sergei Kornilov <sk@zsrv.org>
Discussion: https://postgr.es/m/17928-aa92416a70ff44a2%40postgresql.org
---
src/backend/access/transam/xlogreader.c | 123 ++++---
src/test/perl/PostgreSQL/Test/Utils.pm | 43 +++
src/test/recovery/meson.build | 1 +
src/test/recovery/t/038_end_of_wal.pl | 443 ++++++++++++++++++++++++
4 files changed, 554 insertions(+), 56 deletions(-)
create mode 100644 src/test/recovery/t/038_end_of_wal.pl
diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.cindex c9f9f6e98f..58654b746c 100644--- a/src/backend/access/transam/xlogreader.c+++ b/src/backend/access/transam/xlogreader.c@@ -192,6 +192,9 @@ XLogReaderFree(XLogReaderState *state)
* XLOG_BLCKSZ, and make sure it's at least 5*Max(BLCKSZ, XLOG_BLCKSZ) to start
* with. (That is enough for all "normal" records, but very large commit or
* abort records might need more space.)
+ *+ * Note: This routine should *never* be called for xl_tot_len until the header+ * of the record has been fully validated.
*/
static bool
allocate_recordbuf(XLogReaderState *state, uint32 reclength)
@@ -201,25 +204,6 @@ allocate_recordbuf(XLogReaderState *state, uint32 reclength)
newSize += XLOG_BLCKSZ - (newSize % XLOG_BLCKSZ);
newSize = Max(newSize, 5 * Max(BLCKSZ, XLOG_BLCKSZ));
-#ifndef FRONTEND-- /*- * Note that in much unlucky circumstances, the random data read from a- * recycled segment can cause this routine to be called with a size- * causing a hard failure at allocation. For a standby, this would cause- * the instance to stop suddenly with a hard failure, preventing it to- * retry fetching WAL from one of its sources which could allow it to move- * on with replay without a manual restart. If the data comes from a past- * recycled segment and is still valid, then the allocation may succeed- * but record checks are going to fail so this would be short-lived. If- * the allocation fails because of a memory shortage, then this is not a- * hard failure either per the guarantee given by MCXT_ALLOC_NO_OOM.- */- if (!AllocSizeIsValid(newSize))- return false;--#endif-
if (state->readRecordBuf)
pfree(state->readRecordBuf);
state->readRecordBuf =
@@ -669,41 +653,26 @@ restart:
}
else
{
- /* XXX: more validation should be done here */- if (total_len < SizeOfXLogRecord)- {- report_invalid_record(state,- "invalid record length at %X/%X: expected at least %u, got %u",- LSN_FORMAT_ARGS(RecPtr),- (uint32) SizeOfXLogRecord, total_len);- goto err;- }+ /* We'll validate the header once we have the next page. */
gotheader = false;
}
/*
- * Find space to decode this record. Don't allow oversized allocation if- * the caller requested nonblocking. Otherwise, we *have* to try to- * decode the record now because the caller has nothing else to do, so- * allow an oversized record to be palloc'd if that turns out to be- * necessary.+ * Try to find space to decode this record, if we can do so without+ * calling palloc. If we can't, we'll try again below after we've+ * validated that total_len isn't garbage bytes from a recycled WAL page.
*/
decoded = XLogReadRecordAlloc(state,
total_len,
- !nonblocking /* allow_oversized */ );- if (decoded == NULL)+ false /* allow_oversized */ );+ if (decoded == NULL && nonblocking)
{
/*
- * There is no space in the decode buffer. The caller should help- * with that problem by consuming some records.+ * There is no space in the circular decode buffer, and the caller is+ * only reading ahead. The caller should consume existing records to+ * make space.
*/
- if (nonblocking)- return XLREAD_WOULDBLOCK;-- /* We failed to allocate memory for an oversized record. */- report_invalid_record(state,- "out of memory while trying to decode a record of length %u", total_len);- goto err;+ return XLREAD_WOULDBLOCK;
}
len = XLOG_BLCKSZ - RecPtr % XLOG_BLCKSZ;
@@ -718,16 +687,11 @@ restart:
assembled = true;
/*
- * Enlarge readRecordBuf as needed.+ * We always have space for a couple of pages, enough to validate a+ * boundary-spanning record header.
*/
- if (total_len > state->readRecordBufSize &&- !allocate_recordbuf(state, total_len))- {- /* We treat this as a "bogus data" condition */- report_invalid_record(state, "record length %u at %X/%X too long",- total_len, LSN_FORMAT_ARGS(RecPtr));- goto err;- }+ Assert(state->readRecordBufSize >= XLOG_BLCKSZ * 2);+ Assert(state->readRecordBufSize >= len);
/* Copy the first fragment of the record from the first page. */
memcpy(state->readRecordBuf,
@@ -824,8 +788,35 @@ restart:
goto err;
gotheader = true;
}
- } while (gotlen < total_len);+ /*+ * We might need a bigger buffer. We have validated the record+ * header, in the case that it split over a page boundary. We've+ * also cross-checked total_len against xlp_rem_len on the second+ * page, and verified xlp_pageaddr on both.+ */+ if (total_len > state->readRecordBufSize)+ {+ char save_copy[XLOG_BLCKSZ * 2];++ /*+ * Save and restore the data we already had. It can't be more+ * than two pages.+ */+ Assert(gotlen <= lengthof(save_copy));+ Assert(gotlen <= state->readRecordBufSize);+ memcpy(save_copy, state->readRecordBuf, gotlen);+ if (!allocate_recordbuf(state, total_len))+ {+ /* We treat this as a "bogus data" condition */+ report_invalid_record(state, "record length %u at %X/%X too long",+ total_len, LSN_FORMAT_ARGS(RecPtr));+ goto err;+ }+ memcpy(state->readRecordBuf, save_copy, gotlen);+ buffer = state->readRecordBuf + gotlen;+ }+ } while (gotlen < total_len);
Assert(gotheader);
record = (XLogRecord *) state->readRecordBuf;
@@ -867,6 +858,28 @@ restart:
state->NextRecPtr -= XLogSegmentOffset(state->NextRecPtr, state->segcxt.ws_segsize);
}
+ /*+ * If we got here without a DecodedXLogRecord, it means we needed to+ * validate total_len before trusting it, but by now now we've done that.+ */+ if (decoded == NULL)+ {+ Assert(!nonblocking);+ decoded = XLogReadRecordAlloc(state,+ total_len,+ true /* allow_oversized */ );+ if (decoded == NULL)+ {+ /*+ * We failed to allocate memory for an oversized record. As+ * above, we currently treat this as a "bogus data" condition.+ */+ report_invalid_record(state,+ "out of memory while trying to decode a record of length %u", total_len);+ goto err;+ }+ }+
if (DecodeXLogRecord(state, decoded, record, RecPtr, &errormsg))
{
/* Record the location of the next record. */
@@ -895,8 +908,6 @@ restart:
state->decode_queue_head = decoded;
return XLREAD_SUCCESS;
}
- else- return XLREAD_FAIL;
err:
if (assembled)
diff --git a/src/test/perl/PostgreSQL/Test/Utils.pm b/src/test/perl/PostgreSQL/Test/Utils.pmindex 617caa022f..9de34a2260 100644--- a/src/test/perl/PostgreSQL/Test/Utils.pm+++ b/src/test/perl/PostgreSQL/Test/Utils.pm@@ -71,6 +71,7 @@ our @EXPORT = qw(
chmod_recursive
check_pg_config
dir_symlink
+ scan_server_header
system_or_bail
system_log
run_log
@@ -702,6 +703,48 @@ sub chmod_recursive
=pod
+=item scan_server_header(header_path, regexp)++Returns an array that stores all the matches of the given regular expression+within the PostgreSQL installation's C<header_path>. This can be used to+retrieve specific value patterns from the installation's header files.++=cut++sub scan_server_header+{+ my ($header_path, $regexp) = @_;++ my ($stdout, $stderr);+ my $result = IPC::Run::run [ 'pg_config', '--includedir-server' ], '>',+ \$stdout, '2>', \$stderr+ or die "could not execute pg_config";+ chomp($stdout);+ $stdout =~ s/\r$//;++ open my $header_h, '<', "$stdout/$header_path" or die "$!";++ my @match = undef;+ while (<$header_h>)+ {+ my $line = $_;++ if ($line =~ /^$regexp/)+ {+ # Found match, so store all the results.+ @match = @{^CAPTURE};+ last;+ }+ }++ close $header_h;+ die "could not find match in header $header_path\n"+ unless @match;+ return @match;+}++=pod+
=item check_pg_config(regexp)
Return the number of matches of the given regular expression
diff --git a/src/test/recovery/meson.build b/src/test/recovery/meson.buildindex e7328e4894..10407668d4 100644--- a/src/test/recovery/meson.build+++ b/src/test/recovery/meson.build@@ -43,6 +43,7 @@ tests += {
't/035_standby_logical_decoding.pl',
't/036_truncated_dropped.pl',
't/037_invalid_database.pl',
+ 't/038_end_of_wal.pl',
],
},
}
diff --git a/src/test/recovery/t/038_end_of_wal.pl b/src/test/recovery/t/038_end_of_wal.plnew file mode 100644index 0000000000..aa5eec7c03--- /dev/null+++ b/src/test/recovery/t/038_end_of_wal.pl@@ -0,0 +1,443 @@+# Copyright (c) 2023, PostgreSQL Global Development Group+#+# Test detecting end of WAL replay. This test suite generates fake+# WAL records able to trigger various failure scenarios at replay.++use strict;+use warnings;+use PostgreSQL::Test::Cluster;+use PostgreSQL::Test::Utils;+use Test::More;+use Fcntl qw(SEEK_SET);++use integer; # causes / operator to use integer math++# Header size of record header.+my $RECORD_HEADER_SIZE = 24;++# Fields retrieved from code headers.+my @scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLOG_PAGE_MAGIC\s+(\w+)');+my $XLP_PAGE_MAGIC = hex($scan_result[0]);+@scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLP_FIRST_IS_CONTRECORD\s+(\w+)');+my $XLP_FIRST_IS_CONTRECORD = hex($scan_result[0]);++# Values queried from the server+my $WAL_SEGMENT_SIZE;+my $WAL_BLOCK_SIZE;+my $TLI;++# Build path of a WAL segment.+sub wal_segment_path+{+ my $node = shift;+ my $tli = shift;+ my $segment = shift;+ my $wal_path =+ sprintf("%s/pg_wal/%08X%08X%08X", $node->data_dir, $tli, 0, $segment);+ return $wal_path;+}++# Calculate from a LSN (in bytes) its segment number and its offset.+sub lsn_to_segment_and_offset+{+ my $lsn = shift;+ return ($lsn / $WAL_SEGMENT_SIZE, $lsn % $WAL_SEGMENT_SIZE);+}++# Write some arbitrary data in WAL for the given segment at offset.+# This should be called while the cluster is offline.+sub write_wal+{+ my $node = shift;+ my $tli = shift;+ my $lsn = shift;+ my $data = shift;++ my ($segment, $offset) = lsn_to_segment_and_offset($lsn);+ my $path = wal_segment_path($node, $tli, $segment);++ open my $fh, "+<:raw", $path or die;+ seek($fh, $offset, SEEK_SET) or die;+ print $fh $data;+ close $fh;+}++# Emit a WAL record of arbitrary size. Returns the end LSN of the+# record inserted, in bytes.+sub emit_message+{+ my $node = shift;+ my $size = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT pg_logical_emit_message(true, '', repeat('a', $size)) - '0/0'"+ ));+}++# Get the current insert LSN of a node, in bytes.+sub get_insert_lsn+{+ my $node = shift;+ return int(+ $node->safe_psql(+ 'postgres', "SELECT pg_current_wal_insert_lsn() - '0/0'"));+}++# Get GUC value, converted to an int.+sub get_int_setting+{+ my $node = shift;+ my $name = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT setting FROM pg_settings WHERE name = '$name'"));+}++sub start_of_page+{+ my $lsn = shift;+ return $lsn & ~($WAL_BLOCK_SIZE - 1);+}++sub start_of_next_page+{+ my $lsn = shift;+ return start_of_page($lsn) + $WAL_BLOCK_SIZE;+}++# Build a fake WAL record header based on the data given by the caller.+# This needs to follow the format of the C structure XLogRecord. To+# be inserted with write_wal().+sub build_record_header+{+ my $xl_tot_len = shift;+ my $xl_xid = shift || 0;+ my $xl_prev = shift || 0;+ my $xl_info = shift || 0;+ my $xl_rmid = shift || 0;+ my $xl_crc = shift || 0;++ # This needs to follow the structure XLogRecord:+ # I for xl_tot_len+ # I for xl_xid+ # Q for xl_prev+ # C for xl_info+ # C for xl_rmid+ # BB for two bytes of padding+ # I for xl_crc+ return pack("IIQCCBBI",+ $xl_tot_len, $xl_xid, $xl_prev, $xl_info, $xl_rmid, 0, 0, $xl_crc);+}++# Build a fake WAL page header, based on the data given by the caller+# This needs to follow the format of the C structure XLogPageHeaderData.+# To be inserted with write_wal().+sub build_page_header+{+ my $xlp_magic = shift;+ my $xlp_info = shift || 0;+ my $xlp_tli = shift || 0;+ my $xlp_pageaddr = shift || 0;+ my $xlp_rem_len = shift || 0;++ # This needs to follow the structure XLogPageHeaderData:+ # S for xlp_magic+ # S for xlp_info+ # I for xlp_tli+ # Q for xlp_pageaddr+ # I for xlp_rem_len+ return pack("SSIQI",+ $xlp_magic, $xlp_info, $xlp_tli, $xlp_pageaddr, $xlp_rem_len);+}++# Make sure we are far away enough from the end of a page that we could insert+# a couple of small records. This inserts a few records of a fixed size, until+# the threshold gets close enough to the end of the WAL page inserting records+# to.+sub advance_out_of_record_splitting_zone+{+ my $node = shift;++ my $page_threshold = $WAL_BLOCK_SIZE / 4;+ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ while ($page_offset >= $WAL_BLOCK_SIZE - $page_threshold)+ {+ $end_lsn = emit_message($node, $page_threshold);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }+ return $end_lsn;+}++# Advance so close to the end of a page that an XLogRecordHeader would not+# fit on it.+sub advance_to_record_splitting_zone+{+ my $node = shift;++ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Get fairly close to the end of a page in big steps+ while ($page_offset <= $WAL_BLOCK_SIZE - 512)+ {+ $end_lsn = emit_message($node, $WAL_BLOCK_SIZE - $page_offset - 256);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }++ # Calibrate our message size so that we can get closer 8 bytes at+ # a time.+ my $message_size = $WAL_BLOCK_SIZE - 80;+ while ($page_offset <= $WAL_BLOCK_SIZE - $RECORD_HEADER_SIZE)+ {+ $end_lsn = emit_message($node, $message_size);++ my $old_offset = $page_offset;+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Adjust the message size until it causes 8 bytes changes in+ # offset, enough to be able to split a record header.+ my $delta = $page_offset - $old_offset;+ if ($delta > 8)+ {+ $message_size -= 8;+ }+ elsif ($delta <= 0)+ {+ $message_size += 8;+ }+ }+ return $end_lsn;+}++# Setup a new node. The configuration chosen here minimizes the number+# of arbitrary records that could get generated in a cluster. Enlarging+# checkpoint_timeout avoids noise with checkpoint activity. wal_level+# set to "minimal" avoids random standby snapshot records. Autovacuum+# could also trigger randomly, generating random WAL activity of its own.+my $node = PostgreSQL::Test::Cluster->new("node");+$node->init;+$node->append_conf(+ 'postgresql.conf',+ q[wal_level = minimal+ autovacuum = off+ checkpoint_timeout = '30min'+]);+$node->start;+$node->safe_psql('postgres', "CREATE TABLE t AS SELECT 42");++$WAL_SEGMENT_SIZE = get_int_setting($node, 'wal_segment_size');+$WAL_BLOCK_SIZE = get_int_setting($node, 'wal_block_size');+$TLI = $node->safe_psql('postgres',+ "SELECT timeline_id FROM pg_control_checkpoint();");++my $end_lsn;+my $prev_lsn;++###########################################################################+note "Single-page end-of-WAL detection";+###########################################################################++# xl_tot_len is 0 (a common case, we hit trailing zeroes).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+my $log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: expected at least 24, got 0", $log_size+ ),+ "xl_tot_len zero");++# xl_tot_len is < 24 (presumably recycled garbage).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn, build_record_header(23));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: expected at least 24, got 23",+ $log_size),+ "xl_tot_len short");++# Need more pages, but xl_prev check fails first.+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "record with incorrect prev-link 0/DEADBEEF at .*", $log_size),+ "xl_prev bad");++# xl_crc check fails.+advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 10);+$node->stop('immediate');+# Corrupt a byte in that record, breaking its CRC.+write_wal($node, $TLI, $end_lsn - 8, '!');+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "incorrect resource manager data checksum in record at .*", $log_size+ ),+ "xl_crc bad");+++###########################################################################+note "Multi-page end-of-WAL detection, header is not split";+###########################################################################++# This series of tests requires a valid xl_prev set in the record header+# written to WAL.++# Good xl_prev, we hit zero page next (zero magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 .* LSN .*", $log_size),+ "xlp_magic zero");++# Good xl_prev, we hit garbage page next (bad magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(0xcafe, 0, 1, 0));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number CAFE .* LSN .*", $log_size),+ "xlp_magic bad");++# Good xl_prev, we hit typical recycled page (good xlp_magic, bad+# xlp_pageaddr).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD in .*, LSN .*,", $log_size),+ "xlp_pageaddr bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but bogus xlp_info.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, 0x1234, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid info bits 1234 in .*, LSN .*,", $log_size),+ "xlp_info bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but xlp_info doesn't mention+# continuation record.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("there is no contrecord flag at .*", $log_size),+ "xlp_info lacks XLP_FIRST_IS_CONTRECORD");++# Good xl_prev, xlp_magic, xlp_pageaddr, xlp_info but xlp_rem_len doesn't add+# up.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 .* at .*", $log_size),+ "xlp_rem_len bad");+++###########################################################################+note "Multi-page, but header is split, so page checks are done first";+###########################################################################++# xlp_prev is bad and xl_tot_len is too big, but we'll check xlp_magic first.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 .* LSN .*", $log_size),+ "xlp_magic zero (split record header)");++# And we'll also check xlp_pageaddr before any header checks.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD in .*, LSN .*,", $log_size),+ "xlp_pageaddr bad (split record header)");++# We'll also discover that xlp_rem_len doesn't add up before any+# header checks,+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 .* at .*", $log_size),+ "xlp_rem_len bad (split record header)");++done_testing();
--
2.40.1
From 8a75b763a8c477d1cb62a7e52bb825894a3bcdce Mon Sep 17 00:00:00 2001
From: Thomas Munro <thomas.munro@gmail.com>
Date: Mon, 14 Aug 2023 17:06:42 +1200
Subject: [PATCH v6] Don't trust unvalidated xl_tot_len.
xl_tot_len comes first in a WAL record. Usually we don't trust it to be
the true length until we've validated the record header. If the record
header was split across two pages, previously we wouldn't do the
validation until after we'd already tried to allocate enough memory to
hold the record, which was bad because it might actually be garbage
bytes from a recycled WAL file, so we could try to allocate a lot of
memory. Release 15 made it worse.
Since 70b4f82a4b5, we'd at least generate an end-of-WAL condition if the
garbage 4 byte value happened to be > 1GB, but we'd still try to
allocate up to 1GB of memory bogusly otherwise. That was an
improvement, but unfortunately release 15 tries to allocate another
object before that, so you could get a FATAL error and recovery could
fail.
We can fix both variants of the problem more fundamentally using
pre-existing page-level validation, if we just re-order some logic.
The new order of operations in the split-header case defers all memory
allocation based on xl_tot_len until we've read the following page. At
that point we know that its first few bytes are not recycled data, by
checking its xlp_pageaddr, and that its xlp_rem_len agrees with
xl_tot_len on the preceding page. That is strong evidence that
xl_tot_len was truly the start of a record that was logged.
This problem was most likely to occur on a standby, because
walreceiver.c recycles WAL files without zeroing out trailing regions of
each page. We should fix that too, but that wouldn't protect us from
rare crash scenarios where the trailing zeroes don't make it to disk.
Back-patch to 15. We might decide to back-patch a variant of this
to older branches with more study, but the symptoms there (bogus large
allocation) are less severe.
Author: Thomas Munro <thomas.munro@gmail.com>
Author: Michael Paquier <michael@paquier.xyz>
Reported-by: Alexander Lakhin <exclusion@gmail.com>
Reviewed-by: Noah Misch <noah@leadboat.com> (the idea, not the code)
Reviewed-by: Michael Paquier <michael@paquier.xyz>
Reviewed-by: Sergei Kornilov <sk@zsrv.org>
Discussion: https://postgr.es/m/17928-aa92416a70ff44a2%40postgresql.org
---
src/backend/access/transam/xlogreader.c | 123 ++++---
src/test/perl/PostgreSQL/Test/Utils.pm | 43 +++
src/test/recovery/t/038_end_of_wal.pl | 443 ++++++++++++++++++++++++
3 files changed, 553 insertions(+), 56 deletions(-)
create mode 100644 src/test/recovery/t/038_end_of_wal.pl
diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.cindex 03fad82bc1..4b48abfa05 100644--- a/src/backend/access/transam/xlogreader.c+++ b/src/backend/access/transam/xlogreader.c@@ -192,6 +192,9 @@ XLogReaderFree(XLogReaderState *state)
* XLOG_BLCKSZ, and make sure it's at least 5*Max(BLCKSZ, XLOG_BLCKSZ) to start
* with. (That is enough for all "normal" records, but very large commit or
* abort records might need more space.)
+ *+ * Note: This routine should *never* be called for xl_tot_len until the header+ * of the record has been fully validated.
*/
static bool
allocate_recordbuf(XLogReaderState *state, uint32 reclength)
@@ -201,25 +204,6 @@ allocate_recordbuf(XLogReaderState *state, uint32 reclength)
newSize += XLOG_BLCKSZ - (newSize % XLOG_BLCKSZ);
newSize = Max(newSize, 5 * Max(BLCKSZ, XLOG_BLCKSZ));
-#ifndef FRONTEND-- /*- * Note that in much unlucky circumstances, the random data read from a- * recycled segment can cause this routine to be called with a size- * causing a hard failure at allocation. For a standby, this would cause- * the instance to stop suddenly with a hard failure, preventing it to- * retry fetching WAL from one of its sources which could allow it to move- * on with replay without a manual restart. If the data comes from a past- * recycled segment and is still valid, then the allocation may succeed- * but record checks are going to fail so this would be short-lived. If- * the allocation fails because of a memory shortage, then this is not a- * hard failure either per the guarantee given by MCXT_ALLOC_NO_OOM.- */- if (!AllocSizeIsValid(newSize))- return false;--#endif-
if (state->readRecordBuf)
pfree(state->readRecordBuf);
state->readRecordBuf =
@@ -667,41 +651,26 @@ restart:
}
else
{
- /* XXX: more validation should be done here */- if (total_len < SizeOfXLogRecord)- {- report_invalid_record(state,- "invalid record length at %X/%X: wanted %u, got %u",- LSN_FORMAT_ARGS(RecPtr),- (uint32) SizeOfXLogRecord, total_len);- goto err;- }+ /* We'll validate the header once we have the next page. */
gotheader = false;
}
/*
- * Find space to decode this record. Don't allow oversized allocation if- * the caller requested nonblocking. Otherwise, we *have* to try to- * decode the record now because the caller has nothing else to do, so- * allow an oversized record to be palloc'd if that turns out to be- * necessary.+ * Try to find space to decode this record, if we can do so without+ * calling palloc. If we can't, we'll try again below after we've+ * validated that total_len isn't garbage bytes from a recycled WAL page.
*/
decoded = XLogReadRecordAlloc(state,
total_len,
- !nonblocking /* allow_oversized */ );- if (decoded == NULL)+ false /* allow_oversized */ );+ if (decoded == NULL && nonblocking)
{
/*
- * There is no space in the decode buffer. The caller should help- * with that problem by consuming some records.+ * There is no space in the circular decode buffer, and the caller is+ * only reading ahead. The caller should consume existing records to+ * make space.
*/
- if (nonblocking)- return XLREAD_WOULDBLOCK;-- /* We failed to allocate memory for an oversized record. */- report_invalid_record(state,- "out of memory while trying to decode a record of length %u", total_len);- goto err;+ return XLREAD_WOULDBLOCK;
}
len = XLOG_BLCKSZ - RecPtr % XLOG_BLCKSZ;
@@ -716,16 +685,11 @@ restart:
assembled = true;
/*
- * Enlarge readRecordBuf as needed.+ * We always have space for a couple of pages, enough to validate a+ * boundary-spanning record header.
*/
- if (total_len > state->readRecordBufSize &&- !allocate_recordbuf(state, total_len))- {- /* We treat this as a "bogus data" condition */- report_invalid_record(state, "record length %u at %X/%X too long",- total_len, LSN_FORMAT_ARGS(RecPtr));- goto err;- }+ Assert(state->readRecordBufSize >= XLOG_BLCKSZ * 2);+ Assert(state->readRecordBufSize >= len);
/* Copy the first fragment of the record from the first page. */
memcpy(state->readRecordBuf,
@@ -822,8 +786,35 @@ restart:
goto err;
gotheader = true;
}
- } while (gotlen < total_len);+ /*+ * We might need a bigger buffer. We have validated the record+ * header, in the case that it split over a page boundary. We've+ * also cross-checked total_len against xlp_rem_len on the second+ * page, and verified xlp_pageaddr on both.+ */+ if (total_len > state->readRecordBufSize)+ {+ char save_copy[XLOG_BLCKSZ * 2];++ /*+ * Save and restore the data we already had. It can't be more+ * than two pages.+ */+ Assert(gotlen <= lengthof(save_copy));+ Assert(gotlen <= state->readRecordBufSize);+ memcpy(save_copy, state->readRecordBuf, gotlen);+ if (!allocate_recordbuf(state, total_len))+ {+ /* We treat this as a "bogus data" condition */+ report_invalid_record(state, "record length %u at %X/%X too long",+ total_len, LSN_FORMAT_ARGS(RecPtr));+ goto err;+ }+ memcpy(state->readRecordBuf, save_copy, gotlen);+ buffer = state->readRecordBuf + gotlen;+ }+ } while (gotlen < total_len);
Assert(gotheader);
record = (XLogRecord *) state->readRecordBuf;
@@ -865,6 +856,28 @@ restart:
state->NextRecPtr -= XLogSegmentOffset(state->NextRecPtr, state->segcxt.ws_segsize);
}
+ /*+ * If we got here without a DecodedXLogRecord, it means we needed to+ * validate total_len before trusting it, but by now now we've done that.+ */+ if (decoded == NULL)+ {+ Assert(!nonblocking);+ decoded = XLogReadRecordAlloc(state,+ total_len,+ true /* allow_oversized */ );+ if (decoded == NULL)+ {+ /*+ * We failed to allocate memory for an oversized record. As+ * above, we currently treat this as a "bogus data" condition.+ */+ report_invalid_record(state,+ "out of memory while trying to decode a record of length %u", total_len);+ goto err;+ }+ }+
if (DecodeXLogRecord(state, decoded, record, RecPtr, &errormsg))
{
/* Record the location of the next record. */
@@ -893,8 +906,6 @@ restart:
state->decode_queue_head = decoded;
return XLREAD_SUCCESS;
}
- else- return XLREAD_FAIL;
err:
if (assembled)
diff --git a/src/test/perl/PostgreSQL/Test/Utils.pm b/src/test/perl/PostgreSQL/Test/Utils.pmindex 4e18730dd0..4fd2e48ca9 100644--- a/src/test/perl/PostgreSQL/Test/Utils.pm+++ b/src/test/perl/PostgreSQL/Test/Utils.pm@@ -69,6 +69,7 @@ our @EXPORT = qw(
chmod_recursive
check_pg_config
dir_symlink
+ scan_server_header
system_or_bail
system_log
run_log
@@ -672,6 +673,48 @@ sub chmod_recursive
=pod
+=item scan_server_header(header_path, regexp)++Returns an array that stores all the matches of the given regular expression+within the PostgreSQL installation's C<header_path>. This can be used to+retrieve specific value patterns from the installation's header files.++=cut++sub scan_server_header+{+ my ($header_path, $regexp) = @_;++ my ($stdout, $stderr);+ my $result = IPC::Run::run [ 'pg_config', '--includedir-server' ], '>',+ \$stdout, '2>', \$stderr+ or die "could not execute pg_config";+ chomp($stdout);+ $stdout =~ s/\r$//;++ open my $header_h, '<', "$stdout/$header_path" or die "$!";++ my @match = undef;+ while (<$header_h>)+ {+ my $line = $_;++ if ($line =~ /^$regexp/)+ {+ # Found match, so store all the results.+ @match = @{^CAPTURE};+ last;+ }+ }++ close $header_h;+ die "could not find match in header $header_path\n"+ unless @match;+ return @match;+}++=pod+
=item check_pg_config(regexp)
Return the number of matches of the given regular expression
diff --git a/src/test/recovery/t/038_end_of_wal.pl b/src/test/recovery/t/038_end_of_wal.plnew file mode 100644index 0000000000..779a195a7d--- /dev/null+++ b/src/test/recovery/t/038_end_of_wal.pl@@ -0,0 +1,443 @@+# Copyright (c) 2023, PostgreSQL Global Development Group+#+# Test detecting end of WAL replay. This test suite generates fake+# WAL records able to trigger various failure scenarios at replay.++use strict;+use warnings;+use PostgreSQL::Test::Cluster;+use PostgreSQL::Test::Utils;+use Test::More;+use Fcntl qw(SEEK_SET);++use integer; # causes / operator to use integer math++# Header size of record header.+my $RECORD_HEADER_SIZE = 24;++# Fields retrieved from code headers.+my @scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLOG_PAGE_MAGIC\s+(\w+)');+my $XLP_PAGE_MAGIC = hex($scan_result[0]);+@scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLP_FIRST_IS_CONTRECORD\s+(\w+)');+my $XLP_FIRST_IS_CONTRECORD = hex($scan_result[0]);++# Values queried from the server+my $WAL_SEGMENT_SIZE;+my $WAL_BLOCK_SIZE;+my $TLI;++# Build path of a WAL segment.+sub wal_segment_path+{+ my $node = shift;+ my $tli = shift;+ my $segment = shift;+ my $wal_path =+ sprintf("%s/pg_wal/%08X%08X%08X", $node->data_dir, $tli, 0, $segment);+ return $wal_path;+}++# Calculate from a LSN (in bytes) its segment number and its offset.+sub lsn_to_segment_and_offset+{+ my $lsn = shift;+ return ($lsn / $WAL_SEGMENT_SIZE, $lsn % $WAL_SEGMENT_SIZE);+}++# Write some arbitrary data in WAL for the given segment at offset.+# This should be called while the cluster is offline.+sub write_wal+{+ my $node = shift;+ my $tli = shift;+ my $lsn = shift;+ my $data = shift;++ my ($segment, $offset) = lsn_to_segment_and_offset($lsn);+ my $path = wal_segment_path($node, $tli, $segment);++ open my $fh, "+<:raw", $path or die;+ seek($fh, $offset, SEEK_SET) or die;+ print $fh $data;+ close $fh;+}++# Emit a WAL record of arbitrary size. Returns the end LSN of the+# record inserted, in bytes.+sub emit_message+{+ my $node = shift;+ my $size = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT pg_logical_emit_message(true, '', repeat('a', $size)) - '0/0'"+ ));+}++# Get the current insert LSN of a node, in bytes.+sub get_insert_lsn+{+ my $node = shift;+ return int(+ $node->safe_psql(+ 'postgres', "SELECT pg_current_wal_insert_lsn() - '0/0'"));+}++# Get GUC value, converted to an int.+sub get_int_setting+{+ my $node = shift;+ my $name = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT setting FROM pg_settings WHERE name = '$name'"));+}++sub start_of_page+{+ my $lsn = shift;+ return $lsn & ~($WAL_BLOCK_SIZE - 1);+}++sub start_of_next_page+{+ my $lsn = shift;+ return start_of_page($lsn) + $WAL_BLOCK_SIZE;+}++# Build a fake WAL record header based on the data given by the caller.+# This needs to follow the format of the C structure XLogRecord. To+# be inserted with write_wal().+sub build_record_header+{+ my $xl_tot_len = shift;+ my $xl_xid = shift || 0;+ my $xl_prev = shift || 0;+ my $xl_info = shift || 0;+ my $xl_rmid = shift || 0;+ my $xl_crc = shift || 0;++ # This needs to follow the structure XLogRecord:+ # I for xl_tot_len+ # I for xl_xid+ # Q for xl_prev+ # C for xl_info+ # C for xl_rmid+ # BB for two bytes of padding+ # I for xl_crc+ return pack("IIQCCBBI",+ $xl_tot_len, $xl_xid, $xl_prev, $xl_info, $xl_rmid, 0, 0, $xl_crc);+}++# Build a fake WAL page header, based on the data given by the caller+# This needs to follow the format of the C structure XLogPageHeaderData.+# To be inserted with write_wal().+sub build_page_header+{+ my $xlp_magic = shift;+ my $xlp_info = shift || 0;+ my $xlp_tli = shift || 0;+ my $xlp_pageaddr = shift || 0;+ my $xlp_rem_len = shift || 0;++ # This needs to follow the structure XLogPageHeaderData:+ # S for xlp_magic+ # S for xlp_info+ # I for xlp_tli+ # Q for xlp_pageaddr+ # I for xlp_rem_len+ return pack("SSIQI",+ $xlp_magic, $xlp_info, $xlp_tli, $xlp_pageaddr, $xlp_rem_len);+}++# Make sure we are far away enough from the end of a page that we could insert+# a couple of small records. This inserts a few records of a fixed size, until+# the threshold gets close enough to the end of the WAL page inserting records+# to.+sub advance_out_of_record_splitting_zone+{+ my $node = shift;++ my $page_threshold = $WAL_BLOCK_SIZE / 4;+ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ while ($page_offset >= $WAL_BLOCK_SIZE - $page_threshold)+ {+ $end_lsn = emit_message($node, $page_threshold);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }+ return $end_lsn;+}++# Advance so close to the end of a page that an XLogRecordHeader would not+# fit on it.+sub advance_to_record_splitting_zone+{+ my $node = shift;++ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Get fairly close to the end of a page in big steps+ while ($page_offset <= $WAL_BLOCK_SIZE - 512)+ {+ $end_lsn = emit_message($node, $WAL_BLOCK_SIZE - $page_offset - 256);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }++ # Calibrate our message size so that we can get closer 8 bytes at+ # a time.+ my $message_size = $WAL_BLOCK_SIZE - 80;+ while ($page_offset <= $WAL_BLOCK_SIZE - $RECORD_HEADER_SIZE)+ {+ $end_lsn = emit_message($node, $message_size);++ my $old_offset = $page_offset;+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Adjust the message size until it causes 8 bytes changes in+ # offset, enough to be able to split a record header.+ my $delta = $page_offset - $old_offset;+ if ($delta > 8)+ {+ $message_size -= 8;+ }+ elsif ($delta <= 0)+ {+ $message_size += 8;+ }+ }+ return $end_lsn;+}++# Setup a new node. The configuration chosen here minimizes the number+# of arbitrary records that could get generated in a cluster. Enlarging+# checkpoint_timeout avoids noise with checkpoint activity. wal_level+# set to "minimal" avoids random standby snapshot records. Autovacuum+# could also trigger randomly, generating random WAL activity of its own.+my $node = PostgreSQL::Test::Cluster->new("node");+$node->init;+$node->append_conf(+ 'postgresql.conf',+ q[wal_level = minimal+ autovacuum = off+ checkpoint_timeout = '30min'+]);+$node->start;+$node->safe_psql('postgres', "CREATE TABLE t AS SELECT 42");++$WAL_SEGMENT_SIZE = get_int_setting($node, 'wal_segment_size');+$WAL_BLOCK_SIZE = get_int_setting($node, 'wal_block_size');+$TLI = $node->safe_psql('postgres',+ "SELECT timeline_id FROM pg_control_checkpoint();");++my $end_lsn;+my $prev_lsn;++###########################################################################+note "Single-page end-of-WAL detection";+###########################################################################++# xl_tot_len is 0 (a common case, we hit trailing zeroes).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+my $log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: wanted 24, got 0", $log_size+ ),+ "xl_tot_len zero");++# xl_tot_len is < 24 (presumably recycled garbage).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn, build_record_header(23));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: wanted 24, got 23",+ $log_size),+ "xl_tot_len short");++# Need more pages, but xl_prev check fails first.+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "record with incorrect prev-link 0/DEADBEEF at .*", $log_size),+ "xl_prev bad");++# xl_crc check fails.+advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 10);+$node->stop('immediate');+# Corrupt a byte in that record, breaking its CRC.+write_wal($node, $TLI, $end_lsn - 8, '!');+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "incorrect resource manager data checksum in record at .*", $log_size+ ),+ "xl_crc bad");+++###########################################################################+note "Multi-page end-of-WAL detection, header is not split";+###########################################################################++# This series of tests requires a valid xl_prev set in the record header+# written to WAL.++# Good xl_prev, we hit zero page next (zero magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 ", $log_size),+ "xlp_magic zero");++# Good xl_prev, we hit garbage page next (bad magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(0xcafe, 0, 1, 0));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number CAFE ", $log_size),+ "xlp_magic bad");++# Good xl_prev, we hit typical recycled page (good xlp_magic, bad+# xlp_pageaddr).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD ", $log_size),+ "xlp_pageaddr bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but bogus xlp_info.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, 0x1234, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid info bits 1234 ", $log_size),+ "xlp_info bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but xlp_info doesn't mention+# continuation record.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("there is no contrecord flag at .*", $log_size),+ "xlp_info lacks XLP_FIRST_IS_CONTRECORD");++# Good xl_prev, xlp_magic, xlp_pageaddr, xlp_info but xlp_rem_len doesn't add+# up.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 .* at .*", $log_size),+ "xlp_rem_len bad");+++###########################################################################+note "Multi-page, but header is split, so page checks are done first";+###########################################################################++# xlp_prev is bad and xl_tot_len is too big, but we'll check xlp_magic first.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 ", $log_size),+ "xlp_magic zero (split record header)");++# And we'll also check xlp_pageaddr before any header checks.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD ", $log_size),+ "xlp_pageaddr bad (split record header)");++# We'll also discover that xlp_rem_len doesn't add up before any+# header checks,+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 .* at .*", $log_size),+ "xlp_rem_len bad (split record header)");++done_testing();
--
2.40.1
From a71a7beb88405e24ee9dd3bc616dc26808845bbe Mon Sep 17 00:00:00 2001
From: Thomas Munro <thomas.munro@gmail.com>
Date: Mon, 14 Aug 2023 17:06:42 +1200
Subject: [PATCH v6] Don't trust unvalidated xl_tot_len.
xl_tot_len comes first in a WAL record. Usually we don't trust it to be
the true length until we've validated the record header. If the record
header was split across two pages, previously we wouldn't do the
validation until after we'd already tried to allocate enough memory to
hold the record, which was bad because it might actually be garbage
bytes from a recycled WAL file, so we could try to allocate a lot of
memory. Release 15 made it worse.
Since 70b4f82a4b5, we'd at least generate an end-of-WAL condition if the
garbage 4 byte value happened to be > 1GB, but we'd still try to
allocate up to 1GB of memory bogusly otherwise. That was an
improvement, but unfortunately release 15 tries to allocate another
object before that, so you could get a FATAL error and recovery could
fail.
We can fix both variants of the problem more fundamentally using
pre-existing page-level validation, if we just re-order some logic.
The new order of operations in the split-header case defers all memory
allocation based on xl_tot_len until we've read the following page. At
that point we know that its first few bytes are not recycled data, by
checking its xlp_pageaddr, and that its xlp_rem_len agrees with
xl_tot_len on the preceding page. That is strong evidence that
xl_tot_len was truly the start of a record that was logged.
This problem was most likely to occur on a standby, because
walreceiver.c recycles WAL files without zeroing out trailing regions of
each page. We should fix that too, but that wouldn't protect us from
rare crash scenarios where the trailing zeroes don't make it to disk.
Back-patch to 15. We might decide to back-patch a variant of this
to older branches with more study, but the symptoms there (bogus large
allocation) are less severe.
Author: Thomas Munro <thomas.munro@gmail.com>
Author: Michael Paquier <michael@paquier.xyz>
Reported-by: Alexander Lakhin <exclusion@gmail.com>
Reviewed-by: Noah Misch <noah@leadboat.com> (the idea, not the code)
Reviewed-by: Michael Paquier <michael@paquier.xyz>
Reviewed-by: Sergei Kornilov <sk@zsrv.org>
Discussion: https://postgr.es/m/17928-aa92416a70ff44a2%40postgresql.org
---
src/backend/access/transam/xlogreader.c | 75 ++--
src/test/perl/TestLib.pm | 43 +++
src/test/recovery/t/038_end_of_wal.pl | 449 ++++++++++++++++++++++++
3 files changed, 529 insertions(+), 38 deletions(-)
create mode 100644 src/test/recovery/t/038_end_of_wal.pl
diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.cindex d797d9d508..9d74507dbe 100644--- a/src/backend/access/transam/xlogreader.c+++ b/src/backend/access/transam/xlogreader.c@@ -168,6 +168,9 @@ XLogReaderFree(XLogReaderState *state)
* XLOG_BLCKSZ, and make sure it's at least 5*Max(BLCKSZ, XLOG_BLCKSZ) to start
* with. (That is enough for all "normal" records, but very large commit or
* abort records might need more space.)
+ *+ * Note: This routine should *never* be called for xl_tot_len until the header+ * of the record has been fully validated.
*/
static bool
allocate_recordbuf(XLogReaderState *state, uint32 reclength)
@@ -177,25 +180,6 @@ allocate_recordbuf(XLogReaderState *state, uint32 reclength)
newSize += XLOG_BLCKSZ - (newSize % XLOG_BLCKSZ);
newSize = Max(newSize, 5 * Max(BLCKSZ, XLOG_BLCKSZ));
-#ifndef FRONTEND-- /*- * Note that in much unlucky circumstances, the random data read from a- * recycled segment can cause this routine to be called with a size- * causing a hard failure at allocation. For a standby, this would cause- * the instance to stop suddenly with a hard failure, preventing it to- * retry fetching WAL from one of its sources which could allow it to move- * on with replay without a manual restart. If the data comes from a past- * recycled segment and is still valid, then the allocation may succeed- * but record checks are going to fail so this would be short-lived. If- * the allocation fails because of a memory shortage, then this is not a- * hard failure either per the guarantee given by MCXT_ALLOC_NO_OOM.- */- if (!AllocSizeIsValid(newSize))- return false;--#endif-
if (state->readRecordBuf)
pfree(state->readRecordBuf);
state->readRecordBuf =
@@ -396,15 +380,7 @@ restart:
}
else
{
- /* XXX: more validation should be done here */- if (total_len < SizeOfXLogRecord)- {- report_invalid_record(state,- "invalid record length at %X/%X: wanted %u, got %u",- LSN_FORMAT_ARGS(RecPtr),- (uint32) SizeOfXLogRecord, total_len);- goto err;- }+ /* We'll validate the header once we have the next page. */
gotheader = false;
}
@@ -420,16 +396,11 @@ restart:
assembled = true;
/*
- * Enlarge readRecordBuf as needed.+ * We always have space for a couple of pages, enough to validate a+ * boundary-spanning record header.
*/
- if (total_len > state->readRecordBufSize &&- !allocate_recordbuf(state, total_len))- {- /* We treat this as a "bogus data" condition */- report_invalid_record(state, "record length %u at %X/%X too long",- total_len, LSN_FORMAT_ARGS(RecPtr));- goto err;- }+ Assert(state->readRecordBufSize >= XLOG_BLCKSZ * 2);+ Assert(state->readRecordBufSize >= len);
/* Copy the first fragment of the record from the first page. */
memcpy(state->readRecordBuf,
@@ -525,8 +496,36 @@ restart:
goto err;
gotheader = true;
}
- } while (gotlen < total_len);+ /*+ * We might need a bigger buffer. We have validated the record+ * header, in the case that it split over a page boundary. We've+ * also cross-checked total_len against xlp_rem_len on the second+ * page, and verified xlp_pageaddr on both.+ */+ Assert(gotheader);+ if (total_len > state->readRecordBufSize)+ {+ char save_copy[XLOG_BLCKSZ * 2];++ /*+ * Save and restore the data we already had. It can't be more+ * than two pages.+ */+ Assert(gotlen <= lengthof(save_copy));+ Assert(gotlen <= state->readRecordBufSize);+ memcpy(save_copy, state->readRecordBuf, gotlen);+ if (!allocate_recordbuf(state, total_len))+ {+ /* We treat this as a "bogus data" condition */+ report_invalid_record(state, "record length %u at %X/%X too long",+ total_len, LSN_FORMAT_ARGS(RecPtr));+ goto err;+ }+ memcpy(state->readRecordBuf, save_copy, gotlen);+ buffer = state->readRecordBuf + gotlen;+ }+ } while (gotlen < total_len);
Assert(gotheader);
record = (XLogRecord *) state->readRecordBuf;
diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pmindex 7860425b54..307090321f 100644--- a/src/test/perl/TestLib.pm+++ b/src/test/perl/TestLib.pm@@ -70,6 +70,7 @@ our @EXPORT = qw(
chmod_recursive
check_pg_config
dir_symlink
+ scan_server_header
system_or_bail
system_log
run_log
@@ -648,6 +649,48 @@ sub chmod_recursive
=pod
+=item scan_server_header(header_path, regexp)++Returns an array that stores all the matches of the given regular expression+within the PostgreSQL installation's C<header_path>. This can be used to+retrieve specific value patterns from the installation's header files.++=cut++sub scan_server_header+{+ my ($header_path, $regexp) = @_;++ my ($stdout, $stderr);+ my $result = IPC::Run::run [ 'pg_config', '--includedir-server' ], '>',+ \$stdout, '2>', \$stderr+ or die "could not execute pg_config";+ chomp($stdout);+ $stdout =~ s/\r$//;++ open my $header_h, '<', "$stdout/$header_path" or die "$!";++ my @match = undef;+ while (<$header_h>)+ {+ my $line = $_;++ if ($line =~ /^$regexp/)+ {+ # Found match, so store all the results.+ @match = @{^CAPTURE};+ last;+ }+ }++ close $header_h;+ die "could not find match in header $header_path\n"+ unless @match;+ return @match;+}++=pod+
=item check_pg_config(regexp)
Return the number of matches of the given regular expression
diff --git a/src/test/recovery/t/038_end_of_wal.pl b/src/test/recovery/t/038_end_of_wal.plnew file mode 100644index 0000000000..c918cc31cb--- /dev/null+++ b/src/test/recovery/t/038_end_of_wal.pl@@ -0,0 +1,449 @@+# Copyright (c) 2023, PostgreSQL Global Development Group+#+# Test detecting end of WAL replay. This test suite generates fake+# WAL records able to trigger various failure scenarios at replay.++use strict;+use warnings;+use PostgreSQL::Test::Cluster;+use PostgreSQL::Test::Utils;+use Test::More;+use Fcntl qw(SEEK_SET);++use integer; # causes / operator to use integer math++# Header size of record header.+my $RECORD_HEADER_SIZE = 24;++# Fields retrieved from code headers.+my @scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLOG_PAGE_MAGIC\s+(\w+)');+my $XLP_PAGE_MAGIC = hex($scan_result[0]);+@scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLP_FIRST_IS_CONTRECORD\s+(\w+)');+my $XLP_FIRST_IS_CONTRECORD = hex($scan_result[0]);++# Values queried from the server+my $WAL_SEGMENT_SIZE;+my $WAL_BLOCK_SIZE;+my $TLI;++# Build path of a WAL segment.+sub wal_segment_path+{+ my $node = shift;+ my $tli = shift;+ my $segment = shift;+ my $wal_path =+ sprintf("%s/pg_wal/%08X%08X%08X", $node->data_dir, $tli, 0, $segment);+ return $wal_path;+}++# Calculate from a LSN (in bytes) its segment number and its offset.+sub lsn_to_segment_and_offset+{+ my $lsn = shift;+ return ($lsn / $WAL_SEGMENT_SIZE, $lsn % $WAL_SEGMENT_SIZE);+}++# Write some arbitrary data in WAL for the given segment at offset.+# This should be called while the cluster is offline.+sub write_wal+{+ my $node = shift;+ my $tli = shift;+ my $lsn = shift;+ my $data = shift;++ my ($segment, $offset) = lsn_to_segment_and_offset($lsn);+ my $path = wal_segment_path($node, $tli, $segment);++ open my $fh, "+<:raw", $path or die;+ seek($fh, $offset, SEEK_SET) or die;+ print $fh $data;+ close $fh;+}++sub format_lsn+{+ my $lsn = shift;+ return sprintf("%X/%X", $lsn >> 32, $lsn & 0xffffffff);+}++# Emit a WAL record of arbitrary size. Returns the end LSN of the+# record inserted, in bytes.+sub emit_message+{+ my $node = shift;+ my $size = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT pg_logical_emit_message(true, '', repeat('a', $size)) - '0/0'"+ ));+}++# Get the current insert LSN of a node, in bytes.+sub get_insert_lsn+{+ my $node = shift;+ return int(+ $node->safe_psql(+ 'postgres', "SELECT pg_current_wal_insert_lsn() - '0/0'"));+}++# Get GUC value, converted to an int.+sub get_int_setting+{+ my $node = shift;+ my $name = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT setting FROM pg_settings WHERE name = '$name'"));+}++sub start_of_page+{+ my $lsn = shift;+ return $lsn & ~($WAL_BLOCK_SIZE - 1);+}++sub start_of_next_page+{+ my $lsn = shift;+ return start_of_page($lsn) + $WAL_BLOCK_SIZE;+}++# Build a fake WAL record header based on the data given by the caller.+# This needs to follow the format of the C structure XLogRecord. To+# be inserted with write_wal().+sub build_record_header+{+ my $xl_tot_len = shift;+ my $xl_xid = shift || 0;+ my $xl_prev = shift || 0;+ my $xl_info = shift || 0;+ my $xl_rmid = shift || 0;+ my $xl_crc = shift || 0;++ # This needs to follow the structure XLogRecord:+ # I for xl_tot_len+ # I for xl_xid+ # Q for xl_prev+ # C for xl_info+ # C for xl_rmid+ # BB for two bytes of padding+ # I for xl_crc+ return pack("IIQCCBBI",+ $xl_tot_len, $xl_xid, $xl_prev, $xl_info, $xl_rmid, 0, 0, $xl_crc);+}++# Build a fake WAL page header, based on the data given by the caller+# This needs to follow the format of the C structure XLogPageHeaderData.+# To be inserted with write_wal().+sub build_page_header+{+ my $xlp_magic = shift;+ my $xlp_info = shift || 0;+ my $xlp_tli = shift || 0;+ my $xlp_pageaddr = shift || 0;+ my $xlp_rem_len = shift || 0;++ # This needs to follow the structure XLogPageHeaderData:+ # S for xlp_magic+ # S for xlp_info+ # I for xlp_tli+ # Q for xlp_pageaddr+ # I for xlp_rem_len+ return pack("SSIQI",+ $xlp_magic, $xlp_info, $xlp_tli, $xlp_pageaddr, $xlp_rem_len);+}++# Make sure we are far away enough from the end of a page that we could insert+# a couple of small records. This inserts a few records of a fixed size, until+# the threshold gets close enough to the end of the WAL page inserting records+# to.+sub advance_out_of_record_splitting_zone+{+ my $node = shift;++ my $page_threshold = 2000;+ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ while ($page_offset >= $WAL_BLOCK_SIZE - $page_threshold)+ {+ $end_lsn = emit_message($node, $page_threshold);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }+ return $end_lsn;+}++# Advance so close to the end of a page that an XLogRecordHeader would not+# fit on it.+sub advance_to_record_splitting_zone+{+ my $node = shift;++ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Get fairly close to the end of a page in big steps+ while ($page_offset <= $WAL_BLOCK_SIZE - 512)+ {+ $end_lsn = emit_message($node, $WAL_BLOCK_SIZE - $page_offset - 256);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }++ # Calibrate our message size so that we can get closer 8 bytes at+ # a time.+ my $message_size = $WAL_BLOCK_SIZE - 80;+ while ($page_offset <= $WAL_BLOCK_SIZE - $RECORD_HEADER_SIZE)+ {+ $end_lsn = emit_message($node, $message_size);++ my $old_offset = $page_offset;+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Adjust the message size until it causes 8 bytes changes in+ # offset, enough to be able to split a record header.+ my $delta = $page_offset - $old_offset;+ if ($delta > 8)+ {+ $message_size -= 8;+ }+ elsif ($delta <= 0)+ {+ $message_size += 8;+ }+ }+ return $end_lsn;+}++# Setup a new node. The configuration chosen here minimizes the number+# of arbitrary records that could get generated in a cluster. Enlarging+# checkpoint_timeout avoids noise with checkpoint activity. wal_level+# set to "minimal" avoids random standby snapshot records. Autovacuum+# could also trigger randomly, generating random WAL activity of its own.+my $node = PostgreSQL::Test::Cluster->new("node");+$node->init;+$node->append_conf(+ 'postgresql.conf',+ q[wal_level = minimal+ autovacuum = off+ checkpoint_timeout = '30min'+]);+$node->start;+$node->safe_psql('postgres', "CREATE TABLE t AS SELECT 42");++$WAL_SEGMENT_SIZE = get_int_setting($node, 'wal_segment_size');+$WAL_BLOCK_SIZE = get_int_setting($node, 'wal_block_size');+$TLI = $node->safe_psql('postgres',+ "SELECT timeline_id FROM pg_control_checkpoint();");++my $end_lsn;+my $prev_lsn;++###########################################################################+note "Single-page end-of-WAL detection";+###########################################################################++# xl_tot_len is 0 (a common case, we hit trailing zeroes).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+my $log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: wanted 24, got 0", $log_size+ ),+ "xl_tot_len zero");++# xl_tot_len is < 24 (presumably recycled garbage).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn, build_record_header(23));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: wanted 24, got 23",+ $log_size),+ "xl_tot_len short");++# Need more pages, but xl_prev check fails first.+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "record with incorrect prev-link 0/DEADBEEF at .*", $log_size),+ "xl_prev bad");++# xl_crc check fails.+advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 10);+$node->stop('immediate');+# Corrupt a byte in that record, breaking its CRC.+write_wal($node, $TLI, $end_lsn - 8, '!');+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "incorrect resource manager data checksum in record at .*", $log_size+ ),+ "xl_crc bad");+++###########################################################################+note "Multi-page end-of-WAL detection, header is not split";+###########################################################################++# This series of tests requires a valid xl_prev set in the record header+# written to WAL.++# Good xl_prev, we hit zero page next (zero magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 ", $log_size),+ "xlp_magic zero");++# Good xl_prev, we hit garbage page next (bad magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(0xcafe, 0, 1, 0));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number CAFE ", $log_size),+ "xlp_magic bad");++# Good xl_prev, we hit typical recycled page (good xlp_magic, bad+# xlp_pageaddr).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD ", $log_size),+ "xlp_pageaddr bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but bogus xlp_info.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, 0x1234, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid info bits 1234 ", $log_size),+ "xlp_info bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but xlp_info doesn't mention+# continuation record.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("there is no contrecord flag at .*", $log_size),+ "xlp_info lacks XLP_FIRST_IS_CONTRECORD");++# Good xl_prev, xlp_magic, xlp_pageaddr, xlp_info but xlp_rem_len doesn't add+# up.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 .* at .*", $log_size),+ "xlp_rem_len bad");+++###########################################################################+note "Multi-page, but header is split, so page checks are done first";+###########################################################################++# xlp_prev is bad and xl_tot_len is too big, but we'll check xlp_magic first.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 ", $log_size),+ "xlp_magic zero (split record header)");++# And we'll also check xlp_pageaddr before any header checks.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD ", $log_size),+ "xlp_pageaddr bad (split record header)");++# We'll also discover that xlp_rem_len doesn't add up before any+# header checks,+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 .* at .*", $log_size),+ "xlp_rem_len bad (split record header)");++done_testing();
--
2.40.1
From 9156107d5e3ae860d332cdb3af581ba4c314844d Mon Sep 17 00:00:00 2001
From: Thomas Munro <thomas.munro@gmail.com>
Date: Mon, 14 Aug 2023 17:06:42 +1200
Subject: [PATCH v6] Don't trust unvalidated xl_tot_len.
xl_tot_len comes first in a WAL record. Usually we don't trust it to be
the true length until we've validated the record header. If the record
header was split across two pages, previously we wouldn't do the
validation until after we'd already tried to allocate enough memory to
hold the record, which was bad because it might actually be garbage
bytes from a recycled WAL file, so we could try to allocate a lot of
memory. Release 15 made it worse.
Since 70b4f82a4b5, we'd at least generate an end-of-WAL condition if the
garbage 4 byte value happened to be > 1GB, but we'd still try to
allocate up to 1GB of memory bogusly otherwise. That was an
improvement, but unfortunately release 15 tries to allocate another
object before that, so you could get a FATAL error and recovery could
fail.
We can fix both variants of the problem more fundamentally using
pre-existing page-level validation, if we just re-order some logic.
The new order of operations in the split-header case defers all memory
allocation based on xl_tot_len until we've read the following page. At
that point we know that its first few bytes are not recycled data, by
checking its xlp_pageaddr, and that its xlp_rem_len agrees with
xl_tot_len on the preceding page. That is strong evidence that
xl_tot_len was truly the start of a record that was logged.
This problem was most likely to occur on a standby, because
walreceiver.c recycles WAL files without zeroing out trailing regions of
each page. We should fix that too, but that wouldn't protect us from
rare crash scenarios where the trailing zeroes don't make it to disk.
Back-patch to 15. We might decide to back-patch a variant of this
to older branches with more study, but the symptoms there (bogus large
allocation) are less severe.
Author: Thomas Munro <thomas.munro@gmail.com>
Author: Michael Paquier <michael@paquier.xyz>
Reported-by: Alexander Lakhin <exclusion@gmail.com>
Reviewed-by: Noah Misch <noah@leadboat.com> (the idea, not the code)
Reviewed-by: Michael Paquier <michael@paquier.xyz>
Reviewed-by: Sergei Kornilov <sk@zsrv.org>
Discussion: https://postgr.es/m/17928-aa92416a70ff44a2%40postgresql.org
---
src/backend/access/transam/xlogreader.c | 77 ++--
src/test/perl/TestLib.pm | 43 +++
src/test/recovery/t/038_end_of_wal.pl | 449 ++++++++++++++++++++++++
3 files changed, 530 insertions(+), 39 deletions(-)
create mode 100644 src/test/recovery/t/038_end_of_wal.pl
diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.cindex 911bc91bc9..f2b268d236 100644--- a/src/backend/access/transam/xlogreader.c+++ b/src/backend/access/transam/xlogreader.c@@ -168,6 +168,9 @@ XLogReaderFree(XLogReaderState *state)
* XLOG_BLCKSZ, and make sure it's at least 5*Max(BLCKSZ, XLOG_BLCKSZ) to start
* with. (That is enough for all "normal" records, but very large commit or
* abort records might need more space.)
+ *+ * Note: This routine should *never* be called for xl_tot_len until the header+ * of the record has been fully validated.
*/
static bool
allocate_recordbuf(XLogReaderState *state, uint32 reclength)
@@ -177,25 +180,6 @@ allocate_recordbuf(XLogReaderState *state, uint32 reclength)
newSize += XLOG_BLCKSZ - (newSize % XLOG_BLCKSZ);
newSize = Max(newSize, 5 * Max(BLCKSZ, XLOG_BLCKSZ));
-#ifndef FRONTEND-- /*- * Note that in much unlucky circumstances, the random data read from a- * recycled segment can cause this routine to be called with a size- * causing a hard failure at allocation. For a standby, this would cause- * the instance to stop suddenly with a hard failure, preventing it to- * retry fetching WAL from one of its sources which could allow it to move- * on with replay without a manual restart. If the data comes from a past- * recycled segment and is still valid, then the allocation may succeed- * but record checks are going to fail so this would be short-lived. If- * the allocation fails because of a memory shortage, then this is not a- * hard failure either per the guarantee given by MCXT_ALLOC_NO_OOM.- */- if (!AllocSizeIsValid(newSize))- return false;--#endif-
if (state->readRecordBuf)
pfree(state->readRecordBuf);
state->readRecordBuf =
@@ -396,15 +380,7 @@ restart:
}
else
{
- /* XXX: more validation should be done here */- if (total_len < SizeOfXLogRecord)- {- report_invalid_record(state,- "invalid record length at %X/%X: wanted %u, got %u",- (uint32) (RecPtr >> 32), (uint32) RecPtr,- (uint32) SizeOfXLogRecord, total_len);- goto err;- }+ /* We'll validate the header once we have the next page. */
gotheader = false;
}
@@ -420,17 +396,11 @@ restart:
assembled = true;
/*
- * Enlarge readRecordBuf as needed.+ * We always have space for a couple of pages, enough to validate a+ * boundary-spanning record header.
*/
- if (total_len > state->readRecordBufSize &&- !allocate_recordbuf(state, total_len))- {- /* We treat this as a "bogus data" condition */- report_invalid_record(state, "record length %u at %X/%X too long",- total_len,- (uint32) (RecPtr >> 32), (uint32) RecPtr);- goto err;- }+ Assert(state->readRecordBufSize >= XLOG_BLCKSZ * 2);+ Assert(state->readRecordBufSize >= len);
/* Copy the first fragment of the record from the first page. */
memcpy(state->readRecordBuf,
@@ -525,8 +495,37 @@ restart:
goto err;
gotheader = true;
}
- } while (gotlen < total_len);+ /*+ * We might need a bigger buffer. We have validated the record+ * header, in the case that it split over a page boundary. We've+ * also cross-checked total_len against xlp_rem_len on the second+ * page, and verified xlp_pageaddr on both.+ */+ Assert(gotheader);+ if (total_len > state->readRecordBufSize)+ {+ char save_copy[XLOG_BLCKSZ * 2];++ /*+ * Save and restore the data we already had. It can't be more+ * than two pages.+ */+ Assert(gotlen <= lengthof(save_copy));+ Assert(gotlen <= state->readRecordBufSize);+ memcpy(save_copy, state->readRecordBuf, gotlen);+ if (!allocate_recordbuf(state, total_len))+ {+ /* We treat this as a "bogus data" condition */+ report_invalid_record(state, "record length %u at %X/%X too long",+ total_len,+ (uint32) (RecPtr >> 32), (uint32) RecPtr);+ goto err;+ }+ memcpy(state->readRecordBuf, save_copy, gotlen);+ buffer = state->readRecordBuf + gotlen;+ }+ } while (gotlen < total_len);
Assert(gotheader);
record = (XLogRecord *) state->readRecordBuf;
diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pmindex 7715d551b3..fee244c418 100644--- a/src/test/perl/TestLib.pm+++ b/src/test/perl/TestLib.pm@@ -66,6 +66,7 @@ our @EXPORT = qw(
check_mode_recursive
chmod_recursive
check_pg_config
+ scan_server_header
system_or_bail
system_log
run_log
@@ -632,6 +633,48 @@ sub chmod_recursive
=pod
+=item scan_server_header(header_path, regexp)++Returns an array that stores all the matches of the given regular expression+within the PostgreSQL installation's C<header_path>. This can be used to+retrieve specific value patterns from the installation's header files.++=cut++sub scan_server_header+{+ my ($header_path, $regexp) = @_;++ my ($stdout, $stderr);+ my $result = IPC::Run::run [ 'pg_config', '--includedir-server' ], '>',+ \$stdout, '2>', \$stderr+ or die "could not execute pg_config";+ chomp($stdout);+ $stdout =~ s/\r$//;++ open my $header_h, '<', "$stdout/$header_path" or die "$!";++ my @match = undef;+ while (<$header_h>)+ {+ my $line = $_;++ if ($line =~ /^$regexp/)+ {+ # Found match, so store all the results.+ @match = @{^CAPTURE};+ last;+ }+ }++ close $header_h;+ die "could not find match in header $header_path\n"+ unless @match;+ return @match;+}++=pod+
=item check_pg_config(regexp)
Return the number of matches of the given regular expression
diff --git a/src/test/recovery/t/038_end_of_wal.pl b/src/test/recovery/t/038_end_of_wal.plnew file mode 100644index 0000000000..6927d1298a--- /dev/null+++ b/src/test/recovery/t/038_end_of_wal.pl@@ -0,0 +1,449 @@+# Copyright (c) 2023, PostgreSQL Global Development Group+#+# Test detecting end of WAL replay. This test suite generates fake+# WAL records able to trigger various failure scenarios at replay.++use strict;+use warnings;+use PostgreSQL::Test::Cluster;+use PostgreSQL::Test::Utils;+use Test::More;+use Fcntl qw(SEEK_SET);++use integer; # causes / operator to use integer math++# Header size of record header.+my $RECORD_HEADER_SIZE = 24;++# Fields retrieved from code headers.+my @scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLOG_PAGE_MAGIC\s+(\w+)');+my $XLP_PAGE_MAGIC = hex($scan_result[0]);+@scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLP_FIRST_IS_CONTRECORD\s+(\w+)');+my $XLP_FIRST_IS_CONTRECORD = hex($scan_result[0]);++# Values queried from the server+my $WAL_SEGMENT_SIZE;+my $WAL_BLOCK_SIZE;+my $TLI;++# Build path of a WAL segment.+sub wal_segment_path+{+ my $node = shift;+ my $tli = shift;+ my $segment = shift;+ my $wal_path =+ sprintf("%s/pg_wal/%08X%08X%08X", $node->data_dir, $tli, 0, $segment);+ return $wal_path;+}++# Calculate from a LSN (in bytes) its segment number and its offset.+sub lsn_to_segment_and_offset+{+ my $lsn = shift;+ return ($lsn / $WAL_SEGMENT_SIZE, $lsn % $WAL_SEGMENT_SIZE);+}++# Write some arbitrary data in WAL for the given segment at offset.+# This should be called while the cluster is offline.+sub write_wal+{+ my $node = shift;+ my $tli = shift;+ my $lsn = shift;+ my $data = shift;++ my ($segment, $offset) = lsn_to_segment_and_offset($lsn);+ my $path = wal_segment_path($node, $tli, $segment);++ open my $fh, "+<:raw", $path or die;+ seek($fh, $offset, SEEK_SET) or die;+ print $fh $data;+ close $fh;+}++sub format_lsn+{+ my $lsn = shift;+ return sprintf("%X/%X", $lsn >> 32, $lsn & 0xffffffff);+}++# Emit a WAL record of arbitrary size. Returns the end LSN of the+# record inserted, in bytes.+sub emit_message+{+ my $node = shift;+ my $size = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT pg_logical_emit_message(true, '', repeat('a', $size)) - '0/0'"+ ));+}++# Get the current insert LSN of a node, in bytes.+sub get_insert_lsn+{+ my $node = shift;+ return int(+ $node->safe_psql(+ 'postgres', "SELECT pg_current_wal_insert_lsn() - '0/0'"));+}++# Get GUC value, converted to an int.+sub get_int_setting+{+ my $node = shift;+ my $name = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT setting FROM pg_settings WHERE name = '$name'"));+}++sub start_of_page+{+ my $lsn = shift;+ return $lsn & ~($WAL_BLOCK_SIZE - 1);+}++sub start_of_next_page+{+ my $lsn = shift;+ return start_of_page($lsn) + $WAL_BLOCK_SIZE;+}++# Build a fake WAL record header based on the data given by the caller.+# This needs to follow the format of the C structure XLogRecord. To+# be inserted with write_wal().+sub build_record_header+{+ my $xl_tot_len = shift;+ my $xl_xid = shift || 0;+ my $xl_prev = shift || 0;+ my $xl_info = shift || 0;+ my $xl_rmid = shift || 0;+ my $xl_crc = shift || 0;++ # This needs to follow the structure XLogRecord:+ # I for xl_tot_len+ # I for xl_xid+ # Q for xl_prev+ # C for xl_info+ # C for xl_rmid+ # BB for two bytes of padding+ # I for xl_crc+ return pack("IIQCCBBI",+ $xl_tot_len, $xl_xid, $xl_prev, $xl_info, $xl_rmid, 0, 0, $xl_crc);+}++# Build a fake WAL page header, based on the data given by the caller+# This needs to follow the format of the C structure XLogPageHeaderData.+# To be inserted with write_wal().+sub build_page_header+{+ my $xlp_magic = shift;+ my $xlp_info = shift || 0;+ my $xlp_tli = shift || 0;+ my $xlp_pageaddr = shift || 0;+ my $xlp_rem_len = shift || 0;++ # This needs to follow the structure XLogPageHeaderData:+ # S for xlp_magic+ # S for xlp_info+ # I for xlp_tli+ # Q for xlp_pageaddr+ # I for xlp_rem_len+ return pack("SSIQI",+ $xlp_magic, $xlp_info, $xlp_tli, $xlp_pageaddr, $xlp_rem_len);+}++# Make sure we are far away enough from the end of a page that we could insert+# a couple of small records. This inserts a few records of a fixed size, until+# the threshold gets close enough to the end of the WAL page inserting records+# to.+sub advance_out_of_record_splitting_zone+{+ my $node = shift;++ my $page_threshold = 2000;+ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ while ($page_offset >= $WAL_BLOCK_SIZE - $page_threshold)+ {+ $end_lsn = emit_message($node, $page_threshold);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }+ return $end_lsn;+}++# Advance so close to the end of a page that an XLogRecordHeader would not+# fit on it.+sub advance_to_record_splitting_zone+{+ my $node = shift;++ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Get fairly close to the end of a page in big steps+ while ($page_offset <= $WAL_BLOCK_SIZE - 512)+ {+ $end_lsn = emit_message($node, $WAL_BLOCK_SIZE - $page_offset - 256);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }++ # Calibrate our message size so that we can get closer 8 bytes at+ # a time.+ my $message_size = $WAL_BLOCK_SIZE - 80;+ while ($page_offset <= $WAL_BLOCK_SIZE - $RECORD_HEADER_SIZE)+ {+ $end_lsn = emit_message($node, $message_size);++ my $old_offset = $page_offset;+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Adjust the message size until it causes 8 bytes changes in+ # offset, enough to be able to split a record header.+ my $delta = $page_offset - $old_offset;+ if ($delta > 8)+ {+ $message_size -= 8;+ }+ elsif ($delta <= 0)+ {+ $message_size += 8;+ }+ }+ return $end_lsn;+}++# Setup a new node. The configuration chosen here minimizes the number+# of arbitrary records that could get generated in a cluster. Enlarging+# checkpoint_timeout avoids noise with checkpoint activity. wal_level+# set to "minimal" avoids random standby snapshot records. Autovacuum+# could also trigger randomly, generating random WAL activity of its own.+my $node = PostgreSQL::Test::Cluster->new("node");+$node->init;+$node->append_conf(+ 'postgresql.conf',+ q[wal_level = minimal+ autovacuum = off+ checkpoint_timeout = '30min'+]);+$node->start;+$node->safe_psql('postgres', "CREATE TABLE t AS SELECT 42");++$WAL_SEGMENT_SIZE = get_int_setting($node, 'wal_segment_size');+$WAL_BLOCK_SIZE = get_int_setting($node, 'wal_block_size');+$TLI = $node->safe_psql('postgres',+ "SELECT timeline_id FROM pg_control_checkpoint();");++my $end_lsn;+my $prev_lsn;++###########################################################################+note "Single-page end-of-WAL detection";+###########################################################################++# xl_tot_len is 0 (a common case, we hit trailing zeroes).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+my $log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: wanted 24, got 0", $log_size+ ),+ "xl_tot_len zero");++# xl_tot_len is < 24 (presumably recycled garbage).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn, build_record_header(23));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: wanted 24, got 23",+ $log_size),+ "xl_tot_len short");++# Need more pages, but xl_prev check fails first.+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "record with incorrect prev-link 0/DEADBEEF at .*", $log_size),+ "xl_prev bad");++# xl_crc check fails.+advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 10);+$node->stop('immediate');+# Corrupt a byte in that record, breaking its CRC.+write_wal($node, $TLI, $end_lsn - 8, '!');+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "incorrect resource manager data checksum in record at .*", $log_size+ ),+ "xl_crc bad");+++###########################################################################+note "Multi-page end-of-WAL detection, header is not split";+###########################################################################++# This series of tests requires a valid xl_prev set in the record header+# written to WAL.++# Good xl_prev, we hit zero page next (zero magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 ", $log_size),+ "xlp_magic zero");++# Good xl_prev, we hit garbage page next (bad magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(0xcafe, 0, 1, 0));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number CAFE ", $log_size),+ "xlp_magic bad");++# Good xl_prev, we hit typical recycled page (good xlp_magic, bad+# xlp_pageaddr).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD ", $log_size),+ "xlp_pageaddr bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but bogus xlp_info.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, 0x1234, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid info bits 1234 ", $log_size),+ "xlp_info bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but xlp_info doesn't mention+# continuation record.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("there is no contrecord flag at .*", $log_size),+ "xlp_info lacks XLP_FIRST_IS_CONTRECORD");++# Good xl_prev, xlp_magic, xlp_pageaddr, xlp_info but xlp_rem_len doesn't add+# up.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 at .*", $log_size),+ "xlp_rem_len bad");+++###########################################################################+note "Multi-page, but header is split, so page checks are done first";+###########################################################################++# xlp_prev is bad and xl_tot_len is too big, but we'll check xlp_magic first.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 ", $log_size),+ "xlp_magic zero (split record header)");++# And we'll also check xlp_pageaddr before any header checks.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD ", $log_size),+ "xlp_pageaddr bad (split record header)");++# We'll also discover that xlp_rem_len doesn't add up before any+# header checks,+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 at .*", $log_size),+ "xlp_rem_len bad (split record header)");++done_testing();
--
2.40.1
From ae0864bebe0e475f1a1ee04c2ada573c5e861e38 Mon Sep 17 00:00:00 2001
From: Thomas Munro <thomas.munro@gmail.com>
Date: Mon, 14 Aug 2023 17:06:42 +1200
Subject: [PATCH v6] Don't trust unvalidated xl_tot_len.
xl_tot_len comes first in a WAL record. Usually we don't trust it to be
the true length until we've validated the record header. If the record
header was split across two pages, previously we wouldn't do the
validation until after we'd already tried to allocate enough memory to
hold the record, which was bad because it might actually be garbage
bytes from a recycled WAL file, so we could try to allocate a lot of
memory. Release 15 made it worse.
Since 70b4f82a4b5, we'd at least generate an end-of-WAL condition if the
garbage 4 byte value happened to be > 1GB, but we'd still try to
allocate up to 1GB of memory bogusly otherwise. That was an
improvement, but unfortunately release 15 tries to allocate another
object before that, so you could get a FATAL error and recovery could
fail.
We can fix both variants of the problem more fundamentally using
pre-existing page-level validation, if we just re-order some logic.
The new order of operations in the split-header case defers all memory
allocation based on xl_tot_len until we've read the following page. At
that point we know that its first few bytes are not recycled data, by
checking its xlp_pageaddr, and that its xlp_rem_len agrees with
xl_tot_len on the preceding page. That is strong evidence that
xl_tot_len was truly the start of a record that was logged.
This problem was most likely to occur on a standby, because
walreceiver.c recycles WAL files without zeroing out trailing regions of
each page. We should fix that too, but that wouldn't protect us from
rare crash scenarios where the trailing zeroes don't make it to disk.
Back-patch to 15. We might decide to back-patch a variant of this
to older branches with more study, but the symptoms there (bogus large
allocation) are less severe.
Author: Thomas Munro <thomas.munro@gmail.com>
Author: Michael Paquier <michael@paquier.xyz>
Reported-by: Alexander Lakhin <exclusion@gmail.com>
Reviewed-by: Noah Misch <noah@leadboat.com> (the idea, not the code)
Reviewed-by: Michael Paquier <michael@paquier.xyz>
Reviewed-by: Sergei Kornilov <sk@zsrv.org>
Discussion: https://postgr.es/m/17928-aa92416a70ff44a2%40postgresql.org
---
src/backend/access/transam/xlogreader.c | 77 ++--
src/test/perl/TestLib.pm | 36 ++
src/test/recovery/t/038_end_of_wal.pl | 449 ++++++++++++++++++++++++
3 files changed, 523 insertions(+), 39 deletions(-)
create mode 100644 src/test/recovery/t/038_end_of_wal.pl
diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.cindex 26f8e0ae2c..0016a3b3ef 100644--- a/src/backend/access/transam/xlogreader.c+++ b/src/backend/access/transam/xlogreader.c@@ -155,6 +155,9 @@ XLogReaderFree(XLogReaderState *state)
* XLOG_BLCKSZ, and make sure it's at least 5*Max(BLCKSZ, XLOG_BLCKSZ) to start
* with. (That is enough for all "normal" records, but very large commit or
* abort records might need more space.)
+ *+ * Note: This routine should *never* be called for xl_tot_len until the header+ * of the record has been fully validated.
*/
static bool
allocate_recordbuf(XLogReaderState *state, uint32 reclength)
@@ -164,25 +167,6 @@ allocate_recordbuf(XLogReaderState *state, uint32 reclength)
newSize += XLOG_BLCKSZ - (newSize % XLOG_BLCKSZ);
newSize = Max(newSize, 5 * Max(BLCKSZ, XLOG_BLCKSZ));
-#ifndef FRONTEND-- /*- * Note that in much unlucky circumstances, the random data read from a- * recycled segment can cause this routine to be called with a size- * causing a hard failure at allocation. For a standby, this would cause- * the instance to stop suddenly with a hard failure, preventing it to- * retry fetching WAL from one of its sources which could allow it to move- * on with replay without a manual restart. If the data comes from a past- * recycled segment and is still valid, then the allocation may succeed- * but record checks are going to fail so this would be short-lived. If- * the allocation fails because of a memory shortage, then this is not a- * hard failure either per the guarantee given by MCXT_ALLOC_NO_OOM.- */- if (!AllocSizeIsValid(newSize))- return false;--#endif-
if (state->readRecordBuf)
pfree(state->readRecordBuf);
state->readRecordBuf =
@@ -346,15 +330,7 @@ restart:
}
else
{
- /* XXX: more validation should be done here */- if (total_len < SizeOfXLogRecord)- {- report_invalid_record(state,- "invalid record length at %X/%X: wanted %u, got %u",- (uint32) (RecPtr >> 32), (uint32) RecPtr,- (uint32) SizeOfXLogRecord, total_len);- goto err;- }+ /* We'll validate the header once we have the next page. */
gotheader = false;
}
@@ -370,17 +346,11 @@ restart:
assembled = true;
/*
- * Enlarge readRecordBuf as needed.+ * We always have space for a couple of pages, enough to validate a+ * boundary-spanning record header.
*/
- if (total_len > state->readRecordBufSize &&- !allocate_recordbuf(state, total_len))- {- /* We treat this as a "bogus data" condition */- report_invalid_record(state, "record length %u at %X/%X too long",- total_len,- (uint32) (RecPtr >> 32), (uint32) RecPtr);- goto err;- }+ Assert(state->readRecordBufSize >= XLOG_BLCKSZ * 2);+ Assert(state->readRecordBufSize >= len);
/* Copy the first fragment of the record from the first page. */
memcpy(state->readRecordBuf,
@@ -475,8 +445,37 @@ restart:
goto err;
gotheader = true;
}
- } while (gotlen < total_len);+ /*+ * We might need a bigger buffer. We have validated the record+ * header, in the case that it split over a page boundary. We've+ * also cross-checked total_len against xlp_rem_len on the second+ * page, and verified xlp_pageaddr on both.+ */+ Assert(gotheader);+ if (total_len > state->readRecordBufSize)+ {+ char save_copy[XLOG_BLCKSZ * 2];++ /*+ * Save and restore the data we already had. It can't be more+ * than two pages.+ */+ Assert(gotlen <= lengthof(save_copy));+ Assert(gotlen <= state->readRecordBufSize);+ memcpy(save_copy, state->readRecordBuf, gotlen);+ if (!allocate_recordbuf(state, total_len))+ {+ /* We treat this as a "bogus data" condition */+ report_invalid_record(state, "record length %u at %X/%X too long",+ total_len,+ (uint32) (RecPtr >> 32), (uint32) RecPtr);+ goto err;+ }+ memcpy(state->readRecordBuf, save_copy, gotlen);+ buffer = state->readRecordBuf + gotlen;+ }+ } while (gotlen < total_len);
Assert(gotheader);
record = (XLogRecord *) state->readRecordBuf;
diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pmindex de851e1615..5f80ff9cbc 100644--- a/src/test/perl/TestLib.pm+++ b/src/test/perl/TestLib.pm@@ -33,6 +33,7 @@ our @EXPORT = qw(
check_mode_recursive
chmod_recursive
check_pg_config
+ scan_server_header
system_or_bail
system_log
run_log
@@ -459,6 +460,41 @@ sub chmod_recursive
return;
}
+# Returns an array that stores all the matches of the given regular expression+# within the PostgreSQL installation's C<header_path>. This can be used to+# retrieve specific value patterns from the installation's header files.+sub scan_server_header+{+ my ($header_path, $regexp) = @_;++ my ($stdout, $stderr);+ my $result = IPC::Run::run [ 'pg_config', '--includedir-server' ], '>',+ \$stdout, '2>', \$stderr+ or die "could not execute pg_config";+ chomp($stdout);+ $stdout =~ s/\r$//;++ open my $header_h, '<', "$stdout/$header_path" or die "$!";++ my @match = undef;+ while (<$header_h>)+ {+ my $line = $_;++ if ($line =~ /^$regexp/)+ {+ # Found match, so store all the results.+ @match = @{^CAPTURE};+ last;+ }+ }++ close $header_h;+ die "could not find match in header $header_path\n"+ unless @match;+ return @match;+}+
# Check presence of a given regexp within pg_config.h for the installation
# where tests are running, returning a match status result depending on
# that.
diff --git a/src/test/recovery/t/038_end_of_wal.pl b/src/test/recovery/t/038_end_of_wal.plnew file mode 100644index 0000000000..6927d1298a--- /dev/null+++ b/src/test/recovery/t/038_end_of_wal.pl@@ -0,0 +1,449 @@+# Copyright (c) 2023, PostgreSQL Global Development Group+#+# Test detecting end of WAL replay. This test suite generates fake+# WAL records able to trigger various failure scenarios at replay.++use strict;+use warnings;+use PostgreSQL::Test::Cluster;+use PostgreSQL::Test::Utils;+use Test::More;+use Fcntl qw(SEEK_SET);++use integer; # causes / operator to use integer math++# Header size of record header.+my $RECORD_HEADER_SIZE = 24;++# Fields retrieved from code headers.+my @scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLOG_PAGE_MAGIC\s+(\w+)');+my $XLP_PAGE_MAGIC = hex($scan_result[0]);+@scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLP_FIRST_IS_CONTRECORD\s+(\w+)');+my $XLP_FIRST_IS_CONTRECORD = hex($scan_result[0]);++# Values queried from the server+my $WAL_SEGMENT_SIZE;+my $WAL_BLOCK_SIZE;+my $TLI;++# Build path of a WAL segment.+sub wal_segment_path+{+ my $node = shift;+ my $tli = shift;+ my $segment = shift;+ my $wal_path =+ sprintf("%s/pg_wal/%08X%08X%08X", $node->data_dir, $tli, 0, $segment);+ return $wal_path;+}++# Calculate from a LSN (in bytes) its segment number and its offset.+sub lsn_to_segment_and_offset+{+ my $lsn = shift;+ return ($lsn / $WAL_SEGMENT_SIZE, $lsn % $WAL_SEGMENT_SIZE);+}++# Write some arbitrary data in WAL for the given segment at offset.+# This should be called while the cluster is offline.+sub write_wal+{+ my $node = shift;+ my $tli = shift;+ my $lsn = shift;+ my $data = shift;++ my ($segment, $offset) = lsn_to_segment_and_offset($lsn);+ my $path = wal_segment_path($node, $tli, $segment);++ open my $fh, "+<:raw", $path or die;+ seek($fh, $offset, SEEK_SET) or die;+ print $fh $data;+ close $fh;+}++sub format_lsn+{+ my $lsn = shift;+ return sprintf("%X/%X", $lsn >> 32, $lsn & 0xffffffff);+}++# Emit a WAL record of arbitrary size. Returns the end LSN of the+# record inserted, in bytes.+sub emit_message+{+ my $node = shift;+ my $size = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT pg_logical_emit_message(true, '', repeat('a', $size)) - '0/0'"+ ));+}++# Get the current insert LSN of a node, in bytes.+sub get_insert_lsn+{+ my $node = shift;+ return int(+ $node->safe_psql(+ 'postgres', "SELECT pg_current_wal_insert_lsn() - '0/0'"));+}++# Get GUC value, converted to an int.+sub get_int_setting+{+ my $node = shift;+ my $name = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT setting FROM pg_settings WHERE name = '$name'"));+}++sub start_of_page+{+ my $lsn = shift;+ return $lsn & ~($WAL_BLOCK_SIZE - 1);+}++sub start_of_next_page+{+ my $lsn = shift;+ return start_of_page($lsn) + $WAL_BLOCK_SIZE;+}++# Build a fake WAL record header based on the data given by the caller.+# This needs to follow the format of the C structure XLogRecord. To+# be inserted with write_wal().+sub build_record_header+{+ my $xl_tot_len = shift;+ my $xl_xid = shift || 0;+ my $xl_prev = shift || 0;+ my $xl_info = shift || 0;+ my $xl_rmid = shift || 0;+ my $xl_crc = shift || 0;++ # This needs to follow the structure XLogRecord:+ # I for xl_tot_len+ # I for xl_xid+ # Q for xl_prev+ # C for xl_info+ # C for xl_rmid+ # BB for two bytes of padding+ # I for xl_crc+ return pack("IIQCCBBI",+ $xl_tot_len, $xl_xid, $xl_prev, $xl_info, $xl_rmid, 0, 0, $xl_crc);+}++# Build a fake WAL page header, based on the data given by the caller+# This needs to follow the format of the C structure XLogPageHeaderData.+# To be inserted with write_wal().+sub build_page_header+{+ my $xlp_magic = shift;+ my $xlp_info = shift || 0;+ my $xlp_tli = shift || 0;+ my $xlp_pageaddr = shift || 0;+ my $xlp_rem_len = shift || 0;++ # This needs to follow the structure XLogPageHeaderData:+ # S for xlp_magic+ # S for xlp_info+ # I for xlp_tli+ # Q for xlp_pageaddr+ # I for xlp_rem_len+ return pack("SSIQI",+ $xlp_magic, $xlp_info, $xlp_tli, $xlp_pageaddr, $xlp_rem_len);+}++# Make sure we are far away enough from the end of a page that we could insert+# a couple of small records. This inserts a few records of a fixed size, until+# the threshold gets close enough to the end of the WAL page inserting records+# to.+sub advance_out_of_record_splitting_zone+{+ my $node = shift;++ my $page_threshold = 2000;+ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ while ($page_offset >= $WAL_BLOCK_SIZE - $page_threshold)+ {+ $end_lsn = emit_message($node, $page_threshold);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }+ return $end_lsn;+}++# Advance so close to the end of a page that an XLogRecordHeader would not+# fit on it.+sub advance_to_record_splitting_zone+{+ my $node = shift;++ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Get fairly close to the end of a page in big steps+ while ($page_offset <= $WAL_BLOCK_SIZE - 512)+ {+ $end_lsn = emit_message($node, $WAL_BLOCK_SIZE - $page_offset - 256);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }++ # Calibrate our message size so that we can get closer 8 bytes at+ # a time.+ my $message_size = $WAL_BLOCK_SIZE - 80;+ while ($page_offset <= $WAL_BLOCK_SIZE - $RECORD_HEADER_SIZE)+ {+ $end_lsn = emit_message($node, $message_size);++ my $old_offset = $page_offset;+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Adjust the message size until it causes 8 bytes changes in+ # offset, enough to be able to split a record header.+ my $delta = $page_offset - $old_offset;+ if ($delta > 8)+ {+ $message_size -= 8;+ }+ elsif ($delta <= 0)+ {+ $message_size += 8;+ }+ }+ return $end_lsn;+}++# Setup a new node. The configuration chosen here minimizes the number+# of arbitrary records that could get generated in a cluster. Enlarging+# checkpoint_timeout avoids noise with checkpoint activity. wal_level+# set to "minimal" avoids random standby snapshot records. Autovacuum+# could also trigger randomly, generating random WAL activity of its own.+my $node = PostgreSQL::Test::Cluster->new("node");+$node->init;+$node->append_conf(+ 'postgresql.conf',+ q[wal_level = minimal+ autovacuum = off+ checkpoint_timeout = '30min'+]);+$node->start;+$node->safe_psql('postgres', "CREATE TABLE t AS SELECT 42");++$WAL_SEGMENT_SIZE = get_int_setting($node, 'wal_segment_size');+$WAL_BLOCK_SIZE = get_int_setting($node, 'wal_block_size');+$TLI = $node->safe_psql('postgres',+ "SELECT timeline_id FROM pg_control_checkpoint();");++my $end_lsn;+my $prev_lsn;++###########################################################################+note "Single-page end-of-WAL detection";+###########################################################################++# xl_tot_len is 0 (a common case, we hit trailing zeroes).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+my $log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: wanted 24, got 0", $log_size+ ),+ "xl_tot_len zero");++# xl_tot_len is < 24 (presumably recycled garbage).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn, build_record_header(23));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: wanted 24, got 23",+ $log_size),+ "xl_tot_len short");++# Need more pages, but xl_prev check fails first.+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "record with incorrect prev-link 0/DEADBEEF at .*", $log_size),+ "xl_prev bad");++# xl_crc check fails.+advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 10);+$node->stop('immediate');+# Corrupt a byte in that record, breaking its CRC.+write_wal($node, $TLI, $end_lsn - 8, '!');+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "incorrect resource manager data checksum in record at .*", $log_size+ ),+ "xl_crc bad");+++###########################################################################+note "Multi-page end-of-WAL detection, header is not split";+###########################################################################++# This series of tests requires a valid xl_prev set in the record header+# written to WAL.++# Good xl_prev, we hit zero page next (zero magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 ", $log_size),+ "xlp_magic zero");++# Good xl_prev, we hit garbage page next (bad magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(0xcafe, 0, 1, 0));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number CAFE ", $log_size),+ "xlp_magic bad");++# Good xl_prev, we hit typical recycled page (good xlp_magic, bad+# xlp_pageaddr).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD ", $log_size),+ "xlp_pageaddr bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but bogus xlp_info.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, 0x1234, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid info bits 1234 ", $log_size),+ "xlp_info bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but xlp_info doesn't mention+# continuation record.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("there is no contrecord flag at .*", $log_size),+ "xlp_info lacks XLP_FIRST_IS_CONTRECORD");++# Good xl_prev, xlp_magic, xlp_pageaddr, xlp_info but xlp_rem_len doesn't add+# up.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 at .*", $log_size),+ "xlp_rem_len bad");+++###########################################################################+note "Multi-page, but header is split, so page checks are done first";+###########################################################################++# xlp_prev is bad and xl_tot_len is too big, but we'll check xlp_magic first.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 ", $log_size),+ "xlp_magic zero (split record header)");++# And we'll also check xlp_pageaddr before any header checks.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD ", $log_size),+ "xlp_pageaddr bad (split record header)");++# We'll also discover that xlp_rem_len doesn't add up before any+# header checks,+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 at .*", $log_size),+ "xlp_rem_len bad (split record header)");++done_testing();
--
2.40.1
Attachments:
[text/x-diff] v6-0001-Don-t-trust-unvalidated-xl_tot_len.patch (24.5K, ../ZP+4YYrPZk0GFlc3@paquier.xyz/2-v6-0001-Don-t-trust-unvalidated-xl_tot_len.patch)
download | inline diff:
From 5a294edd527c87248e5c0e47dfdb8a5d43944afe Mon Sep 17 00:00:00 2001
From: Thomas Munro <thomas.munro@gmail.com>
Date: Mon, 14 Aug 2023 17:06:42 +1200
Subject: [PATCH v6] Don't trust unvalidated xl_tot_len.
xl_tot_len comes first in a WAL record. Usually we don't trust it to be
the true length until we've validated the record header. If the record
header was split across two pages, previously we wouldn't do the
validation until after we'd already tried to allocate enough memory to
hold the record, which was bad because it might actually be garbage
bytes from a recycled WAL file, so we could try to allocate a lot of
memory. Release 15 made it worse.
Since 70b4f82a4b5, we'd at least generate an end-of-WAL condition if the
garbage 4 byte value happened to be > 1GB, but we'd still try to
allocate up to 1GB of memory bogusly otherwise. That was an
improvement, but unfortunately release 15 tries to allocate another
object before that, so you could get a FATAL error and recovery could
fail.
We can fix both variants of the problem more fundamentally using
pre-existing page-level validation, if we just re-order some logic.
The new order of operations in the split-header case defers all memory
allocation based on xl_tot_len until we've read the following page. At
that point we know that its first few bytes are not recycled data, by
checking its xlp_pageaddr, and that its xlp_rem_len agrees with
xl_tot_len on the preceding page. That is strong evidence that
xl_tot_len was truly the start of a record that was logged.
This problem was most likely to occur on a standby, because
walreceiver.c recycles WAL files without zeroing out trailing regions of
each page. We should fix that too, but that wouldn't protect us from
rare crash scenarios where the trailing zeroes don't make it to disk.
Back-patch to 15. We might decide to back-patch a variant of this
to older branches with more study, but the symptoms there (bogus large
allocation) are less severe.
Author: Thomas Munro <thomas.munro@gmail.com>
Author: Michael Paquier <michael@paquier.xyz>
Reported-by: Alexander Lakhin <exclusion@gmail.com>
Reviewed-by: Noah Misch <noah@leadboat.com> (the idea, not the code)
Reviewed-by: Michael Paquier <michael@paquier.xyz>
Reviewed-by: Sergei Kornilov <sk@zsrv.org>
Discussion: https://postgr.es/m/17928-aa92416a70ff44a2%40postgresql.org
---
src/backend/access/transam/xlogreader.c | 123 ++++---
src/test/perl/PostgreSQL/Test/Utils.pm | 43 +++
src/test/recovery/meson.build | 1 +
src/test/recovery/t/038_end_of_wal.pl | 443 ++++++++++++++++++++++++
4 files changed, 554 insertions(+), 56 deletions(-)
create mode 100644 src/test/recovery/t/038_end_of_wal.pl
diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.cindex c9f9f6e98f..58654b746c 100644--- a/src/backend/access/transam/xlogreader.c+++ b/src/backend/access/transam/xlogreader.c@@ -192,6 +192,9 @@ XLogReaderFree(XLogReaderState *state)
* XLOG_BLCKSZ, and make sure it's at least 5*Max(BLCKSZ, XLOG_BLCKSZ) to start
* with. (That is enough for all "normal" records, but very large commit or
* abort records might need more space.)
+ *+ * Note: This routine should *never* be called for xl_tot_len until the header+ * of the record has been fully validated.
*/
static bool
allocate_recordbuf(XLogReaderState *state, uint32 reclength)
@@ -201,25 +204,6 @@ allocate_recordbuf(XLogReaderState *state, uint32 reclength)
newSize += XLOG_BLCKSZ - (newSize % XLOG_BLCKSZ);
newSize = Max(newSize, 5 * Max(BLCKSZ, XLOG_BLCKSZ));
-#ifndef FRONTEND-- /*- * Note that in much unlucky circumstances, the random data read from a- * recycled segment can cause this routine to be called with a size- * causing a hard failure at allocation. For a standby, this would cause- * the instance to stop suddenly with a hard failure, preventing it to- * retry fetching WAL from one of its sources which could allow it to move- * on with replay without a manual restart. If the data comes from a past- * recycled segment and is still valid, then the allocation may succeed- * but record checks are going to fail so this would be short-lived. If- * the allocation fails because of a memory shortage, then this is not a- * hard failure either per the guarantee given by MCXT_ALLOC_NO_OOM.- */- if (!AllocSizeIsValid(newSize))- return false;--#endif-
if (state->readRecordBuf)
pfree(state->readRecordBuf);
state->readRecordBuf =
@@ -669,41 +653,26 @@ restart:
}
else
{
- /* XXX: more validation should be done here */- if (total_len < SizeOfXLogRecord)- {- report_invalid_record(state,- "invalid record length at %X/%X: expected at least %u, got %u",- LSN_FORMAT_ARGS(RecPtr),- (uint32) SizeOfXLogRecord, total_len);- goto err;- }+ /* We'll validate the header once we have the next page. */
gotheader = false;
}
/*
- * Find space to decode this record. Don't allow oversized allocation if- * the caller requested nonblocking. Otherwise, we *have* to try to- * decode the record now because the caller has nothing else to do, so- * allow an oversized record to be palloc'd if that turns out to be- * necessary.+ * Try to find space to decode this record, if we can do so without+ * calling palloc. If we can't, we'll try again below after we've+ * validated that total_len isn't garbage bytes from a recycled WAL page.
*/
decoded = XLogReadRecordAlloc(state,
total_len,
- !nonblocking /* allow_oversized */ );- if (decoded == NULL)+ false /* allow_oversized */ );+ if (decoded == NULL && nonblocking)
{
/*
- * There is no space in the decode buffer. The caller should help- * with that problem by consuming some records.+ * There is no space in the circular decode buffer, and the caller is+ * only reading ahead. The caller should consume existing records to+ * make space.
*/
- if (nonblocking)- return XLREAD_WOULDBLOCK;-- /* We failed to allocate memory for an oversized record. */- report_invalid_record(state,- "out of memory while trying to decode a record of length %u", total_len);- goto err;+ return XLREAD_WOULDBLOCK;
}
len = XLOG_BLCKSZ - RecPtr % XLOG_BLCKSZ;
@@ -718,16 +687,11 @@ restart:
assembled = true;
/*
- * Enlarge readRecordBuf as needed.+ * We always have space for a couple of pages, enough to validate a+ * boundary-spanning record header.
*/
- if (total_len > state->readRecordBufSize &&- !allocate_recordbuf(state, total_len))- {- /* We treat this as a "bogus data" condition */- report_invalid_record(state, "record length %u at %X/%X too long",- total_len, LSN_FORMAT_ARGS(RecPtr));- goto err;- }+ Assert(state->readRecordBufSize >= XLOG_BLCKSZ * 2);+ Assert(state->readRecordBufSize >= len);
/* Copy the first fragment of the record from the first page. */
memcpy(state->readRecordBuf,
@@ -824,8 +788,35 @@ restart:
goto err;
gotheader = true;
}
- } while (gotlen < total_len);+ /*+ * We might need a bigger buffer. We have validated the record+ * header, in the case that it split over a page boundary. We've+ * also cross-checked total_len against xlp_rem_len on the second+ * page, and verified xlp_pageaddr on both.+ */+ if (total_len > state->readRecordBufSize)+ {+ char save_copy[XLOG_BLCKSZ * 2];++ /*+ * Save and restore the data we already had. It can't be more+ * than two pages.+ */+ Assert(gotlen <= lengthof(save_copy));+ Assert(gotlen <= state->readRecordBufSize);+ memcpy(save_copy, state->readRecordBuf, gotlen);+ if (!allocate_recordbuf(state, total_len))+ {+ /* We treat this as a "bogus data" condition */+ report_invalid_record(state, "record length %u at %X/%X too long",+ total_len, LSN_FORMAT_ARGS(RecPtr));+ goto err;+ }+ memcpy(state->readRecordBuf, save_copy, gotlen);+ buffer = state->readRecordBuf + gotlen;+ }+ } while (gotlen < total_len);
Assert(gotheader);
record = (XLogRecord *) state->readRecordBuf;
@@ -867,6 +858,28 @@ restart:
state->NextRecPtr -= XLogSegmentOffset(state->NextRecPtr, state->segcxt.ws_segsize);
}
+ /*+ * If we got here without a DecodedXLogRecord, it means we needed to+ * validate total_len before trusting it, but by now now we've done that.+ */+ if (decoded == NULL)+ {+ Assert(!nonblocking);+ decoded = XLogReadRecordAlloc(state,+ total_len,+ true /* allow_oversized */ );+ if (decoded == NULL)+ {+ /*+ * We failed to allocate memory for an oversized record. As+ * above, we currently treat this as a "bogus data" condition.+ */+ report_invalid_record(state,+ "out of memory while trying to decode a record of length %u", total_len);+ goto err;+ }+ }+
if (DecodeXLogRecord(state, decoded, record, RecPtr, &errormsg))
{
/* Record the location of the next record. */
@@ -895,8 +908,6 @@ restart:
state->decode_queue_head = decoded;
return XLREAD_SUCCESS;
}
- else- return XLREAD_FAIL;
err:
if (assembled)
diff --git a/src/test/perl/PostgreSQL/Test/Utils.pm b/src/test/perl/PostgreSQL/Test/Utils.pmindex 617caa022f..9de34a2260 100644--- a/src/test/perl/PostgreSQL/Test/Utils.pm+++ b/src/test/perl/PostgreSQL/Test/Utils.pm@@ -71,6 +71,7 @@ our @EXPORT = qw(
chmod_recursive
check_pg_config
dir_symlink
+ scan_server_header
system_or_bail
system_log
run_log
@@ -702,6 +703,48 @@ sub chmod_recursive
=pod
+=item scan_server_header(header_path, regexp)++Returns an array that stores all the matches of the given regular expression+within the PostgreSQL installation's C<header_path>. This can be used to+retrieve specific value patterns from the installation's header files.++=cut++sub scan_server_header+{+ my ($header_path, $regexp) = @_;++ my ($stdout, $stderr);+ my $result = IPC::Run::run [ 'pg_config', '--includedir-server' ], '>',+ \$stdout, '2>', \$stderr+ or die "could not execute pg_config";+ chomp($stdout);+ $stdout =~ s/\r$//;++ open my $header_h, '<', "$stdout/$header_path" or die "$!";++ my @match = undef;+ while (<$header_h>)+ {+ my $line = $_;++ if ($line =~ /^$regexp/)+ {+ # Found match, so store all the results.+ @match = @{^CAPTURE};+ last;+ }+ }++ close $header_h;+ die "could not find match in header $header_path\n"+ unless @match;+ return @match;+}++=pod+
=item check_pg_config(regexp)
Return the number of matches of the given regular expression
diff --git a/src/test/recovery/meson.build b/src/test/recovery/meson.buildindex e7328e4894..10407668d4 100644--- a/src/test/recovery/meson.build+++ b/src/test/recovery/meson.build@@ -43,6 +43,7 @@ tests += {
't/035_standby_logical_decoding.pl',
't/036_truncated_dropped.pl',
't/037_invalid_database.pl',
+ 't/038_end_of_wal.pl',
],
},
}
diff --git a/src/test/recovery/t/038_end_of_wal.pl b/src/test/recovery/t/038_end_of_wal.plnew file mode 100644index 0000000000..aa5eec7c03--- /dev/null+++ b/src/test/recovery/t/038_end_of_wal.pl@@ -0,0 +1,443 @@+# Copyright (c) 2023, PostgreSQL Global Development Group+#+# Test detecting end of WAL replay. This test suite generates fake+# WAL records able to trigger various failure scenarios at replay.++use strict;+use warnings;+use PostgreSQL::Test::Cluster;+use PostgreSQL::Test::Utils;+use Test::More;+use Fcntl qw(SEEK_SET);++use integer; # causes / operator to use integer math++# Header size of record header.+my $RECORD_HEADER_SIZE = 24;++# Fields retrieved from code headers.+my @scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLOG_PAGE_MAGIC\s+(\w+)');+my $XLP_PAGE_MAGIC = hex($scan_result[0]);+@scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLP_FIRST_IS_CONTRECORD\s+(\w+)');+my $XLP_FIRST_IS_CONTRECORD = hex($scan_result[0]);++# Values queried from the server+my $WAL_SEGMENT_SIZE;+my $WAL_BLOCK_SIZE;+my $TLI;++# Build path of a WAL segment.+sub wal_segment_path+{+ my $node = shift;+ my $tli = shift;+ my $segment = shift;+ my $wal_path =+ sprintf("%s/pg_wal/%08X%08X%08X", $node->data_dir, $tli, 0, $segment);+ return $wal_path;+}++# Calculate from a LSN (in bytes) its segment number and its offset.+sub lsn_to_segment_and_offset+{+ my $lsn = shift;+ return ($lsn / $WAL_SEGMENT_SIZE, $lsn % $WAL_SEGMENT_SIZE);+}++# Write some arbitrary data in WAL for the given segment at offset.+# This should be called while the cluster is offline.+sub write_wal+{+ my $node = shift;+ my $tli = shift;+ my $lsn = shift;+ my $data = shift;++ my ($segment, $offset) = lsn_to_segment_and_offset($lsn);+ my $path = wal_segment_path($node, $tli, $segment);++ open my $fh, "+<:raw", $path or die;+ seek($fh, $offset, SEEK_SET) or die;+ print $fh $data;+ close $fh;+}++# Emit a WAL record of arbitrary size. Returns the end LSN of the+# record inserted, in bytes.+sub emit_message+{+ my $node = shift;+ my $size = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT pg_logical_emit_message(true, '', repeat('a', $size)) - '0/0'"+ ));+}++# Get the current insert LSN of a node, in bytes.+sub get_insert_lsn+{+ my $node = shift;+ return int(+ $node->safe_psql(+ 'postgres', "SELECT pg_current_wal_insert_lsn() - '0/0'"));+}++# Get GUC value, converted to an int.+sub get_int_setting+{+ my $node = shift;+ my $name = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT setting FROM pg_settings WHERE name = '$name'"));+}++sub start_of_page+{+ my $lsn = shift;+ return $lsn & ~($WAL_BLOCK_SIZE - 1);+}++sub start_of_next_page+{+ my $lsn = shift;+ return start_of_page($lsn) + $WAL_BLOCK_SIZE;+}++# Build a fake WAL record header based on the data given by the caller.+# This needs to follow the format of the C structure XLogRecord. To+# be inserted with write_wal().+sub build_record_header+{+ my $xl_tot_len = shift;+ my $xl_xid = shift || 0;+ my $xl_prev = shift || 0;+ my $xl_info = shift || 0;+ my $xl_rmid = shift || 0;+ my $xl_crc = shift || 0;++ # This needs to follow the structure XLogRecord:+ # I for xl_tot_len+ # I for xl_xid+ # Q for xl_prev+ # C for xl_info+ # C for xl_rmid+ # BB for two bytes of padding+ # I for xl_crc+ return pack("IIQCCBBI",+ $xl_tot_len, $xl_xid, $xl_prev, $xl_info, $xl_rmid, 0, 0, $xl_crc);+}++# Build a fake WAL page header, based on the data given by the caller+# This needs to follow the format of the C structure XLogPageHeaderData.+# To be inserted with write_wal().+sub build_page_header+{+ my $xlp_magic = shift;+ my $xlp_info = shift || 0;+ my $xlp_tli = shift || 0;+ my $xlp_pageaddr = shift || 0;+ my $xlp_rem_len = shift || 0;++ # This needs to follow the structure XLogPageHeaderData:+ # S for xlp_magic+ # S for xlp_info+ # I for xlp_tli+ # Q for xlp_pageaddr+ # I for xlp_rem_len+ return pack("SSIQI",+ $xlp_magic, $xlp_info, $xlp_tli, $xlp_pageaddr, $xlp_rem_len);+}++# Make sure we are far away enough from the end of a page that we could insert+# a couple of small records. This inserts a few records of a fixed size, until+# the threshold gets close enough to the end of the WAL page inserting records+# to.+sub advance_out_of_record_splitting_zone+{+ my $node = shift;++ my $page_threshold = $WAL_BLOCK_SIZE / 4;+ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ while ($page_offset >= $WAL_BLOCK_SIZE - $page_threshold)+ {+ $end_lsn = emit_message($node, $page_threshold);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }+ return $end_lsn;+}++# Advance so close to the end of a page that an XLogRecordHeader would not+# fit on it.+sub advance_to_record_splitting_zone+{+ my $node = shift;++ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Get fairly close to the end of a page in big steps+ while ($page_offset <= $WAL_BLOCK_SIZE - 512)+ {+ $end_lsn = emit_message($node, $WAL_BLOCK_SIZE - $page_offset - 256);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }++ # Calibrate our message size so that we can get closer 8 bytes at+ # a time.+ my $message_size = $WAL_BLOCK_SIZE - 80;+ while ($page_offset <= $WAL_BLOCK_SIZE - $RECORD_HEADER_SIZE)+ {+ $end_lsn = emit_message($node, $message_size);++ my $old_offset = $page_offset;+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Adjust the message size until it causes 8 bytes changes in+ # offset, enough to be able to split a record header.+ my $delta = $page_offset - $old_offset;+ if ($delta > 8)+ {+ $message_size -= 8;+ }+ elsif ($delta <= 0)+ {+ $message_size += 8;+ }+ }+ return $end_lsn;+}++# Setup a new node. The configuration chosen here minimizes the number+# of arbitrary records that could get generated in a cluster. Enlarging+# checkpoint_timeout avoids noise with checkpoint activity. wal_level+# set to "minimal" avoids random standby snapshot records. Autovacuum+# could also trigger randomly, generating random WAL activity of its own.+my $node = PostgreSQL::Test::Cluster->new("node");+$node->init;+$node->append_conf(+ 'postgresql.conf',+ q[wal_level = minimal+ autovacuum = off+ checkpoint_timeout = '30min'+]);+$node->start;+$node->safe_psql('postgres', "CREATE TABLE t AS SELECT 42");++$WAL_SEGMENT_SIZE = get_int_setting($node, 'wal_segment_size');+$WAL_BLOCK_SIZE = get_int_setting($node, 'wal_block_size');+$TLI = $node->safe_psql('postgres',+ "SELECT timeline_id FROM pg_control_checkpoint();");++my $end_lsn;+my $prev_lsn;++###########################################################################+note "Single-page end-of-WAL detection";+###########################################################################++# xl_tot_len is 0 (a common case, we hit trailing zeroes).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+my $log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: expected at least 24, got 0", $log_size+ ),+ "xl_tot_len zero");++# xl_tot_len is < 24 (presumably recycled garbage).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn, build_record_header(23));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: expected at least 24, got 23",+ $log_size),+ "xl_tot_len short");++# Need more pages, but xl_prev check fails first.+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "record with incorrect prev-link 0/DEADBEEF at .*", $log_size),+ "xl_prev bad");++# xl_crc check fails.+advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 10);+$node->stop('immediate');+# Corrupt a byte in that record, breaking its CRC.+write_wal($node, $TLI, $end_lsn - 8, '!');+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "incorrect resource manager data checksum in record at .*", $log_size+ ),+ "xl_crc bad");+++###########################################################################+note "Multi-page end-of-WAL detection, header is not split";+###########################################################################++# This series of tests requires a valid xl_prev set in the record header+# written to WAL.++# Good xl_prev, we hit zero page next (zero magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 .* LSN .*", $log_size),+ "xlp_magic zero");++# Good xl_prev, we hit garbage page next (bad magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(0xcafe, 0, 1, 0));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number CAFE .* LSN .*", $log_size),+ "xlp_magic bad");++# Good xl_prev, we hit typical recycled page (good xlp_magic, bad+# xlp_pageaddr).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD in .*, LSN .*,", $log_size),+ "xlp_pageaddr bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but bogus xlp_info.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, 0x1234, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid info bits 1234 in .*, LSN .*,", $log_size),+ "xlp_info bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but xlp_info doesn't mention+# continuation record.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("there is no contrecord flag at .*", $log_size),+ "xlp_info lacks XLP_FIRST_IS_CONTRECORD");++# Good xl_prev, xlp_magic, xlp_pageaddr, xlp_info but xlp_rem_len doesn't add+# up.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 .* at .*", $log_size),+ "xlp_rem_len bad");+++###########################################################################+note "Multi-page, but header is split, so page checks are done first";+###########################################################################++# xlp_prev is bad and xl_tot_len is too big, but we'll check xlp_magic first.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 .* LSN .*", $log_size),+ "xlp_magic zero (split record header)");++# And we'll also check xlp_pageaddr before any header checks.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD in .*, LSN .*,", $log_size),+ "xlp_pageaddr bad (split record header)");++# We'll also discover that xlp_rem_len doesn't add up before any+# header checks,+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 .* at .*", $log_size),+ "xlp_rem_len bad (split record header)");++done_testing();--
2.40.1
[text/plain] v6-0001-Don-t-trust-unvalidated-xl_tot_len.patch.16 (24.5K, ../ZP+4YYrPZk0GFlc3@paquier.xyz/3-v6-0001-Don-t-trust-unvalidated-xl_tot_len.patch.16)
download | inline diff:
From ea7a54c827f18b56796189c0e9d36224e6a32a84 Mon Sep 17 00:00:00 2001
From: Thomas Munro <thomas.munro@gmail.com>
Date: Mon, 14 Aug 2023 17:06:42 +1200
Subject: [PATCH v6] Don't trust unvalidated xl_tot_len.
xl_tot_len comes first in a WAL record. Usually we don't trust it to be
the true length until we've validated the record header. If the record
header was split across two pages, previously we wouldn't do the
validation until after we'd already tried to allocate enough memory to
hold the record, which was bad because it might actually be garbage
bytes from a recycled WAL file, so we could try to allocate a lot of
memory. Release 15 made it worse.
Since 70b4f82a4b5, we'd at least generate an end-of-WAL condition if the
garbage 4 byte value happened to be > 1GB, but we'd still try to
allocate up to 1GB of memory bogusly otherwise. That was an
improvement, but unfortunately release 15 tries to allocate another
object before that, so you could get a FATAL error and recovery could
fail.
We can fix both variants of the problem more fundamentally using
pre-existing page-level validation, if we just re-order some logic.
The new order of operations in the split-header case defers all memory
allocation based on xl_tot_len until we've read the following page. At
that point we know that its first few bytes are not recycled data, by
checking its xlp_pageaddr, and that its xlp_rem_len agrees with
xl_tot_len on the preceding page. That is strong evidence that
xl_tot_len was truly the start of a record that was logged.
This problem was most likely to occur on a standby, because
walreceiver.c recycles WAL files without zeroing out trailing regions of
each page. We should fix that too, but that wouldn't protect us from
rare crash scenarios where the trailing zeroes don't make it to disk.
Back-patch to 15. We might decide to back-patch a variant of this
to older branches with more study, but the symptoms there (bogus large
allocation) are less severe.
Author: Thomas Munro <thomas.munro@gmail.com>
Author: Michael Paquier <michael@paquier.xyz>
Reported-by: Alexander Lakhin <exclusion@gmail.com>
Reviewed-by: Noah Misch <noah@leadboat.com> (the idea, not the code)
Reviewed-by: Michael Paquier <michael@paquier.xyz>
Reviewed-by: Sergei Kornilov <sk@zsrv.org>
Discussion: https://postgr.es/m/17928-aa92416a70ff44a2%40postgresql.org
---
src/backend/access/transam/xlogreader.c | 123 ++++---
src/test/perl/PostgreSQL/Test/Utils.pm | 43 +++
src/test/recovery/meson.build | 1 +
src/test/recovery/t/038_end_of_wal.pl | 443 ++++++++++++++++++++++++
4 files changed, 554 insertions(+), 56 deletions(-)
create mode 100644 src/test/recovery/t/038_end_of_wal.pl
diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.cindex c9f9f6e98f..58654b746c 100644--- a/src/backend/access/transam/xlogreader.c+++ b/src/backend/access/transam/xlogreader.c@@ -192,6 +192,9 @@ XLogReaderFree(XLogReaderState *state)
* XLOG_BLCKSZ, and make sure it's at least 5*Max(BLCKSZ, XLOG_BLCKSZ) to start
* with. (That is enough for all "normal" records, but very large commit or
* abort records might need more space.)
+ *+ * Note: This routine should *never* be called for xl_tot_len until the header+ * of the record has been fully validated.
*/
static bool
allocate_recordbuf(XLogReaderState *state, uint32 reclength)
@@ -201,25 +204,6 @@ allocate_recordbuf(XLogReaderState *state, uint32 reclength)
newSize += XLOG_BLCKSZ - (newSize % XLOG_BLCKSZ);
newSize = Max(newSize, 5 * Max(BLCKSZ, XLOG_BLCKSZ));
-#ifndef FRONTEND-- /*- * Note that in much unlucky circumstances, the random data read from a- * recycled segment can cause this routine to be called with a size- * causing a hard failure at allocation. For a standby, this would cause- * the instance to stop suddenly with a hard failure, preventing it to- * retry fetching WAL from one of its sources which could allow it to move- * on with replay without a manual restart. If the data comes from a past- * recycled segment and is still valid, then the allocation may succeed- * but record checks are going to fail so this would be short-lived. If- * the allocation fails because of a memory shortage, then this is not a- * hard failure either per the guarantee given by MCXT_ALLOC_NO_OOM.- */- if (!AllocSizeIsValid(newSize))- return false;--#endif-
if (state->readRecordBuf)
pfree(state->readRecordBuf);
state->readRecordBuf =
@@ -669,41 +653,26 @@ restart:
}
else
{
- /* XXX: more validation should be done here */- if (total_len < SizeOfXLogRecord)- {- report_invalid_record(state,- "invalid record length at %X/%X: expected at least %u, got %u",- LSN_FORMAT_ARGS(RecPtr),- (uint32) SizeOfXLogRecord, total_len);- goto err;- }+ /* We'll validate the header once we have the next page. */
gotheader = false;
}
/*
- * Find space to decode this record. Don't allow oversized allocation if- * the caller requested nonblocking. Otherwise, we *have* to try to- * decode the record now because the caller has nothing else to do, so- * allow an oversized record to be palloc'd if that turns out to be- * necessary.+ * Try to find space to decode this record, if we can do so without+ * calling palloc. If we can't, we'll try again below after we've+ * validated that total_len isn't garbage bytes from a recycled WAL page.
*/
decoded = XLogReadRecordAlloc(state,
total_len,
- !nonblocking /* allow_oversized */ );- if (decoded == NULL)+ false /* allow_oversized */ );+ if (decoded == NULL && nonblocking)
{
/*
- * There is no space in the decode buffer. The caller should help- * with that problem by consuming some records.+ * There is no space in the circular decode buffer, and the caller is+ * only reading ahead. The caller should consume existing records to+ * make space.
*/
- if (nonblocking)- return XLREAD_WOULDBLOCK;-- /* We failed to allocate memory for an oversized record. */- report_invalid_record(state,- "out of memory while trying to decode a record of length %u", total_len);- goto err;+ return XLREAD_WOULDBLOCK;
}
len = XLOG_BLCKSZ - RecPtr % XLOG_BLCKSZ;
@@ -718,16 +687,11 @@ restart:
assembled = true;
/*
- * Enlarge readRecordBuf as needed.+ * We always have space for a couple of pages, enough to validate a+ * boundary-spanning record header.
*/
- if (total_len > state->readRecordBufSize &&- !allocate_recordbuf(state, total_len))- {- /* We treat this as a "bogus data" condition */- report_invalid_record(state, "record length %u at %X/%X too long",- total_len, LSN_FORMAT_ARGS(RecPtr));- goto err;- }+ Assert(state->readRecordBufSize >= XLOG_BLCKSZ * 2);+ Assert(state->readRecordBufSize >= len);
/* Copy the first fragment of the record from the first page. */
memcpy(state->readRecordBuf,
@@ -824,8 +788,35 @@ restart:
goto err;
gotheader = true;
}
- } while (gotlen < total_len);+ /*+ * We might need a bigger buffer. We have validated the record+ * header, in the case that it split over a page boundary. We've+ * also cross-checked total_len against xlp_rem_len on the second+ * page, and verified xlp_pageaddr on both.+ */+ if (total_len > state->readRecordBufSize)+ {+ char save_copy[XLOG_BLCKSZ * 2];++ /*+ * Save and restore the data we already had. It can't be more+ * than two pages.+ */+ Assert(gotlen <= lengthof(save_copy));+ Assert(gotlen <= state->readRecordBufSize);+ memcpy(save_copy, state->readRecordBuf, gotlen);+ if (!allocate_recordbuf(state, total_len))+ {+ /* We treat this as a "bogus data" condition */+ report_invalid_record(state, "record length %u at %X/%X too long",+ total_len, LSN_FORMAT_ARGS(RecPtr));+ goto err;+ }+ memcpy(state->readRecordBuf, save_copy, gotlen);+ buffer = state->readRecordBuf + gotlen;+ }+ } while (gotlen < total_len);
Assert(gotheader);
record = (XLogRecord *) state->readRecordBuf;
@@ -867,6 +858,28 @@ restart:
state->NextRecPtr -= XLogSegmentOffset(state->NextRecPtr, state->segcxt.ws_segsize);
}
+ /*+ * If we got here without a DecodedXLogRecord, it means we needed to+ * validate total_len before trusting it, but by now now we've done that.+ */+ if (decoded == NULL)+ {+ Assert(!nonblocking);+ decoded = XLogReadRecordAlloc(state,+ total_len,+ true /* allow_oversized */ );+ if (decoded == NULL)+ {+ /*+ * We failed to allocate memory for an oversized record. As+ * above, we currently treat this as a "bogus data" condition.+ */+ report_invalid_record(state,+ "out of memory while trying to decode a record of length %u", total_len);+ goto err;+ }+ }+
if (DecodeXLogRecord(state, decoded, record, RecPtr, &errormsg))
{
/* Record the location of the next record. */
@@ -895,8 +908,6 @@ restart:
state->decode_queue_head = decoded;
return XLREAD_SUCCESS;
}
- else- return XLREAD_FAIL;
err:
if (assembled)
diff --git a/src/test/perl/PostgreSQL/Test/Utils.pm b/src/test/perl/PostgreSQL/Test/Utils.pmindex 617caa022f..9de34a2260 100644--- a/src/test/perl/PostgreSQL/Test/Utils.pm+++ b/src/test/perl/PostgreSQL/Test/Utils.pm@@ -71,6 +71,7 @@ our @EXPORT = qw(
chmod_recursive
check_pg_config
dir_symlink
+ scan_server_header
system_or_bail
system_log
run_log
@@ -702,6 +703,48 @@ sub chmod_recursive
=pod
+=item scan_server_header(header_path, regexp)++Returns an array that stores all the matches of the given regular expression+within the PostgreSQL installation's C<header_path>. This can be used to+retrieve specific value patterns from the installation's header files.++=cut++sub scan_server_header+{+ my ($header_path, $regexp) = @_;++ my ($stdout, $stderr);+ my $result = IPC::Run::run [ 'pg_config', '--includedir-server' ], '>',+ \$stdout, '2>', \$stderr+ or die "could not execute pg_config";+ chomp($stdout);+ $stdout =~ s/\r$//;++ open my $header_h, '<', "$stdout/$header_path" or die "$!";++ my @match = undef;+ while (<$header_h>)+ {+ my $line = $_;++ if ($line =~ /^$regexp/)+ {+ # Found match, so store all the results.+ @match = @{^CAPTURE};+ last;+ }+ }++ close $header_h;+ die "could not find match in header $header_path\n"+ unless @match;+ return @match;+}++=pod+
=item check_pg_config(regexp)
Return the number of matches of the given regular expression
diff --git a/src/test/recovery/meson.build b/src/test/recovery/meson.buildindex e7328e4894..10407668d4 100644--- a/src/test/recovery/meson.build+++ b/src/test/recovery/meson.build@@ -43,6 +43,7 @@ tests += {
't/035_standby_logical_decoding.pl',
't/036_truncated_dropped.pl',
't/037_invalid_database.pl',
+ 't/038_end_of_wal.pl',
],
},
}
diff --git a/src/test/recovery/t/038_end_of_wal.pl b/src/test/recovery/t/038_end_of_wal.plnew file mode 100644index 0000000000..aa5eec7c03--- /dev/null+++ b/src/test/recovery/t/038_end_of_wal.pl@@ -0,0 +1,443 @@+# Copyright (c) 2023, PostgreSQL Global Development Group+#+# Test detecting end of WAL replay. This test suite generates fake+# WAL records able to trigger various failure scenarios at replay.++use strict;+use warnings;+use PostgreSQL::Test::Cluster;+use PostgreSQL::Test::Utils;+use Test::More;+use Fcntl qw(SEEK_SET);++use integer; # causes / operator to use integer math++# Header size of record header.+my $RECORD_HEADER_SIZE = 24;++# Fields retrieved from code headers.+my @scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLOG_PAGE_MAGIC\s+(\w+)');+my $XLP_PAGE_MAGIC = hex($scan_result[0]);+@scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLP_FIRST_IS_CONTRECORD\s+(\w+)');+my $XLP_FIRST_IS_CONTRECORD = hex($scan_result[0]);++# Values queried from the server+my $WAL_SEGMENT_SIZE;+my $WAL_BLOCK_SIZE;+my $TLI;++# Build path of a WAL segment.+sub wal_segment_path+{+ my $node = shift;+ my $tli = shift;+ my $segment = shift;+ my $wal_path =+ sprintf("%s/pg_wal/%08X%08X%08X", $node->data_dir, $tli, 0, $segment);+ return $wal_path;+}++# Calculate from a LSN (in bytes) its segment number and its offset.+sub lsn_to_segment_and_offset+{+ my $lsn = shift;+ return ($lsn / $WAL_SEGMENT_SIZE, $lsn % $WAL_SEGMENT_SIZE);+}++# Write some arbitrary data in WAL for the given segment at offset.+# This should be called while the cluster is offline.+sub write_wal+{+ my $node = shift;+ my $tli = shift;+ my $lsn = shift;+ my $data = shift;++ my ($segment, $offset) = lsn_to_segment_and_offset($lsn);+ my $path = wal_segment_path($node, $tli, $segment);++ open my $fh, "+<:raw", $path or die;+ seek($fh, $offset, SEEK_SET) or die;+ print $fh $data;+ close $fh;+}++# Emit a WAL record of arbitrary size. Returns the end LSN of the+# record inserted, in bytes.+sub emit_message+{+ my $node = shift;+ my $size = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT pg_logical_emit_message(true, '', repeat('a', $size)) - '0/0'"+ ));+}++# Get the current insert LSN of a node, in bytes.+sub get_insert_lsn+{+ my $node = shift;+ return int(+ $node->safe_psql(+ 'postgres', "SELECT pg_current_wal_insert_lsn() - '0/0'"));+}++# Get GUC value, converted to an int.+sub get_int_setting+{+ my $node = shift;+ my $name = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT setting FROM pg_settings WHERE name = '$name'"));+}++sub start_of_page+{+ my $lsn = shift;+ return $lsn & ~($WAL_BLOCK_SIZE - 1);+}++sub start_of_next_page+{+ my $lsn = shift;+ return start_of_page($lsn) + $WAL_BLOCK_SIZE;+}++# Build a fake WAL record header based on the data given by the caller.+# This needs to follow the format of the C structure XLogRecord. To+# be inserted with write_wal().+sub build_record_header+{+ my $xl_tot_len = shift;+ my $xl_xid = shift || 0;+ my $xl_prev = shift || 0;+ my $xl_info = shift || 0;+ my $xl_rmid = shift || 0;+ my $xl_crc = shift || 0;++ # This needs to follow the structure XLogRecord:+ # I for xl_tot_len+ # I for xl_xid+ # Q for xl_prev+ # C for xl_info+ # C for xl_rmid+ # BB for two bytes of padding+ # I for xl_crc+ return pack("IIQCCBBI",+ $xl_tot_len, $xl_xid, $xl_prev, $xl_info, $xl_rmid, 0, 0, $xl_crc);+}++# Build a fake WAL page header, based on the data given by the caller+# This needs to follow the format of the C structure XLogPageHeaderData.+# To be inserted with write_wal().+sub build_page_header+{+ my $xlp_magic = shift;+ my $xlp_info = shift || 0;+ my $xlp_tli = shift || 0;+ my $xlp_pageaddr = shift || 0;+ my $xlp_rem_len = shift || 0;++ # This needs to follow the structure XLogPageHeaderData:+ # S for xlp_magic+ # S for xlp_info+ # I for xlp_tli+ # Q for xlp_pageaddr+ # I for xlp_rem_len+ return pack("SSIQI",+ $xlp_magic, $xlp_info, $xlp_tli, $xlp_pageaddr, $xlp_rem_len);+}++# Make sure we are far away enough from the end of a page that we could insert+# a couple of small records. This inserts a few records of a fixed size, until+# the threshold gets close enough to the end of the WAL page inserting records+# to.+sub advance_out_of_record_splitting_zone+{+ my $node = shift;++ my $page_threshold = $WAL_BLOCK_SIZE / 4;+ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ while ($page_offset >= $WAL_BLOCK_SIZE - $page_threshold)+ {+ $end_lsn = emit_message($node, $page_threshold);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }+ return $end_lsn;+}++# Advance so close to the end of a page that an XLogRecordHeader would not+# fit on it.+sub advance_to_record_splitting_zone+{+ my $node = shift;++ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Get fairly close to the end of a page in big steps+ while ($page_offset <= $WAL_BLOCK_SIZE - 512)+ {+ $end_lsn = emit_message($node, $WAL_BLOCK_SIZE - $page_offset - 256);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }++ # Calibrate our message size so that we can get closer 8 bytes at+ # a time.+ my $message_size = $WAL_BLOCK_SIZE - 80;+ while ($page_offset <= $WAL_BLOCK_SIZE - $RECORD_HEADER_SIZE)+ {+ $end_lsn = emit_message($node, $message_size);++ my $old_offset = $page_offset;+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Adjust the message size until it causes 8 bytes changes in+ # offset, enough to be able to split a record header.+ my $delta = $page_offset - $old_offset;+ if ($delta > 8)+ {+ $message_size -= 8;+ }+ elsif ($delta <= 0)+ {+ $message_size += 8;+ }+ }+ return $end_lsn;+}++# Setup a new node. The configuration chosen here minimizes the number+# of arbitrary records that could get generated in a cluster. Enlarging+# checkpoint_timeout avoids noise with checkpoint activity. wal_level+# set to "minimal" avoids random standby snapshot records. Autovacuum+# could also trigger randomly, generating random WAL activity of its own.+my $node = PostgreSQL::Test::Cluster->new("node");+$node->init;+$node->append_conf(+ 'postgresql.conf',+ q[wal_level = minimal+ autovacuum = off+ checkpoint_timeout = '30min'+]);+$node->start;+$node->safe_psql('postgres', "CREATE TABLE t AS SELECT 42");++$WAL_SEGMENT_SIZE = get_int_setting($node, 'wal_segment_size');+$WAL_BLOCK_SIZE = get_int_setting($node, 'wal_block_size');+$TLI = $node->safe_psql('postgres',+ "SELECT timeline_id FROM pg_control_checkpoint();");++my $end_lsn;+my $prev_lsn;++###########################################################################+note "Single-page end-of-WAL detection";+###########################################################################++# xl_tot_len is 0 (a common case, we hit trailing zeroes).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+my $log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: expected at least 24, got 0", $log_size+ ),+ "xl_tot_len zero");++# xl_tot_len is < 24 (presumably recycled garbage).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn, build_record_header(23));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: expected at least 24, got 23",+ $log_size),+ "xl_tot_len short");++# Need more pages, but xl_prev check fails first.+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "record with incorrect prev-link 0/DEADBEEF at .*", $log_size),+ "xl_prev bad");++# xl_crc check fails.+advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 10);+$node->stop('immediate');+# Corrupt a byte in that record, breaking its CRC.+write_wal($node, $TLI, $end_lsn - 8, '!');+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "incorrect resource manager data checksum in record at .*", $log_size+ ),+ "xl_crc bad");+++###########################################################################+note "Multi-page end-of-WAL detection, header is not split";+###########################################################################++# This series of tests requires a valid xl_prev set in the record header+# written to WAL.++# Good xl_prev, we hit zero page next (zero magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 .* LSN .*", $log_size),+ "xlp_magic zero");++# Good xl_prev, we hit garbage page next (bad magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(0xcafe, 0, 1, 0));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number CAFE .* LSN .*", $log_size),+ "xlp_magic bad");++# Good xl_prev, we hit typical recycled page (good xlp_magic, bad+# xlp_pageaddr).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD in .*, LSN .*,", $log_size),+ "xlp_pageaddr bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but bogus xlp_info.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, 0x1234, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid info bits 1234 in .*, LSN .*,", $log_size),+ "xlp_info bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but xlp_info doesn't mention+# continuation record.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("there is no contrecord flag at .*", $log_size),+ "xlp_info lacks XLP_FIRST_IS_CONTRECORD");++# Good xl_prev, xlp_magic, xlp_pageaddr, xlp_info but xlp_rem_len doesn't add+# up.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 .* at .*", $log_size),+ "xlp_rem_len bad");+++###########################################################################+note "Multi-page, but header is split, so page checks are done first";+###########################################################################++# xlp_prev is bad and xl_tot_len is too big, but we'll check xlp_magic first.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 .* LSN .*", $log_size),+ "xlp_magic zero (split record header)");++# And we'll also check xlp_pageaddr before any header checks.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD in .*, LSN .*,", $log_size),+ "xlp_pageaddr bad (split record header)");++# We'll also discover that xlp_rem_len doesn't add up before any+# header checks,+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 .* at .*", $log_size),+ "xlp_rem_len bad (split record header)");++done_testing();--
2.40.1
[text/plain] v6-0001-Don-t-trust-unvalidated-xl_tot_len.patch.15 (24.0K, ../ZP+4YYrPZk0GFlc3@paquier.xyz/4-v6-0001-Don-t-trust-unvalidated-xl_tot_len.patch.15)
download | inline diff:
From 8a75b763a8c477d1cb62a7e52bb825894a3bcdce Mon Sep 17 00:00:00 2001
From: Thomas Munro <thomas.munro@gmail.com>
Date: Mon, 14 Aug 2023 17:06:42 +1200
Subject: [PATCH v6] Don't trust unvalidated xl_tot_len.
xl_tot_len comes first in a WAL record. Usually we don't trust it to be
the true length until we've validated the record header. If the record
header was split across two pages, previously we wouldn't do the
validation until after we'd already tried to allocate enough memory to
hold the record, which was bad because it might actually be garbage
bytes from a recycled WAL file, so we could try to allocate a lot of
memory. Release 15 made it worse.
Since 70b4f82a4b5, we'd at least generate an end-of-WAL condition if the
garbage 4 byte value happened to be > 1GB, but we'd still try to
allocate up to 1GB of memory bogusly otherwise. That was an
improvement, but unfortunately release 15 tries to allocate another
object before that, so you could get a FATAL error and recovery could
fail.
We can fix both variants of the problem more fundamentally using
pre-existing page-level validation, if we just re-order some logic.
The new order of operations in the split-header case defers all memory
allocation based on xl_tot_len until we've read the following page. At
that point we know that its first few bytes are not recycled data, by
checking its xlp_pageaddr, and that its xlp_rem_len agrees with
xl_tot_len on the preceding page. That is strong evidence that
xl_tot_len was truly the start of a record that was logged.
This problem was most likely to occur on a standby, because
walreceiver.c recycles WAL files without zeroing out trailing regions of
each page. We should fix that too, but that wouldn't protect us from
rare crash scenarios where the trailing zeroes don't make it to disk.
Back-patch to 15. We might decide to back-patch a variant of this
to older branches with more study, but the symptoms there (bogus large
allocation) are less severe.
Author: Thomas Munro <thomas.munro@gmail.com>
Author: Michael Paquier <michael@paquier.xyz>
Reported-by: Alexander Lakhin <exclusion@gmail.com>
Reviewed-by: Noah Misch <noah@leadboat.com> (the idea, not the code)
Reviewed-by: Michael Paquier <michael@paquier.xyz>
Reviewed-by: Sergei Kornilov <sk@zsrv.org>
Discussion: https://postgr.es/m/17928-aa92416a70ff44a2%40postgresql.org
---
src/backend/access/transam/xlogreader.c | 123 ++++---
src/test/perl/PostgreSQL/Test/Utils.pm | 43 +++
src/test/recovery/t/038_end_of_wal.pl | 443 ++++++++++++++++++++++++
3 files changed, 553 insertions(+), 56 deletions(-)
create mode 100644 src/test/recovery/t/038_end_of_wal.pl
diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.cindex 03fad82bc1..4b48abfa05 100644--- a/src/backend/access/transam/xlogreader.c+++ b/src/backend/access/transam/xlogreader.c@@ -192,6 +192,9 @@ XLogReaderFree(XLogReaderState *state)
* XLOG_BLCKSZ, and make sure it's at least 5*Max(BLCKSZ, XLOG_BLCKSZ) to start
* with. (That is enough for all "normal" records, but very large commit or
* abort records might need more space.)
+ *+ * Note: This routine should *never* be called for xl_tot_len until the header+ * of the record has been fully validated.
*/
static bool
allocate_recordbuf(XLogReaderState *state, uint32 reclength)
@@ -201,25 +204,6 @@ allocate_recordbuf(XLogReaderState *state, uint32 reclength)
newSize += XLOG_BLCKSZ - (newSize % XLOG_BLCKSZ);
newSize = Max(newSize, 5 * Max(BLCKSZ, XLOG_BLCKSZ));
-#ifndef FRONTEND-- /*- * Note that in much unlucky circumstances, the random data read from a- * recycled segment can cause this routine to be called with a size- * causing a hard failure at allocation. For a standby, this would cause- * the instance to stop suddenly with a hard failure, preventing it to- * retry fetching WAL from one of its sources which could allow it to move- * on with replay without a manual restart. If the data comes from a past- * recycled segment and is still valid, then the allocation may succeed- * but record checks are going to fail so this would be short-lived. If- * the allocation fails because of a memory shortage, then this is not a- * hard failure either per the guarantee given by MCXT_ALLOC_NO_OOM.- */- if (!AllocSizeIsValid(newSize))- return false;--#endif-
if (state->readRecordBuf)
pfree(state->readRecordBuf);
state->readRecordBuf =
@@ -667,41 +651,26 @@ restart:
}
else
{
- /* XXX: more validation should be done here */- if (total_len < SizeOfXLogRecord)- {- report_invalid_record(state,- "invalid record length at %X/%X: wanted %u, got %u",- LSN_FORMAT_ARGS(RecPtr),- (uint32) SizeOfXLogRecord, total_len);- goto err;- }+ /* We'll validate the header once we have the next page. */
gotheader = false;
}
/*
- * Find space to decode this record. Don't allow oversized allocation if- * the caller requested nonblocking. Otherwise, we *have* to try to- * decode the record now because the caller has nothing else to do, so- * allow an oversized record to be palloc'd if that turns out to be- * necessary.+ * Try to find space to decode this record, if we can do so without+ * calling palloc. If we can't, we'll try again below after we've+ * validated that total_len isn't garbage bytes from a recycled WAL page.
*/
decoded = XLogReadRecordAlloc(state,
total_len,
- !nonblocking /* allow_oversized */ );- if (decoded == NULL)+ false /* allow_oversized */ );+ if (decoded == NULL && nonblocking)
{
/*
- * There is no space in the decode buffer. The caller should help- * with that problem by consuming some records.+ * There is no space in the circular decode buffer, and the caller is+ * only reading ahead. The caller should consume existing records to+ * make space.
*/
- if (nonblocking)- return XLREAD_WOULDBLOCK;-- /* We failed to allocate memory for an oversized record. */- report_invalid_record(state,- "out of memory while trying to decode a record of length %u", total_len);- goto err;+ return XLREAD_WOULDBLOCK;
}
len = XLOG_BLCKSZ - RecPtr % XLOG_BLCKSZ;
@@ -716,16 +685,11 @@ restart:
assembled = true;
/*
- * Enlarge readRecordBuf as needed.+ * We always have space for a couple of pages, enough to validate a+ * boundary-spanning record header.
*/
- if (total_len > state->readRecordBufSize &&- !allocate_recordbuf(state, total_len))- {- /* We treat this as a "bogus data" condition */- report_invalid_record(state, "record length %u at %X/%X too long",- total_len, LSN_FORMAT_ARGS(RecPtr));- goto err;- }+ Assert(state->readRecordBufSize >= XLOG_BLCKSZ * 2);+ Assert(state->readRecordBufSize >= len);
/* Copy the first fragment of the record from the first page. */
memcpy(state->readRecordBuf,
@@ -822,8 +786,35 @@ restart:
goto err;
gotheader = true;
}
- } while (gotlen < total_len);+ /*+ * We might need a bigger buffer. We have validated the record+ * header, in the case that it split over a page boundary. We've+ * also cross-checked total_len against xlp_rem_len on the second+ * page, and verified xlp_pageaddr on both.+ */+ if (total_len > state->readRecordBufSize)+ {+ char save_copy[XLOG_BLCKSZ * 2];++ /*+ * Save and restore the data we already had. It can't be more+ * than two pages.+ */+ Assert(gotlen <= lengthof(save_copy));+ Assert(gotlen <= state->readRecordBufSize);+ memcpy(save_copy, state->readRecordBuf, gotlen);+ if (!allocate_recordbuf(state, total_len))+ {+ /* We treat this as a "bogus data" condition */+ report_invalid_record(state, "record length %u at %X/%X too long",+ total_len, LSN_FORMAT_ARGS(RecPtr));+ goto err;+ }+ memcpy(state->readRecordBuf, save_copy, gotlen);+ buffer = state->readRecordBuf + gotlen;+ }+ } while (gotlen < total_len);
Assert(gotheader);
record = (XLogRecord *) state->readRecordBuf;
@@ -865,6 +856,28 @@ restart:
state->NextRecPtr -= XLogSegmentOffset(state->NextRecPtr, state->segcxt.ws_segsize);
}
+ /*+ * If we got here without a DecodedXLogRecord, it means we needed to+ * validate total_len before trusting it, but by now now we've done that.+ */+ if (decoded == NULL)+ {+ Assert(!nonblocking);+ decoded = XLogReadRecordAlloc(state,+ total_len,+ true /* allow_oversized */ );+ if (decoded == NULL)+ {+ /*+ * We failed to allocate memory for an oversized record. As+ * above, we currently treat this as a "bogus data" condition.+ */+ report_invalid_record(state,+ "out of memory while trying to decode a record of length %u", total_len);+ goto err;+ }+ }+
if (DecodeXLogRecord(state, decoded, record, RecPtr, &errormsg))
{
/* Record the location of the next record. */
@@ -893,8 +906,6 @@ restart:
state->decode_queue_head = decoded;
return XLREAD_SUCCESS;
}
- else- return XLREAD_FAIL;
err:
if (assembled)
diff --git a/src/test/perl/PostgreSQL/Test/Utils.pm b/src/test/perl/PostgreSQL/Test/Utils.pmindex 4e18730dd0..4fd2e48ca9 100644--- a/src/test/perl/PostgreSQL/Test/Utils.pm+++ b/src/test/perl/PostgreSQL/Test/Utils.pm@@ -69,6 +69,7 @@ our @EXPORT = qw(
chmod_recursive
check_pg_config
dir_symlink
+ scan_server_header
system_or_bail
system_log
run_log
@@ -672,6 +673,48 @@ sub chmod_recursive
=pod
+=item scan_server_header(header_path, regexp)++Returns an array that stores all the matches of the given regular expression+within the PostgreSQL installation's C<header_path>. This can be used to+retrieve specific value patterns from the installation's header files.++=cut++sub scan_server_header+{+ my ($header_path, $regexp) = @_;++ my ($stdout, $stderr);+ my $result = IPC::Run::run [ 'pg_config', '--includedir-server' ], '>',+ \$stdout, '2>', \$stderr+ or die "could not execute pg_config";+ chomp($stdout);+ $stdout =~ s/\r$//;++ open my $header_h, '<', "$stdout/$header_path" or die "$!";++ my @match = undef;+ while (<$header_h>)+ {+ my $line = $_;++ if ($line =~ /^$regexp/)+ {+ # Found match, so store all the results.+ @match = @{^CAPTURE};+ last;+ }+ }++ close $header_h;+ die "could not find match in header $header_path\n"+ unless @match;+ return @match;+}++=pod+
=item check_pg_config(regexp)
Return the number of matches of the given regular expression
diff --git a/src/test/recovery/t/038_end_of_wal.pl b/src/test/recovery/t/038_end_of_wal.plnew file mode 100644index 0000000000..779a195a7d--- /dev/null+++ b/src/test/recovery/t/038_end_of_wal.pl@@ -0,0 +1,443 @@+# Copyright (c) 2023, PostgreSQL Global Development Group+#+# Test detecting end of WAL replay. This test suite generates fake+# WAL records able to trigger various failure scenarios at replay.++use strict;+use warnings;+use PostgreSQL::Test::Cluster;+use PostgreSQL::Test::Utils;+use Test::More;+use Fcntl qw(SEEK_SET);++use integer; # causes / operator to use integer math++# Header size of record header.+my $RECORD_HEADER_SIZE = 24;++# Fields retrieved from code headers.+my @scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLOG_PAGE_MAGIC\s+(\w+)');+my $XLP_PAGE_MAGIC = hex($scan_result[0]);+@scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLP_FIRST_IS_CONTRECORD\s+(\w+)');+my $XLP_FIRST_IS_CONTRECORD = hex($scan_result[0]);++# Values queried from the server+my $WAL_SEGMENT_SIZE;+my $WAL_BLOCK_SIZE;+my $TLI;++# Build path of a WAL segment.+sub wal_segment_path+{+ my $node = shift;+ my $tli = shift;+ my $segment = shift;+ my $wal_path =+ sprintf("%s/pg_wal/%08X%08X%08X", $node->data_dir, $tli, 0, $segment);+ return $wal_path;+}++# Calculate from a LSN (in bytes) its segment number and its offset.+sub lsn_to_segment_and_offset+{+ my $lsn = shift;+ return ($lsn / $WAL_SEGMENT_SIZE, $lsn % $WAL_SEGMENT_SIZE);+}++# Write some arbitrary data in WAL for the given segment at offset.+# This should be called while the cluster is offline.+sub write_wal+{+ my $node = shift;+ my $tli = shift;+ my $lsn = shift;+ my $data = shift;++ my ($segment, $offset) = lsn_to_segment_and_offset($lsn);+ my $path = wal_segment_path($node, $tli, $segment);++ open my $fh, "+<:raw", $path or die;+ seek($fh, $offset, SEEK_SET) or die;+ print $fh $data;+ close $fh;+}++# Emit a WAL record of arbitrary size. Returns the end LSN of the+# record inserted, in bytes.+sub emit_message+{+ my $node = shift;+ my $size = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT pg_logical_emit_message(true, '', repeat('a', $size)) - '0/0'"+ ));+}++# Get the current insert LSN of a node, in bytes.+sub get_insert_lsn+{+ my $node = shift;+ return int(+ $node->safe_psql(+ 'postgres', "SELECT pg_current_wal_insert_lsn() - '0/0'"));+}++# Get GUC value, converted to an int.+sub get_int_setting+{+ my $node = shift;+ my $name = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT setting FROM pg_settings WHERE name = '$name'"));+}++sub start_of_page+{+ my $lsn = shift;+ return $lsn & ~($WAL_BLOCK_SIZE - 1);+}++sub start_of_next_page+{+ my $lsn = shift;+ return start_of_page($lsn) + $WAL_BLOCK_SIZE;+}++# Build a fake WAL record header based on the data given by the caller.+# This needs to follow the format of the C structure XLogRecord. To+# be inserted with write_wal().+sub build_record_header+{+ my $xl_tot_len = shift;+ my $xl_xid = shift || 0;+ my $xl_prev = shift || 0;+ my $xl_info = shift || 0;+ my $xl_rmid = shift || 0;+ my $xl_crc = shift || 0;++ # This needs to follow the structure XLogRecord:+ # I for xl_tot_len+ # I for xl_xid+ # Q for xl_prev+ # C for xl_info+ # C for xl_rmid+ # BB for two bytes of padding+ # I for xl_crc+ return pack("IIQCCBBI",+ $xl_tot_len, $xl_xid, $xl_prev, $xl_info, $xl_rmid, 0, 0, $xl_crc);+}++# Build a fake WAL page header, based on the data given by the caller+# This needs to follow the format of the C structure XLogPageHeaderData.+# To be inserted with write_wal().+sub build_page_header+{+ my $xlp_magic = shift;+ my $xlp_info = shift || 0;+ my $xlp_tli = shift || 0;+ my $xlp_pageaddr = shift || 0;+ my $xlp_rem_len = shift || 0;++ # This needs to follow the structure XLogPageHeaderData:+ # S for xlp_magic+ # S for xlp_info+ # I for xlp_tli+ # Q for xlp_pageaddr+ # I for xlp_rem_len+ return pack("SSIQI",+ $xlp_magic, $xlp_info, $xlp_tli, $xlp_pageaddr, $xlp_rem_len);+}++# Make sure we are far away enough from the end of a page that we could insert+# a couple of small records. This inserts a few records of a fixed size, until+# the threshold gets close enough to the end of the WAL page inserting records+# to.+sub advance_out_of_record_splitting_zone+{+ my $node = shift;++ my $page_threshold = $WAL_BLOCK_SIZE / 4;+ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ while ($page_offset >= $WAL_BLOCK_SIZE - $page_threshold)+ {+ $end_lsn = emit_message($node, $page_threshold);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }+ return $end_lsn;+}++# Advance so close to the end of a page that an XLogRecordHeader would not+# fit on it.+sub advance_to_record_splitting_zone+{+ my $node = shift;++ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Get fairly close to the end of a page in big steps+ while ($page_offset <= $WAL_BLOCK_SIZE - 512)+ {+ $end_lsn = emit_message($node, $WAL_BLOCK_SIZE - $page_offset - 256);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }++ # Calibrate our message size so that we can get closer 8 bytes at+ # a time.+ my $message_size = $WAL_BLOCK_SIZE - 80;+ while ($page_offset <= $WAL_BLOCK_SIZE - $RECORD_HEADER_SIZE)+ {+ $end_lsn = emit_message($node, $message_size);++ my $old_offset = $page_offset;+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Adjust the message size until it causes 8 bytes changes in+ # offset, enough to be able to split a record header.+ my $delta = $page_offset - $old_offset;+ if ($delta > 8)+ {+ $message_size -= 8;+ }+ elsif ($delta <= 0)+ {+ $message_size += 8;+ }+ }+ return $end_lsn;+}++# Setup a new node. The configuration chosen here minimizes the number+# of arbitrary records that could get generated in a cluster. Enlarging+# checkpoint_timeout avoids noise with checkpoint activity. wal_level+# set to "minimal" avoids random standby snapshot records. Autovacuum+# could also trigger randomly, generating random WAL activity of its own.+my $node = PostgreSQL::Test::Cluster->new("node");+$node->init;+$node->append_conf(+ 'postgresql.conf',+ q[wal_level = minimal+ autovacuum = off+ checkpoint_timeout = '30min'+]);+$node->start;+$node->safe_psql('postgres', "CREATE TABLE t AS SELECT 42");++$WAL_SEGMENT_SIZE = get_int_setting($node, 'wal_segment_size');+$WAL_BLOCK_SIZE = get_int_setting($node, 'wal_block_size');+$TLI = $node->safe_psql('postgres',+ "SELECT timeline_id FROM pg_control_checkpoint();");++my $end_lsn;+my $prev_lsn;++###########################################################################+note "Single-page end-of-WAL detection";+###########################################################################++# xl_tot_len is 0 (a common case, we hit trailing zeroes).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+my $log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: wanted 24, got 0", $log_size+ ),+ "xl_tot_len zero");++# xl_tot_len is < 24 (presumably recycled garbage).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn, build_record_header(23));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: wanted 24, got 23",+ $log_size),+ "xl_tot_len short");++# Need more pages, but xl_prev check fails first.+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "record with incorrect prev-link 0/DEADBEEF at .*", $log_size),+ "xl_prev bad");++# xl_crc check fails.+advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 10);+$node->stop('immediate');+# Corrupt a byte in that record, breaking its CRC.+write_wal($node, $TLI, $end_lsn - 8, '!');+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "incorrect resource manager data checksum in record at .*", $log_size+ ),+ "xl_crc bad");+++###########################################################################+note "Multi-page end-of-WAL detection, header is not split";+###########################################################################++# This series of tests requires a valid xl_prev set in the record header+# written to WAL.++# Good xl_prev, we hit zero page next (zero magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 ", $log_size),+ "xlp_magic zero");++# Good xl_prev, we hit garbage page next (bad magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(0xcafe, 0, 1, 0));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number CAFE ", $log_size),+ "xlp_magic bad");++# Good xl_prev, we hit typical recycled page (good xlp_magic, bad+# xlp_pageaddr).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD ", $log_size),+ "xlp_pageaddr bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but bogus xlp_info.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, 0x1234, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid info bits 1234 ", $log_size),+ "xlp_info bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but xlp_info doesn't mention+# continuation record.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("there is no contrecord flag at .*", $log_size),+ "xlp_info lacks XLP_FIRST_IS_CONTRECORD");++# Good xl_prev, xlp_magic, xlp_pageaddr, xlp_info but xlp_rem_len doesn't add+# up.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 .* at .*", $log_size),+ "xlp_rem_len bad");+++###########################################################################+note "Multi-page, but header is split, so page checks are done first";+###########################################################################++# xlp_prev is bad and xl_tot_len is too big, but we'll check xlp_magic first.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 ", $log_size),+ "xlp_magic zero (split record header)");++# And we'll also check xlp_pageaddr before any header checks.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD ", $log_size),+ "xlp_pageaddr bad (split record header)");++# We'll also discover that xlp_rem_len doesn't add up before any+# header checks,+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 .* at .*", $log_size),+ "xlp_rem_len bad (split record header)");++done_testing();--
2.40.1
[text/plain] v6-0001-Don-t-trust-unvalidated-xl_tot_len.patch.14 (21.7K, ../ZP+4YYrPZk0GFlc3@paquier.xyz/5-v6-0001-Don-t-trust-unvalidated-xl_tot_len.patch.14)
download | inline diff:
From a71a7beb88405e24ee9dd3bc616dc26808845bbe Mon Sep 17 00:00:00 2001
From: Thomas Munro <thomas.munro@gmail.com>
Date: Mon, 14 Aug 2023 17:06:42 +1200
Subject: [PATCH v6] Don't trust unvalidated xl_tot_len.
xl_tot_len comes first in a WAL record. Usually we don't trust it to be
the true length until we've validated the record header. If the record
header was split across two pages, previously we wouldn't do the
validation until after we'd already tried to allocate enough memory to
hold the record, which was bad because it might actually be garbage
bytes from a recycled WAL file, so we could try to allocate a lot of
memory. Release 15 made it worse.
Since 70b4f82a4b5, we'd at least generate an end-of-WAL condition if the
garbage 4 byte value happened to be > 1GB, but we'd still try to
allocate up to 1GB of memory bogusly otherwise. That was an
improvement, but unfortunately release 15 tries to allocate another
object before that, so you could get a FATAL error and recovery could
fail.
We can fix both variants of the problem more fundamentally using
pre-existing page-level validation, if we just re-order some logic.
The new order of operations in the split-header case defers all memory
allocation based on xl_tot_len until we've read the following page. At
that point we know that its first few bytes are not recycled data, by
checking its xlp_pageaddr, and that its xlp_rem_len agrees with
xl_tot_len on the preceding page. That is strong evidence that
xl_tot_len was truly the start of a record that was logged.
This problem was most likely to occur on a standby, because
walreceiver.c recycles WAL files without zeroing out trailing regions of
each page. We should fix that too, but that wouldn't protect us from
rare crash scenarios where the trailing zeroes don't make it to disk.
Back-patch to 15. We might decide to back-patch a variant of this
to older branches with more study, but the symptoms there (bogus large
allocation) are less severe.
Author: Thomas Munro <thomas.munro@gmail.com>
Author: Michael Paquier <michael@paquier.xyz>
Reported-by: Alexander Lakhin <exclusion@gmail.com>
Reviewed-by: Noah Misch <noah@leadboat.com> (the idea, not the code)
Reviewed-by: Michael Paquier <michael@paquier.xyz>
Reviewed-by: Sergei Kornilov <sk@zsrv.org>
Discussion: https://postgr.es/m/17928-aa92416a70ff44a2%40postgresql.org
---
src/backend/access/transam/xlogreader.c | 75 ++--
src/test/perl/TestLib.pm | 43 +++
src/test/recovery/t/038_end_of_wal.pl | 449 ++++++++++++++++++++++++
3 files changed, 529 insertions(+), 38 deletions(-)
create mode 100644 src/test/recovery/t/038_end_of_wal.pl
diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.cindex d797d9d508..9d74507dbe 100644--- a/src/backend/access/transam/xlogreader.c+++ b/src/backend/access/transam/xlogreader.c@@ -168,6 +168,9 @@ XLogReaderFree(XLogReaderState *state)
* XLOG_BLCKSZ, and make sure it's at least 5*Max(BLCKSZ, XLOG_BLCKSZ) to start
* with. (That is enough for all "normal" records, but very large commit or
* abort records might need more space.)
+ *+ * Note: This routine should *never* be called for xl_tot_len until the header+ * of the record has been fully validated.
*/
static bool
allocate_recordbuf(XLogReaderState *state, uint32 reclength)
@@ -177,25 +180,6 @@ allocate_recordbuf(XLogReaderState *state, uint32 reclength)
newSize += XLOG_BLCKSZ - (newSize % XLOG_BLCKSZ);
newSize = Max(newSize, 5 * Max(BLCKSZ, XLOG_BLCKSZ));
-#ifndef FRONTEND-- /*- * Note that in much unlucky circumstances, the random data read from a- * recycled segment can cause this routine to be called with a size- * causing a hard failure at allocation. For a standby, this would cause- * the instance to stop suddenly with a hard failure, preventing it to- * retry fetching WAL from one of its sources which could allow it to move- * on with replay without a manual restart. If the data comes from a past- * recycled segment and is still valid, then the allocation may succeed- * but record checks are going to fail so this would be short-lived. If- * the allocation fails because of a memory shortage, then this is not a- * hard failure either per the guarantee given by MCXT_ALLOC_NO_OOM.- */- if (!AllocSizeIsValid(newSize))- return false;--#endif-
if (state->readRecordBuf)
pfree(state->readRecordBuf);
state->readRecordBuf =
@@ -396,15 +380,7 @@ restart:
}
else
{
- /* XXX: more validation should be done here */- if (total_len < SizeOfXLogRecord)- {- report_invalid_record(state,- "invalid record length at %X/%X: wanted %u, got %u",- LSN_FORMAT_ARGS(RecPtr),- (uint32) SizeOfXLogRecord, total_len);- goto err;- }+ /* We'll validate the header once we have the next page. */
gotheader = false;
}
@@ -420,16 +396,11 @@ restart:
assembled = true;
/*
- * Enlarge readRecordBuf as needed.+ * We always have space for a couple of pages, enough to validate a+ * boundary-spanning record header.
*/
- if (total_len > state->readRecordBufSize &&- !allocate_recordbuf(state, total_len))- {- /* We treat this as a "bogus data" condition */- report_invalid_record(state, "record length %u at %X/%X too long",- total_len, LSN_FORMAT_ARGS(RecPtr));- goto err;- }+ Assert(state->readRecordBufSize >= XLOG_BLCKSZ * 2);+ Assert(state->readRecordBufSize >= len);
/* Copy the first fragment of the record from the first page. */
memcpy(state->readRecordBuf,
@@ -525,8 +496,36 @@ restart:
goto err;
gotheader = true;
}
- } while (gotlen < total_len);+ /*+ * We might need a bigger buffer. We have validated the record+ * header, in the case that it split over a page boundary. We've+ * also cross-checked total_len against xlp_rem_len on the second+ * page, and verified xlp_pageaddr on both.+ */+ Assert(gotheader);+ if (total_len > state->readRecordBufSize)+ {+ char save_copy[XLOG_BLCKSZ * 2];++ /*+ * Save and restore the data we already had. It can't be more+ * than two pages.+ */+ Assert(gotlen <= lengthof(save_copy));+ Assert(gotlen <= state->readRecordBufSize);+ memcpy(save_copy, state->readRecordBuf, gotlen);+ if (!allocate_recordbuf(state, total_len))+ {+ /* We treat this as a "bogus data" condition */+ report_invalid_record(state, "record length %u at %X/%X too long",+ total_len, LSN_FORMAT_ARGS(RecPtr));+ goto err;+ }+ memcpy(state->readRecordBuf, save_copy, gotlen);+ buffer = state->readRecordBuf + gotlen;+ }+ } while (gotlen < total_len);
Assert(gotheader);
record = (XLogRecord *) state->readRecordBuf;
diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pmindex 7860425b54..307090321f 100644--- a/src/test/perl/TestLib.pm+++ b/src/test/perl/TestLib.pm@@ -70,6 +70,7 @@ our @EXPORT = qw(
chmod_recursive
check_pg_config
dir_symlink
+ scan_server_header
system_or_bail
system_log
run_log
@@ -648,6 +649,48 @@ sub chmod_recursive
=pod
+=item scan_server_header(header_path, regexp)++Returns an array that stores all the matches of the given regular expression+within the PostgreSQL installation's C<header_path>. This can be used to+retrieve specific value patterns from the installation's header files.++=cut++sub scan_server_header+{+ my ($header_path, $regexp) = @_;++ my ($stdout, $stderr);+ my $result = IPC::Run::run [ 'pg_config', '--includedir-server' ], '>',+ \$stdout, '2>', \$stderr+ or die "could not execute pg_config";+ chomp($stdout);+ $stdout =~ s/\r$//;++ open my $header_h, '<', "$stdout/$header_path" or die "$!";++ my @match = undef;+ while (<$header_h>)+ {+ my $line = $_;++ if ($line =~ /^$regexp/)+ {+ # Found match, so store all the results.+ @match = @{^CAPTURE};+ last;+ }+ }++ close $header_h;+ die "could not find match in header $header_path\n"+ unless @match;+ return @match;+}++=pod+
=item check_pg_config(regexp)
Return the number of matches of the given regular expression
diff --git a/src/test/recovery/t/038_end_of_wal.pl b/src/test/recovery/t/038_end_of_wal.plnew file mode 100644index 0000000000..c918cc31cb--- /dev/null+++ b/src/test/recovery/t/038_end_of_wal.pl@@ -0,0 +1,449 @@+# Copyright (c) 2023, PostgreSQL Global Development Group+#+# Test detecting end of WAL replay. This test suite generates fake+# WAL records able to trigger various failure scenarios at replay.++use strict;+use warnings;+use PostgreSQL::Test::Cluster;+use PostgreSQL::Test::Utils;+use Test::More;+use Fcntl qw(SEEK_SET);++use integer; # causes / operator to use integer math++# Header size of record header.+my $RECORD_HEADER_SIZE = 24;++# Fields retrieved from code headers.+my @scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLOG_PAGE_MAGIC\s+(\w+)');+my $XLP_PAGE_MAGIC = hex($scan_result[0]);+@scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLP_FIRST_IS_CONTRECORD\s+(\w+)');+my $XLP_FIRST_IS_CONTRECORD = hex($scan_result[0]);++# Values queried from the server+my $WAL_SEGMENT_SIZE;+my $WAL_BLOCK_SIZE;+my $TLI;++# Build path of a WAL segment.+sub wal_segment_path+{+ my $node = shift;+ my $tli = shift;+ my $segment = shift;+ my $wal_path =+ sprintf("%s/pg_wal/%08X%08X%08X", $node->data_dir, $tli, 0, $segment);+ return $wal_path;+}++# Calculate from a LSN (in bytes) its segment number and its offset.+sub lsn_to_segment_and_offset+{+ my $lsn = shift;+ return ($lsn / $WAL_SEGMENT_SIZE, $lsn % $WAL_SEGMENT_SIZE);+}++# Write some arbitrary data in WAL for the given segment at offset.+# This should be called while the cluster is offline.+sub write_wal+{+ my $node = shift;+ my $tli = shift;+ my $lsn = shift;+ my $data = shift;++ my ($segment, $offset) = lsn_to_segment_and_offset($lsn);+ my $path = wal_segment_path($node, $tli, $segment);++ open my $fh, "+<:raw", $path or die;+ seek($fh, $offset, SEEK_SET) or die;+ print $fh $data;+ close $fh;+}++sub format_lsn+{+ my $lsn = shift;+ return sprintf("%X/%X", $lsn >> 32, $lsn & 0xffffffff);+}++# Emit a WAL record of arbitrary size. Returns the end LSN of the+# record inserted, in bytes.+sub emit_message+{+ my $node = shift;+ my $size = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT pg_logical_emit_message(true, '', repeat('a', $size)) - '0/0'"+ ));+}++# Get the current insert LSN of a node, in bytes.+sub get_insert_lsn+{+ my $node = shift;+ return int(+ $node->safe_psql(+ 'postgres', "SELECT pg_current_wal_insert_lsn() - '0/0'"));+}++# Get GUC value, converted to an int.+sub get_int_setting+{+ my $node = shift;+ my $name = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT setting FROM pg_settings WHERE name = '$name'"));+}++sub start_of_page+{+ my $lsn = shift;+ return $lsn & ~($WAL_BLOCK_SIZE - 1);+}++sub start_of_next_page+{+ my $lsn = shift;+ return start_of_page($lsn) + $WAL_BLOCK_SIZE;+}++# Build a fake WAL record header based on the data given by the caller.+# This needs to follow the format of the C structure XLogRecord. To+# be inserted with write_wal().+sub build_record_header+{+ my $xl_tot_len = shift;+ my $xl_xid = shift || 0;+ my $xl_prev = shift || 0;+ my $xl_info = shift || 0;+ my $xl_rmid = shift || 0;+ my $xl_crc = shift || 0;++ # This needs to follow the structure XLogRecord:+ # I for xl_tot_len+ # I for xl_xid+ # Q for xl_prev+ # C for xl_info+ # C for xl_rmid+ # BB for two bytes of padding+ # I for xl_crc+ return pack("IIQCCBBI",+ $xl_tot_len, $xl_xid, $xl_prev, $xl_info, $xl_rmid, 0, 0, $xl_crc);+}++# Build a fake WAL page header, based on the data given by the caller+# This needs to follow the format of the C structure XLogPageHeaderData.+# To be inserted with write_wal().+sub build_page_header+{+ my $xlp_magic = shift;+ my $xlp_info = shift || 0;+ my $xlp_tli = shift || 0;+ my $xlp_pageaddr = shift || 0;+ my $xlp_rem_len = shift || 0;++ # This needs to follow the structure XLogPageHeaderData:+ # S for xlp_magic+ # S for xlp_info+ # I for xlp_tli+ # Q for xlp_pageaddr+ # I for xlp_rem_len+ return pack("SSIQI",+ $xlp_magic, $xlp_info, $xlp_tli, $xlp_pageaddr, $xlp_rem_len);+}++# Make sure we are far away enough from the end of a page that we could insert+# a couple of small records. This inserts a few records of a fixed size, until+# the threshold gets close enough to the end of the WAL page inserting records+# to.+sub advance_out_of_record_splitting_zone+{+ my $node = shift;++ my $page_threshold = 2000;+ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ while ($page_offset >= $WAL_BLOCK_SIZE - $page_threshold)+ {+ $end_lsn = emit_message($node, $page_threshold);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }+ return $end_lsn;+}++# Advance so close to the end of a page that an XLogRecordHeader would not+# fit on it.+sub advance_to_record_splitting_zone+{+ my $node = shift;++ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Get fairly close to the end of a page in big steps+ while ($page_offset <= $WAL_BLOCK_SIZE - 512)+ {+ $end_lsn = emit_message($node, $WAL_BLOCK_SIZE - $page_offset - 256);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }++ # Calibrate our message size so that we can get closer 8 bytes at+ # a time.+ my $message_size = $WAL_BLOCK_SIZE - 80;+ while ($page_offset <= $WAL_BLOCK_SIZE - $RECORD_HEADER_SIZE)+ {+ $end_lsn = emit_message($node, $message_size);++ my $old_offset = $page_offset;+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Adjust the message size until it causes 8 bytes changes in+ # offset, enough to be able to split a record header.+ my $delta = $page_offset - $old_offset;+ if ($delta > 8)+ {+ $message_size -= 8;+ }+ elsif ($delta <= 0)+ {+ $message_size += 8;+ }+ }+ return $end_lsn;+}++# Setup a new node. The configuration chosen here minimizes the number+# of arbitrary records that could get generated in a cluster. Enlarging+# checkpoint_timeout avoids noise with checkpoint activity. wal_level+# set to "minimal" avoids random standby snapshot records. Autovacuum+# could also trigger randomly, generating random WAL activity of its own.+my $node = PostgreSQL::Test::Cluster->new("node");+$node->init;+$node->append_conf(+ 'postgresql.conf',+ q[wal_level = minimal+ autovacuum = off+ checkpoint_timeout = '30min'+]);+$node->start;+$node->safe_psql('postgres', "CREATE TABLE t AS SELECT 42");++$WAL_SEGMENT_SIZE = get_int_setting($node, 'wal_segment_size');+$WAL_BLOCK_SIZE = get_int_setting($node, 'wal_block_size');+$TLI = $node->safe_psql('postgres',+ "SELECT timeline_id FROM pg_control_checkpoint();");++my $end_lsn;+my $prev_lsn;++###########################################################################+note "Single-page end-of-WAL detection";+###########################################################################++# xl_tot_len is 0 (a common case, we hit trailing zeroes).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+my $log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: wanted 24, got 0", $log_size+ ),+ "xl_tot_len zero");++# xl_tot_len is < 24 (presumably recycled garbage).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn, build_record_header(23));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: wanted 24, got 23",+ $log_size),+ "xl_tot_len short");++# Need more pages, but xl_prev check fails first.+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "record with incorrect prev-link 0/DEADBEEF at .*", $log_size),+ "xl_prev bad");++# xl_crc check fails.+advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 10);+$node->stop('immediate');+# Corrupt a byte in that record, breaking its CRC.+write_wal($node, $TLI, $end_lsn - 8, '!');+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "incorrect resource manager data checksum in record at .*", $log_size+ ),+ "xl_crc bad");+++###########################################################################+note "Multi-page end-of-WAL detection, header is not split";+###########################################################################++# This series of tests requires a valid xl_prev set in the record header+# written to WAL.++# Good xl_prev, we hit zero page next (zero magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 ", $log_size),+ "xlp_magic zero");++# Good xl_prev, we hit garbage page next (bad magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(0xcafe, 0, 1, 0));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number CAFE ", $log_size),+ "xlp_magic bad");++# Good xl_prev, we hit typical recycled page (good xlp_magic, bad+# xlp_pageaddr).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD ", $log_size),+ "xlp_pageaddr bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but bogus xlp_info.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, 0x1234, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid info bits 1234 ", $log_size),+ "xlp_info bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but xlp_info doesn't mention+# continuation record.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("there is no contrecord flag at .*", $log_size),+ "xlp_info lacks XLP_FIRST_IS_CONTRECORD");++# Good xl_prev, xlp_magic, xlp_pageaddr, xlp_info but xlp_rem_len doesn't add+# up.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 .* at .*", $log_size),+ "xlp_rem_len bad");+++###########################################################################+note "Multi-page, but header is split, so page checks are done first";+###########################################################################++# xlp_prev is bad and xl_tot_len is too big, but we'll check xlp_magic first.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 ", $log_size),+ "xlp_magic zero (split record header)");++# And we'll also check xlp_pageaddr before any header checks.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD ", $log_size),+ "xlp_pageaddr bad (split record header)");++# We'll also discover that xlp_rem_len doesn't add up before any+# header checks,+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 .* at .*", $log_size),+ "xlp_rem_len bad (split record header)");++done_testing();--
2.40.1
[text/plain] v6-0001-Don-t-trust-unvalidated-xl_tot_len.patch.13 (21.8K, ../ZP+4YYrPZk0GFlc3@paquier.xyz/6-v6-0001-Don-t-trust-unvalidated-xl_tot_len.patch.13)
download | inline diff:
From 9156107d5e3ae860d332cdb3af581ba4c314844d Mon Sep 17 00:00:00 2001
From: Thomas Munro <thomas.munro@gmail.com>
Date: Mon, 14 Aug 2023 17:06:42 +1200
Subject: [PATCH v6] Don't trust unvalidated xl_tot_len.
xl_tot_len comes first in a WAL record. Usually we don't trust it to be
the true length until we've validated the record header. If the record
header was split across two pages, previously we wouldn't do the
validation until after we'd already tried to allocate enough memory to
hold the record, which was bad because it might actually be garbage
bytes from a recycled WAL file, so we could try to allocate a lot of
memory. Release 15 made it worse.
Since 70b4f82a4b5, we'd at least generate an end-of-WAL condition if the
garbage 4 byte value happened to be > 1GB, but we'd still try to
allocate up to 1GB of memory bogusly otherwise. That was an
improvement, but unfortunately release 15 tries to allocate another
object before that, so you could get a FATAL error and recovery could
fail.
We can fix both variants of the problem more fundamentally using
pre-existing page-level validation, if we just re-order some logic.
The new order of operations in the split-header case defers all memory
allocation based on xl_tot_len until we've read the following page. At
that point we know that its first few bytes are not recycled data, by
checking its xlp_pageaddr, and that its xlp_rem_len agrees with
xl_tot_len on the preceding page. That is strong evidence that
xl_tot_len was truly the start of a record that was logged.
This problem was most likely to occur on a standby, because
walreceiver.c recycles WAL files without zeroing out trailing regions of
each page. We should fix that too, but that wouldn't protect us from
rare crash scenarios where the trailing zeroes don't make it to disk.
Back-patch to 15. We might decide to back-patch a variant of this
to older branches with more study, but the symptoms there (bogus large
allocation) are less severe.
Author: Thomas Munro <thomas.munro@gmail.com>
Author: Michael Paquier <michael@paquier.xyz>
Reported-by: Alexander Lakhin <exclusion@gmail.com>
Reviewed-by: Noah Misch <noah@leadboat.com> (the idea, not the code)
Reviewed-by: Michael Paquier <michael@paquier.xyz>
Reviewed-by: Sergei Kornilov <sk@zsrv.org>
Discussion: https://postgr.es/m/17928-aa92416a70ff44a2%40postgresql.org
---
src/backend/access/transam/xlogreader.c | 77 ++--
src/test/perl/TestLib.pm | 43 +++
src/test/recovery/t/038_end_of_wal.pl | 449 ++++++++++++++++++++++++
3 files changed, 530 insertions(+), 39 deletions(-)
create mode 100644 src/test/recovery/t/038_end_of_wal.pl
diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.cindex 911bc91bc9..f2b268d236 100644--- a/src/backend/access/transam/xlogreader.c+++ b/src/backend/access/transam/xlogreader.c@@ -168,6 +168,9 @@ XLogReaderFree(XLogReaderState *state)
* XLOG_BLCKSZ, and make sure it's at least 5*Max(BLCKSZ, XLOG_BLCKSZ) to start
* with. (That is enough for all "normal" records, but very large commit or
* abort records might need more space.)
+ *+ * Note: This routine should *never* be called for xl_tot_len until the header+ * of the record has been fully validated.
*/
static bool
allocate_recordbuf(XLogReaderState *state, uint32 reclength)
@@ -177,25 +180,6 @@ allocate_recordbuf(XLogReaderState *state, uint32 reclength)
newSize += XLOG_BLCKSZ - (newSize % XLOG_BLCKSZ);
newSize = Max(newSize, 5 * Max(BLCKSZ, XLOG_BLCKSZ));
-#ifndef FRONTEND-- /*- * Note that in much unlucky circumstances, the random data read from a- * recycled segment can cause this routine to be called with a size- * causing a hard failure at allocation. For a standby, this would cause- * the instance to stop suddenly with a hard failure, preventing it to- * retry fetching WAL from one of its sources which could allow it to move- * on with replay without a manual restart. If the data comes from a past- * recycled segment and is still valid, then the allocation may succeed- * but record checks are going to fail so this would be short-lived. If- * the allocation fails because of a memory shortage, then this is not a- * hard failure either per the guarantee given by MCXT_ALLOC_NO_OOM.- */- if (!AllocSizeIsValid(newSize))- return false;--#endif-
if (state->readRecordBuf)
pfree(state->readRecordBuf);
state->readRecordBuf =
@@ -396,15 +380,7 @@ restart:
}
else
{
- /* XXX: more validation should be done here */- if (total_len < SizeOfXLogRecord)- {- report_invalid_record(state,- "invalid record length at %X/%X: wanted %u, got %u",- (uint32) (RecPtr >> 32), (uint32) RecPtr,- (uint32) SizeOfXLogRecord, total_len);- goto err;- }+ /* We'll validate the header once we have the next page. */
gotheader = false;
}
@@ -420,17 +396,11 @@ restart:
assembled = true;
/*
- * Enlarge readRecordBuf as needed.+ * We always have space for a couple of pages, enough to validate a+ * boundary-spanning record header.
*/
- if (total_len > state->readRecordBufSize &&- !allocate_recordbuf(state, total_len))- {- /* We treat this as a "bogus data" condition */- report_invalid_record(state, "record length %u at %X/%X too long",- total_len,- (uint32) (RecPtr >> 32), (uint32) RecPtr);- goto err;- }+ Assert(state->readRecordBufSize >= XLOG_BLCKSZ * 2);+ Assert(state->readRecordBufSize >= len);
/* Copy the first fragment of the record from the first page. */
memcpy(state->readRecordBuf,
@@ -525,8 +495,37 @@ restart:
goto err;
gotheader = true;
}
- } while (gotlen < total_len);+ /*+ * We might need a bigger buffer. We have validated the record+ * header, in the case that it split over a page boundary. We've+ * also cross-checked total_len against xlp_rem_len on the second+ * page, and verified xlp_pageaddr on both.+ */+ Assert(gotheader);+ if (total_len > state->readRecordBufSize)+ {+ char save_copy[XLOG_BLCKSZ * 2];++ /*+ * Save and restore the data we already had. It can't be more+ * than two pages.+ */+ Assert(gotlen <= lengthof(save_copy));+ Assert(gotlen <= state->readRecordBufSize);+ memcpy(save_copy, state->readRecordBuf, gotlen);+ if (!allocate_recordbuf(state, total_len))+ {+ /* We treat this as a "bogus data" condition */+ report_invalid_record(state, "record length %u at %X/%X too long",+ total_len,+ (uint32) (RecPtr >> 32), (uint32) RecPtr);+ goto err;+ }+ memcpy(state->readRecordBuf, save_copy, gotlen);+ buffer = state->readRecordBuf + gotlen;+ }+ } while (gotlen < total_len);
Assert(gotheader);
record = (XLogRecord *) state->readRecordBuf;
diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pmindex 7715d551b3..fee244c418 100644--- a/src/test/perl/TestLib.pm+++ b/src/test/perl/TestLib.pm@@ -66,6 +66,7 @@ our @EXPORT = qw(
check_mode_recursive
chmod_recursive
check_pg_config
+ scan_server_header
system_or_bail
system_log
run_log
@@ -632,6 +633,48 @@ sub chmod_recursive
=pod
+=item scan_server_header(header_path, regexp)++Returns an array that stores all the matches of the given regular expression+within the PostgreSQL installation's C<header_path>. This can be used to+retrieve specific value patterns from the installation's header files.++=cut++sub scan_server_header+{+ my ($header_path, $regexp) = @_;++ my ($stdout, $stderr);+ my $result = IPC::Run::run [ 'pg_config', '--includedir-server' ], '>',+ \$stdout, '2>', \$stderr+ or die "could not execute pg_config";+ chomp($stdout);+ $stdout =~ s/\r$//;++ open my $header_h, '<', "$stdout/$header_path" or die "$!";++ my @match = undef;+ while (<$header_h>)+ {+ my $line = $_;++ if ($line =~ /^$regexp/)+ {+ # Found match, so store all the results.+ @match = @{^CAPTURE};+ last;+ }+ }++ close $header_h;+ die "could not find match in header $header_path\n"+ unless @match;+ return @match;+}++=pod+
=item check_pg_config(regexp)
Return the number of matches of the given regular expression
diff --git a/src/test/recovery/t/038_end_of_wal.pl b/src/test/recovery/t/038_end_of_wal.plnew file mode 100644index 0000000000..6927d1298a--- /dev/null+++ b/src/test/recovery/t/038_end_of_wal.pl@@ -0,0 +1,449 @@+# Copyright (c) 2023, PostgreSQL Global Development Group+#+# Test detecting end of WAL replay. This test suite generates fake+# WAL records able to trigger various failure scenarios at replay.++use strict;+use warnings;+use PostgreSQL::Test::Cluster;+use PostgreSQL::Test::Utils;+use Test::More;+use Fcntl qw(SEEK_SET);++use integer; # causes / operator to use integer math++# Header size of record header.+my $RECORD_HEADER_SIZE = 24;++# Fields retrieved from code headers.+my @scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLOG_PAGE_MAGIC\s+(\w+)');+my $XLP_PAGE_MAGIC = hex($scan_result[0]);+@scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLP_FIRST_IS_CONTRECORD\s+(\w+)');+my $XLP_FIRST_IS_CONTRECORD = hex($scan_result[0]);++# Values queried from the server+my $WAL_SEGMENT_SIZE;+my $WAL_BLOCK_SIZE;+my $TLI;++# Build path of a WAL segment.+sub wal_segment_path+{+ my $node = shift;+ my $tli = shift;+ my $segment = shift;+ my $wal_path =+ sprintf("%s/pg_wal/%08X%08X%08X", $node->data_dir, $tli, 0, $segment);+ return $wal_path;+}++# Calculate from a LSN (in bytes) its segment number and its offset.+sub lsn_to_segment_and_offset+{+ my $lsn = shift;+ return ($lsn / $WAL_SEGMENT_SIZE, $lsn % $WAL_SEGMENT_SIZE);+}++# Write some arbitrary data in WAL for the given segment at offset.+# This should be called while the cluster is offline.+sub write_wal+{+ my $node = shift;+ my $tli = shift;+ my $lsn = shift;+ my $data = shift;++ my ($segment, $offset) = lsn_to_segment_and_offset($lsn);+ my $path = wal_segment_path($node, $tli, $segment);++ open my $fh, "+<:raw", $path or die;+ seek($fh, $offset, SEEK_SET) or die;+ print $fh $data;+ close $fh;+}++sub format_lsn+{+ my $lsn = shift;+ return sprintf("%X/%X", $lsn >> 32, $lsn & 0xffffffff);+}++# Emit a WAL record of arbitrary size. Returns the end LSN of the+# record inserted, in bytes.+sub emit_message+{+ my $node = shift;+ my $size = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT pg_logical_emit_message(true, '', repeat('a', $size)) - '0/0'"+ ));+}++# Get the current insert LSN of a node, in bytes.+sub get_insert_lsn+{+ my $node = shift;+ return int(+ $node->safe_psql(+ 'postgres', "SELECT pg_current_wal_insert_lsn() - '0/0'"));+}++# Get GUC value, converted to an int.+sub get_int_setting+{+ my $node = shift;+ my $name = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT setting FROM pg_settings WHERE name = '$name'"));+}++sub start_of_page+{+ my $lsn = shift;+ return $lsn & ~($WAL_BLOCK_SIZE - 1);+}++sub start_of_next_page+{+ my $lsn = shift;+ return start_of_page($lsn) + $WAL_BLOCK_SIZE;+}++# Build a fake WAL record header based on the data given by the caller.+# This needs to follow the format of the C structure XLogRecord. To+# be inserted with write_wal().+sub build_record_header+{+ my $xl_tot_len = shift;+ my $xl_xid = shift || 0;+ my $xl_prev = shift || 0;+ my $xl_info = shift || 0;+ my $xl_rmid = shift || 0;+ my $xl_crc = shift || 0;++ # This needs to follow the structure XLogRecord:+ # I for xl_tot_len+ # I for xl_xid+ # Q for xl_prev+ # C for xl_info+ # C for xl_rmid+ # BB for two bytes of padding+ # I for xl_crc+ return pack("IIQCCBBI",+ $xl_tot_len, $xl_xid, $xl_prev, $xl_info, $xl_rmid, 0, 0, $xl_crc);+}++# Build a fake WAL page header, based on the data given by the caller+# This needs to follow the format of the C structure XLogPageHeaderData.+# To be inserted with write_wal().+sub build_page_header+{+ my $xlp_magic = shift;+ my $xlp_info = shift || 0;+ my $xlp_tli = shift || 0;+ my $xlp_pageaddr = shift || 0;+ my $xlp_rem_len = shift || 0;++ # This needs to follow the structure XLogPageHeaderData:+ # S for xlp_magic+ # S for xlp_info+ # I for xlp_tli+ # Q for xlp_pageaddr+ # I for xlp_rem_len+ return pack("SSIQI",+ $xlp_magic, $xlp_info, $xlp_tli, $xlp_pageaddr, $xlp_rem_len);+}++# Make sure we are far away enough from the end of a page that we could insert+# a couple of small records. This inserts a few records of a fixed size, until+# the threshold gets close enough to the end of the WAL page inserting records+# to.+sub advance_out_of_record_splitting_zone+{+ my $node = shift;++ my $page_threshold = 2000;+ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ while ($page_offset >= $WAL_BLOCK_SIZE - $page_threshold)+ {+ $end_lsn = emit_message($node, $page_threshold);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }+ return $end_lsn;+}++# Advance so close to the end of a page that an XLogRecordHeader would not+# fit on it.+sub advance_to_record_splitting_zone+{+ my $node = shift;++ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Get fairly close to the end of a page in big steps+ while ($page_offset <= $WAL_BLOCK_SIZE - 512)+ {+ $end_lsn = emit_message($node, $WAL_BLOCK_SIZE - $page_offset - 256);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }++ # Calibrate our message size so that we can get closer 8 bytes at+ # a time.+ my $message_size = $WAL_BLOCK_SIZE - 80;+ while ($page_offset <= $WAL_BLOCK_SIZE - $RECORD_HEADER_SIZE)+ {+ $end_lsn = emit_message($node, $message_size);++ my $old_offset = $page_offset;+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Adjust the message size until it causes 8 bytes changes in+ # offset, enough to be able to split a record header.+ my $delta = $page_offset - $old_offset;+ if ($delta > 8)+ {+ $message_size -= 8;+ }+ elsif ($delta <= 0)+ {+ $message_size += 8;+ }+ }+ return $end_lsn;+}++# Setup a new node. The configuration chosen here minimizes the number+# of arbitrary records that could get generated in a cluster. Enlarging+# checkpoint_timeout avoids noise with checkpoint activity. wal_level+# set to "minimal" avoids random standby snapshot records. Autovacuum+# could also trigger randomly, generating random WAL activity of its own.+my $node = PostgreSQL::Test::Cluster->new("node");+$node->init;+$node->append_conf(+ 'postgresql.conf',+ q[wal_level = minimal+ autovacuum = off+ checkpoint_timeout = '30min'+]);+$node->start;+$node->safe_psql('postgres', "CREATE TABLE t AS SELECT 42");++$WAL_SEGMENT_SIZE = get_int_setting($node, 'wal_segment_size');+$WAL_BLOCK_SIZE = get_int_setting($node, 'wal_block_size');+$TLI = $node->safe_psql('postgres',+ "SELECT timeline_id FROM pg_control_checkpoint();");++my $end_lsn;+my $prev_lsn;++###########################################################################+note "Single-page end-of-WAL detection";+###########################################################################++# xl_tot_len is 0 (a common case, we hit trailing zeroes).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+my $log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: wanted 24, got 0", $log_size+ ),+ "xl_tot_len zero");++# xl_tot_len is < 24 (presumably recycled garbage).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn, build_record_header(23));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: wanted 24, got 23",+ $log_size),+ "xl_tot_len short");++# Need more pages, but xl_prev check fails first.+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "record with incorrect prev-link 0/DEADBEEF at .*", $log_size),+ "xl_prev bad");++# xl_crc check fails.+advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 10);+$node->stop('immediate');+# Corrupt a byte in that record, breaking its CRC.+write_wal($node, $TLI, $end_lsn - 8, '!');+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "incorrect resource manager data checksum in record at .*", $log_size+ ),+ "xl_crc bad");+++###########################################################################+note "Multi-page end-of-WAL detection, header is not split";+###########################################################################++# This series of tests requires a valid xl_prev set in the record header+# written to WAL.++# Good xl_prev, we hit zero page next (zero magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 ", $log_size),+ "xlp_magic zero");++# Good xl_prev, we hit garbage page next (bad magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(0xcafe, 0, 1, 0));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number CAFE ", $log_size),+ "xlp_magic bad");++# Good xl_prev, we hit typical recycled page (good xlp_magic, bad+# xlp_pageaddr).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD ", $log_size),+ "xlp_pageaddr bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but bogus xlp_info.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, 0x1234, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid info bits 1234 ", $log_size),+ "xlp_info bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but xlp_info doesn't mention+# continuation record.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("there is no contrecord flag at .*", $log_size),+ "xlp_info lacks XLP_FIRST_IS_CONTRECORD");++# Good xl_prev, xlp_magic, xlp_pageaddr, xlp_info but xlp_rem_len doesn't add+# up.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 at .*", $log_size),+ "xlp_rem_len bad");+++###########################################################################+note "Multi-page, but header is split, so page checks are done first";+###########################################################################++# xlp_prev is bad and xl_tot_len is too big, but we'll check xlp_magic first.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 ", $log_size),+ "xlp_magic zero (split record header)");++# And we'll also check xlp_pageaddr before any header checks.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD ", $log_size),+ "xlp_pageaddr bad (split record header)");++# We'll also discover that xlp_rem_len doesn't add up before any+# header checks,+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 at .*", $log_size),+ "xlp_rem_len bad (split record header)");++done_testing();--
2.40.1
[text/plain] v6-0001-Don-t-trust-unvalidated-xl_tot_len.patch.12 (21.8K, ../ZP+4YYrPZk0GFlc3@paquier.xyz/7-v6-0001-Don-t-trust-unvalidated-xl_tot_len.patch.12)
download | inline diff:
From ae0864bebe0e475f1a1ee04c2ada573c5e861e38 Mon Sep 17 00:00:00 2001
From: Thomas Munro <thomas.munro@gmail.com>
Date: Mon, 14 Aug 2023 17:06:42 +1200
Subject: [PATCH v6] Don't trust unvalidated xl_tot_len.
xl_tot_len comes first in a WAL record. Usually we don't trust it to be
the true length until we've validated the record header. If the record
header was split across two pages, previously we wouldn't do the
validation until after we'd already tried to allocate enough memory to
hold the record, which was bad because it might actually be garbage
bytes from a recycled WAL file, so we could try to allocate a lot of
memory. Release 15 made it worse.
Since 70b4f82a4b5, we'd at least generate an end-of-WAL condition if the
garbage 4 byte value happened to be > 1GB, but we'd still try to
allocate up to 1GB of memory bogusly otherwise. That was an
improvement, but unfortunately release 15 tries to allocate another
object before that, so you could get a FATAL error and recovery could
fail.
We can fix both variants of the problem more fundamentally using
pre-existing page-level validation, if we just re-order some logic.
The new order of operations in the split-header case defers all memory
allocation based on xl_tot_len until we've read the following page. At
that point we know that its first few bytes are not recycled data, by
checking its xlp_pageaddr, and that its xlp_rem_len agrees with
xl_tot_len on the preceding page. That is strong evidence that
xl_tot_len was truly the start of a record that was logged.
This problem was most likely to occur on a standby, because
walreceiver.c recycles WAL files without zeroing out trailing regions of
each page. We should fix that too, but that wouldn't protect us from
rare crash scenarios where the trailing zeroes don't make it to disk.
Back-patch to 15. We might decide to back-patch a variant of this
to older branches with more study, but the symptoms there (bogus large
allocation) are less severe.
Author: Thomas Munro <thomas.munro@gmail.com>
Author: Michael Paquier <michael@paquier.xyz>
Reported-by: Alexander Lakhin <exclusion@gmail.com>
Reviewed-by: Noah Misch <noah@leadboat.com> (the idea, not the code)
Reviewed-by: Michael Paquier <michael@paquier.xyz>
Reviewed-by: Sergei Kornilov <sk@zsrv.org>
Discussion: https://postgr.es/m/17928-aa92416a70ff44a2%40postgresql.org
---
src/backend/access/transam/xlogreader.c | 77 ++--
src/test/perl/TestLib.pm | 36 ++
src/test/recovery/t/038_end_of_wal.pl | 449 ++++++++++++++++++++++++
3 files changed, 523 insertions(+), 39 deletions(-)
create mode 100644 src/test/recovery/t/038_end_of_wal.pl
diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.cindex 26f8e0ae2c..0016a3b3ef 100644--- a/src/backend/access/transam/xlogreader.c+++ b/src/backend/access/transam/xlogreader.c@@ -155,6 +155,9 @@ XLogReaderFree(XLogReaderState *state)
* XLOG_BLCKSZ, and make sure it's at least 5*Max(BLCKSZ, XLOG_BLCKSZ) to start
* with. (That is enough for all "normal" records, but very large commit or
* abort records might need more space.)
+ *+ * Note: This routine should *never* be called for xl_tot_len until the header+ * of the record has been fully validated.
*/
static bool
allocate_recordbuf(XLogReaderState *state, uint32 reclength)
@@ -164,25 +167,6 @@ allocate_recordbuf(XLogReaderState *state, uint32 reclength)
newSize += XLOG_BLCKSZ - (newSize % XLOG_BLCKSZ);
newSize = Max(newSize, 5 * Max(BLCKSZ, XLOG_BLCKSZ));
-#ifndef FRONTEND-- /*- * Note that in much unlucky circumstances, the random data read from a- * recycled segment can cause this routine to be called with a size- * causing a hard failure at allocation. For a standby, this would cause- * the instance to stop suddenly with a hard failure, preventing it to- * retry fetching WAL from one of its sources which could allow it to move- * on with replay without a manual restart. If the data comes from a past- * recycled segment and is still valid, then the allocation may succeed- * but record checks are going to fail so this would be short-lived. If- * the allocation fails because of a memory shortage, then this is not a- * hard failure either per the guarantee given by MCXT_ALLOC_NO_OOM.- */- if (!AllocSizeIsValid(newSize))- return false;--#endif-
if (state->readRecordBuf)
pfree(state->readRecordBuf);
state->readRecordBuf =
@@ -346,15 +330,7 @@ restart:
}
else
{
- /* XXX: more validation should be done here */- if (total_len < SizeOfXLogRecord)- {- report_invalid_record(state,- "invalid record length at %X/%X: wanted %u, got %u",- (uint32) (RecPtr >> 32), (uint32) RecPtr,- (uint32) SizeOfXLogRecord, total_len);- goto err;- }+ /* We'll validate the header once we have the next page. */
gotheader = false;
}
@@ -370,17 +346,11 @@ restart:
assembled = true;
/*
- * Enlarge readRecordBuf as needed.+ * We always have space for a couple of pages, enough to validate a+ * boundary-spanning record header.
*/
- if (total_len > state->readRecordBufSize &&- !allocate_recordbuf(state, total_len))- {- /* We treat this as a "bogus data" condition */- report_invalid_record(state, "record length %u at %X/%X too long",- total_len,- (uint32) (RecPtr >> 32), (uint32) RecPtr);- goto err;- }+ Assert(state->readRecordBufSize >= XLOG_BLCKSZ * 2);+ Assert(state->readRecordBufSize >= len);
/* Copy the first fragment of the record from the first page. */
memcpy(state->readRecordBuf,
@@ -475,8 +445,37 @@ restart:
goto err;
gotheader = true;
}
- } while (gotlen < total_len);+ /*+ * We might need a bigger buffer. We have validated the record+ * header, in the case that it split over a page boundary. We've+ * also cross-checked total_len against xlp_rem_len on the second+ * page, and verified xlp_pageaddr on both.+ */+ Assert(gotheader);+ if (total_len > state->readRecordBufSize)+ {+ char save_copy[XLOG_BLCKSZ * 2];++ /*+ * Save and restore the data we already had. It can't be more+ * than two pages.+ */+ Assert(gotlen <= lengthof(save_copy));+ Assert(gotlen <= state->readRecordBufSize);+ memcpy(save_copy, state->readRecordBuf, gotlen);+ if (!allocate_recordbuf(state, total_len))+ {+ /* We treat this as a "bogus data" condition */+ report_invalid_record(state, "record length %u at %X/%X too long",+ total_len,+ (uint32) (RecPtr >> 32), (uint32) RecPtr);+ goto err;+ }+ memcpy(state->readRecordBuf, save_copy, gotlen);+ buffer = state->readRecordBuf + gotlen;+ }+ } while (gotlen < total_len);
Assert(gotheader);
record = (XLogRecord *) state->readRecordBuf;
diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pmindex de851e1615..5f80ff9cbc 100644--- a/src/test/perl/TestLib.pm+++ b/src/test/perl/TestLib.pm@@ -33,6 +33,7 @@ our @EXPORT = qw(
check_mode_recursive
chmod_recursive
check_pg_config
+ scan_server_header
system_or_bail
system_log
run_log
@@ -459,6 +460,41 @@ sub chmod_recursive
return;
}
+# Returns an array that stores all the matches of the given regular expression+# within the PostgreSQL installation's C<header_path>. This can be used to+# retrieve specific value patterns from the installation's header files.+sub scan_server_header+{+ my ($header_path, $regexp) = @_;++ my ($stdout, $stderr);+ my $result = IPC::Run::run [ 'pg_config', '--includedir-server' ], '>',+ \$stdout, '2>', \$stderr+ or die "could not execute pg_config";+ chomp($stdout);+ $stdout =~ s/\r$//;++ open my $header_h, '<', "$stdout/$header_path" or die "$!";++ my @match = undef;+ while (<$header_h>)+ {+ my $line = $_;++ if ($line =~ /^$regexp/)+ {+ # Found match, so store all the results.+ @match = @{^CAPTURE};+ last;+ }+ }++ close $header_h;+ die "could not find match in header $header_path\n"+ unless @match;+ return @match;+}+
# Check presence of a given regexp within pg_config.h for the installation
# where tests are running, returning a match status result depending on
# that.
diff --git a/src/test/recovery/t/038_end_of_wal.pl b/src/test/recovery/t/038_end_of_wal.plnew file mode 100644index 0000000000..6927d1298a--- /dev/null+++ b/src/test/recovery/t/038_end_of_wal.pl@@ -0,0 +1,449 @@+# Copyright (c) 2023, PostgreSQL Global Development Group+#+# Test detecting end of WAL replay. This test suite generates fake+# WAL records able to trigger various failure scenarios at replay.++use strict;+use warnings;+use PostgreSQL::Test::Cluster;+use PostgreSQL::Test::Utils;+use Test::More;+use Fcntl qw(SEEK_SET);++use integer; # causes / operator to use integer math++# Header size of record header.+my $RECORD_HEADER_SIZE = 24;++# Fields retrieved from code headers.+my @scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLOG_PAGE_MAGIC\s+(\w+)');+my $XLP_PAGE_MAGIC = hex($scan_result[0]);+@scan_result = scan_server_header('access/xlog_internal.h',+ '#define\s+XLP_FIRST_IS_CONTRECORD\s+(\w+)');+my $XLP_FIRST_IS_CONTRECORD = hex($scan_result[0]);++# Values queried from the server+my $WAL_SEGMENT_SIZE;+my $WAL_BLOCK_SIZE;+my $TLI;++# Build path of a WAL segment.+sub wal_segment_path+{+ my $node = shift;+ my $tli = shift;+ my $segment = shift;+ my $wal_path =+ sprintf("%s/pg_wal/%08X%08X%08X", $node->data_dir, $tli, 0, $segment);+ return $wal_path;+}++# Calculate from a LSN (in bytes) its segment number and its offset.+sub lsn_to_segment_and_offset+{+ my $lsn = shift;+ return ($lsn / $WAL_SEGMENT_SIZE, $lsn % $WAL_SEGMENT_SIZE);+}++# Write some arbitrary data in WAL for the given segment at offset.+# This should be called while the cluster is offline.+sub write_wal+{+ my $node = shift;+ my $tli = shift;+ my $lsn = shift;+ my $data = shift;++ my ($segment, $offset) = lsn_to_segment_and_offset($lsn);+ my $path = wal_segment_path($node, $tli, $segment);++ open my $fh, "+<:raw", $path or die;+ seek($fh, $offset, SEEK_SET) or die;+ print $fh $data;+ close $fh;+}++sub format_lsn+{+ my $lsn = shift;+ return sprintf("%X/%X", $lsn >> 32, $lsn & 0xffffffff);+}++# Emit a WAL record of arbitrary size. Returns the end LSN of the+# record inserted, in bytes.+sub emit_message+{+ my $node = shift;+ my $size = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT pg_logical_emit_message(true, '', repeat('a', $size)) - '0/0'"+ ));+}++# Get the current insert LSN of a node, in bytes.+sub get_insert_lsn+{+ my $node = shift;+ return int(+ $node->safe_psql(+ 'postgres', "SELECT pg_current_wal_insert_lsn() - '0/0'"));+}++# Get GUC value, converted to an int.+sub get_int_setting+{+ my $node = shift;+ my $name = shift;+ return int(+ $node->safe_psql(+ 'postgres',+ "SELECT setting FROM pg_settings WHERE name = '$name'"));+}++sub start_of_page+{+ my $lsn = shift;+ return $lsn & ~($WAL_BLOCK_SIZE - 1);+}++sub start_of_next_page+{+ my $lsn = shift;+ return start_of_page($lsn) + $WAL_BLOCK_SIZE;+}++# Build a fake WAL record header based on the data given by the caller.+# This needs to follow the format of the C structure XLogRecord. To+# be inserted with write_wal().+sub build_record_header+{+ my $xl_tot_len = shift;+ my $xl_xid = shift || 0;+ my $xl_prev = shift || 0;+ my $xl_info = shift || 0;+ my $xl_rmid = shift || 0;+ my $xl_crc = shift || 0;++ # This needs to follow the structure XLogRecord:+ # I for xl_tot_len+ # I for xl_xid+ # Q for xl_prev+ # C for xl_info+ # C for xl_rmid+ # BB for two bytes of padding+ # I for xl_crc+ return pack("IIQCCBBI",+ $xl_tot_len, $xl_xid, $xl_prev, $xl_info, $xl_rmid, 0, 0, $xl_crc);+}++# Build a fake WAL page header, based on the data given by the caller+# This needs to follow the format of the C structure XLogPageHeaderData.+# To be inserted with write_wal().+sub build_page_header+{+ my $xlp_magic = shift;+ my $xlp_info = shift || 0;+ my $xlp_tli = shift || 0;+ my $xlp_pageaddr = shift || 0;+ my $xlp_rem_len = shift || 0;++ # This needs to follow the structure XLogPageHeaderData:+ # S for xlp_magic+ # S for xlp_info+ # I for xlp_tli+ # Q for xlp_pageaddr+ # I for xlp_rem_len+ return pack("SSIQI",+ $xlp_magic, $xlp_info, $xlp_tli, $xlp_pageaddr, $xlp_rem_len);+}++# Make sure we are far away enough from the end of a page that we could insert+# a couple of small records. This inserts a few records of a fixed size, until+# the threshold gets close enough to the end of the WAL page inserting records+# to.+sub advance_out_of_record_splitting_zone+{+ my $node = shift;++ my $page_threshold = 2000;+ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ while ($page_offset >= $WAL_BLOCK_SIZE - $page_threshold)+ {+ $end_lsn = emit_message($node, $page_threshold);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }+ return $end_lsn;+}++# Advance so close to the end of a page that an XLogRecordHeader would not+# fit on it.+sub advance_to_record_splitting_zone+{+ my $node = shift;++ my $end_lsn = get_insert_lsn($node);+ my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Get fairly close to the end of a page in big steps+ while ($page_offset <= $WAL_BLOCK_SIZE - 512)+ {+ $end_lsn = emit_message($node, $WAL_BLOCK_SIZE - $page_offset - 256);+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;+ }++ # Calibrate our message size so that we can get closer 8 bytes at+ # a time.+ my $message_size = $WAL_BLOCK_SIZE - 80;+ while ($page_offset <= $WAL_BLOCK_SIZE - $RECORD_HEADER_SIZE)+ {+ $end_lsn = emit_message($node, $message_size);++ my $old_offset = $page_offset;+ $page_offset = $end_lsn % $WAL_BLOCK_SIZE;++ # Adjust the message size until it causes 8 bytes changes in+ # offset, enough to be able to split a record header.+ my $delta = $page_offset - $old_offset;+ if ($delta > 8)+ {+ $message_size -= 8;+ }+ elsif ($delta <= 0)+ {+ $message_size += 8;+ }+ }+ return $end_lsn;+}++# Setup a new node. The configuration chosen here minimizes the number+# of arbitrary records that could get generated in a cluster. Enlarging+# checkpoint_timeout avoids noise with checkpoint activity. wal_level+# set to "minimal" avoids random standby snapshot records. Autovacuum+# could also trigger randomly, generating random WAL activity of its own.+my $node = PostgreSQL::Test::Cluster->new("node");+$node->init;+$node->append_conf(+ 'postgresql.conf',+ q[wal_level = minimal+ autovacuum = off+ checkpoint_timeout = '30min'+]);+$node->start;+$node->safe_psql('postgres', "CREATE TABLE t AS SELECT 42");++$WAL_SEGMENT_SIZE = get_int_setting($node, 'wal_segment_size');+$WAL_BLOCK_SIZE = get_int_setting($node, 'wal_block_size');+$TLI = $node->safe_psql('postgres',+ "SELECT timeline_id FROM pg_control_checkpoint();");++my $end_lsn;+my $prev_lsn;++###########################################################################+note "Single-page end-of-WAL detection";+###########################################################################++# xl_tot_len is 0 (a common case, we hit trailing zeroes).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+my $log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: wanted 24, got 0", $log_size+ ),+ "xl_tot_len zero");++# xl_tot_len is < 24 (presumably recycled garbage).+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn, build_record_header(23));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid record length at .*: wanted 24, got 23",+ $log_size),+ "xl_tot_len short");++# Need more pages, but xl_prev check fails first.+$end_lsn = advance_out_of_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "record with incorrect prev-link 0/DEADBEEF at .*", $log_size),+ "xl_prev bad");++# xl_crc check fails.+advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 10);+$node->stop('immediate');+# Corrupt a byte in that record, breaking its CRC.+write_wal($node, $TLI, $end_lsn - 8, '!');+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "incorrect resource manager data checksum in record at .*", $log_size+ ),+ "xl_crc bad");+++###########################################################################+note "Multi-page end-of-WAL detection, header is not split";+###########################################################################++# This series of tests requires a valid xl_prev set in the record header+# written to WAL.++# Good xl_prev, we hit zero page next (zero magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 ", $log_size),+ "xlp_magic zero");++# Good xl_prev, we hit garbage page next (bad magic).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(0xcafe, 0, 1, 0));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number CAFE ", $log_size),+ "xlp_magic bad");++# Good xl_prev, we hit typical recycled page (good xlp_magic, bad+# xlp_pageaddr).+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD ", $log_size),+ "xlp_pageaddr bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but bogus xlp_info.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, 0x1234, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid info bits 1234 ", $log_size),+ "xlp_info bad");++# Good xl_prev, xlp_magic, xlp_pageaddr, but xlp_info doesn't mention+# continuation record.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header($XLP_PAGE_MAGIC, 0, 1, start_of_next_page($end_lsn)));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("there is no contrecord flag at .*", $log_size),+ "xlp_info lacks XLP_FIRST_IS_CONTRECORD");++# Good xl_prev, xlp_magic, xlp_pageaddr, xlp_info but xlp_rem_len doesn't add+# up.+$prev_lsn = advance_out_of_record_splitting_zone($node);+$end_lsn = emit_message($node, 0);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 42, $prev_lsn));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 at .*", $log_size),+ "xlp_rem_len bad");+++###########################################################################+note "Multi-page, but header is split, so page checks are done first";+###########################################################################++# xlp_prev is bad and xl_tot_len is too big, but we'll check xlp_magic first.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+$log_size = -s $node->logfile;+$node->start;+ok($node->log_contains("invalid magic number 0000 ", $log_size),+ "xlp_magic zero (split record header)");++# And we'll also check xlp_pageaddr before any header checks.+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD, 1, 0xbaaaaaad));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "unexpected pageaddr 0/BAAAAAAD ", $log_size),+ "xlp_pageaddr bad (split record header)");++# We'll also discover that xlp_rem_len doesn't add up before any+# header checks,+$end_lsn = advance_to_record_splitting_zone($node);+$node->stop('immediate');+write_wal($node, $TLI, $end_lsn,+ build_record_header(2 * 1024 * 1024 * 1024, 0, 0xdeadbeef));+write_wal(+ $node, $TLI,+ start_of_next_page($end_lsn),+ build_page_header(+ $XLP_PAGE_MAGIC, $XLP_FIRST_IS_CONTRECORD,+ 1, start_of_next_page($end_lsn),+ 123456));+$log_size = -s $node->logfile;+$node->start;+ok( $node->log_contains(+ "invalid contrecord length 123456 at .*", $log_size),+ "xlp_rem_len bad (split record header)");++done_testing();--
2.40.1
[application/pgp-signature] signature.asc (832B, ../ZP+4YYrPZk0GFlc3@paquier.xyz/8-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, sk@zsrv.org, noah@leadboat.com, tgl@sss.pgh.pa.us, horikyota.ntt@gmail.com, masao.fujii@oss.nttdata.com
Subject: Re: BUG #17928: Standby fails to decode WAL on termination of primary
In-Reply-To: <ZP+4YYrPZk0GFlc3@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