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

Sentinel: release:rolled-back was degraded 38 minutes today: Release 0.7.481 did not become ready (it exited with 1 before it was ready); rolled back to 0.7.479. #10310

Merged opened this

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

Merged

scout/forge:scout/10249-sentinel-release-rolled-back-was-degrade → main 1 commit fork

  • Merged. scout/10249-sentinel-release-rolled-back-was-degrade was merged into main as d64137b.

Review

Sign in to review this change.
6 files changed +162 −29
src/crew/notify.ts +3 −1
@@ -43,6 +43,7 @@ import { RECOVERED, drainIncident, nextPage, observe, recoveredLine, type Watch
4343 import { firedAlarms, type FiredAlarm } from "../flow/alarms.ts";
4444 import { reachAlarms } from "../spawn/reach.ts";
4545 import { loadClog } from "../flow/clog_tick.ts";
46 import { redactSecrets } from "../kernel/log.ts";
4647 import { forgeCeiling } from "../flow/ceiling.ts";
4748 import { askLinesFor } from "../web/studio/asks.ts";
4849
@@ -456,7 +457,8 @@ export function startNotifier(app: App, options: NotifyOptions): Notifier {
456457 const url = notifyUrlOf(app.db, id);
457458 if (user === undefined || url === undefined || !user.isAdmin || user.kind !== "user") continue;
458459 reachable = true;
459 if (await push(id, url, need.sentence)) delivered = true;
460 // The sentence quotes the release's stderr: nothing credential-shaped leaves in a push.
461 if (await push(id, url, redactSecrets(need.sentence))) delivered = true;
460462 }
461463 if (delivered || !reachable) markRollbackPaged(dataDir);
462464 }
src/kernel/vitals.ts +4 −3
@@ -13,7 +13,7 @@ import { statfsSync, statSync } from "node:fs";
1313 import { dirname } from "node:path";
1414 import { freemem, totalmem } from "node:os";
1515 import { refusedInternal, type RefusedLedger } from "./internal_refused.ts";
16 import { recentErrors, type ErrorLedger, type ErrorLine } from "./log.ts";
16 import { recentErrors, redactSecrets, type ErrorLedger, type ErrorLine } from "./log.ts";
1717 import {
1818 budgetFailures,
1919 leaseLapsed,
@@ -519,9 +519,10 @@ export function vitals(input: VitalsInput): Vitals {
519519 const unproven = proofNeed(input.dataDir, runningVersion().version);
520520 if (unproven !== undefined) need("release", unproven.sentence, unproven.since, "/board");
521521
522 // A roll the image's launcher undid is a card until a later version reads ready.
522 // A roll the image's launcher undid is a card until a later version reads ready. Its sentence
523 // carries the release's own last words (stderr), so anything credential-shaped is masked.
523524 const undone = rollbackNeed(input.dataDir);
524 if (undone !== undefined) need("release:rolled-back", undone.sentence, undone.since, "/board");
525 if (undone !== undefined) need("release:rolled-back", redactSecrets(undone.sentence), undone.since, "/board");
525526
526527 // Production serving a version older than a release main has had over an hour is a card until they match.
527528 const lagging = behindStanding(now);
src/release/launch.ts +102 −22
@@ -7,8 +7,9 @@
77 * (`release/good/<version>/`: its `src/` and the two files beside it) and
88 * named in `release/good.json`; the one before it is removed. A version
99 * that exits first, or is still not ready when the grace runs out, is
10 * stopped, `release/rolled-back.json` says what happened, and the kept tree
11 * runs under its own stamp. The forge that comes up reads that record: a
10 * stopped, `release/rolled-back.json` says what happened and what the
11 * release last said on stderr (#10249: 0.7.481 left only "it exited with 1"),
12 * and the kept tree runs under its own stamp. The forge that comes up reads that record: a
1213 * card while it stands (`kernel/vitals.ts`) and a page to the admins once
1314 * (`crew/notify.ts`). The next version that reads ready clears it.
1415 *
@@ -43,6 +44,12 @@ const STOP_MS = 10_000;
4344 /** What a kept tree is: what the Dockerfile copies into the image. */
4445 const TREE_PARTS = ["src", "package.json", "tsconfig.json"];
4546 const VERSION = /^[0-9A-Za-z][0-9A-Za-z.+_-]{0,63}$/;
47 /** How much of a release's stderr is kept, to say why it did not become ready. */
48 const TAIL_BYTES = 8_192;
49 /** How long a release that exited has to finish writing its last words. */
50 const LAST_WORDS_MS = 1_000;
51 /** How long the last words in the record may be. */
52 const SAID_MAX = 200;
4653
4754 export interface Good {
4855 readonly version: string;
@@ -59,6 +66,8 @@ export interface RolledBack {
5966 readonly to: string;
6067 readonly at: string;
6168 readonly why: string;
69 /** The release's last error line on stderr, when it wrote one: what a person reads to fix it. */
70 readonly said: string | null;
6271 /** Whether the admins were told; set once by the forge that told them. */
6372 readonly paged: boolean;
6473 }
@@ -130,10 +139,10 @@ export function keepGood(
130139 export function rolledBack(dataDir: string): RolledBack | undefined {
131140 const r = readJson(rolledFile(dataDir));
132141 if (r === undefined) return undefined;
133 const { from, to, at, why, paged } = r;
142 const { from, to, at, why, said, paged } = r;
134143 if (typeof from !== "string" || typeof to !== "string" || typeof at !== "string" || typeof why !== "string")
135144 return undefined;
136 return { from, to, at, why, paged: paged === true };
145 return { from, to, at, why, said: typeof said === "string" && said !== "" ? said : null, paged: paged === true };
137146 }
138147
139148 /** Record that the admins were told, so no later boot tells them again. */
@@ -146,7 +155,54 @@ export function markRollbackPaged(dataDir: string): void {
146155 export function rollbackNeed(dataDir: string): { sentence: string; since: string } | undefined {
147156 const r = rolledBack(dataDir);
148157 if (r === undefined) return undefined;
149 return { sentence: `Release ${r.from} did not become ready (${r.why}); rolled back to ${r.to}.`, since: r.at };
158 const said = r.said === null ? "" : ` It said: ${r.said}`;
159 return { sentence: `Release ${r.from} did not become ready (${r.why}); rolled back to ${r.to}.${said}`, since: r.at };
160 }
161
162 /**
163 * The line of a release's stderr that says why it stopped: the last error
164 * line (`error: …`, `SQLiteError: …`) when there is one, else the last line
165 * that is not a stack frame, a source excerpt or Bun's version banner.
166 */
167 export function lastWords(stderr: string): string | null {
168 const lines = stderr
169 .replace(/\x1b\[[0-9;]*[A-Za-z]/g, "")
170 .split("\n")
171 .map((line) => line.trim())
172 .filter((line) => line !== "" && !/^at\s/.test(line) && !/^Bun v\d/.test(line) && !/^\d+\s*\|/.test(line) && !/^\^+$/.test(line));
173 const line = lines.findLast((l) => /^(?:\w*Error|error)(?::|\s|$)/.test(l)) ?? lines.at(-1);
174 if (line === undefined) return null;
175 return line.length > SAID_MAX ? `${line.slice(0, SAID_MAX - 1)}…` : line;
176 }
177
178 /** A child's stderr, passed through to ours, with its tail kept until `forget`. */
179 interface Heard {
180 readonly ended: Promise<void>;
181 tail(): string;
182 forget(): void;
183 }
184
185 function hear(stream: ReadableStream<Uint8Array>): Heard {
186 let kept: Buffer | undefined = Buffer.alloc(0);
187 const ended = (async () => {
188 try {
189 for await (const chunk of stream) {
190 process.stderr.write(chunk);
191 if (kept === undefined) continue;
192 kept = Buffer.concat([kept, chunk]);
193 if (kept.length > TAIL_BYTES) kept = kept.subarray(kept.length - TAIL_BYTES);
194 }
195 } catch {
196 // the pipe closing under us is the child going: what was heard stands
197 }
198 })();
199 return {
200 ended,
201 tail: () => kept?.toString("utf8") ?? "",
202 forget: () => {
203 kept = undefined;
204 },
205 };
150206 }
151207
152208 /**
@@ -211,7 +267,13 @@ export type Launched =
211267 | { readonly ran: "release" | "rollback"; readonly child: Subprocess; readonly line: string }
212268 | { readonly ran: "none"; readonly line: string };
213269
214 function start(input: LaunchInput, tree: string, version: string, commit: string | null): Subprocess {
270 /** A release started, and what it says on stderr. */
271 interface Started {
272 readonly child: Subprocess;
273 readonly heard: Heard;
274 }
275
276 function start(input: LaunchInput, tree: string, version: string, commit: string | null): Started {
215277 const env: Record<string, string> = {};
216278 for (const [k, v] of Object.entries(input.env)) if (v !== undefined) env[k] = v;
217279 env["FORGE_VERSION"] = version;
@@ -223,22 +285,35 @@ function start(input: LaunchInput, tree: string, version: string, commit: string
223285 env,
224286 stdin: "ignore",
225287 stdout: "inherit",
226 stderr: "inherit",
288 // Piped, not inherited, so a release that dies says why in the record; every byte still reaches ours.
289 stderr: "pipe",
227290 });
228291 input.started?.(child);
229 return child;
292 return { child, heard: hear(child.stderr) };
230293 }
231294
232 /** Wait for `child` to answer health as `version`: undefined once it does, else why it did not. */
233 async function becomesReady(input: LaunchInput, child: Subprocess, version: string): Promise<string | undefined> {
295 /** Why a release did not become ready, and the last line it wrote on stderr. */
296 interface NotReady {
297 readonly why: string;
298 readonly said: string | null;
299 }
300
301 /** Wait for the release to answer health as `version`: undefined once it does, else why it did not. */
302 async function becomesReady(input: LaunchInput, { child, heard }: Started, version: string): Promise<NotReady | undefined> {
234303 const now = input.now ?? Date.now;
235304 const grace = input.graceMs ?? READY_GRACE_MS;
236305 const began = now();
237306 for (;;) {
238 if (input.stopping?.()) return "asked to stop before it was ready";
239 if (gone(child)) return `it exited with ${child.exitCode ?? child.signalCode} before it was ready`;
240 if ((await versionAt(input.port, probeHeaders(input.dataDir))) === version) return undefined;
241 if (now() - began >= grace) return `not ready within ${Math.round(grace / 1000)}s`;
307 if (input.stopping?.()) return { why: "asked to stop before it was ready", said: null };
308 if (gone(child)) {
309 await Promise.race([heard.ended, Bun.sleep(LAST_WORDS_MS)]);
310 return { why: `it exited with ${child.exitCode ?? child.signalCode} before it was ready`, said: lastWords(heard.tail()) };
311 }
312 if ((await versionAt(input.port, probeHeaders(input.dataDir))) === version) {
313 heard.forget();
314 return undefined;
315 }
316 if (now() - began >= grace) return { why: `not ready within ${Math.round(grace / 1000)}s`, said: lastWords(heard.tail()) };
242317 await Bun.sleep(POLL_MS);
243318 }
244319 }
@@ -252,19 +327,20 @@ async function becomesReady(input: LaunchInput, child: Subprocess, version: stri
252327 export async function launch(input: LaunchInput): Promise<Launched> {
253328 const now = input.now ?? Date.now;
254329 const swapped = lastGood(input.dataDir);
255 let passed: { version: string; why: string } | undefined;
330 let passed: ({ version: string } & NotReady) | undefined;
256331 if (swapped !== undefined && swapped.base === input.version && swapped.version !== input.version) {
257332 const first = start(input, goodTree(input.dataDir, swapped.version), swapped.version, swapped.commit);
258333 const failed = await becomesReady(input, first, swapped.version);
259334 if (failed === undefined)
260 return { ran: "release", child: first, line: `${swapped.version} is ready: the swapped release kept over image ${input.version}` };
261 await stop(first);
335 return { ran: "release", child: first.child, line: `${swapped.version} is ready: the swapped release kept over image ${input.version}` };
336 await stop(first.child);
262337 if (input.stopping?.()) return { ran: "none", line: "asked to stop before it was ready" };
263 passed = { version: swapped.version, why: failed };
338 passed = { version: swapped.version, ...failed };
264339 }
265 const release = start(input, input.tree, input.version, input.commit);
266 const why = await becomesReady(input, release, input.version);
267 if (why === undefined) {
340 const started = start(input, input.tree, input.version, input.commit);
341 const release = started.child;
342 const failed = await becomesReady(input, started, input.version);
343 if (failed === undefined) {
268344 try {
269345 keepGood(input.dataDir, input.tree, input.version, input.commit, now());
270346 } catch (error) {
@@ -278,12 +354,14 @@ export async function launch(input: LaunchInput): Promise<Launched> {
278354 to: input.version,
279355 at: new Date(now()).toISOString(),
280356 why: passed.why,
357 said: passed.said,
281358 paged: false,
282359 } satisfies RolledBack);
283360 return { ran: "rollback", child: release, line: `${passed.version}: ${passed.why}; the image ${input.version} runs instead` };
284361 }
285362 return { ran: "release", child: release, line: `${input.version} is ready and kept as the last good release` };
286363 }
364 const { why, said } = failed;
287365 await stop(release);
288366 if (input.stopping?.()) return { ran: "none", line: "asked to stop before it was ready" };
289367 const good = lastGood(input.dataDir);
@@ -294,9 +372,11 @@ export async function launch(input: LaunchInput): Promise<Launched> {
294372 to: good.version,
295373 at: new Date(now()).toISOString(),
296374 why,
375 said,
297376 paged: false,
298377 } satisfies RolledBack);
299 const child = start(input, goodTree(input.dataDir, good.version), good.version, good.commit);
378 const { child, heard } = start(input, goodTree(input.dataDir, good.version), good.version, good.commit);
379 heard.forget();
300380 return { ran: "rollback", child, line: `${input.version}: ${why}; rolled back to ${good.version}` };
301381 }
302382
test/notify-rollback.test.ts +10 −2
@@ -42,11 +42,11 @@ afterEach(async () => {
4242 await rm(dataDir, { recursive: true, force: true });
4343 });
4444
45 const record = () => {
45 const record = (said?: string) => {
4646 mkdirSync(join(dataDir, "release"), { recursive: true });
4747 writeFileSync(
4848 join(dataDir, "release", "rolled-back.json"),
49 JSON.stringify({ from: "0.7.166", to: "0.7.162", at: "2026-10-19T05:17:00.000Z", why: "it exited with 1 before it was ready", paged: false }),
49 JSON.stringify({ from: "0.7.166", to: "0.7.162", at: "2026-10-19T05:17:00.000Z", why: "it exited with 1 before it was ready", said, paged: false }),
5050 );
5151 };
5252
@@ -96,3 +96,11 @@ test("no record, no page", async () => {
9696 await boot();
9797 expect(posts).toEqual([]);
9898 });
99
100 test("the release's last words reach the card and the page, with anything credential-shaped masked", async () => {
101 record("error: GET https://x.test failed with Bearer abcdefghijklmnopqrstuvwxyz0123");
102 const said = `${SENTENCE} It said: error: GET https://x.test failed with [redacted]`;
103 expect(vitals({ db: app.db, signals: app.signals, dataDir }).degraded.find((d) => d.cause === "release:rolled-back")?.sentence).toBe(said);
104 await boot();
105 expect(posts).toEqual([`${said}\nhttps://forge.example.test/`]);
106 });
test/release-launch.test.ts +42 −1
@@ -14,6 +14,7 @@ import type { Subprocess } from "bun";
1414 import {
1515 keepGood,
1616 lastGood,
17 lastWords,
1718 launch,
1819 markRollbackPaged,
1920 READY_GRACE_MS,
@@ -53,6 +54,8 @@ Bun.serve({ hostname: "127.0.0.1", port: Number(process.env.PORT), fetch(req) {
5354 `;
5455 const THROWS = `throw new Error("(test fixture) a release whose main throws at import, as 0.7.166's did");\n`;
5556 const HANGS = `setInterval(() => {}, 1_000);\n`;
57 const REFUSES = `console.error("FORGE_DRAIN_LINGER_S: whole seconds from 0 to 60, not \\"x\\""); process.exit(1);\n`;
58 const SAYS_THEN_HANGS = `console.error("waiting on the database"); setInterval(() => {}, 1_000);\n`;
5659
5760 async function freePort(): Promise<number> {
5861 const probe = Bun.serve({ hostname: "127.0.0.1", port: 0, fetch: () => new Response("") });
@@ -104,7 +107,8 @@ test("a version whose main throws at import is undone at once: the last good one
104107 expect(await healthAt(launched.port)).toMatchObject({ version: "0.7.162", commit: "a".repeat(40) });
105108 expect(rolledBack(data)).toMatchObject({ from: "0.7.166", to: "0.7.162", paged: false });
106109 expect(rollbackNeed(data)?.sentence).toBe(
107 "Release 0.7.166 did not become ready (it exited with 1 before it was ready); rolled back to 0.7.162.",
110 "Release 0.7.166 did not become ready (it exited with 1 before it was ready); rolled back to 0.7.162." +
111 " It said: error: (test fixture) a release whose main throws at import, as 0.7.166's did",
108112 );
109113 expect(lastGood(data)?.version).toBe("0.7.162");
110114 });
@@ -119,6 +123,43 @@ test("a version that never becomes ready is undone when the grace runs out, well
119123 expect(await healthAt(launched.port)).toMatchObject({ version: "0.7.162" });
120124 });
121125
126 test("a release that refuses its config and exits is recorded with the line it wrote (#10249)", async () => {
127 const data = join(root, "data-refuses");
128 keepGood(data, tree(SERVES), "0.7.479", null);
129 expect((await run(data, tree(REFUSES), "0.7.481")).ran).toBe("rollback");
130 expect(rolledBack(data)).toMatchObject({
131 from: "0.7.481",
132 why: "it exited with 1 before it was ready",
133 said: 'FORGE_DRAIN_LINGER_S: whole seconds from 0 to 60, not "x"',
134 });
135 });
136
137 test("a release that hangs is recorded with the last line it wrote before the grace ran out", async () => {
138 const data = join(root, "data-says-hangs");
139 keepGood(data, tree(SERVES), "0.7.162", null);
140 await run(data, tree(SAYS_THEN_HANGS), "0.7.168", 500);
141 expect(rolledBack(data)).toMatchObject({ why: "not ready within 1s", said: "waiting on the database" });
142 });
143
144 test("last words are the last error line, past the stack, the excerpt and the banner, and clamped", () => {
145 const bun = [
146 "2026-11-09T15:44:50.000Z INFO [forge] reconciled repos=3",
147 "1 | throw new Error(\"x\");",
148 " ^",
149 "\x1b[31mSQLiteError\x1b[0m: database is locked",
150 " at migrate (/app/src/core/schema.ts:40:3)",
151 "",
152 "Bun v1.3.14 (Linux x64 baseline)",
153 "",
154 ].join("\n");
155 expect(lastWords(bun)).toBe("SQLiteError: database is locked");
156 expect(lastWords("starting\nPORT must be a port number\n")).toBe("PORT must be a port number");
157 expect(lastWords("\n\n")).toBeNull();
158 const long = lastWords(`error: ${"y".repeat(400)}`);
159 expect(long?.length).toBe(200);
160 expect(long?.endsWith("…")).toBe(true);
161 });
162
122163 test("with nothing kept, or only itself, there is nothing to roll back to", async () => {
123164 expect(await run(join(root, "data-empty"), tree(THROWS), "0.7.166")).toMatchObject({
124165 ran: "none",
test/spawn-pipes.test.ts +1
@@ -32,6 +32,7 @@ const PIPING: Record<string, { sites: string[]; reason: string }> = {
3232 "src/kernel/data_home.ts": { sites: ["stdout"], reason: "spawnSync buffers stdout; stderr ignored" },
3333 "src/looks/capture.ts": { sites: ["stderr"], reason: "stderr read in a background loop; stdout ignored" },
3434 "src/release/devtools.ts": { sites: ["stderr"], reason: "stderr read for the DevTools address, then drained in a background loop; stdout ignored" },
35 "src/release/launch.ts": { sites: ["stderr"], reason: "hear() reads stderr to its end for the release's life, passing every chunk through to ours and keeping the tail until ready; stdout inherited" },
3536 "src/release/boot.ts": { sites: ["stderr"], reason: "stderr read to its end in a background loop, awaited before the reason is read; stdout ignored" },
3637 "src/snapshot/boot.ts": { sites: ["stderr"], reason: "stderr read to its end in a background loop, awaited before the exit is read for a lost port; stdout ignored" },
3738 "src/release/checkout.ts": { sites: ["stdout+stderr"], reason: "stdout and stderr both read via Response.text()" },

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs