Various bugs if segment containing redo pointer does not exist

Hi,

I investigated a crashing postgres instance. Turns out the original issue was
operator error. But in the process I found a few postgres issues. The scenario
is basically that redo LSN and checkpoint LSN are in seperate segments, and
that for whatever reason, the file containing the redo LSN is missing.

I'd expect a PANIC in that situation. But, turns out that no such luck.

I've looked at 15 and HEAD so far.

1) For some reason I haven't yet debugged, the ReadRecord(PANIC) in
   PerformWalRecovery() doesn't PANIC, but instead just returns NULL

   We *do* output a DEBUG message, but well, that's insufficient.


2) On HEAD, we then segfault, because the cross check for XLOG_CHECKPOINT_REDO
   causes null pointer dereference. Which I guess is good, we shouldn't have
   gotten there without a record.


3) On 15, with or without assertions, we decide that "redo is not
   required". Gulp.


4) On 15, with assertions enabled, we fail with an assertion in the startup
   process, in FinishWalRecovery()->XLogPrefetcherBeginRead()->XLogBeginRead()
   Assert(!XLogRecPtrIsInvalid(RecPtr))


5) On 15, with optimizations enabled, we don't just crash, it gets scarier.

   First, the startup process actually creates a bogus WAL segment:

#1  0x000055f53b2725ff in XLogFileInitInternal (path=0x7ffccb7b3360 "pg_wal/000000010000000000000000",
added=0x7ffccb7b335f,logtli=1, logsegno=1099511627776)
 
    at /home/andres/src/postgresql-15/src/backend/access/transam/xlog.c:2936
#2  PreallocXlogFiles (endptr=endptr@entry=0, tli=tli@entry=1) at
/home/andres/src/postgresql-15/src/backend/access/transam/xlog.c:3433
#3  0x000055f53b277e00 in PreallocXlogFiles (tli=1, endptr=0) at
/home/andres/src/postgresql-15/src/backend/access/transam/xlog.c:3425
#4  StartupXLOG () at /home/andres/src/postgresql-15/src/backend/access/transam/xlog.c:5517
#5  0x000055f53b4a385e in StartupProcessMain () at /home/andres/src/postgresql-15/src/backend/postmaster/startup.c:282
#6  0x000055f53b49860b in AuxiliaryProcessMain (auxtype=auxtype@entry=StartupProcess)
    at /home/andres/src/postgresql-15/src/backend/postmaster/auxprocess.c:141
#7  0x000055f53b4a2eed in StartChildProcess (type=StartupProcess) at
/home/andres/src/postgresql-15/src/backend/postmaster/postmaster.c:5432
#8  PostmasterMain (argc=argc@entry=39, argv=argv@entry=0x55f53d5095d0) at
/home/andres/src/postgresql-15/src/backend/postmaster/postmaster.c:1473
#9  0x000055f53b1d1bff in main (argc=39, argv=0x55f53d5095d0) at
/home/andres/src/postgresql-15/src/backend/main/main.c:202

    Note the endptr=0 and pg_wal/000000010000000000000000 path.

    With normal log level, one wouldn't learn anything about this.


    Then the *checkpointer* segfaults, trying to write the end-of-recovery
    checkpoint:

#0  __memcpy_evex_unaligned_erms () at ../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S:344
#1  0x000056102ebe84a2 in memcpy (__len=26, __src=0x56102fbe7b48, __dest=<optimized out>) at
/usr/include/x86_64-linux-gnu/bits/string_fortified.h:29
#2  CopyXLogRecordToWAL (tli=1, EndPos=160, StartPos=40, rdata=0x56102f31ffb0 <hdr_rdt>, isLogSwitch=false,
write_len=114)
    at /home/andres/src/postgresql-15/src/backend/access/transam/xlog.c:1229
#3  XLogInsertRecord (rdata=<optimized out>, fpw_lsn=<optimized out>, flags=<optimized out>, num_fpi=0,
topxid_included=<optimizedout>)
 
    at /home/andres/src/postgresql-15/src/backend/access/transam/xlog.c:861
#4  0x000056102ebf12cb in XLogInsert (rmid=rmid@entry=0 '\000', info=info@entry=0 '\000')
    at /home/andres/src/postgresql-15/src/backend/access/transam/xloginsert.c:492
