mcp/server: enable server logging (#501)

mcp/server.go: implement server‑side logging

- Thread a *slog.Logger through server paths to improve debuggability
- Introduce no‑op discard handler + ensureLogger so loggers are never
nil
- Use ensured loggers in Server
- address todo comments related to adding logging support

All tests are passing and no functionality should change with this PR

Fixes https://github.com/modelcontextprotocol/go-sdk/issues/170
This commit is contained in:
Suraj Bobade 2025-10-03 00:14:32 +05:30 • committed by GitHub
commit 1dcbf62661
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
3 changed files with 72 additions and 3 deletions

View file

@ -88,6 +88,23 @@ type LoggingHandler struct {
handler slog.Handler handler slog.Handler
} }
// discardHandler is a slog.Handler that drops all logs.
// TODO: use slog.DiscardHandler when we require Go 1.24+.
type discardHandler struct{}
func (discardHandler) Enabled(context.Context, slog.Level) bool { return false }
func (discardHandler) Handle(context.Context, slog.Record) error { return nil }
func (discardHandler) WithAttrs([]slog.Attr) slog.Handler { return discardHandler{} }
func (discardHandler) WithGroup(string) slog.Handler { return discardHandler{} }
// ensureLogger returns l if non-nil, otherwise a discard logger.
func ensureLogger(l *slog.Logger) *slog.Logger {
if l != nil {
return l
}
return slog.New(discardHandler{})
}
// NewLoggingHandler creates a [LoggingHandler] that logs to the given [ServerSession] using a // NewLoggingHandler creates a [LoggingHandler] that logs to the given [ServerSession] using a
// [slog.JSONHandler]. // [slog.JSONHandler].
func NewLoggingHandler(ss *ServerSession, opts *LoggingHandlerOptions) *LoggingHandler { func NewLoggingHandler(ss *ServerSession, opts *LoggingHandlerOptions) *LoggingHandler {

View file

@ -12,6 +12,7 @@ import (
"encoding/json" "encoding/json"
"fmt" "fmt"
"iter" "iter"
"log/slog"
"maps" "maps"
"net/url" "net/url"
"path/filepath" "path/filepath"
@ -54,6 +55,8 @@ type Server struct {
type ServerOptions struct { type ServerOptions struct {
// Optional instructions for connected clients. // Optional instructions for connected clients.
Instructions string Instructions string
// If non-nil, log server activity.
Logger *slog.Logger
// If non-nil, called when "notifications/initialized" is received. // If non-nil, called when "notifications/initialized" is received.
InitializedHandler func(context.Context, *InitializedRequest) InitializedHandler func(context.Context, *InitializedRequest)
// PageSize is the maximum number of items to return in a single page for // PageSize is the maximum number of items to return in a single page for
@ -130,6 +133,10 @@ func NewServer(impl *Implementation, options *ServerOptions) *Server {
opts.GetSessionID = randText opts.GetSessionID = randText
} }
if opts.Logger == nil { // ensure we have a logger
opts.Logger = ensureLogger(nil)
}
return &Server{ return &Server{
impl: impl, impl: impl,
opts: opts, opts: opts,
@ -695,6 +702,7 @@ func (s *Server) ResourceUpdated(ctx context.Context, params *ResourceUpdatedNot
sessions := slices.Collect(maps.Keys(subscribedSessions)) sessions := slices.Collect(maps.Keys(subscribedSessions))
s.mu.Unlock() s.mu.Unlock()
notifySessions(sessions, notificationResourceUpdated, params) notifySessions(sessions, notificationResourceUpdated, params)
s.opts.Logger.Info("resource updated notification sent", "uri", params.URI, "subscriber_count", len(sessions))
return nil return nil
} }
@ -712,6 +720,7 @@ func (s *Server) subscribe(ctx context.Context, req *SubscribeRequest) (*emptyRe
s.resourceSubscriptions[req.Params.URI] = make(map[*ServerSession]bool) s.resourceSubscriptions[req.Params.URI] = make(map[*ServerSession]bool)
} }
s.resourceSubscriptions[req.Params.URI][req.Session] = true s.resourceSubscriptions[req.Params.URI][req.Session] = true
s.opts.Logger.Info("resource subscribed", "uri", req.Params.URI, "session_id", req.Session.ID())
return &emptyResult{}, nil return &emptyResult{}, nil
} }
@ -733,6 +742,7 @@ func (s *Server) unsubscribe(ctx context.Context, req *UnsubscribeRequest) (*emp
delete(s.resourceSubscriptions, req.Params.URI) delete(s.resourceSubscriptions, req.Params.URI)
} }
} }
s.opts.Logger.Info("resource unsubscribed", "uri", req.Params.URI, "session_id", req.Session.ID())
return &emptyResult{}, nil return &emptyResult{}, nil
} }
@ -751,8 +761,10 @@ func (s *Server) unsubscribe(ctx context.Context, req *UnsubscribeRequest) (*emp
// It need not be called on servers that are used for multiple concurrent connections, // It need not be called on servers that are used for multiple concurrent connections,
// as with [StreamableHTTPHandler]. // as with [StreamableHTTPHandler].
func (s *Server) Run(ctx context.Context, t Transport) error { func (s *Server) Run(ctx context.Context, t Transport) error {
s.opts.Logger.Info("server run start")
ss, err := s.Connect(ctx, t, nil) ss, err := s.Connect(ctx, t, nil)
if err != nil { if err != nil {
s.opts.Logger.Error("server connect failed", "error", err)
return err return err
} }
@ -764,8 +776,14 @@ func (s *Server) Run(ctx context.Context, t Transport) error {
select { select {
case <-ctx.Done(): case <-ctx.Done():
ss.Close() ss.Close()
s.opts.Logger.Error("server run cancelled", "error", ctx.Err())
return ctx.Err() return ctx.Err()
case err := <-ssClosed: case err := <-ssClosed:
if err != nil {
s.opts.Logger.Error("server session ended with error", "error", err)
} else {
s.opts.Logger.Info("server session ended")
}
return err return err
} }
} }
@ -781,6 +799,7 @@ func (s *Server) bind(mcpConn Connection, conn *jsonrpc2.Connection, state *Serv
s.mu.Lock() s.mu.Lock()
s.sessions = append(s.sessions, ss) s.sessions = append(s.sessions, ss)
s.mu.Unlock() s.mu.Unlock()
s.opts.Logger.Info("server session connected", "session_id", ss.ID())
return ss return ss
} }
@ -796,6 +815,7 @@ func (s *Server) disconnect(cc *ServerSession) {
for _, subscribedSessions := range s.resourceSubscriptions { for _, subscribedSessions := range s.resourceSubscriptions {
delete(subscribedSessions, cc) delete(subscribedSessions, cc)
} }
s.opts.Logger.Info("server session disconnected", "session_id", cc.ID())
} }
// ServerSessionOptions configures the server session. // ServerSessionOptions configures the server session.
@ -820,7 +840,14 @@ func (s *Server) Connect(ctx context.Context, t Transport, opts *ServerSessionOp
state = opts.State state = opts.State
onClose = opts.onClose onClose = opts.onClose
} }
return connect(ctx, t, s, state, onClose)
s.opts.Logger.Info("server connecting")
ss, err := connect(ctx, t, s, state, onClose)
if err != nil {
s.opts.Logger.Error("server connect error", "error", err)
return nil, err
}
return ss, nil
} }
// TODO: (nit) move all ServerSession methods below the ServerSession declaration. // TODO: (nit) move all ServerSession methods below the ServerSession declaration.
@ -840,9 +867,11 @@ func (ss *ServerSession) initialized(ctx context.Context, params *InitializedPar
}) })
if !wasInit { if !wasInit {
ss.server.opts.Logger.Error("initialized before initialize")
return nil, fmt.Errorf("%q before %q", notificationInitialized, methodInitialize) return nil, fmt.Errorf("%q before %q", notificationInitialized, methodInitialize)
} }
if wasInitd { if wasInitd {
ss.server.opts.Logger.Error("duplicate initialized notification")
return nil, fmt.Errorf("duplicate %q received", notificationInitialized) return nil, fmt.Errorf("duplicate %q received", notificationInitialized)
} }
if ss.server.opts.KeepAlive > 0 { if ss.server.opts.KeepAlive > 0 {
@ -851,6 +880,7 @@ func (ss *ServerSession) initialized(ctx context.Context, params *InitializedPar
if h := ss.server.opts.InitializedHandler; h != nil { if h := ss.server.opts.InitializedHandler; h != nil {
h(ctx, serverRequestFor(ss, params)) h(ctx, serverRequestFor(ss, params))
} }
ss.server.opts.Logger.Info("session initialized")
return nil, nil return nil, nil
} }
@ -1088,6 +1118,7 @@ func (ss *ServerSession) handle(ctx context.Context, req *jsonrpc.Request) (any,
case methodInitialize, methodPing, notificationInitialized: case methodInitialize, methodPing, notificationInitialized:
default: default:
if !initialized { if !initialized {
ss.server.opts.Logger.Error("method invalid during initialization", "method", req.Method)
return nil, fmt.Errorf("method %q is invalid during session initialization", req.Method) return nil, fmt.Errorf("method %q is invalid during session initialization", req.Method)
} }
} }
@ -1144,6 +1175,7 @@ func (ss *ServerSession) setLevel(_ context.Context, params *SetLoggingLevelPara
ss.updateState(func(state *ServerSessionState) { ss.updateState(func(state *ServerSessionState) {
state.LogLevel = params.Level state.LogLevel = params.Level
}) })
ss.server.opts.Logger.Info("client log level set", "level", params.Level)
return &emptyResult{}, nil return &emptyResult{}, nil
} }

