Azure / Azure/azure-devops-cli-extension
[Bug] Download times out and thus is very slow
- Dominant language
- Python
- Stars
- 682
- Forks
- 278
- Avg merge
- 3d 23h
- Merged PRs (30d)
- 3
Description
**Describe the bug**
When downloading artifacts, a request will timeout for 15 minutes and thus cause the download to be very slow.
**To Reproduce**
"azure-cli": "2.16.0",
"azure-cli-core": "2.16.0",
"azure-cli-telemetry": "1.0.6",
"azure-devops": "0.18.0"
Steps to reproduce the behavior:
1. Download a big universal package from Azure Artifacts:
```
az artifacts universal download --organization "https://dev.azure.com/my_org/" --project "my_proj" --scope project --feed "MyFeed" --name "universal_package" --version "1.0.0" --path .
```
2. Download will get stuck towards the end, during 15 minutes
3. It gets unstuck and finish properly.
**Expected behavior**
Download doesn't get stuck due to time out, or at least timeout is 15s and not 15 minutes.
**Debug logs**
```
Command arguments: ['artifacts', 'universal', 'download', '--organization', 'https://dev.azure.com/my_org/', '--project', '0b602fd1-6b44-4f22-86a7-a729f4fdf917', '--scope', 'project', '--feed', 'my_feed', '--name', 'my_package', '--version', '1.0.1', '--path', '.', '--debug']
Event: Cli.PreExecute []
Event: CommandParser.OnGlobalArgumentsCreate [, , ]
Event: CommandInvoker.OnPreCommandTableCreate []
Modules found from index for 'artifacts': ['azext_devops']
Loading command modules:
Name Load Time Groups Commands
Total (0) 0.000 0 0
These extensions are not installed and will be skipped: ['azext_ai_examples']
Loading extensions:
Name Load Time Groups Commands Directory
azure-devops 0.043 60 191 C:\Users\user\.azure\cliextensions\azure-devops
Total (1) 0.043 60 191
Loaded 60 groups, 191 commands.
Found a match in the command table.
Raw command : artifacts universal download
Command table: artifacts universal download
Event: CommandInvoker.OnPreCommandTableTruncate []
az_command_data_logger : command args: artifacts universal download --organization {} --project {} --scope {} --feed {} --name {} --version {} --path {} --debug
metadata file logging enabled - writing logs to 'C:\Users\user\.azure\commands'.
Event: CommandInvoker.OnPreArgumentLoad [.add_subscription_parameter at 0x03542CD8>, .register_query_examples at 0x0355B468>]
Event: CommandInvoker.OnPostArgumentLoad []
Event: CommandInvoker.OnPostCommandTableCreate [.add_ids_arguments at 0x0355B4B0>, .add_cache_arguments at 0x0355B540>]
Event: CommandInvoker.OnCommandTableLoaded []
Event: CommandInvoker.OnPreParseArgs []
Event: CommandInvoker.OnPostParseArgs [, , .handle_example_parameter at 0x03542E40>, .parse_ids_arguments at 0x0355B4F8>, ]
az_command_data_logger : extension name: azure-devops
az_command_data_logger : extension version: 0.18.0
Checking for a new ArtifactTool
Checking for ArtifactTool updates
Getting credential: azdevops-cli:https://dev.azure.com/my_org
Getting credential: azdevops-cli: default
Current cloud config:
AzureCloud
trying to get token (temp) for tenant 067e9632-ea4c-4ed9-9e6d-e294956e284b and user user@myorg.com
attempting to read file C:\Users\user\.azure\accessTokens.json as utf-8-sig
adal-python : 63f8cbed-cef4-4b8d-82c5-b2da229a1033 - Authority:Performing instance discovery: ...
adal-python : 63f8cbed-cef4-4b8d-82c5-b2da229a1033 - Authority:Performing static instance discovery
adal-python : 63f8cbed-cef4-4b8d-82c5-b2da229a1033 - Authority:Authority validated via static instance discovery
adal-python : 63f8cbed-cef4-4b8d-82c5-b2da229a1033 - TokenRequest:Getting token from cache with refresh if necessary.
adal-python : 63f8cbed-cef4-4b8d-82c5-b2da229a1033 - CacheDriver:finding with query keys: {'_clientId': '...', 'userId': '...'}
adal-python : 63f8cbed-cef4-4b8d-82c5-b2da229a1033 - CacheDriver:Looking for potential cache entries: {'_clientId': '...', 'userId': '...'}
adal-python : 63f8cbed-cef4-4b8d-82c5-b2da229a1033 - CacheDriver:Found 3 potential entries.
adal-python : 63f8cbed-cef4-4b8d-82c5-b2da229a1033 - CacheDriver:Resource specific token found.
adal-python : 63f8cbed-cef4-4b8d-82c5-b2da229a1033 - CacheDriver:Returning token from cache lookup, AccessTokenId: b'aN2y/jhL1bJvpWch+PQYghj0p7w/MhsGHe0yYy/u9+c=', RefreshTokenId: b'GR/FwsmmlQSjDtb5J4WzdP0jDrWa9B5JDFM3mgc6gEs='
msrest.universal_http.requests : Configuring retry: max_retries=3, backoff_factor=0.8, max_backoff=90
Azure devops telemetry enabled.
Logging telemetry to azure devops server.
msrest.universal_http.requests : Configuring retry: max_retries=3, backoff_factor=0.8, max_backoff=90
azext_devops.devops_sdk._file_cache : Loading cache file: C:\Users\user\.azure-devops\python-sdk\cache\options.json
azext_devops.devops_sdk._file_cache : attempting to read file C:\Users\user\.azure-devops\python-sdk\cache\options.json as utf-8-sig
azext_devops.devops_sdk.client : File cache hit for options on: https://dev.azure.com/my_org
msrest.universal_http.requests : Configuring retry: max_retries=3, backoff_factor=0.8, max_backoff=90
azext_devops.devops_sdk._file_cache : Loading cache file: C:\Users\user\.azure-devops\python-sdk\cache\resources.json
azext_devops.devops_sdk.client : Route template: _apis/{area}/{resource}
azext_devops.devops_sdk._file_cache : attempting to read file C:\Users\user\.azure-devops\python-sdk\cache\resources.json as utf-8-sig
azext_devops.devops_sdk.client : Api version '5.0-preview.1'
azext_devops.devops_sdk.connection : File cache hit for resources on: https://dev.azure.com/my_org
azext_devops.devops_sdk.client : POST https://dev.azure.com/my_org/_apis/CustomerIntelligence/Events
msrest.universal_http.requests : Configuring retry: max_retries=3, backoff_factor=0.8, max_backoff=90
Looking up current version of ArtifactTool...azext_devops.devops_sdk.client : Request content: [{'area': 'AzureDevopsCli', 'feature': 'artifacts', 'properties': {'Command': 'universal download', 'Args': 'feed name version path scope organization project', 'ShellType': 'cmd', 'IsInteractive': 'True', 'OutputType': 'json', 'OrgPresentInCommand': True, 'ProjectPresentInCommand': True, 'RepoPresentInCommand': False}}]
msrest.universal_http : Configuring redirects: allow=True, max=30
msrest.universal_http : Configuring request: timeout=100, verify=True, cert=None
msrest.universal_http : Configuring proxies: ''
msrest.universal_http : Evaluate proxies against ENV settings: True
urllib3.connectionpool : Starting new HTTPS connection (1): dev.azure.com:443
azext_devops.devops_sdk.client : File cache hit for options on: https://vsblob.dev.azure.com/my_org
azext_devops.devops_sdk.client : Route template: _apis/{area}/{toolName}/{resource}
azext_devops.devops_sdk.client : Api version '5.0-preview'
azext_devops.devops_sdk.client : GET https://vsblob.dev.azure.com/my_org/_apis/clienttools/ArtifactTool/release?osName=Windows&arch=AMD64&distroName=msys_nt-10.0-17763&distroVersion=3.0.7
azext_devops.devops_sdk.client : Request content: None
msrest.universal_http : Configuring redirects: allow=True, max=30
msrest.universal_http : Configuring request: timeout=100, verify=True, cert=None
msrest.universal_http : Configuring proxies: ''
msrest.universal_http : Evaluate proxies against ENV settings: True
urllib3.connectionpool : Starting new HTTPS connection (1): vsblob.dev.azure.com:443
urllib3.connectionpool : https://dev.azure.com:443 "POST /my_org/_apis/CustomerIntelligence/Events HTTP/1.1" 204 0
urllib3.connectionpool : https://vsblob.dev.azure.com:443 "GET /my_org/_apis/clienttools/ArtifactTool/release?osName=Windows&arch=AMD64&distroName=msys_nt-10.0-17763&distroVersion=3.0.7 HTTP/1.1" 200 450
azext_devops.devops_sdk.client : Response content: b'{"name":"ArtifactTool","rid":"win10-x64","version":"0.2.181","uri":"https://0t3vsblobprodcus362.vsblob.vsassets.io/artifacttool/artifacttool-win10-x64-Release_0.2.181.zip?sv=2019-02-02&sr=b&sig=Fuj7WKN8NKQaQRR5UsJFMKSlpTzjMqhyXkjjoMnX2ng%3D&spr=https&se=2020-12-16T13%3A57%3A36Z&sp=r&P1=1608126756&P2=11&P3=2&P4=aTO11yF7zc7sDnTzRqI5oylcAo3%2bpD%2f65An0KojIaQY%3d"}'
Checking if we already have ArtifactTool release 'ArtifactTool_win10-x64_0.2.181'
Not updating ArtifactTool because the current release already exists at 'C:\Users\user\.azure\azuredevops\cli\tools\artifacttool\ArtifactTool_win10-x64_0.2.181'
Getting credential: azdevops-cli:https://dev.azure.com/my_org
Getting credential: azdevops-cli: default
Current cloud config:
AzureCloud
trying to get token (temp) for tenant 067e9632-ea4c-4ed9-9e6d-e294956e284b and user user@myorg.com
adal-python : 4dc71740-63a7-4577-9582-61e0aab2abfc - Authority:Performing instance discovery: ...
adal-python : 4dc71740-63a7-4577-9582-61e0aab2abfc - Authority:Performing static instance discovery
adal-python : 4dc71740-63a7-4577-9582-61e0aab2abfc - Authority:Authority validated via static instance discovery
adal-python : 4dc71740-63a7-4577-9582-61e0aab2abfc - TokenRequest:Getting token from cache with refresh if necessary.
adal-python : 4dc71740-63a7-4577-9582-61e0aab2abfc - CacheDriver:finding with query keys: {'_clientId': '...', 'userId': '...'}
adal-python : 4dc71740-63a7-4577-9582-61e0aab2abfc - CacheDriver:Looking for potential cache entries: {'_clientId': '...', 'userId': '...'}
adal-python : 4dc71740-63a7-4577-9582-61e0aab2abfc - CacheDriver:Found 3 potential entries.
adal-python : 4dc71740-63a7-4577-9582-61e0aab2abfc - CacheDriver:Resource specific token found.
adal-python : 4dc71740-63a7-4577-9582-61e0aab2abfc - CacheDriver:Returning token from cache lookup, AccessTokenId: b'aN2y/jhL1bJvpWch+PQYghj0p7w/MhsGHe0yYy/u9+c=', RefreshTokenId: b'GR/FwsmmlQSjDtb5J4WzdP0jDrWa9B5JDFM3mgc6gEs='
Running external command: C:\Users\user\.azure\azuredevops\cli\tools\artifacttool\ArtifactTool_win10-x64_0.2.181\artifacttool universal download --service https://dev.azure.com/my_org/ --patvar AZURE_DEVOPS_EXT_ARTIFACTTOOL_PATVAR --feed my_feed --package-name my_package --package-version 1.0.1 --path . --project 0b602fd1-6b44-4f22-86a7-a729f4fdf917
ApplicationInsightsTelemetrySender will correlate events with X-TFS-Session 50a368c0-0296-4312-befb-0e533ec3e603
Obtained package metadata
DedupManifestArtifactClient will correlate http requests with X-TFS-Session 50a368c0-0296-4312-befb-0e533ec3e603
Downloaded 0.0 MB out of 466.2 MB (0%).
Downloaded 8.1 MB out of 466.2 MB (2%).
Downloaded 33.0 MB out of 466.2 MB (7%).
Downloaded 67.5 MB out of 466.2 MB (14%).
Downloaded 98.8 MB out of 466.2 MB (21%).
Downloaded 131.8 MB out of 466.2 MB (28%).
Downloaded 177.3 MB out of 466.2 MB (38%).
Downloaded 222.1 MB out of 466.2 MB (48%).
Downloaded 268.3 MB out of 466.2 MB (58%).
Downloaded 318.7 MB out of 466.2 MB (68%).
Downloaded 362.9 MB out of 466.2 MB (78%).
Downloaded 409.9 MB out of 466.2 MB (88%).
Downloaded 451.3 MB out of 466.2 MB (97%).
Downloaded 451.4 MB out of 466.2 MB (97%).
[... Many lines like the one above ...]
[... Many lines like the one above ...]
[... Many lines like the one above ...]
Downloaded 451.4 MB out of 466.2 MB (97%).
ArtifactHttpRetryMessageHandler.SendAsync: https://vsblobprodcus3.vsblob.visualstudio.com/A8b517d3f-052b-41e0-a7f6-e811999734c0/_apis/dedup/urls attempt 1/6 failed with TimeoutException: 'The HTTP request timed out after 00:15:00.'
ArtifactHttpRetryMessageHandler.SendAsync: https://vsblobprodcus3.vsblob.visualstudio.com/A8b517d3f-052b-41e0-a7f6-e811999734c0/_apis/dedup/urls attempt 1/6 failed with TimeoutException: 'The HTTP request timed out after 00:15:00.'
ArtifactHttpRetryMessageHandler.SendAsync: https://vsblobprodcus3.vsblob.visualstudio.com/A8b517d3f-052b-41e0-a7f6-e811999734c0/_apis/dedup/urls attempt 1/6 failed with TimeoutException: 'The HTTP request timed out after 00:15:00.'
Downloaded 451.4 MB out of 466.2 MB (97%).
Downloaded 451.4 MB out of 466.2 MB (97%).
Downloaded 451.4 MB out of 466.2 MB (97%).
Downloaded 460.3 MB out of 466.2 MB (99%).
Downloaded 460.3 MB out of 466.2 MB (99%).
Downloaded 460.3 MB out of 466.2 MB (99%).
Downloaded 460.3 MB out of 466.2 MB (99%).
Downloaded 460.3 MB out of 466.2 MB (99%).
Downloaded 463.5 MB out of 466.2 MB (99%).
Downloaded 466.2 MB out of 466.2 MB (100%).
Download statistics:
Total Content: 466.2 MB
Physical Content Downloaded: 449.5 MB
Compression Saved: 16.7 MB
Local Caching Saved: 0.0 MB
Chunks Downloaded: 6,023
Nodes Downloaded: 8
Download completed.
Download complete
Success
ApplicationInsightsTelemetrySender correlated 1 events with X-TFS-Session 50a368c0-0296-4312-befb-0e533ec3e603
Event: CommandInvoker.OnTransformResult [, ]
Event: CommandInvoker.OnFilterResult []
{
"Description": "Image data",
"ManifestId": "B99F264C98169F97928509204831F22F11BA61C0D0CBDD0EBD58D3D6F3FA8D0701",
"SuperRootId": "0E6AB96CF5C130AB5E8CBB771CEA621FE701BB662826E91E9FE59985BA492C7102",
"Version": "1.0.1"
}
Event: Cli.PostExecute []
az_command_data_logger : exit code: 0
Command ran in 954.303 seconds (init: 0.211, invoke: 954.092)
telemetry.save : Save telemetry record of length 3024 in cache
telemetry.check : Returns Positive.
telemetry.main : Begin creating telemetry upload process.
telemetry.process : Creating upload process: "C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\python.exe C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\lib\site-packages\azure\cli\telemetry\__init__.pyc C:\Users\user\.azure"
telemetry.process : Return from creating process
telemetry.main : Finish creating telemetry upload process.
```
**Additional info**
My universal package consists of 29 large images for a total of 465MB.
Contributor guide
Assessment
This issue has not been assessed yet.