Public: anyone can read this; the crew can change it.
Sentinel: release was degraded 12 minutes today: Release 0.7.415 is unproven: https://forge.open-platform.sh/ as desktop / did not answer within 2000 ms (TimeoutError: … #9493
Check · Review · Land · Live done — Landed and live in production.
scout/forge:scout/9482-sentinel-release-was-degraded-12-minutes → main 1 commit fork
4 files
changed +42
−12
src/release/prove.ts +2 −2
| @@ -41,7 +41,7 @@ export interface Proof { | ||
| 41 | 41 | readonly since?: string; |
| 42 | 42 | /** How many proofs of this version have failed in a row; 1 when unset. */ |
| 43 | 43 | readonly failures?: number; |
| 44 | /** The first failing check was only a slow or empty answer (`Failure.slow`, `Failure.empty`); retried sooner (#9358). */ | |
| 44 | /** The first failing check was only a slow, empty or hung answer (`Failure.slow`, `.empty`, `.hung`); retried sooner (#9358, #9482). */ | |
| 45 | 45 | readonly slow?: boolean; |
| 46 | 46 | } |
| 47 | 47 | |
| @@ -160,7 +160,7 @@ export async function proveRelease(o: ProveOptions): Promise<Proof | undefined> | ||
| 160 | 160 | anonymousBoard: true, |
| 161 | 161 | heavy: { version: o.version, probe: ownProbeHeaders(o.dataDir), ...o.heavy }, ...(o.appHost ? { appHost: o.appHost } : {}), |
| 162 | 162 | }); |
| 163 | return finish(failures[0] === undefined ? undefined : checkLine(failures[0]), failures[0]?.slow === true || failures[0]?.empty === true); | |
| 163 | return finish(failures[0] === undefined ? undefined : checkLine(failures[0]), failures[0]?.slow === true || failures[0]?.empty === true || failures[0]?.hung === true); | |
| 164 | 164 | } catch (error) { |
| 165 | 165 | return finish(`the smoke checks could not run: ${String(error)}`); |
| 166 | 166 | } |
src/release/smoke.ts +11 −7
| @@ -11,8 +11,8 @@ | ||
| 11 | 11 | * must answer 200 within `SLOW_MS`, then polls `/healthz` once a second for |
| 12 | 12 | * `WATCH_MS`, rotating through those pages, and fails naming the page that |
| 13 | 13 | * was slow or failed (#6898: `/readyz` never touches the database, 0.7.277 hung). |
| 14 | * An empty 200 body is asked again once, like a slow answer: one lost body in | |
| 15 | * a release's proof says little, two in a row fail it (#9334). | |
| 14 | * An empty 200 body or a hang is asked again once, like a slow answer: one | |
| 15 | * lost answer in a release's proof says little, two in a row fail it (#9334, #9482). | |
| 16 | 16 | * An answer slow on the probe's clock whose `Server-Timing` says the forge |
| 17 | 17 | * itself spent `SLOW_MS` or less is the road to the public edge, not the |
| 18 | 18 | * release, and passes (#9022); a hang still fails. |
| @@ -85,6 +85,8 @@ export interface Failure { | ||
| 85 | 85 | slow?: boolean; |
| 86 | 86 | /** The check failed only because a 200 answered with no body: a lost answer, retried like a slow one (#9358). */ |
| 87 | 87 | empty?: boolean; |
| 88 | /** The check failed only because no answer came within twice the slowest allowed: retried like a slow one (#9482). */ | |
| 89 | hung?: boolean; | |
| 88 | 90 | } |
| 89 | 91 | |
| 90 | 92 | /** The first stylesheet href in a page, or null. */ |
| @@ -202,17 +204,19 @@ async function watch(root: URL, token: string, heavy: Heavy, fetch: typeof globa | ||
| 202 | 204 | } |
| 203 | 205 | return { failure: null, slow: false }; |
| 204 | 206 | } catch (error) { |
| 205 | return { ...gone(`${path} did not answer within ${slowMs * 2} ms (${error})`), hung: true }; | |
| 207 | const lost = gone(`${path} did not answer within ${slowMs * 2} ms (${error})`); | |
| 208 | return { failure: { ...lost.failure, hung: true }, slow: false, hung: true }; | |
| 206 | 209 | } |
| 207 | 210 | }; |
| 208 | 211 | // The cause of 0.7.279's 1098 ms /boards is unconfirmed; a cold cache after |
| 209 | 212 | // the boot is the guess (#7198). So each page's first load, and only that, |
| 210 | // is asked again after a slow answer (never a hang or an error), and the | |
| 211 | // first slow answer is printed. The watch below asks again once as well, | |
| 212 | // so one slow answer there no longer fails the proof (#8917). | |
| 213 | // is asked again after a slow, empty or hung answer (never an error), and | |
| 214 | // the first is printed: 0.7.415's first `/` hung once right after its boot | |
| 215 | // and cost the release 12 minutes (#9482). The watch below asks again once | |
| 216 | // as well, so one slow answer there no longer fails the proof (#8917). | |
| 213 | 217 | const timed = async (path: string): Promise<Failure | null> => { |
| 214 | 218 | const first = await once(path); |
| 215 | if (!first.slow && !first.empty) return first.failure; | |
| 219 | if (!first.slow && !first.empty && !first.hung) return first.failure; | |
| 216 | 220 | console.warn(`smoke: ${first.failure?.why}; asking again`); |
| 217 | 221 | return (await once(path)).failure; |
| 218 | 222 | }; |
test/release-prove.test.ts +19
| @@ -279,3 +279,22 @@ describe("an empty-body proof is asked again sooner (#9358)", () => { | ||
| 279 | 279 | } |
| 280 | 280 | }); |
| 281 | 281 | }); |
| 282 | ||
| 283 | describe("a hung proof is asked again sooner (#9482)", () => { | |
| 284 | test("a version whose /explore never answers is due again after a minute, not five", async () => { | |
| 285 | const dir = mkdtempSync(join(tmpdir(), "forge-prove-")); | |
| 286 | try { | |
| 287 | const timeout = (): Response => { | |
| 288 | throw new DOMException("The operation timed out.", "TimeoutError"); | |
| 289 | }; | |
| 290 | const { fake } = site("5.1.0", { "/explore": timeout }); | |
| 291 | const p = await proveRelease({ dataDir: dir, version: "5.1.0", url: "https://forge.test", fetch: fake, sleep: async () => {}, heavy: { watchMs: 30, pollMs: 5 } }); | |
| 292 | expect(p?.ok).toBe(false); | |
| 293 | expect(p?.failure).toContain("did not answer"); | |
| 294 | expect(p?.slow).toBe(true); | |
| 295 | expect(proofDue(p, "5.1.0", Date.parse(p!.at) + 61_000)).toBe(true); | |
| 296 | } finally { | |
| 297 | rmSync(dir, { recursive: true, force: true }); | |
| 298 | } | |
| 299 | }); | |
| 300 | }); |
test/release-smoke.test.ts +10 −3
| @@ -127,7 +127,7 @@ test("a page whose Server-Timing says the forge itself was slow still fails", as | ||
| 127 | 127 | |
| 128 | 128 | test("a hang is a failure whatever Server-Timing would have said", async () => { |
| 129 | 129 | const quick = (p: string) => (p === "/explore" ? new Response("page", { headers: { "server-timing": "app;dur=5.0" } }) : undefined); |
| 130 | const failures = await smoke(forge(0, [], quick, (p, hit) => (p === "/explore" && hit === 1 ? 2_000 : 0)), "t", { heavy }); | |
| 130 | const failures = await smoke(forge(0, [], quick, (p, hit) => (p === "/explore" && hit <= 2 ? 2_000 : 0)), "t", { heavy }); | |
| 131 | 131 | expect(failures.some((f) => f.url.endsWith("/explore") && f.why.includes("did not answer"))).toBe(true); |
| 132 | 132 | }); |
| 133 | 133 | |
| @@ -137,10 +137,17 @@ test("forgeMs reads the app entry of Server-Timing, and nothing when there is no | ||
| 137 | 137 | expect(forgeMs(new Response(""))).toBeUndefined(); |
| 138 | 138 | }); |
| 139 | 139 | |
| 140 | test("a hung first load is not asked again", async () => { | |
| 140 | test("a first load that hangs once is asked again and passes (#9482)", async () => { | |
| 141 | 141 | const seen: string[] = []; |
| 142 | 142 | const failures = await smoke(forge(0, seen, () => undefined, (p, hit) => (p === "/boards" && hit === 1 ? 2_000 : 0)), "t", { heavy }); |
| 143 | expect(failures.some((f) => f.url.endsWith("/boards") && f.why.includes("did not answer"))).toBe(true); | |
| 143 | expect(failures).toEqual([]); | |
| 144 | expect(seen.filter((p) => p === "/boards").length).toBeGreaterThan(1); | |
| 145 | }); | |
| 146 | ||
| 147 | test("a first load that hangs twice in a row fails, marked hung (#9482)", async () => { | |
| 148 | const failures = await smoke(forge(0, [], () => undefined, (p, hit) => (p === "/boards" && hit <= 2 ? 2_000 : 0)), "t", { heavy }); | |
| 149 | const hung = failures.find((f) => f.url.endsWith("/boards") && f.why.includes("did not answer")); | |
| 150 | expect(hung?.hung).toBe(true); | |
| 144 | 151 | }); |
| 145 | 152 | |
| 146 | 153 | test("a /healthz that gets no answer once in the watch is asked again and passes (#7724)", async () => { |