on main help sign in
feat: debug logs request response details (#407)

* feat: debug logs request response details closes #399 * fix: lint * refactor: improvements * fix: improvements * fix: test * fix: centralize body parsing * fix: compatct

commit0e52ccd26a5d82c27446b3e7f80cc28929f87064 authorCarlos Alexandro Becker <caarlos0@users.noreply.github.com> dateFri 1 Aug 2025, 15:26 (1 year ago) parentcd3ef8d
7 files changed+237−41
internal/llm/provider/anthropic.go+8−12 internal/llm/provider/azure.go+7 internal/llm/provider/gemini.go+9−9 internal/llm/provider/openai.go+7−18 internal/llm/provider/vertexai.go+8−2 internal/log/http.go+125 internal/log/http_test.go+73
internal/llm/provider/anthropic.go+8−12
@@ -19,6 +19,7 @@ import (
1919 "github.com/charmbracelet/catwalk/pkg/catwalk"
2020 "github.com/charmbracelet/crush/internal/config"
2121 "github.com/charmbracelet/crush/internal/llm/tools"
22+ "github.com/charmbracelet/crush/internal/log"
2223 "github.com/charmbracelet/crush/internal/message"
2324)
2425
@@ -77,6 +78,12 @@ func createAnthropicClient(opts providerClientOptions, tp AnthropicClientType) a
7778 } else if hasBearerAuth {
7879 slog.Debug("Skipping X-Api-Key header because Authorization header is provided")
7980 }
81+
82+ if config.Get().Options.Debug {
83+ httpClient := log.NewHTTPClient()
84+ anthropicClientOptions = append(anthropicClientOptions, option.WithHTTPClient(httpClient))
85+ }
86+
8087 switch tp {
8188 case AnthropicClientTypeBedrock:
8289 anthropicClientOptions = append(anthropicClientOptions, bedrock.WithLoadDefaultConfig(context.Background()))
@@ -271,17 +278,11 @@ func (a *anthropicClient) preparedMessages(messages []anthropic.MessageParam, to
271278}
272279
273280func (a *anthropicClient) send(ctx context.Context, messages []message.Message, tools []tools.BaseTool) (response *ProviderResponse, err error) {
274− cfg := config.Get()
275−
276281 attempts := 0
277282 for {
278283 attempts++
279284 // Prepare messages on each attempt in case max_tokens was adjusted
280285 preparedMessages := a.preparedMessages(a.convertMessages(messages), a.convertTools(tools))
281− if cfg.Options.Debug {
282− jsonData, _ := json.Marshal(preparedMessages)
283− slog.Debug("Prepared messages", "messages", string(jsonData))
284− }
285286
286287 var opts []option.RequestOption
287288 if a.isThinkingEnabled() {
@@ -294,7 +295,7 @@ func (a *anthropicClient) send(ctx context.Context, messages []message.Message,
294295 )
295296 // If there is an error we are going to see if we can retry the call
296297 if err != nil {
297− slog.Error("Error in Anthropic API call", "error", err)
298+ slog.Error("Anthropic API error", "error", err.Error(), "attempt", attempts, "max_retries", maxRetries)
298299 retry, after, retryErr := a.shouldRetry(attempts, err)
299300 if retryErr != nil {
300301 return nil, retryErr
@@ -327,7 +328,6 @@ func (a *anthropicClient) send(ctx context.Context, messages []message.Message,
327328}
328329
329330func (a *anthropicClient) stream(ctx context.Context, messages []message.Message, tools []tools.BaseTool) <-chan ProviderEvent {
330− cfg := config.Get()
331331 attempts := 0
332332 eventChan := make(chan ProviderEvent)
333333 go func() {
@@ -335,10 +335,6 @@ func (a *anthropicClient) stream(ctx context.Context, messages []message.Message
335335 attempts++
336336 // Prepare messages on each attempt in case max_tokens was adjusted
337337 preparedMessages := a.preparedMessages(a.convertMessages(messages), a.convertTools(tools))
338− if cfg.Options.Debug {
339− jsonData, _ := json.Marshal(preparedMessages)
340− slog.Debug("Prepared messages", "messages", string(jsonData))
341− }
342338
343339 var opts []option.RequestOption
344340 if a.isThinkingEnabled() {
internal/llm/provider/azure.go+7
@@ -1,6 +1,8 @@
11package provider
22
33import (
4+ "github.com/charmbracelet/crush/internal/config"
5+ "github.com/charmbracelet/crush/internal/log"
46 "github.com/openai/openai-go"
57 "github.com/openai/openai-go/azure"
68 "github.com/openai/openai-go/option"
@@ -22,6 +24,11 @@ func newAzureClient(opts providerClientOptions) AzureClient {
2224 azure.WithEndpoint(opts.baseURL, apiVersion),
2325 }
2426
27+ if config.Get().Options.Debug {
28+ httpClient := log.NewHTTPClient()
29+ reqOpts = append(reqOpts, option.WithHTTPClient(httpClient))
30+ }
31+
2532 reqOpts = append(reqOpts, azure.WithAPIKey(opts.apiKey))
2633 base := &openaiClient{
2734 providerOptions: opts,
internal/llm/provider/gemini.go+9−9
@@ -13,6 +13,7 @@ import (
1313 "github.com/charmbracelet/catwalk/pkg/catwalk"
1414 "github.com/charmbracelet/crush/internal/config"
1515 "github.com/charmbracelet/crush/internal/llm/tools"
16+ "github.com/charmbracelet/crush/internal/log"
1617 "github.com/charmbracelet/crush/internal/message"
1718 "github.com/google/uuid"
1819 "google.golang.org/genai"
@@ -39,7 +40,14 @@ func newGeminiClient(opts providerClientOptions) GeminiClient {
3940}
4041
4142func createGeminiClient(opts providerClientOptions) (*genai.Client, error) {
42− client, err := genai.NewClient(context.Background(), &genai.ClientConfig{APIKey: opts.apiKey, Backend: genai.BackendGeminiAPI})
43+ cc := &genai.ClientConfig{
44+ APIKey: opts.apiKey,
45+ Backend: genai.BackendGeminiAPI,
46+ }
47+ if config.Get().Options.Debug {
48+ cc.HTTPClient = log.NewHTTPClient()
49+ }
50+ client, err := genai.NewClient(context.Background(), cc)
4351 if err != nil {
4452 return nil, err
4553 }
@@ -166,10 +174,6 @@ func (g *geminiClient) send(ctx context.Context, messages []message.Message, too
166174 geminiMessages := g.convertMessages(messages)
167175 model := g.providerOptions.model(g.providerOptions.modelType)
168176 cfg := config.Get()
169− if cfg.Options.Debug {
170− jsonData, _ := json.Marshal(geminiMessages)
171− slog.Debug("Prepared messages", "messages", string(jsonData))
172− }
173177
174178 modelConfig := cfg.Models[config.SelectedModelTypeLarge]
175179 if g.providerOptions.modelType == config.SelectedModelTypeSmall {
@@ -266,10 +270,6 @@ func (g *geminiClient) stream(ctx context.Context, messages []message.Message, t
266270
267271 model := g.providerOptions.model(g.providerOptions.modelType)
268272 cfg := config.Get()
269− if cfg.Options.Debug {
270− jsonData, _ := json.Marshal(geminiMessages)
271− slog.Debug("Prepared messages", "messages", string(jsonData))
272− }
273273
274274 modelConfig := cfg.Models[config.SelectedModelTypeLarge]
275275 if g.providerOptions.modelType == config.SelectedModelTypeSmall {
internal/llm/provider/openai.go+7−18
@@ -2,7 +2,6 @@ package provider
22
33import (
44 "context"
5− "encoding/json"
65 "errors"
76 "fmt"
87 "io"
@@ -13,6 +12,7 @@ import (
1312 "github.com/charmbracelet/catwalk/pkg/catwalk"
1413 "github.com/charmbracelet/crush/internal/config"
1514 "github.com/charmbracelet/crush/internal/llm/tools"
15+ "github.com/charmbracelet/crush/internal/log"
1616 "github.com/charmbracelet/crush/internal/message"
1717 "github.com/openai/openai-go"
1818 "github.com/openai/openai-go/option"
@@ -46,6 +46,11 @@ func createOpenAIClient(opts providerClientOptions) openai.Client {
4646 }
4747 }
4848
49+ if config.Get().Options.Debug {
50+ httpClient := log.NewHTTPClient()
51+ openaiClientOptions = append(openaiClientOptions, option.WithHTTPClient(httpClient))
52+ }
53+
4954 for key, value := range opts.extraHeaders {
5055 openaiClientOptions = append(openaiClientOptions, option.WithHeader(key, value))
5156 }
@@ -250,11 +255,6 @@ func (o *openaiClient) preparedParams(messages []openai.ChatCompletionMessagePar
250255
251256func (o *openaiClient) send(ctx context.Context, messages []message.Message, tools []tools.BaseTool) (response *ProviderResponse, err error) {
252257 params := o.preparedParams(o.convertMessages(messages), o.convertTools(tools))
253− cfg := config.Get()
254− if cfg.Options.Debug {
255− jsonData, _ := json.Marshal(params)
256− slog.Debug("Prepared messages", "messages", string(jsonData))
257− }
258258 attempts := 0
259259 for {
260260 attempts++
@@ -311,12 +311,6 @@ func (o *openaiClient) stream(ctx context.Context, messages []message.Message, t
311311 IncludeUsage: openai.Bool(true),
312312 }
313313
314− cfg := config.Get()
315− if cfg.Options.Debug {
316− jsonData, _ := json.Marshal(params)
317− slog.Debug("Prepared messages", "messages", string(jsonData))
318− }
319−
320314 attempts := 0
321315 eventChan := make(chan ProviderEvent)
322316
@@ -420,11 +414,6 @@ func (o *openaiClient) stream(ctx context.Context, messages []message.Message, t
420414
421415 err := openaiStream.Err()
422416 if err == nil || errors.Is(err, io.EOF) {
423− if cfg.Options.Debug {
424− jsonData, _ := json.Marshal(acc.ChatCompletion)
425− slog.Debug("Response", "messages", string(jsonData))
426− }
427−
428417 if len(acc.Choices) == 0 {
429418 eventChan <- ProviderEvent{
430419 Type: EventError,
@@ -525,7 +514,7 @@ func (o *openaiClient) shouldRetry(attempts int, err error) (bool, int64, error)
525514 slog.Warn("Retry-After header", "values", retryAfterValues)
526515 }
527516 } else {
528− slog.Warn("OpenAI API error", "error", err.Error())
517+ slog.Error("OpenAI API error", "error", err.Error(), "attempt", attempts, "max_retries", maxRetries)
529518 }
530519
531520 backoffMs := 2000 * (1 << (attempts - 1))
internal/llm/provider/vertexai.go+8−2
@@ -5,6 +5,8 @@ import (
55 "log/slog"
66 "strings"
77
8+ "github.com/charmbracelet/crush/internal/config"
9+ "github.com/charmbracelet/crush/internal/log"
810 "google.golang.org/genai"
911)
1012
@@ -13,11 +15,15 @@ type VertexAIClient ProviderClient
1315func newVertexAIClient(opts providerClientOptions) VertexAIClient {
1416 project := opts.extraParams["project"]
1517 location := opts.extraParams["location"]
16− client, err := genai.NewClient(context.Background(), &genai.ClientConfig{
18+ cc := &genai.ClientConfig{
1719 Project: project,
1820 Location: location,
1921 Backend: genai.BackendVertexAI,
20− })
22+ }
23+ if config.Get().Options.Debug {
24+ cc.HTTPClient = log.NewHTTPClient()
25+ }
26+ client, err := genai.NewClient(context.Background(), cc)
2127 if err != nil {
2228 slog.Error("Failed to create VertexAI client", "error", err)
2329 return nil
internal/log/http.gonew file+125
@@ -0,0 +1,125 @@
1+package log
2+
3+import (
4+ "bytes"
5+ "context"
6+ "encoding/json"
7+ "io"
8+ "log/slog"
9+ "net/http"
10+ "strings"
11+ "time"
12+)
13+
14+// NewHTTPClient creates an HTTP client with debug logging enabled when debug mode is on.
15+func NewHTTPClient() *http.Client {
16+ if !slog.Default().Enabled(context.TODO(), slog.LevelDebug) {
17+ return http.DefaultClient
18+ }
19+ return &http.Client{
20+ Transport: &HTTPRoundTripLogger{
21+ Transport: http.DefaultTransport,
22+ },
23+ }
24+}
25+
26+// HTTPRoundTripLogger is an http.RoundTripper that logs requests and responses.
27+type HTTPRoundTripLogger struct {
28+ Transport http.RoundTripper
29+}
30+
31+// RoundTrip implements http.RoundTripper interface with logging.
32+func (h *HTTPRoundTripLogger) RoundTrip(req *http.Request) (*http.Response, error) {
33+ var err error
34+ var save io.ReadCloser
35+ save, req.Body, err = drainBody(req.Body)
36+ if err != nil {
37+ slog.Error(
38+ "HTTP request failed",
39+ "method", req.Method,
40+ "url", req.URL,
41+ "error", err,
42+ )
43+ return nil, err
44+ }
45+
46+ slog.Debug(
47+ "HTTP Request",
48+ "method", req.Method,
49+ "url", req.URL,
50+ "body", bodyToString(save),
51+ )
52+
53+ start := time.Now()
54+ resp, err := h.Transport.RoundTrip(req)
55+ duration := time.Since(start)
56+ if err != nil {
57+ slog.Error(
58+ "HTTP request failed",
59+ "method", req.Method,
60+ "url", req.URL,
61+ "duration_ms", duration.Milliseconds(),
62+ "error", err,
63+ )
64+ return resp, err
65+ }
66+
67+ save, resp.Body, err = drainBody(resp.Body)
68+ slog.Debug(
69+ "HTTP Response",
70+ "status_code", resp.StatusCode,
71+ "status", resp.Status,
72+ "headers", formatHeaders(resp.Header),
73+ "body", bodyToString(save),
74+ "content_length", resp.ContentLength,
75+ "duration_ms", duration.Milliseconds(),
76+ "error", err,
77+ )
78+ return resp, err
79+}
80+
81+func bodyToString(body io.ReadCloser) string {
82+ src, err := io.ReadAll(body)
83+ if err != nil {
84+ slog.Error("Failed to read body", "error", err)
85+ return ""
86+ }
87+ var b bytes.Buffer
88+ if json.Compact(&b, bytes.TrimSpace(src)) != nil {
89+ // not json probably
90+ return string(src)
91+ }
92+ return b.String()
93+}
94+
95+// formatHeaders formats HTTP headers for logging, filtering out sensitive information.
96+func formatHeaders(headers http.Header) map[string][]string {
97+ filtered := make(map[string][]string)
98+ for key, values := range headers {
99+ lowerKey := strings.ToLower(key)
100+ // Filter out sensitive headers
101+ if strings.Contains(lowerKey, "authorization") ||
102+ strings.Contains(lowerKey, "api-key") ||
103+ strings.Contains(lowerKey, "token") ||
104+ strings.Contains(lowerKey, "secret") {
105+ filtered[key] = []string{"[REDACTED]"}
106+ } else {
107+ filtered[key] = values
108+ }
109+ }
110+ return filtered
111+}
112+
113+func drainBody(b io.ReadCloser) (r1, r2 io.ReadCloser, err error) {
114+ if b == nil || b == http.NoBody {
115+ return http.NoBody, http.NoBody, nil
116+ }
117+ var buf bytes.Buffer
118+ if _, err = buf.ReadFrom(b); err != nil {
119+ return nil, b, err
120+ }
121+ if err = b.Close(); err != nil {
122+ return nil, b, err
123+ }
124+ return io.NopCloser(&buf), io.NopCloser(bytes.NewReader(buf.Bytes())), nil
125+}
internal/log/http_test.gonew file+73
@@ -0,0 +1,73 @@
1+package log
2+
3+import (
4+ "net/http"
5+ "net/http/httptest"
6+ "strings"
7+ "testing"
8+)
9+
10+func TestHTTPRoundTripLogger(t *testing.T) {
11+ // Create a test server that returns a 500 error
12+ server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
13+ w.Header().Set("Content-Type", "application/json")
14+ w.Header().Set("X-Custom-Header", "test-value")
15+ w.WriteHeader(http.StatusInternalServerError)
16+ w.Write([]byte(`{"error": "Internal server error", "code": 500}`))
17+ }))
18+ defer server.Close()
19+
20+ // Create HTTP client with logging
21+ client := NewHTTPClient()
22+
23+ // Make a request
24+ req, err := http.NewRequestWithContext(
25+ t.Context(),
26+ http.MethodPost,
27+ server.URL,
28+ strings.NewReader(`{"test": "data"}`),
29+ )
30+ if err != nil {
31+ t.Fatal(err)
32+ }
33+ req.Header.Set("Content-Type", "application/json")
34+ req.Header.Set("Authorization", "Bearer secret-token")
35+
36+ resp, err := client.Do(req)
37+ if err != nil {
38+ t.Fatal(err)
39+ }
40+ defer resp.Body.Close()
41+
42+ // Verify response
43+ if resp.StatusCode != http.StatusInternalServerError {
44+ t.Errorf("Expected status code 500, got %d", resp.StatusCode)
45+ }
46+}
47+
48+func TestFormatHeaders(t *testing.T) {
49+ headers := http.Header{
50+ "Content-Type": []string{"application/json"},
51+ "Authorization": []string{"Bearer secret-token"},
52+ "X-API-Key": []string{"api-key-123"},
53+ "User-Agent": []string{"test-agent"},
54+ }
55+
56+ formatted := formatHeaders(headers)
57+
58+ // Check that sensitive headers are redacted
59+ if formatted["Authorization"][0] != "[REDACTED]" {
60+ t.Error("Authorization header should be redacted")
61+ }
62+ if formatted["X-API-Key"][0] != "[REDACTED]" {
63+ t.Error("X-API-Key header should be redacted")
64+ }
65+
66+ // Check that non-sensitive headers are preserved
67+ if formatted["Content-Type"][0] != "application/json" {
68+ t.Error("Content-Type header should be preserved")
69+ }
70+ if formatted["User-Agent"][0] != "test-agent" {
71+ t.Error("User-Agent header should be preserved")
72+ }
73+}