Skip to content

fix(mcp): stop a slow display-name lookup stalling tool calls; harness returns at the response - #480

Draft
leggetter wants to merge 2 commits into
mainfrom
fix/mcp-tool-call-stall
Draft

leggetter wants to merge 2 commits into
mainfrom
fix/mcp-tool-call-stall

Conversation

@leggetter

Copy link
Copy Markdown
Collaborator

What

  • Product fix: the MCP server's project display-name lookup, which runs ahead of every tool call until it succeeds, now gives up after 5s (or when the tool call is cancelled). A slow API response can no longer hold up a tool call that doesn't need the API.
  • Harness fix: RunMCPSubprocess now drives stdio the way an MCP client does. It waits for the initialize response before sending notifications/initialized and the request, reads stdout as it arrives, and returns once every request has a response. runDuration is now an upper bound, not a fixed sleep. Helper signatures are unchanged, so no gateway or outpost MCP test changes.

Why

Three acceptance runs failed on PRs that don't touch MCP code, each with no JSON-RPC response with id 2 in stdout: "{...initialize result...}":

Separately, every MCP subprocess call used its full 20s window even when it passed, which is why every passing test logged subprocess wait: signal: killed.

Root cause

Verified (mechanism):

  1. Before any tool handler runs, wrapWithTelemetry calls FillProjectDisplayNameIfNeeded, which resolves the project name shown in tool output. The name is never set at startup, so the first tool call in every session sends GET /cli-auth/validate first. That includes tools that never otherwise touch the API, such as a write refused in read-only mode, which is why TestGatewayMCPStdio_ReadOnlyRefusesWriteAction could fail.
  2. That request used context.Background(), and the CLI's HTTP client sets no response timeout on its TCP transport. A slow response therefore held the tool call open for as long as the API took.
  3. Reproduced deterministically with a local mock API whose /cli-auth/validate waits 25s, pipelined stdin and the read-only delete refusal: 8/8 runs gave the exact CI signature (initialize answered, no id 2, empty stderr). With a 10-minute stall the call was still blocked at 75s. Waiting for the initialize response first made no difference (4/4 still missing id 2).

Ruled out (verified): a pipelining race. Pipelined stdin against an instant mock API answered id 2 in 4,300/4,300 runs, at up to 64 concurrent processes (max 562ms). A -race build reported no data races in 300 runs. go-sdk v1.8.0 finishes handling initialize before it reads the next message. A request that arrives before initialization gets an error response, not silence.

Inferred (not reproduced): that CI actually hit a slow /cli-auth/validate response. I made 750 live calls from a dev machine (p50 about 205ms, max 446ms) and saw no stall. CI made roughly 500 to 750 MCP calls over the period with 3 stalls, about 1 in 200, so 750 clean samples neither confirm nor rule it out. In the two tests that call the API for their own work, the stall could instead have been in that request. This PR does not bound that request (see below).

Change

  • pkg/mcpcore/project_display.go: FillProjectDisplayNameIfNeeded takes the tool call's context and caps the whole lookup at projectDisplayLookupTimeout (5s). On timeout it gives up silently, as it already did on API errors, and the next call tries again. Once the budget is spent it skips the project listing.
  • pkg/mcpcore/server.go: passes the tool call's context in.
  • pkg/hookdeck: adds ValidateAPIKeyContext and ListProjectsContext. ValidateAPIKey and ListProjects call them with context.Background(), so no other caller changes.
  • test/acceptance/helpers.go: RunMCPSubprocess sends the initialize request on its own and the rest only after it is answered. It watches stdout as it arrives and, once every request in stdin has a response, closes stdin and gives the server up to 5s to exit. The process is killed at runDuration if responses are still missing. Stdin with no requests, or empty stdin, behaves as before (run until exit or runDuration). Stdin is closed only after every response is in, because closing it earlier makes the server shut down and drop in-flight responses.
  • Unit tests: the lookup gives up on a stalled API, cancelling the call ends it, and a wrapped tool call is not held up by a stalled lookup. With the bound removed, that last test fails with "the tool call is still waiting on the display-name lookup".

Not in this PR (follow-ups)

  • Tool handlers' own API requests still have no client-side deadline. A stalled response blocks that tool call until the MCP client gives up. The harness now fails such a call at runDuration instead of hanging, and stderr will show any lookup timeout. A transport-level timeout would affect every CLI command, so it needs its own decision.
  • Concurrent tools/call requests in one session race on the shared API client. go-sdk runs each tools/call on its own goroutine, so the "Stdio MCP invokes tools sequentially" comments in pkg/mcpcore don't hold. A -race build sent four concurrent calls and reported data races in 20/20 runs: wrapWithTelemetry writes Telemetry, and FillProjectDisplayNameIfNeeded writes ProjectName/ProjectOrg. Each acceptance process sends exactly one call, so this isn't the flake.

Testing

Reproduction. A throwaway driver (not committed) runs the built binary as gateway mcp --api-base <mock>, using the read-only delete refusal, which needs no API call of its own.

Scenario main This branch
/cli-auth/validate stalls 25s, pipelined stdin, 20s window, 8 runs 8/8 missing id 2 (initialize only, empty stderr) 0/8 missing, id 2 at about 5.37s
Instant API, pipelined stdin, 1,000 runs at 16 concurrent 0 missing 0 missing (p99 299ms)

Harness against a mock API (local throwaway test, not committed):

  • Instant API: CallMCPTool returned in 2.4s, including go build; before, it always took 20s plus the build.
  • Stalled lookup: the refusal came back in 6.4s.
  • Upper bound: a call whose own API request never answers was killed at its 8s runDuration. The caller got the initialize response and a context deadline exceeded line on stderr.

Unit tests (the CI unit-test job steps), judged by exit code:

  • go test -short ./pkg/... → exit 0 (20 packages ok, 0 FAIL)
  • go vet ./... → exit 0
  • go test -race -short ./pkg/mcpcore/ ./pkg/hookdeck/ → exit 0
  • With the lookup bound removed, TestToolCallIsNotHeldByAStalledDisplayNameLookup fails ("the tool call is still waiting on the display-name lookup").

Acceptance, only the tags that use these helpers, with no CI acceptance run in progress:

Slice main This branch
ACCEPTANCE_SLICE=0 go test -tags=mcp ./test/acceptance/... -count=1 PASS, 561.8s, 23 tests, 24 subprocesses killed PASS, 49.8s, 23 tests, 0 killed
ACCEPTANCE_SLICE=3 go test -tags=outpost ./test/acceptance/... -count=1 PASS, 216.5s, 21 tests, 8 killed PASS, 60.2s, 21 tests, 0 killed

🤖 Generated with Claude Code

leggetter and others added 2 commits October 29, 2026 12:51
Every MCP tool call ran FillProjectDisplayNameIfNeeded before its handler,
and until the name resolved that meant GET /cli-auth/validate with no
deadline: context.Background() on a transport with no response timeout. A
slow API response therefore held any tool call open for as long as the API
took, including calls that never otherwise reach the API, such as a write
refused in read-only mode. The client saw initialize answered and then
nothing.

The lookup is cosmetic, so it now takes the tool call's context and gives up
after 5s, silently, as it already did on API errors. The next call tries
again. ValidateAPIKeyContext and ListProjectsContext carry the context; the
existing methods delegate to them with context.Background().

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
RunMCPSubprocess wrote every message up front, then killed the server
after a fixed runDuration and only then looked for the response, so every
MCP call took the full window (usually 20s) even when it passed.

It now sends initialize on its own and the rest once that is answered,
reads stdout as it arrives, and as soon as every request in stdin has a
response closes stdin and lets the server exit. runDuration is an upper
bound: the process is killed if responses are still missing. Stdin is only
closed once everything is answered, because closing it earlier makes the
server shut down and drop in-flight responses. Helper signatures are
unchanged.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
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