fix(mcplocal): bounded, legible MCP failures — no request can hang forever #127
Merged
michal
merged 9 commits from 2026-08-25 23:03:51 +00:00
fix/bounded-mcp-failures into main
9 Commits
| Author | SHA1 | Message | Date | |
|---|---|---|---|---|
| 47d7c779d0 |
feat: per-server tool-call timeout, on the server resource
Some checks failed
CI/CD / typecheck (pull_request) Successful in 1m25s
CI/CD / lint (pull_request) Successful in 2m39s
CI/CD / test (pull_request) Successful in 1m29s
CI/CD / smoke (pull_request) Failing after 3m6s
CI/CD / build (pull_request) Successful in 2m27s
CI/CD / publish (pull_request) Has been skipped
Completes the plan's last item. The deadline shipped with a global default; this makes it overridable per server, where the knowledge actually lives -- a server with genuinely slow tools declares its own budget instead of forcing the global up for everyone. Source of truth is the server resource, following healthCheck exactly: Prisma column + migration (NULL keeps today's behaviour, so no existing server changes), zod validation on create and update, the repository, an `--tool-call-timeout` flag mirroring `--health-check-timeout`, and the apply schema so `apply -f` accepts what `get server -o yaml` emits. That round-trip needed care: get emits `toolCallTimeoutSeconds: null` for every server without an override, so the apply schema is nullable, not merely optional -- otherwise the very first `get -o yaml | apply -f` on an untouched server would have failed validation. Bounded at one hour. A deadline exists so a wedged call answers instead of hanging; a value beyond an hour is indistinguishable from having none. It reaches mcplocal through server discovery rather than the project-scoped serverOverrides map, and is applied on EVERY sync rather than only at first registration -- raising a server's timeout should take effect at the next refresh, not require the upstream to be dropped and rebuilt. The endpoint sees the wire name (`docmost_search`), so it decodes to the canonical `server/tool` before resolving. The override is keyed by server, so every tool on that server inherits it without being enumerated, and the failure message quotes the deadline actually applied rather than the global. Smoke tests (tests/smoke/bounded-failures.smoke.test.ts) cover the two production faults against the live proxy: a stale session recovers instead of stranding the client on an uncorrelatable 404, every request is answered, and `mcpctl trace` responds for an unknown code. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2 |
|||
| 08b451b7aa |
feat(mcplocal): Anthropic models auto-follow the newest in their family
`claude-opus-4-20250514` was pinned as the heavy provider and had been returning 404 on every gate ranking and every pagination title. The only visible symptom was a fallback that looked like an ordinary one -- it surfaced here because the degradation notice added earlier in this branch finally printed the reason. Checked against GET /v1/models: BOTH pins were dead. The fast tier's claude-haiku-3-5-20241022 is gone too, so that tier had been silently 404ing as well. The provider's listModels() asserted "Anthropic doesn't have a models listing endpoint" and returned four hardcoded dated ids. That endpoint does exist and answers fine with the OAuth token this deployment uses; the hardcoded list was simply stale, and a test pinned it in place. So: `claude-<family>-latest` (or a bare `opus` / `sonnet` / `haiku` / `fable`) now resolves against the live list. Exact ids pass through untouched, so pinning still works when someone wants it. Newest is decided by `created_at`, never by parsing the version out of the id. That is not incidental: `claude-opus-4-5` sorts ABOVE `claude-opus-5` as a string, and "4-5" parses as a larger minor than "5". There is a test for exactly that trap. Resolution is cached (12h, MCPCTL_ANTHROPIC_MODEL_TTL_MS) so it is not a per-call network hop, and shared across instances since the model list is account-wide. When the endpoint is unreachable it falls back to a pinned known-good id per family and says so on stderr -- the map going stale can then only cost availability, never correctness. The constructor default was `claude-sonnet-4-20250514`, also retired; it now tracks the family too. Local config: heavy -> claude-opus-latest, fast -> claude-haiku-latest. Verified live: opus-latest -> claude-opus-5, haiku-latest -> claude-haiku-4-5-20251001, sonnet-latest -> claude-sonnet-5, and an exact id passes through. Also found while there: both anthropic entries were named "anthropic", and the registry keys by name, so the second silently OVERWROTE the first and one tier's model was discarded entirely. Renamed to anthropic-fast / anthropic-heavy so NamedProvider keeps them distinct and the tier split is real. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2 |
|||
| 14eb2623bc |
fix(cli): trace's 'slowest' names a step, not the aggregate
tool_call_trace and pipeline_execution are aggregates OF the stages, so letting them compete always named the total and told you nothing. Verified live: now reports 'slowest: paginate (252ms)' rather than 'tool_call_trace (509ms)'. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2 |
|||
| 89db09a12d |
feat(cli): mcpctl trace <code>, and bound the table it reads
The trace codes are now emitted in every deadline message and degradation notice, so they need somewhere to go. `mcpctl trace <code>` queries the audit events mcpd already stores and renders the request as a waterfall: each step with its offset, duration, byte delta, and any ⚠ degradation or ✗ error, then a summary naming the slowest step. No new endpoint was needed -- GET /api/v1/audit/events?correlationId= already existed and correlationId is already an indexed column; it just had nothing writing meaningful values into it until this branch, and nothing reading it. --strict exits non-zero when the trace contains an error or a degraded step, so it composes into scripts. An empty result explains itself rather than printing nothing: batches flush up to 5s late, old requests predate trace codes, and the codes exclude I/L/O/U so a mistyped one is worth calling out. Retention: AuditEvent had no prune at all. That was defensible while the table was write-only; it is not now that a command reads it. Mirrors the AuditLog convention exactly -- POST /api/v1/audit/events/purge, triggered rather than scheduled, guarded by the existing audit-purge RBAC operation so it cannot be granted by accident separately from the log purge. 30 days by default rather than AuditLog's 90: these are several rows per MCP call, not a record of administrative mutations. Note for the plan's sake: I had assumed AuditLog retention was a scheduled job registered in main.ts. It is not -- it is a manual endpoint. Mirroring what the codebase actually does beat inventing a scheduler that exists for neither table. completions are generated, so `trace` is registered in PROJECT_SCOPED_COMMANDS and both shells regenerated; the freshness test passes. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2 |
|||
| b6e270ee48 |
feat(mcplocal): every request answers, even when the pipeline wedges
The LLM budgets bound the failure we actually hit. This is the backstop for the ones they cannot see: a wedged plugin hook, a virtual-tool handler, an upstream path without its own timeout. transport.onmessage IS the whole request pipeline, and it writes to a socket that has already been hijacked from Fastify. The SDK does not await it, so a throw became an unhandled rejection and a hang became silence -- in both cases the client got no response at all and waited out its own timeout. onmessage is now structured so that reaching transport.send() is unconditional: the route call is raced against a deadline, and the notification flush and the send each carry their own catch, so a failure while flushing can no longer cost the client its response. transport.onerror was never assigned, so SDK-level transport errors were swallowed entirely. It is now. Shape of the answer is deliberate. A tools/call comes back as a SUCCESSFUL result with isError and readable text naming the trace code -- the same shape router.ts already uses for an expired _resultId, because a transport error tends to surface as a hard failure while a tool error is something the model reads and acts on. It also says the upstream may still be running, which is true and matters. Other methods get a JSON-RPC error (-32001). MCPLOCAL_TOOLCALL_DEADLINE_MS defaults to TOOLCALL_TIMEOUT_MS + 30s rather than 120s. The watchdog arms earlier in the request than mcpd's fetch does, so at equal values it would always fire first, masking mcpd's specific UpstreamTimeoutError with a generic message and cutting off pagination and the rest of the post-processing. There is a test asserting the two stay ordered. The pause queue is exempt, but not bypassed. It blocks until a human operator releases, edits or drops a response, so the deadline SUSPENDS -- clock stopped, then re-armed with whatever was left. A test asserts the re-arm, because an exemption that forgot to re-arm would silently make every paused request immortal. End-to-end: an upstream that never settles now yields a response in under a second carrying ⚠, the deadline, and `mcpctl trace <code>`. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2 |
|||
| 0eca4148e3 |
fix(mcplocal): recreate a stale session instead of 404ing outside the envelope
Second 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
|
|||
| c06c34f0a2 |
feat(mcplocal): a trace code that actually reaches the audit trail
The 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_01GqMidYEGUJG5fxeoTELBu2
|
|||
| c2a419b4f7 |
fix(mcplocal): one LLM budget per stage, so a loop cannot multiply it
A 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_01GqMidYEGUJG5fxeoTELBu2
|
|||
| 2c90f5971d |
fix(mcplocal): no LLM call can hang a tool call forever
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_01GqMidYEGUJG5fxeoTELBu2
|
