search

Azure / custom-script-extension-linux

Azure Custom Script Virtual Machine Extension :new:
Apache License 2.0
108 stars 33 forks source link

Unable to run a custom script on a VM (provisioned by Terraform) #96

Closed bitsofparag closed 7 years ago

bitsofparag commented 7 years ago

(It seems like an Azure issue than a Terraform one, hence, opening the issue here first but please correct me if I am wrong)

I am trying to run the install_jenkins.sh script on a linux (UbuntuServer, 14.04.5-LTS) virtual machine. The script fails with the following error:

TYPE Microsoft.Azure.Extensions.CustomScript
VERSION . 2.0.3
STATUS  Provisioning failed
STATUS LEVEL . Error
STATUS MESSAGE . Enable failed: failed to execute command: command terminated with exit status=2
HANDLER STATUS . Ready
HANDLER STATUS LEVEL . Info

The protectedSettings that I am running are as follows:

 {
      "commandToExecute" : "curl -k https://raw.githubusercontent.com/Azure/azure-devops-utils/v0.14.0/install_jenkins.sh >> ~/install_jenkins.sh && chmod +x ~/install_jenkins.sh && ./install_jenkins.sh -jf <fqdn of the public ip of the vm> -pi 10.0.0.6 -al https://raw.githubusercontent.com/Azure/azure-devops-utils/v0.14.0/ -st ''",
      "storageAccountName" : "<storage account name>",
      "storageAccountKey" : "<storage account primary access key>"
  }

Please find here the relevant log file output:

boumenot commented 7 years ago

I think the issue is lack of Internet connectivity.

This log indicates to me that the agent does not have access to the Internet. It downloaded the CustomScript extension package by forwarding the request to the host so it could download the package on its behalf. The host can only satisfy requests for extension packages though.

2017/06/07 18:21:57.869261 WARNING Failed to download from: https://rdfepirv2am2prdstr02.blob.core.windows.net/708cdbbfb9ad4802ac80a012992930b1/Microsoft.Azure.Extensions__CustomScript__2.0.3
2017/06/07 18:21:57.870537 WARNING Download did not succeed, falling back to host plugin

Your script is trying to download something from the Internet, and based on the above logs I assume it will fail. Please ensure your VM has access to Internet.

HTH. Let me know if this resolves your issue or not.

bitsofparag commented 7 years ago

That's right. Thank you! It seems there were a couple of quirks upon provisioning the VM:

  1. the internal DNS servers for the VM (for e.g 10.0.0.4) didn't function. I changed them manually to Google's DNS (8.8.8.8) and then outbound connections started working.
  2. The hostname of the VM (i.e the computer_name specified in the os_profile) was not set in the /etc/hosts file, resulting in some warnings when shell scripts are run.

In any case, the custom script still fails. I eventually ssh-ed into the VM and ran the custom script manually from the command line 😞

Here's what the logs look like now:

