Restore not re-generating project.assets.json

[jaredpar]

NuGet Product Used

MSBuild.exe

Product Version

msbuild 17.5

Worked before?

msbuild 17.4 (caveats below)

Impact

I'm unable to use this version

Repro Steps & Context

This is an involved discussion that is hard to boil down to a simple repro. Have lots of internal data, logs, etc ... to help track this down. Whomever ends up looking at this can reach me internally at jaredpar@microsoft.com and I can help walk you through the situation if this isn't clear.

The rough order of events happening is the following.

1. msbuild.exe /t:restore Roslyn.sln.
2. msbuild.exe /restore src\NuGet\Microsoft.Net.Compilers.Toolset\AnyCpu\Microsoft.Net.Compilers.Toolset.Package.csproj
3. msbuild.exe /t:Clean src\NuGet\Microsoft.Net.Compilers.Toolset\AnyCpu\Microsoft.Net.Compilers.Toolset.Package.csproj
4. msbuild.exe /t:build /restore /p:BootstrapBuildPath=D:\a\_work\1\s\artifacts\Bootstrap Roslyn.sln

The actual commands are significantly more involved (included in verbose section) but that is the gist of commands. The key is the presence of /p:BootstrapBuildPath. When this is empty then every project in the solution will have a reference to Microsoft.Net.Compilers.Toolset (source).

The practical end effect here is that the project.assets.json file produced in step 1 and 2 should be different than the one produced in step 4 as the <PackageReference> set is different. The vast majority of projects do restore this way and show the correct values. The bug is that on every run there are a few projects that do not do this and end up with the version from step 1/2. This results in build breaks for us.

The easiest demonstration of this behavior is the PR: dotnet/roslyn#66864.

Notice that when we use commit b8ffff the build fails with ValidateBootstrap errors (this means restore failed). This failure will go away if we do either of the following:

1. Before step 4 completely delete the obj and bin directories. This forces all project.assets.json files to be regenerated and they are done so correctly. To us this suggests there is some timestamp / caching bug at play here.
2. Merge steps 1 + 2 into the same msbuild.exe command. I have no explanation for this but it's very easy to demonstrate.

This is very hard to reproduce locally. To the point we've not been able to successfully do it. We've only been able to observe this via CI but it reproduces 100% there.

It's unclear how long this bug has existed. What spawned this investigation is our response to #12373 was to delete static graph restore from our pipelines. The moment we did that we started running into this bug. After a few days of investigation we decided to combine steps 1 and 2 together on a whim and the issue went away. It's taken another week of digging to get to this particular point.

Please let us know if you need any other data to help track this down, we have lots.

Verbose Logs

Actual MSBuild commands executed in sequence


