Make mesage at end-of-recovery less scary.

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
12 messages Options
Reply | Threaded
Open this post in threaded view
|

Make mesage at end-of-recovery less scary.

Kyotaro Horiguchi-4
Hello, this is a followup thread of [1].

# I didn't noticed that the thread didn't cover -hackers..

When recovery of any type ends, we see several kinds of error messages
that says "WAL is broken".

> LOG:  invalid record length at 0/7CB6BC8: wanted 24, got 0
> LOG:  redo is not required
> LOG:  database system is ready to accept connections

This patch reduces the scariness of such messages as the follows.

> LOG:  rached end of WAL at 0/1551048 on timeline 1 in pg_wal during crash recovery
> DETAIL:  invalid record length at 0/1551048: wanted 24, got 0
> LOG:  redo is not required
> LOG:  database system is ready to accept connections

[1] https://www.postgresql.org/message-id/20200117.172655.1384889922565817808.horikyota.ntt%40gmail.com

I'll register this to the coming CF.

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

From f3692cb484b7f1ebc351ba8a522039c0b91bcfdb Mon Sep 17 00:00:00 2001
From: Kyotaro Horiguchi <[hidden email]>
Date: Fri, 28 Feb 2020 15:52:58 +0900
Subject: [PATCH] Make End-Of-Recovery error less scary

