tests/runtime: TestRemoteEmitterReachesDispatch (SSE) intermittently hangs in CI until the 25-minute job timeout #200

Activity

1. ViperJuice commented on Aug 27, 2026

   

   ViperJuice

   on Aug 27, 2026

   CollaboratorAuthor

   More actions

   Closing — I filed this on a subagent's report without reproducing it, and it does not reproduce. Both premises are wrong.

   Measured on main at 3413db4 (v2.6.0):

   run	result
   pytest tests/runtime	60 passed in 75s
   pytest tests/runtime/test_downstream_stdio.py	2 passed in 0.96s
   pytest -q (full suite, runtime included)	3189 passed, 3 skipped, 25 deselected in 6m33s

   No hang, standalone or under the full suite — so it is not cross-test pollution either.

   Where the "8 deselected" came from. Not from CI or config: it was the reporting agent's own -k "not stdio" filter, which it applied because it believed those tests hang. Confirmed:

   pytest tests/runtime --collect-only          -> 60 tests collected, 0 deselected
   pytest tests/runtime -k "not stdio" --collect-only -> 52/60 collected (8 deselected)
   

   tests/runtime contains zero live-marked tests, and the config's only deselector is -m 'not live'. So the claim that CI hides these tests is false — nothing is being silently excluded, and there is no gap in the verification story.

   The 25 deselected in the full run are live-marked opt-in integration tests elsewhere in the suite, which is their intended behaviour.

   I have not reproduced the environment in which the original hang was observed, so I cannot say the reporter saw nothing — a transient stdio-harness stall on a loaded host is plausible. But there is no evidence of a standing defect, and an open issue asserting one is worse than no issue. If it recurs, reopen with the exact command and the pytest -q output rather than a filtered run.
2. ViperJuice

   closed this as completedon Aug 27, 2026
3. ViperJuice

   reopened this on Sep 1, 2026
4. ViperJuice commented on Sep 1, 2026

   

   ViperJuice

   on Sep 1, 2026

   CollaboratorAuthor

   More actions

   Reopening with CI evidence — the earlier close was right that the stdio tests don't hang and that nothing is deselected, but the class is real: the remote/SSE emitter-harness tests intermittently hang in CI until timeout-minutes: 25 kills the job (GitHub reports it as cancelled, not failed, so it never showed as a red X on the file).

   Every timed-out test (3.x) job on main in the last two weeks stalled inside tests/runtime/test_emitter_harness.py::TestRemoteEmitterReachesDispatch, at 3% of the suite, with the last PASSED line being:

   run	date	job	last test that passed before the 24-minute silence
   32930058835	2026-08-26	test (3.11)	test_add_tool_then_emit_reaches_read_sse
   33240369148	2026-08-29	test (3.10)	test_unrecognised_method_reaches_read_sse
   33270684206	2026-08-29	test (3.10)	test_unrecognised_method_reaches_read_sse
   33343639560	2026-08-31	test (3.11)	test_add_tool_then_emit_reaches_read_sse
   33532264811	2026-09-01	test (3.12), PR #220	test_unrecognised_method_reaches_read_sse

   So the hanging test is the next one in collection order each time — test_emit_alone_reaches_read_sse or test_remove_tool_then_emit_reaches_read_sse — and the job log ends with Terminate orphan process: pid (…) (pytest). The other two matrix jobs on the same commit pass in 4–5 min, and re-running the job passes, so it is order/timing-dependent, not deterministic. Same uv (0.12.8) in hung and passing runs; unrelated to any dependency bump.

   Working hypothesis (unverified): the sse_starlette process-global AppStatus.should_exit_event latch — once set by an earlier SSE test's shutdown on a different event loop, a later read_sse waits forever. Local runs of tests/runtime alone pass (that is what the earlier close measured), which is consistent with the latch being set by something earlier in the full-suite order.

   Suggested fix: a per-test pytest-timeout (or an asyncio.wait_for) on the SSE reads in this harness so a hang is a failure with a traceback in seconds instead of a 25-minute cancel; then reset the latch (AppStatus.should_exit_event = None) in the harness fixture if the hypothesis holds.
5. ViperJuice

   changed the title [-]tests/runtime: stdio-harness tests hang (8 tests, pre-existing)[/-] [+]tests/runtime: TestRemoteEmitterReachesDispatch (SSE) intermittently hangs in CI until the 25-minute job timeout[/+] on Sep 1, 2026
