fix(twincat): warn once per bad tag; a device refusal is not a comms fault (P10)

CompleteRead logged a Warning for every non-Good status on every poll and latched Degraded for all of them. Now a bad tag warns once per bad episode (re-armed when it reads Good, and on re-initialise), a comms-class status (BadCommunicationError / BadTimeout) degrades with LastSuccessfulRead preserved, and any other status - the device answered and refused this tag - advances LastSuccessfulRead with no state change. Read-path exception handlers now go through MarkCommsFault, so they never downgrade Faulted. Refs #739 Claude-Session: https://claude.ai/code/session_01Ub9hGmYLQvn9XETzw7CMsT
2026-10-22 14:07:03 -04:00
parent ecdd6dbecb
commit 4083b4aada
3 changed files with 175 additions and 13 deletions
@@ -42,6 +42,10 @@ public sealed class TwinCATDriver : IDriver, IReadable, IWritable, ITagDiscovery
    // so concurrent bit-writers to the same word must serialise or they lose each other's
    // updates. Keyed by device + parent symbol. (Cannot guard against the PLC program writing
    // the word between our read and write — inherent to RMW.)
+    // References that already logged their bad-read Warning in the current bad episode (#739 P10).
+    // Removed when the tag reads Good; cleared on (re-)initialise and shutdown.
+    private readonly ConcurrentDictionary<string, byte> _warnedRefs = new(StringComparer.Ordinal);
+
    private readonly ConcurrentDictionary<string, SemaphoreSlim> _bitRmwLocks =
        new(StringComparer.OrdinalIgnoreCase);

@@ -117,6 +121,7 @@ public sealed class TwinCATDriver : IDriver, IReadable, IWritable, ITagDiscovery
        // allows it, and a reconnect retry can overlap a running attempt). Release the previous device states' probe loops + clients before
        // the overwrite below. Deliberately NOT ShutdownAsync: that also drops _poll and the subscriptions.
        await ReleaseDeviceStatesAsync().ConfigureAwait(false);
+        _warnedRefs.Clear();
        _health = new DriverHealth(DriverState.Initializing, null, null);
        try
        {
@@ -335,7 +340,7 @@ public sealed class TwinCATDriver : IDriver, IReadable, IWritable, ITagDiscovery
        catch (OperationCanceledException) { throw; }
        catch (Exception ex)
        {
-            _health = new DriverHealth(DriverState.Degraded, _health.LastSuccessfulRead, ex.Message);
+            MarkCommsFault(ex.Message);
            return new DataValueSnapshot(null, TwinCATStatusMapper.BadCommunicationError, null, now);
        }
    }
@@ -346,25 +351,53 @@ public sealed class TwinCATDriver : IDriver, IReadable, IWritable, ITagDiscovery
    {
        if (status == TwinCATStatusMapper.Good)
        {
+            _warnedRefs.TryRemove(reference, out _); // a later failure is a new episode and warns again
            RecordDeviceAnswered(now, force: true);
            return new DataValueSnapshot(value, status, now, now);
        }

-        if (status == TwinCATStatusMapper.BadTypeMismatch)
-            _logger.LogWarning(
-                "TwinCAT driver '{DriverInstanceId}' refused '{Reference}': declared {DataType} " +
-                "cannot decode the PLC symbol '{Symbol}' (string/numeric kind mismatch, array element type " +
-                "or length mismatch, or a reference/container)",
-                _driverInstanceId, reference, def.DataType, symbolName);
+        // Once per tag per bad episode: a Warning every poll for every bad tag (50 typo'd symbols on a
+        // 500 ms poll = 100 Warnings/s) buried everything else in the log.
+        if (_warnedRefs.TryAdd(reference, 0))
+        {
+            if (status == TwinCATStatusMapper.BadTypeMismatch)
+                _logger.LogWarning(
+                    "TwinCAT driver '{DriverInstanceId}' refused '{Reference}': declared {DataType} " +
+                    "cannot decode the PLC symbol '{Symbol}' (string/numeric kind mismatch, array element type " +
+                    "or length mismatch, or a reference/container); logged once until the tag reads Good",
+                    _driverInstanceId, reference, def.DataType, symbolName);
+            else
+                _logger.LogWarning(
+                    "TwinCAT driver '{DriverInstanceId}' ADS read error 0x{Status:X8} for '{Reference}'; " +
+                    "logged once until the tag reads Good",
+                    _driverInstanceId, status, reference);
+        }
+
+        if (IsCommsStatus(status))
+            MarkCommsFault($"ADS status {status:X8} reading {reference}");
        else
-            _logger.LogWarning(
-                "TwinCAT driver '{DriverInstanceId}' ADS read error 0x{Status:X8} for '{Reference}'",
-                _driverInstanceId, status, reference);
-        _health = new DriverHealth(DriverState.Degraded, _health.LastSuccessfulRead,
-            $"ADS status {status:X8} reading {reference}");
+            RecordDeviceAnsweredKeepState(now); // a refusal: the device answered — no state change
        return new DataValueSnapshot(value, status, now, now);
    }

