azure-cli: az acr login hangs

Describe the bug Running az acr login --name ensuretouchdev never finishes

To Reproduce Run command

Expected behavior Login into registry

Environment summary

Ubuntu 18.04

 $ az --version
azure-cli                         2.16.0

core                              2.16.0
telemetry                          1.0.6

Extensions:
azure-devops                      0.18.0

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

Python (Linux) 3.6.10 (default, Dec  4 2020, 12:36:15)
[GCC 7.5.0]

Your CLI is up-to-date.
 $ docker version
Client:
 Version:           19.03.6
 API version:       1.40
 Go version:        go1.12.17
 Git commit:        369ce74a3c
 Built:             Wed Oct 14 19:00:27 2020
 OS/Arch:           linux/amd64
 Experimental:      false

Server:
 Engine:
  Version:          19.03.6
  API version:      1.40 (minimum version 1.12)
  Go version:       go1.12.17
  Git commit:       369ce74a3c
  Built:            Wed Oct 14 16:52:50 2020
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.3.3-0ubuntu1~18.04.2
  GitCommit:
 runc:
  Version:          spec: 1.0.1-dev
  GitCommit:
 docker-init:
  Version:          0.18.0
  GitCommit:

Additional context

 $ az acr login --name ensuretouchdev --verbose --debug
Command arguments: ['acr', 'login', '--name', 'ensuretouchdev', '--verbose', '--debug']
Event: Cli.PreExecute []
Event: CommandParser.OnGlobalArgumentsCreate [<function CLILogging.on_global_arguments at 0x7f4e1a6a7950>, <function OutputProducer.on_global_arguments at 0x7f4e1a1f96a8>, <function CLIQuery.on_global_argument
s at 0x7f4e19f8e950>]
Event: CommandInvoker.OnPreCommandTableCreate []
Modules found from index for 'acr': ['azure.cli.command_modules.acr']
Loading command modules:
Name                  Load Time    Groups  Commands
acr                       0.004        25       103
Total (1)                 0.004        25       103
These extensions are not installed and will be skipped: ['azext_ai_examples']
Loading extensions:
Name                  Load Time    Groups  Commands  Directory
Total (0)                 0.000         0         0
Loaded 25 groups, 103 commands.
Found a match in the command table.
Raw command  : acr login
Command table: acr login
Event: CommandInvoker.OnPreCommandTableTruncate [<function AzCliLogging.init_command_file_logging at 0x7f4e194119d8>]
az_command_data_logger : command args: acr login --name {} --verbose --debug
metadata file logging enabled - writing logs to '/home/jcormier/.azure/commands'.
Event: CommandInvoker.OnPreArgumentLoad [<function register_global_subscription_argument.<locals>.add_subscription_parameter at 0x7f4e193c2b70>, <function register_global_query_examples_argument.<locals>.regis
ter_query_examples at 0x7f4e1931f2f0>]
Event: CommandInvoker.OnPostArgumentLoad []
Event: CommandInvoker.OnPostCommandTableCreate [<function register_ids_argument.<locals>.add_ids_arguments at 0x7f4e1931f378>, <function register_cache_arguments.<locals>.add_cache_arguments at 0x7f4e1931f488>
]
Event: CommandInvoker.OnCommandTableLoaded []
Event: CommandInvoker.OnPreParseArgs []
Event: CommandInvoker.OnPostParseArgs [<function OutputProducer.handle_output_argument at 0x7f4e1a1f9730>, <function CLIQuery.handle_query_parameter at 0x7f4e19f8e9d8>, <function register_global_query_examples
_argument.<locals>.handle_example_parameter at 0x7f4e1931f268>, <function register_ids_argument.<locals>.parse_ids_arguments at 0x7f4e1931f400>]
Getting management service client client_type=ResourceManagementClient
msrest.universal_http.requests : Configuring retry: max_retries=4, backoff_factor=0.8, max_backoff=90
Adding custom headers to the client:
    'x-ms-client-request-id': 'a88bfe4f-4092-11eb-8496-309c2321fb76'
    'CommandName': 'acr login'
    'ParameterSetName': '--name --verbose --debug'
