Log raw LLM query metadata

bauersimon · bauersimon · commit 65f0fdeda22c · 2025-04-23T17:03:04.000+02:00
Closes #426
diff --git a/evaluate/evaluate_test.go b/evaluate/evaluate_test.go
@@ -181,7 +181,7 @@ func TestEvaluate(t *testing.T) {
 					},
 				}
 				// Set up mocks, when test is running.
-				mockedQuery.On("Query", mock.Anything, mock.Anything, mock.Anything).Return(queryResult1, nil).Once().After(10 * time.Millisecond) // Simulate a model response delay because our internal safety measures trigger when a query is done in 0 milliseconds.
+				mockedQuery.On("Query", mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(queryResult1, nil).Once().After(10 * time.Millisecond) // Simulate a model response delay because our internal safety measures trigger when a query is done in 0 milliseconds.
 
 				queryResult2 := &provider.QueryResult{
 					Message: "",
@@ -192,7 +192,7 @@ func TestEvaluate(t *testing.T) {
 					},
 				}
 				// Set up mocks, when test is running.
-				mockedQuery.On("Query", mock.Anything, mock.Anything, mock.Anything).Return(queryResult2, nil).Once().After(10 * time.Millisecond) // Simulate a model response delay because our internal safety measures trigger when a query is done in 0 milliseconds.
+				mockedQuery.On("Query", mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(queryResult2, nil).Once().After(10 * time.Millisecond) // Simulate a model response delay because our internal safety measures trigger when a query is done in 0 milliseconds.
 			},
 			After: func(t *testing.T, logger *log.Logger, resultPath string) {
 				mockedQuery.AssertNumberOfCalls(t, "Query", 2)
@@ -380,10 +380,10 @@ func TestEvaluate(t *testing.T) {
 						Message: "model-response",
 					}
 					// Set up mocks, when test is running.
-					mockedQuery.On("Query", mock.Anything, mock.Anything, mock.Anything).Return(nil, ErrEmptyResponseFromModel).Once()
-					mockedQuery.On("Query", mock.Anything, mock.Anything, mock.Anything).Return(queryResult, nil).Once().After(10 * time.Millisecond) // Simulate a model response delay because our internal safety measures trigger when a query is done in 0 milliseconds.
-					mockedQuery.On("Query", mock.Anything, mock.Anything, mock.Anything).Return(nil, ErrEmptyResponseFromModel).Once()
-					mockedQuery.On("Query", mock.Anything, mock.Anything, mock.Anything).Return(queryResult, nil).Once().After(10 * time.Millisecond) // Simulate a model response delay because our internal safety measures trigger when a query is done in 0 milliseconds.
+					mockedQuery.On("Query", mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(nil, ErrEmptyResponseFromModel).Once()
+					mockedQuery.On("Query", mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(queryResult, nil).Once().After(10 * time.Millisecond) // Simulate a model response delay because our internal safety measures trigger when a query is done in 0 milliseconds.
+					mockedQuery.On("Query", mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(nil, ErrEmptyResponseFromModel).Once()
+					mockedQuery.On("Query", mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(queryResult, nil).Once().After(10 * time.Millisecond) // Simulate a model response delay because our internal safety measures trigger when a query is done in 0 milliseconds.
 				},
 				After: func(t *testing.T, logger *log.Logger, resultPath string) {
 					mockedQuery.AssertNumberOfCalls(t, "Query", 4)
diff --git a/model/llm/llm_test.go b/model/llm/llm_test.go
@@ -120,7 +120,7 @@ func TestModelGenerateTestsForFile(t *testing.T) {
 				` + "```" + `
 			`),
 			}
-			mockedProvider.On("Query", mock.Anything, mock.Anything, promptMessage).Return(queryResult, nil)
+			mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything, promptMessage).Return(queryResult, nil)
 		},
 
 		Language:          &golang.Language{},
@@ -151,7 +151,7 @@ func TestModelGenerateTestsForFile(t *testing.T) {
 					TotalCost: 0.123456789,
 				},
 			}
-			mockedProvider.On("Query", mock.Anything, mock.Anything, promptMessage).Return(queryResult, nil)
+			mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything, promptMessage).Return(queryResult, nil)
 		},
 
 		Language:          &golang.Language{},
@@ -242,7 +242,7 @@ func TestModelQuery(t *testing.T) {
 			queryResult := &provider.QueryResult{
 				Message: "test response",
 			}
-			mockedProvider.On("Query", mock.Anything, mock.Anything, "test request").Return(queryResult, nil)
+			mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything, "test request").Return(queryResult, nil)
 		},
 		QueryAttempts: 1,
 		Request:       "test request",
@@ -256,7 +256,7 @@ func TestModelQuery(t *testing.T) {
 	validate(t, &testCase{
 		Name: "Failed query no retry",
 		SetupMock: func(mockedProvider *providertesting.MockQuery) {
-			mockedProvider.On("Query", mock.Anything, mock.Anything, "test request").Return(nil, assert.AnError)
+			mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything, "test request").Return(nil, assert.AnError)
 		},
 		QueryAttempts: 1,
 		Request:       "test request",
@@ -266,8 +266,8 @@ func TestModelQuery(t *testing.T) {
 	validate(t, &testCase{
 		Name: "Failed query with retry",
 		SetupMock: func(mockedProvider *providertesting.MockQuery) {
-			mockedProvider.On("Query", mock.Anything, mock.Anything, "test request").Return(nil, assert.AnError).Once()
-			mockedProvider.On("Query", mock.Anything, mock.Anything, "test request").Return(&provider.QueryResult{
+			mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything, "test request").Return(nil, assert.AnError).Once()
+			mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything, "test request").Return(&provider.QueryResult{
 				Message: "test response",
 			}, nil).Once()
 		},
@@ -286,7 +286,7 @@ func TestModelQuery(t *testing.T) {
 			queryResult := &provider.QueryResult{
 				Message: "test response",
 			}
-			mockedProvider.On("Query", mock.Anything, mock.Anything, "test request").Return(queryResult, nil).After(time.Second * 2)
+			mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything, "test request").Return(queryResult, nil).After(time.Second * 2)
 		},
 		QueryAttempts: 1,
 		QueryTimeout:  1,
@@ -300,8 +300,8 @@ func TestModelQuery(t *testing.T) {
 			queryResult := &provider.QueryResult{
 				Message: "test response",
 			}
-			mockedProvider.On("Query", mock.Anything, mock.Anything, "test request").Return(queryResult, nil).After(time.Second * 2)
-			mockedProvider.On("Query", mock.Anything, mock.Anything, "test request").Return(queryResult, nil).After(time.Second * 2)
+			mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything, "test request").Return(queryResult, nil).After(time.Second * 2)
+			mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything, "test request").Return(queryResult, nil).After(time.Second * 2)
 		},
 		QueryAttempts: 2,
 		QueryTimeout:  1,
@@ -392,7 +392,7 @@ func TestModelRepairSourceCodeFile(t *testing.T) {
 						` + "```" + `
 					`),
 				}
-				mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything).Return(queryResult, nil)
+				mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(queryResult, nil)
 			},
 
 			Language:       &golang.Language{},
@@ -446,7 +446,7 @@ func TestModelRepairSourceCodeFile(t *testing.T) {
 						` + "```" + `
 					`),
 				}
-				mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything).Return(queryResult, nil)
+				mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(queryResult, nil)
 			},
 
 			Language:       &java.Language{},
@@ -876,7 +876,7 @@ func TestModelTranspile(t *testing.T) {
 				queryResult := &provider.QueryResult{
 					Message: "```\n" + transpiledFileContent + "```\n",
 				}
-				mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything).Return(queryResult, nil)
+				mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(queryResult, nil)
 			},
 
 			Language:       &golang.Language{},
@@ -929,7 +929,7 @@ func TestModelTranspile(t *testing.T) {
 				queryResult := &provider.QueryResult{
 					Message: "```\n" + transpiledFileContent + "```\n",
 				}
-				mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything).Return(queryResult, nil)
+				mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(queryResult, nil)
 			},
 
 			Language:       &java.Language{},
@@ -1032,7 +1032,7 @@ func TestModelMigrate(t *testing.T) {
 			queryResult := &provider.QueryResult{
 				Message: "```\n" + migratedTestFile + "```\n",
 			}
-			mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything).Return(queryResult, nil)
+			mockedProvider.On("Query", mock.Anything, mock.Anything, mock.Anything, mock.Anything).Return(queryResult, nil)
 		},
 
 		Language: &java.Language{},
diff --git a/provider/openrouter/openrouter.go b/provider/openrouter/openrouter.go
@@ -170,7 +170,14 @@ func (p *Provider) fetchGenerationInfo(logger *log.Logger, generationID string)
 	client := &http.Client{}
 	var responseBody []byte
 	if err := retry.Do( // Query available models with a retry logic cause "openrouter.ai" has failed us in the past.
-		func() error {
+		func() (err error) {
+			logger.Info("getting request metadata from openrouter.ai", "response-id", generationID)
+			defer func() {
+				if err != nil {
+					logger.Error("getting request metadata errored", "response-id", generationID, "error", err.Error())
+				}
+			}()
+
 			response, err := client.Do(request)
 			if err != nil {
 				return pkgerrors.WithStack(err)
@@ -200,6 +207,7 @@ func (p *Provider) fetchGenerationInfo(logger *log.Logger, generationID string)
 		return nil, err
 	}
 
+	logger.Info("obtained request metadata", "response-id", generationID, "metadata", string(responseBody))
 	var dataResponse struct {
 		provider.GenerationInfo `json:"data"`
 	}
