[containers] Docker executable invocations do not log stdout/stderr in production (NullLogger + Debug-only success path)

[JoshuaRowePhantom]

Summary

Invocations of the docker executable do not log their standard output or standard error in production. Two independent gaps cause this: (1) the production Mongo path constructs the Docker engine with a NullLogger, so all docker stdout/stderr is silently discarded; and (2) even when a real ILogger is supplied, successful runs log only the combined output at Debug level, so at default log levels docker output is invisible. The requirement is that invocations of the docker executable log BOTH standard output and standard error, on success and on failure.

Docker is invoked via DockerCommandRunner.RunAsync -> ProcessRunner.RunAndLogAsync -> ProcessRunner.RunProcessAsync.

Root Cause

1. NullLogger in the production Mongo path

Phantom.Workspaces.Data.MongoDB\MongoDbConnectionBroker.cs (line ~35) constructs the engine with the PARAMETERLESS constructor:

_containerEngine = containerEngine ?? new WindowsDockerDesktopEngine();

Phantom.Workspaces.Containers\WindowsDockerDesktopEngine.cs (lines ~11-14): the parameterless ctor wires a NullLogger:

public WindowsDockerDesktopEngine()
    : this(new DockerCommandRunner(NullLogger<DockerCommandRunner>.Instance))
{
}

So EVERY docker command run by the broker (info, container inspect, create, start, stop, rm) logs to NullLogger -> all stdout/stderr is silently discarded. Phantom.Workspaces.Data.MongoDB.Tests\MongoDbTestDatabaseFixture.cs (line ~23) does the same:

private readonly ContainerEngine _containerEngine = new WindowsDockerDesktopEngine();

2. Success output only at Debug, combined stream only

Even when a real ILogger is supplied, Phantom.Workspaces.Data.Core\ProcessRunner.cs RunAndLogAsync (lines ~158-200) logs the COMBINED stdout+stderr blob only at LogDebug on success (exit 0), at LogWarning on non-zero exit, and LogError on timeout:

if (result.ExitCode != 0)
{
    logger.LogWarning(
        "Process '{Command}' exited with code {ExitCode}{Description}.\nOutput:\n{Output}",
        ...
        result.StandardOutAndError);
}
else if (!string.IsNullOrWhiteSpace(result.StandardOutAndError))
{
    logger.LogDebug(
        "Process '{Command}' completed successfully{Description}.\nOutput:\n{Output}",
        ...
        result.StandardOutAndError);
}

On a normal successful run at default log levels, docker output is invisible. stdout and stderr are captured SEPARATELY into ProcessResult (ProcessRunner.cs lines ~146-150), but only the combined StandardOutAndError blob is ever logged:

return new ProcessResult(
    process.ExitCode,
    string.Join(Environment.NewLine, stdoutLines),
    string.Join(Environment.NewLine, stderrLines),
    string.Join(Environment.NewLine, combinedLines));

3. Failure exception surfaces only stderr

WindowsDockerDesktopEngine.RunAndEnsureSuccessAsync (lines ~135-151) throws on failure but includes only result.StandardError in the exception message; stdout on failure is not surfaced there. (It IS in the Warning log, but only when a real logger is wired -- which it is not in the broker path.)

throw new InvalidOperationException(
    $"Docker command failed: docker {string.Join(' ', arguments)}{Environment.NewLine}" +
    $"{result.StandardError}".TrimEnd());

Impact

When the Mongo container fails to create/start (image pull failure, port conflict, mount error, Atlas Local startup error), docker's actual stdout/stderr -- the only useful diagnostic -- is thrown away because the broker uses NullLogger. Users and maintainers diagnosing container issues (e.g. related to the slow/flaky container-connect tests and first-run image pulls) get no docker output at all.

Affected Files

File	Role
Phantom.Workspaces.Data.MongoDB\MongoDbConnectionBroker.cs	Line ~35 uses parameterless WindowsDockerDesktopEngine() -> NullLogger; must pass a real logger
Phantom.Workspaces.Containers\WindowsDockerDesktopEngine.cs	Parameterless ctor (line ~11) wires NullLogger; ctor selection
Phantom.Workspaces.Containers\DockerCommandRunner.cs	Routes all docker commands through ProcessRunner.RunAndLogAsync with its ILogger
Phantom.Workspaces.Data.Core\ProcessRunner.cs	RunAndLogAsync logs combined output only at Debug on success (lines ~181-197); should log stdout+stderr at a visible level
Phantom.Workspaces.Data.MongoDB.Tests\MongoDbTestDatabaseFixture.cs	Line ~23 also uses parameterless ctor

Design / Fix

Make docker invocations always log stdout AND stderr through a real logger.

Recommended

