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
Check · Review · Land · Live done — Landed and live in production.
mason/forge:mason/4061-sentinel-queue-check-was-degraded-75-min → main 2 commits fork
5 files
changed +206
−8
docs/APPS.md +10 −3
| @@ -416,9 +416,16 @@ can select it and hold what `egress` declares. | ||
| 416 | 416 | Checks share `FORGE_CHECKS_CONCURRENCY` slots (default `1`), and when one |
| 417 | 417 | frees, it goes to the most recently requested check waiting, not the one |
| 418 | 418 | 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. | |
| 422 | 429 | |
| 423 | 430 | ### Environment |
| 424 | 431 |
src/checks/service.ts +30 −4
| @@ -108,6 +108,12 @@ export interface ChecksOptions { | ||
| 108 | 108 | * nothing held; the forge says `RED_HOLD_MS`. |
| 109 | 109 | */ |
| 110 | 110 | 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; | |
| 111 | 117 | /** |
| 112 | 118 | * How long `stop` lets checks already running finish before it cuts them |
| 113 | 119 | * off and queues them again (#1796). Nothing new starts meanwhile. |
| @@ -156,15 +162,27 @@ export interface ChecksHandle { | ||
| 156 | 162 | readonly lane: Gate; |
| 157 | 163 | } |
| 158 | 164 | |
| 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 | ||
| 159 | 175 | /** How often queued checks another forge left are looked for. */ |
| 160 | 176 | const TICK_MS = 5_000; |
| 161 | 177 | |
| 162 | 178 | /** |
| 163 | 179 | * How long a queued check may wait before it outranks a newer one however |
| 164 | 180 | * 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. | |
| 166 | 184 | */ |
| 167 | export const STARVATION_MS = 10 * 60 * 1000; | |
| 185 | export const STARVATION_MS = BUDGETS.laneWait / 2; | |
| 168 | 186 | |
| 169 | 187 | /** |
| 170 | 188 | * 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 { | ||
| 270 | 288 | >(); |
| 271 | 289 | /** Checks already told why they wait, so the log says it once. */ |
| 272 | 290 | const waiting = new Set<string>(); |
| 291 | const settle = options.landSettleMs ?? 0; | |
| 273 | 292 | let stopped = false; |
| 274 | 293 | |
| 275 | 294 | sweepCheckouts(app); |
| @@ -281,6 +300,7 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle { | ||
| 281 | 300 | reason: string, |
| 282 | 301 | issueId?: string, |
| 283 | 302 | actorId?: string, |
| 303 | notBefore?: string, | |
| 284 | 304 | ): Promise<Run | undefined> { |
| 285 | 305 | // A suspended or removed owner's code is not run, not even to check it. |
| 286 | 306 | if (stopped || !accountActive(app.db, repo.ownerId)) return undefined; |
| @@ -336,6 +356,7 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle { | ||
| 336 | 356 | reason, |
| 337 | 357 | ...(issueId === undefined ? {} : { issueId }), |
| 338 | 358 | ...(actorId === undefined ? {} : { actorId }), |
| 359 | ...(notBefore === undefined ? {} : { notBefore }), | |
| 339 | 360 | }); |
| 340 | 361 | return { run: created, fresh: true }; |
| 341 | 362 | }); |
| @@ -402,7 +423,10 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle { | ||
| 402 | 423 | // A pull's check waits while its main is red (`checks/red_main.ts`). |
| 403 | 424 | const queued = unheld( |
| 404 | 425 | 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()), | |
| 406 | 430 | ), |
| 407 | 431 | (repoId) => redMain(app.db, repoId), |
| 408 | 432 | options.redHoldMs ?? 0, |
| @@ -1083,7 +1107,8 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle { | ||
| 1083 | 1107 | announceRun(app, run); |
| 1084 | 1108 | } |
| 1085 | 1109 | // 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. | |
| 1087 | 1112 | const mergeOid = event.payload["mergeOid"]; |
| 1088 | 1113 | if ( |
| 1089 | 1114 | event.kind === "pull.merged" && |
| @@ -1098,6 +1123,7 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle { | ||
| 1098 | 1123 | "push", |
| 1099 | 1124 | undefined, |
| 1100 | 1125 | actor, |
| 1126 | settle > 0 ? new Date(Date.now() + settle).toISOString() : undefined, | |
| 1101 | 1127 | ); |
| 1102 | 1128 | return; |
| 1103 | 1129 | } |
src/main.ts +2 −1
| @@ -31,7 +31,7 @@ import { runSync } from "./origins/sync.ts"; | ||
| 31 | 31 | import { startForgeSsh } from "./tui/ssh.ts"; |
| 32 | 32 | import { AppsRuntime } from "./apps/runtime.ts"; |
| 33 | 33 | 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"; | |
| 35 | 35 | import { RED_HOLD_MS } from "./checks/red_main.ts"; |
| 36 | 36 | import { startLooks } from "./looks/service.ts"; |
| 37 | 37 | import { startMirrorOut } from "./origins/mirror-out.ts"; |
| @@ -347,6 +347,7 @@ const checks = | ||
| 347 | 347 | // Sized to the pod's CPUs unless the environment says (#2549). |
| 348 | 348 | concurrency: positive(process.env.FORGE_CHECKS_CONCURRENCY, Number(capacityDefault("checks.concurrency"))), |
| 349 | 349 | redHoldMs: RED_HOLD_MS, |
| 350 | landSettleMs: LAND_SETTLE_MS, | |
| 350 | 351 | // A roll lets running checks finish this long before cutting them off. |
| 351 | 352 | drainMs: positive(process.env.FORGE_CHECKS_DRAIN_S, 300) * 1000, |
| 352 | 353 | }); |
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 | }); |
new above
offline