diff --git a/docs/drivers/OpcUaClient.md b/docs/drivers/OpcUaClient.md index b1d2978c..2cd1f369 100644 --- a/docs/drivers/OpcUaClient.md +++ b/docs/drivers/OpcUaClient.md @@ -199,6 +199,13 @@ The session keep-alive (`KeepAliveInterval`, default 5 s) is the liveness signal reported gone (`BadNoSubscription` / `BadSubscriptionIdInvalid`) never comes back on its session, so that also raises `ConnectionLost` (#676) and the re-initialise happens at once; the `PublishingStopped` **heuristic** is an inference from silence and keeps going through the watchdog. + **Stale `BadNoSubscription` (#763):** the SDK reports it with subscription id 0, and a publish the SDK queued while + the session briefly held no subscription — the driver deleting its last one, e.g. an unsubscribe→resubscribe of the + same set — is answered `BadNoSubscription` and can be handled after the replacement is registered. An anonymous + `BadNoSubscription` within `StaleNoSubscriptionGrace` (5 s) of a delete that left the driver tracking nothing is + therefore ignored (logged at Debug); one that names a subscription id counts only if that id is tracked. A delete + that leaves another subscription tracked opens no window, the window resets with the session, and a genuine loss + inside it is still caught by the `PublishingStopped` heuristic — only the immediate `ConnectionLost` is forgone. - An in-place recovery is bound to the session whose keep-alive recovered: one overtaken by a re-initialise neither publishes, nor degrades, nor re-arms the outage latch of the new session. diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.OpcUaClient/OpcUaClientDriver.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.OpcUaClient/OpcUaClientDriver.cs index 7cb2ce33..4ffb960d 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.OpcUaClient/OpcUaClientDriver.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.OpcUaClient/OpcUaClientDriver.cs @@ -236,7 +236,8 @@ public sealed class OpcUaClientDriver : IDriver, ITagDiscovery, IReadable, IWrit /// Test-only seam: register an alarm subscription over as /// would, without the wire create. /// The alarm RawPaths subscribed. - internal void AddAlarmSubscriptionForTest(IReadOnlyList refs) + /// The alarm subscription handle. + internal IAlarmSubscriptionHandle AddAlarmSubscriptionForTest(IReadOnlyList refs) { var id = Interlocked.Increment(ref _nextAlarmSubscriptionId); var handle = new OpcUaAlarmSubscriptionHandle(id); @@ -245,6 +246,7 @@ public sealed class OpcUaClientDriver : IDriver, ITagDiscovery, IReadable, IWrit _alarmSubscriptions[id] = new RemoteAlarmSubscription( new Subscription(telemetry: null!, new SubscriptionOptions { DisplayName = $"{AlarmSubscriptionNamePrefix}{id}" }), handle, item, (_, _) => { }); + return handle; } /// @@ -302,6 +304,26 @@ public sealed class OpcUaClientDriver : IDriver, ITagDiscovery, IReadable, IWrit /// (0 = none stalled). Only the keep-alive thread and the session release touch it. private long _publishingStoppedSinceTicks; + /// + /// How long after the driver deleted its LAST server-side subscription an anonymous BadNoSubscription + /// (subscription id 0) is attributed to that delete rather than to a loss of whatever was subscribed since + /// (Gitea #763). A publish request the SDK had queued while the session held no subscription is answered + /// BadNoSubscription, and its PublishError can be handled AFTER the next subscription is registered + /// — an unsubscribe→resubscribe of the same set (DriverInstanceActor's reconcile) then looked like the + /// server dropping the new subscription. The SDK names no subscription on that status, so the delete is the + /// only thing it can be attributed to. Bounded on purpose: a genuine loss inside the window still degrades the + /// driver through the publishing-stall heuristic (); only the immediate + /// is forgone for it, and only within this window. + /// + internal static readonly TimeSpan StaleNoSubscriptionGrace = TimeSpan.FromSeconds(5); + + /// + /// UTC ticks of the last time the driver deleted a subscription that left it tracking none (0 = never on this + /// session) — the moment the server could legitimately answer BadNoSubscription. See + /// . Reset when the session is released. + /// + private long _lastSubscriptionsEmptiedTicks; + /// The last in-place recovery started. Test seam: lets a test await it deterministically. private Task _recoveryTask = Task.CompletedTask; @@ -1191,6 +1213,7 @@ public sealed class OpcUaClientDriver : IDriver, ITagDiscovery, IReadable, IWrit Interlocked.Exchange(ref _sessionLost, 0); Interlocked.Exchange(ref _subscriptionLost, 0); Interlocked.Exchange(ref _publishingStoppedSinceTicks, 0); + Interlocked.Exchange(ref _lastSubscriptionsEmptiedTicks, 0); // re-arm the definitive-loss signal for the next session. Interlocked.Exchange(ref _connectionLostRaised, 0); Interlocked.Exchange(ref _closedChannelFailures, 0); @@ -1954,6 +1977,8 @@ public sealed class OpcUaClientDriver : IDriver, ITagDiscovery, IReadable, IWrit await session.RemoveSubscriptionAsync(subscription, removeCts.Token).ConfigureAwait(false); } catch { /* best-effort — the session may be the thing that failed */ } + // a half-built subscription can have been the server's only one, so its delete opens the same window. + NoteSubscriptionDeleted(); throw; } _subscriptions[id] = new RemoteSubscription(subscription, handle, itemHandlers); @@ -2014,6 +2039,7 @@ public sealed class OpcUaClientDriver : IDriver, ITagDiscovery, IReadable, IWrit { if (handle is not OpcUaSubscriptionHandle h) return; if (!_subscriptions.TryRemove(h.Id, out var rs)) return; + var emptied = NoteSubscriptionDeleted(); await _subscriptionGate.WaitAsync(cancellationToken).ConfigureAwait(false); try @@ -2027,7 +2053,12 @@ public sealed class OpcUaClientDriver : IDriver, ITagDiscovery, IReadable, IWrit try { await rs.Subscription.DeleteAsync(silent: true, cancellationToken).ConfigureAwait(false); } catch { /* best-effort — the subscription may already be gone on reconnect */ } } - finally { _subscriptionGate.Release(); } + finally + { + // the server answers the stale publish only once the delete is done, so the window runs from here. + if (emptied) NoteSubscriptionDeleted(force: true); + _subscriptionGate.Release(); + } } private static void DetachNotificationHandlers(IReadOnlyList items) @@ -2463,6 +2494,8 @@ public sealed class OpcUaClientDriver : IDriver, ITagDiscovery, IReadable, IWrit await session.RemoveSubscriptionAsync(subscription, removeCts.Token).ConfigureAwait(false); } catch { /* best-effort — the session may be the thing that failed */ } + // a half-built subscription can have been the server's only one, so its delete opens the same window. + NoteSubscriptionDeleted(); throw; } @@ -2512,6 +2545,7 @@ public sealed class OpcUaClientDriver : IDriver, ITagDiscovery, IReadable, IWrit { if (handle is not OpcUaAlarmSubscriptionHandle h) return; if (!_alarmSubscriptions.TryRemove(h.Id, out var rs)) return; + var emptied = NoteSubscriptionDeleted(); await _subscriptionGate.WaitAsync(cancellationToken).ConfigureAwait(false); try @@ -2524,7 +2558,12 @@ public sealed class OpcUaClientDriver : IDriver, ITagDiscovery, IReadable, IWrit try { await rs.Subscription.DeleteAsync(silent: true, cancellationToken).ConfigureAwait(false); } catch { /* best-effort — session may already be gone across a reconnect */ } } - finally { _subscriptionGate.Release(); } + finally + { + // the server answers the stale publish only once the delete is done, so the window runs from here. + if (emptied) NoteSubscriptionDeleted(force: true); + _subscriptionGate.Release(); + } } /// @@ -3339,7 +3378,9 @@ public sealed class OpcUaClientDriver : IDriver, ITagDiscovery, IReadable, IWrit /// /// Session PublishError: always counted; a BadNoSubscription / BadSubscriptionIdInvalid naming a - /// subscription the driver tracks means the server dropped it while the session lived. + /// subscription the driver tracks means the server dropped it while the session lived. An anonymous + /// BadNoSubscription means the server holds none at all — a loss of anything tracked, except within + /// of the driver deleting its last subscription (#763). /// private void OnPublishError(object? sender, PublishErrorEventArgs e) => HandlePublishError(sender, e.Status?.StatusCode ?? StatusCodes.Good, e.SubscriptionId); @@ -3349,19 +3390,60 @@ public sealed class OpcUaClientDriver : IDriver, ITagDiscovery, IReadable, IWrit _diag.Record(OpcUaClientDiagnostics.PublishError); var generation = Volatile.Read(ref _lifecycleGeneration); if (sender is not null && !ReferenceEquals(sender, Session)) return; + var now = Clock.GetUtcNow().UtcDateTime; bool tracked; - if (code == StatusCodes.BadNoSubscription) + if (code == StatusCodes.BadSubscriptionIdInvalid + || (code == StatusCodes.BadNoSubscription && subscriptionId != 0)) + { + // The error names a subscription: it is a loss only if that subscription is one the driver still tracks + // (one it deleted itself, or never registered, is not). + tracked = IsTrackedSubscription(subscriptionId); + } + else if (code == StatusCodes.BadNoSubscription) + { + // Anonymous: the server holds NO subscription for the session. True of anything tracked — unless the + // driver just deleted its last subscription, when it is the answer to a publish queued in that gap (#763). tracked = !_subscriptions.IsEmpty || !_alarmSubscriptions.IsEmpty; - else if (code == StatusCodes.BadSubscriptionIdInvalid) - tracked = _subscriptions.Values.Any(r => r.Subscription.Id == subscriptionId) - || _alarmSubscriptions.Values.Any(r => r.Subscription.Id == subscriptionId); + if (tracked && IsWithinStaleNoSubscriptionGrace(now)) + { + _logger.LogDebug( + "OpcUaClientDriver '{DriverInstanceId}': ignoring BadNoSubscription within {Grace} of deleting the " + + "last subscription — it answers a publish queued while the session held none, not a loss of the " + + "subscription registered since.", _driverInstanceId, StaleNoSubscriptionGrace); + return; + } + } else return; if (tracked) - DeclareSubscriptionLost(generation, $"server reported {code} for a tracked subscription", Clock.GetUtcNow().UtcDateTime, + DeclareSubscriptionLost(generation, $"server reported {code} for a tracked subscription", now, serverReported: true); } + private bool IsTrackedSubscription(uint subscriptionId) => + _subscriptions.Values.Any(r => r.Subscription.Id == subscriptionId) + || _alarmSubscriptions.Values.Any(r => r.Subscription.Id == subscriptionId); + + /// + /// Stamp when a delete leaves the driver tracking no subscription + /// (or unconditionally with , to restart the window once that delete has completed). + /// + /// Stamp even though a subscription has been registered since (the delete it follows did + /// empty the set). + /// True when the stamp was taken. + private bool NoteSubscriptionDeleted(bool force = false) + { + if (!force && (!_subscriptions.IsEmpty || !_alarmSubscriptions.IsEmpty)) return false; + Interlocked.Exchange(ref _lastSubscriptionsEmptiedTicks, Clock.GetUtcNow().UtcDateTime.Ticks); + return true; + } + + private bool IsWithinStaleNoSubscriptionGrace(DateTime now) + { + var emptied = Interlocked.Read(ref _lastSubscriptionsEmptiedTicks); + return emptied != 0 && now.Ticks - emptied < StaleNoSubscriptionGrace.Ticks; + } + /// /// publish the start of an outage: BadNoCommunication once per (subscription, ref) with the last /// delivered value retained, and a quality-only annotation on every subscribed alarm condition (no state diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.OpcUaClient.Tests/OpcUaClientStaleNoSubscriptionTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.OpcUaClient.Tests/OpcUaClientStaleNoSubscriptionTests.cs new file mode 100644 index 00000000..9990c8b1 --- /dev/null +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.OpcUaClient.Tests/OpcUaClientStaleNoSubscriptionTests.cs @@ -0,0 +1,186 @@ +using System.Text.Json; +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; + +/// +/// Gitea #763 (root cause of #728) — a BadNoSubscription PublishError with no subscription id that answers a +/// publish queued while the driver had just deleted its LAST subscription must not be read as a loss of the +/// subscription registered since. Before the fix any anonymous BadNoSubscription with anything tracked +/// declared the subscription lost: health Degraded, a BadNoCommunication quality-only annotation on every +/// alarm condition and — so a routine unsubscribe → +/// resubscribe re-initialised the driver. A genuine loss must still be declared. +/// +[Trait("Category", "Unit")] +public sealed class OpcUaClientStaleNoSubscriptionTests +{ + private const uint BadNoCommunication = 0x80310000u; + private const string SpeedRef = "Plant/dev/Speed"; + private const string AlarmRef = "Plant/dev/TempHi"; + + 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 static readonly IReadOnlyList Tags = + [ + new(SpeedRef, JsonSerializer.Serialize(new { nodeId = "ns=0;s=Speed" }), WriteIdempotent: true), + ]; + + private sealed record Observed(List Alarms, List Data, + List Lost); + + private static (OpcUaClientDriver Driver, ManualClock Clock, Observed Seen) NewConnectedDriver() + { + var drv = new OpcUaClientDriver(new OpcUaClientDriverOptions { RawTags = Tags }, "opcua-763"); + var session = new Mock(MockBehavior.Loose); + session.SetupGet(s => s.MessageContext).Returns(new ServiceMessageContext(SdkTelemetry.Context)); + session.SetupGet(s => s.NamespaceUris).Returns(new NamespaceTable()); + var clock = new ManualClock(new DateTimeOffset(2026, 11, 9, 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)); + var seen = new Observed([], [], []); + drv.OnAlarmEvent += (_, e) => seen.Alarms.Add(e); + drv.OnDataChange += (_, e) => seen.Data.Add(e); + drv.ConnectionLost += (_, e) => seen.Lost.Add(e); + return (drv, clock, seen); + } + + private static void ShouldBeUntouched(OpcUaClientDriver drv, Observed seen, string because) + { + drv.GetHealth().State.ShouldBe(DriverState.Healthy, because); + seen.Lost.ShouldBeEmpty(because); + seen.Alarms.ShouldBeEmpty(because); + seen.Data.ShouldBeEmpty(because); + } + + private static void ShouldBeDeclaredLost(OpcUaClientDriver drv, Observed seen, string because) + { + drv.GetHealth().State.ShouldBe(DriverState.Degraded, because); + seen.Lost.ShouldHaveSingleItem(because).Reason.ShouldContain("subscription lost"); + } + + /// The #728 wire shape: alarm set released and re-subscribed, then the late error lands. + [Fact] + public async Task A_stale_BadNoSubscription_after_an_alarm_resubscribe_is_not_a_loss() + { + var (drv, clock, seen) = NewConnectedDriver(); + await using var _ = drv; + var first = drv.AddAlarmSubscriptionForTest([AlarmRef]); + + await drv.UnsubscribeAlarmsAsync(first, TestContext.Current.CancellationToken); + drv.AddAlarmSubscriptionForTest([AlarmRef]); + clock.Advance(TimeSpan.FromMilliseconds(850)); // measured on the wire: ~0.85 s after the resubscribe + drv.RaisePublishErrorForTest(StatusCodes.BadNoSubscription); + + ShouldBeUntouched(drv, seen, "the error answers the deleted subscription's publish, not a loss of the new one"); + } + + [Fact] + public async Task A_stale_BadNoSubscription_after_a_data_resubscribe_is_not_a_loss() + { + var (drv, clock, seen) = NewConnectedDriver(); + await using var _ = drv; + var first = drv.AddSubscriptionForTest([SpeedRef]); + + await drv.UnsubscribeAsync(first, TestContext.Current.CancellationToken); + drv.AddSubscriptionForTest([SpeedRef]); + clock.Advance(TimeSpan.FromSeconds(1)); + drv.RaisePublishErrorForTest(StatusCodes.BadNoSubscription); + + ShouldBeUntouched(drv, seen, "the error answers the deleted subscription's publish, not a loss of the new one"); + } + + /// Positive control for the window: the same error once it has elapsed is a genuine loss. + [Fact] + public async Task A_BadNoSubscription_after_the_grace_is_still_a_loss() + { + var (drv, clock, seen) = NewConnectedDriver(); + await using var _ = drv; + var first = drv.AddAlarmSubscriptionForTest([AlarmRef]); + await drv.UnsubscribeAlarmsAsync(first, TestContext.Current.CancellationToken); + drv.AddAlarmSubscriptionForTest([AlarmRef]); + + clock.Advance(OpcUaClientDriver.StaleNoSubscriptionGrace); + drv.RaisePublishErrorForTest(StatusCodes.BadNoSubscription); + + ShouldBeDeclaredLost(drv, seen, "past the grace the server has dropped the new subscription"); + seen.Alarms.ShouldHaveSingleItem().QualityStatusCode.ShouldBe(BadNoCommunication); + } + + /// Genuine loss with no recent delete at all — the pre-#763 behaviour, kept. + [Fact] + public void A_BadNoSubscription_with_no_recent_delete_is_a_loss() + { + var (drv, _, seen) = NewConnectedDriver(); + using var _ = drv; + drv.AddAlarmSubscriptionForTest([AlarmRef]); + + drv.RaisePublishErrorForTest(StatusCodes.BadNoSubscription); + + ShouldBeDeclaredLost(drv, seen, "the server holds none of the subscriptions the driver tracks"); + seen.Alarms.ShouldHaveSingleItem().QualityStatusCode.ShouldBe(BadNoCommunication); + } + + /// + /// Deleting one subscription while another stays tracked never left the server empty, so a BadNoSubscription + /// can only mean the survivor is gone — the window must not open. + /// + [Fact] + public async Task Deleting_a_subscription_that_was_not_the_last_does_not_open_the_window() + { + var (drv, _, seen) = NewConnectedDriver(); + await using var _ = drv; + drv.AddAlarmSubscriptionForTest([AlarmRef]); + var data = drv.AddSubscriptionForTest([SpeedRef]); + + await drv.UnsubscribeAsync(data, TestContext.Current.CancellationToken); + drv.RaisePublishErrorForTest(StatusCodes.BadNoSubscription); + + ShouldBeDeclaredLost(drv, seen, "the alarm subscription outlived the delete, so the server should still hold it"); + } + + [Fact] + public async Task A_BadNoSubscription_naming_a_subscription_the_driver_no_longer_tracks_is_not_a_loss() + { + var (drv, clock, seen) = NewConnectedDriver(); + await using var _ = drv; + var first = drv.AddAlarmSubscriptionForTest([AlarmRef]); + await drv.UnsubscribeAlarmsAsync(first, TestContext.Current.CancellationToken); + drv.AddAlarmSubscriptionForTest([AlarmRef]); + clock.Advance(TimeSpan.FromMinutes(1)); // well past the grace: attribution is by id, not by time + + drv.RaisePublishErrorForTest(StatusCodes.BadNoSubscription, subscriptionId: 4242); + + ShouldBeUntouched(drv, seen, "the error names a subscription the driver does not track"); + } + + /// A released session starts with no window: the stamp of the previous session's delete is gone. + [Fact] + public async Task The_window_does_not_survive_a_session_release() + { + var (drv, clock, seen) = NewConnectedDriver(); + await using var _ = drv; + var first = drv.AddAlarmSubscriptionForTest([AlarmRef]); + await drv.UnsubscribeAlarmsAsync(first, TestContext.Current.CancellationToken); + + await drv.ShutdownAsync(TestContext.Current.CancellationToken); + var session = new Mock(MockBehavior.Loose); + drv.SetSessionForTest(session.Object); + drv.SetHealthForTest(new DriverHealth(DriverState.Healthy, clock.Now.UtcDateTime, null)); + drv.AddAlarmSubscriptionForTest([AlarmRef]); + drv.RaisePublishErrorForTest(StatusCodes.BadNoSubscription); + + ShouldBeDeclaredLost(drv, seen, "the delete belonged to the released session"); + } +} diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.IntegrationTests/OpcUaClientDriverWireTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.IntegrationTests/OpcUaClientDriverWireTests.cs index fc8f2a01..a3134d56 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.IntegrationTests/OpcUaClientDriverWireTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer.IntegrationTests/OpcUaClientDriverWireTests.cs @@ -314,10 +314,21 @@ public sealed class OpcUaClientDriverWireTests Enabled: true, AlarmShelvingKind.Unshelved, 800, "already hot")); await RecordedEvents.WaitUntilAsync(() => Seen().Any(e => e.Kind == AlarmTransitionKind.Acknowledge)); await Task.Delay(500, ct); - Seen().Skip(before).Select(e => e.Kind).ShouldBe([AlarmTransitionKind.Acknowledge], - "the second refresh re-delivered an unchanged state and must have emitted nothing"); + // #728: record each event's full shape on failure, not only its Kind — the extra Unspecified that failed CI + // could be a changed message/severity, a non-condition event or a quality-only annotation, and the Kind alone + // cannot tell them apart. + var after = Seen().Skip(before).ToArray(); + after.Select(e => e.Kind).ShouldBe([AlarmTransitionKind.Acknowledge], + "the second refresh re-delivered an unchanged state and must have emitted nothing; events after the " + + "resubscribe: " + string.Join(" | ", after.Select(Describe))); } + /// One alarm event's distinguishing fields, for a failure message. + private static string Describe(AlarmEventArgs e) => + $"Kind={e.Kind} AlarmType={e.AlarmType} Message='{e.Message}' Severity={e.Severity}/{e.OpcUaSeverity?.ToString() ?? "-"} " + + $"Quality={(e.QualityStatusCode is { } q ? $"0x{q:X8}" : "-")} Restatement={e.IsRestatement} " + + $"Condition={e.ConditionId} Source={e.SourceTimestampUtc:HH:mm:ss.fff}"; + private sealed class RecordingBuilder : IAddressSpaceBuilder { public List<(string BrowseName, DriverAttributeInfo Info)> Variables { get; } = [];