diff --git a/docs/packages/cli.mdx b/docs/packages/cli.mdx index 7182884bc1..a72a4ecdef 100644 --- a/docs/packages/cli.mdx +++ b/docs/packages/cli.mdx @@ -1067,10 +1067,12 @@ cover every finding from the full check. | `--prepare-media` | Only make the browser-playable video copies, then exit: no browser, no report. `--json` lists each file as `ready`, `cached` or `failed`; exit 1 if any failed | A video Chrome cannot decode (HEVC, ProRes) is copied once, and the first check waits -for it. A source longer than a few minutes is copied in one-minute pieces that are kept, -so a copy that is stopped continues from its finished pieces on the next run. For a long -project, run `hyperframes check --prepare-media` first, then the check itself finds every -copy ready. +for it. A source longer than 22 seconds is copied in 15-second pieces that are kept, so a +copy that is stopped continues from its finished pieces on the next run. While it works, the +check prints each copy's progress to stderr every 10 seconds (stdout stays clean for `--json`), +and ends a copy only when it makes no progress for 3 minutes (`HYPERFRAMES_PROXY_STALL_MS`). +For a long project, run `hyperframes check --prepare-media` first, then the check itself finds +every copy ready. `--caption-zone` and `--frame-check` refuse a ranged check when none of their configured seek samples falls inside `--range`; a requested gate never silently diff --git a/packages/cli/src/utils/checkBrowser.test.ts b/packages/cli/src/utils/checkBrowser.test.ts index e4aa74ba97..a6be92d9b1 100644 --- a/packages/cli/src/utils/checkBrowser.test.ts +++ b/packages/cli/src/utils/checkBrowser.test.ts @@ -25,6 +25,15 @@ import { import type { ProjectDir } from "./project.js"; const mocks = vi.hoisted(() => ({ + stopListeners: new Set<() => void>(), + proxyProgress: { + feed: undefined as + | undefined + | (( + report: (index: number, progress: { doneSeconds: number; totalSeconds?: number }) => void, + ) => void), + }, + proxySignal: undefined as AbortSignal | undefined, bundleWithLocalizedFonts: vi.fn(async () => ""), serverClose: vi.fn(async () => undefined), resolveProxy: @@ -56,6 +65,13 @@ const mocks = vi.hoisted(() => ({ >(async () => ({})), })); +vi.mock("../browser/launch.js", async (importOriginal) => ({ + ...(await importOriginal()), + onStopSignal: (listener: () => void) => { + mocks.stopListeners.add(listener); + return () => mocks.stopListeners.delete(listener); + }, +})); vi.mock("./bundleWithLocalizedFonts.js", () => ({ // Keep browser-check unit tests focused on the page driver and audit pipeline. // The real helper cold-loads the producer/font graph, which is covered by its @@ -103,16 +119,24 @@ vi.mock("@hyperframes/studio-server/proxy-transcoder", () => ({ variant: string; box?: { width: number; height: number }; }>, - onSettled: () => void = () => {}, - ) => - Promise.allSettled( - sources.map(({ sourcePath, variant, box }) => + onSettled: (index: number) => void = () => {}, + onProgress: ( + index: number, + progress: { doneSeconds: number; totalSeconds?: number }, + ) => void = () => {}, + signal?: AbortSignal, + ) => { + mocks.proxySignal = signal; + mocks.proxyProgress.feed?.(onProgress); + return Promise.allSettled( + sources.map(({ sourcePath, variant, box }, index) => (box ? mocks.resolveProxy(projectDir, sourcePath, variant, box) : mocks.resolveProxy(projectDir, sourcePath, variant) - ).finally(onSettled), + ).finally(() => onSettled(index)), ), - ), + ); + }, })); const PROJECT: ProjectDir = { @@ -1194,7 +1218,7 @@ describe("preResolveHostileMediaProxies", () => { await preResolveHostileMediaProxies(projectDir, html); // The page asks for the quantized stage size, so the copy and its cache check use that box. - const box = { width: 2048, height: 1448 }; + const box = { width: 2048, height: 1218 }; expect(mocks.resolveProxy).toHaveBeenCalledWith( projectDir, join(projectDir, "clip.mp4"), @@ -1303,6 +1327,105 @@ describe("preResolveHostileMediaProxies", () => { expect(stdoutSpy).not.toHaveBeenCalled(); }); + it("says how far a copy has got every few seconds, so a slow copy reads as slow", async () => { + vi.useFakeTimers(); + try { + const projectDir = mkProjectDir(); + mocks.scanProjectMediaCodecMap.mockResolvedValue({ + "/clip.mov": { + codecName: "hevc", + browserHostile: true, + representativeMime: null, + hasAlpha: false, + }, + }); + let finish: (() => void) | undefined; + mocks.resolveProxy.mockImplementation( + () => new Promise((done) => (finish = () => done("/cache/clip.mp4"))), + ); + mocks.proxyProgress.feed = (report) => report(0, { doneSeconds: 30, totalSeconds: 120 }); + const errorSpy = vi.spyOn(console, "error").mockImplementation(() => undefined); + + const pending = preResolveHostileMediaProxies(projectDir, ""); + await vi.advanceTimersByTimeAsync(10_000); + mocks.proxyProgress.feed = undefined; + finish?.(); + await pending; + + expect(errorSpy.mock.calls.map(([line]) => line)).toContain( + "[hyperframes] browser-playable copy of clip.mov: 25% (10s so far)", + ); + } finally { + mocks.proxyProgress.feed = undefined; + vi.useRealTimers(); + } + }); + + it("stops reporting a copy once it is done, so a finished one is not read as stuck", async () => { + vi.useFakeTimers(); + try { + const projectDir = mkProjectDir(); + const hostile = { + codecName: "hevc", + browserHostile: true, + representativeMime: null, + hasAlpha: false, + }; + mocks.scanProjectMediaCodecMap.mockResolvedValue({ "/a.mov": hostile, "/b.mov": hostile }); + let finishB: (() => void) | undefined; + mocks.resolveProxy.mockImplementation((_dir, sourcePath) => + sourcePath.endsWith("a.mov") + ? Promise.resolve("/cache/a.mp4") + : new Promise((done) => (finishB = () => done("/cache/b.mp4"))), + ); + mocks.proxyProgress.feed = (report) => { + report(0, { doneSeconds: 118, totalSeconds: 120 }); + report(1, { doneSeconds: 30, totalSeconds: 120 }); + }; + const errorSpy = vi.spyOn(console, "error").mockImplementation(() => undefined); + + const pending = preResolveHostileMediaProxies(projectDir, ""); + await vi.advanceTimersByTimeAsync(10_000); + mocks.proxyProgress.feed = undefined; + finishB?.(); + await pending; + + const lines = errorSpy.mock.calls.map(([line]) => String(line)); + expect(lines).toContain("[hyperframes] browser-playable copy of b.mov: 25% (10s so far)"); + expect(lines.some((line) => line.includes("copy of a.mov"))).toBe(false); + } finally { + mocks.proxyProgress.feed = undefined; + vi.useRealTimers(); + } + }); + + it("ends the copies it is making when it is stopped by a signal", async () => { + const projectDir = mkProjectDir(); + mocks.scanProjectMediaCodecMap.mockResolvedValue({ + "/clip.mov": { + codecName: "hevc", + browserHostile: true, + representativeMime: null, + hasAlpha: false, + }, + }); + let finish: (() => void) | undefined; + mocks.resolveProxy.mockImplementation( + () => new Promise((done) => (finish = () => done("/cache/clip.mp4"))), + ); + vi.spyOn(console, "error").mockImplementation(() => undefined); + + const pending = preResolveHostileMediaProxies(projectDir, ""); + await vi.waitFor(() => expect(mocks.proxySignal).toBeDefined()); + expect(mocks.proxySignal!.aborted).toBe(false); + for (const listener of mocks.stopListeners) listener(); + + expect(mocks.proxySignal!.aborted).toBe(true); + finish?.(); + await pending; + expect(mocks.stopListeners.size).toBe(0); + }); + it("says it is making copies, and counts them, only when some are not made yet", async () => { const projectDir = mkProjectDir(); const codec = { diff --git a/packages/cli/src/utils/checkBrowser.ts b/packages/cli/src/utils/checkBrowser.ts index 562b7e58d9..0e53f4ba31 100644 --- a/packages/cli/src/utils/checkBrowser.ts +++ b/packages/cli/src/utils/checkBrowser.ts @@ -1,6 +1,6 @@ import type { CheckDeadline } from "./checkDeadline.js"; import { logCheckProgress } from "./checkProgress.js"; -import { BrowserCleanupError, closeManagedBrowser } from "../browser/launch.js"; +import { BrowserCleanupError, closeManagedBrowser, onStopSignal } from "../browser/launch.js"; import { collectMotionBlurDrafts, dropMotionBlurConsoleEcho } from "./checkMotionBlur.js"; import { checkSnapshotDirectory } from "./checkSnapshotDirectory.js"; import { existsSync, mkdirSync, writeFileSync } from "node:fs"; @@ -50,6 +50,7 @@ import { FfmpegUnavailableError, getProxyCachePath, resolveProxies, + type ProxyProgress, } from "@hyperframes/studio-server/proxy-transcoder"; import { rectToBbox } from "./checkTypes.js"; import type { @@ -136,6 +137,43 @@ interface FinishedContrast { bg: string; } +const COPY_HEARTBEAT_MS = 10_000; + +function elapsedText(ms: number): string { + const seconds = Math.round(ms / 1000); + return seconds < 60 ? `${seconds}s` : `${Math.floor(seconds / 60)}m ${seconds % 60}s`; +} + +/** Says on stderr how far each copy is, so a slow copy reads as slow and a stuck one as stuck. */ +function startCopyHeartbeat( + sources: ReadonlyArray<{ file: string }>, + cached: readonly boolean[], +): { + progress: (index: number, progress: ProxyProgress) => void; + settled: (index: number) => void; + stop: () => void; +} { + const startedAt = Date.now(); + const latest = new Map(); + const timer = setInterval(() => { + for (const [index, { doneSeconds, totalSeconds }] of latest) { + if (cached[index]) continue; + const done = totalSeconds + ? `${Math.min(100, Math.floor((doneSeconds / totalSeconds) * 100))}%` + : ""; + console.error( + `[hyperframes] browser-playable copy of ${sources[index]!.file}: ${done || `${Math.floor(doneSeconds)}s done`} (${elapsedText(Date.now() - startedAt)} so far)`, + ); + } + }, COPY_HEARTBEAT_MS); + timer.unref(); + return { + progress: (index, progress) => void latest.set(index, progress), + settled: (index) => void latest.delete(index), + stop: () => clearInterval(timer), + }; +} + /** * Awaits the H.264 authoring proxy for every browser-hostile local video * asset in `html` BEFORE the timed render-ready wait starts. `check`'s @@ -190,9 +228,22 @@ export async function preResolveHostileMediaProxies( ); } let settled = 0; - const results = await resolveProxies(projectDir, sources, () => { - settled += 1; - if (toMake > 0) console.error(`[hyperframes] browser-playable copies: ${settled}/${total}`); + const heartbeat = startCopyHeartbeat(sources, cached); + const stopped = new AbortController(); + const forgetStop = onStopSignal(() => stopped.abort()); + const results = await resolveProxies( + projectDir, + sources, + (index) => { + settled += 1; + heartbeat.settled(index); + if (toMake > 0) console.error(`[hyperframes] browser-playable copies: ${settled}/${total}`); + }, + heartbeat.progress, + stopped.signal, + ).finally(() => { + heartbeat.stop(); + forgetStop(); }); const failures = sources.flatMap((source, index) => { const result = results[index]!; diff --git a/packages/cli/src/utils/staticProjectServer.test.ts b/packages/cli/src/utils/staticProjectServer.test.ts index 151a7a09a9..a76ae6e820 100644 --- a/packages/cli/src/utils/staticProjectServer.test.ts +++ b/packages/cli/src/utils/staticProjectServer.test.ts @@ -445,7 +445,7 @@ describe("serveStaticProjectHtml transparent media proxies", () => { undefined, true, expect.any(AbortSignal), - { width: 2048, height: 1448 }, + { width: 2048, height: 1218 }, ); }); diff --git a/packages/core/src/hdrToneMap.test.ts b/packages/core/src/hdrToneMap.test.ts index 3e084b66ab..7edea21386 100644 --- a/packages/core/src/hdrToneMap.test.ts +++ b/packages/core/src/hdrToneMap.test.ts @@ -10,6 +10,12 @@ describe("hdrToSdrToneMapFilter", () => { expect(hdrToSdrToneMapFilter(PQ, PQ)).toBe(TONE_MAP); }); + it("resizes in the first zscale, before the tone map, when it is given a size", () => { + expect(hdrToSdrToneMapFilter(PQ, PQ, { width: "1920", height: "1080" })).toBe( + "zscale=w=1920:h=1080:t=linear:npl=100,tonemap=hable:desat=0,zscale=p=bt709:t=bt709:m=bt709:r=tv", + ); + }); + it("sets the probed tags the first frame lacks", () => { expect(hdrToSdrToneMapFilter(PQ, {})).toBe( `setparams=colorspace=bt2020nc:color_primaries=bt2020:color_trc=smpte2084,${TONE_MAP}`, diff --git a/packages/core/src/hdrToneMap.ts b/packages/core/src/hdrToneMap.ts index 5cee5ccdd8..6dac52002e 100644 --- a/packages/core/src/hdrToneMap.ts +++ b/packages/core/src/hdrToneMap.ts @@ -15,6 +15,7 @@ function known(value: string | undefined): string | undefined { export function hdrToSdrToneMapFilter( probed: ToneMapSourceColour, firstFrame: ToneMapSourceColour, + size?: { width: string; height: string }, ): string { const fill = (key: keyof ToneMapSourceColour, fallback?: string) => known(firstFrame[key]) ? undefined : (known(probed[key]) ?? fallback); @@ -24,7 +25,8 @@ export function hdrToSdrToneMapFilter( ["color_trc", fill("colorTransfer")], ].filter(([, value]) => value); const setTags = tags.length ? `setparams=${tags.map((tag) => tag.join("=")).join(":")},` : ""; - return `${setTags}zscale=t=linear:npl=100,tonemap=hable:desat=0,zscale=p=bt709:t=bt709:m=bt709:r=tv`; + const resizeBeforeToneMap = size ? `w=${size.width}:h=${size.height}:` : ""; + return `${setTags}zscale=${resizeBeforeToneMap}t=linear:npl=100,tonemap=hable:desat=0,zscale=p=bt709:t=bt709:m=bt709:r=tv`; } /** ffmpeg args printing the first shown frame's tags; ffprobe's packet-bounded reads miss edit-list pre-roll. */ diff --git a/packages/core/src/previewProxyBox.test.ts b/packages/core/src/previewProxyBox.test.ts index 6d93e03c3f..3e1a2bab14 100644 --- a/packages/core/src/previewProxyBox.test.ts +++ b/packages/core/src/previewProxyBox.test.ts @@ -3,10 +3,19 @@ import { parsePreviewProxyBox, quantizePreviewProxyBox } from "./previewProxyBox describe("preview proxy box", () => { it("rounds each side up to the next rung", () => { - expect(quantizePreviewProxyBox(1080, 1920)).toEqual({ width: 1448, height: 2048 }); + expect(quantizePreviewProxyBox(1080, 1920)).toEqual({ width: 1218, height: 2048 }); expect(quantizePreviewProxyBox(1, 256)).toEqual({ width: 256, height: 256 }); }); + it("keeps a 1080p stage's box within a fifth of the stage on each side", () => { + expect(quantizePreviewProxyBox(1920, 1080)).toEqual({ width: 2048, height: 1218 }); + for (let side = 256; side <= 8192; side += 7) { + const box = quantizePreviewProxyBox(side, side)!; + expect(box.width).toBeGreaterThanOrEqual(side); + expect(box.width / side).toBeLessThan(1.2); + } + }); + it("has no bound for an empty box or one past the largest rung", () => { expect(quantizePreviewProxyBox(0, 1920)).toBeNull(); expect(quantizePreviewProxyBox(8193, 100)).toBeNull(); diff --git a/packages/core/src/previewProxyBox.ts b/packages/core/src/previewProxyBox.ts index ae848ded52..46016422a1 100644 --- a/packages/core/src/previewProxyBox.ts +++ b/packages/core/src/previewProxyBox.ts @@ -3,8 +3,11 @@ export const PREVIEW_PROXY_BOX_PARAM = "hf-proxy-box"; export type PreviewProxyBox = { width: number; height: number }; -// 256 * 2^(k/2), even: nearby boxes share one cached copy, and a rung overshoots by at most ~41%. -const RUNGS = [256, 362, 512, 724, 1024, 1448, 2048, 2896, 4096, 5792, 8192]; +// 256 * 2^(k/4), even: nearby boxes share one cached copy, and a rung overshoots by at most ~19%. +const RUNGS = [ + 256, 304, 362, 430, 512, 608, 724, 862, 1024, 1218, 1448, 1722, 2048, 2436, 2896, 3444, 4096, + 4870, 5792, 6888, 8192, +]; function rungAtLeast(pixels: number): number | null { if (!(pixels > 0)) return null; diff --git a/packages/core/src/runtime/mediaProxy.test.ts b/packages/core/src/runtime/mediaProxy.test.ts index d3b385882e..3a74daef82 100644 --- a/packages/core/src/runtime/mediaProxy.test.ts +++ b/packages/core/src/runtime/mediaProxy.test.ts @@ -799,7 +799,7 @@ describe("a copy sized to how large the video shows", () => { // A 1080x1920 stage at half size on a 2x screen is 1080x1920 device pixels. setProxyDisplayScale(0.5); await settle(); - expect(boxOf(el)).toBe("1448x2048"); + expect(boxOf(el)).toBe("1218x2048"); expect(vi.mocked(fetch).mock.calls[0]?.[0]).toBe(el.src); }); @@ -807,7 +807,7 @@ describe("a copy sized to how large the video shows", () => { const { el, setProxyDisplayScale } = await framedVideo(2160, 3840); setProxyDisplayScale(0.5); await settle(); - expect(boxOf(el)).toBe("2896x4096"); + expect(boxOf(el)).toBe("2436x4096"); }); it("asks for the source-size copy when the host never says", async () => { @@ -828,12 +828,12 @@ describe("a copy sized to how large the video shows", () => { setProxyDisplayScale(1); setProxyDisplayScale(1); await settle(); - expect(boxOf(el)).toBe("2896x4096"); + expect(boxOf(el)).toBe("2436x4096"); expect(el.load).toHaveBeenCalledTimes(2); setProxyDisplayScale(0.25); await settle(); - expect(boxOf(el)).toBe("2896x4096"); + expect(boxOf(el)).toBe("2436x4096"); expect(el.load).toHaveBeenCalledTimes(2); }); @@ -845,7 +845,7 @@ describe("a copy sized to how large the video shows", () => { setProxyDisplayScale(1); setProxyDisplayScale(2); await settle(); - expect(boxOf(el)).toBe("5792x8192"); + expect(boxOf(el)).toBe("4870x8192"); expect(el.load).toHaveBeenCalledTimes(2); }); @@ -866,6 +866,6 @@ describe("a copy sized to how large the video shows", () => { setProxyDisplayScale(1); made = true; await vi.advanceTimersByTimeAsync(2_000); - expect(boxOf(el)).toBe("2896x4096"); + expect(boxOf(el)).toBe("2436x4096"); }); }); diff --git a/packages/studio-server/src/helpers/proxyTranscoder.test.ts b/packages/studio-server/src/helpers/proxyTranscoder.test.ts index 520551a02a..9bad245894 100644 --- a/packages/studio-server/src/helpers/proxyTranscoder.test.ts +++ b/packages/studio-server/src/helpers/proxyTranscoder.test.ts @@ -58,13 +58,20 @@ function meanLuma(path: string, filters = "", inputArgs: string[] = []): number // this test file and the module are authored together). const MAX_CONCURRENT = 2; const MAX_QUEUED = 8; +// Mirrors PROXY_CHUNK_SECONDS in proxyTranscoder.ts. +const PIECE_SECONDS = 15; -type FakeProc = EventEmitter & { stderr: EventEmitter; stdout: EventEmitter }; +type FakeProc = EventEmitter & { + stderr: EventEmitter; + stdout: EventEmitter; + kill: (signal?: string) => void; +}; function createFakeProc(): FakeProc { const proc = new EventEmitter() as FakeProc; proc.stderr = new EventEmitter(); proc.stdout = new EventEmitter(); + proc.kill = vi.fn((signal?: string) => void proc.emit("close", null, signal)); return proc; } @@ -166,6 +173,8 @@ async function loadModule( } describe("resolveProxy on a long source", () => { + // Three pieces: two full ones and a last that takes the remainder. + const LONG_SECONDS = 3 * PIECE_SECONDS + 5; const startsOf = (calls: SpawnCall[]): string[] => calls .filter((call) => call.args.includes("-ss")) @@ -179,7 +188,7 @@ describe("resolveProxy on a long source", () => { false, null, undefined, - 200, + LONG_SECONDS, ); const projectDir = tmpProject(); const sourcePath = join(projectDir, "long.mov"); @@ -193,11 +202,14 @@ describe("resolveProxy on a long source", () => { await flush(50); calls[1]!.proc.emit("close", null, "SIGKILL"); expect(await first).toBeInstanceOf(Error); - expect(startsOf(calls)).toEqual(["0", "60"]); + expect(startsOf(calls)).toEqual(["0", String(PIECE_SECONDS)]); expect(readdirSync(cacheDirectory)).toHaveLength(1); clearFailedTranscodesForTest(); - const second = resolveProxy(projectDir, sourcePath); + const heard: Array<{ doneSeconds: number; totalSeconds?: number }> = []; + const second = resolveProxy(projectDir, sourcePath, "h264", undefined, { + onProgress: (progress) => heard.push(progress), + }); for (let answered = calls.length; ; answered = calls.length) { await flush(50); if (calls.length === answered) break; @@ -206,14 +218,22 @@ describe("resolveProxy on a long source", () => { expect(await second).toBe(cachePath); // Only the pieces that were missing were encoded again; the last one runs to the end. - expect(startsOf(calls)).toEqual(["0", "60", "60", "120"]); + expect(startsOf(calls)).toEqual([ + "0", + String(PIECE_SECONDS), + String(PIECE_SECONDS), + String(2 * PIECE_SECONDS), + ]); + // The retry says at once how much the stopped run left done, then counts on from it. + expect(heard[0]).toEqual({ doneSeconds: PIECE_SECONDS, totalSeconds: LONG_SECONDS }); + expect(heard.at(-1)).toEqual({ doneSeconds: LONG_SECONDS, totalSeconds: LONG_SECONDS }); expect(calls.at(-1)!.args).toEqual(expect.arrayContaining(["-f", "concat", "-c", "copy"])); expect(readdirSync(cacheDirectory)).toEqual([cachePath.split("/").at(-1)]); }); it("keeps a short source to one pass", async () => { const { spawn, calls } = createSpawnSpy(); - const { resolveProxy } = await loadModule(spawn, FFMPEG_PATH, false, null, undefined, 80); + const { resolveProxy } = await loadModule(spawn, FFMPEG_PATH, false, null, undefined, 20); const projectDir = tmpProject(); const sourcePath = join(projectDir, "short.mov"); writeFileSync(sourcePath, "source-bytes"); @@ -438,6 +458,141 @@ describe("resolveProxy", () => { await result; }); + it("resizes HDR input to the box before the tone map, so the map runs on the smaller frame", async () => { + const { spawn, calls } = createSpawnSpy(); + const { resolveProxy } = await loadModule(spawn, FFMPEG_PATH, true); + const projectDir = tmpProject(); + const sourcePath = join(projectDir, "hdr.mov"); + writeFileSync(sourcePath, "source-bytes"); + + const result = resolveProxy(projectDir, sourcePath, "h264", { width: 2048, height: 1218 }); + await flush(); + calls[0]!.proc.stdout.emit( + "data", + Buffer.from(" ..C zscale V->V zimg\n T.C tonemap V->V tone map\n"), + ); + calls[0]!.proc.emit("close", 0); + await flush(); + + const filter = calls[1]!.args[calls[1]!.args.indexOf("-vf") + 1]!; + expect(filter.indexOf("zscale=w=")).toBeGreaterThanOrEqual(0); + expect(filter.indexOf("zscale=w=")).toBeLessThan(filter.indexOf("tonemap=")); + expect(filter).toContain("2048/iw"); + succeed(calls[1]!); + await result; + }); + + it("tells a listener how far the encode has got, from ffmpeg's own progress lines", async () => { + const { spawn, calls } = createSpawnSpy(); + const { resolveProxy } = await loadModule(spawn, FFMPEG_PATH, false, null, undefined, 20); + const projectDir = tmpProject(); + const sourcePath = join(projectDir, "progress.mov"); + writeFileSync(sourcePath, "source-bytes"); + const heard: Array<{ doneSeconds: number; totalSeconds?: number }> = []; + + const result = resolveProxy(projectDir, sourcePath, "h264", undefined, { + onProgress: (progress) => heard.push(progress), + }); + await flush(); + expect(calls[0]!.args).toEqual(expect.arrayContaining(["-progress", "pipe:1"])); + calls[0]!.proc.stdout.emit("data", Buffer.from("frame=10\nout_time_us=12000000\nprogre")); + calls[0]!.proc.stdout.emit( + "data", + Buffer.from("ss=continue\nout_time_us=18500000\nprogress=continue\n"), + ); + + expect(heard).toEqual([ + { doneSeconds: 12, totalSeconds: 20 }, + { doneSeconds: 18.5, totalSeconds: 20 }, + ]); + succeed(calls[0]!); + await result; + }); + + describe("a copy that stops making progress", () => { + afterEach(() => vi.useRealTimers()); + + it("is ended once it makes no progress for the stall window, not before", async () => { + vi.useFakeTimers(); + const { spawn, calls } = createSpawnSpy(); + const { resolveProxy, TRANSCODE_STALL_MS } = await loadModule( + spawn, + FFMPEG_PATH, + false, + null, + undefined, + 80, + ); + const projectDir = tmpProject(); + const sourcePath = join(projectDir, "hung.mov"); + writeFileSync(sourcePath, "source-bytes"); + + const result = resolveProxy(projectDir, sourcePath).catch((error: unknown) => error); + await vi.advanceTimersByTimeAsync(0); + await vi.advanceTimersByTimeAsync(TRANSCODE_STALL_MS - 1); + expect(calls[0]!.proc.kill).not.toHaveBeenCalled(); + await vi.advanceTimersByTimeAsync(1); + + expect(calls[0]!.proc.kill).toHaveBeenCalledWith("SIGKILL"); + expect(await result).toEqual( + expect.objectContaining({ message: expect.stringMatching(/no progress/) }), + ); + }); + + it("keeps going past the old fifteen minute cap while it moves on", async () => { + vi.useFakeTimers(); + const { spawn, calls } = createSpawnSpy(); + const { resolveProxy, TRANSCODE_STALL_MS } = await loadModule( + spawn, + FFMPEG_PATH, + false, + null, + undefined, + 20, + ); + const projectDir = tmpProject(); + const sourcePath = join(projectDir, "slow.mov"); + writeFileSync(sourcePath, "source-bytes"); + + const result = resolveProxy(projectDir, sourcePath); + await vi.advanceTimersByTimeAsync(0); + const step = TRANSCODE_STALL_MS / 2; + for (let at = 1; at <= (20 * 60_000) / step; at++) { + await vi.advanceTimersByTimeAsync(step); + calls[0]!.proc.stdout.emit("data", Buffer.from(`out_time_us=${at * 1_000_000}\n`)); + } + + expect(calls[0]!.proc.kill).not.toHaveBeenCalled(); + succeed(calls[0]!); + await result; + }); + }); + + it("hands the abort signal of a batch to its copies, so a stopped check ends them", async () => { + const { spawn, calls } = createSpawnSpy(); + const { resolveProxies } = await loadModule(spawn, FFMPEG_PATH, false, null, undefined, 80); + const projectDir = tmpProject(); + const sourcePath = join(projectDir, "stopped.mov"); + writeFileSync(sourcePath, "source-bytes"); + const stopped = new AbortController(); + + const results = resolveProxies( + projectDir, + [{ sourcePath, variant: "h264" }], + undefined, + undefined, + stopped.signal, + ); + await flush(); + expect(calls[0]!.options?.signal?.aborted).toBe(false); + stopped.abort(); + await flush(); + + expect(calls[0]!.options?.signal?.aborted).toBe(true); + calls[0]!.proc.emit("close", null, "SIGKILL"); + expect((await results)[0]!.status).toBe("rejected"); + }); + it("preserves alpha on HDR-tagged VP8 proxies by bypassing the opaque tonemap chain", async () => { const { spawn, calls } = createSpawnSpy(); const { resolveProxy } = await loadModule(spawn, FFMPEG_PATH, true); diff --git a/packages/studio-server/src/helpers/proxyTranscoder.ts b/packages/studio-server/src/helpers/proxyTranscoder.ts index 3aa5df973d..3464d8257c 100644 --- a/packages/studio-server/src/helpers/proxyTranscoder.ts +++ b/packages/studio-server/src/helpers/proxyTranscoder.ts @@ -35,7 +35,7 @@ import { mkdirWithinProject, realpath, realProjectRoot } from "./safePath.js"; * dropped from the queue or its ffmpeg is killed. */ -export const PROXY_PARAMS_VERSION = "v5"; +export const PROXY_PARAMS_VERSION = "v6"; export const CACHE_DIR_NAME = ".transcode-cache"; @@ -53,9 +53,15 @@ const MAX_CONCURRENT_TRANSCODES = boundedEnvInteger("HYPERFRAMES_PROXY_MAX_CONCU const MAX_QUEUED_TRANSCODES = boundedEnvInteger("HYPERFRAMES_PROXY_MAX_QUEUE", 8, 0, 256); const STDERR_TAIL_MAX_CHARS = 4000; -export const TRANSCODE_TIMEOUT_MS = 15 * 60 * 1000; -/** A longer source is copied in pieces this long; a stopped copy keeps its finished pieces. */ -const PROXY_CHUNK_SECONDS = 60; +/** A copy that makes no progress this long is ended: a hung encode, not a slow one. */ +export const TRANSCODE_STALL_MS = boundedEnvInteger( + "HYPERFRAMES_PROXY_STALL_MS", + 3 * 60 * 1000, + 10_000, + 60 * 60 * 1000, +); +/** A longer source is copied in pieces this long; a stopped copy keeps its finished pieces and loses at most one. */ +export const PROXY_CHUNK_SECONDS = 15; const CHUNK_PREFIX = ".part-"; const CONCAT_TIMEOUT_MS = 2 * 60 * 1000; const FAILURE_CACHE_TTL_MS = 60 * 1000; @@ -248,6 +254,19 @@ interface ProxyJob { /** Set while the job waits for a slot. */ queued?: { start: () => void; drop: () => void }; abandoned: AbortController; + progress: Set<(progress: ProxyProgress) => void>; + lastProgress?: ProxyProgress; +} + +/** How far a copy has got: seconds of the source done, out of its length when that is known. */ +export interface ProxyProgress { + doneSeconds: number; + totalSeconds?: number; +} + +function reportProgress(job: ProxyJob, progress: ProxyProgress): void { + job.lastProgress = progress; + for (const listener of job.progress) listener(progress); } class ProxyDroppedError extends ProxyTranscodeError { @@ -411,11 +430,16 @@ export function clearFailedTranscodesForTest(): void { } /** Even dimensions; with a box, the source shrinks until its tighter side fills the box, never grows. */ -function proxyScaleFilter(box?: PreviewProxyBox): string { - if (!box) return "scale=trunc(iw/2)*2:trunc(ih/2)*2"; +function proxyScaleSize(box?: PreviewProxyBox): { width: string; height: string } { + if (!box) return { width: "trunc(iw/2)*2", height: "trunc(ih/2)*2" }; const factor = `min(1\\,max(${box.width}/iw\\,${box.height}/ih))`; const side = (d: string) => `min(trunc(${d}/2)*2\\,ceil(${d}*${factor}/2)*2)`; - return `scale=${side("iw")}:${side("ih")}`; + return { width: side("iw"), height: side("ih") }; +} + +function proxyScaleFilter(box?: PreviewProxyBox): string { + const { width, height } = proxyScaleSize(box); + return `scale=${width}:${height}`; } const STDERR_ERROR_LINE = /error|invalid|denied|no space|not found|unknown/i; @@ -448,15 +472,7 @@ function chunkRanges(durationSeconds: number | undefined): ChunkRange[] | null { })); } -function ffmpegBudgetError(chunksKept: number, chunkCount: number): ProxyTranscodeError { - return new ProxyTranscodeError( - `ffmpeg ran out of its ${TRANSCODE_TIMEOUT_MS}ms budget with ${chunksKept}/${chunkCount} pieces done; the finished pieces are kept and the next attempt continues from them`, - null, - "", - ); -} - -type EncodeFn = (outputPath: string, timeoutMs: number, range?: ChunkRange) => Promise; +type EncodeFn = (outputPath: string, range?: ChunkRange) => Promise; /** Copies a long source in pieces that stay in the cache, so a stopped copy continues from the first missing one. */ async function encodeInChunks( @@ -465,19 +481,24 @@ async function encodeInChunks( tempPath: string, encode: EncodeFn, concat: (listPath: string, target: string) => Promise, + onDone: (doneSeconds: number) => void = () => {}, ): Promise { const extension = extname(tempPath); - const deadline = Date.now() + TRANSCODE_TIMEOUT_MS; const pieces = ranges.map((_, index) => `${chunkPrefix}${index}${extension}`); + let doneSeconds = 0; + for (const [index, range] of ranges.entries()) { + if (existsSync(pieces[index]!)) doneSeconds += range.lengthSeconds; + } + if (doneSeconds) onDone(doneSeconds); for (const [index, range] of ranges.entries()) { const piece = pieces[index]!; if (existsSync(piece)) continue; - const timeoutMs = deadline - Date.now(); - if (timeoutMs <= 0) throw ffmpegBudgetError(index, ranges.length); const pieceTemp = join(dirname(piece), `.tmp-${randomUUID()}-${basename(piece)}`); try { - await encode(pieceTemp, timeoutMs, range); + await encode(pieceTemp, range); renameSync(pieceTemp, piece); + doneSeconds += range.lengthSeconds; + onDone(doneSeconds); } finally { if (existsSync(pieceTemp)) unlinkSync(pieceTemp); } @@ -566,7 +587,7 @@ async function buildVideoFilter( // The tone map ends in RGB; older ffmpeg (seen on 5.1) converts it with BT.601 unless the matrix is named. return toneMap ? [ - hdrToSdrToneMapFilter(metadata.color, firstFrame), + hdrToSdrToneMapFilter(metadata.color, firstFrame, box && proxyScaleSize(box)), `${evenScale}:out_color_matrix=bt709:out_range=tv`, `format=${pixelFormat}`, ].join(",") @@ -580,6 +601,7 @@ async function runFfmpeg( variant: ProxyVariant, box: PreviewProxyBox | undefined, signal: AbortSignal, + onProgress: (progress: ProxyProgress) => void, ): Promise { const metadata = await probeMediaMetadata(sourcePath); const ffmpegPath = findFfBinary("ffmpeg", { configuredMustExist: true }); @@ -590,11 +612,15 @@ async function runFfmpeg( const videoFilter = await buildVideoFilter(ffmpegPath, sourcePath, metadata, keepsAlpha, box); const alphaDecoder = keepsAlpha ? alphaDecoderFor(metadata.color.codecName) : null; const decoderArgs = alphaDecoder ? ["-c:v", alphaDecoder] : []; - const encode: EncodeFn = (target, timeoutMs, range) => + const totalSeconds = metadata.durationSeconds; + const encode: EncodeFn = (target, range) => spawnFfmpeg( ffmpegPath, [ "-y", + "-progress", + "pipe:1", + "-nostats", ...(range ? ["-ss", String(range.startSeconds)] : []), ...decoderArgs, "-i", @@ -605,13 +631,21 @@ async function runFfmpeg( ...(variant === "vp8" ? VP8_ARGS : H264_ARGS), target, ], - timeoutMs, + TRANSCODE_STALL_MS, signal, + (encodedSeconds) => + onProgress({ doneSeconds: (range?.startSeconds ?? 0) + encodedSeconds, totalSeconds }), ); - const ranges = chunkRanges(metadata.durationSeconds); - if (!ranges) return encode(outputPath, TRANSCODE_TIMEOUT_MS); - await encodeInChunks(ranges, chunkPrefix, outputPath, encode, (listPath, target) => - spawnFfmpeg(ffmpegPath, concatArgs(listPath, target, variant), CONCAT_TIMEOUT_MS, signal), + const ranges = chunkRanges(totalSeconds); + if (!ranges) return encode(outputPath); + await encodeInChunks( + ranges, + chunkPrefix, + outputPath, + encode, + (listPath, target) => + spawnFfmpeg(ffmpegPath, concatArgs(listPath, target, variant), CONCAT_TIMEOUT_MS, signal), + (doneSeconds) => onProgress({ doneSeconds, totalSeconds }), ); } @@ -631,44 +665,77 @@ function concatArgs(listPath: string, target: string, variant: ProxyVariant): st ]; } +/** ffmpeg's `-progress` lines name the output time reached, in microseconds. */ +const OUT_TIME = /^out_time_(?:us|ms)=(\d+)$/; + +/** Runs ffmpeg and ends it when it makes no progress for `stallMs`; a slow encode that moves on is left to finish. + * `onProgress` hears the seconds of output made so far (from `-progress pipe:1`). */ function spawnFfmpeg( ffmpegPath: string, args: string[], - timeoutMs: number, + stallMs: number, signal: AbortSignal, + onProgress?: (encodedSeconds: number) => void, ): Promise { return new Promise((resolvePromise, reject) => { - // Hard ceiling so a hung ffmpeg can never permanently occupy one of the - // global transcode slots: the child is killed and the slot released via - // the caller's finally. Generous because long assets transcode at - // roughly real time; a healthy encode of any authoring asset fits. signal.throwIfAborted(); const proc = spawn(ffmpegPath, args, { - stdio: ["ignore", "ignore", "pipe"], - timeout: timeoutMs, + stdio: ["ignore", "pipe", "pipe"], killSignal: "SIGKILL", signal, windowsHide: true, }); + let stalled = false; + let timer: NodeJS.Timeout | undefined; + const armStall = (): void => { + clearTimeout(timer); + timer = setTimeout(() => { + stalled = true; + proc.kill("SIGKILL"); + }, stallMs); + timer.unref(); + }; + armStall(); + let furthest = 0; + let lineTail = ""; + proc.stdout?.on("data", (chunk: Buffer) => { + const lines = (lineTail + chunk.toString()).split("\n"); + lineTail = lines.pop() ?? ""; + for (const line of lines) { + const reached = OUT_TIME.exec(line.trim()); + if (!reached) continue; + const seconds = Number(reached[1]) / 1e6; + if (seconds <= furthest) continue; + furthest = seconds; + armStall(); + onProgress?.(seconds); + } + }); let stderrTail = ""; proc.stderr?.on("data", (chunk: Buffer) => { stderrTail = (stderrTail + chunk.toString()).slice(-STDERR_TAIL_MAX_CHARS); }); proc.on("error", (err) => { + clearTimeout(timer); if (signal.aborted) return; reject(new FfmpegUnavailableError(`failed to spawn ffmpeg: ${err.message}`, stderrTail)); }); - proc.on("close", (code, signal) => { + proc.on("close", (code, killedBy) => { + clearTimeout(timer); if (code === 0) { resolvePromise(); - } else if (signal) { + } else if (stalled) { reject( new ProxyTranscodeError( - `ffmpeg killed by ${signal} (timeout ${timeoutMs}ms or external kill)`, + `ffmpeg made no progress for ${Math.round(stallMs / 1000)}s and was ended; finished pieces are kept for the next attempt`, null, stderrTail, ), ); + } else if (killedBy) { + reject( + new ProxyTranscodeError(`ffmpeg killed by ${killedBy} (external kill)`, null, stderrTail), + ); } else { reject( new ProxyTranscodeError( @@ -710,6 +777,7 @@ async function transcodeToCache( variant, box, job.abandoned.signal, + (progress) => reportProgress(job, progress), ); renameSync(tempPath, cachePath); maintainProxyCache(cacheDir); @@ -779,6 +847,7 @@ export async function resolveProxy( priority: options.priority === true, callers: 0, abandoned: new AbortController(), + progress: new Set(), }; const promise = transcodeToCache( job, @@ -802,15 +871,26 @@ export async function resolveProxy( inFlight.set(cachePath, entry); } if (options.priority) prioritize(entry.job); - return joinJob(entry.promise, entry.job, options.signal); + const listener = options.onProgress; + const joined = joinJob(entry.promise, entry.job, options.signal); + if (listener) { + entry.job.progress.add(listener); + if (entry.job.lastProgress) listener(entry.job.lastProgress); + const stop = (): void => void entry.job.progress.delete(listener); + joined.then(stop, stop); + } + return joined; } /** Batch resolve for check and publish: at most MAX_CONCURRENT_TRANSCODES of its own requests in - * flight (other callers can still fill the queue); each waits at most TRANSCODE_TIMEOUT_MS. */ + * flight (other callers can still fill the queue). A copy is ended only when it stops making + * progress (TRANSCODE_STALL_MS), so a long source that keeps moving is never cut by a clock. */ export async function resolveProxies( projectDir: string, sources: ReadonlyArray<{ sourcePath: string; variant: ProxyVariant; box?: PreviewProxyBox }>, - onSettled: () => void = () => {}, + onSettled: (index: number) => void = () => {}, + onProgress: (index: number, progress: ProxyProgress) => void = () => {}, + signal?: AbortSignal, ): Promise[]> { const first = sources[0]; if (first) { @@ -827,14 +907,14 @@ export async function resolveProxies( const worker = async (): Promise => { for (let index = next++; index < sources.length; index = next++) { const { sourcePath, variant, box } = sources[index]!; - results[index] = await waitForProxy( - resolveProxy(projectDir, sourcePath, variant, box), - TRANSCODE_TIMEOUT_MS, - ).then( + results[index] = await resolveProxy(projectDir, sourcePath, variant, box, { + onProgress: (progress) => onProgress(index, progress), + signal, + }).then( (value) => ({ status: "fulfilled", value }), (reason: unknown) => ({ status: "rejected", reason }), ); - onSettled(); + onSettled(index); } }; const workers = Math.min(MAX_CONCURRENT_TRANSCODES, sources.length); @@ -845,6 +925,8 @@ export async function resolveProxies( export interface ResolveProxyOptions { priority?: boolean; signal?: AbortSignal; + /** Hears how far the shared copy has got, from the first caller's start to the copy's end. */ + onProgress?: (progress: ProxyProgress) => void; } function joinJob(promise: Promise, job: ProxyJob, signal?: AbortSignal): Promise { diff --git a/scripts/package-size-budgets.json b/scripts/package-size-budgets.json index ceb05c1831..cede2a2fe2 100644 --- a/scripts/package-size-budgets.json +++ b/scripts/package-size-budgets.json @@ -36,7 +36,7 @@ "unpacked": 541601 }, "@hyperframes/producer": { - "packed": 768546, + "packed": 768601, "unpacked": 2808835 }, "@hyperframes/sdk": { @@ -52,7 +52,7 @@ "unpacked": 24360208 }, "@hyperframes/studio-server": { - "packed": 144500, + "packed": 145266, "unpacked": 568500 } }