diff --git a/src/ZB.MOM.WW.OtOpcUa.Driver.Modbus/ModbusDriver.cs b/src/ZB.MOM.WW.OtOpcUa.Driver.Modbus/ModbusDriver.cs index 3a51869..ba3c370 100644 --- a/src/ZB.MOM.WW.OtOpcUa.Driver.Modbus/ModbusDriver.cs +++ b/src/ZB.MOM.WW.OtOpcUa.Driver.Modbus/ModbusDriver.cs @@ -1,5 +1,7 @@ using System.Buffers.Binary; using System.Text.Json; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; using ZB.MOM.WW.OtOpcUa.Core.Abstractions; namespace ZB.MOM.WW.OtOpcUa.Driver.Modbus; @@ -57,12 +59,16 @@ public sealed class ModbusDriver private DriverHealth _health = new(DriverState.Unknown, null, null); private readonly Dictionary _tagsByName = new(StringComparer.OrdinalIgnoreCase); + private readonly ILogger _logger; + public ModbusDriver(ModbusDriverOptions options, string driverInstanceId, - Func? transportFactory = null) + Func? transportFactory = null, + ILogger? logger = null) { ArgumentNullException.ThrowIfNull(options); _options = options; _driverInstanceId = driverInstanceId; + _logger = logger ?? NullLogger.Instance; _transportFactory = transportFactory ?? (o => new ModbusTcpTransport( o.Host, o.Port, o.Timeout, o.AutoReconnect, @@ -461,14 +467,20 @@ public sealed class ModbusDriver // flooding when a per-tick exception keeps the same range bad. The state visible via // GetAutoProhibitedRanges shows operators the long-tail picture. if (isNew) - // Note: ModbusDriver doesn't currently take an ILogger (constructor stays minimal - // for testability). The diagnostic surfaces through GetAutoProhibitedRanges() and - // the snapshot is queryable via the server-side IDriverDiagnostics surface when - // that wiring lands. Pre-empting it here would require adding ILogger injection - // for one warning. - _ = (unit, region, start, end); + _logger.LogWarning( + "Modbus coalesced read failed; auto-prohibited range recorded. Driver={DriverInstanceId} Unit={Unit} Region={Region} Start={Start} End={End} Span={Span}", + _driverInstanceId, unit, region, start, end, end - start + 1); } + /// + /// #153 — info log when a re-probe clears a prohibition. Operators see recovery + /// events without having to poll . + /// + private void LogProhibitionCleared(byte unit, ModbusRegion region, ushort start, ushort end) => + _logger.LogInformation( + "Modbus auto-prohibition cleared by re-probe. Driver={DriverInstanceId} Unit={Unit} Region={Region} Start={Start} End={End}", + _driverInstanceId, unit, region, start, end); + /// /// #152 — operator-visible snapshot of every range the planner has learned to read /// individually. Exposed through the driver-diagnostics surface; consumers (Admin UI, @@ -546,6 +558,7 @@ public sealed class ModbusDriver { _ = await ReadRegisterBlockAsync(transport, key.Unit, fc, key.Start, qty, ct).ConfigureAwait(false); lock (_autoProhibitedLock) _autoProhibited.Remove(key); + LogProhibitionCleared(key.Unit, key.Region, key.Start, key.End); } catch (OperationCanceledException) when (ct.IsCancellationRequested) { throw; } catch @@ -593,6 +606,18 @@ public sealed class ModbusDriver // Both halves succeeded → entry is just removed. The parent prohibition is gone // and the next normal scan can re-coalesce across the whole original range. } + + // #153 — log per-half outcome OUTSIDE the lock (logger calls can be expensive). + // Both halves clear → emit a single combined "fully cleared" line. + if (!leftFailed && !rightFailed) + LogProhibitionCleared(key.Unit, key.Region, key.Start, key.End); + else + { + if (!leftFailed) + LogProhibitionCleared(key.Unit, key.Region, key.Start, leftEnd); + if (!rightFailed) + LogProhibitionCleared(key.Unit, key.Region, rightStart, key.End); + } } private async Task ProbeFailsAsync(IModbusTransport transport, byte fc, byte unit, diff --git a/src/ZB.MOM.WW.OtOpcUa.Driver.Modbus/ModbusDriverFactoryExtensions.cs b/src/ZB.MOM.WW.OtOpcUa.Driver.Modbus/ModbusDriverFactoryExtensions.cs index 5969597..ae1fa41 100644 --- a/src/ZB.MOM.WW.OtOpcUa.Driver.Modbus/ModbusDriverFactoryExtensions.cs +++ b/src/ZB.MOM.WW.OtOpcUa.Driver.Modbus/ModbusDriverFactoryExtensions.cs @@ -1,5 +1,6 @@ using System.Text.Json; using System.Text.Json.Serialization; +using Microsoft.Extensions.Logging; using ZB.MOM.WW.OtOpcUa.Core.Hosting; namespace ZB.MOM.WW.OtOpcUa.Driver.Modbus; @@ -14,13 +15,23 @@ public static class ModbusDriverFactoryExtensions { public const string DriverTypeName = "Modbus"; - public static void Register(DriverFactoryRegistry registry) + /// + /// Register the Modbus factory with the driver registry. The optional + /// is captured at registration time and used to + /// construct an per driver instance — without it, + /// the driver runs with the null logger (existing tests and standalone callers stay + /// unchanged). + /// + public static void Register(DriverFactoryRegistry registry, ILoggerFactory? loggerFactory = null) { ArgumentNullException.ThrowIfNull(registry); - registry.Register(DriverTypeName, CreateInstance); + registry.Register(DriverTypeName, (id, json) => CreateInstance(id, json, loggerFactory)); } internal static ModbusDriver CreateInstance(string driverInstanceId, string driverConfigJson) + => CreateInstance(driverInstanceId, driverConfigJson, loggerFactory: null); + + internal static ModbusDriver CreateInstance(string driverInstanceId, string driverConfigJson, ILoggerFactory? loggerFactory) { ArgumentException.ThrowIfNullOrWhiteSpace(driverInstanceId); ArgumentException.ThrowIfNullOrWhiteSpace(driverConfigJson); @@ -83,7 +94,10 @@ public static class ModbusDriverFactoryExtensions }, }; - return new ModbusDriver(options, driverInstanceId); + return new ModbusDriver( + options, driverInstanceId, + transportFactory: null, + logger: loggerFactory?.CreateLogger()); } private static ModbusTagDefinition BuildTag(ModbusTagDto t, string driverInstanceId) diff --git a/tests/ZB.MOM.WW.OtOpcUa.Driver.Modbus.Tests/ModbusLoggerInjectionTests.cs b/tests/ZB.MOM.WW.OtOpcUa.Driver.Modbus.Tests/ModbusLoggerInjectionTests.cs new file mode 100644 index 0000000..0f3dff9 --- /dev/null +++ b/tests/ZB.MOM.WW.OtOpcUa.Driver.Modbus.Tests/ModbusLoggerInjectionTests.cs @@ -0,0 +1,99 @@ +using Microsoft.Extensions.Logging; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Core.Abstractions; + +namespace ZB.MOM.WW.OtOpcUa.Driver.Modbus.Tests; + +/// +/// #153 — confirm ModbusDriver emits structured warnings on first-fire of an +/// auto-prohibition and informational logs on re-probe clearance. The logger plumbing +/// extends through ModbusDriverFactoryExtensions.Register so production server-bootstrap +/// paths get the logger automatically; here we exercise the constructor injection +/// directly. +/// +[Trait("Category", "Unit")] +public sealed class ModbusLoggerInjectionTests +{ + private sealed class CapturingLogger : ILogger + { + public readonly List<(LogLevel Level, string Message)> Entries = new(); + public IDisposable BeginScope(TState state) where TState : notnull => NullScope.Instance; + public bool IsEnabled(LogLevel logLevel) => true; + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) + => Entries.Add((logLevel, formatter(state, exception))); + private sealed class NullScope : IDisposable { public static readonly NullScope Instance = new(); public void Dispose() { } } + } + + private sealed class ProtectedHoleTransport : IModbusTransport + { + public ushort ProtectedAddress { get; set; } = 102; + public Task ConnectAsync(CancellationToken ct) => Task.CompletedTask; + public Task SendAsync(byte unitId, byte[] pdu, CancellationToken ct) + { + var addr = (ushort)((pdu[1] << 8) | pdu[2]); + var qty = (ushort)((pdu[3] << 8) | pdu[4]); + if (pdu[0] is 0x03 && ProtectedAddress >= addr && ProtectedAddress < addr + qty) + return Task.FromException(new ModbusException(0x03, 0x02, "IllegalDataAddress")); + var resp = new byte[2 + qty * 2]; + resp[0] = pdu[0]; resp[1] = (byte)(qty * 2); + return Task.FromResult(resp); + } + public ValueTask DisposeAsync() => ValueTask.CompletedTask; + } + + [Fact] + public async Task First_Failure_Emits_Single_Warning_Subsequent_Refire_Stays_Quiet() + { + var fake = new ProtectedHoleTransport(); + var logger = new CapturingLogger(); + var t100 = new ModbusTagDefinition("T100", ModbusRegion.HoldingRegisters, 100, ModbusDataType.Int16); + var t102 = new ModbusTagDefinition("T102", ModbusRegion.HoldingRegisters, 102, ModbusDataType.Int16); + var t104 = new ModbusTagDefinition("T104", ModbusRegion.HoldingRegisters, 104, ModbusDataType.Int16); + var opts = new ModbusDriverOptions { Host = "f", Tags = [t100, t102, t104], MaxReadGap = 5, + Probe = new ModbusProbeOptions { Enabled = false } }; + var drv = new ModbusDriver(opts, "drv-logged", _ => fake, logger: logger); + await drv.InitializeAsync("{}", CancellationToken.None); + + // Scan 1 — coalesced read fails. Expect exactly one warning. + await drv.ReadAsync(["T100", "T102", "T104"], CancellationToken.None); + var warnings = logger.Entries.Where(e => e.Level == LogLevel.Warning).ToList(); + warnings.Count.ShouldBe(1); + warnings[0].Message.ShouldContain("drv-logged"); + warnings[0].Message.ShouldContain("Start=100"); + warnings[0].Message.ShouldContain("End=104"); + + // Scan 2 — same coalesced range still fails. Re-fire is suppressed (planner sees + // the prohibition and skips the merge; even if it didn't, the de-dupe in + // RecordAutoProhibition would suppress). + await drv.ReadAsync(["T100", "T102", "T104"], CancellationToken.None); + logger.Entries.Count(e => e.Level == LogLevel.Warning).ShouldBe(1, "re-fire of same range stays silent"); + + await drv.ShutdownAsync(CancellationToken.None); + } + + [Fact] + public async Task Reprobe_Clearing_Prohibition_Emits_Information_Log() + { + var fake = new ProtectedHoleTransport(); + var logger = new CapturingLogger(); + var t100 = new ModbusTagDefinition("T100", ModbusRegion.HoldingRegisters, 100, ModbusDataType.Int16); + var t102 = new ModbusTagDefinition("T102", ModbusRegion.HoldingRegisters, 102, ModbusDataType.Int16); + var t104 = new ModbusTagDefinition("T104", ModbusRegion.HoldingRegisters, 104, ModbusDataType.Int16); + var opts = new ModbusDriverOptions { Host = "f", Tags = [t100, t102, t104], MaxReadGap = 5, + AutoProhibitReprobeInterval = TimeSpan.FromHours(1), // long interval — we drive it manually + Probe = new ModbusProbeOptions { Enabled = false } }; + var drv = new ModbusDriver(opts, "drv-logged", _ => fake, logger: logger); + await drv.InitializeAsync("{}", CancellationToken.None); + + await drv.ReadAsync(["T100", "T102", "T104"], CancellationToken.None); + // Operator unlocks the protected register; re-probe should clear + log. + fake.ProtectedAddress = ushort.MaxValue; + await drv.RunReprobeOnceForTestAsync(CancellationToken.None); + + var infoLogs = logger.Entries.Where(e => e.Level == LogLevel.Information && e.Message.Contains("cleared")).ToList(); + infoLogs.Count.ShouldBeGreaterThanOrEqualTo(1, "re-probe success must emit a 'cleared' info log"); + + await drv.ShutdownAsync(CancellationToken.None); + } +}