Public: anyone can read this; the crew can change it.
Sentinel: release was degraded 1135 minutes today: Release 0.7.287 is unproven: https://forge.open-platform.sh/healthz as desktop /healthz took 2802 ms, over 1000 ms (sta… #7687
Check · Review · Land · Live done — Landed and live in production.
mason/forge:mason/7622-sentinel-release-was-degraded-1135-minut → main 7 commits fork
4 files
changed +222
−18
src/main.ts +4 −4
| @@ -65,7 +65,7 @@ import { configProblem, dataDirOf, preflight } from "./kernel/preflight.ts"; | ||
| 65 | 65 | import { running } from "./kernel/version.ts"; |
| 66 | 66 | import { record as recordDegraded } from "./kernel/degraded_history.ts"; |
| 67 | 67 | import { vitals } from "./kernel/vitals.ts"; |
| 68 | import { proveRelease } from "./release/prove.ts"; | |
| 68 | import { proveRunning } from "./release/prove.ts"; | |
| 69 | 69 | import { CHECK_EVERY_MS, setBehind, watchBehind } from "./release/behind.ts"; |
| 70 | 70 | import { ownTagsReader } from "./release/own_tags.ts"; |
| 71 | 71 | import { snapshotPlace } from "./actions/health.ts"; |
| @@ -594,8 +594,8 @@ const holdTimer = setInterval(() => { | ||
| 594 | 594 | }, 60_000); |
| 595 | 595 | const processTimer = setInterval(processTick, 60_000); |
| 596 | 596 | processTick(); |
| 597 | // A new version proves itself against the public URL once (release/prove.ts). | |
| 598 | void proveRelease({ | |
| 597 | // A new version proves itself against the public URL; a failed one again, 5 min after and backing off to hourly (release/prove.ts). | |
| 598 | proveRunning({ | |
| 599 | 599 | dataDir: app.config.dataDir, |
| 600 | 600 | version: running().version, |
| 601 | 601 | url: forgeUrl, |
| @@ -605,7 +605,7 @@ void proveRelease({ | ||
| 605 | 605 | const first = listApps(app.db)[0]; |
| 606 | 606 | return apps && first ? apps.urlFor(first, "production") : undefined; |
| 607 | 607 | })(), |
| 608 | }).then((p) => p && app.log.info("release proof", { version: p.version, ok: String(p.ok), ...(p.failure ? { failure: p.failure } : {}) })); | |
| 608 | }, app.log); | |
| 609 | 609 | // The release tags of the forge's own repository are its shipped releases (release/shipped.ts); |
| 610 | 610 | // production behind the newest for over an hour is a card (release/behind.ts). |
| 611 | 611 | // A FORGE_REPO that is not owner/name is dropped by releaseEnv; say so, or the list stops at the frozen one unexplained. |
src/release/prove.ts +98 −11
| @@ -3,9 +3,15 @@ | ||
| 3 | 3 | * forge waits for its own public URL to answer `/healthz` as that version, |
| 4 | 4 | * then runs the smoke checks (`release/smoke.ts`) against it. The verdict is |
| 5 | 5 | * one small file under the data directory (`release/proof.json`), so a |
| 6 | * restart of the same version never runs it again and vitals reads it | |
| 6 | * restart of a proven version never runs it again and vitals reads it | |
| 7 | 7 | * without the network. A failure is a `release` card, paged once by the |
| 8 | * cause pager, until a later version passes. It gives up after ten minutes. | |
| 8 | * cause pager, until a later version passes or the same version is proven | |
| 9 | * again: `startProving` asks every minute, and a failed version runs again | |
| 10 | * once `retryAfter` has passed since its last try (5 minutes, doubling each | |
| 11 | * failure up to an hour), so one slow answer in the watch no longer stands | |
| 12 | * for the version's whole life (#7622) and a version that stays broken | |
| 13 | * costs its public URL a few loads an hour, not one every 5 minutes. It | |
| 14 | * gives up after ten minutes. | |
| 9 | 15 | */ |
| 10 | 16 | |
| 11 | 17 | import { mkdirSync, readFileSync, renameSync, writeFileSync } from "node:fs"; |
| @@ -13,10 +19,17 @@ import { join } from "node:path"; | ||
| 13 | 19 | import { smoke, type Failure, type Heavy } from "./smoke.ts"; |
| 14 | 20 | import { UNSTAMPED } from "../kernel/version.ts"; |
| 15 | 21 | import { ownProbeHeaders } from "../kernel/probe.ts"; |
| 22 | import type { Log } from "../kernel/log.ts"; | |
| 16 | 23 | |
| 17 | 24 | /** How long the public URL has to answer as the new version. */ |
| 18 | 25 | export const GIVE_UP_MS = 10 * 60_000; |
| 19 | 26 | const POLL_MS = 2_000; |
| 27 | /** How long after a first failed proof the same version is proven again; each failure after doubles it. */ | |
| 28 | export const RETRY_MS = 5 * 60_000; | |
| 29 | /** The longest wait between two proofs of a version that keeps failing. */ | |
| 30 | export const MAX_RETRY_MS = 60 * 60_000; | |
| 31 | /** How often `startProving` asks whether a proof is due. */ | |
| 32 | export const TICK_MS = 60_000; | |
| 20 | 33 | |
| 21 | 34 | export interface Proof { |
| 22 | 35 | readonly version: string; |
| @@ -24,6 +37,15 @@ export interface Proof { | ||
| 24 | 37 | readonly ok: boolean; |
| 25 | 38 | /** The first failing check, or the give-up, when `ok` is false. */ |
| 26 | 39 | readonly failure?: string; |
| 40 | /** When this version first failed, kept across retries that fail again. */ | |
| 41 | readonly since?: string; | |
| 42 | /** How many proofs of this version have failed in a row; 1 when unset. */ | |
| 43 | readonly failures?: number; | |
| 44 | } | |
| 45 | ||
| 46 | /** The wait after a version's `failures`th failed proof in a row: `RETRY_MS` doubled per failure, capped at `MAX_RETRY_MS`. */ | |
| 47 | export function retryAfter(failures: number): number { | |
| 48 | return Math.min(MAX_RETRY_MS, RETRY_MS * 2 ** Math.max(0, Math.min(failures, 20) - 1)); | |
| 27 | 49 | } |
| 28 | 50 | |
| 29 | 51 | const proofFile = (dataDir: string): string => join(dataDir, "release", "proof.json"); |
| @@ -47,11 +69,14 @@ function keep(dataDir: string, proof: Proof): Proof { | ||
| 47 | 69 | return proof; |
| 48 | 70 | } |
| 49 | 71 | |
| 50 | /** The card an unproven release is, or undefined while the last verdict is a pass. */ | |
| 72 | /** The card an unproven release is, saying when it is tried again; undefined while the last verdict is a pass. */ | |
| 51 | 73 | export function proofNeed(dataDir: string): { sentence: string; since: string } | undefined { |
| 52 | 74 | const p = lastProof(dataDir); |
| 53 | 75 | if (p === undefined || p.ok) return undefined; |
| 54 | return { sentence: `Release ${p.version} is unproven: ${p.failure ?? "a smoke check failed"}.`, since: p.at }; | |
| 76 | const next = Date.parse(p.at) + retryAfter(p.failures ?? 1); | |
| 77 | // When it is tried again, so a person reading the card knows it is not stuck. | |
| 78 | const again = Number.isFinite(next) ? ` It is proven again at ${new Date(next).toISOString().slice(11, 16)} UTC.` : ""; | |
| 79 | return { sentence: `Release ${p.version} is unproven: ${p.failure ?? "a smoke check failed"}.${again}`, since: p.since ?? p.at }; | |
| 55 | 80 | } |
| 56 | 81 | |
| 57 | 82 | /** A failing check as one line: where, as whom, and why. */ |
| @@ -76,22 +101,37 @@ export interface ProveOptions { | ||
| 76 | 101 | readonly heavy?: Heavy; |
| 77 | 102 | } |
| 78 | 103 | |
| 104 | /** Is a proof of `version` due: never tried, or failed `retryAfter` its failures or more ago? */ | |
| 105 | export function proofDue(last: Proof | undefined, version: string, now: number): boolean { | |
| 106 | if (version === UNSTAMPED) return false; | |
| 107 | if (last?.version !== version) return true; | |
| 108 | if (last.ok) return false; | |
| 109 | const at = Date.parse(last.at); | |
| 110 | return !Number.isFinite(at) || now - at >= retryAfter(last.failures ?? 1); | |
| 111 | } | |
| 112 | ||
| 79 | 113 | /** |
| 80 | * Proves `version` unless it was proven (or failed) before. Returns what was | |
| 81 | * kept, or undefined when nothing ran. Never throws. | |
| 114 | * Proves `version` unless it was proven before, or its last failure's | |
| 115 | * `retryAfter` has not passed. Returns what was kept, or undefined when nothing ran. Never throws. | |
| 82 | 116 | */ |
| 83 | 117 | export async function proveRelease(o: ProveOptions): Promise<Proof | undefined> { |
| 84 | if (o.version === UNSTAMPED || lastProof(o.dataDir)?.version === o.version) return undefined; | |
| 85 | 118 | const now = o.now ?? Date.now; |
| 119 | const last = lastProof(o.dataDir); | |
| 120 | if (!proofDue(last, o.version, now())) return undefined; | |
| 86 | 121 | const sleep = o.sleep ?? Bun.sleep; |
| 87 | 122 | const doFetch = o.fetch ?? fetch; |
| 88 | const finish = (failure?: string): Proof => | |
| 89 | keep(o.dataDir, { | |
| 123 | const failedBefore = last?.version === o.version && !last.ok ? last : undefined; | |
| 124 | const finish = (failure?: string): Proof => { | |
| 125 | const at = new Date(now()).toISOString(); | |
| 126 | return keep(o.dataDir, { | |
| 90 | 127 | version: o.version, |
| 91 | at: new Date(now()).toISOString(), | |
| 128 | at, | |
| 92 | 129 | ok: failure === undefined, |
| 93 | ...(failure === undefined ? {} : { failure }), | |
| 130 | ...(failure === undefined | |
| 131 | ? {} | |
| 132 | : { failure, since: failedBefore ? (failedBefore.since ?? failedBefore.at) : at, failures: (failedBefore?.failures ?? (failedBefore ? 1 : 0)) + 1 }), | |
| 94 | 133 | }); |
| 134 | }; | |
| 95 | 135 | try { |
| 96 | 136 | const health = new URL("/healthz", o.url).href; |
| 97 | 137 | const deadline = now() + (o.giveUpMs ?? GIVE_UP_MS); |
| @@ -116,3 +156,50 @@ export async function proveRelease(o: ProveOptions): Promise<Proof | undefined> | ||
| 116 | 156 | return finish(`the smoke checks could not run: ${String(error)}`); |
| 117 | 157 | } |
| 118 | 158 | } |
| 159 | ||
| 160 | /** Runs `fn` after `ms`; returns its cancel. */ | |
| 161 | export type Schedule = (fn: () => void, ms: number) => () => void; | |
| 162 | ||
| 163 | const unrefTimer: Schedule = (fn, ms) => { | |
| 164 | const timer = setTimeout(fn, ms); | |
| 165 | timer.unref?.(); | |
| 166 | return () => clearTimeout(timer); | |
| 167 | }; | |
| 168 | ||
| 169 | /** | |
| 170 | * Proves the running version now, then asks every `everyMs` whether a proof | |
| 171 | * is due (`proofDue`); one proof runs at a time, the next tick scheduled | |
| 172 | * only once it ends. `done` hears each that ran. `schedule` and `prove` are | |
| 173 | * a test's to replace. Returns the stop. | |
| 174 | */ | |
| 175 | export function startProving( | |
| 176 | o: ProveOptions, | |
| 177 | done: (p: Proof) => void, | |
| 178 | everyMs = TICK_MS, | |
| 179 | schedule: Schedule = unrefTimer, | |
| 180 | prove: (o: ProveOptions) => Promise<Proof | undefined> = proveRelease, | |
| 181 | ): () => void { | |
| 182 | let cancel: (() => void) | undefined; | |
| 183 | let stopped = false; | |
| 184 | const tick = async (): Promise<void> => { | |
| 185 | const p = await prove(o); | |
| 186 | if (p) done(p); | |
| 187 | if (!stopped) cancel = schedule(() => void tick(), everyMs); | |
| 188 | }; | |
| 189 | void tick(); | |
| 190 | return () => { | |
| 191 | stopped = true; | |
| 192 | cancel?.(); | |
| 193 | }; | |
| 194 | } | |
| 195 | ||
| 196 | /** What the forge runs at boot (`main.ts`): `startProving`, each verdict one `release proof` line in `log`. */ | |
| 197 | export function proveRunning( | |
| 198 | o: ProveOptions, | |
| 199 | log: Pick<Log, "info">, | |
| 200 | everyMs = TICK_MS, | |
| 201 | schedule: Schedule = unrefTimer, | |
| 202 | prove: (o: ProveOptions) => Promise<Proof | undefined> = proveRelease, | |
| 203 | ): () => void { | |
| 204 | return startProving(o, (p) => log.info("release proof", { version: p.version, ok: String(p.ok), ...(p.failure ? { failure: p.failure } : {}) }), everyMs, schedule, prove); | |
| 205 | } |
test/release-prove.test.ts +119 −2
| @@ -9,7 +9,7 @@ import { afterEach, beforeEach, describe, expect, test } from "bun:test"; | ||
| 9 | 9 | import { mkdtempSync, rmSync } from "node:fs"; |
| 10 | 10 | import { tmpdir } from "node:os"; |
| 11 | 11 | import { join } from "node:path"; |
| 12 | import { lastProof, proofNeed, proveRelease } from "../src/release/prove.ts"; | |
| 12 | import { lastProof, proofDue, proofNeed, proveRelease, proveRunning, retryAfter, RETRY_MS, startProving, type Proof } 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>'; |
| @@ -110,10 +110,127 @@ describe("proving a release", () => { | ||
| 110 | 110 | expect(p?.ok).toBe(false); |
| 111 | 111 | expect(t).toBeLessThanOrEqual(10 * 60_000); |
| 112 | 112 | expect(t).toBeGreaterThan(9 * 60_000); |
| 113 | expect(proofNeed(dir)?.sentence).toBe("Release 1.0.0 is unproven: the public URL never answered as 1.0.0."); | |
| 113 | expect(proofNeed(dir)?.sentence).toStartWith("Release 1.0.0 is unproven: the public URL never answered as 1.0.0. It is proven again at "); | |
| 114 | 114 | expect(old.hits.every((h) => h === "/healthz")).toBe(true); |
| 115 | 115 | }); |
| 116 | 116 | |
| 117 | test("a failed version is proven again after RETRY_MS, and a pass clears the card (#7622)", async () => { | |
| 118 | let t = Date.parse("2026-10-28T12:00:00Z"); | |
| 119 | const clock = { now: () => t }; | |
| 120 | await run("4.0.0", site("4.0.0", { "/healthz": () => new Response("slow", { status: 503, headers: { "x-forge-version": "4.0.0" } }) }).fake, clock); | |
| 121 | const need = proofNeed(dir)!; | |
| 122 | expect(need.sentence).toContain("Release 4.0.0 is unproven"); | |
| 123 | t += RETRY_MS - 1; | |
| 124 | const early = site("4.0.0"); | |
| 125 | expect(await run("4.0.0", early.fake, clock)).toBeUndefined(); | |
| 126 | expect(early.hits).toEqual([]); | |
| 127 | t += 1; | |
| 128 | expect((await run("4.0.0", site("4.0.0").fake, clock))?.ok).toBe(true); | |
| 129 | expect(proofNeed(dir)).toBeUndefined(); | |
| 130 | // proven now, so never again for this version | |
| 131 | t += 10 * RETRY_MS; | |
| 132 | const later = site("4.0.0"); | |
| 133 | expect(await run("4.0.0", later.fake, clock)).toBeUndefined(); | |
| 134 | expect(later.hits).toEqual([]); | |
| 135 | }); | |
| 136 | ||
| 137 | test("a retry that fails again keeps the card's first since", async () => { | |
| 138 | let t = Date.parse("2026-10-28T12:00:00Z"); | |
| 139 | const clock = { now: () => t }; | |
| 140 | const broken = () => site("4.1.0", { "/": () => new Response("x", { status: 500 }) }).fake; | |
| 141 | await run("4.1.0", broken(), clock); | |
| 142 | const since = proofNeed(dir)!.since; | |
| 143 | t += RETRY_MS; | |
| 144 | expect((await run("4.1.0", broken(), clock))?.ok).toBe(false); | |
| 145 | expect(proofNeed(dir)?.since).toBe(since); | |
| 146 | expect(lastProof(dir)?.at).not.toBe(since); | |
| 147 | }); | |
| 148 | ||
| 149 | test("each failure in a row doubles the wait, up to an hour", async () => { | |
| 150 | expect([1, 2, 3, 4, 5, 99].map(retryAfter)).toEqual([5, 10, 20, 40, 60, 60].map((m) => m * 60_000)); | |
| 151 | let t = Date.parse("2026-10-28T12:00:00Z"); | |
| 152 | const clock = { now: () => t }; | |
| 153 | const broken = () => site("4.3.0", { "/": () => new Response("x", { status: 500 }) }).fake; | |
| 154 | await run("4.3.0", broken(), clock); | |
| 155 | expect(lastProof(dir)?.failures).toBe(1); | |
| 156 | expect(proofNeed(dir)?.sentence).toEndWith(" It is proven again at 12:05 UTC."); | |
| 157 | t += RETRY_MS; | |
| 158 | await run("4.3.0", broken(), clock); | |
| 159 | expect(lastProof(dir)?.failures).toBe(2); | |
| 160 | // the card names the later try: 12:05 plus ten minutes | |
| 161 | expect(proofNeed(dir)?.sentence).toEndWith(" It is proven again at 12:15 UTC."); | |
| 162 | // the third try waits ten minutes, not five | |
| 163 | t += RETRY_MS; | |
| 164 | const early = site("4.3.0"); | |
| 165 | expect(await run("4.3.0", early.fake, clock)).toBeUndefined(); | |
| 166 | expect(early.hits).toEqual([]); | |
| 167 | t += RETRY_MS; | |
| 168 | await run("4.3.0", broken(), clock); | |
| 169 | expect(lastProof(dir)?.failures).toBe(3); | |
| 170 | }); | |
| 171 | ||
| 172 | test("a proof kept before failures were counted is retried as a first failure", () => { | |
| 173 | const at = "2026-10-28T12:00:00.000Z"; | |
| 174 | const old: Proof = { version: "4.4.0", at, ok: false, failure: "x" }; | |
| 175 | expect(proofDue(old, "4.4.0", Date.parse(at) + RETRY_MS - 1)).toBe(false); | |
| 176 | expect(proofDue(old, "4.4.0", Date.parse(at) + RETRY_MS)).toBe(true); | |
| 177 | expect(proofDue({ ...old, ok: true }, "4.4.0", Date.parse(at) + 100 * RETRY_MS)).toBe(false); | |
| 178 | expect(proofDue(old, "4.5.0", Date.parse(at))).toBe(true); | |
| 179 | }); | |
| 180 | ||
| 181 | test("startProving proves at once, schedules the next tick only when one ends, and stops", async () => { | |
| 182 | const queued: { fn: () => void; ms: number }[] = []; | |
| 183 | const schedule = (fn: () => void, ms: number) => { | |
| 184 | const job = { fn, ms }; | |
| 185 | queued.push(job); | |
| 186 | return () => void queued.splice(queued.indexOf(job), 1); | |
| 187 | }; | |
| 188 | const results: (Proof | undefined)[] = [{ version: "4.2.0", at: "a", ok: false, failure: "x" }, undefined, { version: "4.2.0", at: "b", ok: true }]; | |
| 189 | let finish: (() => void) | undefined; | |
| 190 | let proofs = 0; | |
| 191 | const prove = () => { | |
| 192 | proofs++; | |
| 193 | return new Promise<Proof | undefined>((resolve) => (finish = () => resolve(results.shift()))); | |
| 194 | }; | |
| 195 | const heard: Proof[] = []; | |
| 196 | const stop = startProving({ dataDir: dir, version: "4.2.0", url: "https://forge.test" }, (p) => heard.push(p), 60_000, schedule, prove); | |
| 197 | expect(proofs).toBe(1); | |
| 198 | expect(queued).toEqual([]); // nothing scheduled while a proof runs | |
| 199 | for (let i = 0; i < 3; i++) { | |
| 200 | finish!(); | |
| 201 | await Bun.sleep(0); | |
| 202 | expect(queued.map((q) => q.ms)).toEqual([60_000]); | |
| 203 | if (i < 2) queued.shift()!.fn(); | |
| 204 | } | |
| 205 | expect(proofs).toBe(3); | |
| 206 | expect(heard.map((p) => p.ok)).toEqual([false, true]); | |
| 207 | stop(); | |
| 208 | expect(queued).toEqual([]); | |
| 209 | }); | |
| 210 | ||
| 211 | test("proveRunning, what main.ts boots, logs each verdict that ran as one release proof line", async () => { | |
| 212 | const lines: [string, unknown][] = []; | |
| 213 | const queued: (() => void)[] = []; | |
| 214 | const results: (Proof | undefined)[] = [{ version: "4.6.0", at: "a", ok: false, failure: "slow" }, undefined, { version: "4.6.0", at: "b", ok: true }]; | |
| 215 | const stop = proveRunning( | |
| 216 | { dataDir: dir, version: "4.6.0", url: "https://forge.test" }, | |
| 217 | { info: (msg, fields) => void lines.push([msg, fields]) }, | |
| 218 | 60_000, | |
| 219 | (fn) => (queued.push(fn), () => {}), | |
| 220 | async () => results.shift(), | |
| 221 | ); | |
| 222 | for (let i = 0; i < 3; i++) { | |
| 223 | await Bun.sleep(0); | |
| 224 | queued.shift()?.(); | |
| 225 | } | |
| 226 | await Bun.sleep(0); | |
| 227 | stop(); | |
| 228 | expect(lines).toEqual([ | |
| 229 | ["release proof", { version: "4.6.0", ok: "false", failure: "slow" }], | |
| 230 | ["release proof", { version: "4.6.0", ok: "true" }], | |
| 231 | ]); | |
| 232 | }); | |
| 233 | ||
| 117 | 234 | test("an unstamped forge proves nothing", async () => { |
| 118 | 235 | const s = site("dev"); |
| 119 | 236 | expect(await run("dev", s.fake)).toBeUndefined(); |
test/vitals-release.test.ts +1 −1
| @@ -38,7 +38,7 @@ test("no proof, no card", () => { | ||
| 38 | 38 | test("a failing proof is a release card naming the check, linking the board", () => { |
| 39 | 39 | keep({ version: "9.9.9", at: "2026-10-18T10:00:00.000Z", ok: false, failure: "https://f/a.css expected 200 (status 500)" }); |
| 40 | 40 | expect(card()).toMatchObject({ |
| 41 | sentence: "Release 9.9.9 is unproven: https://f/a.css expected 200 (status 500).", | |
| 41 | sentence: "Release 9.9.9 is unproven: https://f/a.css expected 200 (status 500). It is proven again at 10:05 UTC.", | |
| 42 | 42 | href: "/board", |
| 43 | 43 | since: "2026-10-18T10:00:00.000Z", |
| 44 | 44 | }); |
new above
offline