From f98ef09be48efdbfda436c269cedbcee9d41d0d2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Miguel=20=C3=81ngel?= Date: Tue, 20 Oct 2026 09:12:43 +0000 Subject: [PATCH] test: queue runs on slow windows runners stop failing four timing tests (#5949) * test: queue runs on slow windows runners stop failing four timing tests * test(cli): the keepalive process test budgets for a cold start on a slow runner --- ...tionFrame.lateSubresources.browser.test.ts | 5 +-- .../src/capture/captureCompositionFrame.ts | 11 +++--- .../utils/renderCancellation.process.test.ts | 3 +- .../src/services/videoFrameExtractor.test.ts | 36 +++++++++++++------ packages/engine/src/utils/runFfmpeg.test.ts | 33 +++++++++++++++++ .../engine/src/utils/urlDownloader.test.ts | 10 +++--- 6 files changed, 74 insertions(+), 24 deletions(-) diff --git a/packages/cli/src/capture/captureCompositionFrame.lateSubresources.browser.test.ts b/packages/cli/src/capture/captureCompositionFrame.lateSubresources.browser.test.ts index 24f001cacd..e6d5154de1 100644 --- a/packages/cli/src/capture/captureCompositionFrame.lateSubresources.browser.test.ts +++ b/packages/cli/src/capture/captureCompositionFrame.lateSubresources.browser.test.ts @@ -3,8 +3,8 @@ import type { AddressInfo } from "node:net"; import { afterAll, beforeAll, expect, it } from "vitest"; import { openSettledCompositionPage } from "./captureCompositionFrame.js"; -// An image, then a fetched asset after the load event, both well inside the 1.5 s settle cap: with the -// asset at 1.1 s a busy Windows runner settled at up to 1.48 s, 18 ms from the cap. +// An image, then a fetched asset after the load event. The settle cap is lifted: a starved runner +// has not even loaded the page by the default 1.5 s, and the test is about waiting, not the cap. const IMAGE_MS = 300; const FETCH_MS = 500; const PNG = Buffer.from( @@ -45,6 +45,7 @@ it("returns only once images and fetched assets that land after DOMContentLoaded const { browser, page } = await openSettledCompositionPage(HTML, url, { renderReadyTimeoutMs: 5_000, renderReadyWarningSuffix: "test", + lateSubresourceTimeoutMs: 60_000, browserGpuMode: "software", }); try { diff --git a/packages/cli/src/capture/captureCompositionFrame.ts b/packages/cli/src/capture/captureCompositionFrame.ts index 32772afa0f..8d12826676 100644 --- a/packages/cli/src/capture/captureCompositionFrame.ts +++ b/packages/cli/src/capture/captureCompositionFrame.ts @@ -106,6 +106,7 @@ export interface OpenSettledCompositionPageOptions { navigationTimeoutMs?: number; renderReadyTimeoutMs: number; renderReadyWarningSuffix: string; + lateSubresourceTimeoutMs?: number; browserGpuMode?: BrowserGpuMode; signal?: AbortSignal; onBrowser?: (browser: Browser) => void; @@ -249,16 +250,16 @@ async function waitForCompositionSettle( console.warn(` ${c.warn("⚠")} Shader transitions did not finish pre-rendering`); }); - await waitForLateSubresources(page); + await waitForLateSubresources(page, options.lateSubresourceTimeoutMs ?? CAPTURE_SETTLE_MS); return runtimeReady; } -async function waitForLateSubresources(page: Page): Promise { +async function waitForLateSubresources(page: Page, timeoutMs: number): Promise { let cap: ReturnType | undefined; - const deadline = Date.now() + CAPTURE_SETTLE_MS; + const deadline = Date.now() + timeoutMs; const ready = (async () => { await page.waitForFunction(() => document.readyState === "complete", { - timeout: CAPTURE_SETTLE_MS, + timeout: timeoutMs, }); await page.waitForNetworkIdle({ idleTime: NETWORK_IDLE_MS, @@ -273,7 +274,7 @@ async function waitForLateSubresources(page: Page): Promise { await Promise.race([ ready, new Promise((resolveCap) => { - cap = setTimeout(resolveCap, CAPTURE_SETTLE_MS); + cap = setTimeout(resolveCap, timeoutMs); }), ]); } catch { diff --git a/packages/cli/src/utils/renderCancellation.process.test.ts b/packages/cli/src/utils/renderCancellation.process.test.ts index 407a45536f..68892635d0 100644 --- a/packages/cli/src/utils/renderCancellation.process.test.ts +++ b/packages/cli/src/utils/renderCancellation.process.test.ts @@ -148,5 +148,6 @@ describe("render cancellation process keepalive", () => { } finally { rmSync(testDir, { recursive: true, force: true }); } - }, 5_000); + // Sized for a cold tsx start on a slow Windows runner (1.4-2.7 s healthy); the work is 250 ms. + }, 30_000); }); diff --git a/packages/engine/src/services/videoFrameExtractor.test.ts b/packages/engine/src/services/videoFrameExtractor.test.ts index 7e886d8a77..bd3f9a6e6e 100644 --- a/packages/engine/src/services/videoFrameExtractor.test.ts +++ b/packages/engine/src/services/videoFrameExtractor.test.ts @@ -55,7 +55,7 @@ import { extractVideoMetadata, type VideoMetadata, } from "../utils/ffprobe.js"; -import { runFfmpeg } from "../utils/runFfmpeg.js"; +import { ffmpegStatsReader, runFfmpeg, type RunFfmpegOptions } from "../utils/runFfmpeg.js"; // Pass-through, so a test can tell whether extraction ran ffmpeg. vi.mock("../utils/runFfmpeg.js", async (importOriginal) => { @@ -2082,30 +2082,44 @@ describe.skipIf(!HAS_FFMPEG)("frame sampling at the output frame rate", () => { 60_000, ); - it("keeps a run that outlasts the timeout while it still writes frames", async () => { - const source = join(FIXTURE_DIR, "paced-5s.mp4"); + it("stops extraction only on a stall, and its ffmpeg reports each frame it writes", async () => { + const source = join(FIXTURE_DIR, "paced-2s.mp4"); const synth = await runFfmpeg([ ...["-y", "-hide_banner", "-loglevel", "error", "-f", "lavfi"], - ...["-i", `testsrc=s=${WIDTH}x${HEIGHT}:r=30:d=5`, "-pix_fmt", "yuv420p", source], + ...["-i", `testsrc=s=${WIDTH}x${HEIGHT}:r=30:d=2`, "-pix_fmt", "yuv420p", source], ]); if (!synth.success) throw new Error(`paced fixture synthesis failed: ${synth.stderr}`); const { runFfmpeg: real } = await vi.importActual("../utils/runFfmpeg.js"); - // Real-time pacing makes 5 s of source take 5 s against a 2 s timeout. - vi.mocked(runFfmpeg).mockImplementation((args, opts) => - real(["-stats_period", "0.1", "-re", ...args], opts), - ); + let requested: RunFfmpegOptions | undefined; + const reported: number[] = []; + const readStats = ffmpegStatsReader(({ frames }) => { + if (frames) reported.push(frames); + }); + // Real-time pacing spreads the stats over the run. The stall clock itself is runFfmpeg's to + // test; here it is lifted so a starved runner cannot race it. + vi.mocked(runFfmpeg).mockImplementation((args, opts) => { + requested = opts; + return real(["-stats_period", "0.1", "-re", ...args], { + ...opts, + stallTimeout: 60_000, + onStderr: readStats, + }); + }); try { const extracted = await extractVideoFramesRange( source, - "paced-past-timeout", + "paced-stall-only", 0, - 5, + 2, { fps: 10, outputDir: FIXTURE_DIR, format: "png" }, undefined, { ffmpegProcessTimeout: 2000 }, ); - expect(extracted.totalFrames).toBe(50); + expect(extracted.totalFrames).toBe(20); + expect(requested).toMatchObject({ stallTimeout: 2000 }); + expect(requested).not.toHaveProperty("timeout"); + expect(new Set(reported).size).toBeGreaterThan(1); } finally { vi.mocked(runFfmpeg).mockImplementation(real); } diff --git a/packages/engine/src/utils/runFfmpeg.test.ts b/packages/engine/src/utils/runFfmpeg.test.ts index 4a9650ba4b..210c456a04 100644 --- a/packages/engine/src/utils/runFfmpeg.test.ts +++ b/packages/engine/src/utils/runFfmpeg.test.ts @@ -245,6 +245,39 @@ describe("ffmpegStatsReader", () => { }); }); +describe("a run with a stall timeout", () => { + afterEach(() => { + vi.useRealTimers(); + vi.doUnmock("child_process"); + vi.resetModules(); + }); + + it("outlives the timeout while frames advance, and stops once they do not", async () => { + vi.useFakeTimers(); + const proc = Object.assign(new EventEmitter(), { + stderr: new EventEmitter(), + kill: vi.fn(() => queueMicrotask(() => proc.emit("close", null, "SIGTERM"))), + }); + vi.resetModules(); + vi.doMock("child_process", () => ({ spawn: () => proc })); + const { runFfmpeg } = await import("./runFfmpeg.js"); + + const run = runFfmpeg(["-i", "in.mp4", "out-%05d.png"], { stallTimeout: 2_000 }); + for (let frame = 1; frame <= 4; frame += 1) { + await vi.advanceTimersByTimeAsync(1_500); + proc.stderr.emit("data", Buffer.from(`frame=${frame} fps=1 time=00:00:0${frame}.00\r`)); + } + // Six seconds in: three stall timeouts, never one without a new frame. + expect(proc.kill).not.toHaveBeenCalled(); + await vi.advanceTimersByTimeAsync(1_000); + proc.stderr.emit("data", Buffer.from("frame=4 fps=1 time=00:00:04.00\r")); + await vi.advanceTimersByTimeAsync(1_000); + + expect(proc.kill).toHaveBeenCalledWith("SIGTERM"); + await expect(run).resolves.toMatchObject({ terminationReason: "inactivity" }); + }); +}); + describe("a run whose signal already aborted", () => { afterEach(() => { vi.doUnmock("child_process"); diff --git a/packages/engine/src/utils/urlDownloader.test.ts b/packages/engine/src/utils/urlDownloader.test.ts index 8b3384c0d5..18f0d600f9 100644 --- a/packages/engine/src/utils/urlDownloader.test.ts +++ b/packages/engine/src/utils/urlDownloader.test.ts @@ -112,10 +112,10 @@ function isoBmffMediaBytes(marker: string): Buffer { return Buffer.concat([ftyp, Buffer.from(marker)]); } -// Fake Date, and hold the 1_000 ms attempt deadline every test passes: on a slow runner one +// Freeze Date, and hold the 1_000 ms attempt deadline every test passes: on a slow runner one // attempt (hash, fsync, refetch) can outlast it and throw "Download timeout". A test that // needs the deadline calls fireAttemptDeadline(). Other timers (cache-lock poll, test -// delays) stay real. +// delays) stay real. Not fake timers: vi.waitFor advances those, shortening the deadline. const ATTEMPT_DEADLINE_MS = 1_000; const heldDeadlines = new Map, () => void>(); let realSetTimeout: typeof setTimeout; @@ -129,7 +129,7 @@ function fireAttemptDeadline(): void { } beforeEach(() => { - vi.useFakeTimers({ toFake: ["Date"] }); + vi.setSystemTime(Date.now()); realSetTimeout = globalThis.setTimeout; vi.spyOn(globalThis, "setTimeout").mockImplementation((( handler: () => void, @@ -1616,9 +1616,9 @@ describe("downloadToTemp atomic publication and bounded retry", () => { kind: "cancelled", retryable: false, } satisfies Partial); + // Cancel the first caller's request in flight; the second caller's may already be sent too. + await vi.waitFor(() => expect(fetchMock).toHaveBeenCalled()); firstController.abort(); - await vi.waitFor(() => expect(fetchMock).toHaveBeenCalledTimes(1)); - fireAttemptDeadline(); await firstRejected; const path = await second;