diff --git a/packages/cli/src/browser/manager.test.ts b/packages/cli/src/browser/manager.test.ts index 3e60d6bb7..e09bdc98f 100644 --- a/packages/cli/src/browser/manager.test.ts +++ b/packages/cli/src/browser/manager.test.ts @@ -23,6 +23,7 @@ */ import { join, sep } from "node:path"; import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; +import { CHROME_VERSION } from "./manager.js"; // Use `path.join` so the fake paths line up with whatever separator Node's // real `path.join` produces in `manager.ts` on the host running the test @@ -107,7 +108,12 @@ function installFsMocks({ existing, dirs }: FsMockOptions) { function installPuppeteerBrowsersMock( opts: { - installedInHfCache?: Array<{ browser: string; executablePath: string; path?: string }>; + installedInHfCache?: Array<{ + browser: string; + executablePath: string; + path?: string; + buildId?: string; + }>; installedInHfCacheError?: Error; installResult?: { executablePath: string }; installImpl?: () => Promise<{ executablePath: string }>; @@ -167,7 +173,9 @@ describe("findBrowser — cache resolution", () => { // last-resort fallback. installFsMocks({ existing: new Set([HF_CACHE, HF_BINARY]) }); installPuppeteerBrowsersMock({ - installedInHfCache: [{ browser: "chrome-headless-shell", executablePath: HF_BINARY }], + installedInHfCache: [ + { browser: "chrome-headless-shell", executablePath: HF_BINARY, buildId: CHROME_VERSION }, + ], }); const { findBrowser } = await import("./manager.js"); @@ -176,6 +184,25 @@ describe("findBrowser — cache resolution", () => { expect(result).toEqual({ executablePath: HF_BINARY, source: "cache" }); }); + it("does not resolve to a hyperframes-cache build from an older CHROME_VERSION pin", async () => { + // A build downloaded by a prior hyperframes version (this pin has moved + // 131 -> 151 -> 152 across releases) must not satisfy resolution, or an + // upgrade silently keeps running a stale build forever instead of ever + // fetching the version the new release actually needs (HF#2060 review). + installFsMocks({ existing: new Set([HF_CACHE, HF_BINARY, SYSTEM_CHROME]) }); + installPuppeteerBrowsersMock({ + installedInHfCache: [ + { browser: "chrome-headless-shell", executablePath: HF_BINARY, buildId: "131.0.6778.85" }, + ], + }); + + const { findBrowser } = await import("./manager.js"); + const result = await findBrowser(); + + expect(result?.executablePath).not.toBe(HF_BINARY); + expect(result).toEqual({ executablePath: SYSTEM_CHROME, source: "system" }); + }); + it("re-downloads when the hyperframes cache manifest points at a missing binary", async () => { const redownloadedBinary = join( HF_CACHE, @@ -191,7 +218,12 @@ describe("findBrowser — cache resolution", () => { const paths = installFsMocks({ existing: new Set([HF_CACHE, staleInstallDir]) }); installPuppeteerBrowsersMock({ installedInHfCache: [ - { browser: "chrome-headless-shell", executablePath: HF_BINARY, path: staleInstallDir }, + { + browser: "chrome-headless-shell", + executablePath: HF_BINARY, + path: staleInstallDir, + buildId: CHROME_VERSION, + }, ], installResult: { executablePath: redownloadedBinary }, }); diff --git a/packages/cli/src/browser/manager.ts b/packages/cli/src/browser/manager.ts index 5acf32556..7899ee861 100644 --- a/packages/cli/src/browser/manager.ts +++ b/packages/cli/src/browser/manager.ts @@ -228,7 +228,14 @@ async function findFromHyperframesCache(): Promise { ); installed = []; } - const match = installed.find((b) => b.browser === Browser.CHROMEHEADLESSSHELL); + // Match on buildId too, not just browser type — an install left over from + // an older hyperframes version (this pin has moved 131 → 151 → 152 across + // releases) must NOT satisfy resolution, or an upgrade silently keeps + // running whatever build happened to be cached instead of ever fetching + // the version this release actually needs (HF#2060 review). + const match = installed.find( + (b) => b.browser === Browser.CHROMEHEADLESSSHELL && b.buildId === CHROME_VERSION, + ); if (match && existsSync(match.executablePath)) { return { result: { executablePath: match.executablePath, source: "cache" } }; } diff --git a/packages/cli/src/commands/render.ts b/packages/cli/src/commands/render.ts index 5de324f30..8400cdddd 100644 --- a/packages/cli/src/commands/render.ts +++ b/packages/cli/src/commands/render.ts @@ -1708,6 +1708,7 @@ function trackRenderMetrics( speedRatio, captureAvgMs: perf?.captureAvgMs, captureP50Ms: perf?.captureP50Ms, + subTimelineWait: perf?.subTimelineWait, videoCount: perf?.videoCount, capturePeakMs: perf?.capturePeakMs, tmpPeakBytes: perf?.tmpPeakBytes, diff --git a/packages/cli/src/telemetry/events.ts b/packages/cli/src/telemetry/events.ts index a6d017676..b138778f1 100644 --- a/packages/cli/src/telemetry/events.ts +++ b/packages/cli/src/telemetry/events.ts @@ -1,8 +1,11 @@ import { redactTelemetryString, type OutputResolutionIssueKind } from "@hyperframes/core"; +import type { SubTimelineWaitOutcome } from "@hyperframes/engine"; import { trackEvent } from "./client.js"; import { readConfig } from "./config.js"; export interface RenderObservabilityTelemetryPayload { + /** Worst sub-composition timeline wait outcome across sessions. */ + subTimelineWait?: SubTimelineWaitOutcome; observabilityRenderJobId?: string; observabilityCompositionHash?: string; observabilityEventCount?: number; @@ -47,6 +50,7 @@ export interface RenderObservabilityTelemetryPayload { function renderObservabilityEventProperties(props: RenderObservabilityTelemetryPayload) { return { + sub_timeline_wait: props.subTimelineWait, observability_render_job_id: props.observabilityRenderJobId, observability_composition_hash: props.observabilityCompositionHash, observability_event_count: props.observabilityEventCount, diff --git a/packages/cli/src/telemetry/renderObservability.ts b/packages/cli/src/telemetry/renderObservability.ts index 41b96329d..748d112cd 100644 --- a/packages/cli/src/telemetry/renderObservability.ts +++ b/packages/cli/src/telemetry/renderObservability.ts @@ -58,7 +58,10 @@ export function renderObservabilityTelemetryPayload( export function renderJobObservabilityTelemetryPayload( job: RenderJob | undefined, ): RenderObservabilityTelemetryPayload { - return renderObservabilityTelemetryPayload( - job?.errorDetails?.observability ?? job?.perfSummary?.observability, - ); + return { + ...renderObservabilityTelemetryPayload( + job?.errorDetails?.observability ?? job?.perfSummary?.observability, + ), + subTimelineWait: job?.errorDetails?.subTimelineWait ?? job?.perfSummary?.subTimelineWait, + }; } diff --git a/packages/engine/src/index.ts b/packages/engine/src/index.ts index 659843165..b174e8c22 100644 --- a/packages/engine/src/index.ts +++ b/packages/engine/src/index.ts @@ -40,6 +40,7 @@ export type { CaptureResult, CaptureBufferResult, CapturePerfSummary, + SubTimelineWaitOutcome, } from "./types.js"; // ── Configuration ────────────────────────────────────────────────────────────── diff --git a/packages/engine/src/services/frameCapture-subTimelinePoll.test.ts b/packages/engine/src/services/frameCapture-subTimelinePoll.test.ts new file mode 100644 index 000000000..76efad4fe --- /dev/null +++ b/packages/engine/src/services/frameCapture-subTimelinePoll.test.ts @@ -0,0 +1,66 @@ +/** + * pollSubCompositionTimelines fail-fast contract: a script resource that + * failed to load can never register its `window.__timelines[id]`, so the + * poll must cut to the short grace window instead of burning the full + * playerReadyTimeout (measured wild: a 705-render spike at the 45s setup + * bucket over 30 days — ~1% of local renders). + */ + +import { describe, expect, it, vi } from "vitest"; +import type { Page } from "puppeteer-core"; +import { pollSubCompositionTimelines } from "./frameCapture.js"; + +function makeMockPage(evaluateResults: (expr: string) => unknown): Page { + return { + evaluate: vi.fn(async (expr: string) => evaluateResults(expr)), + } as unknown as Page; +} + +describe("pollSubCompositionTimelines fail-fast", () => { + it("returns ready and forces a timeline rebind when timelines register", async () => { + const page = makeMockPage(() => true); + const outcome = await pollSubCompositionTimelines(page, 1_000, 10); + expect(outcome).toBe("ready"); + // Second evaluate is the __hfForceTimelineRebind call. + expect((page.evaluate as ReturnType).mock.calls.length).toBe(2); + }); + + it("bails after the grace window when a script resource failed to load", async () => { + const page = makeMockPage((expr) => + expr.includes("__hfForceTimelineRebind") ? undefined : false, + ); + const started = Date.now(); + const outcome = await pollSubCompositionTimelines( + page, + 60_000, // full timeout must NOT be waited + 10, + () => ["http://localhost/animations.js"], + 50, // grace + ); + expect(outcome).toBe("script_failure"); + expect(Date.now() - started).toBeLessThan(5_000); + }); + + it("waits the full timeout when timelines are missing but no script failed", async () => { + const page = makeMockPage(() => false); + const outcome = await pollSubCompositionTimelines(page, 120, 10, () => []); + expect(outcome).toBe("timeout"); + }); + + it("keeps waiting through the grace window when failures appear but timelines register late", async () => { + let calls = 0; + const page = makeMockPage((expr) => { + if (expr.includes("__hfForceTimelineRebind")) return undefined; + calls++; + return calls >= 3; // registers on the 3rd poll tick, inside the grace window + }); + const outcome = await pollSubCompositionTimelines( + page, + 60_000, + 10, + () => ["http://localhost/late.js"], + 10_000, // generous grace — registration lands first + ); + expect(outcome).toBe("ready"); + }); +}); diff --git a/packages/engine/src/services/frameCapture.ts b/packages/engine/src/services/frameCapture.ts index dbbdd1e23..6f2cba869 100644 --- a/packages/engine/src/services/frameCapture.ts +++ b/packages/engine/src/services/frameCapture.ts @@ -50,6 +50,7 @@ import type { CaptureResult, CaptureBufferResult, CapturePerfSummary, + SubTimelineWaitOutcome, } from "../types.js"; export type { CaptureOptions, CaptureResult, CaptureBufferResult, CapturePerfSummary }; @@ -95,6 +96,16 @@ export interface CaptureSession { pageReleased?: boolean; browserReleased?: boolean; browserConsoleBuffer: string[]; + /** + * Script resources that failed to load (request failure or HTTP >= 400). + * pollSubCompositionTimelines fail-fasts on these: a comp whose timeline + * script 404'd can never register window.__timelines[id], so waiting the + * full playerReadyTimeout (45s) buys nothing (~1% of wild local renders + * were hitting that wall — a 705-render spike at the 45s setup bucket). + */ + scriptLoadFailures: string[]; + /** Outcome of the sub-composition timeline wait: ready | timeout | script_failure. */ + subTimelineWaitOutcome?: SubTimelineWaitOutcome; initTelemetry?: { initDurationMs: number; tweenCount: number; @@ -929,6 +940,7 @@ export async function createCaptureSession( onBeforeCapture, isInitialized: false, browserConsoleBuffer: [], + scriptLoadFailures: [], capturePerf: { frames: 0, seekMs: 0, @@ -1001,21 +1013,6 @@ export function formatConsoleDiagnostic( return { text: `${prefix} ${text}`, suppressHostLog: false }; } -async function pollPageExpression( - page: Page, - expression: string, - timeoutMs: number, - intervalMs: number = 100, -): Promise { - const deadline = Date.now() + timeoutMs; - while (Date.now() < deadline) { - const ready = Boolean(await page.evaluate(expression)); - if (ready) return true; - await new Promise((resolve) => setTimeout(resolve, intervalMs)); - } - return Boolean(await page.evaluate(expression)); -} - const HF_READY_DIAGNOSTIC_EXPR = `(function() { var hf = window.__hf; var player = window.__player; @@ -1151,11 +1148,19 @@ async function pollHfReady(page: Page, timeoutMs: number, intervalMs: number = 1 ); } -async function pollSubCompositionTimelines( +export async function pollSubCompositionTimelines( page: Page, timeoutMs: number, intervalMs: number = 150, -): Promise { + // Fail-fast hook: when a SCRIPT resource failed to load (404 / request + // failure), the timeline registration it carried can never arrive — the + // full-timeout wait buys nothing (measured: a 705-render spike at the 45s + // setup bucket in 30 days of wild local renders, ~1% of renders, each also + // shipping silently-broken animations). Once failures are present the poll + // is cut to `scriptFailureGraceMs` from its start. + getScriptLoadFailures?: () => readonly string[], + scriptFailureGraceMs: number = 2_000, +): Promise { // Hosts may opt out of the timeline wait with `data-no-timeline` — // compositions driven purely by CSS animations / rAF (the render-compat // contract) never register window.__timelines[id], and without the opt-out @@ -1172,7 +1177,28 @@ async function pollSubCompositionTimelines( } return true; })()`; - const ready = await pollPageExpression(page, expression, timeoutMs, intervalMs); + const start = Date.now(); + const deadline = start + timeoutMs; + let ready = false; + let scriptFailureBail = false; + for (;;) { + ready = Boolean(await page.evaluate(expression)); + if (ready) break; + const now = Date.now(); + if (now >= deadline) break; + const failures = getScriptLoadFailures?.() ?? []; + if (failures.length > 0 && now - start >= scriptFailureGraceMs) { + scriptFailureBail = true; + console.warn( + `[FrameCapture] Sub-composition timeline wait cut short after ${now - start}ms: ` + + `script resource(s) failed to load (${failures.join(", ")}) — ` + + `the timeline registration they carry can never arrive. ` + + `Fix the script reference; the render proceeds without those animations.`, + ); + break; + } + await new Promise((resolve) => setTimeout(resolve, intervalMs)); + } // Always force a timeline rebind once sub-composition timelines are // confirmed present. The previous implementation only called rebind // when the timeline count grew during the poll, which missed the case @@ -1186,25 +1212,33 @@ async function pollSubCompositionTimelines( window.__hfForceTimelineRebind(); } })()`); + return "ready"; } - if (!ready) { - const missing = await page.evaluate(`(function() { - var hosts = document.querySelectorAll("[data-composition-id]"); - var timelines = window.__timelines || {}; - var m = []; - for (var i = 0; i < hosts.length; i++) { - if (hosts[i].hasAttribute("data-no-timeline")) continue; - var id = hosts[i].getAttribute("data-composition-id"); - if (id && !timelines[id]) m.push(id); - } - return m.join(", "); - })()`); + // Enumerate the still-unregistered composition ids regardless of bail + // reason — a script-failure bail used to skip this entirely, so a render + // with multiple sub-compositions only named the failed script URL(s), not + // which composition(s) it was still waiting on (review). + const missing = await page.evaluate(`(function() { + var hosts = document.querySelectorAll("[data-composition-id]"); + var timelines = window.__timelines || {}; + var m = []; + for (var i = 0; i < hosts.length; i++) { + if (hosts[i].hasAttribute("data-no-timeline")) continue; + var id = hosts[i].getAttribute("data-composition-id"); + if (id && !timelines[id]) m.push(id); + } + return m.join(", "); + })()`); + if (scriptFailureBail) { + console.warn(`[FrameCapture] Composition(s) still waiting on the failed script: ${missing}.`); + } else { console.warn( `[FrameCapture] Sub-composition timelines not registered after ${timeoutMs}ms: ${missing}. ` + `Compositions that load data asynchronously (e.g. fetch) must register window.__timelines[id] after setup completes. ` + `Compositions intentionally driven without GSAP timelines (CSS animations / rAF) can mark the host with data-no-timeline to skip this wait.`, ); } + return scriptFailureBail ? "script_failure" : "timeout"; } async function pollVideosReady( @@ -1381,6 +1415,16 @@ async function waitForOptionalTailwindReady(page: Page, timeoutMs: number): Prom } } +// A 4xx `response` and a `requestfailed` can both fire for the same script +// (e.g. a `requestfailed` following the 4xx), and repeated