From 05e1068719e8774d364aff099f53c7b9aaf07107 Mon Sep 17 00:00:00 2001 From: Algis Dumbris Date: Wed, 2 Sep 2026 07:41:22 +0300 Subject: [PATCH 1/4] fix(security): stop credentials reaching logs, stdout and structured errors (#1158) A default `mcpproxy serve` at DEBUG published an argv secret 12 times and a URL-query secret 8 times in a 20-second startup, with no trace mode enabled. Verified on a live instance: 24 cleartext occurrences across main.log, server-.log and the terminal, now 0. Four classes, four rules, all routed through seams the #1148/#1157 sweep already built rather than a new matcher. 1. Spawn argv. Every spawn log site used shellwrap.RedactDockerArgs alone - a STRUCTURAL rule that masks the value half of `-e KEY=VALUE` and is blind to `--api-key sk-live-...`. New oauth.Redaction.SpawnArgv / SpawnCommandString compose it with the SEMANTIC flag-name + value-shape rule (Redaction.Argv) and reach inside the single `-c ""` element the login-shell wrap produces - the form that actually leaked, since every non-docker stdio server on macOS spawns that way. Redaction.Argv itself is untouched: it backs the read doors and CheckArgvMaskEcho on the write doors, so the spawn rule has to be additive and log-only. There is deliberately no "already masked, skip" guard between the two stages - the bullet marker carries no character in secretPattern's value class, so stage 2 is provably a no-op on a stage-1 rendering, and a whole-token guard would silence stage 2 for an entire command string as soon as one benign `-e` put a marker in it. 2. The OAuth authorization URL - the largest leak, and one the site list missed. autoDetectResource returns the configured server URL verbatim on every fallback branch, that becomes extraParams["resource"], and all THREE authorize-URL emission paths splice it into the query and then log it at INFO and print it with fmt.Printf. Both sinks on all three paths now go through logSafeAuthURL, and the per-value extra-param Debug lines through Redaction.ExtraParamValue. The credential arrives percent-encoded one level down, where neither the sensitive-parameter name rule nor secretPattern can see it, so URLValueDeep decodes one nesting level. maskExtraParams no longer treats `resource` as a public endpoint. 3. URL log fields inside internal/oauth (~75 sites across discovery.go, config.go, transport_wrapper.go, persistent_token_store.go), plus the configured-URL field in runtime.go and the registry-source URLs in internal/server. They use the AUDIT rendering, not the name-rule-only RedactURLQueryParams the issue names, because a credential under an unrecognised parameter name still reached the log otherwise. url.URL.Redacted() is not used anywhere - it masks the userinfo password and leaves `?token=` intact. 4. The structured OAuth error is scrubbed where it is BUILT (createMetadataError and the seven contracts.OAuthErrorDetails literals), not where it is serialized: the encoder sees an opaque struct and cannot know which leaves are URLs, and every future consumer inherits the fix. Also: the trace transport's stdout Printf copies and zap fields (URL, headers, request/response bodies, SSE frames) - both sinks or neither; logSafeErrorField upgraded to ScrubUpstreamText; the launcher's startup banner takes an injected Spec.RedactArgs whose nil default OMITS argv, so a future caller that forgets it loses a diagnostic rather than a secret. Diagnostics are preserved throughout: flag names, env KEY names, and each URL's scheme/host/path survive; only values are replaced. Two AST guard tests derive the rule from the source across BOTH internal/oauth and internal/upstream/core, so the next URL log field or a re-raw'd authorize-URL Printf fails CI rather than shipping. Behaviour change to note: log lines, `mcpproxy upstream logs`, the `upstream_servers tail_log` MCP tool, `mcpproxy auth status/login` output and the 400 body of POST /api/v1/servers/{id}/login now render masked values where they previously showed cleartext. No config, storage, contract or frontend change. --- internal/appctx/adapters.go | 2 +- internal/oauth/authurl_redact_test.go | 144 ++++++++++++ internal/oauth/config.go | 36 +-- internal/oauth/discovery.go | 145 ++++++------ internal/oauth/logging.go | 38 ++++ internal/oauth/masking.go | 8 +- internal/oauth/persistent_token_store.go | 2 +- internal/oauth/redactview.go | 14 ++ internal/oauth/round8_doorscan_test.go | 4 - .../oauth/round8_renderer_discovery_test.go | 21 ++ internal/oauth/spawnargv.go | 215 ++++++++++++++++++ internal/oauth/spawnargv_test.go | 183 +++++++++++++++ internal/oauth/transport_wrapper.go | 8 +- internal/oauth/url_log_field_guard_test.go | 154 +++++++++++++ internal/runtime/runtime.go | 4 +- internal/server/add_registry_source.go | 4 +- internal/server/edit_registry_source.go | 2 +- internal/server/remove_registry_source.go | 3 +- internal/shellwrap/redact.go | 44 +++- internal/shellwrap/shellwrap.go | 22 +- internal/transport/logging.go | 36 ++- internal/transport/trace_redact_test.go | 151 ++++++++++++ internal/upstream/core/connection.go | 56 ++++- internal/upstream/core/connection_docker.go | 18 +- internal/upstream/core/connection_launcher.go | 9 +- .../upstream/core/connection_lifecycle.go | 8 +- internal/upstream/core/connection_oauth.go | 44 ++-- internal/upstream/core/connection_stdio.go | 10 +- internal/upstream/core/docker.go | 2 +- internal/upstream/core/process_unix.go | 3 +- internal/upstream/core/process_windows.go | 3 +- internal/upstream/core/spawn_redact_test.go | 169 ++++++++++++++ internal/upstream/launcher/launcher.go | 28 ++- .../upstream/launcher/launcher_redact_test.go | 120 ++++++++++ 34 files changed, 1530 insertions(+), 180 deletions(-) create mode 100644 internal/oauth/authurl_redact_test.go create mode 100644 internal/oauth/spawnargv.go create mode 100644 internal/oauth/spawnargv_test.go create mode 100644 internal/oauth/url_log_field_guard_test.go create mode 100644 internal/transport/trace_redact_test.go create mode 100644 internal/upstream/core/spawn_redact_test.go create mode 100644 internal/upstream/launcher/launcher_redact_test.go diff --git a/internal/appctx/adapters.go b/internal/appctx/adapters.go index 9f49fbcc5..21d12c7dd 100644 --- a/internal/appctx/adapters.go +++ b/internal/appctx/adapters.go @@ -128,7 +128,7 @@ func (d *DockerIsolationManagerImpl) StartIsolatedCommand(_ context.Context, com // For now, this is a placeholder that returns the concept d.logger.Info("Starting isolated command", zap.String("command", command), - zap.Strings("args", args), + zap.Strings("args", oauth.AuditRedaction.SpawnArgv(args)), zap.String("working_dir", workingDir)) return nil, fmt.Errorf("not implemented - would use isolation manager") diff --git a/internal/oauth/authurl_redact_test.go b/internal/oauth/authurl_redact_test.go new file mode 100644 index 000000000..9f8aaf1d6 --- /dev/null +++ b/internal/oauth/authurl_redact_test.go @@ -0,0 +1,144 @@ +package oauth + +import ( + "net/url" + "reflect" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// TestURLValueDeep_MasksTheNestedResourceURL is the guard for the biggest leak +// in #1158. +// +// autoDetectResource returns the CONFIGURED upstream URL verbatim on every +// fallback branch, that value becomes extraParams["resource"], and every +// authorize-URL builder splices each extra param into the query — so the +// authorize URL that is logged at INFO and printed to stdout on every login +// attempt carries `resource=`. +// +// The percent-encoding is what makes this its own rule: neither the +// sensitive-query-parameter NAME rule (which sees one opaque value under the +// name `resource`) nor secretPattern (which needs a literal `=` after `token`, +// not `%3D`) can see the credential at that nesting level. +func TestURLValueDeep_MasksTheNestedResourceURL(t *testing.T) { + const secret = "SUPERSECRETALPHAQUERYVALUE" + upstream := "https://host.example.com/mcp?token=" + secret + authURL := "https://auth.example.com/authorize?client_id=abc123&resource=" + + url.QueryEscape(upstream) + "&state=xyz" + + // The rule the design originally proposed is NOT sufficient — pin that, so + // nobody "simplifies" URLValueDeep back to it. + assert.Contains(t, RedactURLQueryParams(authURL), secret, + "sanity: the name-rule-only helper cannot see a credential nested inside a "+ + "percent-encoded parameter value; if it can, this test is no longer testing anything") + + got := AuditRedaction.URLValueDeep(authURL) + assert.NotContains(t, got, secret, "the nested upstream credential reached the log field") + assert.NotContains(t, got, url.QueryEscape(secret)) + + // Diagnostics survive: an operator must still see WHICH provider and + // WHICH resource the flow was for. + assert.Contains(t, got, "auth.example.com/authorize") + assert.Contains(t, got, "client_id=abc123") + assert.Contains(t, got, "state=xyz") + assert.Contains(t, got, "host.example.com/mcp", + "the resource endpoint's host and path must survive; only its credential goes") +} + +// TestURLValueDeep_MasksTheTopLevelQueryToo — the nesting rule must not replace +// the ordinary one. +func TestURLValueDeep_MasksTheTopLevelQueryToo(t *testing.T) { + const secret = "SUPERSECRETALPHAQUERYVALUE" + got := AuditRedaction.URLValueDeep("https://host.example.com/mcp?token=" + secret) + assert.NotContains(t, got, secret) + assert.Contains(t, got, "host.example.com/mcp") +} + +// TestExtraParamValue_MasksResourceCredentials guards the sibling Debug line: +// the authorize-URL builders log every extra parameter's VALUE, and +// maskExtraParams deliberately showed `resource` in full because it was +// documented as "a public endpoint". It is not — it is the configured URL. +func TestExtraParamValue_MasksResourceCredentials(t *testing.T) { + const secret = "SUPERSECRETALPHAQUERYVALUE" + upstream := "https://host.example.com/mcp?token=" + secret + + got := AuditRedaction.ExtraParamValue("resource", upstream) + assert.NotContains(t, got, secret) + assert.Contains(t, got, "host.example.com/mcp") + + masked := maskExtraParams(map[string]string{"resource": upstream}) + assert.NotContains(t, masked["resource"], secret, + "maskExtraParams showed `resource` in full; it carries the configured URL") +} + +// TestCreateMetadataError_ScrubsEveryURLLeaf reflect-walks the built error so a +// string field added later is covered without editing this test. +func TestCreateMetadataError_ScrubsEveryURLLeaf(t *testing.T) { + const secret = "SUPERSECRETALPHAQUERYVALUE" + serverURL := "https://host.example.com/mcp?token=" + secret + prmURL := "https://host.example.com/.well-known/oauth-protected-resource?token=" + secret + asURL := "https://host.example.com/.well-known/oauth-authorization-server?token=" + secret + + err := createMetadataError("alpha", serverURL, &OAuthMetadataValidationResult{ + ProtectedResourceMetadataURL: prmURL, + ProtectedResourceError: &urlBearingError{msg: `Get "` + prmURL + `": 404`}, + AuthorizationServerMetadataURL: asURL, + AuthorizationServerMetadataURLsTried: []string{asURL, prmURL}, + AuthorizationServerError: &urlBearingError{msg: `Get "` + asURL + `": 404`}, + }) + require.Error(t, err) + + var leaves []string + collectStrings(reflect.ValueOf(err), &leaves) + require.NotEmpty(t, leaves) + + sawEndpoint := false + for _, leaf := range leaves { + assert.NotContains(t, leaf, secret, + "a URL-derived leaf of the structured OAuth error is JSON-encoded straight to the client") + if strings.Contains(leaf, "host.example.com") { + sawEndpoint = true + } + } + assert.True(t, sawEndpoint, + "positive control: the endpoint host must SURVIVE. A blanked field would pass the "+ + "leak assertion above while destroying the operator's ability to see which URL failed") +} + +type urlBearingError struct{ msg string } + +func (e *urlBearingError) Error() string { return e.msg } + +// collectStrings walks every reachable string leaf of v. +func collectStrings(v reflect.Value, out *[]string) { + switch v.Kind() { + case reflect.String: + if v.String() != "" { + *out = append(*out, v.String()) + } + case reflect.Ptr, reflect.Interface: + if !v.IsNil() { + collectStrings(v.Elem(), out) + } + case reflect.Slice, reflect.Array: + for i := 0; i < v.Len(); i++ { + collectStrings(v.Index(i), out) + } + case reflect.Map: + for _, k := range v.MapKeys() { + collectStrings(v.MapIndex(k), out) + } + case reflect.Struct: + for i := 0; i < v.NumField(); i++ { + f := v.Field(i) + if !f.CanInterface() { + continue + } + collectStrings(f, out) + } + default: + } +} diff --git a/internal/oauth/config.go b/internal/oauth/config.go index bd679b62b..4ef8da17c 100644 --- a/internal/oauth/config.go +++ b/internal/oauth/config.go @@ -494,7 +494,7 @@ func CreateOAuthConfigWithExtraParamsAndLogger(ctx context.Context, serverConfig if resource, hasResource := extraParams["resource"]; hasResource { logger.Info("Using manual resource parameter from config", zap.String("server", serverConfig.Name), - zap.String("resource", resource)) + zap.String("resource", logSafeURL(resource))) } } @@ -693,7 +693,7 @@ func autoDetectResource(ctx context.Context, serverConfig *config.ServerConfig, logger.Warn("Rate limited during resource auto-detection, exhausted retries, using server URL as fallback", zap.String("server", serverConfig.Name), zap.Int("attempts", resourceDetectMaxRetries+1), - zap.String("fallback_resource", serverConfig.URL)) + zap.String("fallback_resource", logSafeURL(serverConfig.URL))) return serverConfig.URL case resp.StatusCode >= 400: @@ -701,7 +701,7 @@ func autoDetectResource(ctx context.Context, serverConfig *config.ServerConfig, logger.Debug("Server returned error during resource auto-detection, using server URL as fallback", zap.String("server", serverConfig.Name), zap.Int("status_code", resp.StatusCode), - zap.String("fallback_resource", serverConfig.URL)) + zap.String("fallback_resource", logSafeURL(serverConfig.URL))) return serverConfig.URL default: @@ -728,7 +728,7 @@ func handleUnauthorizedResponse(resp *http.Response, body []byte, serverConfig * if err != nil { logger.Debug("Failed to fetch Protected Resource Metadata", zap.String("server", serverConfig.Name), - zap.String("metadata_url", metadataURL), + zap.String("metadata_url", logSafeURL(metadataURL)), zap.Error(err)) // Fallback to server URL return serverConfig.URL @@ -738,21 +738,21 @@ func handleUnauthorizedResponse(resp *http.Response, body []byte, serverConfig * if metadata.Resource != "" { logger.Info("Auto-detected resource parameter from Protected Resource Metadata (RFC 9728)", zap.String("server", serverConfig.Name), - zap.String("resource", metadata.Resource)) + zap.String("resource", logSafeURL(metadata.Resource))) return metadata.Resource } // Metadata exists but lacks resource field - fallback to server URL logger.Info("Protected Resource Metadata lacks resource field, using server URL as fallback", zap.String("server", serverConfig.Name), - zap.String("fallback_resource", serverConfig.URL)) + zap.String("fallback_resource", logSafeURL(serverConfig.URL))) return serverConfig.URL } // No resource_metadata in WWW-Authenticate - fallback to server URL logger.Debug("WWW-Authenticate header lacks resource_metadata, using server URL as fallback", zap.String("server", serverConfig.Name), - zap.String("fallback_resource", serverConfig.URL)) + zap.String("fallback_resource", logSafeURL(serverConfig.URL))) return serverConfig.URL } @@ -806,7 +806,7 @@ func createOAuthConfigInternal(serverConfig *config.ServerConfig, storage *stora logger.Debug("🚀 Starting OAuth config creation", zap.String("server", serverConfig.Name), - zap.String("url", serverConfig.URL)) + zap.String("url", logSafeURL(serverConfig.URL))) // Defer logging of total duration defer func() { @@ -839,7 +839,7 @@ func createOAuthConfigInternal(serverConfig *config.ServerConfig, storage *stora if err == nil && baseURL != "" { logger.Debug("Attempting Protected Resource Metadata scope discovery (RFC 9728)", zap.String("server", serverConfig.Name), - zap.String("base_url", baseURL)) + zap.String("base_url", logSafeURL(baseURL))) // Make a preflight HEAD request to get WWW-Authenticate header resp, err := http.Head(serverConfig.URL) @@ -851,7 +851,7 @@ func createOAuthConfigInternal(serverConfig *config.ServerConfig, storage *stora scopes = discoveredScopes logger.Info("✅ Auto-discovered OAuth scopes from Protected Resource Metadata (RFC 9728)", zap.String("server", serverConfig.Name), - zap.String("metadata_url", metadataURL), + zap.String("metadata_url", logSafeURL(metadataURL)), zap.Strings("scopes", scopes)) } else if err != nil { logger.Debug("Protected Resource Metadata discovery failed", @@ -861,7 +861,7 @@ func createOAuthConfigInternal(serverConfig *config.ServerConfig, storage *stora // err == nil but no scopes returned logger.Warn("Protected Resource Metadata returned no scopes - some clients wait for this before showing OAuth UI", zap.String("server", serverConfig.Name), - zap.String("metadata_url", metadataURL)) + zap.String("metadata_url", logSafeURL(metadataURL))) } } else { logger.Warn("WWW-Authenticate header missing resource_metadata; OAuth clients may refuse to launch browser until PRM exists", @@ -886,7 +886,7 @@ func createOAuthConfigInternal(serverConfig *config.ServerConfig, storage *stora if err == nil && baseURL != "" { logger.Debug("Attempting Authorization Server Metadata scope discovery (RFC 8414)", zap.String("server", serverConfig.Name), - zap.String("base_url", baseURL)) + zap.String("base_url", logSafeURL(baseURL))) discoveredScopes, err := DiscoverScopesFromAuthorizationServer(baseURL, 5*time.Second) if err == nil && len(discoveredScopes) > 0 { @@ -897,11 +897,11 @@ func createOAuthConfigInternal(serverConfig *config.ServerConfig, storage *stora } else if err == nil { logger.Warn("Authorization Server Metadata returned no scopes; some OAuth clients will wait until scopes_supported is published", zap.String("server", serverConfig.Name), - zap.String("metadata_url", baseURL+"/.well-known/oauth-authorization-server")) + zap.String("metadata_url", logSafeURL(baseURL+"/.well-known/oauth-authorization-server"))) } else { logger.Warn("Authorization Server Metadata discovery failed", zap.String("server", serverConfig.Name), - zap.String("metadata_url", baseURL+"/.well-known/oauth-authorization-server"), + zap.String("metadata_url", logSafeURL(baseURL+"/.well-known/oauth-authorization-server")), zap.Error(err)) } } @@ -1103,8 +1103,8 @@ func createOAuthConfigInternal(serverConfig *config.ServerConfig, storage *stora urlToUse = authServerURL logger.Info("Using discovered auth server URL for metadata discovery", zap.String("server", serverConfig.Name), - zap.String("mcp_url", serverConfig.URL), - zap.String("auth_server_url", authServerURL)) + zap.String("mcp_url", logSafeURL(serverConfig.URL)), + zap.String("auth_server_url", logSafeURL(authServerURL))) } // Now find the working metadata URL using the auth server URL (or server URL as fallback) @@ -1118,7 +1118,7 @@ func createOAuthConfigInternal(serverConfig *config.ServerConfig, storage *stora authServerMetadataURL = workingURL logger.Info("Using validated OAuth metadata URL", zap.String("server", serverConfig.Name), - zap.String("metadata_url", authServerMetadataURL)) + zap.String("metadata_url", logSafeURL(authServerMetadataURL))) } } else { logger.Info("Skipping OAuth metadata URL - no server URL configured", @@ -1231,7 +1231,7 @@ func createOAuthConfigInternal(serverConfig *config.ServerConfig, storage *stora zap.Strings("scopes", scopes), zap.Bool("pkce_enabled", true), zap.String("redirect_uri", redirectURI), - zap.String("auth_server_metadata_url", authServerMetadataURL), + zap.String("auth_server_metadata_url", logSafeURL(authServerMetadataURL)), zap.String("registration_mode", registrationMode), zap.String("discovery_mode", "explicit metadata URL"), // Using explicit metadata URL to avoid discovery timeouts zap.String("token_store", "shared")) // Using shared token store for token persistence diff --git a/internal/oauth/discovery.go b/internal/oauth/discovery.go index a56071510..16d00ef41 100644 --- a/internal/oauth/discovery.go +++ b/internal/oauth/discovery.go @@ -104,14 +104,14 @@ func FindWorkingMetadataURL(serverURL string, timeout time.Duration) (string, er for _, metadataURL := range urls { logger.Debug("Validating OAuth metadata URL", - zap.String("server_url", serverURL), - zap.String("metadata_url", metadataURL)) + zap.String("server_url", logSafeURL(serverURL)), + zap.String("metadata_url", logSafeURL(metadataURL))) metadata, err := fetchAuthorizationServerMetadata(metadataURL, timeout) if err != nil { lastErr = err logger.Debug("Metadata URL validation failed", - zap.String("metadata_url", metadataURL), + zap.String("metadata_url", logSafeURL(metadataURL)), zap.Error(err)) continue } @@ -120,13 +120,13 @@ func FindWorkingMetadataURL(serverURL string, timeout time.Duration) (string, er if metadata.AuthorizationEndpoint == "" || metadata.TokenEndpoint == "" { lastErr = fmt.Errorf("metadata missing required fields") logger.Debug("Metadata incomplete", - zap.String("metadata_url", metadataURL)) + zap.String("metadata_url", logSafeURL(metadataURL))) continue } logger.Info("Found working OAuth metadata URL", - zap.String("server_url", serverURL), - zap.String("metadata_url", metadataURL), + zap.String("server_url", logSafeURL(serverURL)), + zap.String("metadata_url", logSafeURL(metadataURL)), zap.String("issuer", metadata.Issuer)) return metadataURL, nil } @@ -152,7 +152,7 @@ func discoverAuthServerMetadataWithFallback(authServerURL string, timeout time.D urlsChecked = append(urlsChecked, metadataURL) logger.Debug("Trying OAuth metadata URL", zap.String("auth_server", authServerURL), - zap.String("metadata_url", metadataURL)) + zap.String("metadata_url", logSafeURL(metadataURL))) metadata, err := fetchAuthorizationServerMetadata(metadataURL, timeout) if err == nil { @@ -161,23 +161,23 @@ func discoverAuthServerMetadataWithFallback(authServerURL string, timeout time.D lastErr = fmt.Errorf("metadata missing required fields: authorization_endpoint=%q, token_endpoint=%q", metadata.AuthorizationEndpoint, metadata.TokenEndpoint) logger.Debug("OAuth metadata incomplete, trying next URL", - zap.String("metadata_url", metadataURL), + zap.String("metadata_url", logSafeURL(metadataURL)), zap.Error(lastErr)) continue } logger.Info("✅ OAuth metadata discovered", zap.String("auth_server", authServerURL), - zap.String("metadata_url", metadataURL), + zap.String("metadata_url", logSafeURL(metadataURL)), zap.String("issuer", metadata.Issuer), - zap.String("authorization_endpoint", metadata.AuthorizationEndpoint), - zap.String("token_endpoint", metadata.TokenEndpoint)) + zap.String("authorization_endpoint", logSafeURL(metadata.AuthorizationEndpoint)), + zap.String("token_endpoint", logSafeURL(metadata.TokenEndpoint))) return metadata, metadataURL, nil } lastErr = err logger.Debug("OAuth metadata fetch failed, trying next URL", - zap.String("metadata_url", metadataURL), + zap.String("metadata_url", logSafeURL(metadataURL)), zap.Error(err)) } @@ -199,7 +199,7 @@ func DiscoverAuthServerURL(serverURL string, timeout time.Duration) string { resp, err := client.Post(serverURL, "application/json", strings.NewReader("{}")) if err != nil { logger.Debug("Preflight request failed for auth server discovery", - zap.String("server_url", serverURL), + zap.String("server_url", logSafeURL(serverURL)), zap.Error(err)) return "" } @@ -207,7 +207,7 @@ func DiscoverAuthServerURL(serverURL string, timeout time.Duration) string { if resp.StatusCode != http.StatusUnauthorized { logger.Debug("Server did not return 401, cannot discover auth server", - zap.String("server_url", serverURL), + zap.String("server_url", logSafeURL(serverURL)), zap.Int("status_code", resp.StatusCode)) return "" } @@ -229,15 +229,15 @@ func DiscoverAuthServerURL(serverURL string, timeout time.Duration) string { metadataURL = baseURL + "/.well-known/oauth-protected-resource" } logger.Debug("Constructed PRM URL from server URL", - zap.String("server_url", serverURL), - zap.String("prm_url", metadataURL)) + zap.String("server_url", logSafeURL(serverURL)), + zap.String("prm_url", logSafeURL(metadataURL))) } // Fetch Protected Resource Metadata metadata, err := DiscoverProtectedResourceMetadata(metadataURL, timeout) if err != nil { logger.Debug("Failed to fetch Protected Resource Metadata", - zap.String("metadata_url", metadataURL), + zap.String("metadata_url", logSafeURL(metadataURL)), zap.Error(err)) return "" } @@ -246,13 +246,13 @@ func DiscoverAuthServerURL(serverURL string, timeout time.Duration) string { if len(metadata.AuthorizationServers) > 0 { authServer := metadata.AuthorizationServers[0] logger.Info("Discovered OAuth authorization server from PRM", - zap.String("server_url", serverURL), + zap.String("server_url", logSafeURL(serverURL)), zap.String("auth_server", authServer)) return authServer } logger.Debug("PRM has no authorization_servers", - zap.String("server_url", serverURL)) + zap.String("server_url", logSafeURL(serverURL))) return "" } @@ -305,7 +305,7 @@ func DiscoverProtectedResourceMetadata(metadataURL string, timeout time.Duration if err != nil { logger.Debug("❌ HTTP Request failed", - zap.String("url", metadataURL), + zap.String("url", logSafeURL(metadataURL)), zap.Error(err), zap.Duration("elapsed", elapsed)) return nil, fmt.Errorf("failed to fetch metadata: %w", err) @@ -317,7 +317,7 @@ func DiscoverProtectedResourceMetadata(metadataURL string, timeout time.Duration if resp.StatusCode != http.StatusOK { logger.Debug("⚠ī¸ Non-200 status code from metadata endpoint", - zap.String("url", metadataURL), + zap.String("url", logSafeURL(metadataURL)), zap.Int("status_code", resp.StatusCode)) return nil, fmt.Errorf("metadata endpoint returned %d", resp.StatusCode) } @@ -325,15 +325,15 @@ func DiscoverProtectedResourceMetadata(metadataURL string, timeout time.Duration var metadata ProtectedResourceMetadata if err := json.NewDecoder(resp.Body).Decode(&metadata); err != nil { logger.Debug("❌ Failed to parse JSON response", - zap.String("url", metadataURL), + zap.String("url", logSafeURL(metadataURL)), zap.Error(err)) return nil, fmt.Errorf("failed to parse metadata: %w", err) } // TRACE: Log parsed metadata logger.Debug("✅ Successfully parsed Protected Resource Metadata", - zap.String("url", metadataURL), - zap.String("resource", metadata.Resource), + zap.String("url", logSafeURL(metadataURL)), + zap.String("resource", logSafeURL(metadata.Resource)), zap.String("resource_name", metadata.ResourceName), zap.Strings("scopes_supported", metadata.ScopesSupported), zap.Strings("authorization_servers", metadata.AuthorizationServers), @@ -342,7 +342,7 @@ func DiscoverProtectedResourceMetadata(metadataURL string, timeout time.Duration // Log resource discovery for RFC 8707 auto-detection if metadata.Resource != "" { logger.Info("Protected Resource Metadata discovered", - zap.String("resource", metadata.Resource), + zap.String("resource", logSafeURL(metadata.Resource)), zap.Strings("scopes", metadata.ScopesSupported), zap.Strings("auth_servers", metadata.AuthorizationServers)) } @@ -361,7 +361,7 @@ func DiscoverScopesFromProtectedResource(metadataURL string, timeout time.Durati if len(metadata.ScopesSupported) == 0 { logger := zap.L().Named("oauth.discovery") logger.Debug("Protected Resource Metadata returned empty scopes_supported", - zap.String("metadata_url", metadataURL)) + zap.String("metadata_url", logSafeURL(metadataURL))) return []string{}, nil } @@ -395,7 +395,7 @@ func DiscoverScopesFromAuthorizationServer(baseURL string, timeout time.Duration if err != nil { logger.Debug("❌ HTTP Request failed", - zap.String("url", metadataURL), + zap.String("url", logSafeURL(metadataURL)), zap.Error(err), zap.Duration("elapsed", elapsed)) return nil, fmt.Errorf("failed to fetch metadata: %w", err) @@ -407,7 +407,7 @@ func DiscoverScopesFromAuthorizationServer(baseURL string, timeout time.Duration if resp.StatusCode != http.StatusOK { logger.Debug("⚠ī¸ Non-200 status code from metadata endpoint", - zap.String("url", metadataURL), + zap.String("url", logSafeURL(metadataURL)), zap.Int("status_code", resp.StatusCode)) return nil, fmt.Errorf("metadata endpoint returned %d", resp.StatusCode) } @@ -415,26 +415,26 @@ func DiscoverScopesFromAuthorizationServer(baseURL string, timeout time.Duration var metadata OAuthServerMetadata if err := json.NewDecoder(resp.Body).Decode(&metadata); err != nil { logger.Debug("❌ Failed to parse JSON response", - zap.String("url", metadataURL), + zap.String("url", logSafeURL(metadataURL)), zap.Error(err)) return nil, fmt.Errorf("failed to parse metadata: %w", err) } // TRACE: Log parsed metadata logger.Debug("✅ Successfully parsed Authorization Server Metadata", - zap.String("url", metadataURL), + zap.String("url", logSafeURL(metadataURL)), zap.String("issuer", metadata.Issuer), - zap.String("authorization_endpoint", metadata.AuthorizationEndpoint), - zap.String("token_endpoint", metadata.TokenEndpoint), + zap.String("authorization_endpoint", logSafeURL(metadata.AuthorizationEndpoint)), + zap.String("token_endpoint", logSafeURL(metadata.TokenEndpoint)), zap.Strings("scopes_supported", metadata.ScopesSupported), zap.Strings("response_types_supported", metadata.ResponseTypesSupported), zap.Strings("grant_types_supported", metadata.GrantTypesSupported)) logger.Debug("Authorization Server Metadata fetched", zap.String("issuer", metadata.Issuer), - zap.String("authorization_endpoint", metadata.AuthorizationEndpoint), - zap.String("token_endpoint", metadata.TokenEndpoint), - zap.String("registration_endpoint", metadata.RegistrationEndpoint), + zap.String("authorization_endpoint", logSafeURL(metadata.AuthorizationEndpoint)), + zap.String("token_endpoint", logSafeURL(metadata.TokenEndpoint)), + zap.String("registration_endpoint", logSafeURL(metadata.RegistrationEndpoint)), zap.Strings("scopes_supported", metadata.ScopesSupported)) if metadata.RegistrationEndpoint == "" { @@ -445,7 +445,7 @@ func DiscoverScopesFromAuthorizationServer(baseURL string, timeout time.Duration if len(metadata.ScopesSupported) == 0 { logger.Debug("Authorization Server Metadata returned empty scopes_supported", - zap.String("metadata_url", metadataURL)) + zap.String("metadata_url", logSafeURL(metadataURL))) return []string{}, nil } @@ -473,7 +473,7 @@ func DetectOAuthAvailability(baseURL string, timeout time.Duration) bool { resp, err := client.Do(req) if err != nil { logger.Debug("OAuth detection failed - endpoint unreachable", - zap.String("url", metadataURL), + zap.String("url", logSafeURL(metadataURL)), zap.Error(err)) return false } @@ -481,7 +481,7 @@ func DetectOAuthAvailability(baseURL string, timeout time.Duration) bool { if resp.StatusCode != http.StatusOK { logger.Debug("OAuth detection failed - non-200 status", - zap.String("url", metadataURL), + zap.String("url", logSafeURL(metadataURL)), zap.Int("status_code", resp.StatusCode)) return false } @@ -489,7 +489,7 @@ func DetectOAuthAvailability(baseURL string, timeout time.Duration) bool { var metadata OAuthServerMetadata if err := json.NewDecoder(resp.Body).Decode(&metadata); err != nil { logger.Debug("OAuth detection failed - invalid JSON", - zap.String("url", metadataURL), + zap.String("url", logSafeURL(metadataURL)), zap.Error(err)) return false } @@ -497,31 +497,31 @@ func DetectOAuthAvailability(baseURL string, timeout time.Duration) bool { // Verify it's valid OAuth metadata if metadata.AuthorizationEndpoint == "" || metadata.TokenEndpoint == "" { logger.Debug("OAuth detection failed - incomplete metadata", - zap.String("url", metadataURL), - zap.String("authorization_endpoint", metadata.AuthorizationEndpoint), - zap.String("token_endpoint", metadata.TokenEndpoint)) + zap.String("url", logSafeURL(metadataURL)), + zap.String("authorization_endpoint", logSafeURL(metadata.AuthorizationEndpoint)), + zap.String("token_endpoint", logSafeURL(metadata.TokenEndpoint))) return false } logger.Info("✅ OAuth detected automatically", - zap.String("server_url", baseURL), + zap.String("server_url", logSafeURL(baseURL)), zap.String("issuer", metadata.Issuer), - zap.String("authorization_endpoint", metadata.AuthorizationEndpoint), - zap.String("token_endpoint", metadata.TokenEndpoint)) + zap.String("authorization_endpoint", logSafeURL(metadata.AuthorizationEndpoint)), + zap.String("token_endpoint", logSafeURL(metadata.TokenEndpoint))) return true } // OAuthMetadataValidationResult contains the result of OAuth metadata validation type OAuthMetadataValidationResult struct { - Valid bool - ProtectedResourceMetadata *ProtectedResourceMetadata - AuthorizationServerMetadata *OAuthServerMetadata - ProtectedResourceMetadataURL string - AuthorizationServerMetadataURL string + Valid bool + ProtectedResourceMetadata *ProtectedResourceMetadata + AuthorizationServerMetadata *OAuthServerMetadata + ProtectedResourceMetadataURL string + AuthorizationServerMetadataURL string AuthorizationServerMetadataURLsTried []string // All URLs tried (RFC 8414 fallback) - ProtectedResourceError error - AuthorizationServerError error + ProtectedResourceError error + AuthorizationServerError error } // ValidateOAuthMetadata performs pre-flight validation of OAuth metadata. @@ -543,7 +543,7 @@ func ValidateOAuthMetadata(serverURL, serverName string, timeout time.Duration) logger.Info("🔍 Starting OAuth metadata pre-flight validation", zap.String("server", serverName), - zap.String("url", serverURL)) + zap.String("url", logSafeURL(serverURL))) // Step 1: Make preflight request to get WWW-Authenticate header client := &http.Client{Timeout: timeout} @@ -605,7 +605,7 @@ func ValidateOAuthMetadata(serverURL, serverName string, timeout time.Duration) result.ProtectedResourceError = err logger.Debug("Failed to fetch protected resource metadata", zap.String("server", serverName), - zap.String("metadata_url", metadataURL), + zap.String("metadata_url", logSafeURL(metadataURL)), zap.Error(err)) // Don't return error yet - try to get auth server metadata for better error info } else { @@ -644,7 +644,7 @@ func ValidateOAuthMetadata(serverURL, serverName string, timeout time.Duration) logger.Debug("Failed to fetch authorization server metadata", zap.String("server", serverName), zap.String("auth_server_base", authServerBaseURL), - zap.Strings("urls_tried", urls), + zap.Strings("urls_tried", logSafeURLs(urls)), zap.Error(err)) return result, createMetadataError(serverName, serverURL, result) } @@ -656,8 +656,8 @@ func ValidateOAuthMetadata(serverURL, serverName string, timeout time.Duration) result.Valid = true logger.Info("✅ OAuth metadata validation successful", zap.String("server", serverName), - zap.String("authorization_endpoint", authMetadata.AuthorizationEndpoint), - zap.String("token_endpoint", authMetadata.TokenEndpoint)) + zap.String("authorization_endpoint", logSafeURL(authMetadata.AuthorizationEndpoint)), + zap.String("token_endpoint", logSafeURL(authMetadata.TokenEndpoint))) return result, nil } @@ -690,7 +690,7 @@ func fetchAuthorizationServerMetadata(metadataURL string, timeout time.Duration) var metadata OAuthServerMetadata if err := json.NewDecoder(resp.Body).Decode(&metadata); err != nil { logger.Debug("Failed to parse authorization server metadata", - zap.String("url", metadataURL), + zap.String("url", logSafeURL(metadataURL)), zap.Error(err)) return nil, fmt.Errorf("failed to parse metadata: %w", err) } @@ -698,7 +698,20 @@ func fetchAuthorizationServerMetadata(metadataURL string, timeout time.Duration) return &metadata, nil } -// createMetadataError creates a structured OAuthFlowError from validation result +// createMetadataError creates a structured OAuthFlowError from validation result. +// +// Issue #1158: every URL leaf below is derived from the CONFIGURED server URL, +// so each one carries whatever credential that URL's query string holds — and +// this struct is JSON-encoded straight to the API client by +// handleServerLogin, as well as rendered by `mcpproxy auth status`. The scrub +// belongs HERE, at the build site, not at the encoder: the encoder sees an +// opaque struct and cannot know which leaves are URLs, and fixing it here means +// every present and future consumer of OAuthMetadataError inherits the safe +// rendering. +// +// The URL leaves keep their scheme, host and path — the Web UI's OAuth-failure +// panel exists to tell the operator WHICH endpoint failed discovery, so +// blanking the field would be a different bug. Only the credentials go. func createMetadataError(serverName, serverURL string, result *OAuthMetadataValidationResult) error { // Import contracts for error types - using string literals to avoid import cycle // These match the constants in internal/contracts/types.go @@ -720,7 +733,7 @@ func createMetadataError(serverName, serverURL string, result *OAuthMetadataVali "MCPProxy tried the following OAuth metadata URLs but none responded: %v. "+ "Verify the authorization server supports OAuth 2.0 discovery (RFC 8414). "+ "If using a custom OAuth server, ensure it exposes /.well-known/oauth-authorization-server.", - result.AuthorizationServerMetadataURLsTried) + logSafeURLs(result.AuthorizationServerMetadataURLsTried)) } else { suggestion = "The OAuth authorization server is not properly configured. Contact the server administrator." } @@ -735,16 +748,16 @@ func createMetadataError(serverName, serverURL string, result *OAuthMetadataVali // Build details structure details := &metadataErrorDetails{ - ServerURL: serverURL, + ServerURL: logSafeURL(serverURL), } if result.ProtectedResourceMetadataURL != "" { details.ProtectedResourceMetadata = &metadataStatus{ Found: result.ProtectedResourceMetadata != nil, - URLChecked: result.ProtectedResourceMetadataURL, + URLChecked: logSafeURL(result.ProtectedResourceMetadataURL), } if result.ProtectedResourceError != nil { - details.ProtectedResourceMetadata.Error = result.ProtectedResourceError.Error() + details.ProtectedResourceMetadata.Error = ScrubUpstreamText(result.ProtectedResourceError.Error()) } if result.ProtectedResourceMetadata != nil { details.ProtectedResourceMetadata.AuthorizationServers = result.ProtectedResourceMetadata.AuthorizationServers @@ -754,11 +767,11 @@ func createMetadataError(serverName, serverURL string, result *OAuthMetadataVali if result.AuthorizationServerMetadataURL != "" || len(result.AuthorizationServerMetadataURLsTried) > 0 { details.AuthorizationServerMetadata = &metadataStatus{ Found: result.AuthorizationServerMetadata != nil, - URLChecked: result.AuthorizationServerMetadataURL, - URLsChecked: result.AuthorizationServerMetadataURLsTried, + URLChecked: logSafeURL(result.AuthorizationServerMetadataURL), + URLsChecked: logSafeURLs(result.AuthorizationServerMetadataURLsTried), } if result.AuthorizationServerError != nil { - details.AuthorizationServerMetadata.Error = result.AuthorizationServerError.Error() + details.AuthorizationServerMetadata.Error = ScrubUpstreamText(result.AuthorizationServerError.Error()) } } diff --git a/internal/oauth/logging.go b/internal/oauth/logging.go index a0f170a3a..e81bb6be6 100644 --- a/internal/oauth/logging.go +++ b/internal/oauth/logging.go @@ -944,3 +944,41 @@ func LogOAuthFlowEnd(logger *zap.Logger, serverName string, correlationID string ) } } + +// logSafeURL renders a URL for a LOG FIELD written from inside this package +// (issue #1158). +// +// Every other package already masked its URL log fields — internal/transport +// through cfg.logSafeURL, internal/upstream/core through Client.logSafeURL — +// while internal/oauth, which handles URLs for a living, wrote the configured +// upstream URL and every URL derived from it (RFC 8414 / RFC 9728 metadata +// candidates, the RFC 8707 resource, the token-store key) verbatim. A +// `?token=â€Ļ` in the configured URL therefore reached ~/.mcpproxy/logs/main.log +// on every discovery attempt. +// +// The AUDIT policy is used rather than the bare RedactURLQueryParams the issue +// names: RedactURLQueryParams is name-rule-only, so a credential under an +// unrecognised parameter name (`?opaque=ghp_â€Ļ`) still reached the log. There is +// no write-path echo to protect on a log sink, so running the value-shaped +// detector as well is pure gain. URLValueDeep also decodes one level of nesting, +// which is where the authorize URL hides the upstream URL. +// +// url.URL.Redacted() is deliberately NOT used anywhere: it masks the userinfo +// password only and leaves `?token=` intact. +func logSafeURL(rawURL string) string { + return AuditRedaction.URLValueDeep(rawURL) +} + +// logSafeURLs is logSafeURL over a slice — the RFC 8414 candidate list is +// logged whole (`urls_tried`) and every entry is derived from the configured +// server URL. +func logSafeURLs(urls []string) []string { + if urls == nil { + return nil + } + out := make([]string, len(urls)) + for i, u := range urls { + out[i] = logSafeURL(u) + } + return out +} diff --git a/internal/oauth/masking.go b/internal/oauth/masking.go index 32384005b..6853bb6d9 100644 --- a/internal/oauth/masking.go +++ b/internal/oauth/masking.go @@ -43,8 +43,12 @@ func maskExtraParams(params map[string]string) map[string]string { masked := make(map[string]string, len(params)) for k, v := range params { if isResourceParam(k) { - // Show resource URLs in full (public endpoints) - masked[k] = v + // Issue #1158: a `resource` parameter is NOT a public constant. + // autoDetectResource returns the CONFIGURED upstream URL verbatim + // on every fallback branch, so `resource` routinely carries the + // operator's `?token=...`. Keep the endpoint readable (that is why + // this branch exists) but mask its credentials. + masked[k] = AuditRedaction.URLValueDeep(v) } else if containsSensitiveKeyword(k) { // Likely sensitive - mask completely masked[k] = "***" diff --git a/internal/oauth/persistent_token_store.go b/internal/oauth/persistent_token_store.go index 9a608cd9b..033c8a5ce 100644 --- a/internal/oauth/persistent_token_store.go +++ b/internal/oauth/persistent_token_store.go @@ -59,7 +59,7 @@ func GenerateServerKey(serverName, serverURL string) string { // Log key generation for debugging server key mismatches zap.L().Debug("Generated OAuth server key", zap.String("server_name", serverName), - zap.String("server_url", serverURL), + zap.String("server_url", logSafeURL(serverURL)), zap.String("generated_key", key)) return key diff --git a/internal/oauth/redactview.go b/internal/oauth/redactview.go index e5be54a77..d876de40d 100644 --- a/internal/oauth/redactview.go +++ b/internal/oauth/redactview.go @@ -273,6 +273,16 @@ func maskDetectedInURLQuery(rawQuery string) string { // Everything else round-trips verbatim: package names, subcommands, paths and // ports are what make the payload useful. func (r Redaction) Argv(argv []string) []string { + return r.argvWith(argv, nil) +} + +// argvWith is Argv with an optional rule for elements that carry embedded +// whitespace - a whole command LINE squeezed into one argv element, which the +// login-shell wrap produces (`["-l","-c","npx some-mcp --api-key ..."]`) and +// which the per-token rules below cannot see into. Passing nil reproduces +// Argv's behaviour byte for byte; only the log-only SpawnArgv rule supplies a +// hook, so the read/write mask-echo contract Argv backs is untouched. +func (r Redaction) argvWith(argv []string, commandStringRule func(string) string) []string { if argv == nil { return nil } @@ -284,6 +294,10 @@ func (r Redaction) Argv(argv []string) []string { maskNext = false continue } + if commandStringRule != nil && strings.ContainsAny(s, " \t\n\r") { + out[i] = commandStringRule(s) + continue + } if flag, value, inline := strings.Cut(s, "="); inline && IsArgvFlag(flag) { out[i] = flag + "=" + r.Leaf(ArgvFlagKey(flag), value) continue diff --git a/internal/oauth/round8_doorscan_test.go b/internal/oauth/round8_doorscan_test.go index b6bb2b0f6..a4ead6583 100644 --- a/internal/oauth/round8_doorscan_test.go +++ b/internal/oauth/round8_doorscan_test.go @@ -82,10 +82,6 @@ var rawServerLeafDoors = map[string]string{ "health.CalculateHealth from a fixed disconnected input; no upstream text and no config string reaches it.", "cmd/mcpproxy/registry_cmd.go:newRegistrySearchCmd": "registry SEARCH results are catalogue entries fetched from a remote registry, not operator configuration.", "internal/runtime/runtime.go:(m).SearchRegistryServers": "same remote catalogue entries; the urls are the catalogue's.", - "internal/upstream/core/connection_oauth.go:(m).emptyClientIDFlowError": "the url in this message is the " + - "DISCOVERED authorization-server endpoint, not the configured upstream url.", - "internal/upstream/core/connection_oauth.go:(m).handleOAuthAuthorization": "discovered authorization/token endpoints in zap log fields, not a client wire.", - "internal/upstream/core/connection_oauth.go:(m).handleOAuthAuthorizationWithResult": "same discovered endpoints.", } // openDoors is the third state a door can be in, and the only honest one for a diff --git a/internal/oauth/round8_renderer_discovery_test.go b/internal/oauth/round8_renderer_discovery_test.go index 7a7575bd1..3f3385924 100644 --- a/internal/oauth/round8_renderer_discovery_test.go +++ b/internal/oauth/round8_renderer_discovery_test.go @@ -85,6 +85,27 @@ var redactionMethodRenderers = map[string][]func(string) string{ func(s string) string { return strings.Join(LiveRedaction.Argv([]string{s}), " ") }, func(s string) string { return strings.Join(AuditRedaction.Argv([]string{"--token", s}), " ") }, }, + // Issue #1158. The three log-only spawn/URL renderings. They are bound here + // rather than exempted because they DO emit masks, so the fail-closed net + // must know their markers even though no write door echoes them back. + "Redaction.SpawnArgv": { + func(s string) string { return strings.Join(AuditRedaction.SpawnArgv([]string{"--token", s}), " ") }, + func(s string) string { return strings.Join(AuditRedaction.SpawnArgv([]string{"-e", "K=" + s}), " ") }, + func(s string) string { return strings.Join(LiveRedaction.SpawnArgv([]string{"--token", s}), " ") }, + }, + "Redaction.SpawnCommandString": { + func(s string) string { return AuditRedaction.SpawnCommandString("npx mcp --token " + s) }, + func(s string) string { return LiveRedaction.SpawnCommandString("npx mcp --token " + s) }, + }, + "Redaction.URLValueDeep": { + func(s string) string { return AuditRedaction.URLValueDeep(s) }, + func(s string) string { return LiveRedaction.URLValueDeep(s) }, + }, + "Redaction.ExtraParamValue": { + func(s string) string { return AuditRedaction.ExtraParamValue("resource", s) }, + func(s string) string { return AuditRedaction.ExtraParamValue("audience", s) }, + func(s string) string { return LiveRedaction.ExtraParamValue("resource", s) }, + }, } // notMaskRenderings records the discovered renderers that are NOT mask diff --git a/internal/oauth/spawnargv.go b/internal/oauth/spawnargv.go new file mode 100644 index 000000000..91db7c566 --- /dev/null +++ b/internal/oauth/spawnargv.go @@ -0,0 +1,215 @@ +package oauth + +import ( + "net/url" + "strings" + + "github.com/smart-mcp-proxy/mcpproxy-go/internal/shellwrap" +) + +// Issue #1158. The SPAWN log sinks — "launcher command prepared", the +// `[launcher] starting:` banner in the per-server log file, "Initialized stdio +// transport", the docker-isolation and cidfile lines — write the child's +// command line to disk. Two rules are needed there and neither is sufficient +// alone: +// +// - shellwrap.RedactDockerArgs is STRUCTURAL: it masks the value half of +// every `-e KEY=VALUE` env injection regardless of whether the key looks +// sensitive, which is the only rule that can see `-e BENIGN=`. +// It knows nothing about `--api-key sk-live-â€Ļ`. +// - Redaction.Argv is SEMANTIC: the flag NAME rule plus the value-shaped +// detector. It catches `--api-key VALUE`, `--api-key=VALUE` and a +// vendor-formatted credential sitting anywhere. It does not blanket-mask +// `-e BENIGN=â€Ļ`. +// +// Every existing spawn log site ran only the structural rule and was therefore +// half-fixed. SpawnArgv / SpawnCommandString compose both. +// +// Redaction.Argv itself must NOT be widened to do this. It backs the READ doors +// (`GET /api/v1/servers`, MCP `upstream_servers list`, the `/events` +// servers.changed payload) AND CheckArgvMaskEcho on the write doors: blanket +// masking every `-e FOO=bar` there would newly mask benign docker env values on +// the read payload and then make the write door REFUSE the echo. Hence a +// separate, log-only rule. +// +// There is deliberately NO "already masked, skip" guard between the two stages. +// The audit rendering is a run of U+2022 bullets, which contains no character in +// secretPattern's value class `[a-zA-Z0-9\-_\.]`, so stage 2 provably leaves a +// stage-1 rendering byte-identical — the guard would buy nothing. It would also +// LEAK: shellwrap routes any whitespace-bearing element (the `-c ""` produced by wrapWithUserShell on every macOS stdio server, and +// by the docker login-shell fallback) through the command-string rule, so a +// single benign `-e UV_CACHE_DIR=/tmp/c` would put a mask marker in the element +// and a whole-token guard would then skip stage 2 for the rest of that command +// line, publishing a second credential in the clear. That is the exact failure +// `finish` / `maskDetectedPreservingURL` already document one level down. + +// SpawnArgv masks a child process's argument vector for a LOG sink. +// +// The flag names, subcommands, image names, paths and ports survive — an +// operator debugging a spawn still needs to see WHICH flag and WHICH image — +// and only the values are replaced. +// +// Elements that carry embedded whitespace are treated as command STRINGS (the +// `-c` argument of a login-shell wrap) and get the same two rules applied +// token-by-token inside the string, because that is the shape most stdio +// upstreams actually spawn as. +// +// Returns nil for nil. +func (r Redaction) SpawnArgv(argv []string) []string { + if argv == nil { + return nil + } + // Stage 1: the structural docker-env rule, using THIS policy's mask so the + // two stages never compose two different renderings (composing + // secret.MaskSecretValue with RedactSensitiveData yields + // `API_KEY=***REDACTED*******ue`, which publishes the secret's last two + // bytes past the marker). + staged := shellwrap.RedactDockerArgsWith(argv, r.masker()) + // Stage 2: the semantic flag-name + value-shape rule. + return r.argvWith(staged, r.spawnCommandTokens) +} + +// SpawnCommandString masks a whole child command LINE for a LOG sink — the +// single `-c "docker run â€Ļ"` / `-c "npx some-mcp --api-key â€Ļ"` element a +// login-shell wrap produces, which no []string-only redactor can reach. +func (r Redaction) SpawnCommandString(s string) string { + if s == "" { + return s + } + return r.spawnCommandTokens(shellwrap.RedactDockerCommandStringWith(s, r.masker())) +} + +// spawnCommandTokens applies the argv rules to a command STRING that stage 1 +// has already run over, preserving the original spacing so the line stays +// readable. +func (r Redaction) spawnCommandTokens(s string) string { + segs := splitCommandSegments(s) + tokens := make([]string, 0, len(segs)) + for _, seg := range segs { + if seg.isToken { + tokens = append(tokens, seg.text) + } + } + if len(tokens) == 0 { + return s + } + masked := r.argvWith(tokens, nil) + + var b strings.Builder + b.Grow(len(s)) + next := 0 + for _, seg := range segs { + if !seg.isToken { + b.WriteString(seg.text) + continue + } + b.WriteString(masked[next]) + next++ + } + return b.String() +} + +type commandSegment struct { + text string + isToken bool +} + +// splitCommandSegments splits a command string into alternating whitespace and +// non-whitespace runs so the masked tokens can be spliced back with the +// original spacing intact. +func splitCommandSegments(s string) []commandSegment { + isSpace := func(b byte) bool { return b == ' ' || b == '\t' || b == '\n' || b == '\r' } + segs := make([]commandSegment, 0, 8) + for i := 0; i < len(s); { + j := i + for j < len(s) && isSpace(s[j]) { + j++ + } + if j > i { + segs = append(segs, commandSegment{text: s[i:j]}) + i = j + } + j = i + for j < len(s) && !isSpace(s[j]) { + j++ + } + if j > i { + segs = append(segs, commandSegment{text: s[i:j], isToken: true}) + i = j + } + } + return segs +} + +// URLValueDeep renders a URL for a LOG sink, masking credentials in its own +// query string AND inside any query-parameter value that is itself a URL. +// +// Issue #1158: the OAuth authorization URL carries the configured upstream URL +// verbatim as the RFC 8707 `resource` parameter — autoDetectResource returns +// serverConfig.URL on every fallback branch — and it is logged at Info level +// and printed to stdout on every login attempt. The nested URL arrives +// percent-encoded (`resource=https%3A%2F%2Fhost%2Fmcp%3Ftoken%3DSECRET`), where +// neither the sensitive-query-parameter name rule (which sees one opaque value +// under the name `resource`) nor secretPattern (which needs a literal `=` after +// `token`) can see the credential. Decoding one level is what closes it. +func (r Redaction) URLValueDeep(rawURL string) string { + return r.urlValueDeep(rawURL, 2) +} + +func (r Redaction) urlValueDeep(rawURL string, depth int) string { + if rawURL == "" { + return rawURL + } + main, fragment, hasFragment := strings.Cut(rawURL, "#") + base, rawQuery, hasQuery := strings.Cut(main, "?") + if hasQuery && depth > 0 { + parts := strings.Split(rawQuery, "&") + changed := false + for i, part := range parts { + key, value, ok := strings.Cut(part, "=") + if !ok || value == "" { + continue + } + decoded, err := url.QueryUnescape(value) + if err != nil || !strings.Contains(decoded, "://") { + continue + } + inner := r.urlValueDeep(decoded, depth-1) + if inner == decoded { + continue + } + parts[i] = key + "=" + escapeNestedURL(inner) + changed = true + } + if changed { + rawURL = base + "?" + strings.Join(parts, "&") + if hasFragment { + rawURL += "#" + fragment + } + } + } + return r.URLValue(rawURL) +} + +// escapeNestedURL re-escapes only the delimiters that would break the enclosing +// query string's framing. The mask marker is left literal on purpose: this +// rendering goes to a log line a human reads, not back onto the wire, and a +// percent-encoded run of bullets is unreadable. +var nestedURLEscaper = strings.NewReplacer("&", "%26", "#", "%23", " ", "%20") + +func escapeNestedURL(s string) string { return nestedURLEscaper.Replace(s) } + +// ExtraParamValue renders one OAuth extra-parameter VALUE for a LOG field. +// +// Issue #1158: the authorize-URL builders log every extra parameter as +// `zap.String("value", value)` while the sibling summary lines mask the same +// map through maskExtraParams - the map was masked and the individual values +// were not. The `resource` parameter is the sharpest case: it carries the +// configured upstream URL verbatim, credentials included. +func (r Redaction) ExtraParamValue(key, value string) string { + if isResourceParam(key) { + return r.URLValueDeep(value) + } + return r.Leaf(key, value) +} diff --git a/internal/oauth/spawnargv_test.go b/internal/oauth/spawnargv_test.go new file mode 100644 index 000000000..a2aa7708c --- /dev/null +++ b/internal/oauth/spawnargv_test.go @@ -0,0 +1,183 @@ +package oauth + +import ( + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/smart-mcp-proxy/mcpproxy-go/internal/shellwrap" +) + +// assertNoSecretFragment is the assertion the naive "output must not contain the secret" +// check is not strong enough to make. +// +// Composing two different mask renderings produces +// `API_KEY=***REDACTED*******ue`, which publishes the secret's last two bytes +// PAST the marker while still passing a whole-string containment check. So the +// oracle is: no run of >= minRun bytes taken from the secret may appear +// anywhere in the rendered output. +func assertNoSecretFragment(t *testing.T, rendered, secret string, minRun int) { + t.Helper() + for i := 0; i+minRun <= len(secret); i++ { + frag := secret[i : i+minRun] + assert.NotContains(t, rendered, frag, + "a %d-byte fragment of the secret survived into the rendered log field", minRun) + } +} + +// TestSpawnArgv_MasksEverySecretClass is the leak half. Each vector is a shape +// that exactly ONE of the two composed rules can see, so a fix that keeps only +// the structural docker rule (which is what every spawn log site had before +// #1158) or only the semantic flag rule fails here. +func TestSpawnArgv_MasksEverySecretClass(t *testing.T) { + const secret = "SUPERSECRETBETAARGVVALUE" + + cases := []struct { + name string + argv []string + // keep is a substring that MUST survive — the diagnostic half. + keep string + }{ + { + // Only the STRUCTURAL docker rule sees this: the key name is + // benign, so no name matcher fires, and the value has no + // vendor shape for the detector. + name: "docker env under a benign key", + argv: []string{"run", "--rm", "-e", "BENIGN_NAME=" + secret, "img"}, + keep: "BENIGN_NAME=", + }, + { + // Only the SEMANTIC flag rule sees this. + name: "space-separated sensitive flag", + argv: []string{"serve", "--api-key", secret}, + keep: "--api-key", + }, + { + name: "inline sensitive flag", + argv: []string{"--api-key=" + secret}, + keep: "--api-key=", + }, + { + // The shape the live repro actually leaked: wrapWithUserShell + // folds the whole command line into ONE argv element, which no + // []string-only rule can see into. + name: "login-shell command string with a spaced sensitive flag", + argv: []string{"-l", "-c", "npx some-mcp --api-key " + secret}, + keep: "npx some-mcp --api-key", + }, + { + // The refutation's case: a benign `-e` puts a mask marker in the + // element, and a whole-token "already masked, skip" guard would + // then publish this second credential in the clear. + name: "command string with a benign -e AND a second credential", + argv: []string{"-l", "-c", "docker run --rm -e UV_CACHE_DIR=/tmp/c img uvx some-mcp --api-token=" + secret}, + keep: "uvx some-mcp --api-token=", + }, + { + name: "glued docker env form", + argv: []string{"run", "-eSLACK_TOKEN=" + secret, "img"}, + keep: "SLACK_TOKEN=", + }, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + out := AuditRedaction.SpawnArgv(tc.argv) + joined := strings.Join(out, " ") + assertNoSecretFragment(t, joined, secret, 6) + assert.Contains(t, joined, tc.keep, + "masking must not erase the flag/key that says WHICH credential moved: %v", out) + assert.True(t, ContainsMaskMarker(joined), + "the element that held the secret must carry a recognised mask marker: %v", out) + }) + } +} + +// TestSpawnArgv_NoComposedDoubleMaskLeak replaces the design's vacuous +// TestSpawnArgv_DoesNotDoubleMask. +// +// The real double-mask defect only manifests when stage 1's output still +// contains `[a-zA-Z0-9]` — i.e. when someone wires the spawn rule to the +// UNPARAMETERIZED shellwrap.RedactDockerArgs (secret.MaskSecretValue, `sk-***ue`) +// instead of this policy's own mask. That composition leaks the secret's last +// two bytes past the marker. Assert byte-exact equality with the intended +// rendering, not a `!Contains("***REDACTED***")` spot check, which holds for the +// broken output too. +func TestSpawnArgv_NoComposedDoubleMaskLeak(t *testing.T) { + const secret = "supersecretvalue" + + // The reachable-by-mistake composition, kept here as the CONTRAST so the + // test documents what it is guarding against. + mistaken := AuditRedaction.Argv(shellwrap.RedactDockerArgs([]string{"-e", "API_KEY=" + secret})) + require.Len(t, mistaken, 2) + assert.Contains(t, mistaken[1], secret[len(secret)-2:], + "sanity: the mistaken composition is what leaks a suffix; if this stops "+ + "holding, the contrast below no longer proves anything") + + got := AuditRedaction.SpawnArgv([]string{"-e", "API_KEY=" + secret}) + require.Len(t, got, 2) + assert.Equal(t, "-e", got[0]) + assert.Equal(t, "API_KEY="+AuditMaskValue(secret), got[1], + "one mask rendering, applied once: the key survives and no byte of the value does") + assertNoSecretFragment(t, strings.Join(got, " "), secret, 2) +} + +// TestSpawnArgv_PreservesDiagnostics is the anti-regression half: masking that +// eats the tokens an operator debugs a spawn with has traded one bug for +// another. +func TestSpawnArgv_PreservesDiagnostics(t *testing.T) { + argv := []string{ + "run", "--rm", "-i", + "--cidfile", "/tmp/mcpproxy-cid-123456.txt", + "--memory", "512m", + "--workdir", "/app", + "ghcr.io/astral-sh/uv:python3.12-bookworm-slim", + "myimage@sha256:0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef", + } + assert.Equal(t, argv, AuditRedaction.SpawnArgv(argv), + "non-secret spawn diagnostics must round-trip byte-identical") + + assert.Nil(t, AuditRedaction.SpawnArgv(nil)) + assert.Equal(t, "", AuditRedaction.SpawnCommandString("")) + + // The command-STRING form is the one every macOS stdio server spawns as, + // and it is where over-masking would be most visible: a value-shaped + // detector that ate an image digest, an nvm path or a package name would + // make the per-server log useless. + for _, line := range []string{ + "npx -y @modelcontextprotocol/server-filesystem /Users/u/docs", + "uvx mcp-server-git --repository /Users/u/repos/x", + "docker run --rm -i --name mcpproxy-github ghcr.io/x/y:1.2.3", + "/opt/homebrew/bin/uv run --directory /Users/u/p mcp", + "node /Users/u/.nvm/versions/node/v22.1.0/bin/some-mcp --port 8080", + } { + assert.Equal(t, line, AuditRedaction.SpawnCommandString(line), + "a secret-free command line must round-trip byte-identical") + } +} + +// TestSpawnCommandString_MasksInsideTheCommandLine covers the string form +// directly (the cidfile rewriter logs original_cmd / modified_cmd). +func TestSpawnCommandString_MasksInsideTheCommandLine(t *testing.T) { + const secret = "SUPERSECRETBETAARGVVALUE" + in := "docker run --rm -e SLACK_TOKEN=" + secret + " img uvx some-mcp --api-key " + secret + out := AuditRedaction.SpawnCommandString(in) + + assertNoSecretFragment(t, out, secret, 6) + assert.Contains(t, out, "docker run --rm -e SLACK_TOKEN=") + assert.Contains(t, out, "img uvx some-mcp --api-key") +} + +// TestArgv_UnchangedByTheSpawnRule pins the constraint the whole design rests +// on: Redaction.Argv backs the READ doors and CheckArgvMaskEcho on the WRITE +// doors, so the log-only spawn rule must be additive. A reviewer who +// "simplifies" the patch by folding SpawnArgv into Argv fails here. +func TestArgv_UnchangedByTheSpawnRule(t *testing.T) { + argv := []string{"run", "--rm", "-e", "BENIGN_NAME=opaquevalue", "img"} + assert.Equal(t, argv, LiveRedaction.Argv(argv), + "Argv must still leave a benign docker env value alone — masking it here "+ + "would make the write doors refuse the client's echo") + assert.Equal(t, argv, AuditRedaction.Argv(argv)) +} diff --git a/internal/oauth/transport_wrapper.go b/internal/oauth/transport_wrapper.go index 7c032a4c4..e4c84434b 100644 --- a/internal/oauth/transport_wrapper.go +++ b/internal/oauth/transport_wrapper.go @@ -92,7 +92,7 @@ func (w *OAuthTransportWrapper) RoundTrip(req *http.Request) (*http.Response, er // but mcp-go only accepts 200. if tokenReq && resp.StatusCode == http.StatusCreated { w.logger.Debug("Normalized token response status 201→200", - zap.String("url", req.URL.String())) + zap.String("url", logSafeURL(req.URL.String()))) resp.StatusCode = http.StatusOK resp.Status = "200 OK" } @@ -108,7 +108,7 @@ func (w *OAuthTransportWrapper) RoundTrip(req *http.Request) (*http.Response, er // Normalize 201 Created to 200 OK for token responses even without extra params. if tokenReq && resp.StatusCode == http.StatusCreated { w.logger.Debug("Normalized token response status 201→200", - zap.String("url", req.URL.String())) + zap.String("url", logSafeURL(req.URL.String()))) resp.StatusCode = http.StatusOK resp.Status = "200 OK" } @@ -151,7 +151,7 @@ func (w *OAuthTransportWrapper) injectQueryParams(req *http.Request) { // Log at DEBUG level with selective masking masked := maskExtraParams(w.extraParams) w.logger.Debug("Injected extra params into authorization URL", - zap.String("url", req.URL.String()), + zap.String("url", logSafeURL(req.URL.String())), zap.Any("extra_params", masked)) } @@ -197,7 +197,7 @@ func (w *OAuthTransportWrapper) injectFormParams(req *http.Request) { // Log at DEBUG level with selective masking masked := maskExtraParams(w.extraParams) w.logger.Debug("Injected extra params into token request body", - zap.String("url", req.URL.String()), + zap.String("url", logSafeURL(req.URL.String())), zap.Any("extra_params", masked)) } diff --git a/internal/oauth/url_log_field_guard_test.go b/internal/oauth/url_log_field_guard_test.go new file mode 100644 index 000000000..49e69b41c --- /dev/null +++ b/internal/oauth/url_log_field_guard_test.go @@ -0,0 +1,154 @@ +package oauth + +import ( + "go/ast" + "go/parser" + "go/token" + "os" + "path/filepath" + "regexp" + "strconv" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// This is the durable, grep-proof half of #1158. A mechanical conversion of ~75 +// URL log fields across two packages cannot be verified by eye, and the 76th +// site added next month re-opens the hole silently. So the rule is derived from +// the source rather than maintained by hand. +// +// It deliberately spans BOTH packages. Scoping it to internal/oauth — which is +// what the original design proposed — would green-light a fix that leaves every +// `auth_url` site in internal/upstream/core raw, and those are the highest +// blast-radius sinks in the issue: they fire at INFO on every OAuth login with +// no debug flag at all. + +// urlFieldName matches the zap field NAMES whose values are URLs. +var urlFieldName = regexp.MustCompile(`(?i)(^url$|^urls$|_url$|_urls$|urls_tried|^resource$|_resource$|^endpoint$|_endpoint$)`) + +// safeURLRenderer matches the call expressions that are an acceptable value for +// such a field. Anything else is a raw URL reaching a log sink. +var safeURLRenderer = regexp.MustCompile( + `logSafeURL|logSafeURLs|logSafeAuthURL|RedactURL|RedactURLQueryParams|URLValue|URLValueDeep|ScrubUpstreamText|ExtraParamValue|MaskValue`) + +type guardedPkg struct { + dir string + name string +} + +func TestNoRawURLReachesALogField(t *testing.T) { + pkgs := []guardedPkg{ + {".", "internal/oauth"}, + {"../upstream/core", "internal/upstream/core"}, + } + + checked := 0 + for _, pkg := range pkgs { + files, err := filepath.Glob(filepath.Join(pkg.dir, "*.go")) + require.NoError(t, err) + require.NotEmpty(t, files, "%s: the guard found no files to scan", pkg.name) + + for _, file := range files { + if strings.HasSuffix(file, "_test.go") { + continue + } + src, err := os.ReadFile(file) //nolint:gosec // fixed, in-repo paths + require.NoError(t, err) + fset := token.NewFileSet() + parsed, err := parser.ParseFile(fset, file, src, 0) + require.NoError(t, err) + + ast.Inspect(parsed, func(n ast.Node) bool { + call, ok := n.(*ast.CallExpr) + if !ok || len(call.Args) != 2 { + return true + } + sel, ok := call.Fun.(*ast.SelectorExpr) + if !ok { + return true + } + pkgIdent, ok := sel.X.(*ast.Ident) + if !ok || pkgIdent.Name != "zap" { + return true + } + if sel.Sel.Name != "String" && sel.Sel.Name != "Strings" { + return true + } + lit, ok := call.Args[0].(*ast.BasicLit) + if !ok || lit.Kind != token.STRING { + return true + } + name, err := strconv.Unquote(lit.Value) + if err != nil || !urlFieldName.MatchString(name) { + return true + } + checked++ + + valueSrc := string(src[call.Args[1].Pos()-1 : call.Args[1].End()-1]) + // A string literal carries no operator data. + if _, isLit := call.Args[1].(*ast.BasicLit); isLit { + return true + } + assert.True(t, safeURLRenderer.MatchString(valueSrc), + "%s: zap.%s(%q, %s) writes a raw URL to a log sink. Route it through "+ + "logSafeURL / logSafeAuthURL (issue #1158): a configured upstream URL "+ + "routinely carries ?token=, and log files outlive the process.", + fset.Position(call.Pos()), sel.Sel.Name, name, valueSrc) + return true + }) + } + } + + assert.Greater(t, checked, 50, + "the guard matched only %d URL log fields — it has stopped seeing the sites it exists for", checked) +} + +// TestAuthorizationURLIsNeverPrintedRaw covers the OTHER sink in the same file. +// +// internal/upstream/core/connection_oauth.go keeps THREE near-duplicate +// authorize-URL emission paths, and each writes the URL twice: a zap field and +// an fmt.Printf to the operator's terminal. A fix that patches only the zap +// half still puts the credential on stdout, and an observer-only test shows +// green against it. +func TestAuthorizationURLIsNeverPrintedRaw(t *testing.T) { + const file = "../upstream/core/connection_oauth.go" + src, err := os.ReadFile(file) + require.NoError(t, err) + fset := token.NewFileSet() + parsed, err := parser.ParseFile(fset, file, src, 0) + require.NoError(t, err) + + printfs := 0 + ast.Inspect(parsed, func(n ast.Node) bool { + call, ok := n.(*ast.CallExpr) + if !ok { + return true + } + sel, ok := call.Fun.(*ast.SelectorExpr) + if !ok { + return true + } + pkgIdent, ok := sel.X.(*ast.Ident) + if !ok || pkgIdent.Name != "fmt" || !strings.HasPrefix(sel.Sel.Name, "Print") { + return true + } + for _, arg := range call.Args { + ident, ok := arg.(*ast.Ident) + if !ok || ident.Name != "authURL" { + continue + } + printfs++ + assert.Fail(t, + "the authorization URL is printed to stdout unredacted", + "%s: fmt.%s prints the bare `authURL` identifier. It carries the configured "+ + "upstream URL as the RFC 8707 `resource` parameter, credentials included; "+ + "wrap it in logSafeAuthURL (issue #1158).", + fset.Position(call.Pos()), sel.Sel.Name) + } + return true + }) + assert.Zero(t, printfs) +} diff --git a/internal/runtime/runtime.go b/internal/runtime/runtime.go index f0d3b5fa7..0b872cf10 100644 --- a/internal/runtime/runtime.go +++ b/internal/runtime/runtime.go @@ -2299,7 +2299,9 @@ func (r *Runtime) GetAllServers() ([]map[string]interface{}, error) { if url != "" && r.storageManager != nil { r.logger.Debug("Checking OAuth token in storage", zap.String("server", serverStatus.Name), - zap.String("url", url), + // #1158: the configured upstream URL routinely carries a + // `?token=` credential; the host and path stay readable. + zap.String("url", oauth.AuditRedaction.URLValue(url)), zap.Bool("has_explicit_oauth_config", serverStatus.Config.OAuth != nil)) // Generate server key matching PersistentTokenStore format diff --git a/internal/server/add_registry_source.go b/internal/server/add_registry_source.go index 57b206dbf..7653584bf 100644 --- a/internal/server/add_registry_source.go +++ b/internal/server/add_registry_source.go @@ -145,7 +145,7 @@ func (s *Server) AddRegistrySource(req *AddRegistrySourceRequest) (*config.Regis s.logger.Info("Added custom registry source", zap.String("registry_id", entry.ID), - zap.String("url", entry.URL), + zap.String("url", oauth.RedactURLQueryParams(entry.URL)), zap.String("provenance", entry.Provenance)) return &entry, nil @@ -169,7 +169,7 @@ func (s *Server) resolveRegistrySourceShape(entry *config.RegistryEntry) error { if err != nil { if errors.Is(err, registries.ErrRegistrySourceUnreachable) { s.logger.Warn("Could not probe registry source; adding it with the derived defaults", - zap.String("url", entry.URL), zap.Error(err)) + zap.String("url", oauth.RedactURLQueryParams(entry.URL)), zap.Error(err)) return nil } return fmt.Errorf("%w: %v", ErrRegistrySourceUnusable, err) diff --git a/internal/server/edit_registry_source.go b/internal/server/edit_registry_source.go index 41b720d19..59d8e7e84 100644 --- a/internal/server/edit_registry_source.go +++ b/internal/server/edit_registry_source.go @@ -109,7 +109,7 @@ func (s *Server) EditRegistrySource(req *EditRegistrySourceRequest) (*config.Reg s.logger.Info("Edited custom registry source", zap.String("registry_id", updated.ID), - zap.String("url", updated.URL)) + zap.String("url", oauth.RedactURLQueryParams(updated.URL))) return &updated, nil } diff --git a/internal/server/remove_registry_source.go b/internal/server/remove_registry_source.go index 12886adc3..74668754a 100644 --- a/internal/server/remove_registry_source.go +++ b/internal/server/remove_registry_source.go @@ -9,6 +9,7 @@ import ( "github.com/smart-mcp-proxy/mcpproxy-go/internal/config" "github.com/smart-mcp-proxy/mcpproxy-go/internal/contracts" + "github.com/smart-mcp-proxy/mcpproxy-go/internal/oauth" "github.com/smart-mcp-proxy/mcpproxy-go/internal/registries" ) @@ -68,7 +69,7 @@ func (s *Server) RemoveRegistrySource(id string) (*config.RegistryEntry, error) s.logger.Info("Removed custom registry source", zap.String("registry_id", removed.ID), - zap.String("url", removed.URL)) + zap.String("url", oauth.RedactURLQueryParams(removed.URL))) return &removed, nil } diff --git a/internal/shellwrap/redact.go b/internal/shellwrap/redact.go index 42cdb4519..f1e19113e 100644 --- a/internal/shellwrap/redact.go +++ b/internal/shellwrap/redact.go @@ -25,6 +25,19 @@ var dockerEnvFlagRegex = regexp.MustCompile(`(^|\s)(--env|-e)(\s+)('[^']*'|"[^"] // // The input slice is never mutated. A nil input returns nil. func RedactDockerArgs(args []string) []string { + return RedactDockerArgsWith(args, secret.MaskSecretValue) +} + +// RedactDockerArgsWith is RedactDockerArgs with a caller-chosen mask rendering. +// +// Issue #1158: the LOG sinks need the audit rendering (`â€ĸâ€ĸâ€ĸâ€ĸ`, carrying neither +// the secret's length nor its trailing bytes) rather than the interactive +// `sk-****89` one, because ~/.mcpproxy/logs/server-.log outlives the +// process and is exported through `upstream_servers tail_log`. Parameterising +// here rather than post-processing also avoids the double-mask that composing +// two maskers produces (`API_KEY=***REDACTED*******ue` leaks the secret's last +// two bytes past the marker). +func RedactDockerArgsWith(args []string, mask func(string) string) []string { if args == nil { return nil } @@ -33,30 +46,30 @@ func RedactDockerArgs(args []string) []string { a := args[i] // Two-token form: `-e`/`--env` followed by `KEY=VALUE`. if (a == "-e" || a == "--env") && i+1 < len(args) { - out = append(out, a, maskEnvToken(args[i+1])) + out = append(out, a, maskEnvTokenWith(args[i+1], mask)) i++ continue } - out = append(out, redactArgElement(a)) + out = append(out, redactArgElement(a, mask)) } return out } // redactArgElement masks env secrets inside a single argv element, covering the // glued single-token forms and the embedded command-string form. -func redactArgElement(a string) string { +func redactArgElement(a string, mask func(string) string) string { // Command-string element (e.g. the `-c` argument of a login-shell wrap): // mask any embedded `-e KEY=VALUE` occurrences. if strings.ContainsAny(a, " \t") { - return RedactDockerCommandString(a) + return RedactDockerCommandStringWith(a, mask) } // Glued long form: `--env=KEY=VALUE`. if rest, ok := strings.CutPrefix(a, "--env="); ok { - return "--env=" + maskEnvToken(rest) + return "--env=" + maskEnvTokenWith(rest, mask) } // Glued short form: `-eKEY=VALUE`. if strings.HasPrefix(a, "-e") && len(a) > 2 && strings.Contains(a[2:], "=") { - return "-e" + maskEnvToken(a[2:]) + return "-e" + maskEnvTokenWith(a[2:], mask) } return a } @@ -65,17 +78,24 @@ func redactArgElement(a string) string { // `--env KEY=VALUE` flag found within a single command string, leaving the rest // of the string (subcommand, flags, image name) intact. func RedactDockerCommandString(s string) string { + return RedactDockerCommandStringWith(s, secret.MaskSecretValue) +} + +// RedactDockerCommandStringWith is RedactDockerCommandString with a +// caller-chosen mask rendering. See RedactDockerArgsWith. +func RedactDockerCommandStringWith(s string, mask func(string) string) string { return dockerEnvFlagRegex.ReplaceAllStringFunc(s, func(m string) string { sub := dockerEnvFlagRegex.FindStringSubmatch(m) // sub[1]=lead, sub[2]=flag, sub[3]=whitespace, sub[4]=value token - return sub[1] + sub[2] + sub[3] + maskEnvToken(sub[4]) + return sub[1] + sub[2] + sub[3] + maskEnvTokenWith(sub[4], mask) }) } -// maskEnvToken masks the value portion of a `KEY=VALUE` token, preserving the -// key and any surrounding single/double quotes. Tokens without a `=` or with an -// empty value are returned unchanged (they are not secret-bearing env values). -func maskEnvToken(tok string) string { +// maskEnvTokenWith masks the value portion of a `KEY=VALUE` token, preserving +// the key and any surrounding single/double quotes. Tokens without a `=` or +// with an empty value are returned unchanged (they are not secret-bearing env +// values). +func maskEnvTokenWith(tok string, mask func(string) string) string { quote := "" inner := tok if len(inner) >= 2 { @@ -94,5 +114,5 @@ func maskEnvToken(tok string) string { if val == "" { return tok } - return quote + key + "=" + secret.MaskSecretValue(val) + quote + return quote + key + "=" + mask(val) + quote } diff --git a/internal/shellwrap/shellwrap.go b/internal/shellwrap/shellwrap.go index 0c5f2c556..362f434b8 100644 --- a/internal/shellwrap/shellwrap.go +++ b/internal/shellwrap/shellwrap.go @@ -106,13 +106,25 @@ func WrapWithUserShell(logger *zap.Logger, command string, args []string) (shell commandString := strings.Join(parts, " ") if logger != nil { - // Redact secret env values (`-e KEY=VALUE`) before logging — docker-command - // upstreams inject Slack/Jira tokens here and debug logs are written to disk. + // Issue #1158: this line deliberately does NOT print argv or the + // wrapped command string. + // + // RedactDockerArgs / RedactDockerCommandString are structural rules — + // they mask the value half of `-e KEY=VALUE` and nothing else — so a + // plain `npx some-mcp --api-key sk-live-...` went through them in the + // clear. The rule that catches that (oauth.Redaction.SpawnArgv) lives + // in internal/oauth, which already depends on this package, so it + // cannot be reached from here without an import cycle. + // + // Rather than keep a half-rule that reads as protection, the fields are + // dropped: the caller one frame up + // (upstream/core.Client.wrapWithUserShell) logs original_command, + // original_args and shell through the complete rule, so nothing + // diagnostic is lost on the path that actually spawns upstreams. logger.Debug("shellwrap: wrapping command with user login shell", zap.String("original_command", command), - zap.Strings("original_args", RedactDockerArgs(args)), - zap.String("shell", shell), - zap.String("wrapped_command", RedactDockerCommandString(commandString))) + zap.Int("arg_count", len(args)), + zap.String("shell", shell)) } isBash := isBashLikeShell(shell) diff --git a/internal/transport/logging.go b/internal/transport/logging.go index fa3c39316..973b52caa 100644 --- a/internal/transport/logging.go +++ b/internal/transport/logging.go @@ -40,9 +40,14 @@ func (t *LoggingTransport) RoundTrip(req *http.Request) (*http.Response, error) startTime := time.Now() - // Log request - fmt.Printf("📤 HTTP REQUEST: %s %s\n", req.Method, req.URL.String()) - fmt.Printf(" Headers: %v\n", req.Header) + // Log request. + // + // Issue #1158: BOTH sinks in this file get the same scrubbed string, never + // one and not the other — the Printf copy goes to the operator's terminal + // and an observer-only test would show green against a zap-only fix. + // The method, host and path survive; only credentials are replaced. + fmt.Printf("📤 HTTP REQUEST: %s %s\n", req.Method, oauth.AuditRedaction.URLValueDeep(req.URL.String())) + fmt.Printf(" Headers: %v\n", oauth.RedactHeaders(req.Header)) // Log request body if present (for non-SSE requests) if req.Body != nil && req.Method != "GET" { @@ -50,7 +55,11 @@ func (t *LoggingTransport) RoundTrip(req *http.Request) (*http.Response, error) if err == nil { req.Body = io.NopCloser(bytes.NewBuffer(bodyBytes)) if len(bodyBytes) > 0 && len(bodyBytes) < 10000 { - t.logger.Debug("📤 REQUEST BODY", zap.String("body", string(bodyBytes))) + // An OAuth token-exchange body carries client_secret and + // refresh_token; ScrubUpstreamText rewrites only the + // recognised credential shapes, so the rest of the JSON stays + // byte-identical and trace mode keeps its purpose. + t.logger.Debug("📤 REQUEST BODY", zap.String("body", oauth.ScrubUpstreamText(string(bodyBytes)))) } } } @@ -73,12 +82,13 @@ func (t *LoggingTransport) RoundTrip(req *http.Request) (*http.Response, error) // Log response using fmt.Printf fmt.Printf("đŸ“Ĩ HTTP RESPONSE: %d %s (duration: %v)\n", resp.StatusCode, resp.Status, duration) - fmt.Printf(" Response Headers: %v\n", resp.Header) + safeRespHeaders := oauth.RedactHeaders(resp.Header) + fmt.Printf(" Response Headers: %v\n", safeRespHeaders) t.logger.Info("đŸ“Ĩ HTTP RESPONSE", zap.Int("status", resp.StatusCode), zap.String("status_text", resp.Status), - zap.Any("headers", resp.Header), + zap.Any("headers", safeRespHeaders), zap.Duration("duration", duration)) // Check if this is an SSE connection @@ -149,7 +159,7 @@ func (lr *loggingReader) readSSEFramesFromPipe(pr *io.PipeReader) { for scanner.Scan() { line := scanner.Text() - fmt.Printf(" 📜 Raw SSE line: %q\n", line) + fmt.Printf(" 📜 Raw SSE line: %q\n", oauth.ScrubUpstreamText(line)) // Empty line indicates end of frame if line == "" { @@ -158,12 +168,14 @@ func (lr *loggingReader) readSSEFramesFromPipe(pr *io.PipeReader) { frameDuration := time.Since(frameStartTime) frameContent := currentFrame.String() + safeData := oauth.ScrubUpstreamText(dataContent) + safeContent := oauth.ScrubUpstreamText(frameContent) fmt.Printf("đŸ”ĩ SSE FRAME #%d (event: %s, data: %s, duration since prev: %v)\n%s\n", - lr.frameID, eventType, dataContent, frameDuration, frameContent) + lr.frameID, eventType, safeData, frameDuration, safeContent) lr.logger.Info(fmt.Sprintf("đŸ”ĩ SSE FRAME #%d", lr.frameID), zap.String("event", eventType), - zap.String("data", dataContent), - zap.String("content", frameContent), + zap.String("data", safeData), + zap.String("content", safeContent), zap.Duration("time_since_prev", frameDuration), zap.Time("timestamp", time.Now())) @@ -218,11 +230,11 @@ func (lr *loggingReader) Read(p []byte) (n int, err error) { if err == io.EOF && !lr.isSSE && lr.buffer.Len() > 0 { body := lr.buffer.String() if len(body) < 10000 { - lr.logger.Debug("đŸ“Ĩ RESPONSE BODY", zap.String("body", body)) + lr.logger.Debug("đŸ“Ĩ RESPONSE BODY", zap.String("body", oauth.ScrubUpstreamText(body))) } else { lr.logger.Debug("đŸ“Ĩ RESPONSE BODY (truncated)", zap.Int("total_size", len(body)), - zap.String("preview", body[:1000]+"...")) + zap.String("preview", oauth.ScrubUpstreamText(body[:1000])+"...")) } } diff --git a/internal/transport/trace_redact_test.go b/internal/transport/trace_redact_test.go new file mode 100644 index 000000000..ad9502fa2 --- /dev/null +++ b/internal/transport/trace_redact_test.go @@ -0,0 +1,151 @@ +package transport + +import ( + "bytes" + "fmt" + "io" + "net/http" + "net/http/httptest" + "os" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" +) + +// captureStdout runs fn with os.Stdout replaced by a pipe and returns what was +// written. The Printf copy is half the leak in this file: a test that only +// watches zap passes vacuously against a fix that only patches the zap fields. +func captureStdout(t *testing.T, fn func()) string { + t.Helper() + orig := os.Stdout + r, w, err := os.Pipe() + require.NoError(t, err) + os.Stdout = w + + done := make(chan string, 1) + go func() { + var buf bytes.Buffer + _, _ = io.Copy(&buf, r) + done <- buf.String() + }() + + fn() + + os.Stdout = orig + require.NoError(t, w.Close()) + out := <-done + require.NoError(t, r.Close()) + return out +} + +func observedText(logs *observer.ObservedLogs) string { + var b strings.Builder + for _, e := range logs.All() { + b.WriteString(e.Message) + for k, v := range e.ContextMap() { + fmt.Fprintf(&b, " %s=%v", k, v) + } + b.WriteString("\n") + } + return b.String() +} + +// TestLoggingTransport_RedactsURLHeadersAndBodies drives the real RoundTrip +// against an httptest server and watches BOTH sinks. +func TestLoggingTransport_RedactsURLHeadersAndBodies(t *testing.T) { + const ( + urlSecret = "SUPERSECRETURLQUERYVALUE" + reqHdrSecret = "SUPERSECRETREQHEADERVALUE" + reqBodySecret = "SUPERSECRETREQBODYVALUE" + respHdrSecret = "SUPERSECRETRESPHEADERVALUE" + respBodySecre = "SUPERSECRETRESPBODYVALUE" + ) + + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.Header().Set("Set-Cookie", "session="+respHdrSecret) + w.Header().Set("Content-Type", "application/json") + w.WriteHeader(http.StatusOK) + _, _ = w.Write([]byte(`{"access_token":"` + respBodySecre + `"}`)) + })) + defer srv.Close() + + obsCore, logs := observer.New(zapcore.DebugLevel) + tr := NewLoggingTransport(srv.Client().Transport, zap.New(obsCore)) + + stdout := captureStdout(t, func() { + req, err := http.NewRequest(http.MethodPost, + srv.URL+"/mcp?token="+urlSecret, + strings.NewReader("client_secret="+reqBodySecret)) + require.NoError(t, err) + req.Header.Set("Authorization", "Bearer "+reqHdrSecret) + + resp, err := tr.RoundTrip(req) + require.NoError(t, err) + _, _ = io.ReadAll(resp.Body) + require.NoError(t, resp.Body.Close()) + }) + + zapText := observedText(logs) + for _, secret := range []string{urlSecret, reqHdrSecret, reqBodySecret, respHdrSecret, respBodySecre} { + assert.NotContains(t, stdout, secret, "secret reached the stdout trace sink") + assert.NotContains(t, zapText, secret, "secret reached the zap trace sink") + } + + // Positive controls: masking that erases the diagnostic line is the other + // failure mode this test has to catch. + assert.Contains(t, stdout, "HTTP REQUEST: POST", "the method must survive") + assert.Contains(t, stdout, "/mcp", "the request path must survive") + assert.Contains(t, stdout, "Authorization", "the header NAME must survive") + assert.Contains(t, zapText, "status=200", "the response status must survive") +} + +// TestLoggingTransport_RedactsSSEFrames covers the SSE path, whose logging is +// asynchronous. +func TestLoggingTransport_RedactsSSEFrames(t *testing.T) { + const frameSecret = "SUPERSECRETSSEFRAMEVALUE" + + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.Header().Set("Content-Type", "text/event-stream") + w.WriteHeader(http.StatusOK) + _, _ = w.Write([]byte("event: message\ndata: {\"access_token\":\"" + frameSecret + "\"}\n\n")) + if f, ok := w.(http.Flusher); ok { + f.Flush() + } + })) + defer srv.Close() + + obsCore, logs := observer.New(zapcore.DebugLevel) + tr := NewLoggingTransport(srv.Client().Transport, zap.New(obsCore)) + + stdout := captureStdout(t, func() { + req, err := http.NewRequest(http.MethodGet, srv.URL+"/sse", http.NoBody) + require.NoError(t, err) + resp, err := tr.RoundTrip(req) + require.NoError(t, err) + _, _ = io.ReadAll(resp.Body) + require.NoError(t, resp.Body.Close()) + + // The frame reader is a goroutine; wait for it rather than asserting + // against an empty observer. + deadline := time.Now().Add(3 * time.Second) + for time.Now().Before(deadline) { + if strings.Contains(observedText(logs), "SSE FRAME") { + return + } + time.Sleep(5 * time.Millisecond) + } + }) + + zapText := observedText(logs) + require.Contains(t, zapText, "SSE FRAME", + "the SSE frame log line under test was never emitted — the assertions below would be vacuous") + assert.NotContains(t, zapText, frameSecret) + assert.NotContains(t, stdout, frameSecret) + assert.Contains(t, zapText, "event=message", "the frame's event type must survive") +} diff --git a/internal/upstream/core/connection.go b/internal/upstream/core/connection.go index d7e440688..bd871ac6a 100644 --- a/internal/upstream/core/connection.go +++ b/internal/upstream/core/connection.go @@ -70,6 +70,55 @@ func (c *Client) logSafeURL() string { return oauth.RedactURLQueryParams(c.config.URL) } +// logSafeAuthURL renders an OAuth AUTHORIZATION URL for a LOG FIELD or for +// stdout (issue #1158). +// +// The authorize URL is the highest-frequency credential leak in the tree and +// needs no debug flag to reach main.log: oauth.autoDetectResource returns +// serverConfig.URL verbatim on every fallback branch (no resource_metadata in +// WWW-Authenticate, metadata without a `resource` field, a failed fetch, any +// 4xx/5xx), that value becomes extraParams["resource"], and every authorize-URL +// builder splices each extra param into the query. The result was logged at +// INFO and printed with fmt.Printf on every login attempt, so a configured +// `https://host/mcp?token=SECRET` landed on disk and on the terminal. +// +// URLValueDeep rather than RedactURLQueryParams because the credential arrives +// percent-encoded one level down (`resource=https%3A%2F%2Fhost%2Fmcp%3Ftoken%3D...`), +// where neither the sensitive-parameter name rule nor secretPattern can see it. +// +// The authorize endpoint's scheme, host, path and its own non-secret parameters +// survive, which is what lets an operator still diagnose the flow. +func logSafeAuthURL(authURL string) string { + return oauth.AuditRedaction.URLValueDeep(authURL) +} + +// logSafeArgs renders a child process's argument vector for a LOG FIELD +// (issue #1158). +// +// Every spawn log line in this package previously used +// shellwrap.RedactDockerArgs alone, which is a STRUCTURAL rule: it masks the +// value half of every `-e KEY=VALUE` docker env injection but is blind to +// `--api-key sk-live-...` and to a vendor-formatted credential sitting in a +// positional argument. oauth.Redaction.SpawnArgv composes that rule with the +// flag-name + value-shape rule, and also reaches inside the single +// `-c ""` element the login-shell wrap produces - the form +// every non-docker stdio server on macOS actually spawns as. +// +// AuditRedaction rather than LiveRedaction because these lines land in +// ~/.mcpproxy/logs/main.log and server-.log, which outlive the process +// and are exported through `upstream_servers tail_log`: the `â€ĸâ€ĸâ€ĸâ€ĸ` marker +// carries neither the secret's length nor its trailing bytes, unlike the +// interactive `sk-****89` rendering the previous helper emitted. +func logSafeArgs(args []string) []string { + return oauth.AuditRedaction.SpawnArgv(args) +} + +// logSafeCommand renders a whole child command LINE for a LOG FIELD. See +// logSafeArgs. +func logSafeCommand(cmd string) string { + return oauth.AuditRedaction.SpawnCommandString(cmd) +} + // redactURLCredentialsInError strips URL-embedded credentials from an error's // TEXT while keeping the error itself intact for errors.Is/As and for the // substring classification the connect paths do (isAuthError, isConfigError, @@ -106,11 +155,16 @@ func (e *urlRedactedError) Unwrap() error { return e.cause } // logSafeErrorField renders an error as a log field with any URL-embedded // credential removed. Use it instead of zap.Error on the connection paths. +// +// #1158: upgraded from RedactSensitiveData to ScrubUpstreamText. The name rule +// alone cannot see a credential under an unrecognised parameter name +// (`?opaque=ghp_â€Ļ`), and a transport error is exactly the free-form, +// originated-outside-mcpproxy text ScrubUpstreamText is documented for. func logSafeErrorField(err error) zap.Field { if err == nil { return zap.Skip() } - return zap.String("error", oauth.RedactSensitiveData(err.Error())) + return zap.String("error", oauth.ScrubUpstreamText(err.Error())) } func (c *Client) Connect(ctx context.Context) error { diff --git a/internal/upstream/core/connection_docker.go b/internal/upstream/core/connection_docker.go index 623b1adf4..ef4cd02fc 100644 --- a/internal/upstream/core/connection_docker.go +++ b/internal/upstream/core/connection_docker.go @@ -68,8 +68,8 @@ func (c *Client) setupDockerIsolation(command string, args []string) (dockerComm zap.String("runtime_type", runtimeType), zap.String("container_name", c.containerName), zap.String("container_command", containerCommand), - zap.Strings("container_args", containerArgs), - zap.Strings("docker_run_args", dockerRunArgs)) + zap.Strings("container_args", logSafeArgs(containerArgs)), + zap.Strings("docker_run_args", logSafeArgs(dockerRunArgs))) // Log to server-specific log as well if c.upstreamLogger != nil { @@ -299,7 +299,7 @@ func (c *Client) insertCidfileIntoDockerArgs(args []string, cidFile string) []st if len(args) == 0 || args[0] != cmdRun { c.logger.Warn("Could not find 'run' as the first docker arg for cidfile insertion - container ID tracking may be limited", zap.String("server", c.config.Name), - zap.Strings("args", args)) + zap.Strings("args", logSafeArgs(args))) return args } @@ -346,7 +346,7 @@ func (c *Client) insertCidfileIntoShellDockerCommand(shellArgs []string, cidFile if len(shellArgs) < 2 { c.logger.Error("Unexpected shell command format for Docker cidfile insertion - cannot track container ID", zap.String("server", c.config.Name), - zap.Strings("shell_args", shellArgs), + zap.Strings("shell_args", logSafeArgs(shellArgs)), zap.String("expected_format", "[shell, -c, docker_command] or [-l, -c, docker_command]")) return shellArgs } @@ -354,7 +354,7 @@ func (c *Client) insertCidfileIntoShellDockerCommand(shellArgs []string, cidFile if secondToLast != "-c" && secondToLast != "/c" { c.logger.Error("Unexpected shell command format for Docker cidfile insertion - cannot track container ID", zap.String("server", c.config.Name), - zap.Strings("shell_args", shellArgs), + zap.Strings("shell_args", logSafeArgs(shellArgs)), zap.String("expected_format", "[shell, -c, docker_command] or [-l, -c, docker_command]")) return shellArgs } @@ -375,8 +375,8 @@ func (c *Client) insertCidfileIntoShellDockerCommand(shellArgs []string, cidFile c.logger.Debug("Inserted cidfile into shell-wrapped Docker command", zap.String("server", c.config.Name), - zap.String("original_cmd", dockerCmd), - zap.String("modified_cmd", dockerCmdWithCid)) + zap.String("original_cmd", logSafeCommand(dockerCmd)), + zap.String("modified_cmd", logSafeCommand(dockerCmdWithCid))) return newArgs } @@ -384,7 +384,7 @@ func (c *Client) insertCidfileIntoShellDockerCommand(shellArgs []string, cidFile // If we can't find "docker run", fall back to appending c.logger.Warn("Could not find 'docker run' in shell command for cidfile insertion", zap.String("server", c.config.Name), - zap.String("docker_cmd", dockerCmd)) + zap.String("docker_cmd", logSafeCommand(dockerCmd))) return append(shellArgs, "--cidfile", cidFile) } @@ -403,6 +403,6 @@ func (c *Client) extractContainerNameFromArgs(dockerArgs []string) string { c.logger.Warn("Could not extract container name from Docker args - cleanup may be limited", zap.String("server", c.config.Name), - zap.Strings("docker_args", dockerArgs)) + zap.Strings("docker_args", logSafeArgs(dockerArgs))) return "" } diff --git a/internal/upstream/core/connection_launcher.go b/internal/upstream/core/connection_launcher.go index 36287bedc..cbf5829f1 100644 --- a/internal/upstream/core/connection_launcher.go +++ b/internal/upstream/core/connection_launcher.go @@ -78,9 +78,10 @@ func (c *Client) connectWithLauncher(ctx context.Context) error { sink := newLoggerWriter(c.upstreamLogger, c.logger) spec := &launcher.Spec{ - Cmd: cmd, - LogSink: sink, - Name: c.config.Name, + Cmd: cmd, + LogSink: sink, + Name: c.config.Name, + RedactArgs: logSafeArgs, } handle, err := launcher.Spawn(ctx, spec, c.logger) @@ -316,7 +317,7 @@ func (c *Client) buildLauncherCmd(_ context.Context, willUseDocker bool) (*exec. c.logger.Debug("launcher command prepared", zap.String("server", c.config.Name), zap.String("command", finalCommand), - zap.Strings("args", finalArgs), + zap.Strings("args", logSafeArgs(finalArgs)), zap.String("working_dir", c.config.WorkingDir), zap.Bool("docker", willUseDocker)) diff --git a/internal/upstream/core/connection_lifecycle.go b/internal/upstream/core/connection_lifecycle.go index 88a8d7dbf..6ea597150 100644 --- a/internal/upstream/core/connection_lifecycle.go +++ b/internal/upstream/core/connection_lifecycle.go @@ -35,8 +35,12 @@ func (c *Client) initialize(ctx context.Context) error { if err != nil { // Log initialization failure to server-specific log if c.upstreamLogger != nil { + // #1158: the transport error quotes the configured URL, + // credentials and all, and this line is written to the per-server + // log FILE which `upstream_servers tail_log` hands to any MCP + // caller. c.upstreamLogger.Error("MCP initialize JSON-RPC call failed", - zap.Error(err)) + logSafeErrorField(err)) } // CRITICAL FIX: Additional cleanup for direct initialize() calls @@ -46,7 +50,7 @@ func (c *Client) initialize(ctx context.Context) error { zap.String("server", c.config.Name), zap.String("container_name", c.containerName), zap.String("container_id", c.containerID), - zap.Error(err)) + logSafeErrorField(err)) } // Surface the useful context that the raw "context deadline exceeded" diff --git a/internal/upstream/core/connection_oauth.go b/internal/upstream/core/connection_oauth.go index ea5c638db..0807bfc10 100644 --- a/internal/upstream/core/connection_oauth.go +++ b/internal/upstream/core/connection_oauth.go @@ -477,7 +477,7 @@ func (c *Client) tryOAuthAuth(ctx context.Context) error { return &ErrOAuthPending{ ServerName: c.config.Name, - ServerURL: c.config.URL, + ServerURL: c.logSafeURL(), Message: "login available via Web UI, system tray menu, or 'mcpproxy auth login' CLI command", } } @@ -545,7 +545,7 @@ func (c *Client) tryOAuthAuth(ctx context.Context) error { zap.String("server", c.config.Name)) return &ErrOAuthPending{ ServerName: c.config.Name, - ServerURL: c.config.URL, + ServerURL: c.logSafeURL(), Message: "server error with stored token - re-login available via Web UI, system tray menu, or 'mcpproxy auth login' CLI command", } } @@ -963,7 +963,7 @@ func (c *Client) handleOAuthAuthorization(ctx context.Context, authErr error, oa ServerName: c.config.Name, Message: metadataErr.Message, Details: &contracts.OAuthErrorDetails{ - ServerURL: c.config.URL, + ServerURL: c.logSafeURL(), ProtectedResourceMetadata: func() *contracts.MetadataStatus { if metadataErr.Details.ProtectedResourceMetadata != nil { return &contracts.MetadataStatus{ @@ -1163,7 +1163,7 @@ func (c *Client) handleOAuthAuthorization(ctx context.Context, authErr error, oa ServerName: c.config.Name, Message: fmt.Sprintf("Failed to get authorization URL for '%s': %s", c.config.Name, authURLErr.Error()), Details: &contracts.OAuthErrorDetails{ - ServerURL: c.config.URL, + ServerURL: c.logSafeURL(), }, Suggestion: suggestion, DebugHint: fmt.Sprintf("For logs: mcpproxy upstream logs %s", c.config.Name), @@ -1181,7 +1181,7 @@ func (c *Client) handleOAuthAuthorization(ctx context.Context, authErr error, oa c.logger.Debug("Added extra OAuth parameter to authorization URL", zap.String("server", c.config.Name), zap.String("key", key), - zap.String("value", value)) + zap.String("value", oauth.AuditRedaction.ExtraParamValue(key, value))) } parsedURL.RawQuery = query.Encode() authURL = parsedURL.String() @@ -1206,8 +1206,8 @@ func (c *Client) handleOAuthAuthorization(ctx context.Context, authErr error, oa // Always log the computed authorization URL so users can copy/paste if auto-launch fails. c.logger.Info("OAuth authorization URL ready", zap.String("server", c.config.Name), - zap.String("auth_url", authURL)) - fmt.Printf("OAuth login URL for %s:\n%s\n", c.config.Name, authURL) + zap.String("auth_url", logSafeAuthURL(authURL))) + fmt.Printf("OAuth login URL for %s:\n%s\n", c.config.Name, logSafeAuthURL(authURL)) // Check if this is a manual OAuth flow using the proper context key isManualFlow := c.isManualOAuthFlow(ctx) @@ -1224,10 +1224,10 @@ func (c *Client) handleOAuthAuthorization(ctx context.Context, authErr error, oa zap.String("server", c.config.Name), zap.Duration("time_since_last", timeSinceLastBrowser), zap.Duration("rate_limit", browserRateLimit), - zap.String("auth_url", authURL)) + zap.String("auth_url", logSafeAuthURL(authURL))) fmt.Printf("OAuth authorization required for %s, but browser opening is rate limited.\n", c.config.Name) - fmt.Printf("Please open the following URL manually in your browser: %s\n", authURL) + fmt.Printf("Please open the following URL manually in your browser: %s\n", logSafeAuthURL(authURL)) } else { if isManualFlow { c.logger.Info("đŸŽ¯ Manual OAuth flow detected - bypassing rate limiting", @@ -1238,14 +1238,14 @@ func (c *Client) handleOAuthAuthorization(ctx context.Context, authErr error, oa // Open the browser to the authorization URL c.logger.Info("🌐 Opening browser for OAuth authorization", zap.String("server", c.config.Name), - zap.String("auth_url", authURL)) + zap.String("auth_url", logSafeAuthURL(authURL))) if err := c.openBrowser(authURL); err != nil { c.logger.Warn("Failed to open browser automatically, please open manually", zap.String("server", c.config.Name), - zap.String("url", authURL), + zap.String("url", logSafeAuthURL(authURL)), zap.Error(err)) - fmt.Printf("Please open the following URL in your browser: %s\n", authURL) + fmt.Printf("Please open the following URL in your browser: %s\n", logSafeAuthURL(authURL)) } // Update the timestamp to track browser opening for rate limiting @@ -1368,7 +1368,7 @@ func (c *Client) handleOAuthAuthorizationWithResult(ctx context.Context, authErr CorrelationID: result.CorrelationID, Message: metadataErr.Message, Details: &contracts.OAuthErrorDetails{ - ServerURL: c.config.URL, + ServerURL: c.logSafeURL(), }, Suggestion: metadataErr.Suggestion, DebugHint: fmt.Sprintf("For logs: mcpproxy upstream logs %s", c.config.Name), @@ -1487,7 +1487,7 @@ func (c *Client) handleOAuthAuthorizationWithResult(ctx context.Context, authErr CorrelationID: result.CorrelationID, Message: fmt.Sprintf("Failed to get authorization URL: %v", authURLErr), Details: &contracts.OAuthErrorDetails{ - ServerURL: c.config.URL, + ServerURL: c.logSafeURL(), }, Suggestion: "Check server OAuth configuration and try again.", DebugHint: fmt.Sprintf("For logs: mcpproxy upstream logs %s", c.config.Name), @@ -1506,7 +1506,7 @@ func (c *Client) handleOAuthAuthorizationWithResult(ctx context.Context, authErr c.logger.Debug("Added extra OAuth parameter to authorization URL", zap.String("server", c.config.Name), zap.String("key", key), - zap.String("value", value)) + zap.String("value", oauth.AuditRedaction.ExtraParamValue(key, value))) } parsedURL.RawQuery = query.Encode() authURL = parsedURL.String() @@ -1530,18 +1530,18 @@ func (c *Client) handleOAuthAuthorizationWithResult(ctx context.Context, authErr result.AuthURL = authURL c.logger.Info("🌐 Authorization URL obtained", zap.String("server", c.config.Name), - zap.String("auth_url", authURL), + zap.String("auth_url", logSafeAuthURL(authURL)), zap.String("correlation_id", result.CorrelationID)) // Open the browser if err := c.openBrowser(authURL); err != nil { c.logger.Warn("Failed to open browser automatically, please open manually", zap.String("server", c.config.Name), - zap.String("url", authURL), + zap.String("url", logSafeAuthURL(authURL)), zap.Error(err)) result.BrowserOpened = false result.BrowserError = err.Error() - fmt.Printf("Please open the following URL in your browser: %s\n", authURL) + fmt.Printf("Please open the following URL in your browser: %s\n", logSafeAuthURL(authURL)) } else { result.BrowserOpened = true } @@ -1866,7 +1866,7 @@ func (c *Client) StartOAuthFlowQuick(ctx context.Context) (*OAuthStartResult, er if os.Getenv("HEADLESS") != "" { c.logger.Info("đŸ“ĩ HEADLESS mode detected - skipping browser open", zap.String("server", c.config.Name), - zap.String("auth_url", authURL)) + zap.String("auth_url", logSafeAuthURL(authURL))) result.BrowserOpened = false result.BrowserError = "HEADLESS mode - browser not opened. Please open the auth_url manually." @@ -1884,7 +1884,7 @@ func (c *Client) StartOAuthFlowQuick(ctx context.Context) (*OAuthStartResult, er if err := c.openBrowser(authURL); err != nil { c.logger.Warn("Failed to open browser automatically", zap.String("server", c.config.Name), - zap.String("url", authURL), + zap.String("url", logSafeAuthURL(authURL)), zap.Error(err)) result.BrowserOpened = false result.BrowserError = err.Error() @@ -2036,7 +2036,7 @@ func (c *Client) getAuthorizationURLQuick(ctx context.Context, oauthConfig *clie c.logger.Debug("Added extra OAuth parameter to authorization URL", zap.String("server", c.config.Name), zap.String("key", key), - zap.String("value", value)) + zap.String("value", oauth.AuditRedaction.ExtraParamValue(key, value))) } parsedURL.RawQuery = query.Encode() authURL = parsedURL.String() @@ -2097,7 +2097,7 @@ func (c *Client) emptyClientIDFlowError(authURL, correlationID string, dcrErr er zap.NamedError("dcr_error", dcrErr), zap.String("help", "Register an OAuth app with the provider and set oauth.client_id in the server config")) details := &contracts.OAuthErrorDetails{ - ServerURL: c.config.URL, + ServerURL: c.logSafeURL(), } if dcrErr != nil { dcrStatus := &contracts.DCRStatus{ diff --git a/internal/upstream/core/connection_stdio.go b/internal/upstream/core/connection_stdio.go index a4223ec59..b233895e9 100644 --- a/internal/upstream/core/connection_stdio.go +++ b/internal/upstream/core/connection_stdio.go @@ -109,7 +109,7 @@ func (c *Client) connectStdio(ctx context.Context) error { c.logger.Debug("Docker command detected, setting up container ID tracking", zap.String("server", c.config.Name), zap.String("command", c.config.Command), - zap.Strings("original_args", shellwrap.RedactDockerArgs(args))) + zap.Strings("original_args", logSafeArgs(args))) // CRITICAL: Clean up any existing containers first to prevent duplicates // This makes container creation idempotent and safe to call multiple times @@ -186,7 +186,7 @@ func (c *Client) connectStdio(ctx context.Context) error { c.logger.Debug("Injected env vars into direct docker command", zap.String("server", c.config.Name), zap.Int("env_count", len(c.config.Env)), - zap.Strings("modified_args", shellwrap.RedactDockerArgs(argsToWrap))) + zap.Strings("modified_args", logSafeArgs(argsToWrap))) } var dockerShellWrapped bool @@ -247,9 +247,9 @@ func (c *Client) connectStdio(ctx context.Context) error { c.logger.Debug("Initialized stdio transport", zap.String("server", c.config.Name), zap.String("final_command", finalCommand), - zap.Strings("final_args", shellwrap.RedactDockerArgs(finalArgs)), + zap.Strings("final_args", logSafeArgs(finalArgs)), zap.String("original_command", c.config.Command), - zap.Strings("original_args", shellwrap.RedactDockerArgs(args)), + zap.Strings("original_args", logSafeArgs(args)), zap.String("working_dir", c.config.WorkingDir), zap.Bool("docker_isolation", c.isDockerCommand)) @@ -434,7 +434,7 @@ func (c *Client) wrapWithUserShell(command string, args []string) (shellCommand c.logger.Debug("Wrapping command with user shell for full environment inheritance", zap.String("server", c.config.Name), zap.String("original_command", command), - zap.Strings("original_args", shellwrap.RedactDockerArgs(args)), + zap.Strings("original_args", logSafeArgs(args)), zap.String("shell", shellCommand)) return shellCommand, shellArgs } diff --git a/internal/upstream/core/docker.go b/internal/upstream/core/docker.go index 5555277b2..90d853084 100644 --- a/internal/upstream/core/docker.go +++ b/internal/upstream/core/docker.go @@ -262,7 +262,7 @@ func (c *Client) killDockerContainerByCommandWithContext(ctx context.Context) { if imageName == "" { c.logger.Warn("No image name found in docker command args", zap.String("server", c.config.Name), - zap.Strings("args", c.config.Args)) + zap.Strings("args", logSafeArgs(c.config.Args))) return } diff --git a/internal/upstream/core/process_unix.go b/internal/upstream/core/process_unix.go index 282d3cffc..bf5a9737a 100644 --- a/internal/upstream/core/process_unix.go +++ b/internal/upstream/core/process_unix.go @@ -8,7 +8,6 @@ import ( "syscall" "time" - "github.com/smart-mcp-proxy/mcpproxy-go/internal/shellwrap" "go.uber.org/zap" ) @@ -40,7 +39,7 @@ func createProcessGroupCommandFunc(client *Client, workingDir string, logger *za logger.Debug("Process group configuration applied", zap.String("command", command), - zap.Strings("args", shellwrap.RedactDockerArgs(args)), + zap.Strings("args", logSafeArgs(args)), zap.String("working_dir", workingDir)) if client != nil { diff --git a/internal/upstream/core/process_windows.go b/internal/upstream/core/process_windows.go index 873fc9b0e..0bf825348 100644 --- a/internal/upstream/core/process_windows.go +++ b/internal/upstream/core/process_windows.go @@ -6,7 +6,6 @@ import ( "context" "os/exec" - "github.com/smart-mcp-proxy/mcpproxy-go/internal/shellwrap" "go.uber.org/zap" ) @@ -34,7 +33,7 @@ func createProcessGroupCommandFunc(client *Client, workingDir string, logger *za logger.Debug("Process group configuration applied (Windows)", zap.String("command", command), - zap.Strings("args", shellwrap.RedactDockerArgs(args)), + zap.Strings("args", logSafeArgs(args)), zap.String("working_dir", workingDir)) if client != nil { diff --git a/internal/upstream/core/spawn_redact_test.go b/internal/upstream/core/spawn_redact_test.go new file mode 100644 index 000000000..969531938 --- /dev/null +++ b/internal/upstream/core/spawn_redact_test.go @@ -0,0 +1,169 @@ +//go:build unix + +package core + +import ( + "context" + "fmt" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" + + "github.com/smart-mcp-proxy/mcpproxy-go/internal/config" + "github.com/smart-mcp-proxy/mcpproxy-go/internal/secureenv" +) + +const spawnSecret = "SUPERSECRETBETAARGVVALUE" + +// assertNoSecretInLog fails on any recorded field, message or fragment that +// carries the secret. +func assertNoSecretInLog(t *testing.T, recorded *observer.ObservedLogs, secret string) { + t.Helper() + for _, entry := range recorded.All() { + if strings.Contains(entry.Message, secret) { + t.Errorf("secret in log MESSAGE %q", entry.Message) + } + for k, v := range entry.ContextMap() { + if strings.Contains(fmt.Sprintf("%v", v), secret) { + t.Errorf("secret in log field %q of %q: %v", k, entry.Message, v) + } + } + } +} + +// findField returns the stringified value of the first occurrence of the named +// field on the named log message. +func findField(recorded *observer.ObservedLogs, msg, field string) (string, bool) { + for _, entry := range recorded.All() { + if entry.Message != msg { + continue + } + if v, ok := entry.ContextMap()[field]; ok { + return fmt.Sprintf("%v", v), true + } + } + return "", false +} + +// TestBuildLauncherCmd_RedactsPlainArgvSecret drives the real buildLauncherCmd +// on the plain (non-docker) path — the shape the live repro leaked, where +// wrapWithUserShell folds the whole command line into one `-c "..."` element. +func TestBuildLauncherCmd_RedactsPlainArgvSecret(t *testing.T) { + obsCore, recorded := observer.New(zapcore.DebugLevel) + + c := &Client{ + config: &config.ServerConfig{ + Name: "beta", + Command: "npx", + Args: []string{"some-mcp", "--api-key", spawnSecret}, + URL: "http://127.0.0.1:9000", + }, + logger: zap.New(obsCore), + isolationManager: NewIsolationManager(config.DefaultDockerIsolationConfig()), + envManager: secureenv.NewManager(nil), + } + + cmd, _, _, err := c.buildLauncherCmd(context.Background(), false) + require.NoError(t, err) + + // Positive control: the SPAWNED command really does still carry the secret, + // so the log assertion below is about redaction and not about a fixture + // that never contained it. + require.Contains(t, strings.Join(cmd.Args, " "), spawnSecret, + "fixture did not land: the child argv must actually carry the secret") + + assertNoSecretInLog(t, recorded, spawnSecret) + + // Positive control on the same log line: the flag must survive, or the + // masking has destroyed the diagnostic it exists for. + args, ok := findField(recorded, "launcher command prepared", "args") + require.True(t, ok, "the launcher log line under test was not emitted") + assert.Contains(t, args, "--api-key", + "masking must keep the flag name: %s", args) +} + +// TestBuildLauncherCmd_RedactsInjectedDockerEnv covers the other class: an env +// var that config turns into `-e KEY=VALUE` argv, under a BENIGN key name that +// no name matcher can recognise. +func TestBuildLauncherCmd_RedactsInjectedDockerEnv(t *testing.T) { + obsCore, recorded := observer.New(zapcore.DebugLevel) + + c := &Client{ + config: &config.ServerConfig{ + Name: "beta-docker", + Command: "docker", + Args: []string{"run", "--rm", "-e", "BENIGN_NAME=" + spawnSecret, "myimage"}, + URL: "http://127.0.0.1:9000", + }, + logger: zap.New(obsCore), + isolationManager: NewIsolationManager(config.DefaultDockerIsolationConfig()), + envManager: secureenv.NewManager(nil), + } + + _, _, _, err := c.buildLauncherCmd(context.Background(), true) + require.NoError(t, err) + + assertNoSecretInLog(t, recorded, spawnSecret) + + args, ok := findField(recorded, "launcher command prepared", "args") + require.True(t, ok, "the launcher log line under test was not emitted") + assert.Contains(t, args, "BENIGN_NAME=", + "masking must keep the env KEY: %s", args) +} + +// TestConnectStdioLogFields_RedactPlainArgvSecret covers wrapWithUserShell's own +// debug line (connection_stdio.go), which the repro showed leaking +// `original_args` twice per startup. +func TestConnectStdioLogFields_RedactPlainArgvSecret(t *testing.T) { + obsCore, recorded := observer.New(zapcore.DebugLevel) + + c := &Client{ + config: &config.ServerConfig{ + Name: "beta", + Command: "npx", + Args: []string{"some-mcp", "--api-key", spawnSecret}, + }, + logger: zap.New(obsCore), + } + + _, shellArgs := c.wrapWithUserShell(c.config.Command, c.config.Args) + require.Contains(t, strings.Join(shellArgs, " "), spawnSecret, + "fixture did not land: the wrapped command must actually carry the secret") + + assertNoSecretInLog(t, recorded, spawnSecret) + + args, ok := findField(recorded, + "Wrapping command with user shell for full environment inheritance", "original_args") + require.True(t, ok, "the wrapWithUserShell log line under test was not emitted") + assert.Contains(t, args, "--api-key", "masking must keep the flag name: %s", args) +} + +// TestInsertCidfileIntoShellDockerCommand_RedactsCommandStrings covers the +// `original_cmd` / `modified_cmd` string fields, the one shape a []string-only +// redactor structurally cannot reach. +func TestInsertCidfileIntoShellDockerCommand_RedactsCommandStrings(t *testing.T) { + obsCore, recorded := observer.New(zapcore.DebugLevel) + + c := &Client{ + config: &config.ServerConfig{Name: "beta-docker"}, + logger: zap.New(obsCore), + } + + shellArgs := []string{"-l", "-c", + "docker run --rm -e BENIGN_NAME=" + spawnSecret + " myimage uvx mcp --api-key " + spawnSecret} + out := c.insertCidfileIntoShellDockerCommand(shellArgs, "/tmp/cid.txt") + require.Contains(t, strings.Join(out, " "), spawnSecret, + "fixture did not land: the rewritten command must still carry the secret") + + assertNoSecretInLog(t, recorded, spawnSecret) + + cmdField, ok := findField(recorded, "Inserted cidfile into shell-wrapped Docker command", "modified_cmd") + require.True(t, ok, "the cidfile log line under test was not emitted") + assert.Contains(t, cmdField, "-e BENIGN_NAME=", + "masking must keep the command shape: %s", cmdField) +} diff --git a/internal/upstream/launcher/launcher.go b/internal/upstream/launcher/launcher.go index b865cc483..324e7e37c 100644 --- a/internal/upstream/launcher/launcher.go +++ b/internal/upstream/launcher/launcher.go @@ -43,6 +43,24 @@ type Spec struct { // StopGrace overrides DefaultStopGrace if non-zero. StopGrace time.Duration + + // RedactArgs masks the child's argv for the startup banner written to + // LogSink (issue #1158). + // + // The banner previously wrote cmd.Args verbatim into + // ~/.mcpproxy/logs/server-.log on every spawn - fully transformed, + // i.e. AFTER the docker env->argv injection has turned every configured + // env var into `-e KEY=VALUE`, and after a login-shell wrap has folded the + // whole command line into one `-c "..."` element. + // + // The redactor is injected rather than imported because this package is + // deliberately dependency-free (`go list -deps` returns only itself); + // importing internal/oauth would drag config/security/storage in with it. + // + // nil means the banner OMITS argv entirely. That default is fail-CLOSED on + // purpose: a future caller that forgets to set the field loses a + // diagnostic, not a secret. + RedactArgs func([]string) []string } // Handle represents a running child managed by the launcher. Stop, Wait, @@ -146,8 +164,14 @@ func Spawn(ctx context.Context, spec *Spec, log *zap.Logger) (Handle, error) { if len(args) > 0 { args = args[1:] } - _, _ = fmt.Fprintf(sink, "[launcher] starting: %s %v (pid=%d)\n", - cmd.Path, args, cmd.Process.Pid) + if spec.RedactArgs == nil { + // Fail closed: no redactor, no argv. See Spec.RedactArgs. + _, _ = fmt.Fprintf(sink, "[launcher] starting: %s (%d args, redacted) (pid=%d)\n", + cmd.Path, len(args), cmd.Process.Pid) + } else { + _, _ = fmt.Fprintf(sink, "[launcher] starting: %s %v (pid=%d)\n", + cmd.Path, spec.RedactArgs(args), cmd.Process.Pid) + } } h.pumpWG.Add(2) diff --git a/internal/upstream/launcher/launcher_redact_test.go b/internal/upstream/launcher/launcher_redact_test.go new file mode 100644 index 000000000..037a4cc94 --- /dev/null +++ b/internal/upstream/launcher/launcher_redact_test.go @@ -0,0 +1,120 @@ +package launcher + +import ( + "bytes" + "context" + "os/exec" + "strings" + "sync" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap" +) + +// syncBuf is a race-free sink: Spawn's banner and the two pump goroutines all +// write to it. +type syncBuf struct { + mu sync.Mutex + b bytes.Buffer +} + +func (s *syncBuf) Write(p []byte) (int, error) { + s.mu.Lock() + defer s.mu.Unlock() + return s.b.Write(p) +} + +func (s *syncBuf) String() string { + s.mu.Lock() + defer s.mu.Unlock() + return s.b.String() +} + +// TestSpawnBanner_OmitsArgvWithoutARedactor pins the fail-CLOSED default. +// +// #1158: the `[launcher] starting:` banner wrote the child's FULLY TRANSFORMED +// argv — post docker env->argv injection, post login-shell wrap — into +// ~/.mcpproxy/logs/server-.log on every spawn. This package is +// deliberately dependency-free, so the redactor is injected; a caller that +// forgets to set it must lose the diagnostic, not the secret. +func TestSpawnBanner_OmitsArgvWithoutARedactor(t *testing.T) { + const secret = "SUPERSECRETBETAARGVVALUE" + sink := &syncBuf{} + + spec := &Spec{ + Cmd: exec.Command("/bin/echo", "--api-key", secret), + LogSink: sink, + Name: "no-redactor", + // RedactArgs deliberately unset. + } + h, err := Spawn(context.Background(), spec, zap.NewNop()) + require.NoError(t, err) + _ = h.Wait() + require.NoError(t, waitForBanner(sink)) + + out := sink.String() + banner := bannerLine(t, out) + assert.NotContains(t, banner, secret, + "a nil redactor must not publish argv: %s", banner) + assert.Contains(t, banner, "/bin/echo", + "the command path is the diagnostic that must survive") + assert.Contains(t, banner, "redacted") +} + +// TestSpawnBanner_UsesTheSuppliedRedactor proves the hook is actually wired to +// the banner (and not, say, applied to a copy that is then discarded). +func TestSpawnBanner_UsesTheSuppliedRedactor(t *testing.T) { + const secret = "SUPERSECRETBETAARGVVALUE" + sink := &syncBuf{} + + spec := &Spec{ + Cmd: exec.Command("/bin/echo", "--api-key", secret), + LogSink: sink, + Name: "with-redactor", + RedactArgs: func(args []string) []string { + out := make([]string, len(args)) + for i, a := range args { + if a == secret { + out[i] = "MASKED" + continue + } + out[i] = a + } + return out + }, + } + h, err := Spawn(context.Background(), spec, zap.NewNop()) + require.NoError(t, err) + _ = h.Wait() + require.NoError(t, waitForBanner(sink)) + + banner := bannerLine(t, sink.String()) + assert.NotContains(t, banner, secret) + assert.Contains(t, banner, "MASKED", "the banner must render the redactor's output") + assert.Contains(t, banner, "--api-key", "the flag name must still be readable") +} + +func waitForBanner(sink *syncBuf) error { + deadline := time.Now().Add(3 * time.Second) + for time.Now().Before(deadline) { + if strings.Contains(sink.String(), "[launcher] starting:") { + return nil + } + time.Sleep(5 * time.Millisecond) + } + return context.DeadlineExceeded +} + +func bannerLine(t *testing.T, out string) string { + t.Helper() + for _, line := range strings.Split(out, "\n") { + if strings.Contains(line, "[launcher] starting:") { + return line + } + } + t.Fatalf("no launcher banner in sink output: %q", out) + return "" +} From 104c9bd12814625b60ce2bd6be1c6fb8599a1c03 Mon Sep 17 00:00:00 2001 From: Algis Dumbris Date: Wed, 2 Sep 2026 10:18:46 +0300 Subject: [PATCH 2/4] fix(security): close the OAuth code, error-text and quoting gaps the first pass left MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Round-2 cross-review of #1158. Seven blocking/major findings, three confirmed minors, three judged-then-fixed, and one design comment that was simply wrong. The sharpest was pre-existing on main rather than introduced here: the OAuth CALLBACK handler logged the authorization CODE at Info, plus the whole raw callback query, on every single login. The code is a single-use credential redeemable at the token endpoint, and it sat in ~/.mcpproxy/logs/main.log for the window before mcpproxy spent it — forever, for a flow that never completed. `state` (the CSRF nonce that pairs with it) was on five more lines and inside two operator-visible error messages; it is now a truncated SHA-256, which is all the log lines ever used it for. The rest is one theme: masking a FIELD does not mask the STATEMENT. - A *url.Error renders the request URL inside its own text, so fourteen `zap.Error(err)` calls in discovery.go published, on the identical line, the credential their masked `metadata_url` sibling was written to hide. New logSafeErrorField/LogSafeErrorText in internal/oauth; internal/transport's twin, which had drifted back to the name-rule-only scrubber, rejoins it. - `url_tried` survived raw four lines below a line this branch fixed, along with every `auth_server*` field in discovery.go — because the AST guard's regex was written from the sites already fixed. It now matches `_tried$` and the four auth-server names, and a second guard fails any log statement that carries a URL field and a raw zap.Error together. - contracts.OAuthFlowError was scrubbed field-by-field at seven construction sites, and one got it half right: emptyClientIDFlowError masked Details.ServerURL and set Details.DCRStatus.Error raw on the same struct, which is JSON-encoded straight to the REST caller. One scrubbedFlowError at construction now walks the whole struct, and a third guard requires every literal to go through it. - Client.logSafeURL, managed.Client.logSafeURL, the transport config, the CLI client and the four registry routes rendered with RedactURLQueryParams — the NAME rule only — while this branch's own new renderer deliberately does not, and says why. One exported oauth.LogSafeURL now backs all of them. Two spawn-rule corrections pull in opposite directions and both matter: - The command-string tokenizer split on whitespace only, while the string it is fed comes from Shellescape — so a credential containing a space arrived single-quoted, was split into four tokens, and had exactly its first fragment masked. On the `-c ""` form the original commit calls "the form that actually leaked". The split is now shell-aware (including the `'"'"'` idiom), falling back to whitespace-only when quotes do not balance, because swallowing the rest of a line into one token would be a new leak rather than a safe degradation. - The other direction: IsSensitiveKeyName matches SUBSTRINGS, so applying it to a spawn argv blanked `--max-tokens 4096` and `--public-key-path /etc/x`. The property that makes this redaction acceptable to an operator is that flag names, hosts and ordinary values survive, so the log-only rule now subtracts a short list of qualifier segments (max/min/num/public/â€Ļ). It keeps the substring match rather than switching to segment EQUALITY, which would have silently un-masked `--apikey` and `--clientsecret`. Three findings were investigated rather than reflexively fixed; all three were genuine and all three are closed. The PRM's own authorization_servers list left createMetadataError unscrubbed beside siblings that were scrubbed. The token endpoint's non-200 BODY was embedded verbatim in the refresh error — provider free text that echoes request parameters, unbounded, logged and returned over REST. And the launched child's stdout/stderr went into the per-server log raw, which matters more than it looks: GET /api/v1/servers/{id}/logs serves that file, so an upstream echoing its own startup banner puts a credential mcpproxy handed it onto an HTTP surface. Finally, the design comment claiming the two-stage spawn composition is provably idempotent was false, and the pinning test used the one fixture that hid it: RedactSensitiveData's sensitiveParams sweep matches `[^&\s]+`, which DOES match the bullet marker, so `SLACK_TOKEN=â€ĸâ€ĸâ€ĸâ€ĸ` becomes `SLACK_TOKEN=***REDACTED***` while `API_KEY=â€ĸâ€ĸâ€ĸâ€ĸ` does not. The composition is disclosure-safe, not byte-idempotent; the comment now says so and both spellings are pinned. Diagnostics preserved throughout: flag names, env KEY names, hosts, paths, OAuth error codes, DCR status codes and `code_present` all survive. --- internal/oauth/callback_redact_test.go | 151 ++++++++++++ internal/oauth/config.go | 45 ++-- internal/oauth/discovery.go | 57 +++-- .../oauth/discovery_redact_round2_test.go | 101 ++++++++ internal/oauth/logging.go | 143 ++++++++++++ internal/oauth/redactview.go | 38 +-- internal/oauth/spawnargv.go | 208 +++++++++++++++-- internal/oauth/spawnargv_round2_test.go | 171 ++++++++++++++ internal/oauth/url_log_field_guard_test.go | 220 +++++++++++++++++- internal/server/add_registry_source.go | 4 +- internal/server/edit_registry_source.go | 2 +- internal/server/remove_registry_source.go | 2 +- internal/transport/http.go | 18 +- internal/transport/logging.go | 32 ++- internal/transport/preview_redact_test.go | 80 +++++++ internal/transport/retry_after.go | 2 +- internal/upstream/cli/client.go | 2 +- .../upstream/core/child_output_redact_test.go | 72 ++++++ internal/upstream/core/client.go | 32 ++- internal/upstream/core/connection.go | 8 +- internal/upstream/core/connection_launcher.go | 16 ++ internal/upstream/core/connection_oauth.go | 165 ++++++++----- .../upstream/core/flow_error_redact_test.go | 120 ++++++++++ internal/upstream/managed/client.go | 2 +- 24 files changed, 1547 insertions(+), 144 deletions(-) create mode 100644 internal/oauth/callback_redact_test.go create mode 100644 internal/oauth/discovery_redact_round2_test.go create mode 100644 internal/oauth/spawnargv_round2_test.go create mode 100644 internal/transport/preview_redact_test.go create mode 100644 internal/upstream/core/child_output_redact_test.go create mode 100644 internal/upstream/core/flow_error_redact_test.go diff --git a/internal/oauth/callback_redact_test.go b/internal/oauth/callback_redact_test.go new file mode 100644 index 000000000..fba9067c2 --- /dev/null +++ b/internal/oauth/callback_redact_test.go @@ -0,0 +1,151 @@ +package oauth + +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" +) + +// Issue #1158, review round 2, finding B1. +// +// The OAuth CALLBACK handler logged, at Info, on every single login: +// +// zap.String("query", r.URL.RawQuery) // the whole callback query +// zap.String("code", params["code"]) // the authorization code itself +// +// The authorization code is a single-use credential: presented at the token +// endpoint with the PKCE verifier it yields an access token. It landed in +// ~/.mcpproxy/logs/main.log — a file that outlives the process, is readable by +// anything with disk access, and is served over REST for stdio servers — on +// every OAuth login, with no debug flag involved. +// +// The oracle is the one this issue keeps needing: no RUN of the secret's bytes +// may appear anywhere in the rendered line. A whole-string containment check +// passes against a half-mask. +func assertNoRun(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) + } +} + +// newObservedCallbackServer builds a CallbackServer wired to an in-memory log +// sink, with one flow parked on `state` so the delivery path is exercised. +func newObservedCallbackServer(t *testing.T, state string) (*CallbackServer, *observer.ObservedLogs) { + t.Helper() + core, logs := observer.New(zap.DebugLevel) + cs := &CallbackServer{ + ServerName: "alpha", + logger: zap.New(core), + waiters: make(map[string]chan map[string]string), + } + if state != "" { + cs.RegisterState(state) + } + return cs, logs +} + +func renderedLines(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() +} + +func TestCallbackHandlerNeverLogsTheAuthorizationCode(t *testing.T) { + const code = "AUTHCODEwqYnFsUD0Rk4pQ3v7XcJ2m" + const state = "STATENONCE9fbc41aa7d2e" + + cs, logs := newObservedCallbackServer(t, state) + + req := httptest.NewRequest(http.MethodGet, DefaultRedirectPath+ + "?code="+code+"&state="+state+"&scope=read%20write", nil) + rec := httptest.NewRecorder() + cs.handleCallback(rec, req) + + out := renderedLines(logs) + require.NotEmpty(t, out, "the handler must still log — a fix that deletes the line is not the fix") + + assertNoRun(t, out, code, 6) + assertNoRun(t, out, state, 6) + + // The diagnostics the lines exist for must survive. + assert.Contains(t, out, "code_present=true", + "an operator still needs to know whether the provider returned a code at all") + assert.Contains(t, out, "scope=read write", + "non-credential callback parameters must stay readable") + assert.Contains(t, out, StateFingerprint(state), + "the state fingerprint is what correlates the callback with the flow that minted it") +} + +// A callback that carries no code (the provider reported an error instead) must +// still be diagnosable, and the provider's own free text must be scrubbed. +func TestCallbackHandlerScrubsProviderErrorText(t *testing.T) { + cs, logs := newObservedCallbackServer(t, "S-unknown-flow") + + req := httptest.NewRequest(http.MethodGet, DefaultRedirectPath+ + "?error=invalid_request&error_description=bad+redirect+for+token%3Dghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789&state=S-unknown-flow", nil) + rec := httptest.NewRecorder() + cs.handleCallback(rec, req) + + out := renderedLines(logs) + assert.NotContains(t, out, "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789", + "provider-authored error text is upstream free text and gets the free-text rule") + assert.Contains(t, out, "invalid_request", + "the provider's error CODE is the diagnostic and must survive") +} + +// The unknown-state path builds an operator-visible error message. It quoted +// the raw state, and that message is stored and surfaced by +// RecordOAuthFailure. +func TestUnknownStateCallbackMessageCarriesNoNonce(t *testing.T) { + const state = "STATENONCEbb17c9d4ef05" + cs, logs := newObservedCallbackServer(t, "") // nobody waiting + + req := httptest.NewRequest(http.MethodGet, DefaultRedirectPath+"?code=X&state="+state, nil) + rec := httptest.NewRecorder() + cs.handleCallback(rec, req) + + out := renderedLines(logs) + assertNoRun(t, out, state, 6) + assert.Equal(t, http.StatusBadRequest, rec.Code) +} + +func TestLogSafeCallbackQuery(t *testing.T) { + const code = "AUTHCODEqq81mVzZlPd0" + got := LogSafeCallbackQuery("code=" + code + "&state=abc123def456&scope=read&error_description=nope") + + assertNoRun(t, got, code, 6) + assert.Contains(t, got, "scope=read", "a benign parameter stays readable") + assert.Contains(t, got, "code=", "the parameter NAME survives; only the value goes") + assert.NotContains(t, got, "state=abc123def456") + + // A query mcpproxy cannot parse still must not be published verbatim. + assert.NotContains(t, LogSafeCallbackQuery("%zz&access_token=ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789"), + "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789") + + assert.Equal(t, "", LogSafeCallbackQuery("")) +} + +func TestStateFingerprintCorrelatesWithoutDisclosing(t *testing.T) { + const state = "STATENONCE-3f7a91cc" + fp := StateFingerprint(state) + + assertNoRun(t, fp, state, 4) + assert.Equal(t, fp, StateFingerprint(state), "the same flow must render the same handle on every line") + assert.NotEqual(t, fp, StateFingerprint(state+"x"), "two live flows must stay distinguishable") + assert.Equal(t, "(none)", StateFingerprint("")) +} diff --git a/internal/oauth/config.go b/internal/oauth/config.go index 4ef8da17c..9bb1d2d25 100644 --- a/internal/oauth/config.go +++ b/internal/oauth/config.go @@ -729,7 +729,7 @@ func handleUnauthorizedResponse(resp *http.Response, body []byte, serverConfig * logger.Debug("Failed to fetch Protected Resource Metadata", zap.String("server", serverConfig.Name), zap.String("metadata_url", logSafeURL(metadataURL)), - zap.Error(err)) + logSafeErrorField(err)) // Fallback to server URL return serverConfig.URL } @@ -902,7 +902,7 @@ func createOAuthConfigInternal(serverConfig *config.ServerConfig, storage *stora logger.Warn("Authorization Server Metadata discovery failed", zap.String("server", serverConfig.Name), zap.String("metadata_url", logSafeURL(baseURL+"/.well-known/oauth-authorization-server")), - zap.Error(err)) + logSafeErrorField(err)) } } } @@ -1112,8 +1112,8 @@ func createOAuthConfigInternal(serverConfig *config.ServerConfig, storage *stora if err != nil { logger.Warn("Could not find working OAuth metadata URL, will rely on auto-discovery", zap.String("server", serverConfig.Name), - zap.String("url_tried", urlToUse), - zap.Error(err)) + zap.String("url_tried", logSafeURL(urlToUse)), + logSafeErrorField(err)) } else { authServerMetadataURL = workingURL logger.Info("Using validated OAuth metadata URL", @@ -1418,7 +1418,7 @@ func (m *CallbackServerManager) StartCallbackServerOnHost(serverName string, bin callbackServer.logger.Info("đŸ“Ĩ HTTP request received on callback server", zap.String("method", r.Method), zap.String("path", r.URL.Path), - zap.String("query", r.URL.RawQuery), + zap.String("query", LogSafeCallbackQuery(r.URL.RawQuery)), zap.String("user_agent", r.UserAgent()), zap.String("remote_addr", r.RemoteAddr)) @@ -1482,7 +1482,7 @@ func (c *CallbackServer) RegisterState(state string) <-chan map[string]string { ch := make(chan map[string]string, 1) c.waiters[state] = ch - c.logger.Debug("Registered OAuth callback waiter", zap.String("state", state)) + c.logger.Debug("Registered OAuth callback waiter", zap.String("state", StateFingerprint(state))) return ch } @@ -1494,7 +1494,7 @@ func (c *CallbackServer) UnregisterState(state string) { if _, exists := c.waiters[state]; exists { delete(c.waiters, state) - c.logger.Debug("Unregistered OAuth callback waiter", zap.String("state", state)) + c.logger.Debug("Unregistered OAuth callback waiter", zap.String("state", StateFingerprint(state))) } } @@ -1530,7 +1530,7 @@ func (c *CallbackServer) deliver(state string, params map[string]string) bool { if !exists { c.logger.Warn("OAuth callback carries a state no flow is waiting for", - zap.String("state", state), + zap.String("state", StateFingerprint(state)), zap.Int("other_waiters", waiterCount)) return false } @@ -1541,7 +1541,7 @@ func (c *CallbackServer) deliver(state string, params map[string]string) bool { default: // Cannot happen: the channel is buffered and single-use. c.logger.Error("OAuth callback waiter channel unexpectedly full", - zap.String("state", state)) + zap.String("state", StateFingerprint(state))) return false } } @@ -1586,7 +1586,7 @@ 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("query", r.URL.RawQuery), + zap.String("query", LogSafeCallbackQuery(r.URL.RawQuery)), zap.String("remote_addr", r.RemoteAddr), zap.String("user_agent", r.UserAgent())) @@ -1599,11 +1599,18 @@ func (c *CallbackServer) handleCallback(w http.ResponseWriter, r *http.Request) } // Log specific OAuth parameters + // Issue #1158 (review round 2, finding B1): the authorization CODE is a + // single-use credential exchangeable for an access token — it is masked + // whole, since no part of it is diagnostic — and `state` is reduced to the + // fingerprint the surrounding lines actually correlate on. `code_present` + // keeps the one thing an operator debugging a callback needs from the code: + // whether the provider sent one at all. c.logger.Info("🔍 OAuth callback parameters extracted", - zap.String("code", params["code"]), - zap.String("state", params["state"]), - zap.String("error", params["error"]), - zap.String("error_description", params["error_description"]), + zap.Bool("code_present", params["code"] != ""), + zap.String("code", callbackParamField("code", params["code"])), + zap.String("state", StateFingerprint(params["state"])), + zap.String("error", ScrubUpstreamText(params["error"])), + zap.String("error_description", ScrubUpstreamText(params["error_description"])), zap.Int("total_params", len(params))) state := params["state"] @@ -1612,14 +1619,14 @@ func (c *CallbackServer) handleCallback(w http.ResponseWriter, r *http.Request) // waiting for is NOT delivered to some other flow and NOT reported to the // user as a success (issue #975). if !c.deliver(state, params) { - reason := fmt.Errorf("OAuth callback for server %q could not be delivered: state %q is unknown or expired "+ - "(the sign-in may have timed out, or it was started by a different mcpproxy session)", c.ServerName, state) + reason := fmt.Errorf("OAuth callback for server %q could not be delivered: state %s is unknown or expired "+ + "(the sign-in may have timed out, or it was started by a different mcpproxy session)", c.ServerName, StateFingerprint(state)) if state == "" { reason = fmt.Errorf("OAuth callback for server %q carried no state parameter and was rejected", c.ServerName) } c.logger.Error("❌ OAuth callback dropped - no flow is waiting for this state", - zap.String("state", state), - zap.String("error", params["error"])) + zap.String("state", StateFingerprint(state)), + zap.String("error", ScrubUpstreamText(params["error"]))) // Surface it to the operator instead of burying it in the log (issue #975). GetTokenStoreManager().RecordOAuthFailure(c.ServerName, reason) @@ -1632,7 +1639,7 @@ func (c *CallbackServer) handleCallback(w http.ResponseWriter, r *http.Request) } c.logger.Info("✅ OAuth callback parameters delivered to the waiting flow", - zap.String("state", state)) + zap.String("state", StateFingerprint(state))) // The provider itself reported a failure: the flow was told, but the user // must not see a success page. diff --git a/internal/oauth/discovery.go b/internal/oauth/discovery.go index 16d00ef41..3f2b90a10 100644 --- a/internal/oauth/discovery.go +++ b/internal/oauth/discovery.go @@ -112,7 +112,7 @@ func FindWorkingMetadataURL(serverURL string, timeout time.Duration) (string, er lastErr = err logger.Debug("Metadata URL validation failed", zap.String("metadata_url", logSafeURL(metadataURL)), - zap.Error(err)) + logSafeErrorField(err)) continue } @@ -131,7 +131,13 @@ func FindWorkingMetadataURL(serverURL string, timeout time.Duration) (string, er return metadataURL, nil } - return "", fmt.Errorf("no working metadata URL found for %s: %w", serverURL, lastErr) + // Issue #1158 (review round 2, finding B2): this error is logged and + // returned to REST callers, and `serverURL` is the CONFIGURED upstream URL + // — the one that routinely carries `?token=`. The wrapped `lastErr` is left + // wrapped so errors.Is/As still work; its own quoted URL is scrubbed at the + // log sinks by logSafeErrorField and at the REST boundary by + // createMetadataError. + return "", fmt.Errorf("no working metadata URL found for %s: %w", logSafeURL(serverURL), lastErr) } // discoverAuthServerMetadataWithFallback attempts to discover OAuth Authorization Server Metadata @@ -151,7 +157,7 @@ func discoverAuthServerMetadataWithFallback(authServerURL string, timeout time.D for _, metadataURL := range urls { urlsChecked = append(urlsChecked, metadataURL) logger.Debug("Trying OAuth metadata URL", - zap.String("auth_server", authServerURL), + zap.String("auth_server", logSafeURL(authServerURL)), zap.String("metadata_url", logSafeURL(metadataURL))) metadata, err := fetchAuthorizationServerMetadata(metadataURL, timeout) @@ -162,12 +168,12 @@ func discoverAuthServerMetadataWithFallback(authServerURL string, timeout time.D metadata.AuthorizationEndpoint, metadata.TokenEndpoint) logger.Debug("OAuth metadata incomplete, trying next URL", zap.String("metadata_url", logSafeURL(metadataURL)), - zap.Error(lastErr)) + logSafeErrorField(lastErr)) continue } logger.Info("✅ OAuth metadata discovered", - zap.String("auth_server", authServerURL), + zap.String("auth_server", logSafeURL(authServerURL)), zap.String("metadata_url", logSafeURL(metadataURL)), zap.String("issuer", metadata.Issuer), zap.String("authorization_endpoint", logSafeURL(metadata.AuthorizationEndpoint)), @@ -178,7 +184,7 @@ func discoverAuthServerMetadataWithFallback(authServerURL string, timeout time.D lastErr = err logger.Debug("OAuth metadata fetch failed, trying next URL", zap.String("metadata_url", logSafeURL(metadataURL)), - zap.Error(err)) + logSafeErrorField(err)) } return nil, "", fmt.Errorf("failed to discover OAuth metadata from %v: %w", urlsChecked, lastErr) @@ -200,7 +206,7 @@ func DiscoverAuthServerURL(serverURL string, timeout time.Duration) string { if err != nil { logger.Debug("Preflight request failed for auth server discovery", zap.String("server_url", logSafeURL(serverURL)), - zap.Error(err)) + logSafeErrorField(err)) return "" } defer resp.Body.Close() @@ -238,7 +244,7 @@ func DiscoverAuthServerURL(serverURL string, timeout time.Duration) string { if err != nil { logger.Debug("Failed to fetch Protected Resource Metadata", zap.String("metadata_url", logSafeURL(metadataURL)), - zap.Error(err)) + logSafeErrorField(err)) return "" } @@ -247,7 +253,7 @@ func DiscoverAuthServerURL(serverURL string, timeout time.Duration) string { authServer := metadata.AuthorizationServers[0] logger.Info("Discovered OAuth authorization server from PRM", zap.String("server_url", logSafeURL(serverURL)), - zap.String("auth_server", authServer)) + zap.String("auth_server", logSafeURL(authServer))) return authServer } @@ -306,7 +312,7 @@ func DiscoverProtectedResourceMetadata(metadataURL string, timeout time.Duration if err != nil { logger.Debug("❌ HTTP Request failed", zap.String("url", logSafeURL(metadataURL)), - zap.Error(err), + logSafeErrorField(err), zap.Duration("elapsed", elapsed)) return nil, fmt.Errorf("failed to fetch metadata: %w", err) } @@ -326,7 +332,7 @@ func DiscoverProtectedResourceMetadata(metadataURL string, timeout time.Duration if err := json.NewDecoder(resp.Body).Decode(&metadata); err != nil { logger.Debug("❌ Failed to parse JSON response", zap.String("url", logSafeURL(metadataURL)), - zap.Error(err)) + logSafeErrorField(err)) return nil, fmt.Errorf("failed to parse metadata: %w", err) } @@ -336,7 +342,7 @@ func DiscoverProtectedResourceMetadata(metadataURL string, timeout time.Duration zap.String("resource", logSafeURL(metadata.Resource)), zap.String("resource_name", metadata.ResourceName), zap.Strings("scopes_supported", metadata.ScopesSupported), - zap.Strings("authorization_servers", metadata.AuthorizationServers), + zap.Strings("authorization_servers", logSafeURLs(metadata.AuthorizationServers)), zap.Strings("bearer_methods_supported", metadata.BearerMethodsSupported)) // Log resource discovery for RFC 8707 auto-detection @@ -344,7 +350,7 @@ func DiscoverProtectedResourceMetadata(metadataURL string, timeout time.Duration logger.Info("Protected Resource Metadata discovered", zap.String("resource", logSafeURL(metadata.Resource)), zap.Strings("scopes", metadata.ScopesSupported), - zap.Strings("auth_servers", metadata.AuthorizationServers)) + zap.Strings("auth_servers", logSafeURLs(metadata.AuthorizationServers))) } return &metadata, nil @@ -396,7 +402,7 @@ func DiscoverScopesFromAuthorizationServer(baseURL string, timeout time.Duration if err != nil { logger.Debug("❌ HTTP Request failed", zap.String("url", logSafeURL(metadataURL)), - zap.Error(err), + logSafeErrorField(err), zap.Duration("elapsed", elapsed)) return nil, fmt.Errorf("failed to fetch metadata: %w", err) } @@ -416,7 +422,7 @@ func DiscoverScopesFromAuthorizationServer(baseURL string, timeout time.Duration if err := json.NewDecoder(resp.Body).Decode(&metadata); err != nil { logger.Debug("❌ Failed to parse JSON response", zap.String("url", logSafeURL(metadataURL)), - zap.Error(err)) + logSafeErrorField(err)) return nil, fmt.Errorf("failed to parse metadata: %w", err) } @@ -474,7 +480,7 @@ func DetectOAuthAvailability(baseURL string, timeout time.Duration) bool { if err != nil { logger.Debug("OAuth detection failed - endpoint unreachable", zap.String("url", logSafeURL(metadataURL)), - zap.Error(err)) + logSafeErrorField(err)) return false } defer resp.Body.Close() @@ -490,7 +496,7 @@ func DetectOAuthAvailability(baseURL string, timeout time.Duration) bool { if err := json.NewDecoder(resp.Body).Decode(&metadata); err != nil { logger.Debug("OAuth detection failed - invalid JSON", zap.String("url", logSafeURL(metadataURL)), - zap.Error(err)) + logSafeErrorField(err)) return false } @@ -551,7 +557,7 @@ func ValidateOAuthMetadata(serverURL, serverName string, timeout time.Duration) if err != nil { logger.Debug("Preflight request failed", zap.String("server", serverName), - zap.Error(err)) + logSafeErrorField(err)) // This is a connection error, not a metadata error - return nil to let OAuth flow proceed // The actual OAuth flow will handle connection errors appropriately return nil, nil @@ -606,7 +612,7 @@ func ValidateOAuthMetadata(serverURL, serverName string, timeout time.Duration) logger.Debug("Failed to fetch protected resource metadata", zap.String("server", serverName), zap.String("metadata_url", logSafeURL(metadataURL)), - zap.Error(err)) + logSafeErrorField(err)) // Don't return error yet - try to get auth server metadata for better error info } else { result.ProtectedResourceMetadata = protectedMetadata @@ -643,9 +649,9 @@ func ValidateOAuthMetadata(serverURL, serverName string, timeout time.Duration) } logger.Debug("Failed to fetch authorization server metadata", zap.String("server", serverName), - zap.String("auth_server_base", authServerBaseURL), + zap.String("auth_server_base", logSafeURL(authServerBaseURL)), zap.Strings("urls_tried", logSafeURLs(urls)), - zap.Error(err)) + logSafeErrorField(err)) return result, createMetadataError(serverName, serverURL, result) } @@ -691,7 +697,7 @@ func fetchAuthorizationServerMetadata(metadataURL string, timeout time.Duration) if err := json.NewDecoder(resp.Body).Decode(&metadata); err != nil { logger.Debug("Failed to parse authorization server metadata", zap.String("url", logSafeURL(metadataURL)), - zap.Error(err)) + logSafeErrorField(err)) return nil, fmt.Errorf("failed to parse metadata: %w", err) } @@ -760,7 +766,12 @@ func createMetadataError(serverName, serverURL string, result *OAuthMetadataVali details.ProtectedResourceMetadata.Error = ScrubUpstreamText(result.ProtectedResourceError.Error()) } if result.ProtectedResourceMetadata != nil { - details.ProtectedResourceMetadata.AuthorizationServers = result.ProtectedResourceMetadata.AuthorizationServers + // The PRM's own authorization_servers list is upstream-authored and + // leaves this struct over REST alongside every sibling URL leaf, + // each of which is scrubbed. Review round 2 flagged the + // inconsistency; scheme/host/path survive, so the panel still says + // WHICH authorization server was advertised. + details.ProtectedResourceMetadata.AuthorizationServers = logSafeURLs(result.ProtectedResourceMetadata.AuthorizationServers) } } diff --git a/internal/oauth/discovery_redact_round2_test.go b/internal/oauth/discovery_redact_round2_test.go new file mode 100644 index 000000000..b6d0e634c --- /dev/null +++ b/internal/oauth/discovery_redact_round2_test.go @@ -0,0 +1,101 @@ +package oauth + +import ( + "errors" + "fmt" + "net/http" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +const opaqueCredURL = "https://host.example/mcp?opaque=ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789" + +// Issue #1158, review round 2, finding B2. +// +// FindWorkingMetadataURL wraps the configured server URL into its failure +// message verbatim. That error is logged and handed to REST callers, and the +// configured URL is precisely the string this issue exists for. +func TestFindWorkingMetadataURL_ErrorCarriesNoCredential(t *testing.T) { + _, err := FindWorkingMetadataURL(opaqueCredURL, 50*time.Millisecond) + require.Error(t, err) + assert.NotContains(t, err.Error(), "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789", + "the configured URL is spliced into this message on every discovery failure") + assert.Contains(t, err.Error(), "host.example", + "the host is what makes the message diagnosable and must survive") +} + +// Issue #1158, review round 2, finding B3. +// +// A *url.Error renders the request URL inside its own text, so an HTTP failure +// path publishes the credential through zap.Error even when the sibling `url` +// field is masked. logSafeErrorField is the answer; assert it on a REAL +// *url.Error rather than a hand-written string. +func TestLogSafeErrorField_ScrubsAUrlErrorFromARealRequest(t *testing.T) { + client := &http.Client{Timeout: 30 * time.Millisecond} + //nolint:noctx // the point is the *url.Error this produces + _, err := client.Get("http://127.0.0.1:1/mcp?opaque=ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789") + require.Error(t, err) + require.Contains(t, err.Error(), "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789", + "sanity: net/http really does quote the request URL in its error") + + field := logSafeErrorField(err) + assert.NotContains(t, field.String, "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789") + assert.Contains(t, field.String, "127.0.0.1", + "the host and the failure reason are the diagnostic") + + assert.Equal(t, "", LogSafeErrorText(nil)) + assert.NotContains(t, LogSafeErrorText(fmt.Errorf("wrapped: %w", err)), + "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789") + assert.NotContains(t, logSafeNamedErrorField("dcr_error", errors.New(opaqueCredURL)).String, + "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789") +} + +// Issue #1158, review round 2, third investigation item: the PRM's own +// authorization_servers list left createMetadataError unscrubbed while every +// sibling URL leaf on the same struct was scrubbed. +func TestCreateMetadataError_ScrubsThePRMAuthorizationServers(t *testing.T) { + err := createMetadataError("alpha", "https://host.example/mcp", &OAuthMetadataValidationResult{ + ProtectedResourceMetadataURL: "https://host.example/.well-known/oauth-protected-resource", + ProtectedResourceMetadata: &ProtectedResourceMetadata{ + AuthorizationServers: []string{opaqueCredURL}, + }, + }) + require.Error(t, err) + + metaErr, ok := err.(*OAuthMetadataError) + require.True(t, ok) + require.NotNil(t, metaErr.Details.ProtectedResourceMetadata) + servers := metaErr.Details.ProtectedResourceMetadata.AuthorizationServers + require.Len(t, servers, 1) + + assert.NotContains(t, servers[0], "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789", + "this list is JSON-encoded to the REST caller alongside leaves that ARE scrubbed") + assert.Contains(t, servers[0], "host.example", + "the panel exists to say WHICH authorization server was advertised") +} + +// Issue #1158, review round 2, finding B6: the exported renderer every package +// now shares must be the DEEP one. RedactURLQueryParams — the rule the other +// packages used — is name-rule only, so a credential under an unrecognised +// parameter name walked straight through it. +func TestLogSafeURL_IsDeeperThanTheNameRule(t *testing.T) { + assert.Contains(t, RedactURLQueryParams(opaqueCredURL), "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789", + "sanity: the name rule is what missed it; if this stops holding the contrast means nothing") + + got := LogSafeURL(opaqueCredURL) + assert.NotContains(t, got, "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789") + assert.Contains(t, got, "host.example/mcp", "scheme, host and path survive") + + // And it still decodes one level of nesting, which is where the authorize + // URL hides the configured upstream URL. + nested := "https://auth.example/authorize?client_id=x&resource=" + + "https%3A%2F%2Fhost.example%2Fmcp%3Ftoken%3Dsk-live-11aa22bb33cc" + assert.NotContains(t, LogSafeURL(nested), "sk-live-11aa22bb33cc") + + // Idempotent: the structured-error scrubber applies it to values that were + // already rendered safely. + assert.Equal(t, got, LogSafeURL(got)) +} diff --git a/internal/oauth/logging.go b/internal/oauth/logging.go index e81bb6be6..13e2fca72 100644 --- a/internal/oauth/logging.go +++ b/internal/oauth/logging.go @@ -3,9 +3,12 @@ package oauth import ( + "crypto/sha256" + "encoding/hex" "net/http" "net/url" "regexp" + "sort" "strconv" "strings" "time" @@ -966,6 +969,21 @@ func LogOAuthFlowEnd(logger *zap.Logger, serverName string, correlationID string // url.URL.Redacted() is deliberately NOT used anywhere: it masks the userinfo // password only and leaves `?token=` intact. func logSafeURL(rawURL string) string { + return LogSafeURL(rawURL) +} + +// LogSafeURL is logSafeURL for callers OUTSIDE this package (issue #1158, +// review round 2 finding B6). +// +// internal/upstream/core.Client.logSafeURL, managed.Client.logSafeURL, +// transport.HTTPTransportConfig.logSafeURL, the CLI client and the registry +// routes each rendered their URL log fields with RedactURLQueryParams — the +// NAME rule only. This package's own new renderer deliberately does not, and +// says why in so many words: a credential under an unrecognised or opaque +// parameter name (`?opaque=ghp_â€Ļ`, `?resource=`) +// is invisible to the name rule and still reached the log. Two renderers for +// the same class of field is how the gap re-opens, so there is one. +func LogSafeURL(rawURL string) string { return AuditRedaction.URLValueDeep(rawURL) } @@ -982,3 +1000,128 @@ func logSafeURLs(urls []string) []string { } return out } + +// logSafeErrorField renders an error as a LOG FIELD with any credential its +// text carries removed (issue #1158, review round 2 finding B3). +// +// Masking the `url` FIELD of a log statement is only half the job on an HTTP +// failure path: net/http quotes the request URL inside the error it returns, so +// `client.Post("https://host/mcp?token=SECRET", â€Ļ)` renders as +// +// Post "https://host/mcp?token=SECRET": dial tcp 10.0.0.1:443: i/o timeout +// +// and the credential the sibling `zap.String("metadata_url", logSafeURL(â€Ļ))` +// masks reaches the identical log line through `zap.Error(err)`. internal/ +// transport has scrubbed its error fields since #1148 round 3; internal/oauth — +// which makes most of the outbound discovery requests — did not. +// +// ScrubUpstreamText rather than RedactSensitiveData: an error string has no +// enclosing key to judge it by, so the value-shaped detector has to run as well +// (`?opaque=ghp_â€Ļ` is invisible to the name rule). The field NAME stays "error" +// so existing log queries keep working. +func logSafeErrorField(err error) zap.Field { + if err == nil { + return zap.Skip() + } + return zap.String("error", ScrubUpstreamText(err.Error())) +} + +// logSafeNamedErrorField is logSafeErrorField under a caller-chosen field name, +// for the sites that log two errors on one statement. +func logSafeNamedErrorField(name string, err error) zap.Field { + if err == nil { + return zap.Skip() + } + return zap.String(name, ScrubUpstreamText(err.Error())) +} + +// LogSafeErrorText renders an error's text for a log field or a structured +// error leaf, with any credential it quotes removed. Exported for +// internal/upstream/core, which builds the same OAuth failure payloads. +func LogSafeErrorText(err error) string { + if err == nil { + return "" + } + return ScrubUpstreamText(err.Error()) +} + +// StateFingerprint renders an OAuth `state` for a LOG FIELD or an error message +// (issue #1158, review round 2 finding B1). +// +// `state` is the CSRF nonce that binds a callback to the flow that minted it. +// It is not an access credential on its own, but it is the other half of the +// pair an attacker who has read the log needs: with the authorization code AND +// the state, a callback can be replayed against the waiting flow. It was +// written verbatim on five log statements and inside two error messages. +// +// The fingerprint keeps what the log lines actually use it for — correlating +// "Registered waiter" with "callback received" with "dropped, nobody waiting" +// across one flow — while carrying no bytes of the nonce itself. A truncated +// SHA-256 is enough: the values it distinguishes are the handful of flows live +// in one process. +func StateFingerprint(state string) string { + if state == "" { + return "(none)" + } + sum := sha256.Sum256([]byte(state)) + return "sha256:" + hex.EncodeToString(sum[:])[:12] +} + +// callbackParamField renders ONE OAuth callback query parameter for a log +// field, by name. +// +// The authorization `code` is a single-use credential exchangeable for an +// access token at the token endpoint, and it was logged at INFO on every +// successful login — so `~/.mcpproxy/logs/main.log` held a working credential +// for the window before mcpproxy redeemed it, and forever after for any flow +// that failed to complete. It is masked whole: unlike a URL, no part of it is +// diagnostic. +func callbackParamField(name, value string) string { + switch strings.ToLower(name) { + case "state": + return StateFingerprint(value) + case "code", "access_token", "id_token", "refresh_token", "token", "client_secret": + if value == "" { + return "" + } + return AuditMaskValue(value) + case "error", "error_description", "error_uri": + // Provider-authored free text: it has no enclosing key to judge it by + // and providers do echo request parameters back into it. + return ScrubUpstreamText(value) + default: + return AuditRedaction.Leaf(name, value) + } +} + +// LogSafeCallbackQuery renders a whole OAuth callback query string for a log +// field, parameter by parameter. +// +// The raw `r.URL.RawQuery` of the callback request was logged at INFO on TWO +// handlers, which put the authorization code on disk a second and third time +// even after the dedicated `code` field was masked. Rendering per parameter +// rather than dropping the field keeps the diagnostic the line exists for: +// WHICH parameters the provider sent back. +func LogSafeCallbackQuery(rawQuery string) string { + if rawQuery == "" { + return rawQuery + } + values, err := url.ParseQuery(rawQuery) + if err != nil { + // Unparseable: fall back to the free-form rule rather than publishing + // it, and say so. + return ScrubUpstreamText(rawQuery) + } + names := make([]string, 0, len(values)) + for name := range values { + names = append(names, name) + } + sort.Strings(names) + parts := make([]string, 0, len(names)) + for _, name := range names { + for _, v := range values[name] { + parts = append(parts, name+"="+callbackParamField(name, v)) + } + } + return strings.Join(parts, "&") +} diff --git a/internal/oauth/redactview.go b/internal/oauth/redactview.go index d876de40d..36f549886 100644 --- a/internal/oauth/redactview.go +++ b/internal/oauth/redactview.go @@ -273,19 +273,31 @@ func maskDetectedInURLQuery(rawQuery string) string { // Everything else round-trips verbatim: package names, subcommands, paths and // ports are what make the payload useful. func (r Redaction) Argv(argv []string) []string { - return r.argvWith(argv, nil) -} - -// argvWith is Argv with an optional rule for elements that carry embedded -// whitespace - a whole command LINE squeezed into one argv element, which the -// login-shell wrap produces (`["-l","-c","npx some-mcp --api-key ..."]`) and -// which the per-token rules below cannot see into. Passing nil reproduces -// Argv's behaviour byte for byte; only the log-only SpawnArgv rule supplies a -// hook, so the read/write mask-echo contract Argv backs is untouched. -func (r Redaction) argvWith(argv []string, commandStringRule func(string) string) []string { + return r.argvWith(argv, false, nil) +} + +// argvWith is Argv with two optional log-only relaxations, both off for +// `spawnRules == false` (which reproduces Argv's behaviour byte for byte, so +// the read/write mask-echo contract Argv backs is untouched): +// +// - commandStringRule handles elements that carry embedded whitespace — a +// whole command LINE squeezed into one argv element, which the login-shell +// wrap produces (`["-l","-c","npx some-mcp --api-key ..."]`) and which the +// per-token rules below cannot see into. +// - spawnRules swaps IsSensitiveKeyName's substring match for +// isSensitiveSpawnFlag's qualifier-aware one, so `--max-tokens 4096` and +// `--public-key-path /etc/x` keep the values an operator reads the spawn +// log for. See benignFlagQualifiers. +func (r Redaction) argvWith(argv []string, spawnRules bool, commandStringRule func(string) string) []string { if argv == nil { return nil } + leaf := r.Leaf + flagNamesSecret := func(flag string) bool { return IsSensitiveKeyName(ArgvFlagKey(flag)) } + if spawnRules { + leaf = r.spawnLeaf + flagNamesSecret = isSensitiveSpawnFlag + } out := make([]string, len(argv)) maskNext := false for i, s := range argv { @@ -299,7 +311,7 @@ func (r Redaction) argvWith(argv []string, commandStringRule func(string) string continue } if flag, value, inline := strings.Cut(s, "="); inline && IsArgvFlag(flag) { - out[i] = flag + "=" + r.Leaf(ArgvFlagKey(flag), value) + out[i] = flag + "=" + leaf(ArgvFlagKey(flag), value) continue } // An unpaired token — a positional argument, a flag name, or the value @@ -307,8 +319,8 @@ func (r Redaction) argvWith(argv []string, commandStringRule func(string) string // enclosing key is what keeps the inline and space-separated spellings // in step: it is the same function the inline branch delegates to, so // the URL rule, the env-name rule and the detector all apply to both. - out[i] = r.Leaf("", s) - maskNext = IsArgvFlag(s) && IsSensitiveKeyName(ArgvFlagKey(s)) + out[i] = leaf("", s) + maskNext = IsArgvFlag(s) && flagNamesSecret(s) } return out } diff --git a/internal/oauth/spawnargv.go b/internal/oauth/spawnargv.go index 91db7c566..deff36c25 100644 --- a/internal/oauth/spawnargv.go +++ b/internal/oauth/spawnargv.go @@ -33,16 +33,30 @@ import ( // separate, log-only rule. // // There is deliberately NO "already masked, skip" guard between the two stages. -// The audit rendering is a run of U+2022 bullets, which contains no character in -// secretPattern's value class `[a-zA-Z0-9\-_\.]`, so stage 2 provably leaves a -// stage-1 rendering byte-identical — the guard would buy nothing. It would also -// LEAK: shellwrap routes any whitespace-bearing element (the `-c ""` produced by wrapWithUserShell on every macOS stdio server, and -// by the docker login-shell fallback) through the command-string rule, so a -// single benign `-e UV_CACHE_DIR=/tmp/c` would put a mask marker in the element -// and a whole-token guard would then skip stage 2 for the rest of that command -// line, publishing a second credential in the clear. That is the exact failure +// The reason is that such a guard would LEAK, not that it would be redundant: +// shellwrap routes any whitespace-bearing element (the `-c ""` produced by wrapWithUserShell on every macOS stdio server, and by the +// docker login-shell fallback) through the command-string rule, so a single +// benign `-e UV_CACHE_DIR=/tmp/c` would put a mask marker in the element and a +// whole-token guard would then skip stage 2 for the rest of that command line, +// publishing a second credential in the clear. That is the exact failure // `finish` / `maskDetectedPreservingURL` already document one level down. +// +// An earlier version of this comment also claimed the composition is a no-op — +// that the audit rendering, a run of U+2022 bullets, carries no character in +// secretPattern's value class `[a-zA-Z0-9\-_\.]`, so stage 2 provably leaves a +// stage-1 rendering byte-identical. That is FALSE, and review round 2 was right +// that the pinning test used the one fixture that hides it. secretPattern is +// not the only rule in RedactSensitiveData: the sensitiveParams sweep that +// follows it matches `(?i)(=)[^&\s]+`, and `[^&\s]` matches a bullet. +// So `API_KEY=â€ĸâ€ĸâ€ĸâ€ĸ` survives stage 2 (`key` is not a sensitiveParam) while +// `SLACK_TOKEN=â€ĸâ€ĸâ€ĸâ€ĸ` is rewritten to `SLACK_TOKEN=***REDACTED***` (`token` is). +// +// The composition is therefore not byte-idempotent — it is DISCLOSURE-safe, +// which is the property that matters: what stage 2 rewrites is already a mask, +// both renderings are in MaskMarkers so the write-path net recognises either, +// and no byte of the secret is involved. Both spellings are pinned by +// TestSpawnArgv_CompositionIsDisclosureSafeOnBothEnvSpellings. // SpawnArgv masks a child process's argument vector for a LOG sink. // @@ -67,7 +81,7 @@ func (r Redaction) SpawnArgv(argv []string) []string { // bytes past the marker). staged := shellwrap.RedactDockerArgsWith(argv, r.masker()) // Stage 2: the semantic flag-name + value-shape rule. - return r.argvWith(staged, r.spawnCommandTokens) + return r.argvWith(staged, true, r.spawnCommandTokens) } // SpawnCommandString masks a whole child command LINE for a LOG sink — the @@ -94,7 +108,7 @@ func (r Redaction) spawnCommandTokens(s string) string { if len(tokens) == 0 { return s } - masked := r.argvWith(tokens, nil) + masked := r.argvWith(tokens, true, nil) var b strings.Builder b.Grow(len(s)) @@ -115,15 +129,98 @@ type commandSegment struct { isToken bool } +func isCommandSpace(b byte) bool { return b == ' ' || b == '\t' || b == '\n' || b == '\r' } + // splitCommandSegments splits a command string into alternating whitespace and -// non-whitespace runs so the masked tokens can be spliced back with the -// original spacing intact. +// TOKEN runs so the masked tokens can be spliced back with the original spacing +// intact. +// +// The split is SHELL-AWARE, and it has to be (issue #1158, review round 2 +// finding B4). The command string this rule exists for is produced by +// shellwrap.WrapWithUserShell, which runs every element through Shellescape — +// so an argument carrying whitespace arrives single-quoted: +// +// npx some-mcp --api-key 'sk live secret' +// +// A whitespace-only split makes that FOUR tokens, the flag-name rule masks only +// the first fragment (`'sk`), and `live secret'` is published in the clear on +// the exact form the fix claims to close. Tracking quote state keeps the whole +// quoted run as one token, so the mask covers all of it. +// +// Shellescape also emits the `'"'"'` idiom for an embedded single quote; the +// state machine below handles it for free (close-single, open-double, literal +// quote, close-double, open-single). +// +// UNBALANCED quotes fall back to the whitespace-only split. An apostrophe in a +// path (`/Users/o'brien/x`) would otherwise swallow the rest of the line into +// one token, and a swallowed `--api-key SECRET` is exactly the leak this +// function exists to prevent — degrading to the old behaviour is strictly +// safer than degrading to one giant token. func splitCommandSegments(s string) []commandSegment { - isSpace := func(b byte) bool { return b == ' ' || b == '\t' || b == '\n' || b == '\r' } + segs, ok := splitCommandSegmentsQuoted(s) + if !ok { + return splitCommandSegmentsOnSpace(s) + } + return segs +} + +// splitCommandSegmentsQuoted is the quote-aware split. It reports false when a +// quote is never closed, in which case the caller falls back. +func splitCommandSegmentsQuoted(s string) (segs []commandSegment, balanced bool) { + segs = make([]commandSegment, 0, 8) + i := 0 + for i < len(s) { + j := i + for j < len(s) && isCommandSpace(s[j]) { + j++ + } + if j > i { + segs = append(segs, commandSegment{text: s[i:j]}) + i = j + } + if i >= len(s) { + break + } + j = i + var quote byte // 0 when outside quotes, else the opening quote char + for j < len(s) { + c := s[j] + if quote != 0 { + if c == quote { + quote = 0 + } + j++ + continue + } + if c == '\'' || c == '"' { + quote = c + j++ + continue + } + if isCommandSpace(c) { + break + } + j++ + } + if quote != 0 { + // Ran off the end inside a quote. + return nil, false + } + if j > i { + segs = append(segs, commandSegment{text: s[i:j], isToken: true}) + } + i = j + } + return segs, true +} + +// splitCommandSegmentsOnSpace is the original whitespace-only split, kept as +// the fallback for command strings whose quoting does not balance. +func splitCommandSegmentsOnSpace(s string) []commandSegment { segs := make([]commandSegment, 0, 8) for i := 0; i < len(s); { j := i - for j < len(s) && isSpace(s[j]) { + for j < len(s) && isCommandSpace(s[j]) { j++ } if j > i { @@ -131,7 +228,7 @@ func splitCommandSegments(s string) []commandSegment { i = j } j = i - for j < len(s) && !isSpace(s[j]) { + for j < len(s) && !isCommandSpace(s[j]) { j++ } if j > i { @@ -213,3 +310,82 @@ func (r Redaction) ExtraParamValue(key, value string) string { } return r.Leaf(key, value) } + +// benignFlagQualifiers are flag-name SEGMENTS that make a marker word +// non-secret (issue #1158, review round 2 finding B5). +// +// IsSensitiveKeyName matches its markers as SUBSTRINGS — that is the right +// rule for an env-var name, where over-masking a value costs nothing anyone +// reads. Applying it to a spawn argv on the LOG path is different: the flag's +// VALUE is often the diagnostic the operator opened the log for, and the +// substring rule blanks it for +// +// --max-tokens 4096 (TOKENS contains TOKEN) +// --public-key-path /etc/x (KEY) +// --num-tokens, --token-limit, --output-tokens, --public-key +// +// none of which is a credential. That is not a safe trade dressed up as a +// cautious one: an operator who cannot read the log stops using it, and the +// property that makes this redaction acceptable at all is that flag names, +// hosts and ordinary values survive. +// +// The rule is therefore: de-dash the flag, split it on `-`, `_` and `.`, and if +// any segment is one of these qualifiers, the flag does not name a secret. +// +// A plain segment-EQUALITY rule (segment == marker) was rejected: it silently +// un-masks `--apikey`, `--authtoken` and `--clientsecret`, the glued spellings +// that are at least as common as the hyphenated ones. Keeping the substring +// match and subtracting a short, explicit list of qualifiers loses no coverage. +var benignFlagQualifiers = map[string]bool{ + "max": true, + "min": true, + "num": true, + "count": true, + "total": true, + "limit": true, + "budget": true, + "input": true, + "output": true, + "public": true, + "window": true, + "size": true, +} + +// isSensitiveSpawnFlag reports whether the token FOLLOWING this flag should be +// masked on a LOG sink. See benignFlagQualifiers. +// +// It is deliberately not used by Redaction.Argv: that function backs the READ +// doors and CheckArgvMaskEcho on the WRITE doors, where relaxing what counts as +// sensitive would newly publish a value on `GET /api/v1/servers`. The +// relaxation is log-only, in the same way the whole spawn rule is. +func isSensitiveSpawnFlag(flag string) bool { + key := ArgvFlagKey(flag) + if key == "" { + return false + } + if !IsSensitiveKeyName(key) { + return false + } + for _, seg := range strings.FieldsFunc(key, func(r rune) bool { + return r == '-' || r == '_' || r == '.' + }) { + if benignFlagQualifiers[strings.ToLower(seg)] { + return false + } + } + return true +} + +// spawnLeaf is Leaf with the log-only flag relaxation applied to the NAME rule. +// Used for the inline `--max-tokens=4096` spelling, so it stays in step with +// the space-separated one — the invariant Redaction.Argv's own doc comment +// insists on. +func (r Redaction) spawnLeaf(flagKey, value string) string { + if flagKey != "" && IsSensitiveKeyName(flagKey) && !isSensitiveSpawnFlag(flagKey) { + // The name rule would have fired on a marker inside a QUALIFIED flag + // name. Judge the value on its own shape instead — the detector still + // runs, so `--max-tokens ghp_â€Ļ` is still masked. + return r.finish(value, RedactSensitiveData(value)) + } + return r.Leaf(flagKey, value) +} diff --git a/internal/oauth/spawnargv_round2_test.go b/internal/oauth/spawnargv_round2_test.go new file mode 100644 index 000000000..188802921 --- /dev/null +++ b/internal/oauth/spawnargv_round2_test.go @@ -0,0 +1,171 @@ +package oauth + +import ( + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/smart-mcp-proxy/mcpproxy-go/internal/shellwrap" +) + +// Issue #1158, review round 2, finding B4. +// +// The spawn rule's command-STRING tokenizer split on whitespace only, while the +// command string it is fed is produced by shellwrap.WrapWithUserShell — which +// runs every element through Shellescape, so any argument carrying whitespace +// arrives SINGLE-QUOTED. A credential with a space in it therefore became four +// tokens, the flag-name rule masked the first fragment, and the rest was +// published in the clear — on the `-c ""` form the fix's +// own commit message calls "the form that actually leaked". +func TestSpawnArgv_MasksAWhitespaceBearingSecretInTheDashCForm(t *testing.T) { + const secret = "SUPERSECRET PASSPHRASE WITH SPACES" + + // Built the way the product builds it, not by hand: Shellescape decides the + // quoting, so the test cannot drift from the real shape. + commandLine := strings.Join([]string{ + shellwrap.Shellescape("npx"), + shellwrap.Shellescape("some-mcp"), + shellwrap.Shellescape("--api-key"), + shellwrap.Shellescape(secret), + }, " ") + require.Contains(t, commandLine, "'", "sanity: Shellescape must have quoted the spaced value") + + for name, got := range map[string]string{ + "SpawnCommandString": AuditRedaction.SpawnCommandString(commandLine), + "SpawnArgv/-c": strings.Join(AuditRedaction.SpawnArgv([]string{"-l", "-c", commandLine}), " "), + } { + t.Run(name, func(t *testing.T) { + for _, word := range strings.Fields(secret) { + assert.NotContains(t, got, word, + "a whitespace-separated fragment of the credential survived: %q", got) + } + assert.Contains(t, got, "npx some-mcp --api-key", + "the command and the flag NAME are the diagnostic and must survive: %q", got) + }) + } +} + +// The embedded-single-quote idiom Shellescape emits ('"'"') must not confuse +// the tokenizer into ending the quoted run early. +func TestSpawnCommandString_HandlesTheEmbeddedQuoteIdiom(t *testing.T) { + const secret = "pass'word with spaces" + commandLine := "npx some-mcp --api-key " + shellwrap.Shellescape(secret) + require.Contains(t, commandLine, `'"'"'`, "sanity: this is the idiom under test") + + got := AuditRedaction.SpawnCommandString(commandLine) + assert.NotContains(t, got, "word with spaces") + assert.NotContains(t, got, "pass") + assert.Contains(t, got, "--api-key") +} + +// An UNBALANCED quote (an apostrophe in a path) must degrade to the old +// whitespace-only split rather than swallowing the rest of the line into one +// token — a swallowed `--api-key SECRET` would be a new leak. +func TestSpawnCommandString_UnbalancedQuoteStillMasks(t *testing.T) { + const secret = "sk-live-0f2a91cc77d4" + got := AuditRedaction.SpawnCommandString("node /Users/o'brien/app.js --api-key " + secret) + + assert.NotContains(t, got, secret) + assert.Contains(t, got, "--api-key") + assert.Contains(t, got, "/Users/o'brien/app.js") +} + +// Issue #1158, review round 2, finding B5. +// +// IsSensitiveKeyName matches its markers as SUBSTRINGS. Applying it to a spawn +// argv on the LOG path blanked `--max-tokens 4096` (TOKENS contains TOKEN) and +// `--public-key-path /etc/x` (KEY) in main.log and in the per-server log. The +// property that makes this whole redaction acceptable to an operator is that +// flag names, hosts and ordinary values survive; eating the value of every flag +// whose name happens to contain a marker word trades one bug for another. +func TestSpawnArgv_KeepsQualifiedFlagValues(t *testing.T) { + keep := [][]string{ + {"serve", "--max-tokens", "4096"}, + {"serve", "--max-tokens=4096"}, + {"serve", "--public-key-path", "/etc/ssl/pub.pem"}, + {"serve", "--public-key-path=/etc/ssl/pub.pem"}, + {"serve", "--num-tokens", "128"}, + {"serve", "--output-tokens", "512"}, + {"serve", "--token-limit", "8000"}, + } + for _, argv := range keep { + assert.Equal(t, argv, AuditRedaction.SpawnArgv(argv), + "a qualified flag names a budget or a public path, not a credential") + } +} + +// â€Ļand the relaxation must not cost coverage. Both the hyphenated and the +// GLUED spellings still lose their values — a plain segment-equality rule would +// have silently un-masked the glued ones. +func TestSpawnArgv_StillMasksRealCredentialFlags(t *testing.T) { + const secret = "sk-live-99aa11bb22cc33dd" + for _, flag := range []string{ + "--api-key", "--apikey", "--auth-token", "--authtoken", + "--client-secret", "--clientsecret", "--password", "--bearer-token", + } { + spaced := AuditRedaction.SpawnArgv([]string{"serve", flag, secret}) + assert.NotContains(t, strings.Join(spaced, " "), secret, "spaced form of %s leaked", flag) + assert.Contains(t, strings.Join(spaced, " "), flag, "the flag name is the audit signal") + + inline := AuditRedaction.SpawnArgv([]string{"serve", flag + "=" + secret}) + assert.NotContains(t, strings.Join(inline, " "), secret, "inline form of %s leaked", flag) + } +} + +// The value-shaped detector still runs under a qualified flag, so a real +// credential handed to `--max-tokens` is masked on its own shape. +func TestSpawnArgv_QualifiedFlagStillMasksAShapedCredential(t *testing.T) { + const ghToken = "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789" + for _, argv := range [][]string{ + {"serve", "--max-tokens", ghToken}, + {"serve", "--max-tokens=" + ghToken}, + } { + got := strings.Join(AuditRedaction.SpawnArgv(argv), " ") + assert.NotContains(t, got, ghToken, + "relaxing the NAME rule must not turn off the VALUE rule: %v", argv) + } +} + +// The READ/WRITE contract is unchanged: the relaxation is log-only. Redaction. +// Argv backs GET /api/v1/servers and CheckArgvMaskEcho on the write doors, and +// relaxing it there would newly publish a value on a read door. +func TestArgv_KeepsTheStrictNameRule(t *testing.T) { + argv := []string{"serve", "--max-tokens", "4096"} + got := LiveRedaction.Argv(argv) + require.Len(t, got, 3) + assert.NotEqual(t, "4096", got[2], + "Argv must keep the strict substring rule — the spawn relaxation is log-only") +} + +// The design comment used to claim that stage 2 "provably leaves a stage-1 +// rendering byte-identical". It does not, and the original pinning test used +// the one env-key spelling that hides it: `key` is not in sensitiveParams, so +// `API_KEY=â€ĸâ€ĸâ€ĸâ€ĸ` survives stage 2 untouched, while `SLACK_TOKEN=â€ĸâ€ĸâ€ĸâ€ĸ` is +// rewritten by RedactSensitiveData's `(?i)(token=)[^&\s]+` sweep — whose value +// class DOES match the bullet marker — into `SLACK_TOKEN=***REDACTED***`. +// +// That is a rendering change, not a disclosure: what stage 2 re-masks is +// already a mask. This test asserts BOTH spellings so the composition's real +// behaviour is pinned rather than the flattering half of it. +func TestSpawnArgv_CompositionIsDisclosureSafeOnBothEnvSpellings(t *testing.T) { + const secret = "supersecretvalue" + + apiKey := AuditRedaction.SpawnArgv([]string{"-e", "API_KEY=" + secret}) + require.Len(t, apiKey, 2) + assert.Equal(t, "API_KEY="+AuditMaskValue(secret), apiKey[1], + "a key spelling outside sensitiveParams is untouched by stage 2") + + slack := AuditRedaction.SpawnArgv([]string{"-e", "SLACK_TOKEN=" + secret}) + require.Len(t, slack, 2) + assert.Equal(t, "SLACK_TOKEN="+redactedMarker, slack[1], + "a key spelling INSIDE sensitiveParams is re-marked by stage 2 — a mask over a mask") + + for _, got := range [][]string{apiKey, slack} { + joined := strings.Join(got, " ") + assertNoSecretFragment(t, joined, secret, 2) + assert.True(t, ContainsMaskMarker(joined), + "whichever rendering wins, the write-path net must recognise it: %v", got) + } +} diff --git a/internal/oauth/url_log_field_guard_test.go b/internal/oauth/url_log_field_guard_test.go index 49e69b41c..42af110e3 100644 --- a/internal/oauth/url_log_field_guard_test.go +++ b/internal/oauth/url_log_field_guard_test.go @@ -27,7 +27,21 @@ import ( // no debug flag at all. // urlFieldName matches the zap field NAMES whose values are URLs. -var urlFieldName = regexp.MustCompile(`(?i)(^url$|^urls$|_url$|_urls$|urls_tried|^resource$|_resource$|^endpoint$|_endpoint$)`) +// +// Review round 2 (finding B2) widened it. The first cut matched the LITERAL +// `urls_tried`, so the sibling `url_tried` four lines below a site it had just +// fixed sailed through, and so did every `auth_server*` field in +// discovery.go — five names, all of them holding a URL derived from the +// configured upstream URL. A guard whose regex is written from the sites that +// were already fixed proves nothing about the ones that were not. +var urlFieldName = regexp.MustCompile(`(?i)(` + strings.Join([]string{ + `^url$`, `^urls$`, `_url$`, `_urls$`, + `_tried$`, // url_tried, urls_tried, metadata_urls_tried, â€Ļ + `^resource$`, `_resource$`, + `^endpoint$`, `_endpoint$`, + `^auth_server$`, `^auth_servers$`, `^auth_server_base$`, + `^authorization_servers$`, +}, "|") + `)`) // safeURLRenderer matches the call expressions that are an acceptable value for // such a field. Anything else is a raw URL reaching a log sink. @@ -152,3 +166,207 @@ func TestAuthorizationURLIsNeverPrintedRaw(t *testing.T) { }) assert.Zero(t, printfs) } + +// TestNoRawErrorSitsBesideAMaskedURL is the other half of the same rule +// (issue #1158, review round 2, finding B3). +// +// Masking a statement's `url` field does not mask the statement. A net/http +// error quotes the request URL inside its own message — +// +// Post "https://host/mcp?token=SECRET": dial tcp 10.0.0.1:443: i/o timeout +// +// — so `zap.Error(err)` sitting next to `zap.String("metadata_url", +// logSafeURL(u))` publishes, on the identical log line, the credential its +// neighbour was written to hide. internal/oauth/discovery.go had fourteen of +// these, every one on an HTTP failure path. +// +// The rule is therefore structural rather than per-site: on a log statement +// that carries a URL field at all, the error goes through the scrubbing +// renderer (logSafeErrorField / oauth.LogSafeErrorText), never zap.Error. +func TestNoRawErrorSitsBesideAMaskedURL(t *testing.T) { + pkgs := []guardedPkg{ + {".", "internal/oauth"}, + {"../upstream/core", "internal/upstream/core"}, + {"../transport", "internal/transport"}, + } + + logMethod := map[string]bool{"Debug": true, "Info": true, "Warn": true, "Error": true, "Fatal": true, "Panic": true} + checked := 0 + + for _, pkg := range pkgs { + files, err := filepath.Glob(filepath.Join(pkg.dir, "*.go")) + require.NoError(t, err) + require.NotEmpty(t, files, "%s: the guard found no files to scan", pkg.name) + + for _, file := range files { + if strings.HasSuffix(file, "_test.go") { + continue + } + src, err := os.ReadFile(file) //nolint:gosec // fixed, in-repo paths + require.NoError(t, err) + fset := token.NewFileSet() + parsed, err := parser.ParseFile(fset, file, src, 0) + require.NoError(t, err) + + ast.Inspect(parsed, func(n ast.Node) bool { + call, ok := n.(*ast.CallExpr) + if !ok { + return true + } + sel, ok := call.Fun.(*ast.SelectorExpr) + if !ok || !logMethod[sel.Sel.Name] { + return true + } + + carriesURL := false + var rawErrors []string + for _, arg := range call.Args { + argSrc := string(src[arg.Pos()-1 : arg.End()-1]) + if name, ok := zapFieldName(arg); ok && urlFieldName.MatchString(name) { + carriesURL = true + } + if safeURLRenderer.MatchString(argSrc) { + carriesURL = true + } + if isZapErrorField(arg) { + rawErrors = append(rawErrors, argSrc) + } + } + if !carriesURL { + return true + } + checked++ + for _, raw := range rawErrors { + assert.Fail(t, + "a raw error sits on a log statement whose URL is masked", + "%s: %s writes a URL through the safe renderer and then hands the same "+ + "line `%s`. A *url.Error renders the request URL verbatim inside its "+ + "own text, so the credential the sibling field masks reaches the log "+ + "anyway. Use logSafeErrorField / oauth.LogSafeErrorText (issue #1158).", + fset.Position(call.Pos()), sel.Sel.Name, raw) + } + return true + }) + } + } + + assert.Greater(t, checked, 20, + "the guard matched only %d URL-bearing log statements — it has stopped seeing the sites it exists for", checked) +} + +// zapFieldName returns the literal field name of a `zap.String("x", â€Ļ)` / +// `zap.Strings("x", â€Ļ)` argument. +func zapFieldName(arg ast.Expr) (string, bool) { + call, ok := arg.(*ast.CallExpr) + if !ok || len(call.Args) != 2 { + return "", false + } + sel, ok := call.Fun.(*ast.SelectorExpr) + if !ok { + return "", false + } + pkgIdent, ok := sel.X.(*ast.Ident) + if !ok || pkgIdent.Name != "zap" { + return "", false + } + if sel.Sel.Name != "String" && sel.Sel.Name != "Strings" { + return "", false + } + lit, ok := call.Args[0].(*ast.BasicLit) + if !ok || lit.Kind != token.STRING { + return "", false + } + name, err := strconv.Unquote(lit.Value) + if err != nil { + return "", false + } + return name, true +} + +// isZapErrorField reports whether an argument is zap.Error(â€Ļ) / zap.NamedError(â€Ļ). +func isZapErrorField(arg ast.Expr) bool { + call, ok := arg.(*ast.CallExpr) + if !ok { + return false + } + sel, ok := call.Fun.(*ast.SelectorExpr) + if !ok { + return false + } + pkgIdent, ok := sel.X.(*ast.Ident) + if !ok || pkgIdent.Name != "zap" { + return false + } + return sel.Sel.Name == "Error" || sel.Sel.Name == "NamedError" +} + +// TestEveryOAuthFlowErrorIsScrubbedAtConstruction pins finding B7. +// +// contracts.OAuthFlowError is JSON-encoded straight to the REST caller. Its +// leaves were scrubbed one field at a time at eight construction sites, and one +// of them got it half right: emptyClientIDFlowError masked Details.ServerURL +// and set Details.DCRStatus.Error raw on the same struct. Per-field scrubbing +// at N sites is how that happens, so the rule is now "every literal goes +// through scrubbedFlowError" — and that is checkable. +func TestEveryOAuthFlowErrorIsScrubbedAtConstruction(t *testing.T) { + files, err := filepath.Glob("../upstream/core/*.go") + require.NoError(t, err) + require.NotEmpty(t, files) + + literals := 0 + for _, file := range files { + if strings.HasSuffix(file, "_test.go") { + continue + } + src, err := os.ReadFile(file) //nolint:gosec // fixed, in-repo paths + require.NoError(t, err) + fset := token.NewFileSet() + parsed, err := parser.ParseFile(fset, file, src, 0) + require.NoError(t, err) + + // Collect the positions of every literal that IS an argument of + // scrubbedFlowError, then require every literal to be one of them. + wrapped := map[token.Pos]bool{} + ast.Inspect(parsed, func(n ast.Node) bool { + call, ok := n.(*ast.CallExpr) + if !ok { + return true + } + ident, ok := call.Fun.(*ast.Ident) + if !ok || ident.Name != "scrubbedFlowError" || len(call.Args) != 1 { + return true + } + arg := call.Args[0] + if unary, ok := arg.(*ast.UnaryExpr); ok { + arg = unary.X + } + wrapped[arg.Pos()] = true + return true + }) + + ast.Inspect(parsed, func(n ast.Node) bool { + lit, ok := n.(*ast.CompositeLit) + if !ok { + return true + } + sel, ok := lit.Type.(*ast.SelectorExpr) + if !ok || sel.Sel.Name != "OAuthFlowError" { + return true + } + pkgIdent, ok := sel.X.(*ast.Ident) + if !ok || pkgIdent.Name != "contracts" { + return true + } + literals++ + assert.True(t, wrapped[lit.Pos()], + "%s: this contracts.OAuthFlowError literal is not wrapped in scrubbedFlowError. "+ + "The struct is JSON-encoded to the REST caller; scrubbing its leaves per site "+ + "is what let DCRStatus.Error ship raw next to a masked ServerURL (issue #1158).", + fset.Position(lit.Pos())) + return true + }) + } + + assert.GreaterOrEqual(t, literals, 7, + "the guard matched only %d OAuthFlowError literals — it has stopped seeing the sites it exists for", literals) +} diff --git a/internal/server/add_registry_source.go b/internal/server/add_registry_source.go index 7653584bf..4ee3b2d6d 100644 --- a/internal/server/add_registry_source.go +++ b/internal/server/add_registry_source.go @@ -145,7 +145,7 @@ func (s *Server) AddRegistrySource(req *AddRegistrySourceRequest) (*config.Regis s.logger.Info("Added custom registry source", zap.String("registry_id", entry.ID), - zap.String("url", oauth.RedactURLQueryParams(entry.URL)), + zap.String("url", oauth.LogSafeURL(entry.URL)), zap.String("provenance", entry.Provenance)) return &entry, nil @@ -169,7 +169,7 @@ func (s *Server) resolveRegistrySourceShape(entry *config.RegistryEntry) error { if err != nil { if errors.Is(err, registries.ErrRegistrySourceUnreachable) { s.logger.Warn("Could not probe registry source; adding it with the derived defaults", - zap.String("url", oauth.RedactURLQueryParams(entry.URL)), zap.Error(err)) + zap.String("url", oauth.LogSafeURL(entry.URL)), zap.Error(err)) return nil } return fmt.Errorf("%w: %v", ErrRegistrySourceUnusable, err) diff --git a/internal/server/edit_registry_source.go b/internal/server/edit_registry_source.go index 59d8e7e84..bcb9e2494 100644 --- a/internal/server/edit_registry_source.go +++ b/internal/server/edit_registry_source.go @@ -109,7 +109,7 @@ func (s *Server) EditRegistrySource(req *EditRegistrySourceRequest) (*config.Reg s.logger.Info("Edited custom registry source", zap.String("registry_id", updated.ID), - zap.String("url", oauth.RedactURLQueryParams(updated.URL))) + zap.String("url", oauth.LogSafeURL(updated.URL))) return &updated, nil } diff --git a/internal/server/remove_registry_source.go b/internal/server/remove_registry_source.go index 74668754a..0ef819b8f 100644 --- a/internal/server/remove_registry_source.go +++ b/internal/server/remove_registry_source.go @@ -69,7 +69,7 @@ func (s *Server) RemoveRegistrySource(id string) (*config.RegistryEntry, error) s.logger.Info("Removed custom registry source", zap.String("registry_id", removed.ID), - zap.String("url", oauth.RedactURLQueryParams(removed.URL))) + zap.String("url", oauth.LogSafeURL(removed.URL))) return &removed, nil } diff --git a/internal/transport/http.go b/internal/transport/http.go index 8eeda308a..9f3fe7273 100644 --- a/internal/transport/http.go +++ b/internal/transport/http.go @@ -475,13 +475,17 @@ func DetermineTransportType(serverConfig *config.ServerConfig) string { // (Client.logSafeURL); this is the same fix for the transport layer, which the // first cut of #1148 missed. // -// oauth.RedactURLQueryParams leaves scheme, host, path and non-sensitive -// parameters verbatim, so the log field stays as diagnosable as it was. +// oauth.LogSafeURL leaves scheme, host, path and non-sensitive parameters +// verbatim, so the log field stays as diagnosable as it was. Issue #1158 +// (review round 2, finding B6) moved it off the name-rule-only +// RedactURLQueryParams: a credential under an unrecognised parameter name +// survived that rule, and the sibling renderer in internal/oauth documents +// exactly why the name rule alone is not enough. func (c *HTTPTransportConfig) logSafeURL() string { if c == nil { return "" } - return oauth.RedactURLQueryParams(c.URL) + return oauth.LogSafeURL(c.URL) } // logSafeErrorField renders an error as a log field with any URL-embedded @@ -491,9 +495,15 @@ func (c *HTTPTransportConfig) logSafeURL() string { // net/http error quotes the request URL inside its own message // (`Post "https://host/mcp?token=â€Ļ": dial tcp â€Ļ`), so the credential kept // reaching the log through zap.Error on the request-failure paths. +// +// #1158 (review round 2): upgraded from RedactSensitiveData to +// ScrubUpstreamText, matching its twin in internal/upstream/core. An error +// string has no enclosing key to judge it by, so the value-shaped detector has +// to run as well — the name rule cannot see `?opaque=ghp_â€Ļ`. The two helpers +// are the same rule on the same class of text and had drifted apart. func logSafeErrorField(err error) zap.Field { if err == nil { return zap.Skip() } - return zap.String("error", oauth.RedactSensitiveData(err.Error())) + return zap.String("error", oauth.ScrubUpstreamText(err.Error())) } diff --git a/internal/transport/logging.go b/internal/transport/logging.go index 973b52caa..685e3a2c4 100644 --- a/internal/transport/logging.go +++ b/internal/transport/logging.go @@ -9,6 +9,7 @@ import ( "strings" "sync" "time" + "unicode/utf8" "go.uber.org/zap" @@ -72,7 +73,7 @@ func (t *LoggingTransport) RoundTrip(req *http.Request) (*http.Response, error) // #1148: the transport error quotes the request URL, credentials and // all. Both sinks get the redacted rendering; the error itself is // returned untouched to the caller. - safeErr := oauth.RedactSensitiveData(err.Error()) + safeErr := oauth.ScrubUpstreamText(err.Error()) fmt.Printf("❌ HTTP REQUEST FAILED: %v (duration: %v)\n", safeErr, duration) t.logger.Error("❌ HTTP REQUEST FAILED", logSafeErrorField(err), @@ -234,7 +235,7 @@ func (lr *loggingReader) Read(p []byte) (n int, err error) { } else { lr.logger.Debug("đŸ“Ĩ RESPONSE BODY (truncated)", zap.Int("total_size", len(body)), - zap.String("preview", oauth.ScrubUpstreamText(body[:1000])+"...")) + zap.String("preview", scrubbedPreview(body, 1000)+"...")) } } @@ -247,3 +248,30 @@ func (lr *loggingReader) Close() error { } return lr.rc.Close() } + +// scrubbedPreview redacts a response body and THEN truncates it (issue #1158, +// review round 2 minor). +// +// The order matters and the old one was wrong: `ScrubUpstreamText(body[:1000])` +// cut the body first, so a credential straddling byte 1000 was handed to the +// detectors as a FRAGMENT. Every vendor-shaped matcher is anchored on a +// complete token — a `ghp_` of the right length, a JWT with three segments, a +// `=` pair with a value — so the fragment matched nothing, and the +// leading bytes of a real secret were published while the log line claimed to +// be redacted. Scrubbing the whole body first means the matchers see the +// complete token; only the masked rendering is then cut. +// +// The cut is moved back to a rune boundary because the mask rendering is a run +// of multi-byte U+2022 bullets, and slicing one in half produces invalid UTF-8 +// that zap escapes into noise. +func scrubbedPreview(body string, limit int) string { + scrubbed := oauth.ScrubUpstreamText(body) + if len(scrubbed) <= limit { + return scrubbed + } + cut := limit + for cut > 0 && !utf8.RuneStart(scrubbed[cut]) { + cut-- + } + return scrubbed[:cut] +} diff --git a/internal/transport/preview_redact_test.go b/internal/transport/preview_redact_test.go new file mode 100644 index 000000000..5501425de --- /dev/null +++ b/internal/transport/preview_redact_test.go @@ -0,0 +1,80 @@ +package transport + +import ( + "strings" + "testing" + "unicode/utf8" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/smart-mcp-proxy/mcpproxy-go/internal/oauth" +) + +// Issue #1158, review round 2 (confirmed minor). +// +// The truncated-response-body log line scrubbed AFTER truncating: +// +// oauth.ScrubUpstreamText(body[:1000]) +// +// so a credential straddling byte 1000 reached the detectors as a FRAGMENT. +// Every vendor-shaped matcher is anchored on a complete token — a `ghp_` of the +// right length, a JWT with three segments — so the fragment matched nothing and +// the secret's leading bytes were published on a line that claims to be +// redacted. +// +// This test places a real credential across the cut and asserts no run of it +// survives. +func TestScrubbedPreview_ScrubsBeforeItTruncates(t *testing.T) { + const secret = "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789" + const limit = 1000 + + // Start the token 12 bytes before the cut, so ~28 bytes of it sit past it. + filler := strings.Repeat("x", limit-12) + body := filler + secret + strings.Repeat("y", 4000) + + require.Contains(t, oauth.ScrubUpstreamText(body[:limit]), secret[:12], + "sanity: truncate-then-scrub really does publish the leading fragment; "+ + "if this stops holding the test below proves nothing") + + got := scrubbedPreview(body, limit) + for i := 0; i+8 <= len(secret); i++ { + assert.NotContains(t, got, secret[i:i+8], + "an 8-byte run of the credential survived the preview") + } + assert.LessOrEqual(t, len(got), limit, "the preview must still be capped") + assert.True(t, utf8.ValidString(got), + "the mask rendering is multi-byte; the cut must land on a rune boundary") +} + +// A body shorter than the cap round-trips through the scrub only. +func TestScrubbedPreview_ShortBodyIsNotTruncated(t *testing.T) { + assert.Equal(t, "hello world", scrubbedPreview("hello world", 1000)) +} + +// The cut must not split a U+2022 bullet, which is what the mask is made of. +func TestScrubbedPreview_CutsOnARuneBoundary(t *testing.T) { + body := strings.Repeat("z", 20) + "api_key=" + strings.Repeat("s3cr3tv4lu3", 200) + for limit := 24; limit < 60; limit++ { + got := scrubbedPreview(body, limit) + assert.True(t, utf8.ValidString(got), "limit %d produced invalid UTF-8: %q", limit, got) + } +} + +// The transport's logSafeErrorField had drifted from its twin in +// internal/upstream/core: it still ran the NAME rule only, while the twin had +// moved to ScrubUpstreamText. Same rule, same class of text, one answer. +func TestTransportLogSafeErrorField_RunsTheValueShapedDetector(t *testing.T) { + const secret = "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789" + err := errorString(`Post "https://host.example/mcp?opaque=` + secret + `": dial tcp: timeout`) + + require.Contains(t, oauth.RedactSensitiveData(err.Error()), secret, + "sanity: the name rule cannot see a credential under an unrecognised parameter name") + + assert.NotContains(t, logSafeErrorField(err).String, secret) + assert.Contains(t, logSafeErrorField(err).String, "host.example") +} + +type errorString string + +func (e errorString) Error() string { return string(e) } diff --git a/internal/transport/retry_after.go b/internal/transport/retry_after.go index 250b16b9f..af3ba8192 100644 --- a/internal/transport/retry_after.go +++ b/internal/transport/retry_after.go @@ -191,7 +191,7 @@ func (t *RetryAfterTransport) RoundTrip(req *http.Request) (*http.Response, erro // password — it leaves `?token=â€Ļ` in the query verbatim, and this // line fires at Info on every 429/503-with-a-hint. Route it through // the project's own redactor, which masks both. - zap.String("url", oauth.RedactURLQueryParams(req.URL.String())), + zap.String("url", oauth.LogSafeURL(req.URL.String())), zap.Duration("retry_after", delay), zap.Time("retry_not_before", deadline)) } diff --git a/internal/upstream/cli/client.go b/internal/upstream/cli/client.go index ffbc63ad9..d97b033d9 100644 --- a/internal/upstream/cli/client.go +++ b/internal/upstream/cli/client.go @@ -107,7 +107,7 @@ func (c *Client) Connect(ctx context.Context) error { c.logger.Info("🔗 Starting connection to upstream server", zap.String("server", c.config.Name), zap.String("transport", c.getTransportType()), - zap.String("url", oauth.RedactURLQueryParams(c.config.URL)), + zap.String("url", oauth.LogSafeURL(c.config.URL)), zap.String("command", c.config.Command)) // Enable JSON-RPC frame logging if trace level is enabled diff --git a/internal/upstream/core/child_output_redact_test.go b/internal/upstream/core/child_output_redact_test.go new file mode 100644 index 000000000..381382484 --- /dev/null +++ b/internal/upstream/core/child_output_redact_test.go @@ -0,0 +1,72 @@ +package core + +import ( + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zaptest/observer" +) + +// Issue #1158, review round 2, investigation 3. +// +// loggerWriter pumps the launched child's own stdout/stderr into the +// per-server log. That log is not a local-only artifact: `mcpproxy upstream +// logs`, the `upstream_servers tail_log` MCP tool and +// GET /api/v1/servers/{id}/logs all serve it. An upstream that echoes its +// configuration on startup — and plenty do, "connecting with token â€Ļ" is a +// common startup banner — therefore publishes, on an HTTP surface, a +// credential mcpproxy itself handed it. +func TestLoggerWriter_ScrubsChildOutput(t *testing.T) { + core, logs := observer.New(zap.DebugLevel) + w := newLoggerWriter(zap.New(core), nil) + + const secret = "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789" + for _, line := range []string{ + "connecting to https://api.example/mcp?token=" + secret + "\n", + "WARN using api_key=" + secret + "\n", + "listening on http://127.0.0.1:9331\n", + } { + n, err := w.Write([]byte(line)) + require.NoError(t, err) + assert.Equal(t, len(line), n, "the writer must report the bytes it consumed, not the bytes it logged") + } + + var rendered []string + for _, entry := range logs.All() { + rendered = append(rendered, entry.Message) + } + joined := strings.Join(rendered, "\n") + + assert.NotContains(t, joined, secret, "the child's own output reaches a REST surface") + assert.Contains(t, joined, "api.example", "the host stays readable") + assert.Contains(t, joined, "listening on http://127.0.0.1:9331", + "ordinary child output must round-trip byte-identical — a per-server log "+ + "nobody can read is a different bug") +} + +// Issue #1158, review round 2, investigation 2: the token endpoint's non-200 +// response BODY was embedded verbatim in the refresh error, which is logged +// with the server name and returned to the REST caller. +func TestCappedScrub_ScrubsAndCapsAnUpstreamBody(t *testing.T) { + const secret = "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789" + + body := `{"error":"invalid_grant","error_description":"bad refresh_token=` + secret + `"}` + got := cappedScrub(body, 512) + assert.NotContains(t, got, secret) + assert.Contains(t, got, "invalid_grant", "the OAuth error CODE is the diagnostic") + + // Unbounded bodies (a proxy's HTML error page) must not go into the log whole. + huge := strings.Repeat("A", 5000) + assert.LessOrEqual(t, len(cappedScrub(huge, 512)), 512+len("â€Ļ (truncated)")) + + // Scrub-then-cap: a credential straddling the cut must not survive as a + // leading fragment. + straddling := strings.Repeat("x", 500) + secret + strings.Repeat("y", 500) + capped := cappedScrub(straddling, 512) + for i := 0; i+8 <= len(secret); i++ { + assert.NotContains(t, capped, secret[i:i+8]) + } +} diff --git a/internal/upstream/core/client.go b/internal/upstream/core/client.go index 214ee7b7d..aff2734c2 100644 --- a/internal/upstream/core/client.go +++ b/internal/upstream/core/client.go @@ -12,6 +12,7 @@ import ( "sync" "sync/atomic" "time" + "unicode/utf8" "github.com/smart-mcp-proxy/mcpproxy-go/internal/config" "github.com/smart-mcp-proxy/mcpproxy-go/internal/hash" @@ -790,7 +791,16 @@ func (c *Client) refreshTokenWithStoredCredentials(ctx context.Context, tokenEnd } if resp.StatusCode != http.StatusOK { - return nil, fmt.Errorf("token refresh failed with status %d: %s", resp.StatusCode, string(body)) + // Issue #1158 (review round 2, investigation 2). The token endpoint's + // error BODY was embedded verbatim, and this error is logged with the + // server name and returned to the REST caller. Two problems, both real: + // an OAuth error_description is provider-authored free text that does + // echo request parameters back (and this request's form carries + // client_secret and refresh_token), and the body is unbounded, so a + // 502 HTML page from a proxy in front of the endpoint went into + // main.log whole. Scrub with the free-text rule, then cap. + return nil, fmt.Errorf("token refresh failed with status %d: %s", + resp.StatusCode, cappedScrub(string(body), 512)) } var tokenResp oauthTokenResponse @@ -909,3 +919,23 @@ func (c *Client) oauthLogger() *zap.Logger { return zap.New(zapcore.NewTee(c.logger.Core(), c.upstreamLogger.Core())) } } + +// cappedScrub renders an upstream-authored response body for an error message: +// the free-form rule first, then the cap, and the cut moved back to a rune +// boundary because the mask rendering is multi-byte. +// +// Scrub-then-cap, not cap-then-scrub: cutting first hands the detectors a +// FRAGMENT of any credential straddling the boundary, and every vendor-shaped +// matcher is anchored on a complete token, so the fragment matches nothing and +// its leading bytes are published. +func cappedScrub(s string, limit int) string { + scrubbed := oauth.ScrubUpstreamText(s) + if len(scrubbed) <= limit { + return scrubbed + } + cut := limit + for cut > 0 && !utf8.RuneStart(scrubbed[cut]) { + cut-- + } + return scrubbed[:cut] + "â€Ļ (truncated)" +} diff --git a/internal/upstream/core/connection.go b/internal/upstream/core/connection.go index bd871ac6a..a7bb0b887 100644 --- a/internal/upstream/core/connection.go +++ b/internal/upstream/core/connection.go @@ -63,11 +63,17 @@ const ( // the file outlives the process and is readable by anything with disk access. // // The host and path survive, which is what makes the line diagnostic. +// +// #1158 (review round 2, finding B6): this delegates to oauth.LogSafeURL — the +// DEEP audit renderer — rather than the name-rule-only RedactURLQueryParams it +// used before. logSafeAuthURL below already argued that case for the authorize +// URL; the same argument applies verbatim to the configured URL this renders, +// and this value is served to REST callers inside OAuthErrorDetails.ServerURL. func (c *Client) logSafeURL() string { if c.config == nil { return "" } - return oauth.RedactURLQueryParams(c.config.URL) + return oauth.LogSafeURL(c.config.URL) } // logSafeAuthURL renders an OAuth AUTHORIZATION URL for a LOG FIELD or for diff --git a/internal/upstream/core/connection_launcher.go b/internal/upstream/core/connection_launcher.go index cbf5829f1..266d1041f 100644 --- a/internal/upstream/core/connection_launcher.go +++ b/internal/upstream/core/connection_launcher.go @@ -12,6 +12,7 @@ import ( "go.uber.org/zap" "github.com/smart-mcp-proxy/mcpproxy-go/internal/config" + "github.com/smart-mcp-proxy/mcpproxy-go/internal/oauth" "github.com/smart-mcp-proxy/mcpproxy-go/internal/upstream/launcher" ) @@ -344,6 +345,21 @@ func (w *loggerWriter) Write(p []byte) (int, error) { if line == "" { return len(p), nil } + // Issue #1158 (review round 2, investigation 3). This is the child + // process's own stdout/stderr, written verbatim into + // ~/.mcpproxy/logs/server-.log — and that file is not local-only: it + // is tailed by `mcpproxy upstream logs`, returned by the + // `upstream_servers tail_log` MCP tool, and served over HTTP by + // GET /api/v1/servers/{id}/logs. An upstream that echoes its own + // configuration on startup ("connecting with token sk-live-â€Ļ", a stack + // trace quoting the request URL) therefore puts a credential on a REST + // surface, and it is a credential mcpproxy itself handed the child. + // + // ScrubUpstreamText is the rule this exact class of string gets everywhere + // else in the tree: text originated OUTSIDE mcpproxy's own structured + // fields, with no enclosing key to judge it by, so both the name rule and + // the value-shaped detector run. Ordinary child output is untouched by it. + line = oauth.ScrubUpstreamText(line) switch { case w.primary != nil: w.primary.Info(line) diff --git a/internal/upstream/core/connection_oauth.go b/internal/upstream/core/connection_oauth.go index 0807bfc10..91370a383 100644 --- a/internal/upstream/core/connection_oauth.go +++ b/internal/upstream/core/connection_oauth.go @@ -233,7 +233,7 @@ func (c *Client) tryOAuthAuth(ctx context.Context) error { zap.Int("extra_params_count", len(extraParams))) if oauthConfig == nil { - c.logger.Error("🚨 OAUTH CONFIG IS NIL - RETURNING ERROR", zap.Error(oauthConfigErr)) + c.logger.Error("🚨 OAUTH CONFIG IS NIL - RETURNING ERROR", logSafeErrorField(oauthConfigErr)) oauthErr = wrapOAuthConfigError(oauthConfigErr) return oauthErr } @@ -252,7 +252,7 @@ func (c *Client) tryOAuthAuth(ctx context.Context) error { httpClient, err := transport.CreateHTTPClient(httpConfig) if err != nil { c.logger.Error("đŸ’Ĩ Failed to create OAuth HTTP client in transport layer", - zap.Error(err)) + logSafeErrorField(err)) return fmt.Errorf("failed to create OAuth HTTP client: %w", err) } @@ -342,7 +342,7 @@ func (c *Client) tryOAuthAuth(ctx context.Context) error { if !client.IsOAuthAuthorizationRequiredError(err) { c.logger.Error("❌ OAuth client start failed with non-OAuth error", zap.String("server", c.config.Name), - zap.Error(err)) + logSafeErrorField(err)) oauthErr = fmt.Errorf("OAuth client start failed: %w", err) return oauthErr } @@ -404,7 +404,7 @@ func (c *Client) tryOAuthAuth(ctx context.Context) error { if err != nil { c.logger.Error("❌ OAuth client start failed after authorization", zap.String("server", c.config.Name), - zap.Error(err)) + logSafeErrorField(err)) oauthErr = fmt.Errorf("OAuth client start failed after authorization: %w", err) return oauthErr } @@ -414,7 +414,7 @@ func (c *Client) tryOAuthAuth(ctx context.Context) error { } else { c.logger.Error("❌ OAuth client start failed with non-OAuth error", zap.String("server", c.config.Name), - zap.Error(lastErr)) + logSafeErrorField(lastErr)) oauthErr = fmt.Errorf("OAuth client start failed: %w", lastErr) return oauthErr } @@ -434,7 +434,7 @@ func (c *Client) tryOAuthAuth(ctx context.Context) error { if err := c.initialize(ctx); err != nil { c.logger.Error("❌ MCP initialization failed after OAuth setup", zap.String("server", c.config.Name), - zap.Error(err)) + logSafeErrorField(err)) // Check if this is a deprecated endpoint error (HTTP 410 Gone) // This indicates the server has migrated to a new endpoint URL @@ -449,7 +449,7 @@ func (c *Client) tryOAuthAuth(ctx context.Context) error { zap.String("correlation_id", correlationID), zap.String("action", "Update the server URL in your configuration"), zap.String("hint", "Check the server's documentation or try removing /sse from the URL"), - zap.Error(err)) + logSafeErrorField(err)) return transport.NewEndpointDeprecatedError( c.config.URL, @@ -512,7 +512,7 @@ func (c *Client) tryOAuthAuth(ctx context.Context) error { if retryErr := c.initialize(ctx); retryErr != nil { c.logger.Error("❌ MCP initialization failed after OAuth authorization", zap.String("server", c.config.Name), - zap.Error(retryErr)) + logSafeErrorField(retryErr)) oauthErr = fmt.Errorf("MCP initialize failed after OAuth authorization: %w", retryErr) return oauthErr } @@ -526,14 +526,14 @@ func (c *Client) tryOAuthAuth(ctx context.Context) error { // and attempt a fresh browser OAuth flow. c.logger.Warn("⚠ī¸ Server returned 5xx during MCP init - stored token may be invalid, attempting fresh OAuth", zap.String("server", c.config.Name), - zap.Error(err)) + logSafeErrorField(err)) // Clear the stored token so a fresh one can be obtained if tokenStore, ok := oauthConfig.TokenStore.(interface{ ClearToken() error }); ok { if clearErr := tokenStore.ClearToken(); clearErr != nil { c.logger.Warn("Failed to clear stored token", zap.String("server", c.config.Name), - zap.Error(clearErr)) + logSafeErrorField(clearErr)) } } @@ -561,7 +561,7 @@ func (c *Client) tryOAuthAuth(ctx context.Context) error { if retryErr := c.initialize(ctx); retryErr != nil { c.logger.Error("❌ MCP initialization failed after fresh OAuth (server may be down)", zap.String("server", c.config.Name), - zap.Error(retryErr)) + logSafeErrorField(retryErr)) oauthErr = fmt.Errorf("MCP initialize failed after fresh OAuth: %w", retryErr) return oauthErr } @@ -668,7 +668,7 @@ func (c *Client) trySSEOAuthAuth(ctx context.Context) error { // Create OAuth config with auto-detected extra params (RFC 8707 resource) oauthConfig, extraParams, oauthConfigErr := oauth.CreateOAuthConfigWithExtraParamsAndLogger(ctx, c.config, c.storage, c.oauthLogger()) if oauthConfig == nil { - c.logger.Error("🚨 Failed to create OAuth config", zap.Error(oauthConfigErr)) + c.logger.Error("🚨 Failed to create OAuth config", logSafeErrorField(oauthConfigErr)) oauthErr = wrapOAuthConfigError(oauthConfigErr) return oauthErr } @@ -687,7 +687,7 @@ func (c *Client) trySSEOAuthAuth(ctx context.Context) error { sseClient, err := transport.CreateSSEClient(httpConfig) if err != nil { c.logger.Error("đŸ’Ĩ Failed to create OAuth SSE client in transport layer", - zap.Error(err)) + logSafeErrorField(err)) return fmt.Errorf("failed to create OAuth SSE client: %w", err) } @@ -700,7 +700,7 @@ func (c *Client) trySSEOAuthAuth(ctx context.Context) error { c.client.OnConnectionLost(func(err error) { c.logger.Warn("⚠ī¸ SSE OAuth connection lost detected", zap.String("server", c.config.Name), - zap.Error(err), + logSafeErrorField(err), zap.String("transport", "sse-oauth"), zap.String("note", "Connection dropped by server or network - will attempt reconnection")) }) @@ -790,7 +790,7 @@ func (c *Client) trySSEOAuthAuth(ctx context.Context) error { if !client.IsOAuthAuthorizationRequiredError(err) { c.logger.Error("❌ SSE OAuth client start failed with non-OAuth error", zap.String("server", c.config.Name), - zap.Error(err)) + logSafeErrorField(err)) oauthErr = fmt.Errorf("SSE OAuth client start failed: %w", err) return oauthErr } @@ -852,7 +852,7 @@ func (c *Client) trySSEOAuthAuth(ctx context.Context) error { if err != nil { c.logger.Error("❌ SSE OAuth client start failed after authorization", zap.String("server", c.config.Name), - zap.Error(err)) + logSafeErrorField(err)) oauthErr = fmt.Errorf("SSE OAuth client start failed after authorization: %w", err) return oauthErr } @@ -862,7 +862,7 @@ func (c *Client) trySSEOAuthAuth(ctx context.Context) error { } else { c.logger.Error("❌ SSE OAuth client start failed with non-OAuth error", zap.String("server", c.config.Name), - zap.Error(lastErr)) + logSafeErrorField(lastErr)) oauthErr = fmt.Errorf("SSE OAuth client start failed: %w", lastErr) return oauthErr } @@ -956,7 +956,7 @@ func (c *Client) handleOAuthAuthorization(ctx context.Context, authErr error, oa zap.String("error_type", metadataErr.ErrorType), zap.String("message", metadataErr.Message)) - return &contracts.OAuthFlowError{ + return scrubbedFlowError(&contracts.OAuthFlowError{ Success: false, ErrorType: metadataErr.ErrorType, ErrorCode: metadataErr.ErrorCode, @@ -988,12 +988,12 @@ func (c *Client) handleOAuthAuthorization(ctx context.Context, authErr error, oa }, Suggestion: metadataErr.Suggestion, DebugHint: fmt.Sprintf("For logs: mcpproxy upstream logs %s", c.config.Name), - } + }) } // For non-metadata errors, log and continue (don't block OAuth flow) c.logger.Debug("OAuth metadata validation returned non-metadata error, continuing with flow", zap.String("server", c.config.Name), - zap.Error(validationErr)) + logSafeErrorField(validationErr)) } } @@ -1078,7 +1078,7 @@ func (c *Client) handleOAuthAuthorization(ctx context.Context, authErr error, oa oauthMode = "public client (PKCE)" c.logger.Warn("⚠ī¸ Dynamic Client Registration not supported - using public client OAuth with PKCE", zap.String("server", c.config.Name), - zap.Error(regErr)) + logSafeErrorField(regErr)) c.logger.Info("💡 Proceeding with public client authentication (no client_id required)", zap.String("server", c.config.Name), zap.String("mode", "OAuth 2.1 public client with PKCE"), @@ -1099,7 +1099,7 @@ func (c *Client) handleOAuthAuthorization(ctx context.Context, authErr error, oa if err := c.storage.UpdateOAuthClientCredentials(serverKey, clientID, clientSecret, callbackPort); err != nil { c.logger.Warn("Failed to persist DCR credentials - token refresh may fail later", zap.String("server", c.config.Name), - zap.Error(err)) + logSafeErrorField(err)) } else { c.logger.Info("✅ DCR credentials persisted for token refresh", zap.String("server", c.config.Name), @@ -1156,7 +1156,7 @@ func (c *Client) handleOAuthAuthorization(ctx context.Context, authErr error, oa suggestion = "The OAuth authorization server metadata is not available. Contact the server administrator." } - return &contracts.OAuthFlowError{ + return scrubbedFlowError(&contracts.OAuthFlowError{ Success: false, ErrorType: errType, ErrorCode: errCode, @@ -1167,7 +1167,7 @@ func (c *Client) handleOAuthAuthorization(ctx context.Context, authErr error, oa }, Suggestion: suggestion, DebugHint: fmt.Sprintf("For logs: mcpproxy upstream logs %s", c.config.Name), - } + }) } // Append extra OAuth parameters to authorization URL (RFC 8707 resource, etc.) @@ -1191,7 +1191,7 @@ func (c *Client) handleOAuthAuthorization(ctx context.Context, authErr error, oa } else { c.logger.Warn("Failed to parse authorization URL for extra params", zap.String("server", c.config.Name), - zap.Error(err)) + logSafeErrorField(err)) } } @@ -1244,7 +1244,7 @@ func (c *Client) handleOAuthAuthorization(ctx context.Context, authErr error, oa c.logger.Warn("Failed to open browser automatically, please open manually", zap.String("server", c.config.Name), zap.String("url", logSafeAuthURL(authURL)), - zap.Error(err)) + logSafeErrorField(err)) fmt.Printf("Please open the following URL in your browser: %s\n", logSafeAuthURL(authURL)) } @@ -1293,7 +1293,7 @@ func (c *Client) handleOAuthAuthorization(ctx context.Context, authErr error, oa if err != nil { c.logger.Error("❌ Failed to process authorization response", zap.String("server", c.config.Name), - zap.Error(err)) + logSafeErrorField(err)) return fmt.Errorf("failed to process authorization response: %w", err) } @@ -1360,7 +1360,7 @@ func (c *Client) handleOAuthAuthorizationWithResult(ctx context.Context, authErr zap.String("error_type", metadataErr.ErrorType), zap.String("message", metadataErr.Message)) - return result, &contracts.OAuthFlowError{ + return result, scrubbedFlowError(&contracts.OAuthFlowError{ Success: false, ErrorType: metadataErr.ErrorType, ErrorCode: metadataErr.ErrorCode, @@ -1372,11 +1372,11 @@ func (c *Client) handleOAuthAuthorizationWithResult(ctx context.Context, authErr }, Suggestion: metadataErr.Suggestion, DebugHint: fmt.Sprintf("For logs: mcpproxy upstream logs %s", c.config.Name), - } + }) } c.logger.Debug("OAuth metadata validation returned non-metadata error, continuing with flow", zap.String("server", c.config.Name), - zap.Error(validationErr)) + logSafeErrorField(validationErr)) } } @@ -1437,7 +1437,7 @@ func (c *Client) handleOAuthAuthorizationWithResult(ctx context.Context, authErr dcrErr = regErr c.logger.Info("ℹī¸ DCR not available, continuing with public client OAuth", zap.String("server", c.config.Name), - zap.Error(regErr)) + logSafeErrorField(regErr)) } else { clientID := oauthHandler.GetClientID() clientSecret := oauthHandler.GetClientSecret() @@ -1454,7 +1454,7 @@ func (c *Client) handleOAuthAuthorizationWithResult(ctx context.Context, authErr if saveErr := c.storage.UpdateOAuthClientCredentials(serverKey, clientID, clientSecret, callbackPort); saveErr != nil { c.logger.Warn("Failed to persist DCR credentials", zap.String("server", c.config.Name), - zap.Error(saveErr)) + logSafeErrorField(saveErr)) } } } @@ -1478,8 +1478,8 @@ func (c *Client) handleOAuthAuthorizationWithResult(ctx context.Context, authErr if authURLErr != nil { c.logger.Error("❌ Failed to get authorization URL", zap.String("server", c.config.Name), - zap.Error(authURLErr)) - return result, &contracts.OAuthFlowError{ + logSafeErrorField(authURLErr)) + return result, scrubbedFlowError(&contracts.OAuthFlowError{ Success: false, ErrorType: contracts.OAuthErrorFlowFailed, ErrorCode: contracts.OAuthCodeFlowFailed, @@ -1491,7 +1491,7 @@ func (c *Client) handleOAuthAuthorizationWithResult(ctx context.Context, authErr }, Suggestion: "Check server OAuth configuration and try again.", DebugHint: fmt.Sprintf("For logs: mcpproxy upstream logs %s", c.config.Name), - } + }) } // Append extra OAuth parameters to authorization URL (RFC 8707 resource, etc.) @@ -1516,7 +1516,7 @@ func (c *Client) handleOAuthAuthorizationWithResult(ctx context.Context, authErr } else { c.logger.Warn("Failed to parse authorization URL for extra params", zap.String("server", c.config.Name), - zap.Error(err)) + logSafeErrorField(err)) } } @@ -1538,9 +1538,9 @@ func (c *Client) handleOAuthAuthorizationWithResult(ctx context.Context, authErr c.logger.Warn("Failed to open browser automatically, please open manually", zap.String("server", c.config.Name), zap.String("url", logSafeAuthURL(authURL)), - zap.Error(err)) + logSafeErrorField(err)) result.BrowserOpened = false - result.BrowserError = err.Error() + result.BrowserError = oauth.LogSafeErrorText(err) fmt.Printf("Please open the following URL in your browser: %s\n", logSafeAuthURL(authURL)) } else { result.BrowserOpened = true @@ -1640,7 +1640,7 @@ func (c *Client) markOAuthComplete() { if err := tm.MarkOAuthCompletedWithDB(c.config.Name, c.storage); err != nil { c.logger.Warn("Failed to persist OAuth completion event to DB; using in-memory notification", zap.String("server", c.config.Name), - zap.Error(err)) + logSafeErrorField(err)) tm.MarkOAuthCompleted(c.config.Name) } else { c.logger.Info("đŸ“ĸ OAuth completion recorded to DB for cross-process notification", @@ -1657,7 +1657,7 @@ func (c *Client) markOAuthComplete() { if err := manager.StopCallbackServer(c.config.Name); err != nil { c.logger.Warn("Failed to stop OAuth callback server", zap.String("server", c.config.Name), - zap.Error(err)) + logSafeErrorField(err)) } } } @@ -1701,7 +1701,7 @@ func (c *Client) persistDCRCredentials() { if err := c.storage.UpdateOAuthClientCredentials(serverKey, clientID, clientSecret, callbackPort); err != nil { c.logger.Error("Failed to persist DCR credentials", zap.String("server", c.config.Name), - zap.Error(err)) + logSafeErrorField(err)) return } @@ -1815,7 +1815,7 @@ func (c *Client) StartOAuthFlowQuick(ctx context.Context) (*OAuthStartResult, er c.logger.Error("❌ Failed to create OAuth config", zap.String("server", c.config.Name), zap.String("correlation_id", result.CorrelationID), - zap.Error(oauthConfigErr)) + logSafeErrorField(oauthConfigErr)) return result, wrapOAuthConfigError(oauthConfigErr) } @@ -1828,7 +1828,7 @@ func (c *Client) StartOAuthFlowQuick(ctx context.Context) (*OAuthStartResult, er zap.String("server", c.config.Name), zap.String("correlation_id", result.CorrelationID), zap.String("error_type", metadataErr.ErrorType)) - return result, &contracts.OAuthFlowError{ + return result, scrubbedFlowError(&contracts.OAuthFlowError{ Success: false, ErrorType: metadataErr.ErrorType, ErrorCode: metadataErr.ErrorCode, @@ -1836,7 +1836,7 @@ func (c *Client) StartOAuthFlowQuick(ctx context.Context) (*OAuthStartResult, er CorrelationID: result.CorrelationID, Message: metadataErr.Message, Suggestion: metadataErr.Suggestion, - } + }) } } } @@ -1847,7 +1847,7 @@ func (c *Client) StartOAuthFlowQuick(ctx context.Context) (*OAuthStartResult, er c.logger.Error("❌ Failed to get authorization URL", zap.String("server", c.config.Name), zap.String("correlation_id", result.CorrelationID), - zap.Error(err)) + logSafeErrorField(err)) // Add correlation_id to structured errors for tracing var flowErr *contracts.OAuthFlowError @@ -1885,9 +1885,9 @@ func (c *Client) StartOAuthFlowQuick(ctx context.Context) (*OAuthStartResult, er c.logger.Warn("Failed to open browser automatically", zap.String("server", c.config.Name), zap.String("url", logSafeAuthURL(authURL)), - zap.Error(err)) + logSafeErrorField(err)) result.BrowserOpened = false - result.BrowserError = err.Error() + result.BrowserError = oauth.LogSafeErrorText(err) } else { result.BrowserOpened = true c.logger.Info("✅ Browser opened successfully", @@ -1982,7 +1982,7 @@ func (c *Client) getAuthorizationURLQuick(ctx context.Context, oauthConfig *clie c.logger.Warn("⚠ī¸ DCR failed", zap.String("server", c.config.Name), zap.String("correlation_id", correlationID), - zap.Error(regErr)) + logSafeErrorField(regErr)) } else { c.logger.Info("✅ DCR succeeded", zap.String("server", c.config.Name), @@ -2014,14 +2014,14 @@ func (c *Client) getAuthorizationURLQuick(ctx context.Context, oauthConfig *clie }() if authURLErr != nil { - return "", nil, "", "", &contracts.OAuthFlowError{ + return "", nil, "", "", scrubbedFlowError(&contracts.OAuthFlowError{ Success: false, ErrorType: contracts.OAuthErrorFlowFailed, ErrorCode: contracts.OAuthCodeFlowFailed, ServerName: c.config.Name, Message: fmt.Sprintf("Failed to get authorization URL: %v", authURLErr), Suggestion: "Check server OAuth configuration and try again.", - } + }) } // Append extra OAuth parameters to authorization URL (RFC 8707 resource, etc.) @@ -2046,7 +2046,7 @@ func (c *Client) getAuthorizationURLQuick(ctx context.Context, oauthConfig *clie } else { c.logger.Warn("Failed to parse authorization URL for extra params", zap.String("server", c.config.Name), - zap.Error(err)) + logSafeErrorField(err)) } } @@ -2094,7 +2094,7 @@ func (c *Client) emptyClientIDFlowError(authURL, correlationID string, dcrErr er c.logger.Error("❌ OAuth provider requires a client_id but none is available (DCR unsupported or failed)", zap.String("server", c.config.Name), zap.String("url", c.logSafeURL()), - zap.NamedError("dcr_error", dcrErr), + zap.String("dcr_error", oauth.LogSafeErrorText(dcrErr)), zap.String("help", "Register an OAuth app with the provider and set oauth.client_id in the server config")) details := &contracts.OAuthErrorDetails{ ServerURL: c.logSafeURL(), @@ -2115,7 +2115,7 @@ func (c *Client) emptyClientIDFlowError(authURL, correlationID string, dcrErr er } details.DCRStatus = dcrStatus } - return &contracts.OAuthFlowError{ + return scrubbedFlowError(&contracts.OAuthFlowError{ Success: false, ErrorType: contracts.OAuthErrorClientIDRequired, ErrorCode: contracts.OAuthCodeNoClientID, @@ -2125,7 +2125,7 @@ func (c *Client) emptyClientIDFlowError(authURL, correlationID string, dcrErr er Details: details, Suggestion: "Register an OAuth app with the provider and set oauth.client_id in the server config.", DebugHint: fmt.Sprintf("For logs: mcpproxy upstream logs %s", c.config.Name), - } + }) } // waitForOAuthCallbackAsync waits for OAuth callback and handles token exchange in background. @@ -2198,7 +2198,7 @@ func (c *Client) waitForOAuthCallbackAsync(ctx context.Context, oauthHandler *up if err := oauthHandler.ProcessAuthorizationResponse(ctx, code, state, codeVerifier); err != nil { c.logger.Error("❌ Failed to exchange authorization code", zap.String("server", c.config.Name), - zap.Error(err)) + logSafeErrorField(err)) c.reportOAuthFailure(fmt.Errorf("OAuth token exchange failed for %s: %w", c.config.Name, err)) return } @@ -2312,7 +2312,7 @@ func (c *Client) forceHTTPOAuthFlowWithResult(ctx context.Context) (*OAuthStartR if oauthConfig == nil { c.logger.Error("❌ Failed to create OAuth config", zap.String("server", c.config.Name), - zap.Error(oauthConfigErr)) + logSafeErrorField(oauthConfigErr)) return nil, wrapOAuthConfigError(oauthConfigErr) } @@ -2380,7 +2380,7 @@ func (c *Client) forceSSEOAuthFlowWithResult(ctx context.Context) (*OAuthStartRe if oauthConfig == nil { c.logger.Error("❌ Failed to create OAuth config", zap.String("server", c.config.Name), - zap.Error(oauthConfigErr)) + logSafeErrorField(oauthConfigErr)) return nil, wrapOAuthConfigError(oauthConfigErr) } @@ -2486,3 +2486,54 @@ func (c *Client) clearOAuthState() { c.oauthCompleted = false c.lastOAuthTimestamp = time.Time{} } + +// scrubbedFlowError masks every free-text and URL leaf of a structured OAuth +// error at the point it is BUILT (issue #1158, review round 2 finding B7). +// +// The struct is JSON-encoded straight to the REST caller by handleServerLogin +// and rendered by `mcpproxy auth status`, so every string on it is a published +// surface. The original fix scrubbed the leaves it could see one at a time and +// half of one struct got done: emptyClientIDFlowError masked +// `Details.ServerURL` and then set `Details.DCRStatus.Error = dcrErr.Error()` +// RAW on the same struct — a DCR failure quotes the registration endpoint URL, +// and mcp-go returns the provider's own response text there. +// +// Scrubbing per-field at eight construction sites is how that happens. This +// walks the whole struct instead, so a leaf added later is covered by +// construction rather than by whoever remembers. +// +// The rules are the package's own: URL leaves keep scheme/host/path through the +// deep audit renderer (the panel exists to say WHICH endpoint failed), and +// free text goes through ScrubUpstreamText, which is what an +// originated-outside-mcpproxy string gets everywhere else in the tree. +// +// Idempotent: every rule is a no-op on its own output, so wrapping a value that +// was already rendered safely (`c.logSafeURL()`) costs nothing. +func scrubbedFlowError(e *contracts.OAuthFlowError) *contracts.OAuthFlowError { + if e == nil { + return nil + } + e.Message = oauth.ScrubUpstreamText(e.Message) + e.Suggestion = oauth.ScrubUpstreamText(e.Suggestion) + e.DebugHint = oauth.ScrubUpstreamText(e.DebugHint) + if d := e.Details; d != nil { + d.ServerURL = oauth.LogSafeURL(d.ServerURL) + scrubMetadataStatus(d.ProtectedResourceMetadata) + scrubMetadataStatus(d.AuthorizationServerMetadata) + if s := d.DCRStatus; s != nil { + s.Error = oauth.ScrubUpstreamText(s.Error) + } + } + return e +} + +func scrubMetadataStatus(m *contracts.MetadataStatus) { + if m == nil { + return + } + m.URLChecked = oauth.LogSafeURL(m.URLChecked) + m.Error = oauth.ScrubUpstreamText(m.Error) + for i, u := range m.AuthorizationServers { + m.AuthorizationServers[i] = oauth.LogSafeURL(u) + } +} diff --git a/internal/upstream/core/flow_error_redact_test.go b/internal/upstream/core/flow_error_redact_test.go new file mode 100644 index 000000000..8044032bf --- /dev/null +++ b/internal/upstream/core/flow_error_redact_test.go @@ -0,0 +1,120 @@ +package core + +import ( + "encoding/json" + "errors" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zaptest/observer" + + "github.com/smart-mcp-proxy/mcpproxy-go/internal/config" + "github.com/smart-mcp-proxy/mcpproxy-go/internal/contracts" +) + +const ( + credURL = "https://host.example/mcp?opaque=ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789" + credToken = "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789" +) + +// Issue #1158, review round 2, finding B7. +// +// emptyClientIDFlowError scrubbed ONE leaf of contracts.OAuthFlowError and left +// its siblings raw on the same struct: `Details.DCRStatus.Error` took +// `dcrErr.Error()` verbatim, and the log statement four lines above wrote the +// same error through zap.NamedError. The whole struct is JSON-encoded to the +// REST caller by handleServerLogin, so a DCR failure that quotes the +// registration endpoint published the credential twice. +// +// Per-field scrubbing at N construction sites is what allowed that, so the +// assertion is on the SERIALIZED struct — every leaf the caller can see — +// rather than on the one field the fix happened to touch. +func TestEmptyClientIDFlowError_ScrubsEveryLeafItPublishes(t *testing.T) { + core, logs := observer.New(zap.DebugLevel) + c := &Client{ + config: &config.ServerConfig{Name: "alpha", URL: credURL}, + logger: zap.New(core), + } + + dcrErr := errors.New(`registration failed: Post "` + credURL + `": 403 Forbidden`) + flowErr := c.emptyClientIDFlowError("https://auth.example/authorize?scope=read", "corr-1", dcrErr) + require.NotNil(t, flowErr) + + encoded, err := json.Marshal(flowErr) + require.NoError(t, err) + assert.NotContains(t, string(encoded), credToken, + "every leaf of this struct reaches the REST caller: %s", encoded) + + require.NotNil(t, flowErr.Details) + require.NotNil(t, flowErr.Details.DCRStatus) + assert.Equal(t, 403, flowErr.Details.DCRStatus.StatusCode, + "the DCR outcome is the diagnostic and must survive the scrub") + assert.Contains(t, flowErr.Details.DCRStatus.Error, "403", + "the provider's status is what distinguishes a rejection from no DCR at all") + assert.Contains(t, flowErr.Details.ServerURL, "host.example", + "the host survives so the panel still names the server") + + var rendered string + for _, entry := range logs.All() { + rendered += entry.Message + for k, v := range entry.ContextMap() { + rendered += " " + k + "=" + toStr(v) + } + } + assert.NotContains(t, rendered, credToken, + "the log statement beside the scrubbed field must not re-publish it") + assert.Contains(t, rendered, "dcr_error", + "the DCR failure is still reported; only its credential is gone") +} + +func toStr(v interface{}) string { + b, err := json.Marshal(v) + if err != nil { + return "" + } + return string(b) +} + +// scrubbedFlowError is the ONE place the rule now lives, so assert it covers a +// leaf that no current construction site sets — that is the property that +// makes it survive the next field somebody adds. +func TestScrubbedFlowError_CoversEveryFreeTextLeaf(t *testing.T) { + got := scrubbedFlowError(&contracts.OAuthFlowError{ + Message: "failed for " + credURL, + Suggestion: "retry against " + credURL, + DebugHint: "see " + credURL, + Details: &contracts.OAuthErrorDetails{ + ServerURL: credURL, + ProtectedResourceMetadata: &contracts.MetadataStatus{ + URLChecked: credURL, + Error: "fetch failed for " + credURL, + AuthorizationServers: []string{credURL}, + }, + AuthorizationServerMetadata: &contracts.MetadataStatus{ + URLChecked: credURL, + Error: "fetch failed for " + credURL, + }, + DCRStatus: &contracts.DCRStatus{Error: "register failed for " + credURL}, + }, + }) + + encoded, err := json.Marshal(got) + require.NoError(t, err) + assert.NotContains(t, string(encoded), credToken, "encoded: %s", encoded) + assert.Contains(t, string(encoded), "host.example", "hosts and paths stay readable") + + assert.Nil(t, scrubbedFlowError(nil)) +} + +// Finding B6 at the call site: Client.logSafeURL must use the DEEP renderer. +// The name-rule-only one it used before could not see a credential under an +// unrecognised parameter name, and this value is served to REST callers inside +// OAuthErrorDetails.ServerURL. +func TestClientLogSafeURL_UsesTheDeepRenderer(t *testing.T) { + c := &Client{config: &config.ServerConfig{Name: "alpha", URL: credURL}} + got := c.logSafeURL() + assert.NotContains(t, got, credToken) + assert.Contains(t, got, "host.example/mcp") +} diff --git a/internal/upstream/managed/client.go b/internal/upstream/managed/client.go index ad8e3c9fb..00ea96b6a 100644 --- a/internal/upstream/managed/client.go +++ b/internal/upstream/managed/client.go @@ -1095,7 +1095,7 @@ func (mc *Client) logSafeURL() string { if cfg == nil { return "" } - return oauth.RedactURLQueryParams(cfg.URL) + return oauth.LogSafeURL(cfg.URL) } // onStateChange handles state transition events From bb9c1c214e39fc5c3da226469f858ef688276a87 Mon Sep 17 00:00:00 2001 From: Algis Dumbris Date: Wed, 2 Sep 2026 10:38:22 +0300 Subject: [PATCH 3/4] fix(security): close the two leaks the live check found, at the seams that feed every sink MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The round-2 live run — a stdio server carrying an argv secret and printing a token on startup, plus an http server with `?token=` and `?opaque=ghp_â€Ļ` in its URL — still put two credentials in the log after every fix above had landed. Both were the same shape as finding B3 one level further out. `sk-live-â€Ļ` appeared 8 times because the stdio stderr PUMP (core/monitoring.go) is a different code path from the launcher's loggerWriter. It feeds THREE sinks from one string: main.log, the per-server log that GET /api/v1/servers/{id}/logs serves, and the recent-stderr ring buffer that connectStdio splices into the "did not respond to MCP initialize" error — which is itself logged and returned to REST callers. Scrubbing the line once at the top of the loop covers all three. `ghp_â€Ļ` appeared 15 times because redactURLCredentialsInError — the ONE seam where a transport error enters mcpproxy, and whose own doc comment says "redacting once, where the transport error enters mcpproxy, is what keeps a future log site from re-leaking it" — ran the NAME rule only. `opaque` is not a recognised parameter name, so the token walked through it and then through managed.Client, upstream.Manager, the supervisor and the runtime, each of which zap.Errors the string it is handed and none of which can be fixed from its own file. ScrubUpstreamText there fixes all four. Also registers the three new exported renderings with the fail-closed net's discovery gate: LogSafeURL and LogSafeCallbackQuery are bound and probed; StateFingerprint is recorded as not-a-rendering, with the reason — it keeps no byte of its input, no read door publishes it and no write door consumes it, so putting a per-value hash into MaskMarkers would be meaningless. Live re-run across seven sinks (three log files, stdout, GET /api/v1/servers and both GET /api/v1/servers/{id}/logs payloads): 0 occurrences of all five planted secrets, while `--api-key`, `--max-tokens 4096`, `--public-key-path /etc/ssl/pub.pem`, the SLACK_TOKEN key name, the upstream host and "connection refused" all survive. --- internal/oauth/logging.go | 7 +++ .../oauth/round8_renderer_discovery_test.go | 9 +++ .../upstream/core/child_output_redact_test.go | 58 +++++++++++++++++++ internal/upstream/core/connection.go | 11 +++- internal/upstream/core/monitoring.go | 11 ++++ 5 files changed, 95 insertions(+), 1 deletion(-) diff --git a/internal/oauth/logging.go b/internal/oauth/logging.go index 13e2fca72..552ea9063 100644 --- a/internal/oauth/logging.go +++ b/internal/oauth/logging.go @@ -1106,6 +1106,13 @@ func LogSafeCallbackQuery(rawQuery string) string { if rawQuery == "" { return rawQuery } + if !strings.Contains(rawQuery, "=") { + // Not a `k=v` query: a bare token, or something that is not a query + // string at all. ParseQuery would turn it into `=`, which + // is a rewrite that says nothing; the free-form rule is the honest + // answer for a string with no parameter names to judge it by. + return ScrubUpstreamText(rawQuery) + } values, err := url.ParseQuery(rawQuery) if err != nil { // Unparseable: fall back to the free-form rule rather than publishing diff --git a/internal/oauth/round8_renderer_discovery_test.go b/internal/oauth/round8_renderer_discovery_test.go index 3f3385924..55ec76722 100644 --- a/internal/oauth/round8_renderer_discovery_test.go +++ b/internal/oauth/round8_renderer_discovery_test.go @@ -44,6 +44,10 @@ var exportedStringFuncs = map[string]func(string) string{ "RedactURLQueryParams": RedactURLQueryParams, "ScrubUpstreamText": ScrubUpstreamText, "ArgvFlagKey": ArgvFlagKey, + // Issue #1158, review round 2. Both emit masks, so the fail-closed net has + // to know their markers even though no write door echoes them back. + "LogSafeURL": LogSafeURL, + "LogSafeCallbackQuery": LogSafeCallbackQuery, } // Round 9 finding 5. Discovery covered PACKAGE-LEVEL functions only, and the @@ -115,6 +119,11 @@ var redactionMethodRenderers = map[string][]func(string) string{ var notMaskRenderings = map[string]string{ "ExtractResourceMetadataURL": "parses a WWW-Authenticate header and returns the resource-metadata URL it advertises; " + "it extracts, it does not mask, and its output never reaches a write door as an echoed value", + "StateFingerprint": "not a RENDERING of its input at all: it is a one-way truncated SHA-256 that keeps " + + "no byte of the OAuth state nonce, and it exists only to correlate log LINES with each other. " + + "No read door publishes it and no write door consumes it, so there is nothing for the " + + "fail-closed net to recognise — binding it would put a per-value hash into MaskMarkers, which " + + "is meaningless. (Issue #1158, review round 2.)", "Redaction.CapString": "a property of the DESTINATION, not a rule: it caps a leaf for a PERSISTED surface " + "(the activity store) and introduces no mask of its own. The live read policies set no limit precisely " + "so a masked value is never truncated below what the write path can recognise, which is why binding it " + diff --git a/internal/upstream/core/child_output_redact_test.go b/internal/upstream/core/child_output_redact_test.go index 381382484..8ce613f77 100644 --- a/internal/upstream/core/child_output_redact_test.go +++ b/internal/upstream/core/child_output_redact_test.go @@ -1,6 +1,8 @@ package core import ( + "context" + "errors" "strings" "testing" @@ -8,6 +10,8 @@ import ( "github.com/stretchr/testify/require" "go.uber.org/zap" "go.uber.org/zap/zaptest/observer" + + "github.com/smart-mcp-proxy/mcpproxy-go/internal/config" ) // Issue #1158, review round 2, investigation 3. @@ -70,3 +74,57 @@ func TestCappedScrub_ScrubsAndCapsAnUpstreamBody(t *testing.T) { assert.NotContains(t, capped, secret[i:i+8]) } } + +// The stdio stderr PUMP is a different code path from the launcher's +// loggerWriter and feeds three sinks at once: main.log, the per-server log +// (served by GET /api/v1/servers/{id}/logs) and the recent-stderr ring buffer +// that connectStdio splices into the "did not respond to MCP initialize" +// error. A live run proved all three published a token a child printed on +// startup. +func TestMonitorStderr_ScrubsAllThreeSinks(t *testing.T) { + const secret = "sk-live-ARGVSECRET0123456789" + + mainCore, mainLogs := observer.New(zap.DebugLevel) + perServerCore, perServerLogs := observer.New(zap.DebugLevel) + c := &Client{ + config: &config.ServerConfig{Name: "alpha"}, + logger: zap.New(mainCore), + upstreamLogger: zap.New(perServerCore), + } + + c.monitorStderr(context.Background(), + strings.NewReader("starting with token "+secret+"\nlistening on 127.0.0.1:9331\n")) + + for name, logs := range map[string]*observer.ObservedLogs{"main": mainLogs, "per-server": perServerLogs} { + var joined string + for _, entry := range logs.All() { + joined += entry.Message + for k, v := range entry.ContextMap() { + joined += " " + k + "=" + toStr(v) + } + } + assert.NotContains(t, joined, secret, "%s log published the child's own credential", name) + assert.Contains(t, joined, "listening on 127.0.0.1:9331", "%s log lost an ordinary line", name) + } + + snapshot := strings.Join(c.RecentStderrSnapshot(), "\n") + assert.NotContains(t, snapshot, secret, + "the recent-stderr buffer is spliced into a connect error that is logged AND returned over REST") + assert.Contains(t, snapshot, "listening on 127.0.0.1:9331") +} + +// redactURLCredentialsInError is the ONE seam every downstream log site +// inherits — managed.Client, upstream.Manager, the supervisor and the runtime +// all zap.Error the value it returns. It ran the NAME rule only, so a +// credential under an unrecognised query-parameter name reached main.log +// fifteen times in a live run. +func TestRedactURLCredentialsInError_RunsTheValueShapedDetector(t *testing.T) { + const secret = "ghp_aBcDeFgHiJkLmNoPqRsTuVwXyZ0123456789" + err := errors.New(`Post "https://127.0.0.1:19999/mcp?opaque=` + secret + `": connection refused`) + + got := redactURLCredentialsInError(err) + assert.NotContains(t, got.Error(), secret) + assert.Contains(t, got.Error(), "connection refused", + "the connect paths classify on this substring; masking must not eat it") + assert.ErrorIs(t, got, err, "the original must stay reachable through Unwrap") +} diff --git a/internal/upstream/core/connection.go b/internal/upstream/core/connection.go index a7bb0b887..098d78163 100644 --- a/internal/upstream/core/connection.go +++ b/internal/upstream/core/connection.go @@ -142,7 +142,16 @@ func redactURLCredentialsInError(err error) error { if err == nil { return nil } - msg := oauth.RedactSensitiveData(err.Error()) + // #1158 (review round 2, live check): upgraded from RedactSensitiveData to + // ScrubUpstreamText, for the reason logSafeErrorField and its twin in + // internal/transport were upgraded — the NAME rule cannot see a credential + // under an unrecognised query-parameter name. A live run with + // `?opaque=ghp_â€Ļ` in the configured URL still put the token in main.log 15 + // times, because this ONE seam is what every downstream log site inherits: + // managed.Client, upstream.Manager, the supervisor and the runtime all + // zap.Error this value, and none of them can be fixed from here except + // through the string they are handed. + msg := oauth.ScrubUpstreamText(err.Error()) if msg == err.Error() { return err } diff --git a/internal/upstream/core/monitoring.go b/internal/upstream/core/monitoring.go index 3aa69520c..6b5f078f7 100644 --- a/internal/upstream/core/monitoring.go +++ b/internal/upstream/core/monitoring.go @@ -193,6 +193,17 @@ func (c *Client) monitorStderr(ctx context.Context, stderr io.Reader) { continue } + // #1158 (review round 2, live check): this is the child's own + // stderr, and it lands in THREE places from here — main.log, the + // per-server log that GET /api/v1/servers/{id}/logs serves, and the + // recent-stderr ring buffer that connectStdio splices into the + // "did not respond to MCP initialize" error, which is itself + // logged and returned over REST. A live run proved it: a server + // whose startup banner named its own token published that token + // eight times. Scrubbing the line once here covers all three, + // which is the same shape as the launcher's loggerWriter fix. + line = oauth.ScrubUpstreamText(line) + // Log to main logger c.logger.Info("stderr output", zap.String("server", c.config.Name), From ad79d32fed9cf34295b6daa10ee38bcfb099032c Mon Sep 17 00:00:00 2001 From: Algis Dumbris Date: Wed, 2 Sep 2026 14:56:44 +0300 Subject: [PATCH 4/4] test(security): make the spawn-redaction tests host-independent Both failures were POSIX assumptions in tests added by the #1158 round-2 work, and both are Windows-only. internal/oauth: the -c command-line fixtures were built with shellwrap.Shellescape, which switches on runtime.GOOS and emits cmd.exe double-quoting on Windows - so the sanity assertions looked for a POSIX quote and the ' idiom that were never going to be there. The tokenizer under test handles the POSIX form WrapWithUserShell produces, and a Windows core still reads per-server logs and configs a POSIX host wrote, so the fixture must be POSIX-quoted on every host. Added posixShellescape plus TestPosixShellescape_MatchesProduction, which pins it against the real Shellescape on POSIX - keeping the drift protection that building the fixture from production code was there to provide. internal/upstream/launcher: the banner tests spawned /bin/echo, which does not exist on Windows. Argv redaction in the banner is platform-independent, so rather than skipping the way this package's POSIX signal-semantics tests do, the interpreter is chosen per host and the expected command path travels with it. Verified: both packages pass on darwin, and GOOS=windows go vet is clean. --- internal/oauth/spawnargv_round2_test.go | 57 ++++++++++++++++--- .../upstream/launcher/launcher_redact_test.go | 29 +++++++++- 2 files changed, 75 insertions(+), 11 deletions(-) diff --git a/internal/oauth/spawnargv_round2_test.go b/internal/oauth/spawnargv_round2_test.go index 188802921..52943f279 100644 --- a/internal/oauth/spawnargv_round2_test.go +++ b/internal/oauth/spawnargv_round2_test.go @@ -1,6 +1,7 @@ package oauth import ( + "runtime" "strings" "testing" @@ -10,6 +11,44 @@ import ( "github.com/smart-mcp-proxy/mcpproxy-go/internal/shellwrap" ) +// posixShellescape mirrors the POSIX branch of shellwrap.Shellescape. +// +// The fixtures below must be POSIX-quoted on EVERY host, not just on POSIX +// ones. shellwrap.Shellescape switches on runtime.GOOS and emits cmd.exe +// double-quoting on Windows, so building the fixture with it directly made +// these tests assert Windows quoting against a tokenizer whose whole job is the +// POSIX `-c ""` form that WrapWithUserShell produces. That is not +// a Windows-only code path from the reader's side: a Windows core reads +// per-server logs and configs that a POSIX host wrote, and the masker must +// still cover them. +// +// TestPosixShellescape_MatchesProduction below pins this against the real +// implementation on POSIX, so the copy cannot drift from the quoting the +// product actually emits — which is what building the fixture from +// shellwrap.Shellescape was protecting in the first place. +func posixShellescape(s string) string { + if s == "" { + return "''" + } + if !strings.ContainsAny(s, " \t\n\r\"'\\$`;&|<>(){}[]?*~") { + return s + } + return "'" + strings.ReplaceAll(s, "'", "'\"'\"'") + "'" +} + +func TestPosixShellescape_MatchesProduction(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("shellwrap.Shellescape emits cmd.exe quoting here; the POSIX equivalence cannot be checked") + } + for _, in := range []string{ + "", "plain", "SUPERSECRET PASSPHRASE WITH SPACES", "pass'word with spaces", + `double"quote`, "semi;colon", "tilde~expand", + } { + assert.Equal(t, shellwrap.Shellescape(in), posixShellescape(in), + "the test's POSIX escaper has drifted from shellwrap.Shellescape for %q", in) + } +} + // Issue #1158, review round 2, finding B4. // // The spawn rule's command-STRING tokenizer split on whitespace only, while the @@ -22,15 +61,17 @@ import ( func TestSpawnArgv_MasksAWhitespaceBearingSecretInTheDashCForm(t *testing.T) { const secret = "SUPERSECRET PASSPHRASE WITH SPACES" - // Built the way the product builds it, not by hand: Shellescape decides the - // quoting, so the test cannot drift from the real shape. + // Built the way the product builds it on a POSIX host, not by hand: the + // escaper decides the quoting, and TestPosixShellescape_MatchesProduction + // pins it against shellwrap.Shellescape, so the test cannot drift from the + // real shape. commandLine := strings.Join([]string{ - shellwrap.Shellescape("npx"), - shellwrap.Shellescape("some-mcp"), - shellwrap.Shellescape("--api-key"), - shellwrap.Shellescape(secret), + posixShellescape("npx"), + posixShellescape("some-mcp"), + posixShellescape("--api-key"), + posixShellescape(secret), }, " ") - require.Contains(t, commandLine, "'", "sanity: Shellescape must have quoted the spaced value") + require.Contains(t, commandLine, "'", "sanity: the spaced value must be quoted") for name, got := range map[string]string{ "SpawnCommandString": AuditRedaction.SpawnCommandString(commandLine), @@ -51,7 +92,7 @@ func TestSpawnArgv_MasksAWhitespaceBearingSecretInTheDashCForm(t *testing.T) { // the tokenizer into ending the quoted run early. func TestSpawnCommandString_HandlesTheEmbeddedQuoteIdiom(t *testing.T) { const secret = "pass'word with spaces" - commandLine := "npx some-mcp --api-key " + shellwrap.Shellescape(secret) + commandLine := "npx some-mcp --api-key " + posixShellescape(secret) require.Contains(t, commandLine, `'"'"'`, "sanity: this is the idiom under test") got := AuditRedaction.SpawnCommandString(commandLine) diff --git a/internal/upstream/launcher/launcher_redact_test.go b/internal/upstream/launcher/launcher_redact_test.go index 037a4cc94..e5b260b70 100644 --- a/internal/upstream/launcher/launcher_redact_test.go +++ b/internal/upstream/launcher/launcher_redact_test.go @@ -3,7 +3,9 @@ package launcher import ( "bytes" "context" + "os" "os/exec" + "runtime" "strings" "sync" "testing" @@ -14,6 +16,25 @@ import ( "go.uber.org/zap" ) +// echoWithSecret returns a harmless, short-lived process carrying the secret in +// its argv, plus the command path the banner is expected to keep as its +// diagnostic. +// +// What is under test here is argv redaction in the spawn banner, which is +// platform-independent — so this must run on Windows too rather than being +// skipped the way the POSIX signal-semantics tests in this package are. +// /bin/echo does not exist there, so the interpreter is chosen per host. +func echoWithSecret(secret string) (cmd *exec.Cmd, wantPath string) { + if runtime.GOOS == "windows" { + comspec := os.Getenv("COMSPEC") + if comspec == "" { + comspec = "cmd.exe" + } + return exec.Command(comspec, "/c", "echo", "--api-key", secret), comspec + } + return exec.Command("/bin/echo", "--api-key", secret), "/bin/echo" +} + // syncBuf is a race-free sink: Spawn's banner and the two pump goroutines all // write to it. type syncBuf struct { @@ -44,8 +65,9 @@ func TestSpawnBanner_OmitsArgvWithoutARedactor(t *testing.T) { const secret = "SUPERSECRETBETAARGVVALUE" sink := &syncBuf{} + cmd, wantPath := echoWithSecret(secret) spec := &Spec{ - Cmd: exec.Command("/bin/echo", "--api-key", secret), + Cmd: cmd, LogSink: sink, Name: "no-redactor", // RedactArgs deliberately unset. @@ -59,7 +81,7 @@ func TestSpawnBanner_OmitsArgvWithoutARedactor(t *testing.T) { banner := bannerLine(t, out) assert.NotContains(t, banner, secret, "a nil redactor must not publish argv: %s", banner) - assert.Contains(t, banner, "/bin/echo", + assert.Contains(t, banner, wantPath, "the command path is the diagnostic that must survive") assert.Contains(t, banner, "redacted") } @@ -70,8 +92,9 @@ func TestSpawnBanner_UsesTheSuppliedRedactor(t *testing.T) { const secret = "SUPERSECRETBETAARGVVALUE" sink := &syncBuf{} + cmd, _ := echoWithSecret(secret) spec := &Spec{ - Cmd: exec.Command("/bin/echo", "--api-key", secret), + Cmd: cmd, LogSink: sink, Name: "with-redactor", RedactArgs: func(args []string) []string {