Merge fix/811-shadow-sibling-load

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<string, DataValueSnapshot> 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<VirtualTagEvalResult> 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");
     }
 
+    /// <summary>
+    ///     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.
+    ///     <para>lmxopcua#811: it was 300 ms, and under heavy CPU load (32 <c>yes</c> 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).</para>
+    /// </summary>
+    private static readonly TimeSpan RunawayRunBudget = TimeSpan.FromSeconds(2);
+
+    /// <summary>Host-side state around one published evaluation, for a self-diagnosing failure message (lmxopcua#811).</summary>
+    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}";
+    }
+
     /// <summary>
     ///     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.