"A task was canceled" exception with CredentialProvider.Microsoft.exe v0.1.15

[mschofie]

Our AzureDevOps build pipeline continues to see "System.Threading.Tasks.TaskCanceledException: A task was canceled." exceptions during NuGet restore, similar to #77, but we have version 0.1.15 that contains the fix for that issue.

We are using NuGet.exe v4.9.4 on AzureDevOps, installed using the NuGetToolInstaller@0 and performing a Restore using NuGetCommand@2, v2.150.0.

From the build logs, here's the NuGet.exe invocation:

Detected NuGet version 4.9.4.5839 / 4.9.4+ed6e2dca9391d13b431f4eff58c5194f0ebcee13
SYSTEMVSSCONNECTION exists true
[command]C:\BA\_tool\NuGet\4.9.4\x64\nuget.exe restore "C:\BA\8139\s\SpatialServices\SpatialServices API - Windows.sln" -Verbosity Detailed -NonInteractive -ConfigFile C:\BA\8139\s\SpatialServices\nuget.config
NuGet Version: 4.9.4.5839
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.

Here's the output from the CredentialProvider.Microsoft.exe showing version information:

Using C:\BA\_tasks\NuGetCommand_333b11bd-d341-40d9-afcf-b32d5ce6f23b\2.150.0\CredentialProviderV2\plugins\netfx\CredentialProvider.Microsoft\CredentialProvider.Microsoft.exe as a credential provider plugin.
    [CredentialProvider.175929]Time elapsed in milliseconds after sending response 'Request' 'GetOperationClaims': 28
    [CredentialProvider.175929]Running in plug-in mode
    [CredentialProvider.175929]Handling 'Request' 'Initialize'. Time elapsed in ms: 7 - Payload: {"ClientVersion":"4.9.4","Culture":"en-US","RequestTimeout":"00:00:05"}
    [CredentialProvider.175929]Time elapsed in milliseconds after sending response 'Request' 'Initialize': 10
    [CredentialProvider.175929]Sending response: 'Request' 'Initialize'. Time elapsed in ms: 9
    [CredentialProvider.175929]Command-line v0.1.15: "C:\BA\_tasks\NuGetCommand_333b11bd-d341-40d9-afcf-b32d5ce6f23b\2.150.0\CredentialProviderV2\plugins\netfx\CredentialProvider.Microsoft\CredentialProvider.Microsoft.exe" -Plugin
    [CredentialProvider.175929]Handling 'Request' 'GetOperationClaims'. Time elapsed in ms: 1 - Payload: {}
    [CredentialProvider.175929]Sending response: 'Request' 'GetOperationClaims'. Time elapsed in ms: 12
    [CredentialProvider.175929]Handling 'Request' 'SetLogLevel'. Time elapsed in ms: 1 - Payload: {"LogLevel":"Debug"}
    [CredentialProvider]Sending response: 'Request' 'SetLogLevel'. Time elapsed in ms: 3
    [CredentialProvider]Time elapsed in milliseconds after sending response 'Request' 'SetLogLevel': 6

And the unhandled exception that fails builds:

