StaticGraphRestore Fails with NETSDK1004 in Some Scenarios

[aolszowka]

Details about Problem

NuGet product used: MSBuild /restore

Microsoft (R) Build Engine version 16.8.1+bd2ea1e3c for .NET Framework
Copyright (C) Microsoft Corporation. All rights reserved.

16.8.1.52902

OS version (i.e. win10 v1607 (14393.321)): Windows Server 1809 17763.1397

Worked before?: Yes, without StaticGraph

Detailed repro steps so we can see the same problem

Unclear on what exactly is happening here, but when using /p:RestoreUseStaticGraphEvaluation=true to get Static Graph we error with the following:

"S:\mobile\All\All.sln" (Build target) (1:2) ->
       "S:\mobile\Core\UserInterface\XX.MobileCore.UserInterface\XX.MobileCore.UserInterface.csproj" (default target) (7:2) ->
       (ResolvePackageAssets target) -> 
         C:\Program Files\dotnet\sdk\5.0.100\Sdks\Microsoft.NET.Sdk\targets\Microsoft.PackageDependencyResolution.targets(241,5): error NETSDK1004: Assets file 'S:\mobile\Core\UserInterface\XX.MobileCore.UserInterface\obj\project.assets.json' not found. Run a NuGet package restore to generate this file. [S:\mobile\Core\UserInterface\XX.MobileCore.UserInterface\XX.MobileCore.UserInterface.csproj]

Not using Static Graph (IE not defining the switch) works just fine.

We're motivated to help solve the issue, but we are constrained as to giving you code that repros (we don't have time to narrow it down blindly, please give guidance)

[aolszowka]

Shamelessly pinging @nkolev92 and @jeffkl as this is StaticGraph related.

[nkolev92]

Can you repro this on a single leaf project without any dependencies?

Try running just restore and then static restore and post the logs from the runs?

Do you set MSBuildProjectExtensionsPath anywhere?

[aolszowka]

Can you repro this on a single leaf project without any dependencies?

Did not appear so with the one project I tried

Try running just restore and then static restore and post the logs from the runs?

Can you clarify this request a bit more? I read this as doing the following:

msbuild Solution.sln /t:restore

Which restores all packages (For 98 projects in the solution)

Then cleaning the output (git clean -dfx) then trying:

msbuild Solution.sln /t:restore /p:RestoreUseStaticGraphEvaluation=true

Which yields the following:

Microsoft (R) Build Engine version 16.8.1+bd2ea1e3c for .NET Framework
Copyright (C) Microsoft Corporation. All rights reserved.

Building the projects in this solution one at a time. To enable parallel build, please add the "-m" switch.
Build started 11/19/2020 7:31:07 PM.
Project "S:\code-subgit\All\All.sln" on node 1 (Restore target(s)).
ValidateSolutionConfiguration:
  Building solution configuration "Debug|Any CPU".
Restore:
  Determining projects to restore...
  Evaluated 98 project(s) in 1386ms (98 builds, 0 failures).
  Nothing to do. None of the projects specified contain packages to restore.
Done Building Project "S:\code-subgit\All\All.sln" (Restore target(s)).

Build succeeded.
    0 Warning(s)
    0 Error(s)

Time Elapsed 00:00:02.48

Restored nothing? Not sure if that is expected?

Do you set MSBuildProjectExtensionsPath anywhere?

We don't explicitly; but this imports targets up the wazoo (including Xamarin) looking at the bin log:

MSBuildProjectExtensionsPath = S:\code-subgit\Core\Core\Implementation\obj\

