diff --git a/run.json b/run.json index 9c5a29c28..192063993 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:48:07.241039Z", + "last_event_at": "2026-05-25T22:52:11.999808Z", "pending_control": null, "checkpoints": [ { @@ -872,9 +872,9 @@ } }, { - "seq": 0, + "seq": 1544, "checkpoint": { - "timestamp": "2026-05-25T22:48:07.334455Z", + "timestamp": "2026-05-25T22:48:11.804786Z", "current_node": "simplify_opus", "completed_nodes": [ "start", @@ -886,48 +886,36 @@ ], "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.", - "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", - "command.output": "blob://sha256/12ae32cb1ec02d01eda3581b127c1fee3b0dc53572ed6baf239721a03d82e126", - "internal.retry_count.toolchain": 0, - "thread.preflight_compile.current_node": "preflight_lint", + "thread.implement.current_node": "simplify_opus", "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.retry_count.start": 0, "internal.run_id": "01KSGHHBR7DQ1RHFYKD7P46R6F", - "internal.retry_count.preflight_lint": 0, + "thread.preflight_compile.current_node": "preflight_lint", "internal.retry_count.implement": 0, + "thread.toolchain.current_node": "preflight_compile", + "graph.model_stylesheet": "\n * { model: claude-opus-4-7; }\n ", + "outcome": "succeeded", + "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", + "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", + "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.retry_count.simplify_opus": 0, "thread.preflight_lint.current_node": "implement", - "thread.implement.current_node": "simplify_opus" + "internal.retry_count.preflight_compile": 0, + "command.output": "blob://sha256/12ae32cb1ec02d01eda3581b127c1fee3b0dc53572ed6baf239721a03d82e126", + "internal.node_visit_count": 1, + "failure_class": "", + "internal.retry_count.toolchain": 0, + "failure_signature": "", + "internal.retry_count.preflight_lint": 0, + "internal.fidelity": "compact", + "internal.thread_id": "implement", + "internal.work_dir": "/home/daytona/workspace/fabro", + "current_node": "simplify_opus", + "last_stage": "simplify_opus", + "graph.rankdir": "LR" }, "node_outcomes": { - "start": { - "status": "succeeded", - "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 - }, "implement": { "status": "succeeded", "context_updates": { @@ -958,6 +946,14 @@ "total_usd_micros": 17743163 } }, + "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 + }, "simplify_opus": { "status": "succeeded", "context_updates": { @@ -1012,6 +1008,88 @@ "notes": "Script completed: cargo check -q --workspace 2>&1", "usage": null }, + "start": { + "status": "succeeded", + "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 + } + }, + "next_node_id": "simplify_gpt", + "git_commit_sha": "f22971be58c217fade7385e77c3d2523117dfadf", + "node_visits": { + "implement": 1, + "preflight_compile": 1, + "preflight_lint": 1, + "simplify_opus": 1, + "start": 1, + "toolchain": 1 + } + }, + "diff": { + "patch": "diff --git a/lib/crates/fabro-agent/src/session.rs b/lib/crates/fabro-agent/src/session.rs\nindex 24df5149d..0cfe25d98 100644\n--- a/lib/crates/fabro-agent/src/session.rs\n+++ b/lib/crates/fabro-agent/src/session.rs\n@@ -76,6 +76,15 @@ pub struct SessionInputTiming {\n pub tool: Duration,\n }\n \n+/// Take the value out of `start`, add its elapsed time to `total`. Used by\n+/// `run_single_input` to accumulate inference and tool spans at well-defined\n+/// boundaries (stream open, retry, error, cancel, end-of-loop).\n+fn record_elapsed(start: &mut Option, total: &mut Duration) {\n+ if let Some(s) = start.take() {\n+ *total = total.saturating_add(s.elapsed());\n+ }\n+}\n+\n impl SteeringItem {\n #[must_use]\n pub fn actor(&self) -> Option<&Principal> {\n@@ -343,8 +352,6 @@ 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@@ -382,8 +389,6 @@ 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@@ -1198,28 +1203,22 @@ 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+ .1\n }\n \n+ /// Process an input. Returns the inference/tool timing accumulated during\n+ /// the call alongside the call result; timing is observed even on error.\n pub async fn process_input_with_runtime(\n &mut self,\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+ ) -> (SessionInputTiming, Result<(), Error>) {\n+ let mut timing = SessionInputTiming::default();\n if self.state == SessionState::Closed {\n- return Err(Error::SessionClosed);\n+ return (timing, Err(Error::SessionClosed));\n }\n \n // Spawn wall-clock timeout task if configured\n@@ -1241,7 +1240,9 @@ impl Session {\n });\n \n // Process the initial input, then drain any followups\n- let mut result = self.run_single_input(input, &agent_tool_runtime).await;\n+ let mut result = self\n+ .run_single_input(input, &agent_tool_runtime, &mut timing)\n+ .await;\n \n if result.is_ok() {\n loop {\n@@ -1251,7 +1252,9 @@ impl Session {\n .expect(\"followup queue lock poisoned\")\n .pop_front();\n let Some(followup) = followup else { break };\n- result = self.run_single_input(&followup, &agent_tool_runtime).await;\n+ result = self\n+ .run_single_input(&followup, &agent_tool_runtime, &mut timing)\n+ .await;\n if result.is_err() {\n break;\n }\n@@ -1268,13 +1271,14 @@ impl Session {\n self.transition(SessionState::Idle);\n }\n \n- result\n+ (timing, result)\n }\n \n async fn run_single_input(\n &mut self,\n input: &str,\n agent_tool_runtime: &AgentToolRuntime,\n+ timing: &mut SessionInputTiming,\n ) -> Result<(), Error> {\n const STREAM_CONSUME_RETRIES: usize = 3;\n \n@@ -1409,15 +1413,6 @@ impl Session {\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@@ -1428,12 +1423,12 @@ impl Session {\n match stream {\n Ok(stream) => stream,\n Err(err) => {\n- record_inference_duration!();\n+ record_elapsed(&mut inference_start, &mut timing.inference);\n return Err(err);\n }\n }\n } else {\n- record_inference_duration!();\n+ record_elapsed(&mut inference_start, &mut timing.inference);\n if self.cancel_token.is_cancelled() {\n self.close();\n return Err(self.interrupted_error());\n@@ -1509,7 +1504,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+ record_elapsed(&mut inference_start, &mut timing.inference);\n self.close();\n return Err(self.interrupted_error());\n }\n@@ -1579,7 +1574,7 @@ impl Session {\n match stream {\n Ok(stream) => stream,\n Err(err) => {\n- record_inference_duration!();\n+ record_elapsed(&mut inference_start, &mut timing.inference);\n return Err(err);\n }\n }\n@@ -1600,7 +1595,7 @@ impl Session {\n },\n );\n }\n- record_inference_duration!();\n+ record_elapsed(&mut inference_start, &mut timing.inference);\n return Err(self.emit_llm_error(err));\n }\n \n@@ -1632,7 +1627,7 @@ impl Session {\n match stream {\n Ok(stream) => stream,\n Err(err) => {\n- record_inference_duration!();\n+ record_elapsed(&mut inference_start, &mut timing.inference);\n return Err(err);\n }\n }\n@@ -1643,7 +1638,7 @@ impl Session {\n };\n }\n }\n- record_inference_duration!();\n+ record_elapsed(&mut inference_start, &mut timing.inference);\n \n // Mid-LLM steer interrupt: drop the unrecorded turn, clear any\n // partial visible output, and re-iterate. The next turn's\n@@ -1770,9 +1765,7 @@ 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+ timing.tool = timing.tool.saturating_add(tool_start.elapsed());\n composite_watcher.abort();\n if tool_calls\n .iter()\n@@ -2292,8 +2285,10 @@ mod tests {\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+ let (first, result) = session\n+ .process_input_with_runtime(\"use the slow tool\", AgentToolRuntime::default())\n+ .await;\n+ result.unwrap();\n assert!(\n first.inference >= Duration::from_millis(35),\n \"expected non-zero inference timing for first input, got {first:?}\"\n@@ -2303,8 +2298,10 @@ mod tests {\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+ let (second, result) = session\n+ .process_input_with_runtime(\"no tools this time\", AgentToolRuntime::default())\n+ .await;\n+ result.unwrap();\n assert!(\n second.inference >= Duration::from_millis(15),\n \"expected per-input inference timing for second input, got {second:?}\"\ndiff --git a/lib/crates/fabro-types/src/timing.rs b/lib/crates/fabro-types/src/timing.rs\nindex 6ca201143..49fa57b06 100644\n--- a/lib/crates/fabro-types/src/timing.rs\n+++ b/lib/crates/fabro-types/src/timing.rs\n@@ -53,6 +53,14 @@ impl StageTiming {\n Self::new(wall_time_ms, 0, 0)\n }\n \n+ /// Active-only timing for stages whose wall time will be supplied\n+ /// separately by the executor's own stopwatch (current shape of the\n+ /// handler → executor hop).\n+ #[must_use]\n+ pub fn active_only(inference_time_ms: u64, tool_time_ms: u64) -> Self {\n+ Self::new(0, inference_time_ms, tool_time_ms)\n+ }\n+\n /// Sum two timings field-by-field. Used to aggregate visits of one node\n /// and to accumulate run-level rollups.\n #[must_use]\ndiff --git a/lib/crates/fabro-workflow/src/billing_rollup.rs b/lib/crates/fabro-workflow/src/billing_rollup.rs\nindex 0e909ce08..feceb0e12 100644\n--- a/lib/crates/fabro-workflow/src/billing_rollup.rs\n+++ b/lib/crates/fabro-workflow/src/billing_rollup.rs\n@@ -164,32 +164,12 @@ mod tests {\n \n use fabro_model::{Catalog, ModelRef, ProviderId};\n use fabro_types::{\n- AttrValue, BilledModelUsage, BilledTokenCounts, Graph, Node, RunProjection, RunSpec,\n- StageCompletion, StageOutcome, WorkflowSettings, first_event_seq, fixtures,\n+ AttrValue, BilledTokenCounts, Graph, Node, RunProjection, RunSpec, StageCompletion,\n+ StageOutcome, WorkflowSettings, first_event_seq, fixtures,\n };\n- use serde_json::json;\n \n use super::billing_rollup_from_projection;\n-\n- fn test_usage(model_id: &str, input_tokens: i64, output_tokens: i64) -> BilledModelUsage {\n- serde_json::from_value(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+ use crate::test_support::test_usage;\n \n fn test_projection() -> RunProjection {\n RunProjection::new(\ndiff --git a/lib/crates/fabro-workflow/src/event/convert.rs b/lib/crates/fabro-workflow/src/event/convert.rs\nindex 2e2014dc1..86a0fef41 100644\n--- a/lib/crates/fabro-workflow/src/event/convert.rs\n+++ b/lib/crates/fabro-workflow/src/event/convert.rs\n@@ -1424,7 +1424,7 @@ mod tests {\n use crate::error::Error;\n use crate::event::test_support::user_principal;\n use crate::event::{Event, StageScope};\n- use crate::outcome::{BilledModelUsage, FailureDetail};\n+ use crate::outcome::FailureDetail;\n \n #[derive(Debug)]\n struct EventTestCause;\n@@ -1446,25 +1446,7 @@ mod tests {\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+ use crate::test_support::test_usage;\n \n #[test]\n fn run_event_stage_completed_places_node_fields_in_header() {\ndiff --git a/lib/crates/fabro-workflow/src/handler/agent.rs b/lib/crates/fabro-workflow/src/handler/agent.rs\nindex f7a9048a5..648f00c4b 100644\n--- a/lib/crates/fabro-workflow/src/handler/agent.rs\n+++ b/lib/crates/fabro-workflow/src/handler/agent.rs\n@@ -20,10 +20,14 @@ use crate::interview_runtime::WorkflowAgentQuestionRuntime;\n use crate::outcome::{BilledModelUsage, Outcome, OutcomeExt};\n \n /// Result from a `CodergenBackend` invocation.\n+#[allow(\n+ clippy::large_enum_variant,\n+ reason = \"Text payload is the common case; Full(Box) is the rare alternative.\"\n+)]\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@@ -302,13 +306,7 @@ impl Handler for AgentHandler {\n files_touched,\n last_file_touched,\n timing,\n- }) => (\n- text,\n- usage.map(|usage| *usage),\n- files_touched,\n- last_file_touched,\n- timing,\n- ),\n+ }) => (text, usage, files_touched, last_file_touched, timing),\n Err(Error::Cancelled) => return Err(Error::Cancelled),\n Err(e) if e.is_retryable() => {\n return Err(e);\ndiff --git a/lib/crates/fabro-workflow/src/handler/command.rs b/lib/crates/fabro-workflow/src/handler/command.rs\nindex 736731a26..dde68dd5d 100644\n--- a/lib/crates/fabro-workflow/src/handler/command.rs\n+++ b/lib/crates/fabro-workflow/src/handler/command.rs\n@@ -178,7 +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+ outcome.timing = Some(StageTiming::active_only(0, result.duration_ms));\n Ok(outcome)\n } else {\n let mut reason = format!(\n@@ -191,7 +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+ outcome.timing = Some(StageTiming::active_only(0, result.duration_ms));\n Ok(outcome)\n }\n }\ndiff --git a/lib/crates/fabro-workflow/src/handler/llm/acp.rs b/lib/crates/fabro-workflow/src/handler/llm/acp.rs\nindex 4b867b7b8..e83d50cf9 100644\n--- a/lib/crates/fabro-workflow/src/handler/llm/acp.rs\n+++ b/lib/crates/fabro-workflow/src/handler/llm/acp.rs\n@@ -233,7 +233,7 @@ impl AgentAcpBackend {\n usage: None,\n files_touched,\n last_file_touched,\n- timing: StageTiming::new(0, result.duration_ms, 0),\n+ timing: StageTiming::active_only(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 df5af98c2..46e2e5d90 100644\n--- a/lib/crates/fabro-workflow/src/handler/llm/api.rs\n+++ b/lib/crates/fabro-workflow/src/handler/llm/api.rs\n@@ -120,12 +120,6 @@ 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@@ -1119,10 +1113,13 @@ impl CodergenBackend for AgentApiBackend {\n \n return Ok(CodergenResult::Text {\n text: response_text,\n- usage: Some(Box::new(stage_usage)),\n+ usage: Some(stage_usage),\n files_touched: Vec::new(),\n last_file_touched: None,\n- timing: active_stage_timing(inference_duration, Duration::ZERO),\n+ timing: StageTiming::active_only(\n+ crate::millis_u64(inference_duration),\n+ 0,\n+ ),\n });\n }\n }\n@@ -1257,10 +1254,9 @@ impl CodergenBackend for AgentApiBackend {\n if !is_reused {\n emit_agent_tools_available(&session, &node.id, &stage_id, emitter);\n }\n- let process_result = session\n+ let (timing, process_result) = session\n .process_input_with_runtime(prompt, agent_tool_runtime.clone())\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@@ -1389,10 +1385,9 @@ impl CodergenBackend for AgentApiBackend {\n }\n }\n emit_agent_tools_available(&session, &node.id, &stage_id, emitter);\n- let process_result = session\n+ let (timing, process_result) = session\n .process_input_with_runtime(prompt, agent_tool_runtime.clone())\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@@ -1456,8 +1451,12 @@ impl CodergenBackend for AgentApiBackend {\n ));\n }\n let repair_message = error.repair_message(schema);\n- let repair_result = session.process_input(&repair_message).await;\n- let timing = session.last_input_timing();\n+ let (timing, repair_result) = session\n+ .process_input_with_runtime(\n+ &repair_message,\n+ fabro_agent::AgentToolRuntime::default(),\n+ )\n+ .await;\n inference_duration = inference_duration.saturating_add(timing.inference);\n tool_duration = tool_duration.saturating_add(timing.tool);\n match repair_result {\n@@ -1532,10 +1531,13 @@ impl CodergenBackend for AgentApiBackend {\n \n Ok(CodergenResult::Text {\n text: response,\n- usage: Some(Box::new(stage_usage)),\n+ usage: Some(stage_usage),\n files_touched,\n last_file_touched,\n- timing: active_stage_timing(inference_duration, tool_duration),\n+ timing: StageTiming::active_only(\n+ crate::millis_u64(inference_duration),\n+ crate::millis_u64(tool_duration),\n+ ),\n })\n }\n }\ndiff --git a/lib/crates/fabro-workflow/src/handler/prompt.rs b/lib/crates/fabro-workflow/src/handler/prompt.rs\nindex 94674421f..8d5b2fdf6 100644\n--- a/lib/crates/fabro-workflow/src/handler/prompt.rs\n+++ b/lib/crates/fabro-workflow/src/handler/prompt.rs\n@@ -138,7 +138,7 @@ impl Handler for PromptHandler {\n files_touched,\n timing,\n ..\n- }) => (text, usage.map(|usage| *usage), files_touched, timing),\n+ }) => (text, usage, files_touched, timing),\n Err(Error::Cancelled) => return Err(Error::Cancelled),\n Err(e) if e.is_retryable() => {\n return Err(e);\ndiff --git a/lib/crates/fabro-workflow/src/operations/start.rs b/lib/crates/fabro-workflow/src/operations/start.rs\nindex 0adc853ac..ec300d581 100644\n--- a/lib/crates/fabro-workflow/src/operations/start.rs\n+++ b/lib/crates/fabro-workflow/src/operations/start.rs\n@@ -209,9 +209,12 @@ pub(super) async fn execute_persisted_run(\n return Err(error);\n }\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+ let mut bootstrap_guard = DetachedRunBootstrapGuard::arm(\n+ run_id,\n+ run_store.clone(),\n+ event_sink.clone(),\n+ cancel_token.clone(),\n+ );\n \n let persisted = match Persisted::load_from_store(&services.run_store, run_dir).await {\n Ok(persisted) => persisted,\n@@ -280,28 +283,28 @@ pub(super) async fn execute_persisted_run(\n }\n }\n \n-async fn persist_terminal_engine_failure(\n+/// Build a conclusion from the store and emit `run.failed` carrying the\n+/// rolled-up timing and billing. Shared by the engine-failure terminal path,\n+/// the bootstrap/completion drop guards, and `persist_detached_failure`.\n+async fn emit_workflow_run_failed(\n run_id: RunId,\n run_store: &RunStoreHandle,\n event_sink: &RunEventSink,\n- _run_dir: &Path,\n error: &Error,\n- duration: Duration,\n+ reason: FailureReason,\n+ wall_duration_ms: u64,\n ) {\n- let engine_result: Result = Err(error.clone());\n- let (final_status, failure_reason, run_status) = classify_engine_result(&engine_result);\n+ let failure = Some(error::run_failure_from_error(error, reason));\n let conclusion = build_conclusion_from_store(\n run_store,\n- final_status,\n- failure_reason,\n- crate::millis_u64(duration),\n+ StageOutcome::Failed {\n+ retry_requested: false,\n+ },\n+ failure,\n+ wall_duration_ms,\n None,\n )\n .await;\n- let reason = match run_status {\n- RunStatus::Failed { reason } => reason,\n- _ => FailureReason::WorkflowError,\n- };\n let failure_event = Event::workflow_run_failed_from_error(\n error,\n conclusion.timing,\n@@ -309,13 +312,38 @@ async fn persist_terminal_engine_failure(\n None,\n None,\n None,\n- conclusion.billing.clone(),\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 terminal engine failure event\");\n+ tracing::warn!(error = %err, \"Failed to append run.failed event\");\n }\n }\n \n+async fn persist_terminal_engine_failure(\n+ run_id: RunId,\n+ run_store: &RunStoreHandle,\n+ event_sink: &RunEventSink,\n+ _run_dir: &Path,\n+ error: &Error,\n+ duration: Duration,\n+) {\n+ let engine_result: Result = Err(error.clone());\n+ let (_, _, run_status) = classify_engine_result(&engine_result);\n+ let reason = match run_status {\n+ RunStatus::Failed { reason } => reason,\n+ _ => FailureReason::WorkflowError,\n+ };\n+ emit_workflow_run_failed(\n+ run_id,\n+ run_store,\n+ event_sink,\n+ error,\n+ reason,\n+ crate::millis_u64(duration),\n+ )\n+ .await;\n+}\n+\n impl RunSession {\n async fn new(persisted: &Persisted, services: StartServices) -> Result {\n let record = persisted.run_spec();\n@@ -902,7 +930,7 @@ impl RunSession {\n \n struct DetachedRunBootstrapGuard {\n run_id: RunId,\n- run_store: Option,\n+ run_store: RunStoreHandle,\n event_sink: RunEventSink,\n cancel_token: CancellationToken,\n active: bool,\n@@ -911,13 +939,13 @@ struct DetachedRunBootstrapGuard {\n impl DetachedRunBootstrapGuard {\n fn arm(\n run_id: RunId,\n- _run_dir: &Path,\n+ run_store: RunStoreHandle,\n event_sink: RunEventSink,\n cancel_token: CancellationToken,\n ) -> Self {\n Self {\n run_id,\n- run_store: None,\n+ run_store,\n event_sink,\n cancel_token,\n active: true,\n@@ -931,45 +959,29 @@ impl DetachedRunBootstrapGuard {\n \n impl Drop for DetachedRunBootstrapGuard {\n fn drop(&mut self) {\n- if self.active {\n- let cancelled = self.cancel_token.is_cancelled();\n- let reason = if cancelled {\n- FailureReason::Cancelled\n- } else {\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- timing,\n- reason,\n- None,\n- None,\n- None,\n- billing,\n- );\n- let _ = append_event_to_sink(&event_sink, &run_id, &failure_event).await;\n- });\n- }\n+ if !self.active {\n+ return;\n+ }\n+ let reason = if self.cancel_token.is_cancelled() {\n+ FailureReason::Cancelled\n+ } else {\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+ emit_workflow_run_failed(\n+ run_id,\n+ &run_store,\n+ &event_sink,\n+ &Error::engine(reason.to_string()),\n+ reason,\n+ 0,\n+ )\n+ .await;\n+ });\n }\n }\n }\n@@ -1033,25 +1045,15 @@ impl Drop for DetachedRunCompletionGuard {\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+ emit_workflow_run_failed(\n+ run_id,\n+ &run_store,\n+ &event_sink,\n &Error::engine(message.to_string()),\n- conclusion.timing,\n reason,\n- None,\n- None,\n- None,\n- conclusion.billing,\n- );\n- let _ = append_event_to_sink(&event_sink, &run_id, &failure_event).await;\n+ 0,\n+ )\n+ .await;\n let _ = append_event_to_sink(&event_sink, &run_id, &Event::RunNotice {\n level: RunNoticeLevel::Error,\n code: code.to_string(),\n@@ -1073,30 +1075,12 @@ async fn persist_detached_failure(\n reason: FailureReason,\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- conclusion.timing,\n- reason,\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- }\n+ emit_workflow_run_failed(run_id, run_store, event_sink, error, reason, 0).await;\n \n let event = Event::RunNotice {\n level: RunNoticeLevel::Error,\n code: format!(\"{phase}_failed\"),\n- message: message.clone(),\n+ message: error.to_string(),\n exec_output_tail: None,\n };\n if let Err(err) = append_event_to_sink(event_sink, &run_id, &event).await {\n@@ -1473,25 +1457,7 @@ 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+ use crate::test_support::{mark_run_running, test_usage};\n \n async fn append_completed_stage(\n run_store: &fabro_store::RunDatabase,\n@@ -1525,27 +1491,6 @@ reasoning = false\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@@ -1671,7 +1616,7 @@ reasoning = false\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+ mark_run_running(&run_store, &fixtures::RUN_1).await;\n append_completed_stage(\n &run_store,\n \"implement\",\n@@ -1717,12 +1662,12 @@ reasoning = false\n }\n \n #[tokio::test]\n- async fn bootstrap_guard_failure_uses_conclusion_timing_and_billing_when_store_exists() {\n+ async fn bootstrap_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 (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+ mark_run_running(&run_store, &fixtures::RUN_1).await;\n append_completed_stage(\n &run_store,\n \"implement\",\n@@ -1734,13 +1679,12 @@ reasoning = false\n let event_sink = RunEventSink::store(run_store.clone());\n \n {\n- let mut guard = DetachedRunBootstrapGuard::arm(\n+ let _guard = DetachedRunBootstrapGuard::arm(\n fixtures::RUN_1,\n- &run_dir,\n+ run_store_handle,\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@@ -1762,7 +1706,7 @@ reasoning = false\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+ mark_run_running(&run_store, &fixtures::RUN_1).await;\n append_completed_stage(\n &run_store,\n \"implement\",\ndiff --git a/lib/crates/fabro-workflow/src/pipeline/finalize.rs b/lib/crates/fabro-workflow/src/pipeline/finalize.rs\nindex 53692daab..05d6db1d0 100644\n--- a/lib/crates/fabro-workflow/src/pipeline/finalize.rs\n+++ b/lib/crates/fabro-workflow/src/pipeline/finalize.rs\n@@ -650,8 +650,8 @@ mod tests {\n use fabro_store::{Database, EventEnvelope, RunDatabase, RunProjection};\n use fabro_types::run_event::{MetadataSnapshotFailureKind, MetadataSnapshotPhase};\n use fabro_types::{\n- BilledModelUsage, BilledTokenCounts, EventBody, RunBlobId, RunEvent, RunId, RunSpec,\n- StageCompletion, WorkflowSettings, first_event_seq, fixtures,\n+ BilledTokenCounts, EventBody, RunBlobId, RunEvent, RunId, RunSpec, StageCompletion,\n+ WorkflowSettings, first_event_seq, fixtures,\n };\n use object_store::memory::InMemory;\n \n@@ -864,25 +864,7 @@ mod tests {\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+ use crate::test_support::test_usage;\n \n #[test]\n fn conclusion_stage_order_follows_projection_first_event_order() {\ndiff --git a/lib/crates/fabro-workflow/src/test_support.rs b/lib/crates/fabro-workflow/src/test_support.rs\nindex 7db2e1ddd..c587e49fa 100644\n--- a/lib/crates/fabro-workflow/src/test_support.rs\n+++ b/lib/crates/fabro-workflow/src/test_support.rs\n@@ -53,6 +53,56 @@ async fn execute_and_emit_terminal(initialized: InitializedState) -> Executed {\n executed\n }\n \n+/// Construct a fully-populated `BilledModelUsage` for tests. Centralised so\n+/// callers don't keep rebuilding the same JSON skeleton.\n+#[must_use]\n+pub fn test_usage(\n+ model_id: &str,\n+ input_tokens: i64,\n+ output_tokens: i64,\n+) -> fabro_types::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+ .expect(\"test_usage JSON must deserialise\")\n+}\n+\n+/// Append the `RunStartRequested → RunRunnable → RunStarting → RunRunning`\n+/// sequence so subsequent calls observe the run as live.\n+pub async fn mark_run_running(run_store: &fabro_store::RunDatabase, run_id: &fabro_types::RunId) {\n+ append_event(run_store, run_id, &Event::RunStartRequested {\n+ resume: false,\n+ actor: None,\n+ })\n+ .await\n+ .expect(\"seed run.start_requested\");\n+ append_event(run_store, run_id, &Event::RunRunnable {\n+ source: fabro_types::RunRunnableSource::StartRequested,\n+ actor: None,\n+ })\n+ .await\n+ .expect(\"seed run.runnable\");\n+ append_event(run_store, run_id, &Event::RunStarting)\n+ .await\n+ .expect(\"seed run.starting\");\n+ append_event(run_store, run_id, &Event::RunRunning)\n+ .await\n+ .expect(\"seed run.running\");\n+}\n+\n pub fn test_store_dir(run_dir: &std::path::Path) -> PathBuf {\n let mut hasher = std::collections::hash_map::DefaultHasher::new();\n std::process::id().hash(&mut hasher);\n", + "summary": { + "files_changed": 17, + "additions": 911, + "deletions": 201 + } + } + }, + { + "seq": 0, + "checkpoint": { + "timestamp": "2026-05-25T22:52:12.048532Z", + "current_node": "simplify_gpt", + "completed_nodes": [ + "start", + "toolchain", + "preflight_compile", + "preflight_lint", + "implement", + "simplify_opus", + "simplify_gpt" + ], + "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.", + "internal.retry_count.start": 0, + "thread.simplify_opus.current_node": "simplify_gpt", + "last_stage": "simplify_gpt", + "graph.model_stylesheet": "\n * { model: claude-opus-4-7; }\n ", + "internal.work_dir": "/home/daytona/workspace/fabro", + "outcome": "succeeded", + "command.output": "blob://sha256/12ae32cb1ec02d01eda3581b127c1fee3b0dc53572ed6baf239721a03d82e126", + "internal.retry_count.toolchain": 0, + "thread.preflight_compile.current_node": "preflight_lint", + "response.simplify_gpt": "Reviewed the branch diff vs merge base and ran the parallel review pass. I found and fixed one cleanup issue:\n\n- Restored `Session::process_input_with_runtime` to its original public `Result<(), Error>` shape instead of returning a tuple.\n- Added the requested `Session::last_input_timing()` getter and `last_input_timing` state on `Session`.\n- Updated workflow callers to read timing through the getter after `process_input_with_runtime(...)`.\n- Updated the agent timing unit test accordingly.\n\nValidation passed:\n\n- `cargo check -q -p fabro-agent -p fabro-workflow`\n- `cargo nextest run -p fabro-agent -p fabro-workflow`\n- `cargo nextest run -p fabro-store -p fabro-core`\n- `cargo +nightly-2026-04-14 fmt --check --all`\n- `cargo +nightly-2026-04-14 clippy -q -p fabro-agent -p fabro-workflow --all-targets -- -D warnings`\n\nWorking tree now has the cleanup edits in:\n\n- `lib/crates/fabro-agent/src/session.rs`\n- `lib/crates/fabro-workflow/src/handler/llm/api.rs`", + "thread.start.current_node": "toolchain", + "internal.retry_count.preflight_compile": 0, + "internal.retry_count.simplify_gpt": 0, + "internal.fidelity": "compact", + "current_node": "simplify_gpt", + "internal.retry_count.simplify_opus": 0, + "last_response": "Reviewed the branch diff vs merge base and ran the parallel review pass. I found and fixed one cleanup issue:\n\n- Restored `Session::process_input_with_runtime` to its original public `Result<(), Error", + "thread.toolchain.current_node": "preflight_compile", + "internal.node_visit_count": 1, + "internal.thread_id": "simplify_opus", + "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.preflight_lint.current_node": "implement", + "thread.implement.current_node": "simplify_opus" + }, + "node_outcomes": { "toolchain": { "status": "succeeded", "context_updates": { @@ -1019,10 +1097,137 @@ }, "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 + }, + "preflight_compile": { + "status": "succeeded", + "context_updates": { + "command.output": "blob://sha256/12ae32cb1ec02d01eda3581b127c1fee3b0dc53572ed6baf239721a03d82e126" + }, + "notes": "Script completed: cargo check -q --workspace 2>&1", + "usage": null + }, + "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" + ] + }, + "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 + } + }, + "simplify_gpt": { + "status": "succeeded", + "context_updates": { + "last_stage": "simplify_gpt", + "response.simplify_gpt": "Reviewed the branch diff vs merge base and ran the parallel review pass. I found and fixed one cleanup issue:\n\n- Restored `Session::process_input_with_runtime` to its original public `Result<(), Error>` shape instead of returning a tuple.\n- Added the requested `Session::last_input_timing()` getter and `last_input_timing` state on `Session`.\n- Updated workflow callers to read timing through the getter after `process_input_with_runtime(...)`.\n- Updated the agent timing unit test accordingly.\n\nValidation passed:\n\n- `cargo check -q -p fabro-agent -p fabro-workflow`\n- `cargo nextest run -p fabro-agent -p fabro-workflow`\n- `cargo nextest run -p fabro-store -p fabro-core`\n- `cargo +nightly-2026-04-14 fmt --check --all`\n- `cargo +nightly-2026-04-14 clippy -q -p fabro-agent -p fabro-workflow --all-targets -- -D warnings`\n\nWorking tree now has the cleanup edits in:\n\n- `lib/crates/fabro-agent/src/session.rs`\n- `lib/crates/fabro-workflow/src/handler/llm/api.rs`", + "last_response": "Reviewed the branch diff vs merge base and ran the parallel review pass. I found and fixed one cleanup issue:\n\n- Restored `Session::process_input_with_runtime` to its original public `Result<(), Error" + }, + "notes": "Stage completed: simplify_gpt", + "usage": { + "input": { + "usage": { + "model": { + "provider": "openai", + "model_id": "gpt-5.5" + }, + "tokens": { + "input_tokens": 884532, + "output_tokens": 3565, + "reasoning_tokens": 1406, + "cache_read_tokens": 628224, + "cache_write_tokens": 0 + } + }, + "facts": { + "algorithm": "openai" + } + }, + "total_usd_micros": 4885902 + } + }, + "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 } }, - "next_node_id": "simplify_gpt", + "next_node_id": "verify", "node_visits": { + "simplify_gpt": 1, "implement": 1, "simplify_opus": 1, "toolchain": 1, @@ -1058,7 +1263,12 @@ "first_event_seq": 845, "prompt": null, "response": null, - "completion": null, + "completion": { + "outcome": "succeeded", + "notes": "Stage completed: simplify_opus", + "failure_reason": null, + "timestamp": "2026-05-25T22:48:07.333773Z" + }, "provider_used": { "mode": "agent", "provider": "anthropic", @@ -1071,6 +1281,12 @@ "output": null, "started_at": "2026-05-25T22:25:15.922125Z", "handler": "agent", + "timing": { + "wall_time_ms": 1371402, + "inference_time_ms": 0, + "tool_time_ms": 0, + "active_time_ms": 0 + }, "usage": { "input_tokens": 146925, "output_tokens": 49357, @@ -1365,7 +1581,7 @@ ], "warnings": [] }, - "state": "running" + "state": "succeeded" }, "toolchain@1": { "first_event_seq": 21, @@ -1792,6 +2008,262 @@ "warnings": [] }, "state": "succeeded" + }, + "simplify_gpt@1": { + "first_event_seq": 1547, + "prompt": null, + "response": null, + "completion": null, + "provider_used": { + "mode": "agent", + "provider": "openai", + "model": "gpt-5.5" + }, + "diff": null, + "script_invocation": null, + "script_timing": null, + "parallel_results": null, + "output": null, + "started_at": "2026-05-25T22:48:11.808047Z", + "handler": "agent", + "usage": { + "input_tokens": 884532, + "output_tokens": 3565, + "total_tokens": 1517727, + "reasoning_tokens": 1406, + "cache_read_tokens": 628224, + "cache_write_tokens": 0, + "total_usd_micros": 4885902 + }, + "model": { + "provider": "openai", + "model_id": "gpt-5.5" + }, + "todos": { + "kind": "openai_plan", + "list_id": "openai_plan:994f8336-cba0-4f7f-972d-ac5427d8976b", + "items": [ + { + "id": "2f6a6b1e89a205ae", + "status": "in_progress", + "order": 0, + "subject": "Inspect repository instructions and staged diff file" + }, + { + "id": "a7e1960422bd0708", + "status": "pending", + "order": 1, + "subject": "Search for existing helpers matching new code" + }, + { + "id": "fe6ade00cfbca35a", + "status": "pending", + "order": 2, + "subject": "Report actionable code reuse findings with references" + } + ] + }, + "subagents": [ + { + "agent_id": "2069b50d", + "depth": 1, + "task": "Code Reuse Review. Review the full diff at /tmp/fabro-stage-timing.diff in working directory /home/daytona/workspace/fabro. For each change, search for existing utilities/helpers that could replace newly written code. Flag duplicate functions or inline logic that should use existing utilities. Focus on actionable findings only; include file/line references where possible. Do not modify files.", + "status": { + "kind": "completed", + "success": true, + "turns_used": 21 + } + }, + { + "agent_id": "963ba487", + "depth": 1, + "task": "Code Quality Review. Review the full diff at /tmp/fabro-stage-timing.diff in working directory /home/daytona/workspace/fabro for hacky patterns: redundant state, parameter sprawl, copy-paste, leaky abstractions, stringly-typed code. Be aggressive but actionable. Include file/line references where possible. Do not modify files.", + "status": { + "kind": "completed", + "success": true, + "turns_used": 21 + } + }, + { + "agent_id": "89af0eac", + "depth": 1, + "task": "Efficiency Review. Review the full diff at /tmp/fabro-stage-timing.diff in working directory /home/daytona/workspace/fabro for unnecessary work, missed concurrency, hot-path bloat, TOCTOU, memory/leaks, overly broad operations. Include actionable findings with file/line references. Do not modify files.", + "status": { + "kind": "completed", + "success": true, + "turns_used": 21 + } + } + ], + "permission_level": "full", + "agent_tools": [ + { + "name": "apply_patch", + "description": "Use the `apply_patch` tool to edit files. This is a FREEFORM tool, so do not wrap the patch in JSON.", + "source": { + "kind": "native" + }, + "category": "write", + "invoked": true + }, + { + "name": "close_agent", + "description": "Close a running subagent that is no longer needed.", + "source": { + "kind": "native" + }, + "category": "subagent", + "invoked": false + }, + { + "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": true + }, + { + "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": "request_user_input", + "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": "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": "update_plan", + "description": "Update the multi-step plan for the current task. Submit the entire plan; existing steps are reconciled by exact step text.", + "source": { + "kind": "native" + }, + "category": "other", + "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": "openai", + "model": "gpt-5.5", + "context_window_tokens": 272000, + "input_tokens": 69307, + "usage_percent": 25.480514705882353, + "count_method": "response_usage_scaled_breakdown", + "staleness": "live", + "generated_at": "2026-05-25T22:52:11.999530Z", + "event_seq": 1812, + "breakdown": [ + { + "category": "system_prompt", + "tokens": 1075, + "usage_percent": 0.3952205882352941 + }, + { + "category": "tools", + "tokens": 1522, + "usage_percent": 0.5595588235294118 + }, + { + "category": "memory", + "tokens": 3601, + "usage_percent": 1.3238970588235295 + }, + { + "category": "conversation", + "tokens": 63103, + "usage_percent": 23.199632352941176 + }, + { + "category": "other", + "tokens": 6, + "usage_percent": 0.0022058823529411764 + } + ], + "warnings": [] + }, + "state": "running" } } } \ No newline at end of file diff --git a/stages/006-simplify_opus@1/diff.patch b/stages/006-simplify_opus@1/diff.patch new file mode 100644 index 000000000..71d656be3 --- /dev/null +++ b/stages/006-simplify_opus@1/diff.patch @@ -0,0 +1,964 @@ +diff --git a/lib/crates/fabro-agent/src/session.rs b/lib/crates/fabro-agent/src/session.rs +index 24df5149d..0cfe25d98 100644 +--- a/lib/crates/fabro-agent/src/session.rs ++++ b/lib/crates/fabro-agent/src/session.rs +@@ -76,6 +76,15 @@ pub struct SessionInputTiming { + pub tool: Duration, + } + ++/// Take the value out of `start`, add its elapsed time to `total`. Used by ++/// `run_single_input` to accumulate inference and tool spans at well-defined ++/// boundaries (stream open, retry, error, cancel, end-of-loop). ++fn record_elapsed(start: &mut Option, total: &mut Duration) { ++ if let Some(s) = start.take() { ++ *total = total.saturating_add(s.elapsed()); ++ } ++} ++ + impl SteeringItem { + #[must_use] + pub fn actor(&self) -> Option<&Principal> { +@@ -343,8 +352,6 @@ 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 { +@@ -382,8 +389,6 @@ impl Session { + tool_env_provider: None, + subagent_manager, + completion_coordinator: None, +- last_input_inference_duration: Duration::ZERO, +- last_input_tool_duration: Duration::ZERO, + } + } + +@@ -1198,28 +1203,22 @@ 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 ++ .1 + } + ++ /// Process an input. Returns the inference/tool timing accumulated during ++ /// the call alongside the call result; timing is observed even on error. + pub async fn process_input_with_runtime( + &mut self, + input: &str, + agent_tool_runtime: AgentToolRuntime, +- ) -> Result<(), Error> { +- self.last_input_inference_duration = Duration::ZERO; +- self.last_input_tool_duration = Duration::ZERO; ++ ) -> (SessionInputTiming, Result<(), Error>) { ++ let mut timing = SessionInputTiming::default(); + if self.state == SessionState::Closed { +- return Err(Error::SessionClosed); ++ return (timing, Err(Error::SessionClosed)); + } + + // Spawn wall-clock timeout task if configured +@@ -1241,7 +1240,9 @@ impl Session { + }); + + // Process the initial input, then drain any followups +- let mut result = self.run_single_input(input, &agent_tool_runtime).await; ++ let mut result = self ++ .run_single_input(input, &agent_tool_runtime, &mut timing) ++ .await; + + if result.is_ok() { + loop { +@@ -1251,7 +1252,9 @@ impl Session { + .expect("followup queue lock poisoned") + .pop_front(); + let Some(followup) = followup else { break }; +- result = self.run_single_input(&followup, &agent_tool_runtime).await; ++ result = self ++ .run_single_input(&followup, &agent_tool_runtime, &mut timing) ++ .await; + if result.is_err() { + break; + } +@@ -1268,13 +1271,14 @@ impl Session { + self.transition(SessionState::Idle); + } + +- result ++ (timing, result) + } + + async fn run_single_input( + &mut self, + input: &str, + agent_tool_runtime: &AgentToolRuntime, ++ timing: &mut SessionInputTiming, + ) -> Result<(), Error> { + const STREAM_CONSUME_RETRIES: usize = 3; + +@@ -1409,15 +1413,6 @@ 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, +@@ -1428,12 +1423,12 @@ impl Session { + match stream { + Ok(stream) => stream, + Err(err) => { +- record_inference_duration!(); ++ record_elapsed(&mut inference_start, &mut timing.inference); + return Err(err); + } + } + } else { +- record_inference_duration!(); ++ record_elapsed(&mut inference_start, &mut timing.inference); + if self.cancel_token.is_cancelled() { + self.close(); + return Err(self.interrupted_error()); +@@ -1509,7 +1504,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!(); ++ record_elapsed(&mut inference_start, &mut timing.inference); + self.close(); + return Err(self.interrupted_error()); + } +@@ -1579,7 +1574,7 @@ impl Session { + match stream { + Ok(stream) => stream, + Err(err) => { +- record_inference_duration!(); ++ record_elapsed(&mut inference_start, &mut timing.inference); + return Err(err); + } + } +@@ -1600,7 +1595,7 @@ impl Session { + }, + ); + } +- record_inference_duration!(); ++ record_elapsed(&mut inference_start, &mut timing.inference); + return Err(self.emit_llm_error(err)); + } + +@@ -1632,7 +1627,7 @@ impl Session { + match stream { + Ok(stream) => stream, + Err(err) => { +- record_inference_duration!(); ++ record_elapsed(&mut inference_start, &mut timing.inference); + return Err(err); + } + } +@@ -1643,7 +1638,7 @@ impl Session { + }; + } + } +- record_inference_duration!(); ++ record_elapsed(&mut inference_start, &mut timing.inference); + + // Mid-LLM steer interrupt: drop the unrecorded turn, clear any + // partial visible output, and re-iterate. The next turn's +@@ -1770,9 +1765,7 @@ impl Session { + agent_tool_runtime, + ) + .await; +- self.last_input_tool_duration = self +- .last_input_tool_duration +- .saturating_add(tool_start.elapsed()); ++ timing.tool = timing.tool.saturating_add(tool_start.elapsed()); + composite_watcher.abort(); + if tool_calls + .iter() +@@ -2292,8 +2285,10 @@ mod tests { + 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(); ++ let (first, result) = session ++ .process_input_with_runtime("use the slow tool", AgentToolRuntime::default()) ++ .await; ++ result.unwrap(); + assert!( + first.inference >= Duration::from_millis(35), + "expected non-zero inference timing for first input, got {first:?}" +@@ -2303,8 +2298,10 @@ mod tests { + "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(); ++ let (second, result) = session ++ .process_input_with_runtime("no tools this time", AgentToolRuntime::default()) ++ .await; ++ result.unwrap(); + assert!( + second.inference >= Duration::from_millis(15), + "expected per-input inference timing for second input, got {second:?}" +diff --git a/lib/crates/fabro-types/src/timing.rs b/lib/crates/fabro-types/src/timing.rs +index 6ca201143..49fa57b06 100644 +--- a/lib/crates/fabro-types/src/timing.rs ++++ b/lib/crates/fabro-types/src/timing.rs +@@ -53,6 +53,14 @@ impl StageTiming { + Self::new(wall_time_ms, 0, 0) + } + ++ /// Active-only timing for stages whose wall time will be supplied ++ /// separately by the executor's own stopwatch (current shape of the ++ /// handler → executor hop). ++ #[must_use] ++ pub fn active_only(inference_time_ms: u64, tool_time_ms: u64) -> Self { ++ Self::new(0, inference_time_ms, tool_time_ms) ++ } ++ + /// Sum two timings field-by-field. Used to aggregate visits of one node + /// and to accumulate run-level rollups. + #[must_use] +diff --git a/lib/crates/fabro-workflow/src/billing_rollup.rs b/lib/crates/fabro-workflow/src/billing_rollup.rs +index 0e909ce08..feceb0e12 100644 +--- a/lib/crates/fabro-workflow/src/billing_rollup.rs ++++ b/lib/crates/fabro-workflow/src/billing_rollup.rs +@@ -164,32 +164,12 @@ mod tests { + + use fabro_model::{Catalog, ModelRef, ProviderId}; + use fabro_types::{ +- AttrValue, BilledModelUsage, BilledTokenCounts, Graph, Node, RunProjection, RunSpec, +- StageCompletion, StageOutcome, WorkflowSettings, first_event_seq, fixtures, ++ AttrValue, BilledTokenCounts, Graph, Node, RunProjection, RunSpec, StageCompletion, ++ StageOutcome, WorkflowSettings, first_event_seq, fixtures, + }; +- use serde_json::json; + + use super::billing_rollup_from_projection; +- +- fn test_usage(model_id: &str, input_tokens: i64, output_tokens: i64) -> BilledModelUsage { +- serde_json::from_value(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() +- } ++ use crate::test_support::test_usage; + + fn test_projection() -> RunProjection { + RunProjection::new( +diff --git a/lib/crates/fabro-workflow/src/event/convert.rs b/lib/crates/fabro-workflow/src/event/convert.rs +index 2e2014dc1..86a0fef41 100644 +--- a/lib/crates/fabro-workflow/src/event/convert.rs ++++ b/lib/crates/fabro-workflow/src/event/convert.rs +@@ -1424,7 +1424,7 @@ mod tests { + use crate::error::Error; + use crate::event::test_support::user_principal; + use crate::event::{Event, StageScope}; +- use crate::outcome::{BilledModelUsage, FailureDetail}; ++ use crate::outcome::FailureDetail; + + #[derive(Debug)] + struct EventTestCause; +@@ -1446,25 +1446,7 @@ mod tests { + } + } + +- 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() +- } ++ use crate::test_support::test_usage; + + #[test] + fn run_event_stage_completed_places_node_fields_in_header() { +diff --git a/lib/crates/fabro-workflow/src/handler/agent.rs b/lib/crates/fabro-workflow/src/handler/agent.rs +index f7a9048a5..648f00c4b 100644 +--- a/lib/crates/fabro-workflow/src/handler/agent.rs ++++ b/lib/crates/fabro-workflow/src/handler/agent.rs +@@ -20,10 +20,14 @@ use crate::interview_runtime::WorkflowAgentQuestionRuntime; + use crate::outcome::{BilledModelUsage, Outcome, OutcomeExt}; + + /// Result from a `CodergenBackend` invocation. ++#[allow( ++ clippy::large_enum_variant, ++ reason = "Text payload is the common case; Full(Box) is the rare alternative." ++)] + 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 +@@ -302,13 +306,7 @@ impl Handler for AgentHandler { + files_touched, + last_file_touched, + timing, +- }) => ( +- text, +- usage.map(|usage| *usage), +- files_touched, +- last_file_touched, +- timing, +- ), ++ }) => (text, usage, files_touched, last_file_touched, timing), + Err(Error::Cancelled) => return Err(Error::Cancelled), + Err(e) if e.is_retryable() => { + return Err(e); +diff --git a/lib/crates/fabro-workflow/src/handler/command.rs b/lib/crates/fabro-workflow/src/handler/command.rs +index 736731a26..dde68dd5d 100644 +--- a/lib/crates/fabro-workflow/src/handler/command.rs ++++ b/lib/crates/fabro-workflow/src/handler/command.rs +@@ -178,7 +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)); ++ outcome.timing = Some(StageTiming::active_only(0, result.duration_ms)); + Ok(outcome) + } else { + let mut reason = format!( +@@ -191,7 +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)); ++ outcome.timing = Some(StageTiming::active_only(0, result.duration_ms)); + Ok(outcome) + } + } +diff --git a/lib/crates/fabro-workflow/src/handler/llm/acp.rs b/lib/crates/fabro-workflow/src/handler/llm/acp.rs +index 4b867b7b8..e83d50cf9 100644 +--- a/lib/crates/fabro-workflow/src/handler/llm/acp.rs ++++ b/lib/crates/fabro-workflow/src/handler/llm/acp.rs +@@ -233,7 +233,7 @@ impl AgentAcpBackend { + usage: None, + files_touched, + last_file_touched, +- timing: StageTiming::new(0, result.duration_ms, 0), ++ timing: StageTiming::active_only(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 df5af98c2..46e2e5d90 100644 +--- a/lib/crates/fabro-workflow/src/handler/llm/api.rs ++++ b/lib/crates/fabro-workflow/src/handler/llm/api.rs +@@ -120,12 +120,6 @@ 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) => { +@@ -1119,10 +1113,13 @@ impl CodergenBackend for AgentApiBackend { + + return Ok(CodergenResult::Text { + text: response_text, +- usage: Some(Box::new(stage_usage)), ++ usage: Some(stage_usage), + files_touched: Vec::new(), + last_file_touched: None, +- timing: active_stage_timing(inference_duration, Duration::ZERO), ++ timing: StageTiming::active_only( ++ crate::millis_u64(inference_duration), ++ 0, ++ ), + }); + } + } +@@ -1257,10 +1254,9 @@ impl CodergenBackend for AgentApiBackend { + if !is_reused { + emit_agent_tools_available(&session, &node.id, &stage_id, emitter); + } +- let process_result = session ++ let (timing, process_result) = session + .process_input_with_runtime(prompt, agent_tool_runtime.clone()) + .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 +@@ -1389,10 +1385,9 @@ impl CodergenBackend for AgentApiBackend { + } + } + emit_agent_tools_available(&session, &node.id, &stage_id, emitter); +- let process_result = session ++ let (timing, process_result) = session + .process_input_with_runtime(prompt, agent_tool_runtime.clone()) + .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 { +@@ -1456,8 +1451,12 @@ impl CodergenBackend for AgentApiBackend { + )); + } + let repair_message = error.repair_message(schema); +- let repair_result = session.process_input(&repair_message).await; +- let timing = session.last_input_timing(); ++ let (timing, repair_result) = session ++ .process_input_with_runtime( ++ &repair_message, ++ fabro_agent::AgentToolRuntime::default(), ++ ) ++ .await; + inference_duration = inference_duration.saturating_add(timing.inference); + tool_duration = tool_duration.saturating_add(timing.tool); + match repair_result { +@@ -1532,10 +1531,13 @@ impl CodergenBackend for AgentApiBackend { + + Ok(CodergenResult::Text { + text: response, +- usage: Some(Box::new(stage_usage)), ++ usage: Some(stage_usage), + files_touched, + last_file_touched, +- timing: active_stage_timing(inference_duration, tool_duration), ++ timing: StageTiming::active_only( ++ crate::millis_u64(inference_duration), ++ crate::millis_u64(tool_duration), ++ ), + }) + } + } +diff --git a/lib/crates/fabro-workflow/src/handler/prompt.rs b/lib/crates/fabro-workflow/src/handler/prompt.rs +index 94674421f..8d5b2fdf6 100644 +--- a/lib/crates/fabro-workflow/src/handler/prompt.rs ++++ b/lib/crates/fabro-workflow/src/handler/prompt.rs +@@ -138,7 +138,7 @@ impl Handler for PromptHandler { + files_touched, + timing, + .. +- }) => (text, usage.map(|usage| *usage), files_touched, timing), ++ }) => (text, usage, files_touched, timing), + Err(Error::Cancelled) => return Err(Error::Cancelled), + Err(e) if e.is_retryable() => { + return Err(e); +diff --git a/lib/crates/fabro-workflow/src/operations/start.rs b/lib/crates/fabro-workflow/src/operations/start.rs +index 0adc853ac..ec300d581 100644 +--- a/lib/crates/fabro-workflow/src/operations/start.rs ++++ b/lib/crates/fabro-workflow/src/operations/start.rs +@@ -209,9 +209,12 @@ pub(super) async fn execute_persisted_run( + return Err(error); + } + +- 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 mut bootstrap_guard = DetachedRunBootstrapGuard::arm( ++ run_id, ++ run_store.clone(), ++ event_sink.clone(), ++ cancel_token.clone(), ++ ); + + let persisted = match Persisted::load_from_store(&services.run_store, run_dir).await { + Ok(persisted) => persisted, +@@ -280,28 +283,28 @@ pub(super) async fn execute_persisted_run( + } + } + +-async fn persist_terminal_engine_failure( ++/// Build a conclusion from the store and emit `run.failed` carrying the ++/// rolled-up timing and billing. Shared by the engine-failure terminal path, ++/// the bootstrap/completion drop guards, and `persist_detached_failure`. ++async fn emit_workflow_run_failed( + run_id: RunId, + run_store: &RunStoreHandle, + event_sink: &RunEventSink, +- _run_dir: &Path, + error: &Error, +- duration: Duration, ++ reason: FailureReason, ++ wall_duration_ms: u64, + ) { +- let engine_result: Result = Err(error.clone()); +- let (final_status, failure_reason, run_status) = classify_engine_result(&engine_result); ++ let failure = Some(error::run_failure_from_error(error, reason)); + let conclusion = build_conclusion_from_store( + run_store, +- final_status, +- failure_reason, +- crate::millis_u64(duration), ++ StageOutcome::Failed { ++ retry_requested: false, ++ }, ++ failure, ++ wall_duration_ms, + None, + ) + .await; +- let reason = match run_status { +- RunStatus::Failed { reason } => reason, +- _ => FailureReason::WorkflowError, +- }; + let failure_event = Event::workflow_run_failed_from_error( + error, + conclusion.timing, +@@ -309,13 +312,38 @@ async fn persist_terminal_engine_failure( + None, + None, + None, +- conclusion.billing.clone(), ++ conclusion.billing, + ); + 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"); ++ tracing::warn!(error = %err, "Failed to append run.failed event"); + } + } + ++async fn persist_terminal_engine_failure( ++ run_id: RunId, ++ run_store: &RunStoreHandle, ++ event_sink: &RunEventSink, ++ _run_dir: &Path, ++ error: &Error, ++ duration: Duration, ++) { ++ let engine_result: Result = Err(error.clone()); ++ let (_, _, run_status) = classify_engine_result(&engine_result); ++ let reason = match run_status { ++ RunStatus::Failed { reason } => reason, ++ _ => FailureReason::WorkflowError, ++ }; ++ emit_workflow_run_failed( ++ run_id, ++ run_store, ++ event_sink, ++ error, ++ reason, ++ crate::millis_u64(duration), ++ ) ++ .await; ++} ++ + impl RunSession { + async fn new(persisted: &Persisted, services: StartServices) -> Result { + let record = persisted.run_spec(); +@@ -902,7 +930,7 @@ impl RunSession { + + struct DetachedRunBootstrapGuard { + run_id: RunId, +- run_store: Option, ++ run_store: RunStoreHandle, + event_sink: RunEventSink, + cancel_token: CancellationToken, + active: bool, +@@ -911,13 +939,13 @@ struct DetachedRunBootstrapGuard { + impl DetachedRunBootstrapGuard { + fn arm( + run_id: RunId, +- _run_dir: &Path, ++ run_store: RunStoreHandle, + event_sink: RunEventSink, + cancel_token: CancellationToken, + ) -> Self { + Self { + run_id, +- run_store: None, ++ run_store, + event_sink, + cancel_token, + active: true, +@@ -931,45 +959,29 @@ impl DetachedRunBootstrapGuard { + + impl Drop for DetachedRunBootstrapGuard { + fn drop(&mut self) { +- if self.active { +- let cancelled = self.cancel_token.is_cancelled(); +- let reason = if cancelled { +- FailureReason::Cancelled +- } else { +- 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()), +- timing, +- reason, +- None, +- None, +- None, +- billing, +- ); +- let _ = append_event_to_sink(&event_sink, &run_id, &failure_event).await; +- }); +- } ++ if !self.active { ++ return; ++ } ++ let reason = if self.cancel_token.is_cancelled() { ++ FailureReason::Cancelled ++ } else { ++ 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 { ++ emit_workflow_run_failed( ++ run_id, ++ &run_store, ++ &event_sink, ++ &Error::engine(reason.to_string()), ++ reason, ++ 0, ++ ) ++ .await; ++ }); + } + } + } +@@ -1033,25 +1045,15 @@ impl Drop for DetachedRunCompletionGuard { + 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( ++ emit_workflow_run_failed( ++ run_id, ++ &run_store, ++ &event_sink, + &Error::engine(message.to_string()), +- conclusion.timing, + reason, +- None, +- None, +- None, +- conclusion.billing, +- ); +- let _ = append_event_to_sink(&event_sink, &run_id, &failure_event).await; ++ 0, ++ ) ++ .await; + let _ = append_event_to_sink(&event_sink, &run_id, &Event::RunNotice { + level: RunNoticeLevel::Error, + code: code.to_string(), +@@ -1073,30 +1075,12 @@ async fn persist_detached_failure( + reason: FailureReason, + 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, +- conclusion.timing, +- reason, +- 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"); +- } ++ emit_workflow_run_failed(run_id, run_store, event_sink, error, reason, 0).await; + + let event = Event::RunNotice { + level: RunNoticeLevel::Error, + code: format!("{phase}_failed"), +- message: message.clone(), ++ message: error.to_string(), + exec_output_tail: None, + }; + if let Err(err) = append_event_to_sink(event_sink, &run_id, &event).await { +@@ -1473,25 +1457,7 @@ 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() +- } ++ use crate::test_support::{mark_run_running, test_usage}; + + async fn append_completed_stage( + run_store: &fabro_store::RunDatabase, +@@ -1525,27 +1491,6 @@ reasoning = false + .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 { +@@ -1671,7 +1616,7 @@ reasoning = false + 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; ++ mark_run_running(&run_store, &fixtures::RUN_1).await; + append_completed_stage( + &run_store, + "implement", +@@ -1717,12 +1662,12 @@ reasoning = false + } + + #[tokio::test] +- async fn bootstrap_guard_failure_uses_conclusion_timing_and_billing_when_store_exists() { ++ async fn bootstrap_guard_failure_uses_conclusion_timing_and_billing() { + let temp = tempfile::tempdir().unwrap(); +- let (storage_root, run_dir) = storage_root_and_run_dir(&temp); ++ 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; ++ mark_run_running(&run_store, &fixtures::RUN_1).await; + append_completed_stage( + &run_store, + "implement", +@@ -1734,13 +1679,12 @@ reasoning = false + let event_sink = RunEventSink::store(run_store.clone()); + + { +- let mut guard = DetachedRunBootstrapGuard::arm( ++ let _guard = DetachedRunBootstrapGuard::arm( + fixtures::RUN_1, +- &run_dir, ++ run_store_handle, + event_sink, + CancellationToken::new(), + ); +- guard.run_store = Some(run_store_handle); + } + + let conclusion = wait_for_conclusion(&run_store).await; +@@ -1762,7 +1706,7 @@ reasoning = false + 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; ++ mark_run_running(&run_store, &fixtures::RUN_1).await; + append_completed_stage( + &run_store, + "implement", +diff --git a/lib/crates/fabro-workflow/src/pipeline/finalize.rs b/lib/crates/fabro-workflow/src/pipeline/finalize.rs +index 53692daab..05d6db1d0 100644 +--- a/lib/crates/fabro-workflow/src/pipeline/finalize.rs ++++ b/lib/crates/fabro-workflow/src/pipeline/finalize.rs +@@ -650,8 +650,8 @@ mod tests { + use fabro_store::{Database, EventEnvelope, RunDatabase, RunProjection}; + use fabro_types::run_event::{MetadataSnapshotFailureKind, MetadataSnapshotPhase}; + use fabro_types::{ +- BilledModelUsage, BilledTokenCounts, EventBody, RunBlobId, RunEvent, RunId, RunSpec, +- StageCompletion, WorkflowSettings, first_event_seq, fixtures, ++ BilledTokenCounts, EventBody, RunBlobId, RunEvent, RunId, RunSpec, StageCompletion, ++ WorkflowSettings, first_event_seq, fixtures, + }; + use object_store::memory::InMemory; + +@@ -864,25 +864,7 @@ mod tests { + ) + } + +- 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() +- } ++ use crate::test_support::test_usage; + + #[test] + fn conclusion_stage_order_follows_projection_first_event_order() { +diff --git a/lib/crates/fabro-workflow/src/test_support.rs b/lib/crates/fabro-workflow/src/test_support.rs +index 7db2e1ddd..c587e49fa 100644 +--- a/lib/crates/fabro-workflow/src/test_support.rs ++++ b/lib/crates/fabro-workflow/src/test_support.rs +@@ -53,6 +53,56 @@ async fn execute_and_emit_terminal(initialized: InitializedState) -> Executed { + executed + } + ++/// Construct a fully-populated `BilledModelUsage` for tests. Centralised so ++/// callers don't keep rebuilding the same JSON skeleton. ++#[must_use] ++pub fn test_usage( ++ model_id: &str, ++ input_tokens: i64, ++ output_tokens: i64, ++) -> fabro_types::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 ++ })) ++ .expect("test_usage JSON must deserialise") ++} ++ ++/// Append the `RunStartRequested → RunRunnable → RunStarting → RunRunning` ++/// sequence so subsequent calls observe the run as live. ++pub async fn mark_run_running(run_store: &fabro_store::RunDatabase, run_id: &fabro_types::RunId) { ++ append_event(run_store, run_id, &Event::RunStartRequested { ++ resume: false, ++ actor: None, ++ }) ++ .await ++ .expect("seed run.start_requested"); ++ append_event(run_store, run_id, &Event::RunRunnable { ++ source: fabro_types::RunRunnableSource::StartRequested, ++ actor: None, ++ }) ++ .await ++ .expect("seed run.runnable"); ++ append_event(run_store, run_id, &Event::RunStarting) ++ .await ++ .expect("seed run.starting"); ++ append_event(run_store, run_id, &Event::RunRunning) ++ .await ++ .expect("seed run.running"); ++} ++ + pub fn test_store_dir(run_dir: &std::path::Path) -> PathBuf { + let mut hasher = std::collections::hash_map::DefaultHasher::new(); + std::process::id().hash(&mut hasher); diff --git a/stages/006-simplify_opus@1/status.json b/stages/006-simplify_opus@1/status.json new file mode 100644 index 000000000..bede01843 --- /dev/null +++ b/stages/006-simplify_opus@1/status.json @@ -0,0 +1,6 @@ +{ + "outcome": "succeeded", + "notes": "Stage completed: simplify_opus", + "failure_reason": null, + "timestamp": "2026-05-25T22:48:07.333773Z" +} \ No newline at end of file diff --git a/stages/007-simplify_gpt@1/prompt.md b/stages/007-simplify_gpt@1/prompt.md new file mode 100644 index 000000000..d18270a6e --- /dev/null +++ b/stages/007-simplify_gpt@1/prompt.md @@ -0,0 +1,189 @@ +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_opus**: succeeded + - Model: claude-opus-4-7, 146.9k tokens in / 49.4k out + - Files: /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 + + +# 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/007-simplify_gpt@1/provider_used.json b/stages/007-simplify_gpt@1/provider_used.json new file mode 100644 index 000000000..a04162cbf --- /dev/null +++ b/stages/007-simplify_gpt@1/provider_used.json @@ -0,0 +1,5 @@ +{ + "mode": "agent", + "provider": "openai", + "model": "gpt-5.5" +} \ No newline at end of file diff --git a/stages/007-simplify_gpt@1/response.md b/stages/007-simplify_gpt@1/response.md new file mode 100644 index 000000000..a5aec1acb --- /dev/null +++ b/stages/007-simplify_gpt@1/response.md @@ -0,0 +1,19 @@ +Reviewed the branch diff vs merge base and ran the parallel review pass. I found and fixed one cleanup issue: + +- Restored `Session::process_input_with_runtime` to its original public `Result<(), Error>` shape instead of returning a tuple. +- Added the requested `Session::last_input_timing()` getter and `last_input_timing` state on `Session`. +- Updated workflow callers to read timing through the getter after `process_input_with_runtime(...)`. +- Updated the agent timing unit test accordingly. + +Validation passed: + +- `cargo check -q -p fabro-agent -p fabro-workflow` +- `cargo nextest run -p fabro-agent -p fabro-workflow` +- `cargo nextest run -p fabro-store -p fabro-core` +- `cargo +nightly-2026-04-14 fmt --check --all` +- `cargo +nightly-2026-04-14 clippy -q -p fabro-agent -p fabro-workflow --all-targets -- -D warnings` + +Working tree now has the cleanup edits in: + +- `lib/crates/fabro-agent/src/session.rs` +- `lib/crates/fabro-workflow/src/handler/llm/api.rs` \ No newline at end of file