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 f1c87ebb..7c95a8f0 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT/TwinCATDriver.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT/TwinCATDriver.cs @@ -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 _warnedRefs = new(StringComparer.Ordinal); + private readonly ConcurrentDictionary _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); } + /// + /// 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. + /// + /// The mapped OPC UA status. + /// True for a comms-class status. + internal static bool IsCommsStatus(uint status) => + status is TwinCATStatusMapper.BadCommunicationError or TwinCATStatusMapper.BadTimeout; + + /// Advances LastSuccessfulRead without changing the state (the device answered with a refusal). + 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 }; + } + /// /// Reads one device's gathered tags as ADS sum-reads of at most SumReadMaxItems symbols each. /// A target that refuses the sum command flips 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) 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 new file mode 100644 index 00000000..9df5d1b8 --- /dev/null +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATCapturingLogger.cs @@ -0,0 +1,26 @@ +using Microsoft.Extensions.Logging; +using ZB.MOM.WW.OtOpcUa.Driver.TwinCAT; + +namespace ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests; + +/// Collects the driver's Warning-level messages (thread-safe) for once-per-X assertions. +internal sealed class TwinCATCapturingLogger : ILogger +{ + private readonly List _warnings = []; + + /// Gets a snapshot of the formatted Warning messages logged so far. + public IReadOnlyList Warnings { get { lock (_warnings) return [.. _warnings]; } } + + /// + public IDisposable? BeginScope(TState state) where TState : notnull => null; + + /// + public bool IsEnabled(LogLevel logLevel) => true; + + /// + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, + Func formatter) + { + if (logLevel == LogLevel.Warning) lock (_warnings) _warnings.Add(formatter(state, exception)); + } +} diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATReadWarningTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATReadWarningTests.cs new file mode 100644 index 00000000..dd669164 --- /dev/null +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATReadWarningTests.cs @@ -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; + +/// +/// #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. +/// +[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)); + + /// Repeated bad reads of one tag log one Warning; a second bad tag gets its own (positive control). + [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); + } + + /// A re-initialise re-arms the warning. + [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); + } + + /// + /// 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. + /// + [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); + } +}