Home: dotnet restore failing with TaskCanceledException

[livarcocc]

_From @ColinM9991 on March 1, 2019 13:9_

Steps to reproduce

N/A
This issue is intermittent, however when it happens it then lingers for some time.

Description

We are using the dotnet CLI to restore packages for an ASP.NET Core application targeting .NET Core in our TeamCity build process, and are intermittently having failed builds where the restore task fails as soon as it picks up the first project file

[12:43:57]  Step 1/13: Restore Packages (.NET CLI (dotnet)) (30s)
[12:43:58]  [Step 1/13] dotnet.exe restore Project.sln --disable-parallel
[12:43:58]  [Step 1/13] restore (29s)
[12:43:58]  [restore] Starting: "C:\Program Files\dotnet\dotnet.exe" restore Project.sln --disable-parallel
[12:43:58]  [restore] in directory: C:\buildAgent\work\g0124fa0e71e5f68
[12:44:16]  [restore]   Restoring packages for C:\buildAgent\work\g0124fa0e71e5f68\ProjectA\Common\ProjectB.csproj...
[12:44:28]  [restore] C:\Program Files\dotnet\sdk\2.2.102\NuGet.targets(114,5): error : A task was canceled.
[12:44:28]  [restore] 
[12:44:28]  [restore] Build FAILED.
[12:44:28]  [restore] 
[12:44:28]  [restore]     0 Warning(s)
[12:44:28]  [restore]     1 Error(s)
[12:44:28]  [restore] 
[12:44:28]  [restore] Time Elapsed 00:00:24.84
[12:44:28]  [restore] 
[12:44:28]  [restore] 
[12:44:28]  [restore] C:\Program Files\dotnet\sdk\2.2.102\NuGet.targets(114,5): error : A task was canceled.
[12:44:28]  [restore] Process exited with code 1
[12:44:28]  [Step 1/13] Process exited with code 1
[12:44:28]  [Step 1/13] Step Restore Packages (.NET CLI (dotnet)) failed

Expected behavior

In the scenario where there is an actual error with the codebase then the dotnet CLI should return a meaningful error message as to what the problem is

In the scenario where nothing is wrong and the dotnet CLI fails for no reason, the expected behavior would be for the restore task to complete successfully as it does in other builds of the same codebase at previous times.

Actual behavior

dotnet restore fails with TaskCanceledException and no indication as to what the issue is.

Environment data

dotnet --info output:

[13:07:51]  [Step 2/2] .NET Core SDK (reflecting any global.json):
[13:07:51]  [Step 2/2]  Version:   2.2.102
[13:07:51]  [Step 2/2]  Commit:    96ff75a873
[13:07:51]  [Step 2/2] 
[13:07:51]  [Step 2/2] Runtime Environment:
[13:07:51]  [Step 2/2]  OS Name:     Windows
[13:07:51]  [Step 2/2]  OS Version:  10.0.17763
[13:07:51]  [Step 2/2]  OS Platform: Windows
[13:07:51]  [Step 2/2]  RID:         win10-x64
[13:07:51]  [Step 2/2]  Base Path:   C:\Program Files\dotnet\sdk\2.2.102\
[13:07:51]  [Step 2/2] 
[13:07:51]  [Step 2/2] Host (useful for support):
[13:07:51]  [Step 2/2]   Version: 2.2.1
[13:07:51]  [Step 2/2]   Commit:  878dd11e62
[13:07:51]  [Step 2/2] 
[13:07:51]  [Step 2/2] .NET Core SDKs installed:
[13:07:51]  [Step 2/2]   1.1.12 [C:\Program Files\dotnet\sdk]
[13:07:51]  [Step 2/2]   2.1.202 [C:\Program Files\dotnet\sdk]
[13:07:51]  [Step 2/2]   2.1.504 [C:\Program Files\dotnet\sdk]
[13:07:51]  [Step 2/2]   2.2.102 [C:\Program Files\dotnet\sdk]
[13:07:51]  [Step 2/2] 
[13:07:51]  [Step 2/2] .NET Core runtimes installed:
[13:07:51]  [Step 2/2]   Microsoft.AspNetCore.All 2.1.8 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
[13:07:51]  [Step 2/2]   Microsoft.AspNetCore.All 2.2.1 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
[13:07:51]  [Step 2/2]   Microsoft.AspNetCore.App 2.1.8 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
[13:07:51]  [Step 2/2]   Microsoft.AspNetCore.App 2.2.1 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
[13:07:51]  [Step 2/2]   Microsoft.NETCore.App 1.0.14 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[13:07:51]  [Step 2/2]   Microsoft.NETCore.App 1.1.11 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[13:07:51]  [Step 2/2]   Microsoft.NETCore.App 2.0.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[13:07:51]  [Step 2/2]   Microsoft.NETCore.App 2.1.8 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[13:07:51]  [Step 2/2]   Microsoft.NETCore.App 2.2.1 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]

