Skip to content

Preventing coordinator messages from getting filtered out by terminal logger - #14356

Open
VolPlita wants to merge 13 commits into
dotnet:mainfrom
VolPlita:fix-14345-unfilter-global-mesages-tl
Open

VolPlita wants to merge 13 commits into
dotnet:mainfrom
VolPlita:fix-14345-unfilter-global-mesages-tl

Conversation

@VolPlita

Copy link
Copy Markdown
Contributor

Fixes: #14345

Issue

When MSBuild is invoked with the /tl (Terminal Logger) flag, coordinator wait messages were silently dropped, leaving users without visibility into build delays during nested grant scenarios. This made it difficult to diagnose why builds appeared to hang.

Root Cause

Coordinator messages have null BuildEventContext and MessageImportance.High to indicate they are global diagnostics. These were filtered out at two levels:

  1. ForwardingTerminalLogger dropped them before forwarding to the central logger
  2. TerminalLogger had no handler for null-context messages

Changes

  • ForwardingTerminalLogger.cs: Forward global messages (null context + HIGH importance) before the null-context filter, respecting quiet mode
  • TerminalLogger.cs: Handle global messages by displaying them directly to terminal without project context

Testing

  • Added unit tests in ForwardingTerminalLogger_Tests.cs:
    • Global HIGH importance messages are forwarded
    • Global NORMAL importance messages are not forwarded
    • Project-context messages still work correctly
    • Multiple coordinator messages are forwarded
    • Quiet mode suppresses all messages including globals
  • Verified existing TerminalLogger suite tests remain unaffected

@VolPlita
VolPlita requested a review from Copilot July 14, 2026 14:43
@VolPlita
VolPlita force-pushed the fix-14345-unfilter-global-mesages-tl branch from ed81240 to c99c974 Compare July 14, 2026 14:43
@VolPlita
VolPlita requested a review from rainersigwald July 14, 2026 14:44
@VolPlita
VolPlita marked this pull request as ready for review July 14, 2026 14:44

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

This PR addresses a /tl (Terminal Logger) usability regression where coordinator “waiting/grant” messages (global, BuildEventContext == null) were being dropped, reducing visibility into build delays.

Changes:

  • Adjusts ForwardingTerminalLogger to forward null-context HIGH importance coordinator/global messages (while still respecting quiet mode).
  • Adds TerminalLogger handling for null-context HIGH importance messages so they can be rendered to the terminal.
  • Introduces new unit tests validating ForwardingTerminalLogger forwarding behavior for null-context/global messages.

Reviewed changes

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

File Description
src/Build/Logging/TerminalLogger/TerminalLogger.cs Adds rendering path for null-context HIGH-importance messages in the terminal logger.
src/Build/Logging/TerminalLogger/ForwardingTerminalLogger.cs Changes message forwarding order/filters so global coordinator messages aren’t dropped before reaching the central logger.
src/Build.UnitTests/ForwardingTerminalLogger_Tests.cs Adds regression/unit tests ensuring null-context forwarding behavior and quiet-mode suppression.

Comment thread src/Build/Logging/TerminalLogger/TerminalLogger.cs
Comment thread src/Build/Logging/TerminalLogger/ForwardingTerminalLogger.cs Outdated
Comment on lines +1200 to +1202
// For global/coordinator messages with high importance
if (buildEventContext is null && message is not null && e.Importance == MessageImportance.High)
{
Comment thread src/Build/Logging/TerminalLogger/ForwardingTerminalLogger.cs Outdated
var buildEventContext = e.BuildEventContext;
string? message = e.Message;
// For global/coordinator messages with high importance
if (buildEventContext is null && message is not null && e.Importance == MessageImportance.High)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

I was very confused about how the BEC could be null here, since it should be set to Invalid when the coordinator event throws. It looks like in the case I was debugging, the message is originally raised in the NuGet.Build.Tasks.Console.exe helper process, which serializes it back to be logged here.

That assembly compiles against Microsoft.Build.Utilities.v4.0, and the LogMessage there explicitly passes null for BuildEventContext.

Because RestoreTaskEx generally runs on the entrypoint node we might be able to avoid pushing the change to the forwarding logger, but I don't think that's worth changing.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

Thanks for the investigation, that makes sense. I think we are fine with defensive guard in the logger, let's keep it as is

Comment thread src/Build/Logging/TerminalLogger/TerminalLogger.cs
var buildEventContext = e.BuildEventContext;
string? message = e.Message;
// For global/coordinator messages with high importance
if (buildEventContext is null && message is not null && e.Importance == MessageImportance.High)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

I would ideally like to check more than context-is-null-and-importance-is-high. Should we add an unlocalized keyword to the message so we can scan for it like IsAuthProviderMessage?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

That would be more robust, but it depends on scope. If coordinator messages are defined in a few places we control, a keyword marker makes sense. If they come from legacy helpers we don't control, the null-bec+HIGH guard might be the most pragmatic boundary. How many sources emit these messages?

VolPlita and others added 2 commits July 15, 2026 10:39
Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com>
github-actions Bot added a commit that referenced this pull request Jul 15, 2026
Recurring reviewer feedback (PRs #14356, #14370, rainersigwald) flagged
direct terminal writes for immediate messages instead of using the
established RenderImmediateMessage path.

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

Copy link
Copy Markdown
Member

could you paste here the before and after (either in plaintext or screenshots)?

string? message = e.Message;

// For global/coordinator messages with high importance
if (buildEventContext is null)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

The real coordinator message is logged with BuildEventContext.Invalid, not null, so the in-process path is still swallowed.

// For global/coordinator messages with high importance
if (buildEventContext is null)
{
if (Verbosity > LoggerVerbosity.Quiet && message is not null && e.Importance == MessageImportance.High)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

null context + high importance is too broad a trigger I think. It may render arbitrary third-party messages.

@VolPlita

VolPlita commented Aug 3, 2026

Copy link
Copy Markdown
Contributor Author

could you paste here the before and after (either in plaintext or screenshots)?

Before the fix global/coordinator messages (with null BuildEventContext, or BuildEventContext.Invalid from the build coordinator) were silently dropped by TerminalLogger, even at High importance, so we just had:

Build succeeded in 5.0s
(the diagnostic message never appeared it's swallowed by the null-context filter)

After the fix the same messages are now rendered before the build-succeeded summary:

Global diagnostic message.
Build succeeded in 5.0s

Waiting for coordinator to grant build resources...
Build succeeded in 5.0s

@VolPlita
VolPlita requested a review from JanProvaznik August 3, 2026 10:05

@JanProvaznik JanProvaznik left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

I think controlling flow by strings is bad for maintainability.
Could we somehow use the type system?
This may require refactoring the coordinator messages to separate type instead of a normal LogComment or a better mechanism for distinguishing events that should be rendered in TL.

@baronfel may have suggestions.

@VolPlita

VolPlita commented Aug 3, 2026

Copy link
Copy Markdown
Contributor Author

I think controlling flow by strings is bad for maintainability. Could we somehow use the type system? This may require refactoring the coordinator messages to separate type instead of a normal LogComment or a better mechanism for distinguishing events that should be rendered in TL.

@baronfel may have suggestions.

Good point, and I agree strings aren't great for this. Here's what I did and what a fully-typed fix would probably have to do.

The current commit: the coordinator's "waiting for nodes" message is now tagged with an ExtendedType (a stable internal key), using MSBuild's existing ExtendedBuildMessageEventArgs mechanism. TerminalLogger checks that tag instead of comparing the message text. So wording/localization can change freely without breaking detection. Tbh, it's still a string check under the hood, just a fixed internal key instead of user-facing text. Not fully type-safe, but no compiler typos possible since it's a shared constant, and it's the standard pattern already used elsewhere in the repo.

A fully type-based fix would mean a dedicated event class (e.g. CoordinatorWaitingForNodesEventArgs), checked with is and no strings at all. But that requires plugging it into MSBuild's node/TaskHost message serialization and the binary log format, likely a binlog version bump. Real type safety, but a much bigger change for one narrow diagnostic.

@JanProvaznik @baronfel Do you think I should do that here, file it as a follow-up issue, or is the current fix good enough?

@VolPlita
VolPlita requested a review from JanProvaznik August 3, 2026 13:47
@JanProvaznik

Copy link
Copy Markdown
Member

Real type safety, but a much bigger change for one narrow diagnostic

the coding agent can do it 😉 it has precedent so shouldn't be too hard

@VolPlita

VolPlita commented Aug 3, 2026

Copy link
Copy Markdown
Contributor Author

Real type safety, but a much bigger change for one narrow diagnostic

the coding agent can do it 😉 it has precedent so shouldn't be too hard

Ok, done, seems fine too me.

@VolPlita
VolPlita enabled auto-merge (squash) August 3, 2026 15:19
Comment on lines +1438 to +1439
e is Microsoft.Build.Framework.Coordinator.CoordinatorWaitingForNodesEventArgs ||
e is IExtendedBuildEventArgs { ExtendedType: Microsoft.Build.Framework.Coordinator.Constants.WaitingForNodesEventType };

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

why or?

Comment on lines -1199 to +1212
if (buildEventContext is null)
string? message = e.Message;

// Null context (e.g. an out-of-process helper) is trusted alone; BuildEventContext.Invalid additionally
// requires a recognized coordinator diagnostic, since Invalid can also be (mis-)used by in-process code
// that IS associated with the current build.
if (buildEventContext is null || buildEventContext == BuildEventContext.Invalid)
{
bool isRecognizedGlobalMessage = buildEventContext is null || IsCoordinatorMessage(e);

if (Verbosity > LoggerVerbosity.Quiet && message is not null && e.Importance == MessageImportance.High && isRecognizedGlobalMessage)
{
RenderImmediateMessage(message);
}

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

isn't this stale in the updated design with dedicated type?

// Null context (e.g. an out-of-process helper) is trusted alone; BuildEventContext.Invalid additionally
// requires a recognized coordinator diagnostic, since Invalid can also be (mis-)used by in-process code
// that IS associated with the current build.
if (buildEventContext is null || buildEventContext == BuildEventContext.Invalid)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

This suppresses unrelated high-importance messages with BuildEventContext.Invalid at Detailed/Diagnostic verbosity. Could maybe unrecognized Invalid-context messages fall through to the existing verbosity-dependent handling?

{
return LoggingEventType.ExtendedBuildMessageEvent;
}
else if (eventType == typeof(Microsoft.Build.Framework.Coordinator.CoordinatorWaitingForNodesEventArgs))

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Could we add a node-packet round-trip test for this event? The TerminalLogger test manually constructs the generic ExtendedBuildMessageEventArgs, so it does not verify that this mapping preserves the message, importance, context, and ExtendedType across serialization.

…or event internal and add verbosity boundary + tests
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.

TerminalLogger should always emit waiting-on-Coordinator messages

5 participants