Skip to content

Ignore stale MSBuild server console writes - #14850

Merged
JanProvaznik merged 4 commits into
dotnet:mainfrom
JanProvaznik:janprovaznik/ignore-stale-server-console-writes
Aug 28, 2026
Merged

Ignore stale MSBuild server console writes#14850
JanProvaznik merged 4 commits into
dotnet:mainfrom
JanProvaznik:janprovaznik/ignore-stale-server-console-writes

Conversation

@JanProvaznik

@JanProvaznik JanProvaznik commented Aug 26, 2026

Copy link
Copy Markdown
Member

Problem

MSBuild Server installs request-scoped RedirectConsoleWriter instances as Console.Out and Console.Error while a build runs, then flushes and disposes them when the request completes.

Microsoft.Sbom.Targets 4.1.5 reaches Spectre.Console through Component Detection. Spectre caches the first request's Console.Out in a process-wide singleton. When a second Pack request reuses the server, SBOM generation writes through that disposed writer and raises ObjectDisposedException. The SBOM task catches the exception, so Pack still exits successfully, but the generated manifest loses its detected dependencies.

This is the failure reported in #14691.

Change

After its final request flush, RedirectConsoleWriter replaces its internal destination with TextWriter.Null before disposing the request buffer. Later writes through a retained reference are discarded rather than throwing or being forwarded to another build client.

The writer continues reporting the buffer encoding after disposal. The existing timer behavior and synchronization are unchanged.

No ChangeWave is required: this is limited to MSBuild Server, removes a failure/warning path, and does not change build outputs.

Unit regression test

WriteAfterDispose_IsDiscardedWithoutThrowingOrInvokingCallback verifies that:

  • Output written before disposal is forwarded by the final flush.
  • Writes and flushes after disposal do not throw.
  • Writes after disposal do not invoke the forwarding callback.

Before the implementation change, the test failed on both net10.0 and net472 with:

System.ObjectDisposedException: Cannot write to a closed TextWriter.

After merging current main, all RedirectConsoleWriter_Tests pass on both net11.0 and .NET Framework.

End-to-end Microsoft.Sbom.Targets reproduction

The test project used the actual affected task and a package dependency for Component Detection to find:

<PropertyGroup>
  <TargetFramework>net10.0</TargetFramework>
  <GenerateSBOM>true</GenerateSBOM>
</PropertyGroup>
<ItemGroup>
  <PackageReference Include="Microsoft.Sbom.Targets" Version="4.1.5" PrivateAssets="all" />
  <PackageReference Include="Newtonsoft.Json" Version="13.0.3" />
</ItemGroup>

A small inline MSBuild task logged the executing process ID. For each comparison, bootstrap MSBuild was rebuilt from a clean worktree, the project was compiled before measurement, the server was shut down to guarantee a cold start, and two separate Pack requests were issued. NoBuild=true keeps the measurement focused on server-hosted SBOM generation:

.\build.cmd -v quiet

$dotnet = '<worktree>\artifacts\bin\bootstrap\core\dotnet.exe'
$msbuild = '<worktree>\artifacts\bin\bootstrap\core\sdk\11.0.100-rc.1.26420.103\MSBuild.dll'

& $dotnet build-server shutdown
$env:MSBUILDUSESERVER = '1'

& $dotnet $msbuild SbomTaskRepro.csproj -t:Pack -p:Configuration=Release -p:NoBuild=true -v:m
& $dotnet $msbuild SbomTaskRepro.csproj -t:Pack -p:Configuration=Release -p:NoBuild=true -v:m

Results

Build Server reuse First request Second request Manifest after request 2 Exit codes
PR base 326f6a7ab2 PID 25164 for both requests Component Detection succeeded; TotalNumberOfPackages=4 Three ObjectDisposedException warnings plus There were no packages detected 1 package: only SbomTaskRepro; Newtonsoft.Json was missing 0, 0
Merged PR head bf0825c5dc PID 9980 for both requests Component Detection succeeded; TotalNumberOfPackages=4 No ObjectDisposedException; TotalNumberOfPackages=4 4 packages, including Newtonsoft.Json 0, 0

The base failure was the same stack reported in #14691:

Unknown error while running CD scan: System.ObjectDisposedException:
Cannot write to a closed TextWriter.
   at Microsoft.Build.Experimental.OutOfProcServerNode.RedirectConsoleWriter.Write(String value)
   at System.IO.TextWriter.SyncTextWriter.Write(String value)
   at Spectre.Console.AnsiConsoleBackend.Write(IRenderable renderable)
   at Microsoft.ComponentDetection.Orchestrator.Services.DetectorProcessingService.LogTabularOutput(...)

The identical PID within each pair proves that the second pack reused the same MSBuild Server and the same Spectre singleton. On the PR build, the second request still completed component detection and preserved the dependency data; only output sent through Spectre's stale first-request writer was discarded.

Addresses #14691.

After a server build completes, switch its redirect writer to a null sink so tasks retaining Console.Out cannot fail a later build. Add regression coverage for write-after-dispose behavior.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>

Copilot-Session: fa3f99a2-bb35-4d8c-9381-91d8d05e752a
Limit the compatibility fix to post-disposal writes and leave the existing timer callback locking behavior unchanged.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>

Copilot-Session: fa3f99a2-bb35-4d8c-9381-91d8d05e752a
@JanProvaznik

Copy link
Copy Markdown
Member Author

Note this is a workaround at a lower level for hard to update internal consumer. The contract is Console APIs are banned in tasks and in code transitively reachable by tasks.

@JanProvaznik
JanProvaznik marked this pull request as ready for review August 27, 2026 11:46
Copilot AI lite review requested due to automatic review settings August 27, 2026 11:46

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Pull request overview

Fixes MSBuild Server reuse scenarios where third-party code (Spectre.Console via Microsoft.Sbom.Targets) retains a stale Console.Out/Console.Error reference and later writes through a disposed RedirectConsoleWriter, causing ObjectDisposedException and lost SBOM dependency data.

Changes:

  • Update RedirectConsoleWriter disposal to swap its destination to TextWriter.Null so late writes are discarded rather than throwing.
  • Add a unit test verifying that writes after Dispose() neither throw nor invoke the forwarding callback.

Reviewed changes

Copilot reviewed 2 out of 2 changed files in this pull request and generated no comments.

File Description
src/Build/BackEnd/Node/OutOfProcServerNode.cs Makes RedirectConsoleWriter tolerate post-dispose writes by redirecting to TextWriter.Null and adding a disposal state.
src/Build.UnitTests/BackEnd/RedirectConsoleWriter_Tests.cs Adds a regression test for writes after dispose.
Suppressed comments (1)

src/Build/BackEnd/Node/OutOfProcServerNode.cs:756

  • TimerCallback reads _disposed and calls _bufferWriter.GetStringBuilder() without taking _lock, while Dispose mutates _disposed, swaps _internalWriter, and disposes _bufferWriter under that lock. This unsynchronized access is a data race and can (in rare timing) observe stale _disposed and touch/discard a disposed _bufferWriter, reintroducing ObjectDisposedException or invoking the callback after disposal.
            private void TimerCallback(object? state)
            {
                if (!_disposed && _bufferWriter.GetStringBuilder().Length > 0)
                {
                    Flush();
                }
            }

💡 Add a code-review agent skill for context-aware, tailored reviews. Learn more in the docs.

@ViktorHofer

Copy link
Copy Markdown
Member

Approve with comments

The core fix is correct and well-targeted. I read all 35 Write/WriteLine overrides (lines 470–748) and confirmed every one acquires _lock and goes through the swappable _internalWriter — none caches it, none touches _bufferWriter directly. I also verified empirically on .NET 10 and .NET Framework 4.8 that every non-overridden path lands on an overridden sync method (WriteAsyncWrite, FlushAsyncFlush, Write(ReadOnlySpan<char>)/WriteLine(ReadOnlySpan<char>)Write(char[],int,int), Close/DisposeAsyncDispose), so there is no async gap. StringWriter.GetStringBuilder() is dispose-insensitive on both runtimes, so keeping _bufferWriter.Dispose() is safe.

One point worth adding to the PR description: TextWriter.Null is the right sink not just because it's inert, but because re-pointing a stale writer at the live request's sink would leak one build's output into a different client's console in a reused server process. That's the reason this must never be "improved" into forwarding.

No ChangeWave needed — the change removes a warning rather than adding one (-WarnAsError builds get strictly better), doesn't touch what gets built, and is confined to MSBUILDUSESERVER=1. Worth stating explicitly in the description so reviewers don't have to re-derive it.


🔴 H-1 — Console.SetOut/SetError restore is not in a finally

src/Build/BackEnd/Node/OutOfProcServerNode.cs:410-425

using (RedirectConsoleWriter outWriter = new(...))
using (RedirectConsoleWriter errWriter = new(...))
{
    Console.SetOut(outWriter);
    Console.SetError(errWriter);

    buildResult = _buildFunction(command.CommandLine);   // can throw

    Console.SetOut(oldOut);      // skipped on the throw path
    Console.SetError(oldErr);
}

HandleServerNodeBuildCommandAsync wraps this in catch (Exception e) { _shutdownException = e; ... }, so the throw path is live and handled, not theoretical. On it, the restore is skipped but the using still disposes — leaving Console.Out/Console.Error pointed at writers whose sink is now TextWriter.Null.

Before this PR that threw ObjectDisposedException — ugly, but visible. After this PR every subsequent console write in the process is silently swallowed: a crashing server now dies mute. Since this PR is what makes the failure silent, I think the two-line fix belongs here:

try
{
    buildResult = _buildFunction(command.CommandLine);
}
finally
{
    // Restore before the writers are disposed so the dispose-time flush callback
    // cannot re-enter Console, and so a failed build doesn't leave the reused
    // server process writing into a dead writer.
    Console.SetOut(oldOut);
    Console.SetError(oldErr);
}

