Azure / Azure/azure-cli

az get-access-token: performance regression factor 10 between version 2.59 and version 2.64

Open
#29,871 2 comments 0 reactions 1 assignee Claimed by @jiasli View on GitHub
act-identity-squad ARM Auto-Assign Azure CLI Team customer-reported question
Dominant language
Python
Stars
4.6k
Forks
3.5k
Avg merge
3d 2h
Merged PRs (30d)
60

Description

### Describe the bug

with newer az versions (> 2.6x) we are suffering from **performance regression** with **factor 10,**
e.g. using "**az account get-access-token**" we have
Azure **CLI v2.64**, with responses taking **10-15 seconds**.
When using **CLI v2.59** or lower, the response time is **1-2 seconds**

We have traced this also via our company firewalls etc, and there are no indication the the infrastructure is blocking something.

Please note that also libraries (e.g. promptflow), which invoke "az account get-access-token" are affected and wont work, because some of them have a timeout specified for the az call with 10 sec, which then fails...
Actually promptflow did fail because it hits the timeout, because of the performance regression in azure cli.

### Related command

az account get-access-token

### Errors

az account get-access-token
CLI v2.64, responses takes 10-15 seconds
CLI v2.59, responses takes 1-2 seconds

regression, with factor 10.
Libraries using this call will fail with timeout.

### Issue script & Debug output

az version 2.64

PS C:\Users\merklbe1> az account get-access-token --debug
cli.knack.cli: Command arguments: ['account', 'get-access-token', '--debug']
cli.knack.cli: __init__ debug log:
Enable color in terminal.
Enable VT mode.
cli.knack.cli: Event: Cli.PreExecute []
cli.knack.cli: Event: CommandParser.OnGlobalArgumentsCreate [, , ]
cli.knack.cli: Event: CommandInvoker.OnPreCommandTableCreate []
cli.azure.cli.core: Modules found from index for 'account': ['azure.cli.command_modules.profile', 'azure.cli.command_modules.resource']
cli.azure.cli.core: Loading command modules:
cli.azure.cli.core: Name Load Time Groups Commands
cli.azure.cli.core: profile 0.004 2 8
cli.azure.cli.core: resource 0.475 51 231
cli.azure.cli.core: Total (2) 0.480 53 239
cli.azure.cli.core: Loaded 52 groups, 239 commands.
cli.azure.cli.core: Found a match in the command table.
cli.azure.cli.core: Raw command : account get-access-token
cli.azure.cli.core: Command table: account get-access-token
cli.knack.cli: Event: CommandInvoker.OnPreCommandTableTruncate []
cli.azure.cli.core.azlogging: metadata file logging enabled - writing logs to 'C:\Users\merklbe1\.azure\commands\2024-09-09.11-24-10.account_get-access-token.35608.log'.
az_command_data_logger: command args: account get-access-token --debug
cli.knack.cli: Event: CommandInvoker.OnPreArgumentLoad [.add_subscription_parameter at 0x00000298AA8A67A0>]
cli.knack.cli: Event: CommandInvoker.OnPostArgumentLoad []
cli.knack.cli: Event: CommandInvoker.OnPostCommandTableCreate [.add_ids_arguments at 0x00000298AA8E8860>, .add_cache_arguments at 0x00000298AA8E89A0>, .update_breaking_change_info at 0x00000298AA8E8A40>]
cli.knack.cli: Event: CommandInvoker.OnCommandTableLoaded []
cli.knack.cli: Event: CommandInvoker.OnPreParseArgs []
cli.knack.cli: Event: CommandInvoker.OnPostParseArgs [, , .parse_ids_arguments at 0x00000298AA8E8900>]
cli.azure.cli.core.auth.persistence: build_persistence: location='C:\\Users\\merklbe1\\.azure\\msal_token_cache.bin', encrypt=True
cli.azure.cli.core.auth.binary_cache: load: C:\Users\merklbe1\.azure\msal_http_cache.bin
urllib3.util.retry: Converted retries value: 1 -> Retry(total=1, connect=None, read=None, redirect=None, status=None)
msal.authority: Initializing with Entra authority: https://login.microsoftonline.com/xxx
msal.authority: openid_config("https://login.microsoftonline.com/xxx/v2.0/.well-known/openid-configuration") = {'token_endpoint': 'https://login.microsoftonline.com/xxx/oauth2/v2.0/token', 'token_endpoint_auth_methods_supported': ['client_secret_post', 'private_key_jwt', 'client_secret_basic'], 'jwks_uri': 'https://login.microsoftonline.com/xxx/discovery/v2.0/keys', 'response_modes_supported': ['query', 'fragment', 'form_post'], 'subject_types_supported': ['pairwise'], 'id_token_signing_alg_values_supported': ['RS256'], 'response_types_supported': ['code', 'id_token', 'code id_token', 'id_token token'], 'scopes_supported': ['openid', 'profile', 'email', 'offline_access'], 'issuer': 'https://login.microsoftonline.com/xxx/v2.0', 'request_uri_parameter_supported': False, 'userinfo_endpoint': 'https://graph.microsoft.com/oidc/userinfo', 'authorization_endpoint': 'https://login.microsoftonline.com/xxx/oauth2/v2.0/authorize', 'device_authorization_endpoint': 'https://login.microsoftonline.com/xxx/oauth2/v2.0/devicecode', 'http_logout_supported': True, 'frontchannel_logout_supported': True, 'end_session_endpoint': 'https://login.microsoftonline.com/xxx/oauth2/v2.0/logout', 'claims_supported': ['sub', 'iss', 'cloud_instance_name', 'cloud_instance_host_name', 'cloud_graph_host_name', 'msgraph_host', 'aud', 'exp', 'iat', 'auth_time', 'acr', 'nonce', 'preferred_username', 'name', 'tid', 'ver', 'at_hash', 'c_hash', 'email'], 'kerberos_endpoint': 'https://login.microsoftonline.com/xxx/kerberos', 'tenant_region_scope': 'EU', 'cloud_instance_name': 'microsoftonline.com', 'cloud_graph_host_name': 'graph.windows.net', 'msgraph_host': 'graph.microsoft.com', 'rbac_url': 'https://pas.windows.net'}
msal.application: Broker enabled? True
cli.azure.cli.core.auth.msal_authentication: UserCredential.get_token: scopes=('https://management.core.windows.net//.default',), claims=None, kwargs={}
msal.application: Cache hit an AT
msal.telemetry: Generate or reuse correlation_id: edcdb67e-857e-4752-8f01-57902bf64cee
cli.knack.cli: Event: CommandInvoker.OnTransformResult [, ]
cli.knack.cli: Event: CommandInvoker.OnFilterResult []

