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 <noreply@anthropic.com>
2026-11-11 05:09:36 -05:00
parent 4cd648b029
commit e89ac2df33
3 changed files with 100 additions and 16 deletions
@@ -105,6 +105,13 @@ public sealed class ScriptRunGuard
        _logger = logger ?? Log.Logger;
    }

+    /// <summary>
+    ///     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.
+    /// </summary>
+    internal Action<string>? SlotReleasingForTest { get; set; }
+
    /// <summary>Raised (on the thread that detected it) when a script is quarantined.</summary>
    public event EventHandler<ScriptQuarantinedEventArgs>? 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;
            }
@@ -61,6 +61,40 @@ public sealed class ScriptRunGuardTests
        guard.IsQuarantined("vt-1", out _).ShouldBeFalse();
    }

+    /// <summary>
+    ///     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.
+    /// </summary>
+    [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<string>();
+        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()
    {
@@ -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.</para></summary>
+    /// <remarks>
+    ///     <b>lmxopcua#843 — this test found a product bug, not a timing assumption.</b> 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 <c>"previous evaluation still running"</c> — impossible for one sequential loop per id unless the
+    ///     id's previous run still held its <see cref="ScriptRunGuard"/> 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
+    ///     <see cref="ObjectDisposedException"/>). The release now happens inside the run, before it completes
+    ///     (<c>ScriptRunGuardTests.A_caller_that_awaited_its_run_is_never_refused_by_it</c> 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).
+    /// </remarks>
    [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) ────────────────────────────────