Azure-pipelines-tasks: Azure CLI Task: az account clear fails
Environment
Server - VSTS or TFS on-premises?
VSTSAgent - Hosted or Private:
Linux Hosted Preview
Issue Description
Our build has started to consistently fail because of Azure CLI task. The task fails at the last step az account clear. This is a regression since it was working the week before.
Version: 1.*
Error logs
2018-02-27T18:12:41.4138212Z ##[debug]Evaluating condition for step: 'Download dependencies'
2018-02-27T18:12:41.4166697Z ##[debug]Evaluating: succeeded()
2018-02-27T18:12:41.4188348Z ##[debug]Evaluating succeeded:
2018-02-27T18:12:41.4219635Z ##[debug]=> (Boolean) True
2018-02-27T18:12:41.4242159Z ##[debug]Expanded: True
2018-02-27T18:12:41.4263812Z ##[debug]Result: True
2018-02-27T18:12:41.4285833Z ##[section]Starting: Download dependencies
2018-02-27T18:12:41.4612898Z ==============================================================================
2018-02-27T18:12:41.4628162Z Task : Azure CLI
2018-02-27T18:12:41.4642343Z Description : Run a Shell or Batch script with Azure CLI commands against an azure subscription
2018-02-27T18:12:41.4656829Z Version : 1.130.0
2018-02-27T18:12:41.4671633Z Author : Microsoft Corporation
2018-02-27T18:12:41.4686463Z Help : [More Information](http://go.microsoft.com/fwlink/?LinkID=827160)
2018-02-27T18:12:41.4701934Z ==============================================================================
2018-02-27T18:12:43.1606295Z ##[debug]agent.workFolder=/opt/vsts/work
2018-02-27T18:12:43.1633569Z ##[debug]loading inputs and endpoints
2018-02-27T18:12:43.1660490Z ##[debug]loading INPUT_CONNECTEDSERVICENAMEARM
2018-02-27T18:12:43.1689378Z ##[debug]loading INPUT_SCRIPTLOCATION
2018-02-27T18:12:43.1722079Z ##[debug]loading INPUT_SCRIPTPATH
2018-02-27T18:12:43.1745656Z ##[debug]loading INPUT_INLINESCRIPT
2018-02-27T18:12:43.1768377Z ##[debug]loading INPUT_CWD
2018-02-27T18:12:43.1791483Z ##[debug]loading INPUT_FAILONSTANDARDERROR
2018-02-27T18:12:43.1817864Z ##[debug]loading ENDPOINT_AUTH_af68dcbd-55f0-447c-9c67-8f8c1fc3b5b9
2018-02-27T18:12:43.1847121Z ##[debug]loading ENDPOINT_AUTH_SCHEME_af68dcbd-55f0-447c-9c67-8f8c1fc3b5b9
2018-02-27T18:12:43.1873242Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_af68dcbd-55f0-447c-9c67-8f8c1fc3b5b9_SERVICEPRINCIPALID
2018-02-27T18:12:43.1901373Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_af68dcbd-55f0-447c-9c67-8f8c1fc3b5b9_SERVICEPRINCIPALKEY
2018-02-27T18:12:43.1929312Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_af68dcbd-55f0-447c-9c67-8f8c1fc3b5b9_TENANTID
2018-02-27T18:12:43.1953936Z ##[debug]loading ENDPOINT_AUTH_SYSTEMVSSCONNECTION
2018-02-27T18:12:43.1977635Z ##[debug]loading ENDPOINT_AUTH_SCHEME_SYSTEMVSSCONNECTION
2018-02-27T18:12:43.2000850Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_SYSTEMVSSCONNECTION_ACCESSTOKEN
2018-02-27T18:12:43.2025522Z ##[debug]loaded 14
2018-02-27T18:12:43.2050235Z ##[debug]check path : /opt/vsts/work/_tasks/AzureCLI_46e4be58-730b-4389-8a2f-ea10b3e5e815/1.130.0/task.json
2018-02-27T18:12:43.2077832Z ##[debug]set resource file to: /opt/vsts/work/_tasks/AzureCLI_46e4be58-730b-4389-8a2f-ea10b3e5e815/1.130.0/task.json
2018-02-27T18:12:43.2106084Z ##[debug]system.culture=en-US
2018-02-27T18:12:43.2131985Z ##[debug]az=/usr/bin/az
2018-02-27T18:12:43.2157804Z ##[debug]check path : /bin/bash
2018-02-27T18:12:43.2183002Z ##[debug]bash=/bin/bash
2018-02-27T18:12:43.2206788Z ##[debug]scriptLocation=inlineScript
2018-02-27T18:12:43.2230636Z ##[debug]cwd=/opt/vsts/work/1/s
2018-02-27T18:12:43.2259870Z ##[debug]inlineScript=az storage file download --account-name builddep --share-name builddep --path $PACKAGENAME.zip
2018-02-27T18:12:43.2286304Z ##[debug]args=null
2018-02-27T18:12:43.2310856Z ##[debug]failOnStandardError=true
2018-02-27T18:12:43.2335870Z ##[debug]testing directory '/opt/vsts/work/1/s'
2018-02-27T18:12:43.2361339Z ##[debug]/bin/bash arg: /tmp/azureclitaskscript1519755163164.sh
2018-02-27T18:12:43.2389165Z ##[debug]connectedServiceNameARM=af68dcbd-55f0-447c-9c67-8f8c1fc3b5b9
2018-02-27T18:12:43.2417999Z ##[debug]af68dcbd-55f0-447c-9c67-8f8c1fc3b5b9 auth param serviceprincipalid = ********
2018-02-27T18:12:43.2454580Z ##[debug]af68dcbd-55f0-447c-9c67-8f8c1fc3b5b9 auth param serviceprincipalkey = ********
2018-02-27T18:12:43.2490884Z ##[debug]af68dcbd-55f0-447c-9c67-8f8c1fc3b5b9 auth param tenantid = ********
2018-02-27T18:12:43.2517883Z ##[debug]af68dcbd-55f0-447c-9c67-8f8c1fc3b5b9 data SubscriptionName = Internal
2018-02-27T18:12:43.2544612Z ##[debug]check path : /usr/bin/az
2018-02-27T18:12:43.2570793Z ##[debug]az=/usr/bin/az
2018-02-27T18:12:43.2597775Z ##[debug]/usr/bin/az arg: login --service-principal -u "********" -p ******** --tenant "********"
2018-02-27T18:12:43.2626792Z ##[debug]/usr/bin/az arg: login --service-principal -u "********" -p ******** --tenant "********"
2018-02-27T18:12:43.2651743Z ##[debug]exec tool: /usr/bin/az
2018-02-27T18:12:43.2678416Z ##[debug]exec tool: /usr/bin/az
2018-02-27T18:12:43.2700985Z ##[debug]Arguments:
2018-02-27T18:12:43.2723627Z ##[debug]Arguments:
2018-02-27T18:12:43.2746497Z ##[debug] login
2018-02-27T18:12:43.2772399Z ##[debug] login
2018-02-27T18:12:43.2796789Z ##[debug] --service-principal
2018-02-27T18:12:43.2823308Z ##[debug] --service-principal
2018-02-27T18:12:43.2849232Z ##[debug] -u
2018-02-27T18:12:43.2875323Z ##[debug] -u
2018-02-27T18:12:43.2905554Z ##[debug] ********
2018-02-27T18:12:43.2929850Z ##[debug] ********
2018-02-27T18:12:43.2954185Z ##[debug] -p
2018-02-27T18:12:43.2983370Z ##[debug] -p
2018-02-27T18:12:43.3012114Z ##[debug] ********
2018-02-27T18:12:43.3034837Z ##[debug] ********
2018-02-27T18:12:43.3059255Z ##[debug] --tenant
2018-02-27T18:12:43.3099072Z ##[debug] --tenant
2018-02-27T18:12:43.3126215Z ##[debug] ********
2018-02-27T18:12:43.3150432Z ##[debug] ********
2018-02-27T18:12:43.3168527Z [command]/usr/bin/az login --service-principal -u ******** -p ******** --tenant ********
2018-02-27T18:12:53.5716651Z [
2018-02-27T18:12:53.5732517Z {
2018-02-27T18:12:53.5750306Z "cloudName": "AzureCloud",
2018-02-27T18:12:53.5766010Z "id": "cb4970ea-4a04-40b6-8177-ab021cc5690f",
2018-02-27T18:12:53.5783002Z "isDefault": true,
2018-02-27T18:12:53.5797086Z "name": "Internal",
2018-02-27T18:12:53.5811485Z "state": "Enabled",
2018-02-27T18:12:53.5828096Z "tenantId": "********",
2018-02-27T18:12:53.5842070Z "user": {
2018-02-27T18:12:53.5858139Z "name": "********",
2018-02-27T18:12:53.5872510Z "type": "servicePrincipal"
2018-02-27T18:12:53.5886925Z }
2018-02-27T18:12:53.5905142Z }
2018-02-27T18:12:53.5923833Z ]
2018-02-27T18:12:53.5947835Z ##[debug]check path : /usr/bin/az
2018-02-27T18:12:53.5970563Z ##[debug]az=/usr/bin/az
2018-02-27T18:12:53.5994896Z ##[debug]/usr/bin/az arg: account set --subscription "Internal"
2018-02-27T18:12:53.6022393Z ##[debug]/usr/bin/az arg: account set --subscription "Internal"
2018-02-27T18:12:53.6049645Z ##[debug]exec tool: /usr/bin/az
2018-02-27T18:12:53.6073969Z ##[debug]exec tool: /usr/bin/az
2018-02-27T18:12:53.6097721Z ##[debug]Arguments:
2018-02-27T18:12:53.6124056Z ##[debug]Arguments:
2018-02-27T18:12:53.6149083Z ##[debug] account
2018-02-27T18:12:53.6174451Z ##[debug] account
2018-02-27T18:12:53.6198100Z ##[debug] set
2018-02-27T18:12:53.6222929Z ##[debug] set
2018-02-27T18:12:53.6247350Z ##[debug] --subscription
2018-02-27T18:12:53.6273927Z ##[debug] --subscription
2018-02-27T18:12:53.6297976Z ##[debug] Internal
2018-02-27T18:12:53.6321123Z ##[debug] Internal
2018-02-27T18:12:53.6337307Z [command]/usr/bin/az account set --subscription Internal
2018-02-27T18:12:54.4233510Z ##[debug]exec tool: /bin/bash
2018-02-27T18:12:54.4256887Z ##[debug]Arguments:
2018-02-27T18:12:54.4280577Z ##[debug] /tmp/azureclitaskscript1519755163164.sh
2018-02-27T18:12:54.4295293Z [command]/bin/bash /tmp/azureclitaskscript1519755163164.sh
2018-02-27T18:12:57.0221249Z
2018-02-27T18:12:57.0239002Z Alive[################################################################] 100.0000%
2018-02-27T18:12:57.0408120Z Finished[#############################################################] 100.0000%
2018-02-27T18:12:57.0424724Z {
2018-02-27T18:12:57.0439688Z "content": null,
2018-02-27T18:12:57.0456418Z "metadata": {},
2018-02-27T18:12:57.0474047Z "name": "package.zip",
2018-02-27T18:12:57.0490449Z "properties": {
2018-02-27T18:12:57.0504589Z "contentLength": 16365416,
2018-02-27T18:12:57.0520631Z "contentRange": "bytes 0-16365415/16365416",
2018-02-27T18:12:57.0536590Z "contentSettings": {
2018-02-27T18:12:57.0555404Z "cacheControl": null,
2018-02-27T18:12:57.0570165Z "contentDisposition": null,
2018-02-27T18:12:57.0665590Z "contentEncoding": null,
2018-02-27T18:12:57.0681069Z "contentLanguage": null,
2018-02-27T18:12:57.0695566Z "contentType": null
2018-02-27T18:12:57.0710892Z },
2018-02-27T18:12:57.0725280Z "copy": {
2018-02-27T18:12:57.0820964Z "completionTime": null,
2018-02-27T18:12:57.0837878Z "id": null,
2018-02-27T18:12:57.0863189Z "progress": null,
2018-02-27T18:12:57.0881693Z "source": null,
2018-02-27T18:12:57.0896123Z "status": null,
2018-02-27T18:12:57.0995367Z "statusDescription": null
2018-02-27T18:12:57.1010192Z },
2018-02-27T18:12:57.1024783Z "etag": "\"0x8D57A3B4DE2C899\"",
2018-02-27T18:12:57.1041753Z "lastModified": "2018-02-22T21:29:07+00:00",
2018-02-27T18:12:57.1058825Z "serverEncrypted": true
2018-02-27T18:12:57.1196221Z }
2018-02-27T18:12:57.1210300Z }
2018-02-27T18:12:57.4209475Z ##[debug]rc:0
2018-02-27T18:12:57.4232988Z ##[debug]success:false
2018-02-27T18:12:57.4263585Z ##[debug]check path : /usr/bin/az
2018-02-27T18:12:57.4287110Z ##[debug]az=/usr/bin/az
2018-02-27T18:12:57.4310513Z ##[debug]/usr/bin/az arg: account clear
2018-02-27T18:12:57.4333098Z ##[debug]/usr/bin/az arg: account clear
2018-02-27T18:12:57.4356669Z ##[debug]exec tool: /usr/bin/az
2018-02-27T18:12:57.4384192Z ##[debug]exec tool: /usr/bin/az
2018-02-27T18:12:57.4407116Z ##[debug]Arguments:
2018-02-27T18:12:57.4430635Z ##[debug]Arguments:
2018-02-27T18:12:57.4456033Z ##[debug] account
2018-02-27T18:12:57.4484368Z ##[debug] account
2018-02-27T18:12:57.4518856Z ##[debug] clear
2018-02-27T18:12:57.4543182Z ##[debug] clear
2018-02-27T18:12:57.4558415Z [command]/usr/bin/az account clear
2018-02-27T18:12:58.3529617Z ##[debug]task result: Failed
2018-02-27T18:12:58.3626548Z ##[error]Script failed with error: Error: /bin/bash failed with return code: 0
2018-02-27T18:12:58.3667232Z ##[debug]Processed: ##vso[task.issue type=error;]Script failed with error: Error: /bin/bash failed with return code: 0
2018-02-27T18:12:58.3727328Z ##[debug]Processed: ##vso[task.complete result=Failed;]Script failed with error: Error: /bin/bash failed with return code: 0
2018-02-27T18:12:58.4516730Z ##[section]Finishing: Download dependencies
Release
MirzaSikander
👍2
All 27 comments
It seems the inline script command being executed is writing some message to āstderrā stream. This can be taken care by unchecking the āFail on stderrā input in the task. Kindly try this once and let me know if this works.
We would recommend to uncheck āFail on stderrā for Azure-CLI task in existing RD/BD. We have also made it āfalseā by default in the task so any new instance of the task will not face this issue.
hiyadav
on 28 Feb 2018
This is still an active issue and it is not fixed yet.
The solution suggested by @hiyadav cannot be applied in all circumstances because it will falsely cover all the actual errors as well which is not the right way of recovering from this.
farchide
on 30 Jan 2019
👍2
I have noticed when the rhel agent is running the agent executable in the systemd mode, it fails. but when you run the agent in the interactive mode, it goes through
farchide
on 30 Jan 2019
@farchide The FailOnStandardError if enabled, fails the task if any message is written to standard error stream, whereas the commands execution success criteria can be determined by its exit status code, which is the recommended way of finding out if the command ran successfully or has no zero error code.
However with newer versions of Azure CLI, the task doesn't seem to be failing even with "FailOnStandardError = true" on Hosted Agent Pools. If it is failing for you, can you try updating the Azure CLI version.
Else for help us debugging can you share task failure logs with us ?
hiyadav
on 31 Jan 2019
@hiyadav thanks for your answer
the az cli is the latest version available (2.0.55)
as I have mentioned before, the weird thing is when the tfs agent is in the interactive mode (./run.sh) it goes through fine. but when I put the agent in the serviced mode it gives me the error that I have mentioned.
And also "FailOnStandardError = false" is not an option for me since I want to fail the build process when an actual error is happening. If I change the variable to "true" it never fails and I cannot use it.
Is there any other workaround available?
farchide
on 31 Jan 2019
👍3
@farchide
If the script is throwing an error (writing something to stderr) which is leading for the task to fail when FailOnStandardError=true.
To avoid the failure, you might need to redirect the standard error stream to standard output for executing that command in the script. this way you will be able to see the error inside the output of the script and any other error will not get masked.
If this doesn't help, can you share the release/build logs with system.debug=true
hiyadav
on 1 Feb 2019
👍1
This workaround doesn't work:
- It's not our script that is writing to stderr. It's the task writing to stderr when it is calling
az account clear FailOnStandardErroris false on our task
mydiemho
on 7 Mar 2019
👍2
build without debug:
https://dev.azure.com/msft-vott/VoTT/_build/results?buildId=1540
build with debug on:
https://dev.azure.com/msft-vott/VoTT/_build/results?buildId=1614
mydiemho
on 7 Mar 2019
digging deeper, there does seem to be a Blocking I/O error, so this might be an azure-cli issue and not the task
ERROR: [Errno 11] write could not complete without blocking
Traceback (most recent call last):
File "/opt/az/lib/python3.6/site-packages/knack/cli.py", line 212, in invoke
self.output.out(cmd_result, formatter=formatter, out_file=out_file)
File "/opt/az/lib/python3.6/site-packages/knack/output.py", line 134, in out
print(output, file=out_file, end='')
BlockingIOError: [Errno 11] write could not complete without blocking
@mydiemho in your case the az command itself is failing with exit code 1. The task will fail if exit code is non-zero irrespective of FailOnStandardError
[error]Script failed with error: Error: /bin/bash failed with return code: 1
It looks like it fails in uploading a file:
{
"Blob": "https://vottv2.blob.core.windows.net/$web/files/react_components_pages_editorPage_editorSideBar_jsx/report.history.js",
"Last Modified": "2
ERROR: [Errno 11] write could not complete without blocking
Traceback (most recent call last):
File "/opt/az/lib/python3.6/site-packages/knack/cli.py", line 212, in invoke
self.output.out(cmd_result, formatter=formatter, out_file=out_file)
File "/opt/az/lib/python3.6/site-packages/knack/output.py", line 134, in out
print(output, file=out_file, end='')
BlockingIOError: [Errno 11] write could not complete without blocking
019-03-07T22:34:23+00:00",
"Type": "application/javascript",
"eTag": ""0x8D6A34D0CA57F9D""
},
You can think about putting a retry in your script.
bishal-pdMSFT
on 8 Mar 2019
@bishal-pdMSFT yes I have posted the same error in the comment above yours.
Also to note, even with this error, all the files in my Azure Blob is updated.
I have come to the conclusion that the broken change is with the azure storage command as the OP and I are both using that in our script. Will create issue on the azure cli repo.
OP
az storage file download --account-name builddep --share-name builddep --path $PACKAGENAME.zip
Me
az storage blob upload-batch -d '$web' -s report
@mydiemho We could not reproduce it yet, but we suspect it's because of the large amount of logs printed to console. Could you try redirecting stdout to a temp file, to see if it works?
In your case
az storage blob upload-batch -d '$web' -s report > tempfile
If it works, could you use cat command to print the tempfile contents and let us know?
issacnitin
on 15 Mar 2019
@issacnitin
here's a sample build with log
https://dev.azure.com/msft-vott/VoTT/_build/results?buildId=1861
Strangely, the build didn't throw any error when I pipe the log to a file
mydiemho
on 19 Mar 2019
I'm getting the same when triggering acr build from within the CLI task. Even with the output from each command sent to a log file.
From what I gather, az acr build is printing some warnings to STDERR causing this to fail, even though the exit code is 0. Is there an option to fail on a non-zero exit code, but allow writing to the STDERR stream? (the expected default for almost anything anywhere).
jlorich
on 26 Mar 2019
@jlorich This usually happens when "Fail on Standard Error" option is checked in Azure CLI task. Can you try running the task again with the option unchecked?
If it fails again, could you provide the logs with variable system.debug set to True?
Thanks!
issacnitin
on 28 Mar 2019
@jlorich - I assume your issue is resolved with @issacnitin's suggestion above and hence closing this. If you are still facing the issue, feel free to reactivate this issue or open a new one.
amaljg
on 3 Apr 2019
Hi @amaljg,
We are facing the same issue while using TFS tasks after the update of "az cli" to version 2.0.74. The TFS task automatically executes the "az account clear" command, which writes in the error stream.
Setting "Fail on standard error" to "false" is not an option, it's a dirty hack that allows errors to left unseen while running the releases to production env. In other words, it's not acceptable to most of our production pipeline deployments.
Do you have any other suggestions? If possible, please reopen this issue.
dmitrykarnitski
on 27 Sep 2019
@dikhakha / @bishal-pdMSFT - Can you help here?
amaljg
on 27 Sep 2019
@dmitrykarnitski Can you please share the debug logs of your pipeline run where this task is failing.
dikhakha
on 1 Oct 2019
Hi @dikhakha, I work with @dmitrykarnitski
logs with debug mode:
2019-10-01T08:51:03.6221810Z ##[section]Starting: Add firewall rules to DW for Toronto office
2019-10-01T08:51:03.6449519Z ==============================================================================
2019-10-01T08:51:03.6449758Z Task : Azure CLI
2019-10-01T08:51:03.6449971Z Description : Run a Shell or Batch script with Azure CLI commands against an azure subscription
2019-10-01T08:51:03.6450158Z Version : 1.130.0
2019-10-01T08:51:03.6450309Z Author : Microsoft Corporation
2019-10-01T08:51:03.6450700Z Help : [More Information](http://go.microsoft.com/fwlink/?LinkID=827160)
2019-10-01T08:51:03.6450910Z ==============================================================================
2019-10-01T08:51:03.9495665Z [command]C:\Windows\system32\cmd.exe /D /S /C ""C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd" login --service-principal -u *** -p *** --tenant ***"
2019-10-01T08:51:06.1527130Z [
2019-10-01T08:51:06.1527986Z {
2019-10-01T08:51:06.1528234Z "cloudName": "AzureCloud",
2019-10-01T08:51:06.1528504Z "id": "<subscription>",
2019-10-01T08:51:06.1528666Z "isDefault": true,
2019-10-01T08:51:06.1528813Z "name": "<subscription name>",
2019-10-01T08:51:06.1528986Z "state": "Enabled",
2019-10-01T08:51:06.1529245Z "tenantId": "***",
2019-10-01T08:51:06.1529403Z "user": {
2019-10-01T08:51:06.1529884Z "name": "***",
2019-10-01T08:51:06.1530291Z "type": "servicePrincipal"
2019-10-01T08:51:06.1530519Z }
2019-10-01T08:51:06.1530699Z }
2019-10-01T08:51:06.1530814Z ]
2019-10-01T08:51:06.1544854Z [command]C:\Windows\system32\cmd.exe /D /S /C ""C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd" account set --subscription DCO-LES-EBH-N"
2019-10-01T08:51:07.5350485Z [command]C:\Windows\system32\cmd.exe /D /S /C "C:\Users\ebhadmin\AppData\Local\Temp\azureclitaskscript1569919863928.bat"
2019-10-01T08:51:07.6479451Z
2019-10-01T08:51:07.6480100Z E:\Agent-EBH-BUILD01\_work\r52\a>powershell.exe -File Build-EBH-Reporting-Deployment-Scripts/deployment-scripts/sql-database/add-firewall-rules.ps1 -StartIpAddress "<ip address here>" -EndIpAddress "<ip address here>" -RuleName "Toronto-Office"
2019-10-01T08:51:08.6506353Z DEBUG: Command arguments: ['sql', 'server', 'firewall-rule', 'create', '-g', '<resource group name>', '-s', '<server name>', '-n', 'Toronto-Office', '--start-ip-address', '<ip address here>', '--end-ip-address', '<ip address here>', '--debug']
2019-10-01T08:51:08.6506863Z DEBUG: Event: Cli.PreExecute []
2019-10-01T08:51:08.6507549Z DEBUG: Event: CommandParser.OnGlobalArgumentsCreate [<function CLILogging.on_global_arguments at 0x0215AE88>, <function OutputProducer.on_global_arguments at 0x02198B70>, <function CLIQuery.on_global_arguments at 0x021BFC48>]
2019-10-01T08:51:08.6913701Z DEBUG: Event: CommandInvoker.OnPreCommandTableCreate []
2019-10-01T08:51:08.7019407Z DEBUG: Installed command modules ['acr', 'acs', 'advisor', 'ams', 'apim', 'appconfig', 'appservice', 'backup', 'batch', 'batchai', 'billing', 'botservice', 'cdn', 'cloud', 'cognitiveservices', 'configure', 'consumption', 'container', 'cosmosdb', 'deploymentmanager', 'dla', 'dls', 'dms', 'eventgrid', 'eventhubs', 'extension', 'feedback', 'find', 'hdinsight', 'interactive', 'iot', 'iotcentral', 'keyvault', 'kusto', 'lab', 'managedservices', 'maps', 'monitor', 'natgateway', 'netappfiles', 'network', 'policyinsights', 'privatedns', 'profile', 'rdbms', 'redis', 'relay', 'reservations', 'resource', 'role', 'search', 'security', 'servicebus', 'servicefabric', 'signalr', 'sql', 'sqlvm', 'storage', 'vm']
2019-10-01T08:51:08.7074370Z DEBUG: Loaded module 'acr' in 0.005 seconds.
2019-10-01T08:51:08.7156960Z DEBUG: Loaded module 'acs' in 0.008 seconds.
2019-10-01T08:51:08.7177165Z DEBUG: Loaded module 'advisor' in 0.002 seconds.
2019-10-01T08:51:08.7189124Z DEBUG: Event: CommandLoader.OnLoadCommandTable []
2019-10-01T08:51:08.7246473Z DEBUG: Loaded module 'ams' in 0.007 seconds.
2019-10-01T08:51:08.7271051Z DEBUG: Loaded module 'apim' in 0.002 seconds.
2019-10-01T08:51:08.7300165Z DEBUG: Loaded module 'appconfig' in 0.003 seconds.
2019-10-01T08:51:08.7403689Z DEBUG: Loaded module 'appservice' in 0.010 seconds.
2019-10-01T08:51:08.7442058Z DEBUG: Loaded module 'backup' in 0.004 seconds.
2019-10-01T08:51:08.7484158Z DEBUG: Event: CommandLoader.OnLoadCommandTable []
2019-10-01T08:51:08.7547894Z DEBUG: Loaded module 'batch' in 0.010 seconds.
2019-10-01T08:51:08.7587011Z DEBUG: Loaded module 'batchai' in 0.004 seconds.
2019-10-01T08:51:08.7609448Z DEBUG: Loaded module 'billing' in 0.002 seconds.
2019-10-01T08:51:08.7654507Z DEBUG: Loaded module 'botservice' in 0.004 seconds.
2019-10-01T08:51:08.7666497Z DEBUG: Event: CommandLoader.OnLoadCommandTable []
2019-10-01T08:51:08.7688198Z DEBUG: Loaded module 'cdn' in 0.003 seconds.
2019-10-01T08:51:08.7718338Z DEBUG: Loaded module 'cloud' in 0.003 seconds.
2019-10-01T08:51:08.7740750Z DEBUG: Loaded module 'cognitiveservices' in 0.002 seconds.
2019-10-01T08:51:08.7757834Z DEBUG: Loaded module 'configure' in 0.001 seconds.
2019-10-01T08:51:08.7789572Z DEBUG: Loaded module 'consumption' in 0.003 seconds.
2019-10-01T08:51:08.7815590Z DEBUG: Loaded module 'container' in 0.002 seconds.
2019-10-01T08:51:08.7894279Z DEBUG: Loaded module 'cosmosdb' in 0.008 seconds.
2019-10-01T08:51:08.7924781Z DEBUG: Loaded module 'deploymentmanager' in 0.003 seconds.
2019-10-01T08:51:08.7980246Z DEBUG: Loaded module 'dla' in 0.005 seconds.
2019-10-01T08:51:08.8020395Z DEBUG: Loaded module 'dls' in 0.004 seconds.
2019-10-01T08:51:08.8050596Z DEBUG: Loaded module 'dms' in 0.003 seconds.
2019-10-01T08:51:08.8086268Z DEBUG: Loaded module 'eventgrid' in 0.003 seconds.
2019-10-01T08:51:08.8133950Z DEBUG: Loaded module 'eventhubs' in 0.005 seconds.
2019-10-01T08:51:08.8149108Z DEBUG: Loaded module 'extension' in 0.001 seconds.
2019-10-01T08:51:08.8160272Z DEBUG: Loaded module 'feedback' in 0.001 seconds.
2019-10-01T08:51:08.8175197Z DEBUG: Loaded module 'find' in 0.001 seconds.
2019-10-01T08:51:08.8209079Z DEBUG: Loaded module 'hdinsight' in 0.003 seconds.
2019-10-01T08:51:08.8221101Z DEBUG: Loaded module 'interactive' in 0.001 seconds.
2019-10-01T08:51:08.8282391Z DEBUG: Loaded module 'iot' in 0.005 seconds.
2019-10-01T08:51:08.8297609Z DEBUG: Loaded module 'iotcentral' in 0.002 seconds.
2019-10-01T08:51:08.8356971Z DEBUG: Loaded module 'keyvault' in 0.006 seconds.
2019-10-01T08:51:08.8384776Z DEBUG: Loaded module 'kusto' in 0.003 seconds.
2019-10-01T08:51:08.8440673Z DEBUG: Loaded module 'lab' in 0.005 seconds.
2019-10-01T08:51:08.8465906Z DEBUG: Loaded module 'managedservices' in 0.002 seconds.
2019-10-01T08:51:08.8491065Z DEBUG: Loaded module 'maps' in 0.002 seconds.
2019-10-01T08:51:08.8560679Z DEBUG: Loaded module 'monitor' in 0.007 seconds.
2019-10-01T08:51:08.8580414Z DEBUG: Loaded module 'natgateway' in 0.002 seconds.
2019-10-01T08:51:08.8591319Z DEBUG: Event: CommandLoader.OnLoadCommandTable []
2019-10-01T08:51:08.8629654Z DEBUG: Loaded module 'netappfiles' in 0.005 seconds.
2019-10-01T08:51:08.8936731Z DEBUG: Loaded module 'network' in 0.031 seconds.
2019-10-01T08:51:08.8961619Z DEBUG: Loaded module 'policyinsights' in 0.002 seconds.
2019-10-01T08:51:08.9017276Z DEBUG: Loaded module 'privatedns' in 0.005 seconds.
2019-10-01T08:51:08.9038004Z DEBUG: Loaded module 'profile' in 0.002 seconds.
2019-10-01T08:51:08.9105508Z DEBUG: Loaded module 'rdbms' in 0.007 seconds.
2019-10-01T08:51:08.9140858Z DEBUG: Loaded module 'redis' in 0.003 seconds.
2019-10-01T08:51:08.9179151Z DEBUG: Loaded module 'relay' in 0.004 seconds.
2019-10-01T08:51:08.9204534Z DEBUG: Loaded module 'reservations' in 0.002 seconds.
2019-10-01T08:51:08.9279830Z DEBUG: Loaded module 'resource' in 0.007 seconds.
2019-10-01T08:51:08.9329586Z DEBUG: Loaded module 'role' in 0.005 seconds.
2019-10-01T08:51:08.9351287Z DEBUG: Loaded module 'search' in 0.002 seconds.
2019-10-01T08:51:08.9381579Z DEBUG: Loaded module 'security' in 0.003 seconds.
2019-10-01T08:51:08.9439977Z DEBUG: Loaded module 'servicebus' in 0.006 seconds.
2019-10-01T08:51:08.9470157Z DEBUG: Loaded module 'servicefabric' in 0.003 seconds.
2019-10-01T08:51:08.9490828Z DEBUG: Loaded module 'signalr' in 0.002 seconds.
2019-10-01T08:51:08.9573821Z DEBUG: Loaded module 'sql' in 0.008 seconds.
2019-10-01T08:51:08.9605709Z DEBUG: Loaded module 'sqlvm' in 0.003 seconds.
2019-10-01T08:51:08.9622225Z DEBUG: Event: CommandLoader.OnLoadCommandTable []
2019-10-01T08:51:08.9943532Z DEBUG: Loaded module 'storage' in 0.034 seconds.
2019-10-01T08:51:09.0117614Z DEBUG: Loaded module 'vm' in 0.017 seconds.
2019-10-01T08:51:09.0122232Z DEBUG: Loaded all modules in 0.302 seconds. (note: there's always an overhead with the first module loaded)
2019-10-01T08:51:09.0146067Z DEBUG: Extensions directory: 'C:\Users\ebhadmin\.azure\cliextensions'
2019-10-01T08:51:09.0157738Z DEBUG: Event: CommandInvoker.OnPreCommandTableTruncate [<function AzCliLogging.init_command_file_logging at 0x02219078>]
2019-10-01T08:51:09.0175374Z INFO: az_command_data_logger : command args: sql server firewall-rule create -g {} -s {} -n {} --start-ip-address {} --end-ip-address {} --debug
2019-10-01T08:51:09.0176077Z DEBUG: metadata file logging enabled - writing logs to 'C:\Users\ebhadmin\.azure\commands'.
2019-10-01T08:51:09.0191396Z DEBUG: Event: CommandInvoker.OnPreArgumentLoad [<function register_global_subscription_argument.<locals>.add_subscription_parameter at 0x02252A08>]
2019-10-01T08:51:09.1941692Z DEBUG: Event: CommandInvoker.OnPostArgumentLoad []
2019-10-01T08:51:09.1942741Z DEBUG: Event: CommandInvoker.OnPostCommandTableCreate [<function register_ids_argument.<locals>.add_ids_arguments at 0x02252A50>, <function register_cache_arguments.<locals>.add_cache_arguments at 0x02252C48>]
2019-10-01T08:51:09.1961525Z DEBUG: Event: CommandInvoker.OnCommandTableLoaded []
2019-10-01T08:51:09.1962601Z DEBUG: Event: CommandInvoker.OnPreParseArgs [<function _documentdb_deprecate at 0x02FFB300>]
2019-10-01T08:51:09.1979003Z DEBUG: Event: CommandInvoker.OnPostParseArgs [<function OutputProducer.handle_output_argument at 0x02198BB8>, <function CLIQuery.handle_query_parameter at 0x021BFC90>, <function register_ids_argument.<locals>.parse_ids_arguments at 0x02252C00>, <function handler at 0x030D5198>]
2019-10-01T08:51:09.3556886Z DEBUG: Getting management service client client_type=SqlManagementClient
2019-10-01T08:51:09.3851459Z DEBUG: msrest.universal_http.requests : Configuring retry: max_retries=4, backoff_factor=0.8, max_backoff=90
2019-10-01T08:51:09.3866549Z DEBUG: attempting to read file C:\Users\ebhadmin\.azure\accessTokens.json as utf-8-sig
2019-10-01T08:51:09.3876112Z DEBUG: adal-python : 0196b3df-305d-463b-9522-23b4ed8c6967 - Authority:Performing instance discovery: ...
2019-10-01T08:51:09.3876620Z DEBUG: adal-python : 0196b3df-305d-463b-9522-23b4ed8c6967 - Authority:Performing static instance discovery
2019-10-01T08:51:09.3876979Z DEBUG: adal-python : 0196b3df-305d-463b-9522-23b4ed8c6967 - Authority:Authority validated via static instance discovery
2019-10-01T08:51:09.3878122Z DEBUG: adal-python : 0196b3df-305d-463b-9522-23b4ed8c6967 - TokenRequest:Getting token with client credentials.
2019-10-01T08:51:09.3879517Z DEBUG: adal-python : 0196b3df-305d-463b-9522-23b4ed8c6967 - TokenRequest:No user_id passed for cache query
2019-10-01T08:51:09.3881208Z DEBUG: adal-python : 0196b3df-305d-463b-9522-23b4ed8c6967 - CacheDriver:finding with query keys: {'_clientId': '...'}
2019-10-01T08:51:09.3881722Z DEBUG: adal-python : 0196b3df-305d-463b-9522-23b4ed8c6967 - CacheDriver:Looking for potential cache entries: {'_clientId': '...'}
2019-10-01T08:51:09.3882934Z DEBUG: adal-python : 0196b3df-305d-463b-9522-23b4ed8c6967 - CacheDriver:Found 0 potential entries.
2019-10-01T08:51:09.3925673Z DEBUG: urllib3.connectionpool : Starting new HTTPS connection (1): login.microsoftonline.com:443
2019-10-01T08:51:09.6060333Z DEBUG: urllib3.connectionpool : https://login.microsoftonline.com:443 "POST /***/oauth2/token HTTP/1.1" 200 1354
2019-10-01T08:51:09.6085815Z DEBUG: adal-python : 0196b3df-305d-463b-9522-23b4ed8c6967 - OAuth2Client:Get Token Server returned this correlation_id: 0196b3df-305d-463b-9522-23b4ed8c6967
2019-10-01T08:51:09.6088693Z DEBUG: adal-python : 0196b3df-305d-463b-9522-23b4ed8c6967 - CacheDriver:Adding entry AccessTokenId: b'MZFTduBGucKgC6Z++lF0wtQ8NgmEpdKp39kO6sofZfk='
2019-10-01T08:51:09.6089134Z DEBUG: adal-python : 0196b3df-305d-463b-9522-23b4ed8c6967 - CacheDriver:Added entry is MRRT
2019-10-01T08:51:09.6091208Z DEBUG: msrest.http_logger : Request URL: 'https://management.azure.com/subscriptions/<subscription>/resourceGroups/<resource group name>/providers/Microsoft.Sql/servers/<sql server name>/firewallRules/Toronto-Office?api-version=2014-04-01'
2019-10-01T08:51:09.6092157Z DEBUG: msrest.http_logger : Request method: 'PUT'
2019-10-01T08:51:09.6092912Z DEBUG: msrest.http_logger : Request headers:
2019-10-01T08:51:09.6093876Z DEBUG: msrest.http_logger : 'Accept': 'application/json'
2019-10-01T08:51:09.6094479Z DEBUG: msrest.http_logger : 'Content-Type': 'application/json; charset=utf-8'
2019-10-01T08:51:09.6097002Z DEBUG: msrest.http_logger : 'accept-language': 'en-US'
2019-10-01T08:51:09.6097679Z DEBUG: msrest.http_logger : 'Content-Length': '86'
2019-10-01T08:51:09.6100134Z DEBUG: msrest.http_logger : 'User-Agent': 'python/3.6.6 (Windows-2012ServerR2-6.3.9600-SP0) msrest/0.6.10 TFS_abfb1e58-9bdc-49f2-bb19-308d48ee45a3_release_11_1055_1892_3 msrest_azure/0.6.2 azure-mgmt-sql/0.12.0 Azure-SDK-For-Python AZURECLI/2.0.74 TFS_abfb1e58-9bdc-49f2-bb19-308d48ee45a3_release_11_1055_1892_3'
2019-10-01T08:51:09.6100545Z DEBUG: msrest.http_logger : Request body:
2019-10-01T08:51:09.6101295Z DEBUG: msrest.http_logger : {"properties": {"startIpAddress": "<ip address here>", "endIpAddress": "<ip address here>"}}
2019-10-01T08:51:09.6102204Z DEBUG: msrest.universal_http : Configuring redirects: allow=True, max=30
2019-10-01T08:51:09.6103988Z DEBUG: msrest.universal_http : Configuring request: timeout=100, verify=True, cert=None
2019-10-01T08:51:09.6104853Z DEBUG: msrest.universal_http : Configuring proxies: ''
2019-10-01T08:51:09.6111207Z DEBUG: msrest.universal_http : Evaluate proxies against ENV settings: True
2019-10-01T08:51:09.6146047Z DEBUG: urllib3.connectionpool : Starting new HTTPS connection (1): management.azure.com:443
2019-10-01T08:51:11.3108632Z DEBUG: urllib3.connectionpool : https://management.azure.com:443 "PUT /subscriptions/<subscription>/resourceGroups/<resource group name>/providers/Microsoft.Sql/servers/<server name>/firewallRules/Toronto-Office?api-version=2014-04-01 HTTP/1.1" 200 None
2019-10-01T08:51:11.3119939Z DEBUG: msrest.http_logger : Response status: 200
2019-10-01T08:51:11.3120198Z DEBUG: msrest.http_logger : Response headers:
2019-10-01T08:51:11.3120383Z DEBUG: msrest.http_logger : 'Cache-Control': 'no-store, no-cache'
2019-10-01T08:51:11.3120766Z DEBUG: msrest.http_logger : 'Transfer-Encoding': 'chunked'
2019-10-01T08:51:11.3121848Z DEBUG: msrest.http_logger : 'Content-Type': 'application/json; odata=minimalmetadata; streaming=true; charset=utf-8'
2019-10-01T08:51:11.3122599Z DEBUG: msrest.http_logger : 'Content-Encoding': 'gzip'
2019-10-01T08:51:11.3123479Z DEBUG: msrest.http_logger : 'Vary': 'Accept-Encoding'
2019-10-01T08:51:11.3124611Z DEBUG: msrest.http_logger : 'x-ms-request-id': '<resource id>'
2019-10-01T08:51:11.3125950Z DEBUG: msrest.http_logger : 'X-Content-Type-Options': 'nosniff'
2019-10-01T08:51:11.3126457Z DEBUG: msrest.http_logger : 'Preference-Applied': 'return-content'
2019-10-01T08:51:11.3127373Z DEBUG: msrest.http_logger : 'DataServiceVersion': '3.0;'
2019-10-01T08:51:11.3128620Z DEBUG: msrest.http_logger : 'Strict-Transport-Security': 'max-age=31536000; includeSubDomains'
2019-10-01T08:51:11.3131644Z DEBUG: msrest.http_logger : 'Server': 'Microsoft-HTTPAPI/2.0'
2019-10-01T08:51:11.3132216Z DEBUG: msrest.http_logger : 'x-ms-ratelimit-remaining-subscription-writes': '1199'
2019-10-01T08:51:11.3149524Z DEBUG: msrest.http_logger : 'x-ms-correlation-request-id': '7ed11348-37a7-4d37-b1e8-e7e8e0935bd9'
2019-10-01T08:51:11.3150131Z DEBUG: msrest.http_logger : 'x-ms-routing-request-id': 'NORTHEUROPE:20191001T085111Z:7ed11348-37a7-4d37-b1e8-e7e8e0935bd9'
2019-10-01T08:51:11.3150390Z DEBUG: msrest.http_logger : 'Date': 'Tue, 01 Oct 2019 08:51:10 GMT'
2019-10-01T08:51:11.3150574Z DEBUG: msrest.http_logger : Response content:
2019-10-01T08:51:11.3150987Z DEBUG: msrest.http_logger : {"id":"/subscriptions/<subscription>/resourceGroups/<resource group name>/providers/Microsoft.Sql/servers/<server name>/firewallRules/Toronto-Office","name":"Toronto-Office","type":"Microsoft.Sql/servers/firewallRules","location":"East US","kind":"v12.0","properties":{"startIpAddress":"<ip address here>","endIpAddress":"<ip address here>"}}
2019-10-01T08:51:11.3186621Z DEBUG: Event: CommandInvoker.OnTransformResult [<function _resource_group_transform at 0x02249FA8>, <function _x509_from_base64_to_hex_transform at 0x02252030>]
2019-10-01T08:51:11.3187311Z {
2019-10-01T08:51:11.3187895Z DEBUG: Event: CommandInvoker.OnFilterResult []
2019-10-01T08:51:11.3188302Z DEBUG: Event: Cli.PostExecute []
2019-10-01T08:51:11.3188735Z "endIpAddress": "<ip address here>",
2019-10-01T08:51:11.3188990Z "id": "/subscriptions/<subscription>/resourceGroups/<resource group name>/providers/Microsoft.Sql/servers/<server name>/firewallRules/Toronto-Office",
2019-10-01T08:51:11.3189235Z "kind": "v12.0",
2019-10-01T08:51:11.3189396Z "location": "East US",
2019-10-01T08:51:11.3189543Z "name": "Toronto-Office",
2019-10-01T08:51:11.3189716Z "resourceGroup": "<resource group name>",
2019-10-01T08:51:11.3189878Z "startIpAddress": "<ip address here>",
2019-10-01T08:51:11.3190164Z INFO: az_command_data_logger : exit code: 0
2019-10-01T08:51:11.3190338Z "type": "Microsoft.Sql/servers/firewallRules"
2019-10-01T08:51:11.3190481Z }
2019-10-01T08:51:11.3314066Z INFO: telemetry.save : Save telemetry record of length 2515 in cache
2019-10-01T08:51:11.3317580Z WARNING: telemetry.check : Negative: The C:\Users\ebhadmin\.azure\telemetry.txt was modified at 2019-10-01 08:45:04.044685, which in less than 600.000000 s
2019-10-01T08:51:11.3318452Z INFO: command ran in 2.675 seconds.
2019-10-01T08:51:11.4479583Z [command]C:\Windows\system32\cmd.exe /D /S /C ""C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd" account clear"
2019-10-01T08:51:12.7590708Z ##[error]Script failed with error: Error: C:\Users\ebhadmin\AppData\Local\Temp\azureclitaskscript1569919863928.bat failed with return code: 0
2019-10-01T08:51:12.7625710Z ##[section]Finishing: Add firewall rules to DW for Toronto office
AndreiLipinski
on 1 Oct 2019
@dikhakha,
Do you have any updates regarding this?
Also, I see that our log is almost identical to the log provided by the author of this post.
Can we reopen this issue then?
dmitrykarnitski
on 3 Oct 2019
Thanks for the logs @AndreiLipinski , @dmitrykarnitski It is possible that the script is writing something to stderr even though it passes with exit code 0. I am not able to repro 'az account clear' causing the failure. Can you share the script which you are executing ? Also, can you share debug logs of the failed pipeline, set 'system.debug' = true as pipeline variable and run it. The current logs do not have task debug information.
dikhakha
on 3 Oct 2019
Hi @dikhakha we have just migrated from TFS 2018 to Azure DevOps, and I still have this issue, but with new description.
Task log with system.debug = true:
2019-10-09T12:13:02.5850938Z ##[debug]Evaluating condition for step: 'Swap Slots'
2019-10-09T12:13:02.5851616Z ##[debug]Evaluating: succeeded()
2019-10-09T12:13:02.5851722Z ##[debug]Evaluating succeeded:
2019-10-09T12:13:02.5851900Z ##[debug]=> True
2019-10-09T12:13:02.5852057Z ##[debug]Result: True
2019-10-09T12:13:02.5852205Z ##[section]Starting: Swap Slots
2019-10-09T12:13:02.5922542Z ==============================================================================
2019-10-09T12:13:02.5922620Z Task : Azure CLI
2019-10-09T12:13:02.5922674Z Description : Run Azure CLI commands against an Azure subscription in a Shell script when running on Linux agent or Batch script when running on Windows agent.
2019-10-09T12:13:02.5922755Z Version : 1.156.0
2019-10-09T12:13:02.5922794Z Author : Microsoft Corporation
2019-10-09T12:13:02.5922858Z Help : https://docs.microsoft.com/azure/devops/pipelines/tasks/deploy/azure-cli
2019-10-09T12:13:02.5922912Z ==============================================================================
2019-10-09T12:13:02.7963974Z ##[debug]agent.TempDirectory=E:\< build agent name >\_work\_temp
2019-10-09T12:13:02.7993343Z ##[debug]loading inputs and endpoints
2019-10-09T12:13:02.8001376Z ##[debug]loading ENDPOINT_AUTH_d3211288-b72b-4cd3-868b-2235e096b9d4
2019-10-09T12:13:02.8014463Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_d3211288-b72b-4cd3-868b-2235e096b9d4_SERVICEPRINCIPALID
2019-10-09T12:13:02.8019326Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_d3211288-b72b-4cd3-868b-2235e096b9d4_SERVICEPRINCIPALKEY
2019-10-09T12:13:02.8021377Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_d3211288-b72b-4cd3-868b-2235e096b9d4_TENANTID
2019-10-09T12:13:02.8023272Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_SYSTEMVSSCONNECTION_ACCESSTOKEN
2019-10-09T12:13:02.8024951Z ##[debug]loading ENDPOINT_AUTH_SCHEME_d3211288-b72b-4cd3-868b-2235e096b9d4
2019-10-09T12:13:02.8026510Z ##[debug]loading ENDPOINT_AUTH_SCHEME_SYSTEMVSSCONNECTION
2019-10-09T12:13:02.8028427Z ##[debug]loading ENDPOINT_AUTH_SYSTEMVSSCONNECTION
2019-10-09T12:13:02.8034384Z ##[debug]loading INPUT_ADDSPNTOENVIRONMENT
2019-10-09T12:13:02.8035378Z ##[debug]loading INPUT_CONNECTEDSERVICENAMEARM
2019-10-09T12:13:02.8036598Z ##[debug]loading INPUT_CWD
2019-10-09T12:13:02.8038919Z ##[debug]loading INPUT_FAILONSTANDARDERROR
2019-10-09T12:13:02.8040849Z ##[debug]loading INPUT_INLINESCRIPT
2019-10-09T12:13:02.8042629Z ##[debug]loading INPUT_SCRIPTLOCATION
2019-10-09T12:13:02.8044055Z ##[debug]loading INPUT_SCRIPTPATH
2019-10-09T12:13:02.8045591Z ##[debug]loading INPUT_USEGLOBALCONFIG
2019-10-09T12:13:02.8063485Z ##[debug]loading SECRET_AUTH_IDENTITYPROVIDER_CLICLIENTSECRET
2019-10-09T12:13:02.8081166Z ##[debug]loaded 17
2019-10-09T12:13:02.8129416Z ##[debug]Agent.ProxyUrl=undefined
2019-10-09T12:13:02.8132312Z ##[debug]Agent.CAInfo=undefined
2019-10-09T12:13:02.8132731Z ##[debug]Agent.ClientCert=undefined
2019-10-09T12:13:02.8132839Z ##[debug]Agent.SkipCertValidation=undefined
2019-10-09T12:13:02.8136992Z ##[debug]check path : E:\< build agent name >\_work\_tasks\AzureCLI_46e4be58-730b-4389-8a2f-ea10b3e5e815\1.156.0\task.json
2019-10-09T12:13:02.8139842Z ##[debug]adding resource file: E:\< build agent name >\_work\_tasks\AzureCLI_46e4be58-730b-4389-8a2f-ea10b3e5e815\1.156.0\task.json
2019-10-09T12:13:02.8140016Z ##[debug]system.culture=en-US
2019-10-09T12:13:02.8159334Z ##[debug]which 'az'
2019-10-09T12:13:02.8176995Z ##[debug]found: 'C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd'
2019-10-09T12:13:02.8196635Z ##[debug]scriptLocation=inlineScript
2019-10-09T12:13:02.8202792Z ##[debug]cwd=E:\< build agent name >\_work\r1\a
2019-10-09T12:13:02.8203146Z ##[debug]Agent.TempDirectory=E:\< build agent name >\_work\_temp
2019-10-09T12:13:02.8204320Z ##[debug]inlineScript=powershell.exe -File Build-EBH-Refresh-Scripts/ps-scripts/api/app-service/swap-slot-app-service.ps1 -WebApp < api name > -ResourceGroupName < resource group name >
2019-10-09T12:13:02.8209125Z ##[debug]args=null
2019-10-09T12:13:02.8210944Z ##[debug]failOnStandardError=true
2019-10-09T12:13:02.8215262Z ##[debug]testing directory 'E:\< build agent name >\_work\r1\a'
2019-10-09T12:13:02.8225186Z ##[debug]which 'E:\< build agent name >\_work\_temp\azureclitaskscript1570623182816.bat'
2019-10-09T12:13:02.8227799Z ##[debug]found: 'E:\< build agent name >\_work\_temp\azureclitaskscript1570623182816.bat'
2019-10-09T12:13:02.8228602Z ##[debug]which 'E:\< build agent name >\_work\_temp\azureclitaskscript1570623182816.bat'
2019-10-09T12:13:02.8230138Z ##[debug]found: 'E:\< build agent name >\_work\_temp\azureclitaskscript1570623182816.bat'
2019-10-09T12:13:02.8232168Z ##[debug]which 'E:\< build agent name >\_work\_temp\azureclitaskscript1570623182816.bat'
2019-10-09T12:13:02.8233152Z ##[debug]found: 'E:\< build agent name >\_work\_temp\azureclitaskscript1570623182816.bat'
2019-10-09T12:13:02.8233484Z ##[debug]which 'E:\< build agent name >\_work\_temp\azureclitaskscript1570623182816.bat'
2019-10-09T12:13:02.8235060Z ##[debug]found: 'E:\< build agent name >\_work\_temp\azureclitaskscript1570623182816.bat'
2019-10-09T12:13:02.8237245Z ##[debug]which 'az'
2019-10-09T12:13:02.8248098Z ##[debug]found: 'C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd'
2019-10-09T12:13:02.8248679Z ##[debug]which 'az'
2019-10-09T12:13:02.8256989Z ##[debug]found: 'C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd'
2019-10-09T12:13:02.8259970Z ##[debug]C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd arg: --version
2019-10-09T12:13:02.8260160Z ##[debug]C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd arg: --version
2019-10-09T12:13:02.8269253Z ##[debug]exec tool: C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd
2019-10-09T12:13:02.8269480Z ##[debug]exec tool: C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd
2019-10-09T12:13:02.8269607Z ##[debug]arguments:
2019-10-09T12:13:02.8269695Z ##[debug]arguments:
2019-10-09T12:13:02.8269805Z ##[debug] --version
2019-10-09T12:13:02.8269911Z ##[debug] --version
2019-10-09T12:13:02.8283013Z [command]C:\Windows\system32\cmd.exe /D /S /C ""C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd" --version"
2019-10-09T12:13:04.9714881Z azure-cli 2.0.74
2019-10-09T12:13:04.9715233Z
2019-10-09T12:13:04.9715504Z command-modules-nspkg 2.0.3
2019-10-09T12:13:04.9715624Z core 2.0.74
2019-10-09T12:13:04.9715750Z nspkg 3.0.4
2019-10-09T12:13:04.9715816Z telemetry 1.0.3
2019-10-09T12:13:04.9715855Z
2019-10-09T12:13:04.9715940Z Python location 'C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\python.exe'
2019-10-09T12:13:04.9716019Z Extensions directory 'C:\Users\ebhadmin\.azure\cliextensions'
2019-10-09T12:13:04.9716095Z
2019-10-09T12:13:04.9716179Z Python (Windows) 3.6.6 (v3.6.6:4cf1f54eb7, Jun 27 2018, 02:47:15) [MSC v.1900 32 bit (Intel)]
2019-10-09T12:13:04.9716227Z
2019-10-09T12:13:04.9716284Z Legal docs and information: aka.ms/AzureCliLegal
2019-10-09T12:13:04.9716448Z
2019-10-09T12:13:04.9716478Z
2019-10-09T12:13:04.9716527Z Your CLI is up-to-date.
2019-10-09T12:13:04.9720685Z ##[debug]useGlobalConfig=false
2019-10-09T12:13:04.9720880Z ##[debug]Agent.TempDirectory=E:\< build agent name >\_work\_temp
2019-10-09T12:13:04.9720987Z ##[debug]Agent.TempDirectory=E:\< build agent name >\_work\_temp
2019-10-09T12:13:04.9765641Z Setting AZURE_CONFIG_DIR env variable to: E:\< build agent name >\_work\_temp\.azclitask
2019-10-09T12:13:04.9768166Z ##[debug]connectedServiceNameARM=d3211288-b72b-4cd3-868b-2235e096b9d4
2019-10-09T12:13:04.9769840Z ##[debug]d3211288-b72b-4cd3-868b-2235e096b9d4 data environment = AzureCloud
2019-10-09T12:13:04.9770164Z Setting active cloud to: AzureCloud
2019-10-09T12:13:04.9771188Z ##[debug]which 'az'
2019-10-09T12:13:04.9791475Z ##[debug]found: 'C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd'
2019-10-09T12:13:04.9791670Z ##[debug]which 'az'
2019-10-09T12:13:04.9821362Z ##[debug]found: 'C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd'
2019-10-09T12:13:04.9822107Z ##[debug]C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd arg: cloud set -n AzureCloud
2019-10-09T12:13:04.9822247Z ##[debug]C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd arg: cloud set -n AzureCloud
2019-10-09T12:13:04.9824296Z ##[debug]exec tool: C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd
2019-10-09T12:13:04.9824682Z ##[debug]exec tool: C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd
2019-10-09T12:13:04.9824782Z ##[debug]arguments:
2019-10-09T12:13:04.9824894Z ##[debug]arguments:
2019-10-09T12:13:04.9825005Z ##[debug] cloud
2019-10-09T12:13:04.9825387Z ##[debug] cloud
2019-10-09T12:13:04.9825556Z ##[debug] set
2019-10-09T12:13:04.9825642Z ##[debug] set
2019-10-09T12:13:04.9825775Z ##[debug] -n
2019-10-09T12:13:04.9825858Z ##[debug] -n
2019-10-09T12:13:04.9825960Z ##[debug] AzureCloud
2019-10-09T12:13:04.9826063Z ##[debug] AzureCloud
2019-10-09T12:13:04.9827500Z [command]C:\Windows\system32\cmd.exe /D /S /C ""C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd" cloud set -n AzureCloud"
2019-10-09T12:13:06.2900009Z ##[debug]connectedServiceNameARM=d3211288-b72b-4cd3-868b-2235e096b9d4
2019-10-09T12:13:06.2905074Z ##[debug]d3211288-b72b-4cd3-868b-2235e096b9d4 auth scheme = ServicePrincipal
2019-10-09T12:13:06.2905887Z ##[debug]d3211288-b72b-4cd3-868b-2235e096b9d4 data SubscriptionID = < subscription >
2019-10-09T12:13:06.2906791Z ##[debug]d3211288-b72b-4cd3-868b-2235e096b9d4 auth param authenticationType = null
2019-10-09T12:13:06.2908376Z ##[debug]d3211288-b72b-4cd3-868b-2235e096b9d4 auth param serviceprincipalid = ***
2019-10-09T12:13:06.2910207Z ##[debug]d3211288-b72b-4cd3-868b-2235e096b9d4 auth param tenantid = ***
2019-10-09T12:13:06.2910350Z ##[debug]key based endpoint
2019-10-09T12:13:06.2912307Z ##[debug]d3211288-b72b-4cd3-868b-2235e096b9d4 auth param serviceprincipalkey = ***
2019-10-09T12:13:06.2912454Z ##[debug]which 'az'
2019-10-09T12:13:06.2926095Z ##[debug]found: 'C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd'
2019-10-09T12:13:06.2926454Z ##[debug]which 'az'
2019-10-09T12:13:06.2939721Z ##[debug]found: 'C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd'
2019-10-09T12:13:06.2940094Z ##[debug]C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd arg: login --service-principal -u "***" -p *** --tenant "***"
2019-10-09T12:13:06.2940319Z ##[debug]C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd arg: login --service-principal -u "***" -p *** --tenant "***"
2019-10-09T12:13:06.2942410Z ##[debug]exec tool: C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd
2019-10-09T12:13:06.2942590Z ##[debug]exec tool: C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd
2019-10-09T12:13:06.2942853Z ##[debug]arguments:
2019-10-09T12:13:06.2943163Z ##[debug]arguments:
2019-10-09T12:13:06.2943952Z ##[debug] login
2019-10-09T12:13:06.2952269Z ##[debug] login
2019-10-09T12:13:06.2952627Z ##[debug] --service-principal
2019-10-09T12:13:06.2953137Z ##[debug] --service-principal
2019-10-09T12:13:06.2953561Z ##[debug] -u
2019-10-09T12:13:06.2953666Z ##[debug] -u
2019-10-09T12:13:06.2953803Z ##[debug] ***
2019-10-09T12:13:06.2953966Z ##[debug] ***
2019-10-09T12:13:06.2954072Z ##[debug] -p
2019-10-09T12:13:06.2954154Z ##[debug] -p
2019-10-09T12:13:06.2954317Z ##[debug] ***
2019-10-09T12:13:06.2954451Z ##[debug] ***
2019-10-09T12:13:06.2954537Z ##[debug] --tenant
2019-10-09T12:13:06.2954642Z ##[debug] --tenant
2019-10-09T12:13:06.2954759Z ##[debug] ***
2019-10-09T12:13:06.2954891Z ##[debug] ***
2019-10-09T12:13:06.2965669Z [command]C:\Windows\system32\cmd.exe /D /S /C ""C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd" login --service-principal -u *** -p *** --tenant ***"
2019-10-09T12:13:08.8371200Z [
2019-10-09T12:13:08.8371474Z {
2019-10-09T12:13:08.8371527Z "cloudName": "AzureCloud",
2019-10-09T12:13:08.8371620Z "id": "< subscription >",
2019-10-09T12:13:08.8371944Z "isDefault": true,
2019-10-09T12:13:08.8372005Z "name": "< subscription name >",
2019-10-09T12:13:08.8372088Z "state": "Enabled",
2019-10-09T12:13:08.8372240Z "tenantId": "***",
2019-10-09T12:13:08.8372314Z "user": {
2019-10-09T12:13:08.8372387Z "name": "***",
2019-10-09T12:13:08.8372445Z "type": "servicePrincipal"
2019-10-09T12:13:08.8372521Z }
2019-10-09T12:13:08.8372571Z }
2019-10-09T12:13:08.8372637Z ]
2019-10-09T12:13:08.8372892Z ##[debug]which 'az'
2019-10-09T12:13:08.8385524Z ##[debug]found: 'C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd'
2019-10-09T12:13:08.8386330Z ##[debug]which 'az'
2019-10-09T12:13:08.8413834Z ##[debug]found: 'C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd'
2019-10-09T12:13:08.8414195Z ##[debug]C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd arg: account set --subscription "< subscription >"
2019-10-09T12:13:08.8414390Z ##[debug]C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd arg: account set --subscription "< subscription >"
2019-10-09T12:13:08.8415472Z ##[debug]exec tool: C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd
2019-10-09T12:13:08.8415993Z ##[debug]exec tool: C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd
2019-10-09T12:13:08.8416521Z ##[debug]arguments:
2019-10-09T12:13:08.8416657Z ##[debug]arguments:
2019-10-09T12:13:08.8416894Z ##[debug] account
2019-10-09T12:13:08.8423497Z ##[debug] account
2019-10-09T12:13:08.8438414Z ##[debug] set
2019-10-09T12:13:08.8439980Z ##[debug] set
2019-10-09T12:13:08.8440162Z ##[debug] --subscription
2019-10-09T12:13:08.8441174Z ##[debug] --subscription
2019-10-09T12:13:08.8441370Z ##[debug] < subscription >
2019-10-09T12:13:08.8441782Z ##[debug] < subscription >
2019-10-09T12:13:08.8441926Z [command]C:\Windows\system32\cmd.exe /D /S /C ""C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd" account set --subscription < subscription >"
2019-10-09T12:13:10.2737553Z ##[debug]addSpnToEnvironment=false
2019-10-09T12:13:10.2744270Z ##[debug]exec tool: E:\< build agent name >\_work\_temp\azureclitaskscript1570623182816.bat
2019-10-09T12:13:10.2744900Z ##[debug]arguments:
2019-10-09T12:13:10.2746287Z [command]C:\Windows\system32\cmd.exe /D /S /C "E:\< build agent name >\_work\_temp\azureclitaskscript1570623182816.bat"
2019-10-09T12:13:10.3978708Z
2019-10-09T12:13:10.3980150Z E:\< build agent name >\_work\r1\a>powershell.exe -File Build-EBH-Refresh-Scripts/ps-scripts/api/app-service/swap-slot-app-service.ps1 -WebApp < api name > -ResourceGroupName < resource group name >
2019-10-09T12:13:11.0457890Z Swap slot for < api name > is started
2019-10-09T12:14:38.1475549Z INFO: command ran in 86.380 seconds.
2019-10-09T12:14:38.2823701Z ##[debug]Exit code 0 received from tool 'E:\< build agent name >\_work\_temp\azureclitaskscript1570623182816.bat'
2019-10-09T12:14:38.2835002Z ##[debug]STDIO streams have closed for tool 'E:\< build agent name >\_work\_temp\azureclitaskscript1570623182816.bat'
2019-10-09T12:14:38.2872589Z ##[debug]task result: Failed
2019-10-09T12:14:38.2933600Z ##[error]Script failed with error: Error: The process 'E:\< build agent name >\_work\_temp\azureclitaskscript1570623182816.bat' failed because one or more lines were written to the STDERR stream
2019-10-09T12:14:38.2941720Z ##[debug]Processed: ##vso[task.issue type=error;]Script failed with error: Error: The process 'E:\< build agent name >\_work\_temp\azureclitaskscript1570623182816.bat' failed because one or more lines were written to the STDERR stream
2019-10-09T12:14:38.2942555Z ##[debug]Processed: ##vso[task.complete result=Failed;]Script failed with error: Error: The process 'E:\< build agent name >\_work\_temp\azureclitaskscript1570623182816.bat' failed because one or more lines were written to the STDERR stream
2019-10-09T12:14:38.2942697Z ##[debug]which 'az'
2019-10-09T12:14:38.2942921Z ##[debug]found: 'C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd'
2019-10-09T12:14:38.2943026Z ##[debug]which 'az'
2019-10-09T12:14:38.2943126Z ##[debug]found: 'C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd'
2019-10-09T12:14:38.2943213Z ##[debug]C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd arg: account clear
2019-10-09T12:14:38.2943318Z ##[debug]C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd arg: account clear
2019-10-09T12:14:38.2943420Z ##[debug]exec tool: C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd
2019-10-09T12:14:38.2943522Z ##[debug]exec tool: C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd
2019-10-09T12:14:38.2943605Z ##[debug]arguments:
2019-10-09T12:14:38.2943690Z ##[debug]arguments:
2019-10-09T12:14:38.2943757Z ##[debug] account
2019-10-09T12:14:38.2943842Z ##[debug] account
2019-10-09T12:14:38.2943925Z ##[debug] clear
2019-10-09T12:14:38.2943994Z ##[debug] clear
2019-10-09T12:14:38.2944083Z [command]C:\Windows\system32\cmd.exe /D /S /C ""C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin\az.cmd" account clear"
2019-10-09T12:14:39.6145504Z ##[section]Finishing: Swap Slots
Script:
param(
[Parameter(Mandatory = $True)]
[string] $WebApp,
[Parameter(Mandatory = $True)]
[string] $ResourceGroupName
)
Write-Host "Swap slot for $WebApp is started"
az webapp deployment slot swap --resource-group $ResourceGroupName `
--name $WebApp --slot staging `
--target-slot production --verbose
Also, I faced this error in other scripts.
AndreiLipinski
on 9 Oct 2019
@dikhakha also, I redirected stderr to log file:
az : INFO: command ran in 73.984 seconds.
At C:\TR-Projects\eBillingHub.Refresh.Scripts\api\app-service\swap-slot-app-service.ps1:13 char:1
+ az webapp deployment slot swap --resource-group $ResourceGroupName `
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+ CategoryInfo : NotSpecified: (INFO: command ran in 73.984 seconds.:String) [], RemoteException
+ FullyQualifiedErrorId : NativeCommandError
The same issue with another script:
az : INFO: command ran in 3.210 seconds.
At C:\TR-Projects\eBillingHub.Reporting\deployment-scripts\resource-group\ensure-resource-group-created.ps1:12 char:1
+ az group create --name $ResourceGroupName --location $ResourceGroupLo ...
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+ CategoryInfo : NotSpecified: (INFO: command ran in 3.210 seconds.:String) [], RemoteException
+ FullyQualifiedErrorId : NativeCommandError
Hi @dmitrykarnitski , @AndreiLipinski. I looked at the logs attached, and I was able to repro the issue with az cli version 2.0.74. This command that writes to the error stream is not 'az account clear', but 'az webapp deployment slot swap...... --verbose'. The '--verbose' flag in earlier az cli versions appears to be a no-op(at least for this command), whereas in version 2.0.74, it writes to error and output stream(apparently even in success cases). In my repro, the command did succeed, but I saw it writing to error stream. The behavior was the same even when the command was executed from powershell console. Can you try removing the verbose flag and let us know if you are still facing the issue?
Also, as the help-text for the input field _'Fail on Standard Error'_ says:
_"If this is true, this task will fail when any errors are written to the StandardError stream. Unselect the checkbox to ignore standard errors and rely on exit codes to determine the status"_
In cases like this, you can choose to rely on the exit codes rather than the error stream as pointed out earlier
edit: it appears that any 'az cli' command which prints a warning is also writing to the error stream(looks like a bug).
tejasd1990
on 15 Oct 2019
Thanks for the info @tejasd1990 , can you give me some examples or links on how this works in the Azure CLI?
AndreiLipinski
on 16 Oct 2019
Hi @AndreiLipinski ,
to get unblocked, uncheck the _'Fail on Standard Error'_ option.
For exit codes, since you are using v1 azurecli task,
- For Windows agent, you can refer this https://stackoverflow.com/questions/334879/how-do-i-get-the-application-exit-code-from-a-windows-command-line
- For Linux agent, you can refer this https://askubuntu.com/questions/324423/how-to-access-the-last-return-value-in-bash
tejasd1990
on 21 Oct 2019
Was this page helpful?
0 / 5 - 0 ratings
Related issues
pharring
Ā·
3Comments
TheRealEdwardCullen
Ā·
3Comments
Mardoxx
Ā·
3Comments
syltaxue
Ā·
3Comments
richard-ob
Ā·
3Comments
Most helpful comment
@hiyadav thanks for your answer
the az cli is the latest version available (2.0.55)
as I have mentioned before, the weird thing is when the tfs agent is in the interactive mode (./run.sh) it goes through fine. but when I put the agent in the serviced mode it gives me the error that I have mentioned.
And also "FailOnStandardError = false" is not an option for me since I want to fail the build process when an actual error is happening. If I change the variable to "true" it never fails and I cannot use it.
Is there any other workaround available?