...

cli.knack.cli: Event: Cli.SuccessfulExecute []
cli.knack.cli: Event: Cli.PostExecute []
az_command_data_logger: exit code: 0
cli.__main__: Command ran in 12.863 seconds (init: 0.341, invoke: 12.522)
telemetry.main: Begin splitting cli events and extra events, total events: 1
telemetry.client: Accumulated 0 events. Flush the clients.
telemetry.main: Finish splitting cli events and extra events, cli events: 1
telemetry.save: Save telemetry record of length 3590 in cache file under C:\Users\merklbe1\.azure\telemetry\20240909112422463
telemetry.main: Begin creating telemetry upload process.
telemetry.process: Creating upload process: "C:\Program Files\Microsoft SDKs\Azure\CLI2\python.exe C:\Program Files\Microsoft SDKs\Azure\CLI2\Lib\site-packages\azure\cli\telemetry\__init__.pyc C:\Users\merklbe1\.azure C:\Users\merklbe1\.azure\telemetry\20240909112422463"
telemetry.process: Return from creating process 36316
telemetry.main: Finish creating telemetry upload process.

### Expected behavior

az version 2.59

PS C:\Users\merklbe1> az account get-access-token --debug
cli.knack.cli: Command arguments: ['account', 'get-access-token', '--debug']
cli.knack.cli: __init__ debug log:
Enable color in terminal.
Enable VT mode.
cli.knack.cli: Event: Cli.PreExecute []
cli.knack.cli: Event: CommandParser.OnGlobalArgumentsCreate [, , ]
cli.knack.cli: Event: CommandInvoker.OnPreCommandTableCreate []
cli.azure.cli.core: Modules found from index for 'account': ['azure.cli.command_modules.profile', 'azure.cli.command_modules.resource']
cli.azure.cli.core: Loading command modules:
cli.azure.cli.core: Name Load Time Groups Commands
cli.azure.cli.core: profile 0.004 2 8
cli.azure.cli.core: resource 0.191 51 228
cli.azure.cli.core: Total (2) 0.195 53 236
cli.azure.cli.core: Loaded 52 groups, 236 commands.
cli.azure.cli.core: Found a match in the command table.
cli.azure.cli.core: Raw command : account get-access-token
cli.azure.cli.core: Command table: account get-access-token
cli.knack.cli: Event: CommandInvoker.OnPreCommandTableTruncate []
cli.azure.cli.core.azlogging: metadata file logging enabled - writing logs to 'C:\Users\merklbe1\.azure\commands\2024-09-09.11-06-10.account_get-access-token.25760.log'.
az_command_data_logger: command args: account get-access-token --debug
cli.knack.cli: Event: CommandInvoker.OnPreArgumentLoad [.add_subscription_parameter at 0x000002D86466B4C0>]
cli.knack.cli: Event: CommandInvoker.OnPostArgumentLoad []
cli.knack.cli: Event: CommandInvoker.OnPostCommandTableCreate [.add_ids_arguments at 0x000002D8646A93A0>, .add_cache_arguments at 0x000002D8646A94E0>]
cli.knack.cli: Event: CommandInvoker.OnCommandTableLoaded []
cli.knack.cli: Event: CommandInvoker.OnPreParseArgs []
cli.knack.cli: Event: CommandInvoker.OnPostParseArgs [, , .parse_ids_arguments at 0x000002D8646A9440>]
cli.azure.cli.core.auth.persistence: build_persistence: location='C:\\Users\\merklbe1\\.azure\\msal_token_cache.bin', encrypt=True
cli.azure.cli.core.auth.binary_cache: load: C:\Users\merklbe1\.azure\msal_http_cache.bin
urllib3.util.retry: Converted retries value: 1 -> Retry(total=1, connect=None, read=None, redirect=None, status=None)
msal.authority: openid_config = {'token_endpoint': 'https://login.microsoftonline.com/xxx/oauth2/v2.0/token', 'token_endpoint_auth_methods_supported': ['client_secret_post', 'private_key_jwt', 'client_secret_basic'], 'jwks_uri': 'https://login.microsoftonline.com/xxx/discovery/v2.0/keys', 'response_modes_supported': ['query', 'fragment', 'form_post'], 'subject_types_supported': ['pairwise'], 'id_token_signing_alg_values_supported': ['RS256'], 'response_types_supported': ['code', 'id_token', 'code id_token', 'id_token token'], 'scopes_supported': ['openid', 'profile', 'email', 'offline_access'], 'issuer': 'https://login.microsoftonline.com/xxx/v2.0', 'request_uri_parameter_supported': False, 'userinfo_endpoint': 'https://graph.microsoft.com/oidc/userinfo', 'authorization_endpoint': 'https://login.microsoftonline.com/xxx/oauth2/v2.0/authorize', 'device_authorization_endpoint': 'https://login.microsoftonline.com/xxx/oauth2/v2.0/devicecode', 'http_logout_supported': True, 'frontchannel_logout_supported': True, 'end_session_endpoint': 'https://login.microsoftonline.com/xxx/oauth2/v2.0/logout', 'claims_supported': ['sub', 'iss', 'cloud_instance_name', 'cloud_instance_host_name', 'cloud_graph_host_name', 'msgraph_host', 'aud', 'exp', 'iat', 'auth_time', 'acr', 'nonce', 'preferred_username', 'name', 'tid', 'ver', 'at_hash', 'c_hash', 'email'], 'kerberos_endpoint': 'https://login.microsoftonline.com/xxx/kerberos', 'tenant_region_scope': 'EU', 'cloud_instance_name': 'microsoftonline.com', 'cloud_graph_host_name': 'graph.windows.net', 'msgraph_host': 'graph.microsoft.com', 'rbac_url': 'https://pas.windows.net'}
msal.application: Broker enabled? None
cli.azure.cli.core.auth.msal_authentication: UserCredential.get_token: scopes=('https://management.core.windows.net//.default',), claims=None, kwargs={}
msal.application: Cache hit an AT
msal.telemetry: Generate or reuse correlation_id: 81da400a-52aa-4d92-b195-b4490b8d6a51
cli.knack.cli: Event: CommandInvoker.OnTransformResult [, ]
cli.knack.cli: Event: CommandInvoker.OnFilterResult []
.....
cli.knack.cli: Event: Cli.SuccessfulExecute []
cli.knack.cli: Event: Cli.PostExecute []
az_command_data_logger: exit code: 0
cli.__main__: Command ran in 0.803 seconds (init: 0.527, invoke: 0.277)
telemetry.main: Begin splitting cli events and extra events, total events: 1
telemetry.client: Accumulated 0 events. Flush the clients.
telemetry.main: Finish splitting cli events and extra events, cli events: 1
telemetry.save: Save telemetry record of length 3536 in cache
telemetry.main: Begin creating telemetry upload process.
telemetry.process: Creating upload process: "C:\Program Files\Microsoft SDKs\Azure\CLI2\python.exe C:\Program Files\Microsoft SDKs\Azure\CLI2\Lib\site-packages\azure\cli\telemetry\__init__.pyc C:\Users\merklbe1\.azure"
telemetry.process: Return from creating process
telemetry.main: Finish creating telemetry upload process.

### Environment Summary

PS C:\Users\merklbe1> az --version
azure-cli 2.59.0 *

core 2.59.0 *
telemetry 1.1.0

Dependencies:
msal 1.27.0
azure-mgmt-resource 23.1.0b2

Python location 'C:\Program Files\Microsoft SDKs\Azure\CLI2\python.exe'
Extensions directory 'C:\Users\merklbe1\.azure\cliextensions'

Python (Windows) 3.11.8 (tags/v3.11.8:db85d51, Feb 6 2024, 22:03:32) [MSC v.1937 64 bit (AMD64)]

PS C:\Users\merklbe1> az --version
azure-cli 2.64.0

core 2.64.0
telemetry 1.1.0

Dependencies:
msal 1.30.0
azure-mgmt-resource 23.1.1

Python location 'C:\Program Files\Microsoft SDKs\Azure\CLI2\python.exe'
Extensions directory 'C:\Users\merklbe1\.azure\cliextensions'

Python (Windows) 3.11.8 (tags/v3.11.8:db85d51, Feb 6 2024, 22:03:32) [MSC v.1937 64 bit (AMD64)]

### Additional context

_No response_

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.