Unhandled Exception: System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NuGet.Protocol.Plugins.MessageDispatcher.<DispatchWithNewContextAsync>d__26`2.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NuGet.Protocol.Plugins.SymmetricHandshake.<HandshakeAsync>d__14.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NuGet.Protocol.Plugins.Connection.<ConnectAsync>d__25.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NuGet.Protocol.Plugins.PluginFactory.<CreateFromCurrentProcessAsync>d__7.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NuGetCredentialProvider.Program.<Main>d__11.MoveNext() in E:\A\_work\616\s\CredentialProvider.Microsoft\Program.cs:line 133
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NuGetCredentialProvider.Program.<Main>(String[] args)

[satbai]

Thank you for reporting. Does this happen intermittently, and if so, what's the failure rate? In your pipeline, are you using a hosted or private agent? Seeing the whole log, including everything that both the NuGet build task and the cred provider writes, might help investigation.

[mschofie]

It is intermittent. We had a 12 hour window when 4 of 7 CI builds failed with this issue. But we haven't hit it in the past ~24 hours. We are using private agents.

I took a look at the 4 recent instances, and 2 of them don't appear to have anything untoward in the logs, beyond what I already shared. The other 2, however, do have logs that suggest that spurious 401's were returned by the package source (all package sources that we're pulling from are Azure Artifact Feeds). I've attached those logs:

InterestingLog1.txt
InterestingLog2.txt

[satbai]

Thanks for the logs. I can see "Object reference not set to an instance of an object." in the logs, which is certainly interesting. Could you add a build variable system.debug = true in your pipeline and make sure the task has Verbosity set to detailed? After those settings the following logs should have more details. We need to determine whether this error is thrown by the cred provider or NuGet and hopefully the more verbose logs will help.

FYI @dtivel

[satbai]

I haven't been able to get a repro so I have a few more questions. When is the first time you started seeing this error? How many feeds do you have in your nuget.config? Are they all feeds from Azure DevOps Artifacts? Do you have a lot of packages you're restoring?

[cannehag]

We have this problem at the moment also.

We are using NuGet.exe v4.9.3 on AzureDevOps, installed using the NuGetToolInstaller@0 and restore performing through "dotnet build" (dotnet 2.2.105).

This was intermittent for us for a while, but now we have a pipeline that we never get to pass because of this error.
C:\Program Files\dotnet\sdk\2.2.105\NuGet.targets(114,5): error : Unable to load the service index for source https://pkgs.dev.azure.com/[org]/_packaging/[name]/nuget/v3/index.json. [D:\a\1\s\src[project][project].csproj]
C:\Program Files\dotnet\sdk\2.2.105\NuGet.targets(114,5): error : A task was canceled. [D:\a\1\s\src[project][project].csproj]

[jeffkl]

Possibly related to NuGet/Home#8198

[satbai]

According to the discussion in the related NuGet issue, the new version 5.1 should have some logging fixes that might help investigating this issue. Please try updating the NuGet version and see if the logs are more interesting.

[mschofie]

Sorry for the delay in replying. I'll switch to NuGet 5.1 and keep an eye on things. Here's the details that satbai asked for back in May:

When is the first time you started seeing this error?
We'd seen it occasionally before (maybe a couple of times per week?), but a tight cluster of hits that took out half the builds in an afternoon (as I commented before) resulted in this issue.

How many feeds do you have in your nuget.config? Are they all feeds from Azure DevOps Artifacts?
At the time we had 7 feeds in nuget.config. All of them were from AzureDevOps. One of them Upstreamed nuget.org (which is how we 'proxy' nuget.org). To try and help with this incident I moved three of the feeds to be Upstreamed by the upstream feed we already had, leaving us with 4 feeds in Nuget.config.

Do you have a lot of packages you're restoring?
We restore ~140 packages.

[cannehag]

I have narrowed it down to that this occurs when using "dotnet restore". If I do "nuget.exe restore" it works all the time.

[Mys73rion]

I have narrowed it down to that this occurs when using "dotnet restore". If I do "nuget.exe restore" it works all the time.

Thanks a lot.
We had the same issue, and with your hint, using "nuget.exe restore", it works like a charm.

[AMoghrabi]

Hey team. I'm receiving a similar error when restoring on TeamCity:

[09:21:03][Execute nuget:restore]   https://pkgs.dev.azure.com/{company}/_packaging/{feed}/nuget/v3/index.json: Unable to load the service index for source https://pkgs.dev.azure.com/{company}/_packaging/{feed}/nuget/v3/index.json.
[09:21:03][Execute nuget:restore]   A task was canceled.

This is unfortunate because when I was testing Azure Artifacts everything worked fine. This also appears to be intermittent for us. I've moved 50,000 packages from our hosted server to Azure Artifacts and was hoping I can get this running today.

Can anyone advise what to do? We're using nuget.exe.

Edit: This may just be an authentication issue. Currently investigating.

Edit2: The error message is a bit misleading. I had to restart our build agents to pick up the environment variables. Thanks!

[satbai]

When reading the discussion related to the NuGet issue jeffkl mentioned earlier, it sounds like for those who see this error with nuget.exe, there might be a fix for this in the next version of NuGet that's coming up (version 5.2?).

[djee-ms]

We have a similar issue on Azure hosted agents (Hosted VS 2017). Unlike @cannehag, in our case nuget restore fails with the same error (and we cannot use dotnet restore). With 5.1.0 the following error is reported:

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.

Tried with NuGet 4.9.1 and 4.9.2 following NuGet/Home#7699, and also 5.1.0, all installedusing the NuGetToolInstaller task, but they all fail. Very occasionally one of the 6 failing jobs succeeds to restore, randomly, then fails again on next CI run. The other 4 jobs almost always succeed. All 10 jobs are running in parallel on different agents, and restoring one single prerelease package each from the same owner on nuget.org with no other source configured. This was working fine until yesterday 30th July although we had only 2 jobs instead of 10, although the issues started to manifest today 31st July even before I increased the number of jobs.

[satbai]

Hi @djee-ms
If the only package source is nuget.org, the credential provider shouldn't be launched. Could you try with NuGet 5.2? It looks like it's now available for download.

[melcloud]

No, 5.2 doesn't work. It failed consistently for one of my pipelines. But others with same build template works fine. I have to use the fix in another github issue by adding two build variables:
NuGet.ForceEnableCredentialProvider: true and NuGet_ForceEnableCredentialProviderV2: false (lower case true and false)

Looks like v2 has some weird authentication errors. as the status code is 401.

It begins to work after I remove NuGet tool installer task, this means NuGet is back to the default version of 4.1.0

[djee-ms]

NuGet 5.2.0 works for me, tried 2 builds of 10 agents, all passed. And the release notes of 5.2.0 point to many fixes around authentication, including NuGet/Home#8198 which very much look like the current issue. Thanks @satbai.

[satbai]

@djee-ms that's great!

@melcloud the most common reason for a 401 in the pipeline is that one of your PATs in your service connections is expired. Could you please verify that all of them are valid? This cred provider only works with NuGet 4.8 or higher, so version 4.1 will use the old authentication method.

[jotaylo]

The issue is still being investigated with the help of the NuGet client team. In the meantime, clearing the nuget http-cache before running the install, as well as increasing plugin timeout values, seems to help.

nuget locals http-cache -c
$env:NUGET_PLUGIN_HANDSHAKE_TIMEOUT_IN_SECONDS=20
$env:NUGET_PLUGIN_REQUEST_TIMEOUT_IN_SECONDS=20

[Hawxy]

This is still a problem with Nuget 5.3 in Azure pipelines. The restore fails in my project after ~50 seconds with the same error.

[sakowiczm]

Experiencing the same problem on NuGet 5.3:

##[error]The nuget command failed with exit code(1) and error(Problem starting the plugin 
'd:\a\_tasks\NuGetCommand_333b11bd-d341-40d9-afcf-b32d5ce6f23b\2.158.0\CredentialProviderV2\plugins\netfx\CredentialProvider.Microsoft\CredentialProvider.Microsoft.exe'.
Plugin 'CredentialProvider.Microsoft' failed within 0.716 seconds with exit code -1.)
##[error]Packages failed to restore

[igor-teresco]

For me adding -DisableParallelProcessing option to "nuget restore" command resolved this issue with latest nuget and CredProvider.

[dgee2]

If anyone else hits this issue, I've had the same issue with one restore working and another failing in Azure DevOps using NuGet 5.3.1.
I had to add disableParallelProcessing to the restore step

[pspill]

This is an instance of NuGet/Home#8528

[satbai]

According to the discussion in the NuGet issue posted above, NuGet version 5.5.x should have all fixes related to this problem, and it looks like there is a preview version now available. Please update to nuget 5.5.x with the latest cred provider release 0.1.20.

[BrianMouncer]

According to the discussion in the NuGet issue posted above, NuGet version 5.5.x should have all fixes related to this problem, and it looks like there is a preview version now available. Please update to nuget 5.5.x with the latest cred provider release 0.1.20.

We are using nuget 5.8.1 and still hitting this issue with Azure feeds. about 1 in 5 builds will fail because auth and restore fail. Re-run the job, and it passes.

I'm going to try moving our CiCd pipeline to the latest version of nuget available, but I don't have confidence that will fix the reliability issue, since many posts on this thread expects this bug to be fixed before 5.8.1 that we are already using.