Azure CLI Taking to long to initialize - breaks default AzureCLICredential setup in Identity

tankbob commented 4 months ago

Describe the bug

When trying to get an accesstoken the command takes longer than 13s to execute resulting in a token timeout error when using Azure.Identity with the AzureCLICredential.

Running

az account get-access-token --output json --resource https://vault.azure.net --tenant REDACTED --debug --verbose

Tells me cli.__main__: Command ran in 11.756 seconds (init: 10.193, invoke: 1.562)

Using Measure-Command I'm told it takes just over 13s.

Why is it taking 10s to init, what can I do to debug why and solve the issue.

Related command

az account get-access-token --output json --resource https://vault.azure.net --tenant REDACTED --debug --verbose

Errors

No error from the command, but because it takes too long the AzureCLICredential gets a token timeout error

Issue script & Debug output

cli.knack.cli: Command arguments: ['account', 'get-access-token', '--output', 'json', '--resource', 'https://vault.azure.net', '--tenant', 'REDACTED', '--debug', '--verbose']
cli.knack.cli: __init__ debug log:
Enable color in terminal.
cli.knack.cli: Event: Cli.PreExecute []
cli.knack.cli: Event: CommandParser.OnGlobalArgumentsCreate [<function CLILogging.on_global_arguments at 0x000001D948A1F880>, <function OutputProducer.on_global_arguments at 0x000001D948BA60C0>, <function CLIQuery.on_global_arguments at 0x000001D948BD3C40>]
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.003         2         8
cli.azure.cli.core: resource                  1.158        51       231
cli.azure.cli.core: Total (2)                 1.162        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 [<function AzCliLogging.init_command_file_logging at 0x000001D94BA4E340>]
cli.azure.cli.core.azlogging: metadata file logging enabled - writing logs to 'C:\Users\REDACTED\.azure\commands\2024-07-08.10-47-10.account_get-access-token.87316.log'.
az_command_data_logger: command args: account get-access-token --output {} --resource {} --tenant {} --debug --verbose
cli.knack.cli: Event: CommandInvoker.OnPreArgumentLoad [<function register_global_subscription_argument.<locals>.add_subscription_parameter at 0x000001D94BAB47C0>]
cli.knack.cli: Event: CommandInvoker.OnPostArgumentLoad []
cli.knack.cli: Event: CommandInvoker.OnPostCommandTableCreate [<function register_ids_argument.<locals>.add_ids_arguments at 0x000001D94BAB4860>, <function register_cache_arguments.<locals>.add_cache_arguments at 0x000001D94BAB49A0>]
cli.knack.cli: Event: CommandInvoker.OnCommandTableLoaded []
cli.knack.cli: Event: CommandInvoker.OnPreParseArgs []
cli.knack.cli: Event: CommandInvoker.OnPostParseArgs [<function OutputProducer.handle_output_argument at 0x000001D948BA6160>, <function CLIQuery.handle_query_parameter at 0x000001D948BD3CE0>, <function register_ids_argument.<locals>.parse_ids_arguments at 0x000001D94BAB4900>]
cli.azure.cli.core.auth.persistence: build_persistence: location='C:\\Users\\REDACTED\\.azure\\msal_token_cache.bin', encrypt=True
cli.azure.cli.core.auth.binary_cache: load: C:\Users\REDACTED\.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/REDACTED
msal.authority: openid_config("https://login.microsoftonline.com/REDACTED/v2.0/.well-known/openid-configuration") = {'token_endpoint': 'https://login.microsoftonline.com/REDACTED/oauth2/v2.0/token', 'token_endpoint_auth_methods_supported': ['client_secret_post', 'private_key_jwt', 'client_secret_basic'], 'jwks_uri': 'https://login.microsoftonline.com/REDACTED/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/REDACTED/v2.0', 'request_uri_parameter_supported': False, 'userinfo_endpoint': 'https://graph.microsoft.com/oidc/userinfo', 'authorization_endpoint': 'https://login.microsoftonline.com/REDACTED/oauth2/v2.0/authorize', 'device_authorization_endpoint': 'https://login.microsoftonline.com/REDACTED/oauth2/v2.0/devicecode', 'http_logout_supported': True, 'frontchannel_logout_supported': True, 'end_session_endpoint': 'https://login.microsoftonline.com/REDACTED/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/REDACTED/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://vault.azure.net/.default',), claims=None, kwargs={}
msal.application: Cache hit an AT
msal.telemetry: Generate or reuse correlation_id: c31be462-20be-4ab7-8c6d-8146d34ee99a
cli.knack.cli: Event: CommandInvoker.OnTransformResult [<function _resource_group_transform at 0x000001D94BA859E0>, <function _x509_from_base64_to_hex_transform at 0x000001D94BA85A80>]
cli.knack.cli: Event: CommandInvoker.OnFilterResult []
{
  "accessToken": REDACTED",
  "expiresOn": "2024-07-08 10:55:57.000000",
  "expires_on": 1720432557,
  "tenant": "REDACTED",
  "tokenType": "Bearer"
}
cli.knack.cli: Event: Cli.SuccessfulExecute []
cli.knack.cli: Event: Cli.PostExecute [<function AzCliLogging.deinit_cmd_metadata_logging at 0x000001D94BA4E5C0>]
az_command_data_logger: exit code: 0
cli.__main__: Command ran in 11.756 seconds (init: 10.193, invoke: 1.562)

Expected behavior

Command to execute far faster, no CLI Timeout error

Environment Summary

azure-cli                         2.61.0

core                              2.61.0
telemetry                          1.1.0

Dependencies:
msal                              1.28.0
azure-mgmt-resource               23.1.1

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

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

Legal docs and information: aka.ms/AzureCliLegal

Your CLI is up-to-date.

Additional context

No response

yonzhan commented 4 months ago

Thank you for opening this issue, we will look into it.

tankbob commented 4 months ago

I actually had this happen on a colleagues machine too, he has far less horse power so it was immediately noticeable that the Datto AV (based on Avira) was CPU spiking at the same time. We added an exclusion to the antivirus for the entire CLI2 folder and the delay seems to have disappeared. Ideally I didn't want to have to do this as it leaves an attack vector for python scripts that know about this.

I'm not sure if the issue to do with pre-scanning of the python scripts going on or a specific part of the process involved triggering the AV to cause the stall. I'm going to be raising it with Datto for analysis as to why it affects the cli so badly.

I'm sorry if this has caused wasted time, unless it helps in future - maybe a Known Conflicts and issues section to be created so that others having the issue can see it's a known problem and how to work around.

Azure / azure-cli