github--github-mcp-server/pkg/github/logging_middleware.go

package github

import (
	"context"
	"log/slog"
	"time"

	"github.com/github/github-mcp-server/pkg/observability"
	"github.com/modelcontextprotocol/go-sdk/mcp"
)

// MCPMethodCallTool is the JSON-RPC method name for MCP tool invocations.
// The SDK keeps its equivalent constant unexported, so we mirror it here.
const MCPMethodCallTool = "tools/call"

// ToolLoggingMiddleware returns an MCP middleware that uniformly logs every
// tool invocation with its name, duration, and outcome, and exposes a
// request-scoped *slog.Logger via observability.ContextWithLogger so tool
// handlers can retrieve an enriched logger from deps.Logger(ctx).
//
// Logging policy:
//   - tools/call success: logged at Debug with tool name and duration.
//   - tools/call failure (error return or IsError result): logged at Error
//     with tool name, duration, and the error when present.
//   - Non-tool methods pass through without emitting any log line; the
//     middleware only attaches an enriched logger so downstream code can
//     still benefit from the method tag if it chooses to log.
//
// The base logger comes from ToolDependencies on the context (populated by
// InjectDepsMiddleware), so this middleware must be registered AFTER
// InjectDepsMiddleware in the receiving middleware chain.
func ToolLoggingMiddleware() mcp.Middleware {
	return func(next mcp.MethodHandler) mcp.MethodHandler {
		return func(ctx context.Context, method string, req mcp.Request) (mcp.Result, error) {
			deps, ok := DepsFromContext(ctx)
			if !ok {
				// Deps not injected yet; nothing we can do but pass through.
				return next(ctx, method, req)
			}

			base := deps.Logger(ctx)
			if base == nil {
				return next(ctx, method, req)
			}

			logger := base.With(slog.String("mcp.method", method))
			toolName := toolNameFromRequest(method, req)
			if toolName != "" {
				logger = logger.With(slog.String("mcp.tool", toolName))
			}

			ctx = observability.ContextWithLogger(ctx, logger)

			// Only time+log for tool calls. Other methods (initialize,
			// resources/list, etc.) are infrastructure chatter we leave
			// to the SDK unless a handler chooses to log explicitly.
			if method != MCPMethodCallTool {
				return next(ctx, method, req)
			}

			start := time.Now()
			result, err := next(ctx, method, req)
			duration := time.Since(start)

			switch {
			case err != nil:
				logger.LogAttrs(ctx, slog.LevelError, "tool call failed",
					slog.Duration("duration", duration),
					slog.String("error", err.Error()),
				)
			case isErrorResult(result):
				logger.LogAttrs(ctx, slog.LevelError, "tool call returned error result",
					slog.Duration("duration", duration),
				)
			default:
				logger.LogAttrs(ctx, slog.LevelDebug, "tool call succeeded",
					slog.Duration("duration", duration),
				)
			}

			return result, err
		}
	}
}

// toolNameFromRequest extracts the tool name from a tools/call request.
// Returns "" for other methods or when the name cannot be determined.
func toolNameFromRequest(method string, req mcp.Request) string {
	if method != MCPMethodCallTool || req == nil {
		return ""
	}
	switch p := req.GetParams().(type) {
	case *mcp.CallToolParams:
		if p != nil {
			return p.Name
		}
	case *mcp.CallToolParamsRaw:
		if p != nil {
			return p.Name
		}
	}
	return ""
}

// isErrorResult reports whether the MCP result represents a tool-reported
// error (CallToolResult.IsError == true). A returned Go error is handled
// separately by the caller.
func isErrorResult(r mcp.Result) bool {
	if r == nil {
		return false
	}
	if ctr, ok := r.(*mcp.CallToolResult); ok && ctr != nil {
		return ctr.IsError
	}
	return false
}