diff --git a/internal/proxy/handler.go b/internal/proxy/handler.go index 3a20c6b..274b442 100644 --- a/internal/proxy/handler.go +++ b/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") } } diff --git a/internal/proxy/sniff.go b/internal/proxy/sniff.go index 20d0a8f..d8d9906 100644 --- a/internal/proxy/sniff.go +++ b/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", - profile.Version, len(profile.Headers), len(profile.Body)) + log.Info(). + Str("version", profile.Version). + Int("headers", len(profile.Headers)). + Int("body_size", len(profile.Body)). + Msg("sniffed claude-code profile") return profile, nil } diff --git a/internal/proxy/transport.go b/internal/proxy/transport.go index c78c94c..a479711 100644 --- a/internal/proxy/transport.go +++ b/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 {