There's a secondary reason: on the success path the restore happens before dispose, so the dispose-time FlushInternal_writeCallbackSendPacket runs with Console.Out already restored. On the throw path it doesn't, so a SendPacket that logs to Console re-enters Write on a half-disposed writer (Monitor is reentrant, so it silently buffers into a StringBuilder that's about to be discarded).


🟠 M-2 — Encoding isn't disposal-aware and changes value differently per TFM

src/Build/BackEnd/Node/OutOfProcServerNode.cs:457

public override Encoding Encoding => _internalWriter.Encoding;

This is the only member that reads the newly-mutable _internalWriter outside _lock, and the fix changes its observable value. TextWriter.Null's Encoding is Encoding.Default on .NET Framework and Encoding.Unicode on .NET, which I measured as:

before Dispose() after Dispose()
.NET 10 utf-16 utf-16
.NET Framework 4.8 utf-16 Windows-1252

So on net472 a retained Console.Out reports a different, ANSI encoding after the request ends — and probing Console.Out.Encoding is exactly what a console library like Spectre does. StringWriter.Encoding has no dispose check, so reading the buffer instead is stable and removes the unlocked mutable read:

// Deliberately reads the buffer writer, not the swappable destination, so the reported
// encoding is stable across dispose and identical on all target frameworks.
public override Encoding Encoding => _bufferWriter.Encoding;

🟠 M-3 — TimerCallback's new guard is decorative, and races the StringBuilder

src/Build/BackEnd/Node/OutOfProcServerNode.cs:750-756

if (!_disposed && _bufferWriter.GetStringBuilder().Length > 0)

_timer.Dispose() (line 762) does not wait for an in-flight callback, so this can run concurrently with Dispose. It's safe in practice — Flush() re-checks _disposed under _lock, and Dispose holds _lock across the whole transition — and an 800-iteration write-storm + dispose + stale-tick stress across both runtimes produced zero failures. But:

  • _disposed is non-volatile and read outside the lock, so the guard added here doesn't actually guarantee anything.
  • StringBuilder.Length is two unsynchronized int reads racing sb.Clear() and sb.Append. Benign (worst case a spurious no-op flush or a skipped tick the next 40 ms tick recovers) but formally UB, and this line is already being edited.
  • Each tick takes _lock twice.

All three go away by doing the check inside the lock you already need, with identical tick cadence and flush semantics:

private void TimerCallback(object? state)
{
    lock (_lock)
    {
        if (!_disposed && _bufferWriter.GetStringBuilder().Length > 0)
        {
            FlushInternal();
        }
    }
}

🟠 M-4 / M-5 — Test coverage

src/Build.UnitTests/BackEnd/RedirectConsoleWriter_Tests.cs:30-41

Two gaps:

The reset discards the more interesting assertion. callbackInvoked = false; after Dispose() throws away the fact that the dispose-time flush does fire the callback and deliver the buffered text. Assert it instead.

Nothing tests the property the fix exists to provide. The bug in #14691 is cross-request: a third party retains request N's writer and writes during request N+1. The current test would pass against several wrong implementations — including one that forwards stale writes to the live request's sink, which is the specific mistake the design is avoiding. A test that pins it:

[Fact]
public void WriteThroughStaleWriter_DoesNotLeakIntoSubsequentRequestOutput()
{
    List<string> firstRequestOutput = [];
    List<string> secondRequestOutput = [];

    // Simulates the reference Spectre.Console caches process-wide.
    OutOfProcServerNode.RedirectConsoleWriter staleWriter = new(text => firstRequestOutput.Add(text));
    staleWriter.Dispose();          // request 1 completes

    using OutOfProcServerNode.RedirectConsoleWriter liveWriter = new(text => secondRequestOutput.Add(text));

    Should.NotThrow(() => staleWriter.WriteLine("component detection output from request 2"));
    liveWriter.Flush();

    secondRequestOutput.ShouldNotContain(s => s.Contains("component detection"));
    firstRequestOutput.ShouldNotContain(s => s.Contains("component detection"));
}

And since the post-dispose safety of Write(char), Write(char[],int,int), Write(ReadOnlySpan<char>), Flush, the async trio, Close() and double-Dispose() all depend on TextWriter base-class fallback that differs between net472 and net10.0, they're worth a [Theory] rather than inspection:

public static TheoryData<string, Action<OutOfProcServerNode.RedirectConsoleWriter>> PostDisposeOperations => new()
{
    { "Write(char)",            w => w.Write('c') },
    { "Write(string)",          w => w.Write("x") },
    { "Write(char[],int,int)",  w => w.Write(new[] { 'a', 'b' }, 0, 2) },
    { "Write(ReadOnlySpan)",    w => w.Write("x".AsSpan()) },
    { "Write(format,args)",     w => w.Write("{0}", 1) },
    { "WriteLine()",            w => w.WriteLine() },
    { "WriteLine(string)",      w => w.WriteLine("x") },
    { "Flush()",                w => w.Flush() },
    { "WriteAsync(string)",     w => w.WriteAsync("x").GetAwaiter().GetResult() },
    { "WriteLineAsync(string)", w => w.WriteLineAsync("x").GetAwaiter().GetResult() },
    { "FlushAsync()",           w => w.FlushAsync().GetAwaiter().GetResult() },
    { "Close()",                w => w.Close() },
    { "Dispose() again",        w => w.Dispose() },
};

[Theory]
[MemberData(nameof(PostDisposeOperations))]
public void WriteAfterDispose_IsDiscarded_WithoutThrowingOrInvokingCallback(
    string description,
    Action<OutOfProcServerNode.RedirectConsoleWriter> operation)
{
    List<string> callbackPayloads = [];
    OutOfProcServerNode.RedirectConsoleWriter writer = new(text => callbackPayloads.Add(text));

    writer.Write("buffered before dispose");
    writer.Dispose();

    // The final request flush must still deliver everything that was buffered.
    callbackPayloads.ShouldHaveSingleItem().ShouldBe("buffered before dispose");
    callbackPayloads.Clear();

    Should.NotThrow(() => operation(writer));
    callbackPayloads.ShouldBeEmpty();
}

🟠 M-6 — Pre-existing: Write(string, params object?[]) calls WriteLine

src/Build/BackEnd/Node/OutOfProcServerNode.cs:598-604

public override void Write(string format, params object?[] arg)
{
    lock (_lock)
    {
        _internalWriter.WriteLine(format, arg);   // should be Write
    }
}

Present on main too, so not introduced here — but it means Console.Write("{0} {1}", a, b) emits a spurious newline only on MSBuild Server, i.e. the same "server output differs from non-server output" family this PR is fixing. One-word fix in the same class; happy either way if you'd rather keep scope tight and file an issue.


🟠 M-7 / 🟡 L-8 — FlushInternal sends empty payloads, and _bufferWriter.Flush() is dead

src/Build/BackEnd/Node/OutOfProcServerNode.cs:785-793

Every request's dispose currently sends two empty ServerNodeConsoleWrite IPC packets (one per writer) when nothing was buffered, plus one per idle timer tick that slips through. And StringWriter has no buffer — Flush() is the empty TextWriter.Flush() (it doesn't even throw when disposed). Both are pre-existing, but the method is newly extracted here, so it's the natural moment:

