Skip to content

test: convert remaining TRUE-FLAKE-RISK wall-clock assertions to ordering witnesses (#438 family) - #549

Merged
Kyzcreig merged 3 commits into
mainfrom
tests-wallclock-438b
Aug 10, 2026
Merged

Kyzcreig merged 3 commits into
mainfrom
tests-wallclock-438b

Conversation

@Kyzcreig

Copy link
Copy Markdown
Collaborator

test: convert remaining TRUE-FLAKE-RISK wall-clock assertions to ordering witnesses

Card t_7e1f87ff. Continues the family started in #438 (and #534 / test_mcp_tool_issue_948.py).
Same rule, applied to the members those PRs left behind:

Convert when failure can be caused by the machine being busy.
Leave alone when failure can only be caused by the behavior being wrong.

The headline: one of these was failing on fork/main right now

tests/tools/test_mcp_stdio_init_timeout.py was not a theoretical flake. On a pristine
fork/main checkout with zero diff applied, it failed:

E  AssertionError: _run_stdio blocked 2.9s on a hanging initialize() — the connect_timeout
   (0.2s) bound was not applied; the #59349 subprocess/FD leak has regressed.
E  assert 2.8976902499998687 < 2.0

That bound was not measuring the behavior it protects

Profiling the measured window (cProfile, cumulative):

ELAPSED= 2.553734750006697
   5    0.000    2.350  tools/mcp_tool.py:2377(_run_stdio)
   2    0.000    2.336  tools/mcp_tool.py:4293(_snapshot_child_pids)

2.336s of the 2.35s window is _snapshot_child_pids — a ps-based child-process scan
that runs before the handshake and has nothing to do with the connect_timeout bound
being asserted. Exactly the trap #426/#438 documented: the threshold silently absorbed
setup cost it was never meant to measure. The instrument was the defect.

What changed (5 conversions)

file was now
tests/tools/test_mcp_stdio_init_timeout.py assert elapsed < 2.0 ordering witness: the task must be done (not pending) after a bounded wait, raised TimeoutError, and the hanging initialize() was actually torn down
tests/acp_adapter/test_acp_mcp_discovery.py assert elapsed < 0.2 entered + discover_returned Events; returned asserted unset when the caller returns
tests/hermes_cli/test_mcp_startup.py assert elapsed < 0.2 (+ a poll loop) same witness pair; also deletes the 3s polling deadline
tests/hermes_cli/test_update_check.py assert elapsed < 1.0 same witness pair on prefetch_update_check
tests/hermes_cli/test_api_key_providers.py assert elapsed < 1.5 (vs a 2.0s sleep — 0.5s margin) slow losers must still be in flight when detect_zai_endpoint returns

Every wait is finite (10s — orders of magnitude above a real rendezvous, so it is not
itself a timing assertion) so a genuine regression fails fast instead of hanging.

RED proofs — every conversion still gates

Each was verified by breaking the behavior it protects and confirming the new assertion
fails by name:

target break applied new assertion caught it
mcp stdio init timeout removed asyncio.wait_for(session.initialize(), ...) (the pre-NousResearch#59349 bug) ✅ "_run_stdio never unwound on its own — the connect_timeout bound was not applied"
acp background discovery discovery called inline instead of on the thread ✅ "start_background_mcp_discovery blocked on discovery — it ran inline"
mcp startup same inline mutation ✅ "_prepare_agent_startup blocked on MCP discovery — it ran inline"
update check prefetch _run() called inline ✅ "prefetch_update_check blocked on check_for_updates — it ran inline"
zai early exit removed the priority-order early-return ✅ "detect_zai_endpoint waited for the slow losers"

The RED exercise caught a real defect in my own draft, which is the argument for making
it mandatory. test_mcp_startup's stub used an unbounded stop.wait(). Under the inline
mutation the caller blocked inside the stub forever, so the suite hung rather than
failing on the witness — a witness only reachable by hanging is not a gate. Fixed to
stop.wait(timeout=10.0) (separate commit).

A first mutation attempt on mcp_startup called _discover() inline, which self-deadlocks
on the re-entrant _mcp_discovery_lock. That deadlock was an artifact of the mutation, not
a real regression, so it was discarded in favour of calling the inner discovery directly.

All source mutations were reverted — this diff is test-only (git status shows 5 test
files; git diff --name-only against the source files is empty).

Verification (exact observed counts)

  • Baseline on the 4 unconverted files before any edit: 4 files, 113 tests passed, 0 failed in 70.9s
  • After conversion, same 4 files: 4 files, 113 tests passed, 0 failed in 9.3s
  • Full directories — scripts/run_tests.sh tests/tools/test_mcp_stdio_init_timeout.py tests/acp_adapter/ tests/hermes_cli/ -q:
    576 files, 4789 tests passed, 0 failed (100% complete) in 95.3s
  • Load immunity (the actual claim — 24 CPU burners, load average 9.31), 3 consecutive runs:
    5 files, 114 tests passed, 0 failed × 3. The converted test_mcp_stdio_init_timeout
    passes under load where the original failed idle.

Side effect

Removing the fixed sleeps: those 4 files go 70.9s → 9.3s, and
test_mcp_stdio_init_timeout goes 4.4s → 0.9s.

Deliberately NOT converted (legitimate — do not "fix" these)

  • assert ev.wait(timeout=N) — asserts the event, not the duration. The number only
    stops a hang. (The overwhelming majority of raw grep hits.)
  • Lower bounds — tests/test_tui_entry_mcp_owner.py:35 assert elapsed >= 0.04,
    tests/tui_gateway/test_compute_host_phase1.py:260. These prove an injected wait
    happened; load makes them more reliable. Converting them would be a mistake.
  • Ceilings an order of magnitude above the guarded hang —
    tests/tools/test_local_background_child_hang.py (< 10.0 vs a 15s+ hang),
    tests/agent/test_codex_ttfb_watchdog.py (< 20 / < 30 vs multi-minute stalls),
    tests/agent/test_cascading_interrupt_6600.py (< 10.0 vs 30s+). Ratio matters.
  • Tests whose subject IS timing / cost — tests/test_hermes_state.py (adversarial
    FTS5 sanitizer runtime), tests/agent/test_redact.py (regex backtracking blowup),
    tests/context_engine/test_lcm_media_token_accounting.py (token cost, not wall clock).
    The bound is the point of the test.

Follow-up candidates (not in this PR — kept reviewable)

Bounded scope per the card. These are plausible members that need individual profiling +
RED proofs and belong in their own diff:

  • tests/agent/test_auxiliary_explicit_cancellation.py — four assert elapsed < 0.75
  • tests/agent/test_memory_async_sync.py:153 — assert elapsed < 0.5
  • tests/hermes_cli/test_kanban_init_lock_bounded.py:69 — assert elapsed < 1.0
  • tests/agent/test_compression_review_76354.py:488 — assert elapsed < idle * 1.8
  • tests/tools/test_async_delegation.py:123 — assert elapsed < 4.0 (already backstopped
    by an active_count() witness, so low priority)

Not for merge

Opening for review only — do not merge.

`assert elapsed < 2.0` made the OS scheduler part of the assertion. Measured on
pristine fork/main with no diff applied, it FAILED at 2.9s. Profiling the window
showed 2.336s of 2.35s was `_snapshot_child_pids` (a ps-based child scan run
before the handshake) — the threshold was dominated by setup cost it was never
meant to measure.

Now asserts the ordering fact the bound stood in for: `_run_stdio` must unwind
BY ITSELF via the inner connect_timeout (task is done, not pending, after a
bounded wait), it raised TimeoutError, and the hanging initialize() was actually
torn down. The 10s wait is a hang-guard 50x the 0.2s connect_timeout, not the
assertion.

RED-proved: removing the `asyncio.wait_for(session.initialize(), ...)` wrapper
(the pre-NousResearch#59349 bug) fails on the new assertion by name. Source mutation
reverted; this diff is test-only.

Side effect: 4.4s -> 0.9s.
Same family as #438/#534: each asserted a *non-blocking* property by measuring
elapsed real time, which makes the OS scheduler part of the assertion.

- tests/acp_adapter/test_acp_mcp_discovery.py  `elapsed < 0.2`
- tests/hermes_cli/test_mcp_startup.py         `elapsed < 0.2`
- tests/hermes_cli/test_update_check.py        `elapsed < 1.0`
- tests/hermes_cli/test_api_key_providers.py   `elapsed < 1.5` (vs a 2.0s sleep)

Each now uses the #438 witness shape: an `entered` Event proving the background
work really started, and a `returned` Event set in a `finally` on every exit
path, asserted UNSET when the caller returns. That is the ordering fact the
bound stood in for — the work is still in flight, so the caller cannot have
waited on it.

Side effect: removing the fixed sleeps drops these four files from 70.9s to
9.3s.
…ssion fails fast

The stub's `stop.wait()` had no timeout. Under the inline-discovery mutation
that RED-proves this test, the caller blocked forever inside the stub, so the
suite HUNG instead of failing on the witness. A witness that can only be
reached by hanging is not a gate. 10s is orders of magnitude above the real
rendezvous and finite, so the regression now fails fast.
@Kyzcreig
Kyzcreig added this pull request to the merge queue Aug 10, 2026
Merged via the queue into main with commit a1a2052 Aug 10, 2026
42 checks passed
@Kyzcreig
Kyzcreig deleted the tests-wallclock-438b branch August 10, 2026 05:07
@Kyzcreig
Kyzcreig restored the tests-wallclock-438b branch September 21, 2026 10:32
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant