Subject: Re: [BUG] Panic due to incorrect missingContrecPtr after promotion

From: Kyotaro Horiguchi <[email-masked]>
Date: Thu, 24 Feb 2022 17:27:03 +0900 (JST)

At Thu, 24 Feb 2022 16:26:42 +0900 (JST), Kyotaro Horiguchi <[email-masked]> wrote in 
> So, actually WAL did not ended in an incomplete record.  I think
> FinishWalRecover is the last place to do that. (But it could be
> earlier.)

After some investigation, I finally concluded that we should reset
abortedRecPtr and missingContrecPtr at processing
XLOG_OVERWRITE_CONTRECORD.

--- a/src/backend/access/transam/xlogrecovery.c
+++ b/src/backend/access/transam/xlogrecovery.c
@@ -1953,6 +1953,11 @@ xlogrecovery_redo(XLogReaderState *record, TimeLineID replayTLI)
                                                LSN_FORMAT_ARGS(xlrec.overwritten_lsn),
                                                timestamptz_to_str(xlrec.overwrite_time))));
 
+               /* We have safely skipped the aborted record */
+               abortedRecPtr = InvalidXLogRecPtr;
+               missingContrecPtr = InvalidXLogRecPtr;
+
                /* Verifying the record should only happen once */
                record->overwrittenRecPtr = InvalidXLogRecPtr;
        }

The last check in the test against "resetting aborted record" is no
longer useful since it is already checked by
026_verwrite_contrecord.pl.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

---

From: "Imseih (AWS), Sami" <[email-masked]>
Date: Fri, 25 Feb 2022 21:28:18 +0000

>    regards.

+1 for this. Resetting abortedRecPtr and missingContrecPtr after the broken record is skipped in is cleaner. I also think it would make sense to move the " successfully skipped missing contrecord" to after we invalidate the aborted and missing record pointers, like below.

