Re: 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