test(scriptworker): self-diagnosing ShadowModeTests runaway failures; 2 s run budget (#811)

A wrong published value now reports its Success/Value/Reason/StatusCode, the
publish's wall time against the run budget, the run guard's in-flight /
refused / quarantined counters, thread-pool and GC state around the call,
the shadow stats, and the tails of the script and runner logs.

Reproduced under heavy load (32 `yes`, test at nice 20, load avg 300+):
3 of 8 runs failed, every one because the SIBLING's shadow run missed the
300 ms soft deadline in the starved worker ("shadow Failed [budget] script
timed out after 0.3s") and was rightly recorded as a sibling mismatch. No
published value was ever wrong. The out-of-process soft deadline is armed at
submit, so it covers the pipe round trip and worker scheduling too.

The run budget (which is also the worker's soft deadline) goes to the 2 s
production default; no assertion changes. The runaway still runs away and is
killed at T + HardGrace, so nothing the test proves depends on T being short.

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)
+    private static CalculationEvaluator Calc(IScriptRunner? runner, TimeSpan? budget = null, CapturingSink? scriptLog = null)
-        => new(NullLogger.Instance, new ScriptRootLogger(new LoggerConfiguration().CreateLogger()),
+        => 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 Expect($"{phase}: published from the in-process run", "runaway", runaway, i * 2);
-            (await Publish("sibling", sibling)).ShouldBe(VirtualTagEvalResult.Ok(i + 100), phase);
+            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.