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

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

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.

* fix(x402-buyer): sanitize user-controlled log inputs (CWE-117)

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.

---------

Co-authored-by: bussyjd <bussyjd@users.noreply.github.com>

Author: JeanDaniel Bussy

internal/x402/buyer/proxy.go

@@ -425,6 +425,46 @@ type replayableX402Transport struct {
 	OnPaymentUnsettled PaymentCallback
 }
 
+// maxLogBodyBytes is the maximum number of bytes read from a response body for
+// structured log output. Truncation prevents huge bodies from flooding logs.
+const maxLogBodyBytes = 512
+
+// peekResponseBody reads up to maxLogBodyBytes from resp.Body for logging and
+// reassembles the full body (via a TeeReader drain) so the caller (ReverseProxy)
+// can still copy it to the client. The body is replaced in-place on resp.
+func peekResponseBody(resp *http.Response) string {
+	if resp == nil || resp.Body == nil {
+		return ""
+	}
+
+	// Drain up to maxLogBodyBytes+1 bytes via a buffer, then prepend those
+	// bytes back using io.MultiReader so the rest of the body is still readable.
+	limitedBuf := new(bytes.Buffer)
+	_, _ = io.Copy(limitedBuf, io.LimitReader(resp.Body, maxLogBodyBytes+1))
+
+	preview := limitedBuf.Bytes()
+	// Reassemble: preview bytes + remainder of original body.
+	resp.Body = io.NopCloser(io.MultiReader(bytes.NewReader(preview), resp.Body))
+
+	s := string(preview)
+	if len(s) > maxLogBodyBytes {
+		s = s[:maxLogBodyBytes] + "…"
+	}
+	return s
+}
+
+// sanitizeLogString strips control characters (including CR/LF) from values
+// that may originate from upstream HTTP requests or responses, preventing log
+// injection (CWE-117) when the strings are interpolated into log lines.
+func sanitizeLogString(s string) string {
+	return strings.Map(func(r rune) rune {
+		if r < 0x20 || r == 0x7f {
+			return '_'
+		}
+		return r
+	}, s)
+}
+
 func (t *replayableX402Transport) RoundTrip(req *http.Request) (*http.Response, error) {
 	if t.Base == nil {
 		t.Base = http.DefaultTransport
@@ -440,9 +480,21 @@ func (t *replayableX402Transport) RoundTrip(req *http.Request) (*http.Response,
 	firstReq.Header.Set("User-Agent", userAgent)
 	resp, err := t.Base.RoundTrip(firstReq)
 	if err != nil {
+		log.Printf("x402-buyer: outbound %s %s → transport error: %s",
+			sanitizeLogString(req.Method),
+			sanitizeLogString(req.URL.String()),
+			sanitizeLogString(err.Error()))
 		return nil, err
 	}
 	if resp.StatusCode != http.StatusPaymentRequired {
+		// Non-402 response on the probe request — pass through verbatim so the
+		// caller (LiteLLM) sees the real upstream status and body, not a
+		// remapped "Payment verification failed" generic error.
+		excerpt := peekResponseBody(resp)
+		log.Printf("x402-buyer: outbound %s %s → %d (no payment required) body=%q",
+			sanitizeLogString(req.Method),
+			sanitizeLogString(req.URL.String()),
+			resp.StatusCode, excerpt)
 		return resp, nil
 	}
 
@@ -531,6 +583,11 @@ func (t *replayableX402Transport) RoundTrip(req *http.Request) (*http.Response,
 
 	if err != nil {
 		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()),
+			duration.Round(time.Millisecond),
+			sanitizeLogString(err.Error()))
 		if t.OnPaymentFailure != nil {
 			t.OnPaymentFailure(PaymentEvent{
 				Type:      PaymentEventFailure,
@@ -545,10 +602,25 @@ func (t *replayableX402Transport) RoundTrip(req *http.Request) (*http.Response,
 	}
 
 	if respRetry.StatusCode >= http.StatusBadRequest {
+		// Non-2xx after payment retry: release the held auth (not consumed) and
+		// pass the upstream status+body verbatim to the caller. This ensures the
+		// real upstream error (e.g. 403 Cloudflare WAF, 404, 500) reaches
+		// LiteLLM instead of being misclassified as "Payment verification failed".
+		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()),
+			respRetry.StatusCode, duration.Round(time.Millisecond), excerpt)
 		releaseHeldPreSignedSpend(t.Signers, heldAuth)
 		return respRetry, nil
 	}
 
+	// 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()),
+		respRetry.StatusCode, duration.Round(time.Millisecond))
+
 	if len(t.Signers) == 1 {
 		if ps, ok := t.Signers[0].(*PreSignedSigner); ok && heldAuth != nil {
 			if confirmErr := ps.ConfirmSpend(heldAuth); confirmErr != nil {

internal/x402/buyer/proxy_test.go

@@ -2124,3 +2124,236 @@ func TestProxy_UserAgentOnPaidRequest(t *testing.T) {
 		t.Errorf("paid User-Agent = %q, want %q", capturedPaidUA, wantUA)
 	}
 }
+
+// TestUpstreamStatusPropagation exercises the pass-through behaviour added in
+// fix(x402-buyer): propagate upstream status/body and log every request.
+//
+// Evidence: during a live demo against inference.v1337.org the upstream
+// returned HTTP 403 + body "error code: 1010" (Cloudflare WAF) but LiteLLM
+// surfaced it as "ServiceUnavailableError: Payment verification failed" — a
+// misleading remapping that cost ~30 min of fruitless debugging. The sidecar
+// must forward non-402 non-2xx responses verbatim so the real error is visible.
+func TestUpstreamStatusPropagation(t *testing.T) {
+	// paymentRequiredBody is the 402 body the upstream emits on the probe request.
+	paymentRequiredBody := `{
+		"x402Version": 1,
+		"accepts": [{
+			"scheme": "exact",
+			"network": "base-sepolia",
+			"maxAmountRequired": "1000",
+			"asset": "0x036CbD53842c5426634e7929541eC2318f3dCF7e",
+			"payTo": "0x70997970C51812dc3A010C7d01b50e0d17dc79C8"
+		}]
+	}`
+
+	type upstreamBehaviour int
+	const (
+		// directStatus: upstream returns the given status immediately (no 402 handshake).
+		directStatus upstreamBehaviour = iota
+		// afterPayment: upstream first returns 402, then returns the given status when X-PAYMENT is present.
+		afterPayment
+	)
+
+	tests := []struct {
+		name         string
+		behaviour    upstreamBehaviour
+		upstreamCode int
+		upstreamBody string
+		wantCode     int
+		wantBodySub  string
+	}{
+		{
+			name:         "200 direct — forwarded as 200",
+			behaviour:    directStatus,
+			upstreamCode: http.StatusOK,
+			upstreamBody: `{"choices":[{"message":{"content":"ok"}}]}`,
+			wantCode:     http.StatusOK,
+			wantBodySub:  "ok",
+		},
+		{
+			name:         "403 direct (no payment) — forwarded as 403 with real body",
+			behaviour:    directStatus,
+			upstreamCode: http.StatusForbidden,
+			upstreamBody: "error code: 1010",
+			wantCode:     http.StatusForbidden,
+			wantBodySub:  "error code: 1010",
+		},
+		{
+			name:         "404 direct — forwarded as 404",
+			behaviour:    directStatus,
+			upstreamCode: http.StatusNotFound,
+			upstreamBody: "not found",
+			wantCode:     http.StatusNotFound,
+			wantBodySub:  "not found",
+		},
+		{
+			name:         "503 direct — forwarded as 503, NOT remapped",
+			behaviour:    directStatus,
+			upstreamCode: http.StatusServiceUnavailable,
+			upstreamBody: "upstream overloaded",
+			wantCode:     http.StatusServiceUnavailable,
+			wantBodySub:  "upstream overloaded",
+		},
+		{
+			name:         "200 after 402 payment — forwarded as 200",
+			behaviour:    afterPayment,
+			upstreamCode: http.StatusOK,
+			upstreamBody: `{"choices":[{"message":{"content":"paid ok"}}]}`,
+			wantCode:     http.StatusOK,
+			wantBodySub:  "paid ok",
+		},
+		{
+			name:         "403 after 402 payment (WAF block) — forwarded as 403 with real body",
+			behaviour:    afterPayment,
+			upstreamCode: http.StatusForbidden,
+			upstreamBody: "error code: 1010",
+			wantCode:     http.StatusForbidden,
+			wantBodySub:  "error code: 1010",
+		},
+		{
+			name:         "500 after 402 payment — forwarded as 500, NOT remapped",
+			behaviour:    afterPayment,
+			upstreamCode: http.StatusInternalServerError,
+			upstreamBody: "internal server error",
+			wantCode:     http.StatusInternalServerError,
+			wantBodySub:  "internal server error",
+		},
+	}
+
+	for _, tt := range tests {
+		tt := tt
+		t.Run(tt.name, func(t *testing.T) {
+			upstream := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+				switch tt.behaviour {
+				case directStatus:
+					w.WriteHeader(tt.upstreamCode)
+					fmt.Fprint(w, tt.upstreamBody)
+				case afterPayment:
+					if r.Header.Get("X-Payment") == "" {
+						w.Header().Set("Content-Type", "application/json")
+						w.WriteHeader(http.StatusPaymentRequired)
+						fmt.Fprint(w, paymentRequiredBody)
+						return
+					}
+					if tt.upstreamCode == http.StatusOK {
+						w.Header().Set("X-PAYMENT-RESPONSE", base64.StdEncoding.EncodeToString([]byte(
+							`{"success":true,"transaction":"0xtest","network":"base-sepolia","payer":"0xpayer"}`,
+						)))
+					}
+					w.WriteHeader(tt.upstreamCode)
+					fmt.Fprint(w, tt.upstreamBody)
+				}
+			}))
+			defer upstream.Close()
+
+			cfg := &Config{
+				Upstreams: map[string]UpstreamConfig{
+					"seller": {
+						URL:     upstream.URL,
+						Network: "base-sepolia",
+						PayTo:   "0x70997970C51812dc3A010C7d01b50e0d17dc79C8",
+						Asset:   "0x036CbD53842c5426634e7929541eC2318f3dCF7e",
+						Price:   "1000",
+					},
+				},
+			}
+			auths := AuthsFile{"seller": {makeAuth("0xsig-prop")}}
+
+			proxy, err := NewProxy(cfg, auths, nil)
+			if err != nil {
+				t.Fatalf("NewProxy: %v", err)
+			}
+
+			srv := httptest.NewServer(proxy)
+			defer srv.Close()
+
+			resp, err := http.Post(
+				srv.URL+"/upstream/seller/v1/chat/completions",
+				"application/json",
+				strings.NewReader(`{"model":"seller","messages":[{"role":"user","content":"hi"}]}`),
+			)
+			if err != nil {
+				t.Fatalf("request: %v", err)
+			}
+			defer resp.Body.Close()
+
+			body, _ := io.ReadAll(resp.Body)
+
+			if resp.StatusCode != tt.wantCode {
+				t.Errorf("status = %d, want %d (body: %s)", resp.StatusCode, tt.wantCode, string(body))
+			}
+
+			if tt.wantBodySub != "" && !strings.Contains(string(body), tt.wantBodySub) {
+				t.Errorf("body %q does not contain %q", string(body), tt.wantBodySub)
+			}
+		})
+	}
+}
+
+func TestSanitizeLogString(t *testing.T) {
+	tests := []struct {
+		name  string
+		input string
+		want  string
+	}{
+		{
+			name:  "newline replaced",
+			input: "foo\nbar",
+			want:  "foo_bar",
+		},
+		{
+			name:  "carriage return replaced",
+			input: "foo\rbar",
+			want:  "foo_bar",
+		},
+		{
+			name:  "tab replaced",
+			input: "foo\tbar",
+			want:  "foo_bar",
+		},
+		{
+			name:  "null byte replaced",
+			input: "foo\x00bar",
+			want:  "foo_bar",
+		},
+		{
+			name:  "escape replaced",
+			input: "foo\x1bbar",
+			want:  "foo_bar",
+		},
+		{
+			name:  "DEL replaced",
+			input: "foo\x7fbar",
+			want:  "foo_bar",
+		},
+		{
+			name:  "multiple control chars",
+			input: "\r\ninjected-log-entry\r\n",
+			want:  "__injected-log-entry__",
+		},
+		{
+			name:  "printable ASCII unchanged",
+			input: "GET /v1/chat/completions HTTP/1.1",
+			want:  "GET /v1/chat/completions HTTP/1.1",
+		},
+		{
+			name:  "UTF-8 letters unchanged",
+			input: "café résumé",
+			want:  "café résumé",
+		},
+		{
+			name:  "empty string",
+			input: "",
+			want:  "",
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			got := sanitizeLogString(tt.input)
+			if got != tt.want {
+				t.Errorf("sanitizeLogString(%q) = %q, want %q", tt.input, got, tt.want)
+			}
+		})
+	}
+}