From f0992394b63ffa7c3598d41d908b0b5dcc115e44 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Mon, 9 Nov 2026 15:06:25 -0500 Subject: [PATCH] fix(twincat): book a refused registration's backoff before releasing ConnectGate (lmxopcua#773) RegisterNotificationAsync published a refused registration into NativeRegistrations under ConnectGate with NextRetryUtc = MinValue; the SubscribeAsync caller booked the refusal backoff (NoteDeadFailure refused: true) only after the gate was released and after its WARN. A probe tick in that window took the gate, saw the registration as due, and retried it at once - the CI flake in A_rearm_during_an_in_flight_retry_is_not_lost ("AttemptsFor(\"MAIN.T\") should be 1 but was 2"). RegisterNotificationAsync now books the failure (refusal backoff, or the comms-class every-tick retry) before it publishes the dead registration, still under the gate. The caller no longer books the refusal a second time (that would double the backoff); its comms-class booking is idempotent and stays. Tests: TwinCATCapturingLogger gains an OnWarning hook. A logger that holds the refusal WARN for ten probe intervals forces the window open, so A_rearm_during_an_in_flight_retry_is_not_lost exercises it on every run, and the new A_refused_registration_is_published_with_its_backoff_already_set pins the backoff (booked once, not doubled). Pass rate of A_rearm_during_an_in_flight_retry_is_not_lost: - before, unmodified test: 40/40 runs, plus 200/200 in-process repeats under CPU load (the natural window is a few instructions wide; the flake is rare); - before, window held open: 0/32 (deterministic failure, "should be 1 but was 2"); - after, window held open: 40/40. Full TwinCAT suite 663/663 at AKKA_TEST_TIMEFACTOR 1 and 3. Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV --- .../TwinCATDriver.cs | 12 ++++- .../TwinCATCapturingLogger.cs | 11 ++++- .../TwinCATReviewFixRound2Tests.cs | 49 ++++++++++++++++++- 3 files changed, 67 insertions(+), 5 deletions(-) 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()