Enabling BuildCheck causes error MSB4166: Child node "1" exited prematurely

[YuliiaKovalova]

Issue Description

Enabling BuildCheck on runtime and other repos caused

 error MSB4166: Child node "1" exited prematurely. Shutting down. Diagnostic information may be found in files in "C:\Users\cloudtest\AppData\Local\Temp\MSBuildTemp\" and will be named MSBuild_*.failure.txt. This location can be changed by setting the MSBUILDDEBUGPATH environment variable to a different directory.Microsoft.Build.Framework.InternalErrorException: MSB0001: Internal MSBuild Error: ContextID 415 should have been in the ID-to-project file mapping but wasn't!
   at Microsoft.Build.Shared.ErrorUtilities.ThrowInternalError(String message, Object[] args)
   at Microsoft.Build.BackEnd.Logging.LoggingService.GetAndVerifyProjectFileFromContext(BuildEventContext context)
   at Microsoft.Build.BackEnd.Logging.LoggingService.LogBuildEvent(BuildEventArgs buildEvent)
   at Microsoft.Build.Experimental.BuildCheck.Infrastructure.BuildCheckManagerProvider.BuildCheckManager.StartProjectRequest(ICheckContext checkContext, String projectFullPath)
   at Microsoft.Build.Experimental.BuildCheck.Infrastructure.BuildCheckBuildEventHandler.HandleProjectStartedRequest(ProjectStartedEventArgs eventArgs)
   at Microsoft.Build.Experimental.BuildCheck.Infrastructure.BuildCheckConnectorLogger.EventSource_AnyEventRaised(Object sender, BuildEventArgs e)
   at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseAnyEvent(BuildEventArgs buildEvent)
   at Microsoft.Build.BackEnd.Logging.EventSourceSink.<Consume>b__81_9(ProjectStartedEventArgs args)
   at Microsoft.Build.BackEnd.Logging.EventSourceSink.Consume(BuildEventArgs buildEvent)
   at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseAnyEvent(BuildEventArgs buildEvent)
   at Microsoft.Build.BackEnd.Logging.EventSourceSink.<Consume>b__81_9(ProjectStartedEventArgs args)
   at Microsoft.Build.BackEnd.Logging.EventSourceSink.Consume(BuildEventArgs buildEvent)
   at Microsoft.Build.BackEnd.Logging.LoggingService.RouteBuildEvent(BuildEventArgs eventArg)
   at Microsoft.Build.BackEnd.Logging.LoggingService.RouteBuildEvent(Object loggingEvent)
   at Microsoft.Build.BackEnd.Logging.LoggingService.LoggingEventProcessor(Object loggingEvent)

or

##[error]Child node "1" exited prematurely. Shutting down. Diagnostic information may be found in files in "/tmp/MSBuildTempcloudtest/" and will be named MSBuild_*.failure.txt. This location can be changed by setting the MSBUILDDEBUGPATH environment variable to a different directory.Microsoft.Build.Framework.InternalErrorException: MSB0001: Internal MSBuild Error: ContextID 61 should have been in the ID-to-project file mapping but wasn't!
   at Microsoft.Build.Shared.ErrorUtilities.ThrowInternalError(String message, Object[] args)
   at Microsoft.Build.BackEnd.Logging.LoggingService.GetAndVerifyProjectFileFromContext(BuildEventContext context)
   at Microsoft.Build.BackEnd.Logging.LoggingService.LogBuildEvent(BuildEventArgs buildEvent)
   at Microsoft.Build.Experimental.BuildCheck.Infrastructure.BuildCheckManagerProvider.BuildCheckManager.Microsoft.Build.Experimental.BuildCheck.Infrastructure.IResultReporter.ReportResult(BuildEventArgs eventArgs, ICheckContext checkContext)
   at Microsoft.Build.Experimental.BuildCheck.Infrastructure.CheckWrapper.ReportResult(BuildCheckResult result, ICheckContext checkContext, CheckConfigurationEffective config)
   at Microsoft.Build.Experimental.BuildCheck.Infrastructure.BuildEventsProcessor.ReportResult(CheckWrapper checkWrapper, ICheckContext checkContext, CheckConfigurationEffective[] configPerRule, BuildCheckResult result)
   at Microsoft.Build.Experimental.BuildCheck.Checks.PropertiesUsageCheck.DoneWithProject(BuildCheckDataContext`1 context)
   at Microsoft.Build.Experimental.BuildCheck.Infrastructure.BuildCheckCentralContext.<>c__DisplayClass25_0`1.<RegisterAction>g__WrappedHandler|0(BuildCheckDataContext`1 context)
   at Microsoft.Build.Experimental.BuildCheck.Infrastructure.BuildCheckCentralContext.RunRegisteredActions[T](List`1 registeredCallbacks, T checkData, ICheckContext checkContext, Action`4 resultHandler)
   at Microsoft.Build.Experimental.BuildCheck.Infrastructure.BuildEventsProcessor.ProcessProjectDone(ICheckContext checkContext, String projectFullPath)
   at Microsoft.Build.Experimental.BuildCheck.Infrastructure.BuildCheckBuildEventHandler.HandleBuildEvent(BuildEventArgs e)
   at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseAnyEvent(Object sender, BuildEventArgs buildEvent)
   at Microsoft.Build.BackEnd.Logging.EventSourceSink.RaiseAnyEvent(Object sender, BuildEventArgs buildEvent)
   at Microsoft.Build.BackEnd.Logging.LoggingService.RouteBuildEvent(BuildEventArgs eventArg)
   at Microsoft.Build.BackEnd.Logging.LoggingService.RouteBuildEvent(Object loggingEvent)
   at Microsoft.Build.BackEnd.Logging.LoggingService.LoggingEventProcessor(Object loggingEvent)

It fails randomly but for sure caused by the feature.

Steps to Reproduce

navigate to the repo and observe the issue https://github.com/dotnet/extensions/pull/5810/checks?check_run_id=35940423010 or check the binlog attached (change .zip -> .binlog)

Build_runtime_windows.zip

Expected Behavior

BuildCheck runs smootly.

Actual Behavior

enabling the feature causes build crash.

Analysis

No response

Versions & Configurations

No response

[baronfel]

I think we just merged a PR hardening this check this morning, so maybe this has already been fixed?

[YuliiaKovalova]

I thought the same but @JanKrivanek claims it's still the issue :(

[JanKrivanek]

If you refer to #11289 - that one is for simiarly looking issue but with different cause (assembly loads logging) and diferent severity - the other one is just overly snapy checking during the logging; this case is real issue (caused be logical bug in LoggingService causing it to not expect any logging for project after ProjectFinishedEventArgs being received - while BuildCheck needs to emit some diagnostics for a said project exactly after that event - e.g. it can only detect that defined properties were unused at that point in time).

This unfortunately feels as an adoption blocker - hence tagging as Pri-1

@YuliiaKovalova - great job for catching this and nicely logging with full stack!