From ca30d17f948b7d490dc55e04b53ff29cf1d12984 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Sat, 15 Aug 2026 03:37:18 -0400 Subject: [PATCH 1/2] fix(test): replace the SandboxTests wall-clock cancellation pins with a deterministic edge MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Sandbox_LongRunningScript_TimesOut and Sandbox_InfiniteLoop_CancelledByToken armed a CancellationTokenSource for a fixed 100 ms / 500 ms and hoped it expired while the script body was still running. That is a race between a fixed timer and a fixed amount of work, not a synchronization, and it is wrong in both directions. Too slow a timer relative to the work and the script FINISHES first, so nothing is cancelled and ThrowsAnyAsync fails with "No exception was thrown". Measured on this machine: the bounded 100M-iteration loop takes 298 ms against the 100 ms pin — a 3x margin that a faster host closes, and that any move off the scripting default OptimizationLevel.Debug would close outright. Reproduced deterministically by shrinking the loop to 1M iterations: it ran in 76 ms and the test failed with exactly that message while all 27 siblings passed. Too fast a timer and the token is already cancelled before the body is entered — Roslyn's runner throws OperationCanceledException up front (verified with a pre-cancelled token) — so the test goes GREEN without the script's own in-loop ThrowIfCancellationRequested ever being reached. That vacuous pass is the worse half: it asserts nothing while looking healthy. Both now cancel deterministically. The script invokes an Action handed in through Parameters from inside its own loop; when that call returns the token is already cancelled ON THE SAME THREAD, so the next in-loop check is guaranteed to observe it, with ~10,000 checks still ahead of it. No wall clock, no host-speed or scheduler dependence — and the 600 ms of sleeping goes away. Sandbox_UncancelledScript_RunsToCompletion is added as the negative control: the same script with the signal wired to a no-op must run every iteration and return the closed-form sum, which is what establishes that the sibling's OCE is caused by the cancellation. Verified: the injection that killed the old test passes with the fix, and suppressing the cancellation entirely still fails it with the identical message, so the claim is unchanged in force. Test-only; the sandbox's cancellation behaviour is correct as written. --- .../Scripts/SandboxTests.cs | 107 ++++++++++++++---- 1 file changed, 88 insertions(+), 19 deletions(-) diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/SandboxTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/SandboxTests.cs index eb5aa9f8..fabd199b 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/SandboxTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/SandboxTests.cs @@ -216,14 +216,57 @@ public class SandboxTests Assert.True(result.IsSuccess); } - // ── Execution timeout ── + // ── Execution cancellation ── + // + // These two tests used to arm a wall-clock CancellationTokenSource + // (500 ms / 100 ms) and hope it expired while the script body was still + // running. That is a race between a fixed timer and a fixed amount of + // work, not a synchronization, and it is wrong in both directions: + // + // * Too slow a timer relative to the work and the script simply + // FINISHES first, so nothing is cancelled and ThrowsAnyAsync fails + // with "No exception was thrown". The bounded loop below was measured + // at 298 ms against a 100 ms pin on this machine — a 3x margin, which + // a faster host (or any change to the scripting OptimizationLevel, + // which is Debug today) closes. Reproduced deterministically by + // shrinking the loop to 1M iterations: it then ran in 76 ms and the + // test failed with exactly that message while all 27 siblings passed. + // * Too fast a timer and the token is ALREADY cancelled before the body + // is entered — Roslyn's runner throws OperationCanceledException up + // front (verified), so the test goes GREEN without the script's own + // in-loop ThrowIfCancellationRequested ever being reached. A vacuous + // pass is worse than a flake: it asserts nothing. + // + // Both are replaced with a deterministic edge. The script triggers the + // cancellation itself, synchronously, from inside its own loop via an + // Action handed in through Parameters. When that call returns, the token + // is already cancelled ON THE SAME THREAD, so the next in-loop check is + // guaranteed to observe it — with iterations to spare and no reliance on + // wall-clock time, host speed or scheduler behaviour. Sandbox_UncancelledScript_RunsToCompletion + // is the negative control for the bounded case. + + /// Builds globals whose "cancelNow" parameter cancels when the script invokes it. + private static ScriptGlobals GlobalsWithCancelHook(CancellationTokenSource cts, Action? onSignal = null) + => new() + { + Instance = null!, + Parameters = new ScriptParameters(new Dictionary + { + ["cancelNow"] = onSignal ?? (() => cts.Cancel()) + }), + CancellationToken = cts.Token + }; [Fact] public async Task Sandbox_InfiniteLoop_CancelledByToken() { - // Compile a script that loops forever + // An unbounded loop that cancels itself on the first pass, so the + // check on that same pass is the one that throws. var code = """ + var spins = 0; while (true) { + spins++; + if (spins == 1) ((Action)Parameters["cancelNow"]!)(); CancellationToken.ThrowIfCancellationRequested(); } return null; @@ -232,14 +275,8 @@ public class SandboxTests var result = _service.Compile("infinite", code); Assert.True(result.IsSuccess, "Infinite loop compiles but should be cancelled at runtime"); - // Execute with a short timeout - using var cts = new CancellationTokenSource(TimeSpan.FromMilliseconds(500)); - var globals = new ScriptGlobals - { - Instance = null!, - Parameters = new ScriptParameters(), - CancellationToken = cts.Token - }; + using var cts = new CancellationTokenSource(); + var globals = GlobalsWithCancelHook(cts); await Assert.ThrowsAnyAsync(async () => { @@ -250,11 +287,16 @@ public class SandboxTests [Fact] public async Task Sandbox_LongRunningScript_TimesOut() { - // A script that does heavy computation with cancellation checks + // Heavy bounded computation with periodic cancellation checks. It + // cancels itself at i == 1, leaving ~100M iterations and ~10,000 + // cancellation checks still ahead of it, so interruption is certain + // however fast the host runs — the point being that a long script + // does not get to run to completion once its deadline has fired. var code = """ - var sum = 0; + var sum = 0L; for (var i = 0; i < 100_000_000; i++) { sum += i; + if (i == 1) ((Action)Parameters["cancelNow"]!)(); if (i % 10000 == 0) CancellationToken.ThrowIfCancellationRequested(); } return sum; @@ -263,13 +305,8 @@ public class SandboxTests var result = _service.Compile("heavy", code); Assert.True(result.IsSuccess); - using var cts = new CancellationTokenSource(TimeSpan.FromMilliseconds(100)); - var globals = new ScriptGlobals - { - Instance = null!, - Parameters = new ScriptParameters(), - CancellationToken = cts.Token - }; + using var cts = new CancellationTokenSource(); + var globals = GlobalsWithCancelHook(cts); await Assert.ThrowsAnyAsync(async () => { @@ -277,6 +314,38 @@ public class SandboxTests }); } + [Fact] + public async Task Sandbox_UncancelledScript_RunsToCompletion() + { + // Negative control for Sandbox_LongRunningScript_TimesOut: the SAME + // script shape, with the signal wired to a no-op instead of Cancel(). + // It must run every iteration and return the closed-form sum. This is + // what proves the sibling's OperationCanceledException is caused by + // the cancellation and not by the loop being unreachable, the trust + // model rejecting the body, or the runner failing for its own reasons. + var code = """ + var sum = 0L; + for (var i = 0; i < 100_000_000; i++) { + sum += i; + if (i == 1) ((Action)Parameters["cancelNow"]!)(); + if (i % 10000 == 0) CancellationToken.ThrowIfCancellationRequested(); + } + return sum; + """; + + var result = _service.Compile("heavy-control", code); + Assert.True(result.IsSuccess); + + using var cts = new CancellationTokenSource(); + var signalled = false; + var globals = GlobalsWithCancelHook(cts, onSignal: () => signalled = true); + + var value = await result.CompiledScript!.RunAsync(globals, cts.Token); + + Assert.True(signalled, "The script's in-loop signal must actually fire."); + Assert.Equal(4999999950000000L, value.ReturnValue); + } + // ── Combined adversarial attempts ── [Fact] From 9fb52153fde8c61c88303f5e095e199103f904c2 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Sat, 15 Aug 2026 03:37:35 -0400 Subject: [PATCH 2/2] fix(test): order three more unsynchronized assertions behind the observables they follow MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Deferred flake-pattern sweep of tests/ for the class fixed in c4caebe9 and cfa6acbf — a bounded wait on observable A followed by a bare assert on an observable B that the product only reaches strictly after A. Three clear instances, each reproduced deterministically by delaying only the later step and each re-verified green with that same delay still injected. AlarmOnTriggerRuns_ShedAtTheSameCap_WithAnAlarmScopedSiteEvent gated on the rate-limited shed site event and then asserted the shed COUNT bare. AlarmActor.ShedAlarmRun increments the counter and only then emits the event, and the event fires on the first shed only — so the gate observed Flap(4)'s shed and ordered nothing with respect to Flap(5)'s, which is a separate mailbox message with no observable of its own (an alarm on-trigger run has no Ask caller to reply to, unlike ScriptActor.ShedRun, whose sibling test is correctly ordered by its ScriptCallResult and is left alone). Deferring Flap(5) by 2 s failed it with "Expected: 2 / Actual: 1". The count is now ACCUMULATED across polls rather than re-read, because SiteHealthCollector.CollectReport DRAINS the interval counters — a poll loop that simply re-read it would consume the first shed and never reach 2. EndToEnd_GrpcStubError_RowStays_Pending_NextTick_Succeeds gated on the central row arriving and then asserted bare that the site SQLite row had left Pending. SiteAuditTelemetryActor pushes via IngestAuditEventsAsync (which is what writes the central row) and calls MarkForwardedAsync only after parsing the ack. Delaying just that post-push step failed it with "Assert.DoesNotContain() Failure: Filter matched in collection". PreSnapshotBuffer_IsCapped_DropsOldest_AndCountsTheDrops gated on "Count >= cap" and then asserted "Count == cap + 1" bare — a gate strictly weaker than the assertion it guards, so it ordered nothing with respect to the last event of a FlushBuffer loop that delivers one at a time. Parking that loop after its 19,999th delivery failed it with "Expected: 20001 / Actual: 20000". Also hardens GrpcCentralTransportTests.WaitUntil, which returned silently on timeout; today's single caller re-asserts immediately, so this only sharpens the message rather than fixing a live flake. Cleared with evidence, not guessed: SiteAlarmLiveCacheService's LingerStop removes the site entry inside one lock, so IsLive and GetCurrentAlarms flip atomically; and SiteReconciliationActor walks response.Gap with a sequential foreach in which the asserted "Gone" log precedes the awaited "Good" row, the inverse of this class. Test-only; every ordering named above is correct as written. --- .../SyncCallEmissionEndToEndTests.cs | 22 ++++++++++++-- .../Grpc/DebugStreamBridgeActorTests.cs | 28 ++++++++++------- .../GrpcCentralTransportTests.cs | 9 ++++++ .../Actors/ScriptRunShedTests.cs | 30 +++++++++++++++++-- 4 files changed, 74 insertions(+), 15 deletions(-) diff --git a/tests/ZB.MOM.WW.ScadaBridge.AuditLog.Tests/Integration/SyncCallEmissionEndToEndTests.cs b/tests/ZB.MOM.WW.ScadaBridge.AuditLog.Tests/Integration/SyncCallEmissionEndToEndTests.cs index aa1278ce..2e7633ad 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.AuditLog.Tests/Integration/SyncCallEmissionEndToEndTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.AuditLog.Tests/Integration/SyncCallEmissionEndToEndTests.cs @@ -213,14 +213,32 @@ public class SyncCallEmissionEndToEndTests : TestKit, IClassFixture= 2, $"Expected at least one failed push + one successful push; saw {stubClient.CallCount} total client calls."); // The site SQLite row must have flipped to Forwarded after the // successful retry. ReadPendingAsync only returns Pending rows; the // row should NOT show up there anymore. - var stillPending = await sqliteWriter.ReadPendingAsync(64); - Assert.DoesNotContain(stillPending, p => p.EventId == evt.EventId); + // + // AwaitAssert, not a bare Assert: the drain marks rows forwarded only + // AFTER the push returns and its ack is parsed — SiteAuditTelemetryActor + // pushes via IngestAuditEventsAsync (which is what writes the central + // row) and only then calls MarkForwardedAsync. Observing the central row + // above therefore establishes no happens-before edge with the site-side + // state flip; on a loaded run the post-push continuation can be scheduled + // after the poll that saw the row, leaving it still Pending. Reproduced + // deterministically by delaying only that post-push step, which fails + // exactly this test with "Assert.DoesNotContain() Failure: Filter matched + // in collection". The bounded wait removes the ordering assumption only — + // the row must still actually leave Pending or the test fails as before. + await AwaitAssertAsync(async () => + { + var stillPending = await sqliteWriter.ReadPendingAsync(64); + Assert.DoesNotContain(stillPending, p => p.EventId == evt.EventId); + }, TimeSpan.FromSeconds(15)); } [SkippableFact] diff --git a/tests/ZB.MOM.WW.ScadaBridge.Communication.Tests/Grpc/DebugStreamBridgeActorTests.cs b/tests/ZB.MOM.WW.ScadaBridge.Communication.Tests/Grpc/DebugStreamBridgeActorTests.cs index dc652363..ad589474 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.Communication.Tests/Grpc/DebugStreamBridgeActorTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.Communication.Tests/Grpc/DebugStreamBridgeActorTests.cs @@ -964,18 +964,26 @@ public class DebugStreamBridgeActorTests : TestKit t.AddMilliseconds(-1)); ctx.BridgeActor.Tell(snapshot); - AwaitCondition(() => + // One awaited block, gated on the EXACT final count. This used to gate on + // "Count >= cap" and then assert "Count == cap + 1" bare — a gate strictly + // weaker than the assertion it guards, which therefore orders nothing with + // respect to the last event. FlushBuffer delivers the buffered events one + // by one via _onEvent inside a single loop, so the poll can legitimately + // observe the count crossing `cap` while the loop still has an event to + // go. Reproduced deterministically by parking that loop for 3 s after its + // 19,999th delivery: the bare form failed with "Expected: 20001 / Actual: + // 20000". The claims are unchanged — exactly the snapshot plus the capped + // retained events, with the newest survivor last. + AwaitAssert(() => { - lock (ctx.ReceivedEvents) { return ctx.ReceivedEvents.Count >= cap; } + lock (ctx.ReceivedEvents) + { + // Snapshot + exactly the retained (capped) events, and the newest survived. + Assert.Equal(cap + 1, ctx.ReceivedEvents.Count); + var lastAttr = ctx.ReceivedEvents.OfType().Last(); + Assert.Equal($"Attr{cap + overflow - 1}", lastAttr.AttributeName); + } }, TimeSpan.FromSeconds(10)); - - lock (ctx.ReceivedEvents) - { - // Snapshot + exactly the retained (capped) events, and the newest survived. - Assert.Equal(cap + 1, ctx.ReceivedEvents.Count); - var lastAttr = ctx.ReceivedEvents.OfType().Last(); - Assert.Equal($"Attr{cap + overflow - 1}", lastAttr.AttributeName); - } } [Fact] diff --git a/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/GrpcCentralTransportTests.cs b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/GrpcCentralTransportTests.cs index 3446bf90..d564e168 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/GrpcCentralTransportTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/GrpcCentralTransportTests.cs @@ -249,6 +249,13 @@ public class GrpcCentralTransportTests : IAsyncLifetime SourceScript: null, SiteEnqueuedAt: DateTimeOffset.UtcNow); + /// + /// Spins until holds, then asserts it — a bare + /// return on timeout would make every future caller's wait silently + /// vacuous. Today's single caller happens to re-assert immediately after, + /// so this only sharpens the failure message; it is here so the next caller + /// does not have to remember to. + /// private static async Task WaitUntil(Func condition, TimeSpan timeout) { var deadline = DateTime.UtcNow + timeout; @@ -261,6 +268,8 @@ public class GrpcCentralTransportTests : IAsyncLifetime await Task.Delay(25); } + + Assert.True(condition(), $"Condition was still false after waiting {timeout}."); } /// diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Actors/ScriptRunShedTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Actors/ScriptRunShedTests.cs index 18024441..da2fb127 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Actors/ScriptRunShedTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Actors/ScriptRunShedTests.cs @@ -177,17 +177,41 @@ public class ScriptRunShedTests : TestKit, IDisposable Flap(4); Flap(5); + // The shed COUNT assertion lives inside the awaited block, not after it. + // ShedAlarmRun increments the counter and only then emits the (rate-limited) + // site event, and that event fires on the FIRST shed only — so an awaited + // gate on the event observes Flap(4)'s shed and orders nothing whatsoever + // with respect to Flap(5)'s, which is a separate mailbox message with no + // observable of its own on this path (an alarm on-trigger run has no Ask + // caller to reply to — AlarmActor.ShedAlarmRun). Asserting the count bare + // after the gate assumed both sheds had been dequeued by the time the + // first one's event landed; under load the second can still be pending and + // the count reads 1. Reproduced deterministically by deferring Flap(5) by + // 2 s: the bare form failed with "Expected: 2 / Actual: 1", while the + // ScriptActor sibling above — which IS ordered, because ShedRun replies + // ScriptCallResult after incrementing — kept passing. + // + // The count is ACCUMULATED across polls rather than re-read, because + // SiteHealthCollector.CollectReport DRAINS the interval counters + // (Interlocked.Exchange(ref _scriptRunShedCount, 0)) — a poll loop that + // simply re-read it would consume the first shed and never see 2. + var shedCounted = 0; AwaitAssert(() => { + shedCounted += health.CollectReport("site-1").ScriptRunShedCount; + var shedEvents = siteLog.OfType("script") .Where(r => r.Severity == "Warning" && r.Message.Contains("shed")) .ToArray(); + + // Both sheds counted, even though the event is rate-limited to one. + Assert.Equal(2, shedCounted); Assert.Single(shedEvents); Assert.Equal("AlarmActor:Flapper", shedEvents[0].Source); - }, TimeSpan.FromSeconds(10)); - Assert.Equal(4, alarm.UnderlyingActor.RunsInFlight); - Assert.Equal(2, health.CollectReport("site-1").ScriptRunShedCount); + // ...and neither shed run was ever launched: still exactly four in flight. + Assert.Equal(4, alarm.UnderlyingActor.RunsInFlight); + }, TimeSpan.FromSeconds(10)); } }