fix(scripting): soft notice resumes the caller on the dispatcher; a late notice still cancels and counts (#827 review F1, F2)

F1: PendingEval.SoftExpired runs on the pipe reader and completed the caller's outcome inline (production outcomes have no async continuations, by design, because results resume on the ResultDispatcher). The caller's code (the runner's Cancel write, the seam's publish) therefore ran on the reader, which could hold up heartbeats (a false silence kill) and, with blocking I/O, write to the pipe from the reader. The soft outcome is now posted to the dispatcher like a result. Test: a 1.5 s continuation on a soft timeout with a 300 ms silence limit resumes on ScriptWorker[t].Results and the worker lives (before: it resumed on the Reader). F2: after a transport timeout ("worker unresponsive"), a late soft notice armed G but nobody sent Cancel, so a polling script could not end itself and the whole worker was killed at notice + G with a kill strike. PendingEval now exposes LateSoftExpiry (asynchronous continuations, cancelled when the run answers); the runner sends the Cancel and counts the timeout (NoteTimeout) from it. A genuinely slow script whose notice is delayed past T + G is thus still a timeout. Test: stall past T + G, thaw, a polling script overruns T: the worker survives G and the key is quarantined for timeouts, not a hard deadline (before: the worker was killed).
2026-11-11 02:21:45 -05:00
parent 30c6c3a0bf
commit c5dffbd8b8
3 changed files with 122 additions and 7 deletions
@@ -227,6 +227,85 @@ public sealed class WorkerSoftClockTests
        sw.Elapsed.ShouldBeGreaterThanOrEqualTo(softT + grace - TimeSpan.FromMilliseconds(50));
    }

