diff --git a/packages/engine/src/services/browserManager.ts b/packages/engine/src/services/browserManager.ts index 9ddec1720..8cba057a9 100644 --- a/packages/engine/src/services/browserManager.ts +++ b/packages/engine/src/services/browserManager.ts @@ -369,6 +369,11 @@ async function launchBrowser( protocolTimeout, }); + const browserVersion = await browser.version().catch(() => "unknown"); + console.log( + `[BrowserManager] Browser launched (${browserVersion}, ${captureMode}, headlessShell=${!!headlessShell}, platform=${process.platform})`, + ); + if (captureMode === "beginframe") { const supported = await probeBeginFrameSupport(browser).catch(() => true); if (!supported) { diff --git a/packages/engine/src/services/frameCapture.ts b/packages/engine/src/services/frameCapture.ts index dda707cb9..d02ed650c 100644 --- a/packages/engine/src/services/frameCapture.ts +++ b/packages/engine/src/services/frameCapture.ts @@ -748,17 +748,26 @@ export async function initializeSession(session: CaptureSession): Promise const url = `${serverUrl}/index.html`; const pageNavigationTimeout = session.config?.pageNavigationTimeout ?? DEFAULT_CONFIG.pageNavigationTimeout; + const initStart = Date.now(); + const logInitPhase = (phase: string) => { + console.log(`[initSession:${session.captureMode}] ${phase} (${Date.now() - initStart}ms)`); + }; + if (session.captureMode === "screenshot") { // Screenshot mode: standard navigation, rAF works normally await page.goto(url, { waitUntil: "domcontentloaded", timeout: pageNavigationTimeout }); + logInitPhase("page.goto complete"); const pageReadyTimeout = session.config?.playerReadyTimeout ?? DEFAULT_CONFIG.playerReadyTimeout; await pollHfReady(page, pageReadyTimeout); + logInitPhase("pollHfReady complete"); await pollSubCompositionTimelines(page, pageReadyTimeout); + logInitPhase("pollSubCompositionTimelines complete"); await applyVideoMetadataHints(page, session.options.videoMetadataHints); + logInitPhase("applyVideoMetadataHints complete"); // Wait for all video elements to have decoded their CURRENT frame, not // just metadata. readyState >= 2 (HAVE_CURRENT_DATA) means a frame is @@ -777,6 +786,7 @@ export async function initializeSession(session: CaptureSession): Promise session.options.skipReadinessVideoIds ?? [], pageReadyTimeout, ); + logInitPhase("pollVideosReady complete"); if (!videosReady) { const failedVideos = await page.evaluate((skipIdList: readonly string[]) => { const skip = new Set(skipIdList); @@ -811,9 +821,12 @@ export async function initializeSession(session: CaptureSession): Promise ); } await decodeAllImages(page); + logInitPhase("images ready + decoded"); await page.evaluate(`document.fonts?.ready`); + logInitPhase("fonts ready"); await waitForOptionalTailwindReady(page, pageReadyTimeout); + logInitPhase("tailwind ready"); // For PNG captures, force the page background fully transparent so the // captured screenshots carry a real alpha channel. Must run AFTER @@ -879,22 +892,27 @@ export async function initializeSession(session: CaptureSession): Promise ); })(); warmupLoopPromise.catch(() => {}); + logInitPhase("warmup loop started"); await page.goto(url, { waitUntil: "domcontentloaded", timeout: pageNavigationTimeout }); + logInitPhase("page.goto complete"); // Poll for window.__hf readiness using manual evaluate loop (waitForFunction // uses rAF polling internally, which won't fire in beginFrame mode). const pageReadyTimeout = session.config?.playerReadyTimeout ?? DEFAULT_CONFIG.playerReadyTimeout; try { await pollHfReady(page, pageReadyTimeout); + logInitPhase("pollHfReady complete"); } catch (err) { warmupState.running = false; throw err; } await pollSubCompositionTimelines(page, pageReadyTimeout); + logInitPhase("pollSubCompositionTimelines complete"); await applyVideoMetadataHints(page, session.options.videoMetadataHints); + logInitPhase("applyVideoMetadataHints complete"); // Same readyState contract as the screenshot path above (>= 2 / HAVE_CURRENT_DATA). const bfVideosReady = await pollVideosReady( @@ -916,6 +934,7 @@ export async function initializeSession(session: CaptureSession): Promise `Continuing render — affected videos will appear as blank/black frames.`, ); } + logInitPhase("pollVideosReady complete"); // Image readiness — parity with pollVideosReady. Defense against remote // URLs that bypass the htmlCompiler localize step. @@ -938,10 +957,12 @@ export async function initializeSession(session: CaptureSession): Promise ); } await decodeAllImages(page); + logInitPhase("images ready + decoded"); - // Font check (no rAF dependency — uses fonts.ready API directly) await page.evaluate(`document.fonts?.ready`); + logInitPhase("fonts ready"); await waitForOptionalTailwindReady(page, pageReadyTimeout); + logInitPhase("tailwind ready"); // Stop warmup. Unlocked mode exits on this flag; locked mode keeps ticking // until LOCKED_WARMUP_TICKS, so we await its promise to ensure the count is diff --git a/packages/producer/src/services/render/captureCost.ts b/packages/producer/src/services/render/captureCost.ts index 1a1e4fd13..16bd1d6b0 100644 --- a/packages/producer/src/services/render/captureCost.ts +++ b/packages/producer/src/services/render/captureCost.ts @@ -53,11 +53,10 @@ export const CAPTURE_CALIBRATION_TARGET_MS = 600; export const MAX_MEASURED_CAPTURE_COST_MULTIPLIER = 8; /** - * CDP protocol timeout used while running calibration. Bounded below - * the normal `cfg.protocolTimeout` so a wedged BeginFrame calibration - * times out fast and falls back to screenshot mode (see the - * `shouldFallbackToScreenshotAfterCalibrationError` path in the - * sequencer). + * CDP protocol timeout used while running calibration. This is a ceiling, + * not a floor — a wedged BeginFrame must time out fast so the sequencer + * can fall back to screenshot mode via + * `shouldFallbackToScreenshotAfterCalibrationError`. */ export const CAPTURE_CALIBRATION_PROTOCOL_TIMEOUT_MS = 30_000; @@ -161,7 +160,7 @@ export function resolveRenderWorkerCount( export function createCaptureCalibrationConfig(cfg: EngineConfig): EngineConfig { return { ...cfg, - protocolTimeout: Math.max(cfg.protocolTimeout, CAPTURE_CALIBRATION_PROTOCOL_TIMEOUT_MS), + protocolTimeout: Math.min(cfg.protocolTimeout, CAPTURE_CALIBRATION_PROTOCOL_TIMEOUT_MS), }; } @@ -362,6 +361,12 @@ export async function runCaptureCalibration(input: { }; const calibrationCfg = createCaptureCalibrationConfig({ ...cfg, forceScreenshot }); + log.info("[Render] Calibration config", { + protocolTimeout: calibrationCfg.protocolTimeout, + parentProtocolTimeout: cfg.protocolTimeout, + forceScreenshot, + totalFrames, + }); let calibration: | { estimate: CaptureCostEstimate; samples: CaptureCalibrationSample[] } | undefined; diff --git a/packages/producer/src/services/renderOrchestrator.test.ts b/packages/producer/src/services/renderOrchestrator.test.ts index 528b5b9c2..3816cfbf0 100644 --- a/packages/producer/src/services/renderOrchestrator.test.ts +++ b/packages/producer/src/services/renderOrchestrator.test.ts @@ -737,21 +737,22 @@ describe("selectCaptureCalibrationFrames", () => { }); describe("capture calibration safeguards", () => { - it("respects user protocol timeout when higher than calibration default", () => { + it("caps protocol timeout at calibration ceiling for fast fallback", () => { const cfg = createConfig(); const calibrationCfg = createCaptureCalibrationConfig(cfg); - // User's 300s timeout is higher than the 30s calibration default — use the user's value - expect(calibrationCfg.protocolTimeout).toBe(300000); + // Default 300s is above the 30s calibration ceiling — cap at 30s + // so a wedged BeginFrame times out fast and falls back to screenshot + expect(calibrationCfg.protocolTimeout).toBe(30000); expect(cfg.protocolTimeout).toBe(300000); }); - it("uses calibration floor when user timeout is lower", () => { + it("preserves user timeout when already below calibration ceiling", () => { const cfg = createConfig(); cfg.protocolTimeout = 5000; - // 5s is below the 30s calibration floor — use the floor - expect(createCaptureCalibrationConfig(cfg).protocolTimeout).toBe(30000); + // 5s is below the 30s ceiling — keep the user's value + expect(createCaptureCalibrationConfig(cfg).protocolTimeout).toBe(5000); }); it("falls back to screenshot mode after beginFrame calibration failures", () => { diff --git a/packages/producer/src/services/renderOrchestrator.ts b/packages/producer/src/services/renderOrchestrator.ts index 75c5b3bde..0b653d5cc 100644 --- a/packages/producer/src/services/renderOrchestrator.ts +++ b/packages/producer/src/services/renderOrchestrator.ts @@ -1495,6 +1495,22 @@ export async function executeRenderJob( job.startedAt = new Date(); assertNotAborted(); + + log.info("[Render] Pipeline started", { + platform: process.platform, + arch: process.arch, + nodeVersion: process.version, + fps: job.config.fps, + format: outputFormat, + quality: job.config.quality, + browserGpuMode: cfg.browserGpuMode, + forceScreenshot: cfg.forceScreenshot, + protocolTimeout: cfg.protocolTimeout, + browserTimeout: cfg.browserTimeout, + pageNavigationTimeout: cfg.pageNavigationTimeout, + playerReadyTimeout: cfg.playerReadyTimeout, + }); + if (!existsSync(workDir)) mkdirSync(workDir, { recursive: true }); if (job.config.debug) { @@ -2126,6 +2142,19 @@ export async function executeRenderJob( hdrDiagnostics, }); + log.info("[Render] Failure summary", { + failedStage: job.currentStage, + error: errorMessage, + elapsedMs: Date.now() - pipelineStart, + stageTimings: perfStages, + isTimeout: isTimeoutError, + workers: job.config.workers ?? "auto", + protocolTimeout: cfg.protocolTimeout, + browserConsoleErrors: lastBrowserConsole + .filter((l) => l.includes("ERROR") || l.includes("PAGEERROR")) + .slice(-5), + }); + await cleanupRenderResources({ fileServer, probeSession,