search

microsoft / azure-pipelines-tasks

Tasks for Azure Pipelines
https://aka.ms/tfbuild
MIT License
3.48k stars 2.61k forks source link

[BUG]: AzureCLI task is too slow #20449

Open ronakj opened 1 week ago

ronakj commented 1 week ago

New issue checklist

Task name

AzureCLI

Task version

2.245.5

Issue Description

We have noticed that our AzureCLI tasks sometimes are too slow. We are using Ubuntu 20.04 images in our pipelines.

See these steps -

2024-09-19T10:51:53.8272777Z ##[debug]found: '/usr/bin/az'
2024-09-19T10:51:53.8274087Z ##[debug]/usr/bin/az arg: --version
2024-09-19T10:51:53.8274537Z ##[debug]/usr/bin/az arg: --version
... (trimmed)
2024-09-19T10:51:53.8277396Z ##[debug]   --version
2024-09-19T10:51:53.8277811Z ##[debug]   --version
2024-09-19T10:51:53.8278329Z [command]/usr/bin/az --version
2024-09-19T10:52:01.3311654Z azure-cli                         2.64.0
2024-09-19T10:52:01.3311900Z 
2024-09-19T10:52:01.3312349Z core                              2.64.0
2024-09-19T10:52:01.3313109Z telemetry                          1.1.0
...

Notice how just booting up with the az --version command takes 8 seconds. Next is the az cloud set -n AzureCloud

2024-09-19T10:52:01.3338533Z ##[debug]/usr/bin/az arg: cloud set -n AzureCloud
...(trimmed)
2024-09-19T10:52:01.3343822Z [command]/usr/bin/az cloud set -n AzureCloud
2024-09-19T10:52:23.6510604Z ##[debug]connectedServiceNameARM=***
2024-09-19T10:52:23.6511880Z ##[debug]*** auth scheme = WorkloadIdentityFederation
2024-09-19T10:52:23.6516971Z ##[debug]*** auth scheme = WorkloadIdentityFederation

Executing az cloud set -n AzureCloud takes more than 22 seconds. This is more than 30 seconds of pipeline time - which we have to pay every run. Sometimes the cloud set command can take upwards of 50 seconds too 🤯

Can we look into this and optimize it somehow?

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

Azure DevOps Server type

dev.azure.com (formerly visualstudio.com)

Azure DevOps Server Version (if applicable)

No response

Operation system

Ubuntu 20.04

Relevant log output

Attached to main post.

Full task logs with system.debug enabled

 2024-09-19T10:51:53.5989477Z ##[section]Starting: REDACTED