private void FlushInternal()
{
    StringBuilder sb = _bufferWriter.GetStringBuilder();
    if (sb.Length == 0)
    {
        return;
    }

    string captured = sb.ToString();
    sb.Clear();
    _writeCallback(captured);
}

🟡 Low

  • L-9_internalWriter (line 446) is now a misleading name: it's the swappable destination, while _bufferWriter is the actual internal writer. Someone scanning 35 overrides will assume the opposite. Renaming to _destination makes the whole fix self-documenting.
  • L-10 — The ordering inside the finally (lines 772-777) is load-bearing: _internalWriter = TextWriter.Null and _disposed = true must both precede _bufferWriter.Dispose(). Correct as written, but nothing says so, and it's exactly what a future cleanup reorders.
  • L-11 — Please add a <remarks> on the class explaining why the writer is kept alive-but-inert (third-party code caches Console.Out across server requests — .NET 11 Preview 7 Parallelism Breaks SBOM Generation #14691), and that forwarding stale writes to the current request's writer would be an output-leak bug. Without it this gets "simplified" back to a plain Dispose.
  • L-12 — Silently dropping is right for the user but undiagnosable for us. This file already uses CommunicationsUtilities.Trace (lines 103, 251, 262, 328, 352), which goes to the MSBUILDDEBUGCOMM log and is not user-visible, so it doesn't collide with the no-new-warnings policy. Trace once (guard with an int + Interlocked.Exchange), not per write, or Spectre's table renderer will flood it.
  • L-13_writeCallback captures this via SendPacket (lines 415-416), so a retained stale writer roots the node, its endpoint and packet queue for the process lifetime. Bounded, so near-zero practical impact — but given the premise is "someone holds our writer forever", clearing it in the finally (_writeCallback = static _ => { };) would make the no-stale-callbacks guarantee structural rather than incidental.

Nits

  • NewLine and FormatProvider aren't overridden, so they silently flip from StringWriter/CurrentCulture to NullTextWriter/InvariantCulture at dispose. Harmless since the output is discarded — noting only for completeness.
  • Test name: repo convention is MethodUnderTest_Scenario_ExpectedResult.

Restore process console streams when server build execution throws, keep the reported encoding stable after disposal, clarify the inert destination, and strengthen the regression test around final flush behavior.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>

Copilot-Session: fa3f99a2-bb35-4d8c-9381-91d8d05e752a
@JanProvaznik

Copy link
Copy Markdown
Member Author

Addressed the relevant review points in 5f4b1ecff8:

  • restore Console.Out/Console.Error in finally
  • keep Encoding stable via the buffer writer
  • remove the decorative unlocked _disposed timer guard while leaving timer synchronization otherwise unchanged
  • rename the swappable field to _destination and document why stale output must remain inert
  • strengthen the regression test to verify pre-dispose output is delivered and post-dispose writes/flushes neither forward nor throw
  • document why no ChangeWave is needed

I kept the pre-existing format-overload and empty-packet cleanups out of scope, and did not add tracing or callback clearing.

I rebuilt and reran the actual Microsoft.Sbom.Targets 4.1.5 E2E on the exact reviewed head: both packs reused PID 21652, both exited 0, request 2 reported TotalNumberOfPackages=4, and the final manifest retained four packages including Newtonsoft.Json.

@JanProvaznik

Copy link
Copy Markdown
Member Author

good feedback, I am unifying the effort with investigation of #14859

Resolve the OutOfProcServerNode refactor by retaining the new server flow and applying the stale-writer null-sink behavior on top.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>

Copilot-Session: fa3f99a2-bb35-4d8c-9381-91d8d05e752a
@JanProvaznik
JanProvaznik merged commit 25e0156 into dotnet:main Aug 28, 2026
10 checks passed
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.

4 participants