using System.Collections.Concurrent; using System.Diagnostics; using System.Diagnostics.Metrics; using System.Text; using System.Text.Json; using Serilog; using Shouldly; using Xunit; using ZB.MOM.WW.OtOpcUa.Core.Abstractions; using ZB.MOM.WW.OtOpcUa.Core.Scripting; using ZB.MOM.WW.OtOpcUa.Core.Scripting.OutOfProcess; using ZB.MOM.WW.OtOpcUa.Core.Scripting.Protocol; using ZB.MOM.WW.OtOpcUa.Core.Scripting.Protocol.V1; namespace ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests; /// /// lmxopcua#780 P1 supervision gaps: the quarantine race, victim re-evaluation on a shard's return, the idle /// isolation worker, the startup orphan sweep, culprit-finding for a compile that crashes its worker, and the /// runner state / crash-loop circuit. Real worker processes throughout. /// [Collection(ScriptWorkerCollection.Name)] [Trait("Category", "ScriptWorker")] public sealed class SupervisionTests { private const string Healthy = "return 7;"; private const string Runaway = "while (true) { }"; private const string Spin = "var ms = (int)ctx.GetTag(\"ms\").Value; var end = ctx.Now.AddMilliseconds(ms); while (ctx.Now < end) { } return ms;"; private static IReadOnlyDictionary Ms(int ms) => Scripts.Input("ms", ms); private static CancellationToken Ct => TestContext.Current.CancellationToken; private static string VtKey(string key) => InProcessScriptRunner.ScopedKey(ScriptContextKind.VirtualTag, key); // ---------------------------------------------------------------- the quarantine race /// /// The ordering invariant behind the race fix, pinned deterministically at the connection: the exit attribution /// callback runs BEFORE any outstanding evaluation or compile is completed and before Exited is signalled. /// Mutation check: moving the attribution call after the completion loop in WorkerConnection.Finish turns /// both assertions red. /// [Fact] public async Task Exit_attribution_runs_before_any_outstanding_evaluation_completes() { var spec = new WorkerLaunchSpec("t", OutOfProcessScriptRunner.ResolveWorkerPath(new ScriptWorkerOptions()), 256L * 1024 * 1024, EvalThreads: 2, HardGrace: TimeSpan.FromSeconds(60), HeartbeatInterval: TimeSpan.FromSeconds(1), HandshakeTimeout: TimeSpan.FromSeconds(15)); PendingEval? pending = null; WorkerConnection? connection = null; bool? pendingCompletedAtAttribution = null, exitedCompletedAtAttribution = null; IReadOnlyList? inFlightAtAttribution = null; connection = await WorkerConnection.StartAsync(spec, new LoggerConfiguration().CreateLogger(), _ => { }, exit => { pendingCompletedAtAttribution = pending?.Completion.IsCompleted; exitedCompletedAtAttribution = connection?.Exited.IsCompleted; inFlightAtAttribution = exit.InFlightKeys; }, Ct); await using var _ = connection; var entry = await connection.EnsureLoadedAsync("k", ContextKind.VirtualTag, Runaway, System.Security.Cryptography.SHA256.HashData(Encoding.UTF8.GetBytes(Runaway)), []).WaitAsync(TimeSpan.FromSeconds(60), Ct); entry!.Outcome!.Ok.ShouldBeTrue(); pending = connection.Submit("k", new EvalRequest { Key = "k", SoftTimeoutMs = 60_000, HardGraceMs = 60_000, NowUtcTicks = DateTime.UtcNow.Ticks }); await Scripts.Eventually(() => connection.LastHeartbeat is { Inflight: 1 }, TimeSpan.FromSeconds(10), "the run in flight"); Process.GetProcessById(connection.Pid).Kill(); await connection.Exited.WaitAsync(TimeSpan.FromSeconds(10), Ct); (await pending.Completion.WaitAsync(TimeSpan.FromSeconds(5), Ct)).ShouldBeNull("the worker went away"); inFlightAtAttribution.ShouldBe(["k"]); pendingCompletedAtAttribution.ShouldBe(false, "attribution must precede the evaluation's completion"); exitedCompletedAtAttribution.ShouldBe(false, "attribution must precede Exited"); } /// /// The other half of the race fix, pinned without timing: the shard hands the connection an attribution callback /// that reaches the runner's exit handler SYNCHRONOUSLY (the pre-fix shard called it from an Exited continuation, /// after the evaluations had already been completed). Mutation check: launching with a no-op callback and /// attributing from the Exited continuation instead leaves attributed false when the callback returns. /// [Fact] public async Task The_shard_attributes_an_exit_synchronously_inside_the_connections_callback() { Action? captured = null; var attributed = false; await using var shard = new WorkerShard("t", isolation: false, (onExiting, _) => { captured = onExiting; throw new InvalidOperationException("no process in this test"); }, (_, _) => attributed = true, new LoggerConfiguration().CreateLogger()); (await shard.GetReadyAsync(TimeSpan.FromSeconds(5), Ct)).ShouldBeNull(); captured.ShouldNotBeNull(); captured(new WorkerExit(WorkerExitReason.Crash, null, 1, ["k"])); attributed.ShouldBeTrue("the runner's verdict is recorded before the callback returns"); } /// /// The race itself, end to end: with QuarantineAfterKills = 1, the moment the killed script's single-flight slot is /// released the quarantine is already in place — so no trigger can re-run it in the restart gap, and the next /// trigger is refused without any wait. Repeated, since the old ordering lost this race only some of the time. /// [Fact] public async Task A_killed_script_is_quarantined_before_its_slot_is_released() { await using var runner = Scripts.Runner(Scripts.Options(hardGrace: TimeSpan.FromMilliseconds(250), quarantineAfterKills: 1)); var observed = new ConcurrentQueue(); runner.SlotReleasingForTest = key => { if (key == VtKey("runaway")) observed.Enqueue(runner.QuarantinedKeys(ScriptContextKind.VirtualTag).Contains("runaway")); }; (await runner.RunAsync(Scripts.Vt("sibling", Healthy), Ct)).Value.ShouldBe(7); for (var round = 1; round <= 3; round++) { var worker = runner.Shards[0].Current.ShouldNotBeNull(); (await runner.RunAsync(Scripts.Vt("runaway", Runaway, TimeSpan.FromMilliseconds(250)), Ct)).Reason! .ShouldStartWith("script timed out after "); await worker.Exited.WaitAsync(TimeSpan.FromSeconds(10), Ct); await Scripts.Eventually(() => observed.Count == round, TimeSpan.FromSeconds(5), "the slot release"); // No Eventually: the very next trigger after the kill is refused. var next = await runner.RunAsync(Scripts.Vt("runaway", Runaway, TimeSpan.FromMilliseconds(250)), Ct); next.Reason!.ShouldStartWith(ScriptRunGuard.QuarantinedReasonPrefix); runner.Reset(ScriptContextKind.VirtualTag); (await runner.RunAsync(Scripts.Vt("sibling", Healthy), Ct)).Value.ShouldBe(7); } observed.ShouldAllBe(quarantined => quarantined, "the slot was released before the kill strike was recorded"); } // ---------------------------------------------------------------- victims re-evaluated on return /// /// A victim's Unavailable outcome carries a Recovery task that completes when its shard is back — and the shard /// comes back on its own (proactive restart), with no further trigger. Mutation check: without the shard's /// recovery loop, Recovery never completes and no worker is running. /// [Fact] public async Task A_victims_recovery_completes_when_its_shard_restarts_by_itself() { await using var runner = Scripts.Runner(Scripts.Options()); (await runner.RunAsync(Scripts.Vt("victim", Spin, inputs: Ms(0)), Ct)).Value.ShouldBe(0); (await runner.RunAsync(Scripts.Vt("sibling", Healthy), Ct)).Value.ShouldBe(7); var worker = runner.Shards[0].Current.ShouldNotBeNull(); var inFlight = runner.RunAsync(Scripts.Vt("sibling", Spin, TimeSpan.FromSeconds(20), Ms(5000)), Ct); await Scripts.Eventually(() => worker.InFlightCount == 1, TimeSpan.FromSeconds(10), "the run in flight"); Process.GetProcessById(worker.Pid).Kill(); var victim = await inFlight.WaitAsync(TimeSpan.FromSeconds(10), Ct); victim.Status.ShouldBe(ScriptRunStatus.Unavailable); _ = victim.Recovery.ShouldNotBeNull("a runner failure tells the seam when to re-evaluate"); victim.ToVirtualTagEvalResult().RetryWhen.ShouldBeSameAs(victim.Recovery); // The crash made "sibling" a suspect, so its recovery is the isolation worker's; the crashed shard restarts by // itself as well, so the scripts placed on it find it warm. await victim.Recovery!.WaitAsync(TimeSpan.FromSeconds(15), Ct); runner.Isolation.Current.ShouldNotBeNull("recovered without any new trigger"); await Scripts.Eventually(() => runner.Shards[0].Current, TimeSpan.FromSeconds(15), "the shard back"); runner.Shards[0].Current!.Pid.ShouldNotBe(worker.Pid); (await runner.RunAsync(Scripts.Vt("sibling", Spin, inputs: Ms(0)), Ct)).Value.ShouldBe(0); } // ---------------------------------------------------------------- the idle isolation worker /// /// The isolation worker stops after IsolationIdleTimeout with nothing to run — an Idle exit, not a failure — and /// starts again for the next suspect. Mutation check: with the maintenance pass not stopping it, it stays up. /// [Fact] public async Task An_idle_isolation_worker_is_stopped_and_restarts_on_demand() { await using var runner = Scripts.Runner(Scripts.Options(isolationIdle: TimeSpan.FromSeconds(1)), maintenanceInterval: TimeSpan.FromMilliseconds(200)); (await runner.RunAsync(Scripts.Vt("spin", Spin, inputs: Ms(0)), Ct)).Value.ShouldBe(0); var worker = runner.Shards[0].Current.ShouldNotBeNull(); var run = runner.RunAsync(Scripts.Vt("spin", Spin, TimeSpan.FromSeconds(20), Ms(5000)), Ct); await Scripts.Eventually(() => worker.InFlightCount == 1, TimeSpan.FromSeconds(10), "the run in flight"); Process.GetProcessById(worker.Pid).Kill(); (await run.WaitAsync(TimeSpan.FromSeconds(10), Ct)).Status.ShouldBe(ScriptRunStatus.Unavailable); runner.SuspectKeys.ShouldBe([VtKey("spin")]); (await runner.RunAsync(Scripts.Vt("spin", Spin, inputs: Ms(0)), Ct)).Value.ShouldBe(0); var iso = runner.Isolation.Current.ShouldNotBeNull(); var exit = await iso.Exited.WaitAsync(TimeSpan.FromSeconds(10), Ct); exit.Reason.ShouldBe(WorkerExitReason.Idle); runner.Isolation.Current.ShouldBeNull(); runner.Isolation.ConsecutiveFailures.ShouldBe(0, "an idle stop is not a failure"); runner.Isolation.DownFor.ShouldBeNull("an idle stop does not make the isolation worker 'down'"); await Scripts.Eventually(() => runner.State == ScriptRunnerState.Ready, TimeSpan.FromSeconds(15), "the runner ready again"); (await runner.RunAsync(Scripts.Vt("spin", Spin, inputs: Ms(0)), Ct)).Value.ShouldBe(0); runner.Isolation.Current.ShouldNotBeNull().Pid.ShouldNotBe(iso.Pid, "a fresh isolation worker for the next suspect run"); } // ---------------------------------------------------------------- the orphan sweep private static Process StartDecoyWorker() { // A real ScriptWorker that will sit waiting (up to 10 s) for a pipe that does not exist: the shape of a worker // its host abandoned. var psi = new ProcessStartInfo(WorkerConnection.ResolveMuxer()) { UseShellExecute = false, CreateNoWindow = true, RedirectStandardError = true, RedirectStandardOutput = true, }; psi.ArgumentList.Add("exec"); psi.ArgumentList.Add(OutOfProcessScriptRunner.ResolveWorkerPath(new ScriptWorkerOptions())); psi.Environment[ScriptWorkerEnvironment.PipeName] = "otopcua-sw-d" + Guid.NewGuid().ToString("N")[..8]; psi.Environment[ScriptWorkerEnvironment.Nonce] = "decoy"; var p = Process.Start(psi)!; Thread.Sleep(300); if (p.HasExited) throw new InvalidOperationException($"the decoy worker exited {p.ExitCode}: {p.StandardError.ReadToEnd()}"); return p; } private static (int Pid, long StartTicks) DeadProcess() { var psi = new ProcessStartInfo(WorkerConnection.ResolveMuxer(), "--version") { UseShellExecute = false, CreateNoWindow = true, RedirectStandardOutput = true, }; using var p = Process.Start(psi)!; var start = p.StartTime.ToUniversalTime().Ticks; var pid = p.Id; p.WaitForExit(); return (pid, start); } private static string WriteMarker(string dir, Process worker, int hostPid, long hostStartTicks, long? workerStartTicks = null) { Directory.CreateDirectory(dir); var record = new WorkerLaunchMarker.MarkerRecord(worker.Id, workerStartTicks ?? worker.StartTime.ToUniversalTime().Ticks, worker.ProcessName, hostPid, hostStartTicks, "decoy"); var path = Path.Combine(dir, worker.Id + ".worker"); File.WriteAllText(path, JsonSerializer.Serialize(record)); return path; } /// /// Design §3.3: a worker left behind by a DEAD host of this instance is killed at the next start — through the /// runner's constructor, so the wiring is pinned too. Mutation check: without the Sweep call the decoy survives. /// [Fact] public async Task The_startup_sweep_kills_a_worker_whose_host_is_gone() { using var dir = new Scripts.TempDir(); using var decoy = StartDecoyWorker(); var (deadPid, deadStart) = DeadProcess(); var marker = WriteMarker(dir.Path, decoy, deadPid, deadStart); await using var runner = Scripts.Runner(Scripts.Options(), markerDirectory: dir.Path); (await Task.Run(() => decoy.WaitForExit(5000), Ct)).ShouldBeTrue("the orphan was killed"); File.Exists(marker).ShouldBeFalse(); } /// /// Never an unrelated process: a marker whose host is ALIVE (another instance, or a sibling runner in this /// process) is left alone, and a marker whose pid now belongs to a different process (start time differs — /// pid reuse) never kills it. Mutation checks: dropping either the host-alive check or the start-time check /// kills the decoy. /// [Fact] public void The_sweep_never_kills_a_live_hosts_worker_or_a_reused_pid() { using var dir = new Scripts.TempDir(); using var decoy = StartDecoyWorker(); using var self = Process.GetCurrentProcess(); try { var liveHostMarker = WriteMarker(dir.Path, decoy, self.Id, self.StartTime.ToUniversalTime().Ticks); WorkerLaunchMarker.Sweep(dir.Path, new LoggerConfiguration().CreateLogger()).ShouldBeEmpty(); decoy.HasExited.ShouldBeFalse("a live host's worker is not an orphan"); File.Exists(liveHostMarker).ShouldBeTrue("the live host still owns its marker"); var (deadPid, deadStart) = DeadProcess(); var reused = WriteMarker(dir.Path, decoy, deadPid, deadStart, workerStartTicks: decoy.StartTime.ToUniversalTime().AddHours(-1).Ticks); WorkerLaunchMarker.Sweep(dir.Path, new LoggerConfiguration().CreateLogger()).ShouldBeEmpty(); decoy.HasExited.ShouldBeFalse("a pid whose start time does not match is some other process"); File.Exists(reused).ShouldBeFalse("a stale marker is cleaned up"); } finally { try { decoy.Kill(); } catch { /* already gone */ } } } /// A worker's marker exists while it runs and is removed when it stops cleanly. [Fact] public async Task A_running_worker_has_a_launch_marker_that_its_clean_stop_removes() { using var dir = new Scripts.TempDir(); var runner = Scripts.Runner(Scripts.Options(), markerDirectory: dir.Path); (await runner.RunAsync(Scripts.Vt("vt", Healthy), Ct)).Value.ShouldBe(7); var pid = runner.Shards[0].Current!.Pid; var marker = Path.Combine(dir.Path, pid + ".worker"); File.Exists(marker).ShouldBeTrue(); JsonSerializer.Deserialize(File.ReadAllText(marker))!.HostPid.ShouldBe(Environment.ProcessId); await runner.DisposeAsync(); File.Exists(marker).ShouldBeFalse(); } // ---------------------------------------------------------------- a compile that crashes its worker /// /// Design §5.3.5 culprit-finding: a worker that dies while a script is COMPILING (no evaluation in flight) makes /// that script a suspect; it then compiles alone in the isolation worker, where a second death is unambiguous and /// quarantines it — so a poison source cannot crash-loop its shard forever. Mutation check: leaving the compiling /// keys out of the attribution leaves the key unsuspected and unquarantined. /// [Fact] public async Task A_script_whose_compile_keeps_crashing_its_worker_is_found_in_isolation_and_quarantined() { await using var runner = Scripts.Runner(Scripts.Options(quarantineAfterKills: 1)); var body = new StringBuilder("long x = 0;\n"); for (var i = 0; i < 3000; i++) body.Append("x = x * 31 + ").Append(i).Append(";\n"); body.Append("return x;"); var poison = body.ToString(); async Task CrashDuringCompile(Func worker) { var run = runner.RunAsync(Scripts.Vt("poison", poison), Ct); var live = await Scripts.Eventually(worker, TimeSpan.FromSeconds(15), "a live worker"); await Scripts.Eventually(() => live.LoadingCount == 1, TimeSpan.FromSeconds(15), "the compile in flight"); live.InFlightCount.ShouldBe(0, "no evaluation: only the compile is in flight"); Process.GetProcessById(live.Pid).Kill(); return await run.WaitAsync(TimeSpan.FromSeconds(15), Ct); } var first = await CrashDuringCompile(() => runner.Shards[0].Current); first.Status.ShouldBe(ScriptRunStatus.Unavailable); runner.SuspectKeys.ShouldBe([VtKey("poison")], "a death during its compile makes it a suspect"); runner.QuarantinedKeys(ScriptContextKind.VirtualTag).ShouldBeEmpty("ambiguous on a shard: no strike"); await CrashDuringCompile(() => runner.Isolation.Current); runner.QuarantinedKeys(ScriptContextKind.VirtualTag).ShouldBe(["poison"]); var refused = await runner.RunAsync(Scripts.Vt("poison", poison), Ct); refused.Reason!.ShouldStartWith(ScriptRunGuard.QuarantinedReasonPrefix); refused.Reason.ShouldContain("compile crashed the isolation worker"); (await runner.RunAsync(Scripts.Vt("sibling", Healthy), Ct)).Value.ShouldBe(7); } // ---------------------------------------------------------------- state, circuit, gauges [Theory] [InlineData(new double[] { }, null, ScriptRunnerState.Ready)] [InlineData(new double[] { -1, -1 }, null, ScriptRunnerState.Ready)] [InlineData(new double[] { -1, 5 }, null, ScriptRunnerState.Degraded)] [InlineData(new double[] { -1, -1 }, 5.0, ScriptRunnerState.Degraded)] [InlineData(new double[] { 200, 5 }, null, ScriptRunnerState.Degraded)] [InlineData(new double[] { 200, 130 }, null, ScriptRunnerState.Unavailable)] public void The_runner_state_rule(double[] shardsDownSeconds, double? isolationDownSeconds, ScriptRunnerState expected) { var shards = shardsDownSeconds.Select(s => s < 0 ? (TimeSpan?)null : TimeSpan.FromSeconds(s)).ToArray(); var iso = isolationDownSeconds is { } i ? TimeSpan.FromSeconds(i) : (TimeSpan?)null; OutOfProcessScriptRunner.ComputeState(shards, iso, TimeSpan.FromMinutes(2)).ShouldBe(expected); } /// /// The crash-loop circuit: every shard down past CircuitOpenAfter makes the runner Unavailable (gauge value 2), /// logs one Error, and answers evaluations at once instead of after UnavailableGrace. Mutation check: without the /// zero grace under an open circuit, the evaluation waits the full 3 s. /// [Fact] public async Task Every_shard_down_opens_the_circuit_answers_at_once_and_reports_state_2() { var sink = new CapturingSink(); var missing = Path.Combine(Path.GetTempPath(), "no-such-dir-" + Guid.NewGuid().ToString("N"), OutOfProcessScriptRunner.WorkerAssemblyFileName); await using var runner = Scripts.Runner( Scripts.Options(workerPath: missing, unavailableGrace: TimeSpan.FromSeconds(3), circuitOpenAfter: TimeSpan.FromSeconds(1)), sink.CreateLogger(), maintenanceInterval: TimeSpan.FromMilliseconds(100)); runner.State.ShouldBe(ScriptRunnerState.Ready, "nothing needed yet"); (await runner.RunAsync(Scripts.Vt("vt", "return 1;"), Ct)).Status.ShouldBe(ScriptRunStatus.Unavailable); runner.State.ShouldNotBe(ScriptRunnerState.Ready); await Scripts.Eventually(() => runner.State == ScriptRunnerState.Unavailable, TimeSpan.FromSeconds(10), "the circuit open"); var sw = Stopwatch.StartNew(); var fast = await runner.RunAsync(Scripts.Vt("vt", "return 1;"), Ct); sw.Elapsed.ShouldBeLessThan(TimeSpan.FromSeconds(1), "an open circuit answers without waiting out the 3 s grace"); fast.Status.ShouldBe(ScriptRunStatus.Unavailable); fast.Reason.ShouldBe(ScriptRunOutcome.RunnerUnavailableReason); await Scripts.Eventually(() => sink.Rendered.Any(m => m.Contains("circuit OPEN")), TimeSpan.FromSeconds(5), "the circuit Error"); await Task.Delay(500, Ct); sink.Events.Count(e => e.Level == Serilog.Events.LogEventLevel.Error && e.RenderMessage().Contains("circuit OPEN")) .ShouldBe(1, "logged once, not per maintenance pass"); var states = new List(); using var listener = new MeterListener(); listener.InstrumentPublished = (instrument, l) => { if (instrument.Name == "otopcua.script.runner.state") l.EnableMeasurementEvents(instrument); }; listener.SetMeasurementEventCallback((_, value, _, _) => states.Add(value)); listener.Start(); listener.RecordObservableInstruments(); states.ShouldContain(2); runner.Status().State.ShouldBe(ScriptRunnerState.Unavailable); } /// The per-shard gauges observe the live worker (positive control: the shard is up and reports its pid). [Fact] public async Task The_shard_gauges_report_a_live_worker() { await using var runner = Scripts.Runner(Scripts.Options()); (await runner.RunAsync(Scripts.Vt("vt", Healthy), Ct)).Value.ShouldBe(7); await Scripts.Eventually(() => runner.Shards[0].Current?.LastHeartbeat is not null, TimeSpan.FromSeconds(5), "a heartbeat"); var up = new List<(int Value, string? Shard)>(); var heap = new List(); using var listener = new MeterListener(); listener.InstrumentPublished = (instrument, l) => { if (instrument.Name is "otopcua.script.worker.up" or "otopcua.script.worker.heap_bytes") l.EnableMeasurementEvents(instrument); }; listener.SetMeasurementEventCallback((_, value, tags, _) => { foreach (var tag in tags) if (tag.Key == "shard") up.Add((value, tag.Value as string)); }); listener.SetMeasurementEventCallback((_, value, _, _) => heap.Add(value)); listener.Start(); listener.RecordObservableInstruments(); up.ShouldContain((1, "0")); up.ShouldContain((0, "iso"), "the isolation worker is not running"); heap.ShouldContain(h => h > 0); var status = runner.Status(); status.State.ShouldBe(ScriptRunnerState.Ready); status.Shards.Single(s => s.Label == "0").Pid.ShouldBe(runner.Shards[0].Current!.Pid); } }