Be strict when request to flush past end of WAL in WaitXLogInsertionsToFinish

On Fri, 2024-03-15 at 13:12 +0530, Bharath Rupireddy wrote:

Hi,

While working on [1], it was identified that
WaitXLogInsertionsToFinish emits a LOG message, and adjusts the upto
ptr to proceed further when caller requests to flush past the end of
generated WAL. There's a comment explaining no caller should ever do
that intentionally except in cases with bogus LSNs. For a similar
situation, XLogWrite emits a PANIC "xlog write request %X/%X is past
end of log %X/%X". Although there's no problem if
WaitXLogInsertionsToFinish emits LOG, but why can't it be a bit more
harsh and emit PANIC something like the attached to detect the corner
case?

Thoughts?

I'm not clear on why the callers of WaitXLogInsertionsToFinish() are
handling errors the way they are. XLogWrite PANICs, XLogFlush ERRORs
(which is likely to be escalated to a PANIC anyway), and the other
callers ignore the return value and leave it up to XLogWrite() to
PANIC.

As far as I can tell, once WaitXLogInsertionsToFinish() detects this
bogus LSN, a PANIC is a likely outcome, so your proposed change makes
sense. But then why are the callers also checking?

I haven't looked in a lot of detail.

Regards,
Jeff Davis

On Tue, Mar 19, 2024 at 04:58:57AM +0000, Jeff Davis wrote:

I'm not clear on why the callers of WaitXLogInsertionsToFinish() are
handling errors the way they are. XLogWrite PANICs, XLogFlush ERRORs
(which is likely to be escalated to a PANIC anyway), and the other
callers ignore the return value and leave it up to XLogWrite() to
PANIC.

I hit a production incident on PostgreSQL 15.13 with physical
streaming replication: the primary logged "request to flush past end
of generated WAL" for a position just past a segment boundary, and the
standby then got stuck retrying "record with incorrect prev-link" at
that same position. That led me to the ignored return value in
XLogBackgroundFlush(). In a non-assert build, XLogWrite() does not
necessarily PANIC for this caller.

I reproduced the following sequence on PostgreSQL 15.13 with 1MB WAL
segments:

1. Inject an asyncXactLSN at a segment boundary plus the 40-byte long
page header.
2. WaitXLogInsertionsToFinish() logs "request to flush past end of
generated WAL" and clamps the request to the reserved position.
3. XLogBackgroundFlush() discards that return value. XLogWrite() writes
the initialized WAL buffer page and advertises the original partial
position, so a physical walsender sends only the new page header.
4. If that header overwrites a recycled segment on the standby, the
remaining bytes are stale. Recovery can interpret them as a record
and report an incorrect prev-link. I reproduced the subsequent
five-second retry loop as well.

On current master with assertions enabled, the same injected request
instead fails the Insert >= Write assertion inside XLogWrite(). That
assertion was added in v17 (f3ff7bf83bc) and does not exist in 15, so
the 15.13 build silently proceeds as described above.

The original source of the bogus asyncXactLSN in the production case is
still unknown. The attached patch does not try to explain or hide that
source. It only prevents XLogBackgroundFlush() from discarding a clamp
that has already been made.

The patch uses the return value only when it is smaller than the request.
Assigning it unconditionally would be wrong because, on the normal path,
WaitXLogInsertionsToFinish() can return a position beyond the requested
one. The flush target is clamped together with the write target. The
patch also updates the header comment of WaitXLogInsertionsToFinish(),
which claimed that the return value is always >= 'upto', contradicting
the clamp documented in the function body.

I verified the patch on current master (92819e57945) with the same
injection reproducer, in both assert and non-assert builds. With the
patch, the assert build no longer fails the Insert >= Write assertion,
and the non-assert build's flush position no longer advances past the
end of reserved WAL for this request. Both servers keep running. One
behavior change worth noting: since the bogus asyncXactLSN itself is
not corrected, the existing "request to flush past end of generated
WAL" message now repeats on every walwriter cycle until real WAL
passes that position, whereas before the patch the first cycle
advanced the flush position past the end of reserved WAL and
subsequent cycles were silent. That seems preferable to me: the
repeated message keeps pointing at a corruption that is still there.

The patch applies as-is down to REL_17_STABLE. REL_15_STABLE and
REL_16_STABLE would need adjustments for the older LogwrtResult code
if backpatching is wanted.

Regards,
Paul

Hi,

On Wed, Sep 2, 2026 at 5:52 PM Paul Kim <mok03127@gmail.com> wrote:

On Tue, Mar 19, 2024 at 04:58:57AM +0000, Jeff Davis wrote:

I'm not clear on why the callers of WaitXLogInsertionsToFinish() are
handling errors the way they are. XLogWrite PANICs, XLogFlush ERRORs
(which is likely to be escalated to a PANIC anyway), and the other
callers ignore the return value and leave it up to XLogWrite() to
PANIC.

I hit a production incident on PostgreSQL 15.13 with physical
streaming replication: the primary logged "request to flush past end
of generated WAL" for a position just past a segment boundary, and the
standby then got stuck retrying "record with incorrect prev-link" at
that same position. That led me to the ignored return value in
XLogBackgroundFlush(). In a non-assert build, XLogWrite() does not
necessarily PANIC for this caller.

I reproduced the following sequence on PostgreSQL 15.13 with 1MB WAL
segments:

1. Inject an asyncXactLSN at a segment boundary plus the 40-byte long
page header.
2. WaitXLogInsertionsToFinish() logs "request to flush past end of
generated WAL" and clamps the request to the reserved position.
3. XLogBackgroundFlush() discards that return value. XLogWrite() writes
the initialized WAL buffer page and advertises the original partial
position, so a physical walsender sends only the new page header.
4. If that header overwrites a recycled segment on the standby, the
remaining bytes are stale. Recovery can interpret them as a record
and report an incorrect prev-link. I reproduced the subsequent
five-second retry loop as well.

Nice! Do you mind adding the reproducer as a TAP test for HEAD?

Also, I suggest adding an entry for this bug in the current CF:
https://commitfest.postgresql.org/. I will try to find some time to
review this.

--
Bharath Rupireddy
Amazon Web Services: https://aws.amazon.com

On Wed, Sep 02, 2026 at 06:13:26PM -0700, Bharath Rupireddy wrote:

Nice! Do you mind adding the reproducer as a TAP test for HEAD?

I'm assuming that it should be possible to use an injection points
based on the fact that we would be up and running for the inserts.
Even if the test is not included into the tree at the end, it's still
good to post cases to be able to double-check a fix, and even in the
case where we would need to look back at this problem due to a
completely reason.
--
Michael

On Wed, Sep 03, 2026 at 11:04:39AM +0900, Michael Paquier wrote:

On Wed, Sep 02, 2026 at 06:13:26PM -0700, Bharath Rupireddy wrote:

Nice! Do you mind adding the reproducer as a TAP test for HEAD?

I'm assuming that it should be possible to use an injection points
based on the fact that we would be up and running for the inserts.

Thanks, both. Attached is v2: 0001 is the fix, unchanged from v1, and
0002 adds the reproducer as a TAP test on HEAD.

The test adds a small module, src/test/modules/test_walwriter, with one
C function that requests a segment switch and then stores the resulting
insert position in asyncXactLSN. After a switch that position is just
past the new segment's long page header, beyond the end of generated
WAL, so the walwriter's next cycle requests a flush past the end of
generated WAL -- the same shape as the production request.

I did look at injection points first, but there is no INJECTION_POINT()
in this path, and what the reproducer needs is a bogus value stored
into asyncXactLSN rather than a backend stopped at a particular point,
which would require a custom callback and hence a test module anyway.
A plain test module also keeps the test runnable in builds without
injection point support. The timing side needs no help: with the
test's wal_writer_flush_after = 0, XLogSetAsyncXactLSN() wakes the
walwriter, which picks the value up on its next cycle, so the test
just waits for the existing "request to flush past end of generated
WAL" message to show up in the log.

After that message, the test checks that the advertised flush position
is still below the bogus request, that no child process was terminated,
and that normal WAL activity afterwards gets past that position.

On unpatched HEAD the test fails in both assert and production builds:
XLogWrite() hits its "xlog write request ... is past end of log" PANIC
and the walwriter's crash takes the server down (TAP clusters run with
restart_after_crash = off). (Which sanity check fires first depends
on the WAL buffer state; with 1MB segments I had seen the
Insert >= Write assertion instead.) With 0001 applied, both build
types pass the test.

