NuGet Restore task fails with TaskCanceledException: A task was canceled.

[satbai]

I'm not sure if this issue belongs to Pipelines, NuGet or Artifacts Cred Provider because it's related to all of them combined.

When running NuGet restore on a Azure DevOps Pipeline hosted agent, in some cases NuGet cancels before all packages have been restored. This has only reproduced when running the restore task with the VS2017 Hosted agent - it does not repro when using a private agent on a dev machine.

Repro:
Restoring multiple packages from multiple feeds that are all in the same Azure DevOps account, when many feeds have the same packages, and some packages have dependencies.

Details:

• NuGet.exe 4.8+
• Azure DevOps Pipelines VS2017 hosted agent (VS2017 hosted agent has VisualStudio/15.8.5+28010.2036
  https://github.com/Microsoft/azure-pipelines-image-generation/blob/master/images/win/Vs2017-Server2016-Readme.md )
• Azure DevOps Pipelines NuGetCommand 2.146.0+ task Restore
• Artifacts Cred Provider 0.1.11

Verbose Logs

[command]C:\hostedtoolcache\windows\NuGet\4.8.1\x64\nuget.exe restore D:\a\1\s\Solution\Solution.sln -PackagesDirectory packages -NoCache -Verbosity Detailed -NonInteractive -ConfigFile D:\a\1\s\nuget.config
NuGet Version: 4.8.1.5435
MSBuild auto-detection: using msbuild version '15.9.21.664' from 'C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\MSBuild\15.0\bin'. Use option -MSBuildVersion to force nuget to use a specific version of MSBuild.
MSBuild P2P timeout [ms]: 120000
C:\Program Files (x86)\Microsoft Visual Studio\2017\Enterprise\MSBuild\15.0\bin\msbuild.exe "C:\Users\VssAdministrator\AppData\Local\Temp\NuGetScratch\4ydv3iew.4bj.nugetinputs.targets" /t:GenerateRestoreGraphFile /nologo /nr:false /v:q /p:NuGetRestoreTargets="C:\Users\VssAdministrator\AppData\Local\Temp\NuGetScratch\u0bjf12q.3k0.nugetrestore.targets" /p:RestoreUseCustomAfterTargets="True" /p:RestoreTaskAssemblyFile="C:\hostedtoolcache\windows\NuGet\4.8.1\x64\nuget.exe" /p:RestoreSolutionDirectory="D:\a\1\s\Solution\" /p:RestoreConfigFile="D:\a\1\s\nuget.config" /p:RestorePackagesPath="packages" /p:SolutionDir="D:\a\1\s\Solution\" /p:SolutionName="Solution"
Running restore with 2 concurrent jobs.
Reading project file D:\a\1\s\Solution\Solution.Client\Solution.Client.csproj.
Restoring packages for D:\a\1\s\Solution\Solution.Client\Solution.Client.csproj...
Restoring packages for .NETStandard,Version=v2.0...
GET https://buildcanary.pkgs.visualstudio.com/_packaging/bcdd2a48-8b72-4e1d-8c66-7731e6aa1736/nuget/v3/flat2/microsoft.dynamics.retail.build.product.msbuild/index.json
GET https://buildcanary.pkgs.visualstudio.com/_packaging/bcdd2a48-8b72-4e1d-8c66-7731e6aa1736/nuget/v3/flat2/newtonsoft.json/index.json
GET https://buildcanary.pkgs.visualstudio.com/_packaging/8495cefb-0629-456b-beca-45236d56a0a4/nuget/v3/flat2/microsoft.dynamics.retail.build.product.msbuild/index.json
GET https://buildcanary.pkgs.visualstudio.com/_packaging/8495cefb-0629-456b-beca-45236d56a0a4/nuget/v3/flat2/newtonsoft.json/index.json
Using D:\a_tasks\NuGetCommand_333b11bd-d341-40d9-afcf-b32d5ce6f23b\2.147.6\CredentialProviderV2\plugins\netfx\CredentialProvider.Microsoft\CredentialProvider.Microsoft.exe as a credential provider plugin.
[CredentialProvider.215708]Command-line v0.1.12: "D:\a_tasks\NuGetCommand_333b11bd-d341-40d9-afcf-b32d5ce6f23b\2.147.6\CredentialProviderV2\plugins\netfx\CredentialProvider.Microsoft\CredentialProvider.Microsoft.exe" -Plugin
[CredentialProvider.215708]Running in plug-in mode
[CredentialProvider.215708]Handling 'Request' 'Initialize' - {"ClientVersion":"4.8.1","Culture":"en-US","RequestTimeout":"00:00:05"}
A task was canceled.
[CredentialProvider.215708]Handling 'Request' 'GetOperationClaims' - {"PackageSourceRepository":"https://buildcanary.pkgs.visualstudio.com/_packaging/DuplicateFeed1/nuget/v3/index.json","ServiceIndex": ........... shortening long log............ }
[CredentialProvider.215708]Handling 'Request' 'GetOperationClaims' - {"PackageSourceRepository":"https://buildcanary.pkgs.visualstudio.com/_packaging/DuplicateFeed2/nuget/v3/index.json","ServiceIndex":{"@context":{"@vocab":"http://schema.nuget.org/services#", ........... shortening long log............ version":"3.0.0-beta"}}
[CredentialProvider.215708]Sending response: 'Request' 'GetOperationClaims'
[CredentialProvider.215708]Sending response: 'Request' 'GetOperationClaims'
[CredentialProvider.215708]Handling 'Request' 'GetOperationClaims' - {}
[CredentialProvider.215708]Sending response: 'Request' 'GetOperationClaims'
[CredentialProvider.215708]Handling 'Request' 'SetLogLevel' - {"LogLevel":"Debug"}
[CredentialProvider]Sending response: 'Request' 'SetLogLevel'
[CredentialProvider.215708]Sending response: 'Request' 'Initialize'
[CredentialProvider]Handling 'Request' 'GetAuthenticationCredentials' - {"Uri":"https://buildcanary.pkgs.visualstudio.com/_packaging/DuplicateFeed1/nuget/v3/index.json","IsRetry":false,"IsNonInteractive":true,"CanShowDialog":true}
[CredentialProvider]Creating a progress reporter with interval: 00:00:02
[CredentialProvider]Handling auth request, Uri: https://buildcanary.pkgs.visualstudio.com/_packaging/DuplicateFeed1/nuget/v3/index.json, IsRetry: False, IsNonInteractive: True, CanShowDialog: True
[CredentialProvider]URI: https://buildcanary.pkgs.visualstudio.com/_packaging/DuplicateFeed1/nuget/v3/index.json
[CredentialProvider]VstsBuildTaskServiceEndpointCredentialProvider - This credential provider must be run under the Team Build tasks for NuGet with external endpoint credentials. Appropriate environment variable needs to be set.
[CredentialProvider]Skipping NuGetCredentialProvider.CredentialProviders.VstsBuildTaskServiceEndpoint.VstsBuildTaskServiceEndpointCredentialProvider, cannot provide credentials for https://buildcanary.pkgs.visualstudio.com/_packaging/DuplicateFeed1/nuget/v3/index.json
[CredentialProvider]VstsBuildTaskCredentialProvider - IsRetry: False
[CredentialProvider]VstsBuildTaskCredentialProvider - URI Prefixes:
[CredentialProvider]VstsBuildTaskCredentialProvider - https://buildcanary.visualstudio.com/
[CredentialProvider]VstsBuildTaskCredentialProvider - https://buildcanary.pkgs.visualstudio.com/
[CredentialProvider]VstsBuildTaskCredentialProvider - https://pkgsprodwcus0.pkgs.visualstudio.com/
[CredentialProvider]VstsBuildTaskCredentialProvider - https://buildcanary.pkgs.visualstudio.com/
[CredentialProvider]VstsBuildTaskCredentialProvider - https://buildcanary.pkgs.visualstudio.com/
[CredentialProvider]VstsBuildTaskCredentialProvider - https://pkgs.dev.azure.com/buildcanary/
[CredentialProvider]VstsBuildTaskCredentialProvider - Matched prefix: https://buildcanary.pkgs.visualstudio.com/
[CredentialProvider]VstsBuildTaskCredentialProvider - Found credentials for endpoint https://buildcanary.pkgs.visualstudio.com/_packaging/DuplicateFeed1/nuget/v3/index.json
[CredentialProvider]Sending response: 'Request' 'GetAuthenticationCredentials'
OK https://buildcanary.pkgs.visualstudio.com/_packaging/8495cefb-0629-456b-beca-45236d56a0a4/nuget/v3/flat2/newtonsoft.json/index.json 141ms
OK https://buildcanary.pkgs.visualstudio.com/_packaging/8495cefb-0629-456b-beca-45236d56a0a4/nuget/v3/flat2/microsoft.dynamics.retail.build.product.msbuild/index.json 173ms
OK https://buildcanary.pkgs.visualstudio.com/_packaging/bcdd2a48-8b72-4e1d-8c66-7731e6aa1736/nuget/v3/flat2/newtonsoft.json/index.json 193ms
OK https://buildcanary.pkgs.visualstudio.com/_packaging/bcdd2a48-8b72-4e1d-8c66-7731e6aa1736/nuget/v3/flat2/microsoft.dynamics.retail.build.product.msbuild/index.json 226ms
GET https://buildcanary.pkgs.visualstudio.com/_packaging/8495cefb-0629-456b-beca-45236d56a0a4/nuget/v3/flat2/newtonsoft.json/11.0.1/newtonsoft.json.11.0.1.nupkg
OK https://buildcanary.pkgs.visualstudio.com/_packaging/8495cefb-0629-456b-beca-45236d56a0a4/nuget/v3/flat2/newtonsoft.json/11.0.1/newtonsoft.json.11.0.1.nupkg 475ms
System.Threading.Tasks.TaskCanceledException: A task was canceled.

[satbai]

There is a workaround available.

• Either use NuGet version lower than 4.8 (e.g. 4.7)
• Or, force-enable the old cred provider with two build variables:
  NuGet.ForceEnableCredentialProvider: true and NuGet_ForceEnableCredentialProviderV2: false (lower case true and false)

[satbai]

@nkolev92 Could you have a look from the NuGet side please? I just updated the logs above with more verbose logging - it looks like we get the first "task canceled" message right after handling initialize. It doesn't look like the cancellation message comes from the cred provider because I don't see the [CredentialProvider] stamp on it. Here's the Artifacts cred provider plugin request handler code. The interesting part is that this only repros on a hosted agent and not on my dev machine. Let me know if you don't have access to this build definition that has a constant repro.

[nkolev92]

I don't see anything obvious.
We need to dig in more from NuGet side. //cc @rrelyea @dtivel as he has more context.

@satbai Can you try the same thing with dotnet.exe?

As far as I remember the hosted machines have fewer resources so that's a possible culprit.

We can potentially try increasing the request time out and see whether the same thing happens.

[satbai]

I'll see if I can get a repro with dotnet.exe. Yes that's probably right since the hosted machines are always "Running restore with 2 concurrent jobs." as you can see from the logs and when running on my dev machine it does it with 16 and succeeds. Is there an environment variable to increase the request timeout?

[nkolev92]

You can find the constant names here:

https://github.com/NuGet/NuGet.Client/blob/dev/src/NuGet.Core/NuGet.Protocol/Plugins/ConnectionOptions.cs#L16-L17

I think the request timeout right now is 5s (which should be plenty but let's see)

[nathansoz]

@satbai I also recently hit this issue. Repros almost 100% on our pipeline. I was able to use the old credential provider as a workaround but feel free to reach out if you want to use my pipeline for diagnostics.

[satbai]

Thanks @nathansoz, the fix is now available in the newest cred provider release. We're working on updating the NuGetCommandV2 task to use the fixed cred provider as well. I'll update here when the fix is available so you can test it.

[satbai]

This is fixed and deployed to all deployment rings except for one. Closing since the fix should be deployed soon everywhere.

[rrelyea]

Much rejoicing. Thanks all!

[laurynasr]

I'm still getting this in around 3 out of 4 builds when using Cake DotNetCoreRestore task.

C:\hostedtoolcache\windows\dncs\2.2.300\x64\sdk\2.2.300\NuGet.targets(121,5): error : Problem starting the plugin 'C:\Users\VssAdministrator\.nuget\plugins\netcore\CredentialProvider.Microsoft\CredentialProvider.Microsoft.dll'. A task was canceled. 
C:\hostedtoolcache\windows\dncs\2.2.300\x64\sdk\2.2.300\NuGet.targets(121,5): error : Problem starting the plugin 'C:\Users\VssAdministrator\.nuget\plugins\netcore\CredentialProvider.Microsoft\CredentialProvider.Microsoft.dll'. A task was canceled. 

Using Hosted Windows 2019 with VS2019 agent

[dtivel]

See if this is relevant:

microsoft/artifacts-credprovider#112
dotnet/arcade#3320

[laurynasr]

The latest version 0.1.18 of credprovider was used in the build that had those timeouts

Downloading https://github.com/microsoft/artifacts-credprovider/releases/download/0.1.18/Microsoft.NuGet.CredentialProvider.zip to C:\Users\VssAdministrator\AppData\Local\Temp\CredProviderZip\Microsoft.NuGet.CredentialProvider.zip
Extracting zip to the Credential Provider temp directory
Copying Credential Provider to C:\Users\VssAdministrator\.nuget\plugins
Removing the Credential Provider temp directory C:\Users\VssAdministrator\AppData\Local\Temp\CredProviderZip
Credential Provider installed successfully

[rubberduck203]

I see that the latest version of credprovider, 0.1.19, mentions a fix for this.
Any idea when it will make it into NugetCommand@2 task?

https://github.com/microsoft/artifacts-credprovider/releases/tag/v0.1.19

[candritzky]

Same problem here. dotnet restore fails in ~50 % of the builds, but NuGet restore always succeeds.

I opened a ticket here:
https://developercommunity.visualstudio.com/content/problem/1106610/sporadic-dotnet-restore-authentication-credentialp.html