Cache is slow

[apobekiaris]

Note

Issues in this repo are for tracking bugs, feature requests and questions for the tasks in this repo

For a list:
https://github.com/Microsoft/azure-pipelines-tasks/tree/master/Tasks

If you have an issue or request for the Azure Pipelines service, use developer community instead:

https://developercommunity.visualstudio.com/spaces/21/index.html )

Required Information

Entering this information will route you directly to the right team and expedite traction.

Question, Bug, or Feature?
Type: Question

Enter Task Name: CacheBeta

list here (V# not needed):
https://github.com/Microsoft/azure-pipelines-tasks/tree/master/Tasks

Environment

• Server - Azure Pipelines or TFS on-premises?

  • If using TFS on-premises, provide the version:

  • If using Azure Pipelines, provide the account name, team project name, build definition name/build number: https://dev.azure.com/eXpandDevOps/eXpandFramework/_build/results?buildId=5782

• Agent - Hosted or Private:

  • If using Hosted agent, provide agent queue name:

  • If using private agent, provide the OS of the machine running the agent and the agent version:

Issue Description

It takes as u can see in the posted linked 1.16m to complete the task of restoring 2.3G cache logs_5783.zip

[johnterickson]

Hi! 2.3GB in 76 seconds is ~250Mbps. What speed are you expecting?

[apobekiaris]

Hi

Your point is valid however in each of my Azure builds the 20% of the time is spent in restoring the same nugets and although caching it helped (before it was around 50%) I would be much more productive if that 20% interval does not exist and my build time in azure matches my local times where I do not re-download the universe constantly.

[Barsonax]

Hi! 2.3GB in 76 seconds is ~250Mbps. What speed are you expecting?

As its all within Azure I would actually expect atleast 1 gbit here.

[estensen]

I'm currently experiencing ~168 Mbps~ Actually ~52 Mbps because of compression ~68 Mbps on another project

[JohnFromPrague]

Hi, we are having trouble with speed as well. Most of the times +/- 1600MB takes around 45s, but sometimes we are getting lot of timeouts and download can take up to 2 minutes (I hope you can access our log).

Are timeouts expected for large file or is that a bug? In case it's bug, should I report a new bug?

EDIT: Today I had to disable Cache task, because it took 18,5m and it was only in 60% (size still +/- 1600MB). You can see log here: https://ecos-group.visualstudio.com/d25793c7-0c98-4ed9-af08-8f1746b505f7/_apis/build/builds/2753/logs/7

[estensen]

Because the cache task is too slow we tried creating a Docker builder image that contains all the dependencies and build with that. We have the same network issues there. Reading metadata before starting to download any files took in one case 35 seconds and download speed is comparable to the cache task (but it's obviously downloading more data). By increasing the complexity of the pipeline we get about the same or +1 min time as just downloading packages straight from Nuget.

[mfahlen]

I am also observing slow download times and multiple timeouts. Here is an example which took 4m 30s:

2020-02-27T07:37:27.6055189Z ##[section]Starting: Cache Yarn packages
2020-02-27T07:37:27.6212641Z ==============================================================================
2020-02-27T07:37:27.6213119Z Task         : Cache
2020-02-27T07:37:27.6213377Z Description  : Cache files between runs
2020-02-27T07:37:27.6213622Z Version      : 2.0.0
2020-02-27T07:37:27.6213871Z Author       : Microsoft Corporation
2020-02-27T07:37:27.6214192Z Help         : https://aka.ms/pipeline-caching-docs
2020-02-27T07:37:27.6214574Z ==============================================================================
2020-02-27T07:37:27.9518713Z Resolving key:
2020-02-27T07:37:27.9666404Z  - version2              [string]
2020-02-27T07:37:27.9666797Z  - yarn                  [string]
2020-02-27T07:37:27.9671253Z  - "Windows_NT"          [string]
2020-02-27T07:37:28.0129397Z  - UserManager/yarn.lock [file] --> F92CC46F426D2B10DA9D1D368165D8B1EEEBC75D26C20A34E9D7FF76F2ED9EE0
2020-02-27T07:37:28.0158891Z Resolved to: version2|yarn|"Windows_NT"|yOZvAqMjy5maD7JwG/44nHLGx8fNxoXnA1rVcxL0LVE=
2020-02-27T07:37:28.7409362Z Information, ApplicationInsightsTelemetrySender will correlate events with X-TFS-Session 3bfe4da0-e19b-42ba-814e-25e53df2b02f
2020-02-27T07:37:28.7583397Z Information, Getting a pipeline cache artifact with one of the following fingerprints:
2020-02-27T07:37:28.7584050Z Information, Fingerprint: `version2|yarn|"Windows_NT"|yOZvAqMjy5maD7JwG/44nHLGx8fNxoXnA1rVcxL0LVE=`
2020-02-27T07:37:29.5619256Z Information, There is a cache hit: `version2|yarn|"Windows_NT"|yOZvAqMjy5maD7JwG/44nHLGx8fNxoXnA1rVcxL0LVE=`
2020-02-27T07:37:29.5620036Z Information, Used scope: 173;95f069a2-8c23-4603-8a3d-6856068a0710;refs/heads/master;384f71dd-d2e2-47ef-8ea6-ddc691090be9
2020-02-27T07:37:29.6234262Z Entry found at fingerprint: `version2|yarn|"Windows_NT"|yOZvAqMjy5maD7JwG/44nHLGx8fNxoXnA1rVcxL0LVE=`
2020-02-27T07:37:29.9461556Z Information, ArtifactHttpRetryMessageHandler.SendAsync: https://vsblobprodsu6weu.vsblob.visualstudio.com/Aa995796d-f9b3-45ee-9e80-903f89a7ee5a/_apis/dedup/chunks/2870C74B08AE6212357B56A30162281EA35F778E5E2E16197912D37AC7B70FF501 attempt 1/6 failed with StatusCode RedirectMethod, IsRetryableResponse False
2020-02-27T07:37:30.5167032Z 
2020-02-27T07:37:30.5167726Z 7-Zip 18.05 (x64) : Copyright (c) 1999-2018 Igor Pavlov : 2018-04-30
2020-02-27T07:37:30.5168002Z 
2020-02-27T07:37:30.5168122Z 
2020-02-27T07:37:30.5168298Z Extracting archive: 
2020-02-27T07:37:30.5376842Z Information, ArtifactHttpRetryMessageHandler.SendAsync: https://vsblobprodsu6weu.vsblob.visualstudio.com/Aa995796d-f9b3-45ee-9e80-903f89a7ee5a/_apis/dedup/nodes/04AAC9AE2AA4A943DF4029AC6C41A854A29ED0F654987621ED33AA7C2157B51502 attempt 1/6 failed with StatusCode RedirectMethod, IsRetryableResponse False
2020-02-27T07:37:30.9934677Z Information, Expected size to be downloaded: 687.9 MB
2020-02-27T07:37:30.9954630Z Information, Downloaded 0.0 MB out of 687.9 MB (0%).
2020-02-27T07:37:36.0075163Z Information, Downloaded 31.5 MB out of 687.9 MB (5%).
2020-02-27T07:37:41.0107644Z Information, Downloaded 82.5 MB out of 687.9 MB (12%).
2020-02-27T07:37:46.0105876Z Information, Downloaded 106.2 MB out of 687.9 MB (15%).
2020-02-27T07:37:51.0102466Z Information, Downloaded 125.7 MB out of 687.9 MB (18%).
2020-02-27T07:37:56.0125853Z Information, Downloaded 155.8 MB out of 687.9 MB (23%).
2020-02-27T07:38:01.0136156Z Information, Downloaded 173.2 MB out of 687.9 MB (25%).
2020-02-27T07:38:06.0165262Z Information, Downloaded 192.8 MB out of 687.9 MB (28%).
2020-02-27T07:38:11.0170081Z Information, Downloaded 193.4 MB out of 687.9 MB (28%).
2020-02-27T07:38:16.0173470Z Information, Downloaded 193.4 MB out of 687.9 MB (28%).
2020-02-27T07:38:21.0181970Z Information, Downloaded 193.4 MB out of 687.9 MB (28%).
2020-02-27T07:38:26.0179609Z Information, Downloaded 193.4 MB out of 687.9 MB (28%).
2020-02-27T07:38:31.0182311Z Information, Downloaded 193.4 MB out of 687.9 MB (28%).
2020-02-27T07:38:36.0198797Z Information, Downloaded 193.4 MB out of 687.9 MB (28%).
2020-02-27T07:38:41.0209907Z Information, Downloaded 193.4 MB out of 687.9 MB (28%).
2020-02-27T07:38:46.0220091Z Information, Downloaded 193.4 MB out of 687.9 MB (28%).
2020-02-27T07:38:51.0220718Z Information, Downloaded 193.4 MB out of 687.9 MB (28%).
2020-02-27T07:38:56.0225857Z Information, Downloaded 193.4 MB out of 687.9 MB (28%).
2020-02-27T07:39:01.0228607Z Information, Downloaded 193.4 MB out of 687.9 MB (28%).
2020-02-27T07:39:02.1846709Z Warning, [https://lnxvsblobprodsu6weus44.blob.core.windows.net/dba995796df9b345ee9e80903f89a7ee5a/DD9DFAD2F5E965B040692B1B4B18BF0F87DB49E2CF43D1CE49CCB16CD9B2CCC401?sv=2017-04-17&sr=b&sig=GskXrAa4UtKxuOBqbCTaJyjuUk6hS3R3d9RJlJlZFeE%3D&spr=https&se=2020-02-28T07%3A51%3A54Z&sp=r&rscl=x-e2eid-385bbfcb-641f4809-9527ca04-573f5b14-session-3bfe4da0-e19b42ba-814e25e5-3df2b02f] Try 1/5, non-retryable exception caught. Throwing. Details:
2020-02-27T07:39:02.1848093Z Task was requested to be canceled. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-02-27T07:39:02.1849037Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-02-27T07:39:02.1849908Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-02-27T07:39:02.1850770Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-02-27T07:39:02.1851337Z --- End of stack trace from previous location where exception was thrown ---
2020-02-27T07:39:02.1851870Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-02-27T07:39:02.1860083Z Warning, [https://lnxvsblobprodsu6weus44.blob.core.windows.net/dba995796df9b345ee9e80903f89a7ee5a/DD9DFAD2F5E965B040692B1B4B18BF0F87DB49E2CF43D1CE49CCB16CD9B2CCC401?sv=2017-04-17&sr=b&sig=GskXrAa4UtKxuOBqbCTaJyjuUk6hS3R3d9RJlJlZFeE%3D&spr=https&se=2020-02-28T07%3A51%3A54Z&sp=r&rscl=x-e2eid-385bbfcb-641f4809-9527ca04-573f5b14-session-3bfe4da0-e19b42ba-814e25e5-3df2b02f] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-02-27T07:39:02.1861736Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-02-27T07:39:02.1862636Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-02-27T07:39:02.1864908Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-02-27T07:39:02.1865501Z --- End of stack trace from previous location where exception was thrown ---
2020-02-27T07:39:02.1866049Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-02-27T07:39:02.1866748Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass60_0.<<HandleRedirectAsync>b__0>d.MoveNext()
2020-02-27T07:39:02.1867310Z --- End of stack trace from previous location where exception was thrown ---
2020-02-27T07:39:02.1867866Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-02-27T07:39:06.0230586Z Information, Downloaded 196.8 MB out of 687.9 MB (29%).
2020-02-27T07:39:11.0254795Z Information, Downloaded 212.7 MB out of 687.9 MB (31%).
2020-02-27T07:39:16.0370891Z Information, Downloaded 239.7 MB out of 687.9 MB (35%).
2020-02-27T07:39:21.0474400Z Information, Downloaded 251.3 MB out of 687.9 MB (37%).
2020-02-27T07:39:26.0524315Z Information, Downloaded 259.8 MB out of 687.9 MB (38%).
2020-02-27T07:39:31.0595801Z Information, Downloaded 268.6 MB out of 687.9 MB (39%).
2020-02-27T07:39:36.0610972Z Information, Downloaded 299.0 MB out of 687.9 MB (43%).
2020-02-27T07:39:41.0614714Z Information, Downloaded 326.5 MB out of 687.9 MB (47%).
2020-02-27T07:39:46.0638893Z Information, Downloaded 335.0 MB out of 687.9 MB (49%).
2020-02-27T07:39:51.0687765Z Information, Downloaded 342.8 MB out of 687.9 MB (50%).
2020-02-27T07:39:56.0730505Z Information, Downloaded 350.0 MB out of 687.9 MB (51%).
2020-02-27T07:40:01.0734010Z Information, Downloaded 402.4 MB out of 687.9 MB (58%).
2020-02-27T07:40:06.0757256Z Information, Downloaded 476.2 MB out of 687.9 MB (69%).
2020-02-27T07:40:11.0759894Z Information, Downloaded 508.6 MB out of 687.9 MB (74%).
2020-02-27T07:40:16.0896163Z Information, Downloaded 554.3 MB out of 687.9 MB (81%).
2020-02-27T07:40:21.0999961Z Information, Downloaded 580.2 MB out of 687.9 MB (84%).
2020-02-27T07:40:26.1016666Z Information, Downloaded 603.7 MB out of 687.9 MB (88%).
2020-02-27T07:40:31.1019012Z Information, Downloaded 603.7 MB out of 687.9 MB (88%).
2020-02-27T07:40:36.1149217Z Information, Downloaded 603.7 MB out of 687.9 MB (88%).
2020-02-27T07:40:38.4260955Z Warning, [https://ao9vsblobprodsu6weus14.blob.core.windows.net/dba995796df9b345ee9e80903f89a7ee5a/C1FB9503E40CDFA1DACF1072987171EF67379A4F333270E831292A47C526CE2C01?sv=2017-04-17&sr=b&sig=FYVTU2ZiqrAr9CDoT6PAz2MszcyvpiJPpLo2allkOXQ%3D&spr=https&se=2020-02-28T07%3A45%3A29Z&sp=r&rscl=x-e2eid-518a2079-bd644188-9813fd18-55e9d93a-session-3bfe4da0-e19b42ba-814e25e5-3df2b02f] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Net.Http.HttpRequestException: An error occurred while sending the request.
2020-02-27T07:40:38.4262767Z  ---> System.Net.Http.WinHttpException (80072EFF, 12030): Error 12030 calling WINHTTP_CALLBACK_STATUS_REQUEST_ERROR, 'The connection with the server was terminated abnormally'.
2020-02-27T07:40:38.4263398Z    at System.Threading.Tasks.RendezvousAwaitable`1.GetResult()
2020-02-27T07:40:38.4263832Z    at System.Net.Http.WinHttpHandler.StartRequestAsync(WinHttpRequestState state)
2020-02-27T07:40:38.4264225Z    --- End of inner exception stack trace ---
2020-02-27T07:40:38.4264747Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-02-27T07:40:38.4265645Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-02-27T07:40:38.4266988Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-02-27T07:40:38.4267563Z --- End of stack trace from previous location where exception was thrown ---
2020-02-27T07:40:38.4268091Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-02-27T07:40:41.1152909Z Information, Downloaded 612.8 MB out of 687.9 MB (89%).
2020-02-27T07:40:45.4129977Z Warning, [https://bwlvsblobprodsu6weus62.blob.core.windows.net/dba995796df9b345ee9e80903f89a7ee5a/76076442F1A9FE02ECA8D910ADA896A471DA03BBCBB4F066E9D96193634DA6B201?sv=2017-04-17&sr=b&sig=m5sMJPhUkK31HYCYaVY3P0MSdknaRjAtUEBVW5p4hwE%3D&spr=https&se=2020-02-28T08%3A27%3A38Z&sp=r&rscl=x-e2eid-518a2079-bd644188-9813fd18-55e9d93a-session-3bfe4da0-e19b42ba-814e25e5-3df2b02f] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Net.Http.HttpRequestException: An error occurred while sending the request.
2020-02-27T07:40:45.4131730Z  ---> System.Net.Http.WinHttpException (80072EE2, 12002): Error 12002 calling WINHTTP_CALLBACK_STATUS_REQUEST_ERROR, 'The operation timed out'.
2020-02-27T07:40:45.4132345Z    at System.Threading.Tasks.RendezvousAwaitable`1.GetResult()
2020-02-27T07:40:45.4132760Z    at System.Net.Http.WinHttpHandler.StartRequestAsync(WinHttpRequestState state)
2020-02-27T07:40:45.4133728Z    --- End of inner exception stack trace ---
2020-02-27T07:40:45.4134248Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-02-27T07:40:45.4135111Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-02-27T07:40:45.4135969Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-02-27T07:40:45.4136539Z --- End of stack trace from previous location where exception was thrown ---
2020-02-27T07:40:45.4137077Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-02-27T07:40:46.1162469Z Information, Downloaded 613.1 MB out of 687.9 MB (89%).
2020-02-27T07:40:51.1261048Z Information, Downloaded 633.3 MB out of 687.9 MB (92%).
2020-02-27T07:40:56.1270309Z Information, Downloaded 633.3 MB out of 687.9 MB (92%).
2020-02-27T07:41:01.1272222Z Information, Downloaded 633.3 MB out of 687.9 MB (92%).
2020-02-27T07:41:06.1389059Z Information, Downloaded 633.3 MB out of 687.9 MB (92%).
2020-02-27T07:41:11.1478932Z Information, Downloaded 633.3 MB out of 687.9 MB (92%).
2020-02-27T07:41:16.1488575Z Information, Downloaded 633.3 MB out of 687.9 MB (92%).
2020-02-27T07:41:21.1492103Z Information, Downloaded 633.3 MB out of 687.9 MB (92%).
2020-02-27T07:41:26.1495012Z Information, Downloaded 633.3 MB out of 687.9 MB (92%).
2020-02-27T07:41:31.1498162Z Information, Downloaded 633.3 MB out of 687.9 MB (92%).
2020-02-27T07:41:36.1501815Z Information, Downloaded 633.3 MB out of 687.9 MB (92%).
2020-02-27T07:41:41.1505202Z Information, Downloaded 633.3 MB out of 687.9 MB (92%).
2020-02-27T07:41:46.1510201Z Information, Downloaded 633.3 MB out of 687.9 MB (92%).
2020-02-27T07:41:46.5787518Z Warning, [https://fv1vsblobprodsu6weus82.blob.core.windows.net/dba995796df9b345ee9e80903f89a7ee5a/5440CE17029A1344D162DB887C66D35D12FCF4326528BC6617F3DEE61CABC89101?sv=2017-04-17&sr=b&sig=JddoX2ys8RT2zIA7G92%2FRBDuEh5DHwOmsb%2F4ppjG5lw%3D&spr=https&se=2020-02-28T08%3A19%3A44Z&sp=r&rscl=x-e2eid-518a2079-bd644188-9813fd18-55e9d93a-session-3bfe4da0-e19b42ba-814e25e5-3df2b02f] Try 1/5, non-retryable exception caught. Throwing. Details:
2020-02-27T07:41:46.5788953Z Task was requested to be canceled. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-02-27T07:41:46.5790188Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-02-27T07:41:46.5791087Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-02-27T07:41:46.5791943Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-02-27T07:41:46.5792511Z --- End of stack trace from previous location where exception was thrown ---
2020-02-27T07:41:46.5793178Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-02-27T07:41:46.5794693Z Warning, [https://fv1vsblobprodsu6weus82.blob.core.windows.net/dba995796df9b345ee9e80903f89a7ee5a/5440CE17029A1344D162DB887C66D35D12FCF4326528BC6617F3DEE61CABC89101?sv=2017-04-17&sr=b&sig=JddoX2ys8RT2zIA7G92%2FRBDuEh5DHwOmsb%2F4ppjG5lw%3D&spr=https&se=2020-02-28T08%3A19%3A44Z&sp=r&rscl=x-e2eid-518a2079-bd644188-9813fd18-55e9d93a-session-3bfe4da0-e19b42ba-814e25e5-3df2b02f] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-02-27T07:41:46.5796245Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-02-27T07:41:46.5797371Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-02-27T07:41:46.5798220Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-02-27T07:41:46.5798787Z --- End of stack trace from previous location where exception was thrown ---
2020-02-27T07:41:46.5799331Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-02-27T07:41:46.5799994Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass60_0.<<HandleRedirectAsync>b__0>d.MoveNext()
2020-02-27T07:41:46.5800576Z --- End of stack trace from previous location where exception was thrown ---
2020-02-27T07:41:46.5801111Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-02-27T07:41:51.1518287Z Information, Downloaded 658.3 MB out of 687.9 MB (96%).
2020-02-27T07:41:55.7553266Z Information, Downloaded 687.9 MB out of 687.9 MB (100%).
2020-02-27T07:41:55.7559817Z Information, 
2020-02-27T07:41:55.7560007Z Download statistics:
2020-02-27T07:41:55.7560324Z Total Content: 687.9 MB
2020-02-27T07:41:55.7560613Z Physical Content Downloaded: 190.7 MB
2020-02-27T07:41:55.7560895Z Compression Saved: 497.1 MB
2020-02-27T07:41:55.7561132Z Local Caching Saved: 0.0 MB
2020-02-27T07:41:55.7561362Z Chunks Downloaded: 8,301
2020-02-27T07:41:55.7561584Z Nodes Downloaded: 17
2020-02-27T07:41:55.7561732Z 
2020-02-27T07:41:57.3784957Z --
2020-02-27T07:41:57.3785212Z Path = 
2020-02-27T07:41:57.3785409Z Type = tar
2020-02-27T07:41:57.3785615Z Code Page = UTF-8
2020-02-27T07:41:57.3785770Z 
2020-02-27T07:41:57.3787506Z Everything is Ok
2020-02-27T07:41:57.3787643Z 
2020-02-27T07:41:57.3787808Z Folders: 6417
2020-02-27T07:41:57.3787981Z Files: 69262
2020-02-27T07:41:57.3788167Z Size:       628825131
2020-02-27T07:41:57.3788370Z Compressed: 38748672
2020-02-27T07:41:57.3865205Z Process exit code: 0
2020-02-27T07:41:57.4262253Z Cache restored.
2020-02-27T07:41:57.7378543Z Information, ApplicationInsightsTelemetrySender correlated 2 events with X-TFS-Session 3bfe4da0-e19b-42ba-814e-25e53df2b02f
2020-02-27T07:41:57.8405471Z ##[section]Finishing: Cache Yarn packages

Is this to be expected? From above log entries: Physical Content Downloaded: 190.7 MB

[kiwiidb]

We are also seeing this issue. Our build pipeline downloads about 1.5 GB of cache every time, which takes about 1min30s.

[neryams]

We are seeing the same thing on our pipelines - in our case our Yarn cache is only 760mb, usually it completes in around a minute (which is still slow for what should be a quick cache...) but on occasion it takes upwards of 7 minutes(!) It will hang at some random percentage while downloading and throw a ton of these errors:

Warning, [https://dlbvsblobprodcus316.blob.core.windows.net/dbcd127c096e7a4af48d6ac9e346673958/6773349A005340CD3FC3A65C8976550CBF24F048BF1C22627874711F88568D4F01?sv=2017-04-17&sr=b&sig=t7K9DDHyfRUu41swq96PdaIo2%2FjlMBGfK6mODh5GYMY%3D&spr=https&se=2020-03-09T22%3A24%3A13Z&sp=r&rscl=x-e2eid-7568c6ed-e69244f3-80f4fd0a-6d0097de-session-d57b7e4f-b2f54b0d-983d59fb-14f555d5] Try 1/5, non-retryable exception caught. Throwing. Details:
Task was requested to be canceled. System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
   at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
Warning, [https://4zjvsblobprodcus390.blob.core.windows.net/dbcd127c096e7a4af48d6ac9e346673958/EF4858F7CBF02C64CC8B7B23AFF2B676665FDDB0A119CA8C959E44A80B9BF1D101?sv=2017-04-17&sr=b&sig=A0RC7JrCEUBlY%2FzyQNZEBp1VOUvCIOOklHWasDvnk0w%3D&spr=https&se=2020-03-09T21%3A56%3A06Z&sp=r&rscl=x-e2eid-7568c6ed-e69244f3-80f4fd0a-6d0097de-session-d57b7e4f-b2f54b0d-983d59fb-14f555d5] Try 1/5, non-retryable exception caught. Throwing. Details:
Task was requested to be canceled. System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
   at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)

Eventually it will succeed and complete the step, but it is really slowing down our pipeline. We are running the pipeline on our own agents, but the same thing was happening on the Microsoft VMs.

[fadnavistanmay]

It looks like, there is slow download intermittently, but otherwise, the speed is around~250Mbps .

[mfahlen]

It looks like, there is slow download intermittently, but otherwise, the speed is around~250Mbps .

The slow download speed is in no way intermittent for us and we have no trouble with downloads from other places. Even with a 100 Mbps download speed, it shouldn't take more than about 16 seconds to download 190 MB. That's not even close to the 4 minutes or more we are seeing. Quite frankly it makes the cache unusable.

[xuhongxu96]

As you can see, the 2 cache tasks below are the same but spent different amount of time.

Log of the second cache task contains many Task was canceled as below:

2020-03-24T06:10:49.9460589Z Information, Expected size to be downloaded: 1,955.9 MB
2020-03-24T06:10:49.9490993Z Information, Downloaded 0.0 MB out of 1,955.9 MB (0%).
2020-03-24T06:10:54.9535671Z Information, Downloaded 50.8 MB out of 1,955.9 MB (3%).
2020-03-24T06:10:59.9543200Z Information, Downloaded 76.9 MB out of 1,955.9 MB (4%).
2020-03-24T06:11:04.9558766Z Information, Downloaded 76.9 MB out of 1,955.9 MB (4%).
2020-03-24T06:11:09.9563184Z Information, Downloaded 76.9 MB out of 1,955.9 MB (4%).
2020-03-24T06:11:14.9569023Z Information, Downloaded 77.0 MB out of 1,955.9 MB (4%).
2020-03-24T06:11:19.9572675Z Information, Downloaded 77.0 MB out of 1,955.9 MB (4%).
2020-03-24T06:11:24.9579770Z Information, Downloaded 77.0 MB out of 1,955.9 MB (4%).
2020-03-24T06:11:29.9585374Z Information, Downloaded 77.0 MB out of 1,955.9 MB (4%).
2020-03-24T06:11:34.9590068Z Information, Downloaded 77.0 MB out of 1,955.9 MB (4%).
2020-03-24T06:11:39.9592386Z Information, Downloaded 77.0 MB out of 1,955.9 MB (4%).
2020-03-24T06:11:44.9599547Z Information, Downloaded 77.0 MB out of 1,955.9 MB (4%).
2020-03-24T06:11:49.9607874Z Information, Downloaded 77.0 MB out of 1,955.9 MB (4%).
2020-03-24T06:11:54.9624703Z Information, Downloaded 77.0 MB out of 1,955.9 MB (4%).
2020-03-24T06:11:55.3525585Z Warning, [https://zrtvsblobprodeus2154.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/1863F0DC250B6F3C71E702DF6510741D896EFB47EA3937C9B2B5D3CB7A74275801?sv=2017-04-17&sr=b&sig=1VLwM94GVaGKvGSufyvEcQy6J1q0gvucplk7xhz9ScM%3D&spr=https&se=2020-03-25T07%3A05%3A42Z&sp=r&rscl=x-e2eid-2532e7ce-a98f42e1-bb58c9d0-0edd3f25-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, non-retryable exception caught. Throwing. Details:
2020-03-24T06:11:55.3527265Z Task was requested to be canceled. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:11:55.3528382Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:11:55.3529672Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:11:55.3530948Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:11:55.3532042Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:11:55.3532820Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:11:55.3552136Z Warning, [https://zrtvsblobprodeus2154.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/1863F0DC250B6F3C71E702DF6510741D896EFB47EA3937C9B2B5D3CB7A74275801?sv=2017-04-17&sr=b&sig=1VLwM94GVaGKvGSufyvEcQy6J1q0gvucplk7xhz9ScM%3D&spr=https&se=2020-03-25T07%3A05%3A42Z&sp=r&rscl=x-e2eid-2532e7ce-a98f42e1-bb58c9d0-0edd3f25-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:11:55.3554323Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:11:55.3555443Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:11:55.3556350Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:11:55.3557366Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:11:55.3557902Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:11:55.3558536Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass60_0.<<HandleRedirectAsync>b__0>d.MoveNext()
2020-03-24T06:11:55.3559350Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:11:55.3559873Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:11:59.9632004Z Information, Downloaded 176.0 MB out of 1,955.9 MB (9%).
2020-03-24T06:12:04.9653198Z Information, Downloaded 331.6 MB out of 1,955.9 MB (17%).
2020-03-24T06:12:09.9656805Z Information, Downloaded 464.9 MB out of 1,955.9 MB (24%).
2020-03-24T06:12:14.9662403Z Information, Downloaded 564.8 MB out of 1,955.9 MB (29%).
2020-03-24T06:12:19.9679610Z Information, Downloaded 698.7 MB out of 1,955.9 MB (36%).
2020-03-24T06:12:24.9680606Z Information, Downloaded 858.0 MB out of 1,955.9 MB (44%).
2020-03-24T06:12:29.9688320Z Information, Downloaded 964.1 MB out of 1,955.9 MB (49%).
2020-03-24T06:12:34.9695114Z Information, Downloaded 1,099.6 MB out of 1,955.9 MB (56%).
2020-03-24T06:12:35.9751982Z Warning, [https://v4lvsblobprodeus2180.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/66F3ADAEC35E91270680462C30AA31649C387DDE7BDAE2D66D5BD9B0DCCA7C3501?sv=2017-04-17&sr=b&sig=i8VkTj0gjbqJ8Dv%2Fhlp9mvMYp5JaUeoKjQDEW9gJDAQ%3D&spr=https&se=2020-03-25T06%3A24%3A06Z&sp=r&rscl=x-e2eid-7900ccaa-773e4b5b-802e9b6e-855b4a5f-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Net.Http.HttpRequestException: An error occurred while sending the request.
2020-03-24T06:12:35.9754410Z  ---> System.Net.Http.CurlException: SSL connect error
2020-03-24T06:12:35.9755096Z    at System.Net.Http.CurlHandler.ThrowIfCURLEError(CURLcode error)
2020-03-24T06:12:35.9755830Z    at System.Net.Http.CurlHandler.MultiAgent.FinishRequest(StrongToWeakReference`1 easyWrapper, CURLcode messageResult)
2020-03-24T06:12:35.9770447Z    --- End of inner exception stack trace ---
2020-03-24T06:12:35.9771300Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:12:35.9772782Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:12:35.9773977Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:12:35.9775122Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:12:35.9775911Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:12:39.9698738Z Information, Downloaded 1,193.2 MB out of 1,955.9 MB (61%).
2020-03-24T06:12:44.9703235Z Information, Downloaded 1,193.2 MB out of 1,955.9 MB (61%).
2020-03-24T06:12:49.9714209Z Information, Downloaded 1,193.2 MB out of 1,955.9 MB (61%).
2020-03-24T06:12:54.9720687Z Information, Downloaded 1,193.2 MB out of 1,955.9 MB (61%).
2020-03-24T06:12:59.9770530Z Information, Downloaded 1,193.2 MB out of 1,955.9 MB (61%).
2020-03-24T06:13:04.9773576Z Information, Downloaded 1,193.2 MB out of 1,955.9 MB (61%).
2020-03-24T06:13:09.9790371Z Information, Downloaded 1,193.2 MB out of 1,955.9 MB (61%).
2020-03-24T06:13:14.9811434Z Information, Downloaded 1,193.2 MB out of 1,955.9 MB (61%).
2020-03-24T06:13:19.9816577Z Information, Downloaded 1,193.2 MB out of 1,955.9 MB (61%).
2020-03-24T06:13:24.9818503Z Information, Downloaded 1,193.2 MB out of 1,955.9 MB (61%).
2020-03-24T06:13:29.9821717Z Information, Downloaded 1,193.2 MB out of 1,955.9 MB (61%).
2020-03-24T06:13:34.9825101Z Information, Downloaded 1,193.2 MB out of 1,955.9 MB (61%).
2020-03-24T06:13:38.7965470Z Warning, [https://1yovsblobprodeus2184.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/03E9824E2CB026D8FFE3DCE8C904173715BFBEC1F1A71D09B3F4EF0279A1FE0D01?sv=2017-04-17&sr=b&sig=Sj9YCrYUKsOXeiqhvH2sjvBYFuF83WAZ9pelJr7XPXc%3D&spr=https&se=2020-03-25T07%3A00%3A54Z&sp=r&rscl=x-e2eid-451a0140-cf4843e4-83910eb7-2cb79a55-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, non-retryable exception caught. Throwing. Details:
2020-03-24T06:13:38.7967567Z Task was requested to be canceled. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:13:38.7968715Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:13:38.7970127Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:13:38.7971235Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.7972424Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.7973178Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.7984939Z Warning, [https://1yovsblobprodeus2184.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/03E9824E2CB026D8FFE3DCE8C904173715BFBEC1F1A71D09B3F4EF0279A1FE0D01?sv=2017-04-17&sr=b&sig=Sj9YCrYUKsOXeiqhvH2sjvBYFuF83WAZ9pelJr7XPXc%3D&spr=https&se=2020-03-25T07%3A00%3A54Z&sp=r&rscl=x-e2eid-451a0140-cf4843e4-83910eb7-2cb79a55-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:13:38.7988432Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:13:38.7990869Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:13:38.7992184Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.7995698Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.7996457Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.7997731Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass60_0.<<HandleRedirectAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.7998799Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8007844Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8082130Z Warning, [https://389vsblobprodeus2186.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/98C0B18AA0F6D81A7C56D4F934A9DD3E558E4BEE7C2231043512021B2DDFEB2E01?sv=2017-04-17&sr=b&sig=l2fcNHDbxGj1zpGT1Vf5Zcx93VM8HtB7V5PGxObvqeY%3D&spr=https&se=2020-03-25T06%3A35%3A46Z&sp=r&rscl=x-e2eid-451a0140-cf4843e4-83910eb7-2cb79a55-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, non-retryable exception caught. Throwing. Details:
2020-03-24T06:13:38.8181726Z Task was requested to be canceled. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:13:38.8182824Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:13:38.8183838Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:13:38.8185055Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8186332Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8187160Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8189536Z Warning, [https://389vsblobprodeus2186.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/98C0B18AA0F6D81A7C56D4F934A9DD3E558E4BEE7C2231043512021B2DDFEB2E01?sv=2017-04-17&sr=b&sig=l2fcNHDbxGj1zpGT1Vf5Zcx93VM8HtB7V5PGxObvqeY%3D&spr=https&se=2020-03-25T06%3A35%3A46Z&sp=r&rscl=x-e2eid-451a0140-cf4843e4-83910eb7-2cb79a55-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:13:38.8191327Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:13:38.8192315Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:13:38.8193610Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8194626Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8195420Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8196213Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass60_0.<<HandleRedirectAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8197810Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8198662Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8200728Z Warning, [https://e2kvsblobprodeus2126.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/5CE80C58348B949919029753190720CD6F3CEADFC91EA8FA653709DE599EEC5A01?sv=2017-04-17&sr=b&sig=yxuIKgpkZq6hzsMwao8nqwnxzTN6mIt84puzDHQEW8I%3D&spr=https&se=2020-03-25T06%3A21%3A46Z&sp=r&rscl=x-e2eid-451a0140-cf4843e4-83910eb7-2cb79a55-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, non-retryable exception caught. Throwing. Details:
2020-03-24T06:13:38.8202265Z Task was requested to be canceled. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:13:38.8203065Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:13:38.8204130Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:13:38.8205321Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8208646Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8209193Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8212336Z Warning, [https://e2kvsblobprodeus2126.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/5CE80C58348B949919029753190720CD6F3CEADFC91EA8FA653709DE599EEC5A01?sv=2017-04-17&sr=b&sig=yxuIKgpkZq6hzsMwao8nqwnxzTN6mIt84puzDHQEW8I%3D&spr=https&se=2020-03-25T06%3A21%3A46Z&sp=r&rscl=x-e2eid-451a0140-cf4843e4-83910eb7-2cb79a55-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:13:38.8213814Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:13:38.8214710Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:13:38.8215520Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8216361Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8216879Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8217507Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass60_0.<<HandleRedirectAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8218360Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8218875Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8220907Z Warning, [https://87qvsblobprodeus2155.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/079F208E1BDA2114D77F4064D9C1027CEE4CC52884859192AC038C6C5777C92E01?sv=2017-04-17&sr=b&sig=t20NtREcspYusLpUjdDa5ujEhDbYggbULSiIIJzgSow%3D&spr=https&se=2020-03-25T07%3A01%3A48Z&sp=r&rscl=x-e2eid-451a0140-cf4843e4-83910eb7-2cb79a55-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, non-retryable exception caught. Throwing. Details:
2020-03-24T06:13:38.8222194Z Task was requested to be canceled. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:13:38.8222902Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:13:38.8223732Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:13:38.8224539Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8226089Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8226626Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8228863Z Warning, [https://87qvsblobprodeus2155.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/079F208E1BDA2114D77F4064D9C1027CEE4CC52884859192AC038C6C5777C92E01?sv=2017-04-17&sr=b&sig=t20NtREcspYusLpUjdDa5ujEhDbYggbULSiIIJzgSow%3D&spr=https&se=2020-03-25T07%3A01%3A48Z&sp=r&rscl=x-e2eid-451a0140-cf4843e4-83910eb7-2cb79a55-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:13:38.8230460Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:13:38.8231375Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:13:38.8232177Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8233045Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8233564Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8234200Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass60_0.<<HandleRedirectAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8235021Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8235543Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8237515Z Warning, [https://nf7vsblobprodeus2166.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/77FC1666FC61E979C97E34B47D913A08CDBA6E6E5E7BDB33C6860F66334E00A601?sv=2017-04-17&sr=b&sig=o16bgvT2rBi6G3UbMDWZsVRjT2jxq6x6%2FuQJHfup324%3D&spr=https&se=2020-03-25T06%3A28%3A06Z&sp=r&rscl=x-e2eid-451a0140-cf4843e4-83910eb7-2cb79a55-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, non-retryable exception caught. Throwing. Details:
2020-03-24T06:13:38.8238739Z Task was requested to be canceled. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:13:38.8239509Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:13:38.8240329Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:13:38.8241303Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8242117Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8242633Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8244788Z Warning, [https://nf7vsblobprodeus2166.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/77FC1666FC61E979C97E34B47D913A08CDBA6E6E5E7BDB33C6860F66334E00A601?sv=2017-04-17&sr=b&sig=o16bgvT2rBi6G3UbMDWZsVRjT2jxq6x6%2FuQJHfup324%3D&spr=https&se=2020-03-25T06%3A28%3A06Z&sp=r&rscl=x-e2eid-451a0140-cf4843e4-83910eb7-2cb79a55-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:13:38.8246249Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:13:38.8247146Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:13:38.8247947Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8248908Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8249578Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8250279Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass60_0.<<HandleRedirectAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8251081Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8251597Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8417723Z Warning, [https://h3xvsblobprodeus2177.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/13C3F85DEB54DA926CA4395AD86CE4ED80D02C666EDE00220524467815E6282201?sv=2017-04-17&sr=b&sig=7rSMwvGzRhEX4RgOscZWyZZ24HEm9C3pyT3qyskXl4c%3D&spr=https&se=2020-03-25T07%3A04%3A41Z&sp=r&rscl=x-e2eid-451a0140-cf4843e4-83910eb7-2cb79a55-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, non-retryable exception caught. Throwing. Details:
2020-03-24T06:13:38.8418878Z Task was requested to be canceled. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:13:38.8419531Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:13:38.8420272Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:13:38.8421099Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8421874Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8422337Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8429583Z Warning, [https://h3xvsblobprodeus2177.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/13C3F85DEB54DA926CA4395AD86CE4ED80D02C666EDE00220524467815E6282201?sv=2017-04-17&sr=b&sig=7rSMwvGzRhEX4RgOscZWyZZ24HEm9C3pyT3qyskXl4c%3D&spr=https&se=2020-03-25T07%3A04%3A41Z&sp=r&rscl=x-e2eid-451a0140-cf4843e4-83910eb7-2cb79a55-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:13:38.8431217Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:13:38.8432115Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:13:38.8432903Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8433734Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8434212Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8434835Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass60_0.<<HandleRedirectAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8435524Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8435981Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8453337Z Warning, [https://ox6vsblobprodeus2146.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/0FF05096CFF181AD78EBF3B544C2AC09F63078BDD691E6A4B494910231A8C8C101?sv=2017-04-17&sr=b&sig=JccTvygphYCyxxT9apF4238AlFvoDsxrTc2rAH4bd08%3D&spr=https&se=2020-03-25T07%3A03%3A45Z&sp=r&rscl=x-e2eid-451a0140-cf4843e4-83910eb7-2cb79a55-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, non-retryable exception caught. Throwing. Details:
2020-03-24T06:13:38.8454680Z Task was requested to be canceled. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:13:38.8455401Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:13:38.8456132Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:13:38.8456917Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8457690Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8458218Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8462680Z Warning, [https://ox6vsblobprodeus2146.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/0FF05096CFF181AD78EBF3B544C2AC09F63078BDD691E6A4B494910231A8C8C101?sv=2017-04-17&sr=b&sig=JccTvygphYCyxxT9apF4238AlFvoDsxrTc2rAH4bd08%3D&spr=https&se=2020-03-25T07%3A03%3A45Z&sp=r&rscl=x-e2eid-451a0140-cf4843e4-83910eb7-2cb79a55-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:13:38.8466701Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:13:38.8467457Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:13:38.8468270Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8469223Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8469764Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:38.8470325Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass60_0.<<HandleRedirectAsync>b__0>d.MoveNext()
2020-03-24T06:13:38.8472033Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:13:38.8472592Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:13:39.9835518Z Information, Downloaded 1,194.1 MB out of 1,955.9 MB (61%).
2020-03-24T06:13:44.9821042Z Information, Downloaded 1,219.4 MB out of 1,955.9 MB (62%).
2020-03-24T06:13:49.9822792Z Information, Downloaded 1,219.4 MB out of 1,955.9 MB (62%).
2020-03-24T06:13:54.9825116Z Information, Downloaded 1,219.4 MB out of 1,955.9 MB (62%).
2020-03-24T06:13:59.9828194Z Information, Downloaded 1,219.4 MB out of 1,955.9 MB (62%).
2020-03-24T06:14:04.9829241Z Information, Downloaded 1,219.4 MB out of 1,955.9 MB (62%).
2020-03-24T06:14:09.9835864Z Information, Downloaded 1,219.4 MB out of 1,955.9 MB (62%).
2020-03-24T06:14:14.9841609Z Information, Downloaded 1,219.4 MB out of 1,955.9 MB (62%).
2020-03-24T06:14:19.9842838Z Information, Downloaded 1,219.4 MB out of 1,955.9 MB (62%).
2020-03-24T06:14:24.9845234Z Information, Downloaded 1,219.4 MB out of 1,955.9 MB (62%).
2020-03-24T06:14:29.9849018Z Information, Downloaded 1,219.4 MB out of 1,955.9 MB (62%).
2020-03-24T06:14:34.9853750Z Information, Downloaded 1,219.4 MB out of 1,955.9 MB (62%).
2020-03-24T06:14:39.9839918Z Information, Downloaded 1,219.4 MB out of 1,955.9 MB (62%).
2020-03-24T06:14:40.3049724Z Warning, [https://v4lvsblobprodeus2180.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/57B372776989683544A966E742B67437F90D09C0D26F8998739F9D504084A96301?sv=2017-04-17&sr=b&sig=D92QpGBUVXypTB5Wub31Rxmcu1oDlxgzd5FCzJ0F3pM%3D&spr=https&se=2020-03-25T06%3A20%3A32Z&sp=r&rscl=x-e2eid-451a0140-cf4843e4-83910eb7-2cb79a55-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, non-retryable exception caught. Throwing. Details:
2020-03-24T06:14:40.3051083Z Task was requested to be canceled. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:14:40.3051774Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:14:40.3052594Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:14:40.3053425Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:14:40.3054287Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:14:40.3054832Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:14:40.3074781Z Warning, [https://v4lvsblobprodeus2180.blob.core.windows.net/db2bcb2cba320949e9b26accfd091ca0bd/57B372776989683544A966E742B67437F90D09C0D26F8998739F9D504084A96301?sv=2017-04-17&sr=b&sig=D92QpGBUVXypTB5Wub31Rxmcu1oDlxgzd5FCzJ0F3pM%3D&spr=https&se=2020-03-25T06%3A20%3A32Z&sp=r&rscl=x-e2eid-451a0140-cf4843e4-83910eb7-2cb79a55-session-91566088-14974740-9ec400a1-97f4ded3] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-03-24T06:14:40.3076697Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-03-24T06:14:40.3077857Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-03-24T06:14:40.3079341Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-03-24T06:14:40.3080511Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:14:40.3081379Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:14:40.3082294Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass60_0.<<HandleRedirectAsync>b__0>d.MoveNext()
2020-03-24T06:14:40.3083389Z --- End of stack trace from previous location where exception was thrown ---
2020-03-24T06:14:40.3084885Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-03-24T06:14:44.9885234Z Information, Downloaded 1,326.7 MB out of 1,955.9 MB (68%).
2020-03-24T06:14:49.9890038Z Information, Downloaded 1,455.2 MB out of 1,955.9 MB (74%).
2020-03-24T06:14:54.9891046Z Information, Downloaded 1,597.2 MB out of 1,955.9 MB (82%).
2020-03-24T06:14:59.9893362Z Information, Downloaded 1,658.8 MB out of 1,955.9 MB (85%).
2020-03-24T06:15:04.9898159Z Information, Downloaded 1,813.4 MB out of 1,955.9 MB (93%).
2020-03-24T06:15:09.6678521Z Information, Downloaded 1,955.9 MB out of 1,955.9 MB (100%).
2020-03-24T06:15:09.6686292Z Information, 
2020-03-24T06:15:09.6686892Z Download statistics:
2020-03-24T06:15:09.6687389Z Total Content: 1,955.9 MB
2020-03-24T06:15:09.6688212Z Physical Content Downloaded: 778.6 MB
2020-03-24T06:15:09.6688766Z Compression Saved: 1,177.2 MB
2020-03-24T06:15:09.6689497Z Local Caching Saved: 0.0 MB
2020-03-24T06:15:09.6690056Z Chunks Downloaded: 23,454
2020-03-24T06:15:09.6690564Z Nodes Downloaded: 46
2020-03-24T06:15:09.6690979Z 
2020-03-24T06:15:09.6697903Z Process exit code: 0
2020-03-24T06:15:09.7358532Z Cache restored.
2020-03-24T06:15:10.0016690Z Information, ApplicationInsightsTelemetrySender correlated 2 events with X-TFS-Session 91566088-1497-4740-9ec4-00a197f4ded3
2020-03-24T06:15:10.0338036Z ##[section]Finishing: Cache docker image

[devsh4]

I'm also facing this issue. Whenever there is a cache hit, the task takes too long to restore cache, maybe due to multiple timeouts? This behavior is consistent across cache tasks whether it's for npm dependencies or cypress binary on vmImage: "windows-2019".

[waterfoul]

Why is this still a problem months later? we periodically see 4+ mins on a cache task because of the timeouts instead of the usual 30s

[rmetzger]

Our caches are 2.5Gb, and we often see insane download times:

• 46 minutes: https://dev.azure.com/rmetzger/Flink/_build/results?buildId=7282&view=logs&s=ae4f8708-9994-57d3-c2d7-b892156e7812&j=1454c523-5777-5d91-a870-f026a11d0383
• 31 minutes: https://dev.azure.com/rmetzger/Flink/_build/results?buildId=7282&view=logs&s=ae4f8708-9994-57d3-c2d7-b892156e7812&j=fc5181b0-e452-5c8f-68de-1097947f6483
• 45 minutes: https://dev.azure.com/rmetzger/Flink/_build/results?buildId=7290&view=logs&j=52b61abe-a3cc-5bde-cc35-1bbe89bb7df5&t=374a2d67-4005-56bd-b901-e1f59e10cd9f
• 1 hour 28 minutes: https://dev.azure.com/rmetzger/Flink/_build/results?buildId=7282&view=logs&j=b2f046ab-ae17-5406-acdc-240be7e870e4&t=deb0681b-f332-5df8-144e-f91a0da53e12

These are self-hosted machines hosted at Alibaba in Frankfurt Germany. Our Azure account is Western Europe. I would not expect the network to be an issue. Our pipeline artifacts (1GB) usually download in 1-5 minutes.

[rmetzger]

@fadnavistanmay it would be nice if you could take a look at this. Thanks a lot!

[Naninani]

Over 1h for creating the cache from the /usr/local/share/.cache/yarn. Thats insane. I'd be nice to have an otion to specify your onw blob that is in the same subscription and location where the self-hosted machines are located in Azure.

Above example is from the Teams EngSys. I cant even open the logs to see the reason why its takings so long.

[DevZenFlow]

Same problem here. 110MB node_modules cache taking almost 90 seconds to download. We went from 3 minute builds without cache to 4 minute builds with cache. The VM is in Azure, so is the blob storage, region is the same. I don't understand why this is so slow. Will try again tomorrow.

[dazinator]

Same problem - cache task sometimes takes a very long time - and when that happens looking at the logs - multiple exceptions:

2020-04-28T17:29:38.9932228Z ##[section]Starting: Cache NuGet release packages
2020-04-28T17:29:39.0051836Z ==============================================================================
2020-04-28T17:29:39.0052110Z Task         : Cache
2020-04-28T17:29:39.0052330Z Description  : Cache files between runs
2020-04-28T17:29:39.0052512Z Version      : 2.0.0
2020-04-28T17:29:39.0052700Z Author       : Microsoft Corporation
2020-04-28T17:29:39.0052931Z Help         : https://aka.ms/pipeline-caching-docs
2020-04-28T17:29:39.0053383Z ==============================================================================
2020-04-28T17:29:39.3781925Z Resolving key:
2020-04-28T17:29:39.4093891Z  - nuget                                    [string]
2020-04-28T17:29:39.4100244Z  - "Windows_NT"                             [string]
2020-04-28T17:29:39.8114348Z  - **/packages.lock.Release.json,!**/bin/** [file pattern; matches: 4]
2020-04-28T17:29:39.8115929Z    - s\src\[***redacted***]]\packages.lock.Release.json         --> 36C6F13EB920EF52C33216B74A78F565155CC129EA0140D20247CDCBE1573517
2020-04-28T17:29:39.8116927Z    - s\src\[***redacted***]]\packages.lock.Release.json         --> 28F0EA728DE80A6F4208D5F7F905C167FABDA8D32937A6C645844C167847E987
2020-04-28T17:29:39.8117732Z    - s\src\[***redacted***]]\packages.lock.Release.json         --> D6F761528E18B63627BA6D44BBD2F3CF3ACC19009F6C5C7BE6806CE30A69CAC1
2020-04-28T17:29:39.8118530Z    - s\src\[***redacted***]]\packages.lock.Release.json --> 7A58449AE165737FC0EF7CFC5F3F27D2805B1DF7573E329510F8A51CEE82D75D
2020-04-28T17:29:39.8151325Z Resolved to: nuget|"Windows_NT"|bAXHdMTIX5CN6n64b3BrgIMgGqi3ZKVytmaF9u3mcyQ=
2020-04-28T17:29:39.8173392Z Resolving restore key:
2020-04-28T17:29:39.8173807Z  - nuget        [string]
2020-04-28T17:29:39.8174098Z  - "Windows_NT" [string]
2020-04-28T17:29:39.8179762Z Resolved to: nuget|"Windows_NT"|**
2020-04-28T17:29:40.9564048Z Information, ApplicationInsightsTelemetrySender will correlate events with X-TFS-Session [***redacted***]]
2020-04-28T17:29:41.1148676Z Information, Getting a pipeline cache artifact with one of the following fingerprints:
2020-04-28T17:29:41.1149688Z Information, Fingerprint: `nuget|"Windows_NT"|bAXHdMTIX5CN6n64b3BrgIMgGqi3ZKVytmaF9u3mcyQ=`
2020-04-28T17:29:41.1150179Z Information, Fingerprint: `nuget|"Windows_NT"|**`
2020-04-28T17:29:41.4336952Z Information, There is a cache hit: `nuget|"Windows_NT"|[***redacted***]]`
2020-04-28T17:29:41.4337763Z Information, Used scope: 8;6334dd50-2591-41b3-8764-746de9f071eb;refs/heads/feature/deployt-pipeline-changes;7759c3db-3eb8-4ea9-ad3b-468684cd3455
2020-04-28T17:29:41.6547600Z Entry found at fingerprint: `nuget|"Windows_NT"|bAXHdMTIX5CN6n64b3BrgIMgGqi3ZKVytmaF9u3mcyQ=`
2020-04-28T17:29:42.6918137Z Information, ArtifactHttpRetryMessageHandler.SendAsync: https://vsblobprodeus21.vsblob.visualstudio.com/A61e4e2f6-c921-43bb-90ea-6e1ced829358/_apis/dedup/chunks/7A307F6A73A6FD0DECBB630F495807ED24F4545F512FCEAB3FCDEAAB46A88F3701 attempt 1/6 failed with StatusCode RedirectMethod, IsRetryableResponse False
2020-04-28T17:29:42.9993333Z Information, ArtifactHttpRetryMessageHandler.SendAsync: https://vsblobprodeus21.vsblob.visualstudio.com/A61e4e2f6-c921-43bb-90ea-6e1ced829358/_apis/dedup/nodes/84B0DB9831F680E688B6030EBDC33FFAB8ED02A26EC0E2FBCB3E5FA3AF0AFD4802 attempt 1/6 failed with StatusCode RedirectMethod, IsRetryableResponse False
2020-04-28T17:29:43.2665803Z Information, Expected size to be downloaded: 775.0 MB
2020-04-28T17:29:43.2698339Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:29:44.2503729Z 
2020-04-28T17:29:44.2504743Z 7-Zip 19.00 (x64) : Copyright (c) 1999-2018 Igor Pavlov : 2019-02-21
2020-04-28T17:29:44.2505485Z 
2020-04-28T17:29:44.2505655Z 
2020-04-28T17:29:44.2505868Z Extracting archive: 
2020-04-28T17:29:48.2690073Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:29:53.2704361Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:29:58.2945301Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:30:03.2950316Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:30:08.3046831Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:30:13.3192864Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:30:18.3241058Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:30:23.3265674Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:30:28.3382993Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:30:33.3507870Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:30:38.3523644Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:30:43.3584978Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:30:48.3630713Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:30:53.3798947Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:30:58.3910930Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:31:03.3914773Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:31:08.4055210Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:31:13.4163504Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:31:18.4186354Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:31:23.4309215Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:31:28.4486831Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:31:33.4556254Z Information, Downloaded 0.0 MB out of 775.0 MB (0%).
2020-04-28T17:31:38.4881541Z Information, Downloaded 16.5 MB out of 775.0 MB (2%).
2020-04-28T17:31:43.4956762Z Information, Downloaded 38.4 MB out of 775.0 MB (5%).
2020-04-28T17:31:48.5048114Z Information, Downloaded 58.0 MB out of 775.0 MB (7%).
2020-04-28T17:31:53.5231632Z Information, Downloaded 68.9 MB out of 775.0 MB (9%).
2020-04-28T17:31:58.5318663Z Information, Downloaded 81.2 MB out of 775.0 MB (10%).
2020-04-28T17:32:03.5455370Z Information, Downloaded 81.3 MB out of 775.0 MB (10%).
2020-04-28T17:32:08.5589188Z Information, Downloaded 96.0 MB out of 775.0 MB (12%).
2020-04-28T17:32:13.5678435Z Information, Downloaded 96.9 MB out of 775.0 MB (13%).
2020-04-28T17:32:18.5781851Z Information, Downloaded 97.3 MB out of 775.0 MB (13%).
2020-04-28T17:32:23.5785713Z Information, Downloaded 103.8 MB out of 775.0 MB (13%).
2020-04-28T17:32:27.0326042Z Warning, [https://ymjvsblobprodeus2150.blob.core.windows.net/db61e4e2f6c92143bb90ea6e1ced829358/20514A0C4B12F3834B16EBE8AD5E3CD4FB01C3A43CE8DE39A88203EFF4B059F501?sv=2017-04-17&sr=b&sig=t5UFQVwYn6sdHlDsxmM4yrwCHGCPbAIxsesQznlBDqk%3D&spr=https&se=2020-04-29T18%3A07%3A34Z&sp=r&rscl=x-e2eid-b6917840-40b24665-93f9a050-b595abe2-session-ce80bd59-310f4629-bad3549a-5feadf2a] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Net.Http.HttpRequestException: An error occurred while sending the request.
2020-04-28T17:32:27.0327438Z  ---> System.Net.Http.WinHttpException (80072EE2, 12002): Error 12002 calling WINHTTP_CALLBACK_STATUS_REQUEST_ERROR, 'The operation timed out'.
2020-04-28T17:32:27.0328238Z    at System.Threading.Tasks.RendezvousAwaitable`1.GetResult()
2020-04-28T17:32:27.0328819Z    at System.Net.Http.WinHttpHandler.StartRequestAsync(WinHttpRequestState state)
2020-04-28T17:32:27.0329085Z    --- End of inner exception stack trace ---
2020-04-28T17:32:27.0329509Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-04-28T17:32:27.0330076Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-04-28T17:32:27.0330970Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-04-28T17:32:27.0331340Z --- End of stack trace from previous location where exception was thrown ---
2020-04-28T17:32:27.0332587Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:32:28.5915677Z Information, Downloaded 121.9 MB out of 775.0 MB (16%).
2020-04-28T17:32:33.6048189Z Information, Downloaded 122.1 MB out of 775.0 MB (16%).
2020-04-28T17:32:38.6091633Z Information, Downloaded 124.2 MB out of 775.0 MB (16%).
2020-04-28T17:32:43.6187281Z Information, Downloaded 124.2 MB out of 775.0 MB (16%).
2020-04-28T17:32:47.3921639Z Warning, [https://r09vsblobprodeus2182.blob.core.windows.net/db61e4e2f6c92143bb90ea6e1ced829358/A8786E9CF5F905244DE3C7A41E4EA6E64BD241F2C079A5A596C3FF3DD081925501?sv=2017-04-17&sr=b&sig=iD3Emqyafiv7r0aNgCCYlPV5JTr8G3%2FYT%2FOrh%2F440yQ%3D&spr=https&se=2020-04-29T17%3A39%3A27Z&sp=r&rscl=x-e2eid-7218dbc6-7d7e4568-9b85c811-2cfb8e5a-session-ce80bd59-310f4629-bad3549a-5feadf2a] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Net.Http.HttpRequestException: An error occurred while sending the request.
2020-04-28T17:32:47.3923755Z  ---> System.Net.Http.WinHttpException (80072EE2, 12002): Error 12002 calling WINHTTP_CALLBACK_STATUS_REQUEST_ERROR, 'The operation timed out'.
2020-04-28T17:32:47.3924493Z    at System.Threading.Tasks.RendezvousAwaitable`1.GetResult()
2020-04-28T17:32:47.3925063Z    at System.Net.Http.WinHttpHandler.StartRequestAsync(WinHttpRequestState state)
2020-04-28T17:32:47.3925629Z    --- End of inner exception stack trace ---
2020-04-28T17:32:47.3926246Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-04-28T17:32:47.3926947Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-04-28T17:32:47.3927601Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-04-28T17:32:47.3928139Z --- End of stack trace from previous location where exception was thrown ---
2020-04-28T17:32:47.3928595Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:32:48.6280489Z Information, Downloaded 124.3 MB out of 775.0 MB (16%).
2020-04-28T17:32:53.6348149Z Information, Downloaded 124.3 MB out of 775.0 MB (16%).
2020-04-28T17:32:58.6361393Z Information, Downloaded 124.3 MB out of 775.0 MB (16%).
2020-04-28T17:33:03.6372007Z Information, Downloaded 124.3 MB out of 775.0 MB (16%).
2020-04-28T17:33:08.6445220Z Information, Downloaded 124.4 MB out of 775.0 MB (16%).
2020-04-28T17:33:13.6467296Z Information, Downloaded 124.4 MB out of 775.0 MB (16%).
2020-04-28T17:33:18.6504739Z Information, Downloaded 124.4 MB out of 775.0 MB (16%).
2020-04-28T17:33:23.6517836Z Information, Downloaded 124.4 MB out of 775.0 MB (16%).
2020-04-28T17:33:28.2508140Z Warning, [https://e2kvsblobprodeus2126.blob.core.windows.net/db61e4e2f6c92143bb90ea6e1ced829358/CC248207EC6D988727B38D7F1FE8EB255E5D56D7F1103A9ADFAC52F851CDA1C101?[***redacted***]]] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-04-28T17:33:28.2509248Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-04-28T17:33:28.2509981Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-04-28T17:33:28.2510995Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-04-28T17:33:28.2511719Z --- End of stack trace from previous location where exception was thrown ---
2020-04-28T17:33:28.2512098Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:33:28.2512543Z    at Microsoft.VisualStudio.Services.Content.Common.ExceptionExtensions.ReThrow(Exception ex)
2020-04-28T17:33:28.2513121Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:33:28.2513589Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass60_0.<<HandleRedirectAsync>b__0>d.MoveNext()
2020-04-28T17:33:28.2514024Z --- End of stack trace from previous location where exception was thrown ---
2020-04-28T17:33:28.2514516Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:33:28.2964333Z Warning, [https://e2kvsblobprodeus2126.blob.core.windows.net/db61e4e2f6c92143bb90ea6e1ced829358/CC248207EC6D988727B38D7F1FE8EB255E5D56D7F1103A9ADFAC52F851CDA1C101?sv=2017-04-17&sr=b&sig=sHTRWxkbA%2FxESpn9untqvMoAw00aKSH0XAfFmo8oUNY%3D&spr=https&se=2020-04-29T17%3A47%3A49Z&sp=r&rscl=x-e2eid-7218dbc6-7d7e4568-9b85c811-2cfb8e5a-session-ce80bd59-310f4629-bad3549a-5feadf2a] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-04-28T17:33:28.2965663Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-04-28T17:33:28.2966485Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-04-28T17:33:28.2967116Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-04-28T17:33:28.2967496Z --- End of stack trace from previous location where exception was thrown ---
2020-04-28T17:33:28.2967858Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:33:28.2968276Z    at Microsoft.VisualStudio.Services.Content.Common.ExceptionExtensions.ReThrow(Exception ex)
2020-04-28T17:33:28.2968659Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:33:28.2969095Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass60_0.<<HandleRedirectAsync>b__0>d.MoveNext()
2020-04-28T17:33:28.2969508Z --- End of stack trace from previous location where exception was thrown ---
2020-04-28T17:33:28.2970019Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:33:28.4058756Z Warning, [https://e2kvsblobprodeus2126.blob.core.windows.net/db61e4e2f6c92143bb90ea6e1ced829358/CC248207EC6D988727B38D7F1FE8EB255E5D56D7F1103A9ADFAC52F851CDA1C101?[***redacted***]]] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-04-28T17:33:28.4060362Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-04-28T17:33:28.4061407Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-04-28T17:33:28.4062605Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-04-28T17:33:28.4063377Z --- End of stack trace from previous location where exception was thrown ---
2020-04-28T17:33:28.4063739Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:33:28.4064328Z    at Microsoft.VisualStudio.Services.Content.Common.ExceptionExtensions.ReThrow(Exception ex)
2020-04-28T17:33:28.4064851Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:33:28.4065263Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass60_0.<<HandleRedirectAsync>b__0>d.MoveNext()
2020-04-28T17:33:28.4066049Z --- End of stack trace from previous location where exception was thrown ---
2020-04-28T17:33:28.4066402Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:33:28.6527280Z Information, Downloaded 124.4 MB out of 775.0 MB (16%).
2020-04-28T17:33:33.7043944Z Information, Downloaded 155.6 MB out of 775.0 MB (20%).
2020-04-28T17:33:38.7187737Z Information, Downloaded 155.6 MB out of 775.0 MB (20%).
2020-04-28T17:33:43.7225928Z Information, Downloaded 155.6 MB out of 775.0 MB (20%).
2020-04-28T17:33:49.2510031Z Information, Downloaded 155.6 MB out of 775.0 MB (20%).
2020-04-28T17:33:53.7395062Z Information, Downloaded 155.6 MB out of 775.0 MB (20%).
2020-04-28T17:33:58.7539350Z Information, Downloaded 155.6 MB out of 775.0 MB (20%).
2020-04-28T17:34:03.7643356Z Information, Downloaded 155.6 MB out of 775.0 MB (20%).
2020-04-28T17:34:08.7704208Z Information, Downloaded 155.6 MB out of 775.0 MB (20%).
2020-04-28T17:34:13.7829528Z Information, Downloaded 155.6 MB out of 775.0 MB (20%).
2020-04-28T17:34:18.7984398Z Information, Downloaded 155.6 MB out of 775.0 MB (20%).
2020-04-28T17:34:23.8109108Z Information, Downloaded 155.6 MB out of 775.0 MB (20%).
2020-04-28T17:34:28.8150151Z Information, Downloaded 155.6 MB out of 775.0 MB (20%).
2020-04-28T17:34:29.5899199Z Warning, [https://3dovsblobprodeus2188.blob.core.windows.net/db61e4e2f6c92143bb90ea6e1ced829358/48DBB0BD87CFD2C4A7AB2DB1B5FE85FC5EF3F855152063D7FDEE3DEA47E4868501?[***redacted***]] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-04-28T17:34:29.5900906Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-04-28T17:34:29.5902047Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-04-28T17:34:29.5902788Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-04-28T17:34:29.5903304Z --- End of stack trace from previous location where exception was thrown ---
2020-04-28T17:34:29.5903826Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:34:29.5904342Z    at Microsoft.VisualStudio.Services.Content.Common.ExceptionExtensions.ReThrow(Exception ex)
2020-04-28T17:34:29.5904856Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:34:29.5905822Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass60_0.<<HandleRedirectAsync>b__0>d.MoveNext()
2020-04-28T17:34:29.5907349Z --- End of stack trace from previous location where exception was thrown ---
2020-04-28T17:34:29.5907882Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:34:29.6048073Z Warning, [https://3dovsblobprodeus2188.blob.core.windows.net/db61e4e2f6c92143bb90ea6e1ced829358/5DE1AF8B2DDDC319040D28EE936B564DA7DA8BC018C9777F4EEEC5EFA85C83A701?sv=2017-04-17&sr=b&sig=QhJMDLYzeGq6QnaM1o5bHNG88%2F0ErSL7OZwKSEIBxz8%3D&spr=https&se=2020-04-29T18%3A21%3A59Z&sp=r&rscl=x-e2eid-7218dbc6-7d7e4568-9b85c811-2cfb8e5a-session-ce80bd59-310f4629-bad3549a-5feadf2a] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Threading.Tasks.TaskCanceledException: A task was canceled.
2020-04-28T17:34:29.6049462Z    at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2020-04-28T17:34:29.6050177Z    at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
2020-04-28T17:34:29.6050723Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
2020-04-28T17:34:29.6051068Z --- End of stack trace from previous location where exception was thrown ---
2020-04-28T17:34:29.6051425Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:34:29.6051773Z    at Microsoft.VisualStudio.Services.Content.Common.ExceptionExtensions.ReThrow(Exception ex)
2020-04-28T17:34:29.6052150Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:34:29.6052552Z    at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass60_0.<<HandleRedirectAsync>b__0>d.MoveNext()
2020-04-28T17:34:29.6052898Z --- End of stack trace from previous location where exception was thrown ---
2020-04-28T17:34:29.6053412Z    at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)
2020-04-28T17:34:33.8752666Z Information, Downloaded 230.4 MB out of 775.0 MB (30%).
2020-04-28T17:34:38.8814635Z Information, Downloaded 484.2 MB out of 775.0 MB (62%).
2020-04-28T17:34:43.8879000Z Information, Downloaded 644.6 MB out of 775.0 MB (83%).
2020-04-28T17:34:48.8950046Z Information, Downloaded 739.0 MB out of 775.0 MB (95%).
2020-04-28T17:34:50.0498087Z Information, Downloaded 775.0 MB out of 775.0 MB (100%).
2020-04-28T17:34:50.0505719Z Information, 
2020-04-28T17:34:50.0506074Z Download statistics:
2020-04-28T17:34:50.0506369Z Total Content: 775.0 MB
2020-04-28T17:34:50.0506666Z Physical Content Downloaded: 307.9 MB
2020-04-28T17:34:50.0507069Z Compression Saved: 467.0 MB
2020-04-28T17:34:50.0507355Z Local Caching Saved: 0.0 MB
2020-04-28T17:34:50.0507674Z Chunks Downloaded: 8,848
2020-04-28T17:34:50.0508096Z Nodes Downloaded: 18
2020-04-28T17:34:50.0508289Z 
2020-04-28T17:34:50.2722510Z --
2020-04-28T17:34:50.2722850Z Path = 
2020-04-28T17:34:50.2723138Z Type = tar
2020-04-28T17:34:50.2723312Z Code Page = UTF-8
2020-04-28T17:34:50.2723434Z 
2020-04-28T17:34:50.2987361Z Everything is Ok
2020-04-28T17:34:50.2988053Z 
2020-04-28T17:34:50.2988332Z Folders: 5604
2020-04-28T17:34:50.2988587Z Files: 7749
2020-04-28T17:34:50.2988892Z Size:       766482389
2020-04-28T17:34:50.2989180Z Compressed: 6837760
2020-04-28T17:34:50.3057880Z Process exit code: 0
2020-04-28T17:34:50.3677888Z Cache restored.
2020-04-28T17:34:51.4349855Z Information, ApplicationInsightsTelemetrySender correlated 2 events with X-TFS-Session ce80bd59-310f-4629-bad3-549a5feadf2a
2020-04-28T17:34:51.5119937Z ##[section]Finishing: Cache NuGet release packages

[frankiea]

Same here - I'm seeing cache times all over the place. ~500MB cache sometimes takes 1 min to download, other times taking over 7 minutes with a bunch of these errors:

---> System.Net.Http.WinHttpException (80072EE2, 12002): Error 12002 calling WINHTTP_CALLBACK_STATUS_REQUEST_ERROR, 'The operation timed out'.

[jonstelly]

I followed the docs to enable npm and nuget caching. Nuget cache restore is super-slow to restore for me. I've got a multi-stage build, 1 build stage, 1 test stage, 1 deploy stage. build and test run concurrently. Agents are running at home, gigabit internet connection that pretty consistently hits ~100MB/sec downloads. Dotnet core + angular solution.

Before adding caching to the build and test stages:

Build Stage

• Average around: 6 minutes, 45 seconds

Test Stage

• Average around: 6 minutes, 30 seconds

After adding caching:

Build Stage

• 31 minutes

Test Stage

• 40 minutes

The NPM cache task seems fairly quick, but the nuget cache task is super slow, 10-25 minutes.

I see many of the below errors in the nuget cache restore task. I was using the same keys for the build and test cache steps, is it possible build+test stages clobbered or corrupted the cache? Nuget key was: 'nuget | "$(Agent.OS)" | **/*.csproj'.

I'm going to undo my caching for now, I was just hoping this might give me an easy win for speeding up builds, so I won't be able to test things, but I can provide detailed logs if needed.

Warning, [https://secretsecretsecretsecretsecret.blob.core.windows.net/secret/secret?secretsecretsecret] Try 1/5, retryable exception caught. Retrying in 00:00:01. System.Net.Http.HttpRequestException: An error occurred while sending the request.
 ---> System.Net.Http.CurlException: SSL connect error
   at System.Net.Http.CurlHandler.ThrowIfCURLEError(CURLcode error)
   at System.Net.Http.CurlHandler.MultiAgent.FinishRequest(StrongToWeakReference`1 easyWrapper, CURLcode messageResult)
   --- End of inner exception stack trace ---
   at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at Microsoft.VisualStudio.Services.Common.TaskCancellationExtensions.EnforceCancellation[TResult](Task`1 task, CancellationToken cancellationToken, Func`1 makeMessage, String file, String member, Int32 line)
   at Microsoft.VisualStudio.Services.BlobStore.WebApi.DedupStoreHttpClient.<>c__DisplayClass57_0.<<GetRedirectResponseAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.VisualStudio.Services.Content.Common.AsyncHttpRetryHelper`1.InvokeAsync(CancellationToken cancellationToken)

[whitleykeith]

I noticed the same issue on the Cache@2 task, but saw it go away when I switched to the CacheBeta@1 definition. Not sure if it was just luck or if there's some underlying issue with the Cache@2 Task.

[JoostVoskuilAegon]

Same here. Normally 1,5 min for 720MB, now it is taking up to 22 min. Lot's of SSL connect errors.

[simmiaggarwal]

@johnterickson Hello, I have same issue, Using Cache@2

Downloading 1,057.3 MB took 43seconds the first time. and now after 11 mins, it's still downloading. I had to cancel the build to get out of it.

It is intermittently taking way long time to download the cache.

any resolutions yet?

[rohithjidagam]

Any resolution for this? I am also seeing longer push times.

[shekibobo]

I just switched over to using Cache@2 for a gradle build cache. The cache package is about 2GB, and it was taking 3-4 minutes at first, and now I had the build cache just take 9 minutes for the same size cache. There are no errors in the logs, just a very slow download speed.

[dazinator]

Does anybody care about this issue or should we be switching back to cache1? :-p

[kensykora]

We are seeing similar slowness in cache restore. Sometimes the download process just completely stalls out. What used to be a ~1min30sec nuget restore turned into a ~7min cache restore. Completely invalidates the purpose of the task.

Example Log here: https://gist.github.com/kensykora/2e78bedf44a1c90e628d0e4d5b61a2af

[travisgosselin]

Same in our organization. This caching task is essential and has completely rendered many of our builds at times incapable of passing in under 1hr. We are beginning to migrate to a custom in-house task that will cache assets into AWS S3. Before going down this route we found a few other caching options (other than switching back to preview or V1) that seem promising in case it helps anyone else:

• Cache artifacts to Azure Artifacts - worked well during testing, and seemed fast. Didn't want to pay the price for Azure Artifact storage though (compared to Azure storage or AWS S3). https://marketplace.visualstudio.com/items?itemName=1ESLighthouseEng.PipelineArtifactCaching
• If looking specifically for Maven, this task allows you to plug into your azure storage account: https://marketplace.visualstudio.com/items?itemName=jhagestedt.maven-cache

[johnterickson]

Hi all- This thread has a lot going on in it!

Some thoughts:

1. If you are running your own private agent, it's going to be difficult to rule out that network topology and disk performance as the culprit. Ideally, repro your issue on a hosted agent in a public project.
2. We've found a hang in HttpClient and we have a fix in the works to mitigate it more quickly. If you're seeing it usually pretty fast and then it looks like it stalls for ~10 minutes and then completes, then it might help you.
3. The more adventurous folks can tinker with AZURE_PIPELINES_DEDUP_PARALLELISM to crank up the parallelism of the download. We've already increased this from 32 to 192 if your agent is up-to-date, but you can tweak from there. https://github.com/microsoft/azure-pipelines-agent/blob/39316cb6c469d3c175f37ebc957beb9c81a176fd/src/Agent.Plugins/PipelineArtifact/PipelineArtifactProvider.cs#L25
4. Some amount of exceptions/retries is expected. Usually these are either: 4a. A red herring 4b. A transient issue as Azure Storage reblanaces, or 4c. Indicative of an overtaxed private network.
5. Disk is far more often the bottleneck than one would think. Check your disk queue length and disk utilization percentages.

Ultimately, it would be best for folks to file issues specific to their scenario as "slowness" can be cause by a multitude of reasons. If you choose to do so, answer the following questions:

1. Is this a private agent or a hosted agent? Does this problem repro on hosted agents?
2. Is the problem consistent or spurious?
3. What is your network utilization percentage?
4. What is your disk utilization percentage?
5. What is the Mbps you are seeing?

Finally, keep in mind that the best performance is going to be with private agents that have persistent state. Nothing is going to beat not having to download and upload everything every time :)

[adrian-skybaker]

Nothing is going to beat not having to download and upload everything every time :)

Why limit the concept of the cache to something that has to be transported remotely (and slowly) over HTTP? Why not transparently present it via local disk? It shouldn't require resorting to managing persistent private agents to achieve this.

The cache was one of the things I was most looking forward to in Azure, mainly to avoid redownloading dependencies from remote HTTP sources, so it's hugely disappointing it's (a) network based and (b) a slow network. Downloading cached content over a small HTTP pipe isn't really a cache, if all the cache contains is HTTP downloads.

[johnterickson]

@adrian-skybaker There are a couple of limitations, but the main driver is costs. Either you have a pool of VMs on standby with state specific to each pipeline or you have a pool of generic VMs that have state injected into them. The former is faster, but the latter is less expensive.

Unfortunately, the term "caching" is quite overloaded. Pipeline Caching is less about "refetching dependencies" and more about "reduce re-computation": e.g. https://devblogs.microsoft.com/cppblog/vcpkg-2019-07-update/

You may find https://docs.microsoft.com/en-us/azure/devops/pipelines/agents/scale-set-agents?view=azure-devops to be what you are looking for:

Azure virtual machine scale set agents, hereafter referred to as scale set agents, are a form of self-hosted agents that can be auto-scaled to meet your demands. This elasticity reduces your need to run dedicated agents all the time. Unlike Microsoft-hosted agents, you have flexibility over the size and the image of machines on which agents run.

If you like Microsoft-hosted agents but are limited by what they offer, you should consider scale set agents. Here are some examples: ... You want to run additional configuration or cache warmup before an agent begins accepting jobs.

[wasabii]

It would be nice if there was a first-level cache on the local machine maintained by this task. All the objects are identified by some ID, I'm sure. So just slam them into a local directory. Fetch remote only when needed.

[johnterickson]

It would be nice if there was a first-level cache on the local machine maintained by this task @wasabii this would be for private agents only, right?

[adrian-skybaker]

Either you have a pool of VMs on standby with state specific to each pipeline or you have a pool of generic VMs that have state injected into them.

The VMs could be maintained on standby only for a short time, that way if the pipeline re-runs within X amount of time (eg hours/days) it could pick up a fast local copy, otherwise it could fall back on cold storage remotely downloaded. You don't need the whole VM though, just a way to mount a near file system onto it.

Once the cache is local (and once caches are supported across branches), it puts far less pressure on having to use solutions like scale set agents purely as a means to efficiently cache stuff.

but the main driver is costs

It's surely pretty expensive having your pool of generic VMs continually running pipelines that spend a huge proportion of their time doing nothing but repeatedly (and slowly) downloading remote content. It's certainly very expensive for the customers.

[adrian-skybaker]

...having said all that, the remote download shouldn't be as slow as it is, which is what I think this issue is about. Here's my download from a build just now on a MS hosted ubuntu-20.04 agent:

2020-07-22T21:37:25.5613477Z Downloaded 0.0 MB out of 159.0 MB (0%).
2020-07-22T21:37:30.5621488Z Downloaded 21.8 MB out of 159.0 MB (14%).
...
2020-07-22T21:38:25.5704478Z Downloaded 21.8 MB out of 159.0 MB (14%).
2020-07-22T21:38:30.5742055Z Downloaded 120.1 MB out of 159.0 MB (76%).
2020-07-22T21:38:31.5500310Z Downloaded 159.0 MB out of 159.0 MB (100%).

another, on hosted macOS-10.15:

2020-07-24T09:42:27.9688770Z Downloaded 0.0 MB out of 387.3 MB (0%).
2020-07-24T09:43:22.2270660Z Downloaded 387.3 MB out of 387.3 MB (100%).

also hosted macOS-10.15:

2020-07-24T23:11:15.8453740Z Downloaded 0.0 MB out of 9,773.4 MB (0%).
...
2020-07-24T23:13:40.9322427Z Downloaded 4,053.3 MB out of 9,773.4 MB (41%).
...
(2 minute stall)
...
2020-07-24T23:15:40.9554311Z Downloaded 4,082.8 MB out of 9,773.4 MB (42%).
...
2020-07-24T23:18:14.6646047Z Downloaded 9,773.4 MB out of 9,773.4 MB (100%).

Download statistics:
Total Content: 9,773.4 MB
Physical Content Downloaded: 2,926.4 MB

2020-07-25T23:44:13.0054890Z Downloaded 0.0 MB out of 387.3 MB (0%).
...(1 min stall)
2020-07-25T23:45:24.3842110Z Downloaded 0.0 MB out of 387.3 MB (0%).
2020-07-25T23:45:29.3866220Z Downloaded 16.8 MB out of 387.3 MB (4%).
2020-07-25T23:45:34.3998100Z Downloaded 19.0 MB out of 387.3 MB (5%).
2020-07-25T23:45:40.4339750Z Downloaded 19.0 MB out of 387.3 MB (5%).
2020-07-25T23:45:44.4949420Z Downloaded 85.0 MB out of 387.3 MB (22%).
2020-07-25T23:45:49.4966520Z Downloaded 158.2 MB out of 387.3 MB (41%).
2020-07-25T23:45:54.5292360Z Downloaded 225.5 MB out of 387.3 MB (58%).
2020-07-25T23:45:59.6768440Z Downloaded 297.8 MB out of 387.3 MB (77%).
2020-07-25T23:46:04.6769880Z Downloaded 385.8 MB out of 387.3 MB (100%).
2020-07-25T23:46:05.3278820Z Downloaded 387.3 MB out of 387.3 MB (100%).
2020-07-25T23:46:05.3291970Z 
2020-07-25T23:46:05.3292520Z Download statistics:
2020-07-25T23:46:05.3292910Z Total Content: 387.3 MB
2020-07-25T23:46:05.3293350Z Physical Content Downloaded: 216.5 MB

2020-07-25T05:12:58.0227430Z Downloaded 0.0 MB out of 9,773.4 MB (0%).
...
2020-07-25T05:32:28.8309720Z Downloaded 9,773.4 MB out of 9,773.4 MB (100%).
2020-07-25T05:32:28.8318560Z 
2020-07-25T05:32:28.8319270Z Download statistics:
2020-07-25T05:32:28.8319980Z Total Content: 9,773.4 MB
2020-07-25T05:32:28.8320680Z Physical Content Downloaded: 2,926.4 MB
2020-07-25T05:32:28.8321410Z Compression Saved: 6,847.0 MB

2020-07-27T00:30:40.7720470Z Downloaded 0.0 MB out of 387.3 MB (0%).
2020-07-27T00:30:50.9369540Z Downloaded 40.0 MB out of 387.3 MB (10%).
...(1 min stall)
2020-07-27T00:31:46.5803720Z Downloaded 40.0 MB out of 387.3 MB (10%).
...
2020-07-27T00:32:11.7055810Z Downloaded 386.3 MB out of 387.3 MB (100%).
...(1 min stall)
2020-07-27T00:33:14.2109670Z Downloaded 387.3 MB out of 387.3 MB (100%).
2020-07-27T00:33:14.2117290Z 
2020-07-27T00:33:14.2118930Z Download statistics:
2020-07-27T00:33:14.2120110Z Total Content: 387.3 MB
2020-07-27T00:33:14.2121170Z Physical Content Downloaded: 216.5 MB
2020-07-27T00:33:14.2122100Z Compression Saved: 170.8 MB

2020-07-28T20:44:51.3082690Z Downloaded 0.0 MB out of 390.2 MB (0%).
..
2020-07-28T20:47:27.8904680Z Downloaded 326.2 MB out of 390.2 MB (84%).
...
2020-07-28T20:48:23.5440270Z Downloaded 326.4 MB out of 390.2 MB (84%).
2020-07-28T20:48:28.5446160Z Downloaded 388.0 MB out of 390.2 MB (99%).
2020-07-28T20:48:29.2662470Z Downloaded 390.2 MB out of 390.2 MB (100%).
2020-07-28T20:48:29.2677130Z 
2020-07-28T20:48:29.2677730Z Download statistics:
2020-07-28T20:48:29.2678680Z Total Content: 390.2 MB
2020-07-28T20:48:29.2679890Z Physical Content Downloaded: 217.3 MB

2020-07-28T22:16:54.9539682Z Downloaded 0.0 MB out of 304.9 MB (0%).
2020-07-28T22:17:09.9571280Z Downloaded 159.4 MB out of 304.9 MB (52%).
...
2020-07-28T22:18:04.9736794Z Downloaded 159.4 MB out of 304.9 MB (52%).
2020-07-28T22:18:10.1064894Z Downloaded 304.9 MB out of 304.9 MB (100%).
2020-07-28T22:18:10.1074481Z 
2020-07-28T22:18:10.1075516Z Download statistics:
2020-07-28T22:18:10.1076305Z Total Content: 304.9 MB
2020-07-28T22:18:10.1078466Z Physical Content Downloaded: 123.3 MB

30 seconds just to determine a cache miss (hosted ubuntu-20.04):

2020-07-28T20:43:09.2898432Z ApplicationInsightsTelemetrySender will correlate events with X-TFS-Session 1366d847-968a-40b6-a03b-53007d9a5389
2020-07-28T20:43:09.8107139Z Getting a pipeline cache artifact with one of the following fingerprints:
2020-07-28T20:43:09.8108044Z Fingerprint: `yarn|"Linux"|L8yjlbmQlFXS8PoV2AZGUIqHE2Fr1O7qxVZGtJwn9aw=`
2020-07-28T20:43:09.8108563Z Fingerprint: `yarn|"Linux"|**`
2020-07-28T20:43:45.0001294Z There is a cache miss.
2020-07-28T20:43:46.5697844Z ApplicationInsightsTelemetrySender correlated 1 events with X-TFS-Session 1366d847-968a-40b6-a03b-53007d9a5389
2020-07-28T20:43:46.5767706Z ##[section]Finishing: restore .yarn

[kensykora]

@johnterickson

Is this a private agent or a hosted agent? Does this problem repro on hosted agents?

Our issue is on hosted agents

Is the problem consistent or spurious?

It's regular, but not consistent.

What is your network utilization percentage? What is your disk utilization percentage? What is the Mbps you are seeing?

n/a -- running on hosted agents

[wasabii]

Hosted agent here also.

As to the speed, let's just say this. If I disable the cache task, and let npm install run on it's own, it's about 3 times faster. Same with dotnet restore. The download of the cache takes longer, by a lot, than just refetching it.

[Meberem]

To echo everyone else on this thread, caches seem to be an issue on the hosted agent. I have a number of cache steps but to highlight a few cases:

libman cache

2020-07-23T16:46:30.7055866Z Downloaded 0.0 MB out of 16.5 MB (0%).
2020-07-23T16:46:32.5671009Z Downloaded 16.5 MB out of 16.5 MB (100%).

~1.8 seconds for 16.5MB

and

npm cache

2020-07-23T16:47:43.2813818Z Downloaded 0.0 MB out of 67.7 MB (0%).
2020-07-23T16:47:47.0962743Z Downloaded 67.7 MB out of 67.7 MB (100%).

~3.8 seconds for 67.7MB

Speeds look better with the larger NuGet cache but I am looking at around 1 minute for 1GB, it makes it seem like the cache is not worth it.

[dazinator]

Hosted agents here also (win latest).

[chevonc]

Having the same issues here. Using cache to speed up things, but variability makes it unreliable

[thewillhuang]

can confirm, the cache is extremely slow if it was really a disc bottleneck then skipping the cache and going straight for NPM or NuGet or Cargo would also take just as long but that does not seem to be the case here so there is something wrong with the cache implementation. so much so that it is easier to use no-cache and achieve better results and faster build times

[johnterickson]

This would only be for persistent agents (e.g. self-hosted or VMSS).

[VannaDii]

I have a pipeline that's taking 13 minutes to download 635 Mb with a self-hosted linux agent on a 1 Gbps connection

[adrian-skybaker]

Is there any update on this? Here's a build just now on hosted ubuntu, 90 seconds for 202.9MB:

2020-10-02T04:17:02.0857759Z Expected size to be downloaded: 325.1 MB
2020-10-02T04:17:02.0885968Z Downloaded 0.0 MB out of 325.1 MB (0%).
2020-10-02T04:17:07.0846360Z Downloaded 18.4 MB out of 325.1 MB (6%).
2020-10-02T04:17:12.0904194Z Downloaded 18.4 MB out of 325.1 MB (6%).
2020-10-02T04:17:17.0913116Z Downloaded 18.4 MB out of 325.1 MB (6%).
2020-10-02T04:17:22.0923183Z Downloaded 18.4 MB out of 325.1 MB (6%).
2020-10-02T04:17:27.0978423Z Downloaded 18.4 MB out of 325.1 MB (6%).
2020-10-02T04:17:32.0975048Z Downloaded 18.4 MB out of 325.1 MB (6%).
2020-10-02T04:17:37.0979857Z Downloaded 18.4 MB out of 325.1 MB (6%).
2020-10-02T04:17:42.0991687Z Downloaded 18.4 MB out of 325.1 MB (6%).
2020-10-02T04:17:47.1002043Z Downloaded 18.4 MB out of 325.1 MB (6%).
2020-10-02T04:17:52.1010702Z Downloaded 18.4 MB out of 325.1 MB (6%).
2020-10-02T04:17:57.1024072Z Downloaded 18.4 MB out of 325.1 MB (6%).
2020-10-02T04:18:02.1032157Z Downloaded 18.4 MB out of 325.1 MB (6%).
2020-10-02T04:18:07.1029415Z Downloaded 107.9 MB out of 325.1 MB (33%).
2020-10-02T04:18:12.1035939Z Downloaded 108.6 MB out of 325.1 MB (33%).
2020-10-02T04:18:17.1065063Z Downloaded 132.1 MB out of 325.1 MB (41%).
2020-10-02T04:18:22.1080940Z Downloaded 205.8 MB out of 325.1 MB (63%).
2020-10-02T04:18:24.9279621Z Downloaded 325.1 MB out of 325.1 MB (100%).
2020-10-02T04:18:24.9287684Z 
2020-10-02T04:18:24.9288716Z Download statistics:
2020-10-02T04:18:24.9289457Z Total Content: 325.1 MB
2020-10-02T04:18:24.9301100Z Physical Content Downloaded: 202.9 MB

[junalmeida]

I can also see terribly slow times in cache task on windows microsoft-hosted agents. A 1.5GB package usually takes 40secs is taking more than 20 minutes or even timing out the whole build job.

[rmundhe-iastate]

Same issue. 1.5 minutes for 308.5 MB.

[tklg]

It took 3:39 to download 72.3MB of npm modules with Cache@2.0.1 on an ubuntu microsoft-hosted agent. There were no failures or warnings in the log, just a very very slow download.
I dont think its worth using a cache at this point; downloading such a small amount of data should never take so long.

2020-11-17T18:31:44.1493095Z Downloaded 0.0 MB out of 72.3 MB (0%).
2020-11-17T18:31:49.1524454Z Downloaded 26.6 MB out of 72.3 MB (37%).
(4 line stall)
2020-11-17T18:32:14.1496121Z Downloaded 26.6 MB out of 72.3 MB (37%).
2020-11-17T18:32:19.1519945Z Downloaded 43.4 MB out of 72.3 MB (60%).
(10 line stall)
2020-11-17T18:33:14.1645030Z Downloaded 43.4 MB out of 72.3 MB (60%).
2020-11-17T18:33:19.1651801Z Downloaded 71.7 MB out of 72.3 MB (99%).
(10 line stall)
2020-11-17T18:34:14.1704838Z Downloaded 71.7 MB out of 72.3 MB (99%).
2020-11-17T18:34:19.1698307Z Downloaded 72.1 MB out of 72.3 MB (100%).
(12 line stall)
2020-11-17T18:35:19.6807716Z Downloaded 72.3 MB out of 72.3 MB (100%).

[dazinator]

No response or even real acknowledgement of this problem from the repo owners - just silence. Compare this to the asp.net core repo where issues raised are actually acknowledged. This silence is very frustrating probably for all concerned. Im left to conclude MS isn't interested in addressing this bug which makes cachev2 worthless. Go back to cache v1.

[evilpilaf]

As stated by others here, we're seeing cache restore times that are way too high, 10mins for under 2GB