From 708e8a0d8fc152975e469a4ba0b46669a4867e37 Mon Sep 17 00:00:00 2001 From: twotalesanimation <80506065+twotalesanimation@users.noreply.github.com> Date: Fri, 18 Sep 2026 04:42:33 +0200 Subject: [PATCH] fix(worker): parse Blender 5.x output so rendered frames are counted Blender 5 logs through CLOG, prefixing every line with elapsed time and a category ("00:02.954 render | Saved: '...'"), and reports errors as "ERROR ..." instead of "Error: ...". The parser anchored on "Saved:" at the start of the line, so it counted no frames from a render that wrote all of them and the job failed as "saved no frames". Progress (Fra:) and error detection were dead on 5.x for the same reason. The prefix is now stripped before matching; 4.x output parses as before. Warnings no longer count as errors: add-ons print them on every launch and one would otherwise be reported as the reason a render failed. A run that saves nothing now reports Blender's own error when there is one. Verified on the real DH2 test.blend under Blender 5.2: the 1.6.2 parser counts 0 of 3 saved frames, this one counts 3. Bump worker to 1.6.3. Co-Authored-By: Claude Opus 5 --- .../BlenderProgressParserTests.cs | 40 +++++++++++++++++++ .../VFXReviewWorker/BlenderProgressParser.cs | 30 +++++++++++--- RenderWorker/VFXReviewWorker/BlenderRunner.cs | 4 +- .../VFXReviewWorker/VFXReviewWorker.csproj | 2 +- 4 files changed, 69 insertions(+), 7 deletions(-) diff --git a/RenderWorker/VFXReviewWorker.Tests/BlenderProgressParserTests.cs b/RenderWorker/VFXReviewWorker.Tests/BlenderProgressParserTests.cs index e9a1b09..9e3b86c 100644 --- a/RenderWorker/VFXReviewWorker.Tests/BlenderProgressParserTests.cs +++ b/RenderWorker/VFXReviewWorker.Tests/BlenderProgressParserTests.cs @@ -73,6 +73,46 @@ public class BlenderProgressParserTests Assert.Equal(1002, frames[^1]); } + /// + /// Blender 5.x prefixes every line with elapsed time and a log category. + /// Anchored on "Saved:", the parser counted no frames from a render that + /// wrote every one, and the job failed as "saved no frames". + /// These lines are verbatim Blender 5.2 output. + /// + [Fact] + public void ParsesBlender5PrefixedOutput() + { + Assert.Equal(@"X:\renders\frame_0001.png", + BlenderProgressParser.ParseSaved(@"00:02.954 render | Saved: 'X:\renders\frame_0001.png'")); + Assert.Equal(1, BlenderProgressParser.ParseFrame("00:02.469 render | Fra: 1 | Mem: 0M | Synchronizing object | Cube")); + Assert.Null(BlenderProgressParser.ParseSaved("00:02.954 render | Time: 00:00.87 (Saving: 00:00.14)")); + Assert.Null(BlenderProgressParser.ParseFrame("00:02.079 render | Rendering frame 1")); + } + + [Fact] + public void RecognisesBlender5Errors() + { + const string unwritable = @"00:03.063 reports | ERROR Render error (No such file or directory) cannot save: 'Q:\out\f_0001.png'"; + Assert.True(BlenderProgressParser.IsErrorLine(unwritable)); + Assert.True(BlenderProgressParser.IsNonRetryableError(unwritable)); + + const string missing = @"00:13.250 reports | ERROR Cannot read file ""X:\gone.blend"": No such file or directory"; + Assert.True(BlenderProgressParser.IsErrorLine(missing)); + Assert.True(BlenderProgressParser.IsNonRetryableError(missing)); + } + + /// + /// Add-ons print warnings on every launch; one must never become the + /// reported reason a render failed. + /// + [Theory] + [InlineData("Warning: add-on missing 'bl_info', this can cause poor performance!: 'G:\\addons\\x\\__init__.py'")] + [InlineData("00:01.000 addon | WARNING something harmless")] + public void WarningsAreNotErrors(string line) + { + Assert.False(BlenderProgressParser.IsErrorLine(line)); + } + /// Mirrors BlenderRunner.PumpAsync: CR and LF both end a line. private static List SplitLikeThePump(string text) { diff --git a/RenderWorker/VFXReviewWorker/BlenderProgressParser.cs b/RenderWorker/VFXReviewWorker/BlenderProgressParser.cs index a79a82b..72cacd0 100644 --- a/RenderWorker/VFXReviewWorker/BlenderProgressParser.cs +++ b/RenderWorker/VFXReviewWorker/BlenderProgressParser.cs @@ -8,18 +8,36 @@ namespace VFXReviewWorker; /// with "Saved: '...'". The saved lines are the reliable signal — a frame can /// be reported for a long time while it renders — so progress counts those and /// falls back to Fra: for a first sign of life. +/// +/// Blender 5.x logs through CLOG, which prefixes every line with an elapsed +/// time and a category ("00:02.954 render | Saved: '...'") and +/// reports errors as "ERROR ..." rather than "Error: ...". The prefix is +/// stripped before matching, so both formats parse the same way. /// public static partial class BlenderProgressParser { - [GeneratedRegex(@"^Fra:(\d+)", RegexOptions.Compiled)] + [GeneratedRegex(@"^(?:\d+:)?\d{2}:\d{2}\.\d{3}\s+\S+\s*\| ?", RegexOptions.Compiled)] + private static partial Regex LogPrefix(); + + [GeneratedRegex(@"^Fra:\s*(\d+)", RegexOptions.Compiled)] private static partial Regex FrameLine(); [GeneratedRegex(@"^Saved:\s*'(.+)'", RegexOptions.Compiled)] private static partial Regex SavedLine(); - [GeneratedRegex(@"^(Error|Warning): |^Error: ", RegexOptions.Compiled | RegexOptions.IgnoreCase)] + // Errors only. Warnings are not failures, and add-ons print them on every + // launch ("Warning: add-on missing 'bl_info'"), so counting them made an + // add-on's complaint the reported reason for a failed render. + [GeneratedRegex(@"(?i:^Error: )|^(ERROR|FATAL) ", RegexOptions.Compiled)] private static partial Regex ErrorLine(); + /// The line without Blender 5.x's "elapsed category | " prefix. + private static string Message(string line) + { + var m = LogPrefix().Match(line); + return m.Success ? line[m.Length..] : line; + } + /// /// Failures that will repeat identically on another machine — a missing /// file, an unknown scene, an unwritable output. Retrying these burns the @@ -35,7 +53,9 @@ public static partial class BlenderProgressParser "unknown scene", "scene not found", "unable to create directory", + "couldn't create directory", "cannot write file", + "cannot save:", "no camera", "python script fail", "unknown argument", @@ -44,18 +64,18 @@ public static partial class BlenderProgressParser /// The frame Blender is currently working on, or null. public static int? ParseFrame(string line) { - var m = FrameLine().Match(line); + var m = FrameLine().Match(Message(line)); return m.Success && int.TryParse(m.Groups[1].Value, out var f) ? f : null; } /// The path of a frame Blender has just written, or null. public static string? ParseSaved(string line) { - var m = SavedLine().Match(line); + var m = SavedLine().Match(Message(line)); return m.Success ? m.Groups[1].Value : null; } - public static bool IsErrorLine(string line) => ErrorLine().IsMatch(line); + public static bool IsErrorLine(string line) => ErrorLine().IsMatch(Message(line)); public static bool IsNonRetryableError(string line) { diff --git a/RenderWorker/VFXReviewWorker/BlenderRunner.cs b/RenderWorker/VFXReviewWorker/BlenderRunner.cs index f7b1733..9f2cfe1 100644 --- a/RenderWorker/VFXReviewWorker/BlenderRunner.cs +++ b/RenderWorker/VFXReviewWorker/BlenderRunner.cs @@ -268,7 +268,9 @@ public sealed class BlenderRunner 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", + 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); } diff --git a/RenderWorker/VFXReviewWorker/VFXReviewWorker.csproj b/RenderWorker/VFXReviewWorker/VFXReviewWorker.csproj index 862fbf0..ed9a71b 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.6.2 + 1.6.3