Restore stuck & can't build due to missing ProjectRestoreInfo

[xen2]

Since we converted our project (Xenko) to new project system, we often (esp. after switching branches) end up in a broken state.

When trying to build, we end up with something like this in the log:

Error occurred while restoring NuGet packages: System.InvalidOperationException: The operation failed as details for project SiliconStudio.Core.Design.Tests could not be loaded.
   at NuGet.PackageManagement.VisualStudio.NetCorePackageReferenceProject.GetPackageSpecsAsync(DependencyGraphCacheContext context)
   at NuGet.PackageManagement.DependencyGraphRestoreUtility.<GetSolutionRestoreSpec>d__7.MoveNext()

Build is totally stuck, i.e it stays like this:

1>FastUpToDate: Project information is older than current project version, skipping check. (SiliconStudio.Core)
Error occurred while restoring NuGet packages: The operation failed as details for project SiliconStudio.Core.Design.Tests could not be loaded.
2>FastUpToDate: Project information is older than current project version, skipping check. (Irony)
3>FastUpToDate: Project information is older than current project version, skipping check. (SiliconStudio.ExecServer)

Restarting VS & git clean (.vs) usually doesn't seem to fix the issue.

I can sometime (but not always) get out of the situation by:
(1) Killing all MSBuild process
(2) Doing a manual (command-line) nuget restore (maybe this is probably what helps fix it since VS doesn't need to restore anymore)
(3) Sometimes (random magic) git clean and/or VS restart might also be necessary
(4) If this doesn't work, I end up doing a new checkout (takes a while)

It happens quite easily on multiple separate PC and users, so not a local issue.

I investigated little bit and it seems NominateProject is not called on this specific project.
Not sure if related, but here's what I noticed when debugging project-system:

• Some NominateRestore calls (but only about 20 of them, out of 100+ projects)
• A big Microsoft.Build.Exceptions.BuildAbortedException exception

  Exception thrown: 'Microsoft.Build.Exceptions.BuildAbortedException' in Microsoft.Build.dll
  Build was canceled. A node of the required type InProc could not be created.
  

  Could this be the main issue?
• Hundreds of System.OperationCanceledException in Microsoft.VisualStudio.Threading.dll
• A few more NominateRestore (but only for projects that already ran through NominateRestore before).

Sorry for the lack of easy repro, it is quite a big project that we can't share publicly yet.
This happens often and quite hard to get out, so quite a big blocker & slowing us down quite a lot.

[jmarolf]

@xen2 could you install this exentions and capture a verbose build log?

[Pilchie]

Also, can you get a project system log as described here: #3027 (comment)

[xen2]

Now loading the project with Build Logging + PROJECTSYSTEM_PROJECTOUTPUTPANEENABLED=1:

Here is the Build Logging pane result:
buildloggingpane2.txt
We can see lot of DesignTimeBuild stuck in Running state. This is probably what is preventing normal build to continue.
Here's the MSBuild log of one of those Running build:
SiliconStudio.Assets.CompilerApp_Debug_AnyCPU_DesignTimeBuild_2018-03-22T12_58_59.3988985+09_00.binlog.zip

I attached to all MSBuild.exe instances and checked their threads. None of them looks busy, so somehow maybe a build success/failure is not properly sent back to caller (DesignTimeBuild still in running state):

Additional remarks of issues I had with with Build Logging + PROJECTSYSTEM_PROJECTOUTPUTPANEENABLED=1:

(1) When Visual Studio is opening solution, I get the following (maybe unrelated?) error:

VsProjectFault_2ba8a90c-dcc7-484d-99ea-2bf2b784ec95.failure.txt

(2) I also sometimes get lots of [3/22/2018 12:41:36 PM Error] LoadProjectIdsAsync: Object reference not set to an instance of an object. in Output > Tests (and it takes over focus of Output pane every second so it is quite annoying).

Hope that helps.

[Pilchie]

@lifengl @jviau @adrianvmsft Any ideas here?

[adrianvmsft]

I see DesignTimeBuildManagerService in the log, so it could be related to the new DTBB service.
Could you try switching off to the old design time mechanism by setting this environment variable and see if you experience the same behavior?

SET CPS_DesignTimeBuild=Cps

[lifengl]

@panopticoncentral do you know about the ProjectLogger code here?

[adrianvmsft]

Actually, nevermind, I see it already calls the old design time build system

[Pilchie]

Any progress here? What are next steps?

[davkean]

The null ref is known is the ProjectLogger - so ignore that.

[Pilchie]

@davkean - which nullref do you mean? The project fault looks like the logger is faulting the output group service dataflow is faulting because of null ref too:

System.AggregateException: Project system data flow 'OutputGroupsService Outer 343713' closed because of an exception: System.AggregateException: One or more errors occurred. ---> System.AggregateException: One or more errors occurred. ---> System.AggregateException: One or more errors occurred. ---> System.AggregateException: One or more errors occurred. ---> System.AggregateException: One or more errors occurred. ---> System.AggregateException: One or more errors occurred. ---> System.AggregateException: One or more errors occurred. ---> System.NullReferenceException: Object reference not set to an instance of an object.
   at Microsoft.VisualStudio.ProjectSystem.Tools.BuildLogging.Model.LoggerBase.GetLogPath(Build build)
   at Microsoft.VisualStudio.ProjectSystem.Tools.BuildLogging.Model.ProjectLogger.Shutdown()
   at Microsoft.Build.Utilities.MuxLogger.SubmissionRecord.Shutdown()
   at Microsoft.Build.Utilities.MuxLogger.UnregisterLoggers(Int32 submissionId)
   at Microsoft.VisualStudio.ProjectSystem.Build.BuildUtilities.<>c__DisplayClass14_0.<AppendUnregisterLoggersTask>b__0(Task`1 flt)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.Tasks.Task.Execute()

@xen2 the project log looks like it's from a bit of an old build? What version of VS are you using?

[davkean]

@xen2 Are you still running into this? I've not seen an update until March - we've significantly changed this code path in 15.7. Please retry with latest build, and comment if you are still running into issues and I'll reopen.

[clarkitect]

This has begun on one of our solutions in 15.7.2 this week. It's rather crippling, please re-open and I'll see if I can get diagnostic info to attach.

[Pilchie]

Is this consistently after debugging or does it only happen with command line builds with dotnet build? If so, we should probably track at https://github.com/dotnet/cli.

[clarkitect]

Occurs at, or immediately after, open of solution in a fresh (escalated privileges, long story) instance of Visual Studio Professional 2017 15.7.2.

There may have been dotnet build command issued recently and there are projects within the solution that have .net core 2 and .net standard build targets defined.

Have not yet experimented with:

1. Uninstalling resharper
2. Uninstalling any other plugins that I've forgotten about

[roldengarm]

I have got exactly the same problem. After upgrading to latest VS 15.7.2 this issue started occurring. No idea what is causing it.

[clarkitect]

Update: problem "solved" or temporarily quieted. Cleaned git clean -fdx repository and haven't seen the complaint since.

A coworker "solved" or temporarily quieted it by rolling back to previous revision of Visual Studio.

[sunilbhujle]

Still happens with VS2017 Enterprise v15.7.5. As suggested git clean -fdx fixed it.