Report eval errors through cli loggers

[baronfel]

Fixes #11372

Context

Eval-time errors are missed because the eval-time ProjectCollection currently is only seeded with single-node loggers, not the central-node loggers that are created for DistributedLoggerRecords. In general, our loggers today are either-or: in single-node mode they register a single logger, but in multi-node mode (the default for dotnet commands) the loggers register as distributed loggers. This means that msbuild.exe-using users will see eval errors, but dotnet users will not.

There is one notable exception here - the binary logger only ever registers as a central logger, because in this configuration absorbs all messages from all node automatically due to an implicit node-forwarding setup that the engine configures.

Changes Made

Add central loggers to the set of loggers registered with the main eval-time ProjectCollection

After this change, it became apparent that the TerminalLogger was getting double-messages sent to it

This led me to investigate the logging service, where logger registration occurs. There are two logging services in play here:

• the eval-time LoggingService
• the build-time LoggingService

The eval-time logging service is primed with Loggers from the eval-time ProjectCollection. However, the eval-time ProjectCollection uses the loggers and forwarding loggers passed into it, but it wraps them as ReusableLoggers. This is a kind of logger that 'buffers' the underlying logger from the fact that evaluation and execution are two separate phases. Doing this allows the inner logger to register to a single event source (the ReusableLogger itself) and internally the ReusableLogger switches between eval-time and execution-time event sinks.

The build-time LoggingService uses the list of Loggers from the eval-time ProjectCollection (threaded through the BuildParameters class), but crucially it uses a different view of the ForwardedLoggers. This view just has the 'inner' CentralLoggers for each configured forwarded logger.

What this means is that during LoggingService initialization, when it checks if a logger is registered already, it sees a TerminalLogger registered (which happens here), and a ReusableLogger containing that same TerminalLogger asking to be registered (which happens here). To fix this, we:

Ensure that ReusableLogger's OriginalLoggers that are already registered with a LoggingService are not re-registered

With this change, both single-proc and multi-proc build report the same amount of events:

With this done I could look at the eval errors themselves. they were now reporting like this:

This is gross and has duplicated information, so now we:

Make Eval-time errors report more nicely in TerminalLogger

Testing

Added a TerminalLogger test case for the formatting.
Updated existing test cases for internal changes related to this work.

Notes

We may want to consider making the ReusableLogger public API - I think we've had issues in this area in the SDK (cc @jjonescz?) that this may have solved.

[Copilot]

Pull Request Overview

This PR fixes eval-time errors not being reported through CLI loggers by ensuring central loggers from distributed logger records are included in evaluation-time project collections. Previously, only single-node loggers were registered for evaluation, causing multi-node environments (default for dotnet commands) to miss eval errors while single-node environments (msbuild.exe) would see them.

Key changes:

• Add central loggers to eval-time ProjectCollection logger registration
• Prevent duplicate logger registration when ReusableLoggers wrap already-registered loggers
• Improve eval error formatting in TerminalLogger by detecting MSBuild placeholder locations

Reviewed Changes

Copilot reviewed 13 out of 13 changed files in this pull request and generated 3 comments.

Show a summary per file

File	Description
src/MSBuild/XMake.cs	Modified to include central loggers from distributed logger records in evaluation logger array
src/MSBuild.UnitTests/XMake_Tests.cs	Updated test expectations and added better error reporting for message importance tests
src/Build/Microsoft.Build.csproj	Added ReusableLogger.cs to project compilation
src/Build/Logging/TerminalLogger/TerminalLogger.cs	Enhanced error formatting and added method to get minimum message importance
src/Build/Logging/ReusableLogger.cs	Moved ReusableLogger class from ProjectCollection to separate file with IEventSource5 support
src/Build/Definition/ProjectCollection.cs	Removed ReusableLogger inner class and updated references to use new location
src/Build/BackEnd/Components/Logging/LoggingService.cs	Enhanced duplicate logger detection for ReusableLoggers and updated TerminalLogger handling

[baronfel]

the only failing test now:

Microsoft.Build.Engine.UnitTests.BackEnd.TaskHostFactory_Tests.TaskNodesDieAfterBuild(taskHostFactorySpecified: False, envVariableSpecified: True)

Zero insight into this one :-/

[YuliiaKovalova]

the only failing test now:

Microsoft.Build.Engine.UnitTests.BackEnd.TaskHostFactory_Tests.TaskNodesDieAfterBuild(taskHostFactorySpecified: False, envVariableSpecified: True)

Zero insight into this one :-/

