Log command headers before process output - #3580
Conversation
fd44ada to
58ce9ae
Compare
|
@codex review |
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 58ce9ae54a
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
58ce9ae to
dd0b2f6
Compare
|
@codex review |
There was a problem hiding this comment.
Review: Log command headers before process output (closes #3550)
The core fix is solid: LogCommandStart now writes the workingdir> command header before execution instead of after, which correctly addresses the bottom-up log ordering described in #3550. The Command.cs main execution path (Of) is careful to pair every LogCommandStart with a LogCommandCompletion even on failure — both the CommandExecutionException and generic Exception catch blocks call LogCommandCompletion via CombineWithCompletionFailure before rethrowing, so exceptions from that path won't leave an orphaned header. The default-interface-method approach on ICommandLogger (no-op LogCommandStart, LogCommandCompletion forwarding to the legacy Log) is a reasonable way to keep third-party ICommandLogger implementations source-compatible. New tests exercise start-before-output-before-completion ordering for both success and failure, which is exactly what regressed before.
Issue found
LoggingCommandLineExecutor.ExecuteAsync can leave an orphaned "command started" line with no completion when the inner executor throws.
src/ModularPipelines/Context/LoggingCommandLineExecutor.cs:42-69
_commandLogger.LogCommandStart(...);
var result = await _inner.ExecuteAsync(commandLine, options, cancellationToken).ConfigureAwait(false);
_commandLogger.LogCommandCompletion(...);There's no try/catch around the await. CommandLineExecutor.ExecuteAsync (the default _inner) can throw — e.g. TimeoutException when options.ExecutionTimeout elapses, or a Win32Exception/FileNotFoundException from CliWrap if the target executable can't be launched. In those cases the header line prints, execution throws, and LogCommandCompletion is skipped entirely.
Before this PR that was harmless — the single Log() call happened once, after a successful await, so a thrown exception meant no log line at all (consistent silence). After this PR, the same exception now produces a partial log: a command header with no resolution, no error output, and no status line. In real usage (e.g. a raw Cmd command that times out or references a missing binary) this reads as if the command hung or the logging pipeline dropped output, which is more confusing than the previous behavior, not less — and it's the same class of bug this PR set out to fix (log blocks not accurately reflecting what happened).
Compare with Command.cs's Of method, which wraps the whole execution in try/catch specifically to guarantee LogCommandCompletion always fires via CombineWithCompletionFailure, even when things go wrong. LoggingCommandLineExecutor should follow the same pattern — wrap the inner ExecuteAsync call in a try/finally (or try/catch that logs a failure completion and rethrows) so a header is never left dangling.
There's no test coverage for LoggingCommandLineExecutor at all (grep for it under test/ returns nothing), so this path — including the exception scenario — isn't exercised. Worth adding a regression test alongside the fix.
Suggestion (minor, not blocking)
The InternalDryRun short-circuit is now split across two places: LogCommandStart special-cases it to print a single [DRY-RUN] line and return, while LogCommandCompletion separately special-cases it to no-op. This only comes together correctly because Command.cs's dry-run branch happens to call the composite Log() (which chains both), rather than calling LogCommandStart/LogCommandCompletion directly like every other call site does. It works, but a future reader wiring up dry-run through the split API directly could easily get double output or none. Consider giving CommandLoggingOptions/dry-run handling a single obvious entry point (e.g. keep dry-run entirely inside LogCommandStart and have LogCommandCompletion's dry-run check simply follow from that invariant with a comment explaining why it's still needed), so the two dry-run checks don't read as redundant to the next person touching this file.
Nice work overall — the split is clean and the test additions correctly pin the new ordering guarantee for the paths they cover.
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: dd0b2f6bd7
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
dd0b2f6 to
f39153f
Compare
|
Rebased onto current main; focused command logging suites pass (53 tests). @codex review |
There was a problem hiding this comment.
Review: Log command headers before process output (closes #3550)
Re-reviewed at f39153f2 (after the "reuse ordered log phases" / "simplify completion logging" refactor commits). The header-before-output reordering itself is solid, the Command.cs Of path still pairs every LogCommandStart with LogCommandCompletion on both the CommandExecutionException and generic exception branches, and the ICommandLogger default-interface-method approach keeps third-party loggers source-compatible. The two new CommandLoggerTests correctly pin start → streamed output → completion ordering for both the success and failure cases.
Previously flagged issue is still unresolved
LoggingCommandLineExecutor.ExecuteAsync still has no try/finally around the inner execute call, so a thrown exception leaves an orphaned "command started" header with no completion line.
src/ModularPipelines/Context/LoggingCommandLineExecutor.cs:49-66
_commandLogger.LogCommandStart(...);
var result = await _inner.ExecuteAsync(commandLine, options, cancellationToken).ConfigureAwait(false);
_commandLogger.LogCommandCompletion(...);This is the same gap called out in review on commit dd0b2f6b — it hasn't changed across the two refactor commits that followed. _inner.ExecuteAsync (the default CommandLineExecutor) can still throw (timeout, missing executable, etc.), and when it does, the header prints with no resolution, no output, and no status. Before this PR that failure mode was silent (no log at all); now it's a dangling, misleading header — exactly the "log block doesn't reflect what happened" class of bug #3550 was about, just on the raw CommandLine/Cmd path instead of the CommandLineToolOptions path.
Command.cs's Of method already demonstrates the right shape here (wrap in try/catch, call LogCommandCompletion via CombineWithCompletionFailure before rethrowing). LoggingCommandLineExecutor should follow the same pattern — a try/catch that logs a failure completion (exit code/duration best-effort, e.g. from the exception) and rethrows, or at minimum a try/finally that guarantees the completion call fires.
Also still true: there is no test coverage for LoggingCommandLineExecutor at all (the new Command_Header_Precedes_Streamed_Output_And_Completion / Failed_Command_Logs_Error_Before_Completion tests both go through ExecuteCommandLineToolAsync → Command.cs's Of, not the raw CommandLine executor), so this path — including the exception scenario — remains unexercised.
New observation: default (Normal) verbosity now always emits a trailing status line
LogCommandStatus (src/ModularPipelines/Logging/CommandLogger.cs:263-280) forces commandStatus to a bare "✓"/"✗" and logs it as its own line whenever BuildCommandStatus returns empty and verbosity is Normal or above:
var commandStatus = BuildCommandStatus(options, isSuccess, exitCode, runTime);
if (string.IsNullOrEmpty(commandStatus) && options.Verbosity >= CommandLogVerbosity.Normal)
{
commandStatus = isSuccess ? "✓" : "✗";
}Under the library's default settings (Verbosity = Normal, ShowExecutionTime = false, ShowExitCode = false), BuildCommandStatus used to return string.Empty for successful commands, and — because the old LogCompact appended it inline onto the single post-execution log line — an empty string was simply invisible. Now that status is always logged as its own Logger.LogInformation call, so every successful command at default verbosity gains an extra ✓ line that didn't exist before. That may well be an intentional trade-off (the header now prints before completion, so a trailing marker helps readers tell when a command finished, especially with interleaved/parallel output) — but it's a visible default-output change for every consumer of this library, it isn't mentioned in the PR description, and none of the existing verbosity tests (Normal_Verbosity_Logs_Input_And_Output etc.) assert on it either way. Worth calling out explicitly (and adding an assertion either confirming or pinning the intended behavior) so it doesn't read as accidental scope creep in the changelog.
Still open (minor, non-blocking, carried over from prior review)
The InternalDryRun short-circuit is still duplicated across LogCommandStart and LogCommandCompletion (CommandLogger.cs:42 and :69). It works today because every call site goes through the paired LogCommandStart/LogCommandCompletion (or the composite Log), but there's nothing preventing a future direct caller from invoking just one and getting inconsistent dry-run output. Not blocking, just worth a comment or a single shared guard if it's touched again.
Summary
Good improvement to log ordering and the tests for the CommandLineToolOptions path are solid, but the exception-safety gap in LoggingCommandLineExecutor was already flagged on this PR and is still present in the current head — that's the one thing I'd want addressed before merge, since it reintroduces (on a different code path) the same "logs don't reflect reality" problem this PR sets out to fix.
|
Codex Review: Didn't find any major issues. Bravo. Reviewed commit: ℹ️ About Codex in GitHubYour team has set up Codex to review pull requests in this repo. Reviews are triggered when you
If Codex has suggestions, it will comment; otherwise it will react with 👍. Codex can also answer questions or update the PR. Try commenting "@codex address that feedback". |
|
Addressed blocking review at 5cf9da9: LoggingCommandLineExecutor now always attempts failure completion and preserves the original execution exception; start-log failures are deferred until after execution; completion entries include command identity. Focused tests pass: CommandLoggerTests 49/49, LoggingCommandLineExecutorTests 2/2, SpectreConsoleLoggerTests 5/5. Core Release build passes. @codex review |
Code review (re-review at
|
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 5cf9da98aa
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
Write command headers before process output and keep completion status at the end so streamed logs read top-down. Refs #3550
5cf9da9 to
257f0b8
Compare
|
Rebased onto current main. Focused command-logging tests pass 56/56; core Release build passes. @codex review |
|
Codex Review: Didn't find any major issues. More of your lovely PRs please. Reviewed commit: ℹ️ About Codex in GitHubYour team has set up Codex to review pull requests in this repo. Reviews are triggered when you
If Codex has suggestions, it will comment; otherwise it will react with 👍. Codex can also answer questions or update the PR. Try commenting "@codex address that feedback". |
Code review (re-review at
|
|
@codex review |
|
Codex Review: Didn't find any major issues. What shall we delve into next? Reviewed commit: ℹ️ About Codex in GitHubYour team has set up Codex to review pull requests in this repo. Reviews are triggered when you
If Codex has suggestions, it will comment; otherwise it will react with 👍. Codex can also answer questions or update the PR. Try commenting "@codex address that feedback". |
|
@codex review |
|
Codex Review: Didn't find any major issues. Chef's kiss. Reviewed commit: ℹ️ About Codex in GitHubYour team has set up Codex to review pull requests in this repo. Reviews are triggered when you
If Codex has suggestions, it will comment; otherwise it will react with 👍. Codex can also answer questions or update the PR. Try commenting "@codex address that feedback". |
Summary
ICommandLoggercompatibility through default lifecycle hooksValidation
CommandLoggerTestspassed with coverageModularPipelines.slnpassed with 0 warnings/errorsCloses #3550