Home: StaticGraph Restore should clearly call out when a project is not `KnownToBeMSBuildFormat` When Called via a Solution File

[aolszowka]

I think is where the actual issue is:

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

In addition there is also another bug in here (if you want I can file another bug report):

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

We had to have our third party submit this PR https://github.com/dotnet/msbuild/pull/5698 (Thanks @madkat) to get this vendor's project extension in the "blessed list" but not all people who extend the project system are going to be as on top of it to actually file a bug, much less a pull request.

This has wide ranging consequences if you intend to make this the default as proposed by #9803 and more discussion at https://github.com/NuGet/docs.microsoft.com-nuget/issues/1941. Note that this is the SAME class of bug as noted here https://github.com/dotnet/msbuild/issues/5159 for full blown /graph that @cdmihai should be aware of as well.

Right or wrong tons of ISV's have extended the project system in unexpected ways, there needs to be a better way to resolve this, the gains are super worth it (@madkat please feel free to share the gains you've seen on our code base and others if you can), and we are super grateful that you guys are pushing this forward, but there are growing pains for sure.

_Originally posted by @aolszowka in https://github.com/NuGet/Home/issues/10307#issuecomment-738505272_

@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?

_Originally posted by @aolszowka in https://github.com/NuGet/Home/issues/10307#issuecomment-738983763_

[aolszowka]

@jeffkl Responding to https://github.com/NuGet/Home/issues/10307#issuecomment-740115167

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.

What about a compromise? A warning if the number of projects to restore != number of projects in solution. That would give people a fighting chance in large mixed mode solutions to at least know that something was not right?

[jeffkl]

@nkolev92 and the NuGet team will need to decide how to handle this issue. I'm technically not on the NuGet team, I contributed this feature from another team within Microsoft.

Any information that can be provided is very helpful to a user. There are other warnings within NuGet that list possible reasons that something isn't working. This code path could log something that says:

Your solution did not have any projects to restore, ensure that all projects are known to be MSBuild projects, that the projects exist, etc etc.

[aolszowka]

Just to be clear this bug is subtle if you have a large solution (3,000+ Projects) and a portion of those do not have their restore ran due to this. This is why the heuristic needs to be number of projects to restore != number of projects in solution.

[nkolev92]

I think adding additional logging to improve the diagnosability of static graph problems is a great idea.
Not confident we should disable the check, but first pursue an msbuild fix for any known false negatives

[aolszowka]

Yeah I am good with that. Is it too far of an ask to have the warning point to a page to report missing projects? Not sure if there is a precedence for that? It might help encourage ISV's to do "the right thing" or at least vote for the "escape hatch" https://github.com/dotnet/msbuild/issues/5931

Again want to stress that the check needs to find the "one or two missing projects in a sea of hundreds", many times project extensions are small "add-ons" to large existing C# code bases (think of like an interop library), they would easily be lost in the shuffle.

Is there any type of telemetry you can pick up to see how many times this gets hit?

[nkolev92]

We can't really tell how many customers are hitting this at this point.

Retitling to capture the logging improvements.

[aolszowka]

@nkolev92 Can you work on the wording for this issue, what is intended?

[nkolev92]

The goals here should be:

• Do not silently drop projects. Provide a log statement at a higher verbosity level for all projects that are not going to be restored.
• Provide an additional log message indicating the number of projects in the sln restored vs skipped.
• Provide additional logging that indicates why a restore happened/did not happen that go beyond project discovery.

[nkolev92]

See related: https://github.com/dotnet/runtime/issues/45755.
Might be worth enhancing the logging to help track what happened there as well.

[ViktorHofer]

Static graph currently crashes with circular dependencies in play and doesn't log this piece (which non static graph restore does):

C:\Program Files\dotnet\sdk\5.0.100\NuGet.targets(1050,5): error MSB4006: There is a circular dependency in the target dependency graph involving target "_GenerateRestoreProjectPathWalk". [C:\git\runtime5\src\libraries\shims\generated\mscorlib.csproj]

[cdmihai]

@ViktorHofer
Static graph does not have any visibility in target execution, it only knows about project level dependencies declared at evaluation time. So it detects cycles in the project dependency graph but not in the target dependency graph, which is only known at target execution time.

Or are you saying that during a static graph based build, a project fails with an exception and that doesn't get logged?

[ViktorHofer]

Or are you saying that during a static graph based build, a project fails with an exception and that doesn't get logged?

Right, the static graph nuget restore console app is crashing and doesn't log anything. Uncertain but I think the build even continues afterwards.

[cdmihai]

Right, the static graph nuget restore console app is crashing and doesn't log anything. Uncertain but I think the build even continues afterwards.

That definitely sounds like an issue. Please open a separate issue. Not enough data to tell if the problem is with msbuild or static graph restore

[nkolev92]

Right, the static graph nuget restore console app is crashing and doesn't log anything. Uncertain but I think the build even continues afterwards.

Static graph restore shouldn't be running that target.

I'm unfamiliar with static graph beyond restore though, so I might be missing some context.

[ViktorHofer]

Right, that target runs only without static graph restore which logs the circular dependency. With static graph restore enabled, restore just silently fails and nothing is logged.

[cdmihai]

With static graph restore enabled, restore just silently fails and nothing is logged.

That part is definitely an issue. Root cause unknown.