Skip to content

Release the binary log file handle when a logger fails during shutdown - #14658

Draft
JanProvaznik wants to merge 1 commit into
dotnet:mainfrom
JanProvaznik:fix/binlog-handle-leak-server
Draft

JanProvaznik wants to merge 1 commit into
dotnet:mainfrom
JanProvaznik:fix/binlog-handle-leak-server

Conversation

@JanProvaznik

Copy link
Copy Markdown
Member

Context

A user-visible symptom in MSBuild Server: after certain builds, the node keeps the .binlog file open forever. Every subsequent build served by that node fails with

MSBUILD : Logger error MSB4104: Failed to write to log file "out.binlog".
The process cannot access the file 'out.binlog' because it is being used by another process.

the file cannot be deleted, and the leaked binlog is left truncated (gzip header only, unreadable). Nothing recovers it short of killing the server — which users don't know exists.

This matters much more than it used to: -mt now implicitly enables MSBuild Server (ShouldUseMSBuildServer), so ordinary command lines land in a long-lived, reused node.

Root cause

The binlog handle is not build-scoped. It is released by ProjectCollection.Dispose(), and only if BuildManager.EndBuild() ran first.

ProjectCollection wraps every logger in ReusableLogger so one ILogger instance can serve both the design-time (evaluation) and build-time lifetimes. Because ILogger.Shutdown() carries no identity, ReusableLogger.Shutdown() infers which lifetime is ending from its own state:

if (_buildTimeEventSource != null) { /* detach build-time, keep logger alive */ }
else { _originalLogger.Shutdown(); }   // the only thing that closes the binlog

Balanced, ordered calls → correct. One missing call → silently wrong, permanently, with no way to detect it.

In EndBuild, ShutdownLoggingService — the call that performs the build-time detach — was the last statement of an unguarded block that first raises BuildFinished and then gathers telemetry:

finally
{
    try
    {
        if (loggingService != null)
        {
            loggingService.LogBuildFinished(...);   // fans out to every logger
            if (_buildTelemetry != null) { /* ~40 lines of telemetry */ }
        }
        ShutdownLoggingService(loggingService);     // skipped if anything above throws
    }
    finally { ... }
}

A logger throwing from BuildFinished — something the engine tolerates everywhere else — skips it. The BinaryLogger is then never shut down and keeps its file handle for the lifetime of the process.

In msbuild.exe this was harmless: the process exits. In a resident server node it is not.

Fix

Minimal and targeted:

  1. BuildManager.EndBuild — run ShutdownLoggingService from a finally so it cannot be skipped. This restores the invariant the rest of the file already relies on; the same "on failure, shut the logging service down" compensation already exists in three other places (InitializeLoggingService's inner catch, the _threadException check, and CreateLoggingService).
  2. BinaryLogger.Shutdown — close the stream from a finally, so the handle is released even if the import-archive or additional-copy work throws. Same fail-open shape, contained.

No public API change; the diff in BuildManager.cs is mostly re-indentation.

Verification

Regression test BinaryLoggerFileHandleIsReleasedWhenAnotherLoggerThrowsDuringShutdown:

  • fails on main — The log file '...binlog' is still held open after the build that created it completed
  • passes with the fix

The test deliberately does not dispose the BuildManager, mirroring MSBuild Server: XMake skips BuildManager.DefaultBuildManager.Dispose() for server nodes, and disposing it shuts the logging service down as a side effect, which hides the leak. It also uses UseSynchronousLogging = true to match the command line, which is what makes the failing logger surface on the thread running EndBuild.

End-to-end against a real server node with a locally built MSBuild:

before after
handle after build #1 held released
binlog size 15 bytes, Unable to read beyond the end of the stream 2364 bytes, valid
builds #2, #3 same -bl path MSB4104 forever succeed
delete the file fails succeeds

Also ran the BinaryLogger, BuildManager_Tests, ProjectCollection, and logging suites (437 tests). Remaining failures are pre-existing and reproduce unchanged on a clean tree — 30s ExecMSBuild process-spawn timeouts in this environment, plus two GraphBuild* ArgumentNullException failures.

Not addressed here (deliberately)

The deeper issue is the ownership inversion: for a build invocation, logger lifetime should be BeginBuild..EndBuild, but the binlog handle is owned by the ProjectCollection. For a regular CLI build that ownership is incidental — BuildParameters(ProjectCollection) doesn't copy loggers, and XMake round-trips them via parameters.Loggers = projectCollection.Loggers mainly to obtain the ReusableLogger wrappers. Removing that inversion (or giving ReusableLogger explicit owner/borrower semantics instead of inference) is a behavior-visible refactor and is out of scope for this fix.

Two adjacent issues also found while investigating, not fixed here:

  • MSB4104 doesn't fail the build — the binlog failure above still exits 0.
  • If the client dies rudely (Ctrl+Break) mid-build, the server exits while the build task is still running, truncating the binlog. OutOfProcServerNode returns from Run() on LinkStatus.Failed without waiting for the in-flight build.

The binary log file handle is released by ProjectCollection.Dispose, but only
once BuildManager.EndBuild has shut its logging service down: that shutdown is
what detaches the build-time event source from the ReusableLogger wrapping each
logger. ReusableLogger.Shutdown infers which of its two lifetimes is ending from
its own state, so if the build-time detach never happens, the single remaining
Shutdown call takes the build-time branch and silently never shuts down the
wrapped logger.

In EndBuild, ShutdownLoggingService was the last statement of an unguarded block
that first raises BuildFinished and then gathers telemetry. A logger throwing
from BuildFinished - which the engine otherwise tolerates everywhere - skipped
it, so the BinaryLogger was never shut down and kept its file handle for the
lifetime of the process.

In msbuild.exe that was harmless because the process exits. It is not harmless
in an MSBuild Server node, which is long-lived, reused across builds, and (since
-mt implies the server) now used by ordinary command lines. The leaked handle
wedges the log file permanently: every subsequent build the node serves fails
with MSB4104 "Failed to write to log file ... because it is being used by
another process", the file cannot be deleted, and the leaked binlog is left
truncated. Nothing recovers it short of killing the server, which users do not
know exists.

Run ShutdownLoggingService from a finally so it cannot be skipped, and close the
BinaryLogger's stream from a finally as well so the handle is released even if
the import-archive or additional-copy work throws.

The regression test deliberately does not dispose the BuildManager, mirroring
MSBuild Server: XMake skips BuildManager.DefaultBuildManager.Dispose for server
nodes, and disposing it shuts the logging service down as a side effect, which
hides the leak.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Copilot-Session: 9ce22e5a-3ad9-490d-943b-cd5c7442ab31

This branch has not been deployed

No deployments
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.

1 participant