dohertj2/lmxopcua
1
0
Fork 0
Code Issues 1 Pull Requests 2 Actions Packages Projects Releases Wiki Activity

Task #153 — ModbusDriver: inject ILogger so prohibition events reach a sink

Browse Source 
#152 left a hook for structured logging when an auto-prohibition first
fires; this commit completes the wiring.

Changes:
- ModbusDriver constructor takes an optional ILogger<ModbusDriver> (defaults
  to NullLogger). Existing standalone callers stay compile-clean.
- RecordAutoProhibition logs LogWarning on first-fire only (re-fires of the
  same range stay quiet via the existing isNew de-dupe). Format includes
  DriverInstanceId, UnitId, Region, Start, End, Span — log aggregators can
  filter / count by any field.
- New LogProhibitionCleared helper called by both StraightReprobeAsync (when
  the re-probe succeeds on a single-register range) and BisectAndReprobeAsync
  (per-half clearing + a single combined line when both halves succeed).
- ModbusDriverFactoryExtensions.Register accepts an optional ILoggerFactory.
  Captured at registration time and used in the factory closure to construct
  a per-driver logger. Server bootstrap code that already has an ILoggerFactory
  in DI threads it through with a single argument addition; old call sites
  (Register(registry)) keep working with a null logger.

Tests (2 new ModbusLoggerInjectionTests):
- First_Failure_Emits_Single_Warning_Subsequent_Refire_Stays_Quiet — pins
  the de-dupe behaviour. First scan logs one warning with the expected
  structured fields; second scan with the same prohibition stays silent.
- Reprobe_Clearing_Prohibition_Emits_Information_Log — protected register
  unlocked between record and re-probe; re-probe success emits an info log
  containing "cleared".

CapturingLogger test harness is purpose-built (xUnit doesn't ship a logger
mock by default and adding Moq is overkill for two tests).

240 + 2 = 242 unit tests green.
This commit is contained in:
Joseph Doherty
2026-04-25 01:26:20 -04:00
parent b8df230eb8
commit 8004394892
3 changed files with 148 additions and 10 deletions
Download Patch File Download Diff File Expand all files Collapse all files

39
src/ZB.MOM.WW.OtOpcUa.Driver.Modbus/ModbusDriver.cs
View File

@@ -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<string, ModbusTagDefinition> _tagsByName = new(StringComparer.OrdinalIgnoreCase);
private readonly ILogger<ModbusDriver> _logger;
public ModbusDriver(ModbusDriverOptions options, string driverInstanceId,
Func<ModbusDriverOptions, IModbusTransport>? transportFactory = null)
Func<ModbusDriverOptions, IModbusTransport>? transportFactory = null,
ILogger<ModbusDriver>? logger = null)
{
ArgumentNullException.ThrowIfNull(options);
_options = options;
_driverInstanceId = driverInstanceId;
_logger = logger ?? NullLogger<ModbusDriver>.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);
}
/// <summary>
/// #153 — info log when a re-probe clears a prohibition. Operators see recovery
/// events without having to poll <see cref="GetAutoProhibitedRanges"/>.
/// </summary>
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);
/// <summary>
/// #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<bool> ProbeFailsAsync(IModbusTransport transport, byte fc, byte unit,

20
src/ZB.MOM.WW.OtOpcUa.Driver.Modbus/ModbusDriverFactoryExtensions.cs
View File

@@ -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)
/// <summary>
/// Register the Modbus factory with the driver registry. The optional
/// <paramref name="loggerFactory"/> is captured at registration time and used to
/// construct an <see cref="ILogger{ModbusDriver}"/> per driver instance — without it,
/// the driver runs with the null logger (existing tests and standalone callers stay
/// unchanged).
/// </summary>
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<ModbusDriver>());
}
private static ModbusTagDefinition BuildTag(ModbusTagDto t, string driverInstanceId)

99
tests/ZB.MOM.WW.OtOpcUa.Driver.Modbus.Tests/ModbusLoggerInjectionTests.cs Normal file
View File

@@ -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;
/// <summary>
/// #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.
/// </summary>
[Trait("Category", "Unit")]
public sealed class ModbusLoggerInjectionTests
{
private sealed class CapturingLogger : ILogger<ModbusDriver>
{
public readonly List<(LogLevel Level, string Message)> Entries = new();
public IDisposable BeginScope<TState>(TState state) where TState : notnull => NullScope.Instance;
public bool IsEnabled(LogLevel logLevel) => true;
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> 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<byte[]> 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<byte[]>(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);
}
}