Thread: pg_waldump error message fix

pg_waldump error message fix

From
"Bossart, Nathan"
Date:
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


Re: pg_waldump error message fix

From
Kyotaro Horiguchi
Date:
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



Re: pg_waldump error message fix

From
Michael Paquier
Date:
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

Re: pg_waldump error message fix

From
Kyotaro Horiguchi
Date:
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



Re: pg_waldump error message fix

From
Kyotaro Horiguchi
Date:
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



Re: pg_waldump error message fix

From
"Bossart, Nathan"
Date:
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


Re: pg_waldump error message fix

From
Kyotaro Horiguchi
Date:
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



Re: pg_waldump error message fix

From
Kyotaro Horiguchi
Date:
> 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


Re: pg_waldump error message fix

From
Michael Paquier
Date:
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

Re: pg_waldump error message fix

From
Michael Paquier
Date:
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

Re: pg_waldump error message fix

From
"Bossart, Nathan"
Date:
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