Skip to content

tests: fix 5 unrelated CI flakes in pytest/pgaftest harnesses#1153

Merged
dimitri merged 4 commits into
mainfrom
fix/five-test-flakes
Jul 23, 2026
Merged

tests: fix 5 unrelated CI flakes in pytest/pgaftest harnesses#1153
dimitri merged 4 commits into
mainfrom
fix/five-test-flakes

Conversation

@dimitri

@dimitri dimitri commented Jul 23, 2026

Copy link
Copy Markdown
Contributor

Problem

Five separate CI flakes, each diagnosed in an earlier round of triage and left unfixed at the time:

  1. pgaftest / multi-misc (PG17)ensure.pgaf's test_004_demoted timing out.
  2. pytest / multi (all PG versions) — test_012_prepare_replication_quorums failing.
  3. pytest / citus (PG14–18) — test_001_init_coordinator timing out.
  4. pgaftest / ssl (PG15)test_008_disable_maintenance failing with "container is not running".
  5. pgaftest / multi-alternate (PG17)test_005_002_fail_primary_again failing 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.pgaftest_003_init_secondary force-restarts node2's Postgres directly (bypassing pg_autoctl) to exercise the keeper's "ensure" restart loop, then confirms node2 self-reports secondary again. 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_demoted immediately kills node1 next; landing inside that window means the monitor can catch node2 mid-unhealthy and refuse to fail over to it. Added a settle sleep 15s between the two steps.

2. tests/test_multi_ifdown.pytest_011_prepare_candidate_priorities changes node2's candidate priority, which makes the monitor rewrite synchronous_standby_names on the primary (node3) via apply_settings — but never waited for node3 to converge back. test_012 then races a primary that's still mid-transition. Added the missing node3.wait_until_state(target_state="primary").

3. tests/pgautofailover_utils.pywait_until_pg_is_running(timeout=...) accepted a timeout parameter but never forwarded it: neither as --timeout to the underlying pg_autoctl inspect pgsetup wait CLI call (which silently used its own 30s default) nor as the Python-side subprocess-wait timeout (which used execute()'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_STARTdocker compose up -d returns as soon as the daemon issues the start, not once the container is registered as actually running; a following exec could race that with "container ... is not running" (confirmed a 75ms gap in raw CI timestamps). Now polls docker 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's state channel. 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 persistent pgautofailover.event log 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's test_005_002_fail_primary_again. 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 ~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 how test_003_001/test_003_002 already handle the same kind of transition earlier in the same spec.

Verification

  • Style: make docker-check (citus_indent) clean.
  • Banned API: ci/banned.h.sh clean.
  • make build-pg18 (no-cache): all 12 REGRESS + 6 ISOLATION monitor 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).

dimitri added 4 commits July 23, 2026 04:49
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.
@dimitri dimitri added Developer productivity Enhancements to ability to ship quality code Packaging and CI Enhancements to our CI integration labels Jul 23, 2026
@dimitri dimitri self-assigned this Jul 23, 2026
@dimitri
dimitri merged commit 5bdcd1b into main Jul 23, 2026
72 checks passed
@dimitri
dimitri deleted the fix/five-test-flakes branch July 23, 2026 13:36
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Developer productivity Enhancements to ability to ship quality code Packaging and CI Enhancements to our CI integration

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant