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

Sentinel: queue:check was degraded 75 minutes today: 9 checks wait behind one lane; the oldest since 04:44; the lane runs #4032 for 2 min (limit 60). #4062

Merged opened this

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

Merged

mason/forge:mason/4061-sentinel-queue-check-was-degraded-75-min → main 2 commits fork

  • Merged. mason/4061-sentinel-queue-check-was-degraded-75-min was merged into main as 31ac3e3.

Review

Sign in to review this change.
5 files changed +206 −8
docs/APPS.md +10 −3
@@ -416,9 +416,16 @@ can select it and hold what `egress` declares.
416416 Checks share `FORGE_CHECKS_CONCURRENCY` slots (default `1`), and when one
417417 frees, it goes to the most recently requested check waiting, not the one
418418 queued longest — a fresh push is never stuck behind pulls that queued hours
419 earlier. The one exception is starvation: a check that has waited ten
420 minutes to start outranks a newer one regardless, so nothing waits forever.
421 A pull's status names how long its queued check has been waiting.
419 earlier. The one exception is starvation: a check that has waited five
420 minutes to start outranks a newer one regardless, so nothing waits forever
421 and nothing waits out the lane's ten-minute budget only because it was passed
422 over.
423 A pull's status names how long its queued check has been waiting. The check
424 of the default branch that a landed pull asks for waits thirty seconds
425 before it may start: the merge queue lands a candidate's pulls seconds
426 apart, and each one's check is superseded by the next while still queued,
427 so the lane checks the head the candidate ends at, not every step on the
428 way.
422429
423430 ### Environment
424431
src/checks/service.ts +30 −4
@@ -108,6 +108,12 @@ export interface ChecksOptions {
108108 * nothing held; the forge says `RED_HOLD_MS`.
109109 */
110110 readonly redHoldMs?: number | undefined;
111 /**
112 * How long main's check after a land waits before it may start, so the
113 * steps of one candidate supersede each other while queued. @default 0,
114 * none; the forge says `LAND_SETTLE_MS`.
115 */
116 readonly landSettleMs?: number | undefined;
111117 /**
112118 * How long `stop` lets checks already running finish before it cuts them
113119 * off and queues them again (#1796). Nothing new starts meanwhile.
@@ -156,15 +162,27 @@ export interface ChecksHandle {
156162 readonly lane: Gate;
157163 }
158164
165 /**
166 * How long main's check after a land waits to start (#4061). The merge queue
167 * lands a candidate's steps seconds apart, and only its tip was gated: a
168 * step's check that started at once ran the full suite on a commit the next
169 * step replaced, up to seven of them filling the lane for nine minutes. A
170 * step's check that waits is superseded by the next while still queued, and
171 * the tip's is proven green by the gate.
172 */
173 export const LAND_SETTLE_MS = 30_000;
174
159175 /** How often queued checks another forge left are looked for. */
160176 const TICK_MS = 5_000;
161177
162178 /**
163179 * How long a queued check may wait before it outranks a newer one however
164180 * fresh: the bound that keeps `pickNext` from starving a pull nobody has
165 * pushed to in a while.
181 * pushed to in a while. Half the lane's budget (#4061): at the budget
182 * itself, every check the newest-first order passed over waited exactly
183 * long enough to make the lane a cause, even when the lane kept up.
166184 */
167 export const STARVATION_MS = 10 * 60 * 1000;
185 export const STARVATION_MS = BUDGETS.laneWait / 2;
168186
169187 /**
170188 * Which queued check takes a slot when one frees: the one requested most
@@ -270,6 +288,7 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle {
270288 >();
271289 /** Checks already told why they wait, so the log says it once. */
272290 const waiting = new Set<string>();
291 const settle = options.landSettleMs ?? 0;
273292 let stopped = false;
274293
275294 sweepCheckouts(app);
@@ -281,6 +300,7 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle {
281300 reason: string,
282301 issueId?: string,
283302 actorId?: string,
303 notBefore?: string,
284304 ): Promise<Run | undefined> {
285305 // A suspended or removed owner's code is not run, not even to check it.
286306 if (stopped || !accountActive(app.db, repo.ownerId)) return undefined;
@@ -336,6 +356,7 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle {
336356 reason,
337357 ...(issueId === undefined ? {} : { issueId }),
338358 ...(actorId === undefined ? {} : { actorId }),
359 ...(notBefore === undefined ? {} : { notBefore }),
339360 });
340361 return { run: created, fresh: true };
341362 });
@@ -402,7 +423,10 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle {
402423 // A pull's check waits while its main is red (`checks/red_main.ts`).
403424 const queued = unheld(
404425 listActive(app.db, "check").filter(
405 (run) => run.state === "queued" && !inFlight.has(run.id),
426 (run) =>
427 run.state === "queued" &&
428 !inFlight.has(run.id) &&
429 (run.notBefore === null || Date.parse(run.notBefore) <= Date.now()),
406430 ),
407431 (repoId) => redMain(app.db, repoId),
408432 options.redHoldMs ?? 0,
@@ -1083,7 +1107,8 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle {
10831107 announceRun(app, run);
10841108 }
10851109 // A land moves the default branch without a push event: check its
1086 // new head, or a red main stays red until someone pushes to it.
1110 // new head, or a red main stays red until someone pushes to it. The
1111 // check settles first: a candidate's next step supersedes it.
10871112 const mergeOid = event.payload["mergeOid"];
10881113 if (
10891114 event.kind === "pull.merged" &&
@@ -1098,6 +1123,7 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle {
10981123 "push",
10991124 undefined,
11001125 actor,
1126 settle > 0 ? new Date(Date.now() + settle).toISOString() : undefined,
11011127 );
11021128 return;
11031129 }
src/main.ts +2 −1
@@ -31,7 +31,7 @@ import { runSync } from "./origins/sync.ts";
3131 import { startForgeSsh } from "./tui/ssh.ts";
3232 import { AppsRuntime } from "./apps/runtime.ts";
3333 import { resolveAppDomain } from "./apps/host.ts";
34 import { requeueAbandonedChecks, startChecks } from "./checks/service.ts";
34 import { LAND_SETTLE_MS, requeueAbandonedChecks, startChecks } from "./checks/service.ts";
3535 import { RED_HOLD_MS } from "./checks/red_main.ts";
3636 import { startLooks } from "./looks/service.ts";
3737 import { startMirrorOut } from "./origins/mirror-out.ts";
@@ -347,6 +347,7 @@ const checks =
347347 // Sized to the pod's CPUs unless the environment says (#2549).
348348 concurrency: positive(process.env.FORGE_CHECKS_CONCURRENCY, Number(capacityDefault("checks.concurrency"))),
349349 redHoldMs: RED_HOLD_MS,
350 landSettleMs: LAND_SETTLE_MS,
350351 // A roll lets running checks finish this long before cutting them off.
351352 drainMs: positive(process.env.FORGE_CHECKS_DRAIN_S, 300) * 1000,
352353 });
test/check-land-settle.test.ts added +104
@@ -0,0 +1,104 @@
1 /**
2 * A merge-queue candidate lands its steps seconds apart, and each landing
3 * asks for a check of main (#4061). The check settles before it may start,
4 * so the next step supersedes it while still queued: the lane runs main's
5 * newest head, not every step the candidate passed through.
6 */
7 import { afterAll, beforeAll, expect, test } from "bun:test";
8 import { mkdtemp, rm } from "node:fs/promises";
9 import { tmpdir } from "node:os";
10 import { join } from "node:path";
11 import { createApp, type App } from "../src/app.ts";
12 import { mergePull, openPull } from "../src/actions/pulls.ts";
13 import { commitToBranch, createRepo } from "../src/actions/repos.ts";
14 import { startChecks, type ChecksHandle } from "../src/checks/service.ts";
15 import { listRuns, type Run } from "../src/core/runs.ts";
16 import { createUser, type User } from "../src/core/users.ts";
17 import type { Repo } from "../src/core/repos.ts";
18 import { serve, type Servers } from "../src/http/server.ts";
19
20 let dataDir: string;
21 let app: App;
22 let servers: Servers;
23 let checks: ChecksHandle;
24 let alice: User;
25 let repo: Repo;
26
27 const checkJson = (run: string): string =>
28 `{"check": {"run": ${JSON.stringify(run)}, "install": ""}}\n`;
29
30 async function finished(where: (r: Run) => boolean): Promise<Run> {
31 const deadline = Date.now() + 30_000;
32 while (Date.now() < deadline) {
33 const run = listRuns(app.db, repo.id, { kind: "check", limit: 50 }).find(where);
34 if (run && (run.state === "ok" || run.state === "failed")) return run;
35 await Bun.sleep(50);
36 }
37 throw new Error("check did not settle");
38 }
39
40 beforeAll(async () => {
41 dataDir = await mkdtemp(join(tmpdir(), "forge-land-settle-"));
42 app = createApp({ dataDir, port: 0 });
43 servers = await serve(app);
44 checks = startChecks(app, { forgeUrl: servers.url, concurrency: 2, landSettleMs: 1_500 });
45 const a = await createUser(app.db, {
46 origin: "seed",
47 trusted: true,
48 username: "alice",
49 email: "[email protected]",
50 password: "a-good-passphrase",
51 adminIfFirst: true,
52 });
53 if (!a.ok) throw new Error(a.error);
54 alice = a.value;
55 const made = await createRepo(app, alice, { name: "lib", visibility: "public" });
56 if (!made.ok) throw new Error(String(made.error));
57 repo = made.value;
58 });
59
60 afterAll(async () => {
61 await checks.stop();
62 servers.stop();
63 app.close();
64 await rm(dataDir, { recursive: true, force: true });
65 });
66
67 async function pullOf(branch: string, file: string) {
68 const branched = await commitToBranch(app, alice, repo, {
69 branch,
70 message: `Add ${file}`,
71 files: [{ path: file, content: "ok\n" }],
72 });
73 if (!branched.ok) throw new Error(JSON.stringify(branched.error));
74 const opened = await openPull(app, alice, repo, { title: file, baseBranch: "main", headBranch: branch });
75 if (!opened.ok) throw new Error(String(opened.error));
76 return opened.value;
77 }
78
79 test("two landings seconds apart: the first step's main check is superseded before it starts", async () => {
80 const declared = await commitToBranch(app, alice, repo, {
81 message: "Declare a check",
82 files: [{ path: "forge.json", content: checkJson("true") }],
83 });
84 if (!declared.ok) throw new Error(JSON.stringify(declared.error));
85 await finished((r) => r.commitOid === declared.value.commitOid);
86
87 const one = await pullOf("one", "ONE.md");
88 const two = await pullOf("two", "TWO.md");
89 const first = await mergePull(app, alice, repo, one, "merge");
90 if (!first.ok) throw new Error(JSON.stringify(first.error));
91 const second = await mergePull(app, alice, repo, two, "merge");
92 if (!second.ok) throw new Error(JSON.stringify(second.error));
93
94 const tip = await finished((r) => r.commitOid === second.value.mergeOid);
95 expect(tip).toMatchObject({ env: "main", issueId: null, state: "ok" });
96 const step = listRuns(app.db, repo.id, { kind: "check", limit: 50 }).find(
97 (r) => r.commitOid === first.value.mergeOid,
98 );
99 expect(step).toMatchObject({
100 state: "cancelled",
101 startedAt: null,
102 summary: `superseded by ${second.value.mergeOid.slice(0, 7)}`,
103 });
104 }, 60_000);
test/lane-wait.test.ts added +60
@@ -0,0 +1,60 @@
1 /**
2 * The lane's order against the lane's budget (#4061): `pickNext` serves the
3 * newest check first, and a check passed over long enough outranks it. When
4 * that bound was the budget itself, a lane that kept up still made every
5 * passed-over check wait just past ten minutes, and `queue:check` was
6 * degraded for it. Plain data: runs are ids and queue times, the clock is a
7 * number.
8 */
9
10 import { describe, expect, test } from "bun:test";
11 import { STARVATION_MS, pickNext } from "../src/checks/service.ts";
12 import type { Run } from "../src/core/runs.ts";
13 import { BUDGETS } from "../src/kernel/budgets.ts";
14
15 const MIN = 60_000;
16 const T0 = Date.parse("2026-10-21T04:30:00.000Z");
17
18 /**
19 * The longest any check waited to start, in ms: `slots` checks of
20 * `serviceMs` each at once, `backlog` queued at the start and one more every
21 * `everyMs`, the lane filled from `pickNext` once a second.
22 */
23 function worstWait(backlog: number, everyMs: number, slots: number, serviceMs: number): number {
24 let seq = 0;
25 const queue = (at: number): Run =>
26 ({ id: String(seq++).padStart(6, "0"), createdAt: new Date(at).toISOString() }) as Run;
27 let queued = Array.from({ length: backlog }, () => queue(T0));
28 let busy: number[] = [];
29 let arrival = T0 + everyMs;
30 let worst = 0;
31 for (let now = T0; now <= T0 + 90 * MIN; now += 1_000) {
32 for (; arrival <= now; arrival += everyMs) queued.push(queue(arrival));
33 busy = busy.filter((until) => until > now);
34 while (busy.length < slots) {
35 const run = pickNext(queued, now);
36 if (run === undefined) break;
37 queued = queued.filter((r) => r !== run);
38 worst = Math.max(worst, now - Date.parse(run.createdAt));
39 busy.push(now + serviceMs);
40 }
41 }
42 return worst;
43 }
44
45 describe("the lane's order and its budget", () => {
46 test("a passed-over check outranks the newest well before the lane's budget", () => {
47 expect(STARVATION_MS).toBeLessThanOrEqual(BUDGETS.laneWait / 2);
48 });
49
50 test("a lane that keeps up never makes a check wait past its budget", () => {
51 // 21 Oct, 04:30: seven slots, four-minute checks, nine queued and one more
52 // every 36 s. The lane cleared it, and the oldest waited 12 minutes.
53 expect(worstWait(9, 36_000, 7, 4 * MIN)).toBeLessThan(BUDGETS.laneWait);
54 expect(worstWait(9, 40_000, 7, 4 * MIN)).toBeLessThan(BUDGETS.laneWait);
55 });
56
57 test("an idle lane starts a check at once", () => {
58 expect(worstWait(0, 40_000, 7, 4 * MIN)).toBe(0);
59 });
60 });

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs