From 786421dfee01675008093a680b378719fc7e8509 Mon Sep 17 00:00:00 2001 From: Fabro Date: Mon, 25 May 2026 18:25:12 -0400 Subject: [PATCH] =?UTF-8?q?checkpoint=20=E2=9A=92=EF=B8=8F=20Generated=20w?= =?UTF-8?q?ith=20[Fabro](https://fabro.sh)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- run.json | 390 +++++++++++++++++- stages/004-preflight_lint@1/output.log | 1 + .../004-preflight_lint@1/script_timing.json | 8 + stages/004-preflight_lint@1/status.json | 6 + stages/005-implement@1/prompt.md | 135 ++++++ stages/005-implement@1/provider_used.json | 6 + stages/005-implement@1/response.md | 35 ++ 7 files changed, 574 insertions(+), 7 deletions(-) create mode 100644 stages/004-preflight_lint@1/output.log create mode 100644 stages/004-preflight_lint@1/script_timing.json create mode 100644 stages/004-preflight_lint@1/status.json create mode 100644 stages/005-implement@1/prompt.md create mode 100644 stages/005-implement@1/provider_used.json create mode 100644 stages/005-implement@1/response.md diff --git a/run.json b/run.json index 41e773926..4a74a0c4f 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-25T21:46:56.213905Z", + "last_event_at": "2026-05-25T22:25:11.875226Z", "pending_control": null, "checkpoints": [ { @@ -672,9 +672,9 @@ } }, { - "seq": 0, + "seq": 48, "checkpoint": { - "timestamp": "2026-05-25T21:49:14.363753Z", + "timestamp": "2026-05-25T21:49:17.980179Z", "current_node": "preflight_lint", "completed_nodes": [ "start", @@ -684,14 +684,98 @@ ], "node_retries": {}, "context_values": { + "command.output": "blob://sha256/12ae32cb1ec02d01eda3581b127c1fee3b0dc53572ed6baf239721a03d82e126", + "failure_class": "", + "failure_signature": "", + "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", + "graph.model_stylesheet": "\n * { model: claude-opus-4-7; }\n ", + "outcome": "succeeded", + "internal.retry_count.preflight_lint": 0, + "thread.start.current_node": "toolchain", + "internal.node_visit_count": 1, + "internal.retry_count.start": 0, "current_node": "preflight_lint", + "internal.thread_id": "preflight_compile", + "graph.rankdir": "LR", + "internal.retry_count.toolchain": 0, + "internal.fidelity": "compact", + "internal.run_id": "01KSGHHBR7DQ1RHFYKD7P46R6F", + "internal.work_dir": "/home/daytona/workspace/fabro", + "internal.retry_count.preflight_compile": 0, + "thread.preflight_compile.current_node": "preflight_lint", + "thread.toolchain.current_node": "preflight_compile" + }, + "node_outcomes": { + "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 + }, + "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 + }, + "preflight_compile": { + "status": "succeeded", + "context_updates": { + "command.output": "blob://sha256/12ae32cb1ec02d01eda3581b127c1fee3b0dc53572ed6baf239721a03d82e126" + }, + "notes": "Script completed: cargo check -q --workspace 2>&1", + "usage": null + }, + "start": { + "status": "succeeded", + "usage": null + } + }, + "next_node_id": "implement", + "git_commit_sha": "b9967be9559cab322655bc3d5371c88fecded8ae", + "node_visits": { + "start": 1, + "toolchain": 1, + "preflight_lint": 1, + "preflight_compile": 1 + } + }, + "diff": { + "summary": { + "files_changed": 0, + "additions": 0, + "deletions": 0 + } + } + }, + { + "seq": 0, + "checkpoint": { + "timestamp": "2026-05-25T22:25:11.925302Z", + "current_node": "implement", + "completed_nodes": [ + "start", + "toolchain", + "preflight_compile", + "preflight_lint", + "implement" + ], + "node_retries": {}, + "context_values": { + "current_node": "implement", "graph.rankdir": "LR", "failure_class": "", + "last_response": "Implemented the stage timing and terminal failure rollup fixes.\n\nSummary of changes:\n- Added per-input `fabro-agent::Session` timing:\n - Tracks LLM inference/stream time and tool execution time.\n - ", "thread.toolchain.current_node": "preflight_compile", "internal.node_visit_count": 1, - "internal.thread_id": "preflight_compile", + "internal.thread_id": "preflight_lint", "graph.goal": "# Plan: Fix stage timing (inference + tool) reporting\n\n## Context\n\nThe web UI's Duration popover shows `Active (inference + tools): 0ms` for every run, including agent-heavy runs that obviously did substantial LLM and tool work. Verified on `01KSE2PAVXD56N4TWNK4T5H5VA`: 10 stage.completed events and 1 run.failed event all carry `inference_time_ms: 0, tool_time_ms: 0`, even though stages like `implement@1` (94 min wall) and `simplify_opus@1` (29 min wall) were doing nothing but inference and tool calls.\n\nTwo independent bugs:\n\n1. **No production handler ever populates `Outcome.timing`.** The plumbing from `Outcome.timing` → `NodeResult` (`lib/crates/fabro-core/src/executor.rs:30-37`) → `StageTiming` → `stage.completed` props → projection → billing rollup → run.completed/failed → UI is fully wired and shipped as of #343 (2026-05-21), but `AgentHandler::execute`, `PromptHandler::execute`, `CommandHandler::execute`, and `FanInHandler` all build `Outcome::success()` and never touch `.timing`. The executor falls back to zero, and every downstream consumer faithfully aggregates zero.\n\n2. **`persist_terminal_engine_failure` and its sibling Drop-guard failure paths discard timing/billing entirely.** When the engine returns `Err` (e.g. `VisitLimitExceeded`, which is what killed the user's run), `lib/crates/fabro-workflow/src/operations/start.rs:284-308` builds a `Conclusion` via `build_conclusion_from_store`, then throws it away (`let _conclusion = ...`) and emits `WorkflowRunFailed` with `RunTiming::wall_only(...)` and `None` for billing/diff. The three Drop-guard paths (`start.rs:934`, `1001`, `1033`) do similar with `RunTiming::default()` and never even build a conclusion.\n\nGoal: stage and run events carry real per-stage `inference_time_ms` + `tool_time_ms`; engine-failure terminal events preserve the conclusion's rolled-up timing and billing.\n\n## Approach\n\n### Part A — Capture inference + tool time in handlers (Bug 1)\n\n**A1. `fabro-agent` — accumulate per-input timing in `Session`**\n\n`lib/crates/fabro-agent/src/session.rs`\n\nAdd two `Duration` accumulators to `Session` (initialised to `Duration::ZERO`):\n- `last_input_inference_duration`\n- `last_input_tool_duration`\n\nIn `process_input_with_runtime` (line 1196), zero them at entry so each call's totals are independent.\n\nIn `run_single_input` (line 1254):\n- Wrap the inference span: capture `Instant::now()` immediately before opening the stream at line 1391, and add `.elapsed()` to `last_input_inference_duration` once `response = Some(resp)` (line 1487-1490) OR when the loop exits with an error/cancellation. The whole `'streamattempts` loop counts as inference work — retries included.\n- Wrap the tool span around `execute_tool_calls` at line 1705-1719: `Instant::now()` before, accumulate `.elapsed()` after `.await`.\n\nExpose a getter:\n```rust\npub fn last_input_timing(&self) -> SessionInputTiming { ... }\n```\nwhere `SessionInputTiming { pub inference: Duration, pub tool: Duration }` is a new tiny struct in `fabro-agent`.\n\n**A2. `fabro-workflow` — thread timing through the backend boundary**\n\n`lib/crates/fabro-workflow/src/handler/agent.rs`\n\nExtend `CodergenResult::Text` with a `timing: fabro_types::StageTiming` field (wall is irrelevant — see note below). Update the few `CodergenResult::Text { ... }` constructions found by the explore agent to populate it; existing match-bindings only read `text`/`usage`/`files_touched` so they keep compiling with `..` patterns. `CodergenResult::Full(outcome)` keeps current behaviour — the outcome itself already carries any timing.\n\nNote on wall: `lib/crates/fabro-core/src/executor.rs:30-37` reads ONLY `inference_time_ms` and `tool_time_ms` out of `outcome.timing`. The wall comes from the executor's own stopwatch. So we construct `StageTiming::new(0, inference_ms, tool_ms)` and document that the wall field is ignored in this hop.\n\n`lib/crates/fabro-workflow/src/handler/llm/api.rs`\n\n- `AgentApiBackend::run` (line 1103): after `session.process_input_with_runtime(...)` returns, read `session.last_input_timing()` and set the new `timing` on `CodergenResult::Text` at line 1094.\n- `AgentApiBackend::one_shot` (line 994): wrap the `complete_one_shot_request` call at line 1053 with `Instant::now()` / `.elapsed()`. Accumulate across repair iterations of the surrounding loop. All of it counts as inference; no tool work happens in `one_shot`. Set `timing` on `CodergenResult::Text` at line 1094.\n\n`lib/crates/fabro-workflow/src/handler/llm/acp.rs`\n\n`AgentAcpBackend::run` (line ~140): already exposes `result.duration_ms`. Set `timing: StageTiming::new(0, duration_ms, 0)` on the returned `CodergenResult::Text` (per user decision: attribute all ACP duration to inference; ACP is opaque about the split).\n\n**A3. Consume timing in stage handlers and set `outcome.timing`**\n\n- `lib/crates/fabro-workflow/src/handler/agent.rs:341` — after building `outcome`, before the final `Ok(outcome)`, set `outcome.timing = Some(timing_from_codergen_result)`.\n- `lib/crates/fabro-workflow/src/handler/prompt.rs:180` — same pattern.\n- `lib/crates/fabro-workflow/src/handler/fan_in.rs:266` — backend returns timing; pass it onto the outcome built from the fan-in response.\n- `lib/crates/fabro-workflow/src/handler/command.rs:175` — `outcome.timing = Some(StageTiming::new(0, 0, result.duration_ms))`. All command wall-time is tool time. `result.duration_ms` is already at line 154 in scope.\n\nOther handlers (`human`, `wait`, `conditional`, `parallel`, `start`, `exit`, `structured_output`, `manager_loop`) do no inference or tool work. Leave `outcome.timing` as `None`; the executor will naturally produce `inference: 0, tool: 0` for those stages, which is correct.\n\n### Part B — Preserve conclusion timing on engine failure (Bug 2)\n\n`lib/crates/fabro-workflow/src/operations/start.rs`\n\n**B1. Main path** (`persist_terminal_engine_failure`, line 274-308):\n- Rename `_conclusion` → `conclusion` and use it:\n - Pass `conclusion.timing` (already a `RunTiming` with the proper inference/tool/wall rollup from `build_conclusion_from_parts`) instead of `RunTiming::wall_only(...)`.\n - Pass `conclusion.billing.clone()` instead of `None` for the billing arg of `workflow_run_failed_from_error`.\n - `final_git_commit_sha`, `final_patch`, `diff_summary` stay `None` — those require the finalize-side workspace diff computation that this path deliberately skips.\n\n**B2. Drop-guard paths** (per user decision: fix them too):\n\n- `DetachedRunBootstrapGuard` (line 882-948): add an `Option` field. The bootstrap function builds the guard before the store exists, then mutates `bootstrap_guard.run_store = Some(store.clone())` once the store is in scope. On Drop, if the store is `Some`, the spawned task calls `build_conclusion_from_store` and uses its timing/billing; otherwise falls back to `RunTiming::default()` (pre-store failure means no stages can possibly exist).\n\n- `DetachedRunCompletionGuard` (line 953-1021): armed after the store exists, so add a non-optional `run_store: RunStoreHandle`. Drop's spawned task builds the conclusion and uses it.\n\n- `persist_detached_failure` (line 1023): add a `run_store: &RunStoreHandle` parameter. Call `build_conclusion_from_store` and forward `timing` + `billing` to the failure event. Update the two callers (postrun-related) to pass the store they already have in scope.\n\n`RunStoreHandle` is already `Clone` (the surrounding code clones it routinely), so move-into-spawned-task is fine.\n\n### Critical existing utilities to reuse (do not duplicate)\n\n- `fabro_types::StageTiming::new(wall, inference, tool)` and `RunTiming::new(...)` — invariant-enforcing constructors at `lib/crates/fabro-types/src/timing.rs:38, 91`.\n- `crate::millis_u64(duration)` helper for `Duration → u64` ms in `fabro-workflow` (used widely; see `lifecycle/event.rs:80-86`).\n- `build_conclusion_from_store` at `lib/crates/fabro-workflow/src/pipeline/finalize.rs:71` already does the rollup we need on the engine-failure path.\n- `billing_rollup_from_projection` (called inside `build_conclusion_from_parts`) sums per-stage timings into `RunTiming` — no need to reimplement.\n\n## Tests\n\n- **`fabro-agent` unit test**: feed `Session` a fake `LlmClient` whose `stream` sleeps a known duration and a fake tool that sleeps another known duration. Drive one `process_input_with_runtime` call. Assert `session.last_input_timing()` reports both non-zero and roughly matching the sleeps. Then call again and assert it's per-call (not cumulative).\n- **`fabro-workflow` handler tests**: in `handler/agent.rs`'s test module, wire a `CodergenBackend` that returns `CodergenResult::Text { timing: StageTiming::new(0, 200, 300), .. }` and assert `AgentHandler::execute`'s returned `Outcome.timing` carries those values. Mirror for `prompt.rs` and `fan_in.rs`. Add a `command.rs` test that mocks a `sandbox.exec_command_streaming` returning `duration_ms = 500` and asserts `outcome.timing.tool_time_ms == 500`.\n- **Executor integration**: add a test in `fabro-workflow` (or extend an existing one in `pipeline/finalize.rs` tests) that runs a tiny graph with a handler producing `Outcome.timing = Some(StageTiming::new(0, 100, 50))` and asserts the emitted `stage.completed` event carries those values, and that `run.completed` carries the summed rollup.\n- **`persist_terminal_engine_failure` test**: seed a `RunStore` with a couple of `stage.completed` events whose timing is non-zero, drive the engine-failure path, and assert the emitted `WorkflowRunFailed` event has `timing.inference_time_ms` and `tool_time_ms` matching the per-stage sum and `billing` populated.\n- **Drop guard tests**: trickier because of `Handle::try_current` + spawn. Add focused tests that arm a guard, drop it, and `tokio::task::yield_now().await` enough times to let the spawned task run, then assert the emitted failure event carries non-zero timing.\n- Run `cargo nextest run -p fabro-agent -p fabro-workflow -p fabro-store -p fabro-core`.\n- Run formatter and lints per CLAUDE.md: `cargo +nightly-2026-04-14 fmt --check --all` and `cargo +nightly-2026-04-14 clippy --workspace --all-targets -- -D warnings`.\n\n## End-to-end verification\n\n1. Build the server: `cargo build -p fabro-server`.\n2. Start server: `fabro server start`.\n3. Run a small agent-backed workflow (e.g. `fabro run repl` with a short prompt that fires at least one tool call).\n4. `fabro events --json | jq -s '[.[] | select(.event==\"stage.completed\")] | .[].properties.timing'` — confirm `inference_time_ms > 0` and `tool_time_ms > 0` for the agent stage.\n5. `fabro events --json | jq -s '[.[] | select(.event==\"run.completed\" or .event==\"run.failed\")] | .[].properties.timing'` — confirm `active_time_ms == inference_time_ms + tool_time_ms` and both are non-zero.\n6. Open the run in the web UI (start the SPA dev build per CLAUDE.md or rebuild the embedded SPA with `cargo dev build`), hover the Duration chip, confirm **Active (inference + tools)** is non-zero.\n7. For Bug 2: force an engine failure by setting a very low visit limit and rerunning the same workflow; confirm the `run.failed` event timing breakdown is non-zero and matches the per-stage sum.\n\n## Out of scope\n\n- Adding `wall_time_ms` correctness to `Outcome.timing` (executor ignores it; doc tweak only if necessary).\n- Surfacing inference vs tool split for ACP backend beyond \"all-inference\" attribution.\n- Backfilling timing for historical runs that have already emitted zero events — past events are immutable.\n- Web UI changes beyond what the existing popover already renders.\n", "internal.retry_count.start": 0, + "response.implement": "Implemented the stage timing and terminal failure rollup fixes.\n\nSummary of changes:\n- Added per-input `fabro-agent::Session` timing:\n - Tracks LLM inference/stream time and tool execution time.\n - Exposes `SessionInputTiming` via `Session::last_input_timing()`.\n - Resets timing at each `process_input_with_runtime` entry.\n- Threaded timing through workflow LLM backends:\n - `CodergenResult::Text` now carries active `StageTiming`.\n - API backend measures one-shot inference and agent-loop inference/tool time.\n - ACP backend attributes opaque duration to inference.\n- Populated `Outcome.timing` in production handlers:\n - Agent, prompt, fan-in, and command handlers now preserve active timing.\n - Command duration is reported as tool time.\n- Preserved timing/billing for terminal run failures:\n - `persist_terminal_engine_failure` now uses `build_conclusion_from_store` timing and billing.\n - Detached bootstrap/completion guards now preserve conclusion timing/billing when a store exists.\n - Detached failure helper now rolls up timing/billing from the store.\n- Added tests for:\n - Agent per-input inference/tool timing.\n - Agent/prompt/fan-in handler timing propagation.\n - Command handler tool timing.\n - Executor propagation into `NodeResult`.\n - Full workflow event rollup from `Outcome.timing` → `stage.completed` → `run.completed`.\n - Terminal engine failure and drop-guard timing/billing preservation.\n\nValidation passed:\n- `cargo nextest run -p fabro-agent -p fabro-workflow -p fabro-store -p fabro-core`\n - 1913 passed, 122 skipped\n- `cargo +nightly-2026-04-14 fmt --check --all`\n- `cargo +nightly-2026-04-14 clippy --workspace --all-targets -- -D warnings`\n- `cargo build -p fabro-server`\n- `git diff --check`\n\nI did not run the interactive/live server + UI E2E workflow steps, but the server build and full requested automated validation are green.", "failure_signature": "", "internal.work_dir": "/home/daytona/workspace/fabro", "outcome": "succeeded", @@ -699,10 +783,13 @@ "command.output": "blob://sha256/12ae32cb1ec02d01eda3581b127c1fee3b0dc53572ed6baf239721a03d82e126", "internal.retry_count.toolchain": 0, "thread.preflight_compile.current_node": "preflight_lint", + "last_stage": "implement", "internal.run_id": "01KSGHHBR7DQ1RHFYKD7P46R6F", "internal.retry_count.preflight_lint": 0, + "internal.retry_count.implement": 0, "thread.start.current_node": "toolchain", "internal.retry_count.preflight_compile": 0, + "thread.preflight_lint.current_node": "implement", "internal.fidelity": "compact" }, "node_outcomes": { @@ -718,6 +805,36 @@ "notes": "Script completed: cargo +nightly-2026-04-14 clippy -q --workspace --all-targets -- -D warnings 2>&1", "usage": null }, + "implement": { + "status": "succeeded", + "context_updates": { + "response.implement": "Implemented the stage timing and terminal failure rollup fixes.\n\nSummary of changes:\n- Added per-input `fabro-agent::Session` timing:\n - Tracks LLM inference/stream time and tool execution time.\n - Exposes `SessionInputTiming` via `Session::last_input_timing()`.\n - Resets timing at each `process_input_with_runtime` entry.\n- Threaded timing through workflow LLM backends:\n - `CodergenResult::Text` now carries active `StageTiming`.\n - API backend measures one-shot inference and agent-loop inference/tool time.\n - ACP backend attributes opaque duration to inference.\n- Populated `Outcome.timing` in production handlers:\n - Agent, prompt, fan-in, and command handlers now preserve active timing.\n - Command duration is reported as tool time.\n- Preserved timing/billing for terminal run failures:\n - `persist_terminal_engine_failure` now uses `build_conclusion_from_store` timing and billing.\n - Detached bootstrap/completion guards now preserve conclusion timing/billing when a store exists.\n - Detached failure helper now rolls up timing/billing from the store.\n- Added tests for:\n - Agent per-input inference/tool timing.\n - Agent/prompt/fan-in handler timing propagation.\n - Command handler tool timing.\n - Executor propagation into `NodeResult`.\n - Full workflow event rollup from `Outcome.timing` → `stage.completed` → `run.completed`.\n - Terminal engine failure and drop-guard timing/billing preservation.\n\nValidation passed:\n- `cargo nextest run -p fabro-agent -p fabro-workflow -p fabro-store -p fabro-core`\n - 1913 passed, 122 skipped\n- `cargo +nightly-2026-04-14 fmt --check --all`\n- `cargo +nightly-2026-04-14 clippy --workspace --all-targets -- -D warnings`\n- `cargo build -p fabro-server`\n- `git diff --check`\n\nI did not run the interactive/live server + UI E2E workflow steps, but the server build and full requested automated validation are green.", + "last_stage": "implement", + "last_response": "Implemented the stage timing and terminal failure rollup fixes.\n\nSummary of changes:\n- Added per-input `fabro-agent::Session` timing:\n - Tracks LLM inference/stream time and tool execution time.\n - " + }, + "notes": "Stage completed: implement", + "usage": { + "input": { + "usage": { + "model": { + "provider": "openai", + "model_id": "gpt-5.5" + }, + "tokens": { + "input_tokens": 2811275, + "output_tokens": 9602, + "reasoning_tokens": 9372, + "cache_read_tokens": 6235136, + "cache_write_tokens": 0 + } + }, + "facts": { + "algorithm": "openai" + } + }, + "total_usd_micros": 17743163 + } + }, "preflight_compile": { "status": "succeeded", "context_updates": { @@ -735,8 +852,9 @@ "usage": null } }, - "next_node_id": "implement", + "next_node_id": "simplify_opus", "node_visits": { + "implement": 1, "toolchain": 1, "start": 1, "preflight_compile": 1, @@ -900,7 +1018,12 @@ "first_event_seq": 41, "prompt": null, "response": null, - "completion": null, + "completion": { + "outcome": "succeeded", + "notes": "Script completed: cargo +nightly-2026-04-14 clippy -q --workspace --all-targets -- -D warnings 2>&1", + "failure_reason": null, + "timestamp": "2026-05-25T21:49:14.363192Z" + }, "provider_used": null, "diff": null, "script_invocation": { @@ -908,11 +1031,27 @@ "command": "exec 2>&1\ncargo +nightly-2026-04-14 clippy -q --workspace --all-targets -- -D warnings 2>&1", "language": "shell" }, - "script_timing": null, + "script_timing": { + "output": "blob://sha256/12ae32cb1ec02d01eda3581b127c1fee3b0dc53572ed6baf239721a03d82e126", + "exit_code": 0, + "duration_ms": 138142, + "termination": "exited", + "output_bytes": 0, + "live_streaming": false + }, "parallel_results": null, "output": null, + "output_bytes": 0, + "live_streaming": false, + "termination": "exited", "started_at": "2026-05-25T21:46:56.213623Z", "handler": "command", + "timing": { + "wall_time_ms": 138148, + "inference_time_ms": 0, + "tool_time_ms": 0, + "active_time_ms": 0 + }, "usage": { "input_tokens": 0, "output_tokens": 0, @@ -921,6 +1060,243 @@ "cache_read_tokens": 0, "cache_write_tokens": 0 }, + "state": "succeeded" + }, + "implement@1": { + "first_event_seq": 51, + "prompt": null, + "response": null, + "completion": null, + "provider_used": { + "mode": "agent", + "provider": "openai", + "model": "gpt-5.5", + "reasoning_effort": "xhigh" + }, + "diff": null, + "script_invocation": null, + "script_timing": null, + "parallel_results": null, + "output": null, + "started_at": "2026-05-25T21:49:17.981654Z", + "handler": "agent", + "usage": { + "input_tokens": 2811275, + "output_tokens": 9602, + "total_tokens": 9065385, + "reasoning_tokens": 9372, + "cache_read_tokens": 6235136, + "cache_write_tokens": 0, + "total_usd_micros": 17743163 + }, + "model": { + "provider": "openai", + "model_id": "gpt-5.5" + }, + "todos": { + "kind": "openai_plan", + "list_id": "openai_plan:ff16519a-e4b9-4109-8761-ebf3dd942afb", + "items": [ + { + "id": "62aa9afb70a148cf", + "status": "completed", + "order": 0, + "subject": "Capture per-input inference/tool timing in fabro-agent Session and expose it" + }, + { + "id": "0691b6a6e300ee04", + "status": "completed", + "order": 1, + "subject": "Thread backend timing through CodergenResult and set Outcome.timing in workflow handlers" + }, + { + "id": "ae5dbfa00f252c30", + "status": "completed", + "order": 2, + "subject": "Preserve conclusion timing/billing in terminal engine failures and detached drop-guard paths" + }, + { + "id": "a3175b949e4bab87", + "status": "completed", + "order": 3, + "subject": "Add unit/integration tests for agent timing, handlers, executor/event rollup, and failure paths" + }, + { + "id": "72b3699e42f11874", + "status": "completed", + "order": 4, + "subject": "Run requested nextest, rustfmt check, clippy, and server build validation" + } + ] + }, + "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": false + }, + { + "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": false + }, + { + "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": 145859, + "usage_percent": 53.62463235294118, + "count_method": "response_usage_scaled_breakdown", + "staleness": "live", + "generated_at": "2026-05-25T22:25:11.871579Z", + "event_seq": 835, + "breakdown": [ + { + "category": "system_prompt", + "tokens": 967, + "usage_percent": 0.35551470588235295 + }, + { + "category": "tools", + "tokens": 1378, + "usage_percent": 0.5066176470588235 + }, + { + "category": "memory", + "tokens": 3259, + "usage_percent": 1.1981617647058824 + }, + { + "category": "conversation", + "tokens": 140248, + "usage_percent": 51.561764705882354 + }, + { + "category": "other", + "tokens": 7, + "usage_percent": 0.002573529411764706 + } + ], + "warnings": [] + }, "state": "running" } } diff --git a/stages/004-preflight_lint@1/output.log b/stages/004-preflight_lint@1/output.log new file mode 100644 index 000000000..d87ba9545 --- /dev/null +++ b/stages/004-preflight_lint@1/output.log @@ -0,0 +1 @@ +blob://sha256/12ae32cb1ec02d01eda3581b127c1fee3b0dc53572ed6baf239721a03d82e126 \ No newline at end of file diff --git a/stages/004-preflight_lint@1/script_timing.json b/stages/004-preflight_lint@1/script_timing.json new file mode 100644 index 000000000..38bab5552 --- /dev/null +++ b/stages/004-preflight_lint@1/script_timing.json @@ -0,0 +1,8 @@ +{ + "output": "blob://sha256/12ae32cb1ec02d01eda3581b127c1fee3b0dc53572ed6baf239721a03d82e126", + "exit_code": 0, + "duration_ms": 138142, + "termination": "exited", + "output_bytes": 0, + "live_streaming": false +} \ No newline at end of file diff --git a/stages/004-preflight_lint@1/status.json b/stages/004-preflight_lint@1/status.json new file mode 100644 index 000000000..a585d8abf --- /dev/null +++ b/stages/004-preflight_lint@1/status.json @@ -0,0 +1,6 @@ +{ + "outcome": "succeeded", + "notes": "Script completed: cargo +nightly-2026-04-14 clippy -q --workspace --all-targets -- -D warnings 2>&1", + "failure_reason": null, + "timestamp": "2026-05-25T21:49:14.363192Z" +} \ No newline at end of file diff --git a/stages/005-implement@1/prompt.md b/stages/005-implement@1/prompt.md new file mode 100644 index 000000000..71223ea52 --- /dev/null +++ b/stages/005-implement@1/prompt.md @@ -0,0 +1,135 @@ +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) + + +Read the plan file referenced in the goal and implement every step. Make all the code changes described in the plan. Use red/green TDD. \ No newline at end of file diff --git a/stages/005-implement@1/provider_used.json b/stages/005-implement@1/provider_used.json new file mode 100644 index 000000000..c57772db6 --- /dev/null +++ b/stages/005-implement@1/provider_used.json @@ -0,0 +1,6 @@ +{ + "mode": "agent", + "provider": "openai", + "model": "gpt-5.5", + "reasoning_effort": "xhigh" +} \ No newline at end of file diff --git a/stages/005-implement@1/response.md b/stages/005-implement@1/response.md new file mode 100644 index 000000000..a364eb92e --- /dev/null +++ b/stages/005-implement@1/response.md @@ -0,0 +1,35 @@ +Implemented the stage timing and terminal failure rollup fixes. + +Summary of changes: +- Added per-input `fabro-agent::Session` timing: + - Tracks LLM inference/stream time and tool execution time. + - Exposes `SessionInputTiming` via `Session::last_input_timing()`. + - Resets timing at each `process_input_with_runtime` entry. +- Threaded timing through workflow LLM backends: + - `CodergenResult::Text` now carries active `StageTiming`. + - API backend measures one-shot inference and agent-loop inference/tool time. + - ACP backend attributes opaque duration to inference. +- Populated `Outcome.timing` in production handlers: + - Agent, prompt, fan-in, and command handlers now preserve active timing. + - Command duration is reported as tool time. +- Preserved timing/billing for terminal run failures: + - `persist_terminal_engine_failure` now uses `build_conclusion_from_store` timing and billing. + - Detached bootstrap/completion guards now preserve conclusion timing/billing when a store exists. + - Detached failure helper now rolls up timing/billing from the store. +- Added tests for: + - Agent per-input inference/tool timing. + - Agent/prompt/fan-in handler timing propagation. + - Command handler tool timing. + - Executor propagation into `NodeResult`. + - Full workflow event rollup from `Outcome.timing` → `stage.completed` → `run.completed`. + - Terminal engine failure and drop-guard timing/billing preservation. + +Validation passed: +- `cargo nextest run -p fabro-agent -p fabro-workflow -p fabro-store -p fabro-core` + - 1913 passed, 122 skipped +- `cargo +nightly-2026-04-14 fmt --check --all` +- `cargo +nightly-2026-04-14 clippy --workspace --all-targets -- -D warnings` +- `cargo build -p fabro-server` +- `git diff --check` + +I did not run the interactive/live server + UI E2E workflow steps, but the server build and full requested automated validation are green. \ No newline at end of file