az cli seems to spends time looking for account config, even if it doesn't need them

[jessehouwing]

Describe the bug

While looking into what causes the az-cli to load slowly on the hosted agents of GitHub Actions and Azure pipelines I noticed that az tries to look for accounts and throws a couple of exceptions even if the account isn't needed.

In this case the access token to access Azure DevOps is supplied through the environment, yet az is trying to load accounts and spends unneeded time there.

It's hard to tell from the logs, bet between the last logged line and the error handling there is a jump of about 10 seconds in the Azure pipelines log. Would be lovely if that time waste could be prevented.

It looks like the 10 seconds was caused by the fact that Windows Update and Storage Service had reenabled on the hosted runner. Still, it's unclear why az devops is not using the environment variable it is given and spends extra time trying to read the credentials from the profile.

Related command

Az DevOps pipelines show ...

Errors

2023-09-15T18:37:22.3348603Z DEBUG: cli.azext_devops.dev.common.services: PAT is present which can be used against this instance
2023-09-15T18:37:22.3375557Z DEBUG: cli.azure.cli.core: Current cloud config:
2023-09-15T18:37:22.3375819Z AzureCloud
2023-09-15T18:37:22.3376906Z DEBUG: cli.azext_devops.dev.common.services: az login is not present
2023-09-15T18:37:22.3382543Z DEBUG: cli.azext_devops.dev.common.services: There are no active accounts.
2023-09-15T18:37:22.3382797Z Traceback (most recent call last):
2023-09-15T18:37:22.3383541Z   File "D:\a\_work\1\s\build_scripts\windows\artifacts\cli\Lib\site-packages\azure/cli/core/_profile.py", line 537, in get_current_account_user
2023-09-15T18:37:22.3384147Z   File "D:\a\_work\1\s\build_scripts\windows\artifacts\cli\Lib\site-packages\azure/cli/core/_profile.py", line 546, in get_subscription
2023-09-15T18:37:22.3384535Z knack.util.CLIError: Please run 'az login' to setup account.
2023-09-15T18:37:22.3384768Z 
2023-09-15T18:37:22.3385009Z During handling of the above exception, another exception occurred:
2023-09-15T18:37:22.3385200Z 
2023-09-15T18:37:22.3385466Z Traceback (most recent call last):
2023-09-15T18:37:22.3385884Z   File "C:\Program Files\Common Files\AzureCliExtensionDirectory\azure-devops\azext_devops\dev\common\services.py", line 61, in _get_credentials
2023-09-15T18:37:22.3386261Z     token_from_az_login = get_token_from_az_logins(organization, pat_token_present)
2023-09-15T18:37:22.3386725Z   File "C:\Program Files\Common Files\AzureCliExtensionDirectory\azure-devops\azext_devops\dev\common\services.py", line 118, in get_token_from_az_logins
2023-09-15T18:37:22.3387095Z     dummy_user = profile.get_current_account_user()     # noqa: F841
2023-09-15T18:37:22.3387524Z   File "D:\a\_work\1\s\build_scripts\windows\artifacts\cli\Lib\site-packages\azure/cli/core/_profile.py", line 539, in get_current_account_user
2023-09-15T18:37:22.3387878Z knack.util.CLIError: There are no active accounts.
2023-09-15T18:37:22.3388195Z INFO: cli.azext_devops.dev.common.services: received PAT from environment variable
2023-09-15T18:37:22.3388587Z INFO: cli.azext_devops.dev.common.services: Creating connection with personal access token.

Issue script & Debug output