2017/06/08 02:06:10.192992 INFO Azure Linux Agent Version:2.2.9
2017/06/08 02:06:10.208196 INFO OS: ubuntu 14.04
2017/06/08 02:06:10.208332 INFO Python: 3.4.3
2017/06/08 02:06:10.208508 INFO Run daemon
2017/06/08 02:06:10.208734 INFO No RDMA handler exists for distro='Ubuntu' version='14.04'
2017/06/08 02:06:10.261420 INFO Clean protocol
2017/06/08 02:06:10.261582 INFO run Ubuntu provision handler
2017/06/08 02:06:10.261686 INFO Waiting cloud-init to copy ovf-env.xml.
2017/06/08 02:06:10.305522 INFO Detect protocol endpoints
2017/06/08 02:06:10.305674 INFO Clean protocol
2017/06/08 02:06:10.319382 INFO WireServer endpoint is not found. Rerun dhcp handler
2017/06/08 02:06:10.319472 INFO Test for route to 168.63.129.16
2017/06/08 02:06:10.319637 INFO Route to 168.63.129.16 exists
2017/06/08 02:06:10.319720 INFO Wire server endpoint:168.63.129.16
2017/06/08 02:06:10.354125 INFO Fabric preferred wire protocol version:2015-04-05
2017/06/08 02:06:10.354375 INFO Wire protocol version:2012-11-30
2017/06/08 02:06:10.354446 WARNING Server preferred version:2015-04-05
2017/06/08 02:06:14.926021 INFO Sleeping 1 second to avoid throttling.
2017/06/08 02:06:15.927324 INFO Wait for ssh host key to be generated.
2017/06/08 02:06:15.927593 INFO Wait for ssh host key be generated: /etc/ssh/ssh_host_rsa_key.pub
2017/06/08 02:06:20.932218 INFO ssh host key found at: /etc/ssh/ssh_host_rsa_key.pub
2017/06/08 02:06:20.965032 INFO Thumbprint obtained from : /etc/ssh/ssh_host_rsa_key.pub
2017/06/08 02:06:20.988096 INFO Finished provisioning
2017/06/08 02:06:22.751953 INFO Event: name=WALA, op=Provision, message=Provision succeed
2017/06/08 02:06:22.774305 INFO RDMA capabilities are not enabled, skipping
2017/06/08 02:06:22.792032 INFO Installed Agent WALinuxAgent-2.2.9 is the most current agent
2017/06/08 02:06:23.067715 INFO Agent WALinuxAgent-2.2.9 is running as the goal state agent
2017/06/08 02:06:23.088806 INFO Wire server endpoint:168.63.129.16
2017/06/08 02:06:23.097177 INFO Event: name=WALinuxAgent-2.2.9, op=HeartBeat, message=
2017/06/08 02:06:23.122858 INFO Start env monitor service.
2017/06/08 02:06:23.126738 INFO Configure routes
2017/06/08 02:06:23.129991 INFO Gateway:None
2017/06/08 02:06:23.133744 INFO Routes:None
2017/06/08 02:06:23.137369 WARNING Hostname record does not exist, creating [/var/lib/waagent/published_hostname] with hostname [nbtops]
2017/06/08 02:06:23.239132 INFO WALinuxAgent-2.2.9 running as process 1587
2017/06/08 02:06:23.239367 INFO Set block dev timeout: sda with timeout: 300
2017/06/08 02:06:23.256673 INFO Wire server endpoint:168.63.129.16
2017/06/08 02:06:23.273320 INFO Set block dev timeout: sdb with timeout: 300
2017/06/08 02:06:23.376405 INFO Event: name=WALinuxAgent, op=Install, message=Agent WALinuxAgent-2.2.10 downloaded successfully
2017/06/08 02:06:23.451948 INFO Event: name=WALinuxAgent, op=Install, message=Agent WALinuxAgent-2.2.12 downloaded successfully
2017/06/08 02:06:23.500493 INFO Event: name=WALinuxAgent, op=Install, message=Agent WALinuxAgent-2.2.7 downloaded successfully
2017/06/08 02:06:23.564460 INFO Event: name=WALinuxAgent, op=Install, message=Agent WALinuxAgent-2.2.8 downloaded successfully
2017/06/08 02:06:23.599289 INFO Agent WALinuxAgent-2.2.9 discovered WALinuxAgent-2.2.12 as an update and will exit
2017/06/08 02:06:23.860790 INFO Agent WALinuxAgent-2.2.9 launched with command 'python3 -u /usr/sbin/waagent -run-exthandlers' is successfully running
2017/06/08 02:06:23.895797 INFO Event: name=WALinuxAgent, op=Enable, message=Agent WALinuxAgent-2.2.9 launched with command 'python3 -u /usr/sbin/waagent -run-exthandlers' is successfully running
2017/06/08 02:06:23.941081 INFO Determined Agent WALinuxAgent-2.2.12 to be the latest agent
2017/06/08 02:06:25.530260 INFO Agent WALinuxAgent-2.2.12 is running as the goal state agent
2017/06/08 02:06:25.544898 INFO Wire server endpoint:168.63.129.16
2017/06/08 02:06:25.552353 INFO Event: name=WALinuxAgent-2.2.12, op=HeartBeat, message=
2017/06/08 02:06:25.560679 INFO Start env monitor service.
2017/06/08 02:06:25.589304 INFO Configure routes
2017/06/08 02:06:25.592607 INFO Gateway:None
2017/06/08 02:06:25.597716 INFO Routes:None
2017/06/08 02:06:25.616810 INFO WALinuxAgent-2.2.12 running as process 1600
2017/06/08 02:06:25.624435 INFO Wire server endpoint:168.63.129.16
2017/06/08 02:06:25.697473 INFO Wire server endpoint:168.63.129.16
2017/06/08 02:06:25.806640 INFO Event: name=WALinuxAgent, op=ProcessGoalState, message=
2017/06/08 02:07:19.519231 INFO [Microsoft.Azure.Extensions.CustomScript-2.0.3] Target handler state: enabled
2017/06/08 02:07:19.523552 INFO [Microsoft.Azure.Extensions.CustomScript-2.0.3] [Enable] current handler state is: notinstalled
2017/06/08 02:07:19.762195 INFO Event: name=Microsoft.Azure.Extensions.CustomScript, op=Download, message=Download succeeded
2017/06/08 02:07:19.767426 INFO [Microsoft.Azure.Extensions.CustomScript-2.0.3] Initialize extension directory
2017/06/08 02:07:19.773321 INFO [Microsoft.Azure.Extensions.CustomScript-2.0.3] Update settings file: 0.settings
2017/06/08 02:07:19.775784 INFO [Microsoft.Azure.Extensions.CustomScript-2.0.3] Install extension [bin/custom-script-shim install]
2017/06/08 02:07:20.874212 INFO Event: name=Microsoft.Azure.Extensions.CustomScript, op=Install, message=Launch command succeeded: bin/custom-script-shim install
2017/06/08 02:07:20.883017 INFO [Microsoft.Azure.Extensions.CustomScript-2.0.3] Enable extension [bin/custom-script-shim enable]
2017/06/08 02:07:21.961971 INFO Event: name=Microsoft.Azure.Extensions.CustomScript, op=Enable, message=Launch command succeeded: bin/custom-script-shim enable
2017/06/08 02:07:22.009462 INFO Event: name=WALinuxAgent, op=ProcessGoalState, message=
2017/06/08 02:21:24.621699 INFO Agent WALinuxAgent-2.2.12 launched with command 'python3 -u bin/WALinuxAgent-2.2.12-py2.7.egg -run-exthandlers' is successfully running
2017/06/08 02:21:25.064131 INFO Event: name=WALinuxAgent, op=Enable, message=Agent WALinuxAgent-2.2.12 launched with command 'python3 -u bin/WALinuxAgent-2.2.12-py2.7.egg -run-exthandlers' is successfully running
boumenot commented 7 years ago

The command was executed, but it failed with exit status 2. Unfortunately, I do not know what the means. What does the stdout of the script have to say in this case?

bitsofparag commented 7 years ago

Hey @boumenot, sorry for my radio silence; was busy with other commitments. I will have another go at this from scratch and post the outcome here, sometime this week. Thanks!

boumenot commented 7 years ago

Understood, and no worries.

boumenot commented 7 years ago

Timing this issue out. Please re-open if necessary.

gzepeda commented 6 years ago

It is happening to me when installing puppet as a custom extension. Same behavior.

My linux VM was created with an ARM template.