Regards,
Paul

Hi,

On Thu, Sep 3, 2026 at 5:05 PM Paul Kim <mok03127@gmail.com> wrote:

Thanks, both. Attached is v2: 0001 is the fix, unchanged from v1, and
0002 adds the reproducer as a TAP test on HEAD.

The test adds a small module, src/test/modules/test_walwriter, with one
C function that requests a segment switch and then stores the resulting
insert position in asyncXactLSN. After a switch that position is just
past the new segment's long page header, beyond the end of generated
WAL, so the walwriter's next cycle requests a flush past the end of
generated WAL -- the same shape as the production request.

I did look at injection points first, but there is no INJECTION_POINT()
in this path, and what the reproducer needs is a bogus value stored
into asyncXactLSN rather than a backend stopped at a particular point,
which would require a custom callback and hence a test module anyway.

Thanks for the v2 patches. Just curious, how did the bogus LSN end up
in asyncXactLSN in production when you hit the issue?

--
Bharath Rupireddy
Amazon Web Services: https://aws.amazon.com

Just curious, how did the bogus LSN end up in asyncXactLSN in
production when you hit the issue?

Honestly, we still don't know, but the value itself is telling.

The production request was exactly segment boundary + 0x28, i.e.
SizeOfXLogLongPHD past a segment start. That is precisely what the
current insert position looks like right after a segment switch,
before any record has been written into the new segment. So it does
not look like random corruption; it looks like something captured the
insert position at that moment and handed it to XLogSetAsyncXactLSN().
That is also how the TAP test's injector reproduces the incident
byte-for-byte.

I went looking for an in-core path that could do this naturally on the
affected version and came up empty: fault-free segment switches
(~100 runs), async commits, LogStandbySnapshot() calls, and top-level
aborts never produced the "past end of generated WAL" warning in my
testing. The affected installation does load third-party preload
libraries; auditing those for WAL-related symbol use is on my list but
has not been done yet, so I cannot rule the source in or out.

Either way, I think the fix stands on its own: whatever plants the
value, WaitXLogInsertionsToFinish() already detects and clamps it, and
XLogBackgroundFlush() discarding that clamp is what turns one bad
request into the standby's prev-link retry loop.

Regards,
Paul Kim

Hi,

On Thu, Sep 3, 2026 at 6:29 PM Paul Kim <mok03127@gmail.com> wrote:

Just curious, how did the bogus LSN end up in asyncXactLSN in
production when you hit the issue?

Honestly, we still don't know, but the value itself is telling.

The production request was exactly segment boundary + 0x28, i.e.
SizeOfXLogLongPHD past a segment start. That is precisely what the
current insert position looks like right after a segment switch,
before any record has been written into the new segment. So it does
not look like random corruption; it looks like something captured the
insert position at that moment and handed it to XLogSetAsyncXactLSN().
That is also how the TAP test's injector reproduces the incident
byte-for-byte.

I went looking for an in-core path that could do this naturally on the
affected version and came up empty: fault-free segment switches
(~100 runs), async commits, LogStandbySnapshot() calls, and top-level
aborts never produced the "past end of generated WAL" warning in my
testing. The affected installation does load third-party preload
libraries; auditing those for WAL-related symbol use is on my list but
has not been done yet, so I cannot rule the source in or out.

Either way, I think the fix stands on its own: whatever plants the
value, WaitXLogInsertionsToFinish() already detects and clamps it, and
XLogBackgroundFlush() discarding that clamp is what turns one bad
request into the standby's prev-link retry loop.

Thanks for the patches. I don't see a CF entry yet, so I created one:
https://commitfest.postgresql.org/patch/7294/. Feel free to add
yourself as an author.

I went through this thread today. Here's my take.

What exactly caused the wait-for-any-in-progress-insertions-to-finish
to receive an LSN past the end of the generated WAL is one problem.
And, when that happens for whatever reason, the walwriter not honoring
the adjusted position in the caller and blindly writing such WAL to
WAL files is another problem.

