diff --git a/RenderWorker/VFXReviewWorker/PreviewStage.cs b/RenderWorker/VFXReviewWorker/PreviewStage.cs index 4031dd8..e39dea0 100644 --- a/RenderWorker/VFXReviewWorker/PreviewStage.cs +++ b/RenderWorker/VFXReviewWorker/PreviewStage.cs @@ -250,11 +250,77 @@ public sealed class PreviewStage private async Task 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; + } + + /// How one ffmpeg attempt ended. + private enum ThumbAttempt + { + /// A thumbnail was written. + Wrote, + /// ffmpeg ran and wrote nothing — a different attempt may work. + NoOutput, + /// ffmpeg hung or could not start — retrying costs minutes and fixes nothing. + Broken, + } + + /// + /// One ffmpeg invocation. null means the old + /// whole-file thumbnail filter. Logs ffmpeg's own diagnosis when no + /// file is produced. + /// + private async Task 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 { "-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)); - await process.WaitForExitAsync(timeout.Token); - return File.Exists(outPath) ? outPath : null; + try + { + await process.WaitForExitAsync(timeout.Token); + } + 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; } } + /// Last characters — ffmpeg puts the error at the end. + private static string Tail(string? text, int max) => + string.IsNullOrEmpty(text) ? "(no output)" + : text.Length <= max ? text + : text[^max..]; + /// /// Timestamp for the poster frame: a quarter of the way into picture, /// skipping the slate. Null when the build did not report where picture diff --git a/RenderWorker/VFXReviewWorker/VFXReviewWorker.csproj b/RenderWorker/VFXReviewWorker/VFXReviewWorker.csproj index d5857d9..2d54cb5 100644 --- a/RenderWorker/VFXReviewWorker/VFXReviewWorker.csproj +++ b/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". --> - 1.5.1 + 1.5.2 diff --git a/lib/render-pipeline/preview.ts b/lib/render-pipeline/preview.ts index 4f79f62..cd9f929 100644 --- a/lib/render-pipeline/preview.ts +++ b/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 } : {}), diff --git a/scripts/diagnose-thumbnails.mjs b/scripts/diagnose-thumbnails.mjs new file mode 100644 index 0000000..45be8d1 --- /dev/null +++ b/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();