a026576 · a486ade
@@ -34,6 +34,10 @@
Nesting a sandbox is not possible there, so `test/crew-sandbox.test.ts` checks
the settings that enforce it (`allowLocalBinding` on, `allowAllUnixSockets` off,
the `denyRead` list) and not the boundary itself.
## Where a run's time went
Every run that started ends its log with one `timing: run ended …s after the run started — clone … · brief … · harness …` line (plus `wrap-up` when the reserve was used), whatever way it ended; `src/apps/timing.ts` draws it.
## The sentinel (#1131)
The forge hunts its own faults. `src/crew/sentinel.ts` runs on the autonomy
@@ -29,6 +29,7 @@
import {
} from "./early.ts";
import { forkRepo, sealedForkFor } from "../actions/repos.ts";
import { announceRun } from "../actions/runs.ts";
import { Stopwatch } from "../apps/timing.ts";
import { previewEnv } from "../apps/data.ts";
import { appsRuntime } from "../apps/runtime.ts";
import { ownApp, ownAppUrls } from "./app_hosts.ts";
@@ -172,6 +173,8 @@
export interface CrewOptions {
  readonly sandboxNote?: string | undefined;
  /** Milliseconds between the crew's ticks; tests pass a small one. @default 5000 */
  readonly tickMs?: number | undefined;
  /** The clock a run's timing line reads; tests pass a fake. @default Date.now */
  readonly now?: (() => number) | undefined;
}
export { crewRoot, workdirFor } from "./workdir.ts";
@@ -286,6 +289,13 @@
export function settleReview(
    : { state: "ok", summary: `reviewed: ${verdict.state.replace("_", " ")}` };
}
/** How far a run got, for the timing line an early return would cut short. */
interface Ran {
  claimed: boolean;
  inHarness: boolean;
  inWrapUp: boolean;
}
/**
 * Claim and execute a queued agent run. Never throws. A run the provider
 * turned away ends cancelled with a `paused:` summary and returns when its
@@ -295,6 +305,31 @@
export async function executeAgentRun(
  app: App,
  run: Run,
  options: CrewOptions,
): Promise<Pause | undefined> {
  const watch = new Stopwatch(options.now ?? Date.now);
  const began = { claimed: false, inHarness: false, inWrapUp: false };
  try {
    return await runClaimed(app, run, options, watch, began);
  } finally {
    // The log's last line, on every path that started: where the time went.
    // A step an early return cut short still owns the time it held.
    if (began.inHarness) watch.lap("harness");
    if (began.inWrapUp) watch.lap("wrap-up");
    if (began.claimed)
      appendRunLog(
        app.config.dataDir,
        run.id,
        watch.line("run ended", "the run started"),
      );
  }
}
async function runClaimed(
  app: App,
  run: Run,
  options: CrewOptions,
  watch: Stopwatch,
  began: Ran,
): Promise<Pause | undefined> {
  // A follow-up queued behind a run that has since answered everything:
  // nothing new to act on, so nothing starts (`guard.ts`).
@@ -311,6 +346,7 @@
export async function executeAgentRun(
  }
  const claimed = claimRun(app.db, run.id);
  if (!claimed) return undefined;
  began.claimed = true;
  const lease = holdLease(app.db, run.id);
  // A resolve run keeps the head it started from, to tell a push from none.
  const startedAt =
@@ -349,6 +385,8 @@
export async function executeAgentRun(
      write,
      controller.signal,
      meter,
      watch,
      began,
    );
  } catch (error) {
    log.error("agent run threw", { run: run.id, error: String(error) });
@@ -744,6 +782,8 @@
async function work(
  write: (line: string) => void,
  signal: AbortSignal,
  meter: Meter,
  watch: Stopwatch,
  ran: Ran,
): Promise<Outcome> {
  const began = new Date().toISOString();
  const repo = getRepoById(app.db, run.repoId);
@@ -901,6 +941,7 @@
async function work(
      signal,
      run.attempt > 0,
    );
    watch.lap("clone");
    if (!prepared.ok) return { state: "failed", summary: prepared.error };
    // What the agent is told.
@@ -1256,6 +1297,8 @@
async function work(
      write(
        `sandbox: off here${options.sandboxNote === undefined ? "" : ` — ${options.sandboxNote}`}; the shell runs unrestricted`,
      );
    watch.lap("brief");
    ran.inHarness = true;
    const working = budget - reserve;
    if (!reviewing)
      early = watchForPull({
@@ -1439,6 +1482,8 @@
async function work(
      limitLifts = resumeAt(result.result, new Date());
    }
    watch.lap("harness");
    ran.inHarness = false;
    // The reserve: the same session gets one more turn, to land what exists
    // rather than to keep working. Its ending is the run's ending, with the
    // whole spend; the pull says where the work stopped.
@@ -1450,6 +1495,7 @@
async function work(
      Date.now() < deadline
    ) {
      stoppedAt = result.costUsd;
      ran.inWrapUp = true;
      write(`claude: wrapping up with the reserve, $${reserve.toFixed(2)}`);
      const wrapped = await retrying(
        await invoke(wrapUpPrompt(), reserve, result.sessionId),
@@ -1474,6 +1520,8 @@
async function work(
        turns: result.turns + wrapped.turns,
      };
      noteRunProgress(app.db, run.id, { costUsd: result.costUsd });
      watch.lap("wrap-up");
      ran.inWrapUp = false;
    }
    if (signal.aborted)
      return {
@@ -0,0 +1,100 @@
/**
 * An agent run's log ends with one `timing:` line: where the run's time went,
 * lap by lap, on the path that started it — a finished run and a failed
 * clone alike. A clock that ticks a second per read makes the laps exact.
 */
