Skip to content

Log command headers before process output - #3580

Open
thomhurst wants to merge 5 commits into
mainfrom
issue-3550-command-log-order
Open

Log command headers before process output#3580
thomhurst wants to merge 5 commits into
mainfrom
issue-3550-command-log-order

Conversation

@thomhurst

Copy link
Copy Markdown
Owner

Summary

  • log each command header immediately before execution starts
  • emit buffered/streamed output after the header and a concise completion status last
  • preserve custom ICommandLogger compatibility through default lifecycle hooks
  • cover success and failure ordering with regression tests

Validation

  • 48 CommandLoggerTests passed with coverage
  • warning-level analyzer gate passed for changed files
  • whitespace verification passed
  • guarded Release build of ModularPipelines.sln passed with 0 warnings/errors

Closes #3550

@thomhurst
thomhurst force-pushed the issue-3550-command-log-order branch from fd44ada to 58ce9ae Compare July 31, 2026 00:37
@thomhurst

Copy link
Copy Markdown
Owner Author

@codex review

@chatgpt-codex-connector chatgpt-codex-connector Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

💡 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".

Comment thread src/ModularPipelines/Logging/CommandLogger.cs Outdated
@thomhurst
thomhurst force-pushed the issue-3550-command-log-order branch from 58ce9ae to dd0b2f6 Compare July 31, 2026 01:07
@thomhurst

Copy link
Copy Markdown
Owner Author

@codex review

@claude claude Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

@chatgpt-codex-connector chatgpt-codex-connector Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

💡 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".

Comment thread src/ModularPipelines/Context/Command.cs Outdated
@thomhurst
thomhurst force-pushed the issue-3550-command-log-order branch from dd0b2f6 to f39153f Compare July 31, 2026 02:13
@thomhurst

Copy link
Copy Markdown
Owner Author

Rebased onto current main; focused command logging suites pass (53 tests). @codex review

@claude claude Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 ExecuteCommandLineToolAsyncCommand.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.

@chatgpt-codex-connector

Copy link
Copy Markdown

Codex Review: Didn't find any major issues. Bravo.

Reviewed commit: f39153f2ff

ℹ️ 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".

@thomhurst

Copy link
Copy Markdown
Owner Author

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

@claude

claude Bot commented Jul 31, 2026

Copy link
Copy Markdown

Code review (re-review at 5cf9da98aa)

Re-checked this against the two blocking/notable points from the earlier reviews on this PR.

✅ Previously blocking issue is now resolved

The earlier reviews flagged that LoggingCommandLineExecutor.ExecuteAsync had no try/finally around the inner ExecuteAsync call, so an exception from execution (timeout, missing executable, etc.) would leave a dangling "command started" header with no completion line.

This is now fixed via the new DeferredCommandLoggingFailures helper (

using System.Runtime.ExceptionServices;
namespace ModularPipelines.Logging;
internal sealed class DeferredCommandLoggingFailures
{
private readonly List<Exception> _failures = [];
public bool HasFailures => _failures.Count > 0;
public void Capture(Action log)
{
try
{
log();
}
catch (Exception exception)
{
_failures.Add(exception);
}
}
public Exception CombineWith(Exception primaryFailure) =>
_failures.Count == 0
? primaryFailure
: new AggregateException([primaryFailure, .. _failures]);
public void Throw()
{
if (_failures.Count == 1)
{
ExceptionDispatchInfo.Capture(_failures[0]).Throw();
}
if (_failures.Count > 1)
{
throw new AggregateException(_failures);
}
}
}
):

  • LoggingCommandLineExecutor.ExecuteAsync now wraps the inner call in try/catch, always logs a completion (exit code -1, error = exception message) before rethrowing, and combines any logging failures with the original exception via AggregateException rather than swallowing either one —
    {
    var workingDirectory = options?.WorkingDirectory ?? Environment.CurrentDirectory;
    var inputToLog = GetInputToLog(commandLine, options);
    var stopwatch = Stopwatch.StartNew();
    var loggingFailures = new DeferredCommandLoggingFailures();
    loggingFailures.Capture(
    () => _commandLogger.LogCommandStart(
    options: null,
    execOpts: options,
    inputToLog: inputToLog,
    commandWorkingDirPath: workingDirectory));
    CommandResult result;
    try
    {
    result = await _inner.ExecuteAsync(commandLine, options, cancellationToken).ConfigureAwait(false);
    }
    catch (Exception executionFailure)
    {
    loggingFailures.Capture(
    () => LogCompletion(
    options,
    inputToLog,
    workingDirectory,
    exitCode: -1,
    runTime: stopwatch.Elapsed,
    standardOutput: string.Empty,
    standardError: executionFailure.Message));
    if (!loggingFailures.HasFailures)
    {
    throw;
    }
    throw loggingFailures.CombineWith(executionFailure);
    }
    loggingFailures.Capture(
    () => LogCompletion(
    options,
    inputToLog,
    workingDirectory,
    result.ExitCode,
    result.Duration,
    result.StandardOutput,
    result.StandardError));
    loggingFailures.Throw();
    return result;
    }
  • Command.cs's Of method was refactored onto the same DeferredCommandLoggingFailures abstraction, which is a nice side benefit: previously CombineWithCompletionFailure only merged the completion-logging failure with the execution exception, silently dropping a LogCommandStart failure. Now start-logging failures are captured too and folded into the combined exception consistently at every exit path (CommandExecutionException catch, generic Exception catch, and the success/failure tail) —
    var loggingFailures = new DeferredCommandLoggingFailures();
    loggingFailures.Capture(
    () => _commandLogger.LogCommandStart(
    options,
    execOpts,
    inputToLog,
    command.WorkingDirPath));
    // Only create timeout token if ExecutionTimeout is specified to avoid unnecessary allocations
    using var timeoutCancellationToken = CreateTimeoutCancellationToken(execOpts);
    // Link the timeout token with the passed cancellation token, or just wrap the original if no timeout
    using var linkedCancellationToken = CreateLinkedCancellationToken(timeoutCancellationToken, cancellationToken);
    using var forcefulCancellationToken = new CancellationTokenSource();
    using var processTreeTerminator = new ProcessTreeTerminator();
    using var processTreeCancellationRegistration =
    forcefulCancellationToken.Token.Register(processTreeTerminator.Kill);
    var registration = linkedCancellationToken.Token.Register(
    () => ScheduleForcefulCancellation(forcefulCancellationToken, execOpts.GracefulShutdownTimeout));
    await using (registration.ConfigureAwait(false))
    {
    CliWrap.CommandResult result;
    try
    {
    var executionTask = command
    .WithStandardOutputPipe(CreateOutputTarget(
    standardOutputBuffer,
    completeStandardOutputBuffer,
    CreateStandardOutputLogger(
    deferredOutputLogger)))
    .WithStandardErrorPipe(CreateOutputTarget(
    standardErrorBuffer,
    completeStandardErrorBuffer,
    CreateStandardErrorLogger(
    deferredOutputLogger)))
    .WithValidation(CommandResultValidation.None)
    .ExecuteAsync(
    configureStartInfo: ConfigureStartInfo,
    configureProcess: processTreeTerminator.Attach,
    forcefulCancellationToken: CancellationToken.None,
    gracefulCancellationToken: linkedCancellationToken.Token);
    using var descendantCaptureRegistration =
    linkedCancellationToken.Token.Register(processTreeTerminator.BeginGracefulShutdown);
    result = await executionTask.ConfigureAwait(false);
    await WaitForForcefulCancellationAsync(
    processTreeTerminator,
    linkedCancellationToken.Token,
    forcefulCancellationToken.Token).ConfigureAwait(false);
    standardOutput = standardOutputBuffer.ToString();
    standardError = standardErrorBuffer.ToString();
    }
    catch (CommandExecutionException e)
    {
    await WaitForForcefulCancellationAsync(
    processTreeTerminator,
    linkedCancellationToken.Token,
    forcefulCancellationToken.Token).ConfigureAwait(false);
    standardOutput = standardOutputBuffer.ToString();
    standardError = standardErrorBuffer.ToString();
    loggingFailures.Capture(
    () => LogCommandCompletion(
    options,
    execOpts,
    inputToLog,
    e.ExitCode,
    stopwatch.Elapsed,
    standardOutput,
    standardError,
    completeStandardOutputBuffer,
    completeStandardErrorBuffer,
    deferredOutputLogger,
    command.WorkingDirPath));
    var failure = loggingFailures.CombineWith(e);
    throw new CommandException(
    CreateFailureResult(
    command,
    execOpts,
    inputToLog,
    e.ExitCode,
    stopwatch.Elapsed,
    standardOutput,
    standardError),
    failure);
    }
    catch (Exception e) when (e is not CommandExecutionException and not CommandException)
    {
    await WaitForForcefulCancellationAsync(
    processTreeTerminator,
    linkedCancellationToken.Token,
    forcefulCancellationToken.Token).ConfigureAwait(false);
    standardOutput = standardOutputBuffer.ToString();
    standardError = standardErrorBuffer.ToString();
    loggingFailures.Capture(
    () => LogCommandCompletion(
    options,
    execOpts,
    inputToLog,
    -1,
    stopwatch.Elapsed,
    standardOutput,
    standardError,
    completeStandardOutputBuffer,
    completeStandardErrorBuffer,
    deferredOutputLogger,
    command.WorkingDirPath));
    var failure = loggingFailures.CombineWith(e);
    if (ShouldPreserveCallerCancellation(e, failure, cancellationToken))
    {
    throw;
    }
    throw CreateExecutionFailure(
    e,
    failure,
    command,
    execOpts,
    inputToLog,
    stopwatch.Elapsed,
    standardOutput,
    standardError,
    cancellationToken,
    timeoutCancellationToken);
    }
    var commandFailure = CreateCommandFailure(
    command,
    result,
    execOpts,
    inputToLog,
    standardOutput,
    standardError);
    loggingFailures.Capture(
    () => LogCommandCompletion(
    options,
    execOpts,
    inputToLog,
    result.ExitCode,
    result.RunTime,
    standardOutput,
    standardError,
    completeStandardOutputBuffer,
    completeStandardErrorBuffer,
    deferredOutputLogger,
    command.WorkingDirPath));
    if (commandFailure is not null && loggingFailures.HasFailures)
    {
    throw new CommandException(
    commandFailure.Result,
    loggingFailures.CombineWith(commandFailure));
    }
    if (commandFailure is not null)
    {
    throw commandFailure;
    }
    loggingFailures.Throw();
    return new CommandResult(command, result, standardOutput, standardError);
    }
  • The previously-missing regression coverage is now present: LoggingCommandLineExecutorTests.InnerFailureStillLogsCompletion / StartLoggingFailureDoesNotPreventExecution exercise the raw CommandLine path directly (
    using ModularPipelines.Context;
    using ModularPipelines.Logging;
    using ModularPipelines.Models;
    using ModularPipelines.Options;
    namespace ModularPipelines.UnitTests.Context;
    public class LoggingCommandLineExecutorTests
    {
    [Test]
    public async Task InnerFailureStillLogsCompletion()
    {
    var expectedException = new InvalidOperationException("Execution failed.");
    var logger = new RecordingCommandLogger();
    var executor = new LoggingCommandLineExecutor(
    new StubCommandLineExecutor(
    (_, _, _) => Task.FromException<CommandResult>(expectedException)),
    logger);
    var exception = await Assert.ThrowsAsync<InvalidOperationException>(
    () => executor.ExecuteAsync(new CommandLine("tool", [])));
    using (Assert.Multiple())
    {
    await Assert.That(exception).IsSameReferenceAs(expectedException);
    await Assert.That(logger.Events).Count().IsEqualTo(2);
    await Assert.That(logger.Events[0]).IsEqualTo("start");
    await Assert.That(logger.Events[1]).IsEqualTo("completion");
    await Assert.That(logger.CompletionExitCode).IsEqualTo(-1);
    await Assert.That(logger.CompletionError).IsEqualTo(expectedException.Message);
    }
    }
    [Test]
    public async Task StartLoggingFailureDoesNotPreventExecution()
    {
    var expectedException = new InvalidOperationException("Logging failed.");
    var executed = false;
    var logger = new RecordingCommandLogger
    {
    StartFailure = expectedException,
    };
    var result = CreateResult();
    var executor = new LoggingCommandLineExecutor(
    new StubCommandLineExecutor((_, _, _) =>
    {
    executed = true;
    return Task.FromResult(result);
    }),
    logger);
    var exception = await Assert.ThrowsAsync<InvalidOperationException>(
    () => executor.ExecuteAsync(new CommandLine("tool", [])));
    using (Assert.Multiple())
    {
    await Assert.That(executed).IsTrue();
    await Assert.That(exception).IsSameReferenceAs(expectedException);
    await Assert.That(logger.Events).Count().IsEqualTo(2);
    await Assert.That(logger.Events[1]).IsEqualTo("completion");
    }
    }
    private static CommandResult CreateResult()
    {
    var timestamp = DateTimeOffset.UtcNow;
    return new CommandResult(
    "tool",
    Environment.CurrentDirectory,
    string.Empty,
    string.Empty,
    new Dictionary<string, string?>(),
    timestamp,
    timestamp,
    TimeSpan.Zero,
    0);
    }
    private sealed class StubCommandLineExecutor(
    Func<CommandLine, CommandExecutionOptions?, CancellationToken, Task<CommandResult>> execute)
    : ICommandLineExecutor
    {
    public Task<CommandResult> ExecuteAsync(
    CommandLine commandLine,
    CommandExecutionOptions? options = null,
    CancellationToken cancellationToken = default) =>
    execute(commandLine, options, cancellationToken);
    }
    private sealed class RecordingCommandLogger : ICommandLogger
    {
    public List<string> Events { get; } = [];
    public Exception? StartFailure { get; init; }
    public int? CompletionExitCode { get; private set; }
    public string? CompletionError { get; private set; }
    public void LogCommandStart(
    CommandLineToolOptions? options,
    CommandExecutionOptions? execOpts,
    string? inputToLog,
    string commandWorkingDirPath)
    {
    Events.Add("start");
    if (StartFailure is not null)
    {
    throw StartFailure;
    }
    }
    public void LogCommandCompletion(
    CommandLineToolOptions? options,
    CommandExecutionOptions? execOpts,
    string? inputToLog,
    int? exitCode,
    TimeSpan? runTime,
    string standardOutput,
    string standardError,
    string commandWorkingDirPath)
    {
    Events.Add("completion");
    CompletionExitCode = exitCode;
    CompletionError = standardError;
    }
    public void Log(
    CommandLineToolOptions? options,
    CommandExecutionOptions? execOpts,
    string? inputToLog,
    int? exitCode,
    TimeSpan? runTime,
    string standardOutput,
    string standardError,
    string commandWorkingDirPath)
    {
    }
    }
    }
    ), and CommandLoggerTests.HeaderLoggingFailureDoesNotPreventCommandExecution pins the equivalent guarantee (execution still happens, side effect observed, failure surfaced as AggregateException) on the Command.cs path.