#5  0x000056102ebea92e in CreateCheckPoint (flags=102) at
/home/andres/src/postgresql-15/src/backend/access/transam/xlog.c:6583
#6  0x000056102ee0e552 in CheckpointerMain () at
/home/andres/src/postgresql-15/src/backend/postmaster/checkpointer.c:455
#7  0x000056102ee0c5f9 in AuxiliaryProcessMain (auxtype=auxtype@entry=CheckpointerProcess)
    at /home/andres/src/postgresql-15/src/backend/postmaster/auxprocess.c:153
#8  0x000056102ee12c38 in StartChildProcess (type=CheckpointerProcess) at
/home/andres/src/postgresql-15/src/backend/postmaster/postmaster.c:5432
#9  0x000056102ee16d54 in PostmasterMain (argc=argc@entry=35, argv=argv@entry=0x56102fb6e5d0)
    at /home/andres/src/postgresql-15/src/backend/postmaster/postmaster.c:1466
#10 0x000056102eb45bff in main (argc=35, argv=0x56102fb6e5d0) at
/home/andres/src/postgresql-15/src/backend/main/main.c:202

    The immediate cause of the crash is that GetXLogBuffer() is called with
    ptr=40, which makes GetXLogBuffer() think it can use the cached path,
    because cachedPage is still zero.

    Which in turn is because because the startup process happily initialized
    XLogCtl->Insert.{CurrBytePos,PrevBytePos} with 0s.  Even though it
    initialized RedoRecPtr with the valid redo pointer.

    The checkpointer actually ends up resetting the valid RedoRecPtr with
    bogus content as part of CreateCheckPoint(), due to the bogus CurrBytePos.


6) On 15, with optimizations enabled, we don't just crash, we also
   can't even get to the prior crashes anymore, because *now* we PANIC:

2023-10-23 16:15:07.208 PDT [2554457][startup][:0][] DEBUG:  could not open file "pg_wal/000000010000000000000095": No
suchfile or directory
 
2023-10-23 16:15:07.208 PDT [2554457][startup][:0][] LOG:  redo is not required
2023-10-23 16:15:07.208 PDT [2554457][startup][:0][] PANIC:  invalid magic number 0000 in log segment
000000010000000000000000,offset 0
 
2023-10-23 16:15:07.211 PDT [2554453][postmaster][:0][] LOG:  startup process (PID 2554457) was terminated by signal 6:
Aborted

(rr) bt
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at
./nptl/pthread_kill.c:44
#1  0x00007f7f6abc915f in __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#2  0x00007f7f6ab7b472 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#3  0x00007f7f6ab654b2 in __GI_abort () at ./stdlib/abort.c:79
#4  0x00005566b5983339 in errfinish (filename=<optimized out>, lineno=<optimized out>, funcname=<optimized out>)
    at /home/andres/src/postgresql-15/src/backend/utils/error/elog.c:675
#5  0x00005566b555630c in ReadRecord (xlogprefetcher=0x5566b60fd7c8, emode=emode@entry=23,
fetching_ckpt=fetching_ckpt@entry=false,
 
    replayTLI=replayTLI@entry=1) at /home/andres/src/postgresql-15/src/backend/access/transam/xlogrecovery.c:3082
#6  0x00005566b5557ea0 in FinishWalRecovery () at
/home/andres/src/postgresql-15/src/backend/access/transam/xlogrecovery.c:1454
#7  0x00005566b554ac1c in StartupXLOG () at /home/andres/src/postgresql-15/src/backend/access/transam/xlog.c:5309
#8  0x00005566b577685e in StartupProcessMain () at /home/andres/src/postgresql-15/src/backend/postmaster/startup.c:282
#9  0x00005566b576b60b in AuxiliaryProcessMain (auxtype=auxtype@entry=StartupProcess)
    at /home/andres/src/postgresql-15/src/backend/postmaster/auxprocess.c:141
#10 0x00005566b5775eed in StartChildProcess (type=StartupProcess) at
/home/andres/src/postgresql-15/src/backend/postmaster/postmaster.c:5432
#11 PostmasterMain (argc=argc@entry=39, argv=argv@entry=0x5566b60fb5d0) at
/home/andres/src/postgresql-15/src/backend/postmaster/postmaster.c:1473
#12 0x00005566b54a4bff in main (argc=39, argv=0x5566b60fb5d0) at
/home/andres/src/postgresql-15/src/backend/main/main.c:202

  Of course 000000010000000000000000 has bogus data, it's an invalid
  file. Here we *do* actually PANIC, presumably because the file actually
  exists.


Of course most of this is downstream from the issue of not PANICing in 1). But
it feels like it showcases a serious lack of error checking in StartupXLOG(),
CreateCheckPoint() etc.


Greetings,

Andres Freund