From b399611070fea0d6b195623969ac08a702e7cce0 Mon Sep 17 00:00:00 2001 From: os-zhuang Date: Mon, 10 Aug 2026 09:58:53 +0000 Subject: [PATCH 1/3] test(metadata-fs): derive the dot-root watcher waits from the case budget (#7369) Both positive waits in `watch-dot-root.test.ts` raced a fixed 20s wall-clock budget and then asserted an exact count, so a delivery that was merely LATE reported as `received 0` -- indistinguishable from a broken watcher. That is what ejected PR #7333, which touches nothing in this package, from the merge queue. `waitForEvent` now polls until the event lands or until the case's own ceiling, so the only budget left is `CASE_TIMEOUT_MS`. Co-Authored-By: Claude --- .../metadata-fs/test/watch-dot-root.test.ts | 118 +++++++++++++----- 1 file changed, 89 insertions(+), 29 deletions(-) diff --git a/packages/metadata-fs/test/watch-dot-root.test.ts b/packages/metadata-fs/test/watch-dot-root.test.ts index 354ac104b8..0fcf943b19 100644 --- a/packages/metadata-fs/test/watch-dot-root.test.ts +++ b/packages/metadata-fs/test/watch-dot-root.test.ts @@ -35,38 +35,91 @@ const ref = (name: string): MetaRef => ({ org: 'system', type: 'view', name }); const sleep = (ms: number) => new Promise((r) => setTimeout(r, ms)); /** - * Deadline for a **positive** watcher assertion — the longest a case waits for - * an event it expects to arrive. Each wait races this against the event - * promise, so a healthy run still finishes in roughly the poll interval; the - * number is only ever paid on the way to a failure. - * - * Sized for the merge queue, not for a quiet laptop. The queue runs the FULL - * suite (PR-side CI runs only the affected subset), and this watcher rides - * `usePolling: 1000ms` plus an `awaitWriteFinish` stability window — both are - * wall-clock timers that stretch when the runner is saturated, while the - * assertions themselves are unaffected. PR #7208 was ejected from the queue - * twice on exactly that: first `fs-behavior.test.ts > chokidar: external file - * change emits an update event` (3s deadline), then this file's positive case - * (8s deadline) — both green on the identical SHA in PR CI and locally. + * Reserve held back from the case ceiling so that a missing event is reported + * by this file's own assertion ("expected length 1, received 0") rather than + * by a bare vitest timeout. Covers `sink.stop()`, `repo.close()` and the + * tmpdir teardown in `afterEach`. + */ +const TEARDOWN_RESERVE_MS = 5_000; + +/** + * Poll interval for `waitForEvent`. A healthy run leaves the wait on the first + * turn after delivery, so this is what a passing case pays, not the ceiling. */ -const EVENT_WAIT_MS = 20_000; +const EVENT_POLL_MS = 50; /** * Quiet window for the **negative** assertion below. ⛔ Never shorten this: a * too-short quiet window cannot fail, it can only produce a FALSE PASS on an - * empty-array assertion. Its liveness control uses `EVENT_WAIT_MS` like every - * other positive wait — the control is a positive assertion and flakes under - * load the same way. + * empty-array assertion. + * + * This one budget stays wall-clock, because you cannot wait for an absence — + * and that is a real limit, not a solved problem. Measured for #7369: under + * event-loop starvation heavy enough to push delivery to 32-36s, a 4s window + * is no longer a window at all and the emptiness below becomes a false pass. + * The case's *positive* control underneath is what still has teeth there, and + * it is now deadline-driven (`waitForEvent`) rather than fixed-budget. */ const QUIET_WINDOW_MS = 4_000; /** - * Per-case ceiling. Has to clear the quiet window plus a full `EVENT_WAIT_MS` - * plus repository setup, or the case dies on the vitest timeout before its own - * deadline is reached — which reports as a timeout rather than as the missing - * event, and re-introduces the flake the deadlines above are widening away. + * Per-case ceiling — and, since #7369, the **source** of every positive wait's + * budget: `waitForEvent` waits until `caseDeadline()`, which is this value + * measured from the case's own start minus `TEARDOWN_RESERVE_MS`. There is no + * second, smaller wall-clock budget left in the file to expire first. + * + * Sized from measurement, not taste. Under in-process event-loop starvation + * (the loop blocked ~99.75% of the time) delivery of a single external edit + * was measured at 24-36s while still arriving every time; the quiet window and + * repository setup ahead of it stretch too. 120s clears that with margin, and + * a healthy run pays none of it — every wait exits on delivery. + */ +const CASE_TIMEOUT_MS = 120_000; + +/** + * The budget every positive wait in this file spends, measured from the start + * of the case that calls it. Call it as the case's first statement. + */ +const caseDeadline = (): number => Date.now() + CASE_TIMEOUT_MS - TEARDOWN_RESERVE_MS; + +/** + * Wait until the sink has delivered at least one event, or until `deadline`. + * + * ⛔ Never put a *fixed* wall-clock budget back here. The shape this replaced + * was `Promise.race([sink.first, sleep(EVENT_WAIT_MS)])` with a hard-coded + * `EVENT_WAIT_MS = 20_000`, and #7369 is what that costs: the budget is a + * constant while the thing it is timing is not. This watcher rides + * `usePolling: 1000ms` plus an `awaitWriteFinish` stability window, both of + * which stretch with runner load — and the merge queue, which runs the FULL + * suite while PR-side CI runs only the affected subset, is the most loaded + * context this file ever executes in. When the fixed budget expires first the + * case reports `received 0`, which reads as "the watcher is broken" and is + * really "the test stopped listening too early". PR #7333 was ejected from the + * queue by exactly that, having touched nothing in this package. + * + * Measured for #7369 on `18ff1dab1`, one external edit per iteration, under + * in-process event-loop starvation (the case blocks its own loop for BLOCK ms + * out of every BLOCK+GAP ms), external CPU oversubscription alongside: + * + * BLOCK/GAP n delivery old fixed-budget shape this shape + * (none) 60 650-707ms green green + * 300/10 40 3.6-4.9s green green + * 900/5 12 9.9-12.7s green green + * 2000/5 8 24-36s RED 5/8 green 8/8 + * + * The event arrived in 120 of 120 iterations — delivery goes *late*, never + * missing. (The failure mode where it never arrives at all was a different + * defect, #7282, fixed at the source in `ab07b5382`; it is not what this + * shape defends against.) So the only thing that decided pass or fail at the + * bottom row was whether the test was still listening, which is why the budget + * now comes from `CASE_TIMEOUT_MS` instead of a number chosen in advance. */ -const CASE_TIMEOUT_MS = 60_000; +async function waitForEvent( + sink: { events: MetadataEvent[] }, + deadline: number, +): Promise { + while (sink.events.length === 0 && Date.now() < deadline) await sleep(EVENT_POLL_MS); +} describe('FileSystemRepository watcher — dot-rooted watch root (#7150)', () => { /** Stands in for the project directory. */ @@ -92,30 +145,26 @@ describe('FileSystemRepository watcher — dot-rooted watch root (#7150)', () => */ function collectEvents(r: FileSystemRepository): { events: MetadataEvent[]; - first: Promise; stop: () => Promise; } { const iter = r.watch({ org: 'system' }, 999)[Symbol.asyncIterator](); const events: MetadataEvent[] = []; - let resolveFirst!: () => void; - const first = new Promise((res) => { resolveFirst = res; }); let stopped = false; void (async () => { while (!stopped) { const next = await iter.next(); if (next.done) return; events.push(next.value as MetadataEvent); - resolveFirst(); } })(); return { events, - first, stop: async () => { stopped = true; await iter.return?.(undefined); }, }; } it('sees an external edit when the root is under a dot-directory', async () => { + const deadline = caseDeadline(); repo = new FileSystemRepository({ root, org: 'system' }); // watcher ENABLED await repo.start(); @@ -136,9 +185,19 @@ describe('FileSystemRepository watcher — dot-rooted watch root (#7150)', () => JSON.stringify({ label: 'externally edited' }, null, 2), ); - await Promise.race([sink.first, sleep(EVENT_WAIT_MS)]); + await waitForEvent(sink, deadline); await sink.stop(); + // ⚠️ The exact count is a GUARD, not evidence of de-duplication: a second + // chokidar delivery of this same write cannot produce a second + // `MetadataEvent`, because `handleFsChange` returns early on + // `currentHead === hash`. Measured for #7369 — 0 duplicates in 120 + // iterations across four starvation levels, and 0 is the only number that + // branch can produce. What the count still has teeth for is a *different* + // event sneaking in: the repository's own `put` above escaping self-write + // suppression, or a dot entry leaking past `isIgnoredWatchPath`. That is + // why it stays exact — and why it is asserted only once the awaited event + // has actually arrived, so a slow runner cannot turn it into `received 0`. expect(sink.events).toHaveLength(1); expect(sink.events[0]!.op).toBe('update'); expect(sink.events[0]!.ref.name).toBe('case_grid'); @@ -147,6 +206,7 @@ describe('FileSystemRepository watcher — dot-rooted watch root (#7150)', () => }, CASE_TIMEOUT_MS); it('still ignores dot entries UNDER the root, including its own bookkeeping', async () => { + const deadline = caseDeadline(); repo = new FileSystemRepository({ root, org: 'system' }); // watcher ENABLED await repo.start(); await repo.put(ref('seed'), { label: 'seed' }, { parentVersion: null, actor: 'tester' }); @@ -178,7 +238,7 @@ describe('FileSystemRepository watcher — dot-rooted watch root (#7150)', () => path.join(root, 'view', 'seed.json'), JSON.stringify({ label: 'really edited' }, null, 2), ); - await Promise.race([sink.first, sleep(EVENT_WAIT_MS)]); + await waitForEvent(sink, deadline); await sink.stop(); expect(sink.events).toHaveLength(1); From cc02ed9b1196be4fac93deabc1dc82807965c1d1 Mon Sep 17 00:00:00 2001 From: os-zhuang Date: Mon, 10 Aug 2026 10:04:11 +0000 Subject: [PATCH 2/3] test(metadata-fs): give the dot-root hooks a budget that survives runner load (#7369) Fixing the case budget exposed the next fixed wall-clock budget behind it: vitest times hooks separately on a 10s default, so under starvation both cases failed with "Hook timed out in 10000ms" while their assertions were satisfied. Co-Authored-By: Claude --- packages/metadata-fs/test/watch-dot-root.test.ts | 15 +++++++++++++-- 1 file changed, 13 insertions(+), 2 deletions(-) diff --git a/packages/metadata-fs/test/watch-dot-root.test.ts b/packages/metadata-fs/test/watch-dot-root.test.ts index 0fcf943b19..7b3a03f0b3 100644 --- a/packages/metadata-fs/test/watch-dot-root.test.ts +++ b/packages/metadata-fs/test/watch-dot-root.test.ts @@ -76,6 +76,17 @@ const QUIET_WINDOW_MS = 4_000; */ const CASE_TIMEOUT_MS = 120_000; +/** + * Budget for `beforeEach` / `afterEach`, which vitest times SEPARATELY from the + * case: `hookTimeout` defaults to 10s and the per-case ceiling does not cover + * it. Measured for #7369 — with the case budget fixed and nothing else changed, + * this became the next fixed wall-clock budget to expire first, and both cases + * failed with "Hook timed out in 10000ms" while their assertions were still + * satisfied. `repo.close()` stops a polling chokidar watcher and `fs.rm` walks + * a temp tree; both stretch with runner load exactly like the waits above do. + */ +const HOOK_TIMEOUT_MS = 30_000; + /** * The budget every positive wait in this file spends, measured from the start * of the case that calls it. Call it as the case's first statement. @@ -131,13 +142,13 @@ describe('FileSystemRepository watcher — dot-rooted watch root (#7150)', () => beforeEach(async () => { base = await fs.mkdtemp(path.join(os.tmpdir(), 'objectstack-fs7150-')); root = path.join(base, '.objectstack', 'metadata'); - }); + }, HOOK_TIMEOUT_MS); afterEach(async () => { if (repo) await repo.close().catch(() => undefined); repo = undefined; await fs.rm(base, { recursive: true, force: true }); - }); + }, HOOK_TIMEOUT_MS); /** * Drain `repo.watch()` into an array for the life of the case. `since: 999` From 8518b838ca5e4d715988a1623fa720187f034434 Mon Sep 17 00:00:00 2001 From: os-zhuang Date: Mon, 10 Aug 2026 10:21:38 +0000 Subject: [PATCH 3/3] docs(metadata-fs): point the quiet-window comment at the finding it opened (#7369) Co-Authored-By: Claude --- packages/metadata-fs/test/watch-dot-root.test.ts | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/packages/metadata-fs/test/watch-dot-root.test.ts b/packages/metadata-fs/test/watch-dot-root.test.ts index 7b3a03f0b3..f26412ac81 100644 --- a/packages/metadata-fs/test/watch-dot-root.test.ts +++ b/packages/metadata-fs/test/watch-dot-root.test.ts @@ -58,7 +58,8 @@ const EVENT_POLL_MS = 50; * event-loop starvation heavy enough to push delivery to 32-36s, a 4s window * is no longer a window at all and the emptiness below becomes a false pass. * The case's *positive* control underneath is what still has teeth there, and - * it is now deadline-driven (`waitForEvent`) rather than fixed-budget. + * it is now deadline-driven (`waitForEvent`) rather than fixed-budget. Making + * this half sound needs a different shape than a longer number — see #7408. */ const QUIET_WINDOW_MS = 4_000;