1. Wire a real logger into the broker's engine. Give MongoDbConnectionBroker access to an ILoggerFactory/ILogger<DockerCommandRunner> (constructor param, defaulting to something non-null) and construct new WindowsDockerDesktopEngine(logger) (the ILogger<DockerCommandRunner> ctor at WindowsDockerDesktopEngine.cs line ~16) instead of the parameterless ctor. Do the same for MongoDbTestDatabaseFixture (use a test logger). Avoid the NullLogger default silently swallowing output in production -- the parameterless ctor should be reserved for tests, or removed/guarded.

2. Log stdout and stderr on every invocation, not just failures. In ProcessRunner.RunAndLogAsync, raise the success log level for external-command output above Debug (e.g. Information, or a caller-selectable level), and/or log stdout and stderr as distinct fields rather than only the combined blob, so both streams are always visible. Consider adding an option so callers (docker) opt into always-log-at-Information. The exact level is a design decision, but the requirement is that docker stdout AND stderr are logged on both success and failure.

Considered / Background

Current behavior (Debug-only combined output, NullLogger in broker) -- rejected because docker output is invisible exactly when it is needed (container create/start failures).

Expected Tests

Existing tests: Phantom.Workspaces.Data.Core.Tests\ProcessRunnerTests.cs (namespace Phantom.Workspaces.Data.Tests) already has a FakeLogger : ILogger capturing (LogLevel Level, string Message) and tests such as RunAndLogAsync_ProcessSucceeds_LogsStdoutAtDebugLevel (which currently asserts Debug and will need updating). Phantom.Workspaces.Containers.Tests\WindowsDockerDesktopEngineTests.cs uses a fake RecordingDockerCommandRunner. New tests should match these classes and styles.

Test Name	Class	What It Verifies
ProcessRunner_RunAndLogAsync_OnSuccess_LogsStandardOutputAndStandardError	ProcessRunnerTests	A FakeLogger receives both stdout and stderr content at a non-Debug (visible) level on exit 0
ProcessRunner_RunAndLogAsync_OnFailure_LogsStandardOutputAndStandardError	ProcessRunnerTests	Both stdout and stderr are logged on non-zero exit
MongoDbConnectionBroker_UsesLoggingDockerEngine_DoesNotUseNullLogger	MongoDbConnectionBrokerTests (broker/engine test)	The production path constructs an engine whose command runner is wired with a real, non-null logger, so docker output is no longer silently discarded

Note: existing RunAndLogAsync_ProcessSucceeds_LogsStdoutAtDebugLevel / RunAndLogAsync_ProcessSucceeds_LogsStderrAtDebugLevel / RunAndLogAsync_NoLogCall_WhenExitCodeIsZero will need to be updated to reflect the new visible success-log level.

[JoshuaRowePhantom]

Design

Root cause 1 (NullLogger): MongoDbConnectionBroker builds the engine via the parameterless WindowsDockerDesktopEngine() ctor, which hard-wires NullLogger<DockerCommandRunner> — every docker stdout/stderr is discarded.

Root cause 2 (Debug-only, combined-only): ProcessRunner.RunAndLogAsync logs the combined blob only at LogDebug on success, so at default levels docker output is invisible; stdout/stderr are captured separately but never logged as distinct fields.

Approach:

1. ProcessRunner.RunAndLogAsync: on success (exit 0) log stdout and stderr as distinct fields at Information (visible). On non-zero exit, keep Warning but include both StandardOut and StandardError distinctly. Timeout stays Error.
2. Remove the parameterless WindowsDockerDesktopEngine() NullLogger ctor from production; the engine now always requires a logger (or an explicit command runner). Tests pass a logger/NullLogger explicitly.
3. MongoDbConnectionBroker gains an ILogger<DockerCommandRunner>? ctor param and builds new WindowsDockerDesktopEngine(logger) — a supplied logger flows through to the command runner instead of being replaced by NullLogger. MongoDbTestDatabaseFixture passes a test logger.
4. WindowsDockerDesktopEngine.RunAndEnsureSuccessAsync surfaces stdout in addition to stderr on failure.

Files: ProcessRunner.cs, WindowsDockerDesktopEngine.cs, DockerCommandRunner.cs (expose logger internally), MongoDbConnectionBroker.cs, MongoDbTestDatabaseFixture.cs, Containers.csproj (InternalsVisibleTo MongoDB.Tests), plus tests.

Tests: ProcessRunner_RunAndLogAsync_OnSuccess_LogsStandardOutputAndStandardError, ProcessRunner_RunAndLogAsync_OnFailure_LogsStandardOutputAndStandardError, MongoDbConnectionBroker_UsesLoggingDockerEngine_DoesNotUseNullLogger; update existing RunAndLogAsync_ProcessSucceeds_LogsStdoutAtDebugLevel / ...LogsStderrAtDebugLevel / RunAndLogAsync_NoLogCall_WhenExitCodeIsZero for the new visible level.

