fix(mcplocal): bounded, legible MCP failures — no request can hang forever #127
Reference in New Issue
Block a user
Delete Branch "fix/bounded-mcp-failures"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Why
An agent asked to "find notes and update" updated a Docmost page, then called
docmost_searchand hung for 1800s. It happened four times across sessions. Every investigation concluded "Docmost transport fault" and one wrote that into a status note. It was never Docmost.Measured from inside the pod: Docmost answers
/searchin 203ms. Through mcplocal on a fresh session: 461ms. Across 9,600 MCP requests in the journal, exactly three were ever accepted and never answered — all threePOST /projects/docmost/mcp, each followed immediately by[llm-adapter] … trying nextand[paginate] Smart page titles failed.Root cause:
stages/paginate.ts:72awaitedctx.llm.complete()with no timeout. Itstry/catchcatches errors; a hang is not an error.docmost_searchreturns ~14kB and crosses the pagination threshold,update_pagereturns a small ack and does not — so one tool paginated, one did not, and only the paginating one could hang.docs/reliability.mdhad stated the rule all along and listed only the gate andllm/pagination.tsas compliant. The newer stages never joined the list.A second, independent fault shared the symptom: an unknown
mcp-session-idreturned a bare 404 outside the JSON-RPC envelope. 3.5ms server-side; 1800s client-side, because the client cannot correlate a response with no id.What changed
Nothing optional is unbounded. The budget lives in
LLMProviderAdapter.complete(), not at call sites, so an unwrapped stage is still bounded and future stages inherit it. One budget spans the whole failover chain — per-provider timeouts would have made the worst caseN × timeout.Stage budgets.
summarize-treerecurses (maxDepth3) and loops per section at every level, so a per-call cap multiplies rather than bounds. One budget is shared across the recursion; a warm cache is never budget-gated.Every request answers. The SDK does not await
onmessage, so a throw was an unhandled rejection and a hang was silence — both on an already-hijacked socket.tools/callfailures return a result withisErrorand readable recovery text; other methods get-32001. The pause queue suspends the clock rather than being exempted (with a test that it re-arms, so the exemption cannot become a bypass).Stale sessions recreate, keeping the client's id, and say so via the established
⚠notice. TheFST_ERR_CTP_EMPTY_JSON_BODYDELETE bug is fixed in the same change — it was manufacturing the stale sessions it works around.Trace codes.
correlationIdexisted and was inert:emitTracedropped it,ExecuteOptions.correlationIdwas dead code, every durable row wasnull. The trace code now is the correlationId (no migration — nothing parsed the old form), reaching plugins and stages viaAsyncLocalStorage.mcpctl trace <code>renders the waterfall.Anthropic models auto-follow.
claude-opus-4-20250514was 404ing on every gate ranking and pagination title; the fast tier's pin was dead too. The provider claimed "Anthropic doesn't have a models listing endpoint" — it does.claude-<family>-latestnow resolves against it, bycreated_at(not version parsing:claude-opus-4-5sorts aboveclaude-opus-5).Verified live
docmost_search⚠ Smart page titles unavailable (…404: claude-opus-4-20250514)tool_call_trace+pipeline_execution+ 2×stage_executionall sharing9Q77WKZWmcpctl traceslowest: paginate (252ms)⚠and a trace code2,800 tests pass. No new lint errors. Plus smoke tests in
tests/smoke/bounded-failures.smoke.test.ts.Notes for review
project-mcp-endpoint.test.ts's "returns 404 for unknown session ID" inverts — that 404 was the bug.providers.test.tspinned a hardcoded list of models that are now all retired.session-adopt.tstouches SDK internals deliberately and fails loudly; its test is the canary for SDK upgrades.🤖 Generated with Claude Code
https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2
docs/reliability.md has stated the rule since it was written: "LLM-optional operations must be time-bounded, fall back deterministically, and report the degradation". The gate and llm/pagination.ts obey it. The newer proxymodel stages never adopted it -- stages/paginate.ts:72 awaited ctx.llm.complete() with no timeout and no signal, and its try/catch caught errors, not hangs. So when a provider hung rather than erroring, the promise never settled, the tool call never returned, mcplocal never wrote to the already-hijacked socket, and the client waited out its own 1800s timeout. In the journal that is three POST /projects/docmost/mcp requests accepted and never answered -- the only three such requests in 9,600 across every project, each followed immediately by [llm-adapter] "trying next" and [paginate] "Smart page titles failed". It read as a Docmost transport fault for two sessions. It was neither: Docmost answers /search in 203ms, and through mcplocal on a fresh session in 461ms. docmost_search returns ~14KB and crosses the pagination threshold; update_page returns a small ack and does not. One tool paginated, one did not, and only the paginating one could hang. Bound it centrally in the adapter rather than at each call site, so a stage that passes no options is still bounded and a stage written next year inherits the guarantee: - LLMCompleteOptions gains optional budgetMs/perCallTimeoutMs/signal. Optional matters -- seven inline stubs implement LLMProvider structurally and a required member would break every one. - LLMProviderAdapter.complete() runs one budget with a deadline across the whole failover chain, each attempt capped at min(perCall, remaining). A per-provider timeout would have made the worst case N x timeout; wrapping the method would have killed failover mid-chain. - Every attempt now gets a real AbortSignal. anthropic and openai (which back vllm) honour it; deepseek/ollama/gemini ignore it, and withTimeout's race unblocks the caller anyway -- exactly what its doc comment anticipated. - A caller abort stops failover: if nobody is waiting, don't burn the chain. util/degrade.ts generalises the gate's bounded -> fallback -> loud log -> degradedReason pattern into bounded(), which cannot throw, so the deterministic fallback is unconditional rather than something a catch block must remember. gate.ts is refactored onto it; plugin-gate and router-gate pass UNMODIFIED (61 tests), which is the proof the generalisation is faithful. anySignal() rather than AbortSignal.any: that landed in Node 20.3 and package.json declares >=20.0.0. proxymodel-llm-adapter.test.ts now asserts signal: expect.any(AbortSignal) -- every provider attempt being cancellable is the guarantee, so it is pinned. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2A per-call timeout bounds one call. It does not bound a stage that calls the LLM in a loop -- and summarize-tree does worse than loop: buildTree recurses to maxDepth (3 by default) and iterates per section at every level, then groupSections iterates again. Hundreds of sequential calls are reachable, so a 10s per-call cap is a multiplier, not a bound. StageBudget is one wall-clock budget shared across everything a single stage invocation does. Once it is gone the stage takes its deterministic path -- first-line excerpts, numbered pages -- and says so. The executor builds one per stage from config.budgetMs ?? MCPCTL_STAGE_LLM_BUDGET_MS (30s) and disposes it in a finally, so a long-lived mcplocal never accumulates timers. Two details that matter more than they look: - A warm cache is never budget-gated. cachedSummarize and generatePageTitles used ctx.cache.getOrCompute, which makes the budget check impossible to place correctly; split into get/set so a cached summary -- which costs nothing -- is still returned when the budget is spent. - "No LLM configured" is NOT a degradation. It is a deliberate choice, and numbered pages are the expected output there, so it gets no warning. Only failures, timeouts and exhausted budgets do. Crying wolf on a working configuration would train people to ignore the notice. summarize-tree's single-block path previously had no try/catch at all, so a failure escaped the stage entirely and executor.ts discarded the whole stage's work. It now degrades like the others. Degradation is reported three ways, all from util/degrade.ts: the reason in the content behind the established "⚠ <feature> unavailable (<reason>)" prefix, the count of affected sections (the recursion can hit one exhausted budget dozens of times, so the user needs the reason once plus what it cost), and degraded/degradedReason on the stage_execution audit event -- previously a degradation was invisible in the trace. docs/reliability.md now names ONE helper rather than a list of compliant call sites. That list is exactly how this drifted: the doc named the gate and llm/pagination.ts, and the newer stages never joined it. Tests: the 20-section recursion completes in ~300ms against a 300ms budget; a warm cache still serves real titles with the budget exhausted. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2The plumbing for request tracing was all present and almost entirely inert. correlationId was generated at the endpoint and threaded into traffic events, but: - emitTrace() dropped it, so every durable tool_call_trace row had correlationId = null and could not be joined to anything; - ExecuteOptions.correlationId existed but its only production caller never passed it, making every stage_execution and pipeline_execution row unjoinable too -- dead code that looked like a feature; - plugin events (all three gate emits) had no access to it at all; - and the value itself was `<session-uuid>:<jsonrpc-id>`, which nobody can retype from a screenshot. Also fixed: onToolCallBefore intercepts returned without emitTrace, so every tool call made while a session was gated produced no trace whatsoever. The trace code now IS the correlationId. Nothing parses the old format -- checked across mcpd's audit repository and route, mcplocal's router and traffic capture, and the CLI console -- sessionId is its own audit column and the JSON-RPC id is in the traffic body, so nothing is lost. AuditEvent.correlationId is already an indexed Postgres column, so lookup works with no migration. 8 chars of Crockford base32 without I/L/O/U: readable aloud, typeable from a screenshot, 40 bits (a collision shows two traces, it corrupts nothing). Getting it to the plugins and the executor needed AsyncLocalStorage, not a parameter. Both are constructed per SESSION, not per request -- processContent is a closure with no RouteContext -- so threading an argument would have touched PluginSessionContext, every plugin, ExecuteOptions and StageContext. ALS also stays correct with two requests in flight on one session, which a mutable field on the session-scoped context would not; there is a test for exactly that. PluginContextImpl.emitAuditEvent auto-fills it the way it already auto-fills sessionId, so this covers every gate event and every plugin written later without a per-callsite edit. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2Second of the two faults that both presented as a 1800s hang. mcplocal keeps MCP sessions in memory only, so any restart -- a deploy, an RPM install, scripts/release.sh -- invalidates every connected client's session id. The response was a bare 404 {"error":"Session not found"}: 3.5ms server-side, but it lands OUTSIDE the JSON-RPC envelope with no id, so the client cannot correlate it to its request and simply waits out its own timeout. Every mcpctl tool call in that session became a 30-minute stall while the server was perfectly healthy and answering other traffic in milliseconds. Now the session is recreated, keeping the id the client already holds -- a re-handshake would change it and invalidate everything the client has cached. The SDK assigns sessionId/_initialized only while handling an `initialize` (webStandardStreamableHttp.js:419-420), so adoptSession() replays exactly those two assignments. It reaches into SDK internals, so it fails LOUDLY: the guard throws with a pointer to itself, and session-adopt.test.ts is the canary that goes red at `pnpm test` rather than in production on the next SDK bump. Recreation is not silent. Doing it quietly would hand an agent an ungated tool list with no signal that its gate state had vanished, so the first tools/call result carries the established "⚠ Session state unavailable (...)" notice telling it to call begin_session again. onsessioninitialized does NOT fire on the adopt path, so its body is factored into registerSession() and called explicitly. That is the subtle part: skipping it would have produced recreated sessions with null userName on every audit event, silently. Also fixed, and it is the CAUSE rather than the symptom: MCP clients close a session with DELETE + Content-Type: application/json and an empty body, which Fastify's default parser rejected with FST_ERR_CTP_EMPTY_JSON_BODY before the route handler ran. sessions.delete() therefore never happened and every "closed" session leaked -- manufacturing the stale-session condition this commit handles. Fixing recreation without fixing teardown would have shipped the workaround and kept the cause. project-mcp-endpoint.test.ts's "returns 404 for unknown session ID" inverts to "recreates an unknown session instead of 404ing it", and asserts the id comes back unchanged. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2