From b50fd6c34ab05e20417c2404323bee80a15560ac Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Fri, 19 Jun 2026 12:08:45 -0400 Subject: [PATCH] review(Driver.AbLegacy.Cli): add FlushLogging() to command finally blocks Re-review at 7286d320. -008 (Low): all four commands now FlushLogging() in finally (parity with AbCip.Cli; subscribe could drop shutdown log lines) + IL-inspection test. --- code-reviews/Driver.AbLegacy.Cli/findings.md | 63 ++++++++++++++++- .../Commands/ProbeCommand.cs | 3 + .../Commands/ReadCommand.cs | 3 + .../Commands/SubscribeCommand.cs | 5 ++ .../Commands/WriteCommand.cs | 3 + .../CommandMetadataTests.cs | 70 ++++++++++++++++++- 6 files changed, 143 insertions(+), 4 deletions(-) diff --git a/code-reviews/Driver.AbLegacy.Cli/findings.md b/code-reviews/Driver.AbLegacy.Cli/findings.md index f87755ff..d340463e 100644 --- a/code-reviews/Driver.AbLegacy.Cli/findings.md +++ b/code-reviews/Driver.AbLegacy.Cli/findings.md @@ -4,16 +4,39 @@ |---|---| | Module | `src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli` | | Reviewer | Claude Code | -| Review date | 2026-05-22 | -| Commit reviewed | `76d35d1` | +| Review date | 2026-06-19 | +| Commit reviewed | `111d6983` | | Status | Reviewed | | Open findings | 0 | +## Re-review 2026-06-19 (commit 111d6983) + +Re-review at HEAD `111d6983`. No changes in this module since the last review commit `7286d320`. Sibling module Driver.Cli.Common received a fix (`1180b017`) but the `FlushLogging` omission was not back-ported to AbLegacy. Cross-module comparison against the AbCip CLI (which received Driver.AbCip.Cli-005 fix) revealed the single new finding below. + +#### Changes since prior review + +No source files in this module changed between `7286d320` and `111d6983`. The finding was surfaced by comparing the AbLegacy CLI commands against the AbCip CLI siblings, which had `FlushLogging()` calls added in a prior review cycle. + ## Checklist coverage A comprehensive review completes every category, recording "No issues found" where a category produced nothing rather than leaving it blank. +| # | Category | Result | +|---|---|---| +| 1 | Correctness & logic bugs | No issues found | +| 2 | OtOpcUa conventions | No issues found | +| 3 | Concurrency & thread safety | No issues found | +| 4 | Error handling & resilience | Driver.AbLegacy.Cli-008 | +| 5 | Security | No issues found | +| 6 | Performance & resource management | Driver.AbLegacy.Cli-008 | +| 7 | Design-document adherence | No issues found | +| 8 | Code organization & conventions | No issues found | +| 9 | Testing coverage | No issues found | +| 10 | Documentation & comments | No issues found | + +Prior review checklist (commit `76d35d1`, 2026-05-22): + | # | Category | Result | |---|---|---| | 1 | Correctness & logic bugs | Driver.AbLegacy.Cli-001, Driver.AbLegacy.Cli-002 | @@ -241,3 +264,39 @@ analyzer. The overflow path for `ParseValue` is already covered by `WriteCommandParseValueTests.ParseValue_out_of_range_throws_CommandException` (theory with `short.Parse` + `AnalogInt` overflow inputs), added when finding Driver.AbLegacy.Cli-001 was resolved. + +--- + +## Findings (re-review 2026-06-19) + +### Driver.AbLegacy.Cli-008 + +| Field | Value | +|---|---| +| Severity | Low | +| Category | Error handling & resilience / Performance & resource management | +| Location | `Commands/ProbeCommand.cs:58-61`, `Commands/ReadCommand.cs:52-55`, `Commands/WriteCommand.cs:62-65`, `Commands/SubscribeCommand.cs:88-96` | +| Status | Resolved | + +**Description:** All four commands call `ConfigureLogging()` at the top of +`ExecuteAsync` but none call `FlushLogging()` (`Log.CloseAndFlush()`) in their +`finally` block. The `DriverCommandBase` XML doc explicitly states "Call +`FlushLogging` in a `finally` block to ensure buffered output is flushed before +the process exits." For the one-shot commands (`probe`, `read`, `write`) the +console sink is flushed on process exit anyway, so the practical impact is nil +there. For `subscribe` — a long-running command terminated by Ctrl+C — buffered +Serilog lines emitted during `ShutdownAsync` can be silently dropped on abrupt +exit. The sibling AbCip CLI already received this fix (Driver.AbCip.Cli-005, +resolved 2026-06-19); AbLegacy was not updated in the same pass. + +**Recommendation:** Add `FlushLogging();` at the end of each command's `finally` +block, after `ShutdownAsync`, mirroring the AbCip CLI fix. + +**Resolution:** Resolved 2026-06-19 — added `FlushLogging()` in the `finally` +block of all four commands (`ProbeCommand`, `ReadCommand`, `WriteCommand`, +`SubscribeCommand`) with an explanatory comment referencing this finding ID. +Added IL-inspection theory test +`CommandMetadataTests.ExecuteAsync_calls_FlushLogging_in_state_machine` (4 +theory cases) that walks each command's compiler-generated async state-machine +`MoveNext` IL to verify the `DriverCommandBase.FlushLogging` method token is +present; test was red before the fix, green after. All 36 tests pass. diff --git a/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli/Commands/ProbeCommand.cs b/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli/Commands/ProbeCommand.cs index 752b187c..a92b5414 100644 --- a/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli/Commands/ProbeCommand.cs +++ b/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli/Commands/ProbeCommand.cs @@ -58,6 +58,9 @@ public sealed class ProbeCommand : AbLegacyCommandBase finally { await driver.ShutdownAsync(CancellationToken.None); + // Driver.AbLegacy.Cli-008 — flush Serilog before process exit so buffered + // log output emitted during driver shutdown is not lost. + FlushLogging(); } } } diff --git a/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli/Commands/ReadCommand.cs b/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli/Commands/ReadCommand.cs index 51ac8ca1..ab8ed216 100644 --- a/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli/Commands/ReadCommand.cs +++ b/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli/Commands/ReadCommand.cs @@ -52,6 +52,9 @@ public sealed class ReadCommand : AbLegacyCommandBase finally { await driver.ShutdownAsync(CancellationToken.None); + // Driver.AbLegacy.Cli-008 — flush Serilog before process exit so buffered + // log output emitted during driver shutdown is not lost. + FlushLogging(); } } diff --git a/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli/Commands/SubscribeCommand.cs b/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli/Commands/SubscribeCommand.cs index 429c0a4b..bccb7bb6 100644 --- a/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli/Commands/SubscribeCommand.cs +++ b/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli/Commands/SubscribeCommand.cs @@ -93,6 +93,11 @@ public sealed class SubscribeCommand : AbLegacyCommandBase catch { /* teardown best-effort */ } } await driver.ShutdownAsync(CancellationToken.None); + // Driver.AbLegacy.Cli-008 — flush Serilog before process exit so buffered + // log output emitted during driver shutdown is not lost. Particularly + // important here: subscribe runs until Ctrl+C; without this, lines logged + // during shutdown can be silently dropped. + FlushLogging(); } } } diff --git a/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli/Commands/WriteCommand.cs b/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli/Commands/WriteCommand.cs index b875ca97..41e58913 100644 --- a/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli/Commands/WriteCommand.cs +++ b/src/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli/Commands/WriteCommand.cs @@ -62,6 +62,9 @@ public sealed class WriteCommand : AbLegacyCommandBase finally { await driver.ShutdownAsync(CancellationToken.None); + // Driver.AbLegacy.Cli-008 — flush Serilog before process exit so buffered + // log output emitted during driver shutdown is not lost. + FlushLogging(); } } diff --git a/tests/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli.Tests/CommandMetadataTests.cs b/tests/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli.Tests/CommandMetadataTests.cs index 131aab84..c7e19881 100644 --- a/tests/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli.Tests/CommandMetadataTests.cs +++ b/tests/Drivers/Cli/ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli.Tests/CommandMetadataTests.cs @@ -4,8 +4,7 @@ using CliFx.Attributes; using Shouldly; using Xunit; using ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli.Commands; - -namespace ZB.MOM.WW.OtOpcUa.Driver.AbLegacy.Cli.Tests; +using ZB.MOM.WW.OtOpcUa.Driver.Cli.Common; /// /// Locks in the CLI command-option contract surface area — short aliases and @@ -83,4 +82,71 @@ public sealed class CommandMetadataTests attr.Description.ShouldNotBeNull(); attr.Description!.ShouldContain("250", Case.Insensitive); } + + // ---------- Driver.AbLegacy.Cli-008 — all commands must call FlushLogging() in their finally ---------- + + /// + /// Verifies that every AbLegacy CLI command's async state-machine references + /// so Serilog output emitted during + /// driver shutdown is flushed before process exit (regression for + /// Driver.AbLegacy.Cli-008, matching the fix applied to AbCip CLI Driver.AbCip.Cli-005). + /// + /// The command type whose state machine is inspected. + [Theory] + [InlineData(typeof(ProbeCommand))] + [InlineData(typeof(ReadCommand))] + [InlineData(typeof(WriteCommand))] + [InlineData(typeof(SubscribeCommand))] + public void ExecuteAsync_calls_FlushLogging_in_state_machine(System.Type commandType) + { + // C# async methods are compiled into a nested 'd__N' state machine + // class with a MoveNext() method that contains the actual IL. We scan the + // MoveNext() body for a call token that resolves to DriverCommandBase.FlushLogging + // using the module's metadata. + var flushMethod = typeof(DriverCommandBase) + .GetMethod("FlushLogging", + BindingFlags.NonPublic | BindingFlags.Static | BindingFlags.FlattenHierarchy); + flushMethod.ShouldNotBeNull("DriverCommandBase.FlushLogging must exist"); + + // Locate the compiler-generated state-machine nested type for ExecuteAsync. + var stateMachine = commandType + .GetNestedTypes(BindingFlags.NonPublic) + .FirstOrDefault(t => t.Name.Contains("ExecuteAsync")); + stateMachine.ShouldNotBeNull( + $"{commandType.Name} must have a compiler-generated ExecuteAsync state machine"); + + var moveNext = stateMachine! + .GetMethod("MoveNext", BindingFlags.NonPublic | BindingFlags.Instance); + moveNext.ShouldNotBeNull("MoveNext must exist on the state machine"); + + var body = moveNext!.GetMethodBody(); + body.ShouldNotBeNull("MoveNext must have an inspectable method body"); + + // Walk the IL stream: call/callvirt opcodes (0x28 / 0x6F) are followed by a + // 4-byte metadata token. Check whether any token resolves to FlushLogging. + var il = body!.GetILAsByteArray(); + il.ShouldNotBeNull(); + var module = moveNext.Module; + bool found = false; + for (int i = 0; i < il!.Length - 4; i++) + { + if (il[i] != 0x28 && il[i] != 0x6F) continue; // call / callvirt + int token = il[i + 1] | (il[i + 2] << 8) | (il[i + 3] << 16) | (il[i + 4] << 24); + try + { + var resolved = module.ResolveMethod(token); + if (resolved?.Name == "FlushLogging" && + resolved.DeclaringType == typeof(DriverCommandBase)) + { + found = true; + break; + } + } + catch (ArgumentException) { /* token is a field or type, not a method */ } + } + + found.ShouldBeTrue( + $"{commandType.Name}.ExecuteAsync must call FlushLogging() in its finally block " + + "so Serilog output during driver shutdown is not lost (Driver.AbLegacy.Cli-008)."); + } }