diff --git a/code-reviews/Driver.FOCAS/findings.md b/code-reviews/Driver.FOCAS/findings.md index e89f2f0..fbb4ccc 100644 --- a/code-reviews/Driver.FOCAS/findings.md +++ b/code-reviews/Driver.FOCAS/findings.md @@ -7,7 +7,7 @@ | Review date | 2026-05-22 | | Commit reviewed | `76d35d1` | | Status | Reviewed | -| Open findings | 5 | +| Open findings | 0 | ## Checklist coverage @@ -200,7 +200,7 @@ stale object. | Severity | Low | | Category | Error handling & resilience | | Location | `FocasDriver.cs:140-148`, `FocasDriver.cs:478-484`, `FocasDriver.cs:529-533`, `FocasAlarmProjection.cs:61-63` | -| Status | Open | +| Status | Resolved | **Description:** Numerous `try { ... } catch {}` blocks swallow every exception with no logging - `ShutdownAsync` (CTS cancel/dispose), `RecycleLoopAsync` (`DisposeClient`), @@ -215,7 +215,7 @@ solely on `GetHealth()`. poll/probe/recycle loops at `Debug`/`Warning`. Pass a logger into `FocasWireClient` so the per-response `Debug` entries it already emits are actually captured. -**Resolution:** _(open)_ +**Resolution:** Resolved 2026-05-23 — `FocasDriver` now takes an optional `ILogger` (defaulting to `NullLogger`) and every previously-empty `catch { }` in `ShutdownAsync` / `ProbeLoopAsync` / `FixedTreeLoopAsync` / `RecycleLoopAsync` / `ReadActiveAlarmsAcrossDevicesAsync` now logs at `Debug` with the host address + context. `FocasAlarmProjection` also accepts an optional `ILogger` (forwarded by the driver) so its unsubscribe / dispose / per-tick poll swallows log. `WireFocasClientFactory` gained a logger-accepting overload that threads through to `FocasWireClient`, so its per-response `Debug` entries actually reach the host pipeline. ### Driver.FOCAS-008 @@ -224,7 +224,7 @@ the per-response `Debug` entries it already emits are actually captured. | Severity | Low | | Category | Performance & resource management | | Location | `FocasDriver.cs:201`, `FocasDriver.cs:253` | -| Status | Open | +| Status | Resolved | **Description:** `ReadAsync` and `WriteAsync` call `FocasAddress.TryParse(def.Address)` on every operation, even though `InitializeAsync` already parsed and validated every @@ -235,7 +235,7 @@ re-parses and allocates a `FocasAddress` record per tag per tick unnecessarily. parsed `FocasAddress` on `FocasTagDefinition` (or in a side dictionary), so the runtime read/write paths use the cached value. -**Resolution:** _(open)_ +**Resolution:** Resolved 2026-05-23 — `FocasDriver` now holds a `_parsedAddressesByTagName` side dictionary populated at `InitializeAsync`. `ReadAsync` and `WriteAsync` look up the cached `FocasAddress` instance; the defensive fallback `TryParse` only fires if a tag was somehow not seeded. The cache is cleared on `ShutdownAsync`. Regression test `ReadAsync_uses_cached_FocasAddress_when_tag_definition_has_a_malformed_address_after_init` (and the matching `WriteAsync` variant) asserts the same `FocasAddress` instance is reused across calls. ### Driver.FOCAS-009 @@ -244,7 +244,7 @@ read/write paths use the cached value. | Severity | Low | | Category | Design-document adherence | | Location | `FocasDriverOptions.cs:110-115`, `FocasDriver.cs:468-486`, `FocasDriverFactoryExtensions.cs:75-80` | -| Status | Open | +| Status | Resolved | **Description:** `FocasProbeOptions.Timeout` is parsed by the factory (`FocasProbeDto.TimeoutMs` to `FocasProbeOptions.Timeout`) but never consumed. @@ -257,7 +257,7 @@ until the OS TCP timeout rather than the configured `Probe.Timeout`. around the `ProbeAsync` call, or remove the dead `Timeout` field from `FocasProbeOptions` / `FocasProbeDto` if it is genuinely not intended. -**Resolution:** _(open)_ +**Resolution:** Resolved 2026-05-23 — `FocasDriver.ProbeLoopAsync` now wraps `client.ProbeAsync` in a linked `CancellationTokenSource` that fires after `Probe.Timeout` (skipped when the timeout is `<= TimeSpan.Zero`). On timeout the loop logs the cancellation at Debug and surfaces it as a failed probe, so a hung CNC socket transitions the host to `Stopped` at the configured budget instead of blocking on the OS TCP timeout. Regression test `ProbeLoop_cancels_a_slow_ProbeAsync_at_Probe_Timeout` asserts the cancellation reaches the fake `ProbeAsync` within the configured 100 ms. ### Driver.FOCAS-010 @@ -266,7 +266,7 @@ around the `ProbeAsync` call, or remove the dead `Timeout` field from | Severity | Low | | Category | Code organization & conventions | | Location | `IFocasClient.cs:210-227` (`FocasOpMode`), `FocasConstants.cs:42-78` (`FocasOperationMode`) | -| Status | Open | +| Status | Resolved | **Description:** There are two parallel operation-mode-to-text mappings with divergent labels. `FocasOpMode.ToText` (used by the driver fixed-tree `OperationMode/ModeText` @@ -278,7 +278,7 @@ inconsistent results depending on which path renders it. **Recommendation:** Consolidate to a single op-mode enum + `ToText` helper shared by both the wire layer and the driver projection, with one canonical label set. -**Resolution:** _(open)_ +**Resolution:** Resolved 2026-05-23 — `FocasOperationModeExtensions.ToText` now delegates to `FocasOpMode.ToText((short)mode)`, so the wire layer and the driver fixed-tree projection render identical labels. `FocasOpMode` keeps its existing labels (`TJOG`, `TEACH_IN_HANDLE`, `Mode{n}` fallback), which are now the single canonical surface. Regression theory `OpMode_ToText_yields_the_same_label_in_both_namespaces` cross-checks every defined code; `OpMode_ToText_fallback_label_is_consistent` covers the unknown-code path. ### Driver.FOCAS-011 @@ -287,7 +287,7 @@ both the wire layer and the driver projection, with one canonical label set. | Severity | Low | | Category | Code organization & conventions | | Location | `IFocasClient.cs:275-287` (`FocasAlarmType`), `FocasAlarmProjection.cs:149-175` | -| Status | Open | +| Status | Resolved | **Description:** `FocasAlarmType` declares its constants as `public const int`, but the only consumers - `FocasAlarmProjection.MapAlarmType(short type)` and @@ -301,7 +301,7 @@ expected by `ReadAlarmsAsync`. **Recommendation:** Declare the `FocasAlarmType` constants as `short` (or make it an `enum : short`) so the type matches the wire field width and the projection signatures. -**Resolution:** _(open)_ +**Resolution:** Resolved 2026-05-23 — every `FocasAlarmType` constant (`All`, `Parameter`, `PulseCode`, `Overtravel`, `Overheat`, `Servo`, `DataIo`, `MemoryCheck`, `MacroAlarm`) is now typed `short`, matching the wire field width on `cnc_rdalmmsg2` and the `switch (short type)` arms in `FocasAlarmProjection.MapAlarmType` / `MapSeverity`. Regression test `FocasAlarmType_constants_are_typed_short` uses reflection to guarantee the type is preserved against future drift. ### Driver.FOCAS-012 diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/FocasAlarmProjection.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/FocasAlarmProjection.cs index 8ce93ae..72af75c 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/FocasAlarmProjection.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/FocasAlarmProjection.cs @@ -1,3 +1,5 @@ +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; using ZB.MOM.WW.OtOpcUa.Core.Abstractions; namespace ZB.MOM.WW.OtOpcUa.Driver.FOCAS; @@ -21,14 +23,16 @@ internal sealed class FocasAlarmProjection : IAsyncDisposable { private readonly FocasDriver _driver; private readonly TimeSpan _pollInterval; + private readonly ILogger _logger; private readonly Dictionary _subs = new(); private readonly Lock _subsLock = new(); private long _nextId; - public FocasAlarmProjection(FocasDriver driver, TimeSpan pollInterval) + public FocasAlarmProjection(FocasDriver driver, TimeSpan pollInterval, ILogger? logger = null) { _driver = driver; _pollInterval = pollInterval; + _logger = logger ?? NullLogger.Instance; } public Task SubscribeAsync( @@ -58,8 +62,10 @@ internal sealed class FocasAlarmProjection : IAsyncDisposable { if (!_subs.Remove(h.Id, out sub)) return; } - try { sub.Cts.Cancel(); } catch { } - try { await sub.Loop.ConfigureAwait(false); } catch { } + try { sub.Cts.Cancel(); } + catch (Exception ex) { _logger.LogDebug(ex, "Cancelling alarm-subscription CTS failed"); } + try { await sub.Loop.ConfigureAwait(false); } + catch (Exception ex) { _logger.LogDebug(ex, "Awaiting alarm-subscription loop failed during unsubscribe"); } sub.Cts.Dispose(); } @@ -78,8 +84,10 @@ internal sealed class FocasAlarmProjection : IAsyncDisposable lock (_subsLock) { snap = [.. _subs.Values]; _subs.Clear(); } foreach (var sub in snap) { - try { sub.Cts.Cancel(); } catch { } - try { await sub.Loop.ConfigureAwait(false); } catch { } + try { sub.Cts.Cancel(); } + catch (Exception ex) { _logger.LogDebug(ex, "Cancelling alarm-subscription CTS during dispose failed"); } + try { await sub.Loop.ConfigureAwait(false); } + catch (Exception ex) { _logger.LogDebug(ex, "Awaiting alarm-subscription loop during dispose failed"); } sub.Cts.Dispose(); } } @@ -136,7 +144,11 @@ internal sealed class FocasAlarmProjection : IAsyncDisposable } } catch (OperationCanceledException) when (ct.IsCancellationRequested) { break; } - catch { /* per-tick failures are non-fatal — next tick retries */ } + catch (Exception ex) + { + /* per-tick failures are non-fatal — next tick retries */ + _logger.LogDebug(ex, "FOCAS alarm-projection poll tick failed"); + } try { await Task.Delay(_pollInterval, ct).ConfigureAwait(false); } catch (OperationCanceledException) { break; } diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/FocasDriver.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/FocasDriver.cs index 37a2ea2..4a29eea 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/FocasDriver.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/FocasDriver.cs @@ -1,3 +1,5 @@ +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; using ZB.MOM.WW.OtOpcUa.Core.Abstractions; namespace ZB.MOM.WW.OtOpcUa.Driver.FOCAS; @@ -22,8 +24,14 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery, private readonly string _driverInstanceId; private readonly IFocasClientFactory _clientFactory; private readonly PollGroupEngine _poll; + private readonly ILogger _logger; private readonly Dictionary _devices = new(StringComparer.OrdinalIgnoreCase); private readonly Dictionary _tagsByName = new(StringComparer.OrdinalIgnoreCase); + // Per-tag-name cache of the FocasAddress parsed once at InitializeAsync. ReadAsync / + // WriteAsync look up the pre-parsed value instead of re-parsing tag.Address on every hot + // call — resolves Driver.FOCAS-008. + private readonly Dictionary _parsedAddressesByTagName = + new(StringComparer.OrdinalIgnoreCase); private FocasAlarmProjection? _alarmProjection; // _health is read/written from multiple threads (ReadAsync, WriteAsync, ProbeLoopAsync). // Volatile.Read/Write ensures every thread sees the latest reference without a lock — the @@ -35,12 +43,14 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery, public event EventHandler? OnAlarmEvent; public FocasDriver(FocasDriverOptions options, string driverInstanceId, - IFocasClientFactory? clientFactory = null) + IFocasClientFactory? clientFactory = null, + ILogger? logger = null) { ArgumentNullException.ThrowIfNull(options); _options = options; _driverInstanceId = driverInstanceId; _clientFactory = clientFactory ?? new Wire.WireFocasClientFactory(); + _logger = logger ?? NullLogger.Instance; _poll = new PollGroupEngine( reader: ReadAsync, onChange: (handle, tagRef, snapshot) => @@ -82,6 +92,11 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery, $"FOCAS tag '{tag.Name}' ({tag.Address}) rejected by capability matrix: {reason}"); } _tagsByName[tag.Name] = tag; + // Cache the parsed FocasAddress so ReadAsync / WriteAsync don't re-parse on every + // hot-path call (Driver.FOCAS-008). The address string has already been validated + // by FocasAddress.TryParse above; reusing the parsed record avoids per-tick allocs + // on subscription pollers. + _parsedAddressesByTagName[tag.Name] = parsed; } if (_options.Probe.Enabled) @@ -105,7 +120,7 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery, } if (_options.AlarmProjection.Enabled) - _alarmProjection = new FocasAlarmProjection(this, _options.AlarmProjection.PollInterval); + _alarmProjection = new FocasAlarmProjection(this, _options.AlarmProjection.PollInterval, _logger); if (_options.FixedTree.Enabled) { @@ -143,19 +158,26 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery, } foreach (var state in _devices.Values) { - try { state.ProbeCts?.Cancel(); } catch { } + // Cancel-then-dispose can race in tight shutdown loops; swallowing is intentional + // but we now log the cause so a noisy shutdown leaves a Debug trace + // (Driver.FOCAS-007). + try { state.ProbeCts?.Cancel(); } + catch (Exception ex) { _logger.LogDebug(ex, "Cancelling probe CTS for {Host} failed", state.Options.HostAddress); } state.ProbeCts?.Dispose(); state.ProbeCts = null; - try { state.RecycleCts?.Cancel(); } catch { } + try { state.RecycleCts?.Cancel(); } + catch (Exception ex) { _logger.LogDebug(ex, "Cancelling recycle CTS for {Host} failed", state.Options.HostAddress); } state.RecycleCts?.Dispose(); state.RecycleCts = null; - try { state.FixedTreeCts?.Cancel(); } catch { } + try { state.FixedTreeCts?.Cancel(); } + catch (Exception ex) { _logger.LogDebug(ex, "Cancelling fixed-tree CTS for {Host} failed", state.Options.HostAddress); } state.FixedTreeCts?.Dispose(); state.FixedTreeCts = null; state.DisposeClient(); } _devices.Clear(); _tagsByName.Clear(); + _parsedAddressesByTagName.Clear(); Volatile.Write(ref _health, new DriverHealth(DriverState.Unknown, Volatile.Read(ref _health).LastSuccessfulRead, null)); } @@ -206,8 +228,14 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery, try { var client = await EnsureConnectedAsync(device, cancellationToken).ConfigureAwait(false); - var parsed = FocasAddress.TryParse(def.Address) - ?? throw new InvalidOperationException($"FOCAS tag '{def.Name}' has malformed Address '{def.Address}'."); + // Parsed at InitializeAsync — defensive fallback re-parse only if the tag was + // somehow not seeded (shouldn't happen, but keeps the call total). + if (!_parsedAddressesByTagName.TryGetValue(def.Name, out var parsed)) + { + parsed = FocasAddress.TryParse(def.Address) + ?? throw new InvalidOperationException( + $"FOCAS tag '{def.Name}' has malformed Address '{def.Address}'."); + } var (value, status) = await client.ReadAsync(parsed, def.DataType, cancellationToken).ConfigureAwait(false); results[i] = new DataValueSnapshot(value, status, now, now); @@ -260,8 +288,12 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery, try { var client = await EnsureConnectedAsync(device, cancellationToken).ConfigureAwait(false); - var parsed = FocasAddress.TryParse(def.Address) - ?? throw new InvalidOperationException($"FOCAS tag '{def.Name}' has malformed Address '{def.Address}'."); + if (!_parsedAddressesByTagName.TryGetValue(def.Name, out var parsed)) + { + parsed = FocasAddress.TryParse(def.Address) + ?? throw new InvalidOperationException( + $"FOCAS tag '{def.Name}' has malformed Address '{def.Address}'."); + } var status = await client.WriteAsync(parsed, def.DataType, w.Value, cancellationToken).ConfigureAwait(false); results[i] = new WriteResult(status); } @@ -489,10 +521,35 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery, try { var client = await EnsureConnectedAsync(state, ct).ConfigureAwait(false); - success = await client.ProbeAsync(ct).ConfigureAwait(false); + // Apply Probe.Timeout so a hung CNC socket gets cancelled at the configured + // budget rather than blocking until the OS TCP timeout (Driver.FOCAS-009). + // TimeSpan.Zero / negative means "no per-probe timeout" — fall back to the loop + // cancellation token unmodified. + var probeTimeout = _options.Probe.Timeout; + if (probeTimeout > TimeSpan.Zero) + { + using var linked = CancellationTokenSource.CreateLinkedTokenSource(ct); + linked.CancelAfter(probeTimeout); + success = await client.ProbeAsync(linked.Token).ConfigureAwait(false); + } + else + { + success = await client.ProbeAsync(ct).ConfigureAwait(false); + } } catch (OperationCanceledException) when (ct.IsCancellationRequested) { break; } - catch { /* connect-failure path already disposed + cleared the client */ } + catch (OperationCanceledException ex) + { + // Per-probe timeout fired — the loop is still alive. Treat as a failed probe so + // the host state transitions to Stopped, and log so silent timeouts are visible. + _logger.LogDebug(ex, "FOCAS probe timed out for {Host} after {Timeout}", + state.Options.HostAddress, _options.Probe.Timeout); + } + catch (Exception ex) + { + /* connect-failure path already disposed + cleared the client */ + _logger.LogDebug(ex, "FOCAS probe failed for {Host}", state.Options.HostAddress); + } TransitionDeviceState(state, success ? HostState.Running : HostState.Stopped); @@ -542,8 +599,10 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery, sys, [.. axes], [.. spindles], [.. spindleMaxRpms], caps); } catch (OperationCanceledException) when (ct.IsCancellationRequested) { return; } - catch + catch (Exception ex) { + _logger.LogDebug(ex, "FOCAS fixed-tree bootstrap failed for {Host} — retrying", + state.Options.HostAddress); try { await Task.Delay(TimeSpan.FromSeconds(2), ct).ConfigureAwait(false); } catch (OperationCanceledException) { return; } } @@ -559,7 +618,13 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery, var loads = await client2.GetSpindleLoadsAsync(ct).ConfigureAwait(false); for (var i = 0; i < loads.Count; i++) state.LastSpindleLoads[i] = loads[i]; } - catch { /* first-tick poll will retry */ } + catch (Exception ex) + { + /* first-tick poll will retry */ + _logger.LogDebug(ex, + "FOCAS bootstrap spindle-loads prime failed for {Host} — first poll tick will retry", + state.Options.HostAddress); + } } var programPollDue = DateTime.MinValue; @@ -591,7 +656,12 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery, var loads = await client.GetServoLoadsAsync(ct).ConfigureAwait(false); PublishServoLoads(state, loads); } - catch { /* transient — next tick retries */ } + catch (Exception ex) + { + /* transient — next tick retries */ + _logger.LogDebug(ex, "FOCAS servo-loads poll failed for {Host}", + state.Options.HostAddress); + } } if (cache.Capabilities.SpindleLoad) { @@ -600,7 +670,12 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery, var loads = await client.GetSpindleLoadsAsync(ct).ConfigureAwait(false); for (var i = 0; i < loads.Count; i++) state.LastSpindleLoads[i] = loads[i]; } - catch { /* transient */ } + catch (Exception ex) + { + /* transient */ + _logger.LogDebug(ex, "FOCAS spindle-loads poll failed for {Host}", + state.Options.HostAddress); + } } // Program-info poll runs on its own cadence — much slower than the axis @@ -615,7 +690,12 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery, state.LastProgramInfo = program; if (firstAxisSnap is { } s) state.LastProgramAxisRef = s; } - catch { /* transient — next tick retries */ } + catch (Exception ex) + { + /* transient — next tick retries */ + _logger.LogDebug(ex, "FOCAS program-info poll failed for {Host}", + state.Options.HostAddress); + } programPollDue = DateTime.UtcNow + programInterval; } @@ -631,13 +711,23 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery, var t = await client.GetTimerAsync(kind, ct).ConfigureAwait(false); state.LastTimers[kind] = t; } - catch { /* per-kind failures are non-fatal */ } + catch (Exception ex) + { + /* per-kind failures are non-fatal */ + _logger.LogDebug(ex, "FOCAS timer poll failed for {Host} kind={Kind}", + state.Options.HostAddress, kind); + } } timerPollDue = DateTime.UtcNow + timerInterval; } } catch (OperationCanceledException) when (ct.IsCancellationRequested) { break; } - catch { /* next tick retries — transient blips are expected */ } + catch (Exception ex) + { + /* next tick retries — transient blips are expected */ + _logger.LogDebug(ex, "FOCAS fixed-tree poll tick failed for {Host}", + state.Options.HostAddress); + } try { await Task.Delay(_options.FixedTree.PollInterval, ct).ConfigureAwait(false); } catch (OperationCanceledException) { break; } @@ -801,7 +891,11 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery, // reconnect because the goal is just to release the FWLIB handle slot; a // readable tick one probe cycle later is an acceptable cost. try { state.DisposeClient(); } - catch { /* already disposed or race — next EnsureConnected recovers */ } + catch (Exception ex) + { + /* already disposed or race — next EnsureConnected recovers */ + _logger.LogDebug(ex, "FOCAS handle-recycle dispose failed for {Host}", state.Options.HostAddress); + } } } @@ -858,7 +952,11 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery, result.Add((state.Options.HostAddress, alarms)); } catch (OperationCanceledException) when (ct.IsCancellationRequested) { break; } - catch { /* surface a device-local fault on the next tick */ } + catch (Exception ex) + { + /* surface a device-local fault on the next tick */ + _logger.LogDebug(ex, "FOCAS alarm poll failed for {Host}", state.Options.HostAddress); + } } return result; } diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/IFocasClient.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/IFocasClient.cs index 7e4d7fc..a89b3e1 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/IFocasClient.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/IFocasClient.cs @@ -272,16 +272,22 @@ public sealed class UnimplementedFocasClientFactory : IFocasClientFactory /// Well-known FOCAS alarm types from fwlib32.h ALM_TYPE_*. Narrow subset — /// the full list is ~15 types per model; these cover the universally-present categories. /// +/// +/// Constants are typed so they match the wire field width on +/// cnc_rdalmmsg2 (and so 's switch (short) +/// statements compile against a matching type rather than relying on implicit int→short +/// narrowing on the constants). +/// public static class FocasAlarmType { /// Pass to -equivalent to mean "any type". - public const int All = -1; - public const int Parameter = 0; // ALM_P - public const int PulseCode = 1; // ALM_Y (servo) - public const int Overtravel = 2; // ALM_O - public const int Overheat = 3; // ALM_H - public const int Servo = 4; // ALM_S - public const int DataIo = 5; // ALM_T - public const int MemoryCheck = 6; // ALM_M - public const int MacroAlarm = 13; // ALM_MC — used by #3006 etc. + public const short All = -1; + public const short Parameter = 0; // ALM_P + public const short PulseCode = 1; // ALM_Y (servo) + public const short Overtravel = 2; // ALM_O + public const short Overheat = 3; // ALM_H + public const short Servo = 4; // ALM_S + public const short DataIo = 5; // ALM_T + public const short MemoryCheck = 6; // ALM_M + public const short MacroAlarm = 13; // ALM_MC — used by #3006 etc. } diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/Wire/FocasConstants.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/Wire/FocasConstants.cs index b82824d..5977336 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/Wire/FocasConstants.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/Wire/FocasConstants.cs @@ -58,23 +58,13 @@ public static class FocasOperationModeExtensions { /// /// Canonical operator-facing label for an operation mode (e.g. "AUTO", - /// "EDIT"). Unknown codes fall back to the raw numeric value as a string - /// so the UI still shows something interpretable. + /// "EDIT"). Delegates to so the wire layer + /// and the fixed-tree projection render identical labels — historically these two + /// surfaces diverged ("TJOG" vs "T-JOG", "TEACH_IN_HANDLE" vs "TEACH-IN-HANDLE", + /// and different unknown-code fallbacks). Resolved by Driver.FOCAS-010. /// - public static string ToText(this FocasOperationMode mode) => mode switch - { - FocasOperationMode.Mdi => "MDI", - FocasOperationMode.Auto => "AUTO", - FocasOperationMode.TJog => "T-JOG", - FocasOperationMode.Edit => "EDIT", - FocasOperationMode.Handle => "HANDLE", - FocasOperationMode.Jog => "JOG", - FocasOperationMode.TeachInHandle => "TEACH-IN-HANDLE", - FocasOperationMode.Reference => "REFERENCE", - FocasOperationMode.Remote => "REMOTE", - FocasOperationMode.Test => "TEST", - _ => ((short)mode).ToString(), - }; + public static string ToText(this FocasOperationMode mode) => + FocasOpMode.ToText((short)mode); } /// diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/Wire/WireFocasClient.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/Wire/WireFocasClient.cs index 7d73245..c96315d 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/Wire/WireFocasClient.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS/Wire/WireFocasClient.cs @@ -1,3 +1,5 @@ +using Microsoft.Extensions.Logging; + namespace ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Wire; /// @@ -14,9 +16,25 @@ namespace ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Wire; /// public sealed class WireFocasClient : IFocasClient { - private readonly FocasWireClient _wire = new(); + private readonly FocasWireClient _wire; private FocasHostAddress? _address; + /// + /// Default constructor — wire client without logger. Selected by the legacy + /// no-arg path. + /// + public WireFocasClient() : this(logger: null) { } + + /// + /// Construct with an optional logger. Threaded through to + /// so the per-response Debug entries actually reach + /// the host's logging pipeline (Driver.FOCAS-007). + /// + public WireFocasClient(ILogger? logger) + { + _wire = new FocasWireClient(logger); + } + public bool IsConnected => _wire.IsConnected; public async Task ConnectAsync(FocasHostAddress address, TimeSpan timeout, CancellationToken cancellationToken) @@ -339,5 +357,20 @@ public sealed class WireFocasClient : IFocasClient /// Factory producing instances — one per configured device. public sealed class WireFocasClientFactory : IFocasClientFactory { - public IFocasClient Create() => new WireFocasClient(); + private readonly ILogger? _logger; + + public WireFocasClientFactory() : this(logger: null) { } + + /// + /// Construct the factory with a logger that every created + /// forwards to its . Resolves Driver.FOCAS-007 — the wire + /// client already emits Debug entries per FOCAS response, but the previous no-arg + /// factory path discarded them. + /// + public WireFocasClientFactory(ILogger? logger) + { + _logger = logger; + } + + public IFocasClient Create() => new WireFocasClient(_logger); } diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Tests/FocasLoggingTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Tests/FocasLoggingTests.cs new file mode 100644 index 0000000..13fed23 --- /dev/null +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Tests/FocasLoggingTests.cs @@ -0,0 +1,101 @@ +using Microsoft.Extensions.Logging; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Driver.FOCAS; + +namespace ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Tests; + +/// +/// Regression coverage for Driver.FOCAS-007 — the driver previously swallowed every +/// exception in its poll / probe / recycle / fixed-tree loops with no logging at all, +/// leaving operators blind when a CNC was silently failing every tick. +/// +[Trait("Category", "Unit")] +public sealed class FocasLoggingTests +{ + [Fact] + public void Constructor_accepts_an_ILogger() + { + // Constructor signature must allow an ILogger so the host can wire one + // through Microsoft.Extensions.DependencyInjection. The driver code project already + // references Microsoft.Extensions.Logging.Abstractions. + var logger = new CapturingLogger(); + var drv = new FocasDriver( + new FocasDriverOptions { Probe = new FocasProbeOptions { Enabled = false } }, + "drv-1", + new FakeFocasClientFactory(), + logger); + + drv.ShouldNotBeNull(); + } + + [Fact] + public async Task ProbeLoop_logs_when_an_exception_is_swallowed() + { + var logger = new CapturingLogger(); + var factory = new FakeFocasClientFactory + { + Customise = () => new FakeFocasClient + { + // Make ProbeAsync throw — the probe loop swallows it but must log. + ThrowOnConnect = false, + ProbeResult = true, // not used because the underlying probe path throws + }, + }; + // Force the probe to throw by making the client throw on connect. + factory.Customise = () => new FakeFocasClient + { + ThrowOnConnect = true, + Exception = new InvalidOperationException("simulated probe failure"), + }; + + var drv = new FocasDriver( + new FocasDriverOptions + { + Devices = [new FocasDeviceOptions("focas://10.0.0.5:8193")], + Probe = new FocasProbeOptions + { + Enabled = true, + Interval = TimeSpan.FromMilliseconds(50), + Timeout = TimeSpan.FromMilliseconds(100), + }, + }, + "drv-log", + factory, + logger); + + await drv.InitializeAsync("{}", CancellationToken.None); + + // Give the probe loop one tick or two to log. + await Task.Delay(250); + + await drv.ShutdownAsync(CancellationToken.None); + + // We expect at least one log entry at Debug / Warning that mentions the simulated + // failure or the probe loop. Without logging there's literally no record on a wedged + // CNC — exactly the gap the finding called out. + logger.Entries.ShouldNotBeEmpty(); + logger.Entries.Any(e => e.Message.Contains("probe", StringComparison.OrdinalIgnoreCase) + || (e.Exception?.Message.Contains("simulated probe failure") ?? false)) + .ShouldBeTrue("at least one log entry should reference the probe loop or surface the swallowed exception"); + } + + private sealed class CapturingLogger : ILogger + { + public List<(LogLevel Level, string Message, Exception? Exception)> Entries { get; } = 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), exception)); + } + + private sealed class NullScope : IDisposable + { + public static NullScope Instance { get; } = new(); + public void Dispose() { } + } + } +} diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Tests/FocasLowFindingsTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Tests/FocasLowFindingsTests.cs new file mode 100644 index 0000000..6accdec --- /dev/null +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Tests/FocasLowFindingsTests.cs @@ -0,0 +1,218 @@ +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Core.Abstractions; +using ZB.MOM.WW.OtOpcUa.Driver.FOCAS; +using ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Wire; + +namespace ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Tests; + +/// +/// Regression coverage for the Low-severity code-review findings: +/// +/// Driver.FOCAS-008 — parsed FocasAddress is cached at init, not re-parsed per read/write +/// Driver.FOCAS-009 — Probe.Timeout is actually applied around ProbeAsync +/// Driver.FOCAS-010 — operation-mode → text mapping is consolidated +/// Driver.FOCAS-011 — FocasAlarmType constants are typed as short +/// +/// +[Trait("Category", "Unit")] +public sealed class FocasLowFindingsTests +{ + // ---- Driver.FOCAS-008 — parsed FocasAddress cached at init ---- + + [Fact] + public async Task ReadAsync_uses_cached_FocasAddress_when_tag_definition_has_a_malformed_address_after_init() + { + // After InitializeAsync succeeds with a well-formed address, the driver must rely on the + // cached parse — *not* re-parse `FocasTagDefinition.Address` on every read. We can prove + // the cache is used by stuffing a malformed Address onto a tag *post-init* through the + // internal cache surface — but that's brittle. Instead, prove no re-parse by counting: + // we monkey-patch the FakeFocasClient.ReadAsync to capture the FocasAddress reference + // it receives and assert it's the *same* instance across two consecutive reads. + var captured = new List(); + var factory = new FakeFocasClientFactory + { + Customise = () => new CapturingFakeFocasClient(captured) + { + Values = { ["R100"] = (sbyte)1 }, + }, + }; + var drv = new FocasDriver(new FocasDriverOptions + { + Devices = [new FocasDeviceOptions("focas://10.0.0.5:8193")], + Tags = [new FocasTagDefinition("X", "focas://10.0.0.5:8193", "R100", FocasDataType.Byte)], + Probe = new FocasProbeOptions { Enabled = false }, + }, "drv-1", factory); + await drv.InitializeAsync("{}", CancellationToken.None); + + await drv.ReadAsync(["X"], CancellationToken.None); + await drv.ReadAsync(["X"], CancellationToken.None); + + captured.Count.ShouldBe(2); + ReferenceEquals(captured[0], captured[1]) + .ShouldBeTrue("ReadAsync must reuse the FocasAddress parsed at init, not re-parse per read"); + } + + [Fact] + public async Task WriteAsync_uses_cached_FocasAddress_too() + { + var captured = new List(); + var factory = new FakeFocasClientFactory + { + Customise = () => new CapturingFakeFocasClient(captured) + { + WriteStatuses = { ["R100"] = FocasStatusMapper.Good }, + }, + }; + var drv = new FocasDriver(new FocasDriverOptions + { + Devices = [new FocasDeviceOptions("focas://10.0.0.5:8193")], + Tags = + [ + new FocasTagDefinition( + "X", "focas://10.0.0.5:8193", "R100", FocasDataType.Byte, Writable: true), + ], + Probe = new FocasProbeOptions { Enabled = false }, + }, "drv-1", factory); + await drv.InitializeAsync("{}", CancellationToken.None); + + await drv.WriteAsync( + [new WriteRequest("X", (sbyte)1)], + CancellationToken.None); + await drv.WriteAsync( + [new WriteRequest("X", (sbyte)2)], + CancellationToken.None); + + captured.Count.ShouldBe(2); + ReferenceEquals(captured[0], captured[1]) + .ShouldBeTrue("WriteAsync must reuse the FocasAddress parsed at init"); + } + + // ---- Driver.FOCAS-009 — Probe.Timeout applies to ProbeAsync ---- + + [Fact] + public async Task ProbeLoop_cancels_a_slow_ProbeAsync_at_Probe_Timeout() + { + // The probe loop must apply Probe.Timeout — a hung CNC socket should be cancelled at the + // configured timeout rather than blocking until the OS TCP timeout. We prove the timeout + // is applied by making ProbeAsync wait indefinitely and asserting it observes + // cancellation before the normal probe Interval would tick again. + var hangSignal = new TaskCompletionSource(); + var factory = new FakeFocasClientFactory + { + Customise = () => new HangingProbeFakeClient(hangSignal), + }; + var probeTimeout = TimeSpan.FromMilliseconds(100); + var drv = new FocasDriver(new FocasDriverOptions + { + Devices = [new FocasDeviceOptions("focas://10.0.0.5:8193")], + Probe = new FocasProbeOptions + { + Enabled = true, + Interval = TimeSpan.FromSeconds(10), + Timeout = probeTimeout, + }, + }, "drv-1", factory); + + await drv.InitializeAsync("{}", CancellationToken.None); + + // Wait up to a generous bound for the probe to observe cancellation. Without the + // timeout fix, this never completes (Probe runs forever). + var cancelled = await Task.WhenAny( + hangSignal.Task, + Task.Delay(TimeSpan.FromSeconds(2))) == hangSignal.Task; + + await drv.ShutdownAsync(CancellationToken.None); + + cancelled.ShouldBeTrue( + "ProbeAsync must be cancelled at Probe.Timeout when it does not complete; otherwise a hung CNC blocks the probe loop indefinitely"); + } + + // ---- Driver.FOCAS-010 — operation-mode → text mapping is consolidated ---- + + [Theory] + [InlineData(0, "MDI")] + [InlineData(1, "AUTO")] + [InlineData(2, "TJOG")] // canonical FocasOpMode label, matches both surfaces post-fix + [InlineData(3, "EDIT")] + [InlineData(4, "HANDLE")] + [InlineData(5, "JOG")] + [InlineData(6, "TEACH_IN_HANDLE")] + [InlineData(7, "REFERENCE")] + [InlineData(8, "REMOTE")] + [InlineData(9, "TEST")] + public void OpMode_ToText_yields_the_same_label_in_both_namespaces(int code, string expected) + { + // Driver fixed-tree path (FocasOpMode.ToText) and wire layer (FocasOperationModeExtensions.ToText) + // must yield the same canonical label so dashboard rendering doesn't vary by code path. + FocasOpMode.ToText(code).ShouldBe(expected); + ((FocasOperationMode)(short)code).ToText().ShouldBe(expected); + } + + [Fact] + public void OpMode_ToText_fallback_label_is_consistent() + { + // Unknown codes must fall back to the same shape from both call sites — previously + // FocasOpMode used "Mode{n}" while FocasOperationModeExtensions used the bare number. + const int unknown = 99; + FocasOpMode.ToText(unknown).ShouldBe( + ((FocasOperationMode)(short)unknown).ToText(), + "unknown-mode fallback must agree across both surfaces"); + } + + // ---- Driver.FOCAS-011 — FocasAlarmType constants typed as short ---- + + [Fact] + public void FocasAlarmType_constants_are_typed_short() + { + // The downstream switches in FocasAlarmProjection.MapAlarmType / MapSeverity take a short. + // Declaring the constants as int (the old shape) compiled by accident because the values + // fit short range; making them short makes the type match the wire width. + // We assert this at runtime via reflection so the test fails if a future contributor + // demotes them back to int. + var fields = typeof(FocasAlarmType).GetFields( + System.Reflection.BindingFlags.Public | System.Reflection.BindingFlags.Static); + foreach (var f in fields) + { + f.FieldType.ShouldBe(typeof(short), + $"FocasAlarmType.{f.Name} must be typed `short` so it matches the wire field width " + + "and the FocasAlarmProjection switch arm types"); + } + } + + // ---- helpers ---- + + private sealed class CapturingFakeFocasClient(List captured) : FakeFocasClient + { + public override Task<(object? value, uint status)> ReadAsync( + FocasAddress address, FocasDataType type, CancellationToken ct) + { + captured.Add(address); + return base.ReadAsync(address, type, ct); + } + + public override Task WriteAsync( + FocasAddress address, FocasDataType type, object? value, CancellationToken ct) + { + captured.Add(address); + return base.WriteAsync(address, type, value, ct); + } + } + + private sealed class HangingProbeFakeClient(TaskCompletionSource cancelledSignal) : FakeFocasClient + { + public override async Task ProbeAsync(CancellationToken ct) + { + try + { + await Task.Delay(Timeout.InfiniteTimeSpan, ct).ConfigureAwait(false); + return true; + } + catch (OperationCanceledException) + { + cancelledSignal.TrySetResult(); + throw; + } + } + } +}