From 837d8a17eb034356632dae4056d675712f4e6de2 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 18 Aug 2026 08:05:51 -0400 Subject: [PATCH] test(scripting): timeout under starvation is not a leak; share the exhaustion-reason constant Review follow-ups to 34829ea0. IMPORTANT - the leak filter had its own flake vector. This test saturates the thread pool by design, and TimedScriptEvaluator starts its 5s clock at WaitAsync rather than when the inner Task.Run gets a thread, so a legitimately-enqueued evaluation can blow the budget while still queued and surface "script timed out after 5.0s". The reason != exhaustion filter classified that as a raw disposed escape and hard-failed on it - handing the test back the load-fragility the reshape removed. Timeouts are now their own bucket, tolerated and rate-bounded exactly as exhaustions are; a raw disposed escape still fails on first occurrence. Doc-comment names this second residual vector alongside the exhaustion calibration. MINOR (scope extension authorised by review) - "evaluator disposed during evaluation" existed as three unshared literals. Promoted to ScriptEvalFailureReasons alongside VirtualTagEvalResult in Commons.Engines (the assembly all three already reference) and referenced from both evaluators and the test. The timeout prefix joins it, since the test now classifies on it too. String values are byte-identical - no behaviour change. Falsified: with a 12ms script budget the race produced real timeouts (3/2695). Classified as leaks (the pre-review filter) they hard-failed the test 6/6 items; bucketed as starvation they sit 0.11% under the 10% bound and the test is green. --- .../Engines/IVirtualTagEvaluator.cs | 30 ++++++++ .../CalculationEvaluator.cs | 5 +- .../Engines/RoslynVirtualTagEvaluator.cs | 5 +- .../RoslynVirtualTagEvaluatorTests.cs | 77 ++++++++++++------- 4 files changed, 86 insertions(+), 31 deletions(-) diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Commons/Engines/IVirtualTagEvaluator.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Commons/Engines/IVirtualTagEvaluator.cs index 78d5ff4a..7864246c 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Commons/Engines/IVirtualTagEvaluator.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Commons/Engines/IVirtualTagEvaluator.cs @@ -37,6 +37,36 @@ public sealed record VirtualTagEvalResult(bool Success, object? Value, string? R public static VirtualTagEvalResult Failure(string reason) => new(false, null, reason); } +/// +/// Failure reasons the script evaluators put on and that +/// callers / tests classify on. The two evaluators — RoslynVirtualTagEvaluator (virtual tags) +/// and CalculationEvaluator (calc tags) — are deliberate mirrors of one another, so these +/// strings are a shared contract rather than two coincidentally-equal literals. They lived as three +/// unshared copies (the two evaluators plus a test const); a reader could not tell the contracts were +/// meant to be identical, and drift on one side would silently break a classifier keyed on the other. +/// Only the reasons something outside the evaluator matches on live here — the purely descriptive ones +/// (compile error:, sandbox violation:, script threw:) stay inline. +/// +public static class ScriptEvalFailureReasons +{ + /// + /// The evaluator's one-shot retry was exhausted: a SECOND concurrent apply-boundary + /// ClearCompiledScripts disposed the compiled script inside the same evaluation. This is the + /// documented, well-formed outcome of losing that race twice — distinct from an + /// escaping to the generic catch as "script threw: …", + /// which is a bug. + /// + public const string EvaluatorDisposedDuringEvaluation = "evaluator disposed during evaluation"; + + /// + /// Prefix of the wall-clock-timeout failure; the evaluator completes it with the budget it applied + /// ("{seconds:F1}s"). Note the timeout covers the enqueue too — TimedScriptEvaluator + /// starts its clock at WaitAsync, not when the inner Task.Run gets a thread — so on a + /// starved pool this reason can mean "never got to run", not "ran too long". + /// + public const string TimedOutPrefix = "script timed out after "; +} + /// Returns from every call. Bound by default /// when the production VirtualTagEngine adapter hasn't been registered (Mac dev, tests). public sealed class NullVirtualTagEvaluator : IVirtualTagEvaluator diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationEvaluator.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationEvaluator.cs index b3f069cf..b2077008 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationEvaluator.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationEvaluator.cs @@ -148,7 +148,8 @@ public sealed class CalculationEvaluator : IScriptCacheOwner, IDisposable } catch (ScriptTimeoutException) { - return VirtualTagEvalResult.Failure($"script timed out after {_runTimeout.TotalSeconds:F1}s"); + return VirtualTagEvalResult.Failure( + $"{ScriptEvalFailureReasons.TimedOutPrefix}{_runTimeout.TotalSeconds:F1}s"); } catch (ObjectDisposedException) when (!_disposed && attempt == 0) { @@ -159,7 +160,7 @@ public sealed class CalculationEvaluator : IScriptCacheOwner, IDisposable } catch (ObjectDisposedException) { - return VirtualTagEvalResult.Failure("evaluator disposed during evaluation"); + return VirtualTagEvalResult.Failure(ScriptEvalFailureReasons.EvaluatorDisposedDuringEvaluation); } catch (Exception ex) { diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Engines/RoslynVirtualTagEvaluator.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Engines/RoslynVirtualTagEvaluator.cs index 2391bd56..2e028c28 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Host/Engines/RoslynVirtualTagEvaluator.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Host/Engines/RoslynVirtualTagEvaluator.cs @@ -136,7 +136,8 @@ public sealed class RoslynVirtualTagEvaluator : IVirtualTagEvaluator, IScriptCac } catch (ScriptTimeoutException) { - return VirtualTagEvalResult.Failure($"script timed out after {_runTimeout.TotalSeconds:F1}s"); + return VirtualTagEvalResult.Failure( + $"{ScriptEvalFailureReasons.TimedOutPrefix}{_runTimeout.TotalSeconds:F1}s"); } catch (ObjectDisposedException) when (!_disposed && attempt == 0) { @@ -148,7 +149,7 @@ public sealed class RoslynVirtualTagEvaluator : IVirtualTagEvaluator, IScriptCac } catch (ObjectDisposedException) { - return VirtualTagEvalResult.Failure("evaluator disposed during evaluation"); + return VirtualTagEvalResult.Failure(ScriptEvalFailureReasons.EvaluatorDisposedDuringEvaluation); } catch (Exception ex) { diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs index df2bf96c..c25bbdb9 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs @@ -5,6 +5,7 @@ using Serilog; using Serilog.Events; using Shouldly; using Xunit; +using ZB.MOM.WW.OtOpcUa.Commons.Engines; using ZB.MOM.WW.OtOpcUa.Commons.Messages.Logging; using ZB.MOM.WW.OtOpcUa.Core.Scripting; using ZB.MOM.WW.OtOpcUa.Host.Engines; @@ -380,12 +381,6 @@ public sealed class RoslynVirtualTagEvaluatorTests CompiledCacheCount(sut).ShouldBe(1); } - /// The one reason string the evaluator is documented to surface when its one-shot retry - /// is exhausted (a SECOND apply-boundary clear landing inside the same evaluation). Anything else - /// carrying "disposed" — notably the pre-fix generic escape "script threw: Cannot access a - /// disposed object…" — is a raw ObjectDisposedException leaking past the retry, i.e. the bug. - private const string RetryExhaustedReason = "evaluator disposed during evaluation"; - /// How long the racing loops below keep hammering the evaluator. A DURATION rather than a /// fixed iteration count: every clear forces a recompile, so a fixed workload's wall-clock cost tracks /// whatever CPU the box has left, and a busy box then blows the test's own hang budget. @@ -417,12 +412,20 @@ public sealed class RoslynVirtualTagEvaluatorTests /// swaps one timing assumption for a safer one — it stays load-sensitive, and needs machinery to /// measure latency at runtime. Instead the assertion now targets the invariant the retry actually /// guarantees, which is timing-independent: no raw disposed-script failure ever ESCAPES the - /// retry. Every failure this race produces must be the documented retry-exhaustion outcome - /// () and nothing else — a "script threw: Cannot access a disposed - /// object…" (the generic-catch escape) fails the test on the first occurrence, however loaded the box - /// is. A loose upper bound on the exhaustion RATE keeps the assertion non-vacuous: a build whose retry - /// never absorbs anything (every raced evaluation exhausting straight to the documented reason) would - /// pass a shape-only check, so exhaustions must stay a small minority of all evaluations. + /// retry. A "script threw: Cannot access a disposed object…" (the generic-catch escape) fails the + /// test on the first occurrence, however loaded the box is. Everything else this race can legitimately + /// produce is bucketed and rate-bounded rather than banned, which keeps the check non-vacuous — a build + /// whose retry never absorbs anything would otherwise sail through a shape-only assertion: + /// + /// — the documented + /// retry-exhaustion outcome (two clears inside one evaluation). + /// — the second residual vector, and it + /// is a starvation symptom, not a disposed-race escape. This test deliberately saturates the thread + /// pool (hundreds of Task.Run enqueues per second from 12 loops plus a spinning clear loop), and + /// TimedScriptEvaluator starts its clock at WaitAsync rather than when the inner + /// Task.Run gets a thread — so a perfectly healthy evaluation can blow the 5 s budget while still + /// queued. Classifying that as a leak would hand the test back the load-fragility this reshape removed. + /// /// /// The workload is duration-bounded, and that is the SECOND timing assumption removed. The /// loops used to run a fixed 12 × 400 = 4800 evaluations against a fixed 45 s WaitAsync budget. @@ -435,7 +438,7 @@ public sealed class RoslynVirtualTagEvaluatorTests /// box simply lands fewer evaluations instead of blowing a budget; the 45 s WaitAsync is left in /// place purely as a hang detector, with 4× headroom over the window it now guards. /// - /// Calibration of the exhaustion bound (be sceptical of it). The disposed-race did NOT + /// Calibration of both bounds (be sceptical of them). The disposed-race did NOT /// reproduce at all on the arm64 macOS dev box this reshape was written on — zero failures in isolation, /// zero under concurrently-running Runtime.Tests / Host.Tests / OpcUaServer suites, and still zero with /// the product's one-shot retry experimentally disabled, i.e. the fetch→run window never opened there @@ -444,12 +447,16 @@ public sealed class RoslynVirtualTagEvaluatorTests /// old fire-on-the-first-failure assertion. Exhaustion needs a clear inside BOTH the first attempt's /// window and the retry's, so its rate goes as the square of the single-window hit rate — 10% of /// evaluations exhausting implies roughly a third of them hitting a disposed evaluator on the first - /// try, which is a broken retry, not a busy machine. If a loaded box ever does trip THIS bound, the - /// rate itself is the finding: record it before widening the number. + /// try, which is a broken retry, not a busy machine. The starvation-timeout bucket gets the same bound + /// for the same reason: a handful of queued-too-long evaluations is the environment, but 10% of them + /// missing a 5 s budget means the evaluator stopped evaluating. If a loaded box ever does trip EITHER + /// bound, the rate itself is the finding: record it before widening the number. [Fact] public async Task Evaluate_racing_ClearCompiledScripts_never_leaks_a_raw_disposed_failure() { - // Generous timeout so the wall-clock budget never fires and confounds the race assertion. + // Generous script budget so the wall-clock timeout rarely fires and confounds the race assertion — + // "rarely", not "never": it covers the Task.Run enqueue, so a starved pool can still blow it. That + // residual is bucketed and bounded below rather than treated as a disposed-race escape. using var sut = new RoslynVirtualTagEvaluator( NullLogger.Instance, NoOpScriptRoot(), TimeSpan.FromSeconds(5)); const string expr = "return (int)ctx.GetTag(\"a\").Value + 1;"; @@ -497,23 +504,39 @@ public sealed class RoslynVirtualTagEvaluatorTests await Task.WhenAll(evalLoops.Append(clearLoop)) .WaitAsync(TimeSpan.FromSeconds(45), TestContext.Current.CancellationToken); - // (1) The invariant: nothing but the documented retry-exhaustion outcome may surface. A raw + var totalEvaluations = Volatile.Read(ref evaluated); + // Loose by design, with an absolute floor so a starved run (few evaluations landed) cannot trip on + // a single occurrence. See the doc-comment: broken-behaviour detectors, not timing gates. + var rateBound = Math.Max(totalEvaluations / 10, 8); + + var exhausted = failures.Count(r => r == ScriptEvalFailureReasons.EvaluatorDisposedDuringEvaluation); + var starved = failures.Count(r => r.StartsWith(ScriptEvalFailureReasons.TimedOutPrefix, StringComparison.Ordinal)); + + // (1) The invariant, and the only assertion that fires on a single occurrence: a raw // ObjectDisposedException escaping the retry (pre-fix: "script threw: Cannot access a - // disposed object…") lands here, as does any other unexpected failure mode. - var leaked = failures.Where(reason => reason != RetryExhaustedReason).ToArray(); + // disposed object…") lands here, as does any other unexpected failure mode. The two + // legitimate outcomes above are excluded — they are rate-bounded instead, below. + var leaked = failures + .Where(r => r != ScriptEvalFailureReasons.EvaluatorDisposedDuringEvaluation) + .Where(r => !r.StartsWith(ScriptEvalFailureReasons.TimedOutPrefix, StringComparison.Ordinal)) + .ToArray(); leaked.ShouldBeEmpty( - $"a racing ClearCompiledScripts must never surface anything but \"{RetryExhaustedReason}\"; " + - $"observed: {string.Join(" | ", leaked)}"); + "a racing ClearCompiledScripts must never surface a failure other than " + + $"\"{ScriptEvalFailureReasons.EvaluatorDisposedDuringEvaluation}\" or " + + $"\"{ScriptEvalFailureReasons.TimedOutPrefix}…\"; observed: {string.Join(" | ", leaked)}"); // (2) Non-vacuity: the retry must actually be absorbing the race, not merely relabelling it. - // Loose by design (see the doc-comment) — a broken-retry detector, not a timing gate. The - // absolute floor keeps a starved run (few evaluations landed) from tripping on a single one. - var exhausted = failures.Count; - var totalEvaluations = Volatile.Read(ref evaluated); exhausted.ShouldBeLessThan( - Math.Max(totalEvaluations / 10, 8), - $"the one-shot retry must absorb the overwhelming majority of raced clears; " + + rateBound, + "the one-shot retry must absorb the overwhelming majority of raced clears; " + $"{exhausted}/{totalEvaluations} evaluations exhausted it"); + + // (3) The starvation bucket is tolerated but not unbounded — at 10% the evaluator has stopped + // evaluating rather than the box being busy. + starved.ShouldBeLessThan( + rateBound, + "queue-starvation timeouts are expected under this stress but must stay marginal; " + + $"{starved}/{totalEvaluations} evaluations missed the 5s budget"); } /// Reads the count of the private compiled-script cache via reflection. The cache is a