using System.Diagnostics; using System.Runtime.InteropServices; using System.Security.Cryptography; using System.Text; using Serilog; using Shouldly; using Xunit; using ZB.MOM.WW.OtOpcUa.Core.Scripting; using ZB.MOM.WW.OtOpcUa.Core.Scripting.OutOfProcess; using ZB.MOM.WW.OtOpcUa.Core.Scripting.Protocol.V1; namespace ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests; /// /// lmxopcua#827: the soft deadline T measures the script's OWN execution — the worker runs it from the moment an /// evaluation thread starts the run — so the pipe round trip and the time a starved worker waits to be scheduled /// no longer count against the script. The host keeps a transport deadline (T + G from submit) and reports passing /// it as a runner fault (, BadResourceUnavailable), never as a /// script timeout. The starved worker is made real here: its process is suspended (SIGSTOP / NtSuspendProcess) /// while a trivial script is submitted. /// [Collection(ScriptWorkerCollection.Name)] [Trait("Category", "ScriptWorker")] public sealed class WorkerSoftClockTests { private const string Trivial = "return 7;"; private const string Runaway = "while (true) { }"; private static CancellationToken Ct => TestContext.Current.CancellationToken; /// /// A runner whose worker heartbeats every 2 s, so the host's silence kill (3 intervals) stays well clear of the /// suspensions below: what is measured is the deadline, not the heartbeat monitor. /// private static OutOfProcessScriptRunner Runner(TimeSpan hardGrace, ILogger? log = null) => new(Scripts.Options(hardGrace: hardGrace, quarantineAfterKills: 1), log ?? new LoggerConfiguration().CreateLogger(), null, heartbeatInterval: TimeSpan.FromSeconds(2), loadTimeout: TimeSpan.FromSeconds(60)); private static async Task WarmAsync(OutOfProcessScriptRunner runner, string key) { var warm = await runner.RunAsync(Scripts.Vt(key, Trivial, TimeSpan.FromSeconds(30)), Ct); warm.Status.ShouldBe(ScriptRunStatus.Ok, warm.Reason); var worker = runner.Shards[0].Current.ShouldNotBeNull(); worker.WorkerSoftClock.ShouldBeTrue("the worker negotiated the soft clock"); return worker; } /// /// The issue's headline: a worker that cannot be scheduled for longer than T, but shorter than the transport /// deadline, answers a trivial script with its value. Before #827 the host's clock, started at submit, answered /// script timed out after 0.3s for return 7;. /// [Fact] public async Task A_worker_stalled_for_longer_than_T_still_answers_a_trivial_script_with_its_value() { var softT = TimeSpan.FromMilliseconds(300); await using var runner = Runner(hardGrace: TimeSpan.FromSeconds(3)); var worker = await WarmAsync(runner, "trivial"); Task run; using (ProcessFreezer.Freeze(worker.Pid)) { run = runner.RunAsync(Scripts.Vt("trivial", Trivial, softT), Ct); await Task.Delay(softT * 4, Ct); // 1.2 s: well past T on the host's clock run.IsCompleted.ShouldBeFalse("nothing can answer while the worker is suspended"); } var outcome = await run.WaitAsync(TimeSpan.FromSeconds(30), Ct); outcome.Status.ShouldBe(ScriptRunStatus.Ok, outcome.Reason); outcome.Value.ShouldBe(7); runner.Shards[0].Current.ShouldNotBeNull().Pid.ShouldBe(worker.Pid, "a stall is not a deadline kill"); runner.QuarantinedKeys(ScriptContextKind.VirtualTag).ShouldBeEmpty(); } /// /// A stall past the transport deadline (T + G) is the runner's fault: the caller gets /// as (published /// BadResourceUnavailable) with a recovery that completes when the worker answers; a re-trigger meanwhile is the /// runner's fault too (not "previous run still running"); the worker is not killed and the key is not struck. /// Before #827 this was a script timeout at T and a deadline kill at T + G that struck the key — with /// QuarantineAfterKills = 1, a quarantine for return 7;. /// [Fact] public async Task A_worker_stalled_past_the_transport_deadline_is_a_runner_fault_and_nothing_is_struck() { var softT = TimeSpan.FromMilliseconds(200); var grace = TimeSpan.FromMilliseconds(400); await using var runner = Runner(grace); var worker = await WarmAsync(runner, "trivial"); ScriptRunOutcome stalled, retriggered; using (ProcessFreezer.Freeze(worker.Pid)) { stalled = await runner.RunAsync(Scripts.Vt("trivial", Trivial, softT), Ct).WaitAsync(TimeSpan.FromSeconds(10), Ct); retriggered = await runner.RunAsync(Scripts.Vt("trivial", Trivial, softT), Ct).WaitAsync(TimeSpan.FromSeconds(10), Ct); stalled.Recovery.ShouldNotBeNull().IsCompleted.ShouldBeFalse("the worker has not answered yet"); } stalled.Status.ShouldBe(ScriptRunStatus.Unavailable, stalled.Reason); stalled.Reason.ShouldBe(ScriptRunOutcome.WorkerUnresponsiveReason); retriggered.Status.ShouldBe(ScriptRunStatus.Unavailable, retriggered.Reason); retriggered.Reason.ShouldBe(ScriptRunOutcome.WorkerUnresponsiveReason); stalled.ToVirtualTagEvalResult().StatusCode.ShouldBe(Commons.OpcUa.OpcUaStatus.BadResourceUnavailable); await stalled.Recovery!.WaitAsync(TimeSpan.FromSeconds(30), Ct); var next = await runner.RunAsync(Scripts.Vt("trivial", Trivial, softT), Ct); next.Status.ShouldBe(ScriptRunStatus.Ok, next.Reason); next.Value.ShouldBe(7); runner.Shards[0].Current.ShouldNotBeNull().Pid.ShouldBe(worker.Pid, "a stall is not a deadline kill"); runner.QuarantinedKeys(ScriptContextKind.VirtualTag).ShouldBeEmpty(); } /// /// The other side of the contract is unchanged: a script that really runs past T is answered at T from its own /// start and killed G after that, even with the worker stalled before it started. Positive control for the two /// tests above — they would also pass if the runner simply never timed anything out. /// [Fact] public async Task A_runaway_that_starts_late_is_still_timed_out_at_T_from_its_start_and_killed_at_G() { var softT = TimeSpan.FromMilliseconds(300); var grace = TimeSpan.FromMilliseconds(600); var stall = TimeSpan.FromMilliseconds(500); await using var runner = Runner(grace); var worker = await WarmAsync(runner, "warm"); var load = await runner.RunAsync(Scripts.Vt("runaway", "return 0;", TimeSpan.FromSeconds(30)), Ct); load.Status.ShouldBe(ScriptRunStatus.Ok, load.Reason); var sw = Stopwatch.StartNew(); Task run; using (ProcessFreezer.Freeze(worker.Pid)) { run = runner.RunAsync(Scripts.Vt("runaway", Runaway, softT), Ct); await Task.Delay(stall, Ct); } var thawed = sw.Elapsed; var outcome = await run.WaitAsync(TimeSpan.FromSeconds(30), Ct); var answered = sw.Elapsed; outcome.Status.ShouldBe(ScriptRunStatus.Failed); outcome.Reason.ShouldNotBeNull().ShouldStartWith("script timed out after "); (answered - thawed).ShouldBeGreaterThanOrEqualTo(softT - TimeSpan.FromMilliseconds(50), "T counts from the run's start, after the stall"); var exit = await worker.Exited.WaitAsync(TimeSpan.FromSeconds(30), Ct); exit.Reason.ShouldBe(WorkerExitReason.KilledDeadline); exit.CulpritKey.ShouldBe(InProcessScriptRunner.ScopedKey(ScriptContextKind.VirtualTag, "runaway")); (sw.Elapsed - thawed).ShouldBeGreaterThanOrEqualTo(softT + grace - TimeSpan.FromMilliseconds(50), "G counts from the soft deadline"); } /// /// Shadow (lmxopcua#780 P2) compares the shadow pool with the published in-process result; a starved worker used to /// show up there as a script mismatch (published Ok, shadow "timed out") and skew the census for the OutOfProcess /// flip. Now a stall shorter than the transport deadline is a match, and a longer one is shadow_unavailable /// — never a mismatch — including the re-trigger that finds the stalled run still holding its slot. /// [Fact] public async Task In_Shadow_a_stalled_worker_is_a_match_or_shadow_unavailable_never_a_mismatch() { var softT = TimeSpan.FromMilliseconds(300); var grace = TimeSpan.FromSeconds(1); var options = Scripts.Options(hardGrace: grace, quarantineAfterKills: 1); options.Runner = ScriptRunnerMode.Shadow; await using var pool = Runner(grace); using var shadow = new ShadowScriptRunner(pool, options, new LoggerConfiguration().CreateLogger()); var worker = await WarmAsync(pool, "trivial"); var published = ScriptRunOutcome.Ok(7); // Stall past T, short of T + G: compared, and a match. using (ProcessFreezer.Freeze(worker.Pid)) { shadow.Mirror(Scripts.Vt("trivial", Trivial, softT), published); await Task.Delay(TimeSpan.FromMilliseconds(900), Ct); } (await shadow.WaitIdleAsync(TimeSpan.FromSeconds(30))).ShouldBeTrue(); shadow.Stats().Matched.ShouldBe(1, Summary(shadow)); // Stall past T + G: not compared. The second mirror arrives while the first still holds the key's slot. using (ProcessFreezer.Freeze(worker.Pid)) { shadow.Mirror(Scripts.Vt("trivial", Trivial, softT), published); await Scripts.Eventually(() => shadow.Stats().ShadowUnavailable == 1, TimeSpan.FromSeconds(10), "the transport deadline"); shadow.Mirror(Scripts.Vt("trivial", Trivial, softT), published); await Scripts.Eventually(() => shadow.Stats().ShadowUnavailable == 2, TimeSpan.FromSeconds(10), "the stalled re-trigger"); } (await shadow.WaitIdleAsync(TimeSpan.FromSeconds(30))).ShouldBeTrue(); var stats = shadow.Stats(); stats.Mismatched.ShouldBe(0, Summary(shadow)); stats.ShadowUnavailable.ShouldBe(2, Summary(shadow)); stats.Matched.ShouldBe(1); pool.Shards[0].Current.ShouldNotBeNull().Pid.ShouldBe(worker.Pid); } /// /// Protocol compatibility: the soft clock is negotiated (Hello.worker_soft_clock → Ready.worker_soft_clock). /// A host that does not ask for it keeps the pre-#827 contract — the soft deadline is the host's, from submit, /// and the worker sends no soft notices — and a runaway is still answered at T and killed at T + G. /// [Theory] [InlineData(true)] [InlineData(false)] public async Task The_soft_clock_is_negotiated_and_both_clocks_enforce_T_and_G(bool workerSoftClock) { var spec = new WorkerLaunchSpec("t", OutOfProcessScriptRunner.ResolveWorkerPath(new ScriptWorkerOptions { ExecutablePath = Scripts.WorkerUnderTest }), 256L * 1024 * 1024, EvalThreads: 2, HardGrace: TimeSpan.FromSeconds(1), HeartbeatInterval: TimeSpan.FromSeconds(1), HandshakeTimeout: TimeSpan.FromSeconds(15), WorkerSoftClock: workerSoftClock); var connection = await WorkerConnection.StartAsync(spec, new LoggerConfiguration().CreateLogger(), _ => { }, _ => { }, Ct); await using var _ = connection; connection.WorkerSoftClock.ShouldBe(workerSoftClock); 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(); var softT = TimeSpan.FromMilliseconds(300); var grace = TimeSpan.FromMilliseconds(500); var sw = Stopwatch.StartNew(); var pending = connection.Submit("k", new EvalRequest { Key = "k", SoftTimeoutMs = (uint)softT.TotalMilliseconds, HardGraceMs = (uint)grace.TotalMilliseconds, NowUtcTicks = DateTime.UtcNow.Ticks }, softT, grace, null); (await pending.Outcome.WaitAsync(TimeSpan.FromSeconds(10), Ct)).ShouldBeSameAs(PendingEval.SoftTimedOut); sw.Elapsed.ShouldBeGreaterThanOrEqualTo(softT - TimeSpan.FromMilliseconds(20)); connection.Cancel(pending); var exit = await connection.Exited.WaitAsync(TimeSpan.FromSeconds(10), Ct); exit.Reason.ShouldBe(WorkerExitReason.KilledDeadline); sw.Elapsed.ShouldBeGreaterThanOrEqualTo(softT + grace - TimeSpan.FromMilliseconds(50)); } // ---------------------------------------------------------------- PendingEval, no process /// The host side of the worker clock, deterministic: no notice means the transport deadline at T + G. [Fact] public async Task Worker_clock_with_no_word_from_the_worker_answers_transport_timed_out_at_T_plus_G_and_never_kills() { var killed = 0; var pending = new PendingEval("k", 1); var sw = Stopwatch.StartNew(); pending.Arm(TimeSpan.FromMilliseconds(100), TimeSpan.FromMilliseconds(200), _ => Interlocked.Increment(ref killed), workerClock: true); (await pending.Outcome.WaitAsync(TimeSpan.FromSeconds(10), Ct)).ShouldBeSameAs(PendingEval.TransportTimedOut); sw.Elapsed.ShouldBeGreaterThanOrEqualTo(TimeSpan.FromMilliseconds(280)); await Task.Delay(500, Ct); killed.ShouldBe(0, "a late worker is not the script's fault"); // A soft notice after the transport answer still arms the kill: the script itself ran for T. pending.SoftExpired(); await Scripts.Eventually(() => Volatile.Read(ref killed) == 1, TimeSpan.FromSeconds(10), "the kill G after the soft notice"); } /// The soft notice answers the caller and arms the kill G later; a result before then cancels it. [Fact] public async Task Worker_clock_soft_notice_answers_soft_timed_out_and_arms_the_kill_G_later() { var killed = 0; var pending = new PendingEval("k", 1); pending.Arm(TimeSpan.FromSeconds(30), TimeSpan.FromMilliseconds(300), _ => Interlocked.Increment(ref killed), workerClock: true); pending.Outcome.IsCompleted.ShouldBeFalse(); var sw = Stopwatch.StartNew(); pending.SoftExpired(); (await pending.Outcome.WaitAsync(TimeSpan.FromSeconds(1), Ct)).ShouldBeSameAs(PendingEval.SoftTimedOut); await Scripts.Eventually(() => Volatile.Read(ref killed) == 1, TimeSpan.FromSeconds(10), "the kill"); sw.Elapsed.ShouldBeGreaterThanOrEqualTo(TimeSpan.FromMilliseconds(280)); var answered = new PendingEval("k2", 2); answered.Arm(TimeSpan.FromSeconds(30), TimeSpan.FromMilliseconds(100), _ => Interlocked.Increment(ref killed), workerClock: true); answered.SoftExpired(); answered.Complete(new EvalResult { EvalId = 2 }); await Task.Delay(400, Ct); killed.ShouldBe(1, "a run that answered inside G is not killed"); } /// Under the host clock a soft notice means nothing (a worker that did not negotiate it cannot send one). [Fact] public void Host_clock_ignores_a_soft_notice() { var pending = new PendingEval("k", 1); pending.Arm(TimeSpan.FromSeconds(30), TimeSpan.FromSeconds(30), _ => { }, workerClock: false); pending.SoftExpired(); pending.Outcome.IsCompleted.ShouldBeFalse(); pending.Complete(null); } private static string Summary(ShadowScriptRunner shadow) => $"{shadow.Stats()}; " + string.Join("; ", shadow.Mismatches.Select(m => $"{m.Key}: {m.LastReason} — {m.LastSummary}")); } /// Suspends a process (SIGSTOP, or NtSuspendProcess on Windows) until disposed. internal sealed class ProcessFreezer : IDisposable { private readonly int _pid; private int _thawed; private ProcessFreezer(int pid) { _pid = pid; Signal(pid, stop: true); } public static ProcessFreezer Freeze(int pid) => new(pid); public void Dispose() { if (Interlocked.Exchange(ref _thawed, 1) == 0) Signal(_pid, stop: false); } private static void Signal(int pid, bool stop) { if (OperatingSystem.IsWindows()) { using var process = Process.GetProcessById(pid); var status = stop ? NtSuspendProcess(process.Handle) : NtResumeProcess(process.Handle); status.ShouldBe(0, $"Nt{(stop ? "Suspend" : "Resume")}Process"); return; } // libc kill(2), not the kill(1) command: a child process's exit is observed through the same SIGCHLD // handling that the suspended worker (another child of this process) just disturbed, and WaitForExit was // seen to take seconds. var signal = stop ? SigStop : SigCont; Kill(pid, signal).ShouldBe(0, $"kill({pid}, {signal}): errno {Marshal.GetLastPInvokeError()}"); } /// SIGSTOP / SIGCONT: 17 / 19 on macOS (BSD), 19 / 18 on Linux. private static int SigStop => OperatingSystem.IsMacOS() ? 17 : 19; private static int SigCont => OperatingSystem.IsMacOS() ? 19 : 18; #pragma warning disable SYSLIB1054 // DllImport kept: LibraryImport would need AllowUnsafeBlocks for three test-only calls. [DllImport("libc", EntryPoint = "kill", SetLastError = true)] private static extern int Kill(int pid, int signal); [DllImport("ntdll.dll")] private static extern int NtSuspendProcess(IntPtr processHandle); [DllImport("ntdll.dll")] private static extern int NtResumeProcess(IntPtr processHandle); #pragma warning restore SYSLIB1054 }