diff --git a/docs/mcpgodebug.md b/docs/mcpgodebug.md index d25b9b49..850b64e4 100644 --- a/docs/mcpgodebug.md +++ b/docs/mcpgodebug.md @@ -44,6 +44,16 @@ Options listed below were added and will be removed in the 1.9.0 version of the soon as its context is cancelled and cannot be delayed by a slow or unresponsive peer. See issue #1150. +- `demotesessionlifecyclelog` added. If set to `1`, the five routine session + bookkeeping records ("server connecting", "server session connected", + "server session disconnected", "session initialized", "client log level + set") are emitted at debug level instead of info. On a stateless streamable + HTTP server a session is minted per request, so these records fire on every + request and bury the server's own logs. See issue #1204. Unlike the other + options on this page this one is opt-in: the default keeps emitting the + records at info, because demoting them changes log output existing users may + rely on. + ### 1.7.0 Options listed below were added and will be removed in the 1.9.0 version of the SDK. diff --git a/internal/docs/mcpgodebug.src.md b/internal/docs/mcpgodebug.src.md index 32f8af26..dbc6ea29 100644 --- a/internal/docs/mcpgodebug.src.md +++ b/internal/docs/mcpgodebug.src.md @@ -43,6 +43,16 @@ Options listed below were added and will be removed in the 1.9.0 version of the soon as its context is cancelled and cannot be delayed by a slow or unresponsive peer. See issue #1150. +- `demotesessionlifecyclelog` added. If set to `1`, the five routine session + bookkeeping records ("server connecting", "server session connected", + "server session disconnected", "session initialized", "client log level + set") are emitted at debug level instead of info. On a stateless streamable + HTTP server a session is minted per request, so these records fire on every + request and bury the server's own logs. See issue #1204. Unlike the other + options on this page this one is opt-in: the default keeps emitting the + records at info, because demoting them changes log output existing users may + rely on. + ### 1.7.0 Options listed below were added and will be removed in the 1.9.0 version of the SDK. diff --git a/mcp/server.go b/mcp/server.go index b935385f..71a34478 100644 --- a/mcp/server.go +++ b/mcp/server.go @@ -33,6 +33,26 @@ import ( "github.com/yosida95/uritemplate/v3" ) +// demotesessionlifecyclelog, when set to "1" via MCPGODEBUG, demotes routine +// session bookkeeping records ("server connecting", "server session +// connected", "server session disconnected", "session initialized", "client +// log level set") from info to debug. On stateless streamable HTTP a session +// is minted per request, so these fire constantly and drown out the server's +// own logs (#1204). It is gated behind MCPGODEBUG because demoting them +// changes log output that existing users may rely on. +var demotesessionlifecyclelog = mcpgodebug.Value("demotesessionlifecyclelog") + +// logSessionLifecycle logs a routine session bookkeeping record at debug when +// MCPGODEBUG=demotesessionlifecyclelog=1, and at info (the historical level) +// otherwise. +func logSessionLifecycle(l *slog.Logger, msg string, args ...any) { + if demotesessionlifecyclelog == "1" { + l.Debug(msg, args...) + return + } + l.Info(msg, args...) +} + // DefaultPageSize is the default for [ServerOptions.PageSize]. const DefaultPageSize = 1000 @@ -1367,7 +1387,7 @@ func (s *Server) bind(mcpConn Connection, conn *jsonrpc2.Connection, state *Serv s.mu.Lock() s.sessions = append(s.sessions, ss) s.mu.Unlock() - s.opts.Logger.Info("server session connected", "session_id", ss.ID()) + logSessionLifecycle(s.opts.Logger, "server session connected", "session_id", ss.ID()) return ss } @@ -1387,7 +1407,7 @@ func (s *Server) disconnect(cc *ServerSession) { delete(s.promptChangeSubscriptions, cc) delete(s.resourceChangeSubscriptions, cc) - s.opts.Logger.Info("server session disconnected", "session_id", cc.ID()) + logSessionLifecycle(s.opts.Logger, "server session disconnected", "session_id", cc.ID()) } // ServerSessionOptions configures the server session. @@ -1413,7 +1433,7 @@ func (s *Server) Connect(ctx context.Context, t Transport, opts *ServerSessionOp onClose = opts.onClose } - s.opts.Logger.Info("server connecting") + logSessionLifecycle(s.opts.Logger, "server connecting") ss, err := connect(ctx, t, s, state, onClose, s.opts.Logger) if err != nil { s.opts.Logger.Error("server connect error", "error", err) @@ -1471,7 +1491,7 @@ func (ss *ServerSession) initialized(ctx context.Context, params *InitializedPar if h := ss.server.opts.InitializedHandler; h != nil { h(ctx, serverRequestFor(ss, params)) } - ss.server.opts.Logger.Info("session initialized") + logSessionLifecycle(ss.server.opts.Logger, "session initialized") return nil, nil } @@ -2100,7 +2120,7 @@ func (ss *ServerSession) setLevel(_ context.Context, params *SetLoggingLevelPara ss.updateState(func(state *ServerSessionState) { state.LogLevel = params.Level }) - ss.server.opts.Logger.Info("client log level set", "level", params.Level) + logSessionLifecycle(ss.server.opts.Logger, "client log level set", "level", params.Level) return &emptyResult{}, nil } diff --git a/mcp/server_lifecycle_log_test.go b/mcp/server_lifecycle_log_test.go new file mode 100644 index 00000000..b08f458e --- /dev/null +++ b/mcp/server_lifecycle_log_test.go @@ -0,0 +1,88 @@ +// Copyright 2026 The Go MCP SDK Authors. All rights reserved. +// Use of this source code is governed by an MIT-style +// license that can be found in the LICENSE file. + +package mcp + +import ( + "bytes" + "context" + "log/slog" + "strings" + "sync" + "testing" +) + +// syncBuffer is a bytes.Buffer safe for concurrent use, since session +// lifecycle events are logged from the connection's read goroutine. +type syncBuffer struct { + mu sync.Mutex + buf bytes.Buffer +} + +func (b *syncBuffer) Write(p []byte) (int, error) { + b.mu.Lock() + defer b.mu.Unlock() + return b.buf.Write(p) +} + +func (b *syncBuffer) String() string { + b.mu.Lock() + defer b.mu.Unlock() + return b.buf.String() +} + +// TestSessionLifecycleLogLevel verifies that routine session bookkeeping +// (connect, disconnect, initialize, setLevel) logs at info by default, and +// moves to debug when MCPGODEBUG=demotesessionlifecyclelog=1. On stateless +// streamable HTTP these events fire on every request, so at info they drown +// out the server's own logs (#1204); the demotion is gated behind +// MCPGODEBUG because it changes log output existing users may rely on. +func TestSessionLifecycleLogLevel(t *testing.T) { + // "session initialized" is also gated but doesn't fire on this + // connection path, so it is not asserted here. + lifecycleMessages := []string{ + "server connecting", + "server session connected", + "client log level set", + "server session disconnected", + } + + run := func(t *testing.T, level slog.Level) string { + var buf syncBuffer + logger := slog.New(slog.NewTextHandler(&buf, &slog.HandlerOptions{Level: level})) + cs, _, cleanup := basicConnection(t, func(s *Server) { + s.opts.Logger = logger + }) + if err := cs.SetLoggingLevel(context.Background(), &SetLoggingLevelParams{Level: "warning"}); err != nil { + t.Fatal(err) + } + cleanup() + return buf.String() + } + + t.Run("info by default", func(t *testing.T) { + got := run(t, slog.LevelInfo) + for _, msg := range lifecycleMessages { + if !strings.Contains(got, msg) { + t.Errorf("log output missing %q at info level by default:\n%s", msg, got) + } + } + }) + + t.Run("demoted to debug with MCPGODEBUG=demotesessionlifecyclelog=1", func(t *testing.T) { + old := demotesessionlifecyclelog + demotesessionlifecyclelog = "1" + t.Cleanup(func() { demotesessionlifecyclelog = old }) + + if got := run(t, slog.LevelInfo); got != "" { + t.Errorf("session lifecycle produced log output at info level with demotesessionlifecyclelog=1:\n%s", got) + } + got := run(t, slog.LevelDebug) + for _, msg := range lifecycleMessages { + if !strings.Contains(got, msg) { + t.Errorf("log output missing %q at debug level with demotesessionlifecyclelog=1:\n%s", msg, got) + } + } + }) +}