+    // ---------------------------------------------------------------- review findings (#827)
+
+    /// <summary>
+    ///     Review F1: the soft notice is handled on the pipe READER, and the caller's resumption is the caller's code. It
+    ///     must go through the result dispatcher like a result does: a continuation that blocks for 1.5 s must not hold up
+    ///     the reader, or the next heartbeats sit unread and a healthy worker is killed for silence (300 ms here). Before
+    ///     the fix the continuation ran inline on the reader and the worker was killed (KilledHeartbeat).
+    /// </summary>
+    [Fact]
+    public async Task A_slow_continuation_of_a_soft_timeout_does_not_stall_the_reader()
+    {
+        var heartbeat = TimeSpan.FromMilliseconds(100);
+        var spec = new WorkerLaunchSpec("t", OutOfProcessScriptRunner.ResolveWorkerPath(new ScriptWorkerOptions { ExecutablePath = Scripts.WorkerUnderTest }),
+            256L * 1024 * 1024, EvalThreads: 2, HardGrace: TimeSpan.FromSeconds(60), HeartbeatInterval: heartbeat,
+            HandshakeTimeout: TimeSpan.FromSeconds(15), HeartbeatSilenceLimit: TimeSpan.FromSeconds(30));
+        var connection = await WorkerConnection.StartAsync(spec, new LoggerConfiguration().CreateLogger(), _ => { }, _ => { }, Ct);
+        await using var _ = connection;
+        var entry = await connection.EnsureLoadedAsync("k", ContextKind.VirtualTag, Runaway,
+            SHA256.HashData(Encoding.UTF8.GetBytes(Runaway)), []).WaitAsync(TimeSpan.FromSeconds(60), Ct);
+        entry.Outcome.ShouldNotBeNull().Ok.ShouldBeTrue();
+        connection.SilenceLimit = heartbeat * 3; // armed only once the cold start is over (see SupervisionTests)
+
+        var softT = TimeSpan.FromMilliseconds(200);
+        var pending = connection.Submit("k",
+            new EvalRequest { Key = "k", SoftTimeoutMs = (uint)softT.TotalMilliseconds, HardGraceMs = 60_000, NowUtcTicks = DateTime.UtcNow.Ticks },
+            softT, TimeSpan.FromSeconds(60), null);
+        string? resumedOn = null;
+        var slowConsumer = pending.Outcome.ContinueWith(t =>
+        {
+            resumedOn = Thread.CurrentThread.Name;
+            t.Result.ShouldBeSameAs(PendingEval.SoftTimedOut);
+            Thread.Sleep(1_500);
+        }, CancellationToken.None, TaskContinuationOptions.ExecuteSynchronously, TaskScheduler.Default);
+
+        await slowConsumer.WaitAsync(TimeSpan.FromSeconds(10), Ct);
+        resumedOn.ShouldBe("ScriptWorker[t].Results", "the caller resumes on the dispatcher, never on the reader");
+        connection.Exited.IsCompleted.ShouldBeFalse("the reader kept reading heartbeats while the consumer was slow");
+        connection.IsAlive.ShouldBeTrue();
+    }
+
+    /// <summary>
+    ///     Review F2: a stall past T + G answers "worker unresponsive"; when the worker then runs the script and it really
+    ///     overruns T, the late soft notice must still cancel its token — a polling script ends itself instead of the whole
+    ///     worker being killed G later — and the run counts as a timeout (QuarantineAfterConsecutiveTimeouts = 1 here).
+    ///     Before the fix nobody sent the Cancel: the worker was killed at notice + G (KilledDeadline, a kill strike).
+    /// </summary>
+    [Fact]
+    public async Task A_slow_script_whose_notice_arrives_after_the_transport_deadline_is_cancelled_and_counted_not_killed()
+    {
+        var softT = TimeSpan.FromMilliseconds(200);
+        var grace = TimeSpan.FromMilliseconds(400);
+        var options = Scripts.Options(hardGrace: grace, quarantineAfterKills: 1);
+        options.QuarantineAfterConsecutiveTimeouts = 1;
+        await using var runner = new OutOfProcessScriptRunner(options, new LoggerConfiguration().CreateLogger(), null,
+            heartbeatInterval: TimeSpan.FromSeconds(2), loadTimeout: TimeSpan.FromSeconds(60));
+        const string polite = "if ((int)ctx.GetTag(\"spin\").Value == 1) { while (!ctx.CancellationToken.IsCancellationRequested) { } } return 1;";
+        (await runner.RunAsync(Scripts.Vt("polite", polite, TimeSpan.FromSeconds(30), Scripts.Input("spin", 0)), Ct)).Value.ShouldBe(1);
+        var worker = runner.Shards[0].Current.ShouldNotBeNull();
+
+        ScriptRunOutcome stalled;
+        using (ProcessFreezer.Freeze(worker.Pid))
+        {
+            stalled = await runner.RunAsync(Scripts.Vt("polite", polite, softT, Scripts.Input("spin", 1)), Ct).WaitAsync(TimeSpan.FromSeconds(10), Ct);
+        }
+        stalled.Reason.ShouldBe(ScriptRunOutcome.WorkerUnresponsiveReason);
+
+        // Thawed: the script starts, spins past T, the late notice cancels it and it returns. The worker survives G.
+        await stalled.Recovery.ShouldNotBeNull().WaitAsync(TimeSpan.FromSeconds(10), Ct);
+        await Task.Delay(softT + grace + TimeSpan.FromMilliseconds(500), Ct);
+        worker.IsAlive.ShouldBeTrue("a cancelled polling script must not cost its worker");
+        runner.Shards[0].Current.ShouldNotBeNull().Pid.ShouldBe(worker.Pid);
+
+        // …and it counted as the timeout it was (threshold 1), not as a kill.
+        await Scripts.Eventually(() => runner.QuarantinedKeys(ScriptContextKind.VirtualTag).Count == 1, TimeSpan.FromSeconds(5), "the timeout quarantine");
+        var refused = await runner.RunAsync(Scripts.Vt("polite", polite, softT, Scripts.Input("spin", 0)), Ct);
+        refused.Reason.ShouldNotBeNull().ShouldContain("timed out");
+        refused.Reason.ShouldNotContain("hard deadline");
+    }
+
    // ---------------------------------------------------------------- PendingEval, no process

    /// <summary>The host side of the worker clock, deterministic: no notice means the transport deadline at T + G.</summary>