tests: fix 5 unrelated CI flakes in pytest/pgaftest harnesses#1153
Merged
Conversation
test_003_init_secondary force-restarts node2's Postgres directly via pg_ctl (bypassing pg_autoctl) to exercise the keeper's "ensure" restart loop, then confirms node2 reports "secondary" again before returning. That self-report only reflects node2's own FSM converging -- the monitor's independent health-check worker (5s probe period, 20s unhealthy-timeout) may not have re-confirmed node2 healthy yet. test_004_demoted immediately kills node1 next. If that lands inside the health-check's stale window, the monitor can catch node2 mid-unhealthy and refuse to fail over to it, stalling test_004's "wait until node2 state is wait_primary" for the full 180s timeout -- observed in CI as "pgaftest / multi-misc (PG17)" failing on exactly this step. Add a settle sleep at the end of test_003_init_secondary, long enough for a few health-check probe cycles to run and clear the earlier "bad" mark, before test_004 destabilizes node1.
test_011_prepare_candidate_priorities calls node2.set_candidate_priority(100),
which makes the monitor rewrite synchronous_standby_names on the primary
(node3) via an apply_settings transition -- but the test returned
immediately without waiting for node3 to converge back to "primary".
Every other candidate-priority/quorum-affecting test in this file
already waits for the primary to stabilize after this kind of change;
this one was missing it.
test_012_prepare_replication_quorums immediately calls
node3.set_number_sync_standbys(0) next. If node3 was still mid
apply_settings, the monitor rejects the call with "cannot set
number_sync_standbys when current goal state for primary node ... is
'primary', and current reported state is 'apply_settings'" -- observed
failing intermittently in CI ("pytest / multi", all PG versions).
Add the missing wait_until_state("primary") at the end of test_011.
Verified: `make -C tests run-test TEST=test_multi_ifdown PGVERSION=17`,
16/16 passed, including test_011/test_012.
wait_until_pg_is_running(timeout=STATE_CHANGE_TIMEOUT) accepted a timeout parameter but never forwarded it anywhere: the underlying `pg_autoctl inspect pgsetup wait` call had no --timeout flag, so it silently used the CLI's own 30s default instead of the caller's intended 90s; and the Python-side subprocess wait used execute()'s own default (COMMAND_TIMEOUT = 60s) rather than the requested timeout too. Citus coordinators take longer to come up than plain nodes, and 30-60s isn't always enough under CI load -- observed as test_001_init_coordinator timing out in "pytest / citus" (PG14-18) while polling for postmaster.pid, even though the node had just reported reaching state "single". Forward the timeout as both --timeout to the CLI and as execute()'s own subprocess-wait timeout (with a small margin over the CLI's own deadline, so Python doesn't kill the process right as the CLI is about to return). Verified: `make -C tests run-test TEST=test_basic_citus_operation PGVERSION=17`, 19/19 passed.
Two independent pgaftest reliability issues, plus one test-spec
adjustment discovered while verifying the second:
1. compose-start/exec race (CMD_COMPOSE_START)
`docker compose up -d` returns as soon as the daemon has issued the
start, not once the container is actually registered as running --
a following `docker exec` could still race that with "container ...
is not running" for a few hundred ms. Observed in CI as
"pgaftest / ssl (PG15)" failing on test_008_disable_maintenance,
confirmed from raw timestamps showing a 75ms gap between compose
logging "Running" and the next exec failing.
Poll `docker inspect --format '{{.State.Running}}'` for the actual
container state (up to 10s, 200ms interval) before declaring
"compose start" successful, instead of trusting compose's own
status line.
2. Pass-through state tracking gaps (runner_wait_notify_goal)
pgaftest tracks "state X passing through Y" via LISTEN/NOTIFY on the
monitor's "state" channel. Two gaps could make it miss a fast
intermediate state and report "$node did not pass through
assigned-state Y" even though the FSM behaved correctly -- observed
in CI as "pgaftest / multi-alternate (PG17)" failing on
test_005_002_fail_primary_again:
- The existing periodic 5s SQL-poll fallback (for when a NOTIFY is
missed, e.g. a transient LISTEN reconnect that silently drops any
notification sent while nobody was listening) only checked the
*final* target state, never backfilling pass-through tracking from
what it polled.
- There was no way to recover a pass-through state after the fact if
both the live NOTIFY and the periodic poll missed it.
Backfill pass-through tracking from the periodic poll's own reads,
and add a retroactive check against the monitor's persistent event
log (pgautofailover.event) once the wait succeeds: every FSM
transition is durably recorded there regardless of whether pgaftest
observed it live, so a single query after the fact settles
pass-through tracking with certainty instead of depending on having
caught the transition in real time.
3. tests/tap/specs/multi_alternate.pgaf: relax test_005_002's assertion
Even with (2)'s event-log backfill, test_005_002_fail_primary_again's
"state is primary passing through report_lsn" still failed
intermittently. Monitor logs pinned down why: node3's goalState and
reportedState can converge on report_lsn and advance to
prepare_promotion within the same log timestamp -- a ~17us window
observed locally. No external observer, live or retroactive, can
reliably catch a transition that fast; this was never a real FSM bug.
Wait for the stable end state directly instead, matching how
test_003_001/002 already handle the same kind of transition earlier
in this same spec.
Verified: rebuilt via `make build-pgaftest`; ran
tests/tap/specs/enable_ssl.pgaf (8/8) and
tests/tap/specs/multi_alternate.pgaf (16/16, twice in a row) against
PG17.
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
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.
Problem
Five separate CI flakes, each diagnosed in an earlier round of triage and left unfixed at the time:
pgaftest / multi-misc (PG17)—ensure.pgaf'stest_004_demotedtiming out.pytest / multi(all PG versions) —test_012_prepare_replication_quorumsfailing.pytest / citus(PG14–18) —test_001_init_coordinatortiming out.pgaftest / ssl (PG15)—test_008_disable_maintenancefailing with "container is not running".pgaftest / multi-alternate (PG17)—test_005_002_fail_primary_againfailing with "node3 did not pass through assigned-state report_lsn".None of these are related to each other or to the region/replication-stall work in #1149 — each is an independent timing/synchronization gap in its own corner of the test infrastructure (the old Python harness, the monitor's health-check timing, and the pgaftest tool itself).
Fixes
1.
tests/tap/specs/ensure.pgaf—test_003_init_secondaryforce-restarts node2's Postgres directly (bypassingpg_autoctl) to exercise the keeper's "ensure" restart loop, then confirms node2 self-reportssecondaryagain. That only reflects node2's own FSM converging — the monitor's independent health-check worker (5s probe period, 20s unhealthy-timeout) may not have re-confirmed node2 healthy yet.test_004_demotedimmediately kills node1 next; landing inside that window means the monitor can catch node2 mid-unhealthy and refuse to fail over to it. Added a settlesleep 15sbetween the two steps.2.
tests/test_multi_ifdown.py—test_011_prepare_candidate_prioritieschanges node2's candidate priority, which makes the monitor rewritesynchronous_standby_nameson the primary (node3) viaapply_settings— but never waited for node3 to converge back.test_012then races a primary that's still mid-transition. Added the missingnode3.wait_until_state(target_state="primary").3.
tests/pgautofailover_utils.py—wait_until_pg_is_running(timeout=...)accepted a timeout parameter but never forwarded it: neither as--timeoutto the underlyingpg_autoctl inspect pgsetup waitCLI call (which silently used its own 30s default) nor as the Python-side subprocess-wait timeout (which usedexecute()'s own 60s default). Citus coordinators can take longer than that under CI load. Now forwards the timeout to both.4.
src/bin/pgaftest/test_runner.c,CMD_COMPOSE_START—docker compose up -dreturns as soon as the daemon issues the start, not once the container is registered as actually running; a followingexeccould race that with "container ... is not running" (confirmed a 75ms gap in raw CI timestamps). Now pollsdocker inspect --format '{{.State.Running}}'(up to 10s) before declaring success.5.
src/bin/pgaftest/test_runner.c,runner_wait_notify_goal— pass-through state tracking (wait until X state is Y passing through Z) relies on catching a NOTIFY on the monitor'sstatechannel. Two gaps could make it miss a fast intermediate state: the existing periodic 5s SQL-poll fallback only checked the final target state, never backfilling pass-through tracking from what it read; and there was no way to recover a missed state after the fact. Added backfill from the periodic poll's own reads, plus a retroactive check against the monitor's persistentpgautofailover.eventlog once the wait succeeds (every transition is durably recorded there regardless of whether pgaftest saw it live).That fix narrowed the flake but didn't eliminate it for one specific case —
tests/tap/specs/multi_alternate.pgaf'stest_005_002_fail_primary_again. Monitor logs pinned down why: node3's goalState and reportedState can converge onreport_lsnand advance toprepare_promotionwithin the same log timestamp (a ~17µs window observed locally). No observer — live NOTIFY, polling, or a retroactive event-log query — can reliably catch a transition that fast, and it isn't a real FSM bug. Relaxed that one assertion to wait for the stable end state directly, matching howtest_003_001/test_003_002already handle the same kind of transition earlier in the same spec.Verification
make docker-check(citus_indent) clean.ci/banned.h.shclean.make build-pg18(no-cache): all 12REGRESS+ 6ISOLATIONmonitor tests pass — confirms nothing here touches the SQL suite.make -C tests run-test TEST=test_multi_ifdown PGVERSION=17: 16/16 passed (fix 2).make -C tests run-test TEST=test_basic_citus_operation PGVERSION=17: 19/19 passed (fix 3).pgaftest run tests/tap/specs/ensure.pgaf: 5/5 passed (fix 1).pgaftest run tests/tap/specs/enable_ssl.pgaf: 8/8 passed (fix 4).pgaftest run tests/tap/specs/multi_alternate.pgaf: 16/16 passed, twice in a row (fix 5 + spec relaxation).