From 0071cfdd5d50d4a96f7f7deb2f666e22cf7d99bd Mon Sep 17 00:00:00 2001 From: Algis Dumbris Date: Wed, 23 Sep 2026 08:08:42 +0300 Subject: [PATCH 1/2] fix(security): redact the request path on the MCP and OAuth-callback log lines MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit SEC-01 left two log sinks writing `r.URL.Path` with no redaction at all — not even the name/shape rules that predate PR #1350. internal/server/server.go — the MCP mux's logging wrapper wrote `zap.String("path", r.URL.Path)` three times per request (Debug on arrival, then Debug or Warn on completion), plus four more in the deadline helpers. `/mcp/` and `/mcp/p/` are registered as SUBTREE patterns, so every byte after the prefix is whatever the caller sent; `ExtractToken` accepts `?apikey=` on this very endpoint, so the admin key in the wrong part of the URL is not a hypothetical shape; and r.URL.Path arrives percent-DECODED, so `GET /mcp/%3Fapikey%3D` reaches the handler as the path `/mcp/?apikey=`. The completion line fires at Warn on any >=400 response, which is the DEFAULT log level — no debug flag involved. internal/oauth/config.go — the loopback callback listener redacted its query (LogSafeCallbackQuery, #1158) but logged the path raw at Info, in both the listener handler and handleCallback. The callback path is normally a fixed operator-configured value, so this closes an inconsistency rather than a demonstrated leak; it is still a client-controlled sink, since the handler has no mux in front of it and every path reaches the log line. Both now go through oauth.LogSafeRequestPath, the renderer internal/httpapi's access log already uses. The MCP wrapper renders it ONCE for all three of its lines: zap evaluates a field eagerly, so an unrendered path would be paid for at every log level, and the renderer walks the path per segment. internal/oauth/logging.go — LogSafeRequestPath did not actually cover the shape above. logSafeURLComponent split only on '/', so the decoded segment `?apikey=` was handed to the name rule as the parameter name "?apikey", which matches nothing, and a 64-char hex value is under the entropy detector's threshold: the live admin key survived into the field. A path segment carries `k=v` pairs after a '?' exactly as a fragment does, and logSafeFragment already allowed for that. logSafePathSegment does the same for the path. The two handler closures were lifted to methods (Server.mcpLoggingHandler, CallbackServer.handleRequest) with no behavior change, so the log fields are reachable from a test without binding a listener. Co-Authored-By: Claude Opus 5 --- .../oauth/callback_path_redaction_test.go | 111 +++++++++++++++ internal/oauth/config.go | 76 +++++++---- internal/oauth/logging.go | 31 ++++- .../server/mcp_logging_path_redaction_test.go | 125 +++++++++++++++++ internal/server/server.go | 126 ++++++++++-------- 5 files changed, 386 insertions(+), 83 deletions(-) create mode 100644 internal/oauth/callback_path_redaction_test.go create mode 100644 internal/server/mcp_logging_path_redaction_test.go diff --git a/internal/oauth/callback_path_redaction_test.go b/internal/oauth/callback_path_redaction_test.go new file mode 100644 index 000000000..4ce5e4673 --- /dev/null +++ b/internal/oauth/callback_path_redaction_test.go @@ -0,0 +1,111 @@ +package oauth + +import ( + "net/http" + "net/http/httptest" + "testing" + + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zaptest/observer" +) + +// SEC-01 follow-up. The OAuth loopback callback listener redacted its QUERY +// (LogSafeCallbackQuery, issue #1158) but logged `zap.String("path", +// r.URL.Path)` verbatim at INFO, in two places: the listener's own handler and +// handleCallback below it. +// +// The callback path is normally a fixed operator-configured value, so this is +// consistency work rather than a demonstrated leak of the user's own admin key. +// It is still a real client-controlled sink: the handler is a bare +// http.HandlerFunc with no mux in front of it (deliberately — see the comment +// in StartCallbackServer), so EVERY path reaches the log line, including the +// ones that fall through to the debug page; the listener is a plain loopback +// HTTP server that any local process or any page in the user's browser can +// reach for the whole login window; and r.URL.Path arrives percent-decoded, so +// `%3Fapikey%3D` and `Bearer%20` land here as the real thing. +// +// Every other field on these two lines already goes through this package's +// redactors. The path was the one that did not. + +// newObservedCallbackServerAtPath builds a CallbackServer wired to an +// in-memory log sink and serving `path`, so the fall-through (debug page) +// branch of handleRequest can be exercised. +func newObservedCallbackServerAtPath(t *testing.T, path string) (*CallbackServer, *observer.ObservedLogs) { + t.Helper() + core, logs := observer.New(zap.DebugLevel) + return &CallbackServer{ + ServerName: "alpha", + Path: path, + Port: 53682, + logger: zap.New(core), + waiters: make(map[string]chan map[string]string), + }, logs +} + +// callbackKeyInPath is the shape an `?apikey=` credential takes once it has +// been percent-decoded into r.URL.Path. 64 hex characters is what +// cmd/mcpproxy generates for the admin key. +const callbackKeyInPath = "4f3c2b1a9e8d7c6b5a4f3e2d1c0b9a8f7e6d5c4b3a2f1e0d9c8b7a6f5e4d3c2b" + +func TestCallbackListenerRedactsACredentialInTheRequestPath(t *testing.T) { + cs, logs := newObservedCallbackServerAtPath(t, DefaultRedirectPath) + + cs.handleRequest(httptest.NewRecorder(), + httptest.NewRequest(http.MethodGet, "/probe/apikey="+callbackKeyInPath, nil)) + + out := renderedLines(logs) + require.NotEmpty(t, out, "the handler must still log — a fix that deletes the line is not the fix") + require.Contains(t, out, "/probe/", "the diagnostic part of the path must survive redaction") + assertNoRun(t, out, callbackKeyInPath, 12) +} + +func TestHandleCallbackRedactsACredentialInTheRequestPath(t *testing.T) { + cs, logs := newObservedCallbackServerAtPath(t, DefaultRedirectPath) + + cs.handleCallback(httptest.NewRecorder(), + httptest.NewRequest(http.MethodGet, + DefaultRedirectPath+"/apikey="+callbackKeyInPath+"?error=access_denied", nil)) + + assertNoRun(t, renderedLines(logs), callbackKeyInPath, 12) +} + +// r.URL.Path arrives percent-decoded, so `Bearer%20` reaches this log +// field as a real `Bearer ` — a shape no `name=value` rule can see. +func TestCallbackListenerRedactsABearerTokenInTheRequestPath(t *testing.T) { + const agentToken = "mcp_agt_Zt7Qv2Lm9XbR4pWc8HsKd3Ng6JyF1aUe" + + cs, logs := newObservedCallbackServerAtPath(t, DefaultRedirectPath) + + cs.handleRequest(httptest.NewRecorder(), + httptest.NewRequest(http.MethodGet, "/probe/Bearer%20"+agentToken, nil)) + + assertNoRun(t, renderedLines(logs), agentToken, 12) +} + +// TestLogSafeRequestPathRedactsAnEncodedQueryInsideThePath covers the shape +// that makes the two path sinks a LIVE-credential risk rather than a purely +// theoretical one, and that LogSafeRequestPath did not handle. +// +// `?apikey=` is the credential form mcpproxy's own Connect wizard and Web +// UI hand out, and a client that percent-encodes its URL suffix sends +// `/mcp/%3Fapikey%3D` — which net/http decodes into +// r.URL.Path == "/mcp/?apikey=" before any handler sees it. ServeMux +// matches that against the `/mcp/` SUBTREE pattern, so it reaches the handler, +// and the log field gets the decoded form. +// +// logSafeURLComponent split only on '/', so the segment handed to the name rule +// was "?apikey=" — whose parameter name reads as "?apikey", which matches +// nothing — and the value is plain hex, under the entropy detector's threshold. +// The credential went to disk in the clear. A path segment carries `k=v` pairs +// after a '?' exactly as a fragment does, and logSafeFragment already accounted +// for that; the path did not. +func TestLogSafeRequestPathRedactsAnEncodedQueryInsideThePath(t *testing.T) { + r := httptest.NewRequest(http.MethodGet, "/mcp/%3Fapikey%3D"+callbackKeyInPath, nil) + require.Equal(t, "/mcp/?apikey="+callbackKeyInPath, r.URL.Path, + "net/http must still hand the handler a DECODED path — the premise of this test") + + rendered := LogSafeRequestPath(r.URL.Path) + require.Contains(t, rendered, "/mcp/", "the diagnostic part of the path must survive redaction") + assertNoRun(t, rendered, callbackKeyInPath, 12) +} diff --git a/internal/oauth/config.go b/internal/oauth/config.go index 1bc765fc5..78eb68f2c 100644 --- a/internal/oauth/config.go +++ b/internal/oauth/config.go @@ -1550,34 +1550,7 @@ func (m *CallbackServerManager) StartCallbackServerOnHost(serverName string, bin // redirected instead of delivered, and the login hangs. // A raw handler function receives r.URL.Path exactly as net/http parsed // it, with neither risk. - handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - callbackServer.logger.Info("📥 HTTP request received on callback server", - zap.String("method", r.Method), - zap.String("path", r.URL.Path), - zap.String("query", LogSafeCallbackQuery(r.URL.RawQuery)), - zap.String("user_agent", r.UserAgent()), - zap.String("remote_addr", r.RemoteAddr)) - - if r.URL.Path == path { - callbackServer.handleCallback(w, r) - } else { - w.Header().Set("Content-Type", "text/html") - debugPage := fmt.Sprintf(` - - -

