diff --git a/RenderWorker/VFXReviewWorker.Tests/BlenderProgressParserTests.cs b/RenderWorker/VFXReviewWorker.Tests/BlenderProgressParserTests.cs new file mode 100644 index 0000000..e9a1b09 --- /dev/null +++ b/RenderWorker/VFXReviewWorker.Tests/BlenderProgressParserTests.cs @@ -0,0 +1,92 @@ +using System.Text; +using VFXReviewWorker; +using Xunit; + +namespace VFXReviewWorker.Tests; + +/// +/// 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. +/// +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)); + } + + /// + /// The regression itself: a realistic stdout chunk where progress is + /// separated by CR and only the saved lines end in LF. + /// + [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]); + } + + /// Mirrors BlenderRunner.PumpAsync: CR and LF both end a line. + private static List SplitLikeThePump(string text) + { + var lines = new List(); + 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; + } +} diff --git a/RenderWorker/VFXReviewWorker/BlenderRunner.cs b/RenderWorker/VFXReviewWorker/BlenderRunner.cs index 512f3b9..7fa310f 100644 --- a/RenderWorker/VFXReviewWorker/BlenderRunner.cs +++ b/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 { "-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 { "-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); } + /// + /// 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 { } diff --git a/RenderWorker/VFXReviewWorker/VFXReviewWorker.csproj b/RenderWorker/VFXReviewWorker/VFXReviewWorker.csproj index 0371ffd..d5857d9 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.0 + 1.5.1