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..2737995f5 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 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 +// 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), + ) + } + }) +}