feat(scripting): Scripting:Runner=Shadow — in-process results published, each compiled run mirrored to the ScriptWorker pool and compared (lmxopcua#780 P2)

- ShadowScriptRunner (Core.Scripting): IScriptShadow.Mirror copies the inputs and queues the shadow run on the
  pool; compares value (structural), CLR type, status and failure class (compile / budget / threw+message /
  unsupported_type); runner-fault shadow outcomes (Unavailable, worker busy) are not compared. Bounded:
  Scripting:Shadow:MaxInFlight (256) and one per script; drops counted (behind | key_busy).
- Metrics otopcua.script.shadow.{compared,mismatch{script},dropped,inflight}; one rate-limited Warning per
  script and reason with a diff summary (Scripting:Shadow:MismatchLogsPerMinute, re-armed at the seam's deploy).
- The VirtualTag, Calculation and scripted-alarm seams recognise the shadow and keep their in-process path
  byte-for-byte (no coalescer, one-at-a-time pump, in-process engine), mirroring after each compiled run.
- ScriptRunnerSelection builds the shadow over an OutOfProcessScriptRunner whose lines carry
  ScriptRunnerRole=Shadow; Status() is null under Shadow so readiness never sees the shadow pool; the
  script-runner health entry stays Healthy and reports the shadow counters as data.
- docker-dev/docker-compose.script-runner-shadow.yml; docs/VirtualTags.md "Shadow mode".
- Tests: comparison table, per-script metric + once-per-reason log, rate limit, hung/blocking/throwing shadow
  never reaches the caller, MaxInFlight drop accounting, input copy; real-worker divergent + unsupported-type
  scripts counted against exactly those scripts, a worker-only runaway killed/quarantined there with every
  published value intact, alarm transitions identical to in process across a kill -9 of the shadow worker.
  Mutation-proved (16 mutants, 15 red; the one survivor added an assertion).

Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV
This commit is contained in:
Joseph Doherty
2026-11-10 07:18:40 -05:00
parent 0796928504
commit 03686eb5d7
17 changed files with 1477 additions and 52 deletions
@@ -0,0 +1,343 @@
using System.Collections.Concurrent;
using System.Diagnostics;
using System.Diagnostics.Metrics;
using Serilog;
using Serilog.Core;
using Serilog.Events;
using Shouldly;
using Xunit;
using ZB.MOM.WW.OtOpcUa.Commons.Engines;
using ZB.MOM.WW.OtOpcUa.Core.Abstractions;
namespace ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests;
/// <summary>
/// lmxopcua#780 P2 — <see cref="ShadowScriptRunner"/>, the comparison half of <c>Scripting:Runner=Shadow</c>, against
/// fake shadow runners: the comparison table, per-script mismatch accounting and its rate-limited log, and the
/// guarantee that nothing on the shadow side — a runner that hangs, blocks its caller, or throws — reaches the
/// evaluation that published, plus the drop accounting that keeps the shadow bounded.
/// </summary>
public sealed class ShadowScriptRunnerTests
{
private static readonly IReadOnlyDictionary<string, DataValueSnapshot> NoInputs =
new Dictionary<string, DataValueSnapshot>(StringComparer.Ordinal);
private sealed class FakeShadow(Func<ScriptInvocation, CancellationToken, Task<ScriptRunOutcome>> run) : IScriptRunner
{
public ConcurrentQueue<ScriptInvocation> Invocations { get; } = new();
public ConcurrentQueue<ScriptContextKind> Resets { get; } = new();
public Task<ScriptRunOutcome> RunAsync(ScriptInvocation invocation, CancellationToken ct = default)
{
Invocations.Enqueue(invocation);
return run(invocation, ct);
}
public void Reset(ScriptContextKind kind) => Resets.Enqueue(kind);
public IReadOnlyCollection<string> QuarantinedKeys(ScriptContextKind kind) => [];
}
private sealed class Capture : ILogEventSink
{
public ConcurrentQueue<LogEvent> Events { get; } = new();
public void Emit(LogEvent logEvent) => Events.Enqueue(logEvent);
public ILogger Logger() => new LoggerConfiguration().MinimumLevel.Verbose().WriteTo.Sink(this).CreateLogger();
public string[] Mismatches => Events.Where(e => e.MessageTemplate.Text.StartsWith("Script shadow mismatch", StringComparison.Ordinal))
.Select(e => e.RenderMessage()).ToArray();
}
private static ScriptInvocation Vt(string key, IReadOnlyDictionary<string, DataValueSnapshot>? inputs = null, string source = "return 1;")
=> new(key, ScriptContextKind.VirtualTag, source, inputs ?? NoInputs, TimeSpan.FromSeconds(2));
private static ScriptingOptions Options(int maxInFlight = 256, int logsPerMinute = 20)
=> new() { Shadow = new ScriptShadowOptions { MaxInFlight = maxInFlight, MismatchLogsPerMinute = logsPerMinute } };
private static string NewKey() => "shadow-" + Guid.NewGuid().ToString("N")[..10];
public static TheoryData<ScriptRunOutcome, ScriptRunOutcome, ScriptShadowVerdict, string?> Table => new()
{
{ ScriptRunOutcome.Ok(42), ScriptRunOutcome.Ok(42), ScriptShadowVerdict.Match, null },
{ ScriptRunOutcome.Ok(null), ScriptRunOutcome.Ok(null), ScriptShadowVerdict.Match, null },
{ ScriptRunOutcome.Ok(new[] { 1, 2 }), ScriptRunOutcome.Ok(new[] { 1, 2 }), ScriptShadowVerdict.Match, null },
{ ScriptRunOutcome.Ok(double.NaN), ScriptRunOutcome.Ok(double.NaN), ScriptShadowVerdict.Match, null },
{ ScriptRunOutcome.Ok(42), ScriptRunOutcome.Ok(43), ScriptShadowVerdict.Mismatch, "value" },
{ ScriptRunOutcome.Ok(new[] { 1, 2 }), ScriptRunOutcome.Ok(new[] { 1, 3 }), ScriptShadowVerdict.Mismatch, "value" },
{ ScriptRunOutcome.Ok(42), ScriptRunOutcome.Ok(null), ScriptShadowVerdict.Mismatch, "value" },
{ ScriptRunOutcome.Ok((short)42), ScriptRunOutcome.Ok(42), ScriptShadowVerdict.Mismatch, "type" },
{ ScriptRunOutcome.Ok(42), ScriptRunOutcome.Failed("script threw: boom"), ScriptShadowVerdict.Mismatch, "status" },
{ ScriptRunOutcome.Failed("script threw: boom"), ScriptRunOutcome.Ok(42), ScriptShadowVerdict.Mismatch, "status" },
{ ScriptRunOutcome.Failed("script threw: boom"), ScriptRunOutcome.Failed("script threw: boom"), ScriptShadowVerdict.Match, null },
{ ScriptRunOutcome.Failed("script threw: boom"), ScriptRunOutcome.Failed("script threw: bang"), ScriptShadowVerdict.Mismatch, "exception" },
{ ScriptRunOutcome.Failed("compile error: CS1002"), ScriptRunOutcome.Failed("compile error: CS1002 (worker)"), ScriptShadowVerdict.Match, null },
{ ScriptRunOutcome.Failed("compile error: CS1002"), ScriptRunOutcome.Failed("script threw: x"), ScriptShadowVerdict.Mismatch, "failure_kind" },
// The same runaway reaches "budget" by different routes in the two runners: a timeout here, a kill-strike quarantine there.
{ ScriptRunOutcome.Failed("script timed out after 2.0s"), ScriptRunOutcome.Failed("script quarantined: killed twice"), ScriptShadowVerdict.Match, null },
{ ScriptRunOutcome.Failed("previous evaluation still running"), ScriptRunOutcome.Failed("script timed out after 2.0s"), ScriptShadowVerdict.Match, null },
// Design §14 #11: what the protocol cannot carry is surfaced in shadow first.
{ ScriptRunOutcome.Ok(1.5m), ScriptRunOutcome.Failed("unsupported type: script returned a value of unsupported type System.Decimal"), ScriptShadowVerdict.Mismatch, "unsupported_type" },
{ ScriptRunOutcome.Failed("script threw: x"), ScriptRunOutcome.Failed("unsupported type: input 'a' has a value of unsupported type System.Guid"), ScriptShadowVerdict.Mismatch, "unsupported_type" },
// The runner's fault, not the script's: not compared.
{ ScriptRunOutcome.Ok(42), ScriptRunOutcome.Unavailable(ScriptRunOutcome.WorkerRestartedReason), ScriptShadowVerdict.ShadowUnavailable, null },
{ ScriptRunOutcome.Ok(42), ScriptRunOutcome.Failed(ScriptRunOutcome.WorkerBusyReason), ScriptShadowVerdict.ShadowUnavailable, null },
};
[Theory]
[MemberData(nameof(Table))]
public void Compare_classifies_each_pair(ScriptRunOutcome published, ScriptRunOutcome shadow, ScriptShadowVerdict verdict, string? reason)
{
var comparison = ShadowScriptRunner.Compare(published, shadow);
comparison.Verdict.ShouldBe(verdict);
comparison.Reason.ShouldBe(reason);
}
[Fact]
public async Task A_divergent_script_is_counted_per_script_in_metrics_and_logged_once_with_a_diff_summary()
{
var divergent = NewKey();
var healthy = NewKey();
var shadow = new FakeShadow((inv, _) => Task.FromResult(inv.Key == divergent ? ScriptRunOutcome.Ok(2) : ScriptRunOutcome.Ok(1)));
var log = new Capture();
using var runner = new ShadowScriptRunner(shadow, Options(), log.Logger());
var measured = new ConcurrentQueue<(long Value, string? Script, string? Reason, string? Kind)>();
using var listener = new MeterListener();
listener.InstrumentPublished = (instrument, l) =>
{
if (instrument.Name == "otopcua.script.shadow.mismatch") l.EnableMeasurementEvents(instrument);
};
listener.SetMeasurementEventCallback<long>((_, value, tags, _) =>
{
string? script = null, reason = null, kind = null;
foreach (var tag in tags)
{
if (tag.Key == "script") script = tag.Value as string;
if (tag.Key == "reason") reason = tag.Value as string;
if (tag.Key == "kind") kind = tag.Value as string;
}
if (script == divergent || script == healthy) measured.Enqueue((value, script, reason, kind));
});
listener.Start();
for (var i = 0; i < 5; i++)
{
runner.Mirror(Vt(divergent), ScriptRunOutcome.Ok(1));
runner.Mirror(Vt(healthy), ScriptRunOutcome.Ok(1));
(await runner.WaitIdleAsync(TimeSpan.FromSeconds(10))).ShouldBeTrue();
}
var stats = runner.Stats();
stats.Compared.ShouldBe(10);
stats.Matched.ShouldBe(5);
stats.Mismatched.ShouldBe(5);
stats.Dropped.ShouldBe(0);
var record = runner.Mismatches.ShouldHaveSingleItem();
record.Key.ShouldBe(divergent);
record.Count.ShouldBe(5);
record.LastReason.ShouldBe("value");
record.LastSummary.ShouldBe("published Ok Int32 1; shadow Ok Int32 2");
measured.Count.ShouldBe(5);
measured.ShouldAllBe(m => m.Script == divergent && m.Reason == "value" && m.Kind == "virtual_tag" && m.Value == 1);
var line = log.Mismatches.ShouldHaveSingleItem("once per script and reason, not once per evaluation");
line.ShouldContain(divergent);
line.ShouldContain("published Ok Int32 1; shadow Ok Int32 2");
}
[Fact]
public async Task Mismatch_lines_are_rate_limited_per_minute_and_the_next_line_reports_what_was_suppressed()
{
var now = new DateTime(2026, 11, 10, 12, 0, 0, DateTimeKind.Utc);
var shadow = new FakeShadow((_, _) => Task.FromResult(ScriptRunOutcome.Ok(2)));
var log = new Capture();
using var runner = new ShadowScriptRunner(shadow, Options(logsPerMinute: 2), log.Logger(), clock: () => now);
for (var i = 0; i < 5; i++) runner.Mirror(Vt(NewKey()), ScriptRunOutcome.Ok(1));
(await runner.WaitIdleAsync(TimeSpan.FromSeconds(10))).ShouldBeTrue();
log.Mismatches.Length.ShouldBe(2);
runner.Stats().Mismatched.ShouldBe(5, "every mismatch is counted even when its line is not written");
now = now.AddMinutes(1);
runner.Mirror(Vt(NewKey()), ScriptRunOutcome.Ok(1));
(await runner.WaitIdleAsync(TimeSpan.FromSeconds(10))).ShouldBeTrue();
log.Mismatches.Length.ShouldBe(3);
log.Mismatches[^1].ShouldContain("3 earlier mismatch line(s) suppressed");
}
[Fact]
public async Task A_reset_re_arms_the_once_per_script_line_and_resets_the_shadow_runner()
{
var key = NewKey();
var shadow = new FakeShadow((_, _) => Task.FromResult(ScriptRunOutcome.Ok(2)));
var log = new Capture();
using var runner = new ShadowScriptRunner(shadow, Options(), log.Logger());
runner.Mirror(Vt(key), ScriptRunOutcome.Ok(1));
(await runner.WaitIdleAsync(TimeSpan.FromSeconds(10))).ShouldBeTrue();
runner.Mirror(Vt(key), ScriptRunOutcome.Ok(1));
(await runner.WaitIdleAsync(TimeSpan.FromSeconds(10))).ShouldBeTrue();
log.Mismatches.Length.ShouldBe(1);
runner.Reset(ScriptContextKind.Calculation);
runner.Mirror(Vt(key), ScriptRunOutcome.Ok(1));
(await runner.WaitIdleAsync(TimeSpan.FromSeconds(10))).ShouldBeTrue();
log.Mismatches.Length.ShouldBe(1, "another seam's deploy does not re-arm a virtual tag's line");
runner.Reset(ScriptContextKind.VirtualTag);
runner.Mirror(Vt(key), ScriptRunOutcome.Ok(1));
(await runner.WaitIdleAsync(TimeSpan.FromSeconds(10))).ShouldBeTrue();
log.Mismatches.Length.ShouldBe(2);
shadow.Resets.ShouldBe([ScriptContextKind.Calculation, ScriptContextKind.VirtualTag]);
}
[Fact]
public async Task A_shadow_runner_that_hangs_blocks_or_throws_never_reaches_the_caller_and_is_never_a_mismatch()
{
var release = new ManualResetEventSlim(false);
var hang = NewKey();
var block = NewKey();
var boom = NewKey();
var shadow = new FakeShadow((inv, _) =>
{
if (inv.Key == hang) return new TaskCompletionSource<ScriptRunOutcome>().Task; // never completes
if (inv.Key == block) release.Wait(TimeSpan.FromSeconds(2)); // blocks the thread that called RunAsync (bounded, so a regression fails instead of hanging)
if (inv.Key == boom) throw new InvalidOperationException("runner bug");
return Task.FromResult(ScriptRunOutcome.Ok(1));
});
using var runner = new ShadowScriptRunner(shadow, Options(), new LoggerConfiguration().CreateLogger());
var sw = Stopwatch.StartNew();
runner.Mirror(Vt(hang), ScriptRunOutcome.Ok(1));
runner.Mirror(Vt(block), ScriptRunOutcome.Ok(1));
runner.Mirror(Vt(boom), ScriptRunOutcome.Ok(1));
sw.Elapsed.ShouldBeLessThan(TimeSpan.FromMilliseconds(500), "Mirror never runs the shadow on the caller's thread");
// Each key's run is outstanding (or done): a second mirror of the hung/blocked keys is dropped, never queued.
await Task.Delay(100, TestContext.Current.CancellationToken);
runner.Mirror(Vt(hang), ScriptRunOutcome.Ok(1));
runner.Mirror(Vt(block), ScriptRunOutcome.Ok(1));
runner.Stats().DroppedKeyBusy.ShouldBe(2);
release.Set();
await Task.Delay(200, TestContext.Current.CancellationToken);
var stats = runner.Stats();
stats.Mismatched.ShouldBe(0);
stats.ShadowUnavailable.ShouldBe(1, "a runner that throws is the runner's fault, not a divergence");
stats.Matched.ShouldBe(1, "the blocked one completed once released");
stats.InFlight.ShouldBe(1, "the hung one is still outstanding — bounded at one per key");
}
[Fact]
public async Task Evaluations_beyond_MaxInFlight_are_dropped_and_counted_and_the_shadow_resumes_once_it_catches_up()
{
var gate = new TaskCompletionSource<ScriptRunOutcome>(TaskCreationOptions.RunContinuationsAsynchronously);
var shadow = new FakeShadow((_, _) => gate.Task);
using var runner = new ShadowScriptRunner(shadow, Options(maxInFlight: 3), new LoggerConfiguration().CreateLogger());
var measured = new ConcurrentQueue<string?>();
using var listener = new MeterListener();
listener.InstrumentPublished = (instrument, l) =>
{
if (instrument.Name == "otopcua.script.shadow.dropped") l.EnableMeasurementEvents(instrument);
};
var keys = Enumerable.Range(0, 10).Select(_ => NewKey()).ToArray();
listener.SetMeasurementEventCallback<long>((_, _, tags, _) =>
{
foreach (var tag in tags) if (tag.Key == "reason") measured.Enqueue(tag.Value as string);
});
listener.Start();
foreach (var key in keys) runner.Mirror(Vt(key), ScriptRunOutcome.Ok(1));
await Scripts.Eventually(() => shadow.Invocations.Count == 3, "three shadow runs started");
var stats = runner.Stats();
stats.InFlight.ShouldBe(3);
stats.DroppedBehind.ShouldBe(7);
shadow.Invocations.Count.ShouldBe(3, "a dropped evaluation never reaches the shadow runner");
gate.SetResult(ScriptRunOutcome.Ok(1));
(await runner.WaitIdleAsync(TimeSpan.FromSeconds(10))).ShouldBeTrue();
runner.Mirror(Vt(keys[9]), ScriptRunOutcome.Ok(1));
(await runner.WaitIdleAsync(TimeSpan.FromSeconds(10))).ShouldBeTrue();
stats = runner.Stats();
stats.Matched.ShouldBe(4);
stats.DroppedBehind.ShouldBe(7);
measured.Count(r => r == "behind").ShouldBeGreaterThanOrEqualTo(7);
}
[Fact]
public async Task Mirror_copies_the_inputs_before_it_returns_and_never_forwards_the_script_logger()
{
var gate = new TaskCompletionSource<ScriptRunOutcome>(TaskCreationOptions.RunContinuationsAsynchronously);
var seen = new TaskCompletionSource<ScriptInvocation>(TaskCreationOptions.RunContinuationsAsynchronously);
var shadow = new FakeShadow((inv, _) =>
{
seen.TrySetResult(inv);
return gate.Task;
});
using var runner = new ShadowScriptRunner(shadow, Options(), new LoggerConfiguration().CreateLogger());
var cache = new Dictionary<string, DataValueSnapshot>(StringComparer.Ordinal)
{
["a"] = new(1, 0u, DateTime.UtcNow, DateTime.UtcNow),
};
var scriptLog = new LoggerConfiguration().CreateLogger();
runner.Mirror(Vt(NewKey(), cache) with { ScriptLogger = scriptLog }, ScriptRunOutcome.Ok(1));
cache["a"] = new DataValueSnapshot(99, 0u, DateTime.UtcNow, DateTime.UtcNow); // the alarm engine refills in place
var invocation = await seen.Task.WaitAsync(TimeSpan.FromSeconds(10), TestContext.Current.CancellationToken);
gate.SetResult(ScriptRunOutcome.Ok(1));
invocation.Inputs["a"].Value.ShouldBe(1);
invocation.Inputs.ShouldNotBeSameAs(cache);
invocation.ScriptLogger.ShouldBeSameAs(Logger.None, "the in-process run already wrote the script's log lines");
}
[Fact]
public async Task As_a_runner_it_publishes_the_in_process_result_and_mirrors_it()
{
var shadow = new FakeShadow((_, _) => Task.FromResult(ScriptRunOutcome.Ok(-1)));
using var runner = new ShadowScriptRunner(shadow, Options(), new LoggerConfiguration().CreateLogger());
var inputs = new Dictionary<string, DataValueSnapshot>(StringComparer.Ordinal)
{
["a"] = new(20, 0u, DateTime.UtcNow, DateTime.UtcNow),
};
var outcome = await runner.RunAsync(Vt(NewKey(), inputs, "return (int)ctx.GetTag(\"a\").Value + 1;"), TestContext.Current.CancellationToken);
outcome.Status.ShouldBe(ScriptRunStatus.Ok);
outcome.Value.ShouldBe(21, "the in-process result, not the shadow's -1");
(await runner.WaitIdleAsync(TimeSpan.FromSeconds(10))).ShouldBeTrue();
runner.Stats().Mismatched.ShouldBe(1);
}
[Theory]
[InlineData("evaluator disposed")]
[InlineData(ScriptEvalFailureReasons.EvaluatorDisposedDuringEvaluation)]
[InlineData("evaluation cancelled (driver shutting down)")]
public void Host_lifecycle_failures_are_not_mirrored(string reason)
=> VirtualTagEvalResult.Failure(reason).ToMirroredOutcome().ShouldBeNull();
[Fact]
public void Script_results_map_onto_runner_outcomes()
{
VirtualTagEvalResult.Ok(5).ToMirroredOutcome()!.ShouldBe(ScriptRunOutcome.Ok(5));
VirtualTagEvalResult.Failure("script threw: x").ToMirroredOutcome()!.ShouldBe(ScriptRunOutcome.Failed("script threw: x"));
VirtualTagEvalResult.Unavailable("script worker restarted").ToMirroredOutcome()!.Status.ShouldBe(ScriptRunStatus.Unavailable);
}
private static class Scripts
{
public static async Task Eventually(Func<bool> probe, string what)
{
var deadline = DateTime.UtcNow + TimeSpan.FromSeconds(10);
while (DateTime.UtcNow < deadline)
{
if (probe()) return;
await Task.Delay(10);
}
throw new TimeoutException($"timed out waiting for {what}");
}
}
}
@@ -128,12 +128,52 @@ public sealed class ScriptRunnerSelectionTests
}
[Fact]
public void Shadow_is_not_implemented_yet_and_runs_in_process_with_a_warning()
public void Shadow_hands_the_selected_seams_a_shadow_runner_and_never_reports_its_pool_to_readiness()
{
// lmxopcua#780 P2. Unset Seams: VirtualTag + Calculation; alarms only when listed (same rule as OutOfProcess).
var options = new ScriptingOptions { Runner = ScriptRunnerMode.Shadow };
ScriptRunnerSelection.Validate(options, "/srv").ShouldHaveSingleItem().ShouldContain("Shadow");
using var selection = ScriptRunnerSelection.Create(options, Silent, null);
selection.OutOfProcessRunner.ShouldBeNull();
ScriptRunnerSelection.Validate(options, "/srv").ShouldContain(w => w.Contains("runs twice") && w.Contains("time-boxed diagnostic"));
using (var selection = ScriptRunnerSelection.Create(options, Silent, null))
{
var vt = selection.ForSeam(ScriptSeam.VirtualTag).ShouldBeOfType<ShadowScriptRunner>();
selection.ForSeam(ScriptSeam.Calculation).ShouldBeSameAs(vt, "one node-wide shadow");
selection.ForSeam(ScriptSeam.ScriptedAlarm).ShouldBeNull();
vt.Shadow.ShouldBeSameAs(selection.OutOfProcessRunner);
selection.Shadow.ShouldBeSameAs(vt);
selection.Status().ShouldBeNull("readiness must not see the shadow pool");
selection.ShadowStatus().ShouldNotBeNull();
}
var withAlarms = new ScriptingOptions { Runner = ScriptRunnerMode.Shadow, RunnerSeams = [ScriptSeam.ScriptedAlarm] };
using (var selection = ScriptRunnerSelection.Create(withAlarms, Silent, null))
{
selection.ForSeam(ScriptSeam.ScriptedAlarm).ShouldBeOfType<ShadowScriptRunner>();
selection.ForSeam(ScriptSeam.VirtualTag).ShouldBeNull();
}
// Out of process: no shadow, the pool's status IS readiness.
using (var oop = ScriptRunnerSelection.Create(new ScriptingOptions { Runner = ScriptRunnerMode.OutOfProcess }, Silent, null))
{
oop.Shadow.ShouldBeNull();
oop.ShadowStatus().ShouldBeNull();
oop.Status().ShouldNotBeNull();
}
}
[Fact]
public void Scripting_Shadow_binds_and_clamps()
{
var config = new ConfigurationBuilder().AddInMemoryCollection(new Dictionary<string, string?>
{
["Scripting:Runner"] = "Shadow",
["Scripting:Shadow:MaxInFlight"] = "0",
["Scripting:Shadow:MismatchLogsPerMinute"] = "5",
}).Build();
var bound = ScriptingOptionsBinding.Bind(config, out var adjustments);
bound.Runner.ShouldBe(ScriptRunnerMode.Shadow);
bound.Shadow.MaxInFlight.ShouldBe(1);
bound.Shadow.MismatchLogsPerMinute.ShouldBe(5);
adjustments.ShouldContain(a => a.Contains("Scripting:Shadow:MaxInFlight"));
}
[Fact]
@@ -106,4 +106,38 @@ public sealed class RoslynVirtualTagEvaluatorScriptRunnerTests
(await sut.EvaluateAsync("vt-1", "return (int)ctx.GetTag(\"a\").Value + 1;", Deps(41))).Value.ShouldBe(42);
sut.RunGuard.StartedRunCount.ShouldBe(1);
}
[Fact]
public async Task Under_Shadow_the_in_process_result_is_published_and_each_compiled_run_is_mirrored()
{
// lmxopcua#780 P2: the shadow answers differently (and slowly) — the published value must still be the in-process one.
var shadowRunner = new FakeRunner();
shadowRunner.Outcomes.Enqueue(ScriptRunOutcome.Ok(-1));
using var shadow = new ShadowScriptRunner(shadowRunner, log: new LoggerConfiguration().CreateLogger());
using var sut = Build(shadow);
sut.ScriptRunner.ShouldBeNull("Shadow keeps the in-process path");
sut.ScriptShadow.ShouldBeSameAs(shadow);
var result = await sut.EvaluateAsync("vt-s", "return (int)ctx.GetTag(\"a\").Value + 1;", Deps(41));
result.Success.ShouldBeTrue();
result.Value.ShouldBe(42);
sut.RunGuard.StartedRunCount.ShouldBe(1, "the in-process guard ran it");
(await shadow.WaitIdleAsync(TimeSpan.FromSeconds(10))).ShouldBeTrue();
var mirrored = shadowRunner.Invocations.ShouldHaveSingleItem();
mirrored.Key.ShouldBe("vt-s");
mirrored.Kind.ShouldBe(ScriptContextKind.VirtualTag);
mirrored.Timeout.ShouldBe(TimeSpan.FromMilliseconds(1500));
mirrored.Inputs["a"].Value.ShouldBe(41);
shadow.Mismatches.ShouldHaveSingleItem().LastSummary.ShouldBe("published Ok Int32 42; shadow Ok Int32 -1");
// The passthrough fast path runs no user code: nothing to mirror.
(await sut.EvaluateAsync("vt-p", "return ctx.GetTag(\"a\").Value;", Deps(7))).Value.ShouldBe(7);
(await shadow.WaitIdleAsync(TimeSpan.FromSeconds(10))).ShouldBeTrue();
shadowRunner.Invocations.Count.ShouldBe(1);
// A redeploy resets the shadow side too.
sut.ClearCompiledScripts();
shadowRunner.Resets.ShouldBe([ScriptContextKind.VirtualTag]);
}
}
@@ -76,4 +76,23 @@ public sealed class ScriptRunnerHealthCheckTests
(await check.CheckHealthAsync(new HealthCheckContext { Registration = registration }, CancellationToken.None))
.Status.ShouldBe(HealthStatus.Healthy);
}
[Theory]
[InlineData(ScriptRunnerState.Ready)]
[InlineData(ScriptRunnerState.Degraded)]
[InlineData(ScriptRunnerState.Unavailable)]
public void Shadow_is_healthy_whatever_its_worker_pool_does(ScriptRunnerState shadowState)
{
// lmxopcua#780 P2: under Shadow every published value is in process — the shadow pool must never move readiness.
var stats = new ZB.MOM.WW.OtOpcUa.Core.Scripting.ScriptShadowStats(10, 7, 3, 1, 2, 1, 0);
var (status, description, data) = ScriptRunnerHealthDecision.Evaluate(
null, (Status(shadowState, Shard("0", shadowState == ScriptRunnerState.Ready, 200)), stats));
status.ShouldBe(HealthStatus.Healthy);
description.ShouldContain("Shadow");
description.ShouldContain("3 mismatch(es)");
data["mode"].ShouldBe("Shadow");
data["shadow.state"].ShouldBe(shadowState.ToString());
data["shadow.mismatched"].ShouldBe(3L);
data["shadow.dropped"].ShouldBe(3L);
}
}
@@ -0,0 +1,226 @@
using System.Collections.Concurrent;
using System.Diagnostics;
using Microsoft.Extensions.Logging.Abstractions;
using Serilog;
using Shouldly;
using Xunit;
using ZB.MOM.WW.OtOpcUa.Commons.Engines;
using ZB.MOM.WW.OtOpcUa.Core.Abstractions;
using ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms;
using ZB.MOM.WW.OtOpcUa.Core.Scripting;
using ZB.MOM.WW.OtOpcUa.Driver.Calculation;
namespace ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests;
/// <summary>
/// lmxopcua#780 P2 — <c>Scripting:Runner=Shadow</c> over the REAL worker: the seams publish their in-process results
/// and mirror each compiled evaluation to the worker pool. Ordinary scripts compare equal; a deliberately divergent
/// one (it reads which process it runs in) and an unsupported return type (design §14 #11) are counted as mismatches
/// for exactly those scripts; and a runaway that only runs away in the worker is killed and quarantined THERE while
/// every published value stays the in-process one. Alarms: the transition sequence is the in-process engine's, a
/// killed shadow worker never annotates or clears a condition.
/// </summary>
[Collection(ScriptWorkerCollection.Name)]
[Trait("Category", "ScriptWorker")]
public sealed class ShadowModeTests
{
/// <summary>True only inside the ScriptWorker (its base directory is <c>script-worker/</c>): a test-only divergence.</summary>
private const string InWorker = "System.AppContext.BaseDirectory.Contains(\"script-worker\")";
private static CancellationToken Ct => TestContext.Current.CancellationToken;
private static ScriptingOptions ShadowOptions(TimeSpan? hardGrace = null)
{
var options = Scripts.Options(hardGrace: hardGrace ?? TimeSpan.FromMilliseconds(500), quarantineAfterKills: 2);
options.Runner = ScriptRunnerMode.Shadow;
return options;
}
private static CalculationEvaluator Calc(IScriptRunner? runner, TimeSpan? budget = null)
=> new(NullLogger.Instance, new ScriptRootLogger(new LoggerConfiguration().CreateLogger()),
budget ?? TimeSpan.FromSeconds(5), scriptRunner: runner);
private static Dictionary<string, DataValueSnapshot> Inputs(int i)
{
var now = DateTime.UtcNow;
DataValueSnapshot S(object v) => new(v, 0u, now, now);
return new Dictionary<string, DataValueSnapshot>(StringComparer.Ordinal)
{
["s"] = S((short)(5 + i)),
["d"] = S(1.25 * i),
["str"] = S("abc" + i),
["i"] = S(i),
["t"] = S(new DateTime(2026, 11, 10, 12, 0, 0, DateTimeKind.Utc).AddSeconds(i)),
["arr"] = S(new[] { 1.5, 2.5 * i }),
};
}
private static bool Same(VirtualTagEvalResult a, VirtualTagEvalResult b)
=> a.Success == b.Success && a.Reason == b.Reason && a.StatusCode == b.StatusCode
&& System.Collections.StructuralComparisons.StructuralEqualityComparer.Equals(a.Value, b.Value)
&& a.Value?.GetType() == b.Value?.GetType();
[Fact]
public async Task Ordinary_scripts_match_and_a_divergent_and_an_unsupported_one_are_counted_against_exactly_those_scripts()
{
var log = new CapturingSink();
await using var pool = Scripts.Runner(ShadowOptions());
using var shadow = new ShadowScriptRunner(pool, ShadowOptions(), log.CreateLogger());
using var shadowed = Calc(shadow);
using var reference = Calc(null);
shadowed.SubmitsBatches.ShouldBeFalse("Shadow keeps the in-process one-at-a-time pump, not the runner path");
var scripts = new Dictionary<string, string>(StringComparer.Ordinal)
{
["short"] = "return (short)ctx.GetTag(\"s\").Value + 1;",
["double"] = "return (double)ctx.GetTag(\"d\").Value * 2.5;",
["string"] = "return \"v=\" + ctx.GetTag(\"str\").Value;",
["intArray"] = "return new[] { (int)ctx.GetTag(\"i\").Value, 2 };",
["doubleArray"] = "var a = (double[])ctx.GetTag(\"arr\").Value; return new[] { a[1], a[0] };",
["datetime"] = "return ((DateTime)ctx.GetTag(\"t\").Value).AddSeconds(1);",
["bool"] = "return (int)ctx.GetTag(\"i\").Value > 1;",
["quality"] = "return ctx.GetTag(\"i\").StatusCode;",
["throws"] = "if ((int)ctx.GetTag(\"i\").Value >= 0) throw new InvalidOperationException(\"boom \" + ctx.GetTag(\"i\").Value); return 0;",
["divergent"] = $"return {InWorker} ? 2 : 1;",
["decimal"] = "return 1.5m;",
};
for (var i = 0; i < 3; i++)
{
foreach (var (key, source) in scripts)
{
var published = await shadowed.EvaluateAsync(key, source, Inputs(i), Ct);
var expected = await reference.EvaluateAsync(key, source, Inputs(i), Ct);
Same(published, expected).ShouldBeTrue($"{key}: Shadow publishes exactly what InProcess publishes ({published} vs {expected})");
}
(await shadow.WaitIdleAsync(TimeSpan.FromSeconds(60))).ShouldBeTrue();
}
var stats = shadow.Stats();
stats.Dropped.ShouldBe(0);
stats.ShadowUnavailable.ShouldBe(0);
stats.Compared.ShouldBe(scripts.Count * 3);
stats.Mismatched.ShouldBe(6, string.Join(Environment.NewLine, shadow.Mismatches.Select(m => $"{m.Key}: {m.LastReason} — {m.LastSummary}")));
var mismatches = shadow.Mismatches.ToDictionary(m => m.Key);
mismatches.Keys.ShouldBe(["decimal", "divergent"], ignoreOrder: true);
mismatches["divergent"].LastReason.ShouldBe("value");
mismatches["divergent"].LastSummary.ShouldBe("published Ok Int32 1; shadow Ok Int32 2");
mismatches["divergent"].Count.ShouldBe(3);
mismatches["decimal"].LastReason.ShouldBe("unsupported_type");
mismatches["decimal"].LastSummary.ShouldContain("System.Decimal");
var lines = log.Events.Where(e => e.MessageTemplate.Text.StartsWith("Script shadow mismatch", StringComparison.Ordinal)).ToArray();
lines.Length.ShouldBe(2, "one line per script and reason");
lines.ShouldAllBe(e => e.Level == Serilog.Events.LogEventLevel.Warning);
}
[Fact]
public async Task A_runaway_that_runs_away_only_in_the_worker_is_killed_and_quarantined_there_and_never_reaches_a_published_value()
{
var log = new CapturingSink();
await using var pool = Scripts.Runner(ShadowOptions(TimeSpan.FromMilliseconds(400)), log.CreateLogger());
using var shadow = new ShadowScriptRunner(pool, ShadowOptions(), log.CreateLogger());
using var shadowed = Calc(shadow, TimeSpan.FromMilliseconds(300));
const string runaway = $"if ({InWorker}) {{ while (true) {{ }} }} return (int)ctx.GetTag(\"i\").Value * 2;";
const string sibling = "return (int)ctx.GetTag(\"i\").Value + 100;";
var slowest = TimeSpan.Zero;
var deadline = DateTime.UtcNow + TimeSpan.FromSeconds(90);
var i = 0;
for (; !pool.QuarantinedKeys(ScriptContextKind.Calculation).Contains("runaway"); i++)
{
if (DateTime.UtcNow > deadline)
throw new TimeoutException("the shadow never quarantined the runaway:" + Environment.NewLine + string.Join(Environment.NewLine, log.Rendered));
var sw = Stopwatch.StartNew();
var a = await shadowed.EvaluateAsync("runaway", runaway, Inputs(i), Ct);
var b = await shadowed.EvaluateAsync("sibling", sibling, Inputs(i), Ct);
if (sw.Elapsed > slowest) slowest = sw.Elapsed;
a.ShouldBe(VirtualTagEvalResult.Ok(i * 2), "published from the in-process run");
b.ShouldBe(VirtualTagEvalResult.Ok(i + 100));
await Task.Delay(100, Ct);
}
// Still publishing correctly after the shadow quarantined it, and never quarantined on the published side.
for (var j = i; j < i + 5; j++)
(await shadowed.EvaluateAsync("runaway", runaway, Inputs(j), Ct)).ShouldBe(VirtualTagEvalResult.Ok(j * 2));
shadowed.QuarantinedScripts.ShouldBeEmpty();
slowest.ShouldBeLessThan(TimeSpan.FromMilliseconds(250), "a published evaluation never waits for its shadow");
log.Rendered.ShouldContain(l => l.Contains("exceeded its hard deadline"));
(await shadow.WaitIdleAsync(TimeSpan.FromSeconds(30))).ShouldBeTrue();
var record = shadow.Mismatches.ShouldHaveSingleItem("the sibling on the killed shard is a victim (not compared), never a mismatch");
record.Key.ShouldBe("runaway");
record.LastReason.ShouldBe("status");
record.LastSummary.ShouldContain("shadow Failed [budget]");
shadow.Stats().DroppedKeyBusy.ShouldBeGreaterThan(0, "triggers while its shadow run was still going were dropped, not queued");
}
private static ScriptedAlarmDefinition Alarm(string id, string predicate) =>
new(AlarmId: id, EquipmentPath: "Plant/Line1/Reactor", AlarmName: id, Kind: AlarmKind.AlarmCondition,
Severity: AlarmSeverity.High, MessageTemplate: "condition", PredicateScriptSource: predicate);
private static ScriptedAlarmEngine Engine(TestUpstream up, IScriptRunner? runner)
{
var logger = new LoggerConfiguration().CreateLogger();
return new ScriptedAlarmEngine(up, new InMemoryAlarmStateStore(), new ScriptLoggerFactory(logger), logger,
scriptTimeout: TimeSpan.FromSeconds(2), scriptRunner: runner);
}
[Fact]
public async Task Alarms_in_shadow_transition_exactly_as_in_process_and_a_killed_shadow_worker_never_touches_a_condition()
{
await using var pool = Scripts.Runner(ShadowOptions());
using var shadow = new ShadowScriptRunner(pool, ShadowOptions(), new LoggerConfiguration().CreateLogger());
var up = new TestUpstream();
var refUp = new TestUpstream();
up.Set("x", 0);
refUp.Set("x", 0);
using var engine = Engine(up, shadow);
using var reference = Engine(refUp, null);
engine.ScriptRunner.ShouldBeNull("Shadow keeps the in-process engine path");
var events = new ConcurrentQueue<ScriptedAlarmEvent>();
var refEvents = new ConcurrentQueue<ScriptedAlarmEvent>();
engine.OnEvent += (_, e) => events.Enqueue(e);
reference.OnEvent += (_, e) => refEvents.Enqueue(e);
ScriptedAlarmDefinition[] defs =
[
Alarm("high", "return (int)ctx.GetTag(\"x\").Value > 5;"),
Alarm("divergent", $"return {InWorker};"),
];
await engine.LoadAsync(defs, Ct);
await reference.LoadAsync(defs, Ct);
async Task Push(int x)
{
up.Push("x", x);
refUp.Push("x", x);
await Scripts.Eventually(() => events.Count == refEvents.Count, TimeSpan.FromSeconds(10), "both engines' emissions");
await Task.Delay(100, Ct);
}
await Push(10);
await Push(2);
(await shadow.WaitIdleAsync(TimeSpan.FromSeconds(30))).ShouldBeTrue();
// kill -9 the shadow's worker: the published engine neither annotates nor clears anything because of it.
var worker = pool.Shards[0].Current.ShouldNotBeNull();
Process.GetProcessById(worker.Pid).Kill();
await Push(12);
await Push(0);
(await shadow.WaitIdleAsync(TimeSpan.FromSeconds(30))).ShouldBeTrue();
await Push(9);
(await shadow.WaitIdleAsync(TimeSpan.FromSeconds(30))).ShouldBeTrue();
events.Select(e => (e.AlarmId, e.Emission, e.WorstInputStatusCode))
.ShouldBe(refEvents.Select(e => (e.AlarmId, e.Emission, e.WorstInputStatusCode)), "the in-process engine's sequence, exactly");
events.Count(e => e is { AlarmId: "high", Emission: EmissionKind.Activated }).ShouldBe(3);
events.ShouldNotContain(e => e.WorstInputStatusCode != 0u, "no shadow-side failure annotates a published condition");
engine.GetState("divergent")!.Active.ShouldBe(AlarmActiveState.Inactive, "the in-process predicate (false) drives it");
var record = shadow.Mismatches.ShouldHaveSingleItem();
record.Key.ShouldBe("divergent");
record.Kind.ShouldBe(ScriptContextKind.AlarmPredicate);
record.LastSummary.ShouldBe("published Ok Boolean False; shadow Ok Boolean True");
shadow.Stats().Matched.ShouldBeGreaterThan(0);
}
}