97246bcbc3
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>
138 lines
4.3 KiB
C#
138 lines
4.3 KiB
C#
using VFXReviewWorker;
|
|
using Xunit;
|
|
|
|
namespace VFXReviewWorker.Tests;
|
|
|
|
/// <summary>
|
|
/// Recorded-transcript tests (§17.2): lines below are representative aerender
|
|
/// stdout from AE 2024/2025/2026 successes, errors, and stalls.
|
|
/// </summary>
|
|
public class ProgressParserTests
|
|
{
|
|
[Theory]
|
|
[InlineData("PROGRESS: 0:00:02:03 (51): 0 Seconds", 51)]
|
|
[InlineData("PROGRESS: 2 (2): 1 Seconds", 2)]
|
|
[InlineData("PROGRESS: 0:00:00:00 (1): 12 Seconds", 1)]
|
|
[InlineData("PROGRESS: 0:00:04:23 (120): 3 Seconds", 120)]
|
|
public void ParsesProgressFrames(string line, int expected)
|
|
{
|
|
Assert.Equal(expected, ProgressParser.ParseFrame(line));
|
|
}
|
|
|
|
[Theory]
|
|
[InlineData("PROGRESS: Rendering frame data")]
|
|
[InlineData("Starting composition \"UNG_106_010_020_cmp\".")]
|
|
[InlineData("aerender version 24.3x52")]
|
|
[InlineData("")]
|
|
public void IgnoresNonFrameLines(string line)
|
|
{
|
|
Assert.Null(ProgressParser.ParseFrame(line));
|
|
}
|
|
|
|
[Theory]
|
|
[InlineData("aerender ERROR: An existing connection was forcibly closed")]
|
|
[InlineData("aerender ERROR -1610153464: After Effects error")]
|
|
[InlineData("ERROR: Unable to open project")]
|
|
[InlineData("aerender SYNTAX ERROR: Illegal argument flag: false")]
|
|
public void DetectsErrorLines(string line)
|
|
{
|
|
Assert.True(ProgressParser.IsErrorLine(line));
|
|
}
|
|
|
|
[Fact]
|
|
public void ProgressLineIsNotAnError()
|
|
{
|
|
Assert.False(ProgressParser.IsErrorLine("PROGRESS: 0:00:02:03 (51): 0 Seconds"));
|
|
}
|
|
|
|
[Theory]
|
|
[InlineData("aerender ERROR: After Effects error: layer source file is missing or inaccessible")]
|
|
[InlineData("aerender ERROR: No comp was found with the given name.")]
|
|
[InlineData("aerender ERROR: project file could not be opened")]
|
|
[InlineData("WARNING: Missing footage in comp")]
|
|
[InlineData("aerender SYNTAX ERROR: Illegal argument flag: false")]
|
|
public void DeterministicErrorsAreNonRetryable(string line)
|
|
{
|
|
Assert.True(ProgressParser.IsNonRetryableError(line));
|
|
}
|
|
|
|
[Theory]
|
|
[InlineData("aerender ERROR: An existing connection was forcibly closed")]
|
|
[InlineData("aerender ERROR -1610153464: After Effects crashed")]
|
|
public void TransientErrorsStayRetryable(string line)
|
|
{
|
|
Assert.False(ProgressParser.IsNonRetryableError(line));
|
|
}
|
|
}
|
|
|
|
public class EtaCalculatorTests
|
|
{
|
|
[Fact]
|
|
public void NoFramesMeansNoEstimate()
|
|
{
|
|
var eta = new EtaCalculator();
|
|
Assert.Null(eta.EstimateSeconds(100));
|
|
}
|
|
|
|
[Fact]
|
|
public void EstimatesFromRollingAverage()
|
|
{
|
|
var eta = new EtaCalculator();
|
|
var t = DateTimeOffset.UtcNow;
|
|
eta.RecordFrame(t);
|
|
eta.RecordFrame(t.AddSeconds(2));
|
|
eta.RecordFrame(t.AddSeconds(4)); // 2 s/frame average
|
|
Assert.Equal(20, eta.EstimateSeconds(10));
|
|
}
|
|
|
|
[Fact]
|
|
public void ZeroRemainingMeansNoEstimate()
|
|
{
|
|
var eta = new EtaCalculator();
|
|
var t = DateTimeOffset.UtcNow;
|
|
eta.RecordFrame(t);
|
|
eta.RecordFrame(t.AddSeconds(1));
|
|
Assert.Null(eta.EstimateSeconds(0));
|
|
}
|
|
|
|
[Fact]
|
|
public void RollingWindowDropsOldFrames()
|
|
{
|
|
var eta = new EtaCalculator(windowSize: 2);
|
|
var t = DateTimeOffset.UtcNow;
|
|
eta.RecordFrame(t);
|
|
eta.RecordFrame(t.AddSeconds(100)); // old slow frame, will roll out
|
|
eta.RecordFrame(t.AddSeconds(101));
|
|
eta.RecordFrame(t.AddSeconds(102)); // window now [1, 1]
|
|
Assert.Equal(10, eta.EstimateSeconds(10));
|
|
}
|
|
}
|
|
|
|
public class LogTailTests
|
|
{
|
|
[Fact]
|
|
public void KeepsOnlyLastNLines()
|
|
{
|
|
var tail = new LogTail(3);
|
|
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;
|
|
}
|
|
}
|