fix(blender): read carriage-return progress, and let any output prove liveness

Blender renders failed with "produced no output for 600s" on every
attempt while rendering perfectly well.

Two causes, both mine. BeginOutputReadLine raises an event per newline,
and Blender writes its render status with a carriage return so it
overwrites one line in place — a frame taking longer than the stall
timeout emits no newline for its whole duration. stdout is now read as a
character stream with CR and LF both ending a line.

The watchdog was also stricter than its own message: it only accepted a
recognised Fra:/Saved: line as a sign of life, so any output we were not
parsing counted as silence. Any output now proves Blender is alive, which
is what "produced no output" is asking; finished frames still drive
progress, since a single frame emits hundreds of status updates.

Also passes -noaudio: a render node has no sound device, and initialising
audio under a session-less service account is a known way to hang.

Covered by tests over a realistic stdout chunk where progress is
CR-separated and only the saved lines end in LF — newline-only splitting
yields one unusable blob and no progress at all.

Worker 1.5.1.

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

RenderWorker/VFXReviewWorker.Tests/BlenderProgressParserTests.cs

@@ -0,0 +1,92 @@
+using System.Text;
+using VFXReviewWorker;
+using Xunit;
+
+namespace VFXReviewWorker.Tests;
+
+/// <summary>
+/// Blender writes its render status with a carriage return so it overwrites one
+/// line in the terminal, and only emits a newline when a frame is saved. A
+/// reader that splits on newlines alone therefore sees nothing at all while a
+/// long frame renders — which had the stall watchdog killing healthy jobs.
+/// </summary>
+public class BlenderProgressParserTests
+{
+    [Theory]
+    [InlineData("Fra:1042 Mem:512.00M (Peak 640.00M) | Time:00:12.34 | Path Tracing Sample 12/128", 1042)]
+    [InlineData("Fra:1 Mem:64.00M | Syncing Cube", 1)]
+    [InlineData("Saved: 'X:/renders/frame_1042.exr'", null)]
+    [InlineData("Blender quit", null)]
+    public void ParsesTheFrameBeingRendered(string line, int? expected)
+    {
+        Assert.Equal(expected, BlenderProgressParser.ParseFrame(line));
+    }
+
+    [Theory]
+    [InlineData("Saved: 'X:/renders/frame_1042.exr'", "X:/renders/frame_1042.exr")]
+    [InlineData(" Saved: 'nope'", null)] // leading space: not the real form
+    [InlineData("Fra:1042 Mem:512.00M", null)]
+    public void ParsesSavedFrames(string line, string? expected)
+    {
+        Assert.Equal(expected, BlenderProgressParser.ParseSaved(line));
+    }
+
+    [Fact]
+    public void TreatsAMissingBlendAsNonRetryable()
+    {
+        const string line = "Error: Cannot read file 'X:/gone.blend': No such file or directory";
+        Assert.True(BlenderProgressParser.IsErrorLine(line));
+        Assert.True(BlenderProgressParser.IsNonRetryableError(line));
+    }
+
+    [Fact]
+    public void TreatsAnUnknownFailureAsRetryable()
+    {
+        const string line = "Error: CUDA device lost, out of memory";
+        Assert.True(BlenderProgressParser.IsErrorLine(line));
+        Assert.False(BlenderProgressParser.IsNonRetryableError(line));
+    }
+
+    /// <summary>
+    /// The regression itself: a realistic stdout chunk where progress is
+    /// separated by CR and only the saved lines end in LF.
+    /// </summary>
+    [Fact]
+    public void CarriageReturnProgressIsSeenWithoutWaitingForANewline()
+    {
+        var stdout =
+            "Fra:1001 Mem:64.00M | Sample 1/128\r" +
+            "Fra:1001 Mem:120.00M | Sample 64/128\r" +
+            "Fra:1001 Mem:128.00M | Sample 128/128\r" +
+            "\nSaved: 'X:/renders/frame_1001.exr'\n" +
+            "Fra:1002 Mem:128.00M | Sample 1/128\r";
+
+        var lines = SplitLikeThePump(stdout);
+
+        var frames = lines.Select(BlenderProgressParser.ParseFrame).Where(f => f is not null).ToList();
+        var saved = lines.Select(BlenderProgressParser.ParseSaved).Where(s => s is not null).ToList();
+
+        // Four status updates and one saved frame; splitting on "\n" alone
+        // would have yielded a single unusable blob and no progress at all.
+        Assert.Equal(4, frames.Count);
+        Assert.Single(saved);
+        Assert.Equal(1002, frames[^1]);
+    }
+
+    /// <summary>Mirrors BlenderRunner.PumpAsync: CR and LF both end a line.</summary>
+    private static List<string> SplitLikeThePump(string text)
+    {
+        var lines = new List<string>();
+        var current = new StringBuilder();
+        foreach (var c in text)
+        {
+            if (c == '\r' || c == '\n')
+            {
+                if (current.Length > 0) { lines.Add(current.ToString()); current.Clear(); }
+            }
+            else current.Append(c);
+        }
+        if (current.Length > 0) lines.Add(current.ToString());
+        return lines;
+    }
+}

RenderWorker/VFXReviewWorker/BlenderRunner.cs

@@ -45,7 +45,9 @@ public sealed class BlenderRunner
 
         // Argument order matters to Blender: everything before -a configures the
         // render, and -a must come last or it renders with the old settings.
-        var args = new List<string> { "-b", blendLocal };
+        // -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))
         {
@@ -143,19 +145,21 @@ public sealed class BlenderRunner
                 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)
-            {
-                // A frame line only proves Blender is alive; a long frame emits
-                // many of them, so this feeds the stall watchdog, not progress.
-                currentFrame = frame.Value;
-                lastProgressAt = DateTimeOffset.UtcNow;
-            }
+            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++;
-                lastProgressAt = DateTimeOffset.UtcNow;
-                eta.RecordFrame(lastProgressAt);
+                eta.RecordFrame(DateTimeOffset.UtcNow);
             }
             if ((isStderr || BlenderProgressParser.IsErrorLine(line)) && !string.IsNullOrWhiteSpace(line))
             {
@@ -164,9 +168,6 @@ public sealed class BlenderRunner
             }
         }
 
-        process.OutputDataReceived += (_, e) => HandleLine(e.Data, isStderr: false);
-        process.ErrorDataReceived += (_, e) => HandleLine(e.Data, isStderr: true);
-
         try
         {
             process.Start();
@@ -177,8 +178,17 @@ public sealed class BlenderRunner
                 $"Failed to launch Blender at {_options.BlenderPath}: {ex.Message}",
                 tail.ToString(), fullLogPath, 0);
         }
-        process.BeginOutputReadLine();
-        process.BeginErrorReadLine();
+
+        // 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)
         {
@@ -219,6 +229,9 @@ public sealed class BlenderRunner
         }
 
         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(); }
 
@@ -248,6 +261,46 @@ public sealed class BlenderRunner
         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 { }

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.0</Version>
+    <Version>1.5.1</Version>
   </PropertyGroup>
 
   <ItemGroup>