az add extension --name certificate failure inconsistency (Windows)

[borjamunozf]

Describe the bug

Hello,

in my company we have been facing issues with some scripts that uses az add extension command to install azure-devops:

• it showed the already reported #17938 long standing issue

We included a bunch of workarounds & tests, seems that the only working approach was to disable AZURE_SSL_VERIFICATION (but this could trigger other issues).

However, today I realized that the issue was not all anything on the script, it's just the inconsistency of the own command:

• Fresh powershell terminal

• Run subsequent 10 times in a row the command (intervaled 5 secs - 45 secs depending if --debug option used& the installation is succesfull)

• The results of the command is sometimes 3 without ssl verification issue, 7 with them; others 9 out of 10 fails, 8/10 works & so on. Tested in 3 different machines in our company.

For info, we have Zscaler in the company, but setting HTTP_PROXY & HTTPS_PROXY makes no difference.

Related command

az add extension --name azure-devops

Errors

Unable to get extension index. Please ensure you have network connection. Error detail: HTTPSConnectionPool(host='aka.ms', port=443): Max retries exce eded with url: /azure-cli-extension-index-v1 (Caused by SSLError(SSLCertVerificationError(1, '[SSL: CERTIFICATEVERIFY FAILED] certificate verify failed: certificate signature failure (_ssl.c:1006)')))

Issue script & Debug output

Fail log:

