Replace flat 10s Postgres-ready timeout with pg_control REDO progress tracking - #1172
Merged
Merged
Conversation
…eady local_postgres_wait_until_ready() used to give up after a single flat 10s wait, which discards an already-successful pg_rewind whenever Postgres has enough WAL to replay before reaching consistency (see #1167). Replace that flat timeout with a loop that keeps retrying while pg_control's 'Latest checkpoint's REDO location' (updated at every restartpoint) keeps advancing between attempts, and only gives up after 5 consecutive attempts with no recorded progress. Before entering the loop, log the 'Minimum recovery ending location' pg_rewind set as the target; on each iteration without progress, log how many bytes are left to replay. - PostgresControlData gains latestCheckpointRedoLSN and minRecoveryEndLSN, parsed by parse_controldata() the same way as the existing checkpoint LSN. - local_postgres_wait_until_ready() uses pg_controldata()/parseLSN() to read those fields and pretty_print_bytes() to report the remaining distance.
…match CI showed the #1167 retry loop regressed test_ensure.py::test_005_inject_error_in_node2 and test_multi_async.py::test_012_ifup_node4: both inject a fatal Postgres config error so every restart attempt crashes immediately, never reaching a checkpoint. local_postgres_wait_until_ready() couldn't tell that apart from a genuinely slow recovery, so it burned the full 5 * 10s stalled- attempts budget twice (once directly, once again after pg_rewind's 'no rewind required' non-fix) before finally falling back to pg_basebackup -- pushing total convergence past the tests' 90s timeout. Fix: pg_setup_wait_until_is_ready() leaves pgSetup->pm_status at POSTMASTER_STATUS_UNKNOWN when postmaster.pid was never found during an attempt, i.e. Postgres never started at all. Only apply the REDO-location patience loop when pm_status shows Postgres actually ran (STARTING or another known status); otherwise fail on the spot as before #1167. Separately, chasing this down surfaced a real bug in the test harness itself: PGAutoCtl.communicate()'s idempotent (repeat-call) branch returned a 2-tuple (out, err) while its normal branch returns a 3-tuple (out, err, ret). logs() always unpacks 3 values, so it crashed with 'ValueError: not enough values to unpack' whenever it ran a second time on an already-communicated process -- this is what turned test_multi_async's real 90s-timeout assertion into a confusing secondary crash in CI. Both branches now consistently return (out, err, last_returncode). Verified locally: test_ensure.py (6/6, ~73s, was previously failing/timing out) and test_multi_async.py (29/29) both pass against a PG17 test image; timeline_fork_report_lsn_deadlock.pgaf (6/6) confirms the original #1167 fix (patient retry during genuine pg_rewind recovery) is unaffected.
CI hit 'failed to bind host port ... address already in use' when docker compose up ran for one spec right after the previous spec's teardown: pick_free_port() (compose_gen.c) only verifies a port is free at generation time, then hands it to Docker to actually bind moments later -- a plain TOCTOU race, made worse by reseeding rand() from time(NULL) (1s resolution) on every call. Since pgaftest runs one spec per process and a schedule launches them back-to-back, two processes started in the same second with nearby pids could reseed to the same value and draw the same 'random' port first. Two changes: - pick_free_port() now seeds once per process, using clock_gettime() nanosecond resolution combined with the pid, instead of reseeding every call from second-resolution time(NULL). Verified empirically: 5 separate pgaftest processes launched back-to-back now each pick a distinct port, where the old code was prone to correlated draws. - runner_compose_up() (test_runner.c) now retries docker compose up up to 3 times on a host-port-conflict error, regenerating the compose file (fresh random ports) before each retry. Since pick_free_port()'s reserved[] list persists for the process lifetime, a retry is guaranteed to try a genuinely different port even if the seeding above still collided with some unrelated process. Verified: clean build, docker-check (citus_indent) and banned.h.sh both clean, and a full pgaftest run (auth.pgaf, 5/5) confirms the rewritten runner_compose_up() still behaves identically on the normal (no conflict) path, including the live compose-up progress output.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Fixes #1167.
Background
local_postgres_wait_until_ready()gives up after a single flat 10s wait for Postgres to become ready. The reporter linked exactly this line: when a restart takes longer than 10s -- e.g. after apg_rewind, replaying WAL until reaching consistency -- the failed wait is treated as a hard failure. That failure propagates up throughprimary_rewind_to_standby()intofsm_rewind_or_init(), whose blanket fallback on any error is a fullpg_basebackup. So an already-successful rewind gets discarded and replaced by a full resync (the reporter measured 12.9GB / ~4 minutes for theirs), purely because recovery took a bit more than 10s.The reporter's own proposed fix was a configurable timeout (
postgres_ready_timeout). That helps but doesn't really solve the problem: a fixed timeout, however long, is either too short for a large recovery or too long to fail fast on a genuinely stuck instance. What we actually want to know is whether Postgres is making progress, not how much time has passed.Fix
Postgres already exposes exactly that signal:
pg_control's "Latest checkpoint's REDO location" advances at every restartpoint during a long recovery, and is readable without a SQL connection via thepg_controldata()wrapper already insrc/bin/common/pgctl.c.PostgresControlData(pgsetup.h) gainslatestCheckpointRedoLSNandminRecoveryEndLSN;parse_controldata()parses both the same way it already parses the existing checkpoint LSN field.local_postgres_wait_until_ready()(primary_standby.c) replaces the single 10s wait with a loop: each iteration still waits up to 10s via the existingpg_setup_wait_until_is_ready(), but a failed wait no longer exits immediately. Instead it reads pg_control's REDO location and only gives up after 5 consecutive iterations with no advance at all. Before the loop, it logs the minimum recovery ending locationpg_rewindset as the target; each iteration without success logs how many bytes are left to replay (pretty_print_bytes()), so an operator watching the logs during a slow recovery sees real progress instead of a silent 10s hang.Verification
make -C src/bin/pg_autoctl).make docker-check(citus_indent) andci/banned.h.shboth clean.timeline_fork_report_lsn_deadlock.pgaf: 6/6 pass, including the steps that exercisepg_rewindand the subsequent restart through this exact code path -- no regression to the normal (fast) case.pg_controldatafield names and LSN format against a real, running Postgres 17 instance (Latest checkpoint's REDO location: 0/1A4F538,Minimum recovery ending location: 0/0) to confirm the parser matches actual output, not just the reference source.The reporter's scenario itself (a recovery slow enough to trip the old 10s timeout) isn't independently reproduced here -- it depends on IO/CPU pressure or a large WAL replay that's hard to manufacture deterministically in CI -- so this is verified by exercising the real rewind path end-to-end plus confirming the pg_control field parsing directly, rather than a new test that reproduces the multi-minute delay itself.