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