0e52ccd · crush · git.iko.soy

git.iko.soy/crush

on main help sign in

feat: debug logs request response details (#407)

0e52ccdCarlos Alexandro Becker1 year ago

internal/llm/provider/anthropic.go+8−12

compare with main

unifiedsplit

@@ -19,6 +19,7 @@ import (

19 "github.com/charmbracelet/catwalk/pkg/catwalk"

20 "github.com/charmbracelet/crush/internal/config"

21 "github.com/charmbracelet/crush/internal/llm/tools"

22+ "github.com/charmbracelet/crush/internal/log"

22 "github.com/charmbracelet/crush/internal/message"

23 "github.com/charmbracelet/crush/internal/message"

23)

24)

@@ -77,6 +78,12 @@ func createAnthropicClient(opts providerClientOptions, tp AnthropicClientType) a

77 } else if hasBearerAuth {

78 } else if hasBearerAuth {

78 slog.Debug("Skipping X-Api-Key header because Authorization header is provided")

79 slog.Debug("Skipping X-Api-Key header because Authorization header is provided")

79 }

80 }

81+

82+ if config.Get().Options.Debug {

83+ httpClient := log.NewHTTPClient()

84+ anthropicClientOptions = append(anthropicClientOptions, option.WithHTTPClient(httpClient))

85+ }

86+

