Diagnostic build log not emitting properties anymore?

[jonathanpeppers]

Issue Description

We first noticed this through Maestro bumps:

• [main] Update dependencies from dotnet/installer android#6029
• [release/6.0.1xx-preview6] Update dependencies from dotnet/installer android#6034

We have a unit test that is asserting several MSBuild properties are in the diagnostic MSBuild log:

build.zip

It's looking for text like AndroidSdkBuildToolsVersion = . I see this as parameters to tasks, but that's it.

That's when I noticed I'm seeing env vars in this log but not properties? Did we regress on that? Thanks!

Steps to Reproduce

I think, just build a project with /flp1:LogFile=build.log;Verbosity=diag and look for properties in the file?

Expected Behavior

Properties are in diagnostic build logs.

Actual Behavior

I don't see properties in diagnostic build logs?

Versions & Configurations

.NET 6.0.100-preview.6.21321.13

Attach a binlog

I don't really see properties in here either:

msbuild.zip

[rainersigwald]

From my minimal local testing, this should be fixed in our current build which will flow through soonish. Please let me know if you see this after tomorrow.

(we talked about this offline but commenting here so it's not lost)

[jonathanpeppers]

I think this is still happening here: dotnet/android#6046

This should be using 67ba2df.

It looks like the fix in #6520 is there:

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

Lines 511 to 530 in 67ba2df

	/// <summary>
	/// Should properties and items be logged on <see cref="ProjectEvaluationFinishedEventArgs"/>
	/// instead of <see cref="ProjectStartedEventArgs"/>?
	/// </summary>
	public bool IncludeEvaluationPropertiesAndItems
	{
	get
	{
	if (_includeEvaluationPropertiesAndItems == null)
	{
	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);
	}
	return _includeEvaluationPropertiesAndItems ?? false;
	}
	set => _includeEvaluationPropertiesAndItems = value;
	}

But maybe there is still a newer commit we need? Let me know, thanks.

[rainersigwald]

cc @KirillOsenkov in case something jumps out at you here

[jonathanpeppers]

Could it be something about using /bl and /flp1 at the same time? We are basically doing:

/noconsolelogger "/flp1:LogFile=build.log;Encoding=UTF-8;Verbosity=Diagnostic" /bl

We're doing this in some integration tests, just to capture every possible log. If we hit something like a crash, sometimes it was easier to read the text log.

[KirillOsenkov]

Curious if you play back the binlog, will the properties be there?

[jonathanpeppers]

Replaying the log above & opening it in VS Code, I don't think I see any properties:

dotnet msbuild msbuild.binlog -v:diag | code -

I see the env vars, but not properties:

Environment at start of build:
                   ALLUSERSPROFILE = C:\ProgramData
...

[KirillOsenkov]

mind sending me both the binlog and the original text log?

[jonathanpeppers]

Oh, they're on the issue above, sorry.

[KirillOsenkov]

Wow, the properties are not in the binlog, neither on ProjectStarted nor on ProjectEvaluationFinished.

This is alarming. I'm taking a look.

[KirillOsenkov]

OK I got a repro. The problem is the environment variable MSBUILDNOINPROCNODE=1.

With this set, and a multi-process build /m, there are no properties at all.

[KirillOsenkov]

So, this environment variable makes stuff weird:

/flp1:v=diag - no props in text log
/flp1:v=diag /bl - props in the text log
/flp1:v=diag /bl /m - no props in the text log

Without it, props are in the text log always.

[KirillOsenkov]

Well, I understand why properties are not on ProjectStarted. They will only be logged when not running on remote node, and with the environment variable we always run on remote node:

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

Lines 88 to 92 in 2c37803

	// If we are only logging critical events lets not pass back the items or properties
	if (!LoggingService.OnlyLogCriticalEvents &&
	!LoggingService.IncludeEvaluationPropertiesAndItems &&
	(!LoggingService.RunningOnRemoteNode || LoggingService.SerializeAllProperties))
	{

[KirillOsenkov]

OK, and IncludeEvaluationPropertiesAndItems will be set to false in presence of either console logger or file logger, so that explains why the properties are missing from evaluation either.

/bl - props in the binlog
/bl /m - no props in the binlog
/bl /m /noconlog - props in the binlog

I'd say this behavior is by design.

[KirillOsenkov]

To have the properties appear on ProjectEvaluationFinished:

• disable console and file loggers (all loggers except for binlog). Console and file loggers will be enlightened by Console logger support for IncludeEvaluationPropertiesAndItems #6535

To have the properties appear on ProjectStarted:

• unset the MSBUILDNOINPROCNODE environment variable or set it to 0
• use single-process build (no multi-proc build)

[KirillOsenkov]

I'm so used to my change to property logging on evaluation regressing things that I'm relieved that this particular one is not a regression ;)

[rainersigwald]

We're attempting to set MSBUILDNOINPROCNODE by default for CLI scenarios because it's an observed performance win (we don't lose in-proc caches in the entry-point process's worker node). However this isn't the only regression discovered in that scenario so we've backed it out for preview6. The next build (and the final build) should not have this problem.

@rokonec here's another thing to keep an eye on when we try to re-enable it 😔

[rokonec]

For close future, I will not have time to work at it. Once/if MSBuild server v1 resumes, I will take this one.