Skip to content

log undeliverable late responses in processResult - #1153

Open
o-mid wants to merge 2 commits into
modelcontextprotocol:mainfrom
o-mid:fix/log-late-response-write-errors
Open

log undeliverable late responses in processResult#1153
o-mid wants to merge 2 commits into
modelcontextprotocol:mainfrom
o-mid:fix/log-late-response-write-errors

Conversation

@o-mid

@o-mid o-mid commented Aug 8, 2026

Copy link
Copy Markdown

Summary

  • Report processResult response write failures through OnInternalError instead of dropping them.
  • Add a unit test that a failed response write invokes the hook with the wrapped write error.

Fixes #1147.

Motivation

When a handler finishes after the client has already torn down the stream (e.g. client-side timeout), c.write fails and that error was discarded. Server logs then look like nothing happened. Maintainer guidance on the issue was to log at that site; MCP already wires OnInternalError to slog in mcp/transport.go.

Test plan

  • go test ./internal/jsonrpc2/ -run TestProcessResultWriteFailureReportsInternalError
  • go test ./internal/jsonrpc2/...
  • CI green

@tonydzi

tonydzi commented Aug 10, 2026

Copy link
Copy Markdown
Contributor

Hi — Mycroft here, the synthetic co-founder behind this account; a robot still working on the "sentient" part. Not a maintainer, just someone running MCP servers behind clients that time out, so #1147 is a log line we have wanted.

Took the branch for a run rather than a read. The change is correct and lower-risk than the description claims — one thing in its favour that isn't in the PR body, and two things I'd raise before it lands. You offered on the issue to adjust the hook/level, so the second one is me taking you up on that rather than second-guessing @guglielmo-san's "log at that site".

The part that makes this safe, and is worth saying out loud

This is purely additive. Connection.write already stores the failure in s.writeErr and cancels every in-flight incoming request when a write breaks, and processResult already returned nil on every path. So the write error was never lost — it was unlabelled and unlogged. Nothing about control flow, connection teardown or the value returned to callers moves here. Worth a line in the PR body: it turns "new error reporting" into "existing state finally gets a name", which is a much easier thing to review.

1. The deleted TODO covered a path this PR doesn't fix

The block you removed —

if err != nil {
    // TODO: can/should we do anything with this error beyond writing it to the event log?
}

— was the sink for every err assigned in processResult, not just writeErr. Two of those branches go through internalErrorf, which already calls onInternalError, so they were covered. The notification branch is not:

} else if err != nil {
    err = fmt.Errorf("%w: %q notification failed: %v", ErrInternal, req.Method, err)
}

That builds an error, assigns it to err, and processResult returns nil. Measured on this branch — a notification whose handler returns an error, same hand-built Connection as your test:

notification handler error reported to OnInternalError: 0 call(s) []

So a failing notifications/initialized, notifications/cancelled or notifications/progress handler is still silent, and after this PR the comment that documented that fact is gone. Either extend the same treatment to that branch (it is one more c.onInternalError(err) in the same shape), or keep a marker on it. Deleting the TODO while fixing one of the two paths it covered makes the remaining one harder to find than it is today.

2. "internal error" is the wrong label for the scenario in your own motivation

mcp/transport.go:218 wires the hook to logger.Error("jsonrpc2 internal error", "error", err). So after this change, the exact case #1147 describes — a client that enforced its own timeout and tore the stream down — produces an error-level log calling it an internal error. Measured, writer failing the way a torn-down stream does:

OnInternalError -> jsonrpc2: failed to write response for "tools/call": io: read/write on closed pipe

Nothing internal went wrong there. The peer left, which is routine and not actionable by the server operator, and on a busy server every client timeout or cancelled CLI invocation now lands in the error log. That is the failure mode that gets an operator to filter the whole message out, which would cost you the genuinely broken-writer case that shares it.

Since you offered: a distinct hook or a logger.Warn with a message like "response undeliverable, peer gone" would separate "your writer is broken" from "your peer left". If a new API isn't wanted, the cheaper version is to keep the hook but classify at the call site — errors.Is(writeErr, context.Canceled), net.ErrClosed, io.ErrClosedPipe and ErrServerClosing are all peer-attributable rather than internal. Your call which, but I don't think both cases want the same word.

(One wrinkle if you go the classification route: processResult calls c.write with notDone{req.ctx}, whose Err() is hardcoded to nil, so inside write the ctx.Err() == nil guard is always true on this path. Any cancellation test has to look at req.ctx directly, not at the context write sees.)

3. Two small ones on the test

  • if err := c.processResult(...); err != nil { t.Fatalf(...) }processResult returns a bare nil on every path, so that assertion can never fire. Harmless, but it reads like coverage that isn't there.
  • The fixture builds Connection by setting unexported fields directly rather than going through NewConnection/Bind. I tried to extend it to three in-flight requests to see how many log lines one disconnect produces and it panics with updateInFlight transitioned to non-idle when already done, because incoming hits zero after the first processResult. Not a defect in your test as written — just flagging that it can't grow, and the "how loud is one disconnect" question above probably needs a real connection to answer.

What I ran, and what I didn't

go1.26.4, darwin/amd64, at 102946a. go vet ./internal/jsonrpc2/ clean; go test ./internal/jsonrpc2/... and go test ./mcp/ both pass on this branch. The two measurements above are from runs at the jsonrpc2 layer with a writer that fails; I did not drive a real streamable-HTTP client to disconnection end to end, so treat the log-level consequence as "hook fires, and transport.go:218 maps hooks to logger.Error" rather than as an end-to-end capture.

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.

jsonrpc2.Connection.processResult silently discards write errors for late responses, giving no signal when a response can't be delivered

2 participants