vfxreview/RenderWorker/VFXReviewWorker/BlenderRunner.cs

using System.Diagnostics;
using System.Text;
using Microsoft.Extensions.Logging;

namespace VFXReviewWorker;

/// <summary>
/// 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.
/// </summary>
public sealed class BlenderRunner
{
    private readonly WorkerOptions _options;
    private readonly ApiClient _api;
    private readonly ILogger<BlenderRunner> _log;

    public BlenderRunner(WorkerOptions options, ApiClient api, ILogger<BlenderRunner> log)
    {
        _options = options;
        _api = api;
        _log = log;
    }

    public async Task<RenderResult> 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<string> { "-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);
    }

    /// <summary>
    /// Settings Blender has no command-line flag for. Returns null when the
    /// submission asked for no overrides, so the file renders exactly as saved.
    /// </summary>
    private static string? BuildOverrideExpression(BlenderManifest m)
    {
        var parts = new List<string>();
        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<RenderResult> ExecuteAsync(
        string jobId,
        string machineId,
        List<string> 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)),
        };

        try
        {
            return await MonitorAsync();
        }
        catch
        {
            // Disposing a Process does not end it: without this, any exception
            // in the monitor loop leaves Blender rendering on the node,
            // unsupervised, while the job is retried alongside it.
            KillTree(process);
            throw;
        }

        async Task<RenderResult> MonitorAsync()
        {
            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,
                    firstError is not null
                        ? $"Blender exited cleanly but saved no frames: {firstError}"
                        : "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);
        }
    }

    /// <summary>
    /// 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.
    /// </summary>
    private static async Task PumpAsync(StreamReader reader, Action<string> 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 { }
    }
}