+++ b/src/backend/access/transam/xlogrecovery.c
@@ -1948,15 +1948,15 @@ xlogrecovery_redo(XLogReaderState *record, TimeLineID replayTLI)
                                 LSN_FORMAT_ARGS(xlrec.overwritten_lsn),
                                 LSN_FORMAT_ARGS(record->overwrittenRecPtr));

                ereport(LOG,
                                (errmsg("successfully skipped missing contrecord at %X/%X, overwritten at %s",

Also, instead of a new test, the current 026_overwrite_contrecord.pl test can include a promotion test at the end.

Attaching a new patch for review.

 --
Sami Imseih
Amazon Web Services

---

From: "Imseih (AWS), Sami" <[email-masked]>
Date: Mon, 7 Mar 2022 20:34:12 +0000

I have gone ahead and backpatched this all the way to 10 as well.

 --
 Sami Imseih
 Amazon Web Services

---

From: "[email-masked]" <[email-masked]>
Date: Wed, 23 Mar 2022 18:24:49 +0100

> I have gone ahead and backpatched this all the way to 10 as well.

Thanks!  I pushed this now.  I edited the test though: I don't
understand why you went to the trouble of setting stuff in order to call
'pg_ctl promote' (in different ways for older branches), when
$node_standby->promote does the same and is simpler to call.  So I
changed the tests to do that.  (I did verify that without the code fix,
the PANIC indeed is thrown.)

Thank again,

-- 
Álvaro Herrera        Breisgau, Deutschland  —  https://www.EnterpriseDB.com/

---

From: "Imseih (AWS), Sami" <[email-masked]>
Date: Thu, 26 May 2022 19:57:41 +0000

We see another occurrence of this bug with the last patch applied in 13.7.

After a promotion we observe the following in the logs:

2022-05-25 00:35:38 UTC::@:[371]:PANIC: xlog flush request 10/B1FA3D88 is not satisfied --- flushed only to 7/A8000060
2022-05-25 00:35:38 UTC:172.31.26.238(38610):administrator@postgres:[23433]:ERROR: current transaction is aborted, commands ignored until end of transaction block

However, The logs do not show "LOG: successfully skipped missing contrecord",
therefore we know that  VerifyOverwriteContrecord 
is not being called to invalidate the missingContrecPtr.

VerifyOverwriteContrecord(xl_overwrite_contrecord *xlrec, XLogReaderState *state)
{
   if (xlrec->overwritten_lsn != state->overwrittenRecPtr)
       elog(FATAL, "mismatching overwritten LSN %X/%X -> %X/%X",
            (uint32) (xlrec->overwritten_lsn >> 32),
            (uint32) xlrec->overwritten_lsn,
            (uint32) (state->overwrittenRecPtr >> 32),
            (uint32) state->overwrittenRecPtr);

   /* We have safely skipped the aborted record */
   abortedRecPtr = InvalidXLogRecPtr;
   missingContrecPtr = InvalidXLogRecPtr;

   ereport(LOG,
           (errmsg("successfully skipped missing contrecord at %X/%X, overwritten at %s",
                   (uint32) (xlrec->overwritten_lsn >> 32),
                   (uint32) xlrec->overwritten_lsn,
                   timestamptz_to_str(xlrec->overwrite_time))));

We think it's because VerifyOverwriteContrecord was not 
called which is why we see this behavior. 

Are there are  other places where missingContrecPtr 
should be invalidated, such as after a successful promotion?

--
Sami Imseih
Amazon Web Services

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Fri, 27 May 2022 10:59:24 +0900 (JST)

At Thu, 26 May 2022 19:57:41 +0000, "Imseih (AWS), Sami" <[email-masked]> wrote in 
> After a promotion we observe the following in the logs:
...
> should be invalidated, such as after a successful promotion?

The only cause known to me for EndOfLog being moved to such location
is missingContrecPtr. But if the next record is not
XLOG_OVERWRITE_CONTRECORD recovery should have stopped there. And if
XLOG_OVERWRITE_CONTRECORD is there, VerifyOverwriteContrecord should
have been called..

Could you inspect WAL files of the environment and see if the first
record of the '7/A8'th segment OVERWRITE_CONTRECORD?  I don't say that
makes some progress on this, but could be the first step.

regards.

---

From: "Imseih (AWS), Sami" <[email-masked]>
Date: Fri, 27 May 2022 02:01:27 +0000

After further research, we found the following.

Testing on 13.6 with the attached patch we see
that the missingContrecPtr is being incorrectly
set on the standby and the promote in the tap
test fails.

Per the comments in xlog.c, the
missingContrecPtr should not be set when
in standby mode.

            /*
             * When not in standby mode we find that WAL ends in an incomplete
             * record, keep track of that record.  After recovery is done,
             * we'll write a record to indicate downstream WAL readers that
             * that portion is to be ignored.
             */
            if (!StandbyMode &&
                !XLogRecPtrIsInvalid(xlogreader->abortedRecPtr))
            {
                abortedRecPtr = xlogreader->abortedRecPtr;
                missingContrecPtr = xlogreader->missingContrecPtr;
                elog(LOG, "missingContrecPtr == %ld", missingContrecPtr);
            }

If StandbyModeRequested is checked instead, which
checks for the presence of a standby signal file,
The missingContrecPtr is not set on the
standby and the test succeeds.

            if (!StandbyModeRequested &&
                !XLogRecPtrIsInvalid(xlogreader->abortedRecPtr))
            {
                abortedRecPtr = xlogreader->abortedRecPtr;
                missingContrecPtr = xlogreader->missingContrecPtr;
                elog(LOG, "missingContrecPtr == %ld", missingContrecPtr);
            }

If this is a bug as it appears, it appears the original patch
to resolve this issue is not needed and the ideal fix
Is to ensure that a standby does not set
missingContrecPtr.

Would like to see what others think.

Thanks

--
Sami Imseih
Amazon Web Services

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Fri, 27 May 2022 15:37:35 +0900 (JST)

At Fri, 27 May 2022 02:01:27 +0000, "Imseih (AWS), Sami" <[email-masked]> wrote in 
> Would like to see what others think.

Due to lack of information, I don't have a clear idea of what is
happening here. If that change "fixed" the "issue", that seems to mean
that crash recovery passed an immature contrecord (@6/A8000060) but
recovery did not stop at the time then continues until 10/B1FA3D88.  A
possibility is, crash recovery ended at the immature contrecord then
the server moved to archive recovery mode and was able to continue
from the same (aborted) LSN on the archived WAL. This means 6/A8 in
pg_wal had been somehow removed after archived, or the segment 6/A7
(not A8) in both pg_xlog and archive are in different histories, which
seems to me what we wanted to prevent by the
XLOG_OVERWRITE_CONTRECORD.  Didn't you use the same archive content
for repeated recovery testing?

And from the fact that entering crash recovery means the cluster
didn't have an idea of how far it should recover until consistency,
that is contained in backup label control file.  That could happen
when a crashed primary is as-is reused as the new standby of the new
primary.

So.. I'd like to hear exactly what you did as the testing.

When standby mode is requested, if crash recovery fails with immature
contrecord, I think we shouldn't continue recovery. But I'm not sure
we need to explictly reject that case.  Further study is needed..

regards.

---

From: "Imseih (AWS), Sami" <[email-masked]>
Date: Fri, 27 May 2022 19:01:37 +0000

>    we need to explictly reject that case.  Further study is needed..

Here is more details about my findings and testing.

Even with commit 9d92582abf918215d27659d45a4c9e78bda50aff 
we still see the issue with post promotion checkpoint
resulting in "request to flush past end of generated WAL;"

i.e.

2022-05-25 00:35:38 UTC::@:[371]:LOG:  checkpoint starting: immediate force wait wal time
2022-05-25 00:35:38 UTC::@:[371]:LOG:  request to flush past end of generated WAL; request 10/B1FA3D88, currpos 7/A8000060
2022-05-25 00:35:38 UTC::@:[371]:PANIC:  xlog flush request 10/B1FA3D88 is not satisfied --- flushed only to 7/A8000060
2022-05-25 00:35:38 UTC:172.31.26.238(38610):administrator@postgres:[23433]:ERROR:  current transaction is aborted, commands ignored until end of transaction block

The intent of commit 9d92582abf918215d27659d45a4c9e78bda50aff 
was to make sure the standby skips the overwrite contrecord.

However, we still see "missingContrecPtr" is being set 
on the standby before promotion and after the instance is 
promoted, the missingContrecPtr is written to WAL 
and the subsequent flush throws a "PANIC:  xlog flush request"

To Reproduce using TAP tests; 

1) apply the attached patch 0001-Patch_to_repro.patch to the head branch.
   This patch adds logging when an OverWriteContRecord
   is created and comments out the invalidation code
   added in commit  9d92582abf918215d27659d45a4c9e78bda50aff
   
2) Run a tap test under "test/recovery"
   make check PROVE_TESTS='t/026_overwrite_contrecord.pl'

3) What is observed in the logfiles for both the standby
   and primary instance in the tap test is 
   that an overwrite contrecord is created on the primary, 
   which is correct, but also on the standby after promotion, 
   which is incorrect. This is incorrect as the contrecord

simseih@88665a22795f recovery % cat tmp_check/log/*prim* | grep 'creating\|promo'
2022-05-27 13:17:50.843 CDT [98429] LOG:  creating overwrite contrecord at 0/2000058 for aborted_lsn 0/1FFD000

simseih@88665a22795f recovery % cat tmp_check/log/*stan* | grep 'creating\|promo'
2022-05-27 13:17:51.361 CDT [98421] LOG:  received promote request
2022-05-27 13:17:51.394 CDT [98421] LOG:  creating overwrite contrecord at 0/2000058 for aborted_lsn 0/1FFD000
simseih@88665a22795f recovery %

What we found:

1. missingContrecPtr is set when 
   StandbyMode is false, therefore
   only a writer should set this value
   and a record is then sent downstream.

   But a standby going through crash 
   recovery will always have StandbyMode = false,
   causing the missingContrecPtr to be incorrectly
   set.

2. If StandbyModeRequested is checked instead,
     we ensure that a standby will not set a 
     missingContrecPtr.

3. After applying the patch below, the tap test succeeded

diff --git a/src/backend/access/transam/xlogrecovery.c b/src/backend/access/transam/xlogrecovery.c
index 5ee90b6..a727aaf 100644
--- a/src/backend/access/transam/xlogrecovery.c
+++ b/src/backend/access/transam/xlogrecovery.c
@@ -2977,7 +2977,7 @@ ReadRecord(XLogPrefetcher *xlogprefetcher, int emode,
                         * we'll write a record to indicate to downstream WAL readers that
                         * that portion is to be ignored.
                         */
-                       if (!StandbyMode &&
+                       if (!StandbyModeRequested &&
                                !XLogRecPtrIsInvalid(xlogreader->abortedRecPtr))
                        {
                                abortedRecPtr = xlogreader->abortedRecPtr;

So, it might be that the best fix is not the commit in 9d92582abf918215d27659d45a4c9e78bda50aff
but to check StandbyModeRequested = false before setting 
missingContrecPtr.

Thank you
---
Sami Imseih
Amazon Web Services