fix(x402-buyer): propagate upstream status/body and log every request#504
Merged
Conversation
bussyjd
added a commit
that referenced
this pull request
May 18, 2026
Addresses CodeQL alerts 4483-4487 from PR #504 review. The 5 new log.Printf calls added for upstream error visibility interpolated req.Method, req.URL, and err directly — an attacker-controlled upstream could embed CR/LF to inject fake log entries (log forging). Adds sanitizeLogString() which replaces any code point < 0x20 or == 0x7f with '_', then wraps every user-controlled argument (Method, URL.String(), err.Error()) in that helper before interpolation. The body excerpt was already %q-escaped and is not changed. Unit test covers \n, \r, \t, \x00, \x1b, DEL, printable ASCII, and UTF-8 multi-byte letters.
| if err != nil { | ||
| log.Printf("x402-buyer: outbound %s %s → transport error: %s", | ||
| sanitizeLogString(req.Method), | ||
| sanitizeLogString(req.URL.String()), |
| excerpt := peekResponseBody(resp) | ||
| log.Printf("x402-buyer: outbound %s %s → %d (no payment required) body=%q", | ||
| sanitizeLogString(req.Method), | ||
| sanitizeLogString(req.URL.String()), |
| releaseHeldPreSignedSpend(t.Signers, heldAuth) | ||
| log.Printf("x402-buyer: outbound %s %s (with X-PAYMENT) → transport error after %s: %s", | ||
| sanitizeLogString(req.Method), | ||
| sanitizeLogString(req.URL.String()), |
| excerpt := peekResponseBody(respRetry) | ||
| log.Printf("x402-buyer: outbound %s %s (with X-PAYMENT) → %d after %s body=%q — passing through upstream error", | ||
| sanitizeLogString(req.Method), | ||
| sanitizeLogString(req.URL.String()), |
| // 2xx — log the successful paid response. | ||
| log.Printf("x402-buyer: outbound %s %s (with X-PAYMENT) → %d after %s", | ||
| sanitizeLogString(req.Method), | ||
| sanitizeLogString(req.URL.String()), |
During a live demo against inference.v1337.org/services/aeon, the upstream responded with HTTP 403 + body "error code: 1010" (Cloudflare WAF blocking on User-Agent). LiteLLM surfaced this as: ServiceUnavailableError: OpenAIException - Payment verification failed That misclassification cost ~30 min of debugging before someone called the sidecar directly and saw the actual 403/1010 body. The real fix is two parts: 1. Structured per-request logging: every outbound RoundTrip now emits a log line with method, URL, status code, duration, and a 512-byte body excerpt: x402-buyer: outbound POST https://.../ → 403 (no payment required) body="error code: 1010" x402-buyer: outbound POST https://.../ (with X-PAYMENT) → 403 after 42ms body="error code: 1010" — passing through upstream error x402-buyer: outbound POST https://.../ (with X-PAYMENT) → 200 after 38ms Transport-level errors (dial failures, TLS) are also logged. 2. Non-402 non-2xx status codes are passed through verbatim: the sidecar already returned the upstream response object unchanged in both the probe path (first request, no X-PAYMENT) and the retry path (after X-PAYMENT). No status remapping was happening in proxy.go — the "Payment verification failed" came from Traefik's x402-verifier ForwardAuth (forwardauth.go:147), not the buyer. The per-request log now gives operators the evidence they need to distinguish "verifier blocked" from "upstream blocked" without having to port-forward and call the sidecar manually. The 402-retry payment signing behaviour is unchanged: the sidecar still intercepts 402 probe responses, attaches X-PAYMENT, and retries. Only the observability and error-surface for non-402 non-2xx is improved. Adds TestUpstreamStatusPropagation table test: 7 subtests covering 200/403/ 404/503 (direct) and 200/403/500 (after payment retry). All 35 buyer tests pass.
Addresses CodeQL alerts 4483-4487 from PR #504 review. The 5 new log.Printf calls added for upstream error visibility interpolated req.Method, req.URL, and err directly — an attacker-controlled upstream could embed CR/LF to inject fake log entries (log forging). Adds sanitizeLogString() which replaces any code point < 0x20 or == 0x7f with '_', then wraps every user-controlled argument (Method, URL.String(), err.Error()) in that helper before interpolation. The body excerpt was already %q-escaped and is not changed. Unit test covers \n, \r, \t, \x00, \x1b, DEL, printable ASCII, and UTF-8 multi-byte letters.
f7b0cca to
fd05580
Compare
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
RoundTripnow emits a log line with method, URL, status code, duration, and a 512-byte body excerpt — both for the initial probe and the X-PAYMENT retry. Transport errors are also logged. Previously the sidecar emitted no per-request output at all.forwardauth.go(Traefik x402-verifier) and fires only when the facilitator call itself fails. The buyer sidecar no longer contributes any generic status remapping; the real upstream error body now reaches LiteLLM.Why
During a live demo against
inference.v1337.org/services/aeon, the upstream returned HTTP 403 + body"error code: 1010"(Cloudflare WAF blocking on User-Agent — totally unrelated to payment). LiteLLM surfaced this as:That misclassification cost ~30 min of fruitless x402-verifier debugging before someone port-forwarded to the sidecar and saw the real 403/1010 body directly.
Evidence
Before (no per-request log, misleading error reaches LiteLLM):
After (real error visible immediately in sidecar log, real status reaches LiteLLM):
The 402-retry and X-PAYMENT signing behaviour is unchanged.
Test plan
TestUpstreamStatusPropagation— 7 subtests: 200/403/404/503 (direct probe) and 200/403/500 (after payment retry). Assert status code and body substring are forwarded verbatim. Log lines visible in-voutput.internal/x402/buyer/tests pass:go test ./internal/x402/buyer/ ./cmd/x402-buyer/ -count=1go build ./...Risks
None — this is a diagnostic/observability improvement. The 402-retry payment path is structurally unchanged. The only new code paths are
peekResponseBody(reads ≤513 bytes viaio.LimitReader, prepends back viaio.MultiReader) andlog.Printfcalls. No configuration changes, no wire-format changes.Parallel PR
fix/x402-buyer-user-agenttouchescmd/x402-buyer/main.goonly — no file overlap with this PR (internal/x402/buyer/proxy.go+proxy_test.go).