Horton

Thread

Commits

Same data as JSON: GET /api/v1/messages/:b64id/commits the thread's linked commits as JSON, with link sources. API reference →

  1. Fix header check for continuation records where standbys could be stuck

  2. Move routines to manipulate WAL into PostgreSQL::Test::Cluster

  3. Prevent archive recovery from scanning non-existent WAL files.

  4. Fix scenario where streaming standby gets stuck at a continuation record.

  1. Infinite loop in XLogPageRead() on standby

    Alexander Kukushkin <cyberdemn@gmail.com> — 2024-02-28T10:19:41Z

    Hello hackers,

I spent some time debugging an issue with standby not being able to
continue streaming after failover.

The problem manifests itself by following messages in the log:
LOG:  received SIGHUP, reloading configuration files
LOG:  parameter "primary_conninfo" changed to "port=58669
host=/tmp/dn20WVmNqF"
LOG:  restored log file "000000010000000000000003" from archive
LOG:  invalid magic number 0000 in WAL segment 000000010000000000000003,
LSN 0/301A000, offset 106496
LOG:  fetching timeline history file for timeline 2 from primary server
LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
LOG:  replication terminated by primary server
DETAIL:  End of WAL reached on timeline 1 at 0/3019158.
FATAL:  terminating walreceiver process due to administrator command
LOG:  restored log file "00000002.history" from archive
LOG:  new target timeline is 2
LOG:  restored log file "000000020000000000000003" from archive
LOG:  invalid magic number 0000 in WAL segment 000000020000000000000003,
LSN 0/301A000, offset 106496
LOG:  started streaming WAL from primary at 0/3000000 on timeline 2
LOG:  invalid magic number 0000 in WAL segment 000000020000000000000003,
LSN 0/301A000, offset 106496
FATAL:  terminating walreceiver process due to administrator command
LOG:  waiting for WAL to become available at 0/301A04E
LOG:  restored log file "000000020000000000000003" from archive
LOG:  invalid magic number 0000 in WAL segment 000000020000000000000003,
LSN 0/301A000, offset 106496
LOG:  invalid magic number 0000 in WAL segment 000000020000000000000003,
LSN 0/301A000, offset 106496
LOG:  waiting for WAL to become available at 0/301A04E
LOG:  restored log file "000000020000000000000003" from archive
LOG:  invalid magic number 0000 in WAL segment 000000020000000000000003,
LSN 0/301A000, offset 106496
LOG:  invalid magic number 0000 in WAL segment 000000020000000000000003,
LSN 0/301A000, offset 106496

