From 4c00594be629ca87637f4316a232377f9b0979cd Mon Sep 17 00:00:00 2001 From: Ravish Gupta Date: Tue, 14 Apr 2026 07:53:11 -0700 Subject: [PATCH] mcp: log out-of-band errors instead of dropping them (#887) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Summary Two error sites in the MCP runtime were previously unobservable: - **`mcp/shared.go` `startKeepalive`** — when a keepalive ping failed, the session was closed silently with no indication of why. - **`mcp/transport.go` `connect`** — `jsonrpc2.OnInternalError` printed via the package-level `log.Printf`, bypassing the `*slog.Logger` configured on `ServerOptions`/`ClientOptions`. Both sites now report through the existing `*slog.Logger` that `Server` and `Client` already guarantee non-nil via `ensureLogger`. The logger is threaded into the unexported `startKeepalive` and `connect` helpers as a parameter — **no new public API surface**. ## Context Per @jba's [suggestion on #865](https://github.com/modelcontextprotocol/go-sdk/pull/865#issuecomment-4156166474): > Maybe we can just use the logger in all the places we currently drop the error. Then it's still reported, but we don't have to add any API. This PR is that smaller alternative. It addresses the concrete observability gap in #218 without expanding `ServerOptions`. PR #865 (the `ErrorHandler` callback proposal) remains open pending community input on whether a structured callback API is also wanted on top of logging. `notifySessions` already logs at `Warn` level on delivery errors and is intentionally left untouched. ## Test plan - [x] New regression test `TestKeepAliveFailure_Logged` asserts the keepalive failure produces a log line on the configured logger. - [x] Verified the test fails when the new `logger.Error(...)` call is removed (sanity check that it pins the behavior). - [x] `go test ./mcp/... -count=1` passes. - [x] `go vet ./...` clean. - [x] `go build ./...` clean. Refs #218 --------- Co-authored-by: Maciej Kisiel --- mcp/client.go | 4 ++-- mcp/mcp_test.go | 46 ++++++++++++++++++++++++++++++++++++++++++++++ mcp/server.go | 4 ++-- mcp/shared.go | 9 +++++++-- mcp/transport.go | 10 +++++++--- 5 files changed, 64 insertions(+), 9 deletions(-) diff --git a/mcp/client.go b/mcp/client.go index 4860b62..c82e189 100644 --- a/mcp/client.go +++ b/mcp/client.go @@ -253,7 +253,7 @@ func (c *Client) capabilities(protocolVersion string) *ClientCapabilities { // server, calls or notifications will return an error wrapping // [ErrConnectionClosed]. func (c *Client) Connect(ctx context.Context, t Transport, opts *ClientSessionOptions) (cs *ClientSession, err error) { - cs, err = connect(ctx, t, c, (*clientSessionState)(nil), nil) + cs, err = connect(ctx, t, c, (*clientSessionState)(nil), nil, c.opts.Logger) if err != nil { return nil, err } @@ -405,7 +405,7 @@ func (cs *ClientSession) registerElicitationWaiter(elicitationID string) (await // startKeepalive starts the keepalive mechanism for this client session. func (cs *ClientSession) startKeepalive(interval time.Duration) { - startKeepalive(cs, interval, &cs.keepaliveCancel) + startKeepalive(cs, interval, &cs.keepaliveCancel, cs.client.opts.Logger) } // AddRoots adds the given roots to the client, diff --git a/mcp/mcp_test.go b/mcp/mcp_test.go index 00c4dc9..5df8b38 100644 --- a/mcp/mcp_test.go +++ b/mcp/mcp_test.go @@ -1817,6 +1817,52 @@ func TestKeepAliveFailure(t *testing.T) { }) } +// TestKeepAliveFailure_Logged verifies that a keepalive ping failure is +// reported via the configured slog.Logger instead of being silently dropped. +// Regression test for #218. +func TestKeepAliveFailure_Logged(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + ctx := context.Background() + + ct, st := NewInMemoryTransports() + + // Server without keepalive. + s := NewServer(testImpl, nil) + AddTool(s, greetTool(), sayHi) + ss, err := s.Connect(ctx, st, nil) + if err != nil { + t.Fatal(err) + } + + // Client with a short keepalive and a logger that writes to a + // buffer so we can assert on its output. + var buf bytes.Buffer + clientOpts := &ClientOptions{ + KeepAlive: 50 * time.Millisecond, + Logger: slog.New(slog.NewTextHandler(&buf, &slog.HandlerOptions{Level: slog.LevelError})), + } + c := NewClient(testImpl, clientOpts) + cs, err := c.Connect(ctx, ct, nil) + if err != nil { + t.Fatal(err) + } + defer cs.Close() + + synctest.Wait() + + // Trigger a ping failure by closing the server side. + ss.Close() + + time.Sleep(100 * time.Millisecond) + synctest.Wait() + + got := buf.String() // slog serializes Write calls internally + if !strings.Contains(got, "keepalive ping failed") { + t.Errorf("expected keepalive failure to be logged, got log output:\n%s", got) + } + }) +} + func TestAddTool_DuplicateNoPanicAndNoDuplicate(t *testing.T) { // Adding the same tool pointer twice should not panic and should not // produce duplicates in the server's tool list. diff --git a/mcp/server.go b/mcp/server.go index 2357959..2850437 100644 --- a/mcp/server.go +++ b/mcp/server.go @@ -1026,7 +1026,7 @@ func (s *Server) Connect(ctx context.Context, t Transport, opts *ServerSessionOp } s.opts.Logger.Info("server connecting") - ss, err := connect(ctx, t, s, state, onClose) + ss, err := connect(ctx, t, s, state, onClose, s.opts.Logger) if err != nil { s.opts.Logger.Error("server connect error", "error", err) return nil, err @@ -1531,7 +1531,7 @@ func (ss *ServerSession) Wait() error { // startKeepalive starts the keepalive mechanism for this server session. func (ss *ServerSession) startKeepalive(interval time.Duration) { - startKeepalive(ss, interval, &ss.keepaliveCancel) + startKeepalive(ss, interval, &ss.keepaliveCancel, ss.server.opts.Logger) } // pageToken is the internal structure for the opaque pagination cursor. diff --git a/mcp/shared.go b/mcp/shared.go index 5662b12..05397a1 100644 --- a/mcp/shared.go +++ b/mcp/shared.go @@ -582,7 +582,10 @@ type keepaliveSession interface { // startKeepalive starts the keepalive mechanism for a session. // It assigns the cancel function to the provided cancelPtr and starts a goroutine // that sends ping messages at the specified interval. -func startKeepalive(session keepaliveSession, interval time.Duration, cancelPtr *context.CancelFunc) { +// +// logger must be non-nil; ping failures (which terminate the keepalive loop and +// close the session) are reported via logger so they are not silently dropped. +func startKeepalive(session keepaliveSession, interval time.Duration, cancelPtr *context.CancelFunc, logger *slog.Logger) { ctx, cancel := context.WithCancel(context.Background()) // Assign cancel function before starting goroutine to avoid race condition. // We cannot return it because the caller may need to cancel during the @@ -602,7 +605,9 @@ func startKeepalive(session keepaliveSession, interval time.Duration, cancelPtr err := session.Ping(pingCtx, nil) pingCancel() if err != nil { - // Ping failed, close the session + // Ping failed; log it before closing the session so the + // failure is observable to operators. See #218. + logger.Error("keepalive ping failed; closing session", "error", err) _ = session.Close() return } diff --git a/mcp/transport.go b/mcp/transport.go index 23dccf8..9288b37 100644 --- a/mcp/transport.go +++ b/mcp/transport.go @@ -10,7 +10,7 @@ import ( "errors" "fmt" "io" - "log" + "log/slog" "net" "os" "sync" @@ -152,7 +152,9 @@ type handler interface { handle(ctx context.Context, req *jsonrpc.Request) (any, error) } -func connect[H handler, State any](ctx context.Context, t Transport, b binder[H, State], s State, onClose func()) (H, error) { +// connect wires a transport to a binder. logger must be non-nil; it receives +// jsonrpc2 internal errors that would otherwise be dropped (see #218). +func connect[H handler, State any](ctx context.Context, t Transport, b binder[H, State], s State, onClose func(), logger *slog.Logger) (H, error) { var zero H mcpConn, err := t.Connect(ctx) if err != nil { @@ -178,7 +180,9 @@ func connect[H handler, State any](ctx context.Context, t Transport, b binder[H, OnDone: func() { b.disconnect(h) }, - OnInternalError: func(err error) { log.Printf("jsonrpc2 error: %v", err) }, + OnInternalError: func(err error) { + logger.Error("jsonrpc2 internal error", "error", err) + }, }) assert(preempter.conn != nil, "unbound preempter") return h, nil