using System.Diagnostics; using System.Text; using Microsoft.Extensions.Logging; namespace VFXReviewWorker; /// /// Standalone Blender renders: `blender -b file.blend -s N -e M -a`. /// /// The .blend is expected to be ready to render — output path, format and /// frame range already set by whoever built it. Overrides are only applied /// when the submission asked for them, so this stays "Ctrl+F12 on the farm" /// rather than a second place where render settings can drift. /// public sealed class BlenderRunner { private readonly WorkerOptions _options; private readonly ApiClient _api; private readonly ILogger _log; public BlenderRunner(WorkerOptions options, ApiClient api, ILogger log) { _options = options; _api = api; _log = log; } public async Task RunAsync( ClaimedJob job, BlenderManifest m, string machineId, ServerConfig config, CancellationToken cancelJob, CancellationToken shutdown) { var mapper = new PathMapper(_options.PathMappings); var blendLocal = mapper.Map(m.BlendFile); var totalFrames = m.TotalFrames; if (!File.Exists(blendLocal)) { return new RenderResult(false, -1, Retryable: false, $"Blend file not found on this machine: {blendLocal}", "", "", 0); } // Argument order matters to Blender: everything before -a configures the // render, and -a must come last or it renders with the old settings. // -noaudio: a render node has no sound device, and initialising audio // under a session-less service account is a known way to hang at startup. var args = new List { "-b", blendLocal, "-noaudio" }; if (!string.IsNullOrWhiteSpace(m.Scene)) { args.Add("-S"); args.Add(m.Scene!); } if (!string.IsNullOrWhiteSpace(m.OutputPath)) { args.Add("-o"); args.Add(mapper.Map(m.OutputPath!)); } if (!string.IsNullOrWhiteSpace(m.Engine)) { args.Add("-E"); args.Add(m.Engine!); } var pythonOverrides = BuildOverrideExpression(m); if (pythonOverrides is not null) { args.Add("--python-expr"); args.Add(pythonOverrides); } args.Add("-s"); args.Add(m.FrameStart.ToString()); args.Add("-e"); args.Add(m.FrameEnd.ToString()); args.Add("-a"); _log.LogInformation("Rendering {Label}: {Blend} frames {Start}-{End}", job.Label ?? job.Id, blendLocal, m.FrameStart, m.FrameEnd); return await ExecuteAsync(job.Id, machineId, args, totalFrames, m.FrameStart, config, $"blender_{job.Id}.log", cancelJob, shutdown); } /// /// Settings Blender has no command-line flag for. Returns null when the /// submission asked for no overrides, so the file renders exactly as saved. /// private static string? BuildOverrideExpression(BlenderManifest m) { var parts = new List(); if (m.Samples is int samples) { parts.Add($"getattr(S.cycles, 'samples', None) and setattr(S.cycles, 'samples', {samples})"); } if (m.ResolutionPercent is int pct) { parts.Add($"setattr(S.render, 'resolution_percentage', {pct})"); } if (!string.IsNullOrWhiteSpace(m.Device)) { var deviceValue = m.Device!.Equals("GPU", StringComparison.OrdinalIgnoreCase) ? "GPU" : "CPU"; parts.Add($"hasattr(S, 'cycles') and setattr(S.cycles, 'device', '{deviceValue}')"); } if (parts.Count == 0) return null; return "import bpy; S = bpy.context.scene; " + string.Join("; ", parts); } private async Task ExecuteAsync( string jobId, string machineId, List args, int totalFrames, int frameStart, ServerConfig config, string logFileName, CancellationToken cancelJob, CancellationToken shutdown) { var fullLogPath = Path.Combine(WorkerOptions.LogsDir, logFileName); Directory.CreateDirectory(WorkerOptions.LogsDir); var psi = new ProcessStartInfo { FileName = _options.BlenderPath, RedirectStandardOutput = true, RedirectStandardError = true, UseShellExecute = false, CreateNoWindow = true, StandardOutputEncoding = Encoding.UTF8, StandardErrorEncoding = Encoding.UTF8, }; foreach (var a in args) psi.ArgumentList.Add(a); var tail = new LogTail(200); var eta = new EtaCalculator(); var sw = Stopwatch.StartNew(); var lastProgressAt = DateTimeOffset.UtcNow; var lastReportAt = DateTimeOffset.MinValue; var framesSaved = 0; var currentFrame = frameStart; string? firstError = null; var nonRetryable = false; var cancelledByServer = false; using var process = new Process { StartInfo = psi }; await using var fullLog = new StreamWriter(fullLogPath, append: false, Encoding.UTF8); var logLock = new object(); void HandleLine(string? line, bool isStderr) { if (line is null) return; lock (logLock) { fullLog.WriteLine(line); tail.Add(line); } // Any output at all means Blender is alive, which is what the stall // watchdog is actually asking. Requiring a recognised progress line // made the watchdog stricter than its own error message and killed // healthy renders whose output we simply were not parsing. lastProgressAt = DateTimeOffset.UtcNow; var frame = BlenderProgressParser.ParseFrame(line); if (frame is not null) currentFrame = frame.Value; if (BlenderProgressParser.ParseSaved(line) is not null) { // Progress counts finished frames only: a frame emits hundreds // of status updates while it renders. framesSaved++; eta.RecordFrame(DateTimeOffset.UtcNow); } if ((isStderr || BlenderProgressParser.IsErrorLine(line)) && !string.IsNullOrWhiteSpace(line)) { if (BlenderProgressParser.IsErrorLine(line)) firstError ??= line.Trim(); if (BlenderProgressParser.IsNonRetryableError(line)) nonRetryable = true; } } try { process.Start(); } catch (Exception ex) { return new RenderResult(false, -1, Retryable: false, $"Failed to launch Blender at {_options.BlenderPath}: {ex.Message}", tail.ToString(), fullLogPath, 0); } // Deliberately not BeginOutputReadLine: that raises an event per // newline, and Blender's render status is written with a carriage // return so it overwrites one line in place. A frame that takes longer // than the stall timeout would emit no newline for its whole duration // and be killed as stalled while rendering perfectly well. var pumps = new[] { PumpAsync(process.StandardOutput, line => HandleLine(line, isStderr: false)), PumpAsync(process.StandardError, line => HandleLine(line, isStderr: true)), }; while (!process.HasExited) { await Task.Delay(TimeSpan.FromSeconds(2), CancellationToken.None); if (cancelJob.IsCancellationRequested || shutdown.IsCancellationRequested) { _log.LogWarning("Cancellation requested — killing Blender tree for job {JobId}", jobId); KillTree(process); cancelledByServer = cancelJob.IsCancellationRequested; break; } if ((DateTimeOffset.UtcNow - lastProgressAt).TotalSeconds > config.StallTimeoutSeconds) { _log.LogError("Blender stalled ({Sec}s without output) — killing job {JobId}", config.StallTimeoutSeconds, jobId); KillTree(process); await WaitForExitSafe(process); return new RenderResult(false, -2, Retryable: true, $"Blender produced no output for {config.StallTimeoutSeconds}s (stall timeout)", tail.ToString(), fullLogPath, sw.Elapsed.TotalSeconds); } if ((DateTimeOffset.UtcNow - lastReportAt).TotalSeconds >= 10) { lastReportAt = DateTimeOffset.UtcNow; var progress = totalFrames > 0 ? Math.Min(1.0, (double)framesSaved / totalFrames) : 0; var resp = await _api.ProgressAsync(jobId, machineId, progress, currentFrame, totalFrames, eta.EstimateSeconds(totalFrames - framesSaved), tail.ToString(), shutdown); if (resp?.CancelRequested == true) { _log.LogWarning("Server requested cancel for job {JobId}", jobId); KillTree(process); cancelledByServer = true; break; } } } await WaitForExitSafe(process); // Let the readers drain what is still buffered before judging the run — // the last frame's "Saved:" often arrives after the process exits. try { await Task.WhenAll(pumps).WaitAsync(TimeSpan.FromSeconds(10)); } catch { } sw.Stop(); lock (logLock) { fullLog.Flush(); } if (cancelledByServer) { return new RenderResult(false, -3, Retryable: false, "Cancelled", tail.ToString(), fullLogPath, sw.Elapsed.TotalSeconds); } var exitCode = process.ExitCode; if (exitCode != 0) { return new RenderResult(false, exitCode, Retryable: !nonRetryable, firstError ?? $"Blender exited with code {exitCode}", tail.ToString(), fullLogPath, sw.Elapsed.TotalSeconds); } // Blender exits 0 having rendered nothing if the range is empty or the // output path is unwritable, so a silent success is treated as failure. if (framesSaved == 0) { return new RenderResult(false, 0, Retryable: false, "Blender exited cleanly but saved no frames — check the output path and frame range in the .blend", tail.ToString(), fullLogPath, sw.Elapsed.TotalSeconds); } _log.LogInformation("Job {JobId}: {Saved}/{Total} frames in {Sec:F0}s", jobId, framesSaved, totalFrames, sw.Elapsed.TotalSeconds); return new RenderResult(true, 0, true, null, tail.ToString(), fullLogPath, sw.Elapsed.TotalSeconds); } /// /// Reads a stream treating both CR and LF as line terminators, so /// Blender's carriage-return progress updates are seen as they happen /// rather than only when a newline eventually arrives. /// private static async Task PumpAsync(StreamReader reader, Action onLine) { var buffer = new char[4096]; var current = new StringBuilder(256); int read; try { while ((read = await reader.ReadAsync(buffer, 0, buffer.Length)) > 0) { for (var i = 0; i < read; i++) { var c = buffer[i]; if (c == '\r' || c == '\n') { if (current.Length > 0) { onLine(current.ToString()); current.Clear(); } } else { current.Append(c); } } } if (current.Length > 0) onLine(current.ToString()); } catch (Exception) { // The process died mid-read; the exit path reports what happened. } } private static void KillTree(Process process) { try { if (!process.HasExited) process.Kill(entireProcessTree: true); } catch { } } private static async Task WaitForExitSafe(Process process) { try { await process.WaitForExitAsync(); } catch { } } }