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.
This commit is contained in:
@@ -37,6 +37,36 @@ public sealed record VirtualTagEvalResult(bool Success, object? Value, string? R
|
||||
public static VirtualTagEvalResult Failure(string reason) => new(false, null, reason);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Failure reasons the script evaluators put on <see cref="VirtualTagEvalResult.Failure"/> and that
|
||||
/// callers / tests classify on. The two evaluators — <c>RoslynVirtualTagEvaluator</c> (virtual tags)
|
||||
/// and <c>CalculationEvaluator</c> (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
|
||||
/// (<c>compile error:</c>, <c>sandbox violation:</c>, <c>script threw:</c>) stay inline.
|
||||
/// </summary>
|
||||
public static class ScriptEvalFailureReasons
|
||||
{
|
||||
/// <summary>
|
||||
/// The evaluator's one-shot retry was exhausted: a SECOND concurrent apply-boundary
|
||||
/// <c>ClearCompiledScripts</c> disposed the compiled script inside the same evaluation. This is the
|
||||
/// documented, well-formed outcome of losing that race twice — distinct from an
|
||||
/// <see cref="ObjectDisposedException"/> escaping to the generic catch as <c>"script threw: …"</c>,
|
||||
/// which is a bug.
|
||||
/// </summary>
|
||||
public const string EvaluatorDisposedDuringEvaluation = "evaluator disposed during evaluation";
|
||||
|
||||
/// <summary>
|
||||
/// Prefix of the wall-clock-timeout failure; the evaluator completes it with the budget it applied
|
||||
/// (<c>"{seconds:F1}s"</c>). Note the timeout covers the enqueue too — <c>TimedScriptEvaluator</c>
|
||||
/// starts its clock at <c>WaitAsync</c>, not when the inner <c>Task.Run</c> gets a thread — so on a
|
||||
/// starved pool this reason can mean "never got to run", not "ran too long".
|
||||
/// </summary>
|
||||
public const string TimedOutPrefix = "script timed out after ";
|
||||
}
|
||||
|
||||
/// <summary>Returns <see cref="VirtualTagEvalResult.NoChange"/> from every call. Bound by default
|
||||
/// when the production <c>VirtualTagEngine</c> adapter hasn't been registered (Mac dev, tests).</summary>
|
||||
public sealed class NullVirtualTagEvaluator : IVirtualTagEvaluator
|
||||
|
||||
@@ -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)
|
||||
{
|
||||
|
||||
@@ -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)
|
||||
{
|
||||
|
||||
+50
-27
@@ -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);
|
||||
}
|
||||
|
||||
/// <summary>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 <c>"script threw: Cannot access a
|
||||
/// disposed object…"</c> — is a raw ObjectDisposedException leaking past the retry, i.e. the bug.</summary>
|
||||
private const string RetryExhaustedReason = "evaluator disposed during evaluation";
|
||||
|
||||
/// <summary>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.</summary>
|
||||
@@ -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: <b>no raw disposed-script failure ever ESCAPES the
|
||||
/// retry</b>. Every failure this race produces must be the documented retry-exhaustion outcome
|
||||
/// (<see cref="RetryExhaustedReason"/>) 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.</para>
|
||||
/// retry</b>. 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:</para>
|
||||
/// <list type="bullet">
|
||||
/// <item><see cref="ScriptEvalFailureReasons.EvaluatorDisposedDuringEvaluation"/> — the documented
|
||||
/// retry-exhaustion outcome (two clears inside one evaluation).</item>
|
||||
/// <item><see cref="ScriptEvalFailureReasons.TimedOutPrefix"/> — <b>the second residual vector, and it
|
||||
/// is a starvation symptom, not a disposed-race escape.</b> This test deliberately saturates the thread
|
||||
/// pool (hundreds of <c>Task.Run</c> enqueues per second from 12 loops plus a spinning clear loop), and
|
||||
/// <c>TimedScriptEvaluator</c> starts its clock at <c>WaitAsync</c> rather than when the inner
|
||||
/// <c>Task.Run</c> 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.</item>
|
||||
/// </list>
|
||||
///
|
||||
/// <para><b>The workload is duration-bounded, and that is the SECOND timing assumption removed.</b> The
|
||||
/// loops used to run a fixed 12 × 400 = 4800 evaluations against a fixed 45 s <c>WaitAsync</c> budget.
|
||||
@@ -435,7 +438,7 @@ public sealed class RoslynVirtualTagEvaluatorTests
|
||||
/// box simply lands fewer evaluations instead of blowing a budget; the 45 s <c>WaitAsync</c> is left in
|
||||
/// place purely as a hang detector, with 4× headroom over the window it now guards.</para>
|
||||
///
|
||||
/// <para><b>Calibration of the exhaustion bound (be sceptical of it).</b> The disposed-race did NOT
|
||||
/// <para><b>Calibration of both bounds (be sceptical of them).</b> 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.</para></summary>
|
||||
/// 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.</para></summary>
|
||||
[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<RoslynVirtualTagEvaluator>.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");
|
||||
}
|
||||
|
||||
/// <summary>Reads the count of the private compiled-script cache via reflection. The cache is a
|
||||
|
||||
Reference in New Issue
Block a user