From a801e2aefbb69e34cb7c819f329e8890a1d9918f Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Thu, 20 Aug 2026 09:32:24 -0400 Subject: [PATCH] =?UTF-8?q?fix(runtime):=20comms-loss=20grace=20is=20per?= =?UTF-8?q?=20connection=20=E2=80=94=20max(LastSuccessfulRead,=20connected?= =?UTF-8?q?Since)=20(archreview=2003/S17)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- ...R3-03-restart-resubscribe-watchdog-plan.md | 35 ++++++++ ...rt-resubscribe-watchdog-plan.md.tasks.json | 2 +- .../Drivers/DriverInstanceActor.cs | 24 +++++- ...iverInstanceActorCommsLossWatchdogTests.cs | 83 +++++++++++++++++++ 4 files changed, 141 insertions(+), 3 deletions(-) diff --git a/archreview/plans/R3-03-restart-resubscribe-watchdog-plan.md b/archreview/plans/R3-03-restart-resubscribe-watchdog-plan.md index e872aefd..4a9966cb 100644 --- a/archreview/plans/R3-03-restart-resubscribe-watchdog-plan.md +++ b/archreview/plans/R3-03-restart-resubscribe-watchdog-plan.md @@ -452,3 +452,38 @@ T8 anytime; T9 last (after T3/T5/T6/T7 merge-ready) ``` Overall effort: **~0.75–1 dev-day code+unit, plus the rig session.** The one HIGH-RISK production slice (T3, which changes what every child receives at spawn) lands behind the full 25-suite `DriverHostActor` regression before any new test stacks on it, and behind T2's explicitly behaviour-preserving refactor. + +--- + +## Execution notes + +Branch `fix/r3-03-restart-resubscribe-watchdog`, worktree +`.claude/worktrees/agent-a5bcdd61bfba22e10`, off master `5fd65d19`. TDD throughout: every +behaviour task's test was written first, RUN, and observed red for the predicted reason before the +production edit landed. Red observations are recorded per task below. + +### T1 — 03/S17 watchdog grace (`??` → max) + +**RED observed (as predicted).** With the two new tests in place against unmodified +`DriverInstanceActor`: + +``` +DriverInstanceActorCommsLossWatchdogTests.A_reconnected_driver_gets_a_full_grace_window_before_the_watchdog_trips_again [FAIL] + Failed: Expected no messages during 00:00:00.4000000, instead we received + after 00:00:00.0496590 +Failed! - Failed: 1, Passed: 9, Total: 10 +``` + +The re-trip landed **49.7 ms** after the reconnect — one health tick (`FastPoll` = 50 ms) — against a +`Grace` of 1500 ms, i.e. exactly the "churn at health-tick cadence instead of the designed grace" +the finding describes. `A_half_broken_device_is_still_declared_lost_once_the_grace_elapses` passed +in the same run, which is what makes it the anti-vacuity control: it cannot distinguish the fix from +the bug, so the delay assertion is the one carrying the finding. + +**GREEN after the one-line max at `:574`** (plus the "grace is per connection" remarks paragraph and +the reciprocal falsification-partner xmldoc on the existing +`A_degraded_driver_that_is_still_reading_successfully_is_left_alone`): 10/10 passed, 20 s. +`A_reconnect_attempt_tears_the_dead_transport_down_before_re_initialising` stayed green — as the plan +anticipated, each of its trip cycles now costs a full `FastTimeout` (250 ms) instead of one 50 ms +tick, and its `AwaitCondition(InitializeCount >= 2, 5 s)` still has ample headroom. No budget change +was needed. diff --git a/archreview/plans/R3-03-restart-resubscribe-watchdog-plan.md.tasks.json b/archreview/plans/R3-03-restart-resubscribe-watchdog-plan.md.tasks.json index b14841de..2464790a 100644 --- a/archreview/plans/R3-03-restart-resubscribe-watchdog-plan.md.tasks.json +++ b/archreview/plans/R3-03-restart-resubscribe-watchdog-plan.md.tasks.json @@ -5,7 +5,7 @@ { "id": "T1", "subject": "Comms-loss grace is per connection: ?? -> max(LastSuccessfulRead, _connectedSinceUtc) + falsification pair (03/S17)", - "status": "pending", + "status": "done", "blockedBy": [] }, { diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/Drivers/DriverInstanceActor.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/Drivers/DriverInstanceActor.cs index 7c8f5b3d..81852667 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/Drivers/DriverInstanceActor.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/Drivers/DriverInstanceActor.cs @@ -561,6 +561,19 @@ public sealed class DriverInstanceActor : ReceiveActor, IWithTimers /// state on sustained failure: the nine poll drivers via Degraded, MQTT via its live connection /// state, Galaxy via its reconnect supervisor. /// + /// + /// The grace is per CONNECTION (03/S17). The silence baseline is + /// max(LastSuccessfulRead, _connectedSinceUtc), not LastSuccessfulRead ?? _connectedSinceUtc. + /// Because LastSuccessfulRead is preserved across Degraded/Faulted writes (see above), + /// a device that accepts a connection but serves no data reconnects carrying a stamp that is already + /// older than the threshold, so a ?? baseline re-trips on the FIRST health tick of every new + /// connection — a reconnect cycle at health-tick cadence rather than the designed threshold. Taking + /// the later of the two gives each connection its own full window, which is exactly what re-stamping + /// _connectedSinceUtc on every Connected entry was for. Note this paces the cycle, it + /// does not end it: a permanently half-broken device still reconnects once per threshold, and a + /// driver that stops reading within a stable connection still trips on schedule (its read + /// stamp is the later term, exactly as before). + /// /// /// The health observed on this tick, or null when /// threw — a failed observation is not evidence of comms loss, so it never advances the watchdog. @@ -570,8 +583,15 @@ public sealed class DriverInstanceActor : ReceiveActor, IWithTimers if (health is not { } observed) return; if (observed.State == DriverState.Healthy) return; - // A driver that has never reported a successful read is measured from the current Connected entry. - var lastEvidence = observed.LastSuccessfulRead ?? _connectedSinceUtc; + // Measure silence from the LATER of the last successful read and THIS connect — the grace is per + // connection. `??` was wrong: drivers PRESERVE LastSuccessfulRead across Degraded/Faulted writes (that + // preservation is the #527 design), so after a trip + reconnect to a device that accepts the connection + // but still serves no data, the stamp is already older than the threshold and the FIRST tick of the new + // connection re-trips — churn at health-tick cadence instead of the designed grace. `??` only ever helped + // a driver that had never read at all. + var lastEvidence = observed.LastSuccessfulRead is { } read && read > _connectedSinceUtc + ? read + : _connectedSinceUtc; var silence = DateTime.UtcNow - lastEvidence; if (silence < _commsLossTimeout) return; diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverInstanceActorCommsLossWatchdogTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverInstanceActorCommsLossWatchdogTests.cs index f12f3b54..8010dd02 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverInstanceActorCommsLossWatchdogTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/Drivers/DriverInstanceActorCommsLossWatchdogTests.cs @@ -40,6 +40,10 @@ public sealed class DriverInstanceActorCommsLossWatchdogTests : RuntimeActorTest private static readonly TimeSpan FastPoll = TimeSpan.FromMilliseconds(50); private static readonly TimeSpan FastTimeout = TimeSpan.FromMilliseconds(250); + /// The threshold used by the per-connection grace pair (03/S17). Deliberately an order of + /// magnitude above so the absence window below is a decision, not a race. + private static readonly TimeSpan Grace = TimeSpan.FromMilliseconds(1500); + /// Drives the actor to Connected and returns once the connect has been announced. private (IActorRef Actor, Akka.TestKit.TestProbe Parent) ConnectDriver( HealthControlledStubDriver driver, @@ -87,6 +91,14 @@ public sealed class DriverInstanceActorCommsLossWatchdogTests : RuntimeActorTest /// ModbusDriver.ReadAsync leaves latched whenever the bad tag is read last — but it is still /// reading successfully, so LastSuccessfulRead keeps advancing. It must be left alone. /// A state-only watchdog would tear this driver down on every threshold, forever. + /// + /// Falsification partner (03/S17): + /// . + /// The silence baseline is max(LastSuccessfulRead, _connectedSinceUtc), and each test kills + /// one term of that max — this one goes red if the LastSuccessfulRead term is dropped (its + /// connect ages far past the threshold while its reads keep succeeding), that one goes red if the + /// _connectedSinceUtc term is dropped (i.e. if the original ?? is restored). + /// /// [Fact] public void A_degraded_driver_that_is_still_reading_successfully_is_left_alone() @@ -258,6 +270,77 @@ public sealed class DriverInstanceActorCommsLossWatchdogTests : RuntimeActorTest parent.ExpectNoMsg(TimeSpan.FromMilliseconds(200)); } + + /// + /// 03/S17 — the grace is per connection. Drivers deliberately preserve + /// across Degraded/Faulted health writes (that + /// preservation is the #527 design), so for a device that accepts a TCP connection but never serves + /// data the stamp stays frozen from before the outage — already older than the threshold. Measuring + /// silence from that stamp alone (??) makes the first health tick of every new + /// connection re-trip, so the reconnect cycle runs at health-tick cadence (~30 s in production) + /// instead of the designed grace. Measuring from max(LastSuccessfulRead, _connectedSinceUtc) + /// gives each connection its own full window, which is exactly what the _connectedSinceUtc + /// re-stamp on every Connected entry already promises in its comment. + /// + /// Falsification partner: + /// — see its + /// remarks for how the pair covers both terms of the max. + /// + /// + /// The absence window carries the house positive control: a proven number of health-poll ticks + /// processed after the reconnect, so "the watchdog did not re-trip" cannot pass because + /// the actor stopped ticking. It is also deliberately far shorter than , so + /// it asserts a delay, not a disablement — + /// is the anti-vacuity half. + /// + /// + [Fact] + public void A_reconnected_driver_gets_a_full_grace_window_before_the_watchdog_trips_again() + { + var driver = new HealthControlledStubDriver + { + // The half-broken device: the socket connects, every read fails, and the last successful read is + // frozen well before the outage — preserved across the Degraded writes, as every driver does. + Health = new DriverHealth(DriverState.Degraded, DateTime.UtcNow.AddMinutes(-5), "reads time out"), + }; + var (_, parent) = ConnectDriver(driver, commsLossTimeout: Grace, reconnectInterval: TimeSpan.FromMilliseconds(100)); + + // The first trip is correct and expected — the device really has been silent for five minutes. + parent.ExpectMsg(PresenceBudget) + .Connected.ShouldBeFalse(); + // The retry re-initialises successfully (the socket still accepts), so a NEW connection starts here. + parent.ExpectMsg(PresenceBudget) + .Connected.ShouldBeTrue(); + + var ticksAtReconnect = driver.HealthReadCount; + parent.ExpectNoMsg(TimeSpan.FromMilliseconds(400)); + (driver.HealthReadCount - ticksAtReconnect).ShouldBeGreaterThanOrEqualTo( + 4, + "health-poll ticks did not run after the reconnect — the absence assertion above would be vacuous"); + } + + /// + /// The anti-vacuity half of the 03/S17 pair: the per-connection grace delays the watchdog, it + /// does not disable it. The same half-broken device is still declared lost once the grace elapses — + /// without this, a "fix" that simply stopped evaluating the watchdog after the first connection would + /// pass + /// and look correct. + /// + [Fact] + public void A_half_broken_device_is_still_declared_lost_once_the_grace_elapses() + { + var driver = new HealthControlledStubDriver + { + Health = new DriverHealth(DriverState.Degraded, DateTime.UtcNow.AddMinutes(-5), "reads time out"), + }; + var (_, parent) = ConnectDriver(driver, commsLossTimeout: Grace, reconnectInterval: TimeSpan.FromMilliseconds(100)); + + parent.ExpectMsg(PresenceBudget).Connected.ShouldBeFalse(); + parent.ExpectMsg(PresenceBudget).Connected.ShouldBeTrue(); + + // The second connection serves no data either, so once ITS grace elapses the watchdog trips again. + parent.ExpectMsg(PresenceBudget).Connected.ShouldBeFalse(); + } } ///