From dfca95fdc16f1a62693c3de7435e54301cb187da Mon Sep 17 00:00:00 2001 From: Arnau Giralt Date: Thu, 12 Mar 2026 16:45:22 +0100 Subject: [PATCH 1/9] refactor(proxy): extract fast/slow path helpers from injectCredentials - Extract applyFastPathCredentials helper (moves fast path block out of injectCredentials, keeping the context enrichment chain intact) - Modify detectSlowPathInjections to return injected header count alongside the modified request (count will be used for DEBUG logging in next commit) - Add sanitizeURL helper that strips query, fragment, and userinfo to prevent token leakage in DEBUG log output - Add extractHost helper to observability package for parsing target host from raw URL strings in request logger No behavior change. Prep for upcoming log enrichment phases. Co-Authored-By: Claude Sonnet 4.6 --- internal/observability/request_logger.go | 11 +++ internal/observability/request_logger_test.go | 53 +++++++++++++++ internal/proxy/server.go | 67 ++++++++++++------- internal/proxy/server_helpers_test.go | 59 ++++++++++++++++ 4 files changed, 167 insertions(+), 23 deletions(-) create mode 100644 internal/proxy/server_helpers_test.go diff --git a/internal/observability/request_logger.go b/internal/observability/request_logger.go index 7f6044e..8de2af9 100644 --- a/internal/observability/request_logger.go +++ b/internal/observability/request_logger.go @@ -6,6 +6,7 @@ package observability import ( "log/slog" "net/http" + "net/url" "strings" "time" ) @@ -130,6 +131,16 @@ func RequestLoggerMiddleware(logger *slog.Logger, vendorHeader string, next http }) } +// extractHost parses rawURL and returns only the host (with port if present). +// Returns an empty string if the URL is invalid or has no host. +func extractHost(rawURL string) string { + u, err := url.Parse(rawURL) + if err != nil || u.Host == "" { + return "" + } + return u.Host +} + // ClientIP extracts the client IP from proxy headers only. // Returns the first IP from X-Forwarded-For, or X-Real-IP as fallback. // Returns "" when no proxy headers are present — in that case the diff --git a/internal/observability/request_logger_test.go b/internal/observability/request_logger_test.go index 13f5706..b09a20d 100644 --- a/internal/observability/request_logger_test.go +++ b/internal/observability/request_logger_test.go @@ -310,6 +310,59 @@ func TestRequestLoggerMiddleware_TraceIDGenerated(t *testing.T) { } } +func TestExtractHost(t *testing.T) { + tests := []struct { + name string + input string + want string + }{ + { + name: "full URL with path", + input: "https://api.vendor.com/v1/users", + want: "api.vendor.com", + }, + { + name: "URL with port", + input: "https://api.vendor.com:8443/v1", + want: "api.vendor.com:8443", + }, + { + name: "URL with query string", + input: "https://api.vendor.com/v1?key=secret", + want: "api.vendor.com", + }, + { + name: "URL without path", + input: "https://api.vendor.com", + want: "api.vendor.com", + }, + { + name: "empty URL returns empty", + input: "", + want: "", + }, + { + name: "invalid URL returns empty", + input: "://invalid", + want: "", + }, + { + name: "path-only URL returns empty", + input: "/just/a/path", + want: "", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got := extractHost(tt.input) + if got != tt.want { + t.Errorf("extractHost(%q) = %q, want %q", tt.input, got, tt.want) + } + }) + } +} + // panicRecoveryForTest wraps a handler with basic panic recovery for testing. func panicRecoveryForTest(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { diff --git a/internal/proxy/server.go b/internal/proxy/server.go index ce3105e..5f7c04a 100644 --- a/internal/proxy/server.go +++ b/internal/proxy/server.go @@ -571,27 +571,9 @@ func (s *Server) injectCredentials(r *http.Request, txCtx *sdk.TransactionContex return nil, err } - // Fast Path: plugin returned headers to inject + // Fast Path: plugin returned headers to inject. if cred != nil { - reqCtx := r.Context() - injectedKeys := make([]string, 0, len(cred.Headers)) - for k, v := range cred.Headers { - r.Header.Set(k, v) - injectedKeys = append(injectedKeys, k) - // Store each credential value in context for value-based log redaction. - // The RedactingHandler will scan all slog string attrs and messages - // for these values. Short values (< MinSecretLength) are automatically - // skipped by the handler to avoid false positives. - reqCtx = observability.WithSecretValue(reqCtx, v) - } - // Store injected header keys so the Reflector can strip them from - // responses (prevents credential reflection for non-standard headers). - reqCtx = security.WithInjectedHeaders(reqCtx, injectedKeys) - // Propagate enriched context to the returned request. The reverse proxy - // will Clone this request, so resp.Request.Context() in ModifyResponse - // will carry the secret values and injected header keys. - r = r.WithContext(reqCtx) - return r, nil + return s.applyFastPathCredentials(r, cred), nil } // Slow Path: plugin mutated the request directly (cred is nil). @@ -599,10 +581,35 @@ func (s *Server) injectCredentials(r *http.Request, txCtx *sdk.TransactionContex // against our pre-call snapshot. This ensures log redaction and response // stripping work even if the plugin doesn't call WithSecretValue() or // WithInjectedHeaders() itself. - r = s.detectSlowPathInjections(r, headersBefore) + r, _ = s.detectSlowPathInjections(r, headersBefore) return r, nil } +// applyFastPathCredentials injects the credential headers into the request and +// enriches the context with secret values and injected header keys. +// All operations must happen together to maintain the context enrichment chain: +// header injection → value-based redaction → response-stripping keys → context propagation. +func (s *Server) applyFastPathCredentials(r *http.Request, cred *sdk.Credential) *http.Request { + reqCtx := r.Context() + injectedKeys := make([]string, 0, len(cred.Headers)) + for k, v := range cred.Headers { + r.Header.Set(k, v) + injectedKeys = append(injectedKeys, k) + // Store each credential value in context for value-based log redaction. + // The RedactingHandler will scan all slog string attrs and messages + // for these values. Short values (< MinSecretLength) are automatically + // skipped by the handler to avoid false positives. + reqCtx = observability.WithSecretValue(reqCtx, v) + } + // Store injected header keys so the Reflector can strip them from + // responses (prevents credential reflection for non-standard headers). + reqCtx = security.WithInjectedHeaders(reqCtx, injectedKeys) + // Propagate enriched context. The reverse proxy will Clone this request, + // so resp.Request.Context() in ModifyResponse carries the secret values + // and injected header keys. + return r.WithContext(reqCtx) +} + // detectSlowPathInjections compares the current request headers against // a pre-plugin snapshot to discover what a Slow Path plugin injected. // Any new or modified headers are treated as injected credentials: @@ -612,7 +619,7 @@ func (s *Server) injectCredentials(r *http.Request, txCtx *sdk.TransactionContex // This is a safety net — Slow Path plugins MAY still call // observability.WithSecretValue() and security.WithInjectedHeaders() // for finer control, but forgetting to do so is no longer a security gap. -func (s *Server) detectSlowPathInjections(r *http.Request, before http.Header) *http.Request { +func (s *Server) detectSlowPathInjections(r *http.Request, before http.Header) (*http.Request, int) { var injectedKeys []string reqCtx := r.Context() @@ -631,7 +638,21 @@ func (s *Server) detectSlowPathInjections(r *http.Request, before http.Header) * r = r.WithContext(reqCtx) } - return r + return r, len(injectedKeys) +} + +// sanitizeURL strips the query string, fragment, and userinfo from a URL +// to prevent token or credential leakage in log output. +// Returns an empty string if the input is not a valid URL. +func sanitizeURL(rawURL string) string { + u, err := url.Parse(rawURL) + if err != nil { + return "" + } + u.RawQuery = "" + u.Fragment = "" + u.User = nil + return u.String() } // headerValuesEqual returns true if two header value slices are identical. diff --git a/internal/proxy/server_helpers_test.go b/internal/proxy/server_helpers_test.go new file mode 100644 index 0000000..98d415d --- /dev/null +++ b/internal/proxy/server_helpers_test.go @@ -0,0 +1,59 @@ +// Copyright 2026 CloudBlue LLC +// SPDX-License-Identifier: Apache-2.0 + +package proxy + +import "testing" + +func TestSanitizeURL(t *testing.T) { + tests := []struct { + name string + input string + want string + }{ + { + name: "strips query string", + input: "https://api.vendor.com/v1?api_key=secret", + want: "https://api.vendor.com/v1", + }, + { + name: "strips fragment", + input: "https://api.vendor.com/v1#section", + want: "https://api.vendor.com/v1", + }, + { + name: "strips userinfo", + input: "https://user:pass@api.vendor.com/v1", + want: "https://api.vendor.com/v1", + }, + { + name: "preserves path", + input: "https://api.vendor.com/v1/users/123", + want: "https://api.vendor.com/v1/users/123", + }, + { + name: "strips all sensitive parts together", + input: "https://user:pass@api.vendor.com/v1?token=abc#frag", + want: "https://api.vendor.com/v1", + }, + { + name: "invalid URL returns empty", + input: "://invalid", + want: "", + }, + { + name: "empty URL returns empty", + input: "", + want: "", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got := sanitizeURL(tt.input) + if got != tt.want { + t.Errorf("sanitizeURL(%q) = %q, want %q", tt.input, got, tt.want) + } + }) + } +} From b0760546c281284b80cac847f761ceeb5bd089a1 Mon Sep 17 00:00:00 2001 From: Arnau Giralt Date: Thu, 12 Mar 2026 16:46:59 +0100 Subject: [PATCH 2/9] feat(proxy): add DEBUG logging for credential injection Add per-request DEBUG logpoints in injectCredentials so Distributors can trace exactly which caching path was taken and how long the plugin ran. - Change injectCredentials signature to accept targetHost string (reuses the already-parsed *url.URL.Host from handleProxy, avoids re-parsing) - Log "credentials injected" at DEBUG after Fast Path with: trace_id, vendor_id, marketplace_id, target_host, credential_path="fast", injected_header_count, plugin_duration_ms - Log "credentials injected" at DEBUG after Slow Path detection with credential_path="slow" and detected injected_header_count - Add integration tests capturing DEBUG output to verify both paths Co-Authored-By: Claude Sonnet 4.6 --- internal/proxy/integration_test.go | 115 +++++++++++++++++++++++++++++ internal/proxy/server.go | 31 +++++++- 2 files changed, 142 insertions(+), 4 deletions(-) diff --git a/internal/proxy/integration_test.go b/internal/proxy/integration_test.go index 1e6039a..b35808a 100644 --- a/internal/proxy/integration_test.go +++ b/internal/proxy/integration_test.go @@ -4,6 +4,7 @@ package proxy_test import ( + "bytes" "context" "errors" "fmt" @@ -1909,3 +1910,117 @@ func TestIntegration_NonContextHeaders_PreservedOnForwarding(t *testing.T) { t.Errorf("Accept = %q, want %q", receivedAccept, "application/json") } } + +// ============================================================================= +// Phase 2: DEBUG logging for credential injection +// ============================================================================= + +func TestIntegration_FastPath_LogsCredentialInjection(t *testing.T) { + // Arrange - capture DEBUG log output + var logBuffer bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&logBuffer, &slog.HandlerOptions{Level: slog.LevelDebug})) + originalLogger := slog.Default() + slog.SetDefault(logger) + defer slog.SetDefault(originalLogger) + + backend := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + })) + defer backend.Close() + + plugin := &mockPlugin{ + getCredentialsFn: func(_ context.Context, _ sdk.TransactionContext, _ *http.Request) (*sdk.Credential, error) { + return &sdk.Credential{ + Headers: map[string]string{"Authorization": "Bearer test-token"}, + ExpiresAt: time.Now().Add(1 * time.Hour), + }, nil + }, + } + + cfg := testConfig() + cfg.Plugin = plugin + srv := mustNewServerForTarget(t, cfg, backend.URL) + handler := srv.Handler() + + req := httptest.NewRequest(http.MethodGet, "/proxy", nil) + req.Header.Set("X-Connect-Target-URL", backend.URL) + req.Header.Set("X-Connect-Vendor-ID", "VA-test") + req.Header.Set("X-Connect-Marketplace-ID", "MP-test") + rec := httptest.NewRecorder() + + // Act + handler.ServeHTTP(rec, req) + + if rec.Code != http.StatusOK { + t.Fatalf("status = %d, want %d", rec.Code, http.StatusOK) + } + + // Assert - "credentials injected" DEBUG log with Fast Path fields + logOutput := logBuffer.String() + if !strings.Contains(logOutput, `"msg":"credentials injected"`) { + t.Errorf("expected credentials injected log, got: %s", logOutput) + } + if !strings.Contains(logOutput, `"credential_path":"fast"`) { + t.Errorf("expected credential_path=fast in log, got: %s", logOutput) + } + if !strings.Contains(logOutput, `"injected_header_count":1`) { + t.Errorf("expected injected_header_count=1 in log, got: %s", logOutput) + } + if !strings.Contains(logOutput, `"vendor_id":"VA-test"`) { + t.Errorf("expected vendor_id in log, got: %s", logOutput) + } + if !strings.Contains(logOutput, `"plugin_duration_ms"`) { + t.Errorf("expected plugin_duration_ms in log, got: %s", logOutput) + } +} + +func TestIntegration_SlowPath_LogsCredentialInjection(t *testing.T) { + // Arrange - capture DEBUG log output + var logBuffer bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&logBuffer, &slog.HandlerOptions{Level: slog.LevelDebug})) + originalLogger := slog.Default() + slog.SetDefault(logger) + defer slog.SetDefault(originalLogger) + + backend := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + })) + defer backend.Close() + + // Slow path: plugin mutates request directly and returns nil credential + plugin := &mockPlugin{ + getCredentialsFn: func(_ context.Context, _ sdk.TransactionContext, req *http.Request) (*sdk.Credential, error) { + req.Header.Set("Authorization", "Bearer slow-token") + return nil, nil + }, + } + + cfg := testConfig() + cfg.Plugin = plugin + srv := mustNewServerForTarget(t, cfg, backend.URL) + handler := srv.Handler() + + req := httptest.NewRequest(http.MethodGet, "/proxy", nil) + req.Header.Set("X-Connect-Target-URL", backend.URL) + req.Header.Set("X-Connect-Vendor-ID", "VA-slow") + rec := httptest.NewRecorder() + + // Act + handler.ServeHTTP(rec, req) + + if rec.Code != http.StatusOK { + t.Fatalf("status = %d, want %d", rec.Code, http.StatusOK) + } + + // Assert - "credentials injected" DEBUG log with Slow Path fields + logOutput := logBuffer.String() + if !strings.Contains(logOutput, `"msg":"credentials injected"`) { + t.Errorf("expected credentials injected log, got: %s", logOutput) + } + if !strings.Contains(logOutput, `"credential_path":"slow"`) { + t.Errorf("expected credential_path=slow in log, got: %s", logOutput) + } + if !strings.Contains(logOutput, `"vendor_id":"VA-slow"`) { + t.Errorf("expected vendor_id in log, got: %s", logOutput) + } +} diff --git a/internal/proxy/server.go b/internal/proxy/server.go index 5f7c04a..0ea64d0 100644 --- a/internal/proxy/server.go +++ b/internal/proxy/server.go @@ -507,7 +507,7 @@ func (s *Server) handleProxy(w http.ResponseWriter, r *http.Request) { ) } - r, err = s.injectCredentials(r, txCtx) + r, err = s.injectCredentials(r, txCtx, targetURL.Host) if err != nil { s.handlePluginError(w, traceID, err) return @@ -535,10 +535,13 @@ func (s *Server) respondBadRequest(w http.ResponseWriter, traceID, msg string, e // RedactingHandler can detect and redact them if they leak into log output // (value-based scanning, Layers 3 & 4). // +// targetHost is the already-parsed host from the target URL, passed from handleProxy +// to avoid re-parsing and to keep the field in DEBUG log output. +// // Returns the (possibly updated) request and any error. The caller MUST use // the returned request for all subsequent operations, because the context may // have been enriched with secret values and injected header keys. -func (s *Server) injectCredentials(r *http.Request, txCtx *sdk.TransactionContext) (*http.Request, error) { +func (s *Server) injectCredentials(r *http.Request, txCtx *sdk.TransactionContext, targetHost string) (*http.Request, error) { if s.config.Plugin == nil { return r, nil } @@ -573,7 +576,17 @@ func (s *Server) injectCredentials(r *http.Request, txCtx *sdk.TransactionContex // Fast Path: plugin returned headers to inject. if cred != nil { - return s.applyFastPathCredentials(r, cred), nil + r = s.applyFastPathCredentials(r, cred) + slog.Debug("credentials injected", + "trace_id", txCtx.TraceID, + "vendor_id", txCtx.VendorID, + "marketplace_id", txCtx.MarketplaceID, + "target_host", targetHost, + "credential_path", "fast", + "injected_header_count", len(cred.Headers), + "plugin_duration_ms", pluginDuration.Milliseconds(), + ) + return r, nil } // Slow Path: plugin mutated the request directly (cred is nil). @@ -581,7 +594,17 @@ func (s *Server) injectCredentials(r *http.Request, txCtx *sdk.TransactionContex // against our pre-call snapshot. This ensures log redaction and response // stripping work even if the plugin doesn't call WithSecretValue() or // WithInjectedHeaders() itself. - r, _ = s.detectSlowPathInjections(r, headersBefore) + var injectedCount int + r, injectedCount = s.detectSlowPathInjections(r, headersBefore) + slog.Debug("credentials injected", + "trace_id", txCtx.TraceID, + "vendor_id", txCtx.VendorID, + "marketplace_id", txCtx.MarketplaceID, + "target_host", targetHost, + "credential_path", "slow", + "injected_header_count", injectedCount, + "plugin_duration_ms", pluginDuration.Milliseconds(), + ) return r, nil } From f84afcc34537b03ba9391968c2d49d4f6e2eca38 Mon Sep 17 00:00:00 2001 From: Arnau Giralt Date: Thu, 12 Mar 2026 16:48:04 +0100 Subject: [PATCH 3/9] fix(proxy): write status 499 on client disconnect MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When the plugin returns context.Canceled (client disconnected before the plugin could fetch credentials), the proxy previously returned without writing a status code. This caused RequestLoggerMiddleware to log the request as status 200 (the ResponseCapturer default), which is misleading. Now writes w.WriteHeader(499) — the nginx convention for client-closed connections — so the logged status accurately reflects what happened. No body is written since the client is already gone. Export StatusClientClosedRequest constant so tests can reference it symbolically rather than hardcoding 499. Co-Authored-By: Claude Sonnet 4.6 --- internal/proxy/integration_test.go | 57 +++++++++++++++++++++++++----- internal/proxy/server.go | 8 ++++- 2 files changed, 55 insertions(+), 10 deletions(-) diff --git a/internal/proxy/integration_test.go b/internal/proxy/integration_test.go index b35808a..13e6399 100644 --- a/internal/proxy/integration_test.go +++ b/internal/proxy/integration_test.go @@ -428,11 +428,10 @@ func TestIntegration_BackendUnreachable_Returns502(t *testing.T) { } } -func TestIntegration_PluginContextCanceled_NoResponse(t *testing.T) { - // Arrange - plugin that checks for context cancellation +func TestIntegration_PluginContextCanceled_Returns499(t *testing.T) { + // Arrange - plugin that simulates client disconnect plugin := &mockPlugin{ - getCredentialsFn: func(ctx context.Context, tx sdk.TransactionContext, req *http.Request) (*sdk.Credential, error) { - // Simulate context being cancelled (client disconnected) + getCredentialsFn: func(_ context.Context, _ sdk.TransactionContext, _ *http.Request) (*sdk.Credential, error) { return nil, context.Canceled }, } @@ -450,11 +449,9 @@ func TestIntegration_PluginContextCanceled_NoResponse(t *testing.T) { // Act handler.ServeHTTP(rec, req) - // Assert - when context is canceled, we don't write a response (or write minimal) - // The important thing is we don't crash and don't return 500 - // In practice, client won't see this response since they disconnected - if rec.Code == http.StatusInternalServerError { - t.Error("context.Canceled should not return 500") + // Assert - 499 Client Closed Request (nginx convention for client disconnect) + if rec.Code != proxy.StatusClientClosedRequest { + t.Errorf("status = %d, want %d (StatusClientClosedRequest)", rec.Code, proxy.StatusClientClosedRequest) } } @@ -2024,3 +2021,45 @@ func TestIntegration_SlowPath_LogsCredentialInjection(t *testing.T) { t.Errorf("expected vendor_id in log, got: %s", logOutput) } } + +// ============================================================================= +// Phase 3: Status 499 on client disconnect +// ============================================================================= + +func TestIntegration_ClientDisconnect_LogsStatus499(t *testing.T) { + // Arrange - capture log output + var logBuffer bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&logBuffer, nil)) + originalLogger := slog.Default() + slog.SetDefault(logger) + defer slog.SetDefault(originalLogger) + + plugin := &mockPlugin{ + getCredentialsFn: func(_ context.Context, _ sdk.TransactionContext, _ *http.Request) (*sdk.Credential, error) { + return nil, context.Canceled + }, + } + + cfg := testConfig() + cfg.Plugin = plugin + srv := mustNewServer(t, cfg) + handler := srv.Handler() + + req := httptest.NewRequest(http.MethodPost, "/proxy", nil) + req.Header.Set("X-Connect-Target-URL", "http://example.com") + req.Header.Set("X-Connect-Vendor-ID", "VA-disconnect") + req.Header.Set("Connect-Request-ID", "trace-499-test") + rec := httptest.NewRecorder() + + // Act + handler.ServeHTTP(rec, req) + + // Assert - RequestLoggerMiddleware logs status 499 (not the default 200) + if rec.Code != proxy.StatusClientClosedRequest { + t.Errorf("response status = %d, want %d", rec.Code, proxy.StatusClientClosedRequest) + } + logOutput := logBuffer.String() + if !strings.Contains(logOutput, `"status":499`) { + t.Errorf("log should contain status 499, got: %s", logOutput) + } +} diff --git a/internal/proxy/server.go b/internal/proxy/server.go index 0ea64d0..19b40e0 100644 --- a/internal/proxy/server.go +++ b/internal/proxy/server.go @@ -710,6 +710,10 @@ func (s *Server) forwardRequest(w http.ResponseWriter, r *http.Request, target * proxy.ServeHTTP(w, r) // #nosec G704 -- target validated against allow-list in handleProxy before reaching here } +// StatusClientClosedRequest is a non-standard status code (nginx convention) +// used when the client disconnects before receiving a response. +const StatusClientClosedRequest = 499 + // handlePluginError handles errors from the plugin. func (s *Server) handlePluginError(w http.ResponseWriter, traceID string, err error) { // Check for context errors (timeout/cancellation) @@ -723,10 +727,12 @@ func (s *Server) handlePluginError(w http.ResponseWriter, traceID string, err er } if errors.Is(err, context.Canceled) { - // Client disconnected - don't write response slog.Info("client disconnected", "trace_id", traceID, ) + // Write 499 so RequestLoggerMiddleware logs the correct status instead of + // the default 200. Do NOT write a body — the client is already gone. + w.WriteHeader(StatusClientClosedRequest) return } From af4d9c5e68a401e77fbc3d1e553341386ca20658 Mon Sep 17 00:00:00 2001 From: Arnau Giralt Date: Thu, 12 Mar 2026 16:49:10 +0100 Subject: [PATCH 4/9] feat(proxy): enrich existing logs with transaction context Add vendor_id, marketplace_id, and target_host to all INFO/WARN/ERROR logs that were previously missing these fields, making it possible to correlate log events with specific vendors and targets without cross-referencing the "request completed" line. - "upstream response": +vendor_id, +marketplace_id, +target_host - "plugin error" / "plugin timeout" / "client disconnected": change handlePluginError signature to accept txCtx and targetHost, add all three fields to each log line - "proxy error": +vendor_id, +marketplace_id, +target_host - "plugin ModifyResponse error": +vendor_id, +marketplace_id, +target_host - "error normalization failed": +vendor_id, +marketplace_id, +target_host Co-Authored-By: Claude Sonnet 4.6 --- internal/proxy/server.go | 38 ++++++++++++++++++++++++++++++++------ 1 file changed, 32 insertions(+), 6 deletions(-) diff --git a/internal/proxy/server.go b/internal/proxy/server.go index 19b40e0..467f648 100644 --- a/internal/proxy/server.go +++ b/internal/proxy/server.go @@ -509,7 +509,7 @@ func (s *Server) handleProxy(w http.ResponseWriter, r *http.Request) { r, err = s.injectCredentials(r, txCtx, targetURL.Host) if err != nil { - s.handlePluginError(w, traceID, err) + s.handlePluginError(w, traceID, txCtx, targetURL.Host, err) return } @@ -715,11 +715,13 @@ func (s *Server) forwardRequest(w http.ResponseWriter, r *http.Request, target * const StatusClientClosedRequest = 499 // handlePluginError handles errors from the plugin. -func (s *Server) handlePluginError(w http.ResponseWriter, traceID string, err error) { - // Check for context errors (timeout/cancellation) +func (s *Server) handlePluginError(w http.ResponseWriter, traceID string, txCtx *sdk.TransactionContext, targetHost string, err error) { if errors.Is(err, context.DeadlineExceeded) { slog.Error("plugin timeout", "trace_id", traceID, + "vendor_id", txCtx.VendorID, + "marketplace_id", txCtx.MarketplaceID, + "target_host", targetHost, "error", err, ) http.Error(w, "Gateway Timeout", http.StatusGatewayTimeout) @@ -729,6 +731,9 @@ func (s *Server) handlePluginError(w http.ResponseWriter, traceID string, err er if errors.Is(err, context.Canceled) { slog.Info("client disconnected", "trace_id", traceID, + "vendor_id", txCtx.VendorID, + "marketplace_id", txCtx.MarketplaceID, + "target_host", targetHost, ) // Write 499 so RequestLoggerMiddleware logs the correct status instead of // the default 200. Do NOT write a body — the client is already gone. @@ -736,9 +741,11 @@ func (s *Server) handlePluginError(w http.ResponseWriter, traceID string, err er return } - // Generic plugin error slog.Error("plugin error", "trace_id", traceID, + "vendor_id", txCtx.VendorID, + "marketplace_id", txCtx.MarketplaceID, + "target_host", targetHost, "error", err, ) http.Error(w, "Internal Server Error", http.StatusInternalServerError) @@ -809,6 +816,9 @@ func (s *Server) createReverseProxy(target *url.URL, traceID string, txCtx *sdk. slog.Error("proxy error", "trace_id", traceID, + "vendor_id", txCtx.VendorID, + "marketplace_id", txCtx.MarketplaceID, + "target_host", target.Host, "error", err, ) http.Error(w, "Bad Gateway", http.StatusBadGateway) @@ -849,7 +859,13 @@ func (s *Server) buildModifyResponse(traceID string, txCtx *sdk.TransactionConte var err error action, err = s.config.Plugin.ModifyResponse(ctx, *txCtx, resp) if err != nil { - slog.Warn("plugin ModifyResponse error", "trace_id", traceID, "error", err) + slog.Warn("plugin ModifyResponse error", + "trace_id", traceID, + "vendor_id", txCtx.VendorID, + "marketplace_id", txCtx.MarketplaceID, + "target_host", resp.Request.URL.Host, + "error", err, + ) // Continue with response processing even if plugin fails } } @@ -868,13 +884,23 @@ func (s *Server) buildModifyResponse(traceID string, txCtx *sdk.TransactionConte if err := security.NormalizeError(resp, traceID); err != nil { slog.Error("error normalization failed", "trace_id", traceID, + "vendor_id", txCtx.VendorID, + "marketplace_id", txCtx.MarketplaceID, + "target_host", resp.Request.URL.Host, "error", err, ) // Continue even if normalization fails - response will be sent as-is } } - slog.Info("upstream response", "trace_id", traceID, "status", resp.StatusCode, "content_length", resp.ContentLength) + slog.Info("upstream response", + "trace_id", traceID, + "status", resp.StatusCode, + "content_length", resp.ContentLength, + "vendor_id", txCtx.VendorID, + "marketplace_id", txCtx.MarketplaceID, + "target_host", resp.Request.URL.Host, + ) return nil } } From e51a1d614517fa828c978e961fa30c8095fdc7d2 Mon Sep 17 00:00:00 2001 From: Arnau Giralt Date: Thu, 12 Mar 2026 16:56:14 +0100 Subject: [PATCH 5/9] feat(observability): add transaction context to request logger Change RequestLoggerMiddleware signature from vendorHeader string to headerPrefix string. The middleware now constructs header names internally using the stable suffix constants, enabling it to extract four context fields per request instead of one. New fields added to every "request completed" log line: - marketplace_id (from -Marketplace-ID) - product_id (from -Product-ID) - target_host (host-only, extracted from -Target-URL) The target_host field re-parses the URL in the deferred log closure. This is the one accepted re-parse in the codebase: middleware ordering prevents reusing the URL parsed in handleProxy (~200ns, negligible vs network RTT). Update all call sites (server.go, server_test.go, middleware_bench_test.go, request_logger_test.go) to pass the prefix string instead of a header name. Co-Authored-By: Claude Sonnet 4.6 --- internal/observability/request_logger.go | 17 ++-- internal/observability/request_logger_test.go | 79 ++++++++++++++----- internal/proxy/middleware_bench_test.go | 6 +- internal/proxy/server.go | 2 +- internal/proxy/server_test.go | 4 +- 5 files changed, 78 insertions(+), 30 deletions(-) diff --git a/internal/observability/request_logger.go b/internal/observability/request_logger.go index 8de2af9..309e4ca 100644 --- a/internal/observability/request_logger.go +++ b/internal/observability/request_logger.go @@ -84,9 +84,8 @@ func (rc *ResponseCapturer) Status() int { // // Parameters: // - logger: structured logger for output -// - vendorHeader: the full header name for vendor ID (e.g., "X-Connect-Vendor-ID") -// constructed by the caller using the configured prefix, so header name -// derivation stays in one place alongside ParseContext (DRY / ADR-005) +// - headerPrefix: the context header prefix (e.g., "X-Connect"). The middleware +// constructs header names internally using the stable suffix constants. // - next: the downstream handler // // Fields emitted: @@ -95,7 +94,10 @@ func (rc *ResponseCapturer) Status() int { // - path: Request path // - status: Response status code // - latency_ms: Time to process request in milliseconds -// - vendor_id: Vendor ID from the vendorHeader request header +// - vendor_id: Vendor ID from the -Vendor-ID request header +// - marketplace_id: Marketplace ID from the -Marketplace-ID request header +// - product_id: Product ID from the -Product-ID request header +// - target_host: Host extracted from the -Target-URL request header // - client_ip: Client IP from proxy headers (X-Forwarded-For > X-Real-IP); // empty when no proxy headers are present (use remote_addr instead) // - remote_addr: Raw TCP peer address (always r.RemoteAddr, useful for @@ -105,7 +107,7 @@ func (rc *ResponseCapturer) Status() int { // already in the request context when this handler receives the request. // Uses defer to ensure logging occurs even if downstream handlers panic // (when used with panic recovery middleware). -func RequestLoggerMiddleware(logger *slog.Logger, vendorHeader string, next http.Handler) http.Handler { +func RequestLoggerMiddleware(logger *slog.Logger, headerPrefix string, next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { start := time.Now() ctx := r.Context() @@ -121,7 +123,10 @@ func RequestLoggerMiddleware(logger *slog.Logger, vendorHeader string, next http "path", r.URL.Path, "status", capturer.Status(), "latency_ms", time.Since(start).Milliseconds(), - "vendor_id", r.Header.Get(vendorHeader), + "vendor_id", r.Header.Get(headerPrefix+"-Vendor-ID"), + "marketplace_id", r.Header.Get(headerPrefix+"-Marketplace-ID"), + "product_id", r.Header.Get(headerPrefix+"-Product-ID"), + "target_host", extractHost(r.Header.Get(headerPrefix+"-Target-URL")), "client_ip", ClientIP(r), "remote_addr", r.RemoteAddr, ) diff --git a/internal/observability/request_logger_test.go b/internal/observability/request_logger_test.go index b09a20d..9d99e6a 100644 --- a/internal/observability/request_logger_test.go +++ b/internal/observability/request_logger_test.go @@ -9,22 +9,26 @@ import ( "log/slog" "net/http" "net/http/httptest" + "strings" "testing" ) // logEntry represents a parsed JSON log line for test assertions. type logEntry struct { - Time string `json:"time"` - Level string `json:"level"` - Msg string `json:"msg"` - TraceID string `json:"trace_id"` - Method string `json:"method"` - Path string `json:"path"` - Status int `json:"status"` - LatencyMs int64 `json:"latency_ms"` - VendorID string `json:"vendor_id"` - ClientIP string `json:"client_ip"` - RemoteAddr string `json:"remote_addr"` + Time string `json:"time"` + Level string `json:"level"` + Msg string `json:"msg"` + TraceID string `json:"trace_id"` + Method string `json:"method"` + Path string `json:"path"` + Status int `json:"status"` + LatencyMs int64 `json:"latency_ms"` + VendorID string `json:"vendor_id"` + MarketplaceID string `json:"marketplace_id"` + ProductID string `json:"product_id"` + TargetHost string `json:"target_host"` + ClientIP string `json:"client_ip"` + RemoteAddr string `json:"remote_addr"` } // parseLogEntry parses a single JSON log line from the buffer. @@ -130,10 +134,13 @@ func TestRequestLoggerMiddleware_LogsRequestFields(t *testing.T) { w.WriteHeader(http.StatusOK) }) - handler := RequestLoggerMiddleware(logger, "X-Connect-Vendor-ID", inner) + handler := RequestLoggerMiddleware(logger, "X-Connect", inner) r := httptest.NewRequest(http.MethodPost, "/proxy", nil) r = r.WithContext(WithTraceID(r.Context(), "test-trace-123")) r.Header.Set("X-Connect-Vendor-ID", "microsoft") + r.Header.Set("X-Connect-Marketplace-ID", "MP-US") + r.Header.Set("X-Connect-Product-ID", "PRD-001") + r.Header.Set("X-Connect-Target-URL", "https://graph.microsoft.com/v1.0/users") r.RemoteAddr = "10.0.0.1:54321" w := httptest.NewRecorder() @@ -161,6 +168,15 @@ func TestRequestLoggerMiddleware_LogsRequestFields(t *testing.T) { if entry.VendorID != "microsoft" { t.Errorf("vendor_id = %q, want %q", entry.VendorID, "microsoft") } + if entry.MarketplaceID != "MP-US" { + t.Errorf("marketplace_id = %q, want %q", entry.MarketplaceID, "MP-US") + } + if entry.ProductID != "PRD-001" { + t.Errorf("product_id = %q, want %q", entry.ProductID, "PRD-001") + } + if entry.TargetHost != "graph.microsoft.com" { + t.Errorf("target_host = %q, want %q", entry.TargetHost, "graph.microsoft.com") + } if entry.ClientIP != "" { t.Errorf("client_ip = %q, want empty (no proxy headers)", entry.ClientIP) } @@ -177,7 +193,7 @@ func TestRequestLoggerMiddleware_CapturesErrorStatus(t *testing.T) { w.WriteHeader(http.StatusBadGateway) }) - handler := RequestLoggerMiddleware(logger, "X-Connect-Vendor-ID", inner) + handler := RequestLoggerMiddleware(logger, "X-Connect", inner) r := httptest.NewRequest(http.MethodGet, "/proxy", nil) r = r.WithContext(WithTraceID(r.Context(), "err-trace")) w := httptest.NewRecorder() @@ -198,7 +214,7 @@ func TestRequestLoggerMiddleware_NoTraceID_LogsEmpty(t *testing.T) { w.WriteHeader(http.StatusOK) }) - handler := RequestLoggerMiddleware(logger, "X-Connect-Vendor-ID", inner) + handler := RequestLoggerMiddleware(logger, "X-Connect", inner) r := httptest.NewRequest(http.MethodGet, "/proxy", nil) // Deliberately no trace ID in context w := httptest.NewRecorder() @@ -220,7 +236,7 @@ func TestRequestLoggerMiddleware_LogsOnPanic(t *testing.T) { }) // Wrap with panic recovery INSIDE request logger, so logger still fires - handler := RequestLoggerMiddleware(logger, "X-Connect-Vendor-ID", panicRecoveryForTest(panicky)) + handler := RequestLoggerMiddleware(logger, "X-Connect", panicRecoveryForTest(panicky)) r := httptest.NewRequest(http.MethodGet, "/proxy", nil) r = r.WithContext(WithTraceID(r.Context(), "panic-trace")) w := httptest.NewRecorder() @@ -244,7 +260,7 @@ func TestRequestLoggerMiddleware_ClientIPFromXForwardedFor(t *testing.T) { w.WriteHeader(http.StatusOK) }) - handler := RequestLoggerMiddleware(logger, "X-Connect-Vendor-ID", inner) + handler := RequestLoggerMiddleware(logger, "X-Connect", inner) r := httptest.NewRequest(http.MethodGet, "/", nil) r.Header.Set("X-Forwarded-For", "203.0.113.50") w := httptest.NewRecorder() @@ -269,7 +285,7 @@ func TestRequestLoggerMiddleware_TraceIDFromOuterMiddleware(t *testing.T) { }) // Production order: TraceID (outermost) → Logger → handler - handler := RequestLoggerMiddleware(logger, "X-Connect-Vendor-ID", inner) + handler := RequestLoggerMiddleware(logger, "X-Connect", inner) handler = TraceIDMiddleware("X-Trace-ID", handler) r := httptest.NewRequest(http.MethodGet, "/test", nil) @@ -295,7 +311,7 @@ func TestRequestLoggerMiddleware_TraceIDGenerated(t *testing.T) { }) // Production order: TraceID (outermost) → Logger → handler - handler := RequestLoggerMiddleware(logger, "X-Connect-Vendor-ID", inner) + handler := RequestLoggerMiddleware(logger, "X-Connect", inner) handler = TraceIDMiddleware("X-Trace-ID", handler) r := httptest.NewRequest(http.MethodGet, "/test", nil) @@ -310,6 +326,33 @@ func TestRequestLoggerMiddleware_TraceIDGenerated(t *testing.T) { } } +func TestRequestLoggerMiddleware_LogsTargetHost_ExtractsHostOnly(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug})) + + inner := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + }) + + handler := RequestLoggerMiddleware(logger, "X-Connect", inner) + r := httptest.NewRequest(http.MethodGet, "/proxy", nil) + // URL with query string and path — only the host should appear in the log + r.Header.Set("X-Connect-Target-URL", "https://api.vendor.com/v1/users?api_key=secret&token=abc") + w := httptest.NewRecorder() + + handler.ServeHTTP(w, r) + + entry := parseLogEntry(t, buf.Bytes()) + if entry.TargetHost != "api.vendor.com" { + t.Errorf("target_host = %q, want %q (only host, no path/query)", entry.TargetHost, "api.vendor.com") + } + // Verify query params did not leak into any logged field + logOutput := buf.String() + if strings.Contains(logOutput, "api_key") || strings.Contains(logOutput, "secret") { + t.Errorf("log should not contain query params, got: %s", logOutput) + } +} + func TestExtractHost(t *testing.T) { tests := []struct { name string diff --git a/internal/proxy/middleware_bench_test.go b/internal/proxy/middleware_bench_test.go index 79ecd32..4e257da 100644 --- a/internal/proxy/middleware_bench_test.go +++ b/internal/proxy/middleware_bench_test.go @@ -38,7 +38,7 @@ func BenchmarkRequestLoggingMiddleware(b *testing.B) { inner := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusOK) }) - handler := observability.RequestLoggerMiddleware(slog.Default(), "X-Connect-Vendor-ID", inner) + handler := observability.RequestLoggerMiddleware(slog.Default(), "X-Connect", inner) req := httptest.NewRequest("GET", "/proxy", nil) b.ReportAllocs() @@ -61,7 +61,7 @@ func BenchmarkMiddlewareStack(b *testing.B) { // Stack middlewares as they would be in production // Order: TraceID (outermost) → Logger → PanicRecovery → handler handler := PanicRecoveryMiddleware(inner) - handler = observability.RequestLoggerMiddleware(slog.Default(), "X-Connect-Vendor-ID", handler) + handler = observability.RequestLoggerMiddleware(slog.Default(), "X-Connect", handler) handler = observability.TraceIDMiddleware("Connect-Request-ID", handler) req := httptest.NewRequest("GET", "/proxy", nil) @@ -82,7 +82,7 @@ func BenchmarkMiddlewareStack_Parallel(b *testing.B) { w.WriteHeader(http.StatusOK) }) handler := PanicRecoveryMiddleware(inner) - handler = observability.RequestLoggerMiddleware(slog.Default(), "X-Connect-Vendor-ID", handler) + handler = observability.RequestLoggerMiddleware(slog.Default(), "X-Connect", handler) handler = observability.TraceIDMiddleware("Connect-Request-ID", handler) b.ReportAllocs() diff --git a/internal/proxy/server.go b/internal/proxy/server.go index 467f648..2ee1874 100644 --- a/internal/proxy/server.go +++ b/internal/proxy/server.go @@ -449,7 +449,7 @@ func (s *Server) withMiddleware(handler http.Handler) http.Handler { ) } - handler = observability.RequestLoggerMiddleware(slog.Default(), s.config.HeaderPrefix+"-Vendor-ID", handler) + handler = observability.RequestLoggerMiddleware(slog.Default(), s.config.HeaderPrefix, handler) handler = observability.TraceIDMiddleware(s.config.TraceHeader, handler) return handler } diff --git a/internal/proxy/server_test.go b/internal/proxy/server_test.go index 256ce99..db34f1c 100644 --- a/internal/proxy/server_test.go +++ b/internal/proxy/server_test.go @@ -375,7 +375,7 @@ func TestMiddlewareStack_PanicLogsCorrectStatus(t *testing.T) { // Apply middleware in production order: TraceID → Logger → PanicRecovery → handler handler := proxy.PanicRecoveryMiddleware(panicHandler) - handler = observability.RequestLoggerMiddleware(slog.Default(), "X-Connect-Vendor-ID", handler) + handler = observability.RequestLoggerMiddleware(slog.Default(), "X-Connect", handler) handler = observability.TraceIDMiddleware("Connect-Request-ID", handler) req := httptest.NewRequest(http.MethodPost, "/test/panic", nil) @@ -420,7 +420,7 @@ func TestMiddlewareStack_NormalRequestLogsCorrectStatus(t *testing.T) { // Apply middleware in production order: TraceID → Logger → PanicRecovery → handler wrapped := proxy.PanicRecoveryMiddleware(handler) - wrapped = observability.RequestLoggerMiddleware(slog.Default(), "X-Connect-Vendor-ID", wrapped) + wrapped = observability.RequestLoggerMiddleware(slog.Default(), "X-Connect", wrapped) wrapped = observability.TraceIDMiddleware("Connect-Request-ID", wrapped) req := httptest.NewRequest(http.MethodPost, "/resource", nil) From 4df606d3f32877f60d1ac16bd64a5e05c6c33057 Mon Sep 17 00:00:00 2001 From: Arnau Giralt Date: Thu, 12 Mar 2026 16:59:16 +0100 Subject: [PATCH 6/9] feat(proxy): add DEBUG logpoints for context parsing and allow-list - Add "transaction context parsed" DEBUG log in handleProxy after successful ParseContext, including vendor_id, marketplace_id, product_id, and a sanitized target_url (query string, fragment, userinfo stripped to prevent token leakage) - Add "allow list validation passed" DEBUG log in AllowListMiddleware with trace_id and target_host - Add trace_id to existing "missing target URL header" and "allow list validation failed" WARN logs (previously uncorrelatable under concurrency) - Add "plugin opted out of error normalization" DEBUG log in buildModifyResponse (only fires when plugin returns ResponseAction{SkipErrorNormalization: true}) - Add extractHostFromURL local helper to router/middleware.go - Import observability into router to access TraceIDFromContext (no cycle: observability does not import router) Co-Authored-By: Claude Sonnet 4.6 --- internal/proxy/integration_test.go | 47 ++++++++++++++++++++ internal/proxy/server.go | 13 ++++++ internal/router/middleware.go | 23 +++++++++- internal/router/middleware_test.go | 70 ++++++++++++++++++++++++++++++ 4 files changed, 151 insertions(+), 2 deletions(-) diff --git a/internal/proxy/integration_test.go b/internal/proxy/integration_test.go index 13e6399..43d02d4 100644 --- a/internal/proxy/integration_test.go +++ b/internal/proxy/integration_test.go @@ -2022,6 +2022,53 @@ func TestIntegration_SlowPath_LogsCredentialInjection(t *testing.T) { } } +// ============================================================================= +// Phase 6: DEBUG logpoints for context parsing +// ============================================================================= + +func TestProxy_ContextParsed_DebugLog_SanitizesURL(t *testing.T) { + // Arrange - capture DEBUG log output + var logBuffer bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&logBuffer, &slog.HandlerOptions{Level: slog.LevelDebug})) + originalLogger := slog.Default() + slog.SetDefault(logger) + defer slog.SetDefault(originalLogger) + + backend := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + })) + defer backend.Close() + + srv := mustNewServerForTarget(t, testConfig(), backend.URL) + handler := srv.Handler() + + // Construct target URL with sensitive query params and credentials in userinfo + targetURL := backend.URL + "/v1/resource?api_key=supersecret&token=abc123" + + req := httptest.NewRequest(http.MethodGet, "/proxy", nil) + req.Header.Set("X-Connect-Target-URL", targetURL) + req.Header.Set("X-Connect-Vendor-ID", "VA-test") + rec := httptest.NewRecorder() + + // Act + handler.ServeHTTP(rec, req) + + // Assert - target_url in the DEBUG log must not contain query params + logOutput := logBuffer.String() + if strings.Contains(logOutput, "supersecret") { + t.Errorf("log must not contain sensitive query value 'supersecret', got: %s", logOutput) + } + if strings.Contains(logOutput, "api_key") { + t.Errorf("log must not contain query param name 'api_key', got: %s", logOutput) + } + if strings.Contains(logOutput, "token=") { + t.Errorf("log must not contain 'token=' query param, got: %s", logOutput) + } + if !strings.Contains(logOutput, `"msg":"transaction context parsed"`) { + t.Errorf("expected 'transaction context parsed' debug log, got: %s", logOutput) + } +} + // ============================================================================= // Phase 3: Status 499 on client disconnect // ============================================================================= diff --git a/internal/proxy/server.go b/internal/proxy/server.go index 2ee1874..c6b01d0 100644 --- a/internal/proxy/server.go +++ b/internal/proxy/server.go @@ -481,6 +481,14 @@ func (s *Server) handleProxy(w http.ResponseWriter, r *http.Request) { return } + slog.Debug("transaction context parsed", + "trace_id", traceID, + "vendor_id", txCtx.VendorID, + "marketplace_id", txCtx.MarketplaceID, + "product_id", txCtx.ProductID, + "target_url", sanitizeURL(txCtx.TargetURL), + ) + targetURL, err := url.Parse(txCtx.TargetURL) if err != nil { s.respondBadRequest(w, traceID, "invalid target URL", err) @@ -880,6 +888,11 @@ func (s *Server) buildModifyResponse(traceID string, txCtx *sdk.TransactionConte security.StripInjectedHeaders(resp.Request.Context(), resp.Header) // Step 3: Core error normalization (safety net - unless plugin opted out) + if action != nil && action.SkipErrorNormalization { + slog.Debug("plugin opted out of error normalization", + "trace_id", traceID, + ) + } if action == nil || !action.SkipErrorNormalization { if err := security.NormalizeError(resp, traceID); err != nil { slog.Error("error normalization failed", diff --git a/internal/router/middleware.go b/internal/router/middleware.go index 7e26913..8f0d185 100644 --- a/internal/router/middleware.go +++ b/internal/router/middleware.go @@ -8,6 +8,9 @@ import ( "errors" "log/slog" "net/http" + "net/url" + + "github.com/cloudblue/chaperone/internal/observability" ) // AllowListMiddleware validates incoming requests against the allow list @@ -42,6 +45,7 @@ func (m *AllowListMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Request) // Missing target URL is a client error if targetURL == "" { slog.Warn("missing target URL header", + "trace_id", observability.TraceIDFromContext(r.Context()), "header", m.headerPrefix+"-Target-URL", "remote_addr", r.RemoteAddr, ) @@ -51,9 +55,9 @@ func (m *AllowListMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Request) // Validate target URL against allow list if err := m.validator.Validate(targetURL); err != nil { - // Log the validation failure with context - // Note: We log the host but not the full URL to avoid leaking query params + // Log the host but not the full URL to avoid leaking query params slog.Warn("allow list validation failed", + "trace_id", observability.TraceIDFromContext(r.Context()), "error", err.Error(), "remote_addr", r.RemoteAddr, ) @@ -73,10 +77,25 @@ func (m *AllowListMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Request) return } + slog.Debug("allow list validation passed", + "trace_id", observability.TraceIDFromContext(r.Context()), + "target_host", extractHostFromURL(targetURL), + ) + // Validation passed, continue to next handler m.next.ServeHTTP(w, r) } +// extractHostFromURL parses a URL string and returns only the host portion. +// Returns an empty string if the URL is invalid or has no host. +func extractHostFromURL(rawURL string) string { + u, err := url.Parse(rawURL) + if err != nil || u.Host == "" { + return "" + } + return u.Host +} + // errorResponse is the JSON structure for error responses. type errorResponse struct { Error string `json:"error"` diff --git a/internal/router/middleware_test.go b/internal/router/middleware_test.go index 225b7df..8e6edf9 100644 --- a/internal/router/middleware_test.go +++ b/internal/router/middleware_test.go @@ -4,11 +4,15 @@ package router import ( + "bytes" "io" + "log/slog" "net/http" "net/http/httptest" "strings" "testing" + + "github.com/cloudblue/chaperone/internal/observability" ) func TestAllowListMiddleware_ValidRequest(t *testing.T) { @@ -312,6 +316,72 @@ func TestAllowListMiddleware_AllMethods(t *testing.T) { } } +func TestAllowListMiddleware_ValidationPassed_DebugLog(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug})) + prevLogger := slog.Default() + slog.SetDefault(logger) + defer slog.SetDefault(prevLogger) + + allowList := map[string][]string{"api.example.com": {"/**"}} + nextHandler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + }) + middleware := NewAllowListMiddleware(allowList, "X-Connect", nextHandler) + + req := httptest.NewRequest(http.MethodGet, "/proxy", nil) + req = req.WithContext(observability.WithTraceID(req.Context(), "trace-debug-123")) + req.Header.Set("X-Connect-Target-URL", "https://api.example.com/v1/users") + rr := httptest.NewRecorder() + + middleware.ServeHTTP(rr, req) + + if rr.Code != http.StatusOK { + t.Fatalf("status = %d, want %d", rr.Code, http.StatusOK) + } + + logOutput := buf.String() + if !strings.Contains(logOutput, `"msg":"allow list validation passed"`) { + t.Errorf("expected allow list validation passed debug log, got: %s", logOutput) + } + if !strings.Contains(logOutput, `"trace_id":"trace-debug-123"`) { + t.Errorf("expected trace_id in log, got: %s", logOutput) + } + if !strings.Contains(logOutput, `"target_host":"api.example.com"`) { + t.Errorf("expected target_host in log, got: %s", logOutput) + } +} + +func TestAllowListMiddleware_ValidationFailed_HasTraceID(t *testing.T) { + var buf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug})) + prevLogger := slog.Default() + slog.SetDefault(logger) + defer slog.SetDefault(prevLogger) + + allowList := map[string][]string{"api.example.com": {"/**"}} + nextHandler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + t.Error("next handler should not be called") + }) + middleware := NewAllowListMiddleware(allowList, "X-Connect", nextHandler) + + req := httptest.NewRequest(http.MethodGet, "/proxy", nil) + req = req.WithContext(observability.WithTraceID(req.Context(), "trace-fail-456")) + req.Header.Set("X-Connect-Target-URL", "https://evil.com/data") + rr := httptest.NewRecorder() + + middleware.ServeHTTP(rr, req) + + if rr.Code != http.StatusForbidden { + t.Fatalf("status = %d, want %d", rr.Code, http.StatusForbidden) + } + + logOutput := buf.String() + if !strings.Contains(logOutput, `"trace_id":"trace-fail-456"`) { + t.Errorf("expected trace_id in failure log, got: %s", logOutput) + } +} + func TestAllowListMiddleware_EmptyAllowListDeniesAll(t *testing.T) { // Both nil and empty map should deny all testCases := []struct { From 7af833bf45522ddd7a931518286a7f1c948b440c Mon Sep 17 00:00:00 2001 From: Arnau Giralt Date: Thu, 12 Mar 2026 16:59:54 +0100 Subject: [PATCH 7/9] fix(proxy): format startup timeouts as human-readable strings and log allow-list MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit logStartup previously logged timeout durations as nanosecond integers (e.g. 30000000000 instead of "30s"). All timeout fields now call .String() which produces human-readable values like "30s", "2m0s", "120ns". Also adds three timeout fields that were configured but not previously logged: ConnectTimeout, KeepAliveTimeout, ShutdownTimeout. New "allow list configured" INFO log at startup shows hosts (sorted for deterministic output), host_count, and route_count — giving operators immediate visibility into which targets the proxy will accept. New "no plugin configured" INFO log if plugin is nil at startup (one-time event, not per-request noise). Co-Authored-By: Claude Sonnet 4.6 --- internal/proxy/server.go | 45 +++++++++++++++++++++++++++++++++------- 1 file changed, 37 insertions(+), 8 deletions(-) diff --git a/internal/proxy/server.go b/internal/proxy/server.go index c6b01d0..e0519d3 100644 --- a/internal/proxy/server.go +++ b/internal/proxy/server.go @@ -18,6 +18,7 @@ import ( "net/http/httputil" "net/url" "os" + "sort" "sync/atomic" "time" @@ -401,6 +402,10 @@ func (s *Server) logStartup() { ) } + if s.config.Plugin == nil { + slog.Info("no plugin configured, requests will be forwarded without credential injection") + } + if s.config.TLS.Enabled { slog.Info("starting proxy server with mTLS (Mode A)", "addr", s.config.Addr, @@ -409,10 +414,13 @@ func (s *Server) logStartup() { "client_auth", "RequireAndVerifyClientCert", ) slog.Info("server configuration", - "read_timeout", s.config.ReadTimeout, - "write_timeout", s.config.WriteTimeout, - "idle_timeout", s.config.IdleTimeout, - "plugin_timeout", s.config.PluginTimeout, + "read_timeout", s.config.ReadTimeout.String(), + "write_timeout", s.config.WriteTimeout.String(), + "idle_timeout", s.config.IdleTimeout.String(), + "plugin_timeout", s.config.PluginTimeout.String(), + "connect_timeout", s.config.ConnectTimeout.String(), + "keepalive_timeout", s.config.KeepAliveTimeout.String(), + "shutdown_timeout", s.config.ShutdownTimeout.String(), "cert_file", s.config.TLS.CertFile, "ca_file", s.config.TLS.CAFile, ) @@ -422,12 +430,33 @@ func (s *Server) logStartup() { "mode", "B (basic)", ) slog.Info("server configuration", - "read_timeout", s.config.ReadTimeout, - "write_timeout", s.config.WriteTimeout, - "idle_timeout", s.config.IdleTimeout, - "plugin_timeout", s.config.PluginTimeout, + "read_timeout", s.config.ReadTimeout.String(), + "write_timeout", s.config.WriteTimeout.String(), + "idle_timeout", s.config.IdleTimeout.String(), + "plugin_timeout", s.config.PluginTimeout.String(), + "connect_timeout", s.config.ConnectTimeout.String(), + "keepalive_timeout", s.config.KeepAliveTimeout.String(), + "shutdown_timeout", s.config.ShutdownTimeout.String(), ) } + + s.logAllowList() +} + +// logAllowList logs the configured allow-list at startup for operational visibility. +func (s *Server) logAllowList() { + hosts := make([]string, 0, len(s.config.AllowList)) + routeCount := 0 + for host, patterns := range s.config.AllowList { + hosts = append(hosts, host) + routeCount += len(patterns) + } + sort.Strings(hosts) // Deterministic output for stable logs and testability + slog.Info("allow list configured", + "hosts", hosts, + "host_count", len(s.config.AllowList), + "route_count", routeCount, + ) } // withMiddleware wraps the handler with the global middleware stack. From c351992e9eea02c1ab9fa3edbd60d1f867a25812 Mon Sep 17 00:00:00 2001 From: Arnau Giralt Date: Thu, 12 Mar 2026 17:03:08 +0100 Subject: [PATCH 8/9] refactor(proxy): fix linter issues from Phase 6-7 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two issues flagged by CI lint run: 1. gocritic/unnamedResult: detectSlowPathInjections returns two values — add named return params (modified, injectedCount) for clarity 2. gocognit: buildModifyResponse closure complexity reached 16 (limit 15) after the Phase 6 opt-out DEBUG log added a branch. Extract applyErrorNormalization helper to bring complexity back within limit. No behavior change. Co-Authored-By: Claude Sonnet 4.6 --- internal/proxy/server.go | 54 ++++++++++++++++++++++------------------ 1 file changed, 30 insertions(+), 24 deletions(-) diff --git a/internal/proxy/server.go b/internal/proxy/server.go index e0519d3..e603d85 100644 --- a/internal/proxy/server.go +++ b/internal/proxy/server.go @@ -679,7 +679,7 @@ func (s *Server) applyFastPathCredentials(r *http.Request, cred *sdk.Credential) // This is a safety net — Slow Path plugins MAY still call // observability.WithSecretValue() and security.WithInjectedHeaders() // for finer control, but forgetting to do so is no longer a security gap. -func (s *Server) detectSlowPathInjections(r *http.Request, before http.Header) (*http.Request, int) { +func (s *Server) detectSlowPathInjections(r *http.Request, before http.Header) (modified *http.Request, injectedCount int) { var injectedKeys []string reqCtx := r.Context() @@ -897,12 +897,12 @@ func (s *Server) buildModifyResponse(traceID string, txCtx *sdk.TransactionConte action, err = s.config.Plugin.ModifyResponse(ctx, *txCtx, resp) if err != nil { slog.Warn("plugin ModifyResponse error", - "trace_id", traceID, - "vendor_id", txCtx.VendorID, - "marketplace_id", txCtx.MarketplaceID, - "target_host", resp.Request.URL.Host, - "error", err, - ) + "trace_id", traceID, + "vendor_id", txCtx.VendorID, + "marketplace_id", txCtx.MarketplaceID, + "target_host", resp.Request.URL.Host, + "error", err, + ) // Continue with response processing even if plugin fails } } @@ -917,23 +917,7 @@ func (s *Server) buildModifyResponse(traceID string, txCtx *sdk.TransactionConte security.StripInjectedHeaders(resp.Request.Context(), resp.Header) // Step 3: Core error normalization (safety net - unless plugin opted out) - if action != nil && action.SkipErrorNormalization { - slog.Debug("plugin opted out of error normalization", - "trace_id", traceID, - ) - } - if action == nil || !action.SkipErrorNormalization { - if err := security.NormalizeError(resp, traceID); err != nil { - slog.Error("error normalization failed", - "trace_id", traceID, - "vendor_id", txCtx.VendorID, - "marketplace_id", txCtx.MarketplaceID, - "target_host", resp.Request.URL.Host, - "error", err, - ) - // Continue even if normalization fails - response will be sent as-is - } - } + s.applyErrorNormalization(traceID, txCtx, resp, action) slog.Info("upstream response", "trace_id", traceID, @@ -946,3 +930,25 @@ func (s *Server) buildModifyResponse(traceID string, txCtx *sdk.TransactionConte return nil } } + +// applyErrorNormalization runs Step 3 of the response modification chain. +// If the plugin opted out via ResponseAction.SkipErrorNormalization, it logs +// the opt-out at DEBUG and skips. Otherwise it runs the core error normalization. +func (s *Server) applyErrorNormalization(traceID string, txCtx *sdk.TransactionContext, resp *http.Response, action *sdk.ResponseAction) { + if action != nil && action.SkipErrorNormalization { + slog.Debug("plugin opted out of error normalization", + "trace_id", traceID, + ) + return + } + if err := security.NormalizeError(resp, traceID); err != nil { + slog.Error("error normalization failed", + "trace_id", traceID, + "vendor_id", txCtx.VendorID, + "marketplace_id", txCtx.MarketplaceID, + "target_host", resp.Request.URL.Host, + "error", err, + ) + // Continue even if normalization fails - response will be sent as-is + } +} From e32b0f77d68363dfc1d9ac691127add3116390ae Mon Sep 17 00:00:00 2001 From: Arnau Giralt Date: Thu, 12 Mar 2026 22:24:44 +0100 Subject: [PATCH 9/9] fix(observability): address review findings from improve-core-logging - Pre-compute header name strings once at RequestLoggerMiddleware construction instead of per-request to avoid redundant allocations - Add product_id to all operational log lines that had vendor_id and marketplace_id for consistent per-product filtering - Replace sanitizeURL (kept path) with extractTargetHost (host only) in the transaction context parsed DEBUG log to prevent path segments from leaking sensitive data (e.g. /users/alice@example.com) - Add target_host to allow-list rejection log and remove misleading comment that described intent that wasn't implemented Co-Authored-By: Claude Sonnet 4.6 --- internal/observability/request_logger.go | 13 +++++++--- internal/proxy/integration_test.go | 18 ++++++++----- internal/proxy/server.go | 24 ++++++++++-------- internal/proxy/server_helpers_test.go | 32 ++++++++++++------------ internal/router/middleware.go | 2 +- internal/router/middleware_test.go | 3 +++ 6 files changed, 55 insertions(+), 37 deletions(-) diff --git a/internal/observability/request_logger.go b/internal/observability/request_logger.go index 309e4ca..21d87a5 100644 --- a/internal/observability/request_logger.go +++ b/internal/observability/request_logger.go @@ -108,6 +108,11 @@ func (rc *ResponseCapturer) Status() int { // Uses defer to ensure logging occurs even if downstream handlers panic // (when used with panic recovery middleware). func RequestLoggerMiddleware(logger *slog.Logger, headerPrefix string, next http.Handler) http.Handler { + vendorHdr := headerPrefix + "-Vendor-ID" + marketplaceHdr := headerPrefix + "-Marketplace-ID" + productHdr := headerPrefix + "-Product-ID" + targetURLHdr := headerPrefix + "-Target-URL" + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { start := time.Now() ctx := r.Context() @@ -123,10 +128,10 @@ func RequestLoggerMiddleware(logger *slog.Logger, headerPrefix string, next http "path", r.URL.Path, "status", capturer.Status(), "latency_ms", time.Since(start).Milliseconds(), - "vendor_id", r.Header.Get(headerPrefix+"-Vendor-ID"), - "marketplace_id", r.Header.Get(headerPrefix+"-Marketplace-ID"), - "product_id", r.Header.Get(headerPrefix+"-Product-ID"), - "target_host", extractHost(r.Header.Get(headerPrefix+"-Target-URL")), + "vendor_id", r.Header.Get(vendorHdr), + "marketplace_id", r.Header.Get(marketplaceHdr), + "product_id", r.Header.Get(productHdr), + "target_host", extractHost(r.Header.Get(targetURLHdr)), "client_ip", ClientIP(r), "remote_addr", r.RemoteAddr, ) diff --git a/internal/proxy/integration_test.go b/internal/proxy/integration_test.go index 43d02d4..460b371 100644 --- a/internal/proxy/integration_test.go +++ b/internal/proxy/integration_test.go @@ -2026,7 +2026,7 @@ func TestIntegration_SlowPath_LogsCredentialInjection(t *testing.T) { // Phase 6: DEBUG logpoints for context parsing // ============================================================================= -func TestProxy_ContextParsed_DebugLog_SanitizesURL(t *testing.T) { +func TestProxy_ContextParsed_DebugLog_LogsHostOnly(t *testing.T) { // Arrange - capture DEBUG log output var logBuffer bytes.Buffer logger := slog.New(slog.NewJSONHandler(&logBuffer, &slog.HandlerOptions{Level: slog.LevelDebug})) @@ -2042,8 +2042,8 @@ func TestProxy_ContextParsed_DebugLog_SanitizesURL(t *testing.T) { srv := mustNewServerForTarget(t, testConfig(), backend.URL) handler := srv.Handler() - // Construct target URL with sensitive query params and credentials in userinfo - targetURL := backend.URL + "/v1/resource?api_key=supersecret&token=abc123" + // URL with a sensitive path segment and query params — only the host should appear in logs + targetURL := backend.URL + "/v1/users/alice@example.com?api_key=supersecret&token=abc123" req := httptest.NewRequest(http.MethodGet, "/proxy", nil) req.Header.Set("X-Connect-Target-URL", targetURL) @@ -2053,8 +2053,11 @@ func TestProxy_ContextParsed_DebugLog_SanitizesURL(t *testing.T) { // Act handler.ServeHTTP(rec, req) - // Assert - target_url in the DEBUG log must not contain query params + // Assert - only the host appears; path, query, and userinfo must not leak logOutput := logBuffer.String() + if !strings.Contains(logOutput, `"msg":"transaction context parsed"`) { + t.Errorf("expected 'transaction context parsed' debug log, got: %s", logOutput) + } if strings.Contains(logOutput, "supersecret") { t.Errorf("log must not contain sensitive query value 'supersecret', got: %s", logOutput) } @@ -2064,8 +2067,11 @@ func TestProxy_ContextParsed_DebugLog_SanitizesURL(t *testing.T) { if strings.Contains(logOutput, "token=") { t.Errorf("log must not contain 'token=' query param, got: %s", logOutput) } - if !strings.Contains(logOutput, `"msg":"transaction context parsed"`) { - t.Errorf("expected 'transaction context parsed' debug log, got: %s", logOutput) + if strings.Contains(logOutput, "alice@example.com") { + t.Errorf("log must not contain path segment 'alice@example.com', got: %s", logOutput) + } + if strings.Contains(logOutput, "/v1/users") { + t.Errorf("log must not contain URL path, got: %s", logOutput) } } diff --git a/internal/proxy/server.go b/internal/proxy/server.go index e603d85..660d448 100644 --- a/internal/proxy/server.go +++ b/internal/proxy/server.go @@ -515,7 +515,7 @@ func (s *Server) handleProxy(w http.ResponseWriter, r *http.Request) { "vendor_id", txCtx.VendorID, "marketplace_id", txCtx.MarketplaceID, "product_id", txCtx.ProductID, - "target_url", sanitizeURL(txCtx.TargetURL), + "target_host", extractTargetHost(txCtx.TargetURL), ) targetURL, err := url.Parse(txCtx.TargetURL) @@ -701,18 +701,15 @@ func (s *Server) detectSlowPathInjections(r *http.Request, before http.Header) ( return r, len(injectedKeys) } -// sanitizeURL strips the query string, fragment, and userinfo from a URL -// to prevent token or credential leakage in log output. -// Returns an empty string if the input is not a valid URL. -func sanitizeURL(rawURL string) string { +// extractTargetHost parses rawURL and returns only the host (with port if present). +// Used in log output to avoid leaking sensitive path or query information. +// Returns an empty string if the URL is invalid or has no host. +func extractTargetHost(rawURL string) string { u, err := url.Parse(rawURL) - if err != nil { + if err != nil || u.Host == "" { return "" } - u.RawQuery = "" - u.Fragment = "" - u.User = nil - return u.String() + return u.Host } // headerValuesEqual returns true if two header value slices are identical. @@ -758,6 +755,7 @@ func (s *Server) handlePluginError(w http.ResponseWriter, traceID string, txCtx "trace_id", traceID, "vendor_id", txCtx.VendorID, "marketplace_id", txCtx.MarketplaceID, + "product_id", txCtx.ProductID, "target_host", targetHost, "error", err, ) @@ -770,6 +768,7 @@ func (s *Server) handlePluginError(w http.ResponseWriter, traceID string, txCtx "trace_id", traceID, "vendor_id", txCtx.VendorID, "marketplace_id", txCtx.MarketplaceID, + "product_id", txCtx.ProductID, "target_host", targetHost, ) // Write 499 so RequestLoggerMiddleware logs the correct status instead of @@ -782,6 +781,7 @@ func (s *Server) handlePluginError(w http.ResponseWriter, traceID string, txCtx "trace_id", traceID, "vendor_id", txCtx.VendorID, "marketplace_id", txCtx.MarketplaceID, + "product_id", txCtx.ProductID, "target_host", targetHost, "error", err, ) @@ -855,6 +855,7 @@ func (s *Server) createReverseProxy(target *url.URL, traceID string, txCtx *sdk. "trace_id", traceID, "vendor_id", txCtx.VendorID, "marketplace_id", txCtx.MarketplaceID, + "product_id", txCtx.ProductID, "target_host", target.Host, "error", err, ) @@ -900,6 +901,7 @@ func (s *Server) buildModifyResponse(traceID string, txCtx *sdk.TransactionConte "trace_id", traceID, "vendor_id", txCtx.VendorID, "marketplace_id", txCtx.MarketplaceID, + "product_id", txCtx.ProductID, "target_host", resp.Request.URL.Host, "error", err, ) @@ -925,6 +927,7 @@ func (s *Server) buildModifyResponse(traceID string, txCtx *sdk.TransactionConte "content_length", resp.ContentLength, "vendor_id", txCtx.VendorID, "marketplace_id", txCtx.MarketplaceID, + "product_id", txCtx.ProductID, "target_host", resp.Request.URL.Host, ) return nil @@ -946,6 +949,7 @@ func (s *Server) applyErrorNormalization(traceID string, txCtx *sdk.TransactionC "trace_id", traceID, "vendor_id", txCtx.VendorID, "marketplace_id", txCtx.MarketplaceID, + "product_id", txCtx.ProductID, "target_host", resp.Request.URL.Host, "error", err, ) diff --git a/internal/proxy/server_helpers_test.go b/internal/proxy/server_helpers_test.go index 98d415d..818aba7 100644 --- a/internal/proxy/server_helpers_test.go +++ b/internal/proxy/server_helpers_test.go @@ -5,36 +5,36 @@ package proxy import "testing" -func TestSanitizeURL(t *testing.T) { +func TestExtractTargetHost(t *testing.T) { tests := []struct { name string input string want string }{ { - name: "strips query string", - input: "https://api.vendor.com/v1?api_key=secret", - want: "https://api.vendor.com/v1", + name: "returns host only, strips path", + input: "https://api.vendor.com/v1/users/123", + want: "api.vendor.com", }, { - name: "strips fragment", - input: "https://api.vendor.com/v1#section", - want: "https://api.vendor.com/v1", + name: "returns host only, strips query string", + input: "https://api.vendor.com/v1?api_key=secret", + want: "api.vendor.com", }, { - name: "strips userinfo", + name: "returns host only, strips userinfo", input: "https://user:pass@api.vendor.com/v1", - want: "https://api.vendor.com/v1", + want: "api.vendor.com", }, { - name: "preserves path", - input: "https://api.vendor.com/v1/users/123", - want: "https://api.vendor.com/v1/users/123", + name: "preserves port", + input: "https://api.vendor.com:8443/v1", + want: "api.vendor.com:8443", }, { name: "strips all sensitive parts together", - input: "https://user:pass@api.vendor.com/v1?token=abc#frag", - want: "https://api.vendor.com/v1", + input: "https://user:pass@api.vendor.com/v1/users/alice@example.com?token=abc#frag", + want: "api.vendor.com", }, { name: "invalid URL returns empty", @@ -50,9 +50,9 @@ func TestSanitizeURL(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - got := sanitizeURL(tt.input) + got := extractTargetHost(tt.input) if got != tt.want { - t.Errorf("sanitizeURL(%q) = %q, want %q", tt.input, got, tt.want) + t.Errorf("extractTargetHost(%q) = %q, want %q", tt.input, got, tt.want) } }) } diff --git a/internal/router/middleware.go b/internal/router/middleware.go index 8f0d185..c07ad2c 100644 --- a/internal/router/middleware.go +++ b/internal/router/middleware.go @@ -55,9 +55,9 @@ func (m *AllowListMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Request) // Validate target URL against allow list if err := m.validator.Validate(targetURL); err != nil { - // Log the host but not the full URL to avoid leaking query params slog.Warn("allow list validation failed", "trace_id", observability.TraceIDFromContext(r.Context()), + "target_host", extractHostFromURL(targetURL), "error", err.Error(), "remote_addr", r.RemoteAddr, ) diff --git a/internal/router/middleware_test.go b/internal/router/middleware_test.go index 8e6edf9..9250db1 100644 --- a/internal/router/middleware_test.go +++ b/internal/router/middleware_test.go @@ -380,6 +380,9 @@ func TestAllowListMiddleware_ValidationFailed_HasTraceID(t *testing.T) { if !strings.Contains(logOutput, `"trace_id":"trace-fail-456"`) { t.Errorf("expected trace_id in failure log, got: %s", logOutput) } + if !strings.Contains(logOutput, `"target_host":"evil.com"`) { + t.Errorf("expected target_host in failure log, got: %s", logOutput) + } } func TestAllowListMiddleware_EmptyAllowListDeniesAll(t *testing.T) {