From d1017da5dd484418b9b784fa07e794ab28d32bdc Mon Sep 17 00:00:00 2001 From: Rahul Yadav Date: Thu, 1 Oct 2026 07:46:25 +0100 Subject: [PATCH v2 1/2] Report the decoded record's LSN in DecodeXLogRecord() errors DecodeXLogRecord() is passed the LSN of the record it decodes, but its error messages printed state->ReadRecPtr instead. Before 3f1ce97346 added the circular WAL decoding buffer, the two were the same, since XLogReadRecord() set ReadRecPtr before decoding. Now records are decoded ahead of the one the reader last returned, so these messages named an earlier record: in pg_waldump, and in recovery without prefetching, the record just before the failing one. With recovery_prefetch, it can be any record in the read-ahead window; in one test it was the redo start point, 45 records before the failing one. pg_walinspect reports the same messages. Use the lsn argument instead. The only other caller, the WAL_DEBUG code in XLogInsertRecord(), passes the end of the record it has just inserted, which matches the LSN that code logs for it. Its messages printed 0/00000000 before, as that reader is never positioned. Add a test that corrupts a full-page image so that its record fails decoding, and checks that pg_waldump's error names that record. Noticed while testing a fix for bug #19599. Author: Rahul Yadav Reviewed-by: Surya Poondla Discussion: https://postgr.es/m/P2qIkq4--F-9@rhyadav.dev Backpatch-through: 15 --- src/backend/access/transam/xlogreader.c | 20 ++--- src/bin/pg_waldump/t/001_basic.pl | 110 ++++++++++++++++++++++++ 2 files changed, 120 insertions(+), 10 deletions(-) diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.c index 1db5ca48c3..9f53c132a6 100644 --- a/src/backend/access/transam/xlogreader.c +++ b/src/backend/access/transam/xlogreader.c @@ -1888,7 +1888,7 @@ DecodeXLogRecord(XLogReaderState *state, report_invalid_record(state, "out-of-order block_id %u at %X/%08X", block_id, - LSN_FORMAT_ARGS(state->ReadRecPtr)); + LSN_FORMAT_ARGS(lsn)); goto err; } decoded->max_block_id = block_id; @@ -1911,7 +1911,7 @@ DecodeXLogRecord(XLogReaderState *state, { report_invalid_record(state, "BKPBLOCK_HAS_DATA set, but no data included at %X/%08X", - LSN_FORMAT_ARGS(state->ReadRecPtr)); + LSN_FORMAT_ARGS(lsn)); goto err; } if (!blk->has_data && blk->data_len != 0) @@ -1919,7 +1919,7 @@ DecodeXLogRecord(XLogReaderState *state, report_invalid_record(state, "BKPBLOCK_HAS_DATA not set, but data length is %d at %X/%08X", blk->data_len, - LSN_FORMAT_ARGS(state->ReadRecPtr)); + LSN_FORMAT_ARGS(lsn)); goto err; } datatotal += blk->data_len; @@ -1957,7 +1957,7 @@ DecodeXLogRecord(XLogReaderState *state, blk->hole_offset, blk->hole_length, blk->bimg_len, - LSN_FORMAT_ARGS(state->ReadRecPtr)); + LSN_FORMAT_ARGS(lsn)); goto err; } @@ -1972,7 +1972,7 @@ DecodeXLogRecord(XLogReaderState *state, "BKPIMAGE_HAS_HOLE not set, but hole offset %d length %d at %X/%08X", blk->hole_offset, blk->hole_length, - LSN_FORMAT_ARGS(state->ReadRecPtr)); + LSN_FORMAT_ARGS(lsn)); goto err; } @@ -1985,7 +1985,7 @@ DecodeXLogRecord(XLogReaderState *state, report_invalid_record(state, "BKPIMAGE_COMPRESSED set, but block image length %d at %X/%08X", blk->bimg_len, - LSN_FORMAT_ARGS(state->ReadRecPtr)); + LSN_FORMAT_ARGS(lsn)); goto err; } @@ -2000,7 +2000,7 @@ DecodeXLogRecord(XLogReaderState *state, report_invalid_record(state, "neither BKPIMAGE_HAS_HOLE nor BKPIMAGE_COMPRESSED set, but block image length is %d at %X/%08X", blk->bimg_len, - LSN_FORMAT_ARGS(state->ReadRecPtr)); + LSN_FORMAT_ARGS(lsn)); goto err; } } @@ -2015,7 +2015,7 @@ DecodeXLogRecord(XLogReaderState *state, { report_invalid_record(state, "BKPBLOCK_SAME_REL set but no previous rel at %X/%08X", - LSN_FORMAT_ARGS(state->ReadRecPtr)); + LSN_FORMAT_ARGS(lsn)); goto err; } @@ -2027,7 +2027,7 @@ DecodeXLogRecord(XLogReaderState *state, { report_invalid_record(state, "invalid block_id %u at %X/%08X", - block_id, LSN_FORMAT_ARGS(state->ReadRecPtr)); + block_id, LSN_FORMAT_ARGS(lsn)); goto err; } } @@ -2094,7 +2094,7 @@ DecodeXLogRecord(XLogReaderState *state, shortdata_err: report_invalid_record(state, "record with invalid length at %X/%08X", - LSN_FORMAT_ARGS(state->ReadRecPtr)); + LSN_FORMAT_ARGS(lsn)); err: *errormsg = state->errormsg_buf; diff --git a/src/bin/pg_waldump/t/001_basic.pl b/src/bin/pg_waldump/t/001_basic.pl index 7b33efc629..c345b07ef4 100644 --- a/src/bin/pg_waldump/t/001_basic.pl +++ b/src/bin/pg_waldump/t/001_basic.pl @@ -509,4 +509,114 @@ for my $scenario (@scenarios) } } +# Check the LSN reported for a record that is rejected while it is decoded. +# Update a row right after a checkpoint, so that the update record carries a +# full-page image of a page with a hole. In a copy of the WAL segment, clear +# the image's hole offset and recompute the record's CRC, so that the record +# passes the CRC check but fails DecodeXLogRecord()'s checks. +$node->start; +$node->safe_psql('postgres', + 'CREATE TABLE t_bad_fpi (a int); INSERT INTO t_bad_fpi VALUES (1);'); +my $bad_fpi_rel = join('/', + $default_ts_oid, $postgres_db_oid, + $node->safe_psql('postgres', q{SELECT pg_relation_filenode('t_bad_fpi')})); +my $wal_block_size = $node->safe_psql('postgres', 'SHOW wal_block_size'); +my $wal_segment_size = $node->safe_psql('postgres', + q{SELECT setting FROM pg_settings WHERE name = 'wal_segment_size'}); + +# Retry until the record fits on one WAL page and doesn't start right after a +# page header, so that it can be patched in place and starts where the +# previous record ends. +my ($bad_lsn, $bad_prev, $bad_len, $bad_off); +foreach my $try (1 .. 10) +{ + my $from = $node->safe_psql('postgres', 'SELECT pg_current_wal_insert_lsn()'); + $node->safe_psql('postgres', 'CHECKPOINT; UPDATE t_bad_fpi SET a = a + 1;'); + my $to = $node->safe_psql('postgres', 'SELECT pg_current_wal_insert_lsn()'); + my ($stdout, $stderr); + IPC::Run::run [ + 'pg_waldump', + '--path' => $node->data_dir . '/pg_wal', + '--start' => $from, + '--end' => $to, + '--relation' => $bad_fpi_rel, + '--fullpage' + ], + '>' => \$stdout, + '2>' => \$stderr; + next + unless $stdout =~ + m{len \(rec/tot\):\s*\d+/\s*(\d+), .* lsn: ([0-9A-F]+/[0-9A-F]+), prev ([0-9A-F]+/[0-9A-F]+)}; + ($bad_len, $bad_lsn, $bad_prev) = ($1, $2, $3); + + # The segment and page sizes divide 2^32, so the low half is enough. + my $lsn_lo = hex((split m{/}, $bad_lsn)[1]); + my $page_off = $lsn_lo % $wal_block_size; + $bad_off = $lsn_lo % $wal_segment_size; + last if $page_off > 40 && $page_off + $bad_len <= $wal_block_size; + undef $bad_lsn; +} +ok(defined $bad_lsn, 'found a record with a full-page image to corrupt'); + +my $bad_walfile = + $node->safe_psql('postgres', "SELECT pg_walfile_name('$bad_lsn')"); +my $rec; +open(my $wal_fh, '<', $node->data_dir . "/pg_wal/$bad_walfile") + or BAIL_OUT("open failed: $!"); +binmode $wal_fh; +sysseek($wal_fh, $bad_off, 0) + or BAIL_OUT("sysseek failed: $!"); +sysread($wal_fh, $rec, $bad_len) == $bad_len + or BAIL_OUT("sysread failed: $!"); +close($wal_fh); + +# The record's CRC covers the data after the 24-byte header, followed by the +# header up to xl_crc. +sub record_crc +{ + my ($rec) = @_; + my $hex = unpack('H*', substr($rec, 24) . substr($rec, 0, 20)); + return $node->safe_psql('postgres', "SELECT crc32c('\\x$hex'::bytea)"); +} +is(record_crc($rec), unpack('V', substr($rec, 20, 4)), + 'CRC computed for the original record'); + +# The first block header (id, fork_flags, data_length) is followed by the +# image header (length, hole_offset, bimg_info). +my ($block_id, $fork_flags, undef, undef, undef, $bimg_info) = + unpack('C C v v v C', substr($rec, 24, 9)); +ok( $block_id == 0 + && ($fork_flags & 0x10) # BKPBLOCK_HAS_IMAGE + && ($bimg_info & 0x01) # BKPIMAGE_HAS_HOLE + && !($bimg_info & 0x1C), # not compressed + 'block 0 carries an uncompressed full-page image with a hole'); + +substr($rec, 30, 2) = pack('v', 0); # hole_offset +substr($rec, 20, 4) = pack('V', record_crc($rec)); +$node->stop; + +my $bad_wal_dir = PostgreSQL::Test::Utils::tempdir_short(); +copy($node->data_dir . "/pg_wal/$bad_walfile", "$bad_wal_dir/$bad_walfile") + || die "copying $bad_walfile $!"; +open($wal_fh, '+<', "$bad_wal_dir/$bad_walfile") + or BAIL_OUT("open failed: $!"); +binmode $wal_fh; +sysseek($wal_fh, $bad_off, 0) + or BAIL_OUT("sysseek failed: $!"); +syswrite($wal_fh, $rec) == $bad_len + or BAIL_OUT("syswrite failed: $!"); +close($wal_fh) + or BAIL_OUT("close failed: $!"); + +my $bad_fpi_error = + qr{BKPIMAGE_HAS_HOLE set, but hole offset 0 length \d+ block image length \d+ at \Q$bad_lsn\E}; +command_fails_like( + [ 'pg_waldump', '--path' => $bad_wal_dir, '--start' => $bad_prev ], + qr{error in WAL record at [0-9A-F]+/[0-9A-F]+: $bad_fpi_error}, + 'decoding error names the rejected record'); +command_fails_like( + [ 'pg_waldump', '--path' => $bad_wal_dir, '--start' => $bad_lsn ], + qr{could not find a valid record after \Q$bad_lsn\E: $bad_fpi_error}, + 'decoding error names the rejected record when starting at it'); + done_testing(); -- 2.50.1 (Apple Git-155)