it's not you, it's sidecartaskhost

[JanProvaznik]

the changes look fine, but I don't think it fully fixes the issue

I checked out the branch, did build.cmd

but still I see the discrepancy it's supposed to address

(foo.csproj is just <Project></Project>

[JanProvaznik]

curiously for MSBuild.exe it works, but has a formatting discrepancy :(

[baronfel]

I made a quick script to test permutations on the bootstrap msbuild variants from this PR.

Runners: dotnet build, dotnet msbuild, msbuild.exe
Variations: TL on or off, M 1 or M 2

results:

To me, these look broadly fine - the console log being indented a bit is an artifact of the way the console logger prepends the node-specific logs with an indent + the node id. I'm not super concerned about changing the console logger's output here for greater usability/prettiness like I am the terminal logger.

ps1 script for repro

```pwsh # Script: test.ps1 # Run MSBuild variants to capture logger output.

param(
[switch]$ShowFailed
)

Determine script directory

$scriptDir = $PSScriptRoot
if (-not $scriptDir) { $scriptDir = Split-Path -Path $MyInvocation.MyCommand.Definition -Parent }

Project path in this workspace

$project = Join-Path $scriptDir 'foo.csproj'

The exact extra property argument requested (kept with the space as provided)

$fixedProperty = '/p:"foo =bar"'

Three invocation styles to test

$invocations = @(
@{ Name = 'dotnet-build'; Exe = 'D:\Code\msbuild\artifacts\bin\bootstrap\core\dotnet.exe'; Verb = 'build' },
@{ Name = 'dotnet-msbuild'; Exe = 'D:\Code\msbuild\artifacts\bin\bootstrap\core\dotnet.exe'; Verb = 'msbuild' },
@{ Name = 'net472-msbuild'; Exe = 'D:\Code\msbuild\artifacts\bin\bootstrap\net472\MSBuild\Current\Bin\msbuild.exe'; Verb = $null }
)

Options to vary

$tlOptions = @('on','off')
$mOptions = @('1','2')

Output folder for logs

$logDir = Join-Path $scriptDir 'msbuild-logs'
if (-not (Test-Path $logDir)) { New-Item -Path $logDir -ItemType Directory | Out-Null }

$results = [System.Collections.Generic.List[object]]::new()
$runIndex = 0

foreach ($inv in $invocations) {
foreach ($tl in $tlOptions) {
foreach ($m in $mOptions) {
$runIndex++
$runName = '{0:D2}_{1}_tl-{2}_m-{3}' -f $runIndex, $inv.Name, $tl, $m
$logFile = Join-Path $logDir ($runName + '.log')

        $args = @()
        if ($inv.Verb) { $args += $inv.Verb }
        $args += $project
        $args += "/tl:$tl"
        $args += "/m:$m"
        # Add the quoted property so the invocation shows it quoted and the command-line parser receives it as intended
        $args += $fixedProperty

        Write-Host "[$runIndex] Running: $($inv.Exe) $([string]::Join(' ', $args))"

        $start = Get-Date
        try {
            $rawOutput = & $inv.Exe @args 2>&1 | Out-String
        } catch {
            $rawOutput = $_ | Out-String
        }

        $rawOutput | Out-File -FilePath $logFile -Encoding utf8

        $results.Add([pscustomobject]@{
            Run = $runName
            Exe = $inv.Exe
            Args = [string]::Join(' ', $args)
            Log = $logFile
        })
    }
}

}

Write-Host "`nSummary:"
$results | Format-Table -AutoSize

if ($ShowFailed) {
$failed = $results | Where-Object { $.ExitCode -ne 0 }
if ($failed) {
Write-Host "nFailed runs (showing last 200 lines):" foreach ($f in $failed) { Write-Host "n== $($f.Run) ($($f.Log)) ==" -ForegroundColor Yellow
Get-Content $f.Log -Tail 200 | ForEach-Object { Write-Host $ }
}
} else {
Write-Host "No failed runs."
}
}

Write-Host "`nLogs written to: $logDir"

</details>

[baronfel]

the only failing test now:

Microsoft.Build.Engine.UnitTests.BackEnd.TaskHostFactory_Tests.TaskNodesDieAfterBuild(taskHostFactorySpecified: False, envVariableSpecified: True)

Zero insight into this one :-/

it's not you, it's sidecartaskhost

@SimaTian is this test issue known? can you please take a look?

[JanProvaznik]

the concern I raised was me using the script validating the change wrong, lgtm

[baronfel]

@dotnet/kitten are we clear to merge this one then?