Ubuntu 2.66.0-1~focal fails to upgrade, ModuleNotFoundError

[kevball2]

Describe the bug

Updates for the AZ Cli started failing to for our GitLab runners. This was working last week for existing pipelines.

Related command

az upgrade --yes

Errors

Pipeline Errors

The following packages will be upgraded:
  azure-cli
1 upgraded, 0 newly installed, 0 to remove and 78 not upgraded.
Need to get 53.4 MB of archives.
After this operation, 116 MB disk space will be freed.
Get:1 https://packages.microsoft.com/repos/azure-cli focal/main amd64 azure-cli amd64 2.66.0-1~focal [53.4 MB]
debconf: delaying package configuration, since apt-utils is not installed
Fetched 53.4 MB in 14s (3888 kB/s)
(Reading database ... 61439 files and directories currently installed.)
Preparing to unpack .../azure-cli_2.66.0-1~focal_amd64.deb ...
Unpacking azure-cli (2.66.0-1~focal) over (2.54.0-1~focal) ...
Setting up azure-cli (2.66.0-1~focal) ...
Traceback (most recent call last):
  File "/opt/az/lib/python3.11/site-packages/knack/cli.py", line 233, in invoke
  File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/__init__.py", line 663, in execute
  File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/__init__.py", line 726, in _run_jobs_serially
  File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/__init__.py", line 697, in _run_job
  File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/__init__.py", line 333, in __call__
  File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/command_operation.py", line 121, in handler
  File "/opt/az/lib/python3.11/site-packages/azure/cli/command_modules/util/custom.py", line 156, in upgrade_version
  File "/opt/az/lib/python3.11/importlib/__init__.py", line 168, in reload
ModuleNotFoundError: spec not found for the module 'subprocess'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "<frozen runpy>", line 198, in _run_module_as_main
  File "<frozen runpy>", line 88, in _run_code
  File "/opt/az/lib/python3.11/site-packages/azure/cli/__main__.py", line 50, in <module>
  File "/opt/az/lib/python3.11/site-packages/azure/cli/__main__.py", line 36, in cli_main
  File "/opt/az/lib/python3.11/site-packages/knack/cli.py", line 245, in invoke
  File "/opt/az/lib/python3.11/site-packages/azure/cli/core/__init__.py", line 127, in exception_handler
  File "/opt/az/lib/python3.11/site-packages/azure/cli/core/util.py", line 61, in handle_exception
ModuleNotFoundError: No module named 'azure.common'

Issue script & Debug output

