From 1696e34868ec5ae100e068e0604951bc59f3a4ab Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Wed, 11 Nov 2026 03:50:12 -0500 Subject: [PATCH] test(scripting): stuck-orphan quarantine test trusts the guard's young/stuck verdict, not the test's stopwatch (#843) Reproduced 4/10 alone under 28 CPU burners (load ~100-250): outcomes were timeout, refused, refused, quarantined... - the guard right, but the test labelled a refusal 'young' only if its OWN stopwatch (started before the first trigger) read < 600 ms, and the first trigger's dispatch + sibling + cadence ate that. A ScriptRunRefusedException IS the young-orphan answer (behind a stuck orphan the guard quarantines instead), so: any refusal before the quarantine proves the rule; stuck factor 50 (3 s) so the second trigger lands young with room; loop until three quarantined answers; the one remaining wall-clock check runs the safe way (quarantine time on the test's stopwatch >= threshold - the orphan is never older than it); runaway is a held spin so it cannot end on its own; failures print the timeline. After: 10/10 under the same load. Co-Authored-By: Claude --- .../ScriptRunGuardTests.cs | 85 +++++++++++++------ 1 file changed, 60 insertions(+), 25 deletions(-) diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs index 2e9b656dc..d7c4bb7f4 100644 --- a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs @@ -162,7 +162,7 @@ public sealed class ScriptRunGuardTests /// while(true) script on a 1 Hz trigger leaked one pool thread per trigger — 30 orphans after 30 /// triggers, trending toward pool starvation. Now the first trigger's orphan is the only one; later /// triggers are refused while it is young, and once it has run longer than - /// × the timeout (10 × 60 ms here — the + /// × the timeout (50 × 60 ms here — the /// trigger cadence is scaled down from 1 Hz to keep the test short) the next refusal quarantines it. /// A healthy sibling keeps evaluating throughout (the positive control an absence assertion needs). /// @@ -171,44 +171,79 @@ public sealed class ScriptRunGuardTests /// / ): moves with /// every parallel test class on a loaded machine, so it is kept as a coarse secondary check only — /// it must stay far below the 30 the leak would have produced. + /// lmxopcua#843 (failed 2/4 full-suite runs at load average 140–280; 2 of the first 4 runs alone under + /// 28 CPU burners): this used to label a refusal "young" by the TEST's stopwatch, started before the first + /// trigger, and demand one inside 600 ms (10 × 60 ms). Under load the first trigger's dispatch, the sibling + /// and the cadence ate those 600 ms, so the guard's answers were timeout, refused, refused, + /// quarantined… — the guard right, the test's label wrong. Now: the guard is the authority on the + /// orphan's age (a IS the young-orphan answer; behind a stuck one + /// it quarantines instead), the stuck factor is 50 (3 s) so the second trigger has ample room to land + /// while the orphan is young, the loop runs until the quarantine instead of a fixed 30 triggers, and the + /// one wall-clock check left runs the safe way round — the orphan is never older than the test's + /// stopwatch, so a quarantine before 3 s on it is early on any box. The runaway is a HELD spin (released + /// at the end) so it cannot end on its own and become a second dispatch on a slow box. /// [Fact] public async Task Runaway_script_leaves_one_orphan_is_quarantined_once_stuck_and_a_sibling_keeps_evaluating() { - var guard = new ScriptRunGuard(); - using var spin = Compile(SpinScript); + const double stuckFactor = 50; + var guard = new ScriptRunGuard(new ScriptingOptions { StuckOrphanQuarantineFactor = stuckFactor }); + using var spin = Compile(BriefSpinScript); using var fast = Compile(FastScript); var ct = TestContext.Current.CancellationToken; + var held = new FakeScriptContext(); var threadsBefore = ThreadPool.ThreadCount; - var stuckAfter = ShortTimeout * ScriptingOptions.DefaultStuckOrphanQuarantineFactor; // 600 ms + var stuckAfter = ShortTimeout * stuckFactor; // 3 s var healthyResults = new List(); var outcomes = new List(); + var timeline = new List(); + TimeSpan? quarantinedAt = null; var sw = System.Diagnostics.Stopwatch.StartNew(); - for (var trigger = 0; trigger < 30; trigger++) + try { - try { await Run(guard, "runaway", SpinScript, spin, ShortTimeout, ct); outcomes.Add("value"); } - catch (ScriptTimeoutException) { outcomes.Add("timeout"); } - catch (ScriptRunRefusedException) { outcomes.Add(sw.Elapsed < stuckAfter ? "refused-young" : "refused"); } - catch (ScriptQuarantinedException) { outcomes.Add("quarantined"); } + // At least 30 triggers (the leak's scale), then until three quarantined answers; capped as a hang guard. + for (var trigger = 0; trigger < 1_000 && (trigger < 30 || outcomes.Count(o => o == "quarantined") < 3); trigger++) + { + string outcome; + try { await Run(guard, "runaway", BriefSpinScript, spin, ShortTimeout, ct, held); outcome = "value"; } + catch (ScriptTimeoutException) { outcome = "timeout"; } + catch (ScriptRunRefusedException) { outcome = "refused"; } + catch (ScriptQuarantinedException) { outcome = "quarantined"; quarantinedAt ??= sw.Elapsed; } + outcomes.Add(outcome); + timeline.Add($"#{trigger} {outcome} @{sw.ElapsedMilliseconds}ms"); - healthyResults.Add(await Run(guard, "healthy", FastScript, fast, ct: ct)); - await Task.Delay(50, ct); + healthyResults.Add(await Run(guard, "healthy", FastScript, fast, ct: ct)); + await Task.Delay(50, ct); + } + + var triggers = outcomes.Count; + var diagnostics = $"timeline: {string.Join(", ", timeline)}"; + guard.InFlightCount.ShouldBe(1, "exactly one orphaned run — the first trigger's — may be executing; " + diagnostics); + guard.StartedRunCount.ShouldBe(1 + triggers, "one dispatch for the runaway script, one per trigger for the healthy sibling; " + diagnostics); + outcomes[0].ShouldBe("timeout", diagnostics); + var firstQuarantine = outcomes.IndexOf("quarantined"); + firstQuarantine.ShouldBeGreaterThan(0, "the stuck orphan was never quarantined; " + diagnostics); + outcomes.Take(firstQuarantine).Skip(1).ShouldAllBe(o => o == "refused", diagnostics); + outcomes.Take(firstQuarantine).ShouldContain("refused", + "a young orphan is only refused — a short overrun is not quarantined; " + diagnostics); + outcomes.Skip(firstQuarantine).ShouldAllBe(o => o == "quarantined", diagnostics); + quarantinedAt!.Value.ShouldBeGreaterThanOrEqualTo(stuckAfter, + $"the orphan is never older than the test's stopwatch, so a quarantine before {stuckFactor}x the budget on it is early; " + diagnostics); + guard.IsQuarantined("runaway", out var reason).ShouldBeTrue("the orphan outlived its stuck threshold"); + reason!.ShouldContain("stuck"); + guard.QuarantinedCount.ShouldBe(1); + healthyResults.ShouldAllBe(v => v == 42); + healthyResults.Count.ShouldBe(triggers); + + var threadDelta = ThreadPool.ThreadCount - threadsBefore; + threadDelta.ShouldBeLessThan(15, $"{triggers} leaked orphans would have grown the pool by ~{triggers} threads"); } - - guard.InFlightCount.ShouldBe(1, "exactly one orphaned run — the first trigger's — may be executing"); - guard.StartedRunCount.ShouldBe(1 + 30, "one dispatch for the runaway script, thirty for the healthy sibling"); - outcomes[0].ShouldBe("timeout"); - outcomes.ShouldContain("refused-young", "a young orphan is only refused — a short overrun is not quarantined"); - guard.IsQuarantined("runaway", out var reason).ShouldBeTrue("the orphan outlived 10x its budget: it is stuck"); - reason!.ShouldContain("stuck"); - outcomes[^1].ShouldBe("quarantined"); - guard.QuarantinedCount.ShouldBe(1); - healthyResults.ShouldAllBe(v => v == 42); - healthyResults.Count.ShouldBe(30); - - var threadDelta = ThreadPool.ThreadCount - threadsBefore; - threadDelta.ShouldBeLessThan(15, "thirty leaked orphans would have grown the pool by ~30 threads"); + finally + { + held.Released = true; + } + await WaitForIdle(guard); } ///