80 switch tp {

87 switch tp {

81 case AnthropicClientTypeBedrock:

88 case AnthropicClientTypeBedrock:

82 anthropicClientOptions = append(anthropicClientOptions, bedrock.WithLoadDefaultConfig(context.Background()))

89 anthropicClientOptions = append(anthropicClientOptions, bedrock.WithLoadDefaultConfig(context.Background()))

@@ -271,17 +278,11 @@ func (a *anthropicClient) preparedMessages(messages []anthropic.MessageParam, to

271}

278}

272

279

273func (a *anthropicClient) send(ctx context.Context, messages []message.Message, tools []tools.BaseTool) (response *ProviderResponse, err error) {

280func (a *anthropicClient) send(ctx context.Context, messages []message.Message, tools []tools.BaseTool) (response *ProviderResponse, err error) {

274− cfg := config.Get()

275−

276 attempts := 0

281 attempts := 0

277 for {

282 for {

278 attempts++

283 attempts++

279 // Prepare messages on each attempt in case max_tokens was adjusted

284 // Prepare messages on each attempt in case max_tokens was adjusted

280 preparedMessages := a.preparedMessages(a.convertMessages(messages), a.convertTools(tools))

285 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− }

285

286

286 var opts []option.RequestOption

287 var opts []option.RequestOption

287 if a.isThinkingEnabled() {

288 if a.isThinkingEnabled() {

@@ -294,7 +295,7 @@ func (a *anthropicClient) send(ctx context.Context, messages []message.Message,

294 )

295 )

295 // If there is an error we are going to see if we can retry the call

296 // If there is an error we are going to see if we can retry the call

296 if err != nil {

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

298 retry, after, retryErr := a.shouldRetry(attempts, err)

299 retry, after, retryErr := a.shouldRetry(attempts, err)

299 if retryErr != nil {

300 if retryErr != nil {

300 return nil, retryErr

301 return nil, retryErr

@@ -327,7 +328,6 @@ func (a *anthropicClient) send(ctx context.Context, messages []message.Message,

327}

328}

328

329

329func (a *anthropicClient) stream(ctx context.Context, messages []message.Message, tools []tools.BaseTool) <-chan ProviderEvent {

330func (a *anthropicClient) stream(ctx context.Context, messages []message.Message, tools []tools.BaseTool) <-chan ProviderEvent {

330− cfg := config.Get()

331 attempts := 0

332 eventChan := make(chan ProviderEvent)

333 go func() {

@@ -335,10 +335,6 @@ func (a *anthropicClient) stream(ctx context.Context, messages []message.Message

335 attempts++

336 // Prepare messages on each attempt in case max_tokens was adjusted

337 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− }

342

338

343 var opts []option.RequestOption

339 var opts []option.RequestOption

344 if a.isThinkingEnabled() {

340 if a.isThinkingEnabled() {

internal/llm/provider/azure.go+7

@@ -1,6 +1,8 @@

1package provider

3import (

4+ "github.com/charmbracelet/crush/internal/config"

5+ "github.com/charmbracelet/crush/internal/log"

4 "github.com/openai/openai-go"

6 "github.com/openai/openai-go"

5 "github.com/openai/openai-go/azure"

7 "github.com/openai/openai-go/azure"

6 "github.com/openai/openai-go/option"

8 "github.com/openai/openai-go/option"

@@ -22,6 +24,11 @@ func newAzureClient(opts providerClientOptions) AzureClient {

22 azure.WithEndpoint(opts.baseURL, apiVersion),

24 azure.WithEndpoint(opts.baseURL, apiVersion),

23 }

25 }

27+ if config.Get().Options.Debug {

28+ httpClient := log.NewHTTPClient()

29+ reqOpts = append(reqOpts, option.WithHTTPClient(httpClient))

30+ }

31+

25 reqOpts = append(reqOpts, azure.WithAPIKey(opts.apiKey))

32 reqOpts = append(reqOpts, azure.WithAPIKey(opts.apiKey))

26 base := &openaiClient{

33 base := &openaiClient{

27 providerOptions: opts,

34 providerOptions: opts,

internal/llm/provider/gemini.go+9−9

@@ -13,6 +13,7 @@ import (

13 "github.com/charmbracelet/catwalk/pkg/catwalk"

14 "github.com/charmbracelet/crush/internal/config"

15 "github.com/charmbracelet/crush/internal/llm/tools"

16+ "github.com/charmbracelet/crush/internal/log"

16 "github.com/charmbracelet/crush/internal/message"

17 "github.com/charmbracelet/crush/internal/message"

17 "github.com/google/uuid"

18 "github.com/google/uuid"

18 "google.golang.org/genai"

19 "google.golang.org/genai"

@@ -39,7 +40,14 @@ func newGeminiClient(opts providerClientOptions) GeminiClient {

39}

40}

41func createGeminiClient(opts providerClientOptions) (*genai.Client, error) {

42func createGeminiClient(opts providerClientOptions) (*genai.Client, error) {

43+ cc := &genai.ClientConfig{

44+ APIKey: opts.apiKey,

42− client, err := genai.NewClient(context.Background(), &genai.ClientConfig{APIKey: opts.apiKey, Backend: genai.BackendGeminiAPI})

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)

43 if err != nil {

51 if err != nil {

44 return nil, err

52 return nil, err

45 }

53 }

@@ -166,10 +174,6 @@ func (g *geminiClient) send(ctx context.Context, messages []message.Message, too

166 geminiMessages := g.convertMessages(messages)

174 geminiMessages := g.convertMessages(messages)

167 model := g.providerOptions.model(g.providerOptions.modelType)

175 model := g.providerOptions.model(g.providerOptions.modelType)

168 cfg := config.Get()

176 cfg := config.Get()

169− if cfg.Options.Debug {

170− jsonData, _ := json.Marshal(geminiMessages)

171− slog.Debug("Prepared messages", "messages", string(jsonData))

172− }

173

177

174 modelConfig := cfg.Models[config.SelectedModelTypeLarge]

178 modelConfig := cfg.Models[config.SelectedModelTypeLarge]

175 if g.providerOptions.modelType == config.SelectedModelTypeSmall {

179 if g.providerOptions.modelType == config.SelectedModelTypeSmall {

@@ -266,10 +270,6 @@ func (g *geminiClient) stream(ctx context.Context, messages []message.Message, t

266

270

267 model := g.providerOptions.model(g.providerOptions.modelType)

271 model := g.providerOptions.model(g.providerOptions.modelType)

268 cfg := config.Get()

272 cfg := config.Get()

269− if cfg.Options.Debug {

270− jsonData, _ := json.Marshal(geminiMessages)

271− slog.Debug("Prepared messages", "messages", string(jsonData))

272− }

273

274 modelConfig := cfg.Models[config.SelectedModelTypeLarge]

275 if g.providerOptions.modelType == config.SelectedModelTypeSmall {

internal/llm/provider/openai.go+7−18

@@ -2,7 +2,6 @@ package provider

3import (

4 "context"

5− "encoding/json"

6 "errors"

5 "errors"

7 "fmt"

6 "fmt"

8 "io"

7 "io"

@@ -13,6 +12,7 @@ import (

13 "github.com/charmbracelet/catwalk/pkg/catwalk"

12 "github.com/charmbracelet/catwalk/pkg/catwalk"

14 "github.com/charmbracelet/crush/internal/config"

13 "github.com/charmbracelet/crush/internal/config"

15 "github.com/charmbracelet/crush/internal/llm/tools"

14 "github.com/charmbracelet/crush/internal/llm/tools"

15+ "github.com/charmbracelet/crush/internal/log"

16 "github.com/charmbracelet/crush/internal/message"

17 "github.com/openai/openai-go"

18 "github.com/openai/openai-go/option"

@@ -46,6 +46,11 @@ func createOpenAIClient(opts providerClientOptions) openai.Client {

46 }

47 }

49+ if config.Get().Options.Debug {

50+ httpClient := log.NewHTTPClient()

51+ openaiClientOptions = append(openaiClientOptions, option.WithHTTPClient(httpClient))

52+ }

53+

49 for key, value := range opts.extraHeaders {

54 for key, value := range opts.extraHeaders {

50 openaiClientOptions = append(openaiClientOptions, option.WithHeader(key, value))

55 openaiClientOptions = append(openaiClientOptions, option.WithHeader(key, value))

51 }

56 }

@@ -250,11 +255,6 @@ func (o *openaiClient) preparedParams(messages []openai.ChatCompletionMessagePar

250

255

251func (o *openaiClient) send(ctx context.Context, messages []message.Message, tools []tools.BaseTool) (response *ProviderResponse, err error) {

256func (o *openaiClient) send(ctx context.Context, messages []message.Message, tools []tools.BaseTool) (response *ProviderResponse, err error) {

252 params := o.preparedParams(o.convertMessages(messages), o.convertTools(tools))

257 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− }

258 attempts := 0

259 for {

260 attempts++

@@ -311,12 +311,6 @@ func (o *openaiClient) stream(ctx context.Context, messages []message.Message, t

311 IncludeUsage: openai.Bool(true),

312 }

313

314− cfg := config.Get()

315− if cfg.Options.Debug {

316− jsonData, _ := json.Marshal(params)

317− slog.Debug("Prepared messages", "messages", string(jsonData))

318− }

319−

320 attempts := 0

314 attempts := 0

321 eventChan := make(chan ProviderEvent)

315 eventChan := make(chan ProviderEvent)

322

316

@@ -420,11 +414,6 @@ func (o *openaiClient) stream(ctx context.Context, messages []message.Message, t

420

414

421 err := openaiStream.Err()

415 err := openaiStream.Err()

422 if err == nil || errors.Is(err, io.EOF) {

416 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−

428 if len(acc.Choices) == 0 {

417 if len(acc.Choices) == 0 {

429 eventChan <- ProviderEvent{

418 eventChan <- ProviderEvent{

430 Type: EventError,

419 Type: EventError,

@@ -525,7 +514,7 @@ func (o *openaiClient) shouldRetry(attempts int, err error) (bool, int64, error)

525 slog.Warn("Retry-After header", "values", retryAfterValues)

514 slog.Warn("Retry-After header", "values", retryAfterValues)

526 }

515 }

527 } else {

516 } else {

528− slog.Warn("OpenAI API error", "error", err.Error())

517+ slog.Error("OpenAI API error", "error", err.Error(), "attempt", attempts, "max_retries", maxRetries)

529 }

518 }

530

519

531 backoffMs := 2000 * (1 << (attempts - 1))

520 backoffMs := 2000 * (1 << (attempts - 1))

internal/llm/provider/vertexai.go+8−2

@@ -5,6 +5,8 @@ import (

5 "log/slog"

6 "strings"

8+ "github.com/charmbracelet/crush/internal/config"

9+ "github.com/charmbracelet/crush/internal/log"

8 "google.golang.org/genai"

10 "google.golang.org/genai"

11)

@@ -13,11 +15,15 @@ type VertexAIClient ProviderClient

13func newVertexAIClient(opts providerClientOptions) VertexAIClient {

15func newVertexAIClient(opts providerClientOptions) VertexAIClient {

14 project := opts.extraParams["project"]

16 project := opts.extraParams["project"]

15 location := opts.extraParams["location"]

17 location := opts.extraParams["location"]

16− client, err := genai.NewClient(context.Background(), &genai.ClientConfig{

18+ cc := &genai.ClientConfig{

17 Project: project,

19 Project: project,

18 Location: location,

20 Location: location,

19 Backend: genai.BackendVertexAI,

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

21 if err != nil {

27 if err != nil {

22 slog.Error("Failed to create VertexAI client", "error", err)

28 slog.Error("Failed to create VertexAI client", "error", err)

23 return nil

29 return nil

internal/log/http.gonew file+125

@@ -0,0 +1,125 @@

1+package log

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

3+import (

4+ "net/http"

5+ "net/http/httptest"

6+ "strings"

7+ "testing"

8+)

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+}