+    /// <summary>
+    ///     True for a status that means the request did not get a device answer (router / transport /
+    ///     timeout). Every other non-Good status is the device refusing this one tag (symbol not found, type
+    ///     mismatch, PLC not running, access denied): per-tag Bad with no health write.
+    /// </summary>
+    /// <param name="status">The mapped OPC UA status.</param>
+    /// <returns>True for a comms-class status.</returns>
+    internal static bool IsCommsStatus(uint status) =>
+        status is TwinCATStatusMapper.BadCommunicationError or TwinCATStatusMapper.BadTimeout;
+
+    /// <summary>Advances <c>LastSuccessfulRead</c> without changing the state (the device answered with a refusal).</summary>
+    private void RecordDeviceAnsweredKeepState(DateTime now)
+    {
+        var current = _health;
+        if (current.State is DriverState.Faulted or DriverState.Unknown or DriverState.Initializing) return;
+        _health = current with { LastSuccessfulRead = now };
+    }
+
    /// <summary>
    ///     Reads one device's gathered tags as ADS sum-reads of at most <c>SumReadMaxItems</c> symbols each.
    ///     A target that refuses the sum command flips <see cref="DeviceState.SumReadUnsupported"/> and the
@@ -430,7 +463,7 @@ public sealed class TwinCATDriver : IDriver, IReadable, IWritable, ITagDiscovery
            {
                foreach (var e in chunk)
                    results[e.Index] = new DataValueSnapshot(null, TwinCATStatusMapper.BadCommunicationError, null, now);
-                _health = new DriverHealth(DriverState.Degraded, _health.LastSuccessfulRead, ex.Message);
+                MarkCommsFault(ex.Message);
                // Once per device: the health message is overwritten by the next good read in the same poll, so
                // without this a sum-read path failing on every poll left no trace (hw2 live gate, 2026-10-08).
                if (connected && !device.SumChunkFailureWarned)
@@ -0,0 +1,26 @@
+using Microsoft.Extensions.Logging;
+using ZB.MOM.WW.OtOpcUa.Driver.TwinCAT;
+
+namespace ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests;
+
+/// <summary>Collects the driver's Warning-level messages (thread-safe) for once-per-X assertions.</summary>
+internal sealed class TwinCATCapturingLogger : ILogger<TwinCATDriver>
+{
+    private readonly List<string> _warnings = [];
+
+    /// <summary>Gets a snapshot of the formatted Warning messages logged so far.</summary>
+    public IReadOnlyList<string> Warnings { get { lock (_warnings) return [.. _warnings]; } }
+
+    /// <inheritdoc />
+    public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
+
+    /// <inheritdoc />
+    public bool IsEnabled(LogLevel logLevel) => true;
+
+    /// <inheritdoc />
+    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));
+    }
+}
@@ -0,0 +1,103 @@
+using Shouldly;
+using Xunit;
+using ZB.MOM.WW.OtOpcUa.Core.Abstractions;
+using ZB.MOM.WW.OtOpcUa.Driver.TwinCAT;
+
+namespace ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests;
+
+/// <summary>
+///     #739 P10: a bad tag warns ONCE (not once per poll — 50 typo'd symbols on a 500 ms poll used to be 100
+///     Warnings/s forever), re-arms when it reads Good, and a device refusal leaves driver health alone while a
+///     comms-class status degrades.
+/// </summary>
+[Trait("Category", "Unit")]
+public sealed class TwinCATReadWarningTests
+{
+    private const string Host = "ads://5.23.91.23.1.1:851";
+
+    private static (TwinCATDriver drv, FakeTwinCATClient fake, TwinCATCapturingLogger log) NewDriver()
+    {
+        var fake = new FakeTwinCATClient();
+        var log = new TwinCATCapturingLogger();
+        var drv = new TwinCATDriver(new TwinCATDriverOptions
+        {
+            Devices = [new TwinCATDeviceOptions(Host)],
+            RawTags = TwinCATRawTags.Entries(
+            [
+                new TwinCATTagDefinition("Typo", Host, "MAIN.Typo", TwinCATDataType.DInt),
+                new TwinCATTagDefinition("Other", Host, "MAIN.Other", TwinCATDataType.DInt),
+            ]),
+            Probe = new TwinCATProbeOptions { Enabled = false },
+        }, "drv-1", new FakeTwinCATClientFactory { Customise = () => fake }, log);
+        return (drv, fake, log);
+    }
+
+    private static int WarningsFor(TwinCATCapturingLogger log, string reference) =>
+        log.Warnings.Count(w => w.Contains($"'{reference}'", StringComparison.Ordinal));
+
+    /// <summary>Repeated bad reads of one tag log one Warning; a second bad tag gets its own (positive control).</summary>
+    [Fact]
+    public async Task A_bad_tag_warns_once_across_polls_and_rearms_after_Good()
+    {
+        var (drv, fake, log) = NewDriver();
+        await drv.InitializeAsync("{}", TestContext.Current.CancellationToken);
+        fake.ReadStatuses["MAIN.Typo"] = TwinCATStatusMapper.BadNodeIdUnknown;
+
+        for (var i = 0; i < 5; i++)
+            (await drv.ReadAsync(["Typo"], TestContext.Current.CancellationToken))
+                .Single().StatusCode.ShouldBe(TwinCATStatusMapper.BadNodeIdUnknown);
+        WarningsFor(log, "Typo").ShouldBe(1);
+
+        fake.ReadStatuses["MAIN.Other"] = TwinCATStatusMapper.BadNodeIdUnknown;
+        _ = await drv.ReadAsync(["Other"], TestContext.Current.CancellationToken);
+        WarningsFor(log, "Other").ShouldBe(1);
+
+        // Fixed, then broken again: a new episode warns again.
+        fake.ReadStatuses.Remove("MAIN.Typo");
+        _ = await drv.ReadAsync(["Typo"], TestContext.Current.CancellationToken);
+        fake.ReadStatuses["MAIN.Typo"] = TwinCATStatusMapper.BadNodeIdUnknown;
+        _ = await drv.ReadAsync(["Typo"], TestContext.Current.CancellationToken);
+        _ = await drv.ReadAsync(["Typo"], TestContext.Current.CancellationToken);
+        WarningsFor(log, "Typo").ShouldBe(2);
+    }
+
+    /// <summary>A re-initialise re-arms the warning.</summary>
+    [Fact]
+    public async Task A_reinitialise_rearms_the_warning()
+    {
+        var (drv, fake, log) = NewDriver();
+        await drv.InitializeAsync("{}", TestContext.Current.CancellationToken);
+        fake.ReadStatuses["MAIN.Typo"] = TwinCATStatusMapper.BadNodeIdUnknown;
+        _ = await drv.ReadAsync(["Typo"], TestContext.Current.CancellationToken);
+
+        await drv.InitializeAsync("{}", TestContext.Current.CancellationToken);
+        _ = await drv.ReadAsync(["Typo"], TestContext.Current.CancellationToken);
+
+        WarningsFor(log, "Typo").ShouldBe(2);
+    }
+
+    /// <summary>
+    ///     A status proving the device answered (symbol not found) keeps the driver Healthy and advances the
+    ///     stamp; a comms-class status (timeout) degrades with the stamp preserved.
+    /// </summary>
+    [Fact]
+    public async Task A_refusal_status_does_not_degrade_but_a_comms_status_does()
+    {
+        var (drv, fake, _) = NewDriver();
+        await drv.InitializeAsync("{}", TestContext.Current.CancellationToken);
+        var initStamp = drv.GetHealth().LastSuccessfulRead!.Value;
+        fake.ReadStatuses["MAIN.Typo"] = TwinCATStatusMapper.BadNodeIdUnknown;
+        await Task.Delay(300, TestContext.Current.CancellationToken);
+
+        _ = await drv.ReadAsync(["Typo"], TestContext.Current.CancellationToken);
+        var afterRefusal = drv.GetHealth();
+        afterRefusal.State.ShouldBe(DriverState.Healthy);
+        afterRefusal.LastSuccessfulRead!.Value.ShouldBeGreaterThan(initStamp);
+
+        fake.ReadStatuses["MAIN.Other"] = TwinCATStatusMapper.BadTimeout;
+        _ = await drv.ReadAsync(["Other"], TestContext.Current.CancellationToken);
+        var afterTimeout = drv.GetHealth();
+        afterTimeout.State.ShouldBe(DriverState.Degraded);
+        afterTimeout.LastSuccessfulRead.ShouldBe(afterRefusal.LastSuccessfulRead);
+    }
+}