Thread: pg_waldump error message fix
Hi,
I noticed that when pg_waldump finds an invalid record, the
corresponding error message seems to point to the last valid record
read.
rmgr: ... lsn: 0/090E5AF8, prev 0/090E59D0, ...
pg_waldump: fatal: error in WAL record at 0/90E5AF8: invalid record length at 0/90E5B30: wanted 24, got 0
Should pg_waldump report currRecPtr instead of ReadRecPtr in the error
message? With that, I see the following.
rmgr: ... lsn: 0/090E5AF8, prev 0/090E59D0, ...
pg_waldump: fatal: error in WAL record at 0/90E5B30: invalid record length at 0/90E5B30: wanted 24, got 0
Here is the patch:
diff --git a/src/bin/pg_waldump/pg_waldump.c b/src/bin/pg_waldump/pg_waldump.c
index 31e99c2a6d..27da60e6db 100644
--- a/src/bin/pg_waldump/pg_waldump.c
+++ b/src/bin/pg_waldump/pg_waldump.c
@@ -1110,8 +1110,8 @@ main(int argc, char **argv)
if (errormsg)
fatal_error("error in WAL record at %X/%X: %s",
- (uint32) (xlogreader_state->ReadRecPtr >> 32),
- (uint32) xlogreader_state->ReadRecPtr,
+ (uint32) (xlogreader_state->currRecPtr >> 32),
+ (uint32) xlogreader_state->currRecPtr,
errormsg);
XLogReaderFree(xlogreader_state);
Nathan
At Thu, 10 Dec 2020 18:47:58 +0000, "Bossart, Nathan" <bossartn@amazon.com> wrote in
> Hi,
>
> I noticed that when pg_waldump finds an invalid record, the
> corresponding error message seems to point to the last valid record
> read.
Good catch!
> rmgr: ... lsn: 0/090E5AF8, prev 0/090E59D0, ...
> pg_waldump: fatal: error in WAL record at 0/90E5AF8: invalid record length at 0/90E5B30: wanted 24, got 0
>
> Should pg_waldump report currRecPtr instead of ReadRecPtr in the error
> message? With that, I see the following.
>
> rmgr: ... lsn: 0/090E5AF8, prev 0/090E59D0, ...
> pg_waldump: fatal: error in WAL record at 0/90E5B30: invalid record length at 0/90E5B30: wanted 24, got 0
>
> Here is the patch:
>
> diff --git a/src/bin/pg_waldump/pg_waldump.c b/src/bin/pg_waldump/pg_waldump.c
> index 31e99c2a6d..27da60e6db 100644
> --- a/src/bin/pg_waldump/pg_waldump.c
> +++ b/src/bin/pg_waldump/pg_waldump.c
> @@ -1110,8 +1110,8 @@ main(int argc, char **argv)
>
> if (errormsg)
> fatal_error("error in WAL record at %X/%X: %s",
> - (uint32) (xlogreader_state->ReadRecPtr >> 32),
> - (uint32) xlogreader_state->ReadRecPtr,
> + (uint32) (xlogreader_state->currRecPtr >> 32),
> + (uint32) xlogreader_state->currRecPtr,
> errormsg);
>
> XLogReaderFree(xlogreader_state);
currRecPtr is a private member of the struct (see the definition of
the struct XLogReaderState). We should instead use EndRecPtr outside
xlog reader.
regardes.
--
Kyotaro Horiguchi
NTT Open Source Software Center
On Fri, Dec 11, 2020 at 01:30:16PM +0900, Kyotaro Horiguchi wrote: > currRecPtr is a private member of the struct (see the definition of > the struct XLogReaderState). We should instead use EndRecPtr outside > xlog reader. Please note that this is documented in xlogreader.h. Hmm. I can see your point here, still I think that what both of you are suggesting is not completely correct. For example, switching to EndRecPtr would cause DecodeXLogRecord() to report an error with the end of the current record but it makes more sense to point to ReadRecPtr in this case. On the other hand, it would make sense to report the beginning of the position we are working on when validating the header if an error happens at this point. So it seems to me that EndRecPtr or ReadRecPtr are not completely correct, and that we may need an extra LSN position to tell on which LSN we are working on instead that gets updated before the validation part, because we update ReadRecPtr and EndRecPtr only after this initial validation is done. -- Michael
Attachment
At Fri, 11 Dec 2020 14:21:57 +0900, Michael Paquier <michael@paquier.xyz> wrote in > On Fri, Dec 11, 2020 at 01:30:16PM +0900, Kyotaro Horiguchi wrote: > > currRecPtr is a private member of the struct (see the definition of > > the struct XLogReaderState). We should instead use EndRecPtr outside > > xlog reader. > > Please note that this is documented in xlogreader.h. Hmm. I can see > your point here, still I think that what both of you are suggesting > is not completely correct. For example, switching to EndRecPtr would EndRecPtr is defined as it points to the LSN to start reading the next record. It donsn't move if XLogReadRecord failed to read the record. I think this is documented in a comment somewhere. It can point to the beginning of a page so "error in WAL record at <page start>" is a kind of bogus but that is not the point here. > cause DecodeXLogRecord() to report an error with the end of the > current record but it makes more sense to point to ReadRecPtr in this DecodeXLogRecord() handles a record alread successflly read. So ReadRecPtr is pointing to the beginning of the given record at the timex. pg_waldump:main() and ReadRecrod (or the context of DecodeXLogRecord()) are in different contexts. The place in question in pg_waldump seems to be a result of a thinko that it can use ReadRecPtr regardless of whether XLogReadRecrod successfully read a record or not. > case. On the other hand, it would make sense to report the beginning > of the position we are working on when validating the header if an > error happens at this point. So it seems to me that EndRecPtr or > ReadRecPtr are not completely correct, and that we may need an extra > LSN position to tell on which LSN we are working on instead that gets > updated before the validation part, because we update ReadRecPtr and > EndRecPtr only after this initial validation is done. So we cannot use the ErrorRecPtr since pg_waldump:main() shoud show the LSN XLogReadRecord() found a invalid record and DecodeXLogRecord() should show the LSN XLogReadRecord() found a valid record. regards. -- Kyotaro Horiguchi NTT Open Source Software Center
At Fri, 11 Dec 2020 17:19:33 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in > At Fri, 11 Dec 2020 14:21:57 +0900, Michael Paquier <michael@paquier.xyz> wrote in > > On Fri, Dec 11, 2020 at 01:30:16PM +0900, Kyotaro Horiguchi wrote: > > > currRecPtr is a private member of the struct (see the definition of > > > the struct XLogReaderState). We should instead use EndRecPtr outside > > > xlog reader. > > > > Please note that this is documented in xlogreader.h. Hmm. I can see > > your point here, still I think that what both of you are suggesting > > is not completely correct. For example, switching to EndRecPtr would > > EndRecPtr is defined as it points to the LSN to start reading the next > record. It donsn't move if XLogReadRecord failed to read the > record. I think this is documented in a comment somewhere. It can > point to the beginning of a page so "error in WAL record at <page > start>" is a kind of bogus but that is not the point here. > > > cause DecodeXLogRecord() to report an error with the end of the > > current record but it makes more sense to point to ReadRecPtr in this > > DecodeXLogRecord() handles a record alread successflly read. So > ReadRecPtr is pointing to the beginning of the given record at the > timex. pg_waldump:main() and ReadRecrod (or the context of > DecodeXLogRecord()) are in different contexts. The place in question > in pg_waldump seems to be a result of a thinko that it can use > ReadRecPtr regardless of whether XLogReadRecrod successfully read a > record or not. > > > case. On the other hand, it would make sense to report the beginning > > of the position we are working on when validating the header if an > > error happens at this point. So it seems to me that EndRecPtr or > > ReadRecPtr are not completely correct, and that we may need an extra > > LSN position to tell on which LSN we are working on instead that gets > > updated before the validation part, because we update ReadRecPtr and > > EndRecPtr only after this initial validation is done. > > So we cannot use the ErrorRecPtr since pg_waldump:main() shoud show > the LSN XLogReadRecord() found a invalid record and DecodeXLogRecord() > should show the LSN XLogReadRecord() found a valid record. Wait! That's wrong. Yeah, we can add ErrorRecPtr to point the error record regardless of the context. regards. -- Kyotaro Horiguchi NTT Open Source Software Center
On 12/10/20, 9:23 PM, "Michael Paquier" <michael@paquier.xyz> wrote: > Please note that this is documented in xlogreader.h. Hmm. I can see > your point here, still I think that what both of you are suggesting > is not completely correct. For example, switching to EndRecPtr would > cause DecodeXLogRecord() to report an error with the end of the > current record but it makes more sense to point to ReadRecPtr in this > case. On the other hand, it would make sense to report the beginning > of the position we are working on when validating the header if an > error happens at this point. So it seems to me that EndRecPtr or > ReadRecPtr are not completely correct, and that we may need an extra > LSN position to tell on which LSN we are working on instead that gets > updated before the validation part, because we update ReadRecPtr and > EndRecPtr only after this initial validation is done. I looked through all the calls to report_invalid_record() in xlogreader.c and noticed that all but a few in XLogReaderValidatePageHeader() already report an LSN. Of the calls in XLogReaderValidatePageHeader() that don't report an LSN, it looks like most still report a position, and the remaining ones are for "WAL file is from different database system...," which IIUC generally happens on the first page of the segment. Perhaps we could simply omit the LSN in the pg_waldump message. Nathan
At Fri, 11 Dec 2020 19:27:31 +0000, "Bossart, Nathan" <bossartn@amazon.com> wrote in > On 12/10/20, 9:23 PM, "Michael Paquier" <michael@paquier.xyz> wrote: > > Please note that this is documented in xlogreader.h. Hmm. I can see > > your point here, still I think that what both of you are suggesting > > is not completely correct. For example, switching to EndRecPtr would > > cause DecodeXLogRecord() to report an error with the end of the > > current record but it makes more sense to point to ReadRecPtr in this > > case. On the other hand, it would make sense to report the beginning > > of the position we are working on when validating the header if an > > error happens at this point. So it seems to me that EndRecPtr or > > ReadRecPtr are not completely correct, and that we may need an extra > > LSN position to tell on which LSN we are working on instead that gets > > updated before the validation part, because we update ReadRecPtr and > > EndRecPtr only after this initial validation is done. > > I looked through all the calls to report_invalid_record() in > xlogreader.c and noticed that all but a few in > XLogReaderValidatePageHeader() already report an LSN. Of the calls in > XLogReaderValidatePageHeader() that don't report an LSN, it looks like > most still report a position, and the remaining ones are for "WAL file > is from different database system...," which IIUC generally happens on > the first page of the segment. > > Perhaps we could simply omit the LSN in the pg_waldump message. Yeah, I had the same feeling. At least, the two LSNs in the message under discussion are simply redundant. So +1 to just remove the LSN at the caller site. regards. -- Kyotaro Horiguchi NTT Open Source Software Center
> At Fri, 11 Dec 2020 19:27:31 +0000, "Bossart, Nathan" <bossartn@amazon.com> wrote in > > I looked through all the calls to report_invalid_record() in > > xlogreader.c and noticed that all but a few in > > XLogReaderValidatePageHeader() already report an LSN. Of the calls in > > XLogReaderValidatePageHeader() that don't report an LSN, it looks like > > most still report a position, and the remaining ones are for "WAL file > > is from different database system...," which IIUC generally happens on > > the first page of the segment. Apart from this issue, while checking that, I noticed that if server starts having WALs from a server of a different systemid, the server stops with obscure messages. > LOG: database system was shut down at 2020-12-14 10:36:02 JST > LOG: invalid primary checkpoint record > PANIC: could not locate a valid checkpoint record The cause is XLogPageRead erases the error message set by XLogReaderValidatePageHeader(). As the comment just above says, this is required to continue replication under a certain situation. The code is aiming to allow continue replication when the first half of a continued record has been removed on the primary so we don't need to do the amendment unless we're in standby mode. If we let the savior code only while StandbyMode, we would have the correct error message. > JST LOG: database system was shut down at 2020-12-14 10:36:02 JST > LOG: WAL file is from different database system: WAL file database system identifier is 6905923817995618754, pg_controldatabase system identifier is 6905924227171453468 > JST LOG: invalid primary checkpoint record > JST PANIC: could not locate a valid checkpoint record I confirmed 0668719801 still works under the intended context using the steps shown in [1]. [1]: https://www.postgresql.org/message-id/flat/CACJqAM3xVz0JY1XFDKPP%2BJoJAjoGx%3DGNuOAshEDWCext7BFvCQ%40mail.gmail.com regards. -- Kyotaro Horiguchi NTT Open Source Software Center From d54531aa2774bad7e426cc16691553fbc8f0b3b3 Mon Sep 17 00:00:00 2001 From: Kyotaro Horiguchi <horikyoga.ntt@gmail.com> Date: Mon, 14 Dec 2020 11:18:08 +0900 Subject: [PATCH] Don't cancel invalid-page-header error in unwanted situation The commit 0668719801 is intending to work while streaming replication but it cancels the error message regardless of the context. As the result ReadRecord fails to show the correct error messages even when it is required, that is, not while replication. Allowing the cancellation happen only on non-standby fixes that. --- src/backend/access/transam/xlog.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index 7e81ce4f17..770902518d 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -12055,7 +12055,8 @@ retry: * Validating the page header is cheap enough that doing it twice * shouldn't be a big deal from a performance point of view. */ - if (!XLogReaderValidatePageHeader(xlogreader, targetPagePtr, readBuf)) + if (StandbyMode && + !XLogReaderValidatePageHeader(xlogreader, targetPagePtr, readBuf)) { /* reset any error XLogReaderValidatePageHeader() might have set */ xlogreader->errormsg_buf[0] = '\0'; -- 2.27.0
On Mon, Dec 14, 2020 at 10:26:01AM +0900, Kyotaro Horiguchi wrote: > Yeah, I had the same feeling. At least, the two LSNs in the message > under discussion are simply redundant. So +1 to just remove the LSN at > the caller site. That would mean that we are ready to accept that we will never forget to a LSN in any of the messages produced by xlogreader.c or any of the callbacks used by pg_waldump. FWIW, I'd rather let a position in this report than none. At least it allows users to know the area where the problem happened. -- Michael
Attachment
On Mon, Dec 14, 2020 at 11:34:51AM +0900, Kyotaro Horiguchi wrote: > Apart from this issue, while checking that, I noticed that if server > starts having WALs from a server of a different systemid, the server > stops with obscure messages. Wouldn't it be better to discuss that on a separate thread? I have mostly missed your message here. -- Michael
Attachment
On 12/13/20, 7:01 PM, "Michael Paquier" <michael@paquier.xyz> wrote: > On Mon, Dec 14, 2020 at 10:26:01AM +0900, Kyotaro Horiguchi wrote: >> Yeah, I had the same feeling. At least, the two LSNs in the message >> under discussion are simply redundant. So +1 to just remove the LSN at >> the caller site. > > That would mean that we are ready to accept that we will never forget > to a LSN in any of the messages produced by xlogreader.c or any of the > callbacks used by pg_waldump. FWIW, I'd rather let a position in this > report than none. At least it allows users to know the area where the > problem happened. Yeah. Unfortunately, I suspect we will have the same problem if we add a new variable that we only use to track the LSN to report for errors. Nathan