Good fix — this closes the exact gap called out on the previous two review passes, and generalizing it into a shared helper used by both call sites is a cleaner outcome than patching LoggingCommandLineExecutor in isolation.

Still open (both already flagged as non-blocking, unchanged since the last review)

  • Default Normal verbosity now always emits a trailing / status line for successful commands (CommandLogger.LogCommandStatus, src/ModularPipelines/Logging/CommandLogger.cs), where previously an empty BuildCommandStatus() was invisible because it was appended inline. This is a visible default-output change for every consumer and still isn't covered by an assertion either way (Normal_Verbosity_Logs_Input_And_Output doesn't check for/against the trailing line). Not required for this PR, but worth a one-line changelog/test callout if it's intentional.
  • The InternalDryRun short-circuit is still duplicated between LogCommandStart and LogCommandCompletion. Harmless today since every call site goes through the paired calls (or the composite Log), but still no single guard preventing a future direct caller from getting inconsistent dry-run output.

Neither of these blocks merge — they were called out as minor/non-blocking last time and nothing about them changed in this update.

Summary

The blocking exception-safety issue is resolved with solid, targeted regression tests on both affected code paths. No new issues introduced by this round of changes. LGTM.

@chatgpt-codex-connector chatgpt-codex-connector Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

💡 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".

