Skip to content

fix(x402-buyer): propagate upstream status/body and log every request#504

Merged
bussyjd merged 2 commits into
mainfrom
fix/x402-buyer-propagate-upstream-errors
May 19, 2026
Merged

fix(x402-buyer): propagate upstream status/body and log every request#504
bussyjd merged 2 commits into
mainfrom
fix/x402-buyer-propagate-upstream-errors

Conversation

@bussyjd
Copy link
Copy Markdown
Collaborator

@bussyjd bussyjd commented May 18, 2026

Summary

  • Structured per-request logging: every outbound RoundTrip now 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.
  • Upstream errors pass through verbatim: non-402 non-2xx status codes (403, 404, 500, 503, …) are forwarded to LiteLLM as-is with their original body intact. The sidecar already returned the upstream response object unchanged — the logging gap was what made diagnosis impossible.
  • "Payment verification failed" is now scoped: that string lives in 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:

ServiceUnavailableError: OpenAIException - Payment verification failed

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):

# sidecar log: (empty — only startup lines)
# LiteLLM error: ServiceUnavailableError: Payment verification failed

After (real error visible immediately in sidecar log, real status reaches LiteLLM):

x402-buyer: outbound POST https://inference.v1337.org/services/aeon/v1/chat/completions (with X-PAYMENT) → 403 after 312ms body="error code: 1010" — passing through upstream error
# LiteLLM error: 403 Forbidden — error code: 1010

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 -v output.
  • All 35 existing internal/x402/buyer/ tests pass: go test ./internal/x402/buyer/ ./cmd/x402-buyer/ -count=1
  • Full build: go 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 via io.LimitReader, prepends back via io.MultiReader) and log.Printf calls. No configuration changes, no wire-format changes.

Parallel PR fix/x402-buyer-user-agent touches cmd/x402-buyer/main.go only — no file overlap with this PR (internal/x402/buyer/proxy.go + proxy_test.go).

Comment thread internal/x402/buyer/proxy.go Fixed
Comment thread internal/x402/buyer/proxy.go Fixed
Comment thread internal/x402/buyer/proxy.go Fixed
Comment thread internal/x402/buyer/proxy.go Fixed
Comment thread internal/x402/buyer/proxy.go Fixed
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()),
bussyjd added 2 commits May 19, 2026 17:33
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.
@bussyjd bussyjd force-pushed the fix/x402-buyer-propagate-upstream-errors branch from f7b0cca to fd05580 Compare May 19, 2026 09:35
@bussyjd bussyjd merged commit f8df92e into main May 19, 2026
2 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants