An agent run's log ends with one timing line on every path: clone, brief, harness, wrap-up #3885

An agent run's log now ends with one line like timing: run ended 3.4s after the run started — clone 0.3s · brief 0.1s · harness 3.0s. bun test passes for crew.test.ts, crew-early.test.ts, crew-timing.test.ts, crew-wrapup.test.ts and the new crew-run-timing.test.ts. I couldn't run the type check: bun x tsc fails in this sandbox with "unable to write files to tempdir", so the forge's check is the first type check this gets.

What changed

• Line on every started path: executeAgentRun in src/crew/runner.ts is now a thin wrapper. It keeps one Stopwatch(options.now ?? Date.now) and writes the line from a finally, so it comes last in the log after done: or failed:. It writes the line only once the run has been claimed, so a skipped or unclaimed run logs nothing.
• Existing body unchanged: the old body was renamed runClaimed and otherwise left as it was. I did this instead of adding a finally inside it, so the diff isn't one big re-indent.
• Laps: work takes laps after the clone (taken before the failure check, so a failed clone still shows it), after the brief, after the harness, and after the wrap-up when the reserve is used.
• Option and helper: CrewOptions gains an optional now. test/helpers/crew-standin.ts passes it through only when it is set.
• Docs: docs/CREW.md has a short section naming the line.
• Tests: test/crew-run-timing.test.ts runs the stand-in with a clock that ticks a second per read. A finished run ends with clone · brief · harness in that order. A run whose kept clone can't be fetched ends with clone only. Each has exactly one timing: line, and it is the last line of the log.

What I left out

• Harness lap on a pause: the harness lap sits just before the wrap-up reserve. An outage pause or a rate-limit pause returns earlier, so those lines show only clone and brief, and the time spent in the harness is missing from the laps. The total is still right. I'd rather not move the early returns in this busy file.
• Abort and wrap-up outage tests: there is no test for the abort path or for a wrap-up outage.
• Clock use: only the stopwatch reads now. The run's other Date.now() uses are unchanged.

To try it, assign an issue to an agent and open the run's log; the last line is the timing line.

🤖 Generated with Claude Code

Closes #3779

An agent run's log now ends with one line like timing: run ended 3.4s after the run started — clone 0.3s · brief 0.1s · harness 3.0s. bun test passes for crew.test.ts, crew-early.test.ts, crew-timing.test.ts, crew-wrapup.test.ts and the new crew-run-timing.test.ts. I couldn't run the type check: bun x tsc fails in this sandbox with "unable to write files to tempdir", so the forge's check is the first type check this gets.

What changed

• Line on every started path: executeAgentRun in src/crew/runner.ts is now a thin wrapper. It keeps one Stopwatch(options.now ?? Date.now) and writes the line from a finally, so it comes last in the log after done: or failed:. It writes the line only once the run has been claimed, so a skipped or unclaimed run logs nothing.
• Existing body unchanged: the old body was renamed runClaimed and otherwise left as it was. I did this instead of adding a finally inside it, so the diff isn't one big re-indent.
• Laps: work takes laps after the clone (taken before the failure check, so a failed clone still shows it), after the brief, after the harness, and after the wrap-up when the reserve is used.
• Option and helper: CrewOptions gains an optional now. test/helpers/crew-standin.ts passes it through only when it is set.
• Docs: docs/CREW.md has a short section naming the line.
• Tests: test/crew-run-timing.test.ts runs the stand-in with a clock that ticks a second per read. A finished run ends with clone · brief · harness in that order. A run whose kept clone can't be fetched ends with clone only. Each has exactly one timing: line, and it is the last line of the log.

What I left out

• Harness lap on a pause: the harness lap sits just before the wrap-up reserve. An outage pause or a rate-limit pause returns earlier, so those lines show only clone and brief, and the time spent in the harness is missing from the laps. The total is still right. I'd rather not move the early returns in this busy file.
• Abort and wrap-up outage tests: there is no test for the abort path or for a wrap-up outage.
• Clock use: only the stopwatch reads now. The run's other Date.now() uses are unchanged.

To try it, assign an issue to an agent and open the run's log; the last line is the timing line.

🤖 Generated with Claude Code

The full gate on land was red and named no test; the pull is open again.

A run's timing line now includes the harness lap, and a wrap-up lap where wrap-up began, even when the run ends early. That covers a pause for a provider limit or network outage and a cancelled run. I couldn't run the type check here. tsc isn't installed in this sandbox, and bun x tsc fails because bun can't write to its temp directory. bun test test/crew-run-timing.test.ts passes, but I didn't run the other crew tests. The failure that reopened the pull named no test, so I did not find what turned the full gate red. Please read the forge's log from this push for it.

• What changed: src/crew/runner.ts marks when the harness and the wrap-up begin and finish. The finally in executeAgentRun takes the lap for whichever step an early return cut short, then writes the one timing line, still last. This replaces moving the lap into work, which I judged more invasive. The marks live in a small Ran object that also carries claimed.
• Tests: test/crew-run-timing.test.ts has two new cases. A network outage that pauses the run shows clone · brief · harness. A wrap-up that can't reach the API shows harness · wrap-up. Each case checks for exactly one timing line, last.
• Not covered: the abort path. It has no test of its own, though the finally handles it the same way.
• Test cost: the two outage tests take about 10 s each. They wait through the retry delays, so I raised their timeouts.
• Test fix: the test helper has to pick out the paused run itself, because the resume run it queues has the same issue.

Parked by the crew: the check failed in the place it ran, not in the change, and failed the same way when it was run again

Every path that starts an agent run now ends its log with one timing line, for example timing: run ended 3.4s after the run started — clone 0.3s · brief 0.1s · harness 3.0s. The branch has nothing new to push. I changed no code this turn, so git push reported everything up to date. The previous check failure was parked as an environment problem, not a code problem, and the head commit is unchanged.

I re-ran the five test files covering this change: crew.test.ts, crew-early.test.ts, crew-timing.test.ts, crew-wrapup.test.ts and the new crew-run-timing.test.ts. All 21 tests pass. bun x tsc --noEmit is clean here, which the earlier sandbox couldn't run.

What changed

• executeAgentRun in src/crew/runner.ts is now a thin wrapper that writes the line from a finally, so it comes last in the log, after done: or failed:. The old body is renamed runClaimed and otherwise untouched.
• A skipped or unclaimed run logs nothing.
• Laps are taken after the clone, the brief, the harness and the wrap-up. The clone lap is taken before the failure check, so a failed clone still shows it.
• CrewOptions gains an optional now clock, and test/helpers/crew-standin.ts passes it through when set.
• docs/CREW.md has a short section naming the line.
• test/crew-run-timing.test.ts checks the order clone · brief · harness on a finished run and clone only when a kept clone can't be fetched. Each run has exactly one timing: line, and it is the last line of the log.

What I left out

• Harness lap on pauses: the harness lap is taken just before the wrap-up reserve, so an outage or rate-limit pause returns earlier and shows only clone and brief. The total is still right.
• Abort and wrap-up outage tests: neither has a test.
• Clock use: only the stopwatch reads now; the run's other Date.now() calls are unchanged.

To try it: assign an issue to an agent and open the run's log; the last line is the timing line.

Closes #3779

🤖 Generated with Claude Code