From 1696e34868ec5ae100e068e0604951bc59f3a4ab Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Wed, 11 Nov 2026 03:50:12 -0500 Subject: [PATCH 1/6] test(scripting): stuck-orphan quarantine test trusts the guard's young/stuck verdict, not the test's stopwatch (#843) Reproduced 4/10 alone under 28 CPU burners (load ~100-250): outcomes were timeout, refused, refused, quarantined... - the guard right, but the test labelled a refusal 'young' only if its OWN stopwatch (started before the first trigger) read < 600 ms, and the first trigger's dispatch + sibling + cadence ate that. A ScriptRunRefusedException IS the young-orphan answer (behind a stuck orphan the guard quarantines instead), so: any refusal before the quarantine proves the rule; stuck factor 50 (3 s) so the second trigger lands young with room; loop until three quarantined answers; the one remaining wall-clock check runs the safe way (quarantine time on the test's stopwatch >= threshold - the orphan is never older than it); runaway is a held spin so it cannot end on its own; failures print the timeline. After: 10/10 under the same load. Co-Authored-By: Claude --- .../ScriptRunGuardTests.cs | 85 +++++++++++++------ 1 file changed, 60 insertions(+), 25 deletions(-) diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs index 2e9b656dc..d7c4bb7f4 100644 --- a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs @@ -162,7 +162,7 @@ public sealed class ScriptRunGuardTests /// while(true) script on a 1 Hz trigger leaked one pool thread per trigger — 30 orphans after 30 /// triggers, trending toward pool starvation. Now the first trigger's orphan is the only one; later /// triggers are refused while it is young, and once it has run longer than - /// × the timeout (10 × 60 ms here — the + /// × the timeout (50 × 60 ms here — the /// trigger cadence is scaled down from 1 Hz to keep the test short) the next refusal quarantines it. /// A healthy sibling keeps evaluating throughout (the positive control an absence assertion needs). /// @@ -171,44 +171,79 @@ public sealed class ScriptRunGuardTests /// / ): moves with /// every parallel test class on a loaded machine, so it is kept as a coarse secondary check only — /// it must stay far below the 30 the leak would have produced. + /// lmxopcua#843 (failed 2/4 full-suite runs at load average 140–280; 2 of the first 4 runs alone under + /// 28 CPU burners): this used to label a refusal "young" by the TEST's stopwatch, started before the first + /// trigger, and demand one inside 600 ms (10 × 60 ms). Under load the first trigger's dispatch, the sibling + /// and the cadence ate those 600 ms, so the guard's answers were timeout, refused, refused, + /// quarantined… — the guard right, the test's label wrong. Now: the guard is the authority on the + /// orphan's age (a IS the young-orphan answer; behind a stuck one + /// it quarantines instead), the stuck factor is 50 (3 s) so the second trigger has ample room to land + /// while the orphan is young, the loop runs until the quarantine instead of a fixed 30 triggers, and the + /// one wall-clock check left runs the safe way round — the orphan is never older than the test's + /// stopwatch, so a quarantine before 3 s on it is early on any box. The runaway is a HELD spin (released + /// at the end) so it cannot end on its own and become a second dispatch on a slow box. /// [Fact] public async Task Runaway_script_leaves_one_orphan_is_quarantined_once_stuck_and_a_sibling_keeps_evaluating() { - var guard = new ScriptRunGuard(); - using var spin = Compile(SpinScript); + const double stuckFactor = 50; + var guard = new ScriptRunGuard(new ScriptingOptions { StuckOrphanQuarantineFactor = stuckFactor }); + using var spin = Compile(BriefSpinScript); using var fast = Compile(FastScript); var ct = TestContext.Current.CancellationToken; + var held = new FakeScriptContext(); var threadsBefore = ThreadPool.ThreadCount; - var stuckAfter = ShortTimeout * ScriptingOptions.DefaultStuckOrphanQuarantineFactor; // 600 ms + var stuckAfter = ShortTimeout * stuckFactor; // 3 s var healthyResults = new List(); var outcomes = new List(); + var timeline = new List(); + TimeSpan? quarantinedAt = null; var sw = System.Diagnostics.Stopwatch.StartNew(); - for (var trigger = 0; trigger < 30; trigger++) + try { - try { await Run(guard, "runaway", SpinScript, spin, ShortTimeout, ct); outcomes.Add("value"); } - catch (ScriptTimeoutException) { outcomes.Add("timeout"); } - catch (ScriptRunRefusedException) { outcomes.Add(sw.Elapsed < stuckAfter ? "refused-young" : "refused"); } - catch (ScriptQuarantinedException) { outcomes.Add("quarantined"); } + // At least 30 triggers (the leak's scale), then until three quarantined answers; capped as a hang guard. + for (var trigger = 0; trigger < 1_000 && (trigger < 30 || outcomes.Count(o => o == "quarantined") < 3); trigger++) + { + string outcome; + try { await Run(guard, "runaway", BriefSpinScript, spin, ShortTimeout, ct, held); outcome = "value"; } + catch (ScriptTimeoutException) { outcome = "timeout"; } + catch (ScriptRunRefusedException) { outcome = "refused"; } + catch (ScriptQuarantinedException) { outcome = "quarantined"; quarantinedAt ??= sw.Elapsed; } + outcomes.Add(outcome); + timeline.Add($"#{trigger} {outcome} @{sw.ElapsedMilliseconds}ms"); - healthyResults.Add(await Run(guard, "healthy", FastScript, fast, ct: ct)); - await Task.Delay(50, ct); + healthyResults.Add(await Run(guard, "healthy", FastScript, fast, ct: ct)); + await Task.Delay(50, ct); + } + + var triggers = outcomes.Count; + var diagnostics = $"timeline: {string.Join(", ", timeline)}"; + guard.InFlightCount.ShouldBe(1, "exactly one orphaned run — the first trigger's — may be executing; " + diagnostics); + guard.StartedRunCount.ShouldBe(1 + triggers, "one dispatch for the runaway script, one per trigger for the healthy sibling; " + diagnostics); + outcomes[0].ShouldBe("timeout", diagnostics); + var firstQuarantine = outcomes.IndexOf("quarantined"); + firstQuarantine.ShouldBeGreaterThan(0, "the stuck orphan was never quarantined; " + diagnostics); + outcomes.Take(firstQuarantine).Skip(1).ShouldAllBe(o => o == "refused", diagnostics); + outcomes.Take(firstQuarantine).ShouldContain("refused", + "a young orphan is only refused — a short overrun is not quarantined; " + diagnostics); + outcomes.Skip(firstQuarantine).ShouldAllBe(o => o == "quarantined", diagnostics); + quarantinedAt!.Value.ShouldBeGreaterThanOrEqualTo(stuckAfter, + $"the orphan is never older than the test's stopwatch, so a quarantine before {stuckFactor}x the budget on it is early; " + diagnostics); + guard.IsQuarantined("runaway", out var reason).ShouldBeTrue("the orphan outlived its stuck threshold"); + reason!.ShouldContain("stuck"); + guard.QuarantinedCount.ShouldBe(1); + healthyResults.ShouldAllBe(v => v == 42); + healthyResults.Count.ShouldBe(triggers); + + var threadDelta = ThreadPool.ThreadCount - threadsBefore; + threadDelta.ShouldBeLessThan(15, $"{triggers} leaked orphans would have grown the pool by ~{triggers} threads"); } - - guard.InFlightCount.ShouldBe(1, "exactly one orphaned run — the first trigger's — may be executing"); - guard.StartedRunCount.ShouldBe(1 + 30, "one dispatch for the runaway script, thirty for the healthy sibling"); - outcomes[0].ShouldBe("timeout"); - outcomes.ShouldContain("refused-young", "a young orphan is only refused — a short overrun is not quarantined"); - guard.IsQuarantined("runaway", out var reason).ShouldBeTrue("the orphan outlived 10x its budget: it is stuck"); - reason!.ShouldContain("stuck"); - outcomes[^1].ShouldBe("quarantined"); - guard.QuarantinedCount.ShouldBe(1); - healthyResults.ShouldAllBe(v => v == 42); - healthyResults.Count.ShouldBe(30); - - var threadDelta = ThreadPool.ThreadCount - threadsBefore; - threadDelta.ShouldBeLessThan(15, "thirty leaked orphans would have grown the pool by ~30 threads"); + finally + { + held.Released = true; + } + await WaitForIdle(guard); } /// From 7095e128e33268c6112514ed71e0ecb6781fd591 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Wed, 11 Nov 2026 03:50:12 -0500 Subject: [PATCH 2/6] test(historian): shared ProcessedConformance asserts DurationGood/DurationBad on every SQL backend (#840) #820 served DurationGood/DurationBad (ms) on SqlServer/QuestDB but only QualityMixConformance asserted them. The shared Processed suite now covers them like the percentages: hand values over tag A (20000/10000/20000/BadNoData and 0/10000/0) with statuses + timestamps and Duration = Percent x interval; the SDK-calculator parity theory (forward/reverse/truncated); outage markers; the only-Bad interval; string tags; and the time-weighted row cap. Live: SqlServer.IntegrationTests 211/211 (central SQL), QuestDb.IntegrationTests 249 passed / 1 skipped (shared /opt/otopcua-questdb fixture). Co-Authored-By: Claude --- .../ProcessedConformance.cs | 36 +++++++++++++++++++ 1 file changed, 36 insertions(+) diff --git a/tests/Drivers/Historian.Conformance/ProcessedConformance.cs b/tests/Drivers/Historian.Conformance/ProcessedConformance.cs index cb220b5b9..a7cc74e4d 100644 --- a/tests/Drivers/Historian.Conformance/ProcessedConformance.cs +++ b/tests/Drivers/Historian.Conformance/ProcessedConformance.cs @@ -127,6 +127,27 @@ public abstract class ProcessedConformance : ConformanceBase s.Select(x => x.StatusCode).ShouldBe([GoodCalc, GoodCalc, GoodCalc | 0x4u, NoDataCalc]); } + [Theory] + [InlineData(HistoryAggregateType.DurationGood, 20_000d, 10_000d, 20_000d)] + [InlineData(HistoryAggregateType.DurationBad, 0d, 10_000d, 0d)] + public async Task Duration_aggregates_are_the_region_times_in_milliseconds(HistoryAggregateType agg, double b0, double b1, + double b2) + { + // #820/#840 (Part 13 §5.4.3.31/32): the same stepped regions as the percentages above, as an OPC UA Duration (ms) — + // B1: [20,30) Bad = 10 000 ms, [30,40) Good = 10 000 ms; B2 runs from the last sample (+40) to the interval end, + // Partial; B3 is after the end of the data ⇒ BadNoData. Same statuses as PercentGood/PercentBad. + await ConformanceData.SeedAAsync(B); + var s = (await ReadA(agg)).Samples; + s.Select(x => x.Value).ShouldBe([b0, b1, b2, null]); + s.Select(x => x.StatusCode).ShouldBe([GoodCalc, GoodCalc, GoodCalc | Partial, NoDataCalc]); + s.Select(x => x.SourceTimestampUtc).ShouldBe([B.Round(At(0)), B.Round(At(20)), B.Round(At(40)), B.Round(At(60))]); + // Duration = Percent × interval ÷ 100, interval by interval (one oracle for both families). + var percent = (await ReadA(agg == HistoryAggregateType.DurationGood + ? HistoryAggregateType.PercentGood : HistoryAggregateType.PercentBad)).Samples; + for (var i = 0; i < 3; i++) + ((double)s[i].Value!).ShouldBe((double)percent[i].Value! * Twenty.TotalMilliseconds / 100, 1e-9, $"bucket {i}"); + } + [Fact] public async Task Actual_time_aggregates_stamp_the_sample_time() { @@ -415,6 +436,7 @@ public abstract class ProcessedConformance : ConformanceBase HistoryAggregateType.Range, HistoryAggregateType.Start, HistoryAggregateType.End, HistoryAggregateType.Delta, HistoryAggregateType.MinimumActualTime, HistoryAggregateType.MaximumActualTime, HistoryAggregateType.PercentGood, HistoryAggregateType.PercentBad, + HistoryAggregateType.DurationGood, HistoryAggregateType.DurationBad, // #820/#840 }) { var ours = (await src.ReadProcessedAsync("P", At(from), At(to), interval, agg, Ct)).Samples.ToList(); @@ -481,6 +503,9 @@ public abstract class ProcessedConformance : ConformanceBase (await One(HistoryAggregateType.Start)).Value.ShouldBe(10d); // #680: duration-based — [0,5) Good, [5,10) Bad, [10,20) Good (no end bound: the last region runs to the interval end). ((double)(await One(HistoryAggregateType.PercentBad)).Value!).ShouldBe(25d, 1e-9); + // #840: the same regions in ms — [5,10) Bad = 5 000, [0,5) + [10,20) Good = 15 000. + ((double)(await One(HistoryAggregateType.DurationBad)).Value!).ShouldBe(5_000d, 1e-9); + ((double)(await One(HistoryAggregateType.DurationGood)).Value!).ShouldBe(15_000d, 1e-9); } [Fact] @@ -507,6 +532,11 @@ public abstract class ProcessedConformance : ConformanceBase pb.Value.ShouldBe(100d); // The tag's data starts (+1) inside the interval ⇒ Partial on the non-Bad percentage (#677). pb.StatusCode.ShouldBe(GoodCalc | 0x4u); + // #840: DurationBad is the same statement in ms — the whole 20 s interval — with the same status. + var db = await One(HistoryAggregateType.DurationBad); + db.Value.ShouldBe(20_000d); + db.StatusCode.ShouldBe(GoodCalc | 0x4u); + (await One(HistoryAggregateType.DurationGood)).Value.ShouldBe(0d); } [Fact] @@ -662,6 +692,7 @@ public abstract class ProcessedConformance : ConformanceBase (await One(HistoryAggregateType.Start)).Value.ShouldBe("a"); (await One(HistoryAggregateType.End)).Value.ShouldBe("b"); (await One(HistoryAggregateType.PercentGood)).Value.ShouldBe(100d); + (await One(HistoryAggregateType.DurationGood)).Value.ShouldBe(20_000d); // #840: quality, not value — strings too foreach (var a in new[] { HistoryAggregateType.Average, HistoryAggregateType.Minimum, HistoryAggregateType.Maximum, @@ -845,6 +876,11 @@ public abstract class ProcessedConformance : ConformanceBase // #680: PercentGood/PercentBad are duration-based, served by the same window stream ⇒ capped too. (await Should.ThrowAsync( () => under.ReadProcessedAsync("A", At(0), At(80), Twenty, HistoryAggregateType.PercentGood, Ct))).Limit.ShouldBe(4); + // #820/#840: DurationGood/DurationBad ride the same window stream ⇒ capped too. + (await Should.ThrowAsync( + () => under.ReadProcessedAsync("A", At(0), At(80), Twenty, HistoryAggregateType.DurationGood, Ct))).Limit.ShouldBe(4); + (await Should.ThrowAsync( + () => under.ReadProcessedAsync("A", At(0), At(80), Twenty, HistoryAggregateType.DurationBad, Ct))).Limit.ShouldBe(4); // Pushed-down (per-sample) aggregates are not capped; the bound rows outside the window do not count. (await under.ReadProcessedAsync("A", At(0), At(80), Twenty, HistoryAggregateType.Average, Ct)).Samples.Count.ShouldBe(4); (await B.CreateDataSource(3).ReadProcessedAsync("W", At(0), At(80), Twenty, HistoryAggregateType.TimeAverage, Ct)) From c3cf11c5e4acde789775711aa47d0746a0807877 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Wed, 11 Nov 2026 03:50:12 -0500 Subject: [PATCH 3/6] ci(questdb): CI keeps its throwaway QuestDB but reads the image pin from the shared fixture's compose file (#841) Decision: CI stays hermetic (no dependency on the 10.100.0.35 box or its state), but must run the same engine. integration-fixtures.sh now takes the questdb/questdb: line from the #822 fixture compose file (10.0.1 today, same as the docker-dev overlay) and fails 'up' if it is missing; CI_QDB_IMAGE overrides for a trial. Documented in scripts/ci/README.md. Co-Authored-By: Claude --- scripts/ci/README.md | 10 +++++++++- scripts/ci/integration-fixtures.sh | 15 ++++++++++++++- 2 files changed, 23 insertions(+), 2 deletions(-) diff --git a/scripts/ci/README.md b/scripts/ci/README.md index 567fb2ff4..9ee3a444f 100644 --- a/scripts/ci/README.md +++ b/scripts/ci/README.md @@ -70,7 +70,15 @@ Neither touches `v2-ci.yml`; each has its own concurrency group (`lmxopcua-v2-in QuestDB and opc-plc — plus a port-NAT opc-plc (`otopcua-ci-opcplc-nat`, host 50110 → 50000, private `.invalid` advertised host, `OPCUA_NAT_ENDPOINT`, #813) — (`otopcua-ci-*`, non-default host ports), exports the env vars the fixtures read, and `down` removes them. It uses plain `docker run`, not `services:` (act_runner support is undocumented and - Postgres needs a seed step); the only runner requirement is a docker daemon. Runs the Sql, Historian.SqlServer, + Postgres needs a seed step); the only runner requirement is a docker daemon. + **QuestDB is a throwaway container by decision (#841), not the shared `/opt/otopcua-questdb` fixture (#822):** CI stays + hermetic — no dependency on the 10.100.0.35 box, no state left by a developer's runs, nothing a concurrent CI job can + share. What must not differ is the engine, so `integration-fixtures.sh` reads the image tag from the shared fixture's + compose file (`tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Historian.QuestDb.IntegrationTests/Docker/docker-compose.yml`, + currently `questdb/questdb:10.0.1`, the same pin as `docker-dev/docker-compose.questdb.yml`) instead of hard-coding + one, and fails `up` if that line is missing. Upgrade QuestDB by bumping the compose file (and the docker-dev overlay); + `CI_QDB_IMAGE` overrides the image for a one-off trial. Both run QuestDB's defaults (incl. + `cairo.ttl.use.wall.clock=true`, which the historian relies on). Runs the Sql, Historian.SqlServer, Historian.QuestDb, OpcUaClient and OpcUaClient.Browser `*.IntegrationTests` with `MIN_EXECUTED=440`. Local run: 468 executed / 8 skipped (Oracle x2, the blackhole `docker pause` gate, one QuestDB stress test, 4 others), about 4.5 min of test time, QuestDB the longest (~3.3 min). Not covered (no pullable image or diff --git a/scripts/ci/integration-fixtures.sh b/scripts/ci/integration-fixtures.sh index 8da099e3b..4a4a8effd 100755 --- a/scripts/ci/integration-fixtures.sh +++ b/scripts/ci/integration-fixtures.sh @@ -29,6 +29,18 @@ SA_PASSWORD="${CI_SA_PASSWORD:-Ci_throwaway_Pw1}" PG_PASSWORD="${CI_PG_PASSWORD:-Ci_throwaway_pg1}" NAMES=(otopcua-ci-mssql otopcua-ci-pg otopcua-ci-questdb otopcua-ci-opcplc otopcua-ci-opcplc-nat) ROOT="$(cd "$(dirname "${BASH_SOURCE[0]}")/../.." && pwd)" +# #841: CI keeps its OWN throwaway QuestDB (hermetic — never the shared /opt/otopcua-questdb fixture), but runs the +# SAME image the shared fixture's compose file pins, read from that file so the two cannot drift. CI_QDB_IMAGE +# overrides it only to trial an upgrade. +QDB_COMPOSE="$ROOT/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Historian.QuestDb.IntegrationTests/Docker/docker-compose.yml" + +questdb_image() { + if [ -n "${CI_QDB_IMAGE:-}" ]; then echo "$CI_QDB_IMAGE"; return; fi + local img + img="$(sed -n 's/^[[:space:]]*image:[[:space:]]*\(questdb\/questdb:[^[:space:]]*\).*/\1/p' "$QDB_COMPOSE" | head -n 1)" + if [ -z "$img" ]; then echo "no questdb/questdb: image line in $QDB_COMPOSE" >&2; return 1; fi + echo "$img" +} fixture_host() { if [ -n "${FIXTURE_HOST:-}" ]; then echo "$FIXTURE_HOST"; return; fi @@ -52,6 +64,7 @@ wait_for() { # up() { command -v docker >/dev/null || { echo "docker not available" >&2; exit 1; } + local qdb_image; qdb_image="$(questdb_image)" down docker run -d --name otopcua-ci-mssql -e ACCEPT_EULA=Y -e MSSQL_PID=Developer \ -e "MSSQL_SA_PASSWORD=$SA_PASSWORD" -p "$SQL_PORT:1433" \ @@ -59,7 +72,7 @@ up() { docker run -d --name otopcua-ci-pg -e "POSTGRES_PASSWORD=$PG_PASSWORD" -e POSTGRES_DB=sqlpollfixture \ -p "$PG_PORT:5432" postgres:17-alpine >/dev/null docker run -d --name otopcua-ci-questdb -p "$QDB_PORT:8812" -p "$QDB_HTTP_PORT:9000" \ - questdb/questdb:10.0.1 >/dev/null + "$qdb_image" >/dev/null docker run -d --name otopcua-ci-opcplc -p "$OPC_PORT:$OPC_PORT" \ mcr.microsoft.com/iotedge/opc-plc:2.14.10 --pn="$OPC_PORT" --ut --aa --alm >/dev/null # Mirrors tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.OpcUaClient.IntegrationTests/Docker/nat/docker-compose.yml. From 4cd648b0299a1fab5294b8363bdf90aa8928c5a3 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Wed, 11 Nov 2026 04:36:29 -0500 Subject: [PATCH 4/6] test(scriptworker): cold-burst heartbeat test kills at production's 3 s silence limit, self-diagnosing (#843) Reproduced 10/10 under 28 CPU burners (load 100-250): every run killed for 157-309 ms of silence with every compile on its dedicated thread - the OS scheduler, not the pool. A 1 s limit still failed 1/10 at load ~300 (1,012 ms). The limit is now production's (3 x the default 1 s heartbeat): 10/10 at load 360-430. The failure message now carries the burst length, the limit and the kill line. Also corrects the doc: its mutation check (compile on the pool again => killed for silence) no longer holds - re-checked on a 14-core Mac, the mutated worker passed at both 150 ms and 1 s, because the host's silence clock counts any frame and since #789 each compile writes its own LoadStarted/LoadResult frames inline. Co-Authored-By: Claude --- .../SupervisionTests.cs | 29 ++++++++++++++++--- 1 file changed, 25 insertions(+), 4 deletions(-) diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/SupervisionTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/SupervisionTests.cs index df214c4b6..1fdceb1d3 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/SupervisionTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.ScriptWorker.Tests/SupervisionTests.cs @@ -125,9 +125,14 @@ public sealed class SupervisionTests /// A burst of cold compiles must not starve the worker's heartbeat. Found on windev by the §8 perf harness: 500 /// loads at once, each compiled synchronously on its own thread-pool work item, queued the heartbeat timer and /// the pipe writer behind them; the host saw no frame for 3 s, killed the shard (KilledHeartbeat) and made all 500 - /// keys suspects. Here a 100 ms heartbeat (kill after 300 ms of silence) and 400 distinct cold scripts at once: - /// every script answers and the shard's worker is the one that started. Mutation check: compile on the thread - /// pool again and the worker is killed for silence. + /// keys suspects. Here a 50 ms heartbeat (kill after 3 s of silence, production's limit) and 1,500 distinct cold scripts at once: + /// every script answers and the shard's worker is the one that started. + /// ⚠️ The old "mutation check: compile on the thread pool again and the worker is killed for silence" does + /// NOT hold any more (re-checked for lmxopcua#843 on a 14-core Mac: the mutated worker passed at both the 150 ms + /// and the 1 s limit). The host's silence clock counts ANY frame, and since lmxopcua#789 a compile writes its own + /// LoadStarted/LoadResult frames inline — so pool-queued compiles keep the pipe busy themselves (the 3 s silence + /// windev saw presumably also needed the pre-#789 pool-scheduled writer stuck behind them). What this still pins is the + /// behaviour: a cold burst under a tight heartbeat is answered without a kill. /// [Fact] public async Task A_burst_of_cold_compiles_does_not_starve_the_heartbeat() @@ -136,13 +141,29 @@ public sealed class SupervisionTests var heartbeat = TimeSpan.FromMilliseconds(50); await using var runner = TightHeartbeatRunner(heartbeat, TimeSpan.FromSeconds(120), sink); var worker = WarmTight(runner, await runner.RunAsync(Scripts.Vt("first", Healthy), Ct), heartbeat, sink); + // lmxopcua#843: three 50 ms intervals (150 ms) is a limit the OS scheduler alone breaks on an overloaded box — at + // load average 100–280 the worker or the host's reader waited 150–310 ms for a core (10/10 runs killed for silence + // under 28 CPU burners, every compile on its dedicated thread), and at ~300 even a 1 s limit was hit once in 10 + // (1,012 ms). The limit is now PRODUCTION's (3 × the default 1 s heartbeat): the test kills only where a real node + // would, and the windev defect (no frame for 3 s, the whole burst) is still the size it catches. The 50 ms + // heartbeat keeps frames flowing for the silence clock. + worker.SilenceLimit = TimeSpan.FromSeconds(3); const int count = 1500; + var burst = Stopwatch.StartNew(); var outcomes = await Task.WhenAll(Enumerable.Range(0, count).Select(i => runner.RunAsync( Scripts.Vt("burst-" + i, $"return (int)ctx.GetTag(\"x\").Value * {i} + 1;", TimeSpan.FromSeconds(60), Scripts.Input("x", 2)), Ct))); + burst.Stop(); - var log = string.Join(Environment.NewLine, sink.Rendered.Where(l => l.Contains("ScriptWorker", StringComparison.Ordinal)).Take(5)); + // The kill line ("sent nothing for N ms") against the burst's length is the diagnosis: N close to the burst is + // the pool-starvation defect, N just over the limit is a starved box. + var log = $"burst took {burst.ElapsedMilliseconds} ms, silence limit {worker.SilenceLimit.TotalMilliseconds} ms\n" + + string.Join(Environment.NewLine, sink.Rendered + .Where(l => l.Contains("ScriptWorker", StringComparison.Ordinal)) + .Where(l => l.Contains("sent nothing", StringComparison.Ordinal) || l.Contains("kill", StringComparison.OrdinalIgnoreCase) + || l.Contains("exit", StringComparison.OrdinalIgnoreCase)) + .Take(10)); for (var i = 0; i < count; i++) outcomes[i].Value.ShouldBe(2 * i + 1, $"{outcomes[i].Status} {outcomes[i].Reason}\n{log}"); runner.Shards[0].Current.ShouldNotBeNull().Pid.ShouldBe(worker.Pid, log); worker.Exited.IsCompleted.ShouldBeFalse(log); From e89ac2df331f0e8e7c7d9b84b65f1add6e25be86 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Wed, 11 Nov 2026 05:09:36 -0500 Subject: [PATCH 5/6] fix(scripting): the run guard frees a script's slot before its run completes, not in a continuation (#843) RoslynVirtualTagEvaluatorTests' race test failed 1 of 3 full Host integration runs under 28 CPU burners (load ~300) with 24 of 4,800 evaluations refused 'previous evaluation still running' - impossible for one sequential loop per id unless a finished run still held its slot after the caller resumed. It did: ScriptRunGuard released the slot from a ContinueWith on the run task, and a task is observably complete before its continuations run, so the next run of the key (the next trigger, or the evaluator's immediate retry after a raced ObjectDisposedException) could be refused - a Bad publish for a script that had finished. Same class #789 fixed for the out-of-process runner. The release (and the late allocation-breach quarantine, now ahead of it) runs in the run's own finally, before the task completes; the continuation only disposes the CTS and observes the fault. New ScriptRunGuardTests.A_caller_that_awaited_its_run_is_never_refused_by_it widens the release with a test hook (SlotReleasingForTest) - mutation-checked: releasing from a continuation again refuses 49 of 50. The race test now prints elapsed / evaluations / clears / pool state / failure histogram on every assertion and on its hang detector. After: 3/3 full Host integration runs pass under the same load. Core.Scripting 298, ScriptedAlarms 109, Calculation 84 green. Co-Authored-By: Claude --- .../ScriptRunGuard.cs | 41 ++++++++++++++----- .../ScriptRunGuardTests.cs | 34 +++++++++++++++ .../RoslynVirtualTagEvaluatorTests.cs | 41 ++++++++++++++++--- 3 files changed, 100 insertions(+), 16 deletions(-) diff --git a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs index 276730286..ccce6c8bb 100644 --- a/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs +++ b/src/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting/ScriptRunGuard.cs @@ -105,6 +105,13 @@ public sealed class ScriptRunGuard _logger = logger ?? Log.Logger; } + /// + /// Test seam (lmxopcua#843): invoked on the run's own thread just before its slot is released, with the key. + /// A sleep here widens the release window, so a test can prove the release is ordered before the caller + /// resumes rather than winning a race. + /// + internal Action? SlotReleasingForTest { get; set; } + /// Raised (on the thread that detected it) when a script is quarantined. public event EventHandler? Quarantined; @@ -233,34 +240,46 @@ public sealed class ScriptRunGuard Volatile.Write(ref state.RunStartedTimestamp, Stopwatch.GetTimestamp()); started.TrySetResult(); var before = GC.GetAllocatedBytesForCurrentThread(); + var succeeded = false; try { // ScriptEvaluator.RunAsync executes the compiled delegate synchronously and returns a completed // task, so the after-sample is taken on the same thread, right after the script returned. var pending = evaluator.RunAsync(context, runToken); slot.AllocatedBytes = GC.GetAllocatedBytesForCurrentThread() - before; - return await pending.ConfigureAwait(false); + var value = await pending.ConfigureAwait(false); + succeeded = true; + return value; } catch { slot.AllocatedBytes = GC.GetAllocatedBytesForCurrentThread() - before; throw; } + finally + { + // Release the slot when the run REALLY finishes — which for an abandoned run is long after + // RunAsync has thrown ScriptTimeoutException — and BEFORE runTask completes (lmxopcua#843). This + // used to be a ContinueWith on runTask: a task is observably complete before its continuations + // run, so a caller that saw the completion (e.g. the virtual-tag evaluator's immediate retry after a + // raced ObjectDisposedException, or simply the next trigger) could + // start the key's NEXT run while this one still held the slot and be refused "previous + // evaluation still running" — a Bad publish for a script that had finished. Seen under load: + // 24 of 4,800 sequential same-key evaluations. A late-finishing orphan that breached the + // allocation budget quarantines its key first, so no re-trigger slips in between. + if (succeeded && BreachedBudget(slot.AllocatedBytes)) + Quarantine(key, state, AllocationReason(slot.AllocatedBytes), "allocation"); + SlotReleasingForTest?.Invoke(key); + Volatile.Write(ref state.RunStartedTimestamp, 0); + Interlocked.Exchange(ref state.InFlight, 0); + Interlocked.Decrement(ref _inFlight); + } }); - // Release the slot when the run REALLY finishes — which for an abandoned run is long after this - // method has thrown ScriptTimeoutException. Registered before the wait so it fires regardless of - // which way the wait below comes out. A late-finishing orphan that breached the allocation budget - // still quarantines its key here. _ = runTask.ContinueWith(t => { - Volatile.Write(ref state.RunStartedTimestamp, 0); - Interlocked.Exchange(ref state.InFlight, 0); - Interlocked.Decrement(ref _inFlight); runCts.Dispose(); if (t.IsFaulted) _ = t.Exception; // observed below by the awaiter when it is still listening - if (t.IsCompletedSuccessfully && BreachedBudget(slot.AllocatedBytes)) - Quarantine(key, state, AllocationReason(slot.AllocatedBytes), "allocation"); }, CancellationToken.None, TaskContinuationOptions.ExecuteSynchronously, TaskScheduler.Default); // The budget clock starts when the pool starts the run, not when we queued it (P5): pool starvation @@ -313,7 +332,7 @@ public sealed class ScriptRunGuard && !string.Equals(state.SourceIdentity, sourceIdentity, StringComparison.Ordinal)) { // The script changed under this key: start from a clean slate. The old state's orphan (if any) - // releases the GLOBAL in-flight count through its own continuation; nothing else references it. + // releases the GLOBAL in-flight count when it finishes; nothing else references it. _keys.TryUpdate(key, new KeyState(sourceIdentity), state); continue; } diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs index d7c4bb7f4..b1c264511 100644 --- a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/ScriptRunGuardTests.cs @@ -61,6 +61,40 @@ public sealed class ScriptRunGuardTests guard.IsQuarantined("vt-1", out _).ShouldBeFalse(); } + /// + /// lmxopcua#843: a caller that awaited its run is never refused by it. The slot used to be released by a + /// ContinueWith on the run task — and a task is observably complete before its continuations run, so the + /// caller (or the evaluator's immediate ODE retry) could start the key's next run while the finished one still + /// held the slot: "previous evaluation still running", 24 of 4,800 sequential evaluations in the Host + /// integration suite under load. The second phase makes every release slow (the hook sleeps inside it), so + /// the ordering, not luck, is what keeps the caller from being refused. Mutation check: release from a + /// continuation again and the second phase goes red. + /// + [Fact] + public async Task A_caller_that_awaited_its_run_is_never_refused_by_it() + { + var guard = new ScriptRunGuard(); + using var fast = Compile(FastScript); + var ct = TestContext.Current.CancellationToken; + var refused = new List(); + for (var i = 0; i < 500; i++) + { + try { (await Run(guard, "seq", FastScript, fast, ct: ct)).ShouldBe(42); } + catch (ScriptRunRefusedException) { refused.Add($"#{i}"); } + } + refused.ShouldBeEmpty(); + + guard.SlotReleasingForTest = _ => Thread.Sleep(5); + for (var i = 0; i < 50; i++) + { + try { (await Run(guard, "seq", FastScript, fast, ct: ct)).ShouldBe(42); } + catch (ScriptRunRefusedException) { refused.Add($"slow release #{i}"); } + } + refused.ShouldBeEmpty(); + guard.RefusedWhileRunningCount.ShouldBe(0); + guard.InFlightCount.ShouldBe(0); + } + [Fact] public async Task A_timed_out_run_throws_ScriptTimeoutException_and_keeps_the_slot_held_by_the_orphan() { diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs index 47ac617a1..70dcd87f9 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs @@ -466,6 +466,19 @@ public sealed class RoslynVirtualTagEvaluatorTests /// for the same reason: a handful of queued-too-long evaluations is the environment, but 10% of them /// missing a 5 s budget means the evaluator stopped evaluating. If a loaded box ever does trip EITHER /// bound, the rate itself is the finding: record it before widening the number. + /// + /// lmxopcua#843 — this test found a product bug, not a timing assumption. Under the full Host + /// integration suite plus 28 CPU burners (load ~300) it failed 1 run in 3 with 24 of 4,800 evaluations + /// refused "previous evaluation still running" — impossible for one sequential loop per id unless the + /// id's previous run still held its slot after its caller had resumed. It did: + /// the slot was released by a continuation on the run task, and a task is observably complete before its + /// continuations run (worst for the evaluator's immediate retry after a raced + /// ). The release now happens inside the run, before it completes + /// (ScriptRunGuardTests.A_caller_that_awaited_its_run_is_never_refused_by_it pins the ordering). A + /// refusal stays in the "leaked" bucket on purpose. The doc above predates P5: the guard's budget clock + /// starts when the pool starts the run, so a queued evaluation no longer lands in the timed-out bucket. + /// Every assertion now prints the run's shape (elapsed, evaluations, clears, pool state, failure histogram). + /// [Fact] public async Task Evaluate_racing_ClearCompiledScripts_never_leaks_a_raw_disposed_failure() { @@ -511,19 +524,37 @@ public sealed class RoslynVirtualTagEvaluatorTests Interlocked.Decrement(ref remaining); }, TestContext.Current.CancellationToken)).ToArray(); + var clears = 0L; var clearLoop = Task.Run(() => { while (Volatile.Read(ref remaining) > 0) { sut.ClearCompiledScripts(); + Interlocked.Increment(ref clears); Thread.SpinWait(4000); // ~tens of µs between clears — frequent, but not back-to-back } }, TestContext.Current.CancellationToken); + // lmxopcua#843: every assertion below carries the run's shape, so a failure under load says which bucket + // moved and how starved the box was (it passed 5/5 on rerun with nothing recorded). + var elapsed = System.Diagnostics.Stopwatch.StartNew(); + string Diagnostics() => + $" [elapsed {elapsed.ElapsedMilliseconds} ms, {Volatile.Read(ref evaluated)} evaluations, " + + $"{Interlocked.Read(ref clears)} clears, loops still running {Volatile.Read(ref remaining)}, " + + $"pool threads {ThreadPool.ThreadCount} / pending {ThreadPool.PendingWorkItemCount}; failures: " + + string.Join(", ", failures.GroupBy(r => r.Length > 80 ? r[..80] : r).Select(g => $"{g.Count()}× \"{g.Key}\"")) + "]"; + // Hang detector only: the loops self-terminate at RaceWindow, so firing this means something // wedged, not that the box was slow. - await Task.WhenAll(evalLoops.Append(clearLoop)) - .WaitAsync(TimeSpan.FromSeconds(45), TestContext.Current.CancellationToken); + try + { + await Task.WhenAll(evalLoops.Append(clearLoop)) + .WaitAsync(TimeSpan.FromSeconds(45), TestContext.Current.CancellationToken); + } + catch (TimeoutException ex) + { + throw new TimeoutException("the racing loops did not finish within 45 s" + Diagnostics(), ex); + } var totalEvaluations = Volatile.Read(ref evaluated); // Loose by design, with an absolute floor so a starved run (few evaluations landed) cannot trip on @@ -544,20 +575,20 @@ public sealed class RoslynVirtualTagEvaluatorTests leaked.ShouldBeEmpty( "a racing ClearCompiledScripts must never surface a failure other than " + $"\"{ScriptEvalFailureReasons.EvaluatorDisposedDuringEvaluation}\" or " + - $"\"{ScriptEvalFailureReasons.TimedOutPrefix}…\"; observed: {string.Join(" | ", leaked)}"); + $"\"{ScriptEvalFailureReasons.TimedOutPrefix}…\"; observed: {string.Join(" | ", leaked)}" + Diagnostics()); // (2) Non-vacuity: the retry must actually be absorbing the race, not merely relabelling it. exhausted.ShouldBeLessThan( rateBound, "the one-shot retry must absorb the overwhelming majority of raced clears; " + - $"{exhausted}/{totalEvaluations} evaluations exhausted it"); + $"{exhausted}/{totalEvaluations} evaluations exhausted it" + Diagnostics()); // (3) The starvation bucket is tolerated but not unbounded — at 10% the evaluator has stopped // evaluating rather than the box being busy. starved.ShouldBeLessThan( rateBound, "queue-starvation timeouts are expected under this stress but must stay marginal; " + - $"{starved}/{totalEvaluations} evaluations missed the 5s budget"); + $"{starved}/{totalEvaluations} evaluations missed the 5s budget" + Diagnostics()); } // ── input quality reaches the script (archreview 02/S14) ──────────────────────────────── From 997c78df8a4a008a26639a1d9dcf0afd1ba1e633 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Wed, 11 Nov 2026 05:09:36 -0500 Subject: [PATCH 6/6] test(host): deploy-seal waits in EquipmentNamespaceMaterializationTests report where the deploy stood on timeout (#843) The one failure on record (48 s vs 3 s, load 140-280) was a bare 'Condition not met within 00:00:45'. It did not reproduce here (0/10 alone and 0/6 full Host integration runs under 28 CPU burners at load ~300), so no timing was changed; the timeout now carries the deployment row (status, artifact size, failure reason), every per-node state (status, started/applied, failure) vs the expected node ids, and both nodes' cluster views - enough to tell a slow apply from a node that never got the dispatch from a failed apply. Co-Authored-By: Claude --- .../EquipmentNamespaceMaterializationTests.cs | 32 ++++++++++++++++--- 1 file changed, 28 insertions(+), 4 deletions(-) diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/EquipmentNamespaceMaterializationTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/EquipmentNamespaceMaterializationTests.cs index dd78d6087..824336829 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/EquipmentNamespaceMaterializationTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/EquipmentNamespaceMaterializationTests.cs @@ -85,7 +85,7 @@ public sealed class EquipmentNamespaceMaterializationTests return true; } return false; - }, TwoNodeClusterHarness.DeploySealTimeout); + }, TwoNodeClusterHarness.DeploySealTimeout, () => DescribeDeploymentAsync(harness, deploymentId)); var composition = DeploymentArtifact.ParseComposition(artifact); @@ -182,7 +182,7 @@ public sealed class EquipmentNamespaceMaterializationTests return true; } return false; - }, TwoNodeClusterHarness.DeploySealTimeout); + }, TwoNodeClusterHarness.DeploySealTimeout, () => DescribeDeploymentAsync(harness, deploymentId)); await using (var db = await CreateDbAsync(harness)) { @@ -261,7 +261,8 @@ public sealed class EquipmentNamespaceMaterializationTests return await factory.CreateDbContextAsync(); } - private static async Task WaitForAsync(Func> condition, TimeSpan timeout) + private static async Task WaitForAsync(Func> condition, TimeSpan timeout, + Func>? diagnose = null) { var deadline = DateTime.UtcNow + timeout; while (DateTime.UtcNow < deadline) @@ -269,6 +270,29 @@ public sealed class EquipmentNamespaceMaterializationTests if (await condition()) return; await Task.Delay(200); } - throw new TimeoutException($"Condition not met within {timeout}"); + throw new TimeoutException($"Condition not met within {timeout}" + + (diagnose is null ? "" : $"; state at timeout: {await diagnose()}")); + } + + /// + /// lmxopcua#843: the seal wait used to time out with a bare "Condition not met within 45s" (seen once at load + /// average 140–280, 48 s against a normal 3 s). Report where the deploy stood — the deployment row, each node's + /// per-node state, and both nodes' cluster views — so the next failure says whether it was a slow apply, a node + /// that never received the dispatch (no ack, still Applying), or a failed apply. + /// + private static async Task DescribeDeploymentAsync(TwoNodeClusterHarness harness, Guid deploymentId) + { + await using var db = await CreateDbAsync(harness); + var d = await db.Deployments.AsNoTracking().FirstOrDefaultAsync(x => x.DeploymentId == deploymentId); + var nodes = await db.NodeDeploymentStates.AsNoTracking() + .Where(s => s.DeploymentId == deploymentId).ToListAsync(); + static string View(Akka.Actor.ActorSystem s) => string.Join(",", + Akka.Cluster.Cluster.Get(s).State.Members.Select(m => $"{m.Address.Port}:{m.Status}")) + + $" unreachable={Akka.Cluster.Cluster.Get(s).State.Unreachable.Count}"; + return $"deployment={d?.Status.ToString() ?? ""} artifact={d?.ArtifactBlob.Length ?? 0}B " + + $"failure='{d?.FailureReason}' created={d?.CreatedAtUtc:O} now={DateTime.UtcNow:O}; " + + $"nodes=[{string.Join("; ", nodes.Select(n => $"{n.NodeId} {n.Status} started={n.StartedAtUtc:O} applied={n.AppliedAtUtc:O} failure='{n.FailureReason}'"))}] " + + $"(expected {harness.NodeANodeId}, {harness.NodeBNodeId}); " + + $"A view=[{View(harness.NodeASystem)}] B view=[{View(harness.NodeBSystem)}]"; } }