From 46f9fbe650b8444f0eba271da03511e54fe61c26 Mon Sep 17 00:00:00 2001 From: aayushprsingh Date: Tue, 2 Jun 2026 18:20:25 +0530 Subject: [PATCH 1/5] feat: implement structured JSON logging for gateway requests and payments --- gateway/errors.go | 6 +++++ gateway/main.go | 13 +++++++++- gateway/main_test.go | 57 +++++++++++++++++++++++++++++++++++++++++++ gateway/middleware.go | 54 ++++++++++++++++++++++++++++++++++++++++ 4 files changed, 129 insertions(+), 1 deletion(-) diff --git a/gateway/errors.go b/gateway/errors.go index 95044a88..70afd20a 100644 --- a/gateway/errors.go +++ b/gateway/errors.go @@ -10,6 +10,12 @@ import ( ) func respondError(c *gin.Context, code int, publicMsg string, internalErr error) { + c.Set("payment_status", "failed") + c.Set("payment_error", publicMsg) + if internalErr != nil { + c.Set("internal_error", internalErr.Error()) + } + correlationID := responseCorrelationID(c) if internalErr != nil { log.Printf( diff --git a/gateway/main.go b/gateway/main.go index 953c94d1..050ff21b 100644 --- a/gateway/main.go +++ b/gateway/main.go @@ -269,7 +269,15 @@ func main() { fmt.Println("[WARN] CHAIN_ID not set, using default: 84532(Base Sepolia)") } - r := gin.Default() + var r *gin.Engine + if os.Getenv("LOG_FORMAT") == "json" { + gin.SetMode(gin.ReleaseMode) + r = gin.New() + r.Use(gin.Recovery()) + r.Use(JSONLoggerMiddleware()) + } else { + r = gin.Default() + } // Restrict trusted proxies to prevent X-Forwarded-For spoofing. // IP-based rate limiting relies on c.ClientIP(), which reads @@ -505,6 +513,9 @@ func handleSummarize(c *gin.Context) { return } + c.Set("payment_status", "success") + c.Set("payer", verifyResp.RecoveredAddress) + verificationTotal.WithLabelValues("success").Inc() // 2. Parse Request diff --git a/gateway/main_test.go b/gateway/main_test.go index 686bbdae..6cfa46bd 100644 --- a/gateway/main_test.go +++ b/gateway/main_test.go @@ -753,3 +753,60 @@ func TestHandleGetReceipt_ValidationAndLookupPaths(t *testing.T) { }) } } + +func TestJSONLoggerMiddleware(t *testing.T) { + // Capturing stdout + oldStdout := os.Stdout + rPipe, wPipe, _ := os.Pipe() + os.Stdout = wPipe + + defer func() { + os.Stdout = oldStdout + }() + + gin.SetMode(gin.TestMode) + r := gin.New() + r.Use(func(c *gin.Context) { + c.Set("correlation_id", "test-corr-123") + c.Set("payment_status", "success") + c.Set("payer", "0xPayerAddress") + c.Next() + }) + r.Use(JSONLoggerMiddleware()) + + r.GET("/test-json-log", func(c *gin.Context) { + c.JSON(200, gin.H{"status": "ok"}) + }) + + req, _ := http.NewRequest("GET", "/test-json-log", nil) + req.RemoteAddr = "127.0.0.1:12345" + w := httptest.NewRecorder() + r.ServeHTTP(w, req) + + // Close write pipe and read captured output + wPipe.Close() + var buf bytes.Buffer + _, _ = buf.ReadFrom(rPipe) + output := buf.String() + + require.NotEmpty(t, output) + + // Parse JSON output + var logEntry JSONLogEntry + err := json.Unmarshal([]byte(output), &logEntry) + require.NoError(t, err) + + require.Equal(t, 200, logEntry.Status) + require.Equal(t, "/test-json-log", logEntry.Path) + require.Equal(t, "GET", logEntry.Method) + require.Equal(t, "test-corr-123", logEntry.CorrelationID) + require.Equal(t, "success", logEntry.PaymentStatus) + require.Equal(t, "0xPayerAddress", logEntry.Payer) + require.Equal(t, "info", logEntry.Level) + require.NotEmpty(t, logEntry.Timestamp) + require.True(t, logEntry.LatencyMs >= 0) + + // Verify no sensitive fields (like private key or signature) are leaked + require.NotContains(t, output, "PRIVATE_KEY") + require.NotContains(t, output, "0x1234567890abcdef") // sample private key / sig values +} diff --git a/gateway/middleware.go b/gateway/middleware.go index 652bc332..47f1ec0b 100644 --- a/gateway/middleware.go +++ b/gateway/middleware.go @@ -4,6 +4,7 @@ import ( "bufio" "bytes" "context" + "encoding/json" "fmt" "log" "net" @@ -316,3 +317,56 @@ func recordRequestMetrics(method, path string, statusCode int, start time.Time) requestsTotal.WithLabelValues(method, path, status).Inc() requestsDuration.WithLabelValues(method, path).Observe(time.Since(start).Seconds()) } + +type JSONLogEntry struct { + Timestamp string `json:"timestamp"` + Level string `json:"level"` + Status int `json:"status"` + Path string `json:"path"` + Method string `json:"method"` + LatencyMs float64 `json:"latency_ms"` + ClientIP string `json:"client_ip"` + CorrelationID string `json:"correlation_id"` + PaymentStatus string `json:"payment_status,omitempty"` + PaymentError string `json:"payment_error,omitempty"` + Payer string `json:"payer,omitempty"` + InternalError string `json:"internal_error,omitempty"` +} + +func JSONLoggerMiddleware() gin.HandlerFunc { + return func(c *gin.Context) { + start := time.Now() + c.Next() + latency := time.Since(start) + + status := c.Writer.Status() + level := "info" + if status >= 500 { + level = "error" + } else if status >= 400 { + level = "warn" + } + + correlationID, _ := c.Get("correlation_id") + corrStr, _ := correlationID.(string) + + entry := JSONLogEntry{ + Timestamp: time.Now().UTC().Format(time.RFC3339), + Level: level, + Status: status, + Path: c.Request.URL.Path, + Method: c.Request.Method, + LatencyMs: float64(latency.Nanoseconds()) / 1e6, + ClientIP: c.ClientIP(), + CorrelationID: corrStr, + PaymentStatus: c.GetString("payment_status"), + PaymentError: c.GetString("payment_error"), + Payer: c.GetString("payer"), + InternalError: c.GetString("internal_error"), + } + + if data, err := json.Marshal(entry); err == nil { + fmt.Println(string(data)) + } + } +} From 7778e15640ffed82522b1c2fceff906eb0cc1a43 Mon Sep 17 00:00:00 2001 From: aayushprsingh Date: Sat, 6 Jun 2026 17:08:09 +0530 Subject: [PATCH 2/5] feat: implement JSON log sanitization and conditional print logs Signed-off-by: aayushprsingh --- gateway/errors.go | 24 ++++++++++++++++---- gateway/main.go | 8 +++++-- gateway/main_test.go | 53 +++++++++++++++++++++++++++++++++++++++++++ gateway/middleware.go | 2 +- 4 files changed, 80 insertions(+), 7 deletions(-) diff --git a/gateway/errors.go b/gateway/errors.go index 70afd20a..9ef903f7 100644 --- a/gateway/errors.go +++ b/gateway/errors.go @@ -4,26 +4,42 @@ import ( "fmt" "log" "net/http" + "os" + "regexp" "strings" "github.com/gin-gonic/gin" ) +var ( + hex64Regex = regexp.MustCompile(`\b[0-9a-fA-F]{64}\b`) + openRouterKeyRegex = regexp.MustCompile(`sk-or-[a-zA-Z0-9]+`) +) + +func sanitizeErrorString(s string) string { + s = hex64Regex.ReplaceAllString(s, "[redacted_hex_64]") + s = openRouterKeyRegex.ReplaceAllString(s, "[redacted_api_key]") + return s +} + func respondError(c *gin.Context, code int, publicMsg string, internalErr error) { c.Set("payment_status", "failed") c.Set("payment_error", publicMsg) + + var sanitizedErr string if internalErr != nil { - c.Set("internal_error", internalErr.Error()) + sanitizedErr = sanitizeErrorString(internalErr.Error()) + c.Set("internal_error", sanitizedErr) } correlationID := responseCorrelationID(c) - if internalErr != nil { + if internalErr != nil && os.Getenv("LOG_FORMAT") != "json" { log.Printf( - "[ERROR] correlation_id=%s status=%d error=%s internal=%v", + "[ERROR] correlation_id=%s status=%d error=%s internal=%s", correlationID, code, publicMsg, - internalErr, + sanitizedErr, ) } diff --git a/gateway/main.go b/gateway/main.go index 050ff21b..da1ece27 100644 --- a/gateway/main.go +++ b/gateway/main.go @@ -544,7 +544,9 @@ func handleSummarize(c *gin.Context) { // 4. Generate & Send Receipt if err := generateAndSendReceipt(c, *paymentCtx, verifyResp.RecoveredAddress, requestBody, summary); err != nil { - log.Printf("Failed to generate receipt: %v", err) + if os.Getenv("LOG_FORMAT") != "json" { + log.Printf("Failed to generate receipt: %v", err) + } // generateAndSendReceipt sends error response if it fails? // No, it returns error, we might have already written status if we aren't careful. // Let's implement generateAndSendReceipt to handle sending response. @@ -952,7 +954,9 @@ func handleGetReceipt(c *gin.Context) { receipt, exists, err := getReceiptWithContext(c.Request.Context(), id) if err != nil { - log.Printf("Failed to retrieve receipt %s: %v", id, err) + if os.Getenv("LOG_FORMAT") != "json" { + log.Printf("Failed to retrieve receipt %s: %v", id, err) + } c.JSON(http.StatusInternalServerError, gin.H{ "error": "failed to retrieve receipt", }) diff --git a/gateway/main_test.go b/gateway/main_test.go index 6cfa46bd..a67523b8 100644 --- a/gateway/main_test.go +++ b/gateway/main_test.go @@ -810,3 +810,56 @@ func TestJSONLoggerMiddleware(t *testing.T) { require.NotContains(t, output, "PRIVATE_KEY") require.NotContains(t, output, "0x1234567890abcdef") // sample private key / sig values } +func TestJSONLoggerMiddleware_Sanitization(t *testing.T) { + // Capturing stdout + oldStdout := os.Stdout + rPipe, wPipe, _ := os.Pipe() + os.Stdout = wPipe + + defer func() { + os.Stdout = oldStdout + }() + + gin.SetMode(gin.TestMode) + r := gin.New() + r.Use(func(c *gin.Context) { + c.Set("correlation_id", "test-corr-123") + c.Set("payment_status", "failed") + // Seed sensitive private key hex string in internal error + c.Set("internal_error", "failed to connect: openrouter key sk-or-1234567890abcdef1234567890abcdef and wallet key 1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef") + c.Next() + }) + r.Use(JSONLoggerMiddleware()) + + r.GET("/test-json-log-sanitize", func(c *gin.Context) { + c.JSON(500, gin.H{"status": "error"}) + }) + + req, _ := http.NewRequest("GET", "/test-json-log-sanitize", nil) + w := httptest.NewRecorder() + r.ServeHTTP(w, req) + + // Close write pipe and read captured output + wPipe.Close() + var buf bytes.Buffer + _, _ = buf.ReadFrom(rPipe) + output := buf.String() + + require.NotEmpty(t, output) + + // Parse JSON output + var logEntry JSONLogEntry + err := json.Unmarshal([]byte(output), &logEntry) + require.NoError(t, err) + + require.Equal(t, 500, logEntry.Status) + require.Equal(t, "test-corr-123", logEntry.CorrelationID) + require.Equal(t, "failed", logEntry.PaymentStatus) + require.Equal(t, "error", logEntry.Level) + + // Assert that sensitive fields are redacted in the log entry's internal error field + require.NotContains(t, logEntry.InternalError, "1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef") + require.NotContains(t, logEntry.InternalError, "sk-or-1234567890abcdef1234567890abcdef") + require.Contains(t, logEntry.InternalError, "[redacted_hex_64]") + require.Contains(t, logEntry.InternalError, "[redacted_api_key]") +} diff --git a/gateway/middleware.go b/gateway/middleware.go index 47f1ec0b..b1691fe5 100644 --- a/gateway/middleware.go +++ b/gateway/middleware.go @@ -362,7 +362,7 @@ func JSONLoggerMiddleware() gin.HandlerFunc { PaymentStatus: c.GetString("payment_status"), PaymentError: c.GetString("payment_error"), Payer: c.GetString("payer"), - InternalError: c.GetString("internal_error"), + InternalError: sanitizeErrorString(c.GetString("internal_error")), } if data, err := json.Marshal(entry); err == nil { From 25564eeccef1b3199289eb03310f98fdd9ed37d3 Mon Sep 17 00:00:00 2001 From: aayushprsingh Date: Sun, 7 Jun 2026 08:40:17 +0530 Subject: [PATCH 3/5] feat(gateway): improve structured JSON logging with cache status and redaction --- gateway/cache.go | 10 ++++++++-- gateway/main_test.go | 2 ++ gateway/middleware.go | 7 ++++++- 3 files changed, 16 insertions(+), 3 deletions(-) diff --git a/gateway/cache.go b/gateway/cache.go index 031d1723..7c9fe2dd 100644 --- a/gateway/cache.go +++ b/gateway/cache.go @@ -115,7 +115,10 @@ func CacheMiddleware() gin.HandlerFunc { // Check Cache if cached, err := getFromCache(c.Request.Context(), cacheKey); err == nil { - log.Printf("Cache HIT: %s", cacheKey) + if os.Getenv("LOG_FORMAT") != "json" { + log.Printf("Cache HIT: %s", cacheKey) + } + c.Set("cache_status", "hit") routePath := c.FullPath() if routePath == "" { @@ -183,7 +186,10 @@ func CacheMiddleware() gin.HandlerFunc { } // Cache MISS - log.Printf("Cache MISS: %s", cacheKey) + if os.Getenv("LOG_FORMAT") != "json" { + log.Printf("Cache MISS: %s", cacheKey) + } + c.Set("cache_status", "miss") routePath := c.FullPath() if routePath == "" { diff --git a/gateway/main_test.go b/gateway/main_test.go index a67523b8..1e525e82 100644 --- a/gateway/main_test.go +++ b/gateway/main_test.go @@ -770,6 +770,7 @@ func TestJSONLoggerMiddleware(t *testing.T) { c.Set("correlation_id", "test-corr-123") c.Set("payment_status", "success") c.Set("payer", "0xPayerAddress") + c.Set("cache_status", "hit") c.Next() }) r.Use(JSONLoggerMiddleware()) @@ -802,6 +803,7 @@ func TestJSONLoggerMiddleware(t *testing.T) { require.Equal(t, "test-corr-123", logEntry.CorrelationID) require.Equal(t, "success", logEntry.PaymentStatus) require.Equal(t, "0xPayerAddress", logEntry.Payer) + require.Equal(t, "hit", logEntry.CacheStatus) require.Equal(t, "info", logEntry.Level) require.NotEmpty(t, logEntry.Timestamp) require.True(t, logEntry.LatencyMs >= 0) diff --git a/gateway/middleware.go b/gateway/middleware.go index b1691fe5..c2517ee6 100644 --- a/gateway/middleware.go +++ b/gateway/middleware.go @@ -9,6 +9,7 @@ import ( "log" "net" "net/http" + "os" "strconv" "sync" "time" @@ -50,7 +51,9 @@ func CorrelationIDMiddleware() gin.HandlerFunc { c.Request = c.Request.WithContext(ctx) c.Header("X-Correlation-ID", id) - log.Printf("[CorrelationID: %s] %s %s", id, c.Request.Method, c.Request.URL.Path) + if os.Getenv("LOG_FORMAT") != "json" { + log.Printf("[CorrelationID: %s] %s %s", id, c.Request.Method, c.Request.URL.Path) + } c.Next() } } @@ -327,6 +330,7 @@ type JSONLogEntry struct { LatencyMs float64 `json:"latency_ms"` ClientIP string `json:"client_ip"` CorrelationID string `json:"correlation_id"` + CacheStatus string `json:"cache_status,omitempty"` PaymentStatus string `json:"payment_status,omitempty"` PaymentError string `json:"payment_error,omitempty"` Payer string `json:"payer,omitempty"` @@ -359,6 +363,7 @@ func JSONLoggerMiddleware() gin.HandlerFunc { LatencyMs: float64(latency.Nanoseconds()) / 1e6, ClientIP: c.ClientIP(), CorrelationID: corrStr, + CacheStatus: c.GetString("cache_status"), PaymentStatus: c.GetString("payment_status"), PaymentError: c.GetString("payment_error"), Payer: c.GetString("payer"), From b1e2b963c8d807174f3e6f038b17db0ce46e9996 Mon Sep 17 00:00:00 2001 From: AnkanMisra Date: Mon, 8 Jun 2026 20:03:26 +0530 Subject: [PATCH 4/5] fix(gateway): correct payment_status overwrite and key redaction gaps MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit respondError unconditionally set payment_status="failed", clobbering a verified payment when a later receipt-generation step failed — corrupting the very metric this feature captures. Now it only marks failed when no prior status exists. Redaction regexes missed real key formats: 0x-prefixed private keys (the \b anchor never matched after "x") and versioned sk-or-v1- tokens (charset excluded dashes). Widened both patterns and reordered so API-key redaction runs first. Added tests covering realistic key shapes and the post-success error path. Co-Authored-By: Claude Opus 4.7 (1M context) --- gateway/errors.go | 24 ++++++++++++++++---- gateway/main_test.go | 54 +++++++++++++++++++++++++++++++++++++++++++- 2 files changed, 72 insertions(+), 6 deletions(-) diff --git a/gateway/errors.go b/gateway/errors.go index 9ef903f7..d61845f2 100644 --- a/gateway/errors.go +++ b/gateway/errors.go @@ -12,20 +12,34 @@ import ( ) var ( - hex64Regex = regexp.MustCompile(`\b[0-9a-fA-F]{64}\b`) - openRouterKeyRegex = regexp.MustCompile(`sk-or-[a-zA-Z0-9]+`) + // Match an optional 0x prefix so real private keys (which are usually + // 0x-prefixed) are caught — a leading \b fails between "x" and the first + // hex digit because both are word characters. The trailing \b avoids + // chopping into longer hex runs. + hex64Regex = regexp.MustCompile(`(?:0x)?[0-9a-fA-F]{64}\b`) + // Allow dashes so versioned keys like sk-or-v1- are redacted in + // full, not just the "sk-or-v1" prefix. + openRouterKeyRegex = regexp.MustCompile(`sk-or-[a-zA-Z0-9-]+`) ) func sanitizeErrorString(s string) string { - s = hex64Regex.ReplaceAllString(s, "[redacted_hex_64]") + // Redact API keys before hex so a key whose secret happens to contain a + // 64-hex run collapses to a single [redacted_api_key] token. s = openRouterKeyRegex.ReplaceAllString(s, "[redacted_api_key]") + s = hex64Regex.ReplaceAllString(s, "[redacted_hex_64]") return s } func respondError(c *gin.Context, code int, publicMsg string, internalErr error) { - c.Set("payment_status", "failed") + // Only mark the payment failed if an earlier stage hasn't already recorded + // an outcome. handleSummarize sets payment_status="success" once the + // verifier accepts the signature; a later receipt-generation error must not + // overwrite that and misreport a paid request as a payment failure. + if _, ok := c.Get("payment_status"); !ok { + c.Set("payment_status", "failed") + } c.Set("payment_error", publicMsg) - + var sanitizedErr string if internalErr != nil { sanitizedErr = sanitizeErrorString(internalErr.Error()) diff --git a/gateway/main_test.go b/gateway/main_test.go index 1e525e82..8a55ad04 100644 --- a/gateway/main_test.go +++ b/gateway/main_test.go @@ -4,6 +4,7 @@ import ( "bytes" "context" "encoding/json" + "errors" "net/http" "net/http/httptest" "os" @@ -858,10 +859,61 @@ func TestJSONLoggerMiddleware_Sanitization(t *testing.T) { require.Equal(t, "test-corr-123", logEntry.CorrelationID) require.Equal(t, "failed", logEntry.PaymentStatus) require.Equal(t, "error", logEntry.Level) - + // Assert that sensitive fields are redacted in the log entry's internal error field require.NotContains(t, logEntry.InternalError, "1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef") require.NotContains(t, logEntry.InternalError, "sk-or-1234567890abcdef1234567890abcdef") require.Contains(t, logEntry.InternalError, "[redacted_hex_64]") require.Contains(t, logEntry.InternalError, "[redacted_api_key]") } + +func TestSanitizeErrorString_RealKeyFormats(t *testing.T) { + // 0x-prefixed private keys are the common real-world shape. The old + // \b-anchored regex failed to match these because there is no word + // boundary between "x" and the first hex digit. + hex := "1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef" + withPrefix := sanitizeErrorString("signing failed with key 0x" + hex) + require.NotContains(t, withPrefix, hex) + require.Contains(t, withPrefix, "[redacted_hex_64]") + + bare := sanitizeErrorString("wallet key " + hex + " leaked") + require.NotContains(t, bare, hex) + require.Contains(t, bare, "[redacted_hex_64]") + + // Versioned OpenRouter keys contain dashes; the secret after sk-or-v1- + // must be fully redacted, not just the prefix. + orKey := "sk-or-v1-abcdef0123456789abcdef0123456789" + redactedKey := sanitizeErrorString("openrouter rejected: " + orKey) + require.NotContains(t, redactedKey, "abcdef0123456789abcdef0123456789") + require.NotContains(t, redactedKey, orKey) + require.Contains(t, redactedKey, "[redacted_api_key]") +} + +func TestRespondError_DoesNotOverwriteSuccessfulPayment(t *testing.T) { + gin.SetMode(gin.TestMode) + + // A receipt-stage failure after the payment was already verified must not + // flip payment_status from "success" to "failed". + w := httptest.NewRecorder() + c, _ := gin.CreateTestContext(w) + c.Request, _ = http.NewRequest("GET", "/", nil) + c.Set("payment_status", "success") + + respondError(c, 500, "receipt_store_failed", errors.New("redis down")) + + require.Equal(t, "success", c.GetString("payment_status")) + require.Equal(t, "receipt_store_failed", c.GetString("payment_error")) +} + +func TestRespondError_MarksFailedWhenNoPriorStatus(t *testing.T) { + gin.SetMode(gin.TestMode) + + w := httptest.NewRecorder() + c, _ := gin.CreateTestContext(w) + c.Request, _ = http.NewRequest("GET", "/", nil) + + respondError(c, 502, "verification_unavailable", errors.New("verifier offline")) + + require.Equal(t, "failed", c.GetString("payment_status")) + require.Equal(t, "verification_unavailable", c.GetString("payment_error")) +} From 1142d223c3e090e096ea7776d04b841d3acb7ffb Mon Sep 17 00:00:00 2001 From: AnkanMisra Date: Tue, 9 Jun 2026 11:24:34 +0530 Subject: [PATCH 5/5] fix(gateway): resolve codex/coderabbit review on JSON logging Addresses the outstanding bot review on PR #206: - Centralize the scattered LOG_FORMAT=="json" checks into a single package-level jsonLogging flag set once at startup (initLogFormat). - Suppress/sanitize the remaining plaintext logs that still fired in JSON mode: invalid-JSON debug, cache-hit verification error, and cached receipt failure in cache.go. - Register JSONLoggerMiddleware before gin.Recovery so panics still produce a structured entry, and route recovery through a writer that redacts X-402-Signature/Nonce/Timestamp (the default dump only scrubs Authorization; a leaked signature is replayable until its nonce burns). - Record payment_status=success + payer on cache-hit verification so cached requests carry the same telemetry as handleSummarize. - Set payment_status=required on the unsigned 402 challenge so dashboards separate it from unrelated 402s. - Preserve a sanitized internal_error in handleGetReceipt under JSON mode so receipt-store outages stay diagnosable. - Distinguish a genuine cache miss (redis.Nil) from a backend error so Redis outages aren't masked as ordinary misses. - Document LOG_FORMAT in .env.example, README.md, and gateway/README.md. Tests: redacting writer scrubs x402 headers, 402 sets required status, plus the existing redaction/payment-status regression tests. Full gateway suite green. Co-Authored-By: Claude Opus 4.7 (1M context) --- .env.example | 5 ++++ README.md | 1 + gateway/README.md | 1 + gateway/cache.go | 40 +++++++++++++++++++++++------- gateway/errors.go | 3 +-- gateway/main.go | 27 +++++++++++++++++--- gateway/main_test.go | 41 +++++++++++++++++++++++++++++++ gateway/middleware.go | 57 ++++++++++++++++++++++++++++++++++++++++++- 8 files changed, 159 insertions(+), 16 deletions(-) diff --git a/.env.example b/.env.example index bdfda407..14af120c 100644 --- a/.env.example +++ b/.env.example @@ -95,6 +95,11 @@ HEALTH_CHECK_TIMEOUT_SECONDS=2 METRICS_ENABLED=true # Gateway Prometheus endpoint path (default: /metrics) METRICS_PATH=/metrics +# Log output format. Set to "json" for one structured JSON line per request +# (status, latency, correlation_id, cache/payment status, sanitized +# internal_error) suitable for log collectors. Any other value (default) keeps +# the human-readable gin/text logs. +# LOG_FORMAT=json diff --git a/README.md b/README.md index eed1f7b7..91f92458 100644 --- a/README.md +++ b/README.md @@ -337,6 +337,7 @@ Core local variables live in [.env.example](.env.example). Production placeholde | `METRICS_PATH` | Gateway | Gateway metrics path. Default `/metrics`; values without a leading slash are normalized. | | `ALLOWED_ORIGINS` | Gateway | Comma-separated CORS origins, no paths or query strings. | | `TRUSTED_PROXIES` | Gateway | Comma-separated trusted proxy CIDRs for production IP handling. | +| `LOG_FORMAT` | Gateway | Set to `json` for one structured JSON log line per request (status, latency, correlation_id, cache/payment status, sanitized internal_error). Any other value (default) keeps human-readable text logs. | | `NEXT_PUBLIC_GATEWAY_URL` | Web | Gateway base URL. Browser fetches `/api/ai/summarize` and `/api/receipts/:id` here. | | `NEXT_PUBLIC_EXPECTED_CHAIN_ID` | Web | Chain ID the wallet widget targets. Must match the gateway's `CHAIN_ID`. Default `84532`. | | `NEXT_PUBLIC_EXPECTED_CHAIN_NAME` | Web | Display name paired with the chain ID — used by the wallet widget's "Switch to " button, hero headline, stat bar, and page title. Must be set when `CHAIN_ID` is overridden (e.g. `Base` for `8453`). | diff --git a/gateway/README.md b/gateway/README.md index 47ad3901..2c742648 100644 --- a/gateway/README.md +++ b/gateway/README.md @@ -105,6 +105,7 @@ Common optional variables: | `CACHE_TTL_SECONDS` | `3600` | Response cache TTL. | | `METRICS_ENABLED` | enabled unless set to `false` | Exposes Prometheus metrics. | | `METRICS_PATH` | `/metrics` | Gateway metrics endpoint path. Missing leading slash is normalized. | +| `LOG_FORMAT` | text | Set to `json` for one structured JSON log line per request (status, latency, correlation_id, cache/payment status, sanitized internal_error). Any other value keeps human-readable text logs. | | `RATE_LIMIT_ENABLED` | disabled unless set to `true` or `1` | Enables token bucket middleware. | | `REQUEST_TIMEOUT_SECONDS` | `60` | Global request timeout. | | `AI_REQUEST_TIMEOUT_SECONDS` | `30` | AI route timeout. | diff --git a/gateway/cache.go b/gateway/cache.go index 7c9fe2dd..70da4de5 100644 --- a/gateway/cache.go +++ b/gateway/cache.go @@ -17,6 +17,7 @@ import ( "time" "github.com/gin-gonic/gin" + "github.com/redis/go-redis/v9" ) // CachedResponse represents the data stored in Redis @@ -87,7 +88,9 @@ func CacheMiddleware() gin.HandlerFunc { var req SummarizeRequest if err := json.Unmarshal(requestBody, &req); err != nil { // Invalid JSON - reject immediately to prevent cache bypass attacks - log.Printf("[DEBUG] Invalid JSON in request: %v", err) + if !jsonLogging { + log.Printf("[DEBUG] Invalid JSON in request: %v", err) + } c.JSON(400, gin.H{"error": "Invalid request body", "message": "Request must be valid JSON"}) c.Abort() return @@ -114,8 +117,9 @@ func CacheMiddleware() gin.HandlerFunc { cacheKey := getCacheKey(req.Text, model) // Check Cache - if cached, err := getFromCache(c.Request.Context(), cacheKey); err == nil { - if os.Getenv("LOG_FORMAT") != "json" { + cached, cacheErr := getFromCache(c.Request.Context(), cacheKey) + if cacheErr == nil { + if !jsonLogging { log.Printf("Cache HIT: %s", cacheKey) } c.Set("cache_status", "hit") @@ -144,7 +148,9 @@ func CacheMiddleware() gin.HandlerFunc { if err != nil { verificationTotal.WithLabelValues("error").Inc() - log.Printf("Verification error on cache hit: %v", err) + if !jsonLogging { + log.Printf("Verification error on cache hit: %v", sanitizeErrorString(err.Error())) + } if errors.Is(err, context.DeadlineExceeded) { respondError(c, 504, "verifier_timeout", err) @@ -171,6 +177,10 @@ func CacheMiddleware() gin.HandlerFunc { // Payment Verified. Store verification for downstream if needed (though we abort) c.Set("payment_verification", verifyResp) c.Set("payment_context", paymentCtx) + // Mirror handleSummarize so cache-hit responses carry complete payment + // telemetry; the structured logger only sees what we set on the context. + c.Set("payment_status", "success") + c.Set("payer", verifyResp.RecoveredAddress) // Generate Receipt and Respond // We treat the cached result as the AI result @@ -178,18 +188,30 @@ func CacheMiddleware() gin.HandlerFunc { // Note: request_hash matches current request, response is from cache, // but both are cryptographically valid since cache key ensures identical text. if err := generateAndSendReceipt(c, *paymentCtx, verifyResp.RecoveredAddress, requestBody, cached.Result); err != nil { - log.Printf("Failed to send cached response receipt: %v", err) + if !jsonLogging { + log.Printf("Failed to send cached response receipt: %v", sanitizeErrorString(err.Error())) + } // generateAndSendReceipt already sent an error response (500) } c.Abort() return } - // Cache MISS - if os.Getenv("LOG_FORMAT") != "json" { - log.Printf("Cache MISS: %s", cacheKey) + // Cache MISS (or a backend failure we treat as a bypass). Distinguish a + // genuine absent key (redis.Nil) from connection errors / corrupt cached + // data so telemetry doesn't mask Redis outages as ordinary misses. + cacheStatus := "miss" + if !errors.Is(cacheErr, redis.Nil) { + cacheStatus = "error" + } + if !jsonLogging { + if cacheStatus == "error" { + log.Printf("Cache lookup error (treating as bypass): %s: %v", cacheKey, sanitizeErrorString(cacheErr.Error())) + } else { + log.Printf("Cache MISS: %s", cacheKey) + } } - c.Set("cache_status", "miss") + c.Set("cache_status", cacheStatus) routePath := c.FullPath() if routePath == "" { diff --git a/gateway/errors.go b/gateway/errors.go index d61845f2..0113ef0a 100644 --- a/gateway/errors.go +++ b/gateway/errors.go @@ -4,7 +4,6 @@ import ( "fmt" "log" "net/http" - "os" "regexp" "strings" @@ -47,7 +46,7 @@ func respondError(c *gin.Context, code int, publicMsg string, internalErr error) } correlationID := responseCorrelationID(c) - if internalErr != nil && os.Getenv("LOG_FORMAT") != "json" { + if internalErr != nil && !jsonLogging { log.Printf( "[ERROR] correlation_id=%s status=%d error=%s internal=%s", correlationID, diff --git a/gateway/main.go b/gateway/main.go index da1ece27..8e7647fe 100644 --- a/gateway/main.go +++ b/gateway/main.go @@ -269,12 +269,20 @@ func main() { fmt.Println("[WARN] CHAIN_ID not set, using default: 84532(Base Sepolia)") } + initLogFormat() + var r *gin.Engine - if os.Getenv("LOG_FORMAT") == "json" { + if jsonLogging { gin.SetMode(gin.ReleaseMode) r = gin.New() - r.Use(gin.Recovery()) + // Register the JSON logger BEFORE recovery so a downstream panic still + // unwinds back through the logger's post-c.Next() block and produces a + // structured entry for the recovered 500. Recovery uses a custom writer + // that redacts x402 payment headers (signature/nonce/timestamp), which + // the default recovery dump would otherwise leak in plaintext — a nonce + // may stay replayable until it is consumed. r.Use(JSONLoggerMiddleware()) + r.Use(gin.RecoveryWithWriter(redactedRecoveryWriter())) } else { r = gin.Default() } @@ -446,6 +454,9 @@ func handleSummarize(c *gin.Context) { // Basic check if signature == "" || nonce == "" { + // Distinct status so dashboards can separate the normal unsigned x402 + // challenge (the most frequent payment event) from unrelated 402s. + c.Set("payment_status", "required") c.JSON(402, gin.H{ "error": "Payment Required", "message": "Please sign the payment context", @@ -544,7 +555,10 @@ func handleSummarize(c *gin.Context) { // 4. Generate & Send Receipt if err := generateAndSendReceipt(c, *paymentCtx, verifyResp.RecoveredAddress, requestBody, summary); err != nil { - if os.Getenv("LOG_FORMAT") != "json" { + // generateAndSendReceipt already routes its failures through respondError + // (which records a sanitized internal_error), so this is just a + // human-readable echo for text-mode logs. + if !jsonLogging { log.Printf("Failed to generate receipt: %v", err) } // generateAndSendReceipt sends error response if it fails? @@ -954,7 +968,12 @@ func handleGetReceipt(c *gin.Context) { receipt, exists, err := getReceiptWithContext(c.Request.Context(), id) if err != nil { - if os.Getenv("LOG_FORMAT") != "json" { + if jsonLogging { + // The plaintext log is suppressed in JSON mode; record a sanitized + // internal_error on the context so the structured entry still + // explains the 500 (Redis / receipt-store outages stay diagnosable). + c.Set("internal_error", sanitizeErrorString(err.Error())) + } else { log.Printf("Failed to retrieve receipt %s: %v", id, err) } c.JSON(http.StatusInternalServerError, gin.H{ diff --git a/gateway/main_test.go b/gateway/main_test.go index 8a55ad04..3a543266 100644 --- a/gateway/main_test.go +++ b/gateway/main_test.go @@ -917,3 +917,44 @@ func TestRespondError_MarksFailedWhenNoPriorStatus(t *testing.T) { require.Equal(t, "failed", c.GetString("payment_status")) require.Equal(t, "verification_unavailable", c.GetString("payment_error")) } + +func TestRedactingWriter_ScrubsX402Headers(t *testing.T) { + var buf bytes.Buffer + rw := redactingWriter{w: &buf} + + // Mimic gin's recovery request dump where header lines are indented. + dump := "GET /api/ai/summarize HTTP/1.1\r\n" + + "Host: example.com\r\n" + + "X-402-Signature: 0xdeadbeefsignature\r\n" + + "X-402-Nonce: nonce-abc-123\r\n" + + "X-402-Timestamp: 1700000000\r\n" + + "Content-Type: application/json\r\n" + + n, err := rw.Write([]byte(dump)) + require.NoError(t, err) + require.Equal(t, len(dump), n, "must report original byte count to gin") + + out := buf.String() + require.NotContains(t, out, "0xdeadbeefsignature") + require.NotContains(t, out, "nonce-abc-123") + require.NotContains(t, out, "1700000000") + require.Contains(t, out, "X-402-Signature: [redacted]") + require.Contains(t, out, "X-402-Nonce: [redacted]") + require.Contains(t, out, "X-402-Timestamp: [redacted]") + // Non-sensitive lines pass through untouched. + require.Contains(t, out, "Content-Type: application/json") + require.Contains(t, out, "Host: example.com") +} + +func TestHandleSummarize_402SetsRequiredPaymentStatus(t *testing.T) { + gin.SetMode(gin.TestMode) + + w := httptest.NewRecorder() + c, _ := gin.CreateTestContext(w) + c.Request, _ = http.NewRequest("POST", "/api/ai/summarize", nil) + + handleSummarize(c) + + require.Equal(t, 402, w.Code) + require.Equal(t, "required", c.GetString("payment_status")) +} diff --git a/gateway/middleware.go b/gateway/middleware.go index c2517ee6..3050e8ec 100644 --- a/gateway/middleware.go +++ b/gateway/middleware.go @@ -6,11 +6,13 @@ import ( "context" "encoding/json" "fmt" + "io" "log" "net" "net/http" "os" "strconv" + "strings" "sync" "time" @@ -37,6 +39,17 @@ func safeCorrelationID(id string) string { return id } +// jsonLogging is set once at startup from LOG_FORMAT and read on the request +// hot paths instead of calling os.Getenv repeatedly. Centralizing it here +// keeps the "json" comparison in one place so suppression stays consistent. +var jsonLogging bool + +// initLogFormat resolves the LOG_FORMAT env var once. Call early in main() +// before the router and handlers start serving traffic. +func initLogFormat() { + jsonLogging = os.Getenv("LOG_FORMAT") == "json" +} + // CorrelationIDMiddleware checks for an existing X-Correlation-ID header // or generates a new one, ensuring requests can be traced across services. func CorrelationIDMiddleware() gin.HandlerFunc { @@ -51,7 +64,7 @@ func CorrelationIDMiddleware() gin.HandlerFunc { c.Request = c.Request.WithContext(ctx) c.Header("X-Correlation-ID", id) - if os.Getenv("LOG_FORMAT") != "json" { + if !jsonLogging { log.Printf("[CorrelationID: %s] %s %s", id, c.Request.Method, c.Request.URL.Path) } c.Next() @@ -375,3 +388,45 @@ func JSONLoggerMiddleware() gin.HandlerFunc { } } } + +// x402SensitiveHeaders are payment headers that must never reach the panic +// recovery dump in plaintext. A leaked signature can stay replayable until its +// nonce is consumed by the verifier. +var x402SensitiveHeaders = []string{ + "x-402-signature", + "x-402-nonce", + "x-402-timestamp", +} + +// redactingWriter wraps an io.Writer and strips the values of x402 payment +// headers out of anything written through it. gin's recovery dump only scrubs +// Authorization, so we filter the rest here. +type redactingWriter struct { + w io.Writer +} + +func (rw redactingWriter) Write(p []byte) (int, error) { + lines := strings.Split(string(p), "\n") + for i, line := range lines { + lower := strings.ToLower(strings.TrimLeft(line, " \t")) + for _, h := range x402SensitiveHeaders { + if strings.HasPrefix(lower, h+":") { + if idx := strings.Index(line, ":"); idx >= 0 { + lines[i] = line[:idx+1] + " [redacted]" + } + break + } + } + } + if _, err := io.WriteString(rw.w, strings.Join(lines, "\n")); err != nil { + return 0, err + } + // Report the original length so gin sees a complete write. + return len(p), nil +} + +// redactedRecoveryWriter returns the writer gin.RecoveryWithWriter uses for its +// panic dump, with x402 payment headers redacted. +func redactedRecoveryWriter() io.Writer { + return redactingWriter{w: os.Stderr} +}