refactor(proxy): migrate to zerolog structured logging

internal/proxy/handler.go

@@ -3,13 +3,15 @@ package proxy
 import (
 	"bufio"
 	"io"
-	"log"
 	"net/http"
+	"time"
 
 	"github.com/gin-gonic/gin"
+	"github.com/rs/zerolog/log"
 	"github.com/tidwall/gjson"
 
 	"github.com/fujin/anthropic-proxy/internal/auth"
+	"github.com/fujin/anthropic-proxy/internal/logging"
 )
 
 func HandleMessages(pool *auth.Pool, profile *SniffedProfile, getSanitizer func() *Sanitizer) gin.HandlerFunc {
@@ -22,7 +24,15 @@ func HandleMessages(pool *auth.Pool, profile *SniffedProfile, getSanitizer func(
 			return
 		}
 
-		log.Printf("incoming: %s %s (%d bytes) model=%s", c.Request.Method, c.Request.URL.Path, len(body), gjson.GetBytes(body, "model").String())
+		originalBody := make([]byte, len(body))
+		copy(originalBody, body)
+
+		log.Info().
+			Str("method", c.Request.Method).
+			Str("path", c.Request.URL.Path).
+			Int("body_size", len(body)).
+			Str("model", gjson.GetBytes(body, "model").String()).
+			Msg("incoming request")
 
 		san := getSanitizer()
 		body = san.SanitizeRequest(body)
@@ -36,24 +46,54 @@ func HandleMessages(pool *auth.Pool, profile *SniffedProfile, getSanitizer func(
 		isStream := gjson.GetBytes(body, "stream").Bool()
 
 		if isStream {
-			handleStream(c, upstream, san, pool, cred, body)
+			handleStream(c, upstream, san, pool, cred, body, originalBody)
 		} else {
-			handleNonStream(c, upstream, san, pool, cred, body)
+			handleNonStream(c, upstream, san, pool, cred, body, originalBody)
 		}
 	}
 }
 
-func handleNonStream(c *gin.Context, upstream *UpstreamClient, san *Sanitizer, pool *auth.Pool, cred *auth.Credential, body []byte) {
+func handleNonStream(c *gin.Context, upstream *UpstreamClient, san *Sanitizer, pool *auth.Pool, cred *auth.Credential, body []byte, originalBody []byte) {
+	startTime := time.Now()
 	respBody, headers, statusCode, err := upstream.Execute(c.Request.Context(), cred, body)
 	if err != nil {
-		log.Printf("upstream error for %s: %v", cred.Email, err)
+		latencyMs := float64(time.Since(startTime).Milliseconds())
+		model := gjson.GetBytes(body, "model").String()
+		log.Error().
+			Err(err).
+			Str("credential", cred.Email).
+			Str("model", model).
+			Bool("stream", false).
+			Str("request_body_original", string(originalBody)).
+			Str("request_body_sanitized", string(body)).
+			Int("request_body_size", len(body)).
+			Float64("latency_ms", latencyMs).
+			Msg("upstream connection error")
 		c.JSON(http.StatusBadGateway, gin.H{"error": "upstream request failed"})
 		return
 	}
 
 	if statusCode >= 400 {
 		pool.MarkFailure(cred, statusCode)
-		log.Printf("upstream %d for %s: %s", statusCode, cred.Email, string(respBody))
+		latencyMs := float64(time.Since(startTime).Milliseconds())
+		model := gjson.GetBytes(body, "model").String()
+		errorType := gjson.GetBytes(respBody, "error.type").String()
+		errorMessage := gjson.GetBytes(respBody, "error.message").String()
+		log.Error().
+			Int("status", statusCode).
+			Str("error_type", errorType).
+			Str("error_message", errorMessage).
+			Str("response_body", string(respBody)).
+			Str("request_id", headers.Get("X-Request-Id")).
+			Float64("latency_ms", latencyMs).
+			Str("credential", cred.Email).
+			Str("model", model).
+			Bool("stream", false).
+			Str("request_body_original", string(originalBody)).
+			Str("request_body_sanitized", string(body)).
+			Int("request_body_size", len(body)).
+			Str("request_headers", logging.RedactHeaders(c.Request.Header)).
+			Msg("upstream error")
 	} else {
 		pool.MarkSuccess(cred)
 		respBody = san.DesanitizeResponse(respBody)
@@ -68,10 +108,22 @@ func handleNonStream(c *gin.Context, upstream *UpstreamClient, san *Sanitizer, p
 	c.Data(statusCode, headers.Get("Content-Type"), respBody)
 }
 
-func handleStream(c *gin.Context, upstream *UpstreamClient, san *Sanitizer, pool *auth.Pool, cred *auth.Credential, body []byte) {
+func handleStream(c *gin.Context, upstream *UpstreamClient, san *Sanitizer, pool *auth.Pool, cred *auth.Credential, body []byte, originalBody []byte) {
+	startTime := time.Now()
 	resp, err := upstream.ExecuteStream(c.Request.Context(), cred, body)
 	if err != nil {
-		log.Printf("upstream stream error for %s: %v", cred.Email, err)
+		latencyMs := float64(time.Since(startTime).Milliseconds())
+		model := gjson.GetBytes(body, "model").String()
+		log.Error().
+			Err(err).
+			Str("credential", cred.Email).
+			Str("model", model).
+			Bool("stream", true).
+			Str("request_body_original", string(originalBody)).
+			Str("request_body_sanitized", string(body)).
+			Int("request_body_size", len(body)).
+			Float64("latency_ms", latencyMs).
+			Msg("upstream connection error")
 		c.JSON(http.StatusBadGateway, gin.H{"error": "upstream stream request failed"})
 		return
 	}
@@ -80,7 +132,25 @@ func handleStream(c *gin.Context, upstream *UpstreamClient, san *Sanitizer, pool
 	if resp.StatusCode >= 400 {
 		pool.MarkFailure(cred, resp.StatusCode)
 		respBody, _ := io.ReadAll(resp.Body)
-		log.Printf("upstream stream %d for %s: %s", resp.StatusCode, cred.Email, string(respBody))
+		latencyMs := float64(time.Since(startTime).Milliseconds())
+		model := gjson.GetBytes(body, "model").String()
+		errorType := gjson.GetBytes(respBody, "error.type").String()
+		errorMessage := gjson.GetBytes(respBody, "error.message").String()
+		log.Error().
+			Int("status", resp.StatusCode).
+			Str("error_type", errorType).
+			Str("error_message", errorMessage).
+			Str("response_body", string(respBody)).
+			Str("request_id", resp.Header.Get("X-Request-Id")).
+			Float64("latency_ms", latencyMs).
+			Str("credential", cred.Email).
+			Str("model", model).
+			Bool("stream", true).
+			Str("request_body_original", string(originalBody)).
+			Str("request_body_sanitized", string(body)).
+			Int("request_body_size", len(body)).
+			Str("request_headers", logging.RedactHeaders(c.Request.Header)).
+			Msg("upstream error")
 		c.Data(resp.StatusCode, resp.Header.Get("Content-Type"), respBody)
 		return
 	}
@@ -94,7 +164,7 @@ func handleStream(c *gin.Context, upstream *UpstreamClient, san *Sanitizer, pool
 
 	flusher, ok := c.Writer.(http.Flusher)
 	if !ok {
-		log.Printf("response writer does not support flushing")
+		log.Error().Msg("response writer does not support flushing")
 		c.JSON(http.StatusInternalServerError, gin.H{"error": "streaming not supported"})
 		return
 	}
@@ -108,6 +178,6 @@ func handleStream(c *gin.Context, upstream *UpstreamClient, san *Sanitizer, pool
 	}
 
 	if err := scanner.Err(); err != nil {
-		log.Printf("stream scan error: %v", err)
+		log.Error().Err(err).Msg("stream scan error")
 	}
 }

internal/proxy/sniff.go

@@ -3,13 +3,14 @@ package proxy
 import (
 	"fmt"
 	"io"
-	"log"
 	"net"
 	"net/http"
 	"os/exec"
 	"strings"
 	"sync"
 	"time"
+
+	"github.com/rs/zerolog/log"
 )
 
 // SniffedProfile holds everything captured from a real Claude Code request.
@@ -116,8 +117,11 @@ func SniffClaudeCode(claudeBinary string) (*SniffedProfile, error) {
 		return nil, fmt.Errorf("no API request captured")
 	}
 
-	log.Printf("sniffed claude-code: version=%s headers=%d body=%d bytes",
+	log.Info().
-		profile.Version, len(profile.Headers), len(profile.Body))
+		Str("version", profile.Version).
+		Int("headers", len(profile.Headers)).
+		Int("body_size", len(profile.Body)).
+		Msg("sniffed claude-code profile")
 	return profile, nil
 }
 

internal/proxy/transport.go

@@ -1,12 +1,12 @@
 package proxy
 
 import (
-	"log"
 	"net"
 	"net/http"
 	"sync"
 
 	tls "github.com/refraction-networking/utls"
+	"github.com/rs/zerolog/log"
 	"golang.org/x/net/http2"
 )
 
@@ -90,7 +90,7 @@ func (t *utlsRoundTripper) RoundTrip(req *http.Request) (*http.Response, error)
 		port = "443"
 	}
 	addr := net.JoinHostPort(hostname, port)
-	log.Printf("utls: RoundTrip to %s (Chrome TLS fingerprint, HTTP/2)", addr)
+	log.Debug().Str("addr", addr).Msg("uTLS round trip")
 
 	h2Conn, err := t.getOrCreateConnection(hostname, addr)
 	if err != nil {