VS Binlog has evaluations that don't include property/item data with MSBUILDLOGIMPORTS

[rainersigwald]

I am in possession of a binlog that looks like this

So it did evaluation, including firing the import events AND EMBEDDING THE FILES but somehow didn't report post-evaluation item and property states?

[AR-May]

Have been able to reproduce the issue:

1. Create a vcxproj console project from a VS template
2. Open a cmd and set MSBUILDLOGIMPORTS and MSBUILDDEBUGENGINE environment variables.
3. Open the solution from the same cmd: <path to devenv.exe> <solution_name>
4. Run build
5. Check MSBuild_Logs folder for binlogs with missing items and properties.

[KirillOsenkov]

Have we validated that @JanKrivanek's change actually fixes this?

Binlogs obtained from VS have always been deficient and missing info. The Project System Tools extension was especially bad, but even the MSBUILDDEBUGENGINE=1 mode produces no evaluation and I thought it's because CPS evaluates separately from builds.

See related:

• Evaluation missing from Design-Time build logs project-system-tools#256
• Items not logged in .binlog project-system-tools#257

I don't think MuxLogger is the problem. I have an environment where MuxLogger is present but still the binlogs have the full information.

[KirillOsenkov]

Another way to test this is set the env variable MSBUILDLOGPROPERTIESANDITEMSAFTEREVALUATION=1 and see if it fixes things. If it does then yes, it indicates a legacy logger is present.

But I suspect it won't fix it.

[rainersigwald]

Binlogs obtained from VS have always been deficient and missing info. The Project System Tools extension was especially bad, but even the MSBUILDDEBUGENGINE=1 mode produces no evaluation and I thought it's because CPS evaluates separately from builds.

there will be no evaluation in the logs of build, because it already happened, but there should be a log with evaluations in it, and this one seems to be that one . . . except they're incomplete.

[KirillOsenkov]

I've never understood how are evaluations separate from build? How is it implemented?

[JanKrivanek]

The ProjectInstance (or Project) can be created and evaluated standalone. They can then be used to issue build requests.
That's how those 2 events get executed separately.

I'll double/triple check and debug the scenario next week (away from my devbox now) to confirm the theory.

[JanKrivanek]

Reopening as fix introduced VS perf regression - we will need to fix that one in coordination with the fix

[JanKrivanek]

We'll need to investigate the hidden root-cause, in order to prevent the perf regression after fix.

First we'll need to find stable repro - steps:

