harn_vm/llm/
trace.rs

1use std::cell::RefCell;
2
3/// A single LLM call trace entry.
4#[derive(Debug, Clone)]
5pub struct LlmTraceEntry {
6    pub model: String,
7    /// Provider that served the call. Carried alongside `model` because
8    /// catalog pricing resolves on the (provider, model) pair, and a trace
9    /// summary that priced by model alone would silently misprice every model
10    /// served by more than one provider.
11    pub provider: String,
12    /// Canonical per-call accounting. Traces carry the ledger rather than a
13    /// second token/cost shape so cache and accelerated-tier pricing cannot be
14    /// lost or recomputed differently by reporting consumers.
15    pub usage: super::usage::LlmUsage,
16    pub duration_ms: u64,
17}
18
19thread_local! {
20    static LLM_TRACE: RefCell<Vec<LlmTraceEntry>> = const { RefCell::new(Vec::new()) };
21    static LLM_TRACING_ENABLED: RefCell<bool> = const { RefCell::new(false) };
22}
23
24/// Enable LLM tracing for the current thread.
25pub fn enable_tracing() {
26    LLM_TRACING_ENABLED.with(|v| *v.borrow_mut() = true);
27}
28
29/// Get and clear the trace log.
30pub fn take_trace() -> Vec<LlmTraceEntry> {
31    LLM_TRACE.with(|v| std::mem::take(&mut *v.borrow_mut()))
32}
33
34/// Clone the current trace log without consuming it.
35pub fn peek_trace() -> Vec<LlmTraceEntry> {
36    LLM_TRACE.with(|v| v.borrow().clone())
37}
38
39/// Summarize trace usage without consuming entries.
40pub fn peek_trace_summary() -> (i64, i64, i64, i64) {
41    LLM_TRACE.with(|v| {
42        let entries = v.borrow();
43        let mut input = 0i64;
44        let mut output = 0i64;
45        let mut duration = 0i64;
46        let count = entries.len() as i64;
47        for e in entries.iter() {
48            input += e.usage.input_tokens;
49            output += e.usage.output_tokens;
50            duration += e.duration_ms as i64;
51        }
52        (input, output, duration, count)
53    })
54}
55
56/// Reset thread-local trace state. Call between test runs.
57pub(crate) fn reset_trace_state() {
58    LLM_TRACE.with(|v| v.borrow_mut().clear());
59    LLM_TRACING_ENABLED.with(|v| *v.borrow_mut() = false);
60}
61
62pub(crate) fn trace_llm_call(entry: LlmTraceEntry) {
63    LLM_TRACING_ENABLED.with(|enabled| {
64        if *enabled.borrow() {
65            LLM_TRACE.with(|v| v.borrow_mut().push(entry));
66        }
67    });
68}
69
70/// The loop and tool facts an agent session already records durably.
71///
72/// Tool activity and loop completion never reached the trace event log:
73/// `ToolExecution`, `ToolRejected`, `LoopIntervention`, `PhaseChange`, and
74/// `LoopComplete` were declared here but no code ever emitted them, so every
75/// summary reported `tool_executions: 0`, `tools_used: []`, and
76/// `status: "unknown"` even for runs whose transcript held the calls (#5997).
77///
78/// The fix is not a second set of events to keep in step with the transcript.
79/// The session that produces `result.tools` and `result.llm` is already the
80/// canonical owner of these facts, so the summary reads them from there.
81#[derive(Debug, Clone, Default)]
82pub struct AgentLoopFacts {
83    pub status: String,
84    pub iterations: usize,
85    /// Wall time for the whole loop, when something canonical measured it.
86    /// `None` serializes as null rather than zero: no agent session records a
87    /// loop duration today, and a zero would read as an instantaneous run.
88    pub total_duration_ms: Option<u64>,
89    pub tool_executions: usize,
90    pub tool_rejections: usize,
91    /// Distinct tools that ran, in first-use order.
92    pub tools_used: Vec<String>,
93}
94
95/// Fine-grained event emitted during agent loop execution. Captures LLM
96/// calls, provider retries, compaction, and typed checkpoints so downstream
97/// consumers (portal, IDE hosts, cloud runners) can display execution traces
98/// without reconstructing them from raw JSON.
99///
100/// Tool and loop-lifecycle facts deliberately do NOT live here; see
101/// [`AgentLoopFacts`].
102#[derive(Debug, Clone, serde::Serialize)]
103#[serde(tag = "type", rename_all = "snake_case")]
104pub enum AgentTraceEvent {
105    LlmCall {
106        call_id: String,
107        model: String,
108        #[serde(flatten)]
109        usage: super::usage::LlmUsage,
110        duration_ms: u64,
111        iteration: usize,
112    },
113    ContextCompaction {
114        archived_messages: usize,
115        new_summary_len: usize,
116        iteration: usize,
117    },
118    /// Emitted when `llm_call` re-prompts the model after the previous
119    /// response failed `output_schema` validation. One event per retry;
120    /// `attempt` counts retries (the initial call is attempt 0 and
121    /// produces no event; the first retry emits `attempt: 1`).
122    ///
123    /// The retry does **not** persist the invalid response — the
124    /// original messages are replayed with a single appended user-role
125    /// correction that cites the validation errors and schema. That
126    /// correction text is surfaced here as `correction_prompt` so
127    /// transcripts show both why the retry happened and what was sent.
128    SchemaRetry {
129        attempt: usize,
130        errors: Vec<String>,
131        nudge_used: bool,
132        correction_prompt: String,
133    },
134    /// Emitted when `llm_call` aborts a streaming provider response
135    /// because the partial JSON content can no longer satisfy
136    /// `output_schema`. `chunks_consumed` counts text-delta chunks seen
137    /// before the abort; `provider` / `model` track the route that fired
138    /// so cost dashboards can attribute the savings.
139    SchemaStreamAborted {
140        provider: String,
141        model: String,
142        reason: String,
143        path: String,
144        chunks_consumed: usize,
145    },
146    TypedCheckpoint {
147        name: String,
148        status: String,
149        checkpoint_attempts: usize,
150        llm_attempts: usize,
151        error_category: Option<String>,
152        errors: Vec<String>,
153        repaired: bool,
154        final_accepted: bool,
155        raw_text: String,
156    },
157    NativeToolFallback {
158        iteration: usize,
159        accepted: bool,
160        policy: String,
161        fallback_index: usize,
162        tool_call_count: usize,
163    },
164    EmptyCompletionRetry {
165        iteration: usize,
166        attempt: usize,
167        provider: String,
168        model: String,
169        reason: String,
170        duration_ms: u64,
171        error: String,
172    },
173    /// Emitted when a `models:`/`ladder:` model ladder advances from one rung
174    /// to the next because the current rung hit a transport-class failure
175    /// (connection/timeout/429/5xx/circuit_open). Schema-validation failures
176    /// never emit this — they re-ask the SAME rung's model. `from_index` is
177    /// the 0-based ladder position that failed; `category` is the failover
178    /// error category that drove the advance.
179    ModelsAdvance {
180        from_index: usize,
181        from_model: String,
182        to_model: String,
183        category: String,
184    },
185}
186
187thread_local! {
188    static AGENT_TRACE: RefCell<Vec<AgentTraceEvent>> = const { RefCell::new(Vec::new()) };
189}
190
191/// Emit an agent trace event.
192pub(crate) fn emit_agent_event(event: AgentTraceEvent) {
193    AGENT_TRACE.with(|v| v.borrow_mut().push(event));
194}
195
196/// Get and clear the agent trace log.
197pub fn take_agent_trace() -> Vec<AgentTraceEvent> {
198    AGENT_TRACE.with(|v| std::mem::take(&mut *v.borrow_mut()))
199}
200
201/// Clone the current agent trace log without consuming it.
202pub fn peek_agent_trace() -> Vec<AgentTraceEvent> {
203    AGENT_TRACE.with(|v| v.borrow().clone())
204}
205
206/// Produce a rolled-up summary of agent trace events as JSON.
207///
208/// The loop and tool fields report `loop_facts: "unavailable"`, because this
209/// entry point has no session to read them from. A caller that holds the
210/// session — the terminal agent result — must use
211/// [`agent_trace_summary_with_loop`] instead, or it will publish zeros beside
212/// a transcript that recorded real tool calls.
213pub fn agent_trace_summary() -> serde_json::Value {
214    agent_trace_summary_inner(None)
215}
216
217/// Produce the summary with loop and tool counters taken from the canonical
218/// session state rather than from trace events, which never carried them.
219pub fn agent_trace_summary_with_loop(facts: &AgentLoopFacts) -> serde_json::Value {
220    agent_trace_summary_inner(Some(facts))
221}
222
223fn agent_trace_summary_inner(facts: Option<&AgentLoopFacts>) -> serde_json::Value {
224    AGENT_TRACE.with(|v| {
225        let events = v.borrow();
226        let mut llm_calls = 0usize;
227        let mut compactions = 0usize;
228        let mut native_text_tool_fallbacks = 0usize;
229        let mut native_text_tool_fallback_rejections = 0usize;
230        let mut empty_completion_retries = 0usize;
231        let mut models_advances = 0usize;
232        let mut schema_stream_aborts = 0usize;
233        let mut typed_checkpoints = 0usize;
234        let mut typed_checkpoint_failures = 0usize;
235        let mut total_input_tokens = 0i64;
236        let mut total_output_tokens = 0i64;
237        let mut total_llm_duration_ms = 0u64;
238
239        let default_facts = AgentLoopFacts::default();
240        let loop_facts = facts.unwrap_or(&default_facts);
241        let status = if facts.is_some() && !loop_facts.status.is_empty() {
242            loop_facts.status.clone()
243        } else {
244            "unknown".to_string()
245        };
246        let loop_facts_source = if facts.is_some() {
247            "observed"
248        } else {
249            "unavailable"
250        };
251
252        for event in events.iter() {
253            match event {
254                AgentTraceEvent::LlmCall {
255                    usage, duration_ms, ..
256                } => {
257                    llm_calls += 1;
258                    total_input_tokens += usage.input_tokens;
259                    total_output_tokens += usage.output_tokens;
260                    total_llm_duration_ms += duration_ms;
261                }
262                AgentTraceEvent::ContextCompaction { .. } => {
263                    compactions += 1;
264                }
265                AgentTraceEvent::SchemaRetry { .. } => {}
266                AgentTraceEvent::SchemaStreamAborted { .. } => {
267                    schema_stream_aborts += 1;
268                }
269                AgentTraceEvent::TypedCheckpoint { final_accepted, .. } => {
270                    typed_checkpoints += 1;
271                    if !final_accepted {
272                        typed_checkpoint_failures += 1;
273                    }
274                }
275                AgentTraceEvent::NativeToolFallback { accepted, .. } => {
276                    native_text_tool_fallbacks += 1;
277                    if !accepted {
278                        native_text_tool_fallback_rejections += 1;
279                    }
280                }
281                AgentTraceEvent::EmptyCompletionRetry { .. } => {
282                    empty_completion_retries += 1;
283                }
284                AgentTraceEvent::ModelsAdvance { .. } => {
285                    models_advances += 1;
286                }
287            }
288        }
289
290        serde_json::json!({
291            // Loop and tool facts come from the session, not from these
292            // events. `loop_facts` says whether a caller supplied them: an
293            // "unavailable" summary is reporting the absence of a session,
294            // not an agent that used no tools.
295            "loop_facts": loop_facts_source,
296            "status": status,
297            "iterations": loop_facts.iterations,
298            "total_duration_ms": loop_facts.total_duration_ms,
299            "tool_executions": loop_facts.tool_executions,
300            "tool_rejections": loop_facts.tool_rejections,
301            "tools_used": loop_facts.tools_used,
302            // Every provider call, including schema retries, empty-completion
303            // retries, and model-ladder advances. `result.llm` counts only the
304            // accepted result of each agent turn, so the two legitimately
305            // differ; `token_scope` names which is which.
306            "token_scope": "every_provider_call",
307            "llm_calls": llm_calls,
308            "compactions": compactions,
309            "native_text_tool_fallbacks": native_text_tool_fallbacks,
310            "native_text_tool_fallback_rejections": native_text_tool_fallback_rejections,
311            "empty_completion_retries": empty_completion_retries,
312            "models_advances": models_advances,
313            "schema_stream_aborts": schema_stream_aborts,
314            "typed_checkpoints": typed_checkpoints,
315            "typed_checkpoint_failures": typed_checkpoint_failures,
316            "total_input_tokens": total_input_tokens,
317            "total_output_tokens": total_output_tokens,
318            "total_llm_duration_ms": total_llm_duration_ms,
319        })
320    })
321}
322
323/// Reset agent trace state. Call between test runs.
324pub(crate) fn reset_agent_trace_state() {
325    AGENT_TRACE.with(|v| v.borrow_mut().clear());
326}
harn_vm/llm/trace.rs

harn_vm/llm/
trace.rs
