Closed kmin1223 closed 2 years ago
Even though the Azure CLI you are using is 2.28.0 which is based on ADAL, but it should be similar to MSAL. @rayluo, does ADAL or MSAL log 400
error details from /common/oauth2/token
?
it's banking system, so VM's outbound is not fully opened. can you guide which URLs should be opened in order to use 'az login' within VM?
az login
only requires AAD endpoint
and ARM endpoint
it's banking system, so VM's outbound is not fully opened. can you guide which URLs should be opened in order to use 'az login' within VM?
The fact that the log mentioned an HTTP 400 error, it already indicates that the round-trip traffic to token endpoint was completed.
from below log, there's 400 http error code. so we suspect that some packet's manipulated. it is correct? urllib3.connectionpool: https://login.microsoftonline.com:443 "POST /common/oauth2/token HTTP/1.1" 400 510
Usually not because "some packets were manipulated". All authentication errors would result in HTTP 400 error.
Even though the Azure CLI you are using is 2.28.0 which is based on ADAL, but it should be similar to MSAL. @rayluo, does ADAL or MSAL log
400
error details from/common/oauth2/token
?
MSAL does not log HTTP 400 error, but the raw error response would be returned to calling app as-is. ADAL was similar.
However, in this particular case, it seems the problem occurred during a device code authentication. The initial many HTTP 400 errors were expected, while the Azure CLI was waiting for the user to complete the device code authentication. The question is why there would be HTTP 400 even after the user authentication allegedly succeeded.
I would suggest @kmin1223 to tentatively switch to Azure CLI 2.30+ (or alternatively, pip install msal
and then download and run this standard sample), and see whether you can reproduce the same issue. If yes, we would need further investigation.
Hi @rayluo,
CLI version is updated to 2.31.0, but issue is still the same.
Here is debug log
[root@KRMMLSAM011 tmp]# az login --debug
cli.knack.cli: Command arguments: ['login', '-u', 'azcli@sc-az-co.kr', '-p', ' '--debug']
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 0x7f9fca56ab70>, <function OutputProducer.on_global_arguments at 0x7f9fca0a0d08>, <function CLIQuery.on_global_arguments at 0x7f9fc9e3e1e0>]
cli.knack.cli: Event: CommandInvoker.OnPreCommandTableCreate []
cli.azure.cli.core: Modules found from index for 'login': ['azure.cli.command_modules.profile']
cli.azure.cli.core: Loading command modules:
cli.azure.cli.core: Name Load Time Groups Commands
cli.azure.cli.core: profile 0.002 2 9
cli.azure.cli.core: Total (1) 0.002 2 9
cli.azure.cli.core: Loaded 2 groups, 9 commands.
cli.azure.cli.core: Found a match in the command table.
cli.azure.cli.core: Raw command : login
cli.azure.cli.core: Command table: login
cli.knack.cli: Event: CommandInvoker.OnPreCommandTableTruncate [<function AzCliLogging.init_command_file_logging at 0x7f9fc8deef28>]
cli.azure.cli.core.azlogging: metadata file logging enabled - writing logs to '/root/.azure/commands/2021-12-09.14-37-50.login.489013.log'.
az_command_data_logger: command args: login -u {} -p {} --debug
cli.knack.cli: Event: CommandInvoker.OnPreArgumentLoad [<function register_global_subscription_argument.
@kmin1223, your execution was cancelled by ^C
. Please share the log with the said 400
errors.
cli.knack.cli: Command arguments: ['login', '--debug']
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 0x7fc2dcf98d90>, <function OutputProducer.on_global_arguments at 0x7fc2dcad0e18>, <function CLIQuery.on_global_arguments at 0x7fc2dc86c400>]
cli.knack.cli: Event: CommandInvoker.OnPreCommandTableCreate []
cli.azure.cli.core: Command index version or cloud profile is invalid or doesn't match the current command.
cli.azure.cli.core: Command index has been invalidated.
cli.azure.cli.core: No module found from index for '['login', '--debug']'
cli.azure.cli.core: Loading all modules and extensions
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', 'cosmosdb', 'databoxedge', 'deploymentmanager', 'dla', 'dls', 'dms', 'eventgrid', 'eventhubs', 'extension', 'feedback', 'find', 'hdinsight', 'interactive', 'iot', 'keyvault', 'kusto', 'lab', 'managedservices', 'maps', 'marketplaceordering', 'monitor', 'natgateway', 'netappfiles', 'network', 'policyinsights', 'privatedns', 'profile', 'rdbms', 'redis', 'relay', 'reservations', 'resource', 'role', 'search', 'security', 'servicebus', 'serviceconnector', 'servicefabric', 'signalr', 'sql', 'sqlvm', 'storage', 'synapse', 'util', 'vm']
cli.azure.cli.core: Loading command modules:
cli.azure.cli.core: Name Load Time Groups Commands
cli.azure.cli.core: acr 0.009 28 116
cli.azure.cli.core: acs 0.126 8 53
cli.azure.cli.core: advisor 0.001 3 6
cli.azure.cli.core: ams 0.007 20 90
cli.azure.cli.core: apim 0.004 9 50
cli.azure.cli.core: appconfig 0.003 7 33
cli.azure.cli.core: appservice 0.014 66 239
cli.azure.cli.core: aro 0.040 1 7
cli.azure.cli.core: backup 0.004 15 55
cli.azure.cli.core: batch 0.038 31 92
cli.azure.cli.core: batchai 0.003 10 30
cli.azure.cli.core: billing 0.006 19 52
cli.azure.cli.core: botservice 0.004 12 42
cli.azure.cli.core: cdn 0.008 39 132
cli.azure.cli.core: cloud 0.001 1 7
cli.azure.cli.core: cognitiveservices 0.002 8 30
cli.azure.cli.core: config 0.001 2 7
cli.azure.cli.core: configure 0.002 3 9
cli.azure.cli.core: consumption 0.002 8 9
cli.azure.cli.core: container 0.001 1 11
cli.azure.cli.core: cosmosdb 0.012 47 167
cli.azure.cli.core: databoxedge 0.004 5 27
cli.azure.cli.core: deploymentmanager 0.002 7 30
cli.azure.cli.core: dla 0.004 23 62
cli.azure.cli.core: dls 0.003 7 41
cli.azure.cli.core: dms 0.002 3 22
cli.azure.cli.core: eventgrid 0.004 18 61
cli.azure.cli.core: eventhubs 0.004 16 57
cli.azure.cli.core: extension 0.001 1 7
cli.azure.cli.core: feedback 0.001 1 1
cli.azure.cli.core: find 0.001 1 1
cli.azure.cli.core: hdinsight 0.003 8 39
cli.azure.cli.core: interactive 0.000 1 1
cli.azure.cli.core: iot 0.006 16 71
cli.azure.cli.core: keyvault 0.010 20 122
cli.azure.cli.core: kusto 0.002 3 14
cli.azure.cli.core: lab 0.003 11 34
cli.azure.cli.core: managedservices 0.001 3 8
cli.azure.cli.core: maps 0.002 5 13
cli.azure.cli.core: marketplaceordering 0.002 1 2
cli.azure.cli.core: monitor 0.009 32 133
cli.azure.cli.core: natgateway 0.001 3 6
cli.azure.cli.core: netappfiles 0.004 13 56
cli.azure.cli.core: network 0.061 139 645
cli.azure.cli.core: policyinsights 0.002 6 12
cli.azure.cli.core: privatedns 0.005 14 66
cli.azure.cli.core: profile 0.001 2 9
cli.azure.cli.core: rdbms 0.079 46 199
cli.azure.cli.core: redis 0.002 4 24
cli.azure.cli.core: relay 0.003 10 37
cli.azure.cli.core: reservations 0.002 5 12
cli.azure.cli.core: resource 0.011 40 187
cli.azure.cli.core: role 0.004 17 61
cli.azure.cli.core: search 0.002 7 22
cli.azure.cli.core: security 0.007 36 82
cli.azure.cli.core: servicebus 0.005 17 64
cli.azure.cli.core: serviceconnector 0.007 4 39
cli.azure.cli.core: servicefabric 0.005 26 75
cli.azure.cli.core: signalr 0.002 6 20
cli.azure.cli.core: sql 0.011 45 179
cli.azure.cli.core: sqlvm 0.002 4 17
cli.azure.cli.core: storage 0.069 55 256
cli.azure.cli.core: synapse 0.012 51 224
cli.azure.cli.core: util 0.001 2 4
cli.azure.cli.core: vm 0.023 52 267
cli.azure.cli.core: Total (65) 0.676 1124 4546
cli.azure.cli.core: Loaded 1113 groups, 4546 commands.
cli.azure.cli.core: Updated command index in 0.004 seconds.
cli.knack.cli: Event: CommandInvoker.OnPreCommandTableTruncate [<function AzCliLogging.init_command_file_logging at 0x7fc2db81d158>]
cli.azure.cli.core.azlogging: metadata file logging enabled - writing logs to '/home/scmdadm/.azure/commands/2021-12-09.15-38-23.login.493928.log'.
az_command_data_logger: command args: login --debug
cli.knack.cli: Event: CommandInvoker.OnPreArgumentLoad [<function register_global_subscription_argument.az login --use-device-code
.
msal.telemetry: Generate or reuse correlation_id: ad111f8f-169d-42e9-b903-f1f4573ee634
msal.oauth2cli.oauth2: Using http://localhost:40325 as redirect_uri
msal.oauth2cli.authcode: Abort by visit http://localhost:40325?error=abort
msal.oauth2cli.authcode: Open a browser on this device to visit: https://login.microsoftonline.com/organizations/oauth2/v2.0/authorize?client_id=04b07795-8ddb-461a-bbee-02f9e1bf7b46&response_type=code&redirect_uri=http%3A%2F%2Flocalhost%3A40325&scope=https%3A%2F%2Fmanagement.core.windows.net%2F%2F.default+offline_access+openid+profile&state=PeqLhRjSBFGAyfEs&code_challenge=sR4XE4IWnEiyZxlEWro90gDCqduYDb03HEe22L2dPUU&code_challenge_method=S256&nonce=1ea73a383047b2e104607c7ebef4b2863d86a394bae3720261ee81249e6c16f3&client_info=1&prompt=select_account
Making connection [------]
┌──────────────────────────────────────┐
│ │
│ Do you really want to exit ELinks? │
│ │
│ [ Yes ] [ No ] │
└──────────────────────────────────────┘
Making connection [------]
^Ccli.knack.cli: Event: Cli.PostExecute [<function AzCliLogging.deinit_cmd_metadata_logging at 0x7fc2db81d378>]
az_command_data_logger: exit code: 1
cli.main: Command ran in 61.838 seconds (init: 0.167, invoke: 61.671)
telemetry.save: Save telemetry record of length 2960 in cache
telemetry.check: Returns Positive.
telemetry.main: Begin creating telemetry upload process.
telemetry.process: Creating upload process: "/usr/bin/python3.6 /usr/lib64/az/lib/python3.6/site-packages/azure/cli/telemetry/init.py /home/scmdadm/.azure"
telemetry.process: Return from creating process
telemetry.main: Finish creating telemetry upload process.
[scmdadm@KRMMLSAM011 ~]$ az login --debug >> /tmp/debug.txt
DEBUG: cli.knack.cli: Command arguments: ['login', '--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 0x7fa79220de18>, <function OutputProducer.on_global_arguments at 0x7fa791d46e18>, <function CLIQuery.on_global_arguments at 0x7fa791ae2400>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreCommandTableCreate []
DEBUG: cli.azure.cli.core: Modules found from index for 'login': ['azure.cli.command_modules.profile']
DEBUG: cli.azure.cli.core: Loading command modules:
DEBUG: cli.azure.cli.core: Name Load Time Groups Commands
DEBUG: cli.azure.cli.core: profile 0.002 2 9
DEBUG: cli.azure.cli.core: Total (1) 0.002 2 9
DEBUG: cli.azure.cli.core: Loaded 2 groups, 9 commands.
DEBUG: cli.azure.cli.core: Found a match in the command table.
DEBUG: cli.azure.cli.core: Raw command : login
DEBUG: cli.azure.cli.core: Command table: login
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreCommandTableTruncate [<function AzCliLogging.init_command_file_logging at 0x7fa790a92158>]
DEBUG: cli.azure.cli.core.azlogging: metadata file logging enabled - writing logs to '/home/scmdadm/.azure/commands/2021-12-09.15-40-53.login.494014.log'.
INFO: az_command_data_logger: command args: login --debug
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreArgumentLoad [<function register_global_subscription_argument.az login --use-device-code
.
DEBUG: msal.telemetry: Generate or reuse correlation_id: dc192712-b31f-49b8-8137-48f304799217
DEBUG: msal.oauth2cli.oauth2: Using http://localhost:29323 as redirect_uri
DEBUG: msal.oauth2cli.authcode: Abort by visit http://localhost:29323?error=abort
INFO: msal.oauth2cli.authcode: Open a browser on this device to visit: https://login.microsoftonline.com/organizations/oauth2/v2.0/authorize?client_id=04b07795-8ddb-461a-bbee-02f9e1bf7b46&response_type=code&redirect_uri=http%3A%2F%2Flocalhost%3A29323&scope=https%3A%2F%2Fmanagement.core.windows.net%2F%2F.default+offline_access+openid+profile&state=eCVzPOwjQTkyYSdZ&code_challenge=B3A1gXSxp9gce2pRMD6m2E4ZqYIF8kbFDacCDTrILwM&code_challenge_method=S256&nonce=b38663e0a0774f922b66af0106bd8db343b3b06c9854a4be29f7b170a628a2be&client_info=1&prompt=select_account
^CDEBUG: cli.knack.cli: Event: Cli.PostExecute [<function AzCliLogging.deinit_cmd_metadata_logging at 0x7fa790a92378>]
INFO: az_command_data_logger: exit code: 1
INFO: cli.main: Command ran in 631.697 seconds (init: 80.555, invoke: 551.143)
INFO: telemetry.save: Save telemetry record of length 2962 in cache
INFO: telemetry.check: Returns Positive.
INFO: telemetry.main: Begin creating telemetry upload process.
INFO: telemetry.process: Creating upload process: "/usr/bin/python3.6 /usr/lib64/az/lib/python3.6/site-packages/azure/cli/telemetry/init.py /home/scmdadm/.azure"
INFO: telemetry.process: Return from creating process
INFO: telemetry.main: Finish creating telemetry upload process.
Previously when using Azure CLI 2.28, the az login
directly attempted a Device Code Auth, which we can see from the earlier logs:
reproducing issue we are using azure cli on azure linux VM.
when we typed 'az login', then below message is showing. "To sign in, use a web browser to open the page https://microsoft.com/devicelogin and enter the code HCK2W55TK to authenticate.", then browser is opened, but it show empty page.
The Device Code Auth was supposed to work, but in @kmin1223 's case it somehow failed.
In Azure CLI 2.30+, the situation is different. az login
would still attempt a "normal authentication", i.e. trying to launch a browser on the machine running that az login
.
... cli.azure.cli.core.auth.identity: The default web browser has been opened at https://login.microsoftonline.com/organizations/oauth2/v2.0/authorize. Please continue the login in the web browser. If no web browser is available or if the web browser fails to open, use device code flow with az login --use-device-code. ... msal.oauth2cli.authcode: Open a browser on this device to visit: https://login.microsoftonline.com/organizations/oauth2/v2.0/authorize?client_id=04b07795-8ddb-461a-bbee-02f9e1bf7b46&response_type=code&redirect_uri=http%3A%2F%2Flocalhost%3A40325...
However, given that the current machine happens to be a remote VM, its local browser generally won't work. Indeed, it ended up launching a text-mode browser named "ELinks", which would probably be incapable to handle modern javascript-based web pages.
Making connection [------]
┌──────────────────────────────────────┐
│ │
│ Do you really want to exit ELinks? │
│ │
│ [ Yes ] [ No ] │
└──────────────────────────────────────┘
Making connection [------]
...
But then the quoted log also contains this line, which is expected to be visible and more noticeable when the log was disabled by default: "The default web browser has been opened at https://login.microsoftonline.com/organizations/oauth2/v2.0/authorize. Please continue the login in the web browser. If no web browser is available or if the web browser fails to open, use device code flow with az login --use-device-code."
So, @kmin1223 please follow the guidance and manually run az login --use-device-code
and see how that works.
below log is the 'az login --use-device-code'
cli.knack.cli: Command arguments: ['login', '--use-device-code', '--debug']
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 0x7f1a8046db70>, <function OutputProducer.on_global_arguments at 0x7f1a7ffa4d08>, <function CLIQuery.on_global_arguments at 0x7f1a7fd421e0>]
cli.knack.cli: Event: CommandInvoker.OnPreCommandTableCreate []
cli.azure.cli.core: Modules found from index for 'login': ['azure.cli.command_modules.profile']
cli.azure.cli.core: Loading command modules:
cli.azure.cli.core: Name Load Time Groups Commands
cli.azure.cli.core: profile 0.002 2 9
cli.azure.cli.core: Total (1) 0.002 2 9
cli.azure.cli.core: Loaded 2 groups, 9 commands.
cli.azure.cli.core: Found a match in the command table.
cli.azure.cli.core: Raw command : login
cli.azure.cli.core: Command table: login
cli.knack.cli: Event: CommandInvoker.OnPreCommandTableTruncate [<function AzCliLogging.init_command_file_logging at 0x7f1a7ed42f28>]
cli.azure.cli.core.azlogging: metadata file logging enabled - writing logs to '/root/.azure/commands/2021-12-09.17-01-57.login.500630.log'.
az_command_data_logger: command args: login --use-device-code --debug
cli.knack.cli: Event: CommandInvoker.OnPreArgumentLoad [<function register_global_subscription_argument.
I think this time it works, as Azure CLI is now trying to connecting to management.azure.com
. Are you still seeing any error?
still have the same issue. without debug, we have below.
bash-4.4$ az login --use-device-code To sign in, use a web browser to open the page https://microsoft.com/devicelogin and enter the code SMN6G4NYS to authenticate. <urllib3.connection.HTTPSConnection object at 0x7f7c3edfd5f8>: Failed to establish a new connection: [Errno 110] Connection timed out
btw, can you guide which URLs should be opened in order to use az cli on azure VM? Below two is enough?
management.azure.com login.microsoftonline.com
new try with debug log
cli.knack.cli: Command arguments: ['login', '--use-device-code', '--debug']
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 0x7f1ad9e4ed90>, <function OutputProducer.on_global_arguments at 0x7f1ad9987e18>, <function CLIQuery.on_global_arguments at 0x7f1ad9722400>]
cli.knack.cli: Event: CommandInvoker.OnPreCommandTableCreate []
cli.azure.cli.core: Modules found from index for 'login': ['azure.cli.command_modules.profile']
cli.azure.cli.core: Loading command modules:
cli.azure.cli.core: Name Load Time Groups Commands
cli.azure.cli.core: profile 0.002 2 9
cli.azure.cli.core: Total (1) 0.002 2 9
cli.azure.cli.core: Loaded 2 groups, 9 commands.
cli.azure.cli.core: Found a match in the command table.
cli.azure.cli.core: Raw command : login
cli.azure.cli.core: Command table: login
cli.knack.cli: Event: CommandInvoker.OnPreCommandTableTruncate [<function AzCliLogging.init_command_file_logging at 0x7f1ad86d3158>]
cli.azure.cli.core.azlogging: metadata file logging enabled - writing logs to '/home/postgres/.azure/commands/2021-12-10.11-45-53.login.596193.log'.
az_command_data_logger: command args: login --use-device-code --debug
cli.knack.cli: Event: CommandInvoker.OnPreArgumentLoad [<function register_global_subscription_argument.
cli.azure.cli.core.azclierror: <urllib3.connection.HTTPSConnection object at 0x7f1ad571b5f8>: Failed to establish a new connection: [Errno 110] Connection timed out az_command_data_logger: <urllib3.connection.HTTPSConnection object at 0x7f1ad571b5f8>: Failed to establish a new connection: [Errno 110] Connection timed out cli.knack.cli: Event: Cli.PostExecute [<function AzCliLogging.deinit_cmd_metadata_logging at 0x7f1ad86d3378>] az_command_data_logger: exit code: 1 cli.main: Command ran in 842.486 seconds (init: 0.147, invoke: 842.339) telemetry.save: Save telemetry record of length 3022 in cache telemetry.check: Returns Positive. telemetry.main: Begin creating telemetry upload process. telemetry.process: Creating upload process: "/usr/bin/python3.6 /usr/lib64/az/lib/python3.6/site-packages/azure/cli/telemetry/init.py /home/postgres/.azure" telemetry.process: Return from creating process telemetry.main: Finish creating telemetry upload process.
This time, the error is a timeout, indicating access to https://management.azure.com/tenants?api-version=2019-11-01 was blocked.
btw, can you guide which URLs should be opened in order to use az cli on azure VM? Below two is enough?
management.azure.com login.microsoftonline.com
Yes.
Hi, we're sending this friendly reminder because we haven't heard back from you in a while. We need more information about this issue to help address it. Please be sure to give us your input within the next 7 days. If we don't hear back from you within 14 days of this comment the issue will be automatically closed. Thank you!
cli version ->"azure-cli": "2.28.0", "azure-cli-core": "2.28.0", "azure-cli-telemetry": "1.0.6", "extensions": {}
reproducing issue we are using azure cli on azure linux VM.
when we typed 'az login', then below message is showing. "To sign in, use a web browser to open the page https://microsoft.com/devicelogin and enter the code HCK2W55TK to authenticate.", then browser is opened, but it show empty page.
from desktop, we opened browser then went to the url and typed code. Then, typed credentials successfully, but from the vm console, there's no progress at all.
urllib3.connectionpool: https://login.microsoftonline.com:443 "POST /common/oauth2/token HTTP/1.1" 400 510 urllib3.connectionpool: Starting new HTTPS connection (1): login.microsoftonline.com:443
outbound is through firewall server(fortigate). login.microsoftonline.com is opened from firewall.