Re: Fix recovery conflict canceling the startup progress timeout

Hi Aidar,

Thanks for this patch, I agree with the PITR example and believe that
flow is a common instinct that grounds the importance of this fix.

> This looks like a backpatch candidate to 15 and later, since the bug
> is there from the moment the progress timeout exists.

You’re right:

━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
branch, @ commit path(s) tested method

────────────────────────────────────────────────────────────────
REL_15_STABLE 06428115017 lock manually (Autoconf)

REL_16_STABLE 1e9c734c26a lock manually (Meson)

REL_17_STABLE 25b55788d89 lock + pin TAP test (Autoconf)

REL_18_STABLE 9d0081c01f9 lock + pin TAP test (Autoconf)

REL_19_STABLE ee189838f94 lock + pin TAP test (Autoconf)

master cea96cdfecb lock + pin TAP test (Meson)

━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
Table 1: findings across branches

The problem reproduced on all, and fixed by v1 on all. v1 also applies
cleanly to 15-19 with a cherry-pick.

For 17-master, I used a modification of 031_recovery_conflict.pl which
tested both the lock- and pin-paths. Couldn’t get TAP section running on
16, so it was manually tested.

I believe your fix is correct and have left some minor comments that
shouldn’t block this patch.

Attached v2-0001 is your v1, unchanged; v2-0002 adds the test so cfbot
runs it alongside the fix. Without 0001, the two “progress reported
after the conflict” checks fail.

This is my first review, so any feedback on how I may improve would be
great too!

Code Trace
══════════

> The problem: a single recovery conflict stops “redo in progress”
> messages for the rest of WAL replay, even though replay continues
> normally.

> ResolveRecoveryConflictWithLock() and
> ResolveRecoveryConflictWithBufferPin() both set up their own
> timeouts (STANDBY_LOCK_TIMEOUT / STANDBY_TIMEOUT and
> STANDBY_DEADLOCK_TIMEOUT), wait, and then clean up with:

> disable_all_timeouts(false);

> That clears every timeout the process has, not only the ones these
> functions enabled. The comment above it says the startup process is
> assumed not to have any other outstanding timeouts, which was true
> when the calls were written. It stopped being true in 15, when
> STARTUP_PROGRESS_TIMEOUT was added by 9ce346eabf3.

