Skip to content

Fix #320: serialize the daemon's MCP sends (SDK transport frame interleave) + single-use stream sessions - #321

Merged
obj-p merged 6 commits into
mainfrom
fix-320-stream-drop
Jul 2, 2026
Merged

Fix #320: serialize the daemon's MCP sends (SDK transport frame interleave) + single-use stream sessions#321
obj-p merged 6 commits into
mainfrom
fix-320-stream-drop

Conversation

@obj-p

@obj-p obj-p commented Jul 2, 2026

Copy link
Copy Markdown
Owner

The callTool-stall face, root-caused and fixed

The dominant residual of the iOS e2e flake (#320) was callTool(preview_snapshot)/callTool(preview_variants) timing out with the daemon otherwise completely healthy. The investigation arc, each step from ground truth:

  1. Hop markers exonerated the handlers: instrumented every await hop (handler → router → session actor → capture); stalled runs showed complete sub-millisecond marker trails for every call that arrived — the stalled call's response never reached the client (or the next request never arrived), pointing at the transport.
  2. The SDK's StdioTransport.send() is actor-reentrant at its EAGAIN suspension: any response larger than the pipe buffer (every base64 snapshot/variants payload) that backs up mid-write suspends in the EAGAIN retry's Task.sleep — and a concurrent send (the daemon's 2s heartbeat notification, a progress notification) splices its bytes into the middle of the frame. The client silently drops what it can't decode; the caller times out; no error surfaces anywhere.
  3. Deterministic proof: the new SerializedStdioTransportTests framing test drives the exact regime (300KB send under pipe backpressure raced by a small send). Pointed at the SDK transport, it reproduces the corruption in <1s; pointed at the fix, frames stay intact.
  4. SerializedStdioTransport wraps the SDK transport and chains each send behind the previous one, so the inner transport never runs two sends concurrently. Sends are cancellable end-to-end (pendingSends + disconnect() cancellation + caller-cancellation forwarding), and connect() pumps the inner receive stream to satisfy the protocol's synchronous receive().

Also included:

  • Single-use URLSession(.ephemeral) for the app-server stream reads (test-side): URLSession.shared's pool could hand a connection abandoned mid-body to the next request against the same host:port — caught live (stream healthy server-side, NSURLError-1 client-side 50ms later).
  • PreviewAppServer stream-lifecycle logging on the previously-silent teardown paths.

Verification

Isolated MCPIntegrationTests campaign rates (6 runs each, hygiene between runs, caffeinated):

  • pre-fixes: 4/6 failed (mixed faces)
  • after pool fix only: 5/6 failed — all callTool-stalls
  • after hop markers (diagnosis run): 2/6 failed
  • after the transport fix: 1/6 failed, ZERO callTool-stalls
  • full local suite: 9/9 first-try (historically needed retries)

Remains open (#320, rescoped)

A low-rate NSURLError-1 residual (~1 in 9 isolated runs, confined to appServerEndToEnd, fails fast) that occurs even with per-request sessions — needs client-side attribution logging next.

Upstream issue for the SDK bug to follow.

🤖 Generated with Claude Code

https://claude.ai/code/session_01PPF6gjyr2BBuz31yRSnMvG

obj-p and others added 6 commits July 2, 2026 16:29
…utable

The stream tasks' catch paths cancelled the connection silently and
NWConnection .failed transitions were invisible, so #320's dropped
streams left no daemon-side trace. Log stream end (with error and frame
count), first frame sent, connection failures, and stop()'s live-task
count — enough to distinguish server-side send failures from client-side
teardown from task cancellation.

First catch with this logging in place showed the NSURLError-1 face is
NOT server-side: stream healthy, first frame sent, no error — see #320.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01PPF6gjyr2BBuz31yRSnMvG
…ace)

Caught live via the new appserver logging (#320): the daemon's stream
was fully healthy — first frame sent, no server-side error — when the
test hit NSURLErrorDomain Code=-1 on its NEXT request. readStreamSample
abandons the mjpeg response mid-body (it samples 20KB of a 220KB frame),
and URLSession.shared's per-host connection pool can hand that dying
connection to the follow-up /stream.avcc request against the same
host:port. A fresh single-use session per stream read has an empty pool,
so nothing poisoned can be reused; invalidateAndCancel() tears the
abandoned connection down with the session.

Post-fix campaign: 0/6 runs hit NSURLError-1 (was 1-2 per 6). The
remaining callTool-timeout face is a separate daemon-side mechanism,
still open on #320.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01PPF6gjyr2BBuz31yRSnMvG
The remaining #320 face: the SDK logs "mcp: callTool preview_snapshot"
(or preview_variants) and the handler never responds — 5/6 isolated runs
after the pool fix, on BOTH platforms (iOS preview_snapshot after HID
input; macOS preview_variants after its renders complete), while the
daemon is otherwise healthy (main thread idle in the event loop,
cooperative pool idle, streamer encoding). Thread samples can't see a
suspended task, so log each await hop instead: handler entry/route/
capture, the variants per-step loop, the macOS handle's two actor hops
(session actor vs main actor), and the iOS session-actor entry plus
fallback branches. The last marker in serve.log before the silence names
the hop the stalled call died in; MCPTestServer already dumps that log
tail into the test failure on callTool timeout.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01PPF6gjyr2BBuz31yRSnMvG
Root cause of the remaining #320 face, proven deterministically: the
SDK's StdioTransport (0.7.x) is an actor, but send() retries EAGAIN on
the non-blocking pipe with `await Task.sleep` — and actor re-entrancy
admits a second send at that suspension. Any response larger than the
pipe buffer (every base64 snapshot/variants payload) that backs up
mid-write can have a concurrent message (the daemon's 2s heartbeat, a
progress notification) spliced into its bytes. The client drops the
frames it can't decode and the awaiting callTool times out with no error
on either side — while hop markers show the handler completed normally
(the campaign specimens: last daemon line "snap: captured N bytes" or a
finished variants loop, then silence; the next request never arrives
because the client is still awaiting the corrupted response).

SerializedStdioTransport mirrors the SDK transport but chains each send
behind the previous one, so a frame's bytes always land contiguously.
The new PreviewsCLITests framing test drives the exact regime — a 300KB
send suspended in EAGAIN backpressure, raced by a small send — and the
identical harness pointed at the SDK transport corrupts both frames
(splice reproduced in <1s), while this transport keeps them intact.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01PPF6gjyr2BBuz31yRSnMvG
The serious one: SerializedStdioTransport's logger drifted from the SDK
original — the SDK deliberately uses SwiftLogNoOpLogHandler because the
SDK Server logs through the transport's logger, and swift-log's default
factory writes plain text to STDOUT, splicing it into the JSON-RPC
stream on any SDK error path (the exact corruption class this transport
exists to prevent). Restored the no-op factory.

Also: fold the appserver connection-failure logging into the single
stream-task teardown line (a dropped stream logged 2-3 warn lines per
event), and drop the redundant "snap: enter" marker (adjacent to the
SDK's own "mcp: callTool" line — its sessionID moved into "snap:
routing").

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01PPF6gjyr2BBuz31yRSnMvG
The review overturned the copy decision with two facts: the SDK's own
StdioTransport logger is already a no-op (so a wrapper needs no logger
care), and chaining sends UPSTREAM of the inner transport means its
re-entrancy window is never entered concurrently — so a thin wrapper
fixes the interleave without duplicating ~110 lines of readLoop/EAGAIN
code that would drift from upstream. receive() is a synchronous protocol
requirement, so connect() pumps the inner stream into our own.

Also fixes the review's confirmed correctness finding: sends are now
cancellable end-to-end. Each chained send registers in pendingSends;
disconnect() cancels them all (a client that stops draining stdout
otherwise leaves the head send retrying EAGAIN forever with every 2s
heartbeat queueing behind it, each retaining its full payload), and
send() forwards its caller's cancellation to the chained task via
withTaskCancellationHandler. Cancellation lands inside the inner
transport's EAGAIN retry through its throwing Task.sleep.

Prunes the #320 hop-marker scaffolding whose job is done (the stall was
in the transport, not the handlers), keeping the useful telemetry:
per-capture byte counts and the iOS snapshot fallback-path markers.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01PPF6gjyr2BBuz31yRSnMvG
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