fix(worker): drain ffmpeg's pipes so thumbnail generation stops deadlocking

ffmpeg was started with stdout and stderr redirected and neither pipe ever
read. Windows gives an anonymous pipe a ~4 KB buffer, which ffmpeg's banner
and stream summary exceed on their own, so it blocked forever on the write,
never exited, and the two-minute cap fired:

    TaskCanceledException at Process.WaitForExitAsync
    Preview complete for job ... in 221s (mov + mp4)

The exception was swallowed as "non-fatal", so every preview silently
produced no thumbnail while paying 120s for the privilege. Nothing
downstream was wrong — there was simply never a thumbnail to promote.

Both pipes are now drained concurrently before the wait. A timeout kills the
process tree rather than leaking an ffmpeg per job, and attempts report a
three-way outcome so a hung or unstartable ffmpeg is not retried — without
that, the slate fallback would have doubled the wasted time to four minutes.

Failures are no longer silent: an unset or missing ffmpegPath, the seek that
was chosen, and ffmpeg's own exit code, command and stderr are all logged.

finalizePreview likewise records every promotion outcome on the export
timeline, not just success. Silence there was indistinguishable from a broken
worker, a project whose flag never saved, and the feature working as
configured — which is what made this take so long to find.

Adds scripts/diagnose-thumbnails.mjs, which walks the chain (ffmpeg →
Export.thumbnailKey → project flag → Shot.generatedThumbnailUrl → what the UI
resolves) and names the first broken link.

Worker 1.5.1 -> 1.5.2; republish required for the fix to take effect.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

RenderWorker/VFXReviewWorker/PreviewStage.cs

@@ -250,11 +250,77 @@ public sealed class PreviewStage
     private async Task<string?> TryMakeThumbnailAsync(
         string jobId, string mp4Path, PreviewBuildResult? build, double fps, CancellationToken ct)
     {
-        if (string.IsNullOrWhiteSpace(_options.FfmpegPath) || !File.Exists(_options.FfmpegPath))
+        if (string.IsNullOrWhiteSpace(_options.FfmpegPath))
         {
+            _log.LogWarning(
+                "No thumbnail for job {JobId}: ffmpegPath is not set in config.json. " +
+                "Thumbnails are skipped, and shots cannot take a frame from this render.",
+                jobId);
             return null;
         }
+        if (!File.Exists(_options.FfmpegPath))
+        {
+            _log.LogWarning(
+                "No thumbnail for job {JobId}: ffmpegPath points at {Path}, which does not exist.",
+                jobId, _options.FfmpegPath);
+            return null;
+        }
+
         var outPath = Path.Combine(WorkerOptions.ScratchDir, $"job_{jobId}_thumb.jpg");
+        var seek = ThumbnailSeekSeconds(build, fps);
+
+        if (seek is { } t)
+        {
+            _log.LogInformation(
+                "Thumbnail for job {JobId}: seeking to {Seek:F2}s (slate {Start:F2}s + 25% of {Frames} frames @ {Fps}fps)",
+                jobId, t, build!.PictureStartSeconds, build.FrameCount, fps);
+
+            var attempt = await RunFfmpegThumbnailAsync(jobId, mp4Path, outPath, t, ct);
+            if (attempt == ThumbAttempt.Wrote) return outPath;
+            // A hung or unstartable ffmpeg will hang the same way a second
+            // time, and each attempt costs the full two-minute cap.
+            if (attempt == ThumbAttempt.Broken) return null;
+
+            // The seek is derived from what the AE build reported; if those
+            // numbers disagree with the rendered file, ffmpeg lands past the
+            // end and writes nothing. Falling back to the whole-file scan means
+            // a wrong seek costs picture content, never the thumbnail itself.
+            _log.LogWarning(
+                "Thumbnail seek to {Seek:F2}s produced nothing for job {JobId} — retrying across the whole file. " +
+                "The frame will likely be the slate.", t, jobId);
+        }
+        else
+        {
+            _log.LogInformation(
+                "Thumbnail for job {JobId}: build reported no picture start, scanning the whole file " +
+                "(the frame will likely be the slate).", jobId);
+        }
+
+        if (await RunFfmpegThumbnailAsync(jobId, mp4Path, outPath, null, ct) == ThumbAttempt.Wrote) return outPath;
+
+        _log.LogWarning("No thumbnail produced for job {JobId} — see the ffmpeg output above.", jobId);
+        return null;
+    }
+
+    /// <summary>How one ffmpeg attempt ended.</summary>
+    private enum ThumbAttempt
+    {
+        /// <summary>A thumbnail was written.</summary>
+        Wrote,
+        /// <summary>ffmpeg ran and wrote nothing — a different attempt may work.</summary>
+        NoOutput,
+        /// <summary>ffmpeg hung or could not start — retrying costs minutes and fixes nothing.</summary>
+        Broken,
+    }
+
+    /// <summary>
+    /// One ffmpeg invocation. <paramref name="seekSeconds"/> null means the old
+    /// whole-file <c>thumbnail</c> filter. Logs ffmpeg's own diagnosis when no
+    /// file is produced.
+    /// </summary>
+    private async Task<ThumbAttempt> RunFfmpegThumbnailAsync(
+        string jobId, string mp4Path, string outPath, double? seekSeconds, CancellationToken ct)
+    {
         TryDelete(outPath);
 
         var psi = new ProcessStartInfo
@@ -267,8 +333,7 @@ public sealed class PreviewStage
         };
 
         var args = new List<string> { "-y" };
