fix(producer): restore calibration timeout ceiling + add pipeline observability

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) {

packages/engine/src/services/frameCapture.ts

@@ -748,17 +748,26 @@ export async function initializeSession(session: CaptureSession): Promise<void>
   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<void>
       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<void>
       );
     }
     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<void>
     );
   })();
   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<void>
         `Continuing render — affected videos will appear as blank/black frames.`,
     );
   }
+  logInitPhase("pollVideosReady complete");
 
   // Image readiness — parity with pollVideosReady. Defense against remote
   // <img> URLs that bypass the htmlCompiler localize step.
@@ -938,10 +957,12 @@ export async function initializeSession(session: CaptureSession): Promise<void>
     );
   }
   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

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;

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", () => {

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,