Get:1 http://security.ubuntu.com/ubuntu focal-security InRelease [128 kB]
Hit:2 http://archive.ubuntu.com/ubuntu focal InRelease
Get:3 http://archive.ubuntu.com/ubuntu focal-updates InRelease [128 kB]
Get:4 http://archive.ubuntu.com/ubuntu focal-backports InRelease [128 kB]
Get:5 http://security.ubuntu.com/ubuntu focal-security/universe amd64 Packages [1276 kB]
Get:6 https://packages.microsoft.com/repos/azure-cli focal InRelease [3596 B]
Get:7 https://packages.microsoft.com/ubuntu/20.04/prod focal InRelease [3632 B]
Get:8 http://archive.ubuntu.com/ubuntu focal-updates/universe amd64 Packages [1566 kB]
Get:9 https://packages.microsoft.com/repos/azure-cli focal/main amd64 Packages [1889 B]
Get:10 https://packages.microsoft.com/repos/azure-cli focal/main all Packages [4103 B]
Get:11 https://packages.microsoft.com/ubuntu/20.04/prod focal/main armhf Packages [23.0 kB]
Get:12 http://security.ubuntu.com/ubuntu focal-security/restricted amd64 Packages [4137 kB]
Get:13 https://packages.microsoft.com/ubuntu/20.04/prod focal/main arm64 Packages [68.3 kB]
Get:14 https://packages.microsoft.com/ubuntu/20.04/prod focal/main all Packages [2938 B]
Get:15 https://packages.microsoft.com/ubuntu/20.04/prod focal/main amd64 Packages [319 kB]
Get:16 http://security.ubuntu.com/ubuntu focal-security/main amd64 Packages [4107 kB]
Get:17 http://archive.ubuntu.com/ubuntu focal-updates/restricted amd64 Packages [4289 kB]
Get:18 http://archive.ubuntu.com/ubuntu focal-updates/multiverse amd64 Packages [33.5 kB]
Get:19 http://archive.ubuntu.com/ubuntu focal-updates/main amd64 Packages [4570 kB]
Get:20 http://security.ubuntu.com/ubuntu focal-security/multiverse amd64 Packages [30.9 kB]
Fetched 20.8 MB in 5s (3812 kB/s)
Reading package lists...
DEBUG: cli.knack.cli: Command arguments: ['upgrade', '--yes', '--debug']
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 0x7fc777ee93a0>, <function OutputProducer.on_global_arguments at 0x7fc777e89da0>, <function CLIQuery.on_global_arguments at 0x7fc777ec3880>]
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 '['upgrade', '--yes', '--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', 'appservice', 'aro', 'backup', 'batch', 'batchai', 'billing', 'botservice', 'cdn', 'cloud', 'cognitiveservices', 'config', 'configure', 'consumption', 'container', 'containerapp', 'cosmosdb', 'databoxedge', 'dla', 'dls', 'dms', 'eventgrid', 'eventhubs', 'extension', 'feedback', 'find', 'hdinsight', 'identity', 'interactive', 'iot', 'keyvault', 'kusto', 'lab', 'managedservices', 'maps', 'marketplaceordering', 'monitor', 'mysql', 'netappfiles', 'network', 'policyinsights', 'privatedns', '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.048 36 149
DEBUG: cli.azure.cli.core: acs 0.015 7 54
DEBUG: cli.azure.cli.core: advisor 0.001 3 6
DEBUG: cli.azure.cli.core: ams 0.004 22 100
DEBUG: cli.azure.cli.core: apim 0.004 14 68
DEBUG: cli.azure.cli.core: appconfig 0.002 9 47
DEBUG: cli.azure.cli.core: appservice 0.051 73 260
DEBUG: cli.azure.cli.core: aro 0.008 1 10
DEBUG: cli.azure.cli.core: backup 0.003 16 60
DEBUG: cli.azure.cli.core: batch 0.020 34 102
DEBUG: cli.azure.cli.core: batchai 0.002 10 30
DEBUG: cli.azure.cli.core: billing 0.005 19 52
DEBUG: cli.azure.cli.core: botservice 0.002 12 42
DEBUG: cli.azure.cli.core: cdn 0.004 39 133
DEBUG: cli.azure.cli.core: cloud 0.001 1 7
DEBUG: cli.azure.cli.core: cognitiveservices 0.002 10 33
DEBUG: cli.azure.cli.core: config 0.001 2 7
DEBUG: cli.azure.cli.core: configure 0.001 2 5
DEBUG: cli.azure.cli.core: consumption 0.013 8 9
DEBUG: cli.azure.cli.core: container 0.006 1 11
DEBUG: cli.azure.cli.core: containerapp 0.074 36 115
DEBUG: cli.azure.cli.core: cosmosdb 0.010 58 192
DEBUG: cli.azure.cli.core: databoxedge 0.003 5 27
DEBUG: cli.azure.cli.core: dla 0.003 23 62
DEBUG: cli.azure.cli.core: dls 0.003 7 41
DEBUG: cli.azure.cli.core: dms 0.002 3 22
DEBUG: cli.azure.cli.core: eventgrid 0.003 25 96
DEBUG: cli.azure.cli.core: eventhubs 0.009 13 19
DEBUG: cli.azure.cli.core: extension 0.001 1 7
DEBUG: cli.azure.cli.core: feedback 0.001 1 2
DEBUG: cli.azure.cli.core: find 0.001 1 1
DEBUG: cli.azure.cli.core: hdinsight 0.004 8 39
DEBUG: cli.azure.cli.core: identity 0.002 2 11
DEBUG: cli.azure.cli.core: interactive 0.000 1 1
DEBUG: cli.azure.cli.core: iot 0.059 19 82
DEBUG: cli.azure.cli.core: keyvault 0.006 20 113
DEBUG: cli.azure.cli.core: kusto 0.001 3 14
DEBUG: cli.azure.cli.core: lab 0.003 11 34
DEBUG: cli.azure.cli.core: managedservices 0.001 3 8
DEBUG: cli.azure.cli.core: maps 0.001 5 13
DEBUG: cli.azure.cli.core: marketplaceordering 0.002 1 2
DEBUG: cli.azure.cli.core: monitor 0.340 18 61
DEBUG: cli.azure.cli.core: mysql 0.102 14 49
DEBUG: cli.azure.cli.core: netappfiles 0.004 17 96
DEBUG: cli.azure.cli.core: network 0.096 103 337
DEBUG: cli.azure.cli.core: policyinsights 0.009 9 17
DEBUG: cli.azure.cli.core: privatedns 0.014 14 60
DEBUG: cli.azure.cli.core: profile 0.001 2 8
DEBUG: cli.azure.cli.core: rdbms 0.015 44 185
DEBUG: cli.azure.cli.core: redis 0.002 5 27
DEBUG: cli.azure.cli.core: relay 0.017 7 8
DEBUG: cli.azure.cli.core: resource 0.010 51 228
DEBUG: cli.azure.cli.core: role 0.002 17 61
DEBUG: cli.azure.cli.core: search 0.005 7 19
DEBUG: cli.azure.cli.core: security 0.004 48 104
DEBUG: cli.azure.cli.core: servicebus 0.006 12 15
DEBUG: cli.azure.cli.core: serviceconnector 0.013 16 235
DEBUG: cli.azure.cli.core: servicefabric 0.010 27 76
DEBUG: cli.azure.cli.core: signalr 0.002 9 34
DEBUG: cli.azure.cli.core: sql 0.010 56 215
DEBUG: cli.azure.cli.core: sqlvm 0.016 4 20
DEBUG: cli.azure.cli.core: storage 0.084 59 273
DEBUG: cli.azure.cli.core: synapse 0.010 54 246
DEBUG: cli.azure.cli.core: util 0.001 3 7
DEBUG: cli.azure.cli.core: vm 0.043 57 230
DEBUG: cli.azure.cli.core: Total (65) 1.199 1218 4697
DEBUG: cli.azure.cli.core: Loaded 1205 groups, 4697 commands.
DEBUG: cli.azure.cli.core: Updated command index in 0.004 seconds.
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreCommandTableTruncate [<function AzCliLogging.init_command_file_logging at 0x7fc77717c2c0>]
DEBUG: cli.azure.cli.core.azlogging: metadata file logging enabled - writing logs to '/root/.azure/commands/2024-11-11.18-45-03.upgrade.357.log'.
INFO: az_command_data_logger: command args: upgrade --yes --debug
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreArgumentLoad [<function register_global_subscription_argument..add_subscription_parameter at 0x7fc776d3b600>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostArgumentLoad []
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostCommandTableCreate [<function register_ids_argument..add_ids_arguments at 0x7fc776d3b6a0>, <function register_cache_arguments..add_cache_arguments at 0x7fc776d3b7e0>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnCommandTableLoaded []
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreParseArgs [<function _documentdb_deprecate at 0x7fc775b01c60>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostParseArgs [<function OutputProducer.handle_output_argument at 0x7fc777e89e40>, <function CLIQuery.handle_query_parameter at 0x7fc777ec3920>, <function register_ids_argument..parse_ids_arguments at 0x7fc776d3b740>]
WARNING: This command is in preview and under development. Reference and support levels: https://aka.ms/CLI_refstatus
DEBUG: urllib3.connectionpool: Starting new HTTPS connection (1): raw.githubusercontent.com:443
DEBUG: urllib3.connectionpool: https://raw.githubusercontent.com:443 "GET /Azure/azure-cli/main/src/azure-cli/setup.py HTTP/1.1" 200 2529
WARNING: cli.azure.cli.command_modules.util.custom: Your current Azure CLI version is 2.54.0. It will be updated to 2.66.0.
Hit:1 https://packages.microsoft.com/repos/azure-cli focal InRelease
Hit:2 http://archive.ubuntu.com/ubuntu focal InRelease
Hit:3 http://security.ubuntu.com/ubuntu focal-security InRelease
Hit:4 https://packages.microsoft.com/ubuntu/20.04/prod focal InRelease
Hit:5 http://archive.ubuntu.com/ubuntu focal-updates InRelease
Hit:6 http://archive.ubuntu.com/ubuntu focal-backports InRelease
Reading package lists...
DEBUG: cli.azure.cli.command_modules.util.custom: Update azure cli with 'apt-get install --only-upgrade -y azure-cli'
Reading package lists...
Building dependency tree...
Reading state information...
The following packages will be upgraded:
azure-cli
1 upgraded, 0 newly installed, 0 to remove and 78 not upgraded.
Need to get 53.4 MB of archives.
After this operation, 116 MB disk space will be freed.
Get:1 https://packages.microsoft.com/repos/azure-cli focal/main amd64 azure-cli amd64 2.66.0-1focal [53.4 MB]
debconf: delaying package configuration, since apt-utils is not installed
Fetched 53.4 MB in 2s (31.7 MB/s)
(Reading database ... 61439 files and directories currently installed.)
Preparing to unpack .../azure-cli_2.66.0-1focal_amd64.deb ...
Unpacking azure-cli (2.66.0-1focal) over (2.54.0-1focal) ...
Setting up azure-cli (2.66.0-1~focal) ...
DEBUG: cli.knack.cli: Event: Cli.PostExecute [<function AzCliLogging.deinit_cmd_metadata_logging at 0x7fc77717c540>]
INFO: az_command_data_logger: exit code: 128
INFO: cli.main: Command ran in 29.517 seconds (init: 0.583, invoke: 28.934)
DEBUG: cli.azure.cli.core._profile: Failed to load installationId from AzureRmSurvey.json. [Errno 2] No such file or directory: '/root/.azure/AzureRmContextSettings.json'
INFO: cli.azure.cli.core.decorators: Suppress exception:
Traceback (most recent call last):
File "/opt/az/lib/python3.11/site-packages/knack/cli.py", line 233, in invoke
File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/init.py", line 663, in execute
File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/init.py", line 726, in _run_jobs_serially
File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/init.py", line 697, in _run_job
File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/init.py", line 333, in call
File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/command_operation.py", line 121, in handler
File "/opt/az/lib/python3.11/site-packages/azure/cli/command_modules/util/custom.py", line 156, in upgrade_version
File "/opt/az/lib/python3.11/importlib/init.py", line 168, in reload
ModuleNotFoundError: spec not found for the module 'subprocess'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/az/lib/python3.11/site-packages/azure/cli/main.py", line 50, in
File "/opt/az/lib/python3.11/site-packages/azure/cli/main.py", line 36, in cli_main
File "/opt/az/lib/python3.11/site-packages/knack/cli.py", line 245, in invoke
File "/opt/az/lib/python3.11/site-packages/azure/cli/core/init.py", line 127, in exception_handler
File "/opt/az/lib/python3.11/site-packages/azure/cli/core/util.py", line 61, in handle_exception
ModuleNotFoundError: No module named 'azure.common'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/opt/az/lib/python3.11/site-packages/azure/cli/core/decorators.py", line 79, in _wrapped_func
File "/opt/az/lib/python3.11/site-packages/azure/cli/core/telemetry.py", line 315, in conclude
File "/opt/az/lib/python3.11/site-packages/azure/cli/telemetry/init.py", line 50, in save
ModuleNotFoundError: No module named 'azure.cli.telemetry.components'

Traceback (most recent call last):
File "/opt/az/lib/python3.11/site-packages/knack/cli.py", line 233, in invoke
File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/init.py", line 663, in execute
File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/init.py", line 726, in _run_jobs_serially
File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/init.py", line 697, in _run_job
File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/init.py", line 333, in call
File "/opt/az/lib/python3.11/site-packages/azure/cli/core/commands/command_operation.py", line 121, in handler
File "/opt/az/lib/python3.11/site-packages/azure/cli/command_modules/util/custom.py", line 156, in upgrade_version
File "/opt/az/lib/python3.11/importlib/init.py", line 168, in reload
ModuleNotFoundError: spec not found for the module 'subprocess'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "", line 198, in _run_module_as_main
File "", line 88, in _run_code
File "/opt/az/lib/python3.11/site-packages/azure/cli/main.py", line 50, in
File "/opt/az/lib/python3.11/site-packages/azure/cli/main.py", line 36, in cli_main
File "/opt/az/lib/python3.11/site-packages/knack/cli.py", line 245, in invoke
File "/opt/az/lib/python3.11/site-packages/azure/cli/core/init.py", line 127, in exception_handler
File "/opt/az/lib/python3.11/site-packages/azure/cli/core/util.py", line 61, in handle_exception
ModuleNotFoundError: No module named 'azure.common'

Expected behavior

expect that the az cli is upgraded successfully

Environment Summary

WARNING: You have 2 update(s) available. Consider updating your CLI installation with 'az upgrade'
azure-cli 2.54.0 *

core 2.54.0 *
telemetry 1.1.0

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

Python location '/opt/az/bin/python3'
Extensions directory '/root/.azure/cliextensions'

Python (Linux) 3.11.5 (main, Nov 8 2023, 05:21:25) [GCC 9.4.0]

Legal docs and information: aka.ms/AzureCliLegal

Additional context

No response

[yonzhan]

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

[bebound]

How you tried to use apt to upgrade azure-cli?

It seems az fails to upgrade itself while running.

[kevball2]

apt upgrade does appear to work. previously version of az upgrade have worked as well.

[bebound]

I assume the difference between Python 3.12 and 3.11 is too large for az to handle.

The design of az upgrade is flawed. It calls an external command to upgrade itself without exiting first. This process is somewhat expected to fail. That's why pip's upgrade command is python -m pip install --upgrade pip.

azure-cli/src/azure-cli/azure/cli/command_modules/util/custom.py

Line 100 in be320b1

exit_code = subprocess.call(az_update_cmd)

On windows, I've changed it to non-blocking to fix this: #26464
Now the same issue happens on Linux.

Ref: https://pip.pypa.io/en/latest/installation/