diff --git a/docs/USAGE.md b/docs/USAGE.md index fe056771..22c9b3a9 100644 --- a/docs/USAGE.md +++ b/docs/USAGE.md @@ -298,6 +298,8 @@ agent-tty record export --format webm --json | jq -c '.result.missi WebM export replays with recorded wall-clock timing by default. Pass `--timing accelerated` (idle gaps clamped to 400ms) or `--timing max-speed` for a time-compressed video. A frame of the video shows the screen after the output that arrived within one frame hold of the first output of that frame: 16 ms in `recorded` and `max-speed` mode, 100 ms in `accelerated` mode. Output events that close together share one frame, so a burst of output does not cost one frame per event, and a state that the next output of the frame replaces is not shown. In `recorded` and `accelerated` mode, an event that changes no pixel (an input, a marker, a run-complete, a signal or the exit) also ends a frame. In `max-speed` mode it does not: only recorded time ends a frame, so output on both sides of an input event that is less than 16 ms apart shares one frame. `max-speed` removes the idle time. It makes a frame at most once per 16 ms of recorded time, so a progress bar that updates every 30 ms shows many of its steps and not only its last one. It makes at most about 2,400 frames, so a recording longer than 38 s gets one frame per 1/2,400 of its recorded time instead (a 1-hour recording: one per 1.5 s), and its export time depends on its length and not on its number of events. `max-speed` waits for one animation frame after each frame but holds no further time between two frames, so two frames that follow each other can end up in one video frame. The video has 25 frames per second, so it can skip a state that lasts less than one video frame (40 ms). A step of 30 ms is shorter than that, and the number of steps that survive depends on how fast the host runs the export. +With recorded timing the replay waits out every recorded gap, so an export takes at least as long as the recording. It takes longer when the recording is dense or resizes a large terminal, because each frame costs time in the browser and each resize of a large terminal costs seconds. On a shared host, a recording of 7.4 s with 7,401 events took 473 s at `--timing accelerated`, and a recording of 0.8 s with 400 resizes of a 600x150 terminal took 910 s at recorded timing. The export has no total time limit. It stops only when the renderer makes no progress for 5 minutes, and then fails with `EXPORT_ERROR`. The message names the window and the last event that the replay reached, and `details` holds `stallWindowMs`, `lastSeq` and `timingMode`. Waiting out a recorded gap is not a stall. + SVG export renders styled grid frames from the event log through the native `libghostty-vt` backend with no browser and no ffmpeg, so it requires the optional `@coder/libghostty-vt-node` package (there is no `ghostty-web` fallback). The output is deterministic: exporting the same session twice produces byte-identical, diffable SVG. `--format svg` writes a still image of the final screen and ignores event timing, so it also works on a log whose clock stepped backward (`--animate` refuses such a log and names the event where the clock stepped back); add `--animate` for an animated SVG of de-duplicated frames replayed with recorded event-log timing (`--timing` is not supported with SVG). Animated SVG capture retains every distinct frame's styled grid in memory, so it is bounded by a total-cell budget (the V8 heap limit divided by 400 bytes, at most 20M cells or roughly 10,000 distinct 80x24 frames, adapting to terminal size); recordings that exceed it fail with a clear error suggesting a still SVG or WebM export instead. The SVG text is also bounded (the V8 heap limit divided by 8 bytes, at most 2^28 characters or about 268 MB of mostly ASCII text), so a dense, colorful animation that fits the cell budget can still fail with the same kind of error. diff --git a/src/cli/commands/README.md b/src/cli/commands/README.md index a37f55bb..a0e2ed1e 100644 --- a/src/cli/commands/README.md +++ b/src/cli/commands/README.md @@ -34,7 +34,7 @@ This directory holds one handler module per agent-tty CLI command. `src/cli/main - `wait` rejects a mix of legacy flags (`--exit`, `--idle-ms`) and render flags. `--text` and `--regex` are mutually exclusive. The default timeout is `DEFAULT_WAIT_TIMEOUT_MS` (30,000 ms), which the `main.ts` help text names. An `--idle-ms` at or above the effective timeout (explicit or default), or a `--screen-stable-ms` whose `screenStableMinimumMs` is not shorter than it, throws `INVALID_DURATION`. `--timeout 0` skips the check. [wait.ts:runWaitCommand] [wait.ts:assertWindowFitsTimeout] [main.ts:main] - A timed-out `wait` throws `WAIT_TIMEOUT` with the wait result attached, so its error envelope keeps `result`. Without `--json`, and only when the wait lasted its whole timeout (`timeoutMs > 0`, measured by the CLI), the message names the timeout and, for the default, how to change it. With `--json`, the message stays `Wait timed out before its condition was met.` The host sends `eventLogStop` with the result of a render wait that timed out. When it does, in both modes the message ends with `The event log stopped at seq (), so output after it is not seen.` and `details.eventLogStop` carries `{ reason, seq }`. The CLI never rereads the event log for a wait. `--idle-ms` and `--exit` waits carry no stop. When the host is unreachable, `wait` replays the stored log. A wait that the replayed screen does not satisfy fails with `REPLAY_ERROR`, and its message and `details.eventLogStop` carry the stop that `findEventLogStop` finds in the replayed events. [wait.ts:throwIfTimedOut] [wait.ts:timeoutMessage] [wait.ts:buildOfflineRenderWaitResult] - `snapshot` and `screenshot` try the live RPC only when the manifest status is `running`. They fall back to offline replay only on `HOST_UNREACHABLE` and rethrow other errors. [snapshot.ts:runSnapshotCommand] [screenshot.ts:runScreenshotCommand] -- `record export` accepts only the formats in `RecordExportFormatSchema` (`asciicast`, `webm`, `svg`). `--animate` needs `svg`, and `svg` refuses `--timing`. An event log over the size limit fails with `EXPORT_ERROR` in every format, a message that names the log size and the limit, and `eventLogBytes` and `maxEventLogBytes` in `details`. A `GhosttyWebCrashedError` from a WebM export fails with `EXPORT_ERROR` and adds its message to the fixed message. [record-export.ts:runRecordExportCommand] +- `record export` accepts only the formats in `RecordExportFormatSchema` (`asciicast`, `webm`, `svg`). `--animate` needs `svg`, and `svg` refuses `--timing`. An event log over the size limit fails with `EXPORT_ERROR` in every format, a message that names the log size and the limit, and `eventLogBytes` and `maxEventLogBytes` in `details`. A `webm` replay whose renderer makes no progress for the stall window fails with `EXPORT_ERROR`, a message that names the window and the last event that the replay reached, and `stallWindowMs`, `lastSeq` and `timingMode` in `details`. A `GhosttyWebCrashedError` from a WebM export fails with `EXPORT_ERROR` and adds its message to the fixed message. [record-export.ts:runRecordExportCommand] - `batch` parses the whole plan with `parseBatchPlan` before it resolves the session target. [batch.ts:runBatchCommand] - `create` polls readiness with an `inspect` RPC every `READINESS_POLL_INTERVAL_MS` (100 ms) for as long as the host process that it spawned runs (`hostRuns`). A probe that fails with `HOST_UNREACHABLE`, `HOST_TIMEOUT` or an `RPC_ERROR` whose cause is `EPIPE` (the host closed its server as the probe connected, as a host does whose program has already exited) counts as not ready yet (`isClosedByHost`). `create` rethrows that last error as soon as the host process has exited, and after `READINESS_DEADLINE_MS` (30 s) in any case. Any other error ends the wait at once. It checks the host process before it reads the manifest, so a session that exited before the host did is a result, not an error. [create.ts:waitForReadyHost] - `doctor` reports the `node-runtime` check as failed when the Node version is outside the `engines.node` range of `package.json`. It keeps running the other checks, reports `ok: false` and sets `process.exitCode = 1`. [doctor.ts:runNodeRuntimeCheck] [doctor.ts:runDoctorCommand] diff --git a/src/cli/commands/record-export.ts b/src/cli/commands/record-export.ts index 4f462149..1bebc8ec 100644 --- a/src/cli/commands/record-export.ts +++ b/src/cli/commands/record-export.ts @@ -13,6 +13,7 @@ import { generateAsciicast } from '../../export/asciicast.js'; import { renderGridFramesToSvg } from '../../export/svg.js'; import { generateWebmExport, + WebmReplayStallError, type WebmExportResult, } from '../../export/webm.js'; import { captureGridFrames } from '../../replay/gridFrames.js'; @@ -597,6 +598,25 @@ export async function runRecordExportCommand( }); } + if (error instanceof WebmReplayStallError) { + const position = + error.lastSeq >= 0 + ? `after event ${String(error.lastSeq)}` + : 'at the start of the replay'; + throw makeCliError(ERROR_CODES.EXPORT_ERROR, { + message: `Failed to export session "${options.sessionId}" as ${format}: the renderer made no progress for ${String(error.stallWindowMs / 1000)} s ${position} (${error.timingMode} timing).`, + details: { + sessionId: options.sessionId, + format, + out: options.out, + stallWindowMs: error.stallWindowMs, + lastSeq: error.lastSeq, + timingMode: error.timingMode, + }, + cause: error, + }); + } + throw makeCliError(ERROR_CODES.EXPORT_ERROR, { message: `Failed to export session "${options.sessionId}" as ${format}.${ error instanceof GhosttyWebCrashedError ? ` ${error.message}` : '' diff --git a/src/export/README.md b/src/export/README.md index 5a471594..2a30546d 100644 --- a/src/export/README.md +++ b/src/export/README.md @@ -10,9 +10,10 @@ This directory converts a session's event log into recording exports. `generateA - `AsciicastExport`: `contents`, `header`, `capturedAtSeq`, `durationMs`, `outputEventCount`, `resizeEventCount` and `markerCount` [asciicast.ts:AsciicastExport]. - `generateAsciicast(sessionId, manifest, events, toolVersion?)` returns an `AsciicastExport`. It runs synchronously [asciicast.ts:generateAsciicast]. - `WebmExportOptions`: `sessionId`, `sessionDir`, `manifest`, `events`, `outputPath`, and optional `targetSeq`, `profileName`, `timingMode` and `rendererName` [webm.ts:WebmExportOptions]. -- `WebmExportDeps`: optional `backendFactory` and `replayTimeoutMs`, for tests and callers that supply their own backend [webm.ts:WebmExportDeps]. +- `WebmExportDeps`: optional `backendFactory` and `stallWindowMs`, for tests and callers that supply their own backend. `stallWindowMs` replaces the 5-minute stall window (see Invariants) [webm.ts:WebmExportDeps]. - `WebmExportResult`: `capturedAtSeq`, `durationMs`, `outputEventCount`, `resizeEventCount`, `cols`, `rows`, `profileName`, `timingMode` and `rendererBackend`, plus the optional `missingGlyphs` and `missingGlyphsTruncated` of `RecordedGlyphFields` [webm.ts:WebmExportResult]. - `generateWebmExport(options, deps?)` returns a `Promise` [webm.ts:generateWebmExport]. +- `WebmReplayStallError` is the error that `generateWebmExport` rejects with when the renderer makes no progress for the stall window. It carries `stallWindowMs`, `lastSeq` (the last event that the replay reached, or -1 for none) and `timingMode` [webm.ts:WebmReplayStallError]. - `renderGridFramesToSvg({ profile, frames, animate, heapSizeLimit? })` returns SVG text from styled grid frames, which `captureGridFrames` in `src/replay/gridFrames.ts` builds. It runs synchronously and leaves the file write to the caller [svg.ts:renderGridFramesToSvg]. ## Invariants @@ -26,7 +27,7 @@ This directory converts a session's event log into recording exports. `generateA - A requested `libghostty-vt` renderer is replaced with `ghostty-web`. A code comment says `libghostty-vt` is semantic-only [webm.ts:generateWebmExport]. - The default backend factory accepts only `ghostty-web` [webm.ts:createDefaultBackend]. - Timing presets: `accelerated` caps gaps at 400 ms and holds frames at least 100 ms. `max-speed` uses a frame hold of 16 ms, but holds it only after the last flush of the replay and before and after a resize (see the `ghostty-web` README). Each mode holds the final frame (1000 ms, or 500 ms for `max-speed`) [webm.ts:buildReplayTimingOptions]. -- The timed replay fails after `REPLAY_TIMEOUT_MS` (5 minutes) [webm.ts:REPLAY_TIMEOUT_MS]. +- The timed replay has no total time limit. It fails with `WebmReplayStallError` only when the renderer makes no progress for `REPLAY_STALL_WINDOW_MS` (5 minutes). The backend reports progress through the `onProgress` argument of `replayWithTiming`: each report restarts the window. A report that comes before a wait on the timing schedule carries the length of that wait, and the window starts after it, so a long recorded gap is not a stall. A stretch without a report is one page call or a fixed hold, never the whole replay: a call carries at most 1000 chunks, and a report follows it. The stretches are the start to the first report (the replay sizes the terminal and holds one frame), one page call (the call that ends a flush also writes the chunks that the earlier calls of the flush held, so the event log limit of 50 MiB bounds it), and the last report to the end (the final frame hold of 1000 ms, or 500 ms at `max-speed`, with the glyph probes inside it, and then a read of the screen). Examples that I measured at 600x150 on a shared host under load: the start took 1.3 to 2.0 s, the end 1.8 to 2.8 s, a flush of 11,000 events of 4 KB 8.4 s, and one stretch inside the loop 4.4 s. These are examples and not bounds. The longest, 8.4 s, is under 3% of the window. No timer runs longer than 2^31-1 ms (the longest delay that a timer runs): a longer span is a chain of timers. The watchdog starts no timer once the replay has ended, failed or stalled. Boot and finalize run outside the watchdog [webm.ts:replayWithStallWatchdog, webm.ts:REPLAY_STALL_WINDOW_MS]. - `renderGridFramesToSvg` needs the profile font size `SVG_FONT_SIZE` (14) and draws fixed 8.4x18 px cells, so equal input gives byte-identical output [svg.ts:renderGridFramesToSvg]. It always embeds the JetBrains Mono subset, and embeds each other bundled face only when a glyph needs it [svg.ts:embeddedFontAssets]. Output past `defaultMaxSvgOutputLength` of the V8 heap limit (the heap limit divided by 8 bytes, at most `MAX_SVG_OUTPUT_LENGTH`) fails with `EXPORT_ERROR` [svg.ts:defaultMaxSvgOutputLength]. ## Side Effects diff --git a/src/export/webm.ts b/src/export/webm.ts index 326351d4..f9f7e5cf 100644 --- a/src/export/webm.ts +++ b/src/export/webm.ts @@ -11,6 +11,7 @@ import { } from '../protocol/schemas.js'; import type { RecordedGlyphFields, + ReplayProgress, ReplayTimingOptions, VideoCapableRendererBackend, VideoRecordingOptions, @@ -25,7 +26,23 @@ import { resolveProfile } from '../renderer/profiles.js'; import type { RenderProfileConfig, ReplayState } from '../renderer/types.js'; import { invariant, unreachable } from '../util/assert.js'; -const REPLAY_TIMEOUT_MS = 5 * 60 * 1000; +// The replay fails when the renderer makes no progress for this long. A stretch +// without a report is one page call or a fixed hold, never the whole replay: a +// call carries at most 1000 chunks, and a report follows it. The stretches are +// the start to the first report (the replay sizes the terminal and holds one +// frame), one page call (the call that ends a flush also writes the chunks that +// the earlier calls of the flush held, so the event log limit of 50 MiB bounds +// it), and the last report to the end (the final frame hold, which also covers +// the glyph probes, and then a read of the screen). Examples that I measured at +// 600x150 on a shared host under load: the start took 1.3 to 2.0 s, the end 1.8 +// to 2.8 s, a flush of 11,000 events of 4 KB 8.4 s, and one stretch inside the +// loop 4.4 s. These are examples and not bounds. The longest, 8.4 s, is under +// 3% of the window. The window is the old fixed limit on the whole replay, so +// an export that fit before still fits. Boot and finalize run outside the +// watchdog. +const REPLAY_STALL_WINDOW_MS = 5 * 60 * 1000; +// Node runs a timer with a longer delay after 1 ms. +const MAX_TIMER_DELAY_MS = 2 ** 31 - 1; // maxGapMs/minFrameHoldMs are tuned for watchability: shorter clamps make the // video flicker because every idle gap collapses to a near-instant cut. const ACCELERATED_TIMING: ReplayTimingOptions = Object.freeze({ @@ -50,6 +67,28 @@ function buildReplayTimingOptions(mode: ReplayTimingMode): ReplayTimingOptions { } } +export class WebmReplayStallError extends Error { + public readonly stallWindowMs: number; + // Seq of the last event that the replay reached, or -1 when it had reached + // none before it stalled. + public readonly lastSeq: number; + public readonly timingMode: ReplayTimingMode; + + public constructor( + stallWindowMs: number, + lastSeq: number, + timingMode: ReplayTimingMode, + ) { + super( + `WebM replay stalled: the renderer made no progress for ${String(stallWindowMs)} ms (last event seq ${String(lastSeq)}, ${timingMode} timing)`, + ); + this.name = 'WebmReplayStallError'; + this.stallWindowMs = stallWindowMs; + this.lastSeq = lastSeq; + this.timingMode = timingMode; + } +} + export interface WebmExportOptions { sessionId: string; sessionDir: string; @@ -69,7 +108,7 @@ export interface WebmExportDeps { profile: RenderProfileConfig, videoOptions: VideoRecordingOptions, ) => VideoCapableRendererBackend; - replayTimeoutMs?: number; + stallWindowMs?: number; } export interface WebmExportResult extends RecordedGlyphFields { @@ -106,27 +145,66 @@ function parseTimestamp(timestamp: string, label: string): number { return parsedTimestamp; } -async function replayWithTimeout( +// Fails the replay when the renderer makes no progress for `stallWindowMs`. +// The replay reports progress (see ReplayProgress) and each report restarts the +// window. A wait on the timing schedule is not a stall, so the window starts +// after that wait. A timer runs at most MAX_TIMER_DELAY_MS, so a longer span +// is a chain of timers. +async function replayWithStallWatchdog( backend: VideoCapableRendererBackend, replayInput: ReturnType, timingOptions: ReplayTimingOptions, - timeoutMs: number, + stallWindowMs: number, ): Promise { - let timeoutHandle: ReturnType | undefined; + let timer: ReturnType | undefined; + let lastSeq = -1; + let done = false; + let rejectStall: (error: WebmReplayStallError) => void = () => undefined; + const stalled = new Promise((_, reject) => { + rejectStall = reject; + }); + const arm = (remainingMs: number): void => { + const delayMs = Math.min(remainingMs, MAX_TIMER_DELAY_MS); + timer = setTimeout(() => { + if (remainingMs > delayMs) { + arm(remainingMs - delayMs); + return; + } + done = true; + rejectStall( + new WebmReplayStallError(stallWindowMs, lastSeq, timingOptions.mode), + ); + }, delayMs); + }; + const onProgress = (progress: ReplayProgress): void => { + // A replay that outlives its failure must not start a timer again. + if (done) { + return; + } + invariant( + Number.isInteger(progress.seq) && progress.seq >= -1, + 'replay progress seq must be an integer of at least -1', + ); + invariant( + Number.isFinite(progress.scheduledWaitMs) && + progress.scheduledWaitMs >= 0, + 'replay progress scheduledWaitMs must be a non-negative number', + ); + clearTimeout(timer); + lastSeq = progress.seq; + arm(progress.scheduledWaitMs + stallWindowMs); + }; + + arm(stallWindowMs); try { return await Promise.race([ - backend.replayWithTiming(replayInput, timingOptions), - new Promise((_, reject) => { - timeoutHandle = setTimeout(() => { - reject(new Error('WebM replay timed out after 5 minutes')); - }, timeoutMs); - }), + backend.replayWithTiming(replayInput, timingOptions, onProgress), + stalled, ]); } finally { - if (timeoutHandle !== undefined) { - clearTimeout(timeoutHandle); - } + done = true; + clearTimeout(timer); } } @@ -187,11 +265,11 @@ export async function generateWebmExport( requestedRendererName === 'libghostty-vt' ? 'ghostty-web' : requestedRendererName; - const replayTimeoutMs = deps?.replayTimeoutMs ?? REPLAY_TIMEOUT_MS; + const stallWindowMs = deps?.stallWindowMs ?? REPLAY_STALL_WINDOW_MS; invariant( - replayTimeoutMs > 0, - 'replayTimeoutMs must be a positive number when provided', + Number.isFinite(stallWindowMs) && stallWindowMs > 0, + 'stallWindowMs must be a positive number when provided', ); backend = backendFactory( videoRendererName, @@ -202,11 +280,11 @@ export async function generateWebmExport( await backend.boot(); - const replayState = await replayWithTimeout( + const replayState = await replayWithStallWatchdog( backend, replayInput, timingOptions, - replayTimeoutMs, + stallWindowMs, ); const missingGlyphs = await backend.recordedMissingGlyphs(); await backend.finalizeVideo(options.outputPath); diff --git a/src/renderer/README.md b/src/renderer/README.md index 5e6a9279..e1b57d3e 100644 --- a/src/renderer/README.md +++ b/src/renderer/README.md @@ -10,7 +10,7 @@ This directory defines the renderer abstraction that turns replayed session even - [./libghosttyVt/README.md](./libghosttyVt/README.md): `LibghosttyVtBackend`, a native semantic renderer from `@coder/libghostty-vt-node`. Its screenshots go through a `ghostty-web` fallback. - `RendererBackend`: `boot`, `replayTo`, `snapshot`, `screenshot`, `getVisibleText`, `dispose`, `rendererBackend` and `isBooted` [backend.ts:RendererBackend]. Option types `SnapshotOptions`, `ScreenshotOptions` and `VideoRecordingOptions` [backend.ts:VideoRecordingOptions]. `ScreenshotOptions.onReplayProgress` is called when a backend that replays the log inside `screenshot()` has booted its second renderer or finished a slice of that replay [backend.ts:ScreenshotOptions]. - `MouseEncodingBackend` adds `encodeMouse(input)`, which encodes one `MouseEncodingInput` with the mouse modes the child set and returns the bytes, empty when tracking suppresses the event. `supportsMouseEncoding(backend)` narrows a `RendererBackend` to it. Only `LibghosttyVtBackend` implements it [backend.ts:MouseEncodingBackend] [backend.ts:supportsMouseEncoding]. -- `VideoCapableRendererBackend` adds `replayWithTiming(input, timing)`, `finalizeVideo(outputPath)` and `recordedMissingGlyphs()`, which resolves to the `RecordedGlyphFields` of the replay and never rejects [backend.ts:VideoCapableRendererBackend]. `ReplayTimingOptions` is the union of the exported interfaces `AcceleratedTimingOptions`, `RecordedTimingOptions` and `MaxSpeedTimingOptions` (modes `accelerated`, `recorded` and `max-speed`) [backend.ts:ReplayTimingOptions]. +- `VideoCapableRendererBackend` adds `replayWithTiming(input, timing, onProgress?)`, `finalizeVideo(outputPath)` and `recordedMissingGlyphs()`, which resolves to the `RecordedGlyphFields` of the replay and never rejects [backend.ts:VideoCapableRendererBackend]. `onProgress` receives a `ReplayProgress`: the last `seq` that the replay reached, and the `scheduledWaitMs` that the replay waits right after the report [backend.ts:ReplayProgress]. `ReplayTimingOptions` is the union of the exported interfaces `AcceleratedTimingOptions`, `RecordedTimingOptions` and `MaxSpeedTimingOptions` (modes `accelerated`, `recorded` and `max-speed`) [backend.ts:ReplayTimingOptions]. - Schemas and inferred types: `ReplayEventSchema` (11 event types, discriminated on `type`), `ReplayInputSchema`, `ReplayStateSchema`, `SemanticSnapshotSchema`, `TextSnapshotSchema`, `ScreenshotResultSchema`, `RenderProfileBundledFontSchema` and `RenderProfileConfigSchema` [types.ts:ReplayEventSchema]. `types.ts` re-exports `VisibleLineSchema` from `src/protocol/schemas.ts`. - `RendererNameSchema` (`'ghostty-web'`, `'libghostty-vt'`), `resolveRendererName`, and the defaults `DEFAULT_RENDERER_NAME`, `DEFAULT_SEMANTIC_RENDERER_NAME` and `DEFAULT_VISUAL_RENDERER_NAME` [names.ts:RendererNameSchema]. - `createRendererBackend(rendererName, sessionId, profile, options?)` returns a backend instance. `RendererRegistryOptions` can override the `libghostty-vt` loader [registry.ts:createRendererBackend]. diff --git a/src/renderer/backend.ts b/src/renderer/backend.ts index 8513b8e7..ceab162f 100644 --- a/src/renderer/backend.ts +++ b/src/renderer/backend.ts @@ -109,11 +109,29 @@ export type ReplayTimingOptions = | RecordedTimingOptions | MaxSpeedTimingOptions; +/** One report that a timed replay makes to its caller. */ +export interface ReplayProgress { + /** Seq of the last event that the replay reached, or -1 before the first. */ + seq: number; + /** + * How long the replay waits on its timing schedule right after this report. + * A caller that watches for stalls must not count that wait. + */ + scheduledWaitMs: number; +} + export interface VideoCapableRendererBackend extends RendererBackend { - /** Replay events with controlled timing for video capture. */ + /** + * Replay events with controlled timing for video capture. `onProgress` + * runs before each wait on the timing schedule (and between the timers of a + * long wait), after each batch of output that the replay writes to the + * renderer, after the renderer resizes for a resize event and once the replay + * has reached its last event. + */ replayWithTiming( input: ReplayInput, timing: ReplayTimingOptions, + onProgress?: (progress: ReplayProgress) => void, ): Promise; /** Finalize and save the video recording to the given path. */ diff --git a/src/renderer/ghosttyWeb/README.md b/src/renderer/ghosttyWeb/README.md index 668a2464..d3880f4c 100644 --- a/src/renderer/ghosttyWeb/README.md +++ b/src/renderer/ghosttyWeb/README.md @@ -8,7 +8,7 @@ This directory holds the `ghostty-web` reference renderer. `GhosttyWebBackend` s - `GhosttyWebBackend` [backend.ts:GhosttyWebBackend]: implements `VideoCapableRendererBackend` from `src/renderer/backend.ts`. Its `rendererBackend` is `'ghostty-web'`. It is re-exported by [index.ts:GhosttyWebBackend]. - `constructor(sessionId, profile, videoOptions?, logger?)` [backend.ts:GhosttyWebBackend.constructor]. - - `boot()`, `replayTo(input)` and `replayWithTiming(input, timing)` [backend.ts:GhosttyWebBackend.replayWithTiming]. Timing modes are `accelerated`, `recorded` and `max-speed`. + - `boot()`, `replayTo(input)` and `replayWithTiming(input, timing, onProgress?)` [backend.ts:GhosttyWebBackend.replayWithTiming]. Timing modes are `accelerated`, `recorded` and `max-speed`. - `snapshot(options?)` returns a `SemanticSnapshot` [backend.ts:GhosttyWebBackend.snapshot]. - `screenshot(outputPath, options?)` returns a `ScreenshotResult` with `sha256`, `renderProfileHash` and `missingGlyphs` [backend.ts:GhosttyWebBackend.screenshot]. - `recordedMissingGlyphs()` returns the boxed code points of every frame that `replayWithTiming()` painted [backend.ts:GhosttyWebBackend.recordedMissingGlyphs]. @@ -30,6 +30,7 @@ This directory holds the `ghostty-web` reference renderer. `GhosttyWebBackend` s - The constructor asserts a non-empty `sessionId`, `profile.name` and `profile.fontFamily`, a positive `fontSize`, and hex colors. With `videoOptions`, `outputDir` must be absolute and the size must use positive integers [backend.ts:GhosttyWebBackend.constructor]. - Replay cannot rewind: `targetSeq` must be >= the last applied seq. The initial dimensions cannot change after the first replay. `input.sessionId` must match the backend [backend.ts:GhosttyWebBackend.replayTo]. - `replayWithTiming` asserts strictly increasing seqs and non-decreasing timestamps [backend.ts:GhosttyWebBackend.replayWithTiming]. +- `replayWithTiming` calls the optional `onProgress` with a `ReplayProgress` in four places. Before each wait on the schedule, `scheduledWaitMs` is the length of that wait. A wait longer than a timer runs (2^31-1 ms) is a chain of timers, so a recorded gap of 30 days takes 30 days, and a report that carries the rest of the wait follows each timer except the last. After each bridge call of a flush, and after the resize call of a resize event, `scheduledWaitMs` is 0. After the last event and its flush, and before the final calls to the renderer, `scheduledWaitMs` is 0 too, so a stall in those calls names the last event, also when that event changed no pixel. `seq` is the last event that the replay had reached. `generateWebmExport` uses these reports to tell a stall from a wait [backend.ts:GhosttyWebBackend.replayWithTiming]. - `replayWithTiming` waits until each event's place on a schedule built from the recorded gaps: `recorded` keeps them, `accelerated` caps each at `maxGapMs`, and `max-speed` sets them to 0. It measures that schedule with `performance.now()`, so frame holds and bridge calls use up idle time instead of adding to it. In `recorded` and `accelerated` mode it flushes pending output once the next event is at least one frame hold after the batch's first output, unless the replay runs behind the schedule, in which case the batch grows until it catches up. `max-speed` has no schedule to fall behind, so only recorded time ends its flushes. A flush ends at the first event that is at least one frame hold of recorded time after the batch's first output. An event that changes no pixel does not end it: input, marker, run-complete, signal and exit events leave the batch as it is, because a flush at each of them would cost a frame per event. A resize and the end of the replay still end it. `max-speed` also spreads at most `MAX_SPEED_FRAME_BUDGET` (2,400) flushes over the recorded span of the events that it applies: the distance between the first output of a flush and the event that ends it is at least the larger of the frame hold and the span divided by 2,400. So a `max-speed` replay makes about one flush per frame hold of recorded time for a recording shorter than 38 s and at most about 2,400 flushes for a longer one, whatever its number of events. Output that arrives less than that distance after the first output of a flush shares the flush, also when an input or a marker sits between, so a state that the next output of the flush replaces is never painted. A flush waits for one animation frame. `max-speed` holds the frame hold only after the last flush of the replay and before and after a resize, so two flushes that follow each other can paint within one video frame. In `recorded` and `accelerated` mode, every event that changes no pixel ends a flush, and a hold follows every flush. Events with the same timestamp share a flush at any hold, 0 included, because a flush needs at least 1 ms of recorded time [backend.ts:GhosttyWebBackend.replayWithTiming]. - `writeBatch(chunks, endsFlush, paintedCap)` takes the chunks of one bridge call. A flush that has more than 1000 chunks needs several calls, and ghostty-web paints on every animation frame, so the page holds the chunks of a call that does not end the flush. The call that ends it (`endsFlush`, set by the backend on the last call only) writes every held chunk in one task, so no frame paints a state between two calls, and then resolves after one frame. ghostty-web calls a write callback one animation frame (about 17 ms) after the write, and waiting on every chunk (`write`) cost one frame per output event. `write()` and `resize()` throw while chunks are held. `discardHeldChunks()` drops them: the backend calls it when a flush fails, because `HostRendererManager` keeps the backend and a retry would otherwise meet them. A `paintedCap` that is not null makes the call that ends the flush add the graphemes on the screen to the set that the missing-glyph check of `replayWithTiming` probes, so a flush is one page call. The call returns the message of a failed note and not an error, because a failed note must not fail the flush. In `replayWithTiming`, the chunks of one flush share one video frame [embeddedHarnessHtml.ts:EMBEDDED_HARNESS_HTML]. - `snapshot()` and `screenshot()` throw until `replayTo()` or `replayWithTiming()` has run once and set the initial size. Both replays accept `targetSeq` -1 for an empty Event Log. A replay over zero events sets `lastAppliedSeq` to `targetSeq` [backend.ts:GhosttyWebBackend.snapshot]. diff --git a/src/renderer/ghosttyWeb/backend.ts b/src/renderer/ghosttyWeb/backend.ts index ba36bddc..589dc740 100644 --- a/src/renderer/ghosttyWeb/backend.ts +++ b/src/renderer/ghosttyWeb/backend.ts @@ -30,6 +30,7 @@ import { } from '../../util/resourceScope.js'; import type { RecordedGlyphFields, + ReplayProgress, ReplayTimingOptions, ScreenshotOptions, SnapshotOptions, @@ -138,13 +139,16 @@ const HTML_CONTENT_TYPE = 'text/html; charset=utf-8'; const WASM_CONTENT_TYPE = 'application/wasm'; const MAX_REPLAY_BATCH_SIZE = 1000; +// Node runs a timer with a longer delay after 1 ms, so a longer wait is a chain +// of timers. +const MAX_TIMER_DELAY_MS = 2 ** 31 - 1; /** * A max-speed replay makes at most about this many flushes, however long the * recording is. A flush costs one animation frame, one page call and one scan * of the screen: 26 ms at 80x24, 33 ms at 120x40 and 112 ms at 200x60 in the * median of five sparse-log runs (host load 40 to 100). The limit then takes - * 1 to 4.5 minutes, under the 5 minutes that a WebM export allows its replay. - * The video has 25 frames per second, so this many flushes fill 96 s of video. + * 1 to 4.5 minutes. The video has 25 frames per second, so this many flushes + * fill 96 s of video. */ const MAX_SPEED_FRAME_BUDGET = 2_400; const RAF_TIMEOUT_MS = 5_000; @@ -555,9 +559,10 @@ export class GhosttyWebBackend implements VideoCapableRendererBackend { public async replayWithTiming( input: ReplayInput, timing: ReplayTimingOptions, + onProgress?: (progress: ReplayProgress) => void, ): Promise { try { - return await this.replayWithTimingInner(input, timing); + return await this.replayWithTimingInner(input, timing, onProgress); } catch (error) { throw describeReplayFailure(error); } @@ -566,6 +571,7 @@ export class GhosttyWebBackend implements VideoCapableRendererBackend { private async replayWithTimingInner( input: ReplayInput, timing: ReplayTimingOptions, + onProgress?: (progress: ReplayProgress) => void, ): Promise { const page = this.requireOperationalPage('replayWithTiming()'); @@ -662,18 +668,29 @@ export class GhosttyWebBackend implements VideoCapableRendererBackend { } }; - const waitForDelay = async (delayMs: number): Promise => { + // A wait longer than a timer runs is a chain of timers, so a recorded gap of + // 30 days takes 30 days. `onRemaining` runs between two timers with the rest + // of the wait. + const waitForDelay = async ( + delayMs: number, + onRemaining?: (remainingMs: number) => void, + ): Promise => { assertNonNegativeInteger( delayMs, 'replayWithTiming delayMs must be a non-negative integer', ); - if (delayMs === 0) { - return; - } - await new Promise((resolvePromise) => { - setTimeout(resolvePromise, delayMs); - }); + let remainingMs = delayMs; + while (remainingMs > 0) { + const stepMs = Math.min(remainingMs, MAX_TIMER_DELAY_MS); + await new Promise((resolvePromise) => { + setTimeout(resolvePromise, stepMs); + }); + remainingMs -= stepMs; + if (remainingMs > 0) { + onRemaining?.(remainingMs); + } + } }; const parseEventTimestampMs = ( eventTs: string, @@ -734,7 +751,15 @@ export class GhosttyWebBackend implements VideoCapableRendererBackend { return; } - await this.flushOutputBatch(page, pendingOutputChunks, undefined, true); + await this.flushOutputBatch( + page, + pendingOutputChunks, + () => { + onProgress?.({ seq: highestProcessedSeq, scheduledWaitMs: 0 }); + return Promise.resolve(); + }, + true, + ); pendingOutputChunks = []; pendingSinceTimestampMs = null; if (holdFrame) { @@ -803,14 +828,19 @@ export class GhosttyWebBackend implements VideoCapableRendererBackend { } // Waiting for the event's place on the schedule lets frame holds and // bridge calls use up time that the recording spent idle. - await waitForDelay( - Math.max( - 0, - Math.round( - scheduledElapsedMs - (performance.now() - scheduleStartedAtMs), - ), + const scheduledWaitMs = Math.max( + 0, + Math.round( + scheduledElapsedMs - (performance.now() - scheduleStartedAtMs), ), ); + onProgress?.({ seq: highestProcessedSeq, scheduledWaitMs }); + await waitForDelay(scheduledWaitMs, (remainingMs) => { + onProgress?.({ + seq: highestProcessedSeq, + scheduledWaitMs: remainingMs, + }); + }); } previousProcessedEventTimestampMs = eventTimestampMs; @@ -835,6 +865,9 @@ export class GhosttyWebBackend implements VideoCapableRendererBackend { this.currentCols = event.payload.cols; this.currentRows = event.payload.rows; resizeEventCount += 1; + // The resize and the note that follows are two page calls. A + // report between them keeps each call a stretch of its own. + onProgress?.({ seq: event.seq, scheduledWaitMs: 0 }); await this.notePaintedGraphemes(page); await waitForDelay(resolvedMinFrameHoldMs); break; @@ -864,6 +897,10 @@ export class GhosttyWebBackend implements VideoCapableRendererBackend { } await flushOutputBatch(); + // The last event can change no pixel, so no flush has reported it. The final + // calls to the renderer follow, and a stall in one of them is a stall after + // this event. + onProgress?.({ seq: highestProcessedSeq, scheduledWaitMs: 0 }); invariant( outputEventCount + resizeEventCount <= processedEventCount, @@ -1754,7 +1791,7 @@ export class GhosttyWebBackend implements VideoCapableRendererBackend { /** * Writes the chunks of one flush into the page. With `notePainted`, the page * also notes the graphemes on the screen once the flush is written, in the - * call that ends the flush. + * call that ends the flush. `afterEachBatch` runs after each page call. */ private async flushOutputBatch( page: Page, diff --git a/test/unit/commands/record-export.test.ts b/test/unit/commands/record-export.test.ts index 779703e9..0d366c00 100644 --- a/test/unit/commands/record-export.test.ts +++ b/test/unit/commands/record-export.test.ts @@ -14,11 +14,13 @@ import process from 'node:process'; import type * as FsPromises from 'node:fs/promises'; +import type * as WebmModule from '../../../src/export/webm.js'; import type * as EventLogCodecModule from '../../../src/storage/eventLogCodec.js'; import type * as HomeModule from '../../../src/storage/home.js'; import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; +import { WebmReplayStallError } from '../../../src/export/webm.js'; import { ERROR_CODES, makeCliError } from '../../../src/protocol/errors.js'; import { EventLogTooLargeError } from '../../../src/storage/eventLogCodec.js'; @@ -89,7 +91,8 @@ vi.mock('../../../src/util/packageMetadata.js', () => ({ loadPackageMetadata: mocks.loadPackageMetadata, })); -vi.mock('../../../src/export/webm.js', () => ({ +vi.mock('../../../src/export/webm.js', async (importOriginal) => ({ + ...(await importOriginal()), generateWebmExport: mocks.generateWebmExport, })); @@ -1659,6 +1662,98 @@ describe('record export command', () => { }, ); + it.each([ + { + lastSeq: 1_234, + timingMode: 'recorded', + position: 'after event 1234', + }, + { + lastSeq: 0, + timingMode: 'accelerated', + position: 'after event 0', + }, + { + lastSeq: -1, + timingMode: 'max-speed', + position: 'at the start of the replay', + }, + ] as const)( + 'names the stall window and the last event when the WebM replay stalls ($position)', + async ({ lastSeq, timingMode, position }) => { + mocks.recordingFilename.mockReturnValue('recording-1-webm.webm'); + mocks.generateWebmExport.mockRejectedValue( + new WebmReplayStallError(300_000, lastSeq, timingMode), + ); + + await expect( + runRecordExportCommand({ + context: TEST_CONTEXT, + json: true, + sessionId: 'session-01', + format: 'webm', + }), + ).rejects.toMatchObject({ + code: ERROR_CODES.EXPORT_ERROR, + message: `Failed to export session "session-01" as webm: the renderer made no progress for 300 s ${position} (${timingMode} timing).`, + details: { + sessionId: 'session-01', + format: 'webm', + stallWindowMs: 300_000, + lastSeq, + timingMode, + }, + }); + expect(mocks.generateWebmExport).toHaveBeenCalledTimes(1); + expect(mocks.emitSuccess).not.toHaveBeenCalled(); + }, + ); + + it('keeps the requested output path and the stall error in the error of a stalled WebM replay', async () => { + const outputDirectory = await createTemporaryDirectory( + 'agent-tty-record-export-stall-', + ); + const out = join(outputDirectory, 'stalled.webm'); + const stall = new WebmReplayStallError(300_000, 12, 'recorded'); + mocks.recordingFilename.mockReturnValue('recording-1-webm.webm'); + mocks.generateWebmExport.mockRejectedValue(stall); + + const failure: unknown = await runRecordExportCommand({ + context: TEST_CONTEXT, + json: true, + sessionId: 'session-01', + format: 'webm', + out, + }).then( + () => undefined, + (error: unknown) => error, + ); + + expect(failure).toMatchObject({ + code: ERROR_CODES.EXPORT_ERROR, + details: { out }, + }); + expect((failure as { cause?: unknown }).cause).toBe(stall); + }); + + it('keeps the generic message for other WebM export failures', async () => { + mocks.recordingFilename.mockReturnValue('recording-1-webm.webm'); + mocks.generateWebmExport.mockRejectedValue(new Error('replay failed')); + + await expect( + runRecordExportCommand({ + context: TEST_CONTEXT, + json: true, + sessionId: 'session-01', + format: 'webm', + }), + ).rejects.toMatchObject({ + code: ERROR_CODES.EXPORT_ERROR, + message: 'Failed to export session "session-01" as webm.', + }); + expect(mocks.generateWebmExport).toHaveBeenCalledTimes(1); + }); + it('keeps the generic message for other event log read failures', async () => { mocks.readEventLogRecords.mockRejectedValue(new Error('EIO')); diff --git a/test/unit/export/webm.test.ts b/test/unit/export/webm.test.ts index fb2e3a85..48c099e4 100644 --- a/test/unit/export/webm.test.ts +++ b/test/unit/export/webm.test.ts @@ -1,6 +1,7 @@ -import { beforeEach, describe, expect, it, vi } from 'vitest'; +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; import type { + ReplayProgress, VideoCapableRendererBackend, VideoRecordingOptions, } from '../../../src/renderer/backend.js'; @@ -23,7 +24,11 @@ vi.mock('../../../src/renderer/profiles.js', () => ({ resolveProfile: mocks.resolveProfile, })); -import { generateWebmExport } from '../../../src/export/webm.js'; +import { + generateWebmExport, + WebmReplayStallError, +} from '../../../src/export/webm.js'; +import { GhosttyWebBackend } from '../../../src/renderer/ghosttyWeb/index.js'; function createManifest(overrides: Partial = {}): SessionRecord { return { @@ -256,6 +261,7 @@ describe('generateWebmExport', () => { mode: 'recorded', finalFrameHoldMs: 1_000, }, + expect.any(Function), ); expect(mockBackend.finalizeVideo).toHaveBeenCalledWith( '/tmp/exports/recording-1-webm.webm', @@ -378,6 +384,7 @@ describe('generateWebmExport', () => { minFrameHoldMs: 100, finalFrameHoldMs: 1_000, }, + expect.any(Function), ); expect(result.timingMode).toBe('accelerated'); }); @@ -400,6 +407,7 @@ describe('generateWebmExport', () => { expect(mockBackend.replayWithTiming).toHaveBeenCalledWith( expect.objectContaining({ sessionId: 'session-01' }), { mode: 'max-speed', minFrameHoldMs: 16, finalFrameHoldMs: 500 }, + expect.any(Function), ); expect(result.timingMode).toBe('max-speed'); }); @@ -421,6 +429,7 @@ describe('generateWebmExport', () => { expect(mockBackend.replayWithTiming).toHaveBeenCalledWith( expect.objectContaining({ sessionId: 'session-01' }), { mode: 'recorded', finalFrameHoldMs: 1_000 }, + expect.any(Function), ); expect(result.timingMode).toBe('recorded'); }); @@ -450,6 +459,7 @@ describe('generateWebmExport', () => { expect(mockBackend.replayWithTiming).toHaveBeenCalledWith( emptyInput, expect.anything(), + expect.any(Function), ); expect(result).toMatchObject({ capturedAtSeq: -1, @@ -493,7 +503,7 @@ describe('generateWebmExport', () => { expect(mockBackend.dispose).toHaveBeenCalledTimes(1); }); - it('times out replay and still disposes the backend', async () => { + it('stops a replay that makes no progress and still disposes the backend', async () => { const replayWithTiming = vi.fn( (): Promise> => new Promise(() => undefined), @@ -511,15 +521,43 @@ describe('generateWebmExport', () => { }, { backendFactory: () => mockBackend.backend, - replayTimeoutMs: 1, + stallWindowMs: 1, }, ), - ).rejects.toThrow('WebM replay timed out after 5 minutes'); + ).rejects.toThrow( + 'WebM replay stalled: the renderer made no progress for 1 ms (last event seq -1, recorded timing)', + ); expect(mockBackend.finalizeVideo).not.toHaveBeenCalled(); expect(mockBackend.dispose).toHaveBeenCalledTimes(1); }); + it.each([0, -1, Number.NaN, Number.POSITIVE_INFINITY])( + 'refuses a stall window of %s before it creates a backend', + async (stallWindowMs) => { + const mockBackend = createMockBackend(); + const backendFactory = vi.fn(() => mockBackend.backend); + + await expect( + generateWebmExport( + { + sessionId: 'session-01', + sessionDir: '/tmp/agent-tty/sessions/session-01', + manifest: createManifest(), + events: createEvents(), + outputPath: '/tmp/exports/recording-1-webm.webm', + }, + { backendFactory, stallWindowMs }, + ), + ).rejects.toThrow( + 'stallWindowMs must be a positive number when provided', + ); + + expect(backendFactory).not.toHaveBeenCalled(); + expect(mockBackend.replayWithTiming).not.toHaveBeenCalled(); + }, + ); + it('disposes the backend when finalizeVideo throws', async () => { const finalizeError = new Error('finalize failed'); const finalizeVideo = vi.fn().mockRejectedValue(finalizeError); @@ -544,3 +582,657 @@ describe('generateWebmExport', () => { expect(mockBackend.dispose).toHaveBeenCalledTimes(1); }); }); + +describe('generateWebmExport stall watchdog', () => { + const WINDOW_MS = 5 * 60 * 1000; + const DAY_MS = 24 * 60 * 60 * 1000; + const MAX_TIMER_DELAY_MS = 2 ** 31 - 1; + + type ReplayScript = ( + onProgress: (progress: ReplayProgress) => void, + ) => Promise>; + + function sleep(ms: number): Promise { + return new Promise((resolve) => { + setTimeout(resolve, ms); + }); + } + + // Starts an export whose replay is `script`, on fake timers. The script + // acts as the renderer: it reports progress and takes fake time. + async function startExport( + script: ReplayScript, + timingMode: 'recorded' | 'accelerated' | 'max-speed' = 'recorded', + stallWindowMs?: number, + ) { + let markReplayStarted: () => void = () => undefined; + const replayStarted = new Promise((resolve) => { + markReplayStarted = resolve; + }); + const replayWithTiming = vi.fn( + ( + _input: unknown, + _timing: unknown, + onProgress?: (progress: ReplayProgress) => void, + ) => { + markReplayStarted(); + return script(onProgress ?? (() => undefined)); + }, + ); + const mockBackend = createMockBackend({ replayWithTiming }); + const outcome = generateWebmExport( + { + sessionId: 'session-01', + sessionDir: '/tmp/agent-tty/sessions/session-01', + manifest: createManifest(), + events: [], + outputPath: '/tmp/exports/recording-1-webm.webm', + timingMode, + }, + { + backendFactory: () => mockBackend.backend, + ...(stallWindowMs === undefined ? {} : { stallWindowMs }), + }, + ).then( + (result) => ({ result, error: undefined }), + (error: unknown) => ({ result: undefined, error }), + ); + await replayStarted; + + return { outcome, mockBackend }; + } + + beforeEach(() => { + vi.clearAllMocks(); + vi.useFakeTimers(); + mocks.resolveProfile.mockReturnValue({ + name: 'reference-dark', + theme: 'dark', + fontFamily: 'monospace', + fontSize: 16, + cursorStyle: 'block', + backgroundColor: '#000000', + foregroundColor: '#ffffff', + }); + mocks.buildReplayInput.mockReturnValue({ + sessionId: 'session-01', + initialCols: 80, + initialRows: 24, + events: createEvents(), + targetSeq: 1, + }); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + it('keeps a replay going while it reports progress for longer than the window', async () => { + const { outcome, mockBackend } = await startExport(async (onProgress) => { + for (let seq = 0; seq < 5; seq += 1) { + await sleep(WINDOW_MS - 60_000); + onProgress({ seq, scheduledWaitMs: 0 }); + } + return createReplayState(); + }); + + await vi.advanceTimersByTimeAsync(5 * (WINDOW_MS - 60_000)); + const { error } = await outcome; + + expect(error).toBeUndefined(); + expect(mockBackend.finalizeVideo).toHaveBeenCalledTimes(1); + }); + + it('does not count a multi-day wait on the timing schedule as a stall', async () => { + const { outcome, mockBackend } = await startExport(async (onProgress) => { + onProgress({ seq: 0, scheduledWaitMs: 20 * DAY_MS }); + await sleep(20 * DAY_MS); + onProgress({ seq: 1, scheduledWaitMs: 0 }); + return createReplayState(); + }); + + await vi.advanceTimersByTimeAsync(20 * DAY_MS); + const { error } = await outcome; + + expect(error).toBeUndefined(); + expect(mockBackend.finalizeVideo).toHaveBeenCalledTimes(1); + }); + + it('keeps going through several waits that together pass the longest timer', async () => { + const { outcome, mockBackend } = await startExport(async (onProgress) => { + for (let seq = 0; seq < 3; seq += 1) { + onProgress({ seq, scheduledWaitMs: 10 * DAY_MS }); + await sleep(10 * DAY_MS); + } + return createReplayState(); + }); + + await vi.advanceTimersByTimeAsync(30 * DAY_MS); + const { error } = await outcome; + + expect(error).toBeUndefined(); + expect(mockBackend.finalizeVideo).toHaveBeenCalledTimes(1); + }); + + it('starts no timer that runs longer than a timer can, for a wait of 30 days', async () => { + const setTimeoutSpy = vi.spyOn(globalThis, 'setTimeout'); + const { outcome, mockBackend } = await startExport(async (onProgress) => { + onProgress({ seq: 0, scheduledWaitMs: 30 * DAY_MS }); + await sleep(15 * DAY_MS); + await sleep(15 * DAY_MS); + onProgress({ seq: 1, scheduledWaitMs: 0 }); + return createReplayState(); + }); + + await vi.advanceTimersByTimeAsync(30 * DAY_MS); + const { error } = await outcome; + + expect(error).toBeUndefined(); + expect(mockBackend.finalizeVideo).toHaveBeenCalledTimes(1); + const delays = setTimeoutSpy.mock.calls.map((call) => Number(call[1])); + expect(delays.length).toBeGreaterThan(0); + expect(Math.max(...delays)).toBeLessThanOrEqual(MAX_TIMER_DELAY_MS); + }); + + it.each(['recorded', 'accelerated', 'max-speed'] as const)( + 'stops a hung %s replay once the window has passed since its last progress', + async (timingMode) => { + const { outcome, mockBackend } = await startExport(async (onProgress) => { + await sleep(1_000); + onProgress({ seq: 7, scheduledWaitMs: 0 }); + return new Promise(() => undefined); + }, timingMode); + + await vi.advanceTimersByTimeAsync(1_000 + WINDOW_MS - 1); + expect(mockBackend.dispose).not.toHaveBeenCalled(); + + await vi.advanceTimersByTimeAsync(1); + const { error } = await outcome; + + expect(error).toBeInstanceOf(WebmReplayStallError); + expect(error).toMatchObject({ + stallWindowMs: WINDOW_MS, + lastSeq: 7, + timingMode, + message: `WebM replay stalled: the renderer made no progress for ${String(WINDOW_MS)} ms (last event seq 7, ${timingMode} timing)`, + }); + expect(mockBackend.finalizeVideo).not.toHaveBeenCalled(); + expect(mockBackend.dispose).toHaveBeenCalledTimes(1); + }, + ); + + it('stops a replay that reports nothing, naming no event', async () => { + const { outcome, mockBackend } = await startExport( + () => new Promise(() => undefined), + ); + + await vi.advanceTimersByTimeAsync(WINDOW_MS - 1); + expect(mockBackend.dispose).not.toHaveBeenCalled(); + + await vi.advanceTimersByTimeAsync(1); + const { error } = await outcome; + + expect(error).toBeInstanceOf(WebmReplayStallError); + expect(error).toMatchObject({ stallWindowMs: WINDOW_MS, lastSeq: -1 }); + }); + + it('starts the window after a scheduled wait, not before it', async () => { + const { outcome, mockBackend } = await startExport((onProgress) => { + onProgress({ seq: 3, scheduledWaitMs: 2 * DAY_MS }); + return new Promise(() => undefined); + }); + + await vi.advanceTimersByTimeAsync(2 * DAY_MS + WINDOW_MS - 1); + expect(mockBackend.dispose).not.toHaveBeenCalled(); + + await vi.advanceTimersByTimeAsync(1); + const { error } = await outcome; + + expect(error).toBeInstanceOf(WebmReplayStallError); + expect(error).toMatchObject({ stallWindowMs: WINDOW_MS, lastSeq: 3 }); + }); + + it('stops a replay that hangs after a scheduled wait of 30 days, which with the window is longer than a timer runs', async () => { + // The wait and the window together are 30 days and 5 minutes: more than + // the longest timer, so the stall is the end of a chain of two timers. + const { outcome, mockBackend } = await startExport((onProgress) => { + onProgress({ seq: 3, scheduledWaitMs: 30 * DAY_MS }); + return new Promise(() => undefined); + }); + + await vi.advanceTimersByTimeAsync(30 * DAY_MS + WINDOW_MS - 1); + expect(mockBackend.dispose).not.toHaveBeenCalled(); + + await vi.advanceTimersByTimeAsync(1); + expect(mockBackend.dispose).toHaveBeenCalledTimes(1); + const { error } = await outcome; + + expect(error).toBeInstanceOf(WebmReplayStallError); + expect(error).toMatchObject({ stallWindowMs: WINDOW_MS, lastSeq: 3 }); + }); + + it('stops a hung replay once a stall window that outlasts a timer has passed', async () => { + const stallWindowMs = MAX_TIMER_DELAY_MS + 5; + const { outcome, mockBackend } = await startExport( + () => new Promise(() => undefined), + 'recorded', + stallWindowMs, + ); + + await vi.advanceTimersByTimeAsync(stallWindowMs - 1); + expect(mockBackend.dispose).not.toHaveBeenCalled(); + + await vi.advanceTimersByTimeAsync(1); + expect(mockBackend.dispose).toHaveBeenCalledTimes(1); + const { error } = await outcome; + + expect(error).toBeInstanceOf(WebmReplayStallError); + expect(error).toMatchObject({ stallWindowMs, lastSeq: -1 }); + }); + + it('leaves no timer behind when the replay succeeds', async () => { + const { outcome } = await startExport((onProgress) => { + onProgress({ seq: 0, scheduledWaitMs: DAY_MS }); + return Promise.resolve(createReplayState()); + }); + + const { error } = await outcome; + + expect(error).toBeUndefined(); + expect(vi.getTimerCount()).toBe(0); + }); + + it('leaves no timer behind when the replay fails', async () => { + const replayError = new Error('replay failed'); + const { outcome } = await startExport((onProgress) => { + onProgress({ seq: 0, scheduledWaitMs: DAY_MS }); + return Promise.reject(replayError); + }); + + const { error } = await outcome; + + expect(error).toBe(replayError); + expect(vi.getTimerCount()).toBe(0); + }); + + it('starts no timer when a replay that already stalled reports again', async () => { + let reportLate: (progress: ReplayProgress) => void = () => undefined; + const { outcome } = await startExport((onProgress) => { + reportLate = onProgress; + return new Promise(() => undefined); + }); + + await vi.advanceTimersByTimeAsync(WINDOW_MS); + const { error } = await outcome; + expect(error).toBeInstanceOf(WebmReplayStallError); + + reportLate({ seq: 9, scheduledWaitMs: DAY_MS }); + + expect(vi.getTimerCount()).toBe(0); + }); + + it.each(['succeeded', 'failed'] as const)( + 'starts no timer when a replay that already %s reports again', + async (ending) => { + let reportLate: (progress: ReplayProgress) => void = () => undefined; + const { outcome } = await startExport((onProgress) => { + reportLate = onProgress; + return ending === 'succeeded' + ? Promise.resolve(createReplayState()) + : Promise.reject(new Error('replay failed')); + }); + + await outcome; + reportLate({ seq: 9, scheduledWaitMs: DAY_MS }); + + expect(vi.getTimerCount()).toBe(0); + }, + ); + + it.each([ + { seq: 0.5, scheduledWaitMs: 0, message: 'seq must be an integer' }, + { seq: -2, scheduledWaitMs: 0, message: 'seq must be an integer' }, + { seq: 0, scheduledWaitMs: -1, message: 'scheduledWaitMs must be' }, + { seq: 0, scheduledWaitMs: Number.NaN, message: 'scheduledWaitMs must be' }, + { + seq: 0, + scheduledWaitMs: Number.POSITIVE_INFINITY, + message: 'scheduledWaitMs must be', + }, + ])( + 'rejects a progress report of seq $seq and wait $scheduledWaitMs', + async ({ seq, scheduledWaitMs, message }) => { + const { outcome } = await startExport((onProgress) => { + onProgress({ seq, scheduledWaitMs }); + return Promise.resolve(createReplayState()); + }); + + const { error } = await outcome; + + expect(error).toBeInstanceOf(Error); + expect((error as Error).message).toContain(message); + expect(vi.getTimerCount()).toBe(0); + }, + ); +}); + +// These tests run the real GhosttyWebBackend replay loop with its renderer +// bridge replaced by a stub that takes fake time. They check that the loop +// reports progress where the watchdog needs it. +describe('generateWebmExport stall watchdog with the ghostty-web replay loop', () => { + const BASE_TIME_MS = Date.parse('2026-03-19T12:00:00.000Z'); + const DAY_MS = 24 * 60 * 60 * 1000; + const WINDOW_MS = 5 * 60 * 1000; + + type ReplayEvent = + | { + seq: number; + type: 'output' | 'input_text'; + ts: string; + payload: { data: string }; + } + | { + seq: number; + type: 'resize'; + ts: string; + payload: { cols: number; rows: number }; + }; + + function event( + seq: number, + offsetMs: number, + type: 'output' | 'input_text' = 'output', + ): ReplayEvent { + return { + seq, + type, + ts: new Date(BASE_TIME_MS + offsetMs).toISOString(), + payload: { data: `e${String(seq)}` }, + }; + } + + function resizeEvent(seq: number, offsetMs: number): ReplayEvent { + return { + seq, + type: 'resize', + ts: new Date(BASE_TIME_MS + offsetMs).toISOString(), + payload: { cols: 100 + seq, rows: 30 }, + }; + } + + // Exports `events` with the real replay loop. Each output bridge call takes + // `bridgeCostMs` of fake time, each resize call `resizeCostMs` and each note + // of the painted graphemes after a resize `noteCostMs`. Returns how long the + // replay took in fake time, or the error that stopped it. + async function exportWithRealReplayLoop( + events: ReplayEvent[], + timingMode: 'recorded' | 'accelerated' | 'max-speed', + bridgeCostMs: number, + runForMs: number, + { + resizeCostMs = 0, + noteCostMs = 0, + hangingCall, + }: { + resizeCostMs?: number; + noteCostMs?: number; + hangingCall?: 'checkPaintedGlyphs' | 'readHarnessSnapshot'; + } = {}, + ): Promise<{ replayMs: number | undefined; error: unknown }> { + mocks.buildReplayInput.mockReturnValue({ + sessionId: 'session-01', + initialCols: 80, + initialRows: 24, + events, + targetSeq: events.length - 1, + }); + let markReplayStarted: () => void = () => undefined; + const replayStarted = new Promise((resolve) => { + markReplayStarted = resolve; + }); + let finalizedAtMs: number | undefined; + let startedAtMs = 0; + let resizeCalls = 0; + const outcome = generateWebmExport( + { + sessionId: 'session-01', + sessionDir: '/tmp/agent-tty/sessions/session-01', + manifest: createManifest(), + events: [], + outputPath: '/tmp/exports/recording-1-webm.webm', + timingMode, + }, + { + backendFactory: (_rendererName, sessionId, profile, videoOptions) => { + const backend = new GhosttyWebBackend( + sessionId, + profile, + videoOptions, + ); + Object.assign(backend as object, { + boot: () => Promise.resolve(), + isBooted: true, + page: { isClosed: () => false }, + resizeBridge: () => { + resizeCalls += 1; + if (resizeCalls === 1) { + // The first call sizes the terminal before the replay starts. + startedAtMs = Date.now(); + markReplayStarted(); + return Promise.resolve(); + } + return new Promise((resolve) => { + setTimeout(resolve, resizeCostMs); + }); + }, + writeBatchBridge: () => + new Promise((resolve) => { + setTimeout(resolve, bridgeCostMs); + }), + notePaintedGraphemes: () => + new Promise((resolve) => { + setTimeout(resolve, noteCostMs); + }), + checkPaintedGlyphs: () => + hangingCall === 'checkPaintedGlyphs' + ? new Promise(() => undefined) + : Promise.resolve({}), + readHarnessSnapshot: () => + hangingCall === 'readHarnessSnapshot' + ? new Promise(() => undefined) + : Promise.resolve({ + cols: 80, + rows: 24, + cursorRow: 0, + cursorCol: 0, + isAltScreen: false, + visibleLines: [], + }), + recordedMissingGlyphs: () => Promise.resolve({}), + finalizeVideo: () => { + finalizedAtMs = Date.now(); + return Promise.resolve(); + }, + dispose: () => Promise.resolve(), + }); + return backend; + }, + }, + ).then( + () => undefined, + (error: unknown) => error, + ); + + await replayStarted; + await vi.advanceTimersByTimeAsync(runForMs); + const error = await outcome; + + return { + replayMs: + finalizedAtMs === undefined ? undefined : finalizedAtMs - startedAtMs, + error, + }; + } + + beforeEach(() => { + vi.clearAllMocks(); + vi.useFakeTimers(); + mocks.resolveProfile.mockReturnValue({ + name: 'reference-dark', + theme: 'dark', + fontFamily: 'monospace', + fontSize: 16, + cursorStyle: 'block', + backgroundColor: '#000000', + foregroundColor: '#ffffff', + }); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + it.each([ + { label: '6 minutes', gapMs: 6 * 60 * 1000 }, + { label: '20 days', gapMs: 20 * DAY_MS }, + ])( + 'exports a recording with a gap of $label at recorded timing', + async ({ gapMs }) => { + const { replayMs, error } = await exportWithRealReplayLoop( + [event(0, 0), event(1, gapMs)], + 'recorded', + 0, + gapMs + 60_000, + ); + + expect(error).toBeUndefined(); + expect(replayMs).toBeGreaterThan(gapMs); + }, + ); + + it('waits a recorded gap of 30 days in full, with no timer longer than a timer can run', async () => { + const gapMs = 30 * DAY_MS; + const setTimeoutSpy = vi.spyOn(globalThis, 'setTimeout'); + try { + const { replayMs, error } = await exportWithRealReplayLoop( + [event(0, 0), event(1, gapMs)], + 'recorded', + 0, + gapMs + 60_000, + ); + + expect(error).toBeUndefined(); + expect(replayMs).toBeGreaterThanOrEqual(gapMs); + const delays = setTimeoutSpy.mock.calls.map((call) => Number(call[1])); + expect(Math.max(...delays)).toBeLessThanOrEqual(2 ** 31 - 1); + } finally { + setTimeoutSpy.mockRestore(); + } + }); + + it.each([ + { calls: 'checkPaintedGlyphs', eventCount: 1, lastSeq: 0 }, + { calls: 'readHarnessSnapshot', eventCount: 1, lastSeq: 0 }, + { calls: 'checkPaintedGlyphs', eventCount: 3, lastSeq: 2 }, + ] as const)( + 'names event $lastSeq when $calls hangs after a recording of $eventCount events that ends with input', + async ({ calls, eventCount, lastSeq }) => { + // The last event is input, so it changes no pixel and no flush reports it. + const events = Array.from({ length: eventCount }, (_, seq) => + event(seq, seq * 10, seq === eventCount - 1 ? 'input_text' : 'output'), + ); + const { replayMs, error } = await exportWithRealReplayLoop( + events, + 'recorded', + 0, + 60 * 60 * 1000, + { hangingCall: calls }, + ); + + expect(replayMs).toBeUndefined(); + expect(error).toBeInstanceOf(WebmReplayStallError); + expect(error).toMatchObject({ lastSeq, timingMode: 'recorded' }); + }, + ); + + it.each([ + { timingMode: 'accelerated', eventCount: 7_401, bridgeCostMs: 50 }, + { timingMode: 'max-speed', eventCount: 39_001, bridgeCostMs: 200 }, + ] as const)( + 'exports a dense $timingMode recording whose replay runs far past its plan', + async ({ timingMode, eventCount, bridgeCostMs }) => { + // In accelerated mode an input event after each output event forces a + // flush, and each flush holds the frame. In max-speed mode the flushes + // are spread over the recorded span, about 2,300 of them here, and each + // one costs a slow bridge call. Either way the replay takes minutes for + // a recording that spans seconds. + const events = Array.from({ length: eventCount }, (_, seq) => + event(seq, seq, seq % 2 === 0 ? 'output' : 'input_text'), + ); + const { replayMs, error } = await exportWithRealReplayLoop( + events, + timingMode, + bridgeCostMs, + 60 * 60 * 1000, + ); + + expect(error).toBeUndefined(); + expect(replayMs).toBeGreaterThan(WINDOW_MS); + }, + ); + + it('exports a max-speed recording whose output goes to the renderer in one flush', async () => { + // Events with one timestamp share a flush. This flush is 40 bridge calls + // of 21 s each, 14 minutes in all. Each call is progress. + const events = Array.from({ length: 39_001 }, (_, seq) => event(seq, 0)); + const { replayMs, error } = await exportWithRealReplayLoop( + events, + 'max-speed', + 21_000, + 60 * 60 * 1000, + ); + + expect(error).toBeUndefined(); + expect(replayMs).toBeGreaterThan(WINDOW_MS); + }); + + it('exports a recording that resizes often while no page call outlasts the window', async () => { + // A resize is two page calls, the resize and the note of the graphemes + // on the screen. Each takes 160 s, so a resize takes longer than the + // window, and the report between the two calls keeps both under it. + const events = [ + event(0, 0), + resizeEvent(1, 10), + resizeEvent(2, 20), + resizeEvent(3, 30), + ]; + const { replayMs, error } = await exportWithRealReplayLoop( + events, + 'recorded', + 0, + 60 * 60 * 1000, + { resizeCostMs: 160_000, noteCostMs: 160_000 }, + ); + + expect(error).toBeUndefined(); + expect(replayMs).toBeGreaterThan(3 * WINDOW_MS); + }); + + it('stops a replay whose renderer call hangs and names the last event it reached', async () => { + const events = [event(0, 0), event(1, 10), event(2, 20, 'input_text')]; + const { replayMs, error } = await exportWithRealReplayLoop( + events, + 'recorded', + // A bridge call that outlasts the window. + 2 * WINDOW_MS, + 60 * 60 * 1000, + ); + + expect(replayMs).toBeUndefined(); + expect(error).toBeInstanceOf(WebmReplayStallError); + expect(error).toMatchObject({ + stallWindowMs: WINDOW_MS, + timingMode: 'recorded', + }); + }); +}); diff --git a/test/unit/renderer/ghosttyWebBackend.test.ts b/test/unit/renderer/ghosttyWebBackend.test.ts index 9b37cdb5..4f0e66a6 100644 --- a/test/unit/renderer/ghosttyWebBackend.test.ts +++ b/test/unit/renderer/ghosttyWebBackend.test.ts @@ -13,7 +13,10 @@ import { dirname, join } from 'node:path'; import { afterEach, describe, expect, it, vi } from 'vitest'; -import type { ReplayTimingOptions } from '../../../src/renderer/backend.js'; +import type { + ReplayProgress, + ReplayTimingOptions, +} from '../../../src/renderer/backend.js'; import type { ReplayInput } from '../../../src/renderer/types.js'; import { BUNDLED_FONT_ASSETS } from '../../../src/renderer/bundledFont.js'; import { MAX_CACHED_GLYPH_PROBES } from '../../../src/renderer/ghosttyWeb/missingGlyphs.js'; @@ -311,6 +314,151 @@ describe('GhosttyWebBackend unit guards', () => { ).toBeNull(); }); + it('reports progress after each bridge batch of a timed replay flush', async () => { + const backend = createBackend(); + const calls: string[] = []; + const reports: ReplayProgress[] = []; + Object.assign(backend as object, { + isBooted: true, + page: { isClosed: () => false }, + resizeBridge: () => Promise.resolve(), + writeBatchBridge: (_page: object, dataChunks: string[]) => { + calls.push(`write ${String(dataChunks.length)}`); + return Promise.resolve(); + }, + checkPaintedGlyphs: () => Promise.resolve({}), + readHarnessSnapshot: () => + Promise.resolve( + createHarnessSnapshotPayload({ + cols: 80, + rows: 24, + cursorRow: 0, + cursorCol: 0, + }), + ), + }); + const events: ReplayInput['events'] = Array.from( + { length: 2_501 }, + (_, seq) => ({ + seq, + ts: '2026-03-19T12:00:00.000Z', + type: 'output', + payload: { data: `out${String(seq)}` }, + }), + ); + + await backend.replayWithTiming( + { + sessionId: 'renderer-unit-session', + initialCols: 80, + initialRows: 24, + targetSeq: 2_500, + events, + }, + { mode: 'max-speed', minFrameHoldMs: 0, finalFrameHoldMs: 0 }, + (progress) => { + calls.push('report'); + reports.push(progress); + }, + ); + + // Max-speed sends the whole run of output in one flush of three bridge + // calls. A caller that watches for stalls sees progress after each call, + // and once more when the replay has reached its last event. + expect(calls.slice(calls.indexOf('write 1000'))).toEqual([ + 'write 1000', + 'report', + 'write 1000', + 'report', + 'write 501', + 'report', + 'report', + ]); + expect(reports.slice(-4)).toEqual([ + { seq: 2_500, scheduledWaitMs: 0 }, + { seq: 2_500, scheduledWaitMs: 0 }, + { seq: 2_500, scheduledWaitMs: 0 }, + { seq: 2_500, scheduledWaitMs: 0 }, + ]); + }); + + it('reports progress between the resize call and the note that follow a resize event', async () => { + const backend = createBackend(); + const calls: string[] = []; + Object.assign(backend as object, { + isBooted: true, + page: { isClosed: () => false }, + resizeBridge: (_page: object, cols: number, rows: number) => { + calls.push(`resize ${String(cols)}x${String(rows)}`); + return Promise.resolve(); + }, + writeBatchBridge: (_page: object, dataChunks: string[]) => { + calls.push(`write ${dataChunks.join(',')}`); + return Promise.resolve(); + }, + notePaintedGraphemes: () => { + calls.push('note'); + return Promise.resolve(); + }, + checkPaintedGlyphs: () => Promise.resolve({}), + readHarnessSnapshot: () => + Promise.resolve( + createHarnessSnapshotPayload({ + cols: 100, + rows: 30, + cursorRow: 0, + cursorCol: 0, + }), + ), + }); + + await backend.replayWithTiming( + { + sessionId: 'renderer-unit-session', + initialCols: 80, + initialRows: 24, + targetSeq: 2, + events: [ + { + seq: 0, + ts: '2026-03-19T12:00:00.000Z', + type: 'output', + payload: { data: 'first' }, + }, + { + seq: 1, + ts: '2026-03-19T12:00:00.000Z', + type: 'resize', + payload: { cols: 100, rows: 30 }, + }, + { + seq: 2, + ts: '2026-03-19T12:00:00.000Z', + type: 'output', + payload: { data: 'second' }, + }, + ], + }, + { mode: 'max-speed', minFrameHoldMs: 0, finalFrameHoldMs: 0 }, + (progress) => { + calls.push( + `report ${String(progress.seq)}/${String(progress.scheduledWaitMs)}`, + ); + }, + ); + + expect(calls.slice(calls.indexOf('resize 100x30') - 1)).toEqual([ + 'report 0/0', + 'resize 100x30', + 'report 1/0', + 'note', + 'report 1/0', + 'write second', + 'report 2/0', + 'report 2/0', + ]); + }); + it('retries the painted-grapheme note after the backend reboots', async () => { const backend = createBackend(); const graphemes = vi.fn(() => Promise.resolve({ missingGlyphs: [] })); @@ -1974,6 +2122,129 @@ describe('GhosttyWebBackend replayWithTiming output pacing', () => { ); }); + it('reports the wait on the timing schedule before it starts the wait', async () => { + vi.useFakeTimers(); + const backend = createBackend(); + Object.assign(backend as object, { + isBooted: true, + page: { isClosed: () => false }, + resizeBridge: () => Promise.resolve(), + flushOutputBatch: () => Promise.resolve(), + readHarnessSnapshot: () => + Promise.resolve( + createHarnessSnapshotPayload({ + cols: 80, + rows: 24, + visibleLines: [], + }), + ), + }); + const reports: (ReplayProgress & { atMs: number })[] = []; + const startedAtMs = performance.now(); + + const replay = backend.replayWithTiming( + { + sessionId: 'renderer-unit-session', + initialCols: 80, + initialRows: 24, + targetSeq: 2, + events: [outputEvent(0, 0), outputEvent(1, 200), outputEvent(2, 5_000)], + }, + RECORDED, + (progress) => { + reports.push({ ...progress, atMs: performance.now() - startedAtMs }); + }, + ); + await vi.runAllTimersAsync(); + await replay; + + // The first event sits at the first frame hold. Each later event sits + // at its recorded offset from it, so a report plus its wait ends at that + // place on the schedule. + expect( + reports.map((report) => ({ + seq: report.seq, + endsAtMs: report.atMs + report.scheduledWaitMs, + })), + ).toEqual([ + { seq: 0, endsAtMs: FIRST_EVENT_AT_MS + 200 }, + { seq: 1, endsAtMs: FIRST_EVENT_AT_MS + 5_000 }, + // The report of the last event follows the frame hold of the last flush. + { seq: 2, endsAtMs: FIRST_EVENT_AT_MS + 5_000 + 16 }, + ]); + }); + + it('runs a wait longer than a timer can run as a chain and reports what is left', async () => { + vi.useFakeTimers(); + const MAX_TIMER_DELAY_MS = 2 ** 31 - 1; + const gapMs = 30 * 24 * 60 * 60 * 1000; + const backend = createBackend(); + Object.assign(backend as object, { + isBooted: true, + page: { isClosed: () => false }, + resizeBridge: () => Promise.resolve(), + flushOutputBatch: () => Promise.resolve(), + readHarnessSnapshot: () => + Promise.resolve( + createHarnessSnapshotPayload({ + cols: 80, + rows: 24, + visibleLines: [], + }), + ), + }); + const setTimeoutSpy = vi.spyOn(globalThis, 'setTimeout'); + const reports: (ReplayProgress & { atMs: number })[] = []; + const startedAtMs = performance.now(); + + try { + const replay = backend.replayWithTiming( + { + sessionId: 'renderer-unit-session', + initialCols: 80, + initialRows: 24, + targetSeq: 1, + events: [outputEvent(0, 0), outputEvent(1, gapMs)], + }, + RECORDED, + (progress) => { + reports.push({ ...progress, atMs: performance.now() - startedAtMs }); + }, + ); + await vi.runAllTimersAsync(); + await replay; + const delays = setTimeoutSpy.mock.calls.map((call) => Number(call[1])); + expect(Math.max(...delays)).toBeLessThanOrEqual(MAX_TIMER_DELAY_MS); + } finally { + setTimeoutSpy.mockRestore(); + } + + // The first report carries the whole wait. The second comes after the first + // timer and carries the rest, so the window of a watchdog follows the wait. + const [first, second] = reports; + if (first === undefined) { + throw new Error('the replay made no report'); + } + expect(first.scheduledWaitMs).toBeGreaterThan(MAX_TIMER_DELAY_MS); + expect(first.atMs + first.scheduledWaitMs).toBe(FIRST_EVENT_AT_MS + gapMs); + expect(second).toEqual({ + seq: 0, + scheduledWaitMs: first.scheduledWaitMs - MAX_TIMER_DELAY_MS, + atMs: first.atMs + MAX_TIMER_DELAY_MS, + }); + }); + + it('waits a recorded gap of 1 ms', async () => { + // The input event ends the flush of the first output, so the flush is + // the mark of the end of the wait before the input event. + const flushes = await replayAndRecordFlushes( + [outputEvent(0, 0), inputEvent(1, 1)], + RECORDED, + ); + + expect(flushes.map((flush) => flush.atMs)).toEqual([FIRST_EVENT_AT_MS + 1]); + }); + it('keeps the recorded pace when continuous output fills every frame hold', async () => { const events = Array.from({ length: 101 }, (_, index) => outputEvent(index, index * 10),