MSB4181: The "Restore Task" task returned false but did not log an error.

[donnie-msft]

NuGet Product Used

dotnet.exe, MSBuild.exe, NuGet.exe, Visual Studio Package Management UI

Product Version

Repro'd at least back to 17.9

Worked before?

Yes, not sure

Impact

It's more difficult to complete my work

Repro Steps & Context

Particular restore errors are no longer being logged, so it's very difficult for customers to know why restore is failing.
In my case, I can repro this by adding a package reference for a package which exists on a feed, but I'm not authorized to download.

1. Add an Azure DevOps feed to your config.
2. Configure an upstream feed which requires authentication.
3. Remove any credentials that would authenticate your account on the upstream feed.
4. Add a PackageReference for a package version that is on the Upstream feed but not the Main feed.
5. Attempt to restore - even with detailed verbosity - and the following error results:
   msbuild src\NuGet.Clients\NuGet.PackageManagement.PowerShellCmdlets\NuGet.PackageManagement.PowerShellCmdlets.csproj /t:restore /clp:v=n

   error MSB4181: The "Restore Task" task returned false but did not log an error.

The actual error I found while debugging, which I expect to be logged, is:

NuGet.Protocol.Core.Types.FatalProtocolException: 'The feed 'vside [https://pkgs.dev.azure.com/azure-public/vside/_packaging/msft_consumption/nuget/v3/index.json]' lists package 'Microsoft.Internal.VisualStudio.Shell.Framework.17.8.37385' but multiple attempts to download the nupkg have failed. The feed is either invalid or required packages were removed while the current operation was in progress. Verify the package exists on the feed and try again.'

Unable to find package 'Microsoft.Internal.VisualStudio.Shell.Framework.17.8.37385'.
at NuGet.Protocol.FindPackagesByIdNupkgDownloader.d__7.MoveNext() in C:\NuGet.Client\src\NuGet.Core\NuGet.Protocol\Utility\FindPackagesByIdNupkgDownloader.cs:line 90
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter1.GetResult() at NuGet.Protocol.HttpFileSystemBasedFindPackageByIdResource.<GetDependencyInfoAsync>d__12.MoveNext() in C:\NuGet.Client\src\NuGet.Core\NuGet.Protocol\RemoteRepositories\HttpFileSystemBasedFindPackageByIdResource.cs:line 200 at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter1.GetResult()
at NuGet.Commands.SourceRepositoryDependencyProvider.d__26.MoveNext() in C:\NuGet.Client\src\NuGet.Core\NuGet.Commands\RestoreCommand\SourceRepositoryDependencyProvider.cs:line 369
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter1.GetResult() at NuGet.TaskResultCache2.<>c__51.<GetOrAddAsync>b__5_1(Task1 task) in C:\NuGet.Client\build\Shared\TaskResultCache.cs:line 98
at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
at System.Threading.Tasks.Task.Execute()

Verbose Logs

No response

[nkolev92]

First call comes to:

• https://github.com/NuGet/NuGet.Client/blob/a7131d98a28b0be1d21a125b5660fc8782c27ace/src/NuGet.Core/NuGet.Commands/RestoreCommand/SourceRepositoryDependencyProvider.cs#L176
  Which then goes to https://github.com/NuGet/NuGet.Client/blob/a7131d98a28b0be1d21a125b5660fc8782c27ace/src/NuGet.Core/NuGet.Commands/RestoreCommand/SourceRepositoryDependencyProvider.cs#L205-L227.

When we talk to the server first, it tells us that the package exists (we determine that byt looking up flat container, which these public upstreams have), so FindLibraryAsync returns at https://github.com/NuGet/NuGet.Client/blob/a7131d98a28b0be1d21a125b5660fc8782c27ace/src/NuGet.Core/NuGet.Commands/RestoreCommand/SourceRepositoryDependencyProvider.cs#L239-L271.
It optimizes because the considered package is there.

Then later, the stack trace above linked by @donnie-msft occurs.

and since the exception is PackageNotFoundProtocolException which extends from InvalidCacheProtocolException, https://github.com/NuGet/NuGet.Client/blob/a7131d98a28b0be1d21a125b5660fc8782c27ace/src/NuGet.Core/NuGet.Commands/RestoreCommand/SourceRepositoryDependencyProvider.cs#L376-L387, it rethrown and not logged to the logger, and thus not failing the restore appropriately.

Not sure why InvalidCacheProtocolException in particular gets ignored.

The fix could be as simple as stop ignoring that, but it could have some unintended side-effects.

I think the real root cause is a package is reported as available, but it isn't really. I'm not sure it's against the protocol to the letter, but it is inconsistent.

I think we need to get a fix here, and approach it holistically.

[nkolev92]

Changes that introduced the PackageNotFound exception.

There's context in the PR description + commit message: NuGet/NuGet.Client@527488e and NuGet/NuGet.Client#1319.

It's supposed to handle "deleted" packages and refresh the cache.

[akoeplinger]

We recently bumped to a 9.0 preview 6 SDK build and started seeing this error quite frequently during the dotnet VMR build.

I uploaded a binlog that shows no obvious signs of any restore issues in dotnet/sdk#41477 (comment)