C:\Program Files\Microsoft Visual Studio\2022\Preview\MSBuild\Current\Bin\msbuild.exe /nologo /bl:D:\a\_work\1\s\artifacts\log\Debug\Restore.binlog /clp:Summary /logger:C:\Users\cloudtest\.nuget\packages\microsoft.dotnet.arcade.sdk\8.0.0-beta.23054.2\tools\net472\Microsoft.DotNet.ArcadeLogging.dll /m /nr:False /p:ContinuousIntegrationBuild=True /p:TreatWarningsAsErrors=false /p:Configuration=Debug /p:Projects=D:\a\_work\1\s\Roslyn.sln /p:RepoRoot=D:\a\_work\1\s\ /p:Restore=True /p:Build=False /p:Rebuild=False /p:Pack=False /p:Sign=False /p:Publish=False /p:ContinuousIntegrationBuild=True /p:OfficialBuildId= /p:RunAnalyzersDuringBuild=False /p:BootstrapBuildPath= /p:TreatWarningsAsErrors=False /p:EnableNgenOptimization=False /p:IbcOptimizationDataDir=D:\a\_work\1\s\.o%5c /p:RestoreUseStaticGraphEvaluation=False /p:VisualStudioIbcDrop= /p:VisualStudioDropAccessToken= /p:DeployExtension=false /p:ROSLYNUSEHARDLINKS=true /v:m C:\Users\cloudtest\.nuget\packages\microsoft.dotnet.arcade.sdk\8.0.0-beta.23054.2\tools\Build.proj
C:\Program Files\Microsoft Visual Studio\2022\Preview\MSBuild\Current\Bin\msbuild.exe /nologo /bl:D:\a\_work\1\s\artifacts\log\Release\Bootstrap.binlog /nodeReuse:false /p:TreatWarningsAsErrors=true /p:Configuration=Release /p:RunAnalyzersDuringBuild=true /p:ContinuousIntegrationBuild=true /p:RestoreUseStaticGraphEvaluation=false /p:RoslynEnforceCodeStyle=false /p:RunAnalyzersDuringBuild=false /p:DotNetUseShippingVersions=true /p:InitialDefineConstants=BOOTSTRAP /p:PackageOutputPath=D:\a\_work\1\s\artifacts\Bootstrap /p:EnableNgenOptimization=false /p:PublishWindowsPdb=false /restore /t:Pack src\NuGet\Microsoft.Net.Compilers.Toolset\AnyCpu\Microsoft.Net.Compilers.Toolset.Package.csproj
C:\Program Files\Microsoft Visual Studio\2022\Preview\MSBuild\Current\Bin\msbuild.exe /nologo /bl:D:\a\_work\1\s\artifacts\log\Release\BootstrapClean.binlog /nodeReuse:false /p:TreatWarningsAsErrors=true /p:Configuration=Release /p:ContinuousIntegrationBuild=true /p:RestoreUseStaticGraphEvaluation=false /t:Clean src\NuGet\Microsoft.Net.Compilers.Toolset\AnyCpu\Microsoft.Net.Compilers.Toolset.Package.csproj
C:\Program Files\Microsoft Visual Studio\2022\Preview\MSBuild\Current\Bin\msbuild.exe /nologo /bl:D:\a\_work\1\s\artifacts\log\Release\Build.binlog /clp:Summary /logger:C:\Users\cloudtest\.nuget\packages\microsoft.dotnet.arcade.sdk\8.0.0-beta.23054.2\tools\net472\Microsoft.DotNet.ArcadeLogging.dll /m /nr:False /p:ContinuousIntegrationBuild=True /p:TreatWarningsAsErrors=false /p:Configuration=Release /p:Projects=D:\a\_work\1\s\Roslyn.sln /p:RepoRoot=D:\a\_work\1\s\ /p:Restore=True /p:Build=True /p:Rebuild=False /p:Pack=True /p:Sign=False /p:Publish=False /p:ContinuousIntegrationBuild=True /p:OfficialBuildId= /p:RunAnalyzersDuringBuild=False /p:BootstrapBuildPath=D:\a\_work\1\s\artifacts\Bootstrap /p:TreatWarningsAsErrors=False /p:EnableNgenOptimization=False /p:IbcOptimizationDataDir=D:\a\_work\1\s\.o%5c /p:RestoreUseStaticGraphEvaluation=False /p:VisualStudioIbcDrop= /p:VisualStudioDropAccessToken= /p:DeployExtension=false /p:ROSLYNUSEHARDLINKS=true /v:m C:\Users\cloudtest\.nuget\packages\microsoft.dotnet.arcade.sdk\8.0.0-beta.23054.2\tools\Build.proj

The associated binlogs for each command are available in the published artifacts. Contact me if the artifacts have expired as I have local copies.

[nkolev92]

We're looking into this offline.

[ghost]

This issue has been automatically marked as stale because we have not received a response in 14 days. It will be closed if no further activity occurs within another 14 days of this comment.

[jaredpar]

Closing as we believe that the primary issue is in arcade: dotnet/arcade#12799

Thanks to @rainersigwald and @nkolev92 for helping us to get to the bottom of this.