Merge branch 'sandbox-timing-fix' — SandboxTests deterministic cancellation + flake-pattern sweep (residual #6 / R5)

2026-08-15 03:38:27 -04:00
parent 58a6d47c93 9fb52153fd
commit 156cacfaeb
5 changed files with 162 additions and 34 deletions
@@ -213,14 +213,32 @@ public class SyncCallEmissionEndToEndTests : TestKit, IClassFixture<MsSqlMigrati
            Assert.Equal(evt.EventId, rows[0].EventId);
        }, TimeSpan.FromSeconds(15));

+        // Safe as a bare assertion: DirectActorSiteStreamAuditClient increments
+        // CallCount as its FIRST statement, before the Ask that writes the
+        // central row — so the row existing already implies the second call.
        Assert.True(stubClient.CallCount >= 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.
+        //
+        // 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]
@@ -964,11 +964,18 @@ 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; }
-        }, TimeSpan.FromSeconds(10));
-
            lock (ctx.ReceivedEvents)
            {
                // Snapshot + exactly the retained (capped) events, and the newest survived.
@@ -976,6 +983,7 @@ public class DebugStreamBridgeActorTests : TestKit
                var lastAttr = ctx.ReceivedEvents.OfType<AttributeValueChanged>().Last();
                Assert.Equal($"Attr{cap + overflow - 1}", lastAttr.AttributeName);
            }
+        }, TimeSpan.FromSeconds(10));
    }

    [Fact]
@@ -249,6 +249,13 @@ public class GrpcCentralTransportTests : IAsyncLifetime
        SourceScript: null,
        SiteEnqueuedAt: DateTimeOffset.UtcNow);

+    /// <summary>
+    /// Spins until <paramref name="condition"/> holds, then asserts it — a bare
+    /// <c>return</c> 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.
+    /// </summary>
    private static async Task WaitUntil(Func<bool> 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}.");
    }

    /// <summary>
@@ -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));

+            // ...and neither shed run was ever launched: still exactly four in flight.
            Assert.Equal(4, alarm.UnderlyingActor.RunsInFlight);
-        Assert.Equal(2, health.CollectReport("site-1").ScriptRunShedCount);
+        }, TimeSpan.FromSeconds(10));
    }
 }

@@ -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.
+
+    /// <summary>Builds globals whose "cancelNow" parameter cancels <paramref name="cts"/> when the script invokes it.</summary>
+    private static ScriptGlobals GlobalsWithCancelHook(CancellationTokenSource cts, Action? onSignal = null)
+        => new()
+        {
+            Instance = null!,
+            Parameters = new ScriptParameters(new Dictionary<string, object?>
+            {
+                ["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<OperationCanceledException>(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<OperationCanceledException>(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]