From 84cbec2d19a7971a4bd33a82cf8bbfe59582d220 Mon Sep 17 00:00:00 2001 From: gramps Date: Fri, 16 Oct 2026 19:02:14 -0700 Subject: [PATCH] =?UTF-8?q?FramePumpTests:=20thread-safe=20log=20sink=20?= =?UTF-8?q?=E2=80=94=20the=20full-suite=20failure=20was=20a=20test=20race?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 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 (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. --- MyMistakes.md | 14 ++++++++++++++ ytLive.Tests/FramePumpTests.cs | 10 +++++++--- 2 files changed, 21 insertions(+), 3 deletions(-) diff --git a/MyMistakes.md b/MyMistakes.md index 054f24a..a47e29b 100644 --- a/MyMistakes.md +++ b/MyMistakes.md @@ -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` 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` (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 diff --git a/ytLive.Tests/FramePumpTests.cs b/ytLive.Tests/FramePumpTests.cs index 96db11b..249a2f7 100644 --- a/ytLive.Tests/FramePumpTests.cs +++ b/ytLive.Tests/FramePumpTests.cs @@ -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 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? options = null, Func? scene = null, Func? resolve = null, - List? log = null, + ConcurrentBag? 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(); + var log = new ConcurrentBag(); 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(); + var log = new ConcurrentBag(); var epoch = 0L; using var pump = NewPump(encoder, scene: () => scene, log: log, resolve: e => {