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

URGENT: the merge queue has landed nothing since the 18:54 boot - 33 approved pulls 'queued', no gate running #3436

Merged opened this in answer to

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

Merged

mason/forge:mason/3430-urgent-the-merge-queue-has-landed-nothin → main 4 commits fork 2 threads · 2 unresolved

  • Merged. mason/3430-urgent-the-merge-queue-has-landed-nothin was merged into main as fc09b1b.

Review

Sign in to review this change.
6 files changed +194 −20
README.md +10 −2
@@ -1087,6 +1087,10 @@ word) and `issue.parked = 1` carries it, so raw SQL never reads it as done.
10871087 its repository's queue (`src/checks/queue.ts`). The queue builds one
10881088 candidate: main, then each queued pull's squash on top of the one before, in
10891089 queue order, leaving out any pull that conflicts or has nothing left to land.
1090 A candidate carries at most eight pulls (`MAX_CANDIDATE`), so a gate stays
1091 near one full tier and a red bisects in three; the rest wait their turn.
1092 The log says `[queue] gating N pulls since HH:MM` as a gate starts and
1093 `[queue] gated N pulls: green|red|cut off` as it ends.
10901094 The full gate runs once on that candidate. Green lands every pull in order,
10911095 and each landing is refused unless main is still where the candidate was
10921096 built and the squash writes the tree that was gated, so main ends at the
@@ -1096,7 +1100,9 @@ waits for a push or a new main, except once: after 30 minutes with neither
10961100 side moved it is gated again, and lands if green; a red that reproduces
10971101 stays red and is not told twice. A gate cut off by the forge stopping (a
10981102 roll, a drain) or by the cluster losing its Job is no red at all: the next
1099 sweep gates it again. Pulls
1103 sweep gates it again. So is a gate that has not answered in 15 minutes
1104 (`GATE_DEADLINE_MS`): it is abandoned and its check aborted, the log says
1105 `[queue] candidate abandoned`, and the next sweep forms the line again. Pulls
11001106 that turn green while a candidate is gating wait for the next one. Each
11011107 queue's numbers — how many pulls are queued, how many are gating, and how
11021108 many landed in the last hour — show in three places: the flow panel on `/boards`, the
@@ -1110,7 +1116,9 @@ own first; the batch lands in one gate. A pull's own check runs again only
11101116 when its head changes. A person's merge, which no candidate gated, still
11111117 refuses a stale green. The autonomy tick line counts the approved pulls the
11121118 last sweep saw and why each waits (`approved="3 approved: queued=2 review=1"`,
1113 from `src/crew/waits.ts`).
1119 from `src/crew/waits.ts`), and what the queue is doing now
1120 (`queue="gating 2 pulls since 18:54"`, `queue="1 waiting"` or `queue=idle`,
1121 in UTC).
11141122
11151123 An autonomous app's planner is **held** while nothing is landing or the plate
11161124 is full: no pull has merged in 48 h while one was closed unmerged, or more than
src/checks/landing.ts +3 −1
@@ -35,6 +35,7 @@ import { ownProbeHeaders } from "../kernel/probe.ts";
3535 * pull with its base, or the merge queue's candidate of several (#2036).
3636 * `pull` is the one the gate is asked for: where the objects are and which
3737 * base branch's check is run. The manifest is the candidate's own.
38 * `signal` is the queue abandoning the gate at its deadline (#3430).
3839 */
3940 export async function gateCandidate(
4041 app: App,
@@ -42,6 +43,7 @@ export async function gateCandidate(
4243 pull: Pull,
4344 dir: string,
4445 commitOid: string,
46 signal?: AbortSignal,
4547 ): Promise<LandVerdict> {
4648 const checks = checksFor(app);
4749 if (checks === undefined) return { lands: true };
@@ -52,7 +54,7 @@ export async function gateCandidate(
5254 const declared = parseCheck(forgeJson, packageJson);
5355 if (!declared.ok || declared.value === undefined || declared.value.fast === null)
5456 return { lands: true };
55 const done = await checks.gate(repo, pull, commitOid);
57 const done = await checks.gate(repo, pull, commitOid, signal);
5658 // Cut off, not judged: no verdict, and not the gate log a red reads (#3155).
5759 if (done.interrupted === true) return { lands: false, interrupted: true };
5860 keepForgeGate(app.config.dataDir, app.config.forgeRepo, `${repo.ownerName}/${repo.name}`, done.lines);
src/checks/queue.ts +111 −11
@@ -10,7 +10,10 @@
1010 * search in the first half while the rest waits for the next candidate. A
1111 * single red step is the culprit and is handed back. A gate cut off by the
1212 * forge stopping is no verdict: nothing is handed back, and the forge that
13 * carries on admits the line again (#3155).
13 * carries on admits the line again (#3155). A gate that has not answered
14 * by `GATE_DEADLINE_MS` is abandoned the same way: cut off, logged, and the
15 * line re-formed by the next sweep, so one gate that never returns cannot
16 * hold the queue for good (#3430).
1417 *
1518 * What is queued is not stored: it is the pulls `landIfGreen` admitted, and
1619 * every sweep admits them again. The queue only orders them and remembers
@@ -67,8 +70,38 @@ export interface Candidate {
6770 readonly treeOid: string;
6871 }
6972
70 /** Gate a candidate: the full tier on its tip. */
71 export type GateCandidate = (candidate: Candidate) => Promise<LandVerdict>;
73 /**
74 * Gate a candidate: the full tier on its tip. `signal` aborts when the
75 * queue abandons the gate at its deadline: what it started should stop.
76 */
77 export type GateCandidate = (candidate: Candidate, signal: AbortSignal) => Promise<LandVerdict>;
78
79 /**
80 * How long a candidate's gate may run before the queue abandons it (#3430):
81 * twice the forge's full tier. Past it the gate is no verdict, as a gate the
82 * forge stopping cut off is not (#3155).
83 */
84 export const GATE_DEADLINE_MS = 15 * 60_000;
85
86 let deadlineMs = GATE_DEADLINE_MS;
87
88 /**
89 * The most pulls one candidate carries (#3430): eight keep a gate near one
90 * full tier and a red's bisection three gates deep. The rest of the line
91 * waits for the next candidate, in order.
92 */
93 export const MAX_CANDIDATE = 8;
94
95 /** Tests shorten the deadline; the answer puts it back. */
96 export function gateDeadlineForTest(ms: number): () => void {
97 deadlineMs = ms;
98 return () => {
99 deadlineMs = GATE_DEADLINE_MS;
100 };
101 }
102
103 /** The gate as a round asks it: the deadline is the line's own. */
104 type Gated = (candidate: Candidate) => Promise<LandVerdict>;
72105
73106 interface Waiting {
74107 readonly entry: Queued;
@@ -76,11 +109,14 @@ interface Waiting {
76109 }
77110
78111 interface Line {
112 readonly repoId: string;
79113 waiting: Waiting[];
80114 /** Pull ids in the queue or its candidate: a pull is in the line once. */
81115 readonly holds: Set<string>;
82116 /** How many pulls the candidate at the gate now carries. */
83117 gating: number;
118 /** When the candidate at the gate started, epoch ms; 0 when none is. */
119 since: number;
84120 /** The gate runs this line has made, for a test and the log. */
85121 gates: number;
86122 draining: boolean;
@@ -100,7 +136,7 @@ const IDENTITY = {
100136 function lineOf(repoId: string): Line {
101137 let line = lines.get(repoId);
102138 if (line === undefined) {
103 line = { waiting: [], holds: new Set(), gating: 0, gates: 0, draining: false };
139 line = { repoId, waiting: [], holds: new Set(), gating: 0, since: 0, gates: 0, draining: false };
104140 lines.set(repoId, line);
105141 }
106142 return line;
@@ -139,6 +175,8 @@ export interface QueueStatus {
139175 readonly repoId: string;
140176 readonly queued: number;
141177 readonly gating: number;
178 /** When the candidate at the gate started, epoch ms; 0 when none is. */
179 readonly since: number;
142180 }
143181
144182 export function queueStatus(): QueueStatus[] {
@@ -147,10 +185,39 @@ export function queueStatus(): QueueStatus[] {
147185 repoId,

since is added to QueueStatus but no caller reads it. Surface it on the flow panel and in tty, or remove it.

148186 queued: line.waiting.length,
149187 gating: line.gating,
188 since: line.since,
150189 }))
151190 .filter((s) => s.queued > 0 || s.gating > 0);
152191 }
153192
193 /**
194 * The repository's line in a few words, for the tick line (#3430):
195 * `gating 4 pulls since 18:54` (UTC), `2 waiting`, both, or `idle`.
196 */
197 export function queueWords(repoId: string): string {
198 const line = lines.get(repoId);
199 if (line === undefined) return "idle";
200 const waiting = line.waiting.length === 0 ? "" : `${line.waiting.length} waiting`;
201 if (line.gating === 0) return waiting === "" ? "idle" : waiting;
202 return `gating ${pullsWord(line.gating)} since ${hhmm(line.since)}${waiting === "" ? "" : `, ${waiting}`}`;
203 }
204
205 /** `1 pull`, `8 pulls`. */
206 function pullsWord(n: number): string {
207 return n === 1 ? "1 pull" : `${n} pulls`;
208 }
209
210 /** An epoch-ms instant as `HH:MM`, UTC as the log is. */
211 function hhmm(ms: number): string {
212 return new Date(ms).toISOString().slice(11, 16);
213 }
214
215 /** A gate's verdict in a word, for the log. */
216 function outcome(verdict: LandVerdict): string {
217 if (verdict.lands) return "green";
218 return "interrupted" in verdict ? "cut off" : "red";
219 }
220
154221 /** Gate runs a repository's line has made since boot. */
155222 export function gateRuns(repoId: string): number {
156223 return lines.get(repoId)?.gates ?? 0;
@@ -159,24 +226,57 @@ export function gateRuns(repoId: string): number {
159226 /**
160227 * One candidate at a time, until the line is empty. A batch is the front
161228 * of the line that shares one place and one base branch; a sealed pull
162 * whose objects live elsewhere is a batch of its own.
229 * whose objects live elsewhere is a batch of its own. A batch carries at
230 * most `MAX_CANDIDATE` pulls.
163231 */
164232 async function drain(line: Line, gate: GateCandidate): Promise<void> {
165233 line.draining = true;
166234 try {
167235 while (line.waiting.length > 0) {
168236 const first = line.waiting[0]!.entry;
169 const batch = line.waiting.filter(
170 (w) => w.entry.dir === first.dir && w.entry.pull.baseBranch === first.pull.baseBranch,
171 );
237 const batch = line.waiting
238 .filter((w) => w.entry.dir === first.dir && w.entry.pull.baseBranch === first.pull.baseBranch)
239 .slice(0, MAX_CANDIDATE);
172240 line.waiting = line.waiting.filter((w) => !batch.includes(w));
173 const counted: GateCandidate = async (candidate) => {
241 const counted: Gated = async (candidate) => {
174242 line.gates++;
175243 line.gating = candidate.steps.length;
244 line.since = Date.now();
245 const pulls = candidate.steps.map((s) => `#${s.entry.pull.number}`).join(",");
246 // Said as it starts and as it ends: a gate takes minutes (#3430).
247 log.info(`gating ${pullsWord(line.gating)} since ${hhmm(line.since)}`, {
248 repo: line.repoId,
249 pulls,
250 waiting: line.waiting.length,
251 });
252 const abandon = new AbortController();
253 let timer: ReturnType<typeof setTimeout> | undefined;
254 // A gate that never answers is abandoned at the deadline: no
255 // verdict, and the next sweep forms the line again (#3430).
256 const deadline = new Promise<LandVerdict>((resolve) => {
257 timer = setTimeout(() => {
258 log.warn("candidate abandoned", {
259 repo: line.repoId,
260 pulls,
261 since: new Date(line.since).toISOString(),
262 deadline: `${Math.round(deadlineMs / 1000)}s`,
263 });
264 abandon.abort();
265 resolve({ lands: false, interrupted: true });
266 }, deadlineMs);
267 });
176268 try {
177 return await gate(candidate);
269 const verdict = await Promise.race([gate(candidate, abandon.signal), deadline]);
270 log.info(`gated ${pullsWord(line.gating)}: ${outcome(verdict)}`, {
271 repo: line.repoId,
272 pulls,
273 took: `${Math.round((Date.now() - line.since) / 1000)}s`,
274 });
275 return verdict;
178276 } finally {
277 clearTimeout(timer);
179278 line.gating = 0;
279 line.since = 0;
180280 }
181281 };
182282 let left: Waiting[];
@@ -202,7 +302,7 @@ async function drain(line: Line, gate: GateCandidate): Promise<void> {
202302 */
203303 async function round(
204304 batch: readonly Waiting[],
205 gate: GateCandidate,
305 gate: Gated,
206306 known?: { treeOid: string; red: Red },
207307 ): Promise<Waiting[]> {
208308 const candidate = await build(batch);
src/checks/service.ts +6 −1
@@ -139,11 +139,13 @@ export interface ChecksHandle {
139139 * queued and no run is written; the answer is the verdict. `interrupted`
140140 * is a gate that did not finish for a reason that is not the code — this
141141 * forge stopping, or the cluster losing its Job — and is no verdict (#3155).
142 * `signal` aborting (the queue's deadline, #3430) cuts it off the same way.
142143 */
143144 gate(
144145 repo: Repo,
145146 pull: Pull,
146147 commitOid: string,
148 signal?: AbortSignal,
147149 ): Promise<{ ok: boolean; error: string; lines: string[]; interrupted?: boolean }>;
148150 /**
149151 * Stop checking. Checks under way get `drainMs` to finish unless `drain`
@@ -1120,13 +1122,15 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle {
11201122
11211123 const handle: ChecksHandle = {
11221124 request,
1123 gate: async (repo, pull, commitOid) => {
1125 gate: async (repo, pull, commitOid, signal) => {
11241126 const lines: string[] = [];
11251127 // A gate asked of a forge already stopping is not started: the forge
11261128 // that carries on asks it again.
11271129 if (stopped) return { ok: false, error: INTERRUPTED, lines, interrupted: true };
11281130 const controller = new AbortController();
11291131 gates.add(controller);
1132 const abandon = (): void => controller.abort();
1133 signal?.addEventListener("abort", abandon, { once: true });

If signal is already aborted when gate is called, this listener never fires. Check signal?.aborted first and abort the controller straight away.

The abort listener is attached after the early stopped return, which is correct. If signal is already aborted when it is passed in, addEventListener never fires. Check signal?.aborted here and abort the controller at once. The queue only passes a live signal today, so this is a guard for later callers.

11301134 try {
11311135 const bare = await pullDir(app.db, app.reposRoot, repo, pull);
11321136 const done = await runTier({
@@ -1146,6 +1150,7 @@ export function startChecks(app: App, options: ChecksOptions): ChecksHandle {
11461150 return { ok: false, error: done.error, lines, interrupted: true };
11471151 return { ok: false, error: done.error, lines };
11481152 } finally {
1153 signal?.removeEventListener("abort", abandon);
11491154 gates.delete(controller);
11501155 }
11511156 },
src/crew/autonomy.ts +5 −3
@@ -23,7 +23,7 @@ import {
2323 import type { AccessError } from "../actions/access.ts";
2424 import { gateCandidate, releaseOnLand } from "../checks/landing.ts";
2525 import { addLearned } from "../checks/learned.ts";
26 import { enqueue, type GateCandidate, type Queued } from "../checks/queue.ts";
26 import { enqueue, type GateCandidate, type Queued, queueWords } from "../checks/queue.ts";
2727 import { mergeable, resolveOid, treeOf } from "../git/merge.ts";
2828 import { repoDir } from "../git/repos.ts";
2929 import { CLOSED_NOTE } from "../core/done_on_main.ts";
@@ -1192,6 +1192,8 @@ export async function autonomyTick(
11921192 }),
11931193 // The approved pulls the last green sweep saw, and why each waits (#3055).
11941194 ...(approved === undefined ? {} : { approved }),
1195 // What the merge queue is doing now, not what the sweep admitted (#3430).
1196 queue: queueWords(current.id),
11951197 spent: `${status.spentTodayUsd.toFixed(2)}/${status.ceilingUsd}`,
11961198 ...(status.paused === null ? {} : { paused: status.paused }),
11971199 });
@@ -1841,8 +1843,8 @@ export function regateDue(red: Decision, now: number): boolean {
18411843
18421844 /** The queue's gate: the full tier on the candidate's tip, asked as its first pull. */
18431845 function gateFor(app: App, repo: Repo): GateCandidate {
1844 return (candidate) =>
1845 gateCandidate(app, repo, candidate.steps[0]!.entry.pull, candidate.dir, candidate.tipOid);
1846 return (candidate, signal) =>
1847 gateCandidate(app, repo, candidate.steps[0]!.entry.pull, candidate.dir, candidate.tipOid, signal);
18461848 }
18471849
18481850 /**
test/merge-queue.test.ts +59 −2
@@ -13,7 +13,7 @@ import { createApp, type App } from "../src/app.ts";
1313 import { mergePull, openPull } from "../src/actions/pulls.ts";
1414 import { commitToBranch, createRepo } from "../src/actions/repos.ts";
1515 import { readLearned } from "../src/checks/learned.ts";
16 import { enqueue, gateRuns, queueStatus, type Queued } from "../src/checks/queue.ts";
16 import { enqueue, gateDeadlineForTest, MAX_CANDIDATE, gateRuns, queueStatus, queueWords, type Queued } from "../src/checks/queue.ts";
1717 import { provideChecksForTest, type ChecksHandle } from "../src/checks/service.ts";
1818 import { latestDecision } from "../src/core/decisions.ts";
1919 import { getPull, type Pull } from "../src/core/pulls.ts";
@@ -41,6 +41,8 @@ describe("the merge queue", () => {
4141 let cutOff = 0;
4242 /** How many gates from now go red whatever the tree, as a machine's red would. */
4343 let flaky = 0;
44 /** The signal the last gate was handed: the queue aborts it at the deadline. */
45 let lastSignal: AbortSignal | undefined;
4446
4547 const git = (repo: Repo, ...args: string[]) =>
4648 Bun.spawnSync(["git", ...args], {
@@ -63,7 +65,8 @@ describe("the merge queue", () => {
6365 if (!a.ok) throw new Error(a.error);
6466 alice = a.value;
6567 provideChecksForTest(app, {
66 gate: async (repo: Repo, _pull: Pull, commitOid: string) => {
68 gate: async (repo: Repo, _pull: Pull, commitOid: string, signal?: AbortSignal) => {
69 lastSignal = signal;
6770 if (held !== undefined) await held;
6871 if (cutOff > 0) {
6972 cutOff--;
@@ -180,6 +183,29 @@ describe("the merge queue", () => {
180183 expect(queueStatus().some((s) => s.repoId === repo.id)).toBe(false);
181184 });
182185
186 test("ten green pulls: a candidate carries eight, the next the other two, and the log says each gate (#3430)", async () => {
187 const repo = await autonomousRepo("ten-green");
188 const base = git(repo, "rev-parse", "refs/heads/main");
189 const pulls = [];
190 for (let i = 0; i < 10; i++) pulls.push(await greenPull(repo, `p${i}.ts`));
191 const said: string[] = [];
192 const info = console.info;
193 console.info = (line: string) => said.push(line);
194 try {
195 expect(await sweepGreen(app, repo)).toBe(10);
196 } finally {
197 console.info = info;
198 }
199 expect(MAX_CANDIDATE).toBe(8);
200 expect(gatesOf(repo)).toHaveLength(2);
201 expect(git(repo, "rev-list", "--count", `${base}..${gatesOf(repo)[0]!.commit}`)).toBe("8");
202 for (const pull of pulls) expect(merged(repo, pull)).toBe(true);
203 const queue = said.filter((l) => l.includes("[queue] "));
204 expect(queue.some((l) => /\[queue\] gating 8 pulls since \d\d:\d\d .*waiting=2/.test(l))).toBe(true);
205 expect(queue.some((l) => l.includes("[queue] gated 8 pulls: green"))).toBe(true);
206 expect(queue.some((l) => l.includes("[queue] gated 2 pulls: green"))).toBe(true);
207 });
208
183209 test("one red among four: three land, the culprit is handed back, three gate runs", async () => {
184210 const repo = await autonomousRepo("one-red");
185211 const pulls = [];
@@ -363,6 +389,37 @@ describe("the merge queue", () => {
363389 expect(merged(repo, pull)).toBe(true);
364390 });
365391
392 test("a gate that never answers is abandoned at the deadline, and the next sweep lands (#3430)", async () => {
393 const repo = await autonomousRepo("never-answers");
394 const pull = await greenPull(repo, "a.ts");
395 expect(queueWords(repo.id)).toBe("idle");
396 const restore = gateDeadlineForTest(300);
397 const warned: string[] = [];
398 const warn = console.warn;
399 console.warn = (line: string) => warned.push(line);
400 held = new Promise<void>(() => {});
401 try {
402 lastSignal = undefined;
403 const sweep = sweepGreen(app, repo);
404 // Building the candidate is git work first: wait for the gate itself.
405 for (let i = 0; i < 200 && lastSignal === undefined; i++) await Bun.sleep(5);
406 expect(queueWords(repo.id)).toMatch(/^gating 1 pull since \d\d:\d\d$/);
407 expect(await sweep).toBe(0);
408 } finally {
409 held = undefined;
410 console.warn = warn;
411 restore();
412 }
413 expect((lastSignal as AbortSignal | undefined)?.aborted).toBe(true);
414 expect(warned.some((l) => l.includes("[queue] candidate abandoned") && l.includes(`#${pull.number}`))).toBe(true);
415 expect(queueWords(repo.id)).toBe("idle");
416 // No verdict: nothing told, and the line forms again on the next sweep.
417 expect(latestDecision(app.db, pull.id, "land")?.answer).not.toBe("red");
418 expect(listComments(app.db, pull.id)).toHaveLength(0);
419 expect(await sweepGreen(app, repo)).toBe(1);
420 expect(merged(repo, pull)).toBe(true);
421 });
422
366423 test("a red cut off mid-bisection hands no one back; the line lands on the next sweep", async () => {
367424 const repo = await autonomousRepo("cut-off-bisect");
368425 const pulls = [];

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs