Properties and items logged at evaluation with legacy loggers for single-process builds

[KirillOsenkov]

We have an unexpected behavior for single-process builds (/bl), where if there are legacy loggers that haven't opted in via IEventSource4.IncludeEvaluationPropertiesAndItems(), and the environment variable MSBUILDLOGPROPERTIESANDITEMSAFTEREVALUATION is not set, we still enable the new behavior if there is at least one "enlightened" logger.

See test results here:
#7217 (comment)

See related:

• Don't move Properties and Items to ProjectEvaluationFinished if legacy loggers present #6520
• Azure Devops pipelines crashing in MSBuild logger, as of 5/25 VS2019 image #6498

[rainersigwald]

Looked at this a bit this morning. Loggers work with an event-based approach, where one "SourceSink" of events can feed multiple loggers.

For a build with the default console logger, the binlog, and a random unenlightened logger, I see only one _eventSinkDictionary here:

msbuild/src/Build/BackEnd/Components/Logging/LoggingService.cs

Lines 528 to 530 in b827bf5

	var sinks = _eventSinkDictionary.Values.OfType<EventSourceSink>();
	// .All() on an empty list defaults to true, we want to default to false
	_includeEvaluationPropertiesAndItems = sinks.Any() && sinks.All(sink => sink.IncludeEvaluationPropertiesAndItems);

I can also see the ProjectCollection.ReusableLogger's internal state here

msbuild/src/Build/Definition/ProjectCollection.cs

Line 2054 in b827bf5

_includeEvaluationPropertiesAndItems = true;

getting toggled while registering the ParallelConsoleLogger.

The second logger gets registered through this path:

msbuild/src/Build/BackEnd/Components/Logging/LoggingService.cs

Lines 926 to 931 in b827bf5

	// We have already create a forwarding logger and have a single eventSink which
	// a logger can listen to inorder to get all events in the system
	EventSourceSink eventSource = (EventSourceSink)_eventSinkDictionary[_centralForwardingLoggerSinkId];
	// Initialize and register the logger
	InitializeLogger(logger, eventSource);

So it sees only the EventSourceSink created in the first logger, which had IncludeEvaluationPropertiesAndItems toggled on.

In the multiproc case, we actually pass only the non-console loggers to the ProjectCollection, because the console logger is a DistributedLoggerRecord which are treated separately

msbuild/src/MSBuild/XMake.cs

Lines 3202 to 3220 in b827bf5

	// Check to see if there is a possibility we will be logging from an out-of-proc node.
	// If so (we're multi-proc or the in-proc node is disabled), we register a distributed logger.
	if (cpuCount == 1 && Environment.GetEnvironmentVariable("MSBUILDNOINPROCNODE") != "1")
	{
	// We've decided to use the MP logger even in single proc mode.
	// Switch it on here, rather than in the logger, so that other hosts that use
	// the existing ConsoleLogger don't see the behavior change in single proc.
	logger.Parameters = $"ENABLEMPLOGGING;{consoleParameters}";
	loggers.Add(logger);
	}
	else
	{
	logger.Parameters = consoleParameters;
	// For performance, register this logger using the forwarding logger mechanism, rather than as an old-style
	// central logger.
	DistributedLoggerRecord forwardingLoggerRecord = CreateForwardingLoggerRecord(logger, consoleParameters, verbosity);
	distributedLoggerRecords.Add(forwardingLoggerRecord);
	}

msbuild/src/MSBuild/XMake.cs

Lines 1027 to 1030 in b827bf5

	foreach (DistributedLoggerRecord distRecord in distributedLoggerRecords)
	{
	remoteLoggerRecords.Add(new ForwardingLoggerRecord(distRecord.CentralLogger, distRecord.ForwardingLoggerDescription));
	}

and passed to the BuildParameters rather than the ProjectCollection

msbuild/src/MSBuild/XMake.cs

Line 1168 in b827bf5

parameters.ForwardingLoggers = remoteLoggerRecords;

So I think the current filtering mechanism just doesn't work, and we've been squeaking by with luck :(

[KirillOsenkov]

Thanks for looking. When I added support for IncludePropertiesAndItems I copy pasted existing support for other settings, which probably have the same issue :|

[KirillOsenkov]

I just noticed that MuxLogger.SubmissionRecord only supports IEventSource2.

I think It needs to be enlightened to support IEventSource4:

msbuild/src/Utilities/MuxLogger.cs

Line 339 in 2cbc8b6

IEventSource2

Here I think:

msbuild/src/Utilities/MuxLogger.cs

Line 1336 in 2cbc8b6

if (_eventSourceForBuild is IEventSource2 eventSource2)

[KirillOsenkov]

Hmm, that's probably fine. I'm not even sure what SubmissionRecord is used for or whether that is relevant in any way.