6. ViperJuice commented on Sep 2, 2026

   

   ViperJuice

   on Sep 2, 2026

   CollaboratorAuthor

   More actions

   Correction to my earlier comment in this issue, and stage 1 is up as #223.

   My earlier suggestion here — reset AppStatus.should_exit_event = None — cannot be implemented as written. It describes an older sse_starlette. The installed version is 3.1.1, and vars(AppStatus) there is exactly:

   {should_exit: False, original_handler: <function Server.handle_exit>, handle_exit: <staticmethod>}
   

   There is no should_exit_event. The 3.1.1 mechanism is different in two ways that matter:

   1. A per-event-loop _ShutdownState held in a contextvars.ContextVar — so an event registered on one loop is never signalled by a watcher on another.
   2. _get_uvicorn_server(), which reads signal.getsignal(signal.SIGTERM).__self__ and polls that object's should_exit — so a stale SIGTERM handler left behind by an earlier uvicorn server can make a later loop's watcher see should_exit == True.

   Both are plausible paths to a stuck stream. Neither is verified, which is exactly why #223 instruments rather than fixes. (Checked in two venvs, py 3.10.12 and py 3.14.7; both resolve 3.1.1 and neither sse.py contains threading.local.)

   The process-global AppStatus.should_exit class attribute, and run_fake_remote's reset of it, are unaffected by the version correction — both are still exactly as described. The stale module comments in tests/runtime/fake_remote.py and tests/runtime/test_downstream_remote.py are corrected in #223.

   ---

   #223 ships stage 1 only: diagnostics. It does not fix the hang, and touches nothing under src/. A stall now produces a stack dump at 2 minutes and a hard failure at ~11.7 minutes, instead of 25 minutes of silence reported as "cancelled":

   • faulthandler_timeout = 120 — dumps every thread's stack and lets the run continue.
   • timeout = 700, timeout_method = "signal" via pytest-timeout. signal was selected empirically over thread: both cover fixture teardown, but thread os._exits the session and loses the rest of the run.
   • run_fake_remote's unbounded await task is bounded, and reports whether the serve() task survived cancellation — the one fact no stack dump can give you, since an idle loop parked in epoll.poll() names nothing.

   One thing worth flagging for whoever picks up stage 2: "the next test hangs" is an inference, not a finding. pytest prints PASSED when the test function returns, before teardown. With asyncio_mode = "auto", pytest-asyncio then tears the loop down, and an async generator that ignores cancellation hangs there — producing a log indistinguishable from "the next test hung". The _tap() spy at test_emitter_harness.py:65 is itself an async generator wrapped around the SSE read stream, so the just-passed test's teardown is a live candidate. That is why the teardown-coverage half of #223 is the half that matters.

   Stage 2 is filed separately and starts when an occurrence produces a traceback.
7. ViperJuice

   added 2 commits that reference this issue on Sep 2, 2026

   test(runtime): dump asyncio task stacks so an async hang names its aw…

   ...

   3d89d88

   test(runtime): make a hang fail fast with a traceback instead of a 25…

   ...

   274d3c2
8. ViperJuice commented on Sep 2, 2026

   

   ViperJuice

   on Sep 2, 2026

   CollaboratorAuthor

   More actions

   Closed by #223 (merged as 274d3c2) — stage 1 only, as scoped.

   A hang in tests/runtime is now a fast, named failure instead of a 25-minute silent job cancel: a bounded stop sequence in run_fake_remote (10s + 5s cancel grace, using asyncio.wait — wait_for cannot bound a cancellation-resistant task), an asyncio task-stack watchdog at 60s that walks the cr_await/ag_await chain (neither faulthandler nor pytest-timeout can see a suspended coroutine — both bottom out in epoll.poll), faulthandler_timeout = 120, and pytest-timeout at 700s with timeout_method = "signal" chosen by an empirical teardown-coverage proof. Nine tests pin all of it in both directions; evidence in .consiliency/evidence/hang-diagnostics-200.md.

   It worked on its first CI run and produced the traceback this issue existed to capture — posted to #224, which carries the root cause from here. Two things it settled: the server is not cancellation-resistant (it ends the moment it is cancelled) but will not drain, because uvicorn.Config here has no timeout_graceful_shutdown; and underneath it the SSE transport dies mid-stream with unhandled errors in a TaskGroup (1 sub-exception) whose sub-exception is swallowed at five call sites.

   Correcting my own earlier comment on this issue for the record: the should_exit_event hypothesis was wrong (3.1.1 has no such attribute), and "the next test hangs" was an inference, not a finding — the failure landed on the 4th test of TestRemoteEmitterReachesDispatch, while 3 of the 5 recorded stalls name the 3rd as their last PASSED.
9. ViperJuice

   closed this as completedon Sep 2, 2026
10. ViperJuice

    added a commit that references this issue on Sep 3, 2026

    fix(client): name the cause inside an exception group in every log (see

    ...

    fed8716
11. ViperJuice

    added a commit that references this issue on Oct 1, 2026

    test: put faulthandler above the kill, exit on it, and stop the root-…

    ...

    9401f06