In this case, although we don't yet know the root cause for the first
problem, which could be not necessarily the async commit/abort LSN
being wrong but could be anyone else setting up an LSN beyond what's
written in XLogCtl->LogwrtRqst, I think fixing the second problem is
the right direction (as the patch does here). The backend doing WAL
write already honors the adjusted position, so the walwriter missing
it needs to be fixed too. If the backend gets to write the WAL before
the walwriter, it would not have written this WAL record because
wait-for-any-in-progress-insertions-to-finish in XLogFlush() honors
the adjusted position. This matters because the consequences on the
standby are hard to deal with in production, stuck WAL replay, vacuum
issues on the primary, and possibly failovers.

If I understand correctly, you identified that the walwriter is the
problem by looking at the pid from the "request to flush past end of
generated WAL" log message, right? Nice find.

Also, I'm curious, how did the standby get out of the stuck error loop
"record with incorrect prev-link"?

Also, did you observe any "xlog flush request %X/%08X is not satisfied
--- flushed only to" or other messages on the primary? And I believe
if the primary had crashed before checkpointing this WAL record, it
would have also been stuck in a similar error loop, right?

A few comments on the patch.

1/ Nit. How about using "adjusted" instead of "clamped" in the
comments and commit message?

+ * if 'upto' is past the end of reserved WAL, the request is clamped to the
+ /* honor the clamp if the request was past the end of reserved WAL */
WaitXLogInsertionsToFinish() clamps a request that is past the end of

2/ Why do we need to check the adjusted LSN against the requested LSN
again? Also, is there a reason to compare it with the flush LSN? Why
not just assign the adjusted LSNs like XLogFlush() does?

+ /* honor the clamp if the request was past the end of reserved WAL */
+ if (insertpos < WriteRqst.Write)
+ {
+ WriteRqst.Write = insertpos;
+ if (WriteRqst.Flush > insertpos)
+ WriteRqst.Flush = insertpos;
+ }

3/ Do we need similar adjusted handling in AdvanceXLInsertBuffer()? I
don't think so because there the whole old page from the WAL buffer is
written anyway. Just want to clarify.

--
Bharath Rupireddy
Amazon Web Services: https://aws.amazon.com

Hi,

Thanks for the detailed review.

Thanks for the patches. I don't see a CF entry yet, so I created one:
https://commitfest.postgresql.org/patch/7294/. Feel free to add
yourself as an author.

There is already an entry for this work: I registered
https://commitfest.postgresql.org/patch/7252/ in PG20-3 when I posted
v1, and cfbot has been testing the v2 series there. Sorry that it was
easy to miss — the entry hangs off this old thread's subject. Could
you withdraw #7294 so we don't split the history between two entries?

What exactly caused the wait-for-any-in-progress-insertions-to-finish
to receive an LSN past the end of the generated WAL is one problem.

An update on that first problem: since my last mail we have identified
the in-core path that produced the bogus LSN, and reproduced the whole
incident on 15.13 with plain SQL — no fault injection, no extensions
involved.

The source is the xlog-switch EndPos override in XLogInsertRecord()
(quoted from REL_15; master has the identical computation under
"class == WALINSERT_SPECIAL_SWITCH"):

if (isLogSwitch)
{
...
if (inserted)
{
EndPos = StartPos + SizeOfXLogRecord;
if (StartPos / XLOG_BLCKSZ != EndPos / XLOG_BLCKSZ)
{
uint64 offset = XLogSegmentOffset(EndPos, wal_segment_size);

if (offset == EndPos % XLOG_BLCKSZ)
EndPos += SizeOfXLogLongPHD;
else
EndPos += SizeOfXLogShortPHD;
}
}
}

When the switch record starts exactly SizeOfXLogRecord (24) bytes
before a segment boundary, EndPos lands on the boundary, the
page-crossing branch fires with offset == 0 == EndPos % XLOG_BLCKSZ,
and EndPos becomes boundary + SizeOfXLogLongPHD = boundary + 0x28 —
the incident value. The override is intended to return the end of the
switch record rather than the end of the reserved segment, but in this
exact-boundary case it also skips the next page header, so the result
is a start-of-the-next-record position — unlike proper end positions,
which stay before the header (compare XLogBytePosToEndRecPtr()). Note
where it flows: the shared LogwrtRqst.Write update happens before the
override, so it gets the sane pre-override value; the overridden value
goes into XactLastRecEnd and the function's return value (which is
what pg_switch_wal() reports). Among the in-core paths that can turn
into a flush request, XactLastRecEnd is the only sink.