[JoshuaRowePhantom]

Verification result

Status: ❌ 1 issue(s) found
Scope: This verification covers #1373 only (commit 30cc02e6). Commit 53442cfe (#1374) is verified separately.
Commits checked:
53442cf Fix #1374: pull docker image before creating the Mongo container
30cc02e Fix #1373: log docker stdout and stderr through a real logger

What was verified (passing)

• ProcessRunner.RunAndLogAsync (root cause 2): ✅ Now logs StandardOut and StandardError as distinct fields at Information on success (exit 0) and Warning on non-zero exit; timeout stays Error. Combined-blob/Debug-only behavior removed. (ProcessRunner.cs)
• Engine NullLogger ctor: ✅ The parameterless WindowsDockerDesktopEngine() (which wired NullLogger) is now internal and documented as tests-only. Broker no longer calls it; it builds new WindowsDockerDesktopEngine(logger) via the ILogger<DockerCommandRunner> ctor. Failure exceptions now surface stdout and stderr.
• Test fixture: ✅ MongoDbTestDatabaseFixture now passes an explicit NullLogger<DockerCommandRunner>.Instance instead of the parameterless ctor.
• Existing tests updated consistently (req 3): ✅ ...LogsStdoutAtDebugLevel / ...LogsStderrAtDebugLevel renamed to ...AtInformationLevel and assert LogLevel.Information. RunAndLogAsync_NoLogCall_WhenExitCodeIsZero remains valid (no output ⇒ no log) and does not assert Debug.
• New tests present & passing (req 4): ✅ ProcessRunner_RunAndLogAsync_OnSuccess_LogsStandardOutputAndStandardError (Information, both streams), ProcessRunner_RunAndLogAsync_OnFailure_LogsStandardOutputAndStandardError (Warning, both streams), MongoDbConnectionBroker_UsesLoggingDockerEngine_DoesNotUseNullLogger. All run in fast mode (not SlowDocker) and pass. InternalsVisibleTo wiring for the broker/engine/runner internals is correct.

Outstanding gaps

1. Root cause 1 is not actually resolved in the shipping production path — the three production entry points still yield a NullLogger. MongoDbConnectionBroker's new dockerCommandRunnerLogger param defaults to NullLogger<DockerCommandRunner>.Instance (MongoDbConnectionBroker.cs), and every production caller constructs the broker with no logger:

   • Phantom.Workspaces\EntityRepository.cs:180 — new MongoDbConnectionBroker()
   • Phantom.Workspaces.Llm.Core\AgentPersistenceStoreFactory.cs:55 — new MongoDbConnectionBroker()
   • Phantom.Workspaces.Llm.Core\FilesystemEditStoreFactory.cs:52 — new MongoDbConnectionBroker()

   Net effect at runtime is identical to before the fix: docker stdout/stderr is still discarded via NullLogger in production. The issue's Summary/Impact require docker output to be logged in production; the plumbing was added but never connected to a real ILogger/ILoggerFactory at the production call sites. The passing MongoDbConnectionBroker_UsesLoggingDockerEngine_DoesNotUseNullLogger test only proves that when a logger is supplied it flows through — it does not exercise the default (no-arg) production path, which still resolves to NullLogger. Fix: thread a real ILogger<DockerCommandRunner> (e.g. from an ILoggerFactory) into the broker at these three call sites so the production Mongo path surfaces docker output.

Tests

Passed!  - Failed: 0, Passed: 20, Skipped: 0, Total: 20 - Phantom.Workspaces.Data.Core.Tests.dll (net10.0)
Passed!  - Failed: 0, Passed:  1, Skipped: 0, Total:  1 - Phantom.Workspaces.Data.MongoDB.Tests.dll (net10.0)

=== Test Run Summary ===
Executed : 21
Passed   : 21
Failed   : 0

Note: diff touches the Docker/container engine and MongoDB data-access layers → needs-slow-tests applied so checkin runs the full suite (incl. SlowDocker broker/engine tests).

[JoshuaRowePhantom]

Verification result

Status: ✅ Verified
Scope: This verification covers #1373 only. #1374-specific concerns (docker pull) are verified separately.
Commits checked:
8e1be66 Fix #1373: keep gh auth token output at Debug, not Information
614409f Fix #1373: wire real docker logger into production MongoDb broker call sites
53442cf Fix #1374: pull docker image before creating the Mongo container
30cc02e Fix #1373: log docker stdout and stderr through a real logger

Prior gap — now CLOSED

The previous verification flagged one gap: the broker's dockerCommandRunnerLogger defaulted to NullLogger and the three production call sites (EntityRepository.cs:180, AgentPersistenceStoreFactory.cs:55, FilesystemEditStoreFactory.cs:52) constructed new MongoDbConnectionBroker() with no logger, so production still discarded docker output.