2024-09-19T10:51:53.5994800Z ==============================================================================
2024-09-19T10:51:53.5994952Z Task         : Azure CLI
2024-09-19T10:51:53.5995043Z Description  : Run Azure CLI commands against an Azure subscription in a PowerShell Core/Shell script when running on Linux agent or PowerShell/PowerShell Core/Batch script when running on Windows agent.
2024-09-19T10:51:53.5995294Z Version      : 2.245.5
2024-09-19T10:51:53.5995384Z Author       : Microsoft Corporation
2024-09-19T10:51:53.5995487Z Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/deploy/azure-cli
2024-09-19T10:51:53.5995635Z ==============================================================================
2024-09-19T10:51:53.6761791Z ##[debug]Using node path: /usr/local/vss-agent/3.243.1/externals/node20_1/bin/node
2024-09-19T10:51:53.7273815Z ##[debug]system.debug=***
2024-09-19T10:51:53.7274535Z ##[debug]DistributedTask.Tasks.Node.SkipDebugLogsWhenDebugModeOff=True
2024-09-19T10:51:53.7308877Z ##[debug]agent.TempDirectory=/mnt/vss/_work/_temp
2024-09-19T10:51:53.7315581Z ##[debug]loading inputs and endpoints
2024-09-19T10:51:53.7322125Z ##[debug]loading REDACTED
2024-09-19T10:51:53.7394908Z ##[debug]loaded 51
2024-09-19T10:51:53.7399281Z ##[debug]Agent.ProxyUrl=undefined
2024-09-19T10:51:53.7399732Z ##[debug]Agent.CAInfo=undefined
2024-09-19T10:51:53.7400177Z ##[debug]Agent.ClientCert=undefined
2024-09-19T10:51:53.7400634Z ##[debug]Agent.SkipCertValidation=undefined
2024-09-19T10:51:53.8191485Z ##[debug]check path : /mnt/vss/_work/_tasks/AzureCLI_46e4be58-730b-4389-8a2f-ea10b3e5e815/2.245.5/node_modules/azure-pipelines-tasks-artifacts-common/module.json
2024-09-19T10:51:53.8192879Z ##[debug]adding resource file: /mnt/vss/_work/_tasks/AzureCLI_46e4be58-730b-4389-8a2f-ea10b3e5e815/2.245.5/node_modules/azure-pipelines-tasks-artifacts-common/module.json
2024-09-19T10:51:53.8193628Z ##[debug]system.culture=en-US
2024-09-19T10:51:53.8206051Z ##[debug]Set default DNS lookup order to ipv4 first
2024-09-19T10:51:53.8206592Z ##[debug]Set default auto select family to false
2024-09-19T10:51:53.8207159Z ##[debug]check path : /mnt/vss/_work/_tasks/AzureCLI_46e4be58-730b-4389-8a2f-ea10b3e5e815/2.245.5/task.json
2024-09-19T10:51:53.8207726Z ##[debug]adding resource file: /mnt/vss/_work/_tasks/AzureCLI_46e4be58-730b-4389-8a2f-ea10b3e5e815/2.245.5/task.json
2024-09-19T10:51:53.8208438Z ##[debug]system.culture=en-US
2024-09-19T10:51:53.8214307Z ##[debug]which 'az'
2024-09-19T10:51:53.8219373Z ##[debug]found: '/usr/bin/az'
2024-09-19T10:51:53.8222592Z ##[debug]Feature flag AZP_AZURECLIV2_SETUP_PROXY_ENV not found. Returning false as default.
2024-09-19T10:51:53.8226423Z ##[debug]scriptType=bash
2024-09-19T10:51:53.8227303Z ##[debug]scriptLocation=inlineScript
2024-09-19T10:51:53.8227764Z ##[debug]scriptArguments=undefined
2024-09-19T10:51:53.8230000Z ##[debug]Agent.TempDirectory=/mnt/vss/_work/_temp
2024-09-19T10:51:53.8231863Z ##[debug]inlineScript=REDACTED
2024-09-19T10:51:53.8233976Z ##[debug]which 'bash'
2024-09-19T10:51:53.8237278Z ##[debug]found: '/usr/bin/bash'
2024-09-19T10:51:53.8238103Z ##[debug]which '/usr/bin/bash'
2024-09-19T10:51:53.8238556Z ##[debug]found: '/usr/bin/bash'
2024-09-19T10:51:53.8239255Z ##[debug]/usr/bin/bash arg: /mnt/vss/_work/_temp/azureclitaskscript1726743113823.sh
2024-09-19T10:51:53.8241003Z ##[debug]cwd=/mnt/vss/_work/1/s
2024-09-19T10:51:53.8241791Z ##[debug]scriptLocation=inlineScript
2024-09-19T10:51:53.8243093Z ##[debug]failOnStandardError=false
2024-09-19T10:51:53.8244095Z ##[debug]testing directory '/mnt/vss/_work/1/s'
2024-09-19T10:51:53.8263275Z ##[debug]which 'az'
2024-09-19T10:51:53.8272777Z ##[debug]found: '/usr/bin/az'
2024-09-19T10:51:53.8274087Z ##[debug]/usr/bin/az arg: --version
2024-09-19T10:51:53.8274537Z ##[debug]/usr/bin/az arg: --version
2024-09-19T10:51:53.8275696Z ##[debug]exec tool: /usr/bin/az
2024-09-19T10:51:53.8276142Z ##[debug]exec tool: /usr/bin/az
2024-09-19T10:51:53.8276564Z ##[debug]arguments:
2024-09-19T10:51:53.8276982Z ##[debug]arguments:
2024-09-19T10:51:53.8277396Z ##[debug]   --version
2024-09-19T10:51:53.8277811Z ##[debug]   --version
2024-09-19T10:51:53.8278329Z [command]/usr/bin/az --version
2024-09-19T10:51:55.1710743Z ##[debug]Agent environment resources - Disk: / Available 195072.20 MB out of 253873.92 MB, Memory: Used 4179.00 MB out of 64300.00 MB, CPU: Usage 6.55%
2024-09-19T10:52:00.1712930Z ##[debug]Agent environment resources - Disk: / Available 195050.58 MB out of 253873.92 MB, Memory: Used 3875.00 MB out of 64300.00 MB, CPU: Usage 6.83%
2024-09-19T10:52:01.3311654Z azure-cli                         2.64.0
2024-09-19T10:52:01.3311900Z 
2024-09-19T10:52:01.3312349Z core                              2.64.0
2024-09-19T10:52:01.3313109Z telemetry                          1.1.0
2024-09-19T10:52:01.3313212Z 
2024-09-19T10:52:01.3313408Z Extensions:
2024-09-19T10:52:01.3313718Z azure-devops                       1.0.1
2024-09-19T10:52:01.3313817Z 
2024-09-19T10:52:01.3314008Z Dependencies:
2024-09-19T10:52:01.3314225Z msal                              1.30.0
2024-09-19T10:52:01.3314488Z azure-mgmt-resource               23.1.1
2024-09-19T10:52:01.3314583Z 
2024-09-19T10:52:01.3314834Z Python location '/opt/az/bin/python3'
2024-09-19T10:52:01.3315120Z Extensions directory '/opt/az/azcliextensions'
2024-09-19T10:52:01.3315226Z 
2024-09-19T10:52:01.3315477Z Python (Linux) 3.11.8 (main, Aug 28 2024, 05:45:28) [GCC 9.4.0]
2024-09-19T10:52:01.3315750Z 
2024-09-19T10:52:01.3315969Z Legal docs and information: aka.ms/AzureCliLegal
2024-09-19T10:52:01.3316078Z 
2024-09-19T10:52:01.3316143Z 
2024-09-19T10:52:01.3316374Z Your CLI is up-to-date.
2024-09-19T10:52:01.3317294Z ##[debug]useGlobalConfig=false
2024-09-19T10:52:01.3317798Z ##[debug]Agent.TempDirectory=/mnt/vss/_work/_temp
2024-09-19T10:52:01.3318279Z ##[debug]Agent.TempDirectory=/mnt/vss/_work/_temp
2024-09-19T10:52:01.3328047Z Setting AZURE_CONFIG_DIR env variable to: /mnt/vss/_work/_temp/.azclitask
2024-09-19T10:52:01.3333389Z ##[debug]connectedServiceNameARM=REDACTED
2024-09-19T10:52:01.3334029Z ##[debug]REDACTED data environment = AzureCloud
2024-09-19T10:52:01.3334422Z Setting active cloud to: AzureCloud
2024-09-19T10:52:01.3334995Z ##[debug]which 'az'
2024-09-19T10:52:01.3337605Z ##[debug]found: '/usr/bin/az'
2024-09-19T10:52:01.3338076Z ##[debug]/usr/bin/az arg: cloud set -n AzureCloud
2024-09-19T10:52:01.3338533Z ##[debug]/usr/bin/az arg: cloud set -n AzureCloud
2024-09-19T10:52:01.3338984Z ##[debug]exec tool: /usr/bin/az
2024-09-19T10:52:01.3339406Z ##[debug]exec tool: /usr/bin/az
2024-09-19T10:52:01.3339823Z ##[debug]arguments:
2024-09-19T10:52:01.3340227Z ##[debug]arguments:
2024-09-19T10:52:01.3340637Z ##[debug]   cloud
2024-09-19T10:52:01.3341036Z ##[debug]   cloud
2024-09-19T10:52:01.3341434Z ##[debug]   set
2024-09-19T10:52:01.3341830Z ##[debug]   set
2024-09-19T10:52:01.3342241Z ##[debug]   -n
2024-09-19T10:52:01.3342634Z ##[debug]   -n
2024-09-19T10:52:01.3343036Z ##[debug]   AzureCloud
2024-09-19T10:52:01.3343447Z ##[debug]   AzureCloud
2024-09-19T10:52:01.3343822Z [command]/usr/bin/az cloud set -n AzureCloud
2024-09-19T10:52:05.1695887Z ##[debug]Agent environment resources - Disk: / Available 195050.46 MB out of 253873.92 MB, Memory: Used 3887.00 MB out of 64300.00 MB, CPU: Usage 11.32%
2024-09-19T10:52:10.1700862Z ##[debug]Agent environment resources - Disk: / Available 195050.41 MB out of 253873.92 MB, Memory: Used 3928.00 MB out of 64300.00 MB, CPU: Usage 6.12%
2024-09-19T10:52:16.2708108Z ##[debug]Agent environment resources - Disk: / Available 195050.41 MB out of 253873.92 MB, Memory: Used 3960.00 MB out of 64300.00 MB, CPU: Usage 6.34%
2024-09-19T10:52:21.2696966Z ##[debug]Agent environment resources - Disk: / Available 195050.41 MB out of 253873.92 MB, Memory: Used 3994.00 MB out of 64300.00 MB, CPU: Usage 7.29%
2024-09-19T10:52:23.6510604Z ##[debug]connectedServiceNameARM=REDACTED
2024-09-19T10:52:23.6511880Z ##[debug]REDACTEDauth scheme = WorkloadIdentityFederation
2024-09-19T10:52:23.6516971Z ##[debug]REDACTED auth scheme = WorkloadIdentityFederation
2024-09-19T10:52:23.6518174Z ##[debug]REDACTED data SubscriptionID = REDACTED
2024-09-19T10:52:23.6519372Z ##[debug]visibleAzLogin=***
2024-09-19T10:52:23.6520560Z ##[debug]REDACTED auth param serviceprincipalid = ***
2024-09-19T10:52:23.6521793Z ##[debug]REDACTED auth param tenantid = ***
2024-09-19T10:52:23.6522853Z ##[debug]System.JobId=REDACTED
2024-09-19T10:52:23.6523858Z ##[debug]System.PlanId=REDACTED
2024-09-19T10:52:23.6525304Z ##[debug]System.TeamProjectId=REDACTED
2024-09-19T10:52:23.6526203Z ##[debug]System.HostType=build
2024-09-19T10:52:23.6527110Z ##[debug]System.CollectionUri=https://REDACTED.visualstudio.com/
2024-09-19T10:52:23.6528065Z ##[debug]Getting credentials for local feeds
2024-09-19T10:52:23.6528869Z ##[debug]SYSTEMVSSCONNECTION exists ***
2024-09-19T10:52:23.6530018Z ##[debug]Got auth token, setting it as secret so it does not print in console log
2024-09-19T10:52:23.6534692Z ##[debug]Processed: ##vso[task.setsecret]***
2024-09-19T10:52:23.9928417Z ##[debug]Processed: ##vso[task.setsecret]***
2024-09-19T10:52:23.9929482Z ##[debug]which 'az'
2024-09-19T10:52:23.9930601Z ##[debug]found: '/usr/bin/az'
2024-09-19T10:52:23.9932657Z ##[debug]/usr/bin/az arg: login --service-principal -u "***" --tenant "***" --allow-no-subscriptions --federated-token "***
2024-09-19T10:52:23.9934042Z ##[debug]/usr/bin/az arg: login --service-principal -u "***" --tenant "***" --allow-no-subscriptions --federated-token "***
2024-09-19T10:52:23.9934587Z ##[debug]exec tool: /usr/bin/az
2024-09-19T10:52:23.9935027Z ##[debug]exec tool: /usr/bin/az
2024-09-19T10:52:23.9935452Z ##[debug]arguments:
2024-09-19T10:52:23.9935922Z ##[debug]arguments:
2024-09-19T10:52:23.9936334Z ##[debug]   login
2024-09-19T10:52:23.9936740Z ##[debug]   login
2024-09-19T10:52:23.9937156Z ##[debug]   --service-principal
2024-09-19T10:52:23.9937585Z ##[debug]   --service-principal
2024-09-19T10:52:23.9937990Z ##[debug]   -u
2024-09-19T10:52:23.9938395Z ##[debug]   -u
2024-09-19T10:52:23.9938834Z ##[debug]   ***
2024-09-19T10:52:23.9939265Z ##[debug]   ***
2024-09-19T10:52:23.9939677Z ##[debug]   --tenant
2024-09-19T10:52:23.9940097Z ##[debug]   --tenant
2024-09-19T10:52:23.9940538Z ##[debug]   ***
2024-09-19T10:52:23.9940968Z ##[debug]   ***
2024-09-19T10:52:23.9941387Z ##[debug]   --allow-no-subscriptions
2024-09-19T10:52:23.9941832Z ##[debug]   --allow-no-subscriptions
2024-09-19T10:52:23.9942266Z ##[debug]   --federated-token
2024-09-19T10:52:23.9942697Z ##[debug]   --federated-token
2024-09-19T10:52:23.9943760Z ##[debug]   ***
2024-09-19T10:52:23.9944745Z ##[debug]   ***
2024-09-19T10:52:23.9947428Z [command]/usr/bin/az login --service-principal -u *** --tenant *** --allow-no-subscriptions --federated-token ***
2024-09-19T10:52:24.9443951Z [
2024-09-19T10:52:24.9444407Z   {
2024-09-19T10:52:24.9444897Z     "cloudName": "AzureCloud",
2024-09-19T10:52:24.9445860Z     "homeTenantId": "***",
2024-09-19T10:52:24.9446312Z     "id": "REDACTED",
2024-09-19T10:52:24.9446626Z     "isDefault": ***,
2024-09-19T10:52:24.9446892Z     "managedByTenants": [],
2024-09-19T10:52:24.9447276Z     "name": "REDACTED",
2024-09-19T10:52:24.9447570Z     "state": "Enabled",
2024-09-19T10:52:24.9448157Z     "tenantId": "***",
2024-09-19T10:52:24.9448594Z     "user": {
2024-09-19T10:52:24.9449292Z       "name": "***",
2024-09-19T10:52:24.9449659Z       "type": "servicePrincipal"
2024-09-19T10:52:24.9450018Z     }
2024-09-19T10:52:24.9450325Z   }
2024-09-19T10:52:24.9450624Z ]
2024-09-19T10:52:24.9451412Z ##[debug]which 'az'
2024-09-19T10:52:24.9451940Z ##[debug]found: '/usr/bin/az'

Repro steps

Use an AzureCLI task with Workload identity federation credential.
v-schhabra commented 3 days ago

Hi @ronakj Thanks for reporting the issue. Will check on it.