-        var seek = ThumbnailSeekSeconds(build, fps);
-        if (seek is { } t)
+        if (seekSeconds is { } t)
         {
             // Before -i: ffmpeg seeks by keyframe, which is fast and accurate
             // enough for a poster frame.
@@ -290,27 +355,65 @@ public sealed class PreviewStage
         args.Add("1");
         args.Add(outPath);
 
-        foreach (var a in args)
-        {
-            psi.ArgumentList.Add(a);
-        }
+        foreach (var a in args) psi.ArgumentList.Add(a);
 
         try
         {
             using var process = Process.Start(psi);
-            if (process is null) return null;
+            if (process is null)
+            {
+                _log.LogWarning("Could not start ffmpeg at {Path} for job {JobId}", _options.FfmpegPath, jobId);
+                return ThumbAttempt.Broken;
+            }
+
+            // Drain BOTH pipes while the process runs. Windows gives an
+            // anonymous pipe a ~4 KB buffer; ffmpeg's banner and stream summary
+            // exceed that on their own, so a redirected-but-unread pipe fills,
+            // ffmpeg blocks forever on the write, and the wait below times out
+            // with the process still alive. That is a deadlock, not a slow
+            // encode, and it is why this step failed with nothing but a
+            // cancellation to show for it.
+            var stderrTask = process.StandardError.ReadToEndAsync();
+            var stdoutTask = process.StandardOutput.ReadToEndAsync();
             using var timeout = CancellationTokenSource.CreateLinkedTokenSource(ct);
             timeout.CancelAfter(TimeSpan.FromMinutes(2));
+            try
+            {
                 await process.WaitForExitAsync(timeout.Token);
-            return File.Exists(outPath) ? outPath : null;
+            }
+            catch (OperationCanceledException) when (!ct.IsCancellationRequested)
+            {
+                // Our own 2-minute cap, not a shutdown: leaving ffmpeg running
+                // would hold the scratch file open and leak a process per job.
+                _log.LogWarning(
+                    "ffmpeg timed out after 2 minutes for job {JobId} — killing it. Command: {Args}",
+                    jobId, string.Join(" ", args));
+                try { process.Kill(entireProcessTree: true); } catch { }
+                return ThumbAttempt.Broken;
+            }
+            var stderr = await stderrTask;
+            await stdoutTask;
+
+            if (File.Exists(outPath) && new FileInfo(outPath).Length > 0) return ThumbAttempt.Wrote;
+
+            _log.LogWarning(
+                "ffmpeg wrote no thumbnail for job {JobId} (exit {Exit}). Command: {Args} -- ffmpeg said: {Stderr}",
+                jobId, process.ExitCode, string.Join(" ", args), Tail(stderr, 1200));
+            return ThumbAttempt.NoOutput;
         }
         catch (Exception ex)
         {
-            _log.LogWarning(ex, "Thumbnail generation failed (non-fatal)");
-            return null;
+            _log.LogWarning(ex, "Thumbnail generation failed for job {JobId} (non-fatal)", jobId);
+            return ThumbAttempt.Broken;
         }
     }
 
