Repository navigation
test_liveness flakes: a check-in thread can still be alive just after its tick returns #45
Description
Follow-up to #39, found on #44's first CI run (38008871788, 2026-10-10).
Symptom: tests/test_liveness.py::test_ok_is_logged_on_the_first_and_after_a_failure_only failed with assert [20, 20] == [20, 20, 20]. The captured log ends:
INFO liveness check-in
WARNING consume loop stale; not checking in
WARNING previous check-in still in flight; skipping this tick
It passed on re-run and has passed locally.
Cause: Heartbeat._in_thread's thread hands its result to the loop with loop.call_soon_threadsafe(settle, …) and then returns. settle can run, and the tick can finish, before that thread has exited, so self._thread.is_alive() stays true for a moment. The test's 5th tick (stale) returns without awaiting anything. That lets the 6th tick run right after the 4th tick's check-in, and it sees the 4th tick's thread still alive and skips (src/processor/liveness.py, the is_alive() check in tick).
Impact: test-only in practice. At interval_s=300 a finished thread has long since exited, and a falsely skipped tick would be absorbed by the monitor's 900 s grace anyway. But a red main push run blocks scripts/deploy.sh (#34), so a flake in the suite is a deploy hazard (#43 had the same problem with image pulls).
Fix options (to weigh):
- Code: "in flight" means the post hasn't returned yet, not that the thread is alive. For example,
targetclears a flag (orself._thread) before it callscall_soon_threadsafe. A timed-out post still counts as in flight, so trap 1 of Liveness check-in for processor run (co-status monitor co-processor-live) #39 (no piled-up threads) still holds. - Test-only: wait for the previous thread to finish before the next tick. This hides the race rather than removing it.
Done when: a test reproduces the race deterministically (for example, a post that doesn't let its thread exit until the loop has seen the result), the fix makes it pass, and the existing in-flight/timeout tests still pass.
Activity
gregoryfoster commentedon Oct 10, 2026
Second occurrence, on #46's CI (run 38069820069, 2026-10-10):
assert [20] == [20, 20, 20]. The first tick's thread was still alive at tick 2, and every tick after it skipped ("previous check-in still in flight" ×4, plus the stale tick). It's the same race with a wider window: a skipped tick returns without awaiting, so the following ticks run back to back on the loop and all see the one thread that hasn't exited yet. Twice in two days of CI makes this a real deploy hazard under #34's gate, not a once-off.gregoryfoster commentedon Oct 10, 2026
Hand-off from the burn-down epic #24, 2026-10-10. This is next. #43 shipped in #44 and #46.
Why now. This flake has turned
mainred three times in two days: #44's first PR run, #46's CI, and themainpush run ofe71f673(the skills bump, 2026-10-10T00:20Z:assert [20] == [20, 20, 20]). Since #34, a red push run meansscripts/deploy.shrefuses that commit. That puts it in the epic's deploy-safety tier, ahead of #47 and #5.Touchpoints (checked against
mainat2ecb9d4):src/processor/liveness.py:tick(line 88); the in-flight check is line 98 (self._thread is not None and self._thread.is_alive());asyncio.timeoutaround_in_thread(lines 108–111);_in_thread(line 127):targetrunspost, thenloop.call_soon_threadsafe(settle, …)(line 146), then the thread exits. Afuture.done()guard (line 133) covers a post cut off by the timeout.tests/test_liveness.py:150test_ok_is_logged_on_the_first_and_after_a_failure_only, plus the existing in-flight and timeout tests beside it.The mechanism is as #45 states it,
[traced, and seen 3 times]: the result reaches the loop before the thread has exited, sois_alive()is briefly true after the tick that awaited it returns. A skipped or stale tick awaits nothing, so the ticks after it run back to back and all see that thread. Hence[20], with 4 ticks skipped, on the second run.Recommendation: fix the code, not the test. #45's first option. "In flight" should mean "the post hasn't handed back its result", not "the thread exists":
start()and cleared intargetbeforecall_soon_threadsafe(or tested from the future's state, if that keeps Liveness check-in for processor run (co-status monitor co-processor-live) #39's trap 1);asyncio.timeoutis still running in its thread, so it must keep counting as in flight until that thread'spostreturns, or a hung Status piles up threads. The marker has to be cleared by the thread, never by the timeout path.Prove it deterministically (the issue's Done-when): reproduce the race without sleeps. For example, a
poststub whose thread is held after it hands back its result (wraptarget, or gate the thread's exit on anEventthe test controls), then run the next tick. It must not skip. Keep a test that a post still running past the timeout does make the next tick skip.Deploy: this changes
src/, so after the FF merge runscripts/deploy.sh(through #34's gate).startingrecord hasliveness: on …, then aliveness check-inwith no WARNING over the next few ticks, and Status'sco-processor-livestaysok.Out of scope:
16.145.19.221; no command was affected). It's on the epic as a watch item;Ship: issue → branch in a worktree → TDD (the race reproduced red first) → PR → FF merge →
git pull --ff-only→scripts/deploy.sh. The closing comment gives each box with its evidence, plus a full-suite loop or repeated runs oftest_liveness.pyunder load, and the follow-ups (or "none").Kickoff prompt:
#45 test: CR 1 — a cut-off check-in frees the next tick once its post…
#45 docs: CR 2 — _in_thread's docstring names the in-flight marker it…
#45 test: CR 3 — the start-failure test counts its calls
gregoryfoster commentedon Oct 10, 2026
Shipped in #48 (FF merge,
a39bb0d..2088d71), live on2088d71df868since 2026-10-10T20:01Z.Fix. "In flight" now means "the post hasn't returned", not "the thread is alive".
Heartbeat._in_flightis set beforestart(), and the thread clears it oncepostreturns and beforecall_soon_threadsafe. The timeout path never clears it, so a cut-off post keeps later ticks skipping until it returns (#39 trap 1). A failedstart()clears it too.Done when:
test_a_finished_check_in_whose_thread_lingers_does_not_skip_the_next_tickholds every check-in thread after its target returns, with no sleeps. Red ata39bb0d(assert 1 == 2, plusprevious check-in still in flight), green at2428fe8.test_a_hung_status_is_cut_off_and_the_next_tick_is_skippedpasses unchanged. CR 1 (d116932) adds the other half of trap 1: a cut-off post frees the next tick once it returns. That test fails if the marker is cleared on the loop instead.test_a_thread_that_fails_to_start_does_not_wedge_the_heartbeat, mutation-checked.Evidence:
-m integration56 passed; PR CI and themainpush run 38081844646 green.tests/test_liveness.py×100 under 4 CPU burners on 2 vCPU: 100/100.scripts/deploy.shthrough deploy.sh: gate a deploy on the commit's CI (status#11's CI gate) #34's gate:live is on 2088d71df868.starting20:01:05Z hasliveness: on 01M4H5FH3PTPGEB24XYQJ4NG7A;liveness check-incheckin: 202at 20:01:05Z; then zero WARNING/ERROR records through 20:17:20Z (three further ticks; a steadyoklogs nothing).co-processor-live's state on Status directly (no read path from here), only through the accepted check-ins.Follow-ups: none.