Skip to content

test(runtime): make a hang fail fast with a traceback instead of a 25-minute cancel (see #200) - #223

Merged
ViperJuice merged 5 commits into
mainfrom
fix/200-sse-hang-diagnostics
Sep 2, 2026
Merged

ViperJuice merged 5 commits into
mainfrom
fix/200-sse-hang-diagnostics

Conversation

@ViperJuice

@ViperJuice ViperJuice commented Sep 2, 2026 •

Copy link
Copy Markdown
Collaborator

Stage 1 of #200: diagnostics only.

Five test (3.x) jobs in the week to 2026-09-01 stalled inside
tests/runtime/test_emitter_harness.py and were killed by the job's
timeout-minutes: 25. GitHub reports a timed-out job as cancelled, not failed,
so not one of them produced a red X, a traceback, or a single line of evidence
about which await was stuck.

This does not fix the hang. The root cause is not known, and a fix chosen now
would be a guess frozen into the suite — the failure class this repo has hit
before. No file under src/ is touched (git diff --name-only origin/main..HEAD -- src/ is empty). Stage 2 is filed separately and starts when an occurrence
produces the traceback this change exists to capture.

What ships

pyproject.toml — faulthandler_timeout = 120 (the zero-risk half: it kills
nothing, it dumps every thread's stack and lets the run continue) plus
timeout = 700 / timeout_method = "signal" via pytest-timeout, newly declared
in the dev extra and locked. Both numbers derive from --durations=25 measured
in this change: the slowest non-live test is 60.25 s, so the dump lands
~9.7 minutes before the kill and both sit well inside the 25-minute job cap.

tests/runtime/fake_remote.py — run_fake_remote's unbounded await task
is bounded and now raises a message naming the port, server.started,
server.should_exit, AppStatus.should_exit, and whether the serve() task
survived cancellation
— the single most valuable fact for stage 2, and one no
stack dump reports, since an idle loop parked in epoll.poll() names nothing.

Deliberately not asyncio.wait_for: it cancels and then waits for the
cancellation to finish, so a serve() that swallows CancelledError hangs it
exactly as hard as the bare await it replaces. The AppStatus.should_exit
reset moves into a nested unconditional finally — it used to sit after
await task, so the new raise would have skipped it and poisoned the next test.

tests/runtime/test_hang_diagnostics.py — six proofs. "The suite no longer
hangs" passes on unchanged main, so each one induces a hang deterministically
and asserts the diagnostic fires, mutant-style:

  • two serve() mutants — one that never returns, one that swallows
    CancelledError
    . The second is the one that matters: a wait_for-based
    implementation passes the first and hangs on the second.
  • a subprocess whose fixture teardown blocks 30 s, proven caught with the
    plugin (non-zero in ~3.4 s) and not caught with -p no:timeout (still
    running when killed at 10 s, exit 124). Teardown coverage is the whole point:
    pytest prints PASSED when the test function returns, before teardown, so
    the likeliest hang site is after the last PASSED line in those five logs.
  • a faulthandler run proving the dump fires, the sentinel test after it still
    runs, and pytest exits 0.

Full transcript with exit codes: .consiliency/evidence/hang-diagnostics-200.md.

timeout_method was selected, not assumed

Both signal and thread cover teardown, so the plan's fallback ("accept
thread if only it passes") was not needed. signal is strictly better on the
axis that separates them: it reports a normal pytest ERROR with the offending
frame and the session continues to a summary, whereas thread hard-exits the
process mid-report and loses the rest of the run.

Two deviations from the plan, stated deliberately

  1. timeout = 700, not the plan's literal 600. The plan also requires
    "≥ 10× the slowest non-live test as measured in this change". The slowest is
    60.25 s, so 600 is 9.96× and fails that bar. (The plan's own figure of 60.06 s
    already made 10× = 600.6 > 600.) The criterion wins.
  2. The "19 deselected / 1019 collected" criterion is rev-1 residue,
    contradicted by the plan's own research section ("3386 passed, 3 skipped,
    25 deselected"). Measured on the unmodified tree: 3389/3414, 25 deselected.
    The criterion's structure is satisfied against the real baseline.

Verification

command result
pytest -q tests/runtime/test_hang_diagnostics.py 6 passed in 43.89s, exit 0
pytest -q tests/runtime 66 passed (60 pre-existing + 6 new), exit 0
pytest --collect-only -q tests/ 3395/3420, 25 deselected (was 3389/3414, 25)
ruff check / ruff format --check clean / 129 files formatted, exit 0
mypy src/ no issues in 43 files, exit 0
scripts/check_workflows.py --base-ref origin/main workflow guards: OK, exit 0

Full suite, same command from the same directory both sides:

before: 107 failed, 3173 passed, 3 skipped, 25 deselected, 106 errors in 349.49s
after:  107 failed, 3179 passed, 3 skipped, 25 deselected, 106 errors in 369.69s

Passes +6 (exactly the new tests); failures, skips, deselections and errors
unchanged. The 107/106 are a host quirk, not a regression: /tmp/package.json
exists on this machine and the npm identity resolver's localPrefix walk finds
it, documented in tests/conftest.py. Identical on both sides.

No CHANGELOG.md entry: the changelog job requires one only for src/ changes.

Correction to the record

The installed sse_starlette is 3.1.1, whose AppStatus is exactly
{should_exit, original_handler, handle_exit} — there is no
should_exit_event
, so the fix floated in #200's early comment ("reset
should_exit_event = None") cannot be written as stated. 3.1.1 keeps a
per-event-loop _ShutdownState in a contextvars.ContextVar, and
_get_uvicorn_server() reads signal.getsignal(signal.SIGTERM).__self__ and
polls that object's should_exit. The stale comments in fake_remote.py and
test_downstream_remote.py are corrected here.

🤖 Generated with Claude Code

https://claude.ai/code/session_01GaTMt2NiBUwqhMoTYzTmQh


View with [code]smith Autofix with [code]smith
Need help on this PR? Tag @codesmith-bot with what you need. Autofix is disabled.


Update (3d89d88): async hangs now name their await

The board on the first cut found — and I confirmed empirically — that every proof here induced a synchronous hang (time.sleep), where a signal traceback trivially names the line. The suspected real hang is a suspended coroutine, whose frames live in Task objects, not on any thread stack. A test awaiting an Event through two coroutine frames, killed by pytest-timeout, reported only:

asyncio/base_events.py:2019: in _run_once
selectors.py:452: in select
>   fd_event_list = self._selector.poll(timeout, max_ev)
E   Failed: Timeout (>3.0s) from pytest-timeout.

epoll.poll — invisible. Without this the PR would have turned a 25-minute cancel into a 700-second failure that still could not tell _tap() from connect_server() from disconnect_all().

tests/runtime/_hang_watchdog.py: one session daemon thread, armed from pytest_runtest_logstart so the window covers teardown, dumping every pending task on the item's loop at 60 s — strictly below faulthandler_timeout = 120 and the 700 s kill. It walks the cr_await/ag_await chain rather than relying on Task.print_stack(), because get_stack() returns a single frame for a suspended coroutine, and an async for suspends on an async_generator_asend that exposes no frame at all — which is exactly the shape of _tap(), the prime suspect. Every path swallows; the worst case is silence.

Scoped to tests/runtime/ deliberately: all five CI stalls happened there, its slowest item is 26.16 s against the 60 s threshold, and at tests/ scope the two 60.2 s progressive-disclosure tests would trip a spurious dump on essentially every run.

Three new proofs, both directions: an async hang does name the awaiting coroutine with the watchdog, does not without it (-p no:...), and the watchdog is actually wired into this package. Verified on this head: test_hang_diagnostics.py 9 passed; tests/runtime 69 passed with zero spurious dumps; ruff, mypy, check_workflows.py all exit 0; collection 3398/3423 (25 deselected).

ViperJuice and others added 4 commits September 2, 2026 05:37
…tant task; count freezes, faulthandler and subprocess-rootdir criteria fixed (#200)
…dler=120) and the /tmp/package.json host quirk (#200)
…-minute cancel (see #200)

Five `test (3.x)` jobs in the week to 2026-09-01 stalled inside
`tests/runtime/test_emitter_harness.py` and were killed by the job's
`timeout-minutes: 25`. GitHub reports a timed-out job as *cancelled*, not
failed, so not one of them produced a red X, a traceback, or a single line
of evidence about which await was stuck.

This is stage 1: diagnostics only. It does not fix the hang. The root cause
is still unknown and a fix chosen now would be a guess frozen into the
suite. No file under `src/` is touched.

- pyproject.toml: `faulthandler_timeout = 120` (dumps every thread's stack
  and lets the run continue) and `timeout = 700` + `timeout_method =
  "signal"` via pytest-timeout, which is newly declared in the `dev` extra
  and locked. Both numbers derive from `--durations=25` in this change:
  the slowest non-`live` test is 60.25s, so the dump lands ~9.7 minutes
  before the kill and both sit well inside the job's 25-minute cap.

- tests/runtime/fake_remote.py: `run_fake_remote`'s unbounded `await task`
  is now bounded, and raises a message naming the port, the server state,
  `AppStatus.should_exit`, and whether the serve() task survived
  cancellation -- the one fact no stack dump can report, since an idle loop
  in `epoll.poll()` names nothing. Deliberately not `asyncio.wait_for`,
  which cancels and then waits for the cancellation to finish and so hangs
  on a cancellation-resistant task exactly as hard as the bare `await`.
  The `AppStatus.should_exit` reset moves into a nested unconditional
  `finally`, because it used to sit after `await task` and the new raise
  would have skipped it.

- tests/runtime/test_hang_diagnostics.py: six proofs, all mutant-style.
  Two induced `serve()` mutants (one that never returns, one that swallows
  `CancelledError` -- the second is what a `wait_for` implementation fails);
  a subprocess whose *fixture teardown* blocks, proven caught with the
  plugin and NOT caught with `-p no:timeout`; and a faulthandler run
  proving the dump fires, the sentinel after it still runs, and pytest
  exits 0.

Two documented deviations from the plan, both in the evidence file:
`timeout = 700` not 600, because 10 x 60.25 = 602.5 and the plan's own
"at least 10x" criterion beats its rounded literal; and the "19 deselected
/ 1019 collected" criterion is rev-1 residue contradicted by the plan's own
research -- the measured baseline is 3389/3414 with 25 deselected, and this
change moves it to 3395/3420 with 25 deselected.

`timeout_method` was selected empirically, not assumed: both `signal` and
`thread` cover teardown, but `thread` `os._exit`s the session and loses the
rest of the run, so `signal` is strictly better and the plan's willingness
to trade the tail away was not needed.

Also corrects two stale comments: the installed sse_starlette is 3.1.1,
whose `AppStatus` has no `should_exit_event`, so the fix floated in #200's
early comment cannot be written as stated.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GaTMt2NiBUwqhMoTYzTmQh
…ait (see #200)

faulthandler and pytest-timeout both dump THREAD stacks, and a suspended
coroutine has no frames there -- they live in Task objects. Verified: a test
awaiting an Event through two coroutine frames reports only

    selectors.py:452: in select
    >   fd_event_list = self._selector.poll(timeout, max_ev)
    E   Failed: Timeout (>3.0s) from pytest-timeout.

so the stuck await was invisible and the change could not have told _tap()
from connect_server() from disconnect_all() -- the whole question it exists
to answer.

_hang_watchdog.py adds one session daemon thread that, at 60s (strictly below
faulthandler's 120s and the 700s kill), dumps every pending task on the item's
loop and walks the cr_await/ag_await chain -- Task.get_stack() returns a single
frame for a suspended coroutine, and an 'async for' suspends on an
async_generator_asend with no frame at all, which is exactly _tap()'s shape.
Armed from logstart so the window covers teardown. Scoped to tests/runtime:
at tests/ scope the two 60.2s progressive-disclosure tests would trip a
spurious dump every run. Three proofs, both directions.
@ViperJuice
ViperJuice merged commit 274d3c2 into main Sep 2, 2026
20 of 23 checks passed
@ViperJuice
ViperJuice deleted the fix/200-sse-hang-diagnostics branch September 2, 2026 15:01
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