vfxreview/RenderWorker/VFXReviewWorker/AerenderRunner.cs

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

namespace VFXReviewWorker;

public sealed record RenderResult(
    bool Success,
    int ExitCode,
    bool Retryable,
    string? ErrorMessage,
    string LogTail,
    string FullLogPath,
    double RenderSeconds);

/// <summary>
/// Stage 1: aerender execution (§7.3). Launches aerender.exe, parses stdout
/// for PROGRESS/ERROR lines, reports progress (renewing the lease), enforces
/// the stall timeout, and honours cancellation by killing the process tree.
/// </summary>
public sealed class AerenderRunner
{
    private readonly WorkerOptions _options;
    private readonly ApiClient _api;
    private readonly ILogger<AerenderRunner> _log;

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

    /// <summary>
    /// Renders every queued item in an already-prepared project (no -comp), used
    /// by the preview stage: the build script saved an AEP with the MOV and MP4
    /// output modules already queued, so one launch produces both.
    /// </summary>
    public Task<RenderResult> RunProjectAsync(
        string jobId,
        string machineId,
        string projectPathLocal,
        int totalFrames,
        ServerConfig config,
        CancellationToken cancelJob,
        CancellationToken shutdown)
    {
        var args = new List<string> { "-project", projectPathLocal, "-mp" };
        _log.LogInformation("Rendering prepared project for job {JobId}: {Project}", jobId, projectPathLocal);
        return ExecuteAsync(jobId, machineId, args, totalFrames, 0, config, $"aerender_{jobId}_preview.log", cancelJob, shutdown);
    }

