NuGet 4.9.2 fails to install packages from nuget.org with "Canceled" error

[dtretyakov]

Details about Problem

NuGet product used: NuGet.exe
NuGet version 4.9.2:
OS: Windows

Detailed repro steps so we can see the same problem

Execute package restore like that:

C:\Teamcity\BuildAgent\tools\NuGet.CommandLine.4.9.2\tools\NuGet.exe restore Z:\work\solution.sln -NoCache -Verbosity detailed -Source https://feed/nuget/ -Source -Source https://api.nuget.org/v3/index.json

Restore command fails with errors like that:

WARNING: Unable to find version '4.0.1' of package 'Microsoft.CSharp'.
  https://api.nuget.org/v3/index.json: Canceled

Unable to find version '4.0.1' of package 'Microsoft.CSharp'.
  https://api.nuget.org/v3/index.json: Canceled
  https://feed/nuget/: Package 'Microsoft.CSharp.4.0.1' is not found on source 'https://feed/nuget/'.

Other suggested things

Verbose Logs

Despite -Verbosity detailed was passed it does not bring any additional details about cause of Canceled task status. So how to investigate the cause of that?

[jainaashish]

Did it only started happening with 4.9.2 version?
Are you able to install the same package with other nuget.exe?
Are you able to access https://api.nuget.org/v3/index.json in browser?

It seems like this was reported in your build server, so just make sure that machine has access to internet.

[dtretyakov]

@jainaashish, the customer says that it was working fine in NuGet 4.8.1. The machine has access to the https://api.nuget.org/v3/index.json

The problem is that cause of Canceled error is unknown and NuGet.exe with -Verbosity detailed does not help to understand whats going wrong.

[jainaashish]

can you provide repro steps to reproduce locally? AFAIK cancelled will only happen when someone explicitly cancelled that restore task.

[dtretyakov]

@jainaashish, I don't know how to reproduce it locally. Customer says that it is intermittent issue, maybe it's caused by firewall/network issues in their on-premises network. Log with timestamps looks like that:

[13:21:01] :		 [restore] Starting: C:\Teamcity\BuildAgent\tools\NuGet.CommandLine.4.9.2\tools\NuGet.exe restore solution.sln -NoCache -Verbosity detailed -Source https://feed/nuget/ -Source https://api.nuget.org/v3/index.json
[13:21:01] :		 [restore] in directory: Z:\Agent\work\solution\src
[13:21:01] :		 [restore] NuGet Version: 4.9.2.5706
[13:21:01] :		 [restore] MSBuild auto-detection: using msbuild version '15.7.179.6572' from 'C:\Program Files (x86)\Microsoft Visual Studio\2017\BuildTools\MSBuild\15.0\bin'. Use option -MSBuildVersion to force nuget to use a specific version of MSBuild.
[13:21:01] :		 [restore] MSBuild P2P timeout [ms]: 228000
[13:21:01] :		 [restore] C:\Program Files (x86)\Microsoft Visual Studio\2017\BuildTools\MSBuild\15.0\bin\msbuild.exe "Z:\Agent\temp\buildTmp\NuGetScratch\rnbo4hiy.dgv.nugetinputs.targets" /t:GenerateRestoreGraphFile /nologo /nr:false /v:q /p:NuGetRestoreTargets="Z:\Agent\temp\buildTmp\NuGetScratch\4o0nwhfw.cm4.nugetrestore.targets" /p:RestoreUseCustomAfterTargets="True" /p:RestoreTaskAssemblyFile="C:\Teamcity\BuildAgent\tools\NuGet.CommandLine.4.9.2\tools\NuGet.exe" /p:RestoreSources="https://feed/nuget/;https://api.nuget.org/v3/index.json;"  /p:RestoreSolutionDirectory="Z:\Agent\work\solution\src\\" /p:SolutionDir="Z:\Agent\work\solution\src\\" /p:SolutionName="Sln"
[13:21:03] :		 [restore] 
[13:21:04] :		 [restore] Restoring NuGet package ...
...
[13:21:05]W:		 [restore] WARNING: Unable to find version '4.4.1' of package 'System.Diagnostics.DiagnosticSource'.
[13:21:05] :		 [restore]   https://api.nuget.org/v3/index.json: Canceled
[13:21:05] :		 [restore]   https://feed/nuget/: Package 'System.Diagnostics.DiagnosticSource.4.4.1' is not found on source 'https://feed/nuget/'.
...
[13:21:05]W:		 [restore] Process exited with code 1

