From 9fffde83121414b162199ec522693780d3a43b6c Mon Sep 17 00:00:00 2001
From: oabrivard <olivier@abrivard.fr>
Date: Tue, 24 Mar 2026 20:34:01 +0100
Subject: [PATCH] feat: log LLM calls with timing at search, classification,
 and rewrite steps

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
---
 backend/src/services/synthesis.rs | 41 +++++++++++++++++++++++++++++++
 1 file changed, 41 insertions(+)

diff --git a/backend/src/services/synthesis.rs b/backend/src/services/synthesis.rs
index cd7824c..c8ce996 100644
--- a/backend/src/services/synthesis.rs
+++ b/backend/src/services/synthesis.rs
@@ -271,6 +271,10 @@ async fn run_generation_inner(
         if deleted > 0 {
             tracing::info!(deleted = deleted, "Cleaned up old article history entries");
         }
+        // Truncate old LLM call logs
+        db::llm_call_log::truncate_old(&state.pool, user_id, settings.article_history_days)
+            .await
+            .ok();
     }
 
     if settings.categories.is_empty() {
@@ -504,6 +508,7 @@ async fn run_generation_inner(
                 );
                 let class_schema = build_classification_schema();
 
+                let llm_start = std::time::Instant::now();
                 let class_response = provider
                     .generate_rewrite_pass(
                         &model_research,
@@ -512,6 +517,9 @@ async fn run_generation_inner(
                         &class_schema,
                     )
                     .await?;
+                let llm_duration = llm_start.elapsed().as_millis() as u64;
+                log_llm_call(&state.pool, user_id, job_id, "classification_phase1", &model_research,
+                    &class_system, &class_user, &class_response, llm_duration).await;
 
                 // 1e. Parse classification and fill categories
                 let (phase1_classified, phase1_overflow) = parse_classification_response(
@@ -659,9 +667,13 @@ async fn run_generation_inner(
             Some(&category_gaps),
         );
 
+        let llm_start = std::time::Instant::now();
         let raw_results = provider
             .generate_search_pass(&model_research, &system_prompt, &user_prompt, &search_schema)
             .await?;
+        let llm_duration = llm_start.elapsed().as_millis() as u64;
+        log_llm_call(&state.pool, user_id, job_id, "search", &model_research,
+            &system_prompt, &user_prompt, &raw_results, llm_duration).await;
 
         // Parse + filter
         emit_progress(tx, "parsing", "Analyse des resultats...", 55);
@@ -801,6 +813,7 @@ async fn run_generation_inner(
             );
             let class_schema = build_classification_schema();
 
+            let llm_start = std::time::Instant::now();
             let class_response = provider
                 .generate_rewrite_pass(
                     &model_research,
@@ -809,6 +822,9 @@ async fn run_generation_inner(
                     &class_schema,
                 )
                 .await?;
+            let llm_duration = llm_start.elapsed().as_millis() as u64;
+            log_llm_call(&state.pool, user_id, job_id, "classification_phase2", &model_research,
+                &class_system, &class_user, &class_response, llm_duration).await;
 
             let (phase2_classified, phase2_overflow) = parse_classification_response(
                 &class_response,
@@ -898,9 +914,13 @@ async fn run_generation_inner(
     let (rewrite_system, rewrite_user) = prompts::build_rewrite_prompt(&all_scraped);
     let rewrite_schema = build_rewrite_schema(&all_scraped, &settings.categories);
 
+    let llm_start = std::time::Instant::now();
     let final_results = provider
         .generate_rewrite_pass(&model_writing, &rewrite_system, &rewrite_user, &rewrite_schema)
         .await?;
+    let llm_duration = llm_start.elapsed().as_millis() as u64;
+    log_llm_call(&state.pool, user_id, job_id, "rewrite", &model_writing,
+        &rewrite_system, &rewrite_user, &final_results, llm_duration).await;
 
     emit_progress(tx, "finalizing", "Finalisation...", 90);
     let mut final_sections = build_final_sections(&final_results, &settings.categories)?;
@@ -999,6 +1019,27 @@ async fn trace_article(
     db::article_history::insert_entry(pool, &entry).await.ok();
 }
 
+/// Log an LLM call with full prompt, response, and timing.
+async fn log_llm_call(
+    pool: &sqlx::PgPool,
+    user_id: Uuid,
+    job_id: Uuid,
+    call_type: &str,
+    model: &str,
+    system_prompt: &str,
+    user_prompt: &str,
+    response: &serde_json::Value,
+    duration_ms: u64,
+) {
+    let response_str = serde_json::to_string_pretty(response).unwrap_or_default();
+    db::llm_call_log::insert(
+        pool, user_id, job_id, call_type, model,
+        system_prompt, user_prompt, &response_str, duration_ms as i32,
+    )
+    .await
+    .ok(); // Don't fail synthesis if logging fails
+}
+
 /// Look up or create a per-user rate limiter stored in AppState.
 ///
 /// Returns `None` if the user has no rate limit overrides, in which case the