This is now closed via a process-wide ambient logger factory (DockerCommandRunnerLogging):

• MongoDbConnectionBroker default ctor now falls back to DockerCommandRunnerLogging.CreateLogger() when no logger is supplied (MongoDbConnectionBroker.cs:45-46), so the no-arg production call sites log through the real logger.
• All four app hosts initialize the ambient factory at startup with their real ILoggerFactory: Agent.Cli/Program.cs, Agent.Gui/Program.cs, Web.Server/Program.cs (app.Services.GetRequiredService<ILoggerFactory>()), and App.axaml.cs (LoggingBootstrap factory).
• Degrades to NullLogger when uninitialized (NullLoggerFactory sentinel) — keeps unit tests quiet. Proven by MongoDbConnectionBroker_DefaultConstructor_WhenAmbientUninitialized_UsesNullLogger and DockerCommandRunnerLoggingTests.CreateLogger_WhenUninitialized_ReturnsNullLogger.

Requirements verified

1. Production default path logs through a real, non-null logger ✅ — ambient factory wired at all four hosts; default broker ctor consumes it. New test MongoDbConnectionBroker_DefaultConstructor_AfterAmbientInit_UsesRealLoggerNotNullLogger proves the no-arg production path yields a real logger.
2. ProcessRunner.RunAndLogAsync logs stdout AND stderr, on success and failure, at a visible level by default ✅ — success logs both distinct fields at Information (new successLogLevel param, default Information); non-zero exit at Warning with both streams; timeout at Error. DockerCommandRunner.RunAsync uses the default (Information), so docker stays visible. GitHubAuthTokenResolver deliberately requests LogLevel.Debug — a correct carve-out so sensitive token output is not surfaced at Information; it does not affect the docker executable.
3. Test exercising the default/production wiring ✅ — MongoDbConnectionBroker_DefaultConstructor_AfterAmbientInit_UsesRealLoggerNotNullLogger + uninitialized companion + DockerCommandRunnerLoggingTests; plus ProcessRunner_RunAndLogAsync_OnSuccess/OnFailure_LogsStandardOutputAndStandardError.
4. Existing tests updated consistently ✅ — ...LogsStdoutAtDebugLevel/...LogsStderrAtDebugLevel renamed to ...AtInformationLevel and assert Information; RunAndLogAsync_NoLogCall_WhenExitCodeIsZero still valid. GitHubAuthTokenResolverTests assert Debug (carve-out) and pass. No leftover Debug-only docker success assertions.

Docker-dependent tests are correctly gated as [Category=SlowDocker] (e.g. WindowsDockerDesktopEngineSlowTests, MongoDbConnectionBrokerSlowTests) and run only in full mode.

Outstanding gaps

None — all criteria satisfied.

Tests

.\scripts\run-tests.ps1 -TestNames ProcessRunnerTests,MongoDbConnectionBrokerDockerDesktopTests,DockerCommandRunnerLoggingTests,GitHubAuthTokenResolverTests

Passed!  - Failed: 0, Passed:  3, Skipped: 0, Total:  3 - Phantom.Workspaces.Containers.Tests.dll (net10.0)
Passed!  - Failed: 0, Passed: 20, Skipped: 0, Total: 20 - Phantom.Workspaces.Data.Core.Tests.dll (net10.0)
Passed!  - Failed: 0, Passed: 10, Skipped: 0, Total: 10 - Phantom.Workspaces.Data.MongoDB.Tests.dll (net10.0)
Passed!  - Failed: 0, Passed:  5, Skipped: 0, Total:  5 - Phantom.Workspaces.Llm.Core.Tests.dll (net10.0)

=== Test Run Summary ===
Executed : 38
Passed   : 38
Failed   : 0

Note: diff touches the MongoDB data-access layer and container engine → needs-slow-tests applied so checkin runs the full suite (incl. SlowDocker broker/engine tests).

[JoshuaRowePhantom]

Checked in

Commit: 8e1be66
Branch fast-forwarded: features → 8e1be66

Fast suite: 5866 passed, 0 failed. Full suite: 6050 passed, 0 failed. Stability run (ProcessRunnerTests, WindowsDockerDesktopEngineTests, MongoDbConnectionBrokerDockerDesktopTests, DockerCommandRunnerLoggingTests, GitHubAuthTokenResolverTests): 10/10 passed.

Known-flaky #791 (AgentFactoryTests.CreateAgentChat_UsesAgentDefinitionChatHistoryTool, MongoDB server-selection timing hang) recurred in the full run and was confirmed unrelated via hang-dump analysis (block in Cluster.SelectServerAsync under ConnectContainerAsync, not the docker pull/logging changes). Dump archived to dumps\791\. Not blocking.