How to diagnose this problem? NuGet.exe logging does not help in it.

[jainaashish]

can you ask your customer to run this command with -Verbosity detailed and then shared the logs... may be that give us more details.

[dtretyakov]

@jainaashish, already did it and have mentioned it multiple times that -Verbosity detailed does not bring any additional details.

[jainaashish]

then I don't know what we can do here until we have the repro details. It may be nuget 4.8.1 was not handling cancellation properly which could have been fixed in 4.9.2 which is why your customer is seeing it now but in reality the problem was already there which is, something is always cancelling those http requests to nuget.org

[DomZZ]

Same problem here (also with TeamCity).
I never seen this problem with nuget 2.7 and this one appears sometimes (with nuget v4.9.3), may be this is related to either client or server timeouts.

[danpowell88]

Also getting this same issue on Teamcity as @DomZZ , detailed verbosity does not seem to add any more information, it has been around for a few versions of nuget at least

I worked with our ops team and they dont believe there is any filtering/firewalls in place, and I would assume so saying we can rerun the step directly after and it will work.

Ive also had this happen on windows server 2012 and 2019 boxes, the 2019 boxes are also just recently setup.

For reference we are also in Australia, perhaps some kind of issue with the Oceania cdn?

[triumlabs]

Also getting the same issue on Teamcity after upgraded to NuGet 5.1.0:

[12:49:56][restore] WARNING: Unable to find version '0.29.0' of package 'NuGetPowerTools'.
[12:49:56][restore]   C:\Users\TeamCityBuildAgent\.nuget\packages\: Package 'NuGetPowerTools.0.29.0' is not found on source 'C:\Users\TeamCityBuildAgent\.nuget\packages\'.
[12:49:56][restore]   https://api.nuget.org/v3/index.json: Problem starting the plugin 'C:\TeamCity\buildAgent\plugins\nuget-agent\bin\credential-plugin\net46\CredentialProvider.TeamCity.exe'. A task was canceled.
[12:49:56][restore] 

As a resolution, NuGet was reverted back to version 4.9.1 where nuget restore works fine again.

[danpowell88]

It now seems to have changed slightly with more error detail

[restore] NuGet Version: 5.1.0.6013
.........
[11:16:02] [restore] WARNING: Unable to find version '1.5.1' of package 'WebActivator'.
[11:16:02] [restore] E:\nuget\packages: Package 'WebActivator.1.5.1' is not found on source 'E:\nuget\packages'.
[11:16:02] [restore] C:\Program Files (x86)\Microsoft SDKs\NuGetPackages: Package 'WebActivator.1.5.1' is not found on source 'C:\Program Files (x86)\Microsoft SDKs\NuGetPackages'.
[11:16:02] [restore] https://api.nuget.org/v3/index.json: Problem starting the plugin 'C:\Program Files\BuildAgent\plugins\nuget-agent\bin\credential-plugin\net46\CredentialProvider.TeamCity.exe'. A task was canceled.
[11:16:02] [restore] http://nuget.ebgames.com.au/nuget: Package 'WebActivator.1.5.1' is not found on source 'http://nuget.ebgames.com.au/nuget'.
[11:16:02] [restore]

[DomZZ]

It seems that many people reach this issues and it has been fixed in Microsoft Credential Provider : https://github.com/Microsoft/artifacts-credprovider/releases/tag/0.1.15