    public async Task<RenderResult> RunAsync(
        ClaimedJob job,
        RenderManifest m,
        string machineId,
        string outputDirLocal,
        ServerConfig config,
        CancellationToken cancelJob,
        CancellationToken shutdown)
    {
        var mapper = new PathMapper(_options.PathMappings);
        var aepLocal = mapper.Map(m.AepPath);
        var outputArg = Path.Combine(outputDirLocal, m.OutputPattern);

        PrepareOutputDir(outputDirLocal, m.OutputPattern);

        var args = new List<string>
        {
            "-project", aepLocal,
            "-comp", m.CompName,
            "-s", m.FrameStart.ToString(),
            "-e", m.FrameEnd.ToString(),
        };
        if (!string.IsNullOrEmpty(m.RenderSettingsTemplate)) { args.Add("-RStemplate"); args.Add(m.RenderSettingsTemplate); }
        if (!string.IsNullOrEmpty(m.OutputModuleTemplate)) { args.Add("-OMtemplate"); args.Add(m.OutputModuleTemplate); }
        args.Add("-output"); args.Add(outputArg);
        // NB: no "-continueOnMissingFootage" — the real flag takes no value
        // (passing "false" is an aerender SYNTAX ERROR), and its *presence*
        // enables skipping missing footage. aerender's default is to stop on
        // missing footage, which is exactly what the pipeline wants.

        _log.LogInformation("Launching aerender for job {JobId}: {Aep} comp \"{Comp}\" frames {S}-{E} → {Out}",
            job.Id, aepLocal, m.CompName, m.FrameStart, m.FrameEnd, outputArg);

        return await ExecuteAsync(job.Id, machineId, args, m.TotalFrames, m.FrameStart, config,
            $"aerender_{job.Id}.log", cancelJob, shutdown);
    }

    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.AerenderPath,
            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;
        int framesDone = 0;
        string? firstError = null;
        bool nonRetryable = false;
        bool 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);
            }
            var frame = ProgressParser.ParseFrame(line);
            if (frame is not null)
            {
                framesDone = Math.Max(framesDone, frame.Value);
                lastProgressAt = DateTimeOffset.UtcNow;
                eta.RecordFrame(lastProgressAt);
            }
            if ((isStderr || ProgressParser.IsErrorLine(line)) && !string.IsNullOrWhiteSpace(line))
            {
                if (ProgressParser.IsErrorLine(line)) firstError ??= line.Trim();
                if (ProgressParser.IsNonRetryableError(line)) nonRetryable = true;
            }
        }

        process.OutputDataReceived += (_, e) => HandleLine(e.Data, isStderr: false);
        process.ErrorDataReceived += (_, e) => HandleLine(e.Data, isStderr: true);

        try
        {
            process.Start();
        }
        catch (Exception ex)
        {
            return new RenderResult(false, -1, Retryable: false,
                $"Failed to launch aerender at {_options.AerenderPath}: {ex.Message}",
                tail.ToString(), fullLogPath, 0);
        }
        process.BeginOutputReadLine();
        process.BeginErrorReadLine();

        var total = totalFrames;
        while (!process.HasExited)
        {
            await Task.Delay(TimeSpan.FromSeconds(2), CancellationToken.None);

            if (cancelJob.IsCancellationRequested || shutdown.IsCancellationRequested)
            {
                _log.LogWarning("Cancellation requested — killing aerender tree for job {JobId}", jobId);
                KillTree(process);
                cancelledByServer = cancelJob.IsCancellationRequested;
                break;
            }

            // Stall watchdog (§7.3): no progress line for stallTimeoutSeconds → kill
            if ((DateTimeOffset.UtcNow - lastProgressAt).TotalSeconds > config.StallTimeoutSeconds)
            {
                _log.LogError("aerender stalled ({Sec}s without progress) — killing job {JobId}", config.StallTimeoutSeconds, jobId);
                KillTree(process);
                await WaitForExitSafe(process);
                return new RenderResult(false, -2, Retryable: true,
                    $"aerender produced no progress for {config.StallTimeoutSeconds}s (stall timeout)",
                    tail.ToString(), fullLogPath, sw.Elapsed.TotalSeconds);
            }

            // Progress report every ~10 s (renews lease); best-effort
            if ((DateTimeOffset.UtcNow - lastReportAt).TotalSeconds >= 10)
            {
                lastReportAt = DateTimeOffset.UtcNow;
                var progress = total > 0 ? Math.Min(1.0, (double)framesDone / total) : 0;
                try
                {
                    var resp = await _api.ProgressAsync(jobId, machineId, progress,
                        framesDone > 0 ? frameStart + framesDone - 1 : null,
                        total, eta.EstimateSeconds(total - framesDone), tail.ToString(), shutdown);
                    if (resp?.CancelRequested == true)
                    {
                        _log.LogWarning("Server requested cancel for job {JobId}", jobId);
                        KillTree(process);
                        cancelledByServer = true;
                        break;
                    }
                }
                catch (Exception ex)
                {
                    _log.LogDebug(ex, "Progress report failed (non-fatal; lease covered by reaper)");
                }
            }
        }

        await WaitForExitSafe(process);
        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 && firstError is null)
        {
            return new RenderResult(true, 0, true, null, tail.ToString(), fullLogPath, sw.Elapsed.TotalSeconds);
        }
        return new RenderResult(false, exitCode, Retryable: !nonRetryable,
            firstError ?? $"aerender exited with code {exitCode}",
            tail.ToString(), fullLogPath, sw.Elapsed.TotalSeconds);
    }

    /// <summary>
    /// §7.3: outputDir is created before launch; a pre-existing dir can hold
    /// frames from a previous crashed attempt, which aerender would otherwise
    /// leave interleaved with this attempt's. Safety guard: only files matching
    /// the job's own output pattern — its prefix *and* its extension — are ever
    /// deleted.
    ///
    /// The extension is not optional. The version folder is shared with the
    /// preview stage, whose MOV and MP4 are built from the same basename
    /// (preview.ts: `{outputDir}/{base}.mov`), so prefix alone also matches
    /// them. A version folder can legitimately be rendered into twice — the
    /// output path is keyed on the shot's manually-set version, not on the
    /// export — and on a no-preview re-render (Export.skipPreview) the media
    /// that gets inherited is precisely the MOV sitting in this folder.
    /// Deleting it left the export pointing at a file that no longer existed,
    /// and delivery silently packaged the EXRs without their viewing copy.
    /// </summary>
    internal static void PrepareOutputDir(string outputDirLocal, string outputPattern)
    {
        Directory.CreateDirectory(outputDirLocal);
        var pattern = SequencePattern.FromOutputPattern(outputPattern);
        if (string.IsNullOrEmpty(pattern.Prefix)) return;
        foreach (var file in Directory.EnumerateFiles(outputDirLocal))
        {
            if (pattern.MatchesOutputFile(Path.GetFileName(file)))
            {
                try { File.Delete(file); } catch { /* locked leftovers surface as an aerender error */ }
            }
        }
    }

    private static void KillTree(Process process)
    {
        try
        {
            if (!process.HasExited) process.Kill(entireProcessTree: true);
        }
        catch { /* already gone */ }
    }

    private static async Task WaitForExitSafe(Process process)
    {
        try { await process.WaitForExitAsync(new CancellationTokenSource(TimeSpan.FromSeconds(30)).Token); }
        catch { try { process.Kill(entireProcessTree: true); } catch { } }
    }
}

/// <summary>Ring buffer of the last N output lines (§5.3 logTail).</summary>
public sealed class LogTail
{
    private readonly Queue<string> _lines;
    private readonly int _capacity;

    public LogTail(int capacity)
    {
        _capacity = capacity;
        _lines = new Queue<string>(capacity);
    }

    public void Add(string line)
    {
        _lines.Enqueue(line);
        while (_lines.Count > _capacity) _lines.Dequeue();
    }

    public override string ToString() => string.Join('\n', _lines);
}