OAuth Callback Server Debug

-

Path: %s

-

Expected: %s

-

Server: %s

-

Port: %d

- - - `, html.EscapeString(r.URL.Path), html.EscapeString(path), html.EscapeString(serverName), port) - if _, err := w.Write([]byte(debugPage)); err != nil { - callbackServer.logger.Error("Error writing debug page", zap.Error(err)) - } - } - }) + handler := http.HandlerFunc(callbackServer.handleRequest) server := &http.Server{ Addr: listenAddr, @@ -1726,11 +1699,56 @@ func callbackPage(title, message string) string { `, html.EscapeString(title), html.EscapeString(message), closeScript) } +// handleRequest is the callback listener's only handler: it logs the request, +// then either delivers a real callback or renders the debug page. A method +// rather than a closure in StartCallbackServer so the log fields it writes are +// reachable from a test without binding a listener; it reads c.Path, +// c.ServerName and c.Port, which are exactly the values the closure captured. +// +// SEC-01 follow-up: `path` goes through LogSafeRequestPath like every other +// field on this line. The callback path is normally a fixed, operator- +// configured value, so this closes an inconsistency rather than a demonstrated +// leak — but there is no mux in front of this handler (deliberately, see +// StartCallbackServer), so EVERY path reaches the log line including the ones +// that fall through to the debug page; the listener is a plain loopback HTTP +// server any local process can reach for the whole login window; and +// r.URL.Path arrives percent-DECODED, so an encoded `?apikey=` or +// `Bearer ` in the request target lands here as the real thing. +func (c *CallbackServer) handleRequest(w http.ResponseWriter, r *http.Request) { + c.logger.Info("📥 HTTP request received on callback server", + zap.String("method", r.Method), + zap.String("path", LogSafeRequestPath(r.URL.Path)), + zap.String("query", LogSafeCallbackQuery(r.URL.RawQuery)), + zap.String("user_agent", r.UserAgent()), + zap.String("remote_addr", r.RemoteAddr)) + + if r.URL.Path == c.Path { + c.handleCallback(w, r) + return + } + + w.Header().Set("Content-Type", "text/html") + debugPage := fmt.Sprintf(` + + +

