diff --git a/code-reviews/Driver.FOCAS.Cli/findings.md b/code-reviews/Driver.FOCAS.Cli/findings.md index 2f76854a..d9c118a3 100644 --- a/code-reviews/Driver.FOCAS.Cli/findings.md +++ b/code-reviews/Driver.FOCAS.Cli/findings.md @@ -4,8 +4,8 @@ |---|---| | Module | `src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli` | | Reviewer | Claude Code | -| Review date | 2026-05-22 | -| Commit reviewed | `76d35d1` | +| Review date | 2026-06-19 | +| Commit reviewed | `7286d320` | | Status | Reviewed | | Open findings | 0 | @@ -229,3 +229,83 @@ promises, restoring parity between the docs and the shipped behaviour. Regressio shortlist again; the existing well-known shortlist `[Theory]` was extended with the same five entries to enforce the exact `0x... (Name)` rendering. Suite now 47 green (was 42). + +## Re-review 2026-06-19 (commit 7286d320) + +All five prior findings (001–005) remain Resolved. The test suite now has 52 tests +(48 pre-existing + 4 added in this re-review). Two new findings were identified. + +#### Checklist coverage (re-review) + +| # | Category | Result | +|---|---|---| +| 1 | Correctness & logic bugs | No new issues found | +| 2 | OtOpcUa conventions | No new issues found | +| 3 | Concurrency & thread safety | No new issues found | +| 4 | Error handling & resilience | No new issues found | +| 5 | Security | No new issues found | +| 6 | Performance & resource management | No new issues found | +| 7 | Design-document adherence | No new issues found | +| 8 | Code organization & conventions | Driver.FOCAS.Cli-006, Driver.FOCAS.Cli-007 | +| 9 | Testing coverage | No new issues found | +| 10 | Documentation & comments | Driver.FOCAS.Cli-007 | + +### Driver.FOCAS.Cli-006 + +| Field | Value | +|---|---| +| Severity | Low | +| Category | Code organization & conventions | +| Location | `Commands/ProbeCommand.cs`, `Commands/ReadCommand.cs`, `Commands/WriteCommand.cs`, `Commands/SubscribeCommand.cs` | +| Status | Resolved | + +**Description:** `DriverCommandBase.ConfigureLogging` was extended between review +commits to document that callers must call `FlushLogging()` in a `finally` block +to ensure buffered Serilog output is flushed before process exit. Every sibling +driver CLI (Modbus, AbCip, AbLegacy, TwinCAT) honours this contract, but all four +FOCAS CLI commands were missing the call. With the Console sink (Serilog 6.0.0) +there is no actual data loss today because `System.Console.Out` auto-flushes; +however the gap is a maintenance hazard: if a file sink or an async sink is ever +added to the logger configuration, the omission becomes data-losing. The +inconsistency with sibling CLIs also makes the codebase misleading for reviewers. + +**Recommendation:** Add `try/finally` wrappers in ProbeCommand, ReadCommand, and +WriteCommand (which had no finally blocks since the -004 cleanup) and extend +SubscribeCommand's existing finally block, calling `FlushLogging()` in each. +Add a convention test (parallel to `CommandDisposalConventionsTests`) that +scans source files and asserts the call is present, preventing silent regressions. + +**Resolution:** Resolved 2026-06-19 — added `try/finally` wrappers with +`FlushLogging()` to `ProbeCommand`, `ReadCommand`, and `WriteCommand`; extended +SubscribeCommand's existing `finally` block with the same call. Added +`FlushLoggingConventionsTests` with a `[Theory]` over all four command files so +the call cannot be silently dropped in future refactors. Suite now 52 green (was 48). + +### Driver.FOCAS.Cli-007 + +| Field | Value | +|---|---| +| Severity | Low | +| Category | Documentation & comments | +| Location | `Commands/SubscribeCommand.cs:113-120` | +| Status | Resolved | + +**Description:** The comment in the `SubscribeCommand.finally` block (added by +the -002 resolution) said "detach the OnDataChange handler before unsubscribe + +disposal" — but no `-=` operator call exists in the block. The comment's claim +was factually incorrect: handler cleanup is achieved by driver disposal (via +`await using`), which tears down the `PollGroupEngine` and prevents further +`OnDataChange` events; not by explicit unsubscription from the event. A +parenthetical note at the end of the original comment partially explained the +real mechanism, but the leading sentence was still misleading for future readers. + +**Recommendation:** Reword the comment to accurately describe what the code does: +`UnsubscribeAsync` stops the poll-group ticker (a subscription lifecycle step); +the anonymous handler is never explicitly removed via `-=`; driver disposal via +`await using` is the real cleanup. + +**Resolution:** Resolved 2026-06-19 — rewrote the comment to correctly describe +the two-step teardown: `UnsubscribeAsync` halts the poll ticker (subscription +lifecycle), then `await using` disposes the driver and tears down +`PollGroupEngine` (real cleanup). Removed the incorrect claim about `-=` +detachment. No behavioral change; documentation only. diff --git a/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli/Commands/ProbeCommand.cs b/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli/Commands/ProbeCommand.cs index c5a275f1..111084e4 100644 --- a/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli/Commands/ProbeCommand.cs +++ b/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli/Commands/ProbeCommand.cs @@ -43,16 +43,26 @@ public sealed class ProbeCommand : FocasCommandBase // already invokes ShutdownAsync, so a redundant explicit ShutdownAsync(CancellationToken.None) // in a finally block ran shutdown twice. The await-using on the next line is enough. await using var driver = new FocasDriver(options, DriverInstanceId); - await driver.InitializeAsync("{}", ct); - var snapshot = await driver.ReadAsync(["__probe"], ct); - var health = driver.GetHealth(); + try + { + await driver.InitializeAsync("{}", ct); + var snapshot = await driver.ReadAsync(["__probe"], ct); + var health = driver.GetHealth(); - await console.Output.WriteLineAsync($"CNC: {CncHost}:{CncPort}"); - await console.Output.WriteLineAsync($"Series: {Series}"); - await console.Output.WriteLineAsync($"Health: {health.State}"); - if (health.LastError is { } err) - await console.Output.WriteLineAsync($"Last error: {err}"); - await console.Output.WriteLineAsync(); - await console.Output.WriteLineAsync(SnapshotFormatter.Format(Address, snapshot[0])); + await console.Output.WriteLineAsync($"CNC: {CncHost}:{CncPort}"); + await console.Output.WriteLineAsync($"Series: {Series}"); + await console.Output.WriteLineAsync($"Health: {health.State}"); + if (health.LastError is { } err) + await console.Output.WriteLineAsync($"Last error: {err}"); + await console.Output.WriteLineAsync(); + await console.Output.WriteLineAsync(SnapshotFormatter.Format(Address, snapshot[0])); + } + finally + { + // Driver.FOCAS.Cli-006: flush Serilog before process exit so buffered log output + // emitted during driver shutdown is not silently dropped (matching DriverCommandBase + // docs and every sibling CLI — Modbus / AbCip / AbLegacy / TwinCAT). + FlushLogging(); + } } } diff --git a/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli/Commands/ReadCommand.cs b/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli/Commands/ReadCommand.cs index c1a92581..dc3584ef 100644 --- a/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli/Commands/ReadCommand.cs +++ b/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli/Commands/ReadCommand.cs @@ -44,9 +44,19 @@ public sealed class ReadCommand : FocasCommandBase // already invokes ShutdownAsync, so a redundant explicit ShutdownAsync(CancellationToken.None) // in a finally block ran shutdown twice. The await-using on the next line is enough. await using var driver = new FocasDriver(options, DriverInstanceId); - await driver.InitializeAsync("{}", ct); - var snapshot = await driver.ReadAsync([tagName], ct); - await console.Output.WriteLineAsync(SnapshotFormatter.Format(Address, snapshot[0])); + try + { + await driver.InitializeAsync("{}", ct); + var snapshot = await driver.ReadAsync([tagName], ct); + await console.Output.WriteLineAsync(SnapshotFormatter.Format(Address, snapshot[0])); + } + finally + { + // Driver.FOCAS.Cli-006: flush Serilog before process exit so buffered log output + // emitted during driver shutdown is not silently dropped (matching DriverCommandBase + // docs and every sibling CLI — Modbus / AbCip / AbLegacy / TwinCAT). + FlushLogging(); + } } /// Constructs a tag name from address and data type. diff --git a/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli/Commands/SubscribeCommand.cs b/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli/Commands/SubscribeCommand.cs index dc5e5218..9f053e96 100644 --- a/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli/Commands/SubscribeCommand.cs +++ b/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli/Commands/SubscribeCommand.cs @@ -110,16 +110,19 @@ public sealed class SubscribeCommand : FocasCommandBase { if (handle is not null) { - // Driver.FOCAS.Cli-002: detach the OnDataChange handler before unsubscribe + - // disposal for symmetry with the handle teardown, so a future refactor that - // reuses the driver after the subscribe verb returns wouldn't leak a - // dangling subscription. - // (Single anonymous handler instance is captured implicitly by `await using` - // disposing the driver immediately afterwards; the unsubscribe + dispose - // sequence is what really cleans up here.) + // Driver.FOCAS.Cli-002: stop the subscription before disposal — UnsubscribeAsync + // halts the poll-group ticker so no further OnDataChange events fire. The + // anonymous handler is never explicitly removed via -=; instead, driver disposal + // (via `await using` immediately after this finally) tears down the PollGroupEngine, + // which is the real cleanup. The unsubscribe here is a best-effort subscription + // lifecycle step so the CNC-side session is cleanly released before teardown. try { await driver.UnsubscribeAsync(handle, CancellationToken.None); } catch { /* teardown best-effort */ } } + // Driver.FOCAS.Cli-006: flush Serilog before process exit so buffered log output + // emitted during driver shutdown is not silently dropped (matching DriverCommandBase + // docs and every sibling CLI — Modbus / AbCip / AbLegacy / TwinCAT). + FlushLogging(); } } } diff --git a/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli/Commands/WriteCommand.cs b/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli/Commands/WriteCommand.cs index 906849fb..2c45712b 100644 --- a/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli/Commands/WriteCommand.cs +++ b/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli/Commands/WriteCommand.cs @@ -54,9 +54,19 @@ public sealed class WriteCommand : FocasCommandBase // already invokes ShutdownAsync, so a redundant explicit ShutdownAsync(CancellationToken.None) // in a finally block ran shutdown twice. The await-using on the next line is enough. await using var driver = new FocasDriver(options, DriverInstanceId); - await driver.InitializeAsync("{}", ct); - var results = await driver.WriteAsync([new WriteRequest(tagName, parsed)], ct); - await console.Output.WriteLineAsync(SnapshotFormatter.FormatWrite(Address, results[0])); + try + { + await driver.InitializeAsync("{}", ct); + var results = await driver.WriteAsync([new WriteRequest(tagName, parsed)], ct); + await console.Output.WriteLineAsync(SnapshotFormatter.FormatWrite(Address, results[0])); + } + finally + { + // Driver.FOCAS.Cli-006: flush Serilog before process exit so buffered log output + // emitted during driver shutdown is not silently dropped (matching DriverCommandBase + // docs and every sibling CLI — Modbus / AbCip / AbLegacy / TwinCAT). + FlushLogging(); + } } /// Parse --value per , invariant culture throughout. diff --git a/tests/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli.Tests/FlushLoggingConventionsTests.cs b/tests/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli.Tests/FlushLoggingConventionsTests.cs new file mode 100644 index 00000000..b2a52cc3 --- /dev/null +++ b/tests/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli.Tests/FlushLoggingConventionsTests.cs @@ -0,0 +1,53 @@ +using Shouldly; +using Xunit; + +namespace ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli.Tests; + +/// +/// Driver.FOCAS.Cli-006: every FOCAS CLI command must call +/// FlushLogging() in a finally block so buffered Serilog output +/// emitted during driver shutdown is not silently dropped when the process exits. +/// DriverCommandBase documents this requirement and every sibling CLI +/// (Modbus / S7 / AbCip / AbLegacy / TwinCAT) honours it; the FOCAS CLI was +/// the only one missing the call. +/// +[Trait("Category", "Unit")] +public sealed class FlushLoggingConventionsTests +{ + private static readonly string CommandsDir = LocateCommandsDir(); + + /// + /// Verifies that a FOCAS CLI command source file contains a FlushLogging() + /// call, matching the pattern used by every other driver CLI in the repo. + /// + /// The command source file name to inspect. + [Theory] + [InlineData("ProbeCommand.cs")] + [InlineData("ReadCommand.cs")] + [InlineData("WriteCommand.cs")] + [InlineData("SubscribeCommand.cs")] + public void Command_calls_FlushLogging_in_finally_block(string commandFile) + { + var path = Path.Combine(CommandsDir, commandFile); + File.Exists(path).ShouldBeTrue($"Expected {path} to exist."); + var source = File.ReadAllText(path); + + // DriverCommandBase.ConfigureLogging XML doc says: + // "Call FlushLogging in a finally block to ensure buffered output is flushed + // before the process exits." + // Every other driver CLI (Modbus, AbCip, AbLegacy, TwinCAT) calls FlushLogging() + // from a finally block. The FOCAS CLI must do the same so buffered Serilog output + // during driver shutdown is not lost when the process exits abruptly. + source.ShouldContain("FlushLogging()"); + } + + private static string LocateCommandsDir() + { + var dir = new DirectoryInfo(AppContext.BaseDirectory); + while (dir is not null && !File.Exists(Path.Combine(dir.FullName, "ZB.MOM.WW.OtOpcUa.slnx"))) + dir = dir.Parent; + dir.ShouldNotBeNull("Could not find solution root (ZB.MOM.WW.OtOpcUa.slnx)."); + return Path.Combine( + dir!.FullName, "src", "Drivers", "Cli", "ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Cli", "Commands"); + } +}