Comment thread src/ModularPipelines/Context/Command.cs Outdated
@thomhurst
thomhurst force-pushed the issue-3550-command-log-order branch from 5cf9da9 to 257f0b8 Compare July 31, 2026 02:57
@thomhurst

Copy link
Copy Markdown
Owner Author

Rebased onto current main. Focused command-logging tests pass 56/56; core Release build passes. @codex review

@chatgpt-codex-connector

Copy link
Copy Markdown

Codex Review: Didn't find any major issues. More of your lovely PRs please.

Reviewed commit: 257f0b81b0

ℹ️ 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".

@claude

claude Bot commented Jul 31, 2026

Copy link
Copy Markdown

Code review (re-review at 257f0b81b0)

Re-reviewed this PR against the state at the time of the last Claude review (5cf9da98aa, on the pre-rebase branch history). All 8 PR-touched files have real content changes since then (the branch was rebased and Command.cs / LoggingCommandLineExecutor.cs were further refactored to route logging failures through the new shared DeferredCommandLoggingFailures helper), so this was a full re-review, not a rubber stamp.

Findings

No high-confidence bugs or CLAUDE.md violations found in the current diff.

I specifically chased down one candidate issue that looked real on static reading: DeferredCommandLoggingFailures.Throw() (

public void Throw()
{
if (_failures.Count == 1)
{
ExceptionDispatchInfo.Capture(_failures[0]).Throw();
}
if (_failures.Count > 1)
{
throw new AggregateException(_failures);
}
}
) only wraps captured failures in an AggregateException when there are 2+, whereas the new test HeaderLoggingFailureDoesNotPreventCommandExecution (CommandLoggerTests.cs) expects an AggregateException for a single LogCommandStart failure. I built and ran that specific test (--treenode-filter '/*/*/*/HeaderLoggingFailureDoesNotPreventCommandExecution') rather than trusting the static trace, and it passes: Microsoft.Extensions.Logging's own composite Logger.Log already wraps a single provider's thrown exception in an AggregateException before it ever reaches DeferredCommandLoggingFailures.Capture, so the observed behavior is correct. (The equivalent LoggingCommandLineExecutorTests test uses a hand-written ICommandLogger mock that bypasses ILogger entirely, which is why it correctly expects the unwrapped exception instead — the two tests aren't actually contradictory once you account for where each failure is manufactured.) Flagging this only so the reasoning is on record in case it comes up again.

Previously flagged, still open (both already called out as non-blocking in the prior review, unchanged in this update — confirmed, not re-flagging as new)

  • CommandLogger.LogCommandStatus still always emits a trailing ✓ {input} line at default Normal verbosity for successful commands, which is a visible default-output change from pre-PR behavior and still isn't asserted either way by Normal_Verbosity_Logs_Input_And_Output.
  • The InternalDryRun short-circuit is still duplicated between CommandLogger.LogCommandStart and CommandLogger.LogCommandCompletion (
    var effectiveOptions = GetEffectiveLoggingOptions(options, execOpts);
    if (effectiveOptions.Verbosity == CommandLogVerbosity.Silent)
    {
    return;
    }
    if (execOpts?.InternalDryRun == true)
    {
    LogDryRunCommand(effectiveOptions, commandWorkingDirPath, inputToLog);
    return;
    }
    var obfuscatedInput = ShouldShowInput(effectiveOptions)
    ? _secretObfuscator.Obfuscate(inputToLog, null)
    : LoggingConstants.CommandMask;
    Logger.LogInformation(
    "{WorkingDirectory}> {Input}",
    commandWorkingDirPath,
    obfuscatedInput);
    }
    public void LogCommandCompletion(
    CommandLineToolOptions? options,
    CommandExecutionOptions? execOpts,
    string? inputToLog,
    int? exitCode,
    TimeSpan? runTime,
    string standardOutput,
    string standardError,
    string commandWorkingDirPath)
    {
    var effectiveOptions = GetEffectiveLoggingOptions(options, execOpts);
    if (effectiveOptions.Verbosity == CommandLogVerbosity.Silent
    || execOpts?.InternalDryRun == true)
    {
    return;
    }
    ). Since both methods now share the same GetEffectiveLoggingOptions/verbosity-gate shape, pulling the dry-run check into one shared private helper (e.g. TryGetEffectiveOptions(...) returning null when logging should be skipped) would remove the duplicate condition and guarantee any future third call site can't get an inconsistent dry-run/silent gate by construction — worth doing opportunistically, not blocking.

Summary

The command-start/output/completion ordering change, the DeferredCommandLoggingFailures consolidation, and the backward-compatible default-interface-method design on ICommandLogger (no-op LogCommandStart, LogCommandCompletion falling back to Log) are solid. New regression tests (Command_Header_Precedes_Streamed_Output_And_Completion, Failed_Command_Logs_Error_Before_Completion, HeaderLoggingFailureDoesNotPreventCommandExecution, InnerFailureStillLogsCompletion, StartLoggingFailureDoesNotPreventExecution) directly exercise the ordering and failure-preservation guarantees the PR is about. LGTM.

@thomhurst

Copy link
Copy Markdown
Owner Author

@codex review

@chatgpt-codex-connector

Copy link
Copy Markdown

Codex Review: Didn't find any major issues. What shall we delve into next?

Reviewed commit: f88f182f71

ℹ️ 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".

@thomhurst

Copy link
Copy Markdown
Owner Author

@codex review

@chatgpt-codex-connector

Copy link
Copy Markdown

Codex Review: Didn't find any major issues. Chef's kiss.

Reviewed commit: f88f182f71

ℹ️ 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".

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Logging: command echo is written after its own output - command blocks read bottom-up

1 participant