Then, because pg_switch_wal() allocates no XID, markXidCommitted is
false in RecordTransactionCommit(), so even with synchronous_commit =
on the commit takes the async branch and hands exactly that value to
XLogSetAsyncXactLSN(). From there the walwriter picks it up, emits the
"past end of generated WAL" warning, and — without the fix — performs
the header-only flush.

Why it is so rare: the window is exactly that one position. If the
switch record instead starts 16 or 8 bytes before the boundary, its
reservation spills over and ReserveXLogSwitch() consumes the rest of
the segment, so reservedUpto advances past the final EndPos and the
condition never triggers. The affected installation runs a backup
script that issues pg_switch_wal() every ten minutes, and one of those
eventually hit the 24-byte window.

The reproduction drives the insert position to boundary - 24 with
pg_logical_emit_message() padding, with autovacuum disabled to reduce
interference, then calls pg_switch_wal(). The primary logs the same
warning with request = boundary + 0x28, the standby fails replay with
the same prev-link error at + 0x28, and the standby-side segment file
shows the recycled-file mechanism directly: the directory listings
show the 16MB file already existed before the test with an old mtime,
and afterwards its size was unchanged and only its mtime had advanced —
walreceiver overwrote just the received bytes. The code involved is
unchanged all the way to master.

This doesn't change the patch: XLogFlush() already honors the adjusted
position — it never writes past the reserved end, and then reports the
mismatch with the "is not satisfied" ERROR — and the walwriter must
honor the adjustment the same way. But it does mean the first problem
is in-core and reproducible with SQL alone. Whether XactLastRecEnd
receiving a "start of the next record" position deserves a fix of its
own is a fair follow-up question; the other consumers appear to cope
with it, so I kept it out of this patch series.

It also lets me improve the tests: I plan to replace the C injector
module in v2-0002 with a TAP test that reproduces the incident
naturally via pg_logical_emit_message() + pg_switch_wal(), which
should also settle the earlier injection-points discussion — there is
no longer anything to inject.

If I understand correctly, you identified that the walwriter is the
problem by looking at the pid from the "request to flush past end of
generated WAL" log message, right? Nice find.

Yes — the warning was logged under the walwriter's pid, and the value
shape pointed the same way: a request at sub-page granularity can only
reach that path through asyncXactLSN, whose sole consumer is
XLogBackgroundFlush(). It also ruled out the scenario the comment in
WaitXLogInsertionsToFinish() mentions (a data page with a bogus LSN):
that path goes through XLogFlush() — from a backend, bgwriter or
checkpointer, not the walwriter — and ends in the "not satisfied"
error, and neither was observed.

Also, I'm curious, how did the standby get out of the stuck error loop
"record with incorrect prev-link"?

Via the archive. About nine minutes later the segment filled up with
regular traffic, was archived on completion, and the standby's
restore_command fetched the intact copy over the partial local file;
replay then passed the bad spot and streaming resumed. Streaming could
not self-heal on its own: the dead walreceiver's flushedUpto stays in
shared memory, so the startup process believed data was already
available and never waited long enough for a new walreceiver to
connect. That is a separate availability problem I intend to raise
separately, to keep this patch focused.

Also, did you observe any "xlog flush request %X/%08X is not satisfied
--- flushed only to" or other messages on the primary?

No — the only anomalous message on the primary was the "request to
flush past end of generated WAL" warning. With the root cause above
that is now fully explained: the bogus LSN travelled the async-commit
branch, so it never went through XLogFlush(), which is where that
error would have come from. The absence of that message was in fact
one of the clues pointing at the async path.

And I believe if the primary had crashed before checkpointing this
WAL record, it would have also been stuck in a similar error loop,
right?

