pinto/vfxreview
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

fix(worker): Blender jobs always failed with "Collection was modified"

Browse Source 
LogTail was read by the progress loop while the output pumps appended to
it. Blender rewrites its status line many times a second, so the first
progress report of every job threw; aerender hit the same race only rarely.
LogTail now locks internally.

The exception also escaped BlenderRunner without ending the process, leaving
blender.exe rendering unsupervised on the node on every failed attempt. Any
unexpected exception in the monitor loop now kills the process tree.

Bump worker to 1.6.2.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
twotalesanimation
2026-09-18 04:21:54 +02:00
parent 400cf3f6ea
commit 97246bcbc3
4 changed files with 109 additions and 62 deletions
Download Patch File Download Diff File Expand all files Collapse all files
RenderWorker/VFXReviewWorker.Tests/ProgressParserTests.cs
+17
View File
@@ -117,4 +117,21 @@ public class LogTailTests
for (var i = 1; i <= 5; i++) tail.Add($"line {i}");
Assert.Equal("line 3\nline 4\nline 5", tail.ToString());
}
[Fact]
public async Task ReadingWhileAnotherThreadWritesDoesNotThrow()
{
// The Blender runner's output pumps add lines while its progress loop
// reads the tail; unsynchronised this threw "Collection was modified".
var tail = new LogTail(200);
using var stop = new CancellationTokenSource(TimeSpan.FromSeconds(1));
var writer = Task.Run(() =>
{
var i = 0;
while (!stop.IsCancellationRequested) tail.Add($"Fra:1001 Sample {i++}/128");
});
while (!stop.IsCancellationRequested) _ = tail.ToString();
await writer;
}
}
RenderWorker/VFXReviewWorker/AerenderRunner.cs
+18 -4
View File
@@ -280,11 +280,19 @@ public sealed class AerenderRunner
}
}
/// <summary>Ring buffer of the last N output lines (§5.3 logTail).</summary>
/// <summary>
/// Ring buffer of the last N output lines (§5.3 logTail).
///
/// Thread-safe: output readers add lines while the progress loop reads the
/// tail for its report. Unsynchronised, ToString enumerates the queue while a
/// reader enqueues and throws "Collection was modified" — Blender, which
/// writes a status line many times a second, hit this on every job.
/// </summary>
public sealed class LogTail
{
private readonly Queue<string> _lines;
private readonly int _capacity;
private readonly object _gate = new();
public LogTail(int capacity)
{
@@ -294,9 +302,15 @@ public sealed class LogTail
public void Add(string line)
{
_lines.Enqueue(line);
while (_lines.Count > _capacity) _lines.Dequeue();
lock (_gate)
{
_lines.Enqueue(line);
while (_lines.Count > _capacity) _lines.Dequeue();
}
}
public override string ToString() => string.Join('\n', _lines);
public override string ToString()
{
lock (_gate) return string.Join('\n', _lines);
}
}
RenderWorker/VFXReviewWorker/BlenderRunner.cs
+73 -57
View File
@@ -190,75 +190,91 @@ public sealed class BlenderRunner
PumpAsync(process.StandardError, line => HandleLine(line, isStderr: true)),
};
while (!process.HasExited)
try
{
await Task.Delay(TimeSpan.FromSeconds(2), CancellationToken.None);
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;
}
if (cancelJob.IsCancellationRequested || shutdown.IsCancellationRequested)
async Task<RenderResult> MonitorAsync()
{
while (!process.HasExited)
{
_log.LogWarning("Cancellation requested — killing Blender tree for job {JobId}", jobId);
KillTree(process);
cancelledByServer = cancelJob.IsCancellationRequested;
break;
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;
}
}
}
if ((DateTimeOffset.UtcNow - lastProgressAt).TotalSeconds > config.StallTimeoutSeconds)
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)
{
_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)",
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);
}
if ((DateTimeOffset.UtcNow - lastReportAt).TotalSeconds >= 10)
// 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)
{
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;
}
return new RenderResult(false, 0, Retryable: false,
"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);
}
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,
"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>
RenderWorker/VFXReviewWorker/VFXReviewWorker.csproj
+1 -1
View File
@@ -15,7 +15,7 @@
every change that gets published. publish.ps1 appends the git SHA via
SourceRevisionId, giving "1.1.0+feb1c7b".
-->
<Version>1.6.1</Version>
<Version>1.6.2</Version>
</PropertyGroup>
<ItemGroup>