msrest.async_paging : Paging async iterator protocol is not available for GenericResourceExpandedPaged
AdalAuthentication.signed_session invoked by Track 1 SDK
Retrieving token from ADAL for resource 'https://management.core.windows.net/'
attempting to read file /home/jcormier/.azure/accessTokens.json as utf-8-sig
adal-python : 4850b117-3d1e-4cc9-8542-b3f4005dfca9 - Authority:Performing instance discovery: ...
adal-python : 4850b117-3d1e-4cc9-8542-b3f4005dfca9 - Authority:Performing static instance discovery                                                                                                     [73/7640]
adal-python : 4850b117-3d1e-4cc9-8542-b3f4005dfca9 - Authority:Authority validated via static instance discovery
adal-python : 4850b117-3d1e-4cc9-8542-b3f4005dfca9 - TokenRequest:Getting token from cache with refresh if necessary.
adal-python : 4850b117-3d1e-4cc9-8542-b3f4005dfca9 - CacheDriver:finding with query keys: {'_clientId': '...', 'userId': '...'}
adal-python : 4850b117-3d1e-4cc9-8542-b3f4005dfca9 - CacheDriver:Looking for potential cache entries: {'_clientId': '...', 'userId': '...'}
adal-python : 4850b117-3d1e-4cc9-8542-b3f4005dfca9 - CacheDriver:Found 4 potential entries.
adal-python : 4850b117-3d1e-4cc9-8542-b3f4005dfca9 - CacheDriver:Resource specific token found.
adal-python : 4850b117-3d1e-4cc9-8542-b3f4005dfca9 - CacheDriver:Returning token from cache lookup, AccessTokenId: b'QRuqbIhPkNx9myZm1VOuTW3RNzIWQyWL+IWBXuz6GIo=', RefreshTokenId: b'duW+Q1xAb4tYSekaf6z1J6cWa8n
NR9DfkUjme/B9IJE='
msrest.http_logger : Request URL: 'https://management.azure.com/subscriptions/4c1c123b-e4e5-4068-b1f0-439062b6a102/resources?$filter=resourceType%20eq%20%27Microsoft.ContainerRegistry%2Fregistries%27&api-versi
on=2020-06-01'
msrest.http_logger : Request method: 'GET'
msrest.http_logger : Request headers:
msrest.http_logger :     'Accept': 'application/json'
msrest.http_logger :     'accept-language': 'en-US'
msrest.http_logger :     'User-Agent': 'python/3.6.10 (Linux-4.15.0-118-generic-x86_64-with-debian-buster-sid) msrest/0.6.18 msrest_azure/0.6.3 azure-mgmt-resource/10.3.0 Azure-SDK-For-Python AZURECLI/2.16.0 (
DEB)'
msrest.http_logger : Request body:
msrest.http_logger : None
msrest.universal_http : Configuring redirects: allow=True, max=30
msrest.universal_http : Configuring request: timeout=100, verify=True, cert=None
msrest.universal_http : Configuring proxies: ''
msrest.universal_http : Evaluate proxies against ENV settings: True
urllib3.connectionpool : Starting new HTTPS connection (1): management.azure.com:443
urllib3.connectionpool : https://management.azure.com:443 "GET /subscriptions/4c1c123b-e4e5-4068-b1f0-439062b6a102/resources?$filter=resourceType%20eq%20%27Microsoft.ContainerRegistry%2Fregistries%27&api-versi
on=2020-06-01 HTTP/1.1" 200 452
msrest.http_logger : Response status: 200
msrest.http_logger : Response headers:
msrest.http_logger :     'Cache-Control': 'no-cache'
msrest.http_logger :     'Pragma': 'no-cache'
msrest.http_logger :     'Content-Type': 'application/json; charset=utf-8'
msrest.http_logger :     'Content-Encoding': 'gzip'
msrest.http_logger :     'Expires': '-1'
msrest.http_logger :     'Vary': 'Accept-Encoding'
msrest.http_logger :     'x-ms-request-id': '292d275c-d8df-4c2b-aabf-e2b9ce3fdaaf'
msrest.http_logger :     'x-ms-correlation-request-id': '292d275c-d8df-4c2b-aabf-e2b9ce3fdaaf'
msrest.http_logger :     'x-ms-routing-request-id': 'CANADACENTRAL:20201217T180700Z:292d275c-d8df-4c2b-aabf-e2b9ce3fdaaf'
msrest.http_logger :     'Strict-Transport-Security': 'max-age=31536000; includeSubDomains'
msrest.http_logger :     'X-Content-Type-Options': 'nosniff'
msrest.http_logger :     'Date': 'Thu, 17 Dec 2020 18:07:00 GMT'
msrest.http_logger :     'Content-Length': '452'
msrest.http_logger : Response content:
msrest.http_logger : {"value":[{"id":"/subscriptions/4c1c123b-e4e5-4068-b1f0-439062b6a102/resourceGroups/EnsureTouch-Dev/providers/Microsoft.ContainerRegistry/registries/EnsureTouchDev","name":"EnsureTouchDev"
,"type":"Microsoft.ContainerRegistry/registries","sku":{"name":"Premium","tier":"Premium"},"location":"westus","tags":{},"systemData":{"createdBy":"anudelman@hygiena.com","createdByType":"User","createdAt":"20
20-12-14T23:34:26.2600584Z","lastModifiedBy":"anudelman@hygiena.com","lastModifiedByType":"User","lastModifiedAt":"2020-12-15T22:29:42.0884895Z"}}]}
Getting management service client client_type=ContainerRegistryManagementClient
msrest.universal_http.requests : Configuring retry: max_retries=4, backoff_factor=0.8, max_backoff=90
Adding custom headers to the client:
    'x-ms-client-request-id': 'a88bfe4f-4092-11eb-8496-309c2321fb76'
    'CommandName': 'acr login'
    'ParameterSetName': '--name --verbose --debug'
AdalAuthentication.signed_session invoked by Track 1 SDK
Retrieving token from ADAL for resource 'https://management.core.windows.net/'
adal-python : cdfbc30c-9d94-447d-8237-a1dd7af4038c - Authority:Performing instance discovery: ...
adal-python : cdfbc30c-9d94-447d-8237-a1dd7af4038c - Authority:Performing static instance discovery
adal-python : cdfbc30c-9d94-447d-8237-a1dd7af4038c - Authority:Authority validated via static instance discovery
adal-python : cdfbc30c-9d94-447d-8237-a1dd7af4038c - TokenRequest:Getting token from cache with refresh if necessary.
adal-python : cdfbc30c-9d94-447d-8237-a1dd7af4038c - CacheDriver:finding with query keys: {'_clientId': '...', 'userId': '...'}
adal-python : cdfbc30c-9d94-447d-8237-a1dd7af4038c - CacheDriver:Looking for potential cache entries: {'_clientId': '...', 'userId': '...'}
adal-python : cdfbc30c-9d94-447d-8237-a1dd7af4038c - CacheDriver:Found 4 potential entries.
adal-python : cdfbc30c-9d94-447d-8237-a1dd7af4038c - CacheDriver:Resource specific token found.
adal-python : cdfbc30c-9d94-447d-8237-a1dd7af4038c - CacheDriver:Returning token from cache lookup, AccessTokenId: b'QRuqbIhPkNx9myZm1VOuTW3RNzIWQyWL+IWBXuz6GIo=', RefreshTokenId: b'duW+Q1xAb4tYSekaf6z1J6cWa8n
NR9DfkUjme/B9IJE='
msrest.http_logger : Request URL: 'https://management.azure.com/subscriptions/4c1c123b-e4e5-4068-b1f0-439062b6a102/resourceGroups/ensuretouch-dev/providers/Microsoft.ContainerRegistry/registries/ensuretouchdev
?api-version=2019-12-01-preview'
msrest.http_logger : Request method: 'GET'
msrest.http_logger : Request headers:
msrest.http_logger :     'Accept': 'application/json'
msrest.http_logger :     'accept-language': 'en-US'
msrest.http_logger :     'User-Agent': 'python/3.6.10 (Linux-4.15.0-118-generic-x86_64-with-debian-buster-sid) msrest/0.6.18 msrest_azure/0.6.3 azure-mgmt-containerregistry/3.0.0rc15 Azure-SDK-For-Python AZURE
CLI/2.16.0 (DEB)'
msrest.http_logger : Request body:
msrest.http_logger : None
msrest.universal_http : Configuring redirects: allow=True, max=30
msrest.universal_http : Configuring request: timeout=100, verify=True, cert=None
msrest.universal_http : Configuring proxies: ''
msrest.universal_http : Evaluate proxies against ENV settings: True
urllib3.connectionpool : Starting new HTTPS connection (1): management.azure.com:443
urllib3.connectionpool : https://management.azure.com:443 "GET /subscriptions/4c1c123b-e4e5-4068-b1f0-439062b6a102/resourceGroups/ensuretouch-dev/providers/Microsoft.ContainerRegistry/registries/ensuretouchdev
?api-version=2019-12-01-preview HTTP/1.1" 200 None
msrest.http_logger : Response status: 200
msrest.http_logger : Response headers:
msrest.http_logger :     'Cache-Control': 'no-cache'
msrest.http_logger :     'Pragma': 'no-cache'
msrest.http_logger :     'Transfer-Encoding': 'chunked'
msrest.http_logger :     'Content-Type': 'application/json; charset=utf-8'
msrest.http_logger :     'Content-Encoding': 'gzip'
msrest.http_logger :     'Expires': '-1'
msrest.http_logger :     'Vary': 'Accept-Encoding'
msrest.http_logger :     'Strict-Transport-Security': 'max-age=31536000; includeSubDomains'
msrest.http_logger :     'Server': 'Microsoft-HTTPAPI/2.0'
msrest.http_logger :     'x-ms-ratelimit-remaining-subscription-reads': '11999'
msrest.http_logger :     'x-ms-request-id': '2bce4e35-e54e-4047-baf2-6181c5548eca'
msrest.http_logger :     'x-ms-correlation-request-id': '2bce4e35-e54e-4047-baf2-6181c5548eca'
msrest.http_logger :     'x-ms-routing-request-id': 'CANADACENTRAL:20201217T180701Z:2bce4e35-e54e-4047-baf2-6181c5548eca'
msrest.http_logger :     'X-Content-Type-Options': 'nosniff'
msrest.http_logger :     'Date': 'Thu, 17 Dec 2020 18:07:00 GMT'
msrest.http_logger : Response content:
msrest.http_logger : {"sku":{"name":"Premium","tier":"Premium"},"type":"Microsoft.ContainerRegistry/registries","id":"/subscriptions/4c1c123b-e4e5-4068-b1f0-439062b6a102/resourceGroups/EnsureTouch-Dev/provider
s/Microsoft.ContainerRegistry/registries/EnsureTouchDev","name":"EnsureTouchDev","location":"westus","tags":{},"systemData":{"createdBy":"anudelman@hygiena.com","createdByType":"User","createdAt":"2020-12-14T2
3:34:26.2600584+00:00","lastModifiedBy":"anudelman@hygiena.com","lastModifiedByType":"User","lastModifiedAt":"2020-12-15T22:29:42.0884895+00:00"},"properties":{"loginServer":"ensuretouchdev.azurecr.io","creationDate":"2020-12-14T23:34:26.2600584Z","provisioningState":"Succeeded","adminUserEnabled":false,"networkRuleSet":{"defaultAction":"Allow","virtualNetworkRules":[],"ipRules":[]},"policies":{"quarantinePolicy":{
"status":"disabled"},"trustPolicy":{"type":"Notary","status":"disabled"},"retentionPolicy":{"days":7,"lastUpdatedTime":"2020-12-14T23:34:27.1103104+00:00","status":"disabled"}},"encryption":{"status":"disabled"},"dataEndpointEnabled":false,"dataEndpointHostNames":[],"privateEndpointConnections":[],"publicNetworkAccess":"Enabled","networkRuleBypassOptions":"AzureServices"}}
urllib3.connectionpool : Starting new HTTPS connection (1): ensuretouchdev.azurecr.io:443
urllib3.connectionpool : https://ensuretouchdev.azurecr.io:443 "GET /v2/ HTTP/1.1" 401 149
Attempting to retrieve AAD refresh token...
urllib3.connectionpool : Starting new HTTPS connection (1): ensuretouchdev.azurecr.io:443
urllib3.connectionpool : https://ensuretouchdev.azurecr.io:443 "GET /v2/ HTTP/1.1" 401 149
Profile.get_raw_token invoked with resource=None, subscription='4c1c123b-e4e5-4068-b1f0-439062b6a102', tenant=None
adal-python : 7e7d818d-561f-443c-949b-e9dc26082717 - Authority:Performing instance discovery: ...
adal-python : 7e7d818d-561f-443c-949b-e9dc26082717 - Authority:Performing static instance discovery
adal-python : 7e7d818d-561f-443c-949b-e9dc26082717 - Authority:Authority validated via static instance discovery
adal-python : 7e7d818d-561f-443c-949b-e9dc26082717 - TokenRequest:Getting token from cache with refresh if necessary.
adal-python : 7e7d818d-561f-443c-949b-e9dc26082717 - CacheDriver:finding with query keys: {'_clientId': '...', 'userId': '...'}
adal-python : 7e7d818d-561f-443c-949b-e9dc26082717 - CacheDriver:Looking for potential cache entries: {'_clientId': '...', 'userId': '...'}
adal-python : 7e7d818d-561f-443c-949b-e9dc26082717 - CacheDriver:Found 4 potential entries.
adal-python : 7e7d818d-561f-443c-949b-e9dc26082717 - CacheDriver:Resource specific token found.
adal-python : 7e7d818d-561f-443c-949b-e9dc26082717 - CacheDriver:Returning token from cache lookup, AccessTokenId: b'QRuqbIhPkNx9myZm1VOuTW3RNzIWQyWL+IWBXuz6GIo=', RefreshTokenId: b'duW+Q1xAb4tYSekaf6z1J6cWa8n
NR9DfkUjme/B9IJE='
urllib3.connectionpool : Starting new HTTPS connection (1): ensuretouchdev.azurecr.io:443
urllib3.connectionpool : https://ensuretouchdev.azurecr.io:443 "POST /oauth2/exchange HTTP/1.1" 200 None

About this issue

  • Original URL
  • State: open
  • Created 4 years ago
  • Reactions: 5
  • Comments: 22 (4 by maintainers)

Most upvoted comments

(Relaying part of the email conversation here, in the hopes that it’ll help folks debug this issue if they run into it.)

A working theory on this is that acr login is doing some sort of docker call/command during the hang.

In the course of debugging something completely separate, I discovered that Docker for OS X on my machine was hung; the whale icon in the menu was grey, and hovering over it got me the beachball. It occurs to me (since I don’t know how long that was going on) that it could be related to this; perhaps a recent Docker update has introduced some bug recently that causes hangs, and that also translates to hangs inside acr login, and that’s just how I’m noticing it.

It sounds like acr login is doing something docker related at this point. (If you read the logs posted here, you see that the POST /oauth2/exchange call appears to have completed, but that raises the question: if that finished, then what are we waiting on?) I’ve asked that acr login log whatever it is that it is doing here, since then it would provide clear feedback (at least, if you’re using --debug) as to what the hang was for.

Restarting Docker Desktop, then running az acr login again worked for me on Pop!_OS 22.04 LTS

Still an issue

Having the same issue. Other suggestions here are not working. I’ve tried restarting docker desktop and re-running az login.