I don't think it would loop, for two reasons. First, the retry loop is
standby-mode behavior: the standby keeps waiting for more WAL because
the advertised flush position claims it exists. Crash recovery on the
primary treats the first invalid record as end-of-WAL and starts up.
Second, the primary's local segment doesn't even contain the
prev-link-failing bytes: the walwriter wrote out the initialized WAL
buffer page (long header followed by zeros), so at +0x28 crash
recovery would see a zero record length, i.e. a clean end of WAL. The
standby only saw a prev-link mismatch because walreceiver overwrote
just the first 40 bytes of a recycled segment, leaving stale bytes
behind them.

1/ Nit. How about using "adjusted" instead of "clamped" in the
comments and commit message?

Fine by me, will do in the next version.

2/ Why do we need to check the adjusted LSN against the requested LSN
again? Also, is there a reason to compare it with the flush LSN? Why
not just assign the adjusted LSNs like XLogFlush() does?

Because the two callers want opposite things from the return value.
In XLogFlush() the unconditional assignment is a deliberate group
commit optimization — "try to write/flush later additions to XLOG as
well" — and writing further than requested is a free win there since
the caller must flush at least up to its record anyway. The
walwriter's request is deliberately conservative in the other
direction: the LogwrtRqst path backs off to the last completed page
boundary to avoid rewriting the hot partial page, and WriteRqst.Flush
is chosen by the wal_writer_delay / wal_writer_flush_after policy,
including write-only cycles with Flush = 0. Unconditionally assigning
the adjusted position to both would silently override those policies —
raising Write into the current partial page and turning write-only
cycles into fsync cycles.

The fix only needs the safety direction, so it only ever lowers the
targets: take the adjusted position when it is smaller than the
request, and then cap Flush too, since Flush must not exceed Write.
Comparing rather than assigning is what preserves the Flush = 0
write-only cycles. I'll add a comment spelling this out in the next
version.

3/ Do we need similar adjusted handling in AdvanceXLInsertBuffer()? I
don't think so because there the whole old page from the WAL buffer is
written anyway. Just want to clarify.

Agreed, and for an additional reason: the request there is derived
from the buffer page being evicted, which is always at or behind the
current insert position, i.e. inside already-reserved WAL. So
WaitXLogInsertionsToFinish() can never be asked for a position past
the reserved end from that call site, and the adjusted return can't be
smaller than the request.

I'll post v3 with the "adjusted" wording, the comment above, and the
natural-reproduction TAP test.

Regards,
Paul Kim

Here is v3, with the changes discussed upthread:

- s/clamp/adjust/ in the comments and commit messages.

- XLogBackgroundFlush() now has a comment explaining why the adjusted
position is applied conditionally instead of being assigned the way
XLogFlush() does.

- The C injector module is gone. The TAP test now reproduces the
incident naturally: it pads WAL with pg_logical_emit_message() until
the insert position is exactly SizeOfXLogRecord bytes before a
segment boundary and then calls pg_switch_wal(), as described in my
previous mail. Since no dedicated module is needed anymore, the
test moved to src/test/modules/test_misc. If a concurrent record
(e.g. a bgwriter snapshot) spoils the alignment, the test retries on
a later segment boundary; pg_switch_wal()'s return value tells
whether the window was hit.

On an unpatched assert build the test brings the walwriter down with
Assert("Insert >= Write") and fails; with the fix it passes. The fix
itself is unchanged from v2 apart from comments. Rebased onto current
master.

Regards,
Paul Kim

The cfbot's Linux 32-bit task failed on v3: the TAP test's padding
loop raised "could not align the insert position". The loop computed
the exact-fill payload as (gap - base), with base measured from a
message with an empty payload. Once the payload exceeds the short
data header's range, the record switches to the long data header,
which is 3 bytes larger. With 8-byte MAXALIGN those extra bytes
disappear into alignment padding and the fill still lands exactly on
the target, but with 4-byte MAXALIGN they round up to a 4-byte
overshoot, so on 32-bit builds every attempt missed the window and the
loop gave up.

Here is v4, which approaches the target in small steps once the gap
falls below base + 200 bytes, so the final exact-fill record always
keeps the short data header. While at it, the window-hit check no
longer hardcodes SizeOfXLogLongPHD as 40 bytes (36 on 32-bit): a
normal switch reports the segment boundary itself and only the
overridden EndPos lies past it, so any nonzero offset into the new
segment marks the hit.

No changes to the fix; 0001 is identical to v3.

Regards,
Paul Kim