az : DEBUG: cli.knack.cli: Command arguments: ['extension', 'add', '--name', 'azure-devops', '--debug']
At line:1 char:1
+ az extension add --name azure-devops --debug 2>&1 > .\add_extension2. ...
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (DEBUG: cli.knac...ps', '--debug']:String) [], RemoteException
    + FullyQualifiedErrorId : NativeCommandError

DEBUG: cli.knack.cli: __init__ debug log:
Cannot enable color.
DEBUG: cli.knack.cli: Event: Cli.PreExecute []
DEBUG: cli.knack.cli: Event: CommandParser.OnGlobalArgumentsCreate [<function CLILogging.on_global_arguments at 0x00000
1DA67776FC0>, <function OutputProducer.on_global_arguments at 0x000001DA6789C900>, <function CLIQuery.on_global_argumen
ts at 0x000001DA678C6520>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreCommandTableCreate []
DEBUG: cli.azure.cli.core: Modules found from index for 'extension': ['azure.cli.command_modules.extension']
DEBUG: cli.azure.cli.core: Loading command modules:
DEBUG: cli.azure.cli.core: Name                  Load Time    Groups  Commands
DEBUG: cli.azure.cli.core: extension                 0.004         1         7
DEBUG: cli.azure.cli.core: Total (1)                 0.004         1         7
DEBUG: cli.azure.cli.core: These extensions are not installed and will be skipped: ['azext_ai_examples', 'azext_next']
DEBUG: cli.azure.cli.core: Loading extensions:
DEBUG: cli.azure.cli.core: Name                  Load Time    Groups  Commands  Directory
DEBUG: cli.azure.cli.core: Total (0)                 0.000         0         0  
DEBUG: cli.azure.cli.core: Loaded 1 groups, 7 commands.
DEBUG: cli.azure.cli.core: Found a match in the command table.
DEBUG: cli.azure.cli.core: Raw command  : extension add
DEBUG: cli.azure.cli.core: Command table: extension add
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreCommandTableTruncate [<function AzCliLogging.init_command_file_logging
 at 0x000001DA695C5440>]
DEBUG: cli.azure.cli.core.azlogging: metadata file logging enabled - writing logs to 'C:\UsersUser\.azure\commands\
2024-02-16.12-18-50.extension_add.24048.log'.
INFO: az_command_data_logger: command args: extension add --name {} --debug
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreArgumentLoad [<function register_global_subscription_argument.<locals>
.add_subscription_parameter at 0x000001DA695FCC20>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostArgumentLoad []
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostCommandTableCreate [<function register_ids_argument.<locals>.add_ids_
arguments at 0x000001DA695FF880>, <function register_cache_arguments.<locals>.add_cache_arguments at 0x000001DA695FF9C0
>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnCommandTableLoaded []
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreParseArgs []
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostParseArgs [<function OutputProducer.handle_output_argument at 0x00000
1DA6789C9A0>, <function CLIQuery.handle_query_parameter at 0x000001DA678C65C0>, <function register_ids_argument.<locals
>.parse_ids_arguments at 0x000001DA695FF920>]
DEBUG: urllib3.connectionpool: Starting new HTTPS connection (1): aka.ms:443
DEBUG: urllib3.connectionpool: Starting new HTTPS connection (1): aka.ms:443
DEBUG: urllib3.connectionpool: Starting new HTTPS connection (1): aka.ms:443
DEBUG: cli.azure.cli.core.azclierror: Traceback (most recent call last):
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\urllib3\connectionpool.py", line 467
, in _make_request
    self._validate_conn(conn)
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\urllib3\connectionpool.py", line 109
6, in _validate_conn
    conn.connect()
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\urllib3\connection.py", line 642, in
 connect
    sock_and_verified = _ssl_wrap_socket_and_match_hostname(
                        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\urllib3\connection.py", line 782, in
 _ssl_wrap_socket_and_match_hostname
    ssl_sock = ssl_wrap_socket(
               ^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\urllib3\util\ssl_.py", line 470, in 
ssl_wrap_socket
    ssl_sock = _ssl_wrap_socket_impl(sock, context, tls_in_tls, server_hostname)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\urllib3\util\ssl_.py", line 514, in 
_ssl_wrap_socket_impl
    return ssl_context.wrap_socket(sock, server_hostname=server_hostname)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\ssl.py", line 517, in wrap_socket
    return self.sslsocket_class._create(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\ssl.py", line 1108, in _create
    self.do_handshake()
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\ssl.py", line 1379, in do_handshake
    self._sslobj.do_handshake()
ssl.SSLCertVerificationError: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed: certificate signature failure
 (_ssl.c:1006)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\urllib3\connectionpool.py", line 790
, in urlopen
    response = self._make_request(
               ^^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\urllib3\connectionpool.py", line 491
, in _make_request
    raise new_e
urllib3.exceptions.SSLError: [SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed: certificate signature failure 
(_ssl.c:1006)

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\requests\adapters.py", line 486, in 
send
    resp = conn.urlopen(
           ^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\urllib3\connectionpool.py", line 844
, in urlopen
    retries = retries.increment(
              ^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\urllib3\util\retry.py", line 515, in
 increment
    raise MaxRetryError(_pool, url, reason) from reason  # type: ignore[arg-type]
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
urllib3.exceptions.MaxRetryError: HTTPSConnectionPool(host='aka.ms', port=443): Max retries exceeded with url: /azure-c
li-extension-index-v1 (Caused by SSLError(SSLCertVerificationError(1, '[SSL: CERTIFICATE_VERIFY_FAILED] certificate ver
ify failed: certificate signature failure (_ssl.c:1006)')))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\azure\cli\core\extension\_index.py",
 line 47, in get_index
    response = requests.get(index_url, verify=(not should_disable_connection_verify()))
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\requests\api.py", line 73, in get
    return request("get", url, params=params, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\requests\api.py", line 59, in reques
t
    return session.request(method=method, url=url, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\requests\sessions.py", line 589, in 
request
    resp = self.send(prep, **send_kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\requests\sessions.py", line 703, in 
send
    r = adapter.send(request, **kwargs)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\requests\adapters.py", line 517, in 
send
    raise SSLError(e, request=request)
requests.exceptions.SSLError: HTTPSConnectionPool(host='aka.ms', port=443): Max retries exceeded with url: /azure-cli-e
xtension-index-v1 (Caused by SSLError(SSLCertVerificationError(1, '[SSL: CERTIFICATE_VERIFY_FAILED] certificate verify 
failed: certificate signature failure (_ssl.c:1006)')))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\knack\cli.py", line 233, in invoke
    cmd_result = self.invocation.execute(args)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\azure\cli\core\commands\__init__.py"
, line 663, in execute
    raise ex
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\azure\cli\core\commands\__init__.py"
, line 726, in _run_jobs_serially
    results.append(self._run_job(expanded_arg, cmd_copy))
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\azure\cli\core\commands\__init__.py"
, line 697, in _run_job
    result = cmd_copy(params)
             ^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\azure\cli\core\commands\__init__.py"
, line 333, in __call__
    return self.handler(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\azure\cli\core\commands\command_oper
ation.py", line 121, in handler
    return op(**command_args)
           ^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\azure\cli\command_modules\extension\
custom.py", line 16, in add_extension_cmd
    return add_extension(cli_ctx=cmd.cli_ctx, source=source, extension_name=extension_name, index_url=index_url,
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\azure\cli\core\extension\operations.
py", line 318, in add_extension
    source, ext_sha256 = resolve_from_index(extension_name, index_url=index_url, target_version=version, cli_ctx=cmd_cl
i_ctx)
                         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\azure\cli\core\extension\_resolve.py
", line 100, in resolve_from_index
    candidates = get_index_extensions(index_url=index_url, cli_ctx=cli_ctx).get(extension_name, [])
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\azure\cli\core\extension\_index.py",
 line 64, in get_index_extensions
    index = get_index(index_url=index_url, cli_ctx=cli_ctx)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\azure\cli\core\extension\_index.py",
 line 57, in get_index
    raise CLIError(msg)
knack.util.CLIError: Unable to get extension index.
Please ensure you have network connection. Error detail: HTTPSConnectionPool(host='aka.ms', port=443): Max retries exce
eded with url: /azure-cli-extension-index-v1 (Caused by SSLError(SSLCertVerificationError(1, '[SSL: CERTIFICATE_VERIFY_
FAILED] certificate verify failed: certificate signature failure (_ssl.c:1006)')))

ERROR: cli.azure.cli.core.azclierror: Unable to get extension index.
Please ensure you have network connection. Error detail: HTTPSConnectionPool(host='aka.ms', port=443): Max retries exce
eded with url: /azure-cli-extension-index-v1 (Caused by SSLError(SSLCertVerificationError(1, '[SSL: CERTIFICATE_VERIFY_
FAILED] certificate verify failed: certificate signature failure (_ssl.c:1006)')))
ERROR: az_command_data_logger: Unable to get extension index.
Please ensure you have network connection. Error detail: HTTPSConnectionPool(host='aka.ms', port=443): Max retries exce
eded with url: /azure-cli-extension-index-v1 (Caused by SSLError(SSLCertVerificationError(1, '[SSL: CERTIFICATE_VERIFY_
FAILED] certificate verify failed: certificate signature failure (_ssl.c:1006)')))
DEBUG: cli.knack.cli: Event: Cli.PostExecute [<function AzCliLogging.deinit_cmd_metadata_logging at 0x000001DA695C56C0>
]
INFO: az_command_data_logger: exit code: 1
INFO: cli.__main__: Command ran in 3.176 seconds (init: 1.130, invoke: 2.046)
INFO: telemetry.main: Begin splitting cli events and extra events, total events: 1
INFO: telemetry.client: Accumulated 0 events. Flush the clients.
INFO: telemetry.main: Finish splitting cli events and extra events, cli events: 1
INFO: telemetry.save: Save telemetry record of length 3737 in cache
INFO: telemetry.main: Begin creating telemetry upload process.
INFO: telemetry.process: Creating upload process: "C:\UsersUser\AppData\Local\Programs\Python\Python311\python.exe 
C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\azure\cli\telemetry\__init__.py C:\Users\SFD
XJAY\.azure"
INFO: telemetry.process: Return from creating process
INFO: telemetry.main: Finish creating telemetry upload process.

OK Log:

az : DEBUG: cli.knack.cli: Command arguments: ['extension', 'add', '--name', 'azure-devops', '--debug']
At line:1 char:1
+ az extension add --name azure-devops --debug 2>&1 > .\add_extension.l ...
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (DEBUG: cli.knac...ps', '--debug']:String) [], RemoteException
    + FullyQualifiedErrorId : NativeCommandError

DEBUG: cli.knack.cli: __init__ debug log:
Cannot enable color.
DEBUG: cli.knack.cli: Event: Cli.PreExecute []
DEBUG: cli.knack.cli: Event: CommandParser.OnGlobalArgumentsCreate [<function CLILogging.on_global_arguments at 0x00000
166EAED6FC0>, <function OutputProducer.on_global_arguments at 0x00000166EAFFC900>, <function CLIQuery.on_global_argumen
ts at 0x00000166EB026520>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreCommandTableCreate []
DEBUG: cli.azure.cli.core: Command index version or cloud profile is invalid or doesn't match the current command.
DEBUG: cli.azure.cli.core: Command index has been invalidated.
DEBUG: cli.azure.cli.core: No module found from index for '['extension', 'add', '--name', 'azure-devops', '--debug']'
DEBUG: cli.azure.cli.core: Loading all modules and extensions
DEBUG: cli.azure.cli.core: Discovered command modules: ['acr', 'acs', 'advisor', 'ams', 'apim', 'appconfig', 'appservic
e', 'aro', 'backup', 'batch', 'batchai', 'billing', 'botservice', 'cdn', 'cloud', 'cognitiveservices', 'config', 'confi
gure', 'consumption', 'container', 'containerapp', 'cosmosdb', 'databoxedge', 'dla', 'dls', 'dms', 'eventgrid', 'eventh
ubs', 'extension', 'feedback', 'find', 'hdinsight', 'identity', 'interactive', 'iot', 'keyvault', 'kusto', 'lab', 'mana
gedservices', 'maps', 'marketplaceordering', 'monitor', 'mysql', 'netappfiles', 'network', 'policyinsights', 'privatedn
s', 'profile', 'rdbms', 'redis', 'relay', 'resource', 'role', 'search', 'security', 'servicebus', 'serviceconnector', '
servicefabric', 'signalr', 'sql', 'sqlvm', 'storage', 'synapse', 'util', 'vm']
DEBUG: cli.azure.cli.core: Loading command modules:
DEBUG: cli.azure.cli.core: Name                  Load Time    Groups  Commands
DEBUG: cli.azure.cli.core: acr                       0.218        36       149
DEBUG: cli.azure.cli.core: acs                       0.040         7        54
DEBUG: cli.azure.cli.core: advisor                   0.003         3         6
DEBUG: cli.azure.cli.core: ams                       0.007        22       100
DEBUG: cli.azure.cli.core: apim                      0.010        14        68
DEBUG: cli.azure.cli.core: appconfig                 0.005         9        47
DEBUG: cli.azure.cli.core: appservice                0.122        73       260
DEBUG: cli.azure.cli.core: aro                       0.023         1        10
DEBUG: cli.azure.cli.core: backup                    0.009        16        60
DEBUG: cli.azure.cli.core: batch                     0.050        34       102
DEBUG: cli.azure.cli.core: batchai                   0.005        10        30
DEBUG: cli.azure.cli.core: billing                   0.014        19        52
DEBUG: cli.azure.cli.core: botservice                0.006        12        42
DEBUG: cli.azure.cli.core: cdn                       0.007        39       133
DEBUG: cli.azure.cli.core: cloud                     0.004         1         7
DEBUG: cli.azure.cli.core: cognitiveservices         0.004        10        33
DEBUG: cli.azure.cli.core: config                    0.004         2         7
DEBUG: cli.azure.cli.core: configure                 0.003         2         5
DEBUG: cli.azure.cli.core: consumption               0.036         8         9
DEBUG: cli.azure.cli.core: container                 0.019         1        11
DEBUG: cli.azure.cli.core: containerapp              0.215        36       115
DEBUG: cli.azure.cli.core: cosmosdb                  0.021        58       192
DEBUG: cli.azure.cli.core: databoxedge               0.011         5        27
DEBUG: cli.azure.cli.core: dla                       0.006        23        62
DEBUG: cli.azure.cli.core: dls                       0.006         7        41
DEBUG: cli.azure.cli.core: dms                       0.004         3        22
DEBUG: cli.azure.cli.core: eventgrid                 0.006        25        96
DEBUG: cli.azure.cli.core: eventhubs                 0.025        13        19
DEBUG: cli.azure.cli.core: extension                 0.002         1         7
DEBUG: cli.azure.cli.core: feedback                  0.002         1         2
DEBUG: cli.azure.cli.core: find                      0.003         1         1
DEBUG: cli.azure.cli.core: hdinsight                 0.013         8        39
DEBUG: cli.azure.cli.core: identity                  0.004         2        11
DEBUG: cli.azure.cli.core: interactive               0.001         1         1
DEBUG: cli.azure.cli.core: iot                       0.191        19        82
DEBUG: cli.azure.cli.core: keyvault                  0.010        20       113
DEBUG: cli.azure.cli.core: kusto                     0.004         3        14
DEBUG: cli.azure.cli.core: lab                       0.006        11        34
DEBUG: cli.azure.cli.core: managedservices           0.003         3         8
DEBUG: cli.azure.cli.core: maps                      0.003         5        13
DEBUG: cli.azure.cli.core: marketplaceordering       0.007         1         2
DEBUG: cli.azure.cli.core: monitor                   0.906        18        61
DEBUG: cli.azure.cli.core: mysql                     0.146        14        49
DEBUG: cli.azure.cli.core: netappfiles               0.009        17        96
DEBUG: cli.azure.cli.core: network                   0.240       103       337
DEBUG: cli.azure.cli.core: policyinsights            0.026         9        17
DEBUG: cli.azure.cli.core: privatedns                0.039        14        60
DEBUG: cli.azure.cli.core: profile                   0.004         2         8
DEBUG: cli.azure.cli.core: rdbms                     0.127        44       185
DEBUG: cli.azure.cli.core: redis                     0.004         5        27
DEBUG: cli.azure.cli.core: relay                     0.046         7         8
DEBUG: cli.azure.cli.core: resource                  0.019        51       228
DEBUG: cli.azure.cli.core: role                      0.003        17        61
DEBUG: cli.azure.cli.core: search                    0.015         7        19
DEBUG: cli.azure.cli.core: security                  0.006        48       104
DEBUG: cli.azure.cli.core: servicebus                0.017        12        15
DEBUG: cli.azure.cli.core: serviceconnector          0.080        16       235
DEBUG: cli.azure.cli.core: servicefabric             0.025        27        76
DEBUG: cli.azure.cli.core: signalr                   0.004         9        34
DEBUG: cli.azure.cli.core: sql                       0.019        56       215
DEBUG: cli.azure.cli.core: sqlvm                     0.038         4        20
DEBUG: cli.azure.cli.core: storage                   0.051        59       273
DEBUG: cli.azure.cli.core: synapse                   0.016        54       246
DEBUG: cli.azure.cli.core: util                      0.003         3         7
DEBUG: cli.azure.cli.core: vm                        0.101        57       230
DEBUG: cli.azure.cli.core: Total (65)                3.074      1218      4697
DEBUG: cli.azure.cli.core: Loading extensions:
DEBUG: cli.azure.cli.core: Name                  Load Time    Groups  Commands  Directory
DEBUG: cli.azure.cli.core: azure-devops              0.036        60       192  C:\UsersUser\.azure\cliextensions\a
zure-devops
DEBUG: cli.azure.cli.core: Total (1)                 0.036        60       192  
DEBUG: cli.azure.cli.core: Loaded 1265 groups, 4889 commands.
DEBUG: cli.azure.cli.core: Updated command index in 0.008 seconds.
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreCommandTableTruncate [<function AzCliLogging.init_command_file_logging
 at 0x00000166ECD15440>]
DEBUG: cli.azure.cli.core.azlogging: metadata file logging enabled - writing logs to 'C:\UsersUser\.azure\commands\
2024-02-16.12-18-07.extension_add.940.log'.
INFO: az_command_data_logger: command args: extension add --name {} --debug
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreArgumentLoad [<function register_global_subscription_argument.<locals>
.add_subscription_parameter at 0x00000166ECD4CC20>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostArgumentLoad []
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostCommandTableCreate [<function register_ids_argument.<locals>.add_ids_
arguments at 0x00000166ECD4F880>, <function register_cache_arguments.<locals>.add_cache_arguments at 0x00000166ECD4F9C0
>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnCommandTableLoaded []
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreParseArgs [<function _documentdb_deprecate at 0x00000166EF162C00>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostParseArgs [<function OutputProducer.handle_output_argument at 0x00000
166EAFFC9A0>, <function CLIQuery.handle_query_parameter at 0x00000166EB0265C0>, <function register_ids_argument.<locals
>.parse_ids_arguments at 0x00000166ECD4F920>, <function DevCommandsLoader.post_parse_args at 0x00000166F53A6200>]
DEBUG: urllib3.connectionpool: Starting new HTTPS connection (1): aka.ms:443
DEBUG: urllib3.connectionpool: https://aka.ms:443 "GET /azure-cli-extension-index-v1 HTTP/1.1" 301 0
DEBUG: urllib3.connectionpool: Starting new HTTPS connection (1): azcliextensionsync.blob.core.windows.net:443
DEBUG: urllib3.connectionpool: https://azcliextensionsync.blob.core.windows.net:443 "GET /index1/index.json HTTP/1.1" 2
00 3681515
DEBUG: cli.azure.cli.core.extension._resolve: Candidates ['azure_devops-0.12.0-py2.py3-none-any.whl', 'azure_devops-0.1
7.0-py2.py3-none-any.whl', 'azure_devops-0.21.0-py2.py3-none-any.whl', 'azure_devops-0.26.0-py2.py3-none-any.whl']
DEBUG: cli.azure.cli.core.extension._resolve: Candidates ['azure_devops-0.12.0-py2.py3-none-any.whl', 'azure_devops-0.1
7.0-py2.py3-none-any.whl', 'azure_devops-0.21.0-py2.py3-none-any.whl', 'azure_devops-0.26.0-py2.py3-none-any.whl']
DEBUG: cli.azure.cli.core.extension._resolve: Candidates ['azure_devops-0.12.0-py2.py3-none-any.whl', 'azure_devops-0.1
7.0-py2.py3-none-any.whl', 'azure_devops-0.21.0-py2.py3-none-any.whl', 'azure_devops-0.26.0-py2.py3-none-any.whl']
DEBUG: cli.azure.cli.core.extension._resolve: Candidates ['azure_devops-0.12.0-py2.py3-none-any.whl', 'azure_devops-0.1
7.0-py2.py3-none-any.whl', 'azure_devops-0.21.0-py2.py3-none-any.whl', 'azure_devops-0.26.0-py2.py3-none-any.whl']
DEBUG: cli.azure.cli.core.extension._resolve: Chosen {'downloadUrl': 'https://github.com/Azure/azure-devops-cli-extensi
on/releases/download/20230127.2/azure_devops-0.26.0-py2.py3-none-any.whl', 'filename': 'azure_devops-0.26.0-py2.py3-non
e-any.whl', 'metadata': {'azext.minCliCoreVersion': '2.30.0', 'classifiers': ['Development Status :: 4 - Beta', 'Intend
ed Audience :: Developers', 'Intended Audience :: System Administrators', 'Programming Language :: Python', 'Programmin
g Language :: Python :: 3', 'Programming Language :: Python :: 3.4', 'Programming Language :: Python :: 3.5', 'Programm
ing Language :: Python :: 3.6', 'License :: OSI Approved :: MIT License'], 'extensions': {'python.details': {'contacts'
: [{'email': 'VSTS_Social@microsoft.com', 'name': 'Microsoft', 'role': 'author'}], 'document_names': {'description': 'D
ESCRIPTION.rst'}, 'project_urls': {'Home': 'https://github.com/Microsoft/azure-devops-cli-extension'}}}, 'extras': [], 
'generator': 'bdist_wheel (0.30.0)', 'license': 'MIT', 'metadata_version': '2.0', 'name': 'azure-devops', 'run_requires
': [{'requires': ['distro (==1.3.0)']}], 'summary': 'Tools for managing Azure DevOps.', 'version': '0.26.0'}, 'sha256Di
gest': '565fc207f1740c26957f382fe2eefabec254011fb2d1b50c0e540f894f47dcbe'}
WARNING: cli.azure.cli.core.extension.operations: Extension 'azure-devops' 0.26.0 is already installed.
DEBUG: cli.knack.cli: Event: CommandInvoker.OnTransformResult [<function _resource_group_transform at 0x00000166ECD4C90
0>, <function _x509_from_base64_to_hex_transform at 0x00000166ECD4C9A0>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnFilterResult []
DEBUG: cli.knack.cli: Event: Cli.SuccessfulExecute []
DEBUG: cli.knack.cli: Event: Cli.PostExecute [<function AzCliLogging.deinit_cmd_metadata_logging at 0x00000166ECD156C0>
]
INFO: az_command_data_logger: exit code: 0
INFO: cli.__main__: Command ran in 8.769 seconds (init: 1.038, invoke: 7.731)
INFO: telemetry.main: Begin splitting cli events and extra events, total events: 1
INFO: telemetry.client: Accumulated 0 events. Flush the clients.
INFO: telemetry.main: Finish splitting cli events and extra events, cli events: 1
INFO: telemetry.save: Save telemetry record of length 3397 in cache
INFO: telemetry.main: Begin creating telemetry upload process.
INFO: telemetry.process: Creating upload process: "C:\UsersUser\AppData\Local\Programs\Python\Python311\python.exe 
C:\UsersUser\AppData\Local\Programs\Python\Python311\Lib\site-packages\azure\cli\telemetry\__init__.py C:\Users\SFD
XJAY\.azure"
INFO: telemetry.process: Return from creating process
INFO: telemetry.main: Finish creating telemetry upload process.

Differences of seconds between executions.

Expected behavior

az add extension --name azure-devops works consistently.

Environment Summary

Tested with azure-cli 2.54, 2.56 & 2.57 and different Python versions (3.10, 3.9, 3.11.5, 3.11.8)

azure-cli 2.57.0

core 2.57.0 telemetry 1.1.0

Extensions: azure-devops 0.26.0

Dependencies: msal 1.26.0 azure-mgmt-resource 23.1.0b2

Python location 'C:\Users\User\AppData\Local\Programs\Python\Python311\python.exe' Extensions directory 'C:\Users\User.azure\cliextensions'

Python (Windows) 3.11.5 (tags/v3.11.5:cce6ba9, Aug 24 2023, 14:38:34) [MSC v.1936 64 bit (AMD64)]

Legal docs and information: aka.ms/AzureCliLegal

Your CLI is up-to-date.

Additional context

No response

[yonzhan]

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

[microsoft-github-policy-service[bot]]

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