diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT/TwinCATDriver.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT/TwinCATDriver.cs index 8b6c0927..1ffe7b4d 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT/TwinCATDriver.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT/TwinCATDriver.cs @@ -964,10 +964,11 @@ public sealed class TwinCATDriver : IDriver, IReadable, IWritable, ITagDiscovery // snapshot carrying the refusal's status, no health write (a refusal is not a comms // fault). Its intent stays on the device with no live handle, so the probe-tick retry // re-checks it after a PLC program change. + // Its backoff was booked under ConnectGate by RegisterNotificationAsync (lmxopcua#773); + // booking it again here would double it. _logger.LogWarning( "TwinCAT driver '{DriverInstanceId}' refused native notification for '{Reference}': {Reason}", _driverInstanceId, reference, refused.Message); - NoteDeadFailure(reg, refused.StatusCode, refused: true, DateTime.UtcNow); RaiseDataChange(handle, reference, new DataValueSnapshot( null, refused.StatusCode, null, DateTime.UtcNow)); } @@ -990,6 +991,7 @@ public sealed class TwinCATDriver : IDriver, IReadable, IWritable, ITagDiscovery "'{Reference}'; it will be retried on the next healthy probe tick", _driverInstanceId, reference); MarkCommsFault(ex.Message, device); + // Idempotent for a comms-class failure (RegisterNotificationAsync already booked it). NoteDeadFailure(reg, TwinCATStatusMapper.BadCommunicationError, refused: false, DateTime.UtcNow); RaiseDataChange(handle, reference, new DataValueSnapshot( null, TwinCATStatusMapper.BadCommunicationError, null, DateTime.UtcNow)); @@ -1196,10 +1198,16 @@ public sealed class TwinCATDriver : IDriver, IReadable, IWritable, ITagDiscovery _options.NotificationMaxDelayMs, reg.OnChange, ct).ConfigureAwait(false); } catch (OperationCanceledException) { throw; } - catch + catch (Exception ex) { // Keep the intent with no live handle (a "dead" registration) so the probe-tick // retry re-checks it and UnsubscribeAsync still removes it; the caller isolates it. + // Book the failure (a refusal's backoff) BEFORE publishing it, still under the gate: the + // probe tick takes the same gate, and a refusal it saw with NextRetryUtc = MinValue was + // retried at once instead of waiting out its backoff (lmxopcua#773). + NoteDeadFailure(reg, + (ex as TwinCATNotificationRefusedException)?.StatusCode ?? TwinCATStatusMapper.BadCommunicationError, + refused: ex is TwinCATNotificationRefusedException, DateTime.UtcNow); device.NativeRegistrations[reg.Id] = reg; throw; } diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATCapturingLogger.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATCapturingLogger.cs index 9df5d1b8..e804b724 100644 --- a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATCapturingLogger.cs +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATCapturingLogger.cs @@ -11,6 +11,12 @@ internal sealed class TwinCATCapturingLogger : ILogger /// Gets a snapshot of the formatted Warning messages logged so far. public IReadOnlyList Warnings { get { lock (_warnings) return [.. _warnings]; } } + /// + /// Optional hook run synchronously on the logging thread for each Warning, after it is captured. A test can + /// block in it to hold open the window between the driver's log call and its next statement. + /// + public Action? OnWarning { get; init; } + /// public IDisposable? BeginScope(TState state) where TState : notnull => null; @@ -21,6 +27,9 @@ internal sealed class TwinCATCapturingLogger : ILogger public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) { - if (logLevel == LogLevel.Warning) lock (_warnings) _warnings.Add(formatter(state, exception)); + if (logLevel != LogLevel.Warning) return; + var message = formatter(state, exception); + lock (_warnings) _warnings.Add(message); + OnWarning?.Invoke(message); } } diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATReviewFixRound2Tests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATReviewFixRound2Tests.cs index 0acc860f..fb6619cd 100644 --- a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATReviewFixRound2Tests.cs +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATReviewFixRound2Tests.cs @@ -26,13 +26,17 @@ public sealed class TwinCATReviewFixRound2Tests private static TwinCATDriver NewDriver(FakeTwinCATClientFactory factory, TwinCATProbeOptions probe, bool native, params TwinCATTagDefinition[] tags) => + NewDriver(factory, probe, native, logger: null, tags); + + private static TwinCATDriver NewDriver(FakeTwinCATClientFactory factory, TwinCATProbeOptions probe, bool native, + TwinCATCapturingLogger? logger, params TwinCATTagDefinition[] tags) => new(new TwinCATDriverOptions { Devices = [new TwinCATDeviceOptions(Host)], RawTags = TwinCATRawTags.Entries(tags), Probe = probe, UseNativeNotifications = native, - }, "drv-1", factory); + }, "drv-1", factory, logger); private static async Task WaitForAsync(Func condition, TimeSpan timeout) { @@ -161,7 +165,9 @@ public sealed class TwinCATReviewFixRound2Tests /// /// A symbol-version re-arm that lands while a retry of the refused registration is in flight is not /// overwritten by that retry's failure: the next tick re-attempts at once. (Without the epoch the - /// failure re-imposed a 30 s+ backoff.) + /// failure re-imposed a 30 s+ backoff.) The initial refusal's WARN is held for ten probe intervals so the + /// window that made this test flake (lmxopcua#773 — a tick retrying before the backoff was booked) is + /// always exercised rather than hit by chance. /// [Fact] public async Task A_rearm_during_an_in_flight_retry_is_not_lost() @@ -169,6 +175,7 @@ public sealed class TwinCATReviewFixRound2Tests var fake = new FakeTwinCATClient(); fake.AddNotificationErrors["MAIN.T"] = new TwinCATTypeMismatchException("MAIN.T", "PLC STRING"); var drv = NewDriver(new FakeTwinCATClientFactory { Customise = () => fake }, FastProbe, native: true, + HoldingRefusalWarning(), new TwinCATTagDefinition("T", Host, "MAIN.T", TwinCATDataType.DInt)); await drv.InitializeAsync("{}", TestContext.Current.CancellationToken); _ = await drv.SubscribeAsync(["T"], TimeSpan.FromMilliseconds(100), TestContext.Current.CancellationToken); @@ -187,6 +194,44 @@ public sealed class TwinCATReviewFixRound2Tests await drv.ShutdownAsync(TestContext.Current.CancellationToken); } + /// A logger that blocks the driver's refusal WARN for ten probe intervals (see lmxopcua#773). + private static TwinCATCapturingLogger HoldingRefusalWarning() + { + var hold = TimeSpan.FromMilliseconds(FastProbe.Interval.TotalMilliseconds * 10); + return new TwinCATCapturingLogger + { + OnWarning = m => { if (m.Contains("refused native notification")) Thread.Sleep(hold); }, + }; + } + + /// + /// lmxopcua#773: a refused registration is published to the device's registry WITH its refusal backoff + /// already set, so a probe tick can never see it with NextRetryUtc = MinValue and retry at once. + /// The refusal WARN is held for ten probe intervals to open the window between the subscribe path + /// releasing ConnectGate and its caller finishing; before the fix the backoff was booked only after + /// that warning, so a tick in the window re-attempted the tag (the CI flake in the test above: + /// AttemptsFor("MAIN.T") should be 1 but was 2). Deterministic: it failed every run before the fix. + /// + [Fact] + public async Task A_refused_registration_is_published_with_its_backoff_already_set() + { + var fake = new FakeTwinCATClient(); + fake.AddNotificationErrors["MAIN.T"] = new TwinCATTypeMismatchException("MAIN.T", "PLC STRING"); + var logger = HoldingRefusalWarning(); + var drv = NewDriver(new FakeTwinCATClientFactory { Customise = () => fake }, FastProbe, native: true, logger, + new TwinCATTagDefinition("T", Host, "MAIN.T", TwinCATDataType.DInt)); + await drv.InitializeAsync("{}", TestContext.Current.CancellationToken); + + _ = await drv.SubscribeAsync(["T"], TimeSpan.FromMilliseconds(100), TestContext.Current.CancellationToken); + + logger.Warnings.ShouldContain(w => w.Contains("refused native notification")); // the window was held open + fake.AttemptsFor("MAIN.T").ShouldBe(1, "a probe tick retried the refusal before its backoff was booked"); + var reg = drv.GetDeviceState(Host)!.NativeRegistrations.Values.Single(); + reg.RefusalBackoff.ShouldBe(TwinCATDriver.RefusedRetryInitial, "booked once, not doubled by the caller"); + reg.NextRetryUtc.ShouldBeGreaterThan(DateTime.UtcNow); + await drv.ShutdownAsync(TestContext.Current.CancellationToken); + } + /// A re-arm restarts the refusal backoff from the initial delay instead of doubling the old one. [Fact] public async Task A_rearm_restarts_the_refusal_backoff()