2023-09-15T18:37:12.7002991Z DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreCommandTableTruncate [<function AzCliLogging.init_command_file_logging at 0x0000025BD8AEC430>]
2023-09-15T18:37:12.7003914Z DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreArgumentLoad [<function register_global_subscription_argument.<locals>.add_subscription_parameter at 0x0000025BD8AEF0A0>]
2023-09-15T18:37:22.0011676Z DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostArgumentLoad []
2023-09-15T18:37:22.0012102Z DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostCommandTableCreate [<function register_ids_argument.<locals>.add_ids_arguments at 0x0000025BD8B51090>, <function register_cache_arguments.<locals>.add_cache_arguments at 0x0000025BD8B511B0>]
2023-09-15T18:37:22.0026227Z DEBUG: cli.knack.cli: Event: CommandInvoker.OnCommandTableLoaded []
2023-09-15T18:37:22.0026678Z DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreParseArgs []
2023-09-15T18:37:22.3327775Z DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostParseArgs [<function OutputProducer.handle_output_argument at 0x0000025BD63AFF40>, <function CLIQuery.handle_query_parameter at 0x0000025BD63F92D0>, <function register_ids_argument.<locals>.parse_ids_arguments at 0x0000025BD8B51120>, <function DevCommandsLoader.post_parse_args at 0x0000025BD8B72B90>]
2023-09-15T18:37:22.3348603Z DEBUG: cli.azext_devops.dev.common.services: PAT is present which can be used against this instance
2023-09-15T18:37:22.3375557Z DEBUG: cli.azure.cli.core: Current cloud config:
2023-09-15T18:37:22.3375819Z AzureCloud
2023-09-15T18:37:22.3376906Z DEBUG: cli.azext_devops.dev.common.services: az login is not present
2023-09-15T18:37:22.3382543Z DEBUG: cli.azext_devops.dev.common.services: There are no active accounts.
2023-09-15T18:37:22.3382797Z Traceback (most recent call last):
2023-09-15T18:37:22.3383541Z   File "D:\a\_work\1\s\build_scripts\windows\artifacts\cli\Lib\site-packages\azure/cli/core/_profile.py", line 537, in get_current_account_user
2023-09-15T18:37:22.3384147Z   File "D:\a\_work\1\s\build_scripts\windows\artifacts\cli\Lib\site-packages\azure/cli/core/_profile.py", line 546, in get_subscription
2023-09-15T18:37:22.3384535Z knack.util.CLIError: Please run 'az login' to setup account.
2023-09-15T18:37:22.3384768Z 
2023-09-15T18:37:22.3385009Z During handling of the above exception, another exception occurred:
2023-09-15T18:37:22.3385200Z 
2023-09-15T18:37:22.3385466Z Traceback (most recent call last):
2023-09-15T18:37:22.3385884Z   File "C:\Program Files\Common Files\AzureCliExtensionDirectory\azure-devops\azext_devops\dev\common\services.py", line 61, in _get_credentials
2023-09-15T18:37:22.3386261Z     token_from_az_login = get_token_from_az_logins(organization, pat_token_present)
2023-09-15T18:37:22.3386725Z   File "C:\Program Files\Common Files\AzureCliExtensionDirectory\azure-devops\azext_devops\dev\common\services.py", line 118, in get_token_from_az_logins
2023-09-15T18:37:22.3387095Z     dummy_user = profile.get_current_account_user()     # noqa: F841
2023-09-15T18:37:22.3387524Z   File "D:\a\_work\1\s\build_scripts\windows\artifacts\cli\Lib\site-packages\azure/cli/core/_profile.py", line 539, in get_current_account_user
2023-09-15T18:37:22.3387878Z knack.util.CLIError: There are no active accounts.
2023-09-15T18:37:22.3388195Z INFO: cli.azext_devops.dev.common.services: received PAT from environment variable
2023-09-15T18:37:22.3388587Z INFO: cli.azext_devops.dev.common.services: Creating connection with personal access token.

Expected behavior

Account info is only loaded when needed. Lack of account data doesn't result in a swallowed error.

Environment Summary

azure-cli 2.52.0

core 2.52.0
telemetry 1.1.0

Extensions:
azure-devops 0.26.0

Dependencies:
msal 1.24.0b1
azure-mgmt-resource 23.1.0b2

Python location 'C:\Program Files\Microsoft SDKs\Azure\CLI2\python.exe'
Extensions directory 'C:\Program Files\Common Files\AzureCliExtensionDirectory'

Python (Windows) 3.10.10 (tags/v3.10.10:aad5f6a, Feb 7 2023, 17:20:36) [MSC v.1929 64 bit (AMD64)]

Additional context

actions/runner-images#8294

[yonzhan]

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

[microsoft-github-policy-service]

Thanks for the feedback! We are routing this to the appropriate team for follow-up. cc @v-anvashist, @V-hmusukula.

[jessehouwing]

https://github.com/Azure/azure-devops-cli-extension/blob/bd34a6fd0658a15dadf6c09c7f6217ca5ffa662b/azure-devops/azext_devops/dev/common/services.py#L60

Is where the presence of the environment variable is detected, but the code proceeds to try az login anyway there is no code path that forces the use of the PAT token here.

[jessehouwing]

According to the docs here, this seems like the behavior is intended:

To gain access in a non-interactive manner for automation scenarios, you can use environment variables or fetch a PAT from a file.

If az login or az devops login haven't been used, all az devops commands try to sign in using a PAT stored in the AZURE_DEVOPS_EXT_PAT environment variable.

https://learn.microsoft.com/en-us/azure/devops/cli/log-in-via-pat?view=azure-devops&tabs=windows#use-the-azure_devops_ext_pat-environment-variable

If so, it's a very unfortunate choice for automation workflows.

[jessehouwing]

It would be nice to have a --use-token-from-environment like switch to just immediately jump to the codepath that uses the token supplied. Or something like --auth env or --auth auto.