Public: anyone can read this; the crew can change it.

Sentinel: queue:agent was degraded 31 minutes today: The agent queue has waited over 30 minutes: 7 queued, 0 of 2 slots running. #9465

Merged opened this

Check · Review · Land · Live done — Landed and live in production.

Merged

scout/forge:scout/9403-sentinel-queue-agent-was-degraded-31-min → main 7 commits fork 3 threads · 3 unresolved

  • Merged. scout/9403-sentinel-queue-agent-was-degraded-31-min was merged into main as 6e3760b.

Review

Sign in to review this change.
10 files changed +274 −11
AGENTS.md +2
@@ -13,3 +13,5 @@ A new terminal screen offered only to site admins exports its palette `entry` fr
1313 A new read of a table that grows (`event`, `issue`, `run`, `comment`) names the index it walks, in the migration that adds it, and a test shows it from the query plan (`test/hot-reads-indexed.test.ts` is the pattern): no `SCAN`, no `TEMP B-TREE`. Judge by plan or row count, never the clock. A read that stays slow with the best index is a summary table, kept as the rows change, before it is a worker.
1414
1515 A new `/settings…` page route goes in `src/http/settings_routes.ts` (`settingsRoutes`), not `src/http/server.ts`.
16
17 State shared between modules through process memory, not the database, is named here. `src/runs/held.ts`: each dispatcher pass (`src/crew/dispatch.ts`, `pump`) records which queued agent runs it held and why (valve, pace, limit), and vitals (`src/kernel/vitals.ts`) leaves those out of `queue:agent`. A record older than `HELD_FRESH_MS` is ignored, so a stopped dispatcher cannot hide its queue.
src/core/runs.ts +31
@@ -1381,6 +1381,37 @@ export function queueDepth(
13811381 .all(new Date(now).toISOString());
13821382 }
13831383
1384 /**
1385 * The queued runs of one kind that may start now, weighed against the ids the
1386 * dispatcher holds on purpose (#9403): which held ids are still queued, and the
1387 * count and oldest of the rest. Two queries, however deep the queue, both on
1388 * `run_queue`: the `state IN` repeats the partial index's own condition so
1389 * SQLite may use it, and `+kind` keeps it off the per-repository agent index.
1390 */
1391 export function queuedApart(
1392 db: Database,
outdated

A limit of 500 makes the caller's row.queued - waiting wrong when more than 500 are queued. Exclude the held ids in SQL, or count held from the held map.

1393 kind: RunKind,
1394 heldIds: readonly string[],
1395 now = Date.now(),
1396 ): { held: string[]; waiting: number; oldest: string | null } {
1397 const ids = JSON.stringify(heldIds);
1398 const at = new Date(now).toISOString();
1399 const eligible = "state IN ('queued','running') AND state = 'queued' AND +kind = ?1 AND (not_before IS NULL OR not_before <= ?2)";
1400 const held = db
1401 .query<{ id: string }, [RunKind, string, string]>(
1402 `SELECT id FROM run WHERE ${eligible} AND id IN (SELECT value FROM json_each(?3))`,
1403 )
1404 .all(kind, at, ids)
1405 .map((r) => r.id);
1406 const rest = db
1407 .query<{ waiting: number; oldest: string | null }, [RunKind, string, string]>(
1408 `SELECT COUNT(*) AS waiting, MIN(created_at) AS oldest FROM run
1409 WHERE ${eligible} AND id NOT IN (SELECT value FROM json_each(?3))`,
1410 )
1411 .get(kind, at, ids)!;
1412 return { held, waiting: rest.waiting, oldest: rest.oldest };
1413 }
1414
13841415 /** Every running run with the repository and issue number it is about, in one query. */
13851416 export function listRunning(
13861417 db: Database,
src/crew/dispatch.ts +10 −3
@@ -43,6 +43,7 @@ import { resolveOpen } from "../core/decisions.ts";
4343 import { accountActive } from "../core/accounts.ts";
4444 import { runningLimitSentence, runningRuns } from "../settings/quotas.ts";
4545 import { appendRunLog } from "../runs/log.ts";
46 import { noteHeld, type HoldCause } from "../runs/held.ts";
4647 import { decideAndRecord } from "./ledger.ts";
4748 import { bugsFirst } from "../flow/bugs.ts";
4849 import { byDials } from "./team_share.ts";
@@ -1511,7 +1512,10 @@ function pump(
15111512 // Builder starts go to teams in proportion to their dials (`team_share.ts`),
15121513 // then through the valves a person turned (`flow/valve_gate.ts`).
15131514 const gated = startOrder(app);
1515 // What this pass holds by policy, for vitals (`runs/held.ts`, #9403).
1516 const held = new Map<string, HoldCause>();
15141517 for (const shut of gated.held) {
1518 held.set(shut.id, "valve");
15151519 if (noted.has(shut.id)) continue;
15161520 noted.add(shut.id);
15171521 appendRunLog(app.config.dataDir, shut.id, "queued, not started: its repository's valve is shut (/flow)");
@@ -1540,11 +1544,12 @@ function pump(
15401544 const priorityGoing =
15411545 (priorityIn.get(home.id) ?? 0) +
15421546 active.filter((r) => r.state === "running" && r.repoId === home.id && isPriorityRun(app, r, priorityMemo)).length;
1543 const held = weekHold(weekFor(app, home, new Date()), home.autonomySlots, going - priorityGoing, isPriorityRun(app, fresh, priorityMemo) ? fresh.reason : "pick", priorityGoing, paceFloor(app.db));
1544 if (held !== null) {
1547 const paced = weekHold(weekFor(app, home, new Date()), home.autonomySlots, going - priorityGoing, isPriorityRun(app, fresh, priorityMemo) ? fresh.reason : "pick", priorityGoing, paceFloor(app.db));
1548 if (paced !== null) {
1549 held.set(fresh.id, "pace");
15451550 if (!noted.has(fresh.id)) {
15461551 noted.add(fresh.id);
1547 appendRunLog(app.config.dataDir, fresh.id, held);
1552 appendRunLog(app.config.dataDir, fresh.id, paced);
15481553 }
15491554 continue;
15501555 }
@@ -1559,6 +1564,7 @@ function pump(
15591564 runningRuns(app.db, "agent", owner, [...inFlight.keys(), ...started]),
15601565 );
15611566 if (full !== undefined) {
1567 held.set(fresh.id, "limit");
15621568 if (!noted.has(fresh.id)) {
15631569 noted.add(fresh.id);
15641570 appendRunLog(app.config.dataDir, fresh.id, `queued, not started: ${full}`);
@@ -1584,4 +1590,5 @@ function pump(
15841590 .finally(() => inFlight.delete(queued.id));
15851591 inFlight.set(queued.id, running);
15861592 }
1593 noteHeld(app.db, held);
15871594 }
src/kernel/vitals.ts +33 −5
@@ -19,7 +19,9 @@ import {
1919 leaseLapsed,
2020 listRunning,
2121 queueDepth,
22 queuedApart,
2223 } from "../core/runs.ts";
24 import { HOLD_WORDS, heldRuns, type HoldCause } from "../runs/held.ts";
2325 import { STALE_AFTER_MS } from "../runs/lease.ts";
2426 import { ownRepoPath } from "./own_repo.ts";
2527 import { BUDGETS } from "./budgets.ts";
@@ -268,9 +270,17 @@ function holders(issues: (string | null)[], perIssue: boolean): number {
268270 }
269271
270272 /** What a long queue is waiting behind: how many wait, how many run, and the slots in force. */
271 function queueSentence(kind: string, queued: number, running: number, slots: number | null): string {
273 function queueSentence(
274 kind: string,
275 queued: number,
276 running: number,
277 slots: number | null,
278 held: ReadonlyMap<HoldCause, number> = new Map(),
279 ): string {
272280 const behind = slots === null ? `${running} running` : `${running} of ${slots} slots running`;
273 return `The ${kind} queue has waited over ${QUEUE_WAIT_MAX_MS / 60_000} minutes: ${queued} queued, ${behind}.`;
281 const parts = [...held].map(([cause, n]) => `${n} by ${HOLD_WORDS[cause]}`);
282 const more = parts.length > 0 ? `; held on purpose: ${parts.join(", ")}` : "";
283 return `The ${kind} queue has waited over ${QUEUE_WAIT_MAX_MS / 60_000} minutes: ${queued} queued, ${behind}${more}.`;
274284 }
275285
276286 /**
@@ -383,17 +393,35 @@ export function vitals(input: VitalsInput): Vitals {
383393 );
384394 continue;
385395 }
386 const waited = now - new Date(row.oldest).getTime();
396 // Agent runs the dispatcher holds on purpose (a shut valve, the week's
397 // pace, an account limit) are not waiting for a slot (#9403): age and
outdated

waiting is capped by the queuedOf limit, so row.queued - waiting overcounts held runs on a deep queue. Derive the held count from the holds that are still queued.

398 // "since" come from the rest, and the sentence names how many are held.
399 let waiting = row.queued;
400 let oldest: string | null = row.oldest;
401 const byCause = new Map<HoldCause, number>();
402 const holds = row.kind === "agent" ? heldRuns(input.db, now) : new Map<string, HoldCause>();
403 if (holds.size > 0) {
404 const apart = queuedApart(input.db, "agent", [...holds.keys()], now);
405 waiting = apart.waiting;
406 oldest = apart.oldest;
407 for (const id of apart.held) {
408 const cause = holds.get(id)!;
409 byCause.set(cause, (byCause.get(cause) ?? 0) + 1);
410 }
411 }
412 if (oldest === null) continue;
413 const waited = now - new Date(oldest).getTime();
387414 if (waited > QUEUE_WAIT_MAX_MS)
388415 need(
389416 `queue:${row.kind}`,
390417 queueSentence(
391418 row.kind,
392 row.queued,
419 waiting,
393420 holders(running.filter((r) => r.run.kind === row.kind).map((r) => r.run.issueId), row.kind === "agent"),
394421 row.kind === "agent" ? Number(capacityValue(input.db, "crew.concurrency")) : null,
422 byCause,
395423 ),
396 new Date(row.oldest).toISOString(),
424 new Date(oldest).toISOString(),
397425 "/settings/capacity",
398426 );
399427 }
src/looks/service.ts +1 −2
@@ -435,8 +435,7 @@ export function startLooks(app: App, options: LooksOptions): LooksHandle {
435435 if (shot.ok) {
436436 const size = shot.value.size === undefined ? {} : { size: shot.value.size };
437437 vitals.push({ look, entries: shot.value.entries, ...size });
438 }
439 else if (isNoBrowser(shot.error))
438 } else if (isNoBrowser(shot.error))
440439 vitals.push({ look, skipped: "no browser" });
441440 }
442441 const taken =
src/runs/held.ts added +46
@@ -0,0 +1,46 @@
1 /**
2 * The queued agent runs the dispatcher chose not to start on its last pass,
3 * and which policy held each: a shut valve, the week's pace, an account at its
4 * limit. Policy, not a fault: vitals leaves them out of "the agent queue has
5 * waited" and names how many each cause holds (#9403), as it leaves out the
6 * checks a red main holds.
7 *
8 * Process memory, per database, replaced whole by each dispatcher pass: the
9 * one place the dispatcher and vitals share state. A pass older than
10 * `HELD_FRESH_MS` is ignored, so a dispatcher that stopped cannot hide its
11 * queue behind the last thing it said.
12 */
13
14 import type { Database } from "bun:sqlite";
15
16 /** A dispatcher pass runs every 5 s; one not heard from in two minutes has stopped. */
17 export const HELD_FRESH_MS = 2 * 60_000;
18
19 /** Why the dispatcher held a run. */
outdated

The reason strings are stored but only the test reads them. Use them in the vitals sentence, grouped by cause, or store ids only.

20 export type HoldCause = "valve" | "pace" | "limit";
21
22 /** How vitals names each cause: "2 by a shut valve". */
23 export const HOLD_WORDS: Readonly<Record<HoldCause, string>> = {
24 valve: "a shut valve",
25 pace: "the week's pace",
26 limit: "an account limit",
27 };
28
29 interface Pass {
30 readonly at: number;
31 readonly held: ReadonlyMap<string, HoldCause>;
32 }
33
34 const passes = new WeakMap<Database, Pass>();
35
36 /** One pass's holds, replacing the last: run id → the policy that held it. */
37 export function noteHeld(db: Database, held: ReadonlyMap<string, HoldCause>, at = Date.now()): void {
38 passes.set(db, { at, held: new Map(held) });
39 }
40
41 /** The holds of the latest pass, when it is fresh; empty otherwise. */
42 export function heldRuns(db: Database, now = Date.now()): ReadonlyMap<string, HoldCause> {
43 const pass = passes.get(db);
44 if (pass === undefined || now - pass.at > HELD_FRESH_MS || pass.at - now > HELD_FRESH_MS) return new Map();
45 return pass.held;
46 }
src/web/pages/scrapes.ts +1 −1
@@ -119,7 +119,7 @@ function groupDetail(g: Group, net: NetworkTable): Html {
119119 <p class="small">${g.size} requests from ${g.addresses.length} addresses, confidence ${g.confidence}.</p>
120120 <ul class="small">${g.reasons.map((r) => html`<li>${r}</li>`)}</ul>
121121 <p class="small muted">${LIMITS}</p>
122 ${btn("Export for an abuse report", { href: `${BASE}/export?group=${g.id}`, size: "sm" })}
122 ${btn("Export for an abuse report", { href: `/settings/traffic/scrapes/export?group=${g.id}`, size: "sm" })}
123123 <div class="table-scroll">
124124 <table class="table" data-dense>
125125 <caption class="sr-only">Requests behind group ${g.id}</caption>
test/hot-reads-indexed.test.ts +7
@@ -5,6 +5,7 @@ import { tmpdir } from "node:os";
55 import { join } from "node:path";
66 import { createApp, type App } from "../src/app.ts";
77 import { listEvents } from "../src/core/events.ts";
8 import { queuedApart } from "../src/core/runs.ts";
89 import { closedByReview, reviewedClosed } from "../src/core/gate_hold.ts";
910 import { askToLiveByPillar } from "../src/core/pillars.ts";
1011
@@ -75,3 +76,9 @@ test("whether the Later gate review closed an issue reads the event index, not t
7576 expect(many.join("\n")).toContain("SEARCH e USING");
7677 noScan(many);
7778 });
79
80 test("the queued agent runs weighed against the dispatcher's holds walk the queue index", () => {
81 const lines = plans(() => void queuedApart(app.db, "agent", ["a", "b"]));
82 expect(lines.filter((l) => l.includes("USING INDEX run_queue")).length).toBe(2);
83 noScan(lines.filter((l) => !l.startsWith("SCAN json_each")));
84 });
test/quotas-running.test.ts +3
@@ -27,6 +27,7 @@ import { createUser, type User } from "../src/core/users.ts";
2727 import { startCrew } from "../src/crew/dispatch.ts";
2828 import { serve } from "../src/http/server.ts";
2929 import { readRunLog } from "../src/runs/log.ts";
30 import { heldRuns } from "../src/runs/held.ts";
3031 import { QUOTA_KEYS, getQuota, runningLimitSentence, setQuota } from "../src/settings/quotas.ts";
3132 import { promote } from "./helpers/members.ts";
3233
@@ -443,6 +444,8 @@ echo '{"type":"result","subtype":"success","is_error":false,"result":"ok","total
443444 readRunLog(dataDir, waiting.id).lines.join("\n").includes("1 of 1 concurrent runs") ? true : undefined,
444445 );
445446 expect(count(mine, "running")).toBe(1);
447 // The pass that held it says so, for vitals (#9403).
448 expect(heldRuns(app.db).get(waiting.id)).toBe("limit");
446449
447450 const theirs = await assignTwo(alice, "orchard");
448451 await until(() => (count(theirs, "running") === 2 ? true : undefined));
test/vitals-held-agent.test.ts added +140
@@ -0,0 +1,140 @@
1 /** Agent runs the dispatcher holds on purpose are not a stalled queue (#9403). */
2
3 import { afterAll, beforeAll, expect, test } from "bun:test";
4 import { chmodSync, writeFileSync } from "node:fs";
5 import { mkdtemp, rm } from "node:fs/promises";
6 import { tmpdir } from "node:os";
7 import { join } from "node:path";
8 import { createApp, type App } from "../src/app.ts";
9 import { createRun } from "../src/core/runs.ts";
10 import { createUser } from "../src/core/users.ts";
11 import { startCrew } from "../src/crew/dispatch.ts";
12 import { turnValve } from "../src/flow/valve_store.ts";
13 import { serve } from "../src/http/server.ts";
14 import { HELD_FRESH_MS, heldRuns, noteHeld } from "../src/runs/held.ts";
15 import { QUEUE_WAIT_MAX_MS, vitals } from "../src/kernel/vitals.ts";
16
17 let dataDir: string;
18 let app: App;
19 let repoId = "";
20 let ownerId = "";
21 const roomy = () => ({ freeBytes: 100, totalBytes: 100 });
22
23 beforeAll(async () => {
24 dataDir = await mkdtemp(join(tmpdir(), "forge-vitals-held-"));
25 app = createApp({ dataDir, port: 0, disk: roomy });
26 const owner = await createUser(app.db, {
27 origin: "seed",
28 trusted: true,
29 username: "holder",
30 email: "[email protected]",
31 password: "a-good-passphrase",
32 });
33 if (!owner.ok) throw new Error(String(owner.error));
34 ownerId = owner.value.id;
35 repoId = crypto.randomUUID();
36 app.db
37 .query("INSERT INTO repo (id, owner_id, name, visibility, created_at) VALUES (?1, ?2, 'held', 'private', ?3)")
38 .run(repoId, owner.value.id, new Date().toISOString());
39 });
40
41 afterAll(async () => {
42 app.close();
43 await rm(dataDir, { recursive: true, force: true });
44 });
45
46 const agentQueue = (now: number) =>
47 vitals({ db: app.db, signals: app.signals, dataDir, disk: roomy, now }).degraded.find((d) => d.cause === "queue:agent");
48
49 test("a pass's holds are read while fresh, and forgotten once the dispatcher goes quiet", () => {
50 const at = Date.now();
51 noteHeld(app.db, new Map([["r1", "pace"]]), at);
52 expect(heldRuns(app.db, at + 1000).get("r1")).toBe("pace");
53 expect(heldRuns(app.db, at + HELD_FRESH_MS + 1).size).toBe(0);
54 noteHeld(app.db, new Map(), at);
55 expect(heldRuns(app.db, at).size).toBe(0);
56 });
57
58 test("queue:agent leaves out the runs the dispatcher holds, and names them", () => {
59 app.db.query("DELETE FROM run").run();
60 const a = createRun(app.db, { repoId, kind: "agent" });
61 const b = createRun(app.db, { repoId, kind: "agent" });
62 const later = Date.now() + 2 * QUEUE_WAIT_MAX_MS;
63
64 // Nothing said: both wait, as before.
65 noteHeld(app.db, new Map(), later);
66 expect(agentQueue(later)?.sentence).toContain("2 queued, 0 of");
67
68 // Every queued run held by policy: no stalled queue to report.
69 noteHeld(app.db, new Map([[a.id, "pace"], [b.id, "limit"]]), later);
70 expect(agentQueue(later)).toBeUndefined();
71
72 // One held, one free: the free one is the queue, the held one is named.
73 noteHeld(app.db, new Map([[a.id, "pace"]]), later);
74 const one = agentQueue(later);
75 expect(one?.sentence).toContain("1 queued, 0 of");
76 expect(one?.sentence).toContain("held on purpose: 1 by the week's pace.");
77 expect(one?.since).toBe(new Date(b.createdAt).toISOString());
78
79 // A dispatcher that stopped cannot hide its queue behind its last pass.
80 noteHeld(app.db, new Map([[a.id, "pace"], [b.id, "pace"]]), later - HELD_FRESH_MS - 1);
81 expect(agentQueue(later)?.sentence).toContain("2 queued, 0 of");
82 });
83
84 test("the held count is grouped by cause, and counts only the held runs still queued", () => {
85 app.db.query("DELETE FROM run").run();
86 const runs = Array.from({ length: 5 }, () => createRun(app.db, { repoId, kind: "agent" }));
87 const later = Date.now() + 2 * QUEUE_WAIT_MAX_MS;
88 const [a, b, c] = runs.map((r) => r.id) as [string, string, string];
89 // `gone` is held but no longer queued: it must not be counted.
90 noteHeld(app.db, new Map([[a, "valve"], [b, "valve"], [c, "limit"], ["gone", "pace"]]), later);
91 const sentence = agentQueue(later)?.sentence ?? "";
92 expect(sentence).toContain("2 queued, 0 of");
93 expect(sentence).toContain("held on purpose: 2 by a shut valve, 1 by an account limit.");
94 expect(sentence).not.toContain("pace");
95 });
96
97 test("past 500 queued, the held count and the waiting count are exact", () => {
98 app.db.query("DELETE FROM run").run();
99 const ids = Array.from({ length: 620 }, () => createRun(app.db, { repoId, kind: "agent" }).id);
100 const later = Date.now() + 2 * QUEUE_WAIT_MAX_MS;
101 noteHeld(app.db, new Map(ids.slice(0, 600).map((id) => [id, "pace" as const])), later);
102 const sentence = agentQueue(later)?.sentence ?? "";
103 expect(sentence).toContain("20 queued, 0 of");
104 expect(sentence).toContain("held on purpose: 600 by the week's pace.");
105 });
106
107 test("with the real dispatcher, every queued run held is quiet while the pass is fresh, and reports once it goes stale", async () => {
108 app.db.query("DELETE FROM run").run();
109 const servers = await serve(app);
110 const fake = join(dataDir, "fake-claude");
111 writeFileSync(fake, `#!/bin/sh\nif [ "$1" = "--version" ]; then echo "2.1.0 (fake)"; exit 0; fi\nexit 1\n`);
112 chmodSync(fake, 0o755);
113 turnValve(app.db, repoId, 0, ownerId);
114 const a = createRun(app.db, { repoId, kind: "agent" });
115 const b = createRun(app.db, { repoId, kind: "agent" });
116 const hourAgo = new Date(Date.now() - 2 * QUEUE_WAIT_MAX_MS).toISOString();
117 app.db.query("UPDATE run SET created_at = ?1 WHERE id IN (?2, ?3)").run(hourAgo, a.id, b.id);
118 const crew = await startCrew(app, {
119 forgeUrl: servers.url,
120 localUrl: servers.url,
121 binary: fake,
122 concurrency: 2,
123 budgetUsd: 1,
124 runTimeoutMs: 60_000,
125 tickMs: 20,
126 });
127 try {
128 const deadline = Date.now() + 10_000;
129 while (heldRuns(app.db).get(b.id) !== "valve" && Date.now() < deadline) await Bun.sleep(20);
130 expect(heldRuns(app.db).get(a.id)).toBe("valve");
131 expect(heldRuns(app.db).get(b.id)).toBe("valve");
132 await crew.stop();
133 const now = Date.now();
134 expect(agentQueue(now)).toBeUndefined();
135 expect(agentQueue(now + HELD_FRESH_MS + 1_000)?.sentence).toContain("2 queued, 0 of");
136 } finally {
137 await crew.stop();
138 servers.stop();
139 }
140 });

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs