diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/ShadowModeTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/ShadowModeTests.cs index 9fdda629f..b447ad67c 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/ShadowModeTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/ShadowModeTests.cs @@ -42,8 +42,11 @@ public sealed class ShadowModeTests return options; } - private static CalculationEvaluator Calc(IScriptRunner? runner, TimeSpan? budget = null) - => new(NullLogger.Instance, new ScriptRootLogger(new LoggerConfiguration().CreateLogger()), + private static CalculationEvaluator Calc(IScriptRunner? runner, TimeSpan? budget = null, CapturingSink? scriptLog = null) + => new(NullLogger.Instance, + new ScriptRootLogger(scriptLog is null + ? new LoggerConfiguration().CreateLogger() + : new LoggerConfiguration().MinimumLevel.Verbose().WriteTo.Sink(scriptLog).CreateLogger()), budget ?? TimeSpan.FromSeconds(5), scriptRunner: runner); private static Dictionary Inputs(int i) @@ -147,23 +150,54 @@ public sealed class ShadowModeTests 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(); + var scriptLog = new CapturingSink(); await using var pool = Scripts.Runner(ShadowOptions(TimeSpan.FromMilliseconds(400)), log.CreateLogger()); var gate = new GatedShadow(pool); using var shadow = new ShadowScriptRunner(gate, ShadowOptions(), log.CreateLogger()); - using var shadowed = Calc(shadow, TimeSpan.FromMilliseconds(300)); + using var shadowed = Calc(shadow, RunawayRunBudget, scriptLog); 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 i = 0; + var testClock = Stopwatch.StartNew(); // Off the test thread with a liveness bound (not a latency bound): a Mirror that waited for its held shadow would // otherwise hang the test instead of failing it. Task Publish(string key, string source) => Task.Run(() => shadowed.EvaluateAsync(key, source, Inputs(i), Ct), Ct).WaitAsync(TimeSpan.FromSeconds(30), Ct); + // lmxopcua#811: a wrong published value must say what it was and what the host was doing — the one loaded + // failure seen so far was unattributable because only "should be Ok(…)" survived a truncated log. + async Task Expect(string phase, string key, string source, int expected) + { + var before = PublishProbe.Take(shadowed, shadow); + var sw = Stopwatch.StartNew(); + var published = await Publish(key, source); + sw.Stop(); + if (published == VirtualTagEvalResult.Ok(expected)) return; + var after = PublishProbe.Take(shadowed, shadow); + published.ShouldBe(VirtualTagEvalResult.Ok(expected), + $"{phase}: {key} (iteration {i}) published the wrong value — " + + $"Success={published.Success}, Value={published.Value ?? "null"} ({published.Value?.GetType().Name ?? "-"}), " + + $"Reason={published.Reason ?? "null"}, StatusCode={(published.StatusCode is { } sc ? $"0x{sc:X8}" : "null")}, " + + $"RetryWhen={(published.RetryWhen is null ? "null" : "set")}; publish took {sw.Elapsed.TotalMilliseconds:F0} ms " + + $"against a {RunawayRunBudget.TotalMilliseconds:F0} ms run budget, at t+{testClock.Elapsed.TotalSeconds:F1} s; " + + $"quarantined={(shadowed.RunGuard.IsQuarantined(key, out var why) ? why : "no")}" + Environment.NewLine + + $" before: {before}" + Environment.NewLine + + $" after: {after}" + Environment.NewLine + + " script log (last 20):" + Lines(scriptLog) + Environment.NewLine + + " runner log (last 20):" + Lines(log)); + } + + static string Lines(CapturingSink sink) + => sink.Events.IsEmpty + ? " (none)" + : Environment.NewLine + " " + string.Join(Environment.NewLine + " ", + sink.Events.TakeLast(20).Select(e => $"{e.Timestamp:HH:mm:ss.fff} {e.Level} {e.RenderMessage()}")); + async Task PublishBoth(string phase) { - (await Publish("runaway", runaway)).ShouldBe(VirtualTagEvalResult.Ok(i * 2), $"{phase}: published from the in-process run"); - (await Publish("sibling", sibling)).ShouldBe(VirtualTagEvalResult.Ok(i + 100), phase); + await Expect($"{phase}: published from the in-process run", "runaway", runaway, i * 2); + await Expect(phase, "sibling", sibling, i + 100); i++; } @@ -224,6 +258,37 @@ public sealed class ShadowModeTests shadow.Stats().DroppedKeyBusy.ShouldBeGreaterThan(0, "triggers while its shadow run was still going were dropped, not queued"); } + /// + /// The in-process run budget of the runaway test's published path. It is also the soft deadline the shadow worker + /// answers the runaway at (the mirrored invocation carries the seam's budget), so it sets how long the shadow runs + /// away before it is killed. + /// lmxopcua#811: it was 300 ms, and under heavy CPU load (32 yes processes, the test at nice 20, load + /// average 300+) 3 of 8 runs failed because the SIBLING's shadow — a one-line script — missed that soft deadline + /// in the worker ("shadow Failed [budget] script timed out after 0.3s"), which the comparison rightly records as a + /// sibling mismatch. The out-of-process soft deadline is armed at submit, so it also covers the pipe round trip + /// and the starved worker being scheduled at all. The published values were never wrong. 2 s is the production + /// default budget; the runaway still runs away (and is killed at T + HardGrace) whatever T is, so nothing the test + /// proves depends on T being short — only its runtime does (two kills, ~5 s). + /// + private static readonly TimeSpan RunawayRunBudget = TimeSpan.FromSeconds(2); + + /// Host-side state around one published evaluation, for a self-diagnosing failure message (lmxopcua#811). + private readonly record struct PublishProbe( + int GuardInFlight, long GuardStarted, long GuardRefused, long GuardQuarantined, int PoolThreads, long PoolPending, + int Gen0, int Gen1, int Gen2, double GcPauseMs, ScriptShadowStats Shadow) + { + public static PublishProbe Take(CalculationEvaluator evaluator, ShadowScriptRunner shadow) => new( + evaluator.RunGuard.InFlightCount, evaluator.RunGuard.StartedRunCount, evaluator.RunGuard.RefusedWhileRunningCount, + evaluator.RunGuard.QuarantinedCount, ThreadPool.ThreadCount, ThreadPool.PendingWorkItemCount, + GC.CollectionCount(0), GC.CollectionCount(1), GC.CollectionCount(2), GC.GetTotalPauseDuration().TotalMilliseconds, + shadow.Stats()); + + public override string ToString() => + $"guard inFlight={GuardInFlight} started={GuardStarted} refused={GuardRefused} quarantined={GuardQuarantined}; " + + $"pool threads={PoolThreads} pending={PoolPending}; gc gen0/1/2={Gen0}/{Gen1}/{Gen2} totalPause={GcPauseMs:F1} ms; " + + $"shadow {Shadow}"; + } + /// /// A pass-through shadow runner with test-owned barriers on one key's next run: it holds that run before it reaches /// the inner runner, and holds the inner runner's outcome before returning it. Everything else forwards untouched.