login: the azure cli task in azure devops takes >1 minute to even start

[Zazcallabah]

Ok, basically no matter how you try to use az cli in azure devops on a microsoft-hosted build agent, the first command (usually az login) will take over a minute to complete. This is a very long time when you're waiting for a build to complete that otherwise takes less than 10 seconds.

I don't know exactly what az cli is doing, but whatever it is, there must be less of it.

steps to reproduce

Have a build in azure devops, set to run on a microsoft hosted vs2017 build agent. Add a azure cli build step, connect it to any valid service principal, set the inline script to echo "". Run the build. Watch the azure cli build step take 75 seconds to complete.

I figure acceptable numbers here are something like 5 seconds.

[yugangw-msft]

please capture the trace using az login --debug and i will take a look. If it is too long, send it to me at yugangw at microsoft dot com

[Zazcallabah]

write-host "Before az login"
az login --debug --service-principal -u "<name>" -p <key> --tenant "<tenant>"
write-host "After az login"

2018-10-02T18:30:52.2437598Z Before az login
2018-10-02T18:31:03.3447808Z DEBUG: Command arguments: ['login', '--debug', '--service-principal', '-u', 'https://VisualStudio/SPN***', '-p', '***', '--tenant', '***']
2018-10-02T18:31:03.3448305Z DEBUG: Event: Cli.PreExecute []
2018-10-02T18:31:03.3453267Z DEBUG: Event: CommandParser.OnGlobalArgumentsCreate [<function CLILogging.on_global_arguments at 0x032FAE88>, <function OutputProducer.on_global_arguments at 0x033F2150>, <function CLIQuery.on_global_arguments at 0x0340CAE0>]
2018-10-02T18:31:03.3463977Z DEBUG: Event: CommandInvoker.OnPreCommandTableCreate [<function CLILogging.remove_logger_flags at 0x032FAED0>]
2018-10-02T18:31:04.5308275Z DEBUG: Installed command modules ['acr', 'acs', 'advisor', 'ams', 'appservice', 'backup', 'batch', 'batchai', 'billing', 'cdn', 'cloud', 'cognitiveservices', 'configure', 'consumption', 'container', 'cosmosdb', 'dla', 'dls', 'dms', 'eventgrid', 'eventhubs', 'extension', 'feedback', 'find', 'interactive', 'iot', 'iotcentral', 'keyvault', 'lab', 'maps', 'monitor', 'network', 'policyinsights', 'profile', 'rdbms', 'redis', 'relay', 'reservations', 'resource', 'role', 'search', 'servicebus', 'servicefabric', 'sql', 'storage', 'vm']
2018-10-02T18:31:04.6385323Z DEBUG: Loaded module 'acr' in 0.108 seconds.
2018-10-02T18:31:04.7930145Z DEBUG: Loaded module 'acs' in 0.154 seconds.
2018-10-02T18:31:04.8876086Z DEBUG: Loaded module 'advisor' in 0.094 seconds.
2018-10-02T18:31:04.9427975Z DEBUG: Event: CommandLoader.OnLoadCommandTable []
2018-10-02T18:31:04.9986227Z DEBUG: Loaded module 'ams' in 0.111 seconds.
2018-10-02T18:31:05.1109660Z DEBUG: Loaded module 'appservice' in 0.112 seconds.
2018-10-02T18:31:05.2285821Z DEBUG: Loaded module 'backup' in 0.117 seconds.
2018-10-02T18:31:05.4189433Z DEBUG: Event: CommandLoader.OnLoadCommandTable []
2018-10-02T18:31:05.4798556Z DEBUG: Loaded module 'batch' in 0.251 seconds.
2018-10-02T18:31:05.5560326Z DEBUG: Loaded module 'batchai' in 0.076 seconds.
2018-10-02T18:31:05.6479380Z DEBUG: Loaded module 'billing' in 0.092 seconds.
2018-10-02T18:31:05.7045969Z DEBUG: Event: CommandLoader.OnLoadCommandTable []
2018-10-02T18:31:05.7147496Z DEBUG: Loaded module 'cdn' in 0.067 seconds.
2018-10-02T18:31:05.7836800Z DEBUG: Loaded module 'cloud' in 0.069 seconds.
2018-10-02T18:31:05.8371438Z DEBUG: Loaded module 'cognitiveservices' in 0.053 seconds.
2018-10-02T18:31:05.8905233Z DEBUG: Loaded module 'configure' in 0.053 seconds.
2018-10-02T18:31:06.1708714Z DEBUG: Loaded module 'consumption' in 0.280 seconds.
2018-10-02T18:31:06.3047799Z DEBUG: Loaded module 'container' in 0.134 seconds.
2018-10-02T18:31:06.4827563Z DEBUG: Loaded module 'cosmosdb' in 0.178 seconds.
2018-10-02T18:31:06.5652437Z DEBUG: Loaded module 'dla' in 0.082 seconds.
2018-10-02T18:31:06.6691168Z DEBUG: Loaded module 'dls' in 0.104 seconds.
2018-10-02T18:31:06.7535353Z DEBUG: Loaded module 'dms' in 0.084 seconds.
2018-10-02T18:31:06.8634765Z DEBUG: Loaded module 'eventgrid' in 0.110 seconds.
2018-10-02T18:31:07.0318691Z DEBUG: Loaded module 'eventhubs' in 0.168 seconds.
2018-10-02T18:31:07.0800736Z DEBUG: Loaded module 'extension' in 0.048 seconds.
2018-10-02T18:31:07.1248847Z DEBUG: Loaded module 'feedback' in 0.045 seconds.
2018-10-02T18:31:07.1685207Z DEBUG: Loaded module 'find' in 0.044 seconds.
2018-10-02T18:31:07.1970013Z DEBUG: Loaded module 'interactive' in 0.028 seconds.
2018-10-02T18:31:07.2877618Z DEBUG: Loaded module 'iot' in 0.091 seconds.
2018-10-02T18:31:07.3982716Z DEBUG: Loaded module 'iotcentral' in 0.110 seconds.
2018-10-02T18:31:07.5773514Z DEBUG: Loaded module 'keyvault' in 0.179 seconds.
2018-10-02T18:31:07.7317404Z DEBUG: Loaded module 'lab' in 0.154 seconds.
2018-10-02T18:31:07.8568655Z DEBUG: Loaded module 'maps' in 0.125 seconds.
2018-10-02T18:31:08.0657234Z DEBUG: Loaded module 'monitor' in 0.209 seconds.
2018-10-02T18:31:08.2746548Z DEBUG: Loaded module 'network' in 0.209 seconds.
2018-10-02T18:31:08.3208043Z DEBUG: Loaded module 'policyinsights' in 0.046 seconds.
2018-10-02T18:31:08.3786581Z DEBUG: Loaded module 'profile' in 0.058 seconds.
2018-10-02T18:31:08.4620590Z DEBUG: Loaded module 'rdbms' in 0.083 seconds.
2018-10-02T18:31:08.5072276Z DEBUG: Loaded module 'redis' in 0.045 seconds.
2018-10-02T18:31:08.5406427Z DEBUG: Loaded module 'relay' in 0.033 seconds.
2018-10-02T18:31:08.6882310Z DEBUG: Loaded module 'reservations' in 0.147 seconds.
2018-10-02T18:31:08.8379689Z DEBUG: Loaded module 'resource' in 0.150 seconds.
2018-10-02T18:31:08.8920311Z DEBUG: Loaded module 'role' in 0.054 seconds.
2018-10-02T18:31:09.0140585Z DEBUG: Loaded module 'search' in 0.122 seconds.
2018-10-02T18:31:09.1328727Z DEBUG: Loaded module 'servicebus' in 0.119 seconds.
2018-10-02T18:31:09.1668856Z DEBUG: Loaded module 'servicefabric' in 0.034 seconds.
2018-10-02T18:31:09.3111236Z DEBUG: Loaded module 'sql' in 0.144 seconds.
2018-10-02T18:31:09.3867459Z DEBUG: Event: CommandLoader.OnLoadCommandTable []
2018-10-02T18:31:09.5525238Z DEBUG: Loaded module 'storage' in 0.241 seconds.
2018-10-02T18:31:09.7998312Z DEBUG: Loaded module 'vm' in 0.247 seconds.
2018-10-02T18:31:09.8001975Z DEBUG: Loaded all modules in 5.262 seconds. (note: there's always an overhead with the first module loaded)
2018-10-02T18:31:09.8005284Z DEBUG: Extensions directory: 'C:\Users\VssAdministrator\.azure\cliextensions'
2018-10-02T18:31:09.8006662Z DEBUG: Event: CommandInvoker.OnPreCommandTableTruncate []
2018-10-02T18:31:11.0393782Z DEBUG: Event: CommandInvoker.OnPostCommandTableCreate [<function add_id_parameters at 0x0345E4F8>, <function register_global_subscription_parameter.<locals>.add_subscription_parameter at 0x034795D0>]
2018-10-02T18:31:11.0406823Z DEBUG: Event: CommandInvoker.OnCommandTableLoaded []
2018-10-02T18:31:11.0407957Z DEBUG: Event: CommandInvoker.OnPreParseArgs [<function _documentdb_deprecate at 0x0360EB28>]
2018-10-02T18:31:11.0417061Z DEBUG: Event: CommandInvoker.OnPostParseArgs [<function OutputProducer.handle_output_argument at 0x033F2198>, <function CLIQuery.handle_query_parameter at 0x0340CA98>, <function register_global_subscription_parameter.<locals>.parse_subscription_parameter at 0x03479588>, <function handler at 0x03698198>]
2018-10-02T18:31:24.7697184Z DEBUG: adal-python : 086bf053-2905-4881-8cc3-f95b7b083b31 - Authority:Performing instance discovery: ...
2018-10-02T18:31:24.7697611Z DEBUG: adal-python : 086bf053-2905-4881-8cc3-f95b7b083b31 - Authority:Performing static instance discovery
2018-10-02T18:31:24.7699056Z DEBUG: adal-python : 086bf053-2905-4881-8cc3-f95b7b083b31 - Authority:Authority validated via static instance discovery
2018-10-02T18:31:24.7700354Z INFO: adal-python : 086bf053-2905-4881-8cc3-f95b7b083b31 - TokenRequest:Getting token with client credentials.
2018-10-02T18:31:24.7702005Z DEBUG: adal-python : 086bf053-2905-4881-8cc3-f95b7b083b31 - TokenRequest:No user_id passed for cache query
2018-10-02T18:31:24.7703162Z DEBUG: adal-python : 086bf053-2905-4881-8cc3-f95b7b083b31 - CacheDriver:finding with query keys: {'_clientId': '...'}
2018-10-02T18:31:24.7704976Z DEBUG: adal-python : 086bf053-2905-4881-8cc3-f95b7b083b31 - CacheDriver:Looking for potential cache entries: {'_clientId': '...'}
2018-10-02T18:31:24.7706030Z DEBUG: adal-python : 086bf053-2905-4881-8cc3-f95b7b083b31 - CacheDriver:Found 0 potential entries.
2018-10-02T18:31:24.8232495Z DEBUG: urllib3.connectionpool : Starting new HTTPS connection (1): login.microsoftonline.com:443
2018-10-02T18:31:25.6587188Z DEBUG: urllib3.connectionpool : https://login.microsoftonline.com:443 "POST /***/oauth2/token HTTP/1.1" 200 1443
2018-10-02T18:31:25.6614885Z INFO: adal-python : 086bf053-2905-4881-8cc3-f95b7b083b31 - OAuth2Client:Get Token Server returned this correlation_id: 086bf053-2905-4881-8cc3-f95b7b083b31
2018-10-02T18:31:25.6805031Z DEBUG: adal-python : 086bf053-2905-4881-8cc3-f95b7b083b31 - CacheDriver:Adding entry AccessTokenId: b'***'
2018-10-02T18:31:25.6805611Z DEBUG: adal-python : 086bf053-2905-4881-8cc3-f95b7b083b31 - CacheDriver:Added entry is MRRT
2018-10-02T18:31:27.4036675Z DEBUG: msrest.service_client : Accept header absent and forced to application/json
2018-10-02T18:31:27.4038613Z DEBUG: msrest.pipeline : Configuring request: timeout=100, verify=True, cert=None
2018-10-02T18:31:27.4046986Z DEBUG: msrest.pipeline : Configuring proxies: ''
2018-10-02T18:31:27.4153420Z DEBUG: msrest.pipeline : Evaluate proxies against ENV settings: True
2018-10-02T18:31:27.4155393Z DEBUG: msrest.pipeline : Configuring redirects: allow=True, max=30
2018-10-02T18:31:27.4155877Z DEBUG: msrest.pipeline : Configuring retry: max_retries=4, backoff_factor=0.8, max_backoff=90
2018-10-02T18:31:27.4156279Z DEBUG: urllib3.connectionpool : Starting new HTTPS connection (1): management.azure.com:443
2018-10-02T18:31:27.5768491Z DEBUG: urllib3.connectionpool : https://management.azure.com:443 "GET /subscriptions?api-version=2016-06-01 HTTP/1.1" 200 None
2018-10-02T18:31:27.5864434Z DEBUG: Event: CommandInvoker.OnTransformResult [<function _resource_group_transform at 0x03470930>, <function _x509_from_base64_to_hex_transform at 0x03470978>]
2018-10-02T18:31:27.5866591Z DEBUG: Event: CommandInvoker.OnFilterResult []
2018-10-02T18:31:27.5868671Z [
2018-10-02T18:31:27.5868745Z   {
2018-10-02T18:31:27.5868817Z     "cloudName": "AzureCloud",
2018-10-02T18:31:27.5868893Z     "id": "***",
2018-10-02T18:31:27.5868975Z     "isDefault": true,
2018-10-02T18:31:27.5869042Z     "name": "***",
2018-10-02T18:31:27.5869109Z     "state": "Enabled",
2018-10-02T18:31:27.5869278Z     "tenantId": "***",
2018-10-02T18:31:27.5869361Z     "user": {
2018-10-02T18:31:27.5869436Z       "name": "https://VisualStudio/SPN***",
2018-10-02T18:31:27.5869523Z       "type": "servicePrincipal"
2018-10-02T18:31:27.5869607Z     }
2018-10-02T18:31:27.5869670Z   }
2018-10-02T18:31:27.5869737Z ]
2018-10-02T18:31:27.5870394Z DEBUG: Event: Cli.PostExecute []
2018-10-02T18:31:28.4321299Z INFO: telemetry.save : Save telemetry record of length 2448 in cache
2018-10-02T18:31:28.4324614Z INFO: telemetry.check : Positive: The C:\Users\VssAdministrator\.azure\telemetry.txt does not exist.
2018-10-02T18:31:28.4326125Z INFO: telemetry.main : Begin creating telemetry upload process.
2018-10-02T18:31:28.4327845Z INFO: telemetry.process : Creating upload process: "C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\python.exe C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\Lib\site-packages\azure\cli\telemetry\__init__.pyc C:\Users\VssAdministrator\.azure"
2018-10-02T18:31:28.4374140Z INFO: telemetry.process : Return from creating porcess
2018-10-02T18:31:28.4374729Z INFO: telemetry.main : Finish creating telemetry upload process.
2018-10-02T18:31:28.5520204Z After az login

I notice that it takes more than ten seconds for az login to even start outputting debug messages.

[yugangw-msft]

> I notice that it takes more than ten seconds for az login to even start outputting debug messages.

This is expected for cold start as file loading, anti-virus scan, and compiling .py to .pyc are happening during this period . #6673 by adding more pre-compiled files should help

> 2018-10-02T18:31:11.0417061Z DEBUG: Event: CommandInvoker.OnPostParseArgs ...
> 2018-10-02T18:31:24.7697184Z DEBUG: adal-python : ...

I can't explain why there are 13 seconds latency here. If you run az login again, does it reproduce?

[Zazcallabah]

As far as I can tell, yes. Here is another from this morning.

2018-10-03T08:41:56.1871996Z DEBUG: Event: CommandInvoker.OnPostParseArgs ...
2018-10-03T08:42:12.0664529Z DEBUG: adal-python : ...

I'm guessing someone over at https://github.com/Microsoft/vsts-tasks may have more insight into what exactly is happening, but I wouldn't know who to ask.

[yonzhan]

add to S164.