Public: anyone can read this; the crew can change it.
Sentinel: queue:check is past its budget: 14 checks wait behind one lane; the oldest since 01:41; the lane runs #3910 for 0 min (limit 60). #3999
Check · Review · Land · Live done — Landed and live in production.
mason/forge:mason/3946-sentinel-queue-check-is-past-its-budget → main 2 commits fork
2 files
changed +154
−11
src/checks/red_main.ts +89 −10
| @@ -174,25 +174,104 @@ export function heldChecks(db: Database): { red: RedMain; held: number }[] { | ||
| 174 | 174 | return out; |
| 175 | 175 | } |
| 176 | 176 | |
| 177 | /** A main that was red and is green again: when its last red and its green finished. */ | |
| 178 | export interface Release { | |
| 179 | readonly redAt: string; | |
| 180 | readonly greenAt: string; | |
| 181 | } | |
| 182 | ||
| 183 | /** | |
| 184 | * The id of `q`'s repository's last finished default-branch check, older | |
| 185 | * than `below` when given: a constant of this module, never input. | |
| 186 | */ | |
| 187 | const mainBefore = (below: string): string => `( | |
| 188 | SELECT r.id FROM run r JOIN repo m ON m.id = r.repo_id | |
| 189 | WHERE r.repo_id = q.repo_id AND r.kind = 'check' | |
| 190 | AND r.issue_id IS NULL AND r.env = m.default_branch | |
| 191 | AND r.state IN ('ok', 'failed') ${below} | |
| 192 | ORDER BY r.id DESC LIMIT 1)`; | |
| 193 | ||
| 194 | /** The last two finished main checks, as `toRelease` reads them. */ | |
| 195 | interface ReleaseRow { | |
| 196 | last_state: string | null; | |
| 197 | green_at: string | null; | |
| 198 | prev_state: string | null; | |
| 199 | prev_summary: string | null; | |
| 200 | red_at: string | null; | |
| 201 | } | |
| 202 | ||
| 203 | /** | |
| 204 | * The repository's last turn from red to green: its default branch's last | |
| 205 | * finished check passed and the one before it failed by a test (a limit | |
| 206 | * holds nothing, so releases nothing). | |
| 207 | */ | |
| 208 | function toRelease(row: ReleaseRow): Release | undefined { | |
| 209 | if ( | |
| 210 | row.last_state !== "ok" || | |
| 211 | row.prev_state !== "failed" || | |
| 212 | LIMIT.test(row.prev_summary ?? "") || | |
| 213 | row.green_at === null || | |
| 214 | row.red_at === null | |
| 215 | ) | |
| 216 | return undefined; | |
| 217 | return { redAt: row.red_at, greenAt: row.green_at }; | |
| 218 | } | |
| 219 | ||
| 220 | /** | |
| 221 | * Since when a queued check has waited for the lane (#3946): its queue time, | |
| 222 | * unless the last red main held it — then the moment the hold ended, at the | |
| 223 | * green or at `holdMs` after it was queued, whichever came first. Fourteen | |
| 224 | * checks a red main held for twenty minutes, freed at once by the green, | |
| 225 | * have not waited twenty minutes behind the lane. | |
| 226 | */ | |
| 227 | export function laneSince( | |
| 228 | run: { readonly issueId: string | null; readonly reason: string; readonly createdAt: string }, | |
| 229 | release: Release | undefined, | |
| 230 | holdMs: number, | |
| 231 | ): string { | |
| 232 | if (release === undefined || run.issueId === null || run.reason === ASKED) return run.createdAt; | |
| 233 | const queued = Date.parse(run.createdAt); | |
| 234 | const green = Date.parse(release.greenAt); | |
| 235 | // Queued after the green, or its hold over before the red: never held. | |
| 236 | if (queued >= green || queued + holdMs <= Date.parse(release.redAt)) return run.createdAt; | |
| 237 | return new Date(Math.min(green, queued + holdMs)).toISOString(); | |
| 238 | } | |
| 239 | ||
| 177 | 240 | /** |
| 178 | 241 | * The queued checks no red main holds (startable now): how many, and the |
| 179 | * oldest one's queue time. A held check's age says nothing about the lane. | |
| 242 | * oldest one's `laneSince`. A held check's age says nothing about the lane, | |
| 243 | * and nor does the time a released one spent held. | |
| 180 | 244 | */ |
| 181 | 245 | export function freeChecks( |
| 182 | 246 | db: Database, |
| 183 | 247 | redRepoIds: readonly string[], |
| 184 | 248 | now: number, |
| 249 | holdMs: number = RED_HOLD_MS, | |
| 185 | 250 | ): { n: number; oldest: string | null } { |
| 186 | const row = db | |
| 187 | .query<{ n: number; oldest: string | null }, [string, string]>( | |
| 188 | `SELECT COUNT(*) AS n, MIN(created_at) AS oldest FROM run | |
| 189 | WHERE state = 'queued' AND kind = 'check' | |
| 190 | AND (not_before IS NULL OR not_before <= ?1) | |
| 191 | AND NOT (issue_id IS NOT NULL AND reason <> '${ASKED}' | |
| 192 | AND repo_id IN (SELECT value FROM json_each(?2)))`, | |
| 251 | const rows = db | |
| 252 | .query<ReleaseRow & { issue_id: string | null; reason: string; created_at: string }, [string, string]>( | |
| 253 | `SELECT q.issue_id, q.reason, q.created_at, | |
| 254 | last.state AS last_state, last.finished_at AS green_at, | |
| 255 | prev.state AS prev_state, prev.summary AS prev_summary, prev.finished_at AS red_at | |
| 256 | FROM run q | |
| 257 | LEFT JOIN run last ON last.id = ${mainBefore("")} | |
| 258 | LEFT JOIN run prev ON prev.id = ${mainBefore("AND r.id < last.id")} | |
| 259 | WHERE q.state = 'queued' AND q.kind = 'check' | |
| 260 | AND (q.not_before IS NULL OR q.not_before <= ?1) | |
| 261 | AND NOT (q.issue_id IS NOT NULL AND q.reason <> '${ASKED}' | |
| 262 | AND q.repo_id IN (SELECT value FROM json_each(?2)))`, | |
| 193 | 263 | ) |
| 194 | .get(new Date(now).toISOString(), JSON.stringify(redRepoIds)); | |
| 195 | return row ?? { n: 0, oldest: null }; | |
| 264 | .all(new Date(now).toISOString(), JSON.stringify(redRepoIds)); | |
| 265 | let oldest: string | null = null; | |
| 266 | for (const row of rows) { | |
| 267 | const since = laneSince( | |
| 268 | { issueId: row.issue_id, reason: row.reason, createdAt: row.created_at }, | |
| 269 | toRelease(row), | |
| 270 | holdMs, | |
| 271 | ); | |
| 272 | if (oldest === null || Date.parse(since) < Date.parse(oldest)) oldest = since; | |
| 273 | } | |
| 274 | return { n: rows.length, oldest }; | |
| 196 | 275 | } |
| 197 | 276 | |
| 198 | 277 | /** |
test/red-main.test.ts +65 −1
| @@ -9,7 +9,7 @@ import { tmpdir } from "node:os"; | ||
| 9 | 9 | import { migrations } from "../src/core/schema.ts"; |
| 10 | 10 | import { openDb } from "../src/kernel/db.ts"; |
| 11 | 11 | import { claimRun, createRun, finishRun, listActive, type Run } from "../src/core/runs.ts"; |
| 12 | import { RED_HOLD_MS, heldChecks, redHref, redMain, redSentence, sharedWithMain, unheld } from "../src/checks/red_main.ts"; | |
| 12 | import { RED_HOLD_MS, heldChecks, laneSince, redHref, redMain, redSentence, sharedWithMain, unheld } from "../src/checks/red_main.ts"; | |
| 13 | 13 | import { coveredByRedFix } from "../src/crew/red_fix.ts"; |
| 14 | 14 | import { budgetBreaches, findFaults } from "../src/crew/sentinel.ts"; |
| 15 | 15 | import { redLines } from "../src/crew/notify.ts"; |
| @@ -238,6 +238,70 @@ describe("the lane sentence and a red main", () => { | ||
| 238 | 238 | expect(causes).toContain("red:r1"); |
| 239 | 239 | expect(causes).not.toContain("queue:check"); |
| 240 | 240 | }); |
| 241 | ||
| 242 | // #3946: main went green at 01:52, freeing 14 checks it had held since 01:38; | |
| 243 | // the lane started them that second and was blamed for their twenty minutes. | |
| 244 | const ago = (min: number) => new Date(Date.now() - min * 60_000).toISOString(); | |
| 245 | const at = (run: Run, column: "created_at" | "finished_at", min: number) => | |
| 246 | db.run(`UPDATE run SET ${column} = ?2 WHERE id = ?1`, [run.id, ago(min)]); | |
| 247 | ||
| 248 | test("checks a red main held, freed by the green a moment ago: the lane is not blamed", () => { | |
| 249 | at(main("b", "failed", ["x"]), "finished_at", 18); | |
| 250 | const held = [pullCheck("1"), pullCheck("2"), pullCheck("3")]; | |
| 251 | held.forEach((r) => at(r, "created_at", 15)); | |
| 252 | main("c", "ok"); | |
| 253 | expect(read().map((d) => d.cause)).not.toContain("queue:check"); | |
| 254 | }); | |
| 255 | ||
| 256 | test("freed checks still waiting long after the green: the lane is a cause, since the green", () => { | |
| 257 | at(main("b", "failed", ["x"]), "finished_at", 40); | |
| 258 | const held = [pullCheck("1"), pullCheck("2")]; | |
| 259 | held.forEach((r) => at(r, "created_at", 35)); | |
| 260 | const green = main("c", "ok"); | |
| 261 | at(green, "finished_at", 25); | |
| 262 | const lane = read().find((d) => d.cause === "queue:check"); | |
| 263 | expect(lane?.since.slice(0, 16)).toBe(ago(25).slice(0, 16)); | |
| 264 | expect(lane?.sentence).toStartWith(`2 checks wait behind one lane; the oldest since ${ago(25).slice(11, 16)};`); | |
| 265 | }); | |
| 266 | ||
| 267 | test("a check held past the hold waits for the lane from the hold's end, not the green", () => { | |
| 268 | at(main("b", "failed", ["x"]), "finished_at", 60); | |
| 269 | at(pullCheck("1"), "created_at", 50); | |
| 270 | at(main("c", "ok"), "finished_at", 2); | |
| 271 | const lane = read().find((d) => d.cause === "queue:check"); | |
| 272 | expect(lane?.sentence).toContain(`the oldest since ${ago(50 - HOLD / 60_000).slice(11, 16)};`); | |
| 273 | }); | |
| 274 | ||
| 275 | test("an asked check, never held, keeps its whole wait after a red and a green", () => { | |
| 276 | at(main("b", "failed", ["x"]), "finished_at", 18); | |
| 277 | at(pullCheck("1", "asked"), "created_at", 15); | |
| 278 | main("c", "ok"); | |
| 279 | expect(read().map((d) => d.cause)).toContain("queue:check"); | |
| 280 | }); | |
| 281 | ||
| 282 | test("a check queued after the green, or long before the red, keeps its queue time", () => { | |
| 283 | const release = { redAt: "2026-10-21T01:38:00.000Z", greenAt: "2026-10-21T01:52:00.000Z" }; | |
| 284 | const check = (createdAt: string) => ({ issueId: pull, reason: "push", createdAt }); | |
| 285 | expect(laneSince(check("2026-10-21T01:53:00.000Z"), release, HOLD)).toBe("2026-10-21T01:53:00.000Z"); | |
| 286 | expect(laneSince(check("2026-10-21T01:00:00.000Z"), release, HOLD)).toBe("2026-10-21T01:00:00.000Z"); | |
| 287 | expect(laneSince(check("2026-10-21T01:41:00.000Z"), release, HOLD)).toBe(release.greenAt); | |
| 288 | expect(laneSince({ ...check("2026-10-21T01:41:00.000Z"), issueId: null }, release, HOLD)).toBe( | |
| 289 | "2026-10-21T01:41:00.000Z", | |
| 290 | ); | |
| 291 | }); | |
| 292 | ||
| 293 | test("a main green twice, or red by a limit before its green, freed nothing: the wait counts whole", () => { | |
| 294 | at(main("b", "failed", ["x"]), "finished_at", 18); | |
| 295 | at(pullCheck("1"), "created_at", 15); | |
| 296 | main("c", "ok"); | |
| 297 | expect(read().map((d) => d.cause)).not.toContain("queue:check"); | |
| 298 | main("d", "ok"); | |
| 299 | expect(read().map((d) => d.cause)).toContain("queue:check"); | |
| 300 | const stopped = main("e", "failed"); | |
| 301 | db.run("UPDATE run SET summary = 'check failed: budget: check took 61 min, limit 60' WHERE id = ?1", [stopped.id]); | |
| 302 | main("f", "ok"); | |
| 303 | expect(read().map((d) => d.cause)).toContain("queue:check"); | |
| 304 | }); | |
| 241 | 305 | }); |
| 242 | 306 | |
| 243 | 307 | describe("a red main in another repository (#3992)", () => { |
new above
offline