Then I think that the problem is on client side and TeamCity needs to make some updates.

[NikolayPianikov]

Could you add the environment variable NUGET_PLUGIN_LOG_PATH to your build configuration and specify a log file path there. Please share this file

[danpowell88]

Build log

[09:13:10]	    Unable to find version '3.1.0' of package 'NSubstitute'.
[09:13:10]	      E:\nuget\packages: Package 'NSubstitute.3.1.0' is not found on source 'E:\nuget\packages'.
[09:13:10]	      C:\Program Files (x86)\Microsoft SDKs\NuGetPackages\: Package 'NSubstitute.3.1.0' is not found on source 'C:\Program Files (x86)\Microsoft SDKs\NuGetPackages\'.
[09:13:10]	      https://api.nuget.org/v3/index.json: Problem starting the plugin 'C:\Program Files\BuildAgent\plugins\nuget-agent\bin\credential-plugin\net46\CredentialProvider.TeamCity.exe'. A task was canceled.
[09:13:10]	      http://nuget.abcd.com/nuget: Package 'NSubstitute.3.1.0' is not found on source 'http://nuget.abcd.com/nuget'.
[09:13:10]	    Unable to find version '3.1.0' of package 'Microsoft.Owin.Security'.
[09:13:10]	      E:\nuget\packages: Package 'Microsoft.Owin.Security.3.1.0' is not found on source 'E:\nuget\packages'.
[09:13:10]	      C:\Program Files (x86)\Microsoft SDKs\NuGetPackages\: Package 'Microsoft.Owin.Security.3.1.0' is not found on source 'C:\Program Files (x86)\Microsoft SDKs\NuGetPackages\'.
[09:13:10]	      https://api.nuget.org/v3/index.json: Problem starting the plugin 'C:\Program Files\BuildAgent\plugins\nuget-agent\bin\credential-plugin\net46\CredentialProvider.TeamCity.exe'. A task was canceled.
[09:13:10]	      http://nuget.abcd.com/nuget: Package 'Microsoft.Owin.Security.3.1.0' is not found on source 'http://nuget.abcd.com/nuget'.
[09:13:10]	    Unable to find version '2.0.0' of package 'NodaTime'.
[09:13:10]	      E:\nuget\packages: Package 'NodaTime.2.0.0' is not found on source 'E:\nuget\packages'.
[09:13:10]	      C:\Program Files (x86)\Microsoft SDKs\NuGetPackages\: Package 'NodaTime.2.0.0' is not found on source 'C:\Program Files (x86)\Microsoft SDKs\NuGetPackages\'.
[09:13:10]	      https://api.nuget.org/v3/index.json: Problem starting the plugin 'C:\Program Files\BuildAgent\plugins\nuget-agent\bin\credential-plugin\net46\CredentialProvider.TeamCity.exe'. A task was canceled.
[09:13:10]	      http://nuget.abcd.com/nuget: Package 'NodaTime.2.0.0' is not found on source 'http://nuget.abcd.com/nuget'.
[09:13:10]	    Unable to find version '0.1.0' of package 'Dapper-NodaTime'.
[09:13:10]	      E:\nuget\packages: Package 'Dapper-NodaTime.0.1.0' is not found on source 'E:\nuget\packages'.
[09:13:10]	      C:\Program Files (x86)\Microsoft SDKs\NuGetPackages\: Package 'Dapper-NodaTime.0.1.0' is not found on source 'C:\Program Files (x86)\Microsoft SDKs\NuGetPackages\'.
[09:13:10]	      https://api.nuget.org/v3/index.json: Problem starting the plugin 'C:\Program Files\BuildAgent\plugins\nuget-agent\bin\credential-plugin\net46\CredentialProvider.TeamCity.exe'. A task was canceled.
[09:13:10]	      http://nuget.abcd.com/nuget: Package 'Dapper-NodaTime.0.1.0' is not found on source 'http://nuget.abcd.com/nuget'.

Nuget log during that time

[2019-07-02 09:13:06,096] VERBOSE - .NET SDK was not detected.
[2019-07-02 09:13:06,104] VERBOSE - Authentication is supported.
[2019-07-02 09:13:06,107] VERBOSE - Running in plug-in mode

There are additional logs after that time also, note we dont use any kind of credentials for nuget

[2019-07-02 09:55:24,996] VERBOSE - .NET SDK 2.2.202 was detected.
[2019-07-02 09:55:25,002] VERBOSE - Authentication is supported.
[2019-07-02 09:55:25,003] VERBOSE - Running in plug-in mode
[2019-07-02 09:55:25,804] VERBOSE - Could not provide credentials for URI https://api.nuget.org/v3/index.json
[2019-07-02 11:04:03,538] VERBOSE - .NET SDK 2.2.202 was detected.
[2019-07-02 11:04:03,543] VERBOSE - Authentication is supported.
[2019-07-02 11:04:03,545] VERBOSE - Running in plug-in mode
[2019-07-02 11:04:04,067] VERBOSE - Could not provide credentials for URI https://api.nuget.org/v3/index.json
[2019-07-02 11:04:21,622] VERBOSE - .NET SDK 2.2.202 was detected.
[2019-07-02 11:04:21,625] VERBOSE - Authentication is supported.
[2019-07-02 11:04:21,627] VERBOSE - Running in plug-in mode
[2019-07-02 11:04:22,111] VERBOSE - Could not provide credentials for URI https://api.nuget.org/v3/index.json

Not sure why it couldn't detect the sdk and then later it did or if thats related at all.

PS C:\Users\Administrator> dotnet --info
.NET Core SDK (reflecting any global.json):
Version: 2.2.202
Commit: 8a7ff6789d

Runtime Environment:
OS Name: Windows
OS Version: 10.0.17763
OS Platform: Windows
RID: win10-x64
Base Path: C:\Program Files\dotnet\sdk\2.2.202\

Host (useful for support):
Version: 2.2.3
Commit: 6b8ad509b6

.NET Core SDKs installed:
1.1.12 [C:\Program Files\dotnet\sdk]
1.1.13 [C:\Program Files\dotnet\sdk]
2.1.202 [C:\Program Files\dotnet\sdk]
2.1.504 [C:\Program Files\dotnet\sdk]
2.1.505 [C:\Program Files\dotnet\sdk]
2.1.602 [C:\Program Files\dotnet\sdk]
2.2.104 [C:\Program Files\dotnet\sdk]
2.2.202 [C:\Program Files\dotnet\sdk]

.NET Core runtimes installed:
Microsoft.AspNetCore.All 2.1.8 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
Microsoft.AspNetCore.All 2.1.9 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
Microsoft.AspNetCore.All 2.2.2 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
Microsoft.AspNetCore.All 2.2.3 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
Microsoft.AspNetCore.App 2.1.8 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 2.1.9 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 2.2.2 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 2.2.3 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.NETCore.App 1.0.14 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 1.0.15 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 1.1.11 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 1.1.12 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 2.0.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.8 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 2.1.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 2.2.2 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 2.2.3 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]

[danpowell88]

Any movement on this?

Also had a slightly different error log today that resulted in restore not completing

[restore] Starting: "C:\Program Files\BuildAgent\tools\NuGet.CommandLine.5.1.0\tools\NuGet.exe" restore E:\teamcity\work<sha>\foobar.sln
[13:18:57] [restore] in directory: E:\teamcity\work<sha>
[13:18:57] [restore] MSBuild auto-detection: using msbuild version '15.9.21.664' from 'C:\Program Files (x86)\Microsoft Visual Studio\2017\Community\MSBuild\15.0\bin'.
[13:18:58] [restore] Restoring NuGet package foobar.Core.Logging.1.1.0.48.
[13:18:58] [restore] Restoring NuGet package foobar.Core.1.1.276.
[13:18:58] [restore] Restoring NuGet package Dispatch.Messages.1.1.65.
[13:18:58] [restore] Restoring NuGet package foobar.Core.AppEnvironment.1.1.236.
[13:18:58] [restore] Restoring NuGet package Dispatch.Client.1.1.65.
[13:18:58] [restore] Restoring NuGet package JetBrains.Annotations.2019.1.1.
[13:18:59] [restore] GET http://nuget.foobar.com/nuget/Packages(Id='JetBrains.Annotations',Version='2019.1.1')
[13:18:59] [restore] GET http://nuget.foobar.com/nuget/Packages(Id='foobar.Core',Version='1.1.276')
[13:18:59] [restore] GET http://nuget.foobar.com/nuget/Packages(Id='Dispatch.Client',Version='1.1.65')
[13:18:59] [restore] GET http://nuget.foobar.com/nuget/Packages(Id='foobar.Core.Logging',Version='1.1.0.48')
[13:18:59] [restore] GET http://nuget.foobar.com/nuget/Packages(Id='foobar.Core.AppEnvironment',Version='1.1.236')
[13:18:59] [restore] GET http://nuget.foobar.com/nuget/Packages(Id='Dispatch.Messages',Version='1.1.65')
[13:18:59] [restore] NotFound http://nuget.foobar.com/nuget/Packages(Id='JetBrains.Annotations',Version='2019.1.1') 39ms
[13:18:59] [restore] OK http://nuget.foobar.com/nuget/Packages(Id='foobar.Core.Logging',Version='1.1.0.48') 43ms
[13:18:59] [restore] GET http://nuget.foobar.com/nuget/FindPackagesById()?id='JetBrains.Annotations'&semVerLevel=2.0.0
[13:18:59] [restore] OK http://nuget.foobar.com/nuget/Packages(Id='foobar.Core.AppEnvironment',Version='1.1.236') 44ms
[13:18:59] [restore] OK http://nuget.foobar.com/nuget/Packages(Id='Dispatch.Client',Version='1.1.65') 46ms
[13:18:59] [restore] OK http://nuget.foobar.com/nuget/Packages(Id='foobar.Core',Version='1.1.276') 59ms
[13:18:59] [restore] OK http://nuget.foobar.com/nuget/Packages(Id='Dispatch.Messages',Version='1.1.65') 58ms
[13:18:59] [restore] OK http://nuget.foobar.com/nuget/FindPackagesById()?id='JetBrains.Annotations'&semVerLevel=2.0.0 18ms
[13:18:59] [restore] GET http://nuget.foobar.com/api/v2/package/foobar.core.appenvironment/1.1.236
[13:18:59] [restore] GET http://nuget.foobar.com/api/v2/package/dispatch.messages/1.1.65
[13:18:59] [restore] GET http://nuget.foobar.com/api/v2/package/foobar.core/1.1.276
[13:18:59] [restore] GET http://nuget.foobar.com/api/v2/package/foobar.core.logging/1.1.0.48
[13:18:59] [restore] GET http://nuget.foobar.com/api/v2/package/dispatch.client/1.1.65
[13:18:59] [restore] OK http://nuget.foobar.com/api/v2/package/dispatch.messages/1.1.65 6ms
[13:18:59] [restore] OK http://nuget.foobar.com/api/v2/package/foobar.core/1.1.276 6ms
[13:18:59] [restore] OK http://nuget.foobar.com/api/v2/package/foobar.core.logging/1.1.0.48 6ms
[13:18:59] [restore] OK http://nuget.foobar.com/api/v2/package/foobar.core.appenvironment/1.1.236 6ms
[13:18:59] [restore] OK http://nuget.foobar.com/api/v2/package/dispatch.client/1.1.65 8ms
[13:18:59] [restore] Installing Dispatch.Messages 1.1.65.
[13:18:59] [restore] Installing foobar.Core.AppEnvironment 1.1.236.
[13:18:59] [restore] Installing foobar.Core 1.1.276.
[13:18:59] [restore] Installing foobar.Core.Logging 1.1.0.48.
[13:18:59] [restore] Installing Dispatch.Client 1.1.65.
[13:18:59] [restore] Adding package 'foobar.Core.AppEnvironment.1.1.236' to folder 'E:\teamcity\work<sha>\packages'
[13:18:59] [restore] Adding package 'Dispatch.Messages.1.1.65' to folder 'E:\teamcity\work<sha>\packages'
[13:18:59] [restore] Adding package 'Dispatch.Client.1.1.65' to folder 'E:\teamcity\work<sha>\packages'
[13:18:59] [restore] Adding package 'foobar.Core.Logging.1.1.0.48' to folder 'E:\teamcity\work<sha>\packages'
[13:18:59] [restore] Adding package 'foobar.Core.1.1.276' to folder 'E:\teamcity\work<sha>\packages'
[13:18:59] [restore] Added package 'foobar.Core.AppEnvironment.1.1.236' to folder 'E:\teamcity\work<sha>\packages'
[13:18:59] [restore] Restoring NuGet package Microsoft.VisualStudio.SlowCheetah.3.0.61.
[13:18:59] [restore] Adding package 'Microsoft.VisualStudio.SlowCheetah.3.0.61' to folder 'E:\teamcity\work<sha>\packages'
[13:18:59] [restore] WARNING: Unable to find version '2019.1.1' of package 'JetBrains.Annotations'.
[13:18:59] [restore] E:\nuget\packages: Package 'JetBrains.Annotations.2019.1.1' is not found on source 'E:\nuget\packages'.
[13:18:59] [restore] C:\Program Files (x86)\Microsoft SDKs\NuGetPackages: Package 'JetBrains.Annotations.2019.1.1' is not found on source 'C:\Program Files (x86)\Microsoft SDKs\NuGetPackages'.
[13:18:59] [restore] http://nuget.foobar.com/nuget: Package 'JetBrains.Annotations.2019.1.1' is not found on source 'http://nuget.foobar.com/nuget'.
[13:18:59] [restore] https://api.nuget.org/v3/index.json: Problem starting the plugin 'C:\Program Files\BuildAgent\plugins\nuget-agent\bin\credential-plugin\net46\CredentialProvider.TeamCity.exe'. No async read operation is in progress on the stream.

Unfortunately I dont have the plugin log for this one.

[danpowell88]

any update on this, its crippling our workflow

[djee-ms]

We are hitting an issue which looks similar, and this is blocking our customers. We have some packages restoring correctly on Azure DevOps Pipeline (CI), and from the same feed some packages failing to restore. The package ID and version are correct, manual search and download from nuget.org works, but restore fail for no apparent reason. Any update on this?

[djee-ms]

See also microsoft/artifacts-credprovider#91, using 5.1.0 shows that the actual error is:

Problem starting the plugin 'D:\a\_tasks\NuGetCommand_333b11bd-d341-40d9-afcf-b32d5ce6f23b\2.155.0\CredentialProviderV2\plugins\netfx\CredentialProvider.Microsoft\CredentialProvider.Microsoft.exe'. A task was canceled.

[danpowell88]

We are now getting this error

 https://api.nuget.org/v3/index.json: Problem starting the plugin 'C:\Program Files\BuildAgent\plugins\nuget-agent\bin\credential-plugin\net46\CredentialProvider.TeamCity.exe'. Plugin 'CredentialProvider.TeamCity' failed within 0.434 seconds with exit code -1.

[nkolev92]

Hey folks,
We believe we have addressed all plugin reliability issues captured in #8528 which I believe is identical to this issue.

(Update: Fixes went into 5.3.1 and 5.4.0 and 5.5.0 - 5.5.0 didn't ship yet, but that fix will first hit 5.5.0-preview2)

[kartheekp-ms]

Duplicate of #7842