Re: [BUG] Panic due to incorrect missingContrecPtr after promotion
Kyotaro Horiguchi <horikyota.ntt@gmail.com>
From: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
To: michael@paquier.xyz
Cc: simseih@amazon.com, alvherre@alvh.no-ip.org,
pgsql-hackers@postgresql.org
Date: 2022-06-28T07:09:26Z
Lists: pgsql-hackers
Attachments
- detect_aborted_contrec_panic_2.diff (text/x-patch) patch
- abortcont_additional_log.diff (text/x-patch) patch
I'd like to look into the WAL segments related to the failure. Mmm... With the patch, xlogreader->abortedRecPtr is valid only and always when the last read failed record was an aborted contrec. If recovery ends here the first insereted record is an "aborted contrec" record. I still see it as the only chance that an aborted contrecord is followed by a non-"aborted contrec" record is that recovery somehow fetches two consecutive WAL segments that are inconsistent at the boundary. I found the reason that the TAP test doesn't respond to the first proposed patch (the below). - if (!StandbyMode && + if (!StandbyModeRequested && !XLogRecPtrIsInvalid(xlogreader->abortedRecPtr)) The cause was that I disabled standby-mode in the test. The change affects only while standby mode is on, which was to make the test reliable and simpler. The first attached detects the same error (in a somwhat maybe-unstable way) and responds to the fix above, and also responds to the aborted_contrec_reset_3.patch. So, aborted_contrec_reset_3 looks closer to the issue than before. Would you mind trying the second attached to abtain detailed log on your testing environment? With the patch, the modified TAP test yields the log lines like below. 2022-06-28 15:49:20.661 JST [165472] LOG: ### [A] @0/1FFD338: abort=(0/1FFD338)0/0, miss=(0/2000000)0/0, SbyMode=0, SbyModeReq=1 ... 2022-06-28 15:49:20.681 JST [165472] LOG: ### [F] @0/2094610: abort=(0/0)0/1FFD338, miss=(0/0)0/2000000, SbyMode=1, SbyModeReq=1 ... 2022-06-28 15:49:20.767 JST [165472] LOG: ### [S] @0/2094610: abort=(0/0)0/1FFD338, miss=(0/0)0/2000000, SbyMode=0, SbyModeReq=1 ... 2022-06-28 15:49:20.777 JST [165470] PANIC: xlog flush request 0/2094610 is not satisfied --- flushed only to 0/2000088 In this example, abortedRecPtr is set at the first line and recovery continued to 2094610 but abortedRecPtr is not reset then PANICed. ([A] means aborted contrec falure. [F] and [S] are failed and succeeded reads respectively.) regards. -- Kyotaro Horiguchi NTT Open Source Software Center
Commits
-
Prevent WAL corruption after a standby promotion.
- 0b3ff539dd34 10.23 landed
- 002fba80ebde 11.18 landed
- 3c0ef0832748 12.13 landed
- 3f2701cda590 13.9 landed
- 0e54a5e27494 14.6 landed
- eb29fa38895c 15.0 landed
- 6672d7913929 16.0 landed
-
Fix "missing continuation record" after standby promotion
- caaeb88ff7ae 14.3 landed
- c714ebd0e8c1 12.11 landed
- 9d92582abf91 15.0 landed
- 9ade3c09a5d1 10.21 landed
- 98eb3e06ce3a 13.7 landed
- 199cd7b59a16 11.16 landed