innate_core/
llm_trace.rs

1//! LLM / embedding HTTP call tracing.
2//!
3//! Every chat (distill) and embedding request flows through `llm::post_json_retry`,
4//! which calls [`record`] once per call with the final outcome. Traces are appended
5//! as JSONL to `~/.innate/logs/llm_trace.log` (size-capped with single-file rotation)
6//! so any process — MCP, CLI, evolve — contributes automatically, failures included.
7//!
8//! Design notes:
9//! - **Never logs the API key.** Only the request *body* is captured; the
10//!   `Authorization` header is not passed in and is never recorded.
11//! - Request/response bodies are truncated to keep the log bounded.
12//! - Disable entirely with `INNATE_LLM_TRACE=0`.
13
14use std::io::Write;
15use std::time::Duration;
16
17use serde_json::{json, Value};
18
19use crate::errors::{InnateError, Result};
20
21/// Max bytes for request/response preview each.
22const PREVIEW_CAP: usize = 4000;
23/// Rotate the trace file once it exceeds this size (5 MiB).
24const ROTATE_BYTES: u64 = 5 * 1024 * 1024;
25
26/// Whether tracing is enabled (default on; `INNATE_LLM_TRACE=0` turns it off).
27fn enabled() -> bool {
28    !matches!(
29        std::env::var("INNATE_LLM_TRACE").ok().as_deref(),
30        Some("0") | Some("false") | Some("off")
31    )
32}
33
34/// Record one LLM/embedding call outcome. Best-effort: tracing failures never
35/// affect the caller (the LLM call result is returned regardless).
36///
37/// * `label`  — call-site kind from `post_json_retry` ("LLM" / "Anthropic" / "Embedding").
38/// * `url`    — full endpoint URL (only the host is stored).
39/// * `request`— the JSON body sent (contains the prompt/input; no API key).
40/// * `outcome`— the final `Result` after retries.
41/// * `attempts` / `elapsed` — retry count and total wall time.
42pub fn record(
43    label: &str,
44    url: &str,
45    request: &Value,
46    outcome: &Result<Value>,
47    attempts: u32,
48    elapsed: Duration,
49) {
50    if !enabled() {
51        return;
52    }
53    let entry = build_entry(label, url, request, outcome, attempts, elapsed);
54    // Serialize to a single line; swallow any error (diagnostics must not break calls).
55    if let Ok(line) = serde_json::to_string(&entry) {
56        let _ = append_line(&line);
57    }
58}
59
60fn build_entry(
61    label: &str,
62    url: &str,
63    request: &Value,
64    outcome: &Result<Value>,
65    attempts: u32,
66    elapsed: Duration,
67) -> Value {
68    let kind = match label {
69        "Embedding" => "embedding",
70        _ => "chat",
71    };
72    let model = request.get("model").and_then(Value::as_str).unwrap_or("");
73    let (status, error, response_preview, usage) = match outcome {
74        Ok(resp) => (
75            "ok".to_string(),
76            Value::Null,
77            json!(truncate(&resp.to_string())),
78            resp.get("usage").cloned().unwrap_or(Value::Null),
79        ),
80        Err(e) => {
81            let msg = e.to_string();
82            (classify_error(&msg), json!(msg), Value::Null, Value::Null)
83        }
84    };
85
86    json!({
87        "ts": crate::utils::utc_now_iso(),
88        "kind": kind,
89        "label": label,
90        "model": model,
91        "host": host_of(url),
92        "status": status,
93        "attempts": attempts,
94        "latency_ms": elapsed.as_millis() as u64,
95        "token_usage": usage,
96        "error": error,
97        "request_preview": truncate(&request.to_string()),
98        "response_preview": response_preview,
99    })
100}
101
102/// Coarse status bucket derived from the error message produced by `post_json_retry`
103/// (e.g. `"Embedding HTTP error: <ureq Error>"`). Buckets: `http_4xx`, `http_5xx`,
104/// `rate_limited`, `transport`, `error`.
105fn classify_error(msg: &str) -> String {
106    let lower = msg.to_ascii_lowercase();
107    if lower.contains("status: 429") || lower.contains("429 ") {
108        "rate_limited".into()
109    } else if let Some(code) = extract_status_code(&lower) {
110        if (500..=599).contains(&code) {
111            "http_5xx".into()
112        } else if (400..=499).contains(&code) {
113            "http_4xx".into()
114        } else {
115            "error".into()
116        }
117    } else if lower.contains("transport") || lower.contains("connection") || lower.contains("tls") {
118        "transport".into()
119    } else {
120        "error".into()
121    }
122}
123
124/// Pull the first 3-digit HTTP status (e.g. from "status: 404") out of a message.
125fn extract_status_code(lower: &str) -> Option<u16> {
126    let bytes = lower.as_bytes();
127    for i in 0..bytes.len().saturating_sub(2) {
128        if bytes[i].is_ascii_digit()
129            && bytes[i + 1].is_ascii_digit()
130            && bytes[i + 2].is_ascii_digit()
131        {
132            let three = &lower[i..i + 3];
133            if let Ok(code) = three.parse::<u16>() {
134                if (100..=599).contains(&code) {
135                    return Some(code);
136                }
137            }
138        }
139    }
140    None
141}
142
143fn host_of(url: &str) -> String {
144    url.split("://")
145        .nth(1)
146        .unwrap_or(url)
147        .split('/')
148        .next()
149        .unwrap_or("")
150        .to_string()
151}
152
153fn truncate(s: &str) -> String {
154    if s.len() <= PREVIEW_CAP {
155        return s.to_string();
156    }
157    // Truncate on a char boundary to keep valid UTF-8.
158    let mut end = PREVIEW_CAP;
159    while end > 0 && !s.is_char_boundary(end) {
160        end -= 1;
161    }
162    format!("{}…[truncated {} bytes]", &s[..end], s.len() - end)
163}
164
165fn append_line(line: &str) -> std::io::Result<()> {
166    let path = crate::paths::llm_trace_path();
167    if let Some(dir) = path.parent() {
168        std::fs::create_dir_all(dir)?;
169    }
170    rotate_if_large(&path);
171    let mut f = std::fs::OpenOptions::new()
172        .create(true)
173        .append(true)
174        .open(&path)?;
175    writeln!(f, "{line}")
176}
177
178/// Single-file rotation: when the log exceeds `ROTATE_BYTES`, move it to `.1`
179/// (replacing any previous `.1`) so the active file stays bounded.
180fn rotate_if_large(path: &std::path::Path) {
181    if let Ok(meta) = std::fs::metadata(path) {
182        if meta.len() >= ROTATE_BYTES {
183            let rotated = path.with_extension("log.1");
184            let _ = std::fs::rename(path, rotated);
185        }
186    }
187}
188
189/// Read the most recent trace entries (newest first) for the web viewer. Optional
190/// exact-match filters on `kind` ("chat"/"embedding") and `status`. Read-only.
191pub fn read_recent(limit: usize, kind: Option<&str>, status: Option<&str>) -> Result<Vec<Value>> {
192    let path = crate::paths::llm_trace_path();
193    let text = match std::fs::read_to_string(&path) {
194        Ok(t) => t,
195        Err(e) if e.kind() == std::io::ErrorKind::NotFound => return Ok(Vec::new()),
196        Err(e) => return Err(InnateError::Other(format!("read llm_trace.log: {e}"))),
197    };
198    let mut out = Vec::new();
199    for line in text.lines().rev() {
200        if line.trim().is_empty() {
201            continue;
202        }
203        let Ok(v) = serde_json::from_str::<Value>(line) else {
204            continue; // skip malformed lines rather than failing the whole view
205        };
206        if let Some(k) = kind {
207            if v.get("kind").and_then(Value::as_str) != Some(k) {
208                continue;
209            }
210        }
211        if let Some(s) = status {
212            if v.get("status").and_then(Value::as_str) != Some(s) {
213                continue;
214            }
215        }
216        out.push(v);
217        if out.len() >= limit {
218            break;
219        }
220    }
221    Ok(out)
222}
223
224#[cfg(test)]
225mod tests {
226    use super::*;
227
228    #[test]
229    fn host_strips_scheme_and_path() {
230        assert_eq!(
231            host_of("https://dashscope.aliyuncs.com/v1/embeddings"),
232            "dashscope.aliyuncs.com"
233        );
234        assert_eq!(host_of("http://127.0.0.1:8788/x"), "127.0.0.1:8788");
235    }
236
237    #[test]
238    fn truncate_respects_cap_and_utf8() {
239        let s = "a".repeat(PREVIEW_CAP + 50);
240        let t = truncate(&s);
241        assert!(t.contains("truncated"));
242        let multi = "好".repeat(PREVIEW_CAP); // 3 bytes each → exceeds cap
243        let _ = truncate(&multi); // must not panic on char boundary
244    }
245
246    #[test]
247    fn classifies_statuses() {
248        assert_eq!(
249            classify_error("LLM HTTP error: ... status: 404 ..."),
250            "http_4xx"
251        );
252        assert_eq!(
253            classify_error("LLM HTTP error: ... status: 503 ..."),
254            "http_5xx"
255        );
256        assert_eq!(
257            classify_error("Embedding HTTP error: Transport(...)"),
258            "transport"
259        );
260    }
261
262    #[test]
263    fn build_entry_redacts_to_host_and_records_outcome() {
264        let req = json!({"model": "text-embedding-v4", "input": "secret prompt"});
265        let ok: Result<Value> = Ok(json!({"data":[1], "usage":{"prompt_tokens":3}}));
266        let e = build_entry(
267            "Embedding",
268            "https://h.example.com/v1/embeddings",
269            &req,
270            &ok,
271            1,
272            Duration::from_millis(42),
273        );
274        assert_eq!(e["kind"], "embedding");
275        assert_eq!(e["host"], "h.example.com");
276        assert_eq!(e["status"], "ok");
277        assert_eq!(e["model"], "text-embedding-v4");
278        assert_eq!(e["latency_ms"], 42);
279        assert_eq!(e["token_usage"]["prompt_tokens"], 3);
280        // Request body (prompt) is captured; no api key is anywhere in the entry.
281        assert!(e["request_preview"]
282            .as_str()
283            .unwrap()
284            .contains("secret prompt"));
285        assert!(!e.to_string().contains("Authorization"));
286    }
287}
innate_core/llm_trace.rs

innate_core/
llm_trace.rs
