From 4ea6bcbe17cb663c51cece7875f9448470bb1a0f Mon Sep 17 00:00:00 2001 From: Steven Syrek Date: Mon, 27 Jul 2026 16:41:45 -0400 Subject: [PATCH] test(sync): stop watchAndSync tests flaking on slow CI runners MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The watchAndSync block intermittently failed CI on unrelated dependency PRs (#81 Jun 30 Node 22, #91 and #93 Jul 27 Node 24), always as a 10s test timeout and never as an assertion, hitting a different test each time. Both #81 and #91 passed on plain re-run with no code change. Three changes, in order of importance: 1. jest.setTimeout(30_000) for the block. The suite runs in ~1.8s locally but was observed at 10.8-10.9s on GitHub runners with 232 suites competing for ~4 cores — i.e. sitting on the 10s default, which tipped an arbitrary test over each time. This is the headroom the block actually needed. 2. flushWatchSetup now waits for an observable readiness signal (mockWatcherOn having been called) instead of burning a fixed round count, then drains a settle budget. attachDebouncedWatchLoop calls watcher.on() in the same synchronous continuation as the process.on('SIGINT') registration, so listeners-attached implies the handler each test uses for shutdown is registered. A fixed count could under-wait; this cannot. On a genuine stall it throws with the pending state instead of timing out mutely. 3. Settle rounds 250 -> 25. Every test in the block passes with as few as 5 (measured), so 25 keeps a 5x margin. On method: the historical escalation was 20 -> 50 -> 250 rounds, each assuming the budget was too small. Suite duration is flat across 250/25/5 rounds, so widening it could never have worked. Four further hypotheses were tested and disproven — slow sweepStaleBackups I/O (its projectRoot '/test' does not exist, so readdir ENOENTs immediately), a hang in controller.shutdown() (microtask-only), expensive flush rounds (0.00ms per 250), and CPU contention (old code passed 12/12 under 16 spinners on 11 cores). Details in bead sync-94ua. Honest limitation: the flake could not be reproduced locally — ~58 runs across five contention profiles (CPU, I/O+CPU, full-suite, starved budget) produced one failure whose identity was lost. So this targets the signature the evidence supports rather than a reproduction, and the new diagnostic ensures the next occurrence identifies itself. Verified: 49 tests in the block pass; 20/20 under combined I/O and CPU contention; lint, type-check, and 5501 tests green on Node 24.18.0. --- CHANGELOG.md | 1 + tests/unit/sync/sync-command.test.ts | 86 ++++++++++++++++++++++++---- 2 files changed, 75 insertions(+), 12 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 7f587f9..aec15cc 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Changed +- **tests**: Raised the timeout for the `watchAndSync` test block to 30s and replaced its fixed-round setup flush with a wait on an observable readiness signal. These tests intermittently exceeded the 10s default on CI runners — always as timeouts, never assertions — failing unrelated dependency PRs. Suite duration was measured to be flat across 250/25/5 flush rounds, so the historical 20 → 50 → 250 escalation could not have addressed it; the cost is runner CPU starvation (1.8s locally vs 10.8s observed on CI). The flush now also fails with the pending state rather than a bare timeout if setup genuinely stalls. - **deps**: `commander` 14.0.3 → 15.0.0. commander 15 is ESM-only (`"type": "module"`) and requires Node >=22.12.0, so it was unmergeable until the Node 24 baseline landed. Jest's `transformIgnorePatterns` allowlist gains `commander` so ts-jest transforms it under CommonJS test execution; without that, 28 suites fail to load with `SyntaxError: Cannot use import statement outside a module`. - **ci**: Test matrix, release workflow, and security workflow now target Node 24 (previously Node 20 and 22). Node 20 reached end-of-life in April 2026, and Node 24 is the current LTS. This aligns CI with the runtime the project is moving to; the `engines.node` range is unchanged in this entry and is bumped separately. diff --git a/tests/unit/sync/sync-command.test.ts b/tests/unit/sync/sync-command.test.ts index afb5d96..fcff155 100644 --- a/tests/unit/sync/sync-command.test.ts +++ b/tests/unit/sync/sync-command.test.ts @@ -810,6 +810,21 @@ describe('SyncCommand', () => { }); describe('watchAndSync', () => { + // These are the heaviest tests in the file: each drives a full watch + // lifecycle (chokidar setup, debounced change handling, SIGINT shutdown) + // through fake timers. Locally the whole suite runs in ~1.8s, but on + // GitHub's shared runners it has been observed at 10.8-10.9s with 232 + // suites competing for ~4 cores — right at the 10s jest default, which + // tipped a different test over on each occurrence (bead sync-94ua). + // + // The failures were always timeouts, never assertions, and the suite was + // measured to be insensitive to the flush round count (250/25/5 rounds all + // ran in ~1.4-2.0s locally), so the cost is CI CPU starvation rather than + // anything this block does wrong. Raising the ceiling for these tests only + // buys headroom; it does not mask a hang, because a genuinely stuck setup + // now fails fast with a diagnostic from flushWatchSetup below. + jest.setTimeout(30_000); + const mockWatcher = { on: mockWatcherOn, close: mockWatcherClose }; type ProcessOn = typeof process.on; @@ -825,19 +840,66 @@ describe('SyncCommand', () => { jest.useRealTimers(); }); - // watchAndSync awaits chokidar/path dynamic imports and a filesystem sweep - // before registering its SIGINT handler and change/add listeners. Under - // fake timers, flushing that chain requires alternating microtask drains - // (`await Promise.resolve()`) with zero-duration timer advances — timers - // advance queued macrotasks, Promise.resolve drains microtask-only awaits. - // History: 20 rounds flaked → 50 rounds flaked under Node 22 CI worker - // contention (sync-command.test.ts in PR 44). 250 gives ample headroom - // (each round is sub-microsecond) without hiding real hangs — tests still - // fail loudly if setup never finishes, just with a longer safety margin. + // Under fake timers, driving watchAndSync's setup chain forward requires + // alternating microtask drains (`await Promise.resolve()`) with + // zero-duration timer advances — timers advance queued macrotasks, + // Promise.resolve drains microtask-only awaits. + async function flushRound(): Promise { + await Promise.resolve(); + await jest.advanceTimersByTimeAsync(0); + } + + // watchAndSync's setup order is: dynamic import of chokidar/path -> resolve + // watch paths -> chokidar.watch() -> `await controller.sweepStaleBackups()` + // -> attachDebouncedWatchLoop() -> `process.on('SIGINT', ...)`. The last two + // run in one synchronous continuation, so `watcher.on` having been called + // means the SIGINT handler is registered too. That makes mockWatcherOn an + // observable readiness signal for the entire chain. + // + // Phase 1 waits for that signal rather than guessing a round count, because + // a fixed count cannot be correct here. chokidar is jest-mocked, so the + // dynamic imports resolve immediately; the genuinely slow step is + // sweepStaleBackups, which performs real fs.promises.readdir/stat I/O. A + // fixed budget therefore races microsecond-scale iterations against + // millisecond-scale syscalls, and loses under CI worker contention. + // + // When the budget ran out early the failure was not a clean assertion: the + // SIGINT handler was never registered, so each test's shutdown + // (`for (const l of sigintListeners) l()`) had nothing to call, `await + // runPromise` never resolved, and the test died on the 10s testTimeout. + // That flake was escalated 20 -> 50 -> 250 rounds and still recurred on + // Node 24 CI, hitting a different test in this block each time. See bead + // sync-94ua. + // + // Phase 2 keeps the previous fixed drain. Most callers invoke this helper + // again after emitting change events, to settle a debounced sync cycle — + // those calls need the drain, not an early return. Readiness is already + // true by then, so phase 1 is a no-op for them. + // 25 settle rounds, not the historical 250. Every test in this block passes + // with as few as 5 (measured), so 25 keeps a 5x margin while dropping the + // rest as waste. The escalation to 250 was an attempt to fix the timeout by + // widening this budget, which the measurements above show could not have + // worked — suite duration is flat across 250/25/5 rounds. + const SETUP_READY_MAX_ROUNDS = 20_000; + const SETTLE_ROUNDS = 25; + async function flushWatchSetup(): Promise { - for (let i = 0; i < 250; i++) { - await Promise.resolve(); - await jest.advanceTimersByTimeAsync(0); + let rounds = 0; + while (mockWatcherOn.mock.calls.length === 0) { + if (rounds >= SETUP_READY_MAX_ROUNDS) { + throw new Error( + `watchAndSync setup did not attach watcher listeners within ${SETUP_READY_MAX_ROUNDS} ` + + `flush rounds (chokidar.watch calls: ${mockWatch.mock.calls.length}). Either setup ` + + `is genuinely hung, or this test exercises the early-return path where no watcher ` + + `is created and should not call flushWatchSetup.`, + ); + } + await flushRound(); + rounds++; + } + + for (let i = 0; i < SETTLE_ROUNDS; i++) { + await flushRound(); } }