FramePumpTests: thread-safe log sink — the full-suite failure was a test race

The suite failed Stats_ReportRealRendersAndDistinctWebcamFrames_NotJustPaddedSubmits
with "Collection was modified; enumeration operation may not execute" at its OWN
log.Any(...) line (FramePumpTests.cs:606): the test handed FramePump a plain
List<string> and enumerated it from the test thread while the pump reported stats
from its loop thread — pacingDelay is Task.Yield(), so the loop really is concurrent.
Production passes the thread-safe AppLog, so the app was never involved.

It passed 3/3 in isolation, which is exactly how a data race presents as a
load-sensitive flake. The trigger: the previous commit ("Per-element composite timing
+ scene dump") added log lines emitted FROM the pump thread, raising the collision
rate from rare to routine — a latent race in the old test, promoted by the new
traffic.

Fix: ConcurrentBag<string> (enumeration is a moment-in-time snapshot) for the sink,
2 call sites + the NewPump parameter. No app code touched.

Proof: full suite 428/428 passed, 0 warnings (the run that surfaced the failure was
before the fix; the same failure has not recurred).

Docs in the same commit: MyMistakes.md — "A 'known failure' label without a recorded
cause = a bug on life support" gained this second instance, with the rule that a
test failing ONLY under load means a shared mutable collection on the producer's
thread, not a retry.
This commit is contained in:
2026-10-16 19:02:14 -07:00
parent a3a4681aac
commit 84cbec2d19
2 changed files with 21 additions and 3 deletions
+14
View File
@@ -746,6 +746,20 @@ Rules derived:
for the producer before blaming the test.
3. Catch-and-log-swallow of `ex.Message` hides root causes; log with stack (`AppLog.Write(ex,
...)`) and throttle (5s) instead of dropping or flooding.
**Second instance (2026-10-16) — a "timing flake" that was a test-side data race.** A full-suite run
failed `FramePumpTests.Stats_ReportRealRendersAndDistinctWebcamFrames_NotJustPaddedSubmits`; it passed
3/3 in isolation, which is exactly how a load-sensitive flake presents. It was not timing:
`System.InvalidOperationException: Collection was modified; enumeration operation may not execute` at
the test's own `log.Any(...)` line — the test handed `FramePump` a plain `List<string>` and enumerated
it from the test thread while the pump reported stats from its loop thread (`pacingDelay` is
`Task.Yield()`, so the loop really is concurrent). The app was innocent (production passes the
thread-safe `AppLog`). Fix: `ConcurrentBag<string>` (snapshot enumeration). **The lesson that produced
it:** the previous commit ADDED log lines from the pump thread, which raised the collision rate from
rare to routine — a latent race is promoted to a routine failure by any change that increases the
frequency of the shared access, and the failure then looks like a flake in the new code rather than a
race in the old test. When a test fails ONLY under load, check for a shared mutable collection on the
producer's thread before reaching for a retry.
Bonus: the "failing" test encoded the MAP's contract (`loopbackGain = GameAudioVolume`); the
code had drifted to unity on a disproven premise (loopback capture does NOT follow endpoint
volume — creator's 20%-volume/pegged-meter observation killed it). The test was right all
+7 -3
View File
@@ -1,3 +1,4 @@
using System.Collections.Concurrent;
using System.Net;
using System.Text;
using System.Text.RegularExpressions;
@@ -74,9 +75,12 @@ public class FramePumpTests
return scene;
}
// The log sink must be thread-safe: FramePump reports stats from its OWN loop thread while
// the test enumerates this collection (a plain List<string> threw "Collection was modified"
// under full-suite load — the pump's extra parts/scene-dump lines made it fire far more often).
private static FramePump NewPump(FakeEncoder encoder, Func<EncoderOptions?>? options = null,
Func<Scene?>? scene = null, Func<SceneElement, VideoFrame?>? resolve = null,
List<string>? log = null,
ConcurrentBag<string>? log = null,
Func<(VideoFrame? Frame, SocialBarPosition Position)>? socialBar = null)
{
return new FramePump(
@@ -197,7 +201,7 @@ public class FramePumpTests
public async Task Start_WithoutRtmpUrl_SkipsEncoder()
{
var encoder = new FakeEncoder();
var log = new List<string>();
var log = new ConcurrentBag<string>();
using var pump = NewPump(encoder, options: () => null, log: log);
await pump.StartAsync();
@@ -589,7 +593,7 @@ public class FramePumpTests
var scene = new Scene { Name = "Live" };
scene.Elements.Add(new WebcamSceneConfig { Name = "Webcam", IsVisible = true });
var encoder = new FakeEncoder();
var log = new List<string>();
var log = new ConcurrentBag<string>();
var epoch = 0L;
using var pump = NewPump(encoder, scene: () => scene, log: log, resolve: e =>
{