NuGet.CommandLine version: 4.9.3

_Copied from original issue: dotnet/cli#10905_

[livarcocc]

Moving to NuGet for them to take a first look at it.

[rrelyea]

@dtivel is working on better logging and a fix for this. we plan to fix in 5.0, and likely also ship in 4.9.x

Update: i mistakenly thought that issue was identical to issue 7837 - we are not on path to address this - but would love continued details to help understand when it is happening, etc...

[ColinM9991-zz]

Thank you for that info @rrelyea, it certainly confirms that I am not going insane.

Is there any indication as to what the cause may be, or is it best to wait for the logging improvements to determine the cause?

[loop-evgeny]

We're running into this as well (intermittently) when building in TeamCity on Windows using .NET Core SDK 2.1.504. Is there a known workaround?

[ColinM9991-zz]

@loop-evgeny I updated one of our problematic build processes to first do a NuGet restore directly with NuGet, and then use dotnet restore to generate the project.assets.json files. This seems to have given us a workaround for now and the build hasn't failed for this reason since.

[BackTrak]

Adding the dotnet restore in the teamcity build pipeline fixed this for me as well, thanks for the tip Colin! It's interesting that running dotnet publish directly on the build server without using teamcity works fine, but running the same command under teamcity always fails with this error.

[dtivel]

@ColinM9991, @loop-evgeny, or @BackTrak, can you provide me with a repro?

Are you using a credential provider? If yes, which one? (Azure Artifacts Credential Provider, perhaps?)

How many package sources are you using?

[loop-evgeny]

I can't repro this intentionally, it only happens occasionally when running in TeamCity. We're not using a credentials provider and the only package source is the official NuGet one.

[BackTrak]

I think I found a clue. When TC is running dotnet restore, it is adding a response file on the command it is executing like this:

[restore] Starting: "C:\Program Files\dotnet\dotnet.exe" restore DevApplication.sln --runtime rhel.7.2-x64 @D:\TC\temp\agentTmp\1.rsp

Unfortunately, TC is removing this file before I can grab it and see what's in there.

This command fails with:

[11:18:23][restore] C:\Program Files\dotnetsdk\2.1.504\NuGet.targets(114,5): error : A task was canceled.

However, when I run that same command on the build box without that response file, it runs fine and completes normally:
"C:\Program Files\dotnet\dotnet.exe" restore DevApplication.sln --runtime rhel.7.2-x64

Subsequent builds then seem to work fine on that build box from TC. I then created a build step that uses Command Line and put:
"C:\Program Files\dotnet\dotnet.exe" restore DevApplication.sln --runtime rhel.7.2-x64

into that, and ran it on a build box that had not been working, and that worked as well. Then I noted this output from the build log:

11:24:52] : [Step 4/7]
[11:24:52] : [Step 4/7] Welcome to .NET Core!
[11:24:52] : [Step 4/7] ---------------------
[11:24:52] : [Step 4/7] Learn more about .NET Core: https://aka.ms/dotnet-docs
[11:24:52] : [Step 4/7] Use 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docs
[11:24:52] : [Step 4/7]
[11:24:52] : [Step 4/7] Telemetry
[11:24:52] : [Step 4/7] ---------
[11:24:52] : [Step 4/7] The .NET Core tools collect usage data in order to help us improve your experience. The data is anonymous and doesn't include command-line arguments. The data is collected by Microsoft and shared with the community. You can opt-out of telemetry by setting the DOTNET_CLI_TELEMETRY_OPTOUT environment variable to '1' or 'true' using your favorite shell.
[11:24:52] : [Step 4/7]
[11:24:52] : [Step 4/7] Read more about .NET Core CLI Tools telemetry: https://aka.ms/dotnet-cli-telemetry
[11:24:53] : [Step 4/7]
[11:24:53] : [Step 4/7] ASP.NET Core
[11:24:53] : [Step 4/7] ------------
[11:24:53] : [Step 4/7] Successfully installed the ASP.NET Core HTTPS Development Certificate.
[11:24:53] : [Step 4/7] To trust the certificate run 'dotnet dev-certs https --trust' (Windows and macOS only). For establishing trust on other platforms refer to the platform specific documentation.
[11:24:53] : [Step 4/7] For more information on configuring HTTPS see https://go.microsoft.com/fwlink/?linkid=848054.

So, I think the key is that dotnet is installing that cert on first run, but TC using the response file in the command it is running is disrupting that.

So, the work-around is to run your dotnet restore from a Command Line build step, and not a dotnet install step. For TC build servers that have previously installed dotnet (performing the ASP.NET Core HTTPS Development Certificate installation), you may not need this step at all.

Hope that helps!

Repro steps (this is my best guess... I am out of build server s to test with):

1. Create a brand new TC build server
2. On your dev machine, install AWSSDK for VS2017
3. Create a new WebAPI / Lambda project from the AWS templates (dependant on .net core 2.1)
4. Create a new TC build job with dotnet pubish for the solution file:
   "C:\Program Files\dotnet\dotnet.exe" publish Application.sln --framework netcoreapp2.1 --configuration Release --runtime rhel.7.2-x64

(TeamCity adds @D:\TC\temp\agentTmp\1.rsp on it's own)

1. Attempt to build on the new build server.

The job should fail with the target error.

[ColinM9991-zz]

@BackTrak unless I'm mistaken, the rsp files which TeamCity generates are used to provide output back to you via the build logs from each individual step, they are essentially merged together into one bigger log file.

The certificate installation makes sense, though even with logging set to Detailed I have seen no errors about this on our build agents which are elastic instances in AWS. I will pick one of our build definitions tomorrow and try using a command line build step to invoke dotnet restore with more verbosity.

[rrelyea]

Updated my earlier comment...but also wanted to say this here too:
i mistakenly thought that issue was identical to issue 7837 - we are not on path to address this - but would love continued details to help understand when it is happening, etc...

[ColinM9991-zz]

@dtivel

I have created a .NET Core repository and build definition in TeamCity which runs every on a schedule every 2 hours, once a build has failed for this reason then I will provide the TeamCity build configuration and repository source files in a GitHub repository.

[ColinM9991-zz]

12 days later, I have been unable to reproduce this build issue with a the new repository I created.

All other builds have been resolved also by adding a restore step using NuGet.exe directly first, and then dotnet restore to generate the project.assets.json file for the build.

I'd say that logging and error messages do need some improvement overall to better identify the issue, but this is a blanket statement without being able to provide reproducible steps.

[bklooste]

I have same issue..

2.1 and 2.2 .. It looks like its a net461 project in a solution with other core projects.
Also looks like it relates to the other issues of using a private nuget repository

[loop-evgeny]

We're not using a private NuGet repository and the entire solution is composed of .NET Core 2.0 projects (no .NET Framework). Trying the "dotnet restore" workaround now. This should not be closed - it's a definitely a bug, and an annoying one.

[loop-evgeny]

Even with a separate dotnet restore step it occasionally fails. We have 2 permanently running TeamCity build agents and it hasn't happened on those since adding that workaround. However, we also have an AWS instance that gets created on demand and destroyed again later, which starts out with an empty NuGet cache. When it first started today the first two builds on it failed with this exception (in the dotnet restore step, not in the dotnet build step). The third build succeeded.

[dcopestake]

Not 100% sure if my issue was exactly the same as this or not, but I was experiencing something very similar to this, and after enabling assembly bind failures I managed to work out that the restore MSBuild task from NuGet.Build.Tasks was throwing an exception, resulting in the 'task cancelled' message. I also had absolutely no issue when running the exact same command directly from the build agent machine rather than via the TeamCity .NET CLI build runner. I raised this with JetBrains who have now provided a fix which has resolved the problem for me.

[ColinM9991-zz]

Just to clarify, the workaround isn't just to add a separate dotnet restore step, but to add a NuGet Installer step in TeamCity _BEFORE_ the dotnet restore

[loop-evgeny]

Oh, right! Thanks, @ColinM9991 , I've added it, will see if it helps.

[loop-evgeny]

Just happened again, even with the NuGet Installer step. This was again on a newly created AWS instance, which had an empty NuGet cache.

[Waldo000000]

We're hitting this, too. The workaround (i.e. adding a NuGet Installer step in TeamCity before the dotnet restore) has not seemed to help.

[ColinM9991-zz]

We were hit with this again yesterday despite the workaround which seems to work for me.

I had to specify --no-restore in the build/publish step to not restore any packages as that work had been done by the 2 restore steps.

[bklooste]

That what I did as well ( on services deploying to Azure SF not that it matters )

Nuget installer
(msbuild / solution build not sure if needed ) .
Then --no-restore on the dotnet build .. (no restore step but dirs. need to align as nuget install places it there)

Kind of crap though because they work different , build directories , different from local etc.

.Net core 2.1 & 2.2
TC only .

[ColinM9991-zz]

Another scenario:

We added another build with the following steps

1. NuGet.exe Restore
2. dotnet.exe Restore
3. dotnet.exe Build

This failed on step 2, disabling step 2 and adding --no-restore to step 3 got us past the failing restore, but highlighted an issue where we had to specify the target platform which then succeeded the build.

Seems like C:\Program Files\dotnet\sdk\2.2.102\NuGet.targets(114,5): error : A task was canceled. is swallowing the actual error that occurs at build time in this scenario, though in most other scenarios I've seen the error is completely random.

[Egor92]

I have NuGet restore and dotnet publish after it. So dotnet publish restored packages a second time. But restoring of dotnet publish leads to task canceled exception. Then I wrote parameter --no-restore for dotnet publish step in order to prevent duplicate restoring. Then deploy passed successfully.
Thanx to @ColinM9991

[CraigSelbert]

For those that are having this issue with TeamCity I followed @dcopestake link (which was not my issue, but similar) and found my issue that has a NuGet Plugin that fixed my issues.

[Egor92]

@CraigSelbert, it turned out that NuGet Plugin (dotNetPackagesSupport.zip) from this issue is the real solution in my case. Because I had warning

The specified framework 'Microsoft.NETCore.App', version '1.0.5' was not found

[loop-evgeny]

I tried the plugin attached to https://youtrack.jetbrains.com/issue/TW-59974 but still got the same error. :(

[dtivel]

Echoing @ColinM9991's comment, NuGet should report more context when this error occurs. With a sufficient logging verbosity level, NuGet should report exception callstacks, but I have identified several bugs which prevent callstacks from being logged in NuGet releases that you're using.

I plan on improving error reporting for NuGet 5.1 (https://github.com/NuGet/NuGet.Client/commit/2047ef932f6197947b55180f47ea73cbdcd663b8, https://github.com/NuGet/NuGet.Client/pull/2838).

Then, adding -Verbosity Detailed to NuGet.exe like:

NuGet.exe restore -Verbosity Detailed

...should display callstacks for "A task was canceled." errors.

For dotnet restore adding --verbosity detailed should log exception callstacks.

I'm glad that an updated JetBrains plugin resolved this restore error for some of you.

For those of you who are still encountering this error, can you please confirm whether or not you're using a NuGet plugin? You should be able to determine if plugins are in use by checking if either are true:

• The NUGET_PLUGIN_PATHS environment variable is defined.
• There are folders under %UserProfile%/.nuget/plugins.

See documentation for more information.

Also, does this issue only repro with TeamCity?

[loop-evgeny]

Thanks @dtivel. Yes, I've only seen this happen in TeamCity. We are not using NuGet plugins.

[Peter-Optiway]

Echoing @ColinM9991's comment, NuGet should report more context when this error occurs. With a sufficient logging verbosity level, NuGet should report exception callstacks, but I have identified several bugs which prevent callstacks from being logged in NuGet releases that you're using.

I plan on improving error reporting for NuGet 5.1 (NuGet/NuGet.Client@2047ef9, NuGet/NuGet.Client#2838).

Then, adding -Verbosity Detailed to NuGet.exe like:

NuGet.exe restore -Verbosity Detailed

...should display callstacks for "A task was canceled." errors.

For dotnet restore adding --verbosity detailed should log exception callstacks.

I'm glad that an updated JetBrains plugin resolved this restore error for some of you.

For those of you who are still encountering this error, can you please confirm whether or not you're using a NuGet plugin? You should be able to determine if plugins are in use by checking if either are true:

• The NUGET_PLUGIN_PATHS environment variable is defined.
• There are folders under %UserProfile%/.nuget/plugins.

See documentation for more information.

Also, does this issue only repro with TeamCity?

I just got this error with Verbosity set to Detailed.

dotnet --info:

[10:48:14] :     [Step 4/21] .NET Core SDK (reflecting any global.json):
[10:48:14] :     [Step 4/21]  Version:   2.2.203
[10:48:14] :     [Step 4/21]  Commit:    e5bab63eca
[10:48:14] :     [Step 4/21] 
[10:48:14] :     [Step 4/21] Runtime Environment:
[10:48:14] :     [Step 4/21]  OS Name:     Windows
[10:48:14] :     [Step 4/21]  OS Version:  10.0.14393
[10:48:14] :     [Step 4/21]  OS Platform: Windows
[10:48:15] :     [Step 4/21]  RID:         win10-x64
[10:48:15] :     [Step 4/21]  Base Path:   C:\Program Files\dotnet\sdk\2.2.203\
[10:48:15] :     [Step 4/21] 
[10:48:15] :     [Step 4/21] Host (useful for support):
[10:48:15] :     [Step 4/21]   Version: 2.2.4
[10:48:15] :     [Step 4/21]   Commit:  f95848e524
[10:48:15] :     [Step 4/21] 
[10:48:15] :     [Step 4/21] .NET Core SDKs installed:
[10:48:15] :     [Step 4/21]   1.0.0-preview2-003131 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   1.0.0-preview2.1-003155 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   1.0.1 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   1.0.4 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   1.1.0 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   2.0.0 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   2.0.2 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   2.0.3 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   2.1.4 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   2.1.103 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   2.1.202 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   2.1.300 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   2.1.403 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   2.1.504 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   2.1.505 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   2.2.100 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   2.2.202 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21]   2.2.203 [C:\Program Files\dotnet\sdk]
[10:48:15] :     [Step 4/21] 
[10:48:15] :     [Step 4/21] .NET Core runtimes installed:
[10:48:15] :     [Step 4/21]   Microsoft.AspNetCore.All 2.1.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
[10:48:15] :     [Step 4/21]   Microsoft.AspNetCore.All 2.1.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
[10:48:15] :     [Step 4/21]   Microsoft.AspNetCore.All 2.1.8 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
[10:48:15] :     [Step 4/21]   Microsoft.AspNetCore.All 2.1.9 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
[10:48:15] :     [Step 4/21]   Microsoft.AspNetCore.All 2.2.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
[10:48:15] :     [Step 4/21]   Microsoft.AspNetCore.All 2.2.3 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
[10:48:15] :     [Step 4/21]   Microsoft.AspNetCore.All 2.2.4 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
[10:48:15] :     [Step 4/21]   Microsoft.AspNetCore.App 2.1.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.AspNetCore.App 2.1.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.AspNetCore.App 2.1.8 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.AspNetCore.App 2.1.9 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.AspNetCore.App 2.2.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.AspNetCore.App 2.2.3 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.AspNetCore.App 2.2.4 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 1.0.1 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 1.0.4 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 1.0.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 1.1.0-preview1-001100-00 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 1.1.1 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 1.1.2 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 2.0.0 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 2.0.3 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 2.0.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 2.0.6 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 2.0.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 2.1.0 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 2.1.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 2.1.8 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 2.1.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 2.2.0 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 2.2.3 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
[10:48:15] :     [Step 4/21]   Microsoft.NETCore.App 2.2.4 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]

But the log does not contain a stacktrace.

No environment variable named NUGET_PLUGIN_PATHS seems to exist on the agent.

The log is huge, is there some part of it you want me to post?

[dtivel]

@Peter-Optiway, NuGet 5.1 has not been released yet, so you won't see callstack fixes yet. I'll update this thread when it has been.

The latest release is 5.0.0.

I don't need to see your full log.

Thanks for checking for the NUGET_PLUGIN_PATHS environment variable. There are folders under %UserProfile%/.nuget/plugins? Note that %UserProfile% should be specific to whatever account builds run under.

[Peter-Optiway]

@dtivel how do i check %UserProfile%/.nuget/plugins if i add a script that does dir %UserProfile%\.nuget\plugins i can't run the build as it complains that there is no variable named UserProfile.

Sadly i have no access to the build image so i can't check it.

[ColinM9991-zz]

@dtivel how do i check %UserProfile%/.nuget/plugins if i add a script that does dir %UserProfile%\.nuget\plugins i can't run the build as it complains that there is no variable named UserProfile.

Sadly i have no access to the build image so i can't check it.

If you're using a script which is PowerShell then you can use $env:USERPROFILE to resolve the User Profile path.

[Peter-Optiway]

It seems i have no %UserProfile%/.nuget/plugins folder i get Cannot find path 'C:\Users\Administrator\.nuget\plugins' because it does not exist..

[ColinM9991-zz]

@Peter-Optiway

What about C:\Windows\system32\config\systemprofile\.nuget

This is where the user profile data goes if you're running the agent service as the default LOCAL System user.

[Peter-Optiway]

@ColinM9991 that directory does not exists.

[dtivel]

NuGet 5.1 has been released.

If you can still repro this issue, it would be good to update to this version and enable verbose logging. Hopefully, we'll get a useful callstack.

For dotnet restore add --verbosity detailed. For NuGet.exe restore add -Verbosity detailed.

[ColinM9991-zz]

@dtivel

I have a log file from a failed build using the --verbosity detailed switch, where can I send it to you guys?

[dtivel]

@ColinM9991, please send it to my username at microsoft.com.

[ColinM9991-zz]

@dtivel I've emailed you the log file

Another build has flagged the following error with some context along with it.

C:\Program Files\dotnet\sdk\2.2.300\NuGet.targets(121,5): error : Problem starting the plugin 'C:\buildAgent\plugins\nuget-agent\bin\credential-plugin\netcoreapp2.0\CredentialProvider.TeamCity.dll'. A task was canceled.

[loop-evgeny]

Is there any progress on fixing this? Every time our TeamCity server starts a new VM the first build on that VM fails and has to be manually re-run and it's really annoying!

[NinjaCross]

Same problem here
C:\Program Files\dotnetsdk\2.2.300\NuGet.targets(121,5): error : Problem starting the plugin 'C:\TeamCity\buildAgent\plugins\nuget-agent\bin\credential-plugin\netcoreapp2.0\CredentialProvider.TeamCity.dll'.

[dtivel]

@loop-evgeny, I don't have enough information yet to diagnose your issue. Can you update your NuGet.exe/dotnet.exe version and enable verbose logging? That might provide more context.

@NinjaCross, your error suggests that the problem is with the CredentialProvider.TeamCity authentication plugin.

The error you're seeing is raised here and indicates that NuGet started the plugin process, but the process most likely exited early. Reason why this might occur include:

• a plugin crashed. This could be for a variety of reasons including missing dependencies.
• a plugin self-exited
• a plugin wrote to stdin/stdout outside of the NuGet plugin machinery. (The streams are reserved for NuGet-plugin communications.)

I recommend reaching out to JetBrains to help diagnose this further. A quick search yielded this issue. Another resolution was logged earlier in this issue.

You can also try increasing the verbosity level of a restore operation to see if more useful information is logged.

I added opt-in diagnostic plugin logging in NuGet 5.1. Details of how to enable it are here. Ideally, the plugin (CredentialProvider.TeamCity) would also update to NuGet 5.1+ to enable diagnostic logging on the plugin side.

[loop-evgeny]

Updated to NuGet 5.1.0 in TeamCity and now the problem no longer happens if I run a separate NuGet Installer task as suggested by ColinM9991. The dotnet restore after it seems unnecessary. So this is certainly an improvement - the first build on a new VM takes longer, but it succeeds.

If I disable the NuGet Installer step I still get the TaskCancelledException during dotnet build. I tried enabling verbose logging on the dotnet build step but that doesn't log a stack trace for the exception - possibly because that's not using the new NuGet version, but the one that came with the .NET Core SDK. It just logs this:

[15:21:01] : [Target "Restore"] [34m Restoring packages for .NETCoreApp,Version=v2.0... [15:21:01] : [Target "Restore"] [34m Restoring packages for .NETCoreApp,Version=v2.1... [15:21:14]E: [Target "Restore"] 1>C:\Program Files\dotnet\sdk\2.2.107\NuGet.targets(114,5): error : A task was canceled. [15:21:14] : [Target "Restore"] [34m System.Threading.Tasks.TaskCanceledException: A task was canceled.

(I enabled verbose logging on the NuGet Installer step, but since that now succeeds there is probably nothing interesting there.)

[dtivel]

@loop-evgeny, we release NuGet client updates through several channels:

• Visual Studio
• NuGet.exe standalone CLI
• .NET Core SDK

The NuGet 5.1 release was delivered in each of these channels. For the 5.1.x NuGet.exe release, you simply need to download it from here. For the .NET Core SDK, you need to install the appropriate release. The NuGet 5.1 release notes I previously shared indicates that the following .NET Core SDK releases include NuGet 5.1:

• 2.1.70X
• 2.2.30X

I see from your error message that you're using .NET Core SDK 2.2.107, which has NuGet 4.9.4 not 5.1. This explains why you're not seeing the improved logging with "dotnet build". You will need to update to either of the above .NET Core SDK releases to get NuGet 5.1.

I don't know why you would see this "A task was canceled" error on 4.9.4 but not 5.1; I don't recall any fixes between those two releases around that error.

[NinjaCross]

@NinjaCross, your error suggests that the problem is with the CredentialProvider.TeamCity authentication plugin.

Indeed, the source of the problem seems to be that.
Anyway, I solved using the workaround suggested by @ColinM9991 here https://github.com/NuGet/Home/issues/7842#issuecomment-470114679

[loop-evgeny]

OK, yes, I upgraded the SDK and now get the exception stack trace from dotnet build -verbosity detailed:

[11:19:07] :                 [Target "Restore"]  [34m         Restoring packages for .NETCoreApp,Version=v2.0...
[11:19:07] :                 [Target "Restore"]  [34m         Restoring packages for .NETCoreApp,Version=v2.1...
[11:19:14]E:                 [Target "Restore"]      1>C:\Program Files\dotnet\sdk\2.2.300\NuGet.targets(121,5): error : Problem starting the plugin 'C:\BuildAgent\plugins\nuget-agent\bin\credential-plugin\netcoreapp2.0\CredentialProvider.TeamCity.dll'. A task was canceled.
[11:19:15] :                 [Target "Restore"]  [34m         NuGet.Protocol.Plugins.PluginException: Problem starting the plugin 'C:\BuildAgent\plugins\nuget-agent\bin\credential-plugin\netcoreapp2.0\CredentialProvider.TeamCity.dll'. A task was canceled.
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Protocol.Core.Types.PluginResource.GetPluginAsync(OperationClaim requiredClaim, CancellationToken cancellationToken)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Protocol.PluginFindPackageByIdResourceProvider.TryCreate(SourceRepository source, CancellationToken cancellationToken)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Protocol.Core.Types.SourceRepository.GetResourceAsync[T](CancellationToken token)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Protocol.Core.Types.SourceRepository.GetResourceAsync[T]()
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Commands.SourceRepositoryDependencyProvider.EnsureResource()
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Commands.SourceRepositoryDependencyProvider.FindLibraryCoreAsync(LibraryRange libraryRange, SourceCacheContext cacheContext, ILogger logger, CancellationToken cancellationToken)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Commands.SourceRepositoryDependencyProvider.<>c__DisplayClass19_0.<<FindLibraryAsync>b__0>d.MoveNext()
[11:19:15] :                 [Target "Restore"]  [34m         --- End of stack trace from previous location where exception was thrown ---
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Commands.SourceRepositoryDependencyProvider.FindLibraryAsync(LibraryRange libraryRange, NuGetFramework targetFramework, SourceCacheContext cacheContext, ILogger logger, CancellationToken cancellationToken)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.DependencyResolver.ResolverUtility.<>c__DisplayClass9_1.<<FindLibraryFromSourcesAsync>b__0>d.MoveNext()
[11:19:15] :                 [Target "Restore"]  [34m         --- End of stack trace from previous location where exception was thrown ---
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.DependencyResolver.ResolverUtility.FindLibraryFromSourcesAsync(LibraryRange libraryRange, IEnumerable`1 providers, Func`2 action)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.DependencyResolver.ResolverUtility.FindLibraryByVersionAsync(LibraryRange libraryRange, NuGetFramework framework, IEnumerable`1 providers, SourceCacheContext cacheContext, ILogger logger, CancellationToken token)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.DependencyResolver.ResolverUtility.FindPackageLibraryMatchAsync(LibraryRange libraryRange, NuGetFramework framework, IEnumerable`1 remoteProviders, IEnumerable`1 localProviders, SourceCacheContext cacheContext, ILogger logger, CancellationToken cancellationToken)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.DependencyResolver.ResolverUtility.FindLibraryMatchAsync(LibraryRange libraryRange, NuGetFramework framework, String runtimeIdentifier, IEnumerable`1 remoteProviders, IEnumerable`1 localProviders, IEnumerable`1 projectProviders, IDictionary`2 lockFileLibraries, SourceCacheContext cacheContext, ILogger logger, CancellationToken cancellationToken)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.DependencyResolver.ResolverUtility.FindLibraryEntryAsync(LibraryRange libraryRange, NuGetFramework framework, String runtimeIdentifier, RemoteWalkContext context, CancellationToken cancellationToken)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.DependencyResolver.RemoteDependencyWalker.CreateGraphNode(LibraryRange libraryRange, NuGetFramework framework, String runtimeName, RuntimeGraph runtimeGraph, Func`2 predicate, GraphEdge`1 outerEdge)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.DependencyResolver.RemoteDependencyWalker.CreateGraphNode(LibraryRange libraryRange, NuGetFramework framework, String runtimeName, RuntimeGraph runtimeGraph, Func`2 predicate, GraphEdge`1 outerEdge)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Commands.ProjectRestoreCommand.WalkDependenciesAsync(LibraryRange projectRange, NuGetFramework framework, String runtimeIdentifier, RuntimeGraph runtimeGraph, RemoteDependencyWalker walker, RemoteWalkContext context, CancellationToken token)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Commands.ProjectRestoreCommand.TryRestoreAsync(LibraryRange projectRange, IEnumerable`1 frameworkRuntimePairs, NuGetv3LocalRepository userPackageFolder, IReadOnlyList`1 fallbackPackageFolders, RemoteDependencyWalker remoteWalker, RemoteWalkContext context, Boolean forceRuntimeGraphCreation, CancellationToken token, TelemetryActivity telemetryActivity)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Commands.RestoreCommand.ExecuteRestoreAsync(NuGetv3LocalRepository userPackageFolder, IReadOnlyList`1 fallbackPackageFolders, RemoteWalkContext context, CancellationToken token, TelemetryActivity telemetryActivity)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Commands.RestoreCommand.ExecuteAsync(CancellationToken token)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Commands.RestoreRunner.ExecuteAsync(RestoreSummaryRequest summaryRequest, CancellationToken token)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Commands.RestoreRunner.ExecuteAndCommitAsync(RestoreSummaryRequest summaryRequest, CancellationToken token)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Commands.RestoreRunner.CompleteTaskAsync(List`1 restoreTasks)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Commands.RestoreRunner.RunAsync(IEnumerable`1 restoreRequests, RestoreArgs restoreContext, CancellationToken token)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Commands.RestoreRunner.RunAsync(RestoreArgs restoreContext, CancellationToken token)
[11:19:15] :                 [Target "Restore"]  [34m            at NuGet.Build.Tasks.RestoreTask.ExecuteAsync(ILogger log)
[11:19:15] :                 [Target "Restore"]  [36m       Done executing task "RestoreTask" -- FAILED.

[loop-evgeny]

However, with the new SDKs installed, if I enable the NuGet Installer step on a different project that multi-targets .NET Core 2.0 and 2.1 (<TargetFrameworks>netcoreapp2.0;netcoreapp2.1</TargetFrameworks>) that step fails:

[13:13:01][Step 4/16] scan: Searching for nuget.config files
[13:13:01][Step 4/16] restore: Restoring NuGet packages for MySolution.sln (25s)
[13:13:01][restore] Starting: C:\BuildAgent\tools\NuGet.CommandLine.5.1.0\tools\NuGet.exe restore C:\BuildAgent\work\fb9ae0409f91bac8\MySolution.sln
[13:13:01][restore] in directory: C:\BuildAgent\work\fb9ae0409f91bac8\mydir
[13:13:11][restore] MSBuild auto-detection: using msbuild version '15.9.21.664' from 'C:\Program Files (x86)\Microsoft Visual Studio\2017\BuildTools\MSBuild\15.0\bin'.
[13:13:26][restore] C:\Program Files\dotnet\sdk\2.1.202\Sdks\Microsoft.NET.Sdk\build\Microsoft.NET.TargetFrameworkInference.targets(135,5): error : The current .NET SDK does not support targeting .NET Core 2.1.  Either target .NET Core 2.0 or lower, or use a version of the .NET SDK that supports .NET Core 2.1. [C:\BuildAgent\work\fb9ae0409f91bac8\...\MyProject.csproj]
[13:13:26][restore] Process exited with code 1

dotnet --info output:

.NET Core SDK (reflecting any global.json):
 Version:   2.2.300
 Commit:    73efd5bd87

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

Host (useful for support):
  Version: 2.2.5
  Commit:  0a3c9209c0

.NET Core SDKs installed:
  2.1.202 [C:\Program Files\dotnet\sdk]
  2.1.700 [C:\Program Files\dotnet\sdk]
  2.2.300 [C:\Program Files\dotnet\sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.1.11 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.2.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.11 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.2.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.0.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.11 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.2.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]

To install additional .NET Core runtimes or SDKs:
  https://aka.ms/dotnet-download

This did not happen before the SDK upgrade.

[loop-evgeny]

I still occasionally get this now, even with the workaround, but I suspect that's a TeamCity issue, so I opened a JetBrains ticket for it: https://youtrack.jetbrains.com/issue/TW-61370

[nkolev92]

There's an active investigation on this topic.

With 5.2 and 5.3 of NuGet, and 2.2.400 and 3.0-preview9 of the SDK the current status are intermittent task cancellation exceptions.

The workaround until further notice is to set the following environment variables.
Currently they both default to 5.

$env:NUGET_PLUGIN_HANDSHAKE_TIMEOUT_IN_SECONDS=20
$env:NUGET_PLUGIN_REQUEST_TIMEOUT_IN_SECONDS=20
Additionally if you're still hitting this, potentially clearing the http-cache should help.

[rrelyea]

5.3.1 has 2 fixes.
5.4 has additional two fixes.
And @nkolev92 is continuuing to investigate one more related problem now.

[rrelyea]

Dupe and close...now that you've fixed the last issue in 5.5, right?

[nkolev92]

Duplicate of https://github.com/NuGet/Home/issues/8528.

Copying the mega summary:

We have 5 fixes on the NuGet side so far, 5.3.x – 3.0.100, 5.4.x – 3.1.100, 5.5.x -3.1.200

We have 2 fixes on the plugin side in 0.19 and 0.20 versions

• NuGet internally cancelling prematurely. (5.3.1) https://github.com/NuGet/Home/issues/8648
• Logging failures triggering plugin shut down. (5.3.1) https://github.com/NuGet/Home/issues/8688
• Propagated exception at dispose time fails the whole auth with a task cancellation error. (5.4) https://github.com/NuGet/Home/issues/8732
• Plugin logging accuracy improvement (5.4) https://github.com/NuGet/Home/issues/8747
• Threadpool starvation issues (5.5) https://github.com/NuGet/Home/issues/8528

Plugin side:

• Unhandled exception crashes the restore operation (0.19.0) - https://github.com/microsoft/artifacts-credprovider/issues/108
• Change exit timeout to start ticking on a shutdown request, not at startup(0.20.0) https://github.com/microsoft/artifacts-credprovider/issues/143