Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 10 additions & 0 deletions docs/mcpgodebug.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
10 changes: 10 additions & 0 deletions internal/docs/mcpgodebug.src.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
30 changes: 25 additions & 5 deletions mcp/server.go
Original file line number Diff line number Diff line change
Expand Up @@ -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")
Comment on lines +36 to +43

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

a description should be added in mcpgodebug.rc.md files

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Added in a9b6d0d — an entry under 1.8.0 next to blockingcancelnotify, in both internal/docs/mcpgodebug.src.md and the generated docs/mcpgodebug.md. Re-ran go generate ./internal/docs/ so the two agree, and go test ./internal/docs/ passes.

One thing worth flagging while you are looking at it: every other option on that page is opt-out (set to 1 to get the old behavior back), whereas this one is opt-in — the default keeps logging at info, which is what avoids the behavior change you raised. I said that explicitly in the entry, but it does sit a bit awkwardly next to the section's "will be removed in the 1.9.0 version" line, since dropping the knob would make the demotion unreachable rather than permanent.

If you would rather it follow the page convention, I can flip it to keepsessionlifecycleloginfo: demote by default, 1 restores info, and removal in 1.9.0 then means the demotion becomes permanent. Your call — happy either way.


// 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

Expand Down Expand Up @@ -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
}

Expand All @@ -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.
Expand All @@ -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)
Expand Down Expand Up @@ -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
}

Expand Down Expand Up @@ -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
}

Expand Down
88 changes: 88 additions & 0 deletions mcp/server_lifecycle_log_test.go
Original file line number Diff line number Diff line change
@@ -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)
}
}
})
}