Azure Devops pipelines crashing in MSBuild logger, as of 5/25 VS2019 image

[Scottj1s]

Beginning on 5/25, a stage of the WinUI build which executes on hosted VS2019 agents, began failing intermittently with the stack below. Subsequent runs of the pipeline produce different combinations of success/failure.

MSBUILD : error MSB4017: The build stopped unexpectedly because of an unexpected logger failure. 
Microsoft.Build.Exceptions.InternalLoggerException: The build stopped unexpectedly because of an unexpected logger failure. ---> System.NullReferenceException: Object reference not set to an instance of an object. 
at MSBuild.Logger.BuildConfiguration.Equals(Object obj) 
at System.Collections.Generic.ObjectEqualityComparer`1.Equals(T x, T y) 
at System.Collections.Generic.List`1.Contains(T item) 
at MSBuild.Logger.ProjectTrees.AddTopLevelProject(ProjectStartedEventArgs startedEvent, BuildConfiguration platformConfiguration) 
at MSBuild.Logger.CentralLogger.HandleProjectStarted(Object sender, ProjectStartedEventArgs e) 
at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseProjectStartedEvent(Object sender, ProjectStartedEventArgs buildEvent) 

[rainersigwald]

This issue was moved to microsoft/azure-pipelines-tasks#14904

[rainersigwald]

I think this is a regression caused by #6287. In this case there's a binary logger and a third-party logger attached, and the third-party logger looks through ProjectStartedEventArgs.Properties.

Specifically I think this logic is not as backward-compatible as hoped:

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

Lines 511 to 519 in 2fd48ab

	/// <summary>
	/// Should properties and items be logged on <see cref="ProjectEvaluationFinishedEventArgs"/>
	/// instead of <see cref="ProjectStartedEventArgs"/>?
	/// </summary>
	public bool IncludeEvaluationPropertiesAndItems
	{
	get => _includeEvaluationPropertiesAndItems ??= _eventSinkDictionary.Values.OfType<EventSourceSink>().Any(sink => sink.IncludeEvaluationPropertiesAndItems);
	set => _includeEvaluationPropertiesAndItems = value;
	}

We want to turn that on if only enlightened loggers are attached, not if any enlightened logger is attached.

cc @KirillOsenkov

[rainersigwald]

Workaround 1 (tested):

Use the VSBuild task parameter enableDefaultLogger: false to disable the Azure DevOps logger and avoid microsoft/azure-pipelines-tasks#14904.

Workaround 2 (please report if this works)

Set the environment variable MSBUILDLOGPROPERTIESANDITEMSAFTEREVALUATION=false around your MSBuild invocation.

[KirillOsenkov]

ProjectStartedEventArgs.Properties could be null even in 16.9, if the project built in a worker node. I’m guessing their logger was always buggy but happened to work for single-process builds.

[KirillOsenkov]

What is the other logger (MSBuild.Logger) and how do I test it and where is the source?

[KirillOsenkov]

Hmm, so should we change that .Any to .All?

[KirillOsenkov]

Also should we initialize ProjectStartedEventArgs.Properties to an empty array instead of being null? Or will this only mask other failures because loggers might rely on a certain property being there?

[rainersigwald]

What is the other logger (MSBuild.Logger) and how do I test it and where is the source?

It's internal and the source is . . . a long story. I was grousing about it in our Teams channel.

Hmm, so should we change that .Any to .All?

I think so, plus opt the text loggers into the new behavior so the standard console logger + -bl continues to work nicely.

Also should we initialize ProjectStartedEventArgs.Properties to an empty array instead of being null? Or will this only mask other failures because loggers might rely on a certain property being there?

I think this is a good mitigation. I'd be shocked if there were loggers that depended on a particular property being set in all projects (but of course I've been surprised before . . .)

[KirillOsenkov]

Fix attempt in #6514

I'm guessing if unenlightened, but well-behaved loggers are co-present with binlog, this will revert to the legacy behavior silently. This will increase binlog sizes. I suppose it's OK and we should drive logger authors to opt-in to the new behavior slowly - fortunately there aren't really that many loggers floating around, but I imagine each CI provider would have one, and many tool vendors such as JetBrains.

No idea how to communicate this other than ad-hoc on Twitter.

[KirillOsenkov]

Judging from the callstack, the null ref in the logger is somewhere here:

[KirillOsenkov]

@Forgind

[rainersigwald]

Visual Studio 16.10.2 has been released and will be picked up by Azure DevOps/GitHub Actions hosted images shortly.