Public: anyone can read this; the crew can change it.
An agent run's log says how long the run took to its first push, when its pull opens #5751
Check · Review · Land · Live done — Landed and live in production.
scout/forge:scout/3780-an-agent-run-s-log-says-how-long-the-run → main 1 commit fork
4 files
changed +46
−4
src/apps/timing.ts +7 −3
| @@ -38,10 +38,14 @@ export class Stopwatch { | ||
| 38 | 38 | /** |
| 39 | 39 | * `timing: <what> 0.4s after the deploy started — turn 0.0s · checkout |
| 40 | 40 | * 0.3s · …`, every lap so far in the order it was taken. `since` names |
| 41 | * the start in the line's words; a run says "the run started". | |
| 41 | * the start in the line's words; a run says "the run started". `running` | |
| 42 | * names a step not yet over, shown with the time it has taken so far. | |
| 42 | 43 | */ |
| 43 | line(what: string, since = "the deploy started"): string { | |
| 44 | const steps = this.laps.map((l) => `${l.name} ${seconds(l.ms)}`).join(" · "); | |
| 44 | line(what: string, since = "the deploy started", running?: string): string { | |
| 45 | const laps = [...this.laps]; | |
| 46 | // The step still going, counted to now without taking its lap. | |
| 47 | if (running !== undefined) laps.push({ name: running, ms: this.now() - this.last }); | |
| 48 | const steps = laps.map((l) => `${l.name} ${seconds(l.ms)}`).join(" · "); | |
| 45 | 49 | return `timing: ${what} ${seconds(this.elapsed())} after ${since}${steps === "" ? "" : ` — ${steps}`}`; |
| 46 | 50 | } |
| 47 | 51 | } |
src/crew/early.ts +9
| @@ -73,6 +73,8 @@ export interface EarlyInput { | ||
| 73 | 73 | /** A pull already stands for this work: nothing to open. */ |
| 74 | 74 | continuing: boolean; |
| 75 | 75 | intervalMs?: number; |
| 76 | /** Called once when this watcher opens the pull; a throw is logged, not raised. */ | |
| 77 | onOpened?: () => void; | |
| 76 | 78 | } |
| 77 | 79 | |
| 78 | 80 | /** |
| @@ -135,6 +137,13 @@ export function watchForPull(input: EarlyInput): EarlyPull { | ||
| 135 | 137 | ? `opened pull #${opened.value.number} at the first push, in progress` |
| 136 | 138 | : `could not open the pull early: ${JSON.stringify(opened.error)}`, |
| 137 | 139 | ); |
| 140 | if (opened.ok && input.onOpened !== undefined) { | |
| 141 | try { | |
| 142 | input.onOpened(); | |
| 143 | } catch (err) { | |
| 144 | input.write(`could not write the first-push timing: ${String(err)}`); | |
| 145 | } | |
| 146 | } | |
| 138 | 147 | }; |
| 139 | 148 | const every = input.intervalMs ?? WATCH_MS; |
| 140 | 149 | let looks = 0; |
src/crew/runner.ts +2
| @@ -1342,6 +1342,8 @@ async function work( | ||
| 1342 | 1342 | write, |
| 1343 | 1343 | variantGroup: run.variantGroup, |
| 1344 | 1344 | continuing: pullStands, |
| 1345 | onOpened: () => | |
| 1346 | write(watch.line("first push", "the run started", "harness to first push")), | |
| 1345 | 1347 | }); |
| 1346 | 1348 | let result = await invoke( |
| 1347 | 1349 | prompt, |
test/crew-run-timing.test.ts +28 −1
| @@ -5,9 +5,10 @@ | ||
| 5 | 5 | */ |
| 6 | 6 | |
| 7 | 7 | import { afterAll, beforeAll, describe, expect, test } from "bun:test"; |
| 8 | import { mkdirSync, rmSync } from "node:fs"; | |
| 8 | import { mkdirSync, rmSync, writeFileSync } from "node:fs"; | |
| 9 | 9 | import { join } from "node:path"; |
| 10 | 10 | import { assignIssue, openIssue } from "../src/actions/issues.ts"; |
| 11 | import { listPulls } from "../src/core/pulls.ts"; | |
| 11 | 12 | import { getAgent } from "../src/core/agents.ts"; |
| 12 | 13 | import { workdirFor } from "../src/crew/runner.ts"; |
| 13 | 14 | import { readRunLog } from "../src/runs/log.ts"; |
| @@ -61,6 +62,32 @@ describe("an agent run's timing line", () => { | ||
| 61 | 62 | ); |
| 62 | 63 | }, 30_000); |
| 63 | 64 | |
| 65 | test("a pull opened at the first push gets its line before the end line", async () => { | |
| 66 | rmSync(join(standIn.dataDir, "release"), { force: true }); | |
| 67 | // The stand-in lingers after its push; release it once the pull is open. | |
| 68 | const releasing = (async () => { | |
| 69 | const deadline = Date.now() + 30_000; | |
| 70 | while (Date.now() < deadline) { | |
| 71 | const open = listPulls(standIn.app.db, standIn.repo.id, { | |
| 72 | state: "open", | |
| 73 | limit: 50, | |
| 74 | }); | |
| 75 | if (open.some((p) => p.title === "Sow the beans")) break; | |
| 76 | await Bun.sleep(100); | |
| 77 | } | |
| 78 | writeFileSync(join(standIn.dataDir, "release"), ""); | |
| 79 | })(); | |
| 80 | const { run, lines, timing } = await runOn("Sow the beans", undefined, "LINGER-ME"); | |
| 81 | await releasing; | |
| 82 | expect(run.state).toBe("ok"); | |
| 83 | expect(timing).toHaveLength(2); | |
| 84 | expect(timing[0]).toMatch( | |
| 85 | /^timing: first push \d+\.\ds after the run started — clone \d+\.\ds · brief \d+\.\ds · harness to first push \d+\.\ds$/, | |
| 86 | ); | |
| 87 | expect(lines.indexOf(timing[0]!)).toBeLessThan(lines.indexOf(timing[1]!)); | |
| 88 | expect(lines.at(-1)).toBe(timing[1]!); | |
| 89 | }, 60_000); | |
| 90 | ||
| 64 | 91 | test("a run whose clone cannot be prepared still ends with the line", async () => { |
| 65 | 92 | const { run, lines, timing } = await runOn("Prune the roses", (number) => { |
| 66 | 93 | const agent = getAgent(standIn.app.db, standIn.bot.id); |
new above
offline