Hi,
Konstantin Knizhnik <[email protected]> wrote:
> I have not re-run the recovery TAP suite against this tree (no local
> install of current master).
I ran it on master 2c10c2ce4d7 with v2 (cassert, injection points):
src/test/recovery passes, 802 tests against 799 on master, the new
ones being 058. Without the C changes, 058 fails as intended, with
startup rereading the corrupt local copy until the timeout.
One ordering issue: the reset of applyFlushedUpto runs after
RequestXLogStreaming(). If the new walreceiver flushes the
replacement bytes before the reset, the pointer goes back below them
and startup waits for the next flush. The window is tiny, but with a
3 s sleep there, replay sat for about 18 s until an unrelated
running-xacts record arrived.
Doing the reset before RequestXLogStreaming() closes it: with the
same sleep there is no stall, and with only that change (attached, on
top of v2) the recovery suite passes and 058 passed 20 of 20 runs.
Logs and the review-only diffs are in the second attachment.
Regards,
Manu
diff --git a/src/backend/access/transam/xlogrecovery.c
b/src/backend/access/transam/xlogrecovery.c
index 061c7e1ff5b..e3dc1138c4e 100644
--- a/src/backend/access/transam/xlogrecovery.c
+++ b/src/backend/access/transam/xlogrecovery.c
@@ -3880,11 +3880,6 @@ WaitForWALToBecomeAvailable(XLogRecPtr RecPtr, bool
randAccess,
}
curFileTLI = tli;
SetInstallXLogFileSegmentActive();
- RequestXLogStreaming(tli, ptr,
PrimaryConnInfo,
-
PrimarySlotName,
-
wal_receiver_create_temp_slot);
- flushedUpto = InvalidXLogRecPtr;
-
/*
* RequestXLogStreaming()
rounds ptr down to a segment
* boundary and leaves
flushedUpto unchanged on a
@@ -3911,6 +3906,11 @@ WaitForWALToBecomeAvailable(XLogRecPtr RecPtr, bool
randAccess,
ResetWalRcvApplyFlushRecPtr(ptr);
}
}
+
+ RequestXLogStreaming(tli, ptr,
PrimaryConnInfo,
+
PrimarySlotName,
+
wal_receiver_create_temp_slot);
+ flushedUpto = InvalidXLogRecPtr;
}
/*
Review of v2 (applyFlushedUpto) on master 2c10c2ce4d7
--enable-cassert --enable-debug --enable-tap-tests --enable-injection-points
===== recovery suite (make check in src/test/recovery, PROVE_FLAGS=-j6) =====
v2: Files=57, Tests=802, 62 wallclock secs ( 0.45 usr 0.07 sys + 20.70
cusr 41.80 csys = 63.02 CPU) Result: PASS
master: Files=56, Tests=799, 67 wallclock secs ( 0.46 usr 0.08 sys + 21.34
cusr 42.92 csys = 64.80 CPU) Result: PASS
===== 058 alone, 20 runs with v2 =====
run 1: PASS in 6 s
run 2: PASS in 4 s
run 3: PASS in 5 s
run 4: PASS in 7 s
run 5: PASS in 4 s
run 6: PASS in 6 s
run 7: PASS in 6 s
run 8: PASS in 6 s
run 9: PASS in 7 s
run 10: PASS in 5 s
run 11: PASS in 4 s
run 12: PASS in 4 s
run 13: PASS in 4 s
run 14: PASS in 4 s
run 15: PASS in 4 s
run 16: PASS in 5 s
run 17: PASS in 5 s
run 18: PASS in 4 s
run 19: PASS in 5 s
run 20: PASS in 5 s
v2: 20 passed, 0 failed of 20
===== 058 with the test but without the C changes =====
run 1: FAIL in 77 s
# poll_query_until timed out executing this query:
tonly: 0 passed, 1 failed of 1
standby log: 'incorrect prev-link 0/DEADBEEF' x 663, 'started streaming WAL' x 2
===== delay.diff (review only: 3 s between RequestXLogStreaming() and the
reset) =====
diff --git a/src/backend/access/transam/xlogrecovery.c
b/src/backend/access/transam/xlogrecovery.c
index 061c7e1ff5b..318d2db8c26 100644
--- a/src/backend/access/transam/xlogrecovery.c
+++ b/src/backend/access/transam/xlogrecovery.c
@@ -3896,6 +3896,11 @@ WaitForWALToBecomeAvailable(XLogRecPtr RecPtr, bool
randAccess,
* apply pointer so replay is
not stalled on WAL that
* is already on disk.
*/
+ /* REVIEW ONLY: widen the
window between RequestXLogStreaming()
+ * and the reset below, to see
what happens if the new
+ * walreceiver flushes before
the reset. */
+ if (resetApplyFlush)
+ pg_usleep(3000000L);
if (resetApplyFlush)
{
XLogRecPtr
sharedFlush;
===== reorder.diff (review only: reset moved before RequestXLogStreaming(),
same 3 s sleep after it) =====
diff --git a/src/backend/access/transam/xlogrecovery.c
b/src/backend/access/transam/xlogrecovery.c
index 061c7e1ff5b..8c4760b1a78 100644
--- a/src/backend/access/transam/xlogrecovery.c
+++ b/src/backend/access/transam/xlogrecovery.c
@@ -3880,11 +3880,6 @@ WaitForWALToBecomeAvailable(XLogRecPtr RecPtr, bool
randAccess,
}
curFileTLI = tli;
SetInstallXLogFileSegmentActive();
- RequestXLogStreaming(tli, ptr,
PrimaryConnInfo,
-
PrimarySlotName,
-
wal_receiver_create_temp_slot);
- flushedUpto = InvalidXLogRecPtr;
-
/*
* RequestXLogStreaming()
rounds ptr down to a segment
* boundary and leaves
flushedUpto unchanged on a
@@ -3911,6 +3906,15 @@ WaitForWALToBecomeAvailable(XLogRecPtr RecPtr, bool
randAccess,
ResetWalRcvApplyFlushRecPtr(ptr);
}
}
+ RequestXLogStreaming(tli, ptr,
PrimaryConnInfo,
+
PrimarySlotName,
+
wal_receiver_create_temp_slot);
+ flushedUpto = InvalidXLogRecPtr;
+
+ /* REVIEW ONLY: same 3 s window
as the v2delay build, now
+ * after the reset instead of
before it. */
+ if (resetApplyFlush)
+ pg_usleep(3000000L);
}
/*
===== t/058b_stream_repair_probe.pl (058 + primary at debug2 + PROBE note) =====
--- /home/manu/pgwal/src-v2/src/test/recovery/t/058_stream_repair.pl
2026-09-24 22:39:11.024531848 -0300
+++
/home/manu/pgwal/src-v2delay/src/test/recovery/t/058b_stream_repair_probe.pl
2026-09-24 22:46:25.933116755 -0300
@@ -21,6 +21,7 @@
'postgresql.conf', qq(
autovacuum = off
wal_keep_size = 1GB
+log_min_messages = debug2
));
$primary->start;
@@ -145,6 +146,13 @@
"SELECT pg_last_wal_replay_lsn() >= '$target_lsn'")
or die "standby did not replace corrupt WAL and catch up";
+# REVIEW PROBE: did the primary have to write WAL past the target for the
+# standby to get there?
+my $primary_now = $primary->lsn('insert');
+my $past = $primary->safe_psql('postgres',
+ "SELECT pg_wal_lsn_diff('$primary_now', '$target_lsn')");
+note "PROBE target_lsn=$target_lsn primary_insert_now=$primary_now
bytes_past_target=$past";
+
ok( $standby->log_contains(
qr/record with incorrect prev-link 0\/DEADBEEF/),
'standby observed the injected corrupt record');
===== probe with delay.diff =====
2026-09-24 22:46:34.626 -03 checkpointer[912365] DEBUG: snapshot of 0+0
running transaction ids (lsn 0/02000088 oldest
2026-09-24 22:46:58.978 -03 background writer[912366] DEBUG: snapshot of 0+0
running transaction ids (lsn 0/050020D8 ol
2026-09-24 22:46:34.876 -03 walreceiver[912494] LOG: started streaming WAL
from primary at 0/03000000 on timeline 1
2026-09-24 22:46:38.002 -03 walreceiver[913390] LOG: started streaming WAL
from primary at 0/03000000 on timeline 1
2026-09-24 22:46:38.115 -03 startup[912493] LOG: record with incorrect
prev-link 0/DEADBEEF at 0/04000028
2026-09-24 22:46:38.117 -03 walreceiver[913456] LOG: started streaming WAL
from primary at 0/04000000 on timeline 1
2026-09-24 22:46:41.116 -03 startup[912493] LOG: restarting WAL streaming from
0/04000018; ignoring previously flushed WAL up to 0/050020A0
[22:46:38.009](4.490s) ok 1 - receive LSN does not move backward on walreceiver
restart with apply lag
[22:46:59.085](21.076s) # PROBE target_lsn=0/050020A0
primary_insert_now=0/050020D8 bytes_past_target=56
[22:46:59.087](0.002s) ok 2 - standby observed the injected corrupt record
[22:46:59.087](0.000s) ok 3 - standby ignored stale flush pointer after the
corrupt record
===== probe with reorder.diff =====
Files=1, Tests=3, 8 wallclock secs ( 0.01 usr 0.00 sys + 0.25 cusr 0.55
csys = 0.81 CPU)
Result: PASS
2026-09-24 22:48:49.248 -03 startup[957343] LOG: record with incorrect
prev-link 0/DEADBEEF at 0/04000028
2026-09-24 22:48:49.248 -03 startup[957343] LOG: restarting WAL streaming from
0/04000018; ignoring previously flushed WAL up to 0/050020A0
2026-09-24 22:48:49.250 -03 walreceiver[958288] LOG: started streaming WAL
from primary at 0/04000000 on timeline 1
[22:48:49.124](4.254s) ok 1 - receive LSN does not move backward on walreceiver
restart with apply lag
[22:48:52.371](3.247s) # PROBE target_lsn=0/050020A0
primary_insert_now=0/050020A0 bytes_past_target=0
[22:48:52.372](0.000s) ok 2 - standby observed the injected corrupt record
[22:48:52.372](0.000s) ok 3 - standby ignored stale flush pointer after the
corrupt record
===== v2 + nocfbot-reset-before-request.diff.txt (no sleep) =====
v2fix built, warnings=0
v2fix: 20 passed, 0 failed of 20
recovery suite v2fix: rc=0 in 45 s; Files=57, Tests=802, 43 wallclock secs (
0.36 usr 0.06 sys + 14.60 cusr 30.96 csys = 45.98 CPU) Result: PASS