• Create simple console app
• Use latest preview or main VS (the issue should be in main from about beginning of June, so doesn't have to be exactly latest)
• Run the following - to enable binlogging and collect them:

$env:MSBUILDDEBUGENGINE = 1 
> $env:MSBUILDDEBUGPATH="C:\MSBuildReproLogs" 
> & "devenv.exe" MySolution.sln
<Run full rebuild from GUI>

Check the binlog - evaluation result of a project should normally contain properties and items:

If they are missing - issue reproduces.

If issue doesn't reproduce, try:

• With new c++ console project instead of C# console project
• With disabling msbuild in-proc nodes:

> $env:MSBUILDNOINPROCNODE="1" 

Once repro is found, we'll need previous - unbroken instance

• Try 17.10 (LTSC), edition doesn't matter. Older versions should be without issue as well - but ideally we get something closer before regression was introduced
• During trying if issue reproes - make sure to kill all outstanding dotnet and msbuild instances (e.g. use sysinternals pskill: simple pskill msbuild and pskill dotnet will do the job)
• And make sure you fully rebuild the project
• Unbroken instance will mean we see properties and items in evaluation node for the same scenario where we do not see those in the 'broken version'

Once we have 2 versions to compare - we'll need to look into behavior differences

• The Issue is most likely in different boolean value returned by IncludeEvaluationPropertiesAndItems

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

  Lines 555 to 573 in bd46115

  	get
  	{
  	if (_includeEvaluationPropertiesAndItems == null)
  	{
  	var escapeHatch = Traits.Instance.EscapeHatches.LogPropertiesAndItemsAfterEvaluation;
  	if (escapeHatch.HasValue)
  	{
  	_includeEvaluationPropertiesAndItems = escapeHatch.Value;
  	}
  	else
  	{
  	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;
  	}

• Break into the MSBuild engine - e.g. via setting:

$env:MSBUILDDEBUGONSTART="1"

• Set the breakpoint to the mentioned property
• Ideally we have repro that reproes without in proc node (see MSBUILDNOINPROCNODE above) - so that we can rely on breaking into external process. Otherwise - if we'd need to debug the msbuild code run within the VS process - we'd need to inject custom built MSBuild bits (and add Debugger.Launch() into the property), or attach to VS and use 'Function breakpoint' (see later). We might likely need any of those techniques in a later steps anyway (see next steps), but we might be able to avoid now.
• See if the returned values differes between versions
• They'll likely differ and it'll likely be because one of the sink.IncludeEvaluationPropertiesAndItems values differ between the cases
• If that's the case - It's likely that MuxLogger is the one logger causing the difference:

  msbuild/src/Utilities/MuxLogger.cs

  Line 187 in bd46115

  eventSource4.IncludeEvaluationPropertiesAndItems();

• For investigation which loggers are registered (and for investigating what called MuxLogger differently - if that's proved culprit) we'll need our custom msbuild bits - as we need to break into InitializeLogger - which runs in the main node. Other option is to attach debugger to VS process and add unresolved Function breakpoint (Debug -> New Breakpoint -> Function Breakpoint) and specify the InitializeLogger function - it might though get some efforts to get working correctly
• If MuxLogger is the culprit - we need to set breakpoint on its IncludeEvaluationPropertiesAndItems setter and see what code did call it in the 'before regression VS version' and see if that code is not called in 'after regression VS version'

If any of the above steps doesn't work - please do not continue with further steps (as they might expect the previous steps are true) - instead we'll need to figure adjustment of investigation.

[GangWang01]

No matter disabling msbuild in-proc node or not, this issue could be reproduced with older VS versions, even back to 17.0.0. VS 2019(16.11.38) also has this issue. It means this issue has existed for a long time.

With Jan's help, I looked into which loggers are registered and which of these call IEventSource4.IncludeEvaluationPropertiesAndItems() in Initialize(IEventSource eventSource) of the loggers through debugging with $env:MSBuildDebugBuildManagerOnStart="1". The registered loggers are:

• Microsoft.Build.Logging.BinaryLogger - This is set by $env:MSBUILDDEBUGENGINE=1.
• Microsoft.Build.Utilities.MuxLogger
  
  As the screenshot above, the IncludeEvaluationPropertiesAndItems of EventSourceSink with the value false was from the MuxLogger.Initialize(IEventSource eventSource). The breakpoint added to the setter of MuxLogger's property IncludeEvaluationPropertiesAndItems was never hit and it was false by default.

  msbuild/src/Utilities/MuxLogger.cs

  Lines 185 to 188 in bd46115

  	if (IncludeEvaluationPropertiesAndItems)
  	{
  	eventSource4.IncludeEvaluationPropertiesAndItems();
  	}

  was not run to set IncludeEvaluationPropertiesAndItems of EventSourceSink and caused the issue.

[JanKrivanek]

Thank you @GangWang01!
Let's dig more into why the fix for this causes perf regression - what are the other registered loggers in VS and what are their setting of IncludeEvaluationPropertiesAndItems?

[GangWang01]

Enabling binary logger by setting $env:MSBUILDNOINPROCNODE="1" interfered the investigation. It didn't simulate the case in VS perf tests.
Without enabling binary logger, I found the loggers below were registered that was different from the investigation.

• Microsoft.Build.Utilities.MuxLogger - The setter of MuxLogger's property IncludeEvaluationPropertiesAndItems was never hit.
• Microsoft.Build.Execution.BuildManager.NullLogger - It calls eventSource4.IncludeEvaluationPropertiesAndItems() directly

  msbuild/src/Build/BackEnd/BuildManager/BuildManager.cs

  Line 3300 in 1b1df9e

  eventSource4.IncludeEvaluationPropertiesAndItems();

  . This logger may cause the perf regression with the fix.