OAuth Callback Server Debug

+

Path: %s

+

Expected: %s

+

Server: %s

+

Port: %d

+ + + `, html.EscapeString(r.URL.Path), html.EscapeString(c.Path), html.EscapeString(c.ServerName), c.Port) + if _, err := w.Write([]byte(debugPage)); err != nil { + c.logger.Error("Error writing debug page", zap.Error(err)) + } +} + // handleCallback handles OAuth callback requests func (c *CallbackServer) handleCallback(w http.ResponseWriter, r *http.Request) { c.logger.Info("🎯 OAuth callback received", zap.String("method", r.Method), - zap.String("path", r.URL.Path), + zap.String("path", LogSafeRequestPath(r.URL.Path)), zap.String("query", LogSafeCallbackQuery(r.URL.RawQuery)), zap.String("remote_addr", r.RemoteAddr), zap.String("user_agent", r.UserAgent())) diff --git a/internal/oauth/logging.go b/internal/oauth/logging.go index 3e036a24a..6a5cde542 100644 --- a/internal/oauth/logging.go +++ b/internal/oauth/logging.go @@ -1248,11 +1248,40 @@ func logSafeURLComponent(s string) string { s = tokenPattern.ReplaceAllString(redactURLUserinfo(s), "${1}"+redactedMarker) segments := strings.Split(s, "/") for i, segment := range segments { - segments[i] = LogSafeQueryString(segment) + segments[i] = logSafePathSegment(segment) } return MaskDetectedSecrets(strings.Join(segments, "/")) } +// logSafePathSegment applies the name rule to ONE path segment, treating +// anything after a '?' inside it as a query of its own. +// +// The '?' split is not hypothetical tidying. r.URL.Path is what net/http hands +// a handler and it arrives percent-DECODED, so a client that encodes its URL +// suffix — `GET /mcp/%3Fapikey%3D`, which ServeMux still matches against +// the `/mcp/` subtree pattern — produces the path `/mcp/?apikey=`. +// Splitting on '/' alone left the segment `?apikey=`, whose parameter name +// reads as "?apikey" and so matches no name rule, and whose plain-hex value is +// under the entropy detector's threshold: the live admin key reached the log +// field in the clear. logSafeFragment already made exactly this allowance for a +// fragment; a decoded path needs it for the same reason. +// +// Every '?'-delimited piece is redacted, not just the first: a second '?' is +// otherwise swallowed into a parameter VALUE, where the name rule stops +// looking. The cost stays bounded by the caller's input cap — the pieces +// partition the segment, so the total work over a path is still linear in its +// (capped) length. +func logSafePathSegment(segment string) string { + if !strings.Contains(segment, "?") { + return LogSafeQueryString(segment) + } + pieces := strings.Split(segment, "?") + for i, piece := range pieces { + pieces[i] = LogSafeQueryString(piece) + } + return strings.Join(pieces, "?") +} + // logSafeFragment redacts a URL fragment. No URL renderer applies the name rule // there, but a fragment carries `k=v` pairs as readily as a query does — hash // routing puts a whole path and query after the '#' — so the same rule runs over diff --git a/internal/server/mcp_logging_path_redaction_test.go b/internal/server/mcp_logging_path_redaction_test.go new file mode 100644 index 000000000..e3285687a --- /dev/null +++ b/internal/server/mcp_logging_path_redaction_test.go @@ -0,0 +1,125 @@ +package server + +import ( + "fmt" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zaptest/observer" +) + +// SEC-01 follow-up. PR #1350 routed every `path` log field in internal/httpapi +// through oauth.LogSafeRequestPath. The MCP mux's own logging wrapper was left +// behind: it wrote `zap.String("path", r.URL.Path)` verbatim, three times per +// request (Debug on arrival, then Debug or Warn on completion). +// +// That is a live sink for a client-controlled string. `/mcp/` and `/mcp/p/` are +// registered as SUBTREE patterns, so every byte after the prefix is whatever +// the caller sent; `ExtractToken` accepts `?apikey=` on this very +// endpoint, so a client configured with the key in the wrong part of the URL is +// not a hypothetical shape; and r.URL.Path arrives percent-DECODED, so +// `%3Fapikey%3D` and `Bearer%20` both land here as the real thing. The +// completion line is logged at Warn on any >=400 response, which is on at the +// DEFAULT log level — no debug flag involved. +// +// The oracle is the one issue #1158 settled on: no RUN of the credential's +// bytes may survive anywhere in the rendered line. A whole-string containment +// check passes against a half-mask. +func assertNoCredentialRun(t *testing.T, rendered, secret string, minRun int) { + t.Helper() + for i := 0; i+minRun <= len(secret); i++ { + assert.NotContains(t, rendered, secret[i:i+minRun], + "a %d-byte run of the credential survived into %q", minRun, rendered) + } +} + +func renderObservedLines(logs *observer.ObservedLogs) string { + var b strings.Builder + for _, entry := range logs.All() { + b.WriteString(entry.Message) + for k, v := range entry.ContextMap() { + fmt.Fprintf(&b, " %s=%v", k, v) + } + b.WriteString("\n") + } + return b.String() +} + +// newObservedMCPLoggingHandler builds the MCP logging wrapper against an +// in-memory log sink. mcpLoggingHandler reads nothing from Server but the +// logger, so no runtime, storage or listener is needed. +func newObservedMCPLoggingHandler(t *testing.T, status int) (http.Handler, *observer.ObservedLogs) { + t.Helper() + core, logs := observer.New(zap.DebugLevel) + s := &Server{logger: zap.New(core)} + return s.mcpLoggingHandler(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(status) + })), logs +} + +// adminKeyInPath is the shape an `?apikey=` credential takes once it has been +// percent-decoded into r.URL.Path, or typed into the path by a +// misconfigured client. 64 hex characters is what cmd/mcpproxy generates. +const adminKeyInPath = "4f3c2b1a9e8d7c6b5a4f3e2d1c0b9a8f7e6d5c4b3a2f1e0d9c8b7a6f5e4d3c2b" + +func TestMCPLoggingHandlerRedactsANamedCredentialInThePath(t *testing.T) { + handler, logs := newObservedMCPLoggingHandler(t, http.StatusOK) + + handler.ServeHTTP(httptest.NewRecorder(), + httptest.NewRequest(http.MethodGet, "/mcp/apikey="+adminKeyInPath, nil)) + + out := renderObservedLines(logs) + require.NotEmpty(t, out, "the handler must still log — a fix that deletes the line is not the fix") + require.Contains(t, out, "/mcp/", "the diagnostic part of the path must survive redaction") + assertNoCredentialRun(t, out, adminKeyInPath, 12) +} + +// The completion line at Warn is the one that fires at the DEFAULT log level, +// so it is the one that actually writes to main.log on a stock install. +func TestMCPLoggingHandlerRedactsThePathOnTheWarnCompletionLine(t *testing.T) { + handler, logs := newObservedMCPLoggingHandler(t, http.StatusNotFound) + + handler.ServeHTTP(httptest.NewRecorder(), + httptest.NewRequest(http.MethodGet, "/mcp/p/apikey="+adminKeyInPath, nil)) + + warnLines := logs.FilterLevelExact(zap.WarnLevel).All() + require.NotEmpty(t, warnLines, "a >=400 response must still be logged at Warn") + assertNoCredentialRun(t, renderObservedLines(logs), adminKeyInPath, 12) +} + +// r.URL.Path arrives percent-decoded, so `Bearer%20` in the request +// target reaches this log field as a real `Bearer ` — a shape no +// `name=value` rule can see. LogSafeRequestPath applies the token rule for it. +func TestMCPLoggingHandlerRedactsABearerTokenInThePath(t *testing.T) { + const agentToken = "mcp_agt_Zt7Qv2Lm9XbR4pWc8HsKd3Ng6JyF1aUe" + + handler, logs := newObservedMCPLoggingHandler(t, http.StatusOK) + + handler.ServeHTTP(httptest.NewRecorder(), + httptest.NewRequest(http.MethodGet, "/mcp/Bearer%20"+agentToken, nil)) + + assertNoCredentialRun(t, renderObservedLines(logs), agentToken, 12) +} + +// The realistic delivery vehicle for the LIVE admin key. `?apikey=` is the +// credential form mcpproxy's own Connect wizard and Web UI hand out, and +// net/http hands the handler a percent-DECODED r.URL.Path — so a client that +// encodes its URL suffix turns `GET /mcp/%3Fapikey%3D` into the path +// `/mcp/?apikey=`, which ServeMux still matches against the `/mcp/` +// subtree pattern and which this log field then received verbatim. +func TestMCPLoggingHandlerRedactsAnEncodedQueryInsideThePath(t *testing.T) { + handler, logs := newObservedMCPLoggingHandler(t, http.StatusOK) + + req := httptest.NewRequest(http.MethodGet, "/mcp/%3Fapikey%3D"+adminKeyInPath, nil) + require.Equal(t, "/mcp/?apikey="+adminKeyInPath, req.URL.Path, + "net/http must still hand the handler a DECODED path — the premise of this test") + + handler.ServeHTTP(httptest.NewRecorder(), req) + + assertNoCredentialRun(t, renderObservedLines(logs), adminKeyInPath, 12) +} diff --git a/internal/server/server.go b/internal/server/server.go index 3e4f3d741..700ecf27c 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -2741,12 +2741,12 @@ func (s *Server) extendedDeadline(d time.Duration, next http.Handler) http.Handl rc := http.NewResponseController(w) if err := rc.SetWriteDeadline(deadline); err != nil { s.logger.Debug("Could not extend the write deadline for a long-running route", - zap.String("path", r.URL.Path), + zap.String("path", oauth.LogSafeRequestPath(r.URL.Path)), zap.Error(err)) } if err := rc.SetReadDeadline(deadline); err != nil { s.logger.Debug("Could not extend the read deadline for a long-running route", - zap.String("path", r.URL.Path), + zap.String("path", oauth.LogSafeRequestPath(r.URL.Path)), zap.Error(err)) } next.ServeHTTP(w, r) @@ -2792,13 +2792,13 @@ func (s *Server) streamingNoDeadline(next http.Handler) http.Handler { rc := http.NewResponseController(w) if err := rc.SetWriteDeadline(time.Time{}); err != nil { s.logger.Debug("Could not clear the write deadline for a streaming route", - zap.String("path", r.URL.Path), + zap.String("path", oauth.LogSafeRequestPath(r.URL.Path)), zap.Error(err)) } if r.Method == http.MethodGet || r.Method == http.MethodHead { if err := rc.SetReadDeadline(time.Time{}); err != nil { s.logger.Debug("Could not clear the read deadline for a streaming route", - zap.String("path", r.URL.Path), + zap.String("path", oauth.LogSafeRequestPath(r.URL.Path)), zap.Error(err)) } } @@ -2897,55 +2897,7 @@ func (s *Server) startCustomHTTPServer(ctx context.Context, streamableServer *se mux := http.NewServeMux() // Create a logging wrapper for debugging client connections - loggingHandler := func(handler http.Handler) http.Handler { - return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - start := time.Now() - - // Extract connection source from context - source := GetConnectionSource(r.Context()) - - // Log incoming request with connection details - s.logger.Debug("MCP client request received", - zap.String("method", r.Method), - zap.String("path", r.URL.Path), - zap.String("remote_addr", r.RemoteAddr), - zap.String("source", string(source)), - zap.String("user_agent", r.UserAgent()), - zap.String("content_type", r.Header.Get("Content-Type")), - zap.String("connection", r.Header.Get("Connection")), - zap.Int64("content_length", r.ContentLength), - ) - - // Create response writer wrapper to capture status and errors - wrappedWriter := &responseWriter{ResponseWriter: w, statusCode: 200} - - // Handle the request - handler.ServeHTTP(wrappedWriter, r) - - duration := time.Since(start) - - // Log response with timing and status - if wrappedWriter.statusCode >= 400 { - s.logger.Warn("MCP client request completed with error", - zap.String("method", r.Method), - zap.String("path", r.URL.Path), - zap.String("remote_addr", r.RemoteAddr), - zap.String("source", string(source)), - zap.Int("status_code", wrappedWriter.statusCode), - zap.Duration("duration", duration), - ) - } else { - s.logger.Debug("MCP client request completed successfully", - zap.String("method", r.Method), - zap.String("path", r.URL.Path), - zap.String("remote_addr", r.RemoteAddr), - zap.String("source", string(source)), - zap.Int("status_code", wrappedWriter.statusCode), - zap.Duration("duration", duration), - ) - } - }) - } + loggingHandler := s.mcpLoggingHandler // Standard MCP endpoint according to the specification // Wrap with auth middleware to inject AuthContext for agent token scope enforcement. @@ -4617,3 +4569,71 @@ func (p *configServerInfoProvider) IsConnected(serverName string) bool { } return serverStatus.Connected } + +// mcpLoggingHandler wraps an MCP route with the request/response debug lines +// that every /mcp mount shares. Extracted from startCustomHTTPServer so the +// log fields it writes are reachable from a test without binding a listener. +func (s *Server) mcpLoggingHandler(handler http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + start := time.Now() + + // Extract connection source from context + source := GetConnectionSource(r.Context()) + + // SEC-01 follow-up: `/mcp/` and `/mcp/p/` are SUBTREE patterns, so + // everything after the prefix is whatever the caller sent, and + // r.URL.Path arrives percent-DECODED — an `?apikey=` or a + // `Bearer ` encoded into the request target reaches this field + // as the real thing. The renderer is internal/oauth's, the same one + // internal/httpapi's access log uses: one rule for every log sink. + // + // Rendered ONCE for all three lines below. zap evaluates a field's + // value eagerly, so this runs whether or not Debug is enabled, and the + // renderer walks the path per segment; doing it twice per request + // would double that cost for nothing. Its input is capped inside + // LogSafeRequestPath (see maxLogSafeRequestBytes), which is what keeps + // the work per request bounded on this anonymous-by-default endpoint. + safePath := oauth.LogSafeRequestPath(r.URL.Path) + + // Log incoming request with connection details + s.logger.Debug("MCP client request received", + zap.String("method", r.Method), + zap.String("path", safePath), + zap.String("remote_addr", r.RemoteAddr), + zap.String("source", string(source)), + zap.String("user_agent", r.UserAgent()), + zap.String("content_type", r.Header.Get("Content-Type")), + zap.String("connection", r.Header.Get("Connection")), + zap.Int64("content_length", r.ContentLength), + ) + + // Create response writer wrapper to capture status and errors + wrappedWriter := &responseWriter{ResponseWriter: w, statusCode: 200} + + // Handle the request + handler.ServeHTTP(wrappedWriter, r) + + duration := time.Since(start) + + // Log response with timing and status + if wrappedWriter.statusCode >= 400 { + s.logger.Warn("MCP client request completed with error", + zap.String("method", r.Method), + zap.String("path", safePath), + zap.String("remote_addr", r.RemoteAddr), + zap.String("source", string(source)), + zap.Int("status_code", wrappedWriter.statusCode), + zap.Duration("duration", duration), + ) + } else { + s.logger.Debug("MCP client request completed successfully", + zap.String("method", r.Method), + zap.String("path", safePath), + zap.String("remote_addr", r.RemoteAddr), + zap.String("source", string(source)), + zap.Int("status_code", wrappedWriter.statusCode), + zap.Duration("duration", duration), + ) + } + }) +} From 4365ff6817227bfa7e7ccf78c89bf18a6ee94c5f Mon Sep 17 00:00:00 2001 From: Algis Dumbris Date: Wed, 23 Sep 2026 08:29:39 +0300 Subject: [PATCH 2/2] docs: name the right constructor in the handleRequest comment MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Cross-model review (zcode/GLM-5.3) on #1354: the comment pointed at StartCallbackServer, but the closure it replaced — and the ServeMux-avoidance rationale it refers to — live in StartCallbackServerOnHost. Co-Authored-By: Claude Opus 5 --- internal/oauth/config.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/internal/oauth/config.go b/internal/oauth/config.go index 78eb68f2c..2737995f5 100644 --- a/internal/oauth/config.go +++ b/internal/oauth/config.go @@ -1701,8 +1701,8 @@ func callbackPage(title, message string) string { // handleRequest is the callback listener's only handler: it logs the request, // then either delivers a real callback or renders the debug page. A method -// rather than a closure in StartCallbackServer so the log fields it writes are -// reachable from a test without binding a listener; it reads c.Path, +// rather than a closure in StartCallbackServerOnHost so the log fields it +// writes are reachable from a test without binding a listener; it reads c.Path, // c.ServerName and c.Port, which are exactly the values the closure captured. // // SEC-01 follow-up: `path` goes through LogSafeRequestPath like every other