When recovery in any type ends, we see a bit scary error message like
"invalid record length" that suggests something serious is happening.
Make this message less scary as "reached end of WAL".
---
 src/backend/access/transam/xlog.c | 45 ++++++++++++++++++++++++++-----
 1 file changed, 38 insertions(+), 7 deletions(-)

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index d19408b3be..452c376f62 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -4288,6 +4288,10 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
  EndRecPtr = xlogreader->EndRecPtr;
  if (record == NULL)
  {
+ int actual_emode =
+ emode_for_corrupt_record(emode,
+ ReadRecPtr ? ReadRecPtr : EndRecPtr);
+
  if (readFile >= 0)
  {
  close(readFile);
@@ -4295,14 +4299,41 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
  }
 
  /*
- * We only end up here without a message when XLogPageRead()
- * failed - in that case we already logged something. In
- * StandbyMode that only happens if we have been triggered, so we
- * shouldn't loop anymore in that case.
+ * randAccess here means we are reading successive records during
+ * recovery. If we get here during recovery, we can assume that we
+ * reached the end of WAL.  Otherwise something's really wrong and
+ * we report just only the errormsg if any. If we don't receive
+ * errormsg here, we already logged something.  We don't emit
+ * "reached end of WAL" in muted messages.
+ *
+ * Note: errormsg is alreay translated.
  */
- if (errormsg)
- ereport(emode_for_corrupt_record(emode, EndRecPtr),
- (errmsg_internal("%s", errormsg) /* already translated */ ));
+ if (!private->randAccess && actual_emode == emode)
+ {
+ if (StandbyMode)
+ ereport(actual_emode,
+ (errmsg ("rached end of WAL at %X/%X on timeline %u in %s during streaming replication",
+ (uint32) (EndRecPtr >> 32), (uint32) EndRecPtr,
+ ThisTimeLineID,
+ xlogSourceNames[currentSource]),
+ (errormsg ? errdetail_internal("%s", errormsg) : 0)));
+ else if (InArchiveRecovery)
+ ereport(actual_emode,
+ (errmsg ("rached end of WAL at %X/%X on timeline %u in %s during archive recovery",
+ (uint32) (EndRecPtr >> 32), (uint32) EndRecPtr,
+ ThisTimeLineID,
+ xlogSourceNames[currentSource]),
+ (errormsg ? errdetail_internal("%s", errormsg) : 0)));
+ else
+ ereport(actual_emode,
+ (errmsg ("rached end of WAL at %X/%X on timeline %u in %s during crash recovery",
+ (uint32) (EndRecPtr >> 32), (uint32) EndRecPtr,
+ ThisTimeLineID,
+ xlogSourceNames[currentSource]),
+ (errormsg ? errdetail_internal("%s", errormsg) : 0)));
+ }
+ else if (errormsg)
+ ereport(actual_emode, (errmsg_internal("%s", errormsg)));
  }
 
  /*
--
2.18.2

Reply | Threaded
Open this post in threaded view
|

Re: Make mesage at end-of-recovery less scary.

Michael Paquier-2
On Fri, Feb 28, 2020 at 04:01:00PM +0900, Kyotaro Horiguchi wrote:
> Hello, this is a followup thread of [1].
>
> # I didn't noticed that the thread didn't cover -hackers..
>
> When recovery of any type ends, we see several kinds of error messages
> that says "WAL is broken".

Have you considered an error context here?  Your patch leads to a bit
of duplication with the message a bit down of what you are changing
where the end of local pg_wal is reached.

> + * reached the end of WAL.  Otherwise something's really wrong and
> + * we report just only the errormsg if any. If we don't receive

This sentence sounds strange to me.  Or you meant "Something is wrong,
so use errormsg as report if it is set"?

> + * Note: errormsg is alreay translated.

Typo here.

> + if (StandbyMode)
> + ereport(actual_emode,
> + (errmsg ("rached end of WAL at %X/%X on timeline %u in %s during streaming replication",

StandbyMode happens also with only WAL archiving, depending on if
primary_conninfo is set or not.

> + (errmsg ("rached end of WAL at %X/%X on timeline %u in %s during crash recovery",

FWIW, you are introducing three times the same typo, in the same
word, in three different messages.
--
Michael

signature.asc (849 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Make mesage at end-of-recovery less scary.

Kyotaro Horiguchi-4
Thank you for the comments.

At Fri, 28 Feb 2020 16:33:18 +0900, Michael Paquier <[hidden email]> wrote in

> On Fri, Feb 28, 2020 at 04:01:00PM +0900, Kyotaro Horiguchi wrote:
> > Hello, this is a followup thread of [1].
> >
> > # I didn't noticed that the thread didn't cover -hackers..
> >
> > When recovery of any type ends, we see several kinds of error messages
> > that says "WAL is broken".
>
> Have you considered an error context here?  Your patch leads to a bit
> of duplication with the message a bit down of what you are changing
> where the end of local pg_wal is reached.

It is a DEBUG message and it is for the time moving from crash
recovery to archive recovery. I could remove that but decided to leave
it for tracability.

> > + * reached the end of WAL.  Otherwise something's really wrong and
> > + * we report just only the errormsg if any. If we don't receive
>
> This sentence sounds strange to me.  Or you meant "Something is wrong,
> so use errormsg as report if it is set"?

The whole comment there follows.
| recovery. If we get here during recovery, we can assume that we
| reached the end of WAL.  Otherwise something's really wrong and
| we report just only the errormsg if any. If we don't receive
| errormsg here, we already logged something.  We don't emit
| "reached end of WAL" in muted messages.

"Othhersise" means "other than the case of recovery".  "Just only the
errmsg" means "show the message not as a part the message "reached end
of WAL".

> > + * Note: errormsg is alreay translated.
>
> Typo here.

Thanks. Will fix along with "rached".

> > + if (StandbyMode)
> > + ereport(actual_emode,
> > + (errmsg ("rached end of WAL at %X/%X on timeline %u in %s during streaming replication",
>
> StandbyMode happens also with only WAL archiving, depending on if
> primary_conninfo is set or not.

Right. I'll fix it. Maybe to "during standby mode".

> > + (errmsg ("rached end of WAL at %X/%X on timeline %u in %s during crash recovery",
>
> FWIW, you are introducing three times the same typo, in the same
> word, in three different messages.

They're copy-pasto.  I refrained from constructing an error message
from multiple nonindipendent parts.  Are you suggesting to do so?

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center


Reply | Threaded
Open this post in threaded view
|

Re: Make mesage at end-of-recovery less scary.

Kyotaro Horiguchi-4
Hello.

I changed the condition from randAccess to fetching_ckpt considering
the discussion in another thread [1]. Then I moved the block that
shows the new messages to more appropriate place.

At Fri, 28 Feb 2020 17:28:06 +0900 (JST), Kyotaro Horiguchi <[hidden email]> wrote in
> >
> > Have you considered an error context here?  Your patch leads to a bit
> > of duplication with the message a bit down of what you are changing
> > where the end of local pg_wal is reached.
>
> It is a DEBUG message and it is for the time moving from crash
> recovery to archive recovery. I could remove that but decided to leave
> it for tracability.

I modified the message so that it has the same look to the new
messages, but I left it being DEBUG1, since it is just a intermediate
state. We should finally see one of the new three messages.

After the messages changed, another message from wal sender came to
look redundant.

| [20866] LOG:  replication terminated by primary server
| [20866] DETAIL:  End of WAL reached on timeline 1 at 0/30001C8.
| [20866] FATAL:  could not send end-of-streaming message to primary: no COPY in progress
| [20851] LOG:  reached end of WAL at 0/30001C8 on timeline 1 in archive during standby mode
| [20851] DETAIL:  invalid record length at 0/30001C8: wanted 24, got 0

I changed the above to the below, which looks more adequate.

| [24271]  LOG:  replication terminated by primary server on timeline 1 at 0/3000240.
| [24271]  FATAL:  could not send end-of-streaming message to primary: no COPY in progress
| [24267]  LOG:  reached end of WAL at 0/3000240 on timeline 1 in archive during standby mode
| [24267]  DETAIL:  invalid record length at 0/3000240: wanted 24, got 0

> > > + * reached the end of WAL.  Otherwise something's really wrong and
> > > + * we report just only the errormsg if any. If we don't receive
> >
> > This sentence sounds strange to me.  Or you meant "Something is wrong,
> > so use errormsg as report if it is set"?

The message no longer exists.

> > > + (errmsg ("rached end of WAL at %X/%X on timeline %u in %s during crash recovery",
> >
> > FWIW, you are introducing three times the same typo, in the same
> > word, in three different messages.
>
> They're copy-pasto.  I refrained from constructing an error message
> from multiple nonindipendent parts.  Are you suggesting to do so?

The tree times repetition of almost same phrases is very unreadable. I
rewrote it in more simple shape.

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

From 17ee82e5d44dd5a932ed69b8a1ea91a23d170952 Mon Sep 17 00:00:00 2001
From: Kyotaro Horiguchi <[hidden email]>
Date: Fri, 28 Feb 2020 15:52:58 +0900
Subject: [PATCH v2] Make End-Of-Recovery error less scary

When recovery in any type ends, we see a bit scary error message like
"invalid record length" that suggests something serious is happening.
Make this message less scary as "reached end of WAL".
---
 src/backend/access/transam/xlog.c     | 72 ++++++++++++++++++++-------
 src/backend/replication/walreceiver.c |  3 +-
 2 files changed, 55 insertions(+), 20 deletions(-)

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index d19408b3be..849cf6fe6b 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -4282,12 +4282,15 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
  for (;;)
  {
  char   *errormsg;
+ XLogRecPtr ErrRecPtr = InvalidXLogRecPtr;
 
  record = XLogReadRecord(xlogreader, &errormsg);
  ReadRecPtr = xlogreader->ReadRecPtr;
  EndRecPtr = xlogreader->EndRecPtr;
  if (record == NULL)
  {
+ ErrRecPtr = ReadRecPtr ? ReadRecPtr : EndRecPtr;
+
  if (readFile >= 0)
  {
  close(readFile);
@@ -4295,14 +4298,16 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
  }
 
  /*
- * We only end up here without a message when XLogPageRead()
- * failed - in that case we already logged something. In
- * StandbyMode that only happens if we have been triggered, so we
- * shouldn't loop anymore in that case.
+ * If we are fetching checkpoint, we emit the error message right
+ * now. Otherwise the error is regarded as "end of WAL" and the
+ * message if any is shown as a part of the end-of-WAL message
+ * below.
  */