import { afterAll, beforeAll, describe, expect, test } from "bun:test";
import { mkdirSync, rmSync } from "node:fs";
import { join } from "node:path";
import { assignIssue, openIssue } from "../src/actions/issues.ts";
import { getAgent } from "../src/core/agents.ts";
import { workdirFor } from "../src/crew/runner.ts";
import { readRunLog } from "../src/runs/log.ts";
import {
  agentRunSettled,
  startStandInCrew,
  stopStandInCrew,
  type StandInCrew,
} from "./helpers/crew-standin.ts";
describe("an agent run's timing line", () => {
  let standIn: StandInCrew;
  let ticks = 0;
  beforeAll(async () => {
    standIn = await startStandInCrew({ now: () => 1_000 * ticks++ });
  }, 30_000);
  afterAll(() => stopStandInCrew(standIn));
  async function runOn(
    title: string,
    prepare?: (n: number) => void,
    body = "Do it.",
    paused = false,
  ) {
    const { app, alice, bot, repo } = standIn;
    const issue = openIssue(app, alice, repo, { title, body });
    if (!issue.ok) throw new Error(String(issue.error));
    prepare?.(issue.value.number);
    expect(assignIssue(app, alice, repo, issue.value, bot).ok).toBe(true);
    const run = await agentRunSettled(
      app,
      repo,
      (r) =>
        r.issueId === issue.value.id &&
        (!paused || r.summary.startsWith("paused:")),
      60_000,
    );
    const lines = readRunLog(standIn.dataDir, run.id).lines;
    return { run, lines, timing: lines.filter((l) => l.startsWith("timing:")) };
  }
  test("a finished run ends with the laps in order", async () => {
    const { run, lines, timing } = await runOn("Water the ferns");
    expect(run.state).toBe("ok");
    expect(timing).toHaveLength(1);
    expect(lines.at(-1)).toBe(timing[0]!);
    expect(timing[0]!).toMatch(
      /^timing: run ended \d+\.\ds after the run started — clone \d+\.\ds · brief \d+\.\ds · harness \d+\.\ds$/,
    );
  }, 30_000);
  test("a run whose clone cannot be prepared still ends with the line", async () => {
    const { run, lines, timing } = await runOn("Prune the roses", (number) => {
      const agent = getAgent(standIn.app.db, standIn.bot.id);
      if (!agent) throw new Error("no agent");
      // A `.git` that is no repository: the fetch of a kept clone fails.
      mkdirSync(
        join(
          workdirFor(standIn.app.config.dataDir, agent, standIn.repo, number),
          ".git",
        ),
        { recursive: true },
      );
    });
    expect(run.state).toBe("failed");
    expect(timing).toHaveLength(1);
    expect(lines.at(-1)).toBe(timing[0]!);
    expect(timing[0]!).toMatch(/after the run started — clone \d+\.\ds$/);
  }, 30_000);
  test("a run paused by an outage keeps its harness lap, one line last", async () => {
    const { run, lines, timing } = await runOn("Network out", undefined, "NET-DOWN", true);
    expect(run.state).toBe("cancelled");
    expect(timing).toHaveLength(1);
    expect(lines.at(-1)).toBe(timing[0]!);
    expect(timing[0]!).toMatch(/clone \d+\.\ds · brief \d+\.\ds · harness \d+\.\ds$/);
    rmSync(join(standIn.dataDir, "down"), { force: true });
  }, 90_000);
  test("a wrap-up outage keeps the harness and wrap-up laps, one line last", async () => {
    const { run, lines, timing } = await runOn("Wrap down", undefined, "WRAP-DOWN", true);
    expect(run.state).toBe("cancelled");
    expect(timing).toHaveLength(1);
    expect(lines.at(-1)).toBe(timing[0]!);
    expect(timing[0]!).toMatch(/harness \d+\.\ds · wrap-up \d+\.\ds$/);
    rmSync(join(standIn.dataDir, "wrapdown"), { force: true });
  }, 90_000);
});
@@ -43,7 +43,11 @@
export interface StandInCrew {
/** A forge with checks and a crew whose Claude Code is the stand-in. */
export async function startStandInCrew(
  options: { readonly reviewBudgetMs?: number; readonly tickMs?: number } = {},
  options: {
    readonly reviewBudgetMs?: number;
    readonly tickMs?: number;
    readonly now?: () => number;
  } = {},
): Promise<StandInCrew> {
  const dataDir = await mkdtemp(join(tmpdir(), "forge-crew-"));
  const app = createApp({ dataDir, port: 0 });
@@ -179,6 +183,7 @@
echo '{"type":"result","subtype":"success","is_error":false,"result":"Added CREW
    networkRetryScale: 0,
    reviewBudgetMs: options.reviewBudgetMs ?? 4_000,
    ...(options.tickMs === undefined ? {} : { tickMs: options.tickMs }),
    ...(options.now === undefined ? {} : { now: options.now }),
  });
  const a = await createUser(app.db, {
    origin: "seed",
		@@ -34,6 +34,10 @@ Nesting a sandbox is not possible there, so `test/crew-sandbox.test.ts` checks
34	34	the settings that enforce it (`allowLocalBinding` on, `allowAllUnixSockets` off,
35	35	the `denyRead` list) and not the boundary itself.
36	36
	37	## Where a run's time went
	38
	39	Every run that started ends its log with one `timing: run ended …s after the run started — clone … · brief … · harness …` line (plus `wrap-up` when the reserve was used), whatever way it ended; `src/apps/timing.ts` draws it.
	40
37	41	## The sentinel (#1131)
38	42
39	43	The forge hunts its own faults. `src/crew/sentinel.ts` runs on the autonomy
		@@ -29,6 +29,7 @@ import {
29	29	} from "./early.ts";
30	30	import { forkRepo, sealedForkFor } from "../actions/repos.ts";
31	31	import { announceRun } from "../actions/runs.ts";
	32	import { Stopwatch } from "../apps/timing.ts";
32	33	import { previewEnv } from "../apps/data.ts";
33	34	import { appsRuntime } from "../apps/runtime.ts";
34	35	import { ownApp, ownAppUrls } from "./app_hosts.ts";
		@@ -172,6 +173,8 @@ export interface CrewOptions {
172	173	readonly sandboxNote?: string \| undefined;
173	174	/** Milliseconds between the crew's ticks; tests pass a small one. @default 5000 */
174	175	readonly tickMs?: number \| undefined;
	176	/** The clock a run's timing line reads; tests pass a fake. @default Date.now */
	177	readonly now?: (() => number) \| undefined;
175	178	}
176	179
177	180	export { crewRoot, workdirFor } from "./workdir.ts";
		@@ -286,6 +289,13 @@ export function settleReview(
286	289	: { state: "ok", summary: `reviewed: ${verdict.state.replace("_", " ")}` };
287	290	}
288	291
	292	/** How far a run got, for the timing line an early return would cut short. */
	293	interface Ran {
	294	claimed: boolean;
	295	inHarness: boolean;
	296	inWrapUp: boolean;
	297	}
	298
289	299	/**
290	300	* Claim and execute a queued agent run. Never throws. A run the provider
291	301	* turned away ends cancelled with a `paused:` summary and returns when its
		@@ -295,6 +305,31 @@ export async function executeAgentRun(
295	305	app: App,
296	306	run: Run,
297	307	options: CrewOptions,
	308	): Promise<Pause \| undefined> {
	309	const watch = new Stopwatch(options.now ?? Date.now);
	310	const began = { claimed: false, inHarness: false, inWrapUp: false };
	311	try {
	312	return await runClaimed(app, run, options, watch, began);
	313	} finally {
	314	// The log's last line, on every path that started: where the time went.
	315	// A step an early return cut short still owns the time it held.
	316	if (began.inHarness) watch.lap("harness");
	317	if (began.inWrapUp) watch.lap("wrap-up");
	318	if (began.claimed)
	319	appendRunLog(
	320	app.config.dataDir,
	321	run.id,
	322	watch.line("run ended", "the run started"),
	323	);
	324	}
	325	}
	326
	327	async function runClaimed(
	328	app: App,
	329	run: Run,
	330	options: CrewOptions,
	331	watch: Stopwatch,
	332	began: Ran,
298	333	): Promise<Pause \| undefined> {
299	334	// A follow-up queued behind a run that has since answered everything:
300	335	// nothing new to act on, so nothing starts (`guard.ts`).
		@@ -311,6 +346,7 @@ export async function executeAgentRun(
311	346	}
312	347	const claimed = claimRun(app.db, run.id);
313	348	if (!claimed) return undefined;
	349	began.claimed = true;
314	350	const lease = holdLease(app.db, run.id);
315	351	// A resolve run keeps the head it started from, to tell a push from none.
316	352	const startedAt =
		@@ -349,6 +385,8 @@ export async function executeAgentRun(
349	385	write,
350	386	controller.signal,
351	387	meter,
	388	watch,
	389	began,
352	390	);
353	391	} catch (error) {
354	392	log.error("agent run threw", { run: run.id, error: String(error) });
		@@ -744,6 +782,8 @@ async function work(
744	782	write: (line: string) => void,
745	783	signal: AbortSignal,
746	784	meter: Meter,
	785	watch: Stopwatch,
	786	ran: Ran,
747	787	): Promise<Outcome> {
748	788	const began = new Date().toISOString();
749	789	const repo = getRepoById(app.db, run.repoId);
		@@ -901,6 +941,7 @@ async function work(
901	941	signal,
902	942	run.attempt > 0,
903	943	);
	944	watch.lap("clone");
904	945	if (!prepared.ok) return { state: "failed", summary: prepared.error };
905	946
906	947	// What the agent is told.
		@@ -1256,6 +1297,8 @@ async function work(
1256	1297	write(
1257	1298	`sandbox: off here${options.sandboxNote === undefined ? "" : ` — ${options.sandboxNote}`}; the shell runs unrestricted`,
1258	1299	);
	1300	watch.lap("brief");
	1301	ran.inHarness = true;
1259	1302	const working = budget - reserve;
1260	1303	if (!reviewing)
1261	1304	early = watchForPull({
		@@ -1439,6 +1482,8 @@ async function work(
1439	1482	limitLifts = resumeAt(result.result, new Date());
1440	1483	}
1441	1484
	1485	watch.lap("harness");
	1486	ran.inHarness = false;
1442	1487	// The reserve: the same session gets one more turn, to land what exists
1443	1488	// rather than to keep working. Its ending is the run's ending, with the
1444	1489	// whole spend; the pull says where the work stopped.
		@@ -1450,6 +1495,7 @@ async function work(
1450	1495	Date.now() < deadline
1451	1496	) {
1452	1497	stoppedAt = result.costUsd;
	1498	ran.inWrapUp = true;
1453	1499	write(`claude: wrapping up with the reserve, $${reserve.toFixed(2)}`);
1454	1500	const wrapped = await retrying(
1455	1501	await invoke(wrapUpPrompt(), reserve, result.sessionId),
		@@ -1474,6 +1520,8 @@ async function work(
1474	1520	turns: result.turns + wrapped.turns,
1475	1521	};
1476	1522	noteRunProgress(app.db, run.id, { costUsd: result.costUsd });
	1523	watch.lap("wrap-up");
	1524	ran.inWrapUp = false;
1477	1525	}
1478	1526	if (signal.aborted)
1479	1527	return {
		@@ -0,0 +1,100 @@
	1	/**
	2	* An agent run's log ends with one `timing:` line: where the run's time went,
	3	* lap by lap, on the path that started it — a finished run and a failed
	4	* clone alike. A clock that ticks a second per read makes the laps exact.
	5	*/
	6
	7	import { afterAll, beforeAll, describe, expect, test } from "bun:test";
	8	import { mkdirSync, rmSync } from "node:fs";
	9	import { join } from "node:path";
	10	import { assignIssue, openIssue } from "../src/actions/issues.ts";
	11	import { getAgent } from "../src/core/agents.ts";
	12	import { workdirFor } from "../src/crew/runner.ts";
	13	import { readRunLog } from "../src/runs/log.ts";
	14	import {
	15	agentRunSettled,
	16	startStandInCrew,
	17	stopStandInCrew,
	18	type StandInCrew,
	19	} from "./helpers/crew-standin.ts";
	20
	21	describe("an agent run's timing line", () => {
	22	let standIn: StandInCrew;
	23	let ticks = 0;
	24
	25	beforeAll(async () => {
	26	standIn = await startStandInCrew({ now: () => 1_000 * ticks++ });
	27	}, 30_000);
	28
	29	afterAll(() => stopStandInCrew(standIn));
	30
	31	async function runOn(
	32	title: string,
	33	prepare?: (n: number) => void,
	34	body = "Do it.",
	35	paused = false,
	36	) {
	37	const { app, alice, bot, repo } = standIn;
	38	const issue = openIssue(app, alice, repo, { title, body });
	39	if (!issue.ok) throw new Error(String(issue.error));
	40	prepare?.(issue.value.number);
	41	expect(assignIssue(app, alice, repo, issue.value, bot).ok).toBe(true);
	42	const run = await agentRunSettled(
	43	app,
	44	repo,
	45	(r) =>
	46	r.issueId === issue.value.id &&
	47	(!paused \|\| r.summary.startsWith("paused:")),
	48	60_000,
	49	);
	50	const lines = readRunLog(standIn.dataDir, run.id).lines;
	51	return { run, lines, timing: lines.filter((l) => l.startsWith("timing:")) };
	52	}
	53
	54	test("a finished run ends with the laps in order", async () => {
	55	const { run, lines, timing } = await runOn("Water the ferns");
	56	expect(run.state).toBe("ok");
	57	expect(timing).toHaveLength(1);
	58	expect(lines.at(-1)).toBe(timing[0]!);
	59	expect(timing[0]!).toMatch(
	60	/^timing: run ended \d+\.\ds after the run started — clone \d+\.\ds · brief \d+\.\ds · harness \d+\.\ds$/,
	61	);
	62	}, 30_000);
	63
	64	test("a run whose clone cannot be prepared still ends with the line", async () => {
	65	const { run, lines, timing } = await runOn("Prune the roses", (number) => {
	66	const agent = getAgent(standIn.app.db, standIn.bot.id);
	67	if (!agent) throw new Error("no agent");
	68	// A `.git` that is no repository: the fetch of a kept clone fails.
	69	mkdirSync(
	70	join(
	71	workdirFor(standIn.app.config.dataDir, agent, standIn.repo, number),
	72	".git",
	73	),
	74	{ recursive: true },
	75	);
	76	});
	77	expect(run.state).toBe("failed");
	78	expect(timing).toHaveLength(1);
	79	expect(lines.at(-1)).toBe(timing[0]!);
	80	expect(timing[0]!).toMatch(/after the run started — clone \d+\.\ds$/);
	81	}, 30_000);
	82
	83	test("a run paused by an outage keeps its harness lap, one line last", async () => {
	84	const { run, lines, timing } = await runOn("Network out", undefined, "NET-DOWN", true);
	85	expect(run.state).toBe("cancelled");
	86	expect(timing).toHaveLength(1);
	87	expect(lines.at(-1)).toBe(timing[0]!);
	88	expect(timing[0]!).toMatch(/clone \d+\.\ds · brief \d+\.\ds · harness \d+\.\ds$/);
	89	rmSync(join(standIn.dataDir, "down"), { force: true });
	90	}, 90_000);
	91
	92	test("a wrap-up outage keeps the harness and wrap-up laps, one line last", async () => {
	93	const { run, lines, timing } = await runOn("Wrap down", undefined, "WRAP-DOWN", true);
	94	expect(run.state).toBe("cancelled");
	95	expect(timing).toHaveLength(1);
	96	expect(lines.at(-1)).toBe(timing[0]!);
	97	expect(timing[0]!).toMatch(/harness \d+\.\ds · wrap-up \d+\.\ds$/);
	98	rmSync(join(standIn.dataDir, "wrapdown"), { force: true });
	99	}, 90_000);
	100	});
		@@ -43,7 +43,11 @@ export interface StandInCrew {
43	43
44	44	/** A forge with checks and a crew whose Claude Code is the stand-in. */
45	45	export async function startStandInCrew(
46		options: { readonly reviewBudgetMs?: number; readonly tickMs?: number } = {},
	46	options: {
	47	readonly reviewBudgetMs?: number;
	48	readonly tickMs?: number;
	49	readonly now?: () => number;
	50	} = {},
47	51	): Promise<StandInCrew> {
48	52	const dataDir = await mkdtemp(join(tmpdir(), "forge-crew-"));
49	53	const app = createApp({ dataDir, port: 0 });
		@@ -179,6 +183,7 @@ echo '{"type":"result","subtype":"success","is_error":false,"result":"Added CREW
179	183	networkRetryScale: 0,
180	184	reviewBudgetMs: options.reviewBudgetMs ?? 4_000,
181	185	...(options.tickMs === undefined ? {} : { tickMs: options.tickMs }),
	186	...(options.now === undefined ? {} : { now: options.now }),
182	187	});
183	188	const a = await createUser(app.db, {
184	189	origin: "seed",