public inbox for [email protected]
help / color / mirror / Atom feedMake mesage at end-of-recovery less scary.
38+ messages / 13 participants
[nested] [flat]
* Make mesage at end-of-recovery less scary.
@ 2020-02-28 07:01 Kyotaro Horiguchi <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Kyotaro Horiguchi @ 2020-02-28 07:01 UTC (permalink / raw)
To: [email protected]
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
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2020-02-28 07:33 Michael Paquier <[email protected]>
parent: Kyotaro Horiguchi <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Michael Paquier @ 2020-02-28 07:33 UTC (permalink / raw)
To: Kyotaro Horiguchi <[email protected]>; +Cc: [email protected]
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
Attachments:
[application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc)
download
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2020-02-28 08:28 Kyotaro Horiguchi <[email protected]>
parent: Michael Paquier <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Kyotaro Horiguchi @ 2020-02-28 08:28 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]
Thank you for the comments.
At Fri, 28 Feb 2020 16:33:18 +0900, Michael Paquier <[email protected]> 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
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2020-03-05 07:06 Kyotaro Horiguchi <[email protected]>
parent: Kyotaro Horiguchi <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Kyotaro Horiguchi @ 2020-03-05 07:06 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]
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 <[email protected]> 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
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2020-03-23 09:37 Peter Eisentraut <[email protected]>
parent: Kyotaro Horiguchi <[email protected]>
0 siblings, 2 replies; 38+ messages in thread
From: Peter Eisentraut @ 2020-03-23 09:37 UTC (permalink / raw)
To: Kyotaro Horiguchi <[email protected]>; [email protected]; +Cc: [email protected]
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
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2020-03-23 17:43 Ashwin Agrawal <[email protected]>
parent: Peter Eisentraut <[email protected]>
1 sibling, 1 reply; 38+ messages in thread
From: Ashwin Agrawal @ 2020-03-23 17:43 UTC (permalink / raw)
To: Peter Eisentraut <[email protected]>; +Cc: Kyotaro Horiguchi <[email protected]>; Michael Paquier <[email protected]>; PostgreSQL Hackers <[email protected]>
On Mon, Mar 23, 2020 at 2:37 AM Peter Eisentraut <
[email protected]> 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
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2020-03-23 19:47 Andres Freund <[email protected]>
parent: Peter Eisentraut <[email protected]>
1 sibling, 1 reply; 38+ messages in thread
From: Andres Freund @ 2020-03-23 19:47 UTC (permalink / raw)
To: Peter Eisentraut <[email protected]>; +Cc: Kyotaro Horiguchi <[email protected]>; [email protected]; [email protected]
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
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2020-03-23 19:49 Andres Freund <[email protected]>
parent: Ashwin Agrawal <[email protected]>
0 siblings, 0 replies; 38+ messages in thread
From: Andres Freund @ 2020-03-23 19:49 UTC (permalink / raw)
To: Ashwin Agrawal <[email protected]>; +Cc: Peter Eisentraut <[email protected]>; Kyotaro Horiguchi <[email protected]>; Michael Paquier <[email protected]>; PostgreSQL Hackers <[email protected]>
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
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2020-03-24 01:52 Kyotaro Horiguchi <[email protected]>
parent: Andres Freund <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Kyotaro Horiguchi @ 2020-03-24 01:52 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]; [email protected]; [email protected]
At Mon, 23 Mar 2020 12:47:36 -0700, Andres Freund <[email protected]> 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
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2020-03-25 12:53 Peter Eisentraut <[email protected]>
parent: Kyotaro Horiguchi <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Peter Eisentraut @ 2020-03-25 12:53 UTC (permalink / raw)
To: Kyotaro Horiguchi <[email protected]>; [email protected]; +Cc: [email protected]; [email protected]
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
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2020-03-26 16:40 Robert Haas <[email protected]>
parent: Peter Eisentraut <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Robert Haas @ 2020-03-26 16:40 UTC (permalink / raw)
To: Peter Eisentraut <[email protected]>; +Cc: Kyotaro Horiguchi <[email protected]>; Andres Freund <[email protected]>; Michael Paquier <[email protected]>; PostgreSQL Hackers <[email protected]>
On Wed, Mar 25, 2020 at 8:53 AM Peter Eisentraut
<[email protected]> 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
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2020-03-28 02:25 James Coleman <[email protected]>
parent: Robert Haas <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: James Coleman @ 2020-03-28 02:25 UTC (permalink / raw)
To: Robert Haas <[email protected]>; +Cc: Peter Eisentraut <[email protected]>; Kyotaro Horiguchi <[email protected]>; Andres Freund <[email protected]>; Michael Paquier <[email protected]>; PostgreSQL Hackers <[email protected]>
On Thu, Mar 26, 2020 at 12:41 PM Robert Haas <[email protected]> wrote:
>
> On Wed, Mar 25, 2020 at 8:53 AM Peter Eisentraut
> <[email protected]> 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
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2021-03-03 16:14 David Steele <[email protected]>
parent: James Coleman <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: David Steele @ 2021-03-03 16:14 UTC (permalink / raw)
To: Kyotaro Horiguchi <[email protected]>; +Cc: Peter Eisentraut <[email protected]>; Andres Freund <[email protected]>; Michael Paquier <[email protected]>; PostgreSQL Hackers <[email protected]>; James Coleman <[email protected]>; Robert Haas <[email protected]>
Hi Kyotaro,
On 3/27/20 10:25 PM, James Coleman wrote:
> On Thu, Mar 26, 2020 at 12:41 PM Robert Haas <[email protected]> wrote:
>>
>> 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.
Any thoughts on the suggestions for making the messaging clearer?
Also, the patch no longer applies:
http://cfbot.cputube.org/patch_32_2490.log.
Marking this Waiting on Author.
Regards,
--
-David
[email protected]
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2021-03-04 06:50 Kyotaro Horiguchi <[email protected]>
parent: David Steele <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Kyotaro Horiguchi @ 2021-03-04 06:50 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
At Wed, 3 Mar 2021 11:14:20 -0500, David Steele <[email protected]> wrote in
> Hi Kyotaro,
>
> On 3/27/20 10:25 PM, James Coleman wrote:
> > On Thu, Mar 26, 2020 at 12:41 PM Robert Haas <[email protected]>
> > wrote:
> >>
> >> 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.
>
> Any thoughts on the suggestions for making the messaging clearer?
>
> Also, the patch no longer applies:
> http://cfbot.cputube.org/patch_32_2490.log.
Sorry for missing the last discussions. I agree to the point about
really-scary situation.
ValidXLogRecordHeader deliberately marks End-Of-WAL only in the case
of zero-length record so that the callers can identify that case,
instead of inferring the EOW state without it. All other invalid data
is treated as potentially danger situation. I think this is a
reasonable classification. And the error level for the "danger" cases
is changed to WARNING (from LOG).
As the result, the following messages are emitted with the attached.
- found zero-length record during recovery (the DETAIL might not be needed.)
> LOG: redo starts at 0/14000118
> LOG: reached end of WAL at 0/14C5D070 on timeline 1 in pg_wal during crash recovery
> DETAIL: record length is 0 at 0/14C5D070
> LOG: redo done at 0/14C5CF48 system usage: ...
- found another kind of invalid data
> LOG: redo starts at 0/150000A0
> WARNING: invalid record length at 0/1500CA60: wanted 24, got 54
> LOG: redo done at 0/1500CA28 system usage: ...
On the way checking the patch, I found that it emits the following log
lines in the case the redo loop meets an invalid record at the
starting:
> LOG: invalid record length at 0/10000118: wanted 24, got 42
> LOG: redo is not required
which doesn't look proper. That case is identifiable using the
End-of_WAL flag this patch adds. Thus we get the following error
messages.
- found end-of-wal at the beginning of recovery
> LOG: reached end of WAL at 0/130000A0 on timeline 1 in pg_wal during crash recovery
> DETAIL: record length is 0 at 0/130000A0
> LOG: redo is not required
- found invalid data
> WARNING: invalid record length at 0/120000A0: wanted 24, got 42
> WARNING: redo is skipped
> HINT: This suggests WAL file corruption. You might need to check the database.
The logic of ErrRecPtr in ReadRecord may wrong. I remember having
such an discussion before...
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2021-10-22 17:54 Bossart, Nathan <[email protected]>
parent: Kyotaro Horiguchi <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Bossart, Nathan @ 2021-10-22 17:54 UTC (permalink / raw)
To: Kyotaro Horiguchi <[email protected]>; [email protected] <[email protected]>; +Cc: [email protected] <[email protected]>; [email protected] <[email protected]>; [email protected] <[email protected]>; [email protected] <[email protected]>; [email protected] <[email protected]>; [email protected] <[email protected]>
On 3/4/21, 10:50 PM, "Kyotaro Horiguchi" <[email protected]> wrote:
> As the result, the following messages are emitted with the attached.
I'd like to voice my support for this effort, and I intend to help
review the patch. It looks like the latest patch no longer applies,
so I've marked the commitfest entry [0] as waiting-on-author.
Nathan
[0] https://commitfest.postgresql.org/35/2490/
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2021-11-08 05:59 Kyotaro Horiguchi <[email protected]>
parent: Bossart, Nathan <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Kyotaro Horiguchi @ 2021-11-08 05:59 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
At Fri, 22 Oct 2021 17:54:40 +0000, "Bossart, Nathan" <[email protected]> wrote in
> On 3/4/21, 10:50 PM, "Kyotaro Horiguchi" <[email protected]> wrote:
> > As the result, the following messages are emitted with the attached.
>
> I'd like to voice my support for this effort, and I intend to help
> review the patch. It looks like the latest patch no longer applies,
> so I've marked the commitfest entry [0] as waiting-on-author.
>
> Nathan
>
> [0] https://commitfest.postgresql.org/35/2490/
Sorry for being late to reply. I rebased this to the current master.
- rebased
- use LSN_FORMAT_ARGS instead of bare shift and mask.
- v4 immediately exited walreceiver on disconnection. Maybe I wanted
not to see a FATAL message on standby after primary dies. However
that would be another issue and that change was plain wrong.. v5
just removes the "end-of-WAL" part from the message, which duplicate
to what startup emits.
- add a new error message "missing contrecord at %X/%X". Maybe this
should be regarded as a leftover of the contrecord patch. In the
attached patch the "%X/%X" is the LSN of the current record. The log
messages look like this (026_overwrite_contrecord).
LOG: redo starts at 0/1486CB8
WARNING: missing contrecord at 0/1FFC2E0
LOG: consistent recovery state reached at 0/1FFC2E0
LOG: started streaming WAL from primary at 0/2000000 on timeline 1
LOG: successfully skipped missing contrecord at 0/1FFC2E0, overwritten at 2021-11-08 14:50:11.969952+09
CONTEXT: WAL redo at 0/2000028 for XLOG/OVERWRITE_CONTRECORD: lsn 0/1FFC2E0; time 2021-11-08 14:50:11.969952+09
While checking the behavior for the case of missing-contrecord, I
noticed that emode_for_corrupt_record() doesn't work as expected since
readSource is reset to XLOG_FROM_ANY after a read failure. We could
remember the last failed source but pg_wal should have been visited if
page read error happened so I changed the function so that it treats
XLOG_FROM_ANY the same way with XLOG_FROM_PG_WAL.
(Otherwise we see "LOG: reached end-of-WAL at .." message after
"WARNING: missing contrecord at.." message.)
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2021-11-09 00:53 Michael Paquier <[email protected]>
parent: Kyotaro Horiguchi <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Michael Paquier @ 2021-11-09 00:53 UTC (permalink / raw)
To: Kyotaro Horiguchi <[email protected]>; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
On Mon, Nov 08, 2021 at 02:59:46PM +0900, Kyotaro Horiguchi wrote:
> While checking the behavior for the case of missing-contrecord, I
> noticed that emode_for_corrupt_record() doesn't work as expected since
> readSource is reset to XLOG_FROM_ANY after a read failure. We could
> remember the last failed source but pg_wal should have been visited if
> page read error happened so I changed the function so that it treats
> XLOG_FROM_ANY the same way with XLOG_FROM_PG_WAL.
FWIW, I am not much a fan of assuming that it is fine to use
XLOG_FROM_ANY as a condition here. The comments on top of
emode_for_corrupt_record() make it rather clear what the expectations
are, and this is the default readSource.
> (Otherwise we see "LOG: reached end-of-WAL at .." message after
> "WARNING: missing contrecord at.." message.)
+ /* broken record found */
+ ereport(WARNING,
+ (errmsg("redo is skipped"),
+ errhint("This suggests WAL file corruption. You might need to check the database.")));
This looks rather scary to me, FWIW, and this could easily be reached
if one forgets about EndOfWAL while hacking on xlogreader.c.
Unlikely so, still.
+ report_invalid_record(state,
+ "missing contrecord at %X/%X",
+ LSN_FORMAT_ARGS(RecPtr));
Isn't there a risk here to break applications checking after error
messages stored in the WAL reader after seeing a contrecord?
+ 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",
+ LSN_FORMAT_ARGS(RecPtr));
+ state->EndOfWAL = true;
+ return false;
+ }
This assumes that a value of 0 for xl_tot_len is a synonym of the end
of WAL, but cannot we have also a corrupted record in this case in the
shape of xl_tot_len being 0? We validate the full record after
reading the header, so it seems to me that we should not assume that
things are just ending as proposed in this patch.
--
Michael
Attachments:
[application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc)
download
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2021-11-09 07:27 Kyotaro Horiguchi <[email protected]>
parent: Michael Paquier <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Kyotaro Horiguchi @ 2021-11-09 07:27 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
Thank you for the comments!
At Tue, 9 Nov 2021 09:53:15 +0900, Michael Paquier <[email protected]> wrote in
> On Mon, Nov 08, 2021 at 02:59:46PM +0900, Kyotaro Horiguchi wrote:
> > While checking the behavior for the case of missing-contrecord, I
> > noticed that emode_for_corrupt_record() doesn't work as expected since
> > readSource is reset to XLOG_FROM_ANY after a read failure. We could
> > remember the last failed source but pg_wal should have been visited if
> > page read error happened so I changed the function so that it treats
> > XLOG_FROM_ANY the same way with XLOG_FROM_PG_WAL.
>
> FWIW, I am not much a fan of assuming that it is fine to use
> XLOG_FROM_ANY as a condition here. The comments on top of
> emode_for_corrupt_record() make it rather clear what the expectations
> are, and this is the default readSource.
The readSource is expected by the function to be the failed source but
it goes back to XLOG_FROM_ANY on page read failure. So the function
*is* standing on the wrong assumption. I noticed that currentSource
holds the last accessed source (but forgot about that). So it is
exactly what we need here. No longer need to introduce the unclear
assumption by using it.
> > (Otherwise we see "LOG: reached end-of-WAL at .." message after
> > "WARNING: missing contrecord at.." message.)
>
> + /* broken record found */
> + ereport(WARNING,
> + (errmsg("redo is skipped"),
> + errhint("This suggests WAL file corruption. You might need to check the database.")));
> This looks rather scary to me, FWIW, and this could easily be reached
Yes, the message is intentionally scary, since we don't come here in
the case of clean WAL:)
> if one forgets about EndOfWAL while hacking on xlogreader.c.
> Unlikely so, still.
I don't understand. Isn't it the case of almost every feature?
The patch compells hackers to maintain the condition for recovery
being considered cleanly ended. If the last record doesn't meet the
condition, the WAL file should be considered having a
problem. However, I don't see the condition expanded to have another
term in future.
Even if someone including myself broke that condition, we will at
worst unwantedly see a scary message. And I believe almost all
hackers can easily find it a bug from the DETAILED message shown along
aside. I'm not sure such bugs could be found in development phase,
though..
> + report_invalid_record(state,
> + "missing contrecord at %X/%X",
> + LSN_FORMAT_ARGS(RecPtr));
> Isn't there a risk here to break applications checking after error
> messages stored in the WAL reader after seeing a contrecord?
I'm not sure you are mentioning the case where no message is stored
previously, or the case where already a message is stored. The former
is fine as the record is actually broken. But I was missing the latter
case. In this version I avoided to overwite the error message.
> + 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",
> + LSN_FORMAT_ARGS(RecPtr));
> + state->EndOfWAL = true;
> + return false;
> + }
> This assumes that a value of 0 for xl_tot_len is a synonym of the end
> of WAL, but cannot we have also a corrupted record in this case in the
> shape of xl_tot_len being 0? We validate the full record after
> reading the header, so it seems to me that we should not assume that
> things are just ending as proposed in this patch.
Yeah, it's the most serious concern to me. So I didn't hide the
detailed message in the "end-of-wal reached message".
> LOG: reached end of WAL at 0/512F198 on timeline 1 in pg_wal during crash recovery
> DETAIL: record length is 0 at 0/512F210
I believe everyone regards zero record length as fine unless something
wrong is seen afterwards. However, we can extend the check to the
whole record header. I think it is by far nearer to the perfect for
almost all cases. The attached emits the following message for the
good (true end-of-WAL) case.
> LOG: reached end of WAL at 0/512F4A0 on timeline 1 in pg_wal during crash recovery
> DETAIL: empty record header found at 0/512F518
If garbage bytes are found in the header area, the following log will
be left. I think we can have a better message here.
> WARNING: garbage record header at 0/2095458
> LOG: redo done at 0/2095430 system usage: CPU: user: 0.03 s, system: 0.01 s, elapsed: 0.04 s
This is the updated version.
- emode_for_currupt_record() now uses currentSource instead of
readSource.
- If zero record length is faced, make sure the whole header is zeroed
before deciding it as the end-of-WAL.
- Do not overwrite existig message when missing contrecord is
detected. The message added here is seen in the TAP test log
026_overwrite_contrecord_standby.log
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2021-12-08 07:01 Kyotaro Horiguchi <[email protected]>
parent: Kyotaro Horiguchi <[email protected]>
0 siblings, 0 replies; 38+ messages in thread
From: Kyotaro Horiguchi @ 2021-12-08 07:01 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
At Tue, 09 Nov 2021 16:27:51 +0900 (JST), Kyotaro Horiguchi <[email protected]> wrote in
> This is the updated version.
>
> - emode_for_currupt_record() now uses currentSource instead of
> readSource.
>
> - If zero record length is faced, make sure the whole header is zeroed
> before deciding it as the end-of-WAL.
>
> - Do not overwrite existig message when missing contrecord is
> detected. The message added here is seen in the TAP test log
> 026_overwrite_contrecord_standby.log
d2ddfa681db27a138acb63c8defa8cc6fa588922 removed global variables
ReadRecPtr and EndRecPtr. This is rebased version that reads the LSNs
directly from xlogreader instead of the removed global variables.
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2022-03-03 10:09 Ashutosh Sharma <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Ashutosh Sharma @ 2022-03-03 10:09 UTC (permalink / raw)
To: Kyotaro Horiguchi <[email protected]>; +Cc: [email protected]; Michael Paquier <[email protected]>; Bossart, Nathan <[email protected]>; David Steele <[email protected]>; Peter Eisentraut <[email protected]>; Andres Freund <[email protected]>; PostgreSQL Hackers <[email protected]>; [email protected]; Robert Haas <[email protected]>
On Wed, Mar 2, 2022 at 7:47 AM Kyotaro Horiguchi
<[email protected]> wrote:
>
> At Sat, 19 Feb 2022 09:31:33 +0530, Ashutosh Sharma <[email protected]> wrote in
> > The changes looks good. thanks.!
>
> Thanks!
>
> Some recent core change changed WAL insertion speed during the TAP
> test and revealed one forgotton case of EndOfWAL. When a record
> header flows into the next page, XLogReadRecord does separate check
> from ValidXLogRecordHeader by itself.
>
The new changes made in the patch look good. Thanks to the recent
changes to speed WAL insertion that have helped us catch this bug.
One small comment:
record = (XLogRecord *) (state->readBuf + RecPtr % XLOG_BLCKSZ);
- total_len = record->xl_tot_len;
Do you think we need to change the position of the comments written
for above code that says:
/*
* Read the record length.
*
...
...
--
With Regards,
Ashutosh Sharma.
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2022-03-04 00:43 Kyotaro Horiguchi <[email protected]>
parent: Ashutosh Sharma <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Kyotaro Horiguchi @ 2022-03-04 00:43 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
At Thu, 3 Mar 2022 15:39:44 +0530, Ashutosh Sharma <[email protected]> wrote in
> The new changes made in the patch look good. Thanks to the recent
> changes to speed WAL insertion that have helped us catch this bug.
Thanks for the quick checking.
> One small comment:
>
> record = (XLogRecord *) (state->readBuf + RecPtr % XLOG_BLCKSZ);
> - total_len = record->xl_tot_len;
>
> Do you think we need to change the position of the comments written
> for above code that says:
Yeah, I didn't do that since it is about header verification. But as
you pointed, the result still doesn't look perfect.
On second thought the two seems repeating the same things. Thus I
merged the two comments together. In this verion 16 it looks like
this.
> /*
> * Validate the record header.
> *
> * Even though we use an XLogRecord pointer here, the whole record header
> * might not fit on this page. If the whole record header is on this page,
> * validate it immediately. Even otherwise xl_tot_len must be on this page
> * (it is the first field of MAXALIGNed records), but we still cannot
> * access any further fields until we've verified that we got the whole
> * header, so do just a basic sanity check on record length, and validate
> * the rest of the header after reading it from the next page. The length
> * check is necessary here to ensure that we enter the "Need to reassemble
> * record" code path below; otherwise we might fail to apply
> * ValidXLogRecordHeader at all.
> */
> record = (XLogRecord *) (state->readBuf + RecPtr % XLOG_BLCKSZ);
>
> if (targetRecOff <= XLOG_BLCKSZ - SizeOfXLogRecord)
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
Attachments:
[text/x-patch] v16-0001-Make-End-Of-Recovery-error-less-scary.patch (19.8K, ../../[email protected]/2-v16-0001-Make-End-Of-Recovery-error-less-scary.patch)
download | inline diff:
From 00d848df6bb8b9966dfbd39c98a388fda42a3e3c Mon Sep 17 00:00:00 2001
From: Kyotaro Horiguchi <[email protected]>
Date: Fri, 28 Feb 2020 15:52:58 +0900
Subject: [PATCH v16] 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. Actually if recovery meets a record with length = 0, that
usually means it finished applying all available WAL records.
Make this message less scary as "reached end of WAL". Instead, raise
the error level for other kind of WAL failure to WARNING.
---
src/backend/access/transam/xlogreader.c | 144 +++++++++++++++++-----
src/backend/access/transam/xlogrecovery.c | 92 ++++++++++----
src/backend/replication/walreceiver.c | 7 +-
src/bin/pg_waldump/pg_waldump.c | 13 +-
src/include/access/xlogreader.h | 1 +
src/test/recovery/t/011_crash_recovery.pl | 106 ++++++++++++++++
6 files changed, 305 insertions(+), 58 deletions(-)
diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.c
index 35029cf97d..bd0f211a23 100644
--- a/src/backend/access/transam/xlogreader.c
+++ b/src/backend/access/transam/xlogreader.c
@@ -42,6 +42,8 @@ static bool allocate_recordbuf(XLogReaderState *state, uint32 reclength);
static int ReadPageInternal(XLogReaderState *state, XLogRecPtr pageptr,
int reqLen);
static void XLogReaderInvalReadState(XLogReaderState *state);
+static bool ValidXLogRecordLength(XLogReaderState *state, XLogRecPtr RecPtr,
+ XLogRecord *record);
static bool ValidXLogRecordHeader(XLogReaderState *state, XLogRecPtr RecPtr,
XLogRecPtr PrevRecPtr, XLogRecord *record, bool randAccess);
static bool ValidXLogRecord(XLogReaderState *state, XLogRecord *record,
@@ -121,6 +123,7 @@ XLogReaderAllocate(int wal_segment_size, const char *waldir,
pfree(state);
return NULL;
}
+ state->EndOfWAL = false;
state->errormsg_buf[0] = '\0';
/*
@@ -292,6 +295,7 @@ XLogReadRecord(XLogReaderState *state, char **errormsg)
/* reset error state */
*errormsg = NULL;
state->errormsg_buf[0] = '\0';
+ state->EndOfWAL = false;
ResetDecoder(state);
state->abortedRecPtr = InvalidXLogRecPtr;
@@ -371,25 +375,21 @@ restart:
Assert(pageHeaderSize <= readOff);
/*
- * Read the record length.
+ * Validate the record header.
*
- * NB: Even though we use an XLogRecord pointer here, the whole record
- * header might not fit on this page. xl_tot_len is the first field of the
- * struct, so it must be on this page (the records are MAXALIGNed), but we
- * cannot access any other fields until we've verified that we got the
- * whole header.
- */
- record = (XLogRecord *) (state->readBuf + RecPtr % XLOG_BLCKSZ);
- total_len = record->xl_tot_len;
-
- /*
- * If the whole record header is on this page, validate it immediately.
- * Otherwise do just a basic sanity check on xl_tot_len, and validate the
- * rest of the header after reading it from the next page. The xl_tot_len
+ * Even though we use an XLogRecord pointer here, the whole record header
+ * might not fit on this page. If the whole record header is on this page,
+ * validate it immediately. Even otherwise xl_tot_len must be on this page
+ * (it is the first field of MAXALIGNed records), but we still cannot
+ * access any further fields until we've verified that we got the whole
+ * header, so do just a basic sanity check on record length, and validate
+ * the rest of the header after reading it from the next page. The length
* check is necessary here to ensure that we enter the "Need to reassemble
* record" code path below; otherwise we might fail to apply
* ValidXLogRecordHeader at all.
*/
+ record = (XLogRecord *) (state->readBuf + RecPtr % XLOG_BLCKSZ);
+
if (targetRecOff <= XLOG_BLCKSZ - SizeOfXLogRecord)
{
if (!ValidXLogRecordHeader(state, RecPtr, state->ReadRecPtr, record,
@@ -399,18 +399,13 @@ restart:
}
else
{
- /* XXX: more validation should be done here */
- if (total_len < SizeOfXLogRecord)
- {
- report_invalid_record(state,
- "invalid record length at %X/%X: wanted %u, got %u",
- LSN_FORMAT_ARGS(RecPtr),
- (uint32) SizeOfXLogRecord, total_len);
+ if (!ValidXLogRecordLength(state, RecPtr, record))
goto err;
- }
+
gotheader = false;
}
+ total_len = record->xl_tot_len;
len = XLOG_BLCKSZ - RecPtr % XLOG_BLCKSZ;
if (total_len > len)
{
@@ -588,6 +583,15 @@ err:
*/
state->abortedRecPtr = RecPtr;
state->missingContrecPtr = targetPagePtr;
+
+ /*
+ * If the message is not set yet, that means we failed to load the
+ * page for the record. Otherwise do not hide the existing message.
+ */
+ if (state->errormsg_buf[0] == '\0')
+ report_invalid_record(state,
+ "missing contrecord at %X/%X",
+ LSN_FORMAT_ARGS(RecPtr));
}
/*
@@ -719,6 +723,60 @@ XLogReaderInvalReadState(XLogReaderState *state)
state->readLen = 0;
}
+/*
+ * Validate record length of an XLOG record header.
+ *
+ * This is substantially a part of ValidXLogRecordHeader. But XLogReadRecord
+ * needs this separate from the function in case of a partial record header.
+ */
+static bool
+ValidXLogRecordLength(XLogReaderState *state, XLogRecPtr RecPtr,
+ XLogRecord *record)
+{
+ if (record->xl_tot_len == 0)
+ {
+ char *p;
+ char *pe;
+
+ /*
+ * We are almost sure reaching the end of WAL, make sure that the
+ * whole page after the record is filled with zeroes.
+ */
+ p = (char *) record;
+ pe = p + XLOG_BLCKSZ - (RecPtr & (XLOG_BLCKSZ - 1));
+
+ while (*p == 0 && p < pe)
+ p++;
+
+ if (p == pe)
+ {
+ /*
+ * The page after the record is completely zeroed. That suggests
+ * we don't have a record after this point. We don't bother
+ * checking the pages after since they are not zeroed in the case
+ * of recycled segments.
+ */
+ report_invalid_record(state, "empty record at %X/%X",
+ LSN_FORMAT_ARGS(RecPtr));
+
+ /* notify end-of-wal to callers */
+ state->EndOfWAL = true;
+ return false;
+ }
+ }
+
+ if (record->xl_tot_len < SizeOfXLogRecord)
+ {
+ report_invalid_record(state,
+ "invalid record length at %X/%X: wanted %u, got %u",
+ LSN_FORMAT_ARGS(RecPtr),
+ (uint32) SizeOfXLogRecord, record->xl_tot_len);
+ return false;
+ }
+
+ return true;
+}
+
/*
* Validate an XLOG record header.
*
@@ -730,14 +788,9 @@ ValidXLogRecordHeader(XLogReaderState *state, XLogRecPtr RecPtr,
XLogRecPtr PrevRecPtr, XLogRecord *record,
bool randAccess)
{
- if (record->xl_tot_len < SizeOfXLogRecord)
- {
- report_invalid_record(state,
- "invalid record length at %X/%X: wanted %u, got %u",
- LSN_FORMAT_ARGS(RecPtr),
- (uint32) SizeOfXLogRecord, record->xl_tot_len);
+ if (!ValidXLogRecordLength(state, RecPtr, record))
return false;
- }
+
if (record->xl_rmid > RM_MAX_ID)
{
report_invalid_record(state,
@@ -836,6 +889,31 @@ XLogReaderValidatePageHeader(XLogReaderState *state, XLogRecPtr recptr,
XLogSegNoOffsetToRecPtr(segno, offset, state->segcxt.ws_segsize, recaddr);
+ StaticAssertStmt(XLOG_PAGE_MAGIC != 0, "XLOG_PAGE_MAGIC is zero");
+
+ if (hdr->xlp_magic == 0)
+ {
+ /* Regard an empty page as End-Of-WAL */
+ int i;
+
+ for (i = 0; i < XLOG_BLCKSZ && phdr[i] == 0; i++);
+ if (i == XLOG_BLCKSZ)
+ {
+ char fname[MAXFNAMELEN];
+
+ XLogFileName(fname, state->seg.ws_tli, segno,
+ state->segcxt.ws_segsize);
+
+ report_invalid_record(state,
+ "empty page in log segment %s, offset %u",
+ fname,
+ offset);
+ state->EndOfWAL = true;
+ return false;
+ }
+
+ /* The same condition will be caught as invalid magic number */
+ }
if (hdr->xlp_magic != XLOG_PAGE_MAGIC)
{
char fname[MAXFNAMELEN];
@@ -921,6 +999,14 @@ XLogReaderValidatePageHeader(XLogReaderState *state, XLogRecPtr recptr,
LSN_FORMAT_ARGS(hdr->xlp_pageaddr),
fname,
offset);
+
+ /*
+ * If the page address is less than expected we assume it is an unused
+ * page in a recycled segment.
+ */
+ if (hdr->xlp_pageaddr < recaddr)
+ state->EndOfWAL = true;
+
return false;
}
diff --git a/src/backend/access/transam/xlogrecovery.c b/src/backend/access/transam/xlogrecovery.c
index f9f212680b..750056acaf 100644
--- a/src/backend/access/transam/xlogrecovery.c
+++ b/src/backend/access/transam/xlogrecovery.c
@@ -1592,7 +1592,7 @@ PerformWalRecovery(void)
/* just have to read next record after CheckPoint */
Assert(xlogreader->ReadRecPtr == CheckPointLoc);
replayTLI = CheckPointTLI;
- record = ReadRecord(xlogreader, LOG, false, replayTLI);
+ record = ReadRecord(xlogreader, WARNING, false, replayTLI);
}
if (record != NULL)
@@ -1706,7 +1706,7 @@ PerformWalRecovery(void)
}
/* Else, try to fetch the next WAL record */
- record = ReadRecord(xlogreader, LOG, false, replayTLI);
+ record = ReadRecord(xlogreader, WARNING, false, replayTLI);
} while (record != NULL);
/*
@@ -1765,13 +1765,20 @@ PerformWalRecovery(void)
InRedo = false;
}
- else
+ else if (xlogreader->EndOfWAL)
{
/* there are no WAL records following the checkpoint */
ereport(LOG,
(errmsg("redo is not required")));
}
+ else
+ {
+ /* broken record found */
+ ereport(WARNING,
+ (errmsg("redo is skipped"),
+ errhint("This suggests WAL file corruption. You might need to check the database.")));
+ }
/*
* This check is intentionally after the above log messages that indicate
@@ -2939,6 +2946,7 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
for (;;)
{
char *errormsg;
+ XLogRecPtr ErrRecPtr = InvalidXLogRecPtr;
record = XLogReadRecord(xlogreader, &errormsg);
if (record == NULL)
@@ -2954,6 +2962,18 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
{
abortedRecPtr = xlogreader->abortedRecPtr;
missingContrecPtr = xlogreader->missingContrecPtr;
+ ErrRecPtr = abortedRecPtr;
+ }
+ else
+ {
+ /*
+ * EndRecPtr is the LSN we tried to read but failed. In the
+ * case of decoding error, it is at the end of the failed
+ * record but we don't have a means for now to know EndRecPtr
+ * is pointing to which of the beginning or ending of the
+ * failed record.
+ */
+ ErrRecPtr = xlogreader->EndRecPtr;
}
if (readFile >= 0)
@@ -2963,13 +2983,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.
+ * We only end up here without a message when XLogPageRead() failed
+ * in that case we already logged something, or just met end-of-WAL
+ * conditions. In StandbyMode that only happens if we have been
+ * triggered, so we shouldn't loop anymore in that case. When
+ * EndOfWAL is true, we don't emit that error if any immediately
+ * and instead will show it as a part of a decent end-of-wal
+ * message later.
*/
- if (errormsg)
- ereport(emode_for_corrupt_record(emode, xlogreader->EndRecPtr),
+ if (!xlogreader->EndOfWAL && errormsg)
+ ereport(emode_for_corrupt_record(emode, ErrRecPtr),
(errmsg_internal("%s", errormsg) /* already translated */ ));
}
@@ -3000,11 +3023,14 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
/* Great, got a record */
return record;
}
- else
+
+ Assert(ErrRecPtr != InvalidXLogRecPtr);
+
+ /* No valid record available from this source */
+ lastSourceFailed = true;
+
+ if (!fetching_ckpt)
{
- /* No valid record available from this source */
- lastSourceFailed = true;
-
/*
* If archive recovery was requested, but we were still doing
* crash recovery, switch to archive recovery and retry using the
@@ -3017,11 +3043,16 @@ 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 pg_wal during crash recovery, entering archive recovery",
+ LSN_FORMAT_ARGS(ErrRecPtr),
+ replayTLI)));
InArchiveRecovery = true;
if (StandbyModeRequested)
StandbyMode = true;
@@ -3042,12 +3073,24 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
continue;
}
- /* In standby mode, loop back to retry. Otherwise, give up. */
- if (StandbyMode && !CheckForStandbyTrigger())
- continue;
- else
- return NULL;
+ /*
+ * recovery ended.
+ *
+ * Emit a decent message if we met end-of-WAL. Otherwise we should
+ * have already emitted an error message.
+ */
+ if (xlogreader->EndOfWAL)
+ ereport(LOG,
+ (errmsg("reached end of WAL at %X/%X on timeline %u",
+ LSN_FORMAT_ARGS(ErrRecPtr), replayTLI),
+ (errormsg ? errdetail_internal("%s", errormsg) : 0)));
}
+
+ /* In standby mode, loop back to retry. Otherwise, give up. */
+ if (StandbyMode && !CheckForStandbyTrigger())
+ continue;
+ else
+ return NULL;
}
}
@@ -3129,12 +3172,16 @@ retry:
private->replayTLI,
xlogreader->EndRecPtr))
{
+ Assert(!StandbyMode || CheckForStandbyTrigger());
+
if (readFile >= 0)
close(readFile);
readFile = -1;
readLen = 0;
readSource = XLOG_FROM_ANY;
+ /* promotion exit is not end-of-WAL */
+ xlogreader->EndOfWAL = !StandbyMode;
return -1;
}
}
@@ -3767,7 +3814,8 @@ emode_for_corrupt_record(int emode, XLogRecPtr RecPtr)
{
static XLogRecPtr lastComplaint = 0;
- if (readSource == XLOG_FROM_PG_WAL && emode == LOG)
+ /* use currentSource as readSource is reset at failure */
+ if (currentSource == XLOG_FROM_PG_WAL && emode <= WARNING)
{
if (RecPtr == lastComplaint)
emode = DEBUG1;
diff --git a/src/backend/replication/walreceiver.c b/src/backend/replication/walreceiver.c
index ceaff097b9..4f117ea4da 100644
--- a/src/backend/replication/walreceiver.c
+++ b/src/backend/replication/walreceiver.c
@@ -472,10 +472,9 @@ 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.",
- startpointTLI,
- LSN_FORMAT_ARGS(LogstreamResult.Write))));
+ (errmsg("replication terminated by primary server at %X/%X on timeline %u.",
+ LSN_FORMAT_ARGS(LogstreamResult.Write),
+ startpointTLI)));
endofwal = true;
break;
}
diff --git a/src/bin/pg_waldump/pg_waldump.c b/src/bin/pg_waldump/pg_waldump.c
index 2340dc247b..215abe95dc 100644
--- a/src/bin/pg_waldump/pg_waldump.c
+++ b/src/bin/pg_waldump/pg_waldump.c
@@ -1173,9 +1173,16 @@ main(int argc, char **argv)
exit(0);
if (errormsg)
- fatal_error("error in WAL record at %X/%X: %s",
- LSN_FORMAT_ARGS(xlogreader_state->ReadRecPtr),
- errormsg);
+ {
+ if (xlogreader_state->EndOfWAL)
+ pg_log_info("end of WAL at %X/%X: %s",
+ LSN_FORMAT_ARGS(xlogreader_state->EndRecPtr),
+ errormsg);
+ else
+ fatal_error("error in WAL record at %X/%X: %s",
+ LSN_FORMAT_ARGS(xlogreader_state->EndRecPtr),
+ errormsg);
+ }
XLogReaderFree(xlogreader_state);
diff --git a/src/include/access/xlogreader.h b/src/include/access/xlogreader.h
index 477f0efe26..7b314ef10e 100644
--- a/src/include/access/xlogreader.h
+++ b/src/include/access/xlogreader.h
@@ -174,6 +174,7 @@ struct XLogReaderState
*/
XLogRecPtr ReadRecPtr; /* start of last record read */
XLogRecPtr EndRecPtr; /* end+1 of last record read */
+ bool EndOfWAL; /* was the last attempt EOW? */
/*
* Set at the end of recovery: the start point of a partial record at the
diff --git a/src/test/recovery/t/011_crash_recovery.pl b/src/test/recovery/t/011_crash_recovery.pl
index 14154d1ce0..01033334d6 100644
--- a/src/test/recovery/t/011_crash_recovery.pl
+++ b/src/test/recovery/t/011_crash_recovery.pl
@@ -10,7 +10,9 @@ use PostgreSQL::Test::Cluster;
use PostgreSQL::Test::Utils;
use Test::More;
use Config;
+use IPC::Run;
+my $reached_eow_pat = "reached end of WAL at ";
my $node = PostgreSQL::Test::Cluster->new('primary');
$node->init(allows_streaming => 1);
$node->start;
@@ -48,7 +50,15 @@ is($node->safe_psql('postgres', qq[SELECT pg_xact_status('$xid');]),
# Crash and restart the postmaster
$node->stop('immediate');
+my $logstart = get_log_size($node);
$node->start;
+my $max_attempts = 360;
+while ($max_attempts-- >= 0)
+{
+ last if (find_in_log($node, $reached_eow_pat, $logstart));
+ sleep 0.5;
+}
+ok ($max_attempts >= 0, "end-of-wal is logged");
# Make sure we really got a new xid
cmp_ok($node->safe_psql('postgres', 'SELECT pg_current_xact_id()'),
@@ -61,4 +71,100 @@ is($node->safe_psql('postgres', qq[SELECT pg_xact_status('$xid');]),
$stdin .= "\\q\n";
$tx->finish; # wait for psql to quit gracefully
+my $segsize = $node->safe_psql('postgres',
+ qq[SELECT setting FROM pg_settings WHERE name = 'wal_segment_size';]);
+
+# make sure no records afterwards go to the next segment
+$node->safe_psql('postgres', qq[
+ SELECT pg_switch_wal();
+ CHECKPOINT;
+ CREATE TABLE t();
+]);
+$node->stop('immediate');
+
+# identify REDO WAL file
+my $cmd = "pg_controldata -D " . $node->data_dir();
+$cmd = ['pg_controldata', '-D', $node->data_dir()];
+$stdout = '';
+$stderr = '';
+IPC::Run::run $cmd, '>', \$stdout, '2>', \$stderr;
+ok($stdout =~ /^Latest checkpoint's REDO WAL file:[ \t] *(.+)$/m,
+ "checkpoint file is identified");
+my $chkptfile = $1;
+
+# identify the last record
+my $walfile = $node->data_dir() . "/pg_wal/$chkptfile";
+$cmd = ['pg_waldump', $walfile];
+$stdout = '';
+$stderr = '';
+my $lastrec;
+IPC::Run::run $cmd, '>', \$stdout, '2>', \$stderr;
+foreach my $l (split(/\r?\n/, $stdout))
+{
+ $lastrec = $l;
+}
+ok(defined $lastrec, "last WAL record is extracted");
+ok($stderr =~ /end of WAL at ([0-9A-F\/]+): .* at \g1/,
+ "pg_waldump emits the correct ending message");
+
+# read the last record LSN excluding leading zeroes
+ok ($lastrec =~ /, lsn: 0\/0*([1-9A-F][0-9A-F]+),/,
+ "LSN of the last record identified");
+my $lastlsn = $1;
+
+# corrupt the last record
+my $offset = hex($lastlsn) % $segsize;
+open(my $segf, '+<', $walfile) or die "failed to open $walfile\n";
+seek($segf, $offset, 0); # halfway break the last record
+print $segf "\0\0\0\0";
+close($segf);
+
+# pg_waldump complains about the corrupted record
+$stdout = '';
+$stderr = '';
+IPC::Run::run $cmd, '>', \$stdout, '2>', \$stderr;
+ok($stderr =~ /fatal: error in WAL record at 0\/$lastlsn: .* at 0\/$lastlsn/,
+ "pg_waldump emits the correct error message");
+
+# also server complains
+$logstart = get_log_size($node);
+$node->start;
+$max_attempts = 360;
+while ($max_attempts-- >= 0)
+{
+ last if (find_in_log($node, "WARNING: invalid record length at 0/$lastlsn: wanted [0-9]+, got 0",
+ $logstart));
+ sleep 0.5;
+}
+ok($max_attempts >= 0, "header error is logged at $lastlsn");
+
+# no end-of-wal message should be seen this time
+ok(!find_in_log($node, $reached_eow_pat, $logstart),
+ "false log message is not emitted");
+
+$node->stop('immediate');
+
done_testing();
+
+#### helper routines
+# return the size of logfile of $node in bytes
+sub get_log_size
+{
+ my ($node) = @_;
+
+ return (stat $node->logfile)[7];
+}
+
+# find $pat in logfile of $node after $off-th byte
+sub find_in_log
+{
+ my ($node, $pat, $off) = @_;
+
+ $off = 0 unless defined $off;
+ my $log = PostgreSQL::Test::Utils::slurp_file($node->logfile);
+ return 0 if (length($log) <= $off);
+
+ $log = substr($log, $off);
+
+ return $log =~ m/$pat/;
+}
--
2.27.0
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2022-03-22 00:01 Andres Freund <[email protected]>
parent: Kyotaro Horiguchi <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Andres Freund @ 2022-03-22 00:01 UTC (permalink / raw)
To: Kyotaro Horiguchi <[email protected]>; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
Hi,
On 2022-03-04 09:43:59 +0900, Kyotaro Horiguchi wrote:
> On second thought the two seems repeating the same things. Thus I
> merged the two comments together. In this verion 16 it looks like
> this.
Patch currently fails to apply, needs a rebase:
http://cfbot.cputube.org/patch_37_2490.log
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2022-03-22 02:34 Kyotaro Horiguchi <[email protected]>
parent: Andres Freund <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Kyotaro Horiguchi @ 2022-03-22 02:34 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
At Mon, 21 Mar 2022 17:01:19 -0700, Andres Freund <[email protected]> wrote in
> Patch currently fails to apply, needs a rebase:
> http://cfbot.cputube.org/patch_37_2490.log
Thanks for noticing me of that.
Rebased to the current HEAD.
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
Attachments:
[text/x-patch] v17-0001-Make-End-Of-Recovery-error-less-scary.patch (20.0K, ../../[email protected]/2-v17-0001-Make-End-Of-Recovery-error-less-scary.patch)
download | inline diff:
From a7c9f36e631eaba5078398598dae5d459e79add9 Mon Sep 17 00:00:00 2001
From: Kyotaro Horiguchi <[email protected]>
Date: Fri, 28 Feb 2020 15:52:58 +0900
Subject: [PATCH v17] 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. Actually if recovery meets a record with length = 0, that
usually means it finished applying all available WAL records.
Make this message less scary as "reached end of WAL". Instead, raise
the error level for other kind of WAL failure to WARNING.
---
src/backend/access/transam/xlogreader.c | 145 +++++++++++++++++-----
src/backend/access/transam/xlogrecovery.c | 92 ++++++++++----
src/backend/replication/walreceiver.c | 7 +-
src/bin/pg_waldump/pg_waldump.c | 13 +-
src/include/access/xlogreader.h | 1 +
src/test/recovery/t/011_crash_recovery.pl | 106 ++++++++++++++++
6 files changed, 306 insertions(+), 58 deletions(-)
diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.c
index e437c42992..0942265408 100644
--- a/src/backend/access/transam/xlogreader.c
+++ b/src/backend/access/transam/xlogreader.c
@@ -46,6 +46,8 @@ static int ReadPageInternal(XLogReaderState *state, XLogRecPtr pageptr,
int reqLen);
static void XLogReaderInvalReadState(XLogReaderState *state);
static XLogPageReadResult XLogDecodeNextRecord(XLogReaderState *state, bool non_blocking);
+static bool ValidXLogRecordLength(XLogReaderState *state, XLogRecPtr RecPtr,
+ XLogRecord *record);
static bool ValidXLogRecordHeader(XLogReaderState *state, XLogRecPtr RecPtr,
XLogRecPtr PrevRecPtr, XLogRecord *record, bool randAccess);
static bool ValidXLogRecord(XLogReaderState *state, XLogRecord *record,
@@ -147,6 +149,7 @@ XLogReaderAllocate(int wal_segment_size, const char *waldir,
pfree(state);
return NULL;
}
+ state->EndOfWAL = false;
state->errormsg_buf[0] = '\0';
/*
@@ -552,6 +555,7 @@ XLogDecodeNextRecord(XLogReaderState *state, bool nonblocking)
/* reset error state */
state->errormsg_buf[0] = '\0';
decoded = NULL;
+ state->EndOfWAL = false;
state->abortedRecPtr = InvalidXLogRecPtr;
state->missingContrecPtr = InvalidXLogRecPtr;
@@ -633,25 +637,21 @@ restart:
Assert(pageHeaderSize <= readOff);
/*
- * Read the record length.
+ * Validate the record header.
*
- * NB: Even though we use an XLogRecord pointer here, the whole record
- * header might not fit on this page. xl_tot_len is the first field of the
- * struct, so it must be on this page (the records are MAXALIGNed), but we
- * cannot access any other fields until we've verified that we got the
- * whole header.
- */
- record = (XLogRecord *) (state->readBuf + RecPtr % XLOG_BLCKSZ);
- total_len = record->xl_tot_len;
-
- /*
- * If the whole record header is on this page, validate it immediately.
- * Otherwise do just a basic sanity check on xl_tot_len, and validate the
- * rest of the header after reading it from the next page. The xl_tot_len
+ * Even though we use an XLogRecord pointer here, the whole record header
+ * might not fit on this page. If the whole record header is on this page,
+ * validate it immediately. Even otherwise xl_tot_len must be on this page
+ * (it is the first field of MAXALIGNed records), but we still cannot
+ * access any further fields until we've verified that we got the whole
+ * header, so do just a basic sanity check on record length, and validate
+ * the rest of the header after reading it from the next page. The length
* check is necessary here to ensure that we enter the "Need to reassemble
* record" code path below; otherwise we might fail to apply
* ValidXLogRecordHeader at all.
*/
+ record = (XLogRecord *) (state->readBuf + RecPtr % XLOG_BLCKSZ);
+
if (targetRecOff <= XLOG_BLCKSZ - SizeOfXLogRecord)
{
if (!ValidXLogRecordHeader(state, RecPtr, state->DecodeRecPtr, record,
@@ -661,18 +661,14 @@ restart:
}
else
{
- /* XXX: more validation should be done here */
- if (total_len < SizeOfXLogRecord)
- {
- report_invalid_record(state,
- "invalid record length at %X/%X: wanted %u, got %u",
- LSN_FORMAT_ARGS(RecPtr),
- (uint32) SizeOfXLogRecord, total_len);
+ if (!ValidXLogRecordLength(state, RecPtr, record))
goto err;
- }
+
gotheader = false;
}
+ total_len = record->xl_tot_len;
+
/*
* Find space to decode this record. Don't allow oversized allocation if
* the caller requested nonblocking. Otherwise, we *have* to try to
@@ -904,6 +900,15 @@ err:
*/
state->abortedRecPtr = RecPtr;
state->missingContrecPtr = targetPagePtr;
+
+ /*
+ * If the message is not set yet, that means we failed to load the
+ * page for the record. Otherwise do not hide the existing message.
+ */
+ if (state->errormsg_buf[0] == '\0')
+ report_invalid_record(state,
+ "missing contrecord at %X/%X",
+ LSN_FORMAT_ARGS(RecPtr));
}
if (decoded && decoded->oversized)
@@ -1083,6 +1088,60 @@ XLogReaderInvalReadState(XLogReaderState *state)
state->readLen = 0;
}
+/*
+ * Validate record length of an XLOG record header.
+ *
+ * This is substantially a part of ValidXLogRecordHeader. But XLogReadRecord
+ * needs this separate from the function in case of a partial record header.
+ */
+static bool
+ValidXLogRecordLength(XLogReaderState *state, XLogRecPtr RecPtr,
+ XLogRecord *record)
+{
+ if (record->xl_tot_len == 0)
+ {
+ char *p;
+ char *pe;
+
+ /*
+ * We are almost sure reaching the end of WAL, make sure that the
+ * whole page after the record is filled with zeroes.
+ */
+ p = (char *) record;
+ pe = p + XLOG_BLCKSZ - (RecPtr & (XLOG_BLCKSZ - 1));
+
+ while (*p == 0 && p < pe)
+ p++;
+
+ if (p == pe)
+ {
+ /*
+ * The page after the record is completely zeroed. That suggests
+ * we don't have a record after this point. We don't bother
+ * checking the pages after since they are not zeroed in the case
+ * of recycled segments.
+ */
+ report_invalid_record(state, "empty record at %X/%X",
+ LSN_FORMAT_ARGS(RecPtr));
+
+ /* notify end-of-wal to callers */
+ state->EndOfWAL = true;
+ return false;
+ }
+ }
+
+ if (record->xl_tot_len < SizeOfXLogRecord)
+ {
+ report_invalid_record(state,
+ "invalid record length at %X/%X: wanted %u, got %u",
+ LSN_FORMAT_ARGS(RecPtr),
+ (uint32) SizeOfXLogRecord, record->xl_tot_len);
+ return false;
+ }
+
+ return true;
+}
+
/*
* Validate an XLOG record header.
*
@@ -1094,14 +1153,9 @@ ValidXLogRecordHeader(XLogReaderState *state, XLogRecPtr RecPtr,
XLogRecPtr PrevRecPtr, XLogRecord *record,
bool randAccess)
{
- if (record->xl_tot_len < SizeOfXLogRecord)
- {
- report_invalid_record(state,
- "invalid record length at %X/%X: wanted %u, got %u",
- LSN_FORMAT_ARGS(RecPtr),
- (uint32) SizeOfXLogRecord, record->xl_tot_len);
+ if (!ValidXLogRecordLength(state, RecPtr, record))
return false;
- }
+
if (record->xl_rmid > RM_MAX_ID)
{
report_invalid_record(state,
@@ -1200,6 +1254,31 @@ XLogReaderValidatePageHeader(XLogReaderState *state, XLogRecPtr recptr,
XLogSegNoOffsetToRecPtr(segno, offset, state->segcxt.ws_segsize, recaddr);
+ StaticAssertStmt(XLOG_PAGE_MAGIC != 0, "XLOG_PAGE_MAGIC is zero");
+
+ if (hdr->xlp_magic == 0)
+ {
+ /* Regard an empty page as End-Of-WAL */
+ int i;
+
+ for (i = 0; i < XLOG_BLCKSZ && phdr[i] == 0; i++);
+ if (i == XLOG_BLCKSZ)
+ {
+ char fname[MAXFNAMELEN];
+
+ XLogFileName(fname, state->seg.ws_tli, segno,
+ state->segcxt.ws_segsize);
+
+ report_invalid_record(state,
+ "empty page in log segment %s, offset %u",
+ fname,
+ offset);
+ state->EndOfWAL = true;
+ return false;
+ }
+
+ /* The same condition will be caught as invalid magic number */
+ }
if (hdr->xlp_magic != XLOG_PAGE_MAGIC)
{
char fname[MAXFNAMELEN];
@@ -1285,6 +1364,14 @@ XLogReaderValidatePageHeader(XLogReaderState *state, XLogRecPtr recptr,
LSN_FORMAT_ARGS(hdr->xlp_pageaddr),
fname,
offset);
+
+ /*
+ * If the page address is less than expected we assume it is an unused
+ * page in a recycled segment.
+ */
+ if (hdr->xlp_pageaddr < recaddr)
+ state->EndOfWAL = true;
+
return false;
}
diff --git a/src/backend/access/transam/xlogrecovery.c b/src/backend/access/transam/xlogrecovery.c
index 9feea3e6ec..98382d66a4 100644
--- a/src/backend/access/transam/xlogrecovery.c
+++ b/src/backend/access/transam/xlogrecovery.c
@@ -1592,7 +1592,7 @@ PerformWalRecovery(void)
/* just have to read next record after CheckPoint */
Assert(xlogreader->ReadRecPtr == CheckPointLoc);
replayTLI = CheckPointTLI;
- record = ReadRecord(xlogreader, LOG, false, replayTLI);
+ record = ReadRecord(xlogreader, WARNING, false, replayTLI);
}
if (record != NULL)
@@ -1706,7 +1706,7 @@ PerformWalRecovery(void)
}
/* Else, try to fetch the next WAL record */
- record = ReadRecord(xlogreader, LOG, false, replayTLI);
+ record = ReadRecord(xlogreader, WARNING, false, replayTLI);
} while (record != NULL);
/*
@@ -1765,13 +1765,20 @@ PerformWalRecovery(void)
InRedo = false;
}
- else
+ else if (xlogreader->EndOfWAL)
{
/* there are no WAL records following the checkpoint */
ereport(LOG,
(errmsg("redo is not required")));
}
+ else
+ {
+ /* broken record found */
+ ereport(WARNING,
+ (errmsg("redo is skipped"),
+ errhint("This suggests WAL file corruption. You might need to check the database.")));
+ }
/*
* This check is intentionally after the above log messages that indicate
@@ -2939,6 +2946,7 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
for (;;)
{
char *errormsg;
+ XLogRecPtr ErrRecPtr = InvalidXLogRecPtr;
record = XLogReadRecord(xlogreader, &errormsg);
if (record == NULL)
@@ -2954,6 +2962,18 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
{
abortedRecPtr = xlogreader->abortedRecPtr;
missingContrecPtr = xlogreader->missingContrecPtr;
+ ErrRecPtr = abortedRecPtr;
+ }
+ else
+ {
+ /*
+ * EndRecPtr is the LSN we tried to read but failed. In the
+ * case of decoding error, it is at the end of the failed
+ * record but we don't have a means for now to know EndRecPtr
+ * is pointing to which of the beginning or ending of the
+ * failed record.
+ */
+ ErrRecPtr = xlogreader->EndRecPtr;
}
if (readFile >= 0)
@@ -2963,13 +2983,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.
+ * We only end up here without a message when XLogPageRead() failed
+ * in that case we already logged something, or just met end-of-WAL
+ * conditions. In StandbyMode that only happens if we have been
+ * triggered, so we shouldn't loop anymore in that case. When
+ * EndOfWAL is true, we don't emit that error if any immediately
+ * and instead will show it as a part of a decent end-of-wal
+ * message later.
*/
- if (errormsg)
- ereport(emode_for_corrupt_record(emode, xlogreader->EndRecPtr),
+ if (!xlogreader->EndOfWAL && errormsg)
+ ereport(emode_for_corrupt_record(emode, ErrRecPtr),
(errmsg_internal("%s", errormsg) /* already translated */ ));
}
@@ -3000,11 +3023,14 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
/* Great, got a record */
return record;
}
- else
+
+ Assert(ErrRecPtr != InvalidXLogRecPtr);
+
+ /* No valid record available from this source */
+ lastSourceFailed = true;
+
+ if (!fetching_ckpt)
{
- /* No valid record available from this source */
- lastSourceFailed = true;
-
/*
* If archive recovery was requested, but we were still doing
* crash recovery, switch to archive recovery and retry using the
@@ -3017,11 +3043,16 @@ 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 pg_wal during crash recovery, entering archive recovery",
+ LSN_FORMAT_ARGS(ErrRecPtr),
+ replayTLI)));
InArchiveRecovery = true;
if (StandbyModeRequested)
StandbyMode = true;
@@ -3042,12 +3073,24 @@ ReadRecord(XLogReaderState *xlogreader, int emode,
continue;
}
- /* In standby mode, loop back to retry. Otherwise, give up. */
- if (StandbyMode && !CheckForStandbyTrigger())
- continue;
- else
- return NULL;
+ /*
+ * recovery ended.
+ *
+ * Emit a decent message if we met end-of-WAL. Otherwise we should
+ * have already emitted an error message.
+ */
+ if (xlogreader->EndOfWAL)
+ ereport(LOG,
+ (errmsg("reached end of WAL at %X/%X on timeline %u",
+ LSN_FORMAT_ARGS(ErrRecPtr), replayTLI),
+ (errormsg ? errdetail_internal("%s", errormsg) : 0)));
}
+
+ /* In standby mode, loop back to retry. Otherwise, give up. */
+ if (StandbyMode && !CheckForStandbyTrigger())
+ continue;
+ else
+ return NULL;
}
}
@@ -3129,12 +3172,16 @@ retry:
private->replayTLI,
xlogreader->EndRecPtr))
{
+ Assert(!StandbyMode || CheckForStandbyTrigger());
+
if (readFile >= 0)
close(readFile);
readFile = -1;
readLen = 0;
readSource = XLOG_FROM_ANY;
+ /* promotion exit is not end-of-WAL */
+ xlogreader->EndOfWAL = !StandbyMode;
return -1;
}
}
@@ -3767,7 +3814,8 @@ emode_for_corrupt_record(int emode, XLogRecPtr RecPtr)
{
static XLogRecPtr lastComplaint = 0;
- if (readSource == XLOG_FROM_PG_WAL && emode == LOG)
+ /* use currentSource as readSource is reset at failure */
+ if (currentSource == XLOG_FROM_PG_WAL && emode <= WARNING)
{
if (RecPtr == lastComplaint)
emode = DEBUG1;
diff --git a/src/backend/replication/walreceiver.c b/src/backend/replication/walreceiver.c
index ceaff097b9..4f117ea4da 100644
--- a/src/backend/replication/walreceiver.c
+++ b/src/backend/replication/walreceiver.c
@@ -472,10 +472,9 @@ 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.",
- startpointTLI,
- LSN_FORMAT_ARGS(LogstreamResult.Write))));
+ (errmsg("replication terminated by primary server at %X/%X on timeline %u.",
+ LSN_FORMAT_ARGS(LogstreamResult.Write),
+ startpointTLI)));
endofwal = true;
break;
}
diff --git a/src/bin/pg_waldump/pg_waldump.c b/src/bin/pg_waldump/pg_waldump.c
index fc081adfb8..9bebca8154 100644
--- a/src/bin/pg_waldump/pg_waldump.c
+++ b/src/bin/pg_waldump/pg_waldump.c
@@ -1174,9 +1174,16 @@ main(int argc, char **argv)
exit(0);
if (errormsg)
- fatal_error("error in WAL record at %X/%X: %s",
- LSN_FORMAT_ARGS(xlogreader_state->ReadRecPtr),
- errormsg);
+ {
+ if (xlogreader_state->EndOfWAL)
+ pg_log_info("end of WAL at %X/%X: %s",
+ LSN_FORMAT_ARGS(xlogreader_state->EndRecPtr),
+ errormsg);
+ else
+ fatal_error("error in WAL record at %X/%X: %s",
+ LSN_FORMAT_ARGS(xlogreader_state->EndRecPtr),
+ errormsg);
+ }
XLogReaderFree(xlogreader_state);
diff --git a/src/include/access/xlogreader.h b/src/include/access/xlogreader.h
index f4388cc9be..21a8f9552c 100644
--- a/src/include/access/xlogreader.h
+++ b/src/include/access/xlogreader.h
@@ -201,6 +201,7 @@ struct XLogReaderState
*/
XLogRecPtr ReadRecPtr; /* start of last record read */
XLogRecPtr EndRecPtr; /* end+1 of last record read */
+ bool EndOfWAL; /* was the last attempt EOW? */
/*
* Set at the end of recovery: the start point of a partial record at the
diff --git a/src/test/recovery/t/011_crash_recovery.pl b/src/test/recovery/t/011_crash_recovery.pl
index 14154d1ce0..01033334d6 100644
--- a/src/test/recovery/t/011_crash_recovery.pl
+++ b/src/test/recovery/t/011_crash_recovery.pl
@@ -10,7 +10,9 @@ use PostgreSQL::Test::Cluster;
use PostgreSQL::Test::Utils;
use Test::More;
use Config;
+use IPC::Run;
+my $reached_eow_pat = "reached end of WAL at ";
my $node = PostgreSQL::Test::Cluster->new('primary');
$node->init(allows_streaming => 1);
$node->start;
@@ -48,7 +50,15 @@ is($node->safe_psql('postgres', qq[SELECT pg_xact_status('$xid');]),
# Crash and restart the postmaster
$node->stop('immediate');
+my $logstart = get_log_size($node);
$node->start;
+my $max_attempts = 360;
+while ($max_attempts-- >= 0)
+{
+ last if (find_in_log($node, $reached_eow_pat, $logstart));
+ sleep 0.5;
+}
+ok ($max_attempts >= 0, "end-of-wal is logged");
# Make sure we really got a new xid
cmp_ok($node->safe_psql('postgres', 'SELECT pg_current_xact_id()'),
@@ -61,4 +71,100 @@ is($node->safe_psql('postgres', qq[SELECT pg_xact_status('$xid');]),
$stdin .= "\\q\n";
$tx->finish; # wait for psql to quit gracefully
+my $segsize = $node->safe_psql('postgres',
+ qq[SELECT setting FROM pg_settings WHERE name = 'wal_segment_size';]);
+
+# make sure no records afterwards go to the next segment
+$node->safe_psql('postgres', qq[
+ SELECT pg_switch_wal();
+ CHECKPOINT;
+ CREATE TABLE t();
+]);
+$node->stop('immediate');
+
+# identify REDO WAL file
+my $cmd = "pg_controldata -D " . $node->data_dir();
+$cmd = ['pg_controldata', '-D', $node->data_dir()];
+$stdout = '';
+$stderr = '';
+IPC::Run::run $cmd, '>', \$stdout, '2>', \$stderr;
+ok($stdout =~ /^Latest checkpoint's REDO WAL file:[ \t] *(.+)$/m,
+ "checkpoint file is identified");
+my $chkptfile = $1;
+
+# identify the last record
+my $walfile = $node->data_dir() . "/pg_wal/$chkptfile";
+$cmd = ['pg_waldump', $walfile];
+$stdout = '';
+$stderr = '';
+my $lastrec;
+IPC::Run::run $cmd, '>', \$stdout, '2>', \$stderr;
+foreach my $l (split(/\r?\n/, $stdout))
+{
+ $lastrec = $l;
+}
+ok(defined $lastrec, "last WAL record is extracted");
+ok($stderr =~ /end of WAL at ([0-9A-F\/]+): .* at \g1/,
+ "pg_waldump emits the correct ending message");
+
+# read the last record LSN excluding leading zeroes
+ok ($lastrec =~ /, lsn: 0\/0*([1-9A-F][0-9A-F]+),/,
+ "LSN of the last record identified");
+my $lastlsn = $1;
+
+# corrupt the last record
+my $offset = hex($lastlsn) % $segsize;
+open(my $segf, '+<', $walfile) or die "failed to open $walfile\n";
+seek($segf, $offset, 0); # halfway break the last record
+print $segf "\0\0\0\0";
+close($segf);
+
+# pg_waldump complains about the corrupted record
+$stdout = '';
+$stderr = '';
+IPC::Run::run $cmd, '>', \$stdout, '2>', \$stderr;
+ok($stderr =~ /fatal: error in WAL record at 0\/$lastlsn: .* at 0\/$lastlsn/,
+ "pg_waldump emits the correct error message");
+
+# also server complains
+$logstart = get_log_size($node);
+$node->start;
+$max_attempts = 360;
+while ($max_attempts-- >= 0)
+{
+ last if (find_in_log($node, "WARNING: invalid record length at 0/$lastlsn: wanted [0-9]+, got 0",
+ $logstart));
+ sleep 0.5;
+}
+ok($max_attempts >= 0, "header error is logged at $lastlsn");
+
+# no end-of-wal message should be seen this time
+ok(!find_in_log($node, $reached_eow_pat, $logstart),
+ "false log message is not emitted");
+
+$node->stop('immediate');
+
done_testing();
+
+#### helper routines
+# return the size of logfile of $node in bytes
+sub get_log_size
+{
+ my ($node) = @_;
+
+ return (stat $node->logfile)[7];
+}
+
+# find $pat in logfile of $node after $off-th byte
+sub find_in_log
+{
+ my ($node, $pat, $off) = @_;
+
+ $off = 0 unless defined $off;
+ my $log = PostgreSQL::Test::Utils::slurp_file($node->logfile);
+ return 0 if (length($log) <= $off);
+
+ $log = substr($log, $off);
+
+ return $log =~ m/$pat/;
+}
--
2.27.0
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2022-03-29 06:07 Kyotaro Horiguchi <[email protected]>
parent: Kyotaro Horiguchi <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Kyotaro Horiguchi @ 2022-03-29 06:07 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
me> Rebased to the current HEAD.
b64c3bd62e (removal of unused "use Config") conflicted on a TAP
script.
Rebased.
--
Kyotaro Horiguchi
NTT Open Source Software Center
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2022-07-06 18:05 Jacob Champion <[email protected]>
parent: Kyotaro Horiguchi <[email protected]>
0 siblings, 2 replies; 38+ messages in thread
From: Jacob Champion @ 2022-07-06 18:05 UTC (permalink / raw)
To: Kyotaro Horiguchi <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]; [email protected]; Michael Paquier <[email protected]>; [email protected]; David Steele <[email protected]>; [email protected]; PostgreSQL Hackers <[email protected]>; [email protected]; Robert Haas <[email protected]>
On Mon, Mar 28, 2022 at 11:07 PM Kyotaro Horiguchi
<[email protected]> wrote:
>
> Rebased.
Unfortunately this will need another rebase over latest.
[CFM hat] Looking through the history here, this has been bumped to
Ready for Committer a few times and then bumped back to Needs Review
after a required rebase. What's the best way for us to provide support
for contributors who get stuck in this loop? Maybe we can be more
aggressive about automated notifications when a RfC patch goes red in
the cfbot?
Thanks,
--Jacob
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2022-07-07 00:04 Michael Paquier <[email protected]>
parent: Jacob Champion <[email protected]>
1 sibling, 0 replies; 38+ messages in thread
From: Michael Paquier @ 2022-07-07 00:04 UTC (permalink / raw)
To: Jacob Champion <[email protected]>; +Cc: Kyotaro Horiguchi <[email protected]>; Andres Freund <[email protected]>; [email protected]; [email protected]; [email protected]; David Steele <[email protected]>; [email protected]; PostgreSQL Hackers <[email protected]>; [email protected]; Robert Haas <[email protected]>
On Wed, Jul 06, 2022 at 11:05:51AM -0700, Jacob Champion wrote:
> [CFM hat] Looking through the history here, this has been bumped to
> Ready for Committer a few times and then bumped back to Needs Review
> after a required rebase. What's the best way for us to provide support
> for contributors who get stuck in this loop? Maybe we can be more
> aggressive about automated notifications when a RfC patch goes red in
> the cfbot?
Having a better integration between the CF bot and the CF app would be
great, IMO. People tend to easily forget about what they send in my
experience, even if they manage a small pool of patches or a larger
one.
--
Michael
Attachments:
[application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc)
download
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2022-07-07 08:32 Kyotaro Horiguchi <[email protected]>
parent: Jacob Champion <[email protected]>
1 sibling, 1 reply; 38+ messages in thread
From: Kyotaro Horiguchi @ 2022-07-07 08:32 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
At Wed, 6 Jul 2022 11:05:51 -0700, Jacob Champion <[email protected]> wrote in
> On Mon, Mar 28, 2022 at 11:07 PM Kyotaro Horiguchi
> <[email protected]> wrote:
> >
> > Rebased.
>
> Unfortunately this will need another rebase over latest.
Thanks! Done.
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2022-09-17 04:21 Justin Pryzby <[email protected]>
parent: Kyotaro Horiguchi <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Justin Pryzby @ 2022-09-17 04:21 UTC (permalink / raw)
To: Kyotaro Horiguchi <[email protected]>; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
@cfbot: rebased over adb466150, which did the same thing as one of the
hunks in xlogreader.c.
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2022-09-26 07:17 Kyotaro Horiguchi <[email protected]>
parent: Justin Pryzby <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Kyotaro Horiguchi @ 2022-09-26 07:17 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
At Fri, 16 Sep 2022 23:21:50 -0500, Justin Pryzby <[email protected]> wrote in
> @cfbot: rebased over adb466150, which did the same thing as one of the
> hunks in xlogreader.c.
Oops. Thanks! And then this gets a further conflict (param names
harmonization). So further rebased. And removed an extra blank line
you pointed.
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
^ permalink raw reply [nested|flat] 38+ messages in thread
* [PATCH v1 4/6] meson: Implement getopt logic from autoconf
@ 2022-09-28 17:06 Andres Freund <[email protected]>
0 siblings, 0 replies; 38+ messages in thread
From: Andres Freund @ 2022-09-28 17:06 UTC (permalink / raw)
Not replacing getopt/getopt_long definitely causes issues on mingw. It's not
as clear whether the solaris & openbsd aspect is still needed, but if not, we
should remove it from both autoconf and meson.
---
meson.build | 13 +++++++++++--
1 file changed, 11 insertions(+), 2 deletions(-)
diff --git a/meson.build b/meson.build
index cd410319f3f..48b0b4cbed8 100644
--- a/meson.build
+++ b/meson.build
@@ -2265,6 +2265,15 @@ posix4_dep = cc.find_library('posix4', required: false)
getopt_dep = cc.find_library('getopt', required: false)
gnugetopt_dep = cc.find_library('gnugetopt', required: false)
+# Check if we want to replace getopt/getopt_long even if provided by the system
+# - We want to use system's getopt_long() only if system provides struct
+# option
+# - Mingw has adopted a GNU-centric interpretation of optind/optreset,
+# so always use our version on Windows
+# - On OpenBSD and Solaris, getopt() doesn't do what we want for long options
+# (i.e., allow '-' as a flag character), so use our version on those platforms
+always_replace_getopt = host_system in ['windows', 'openbsd', 'solaris']
+always_replace_getopt_long = cdata.get('HAVE_STRUCT_OPTION', 1) != 1 or host_system == 'windows'
# Required on BSDs
execinfo_dep = cc.find_library('execinfo', required: false)
@@ -2295,8 +2304,8 @@ func_checks = [
['explicit_bzero'],
['fdatasync', {'dependencies': [rt_dep, posix4_dep], 'define': false}], # Solaris
['getifaddrs'],
- ['getopt', {'dependencies': [getopt_dep, gnugetopt_dep]}],
- ['getopt_long', {'dependencies': [getopt_dep, gnugetopt_dep]}],
+ ['getopt', {'dependencies': [getopt_dep, gnugetopt_dep], 'skip': always_replace_getopt}],
+ ['getopt_long', {'dependencies': [getopt_dep, gnugetopt_dep], 'skip': always_replace_getopt_long}],
['getpeereid'],
['getpeerucred'],
['inet_aton'],
--
2.37.3.542.gdd3f6c4cae
--3mylvpkolouaexyj
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
filename="v1-0005-mingw-Define-PGDLLEXPORT-as-__declspec-dllexport-.patch"
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2022-10-28 02:37 Justin Pryzby <[email protected]>
parent: Kyotaro Horiguchi <[email protected]>
0 siblings, 1 reply; 38+ messages in thread
From: Justin Pryzby @ 2022-10-28 02:37 UTC (permalink / raw)
To: Kyotaro Horiguchi <[email protected]>; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
rebased
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2022-11-18 08:25 Kyotaro Horiguchi <[email protected]>
parent: Justin Pryzby <[email protected]>
0 siblings, 2 replies; 38+ messages in thread
From: Kyotaro Horiguchi @ 2022-11-18 08:25 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
Just rebased.
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2022-11-22 17:20 Andres Freund <[email protected]>
parent: Kyotaro Horiguchi <[email protected]>
1 sibling, 0 replies; 38+ messages in thread
From: Andres Freund @ 2022-11-22 17:20 UTC (permalink / raw)
To: Kyotaro Horiguchi <[email protected]>; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
Hi,
On 2022-11-18 17:25:37 +0900, Kyotaro Horiguchi wrote:
> Just rebased.
Fails with address sanitizer:
https://cirrus-ci.com/task/5632986241564672
Unfortunately one of the failures is in pg_waldump and we don't seem to
capture its output in 011_crash_recovery. So we don't see the nice formattted
output...
[11:07:18.868] #0 0x00007fcf43803ce1 in raise () from /lib/x86_64-linux-gnu/libc.so.6
[11:07:18.912]
[11:07:18.912] Thread 1 (Thread 0x7fcf43662780 (LWP 39124)):
[11:07:18.912] #0 0x00007fcf43803ce1 in raise () from /lib/x86_64-linux-gnu/libc.so.6
[11:07:18.912] No symbol table info available.
[11:07:18.912] #1 0x00007fcf437ed537 in abort () from /lib/x86_64-linux-gnu/libc.so.6
[11:07:18.912] No symbol table info available.
[11:07:18.912] #2 0x00007fcf43b8511b in __sanitizer::Abort () at ../../../../src/libsanitizer/sanitizer_common/sanitizer_posix_libcdep.cpp:155
[11:07:18.912] No locals.
[11:07:18.912] #3 0x00007fcf43b8fce8 in __sanitizer::Die () at ../../../../src/libsanitizer/sanitizer_common/sanitizer_termination.cpp:58
[11:07:18.912] No locals.
[11:07:18.912] #4 0x00007fcf43b7244c in __asan::ScopedInErrorReport::~ScopedInErrorReport (this=0x7ffd4fde18e6, __in_chrg=<optimized out>) at ../../../../src/libsanitizer/asan/asan_report.cpp:186
[11:07:18.912] buffer_copy = {<__sanitizer::InternalMmapVectorNoCtor<char>> = {data_ = 0x7fcf40350000 '=' <repeats 65 times>, "\n==39124==ERROR: AddressSanitizer: heap-buffer-overflow on address 0x625000002100 at pc 0x55c36c21e315 bp 0x7ffd4fde2550 sp 0x7ffd4fde2"..., capacity_bytes_ = 65536, size_ = <optimized out>}, <No data fields>}
...
[11:07:18.912] #6 0x00007fcf43b72788 in __asan::__asan_report_load1 (addr=<optimized out>) at ../../../../src/libsanitizer/asan/asan_rtl.cpp:117
[11:07:18.912] bp = 140725943412048
[11:07:18.912] pc = <optimized out>
[11:07:18.912] local_stack = 140528180793728
[11:07:18.912] sp = 140725943412040
[11:07:18.912] #7 0x000055c36c21e315 in ValidXLogRecordLength (state=state@entry=0x61a000000680, RecPtr=RecPtr@entry=33655480, record=record@entry=0x625000000bb8) at xlogreader.c:1126
[11:07:18.912] p = <optimized out>
[11:07:18.912] pe = 0x625000002100 ""
[11:07:18.912] #8 0x000055c36c21e3b1 in ValidXLogRecordHeader (state=state@entry=0x61a000000680, RecPtr=RecPtr@entry=33655480, PrevRecPtr=33655104, record=record@entry=0x625000000bb8, randAccess=randAccess@entry=false) at xlogreader.c:1169
[11:07:18.912] No locals.
The most important bit is "AddressSanitizer: heap-buffer-overflow on address 0x6250000\
02100 at pc 0x55c36c21e315 bp 0x7ffd4fde2550 sp 0x7ffd4fde2"
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2022-11-22 22:04 Justin Pryzby <[email protected]>
parent: Kyotaro Horiguchi <[email protected]>
1 sibling, 1 reply; 38+ messages in thread
From: Justin Pryzby @ 2022-11-22 22:04 UTC (permalink / raw)
To: Kyotaro Horiguchi <[email protected]>; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
On Fri, Nov 18, 2022 at 05:25:37PM +0900, Kyotaro Horiguchi wrote:
> + while (*p == 0 && p < pe)
> + p++;
The bug reported by Andres/cfbot/ubsan is here.
Fixed in attached.
I didn't try to patch the test case to output the failing stderr, but
that might be good.
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2022-11-30 02:56 Kyotaro Horiguchi <[email protected]>
parent: Justin Pryzby <[email protected]>
0 siblings, 0 replies; 38+ messages in thread
From: Kyotaro Horiguchi @ 2022-11-30 02:56 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
At Tue, 22 Nov 2022 16:04:56 -0600, Justin Pryzby <[email protected]> wrote in
> On Fri, Nov 18, 2022 at 05:25:37PM +0900, Kyotaro Horiguchi wrote:
> > + while (*p == 0 && p < pe)
> > + p++;
>
> The bug reported by Andres/cfbot/ubsan is here.
>
> Fixed in attached.
Ur..ou..
- while (*p == 0 && p < pe)
+ while (p < pe && *p == 0)
It was an off-by-one error. Thanks!
> I didn't try to patch the test case to output the failing stderr, but
> that might be good.
I have made use of Cluster::wait_for_log(), but still find_in_log() is
there since it is used to check if a message that should not be logged
is not logged.
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2024-01-22 05:09 Peter Smith <[email protected]>
1 sibling, 1 reply; 38+ messages in thread
From: Peter Smith @ 2024-01-22 05:09 UTC (permalink / raw)
To: Michael Paquier <[email protected]>; +Cc: Aleksander Alekseev <[email protected]>; [email protected]; Kyotaro Horiguchi <[email protected]>; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
2024-01 Commitfest.
Hi, This patch has a CF status of "Needs Review" [1], but it seems
there were CFbot test failures last time it was run [2]. Please have a
look and post an updated version if necessary.
======
[1] https://commitfest.postgresql.org/46/2490/
[2] https://cirrus-ci.com/github/postgresql-cfbot/postgresql/commitfest/46/2490
Kind Regards,
Peter Smith.
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2024-01-23 04:01 Kyotaro Horiguchi <[email protected]>
parent: Peter Smith <[email protected]>
0 siblings, 0 replies; 38+ messages in thread
From: Kyotaro Horiguchi @ 2024-01-23 04:01 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
At Mon, 22 Jan 2024 16:09:28 +1100, Peter Smith <[email protected]> wrote in
> 2024-01 Commitfest.
>
> Hi, This patch has a CF status of "Needs Review" [1], but it seems
> there were CFbot test failures last time it was run [2]. Please have a
> look and post an updated version if necessary.
>
> ======
> [1] https://commitfest.postgresql.org/46/2490/
> [2] https://cirrus-ci.com/github/postgresql-cfbot/postgresql/commitfest/46/2490
Thanks for noticing of that. Will repost a new version.
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
^ permalink raw reply [nested|flat] 38+ messages in thread
* Re: Make mesage at end-of-recovery less scary.
@ 2024-01-23 04:13 Kyotaro Horiguchi <[email protected]>
1 sibling, 0 replies; 38+ messages in thread
From: Kyotaro Horiguchi @ 2024-01-23 04:13 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
At Wed, 17 Jan 2024 14:32:00 +0900, Michael Paquier <[email protected]> wrote in
> On Tue, Jan 16, 2024 at 02:46:02PM +0300, Aleksander Alekseev wrote:
> >> For now, let me explain the basis for this patch. The fundamental
> >> issue is that these warnings that always appear are, in practice, not
> >> a problem in almost all cases. Some of those who encounter them for
> >> the first time may feel uneasy and reach out with inquiries. On the
> >> other hand, those familiar with these warnings tend to ignore them and
> >> only pay attention to details when actual issues arise. Therefore, the
> >> intention of this patch is to label them as "no issue" unless a
> >> problem is blatantly evident, in order to prevent unnecessary concern.
> >
> > I agree and don't mind affecting the error message per se.
> >
> > However I see that the actual logic of how WAL is processed is being
> > changed. If we do this, at very least it requires thorough thinking. I
> > strongly suspect that the proposed code is wrong and/or not safe
> > and/or less safe than it is now for the reasons named above.
>
> FWIW, that pretty much sums up my feeling regarding this patch,
> because an error, basically any error, would hurt back very badly.
> Sure, the error messages we generate now when reaching the end of WAL
> can sound scary, and they are (I suspect that's not really the case
> for anybody who has history doing support with PostgreSQL because a
> bunch of these messages are old enough to vote, but I can understand
> that anybody would freak out the first time they see that).
>
> However, per the recent issues we've had in this area, like
> cd7f19da3468 but I'm more thinking about 6b18b3fe2c2f and
> bae868caf222, I am of the opinion that the header validation, the
> empty page case in XLogReaderValidatePageHeader() and the record read
> changes are risky enough that I am not convinced that the gains are
> worth the risks taken.
>
> The error stack in the WAL reader is complicated enough that making it
> more complicated as the patch proposes does not sound like not a good
> tradeoff to me to make the reports related to the end of WAL cleaner
> for the end-user. I agree that we should do something, but the patch
> does not seem like a good step towards this goal. Perhaps somebody
> would be more excited about this proposal than I am, of course.
Thank you both for the comments. The criticism seems valid. The
approach to identifying the end-of-WAL state in this patch is quite
heuristic, and its validity or safety can certainly be contested. On
the other hand, if we seek perfection in this area of judgment, we may
need to have the WAL format itself more robust. In any case, since the
majority of the feedback on this patch seems to be negative, I am
going to withdraw it if no supportive opinions emerge during this
commit-fest.
The attached patch addresses the errors reported by CF-bot.
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
^ permalink raw reply [nested|flat] 38+ messages in thread
end of thread, other threads:[~2024-01-23 04:13 UTC | newest]
Thread overview: 38+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2020-02-28 07:01 Make mesage at end-of-recovery less scary. Kyotaro Horiguchi <[email protected]>
2020-02-28 07:33 ` Michael Paquier <[email protected]>
2020-02-28 08:28 ` Kyotaro Horiguchi <[email protected]>
2020-03-05 07:06 ` Kyotaro Horiguchi <[email protected]>
2020-03-23 09:37 ` Peter Eisentraut <[email protected]>
2020-03-23 17:43 ` Ashwin Agrawal <[email protected]>
2020-03-23 19:49 ` Andres Freund <[email protected]>
2020-03-23 19:47 ` Andres Freund <[email protected]>
2020-03-24 01:52 ` Kyotaro Horiguchi <[email protected]>
2020-03-25 12:53 ` Peter Eisentraut <[email protected]>
2020-03-26 16:40 ` Robert Haas <[email protected]>
2020-03-28 02:25 ` James Coleman <[email protected]>
2021-03-03 16:14 ` David Steele <[email protected]>
2021-03-04 06:50 ` Kyotaro Horiguchi <[email protected]>
2021-10-22 17:54 ` Bossart, Nathan <[email protected]>
2021-11-08 05:59 ` Kyotaro Horiguchi <[email protected]>
2021-11-09 00:53 ` Michael Paquier <[email protected]>
2021-11-09 07:27 ` Kyotaro Horiguchi <[email protected]>
2021-12-08 07:01 ` Kyotaro Horiguchi <[email protected]>
2022-03-03 10:09 Re: Make mesage at end-of-recovery less scary. Ashutosh Sharma <[email protected]>
2022-03-04 00:43 ` Kyotaro Horiguchi <[email protected]>
2022-03-22 00:01 ` Andres Freund <[email protected]>
2022-03-22 02:34 ` Kyotaro Horiguchi <[email protected]>
2022-03-29 06:07 ` Kyotaro Horiguchi <[email protected]>
2022-07-06 18:05 ` Jacob Champion <[email protected]>
2022-07-07 00:04 ` Michael Paquier <[email protected]>
2022-07-07 08:32 ` Kyotaro Horiguchi <[email protected]>
2022-09-17 04:21 ` Justin Pryzby <[email protected]>
2022-09-26 07:17 ` Kyotaro Horiguchi <[email protected]>
2022-10-28 02:37 ` Justin Pryzby <[email protected]>
2022-11-18 08:25 ` Kyotaro Horiguchi <[email protected]>
2022-11-22 17:20 ` Andres Freund <[email protected]>
2022-11-22 22:04 ` Justin Pryzby <[email protected]>
2022-11-30 02:56 ` Kyotaro Horiguchi <[email protected]>
2022-09-28 17:06 [PATCH v1 4/6] meson: Implement getopt logic from autoconf Andres Freund <[email protected]>
2024-01-22 05:09 ` Peter Smith <[email protected]>
2024-01-23 04:01 ` Kyotaro Horiguchi <[email protected]>
2024-01-23 04:13 ` Kyotaro Horiguchi <[email protected]>
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox