Files
lmxopcua/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.OpcUaClient.Tests/OpcUaClientConnectionLossSignalTests.cs
T
Joseph Doherty fccffd0a0f feat(opcuaclient): #676 follow-ups — endpoint rewrite, stall wire test, fast definitive-loss recovery
- Endpoint rewrite: the driver now connects to the configured host AND port (scheme
  match, advertised path kept) instead of the server-advertised URL — fixes NAT/port-map
  upstreams and lets an in-test proxy carry the session (SDK SelectEndpoint rule).
- TcpStallProxy + OpcUaClientDriverStallWireTests: the in-place blip (#670) is now
  wire-tested on loopback — one Bad, frozen read stamp, same session, identical value
  republished Good, a post-recovery change arrives, no source-time regression after
  the SDK's late backlog flush.
- Defect found by that test, fixed: a change published right after a stall rode a
  Publish response the SDK timed out and never republished, leaving the node Good on
  the pre-change value indefinitely. New trailing reconcile read (Timeout +
  KeepAliveInterval after recovery) publishes any Good value newer than the last
  accepted one, through the replay guard's mark.
- IDriverConnectionLossSource (Core.Abstractions): opt-in definitive-loss signal.
  DriverInstanceActor attaches in PreStart / detaches in PostStop and turns a raise
  into a disconnect only while Connected. OpcUaClient raises once per session on
  keep-alive BadSessionIdInvalid/BadSessionClosed/BadSessionNotActivated/
  BadServerHalted (measured: the SDK never re-opens a halted channel) or a dropped
  subscription; ambiguous codes stay with the #527 watchdog.
- Replay guard: one Information summary per recovery when the window closes
  ("dropped N late notifications across M refs"), with a timer so quiet
  subscriptions log it too.
- ReconnectPeriod deleted (options, AdminUI form, docs, tests); stored configs that
  carry reconnectPeriod still parse in the factory, probe and browser.
- Docs: OpcUaClient.md, DriverLifecycle.md, driver-specs.md, CLAUDE.md.
2026-10-11 11:35:52 -04:00

409 lines
19 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)
{
lock (Entries)
return [.. Entries.Where(e => e.Level == LogLevel.Information && 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.BadConnectionClosed,
StatusCodes.BadNotConnected,
StatusCodes.BadRequestTimeout,
StatusCodes.BadTimeout,
StatusCodes.BadSecureChannelClosed,
];
[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");
}
[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);
}
// ── 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_still_reports_it_closed_and_counts_restart_per_window()
{
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(31));
drv.DeliverNotificationForTest(handle, SpeedRef, Good(2, t0.AddSeconds(40)));
drv.RaiseKeepAliveForTest(StatusCodes.BadNoCommunication);
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.",
"OpcUaClientDriver 'opcua-676': post-recovery replay window closed — dropped 0 late notifications across 0 refs after recovery.",
]);
}
// ── 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");
}
}