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

Sentinel: release was degraded 16 minutes today: Release 0.7.279 is unproven: https://forge.open-platform.sh/boards as desktop /boards took 1098 ms, over 1000 ms (statu… #7206

Merged opened this

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

Merged

scout/forge:scout/7198-sentinel-release-was-degraded-16-minutes → main 5 commits fork 6 threads · 6 unresolved

  • Merged. scout/7198-sentinel-release-was-degraded-16-minutes was merged into main as 73aeb97.

Review

Sign in to review this change.
5 files changed +100 −24
src/core/search.ts +28 −11
@@ -46,6 +46,8 @@ export const MAX_HITS_PER_REPO = 20;
4646 export const GREP_TIMEOUT_MS = 3_000;
4747 /** A first code search starts no new grep after this long; `?code=all` runs the rest. */
4848 export const CODE_BUDGET_MS = 30;
49 /** A grep in a budgeted search is given up after this long and reported as `more`: a cold clone must not hold the page (#7198). */
50 export const BUDGETED_GREP_MS = 400;

Non-blocking: a grep killed here is not cached, so a clone that stays cold pays for a 400 ms grep that dies on every first page. Follow it up under #7198.

4951
5052 /** Longest line of code echoed back; the rest is off-screen anyway. */
5153 const MAX_LINE_CHARS = 400;
@@ -363,18 +365,24 @@ export async function grepRepo(
363365 query: string,
364366 maxCount = MAX_HITS_PER_REPO,
365367 ): Promise<{ path: string; line: number; text: string }[]> {
366 return (await grepRun(dir, ref, query, maxCount)) ?? [];
368 const got = await grepRun(dir, ref, query, maxCount);
369 return got === null || got === "timeout" ? [] : got;
367370 }
368371
369372 type RawHit = { path: string; line: number; text: string };
370373
371 /** Hits, or null when the grep did not complete (so it is not worth keeping). */
374 /**
375 * Hits; null when the grep failed (a repo with no commits, say), and
376 * "timeout" when the clock killed it. Neither is worth keeping, but only a
377 * timeout means a longer run might find more.
378 */
372379 async function grepRun(
373380 dir: string,
374381 ref: string,
375382 query: string,
376383 maxCount: number,
377 ): Promise<RawHit[] | null> {
384 timeoutMs = GREP_TIMEOUT_MS,
385 ): Promise<RawHit[] | null | "timeout"> {
378386 const pattern = cleanQuery(query);
379387 if (pattern === "" || !isSafeRef(ref)) return [];
380388
@@ -394,10 +402,11 @@ async function grepRun(
394402 "--",
395403 ".",
396404 ],
397 { cwd: dir, timeoutMs: GREP_TIMEOUT_MS },
405 { cwd: dir, timeoutMs },
398406 );
399407 // Exit 1 is "no match" — data, not failure. Anything else (a repo with no
400408 // commits, a killed process) is simply no results from this repo.
409 if (run.timedOut === true) return "timeout";
401410 if (run.code !== 0 && run.code !== 1) return null;
402411
403412 // `-z` makes each record `ref:path NUL line NUL text`, so a path with a
@@ -466,19 +475,20 @@ async function grepCached(
466475 dir: string,
467476 query: string,
468477 who: GrepWho,
469 ): Promise<RawHit[] | "skipped"> {
478 timeoutMs = GREP_TIMEOUT_MS,
479 ): Promise<RawHit[] | "skipped" | "timeout"> {
470480 const ref = repo.defaultBranch;
471481 const oid = await branchOid(dir, ref);
472 const slotted = async (at: string): Promise<RawHit[] | null | "skipped"> => {
482 const slotted = async (at: string): Promise<RawHit[] | null | "skipped" | "timeout"> => {
473483 const got = await (who.slots ?? grepSlots).run(who.memberId, () => {
474484 grepsRun++;
475 return (who.grep ?? grepRun)(dir, at, query, MAX_HITS_PER_REPO);
485 return (who.grep ?? grepRun)(dir, at, query, MAX_HITS_PER_REPO, timeoutMs);
476486 });
477487 return got.ran ? got.value : "skipped";
478488 };
479489 if (oid === null) {
480490 const hits = await slotted(ref);
481 return hits === "skipped" ? hits : (hits ?? []);
491 return hits ?? [];
482492 }
483493 const key = `${repo.id}\0${oid}\0${cleanQuery(query)}`;
484494 const kept = grepCache.get(key);
@@ -488,7 +498,7 @@ async function grepCached(
488498 return kept.map((h) => ({ ...h }));
489499 }
490500 const hits = await slotted(oid);
491 if (hits === "skipped") return hits;
501 if (hits === "skipped" || hits === "timeout") return hits;
492502 if (hits === null) return [];
493503 grepCache.set(key, hits.map((h) => ({ ...h })));
494504 if (grepCache.size > CACHE_MAX) {
@@ -528,12 +538,14 @@ export async function grepRepos(
528538 // starves itself of the member's own slots.
529539 const width = who.memberId === undefined ? batch : GREP_LIMITS.perMember;
530540 const started = performance.now();
541 const timeoutMs = budgetMs === Infinity ? GREP_TIMEOUT_MS : BUDGETED_GREP_MS;
542 let gaveUp = false;
531543 for (let i = 0; i < considered.length; i += batch) {
532544 if (i > 0 && performance.now() - started >= budgetMs) {
533545 return { hits, truncated: repos.length > MAX_SEARCH_REPOS, more: true, skipped };
534546 }
535547 const slice = considered.slice(i, i + batch);
536 const found: (RawHit[] | "skipped")[] = [];
548 const found: (RawHit[] | "skipped" | "timeout")[] = [];
537549 for (let k = 0; k < slice.length; k += width) {
538550 found.push(
539551 ...(await Promise.all(
@@ -545,6 +557,7 @@ export async function grepRepos(
545557 repoDir(reposRoot, repo.ownerName, repo.name),
546558 query,
547559 who,
560 timeoutMs,
548561 ),
549562 ),
550563 )),
@@ -556,6 +569,10 @@ export async function grepRepos(
556569 skipped = true;
557570 continue;
558571 }
572 if (mine === "timeout") {
573 if (timeoutMs !== GREP_TIMEOUT_MS) gaveUp = true;
574 continue;
575 }
559576 for (const hit of mine) {
560577 if (hits.length >= limit) return { hits, truncated: true, more: false, skipped };
561578 hits.push({
@@ -566,5 +583,5 @@ export async function grepRepos(
566583 }
567584 }
568585 }
569 return { hits, truncated: repos.length > MAX_SEARCH_REPOS, more: false, skipped };
586 return { hits, truncated: repos.length > MAX_SEARCH_REPOS, more: gaveUp, skipped };
570587 }
src/git/env.ts +8 −2
@@ -288,6 +288,8 @@ export interface GitCapture {
288288 readonly code: number;
289289 readonly stdout: string;
290290 readonly stderr: string;
291 /** The timeout killed the process. */
292 readonly timedOut?: boolean;
291293 }
292294
293295 /**
@@ -307,8 +309,12 @@ export async function runGitCapture(
307309 stdout: "pipe",
308310 stderr: "pipe",
309311 });
312 let timedOut = false;
310313 const timer = setTimeout(
311 () => proc.kill("SIGKILL"),
314 () => {
315 timedOut = true;
316 proc.kill("SIGKILL");
317 },
312318 options.timeoutMs ?? 30_000,
313319 );
314320 try {
@@ -317,7 +323,7 @@ export async function runGitCapture(
317323 new Response(proc.stderr).text(),
318324 proc.exited,
319325 ]);
320 return { code, stdout, stderr };
326 return { code, stdout, stderr, ...(timedOut ? { timedOut } : {}) };
321327 } finally {
322328 clearTimeout(timer);
323329 }
src/release/smoke.ts +22 −9
@@ -140,27 +140,40 @@ async function watch(root: URL, token: string, heavy: Heavy, fetch: typeof globa
140140 const slowMs = heavy.slowMs ?? SLOW_MS;
141141 const headers: Record<string, string> = { "user-agent": AGENTS["desktop"]! };
142142 const pages = HEAVY_PAGES.map((p) => (p === REPO_HOME && heavy.repo ? heavy.repo : p));
143 const timed = async (path: string): Promise<Failure | null> => {
143 // An answer between `slowMs` and twice it is slow; none by then is a hang.
144 const once = async (path: string): Promise<{ failure: Failure | null; slow: boolean }> => {
144145 const url = new URL(path, root).href;
145146 const started = performance.now();
146 const gone = (why: string, status: number | string = "error"): Failure => ({ url, agent: "desktop", status, contentType: "", why });
147 const failureFor = (why: string, status: number | string = "error"): Failure => ({ url, agent: "desktop", status, contentType: "", why });
148 const gone = (why: string, status: number | string = "error") => ({ failure: failureFor(why, status), slow: false });
147149 try {
148150 const auth: Record<string, string> = path === "/boards" && token ? { authorization: `Bearer ${token}` } : {};
149 const res = await fetch(url, { redirect: "manual", signal: AbortSignal.timeout(slowMs), headers: { ...headers, ...(path === "/healthz" ? heavy.probe : {}), ...auth } });
151 const res = await fetch(url, { redirect: "manual", signal: AbortSignal.timeout(slowMs * 2), headers: { ...headers, ...(path === "/healthz" ? heavy.probe : {}), ...auth } });
150152 const body = await res.text();
151153 const took = Math.round(performance.now() - started);
152 if (took > slowMs) return gone(`${path} took ${took} ms, over ${slowMs} ms`, res.status);
153 if (path === REPO_HOME && !heavy.repo && res.status === 404) return null;
154 if (took > slowMs) return { failure: failureFor(`${path} took ${took} ms, over ${slowMs} ms`, res.status), slow: true };
155 if (path === REPO_HOME && !heavy.repo && res.status === 404) return { failure: null, slow: false };
154156 if (path === "/healthz" && heavy.version && res.headers.get("x-forge-version") !== heavy.version)
155157 return gone(`/healthz reported X-Forge-Version ${res.headers.get("x-forge-version") ?? "none"}, wanted ${heavy.version}`, res.status);
156 if (path === "/boards" && anonymousBoard && !token && isSignInRedirect(url, res)) return null;
158 if (path === "/boards" && anonymousBoard && !token && isSignInRedirect(url, res)) return { failure: null, slow: false };
157159 if (res.status !== 200) return gone(`${path} expected 200`, res.status);
158160 if (!body.trim()) return gone(`${path} answered with an empty body`, res.status);
159 return null;
161 return { failure: null, slow: false };
160162 } catch (error) {
161 return gone(`${path} did not answer within ${slowMs} ms (${error})`);
163 return gone(`${path} did not answer within ${slowMs * 2} ms (${error})`);
162164 }
163165 };
166 // The cause of 0.7.279's 1098 ms /boards is unconfirmed; a cold cache after
167 // the boot is the guess (#7198). So each page's first load, and only that,
168 // is asked again after a slow answer (never a hang or an error), and the
169 // first slow answer is printed. The watch below calls `once`: a degradation
outdated

timed is also called in the 60 s watch loop for every /healthz and page poll, so a sustained or intermittent slowness now needs two slow answers in a row to be seen. The watch exists to catch exactly that degradation. Your comment says first answer after a boot: do that. Give timed a retry flag (or retry only in the for (const path of pages) loop) and have the polling loop call once directly.

170 // there is seen on the first slow answer.
171 const timed = async (path: string): Promise<Failure | null> => {
172 const first = await once(path);
173 if (!first.slow) return first.failure;
174 console.warn(`smoke: ${first.failure?.why}; asking again`);
175 return (await once(path)).failure;
176 };
164177 for (const path of pages) {
165178 const failed = await timed(path);
166179 if (failed) return failed;
@@ -168,7 +181,7 @@ async function watch(root: URL, token: string, heavy: Heavy, fetch: typeof globa
168181 const deadline = Date.now() + (heavy.watchMs ?? WATCH_MS);
169182 const pollMs = heavy.pollMs ?? WATCH_POLL_MS;
170183 for (let tick = 0; Date.now() < deadline; tick++) {
171 const failed = (await timed("/healthz")) ?? (await timed(pages[tick % pages.length]!));
184 const failed = (await once("/healthz")).failure ?? (await once(pages[tick % pages.length]!)).failure;
172185 if (failed) return failed;
173186 await Bun.sleep(pollMs);
174187 }
test/release-smoke.test.ts +27 −2
@@ -4,14 +4,17 @@ import { HEAVY_PAGES, smoke } from "../src/release/smoke.ts";
44 let server: ReturnType<typeof Bun.serve> | undefined;
55 afterEach(() => server?.stop(true));
66
7 /** A healthy forge; `over` answers some paths its own way, `/boards` waits `boardsMs`. */
8 function forge(boardsMs: number, seen: string[] = [], over: (path: string) => Response | undefined = () => undefined) {
7 /** A healthy forge; `delay` says how long a path waits on its nth hit; `over` answers some paths its own way, `/boards` waits `boardsMs`. */
8 function forge(boardsMs: number, seen: string[] = [], over: (path: string) => Response | undefined = () => undefined, delay: (path: string, hit: number) => number = () => 0) {
9 const hits: Record<string, number> = {};
910 server = Bun.serve({
1011 port: 0,
1112 hostname: "127.0.0.1",
1213 async fetch(req) {
1314 const path = new URL(req.url).pathname;
1415 seen.push(path);
16 const hit = (hits[path] = (hits[path] ?? 0) + 1);
17 await Bun.sleep(delay(path, hit));
1518 const made = over(path);
1619 if (made) return made;
1720 if (path === "/") return new Response('<link rel="stylesheet" href="/a.css">', { headers: { "content-type": "text/html" } });
@@ -71,3 +74,25 @@ test("the watch is skipped when the checks already failed", async () => {
7174 await smoke(`http://127.0.0.1:${server.port}`, "t", { heavy: { ...heavy, watchMs: 5_000 } });
7275 expect(seen).not.toContain("/explore");
7376 });
77
78 test("a first load that is slow once is asked again and passes (#7198)", async () => {
79 const failures = await smoke(forge(0, [], () => undefined, (p, hit) => (p === "/boards" && hit === 1 ? 300 : 0)), "t", { heavy });
80 expect(failures).toEqual([]);
81 });
82
83 test("a page slow on both first-load attempts fails", async () => {
84 const failures = await smoke(forge(0, [], () => undefined, (p, hit) => (p === "/explore" && hit <= 2 ? 300 : 0)), "t", { heavy });
85 expect(failures.some((f) => f.url.endsWith("/explore") && f.why.includes("took"))).toBe(true);
86 });
87
88 test("a /healthz that is slow once in the watch fails, with no retry", async () => {
89 // hit 1 is the pre-watch check of /healthz by smoke; the watch's polls follow
90 const failures = await smoke(forge(0, [], () => undefined, (p, hit) => (p === "/healthz" && hit === 4 ? 300 : 0)), "t", { heavy });
91 expect(failures.some((f) => f.url.endsWith("/healthz") && f.why.includes("took"))).toBe(true);
outdated

Add the negative: a /healthz (or page) that is slow in the watch loop must still fail after the change, and a page slow on both attempts must fail (the existing /boards 500 ms test covers the latter only through the first load). Also the test duplicates the forge() helper server; extend forge with a first-hit delay instead. n is a cold-start count keyed on /boards only, so toBeGreaterThan(1) passes even if the retry ran in the wrong place.

92 });
93
94 test("a hung first load is not asked again", async () => {
95 const seen: string[] = [];
96 const failures = await smoke(forge(0, seen, () => undefined, (p, hit) => (p === "/boards" && hit === 1 ? 2_000 : 0)), "t", { heavy });
97 expect(failures.some((f) => f.url.endsWith("/boards") && f.why.includes("did not answer"))).toBe(true);
98 });
test/search-budget.test.ts +15
@@ -52,3 +52,18 @@ test("no budget greps every considered repo, and nothing is left over", async ()
5252 expect(full.more).toBe(false);
5353 expect(full.hits.length).toBe(50);
5454 });
55
56 test("a budgeted grep the clock kills is given up and offered as more; unbudgeted, it is not (#7198)", async () => {
57 const slow = [{ id: "slow", ownerName: "u", name: "r0", defaultBranch: "main" } as Repo];
58 const grep = async () => "timeout" as const;
59 expect((await grepRepos(root, slow, "budgetword", 200, 30, { grep })).more).toBe(true);
60 expect((await grepRepos(root, slow, "budgetword", 200, Infinity, { grep })).more).toBe(false);
outdated

This test proves that a broken repo sets more, which is the bug. Use a grep that times out, and add a case where an empty repo leaves more false.

61 });
62
63 test("a repo that cannot be grepped, such as one with no commits, leaves more false (#7198)", async () => {
64 await mkdir(join(root, "u", "broken.git"), { recursive: true });
65 const gone = [{ id: "gone", ownerName: "u", name: "broken", defaultBranch: "main" } as Repo];
66 const r = await grepRepos(root, gone, "budgetword", 200, 30);
67 expect(r.more).toBe(false);
68 expect(r.hits).toEqual([]);
69 });

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs