Self hosted agent cache download is really slow, task times out

[SzilkoBalog]

Describe your question

Ive set up a self hosted agent on my Windows computer. When I run the pipeline on the agent, it downloads the job, checks out the repo quickly. Then the next step in the pipeline is a Cache task. For some reason, it is really slow and times out.

Here is the log of the cache task:
Starting: NuGet Cache

Task : Cache
Description : Cache files between runs
Version : 2.198.0
Author : Microsoft Corporation
Help : https://aka.ms/pipeline-caching-docs

Resolving key:

• nuget [string]
• "Windows_NT" [string]
• C:\agent_work\1\s/**/*.csproj [file pattern; matches: 16]
  ...
  ...
  Resolved to: nuget|"Windows_NT"|m9XAv3djbkqwtmVOc3XHWBH7XIHQUalMVHWtVuARTt4=
  Resolving restore key:
• nuget [string]
• "Windows_NT" [string]
  Resolved to: nuget|"Windows_NT"|**
  Using default max parallelism.
  Using default max parallelism.
  Max dedup parallelism: 192
  DomainId: 0
  ApplicationInsightsTelemetrySender will correlate events with X-TFS-Session cbb5cf5d-f7e5-4a89-bdc4-08cedef451f2
  Hashtype: Dedup64K
  Getting a pipeline cache artifact with one of the following fingerprints:
  Fingerprint: nuget|"Windows_NT"|m9XAv3djbkqwtmVOc3XHWBH7XIHQUalMVHWtVuARTt4=
  Fingerprint: nuget|"Windows_NT"|**
  There is a cache hit: nuget|"Windows_NT"|m9XAv3djbkqwtmVOc3XHWBH7XIHQUalMVHWtVuARTt4=
  Used scope: 1;964b935e-d82b-4899-be22-b7741e10d7e9;refs/heads/refactor/webview2;5846b47a-a0ef-4c62-9456-20b032863955
  Entry found at fingerprint: nuget|"Windows_NT"|m9XAv3djbkqwtmVOc3XHWBH7XIHQUalMVHWtVuARTt4=

7-Zip 24.08 (x64) : Copyright (c) 1999-2024 Igor Pavlov : 2024-08-11

[https://sdfvsblobprodweu290.blob.core.windows.net/dba21690dfddf343afa5ee0ee5f3d35952/CE35CDF62DB861145C51C9D7C603CD109982DDC95E095468C669BA7F22FF7F7B02?sv=2019-07-07&sr=b&skoid=b3c3d5ad-124a-4025-8525-7a7a28563a43&sktid=33e01921-4d64-4f8c-a055-5bdaffd5e33d&skt=2024-11-28T08:41:59Z&ske=2024-11-30T09:41:59Z&sks=b&skv=2019-07-07&se=2024-11-28T11:54:10Z&sp=r&rscl=x-e2eid-46c9460b-c5684bf7-bec7f85d-ae328057-session-cbb5cf5d-f7e54a89-bdc408ce-def451f2] Try 1/5, Task was requested to be canceled.
[https://wcovsblobprodweu265.blob.core.windows.net/dba21690dfddf343afa5ee0ee5f3d35952/46E92E290B18F9AD9982782AC27FC6A22564395EEF9AAB4B1706ADB43EF84CB302?sv=2019-07-07&sr=b&skoid=b3c3d5ad-124a-4025-8525-7a7a28563a43&sktid=33e01921-4d64-4f8c-a055-5bdaffd5e33d&skt=2024-11-28T08:41:59Z&ske=2024-11-30T09:41:59Z&sks=b&skv=2019-07-07&se=2024-11-28T12:08:18Z&sp=r&rscl=x-e2eid-46c9460b-c5684bf7-bec7f85d-ae328057-session-cbb5cf5d-f7e54a89-bdc408ce-def451f2] Try 1/5, Task was requested to be canceled.
[https://o30vsblobprodweu248.blob.core.windows.net/dba21690dfddf343afa5ee0ee5f3d35952/8DC533CE352593F21BB9F41CB762FD0AD91021EA37A63F78AA3B33625EE6660802?sv=2019-07-07&sr=b&skoid=b3c3d5ad-124a-4025-8525-7a7a28563a43&sktid=33e01921-4d64-4f8c-a055-5bdaffd5e33d&skt=2024-11-28T08:41:59Z&ske=2024-11-30T09:41:59Z&sks=b&skv=2019-07-07&se=2024-11-28T12:16:35Z&sp=r&rscl=x-e2eid-46c9460b-c5684bf7-bec7f85d-ae328057-session-cbb5cf5d-f7e54a89-bdc408ce-def451f2] Try 1/5, Task was requested to be canceled.
[https://4ysvsblobprodweu228.blob.core.windows.net/dba21690dfddf343afa5ee0ee5f3d35952/767EA5E02042FDECF3302435DAFD3AC7EC6AC568F00A502F0C52AE191B35EE5302?sv=2019-07-07&sr=b&skoid=b3c3d5ad-124a-4025-8525-7a7a28563a43&sktid=33e01921-4d64-4f8c-a055-5bdaffd5e33d&skt=2024-11-28T08:41:59Z&ske=2024-11-30T09:41:59Z&sks=b&skv=2019-07-07&se=2024-11-28T12:13:52Z&sp=r&rscl=x-e2eid-46c9460b-c5684bf7-bec7f85d-ae328057-session-cbb5cf5d-f7e54a89-bdc408ce-def451f2] Try 1/5, Task was requested to be canceled.
[https://vxpvsblobprodweu275.blob.core.windows.net/dba21690dfddf343afa5ee0ee5f3d35952/EB6FDB2B582D38CECCA11202B562CBB66B5EABA683EB40AC27D3B1039D7AC35B02?sv=2019-07-07&sr=b&skoid=b3c3d5ad-124a-4025-8525-7a7a28563a43&sktid=33e01921-4d64-4f8c-a055-5bdaffd5e33d&skt=2024-11-28T08:41:59Z&ske=2024-11-30T09:41:59Z&sks=b&skv=2019-07-07&se=2024-11-28T11:57:33Z&sp=r&rscl=x-e2eid-46c9460b-c5684bf7-bec7f85d-ae328057-session-cbb5cf5d-f7e54a89-bdc408ce-def451f2] Try 1/5, Task was requested to be canceled.
Downloaded 0.0 MB out of 1,119.7 MB (0%).
Downloaded 0.0 MB out of 1,119.7 MB (0%).
Downloaded 0.0 MB out of 1,119.7 MB (0%).
Downloaded 0.0 MB out of 1,119.7 MB (0%).
Downloaded 0.0 MB out of 1,119.7 MB (0%).
Downloaded 0.0 MB out of 1,119.7 MB (0%).
Downloaded 0.9 MB out of 1,119.7 MB (0%).
Downloaded 0.9 MB out of 1,119.7 MB (0%).
Downloaded 0.9 MB out of 1,119.7 MB (0%).
Downloaded 0.9 MB out of 1,119.7 MB (0%).
Downloaded 0.9 MB out of 1,119.7 MB (0%).
Downloaded 0.9 MB out of 1,119.7 MB (0%).
Downloaded 0.9 MB out of 1,119.7 MB (0%).
Downloaded 0.9 MB out of 1,119.7 MB (0%).
Downloaded 0.9 MB out of 1,119.7 MB (0%).
Downloaded 0.9 MB out of 1,119.7 MB (0%).
Downloaded 0.9 MB out of 1,119.7 MB (0%).
Downloaded 0.9 MB out of 1,119.7 MB (0%).

As you can see after a while it downloads some.

My company is using a proxy. I included *.blob.core.windows.net in the no_proxy variable, but that does not seem to help.

Here is the agent config log:
Starting: Initialize job
Agent name: 'BP-C-011AE'
Agent machine name: 'BP-C-011AE'
Current agent version: '3.248.0'
Agent running as: 'BP-C-011AE$'
Agent is running behind proxy server: 'http://127.0.0.1:3128'/
Prepare build directory.
Set build variables.
Download all required tasks.
Checking job knob settings.
Knob: DockerActionRetries = true Source: $(VSTSAGENT_DOCKER_ACTION_RETRIES)
Knob: UseGitLongPaths = true Source: $(USE_GIT_LONG_PATHS)
Knob: NoProxy = some_other_links,.blob.core.windows.net,.dev.azure.com,127.0.0.* Source: ${no_proxy}
Knob: ProxyAddress = http://127.0.0.1:3128/ Source: ${http_proxy}
Knob: EnableIssueSourceValidation = true Source: $(ENABLE_ISSUE_SOURCE_VALIDATION)
Knob: AgentEnablePipelineArtifactLargeChunkSize = true Source: $(AGENT_ENABLE_PIPELINEARTIFACT_LARGE_CHUNK_SIZE)
Knob: ContinueAfterCancelProcessTreeKillAttempt = true Source: $(VSTSAGENT_CONTINUE_AFTER_CANCEL_PROCESSTREEKILL_ATTEMPT)
Knob: ProcessHandlerSecureArguments = false Source: $(AZP_75787_ENABLE_NEW_LOGIC)
Knob: ProcessHandlerSecureArguments = false Source: $(AZP_75787_ENABLE_NEW_LOGIC_LOG)
Knob: ProcessHandlerTelemetry = true Source: $(AZP_75787_ENABLE_COLLECT)
Knob: UseNewNodeHandlerTelemetry = True Source: $(DistributedTask.Agent.USENEWNODEHANDLERTELEMETRY)
Knob: ProcessHandlerEnableNewLogic = true Source: $(AZP_75787_ENABLE_NEW_PH_LOGIC)
Knob: EnableResourceMonitorDebugOutput = true Source: $(AZP_ENABLE_RESOURCE_MONITOR_DEBUG_OUTPUT)
Knob: EnableResourceUtilizationWarnings = true Source: $(AZP_ENABLE_RESOURCE_UTILIZATION_WARNINGS)
Knob: IgnoreVSTSTaskLib = true Source: $(AZP_AGENT_IGNORE_VSTSTASKLIB)
Knob: FailJobWhenAgentDies = true Source: $(FAIL_JOB_WHEN_AGENT_DIES)
Knob: CheckForTaskDeprecation = true Source: $(AZP_AGENT_CHECK_FOR_TASK_DEPRECATION)
Knob: CheckIfTaskNodeRunnerIsDeprecated246 = True Source: $(DistributedTask.Agent.CheckIfTaskNodeRunnerIsDeprecated246)
Knob: UseNode20ToStartContainer = True Source: $(DistributedTask.Agent.UseNode20ToStartContainer)
Knob: LogTaskNameInUserAgent = true Source: $(AZP_AGENT_LOG_TASKNAME_IN_USERAGENT)
Knob: UseFetchFilterInCheckoutTask = true Source: $(AGENT_USE_FETCH_FILTER_IN_CHECKOUT_TASK)
Knob: Rosetta2Warning = true Source: $(ROSETTA2_WARNING)
Knob: AddForceCredentialsToGitCheckout = True Source: $(DistributedTask.Agent.AddForceCredentialsToGitCheckout)
Finished checking job knob settings.
Start tracking orphan processes.
Finishing: Initialize job

What coudl be the problem?
Thank you!

Versions

vsts-agent-win-x64-3.248.0
Windows 11 Enterprise

Environment type (Please select at least one enviroment where you face this issue)

• Self-Hosted
• Microsoft Hosted
• VMSS Pool
• Container

Azure DevOps Server type

dev.azure.com (formerly visualstudio.com)

Operation system

Windows 11 Enterprise

Version controll system

No response

Azure DevOps Server Version (if applicable)

No response

[aleksandrlevochkin]

Hi @SzilkoBalog! Thank you for reporting this issue and sorry for the late response.

Could you please clarify a few things:

• did this setup use to work normally for you and then a regression happened or were there timeouts like this from the beginning?
• does this problem occur consistently on every pipeline run?

There are no explicit timestamps in the attached logs, so it is not quite clear where exactly the delay occurs and if it is the download operation itself that is slow and leads to timeout, or the process of finding a cache entry?

Ideally, it would be useful to check the pipeline and agent logs with the system.debug variable enabled. As the logs may contain private information, please, consider opening a ticket on https://developercommunity.visualstudio.com/AzureDevOps and uploading them there in a message marked as viewable by MS only.