The problem happens when standbys received only the first part of the WAL
record that spans multiple pages.
In this case the promoted standby discards the first part of the WAL record
and writes END_OF_RECOVERY instead. If in addition to that someone will
call pg_switch_wal(), then there are chances that SWITCH record will also
fit to the page where the discarded part was settling, As a result the
other standby (that wasn't promoted) will infinitely try making attempts to
decode WAL record span on multiple pages by reading the next page, which is
filled with zero bytes. And, this next page will never be written, because
the new primary will be writing to the new WAL file after pg_switch_wal().

Restart of the stuck standby fixes the problem, because it will be first
reading the history file and therefore will never read the incomplete WAL
file from the old timeline. That is, all major versions starting from v13
are impacted (including the master branch), because they allow changing of
primary_conninfo GUC with reload.

Please find attached the TAP test that reproduces the problem.

To be honest, I don't know yet how to fix it nicely. I am thinking about
returning XLREAD_FAIL from XLogPageRead() if it suddenly switched to a new
timeline while trying to read a page and if this page is invalid.

-- 
Regards,
--
Alexander Kukushkin

  2. Re: Infinite loop in XLogPageRead() on standby

    Michael Paquier <michael@paquier.xyz> — 2024-02-29T05:05:15Z

    On Wed, Feb 28, 2024 at 11:19:41AM +0100, Alexander Kukushkin wrote:
> I spent some time debugging an issue with standby not being able to
> continue streaming after failover.
>
> The problem happens when standbys received only the first part of the WAL
> record that spans multiple pages.
> In this case the promoted standby discards the first part of the WAL record
> and writes END_OF_RECOVERY instead. If in addition to that someone will
> call pg_switch_wal(), then there are chances that SWITCH record will also
> fit to the page where the discarded part was settling, As a result the
> other standby (that wasn't promoted) will infinitely try making attempts to
> decode WAL record span on multiple pages by reading the next page, which is
> filled with zero bytes. And, this next page will never be written, because
> the new primary will be writing to the new WAL file after pg_switch_wal().

Wow.  Have you seen that in an actual production environment?

I was just trying your TAP test to see it looping on a single record
as you mentioned:
2024-02-29 12:57:44.884 JST [2555] LOG:  invalid magic number 0000 in
WAL segment 000000020000000000000003, LSN 0/301A000, offset 106496
2024-02-29 12:57:44.884 JST [2555] LOG:  invalid magic number 0000 in
WAL segment 000000020000000000000003, LSN 0/301A000, offset 106496 

> Restart of the stuck standby fixes the problem, because it will be first
> reading the history file and therefore will never read the incomplete WAL
> file from the old timeline. That is, all major versions starting from v13
> are impacted (including the master branch), because they allow changing of
> primary_conninfo GUC with reload.

Still that's not nice at a large scale, because you would not know
about the problem until your monitoring tools raise alarms because
some nodes in your cluster setup decide to lag behind.

> Please find attached the TAP test that reproduces the problem.

my $start_page = start_of_page($end_lsn);
my $wal_file = write_wal($primary, $TLI, $start_page,
                         "\x00" x $WAL_BLOCK_SIZE);
# copy the file we just "hacked" to the archive
copy($wal_file, $primary->archive_dir);

So you are emulating a failure by filling with zeros the second page
where the last emit_message() generated a record, and the page before
that includes the continuation record.  Then abuse of WAL archiving to
force the replay of the last record.  That's kind of cool.

> To be honest, I don't know yet how to fix it nicely. I am thinking about
> returning XLREAD_FAIL from XLogPageRead() if it suddenly switched to a new
> timeline while trying to read a page and if this page is invalid.

Hmm.  I suspect that you may be right on a TLI change when reading a
page.  There are a bunch of side cases with continuation records and
header validation around XLogReaderValidatePageHeader().  Perhaps you
have an idea of patch to show your point?

Nit.  In your test, it seems to me that you should not call directly
set_standby_mode and enable_restoring, just rely on has_restoring with
the standby option included.
--
Michael

  3. Re: Infinite loop in XLogPageRead() on standby

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2024-02-29T07:18:14Z

    At Thu, 29 Feb 2024 14:05:15 +0900, Michael Paquier <michael@paquier.xyz> wrote in 
> On Wed, Feb 28, 2024 at 11:19:41AM +0100, Alexander Kukushkin wrote:
> > I spent some time debugging an issue with standby not being able to
> > continue streaming after failover.
> >
> > The problem happens when standbys received only the first part of the WAL
> > record that spans multiple pages.
> > In this case the promoted standby discards the first part of the WAL record
> > and writes END_OF_RECOVERY instead. If in addition to that someone will
> > call pg_switch_wal(), then there are chances that SWITCH record will also
> > fit to the page where the discarded part was settling, As a result the
> > other standby (that wasn't promoted) will infinitely try making attempts to
> > decode WAL record span on multiple pages by reading the next page, which is
> > filled with zero bytes. And, this next page will never be written, because
> > the new primary will be writing to the new WAL file after pg_switch_wal().

In the first place, it's important to note that we do not guarantee
that an async standby can always switch its replication connection to
the old primary or another sibling standby. This is due to the
variations in replication lag among standbys. pg_rewind is required to
adjust such discrepancies.

I might be overlooking something, but I don't understand how this
occurs without purposefully tweaking WAL files. The repro script
pushes an incomplete WAL file to the archive as a non-partial
segment. This shouldn't happen in the real world.

In the repro script, the replication connection of the second standby
is switched from the old primary to the first standby after its
promotion. After the switching, replication is expected to continue
from the beginning of the last replayed segment. But with the script,
the second standby copies the intentionally broken file, which differs
from the data that should be received via streaming. A similar problem
to the issue here was seen at segment boundaries, before we introduced
the XLP_FIRST_IS_OVERWRITE_CONTRECORD flag, which prevents overwriting
a WAL file that is already archived. However, in this case, the second
standby won't see the broken record because it cannot be in a
non-partial segment in the archive, and the new primary streams
END_OF_RECOVERY instead of the broken record.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  4. Re: Infinite loop in XLogPageRead() on standby

    Alexander Kukushkin <cyberdemn@gmail.com> — 2024-02-29T16:36:29Z

    Hi Michael,

On Thu, 29 Feb 2024 at 06:05, Michael Paquier <michael@paquier.xyz> wrote:

>
> Wow.  Have you seen that in an actual production environment?
>

Yes, we see it regularly, and it is reproducible in test environments as
well.


> my $start_page = start_of_page($end_lsn);
> my $wal_file = write_wal($primary, $TLI, $start_page,
>                          "\x00" x $WAL_BLOCK_SIZE);
> # copy the file we just "hacked" to the archive
> copy($wal_file, $primary->archive_dir);
>
> So you are emulating a failure by filling with zeros the second page
> where the last emit_message() generated a record, and the page before
> that includes the continuation record.  Then abuse of WAL archiving to
> force the replay of the last record.  That's kind of cool.
>

Right, at this point it is easier than to cause an artificial crash on the
primary after it finished writing just one page.


> > To be honest, I don't know yet how to fix it nicely. I am thinking about
> > returning XLREAD_FAIL from XLogPageRead() if it suddenly switched to a
> new
> > timeline while trying to read a page and if this page is invalid.
>
> Hmm.  I suspect that you may be right on a TLI change when reading a
> page.  There are a bunch of side cases with continuation records and
> header validation around XLogReaderValidatePageHeader().  Perhaps you
> have an idea of patch to show your point?
>

Not yet, but hopefully I will get something done next week.


>
> Nit.  In your test, it seems to me that you should not call directly
> set_standby_mode and enable_restoring, just rely on has_restoring with
> the standby option included.
>

Thanks, I'll look into it.

-- 
Regards,
--
Alexander Kukushkin

  5. Re: Infinite loop in XLogPageRead() on standby

    Alexander Kukushkin <cyberdemn@gmail.com> — 2024-02-29T16:44:25Z

    Hi Kyotaro,

On Thu, 29 Feb 2024 at 08:18, Kyotaro Horiguchi <horikyota.ntt@gmail.com>
wrote:

In the first place, it's important to note that we do not guarantee
> that an async standby can always switch its replication connection to
> the old primary or another sibling standby. This is due to the
> variations in replication lag among standbys. pg_rewind is required to
> adjust such discrepancies.
>

Sure, I know. But in this case the async standby received and flushed
absolutely the same amount of WAL as the promoted one.


>
> I might be overlooking something, but I don't understand how this
> occurs without purposefully tweaking WAL files. The repro script
> pushes an incomplete WAL file to the archive as a non-partial
> segment. This shouldn't happen in the real world.
>

It easily happens if the primary crashed and standbys didn't receive
another page with continuation record.

In the repro script, the replication connection of the second standby
> is switched from the old primary to the first standby after its
> promotion. After the switching, replication is expected to continue
> from the beginning of the last replayed segment.


Well, maybe, but apparently the standby is busy trying to decode a record
that spans multiple pages, and it is just infinitely waiting for the next
page to arrive. Also, the restart "fixes" the problem, because indeed it is
reading the file from the beginning.


> But with the script,
> the second standby copies the intentionally broken file, which differs
> from the data that should be received via streaming.


As I already said, this is a simple way to emulate the primary crash while
standbys receiving WAL.
It could easily happen that the record spans on multiple pages is not fully
received and flushed.

-- 
Regards,
--
Alexander Kukushkin

  6. Re: Infinite loop in XLogPageRead() on standby

    Michael Paquier <michael@paquier.xyz> — 2024-02-29T23:17:04Z

    On Thu, Feb 29, 2024 at 05:44:25PM +0100, Alexander Kukushkin wrote:
> On Thu, 29 Feb 2024 at 08:18, Kyotaro Horiguchi <horikyota.ntt@gmail.com>
> wrote:
>> In the first place, it's important to note that we do not guarantee
>> that an async standby can always switch its replication connection to
>> the old primary or another sibling standby. This is due to the
>> variations in replication lag among standbys. pg_rewind is required to
>> adjust such discrepancies.
> 
> Sure, I know. But in this case the async standby received and flushed
> absolutely the same amount of WAL as the promoted one.

Ugh.  If it can happen transparently to the user without the user
knowing directly about it, that does not sound good to me.  I did not
look very closely at monitoring tools available out there, but if both
standbys flushed the same WAL locations a rewind should not be
required.  It is not something that monitoring tools would be able to
detect because they just look at LSNs.

>> In the repro script, the replication connection of the second standby
>> is switched from the old primary to the first standby after its
>> promotion. After the switching, replication is expected to continue
>> from the beginning of the last replayed segment.
> 
> Well, maybe, but apparently the standby is busy trying to decode a record
> that spans multiple pages, and it is just infinitely waiting for the next
> page to arrive. Also, the restart "fixes" the problem, because indeed it is
> reading the file from the beginning.

What happens if the continuation record spawns across multiple segment
files boundaries in this case?  We would go back to the beginning of
the segment where the record spawning across multiple segments began,
right?  (I may recall this part of contrecords incorrectly, feel free
to correct me if necessary.)

>> But with the script,
>> the second standby copies the intentionally broken file, which differs
>> from the data that should be received via streaming.
> 
> As I already said, this is a simple way to emulate the primary crash while
> standbys receiving WAL.
> It could easily happen that the record spans on multiple pages is not fully
> received and flushed.

I think that's OK to do so at test level to force a test in the
backend, FWIW, because that's cheaper, and 039_end_of_wal.pl has
proved that this can be designed to be cheap and stable across the
buildfarm fleet.

For anything like that, the result had better have solid test
coverage, where perhaps we'd better refactor some of the routines of
039_end_of_wal.pl into a module to use them here, rather than
duplicate the code.  The other test has a few assumptions with the
calculation of page boundaries, and I'd rather not duplicate that
across the tree.

Seeing that Alexander is a maintainer of Patroni, which is very
probably used by his employer across a large set of PostgreSQL
instances, if he says that he's seen that in the field, that's good
enough for me to respond to the problem, especially if reconnecting a
standby to a promoted node where both flushed the same LSN.  Now the
level of response also depends on the invasiness of the change, and we
need a very careful evaluation here.
--
Michael

  7. Re: Infinite loop in XLogPageRead() on standby

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2024-03-01T01:29:12Z

    At Fri, 1 Mar 2024 08:17:04 +0900, Michael Paquier <michael@paquier.xyz> wrote in 
> On Thu, Feb 29, 2024 at 05:44:25PM +0100, Alexander Kukushkin wrote:
> > On Thu, 29 Feb 2024 at 08:18, Kyotaro Horiguchi <horikyota.ntt@gmail.com>
> > wrote:
> >> In the first place, it's important to note that we do not guarantee
> >> that an async standby can always switch its replication connection to
> >> the old primary or another sibling standby. This is due to the
> >> variations in replication lag among standbys. pg_rewind is required to
> >> adjust such discrepancies.
> > 
> > Sure, I know. But in this case the async standby received and flushed
> > absolutely the same amount of WAL as the promoted one.
> 
> Ugh.  If it can happen transparently to the user without the user
> knowing directly about it, that does not sound good to me.  I did not
> look very closely at monitoring tools available out there, but if both
> standbys flushed the same WAL locations a rewind should not be
> required.  It is not something that monitoring tools would be able to
> detect because they just look at LSNs.
> 
> >> In the repro script, the replication connection of the second standby
> >> is switched from the old primary to the first standby after its
> >> promotion. After the switching, replication is expected to continue
> >> from the beginning of the last replayed segment.
> > 
> > Well, maybe, but apparently the standby is busy trying to decode a record
> > that spans multiple pages, and it is just infinitely waiting for the next
> > page to arrive. Also, the restart "fixes" the problem, because indeed it is
> > reading the file from the beginning.
> 
> What happens if the continuation record spawns across multiple segment
> files boundaries in this case?  We would go back to the beginning of
> the segment where the record spawning across multiple segments began,
> right?  (I may recall this part of contrecords incorrectly, feel free
> to correct me if necessary.)

After reading this, I came up with a possibility that walreceiver
recovers more quickly than the calling interval to
WaitForWALtoBecomeAvailable(). If walreceiver disconnects after a call
to the function WaitForWAL...(), and then somehow recovers the
connection before the next call, the function doesn't notice the
disconnection and returns XLREAD_SUCCESS wrongly. If this assumption
is correct, the correct fix might be for us to return XLREAD_FAIL when
reconnection happens after the last call to the WaitForWAL...()
function.

> >> But with the script,
> >> the second standby copies the intentionally broken file, which differs
> >> from the data that should be received via streaming.
> > 
> > As I already said, this is a simple way to emulate the primary crash while
> > standbys receiving WAL.
> > It could easily happen that the record spans on multiple pages is not fully
> > received and flushed.
> 
> I think that's OK to do so at test level to force a test in the
> backend, FWIW, because that's cheaper, and 039_end_of_wal.pl has
> proved that this can be designed to be cheap and stable across the
> buildfarm fleet.

Yeah, I agree that it clearly illustrates the final state after the
issue happened, but if my assumption above is correct, the test
doesn't manifest the real issue.

> For anything like that, the result had better have solid test
> coverage, where perhaps we'd better refactor some of the routines of
> 039_end_of_wal.pl into a module to use them here, rather than
> duplicate the code.  The other test has a few assumptions with the
> calculation of page boundaries, and I'd rather not duplicate that
> across the tree.

I agree to the point.

> Seeing that Alexander is a maintainer of Patroni, which is very
> probably used by his employer across a large set of PostgreSQL
> instances, if he says that he's seen that in the field, that's good
> enough for me to respond to the problem, especially if reconnecting a
> standby to a promoted node where both flushed the same LSN.  Now the
> level of response also depends on the invasiness of the change, and we
> need a very careful evaluation here.

I don't mean to say that we should respond with DNF to this "issue" at
all. I simply wanted to make the real issue clear.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  8. Re: Infinite loop in XLogPageRead() on standby

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2024-03-01T03:04:31Z

    At Fri, 01 Mar 2024 10:29:12 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in 
> After reading this, I came up with a possibility that walreceiver
> recovers more quickly than the calling interval to
> WaitForWALtoBecomeAvailable(). If walreceiver disconnects after a call
> to the function WaitForWAL...(), and then somehow recovers the
> connection before the next call, the function doesn't notice the
> disconnection and returns XLREAD_SUCCESS wrongly. If this assumption
> is correct, the correct fix might be for us to return XLREAD_FAIL when
> reconnection happens after the last call to the WaitForWAL...()
> function.

That's my stupid. The function performs reconnection by itself.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  9. Re: Infinite loop in XLogPageRead() on standby

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2024-03-01T03:37:55Z

    At Fri, 01 Mar 2024 12:04:31 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in 
> At Fri, 01 Mar 2024 10:29:12 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in 
> > After reading this, I came up with a possibility that walreceiver
> > recovers more quickly than the calling interval to
> > WaitForWALtoBecomeAvailable(). If walreceiver disconnects after a call
> > to the function WaitForWAL...(), and then somehow recovers the
> > connection before the next call, the function doesn't notice the
> > disconnection and returns XLREAD_SUCCESS wrongly. If this assumption
> > is correct, the correct fix might be for us to return XLREAD_FAIL when
> > reconnection happens after the last call to the WaitForWAL...()
> > function.
> 
> That's my stupid. The function performs reconnection by itself.

Anyway, our current policy here is to avoid record-rereads beyond
source switches. However, fixing this seems to require that source
switches cause record rereads unless some additional information is
available to know if replay LSN needs to back up.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  10. Re: Infinite loop in XLogPageRead() on standby

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2024-03-01T04:16:37Z

    At Fri, 01 Mar 2024 12:37:55 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in 
> Anyway, our current policy here is to avoid record-rereads beyond
> source switches. However, fixing this seems to require that source
> switches cause record rereads unless some additional information is
> available to know if replay LSN needs to back up.

It seems to me that the error messages are related to commit 0668719801.

XLogPageRead:
> * Check the page header immediately, so that we can retry immediately if
> * it's not valid. This may seem unnecessary, because ReadPageInternal()
> * validates the page header anyway, and would propagate the failure up to
> * ReadRecord(), which would retry. However, there's a corner case with
> * continuation records, if a record is split across two pages such that
> * we would need to read the two pages from different sources. For
...
>	if (StandbyMode &&
>		!XLogReaderValidatePageHeader(xlogreader, targetPagePtr, readBuf))
>	{
>		/*
>		 * Emit this error right now then retry this page immediately. Use
>		 * errmsg_internal() because the message was already translated.
>		 */
>		if (xlogreader->errormsg_buf[0])
>			ereport(emode_for_corrupt_record(emode, xlogreader->EndRecPtr),
>					(errmsg_internal("%s", xlogreader->errormsg_buf)));

This code intends to prevent a page header error from causing a record
reread, when a record is required to be read from multiple sources. We
could restrict this to only fire at segment boundaries. At segment
boundaries, we won't let LSN back up by using XLP_FIRST_IS_CONTRECORD.

Having thought up to this point, I now believe that we should
completely prevent LSN from going back in any case. One drawback is
that the fix cannot be back-patched.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  11. Re: Infinite loop in XLogPageRead() on standby

    Alexander Kukushkin <cyberdemn@gmail.com> — 2024-03-05T08:36:44Z

    Hello Michael, Kyotaro,

Please find attached the patch fixing the problem and the updated TAP test
that addresses Nit.

-- 
Regards,
--
Alexander Kukushkin

  12. Re: Infinite loop in XLogPageRead() on standby

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2024-03-06T08:57:44Z

    At Tue, 5 Mar 2024 09:36:44 +0100, Alexander Kukushkin <cyberdemn@gmail.com> wrote in 
> Please find attached the patch fixing the problem and the updated TAP test
> that addresses Nit.

Record-level retries happen when the upper layer detects errors. In my
previous mail, I cited code that is intended to prevent this at
segment boundaries. However, the resulting code applies to all page
boundaries, since we judged that the difference doen't significanty
affects the outcome.

> * Check the page header immediately, so that we can retry immediately if
> * it's not valid. This may seem unnecessary, because ReadPageInternal()
> * validates the page header anyway, and would propagate the failure up to

So, the following (tentative) change should also work.

xlogrecovery.c:
@@ -3460,8 +3490,10 @@ retry:
 	 * responsible for the validation.
 	 */
 	if (StandbyMode &&
+		targetPagePtr % 0x100000 == 0 &&
 		!XLogReaderValidatePageHeader(xlogreader, targetPagePtr, readBuf))
 	{

Thus, I managed to reproduce precisely the same situation as you
described utilizing your script with modifications and some core
tweaks, and with the change above, I saw that the behavior was
fixed. However, for reasons unclear to me, it shows another issue, and
I am running out of time and need more caffeine. I'll continue
investigating this tomorrow.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  13. Re: Infinite loop in XLogPageRead() on standby

    Alexander Kukushkin <cyberdemn@gmail.com> — 2024-03-06T10:34:29Z

    Hi Kyotaro,

Oh, now I understand what you mean. Is the retry supposed to happen only
when we are reading the very first page from the WAL file?

On Wed, 6 Mar 2024 at 09:57, Kyotaro Horiguchi <horikyota.ntt@gmail.com>
wrote:

>
> xlogrecovery.c:
> @@ -3460,8 +3490,10 @@ retry:
>          * responsible for the validation.
>          */
>         if (StandbyMode &&
> +               targetPagePtr % 0x100000 == 0 &&
>                 !XLogReaderValidatePageHeader(xlogreader, targetPagePtr,
> readBuf))
>         {
>
>
Hmm, I think you meant to use wal_segment_size, because 0x100000 is just
1MB. As a result, currently it works for you by accident.


> Thus, I managed to reproduce precisely the same situation as you
> described utilizing your script with modifications and some core
> tweaks, and with the change above, I saw that the behavior was
> fixed. However, for reasons unclear to me, it shows another issue, and
> I am running out of time and need more caffeine. I'll continue
> investigating this tomorrow.
>

Thank you for spending your time on it!

-- 
Regards,
--
Alexander Kukushkin

  14. Re: Infinite loop in XLogPageRead() on standby

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2024-03-11T07:43:32Z

    At Wed, 6 Mar 2024 11:34:29 +0100, Alexander Kukushkin <cyberdemn@gmail.com> wrote in 
> Hmm, I think you meant to use wal_segment_size, because 0x100000 is just
> 1MB. As a result, currently it works for you by accident.

Oh, I once saw the fix work, but seems not to be working after some
point. The new issue was a corruption of received WAL records on the
first standby, and it may be related to the setting.

> > Thus, I managed to reproduce precisely the same situation as you
> > described utilizing your script with modifications and some core
> > tweaks, and with the change above, I saw that the behavior was
> > fixed. However, for reasons unclear to me, it shows another issue, and
> > I am running out of time and need more caffeine. I'll continue
> > investigating this tomorrow.
> >
> 
> Thank you for spending your time on it!

You're welcome, but I aplogize for the delay in the work..

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  15. Re: Infinite loop in XLogPageRead() on standby

    Michael Paquier <michael@paquier.xyz> — 2024-03-11T23:20:24Z

    On Mon, Mar 11, 2024 at 04:43:32PM +0900, Kyotaro Horiguchi wrote:
> At Wed, 6 Mar 2024 11:34:29 +0100, Alexander Kukushkin <cyberdemn@gmail.com> wrote in 
>> Thank you for spending your time on it!
> 
> You're welcome, but I aplogize for the delay in the work..

Thanks for spending time on this.  Everybody is busy with the last
commit fest, and the next minor release set is planned for May so
there should still be time even after the feature freeze:
https://www.postgresql.org/developer/roadmap/

I should be able to come back to this thread around the beginning of
April.  If you are able to do some progress in-between, that would be
surely helpful.

Thanks,
--
Michael

  16. Re: Infinite loop in XLogPageRead() on standby

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2024-03-13T02:56:21Z

    At Mon, 11 Mar 2024 16:43:32 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in 
> Oh, I once saw the fix work, but seems not to be working after some
> point. The new issue was a corruption of received WAL records on the
> first standby, and it may be related to the setting.

I identified the cause of the second issue. When I tried to replay the
issue, the second standby accidentally received the old timeline's
last page-spanning record till the end while the first standby was
promoting (but it had not been read by recovery). In addition to that,
on the second standby, there's a time window where the timeline
increased but the first segment of the new timeline is not available
yet. In this case, the second standby successfully reads the
page-spanning record in the old timeline even after the second standby
noticed that the timeline ID has been increased, thanks to the
robustness of XLogFileReadAnyTLI().

I think the primary change to XLogPageRead that I suggested is correct
(assuming the use of wal_segment_size instead of the
constant). However, still XLogFileReadAnyTLI() has a chance to read
the segment from the old timeline after the second standby notices a
timeline switch, leading to the second issue. The second issue was
fixed by preventing XLogFileReadAnyTLI from reading segments from
older timelines than those suggested by the latest timeline
history. (In other words, disabling the "AnyTLI" part).

I recall that there was a discussion for commit 4bd0ad9e44, about the
objective of allowing reading segments from older timelines than the
timeline history suggests. In my faint memory, we concluded to
postpone making the decision to remove the feature due to uncertainity
about the objective. If there's no clear reason to continue using
XLogFileReadAnyTLI(), I suggest we stop its use and instead adopt
XLogFileReadOnTLHistory(), which reads segments that align precisely
with the timeline history.

Of course, regardless of the changes above, if recovery on the second
standby had reached the end of the page-spanning record before
redirection to the first standby, it would need pg_rewind to connect
to the first standby.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  17. Re: Infinite loop in XLogPageRead() on standby

    Alexander Kukushkin <cyberdemn@gmail.com> — 2024-03-15T07:20:15Z

    Hi Kyotaro,

On Wed, 13 Mar 2024 at 03:56, Kyotaro Horiguchi <horikyota.ntt@gmail.com>
wrote:

I identified the cause of the second issue. When I tried to replay the
> issue, the second standby accidentally received the old timeline's
> last page-spanning record till the end while the first standby was
> promoting (but it had not been read by recovery). In addition to that,
> on the second standby, there's a time window where the timeline
> increased but the first segment of the new timeline is not available
> yet. In this case, the second standby successfully reads the
> page-spanning record in the old timeline even after the second standby
> noticed that the timeline ID has been increased, thanks to the
> robustness of XLogFileReadAnyTLI().
>

Hmm, I don't think it could really be prevented.
There are always chances that the standby that is not ahead of other
standbys could be promoted due to reasons like:
1. HA configuration doesn't let certain nodes to be promoted.
2. This is an async standby (name isn't listed in
synchronous_standby_names) and it was ahead of promoted sync standby. No
data loss from the client point of view.


> Of course, regardless of the changes above, if recovery on the second
> standby had reached the end of the page-spanning record before
> redirection to the first standby, it would need pg_rewind to connect
> to the first standby.
>

Correct, IMO pg_rewind is a right way of solving it.

Regards,
--
Alexander Kukushkin

  18. Re: Infinite loop in XLogPageRead() on standby

    Ants Aasma <ants.aasma@cybertec.at> — 2024-03-15T10:43:41Z

    On Wed, 13 Mar 2024 at 04:56, Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote:
>
> At Mon, 11 Mar 2024 16:43:32 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in
> > Oh, I once saw the fix work, but seems not to be working after some
> > point. The new issue was a corruption of received WAL records on the
> > first standby, and it may be related to the setting.
>
> I identified the cause of the second issue. When I tried to replay the
> issue, the second standby accidentally received the old timeline's
> last page-spanning record till the end while the first standby was
> promoting (but it had not been read by recovery). In addition to that,
> on the second standby, there's a time window where the timeline
> increased but the first segment of the new timeline is not available
> yet. In this case, the second standby successfully reads the
> page-spanning record in the old timeline even after the second standby
> noticed that the timeline ID has been increased, thanks to the
> robustness of XLogFileReadAnyTLI().
>
> I think the primary change to XLogPageRead that I suggested is correct
> (assuming the use of wal_segment_size instead of the
> constant). However, still XLogFileReadAnyTLI() has a chance to read
> the segment from the old timeline after the second standby notices a
> timeline switch, leading to the second issue. The second issue was
> fixed by preventing XLogFileReadAnyTLI from reading segments from
> older timelines than those suggested by the latest timeline
> history. (In other words, disabling the "AnyTLI" part).
>
> I recall that there was a discussion for commit 4bd0ad9e44, about the
> objective of allowing reading segments from older timelines than the
> timeline history suggests. In my faint memory, we concluded to
> postpone making the decision to remove the feature due to uncertainity
> about the objective. If there's no clear reason to continue using
> XLogFileReadAnyTLI(), I suggest we stop its use and instead adopt
> XLogFileReadOnTLHistory(), which reads segments that align precisely
> with the timeline history.


This sounds very similar to the problem described in [1]. And I think
both will be resolved by that change.

[1] https://postgr.es/m/CANwKhkMN3QwAcvuDZHb6wsvLRtkweBiYso-KLFykkQVWuQLcOw%40mail.gmail.com

  19. Re: Infinite loop in XLogPageRead() on standby

    Alexander Kukushkin <cyberdemn@gmail.com> — 2024-06-04T14:16:43Z

    Hi Michael and Kyotaro,

Now that beta1 was released I hope you are not so busy and hence would like
to follow up on this problem.

Regards,
--
Alexander Kukushkin

  20. Re: Infinite loop in XLogPageRead() on standby

    Michael Paquier <michael@paquier.xyz> — 2024-06-05T05:09:01Z

    On Tue, Jun 04, 2024 at 04:16:43PM +0200, Alexander Kukushkin wrote:
> Now that beta1 was released I hope you are not so busy and hence would like
> to follow up on this problem.

I am still working on something for the v18 cycle that I'd like to
present before the beginning of the next commit fest, so I am a bit
busy to get that out first.  Fingers crossed to not have open items to
look at..  This thread is one of the things I have marked as an item
to look at, yes.
--
Michael

  21. Re: Infinite loop in XLogPageRead() on standby

    Alexander Kukushkin <cyberdemn@gmail.com> — 2024-11-13T13:18:06Z

    Hi Michael,

Now that v17 is released and before v18 feature freeze we have a few
months, I hope you will find some time to look at it.

On Wed, 5 Jun 2024 at 07:09, Michael Paquier <michael@paquier.xyz> wrote:

> On Tue, Jun 04, 2024 at 04:16:43PM +0200, Alexander Kukushkin wrote:
> > Now that beta1 was released I hope you are not so busy and hence would
> like
> > to follow up on this problem.
>
> I am still working on something for the v18 cycle that I'd like to
> present before the beginning of the next commit fest, so I am a bit
> busy to get that out first.  Fingers crossed to not have open items to
> look at..  This thread is one of the things I have marked as an item
> to look at, yes.
> --
> Michael
>


Regards,
--
Alexander Kukushkin

  22. Re: Infinite loop in XLogPageRead() on standby

    Michael Paquier <michael@paquier.xyz> — 2024-12-25T03:00:59Z

    On Wed, Nov 13, 2024 at 02:18:06PM +0100, Alexander Kukushkin wrote:
> Now that v17 is released and before v18 feature freeze we have a few
> months, I hope you will find some time to look at it.

My apologies for taking a couple of weeks before coming back to this
thread.  I have been informed a couple of days ago about a report
which is showing the same symptoms as what you have reported.  Please
note that we have two other threads which refer to the same problem as
what you have here:
https://www.postgresql.org/message-id/15567-a9ff747c5e7c031c%40postgresql.org
https://www.postgresql.org/message-id/CAJ%2BDhQaf9ZMkqPPnapu06mvMFe-b_K4NGF%2B-MV%2Be%3DJB2edF4cQ%40mail.gmail.com

All of them refer to an infinite loop reachable in the startup process
when we read an incorrect incomplete record just after a failover or
when a WAL receiver restarts.  Not sure which way is best in order to
fix all of them in one shot, I am still considering what the possible
options at hand are here.
--
Michael

  23. Re: Infinite loop in XLogPageRead() on standby

    Michael Paquier <michael@paquier.xyz> — 2025-01-10T05:54:16Z

    On Fri, Mar 01, 2024 at 01:16:37PM +0900, Kyotaro Horiguchi wrote:
> This code intends to prevent a page header error from causing a record
> reread, when a record is required to be read from multiple sources. We
> could restrict this to only fire at segment boundaries. At segment
> boundaries, we won't let LSN back up by using XLP_FIRST_IS_CONTRECORD.
> 
> Having thought up to this point, I now believe that we should
> completely prevent LSN from going back in any case. One drawback is
> that the fix cannot be back-patched.

I don't immediately see why we should not be able to backpatch a fix
that restricts the early page header check to happen only at segment
boundary when we are in standby mode.  Perhaps I'm just missing your
point.

If we cannot use that, wouldn't it be better just to stick with the
proposed check on the TLI and force an error in the page read callback
if the situation has changed due to a TLI jump with curFileTLI so as
we don't loop and check infinitely these incorrect pages?
--
Michael

  24. Re: Infinite loop in XLogPageRead() on standby

    Michael Paquier <michael@paquier.xyz> — 2025-01-15T04:45:05Z

    On Wed, Dec 25, 2024 at 12:00:59PM +0900, Michael Paquier wrote:
> All of them refer to an infinite loop reachable in the startup process
> when we read an incorrect incomplete record just after a failover or
> when a WAL receiver restarts.  Not sure which way is best in order to
> fix all of them in one shot, I am still considering what the possible
> options at hand are here.

And please find attached a set of two patches addressing the issue.
I've reviewed again the thread and after pondering quite a bit about
it I am on board with the point of making the early header check in
the page read callback less generic by restricting it to a WAL segment
boundary, as that's the original case we care about, to map also with 
the fact that WAL receivers are spawned with a LSN starting at the
beginning of segment, as suggested by Horiguchi-san.  As far as I can
see, I've misunderstood a bit things last week about the backpatch
point, sorry about that.

The new regression test is something I really want to keep around,
to be able to emulate the infinite loop, but I got annoyed with the
amount of duplication between the new test and the existing
039_end_of_wal.pl as there share the same ideas.  I have refactored
039_end_of_wal.pl and moved its routines to generate WAL messages,
to advance WAL and to write WAL into Cluster.pm, then reused the
refactored result in the new test.  I've also detected a race
condition in the new test, where we should wait for the logs of the
two standbys to report their "invalid magic number" failures.  The
test could fail if the replay is slow when scanning their logs.  There
is wait_for_log() for this job, available down to v13.

Barring objections, I'd like to get the main issue in 0002 fixed at
the beginning of next week.  I am also planning to do the refactoring
bits tomorrow or so as these are rather straight-forward.  The names
of the new routines in Cluster.pm are inherited from the existing
recovery test.  Perhaps they could use a better name, but 0001 does
not look that bad to me either.
--
Michael

  25. Re: Infinite loop in XLogPageRead() on standby

    Alexander Kukushkin <cyberdemn@gmail.com> — 2025-01-15T09:35:42Z

    Hi Michael,

On Wed, 15 Jan 2025 at 05:45, Michael Paquier <michael@paquier.xyz> wrote:.

> The new regression test is something I really want to keep around,
> to be able to emulate the infinite loop, but I got annoyed with the
> amount of duplication between the new test and the existing
> 039_end_of_wal.pl as there share the same ideas.  I have refactored
> 039_end_of_wal.pl and moved its routines to generate WAL messages,
> to advance WAL and to write WAL into Cluster.pm, then reused the
> refactored result in the new test.
>


> Barring objections, I'd like to get the main issue in 0002 fixed at
> the beginning of next week.  I am also planning to do the refactoring
> bits tomorrow or so as these are rather straight-forward.  The names
> of the new routines in Cluster.pm are inherited from the existing
> recovery test.  Perhaps they could use a better name, but 0001 does
> not look that bad to me either.
>

 Thank you for picking it up. I briefly looked at both patches. The actual
fix in XLogPageRead() looks good to me.
I also agree with suggested refactoring, where there is certainly some room
for improvement - $WAL_SEGMENT_SIZE, $WAL_BLOCK_SIZE variables and
get_int_setting(), start_of_page() funcs are still duplicated in both test
files.
Maybe we can have something like the following in Cluster.pm? It'll allow
further simplify tests and reduce code duplication.

sub get_timeline_id
{
    my self = shift;
    return $self->safe_psql('postgres',
           "SELECT timeline_id FROM pg_control_checkpoint()");
}

sub get_int_setting
{
       my ($self, $name) = @_;
       return int(
               $self->safe_psql(
                       'postgres',
                       "SELECT setting FROM pg_settings WHERE name =
'$name'"));
}

sub WAL_SEGMENT_SIZE
{
    my $self = shift;
    self->{_WAL_SEGMENT_SIZE} = self->get_int_setting('wal_segment_size')
      unless defined self->{_WAL_SEGMENT_SIZE};
    return self->{_WAL_SEGMENT_SIZE};
}

sub WAL_BLOCK_SIZE
{
    my $self = shift;
    self->{_WAL_BLOCK_SIZE} = self->get_int_setting('wal_block_size')
      unless defined self->{_WAL_BLOCK_SIZE};
    return self->{_WAL_BLOCK_SIZE};
}

sub start_of_page
{
    my ($self, $lsn) = @_;
    return $lsn & ~($self->WAL_BLOCK_SIZE - 1);
}

Regards,
--
Alexander Kukushkin

  26. Re: Infinite loop in XLogPageRead() on standby

    Michael Paquier <michael@paquier.xyz> — 2025-01-16T00:42:49Z

    On Wed, Jan 15, 2025 at 10:35:42AM +0100, Alexander Kukushkin wrote:
>  Thank you for picking it up. I briefly looked at both patches. The actual
> fix in XLogPageRead() looks good to me.
> I also agree with suggested refactoring, where there is certainly some room
> for improvement - $WAL_SEGMENT_SIZE, $WAL_BLOCK_SIZE variables and
> get_int_setting(), start_of_page() funcs are still duplicated in both test
> files.
> Maybe we can have something like the following in Cluster.pm? It'll allow
> further simplify tests and reduce code duplication.

Yeah, I was looking at that, but disliked a bit this option compared
to the routines doing WAL manipulations which are more complex with
their own ways of getting close to page limits, because I feel that we
should be smarter with the interfaces of these routines with more
options.  For example, we have other things scanning control file
data like system_identifier in 040_pg_createsubscriber.p, so we could
have a SQL that wraps around the pg_control_* functions with a custom
field, like we do for "sub lsn" in Cluster.pm.  Same comment for the
pg_settings queries, which are not limited to only what we do here.
The wrapper around integers is useful, of course, but we could make a
refactored routine apply a cast after checking its unit internally,
or something like that.

The routines for the start page position would not be fit within
Cluster.pm as it does not depend on a $node.  Perhaps Utils.pm?  Here
again, living with this small duplication felt OK in the scope of this
bug fix.  I'm of course open to tuning all that, though my primary
goal is to wrap the fix :D

I've applied the first refactoring bits down to v13 (see for example a
s/emit_message/emit_wal/ tweaked for consistency, with more comment
tweaks).  Attached are patches for each branch for the bug fix, that
I'm still testing and looking at more.  The readability of
043_no_contrecord_switch.pl looks rather OK here.
--
Michael

  27. Re: Infinite loop in XLogPageRead() on standby

    Michael Paquier <michael@paquier.xyz> — 2025-01-20T01:24:35Z

    On Thu, Jan 16, 2025 at 09:42:49AM +0900, Michael Paquier wrote:
> I've applied the first refactoring bits down to v13 (see for example a
> s/emit_message/emit_wal/ tweaked for consistency, with more comment
> tweaks).  Attached are patches for each branch for the bug fix, that
> I'm still testing and looking at more.  The readability of
> 043_no_contrecord_switch.pl looks rather OK here.

And done this as well.  The buildfarm looks OK with it for the moment.
I'll keep an eye on things, including the CF bot.
--
Michael