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

Merged opened this

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

Merged

mason/forge:mason/7622-sentinel-release-was-degraded-1135-minut → main 7 commits fork

  • Merged. mason/7622-sentinel-release-was-degraded-1135-minut was merged into main as 9cf8bc5.

Review

Sign in to review this change.
4 files changed +222 −18
src/main.ts +4 −4
@@ -65,7 +65,7 @@ import { configProblem, dataDirOf, preflight } from "./kernel/preflight.ts";
6565 import { running } from "./kernel/version.ts";
6666 import { record as recordDegraded } from "./kernel/degraded_history.ts";
6767 import { vitals } from "./kernel/vitals.ts";
68 import { proveRelease } from "./release/prove.ts";
68 import { proveRunning } from "./release/prove.ts";
6969 import { CHECK_EVERY_MS, setBehind, watchBehind } from "./release/behind.ts";
7070 import { ownTagsReader } from "./release/own_tags.ts";
7171 import { snapshotPlace } from "./actions/health.ts";
@@ -594,8 +594,8 @@ const holdTimer = setInterval(() => {
594594 }, 60_000);
595595 const processTimer = setInterval(processTick, 60_000);
596596 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({
599599 dataDir: app.config.dataDir,
600600 version: running().version,
601601 url: forgeUrl,
@@ -605,7 +605,7 @@ void proveRelease({
605605 const first = listApps(app.db)[0];
606606 return apps && first ? apps.urlFor(first, "production") : undefined;
607607 })(),
608 }).then((p) => p && app.log.info("release proof", { version: p.version, ok: String(p.ok), ...(p.failure ? { failure: p.failure } : {}) }));
608 }, app.log);
609609 // The release tags of the forge's own repository are its shipped releases (release/shipped.ts);
610610 // production behind the newest for over an hour is a card (release/behind.ts).
611611 // 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 @@
33 * forge waits for its own public URL to answer `/healthz` as that version,
44 * then runs the smoke checks (`release/smoke.ts`) against it. The verdict is
55 * 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
77 * 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.
915 */
1016
1117 import { mkdirSync, readFileSync, renameSync, writeFileSync } from "node:fs";
@@ -13,10 +19,17 @@ import { join } from "node:path";
1319 import { smoke, type Failure, type Heavy } from "./smoke.ts";
1420 import { UNSTAMPED } from "../kernel/version.ts";
1521 import { ownProbeHeaders } from "../kernel/probe.ts";
22 import type { Log } from "../kernel/log.ts";
1623
1724 /** How long the public URL has to answer as the new version. */
1825 export const GIVE_UP_MS = 10 * 60_000;
1926 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;
2033
2134 export interface Proof {
2235 readonly version: string;
@@ -24,6 +37,15 @@ export interface Proof {
2437 readonly ok: boolean;
2538 /** The first failing check, or the give-up, when `ok` is false. */
2639 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));
2749 }
2850
2951 const proofFile = (dataDir: string): string => join(dataDir, "release", "proof.json");
@@ -47,11 +69,14 @@ function keep(dataDir: string, proof: Proof): Proof {
4769 return proof;
4870 }
4971
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. */
5173 export function proofNeed(dataDir: string): { sentence: string; since: string } | undefined {
5274 const p = lastProof(dataDir);
5375 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 };
5580 }
5681
5782 /** A failing check as one line: where, as whom, and why. */
@@ -76,22 +101,37 @@ export interface ProveOptions {
76101 readonly heavy?: Heavy;
77102 }
78103
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
79113 /**
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.
82116 */
83117 export async function proveRelease(o: ProveOptions): Promise<Proof | undefined> {
84 if (o.version === UNSTAMPED || lastProof(o.dataDir)?.version === o.version) return undefined;
85118 const now = o.now ?? Date.now;
119 const last = lastProof(o.dataDir);
120 if (!proofDue(last, o.version, now())) return undefined;
86121 const sleep = o.sleep ?? Bun.sleep;
87122 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, {
90127 version: o.version,
91 at: new Date(now()).toISOString(),
128 at,
92129 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 }),
94133 });
134 };
95135 try {
96136 const health = new URL("/healthz", o.url).href;
97137 const deadline = now() + (o.giveUpMs ?? GIVE_UP_MS);
@@ -116,3 +156,50 @@ export async function proveRelease(o: ProveOptions): Promise<Proof | undefined>
116156 return finish(`the smoke checks could not run: ${String(error)}`);
117157 }
118158 }
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";
99 import { mkdtempSync, rmSync } from "node:fs";
1010 import { tmpdir } from "node:os";
1111 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";
1313 import { owned } from "../src/crew/incidents.ts";
1414
1515 const CSS = '<html><link rel="stylesheet" href="/a.css"></html>';
@@ -110,10 +110,127 @@ describe("proving a release", () => {
110110 expect(p?.ok).toBe(false);
111111 expect(t).toBeLessThanOrEqual(10 * 60_000);
112112 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 ");
114114 expect(old.hits.every((h) => h === "/healthz")).toBe(true);
115115 });
116116
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
117234 test("an unstamped forge proves nothing", async () => {
118235 const s = site("dev");
119236 expect(await run("dev", s.fake)).toBeUndefined();
test/vitals-release.test.ts +1 −1
@@ -38,7 +38,7 @@ test("no proof, no card", () => {
3838 test("a failing proof is a release card naming the check, linking the board", () => {
3939 keep({ version: "9.9.9", at: "2026-10-18T10:00:00.000Z", ok: false, failure: "https://f/a.css expected 200 (status 500)" });
4040 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.",
4242 href: "/board",
4343 since: "2026-10-18T10:00:00.000Z",
4444 });

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs