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

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;
             }

tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATCapturingLogger.cs

@@ -11,6 +11,12 @@ internal sealed class TwinCATCapturingLogger : ILogger<TwinCATDriver>
     /// <summary>Gets a snapshot of the formatted Warning messages logged so far.</summary>
     public IReadOnlyList<string> Warnings { get { lock (_warnings) return [.. _warnings]; } }
 
+    /// <summary>
+    ///     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.
+    /// </summary>
+    public Action<string>? OnWarning { get; init; }
+
     /// <inheritdoc />
     public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
 
@@ -21,6 +27,9 @@ internal sealed class TwinCATCapturingLogger : ILogger<TwinCATDriver>
     public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception,
         Func<TState, Exception?, string> 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);
     }
 }

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<bool> condition, TimeSpan timeout)
     {
@@ -161,7 +165,9 @@ public sealed class TwinCATReviewFixRound2Tests
     /// <summary>
     ///     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.
     /// </summary>
     [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);
     }
 
+    /// <summary>A logger that blocks the driver's refusal WARN for ten probe intervals (see lmxopcua#773).</summary>
+    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); },
+        };
+    }
+
+    /// <summary>
+    ///     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 <c>NextRetryUtc = MinValue</c> and retry at once.
+    ///     The refusal WARN is held for ten probe intervals to open the window between the subscribe path
+    ///     releasing <c>ConnectGate</c> 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:
+    ///     <c>AttemptsFor("MAIN.T") should be 1 but was 2</c>). Deterministic: it failed every run before the fix.
+    /// </summary>
+    [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);
+    }
+
     /// <summary>A re-arm restarts the refusal backoff from the initial delay instead of doubling the old one.</summary>
     [Fact]
     public async Task A_rearm_restarts_the_refusal_backoff()