From 55ae230fa4582a561e14650529cf72347f9f8c59 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Thu, 8 Oct 2026 19:44:31 -0400 Subject: [PATCH 1/2] ci(#606): Gitea-compatible trx upload + deterministic fixes for the CI-load test flakes MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - v2-ci.yml: upload-artifact@v4 -> @v3 + continue-on-error (act_runner reports as GHES and v4 refuses GHES, failing every run); runner-capacity diagnostic step; AKKA_TEST_TIMEFACTOR=3 on the test step. - Runtime/ControlPlane harnesses: akka.test.timefactor from AKKA_TEST_TIMEFACTOR (TestTimeFactor), single-expect-default 15s; ControlPlane gains PresenceBudget. - Leaked spinner threads: the infinite-loop timeout tests (Calculation, Host.IntegrationTests RoslynVirtualTagEvaluator, 3x Core.Scripting) pinned a core for the rest of the test process (abandoned, never stopped). Now a bounded 5 s wall-clock spin; outer compile-inclusive bound 30 s. - Real test races fixed: ScriptedAlarmEngine push-during-drain (Inactive is also the start state + persist-before-update => wait for the Cleared save); DriverReconnectE2e (both nodes host the driver; Created[] is last-writer-wins and ForceReconnect is a no-op while Connecting); ControlPlaneStarterOrder (lost-race heal waited for a 60 s refresh tick). - Fixed sleeps -> poll-for-condition: ReconnectSupervisor LastError, Modbus deadband steps (wait for observed reads), Modbus dispose hygiene precondition, FOCAS probe-loop log. - Short presence budgets -> PresenceBudget in the Runtime/ControlPlane tests seen failing on Gitea; Calculation Settle 10 -> 30 s. No assertion removed, nothing skipped. - infra/README.md §10 CI; stale TreatWarningsAsErrors comment in Directory.Build.props. Claude-Session: https://claude.ai/code/session_01Ef2ozxS7QPanGT8uoATbTe --- .github/workflows/v2-ci.yml | 23 +++++++- Directory.Build.props | 4 +- infra/README.md | 28 ++++++++++ .../ScriptedAlarmEngineTests.cs | 23 +++++++- .../TimedScriptEvaluatorTests.cs | 43 ++++++++------- .../CalculationDriverInputQualityTests.cs | 4 +- .../CalculationDriverTests.cs | 4 +- .../CalculationEvaluatorTests.cs | 18 ++++++- .../FocasLoggingTests.cs | 26 ++++++--- .../Runtime/ReconnectSupervisorTests.cs | 12 ++++- .../ModbusLifecycleHygieneTests.cs | 8 ++- .../ModbusSubscribeOptionsTests.cs | 40 ++++++++++---- .../AdminOperationsActorTagConfigGateTests.cs | 14 ++--- .../AuditWriterActorTests.cs | 2 +- .../ControlPlaneStarterOrderTests.cs | 9 +++- .../Communication/MeshRouterDispatchTests.cs | 16 +++--- .../Harness/ControlPlaneTestHarness.cs | 25 ++++++++- .../Harness/TestTimeFactor.cs | 38 +++++++++++++ .../DriverReconnectE2eTests.cs | 54 +++++++++++++++---- .../Fakes/FakeReconnectDriverFactory.cs | 17 ++++++ .../RoslynVirtualTagEvaluatorTests.cs | 18 ++++++- .../Drivers/CalculationDependencyFlowTests.cs | 6 +-- .../DriverHostActorBootFromCacheTests.cs | 8 +-- .../Drivers/DriverHostActorDbLessTests.cs | 8 +-- .../DriverHostActorFetchAndCacheTests.cs | 12 ++--- ...erHostActorFetchAndCacheUnreadableTests.cs | 12 ++--- ...iverHostActorHistorizationRoleViewTests.cs | 2 +- ...iverHostActorNativeAlarmAckRoutingTests.cs | 2 +- .../DriverHostActorPrimaryRoleSourceTests.cs | 2 +- .../DriverInstanceActorBatchForwardTests.cs | 22 ++++---- .../Harness/RuntimeActorTestBase.cs | 12 ++++- .../Harness/TestTimeFactor.cs | 38 +++++++++++++ .../Health/HealthProbeActorTests.cs | 2 +- .../ContinuousHistorizationRecorderTests.cs | 7 ++- .../Telemetry/PublishSeamEmitsToHubTests.cs | 14 ++--- .../VirtualTags/DependencyMuxActorTests.cs | 4 +- 36 files changed, 449 insertions(+), 128 deletions(-) create mode 100644 tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Harness/TestTimeFactor.cs create mode 100644 tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Harness/TestTimeFactor.cs diff --git a/.github/workflows/v2-ci.yml b/.github/workflows/v2-ci.yml index d2e81dd4..3d92c387 100644 --- a/.github/workflows/v2-ci.yml +++ b/.github/workflows/v2-ci.yml @@ -52,6 +52,13 @@ jobs: dotnet-version: 10.0.x - name: dotnet restore run: dotnet restore ZB.MOM.WW.OtOpcUa.slnx + # #606: the runner's size is the context every timing-sensitive failure needs and the log never + # recorded it (load average included: the two Gitea runners may be running jobs side by side). + - name: runner capacity + run: | + echo "nproc=$(nproc)" + free -m || true + uptime || true # 07/S-1: ONE whole-solution leg instead of a hand-maintained 5-project matrix that # silently dropped Client (388 tests), Analyzers (31), and every driver + most Core suite. # Self-maintaining — a new *.Tests project is covered automatically, no matrix to widen — @@ -61,6 +68,13 @@ jobs: # excluded here — it is a local-dev-loop opt-out only. The skip-gated *.IntegrationTests Assert.Skip when their fixtures # are unreachable, so they run harmlessly here (and are counted by the skip-gate below). - name: dotnet test (whole solution, minus E2E + LiveIntegration) + # #606: Akka TestKit time dilation for the Runtime + ControlPlane actor suites (read by their + # harnesses, tests/Server/*/Harness/TestTimeFactor.cs). This leg runs every test assembly at once + # on the runner, and their 2–8 s presence budgets — sized on an idle dev box — failed in a long + # tail, a different test per run. Dilation only stretches waits: a presence wait still fails if + # the message never comes, and absence windows get longer (stricter). Local runs stay at 1. + env: + AKKA_TEST_TIMEFACTOR: "3" run: > dotnet test ZB.MOM.WW.OtOpcUa.slnx --configuration Release --no-restore --filter "Category!=E2E&Category!=LiveIntegration" @@ -71,9 +85,16 @@ jobs: - name: assert not-all-skipped if: always() run: bash scripts/ci/assert-not-all-skipped.sh artifacts/trx/*.trx + # #606: pinned to v3. Gitea's act_runner reports itself as GHES, and @actions/artifact v2+ + # (upload-artifact@v4+) refuses GHES outright ("GHESNotSupportedError") — so on Gitea the v4 + # step failed EVERY run and the job could never go green, independent of the tests. v3 speaks + # the artifact API Gitea implements. continue-on-error because the trx upload is evidence, not a + # gate: the test step and the skip-gate above decide the job, and an artifact-store hiccup must + # not turn a green run red. - name: upload trx if: always() - uses: actions/upload-artifact@v4 + continue-on-error: true + uses: actions/upload-artifact@v3 with: name: unit-trx path: artifacts/trx/*.trx diff --git a/Directory.Build.props b/Directory.Build.props index 1b08fc60..34733807 100644 --- a/Directory.Build.props +++ b/Directory.Build.props @@ -4,8 +4,8 @@ TreatWarningsAsErrors is NOT set globally because test projects carry analyzer warnings (e.g. xUnit1051) that would fail the build. src/ projects opt in to - true in their own csproj (a few still pending; - see #606). Once every project is clean this can be promoted back to a global default. + true in their own csproj — all 61 do as of #606. + It stays per-project rather than global only because the test projects are not yet clean. --> net10.0 diff --git a/infra/README.md b/infra/README.md index e8cc302a..79eb1470 100644 --- a/infra/README.md +++ b/infra/README.md @@ -209,3 +209,31 @@ and a real directory (LDAP) — never the dev values in this doc. > The legacy Wonderware TCP/ArchestrA sidecar was retired; the historian backend is now the > `ZB.MOM.WW.HistorianGateway` sidecar (see §6 and `docs/Historian.md`). + +## 10. CI — Gitea Actions (`.github/workflows/v2-ci.yml`) + +The one workflow (there is no `.gitea/workflows/`) runs on the Gitea act_runners `gitea-runner` / +`gitea-runner-2`: a `build` job (restore, Release build, `code-reviews/regen-readme.py --check`) and a +`unit-tests` job (the whole solution minus `Category=E2E|LiveIntegration`, trx → +`scripts/ci/assert-not-all-skipped.sh` → trx upload). Read run logs read-only with +`tea api --login /repos/dohertj2/lmxopcua/actions/runs` (then `…/runs//jobs`, +`…/jobs//logs`). + +Things that are not obvious (#606): + +- **`actions/upload-artifact` is pinned to `@v3` and `continue-on-error`.** act_runner reports as GHES, + and `upload-artifact@v4+` refuses GHES outright (`GHESNotSupportedError`), which failed every run + regardless of the tests. Do not "upgrade" it back to v4. +- **`AKKA_TEST_TIMEFACTOR=3` on the test step.** The Runtime/ControlPlane actor-test harnesses + (`tests/Server/*/Harness/TestTimeFactor.cs`) feed it to `akka.test.timefactor`, which dilates every + TestKit wait (explicit durations included). The leg runs every assembly at once on the runner; a long + tail of 2–8 s presence budgets each failed about one run in eight. Local runs stay at 1. +- **Presence vs absence.** A presence wait (`ExpectMsg`, `AwaitAssert`, a poll-until) is a ceiling and + is sized from the suites' `PresenceBudget` (15 s); an absence window (`ExpectNoMsg`, settle-then- + assert) is the assertion itself and keeps its short literal. Replace a fixed `Task.Delay` before an + assertion with a poll for the condition. +- **Never leave a script spinning.** A timed-out script is abandoned, not stopped + (`TimedScriptEvaluator`), so `while(true){}` pinned a core for the rest of the test process. Timeout + tests use a bounded wall-clock spin (`System.DateTime.UtcNow` is sandbox-allowed). +- **`MIN_EXECUTED`** (`assert-not-all-skipped.sh`) is still the default `1`; raise it once a green run + is recorded (a full run executes ~12.7k tests across ~57 trx files). diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmEngineTests.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmEngineTests.cs index a8ca67b2..1817003d 100644 --- a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmEngineTests.cs +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmEngineTests.cs @@ -1183,6 +1183,23 @@ public sealed class ScriptedAlarmEngineTests throw new TimeoutException("Condition did not become true in time"); } + /// + /// Waits for a blocked-Activated-save scenario to finish its follow-up pass: the Cleared transition + /// has been persisted (the second SaveAsync) AND applied in memory. + /// + /// + /// Waiting for Active == Inactive alone is ambiguous here — Inactive is also the state the + /// alarm STARTED in, and the engine persists BEFORE it updates memory, so in the instant after the + /// gate is released the in-memory state still reads the pre-activation Inactive. The wait then + /// returned before the follow-up pass ran and the evaluation count read 1 (#606, a Gitea CI failure + /// in 137 ms). counts at SaveAsync entry, so + /// "two saves started AND Inactive in memory" is only true after the Cleared update. + /// + private static Task WaitForClearedFollowUpAsync(ScriptedAlarmEngine eng, CountingAlarmStateStore store) => + WaitForAsync( + () => store.SaveCount >= 2 && eng.GetState("A")!.Active == AlarmActiveState.Inactive, + timeoutMs: 3000); + // ------------------------------------------------------------------------- // Test helpers // ------------------------------------------------------------------------- @@ -1486,7 +1503,7 @@ public sealed class ScriptedAlarmEngineTests up.Push("Temp", 50); saveGate.SetResult(); - await WaitForAsync(() => eng.GetState("A")!.Active == AlarmActiveState.Inactive, timeoutMs: 3000); + await WaitForClearedFollowUpAsync(eng, store); probe.Count.ShouldBeLessThanOrEqualTo(2, "11 pushes over one blocked evaluation must produce the in-flight evaluation plus at " + @@ -1529,7 +1546,9 @@ public sealed class ScriptedAlarmEngineTests await eng.LoadAsync([ Alarm("A", """ctx.Logger.Information("EVALPROBE"); return (int)ctx.GetTag("Temp").Value > 100;"""), ], TestContext.Current.CancellationToken); + // LoadAsync evaluates AND saves once (startup recovery) — count both from here. probe.Reset(); + store.ResetCount(); var saveGate = new TaskCompletionSource(); store.BlockNextSave = saveGate; @@ -1542,7 +1561,7 @@ public sealed class ScriptedAlarmEngineTests up.Push("Temp", 40); saveGate.SetResult(); - await WaitForAsync(() => eng.GetState("A")!.Active == AlarmActiveState.Inactive, timeoutMs: 3000); + await WaitForClearedFollowUpAsync(eng, store); probe.Count.ShouldBe(2, "the in-flight pass plus exactly one follow-up pass for the late push"); } diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/TimedScriptEvaluatorTests.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/TimedScriptEvaluatorTests.cs index f9feeeac..3ae5b280 100644 --- a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/TimedScriptEvaluatorTests.cs +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests/TimedScriptEvaluatorTests.cs @@ -13,6 +13,26 @@ namespace ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests; [Trait("Category", "Unit")] public sealed class TimedScriptEvaluatorTests { + /// + /// A CPU-bound script that outlives every timeout in this file but still ENDS. + /// + /// + /// A timed-out script is abandoned, not stopped — its pool thread keeps running (the documented + /// leak). The previous body, + /// long acc = 0; while (true) { acc++; if (acc < 0) break; }, needs 2^63 increments to + /// overflow, so each of the three tests using it pinned one core at 100 % for the rest of the test + /// process — CPU the parallel suites on a small CI runner were starving for (#606). A 5 s wall-clock + /// spin is still one to two orders of magnitude past the 30–80 ms timeouts/cancels asserted here, so + /// the script cannot finish first even under heavy load, and the abandoned thread exits on its own. + /// System.DateTime is outside the sandbox deny-list; Thread/Environment/Diagnostics are not. + /// + private const string BoundedSpinScript = + """ + var end = System.DateTime.UtcNow.AddSeconds(5); + while (System.DateTime.UtcNow < end) { } + return 1; + """; + /// Verifies that fast scripts complete under timeout and return value. [Fact] public async Task Fast_script_completes_under_timeout_and_returns_value() @@ -33,13 +53,8 @@ public sealed class TimedScriptEvaluatorTests { // Scripts can't reach the sandbox-denied process surface (System.Threading.Thread // and System.Environment are both denied — Core.Scripting-001). A tight CPU loop - // that never returns exceeds any short timeout without touching a forbidden type. - var inner = ScriptEvaluator.Compile( - """ - long acc = 0; - while (true) { acc++; if (acc < 0) break; } - return 1; - """); + // that outlives the timeout exceeds it without touching a forbidden type. + var inner = ScriptEvaluator.Compile(BoundedSpinScript); var timed = new TimedScriptEvaluator( inner, TimeSpan.FromMilliseconds(50)); @@ -56,12 +71,7 @@ public sealed class TimedScriptEvaluatorTests // A CPU-bound script that would otherwise timeout; external ct fires first. // Expected: OperationCanceledException (not ScriptTimeoutException) so shutdown // paths aren't misclassified as timeouts. - var inner = ScriptEvaluator.Compile( - """ - long acc = 0; - while (true) { acc++; if (acc < 0) break; } - return 1; - """); + var inner = ScriptEvaluator.Compile(BoundedSpinScript); var timed = new TimedScriptEvaluator( inner, TimeSpan.FromSeconds(5)); @@ -127,12 +137,7 @@ public sealed class TimedScriptEvaluatorTests [Fact] public async Task ScriptTimeoutException_message_points_at_diagnostic_path() { - var inner = ScriptEvaluator.Compile( - """ - long acc = 0; - while (true) { acc++; if (acc < 0) break; } - return 1; - """); + var inner = ScriptEvaluator.Compile(BoundedSpinScript); var timed = new TimedScriptEvaluator( inner, TimeSpan.FromMilliseconds(30)); diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverInputQualityTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverInputQualityTests.cs index 73f6f012..b70c6eed 100644 --- a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverInputQualityTests.cs +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverInputQualityTests.cs @@ -69,9 +69,11 @@ public sealed class CalculationDriverInputQualityTests } } + // 30 s ceiling: covers a cold Roslyn compile of the first evaluation on a loaded CI runner, where + // 10 s ran out (#606). A quiescence wait — it returns the instant the pump drains. private static async Task Settle(CalculationDriver driver) { - var deadline = DateTime.UtcNow + TimeSpan.FromSeconds(10); + var deadline = DateTime.UtcNow + TimeSpan.FromSeconds(30); while (DateTime.UtcNow < deadline) { if (driver.IsEvaluationIdle) return; diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverTests.cs index 35945878..42e11132 100644 --- a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverTests.cs +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverTests.cs @@ -46,10 +46,12 @@ public sealed class CalculationDriverTests /// OnDependencyValue and run on the driver's own worker (Driver.Calculation-005), so a test /// that used to assert on the very next line now settles first. Quiescence, not a sleep: the work /// is enqueued synchronously inside the callback, so "idle" can never be observed before it lands. + /// The 30 s ceiling covers a cold Roslyn compile of the first evaluation on a loaded CI runner, + /// where 10 s ran out (#606); quiescence returns the instant the pump drains, so it costs nothing. /// private static async Task Settle(CalculationDriver driver) { - var idle = await WaitUntil(() => driver.IsEvaluationIdle, TimeSpan.FromSeconds(10)); + var idle = await WaitUntil(() => driver.IsEvaluationIdle, TimeSpan.FromSeconds(30)); idle.ShouldBeTrue("the calc driver's evaluation pump should have drained"); } diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationEvaluatorTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationEvaluatorTests.cs index 7669aa05..19e65601 100644 --- a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationEvaluatorTests.cs +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationEvaluatorTests.cs @@ -60,6 +60,15 @@ public sealed class CalculationEvaluatorTests /// An infinite-loop script returns Failure ("timed out") within the wall-clock budget instead /// of wedging the caller. The whole call is WaitAsync-bounded so a regression FAILS rather than hangs. + /// + /// A CPU-bound script that outlives the 200 ms run timeout by 25x but still ENDS. A timed-out script + /// is abandoned, not stopped, so the old while(true){} pinned one core for the rest of the test + /// process — starving every parallel suite on a small CI runner (#606). System.DateTime is + /// outside the sandbox deny-list. + /// + private const string BoundedSpinScript = + "var end = System.DateTime.UtcNow.AddSeconds(5); while (System.DateTime.UtcNow < end) { } return 0;"; + [Fact] public async Task Evaluate_infinite_loop_script_fails_within_timeout_and_does_not_hang() { @@ -67,10 +76,15 @@ public sealed class CalculationEvaluatorTests NullLogger.Instance, NoOpScriptRoot(), TimeSpan.FromMilliseconds(200)); var evalTask = Task.Run( - () => sut.Evaluate("calc-loop", "while(true){}return 0;", new Dictionary()), + () => sut.Evaluate("calc-loop", BoundedSpinScript, new Dictionary()), TestContext.Current.CancellationToken); - var result = await evalTask.WaitAsync(TimeSpan.FromSeconds(5), TestContext.Current.CancellationToken); + // The outer bound covers the Roslyn COMPILE as well as the run — the 200 ms run timeout starts + // only once the script is compiled — and a cold compile on a loaded CI runner took the old 5 s + // budget on every one of four consecutive Gitea runs (#606). 30 s is still a hard bound, so a + // hang still fails the test; and because the spin ends after 5 s, a timeout that never fires + // now fails it too (Success == true), rather than only failing as a hang. + var result = await evalTask.WaitAsync(TimeSpan.FromSeconds(30), TestContext.Current.CancellationToken); result.Success.ShouldBeFalse(); result.Reason.ShouldNotBeNull(); diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Tests/FocasLoggingTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Tests/FocasLoggingTests.cs index 44483c14..672db8ca 100644 --- a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Tests/FocasLoggingTests.cs +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Tests/FocasLoggingTests.cs @@ -68,8 +68,12 @@ public sealed class FocasLoggingTests await drv.InitializeAsync("{}", CancellationToken.None); - // Give the probe loop one tick or two to log. - await Task.Delay(250); + // Wait for the probe loop's first swallowed-exception log instead of sleeping a fixed 250 ms: + // on a loaded CI runner no tick had run yet and Entries was empty (#606). A presence wait — + // it returns as soon as the entry lands, and a loop that never logs still fails below. + var deadline = DateTime.UtcNow.AddSeconds(10); + while (!HasProbeEntry(logger) && DateTime.UtcNow < deadline) + await Task.Delay(10, TestContext.Current.CancellationToken); await drv.ShutdownAsync(CancellationToken.None); @@ -77,15 +81,23 @@ public sealed class FocasLoggingTests // failure or the probe loop. Without logging there's literally no record on a wedged // CNC — exactly the gap the finding called out. logger.Entries.ShouldNotBeEmpty(); - logger.Entries.Any(e => e.Message.Contains("probe", StringComparison.OrdinalIgnoreCase) - || (e.Exception?.Message.Contains("simulated probe failure") ?? false)) + HasProbeEntry(logger) .ShouldBeTrue("at least one log entry should reference the probe loop or surface the swallowed exception"); } + private static bool HasProbeEntry(CapturingLogger logger) => + logger.Entries.Any(e => e.Message.Contains("probe", StringComparison.OrdinalIgnoreCase) + || (e.Exception?.Message.Contains("simulated probe failure") ?? false)); + private sealed class CapturingLogger : ILogger { - /// Gets the captured log entries. - public List<(LogLevel Level, string Message, Exception? Exception)> Entries { get; } = new(); + private readonly List<(LogLevel Level, string Message, Exception? Exception)> _entries = new(); + + /// Gets a snapshot of the captured log entries (written from the probe loop's thread). + public IReadOnlyList<(LogLevel Level, string Message, Exception? Exception)> Entries + { + get { lock (_entries) return _entries.ToArray(); } + } /// Begins a logging scope. /// The scope state. @@ -104,7 +116,7 @@ public sealed class FocasLoggingTests public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) { - Entries.Add((logLevel, formatter(state, exception), exception)); + lock (_entries) _entries.Add((logLevel, formatter(state, exception), exception)); } private sealed class NullScope : IDisposable diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Galaxy.Tests/Runtime/ReconnectSupervisorTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Galaxy.Tests/Runtime/ReconnectSupervisorTests.cs index a5008be6..91376cf8 100644 --- a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Galaxy.Tests/Runtime/ReconnectSupervisorTests.cs +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Galaxy.Tests/Runtime/ReconnectSupervisorTests.cs @@ -134,8 +134,16 @@ public sealed class ReconnectSupervisorTests sup.ReportTransportFailure(new IOException("initial")); - // Allow the loop to attempt at least twice. - await Task.Delay(100); + // Wait for the loop's first failed reopen to land rather than sleeping a fixed 100 ms: on a + // loaded CI runner the recovery loop had not been scheduled yet, so LastError still held the + // reported cause ("initial") — #606. A presence wait returns the instant the condition holds. + var deadline = DateTime.UtcNow.AddMilliseconds(WaitMs); + while (DateTime.UtcNow < deadline + && sup.LastError?.Contains("reopen broke", StringComparison.OrdinalIgnoreCase) != true) + { + await Task.Delay(5, TestContext.Current.CancellationToken); + } + sup.LastError.ShouldNotBeNull(); sup.LastError.ShouldContain("reopen broke"); // updates from the loop's failed reopen attempts } diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Modbus.Tests/ModbusLifecycleHygieneTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Modbus.Tests/ModbusLifecycleHygieneTests.cs index f356156e..df7beb48 100644 --- a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Modbus.Tests/ModbusLifecycleHygieneTests.cs +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Modbus.Tests/ModbusLifecycleHygieneTests.cs @@ -169,8 +169,12 @@ public sealed class ModbusLifecycleHygieneTests var drv = new ModbusDriver(opts, "modbus-1", _ => fake); await drv.InitializeAsync("{}", CancellationToken.None); - // Let the probe + re-probe loops spin a few iterations. - await Task.Delay(200); + // Wait for the probe loop to issue its first send instead of sleeping a fixed 200 ms — on a + // loaded CI runner the loop had not run yet and the precondition below read 0 (#606). This is a + // presence wait (returns as soon as a send lands); the post-dispose absence window stays fixed. + var deadline = DateTime.UtcNow.AddSeconds(10); + while (Interlocked.CompareExchange(ref fake.SendCount, 0, 0) == 0 && DateTime.UtcNow < deadline) + await Task.Delay(10, TestContext.Current.CancellationToken); var sendsAtDispose = Interlocked.CompareExchange(ref fake.SendCount, 0, 0); sendsAtDispose.ShouldBeGreaterThan(0, "background probe loop should have issued at least one send"); diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Modbus.Tests/ModbusSubscribeOptionsTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Modbus.Tests/ModbusSubscribeOptionsTests.cs index bf2c44c4..9ce5ae29 100644 --- a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Modbus.Tests/ModbusSubscribeOptionsTests.cs +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Modbus.Tests/ModbusSubscribeOptionsTests.cs @@ -20,6 +20,7 @@ public sealed class ModbusSubscribeOptionsTests public ushort CurrentValue; public int WritesSent; public int FC06Count; + public int ReadCount; /// Establishes a connection (no-op for testing). /// The cancellation token. public Task ConnectAsync(CancellationToken ct) => Task.CompletedTask; @@ -33,6 +34,8 @@ public sealed class ModbusSubscribeOptionsTests { case 0x03: { + // Counted BEFORE CurrentValue is read, so a read counted after a step saw that step. + Interlocked.Increment(ref ReadCount); var qty = (ushort)((pdu[3] << 8) | pdu[4]); var resp = new byte[2 + qty * 2]; resp[0] = 0x03; resp[1] = (byte)(qty * 2); @@ -53,6 +56,27 @@ public sealed class ModbusSubscribeOptionsTests } /// Disposes the transport (no-op for testing). public ValueTask DisposeAsync() => ValueTask.CompletedTask; + + /// + /// Step the register and wait until the poll loop has demonstrably observed it: two FC03 reads + /// counted after the step. The first may be the one that read the new value; the poll loop is + /// sequential, so the second cannot start until the first's publish has been raised. Replaces a + /// fixed 150 ms sleep that, on a loaded CI runner, let a whole step go unpolled — the deadband + /// test then saw [102, 107] or [100, 107] (#606). + /// + /// The new register value. + public async Task StepAndObserveAsync(ushort value) + { + CurrentValue = value; + var target = Volatile.Read(ref ReadCount) + 2; + var deadline = DateTime.UtcNow.AddSeconds(10); + while (Volatile.Read(ref ReadCount) < target) + { + if (DateTime.UtcNow > deadline) + throw new TimeoutException($"poll loop did not read register value {value} within 10 s"); + await Task.Delay(5); + } + } } /// Verifies that deadband filter suppresses changes below the threshold. @@ -73,14 +97,10 @@ public sealed class ModbusSubscribeOptionsTests var sub = await drv.SubscribeAsync(["Temp"], TimeSpan.FromMilliseconds(50), CancellationToken.None); try { - fake.CurrentValue = 100; - await Task.Delay(150); - fake.CurrentValue = 102; - await Task.Delay(150); - fake.CurrentValue = 106; - await Task.Delay(150); - fake.CurrentValue = 107; - await Task.Delay(150); + await fake.StepAndObserveAsync(100); + await fake.StepAndObserveAsync(102); + await fake.StepAndObserveAsync(106); + await fake.StepAndObserveAsync(107); } finally { @@ -112,8 +132,8 @@ public sealed class ModbusSubscribeOptionsTests var sub = await drv.SubscribeAsync(["Temp"], TimeSpan.FromMilliseconds(50), CancellationToken.None); try { - fake.CurrentValue = 100; await Task.Delay(150); - fake.CurrentValue = 101; await Task.Delay(150); // tiny change still publishes + await fake.StepAndObserveAsync(100); + await fake.StepAndObserveAsync(101); // tiny change still publishes } finally { await drv.UnsubscribeAsync(sub, CancellationToken.None); } diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/AdminOperationsActorTagConfigGateTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/AdminOperationsActorTagConfigGateTests.cs index d4e291e6..f9689d47 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/AdminOperationsActorTagConfigGateTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/AdminOperationsActorTagConfigGateTests.cs @@ -61,8 +61,8 @@ public sealed class AdminOperationsActorTagConfigGateTests : ControlPlaneActorTe actor.Tell(new StartDeployment("joe", CorrelationId.NewId())); - coordinator.ExpectMsg(TimeSpan.FromSeconds(3)); - var reply = ExpectMsg(TimeSpan.FromSeconds(3)); + coordinator.ExpectMsg(PresenceBudget); + var reply = ExpectMsg(PresenceBudget); reply.Outcome.ShouldBe(StartDeploymentOutcome.Accepted); reply.Message.ShouldNotBeNull(); reply.Message.ShouldContain("Intt16"); @@ -81,7 +81,7 @@ public sealed class AdminOperationsActorTagConfigGateTests : ControlPlaneActorTe actor.Tell(new StartDeployment("joe", CorrelationId.NewId())); coordinator.ExpectNoMsg(TimeSpan.FromMilliseconds(500)); - var reply = ExpectMsg(TimeSpan.FromSeconds(3)); + var reply = ExpectMsg(PresenceBudget); reply.Outcome.ShouldBe(StartDeploymentOutcome.Rejected); reply.Message.ShouldNotBeNull(); reply.Message.ShouldContain("TagConfigInvalid"); @@ -102,8 +102,8 @@ public sealed class AdminOperationsActorTagConfigGateTests : ControlPlaneActorTe actor.Tell(new StartDeployment("joe", CorrelationId.NewId())); - coordinator.ExpectMsg(TimeSpan.FromSeconds(3)); - var reply = ExpectMsg(TimeSpan.FromSeconds(3)); + coordinator.ExpectMsg(PresenceBudget); + var reply = ExpectMsg(PresenceBudget); reply.Outcome.ShouldBe(StartDeploymentOutcome.Accepted); (reply.Message is null || !reply.Message.Contains("Intt16")).ShouldBeTrue(); } @@ -121,7 +121,7 @@ public sealed class AdminOperationsActorTagConfigGateTests : ControlPlaneActorTe actor.Tell(new StartDeployment("joe", CorrelationId.NewId())); - coordinator.ExpectMsg(TimeSpan.FromSeconds(3)); - ExpectMsg(TimeSpan.FromSeconds(3)).Outcome.ShouldBe(StartDeploymentOutcome.Accepted); + coordinator.ExpectMsg(PresenceBudget); + ExpectMsg(PresenceBudget).Outcome.ShouldBe(StartDeploymentOutcome.Accepted); } } diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/AuditWriterActorTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/AuditWriterActorTests.cs index d7e3400c..7d0c5522 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/AuditWriterActorTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/AuditWriterActorTests.cs @@ -39,7 +39,7 @@ public sealed class AuditWriterActorTests : ControlPlaneActorTestBase { using var db = dbFactory.CreateDbContext(); db.ConfigAuditLogs.Count().ShouldBe(AuditWriterActor.FlushBatchSize); - }, duration: TimeSpan.FromSeconds(2)); + }, duration: PresenceBudget); } /// Verifies that duplicate event IDs within a batch are deduplicated in the buffer. diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Communication/ControlPlaneStarterOrderTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Communication/ControlPlaneStarterOrderTests.cs index cd0a8112..9fd832c4 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Communication/ControlPlaneStarterOrderTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Communication/ControlPlaneStarterOrderTests.cs @@ -143,8 +143,15 @@ public sealed class ControlPlaneStarterOrderTests .ConfigureServices(services => { services.AddSingleton>(Options.Create(clusterOptions)); + // ContactRefreshSeconds = 1 (production: 60). The memoized PSK provider retries on EVERY + // refresh, so a first refresh that lands before the registry-bound graph is resolvable + // (the lost race the resolution fact exists to heal) publishes on the NEXT tick. At 60 s + // that next tick was outside the fact's 20 s budget — a lost race on a loaded CI runner + // timed out red exactly like a never-resolved provider (the Dps case failed in 2 of 7 + // Gitea runs, #606). A 1 s cadence + // still proves "resolved and used" — a provider that stayed null forever never publishes. services.AddSingleton>(Options.Create( - new MeshTransportOptions { Mode = mode, DispatchTimeoutSeconds = 10 })); + new MeshTransportOptions { Mode = mode, DispatchTimeoutSeconds = 10, ContactRefreshSeconds = 1 })); services.AddDbContextFactory( o => o.UseInMemoryDatabase($"starter-order-{Guid.NewGuid():N}")); services.AddSingleton(new StubClusterRoleInfo()); diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Communication/MeshRouterDispatchTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Communication/MeshRouterDispatchTests.cs index fdb17d6d..5d4095b7 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Communication/MeshRouterDispatchTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Communication/MeshRouterDispatchTests.cs @@ -38,7 +38,7 @@ public class MeshRouterDispatchTests : ControlPlaneActorTestBase coordinator.Tell(new Commons.Messages.Deploy.DispatchDeployment( deploymentId, new RevisionHash("rev-1"), CorrelationId.NewId())); - var cmd = router.ExpectMsg(TimeSpan.FromSeconds(5)); + var cmd = router.ExpectMsg(PresenceBudget); cmd.Topic.ShouldBe(DeploymentsTopic); cmd.Message.ShouldBeOfType(); } @@ -49,7 +49,7 @@ public class MeshRouterDispatchTests : ControlPlaneActorTestBase var subscriber = CreateTestProbe(); DistributedPubSub.Get(Sys).Mediator.Tell( new Subscribe(DeploymentsTopic, subscriber.Ref), subscriber.Ref); - subscriber.ExpectMsg(TimeSpan.FromSeconds(5)); + subscriber.ExpectMsg(PresenceBudget); var coordinator = Sys.ActorOf(ConfigPublishCoordinator.Props(NewInMemoryDbFactory())); @@ -57,7 +57,9 @@ public class MeshRouterDispatchTests : ControlPlaneActorTestBase coordinator.Tell(new Commons.Messages.Deploy.DispatchDeployment( deploymentId, new RevisionHash("rev-1"), CorrelationId.NewId())); - subscriber.ExpectMsg(TimeSpan.FromSeconds(5)); + // Presence budget, not 5 s: the coordinator's first ConfigDb (EF InMemory) read sits in front + // of the dispatch and is a cold multi-second cost on a loaded CI runner (#606). + subscriber.ExpectMsg(PresenceBudget); } [Fact] @@ -73,7 +75,7 @@ public class MeshRouterDispatchTests : ControlPlaneActorTestBase admin.Tell(new RestartDriver("C1", "driver-1", "alice", Guid.NewGuid())); - var cmd = router.ExpectMsg(TimeSpan.FromSeconds(5)); + var cmd = router.ExpectMsg(PresenceBudget); cmd.Topic.ShouldBe(DriverControlTopic.Name); cmd.Message.ShouldBeOfType(); } @@ -91,7 +93,7 @@ public class MeshRouterDispatchTests : ControlPlaneActorTestBase admin.Tell(new ReconnectDriver("C1", "driver-1", "alice", Guid.NewGuid())); - var cmd = router.ExpectMsg(TimeSpan.FromSeconds(5)); + var cmd = router.ExpectMsg(PresenceBudget); cmd.Topic.ShouldBe(DriverControlTopic.Name); cmd.Message.ShouldBeOfType(); } @@ -109,7 +111,7 @@ public class MeshRouterDispatchTests : ControlPlaneActorTestBase admin.Tell(new AcknowledgeAlarmCommand("alarm-1", "alice", "c", CorrelationId.NewId())); - var cmd = router.ExpectMsg(TimeSpan.FromSeconds(5)); + var cmd = router.ExpectMsg(PresenceBudget); cmd.Topic.ShouldBe(AlarmCommandsTopic.Name); cmd.Message.ShouldBeOfType(); } @@ -127,7 +129,7 @@ public class MeshRouterDispatchTests : ControlPlaneActorTestBase admin.Tell(new ShelveAlarmCommand("alarm-1", "alice", ShelveKind.OneShot, null, "c", CorrelationId.NewId())); - var cmd = router.ExpectMsg(TimeSpan.FromSeconds(5)); + var cmd = router.ExpectMsg(PresenceBudget); cmd.Topic.ShouldBe(AlarmCommandsTopic.Name); cmd.Message.ShouldBeOfType(); } diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Harness/ControlPlaneTestHarness.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Harness/ControlPlaneTestHarness.cs index 5a07da68..aba03afd 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Harness/ControlPlaneTestHarness.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Harness/ControlPlaneTestHarness.cs @@ -16,10 +16,33 @@ namespace ZB.MOM.WW.OtOpcUa.ControlPlane.Tests.Harness; /// public abstract class ControlPlaneActorTestBase : TestKit { + /// + /// Shared upper bound for a presence wait (ExpectMsg / ExpectTerminated / + /// AwaitAssert) — the same doctrine as RuntimeActorTestBase.PresenceBudget. + /// + /// + /// A budget, not a delay: the helpers return the instant the condition holds, so raising it costs + /// nothing on the happy path and cannot make a genuinely failing assertion pass. Several actors here + /// do their first EF Core (InMemory) work inside the waited-for step — model build is a multi-second + /// cold cost on a loaded CI runner — and 3–5 s budgets sized on an idle machine failed there (#606). + /// Absence windows (ExpectNoMsg) keep their own short literals and must not use this. + /// + protected static readonly TimeSpan PresenceBudget = TimeSpan.FromSeconds(15); + /// Gets the Akka configuration for test actors, including cluster and pub-sub extensions. - protected static string AkkaTestHocon => @" + /// + /// akka.test.single-expect-default is raised from Akka's 3 s to : + /// it is the budget every duration-less ExpectMsg/ExpectTerminated/AwaitAssert + /// uses, all of which are presence waits. Nothing in this assembly calls a duration-less + /// ExpectNoMsg(), the one absence wait that would also read it. + /// akka.test.timefactor comes from . + /// + protected static string AkkaTestHocon => BaseHocon + TestTimeFactor.Hocon; + + private const string BaseHocon = @" akka { loglevel = ""WARNING"" + test.single-expect-default = 15s extensions = [ ""Akka.Cluster.Tools.PublishSubscribe.DistributedPubSubExtensionProvider, Akka.Cluster.Tools"" ] diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Harness/TestTimeFactor.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Harness/TestTimeFactor.cs new file mode 100644 index 00000000..585c8c96 --- /dev/null +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Harness/TestTimeFactor.cs @@ -0,0 +1,38 @@ +using System.Globalization; + +namespace ZB.MOM.WW.OtOpcUa.ControlPlane.Tests.Harness; + +/// +/// The Akka TestKit time-dilation factor for this run, from the AKKA_TEST_TIMEFACTOR environment +/// variable (unset ⇒ 1, Akka's own default). +/// +/// +/// +/// akka.test.timefactor is Akka's sanctioned answer to "this machine is slower than the one +/// the timeouts were sized on": TestKit multiplies every ExpectMsg / ExpectTerminated / +/// AwaitAssert / AwaitCondition / ExpectNoMsg duration by it — explicit +/// durations included (RemainingOrDilated). The Gitea CI leg sets it (#606): the whole +/// solution runs there at once on the CI runner, and a long tail of 2–8 s presence budgets that +/// never fail locally each failed in roughly one run in eight, a different test each time — a +/// distribution, not a defect, the same shape Gitea #500 hit inside Runtime.Tests. +/// +/// +/// Dilation cannot make a broken assertion pass: a presence wait still fails, just later, and an +/// absence window only gets LONGER (a stronger check). It does not reach Ask timeouts or +/// plain Task.WaitAsync budgets — those are sized from ControlPlaneActorTestBase.PresenceBudget instead. +/// +/// +internal static class TestTimeFactor +{ + /// The environment variable the CI workflow sets. + public const string EnvironmentVariable = "AKKA_TEST_TIMEFACTOR"; + + /// The factor in effect: the variable's value when it parses to a number ≥ 1, else 1. + public static double Value { get; } = + double.TryParse(Environment.GetEnvironmentVariable(EnvironmentVariable), NumberStyles.Float, + CultureInfo.InvariantCulture, out var f) && f >= 1 ? f : 1; + + /// A HOCON line setting akka.test.timefactor, to append to a test config. + public static string Hocon => + "\nakka.test.timefactor = " + Value.ToString(CultureInfo.InvariantCulture) + "\n"; +} diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/DriverReconnectE2eTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/DriverReconnectE2eTests.cs index 72c1ea61..824030e4 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/DriverReconnectE2eTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/DriverReconnectE2eTests.cs @@ -94,6 +94,13 @@ public sealed class DriverReconnectE2eTests r2.CorrelationId.ShouldBe(second.CorrelationId); } + /// + /// Presence budget for the full-stack waits below — two in-process nodes booting a deployment on a + /// loaded CI runner. Each wait returns as soon as its condition holds, so this is a ceiling, not a + /// delay; the previous 20 s ceiling timed out on a Gitea run (#606). + /// + private static readonly TimeSpan Budget = TimeSpan.FromSeconds(45); + private const string ClusterId = "RECONNECT-E2E"; private const string DriverId = "drv-modbus"; @@ -150,24 +157,50 @@ public sealed class DriverReconnectE2eTests var deploy = await client.StartDeploymentAsync(createdBy: "e2e", Ct); deploy.Outcome.ShouldBe(StartDeploymentOutcome.Accepted, $"Deploy not accepted: {deploy.Message}"); - // Wait until the driver is spawned (factory recorded it) AND reached Healthy in the store. + // BOTH harness nodes are driver members of the cluster, so each spawns its own instance from + // the one shared factory (#606). Wait for both, not just "the" one in `Created` — that slot is + // last-writer-wins, and on a loaded runner the second node's instance landed AFTER the test had + // flipped the first, so the final InitializeCount read an instance the command never touched. await WaitForAsync(() => Task.FromResult( - factory.Created.TryGetValue(DriverId, out _) + factory.InstancesOf(DriverId).Count >= 2 && store.TryGet(DriverId, out var s) && s.State == "Healthy"), - TimeSpan.FromSeconds(20)); + Budget); + var instances = factory.InstancesOf(DriverId); // Simulate the lost connection the operator Reconnect responds to. - factory.Created[DriverId].ReportReconnecting(); + foreach (var instance in instances) instance.ReportReconnecting(); - var result = await client.AskAsync( - new ReconnectDriver(ClusterId, DriverId, "e2e", Guid.NewGuid()), Ct); - result.Ok.ShouldBeTrue($"ReconnectDriver failed: {result.Message}"); + // ForceReconnect is a documented no-op while a DriverInstanceActor is still Connecting, and the + // store cannot say which node's actor has reached Connected. So re-issue the (idempotent — see + // Reconnect_IsIdempotent_SecondCallAlsoReturnsOk) command until every instance has been + // re-initialised. Nothing else re-initialises a fake driver inside this window — the comms-loss + // watchdog needs 90 s of frozen reads — so InitializeCount >= 2 is still the command's doing. + await WaitForAsync(async () => + { + var result = await client.AskAsync( + new ReconnectDriver(ClusterId, DriverId, "e2e", Guid.NewGuid()), Ct); + result.Ok.ShouldBeTrue($"ReconnectDriver failed: {result.Message}"); + + var settle = DateTime.UtcNow.AddSeconds(3); + while (DateTime.UtcNow < settle) + { + if (instances.All(i => i.InitializeCount >= 2)) return true; + await Task.Delay(100, Ct); + } + + return false; + }, Budget); // The published health must walk Reconnecting → (later) Healthy for this driver. await WaitForAsync(() => { lock (captureLock) return Task.FromResult(HasReconnectThenHealthy(captured)); - }, TimeSpan.FromSeconds(20)); + }, Budget); + + // The store is last-writer-wins across the two nodes too: wait for the settled state rather + // than reading whichever node's push happened to land last. + await WaitForAsync( + () => Task.FromResult(store.TryGet(DriverId, out var s) && s.State == "Healthy"), Budget); List snapshot; lock (captureLock) snapshot = captured.Where(c => c.DriverInstanceId == DriverId).ToList(); @@ -180,8 +213,9 @@ public sealed class DriverReconnectE2eTests final.State.ShouldBe("Healthy"); // ≥ 2 proves the command genuinely re-initialised the driver via the full cluster path - // (initial connect + at least one reconnect retry). - factory.Created[DriverId].InitializeCount.ShouldBeGreaterThanOrEqualTo(2); + // (initial connect + at least one reconnect retry) — on every node hosting it. + foreach (var instance in instances) + instance.InitializeCount.ShouldBeGreaterThanOrEqualTo(2); } finally { diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/Fakes/FakeReconnectDriverFactory.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/Fakes/FakeReconnectDriverFactory.cs index a2ff9911..5f53a554 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/Fakes/FakeReconnectDriverFactory.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/Fakes/FakeReconnectDriverFactory.cs @@ -46,9 +46,26 @@ public sealed class FakeReconnectDriverFactory : IDriverFactory if (driverType != FakeDriverType) return null; var driver = new FakeReconnectDriver(driverInstanceId, driverType); Created[driverInstanceId] = driver; + _all.Enqueue(driver); return driver; } + private readonly ConcurrentQueue _all = new(); + + /// + /// EVERY driver this factory has created for , in creation order. + /// + /// + /// The harness registers ONE factory on BOTH nodes, and both nodes host a deployed driver, so + /// (last writer wins) holds whichever node spawned last — and that can change + /// after a test has read it. A test that flips or inspects "the" driver must use this instead + /// (#606: the reconnect E2E asserted on an instance the other node had just replaced). + /// + /// The driver-instance identifier. + /// A snapshot of the created instances. + public IReadOnlyList InstancesOf(string driverInstanceId) => + _all.Where(d => d.DriverInstanceId == driverInstanceId).ToList(); + /// Gets the driver-type names this factory can materialise. public IReadOnlyCollection SupportedTypes { get; } = new[] { FakeDriverType }; } 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 4fd78970..004b7165 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Host.IntegrationTests/RoslynVirtualTagEvaluatorTests.cs @@ -308,6 +308,15 @@ public sealed class RoslynVirtualTagEvaluatorTests /// An infinite-loop script returns Failure ("timed out") within the timeout budget instead /// of hanging. The whole call is bounded by WaitAsync so a regression FAILS the test (with a /// TimeoutException) rather than wedging the suite. + /// + /// A CPU-bound script that outlives the 200 ms run timeout by 25x but still ENDS. A timed-out script + /// is abandoned, not stopped, so the old while(true){} pinned one core for the rest of the test + /// process — starving every parallel suite on a small CI runner (#606). System.DateTime is + /// outside the sandbox deny-list. + /// + private const string BoundedSpinScript = + "var end = System.DateTime.UtcNow.AddSeconds(5); while (System.DateTime.UtcNow < end) { } return 0;"; + [Fact] public async Task Evaluate_infinite_loop_script_fails_within_timeout_and_does_not_hang() { @@ -315,10 +324,15 @@ public sealed class RoslynVirtualTagEvaluatorTests NullLogger.Instance, NoOpScriptRoot(), TimeSpan.FromMilliseconds(200)); var evalTask = Task.Run( - () => sut.Evaluate("vt-loop", "while(true){}return 0;", new Dictionary()), + () => sut.Evaluate("vt-loop", BoundedSpinScript, new Dictionary()), TestContext.Current.CancellationToken); - var result = await evalTask.WaitAsync(TimeSpan.FromSeconds(5), TestContext.Current.CancellationToken); + // The outer bound covers the Roslyn COMPILE as well as the run — the 200 ms run timeout starts + // only once the script is compiled — and a cold compile on a loaded CI runner took the old 5 s + // budget on every one of four consecutive Gitea runs (#606). 30 s is still a hard bound, so a + // hang still fails the test; and because the spin ends after 5 s, a timeout that never fires + // now fails it too (Success == true), rather than only failing as a hang. + var result = await evalTask.WaitAsync(TimeSpan.FromSeconds(30), TestContext.Current.CancellationToken); result.Success.ShouldBeFalse(); result.Reason.ShouldNotBeNull(); diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/CalculationDependencyFlowTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/CalculationDependencyFlowTests.cs index b70d82a5..9a8aa40c 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/CalculationDependencyFlowTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/CalculationDependencyFlowTests.cs @@ -82,7 +82,7 @@ public sealed class CalculationDependencyFlowTests : RuntimeActorTestBase published.ShouldContain(e => e.FullReference == "calc/engine/out" && Equals(e.Snapshot.Value, 42.0)); // Leg 2 — calc-of-calc: A's 42 re-entered the mux → B computes 43 on calc/engine/b. published.ShouldContain(e => e.FullReference == "calc/engine/b" && Equals(e.Snapshot.Value, 43.0)); - }, TimeSpan.FromSeconds(5), TimeSpan.FromMilliseconds(100)); + }, PresenceBudget, TimeSpan.FromMilliseconds(100)); } /// @@ -128,7 +128,7 @@ public sealed class CalculationDependencyFlowTests : RuntimeActorTestBase mux.Tell(new DriverInstanceActor.AttributeValuePublished("src-drv", "src/a", 2.0, OpcUaStatus.Good, Ts)); published.ShouldContain(e => e.FullReference == "calc/keep" && Equals(e.Snapshot.Value, 20.0)); published.ShouldContain(e => e.FullReference == "calc/remove" && Equals(e.Snapshot.Value, 7.0)); - }, TimeSpan.FromSeconds(5), TimeSpan.FromMilliseconds(100)); + }, PresenceBudget, TimeSpan.FromMilliseconds(100)); // ---- REDEPLOY (in-place ApplyDelta) ---- // New authored set: "keep" script EDITED to src/a*1000; "add" is a NEW tag reading a NEW dep src/b; @@ -156,7 +156,7 @@ public sealed class CalculationDependencyFlowTests : RuntimeActorTestBase published.ShouldContain(e => e.FullReference == "calc/add" && Equals(e.Snapshot.Value, 150.0)); // (c) edited script produces the NEW result: 3 * 1000 = 3000 (NOT the pre-edit 3 * 10 = 30). published.ShouldContain(e => e.FullReference == "calc/keep" && Equals(e.Snapshot.Value, 3000.0)); - }, TimeSpan.FromSeconds(5), TimeSpan.FromMilliseconds(100)); + }, PresenceBudget, TimeSpan.FromMilliseconds(100)); // (b) the removed tag never recomputes on the post-redeploy src/a=3 (it would be 3 + 5 = 8) and the // edited "keep" never serves the stale *10 result (3 * 10 = 30). Give any errant compute a moment to land. diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorBootFromCacheTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorBootFromCacheTests.cs index bdc671f2..c19a75f3 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorBootFromCacheTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorBootFromCacheTests.cs @@ -75,7 +75,7 @@ public sealed class DriverHostActorBootFromCacheTests : RuntimeActorTestBase opcUaPublishActor: publishProbe.Ref, deploymentArtifactCache: new StubArtifactCache(cached))); - var rebuild = publishProbe.ExpectMsg(TimeSpan.FromSeconds(5)); + var rebuild = publishProbe.ExpectMsg(PresenceBudget); rebuild.Artifact.ShouldNotBeNull(); rebuild.Artifact.ShouldBe(blob); } @@ -226,7 +226,7 @@ public sealed class DriverHostActorBootFromCacheTests : RuntimeActorTestBase // The point: the restore path wrote the served artifact back into the cache. AwaitAssert( () => cache.Stores.ShouldBe(1), - duration: TimeSpan.FromSeconds(5)); + duration: PresenceBudget); cache.LastStoredDeploymentId.ShouldBe(deploymentId.ToString()); } @@ -241,10 +241,10 @@ public sealed class DriverHostActorBootFromCacheTests : RuntimeActorTestBase actor.Tell(new GetDiagnostics(CorrelationId.NewId()), probe.Ref); probe.ExpectMsg(TimeSpan.FromSeconds(2)); }, - duration: TimeSpan.FromSeconds(5)); + duration: PresenceBudget); actor.Tell(new GetDiagnostics(CorrelationId.NewId()), probe.Ref); - return probe.ExpectMsg(TimeSpan.FromSeconds(5)); + return probe.ExpectMsg(PresenceBudget); } /// A syntactically valid artifact with no driver instances. diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorDbLessTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorDbLessTests.cs index fbf049f3..2edeee62 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorDbLessTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorDbLessTests.cs @@ -88,7 +88,7 @@ public sealed class DriverHostActorDbLessTests : RuntimeActorTestBase private IActorRef? ResolveChild(IActorRef parent, string name) { var id = Sys.ActorSelection(parent.Path / name) - .Ask(new Identify(name), TimeSpan.FromSeconds(3)) + .Ask(new Identify(name), PresenceBudget) .GetAwaiter().GetResult(); return id.Subject; } @@ -96,7 +96,7 @@ public sealed class DriverHostActorDbLessTests : RuntimeActorTestBase /// Blocks until the actor has processed a message — proving PreStart has run. private void AwaitStarted(IActorRef actor) { - var id = actor.Ask(new Identify("started"), TimeSpan.FromSeconds(5)) + var id = actor.Ask(new Identify("started"), PresenceBudget) .GetAwaiter().GetResult(); id.Subject.ShouldBe(actor); } @@ -129,8 +129,8 @@ public sealed class DriverHostActorDbLessTests : RuntimeActorTestBase actor.Tell(new DispatchDeployment(deploymentId, RevA, CorrelationId.NewId())); - coordinator.ExpectMsg(TimeSpan.FromSeconds(5)).Outcome.ShouldBe(ApplyAckOutcome.Applied); - AwaitAssert(() => cache.Stores.Count.ShouldBe(1), duration: TimeSpan.FromSeconds(3)); + coordinator.ExpectMsg(PresenceBudget).Outcome.ShouldBe(ApplyAckOutcome.Applied); + AwaitAssert(() => cache.Stores.Count.ShouldBe(1), duration: PresenceBudget); fetcher.Calls.ShouldBe(1); } diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorFetchAndCacheTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorFetchAndCacheTests.cs index 1bcaea99..97d12c1d 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorFetchAndCacheTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorFetchAndCacheTests.cs @@ -47,8 +47,8 @@ public sealed class DriverHostActorFetchAndCacheTests : RuntimeActorTestBase actor.Tell(new DispatchDeployment(deploymentId, RevA, CorrelationId.NewId())); - coordinator.ExpectMsg(TimeSpan.FromSeconds(5)).Outcome.ShouldBe(ApplyAckOutcome.Applied); - AwaitAssert(() => cache.Stores.Count.ShouldBe(1), duration: TimeSpan.FromSeconds(3)); + coordinator.ExpectMsg(PresenceBudget).Outcome.ShouldBe(ApplyAckOutcome.Applied); + AwaitAssert(() => cache.Stores.Count.ShouldBe(1), duration: PresenceBudget); cache.Stores[0].RevisionHash.ShouldBe(RevA.Value); fetcher.Calls.ShouldBe(1); } @@ -70,7 +70,7 @@ public sealed class DriverHostActorFetchAndCacheTests : RuntimeActorTestBase artifactFetcher: fetcher)); actor.Tell(new DispatchDeployment(deploymentId, RevA, CorrelationId.NewId())); - coordinator.ExpectMsg(TimeSpan.FromSeconds(5)).Outcome.ShouldBe(ApplyAckOutcome.Failed); + coordinator.ExpectMsg(PresenceBudget).Outcome.ShouldBe(ApplyAckOutcome.Failed); Thread.Sleep(300); cache.Stores.ShouldBeEmpty(); @@ -78,7 +78,7 @@ public sealed class DriverHostActorFetchAndCacheTests : RuntimeActorTestBase // The revision was NOT advanced: a re-dispatch of the SAME revision fetches AGAIN rather than // short-circuiting as "already current". (Two fetch attempts prove #485's keep-last-known-good.) actor.Tell(new DispatchDeployment(deploymentId, RevA, CorrelationId.NewId())); - coordinator.ExpectMsg(TimeSpan.FromSeconds(5)).Outcome.ShouldBe(ApplyAckOutcome.Failed); + coordinator.ExpectMsg(PresenceBudget).Outcome.ShouldBe(ApplyAckOutcome.Failed); fetcher.Calls.ShouldBe(2); } @@ -99,12 +99,12 @@ public sealed class DriverHostActorFetchAndCacheTests : RuntimeActorTestBase artifactFetcher: fetcher)); actor.Tell(new DispatchDeployment(deploymentId, RevA, CorrelationId.NewId())); - coordinator.ExpectMsg(TimeSpan.FromSeconds(5)).Outcome.ShouldBe(ApplyAckOutcome.Applied); + coordinator.ExpectMsg(PresenceBudget).Outcome.ShouldBe(ApplyAckOutcome.Applied); // Re-dispatch the now-current revision: the _currentRevision guard short-circuits to an // immediate ACK without a second fetch. actor.Tell(new DispatchDeployment(deploymentId, RevA, CorrelationId.NewId())); - coordinator.ExpectMsg(TimeSpan.FromSeconds(5)).Outcome.ShouldBe(ApplyAckOutcome.Applied); + coordinator.ExpectMsg(PresenceBudget).Outcome.ShouldBe(ApplyAckOutcome.Applied); Thread.Sleep(200); fetcher.Calls.ShouldBe(1); diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorFetchAndCacheUnreadableTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorFetchAndCacheUnreadableTests.cs index a1963a56..f74ea851 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorFetchAndCacheUnreadableTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorFetchAndCacheUnreadableTests.cs @@ -54,11 +54,11 @@ public sealed class DriverHostActorFetchAndCacheUnreadableTests : RuntimeActorTe artifactFetcher: fetcher)); actor.Tell(new DispatchDeployment(DeploymentId.NewId(), RevA, CorrelationId.NewId())); - coordinator.ExpectMsg(TimeSpan.FromSeconds(5)).Outcome.ShouldBe(ApplyAckOutcome.Applied); - publishProbe.ExpectMsg(TimeSpan.FromSeconds(5)); // revA rebuild + coordinator.ExpectMsg(PresenceBudget).Outcome.ShouldBe(ApplyAckOutcome.Applied); + publishProbe.ExpectMsg(PresenceBudget); // revA rebuild actor.Tell(new DispatchDeployment(DeploymentId.NewId(), RevB, CorrelationId.NewId())); - coordinator.ExpectMsg(TimeSpan.FromSeconds(5)).Outcome.ShouldBe(ApplyAckOutcome.Failed); + coordinator.ExpectMsg(PresenceBudget).Outcome.ShouldBe(ApplyAckOutcome.Failed); // The #485 negative: no rebuild for the failed revB — the served address space is untouched. publishProbe.ExpectNoMsg(TimeSpan.FromMilliseconds(500)); @@ -85,7 +85,7 @@ public sealed class DriverHostActorFetchAndCacheUnreadableTests : RuntimeActorTe actor.Tell(new DispatchDeployment(DeploymentId.NewId(), RevA, CorrelationId.NewId())); - coordinator.ExpectMsg(TimeSpan.FromSeconds(5)).Outcome.ShouldBe(ApplyAckOutcome.Failed); + coordinator.ExpectMsg(PresenceBudget).Outcome.ShouldBe(ApplyAckOutcome.Failed); publishProbe.ExpectNoMsg(TimeSpan.FromMilliseconds(500)); // nothing applied, nothing rebuilt } @@ -119,10 +119,10 @@ public sealed class DriverHostActorFetchAndCacheUnreadableTests : RuntimeActorTe actor.Tell(new GetDiagnostics(CorrelationId.NewId()), probe.Ref); probe.ExpectMsg(TimeSpan.FromSeconds(2)); }, - duration: TimeSpan.FromSeconds(5)); + duration: PresenceBudget); actor.Tell(new GetDiagnostics(CorrelationId.NewId()), probe.Ref); - return probe.ExpectMsg(TimeSpan.FromSeconds(5)); + return probe.ExpectMsg(PresenceBudget); } private sealed class MapFetcher(Dictionary map) : IDeploymentArtifactFetcher diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorHistorizationRoleViewTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorHistorizationRoleViewTests.cs index ad699c62..5230ea3b 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorHistorizationRoleViewTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorHistorizationRoleViewTests.cs @@ -32,7 +32,7 @@ public sealed class DriverHostActorHistorizationRoleViewTests : RuntimeActorTest private static readonly NodeId TestNode = NodeId.Parse("driver-histview-test"); private static readonly NodeId MeshPeer = NodeId.Parse("mesh-peer:4053"); private static readonly NodeId ForeignNode = NodeId.Parse("other-cluster:4053"); - private static readonly TimeSpan Timeout = TimeSpan.FromSeconds(5); + private static readonly TimeSpan Timeout = PresenceBudget; /// /// Before any snapshot arrives the view must read open, not closed. diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorNativeAlarmAckRoutingTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorNativeAlarmAckRoutingTests.cs index f3d75523..c74619fa 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorNativeAlarmAckRoutingTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorNativeAlarmAckRoutingTests.cs @@ -41,7 +41,7 @@ public sealed class DriverHostActorNativeAlarmAckRoutingTests : RuntimeActorTest { private static readonly NodeId TestNode = NodeId.Parse("driver-ack-test"); private static readonly RevisionHash RevA = RevisionHash.Parse(new string('a', 64)); - private static readonly TimeSpan Timeout = TimeSpan.FromSeconds(5); + private static readonly TimeSpan Timeout = PresenceBudget; // The v3 RawPath for the seeded alarm tag: RawFolder "Plant" / DriverName "gw" / Device "dev1" / Tag. private const string AlarmRawPath = "Plant/gw/dev1/temp_hi"; diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorPrimaryRoleSourceTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorPrimaryRoleSourceTests.cs index 6043f7dd..859b7818 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorPrimaryRoleSourceTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorPrimaryRoleSourceTests.cs @@ -24,7 +24,7 @@ namespace ZB.MOM.WW.OtOpcUa.Runtime.Tests.Drivers; public sealed class DriverHostActorPrimaryRoleSourceTests : RuntimeActorTestBase { private static readonly NodeId TestNode = NodeId.Parse("driver-primary-source-test"); - private static readonly TimeSpan Timeout = TimeSpan.FromSeconds(5); + private static readonly TimeSpan Timeout = PresenceBudget; /// On a pair, an unknown role publishes DENY at start — before any snapshot. The later Primary snapshot /// is the positive control: the source is wired, and the deny was the verdict, not a missing publish. diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverInstanceActorBatchForwardTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverInstanceActorBatchForwardTests.cs index 922a12fc..1c470992 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverInstanceActorBatchForwardTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverInstanceActorBatchForwardTests.cs @@ -42,7 +42,7 @@ public sealed class DriverInstanceActorBatchForwardTests : RuntimeActorTestBase await actor.Ask( new DriverInstanceActor.Subscribe(new[] { "tag-a", "tag-b", "tag-c" }, TimeSpan.FromMilliseconds(100)), - TimeSpan.FromSeconds(3)); + PresenceBudget); var sourceTs = new DateTime(2026, 8, 15, 10, 0, 0, DateTimeKind.Utc); var serverTs = new DateTime(2026, 8, 15, 10, 0, 5, DateTimeKind.Utc); @@ -52,7 +52,7 @@ public sealed class DriverInstanceActorBatchForwardTests : RuntimeActorTestBase // Null source timestamp — the server timestamp is the fallback, per OnDataChangeForward. new DataChangeItem("tag-c", new DataValueSnapshot(null, OpcUaStatus.BadNoCommunication, null, serverTs))); - var batch = parent.ExpectMsg(TimeSpan.FromSeconds(2)); + var batch = parent.ExpectMsg(PresenceBudget); batch.DriverInstanceId.ShouldBe(driver.DriverInstanceId); batch.Items.Count.ShouldBe(3); @@ -95,7 +95,7 @@ public sealed class DriverInstanceActorBatchForwardTests : RuntimeActorTestBase await actor.Ask( new DriverInstanceActor.Subscribe(new[] { "tag-a", "tag-b" }, TimeSpan.FromMilliseconds(100)), - TimeSpan.FromSeconds(3)); + PresenceBudget); // Deterministic half of the assertion: the per-tag handler was never attached at all. ExpectNoMsg // below only proves nothing arrived within its window; this proves it structurally cannot. @@ -106,7 +106,7 @@ public sealed class DriverInstanceActorBatchForwardTests : RuntimeActorTestBase new DataChangeItem("tag-a", new DataValueSnapshot(1, OpcUaStatus.Good, ts, ts)), new DataChangeItem("tag-b", new DataValueSnapshot(2, OpcUaStatus.Good, ts, ts))); - var batch = parent.ExpectMsg(TimeSpan.FromSeconds(2)); + var batch = parent.ExpectMsg(PresenceBudget); batch.Items.Count.ShouldBe(2); // The per-tag raises for the SAME burst produced nothing extra — no second batch, no @@ -132,11 +132,11 @@ public sealed class DriverInstanceActorBatchForwardTests : RuntimeActorTestBase await actor.Ask( new DriverInstanceActor.Subscribe(new[] { "tag-a" }, TimeSpan.FromMilliseconds(100)), - TimeSpan.FromSeconds(3)); + PresenceBudget); driver.FireDataChange("tag-a", value: 3.14, statusCode: OpcUaStatus.Good); - var batch = parent.ExpectMsg(TimeSpan.FromSeconds(2)); + var batch = parent.ExpectMsg(PresenceBudget); batch.DriverInstanceId.ShouldBe(driver.DriverInstanceId); batch.Items.Count.ShouldBe(1); batch.Items[0].FullReference.ShouldBe("tag-a"); @@ -162,7 +162,7 @@ public sealed class DriverInstanceActorBatchForwardTests : RuntimeActorTestBase await actor.Ask( new DriverInstanceActor.Subscribe(new[] { "tag-a" }, TimeSpan.FromMilliseconds(100)), - TimeSpan.FromSeconds(3)); + PresenceBudget); driver.OnDataChangeBatchSubscriberCount.ShouldBe(1, "the batch handler is attached for an IBatchSubscribable driver"); actor.Tell(new DriverInstanceActor.Unsubscribe()); @@ -194,7 +194,7 @@ public sealed class DriverInstanceActorBatchForwardTests : RuntimeActorTestBase await actor.Ask( new DriverInstanceActor.Subscribe(new[] { "tag-a" }, TimeSpan.FromMilliseconds(100)), - TimeSpan.FromSeconds(3)); + PresenceBudget); driver.OnDataChangeBatchSubscriberCount.ShouldBe(1); actor.Tell(new DriverInstanceActor.DisconnectObserved("backend went away")); @@ -227,7 +227,7 @@ public sealed class DriverInstanceActorBatchForwardTests : RuntimeActorTestBase await actor.Ask( new DriverInstanceActor.Subscribe(new[] { "tag-a" }, TimeSpan.FromMilliseconds(100)), - TimeSpan.FromSeconds(3)); + PresenceBudget); driver.OnDataChangeBatchSubscriberCount.ShouldBe(1); Sys.Stop(actor); @@ -254,7 +254,7 @@ public sealed class DriverInstanceActorBatchForwardTests : RuntimeActorTestBase await actor.Ask( new DriverInstanceActor.Subscribe(new[] { "tag-a" }, TimeSpan.FromMilliseconds(100)), - TimeSpan.FromSeconds(3)); + PresenceBudget); driver.FireBatch(includePerTagRaises: false /* no items — an empty burst */); driver.FireNullBatch(); @@ -268,7 +268,7 @@ public sealed class DriverInstanceActorBatchForwardTests : RuntimeActorTestBase driver.FireBatch(includePerTagRaises: false, new DataChangeItem("tag-a", new DataValueSnapshot(5, OpcUaStatus.Good, ts, ts))); - var batch = parent.ExpectMsg(TimeSpan.FromSeconds(2)); + var batch = parent.ExpectMsg(PresenceBudget); batch.Items.Count.ShouldBe(1); batch.Items[0].FullReference.ShouldBe("tag-a"); batch.Items[0].Value.ShouldBe(5); diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Harness/RuntimeActorTestBase.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Harness/RuntimeActorTestBase.cs index d6f8fafe..3e52f0e0 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Harness/RuntimeActorTestBase.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Harness/RuntimeActorTestBase.cs @@ -34,9 +34,19 @@ public abstract class RuntimeActorTestBase : TestKit public static readonly TimeSpan PresenceBudget = TimeSpan.FromSeconds(15); /// Gets the Akka test HOCON configuration string for single-node cluster setup. - protected static string AkkaTestHocon => @" + /// + /// akka.test.single-expect-default is raised from Akka's 3 s to + /// (#606): it is the budget of every duration-less ExpectMsg/ExpectTerminated/ + /// AwaitAssert, all presence waits. No test here calls a duration-less ExpectNoMsg(), + /// the one absence wait that would also read it. + /// akka.test.timefactor comes from . + /// + protected static string AkkaTestHocon => BaseHocon + TestTimeFactor.Hocon; + + private const string BaseHocon = @" akka { loglevel = ""WARNING"" + test.single-expect-default = 15s extensions = [ ""Akka.Cluster.Tools.PublishSubscribe.DistributedPubSubExtensionProvider, Akka.Cluster.Tools"" ] diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Harness/TestTimeFactor.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Harness/TestTimeFactor.cs new file mode 100644 index 00000000..d8a028c4 --- /dev/null +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Harness/TestTimeFactor.cs @@ -0,0 +1,38 @@ +using System.Globalization; + +namespace ZB.MOM.WW.OtOpcUa.Runtime.Tests.Harness; + +/// +/// The Akka TestKit time-dilation factor for this run, from the AKKA_TEST_TIMEFACTOR environment +/// variable (unset ⇒ 1, Akka's own default). +/// +/// +/// +/// akka.test.timefactor is Akka's sanctioned answer to "this machine is slower than the one +/// the timeouts were sized on": TestKit multiplies every ExpectMsg / ExpectTerminated / +/// AwaitAssert / AwaitCondition / ExpectNoMsg duration by it — explicit +/// durations included (RemainingOrDilated). The Gitea CI leg sets it (#606): the whole +/// solution runs there at once on the CI runner, and a long tail of 2–8 s presence budgets that +/// never fail locally each failed in roughly one run in eight, a different test each time — a +/// distribution, not a defect, exactly the shape Gitea #500 hit inside this assembly alone. +/// +/// +/// Dilation cannot make a broken assertion pass: a presence wait still fails, just later, and an +/// absence window only gets LONGER (a stronger check). It does not reach Ask timeouts or +/// plain Task.WaitAsync budgets — those are sized from PresenceBudget instead. +/// +/// +internal static class TestTimeFactor +{ + /// The environment variable the CI workflow sets. + public const string EnvironmentVariable = "AKKA_TEST_TIMEFACTOR"; + + /// The factor in effect: the variable's value when it parses to a number ≥ 1, else 1. + public static double Value { get; } = + double.TryParse(Environment.GetEnvironmentVariable(EnvironmentVariable), NumberStyles.Float, + CultureInfo.InvariantCulture, out var f) && f >= 1 ? f : 1; + + /// A HOCON line setting akka.test.timefactor, to append to a test config. + public static string Hocon => + "\nakka.test.timefactor = " + Value.ToString(CultureInfo.InvariantCulture) + "\n"; +} diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Health/HealthProbeActorTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Health/HealthProbeActorTests.cs index f07caa95..cf5863cd 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Health/HealthProbeActorTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Health/HealthProbeActorTests.cs @@ -23,7 +23,7 @@ public sealed class HealthProbeActorTests : RuntimeActorTestBase var actor = Sys.ActorOf(DbHealthProbeActor.Props(db)); var status = await actor.Ask( - DbHealthProbeActor.GetStatus.Instance, TimeSpan.FromSeconds(3)); + DbHealthProbeActor.GetStatus.Instance, PresenceBudget); status.Reachable.ShouldBeTrue(); status.LastError.ShouldBeNull(); diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Historian/ContinuousHistorizationRecorderTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Historian/ContinuousHistorizationRecorderTests.cs index 2a8c7bde..1d817c46 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Historian/ContinuousHistorizationRecorderTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Historian/ContinuousHistorizationRecorderTests.cs @@ -4,6 +4,7 @@ using Akka.TestKit.Xunit2; using Xunit; using ZB.MOM.WW.OtOpcUa.Core.Abstractions; using ZB.MOM.WW.OtOpcUa.Runtime.Historian; +using ZB.MOM.WW.OtOpcUa.Runtime.Tests.Harness; using ZB.MOM.WW.OtOpcUa.Runtime.VirtualTags; namespace ZB.MOM.WW.OtOpcUa.Runtime.Tests.Historian; @@ -591,7 +592,9 @@ public sealed class ContinuousHistorizationRecorderTests : TestKit rec.Tell(new VirtualTagActor.DependencyValueChanged("Good.Tag", 1.0, DateTime.UtcNow)); rec.Tell(new VirtualTagActor.DependencyValueChanged("Bad.Tag", 2.0, DateTime.UtcNow)); - await writer.Entered.WaitAsync(TimeSpan.FromSeconds(10)); + // Presence waits, budgeted from the shared RuntimeActorTestBase constant rather than 10 s: this + // one timed out on a loaded Gitea runner (#606). They return the instant the writer signals. + await writer.Entered.WaitAsync(RuntimeActorTestBase.PresenceBudget); // Preconditions, so a green result can never be vacuous: both entries are still queued (they were // peeked as ONE batch — a lone healthy entry would have been acked and gone), and the healthy tag @@ -601,7 +604,7 @@ public sealed class ContinuousHistorizationRecorderTests : TestKit Sys.Stop(rec); // PostStop cancels the drain token underneath the in-flight write - await writer.Cancelled.WaitAsync(TimeSpan.FromSeconds(10)); + await writer.Cancelled.WaitAsync(RuntimeActorTestBase.PresenceBudget); // Bounded negative watch — red is immediate when the fold truncates; green costs the window once. // This guards a NEGATIVE ("the pass unwound without acking"), so instead of sleeping and hoping the diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Telemetry/PublishSeamEmitsToHubTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Telemetry/PublishSeamEmitsToHubTests.cs index 4cfaf6c7..f252dd7c 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Telemetry/PublishSeamEmitsToHubTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Telemetry/PublishSeamEmitsToHubTests.cs @@ -121,10 +121,10 @@ public sealed class PublishSeamEmitsToHubTests : RuntimeActorTestBase Kind: AlarmTransitionKind.Raise))); // The OPC UA condition update confirms the transition was processed (ordered before the alerts fan-out). - publish.ExpectMsg(TimeSpan.FromSeconds(5)); + publish.ExpectMsg(PresenceBudget); // Exactly one Alarm item, carrying the same transition the alerts topic received. - AwaitAssert(() => hub.Items.Count.ShouldBe(1), TimeSpan.FromSeconds(5), TimeSpan.FromMilliseconds(100)); + AwaitAssert(() => hub.Items.Count.ShouldBe(1), PresenceBudget, TimeSpan.FromMilliseconds(100)); var item = hub.Items[0].ShouldBeOfType(); item.E.AlarmId.ShouldBe(AlarmRawPath); item.E.AlarmName.ShouldBe("temp_hi"); @@ -150,15 +150,15 @@ public sealed class PublishSeamEmitsToHubTests : RuntimeActorTestBase // One enabled alarm firing when M.T > 90; wait for load to complete (RegisterInterest lands). host.Tell(new ScriptedAlarmHostActor.ApplyScriptedAlarms(new[] { ScriptedPlan() })); - mux.ExpectMsg(TimeSpan.FromSeconds(8)); + mux.ExpectMsg(PresenceBudget); host.Tell(new VirtualTagActor.DependencyValueChanged("M.T", 99, DateTime.UtcNow)); // The OPC UA condition update confirms the transition was processed. - publish.FishForMessage(m => m.State.Active, TimeSpan.FromSeconds(8)); + publish.FishForMessage(m => m.State.Active, PresenceBudget); // Exactly one Alarm item, carrying the Activated transition the alerts topic received. - AwaitAssert(() => hub.Items.Count.ShouldBe(1), TimeSpan.FromSeconds(5), TimeSpan.FromMilliseconds(100)); + AwaitAssert(() => hub.Items.Count.ShouldBe(1), PresenceBudget, TimeSpan.FromMilliseconds(100)); var item = hub.Items[0].ShouldBeOfType(); item.E.AlarmId.ShouldBe("alm-1"); item.E.TransitionKind.ShouldBe("Activated"); @@ -246,8 +246,8 @@ public sealed class PublishSeamEmitsToHubTests : RuntimeActorTestBase telemetryHub: hub)); actor.Tell(new DispatchDeployment(deploymentId, RevA, CorrelationId.NewId())); - coordinator.ExpectMsg(TimeSpan.FromSeconds(5)).Outcome.ShouldBe(ApplyAckOutcome.Applied); - publish.ExpectMsg(TimeSpan.FromSeconds(5)); + coordinator.ExpectMsg(PresenceBudget).Outcome.ShouldBe(ApplyAckOutcome.Applied); + publish.ExpectMsg(PresenceBudget); return (actor, publish); } diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/VirtualTags/DependencyMuxActorTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/VirtualTags/DependencyMuxActorTests.cs index 5157f585..76ad462f 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/VirtualTags/DependencyMuxActorTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/VirtualTags/DependencyMuxActorTests.cs @@ -114,11 +114,11 @@ public sealed class DependencyMuxActorTests : RuntimeActorTestBase "driver-1", "ref-a", 10, OpcUaStatus.Good, DateTime.UtcNow)); parent.ExpectMsg(TimeSpan.FromMilliseconds(200)) .Value.ShouldBe(10); - }, duration: TimeSpan.FromSeconds(3)); + }, duration: PresenceBudget); // From here the actor is wired — second publish drives the sum. mux.Tell(new DriverInstanceActor.AttributeValuePublished("driver-1", "ref-b", 32, OpcUaStatus.Good, DateTime.UtcNow)); - parent.ExpectMsg(TimeSpan.FromSeconds(2)).Value.ShouldBe(42); + parent.ExpectMsg(PresenceBudget).Value.ShouldBe(42); // Unrelated ref shouldn't fire eval. mux.Tell(new DriverInstanceActor.AttributeValuePublished("driver-1", "ref-unrelated", 99, OpcUaStatus.Good, DateTime.UtcNow)); From beccfc640402dd83495b6da36a925e5d81378dff Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Thu, 8 Oct 2026 20:37:15 -0400 Subject: [PATCH 2/2] test(#606): native-ack routing waits for the driver child to be Connected; widen a starved poll MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit DriverHostActorNativeAlarmAckRoutingTests: Applied does not mean the child DriverInstanceActor is Connected, and an ack reaching a still-Connecting child is dropped by design — the single positive-control ack was itself dropped (4/20 under DOTNET_PROCESSOR_COUNT=1 x8, still failing with the presence budget dilated to 45 s, so not a budget problem). SpawnHostAndApply now waits for SubscribeAlarmsAsync, which only the Connected state calls. ScriptedAlarmEngine OnEvent_emission_happens_outside_evalGate: 2 s blocking poll -> 15 s (5/20 under starvation). Claude-Session: https://claude.ai/code/session_01Ef2ozxS7QPanGT8uoATbTe --- .../ScriptedAlarmEngineTests.cs | 7 ++++-- ...iverHostActorNativeAlarmAckRoutingTests.cs | 24 +++++++++++++++++-- 2 files changed, 27 insertions(+), 4 deletions(-) diff --git a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmEngineTests.cs b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmEngineTests.cs index 1817003d..af5fae06 100644 --- a/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmEngineTests.cs +++ b/tests/Core/ZB.MOM.WW.OtOpcUa.Core.ScriptedAlarms.Tests/ScriptedAlarmEngineTests.cs @@ -769,8 +769,11 @@ public sealed class ScriptedAlarmEngineTests // Drive to Active so Acknowledge has something to ack. up.Push("Temp", 150); // Use the same WaitForAsync that other tests use — synchronously - // here since this is a non-async test. - for (var i = 0; i < 80 && eng.GetState("HighTemp")!.Active != AlarmActiveState.Active; i++) + // here since this is a non-async test. A 15 s presence ceiling, not 2 s: this thread blocks a + // pool thread while the drain that activates the alarm needs another, and under thread-pool + // starvation (DOTNET_PROCESSOR_COUNT=1, 8 parallel copies) 2 s failed 5 runs in 20 (#606). + var activeBy = DateTime.UtcNow.AddSeconds(15); + while (DateTime.UtcNow < activeBy && eng.GetState("HighTemp")!.Active != AlarmActiveState.Active) Thread.Sleep(25); eng.GetState("HighTemp")!.Active.ShouldBe(AlarmActiveState.Active); diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorNativeAlarmAckRoutingTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorNativeAlarmAckRoutingTests.cs index c74619fa..08d2f449 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorNativeAlarmAckRoutingTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverHostActorNativeAlarmAckRoutingTests.cs @@ -157,6 +157,15 @@ public sealed class DriverHostActorNativeAlarmAckRoutingTests : RuntimeActorTest actor.Tell(new DispatchDeployment(deploymentId, RevA, CorrelationId.NewId())); coordinator.ExpectMsg(Timeout).Outcome.ShouldBe(ApplyAckOutcome.Applied); + // Applied does NOT mean the driver child is Connected: the apply acks once the child is spawned, + // and a RouteAlarmAck reaching a still-Connecting child is dropped by design (fire-and-forget, no + // upstream to reach). Each test sends its positive-control ack exactly once, so on a loaded runner + // the control itself was dropped and the wait read [] — 4 of 20 runs under thread-pool starvation, + // and on Gitea (#606). SubscribeAlarmsAsync is only ever called from the Connected state (a + // pre-connect request is swallowed and re-issued on the Connected entry), so wait for it. + if (factory is RecordingAlarmDriverFactory recording) + AwaitCondition(() => recording.AlarmsSubscribed, Timeout); + return actor; } @@ -234,6 +243,9 @@ public sealed class DriverHostActorNativeAlarmAckRoutingTests : RuntimeActorTest /// off the actor thread). public IReadOnlyList Acks => _driver.Acks; + /// True once the driver child has reached Connected and opened its alarm subscription. + public bool AlarmsSubscribed => _driver.AlarmsSubscribed; + /// public IDriver? TryCreate(string driverType, string driverInstanceId, string driverConfigJson) { @@ -269,8 +281,16 @@ public sealed class DriverHostActorNativeAlarmAckRoutingTests : RuntimeActorTest /// public Task SubscribeAlarmsAsync( - IReadOnlyList sourceNodeIds, CancellationToken cancellationToken) => - Task.FromResult(new StubAlarmHandle()); + IReadOnlyList sourceNodeIds, CancellationToken cancellationToken) + { + Volatile.Write(ref _alarmsSubscribed, true); + return Task.FromResult(new StubAlarmHandle()); + } + + private bool _alarmsSubscribed; + + /// True once has been called (only ever from Connected). + public bool AlarmsSubscribed => Volatile.Read(ref _alarmsSubscribed); /// public Task UnsubscribeAlarmsAsync(IAlarmSubscriptionHandle handle, CancellationToken cancellationToken) =>