Public: anyone can read this; the crew can change it.
Sentinel: release was degraded 172 minutes today: Release 0.7.479 is unproven: the public URL never answered as 0.7.479. It is proven again at 15:55 UTC. #10323
Check · Review · Land · Live done — Landed and live in production.
scout/forge:scout/10313-sentinel-release-was-degraded-172-minute → main 3 commits fork 1 thread · 1 unresolved
2 files
changed +96
−9
src/release/prove.ts +45 −7
| @@ -40,6 +40,8 @@ export const TICK_MS = 60_000; | ||
| 40 | 40 | export const RETRY_POLL_MS = 10_000; |
| 41 | 41 | /** How many give-ups in a row are retried after one tick before the doubling takes over. */ |
| 42 | 42 | export const QUICK_RETRIES = 10; |
| 43 | /** A proof not ended by then is hung: the next tick is scheduled anyway, or the last failure would stand for hours (#10313). */ | |
| 44 | export const HANG_MS = GIVE_UP_MS + 5 * 60_000; | |
| 43 | 45 | |
| 44 | 46 | export interface Proof { |
| 45 | 47 | readonly version: string; |
| @@ -146,6 +148,8 @@ export interface ProveOptions { | ||
| 146 | 148 | readonly giveUpMs?: number; |
| 147 | 149 | /** The heavy-page load and `/healthz` watch after go-live; a shorter window for a test. */ |
| 148 | 150 | readonly heavy?: Heavy; |
| 151 | /** Aborted when the proof is hung: its asks stop and it keeps no verdict (#10313). */ | |
| 152 | readonly signal?: AbortSignal; | |
| 149 | 153 | } |
| 150 | 154 | |
| 151 | 155 | /** Is a proof of `version` due: never tried, or failed `retryAfter` its failures or more ago? */ |
| @@ -159,16 +163,18 @@ export function proofDue(last: Proof | undefined, version: string, now: number): | ||
| 159 | 163 | |
| 160 | 164 | /** |
| 161 | 165 | * Proves `version` unless it was proven before, or its last failure's |
| 162 | * `retryAfter` has not passed. Returns what was kept, or undefined when nothing ran. Never throws. | |
| 166 | * `retryAfter` has not passed. Returns what was kept, or undefined when nothing ran. Throws only when `signal` aborts it. | |
| 163 | 167 | */ |
| 164 | 168 | export async function proveRelease(o: ProveOptions): Promise<Proof | undefined> { |
| 165 | 169 | const now = o.now ?? Date.now; |
| 166 | 170 | const last = lastProof(o.dataDir); |
| 167 | 171 | if (now() < (superseded.get(o.version) ?? -Infinity) || !proofDue(last, o.version, now())) return undefined; |
| 168 | 172 | const sleep = o.sleep ?? Bun.sleep; |
| 169 | const doFetch = o.fetch ?? fetch; | |
| 173 | const baseFetch = o.fetch ?? fetch; | |
| 174 | const doFetch = ((url, init) => baseFetch(url, o.signal ? { ...init, signal: init?.signal ? AbortSignal.any([init.signal, o.signal]) : o.signal } : init)) as typeof fetch; | |
| 170 | 175 | const failedBefore = last?.version === o.version && !last.ok ? last : undefined; |
| 171 | 176 | const finish = (failure?: string, slow = false, gaveUp = false): Proof => { |
| 177 | if (o.signal?.aborted) throw new Error("the proof was aborted as hung"); | |
| 172 | 178 | const at = new Date(now()).toISOString(); |
| 173 | 179 | return keep(o.dataDir, { |
| 174 | 180 | version: o.version, |
| @@ -184,6 +190,7 @@ export async function proveRelease(o: ProveOptions): Promise<Proof | undefined> | ||
| 184 | 190 | const deadline = now() + (o.giveUpMs ?? (failedBefore?.gaveUp === true ? RETRY_POLL_MS : GIVE_UP_MS)); |
| 185 | 191 | let seen = ""; |
| 186 | 192 | for (;;) { |
| 193 | if (o.signal?.aborted) throw new Error("the proof was aborted as hung"); | |
| 187 | 194 | try { |
| 188 | 195 | // Each ask is a fresh URL and says no-cache, so a proxy or edge holding an older /healthz answer cannot stand for the public URL (#10184). |
| 189 | 196 | const res = await doFetch(`${health}?proof=${now()}`, { redirect: "manual", cache: "no-store", headers: { ...ownProbeHeaders(o.dataDir), "cache-control": "no-cache" }, signal: AbortSignal.timeout(5_000) }); |
| @@ -235,14 +242,45 @@ export function startProving( | ||
| 235 | 242 | everyMs = TICK_MS, |
| 236 | 243 | schedule: Schedule = unrefTimer, |
| 237 | 244 | prove: (o: ProveOptions) => Promise<Proof | undefined> = proveRelease, |
| 245 | hangMs = HANG_MS, | |
| 246 | log?: Pick<Log, "warn">, | |
| 238 | 247 | ): () => void { |
| 239 | 248 | let cancel: (() => void) | undefined; |
| 240 | 249 | let stopped = false; |
| 241 | const tick = async (): Promise<void> => { | |
| 242 | const p = await prove(o); | |
| 243 | if (p) done(p); | |
| 250 | // True from a proof's start until it settles: a proof is never started over one still running. | |
| 251 | let running = false; | |
| 252 | const next = (): void => { | |
| 244 | 253 | if (!stopped) cancel = schedule(() => void tick(), everyMs); |
| 245 | 254 | }; |
| 255 | const tick = async (): Promise<void> => { | |
| 256 | if (running) { | |
| 257 | log?.warn("release proof still running", { version: o.version }); | |
| 258 | return next(); | |
| 259 | } | |
| 260 | running = true; | |
| 261 | const abort = new AbortController(); | |
| 262 | const work = prove({ ...o, signal: abort.signal }).then( | |
| 263 | (p) => ({ p }), | |
| 264 | (error) => { | |
| 265 | log?.warn("release proof failed", { version: o.version, error: String(error) }); | |
| 266 | return { p: undefined }; | |
| 267 | }, | |
| 268 | ); | |
| 269 | void work.finally(() => void (running = false)); | |
| 270 | let timer: ReturnType<typeof setTimeout> | undefined; | |
| 271 | const hung = new Promise<"hung">((resolve) => { | |
| 272 | timer = setTimeout(() => resolve("hung"), hangMs); | |
| 273 | timer.unref?.(); | |
| 274 | }); | |
| 275 | const result = await Promise.race([work, hung]); | |
| 276 | clearTimeout(timer); | |
| 277 | if (result === "hung") { | |
| 278 | // Stop its asks; the next tick waits for it to settle rather than run beside it. | |
| 279 | log?.warn("release proof hung", { version: o.version, afterMs: hangMs }); | |
| 280 | abort.abort(); | |
| 281 | } else if (result.p) done(result.p); | |
| 282 | next(); | |
| 283 | }; | |
| 246 | 284 | void tick(); |
| 247 | 285 | return () => { |
| 248 | 286 | stopped = true; |
| @@ -253,10 +291,10 @@ export function startProving( | ||
| 253 | 291 | /** What the forge runs at boot (`main.ts`): `startProving`, each verdict one `release proof` line in `log`. */ |
| 254 | 292 | export function proveRunning( |
| 255 | 293 | o: ProveOptions, |
| 256 | log: Pick<Log, "info">, | |
| 294 | log: Pick<Log, "info" | "warn">, | |
| 257 | 295 | everyMs = TICK_MS, |
| 258 | 296 | schedule: Schedule = unrefTimer, |
| 259 | 297 | prove: (o: ProveOptions) => Promise<Proof | undefined> = proveRelease, |
| 260 | 298 | ): () => void { |
| 261 | return startProving(o, (p) => log.info("release proof", { version: p.version, ok: String(p.ok), ...(p.failure ? { failure: p.failure } : {}) }), everyMs, schedule, prove); | |
| 299 | return startProving(o, (p) => log.info("release proof", { version: p.version, ok: String(p.ok), ...(p.failure ? { failure: p.failure } : {}) }), everyMs, schedule, prove, HANG_MS, log); | |
| 262 | 300 | } |
test/release-prove.test.ts +51 −2
| @@ -9,7 +9,7 @@ import { afterEach, beforeEach, describe, expect, test } from "bun:test"; | ||
| 9 | 9 | import { mkdirSync, mkdtempSync, rmSync, writeFileSync } from "node:fs"; |
| 10 | 10 | import { tmpdir } from "node:os"; |
| 11 | 11 | import { join } from "node:path"; |
| 12 | import { GIVE_UP_MS, isNewer, lastProof, proofDue, proofNeed, proveRelease, proveRunning, QUICK_RETRIES, retryAfter, RETRY_MS, startProving, type Proof } from "../src/release/prove.ts"; | |
| 12 | import { GIVE_UP_MS, isNewer, lastProof, proofDue, proofNeed, proveRelease, proveRunning, QUICK_RETRIES, retryAfter, RETRY_MS, startProving, type Proof, type ProveOptions } from "../src/release/prove.ts"; | |
| 13 | 13 | import { owned } from "../src/crew/incidents.ts"; |
| 14 | 14 | |
| 15 | 15 | const CSS = '<html><link rel="stylesheet" href="/a.css"></html>'; |
| @@ -321,13 +321,62 @@ describe("proving a release", () => { | ||
| 321 | 321 | expect(queued).toEqual([]); |
| 322 | 322 | }); |
| 323 | 323 | |
| 324 | test("startProving aborts a hung proof, logs it, and never runs two proofs at once (#10313)", async () => { | |
| 325 | const queued: { fn: () => void; ms: number }[] = []; | |
| 326 | const schedule = (fn: () => void, ms: number) => { | |
| 327 | queued.push({ fn, ms }); | |
| 328 | return () => {}; | |
| 329 | }; | |
| 330 | const warned: string[] = []; | |
| 331 | const log = { warn: (m: string) => void warned.push(m) }; | |
| 332 | let calls = 0, live = 0, most = 0; | |
| 333 | let release: (() => void) | undefined; | |
| 334 | const signals: AbortSignal[] = []; | |
| 335 | const prove = (o: ProveOptions) => { | |
| 336 | calls++; | |
| 337 | signals.push(o.signal!); | |
| 338 | live++; | |
| 339 | most = Math.max(most, live); | |
| 340 | if (calls === 1) return new Promise<Proof | undefined>((resolve) => (release = () => ((live--), resolve(undefined)))); // ignores the abort | |
| 341 | live--; | |
| 342 | return Promise.reject(new Error("boom")); | |
| 343 | }; | |
| 344 | const stop = startProving({ dataDir: dir, version: "4.2.0", url: "https://forge.test" }, () => {}, 60_000, schedule, prove, 20, log); | |
| 345 | await Bun.sleep(60); | |
| 346 | expect(signals[0]!.aborted).toBe(true); | |
| 347 | expect(warned).toEqual(["release proof hung"]); | |
| 348 | expect(queued.map((q) => q.ms)).toEqual([60_000]); | |
| 349 | queued.shift()!.fn(); // the hung one has not settled: no second proof | |
| 350 | await Bun.sleep(5); | |
| 351 | expect(calls).toBe(1); | |
| 352 | expect(warned).toEqual(["release proof hung", "release proof still running"]); | |
| 353 | release!(); | |
| 354 | await Bun.sleep(5); | |
| 355 | queued.shift()!.fn(); | |
| 356 | await Bun.sleep(10); | |
| 357 | expect(calls).toBe(2); | |
| 358 | expect(warned.at(-1)).toBe("release proof failed"); | |
| 359 | expect(most).toBe(1); | |
| 360 | stop(); | |
| 361 | }); | |
| 362 | ||
| 363 | test("proveRelease aborted mid-wait stops asking and keeps no verdict (#10313)", async () => { | |
| 364 | const abort = new AbortController(); | |
| 365 | const fetcher = ((_u: unknown, init?: RequestInit) => | |
| 366 | new Promise((_r, reject) => init?.signal?.addEventListener("abort", () => reject(new Error("aborted"))))) as unknown as typeof fetch; | |
| 367 | setTimeout(() => abort.abort(), 20); | |
| 368 | const run = proveRelease({ dataDir: dir, version: "9.9.9", url: "https://forge.test", fetch: fetcher, signal: abort.signal }); | |
| 369 | await expect(run).rejects.toThrow("aborted"); | |
| 370 | expect(lastProof(dir)).toBeUndefined(); | |
| 371 | }); | |
| 372 | ||
| 324 | 373 | test("proveRunning, what main.ts boots, logs each verdict that ran as one release proof line", async () => { |
| 325 | 374 | const lines: [string, unknown][] = []; |
| 326 | 375 | const queued: (() => void)[] = []; |
| 327 | 376 | const results: (Proof | undefined)[] = [{ version: "4.6.0", at: "a", ok: false, failure: "slow" }, undefined, { version: "4.6.0", at: "b", ok: true }]; |
| 328 | 377 | const stop = proveRunning( |
| 329 | 378 | { dataDir: dir, version: "4.6.0", url: "https://forge.test" }, |
| 330 | { info: (msg, fields) => void lines.push([msg, fields]) }, | |
| 379 | { info: (msg, fields) => void lines.push([msg, fields]), warn: () => {} }, | |
| 331 | 380 | 60_000, |
| 332 | 381 | (fn) => (queued.push(fn), () => {}), |
| 333 | 382 | async () => results.shift(), |
new above
offline
The
.catchhere drops the error silently, and the timed-out proof is left running. Log both outcomes, and cancel the old proof or do not start an overlapping one.