- if (errormsg)
- ereport(emode_for_corrupt_record(emode, EndRecPtr),
+ if (fetching_ckpt && errormsg)
+ {
+ ereport(emode_for_corrupt_record(emode, ErrRecPtr),
  (errmsg_internal("%s", errormsg) /* already translated */ ));
+ }
  }
 
  /*
@@ -4332,11 +4337,12 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
  /* Great, got a record */
  return record;
  }
- else
- {
- /* No valid record available from this source */
- lastSourceFailed = true;
 
+ /* No valid record available from this source */
+ lastSourceFailed = true;
+
+ if (!fetching_ckpt)
+ {
  /*
  * If archive recovery was requested, but we were still doing
  * crash recovery, switch to archive recovery and retry using the
@@ -4349,11 +4355,18 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
  * we'd have no idea how far we'd have to replay to reach
  * consistency.  So err on the safe side and give up.
  */
- if (!InArchiveRecovery && ArchiveRecoveryRequested &&
- !fetching_ckpt)
+ if (!InArchiveRecovery && ArchiveRecoveryRequested)
  {
+ /*
+ * We don't report this as LOG, since we don't stop recovery
+ * here
+ */
  ereport(DEBUG1,
- (errmsg_internal("reached end of WAL in pg_wal, entering archive recovery")));
+ (errmsg_internal("reached end of WAL at %X/%X on timeline %u in %s during crash recovery, entering archive recovery",
+ (uint32) (ErrRecPtr >> 32),
+ (uint32) ErrRecPtr,
+ ThisTimeLineID,
+ xlogSourceNames[currentSource])));
  InArchiveRecovery = true;
  if (StandbyModeRequested)
  StandbyMode = true;
@@ -4391,12 +4404,35 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
  continue;
  }
 
- /* In standby mode, loop back to retry. Otherwise, give up. */
- if (StandbyMode && !CheckForStandbyTrigger())
- continue;
- else
- return NULL;
+ /*
+ *  We reached the end of WAL, show the messages just once at the
+ *  same LSN.
+ */
+ if (emode_for_corrupt_record(LOG, ErrRecPtr) == LOG)
+ {
+ char *fmt;
+
+ if (StandbyMode)
+ fmt = gettext_noop("reached end of WAL at %X/%X on timeline %u in %s during standby mode");
+ else if (InArchiveRecovery)
+ fmt = gettext_noop("reached end of WAL at %X/%X on timeline %u in %s during archive recovery");
+ else
+ fmt = gettext_noop("reached end of WAL at %X/%X on timeline %u in %s during crash recovery");
+
+ ereport(LOG,
+ (errmsg (fmt, (uint32) (EndRecPtr >> 32),
+ (uint32) EndRecPtr,
+ ThisTimeLineID,
+ xlogSourceNames[currentSource]),
+ (errormsg ? errdetail_internal("%s", errormsg) : 0)));
+ }
  }
+
+ /* In standby mode, loop back to retry. Otherwise, give up. */
+ if (StandbyMode && !CheckForStandbyTrigger())
+ continue;
+ else
+ return NULL;
  }
 }
 
diff --git a/src/backend/replication/walreceiver.c b/src/backend/replication/walreceiver.c
index 2ab15c3cbb..682dbb4e1f 100644
--- a/src/backend/replication/walreceiver.c
+++ b/src/backend/replication/walreceiver.c
@@ -478,8 +478,7 @@ WalReceiverMain(void)
  else if (len < 0)
  {
  ereport(LOG,
- (errmsg("replication terminated by primary server"),
- errdetail("End of WAL reached on timeline %u at %X/%X.",
+ (errmsg("replication terminated by primary server on timeline %u at %X/%X.",
    startpointTLI,
    (uint32) (LogstreamResult.Write >> 32), (uint32) LogstreamResult.Write)));
  endofwal = true;
--
2.18.2

Reply | Threaded
Open this post in threaded view
|

Re: Make mesage at end-of-recovery less scary.

Peter Eisentraut-6
On 2020-03-05 08:06, Kyotaro Horiguchi wrote:

> | [20866] LOG:  replication terminated by primary server
> | [20866] DETAIL:  End of WAL reached on timeline 1 at 0/30001C8.
> | [20866] FATAL:  could not send end-of-streaming message to primary: no COPY in progress
> | [20851] LOG:  reached end of WAL at 0/30001C8 on timeline 1 in archive during standby mode
> | [20851] DETAIL:  invalid record length at 0/30001C8: wanted 24, got 0
>
> I changed the above to the below, which looks more adequate.
>
> | [24271]  LOG:  replication terminated by primary server on timeline 1 at 0/3000240.
> | [24271]  FATAL:  could not send end-of-streaming message to primary: no COPY in progress
> | [24267]  LOG:  reached end of WAL at 0/3000240 on timeline 1 in archive during standby mode
> | [24267]  DETAIL:  invalid record length at 0/3000240: wanted 24, got 0

Is this the before and after?  That doesn't seem like a substantial
improvement to me.  You still get the "scary" message at the end.

--
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services


Reply | Threaded
Open this post in threaded view
|

Re: Make mesage at end-of-recovery less scary.

Ashwin Agrawal
On Mon, Mar 23, 2020 at 2:37 AM Peter Eisentraut <[hidden email]> wrote:
On 2020-03-05 08:06, Kyotaro Horiguchi wrote:
> | [20866] LOG:  replication terminated by primary server
> | [20866] DETAIL:  End of WAL reached on timeline 1 at 0/30001C8.
> | [20866] FATAL:  could not send end-of-streaming message to primary: no COPY in progress
> | [20851] LOG:  reached end of WAL at 0/30001C8 on timeline 1 in archive during standby mode
> | [20851] DETAIL:  invalid record length at 0/30001C8: wanted 24, got 0
>
> I changed the above to the below, which looks more adequate.
>
> | [24271]  LOG:  replication terminated by primary server on timeline 1 at 0/3000240.
> | [24271]  FATAL:  could not send end-of-streaming message to primary: no COPY in progress
> | [24267]  LOG:  reached end of WAL at 0/3000240 on timeline 1 in archive during standby mode
> | [24267]  DETAIL:  invalid record length at 0/3000240: wanted 24, got 0

Is this the before and after?  That doesn't seem like a substantial
improvement to me.  You still get the "scary" message at the end.

+1 I agree it still reads scary and doesn't seem improvement.

Plus, I am hoping message will improve for pg_waldump as well?
Since it reads confusing and every-time have to explain new developer it's expected behavior which is annoying.

pg_waldump: fatal: error in WAL record at 0/1553F70: invalid record length at 0/1553FA8: wanted 24, got 0
Reply | Threaded
Open this post in threaded view
|

Re: Make mesage at end-of-recovery less scary.

Andres Freund
In reply to this post by Peter Eisentraut-6
Hi,

On 2020-03-23 10:37:16 +0100, Peter Eisentraut wrote:
> On 2020-03-05 08:06, Kyotaro Horiguchi wrote:
> > | [20866] LOG:  replication terminated by primary server
> > | [20866] DETAIL:  End of WAL reached on timeline 1 at 0/30001C8.
> > | [20866] FATAL:  could not send end-of-streaming message to primary: no COPY in progress

IMO it's a bug that we see this FATAL. I seem to recall that we didn't
use to get that?


> > | [20851] LOG:  reached end of WAL at 0/30001C8 on timeline 1 in archive during standby mode
> > | [20851] DETAIL:  invalid record length at 0/30001C8: wanted 24, got 0
> >
> > I changed the above to the below, which looks more adequate.
> >
> > | [24271]  LOG:  replication terminated by primary server on timeline 1 at 0/3000240.
> > | [24271]  FATAL:  could not send end-of-streaming message to primary: no COPY in progress
> > | [24267]  LOG:  reached end of WAL at 0/3000240 on timeline 1 in archive during standby mode
> > | [24267]  DETAIL:  invalid record length at 0/3000240: wanted 24, got 0
>
> Is this the before and after?  That doesn't seem like a substantial
> improvement to me.  You still get the "scary" message at the end.

It seems like a minor improvement - folding the DETAIL into the message
makes sense to me here. But it indeed doesn't really address the main
issue.

I think we don't want to elide the information about how the end of the
WAL was detected - there are some issues where I found that quite
helpful. But we could reformulate it to be clearer that it's informative
output, not a bug.  E.g. something roughly like

LOG:  reached end of WAL at 0/3000240 on timeline 1 in archive during standby mode
DETAIL: End detected due to invalid record length at 0/3000240: expected 24, got 0
(I first elided the position in the DETAIL, but it could differ from the
one in LOG)

I don't find that very satisfying, but I can't come up with something
that provides the current information, while being less scary than my
suggestion?

Greetings,

Andres Freund


Reply | Threaded
Open this post in threaded view
|

Re: Make mesage at end-of-recovery less scary.

Andres Freund
In reply to this post by Ashwin Agrawal
Hi,

On 2020-03-23 10:43:09 -0700, Ashwin Agrawal wrote:
> Plus, I am hoping message will improve for pg_waldump as well?
> Since it reads confusing and every-time have to explain new developer it's
> expected behavior which is annoying.
>
> pg_waldump: fatal: error in WAL record at 0/1553F70: invalid record length
> at 0/1553FA8: wanted 24, got 0

What would you like to see here? There's inherently a lot less
information about the context in waldump. We can't know whether it's to
be expected that the WAL ends at that point, or whether there was
corruption.

Greetings,

Andres Freund


Reply | Threaded
Open this post in threaded view
|

Re: Make mesage at end-of-recovery less scary.

Kyotaro Horiguchi-4
In reply to this post by Andres Freund
At Mon, 23 Mar 2020 12:47:36 -0700, Andres Freund <[hidden email]> wrote in

> Hi,
>
> On 2020-03-23 10:37:16 +0100, Peter Eisentraut wrote:
> > On 2020-03-05 08:06, Kyotaro Horiguchi wrote:
> > > | [20866] LOG:  replication terminated by primary server
> > > | [20866] DETAIL:  End of WAL reached on timeline 1 at 0/30001C8.
> > > | [20866] FATAL:  could not send end-of-streaming message to primary: no COPY in progress
>
> IMO it's a bug that we see this FATAL. I seem to recall that we didn't
> use to get that?
I thought that it is a convention that A auxiliary process uses ERROR
(which is turned into FATAL in ereport) to exit, which I didn't like
so much, but it was out of scope of this patch.

As for the message bove, the FATAL is preceded by the "LOG:
replication terminated by" message, that means walreceiver tries to
send new data after disconnection just to fail, which is
unreasonable. I think we should exit immediately after detecting
disconnection. The FATAL is gone by the attached.

> > > | [24267]  LOG:  reached end of WAL at 0/3000240 on timeline 1 in archive during standby mode
> > > | [24267]  DETAIL:  invalid record length at 0/3000240: wanted 24, got 0
> >
> > Is this the before and after?  That doesn't seem like a substantial
> > improvement to me.  You still get the "scary" message at the end.
>
> It seems like a minor improvement - folding the DETAIL into the message
> makes sense to me here. But it indeed doesn't really address the main
> issue.
>
> I think we don't want to elide the information about how the end of the
> WAL was detected - there are some issues where I found that quite
> helpful. But we could reformulate it to be clearer that it's informative
> output, not a bug.  E.g. something roughly like
>
> LOG:  reached end of WAL at 0/3000240 on timeline 1 in archive during standby mode
> DETAIL: End detected due to invalid record length at 0/3000240: expected 24, got 0
> (I first elided the position in the DETAIL, but it could differ from the
> one in LOG)
>
> I don't find that very satisfying, but I can't come up with something
> that provides the current information, while being less scary than my
> suggestion?
The 0-length record is not an "invalid" state during recovery, so we
can add the message for the state as "record length is 0 at %X/%X". I
think if other states found there, it implies something wrong.

LSN is redundantly shown but I'm not sure if it is better to remove it
from either of the two lines.

| LOG:  reached end of WAL at 0/3000850 on timeline 1 in pg_wal during crash recovery
| DETAIL:  record length is 0 at 0/3000850

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

From 47511afed5f8acf92abaf1cd6fcfecc1faea9c87 Mon Sep 17 00:00:00 2001
From: Kyotaro Horiguchi <[hidden email]>
Date: Fri, 28 Feb 2020 15:52:58 +0900
Subject: [PATCH v3] Make End-Of-Recovery error less scary

When recovery in any type ends, we see a bit scary error message like
"invalid record length" that suggests something serious is happening.
Make this message less scary as "reached end of WAL".
---
 src/backend/access/transam/xlog.c       | 69 ++++++++++++++++++-------
 src/backend/access/transam/xlogreader.c |  9 ++++
 src/backend/replication/walreceiver.c   | 11 ++--
 3 files changed, 67 insertions(+), 22 deletions(-)

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 793c076da6..6c2924dfb7 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -4283,12 +4283,15 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
  for (;;)
  {
  char   *errormsg;
+ XLogRecPtr ErrRecPtr = InvalidXLogRecPtr;
 
  record = XLogReadRecord(xlogreader, &errormsg);
  ReadRecPtr = xlogreader->ReadRecPtr;
  EndRecPtr = xlogreader->EndRecPtr;
  if (record == NULL)
  {
+ ErrRecPtr = ReadRecPtr ? ReadRecPtr : EndRecPtr;
+
  if (readFile >= 0)
  {
  close(readFile);
@@ -4296,13 +4299,13 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
  }
 
  /*
- * We only end up here without a message when XLogPageRead()
- * failed - in that case we already logged something. In
- * StandbyMode that only happens if we have been triggered, so we
- * shouldn't loop anymore in that case.
+ * If we are fetching checkpoint, we emit the error message right
+ * now. Otherwise the error is regarded as "end of WAL" and the
+ * message if any is shown as a part of the end-of-WAL message
+ * below.
  */
- if (errormsg)
- ereport(emode_for_corrupt_record(emode, EndRecPtr),
+ if (fetching_ckpt && errormsg)
+ ereport(emode_for_corrupt_record(emode, ErrRecPtr),
  (errmsg_internal("%s", errormsg) /* already translated */ ));
  }
 
@@ -4333,11 +4336,12 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
  /* Great, got a record */
  return record;
  }
- else
- {
- /* No valid record available from this source */
- lastSourceFailed = true;
 
+ /* No valid record available from this source */
+ lastSourceFailed = true;
+
+ if (!fetching_ckpt)
+ {
  /*
  * If archive recovery was requested, but we were still doing
  * crash recovery, switch to archive recovery and retry using the
@@ -4350,11 +4354,18 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
  * we'd have no idea how far we'd have to replay to reach
  * consistency.  So err on the safe side and give up.
  */
- if (!InArchiveRecovery && ArchiveRecoveryRequested &&
- !fetching_ckpt)
+ if (!InArchiveRecovery && ArchiveRecoveryRequested)
  {
+ /*
+ * We don't report this as LOG, since we don't stop recovery
+ * here
+ */
  ereport(DEBUG1,
- (errmsg_internal("reached end of WAL in pg_wal, entering archive recovery")));
+ (errmsg_internal("reached end of WAL at %X/%X on timeline %u in %s during crash recovery, entering archive recovery",
+ (uint32) (ErrRecPtr >> 32),
+ (uint32) ErrRecPtr,
+ ThisTimeLineID,
+ xlogSourceNames[currentSource])));
  InArchiveRecovery = true;
  if (StandbyModeRequested)
  StandbyMode = true;
@@ -4392,12 +4403,34 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
  continue;
  }
 
- /* In standby mode, loop back to retry. Otherwise, give up. */
- if (StandbyMode && !CheckForStandbyTrigger())
- continue;
- else
- return NULL;
+ /*
+ *  We reached the end of WAL, show the messages just once at the
+ *  same LSN.
+ */
+ if (emode_for_corrupt_record(LOG, ErrRecPtr) == LOG)
+ {
+ char *fmt;
+
+ if (StandbyMode)
+ fmt = gettext_noop("reached end of WAL at %X/%X on timeline %u in %s during standby mode");
+ else if (InArchiveRecovery)
+ fmt = gettext_noop("reached end of WAL at %X/%X on timeline %u in %s during archive recovery");
+ else
+ fmt = gettext_noop("reached end of WAL at %X/%X on timeline %u in %s during crash recovery");
+
+ ereport(LOG,
+ (errmsg(fmt, (uint32) (EndRecPtr >> 32),
+ (uint32) EndRecPtr, ThisTimeLineID,
+ xlogSourceNames[currentSource]),
+ (errormsg ? errdetail_internal("%s", errormsg) : 0)));
+ }
  }
+
+ /* In standby mode, loop back to retry. Otherwise, give up. */
+ if (StandbyMode && !CheckForStandbyTrigger())
+ continue;
+ else
+ return NULL;
  }
 }
 
diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.c
index 32f02256ed..9ea1305364 100644
--- a/src/backend/access/transam/xlogreader.c
+++ b/src/backend/access/transam/xlogreader.c
@@ -682,6 +682,15 @@ ValidXLogRecordHeader(XLogReaderState *state, XLogRecPtr RecPtr,
   XLogRecPtr PrevRecPtr, XLogRecord *record,
   bool randAccess)
 {
+
+ if (record->xl_tot_len == 0)
+ {
+ /* This is strictly not an invalid state, so phrase it as so. */
+ report_invalid_record(state,
+  "record length is 0 at %X/%X",
+  (uint32) (RecPtr >> 32), (uint32) RecPtr);
+ return false;
+ }
  if (record->xl_tot_len < SizeOfXLogRecord)
  {
  report_invalid_record(state,
diff --git a/src/backend/replication/walreceiver.c b/src/backend/replication/walreceiver.c
index 25e0333c9e..da978d4047 100644
--- a/src/backend/replication/walreceiver.c
+++ b/src/backend/replication/walreceiver.c
@@ -479,12 +479,15 @@ WalReceiverMain(void)
  else if (len < 0)
  {
  ereport(LOG,
- (errmsg("replication terminated by primary server"),
- errdetail("End of WAL reached on timeline %u at %X/%X.",
+ (errmsg("replication terminated by primary server on timeline %u at %X/%X.",
    startpointTLI,
    (uint32) (LogstreamResult.Write >> 32), (uint32) LogstreamResult.Write)));
- endofwal = true;
- break;
+
+ /*
+ * we have no longer anything to do on the broken
+ * connection other than exiting.
+ */
+ proc_exit(1);
  }
  len = walrcv_receive(wrconn, &buf, &wait_fd);
  }
--
2.18.2

Reply | Threaded
Open this post in threaded view
|

Re: Make mesage at end-of-recovery less scary.

Peter Eisentraut-6
On 2020-03-24 02:52, Kyotaro Horiguchi wrote:

>> I don't find that very satisfying, but I can't come up with something
>> that provides the current information, while being less scary than my
>> suggestion?
> The 0-length record is not an "invalid" state during recovery, so we
> can add the message for the state as "record length is 0 at %X/%X". I
> think if other states found there, it implies something wrong.
>
> LSN is redundantly shown but I'm not sure if it is better to remove it
> from either of the two lines.
>
> | LOG:  reached end of WAL at 0/3000850 on timeline 1 in pg_wal during crash recovery
> | DETAIL:  record length is 0 at 0/3000850

I'm not up to date on all these details, but my high-level idea would be
some kind of hint associated with the existing error messages, like:

HINT:  This is to be expected if this is the end of the WAL.  Otherwise,
it could indicate corruption.

--
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services


Reply | Threaded
Open this post in threaded view
|

Re: Make mesage at end-of-recovery less scary.

Robert Haas
On Wed, Mar 25, 2020 at 8:53 AM Peter Eisentraut
<[hidden email]> wrote:
> HINT:  This is to be expected if this is the end of the WAL.  Otherwise,
> it could indicate corruption.

First, I agree that this general issue is a problem, because it's come
up for me in quite a number of customer situations. Either people get
scared when they shouldn't, because the message is innocuous, or they
don't get scared about other things that actually are scary, because
if some scary-looking messages are actually innocuous, it can lead
people to believe that the same is true in other cases.

Second, I don't really like the particular formulation you have above,
because the user still doesn't know whether or not to be scared. Can
we figure that out? I think if we're in crash recovery, I think that
we should not be scared, because we have no alternative to assuming
that we've reached the end of WAL, so all crash recoveries will end
like this. If we're in archive recovery, we should definitely be
scared if we haven't yet reached the minimum recovery point, because
more WAL than that should certainly exist. After that, it depends on
how we got the WAL. If it's being streamed, the question is whether
we've reached the end of what got streamed. If it's being copied from
the archive, we ought to have the whole segment, but maybe not more.
Can we get the right context to the point where the error is being
reported to know whether we hit the error at the end of the WAL that
was streamed? If not, can we somehow rejigger things so that we only
make it sound scary if we keep getting stuck at the same point when we
woud've expected to make progress meanwhile?

I'm just spitballing here, but it would be really good if there's a
way to know definitely whether or not you should be scared. Corrupted
WAL segments are definitely a thing that happens, but retries are a
lot more common.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company


Reply | Threaded
Open this post in threaded view
|

Re: Make mesage at end-of-recovery less scary.

James Coleman
On Thu, Mar 26, 2020 at 12:41 PM Robert Haas <[hidden email]> wrote:

>
> On Wed, Mar 25, 2020 at 8:53 AM Peter Eisentraut
> <[hidden email]> wrote:
> > HINT:  This is to be expected if this is the end of the WAL.  Otherwise,
> > it could indicate corruption.
>
> First, I agree that this general issue is a problem, because it's come
> up for me in quite a number of customer situations. Either people get
> scared when they shouldn't, because the message is innocuous, or they
> don't get scared about other things that actually are scary, because
> if some scary-looking messages are actually innocuous, it can lead
> people to believe that the same is true in other cases.
>
> Second, I don't really like the particular formulation you have above,
> because the user still doesn't know whether or not to be scared. Can
> we figure that out? I think if we're in crash recovery, I think that
> we should not be scared, because we have no alternative to assuming
> that we've reached the end of WAL, so all crash recoveries will end
> like this. If we're in archive recovery, we should definitely be
> scared if we haven't yet reached the minimum recovery point, because
> more WAL than that should certainly exist. After that, it depends on
> how we got the WAL. If it's being streamed, the question is whether
> we've reached the end of what got streamed. If it's being copied from
> the archive, we ought to have the whole segment, but maybe not more.
> Can we get the right context to the point where the error is being
> reported to know whether we hit the error at the end of the WAL that
> was streamed? If not, can we somehow rejigger things so that we only
> make it sound scary if we keep getting stuck at the same point when we
> woud've expected to make progress meanwhile?
>
> I'm just spitballing here, but it would be really good if there's a
> way to know definitely whether or not you should be scared. Corrupted
> WAL segments are definitely a thing that happens, but retries are a
> lot more common.

First, I agree that getting enough context to say precisely is by far the ideal.

That being said, as an end user who's found this surprising -- and
momentarily scary every time I initially scan it even though I *know
intellectually it's not* -- I would find Peter's suggestion a
significant improvement over what we have now. I'm fairly certainly my
co-workers on our database team would also. Knowing that something is
at least not always scary is good. Though I'll grant that this does
have the negative in reverse: if it actually is a scary
situation...this mutes your concern level. On the other hand,
monitoring would tell us if there's a real problem (namely replication
lag), so I think the trade-off is clearly worth it.

How about this minor tweak:
HINT:  This is expected if this is the end of currently available WAL.
Otherwise, it could indicate corruption.

Thanks,
James