From e89ac2df331f0e8e7c7d9b84b65f1add6e25be86 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Wed, 11 Nov 2026 05:09:36 -0500 Subject: [PATCH] fix(scripting): the run guard frees a script's slot before its run completes, not in a continuation (#843) RoslynVirtualTagEvaluatorTests' race test failed 1 of 3 full Host integration runs under 28 CPU burners (load ~300) with 24 of 4,800 evaluations refused 'previous evaluation still running' - impossible for one sequential loop per id unless a finished run still held its slot after the caller resumed. It did: ScriptRunGuard released the slot from a ContinueWith on the run task, and a task is observably complete before its continuations run, so the next run of the key (the next trigger, or the evaluator's immediate retry after a raced ObjectDisposedException) could be refused - a Bad publish for a script that had finished. Same class #789 fixed for the out-of-process runner. The release (and the late allocation-breach quarantine, now ahead of it) runs in the run's own finally, before the task completes; the continuation only disposes the CTS and observes the fault. New ScriptRunGuardTests.A_caller_that_awaited_its_run_is_never_refused_by_it widens the release with a test hook (SlotReleasingForTest) - mutation-checked: releasing from a continuation again refuses 49 of 50. The race test now prints elapsed / evaluations / clears / pool state / failure histogram on every assertion and on its hang detector. After: 3/3 full Host integration runs pass under the same load. Core.Scripting 298, ScriptedAlarms 109, Calculation 84 green. Co-Authored-By: Claude --- .../ScriptRunGuard.cs | 41 ++++++++++++++----- .../ScriptRunGuardTests.cs | 34 +++++++++++++++ .../RoslynVirtualTagEvaluatorTests.cs | 41 ++++++++++++++++--- 3 files changed, 100 insertions(+), 16 deletions(-) diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs index 276730286..ccce6c8bb 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs @@ -105,6 +105,13 @@ public sealed class ScriptRunGuard _logger = logger ?? Log.Logger; } + /// + /// Test seam (lmxopcua#843): invoked on the run's own thread just before its slot is released, with the key. + /// A sleep here widens the release window, so a test can prove the release is ordered before the caller + /// resumes rather than winning a race. + /// + internal Action? SlotReleasingForTest { get; set; } + /// Raised (on the thread that detected it) when a script is quarantined. public event EventHandler? Quarantined; @@ -233,34 +240,46 @@ public sealed class ScriptRunGuard Volatile.Write(ref state.RunStartedTimestamp, Stopwatch.GetTimestamp()); started.TrySetResult(); var before = GC.GetAllocatedBytesForCurrentThread(); + var succeeded = false; try { // ScriptEvaluator.RunAsync executes the compiled delegate synchronously and returns a completed // task, so the after-sample is taken on the same thread, right after the script returned. var pending = evaluator.RunAsync(context, runToken); slot.AllocatedBytes = GC.GetAllocatedBytesForCurrentThread() - before; - return await pending.ConfigureAwait(false); + var value = await pending.ConfigureAwait(false); + succeeded = true; + return value; } catch { slot.AllocatedBytes = GC.GetAllocatedBytesForCurrentThread() - before; throw; } + finally + { + // Release the slot when the run REALLY finishes — which for an abandoned run is long after + // RunAsync has thrown ScriptTimeoutException — and BEFORE runTask completes (lmxopcua#843). This + // used to be a ContinueWith on runTask: a task is observably complete before its continuations + // run, so a caller that saw the completion (e.g. the virtual-tag evaluator's immediate retry after a + // raced ObjectDisposedException, or simply the next trigger) could + // start the key's NEXT run while this one still held the slot and be refused "previous + // evaluation still running" — a Bad publish for a script that had finished. Seen under load: + // 24 of 4,800 sequential same-key evaluations. A late-finishing orphan that breached the + // allocation budget quarantines its key first, so no re-trigger slips in between. + if (succeeded && BreachedBudget(slot.AllocatedBytes)) + Quarantine(key, state, AllocationReason(slot.AllocatedBytes), "allocation"); + SlotReleasingForTest?.Invoke(key); + Volatile.Write(ref state.RunStartedTimestamp, 0); + Interlocked.Exchange(ref state.InFlight, 0); + Interlocked.Decrement(ref _inFlight); + } }); - // Release the slot when the run REALLY finishes — which for an abandoned run is long after this - // method has thrown ScriptTimeoutException. Registered before the wait so it fires regardless of - // which way the wait below comes out. A late-finishing orphan that breached the allocation budget - // still quarantines its key here. _ = runTask.ContinueWith(t => { - Volatile.Write(ref state.RunStartedTimestamp, 0); - Interlocked.Exchange(ref state.InFlight, 0); - Interlocked.Decrement(ref _inFlight); runCts.Dispose(); if (t.IsFaulted) _ = t.Exception; // observed below by the awaiter when it is still listening - if (t.IsCompletedSuccessfully && BreachedBudget(slot.AllocatedBytes)) - Quarantine(key, state, AllocationReason(slot.AllocatedBytes), "allocation"); }, CancellationToken.None, TaskContinuationOptions.ExecuteSynchronously, TaskScheduler.Default); // The budget clock starts when the pool starts the run, not when we queued it (P5): pool starvation @@ -313,7 +332,7 @@ public sealed class ScriptRunGuard && !string.Equals(state.SourceIdentity, sourceIdentity, StringComparison.Ordinal)) { // The script changed under this key: start from a clean slate. The old state's orphan (if any) - // releases the GLOBAL in-flight count through its own continuation; nothing else references it. + // releases the GLOBAL in-flight count when it finishes; nothing else references it. _keys.TryUpdate(key, new KeyState(sourceIdentity), state); continue; } 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 d7c4bb7f4..b1c264511 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 @@ -61,6 +61,40 @@ public sealed class ScriptRunGuardTests guard.IsQuarantined("vt-1", out _).ShouldBeFalse(); } + /// + /// lmxopcua#843: a caller that awaited its run is never refused by it. The slot used to be released by a + /// ContinueWith on the run task — and a task is observably complete before its continuations run, so the + /// caller (or the evaluator's immediate ODE retry) could start the key's next run while the finished one still + /// held the slot: "previous evaluation still running", 24 of 4,800 sequential evaluations in the Host + /// integration suite under load. The second phase makes every release slow (the hook sleeps inside it), so + /// the ordering, not luck, is what keeps the caller from being refused. Mutation check: release from a + /// continuation again and the second phase goes red. + /// + [Fact] + public async Task A_caller_that_awaited_its_run_is_never_refused_by_it() + { + var guard = new ScriptRunGuard(); + using var fast = Compile(FastScript); + var ct = TestContext.Current.CancellationToken; + var refused = new List(); + for (var i = 0; i < 500; i++) + { + try { (await Run(guard, "seq", FastScript, fast, ct: ct)).ShouldBe(42); } + catch (ScriptRunRefusedException) { refused.Add($"#{i}"); } + } + refused.ShouldBeEmpty(); + + guard.SlotReleasingForTest = _ => Thread.Sleep(5); + for (var i = 0; i < 50; i++) + { + try { (await Run(guard, "seq", FastScript, fast, ct: ct)).ShouldBe(42); } + catch (ScriptRunRefusedException) { refused.Add($"slow release #{i}"); } + } + refused.ShouldBeEmpty(); + guard.RefusedWhileRunningCount.ShouldBe(0); + guard.InFlightCount.ShouldBe(0); + } + [Fact] public async Task A_timed_out_run_throws_ScriptTimeoutException_and_keeps_the_slot_held_by_the_orphan() { 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 47ac617a1..70dcd87f9 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs @@ -466,6 +466,19 @@ public sealed class RoslynVirtualTagEvaluatorTests /// 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. + /// + /// lmxopcua#843 — this test found a product bug, not a timing assumption. Under the full Host + /// integration suite plus 28 CPU burners (load ~300) it failed 1 run in 3 with 24 of 4,800 evaluations + /// refused "previous evaluation still running" — impossible for one sequential loop per id unless the + /// id's previous run still held its slot after its caller had resumed. It did: + /// the slot was released by a continuation on the run task, and a task is observably complete before its + /// continuations run (worst for the evaluator's immediate retry after a raced + /// ). The release now happens inside the run, before it completes + /// (ScriptRunGuardTests.A_caller_that_awaited_its_run_is_never_refused_by_it pins the ordering). A + /// refusal stays in the "leaked" bucket on purpose. The doc above predates P5: the guard's budget clock + /// starts when the pool starts the run, so a queued evaluation no longer lands in the timed-out bucket. + /// Every assertion now prints the run's shape (elapsed, evaluations, clears, pool state, failure histogram). + /// [Fact] public async Task Evaluate_racing_ClearCompiledScripts_never_leaks_a_raw_disposed_failure() { @@ -511,19 +524,37 @@ public sealed class RoslynVirtualTagEvaluatorTests Interlocked.Decrement(ref remaining); }, TestContext.Current.CancellationToken)).ToArray(); + var clears = 0L; var clearLoop = Task.Run(() => { while (Volatile.Read(ref remaining) > 0) { sut.ClearCompiledScripts(); + Interlocked.Increment(ref clears); Thread.SpinWait(4000); // ~tens of µs between clears — frequent, but not back-to-back } }, TestContext.Current.CancellationToken); + // lmxopcua#843: every assertion below carries the run's shape, so a failure under load says which bucket + // moved and how starved the box was (it passed 5/5 on rerun with nothing recorded). + var elapsed = System.Diagnostics.Stopwatch.StartNew(); + string Diagnostics() => + $" [elapsed {elapsed.ElapsedMilliseconds} ms, {Volatile.Read(ref evaluated)} evaluations, " + + $"{Interlocked.Read(ref clears)} clears, loops still running {Volatile.Read(ref remaining)}, " + + $"pool threads {ThreadPool.ThreadCount} / pending {ThreadPool.PendingWorkItemCount}; failures: " + + string.Join(", ", failures.GroupBy(r => r.Length > 80 ? r[..80] : r).Select(g => $"{g.Count()}× \"{g.Key}\"")) + "]"; + // Hang detector only: the loops self-terminate at RaceWindow, so firing this means something // wedged, not that the box was slow. - await Task.WhenAll(evalLoops.Append(clearLoop)) - .WaitAsync(TimeSpan.FromSeconds(45), TestContext.Current.CancellationToken); + try + { + await Task.WhenAll(evalLoops.Append(clearLoop)) + .WaitAsync(TimeSpan.FromSeconds(45), TestContext.Current.CancellationToken); + } + catch (TimeoutException ex) + { + throw new TimeoutException("the racing loops did not finish within 45 s" + Diagnostics(), ex); + } var totalEvaluations = Volatile.Read(ref evaluated); // Loose by design, with an absolute floor so a starved run (few evaluations landed) cannot trip on @@ -544,20 +575,20 @@ public sealed class RoslynVirtualTagEvaluatorTests leaked.ShouldBeEmpty( "a racing ClearCompiledScripts must never surface a failure other than " + $"\"{ScriptEvalFailureReasons.EvaluatorDisposedDuringEvaluation}\" or " + - $"\"{ScriptEvalFailureReasons.TimedOutPrefix}…\"; observed: {string.Join(" | ", leaked)}"); + $"\"{ScriptEvalFailureReasons.TimedOutPrefix}…\"; observed: {string.Join(" | ", leaked)}" + Diagnostics()); // (2) Non-vacuity: the retry must actually be absorbing the race, not merely relabelling it. exhausted.ShouldBeLessThan( rateBound, "the one-shot retry must absorb the overwhelming majority of raced clears; " + - $"{exhausted}/{totalEvaluations} evaluations exhausted it"); + $"{exhausted}/{totalEvaluations} evaluations exhausted it" + Diagnostics()); // (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"); + $"{starved}/{totalEvaluations} evaluations missed the 5s budget" + Diagnostics()); } // ── input quality reaches the script (archreview 02/S14) ────────────────────────────────