Wrong LSN in WAL decoding error messages

Hi Rahul,

Thanks for the patches. I reviewed both, and tested 0001 on REL_19_STABLE
(3f5bfbce4c4) and 0001+0002 on master.

0001 looks right to me. The other checks in XLogDecodeNextRecord() already
report RecPtr; DecodeXLogRecord() is the only place that uses
ReadRecPtr, and that pointer has been unreliable there since 3f1ce97346.
You also correctly left RestoreBlockImage() alone, it only runs on a record
that has already been returned (redo, pg_waldump
--save-fullpage, pg_walinspect), so ReadRecPtr really is that record.

Thanks to the reproducing steps, I reproduced it the same way you did.
hole_offset set to 0 in an uncompressed FPI, CRC recomputed. I crashed a
cluster with kill -9
partway through a transaction after a checkpoint, then corrupted an FPI
from that transaction, at 0/01821288.

Crash recovery reported these LSNs (in all cases "redo done at 0/01821248"):

recovery_prefetch=try recovery_prefetch=off
unpatched 0/0180F608 0/01821248
patched 0/01821288 0/01821288

With prefetching on, the unpatched message named the redo start point, 45
records (about 71kB) before the bad record.
The prefetcher had decoded that whole span in one go before redo got its
second record,
so ReadRecPtr was still at the redo point. So "several records back" in the
commit message undersells it a bit.
With recovery_prefetch on, the LSN can be anywhere in the read-ahead
window, and here it was the redo point. It might be worth saying that.

The patched and unpatched clusters ended up the same, i.e same stop point,
same rows, and byte-identical relation files (pg_control differed only
in timestamps). So 0001 changes only the message, which makes it an easy
backpatch.

One more case for pg_waldump, from a separate WAL segment (an initdb
template, not the cluster above) with the same corruption applied to
the FPI at 0/010165F8. When pg_waldump is started at the bad record (-s
0/010165F8), the unpatched build reports

"could not find a valid record after 0/010165F8: ... at 0/01016568"

which is an LSN before the requested start. With 0001 it names 0/010165F8.

A few comments:
1. The WAL_DEBUG caller in XLogInsertRecord() passes EndPos, so after the
patch those messages show the end of the record rather than its
start. As you say, that matches what that code logs. It's still an
improvement, because debug_reader is never positioned, so the
messages printed 0/00000000 before. A line in the commit message would make
the difference from the other caller clear.

2. Could we have a test? pg_waldump's 001_basic.pl checks the "error in WAL
record at" message only for falling off the end of WAL, and
only matches the prefix. Patching two bytes of an FPI and fixing the CRC is
easy enough in Perl, and a check that the reported LSN equals
the record's LSN would cover both 0001 and 0002. I'm happy to share the
script I used if that helps.

3. pg_walinspect passes the same message through, so users of
pg_get_wal_records_info() will benefit from 0001 too.

Reaging the 0002:
+1. It does what pg_rewind's extractPageMap() and pg_walinspect's
ReadNextXLogRecord() already do when XLogReadRecord() fails, and with
the prefix and the message agree at the normal end of WAL. I agree about
keeping it to master.

Regards,
Surya Poondla

Hi Surya,

Thanks for the review, and for testing on 19 and master.  Your
recovery_prefetch numbers show the problem much better than mine did.

v2 attached:

- 0001's commit message now says that with recovery_prefetch the
  message can name any record in the read-ahead window, with your
  redo start point as the example, and that pg_walinspect reports the
  same messages (your point 3).

- It also says the WAL_DEBUG messages now show the end of the
  inserted record, where they printed 0/00000000 before (point 1).

- 0001 adds a test to pg_waldump's 001_basic.pl (point 2).  It
  updates a row right after a checkpoint, so that the update record
  carries a full-page image with a hole, clears the hole offset in a
  copy of the WAL segment, and recomputes the record's CRC with
  crc32c().  It then checks that pg_waldump names that record, both
  when started before it and when started at it, your second
  pg_waldump case.  0002 extends it to check the "error in WAL record
  at" prefix too.  Without the fixes, those checks fail.

Thanks for offering your script.  Recomputing the CRC with crc32c()
kept the test short, but that function only exists from 18 on, so the
test can't go back further than that with 0001.

Regards,
Rahul Yadav

Hi Rahul,

Thanks for v2. It addresses everything I raised.

I tested it on REL_19_STABLE (1a1248818fb) and master (9e7d152488f).
Both patches apply cleanly and build without warnings, and the code
changes are the same as in v1. The pg_waldump TAP tests pass, and the new
checks behave as you described:

All tests pass with v2.

without 0002's C change: only the "error in WAL record at" prefix check
fails
without both C changes: both LSN checks fail

Without the fixes, the start-at-the-bad-record case again names an LSN
before the requested start point (0/017B2B78 when starting at
0/017B2C00 on master), so the test covers that case too.

The commit messages look good to me. As you said, the test needs crc32c(),
which only exists from 18 on, so it can't go back further
than 18, while the code fix goes back to 15.

The patch looks ready for a Committer.

Regards,
Surya Poondla