Yes, the source of this bug is an outdated assumption — the
recovery-conflict resolvers (`ResolveRecoveryConflictWithLock',
`ResolveRecoveryConflictWithBufferPin') have always canceled /every/
timeout that the process has. Since 9ce346eabf3 that includes the
progress timer (`STARTUP_PROGRESS_TIMEOUT'), although it’s not a timer
that the resolver function armed. It’s not a problem for other conflict
types (snapshot, db, tablespace…) because they use a different wait-path
that doesn’t use timeouts.

> begin_startup_progress_phase() is called once, right before the redo
> loop. If a conflict happens later, the progress timeout is canceled
> along with the conflict timeouts and nothing ever re-arms it, so
> ereport_startup_progress() never fires again.

This is why *one conflict is enough to silence progress for the rest of
redo*, not just momentarily.

Reproducers
═══════════

I manually tested things and also modified existing TAP tests on
recovery conflicts for this. The manual flow covers only the lock path;
the TAP test additionally covers the pin path, modelled on 031’s
existing buffer pin section.

Manual Testing Approach
───────────────────────

> I reproduced it locally with recovery.signal, hot_standby=on, a slow
> restore_command with a read-only query holding ACCESS SHARE on a
> table that the WAL stream takes ACCESS EXCLUSIVE on:

> no conflict: 22 “redo in progress” messages, up to “redo done” one
> conflict: 7 messages, then silence for the last time of redo

> Redo itself completes and the data is correct; only the log messages
> disappear. But someone watching a long recovery sees the progress
> stop and can easily conclude it is stuck.

I followed your directions for the manual reproduction of the lock-path,
some details on my steps:

1. Spawn two shells: T1, a driver; T2, a log-viewer. Basic env setup on
both:
┌────
│ export R=$PGDATA/repro # scratch path
│ export P1=$((PGPORT+200)) P2=$((PGPORT+300)) # e.g primary 5719, recovery node 5819
└────
Listing 1: Basic envvar setup for both T1 and T2

2. T1: Setup primary, archive and backup, to be run on T1:
┌────
│ rm -rf "$R" && mkdir -p "$R/archive"
│

│ initdb -D "$R/primary" --no-sync -E UTF8 --no-locale
│

│ cat >> "$R/primary/postgresql.conf" <<EOF
│ port = $P1
│ log_line_prefix = '%m [%p] %q%u(at)%d '
│ fsync = off
│ autovacuum = off
│ archive_mode = on
│ archive_command = 'cp "%p" "$R/archive/%f"'
│ EOF
│

│ pg_ctl -D "$R/primary" -l "$R/primary.log" -w start
│

│ psql -X -p $P1 -c 'CREATE TABLE t (a int)'
│

│ pg_basebackup -p $P1 -D "$R/backup" --checkpoint=fast # no -R
└────
Listing 2: T1: use primary once for backups, archiving

┌────
│ # 20 segments, the LOCK record, 20 more segments
│ fill() { for i in $(seq "$1"); do
│ psql -X -q -p $P1 -c "INSERT INTO t VALUES ($i)" -c 'SELECT pg_switch_wal()' >/dev/null; done; }
│ fill 20
│ psql -X -p $P1 -c 'BEGIN; LOCK TABLE t; COMMIT;'
│ fill 20
│

│ pg_ctl -D "$R/primary" -m fast -w stop # shutdown archives the remaining finished segments
│

│ ls "$R/archive" | wc -l # expect ~40+ segments
└────
Listing 3: T1: Seed WAL segments

3. Create the Recovery Node, set `recovery.signal' and other parameters
┌────
│ RUN=base
│

│ rm -rf "$R/pitr" && cp -a "$R/backup" "$R/pitr"
│

│ cat >> "$R/pitr/postgresql.conf" <<EOF
│

│ # --- recovery node ---
│ port = $P2
│ archive_mode = off
│ hot_standby = on
│ recovery_prefetch = off
│ restore_command = 'sleep 1; cp "$R/archive/%f" "%p"'
│ log_startup_progress_interval = 500ms
│ log_recovery_conflict_waits = on
│ deadlock_timeout = 100ms
│ max_standby_archive_delay = -1
│ EOF
│

│ touch "$R/pitr/recovery.signal"
└────
Listing 4: T1: setup recovery node

4. Run the actions, driven by T1

┌────
│ RUN=base; tail -F "$R/pitr-$RUN.log"
└────
Listing 5: T2: watch the log run to understand, coordinate timing

┌────
│ pg_ctl -D "$R/pitr" -l "$R/pitr-$RUN.log" -w start && psql -X -p $P2
└────
Listing 6: T1: run the recovery proc, start psql (connected to
Recovery Node)

At this point, seeing the logs on T2 will show milestones in the
recovery process (restored log file stmts, consistent recovery state
reached, ready to accept read-only connection [hot-standby]…)

┌────
│ BEGIN; LOCK TABLE t IN ACCESS SHARE MODE;
└────
Listing 7: T1: take the lock before replay reaches the LOCK TABLE
record (~within 20s)

Observe T2, the replay pauses at the `LOCK TABLE' record (around 20
segments in) with “recovery still waiting after … ms: recovery
conflict on lock”. This gives a 20s window to take the lock.

┌────
│ COMMIT;
│ \q # exit psql
└────
Listing 8: T1: Release lock via psql to resume

Now, on logs (T2) we should see the recovery process resume:

┌────
│ recovery finished waiting after <time> ms: recovery conflict on lock
│ <20 more lines of "restored log file <segment file name> from archive">
│ redo done at ...
└────
Listing 9: Remaining shape of the log output (without v1 applied)

┌────
│ recovery finished waiting after <time> ms: recovery conflict on lock
│ <
│ 20 more lines of
│ "restored log file <segment file name> from archive"
│ interleaved with:
│ "redo in progress, elapsed time: ..."
│ >
│ redo done at ...
└────
Listing 10: Remaining shape of the log output (v1 applied)

So, with the base build, no “redo in progress” appears after
“recovery finished waiting”; with v1 applied, it keeps appearing
until “redo done”.

TAP Additions
─────────────

It seems to me that in the near future, this area of the codebase may be
redesigned. For example, other than the patches related to this —
cf/7372 (deadlock-detection), cf/6876 (on timeout disabling) — there’s
refactor patches like cf/6690 and some discord discussions[1].
Therefore, I think adding some simple tests may guard against
inadvertent regressions.

I modified 031_recovery_conflict.pl by adding a section that crudely
follows the manual testing approach above — e.g. it’s time-based and
uses sleeps in `restore_command' (increases the test run by ~13s). This
is also a place where I’ve used AI-assistance to help me translate the
flow to Perl/TAP-code (Claude Sonnet 5.5). Though this works for
correctness testing, it is likely not good enough to be in the final
patch for this cf entry.

I’m happy to help refine the test logic if you think there’s value to
putting the tests in. Else, feel free to ignore v2-0002.

Observation: Batch-helpers
══════════════════════════

Reading cf/7372, I noticed `timeout.c'’s batched disable_timeouts(). I
don’t think your patch needs it. With the progress timer still active,
each `disable_timeout()' call reschedules the alarm, so batching saves
one `GetCurrentTimestamp()' and at most one `setitimer()' per conflict
wait. It’s just two single calls and likely isn’t worth the extra lines.

I thought to include this observation in for completeness-sake.

Regards, Ritesh

Footnotes
─────────

[1] : An example of a discussion on buffer pins and possible changes in
the future — see [this thread]
(<https://discord.com/channels/1258108670710124574/1565326785464373301>)
on pin-conflict magic