Skip to content

fix(mcp): a slow log stream can no longer stop the server - #64

Merged
Gintm merged 5 commits into
developfrom
fix/mcp-nonblocking-logs
Nov 4, 2026
Merged

Gintm merged 5 commits into
developfrom
fix/mcp-nonblocking-logs

Conversation

@Gintm

@Gintm Gintm commented Nov 4, 2026 •

Copy link
Copy Markdown
Contributor

Why

Log writes ran on the event loop, so a blocked stdout froze every request. On Nov 4 from 13:03 to 13:28 UTC, a container whose Railway logs lagged up to 13 minutes dropped to 10-20% of its normal calls and timed out on /health until a redeploy replaced it. Client disconnects then wrote long tracebacks, which added to the backlog.

What

  • All logging on the HTTP server goes through a background thread and a bounded queue (10,000 records). When the stream stays blocked, records are dropped and a Dropped N log records line appears once it recovers.
  • On SIGTERM or SIGINT the server waits up to 2 seconds for queued logs, then exits. Ctrl-C no longer prints a traceback.
  • Client disconnects are no longer logged as error tracebacks (about 50 lines each before). The filter already existed in zernio-mcp and never reached this repo.
  • Version 1.2.3. STDIO mode is unchanged.

Verified

Installed as the Dockerfile does, real server, local stub API, mix of successful calls, tool errors, unknown tools, bad arguments and 401s.

Scenario Result
Stdout blocked, before this PR 328, 12, 0, 0 calls per 10 s; /health times out
Stdout and stderr blocked for 130 s 1,479 to 2,335 calls per 10 s; /health at most 0.68 s, no timeouts
Only stdout or only stderr blocked for 20 s no errors, no /health timeouts
Stream recovers after 70 s blocked Dropped 35961 log records appears, no logging errors
SIGTERM, stream healthy Application shutdown complete is logged, exit 143
SIGTERM, stream blocked exits in 2.2 s
20 real client disconnects 0 traceback lines (80 on develop, about 1,000 log lines)
Port in use exit 1, error visible
Memory over about 22,000 requests 361 MB, 360 MB on develop

Also 26 of 26 end-to-end checks, including /chatgpt, legacy SSE and Sentry envelopes.

Not verified on Railway. The log lag and the stall coincide, but the pipe blocking there is inferred, not observed. After merging, a log lag should show up as Dropped N log records instead of a stall. If the server stalls with no such line, the cause is something else.

Follow-ups

  • SENTRY_DSN is missing in Railway production (only zernio-mcp-dev has it).
  • Memory grows about 2 MB per 1,000 requests on develop too, and the frequent regen redeploys hide it.

🤖 Generated with Claude Code

Gintm and others added 5 commits November 4, 2026 16:04
Log writes ran on the event loop, so a blocked stdout froze every request.
On Nov 4 a container whose Railway logs lagged 13 minutes dropped to 10-20%
of its calls and timed out on /health until a redeploy replaced it.

- Write all logs from a background thread through a bounded queue. When the
  stream stays blocked, records are dropped and counted instead of blocking.
- Stop logging client disconnects as error tracebacks, which fed the backlog.

Co-Authored-By: Claude Opus 5.5 <[email protected]>
SIGTERM killed the process with records still queued, so every redeploy lost
its last log lines. Drain for up to 2 seconds before exiting on SIGTERM or
SIGINT, which also removes the Ctrl-C traceback.

The drop notice went through the last handler used. Most often that is
uvicorn's access handler, whose format rejects a record without its arguments,
so the notice never appeared. It now has its own handler.

Co-Authored-By: Claude Opus 5.5 <[email protected]>
@Gintm
Gintm merged commit ead37f0 into develop Nov 4, 2026
4 checks passed
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