[Bug]: MSBuild crashes with "MSB0001: Internal MSBuild Error: must be valid"

[akoeplinger]

Issue Description

Copied from dotnet/dnceng#3304

I queried Kusto and it seems we started seeing this more often after we bumped the VMR build to use a bleeding-edge preview 7 SDK. I see one hit in the last 60 days but since we bumped to P7 SDK about 10 hours ago we already hit this three times.

    MSBUILD : error MSB4166: Child node "3" exited prematurely. Shutting down. Diagnostic information may be found in files in "/tmp/MSBuildTemproot/" and will be named MSBuild_*.failure.txt. This location can be changed by setting the MSBUILDDEBUGPATH environment variable to a different directory.
    MSBUILD : error MSB4166: /tmp/MSBuildTemproot/MSBuild_pid-14914_ef532437860e4947b63c7a07fa167972.failure.txt:
    MSBUILD : error MSB4166: UNHANDLED EXCEPTIONS FROM PROCESS 14914:
    MSBUILD : error MSB4166: =====================
    MSBUILD : error MSB4166: 07/08/2024 11:37:54
    MSBUILD : error MSB4166: Microsoft.Build.Framework.InternalErrorException: MSB0001: Internal MSBuild Error: must be valid
    MSBUILD : error MSB4166:    at Microsoft.Build.Shared.ErrorUtilities.ThrowInternalError(String message, Exception innerException, Object[] args)
    MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.Logging.LoggingContext.LogBuildEvent(BuildEventArgs buildEvent)
    MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.Components.RequestBuilder.AssemblyLoadsTracker.CurrentDomainOnAssemblyLoad(Object sender, AssemblyLoadEventArgs args)
    MSBUILD : error MSB4166: ===================
    MSBUILD : error MSB4166: 

Steps to Reproduce

Build the VMR repo. The failure only happens occasionally.

Expected Behavior

No crash.

Actual Behavior

There is a crash.

Analysis

No response

Versions & Configurations

No response

[JanKrivanek]

Strong suspect: #10102

[akoeplinger]

@JanKrivanek I got a couple hits, all of them with this log:

/vmr/.dotnet/sdk/9.0.100-preview.7.24365.4/NuGet.RestoreEx.targets(19,5): error : Unhandled exception. Microsoft.Build.Framework.InternalErrorException: MSB0001: Internal MSBuild Error: LoggingContext (type: Microsoft.Build.BackEnd.Components.Logging.EvaluationLoggingContext) was not valid during logging attempt.
/vmr/.dotnet/sdk/9.0.100-preview.7.24365.4/NuGet.RestoreEx.targets(19,5): error :    at Microsoft.Build.Shared.ErrorUtilities.ThrowInternalError(String message, Object[] args)
/vmr/.dotnet/sdk/9.0.100-preview.7.24365.4/NuGet.RestoreEx.targets(19,5): error :    at Microsoft.Build.BackEnd.Logging.LoggingContext.LogBuildEvent(BuildEventArgs buildEvent)
/vmr/.dotnet/sdk/9.0.100-preview.7.24365.4/NuGet.RestoreEx.targets(19,5): error :    at Microsoft.Build.BackEnd.Components.RequestBuilder.AssemblyLoadsTracker.CurrentDomainOnAssemblyLoad(Object sender, AssemblyLoadEventArgs args)

[JanKrivanek]

Thank you @akoeplinger for being on top of this without me giving you proper info about inserted versions!

This helps!

Stay tunned - this is near the top of my priority list :-)

[akoeplinger]

Got another hit with a different type (TaskLoggingContext):

MSBUILD : error MSB4166: Child node "4" exited prematurely. Shutting down. Diagnostic information may be found in files in "/tmp/MSBuildTemproot/" and will be named MSBuild_*.failure.txt. This location can be changed by setting the MSBUILDDEBUGPATH environment variable to a different directory.
MSBUILD : error MSB4166: /tmp/MSBuildTemproot/MSBuild_pid-86765_ae807cc80b1b4d5e9b44616aba701e05.failure.txt:
MSBUILD : error MSB4166: UNHANDLED EXCEPTIONS FROM PROCESS 86765:
MSBUILD : error MSB4166: =====================
MSBUILD : error MSB4166: 07/16/2024 10:54:06
MSBUILD : error MSB4166: Microsoft.Build.Framework.InternalErrorException: MSB0001: Internal MSBuild Error: LoggingContext (type: Microsoft.Build.BackEnd.Logging.TaskLoggingContext) was not valid during logging attempt.
MSBUILD : error MSB4166:    at Microsoft.Build.Shared.ErrorUtilities.ThrowInternalError(String message, Object[] args)
MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.Logging.LoggingContext.CheckValidity()
MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.Logging.LoggingContext.LogBuildEvent(BuildEventArgs buildEvent)
MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.Components.RequestBuilder.AssemblyLoadsTracker.CurrentDomainOnAssemblyLoad(Object sender, AssemblyLoadEventArgs args)
MSBUILD : error MSB4166: ===================

[JanKrivanek]

@akoeplinger - would you be able to point me to the builds as well? Binlog(s) would be super helpful

[akoeplinger]

They're mostly from https://dev.azure.com/dnceng-public/public/_build/results?buildId=742084&view=results and https://dev.azure.com/dnceng-public/public/_build/results?buildId=742554&view=results, but it's a bit hard to find the relevant failures.

I'll dig up the other ones tomorrow but here's one from this build and the corresponding binlog (renamed as zip so GitHub accepted it): source-inner-build.zip

    MSBUILD : error MSB4166: Child node "3" exited prematurely. Shutting down. Diagnostic information may be found in files in "/tmp/MSBuildTemproot/" and will be named MSBuild_*.failure.txt. This location can be changed by setting the MSBUILDDEBUGPATH environment variable to a different directory.
    MSBUILD : error MSB4166: /tmp/MSBuildTemproot/MSBuild_pid-16756_75287fc0501448ecbac643716c278662.failure.txt:
    MSBUILD : error MSB4166: UNHANDLED EXCEPTIONS FROM PROCESS 16756:
    MSBUILD : error MSB4166: =====================
    MSBUILD : error MSB4166: 07/16/2024 10:10:46
    MSBUILD : error MSB4166: Microsoft.Build.Framework.InternalErrorException: MSB0001: Internal MSBuild Error: LoggingContext (type: Microsoft.Build.BackEnd.Logging.TaskLoggingContext) was not valid during logging attempt.
    MSBUILD : error MSB4166:    at Microsoft.Build.Shared.ErrorUtilities.ThrowInternalError(String message, Object[] args)
    MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.Logging.LoggingContext.LogBuildEvent(BuildEventArgs buildEvent)
    MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.Components.RequestBuilder.AssemblyLoadsTracker.CurrentDomainOnAssemblyLoad(Object sender, AssemblyLoadEventArgs args)
    MSBUILD : error MSB4166: ===================
    MSBUILD : error MSB4166: