Joseph Doherty
beb1c583b1
Live gate A1 (docker-dev, opc-plc restart / SIGINT / kill): the fast path never fired — a real process stop delivers no session status; the keep-alives report BadSecureChannelClosed (0x80860000) once, then BadConnectionClosed (0x80AE0000) interleaved with BadNoCommunication for the whole outage. Reproduced in-process with TcpStallProxy.HardClose (reset every connection, refuse new ones; server and session alive behind it): the identical sequence, and the SDK 1.5.378 session never opens a new connection on its own (48 s with the proxy accepting again, zero attempts) — a closed channel cannot recover in place. The driver now treats BadSecureChannelClosed/BadConnectionClosed as definitive on the SECOND closed-channel keep-alive failure in one outage (a good keep-alive resets the count), raising ConnectionLost ~1 keep-alive after the drop. BadNoCommunication / BadRequestTimeout / BadNotConnected (stall/pause) stay with the watchdog; the stall test still sees no ConnectionLost. New wire test (hard close + reopen ⇒ raised once, SDK never reconnects, reinit brings the identical value back Good) and unit tests (sustained raises once; a single blip that recovers does not) — all red on the previous code. Docs updated.
709 lines
34 KiB
C#
709 lines
34 KiB
C#
using System.Text.Json;
|
|
using Microsoft.Extensions.Logging;
|
|
using Moq;
|
|
using Opc.Ua;
|
|
using Opc.Ua.Client;
|
|
using Shouldly;
|
|
using Xunit;
|
|
using ZB.MOM.WW.OtOpcUa.Core.Abstractions;
|
|
|
|
namespace ZB.MOM.WW.OtOpcUa.Driver.OpcUaClient.Tests;
|
|
|
|
/// <summary>
|
|
/// Gitea #676 — the driver half of the fast recovery path (<see cref="IDriverConnectionLossSource"/>), the
|
|
/// per-recovery replay-drop summary, and the trailing reconcile read after an in-place recovery.
|
|
/// </summary>
|
|
[Trait("Category", "Unit")]
|
|
public sealed class OpcUaClientConnectionLossSignalTests
|
|
{
|
|
private const uint BadNoCommunication = 0x80310000u;
|
|
private const string SpeedRef = "Plant/dev/Speed";
|
|
private const string CounterRef = "Plant/dev/Counter";
|
|
|
|
private sealed class ManualClock(DateTimeOffset start) : TimeProvider
|
|
{
|
|
public DateTimeOffset Now { get; set; } = start;
|
|
public override DateTimeOffset GetUtcNow() => Now;
|
|
public void Advance(TimeSpan by) => Now += by;
|
|
}
|
|
|
|
private sealed class ListLogger : ILogger<OpcUaClientDriver>
|
|
{
|
|
public List<(LogLevel Level, string Message)> Entries { get; } = [];
|
|
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
|
|
public bool IsEnabled(LogLevel logLevel) => true;
|
|
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception,
|
|
Func<TState, Exception?, string> formatter)
|
|
{
|
|
lock (Entries) Entries.Add((logLevel, formatter(state, exception)));
|
|
}
|
|
|
|
public string[] Info(string contains) => At(LogLevel.Information, contains);
|
|
|
|
public string[] At(LogLevel level, string contains)
|
|
{
|
|
lock (Entries)
|
|
return [.. Entries.Where(e => e.Level == level && e.Message.Contains(contains)).Select(e => e.Message)];
|
|
}
|
|
}
|
|
|
|
private static RawTagEntry Tag(string rawPath, string nodeId) =>
|
|
new(rawPath, JsonSerializer.Serialize(new { nodeId }), WriteIdempotent: true);
|
|
|
|
private static readonly IReadOnlyList<RawTagEntry> Tags =
|
|
[
|
|
Tag(SpeedRef, "ns=0;s=Speed"),
|
|
Tag(CounterRef, "ns=0;s=Counter"),
|
|
];
|
|
|
|
private static Mock<ISession> NewSession()
|
|
{
|
|
var mock = new Mock<ISession>(MockBehavior.Loose);
|
|
mock.SetupGet(s => s.MessageContext).Returns(new ServiceMessageContext(SdkTelemetry.Context));
|
|
mock.SetupGet(s => s.NamespaceUris).Returns(new NamespaceTable());
|
|
return mock;
|
|
}
|
|
|
|
private static (OpcUaClientDriver Driver, Mock<ISession> Session, ManualClock Clock, ListLogger Log) NewConnectedDriver()
|
|
{
|
|
var log = new ListLogger();
|
|
var drv = new OpcUaClientDriver(new OpcUaClientDriverOptions { RawTags = Tags }, "opcua-676", log);
|
|
var session = NewSession();
|
|
var clock = new ManualClock(new DateTimeOffset(2026, 10, 11, 12, 0, 0, TimeSpan.Zero));
|
|
drv.Clock = clock;
|
|
drv.SetSessionForTest(session.Object);
|
|
drv.SetNamespaceMapForTest(NamespaceMap.FromTable(new NamespaceTable(), Tags));
|
|
drv.SetHealthForTest(new DriverHealth(DriverState.Healthy, clock.Now.UtcDateTime, null));
|
|
return (drv, session, clock, log);
|
|
}
|
|
|
|
private static DataValue Good(object value, DateTime ts) => new(new Variant(value), StatusCodes.Good, ts, ts);
|
|
|
|
/// <summary>Every read returns <paramref name="values"/> (one per requested node, in order) at <paramref name="at"/>.</summary>
|
|
private static void SetupRead(Mock<ISession> session, Func<DateTime> at, params object[] values) =>
|
|
session.Setup(s => s.ReadAsync(
|
|
It.IsAny<RequestHeader>(), It.IsAny<double>(), It.IsAny<TimestampsToReturn>(),
|
|
It.IsAny<ReadValueIdCollection>(), It.IsAny<CancellationToken>()))
|
|
.ReturnsAsync((RequestHeader _, double _, TimestampsToReturn _, ReadValueIdCollection nodes, CancellationToken _) =>
|
|
new ReadResponse
|
|
{
|
|
ResponseHeader = new ResponseHeader(),
|
|
Results = [.. nodes.Select((_, i) => Good(values[i], at()))],
|
|
DiagnosticInfos = [],
|
|
});
|
|
|
|
// ── IDriverConnectionLossSource ──────────────────────────────────────────────────────────────────────────────
|
|
|
|
public static TheoryData<uint> DefinitiveStatuses =>
|
|
[
|
|
StatusCodes.BadSessionIdInvalid,
|
|
StatusCodes.BadSessionClosed,
|
|
StatusCodes.BadSessionNotActivated,
|
|
StatusCodes.BadServerHalted,
|
|
];
|
|
|
|
public static TheoryData<uint> AmbiguousStatuses =>
|
|
[
|
|
StatusCodes.BadNoCommunication,
|
|
StatusCodes.BadNotConnected,
|
|
StatusCodes.BadRequestTimeout,
|
|
StatusCodes.BadTimeout,
|
|
];
|
|
|
|
[Theory]
|
|
[MemberData(nameof(DefinitiveStatuses))]
|
|
public void A_definitive_keep_alive_raises_ConnectionLost_once_after_publishing_the_outage(uint status)
|
|
{
|
|
var (drv, _, _, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
drv.AddSubscriptionForTest([SpeedRef]);
|
|
var order = new List<string>();
|
|
drv.OnDataChange += (_, e) => order.Add($"bad:{e.Snapshot.StatusCode:X8}");
|
|
var raised = new List<DriverConnectionLossEventArgs>();
|
|
drv.ConnectionLost += (_, e) => { raised.Add(e); order.Add("lost"); };
|
|
|
|
drv.RaiseKeepAliveForTest(status);
|
|
drv.RaiseKeepAliveForTest(status);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadSessionIdInvalid);
|
|
|
|
raised.ShouldHaveSingleItem("once per session, however many definitive keep-alives follow")
|
|
.Reason.ShouldContain(StatusCodes.GetBrowseName(status));
|
|
order.ShouldBe([$"bad:{BadNoCommunication:X8}", "lost"], "subscribers see the Bad before the host tears down");
|
|
}
|
|
|
|
[Theory]
|
|
[MemberData(nameof(AmbiguousStatuses))]
|
|
public void An_ambiguous_keep_alive_does_not_raise_ConnectionLost(uint status)
|
|
{
|
|
var (drv, _, _, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
drv.AddSubscriptionForTest([SpeedRef]);
|
|
var raised = 0;
|
|
drv.ConnectionLost += (_, _) => raised++;
|
|
var seen = new List<DataChangeEventArgs>();
|
|
drv.OnDataChange += (_, e) => seen.Add(e);
|
|
|
|
for (var i = 0; i < 5; i++) drv.RaiseKeepAliveForTest(status);
|
|
|
|
// Positive control: the keep-alives WERE processed as an outage — the outage just is not definitive.
|
|
seen.ShouldHaveSingleItem().Snapshot.StatusCode.ShouldBe(BadNoCommunication);
|
|
drv.GetHealth().State.ShouldBe(DriverState.Degraded);
|
|
raised.ShouldBe(0, "an ambiguous loss may yet resume in place — it belongs to the #527 watchdog");
|
|
}
|
|
|
|
/// <summary>
|
|
/// #676 live gate A1: a real upstream process stop (docker restart / SIGINT / docker kill) never produced a
|
|
/// session status — the keep-alives carried <c>BadSecureChannelClosed</c> once, then <c>BadConnectionClosed</c>
|
|
/// (interleaved with <c>BadNoCommunication</c>) for the whole outage. Measured in-process (hard-closing proxy, the
|
|
/// server and its session still alive): the SDK 1.5.378 session NEVER opens a new connection on its own, so a
|
|
/// closed channel is dead for good. Sustained — a second closed-channel failure in the same outage — it raises.
|
|
/// </summary>
|
|
[Fact]
|
|
public void A_sustained_closed_channel_raises_ConnectionLost_once()
|
|
{
|
|
var (drv, _, _, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
var raised = new List<string>();
|
|
drv.ConnectionLost += (_, e) => raised.Add(e.Reason);
|
|
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadSecureChannelClosed); // the live sequence …
|
|
raised.ShouldBeEmpty("one closed-channel failure may be a transient");
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadNoCommunication);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadConnectionClosed); // … sustained
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadNoCommunication);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadConnectionClosed);
|
|
|
|
raised.ShouldHaveSingleItem().ShouldContain("BadConnectionClosed");
|
|
}
|
|
|
|
[Theory]
|
|
[InlineData(0x80860000u)] // BadSecureChannelClosed
|
|
[InlineData(0x80AE0000u)] // BadConnectionClosed
|
|
public void A_single_closed_channel_blip_that_recovers_does_not_raise(uint closed)
|
|
{
|
|
var (drv, _, _, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
var raised = 0;
|
|
drv.ConnectionLost += (_, _) => raised++;
|
|
|
|
drv.RaiseKeepAliveForTest(closed);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadNoCommunication);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.Good); // recovered — the count starts again
|
|
drv.RaiseKeepAliveForTest(closed);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.Good);
|
|
|
|
raised.ShouldBe(0);
|
|
// Positive control: the same driver DOES raise once a closed channel is sustained.
|
|
drv.RaiseKeepAliveForTest(closed);
|
|
drv.RaiseKeepAliveForTest(closed);
|
|
raised.ShouldBe(1);
|
|
}
|
|
|
|
[Fact]
|
|
public void An_ambiguous_outage_that_turns_definitive_raises_once()
|
|
{
|
|
var (drv, _, _, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
var raised = 0;
|
|
drv.ConnectionLost += (_, _) => raised++;
|
|
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadNoCommunication);
|
|
raised.ShouldBe(0);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadServerHalted);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadNoCommunication);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadServerHalted);
|
|
|
|
raised.ShouldBe(1);
|
|
}
|
|
|
|
[Fact]
|
|
public async Task The_signal_is_re_armed_by_a_re_initialise()
|
|
{
|
|
var (drv, _, _, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
var raised = 0;
|
|
drv.ConnectionLost += (_, _) => raised++;
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadSessionIdInvalid);
|
|
raised.ShouldBe(1);
|
|
|
|
// The host's response: ShutdownAsync + InitializeAsync, i.e. a NEW session.
|
|
await drv.ShutdownAsync(TestContext.Current.CancellationToken);
|
|
var fresh = NewSession();
|
|
drv.SetSessionForTest(fresh.Object);
|
|
drv.SetNamespaceMapForTest(NamespaceMap.FromTable(new NamespaceTable(), Tags));
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadSessionIdInvalid);
|
|
|
|
raised.ShouldBe(2, "the next session's definitive loss must be reported too");
|
|
}
|
|
|
|
[Fact]
|
|
public void A_definitive_keep_alive_from_a_superseded_session_is_ignored()
|
|
{
|
|
var (drv, _, _, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
var raised = 0;
|
|
drv.ConnectionLost += (_, _) => raised++;
|
|
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadSessionIdInvalid, NewSession().Object);
|
|
|
|
raised.ShouldBe(0);
|
|
drv.GetHealth().State.ShouldBe(DriverState.Healthy);
|
|
}
|
|
|
|
[Fact]
|
|
public void A_subscription_the_server_dropped_raises_ConnectionLost_once()
|
|
{
|
|
var (drv, _, _, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
drv.AddSubscriptionForTest([SpeedRef]);
|
|
var raised = new List<DriverConnectionLossEventArgs>();
|
|
drv.ConnectionLost += (_, e) => raised.Add(e);
|
|
|
|
drv.RaisePublishErrorForTest(StatusCodes.BadSubscriptionIdInvalid, subscriptionId: 4242); // not ours
|
|
raised.ShouldBeEmpty();
|
|
|
|
drv.RaisePublishErrorForTest(StatusCodes.BadNoSubscription);
|
|
drv.RaisePublishErrorForTest(StatusCodes.BadNoSubscription);
|
|
|
|
raised.ShouldHaveSingleItem().Reason.ShouldContain("subscription lost");
|
|
}
|
|
|
|
[Fact]
|
|
public void A_faulting_ConnectionLost_subscriber_does_not_break_the_keep_alive_path()
|
|
{
|
|
var (drv, _, _, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
drv.ConnectionLost += (_, _) => throw new InvalidOperationException("subscriber bug");
|
|
|
|
Should.NotThrow(() => drv.RaiseKeepAliveForTest(StatusCodes.BadSessionClosed));
|
|
drv.GetHealth().State.ShouldBe(DriverState.Degraded);
|
|
}
|
|
|
|
/// <summary>
|
|
/// Review of 3b88056f: only a SERVER-reported subscription loss is definitive. The publishing-stall heuristic
|
|
/// (SDK <c>PublishingStopped</c> persisting past a grace) is an inference from silence — it still degrades health
|
|
/// and freezes the stamp, but recovery stays with the #527 watchdog.
|
|
/// </summary>
|
|
[Fact]
|
|
public void The_publishing_stall_heuristic_does_not_raise_ConnectionLost()
|
|
{
|
|
var (drv, _, clock, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
drv.AddSubscriptionForTest([SpeedRef]);
|
|
drv.IsPublishingStopped = _ => true;
|
|
drv.PublishingStallGrace = _ => TimeSpan.FromSeconds(10);
|
|
var raised = 0;
|
|
drv.ConnectionLost += (_, _) => raised++;
|
|
|
|
drv.RaiseKeepAliveForTest(StatusCodes.Good);
|
|
clock.Advance(TimeSpan.FromSeconds(11));
|
|
drv.RaiseKeepAliveForTest(StatusCodes.Good);
|
|
|
|
// Positive control: the heuristic DID fire.
|
|
drv.GetHealth().LastError.ShouldNotBeNull().ShouldContain("subscription lost");
|
|
raised.ShouldBe(0);
|
|
}
|
|
|
|
// ── Replay-drop summary ──────────────────────────────────────────────────────────────────────────────────────
|
|
|
|
[Fact]
|
|
public async Task The_replay_window_logs_one_Information_summary_of_its_drops_when_it_closes()
|
|
{
|
|
var (drv, session, clock, log) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
drv.PostRecoveryReconcileDelay = () => TimeSpan.FromDays(1); // keep the trailing read out of this test
|
|
var handle = drv.AddSubscriptionForTest([SpeedRef, CounterRef]);
|
|
var t0 = clock.Now.UtcDateTime;
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(1, t0.AddSeconds(5)));
|
|
drv.DeliverNotificationForTest(handle, CounterRef, Good(2, t0.AddSeconds(5)));
|
|
SetupRead(session, () => t0.AddSeconds(5), 1, 2);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadNoCommunication);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.Good);
|
|
await drv.RecoveryTaskForTest;
|
|
|
|
// Three late replays across two refs, one fresh notification that is accepted.
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(0, t0));
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(1, t0.AddSeconds(5)));
|
|
drv.DeliverNotificationForTest(handle, CounterRef, Good(0, t0));
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(3, t0.AddSeconds(6)));
|
|
log.Info("replay window closed").ShouldBeEmpty("the summary is logged once, when the window closes");
|
|
|
|
clock.Advance(TimeSpan.FromSeconds(31));
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(4, t0.AddSeconds(40))); // first notification after expiry
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(5, t0.AddSeconds(41)));
|
|
|
|
log.Info("replay window closed").ShouldHaveSingleItem()
|
|
.ShouldContain("dropped 3 late notifications across 2 refs after recovery");
|
|
}
|
|
|
|
[Fact]
|
|
public async Task A_window_with_no_drops_closes_at_Debug_not_Information()
|
|
{
|
|
var (drv, session, clock, log) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
drv.PostRecoveryReconcileDelay = () => TimeSpan.FromDays(1);
|
|
var handle = drv.AddSubscriptionForTest([SpeedRef]);
|
|
var t0 = clock.Now.UtcDateTime;
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(1, t0));
|
|
SetupRead(session, () => t0, 1);
|
|
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadNoCommunication);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.Good);
|
|
await drv.RecoveryTaskForTest;
|
|
clock.Advance(TimeSpan.FromSeconds(31));
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(2, t0.AddSeconds(40)));
|
|
|
|
log.Info("replay window closed").ShouldBeEmpty("nothing was dropped — not worth an Information line per recovery");
|
|
log.At(LogLevel.Debug, "replay window closed").ShouldHaveSingleItem().ShouldContain("dropped 0");
|
|
}
|
|
|
|
[Fact]
|
|
public async Task A_re_arm_inside_an_open_window_reports_the_earlier_drops_once_and_starts_counting_afresh()
|
|
{
|
|
var (drv, session, clock, log) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
drv.PostRecoveryReconcileDelay = () => TimeSpan.FromDays(1);
|
|
var handle = drv.AddSubscriptionForTest([SpeedRef]);
|
|
var t0 = clock.Now.UtcDateTime;
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(1, t0));
|
|
SetupRead(session, () => t0, 1);
|
|
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadNoCommunication);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.Good);
|
|
await drv.RecoveryTaskForTest;
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(0, t0.AddSeconds(-1))); // one drop in window 1
|
|
|
|
clock.Advance(TimeSpan.FromSeconds(5)); // window 1 still open …
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadNoCommunication); // … a second outage re-arms it
|
|
drv.RaiseKeepAliveForTest(StatusCodes.Good);
|
|
await drv.RecoveryTaskForTest;
|
|
clock.Advance(TimeSpan.FromSeconds(31));
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(3, t0.AddSeconds(80)));
|
|
|
|
log.Info("replay window closed").ShouldBe(
|
|
["OpcUaClientDriver 'opcua-676': post-recovery replay window closed — dropped 1 late notifications across 1 refs after recovery."],
|
|
"window 1's drop is reported once, when the re-arm supersedes it — not carried into window 2's summary");
|
|
log.At(LogLevel.Debug, "replay window closed").ShouldHaveSingleItem().ShouldContain("dropped 0");
|
|
}
|
|
|
|
// ── Trailing reconcile read ──────────────────────────────────────────────────────────────────────────────────
|
|
|
|
[Fact]
|
|
public async Task The_trailing_re_read_publishes_a_change_the_subscription_lost_and_nothing_it_already_has()
|
|
{
|
|
var (drv, session, clock, log) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
drv.PostRecoveryReconcileDelay = () => TimeSpan.Zero;
|
|
var handle = drv.AddSubscriptionForTest([SpeedRef, CounterRef]);
|
|
var t0 = clock.Now.UtcDateTime;
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(10f, t0));
|
|
drv.DeliverNotificationForTest(handle, CounterRef, Good(7, t0));
|
|
|
|
// The recovery read sees both unchanged; by the trailing read Speed has moved on (its notification was lost in
|
|
// the stalled publish pipeline) while Counter has not.
|
|
var reads = 0;
|
|
session.Setup(s => s.ReadAsync(
|
|
It.IsAny<RequestHeader>(), It.IsAny<double>(), It.IsAny<TimestampsToReturn>(),
|
|
It.IsAny<ReadValueIdCollection>(), It.IsAny<CancellationToken>()))
|
|
.ReturnsAsync(() =>
|
|
{
|
|
var trailing = Interlocked.Increment(ref reads) > 1;
|
|
return new ReadResponse
|
|
{
|
|
ResponseHeader = new ResponseHeader(),
|
|
Results = trailing
|
|
? [Good(40f, t0.AddSeconds(9)), Good(7, t0)]
|
|
: [Good(10f, t0), Good(7, t0)],
|
|
DiagnosticInfos = [],
|
|
};
|
|
});
|
|
var seen = new List<DataChangeEventArgs>();
|
|
drv.OnDataChange += (_, e) => { lock (seen) seen.Add(e); };
|
|
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadNoCommunication);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.Good);
|
|
await drv.RecoveryTaskForTest;
|
|
await drv.ReconcileTaskForTest;
|
|
|
|
reads.ShouldBe(2, "the recovery read plus exactly one trailing read");
|
|
DataChangeEventArgs[] afterRecovery;
|
|
lock (seen) afterRecovery = [.. seen.Where(e => e.Snapshot.StatusCode == 0u)];
|
|
// Recovery read republishes both Good (they were published Bad); the trailing read adds ONLY the lost change.
|
|
afterRecovery.Select(e => (e.FullReference, e.Snapshot.Value))
|
|
.ShouldBe([(SpeedRef, (object?)10f), (CounterRef, (object?)7), (SpeedRef, (object?)40f)]);
|
|
log.Info("trailing re-read").ShouldHaveSingleItem().ShouldContain("found 1 of 2 refs");
|
|
}
|
|
|
|
[Fact]
|
|
public async Task The_trailing_re_read_never_publishes_an_older_value_than_a_notification_already_accepted()
|
|
{
|
|
var (drv, session, clock, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
var gate = new TaskCompletionSource();
|
|
drv.PostRecoveryReconcileDelay = () => TimeSpan.Zero;
|
|
var handle = drv.AddSubscriptionForTest([SpeedRef]);
|
|
var t0 = clock.Now.UtcDateTime;
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(10f, t0));
|
|
var reads = 0;
|
|
session.Setup(s => s.ReadAsync(
|
|
It.IsAny<RequestHeader>(), It.IsAny<double>(), It.IsAny<TimestampsToReturn>(),
|
|
It.IsAny<ReadValueIdCollection>(), It.IsAny<CancellationToken>()))
|
|
.Returns(async () =>
|
|
{
|
|
if (Interlocked.Increment(ref reads) > 1) await gate.Task; // hold the trailing read
|
|
return new ReadResponse
|
|
{
|
|
ResponseHeader = new ResponseHeader(),
|
|
Results = [Good(reads > 1 ? 20f : 10f, t0.AddSeconds(reads > 1 ? 5 : 0))],
|
|
DiagnosticInfos = [],
|
|
};
|
|
});
|
|
var seen = new List<(uint Status, object? Value)>();
|
|
drv.OnDataChange += (_, e) => { lock (seen) seen.Add((e.Snapshot.StatusCode, e.Snapshot.Value)); };
|
|
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadNoCommunication);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.Good);
|
|
await drv.RecoveryTaskForTest;
|
|
// While the trailing read is in flight, a NEWER value arrives through the subscription.
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(30f, t0.AddSeconds(8)));
|
|
gate.SetResult();
|
|
await drv.ReconcileTaskForTest;
|
|
|
|
reads.ShouldBe(2, "the trailing read must actually have run, or the absence below proves nothing");
|
|
lock (seen)
|
|
seen.ShouldBe([(BadNoCommunication, (object?)10f), (0u, 10f), (0u, 30f)],
|
|
"the trailing read's 20 @ t0+5 is older than the 30 @ t0+8 already accepted, so it is not published");
|
|
}
|
|
|
|
[Fact]
|
|
public async Task The_trailing_re_read_does_nothing_if_the_session_was_replaced()
|
|
{
|
|
var (drv, session, clock, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
drv.PostRecoveryReconcileDelay = () => TimeSpan.FromMilliseconds(300);
|
|
var handle = drv.AddSubscriptionForTest([SpeedRef]);
|
|
var t0 = clock.Now.UtcDateTime;
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(10f, t0));
|
|
SetupRead(session, () => t0.AddSeconds(5), 99f);
|
|
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadNoCommunication);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.Good);
|
|
await drv.RecoveryTaskForTest;
|
|
// A re-initialise lands between the recovery read and the trailing one.
|
|
drv.SetSessionForTest(NewSession().Object);
|
|
await drv.ReconcileTaskForTest;
|
|
|
|
session.Verify(s => s.ReadAsync(
|
|
It.IsAny<RequestHeader>(), It.IsAny<double>(), It.IsAny<TimestampsToReturn>(),
|
|
It.IsAny<ReadValueIdCollection>(), It.IsAny<CancellationToken>()), Times.Once,
|
|
"only the recovery read — the trailing read must not run against a session that is no longer current");
|
|
}
|
|
|
|
/// <summary>Wires the mock session so the first read (the recovery read) returns <paramref name="recovery"/> and
|
|
/// every later one (the trailing read) returns <paramref name="trailing"/>.</summary>
|
|
private static Func<int> SetupRecoveryThenTrailing(Mock<ISession> session, DataValue recovery, DataValue trailing)
|
|
{
|
|
var reads = 0;
|
|
session.Setup(s => s.ReadAsync(
|
|
It.IsAny<RequestHeader>(), It.IsAny<double>(), It.IsAny<TimestampsToReturn>(),
|
|
It.IsAny<ReadValueIdCollection>(), It.IsAny<CancellationToken>()))
|
|
.ReturnsAsync(() => new ReadResponse
|
|
{
|
|
ResponseHeader = new ResponseHeader(),
|
|
Results = [Interlocked.Increment(ref reads) > 1 ? trailing : recovery],
|
|
DiagnosticInfos = [],
|
|
});
|
|
return () => Volatile.Read(ref reads);
|
|
}
|
|
|
|
private static async Task<List<(uint Status, object? Value)>> RecoverAndReconcileAsync(
|
|
OpcUaClientDriver drv, string fullRef = SpeedRef)
|
|
{
|
|
var seen = new List<(uint Status, object? Value)>();
|
|
drv.OnDataChange += (_, e) => { if (e.FullReference == fullRef) lock (seen) seen.Add((e.Snapshot.StatusCode, e.Snapshot.Value)); };
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadNoCommunication);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.Good);
|
|
await drv.RecoveryTaskForTest;
|
|
await drv.ReconcileTaskForTest;
|
|
return seen;
|
|
}
|
|
|
|
/// <summary>Review of 3b88056f: a Good→Bad change lost in the stalled pipeline left the node stale-GOOD; the
|
|
/// trailing read repairs any (value, status) difference, not just Good ones.</summary>
|
|
[Fact]
|
|
public async Task The_trailing_re_read_repairs_a_lost_change_to_Bad()
|
|
{
|
|
var (drv, session, clock, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
drv.PostRecoveryReconcileDelay = () => TimeSpan.Zero;
|
|
var handle = drv.AddSubscriptionForTest([SpeedRef]);
|
|
var t0 = clock.Now.UtcDateTime;
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(10f, t0));
|
|
var reads = SetupRecoveryThenTrailing(session, Good(10f, t0),
|
|
new DataValue(new Variant(10f), StatusCodes.BadSensorFailure, t0.AddSeconds(9), t0.AddSeconds(9)));
|
|
|
|
var seen = await RecoverAndReconcileAsync(drv);
|
|
|
|
reads().ShouldBe(2);
|
|
seen.ShouldBe([(BadNoCommunication, (object?)10f), (0u, 10f), ((uint)StatusCodes.BadSensorFailure, 10f)]);
|
|
}
|
|
|
|
/// <summary>A server that sends no source timestamp: the re-read is the server's CURRENT state, read after the
|
|
/// stalled pipeline drained, so a differing value is newer than anything delivered before — it is published.</summary>
|
|
[Fact]
|
|
public async Task The_trailing_re_read_repairs_a_server_that_sends_no_source_timestamp()
|
|
{
|
|
var (drv, session, clock, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
drv.PostRecoveryReconcileDelay = () => TimeSpan.Zero;
|
|
var handle = drv.AddSubscriptionForTest([SpeedRef]);
|
|
var t0 = clock.Now.UtcDateTime;
|
|
DataValue NoSource(object v, DateTime server) =>
|
|
new(new Variant(v), StatusCodes.Good, DateTime.MinValue, server);
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, NoSource(10f, t0));
|
|
var reads = SetupRecoveryThenTrailing(session, NoSource(10f, t0.AddSeconds(1)), NoSource(40f, t0.AddSeconds(9)));
|
|
|
|
var seen = await RecoverAndReconcileAsync(drv);
|
|
|
|
reads().ShouldBe(2);
|
|
seen.ShouldBe([(BadNoCommunication, (object?)10f), (0u, 10f), (0u, 40f)]);
|
|
}
|
|
|
|
/// <summary>
|
|
/// Equal source timestamp, different status: the re-read is the server's current state, not a replay, so it is
|
|
/// published — which also repairs the one case the replay guard drops by design (a status-only change that kept
|
|
/// its source timestamp inside the window). An IDENTICAL (value, status) is not republished.
|
|
/// </summary>
|
|
[Fact]
|
|
public async Task The_trailing_re_read_publishes_a_status_only_change_at_an_equal_source_time_but_not_an_identical_value()
|
|
{
|
|
var (drv, session, clock, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
drv.PostRecoveryReconcileDelay = () => TimeSpan.Zero;
|
|
var handle = drv.AddSubscriptionForTest([SpeedRef, CounterRef]);
|
|
var t0 = clock.Now.UtcDateTime;
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(10f, t0));
|
|
drv.DeliverNotificationForTest(handle, CounterRef, Good(7, t0));
|
|
var reads = 0;
|
|
session.Setup(s => s.ReadAsync(
|
|
It.IsAny<RequestHeader>(), It.IsAny<double>(), It.IsAny<TimestampsToReturn>(),
|
|
It.IsAny<ReadValueIdCollection>(), It.IsAny<CancellationToken>()))
|
|
.ReturnsAsync(() => new ReadResponse
|
|
{
|
|
ResponseHeader = new ResponseHeader(),
|
|
Results = Interlocked.Increment(ref reads) > 1
|
|
? [new DataValue(new Variant(10f), StatusCodes.UncertainLastUsableValue, t0, t0), Good(7, t0)]
|
|
: [Good(10f, t0), Good(7, t0)],
|
|
DiagnosticInfos = [],
|
|
});
|
|
var seen = new List<(string Ref, uint Status)>();
|
|
drv.OnDataChange += (_, e) => { lock (seen) seen.Add((e.FullReference, e.Snapshot.StatusCode)); };
|
|
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadNoCommunication);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.Good);
|
|
await drv.RecoveryTaskForTest;
|
|
await drv.ReconcileTaskForTest;
|
|
|
|
reads.ShouldBe(2);
|
|
seen.Where(e => e.Status != BadNoCommunication).ShouldBe([
|
|
(SpeedRef, 0u), (CounterRef, 0u), // recovery read
|
|
(SpeedRef, (uint)StatusCodes.UncertainLastUsableValue), // trailing read: status-only change at t0
|
|
]);
|
|
}
|
|
|
|
/// <summary>
|
|
/// Review of 3b88056f: the trailing read's compare and its publish are one critical section with the live
|
|
/// notification path. Here a NEWER notification arrives exactly between the trailing read's decision and its
|
|
/// publish; it must wait, so the older re-read can never land after it and regress the node.
|
|
/// </summary>
|
|
[Fact]
|
|
public async Task A_notification_racing_the_trailing_publish_is_serialised_after_it()
|
|
{
|
|
var (drv, session, clock, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
drv.PostRecoveryReconcileDelay = () => TimeSpan.Zero;
|
|
var handle = drv.AddSubscriptionForTest([SpeedRef]);
|
|
var t0 = clock.Now.UtcDateTime;
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(10f, t0));
|
|
SetupRecoveryThenTrailing(session, Good(10f, t0), Good(40f, t0.AddSeconds(5)));
|
|
Task? racer = null;
|
|
drv.BeforeReconcilePublishForTest = _ =>
|
|
{
|
|
racer = Task.Run(() => drv.DeliverNotificationForTest(handle, SpeedRef, Good(50f, t0.AddSeconds(8))));
|
|
// Bounded: with the critical section the racer cannot finish until this publish is done.
|
|
racer.Wait(TimeSpan.FromMilliseconds(300));
|
|
};
|
|
|
|
var seen = await RecoverAndReconcileAsync(drv);
|
|
await racer!.WaitAsync(TimeSpan.FromSeconds(5), TestContext.Current.CancellationToken);
|
|
|
|
lock (seen) seen.Select(e => e.Value).ShouldBe([10f, 10f, 40f, 50f], "the newer 50 must be the last value delivered");
|
|
}
|
|
|
|
/// <summary>Review of 3b88056f: the background timers are bound to the session — a shutdown cancels a pending
|
|
/// trailing read instead of leaving it to fire (and read) against whatever session exists later.</summary>
|
|
[Fact]
|
|
public async Task Shutdown_cancels_a_pending_trailing_read()
|
|
{
|
|
var (drv, session, clock, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
drv.PostRecoveryReconcileDelay = () => TimeSpan.FromHours(1);
|
|
var handle = drv.AddSubscriptionForTest([SpeedRef]);
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, Good(10f, clock.Now.UtcDateTime));
|
|
SetupRead(session, () => clock.Now.UtcDateTime, 10f);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.BadNoCommunication);
|
|
drv.RaiseKeepAliveForTest(StatusCodes.Good);
|
|
await drv.RecoveryTaskForTest;
|
|
drv.ReconcileTaskForTest.IsCompleted.ShouldBeFalse("pending for an hour");
|
|
|
|
await drv.ShutdownAsync(TestContext.Current.CancellationToken);
|
|
|
|
await drv.ReconcileTaskForTest.WaitAsync(TimeSpan.FromSeconds(5), TestContext.Current.CancellationToken);
|
|
}
|
|
|
|
/// <summary>
|
|
/// Re-review of 30a9d5f0: with no source timestamps to compare, "newer" cannot be judged from the values. The
|
|
/// trailing read samples V1; while it is in flight a live notification delivers V2; the read then returns V1 —
|
|
/// different from the last delivered value and with no timestamp to prove it older. It must NOT be published: a
|
|
/// ref delivered to after the read was issued is skipped (per-ref delivery sequence), or the node regresses to V1.
|
|
/// </summary>
|
|
[Theory]
|
|
[InlineData(false)]
|
|
[InlineData(true)]
|
|
public async Task A_notification_delivered_while_the_trailing_read_is_in_flight_is_not_overwritten(bool readHasSourceTime)
|
|
{
|
|
var (drv, session, clock, _) = NewConnectedDriver();
|
|
using var _ = drv;
|
|
drv.PostRecoveryReconcileDelay = () => TimeSpan.Zero;
|
|
var handle = drv.AddSubscriptionForTest([SpeedRef]);
|
|
var t0 = clock.Now.UtcDateTime;
|
|
DataValue NoSource(object v, DateTime server) => new(new Variant(v), StatusCodes.Good, DateTime.MinValue, server);
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, NoSource(10f, t0));
|
|
var reads = 0;
|
|
session.Setup(s => s.ReadAsync(
|
|
It.IsAny<RequestHeader>(), It.IsAny<double>(), It.IsAny<TimestampsToReturn>(),
|
|
It.IsAny<ReadValueIdCollection>(), It.IsAny<CancellationToken>()))
|
|
.ReturnsAsync(() =>
|
|
{
|
|
DataValue result;
|
|
if (Interlocked.Increment(ref reads) == 1)
|
|
result = NoSource(10f, t0.AddSeconds(1)); // recovery read: unchanged
|
|
else
|
|
{
|
|
// The trailing read has sampled V1 at the server; before its response is processed, the live
|
|
// subscription delivers the newer V2.
|
|
drv.DeliverNotificationForTest(handle, SpeedRef, NoSource(20f, t0.AddSeconds(9)));
|
|
result = readHasSourceTime
|
|
? Good(15f, t0.AddSeconds(8)) // read carries a source time, V2 did not
|
|
: NoSource(15f, t0.AddSeconds(8));
|
|
}
|
|
return new ReadResponse { ResponseHeader = new ResponseHeader(), Results = [result], DiagnosticInfos = [] };
|
|
});
|
|
|
|
var seen = await RecoverAndReconcileAsync(drv);
|
|
|
|
reads.ShouldBe(2, "the trailing read must have run");
|
|
lock (seen) seen.Select(e => e.Value).ShouldBe([10f, 10f, 20f], "the read's stale 15 must not overwrite the newer 20");
|
|
}
|
|
}
|