View file

@ -68,6 +68,10 @@ type StreamableHTTPOptions struct {
// //
// [§2.1.5]: https://modelcontextprotocol.io/specification/2025-06-18/basic/transports#sending-messages-to-the-server // [§2.1.5]: https://modelcontextprotocol.io/specification/2025-06-18/basic/transports#sending-messages-to-the-server
JSONResponse bool JSONResponse bool
// Logger specifies the logger to use.
// If nil, do not log.
Logger *slog.Logger
} }
// NewStreamableHTTPHandler returns a new [StreamableHTTPHandler]. // NewStreamableHTTPHandler returns a new [StreamableHTTPHandler].
@ -83,6 +87,11 @@ func NewStreamableHTTPHandler(getServer func(*http.Request) *Server, opts *Strea
if opts != nil { if opts != nil {
h.opts = *opts h.opts = *opts
} }
if h.opts.Logger == nil { // ensure we have a logger
h.opts.Logger = ensureLogger(nil)
}
return h return h
} }
@ -368,6 +377,8 @@ type StreamableServerTransport struct {
// StreamableHTTPOptions.JSONResponse is exported. // StreamableHTTPOptions.JSONResponse is exported.
jsonResponse bool jsonResponse bool
logger *slog.Logger
// connection is non-nil if and only if the transport has been connected. // connection is non-nil if and only if the transport has been connected.
connection *streamableServerConn connection *streamableServerConn
} }
@ -382,6 +393,7 @@ func (t *StreamableServerTransport) Connect(ctx context.Context) (Connection, er
stateless: t.Stateless, stateless: t.Stateless,
eventStore: t.EventStore, eventStore: t.EventStore,
jsonResponse: t.jsonResponse, jsonResponse: t.jsonResponse,
logger: t.logger,
incoming: make(chan jsonrpc.Message, 10), incoming: make(chan jsonrpc.Message, 10),
done: make(chan struct{}), done: make(chan struct{}),
streams: make(map[string]*stream), streams: make(map[string]*stream),
@ -408,6 +420,8 @@ type streamableServerConn struct {
jsonResponse bool jsonResponse bool
eventStore EventStore eventStore EventStore
logger *slog.Logger
incoming chan jsonrpc.Message // messages from the client to the server incoming chan jsonrpc.Message // messages from the client to the server
mu sync.Mutex // guards all fields below mu sync.Mutex // guards all fields below
@ -755,7 +769,7 @@ func (c *streamableServerConn) respondSSE(stream *stream, w http.ResponseWriter,
} }
if _, err := writeEvent(w, e); err != nil { if _, err := writeEvent(w, e); err != nil {
// Connection closed or broken. // Connection closed or broken.
// TODO(#170): log when we add server-side logging. c.logger.Warn("error writing event", "error", err)
return false return false
} }
writes++ writes++
@ -774,7 +788,13 @@ func (c *streamableServerConn) respondSSE(stream *stream, w http.ResponseWriter,
// simplify. // simplify.
http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError)
} else { } else {
// TODO(#170): log when we add server-side logging if ctx.Err() != nil {
// Client disconnected or cancelled the request.
c.logger.Error("stream context done", "error", ctx.Err())
} else {
// Some other error.
c.logger.Error("error receiving message", "error", err)
}
} }
return return
} }