diff --git a/run.json b/run.json index 4a74a0c4f..9c5a29c28 100644 --- a/run.json +++ b/run.json @@ -505,7 +505,7 @@ "kind": "running" }, "status_updated_at": "2026-05-25T21:44:41.751851Z", - "last_event_at": "2026-05-25T22:25:11.875226Z", + "last_event_at": "2026-05-25T22:48:07.241039Z", "pending_control": null, "checkpoints": [ { @@ -753,9 +753,9 @@ } }, { - "seq": 0, + "seq": 842, "checkpoint": { - "timestamp": "2026-05-25T22:25:11.925302Z", + "timestamp": "2026-05-25T22:25:15.920641Z", "current_node": "implement", "completed_nodes": [ "start", @@ -766,31 +766,154 @@ ], "node_retries": {}, "context_values": { + "internal.run_id": "01KSGHHBR7DQ1RHFYKD7P46R6F", + "failure_signature": "", + "internal.retry_count.start": 0, + "last_stage": "implement", + "outcome": "succeeded", + "response.implement": "Implemented the stage timing and terminal failure rollup fixes.\n\nSummary of changes:\n- Added per-input `fabro-agent::Session` timing:\n - Tracks LLM inference/stream time and tool execution time.\n - Exposes `SessionInputTiming` via `Session::last_input_timing()`.\n - Resets timing at each `process_input_with_runtime` entry.\n- Threaded timing through workflow LLM backends:\n - `CodergenResult::Text` now carries active `StageTiming`.\n - API backend measures one-shot inference and agent-loop inference/tool time.\n - ACP backend attributes opaque duration to inference.\n- Populated `Outcome.timing` in production handlers:\n - Agent, prompt, fan-in, and command handlers now preserve active timing.\n - Command duration is reported as tool time.\n- Preserved timing/billing for terminal run failures:\n - `persist_terminal_engine_failure` now uses `build_conclusion_from_store` timing and billing.\n - Detached bootstrap/completion guards now preserve conclusion timing/billing when a store exists.\n - Detached failure helper now rolls up timing/billing from the store.\n- Added tests for:\n - Agent per-input inference/tool timing.\n - Agent/prompt/fan-in handler timing propagation.\n - Command handler tool timing.\n - Executor propagation into `NodeResult`.\n - Full workflow event rollup from `Outcome.timing` → `stage.completed` → `run.completed`.\n - Terminal engine failure and drop-guard timing/billing preservation.\n\nValidation passed:\n- `cargo nextest run -p fabro-agent -p fabro-workflow -p fabro-store -p fabro-core`\n - 1913 passed, 122 skipped\n- `cargo +nightly-2026-04-14 fmt --check --all`\n- `cargo +nightly-2026-04-14 clippy --workspace --all-targets -- -D warnings`\n- `cargo build -p fabro-server`\n- `git diff --check`\n\nI did not run the interactive/live server + UI E2E workflow steps, but the server build and full requested automated validation are green.", + "thread.preflight_lint.current_node": "implement", + "thread.start.current_node": "toolchain", + "internal.work_dir": "/home/daytona/workspace/fabro", + "internal.fidelity": "compact", "current_node": "implement", - "graph.rankdir": "LR", - "failure_class": "", + "internal.thread_id": "preflight_lint", + "command.output": "blob://sha256/12ae32cb1ec02d01eda3581b127c1fee3b0dc53572ed6baf239721a03d82e126", + "internal.node_visit_count": 1, "last_response": "Implemented the stage timing and terminal failure rollup fixes.\n\nSummary of changes:\n- Added per-input `fabro-agent::Session` timing:\n - Tracks LLM inference/stream time and tool execution time.\n - ", "thread.toolchain.current_node": "preflight_compile", - "internal.node_visit_count": 1, - "internal.thread_id": "preflight_lint", + "failure_class": "", + "thread.preflight_compile.current_node": "preflight_lint", + "graph.model_stylesheet": "\n * { model: claude-opus-4-7; }\n ", "graph.goal": "# Plan: Fix stage timing (inference + tool) reporting\n\n## Context\n\nThe web UI's Duration popover shows `Active (inference + tools): 0ms` for every run, including agent-heavy runs that obviously did substantial LLM and tool work. Verified on `01KSE2PAVXD56N4TWNK4T5H5VA`: 10 stage.completed events and 1 run.failed event all carry `inference_time_ms: 0, tool_time_ms: 0`, even though stages like `implement@1` (94 min wall) and `simplify_opus@1` (29 min wall) were doing nothing but inference and tool calls.\n\nTwo independent bugs:\n\n1. **No production handler ever populates `Outcome.timing`.** The plumbing from `Outcome.timing` → `NodeResult` (`lib/crates/fabro-core/src/executor.rs:30-37`) → `StageTiming` → `stage.completed` props → projection → billing rollup → run.completed/failed → UI is fully wired and shipped as of #343 (2026-05-21), but `AgentHandler::execute`, `PromptHandler::execute`, `CommandHandler::execute`, and `FanInHandler` all build `Outcome::success()` and never touch `.timing`. The executor falls back to zero, and every downstream consumer faithfully aggregates zero.\n\n2. **`persist_terminal_engine_failure` and its sibling Drop-guard failure paths discard timing/billing entirely.** When the engine returns `Err` (e.g. `VisitLimitExceeded`, which is what killed the user's run), `lib/crates/fabro-workflow/src/operations/start.rs:284-308` builds a `Conclusion` via `build_conclusion_from_store`, then throws it away (`let _conclusion = ...`) and emits `WorkflowRunFailed` with `RunTiming::wall_only(...)` and `None` for billing/diff. The three Drop-guard paths (`start.rs:934`, `1001`, `1033`) do similar with `RunTiming::default()` and never even build a conclusion.\n\nGoal: stage and run events carry real per-stage `inference_time_ms` + `tool_time_ms`; engine-failure terminal events preserve the conclusion's rolled-up timing and billing.\n\n## Approach\n\n### Part A — Capture inference + tool time in handlers (Bug 1)\n\n**A1. `fabro-agent` — accumulate per-input timing in `Session`**\n\n`lib/crates/fabro-agent/src/session.rs`\n\nAdd two `Duration` accumulators to `Session` (initialised to `Duration::ZERO`):\n- `last_input_inference_duration`\n- `last_input_tool_duration`\n\nIn `process_input_with_runtime` (line 1196), zero them at entry so each call's totals are independent.\n\nIn `run_single_input` (line 1254):\n- Wrap the inference span: capture `Instant::now()` immediately before opening the stream at line 1391, and add `.elapsed()` to `last_input_inference_duration` once `response = Some(resp)` (line 1487-1490) OR when the loop exits with an error/cancellation. The whole `'streamattempts` loop counts as inference work — retries included.\n- Wrap the tool span around `execute_tool_calls` at line 1705-1719: `Instant::now()` before, accumulate `.elapsed()` after `.await`.\n\nExpose a getter:\n```rust\npub fn last_input_timing(&self) -> SessionInputTiming { ... }\n```\nwhere `SessionInputTiming { pub inference: Duration, pub tool: Duration }` is a new tiny struct in `fabro-agent`.\n\n**A2. `fabro-workflow` — thread timing through the backend boundary**\n\n`lib/crates/fabro-workflow/src/handler/agent.rs`\n\nExtend `CodergenResult::Text` with a `timing: fabro_types::StageTiming` field (wall is irrelevant — see note below). Update the few `CodergenResult::Text { ... }` constructions found by the explore agent to populate it; existing match-bindings only read `text`/`usage`/`files_touched` so they keep compiling with `..` patterns. `CodergenResult::Full(outcome)` keeps current behaviour — the outcome itself already carries any timing.\n\nNote on wall: `lib/crates/fabro-core/src/executor.rs:30-37` reads ONLY `inference_time_ms` and `tool_time_ms` out of `outcome.timing`. The wall comes from the executor's own stopwatch. So we construct `StageTiming::new(0, inference_ms, tool_ms)` and document that the wall field is ignored in this hop.\n\n`lib/crates/fabro-workflow/src/handler/llm/api.rs`\n\n- `AgentApiBackend::run` (line 1103): after `session.process_input_with_runtime(...)` returns, read `session.last_input_timing()` and set the new `timing` on `CodergenResult::Text` at line 1094.\n- `AgentApiBackend::one_shot` (line 994): wrap the `complete_one_shot_request` call at line 1053 with `Instant::now()` / `.elapsed()`. Accumulate across repair iterations of the surrounding loop. All of it counts as inference; no tool work happens in `one_shot`. Set `timing` on `CodergenResult::Text` at line 1094.\n\n`lib/crates/fabro-workflow/src/handler/llm/acp.rs`\n\n`AgentAcpBackend::run` (line ~140): already exposes `result.duration_ms`. Set `timing: StageTiming::new(0, duration_ms, 0)` on the returned `CodergenResult::Text` (per user decision: attribute all ACP duration to inference; ACP is opaque about the split).\n\n**A3. Consume timing in stage handlers and set `outcome.timing`**\n\n- `lib/crates/fabro-workflow/src/handler/agent.rs:341` — after building `outcome`, before the final `Ok(outcome)`, set `outcome.timing = Some(timing_from_codergen_result)`.\n- `lib/crates/fabro-workflow/src/handler/prompt.rs:180` — same pattern.\n- `lib/crates/fabro-workflow/src/handler/fan_in.rs:266` — backend returns timing; pass it onto the outcome built from the fan-in response.\n- `lib/crates/fabro-workflow/src/handler/command.rs:175` — `outcome.timing = Some(StageTiming::new(0, 0, result.duration_ms))`. All command wall-time is tool time. `result.duration_ms` is already at line 154 in scope.\n\nOther handlers (`human`, `wait`, `conditional`, `parallel`, `start`, `exit`, `structured_output`, `manager_loop`) do no inference or tool work. Leave `outcome.timing` as `None`; the executor will naturally produce `inference: 0, tool: 0` for those stages, which is correct.\n\n### Part B — Preserve conclusion timing on engine failure (Bug 2)\n\n`lib/crates/fabro-workflow/src/operations/start.rs`\n\n**B1. Main path** (`persist_terminal_engine_failure`, line 274-308):\n- Rename `_conclusion` → `conclusion` and use it:\n - Pass `conclusion.timing` (already a `RunTiming` with the proper inference/tool/wall rollup from `build_conclusion_from_parts`) instead of `RunTiming::wall_only(...)`.\n - Pass `conclusion.billing.clone()` instead of `None` for the billing arg of `workflow_run_failed_from_error`.\n - `final_git_commit_sha`, `final_patch`, `diff_summary` stay `None` — those require the finalize-side workspace diff computation that this path deliberately skips.\n\n**B2. Drop-guard paths** (per user decision: fix them too):\n\n- `DetachedRunBootstrapGuard` (line 882-948): add an `Option` field. The bootstrap function builds the guard before the store exists, then mutates `bootstrap_guard.run_store = Some(store.clone())` once the store is in scope. On Drop, if the store is `Some`, the spawned task calls `build_conclusion_from_store` and uses its timing/billing; otherwise falls back to `RunTiming::default()` (pre-store failure means no stages can possibly exist).\n\n- `DetachedRunCompletionGuard` (line 953-1021): armed after the store exists, so add a non-optional `run_store: RunStoreHandle`. Drop's spawned task builds the conclusion and uses it.\n\n- `persist_detached_failure` (line 1023): add a `run_store: &RunStoreHandle` parameter. Call `build_conclusion_from_store` and forward `timing` + `billing` to the failure event. Update the two callers (postrun-related) to pass the store they already have in scope.\n\n`RunStoreHandle` is already `Clone` (the surrounding code clones it routinely), so move-into-spawned-task is fine.\n\n### Critical existing utilities to reuse (do not duplicate)\n\n- `fabro_types::StageTiming::new(wall, inference, tool)` and `RunTiming::new(...)` — invariant-enforcing constructors at `lib/crates/fabro-types/src/timing.rs:38, 91`.\n- `crate::millis_u64(duration)` helper for `Duration → u64` ms in `fabro-workflow` (used widely; see `lifecycle/event.rs:80-86`).\n- `build_conclusion_from_store` at `lib/crates/fabro-workflow/src/pipeline/finalize.rs:71` already does the rollup we need on the engine-failure path.\n- `billing_rollup_from_projection` (called inside `build_conclusion_from_parts`) sums per-stage timings into `RunTiming` — no need to reimplement.\n\n## Tests\n\n- **`fabro-agent` unit test**: feed `Session` a fake `LlmClient` whose `stream` sleeps a known duration and a fake tool that sleeps another known duration. Drive one `process_input_with_runtime` call. Assert `session.last_input_timing()` reports both non-zero and roughly matching the sleeps. Then call again and assert it's per-call (not cumulative).\n- **`fabro-workflow` handler tests**: in `handler/agent.rs`'s test module, wire a `CodergenBackend` that returns `CodergenResult::Text { timing: StageTiming::new(0, 200, 300), .. }` and assert `AgentHandler::execute`'s returned `Outcome.timing` carries those values. Mirror for `prompt.rs` and `fan_in.rs`. Add a `command.rs` test that mocks a `sandbox.exec_command_streaming` returning `duration_ms = 500` and asserts `outcome.timing.tool_time_ms == 500`.\n- **Executor integration**: add a test in `fabro-workflow` (or extend an existing one in `pipeline/finalize.rs` tests) that runs a tiny graph with a handler producing `Outcome.timing = Some(StageTiming::new(0, 100, 50))` and asserts the emitted `stage.completed` event carries those values, and that `run.completed` carries the summed rollup.\n- **`persist_terminal_engine_failure` test**: seed a `RunStore` with a couple of `stage.completed` events whose timing is non-zero, drive the engine-failure path, and assert the emitted `WorkflowRunFailed` event has `timing.inference_time_ms` and `tool_time_ms` matching the per-stage sum and `billing` populated.\n- **Drop guard tests**: trickier because of `Handle::try_current` + spawn. Add focused tests that arm a guard, drop it, and `tokio::task::yield_now().await` enough times to let the spawned task run, then assert the emitted failure event carries non-zero timing.\n- Run `cargo nextest run -p fabro-agent -p fabro-workflow -p fabro-store -p fabro-core`.\n- Run formatter and lints per CLAUDE.md: `cargo +nightly-2026-04-14 fmt --check --all` and `cargo +nightly-2026-04-14 clippy --workspace --all-targets -- -D warnings`.\n\n## End-to-end verification\n\n1. Build the server: `cargo build -p fabro-server`.\n2. Start server: `fabro server start`.\n3. Run a small agent-backed workflow (e.g. `fabro run repl` with a short prompt that fires at least one tool call).\n4. `fabro events --json | jq -s '[.[] | select(.event==\"stage.completed\")] | .[].properties.timing'` — confirm `inference_time_ms > 0` and `tool_time_ms > 0` for the agent stage.\n5. `fabro events --json | jq -s '[.[] | select(.event==\"run.completed\" or .event==\"run.failed\")] | .[].properties.timing'` — confirm `active_time_ms == inference_time_ms + tool_time_ms` and both are non-zero.\n6. Open the run in the web UI (start the SPA dev build per CLAUDE.md or rebuild the embedded SPA with `cargo dev build`), hover the Duration chip, confirm **Active (inference + tools)** is non-zero.\n7. For Bug 2: force an engine failure by setting a very low visit limit and rerunning the same workflow; confirm the `run.failed` event timing breakdown is non-zero and matches the per-stage sum.\n\n## Out of scope\n\n- Adding `wall_time_ms` correctness to `Outcome.timing` (executor ignores it; doc tweak only if necessary).\n- Surfacing inference vs tool split for ACP backend beyond \"all-inference\" attribution.\n- Backfilling timing for historical runs that have already emitted zero events — past events are immutable.\n- Web UI changes beyond what the existing popover already renders.\n", - "internal.retry_count.start": 0, + "internal.retry_count.preflight_lint": 0, + "graph.rankdir": "LR", + "internal.retry_count.implement": 0, + "internal.retry_count.preflight_compile": 0, + "internal.retry_count.toolchain": 0 + }, + "node_outcomes": { + "implement": { + "status": "succeeded", + "context_updates": { + "response.implement": "Implemented the stage timing and terminal failure rollup fixes.\n\nSummary of changes:\n- Added per-input `fabro-agent::Session` timing:\n - Tracks LLM inference/stream time and tool execution time.\n - Exposes `SessionInputTiming` via `Session::last_input_timing()`.\n - Resets timing at each `process_input_with_runtime` entry.\n- Threaded timing through workflow LLM backends:\n - `CodergenResult::Text` now carries active `StageTiming`.\n - API backend measures one-shot inference and agent-loop inference/tool time.\n - ACP backend attributes opaque duration to inference.\n- Populated `Outcome.timing` in production handlers:\n - Agent, prompt, fan-in, and command handlers now preserve active timing.\n - Command duration is reported as tool time.\n- Preserved timing/billing for terminal run failures:\n - `persist_terminal_engine_failure` now uses `build_conclusion_from_store` timing and billing.\n - Detached bootstrap/completion guards now preserve conclusion timing/billing when a store exists.\n - Detached failure helper now rolls up timing/billing from the store.\n- Added tests for:\n - Agent per-input inference/tool timing.\n - Agent/prompt/fan-in handler timing propagation.\n - Command handler tool timing.\n - Executor propagation into `NodeResult`.\n - Full workflow event rollup from `Outcome.timing` → `stage.completed` → `run.completed`.\n - Terminal engine failure and drop-guard timing/billing preservation.\n\nValidation passed:\n- `cargo nextest run -p fabro-agent -p fabro-workflow -p fabro-store -p fabro-core`\n - 1913 passed, 122 skipped\n- `cargo +nightly-2026-04-14 fmt --check --all`\n- `cargo +nightly-2026-04-14 clippy --workspace --all-targets -- -D warnings`\n- `cargo build -p fabro-server`\n- `git diff --check`\n\nI did not run the interactive/live server + UI E2E workflow steps, but the server build and full requested automated validation are green.", + "last_stage": "implement", + "last_response": "Implemented the stage timing and terminal failure rollup fixes.\n\nSummary of changes:\n- Added per-input `fabro-agent::Session` timing:\n - Tracks LLM inference/stream time and tool execution time.\n - " + }, + "notes": "Stage completed: implement", + "usage": { + "input": { + "usage": { + "model": { + "provider": "openai", + "model_id": "gpt-5.5" + }, + "tokens": { + "input_tokens": 2811275, + "output_tokens": 9602, + "reasoning_tokens": 9372, + "cache_read_tokens": 6235136, + "cache_write_tokens": 0 + } + }, + "facts": { + "algorithm": "openai" + } + }, + "total_usd_micros": 17743163 + } + }, + "preflight_compile": { + "status": "succeeded", + "context_updates": { + "command.output": "blob://sha256/12ae32cb1ec02d01eda3581b127c1fee3b0dc53572ed6baf239721a03d82e126" + }, + "notes": "Script completed: cargo check -q --workspace 2>&1", + "usage": null + }, + "preflight_lint": { + "status": "succeeded", + "context_updates": { + "command.output": "blob://sha256/12ae32cb1ec02d01eda3581b127c1fee3b0dc53572ed6baf239721a03d82e126" + }, + "notes": "Script completed: cargo +nightly-2026-04-14 clippy -q --workspace --all-targets -- -D warnings 2>&1", + "usage": null + }, + "start": { + "status": "succeeded", + "usage": null + }, + "toolchain": { + "status": "succeeded", + "context_updates": { + "command.output": "blob://sha256/fc14b2ba2d770e5cd3169df7a29525c962adfc4cfa3097b9098c63ebd61a748c" + }, + "notes": "Script completed: command -v cargo >/dev/null || { curl --proto '=https' --tlsv1.2 -sSf https://sh.rustup.rs | sh -s -- -y && sudo ln -sf $HOME/.cargo/bin/* /usr/local/bin/; }; cargo --version 2>&1", + "usage": null + } + }, + "next_node_id": "simplify_opus", + "git_commit_sha": "7e7d68a963b243d72619380e26cac8d50072094b", + "node_visits": { + "implement": 1, + "preflight_compile": 1, + "preflight_lint": 1, + "toolchain": 1, + "start": 1 + } + }, + "diff": { + "patch": "diff --git a/lib/crates/fabro-agent/src/lib.rs b/lib/crates/fabro-agent/src/lib.rs\nindex e91695865..3669cba75 100644\n--- a/lib/crates/fabro-agent/src/lib.rs\n+++ b/lib/crates/fabro-agent/src/lib.rs\n@@ -61,8 +61,8 @@ pub use sandbox::{\n shell_quote,\n };\n pub use session::{\n- CompletionCoordinator, Session, SessionControlHandle, StaticEnvProvider, SteeringItem,\n- ToolEnvProvider,\n+ CompletionCoordinator, Session, SessionControlHandle, SessionInputTiming, StaticEnvProvider,\n+ SteeringItem, ToolEnvProvider,\n };\n pub use skills::Skill;\n pub use subagent::{\ndiff --git a/lib/crates/fabro-agent/src/session.rs b/lib/crates/fabro-agent/src/session.rs\nindex d97836c0d..24df5149d 100644\n--- a/lib/crates/fabro-agent/src/session.rs\n+++ b/lib/crates/fabro-agent/src/session.rs\n@@ -1,6 +1,6 @@\n use std::collections::{HashMap, VecDeque};\n use std::sync::{Arc, Mutex, RwLock};\n-use std::time::SystemTime;\n+use std::time::{Duration, Instant, SystemTime};\n \n use fabro_auth::CredentialSource;\n use fabro_llm::client::Client;\n@@ -70,6 +70,12 @@ pub enum SteeringItem {\n },\n }\n \n+#[derive(Debug, Clone, Copy, Default, PartialEq, Eq)]\n+pub struct SessionInputTiming {\n+ pub inference: Duration,\n+ pub tool: Duration,\n+}\n+\n impl SteeringItem {\n #[must_use]\n pub fn actor(&self) -> Option<&Principal> {\n@@ -337,6 +343,8 @@ pub struct Session {\n tool_env_provider: Option>,\n subagent_manager: Option>>,\n completion_coordinator: Option>,\n+ last_input_inference_duration: Duration,\n+ last_input_tool_duration: Duration,\n }\n \n impl Session {\n@@ -374,6 +382,8 @@ impl Session {\n tool_env_provider: None,\n subagent_manager,\n completion_coordinator: None,\n+ last_input_inference_duration: Duration::ZERO,\n+ last_input_tool_duration: Duration::ZERO,\n }\n }\n \n@@ -1188,6 +1198,14 @@ impl Session {\n &self.file_tracker\n }\n \n+ #[must_use]\n+ pub const fn last_input_timing(&self) -> SessionInputTiming {\n+ SessionInputTiming {\n+ inference: self.last_input_inference_duration,\n+ tool: self.last_input_tool_duration,\n+ }\n+ }\n+\n pub async fn process_input(&mut self, input: &str) -> Result<(), Error> {\n self.process_input_with_runtime(input, AgentToolRuntime::default())\n .await\n@@ -1198,6 +1216,8 @@ impl Session {\n input: &str,\n agent_tool_runtime: AgentToolRuntime,\n ) -> Result<(), Error> {\n+ self.last_input_inference_duration = Duration::ZERO;\n+ self.last_input_tool_duration = Duration::ZERO;\n if self.state == SessionState::Closed {\n return Err(Error::SessionClosed);\n }\n@@ -1388,6 +1408,16 @@ impl Session {\n };\n let client = self.llm_client.clone();\n let cancel_token_for_select = self.cancel_token.clone();\n+ let mut inference_start = Some(Instant::now());\n+ macro_rules! record_inference_duration {\n+ () => {\n+ if let Some(start) = inference_start.take() {\n+ self.last_input_inference_duration = self\n+ .last_input_inference_duration\n+ .saturating_add(start.elapsed());\n+ }\n+ };\n+ }\n let stream_outcome: Option> = tokio::select! {\n biased;\n () = round_token.cancelled() => None,\n@@ -1395,8 +1425,15 @@ impl Session {\n stream = self.open_stream_with_retry(&client, &request, &retry_policy) => Some(stream),\n };\n let mut event_stream = if let Some(stream) = stream_outcome {\n- stream?\n+ match stream {\n+ Ok(stream) => stream,\n+ Err(err) => {\n+ record_inference_duration!();\n+ return Err(err);\n+ }\n+ }\n } else {\n+ record_inference_duration!();\n if self.cancel_token.is_cancelled() {\n self.close();\n return Err(self.interrupted_error());\n@@ -1472,6 +1509,7 @@ impl Session {\n // If terminal cancel fired, drop the stream and bail out.\n if self.cancel_token.is_cancelled() {\n drop(event_stream);\n+ record_inference_duration!();\n self.close();\n return Err(self.interrupted_error());\n }\n@@ -1538,7 +1576,13 @@ impl Session {\n stream = self.open_stream_with_retry(&client, &request, &retry_policy) => Some(stream),\n };\n event_stream = if let Some(stream) = retry_outcome {\n- stream?\n+ match stream {\n+ Ok(stream) => stream,\n+ Err(err) => {\n+ record_inference_duration!();\n+ return Err(err);\n+ }\n+ }\n } else {\n steer_interrupted =\n round_token.is_cancelled() && !self.cancel_token.is_cancelled();\n@@ -1556,6 +1600,7 @@ impl Session {\n },\n );\n }\n+ record_inference_duration!();\n return Err(self.emit_llm_error(err));\n }\n \n@@ -1584,7 +1629,13 @@ impl Session {\n stream = self.open_stream_with_retry(&client, &request, &retry_policy) => Some(stream),\n };\n event_stream = if let Some(stream) = retry_outcome {\n- stream?\n+ match stream {\n+ Ok(stream) => stream,\n+ Err(err) => {\n+ record_inference_duration!();\n+ return Err(err);\n+ }\n+ }\n } else {\n steer_interrupted =\n round_token.is_cancelled() && !self.cancel_token.is_cancelled();\n@@ -1592,6 +1643,7 @@ impl Session {\n };\n }\n }\n+ record_inference_duration!();\n \n // Mid-LLM steer interrupt: drop the unrecorded turn, clear any\n // partial visible output, and re-iterate. The next turn's\n@@ -1702,6 +1754,7 @@ impl Session {\n \n // Execute tool calls (parallel or sequential based on provider)\n self.transition(SessionState::Executing);\n+ let tool_start = Instant::now();\n let results = execute_tool_calls(\n &tool_calls,\n true,\n@@ -1717,6 +1770,9 @@ impl Session {\n agent_tool_runtime,\n )\n .await;\n+ self.last_input_tool_duration = self\n+ .last_input_tool_duration\n+ .saturating_add(tool_start.elapsed());\n composite_watcher.abort();\n if tool_calls\n .iter()\n@@ -2091,6 +2147,47 @@ mod tests {\n }\n }\n \n+ struct DelayedStreamProvider {\n+ responses: Vec,\n+ delay: Duration,\n+ call_index: AtomicUsize,\n+ }\n+\n+ impl DelayedStreamProvider {\n+ fn new(responses: Vec, delay: Duration) -> Self {\n+ Self {\n+ responses,\n+ delay,\n+ call_index: AtomicUsize::new(0),\n+ }\n+ }\n+ }\n+\n+ #[async_trait::async_trait]\n+ impl ProviderAdapter for DelayedStreamProvider {\n+ fn name(&self) -> &'static str {\n+ \"mock\"\n+ }\n+\n+ async fn complete(&self, _request: &Request) -> Result {\n+ Err(LlmError::Configuration {\n+ message: \"DelayedStreamProvider does not implement complete()\".into(),\n+ source: None,\n+ })\n+ }\n+\n+ async fn stream(&self, _request: &Request) -> Result {\n+ sleep(self.delay).await;\n+ let idx = self.call_index.fetch_add(1, Ordering::SeqCst);\n+ let response = if idx < self.responses.len() {\n+ self.responses[idx].clone()\n+ } else {\n+ self.responses[self.responses.len() - 1].clone()\n+ };\n+ Ok(response_to_stream(response))\n+ }\n+ }\n+\n async fn make_session_with_provider(provider: Arc) -> Session {\n make_session_with_provider_and_manager(provider, None).await\n }\n@@ -2165,6 +2262,56 @@ mod tests {\n }\n }\n \n+ #[tokio::test]\n+ async fn last_input_timing_reports_inference_and_tool_per_call() {\n+ let mut registry = ToolRegistry::new();\n+ registry.register(RegisteredTool {\n+ definition: ToolDefinition {\n+ name: \"slow_tool\".into(),\n+ description: \"Sleeps before returning\".into(),\n+ parameters: serde_json::json!({\"type\": \"object\"}),\n+ },\n+ executor: Arc::new(|_args, _ctx| {\n+ Box::pin(async move {\n+ sleep(Duration::from_millis(30)).await;\n+ Ok(\"slept\".to_string())\n+ })\n+ }),\n+ source: ToolSource::Native,\n+ });\n+ let provider = Arc::new(DelayedStreamProvider::new(\n+ vec![\n+ tool_call_response(\"slow_tool\", \"call_1\", serde_json::json!({})),\n+ text_response(\"Done!\"),\n+ text_response(\"Second response\"),\n+ ],\n+ Duration::from_millis(20),\n+ ));\n+ let client = make_client(provider).await;\n+ let profile = Arc::new(TestProfile::with_tools(registry));\n+ let env = Arc::new(MockSandbox::default());\n+ let mut session = Session::new(client, profile, env, SessionOptions::default(), None);\n+\n+ session.process_input(\"use the slow tool\").await.unwrap();\n+ let first = session.last_input_timing();\n+ assert!(\n+ first.inference >= Duration::from_millis(35),\n+ \"expected non-zero inference timing for first input, got {first:?}\"\n+ );\n+ assert!(\n+ first.tool >= Duration::from_millis(20),\n+ \"expected non-zero tool timing for first input, got {first:?}\"\n+ );\n+\n+ session.process_input(\"no tools this time\").await.unwrap();\n+ let second = session.last_input_timing();\n+ assert!(\n+ second.inference >= Duration::from_millis(15),\n+ \"expected per-input inference timing for second input, got {second:?}\"\n+ );\n+ assert_eq!(second.tool, Duration::ZERO);\n+ }\n+\n struct SequenceToolEnvProvider {\n values: Mutex>>,\n }\ndiff --git a/lib/crates/fabro-core/src/executor.rs b/lib/crates/fabro-core/src/executor.rs\nindex 19cf142a1..3a94eb332 100644\n--- a/lib/crates/fabro-core/src/executor.rs\n+++ b/lib/crates/fabro-core/src/executor.rs\n@@ -555,6 +555,55 @@ mod tests {\n assert_eq!(log.lock().unwrap().clone(), vec![\"start\"]);\n }\n \n+ #[tokio::test]\n+ async fn executor_copies_outcome_active_timing_into_node_result() {\n+ struct TimedHandler;\n+\n+ #[async_trait]\n+ impl NodeHandler for TimedHandler {\n+ async fn execute(\n+ &self,\n+ _node: &TestNode,\n+ _context: &Context,\n+ _graph: &TestGraph,\n+ ) -> Result {\n+ let mut outcome = Outcome::success();\n+ outcome.timing = Some(fabro_types::StageTiming::new(999, 100, 50));\n+ Ok(outcome)\n+ }\n+ }\n+\n+ struct TimingCapture(Arc>>);\n+\n+ #[async_trait]\n+ impl RunLifecycle for TimingCapture {\n+ async fn after_node(\n+ &self,\n+ _node: &TestNode,\n+ result: &mut NodeResult,\n+ _state: &ExecutionState,\n+ ) -> Result<()> {\n+ *self.0.lock().unwrap() = Some((\n+ result.inference_time.as_millis(),\n+ result.tool_time.as_millis(),\n+ ));\n+ Ok(())\n+ }\n+ }\n+\n+ let captured = Arc::new(Mutex::new(None));\n+ let g = linear_graph(&[\"work\", \"end\"]);\n+ let state = ExecutionState::new(&g).unwrap();\n+ let executor =\n+ ExecutorBuilder::new(Arc::new(TimedHandler) as Arc>)\n+ .lifecycle(Box::new(TimingCapture(Arc::clone(&captured))))\n+ .build();\n+\n+ executor.run(&g, state).await.unwrap();\n+\n+ assert_eq!(*captured.lock().unwrap(), Some((100, 50)));\n+ }\n+\n #[tokio::test]\n async fn executor_builder_sets_cancel_token() {\n let token = CancellationToken::new();\ndiff --git a/lib/crates/fabro-types/src/timing.rs b/lib/crates/fabro-types/src/timing.rs\nindex 993511c6a..6ca201143 100644\n--- a/lib/crates/fabro-types/src/timing.rs\n+++ b/lib/crates/fabro-types/src/timing.rs\n@@ -46,8 +46,8 @@ impl StageTiming {\n }\n }\n \n- /// Stages with no inference/tool work (human, wait, conditional, fan-in,\n- /// start, exit, parallel container) report wall time only.\n+ /// Stages with no inference/tool work (human, wait, conditional, start,\n+ /// exit, parallel container) report wall time only.\n #[must_use]\n pub fn wall_only(wall_time_ms: u64) -> Self {\n Self::new(wall_time_ms, 0, 0)\ndiff --git a/lib/crates/fabro-workflow/src/handler/agent.rs b/lib/crates/fabro-workflow/src/handler/agent.rs\nindex 3290ca85a..f7a9048a5 100644\n--- a/lib/crates/fabro-workflow/src/handler/agent.rs\n+++ b/lib/crates/fabro-workflow/src/handler/agent.rs\n@@ -4,7 +4,7 @@ use std::sync::Arc;\n use async_trait::async_trait;\n use fabro_agent::Sandbox;\n use fabro_graphviz::graph::{Graph, Node};\n-use fabro_types::{RunId, StageModelUsage};\n+use fabro_types::{RunId, StageModelUsage, StageTiming};\n pub(crate) use structured_output::extract_status_fields;\n use tokio_util::sync::CancellationToken;\n \n@@ -23,9 +23,12 @@ use crate::outcome::{BilledModelUsage, Outcome, OutcomeExt};\n pub enum CodergenResult {\n Text {\n text: String,\n- usage: Option,\n+ usage: Option>,\n files_touched: Vec,\n last_file_touched: Option,\n+ /// Active timing observed by the backend. The wall field is ignored by\n+ /// the executor on this hop; executor wall time remains authoritative.\n+ timing: StageTiming,\n },\n Full(Box),\n }\n@@ -276,7 +279,7 @@ impl Handler for AgentHandler {\n node_id: node.id.clone(),\n }) as Arc\n });\n- let (response_text, stage_usage, backend_files_touched, last_file_touched) =\n+ let (response_text, stage_usage, backend_files_touched, last_file_touched, timing) =\n if let Some(backend) = &self.backend {\n let result = backend\n .run(CodergenRunRequest {\n@@ -298,7 +301,14 @@ impl Handler for AgentHandler {\n usage,\n files_touched,\n last_file_touched,\n- }) => (text, usage, files_touched, last_file_touched),\n+ timing,\n+ }) => (\n+ text,\n+ usage.map(|usage| *usage),\n+ files_touched,\n+ last_file_touched,\n+ timing,\n+ ),\n Err(Error::Cancelled) => return Err(Error::Cancelled),\n Err(e) if e.is_retryable() => {\n return Err(e);\n@@ -313,6 +323,7 @@ impl Handler for AgentHandler {\n None,\n Vec::new(),\n None,\n+ StageTiming::default(),\n )\n };\n \n@@ -353,7 +364,7 @@ impl Handler for AgentHandler {\n );\n \n if let Some(schema) = structured_output::parse_node_output_schema(node)? {\n- match validate_agent_output_sources(\n+ if let Ok(validated) = validate_agent_output_sources(\n &schema,\n &response_text,\n &services.run.sandbox,\n@@ -361,19 +372,14 @@ impl Handler for AgentHandler {\n )\n .await\n {\n- Ok(validated) => {\n- structured_output::apply_validated_output(\n- node,\n- &schema,\n- &validated,\n- &mut outcome,\n- );\n- }\n- Err(_) => {\n- return Ok(structured_output::exhausted_failure_outcome(\n- node.output_retries(),\n- ));\n- }\n+ structured_output::apply_validated_output(node, &schema, &validated, &mut outcome);\n+ } else {\n+ let mut failed =\n+ structured_output::exhausted_failure_outcome(node.output_retries());\n+ failed.timing = Some(timing);\n+ failed.usage = stage_usage;\n+ failed.files_touched = backend_files_touched;\n+ return Ok(failed);\n }\n } else {\n // 7b. Parse routing directives from response text, falling back to\n@@ -399,6 +405,7 @@ impl Handler for AgentHandler {\n }\n outcome.usage = stage_usage;\n outcome.files_touched = backend_files_touched;\n+ outcome.timing = Some(timing);\n \n Ok(outcome)\n }\n@@ -656,6 +663,7 @@ mod tests {\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: StageTiming::default(),\n })\n }\n }\n@@ -691,6 +699,37 @@ mod tests {\n assert!(outcome.failure.is_none());\n }\n \n+ #[tokio::test]\n+ async fn codergen_handler_copies_backend_timing_to_outcome() {\n+ struct TimingBackend;\n+\n+ #[async_trait]\n+ impl CodergenBackend for TimingBackend {\n+ async fn run(&self, _request: CodergenRunRequest<'_>) -> Result {\n+ Ok(CodergenResult::Text {\n+ text: \"done\".to_string(),\n+ usage: None,\n+ files_touched: Vec::new(),\n+ last_file_touched: None,\n+ timing: StageTiming::new(0, 200, 300),\n+ })\n+ }\n+ }\n+\n+ let handler = AgentHandler::new(Some(Box::new(TimingBackend)));\n+ let node = Node::new(\"step\");\n+ let context = test_context();\n+ let graph = Graph::new(\"test\");\n+ let tmp = TempDir::new().unwrap();\n+\n+ let outcome = handler\n+ .execute(&node, &context, &graph, tmp.path(), &make_services())\n+ .await\n+ .unwrap();\n+\n+ assert_eq!(outcome.timing, Some(StageTiming::new(0, 200, 300)));\n+ }\n+\n #[tokio::test]\n async fn codergen_handler_extracts_status_from_last_file_touched() {\n struct LastFileBackend;\n@@ -703,6 +742,7 @@ mod tests {\n usage: None,\n files_touched: vec![\"results.md\".to_string()],\n last_file_touched: Some(\"results.md\".to_string()),\n+ timing: StageTiming::default(),\n })\n }\n }\n@@ -793,6 +833,7 @@ mod tests {\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: StageTiming::default(),\n })\n }\n }\n@@ -851,6 +892,7 @@ mod tests {\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: StageTiming::default(),\n })\n }\n }\n@@ -907,6 +949,7 @@ mod tests {\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: StageTiming::default(),\n })\n }\n }\n@@ -961,6 +1004,7 @@ mod tests {\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: StageTiming::default(),\n })\n }\n }\n@@ -1005,6 +1049,7 @@ mod tests {\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: StageTiming::default(),\n })\n }\n }\n@@ -1212,6 +1257,7 @@ Some text in between.\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: StageTiming::default(),\n })\n }\n }\n@@ -1272,6 +1318,7 @@ Some text in between.\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: StageTiming::default(),\n })\n }\n }\ndiff --git a/lib/crates/fabro-workflow/src/handler/command.rs b/lib/crates/fabro-workflow/src/handler/command.rs\nindex 63922632a..736731a26 100644\n--- a/lib/crates/fabro-workflow/src/handler/command.rs\n+++ b/lib/crates/fabro-workflow/src/handler/command.rs\n@@ -3,7 +3,7 @@ use std::path::Path;\n use async_trait::async_trait;\n use fabro_agent::CommandOutputCallback;\n use fabro_graphviz::graph::{Graph, Node};\n-use fabro_types::CommandTermination;\n+use fabro_types::{CommandTermination, StageTiming};\n \n use super::{EngineServices, Handler, NodeTimeoutPolicy};\n use crate::command_log::CommandLogRecorder;\n@@ -178,6 +178,7 @@ impl Handler for CommandHandler {\n serde_json::json!(finalized.output_ref),\n );\n outcome.notes = Some(format!(\"Script completed: {script}\"));\n+ outcome.timing = Some(StageTiming::new(0, 0, result.duration_ms));\n Ok(outcome)\n } else {\n let mut reason = format!(\n@@ -190,6 +191,7 @@ impl Handler for CommandHandler {\n keys::COMMAND_OUTPUT.to_string(),\n serde_json::json!(finalized.output_ref),\n );\n+ outcome.timing = Some(StageTiming::new(0, 0, result.duration_ms));\n Ok(outcome)\n }\n }\n@@ -468,6 +470,33 @@ mod tests {\n assert!(!outcome.context_updates.contains_key(\"command.stderr\"));\n }\n \n+ #[tokio::test]\n+ async fn script_handler_reports_command_duration_as_tool_timing() {\n+ let handler = CommandHandler;\n+ let mut node = Node::new(\"script_node\");\n+ node.attrs.insert(\n+ \"script\".to_string(),\n+ AttrValue::String(\"sleep 0.05; echo hello\".to_string()),\n+ );\n+ let context = Context::new();\n+ let graph = Graph::new(\"test\");\n+ let run_dir = tempfile::tempdir().unwrap();\n+\n+ let services = make_services();\n+ let outcome = handler\n+ .execute(&node, &context, &graph, run_dir.path(), &services)\n+ .await\n+ .unwrap();\n+\n+ let timing = outcome.timing.expect(\"command outcome should carry timing\");\n+ assert_eq!(timing.inference_time_ms, 0);\n+ assert!(\n+ timing.tool_time_ms >= 25,\n+ \"expected command duration to be reported as tool time, got {timing:?}\"\n+ );\n+ assert_eq!(timing.active_time_ms, timing.tool_time_ms);\n+ }\n+\n #[tokio::test]\n async fn script_handler_failing_command() {\n let handler = CommandHandler;\ndiff --git a/lib/crates/fabro-workflow/src/handler/fan_in.rs b/lib/crates/fabro-workflow/src/handler/fan_in.rs\nindex 8ba1e251f..aa03d8f74 100644\n--- a/lib/crates/fabro-workflow/src/handler/fan_in.rs\n+++ b/lib/crates/fabro-workflow/src/handler/fan_in.rs\n@@ -4,7 +4,7 @@ use std::sync::Arc;\n use async_trait::async_trait;\n use fabro_agent::Sandbox;\n use fabro_graphviz::graph::{Graph, Node};\n-use fabro_types::StageModelUsage;\n+use fabro_types::{StageModelUsage, StageTiming};\n use tokio_util::sync::CancellationToken;\n \n use super::agent::{CodergenBackend, CodergenResult, CodergenRunRequest};\n@@ -112,7 +112,9 @@ impl Handler for FanInHandler {\n };\n \n if all_failed {\n- return Ok(Outcome::fail_deterministic(\"all candidates failed\"));\n+ let mut outcome = Outcome::fail_deterministic(\"all candidates failed\");\n+ outcome.timing = Some(best.timing);\n+ return Ok(outcome);\n }\n \n // --- Fast-forward to winner's HEAD when git isolation is active ---\n@@ -144,6 +146,7 @@ impl Handler for FanInHandler {\n );\n }\n outcome.notes = Some(format!(\"Selected best candidate: {}\", best.id));\n+ outcome.timing = Some(best.timing);\n \n Ok(outcome)\n }\n@@ -153,6 +156,7 @@ struct Candidate {\n id: String,\n status: String,\n score: f64,\n+ timing: StageTiming,\n }\n \n fn status_rank(status: &str) -> u32 {\n@@ -172,6 +176,7 @@ fn heuristic_select(results: &serde_json::Value) -> Candidate {\n id: \"unknown\".to_string(),\n status: \"failed\".to_string(),\n score: 0.0,\n+ timing: StageTiming::default(),\n };\n }\n \n@@ -192,6 +197,7 @@ fn heuristic_select(results: &serde_json::Value) -> Candidate {\n .get(\"score\")\n .and_then(serde_json::Value::as_f64)\n .unwrap_or(0.0),\n+ timing: StageTiming::default(),\n })\n .collect();\n \n@@ -215,6 +221,7 @@ fn heuristic_select(results: &serde_json::Value) -> Candidate {\n id: \"unknown\".to_string(),\n status: \"failed\".to_string(),\n score: 0.0,\n+ timing: StageTiming::default(),\n })\n }\n \n@@ -277,6 +284,7 @@ async fn llm_evaluate(\n .await\n {\n Ok(CodergenResult::Full(outcome)) => {\n+ let timing = outcome.timing.unwrap_or_default();\n // If the backend returned a full Outcome, extract best_id from context_updates\n let best_id = outcome\n .context_updates\n@@ -298,12 +306,13 @@ async fn llm_evaluate(\n &stage_scope,\n );\n Ok(Candidate {\n- id: best_id,\n+ id: best_id,\n status: outcome.status.to_string(),\n- score: 0.0,\n+ score: 0.0,\n+ timing,\n })\n }\n- Ok(CodergenResult::Text { text, .. }) => {\n+ Ok(CodergenResult::Text { text, timing, .. }) => {\n emitter.emit_scoped(\n &Event::PromptCompleted {\n node_id: node_id.to_string(),\n@@ -337,13 +346,16 @@ async fn llm_evaluate(\n id: id.to_string(),\n status,\n score,\n+ timing,\n });\n }\n }\n }\n \n // No match found; fall back to heuristic\n- Ok(heuristic_select(results))\n+ let mut fallback = heuristic_select(results);\n+ fallback.timing = timing;\n+ Ok(fallback)\n }\n Err(_) => {\n // LLM call failed; fall back to heuristic\n@@ -486,6 +498,7 @@ mod tests {\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: StageTiming::default(),\n })\n }\n }\n@@ -519,6 +532,52 @@ mod tests {\n );\n }\n \n+ #[tokio::test]\n+ async fn fan_in_with_backend_copies_llm_timing_to_outcome() {\n+ use tempfile::TempDir;\n+\n+ use crate::handler::agent::{CodergenBackend, CodergenRunRequest};\n+\n+ struct TimingBackend;\n+\n+ #[async_trait]\n+ impl CodergenBackend for TimingBackend {\n+ async fn run(&self, _request: CodergenRunRequest<'_>) -> Result {\n+ Ok(CodergenResult::Text {\n+ text: \"branch_b\".to_string(),\n+ usage: None,\n+ files_touched: Vec::new(),\n+ last_file_touched: None,\n+ timing: StageTiming::new(0, 200, 300),\n+ })\n+ }\n+ }\n+\n+ let handler = FanInHandler::new(Some(Box::new(TimingBackend)));\n+ let mut node = Node::new(\"fan_in\");\n+ node.attrs.insert(\n+ \"prompt\".to_string(),\n+ fabro_graphviz::graph::AttrValue::String(\"Pick the best branch\".to_string()),\n+ );\n+ let context = Context::new();\n+ context.set(\n+ keys::PARALLEL_RESULTS,\n+ serde_json::json!([\n+ {\"id\": \"branch_a\", \"status\": \"succeeded\"},\n+ {\"id\": \"branch_b\", \"status\": \"succeeded\"},\n+ ]),\n+ );\n+ let graph = Graph::new(\"test\");\n+ let tmp = TempDir::new().unwrap();\n+\n+ let outcome = handler\n+ .execute(&node, &context, &graph, tmp.path(), &make_services())\n+ .await\n+ .unwrap();\n+\n+ assert_eq!(outcome.timing, Some(StageTiming::new(0, 200, 300)));\n+ }\n+\n #[tokio::test]\n async fn fan_in_all_fail_returns_fail() {\n let handler = FanInHandler::new(None);\ndiff --git a/lib/crates/fabro-workflow/src/handler/llm/acp.rs b/lib/crates/fabro-workflow/src/handler/llm/acp.rs\nindex 07bfed7c1..4b867b7b8 100644\n--- a/lib/crates/fabro-workflow/src/handler/llm/acp.rs\n+++ b/lib/crates/fabro-workflow/src/handler/llm/acp.rs\n@@ -10,7 +10,9 @@ use fabro_acp::{\n };\n use fabro_agent::{AgentEvent, Sandbox, StaticEnvProvider, SteeringItem, ToolEnvProvider};\n use fabro_graphviz::graph::Node;\n-use fabro_types::{AgentBackend, Principal, SessionCapability, StageId, SteeringMessage};\n+use fabro_types::{\n+ AgentBackend, Principal, SessionCapability, StageId, StageTiming, SteeringMessage,\n+};\n use fabro_util::time::elapsed_ms;\n use tokio_util::sync::CancellationToken;\n \n@@ -231,6 +233,7 @@ impl AgentAcpBackend {\n usage: None,\n files_touched,\n last_file_touched,\n+ timing: StageTiming::new(0, result.duration_ms, 0),\n })\n }\n \ndiff --git a/lib/crates/fabro-workflow/src/handler/llm/api.rs b/lib/crates/fabro-workflow/src/handler/llm/api.rs\nindex d13103c5d..df5af98c2 100644\n--- a/lib/crates/fabro-workflow/src/handler/llm/api.rs\n+++ b/lib/crates/fabro-workflow/src/handler/llm/api.rs\n@@ -1,5 +1,6 @@\n use std::collections::{HashMap, HashSet};\n use std::sync::{Arc, Mutex};\n+use std::time::{Duration, Instant};\n \n use async_trait::async_trait;\n use fabro_agent::subagent::{SessionFactory, SubAgentManager};\n@@ -21,7 +22,7 @@ use fabro_mcp::config::McpServerSettings;\n use fabro_model::catalog::LlmCatalogSettings;\n use fabro_model::{AgentProfileKind, Catalog, FallbackTarget, ModelRef, ProviderId};\n use fabro_types::settings::run::RunModelControls;\n-use fabro_types::{PermissionLevel, RunId, SessionCapability, StageId};\n+use fabro_types::{PermissionLevel, RunId, SessionCapability, StageId, StageTiming};\n use serde::de::DeserializeOwned;\n use tokio::sync::Mutex as TokioMutex;\n use tokio::task::JoinHandle;\n@@ -119,6 +120,12 @@ pub struct EffectiveRequestControls {\n pub(crate) speed: Option,\n }\n \n+fn active_stage_timing(inference: Duration, tool: Duration) -> StageTiming {\n+ // The executor ignores this wall field and supplies its own stopwatch-based\n+ // value when converting Outcome.timing into the emitted stage timing.\n+ StageTiming::new(0, crate::millis_u64(inference), crate::millis_u64(tool))\n+}\n+\n fn classify_agent_error(err: fabro_agent::Error, allow_failover: bool) -> AgentApiErrorDisposition {\n match err {\n fabro_agent::Error::Interrupted(fabro_agent::InterruptReason::Cancelled) => {\n@@ -1046,6 +1053,7 @@ impl CodergenBackend for AgentApiBackend {\n .map(structured_output::prompt_response_format);\n let mut repair_attempts = 0_i64;\n let mut total_usage = TokenCounts::default();\n+ let mut inference_duration = Duration::ZERO;\n \n loop {\n let request = Request {\n@@ -1065,7 +1073,8 @@ impl CodergenBackend for AgentApiBackend {\n provider_options: None,\n };\n \n- let completion = self\n+ let inference_start = Instant::now();\n+ let completion_result = self\n .complete_one_shot_request(\n &client,\n node,\n@@ -1075,7 +1084,9 @@ impl CodergenBackend for AgentApiBackend {\n controls,\n fallback_chain,\n )\n- .await?;\n+ .await;\n+ inference_duration = inference_duration.saturating_add(inference_start.elapsed());\n+ let completion = completion_result?;\n total_usage += completion.response.usage.clone();\n let response_text = completion.response.text();\n \n@@ -1108,9 +1119,10 @@ impl CodergenBackend for AgentApiBackend {\n \n return Ok(CodergenResult::Text {\n text: response_text,\n- usage: Some(stage_usage),\n+ usage: Some(Box::new(stage_usage)),\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: active_stage_timing(inference_duration, Duration::ZERO),\n });\n }\n }\n@@ -1191,6 +1203,8 @@ impl CodergenBackend for AgentApiBackend {\n \n // Record turn count before processing so we only aggregate new usage.\n let mut turns_before = session.history().turns().len();\n+ let mut inference_duration = Duration::ZERO;\n+ let mut tool_duration = Duration::ZERO;\n \n // Activate with the steering hub after initialization so HTTP\n // `POST /runs/{id}/steer` calls reach this session. The activation\n@@ -1243,9 +1257,13 @@ impl CodergenBackend for AgentApiBackend {\n if !is_reused {\n emit_agent_tools_available(&session, &node.id, &stage_id, emitter);\n }\n- session\n+ let process_result = session\n .process_input_with_runtime(prompt, agent_tool_runtime.clone())\n- .await\n+ .await;\n+ let timing = session.last_input_timing();\n+ inference_duration = inference_duration.saturating_add(timing.inference);\n+ tool_duration = tool_duration.saturating_add(timing.tool);\n+ process_result\n }\n Err(err) => Err(err),\n };\n@@ -1371,10 +1389,13 @@ impl CodergenBackend for AgentApiBackend {\n }\n }\n emit_agent_tools_available(&session, &node.id, &stage_id, emitter);\n- match session\n+ let process_result = session\n .process_input_with_runtime(prompt, agent_tool_runtime.clone())\n- .await\n- {\n+ .await;\n+ let timing = session.last_input_timing();\n+ inference_duration = inference_duration.saturating_add(timing.inference);\n+ tool_duration = tool_duration.saturating_add(timing.tool);\n+ match process_result {\n Ok(()) => {\n succeeded = true;\n break;\n@@ -1435,7 +1456,11 @@ impl CodergenBackend for AgentApiBackend {\n ));\n }\n let repair_message = error.repair_message(schema);\n- match session.process_input(&repair_message).await {\n+ let repair_result = session.process_input(&repair_message).await;\n+ let timing = session.last_input_timing();\n+ inference_duration = inference_duration.saturating_add(timing.inference);\n+ tool_duration = tool_duration.saturating_add(timing.tool);\n+ match repair_result {\n Ok(()) => {\n repair_attempts += 1;\n response = last_assistant_response(&session);\n@@ -1507,9 +1532,10 @@ impl CodergenBackend for AgentApiBackend {\n \n Ok(CodergenResult::Text {\n text: response,\n- usage: Some(stage_usage),\n+ usage: Some(Box::new(stage_usage)),\n files_touched,\n last_file_touched,\n+ timing: active_stage_timing(inference_duration, tool_duration),\n })\n }\n }\ndiff --git a/lib/crates/fabro-workflow/src/handler/llm/router.rs b/lib/crates/fabro-workflow/src/handler/llm/router.rs\nindex 821bd8136..24dc97e0e 100644\n--- a/lib/crates/fabro-workflow/src/handler/llm/router.rs\n+++ b/lib/crates/fabro-workflow/src/handler/llm/router.rs\n@@ -161,6 +161,7 @@ mod tests {\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: fabro_types::StageTiming::default(),\n })\n }\n \n@@ -170,6 +171,7 @@ mod tests {\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: fabro_types::StageTiming::default(),\n })\n }\n \ndiff --git a/lib/crates/fabro-workflow/src/handler/prompt.rs b/lib/crates/fabro-workflow/src/handler/prompt.rs\nindex 27b9fa524..94674421f 100644\n--- a/lib/crates/fabro-workflow/src/handler/prompt.rs\n+++ b/lib/crates/fabro-workflow/src/handler/prompt.rs\n@@ -3,7 +3,7 @@ use std::sync::Arc;\n \n use async_trait::async_trait;\n use fabro_graphviz::graph::{Graph, Node};\n-use fabro_types::StageModelUsage;\n+use fabro_types::{StageModelUsage, StageTiming};\n \n use super::agent::{\n CodergenBackend, CodergenResult, OneShotRequest, emit_stage_prompt, extract_status_fields,\n@@ -117,7 +117,7 @@ impl Handler for PromptHandler {\n )?;\n \n // 3. Call LLM backend (one_shot)\n- let (response_text, stage_usage, backend_files_touched) =\n+ let (response_text, stage_usage, backend_files_touched, timing) =\n if let Some(backend) = &self.backend {\n let result = backend\n .one_shot(OneShotRequest {\n@@ -136,8 +136,9 @@ impl Handler for PromptHandler {\n text,\n usage,\n files_touched,\n+ timing,\n ..\n- }) => (text, usage, files_touched),\n+ }) => (text, usage.map(|usage| *usage), files_touched, timing),\n Err(Error::Cancelled) => return Err(Error::Cancelled),\n Err(e) if e.is_retryable() => {\n return Err(e);\n@@ -151,6 +152,7 @@ impl Handler for PromptHandler {\n format!(\"[Simulated] Response for stage: {}\", node.id),\n None,\n Vec::new(),\n+ StageTiming::default(),\n )\n };\n \n@@ -192,26 +194,24 @@ impl Handler for PromptHandler {\n );\n \n if let Some(schema) = structured_output::parse_node_output_schema(node)? {\n- match structured_output::validate_response_text(&schema, &response_text) {\n- Ok(validated) => {\n- structured_output::apply_validated_output(\n- node,\n- &schema,\n- &validated,\n- &mut outcome,\n- );\n- }\n- Err(_) => {\n- return Ok(structured_output::exhausted_failure_outcome(\n- node.output_retries(),\n- ));\n- }\n+ if let Ok(validated) =\n+ structured_output::validate_response_text(&schema, &response_text)\n+ {\n+ structured_output::apply_validated_output(node, &schema, &validated, &mut outcome);\n+ } else {\n+ let mut failed =\n+ structured_output::exhausted_failure_outcome(node.output_retries());\n+ failed.timing = Some(timing);\n+ failed.usage = stage_usage;\n+ failed.files_touched = backend_files_touched;\n+ return Ok(failed);\n }\n } else {\n extract_status_fields(&response_text, &mut outcome);\n }\n outcome.usage = stage_usage;\n outcome.files_touched = backend_files_touched;\n+ outcome.timing = Some(timing);\n \n Ok(outcome)\n }\n@@ -349,6 +349,7 @@ mod tests {\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: StageTiming::default(),\n })\n }\n \n@@ -387,6 +388,44 @@ mod tests {\n );\n }\n \n+ #[tokio::test]\n+ async fn prompt_handler_copies_backend_timing_to_outcome() {\n+ struct TimingBackend;\n+\n+ #[async_trait]\n+ impl CodergenBackend for TimingBackend {\n+ async fn run(&self, _request: CodergenRunRequest<'_>) -> Result {\n+ panic!(\"run() should not be called for prompt handler\");\n+ }\n+\n+ async fn one_shot(\n+ &self,\n+ _request: OneShotRequest<'_>,\n+ ) -> Result {\n+ Ok(CodergenResult::Text {\n+ text: \"one-shot response\".to_string(),\n+ usage: None,\n+ files_touched: Vec::new(),\n+ last_file_touched: None,\n+ timing: StageTiming::new(0, 200, 300),\n+ })\n+ }\n+ }\n+\n+ let handler = PromptHandler::new(Some(Box::new(TimingBackend)));\n+ let node = Node::new(\"classify\");\n+ let context = Context::new();\n+ let graph = Graph::new(\"test\");\n+ let tmp = TempDir::new().unwrap();\n+\n+ let outcome = handler\n+ .execute(&node, &context, &graph, tmp.path(), &make_services())\n+ .await\n+ .unwrap();\n+\n+ assert_eq!(outcome.timing, Some(StageTiming::new(0, 200, 300)));\n+ }\n+\n #[tokio::test]\n async fn prompt_handler_custom_output_schema_updates_output_context_key() {\n struct CustomOutputBackend;\n@@ -406,6 +445,7 @@ mod tests {\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: StageTiming::default(),\n })\n }\n }\n@@ -453,6 +493,7 @@ mod tests {\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: StageTiming::default(),\n })\n }\n }\n@@ -502,6 +543,7 @@ mod tests {\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: StageTiming::default(),\n })\n }\n \n@@ -561,6 +603,7 @@ mod tests {\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: StageTiming::default(),\n })\n }\n }\ndiff --git a/lib/crates/fabro-workflow/src/operations/start.rs b/lib/crates/fabro-workflow/src/operations/start.rs\nindex 66f1a5fc4..0adc853ac 100644\n--- a/lib/crates/fabro-workflow/src/operations/start.rs\n+++ b/lib/crates/fabro-workflow/src/operations/start.rs\n@@ -30,13 +30,13 @@ use tokio_util::sync::CancellationToken;\n \n use crate::artifact_upload::ArtifactSink;\n use crate::context::Context;\n-use crate::error::Error;\n+use crate::error::{self, Error};\n use crate::event::{\n Emitter, Event, EventBody, RunEventLogger, RunEventSink, RunNoticeLevel, append_event_to_sink,\n };\n use crate::handler::HandlerRegistry;\n use crate::handler::llm::routing;\n-use crate::outcome::Outcome;\n+use crate::outcome::{Outcome, StageOutcome};\n use crate::pipeline::{\n self, DevcontainerSpec, FinalizeOptions, Finalized, InitOptions, LlmSpec, Persisted,\n PullRequestOptions, SandboxEnvSpec, build_conclusion_from_store, classify_engine_result,\n@@ -184,6 +184,7 @@ pub(super) async fn execute_persisted_run(\n let error = Error::engine(err.to_string());\n let _ = persist_detached_failure(\n run_id,\n+ &run_store,\n &event_sink,\n run_dir,\n \"bootstrap\",\n@@ -197,6 +198,7 @@ pub(super) async fn execute_persisted_run(\n let error = Error::engine(err.to_string());\n let _ = persist_detached_failure(\n run_id,\n+ &run_store,\n &event_sink,\n run_dir,\n \"bootstrap\",\n@@ -209,12 +211,14 @@ pub(super) async fn execute_persisted_run(\n \n let mut bootstrap_guard =\n DetachedRunBootstrapGuard::arm(run_id, run_dir, event_sink.clone(), cancel_token.clone());\n+ bootstrap_guard.run_store = Some(run_store.clone());\n \n let persisted = match Persisted::load_from_store(&services.run_store, run_dir).await {\n Ok(persisted) => persisted,\n Err(err) => {\n let _ = persist_detached_failure(\n run_id,\n+ &run_store,\n &event_sink,\n run_dir,\n \"bootstrap\",\n@@ -232,6 +236,7 @@ pub(super) async fn execute_persisted_run(\n Err(err) => {\n let _ = persist_detached_failure(\n run_id,\n+ &run_store,\n &event_sink,\n run_dir,\n \"bootstrap\",\n@@ -245,8 +250,12 @@ pub(super) async fn execute_persisted_run(\n };\n \n bootstrap_guard.defuse();\n- let mut completion_guard =\n- DetachedRunCompletionGuard::arm(run_id, event_sink.clone(), cancel_token);\n+ let mut completion_guard = DetachedRunCompletionGuard::arm(\n+ run_id,\n+ run_store.clone(),\n+ event_sink.clone(),\n+ cancel_token,\n+ );\n let run_start = Instant::now();\n let started = Box::pin(session.run(persisted, checkpoint)).await;\n \n@@ -281,7 +290,7 @@ async fn persist_terminal_engine_failure(\n ) {\n let engine_result: Result = Err(error.clone());\n let (final_status, failure_reason, run_status) = classify_engine_result(&engine_result);\n- let _conclusion = build_conclusion_from_store(\n+ let conclusion = build_conclusion_from_store(\n run_store,\n final_status,\n failure_reason,\n@@ -295,12 +304,12 @@ async fn persist_terminal_engine_failure(\n };\n let failure_event = Event::workflow_run_failed_from_error(\n error,\n- fabro_types::RunTiming::wall_only(crate::millis_u64(duration)),\n+ conclusion.timing,\n reason,\n None,\n None,\n None,\n- None,\n+ conclusion.billing.clone(),\n );\n if let Err(err) = append_event_to_sink(event_sink, &run_id, &failure_event).await {\n tracing::warn!(error = %err, \"Failed to append terminal engine failure event\");\n@@ -893,6 +902,7 @@ impl RunSession {\n \n struct DetachedRunBootstrapGuard {\n run_id: RunId,\n+ run_store: Option,\n event_sink: RunEventSink,\n cancel_token: CancellationToken,\n active: bool,\n@@ -907,6 +917,7 @@ impl DetachedRunBootstrapGuard {\n ) -> Self {\n Self {\n run_id,\n+ run_store: None,\n event_sink,\n cancel_token,\n active: true,\n@@ -928,17 +939,33 @@ impl Drop for DetachedRunBootstrapGuard {\n FailureReason::SandboxInitFailed\n };\n let run_id = self.run_id;\n+ let run_store = self.run_store.clone();\n let event_sink = self.event_sink.clone();\n if let Ok(handle) = Handle::try_current() {\n handle.spawn(async move {\n+ let (timing, billing) = if let Some(run_store) = run_store {\n+ let final_status = StageOutcome::Failed {\n+ retry_requested: false,\n+ };\n+ let failure = Some(error::run_failure_from_error(\n+ &Error::engine(reason.to_string()),\n+ reason,\n+ ));\n+ let conclusion =\n+ build_conclusion_from_store(&run_store, final_status, failure, 0, None)\n+ .await;\n+ (conclusion.timing, conclusion.billing)\n+ } else {\n+ (fabro_types::RunTiming::default(), None)\n+ };\n let failure_event = Event::workflow_run_failed_from_error(\n &Error::engine(reason.to_string()),\n- fabro_types::RunTiming::default(),\n+ timing,\n reason,\n None,\n None,\n None,\n- None,\n+ billing,\n );\n let _ = append_event_to_sink(&event_sink, &run_id, &failure_event).await;\n });\n@@ -953,15 +980,22 @@ const POSTRUN_CANCELLED_MESSAGE: &str = \"Run cancelled before post-run finalizat\n struct DetachedRunCompletionGuard {\n event_sink: RunEventSink,\n run_id: RunId,\n+ run_store: RunStoreHandle,\n cancel_token: CancellationToken,\n active: bool,\n }\n \n impl DetachedRunCompletionGuard {\n- fn arm(run_id: RunId, event_sink: RunEventSink, cancel_token: CancellationToken) -> Self {\n+ fn arm(\n+ run_id: RunId,\n+ run_store: RunStoreHandle,\n+ event_sink: RunEventSink,\n+ cancel_token: CancellationToken,\n+ ) -> Self {\n Self {\n event_sink,\n run_id,\n+ run_store,\n cancel_token,\n active: true,\n }\n@@ -996,16 +1030,26 @@ impl Drop for DetachedRunCompletionGuard {\n };\n let event_sink = self.event_sink.clone();\n let run_id = self.run_id;\n+ let run_store = self.run_store.clone();\n if let Ok(handle) = Handle::try_current() {\n handle.spawn(async move {\n+ let final_status = StageOutcome::Failed {\n+ retry_requested: false,\n+ };\n+ let failure = Some(error::run_failure_from_error(\n+ &Error::engine(message.to_string()),\n+ reason,\n+ ));\n+ let conclusion =\n+ build_conclusion_from_store(&run_store, final_status, failure, 0, None).await;\n let failure_event = Event::workflow_run_failed_from_error(\n &Error::engine(message.to_string()),\n- fabro_types::RunTiming::default(),\n+ conclusion.timing,\n reason,\n None,\n None,\n None,\n- None,\n+ conclusion.billing,\n );\n let _ = append_event_to_sink(&event_sink, &run_id, &failure_event).await;\n let _ = append_event_to_sink(&event_sink, &run_id, &Event::RunNotice {\n@@ -1022,6 +1066,7 @@ impl Drop for DetachedRunCompletionGuard {\n \n async fn persist_detached_failure(\n run_id: RunId,\n+ run_store: &RunStoreHandle,\n event_sink: &RunEventSink,\n _run_dir: &Path,\n phase: &'static str,\n@@ -1029,15 +1074,20 @@ async fn persist_detached_failure(\n error: &Error,\n ) -> Result<(), Error> {\n let message = error.to_string();\n+ let final_status = StageOutcome::Failed {\n+ retry_requested: false,\n+ };\n+ let failure = Some(error::run_failure_from_error(error, reason));\n+ let conclusion = build_conclusion_from_store(run_store, final_status, failure, 0, None).await;\n \n let failure_event = Event::workflow_run_failed_from_error(\n error,\n- fabro_types::RunTiming::default(),\n+ conclusion.timing,\n reason,\n None,\n None,\n None,\n- None,\n+ conclusion.billing,\n );\n if let Err(err) = append_event_to_sink(event_sink, &run_id, &failure_event).await {\n tracing::warn!(error = %err, \"Failed to append detached failure event\");\n@@ -1072,18 +1122,18 @@ mod tests {\n use fabro_store::Database;\n use fabro_types::settings::run::RunMode;\n use fabro_types::settings::{InterpString, ModelRef};\n- use fabro_types::{ManifestPath, WorkflowSettings, fixtures};\n+ use fabro_types::{BilledModelUsage, ManifestPath, StageTiming, WorkflowSettings, fixtures};\n use object_store::memory::InMemory;\n \n use super::*;\n use crate::context::Context;\n use crate::event::{Emitter, EventBody};\n- use crate::handler::HandlerRegistry;\n use crate::handler::exit::ExitHandler;\n use crate::handler::manager_loop::SubWorkflowHandler;\n use crate::handler::start::StartHandler;\n+ use crate::handler::{EngineServices, Handler, HandlerRegistry};\n use crate::operations::resume;\n- use crate::outcome::StageOutcome;\n+ use crate::outcome::{Outcome, StageOutcome};\n use crate::records::CheckpointExt;\n use crate::workflow_bundle::{BundledWorkflow, WorkflowBundle};\n \n@@ -1094,6 +1144,48 @@ mod tests {\n start -> exit\n }\"#;\n \n+ const TIMED_DOT: &str = r#\"digraph Test {\n+ graph [goal=\"Time active work\"]\n+ start [shape=Mdiamond]\n+ work [type=\"timed\"]\n+ exit [shape=Msquare]\n+ start -> work\n+ work -> exit\n+ }\"#;\n+\n+ struct TimedOutcomeHandler;\n+\n+ fn timed_success_outcome() -> Outcome {\n+ let mut outcome = Outcome::success();\n+ outcome.timing = Some(StageTiming::new(0, 100, 50));\n+ outcome\n+ }\n+\n+ #[async_trait::async_trait]\n+ impl Handler for TimedOutcomeHandler {\n+ async fn execute(\n+ &self,\n+ _node: &fabro_graphviz::graph::Node,\n+ _context: &Context,\n+ _graph: &fabro_graphviz::graph::Graph,\n+ _run_dir: &Path,\n+ _services: &EngineServices,\n+ ) -> Result {\n+ Ok(timed_success_outcome())\n+ }\n+\n+ async fn simulate(\n+ &self,\n+ _node: &fabro_graphviz::graph::Node,\n+ _context: &Context,\n+ _graph: &fabro_graphviz::graph::Graph,\n+ _run_dir: &Path,\n+ _services: &EngineServices,\n+ ) -> Result {\n+ Ok(timed_success_outcome())\n+ }\n+ }\n+\n fn memory_store() -> Arc {\n Arc::new(Database::new(\n Arc::new(InMemory::new()),\n@@ -1381,6 +1473,92 @@ reasoning = false\n }\n }\n \n+ fn test_usage(model_id: &str, input_tokens: i64, output_tokens: i64) -> BilledModelUsage {\n+ serde_json::from_value(serde_json::json!({\n+ \"input\": {\n+ \"usage\": {\n+ \"model\": {\n+ \"provider\": \"openai\",\n+ \"model_id\": model_id\n+ },\n+ \"tokens\": {\n+ \"input_tokens\": input_tokens,\n+ \"output_tokens\": output_tokens\n+ }\n+ },\n+ \"facts\": { \"algorithm\": \"openai\" }\n+ },\n+ \"total_usd_micros\": input_tokens + output_tokens\n+ }))\n+ .unwrap()\n+ }\n+\n+ async fn append_completed_stage(\n+ run_store: &fabro_store::RunDatabase,\n+ node_id: &str,\n+ timing: fabro_types::StageTiming,\n+ billing: Option,\n+ ) {\n+ crate::event::append_event(run_store, &fixtures::RUN_1, &Event::StageCompleted {\n+ node_id: node_id.to_string(),\n+ name: node_id.to_string(),\n+ index: 0,\n+ timing,\n+ status: StageOutcome::Succeeded.to_string(),\n+ preferred_label: None,\n+ suggested_next_ids: Vec::new(),\n+ billing,\n+ failure: None,\n+ notes: None,\n+ files_touched: Vec::new(),\n+ context_updates: None,\n+ jump_to_node: None,\n+ context_values: None,\n+ node_visits: None,\n+ loop_failure_signatures: None,\n+ restart_failure_signatures: None,\n+ response: None,\n+ attempt: 1,\n+ max_attempts: 1,\n+ })\n+ .await\n+ .unwrap();\n+ }\n+\n+ async fn mark_run_running(run_store: &fabro_store::RunDatabase) {\n+ crate::event::append_event(run_store, &fixtures::RUN_1, &Event::RunStartRequested {\n+ resume: false,\n+ actor: None,\n+ })\n+ .await\n+ .unwrap();\n+ crate::event::append_event(run_store, &fixtures::RUN_1, &Event::RunRunnable {\n+ source: RunRunnableSource::StartRequested,\n+ actor: None,\n+ })\n+ .await\n+ .unwrap();\n+ crate::event::append_event(run_store, &fixtures::RUN_1, &Event::RunStarting)\n+ .await\n+ .unwrap();\n+ crate::event::append_event(run_store, &fixtures::RUN_1, &Event::RunRunning)\n+ .await\n+ .unwrap();\n+ }\n+\n+ async fn wait_for_conclusion(\n+ run_store: &fabro_store::RunDatabase,\n+ ) -> crate::records::Conclusion {\n+ for _ in 0..50 {\n+ if let Some(conclusion) = run_store.state().await.unwrap().conclusion {\n+ return conclusion;\n+ }\n+ tokio::task::yield_now().await;\n+ tokio::time::sleep(Duration::from_millis(1)).await;\n+ }\n+ panic!(\"timed out waiting for run conclusion\");\n+ }\n+\n #[tokio::test]\n async fn start_captures_checkpoint_git_sha_in_conclusion() {\n let temp = tempfile::tempdir().unwrap();\n@@ -1435,6 +1613,188 @@ reasoning = false\n assert_eq!(started.finalized.conclusion.status, StageOutcome::Succeeded);\n }\n \n+ #[tokio::test]\n+ async fn start_events_roll_up_outcome_active_timing() {\n+ let temp = tempfile::tempdir().unwrap();\n+ let (storage_root, run_dir) = storage_root_and_run_dir(&temp);\n+ let emitter = Arc::new(Emitter::new(fixtures::RUN_1));\n+ let stage_timing = Arc::new(Mutex::new(None));\n+ let run_timing = Arc::new(Mutex::new(None));\n+ {\n+ let stage_timing = Arc::clone(&stage_timing);\n+ let run_timing = Arc::clone(&run_timing);\n+ emitter.on_event(move |event| match &event.body {\n+ EventBody::StageCompleted(props) if event.node_id.as_deref() == Some(\"work\") => {\n+ *stage_timing.lock().unwrap() = Some(props.timing);\n+ }\n+ EventBody::RunCompleted(props) => {\n+ *run_timing.lock().unwrap() = Some(props.timing);\n+ }\n+ _ => {}\n+ });\n+ }\n+\n+ let mut registry = test_registry();\n+ registry.register(\"timed\", Box::new(TimedOutcomeHandler));\n+ let (_persisted, store) = persisted_workflow(TIMED_DOT, &storage_root).await;\n+\n+ let started = start(\n+ &run_dir,\n+ test_start_services(&store, &run_dir, emitter, Arc::new(registry)).await,\n+ )\n+ .await\n+ .unwrap();\n+\n+ let stage_timing = stage_timing\n+ .lock()\n+ .unwrap()\n+ .expect(\"work stage should emit stage.completed timing\");\n+ assert_eq!(stage_timing.inference_time_ms, 100);\n+ assert_eq!(stage_timing.tool_time_ms, 50);\n+ assert_eq!(stage_timing.active_time_ms, 150);\n+\n+ let run_timing = run_timing\n+ .lock()\n+ .unwrap()\n+ .expect(\"successful run should emit run.completed timing\");\n+ assert_eq!(run_timing.inference_time_ms, 100);\n+ assert_eq!(run_timing.tool_time_ms, 50);\n+ assert_eq!(run_timing.active_time_ms, 150);\n+ assert_eq!(started.finalized.conclusion.timing.inference_time_ms, 100);\n+ assert_eq!(started.finalized.conclusion.timing.tool_time_ms, 50);\n+ assert_eq!(started.finalized.conclusion.timing.active_time_ms, 150);\n+ }\n+\n+ #[tokio::test]\n+ async fn persist_terminal_engine_failure_uses_conclusion_timing_and_billing() {\n+ let temp = tempfile::tempdir().unwrap();\n+ let (storage_root, run_dir) = storage_root_and_run_dir(&temp);\n+ let (_persisted, store) = persisted_workflow(MINIMAL_DOT, &storage_root).await;\n+ let run_store = store.open_run(&fixtures::RUN_1).await.unwrap();\n+ mark_run_running(&run_store).await;\n+ append_completed_stage(\n+ &run_store,\n+ \"implement\",\n+ fabro_types::StageTiming::new(1_000, 200, 300),\n+ Some(test_usage(\"gpt-5.4\", 100, 50)),\n+ )\n+ .await;\n+ append_completed_stage(\n+ &run_store,\n+ \"review\",\n+ fabro_types::StageTiming::new(500, 25, 75),\n+ None,\n+ )\n+ .await;\n+ let run_store_handle: RunStoreHandle = run_store.clone().into();\n+ let event_sink = RunEventSink::store(run_store.clone());\n+\n+ persist_terminal_engine_failure(\n+ fixtures::RUN_1,\n+ &run_store_handle,\n+ &event_sink,\n+ &run_dir,\n+ &Error::engine(\"visit limit exceeded\"),\n+ Duration::from_millis(9_999),\n+ )\n+ .await;\n+\n+ let projection = run_store.state().await.unwrap();\n+ let conclusion = projection\n+ .conclusion\n+ .expect(\"run.failed should populate conclusion\");\n+ assert_eq!(conclusion.timing.wall_time_ms, 9_999);\n+ assert_eq!(conclusion.timing.inference_time_ms, 225);\n+ assert_eq!(conclusion.timing.tool_time_ms, 375);\n+ assert_eq!(conclusion.timing.active_time_ms, 600);\n+ assert_eq!(\n+ conclusion\n+ .billing\n+ .as_ref()\n+ .map(|billing| billing.total_tokens),\n+ Some(150),\n+ );\n+ }\n+\n+ #[tokio::test]\n+ async fn bootstrap_guard_failure_uses_conclusion_timing_and_billing_when_store_exists() {\n+ let temp = tempfile::tempdir().unwrap();\n+ let (storage_root, run_dir) = storage_root_and_run_dir(&temp);\n+ let (_persisted, store) = persisted_workflow(MINIMAL_DOT, &storage_root).await;\n+ let run_store = store.open_run(&fixtures::RUN_1).await.unwrap();\n+ mark_run_running(&run_store).await;\n+ append_completed_stage(\n+ &run_store,\n+ \"implement\",\n+ fabro_types::StageTiming::new(1_000, 120, 80),\n+ Some(test_usage(\"gpt-5.4\", 40, 10)),\n+ )\n+ .await;\n+ let run_store_handle: RunStoreHandle = run_store.clone().into();\n+ let event_sink = RunEventSink::store(run_store.clone());\n+\n+ {\n+ let mut guard = DetachedRunBootstrapGuard::arm(\n+ fixtures::RUN_1,\n+ &run_dir,\n+ event_sink,\n+ CancellationToken::new(),\n+ );\n+ guard.run_store = Some(run_store_handle);\n+ }\n+\n+ let conclusion = wait_for_conclusion(&run_store).await;\n+ assert_eq!(conclusion.timing.inference_time_ms, 120);\n+ assert_eq!(conclusion.timing.tool_time_ms, 80);\n+ assert_eq!(conclusion.timing.active_time_ms, 200);\n+ assert_eq!(\n+ conclusion\n+ .billing\n+ .as_ref()\n+ .map(|billing| billing.total_tokens),\n+ Some(50),\n+ );\n+ }\n+\n+ #[tokio::test]\n+ async fn completion_guard_failure_uses_conclusion_timing_and_billing() {\n+ let temp = tempfile::tempdir().unwrap();\n+ let (storage_root, _run_dir) = storage_root_and_run_dir(&temp);\n+ let (_persisted, store) = persisted_workflow(MINIMAL_DOT, &storage_root).await;\n+ let run_store = store.open_run(&fixtures::RUN_1).await.unwrap();\n+ mark_run_running(&run_store).await;\n+ append_completed_stage(\n+ &run_store,\n+ \"implement\",\n+ fabro_types::StageTiming::new(1_000, 70, 30),\n+ Some(test_usage(\"gpt-5.4\", 20, 5)),\n+ )\n+ .await;\n+ let run_store_handle: RunStoreHandle = run_store.clone().into();\n+ let event_sink = RunEventSink::store(run_store.clone());\n+\n+ {\n+ let _guard = DetachedRunCompletionGuard::arm(\n+ fixtures::RUN_1,\n+ run_store_handle,\n+ event_sink,\n+ CancellationToken::new(),\n+ );\n+ }\n+\n+ let conclusion = wait_for_conclusion(&run_store).await;\n+ assert_eq!(conclusion.timing.inference_time_ms, 70);\n+ assert_eq!(conclusion.timing.tool_time_ms, 30);\n+ assert_eq!(conclusion.timing.active_time_ms, 100);\n+ assert_eq!(\n+ conclusion\n+ .billing\n+ .as_ref()\n+ .map(|billing| billing.total_tokens),\n+ Some(25),\n+ );\n+ }\n+\n #[tokio::test]\n async fn start_loads_persisted_from_run_dir() {\n let temp = tempfile::tempdir().unwrap();\ndiff --git a/lib/crates/fabro-workflow/tests/it/integration.rs b/lib/crates/fabro-workflow/tests/it/integration.rs\nindex fdfa426d7..27409d025 100644\n--- a/lib/crates/fabro-workflow/tests/it/integration.rs\n+++ b/lib/crates/fabro-workflow/tests/it/integration.rs\n@@ -1783,6 +1783,7 @@ impl CodergenBackend for MockCodergenBackend {\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: fabro_types::StageTiming::default(),\n })\n }\n }\n@@ -6496,6 +6497,7 @@ mod real_llm {\n usage: None,\n files_touched: Vec::new(),\n last_file_touched: None,\n+ timing: fabro_types::StageTiming::default(),\n })\n }\n }\n", + "summary": { + "files_changed": 13, + "additions": 846, + "deletions": 79 + } + } + }, + { + "seq": 0, + "checkpoint": { + "timestamp": "2026-05-25T22:48:07.334455Z", + "current_node": "simplify_opus", + "completed_nodes": [ + "start", + "toolchain", + "preflight_compile", + "preflight_lint", + "implement", + "simplify_opus" + ], + "node_retries": {}, + "context_values": { + "graph.rankdir": "LR", + "failure_class": "", "response.implement": "Implemented the stage timing and terminal failure rollup fixes.\n\nSummary of changes:\n- Added per-input `fabro-agent::Session` timing:\n - Tracks LLM inference/stream time and tool execution time.\n - Exposes `SessionInputTiming` via `Session::last_input_timing()`.\n - Resets timing at each `process_input_with_runtime` entry.\n- Threaded timing through workflow LLM backends:\n - `CodergenResult::Text` now carries active `StageTiming`.\n - API backend measures one-shot inference and agent-loop inference/tool time.\n - ACP backend attributes opaque duration to inference.\n- Populated `Outcome.timing` in production handlers:\n - Agent, prompt, fan-in, and command handlers now preserve active timing.\n - Command duration is reported as tool time.\n- Preserved timing/billing for terminal run failures:\n - `persist_terminal_engine_failure` now uses `build_conclusion_from_store` timing and billing.\n - Detached bootstrap/completion guards now preserve conclusion timing/billing when a store exists.\n - Detached failure helper now rolls up timing/billing from the store.\n- Added tests for:\n - Agent per-input inference/tool timing.\n - Agent/prompt/fan-in handler timing propagation.\n - Command handler tool timing.\n - Executor propagation into `NodeResult`.\n - Full workflow event rollup from `Outcome.timing` → `stage.completed` → `run.completed`.\n - Terminal engine failure and drop-guard timing/billing preservation.\n\nValidation passed:\n- `cargo nextest run -p fabro-agent -p fabro-workflow -p fabro-store -p fabro-core`\n - 1913 passed, 122 skipped\n- `cargo +nightly-2026-04-14 fmt --check --all`\n- `cargo +nightly-2026-04-14 clippy --workspace --all-targets -- -D warnings`\n- `cargo build -p fabro-server`\n- `git diff --check`\n\nI did not run the interactive/live server + UI E2E workflow steps, but the server build and full requested automated validation are green.", - "failure_signature": "", + "internal.retry_count.start": 0, + "last_stage": "simplify_opus", + "graph.model_stylesheet": "\n * { model: claude-opus-4-7; }\n ", "internal.work_dir": "/home/daytona/workspace/fabro", "outcome": "succeeded", - "graph.model_stylesheet": "\n * { model: claude-opus-4-7; }\n ", "command.output": "blob://sha256/12ae32cb1ec02d01eda3581b127c1fee3b0dc53572ed6baf239721a03d82e126", "internal.retry_count.toolchain": 0, "thread.preflight_compile.current_node": "preflight_lint", - "last_stage": "implement", + "thread.start.current_node": "toolchain", + "internal.retry_count.preflight_compile": 0, + "internal.fidelity": "compact", + "current_node": "simplify_opus", + "internal.retry_count.simplify_opus": 0, + "last_response": "All six fixes landed, with net **-57 lines** even while adding three shared helpers and a constructor. Summary of cleanups applied based on the three reviewers' findings:\n\n## Fixed\n\n1. **Returned timi", + "thread.toolchain.current_node": "preflight_compile", + "internal.node_visit_count": 1, + "internal.thread_id": "implement", + "graph.goal": "# Plan: Fix stage timing (inference + tool) reporting\n\n## Context\n\nThe web UI's Duration popover shows `Active (inference + tools): 0ms` for every run, including agent-heavy runs that obviously did substantial LLM and tool work. Verified on `01KSE2PAVXD56N4TWNK4T5H5VA`: 10 stage.completed events and 1 run.failed event all carry `inference_time_ms: 0, tool_time_ms: 0`, even though stages like `implement@1` (94 min wall) and `simplify_opus@1` (29 min wall) were doing nothing but inference and tool calls.\n\nTwo independent bugs:\n\n1. **No production handler ever populates `Outcome.timing`.** The plumbing from `Outcome.timing` → `NodeResult` (`lib/crates/fabro-core/src/executor.rs:30-37`) → `StageTiming` → `stage.completed` props → projection → billing rollup → run.completed/failed → UI is fully wired and shipped as of #343 (2026-05-21), but `AgentHandler::execute`, `PromptHandler::execute`, `CommandHandler::execute`, and `FanInHandler` all build `Outcome::success()` and never touch `.timing`. The executor falls back to zero, and every downstream consumer faithfully aggregates zero.\n\n2. **`persist_terminal_engine_failure` and its sibling Drop-guard failure paths discard timing/billing entirely.** When the engine returns `Err` (e.g. `VisitLimitExceeded`, which is what killed the user's run), `lib/crates/fabro-workflow/src/operations/start.rs:284-308` builds a `Conclusion` via `build_conclusion_from_store`, then throws it away (`let _conclusion = ...`) and emits `WorkflowRunFailed` with `RunTiming::wall_only(...)` and `None` for billing/diff. The three Drop-guard paths (`start.rs:934`, `1001`, `1033`) do similar with `RunTiming::default()` and never even build a conclusion.\n\nGoal: stage and run events carry real per-stage `inference_time_ms` + `tool_time_ms`; engine-failure terminal events preserve the conclusion's rolled-up timing and billing.\n\n## Approach\n\n### Part A — Capture inference + tool time in handlers (Bug 1)\n\n**A1. `fabro-agent` — accumulate per-input timing in `Session`**\n\n`lib/crates/fabro-agent/src/session.rs`\n\nAdd two `Duration` accumulators to `Session` (initialised to `Duration::ZERO`):\n- `last_input_inference_duration`\n- `last_input_tool_duration`\n\nIn `process_input_with_runtime` (line 1196), zero them at entry so each call's totals are independent.\n\nIn `run_single_input` (line 1254):\n- Wrap the inference span: capture `Instant::now()` immediately before opening the stream at line 1391, and add `.elapsed()` to `last_input_inference_duration` once `response = Some(resp)` (line 1487-1490) OR when the loop exits with an error/cancellation. The whole `'streamattempts` loop counts as inference work — retries included.\n- Wrap the tool span around `execute_tool_calls` at line 1705-1719: `Instant::now()` before, accumulate `.elapsed()` after `.await`.\n\nExpose a getter:\n```rust\npub fn last_input_timing(&self) -> SessionInputTiming { ... }\n```\nwhere `SessionInputTiming { pub inference: Duration, pub tool: Duration }` is a new tiny struct in `fabro-agent`.\n\n**A2. `fabro-workflow` — thread timing through the backend boundary**\n\n`lib/crates/fabro-workflow/src/handler/agent.rs`\n\nExtend `CodergenResult::Text` with a `timing: fabro_types::StageTiming` field (wall is irrelevant — see note below). Update the few `CodergenResult::Text { ... }` constructions found by the explore agent to populate it; existing match-bindings only read `text`/`usage`/`files_touched` so they keep compiling with `..` patterns. `CodergenResult::Full(outcome)` keeps current behaviour — the outcome itself already carries any timing.\n\nNote on wall: `lib/crates/fabro-core/src/executor.rs:30-37` reads ONLY `inference_time_ms` and `tool_time_ms` out of `outcome.timing`. The wall comes from the executor's own stopwatch. So we construct `StageTiming::new(0, inference_ms, tool_ms)` and document that the wall field is ignored in this hop.\n\n`lib/crates/fabro-workflow/src/handler/llm/api.rs`\n\n- `AgentApiBackend::run` (line 1103): after `session.process_input_with_runtime(...)` returns, read `session.last_input_timing()` and set the new `timing` on `CodergenResult::Text` at line 1094.\n- `AgentApiBackend::one_shot` (line 994): wrap the `complete_one_shot_request` call at line 1053 with `Instant::now()` / `.elapsed()`. Accumulate across repair iterations of the surrounding loop. All of it counts as inference; no tool work happens in `one_shot`. Set `timing` on `CodergenResult::Text` at line 1094.\n\n`lib/crates/fabro-workflow/src/handler/llm/acp.rs`\n\n`AgentAcpBackend::run` (line ~140): already exposes `result.duration_ms`. Set `timing: StageTiming::new(0, duration_ms, 0)` on the returned `CodergenResult::Text` (per user decision: attribute all ACP duration to inference; ACP is opaque about the split).\n\n**A3. Consume timing in stage handlers and set `outcome.timing`**\n\n- `lib/crates/fabro-workflow/src/handler/agent.rs:341` — after building `outcome`, before the final `Ok(outcome)`, set `outcome.timing = Some(timing_from_codergen_result)`.\n- `lib/crates/fabro-workflow/src/handler/prompt.rs:180` — same pattern.\n- `lib/crates/fabro-workflow/src/handler/fan_in.rs:266` — backend returns timing; pass it onto the outcome built from the fan-in response.\n- `lib/crates/fabro-workflow/src/handler/command.rs:175` — `outcome.timing = Some(StageTiming::new(0, 0, result.duration_ms))`. All command wall-time is tool time. `result.duration_ms` is already at line 154 in scope.\n\nOther handlers (`human`, `wait`, `conditional`, `parallel`, `start`, `exit`, `structured_output`, `manager_loop`) do no inference or tool work. Leave `outcome.timing` as `None`; the executor will naturally produce `inference: 0, tool: 0` for those stages, which is correct.\n\n### Part B — Preserve conclusion timing on engine failure (Bug 2)\n\n`lib/crates/fabro-workflow/src/operations/start.rs`\n\n**B1. Main path** (`persist_terminal_engine_failure`, line 274-308):\n- Rename `_conclusion` → `conclusion` and use it:\n - Pass `conclusion.timing` (already a `RunTiming` with the proper inference/tool/wall rollup from `build_conclusion_from_parts`) instead of `RunTiming::wall_only(...)`.\n - Pass `conclusion.billing.clone()` instead of `None` for the billing arg of `workflow_run_failed_from_error`.\n - `final_git_commit_sha`, `final_patch`, `diff_summary` stay `None` — those require the finalize-side workspace diff computation that this path deliberately skips.\n\n**B2. Drop-guard paths** (per user decision: fix them too):\n\n- `DetachedRunBootstrapGuard` (line 882-948): add an `Option` field. The bootstrap function builds the guard before the store exists, then mutates `bootstrap_guard.run_store = Some(store.clone())` once the store is in scope. On Drop, if the store is `Some`, the spawned task calls `build_conclusion_from_store` and uses its timing/billing; otherwise falls back to `RunTiming::default()` (pre-store failure means no stages can possibly exist).\n\n- `DetachedRunCompletionGuard` (line 953-1021): armed after the store exists, so add a non-optional `run_store: RunStoreHandle`. Drop's spawned task builds the conclusion and uses it.\n\n- `persist_detached_failure` (line 1023): add a `run_store: &RunStoreHandle` parameter. Call `build_conclusion_from_store` and forward `timing` + `billing` to the failure event. Update the two callers (postrun-related) to pass the store they already have in scope.\n\n`RunStoreHandle` is already `Clone` (the surrounding code clones it routinely), so move-into-spawned-task is fine.\n\n### Critical existing utilities to reuse (do not duplicate)\n\n- `fabro_types::StageTiming::new(wall, inference, tool)` and `RunTiming::new(...)` — invariant-enforcing constructors at `lib/crates/fabro-types/src/timing.rs:38, 91`.\n- `crate::millis_u64(duration)` helper for `Duration → u64` ms in `fabro-workflow` (used widely; see `lifecycle/event.rs:80-86`).\n- `build_conclusion_from_store` at `lib/crates/fabro-workflow/src/pipeline/finalize.rs:71` already does the rollup we need on the engine-failure path.\n- `billing_rollup_from_projection` (called inside `build_conclusion_from_parts`) sums per-stage timings into `RunTiming` — no need to reimplement.\n\n## Tests\n\n- **`fabro-agent` unit test**: feed `Session` a fake `LlmClient` whose `stream` sleeps a known duration and a fake tool that sleeps another known duration. Drive one `process_input_with_runtime` call. Assert `session.last_input_timing()` reports both non-zero and roughly matching the sleeps. Then call again and assert it's per-call (not cumulative).\n- **`fabro-workflow` handler tests**: in `handler/agent.rs`'s test module, wire a `CodergenBackend` that returns `CodergenResult::Text { timing: StageTiming::new(0, 200, 300), .. }` and assert `AgentHandler::execute`'s returned `Outcome.timing` carries those values. Mirror for `prompt.rs` and `fan_in.rs`. Add a `command.rs` test that mocks a `sandbox.exec_command_streaming` returning `duration_ms = 500` and asserts `outcome.timing.tool_time_ms == 500`.\n- **Executor integration**: add a test in `fabro-workflow` (or extend an existing one in `pipeline/finalize.rs` tests) that runs a tiny graph with a handler producing `Outcome.timing = Some(StageTiming::new(0, 100, 50))` and asserts the emitted `stage.completed` event carries those values, and that `run.completed` carries the summed rollup.\n- **`persist_terminal_engine_failure` test**: seed a `RunStore` with a couple of `stage.completed` events whose timing is non-zero, drive the engine-failure path, and assert the emitted `WorkflowRunFailed` event has `timing.inference_time_ms` and `tool_time_ms` matching the per-stage sum and `billing` populated.\n- **Drop guard tests**: trickier because of `Handle::try_current` + spawn. Add focused tests that arm a guard, drop it, and `tokio::task::yield_now().await` enough times to let the spawned task run, then assert the emitted failure event carries non-zero timing.\n- Run `cargo nextest run -p fabro-agent -p fabro-workflow -p fabro-store -p fabro-core`.\n- Run formatter and lints per CLAUDE.md: `cargo +nightly-2026-04-14 fmt --check --all` and `cargo +nightly-2026-04-14 clippy --workspace --all-targets -- -D warnings`.\n\n## End-to-end verification\n\n1. Build the server: `cargo build -p fabro-server`.\n2. Start server: `fabro server start`.\n3. Run a small agent-backed workflow (e.g. `fabro run repl` with a short prompt that fires at least one tool call).\n4. `fabro events --json | jq -s '[.[] | select(.event==\"stage.completed\")] | .[].properties.timing'` — confirm `inference_time_ms > 0` and `tool_time_ms > 0` for the agent stage.\n5. `fabro events --json | jq -s '[.[] | select(.event==\"run.completed\" or .event==\"run.failed\")] | .[].properties.timing'` — confirm `active_time_ms == inference_time_ms + tool_time_ms` and both are non-zero.\n6. Open the run in the web UI (start the SPA dev build per CLAUDE.md or rebuild the embedded SPA with `cargo dev build`), hover the Duration chip, confirm **Active (inference + tools)** is non-zero.\n7. For Bug 2: force an engine failure by setting a very low visit limit and rerunning the same workflow; confirm the `run.failed` event timing breakdown is non-zero and matches the per-stage sum.\n\n## Out of scope\n\n- Adding `wall_time_ms` correctness to `Outcome.timing` (executor ignores it; doc tweak only if necessary).\n- Surfacing inference vs tool split for ACP backend beyond \"all-inference\" attribution.\n- Backfilling timing for historical runs that have already emitted zero events — past events are immutable.\n- Web UI changes beyond what the existing popover already renders.\n", + "failure_signature": "", + "response.simplify_opus": "All six fixes landed, with net **-57 lines** even while adding three shared helpers and a constructor. Summary of cleanups applied based on the three reviewers' findings:\n\n## Fixed\n\n1. **Returned timing from `process_input_with_runtime` instead of stashing it on `Session`** (Agent 2 #1). Dropped `last_input_inference_duration` / `last_input_tool_duration` fields, the `last_input_timing()` getter, and the per-call reset prologue. Signature is now `-> (SessionInputTiming, Result<(), Error>)`. Eliminates the \"must read immediately\" implicit contract.\n\n2. **Replaced the `record_inference_duration!` macro with a free function** `record_elapsed(&mut Option, &mut Duration)` (Agent 1 #2, Agent 2 #2). Same 7 call sites, but type-checked, IDE-discoverable, and no macro hygiene.\n\n3. **Made `run_store` required on `DetachedRunBootstrapGuard::arm()`** (Agent 1 #7, Agent 2 #3/#5). Dropped the `Option` field and the external setter pattern. Drop impl unconditionally builds the conclusion now.\n\n4. **Extracted `emit_workflow_run_failed` helper** (Agent 1 #7, Agent 2 #4). Collapses the four near-identical \"build conclusion → emit run.failed\" sites in `start.rs` (terminal engine failure, both Drop guards, `persist_detached_failure`) into one shared function.\n\n5. **Added `StageTiming::active_only(inference, tool)` constructor** (Agent 1 #1). Removed the local `active_stage_timing` helper in `handler/llm/api.rs` and unified `acp.rs` and `command.rs` on the same shape.\n\n6. **Reverted `Box` in `CodergenResult::Text`** (Agent 1 #6, Agent 2 #6). Was the worst of both worlds — didn't equalise variant size, forced `.map(|usage| *usage)` ceremony at every call site. Used `#[allow(clippy::large_enum_variant, reason = \"...\")]` matching the established pattern in `event/events.rs` and `event/sink.rs`.\n\n7. **Hoisted `test_usage` and `mark_run_running` to `test_support`** (Agent 1 #3/#4). `test_usage` was duplicated in 4 files (this PR was about to add a 5th); the 4th `mark_run_running` copy was right next to a pre-existing 3-event seed in test_support that didn't quite match. Both are now public helpers in `crate::test_support`.\n\n## Skipped (with reason)\n\n- **Make Drop guard tasks survive runtime shutdown** (Agent 3 #3) — flagged as a correctness-on-shutdown concern, not introduced by this PR; widening it would be a separate fix.\n- **`wait_for_conclusion` polling timeout hardening** (Agent 2 #8) — minor CI flake risk; current 50ms budget is enough for unit tests.\n- **`Candidate::timing` zero on LLM-failure heuristic fallback** (Agent 2 #9, Agent 3 implicit) — agent itself noted this is acceptable; capturing wasted inference on errors would require threading Instants through the fan-in evaluator.\n- **Helper for the 3-line failed-outcome decoration in agent.rs/prompt.rs** (Agent 2 #7/#10) — marginal benefit not worth the indirection.\n\n## Verification\n\n- `cargo +nightly-2026-04-14 clippy --workspace --all-targets -- -D warnings` clean\n- `cargo +nightly-2026-04-14 fmt --check --all` clean\n- `cargo nextest run -p fabro-workflow -p fabro-agent -p fabro-types -p fabro-core` — all 3592 tests pass (1175 + 1844 + 573 across the affected crates).", "internal.run_id": "01KSGHHBR7DQ1RHFYKD7P46R6F", "internal.retry_count.preflight_lint": 0, "internal.retry_count.implement": 0, - "thread.start.current_node": "toolchain", - "internal.retry_count.preflight_compile": 0, "thread.preflight_lint.current_node": "implement", - "internal.fidelity": "compact" + "thread.implement.current_node": "simplify_opus" }, "node_outcomes": { "start": { @@ -835,6 +958,52 @@ "total_usd_micros": 17743163 } }, + "simplify_opus": { + "status": "succeeded", + "context_updates": { + "last_stage": "simplify_opus", + "response.simplify_opus": "All six fixes landed, with net **-57 lines** even while adding three shared helpers and a constructor. Summary of cleanups applied based on the three reviewers' findings:\n\n## Fixed\n\n1. **Returned timing from `process_input_with_runtime` instead of stashing it on `Session`** (Agent 2 #1). Dropped `last_input_inference_duration` / `last_input_tool_duration` fields, the `last_input_timing()` getter, and the per-call reset prologue. Signature is now `-> (SessionInputTiming, Result<(), Error>)`. Eliminates the \"must read immediately\" implicit contract.\n\n2. **Replaced the `record_inference_duration!` macro with a free function** `record_elapsed(&mut Option, &mut Duration)` (Agent 1 #2, Agent 2 #2). Same 7 call sites, but type-checked, IDE-discoverable, and no macro hygiene.\n\n3. **Made `run_store` required on `DetachedRunBootstrapGuard::arm()`** (Agent 1 #7, Agent 2 #3/#5). Dropped the `Option` field and the external setter pattern. Drop impl unconditionally builds the conclusion now.\n\n4. **Extracted `emit_workflow_run_failed` helper** (Agent 1 #7, Agent 2 #4). Collapses the four near-identical \"build conclusion → emit run.failed\" sites in `start.rs` (terminal engine failure, both Drop guards, `persist_detached_failure`) into one shared function.\n\n5. **Added `StageTiming::active_only(inference, tool)` constructor** (Agent 1 #1). Removed the local `active_stage_timing` helper in `handler/llm/api.rs` and unified `acp.rs` and `command.rs` on the same shape.\n\n6. **Reverted `Box` in `CodergenResult::Text`** (Agent 1 #6, Agent 2 #6). Was the worst of both worlds — didn't equalise variant size, forced `.map(|usage| *usage)` ceremony at every call site. Used `#[allow(clippy::large_enum_variant, reason = \"...\")]` matching the established pattern in `event/events.rs` and `event/sink.rs`.\n\n7. **Hoisted `test_usage` and `mark_run_running` to `test_support`** (Agent 1 #3/#4). `test_usage` was duplicated in 4 files (this PR was about to add a 5th); the 4th `mark_run_running` copy was right next to a pre-existing 3-event seed in test_support that didn't quite match. Both are now public helpers in `crate::test_support`.\n\n## Skipped (with reason)\n\n- **Make Drop guard tasks survive runtime shutdown** (Agent 3 #3) — flagged as a correctness-on-shutdown concern, not introduced by this PR; widening it would be a separate fix.\n- **`wait_for_conclusion` polling timeout hardening** (Agent 2 #8) — minor CI flake risk; current 50ms budget is enough for unit tests.\n- **`Candidate::timing` zero on LLM-failure heuristic fallback** (Agent 2 #9, Agent 3 implicit) — agent itself noted this is acceptable; capturing wasted inference on errors would require threading Instants through the fan-in evaluator.\n- **Helper for the 3-line failed-outcome decoration in agent.rs/prompt.rs** (Agent 2 #7/#10) — marginal benefit not worth the indirection.\n\n## Verification\n\n- `cargo +nightly-2026-04-14 clippy --workspace --all-targets -- -D warnings` clean\n- `cargo +nightly-2026-04-14 fmt --check --all` clean\n- `cargo nextest run -p fabro-workflow -p fabro-agent -p fabro-types -p fabro-core` — all 3592 tests pass (1175 + 1844 + 573 across the affected crates).", + "last_response": "All six fixes landed, with net **-57 lines** even while adding three shared helpers and a constructor. Summary of cleanups applied based on the three reviewers' findings:\n\n## Fixed\n\n1. **Returned timi" + }, + "notes": "Stage completed: simplify_opus", + "usage": { + "input": { + "usage": { + "model": { + "provider": "anthropic", + "model_id": "claude-opus-4-7" + }, + "tokens": { + "input_tokens": 146925, + "output_tokens": 49357, + "reasoning_tokens": 0, + "cache_read_tokens": 14717122, + "cache_write_tokens": 1256698 + } + }, + "facts": { + "algorithm": "anthropic", + "cache_write_5m_tokens": 1256698, + "cache_write_1h_tokens": 0 + } + }, + "total_usd_micros": 17181473 + }, + "files_touched": [ + "/home/daytona/workspace/fabro/lib/crates/fabro-agent/src/session.rs", + "/home/daytona/workspace/fabro/lib/crates/fabro-types/src/timing.rs", + "/home/daytona/workspace/fabro/lib/crates/fabro-workflow/src/billing_rollup.rs", + "/home/daytona/workspace/fabro/lib/crates/fabro-workflow/src/event/convert.rs", + "/home/daytona/workspace/fabro/lib/crates/fabro-workflow/src/handler/agent.rs", + "/home/daytona/workspace/fabro/lib/crates/fabro-workflow/src/handler/command.rs", + "/home/daytona/workspace/fabro/lib/crates/fabro-workflow/src/handler/llm/acp.rs", + "/home/daytona/workspace/fabro/lib/crates/fabro-workflow/src/handler/llm/api.rs", + "/home/daytona/workspace/fabro/lib/crates/fabro-workflow/src/handler/prompt.rs", + "/home/daytona/workspace/fabro/lib/crates/fabro-workflow/src/operations/start.rs", + "/home/daytona/workspace/fabro/lib/crates/fabro-workflow/src/pipeline/finalize.rs", + "/home/daytona/workspace/fabro/lib/crates/fabro-workflow/src/test_support.rs" + ] + }, "preflight_compile": { "status": "succeeded", "context_updates": { @@ -852,9 +1021,10 @@ "usage": null } }, - "next_node_id": "simplify_opus", + "next_node_id": "simplify_gpt", "node_visits": { "implement": 1, + "simplify_opus": 1, "toolchain": 1, "start": 1, "preflight_compile": 1, @@ -884,6 +1054,319 @@ "superseded_by": null, "pending_interviews": {}, "stages": { + "simplify_opus@1": { + "first_event_seq": 845, + "prompt": null, + "response": null, + "completion": null, + "provider_used": { + "mode": "agent", + "provider": "anthropic", + "model": "claude-opus-4-7" + }, + "diff": null, + "script_invocation": null, + "script_timing": null, + "parallel_results": null, + "output": null, + "started_at": "2026-05-25T22:25:15.922125Z", + "handler": "agent", + "usage": { + "input_tokens": 146925, + "output_tokens": 49357, + "total_tokens": 16170102, + "reasoning_tokens": 0, + "cache_read_tokens": 14717122, + "cache_write_tokens": 1256698, + "total_usd_micros": 17181473 + }, + "model": { + "provider": "anthropic", + "model_id": "claude-opus-4-7" + }, + "todos": { + "kind": "anthropic_tasks", + "list_id": "anthropic_tasks:2d85ef70-8fdf-4c5a-bd6f-2e4e4da09696", + "items": [ + { + "id": "1", + "status": "completed", + "order": 0, + "subject": "Return SessionInputTiming from process_input_with_runtime", + "description": "Drop last_input_inference_duration/last_input_tool_duration fields, the SessionInputTiming reset prologue, last_input_timing() getter, and the macro. Change return type to `(SessionInputTiming, Result<(), Error>)` or similar. Update callers in handler/llm/api.rs.", + "active_form": "Returning timing from process_input" + }, + { + "id": "2", + "status": "completed", + "order": 1, + "subject": "Require run_store on DetachedRunBootstrapGuard", + "description": "Make run_store a required arg at arm(). Drop Option field and external setter. Simplify Drop impl to always use the store.", + "active_form": "Requiring run_store on bootstrap guard" + }, + { + "id": "3", + "status": "completed", + "order": 2, + "subject": "Extract emit_terminal_failure helper", + "description": "Collapse the 4 near-identical conclusion+run.failed sites in start.rs into one helper.", + "active_form": "Extracting emit_terminal_failure" + }, + { + "id": "4", + "status": "completed", + "order": 3, + "subject": "Add StageTiming::active_only constructor", + "description": "Add sibling to wall_only. Apply at the 3 sites in api.rs/acp.rs/command.rs and delete local active_stage_timing helper.", + "active_form": "Adding StageTiming::active_only" + }, + { + "id": "5", + "status": "completed", + "order": 4, + "subject": "Revert Box on CodergenResult::Text usage", + "description": "Pre-change shape was already large; adding StageTiming (24 bytes) doesn't change size category. Revert to Option<BilledModelUsage>. Drop the .map(|usage| *usage) call sites.", + "active_form": "Reverting Box on usage" + }, + { + "id": "6", + "status": "completed", + "order": 5, + "subject": "Move test_usage + mark_run_running to test_support", + "description": "test_usage is duplicated in 4 files (this diff adds the 4th); mark_run_running is partially in test_support already. Hoist both.", + "active_form": "Hoisting test fixtures" + } + ] + }, + "subagents": [ + { + "agent_id": "64fbe2b6", + "depth": 1, + "task": "You are Agent 1 (Code Reuse Review) for a code review.\n\nThe diff is at /tmp/full_diff.txt. Read it, then look for opportunities for code reuse.\n\nContext: this change fixes stage timing reporting. It threads `StageTiming` (inference_time_ms, tool_time_ms) from `fabro-agent`'s Session through workflow handlers into `Outcome.timing` and into engine-failure terminal events.\n\nFiles changed (review root is /home/daytona/workspace/fabro):\n- lib/crates/fabro-agent/src/lib.rs, src/session.rs\n- lib/crates/fabro-core/src/executor.rs\n- lib/crates/fabro-types/src/timing.rs (doc tweak)\n- lib/crates/fabro-workflow/src/handler/agent.rs, command.rs, fan_in.rs, prompt.rs\n- lib/crates/fabro-workflow/src/handler/llm/acp.rs, api.rs, router.rs\n- lib/crates/fabro-workflow/src/operations/start.rs\n- lib/crates/fabro-workflow/tests/it/integration.rs\n\nTask:\n1. For each new piece of logic, search the codebase with Grep for similar existing utilities. Common candidates:\n - `millis_u64`, `elapsed_ms`, `RunTiming::wall_only`, `RunTiming::default()`, `StageTiming::new/default/wall_only` (in fabro-types and fabro-util)\n - existing run-failure helpers, `build_conclusion_from_store`, `run_failure_from_error`\n - existing inference-timing capture (search for `Instant::now()` usage in fabro-agent/fabro-llm)\n - timing accumulation patterns\n2. In particular, scrutinize:\n - The `active_stage_timing` helper in handler/llm/api.rs — is it duplicative? Used only locally?\n - The `record_inference_duration!` macro in session.rs — would a simple helper method on Session work better and be less hacky than a macro? Look at how the macro is used (it captures `self.last_input_inference_duration` and `inference_start` via outer scope).\n - The new test helpers `test_usage`, `append_completed_stage`, `mark_run_running`, `wait_for_conclusion` in operations/start.rs tests — do similar helpers already exist in the workflow crate's tests?\n - The boxing of `BilledModelUsage` in `CodergenResult::Text` — is the size differential actually warranting `Box`? (CodergenResult variants probably already big due to Outcome.)\n3. Flag any code that should be replaced with an existing helper. Provide file:line and the replacement to use.\n\nOutput: a numbered list of concrete findings with file:line refs and suggested fixes. If nothing to fix, say so.", + "status": { + "kind": "completed", + "success": true, + "turns_used": 58 + } + }, + { + "agent_id": "422e2a93", + "depth": 1, + "task": "You are Agent 2 (Code Quality Review).\n\nThe diff is at /tmp/full_diff.txt. Read it. Repo root is /home/daytona/workspace/fabro.\n\nContext: this change adds stage timing (inference_time_ms, tool_time_ms) to outcomes and run-failure paths.\n\nFiles changed:\n- lib/crates/fabro-agent/src/session.rs (adds last_input_inference_duration, last_input_tool_duration, SessionInputTiming, last_input_timing(), record_inference_duration macro)\n- lib/crates/fabro-workflow/src/handler/agent.rs, prompt.rs, command.rs, fan_in.rs, llm/api.rs, llm/acp.rs (thread timing through CodergenResult)\n- lib/crates/fabro-workflow/src/operations/start.rs (engine-failure paths preserve conclusion timing/billing; DetachedRunBootstrapGuard gains an Option; DetachedRunCompletionGuard gains a RunStoreHandle; persist_detached_failure gains a &RunStoreHandle parameter)\n- BilledModelUsage was boxed inside CodergenResult::Text\n\nReview for hacky patterns:\n\n1. **Redundant state**: `last_input_inference_duration` and `last_input_tool_duration` on Session — are they actually needed as struct fields, or could they be returned directly from `process_input_with_runtime`? What's the contract semantics — does any caller need to read them later, or only immediately after the call? If only immediately after, returning them is cleaner than mutable fields-with-reset.\n\n2. **The `record_inference_duration!` macro** in session.rs:1410: it's a macro that captures `self.last_input_inference_duration` and `inference_start` from the outer scope, and is called from at least 6 different points in `run_single_input`. This is fragile (the multiple call sites in error paths plus the loop-end one suggest this should be wrapped in a guard struct like a Drop-on-elapsed scope, or the whole inference span could be tracked by `Instant::now() - stream_open_time` summed in a simpler way). Investigate and propose.\n\n3. **Parameter sprawl**: `persist_detached_failure` gained a `run_store: &RunStoreHandle` param. `DetachedRunBootstrapGuard` gained an `Option` field (set after construction via direct field write `bootstrap_guard.run_store = Some(...)`). `DetachedRunCompletionGuard::arm` gained a param. Is there a cleaner way? E.g. always require run_store at construction (and skip the guard arming until store exists)? Or fold the conclusion-building into a shared helper?\n\n4. **Copy-paste with variation**: the three Drop-guard paths and `persist_terminal_engine_failure` and `persist_detached_failure` all do roughly: build conclusion → call `Event::workflow_run_failed_from_error` with timing + billing → append. Could a single helper unify these? Look at the spawned-task blocks in `Drop for DetachedRunBootstrapGuard` and `Drop for DetachedRunCompletionGuard`.\n\n5. **Leaky abstractions**: `DetachedRunBootstrapGuard::run_store` is written from outside (`bootstrap_guard.run_store = Some(run_store.clone());` at start.rs:213). The field is `pub(crate)` (or private same-module). This is a setter-by-direct-field-write pattern. Cleaner would be a method or constructor that requires it.\n\n6. **Boxing**: `usage: Option` → `usage: Option>`. Was this needed (large_enum_variant clippy lint?) and if so, is it the right fix here vs boxing elsewhere?\n\n7. The `if let Ok(validated) = ... else { ... }` refactor in agent.rs and prompt.rs structurally changes error handling; verify it preserves semantics (the error case used to early-return; in the new code the else branch also early-returns with the failure outcome). Look closely.\n\n8. Look at test helpers (`mark_run_running`, `append_completed_stage`, `wait_for_conclusion`, `test_usage`) — are they reasonable or do they leak internals?\n\n9. In `fan_in.rs`, `Candidate` gains a `timing: StageTiming` field. The heuristic-select path returns `StageTiming::default()`. In `llm_evaluate`, when the LLM call fails, the catch-all falls through to `heuristic_select(results)` and the resulting Candidate has zero timing — but the LLM may have done some work before failing. Is this a real concern or out of scope?\n\n10. The new `if let Ok(validated) = ...` blocks in handler/agent.rs (around line 364) and handler/prompt.rs (around line 196) introduce a 3-line repeated pattern (failed.timing/usage/files_touched). Could be a helper, but may not be worth it.\n\nOutput: numbered findings with file:line and fix recommendations. Be aggressive — this is greenfield. If clean, say so.", + "status": { + "kind": "completed", + "success": true, + "turns_used": 39 + } + }, + { + "agent_id": "0a24389f", + "depth": 1, + "task": "You are Agent 3 (Efficiency Review).\n\nThe diff is at /tmp/full_diff.txt. Read it. Repo root is /home/daytona/workspace/fabro.\n\nContext: this change adds stage timing capture in fabro-agent/Session and threads it through workflow handlers. It also preserves conclusion timing/billing on engine-failure paths.\n\nReview for efficiency issues:\n\n1. **Hot-path: `record_inference_duration!` macro** in session.rs:1410. The macro takes Instant::now()-based elapsed and accumulates via `.saturating_add`. Inspect: is there any meaningful per-token overhead? (It's only called at retry boundaries / once per single_input loop iteration, so likely fine.)\n\n2. **`build_conclusion_from_store`** is called now in **four** places on engine-failure: `persist_terminal_engine_failure`, `Drop for DetachedRunBootstrapGuard`, `Drop for DetachedRunCompletionGuard`, `persist_detached_failure`. Each rebuilds the conclusion from scratch by reading the entire run-store projection. Is there an N+1 or redundancy here? Could `Drop for DetachedRunCompletionGuard` reuse a conclusion already built elsewhere?\n\n3. **Drop-guard spawned tasks**: `Drop for DetachedRunBootstrapGuard` and `Drop for DetachedRunCompletionGuard` both `Handle::try_current().spawn(async move { ... })` for the failure-event append. The spawned task now also calls `build_conclusion_from_store(...).await`. This is fire-and-forget. Is there a risk it doesn't complete before process exit (e.g. on critical engine failures)? Not strictly an efficiency issue but related to correctness-on-shutdown.\n\n4. **Sequential awaits**: in the new Drop tasks, the conclusion build and event append are sequential. Could be unified.\n\n5. **Cloning**: `run_store.clone()` is called multiple times — `RunStoreHandle: Clone` is presumably cheap (Arc-wrap). Verify by grepping at lib/crates/fabro-workflow for `struct RunStoreHandle` or `RunStoreHandle = ` — what's the underlying type?\n\n6. **Memory/data**: any unbounded growth? The two new Duration fields on Session are bounded (reset per process_input call). The `inference_duration`/`tool_duration` locals in api.rs run/one_shot are scoped per call. Fine.\n\n7. **boxing BilledModelUsage**: pure-stack to heap; trivially small one-time alloc per LLM call. Negligible.\n\n8. **The session.rs test `last_input_timing_reports_inference_and_tool_per_call`** sleeps real wall time (20-30ms). That's fine but slightly slow; CI implication is minor.\n\n9. **fan_in.rs**: `let timing = outcome.timing.unwrap_or_default();` then `outcome.timing` is also used through the rest. Verify no double-unwrap/clone.\n\n10. **agent.rs:413** `outcome.timing = Some(timing);` — and inside the structured-output failure branch a separate `failed.timing = Some(timing)`. Verify `timing` is `Copy` (it should be — `StageTiming` is a small POD type).\n\nOutput: numbered findings with file:line and recommendations. Skip if not material.", + "status": { + "kind": "completed", + "success": true, + "turns_used": 29 + } + } + ], + "permission_level": "full", + "agent_tools": [ + { + "name": "AskUserQuestion", + "description": "Ask the human one or more questions and wait for their answers before continuing this stage.", + "source": { + "kind": "native" + }, + "category": "other", + "invoked": false + }, + { + "name": "TaskCreate", + "description": "Create pending tasks in the current session. Use concise subjects, descriptions, optional activeForm text, and metadata. Check TaskList first to avoid duplicate tasks.", + "source": { + "kind": "native" + }, + "category": "other", + "invoked": true + }, + { + "name": "TaskGet", + "description": "Get one task by taskId, including subject, status, description, owner, blockedBy, and blocks.", + "source": { + "kind": "native" + }, + "category": "other", + "invoked": false + }, + { + "name": "TaskList", + "description": "List tasks for the current session, including status, owner, and blocking dependencies. Use TaskGet with a taskId for full description and dependency details.", + "source": { + "kind": "native" + }, + "category": "other", + "invoked": true + }, + { + "name": "TaskUpdate", + "description": "Update an existing task's status, text, owner, metadata, or dependencies. Valid statuses are pending, in_progress, completed, and deleted. After completing a task, call TaskList to find newly unblocked work.", + "source": { + "kind": "native" + }, + "category": "other", + "invoked": true + }, + { + "name": "close_agent", + "description": "Close a running subagent that is no longer needed.", + "source": { + "kind": "native" + }, + "category": "subagent", + "invoked": false + }, + { + "name": "edit_file", + "description": "Edit a file by replacing an exact string. The old_string must be an exact match and unique unless replace_all is true; include surrounding context when needed. Read the file first and preserve existing indentation.", + "source": { + "kind": "native" + }, + "category": "write", + "invoked": true + }, + { + "name": "glob", + "description": "Find files by file names using a glob pattern. Use path to choose the search root. Prefer this over shell find or ls when locating repository files.", + "source": { + "kind": "native" + }, + "category": "read", + "invoked": false + }, + { + "name": "grep", + "description": "Search file contents with a regex pattern. Use path to choose the search root, glob_filter to limit matching files, case_insensitive for case folding, and max_results to cap output.", + "source": { + "kind": "native" + }, + "category": "read", + "invoked": true + }, + { + "name": "read_file", + "description": "Read files before editing them. Returns line-numbered text and supports offset/limit for large files. Use this instead of shell cat, head, tail, or sed when inspecting repository files.", + "source": { + "kind": "native" + }, + "category": "read", + "invoked": true + }, + { + "name": "send_input", + "description": "Send a follow-up message to a running subagent when new information or corrected instructions are needed.", + "source": { + "kind": "native" + }, + "category": "subagent", + "invoked": false + }, + { + "name": "shell", + "description": "Execute shell commands for terminal operations, package managers, tests and builds. Use dedicated tools for file reads, file edits, filename searches, and content searches. Provide timeout_ms for long-running commands.", + "source": { + "kind": "native" + }, + "category": "shell", + "invoked": true + }, + { + "name": "spawn_agent", + "description": "Spawn a subagent for independent work or context isolation. Use it for tasks that can proceed separately, and avoid duplicating the same work in the parent session.", + "source": { + "kind": "native" + }, + "category": "subagent", + "invoked": true + }, + { + "name": "wait", + "description": "Wait for a subagent to complete, then use the result to synthesize the outcome for the user.", + "source": { + "kind": "native" + }, + "category": "subagent", + "invoked": true + }, + { + "name": "web_fetch", + "description": "Fetch content from a URL that starts with http:// or https://. Pass a prompt to extract specific information or summarize the page; omit prompt to return the page content.", + "source": { + "kind": "native" + }, + "category": "other", + "invoked": false + }, + { + "name": "web_search", + "description": "Search the web using Brave Search when current external information is needed. Returns result titles, URLs, and descriptions; use web_fetch for a specific URL.", + "source": { + "kind": "native" + }, + "category": "other", + "invoked": false + }, + { + "name": "write_file", + "description": "Create new files, or overwrite an existing file only when replacement is explicitly intended. Prefer edit_file for targeted changes to existing files because write_file overwrites the full file content.", + "source": { + "kind": "native" + }, + "category": "write", + "invoked": false + } + ], + "context_window": { + "provider": "anthropic", + "model": "claude-opus-4-7", + "context_window_tokens": 1000000, + "input_tokens": 159713, + "usage_percent": 15.9713, + "count_method": "response_usage_scaled_breakdown", + "staleness": "live", + "generated_at": "2026-05-25T22:48:07.239132Z", + "event_seq": 1536, + "breakdown": [ + { + "category": "system_prompt", + "tokens": 2301, + "usage_percent": 0.2301 + }, + { + "category": "tools", + "tokens": 2613, + "usage_percent": 0.2613 + }, + { + "category": "memory", + "tokens": 5520, + "usage_percent": 0.552 + }, + { + "category": "conversation", + "tokens": 149272, + "usage_percent": 14.9272 + }, + { + "category": "other", + "tokens": 7, + "usage_percent": 0.0007 + } + ], + "warnings": [] + }, + "state": "running" + }, "toolchain@1": { "first_event_seq": 21, "prompt": null, @@ -1066,7 +1549,12 @@ "first_event_seq": 51, "prompt": null, "response": null, - "completion": null, + "completion": { + "outcome": "succeeded", + "notes": "Stage completed: implement", + "failure_reason": null, + "timestamp": "2026-05-25T22:25:11.924633Z" + }, "provider_used": { "mode": "agent", "provider": "openai", @@ -1080,6 +1568,12 @@ "output": null, "started_at": "2026-05-25T21:49:17.981654Z", "handler": "agent", + "timing": { + "wall_time_ms": 2153930, + "inference_time_ms": 0, + "tool_time_ms": 0, + "active_time_ms": 0 + }, "usage": { "input_tokens": 2811275, "output_tokens": 9602, @@ -1297,7 +1791,7 @@ ], "warnings": [] }, - "state": "running" + "state": "succeeded" } } } \ No newline at end of file diff --git a/stages/005-implement@1/diff.patch b/stages/005-implement@1/diff.patch new file mode 100644 index 000000000..06d3b4975 --- /dev/null +++ b/stages/005-implement@1/diff.patch @@ -0,0 +1,1770 @@ +diff --git a/lib/crates/fabro-agent/src/lib.rs b/lib/crates/fabro-agent/src/lib.rs +index e91695865..3669cba75 100644 +--- a/lib/crates/fabro-agent/src/lib.rs ++++ b/lib/crates/fabro-agent/src/lib.rs +@@ -61,8 +61,8 @@ pub use sandbox::{ + shell_quote, + }; + pub use session::{ +- CompletionCoordinator, Session, SessionControlHandle, StaticEnvProvider, SteeringItem, +- ToolEnvProvider, ++ CompletionCoordinator, Session, SessionControlHandle, SessionInputTiming, StaticEnvProvider, ++ SteeringItem, ToolEnvProvider, + }; + pub use skills::Skill; + pub use subagent::{ +diff --git a/lib/crates/fabro-agent/src/session.rs b/lib/crates/fabro-agent/src/session.rs +index d97836c0d..24df5149d 100644 +--- a/lib/crates/fabro-agent/src/session.rs ++++ b/lib/crates/fabro-agent/src/session.rs +@@ -1,6 +1,6 @@ + use std::collections::{HashMap, VecDeque}; + use std::sync::{Arc, Mutex, RwLock}; +-use std::time::SystemTime; ++use std::time::{Duration, Instant, SystemTime}; + + use fabro_auth::CredentialSource; + use fabro_llm::client::Client; +@@ -70,6 +70,12 @@ pub enum SteeringItem { + }, + } + ++#[derive(Debug, Clone, Copy, Default, PartialEq, Eq)] ++pub struct SessionInputTiming { ++ pub inference: Duration, ++ pub tool: Duration, ++} ++ + impl SteeringItem { + #[must_use] + pub fn actor(&self) -> Option<&Principal> { +@@ -337,6 +343,8 @@ pub struct Session { + tool_env_provider: Option>, + subagent_manager: Option>>, + completion_coordinator: Option>, ++ last_input_inference_duration: Duration, ++ last_input_tool_duration: Duration, + } + + impl Session { +@@ -374,6 +382,8 @@ impl Session { + tool_env_provider: None, + subagent_manager, + completion_coordinator: None, ++ last_input_inference_duration: Duration::ZERO, ++ last_input_tool_duration: Duration::ZERO, + } + } + +@@ -1188,6 +1198,14 @@ impl Session { + &self.file_tracker + } + ++ #[must_use] ++ pub const fn last_input_timing(&self) -> SessionInputTiming { ++ SessionInputTiming { ++ inference: self.last_input_inference_duration, ++ tool: self.last_input_tool_duration, ++ } ++ } ++ + pub async fn process_input(&mut self, input: &str) -> Result<(), Error> { + self.process_input_with_runtime(input, AgentToolRuntime::default()) + .await +@@ -1198,6 +1216,8 @@ impl Session { + input: &str, + agent_tool_runtime: AgentToolRuntime, + ) -> Result<(), Error> { ++ self.last_input_inference_duration = Duration::ZERO; ++ self.last_input_tool_duration = Duration::ZERO; + if self.state == SessionState::Closed { + return Err(Error::SessionClosed); + } +@@ -1388,6 +1408,16 @@ impl Session { + }; + let client = self.llm_client.clone(); + let cancel_token_for_select = self.cancel_token.clone(); ++ let mut inference_start = Some(Instant::now()); ++ macro_rules! record_inference_duration { ++ () => { ++ if let Some(start) = inference_start.take() { ++ self.last_input_inference_duration = self ++ .last_input_inference_duration ++ .saturating_add(start.elapsed()); ++ } ++ }; ++ } + let stream_outcome: Option> = tokio::select! { + biased; + () = round_token.cancelled() => None, +@@ -1395,8 +1425,15 @@ impl Session { + stream = self.open_stream_with_retry(&client, &request, &retry_policy) => Some(stream), + }; + let mut event_stream = if let Some(stream) = stream_outcome { +- stream? ++ match stream { ++ Ok(stream) => stream, ++ Err(err) => { ++ record_inference_duration!(); ++ return Err(err); ++ } ++ } + } else { ++ record_inference_duration!(); + if self.cancel_token.is_cancelled() { + self.close(); + return Err(self.interrupted_error()); +@@ -1472,6 +1509,7 @@ impl Session { + // If terminal cancel fired, drop the stream and bail out. + if self.cancel_token.is_cancelled() { + drop(event_stream); ++ record_inference_duration!(); + self.close(); + return Err(self.interrupted_error()); + } +@@ -1538,7 +1576,13 @@ impl Session { + stream = self.open_stream_with_retry(&client, &request, &retry_policy) => Some(stream), + }; + event_stream = if let Some(stream) = retry_outcome { +- stream? ++ match stream { ++ Ok(stream) => stream, ++ Err(err) => { ++ record_inference_duration!(); ++ return Err(err); ++ } ++ } + } else { + steer_interrupted = + round_token.is_cancelled() && !self.cancel_token.is_cancelled(); +@@ -1556,6 +1600,7 @@ impl Session { + }, + ); + } ++ record_inference_duration!(); + return Err(self.emit_llm_error(err)); + } + +@@ -1584,7 +1629,13 @@ impl Session { + stream = self.open_stream_with_retry(&client, &request, &retry_policy) => Some(stream), + }; + event_stream = if let Some(stream) = retry_outcome { +- stream? ++ match stream { ++ Ok(stream) => stream, ++ Err(err) => { ++ record_inference_duration!(); ++ return Err(err); ++ } ++ } + } else { + steer_interrupted = + round_token.is_cancelled() && !self.cancel_token.is_cancelled(); +@@ -1592,6 +1643,7 @@ impl Session { + }; + } + } ++ record_inference_duration!(); + + // Mid-LLM steer interrupt: drop the unrecorded turn, clear any + // partial visible output, and re-iterate. The next turn's +@@ -1702,6 +1754,7 @@ impl Session { + + // Execute tool calls (parallel or sequential based on provider) + self.transition(SessionState::Executing); ++ let tool_start = Instant::now(); + let results = execute_tool_calls( + &tool_calls, + true, +@@ -1717,6 +1770,9 @@ impl Session { + agent_tool_runtime, + ) + .await; ++ self.last_input_tool_duration = self ++ .last_input_tool_duration ++ .saturating_add(tool_start.elapsed()); + composite_watcher.abort(); + if tool_calls + .iter() +@@ -2091,6 +2147,47 @@ mod tests { + } + } + ++ struct DelayedStreamProvider { ++ responses: Vec, ++ delay: Duration, ++ call_index: AtomicUsize, ++ } ++ ++ impl DelayedStreamProvider { ++ fn new(responses: Vec, delay: Duration) -> Self { ++ Self { ++ responses, ++ delay, ++ call_index: AtomicUsize::new(0), ++ } ++ } ++ } ++ ++ #[async_trait::async_trait] ++ impl ProviderAdapter for DelayedStreamProvider { ++ fn name(&self) -> &'static str { ++ "mock" ++ } ++ ++ async fn complete(&self, _request: &Request) -> Result { ++ Err(LlmError::Configuration { ++ message: "DelayedStreamProvider does not implement complete()".into(), ++ source: None, ++ }) ++ } ++ ++ async fn stream(&self, _request: &Request) -> Result { ++ sleep(self.delay).await; ++ let idx = self.call_index.fetch_add(1, Ordering::SeqCst); ++ let response = if idx < self.responses.len() { ++ self.responses[idx].clone() ++ } else { ++ self.responses[self.responses.len() - 1].clone() ++ }; ++ Ok(response_to_stream(response)) ++ } ++ } ++ + async fn make_session_with_provider(provider: Arc) -> Session { + make_session_with_provider_and_manager(provider, None).await + } +@@ -2165,6 +2262,56 @@ mod tests { + } + } + ++ #[tokio::test] ++ async fn last_input_timing_reports_inference_and_tool_per_call() { ++ let mut registry = ToolRegistry::new(); ++ registry.register(RegisteredTool { ++ definition: ToolDefinition { ++ name: "slow_tool".into(), ++ description: "Sleeps before returning".into(), ++ parameters: serde_json::json!({"type": "object"}), ++ }, ++ executor: Arc::new(|_args, _ctx| { ++ Box::pin(async move { ++ sleep(Duration::from_millis(30)).await; ++ Ok("slept".to_string()) ++ }) ++ }), ++ source: ToolSource::Native, ++ }); ++ let provider = Arc::new(DelayedStreamProvider::new( ++ vec![ ++ tool_call_response("slow_tool", "call_1", serde_json::json!({})), ++ text_response("Done!"), ++ text_response("Second response"), ++ ], ++ Duration::from_millis(20), ++ )); ++ let client = make_client(provider).await; ++ let profile = Arc::new(TestProfile::with_tools(registry)); ++ let env = Arc::new(MockSandbox::default()); ++ let mut session = Session::new(client, profile, env, SessionOptions::default(), None); ++ ++ session.process_input("use the slow tool").await.unwrap(); ++ let first = session.last_input_timing(); ++ assert!( ++ first.inference >= Duration::from_millis(35), ++ "expected non-zero inference timing for first input, got {first:?}" ++ ); ++ assert!( ++ first.tool >= Duration::from_millis(20), ++ "expected non-zero tool timing for first input, got {first:?}" ++ ); ++ ++ session.process_input("no tools this time").await.unwrap(); ++ let second = session.last_input_timing(); ++ assert!( ++ second.inference >= Duration::from_millis(15), ++ "expected per-input inference timing for second input, got {second:?}" ++ ); ++ assert_eq!(second.tool, Duration::ZERO); ++ } ++ + struct SequenceToolEnvProvider { + values: Mutex>>, + } +diff --git a/lib/crates/fabro-core/src/executor.rs b/lib/crates/fabro-core/src/executor.rs +index 19cf142a1..3a94eb332 100644 +--- a/lib/crates/fabro-core/src/executor.rs ++++ b/lib/crates/fabro-core/src/executor.rs +@@ -555,6 +555,55 @@ mod tests { + assert_eq!(log.lock().unwrap().clone(), vec!["start"]); + } + ++ #[tokio::test] ++ async fn executor_copies_outcome_active_timing_into_node_result() { ++ struct TimedHandler; ++ ++ #[async_trait] ++ impl NodeHandler for TimedHandler { ++ async fn execute( ++ &self, ++ _node: &TestNode, ++ _context: &Context, ++ _graph: &TestGraph, ++ ) -> Result { ++ let mut outcome = Outcome::success(); ++ outcome.timing = Some(fabro_types::StageTiming::new(999, 100, 50)); ++ Ok(outcome) ++ } ++ } ++ ++ struct TimingCapture(Arc>>); ++ ++ #[async_trait] ++ impl RunLifecycle for TimingCapture { ++ async fn after_node( ++ &self, ++ _node: &TestNode, ++ result: &mut NodeResult, ++ _state: &ExecutionState, ++ ) -> Result<()> { ++ *self.0.lock().unwrap() = Some(( ++ result.inference_time.as_millis(), ++ result.tool_time.as_millis(), ++ )); ++ Ok(()) ++ } ++ } ++ ++ let captured = Arc::new(Mutex::new(None)); ++ let g = linear_graph(&["work", "end"]); ++ let state = ExecutionState::new(&g).unwrap(); ++ let executor = ++ ExecutorBuilder::new(Arc::new(TimedHandler) as Arc>) ++ .lifecycle(Box::new(TimingCapture(Arc::clone(&captured)))) ++ .build(); ++ ++ executor.run(&g, state).await.unwrap(); ++ ++ assert_eq!(*captured.lock().unwrap(), Some((100, 50))); ++ } ++ + #[tokio::test] + async fn executor_builder_sets_cancel_token() { + let token = CancellationToken::new(); +diff --git a/lib/crates/fabro-types/src/timing.rs b/lib/crates/fabro-types/src/timing.rs +index 993511c6a..6ca201143 100644 +--- a/lib/crates/fabro-types/src/timing.rs ++++ b/lib/crates/fabro-types/src/timing.rs +@@ -46,8 +46,8 @@ impl StageTiming { + } + } + +- /// Stages with no inference/tool work (human, wait, conditional, fan-in, +- /// start, exit, parallel container) report wall time only. ++ /// Stages with no inference/tool work (human, wait, conditional, start, ++ /// exit, parallel container) report wall time only. + #[must_use] + pub fn wall_only(wall_time_ms: u64) -> Self { + Self::new(wall_time_ms, 0, 0) +diff --git a/lib/crates/fabro-workflow/src/handler/agent.rs b/lib/crates/fabro-workflow/src/handler/agent.rs +index 3290ca85a..f7a9048a5 100644 +--- a/lib/crates/fabro-workflow/src/handler/agent.rs ++++ b/lib/crates/fabro-workflow/src/handler/agent.rs +@@ -4,7 +4,7 @@ use std::sync::Arc; + use async_trait::async_trait; + use fabro_agent::Sandbox; + use fabro_graphviz::graph::{Graph, Node}; +-use fabro_types::{RunId, StageModelUsage}; ++use fabro_types::{RunId, StageModelUsage, StageTiming}; + pub(crate) use structured_output::extract_status_fields; + use tokio_util::sync::CancellationToken; + +@@ -23,9 +23,12 @@ use crate::outcome::{BilledModelUsage, Outcome, OutcomeExt}; + pub enum CodergenResult { + Text { + text: String, +- usage: Option, ++ usage: Option>, + files_touched: Vec, + last_file_touched: Option, ++ /// Active timing observed by the backend. The wall field is ignored by ++ /// the executor on this hop; executor wall time remains authoritative. ++ timing: StageTiming, + }, + Full(Box), + } +@@ -276,7 +279,7 @@ impl Handler for AgentHandler { + node_id: node.id.clone(), + }) as Arc + }); +- let (response_text, stage_usage, backend_files_touched, last_file_touched) = ++ let (response_text, stage_usage, backend_files_touched, last_file_touched, timing) = + if let Some(backend) = &self.backend { + let result = backend + .run(CodergenRunRequest { +@@ -298,7 +301,14 @@ impl Handler for AgentHandler { + usage, + files_touched, + last_file_touched, +- }) => (text, usage, files_touched, last_file_touched), ++ timing, ++ }) => ( ++ text, ++ usage.map(|usage| *usage), ++ files_touched, ++ last_file_touched, ++ timing, ++ ), + Err(Error::Cancelled) => return Err(Error::Cancelled), + Err(e) if e.is_retryable() => { + return Err(e); +@@ -313,6 +323,7 @@ impl Handler for AgentHandler { + None, + Vec::new(), + None, ++ StageTiming::default(), + ) + }; + +@@ -353,7 +364,7 @@ impl Handler for AgentHandler { + ); + + if let Some(schema) = structured_output::parse_node_output_schema(node)? { +- match validate_agent_output_sources( ++ if let Ok(validated) = validate_agent_output_sources( + &schema, + &response_text, + &services.run.sandbox, +@@ -361,19 +372,14 @@ impl Handler for AgentHandler { + ) + .await + { +- Ok(validated) => { +- structured_output::apply_validated_output( +- node, +- &schema, +- &validated, +- &mut outcome, +- ); +- } +- Err(_) => { +- return Ok(structured_output::exhausted_failure_outcome( +- node.output_retries(), +- )); +- } ++ structured_output::apply_validated_output(node, &schema, &validated, &mut outcome); ++ } else { ++ let mut failed = ++ structured_output::exhausted_failure_outcome(node.output_retries()); ++ failed.timing = Some(timing); ++ failed.usage = stage_usage; ++ failed.files_touched = backend_files_touched; ++ return Ok(failed); + } + } else { + // 7b. Parse routing directives from response text, falling back to +@@ -399,6 +405,7 @@ impl Handler for AgentHandler { + } + outcome.usage = stage_usage; + outcome.files_touched = backend_files_touched; ++ outcome.timing = Some(timing); + + Ok(outcome) + } +@@ -656,6 +663,7 @@ mod tests { + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: StageTiming::default(), + }) + } + } +@@ -691,6 +699,37 @@ mod tests { + assert!(outcome.failure.is_none()); + } + ++ #[tokio::test] ++ async fn codergen_handler_copies_backend_timing_to_outcome() { ++ struct TimingBackend; ++ ++ #[async_trait] ++ impl CodergenBackend for TimingBackend { ++ async fn run(&self, _request: CodergenRunRequest<'_>) -> Result { ++ Ok(CodergenResult::Text { ++ text: "done".to_string(), ++ usage: None, ++ files_touched: Vec::new(), ++ last_file_touched: None, ++ timing: StageTiming::new(0, 200, 300), ++ }) ++ } ++ } ++ ++ let handler = AgentHandler::new(Some(Box::new(TimingBackend))); ++ let node = Node::new("step"); ++ let context = test_context(); ++ let graph = Graph::new("test"); ++ let tmp = TempDir::new().unwrap(); ++ ++ let outcome = handler ++ .execute(&node, &context, &graph, tmp.path(), &make_services()) ++ .await ++ .unwrap(); ++ ++ assert_eq!(outcome.timing, Some(StageTiming::new(0, 200, 300))); ++ } ++ + #[tokio::test] + async fn codergen_handler_extracts_status_from_last_file_touched() { + struct LastFileBackend; +@@ -703,6 +742,7 @@ mod tests { + usage: None, + files_touched: vec!["results.md".to_string()], + last_file_touched: Some("results.md".to_string()), ++ timing: StageTiming::default(), + }) + } + } +@@ -793,6 +833,7 @@ mod tests { + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: StageTiming::default(), + }) + } + } +@@ -851,6 +892,7 @@ mod tests { + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: StageTiming::default(), + }) + } + } +@@ -907,6 +949,7 @@ mod tests { + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: StageTiming::default(), + }) + } + } +@@ -961,6 +1004,7 @@ mod tests { + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: StageTiming::default(), + }) + } + } +@@ -1005,6 +1049,7 @@ mod tests { + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: StageTiming::default(), + }) + } + } +@@ -1212,6 +1257,7 @@ Some text in between. + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: StageTiming::default(), + }) + } + } +@@ -1272,6 +1318,7 @@ Some text in between. + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: StageTiming::default(), + }) + } + } +diff --git a/lib/crates/fabro-workflow/src/handler/command.rs b/lib/crates/fabro-workflow/src/handler/command.rs +index 63922632a..736731a26 100644 +--- a/lib/crates/fabro-workflow/src/handler/command.rs ++++ b/lib/crates/fabro-workflow/src/handler/command.rs +@@ -3,7 +3,7 @@ use std::path::Path; + use async_trait::async_trait; + use fabro_agent::CommandOutputCallback; + use fabro_graphviz::graph::{Graph, Node}; +-use fabro_types::CommandTermination; ++use fabro_types::{CommandTermination, StageTiming}; + + use super::{EngineServices, Handler, NodeTimeoutPolicy}; + use crate::command_log::CommandLogRecorder; +@@ -178,6 +178,7 @@ impl Handler for CommandHandler { + serde_json::json!(finalized.output_ref), + ); + outcome.notes = Some(format!("Script completed: {script}")); ++ outcome.timing = Some(StageTiming::new(0, 0, result.duration_ms)); + Ok(outcome) + } else { + let mut reason = format!( +@@ -190,6 +191,7 @@ impl Handler for CommandHandler { + keys::COMMAND_OUTPUT.to_string(), + serde_json::json!(finalized.output_ref), + ); ++ outcome.timing = Some(StageTiming::new(0, 0, result.duration_ms)); + Ok(outcome) + } + } +@@ -468,6 +470,33 @@ mod tests { + assert!(!outcome.context_updates.contains_key("command.stderr")); + } + ++ #[tokio::test] ++ async fn script_handler_reports_command_duration_as_tool_timing() { ++ let handler = CommandHandler; ++ let mut node = Node::new("script_node"); ++ node.attrs.insert( ++ "script".to_string(), ++ AttrValue::String("sleep 0.05; echo hello".to_string()), ++ ); ++ let context = Context::new(); ++ let graph = Graph::new("test"); ++ let run_dir = tempfile::tempdir().unwrap(); ++ ++ let services = make_services(); ++ let outcome = handler ++ .execute(&node, &context, &graph, run_dir.path(), &services) ++ .await ++ .unwrap(); ++ ++ let timing = outcome.timing.expect("command outcome should carry timing"); ++ assert_eq!(timing.inference_time_ms, 0); ++ assert!( ++ timing.tool_time_ms >= 25, ++ "expected command duration to be reported as tool time, got {timing:?}" ++ ); ++ assert_eq!(timing.active_time_ms, timing.tool_time_ms); ++ } ++ + #[tokio::test] + async fn script_handler_failing_command() { + let handler = CommandHandler; +diff --git a/lib/crates/fabro-workflow/src/handler/fan_in.rs b/lib/crates/fabro-workflow/src/handler/fan_in.rs +index 8ba1e251f..aa03d8f74 100644 +--- a/lib/crates/fabro-workflow/src/handler/fan_in.rs ++++ b/lib/crates/fabro-workflow/src/handler/fan_in.rs +@@ -4,7 +4,7 @@ use std::sync::Arc; + use async_trait::async_trait; + use fabro_agent::Sandbox; + use fabro_graphviz::graph::{Graph, Node}; +-use fabro_types::StageModelUsage; ++use fabro_types::{StageModelUsage, StageTiming}; + use tokio_util::sync::CancellationToken; + + use super::agent::{CodergenBackend, CodergenResult, CodergenRunRequest}; +@@ -112,7 +112,9 @@ impl Handler for FanInHandler { + }; + + if all_failed { +- return Ok(Outcome::fail_deterministic("all candidates failed")); ++ let mut outcome = Outcome::fail_deterministic("all candidates failed"); ++ outcome.timing = Some(best.timing); ++ return Ok(outcome); + } + + // --- Fast-forward to winner's HEAD when git isolation is active --- +@@ -144,6 +146,7 @@ impl Handler for FanInHandler { + ); + } + outcome.notes = Some(format!("Selected best candidate: {}", best.id)); ++ outcome.timing = Some(best.timing); + + Ok(outcome) + } +@@ -153,6 +156,7 @@ struct Candidate { + id: String, + status: String, + score: f64, ++ timing: StageTiming, + } + + fn status_rank(status: &str) -> u32 { +@@ -172,6 +176,7 @@ fn heuristic_select(results: &serde_json::Value) -> Candidate { + id: "unknown".to_string(), + status: "failed".to_string(), + score: 0.0, ++ timing: StageTiming::default(), + }; + } + +@@ -192,6 +197,7 @@ fn heuristic_select(results: &serde_json::Value) -> Candidate { + .get("score") + .and_then(serde_json::Value::as_f64) + .unwrap_or(0.0), ++ timing: StageTiming::default(), + }) + .collect(); + +@@ -215,6 +221,7 @@ fn heuristic_select(results: &serde_json::Value) -> Candidate { + id: "unknown".to_string(), + status: "failed".to_string(), + score: 0.0, ++ timing: StageTiming::default(), + }) + } + +@@ -277,6 +284,7 @@ async fn llm_evaluate( + .await + { + Ok(CodergenResult::Full(outcome)) => { ++ let timing = outcome.timing.unwrap_or_default(); + // If the backend returned a full Outcome, extract best_id from context_updates + let best_id = outcome + .context_updates +@@ -298,12 +306,13 @@ async fn llm_evaluate( + &stage_scope, + ); + Ok(Candidate { +- id: best_id, ++ id: best_id, + status: outcome.status.to_string(), +- score: 0.0, ++ score: 0.0, ++ timing, + }) + } +- Ok(CodergenResult::Text { text, .. }) => { ++ Ok(CodergenResult::Text { text, timing, .. }) => { + emitter.emit_scoped( + &Event::PromptCompleted { + node_id: node_id.to_string(), +@@ -337,13 +346,16 @@ async fn llm_evaluate( + id: id.to_string(), + status, + score, ++ timing, + }); + } + } + } + + // No match found; fall back to heuristic +- Ok(heuristic_select(results)) ++ let mut fallback = heuristic_select(results); ++ fallback.timing = timing; ++ Ok(fallback) + } + Err(_) => { + // LLM call failed; fall back to heuristic +@@ -486,6 +498,7 @@ mod tests { + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: StageTiming::default(), + }) + } + } +@@ -519,6 +532,52 @@ mod tests { + ); + } + ++ #[tokio::test] ++ async fn fan_in_with_backend_copies_llm_timing_to_outcome() { ++ use tempfile::TempDir; ++ ++ use crate::handler::agent::{CodergenBackend, CodergenRunRequest}; ++ ++ struct TimingBackend; ++ ++ #[async_trait] ++ impl CodergenBackend for TimingBackend { ++ async fn run(&self, _request: CodergenRunRequest<'_>) -> Result { ++ Ok(CodergenResult::Text { ++ text: "branch_b".to_string(), ++ usage: None, ++ files_touched: Vec::new(), ++ last_file_touched: None, ++ timing: StageTiming::new(0, 200, 300), ++ }) ++ } ++ } ++ ++ let handler = FanInHandler::new(Some(Box::new(TimingBackend))); ++ let mut node = Node::new("fan_in"); ++ node.attrs.insert( ++ "prompt".to_string(), ++ fabro_graphviz::graph::AttrValue::String("Pick the best branch".to_string()), ++ ); ++ let context = Context::new(); ++ context.set( ++ keys::PARALLEL_RESULTS, ++ serde_json::json!([ ++ {"id": "branch_a", "status": "succeeded"}, ++ {"id": "branch_b", "status": "succeeded"}, ++ ]), ++ ); ++ let graph = Graph::new("test"); ++ let tmp = TempDir::new().unwrap(); ++ ++ let outcome = handler ++ .execute(&node, &context, &graph, tmp.path(), &make_services()) ++ .await ++ .unwrap(); ++ ++ assert_eq!(outcome.timing, Some(StageTiming::new(0, 200, 300))); ++ } ++ + #[tokio::test] + async fn fan_in_all_fail_returns_fail() { + let handler = FanInHandler::new(None); +diff --git a/lib/crates/fabro-workflow/src/handler/llm/acp.rs b/lib/crates/fabro-workflow/src/handler/llm/acp.rs +index 07bfed7c1..4b867b7b8 100644 +--- a/lib/crates/fabro-workflow/src/handler/llm/acp.rs ++++ b/lib/crates/fabro-workflow/src/handler/llm/acp.rs +@@ -10,7 +10,9 @@ use fabro_acp::{ + }; + use fabro_agent::{AgentEvent, Sandbox, StaticEnvProvider, SteeringItem, ToolEnvProvider}; + use fabro_graphviz::graph::Node; +-use fabro_types::{AgentBackend, Principal, SessionCapability, StageId, SteeringMessage}; ++use fabro_types::{ ++ AgentBackend, Principal, SessionCapability, StageId, StageTiming, SteeringMessage, ++}; + use fabro_util::time::elapsed_ms; + use tokio_util::sync::CancellationToken; + +@@ -231,6 +233,7 @@ impl AgentAcpBackend { + usage: None, + files_touched, + last_file_touched, ++ timing: StageTiming::new(0, result.duration_ms, 0), + }) + } + +diff --git a/lib/crates/fabro-workflow/src/handler/llm/api.rs b/lib/crates/fabro-workflow/src/handler/llm/api.rs +index d13103c5d..df5af98c2 100644 +--- a/lib/crates/fabro-workflow/src/handler/llm/api.rs ++++ b/lib/crates/fabro-workflow/src/handler/llm/api.rs +@@ -1,5 +1,6 @@ + use std::collections::{HashMap, HashSet}; + use std::sync::{Arc, Mutex}; ++use std::time::{Duration, Instant}; + + use async_trait::async_trait; + use fabro_agent::subagent::{SessionFactory, SubAgentManager}; +@@ -21,7 +22,7 @@ use fabro_mcp::config::McpServerSettings; + use fabro_model::catalog::LlmCatalogSettings; + use fabro_model::{AgentProfileKind, Catalog, FallbackTarget, ModelRef, ProviderId}; + use fabro_types::settings::run::RunModelControls; +-use fabro_types::{PermissionLevel, RunId, SessionCapability, StageId}; ++use fabro_types::{PermissionLevel, RunId, SessionCapability, StageId, StageTiming}; + use serde::de::DeserializeOwned; + use tokio::sync::Mutex as TokioMutex; + use tokio::task::JoinHandle; +@@ -119,6 +120,12 @@ pub struct EffectiveRequestControls { + pub(crate) speed: Option, + } + ++fn active_stage_timing(inference: Duration, tool: Duration) -> StageTiming { ++ // The executor ignores this wall field and supplies its own stopwatch-based ++ // value when converting Outcome.timing into the emitted stage timing. ++ StageTiming::new(0, crate::millis_u64(inference), crate::millis_u64(tool)) ++} ++ + fn classify_agent_error(err: fabro_agent::Error, allow_failover: bool) -> AgentApiErrorDisposition { + match err { + fabro_agent::Error::Interrupted(fabro_agent::InterruptReason::Cancelled) => { +@@ -1046,6 +1053,7 @@ impl CodergenBackend for AgentApiBackend { + .map(structured_output::prompt_response_format); + let mut repair_attempts = 0_i64; + let mut total_usage = TokenCounts::default(); ++ let mut inference_duration = Duration::ZERO; + + loop { + let request = Request { +@@ -1065,7 +1073,8 @@ impl CodergenBackend for AgentApiBackend { + provider_options: None, + }; + +- let completion = self ++ let inference_start = Instant::now(); ++ let completion_result = self + .complete_one_shot_request( + &client, + node, +@@ -1075,7 +1084,9 @@ impl CodergenBackend for AgentApiBackend { + controls, + fallback_chain, + ) +- .await?; ++ .await; ++ inference_duration = inference_duration.saturating_add(inference_start.elapsed()); ++ let completion = completion_result?; + total_usage += completion.response.usage.clone(); + let response_text = completion.response.text(); + +@@ -1108,9 +1119,10 @@ impl CodergenBackend for AgentApiBackend { + + return Ok(CodergenResult::Text { + text: response_text, +- usage: Some(stage_usage), ++ usage: Some(Box::new(stage_usage)), + files_touched: Vec::new(), + last_file_touched: None, ++ timing: active_stage_timing(inference_duration, Duration::ZERO), + }); + } + } +@@ -1191,6 +1203,8 @@ impl CodergenBackend for AgentApiBackend { + + // Record turn count before processing so we only aggregate new usage. + let mut turns_before = session.history().turns().len(); ++ let mut inference_duration = Duration::ZERO; ++ let mut tool_duration = Duration::ZERO; + + // Activate with the steering hub after initialization so HTTP + // `POST /runs/{id}/steer` calls reach this session. The activation +@@ -1243,9 +1257,13 @@ impl CodergenBackend for AgentApiBackend { + if !is_reused { + emit_agent_tools_available(&session, &node.id, &stage_id, emitter); + } +- session ++ let process_result = session + .process_input_with_runtime(prompt, agent_tool_runtime.clone()) +- .await ++ .await; ++ let timing = session.last_input_timing(); ++ inference_duration = inference_duration.saturating_add(timing.inference); ++ tool_duration = tool_duration.saturating_add(timing.tool); ++ process_result + } + Err(err) => Err(err), + }; +@@ -1371,10 +1389,13 @@ impl CodergenBackend for AgentApiBackend { + } + } + emit_agent_tools_available(&session, &node.id, &stage_id, emitter); +- match session ++ let process_result = session + .process_input_with_runtime(prompt, agent_tool_runtime.clone()) +- .await +- { ++ .await; ++ let timing = session.last_input_timing(); ++ inference_duration = inference_duration.saturating_add(timing.inference); ++ tool_duration = tool_duration.saturating_add(timing.tool); ++ match process_result { + Ok(()) => { + succeeded = true; + break; +@@ -1435,7 +1456,11 @@ impl CodergenBackend for AgentApiBackend { + )); + } + let repair_message = error.repair_message(schema); +- match session.process_input(&repair_message).await { ++ let repair_result = session.process_input(&repair_message).await; ++ let timing = session.last_input_timing(); ++ inference_duration = inference_duration.saturating_add(timing.inference); ++ tool_duration = tool_duration.saturating_add(timing.tool); ++ match repair_result { + Ok(()) => { + repair_attempts += 1; + response = last_assistant_response(&session); +@@ -1507,9 +1532,10 @@ impl CodergenBackend for AgentApiBackend { + + Ok(CodergenResult::Text { + text: response, +- usage: Some(stage_usage), ++ usage: Some(Box::new(stage_usage)), + files_touched, + last_file_touched, ++ timing: active_stage_timing(inference_duration, tool_duration), + }) + } + } +diff --git a/lib/crates/fabro-workflow/src/handler/llm/router.rs b/lib/crates/fabro-workflow/src/handler/llm/router.rs +index 821bd8136..24dc97e0e 100644 +--- a/lib/crates/fabro-workflow/src/handler/llm/router.rs ++++ b/lib/crates/fabro-workflow/src/handler/llm/router.rs +@@ -161,6 +161,7 @@ mod tests { + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: fabro_types::StageTiming::default(), + }) + } + +@@ -170,6 +171,7 @@ mod tests { + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: fabro_types::StageTiming::default(), + }) + } + +diff --git a/lib/crates/fabro-workflow/src/handler/prompt.rs b/lib/crates/fabro-workflow/src/handler/prompt.rs +index 27b9fa524..94674421f 100644 +--- a/lib/crates/fabro-workflow/src/handler/prompt.rs ++++ b/lib/crates/fabro-workflow/src/handler/prompt.rs +@@ -3,7 +3,7 @@ use std::sync::Arc; + + use async_trait::async_trait; + use fabro_graphviz::graph::{Graph, Node}; +-use fabro_types::StageModelUsage; ++use fabro_types::{StageModelUsage, StageTiming}; + + use super::agent::{ + CodergenBackend, CodergenResult, OneShotRequest, emit_stage_prompt, extract_status_fields, +@@ -117,7 +117,7 @@ impl Handler for PromptHandler { + )?; + + // 3. Call LLM backend (one_shot) +- let (response_text, stage_usage, backend_files_touched) = ++ let (response_text, stage_usage, backend_files_touched, timing) = + if let Some(backend) = &self.backend { + let result = backend + .one_shot(OneShotRequest { +@@ -136,8 +136,9 @@ impl Handler for PromptHandler { + text, + usage, + files_touched, ++ timing, + .. +- }) => (text, usage, files_touched), ++ }) => (text, usage.map(|usage| *usage), files_touched, timing), + Err(Error::Cancelled) => return Err(Error::Cancelled), + Err(e) if e.is_retryable() => { + return Err(e); +@@ -151,6 +152,7 @@ impl Handler for PromptHandler { + format!("[Simulated] Response for stage: {}", node.id), + None, + Vec::new(), ++ StageTiming::default(), + ) + }; + +@@ -192,26 +194,24 @@ impl Handler for PromptHandler { + ); + + if let Some(schema) = structured_output::parse_node_output_schema(node)? { +- match structured_output::validate_response_text(&schema, &response_text) { +- Ok(validated) => { +- structured_output::apply_validated_output( +- node, +- &schema, +- &validated, +- &mut outcome, +- ); +- } +- Err(_) => { +- return Ok(structured_output::exhausted_failure_outcome( +- node.output_retries(), +- )); +- } ++ if let Ok(validated) = ++ structured_output::validate_response_text(&schema, &response_text) ++ { ++ structured_output::apply_validated_output(node, &schema, &validated, &mut outcome); ++ } else { ++ let mut failed = ++ structured_output::exhausted_failure_outcome(node.output_retries()); ++ failed.timing = Some(timing); ++ failed.usage = stage_usage; ++ failed.files_touched = backend_files_touched; ++ return Ok(failed); + } + } else { + extract_status_fields(&response_text, &mut outcome); + } + outcome.usage = stage_usage; + outcome.files_touched = backend_files_touched; ++ outcome.timing = Some(timing); + + Ok(outcome) + } +@@ -349,6 +349,7 @@ mod tests { + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: StageTiming::default(), + }) + } + +@@ -387,6 +388,44 @@ mod tests { + ); + } + ++ #[tokio::test] ++ async fn prompt_handler_copies_backend_timing_to_outcome() { ++ struct TimingBackend; ++ ++ #[async_trait] ++ impl CodergenBackend for TimingBackend { ++ async fn run(&self, _request: CodergenRunRequest<'_>) -> Result { ++ panic!("run() should not be called for prompt handler"); ++ } ++ ++ async fn one_shot( ++ &self, ++ _request: OneShotRequest<'_>, ++ ) -> Result { ++ Ok(CodergenResult::Text { ++ text: "one-shot response".to_string(), ++ usage: None, ++ files_touched: Vec::new(), ++ last_file_touched: None, ++ timing: StageTiming::new(0, 200, 300), ++ }) ++ } ++ } ++ ++ let handler = PromptHandler::new(Some(Box::new(TimingBackend))); ++ let node = Node::new("classify"); ++ let context = Context::new(); ++ let graph = Graph::new("test"); ++ let tmp = TempDir::new().unwrap(); ++ ++ let outcome = handler ++ .execute(&node, &context, &graph, tmp.path(), &make_services()) ++ .await ++ .unwrap(); ++ ++ assert_eq!(outcome.timing, Some(StageTiming::new(0, 200, 300))); ++ } ++ + #[tokio::test] + async fn prompt_handler_custom_output_schema_updates_output_context_key() { + struct CustomOutputBackend; +@@ -406,6 +445,7 @@ mod tests { + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: StageTiming::default(), + }) + } + } +@@ -453,6 +493,7 @@ mod tests { + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: StageTiming::default(), + }) + } + } +@@ -502,6 +543,7 @@ mod tests { + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: StageTiming::default(), + }) + } + +@@ -561,6 +603,7 @@ mod tests { + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: StageTiming::default(), + }) + } + } +diff --git a/lib/crates/fabro-workflow/src/operations/start.rs b/lib/crates/fabro-workflow/src/operations/start.rs +index 66f1a5fc4..0adc853ac 100644 +--- a/lib/crates/fabro-workflow/src/operations/start.rs ++++ b/lib/crates/fabro-workflow/src/operations/start.rs +@@ -30,13 +30,13 @@ use tokio_util::sync::CancellationToken; + + use crate::artifact_upload::ArtifactSink; + use crate::context::Context; +-use crate::error::Error; ++use crate::error::{self, Error}; + use crate::event::{ + Emitter, Event, EventBody, RunEventLogger, RunEventSink, RunNoticeLevel, append_event_to_sink, + }; + use crate::handler::HandlerRegistry; + use crate::handler::llm::routing; +-use crate::outcome::Outcome; ++use crate::outcome::{Outcome, StageOutcome}; + use crate::pipeline::{ + self, DevcontainerSpec, FinalizeOptions, Finalized, InitOptions, LlmSpec, Persisted, + PullRequestOptions, SandboxEnvSpec, build_conclusion_from_store, classify_engine_result, +@@ -184,6 +184,7 @@ pub(super) async fn execute_persisted_run( + let error = Error::engine(err.to_string()); + let _ = persist_detached_failure( + run_id, ++ &run_store, + &event_sink, + run_dir, + "bootstrap", +@@ -197,6 +198,7 @@ pub(super) async fn execute_persisted_run( + let error = Error::engine(err.to_string()); + let _ = persist_detached_failure( + run_id, ++ &run_store, + &event_sink, + run_dir, + "bootstrap", +@@ -209,12 +211,14 @@ pub(super) async fn execute_persisted_run( + + let mut bootstrap_guard = + DetachedRunBootstrapGuard::arm(run_id, run_dir, event_sink.clone(), cancel_token.clone()); ++ bootstrap_guard.run_store = Some(run_store.clone()); + + let persisted = match Persisted::load_from_store(&services.run_store, run_dir).await { + Ok(persisted) => persisted, + Err(err) => { + let _ = persist_detached_failure( + run_id, ++ &run_store, + &event_sink, + run_dir, + "bootstrap", +@@ -232,6 +236,7 @@ pub(super) async fn execute_persisted_run( + Err(err) => { + let _ = persist_detached_failure( + run_id, ++ &run_store, + &event_sink, + run_dir, + "bootstrap", +@@ -245,8 +250,12 @@ pub(super) async fn execute_persisted_run( + }; + + bootstrap_guard.defuse(); +- let mut completion_guard = +- DetachedRunCompletionGuard::arm(run_id, event_sink.clone(), cancel_token); ++ let mut completion_guard = DetachedRunCompletionGuard::arm( ++ run_id, ++ run_store.clone(), ++ event_sink.clone(), ++ cancel_token, ++ ); + let run_start = Instant::now(); + let started = Box::pin(session.run(persisted, checkpoint)).await; + +@@ -281,7 +290,7 @@ async fn persist_terminal_engine_failure( + ) { + let engine_result: Result = Err(error.clone()); + let (final_status, failure_reason, run_status) = classify_engine_result(&engine_result); +- let _conclusion = build_conclusion_from_store( ++ let conclusion = build_conclusion_from_store( + run_store, + final_status, + failure_reason, +@@ -295,12 +304,12 @@ async fn persist_terminal_engine_failure( + }; + let failure_event = Event::workflow_run_failed_from_error( + error, +- fabro_types::RunTiming::wall_only(crate::millis_u64(duration)), ++ conclusion.timing, + reason, + None, + None, + None, +- None, ++ conclusion.billing.clone(), + ); + if let Err(err) = append_event_to_sink(event_sink, &run_id, &failure_event).await { + tracing::warn!(error = %err, "Failed to append terminal engine failure event"); +@@ -893,6 +902,7 @@ impl RunSession { + + struct DetachedRunBootstrapGuard { + run_id: RunId, ++ run_store: Option, + event_sink: RunEventSink, + cancel_token: CancellationToken, + active: bool, +@@ -907,6 +917,7 @@ impl DetachedRunBootstrapGuard { + ) -> Self { + Self { + run_id, ++ run_store: None, + event_sink, + cancel_token, + active: true, +@@ -928,17 +939,33 @@ impl Drop for DetachedRunBootstrapGuard { + FailureReason::SandboxInitFailed + }; + let run_id = self.run_id; ++ let run_store = self.run_store.clone(); + let event_sink = self.event_sink.clone(); + if let Ok(handle) = Handle::try_current() { + handle.spawn(async move { ++ let (timing, billing) = if let Some(run_store) = run_store { ++ let final_status = StageOutcome::Failed { ++ retry_requested: false, ++ }; ++ let failure = Some(error::run_failure_from_error( ++ &Error::engine(reason.to_string()), ++ reason, ++ )); ++ let conclusion = ++ build_conclusion_from_store(&run_store, final_status, failure, 0, None) ++ .await; ++ (conclusion.timing, conclusion.billing) ++ } else { ++ (fabro_types::RunTiming::default(), None) ++ }; + let failure_event = Event::workflow_run_failed_from_error( + &Error::engine(reason.to_string()), +- fabro_types::RunTiming::default(), ++ timing, + reason, + None, + None, + None, +- None, ++ billing, + ); + let _ = append_event_to_sink(&event_sink, &run_id, &failure_event).await; + }); +@@ -953,15 +980,22 @@ const POSTRUN_CANCELLED_MESSAGE: &str = "Run cancelled before post-run finalizat + struct DetachedRunCompletionGuard { + event_sink: RunEventSink, + run_id: RunId, ++ run_store: RunStoreHandle, + cancel_token: CancellationToken, + active: bool, + } + + impl DetachedRunCompletionGuard { +- fn arm(run_id: RunId, event_sink: RunEventSink, cancel_token: CancellationToken) -> Self { ++ fn arm( ++ run_id: RunId, ++ run_store: RunStoreHandle, ++ event_sink: RunEventSink, ++ cancel_token: CancellationToken, ++ ) -> Self { + Self { + event_sink, + run_id, ++ run_store, + cancel_token, + active: true, + } +@@ -996,16 +1030,26 @@ impl Drop for DetachedRunCompletionGuard { + }; + let event_sink = self.event_sink.clone(); + let run_id = self.run_id; ++ let run_store = self.run_store.clone(); + if let Ok(handle) = Handle::try_current() { + handle.spawn(async move { ++ let final_status = StageOutcome::Failed { ++ retry_requested: false, ++ }; ++ let failure = Some(error::run_failure_from_error( ++ &Error::engine(message.to_string()), ++ reason, ++ )); ++ let conclusion = ++ build_conclusion_from_store(&run_store, final_status, failure, 0, None).await; + let failure_event = Event::workflow_run_failed_from_error( + &Error::engine(message.to_string()), +- fabro_types::RunTiming::default(), ++ conclusion.timing, + reason, + None, + None, + None, +- None, ++ conclusion.billing, + ); + let _ = append_event_to_sink(&event_sink, &run_id, &failure_event).await; + let _ = append_event_to_sink(&event_sink, &run_id, &Event::RunNotice { +@@ -1022,6 +1066,7 @@ impl Drop for DetachedRunCompletionGuard { + + async fn persist_detached_failure( + run_id: RunId, ++ run_store: &RunStoreHandle, + event_sink: &RunEventSink, + _run_dir: &Path, + phase: &'static str, +@@ -1029,15 +1074,20 @@ async fn persist_detached_failure( + error: &Error, + ) -> Result<(), Error> { + let message = error.to_string(); ++ let final_status = StageOutcome::Failed { ++ retry_requested: false, ++ }; ++ let failure = Some(error::run_failure_from_error(error, reason)); ++ let conclusion = build_conclusion_from_store(run_store, final_status, failure, 0, None).await; + + let failure_event = Event::workflow_run_failed_from_error( + error, +- fabro_types::RunTiming::default(), ++ conclusion.timing, + reason, + None, + None, + None, +- None, ++ conclusion.billing, + ); + if let Err(err) = append_event_to_sink(event_sink, &run_id, &failure_event).await { + tracing::warn!(error = %err, "Failed to append detached failure event"); +@@ -1072,18 +1122,18 @@ mod tests { + use fabro_store::Database; + use fabro_types::settings::run::RunMode; + use fabro_types::settings::{InterpString, ModelRef}; +- use fabro_types::{ManifestPath, WorkflowSettings, fixtures}; ++ use fabro_types::{BilledModelUsage, ManifestPath, StageTiming, WorkflowSettings, fixtures}; + use object_store::memory::InMemory; + + use super::*; + use crate::context::Context; + use crate::event::{Emitter, EventBody}; +- use crate::handler::HandlerRegistry; + use crate::handler::exit::ExitHandler; + use crate::handler::manager_loop::SubWorkflowHandler; + use crate::handler::start::StartHandler; ++ use crate::handler::{EngineServices, Handler, HandlerRegistry}; + use crate::operations::resume; +- use crate::outcome::StageOutcome; ++ use crate::outcome::{Outcome, StageOutcome}; + use crate::records::CheckpointExt; + use crate::workflow_bundle::{BundledWorkflow, WorkflowBundle}; + +@@ -1094,6 +1144,48 @@ mod tests { + start -> exit + }"#; + ++ const TIMED_DOT: &str = r#"digraph Test { ++ graph [goal="Time active work"] ++ start [shape=Mdiamond] ++ work [type="timed"] ++ exit [shape=Msquare] ++ start -> work ++ work -> exit ++ }"#; ++ ++ struct TimedOutcomeHandler; ++ ++ fn timed_success_outcome() -> Outcome { ++ let mut outcome = Outcome::success(); ++ outcome.timing = Some(StageTiming::new(0, 100, 50)); ++ outcome ++ } ++ ++ #[async_trait::async_trait] ++ impl Handler for TimedOutcomeHandler { ++ async fn execute( ++ &self, ++ _node: &fabro_graphviz::graph::Node, ++ _context: &Context, ++ _graph: &fabro_graphviz::graph::Graph, ++ _run_dir: &Path, ++ _services: &EngineServices, ++ ) -> Result { ++ Ok(timed_success_outcome()) ++ } ++ ++ async fn simulate( ++ &self, ++ _node: &fabro_graphviz::graph::Node, ++ _context: &Context, ++ _graph: &fabro_graphviz::graph::Graph, ++ _run_dir: &Path, ++ _services: &EngineServices, ++ ) -> Result { ++ Ok(timed_success_outcome()) ++ } ++ } ++ + fn memory_store() -> Arc { + Arc::new(Database::new( + Arc::new(InMemory::new()), +@@ -1381,6 +1473,92 @@ reasoning = false + } + } + ++ fn test_usage(model_id: &str, input_tokens: i64, output_tokens: i64) -> BilledModelUsage { ++ serde_json::from_value(serde_json::json!({ ++ "input": { ++ "usage": { ++ "model": { ++ "provider": "openai", ++ "model_id": model_id ++ }, ++ "tokens": { ++ "input_tokens": input_tokens, ++ "output_tokens": output_tokens ++ } ++ }, ++ "facts": { "algorithm": "openai" } ++ }, ++ "total_usd_micros": input_tokens + output_tokens ++ })) ++ .unwrap() ++ } ++ ++ async fn append_completed_stage( ++ run_store: &fabro_store::RunDatabase, ++ node_id: &str, ++ timing: fabro_types::StageTiming, ++ billing: Option, ++ ) { ++ crate::event::append_event(run_store, &fixtures::RUN_1, &Event::StageCompleted { ++ node_id: node_id.to_string(), ++ name: node_id.to_string(), ++ index: 0, ++ timing, ++ status: StageOutcome::Succeeded.to_string(), ++ preferred_label: None, ++ suggested_next_ids: Vec::new(), ++ billing, ++ failure: None, ++ notes: None, ++ files_touched: Vec::new(), ++ context_updates: None, ++ jump_to_node: None, ++ context_values: None, ++ node_visits: None, ++ loop_failure_signatures: None, ++ restart_failure_signatures: None, ++ response: None, ++ attempt: 1, ++ max_attempts: 1, ++ }) ++ .await ++ .unwrap(); ++ } ++ ++ async fn mark_run_running(run_store: &fabro_store::RunDatabase) { ++ crate::event::append_event(run_store, &fixtures::RUN_1, &Event::RunStartRequested { ++ resume: false, ++ actor: None, ++ }) ++ .await ++ .unwrap(); ++ crate::event::append_event(run_store, &fixtures::RUN_1, &Event::RunRunnable { ++ source: RunRunnableSource::StartRequested, ++ actor: None, ++ }) ++ .await ++ .unwrap(); ++ crate::event::append_event(run_store, &fixtures::RUN_1, &Event::RunStarting) ++ .await ++ .unwrap(); ++ crate::event::append_event(run_store, &fixtures::RUN_1, &Event::RunRunning) ++ .await ++ .unwrap(); ++ } ++ ++ async fn wait_for_conclusion( ++ run_store: &fabro_store::RunDatabase, ++ ) -> crate::records::Conclusion { ++ for _ in 0..50 { ++ if let Some(conclusion) = run_store.state().await.unwrap().conclusion { ++ return conclusion; ++ } ++ tokio::task::yield_now().await; ++ tokio::time::sleep(Duration::from_millis(1)).await; ++ } ++ panic!("timed out waiting for run conclusion"); ++ } ++ + #[tokio::test] + async fn start_captures_checkpoint_git_sha_in_conclusion() { + let temp = tempfile::tempdir().unwrap(); +@@ -1435,6 +1613,188 @@ reasoning = false + assert_eq!(started.finalized.conclusion.status, StageOutcome::Succeeded); + } + ++ #[tokio::test] ++ async fn start_events_roll_up_outcome_active_timing() { ++ let temp = tempfile::tempdir().unwrap(); ++ let (storage_root, run_dir) = storage_root_and_run_dir(&temp); ++ let emitter = Arc::new(Emitter::new(fixtures::RUN_1)); ++ let stage_timing = Arc::new(Mutex::new(None)); ++ let run_timing = Arc::new(Mutex::new(None)); ++ { ++ let stage_timing = Arc::clone(&stage_timing); ++ let run_timing = Arc::clone(&run_timing); ++ emitter.on_event(move |event| match &event.body { ++ EventBody::StageCompleted(props) if event.node_id.as_deref() == Some("work") => { ++ *stage_timing.lock().unwrap() = Some(props.timing); ++ } ++ EventBody::RunCompleted(props) => { ++ *run_timing.lock().unwrap() = Some(props.timing); ++ } ++ _ => {} ++ }); ++ } ++ ++ let mut registry = test_registry(); ++ registry.register("timed", Box::new(TimedOutcomeHandler)); ++ let (_persisted, store) = persisted_workflow(TIMED_DOT, &storage_root).await; ++ ++ let started = start( ++ &run_dir, ++ test_start_services(&store, &run_dir, emitter, Arc::new(registry)).await, ++ ) ++ .await ++ .unwrap(); ++ ++ let stage_timing = stage_timing ++ .lock() ++ .unwrap() ++ .expect("work stage should emit stage.completed timing"); ++ assert_eq!(stage_timing.inference_time_ms, 100); ++ assert_eq!(stage_timing.tool_time_ms, 50); ++ assert_eq!(stage_timing.active_time_ms, 150); ++ ++ let run_timing = run_timing ++ .lock() ++ .unwrap() ++ .expect("successful run should emit run.completed timing"); ++ assert_eq!(run_timing.inference_time_ms, 100); ++ assert_eq!(run_timing.tool_time_ms, 50); ++ assert_eq!(run_timing.active_time_ms, 150); ++ assert_eq!(started.finalized.conclusion.timing.inference_time_ms, 100); ++ assert_eq!(started.finalized.conclusion.timing.tool_time_ms, 50); ++ assert_eq!(started.finalized.conclusion.timing.active_time_ms, 150); ++ } ++ ++ #[tokio::test] ++ async fn persist_terminal_engine_failure_uses_conclusion_timing_and_billing() { ++ let temp = tempfile::tempdir().unwrap(); ++ let (storage_root, run_dir) = storage_root_and_run_dir(&temp); ++ let (_persisted, store) = persisted_workflow(MINIMAL_DOT, &storage_root).await; ++ let run_store = store.open_run(&fixtures::RUN_1).await.unwrap(); ++ mark_run_running(&run_store).await; ++ append_completed_stage( ++ &run_store, ++ "implement", ++ fabro_types::StageTiming::new(1_000, 200, 300), ++ Some(test_usage("gpt-5.4", 100, 50)), ++ ) ++ .await; ++ append_completed_stage( ++ &run_store, ++ "review", ++ fabro_types::StageTiming::new(500, 25, 75), ++ None, ++ ) ++ .await; ++ let run_store_handle: RunStoreHandle = run_store.clone().into(); ++ let event_sink = RunEventSink::store(run_store.clone()); ++ ++ persist_terminal_engine_failure( ++ fixtures::RUN_1, ++ &run_store_handle, ++ &event_sink, ++ &run_dir, ++ &Error::engine("visit limit exceeded"), ++ Duration::from_millis(9_999), ++ ) ++ .await; ++ ++ let projection = run_store.state().await.unwrap(); ++ let conclusion = projection ++ .conclusion ++ .expect("run.failed should populate conclusion"); ++ assert_eq!(conclusion.timing.wall_time_ms, 9_999); ++ assert_eq!(conclusion.timing.inference_time_ms, 225); ++ assert_eq!(conclusion.timing.tool_time_ms, 375); ++ assert_eq!(conclusion.timing.active_time_ms, 600); ++ assert_eq!( ++ conclusion ++ .billing ++ .as_ref() ++ .map(|billing| billing.total_tokens), ++ Some(150), ++ ); ++ } ++ ++ #[tokio::test] ++ async fn bootstrap_guard_failure_uses_conclusion_timing_and_billing_when_store_exists() { ++ let temp = tempfile::tempdir().unwrap(); ++ let (storage_root, run_dir) = storage_root_and_run_dir(&temp); ++ let (_persisted, store) = persisted_workflow(MINIMAL_DOT, &storage_root).await; ++ let run_store = store.open_run(&fixtures::RUN_1).await.unwrap(); ++ mark_run_running(&run_store).await; ++ append_completed_stage( ++ &run_store, ++ "implement", ++ fabro_types::StageTiming::new(1_000, 120, 80), ++ Some(test_usage("gpt-5.4", 40, 10)), ++ ) ++ .await; ++ let run_store_handle: RunStoreHandle = run_store.clone().into(); ++ let event_sink = RunEventSink::store(run_store.clone()); ++ ++ { ++ let mut guard = DetachedRunBootstrapGuard::arm( ++ fixtures::RUN_1, ++ &run_dir, ++ event_sink, ++ CancellationToken::new(), ++ ); ++ guard.run_store = Some(run_store_handle); ++ } ++ ++ let conclusion = wait_for_conclusion(&run_store).await; ++ assert_eq!(conclusion.timing.inference_time_ms, 120); ++ assert_eq!(conclusion.timing.tool_time_ms, 80); ++ assert_eq!(conclusion.timing.active_time_ms, 200); ++ assert_eq!( ++ conclusion ++ .billing ++ .as_ref() ++ .map(|billing| billing.total_tokens), ++ Some(50), ++ ); ++ } ++ ++ #[tokio::test] ++ async fn completion_guard_failure_uses_conclusion_timing_and_billing() { ++ let temp = tempfile::tempdir().unwrap(); ++ let (storage_root, _run_dir) = storage_root_and_run_dir(&temp); ++ let (_persisted, store) = persisted_workflow(MINIMAL_DOT, &storage_root).await; ++ let run_store = store.open_run(&fixtures::RUN_1).await.unwrap(); ++ mark_run_running(&run_store).await; ++ append_completed_stage( ++ &run_store, ++ "implement", ++ fabro_types::StageTiming::new(1_000, 70, 30), ++ Some(test_usage("gpt-5.4", 20, 5)), ++ ) ++ .await; ++ let run_store_handle: RunStoreHandle = run_store.clone().into(); ++ let event_sink = RunEventSink::store(run_store.clone()); ++ ++ { ++ let _guard = DetachedRunCompletionGuard::arm( ++ fixtures::RUN_1, ++ run_store_handle, ++ event_sink, ++ CancellationToken::new(), ++ ); ++ } ++ ++ let conclusion = wait_for_conclusion(&run_store).await; ++ assert_eq!(conclusion.timing.inference_time_ms, 70); ++ assert_eq!(conclusion.timing.tool_time_ms, 30); ++ assert_eq!(conclusion.timing.active_time_ms, 100); ++ assert_eq!( ++ conclusion ++ .billing ++ .as_ref() ++ .map(|billing| billing.total_tokens), ++ Some(25), ++ ); ++ } ++ + #[tokio::test] + async fn start_loads_persisted_from_run_dir() { + let temp = tempfile::tempdir().unwrap(); +diff --git a/lib/crates/fabro-workflow/tests/it/integration.rs b/lib/crates/fabro-workflow/tests/it/integration.rs +index fdfa426d7..27409d025 100644 +--- a/lib/crates/fabro-workflow/tests/it/integration.rs ++++ b/lib/crates/fabro-workflow/tests/it/integration.rs +@@ -1783,6 +1783,7 @@ impl CodergenBackend for MockCodergenBackend { + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: fabro_types::StageTiming::default(), + }) + } + } +@@ -6496,6 +6497,7 @@ mod real_llm { + usage: None, + files_touched: Vec::new(), + last_file_touched: None, ++ timing: fabro_types::StageTiming::default(), + }) + } + } diff --git a/stages/005-implement@1/status.json b/stages/005-implement@1/status.json new file mode 100644 index 000000000..b9226e6cc --- /dev/null +++ b/stages/005-implement@1/status.json @@ -0,0 +1,6 @@ +{ + "outcome": "succeeded", + "notes": "Stage completed: implement", + "failure_reason": null, + "timestamp": "2026-05-25T22:25:11.924633Z" +} \ No newline at end of file diff --git a/stages/006-simplify_opus@1/prompt.md b/stages/006-simplify_opus@1/prompt.md new file mode 100644 index 000000000..d18bf668d --- /dev/null +++ b/stages/006-simplify_opus@1/prompt.md @@ -0,0 +1,186 @@ +Goal: # Plan: Fix stage timing (inference + tool) reporting + +## Context + +The web UI's Duration popover shows `Active (inference + tools): 0ms` for every run, including agent-heavy runs that obviously did substantial LLM and tool work. Verified on `01KSE2PAVXD56N4TWNK4T5H5VA`: 10 stage.completed events and 1 run.failed event all carry `inference_time_ms: 0, tool_time_ms: 0`, even though stages like `implement@1` (94 min wall) and `simplify_opus@1` (29 min wall) were doing nothing but inference and tool calls. + +Two independent bugs: + +1. **No production handler ever populates `Outcome.timing`.** The plumbing from `Outcome.timing` → `NodeResult` (`lib/crates/fabro-core/src/executor.rs:30-37`) → `StageTiming` → `stage.completed` props → projection → billing rollup → run.completed/failed → UI is fully wired and shipped as of #343 (2026-05-21), but `AgentHandler::execute`, `PromptHandler::execute`, `CommandHandler::execute`, and `FanInHandler` all build `Outcome::success()` and never touch `.timing`. The executor falls back to zero, and every downstream consumer faithfully aggregates zero. + +2. **`persist_terminal_engine_failure` and its sibling Drop-guard failure paths discard timing/billing entirely.** When the engine returns `Err` (e.g. `VisitLimitExceeded`, which is what killed the user's run), `lib/crates/fabro-workflow/src/operations/start.rs:284-308` builds a `Conclusion` via `build_conclusion_from_store`, then throws it away (`let _conclusion = ...`) and emits `WorkflowRunFailed` with `RunTiming::wall_only(...)` and `None` for billing/diff. The three Drop-guard paths (`start.rs:934`, `1001`, `1033`) do similar with `RunTiming::default()` and never even build a conclusion. + +Goal: stage and run events carry real per-stage `inference_time_ms` + `tool_time_ms`; engine-failure terminal events preserve the conclusion's rolled-up timing and billing. + +## Approach + +### Part A — Capture inference + tool time in handlers (Bug 1) + +**A1. `fabro-agent` — accumulate per-input timing in `Session`** + +`lib/crates/fabro-agent/src/session.rs` + +Add two `Duration` accumulators to `Session` (initialised to `Duration::ZERO`): +- `last_input_inference_duration` +- `last_input_tool_duration` + +In `process_input_with_runtime` (line 1196), zero them at entry so each call's totals are independent. + +In `run_single_input` (line 1254): +- Wrap the inference span: capture `Instant::now()` immediately before opening the stream at line 1391, and add `.elapsed()` to `last_input_inference_duration` once `response = Some(resp)` (line 1487-1490) OR when the loop exits with an error/cancellation. The whole `'streamattempts` loop counts as inference work — retries included. +- Wrap the tool span around `execute_tool_calls` at line 1705-1719: `Instant::now()` before, accumulate `.elapsed()` after `.await`. + +Expose a getter: +```rust +pub fn last_input_timing(&self) -> SessionInputTiming { ... } +``` +where `SessionInputTiming { pub inference: Duration, pub tool: Duration }` is a new tiny struct in `fabro-agent`. + +**A2. `fabro-workflow` — thread timing through the backend boundary** + +`lib/crates/fabro-workflow/src/handler/agent.rs` + +Extend `CodergenResult::Text` with a `timing: fabro_types::StageTiming` field (wall is irrelevant — see note below). Update the few `CodergenResult::Text { ... }` constructions found by the explore agent to populate it; existing match-bindings only read `text`/`usage`/`files_touched` so they keep compiling with `..` patterns. `CodergenResult::Full(outcome)` keeps current behaviour — the outcome itself already carries any timing. + +Note on wall: `lib/crates/fabro-core/src/executor.rs:30-37` reads ONLY `inference_time_ms` and `tool_time_ms` out of `outcome.timing`. The wall comes from the executor's own stopwatch. So we construct `StageTiming::new(0, inference_ms, tool_ms)` and document that the wall field is ignored in this hop. + +`lib/crates/fabro-workflow/src/handler/llm/api.rs` + +- `AgentApiBackend::run` (line 1103): after `session.process_input_with_runtime(...)` returns, read `session.last_input_timing()` and set the new `timing` on `CodergenResult::Text` at line 1094. +- `AgentApiBackend::one_shot` (line 994): wrap the `complete_one_shot_request` call at line 1053 with `Instant::now()` / `.elapsed()`. Accumulate across repair iterations of the surrounding loop. All of it counts as inference; no tool work happens in `one_shot`. Set `timing` on `CodergenResult::Text` at line 1094. + +`lib/crates/fabro-workflow/src/handler/llm/acp.rs` + +`AgentAcpBackend::run` (line ~140): already exposes `result.duration_ms`. Set `timing: StageTiming::new(0, duration_ms, 0)` on the returned `CodergenResult::Text` (per user decision: attribute all ACP duration to inference; ACP is opaque about the split). + +**A3. Consume timing in stage handlers and set `outcome.timing`** + +- `lib/crates/fabro-workflow/src/handler/agent.rs:341` — after building `outcome`, before the final `Ok(outcome)`, set `outcome.timing = Some(timing_from_codergen_result)`. +- `lib/crates/fabro-workflow/src/handler/prompt.rs:180` — same pattern. +- `lib/crates/fabro-workflow/src/handler/fan_in.rs:266` — backend returns timing; pass it onto the outcome built from the fan-in response. +- `lib/crates/fabro-workflow/src/handler/command.rs:175` — `outcome.timing = Some(StageTiming::new(0, 0, result.duration_ms))`. All command wall-time is tool time. `result.duration_ms` is already at line 154 in scope. + +Other handlers (`human`, `wait`, `conditional`, `parallel`, `start`, `exit`, `structured_output`, `manager_loop`) do no inference or tool work. Leave `outcome.timing` as `None`; the executor will naturally produce `inference: 0, tool: 0` for those stages, which is correct. + +### Part B — Preserve conclusion timing on engine failure (Bug 2) + +`lib/crates/fabro-workflow/src/operations/start.rs` + +**B1. Main path** (`persist_terminal_engine_failure`, line 274-308): +- Rename `_conclusion` → `conclusion` and use it: + - Pass `conclusion.timing` (already a `RunTiming` with the proper inference/tool/wall rollup from `build_conclusion_from_parts`) instead of `RunTiming::wall_only(...)`. + - Pass `conclusion.billing.clone()` instead of `None` for the billing arg of `workflow_run_failed_from_error`. + - `final_git_commit_sha`, `final_patch`, `diff_summary` stay `None` — those require the finalize-side workspace diff computation that this path deliberately skips. + +**B2. Drop-guard paths** (per user decision: fix them too): + +- `DetachedRunBootstrapGuard` (line 882-948): add an `Option` field. The bootstrap function builds the guard before the store exists, then mutates `bootstrap_guard.run_store = Some(store.clone())` once the store is in scope. On Drop, if the store is `Some`, the spawned task calls `build_conclusion_from_store` and uses its timing/billing; otherwise falls back to `RunTiming::default()` (pre-store failure means no stages can possibly exist). + +- `DetachedRunCompletionGuard` (line 953-1021): armed after the store exists, so add a non-optional `run_store: RunStoreHandle`. Drop's spawned task builds the conclusion and uses it. + +- `persist_detached_failure` (line 1023): add a `run_store: &RunStoreHandle` parameter. Call `build_conclusion_from_store` and forward `timing` + `billing` to the failure event. Update the two callers (postrun-related) to pass the store they already have in scope. + +`RunStoreHandle` is already `Clone` (the surrounding code clones it routinely), so move-into-spawned-task is fine. + +### Critical existing utilities to reuse (do not duplicate) + +- `fabro_types::StageTiming::new(wall, inference, tool)` and `RunTiming::new(...)` — invariant-enforcing constructors at `lib/crates/fabro-types/src/timing.rs:38, 91`. +- `crate::millis_u64(duration)` helper for `Duration → u64` ms in `fabro-workflow` (used widely; see `lifecycle/event.rs:80-86`). +- `build_conclusion_from_store` at `lib/crates/fabro-workflow/src/pipeline/finalize.rs:71` already does the rollup we need on the engine-failure path. +- `billing_rollup_from_projection` (called inside `build_conclusion_from_parts`) sums per-stage timings into `RunTiming` — no need to reimplement. + +## Tests + +- **`fabro-agent` unit test**: feed `Session` a fake `LlmClient` whose `stream` sleeps a known duration and a fake tool that sleeps another known duration. Drive one `process_input_with_runtime` call. Assert `session.last_input_timing()` reports both non-zero and roughly matching the sleeps. Then call again and assert it's per-call (not cumulative). +- **`fabro-workflow` handler tests**: in `handler/agent.rs`'s test module, wire a `CodergenBackend` that returns `CodergenResult::Text { timing: StageTiming::new(0, 200, 300), .. }` and assert `AgentHandler::execute`'s returned `Outcome.timing` carries those values. Mirror for `prompt.rs` and `fan_in.rs`. Add a `command.rs` test that mocks a `sandbox.exec_command_streaming` returning `duration_ms = 500` and asserts `outcome.timing.tool_time_ms == 500`. +- **Executor integration**: add a test in `fabro-workflow` (or extend an existing one in `pipeline/finalize.rs` tests) that runs a tiny graph with a handler producing `Outcome.timing = Some(StageTiming::new(0, 100, 50))` and asserts the emitted `stage.completed` event carries those values, and that `run.completed` carries the summed rollup. +- **`persist_terminal_engine_failure` test**: seed a `RunStore` with a couple of `stage.completed` events whose timing is non-zero, drive the engine-failure path, and assert the emitted `WorkflowRunFailed` event has `timing.inference_time_ms` and `tool_time_ms` matching the per-stage sum and `billing` populated. +- **Drop guard tests**: trickier because of `Handle::try_current` + spawn. Add focused tests that arm a guard, drop it, and `tokio::task::yield_now().await` enough times to let the spawned task run, then assert the emitted failure event carries non-zero timing. +- Run `cargo nextest run -p fabro-agent -p fabro-workflow -p fabro-store -p fabro-core`. +- Run formatter and lints per CLAUDE.md: `cargo +nightly-2026-04-14 fmt --check --all` and `cargo +nightly-2026-04-14 clippy --workspace --all-targets -- -D warnings`. + +## End-to-end verification + +1. Build the server: `cargo build -p fabro-server`. +2. Start server: `fabro server start`. +3. Run a small agent-backed workflow (e.g. `fabro run repl` with a short prompt that fires at least one tool call). +4. `fabro events --json | jq -s '[.[] | select(.event=="stage.completed")] | .[].properties.timing'` — confirm `inference_time_ms > 0` and `tool_time_ms > 0` for the agent stage. +5. `fabro events --json | jq -s '[.[] | select(.event=="run.completed" or .event=="run.failed")] | .[].properties.timing'` — confirm `active_time_ms == inference_time_ms + tool_time_ms` and both are non-zero. +6. Open the run in the web UI (start the SPA dev build per CLAUDE.md or rebuild the embedded SPA with `cargo dev build`), hover the Duration chip, confirm **Active (inference + tools)** is non-zero. +7. For Bug 2: force an engine failure by setting a very low visit limit and rerunning the same workflow; confirm the `run.failed` event timing breakdown is non-zero and matches the per-stage sum. + +## Out of scope + +- Adding `wall_time_ms` correctness to `Outcome.timing` (executor ignores it; doc tweak only if necessary). +- Surfacing inference vs tool split for ACP backend beyond "all-inference" attribution. +- Backfilling timing for historical runs that have already emitted zero events — past events are immutable. +- Web UI changes beyond what the existing popover already renders. + + +## Completed stages +- **toolchain**: succeeded + - Script: `command -v cargo >/dev/null || { curl --proto '=https' --tlsv1.2 -sSf https://sh.rustup.rs | sh -s -- -y && sudo ln -sf $HOME/.cargo/bin/* /usr/local/bin/; }; cargo --version 2>&1` + - Output: + ``` + cargo 1.95.0 (f2d3ce0bd 2026-03-21) + ``` +- **preflight_compile**: succeeded + - Script: `cargo check -q --workspace 2>&1` + - Output: (empty) +- **preflight_lint**: succeeded + - Script: `cargo +nightly-2026-04-14 clippy -q --workspace --all-targets -- -D warnings 2>&1` + - Output: (empty) +- **implement**: succeeded + - Model: gpt-5.5, 2.8m tokens in / 19.0k out + + +# Simplify: Code Review and Cleanup + +Review changes vs. origin for reuse, quality, and efficiency. Fix any issues found. + +## Phase 1: Identify Changes + +Run git diff (or git diff HEAD if there are staged changes) to see what changed. If there are no git changes, review the most recently modified files that the user mentioned or that you edited earlier in this conversation. + +## Phase 2: Launch Three Review Agents in Parallel + +Use the Agent tool to launch all three agents concurrently in a single message. Pass each agent the full diff so it has the complete context. + +### Agent 1: Code Reuse Review + +For each change: + +1. Search for existing utilities and helpers that could replace newly written code. Use Grep to find similar patterns elsewhere in the codebase — common locations are utility directories, shared modules, and files adjacent to the changed ones. +2. Flag any new function that duplicates existing functionality. Suggest the existing function to use instead. +3. Flag any inline logic that could use an existing utility — hand-rolled string manipulation, manual path handling, custom environment checks, ad-hoc type guards, and similar patterns are common candidates. + +Note: This is a greenfield app, so focus on maximizing simplicity and don't worry about changing things to achieve it. + +### Agent 2: Code Quality Review + +Review the same changes for hacky patterns: + +1. Redundant state: state that duplicates existing state, cached values that could be derived, observers/effects that could be direct calls +2. Parameter sprawl: adding new parameters to a function instead of generalizing or restructuring existing ones +3. Copy-paste with slight variation: near-duplicate code blocks that should be unified with a shared abstraction +4. Leaky abstractions: exposing internal details that should be encapsulated, or breaking existing abstraction boundaries +5. Stringly-typed code: using raw strings where constants, enums (string unions), or branded types already exist in the codebase + +Note: This is a greenfield app, so be aggressive in optimizing quality. + +### Agent 3: Efficiency Review + +Review the same changes for efficiency: + +1. Unnecessary work: redundant computations, repeated file reads, duplicate network/API calls, N+1 patterns +2. Missed concurrency: independent operations run sequentially when they could run in parallel +3. Hot-path bloat: new blocking work added to startup or per-request/per-render hot paths +4. Unnecessary existence checks: pre-checking file/resource existence before operating (TOCTOU anti-pattern) — operate directly and handle the error +5. Memory: unbounded data structures, missing cleanup, event listener leaks +6. Overly broad operations: reading entire files when only a portion is needed, loading all items when filtering for one + +## Phase 3: Fix Issues + +Wait for all three agents to complete. Aggregate their findings and fix each issue directly. If a finding is a false positive or not worth addressing, note it and move on — do not argue with the finding, just skip it. + +When done, briefly summarize what was fixed (or confirm the code was already clean). \ No newline at end of file diff --git a/stages/006-simplify_opus@1/provider_used.json b/stages/006-simplify_opus@1/provider_used.json new file mode 100644 index 000000000..672cc50e5 --- /dev/null +++ b/stages/006-simplify_opus@1/provider_used.json @@ -0,0 +1,5 @@ +{ + "mode": "agent", + "provider": "anthropic", + "model": "claude-opus-4-7" +} \ No newline at end of file diff --git a/stages/006-simplify_opus@1/response.md b/stages/006-simplify_opus@1/response.md new file mode 100644 index 000000000..661ec6ad1 --- /dev/null +++ b/stages/006-simplify_opus@1/response.md @@ -0,0 +1,30 @@ +All six fixes landed, with net **-57 lines** even while adding three shared helpers and a constructor. Summary of cleanups applied based on the three reviewers' findings: + +## Fixed + +1. **Returned timing from `process_input_with_runtime` instead of stashing it on `Session`** (Agent 2 #1). Dropped `last_input_inference_duration` / `last_input_tool_duration` fields, the `last_input_timing()` getter, and the per-call reset prologue. Signature is now `-> (SessionInputTiming, Result<(), Error>)`. Eliminates the "must read immediately" implicit contract. + +2. **Replaced the `record_inference_duration!` macro with a free function** `record_elapsed(&mut Option, &mut Duration)` (Agent 1 #2, Agent 2 #2). Same 7 call sites, but type-checked, IDE-discoverable, and no macro hygiene. + +3. **Made `run_store` required on `DetachedRunBootstrapGuard::arm()`** (Agent 1 #7, Agent 2 #3/#5). Dropped the `Option` field and the external setter pattern. Drop impl unconditionally builds the conclusion now. + +4. **Extracted `emit_workflow_run_failed` helper** (Agent 1 #7, Agent 2 #4). Collapses the four near-identical "build conclusion → emit run.failed" sites in `start.rs` (terminal engine failure, both Drop guards, `persist_detached_failure`) into one shared function. + +5. **Added `StageTiming::active_only(inference, tool)` constructor** (Agent 1 #1). Removed the local `active_stage_timing` helper in `handler/llm/api.rs` and unified `acp.rs` and `command.rs` on the same shape. + +6. **Reverted `Box` in `CodergenResult::Text`** (Agent 1 #6, Agent 2 #6). Was the worst of both worlds — didn't equalise variant size, forced `.map(|usage| *usage)` ceremony at every call site. Used `#[allow(clippy::large_enum_variant, reason = "...")]` matching the established pattern in `event/events.rs` and `event/sink.rs`. + +7. **Hoisted `test_usage` and `mark_run_running` to `test_support`** (Agent 1 #3/#4). `test_usage` was duplicated in 4 files (this PR was about to add a 5th); the 4th `mark_run_running` copy was right next to a pre-existing 3-event seed in test_support that didn't quite match. Both are now public helpers in `crate::test_support`. + +## Skipped (with reason) + +- **Make Drop guard tasks survive runtime shutdown** (Agent 3 #3) — flagged as a correctness-on-shutdown concern, not introduced by this PR; widening it would be a separate fix. +- **`wait_for_conclusion` polling timeout hardening** (Agent 2 #8) — minor CI flake risk; current 50ms budget is enough for unit tests. +- **`Candidate::timing` zero on LLM-failure heuristic fallback** (Agent 2 #9, Agent 3 implicit) — agent itself noted this is acceptable; capturing wasted inference on errors would require threading Instants through the fan-in evaluator. +- **Helper for the 3-line failed-outcome decoration in agent.rs/prompt.rs** (Agent 2 #7/#10) — marginal benefit not worth the indirection. + +## Verification + +- `cargo +nightly-2026-04-14 clippy --workspace --all-targets -- -D warnings` clean +- `cargo +nightly-2026-04-14 fmt --check --all` clean +- `cargo nextest run -p fabro-workflow -p fabro-agent -p fabro-types -p fabro-core` — all 3592 tests pass (1175 + 1844 + 573 across the affected crates). \ No newline at end of file