From 1dcbf62661fc9c54ae364e0af80433db347e2fc4 Mon Sep 17 00:00:00 2001 From: Suraj Bobade Date: Fri, 3 Oct 2025 00:14:32 +0530 Subject: [PATCH] mcp/server: enable server logging (#501) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- mcp/logging.go | 17 +++++++++++++++++ mcp/server.go | 34 +++++++++++++++++++++++++++++++++- mcp/streamable.go | 24 ++++++++++++++++++++++-- 3 files changed, 72 insertions(+), 3 deletions(-) diff --git a/mcp/logging.go b/mcp/logging.go index b3186a9..208427e 100644 --- a/mcp/logging.go +++ b/mcp/logging.go @@ -88,6 +88,23 @@ type LoggingHandler struct { 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 // [slog.JSONHandler]. func NewLoggingHandler(ss *ServerSession, opts *LoggingHandlerOptions) *LoggingHandler { diff --git a/mcp/server.go b/mcp/server.go index 44483af..f5b99cf 100644 --- a/mcp/server.go +++ b/mcp/server.go @@ -12,6 +12,7 @@ import ( "encoding/json" "fmt" "iter" + "log/slog" "maps" "net/url" "path/filepath" @@ -54,6 +55,8 @@ type Server struct { type ServerOptions struct { // Optional instructions for connected clients. Instructions string + // If non-nil, log server activity. + Logger *slog.Logger // If non-nil, called when "notifications/initialized" is received. InitializedHandler func(context.Context, *InitializedRequest) // 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 } + if opts.Logger == nil { // ensure we have a logger + opts.Logger = ensureLogger(nil) + } + return &Server{ impl: impl, opts: opts, @@ -695,6 +702,7 @@ func (s *Server) ResourceUpdated(ctx context.Context, params *ResourceUpdatedNot sessions := slices.Collect(maps.Keys(subscribedSessions)) s.mu.Unlock() notifySessions(sessions, notificationResourceUpdated, params) + s.opts.Logger.Info("resource updated notification sent", "uri", params.URI, "subscriber_count", len(sessions)) 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][req.Session] = true + s.opts.Logger.Info("resource subscribed", "uri", req.Params.URI, "session_id", req.Session.ID()) return &emptyResult{}, nil } @@ -733,6 +742,7 @@ func (s *Server) unsubscribe(ctx context.Context, req *UnsubscribeRequest) (*emp delete(s.resourceSubscriptions, req.Params.URI) } } + s.opts.Logger.Info("resource unsubscribed", "uri", req.Params.URI, "session_id", req.Session.ID()) 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, // as with [StreamableHTTPHandler]. func (s *Server) Run(ctx context.Context, t Transport) error { + s.opts.Logger.Info("server run start") ss, err := s.Connect(ctx, t, nil) if err != nil { + s.opts.Logger.Error("server connect failed", "error", err) return err } @@ -764,8 +776,14 @@ func (s *Server) Run(ctx context.Context, t Transport) error { select { case <-ctx.Done(): ss.Close() + s.opts.Logger.Error("server run cancelled", "error", ctx.Err()) return ctx.Err() 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 } } @@ -781,6 +799,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()) return ss } @@ -796,6 +815,7 @@ func (s *Server) disconnect(cc *ServerSession) { for _, subscribedSessions := range s.resourceSubscriptions { delete(subscribedSessions, cc) } + s.opts.Logger.Info("server session disconnected", "session_id", cc.ID()) } // ServerSessionOptions configures the server session. @@ -820,7 +840,14 @@ func (s *Server) Connect(ctx context.Context, t Transport, opts *ServerSessionOp state = opts.State 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. @@ -840,9 +867,11 @@ func (ss *ServerSession) initialized(ctx context.Context, params *InitializedPar }) if !wasInit { + ss.server.opts.Logger.Error("initialized before initialize") return nil, fmt.Errorf("%q before %q", notificationInitialized, methodInitialize) } if wasInitd { + ss.server.opts.Logger.Error("duplicate initialized notification") return nil, fmt.Errorf("duplicate %q received", notificationInitialized) } 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 { h(ctx, serverRequestFor(ss, params)) } + ss.server.opts.Logger.Info("session initialized") return nil, nil } @@ -1088,6 +1118,7 @@ func (ss *ServerSession) handle(ctx context.Context, req *jsonrpc.Request) (any, case methodInitialize, methodPing, notificationInitialized: default: 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) } } @@ -1144,6 +1175,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) return &emptyResult{}, nil } diff --git a/mcp/streamable.go b/mcp/streamable.go index a96386d..4886f80 100644 --- a/mcp/streamable.go +++ b/mcp/streamable.go @@ -68,6 +68,10 @@ type StreamableHTTPOptions struct { // // [§2.1.5]: https://modelcontextprotocol.io/specification/2025-06-18/basic/transports#sending-messages-to-the-server JSONResponse bool + + // Logger specifies the logger to use. + // If nil, do not log. + Logger *slog.Logger } // NewStreamableHTTPHandler returns a new [StreamableHTTPHandler]. @@ -83,6 +87,11 @@ func NewStreamableHTTPHandler(getServer func(*http.Request) *Server, opts *Strea if opts != nil { h.opts = *opts } + + if h.opts.Logger == nil { // ensure we have a logger + h.opts.Logger = ensureLogger(nil) + } + return h } @@ -368,6 +377,8 @@ type StreamableServerTransport struct { // StreamableHTTPOptions.JSONResponse is exported. jsonResponse bool + logger *slog.Logger + // connection is non-nil if and only if the transport has been connected. connection *streamableServerConn } @@ -382,6 +393,7 @@ func (t *StreamableServerTransport) Connect(ctx context.Context) (Connection, er stateless: t.Stateless, eventStore: t.EventStore, jsonResponse: t.jsonResponse, + logger: t.logger, incoming: make(chan jsonrpc.Message, 10), done: make(chan struct{}), streams: make(map[string]*stream), @@ -408,6 +420,8 @@ type streamableServerConn struct { jsonResponse bool eventStore EventStore + logger *slog.Logger + incoming chan jsonrpc.Message // messages from the client to the server 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 { // Connection closed or broken. - // TODO(#170): log when we add server-side logging. + c.logger.Warn("error writing event", "error", err) return false } writes++ @@ -774,7 +788,13 @@ func (c *streamableServerConn) respondSSE(stream *stream, w http.ResponseWriter, // simplify. http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) } 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 }