fix(cli): a check that runs out of time says which step it was in and how long each took (#6060)

* fix(cli): a check that runs out of time says which step it was in and how long each took

When check hits its 120 s deadline, the error now names the step it was in
(loading the page, waiting for it to be ready, checking samples, the overlap
pass, finding crops) and the seconds each step took, including the video
copies and Chrome start that happen before the deadline starts.

* fix(cli): drop two comments the names already say

packages/cli/src/capture/captureCompositionFrame.ts

@@ -115,6 +115,7 @@ export interface OpenSettledCompositionPageOptions {
   // Runs after the page exists but before page.goto, so console/pageerror/
   // request listeners can attach without missing load-time events.
   beforeNavigate?: (page: Page) => void | Promise<void>;
+  onLoaded?: () => void;
   // Started before the project was bundled; used only if it was launched with the same arguments.
   prelaunched?: PrelaunchedBrowser;
 }
@@ -331,6 +332,7 @@ export async function openSettledCompositionPage(
     await options.beforeNavigate?.(page);
     await gotoWhenSent(page, url, pageNavigationTimeoutMs(options.navigationTimeoutMs));
     await assertWebGpuAdapterAvailable(page, requiresWebGpu, softwareWebGpu);
+    options.onLoaded?.();
     const renderReadyTimedOut = !(await waitForCompositionSettle(page, options));
     return { browser: chromeBrowser, page, renderReadyTimedOut };
   } catch (err) {

packages/cli/src/commands/check.test.ts

@@ -1631,6 +1631,38 @@ describe("check pipeline", () => {
     );
   });
 
+  it("a deadline that fires in the overlap pass names that pass in its finding", async () => {
+    vi.useFakeTimers();
+    try {
+      let aborted!: AbortSignal;
+      const driver = fakeDriver({
+        collectOverlapGrid: vi.fn(
+          () =>
+            new Promise<never>((_, reject) =>
+              aborted.addEventListener("abort", () => reject(aborted.reason)),
+            ),
+        ),
+      });
+      const { deps } = dependencies(driver);
+      deps.runBrowserCheck = async (_project, options, motion, deadline) => {
+        aborted = deadline!.signal;
+        deadline!.start();
+        return runAuditGrid(driver, options, motion, undefined, deadline!.enter);
+      };
+      const pending = runCheckPipeline(PROJECT, DEFAULT_CHECK_OPTIONS, deps);
+      await vi.advanceTimersByTimeAsync(120_000);
+      const report = await pending;
+      const failure = report.runtime.findings.find(
+        (finding) => finding.code === "check_runtime_failure",
+      );
+      expect(failure?.message).toMatch(/^Check did not finish within its deadline/);
+      expect(failure?.message).toContain("while running the overlap pass.");
+      expect(failure?.message).toContain("checking samples 0.0, running the overlap pass 120.0.");
+    } finally {
+      vi.useRealTimers();
+    }
+  });
+
   it("--strict flips a warnings-only result from exit 0 to exit 1", async () => {
     const warningDriver = () =>
       fakeDriver({

packages/cli/src/utils/checkBrowser.ts

@@ -239,11 +239,13 @@ export async function runBrowserCheck(
 ): Promise<CheckBrowserResult> {
   const { bundleWithLocalizedFonts } = await import("./bundleWithLocalizedFonts.js");
   const html = await bundleWithLocalizedFonts(project.dir);
+  deadline?.enter("copies");
   const { findings: drafts, failedPaths } = await preResolveHostileMediaProxies(
     project.dir,
     html,
     options.autoProxy,
   );
+  deadline?.enter("launch");
   const server = await serveStaticProjectHtml(
     project.dir,
     html,
@@ -279,6 +281,7 @@ export async function runBrowserCheck(
         wireRuntimeListeners(page, drafts, clock);
         await deadline?.preparePage(page);
       },
+      onLoaded: () => deadline?.enter("settle"),
     });
     chromeBrowser = session.browser;
     const page = session.page;
@@ -303,7 +306,7 @@ export async function runBrowserCheck(
     drafts.push(...blur);
     const sampleLog = sampleWindow(drafts);
     const driver = createPageDriver(page, clock, sampleLog);
-    const result = await runGrid(driver, options, motion, helpers);
+    const result = await runGrid(driver, options, motion, helpers, deadline?.enter);
     helperSession?.stop();
     const helper = await helperOpen?.catch(() => undefined);
     const merged = helper ? mergeHelperDrafts(sampleLog, helper.sampleLog) : drafts;

packages/cli/src/utils/checkDeadline.test.ts

@@ -93,3 +93,32 @@ it("closing before browser readiness prevents a later clock from starting", asyn
   expect(vi.getTimerCount()).toBe(0);
   expect(deadline.signal.aborted).toBe(false);
 });
+
+it("an expired check names the phase it was in and the seconds each phase took", async () => {
+  vi.useFakeTimers();
+  const deadline = new CheckDeadline();
+  const outcome = deadline
+    .run(() => rejectOnAbort(deadline.signal))
+    .catch((error: unknown) => error);
+  try {
+    deadline.enter("copies");
+    await vi.advanceTimersByTimeAsync(247_000);
+    deadline.enter("launch");
+    await vi.advanceTimersByTimeAsync(2_000);
+    deadline.start();
+    await vi.advanceTimersByTimeAsync(3_000);
+    deadline.enter("settle");
+    await vi.advanceTimersByTimeAsync(60_000);
+    deadline.enter("samples");
+    await vi.advanceTimersByTimeAsync(50_000);
+    deadline.enter("overlap");
+    await vi.advanceTimersByTimeAsync(7_000);
+    expect(((await outcome) as Error).message).toBe(
+      "Check did not finish within its deadline (120 s from when Chrome was ready), while running the overlap pass. " +
+        "Seconds per phase: making video copies 247.0 (before the deadline), starting Chrome 2.0 (before the deadline), " +
+        "loading the page 3.0, waiting for the page to be ready 60.0, checking samples 50.0, running the overlap pass 7.0.",
+    );
+  } finally {
+    await deadline.close();
+  }
+});

packages/cli/src/utils/checkDeadline.ts

@@ -7,12 +7,27 @@ const CHECK_DEADLINE_MS = 120_000;
 const SCRIPT_START = "[hyperframes:script:start] ";
 const SCRIPT_FINISH = "[hyperframes:script:finish] ";
 
+const PHASE_LABELS = {
+  copies: "making video copies",
+  launch: "starting Chrome",
+  load: "loading the page",
+  settle: "waiting for the page to be ready",
+  samples: "checking samples",
+  overlap: "running the overlap pass",
+  crops: "capturing finding crops",
+} as const;
+export type CheckPhase = keyof typeof PHASE_LABELS;
+const BEFORE_DEADLINE: ReadonlySet<CheckPhase> = new Set(["copies", "launch"]);
+
 export class CheckDeadlineError extends Error {
-  constructor(readonly sourceFile?: string) {
+  constructor(
+    readonly sourceFile?: string,
+    phases = "",
+  ) {
     super(
-      sourceFile === undefined
-        ? "Check did not finish within its deadline."
-        : `${sourceFile}: its script did not finish within the check deadline.`,
+      (sourceFile === undefined
+        ? "Check did not finish within its deadline"
+        : `${sourceFile}: its script did not finish within the check deadline`) + (phases || "."),
     );
   }
 }
@@ -29,6 +44,8 @@ export class CheckDeadline {
   private readonly expiry: Promise<never>;
   private rejectExpiry!: (error: CheckDeadlineError) => void;
   private phase: "waiting" | "started" | "closed" = "waiting";
+  private work: { phase: CheckPhase; since: number } | undefined;
+  private readonly spent = new Map<CheckPhase, number>();
 
   constructor() {
     this.expiry = new Promise((_, reject) => {
@@ -36,11 +53,34 @@ export class CheckDeadline {
     });
   }
 
+  enter = (phase: CheckPhase): void => {
+    if (this.expired) return;
+    const now = Date.now();
+    if (this.work) this.spend(this.work.phase, now - this.work.since);
+    this.work = { phase, since: now };
+    this.spend(phase, 0);
+  };
+
+  private spend(phase: CheckPhase, ms: number): void {
+    this.spent.set(phase, (this.spent.get(phase) ?? 0) + ms);
+  }
+
+  private describe(): string {
+    if (!this.work) return "";
+    const open = Date.now() - this.work.since;
+    const parts = [...this.spent].map(([phase, ms]) => {
+      const seconds = ((phase === this.work?.phase ? ms + open : ms) / 1000).toFixed(1);
+      return `${PHASE_LABELS[phase]} ${seconds}${BEFORE_DEADLINE.has(phase) ? " (before the deadline)" : ""}`;
+    });
+    return ` (${CHECK_DEADLINE_MS / 1000} s from when Chrome was ready), while ${PHASE_LABELS[this.work.phase]}. Seconds per phase: ${parts.join(", ")}.`;
+  }
+
   start = (): void => {
     if (this.phase !== "waiting") return;
     this.phase = "started";
+    this.enter("load");
     this.timer = setTimeout(() => {
-      this.expired = new CheckDeadlineError(this.scripts.at(-1));
+      this.expired = new CheckDeadlineError(this.scripts.at(-1), this.describe());
       this.rejectExpiry(this.expired);
       this.abort.abort(this.expired);
     }, CHECK_DEADLINE_MS);

packages/cli/src/utils/checkPipeline.ts

@@ -1,5 +1,5 @@
 import { BrowserCleanupError } from "../browser/launch.js";
-import { CheckDeadline, CheckDeadlineError } from "./checkDeadline.js";
+import { CheckDeadline, CheckDeadlineError, type CheckPhase } from "./checkDeadline.js";
 import {
   checkSnapshotDirectory,
   beginCheckSnapshots,
@@ -514,6 +514,7 @@ async function collectGridSamples(
   grid: SampleGrid,
   motion: MotionPlan,
   helpers: Promise<CheckAuditDriver[]>,
+  enter: (phase: CheckPhase) => void,
 ): Promise<GridSamples> {
   const geometryEnabled = grid.captionSamples.length > 0 || grid.frameSamples.length > 0;
   const sets: SampleSets = {
@@ -559,6 +560,7 @@ async function collectGridSamples(
   driver.markSamples?.("end");
   const collected = emptyGridSamples();
   for (const samples of perTime) appendGridSamples(collected, samples);
+  enter("overlap");
   await collectMotionOverlapSamples(
     driver,
     grid,
@@ -566,6 +568,7 @@ async function collectGridSamples(
     options.range,
     craftEnabled(driver, options),
   );
+  enter("samples");
   return collected;
 }
 
@@ -1431,7 +1434,9 @@ export async function runAuditGrid(
   options: CheckOptions,
   motion: MotionSpecResolution,
   helpers: Promise<CheckAuditDriver[]> = Promise.resolve([]),
+  enter: (phase: CheckPhase) => void = () => {},
 ): Promise<CheckBrowserResult> {
+  enter("samples");
   await driver.initialize(options.contrast);
   const grid = await buildSampleGrid(driver, options);
   const plan = await planMotionSampling(
@@ -1440,7 +1445,7 @@ export async function runAuditGrid(
     grid.duration,
   );
   const seekLoopStart = Date.now();
-  const collected = await collectGridSamples(driver, options, grid, plan, helpers);
+  const collected = await collectGridSamples(driver, options, grid, plan, helpers, enter);
   const seekLoopMs = Date.now() - seekLoopStart;
 
   let motionIssues = plan.preflightIssues;
@@ -1693,6 +1698,7 @@ async function withFindingCrops(
   const cropRequests = selectFindingCropRequests(report);
   if (cropRequests.length === 0) return report;
   try {
+    deadline.enter("crops");
     const findingFiles = await deadline.run(() =>
       dependencies.captureFindingCrops(project, options, cropRequests, deadline),
     );

packages/cli/src/utils/checkTypes.ts

@@ -7,6 +7,7 @@ import type { ProjectDir } from "./project.js";
 import type { BrowserGpuMode } from "../browser/gpuPolicy.js";
 import type { HdrAutoPromotion } from "@hyperframes/engine";
 import type { PrelaunchedBrowser } from "../capture/captureCompositionFrame.js";
+import type { CheckPhase } from "./checkDeadline.js";
 
 export interface CheckOptions {
   samples: number;
@@ -325,6 +326,7 @@ export type RunAuditGrid = (
   options: CheckOptions,
   motion: MotionSpecResolution,
   helpers?: Promise<CheckAuditDriver[]>,
+  enter?: (phase: CheckPhase) => void,
 ) => Promise<CheckBrowserResult>;
 
 export interface CheckSection<T extends CheckFinding = CheckFinding> {