Not sure who set this? (wasn't us)

[nkolev92]

Nothing to do. None of the projects specified contain packages to restore.

Weird, this suggests to me something went wrong and NuGet did not even start the restore.

Can you do verbose logs? Nothing rings a bell right now.

Not sure who set this? (wasn't us)

There are defaults, and that's normal. That property basically tells you where the assets file should go.

[aolszowka]

Can you do verbose logs? Nothing rings a bell right now.

Sure is there something in particular I can give to you? Or some private way to share the *.binlog (which would probably be way more useful?)

[nkolev92]

You can send it to nikolev [at] microsoft [dot] com

Verbose logs & binlog from the restore not happening might help.

[aolszowka]

Both have been provided as well as a binlog where staticgraph is not used (and it works without it)

[aolszowka]

@nkolev92 any chance to look at those logs?

[nkolev92]

Hey @aolszowka

I was out all of last week, I haven't gotten a chance yet. I'll get to it this week.

[nkolev92]

Hey @aolszowka

Unfortunately the logs are not telling me enough where I can figure out what's going wrong.
I can do some custom patches that you can run on your end that'd allow us to investigate more.

Here's a rundown on what I'd do to help us diagnose further.

• Static graph and regular restore really only differ in the msbuild project file reading. The core restore algorithms are 100% the same.
  Prior to any restore operation, be it in msbuild, dotnet or VS, NuGet creates a project representation that can be used to roundtrip a restore. We call that a dg spec.

With regular restore, you can see said dg spec by running GenerateRestoreGraphFile target.

You can try running on your sln.

My idea would be to make static graph write an equivalent file, and then we can compare those 2 files.

Alternatively, if you willing to debug, you can always follow:
https://github.com/NuGet/NuGet.Client/blob/dev/docs/debugging.md#testing-and-debugging-restore-in-msbuild
Build locally, import the powershell scripts linked and then call Invoke-NuGetCustom whereever you'd write msbuild.exe.

[aolszowka]

@nkolev92

With regular restore, you can see said dg spec by running GenerateRestoreGraphFile target.
You can try running on your sln.

Running "C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\MSBuild\Current\Bin\amd64\msbuild.exe" All.sln /t:GenerateRestoreGraphFile

Fails with:

"S:\code\All\All.sln" (GenerateRestoreGraphFile target) (1) ->
(GenerateRestoreGraphFile target) ->
  C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\Common7\IDE\CommonExtensions\Microsoft\NuGet\NuGet.targets(152,5): error : Missing RestoreGraphOutputPath property! [S:\code\All\All.sln]

Attempting to define it as this: "C:\Program Files (x86)\Microsoft Visual Studio\2019\Enterprise\MSBuild\Current\Bin\amd64\msbuild.exe" All.sln /t:GenerateRestoreGraphFile /p:RestoreGraphOutputPath=%CD%\out.g

Yields an incredibly complex file that will take me a couple of minutes to sanitize for public consumption, is this expected?

EDIT Here's the sanitized Gist: https://gist.github.com/aolszowka/efb0cd7620b4bee3df2117b2232705b8

[nkolev92]

Hey @aolszowka, yes the complex file is the one that's interesting.

Basically comparing that file from traditional msbuild walk restore, should be equivalent to the one generated by static graph restore.

Would you be willing to run a custom build static graph restore if I were to start a branch for that?

[aolszowka]

@nkolev92 I'm ready and willing, lets do this!

[nkolev92]

The easiest way to do this is to build the NuGet.Client locally.

I have added an environment variable that'll help you generate the equivalent of
GenerateRestoreGraphFile does for normal restore.

Steps:

1. Follow https://github.com/NuGet/NuGet.Client/blob/dev/CONTRIBUTING.md#code.
2. Clone https://github.com/nuget/nuget.client
3. Checkout dev-nkolev92-staticGraphLogging
4. From here on, I'd recommend using developer powershell command prompt.
5. Once you have built the repo, I'd recommend import nuget-debug-helpers.ps1. https://github.com/NuGet/NuGet.Client/blob/dev/docs/debugging.md#testing-and-debugging-restore-in-msbuild
6. Once you have done that, set the follow env var: to a location equivalent to what you have $env:RESTORE_TASK_DEPENDENCYGRAPHSPEC_PATH="C:\Users\Nikolche\Documents\Code\NuGet\NuGet.Client\staticGraph.dgspec.json"
7. Invoke-NuGetCustom /t:restore /p:RestoreUseStaticGraphEvaluation=true

You should be able to generate both dg spec files and the difference between them will be a good start in helping us understand what goes wrong.

[aolszowka]

@nkolev92 Not going to lie man fighting though this is a trip; is this really how it is on the inside? Like there isn't just an Azure DevOps Pipeline drop somewhere for this? for your branch? that you could just point me to? Unreal!

Right off the bat trying to run config.ps1 I get burned by dotnet/sdk#4240, charging on like a Wide Eyed Web Dev Fresh out of the 72 hour Coding Boot Camp that was given next to the abandoned KMart Super Center, I blindly invoke build.ps1 a ton of errors fly by. Still undeterred and hoping for those sweet gains I push forward.

After defining the environment variable as defined above I try running Invoke-NuGetCustom /t:restore /p:RestoreUseStaticGraphEvaluation=true

I hit the wall at 120mph with this gem:

Could not load file or assembly 'NuGet.Build.Tasks.Console, Version=5.9.0.30801, Culture=neutral, PublicKeyToken=31bf3856ad364e35' or one of its dependencies. Strong name validation failed. (Exception from HRESULT: 0x8013141A)

Any way to disable this? Like and oldschool CAS policy overload that says YOLO on the signatures? Probably related to the multitude of errors I just sped past because you can't stop in bat country?

[nkolev92]

I will get you a vsix that you can install.

I went with the approach that didn't require you to install anything to your VS instance. Bad assumption by me, the drop should hopefully make it easier.

[aolszowka]

Sounds great, let me know and I'll install it right away, I am not usually tied to my VS instances, I'll just snapshot and roll back if I'm that concerned.

[nkolev92]

Here's a link to the vsix.

To install, just double click or run the vsixinstaller.exe on the file.

To revert back, follow https://github.com/NuGet/NuGet.Client/blob/dev/docs/debugging.md#uninstalling-a-custom-version-of-the-nuget-extension-from-visual-studio.

[aolszowka]

@nkolev92 locked out :( I'll grab it as soon as the share link is fixed.

[nkolev92]

Argghhh...I got bit by one drive again...try this

[aolszowka]

@nkolev92

The files have a single difference; there is NOTHING in the Restore section!

[nkolev92]

and the rest of the specs are all the same?

For example, all of them say projectStyle": "PackageReference",?

Nothing obvious...I'll dig more to see if I can understand how this might happen.

[jeffkl]

@jeffkl, what happens if the project doesn't report itself as SolutionProjectType.KnownToBeMSBuildFormat?

I was referring to that question, why a project might be left out of restore when static graph based versus not.

[aolszowka]

@jeffkl I no longer have a pre-16.8 Visual Studio Install handy, the only third party library we utilize that was not a KnownToBeMSBuildFormat had support added in 16.8 as part of that above merged PR. Let me see if I can find an ancient box somewhere and get what your requested.

[aolszowka]

@jeffkl Found an old Visual Studio box that doesn't have the pulled PR; compare the following (same project/solution I probably messed up the xxxx in the sanitation between the two so ignore that):

Visual Studio 2019 MSBuild 16.7.4:

R:\xxxxxx\xxxxxx\xxxxxx\xxxxxx\xxxxxx>msbuild.exe /t:restore xxxxxxxxxxxxx.xxxxxxx.sln /p:RestoreUseStaticGraphEvaluation=true
Microsoft (R) Build Engine version 16.7.0+b89cb5fde for .NET Framework
Copyright (C) Microsoft Corporation. All rights reserved.

Building the projects in this solution one at a time. To enable parallel build, please add the "-m" switch.
Build started 12/4/2020 12:41:18 PM.
Project "R:\xxxxxx\xxxxxx\xxxxxx\xxxxxx\xxxxxx\xxxxxxxxxxxxx.xxxxxxx.sln" on node 1 (Restore target(s)).
ValidateSolutionConfiguration:
  Building solution configuration "Debug|Any CPU".
Restore:
  Determining projects to restore...
  Evaluated 0 project(s) in 142ms (0 builds, 0 failures).
Done Building Project "R:\xxxxxx\xxxxxx\xxxxxx\xxxxxx\xxxxxx\xxxxxxxxxxxxx.xxxxxxx.sln" (Restore target(s)).


Build succeeded.
    0 Warning(s)
    0 Error(s)

Time Elapsed 00:00:01.01

Visual Studio 2019 MSBuild 16.8.2 (this has the patch applied to allow this third party type to be recongized as a KnownToBeMSBuildFormat type:

S:\XXXXXX\xx\xxxxx\xxxxxx\xxxxxxxxx\xxxxxxxxxxxxxxx\xxxxxx>msbuild.exe /Target:Restore xxxxxxxxxxxxx.xxxxxxx.sln /p:RestoreUseStaticGraphEvaluation=true
Microsoft (R) Build Engine version 16.8.2+25e4d540b for .NET Framework
Copyright (C) Microsoft Corporation. All rights reserved.

Building the projects in this solution one at a time. To enable parallel build, please add the "-m" switch.
Build started 12/4/2020 12:41:28 PM.
Project "S:\XXXXXX\xx\xxxxx\xxxxxx\xxxxxxxxx\xxxxxxxxxxxxxxx\xxxxxx\xxxxxxxxxxxxx.xxxxxxx.sln" on node 1 (Restore target(s)).
ValidateSolutionConfiguration:
  Building solution configuration "Debug|Any CPU".
Restore:
  Determining projects to restore...
  Evaluated 3 project(s) in 703ms (3 builds, 0 failures).
  Committing restore...
  Assets file has not changed. Skipping assets file writing. Path: S:\XXXXXX\xx\xxxxx\xxxxxx\xxxxxxxxx\xxxxxxxxxxxxxxx\xxxxxx\obj\project.a
  ssets.json
  Restored S:\XXXXXX\xx\xxxxx\xxxxxx\xxxxxxxxx\xxxxxxxxxxxxxxx\xxxxxx\xxxxxxxxxxxxx.xxxxxxx.synproj (in 70 ms).

  NuGet Config files used:
      S:\XXXXXX\xx\xxxxx\NuGet.Config
      C:\Users\aceo\AppData\Roaming\NuGet\NuGet.Config
      C:\xxxxxx Files (x86)\NuGet\Config\Microsoft.VisualStudio.Offline.config

  Feeds used:
      S:\XXXXXX\xx\xxxxx\ProductDependencies\_Packages
      https://api.nuget.org/v3/index.json
      C:\xxxxxx Files (x86)\Microsoft SDKs\NuGetPackages\
      https://dotnet.myget.org/F/roslyn/api/v3/index.json
  All projects are up-to-date for restore.
Done Building Project "S:\XXXXXX\xx\xxxxx\xxxxxx\xxxxxxxxx\xxxxxxxxxxxxxxx\xxxxxx\xxxxxxxxxxxxx.xxxxxxx.sln" (Restore target(s)).


Build succeeded.
    0 Warning(s)
    0 Error(s)

Time Elapsed 00:00:01.91

As I described above, if you don't register yourself as KnownToBeMSBuildFormat you get lost when it attempts to perform a Graph based restore.

For our particular usecase with our third party we're OK, how do other ISV's know to do this?

EDIT: If we want to persue this we should open up a new case to avoid confusing this one. @nkolev92 what do we want to do about the original bug report that I opened this case up for? The relative paths issue?

[jeffkl]

Yeah the discussion around KnownToBeMSBuildFormat should move to MSBuild/Visual Studio as they both have a heavy dependency on it. My static graph restore implementation took the same dependency because I thought it was the best way to ensure we didn't try to restore projects that didn't support it.

One possible workaround, depending on the scenario is to move away from solution files all together and use Traversal projects. You restore these with static graph restore and they don't look at the project type in the same way as a solution file.

[aolszowka]

@jeffkl What part of the discussion? I already opened up a bug for KnownToBeMSBuildFormat (dotnet/msbuild#5931), however NuGet's StaticGraphRestore is basically broken for any other ISV until they provide some type of work around (or someone submits a PR to change the if statment). That discussion needs to happen with NuGet since the bug is with StaticGraphRestore, and I will open a case for that. EDIT: #10363

Using Traversal Projects is great, however we've got ~4,000 Solutions to Convert (Yeah, not great). Is there any tooling along the lines of try-convert for the Solutions? I'd be willing to give it a good run.

[jeffkl]

My point is that if you're not in the blessed list of KnownToBeMSBuildFormat, you're going to hit more and more roadblocks even if we just make it work with static graph restore. So dotnet/msbuild#5931 is the correct path to take to get the best long term fix. I'm not sure if the NuGet team should work around it by removing the check, as not checking could be a breaking change where projects used to be left out of restore and now they would be included which could lead to errors. I'll leave that decision up to the NuGet team. In my opinion, it is not a bug that projects that are not KnownToBeMSBuild are left out of restore. This is the intended behavior.

I do not know of an existing tool that would create a Traversal project out of a solution file, but if you have any knowledge of the MSBuild construction APIs, I would not expect it to be too difficult.

[aolszowka]

Fair enough, we'll move discussion on that issue to the linked one (#10363).

Back to this issue, these ARE supported types, who does this go to?

[jeffkl]

I've read through this issue and just to confirm, we think the root cause is that this line's i.AbsolutePath isn't returning an absolute path?

https://github.com/NuGet/NuGet.Client/blob/223189bbc21e8259e6771d363e69d37d9b10e693/src/NuGet.Core/NuGet.Build.Tasks.Console/MSBuildStaticGraphRestore.cs#L508

[aolszowka]

@jeffkl That is correct (at least what our debugging shows, seems like an Solution bug?) Why are we only affected by it in some scenarios?

[jeffkl]

Is there any way for you to create a small repro of the issue with a simple solution file and maybe two projects? That would be extremely useful. If AbsolutePath isn't returning an absolute path, that would be an MSBuild bug. We could work around it in here in NuGet as well.

[aolszowka]

Is there any way for you to create a small repro of the issue with a simple solution file and maybe two projects?

I can dig a bit more, but to be honest this solution has 98 projects (and a single leaf node did not repro it). It'd be great if this solution was smaller that I could throw it through Delta (https://www.st.cs.uni-saarland.de/dd/) to automate this. I'll give it a shot.

We could work around it in here in NuGet as well.

As much as this stinks this is where I am at with this bug, sprinkling a Path.GetFullPath(string) and move on with life. Not super optimal, but would get us past this bug. Would the team accept that?

[jeffkl]

I think a workaround is a decent approach. NuGet and MSBuild ship at the same time though so fixing it in MSBuild will achieve the same outcome in the same amount of time.

[nkolev92]

Thank you for the investigation to you both!

@aolszowka

this solution has 98 projects

Can you manually try to edit out the 97 projects and see if it repros?
I was recently doing the work that I provided above to get it ready for prod, and I ran into a problem where a project is not marked as KnownToMSBUild because of the Guid in the first part of the project, as here: https://github.com/NuGet/NuGet.Client/blob/3ef6cd3c0145e59314a495569c2d53296794fbf3/NuGet.sln#L9.
In particular FAE04EC0-301F-11D3-BF4B-00C04F79EFBC was something totally invalid.

As much as this stinks this is where I am at with this bug, sprinkling a Path.GetFullPath(string) and move on with life. Not super optimal, but would get us past this bug. Would the team accept that?

Where in particular would you recommend that?

Overall, I do think we need some additional logging on a more verbose level to ensure we're not silently dropping projects.

Removing the KnownToBeMSBuildFormat check makes me think we'd make it significantly harder to weed out the static graph bugs.

[aolszowka]

As much as this stinks this is where I am at with this bug, sprinkling a Path.GetFullPath(string) and move on with life. Not super optimal, but would get us past this bug. Would the team accept that?

Where in particular would you recommend that?

I would vote for it right here: https://github.com/NuGet/NuGet.Client/blob/223189bbc21e8259e6771d363e69d37d9b10e693/src/NuGet.Core/NuGet.Build.Tasks.Console/MSBuildStaticGraphRestore.cs#L508

Changed to:

return
  solutionFile
  .ProjectsInOrder
  .Where(i => i.ProjectType == SolutionProjectType.KnownToBeMSBuildFormat)
  .Select(i => new ProjectGraphEntryPoint(Path.GetFullPath(i.AbsolutePath), globalProperties))
  .ToList();

Note the addition of the Path.GetFullPath(string) in theory this should not be needed, but I believe this is where the bug is.

I would be willing to test out a patch on this.

Can you manually try to edit out the 97 projects and see if it repros?

I had originally tried this above, but let me try a few others when I get access back to this project tomorrow morning.

Removing the KnownToBeMSBuildFormat check makes me think we'd make it significantly harder to weed out the static graph bugs.

That is fair, for us we are OK today (we got our PR accepted into MSBuild), I was just trying to help the next guy down the road, especially if you plan to turn on static graph by default. I want to see this feature succeed and not get stymied by unexpected users of the ecosystem.

[nkolev92]

That is fair, for us we are OK today (we got our PR accepted into MSBuild), I was just trying to help the next guy down the road, especially if you plan to turn on static graph by default. I want to see this feature succeed and not get stymied by unexpected users of the ecosystem.

We appreciate all the help here.
We want to make it the default experience eventually, but we're going to listen to feedback. We certainly don't to break our customers.

Regarding the patch idea, if it's a relative path, we probably need to know what to resolve it against right?
Is this a path relative to the sln file?

[aolszowka]

Is this a path relative to the sln file?

I am not sure I understand the question?

The folder structure looks something like this:

src
src\All
src\All\All.sln
scr\Core\Email\Implementation\XX.MobileCore.Email.csproj

Is there any way for you to create a small repro of the issue with a simple solution file and maybe two projects?

I can dig a bit more, but to be honest this solution has 98 projects (and a single leaf node did not repro it). It'd be great if this solution was smaller that I could throw it through Delta (https://www.st.cs.uni-saarland.de/dd/) to automate this. I'll give it a shot.

I have dug on this, I am able to get this to repro with a single one of our projects, HOWEVER I still cannot get it to repro if I create a new project from scratch, here's what our SLN Looks like (minimized):

Microsoft Visual Studio Solution File, Format Version 12.00
# Visual Studio 15
VisualStudioVersion = 15.0.26124.0
MinimumVisualStudioVersion = 15.0.26124.0
Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "XX.MobileCore.Email", "..\Core\Email\Implementation\XX.MobileCore.Email.csproj", "{FB4074AX-70D2-4462-BFB8-0B0D425C73AD}"
EndProject
Global
	GlobalSection(SolutionConfigurationPlatforms) = preSolution
		Debug|Any CPU = Debug|Any CPU
		Release|Any CPU = Release|Any CPU
	EndGlobalSection
	GlobalSection(SolutionProperties) = preSolution
		HideSolutionNode = FALSE
	EndGlobalSection
	GlobalSection(ProjectConfigurationPlatforms) = postSolution
		{FB4074AX-70D2-4462-BFB8-0B0D425C73AD}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
		{FB4074AX-70D2-4462-BFB8-0B0D425C73AD}.Debug|Any CPU.Build.0 = Debug|Any CPU
		{FB4074AX-70D2-4462-BFB8-0B0D425C73AD}.Release|Any CPU.ActiveCfg = Release|Any CPU
		{FB4074AX-70D2-4462-BFB8-0B0D425C73AD}.Release|Any CPU.Build.0 = Release|Any CPU
	EndGlobalSection
EndGlobal

Some type of bug where going up a folder from the solution itself is mad?

[jeffkl]

Woohoo I was finally able to repro the issue. The problem is that this line:

https://github.com/NuGet/NuGet.Client/blob/dev/src/NuGet.Core/NuGet.Build.Tasks.Console/MSBuildStaticGraphRestore.cs#L508

Adds to a list containing paths like this:

C:\Foo\Bar\..\Baz\ClassLibrary1\ClassLibrary.csproj

Projects are then added to the dependency graph spec with the correct full path, but then this line looks for the projects by path:

https://github.com/NuGet/NuGet.Client/blob/dev/src/NuGet.Core/NuGet.Build.Tasks.Console/MSBuildStaticGraphRestore.cs#L654

And the dictionary lookup fails because the paths are in two different formats. I'll discuss with some people and see what the right fix is.

[aolszowka]

@jeffkl correct this was pointed out here #10307 (comment) and the comment proceeding it....

What is unknown is WHY that is coming back with a non-fully qualified path. Do you have an answer for that?

[jeffkl]

Yes the real question is:

Should MSBuild's SolutionFile API return a normalized full path when you call the AbsolutePath property?
Should MSBuild's ProjectGraphEntryPoint constructor normalize the path when you pass it in?
Should NuGet normalize the path before calling the ProjectGraphEntryPoint constructor?
Should NuGet normalize the path before looking it up in the dependency graph?

I'm asking around here to see what MSBuild/NuGet want to do...

[jeffkl]

@nkolev92 I'll be fixing this in dotnet/msbuild#5950, can you please mark this issue as External? And remove the NeedsRepro tag.

[aortiz-msft]

Closing as External per last comment.