+    /// <summary>Last <paramref name="max"/> characters — ffmpeg puts the error at the end.</summary>
+    private static string Tail(string? text, int max) =>
+        string.IsNullOrEmpty(text) ? "(no output)"
+        : text.Length <= max ? text
+        : text[^max..];
+
     /// <summary>
     /// Timestamp for the poster frame: a quarter of the way into picture,
     /// skipping the slate. Null when the build did not report where picture

RenderWorker/VFXReviewWorker/VFXReviewWorker.csproj

@@ -15,7 +15,7 @@
       every change that gets published. publish.ps1 appends the git SHA via
       SourceRevisionId, giving "1.1.0+feb1c7b".
     -->
-    <Version>1.5.1</Version>
+    <Version>1.5.2</Version>
   </PropertyGroup>
 
   <ItemGroup>

lib/render-pipeline/preview.ts

@@ -413,13 +413,27 @@ export async function finalizePreview(jobId: string, machineId: string, body: Fi
     // reference frame that came with the brief and the pipeline never touches
     // it. Shows that supply stills therefore look exactly as they did; shows
     // that supply none get their empty grids filled from the renders instead.
-    let thumbnailPromoted = false;
-    if (artifacts.thumbnailKey) {
+    //
+    // Every outcome is recorded on the export timeline, including the ones that
+    // did nothing: silence here is indistinguishable from a broken worker, a
+    // project whose flag never saved, and a feature working as configured.
+    let thumbnailNote: string;
+    if (!artifacts.thumbnailKey) {
+      thumbnailNote =
+        " — no thumbnail in this render, so the shot's was left alone " +
+        "(the worker reported no thumbnail: check ffmpegPath in its config.json)";
+    } else {
       const shot = await tx.shot.findUnique({
         where: { id: exportRow.shotId },
         select: { project: { select: { pipelineConfig: true } } },
       });
-      if (shot && autoShotThumbnailEnabled(shot.project)) {
+      if (!shot) {
+        thumbnailNote = " — shot not found, thumbnail not applied";
+      } else if (!autoShotThumbnailEnabled(shot.project)) {
+        thumbnailNote =
+          " — shot thumbnail left alone (this project has \"Use render frames as " +
+          "shot thumbnails\" turned off)";
+      } else {
         await tx.shot.update({
           where: { id: exportRow.shotId },
           data: {
@@ -427,7 +441,7 @@ export async function finalizePreview(jobId: string, machineId: string, body: Fi
             generatedThumbnailFrom: exportRow.versionString,
           },
         });
-        thumbnailPromoted = true;
+        thumbnailNote = " — shot thumbnail updated from this render";
       }
     }
 
@@ -469,7 +483,7 @@ export async function finalizePreview(jobId: string, machineId: string, body: Fi
               : ` — review version created (${inheritedApproval ?? "PENDING_REVIEW"})`
             : " — no preview media reported") +
           (taskRenamed ? ` — task renamed to ${taskTitle}` : "") +
-          (thumbnailPromoted ? " — shot thumbnail updated from this render" : ""),
+          thumbnailNote,
       },
       {
         ...(versionId ? { versionId } : {}),

scripts/diagnose-thumbnails.mjs

@@ -0,0 +1,90 @@
+/**
+ * Why is a shot not showing a render-derived thumbnail?
+ *
+ * Walks the chain in order and reports the first broken link:
+ *
+ *   ffmpeg on the worker → Export.thumbnailKey → project flag →
+ *   Shot.generatedThumbnailUrl → what the UI resolves
+ *
+ * Usage:  node scripts/diagnose-thumbnails.mjs [PROJECT_CODE]
+ */
+import { PrismaClient } from "@prisma/client";
+
+const db = new PrismaClient();
+const projectCode = process.argv[2]?.toUpperCase();
+
+const projects = await db.project.findMany({
+  where: projectCode ? { code: projectCode } : {},
+  select: { id: true, code: true, name: true, pipelineConfig: true },
+  orderBy: { code: "asc" },
+});
+
+if (projects.length === 0) {
+  console.log(projectCode ? `No project with code ${projectCode}.` : "No projects.");
+  process.exit(0);
+}
+
+for (const p of projects) {
+  const cfg = (p.pipelineConfig ?? {});
+  const flag = cfg.autoShotThumbnail;
+  const on = flag === true;
+
+  console.log(`\n━━ ${p.code} — ${p.name}`);
+  console.log(`   auto-promote flag : ${JSON.stringify(flag)} ${on ? "✔ on" : "✘ OFF"}`);
+  if (flag === undefined) {
+    console.log(`   ⚠ key absent from pipelineConfig. Either the setting was never saved,`);
+    console.log(`     or the server that saved it predates the boolean fix in actions/projects.ts.`);
+    console.log(`     Stored keys: ${JSON.stringify(Object.keys(cfg))}`);
+  }
+
+  const exports = await db.export.findMany({
+    where: { shot: { projectId: p.id } },
+    orderBy: { createdAt: "desc" },
+    take: 10,
+    select: {
+      versionString: true, status: true, createdAt: true,
+      thumbnailKey: true, skipPreview: true,
+      shot: {
+        select: {
+          shotCode: true, thumbnailUrl: true,
+          generatedThumbnailUrl: true, generatedThumbnailFrom: true,
+        },
+      },
+    },
+  });
+
+  if (exports.length === 0) {
+    console.log("   (no exports yet)");
+    continue;
+  }
+
+  console.log(`   last ${exports.length} exports:`);
+  for (const e of exports) {
+    const s = e.shot;
+    const displayed = s.thumbnailUrl || s.generatedThumbnailUrl || null;
+    const source = s.thumbnailUrl ? "reference" : s.generatedThumbnailUrl ? "render" : "NOTHING";
+    console.log(
+      `\n     ${s.shotCode} ${e.versionString} [${e.status}]${e.skipPreview ? " skipPreview" : ""}`
+    );
+    console.log(`       export.thumbnailKey     : ${e.thumbnailKey ?? "✘ NULL — worker produced no thumbnail (ffmpeg?)"}`);
+    console.log(`       shot.thumbnailUrl       : ${s.thumbnailUrl ?? "(none)"}`);
+    console.log(`       shot.generatedThumbnail : ${s.generatedThumbnailUrl ?? "(none)"}${s.generatedThumbnailFrom ? ` [from ${s.generatedThumbnailFrom}]` : ""}`);
+    console.log(`       → UI shows              : ${displayed ?? "nothing"}  (${source})`);
+
+    if (!e.thumbnailKey) {
+      console.log(`       ⇒ Broken at the WORKER. Check ffmpegPath in config.json on the`);
+      console.log(`         machine that ran it, and its log for "no thumbnail".`);
+    } else if (!on) {
+      console.log(`       ⇒ Thumbnail exists but the project flag is off, so it was not promoted.`);
+      console.log(`         Turn on "Use render frames as shot thumbnails", or use the`);
+      console.log(`         per-export "Use frame" button on the shot's Exports tab.`);
+    } else if (!s.generatedThumbnailUrl) {
+      console.log(`       ⇒ Thumbnail exists and the flag is on, but nothing was promoted.`);
+      console.log(`         This export probably finalized BEFORE the flag was turned on —`);
+      console.log(`         promotion happens at finalize, it is not retroactive. Re-render,`);
+      console.log(`         or press "Use frame" on the Exports tab.`);
+    }
+  }
+}
+
+await db.$disconnect();