az get-access-token: performance regression factor 10 between version 2.59 and version 2.64
- 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
Assessment
This issue has not been assessed yet.