1 commit

Author	SHA1	Message	Date
Patrick A	17cdb185bc	fix(proxy): graceful shutdown and reliable Ctrl+C exit (#621) ... ## Problems ### 1. Noisy CancelledError traceback on Ctrl+C Every Ctrl+C produced one or more "Exception in ASGI application" ERROR log entries with a CancelledError traceback: ``` ERROR: Exception in ASGI application Traceback (most recent call last): ... File "uvicorn/protocols/http/h11_impl.py", line 410, in run_asgi result = await app(...) ... asyncio.exceptions.CancelledError ``` ### 2. Inconsistent / hung shutdown in multi-worker mode (`--workers 8`) Workers blocked in a C-extension call (hnswlib, tree-sitter, ONNX inference) could prevent Ctrl+C from completing because `timeout_graceful_shutdown` defaulted to `None` (wait forever). --- ## Root causes **Root cause A (CancelledError noise)** uvicorn 0.40.0's `h11_impl.run_asgi()` (line 413) catches `BaseException` — not just `Exception` — so `asyncio.CancelledError` raised on every in-flight request at shutdown is unconditionally logged as `ERROR: Exception in ASGI application`. This is expected behaviour during shutdown, not a bug. **Root cause B (hung multi-worker shutdown)** `uvicorn.run()` was called without `timeout_graceful_shutdown`, which defaults to `None`. This means the supervisor waits indefinitely for in-flight requests to drain. A single request blocked in a C-extension (e.g. hnswlib nearest-neighbour search, tree-sitter parse, ONNX inference) prevents the whole process group from exiting. **Root cause C (hung single-worker shutdown — lifespan unbounded awaits)** The lifespan `finally` block contained unbounded `await` calls to `_beacon.stop()`, `proxy.usage_reporter.stop()`, `proxy.traffic_learner.stop()`, and `proxy.shutdown()`. uvicorn's `lifespan.shutdown()` calls `await self.shutdown_event.wait()` with no timeout — that event is only set once the lifespan `finally` block returns. Any of these awaits hanging (e.g. a reporter making a network call) therefore requires a second Ctrl+C to force-exit. --- ## Changes ### `headroom/proxy/server.py` 1. **`_SuppressCancelledErrorFilter`** (new class, ~10 lines): a `logging.Filter` that returns `False` for ERROR records on `uvicorn.error` whose `exc_info[0]` is a subclass of `asyncio.CancelledError`. Installed on `logging.getLogger("uvicorn.error")` at the start of `run_server()`. 2. **`timeout_graceful_shutdown=10`** added to `uvicorn.run()`: forces cancellation of any tasks still running 10 seconds after the shutdown signal, ensuring workers blocked in C-extensions are reaped promptly. 3. **Bounded awaits in lifespan `finally` block**: a local `_timed(coro, label, timeout)` helper wraps each shutdown step with `asyncio.wait_for()`. Timeouts: beacon.stop 3s, usage_reporter.stop 3s, traffic_learner.stop 3s, proxy.shutdown 5s. Each step logs a warning on timeout/error and continues — the teardown path is now deterministic and completes within ~15s on a single Ctrl+C. 4. **Shutdown log message** in the lifespan `finally` block: `event=proxy_shutdown reason=signal pid=<n>` is logged as the first action on teardown. ### `tests/test_graceful_shutdown.py` (new) 9 tests: - 6 unit tests for `_SuppressCancelledErrorFilter` (suppresses CancelledError at ERROR level, passes through WARNING-level CancelledError, passes through other exceptions, handles `exc_info=None`, handles `(None,None,None)` tuple, suppresses subclasses) - 1 integration test: `run_server()` installs the filter on `uvicorn.error` - 1 integration test: `run_server()` passes `timeout_graceful_shutdown=10` to `uvicorn.run()` - 1 integration test: lifespan emits `event=proxy_shutdown` on teardown --- ## Files changed - `headroom/proxy/server.py` — filter class, bounded lifespan awaits, graceful shutdown timeout - `tests/test_graceful_shutdown.py` (new) — 9 tests - `uv.lock` — dependency lockfile updated (routine sync, no dependency changes) - `CHANGELOG.md` — changelog entry --- ## How to verify 1. Start the proxy: `headroom proxy --port 8787 --workers 8 --memory --code-aware ...` 2. Press Ctrl+C 3. Before: ERROR traceback for each in-flight request; second Ctrl+C sometimes required 4. After: clean `event=proxy_shutdown reason=signal pid=...` log, then process exits within ~15s regardless of stuck C-extensions or slow reporters --------- Co-authored-by: JD Davis <jd@jds-macbook-air.tail2a279.ts.net>	2026-08-05 22:33:34 -05:00