search

Azure / custom-script-extension-linux

Azure Custom Script Virtual Machine Extension :new:
Apache License 2.0
106 stars 32 forks source link

az vmss extension set creating the extension but no action #185

Open adilliadil opened 3 years ago

adilliadil commented 3 years ago

I want to run a script with az vmss extension set command, however, the command seems not to be functioning. Could you please help me identify where the problem is, as this is currently a blocking our feature implementation. My az version:

{
  "azure-cli": "2.16.0",
  "azure-cli-core": "2.16.0",
  "azure-cli-telemetry": "1.0.6",
  "extensions": {
    "aks-preview": "0.4.62",
    "azure-devops": "0.18.0"
  }
}

Steps

  1. Create a VMSS az vmss create --name adadilliVMSS --resource-group adadilliRG --image "microsoft-aks:aks:aks-ubuntu-1804-gen2-2021-q1:2021.03.17" --custom-data cloud-init.txt --admin-username adadilli --generate-ssh-keys
    1. Set extension az vmss extension set --resource-group adadilliRG --name customScript --vmss-name adadilliVMSS --settings '{"commandToExecute": "./randomscript.sh", "fileUris": ["https://adadillie2esa.blob.core.windows.net/scripts/randomscript.sh"]}' --version 2.0 --publisher Microsoft.Azure.Extensions

The content of randomscript.sh is as follows:

#!/bin/sh
echo "Updating packages ..."
apt update
apt upgrade -y

Observerations

  1. There is no error outputted during the command run
  2. The Provisioning State of the extension null
  3. The /var/log/azure/custom-script/handler.log logs don't exist, in fact there is nothing under /var/log/azure folder
  4. The /var/log/waagent.log log does not contain anything relevant to customscript. 
    
adadilli@adadi0133000002:~$ cat /var/log/waagent.log

2021/04/08 21:29:01.909653 INFO Daemon Azure Linux Agent Version:2.2.45 2021/04/08 21:29:01.921219 INFO Daemon OS: ubuntu 18.04 2021/04/08 21:29:01.924739 INFO Daemon Python: 3.6.9 2021/04/08 21:29:01.929949 INFO Daemon CGroups Status: The cgroup filesystem is ready to use 2021/04/08 21:29:01.937106 INFO Daemon Run daemon 2021/04/08 21:29:01.946325 INFO Daemon cloud-init is enabled: True 2021/04/08 21:29:01.949832 INFO Daemon Using cloud-init for provisioning 2021/04/08 21:29:01.953781 INFO Daemon Clean protocol 2021/04/08 21:29:01.957076 INFO Daemon Running CloudInit provisioning handler 2021/04/08 21:29:01.964080 INFO Daemon Detect protocol endpoints 2021/04/08 21:29:01.967504 INFO Daemon Clean protocol 2021/04/08 21:29:01.970339 INFO Daemon WireServer endpoint is not found. Rerun dhcp handler 2021/04/08 21:29:01.974903 INFO Daemon Test for route to 168.63.129.16 2021/04/08 21:29:01.979560 INFO Daemon Route to 168.63.129.16 exists 2021/04/08 21:29:01.982956 INFO Daemon Wire server endpoint:168.63.129.16 2021/04/08 21:29:01.993861 INFO Daemon Fabric preferred wire protocol version:2015-04-05 2021/04/08 21:29:01.998390 INFO Daemon Wire protocol version:2012-11-30 2021/04/08 21:29:02.001929 INFO Daemon Server preferred version:2015-04-05 2021/04/08 21:29:02.324991 INFO Daemon Certificate with thumbprint E95246F76D8648E4A57C2BC0F344C2D5DE9A050C has no matching private key. 2021/04/08 21:29:02.343255 INFO Daemon ssh host key found at: /etc/ssh/ssh_host_rsa_key.pub 2021/04/08 21:29:02.351043 INFO Daemon Thumbprint obtained from : /etc/ssh/ssh_host_rsa_key.pub 2021/04/08 21:29:02.356912 INFO Daemon Finished provisioning 2021/04/08 21:29:03.374676 INFO Daemon RDMA capabilities are not enabled, skipping 2021/04/08 21:29:03.381716 INFO Daemon Installed Agent WALinuxAgent-2.2.45 is the most current agent 2021/04/08 21:29:03.527728 INFO ExtHandler Agent WALinuxAgent-2.2.45 is running as the goal state agent 2021/04/08 21:29:03.535541 INFO ExtHandler Distro info: ubuntu 18.04, osutil class being used: Ubuntu18OSUtil, agent service name: walinuxagent 2021/04/08 21:29:03.568068 INFO ExtHandler Wire server endpoint:168.63.129.16 2021/04/08 21:29:03.587698 INFO ExtHandler Start env monitor service. 2021/04/08 21:29:03.592896 INFO ExtHandler Configure routes 2021/04/08 21:29:03.598340 INFO ExtHandler Gateway:None 2021/04/08 21:29:03.602387 INFO ExtHandler Routes:None 2021/04/08 21:29:03.607602 INFO ExtHandler Hostname record does not exist, creating [/var/lib/waagent/published_hostname] with hostname [adadi0133000002] 2021/04/08 21:29:03.637186 INFO ExtHandler WALinuxAgent-2.2.45 running as process 1366 2021/04/08 21:29:03.642958 INFO ExtHandler Wire server endpoint:168.63.129.16 2021/04/08 21:29:03.651312 INFO ExtHandler CGroups Status: The cgroup filesystem is ready to use 2021/04/08 21:29:03.661732 INFO ExtHandler Started tracking new cgroup: walinuxagent.service, path: /sys/fs/cgroup/cpu/system.slice/walinuxagent.service 2021/04/08 21:29:03.680618 INFO ExtHandler Route table: [{"Iface": "eth0", "Destination": "0.0.0.0", "Gateway": "10.0.0.1", "Mask": "0.0.0.0", "Flags": "0x0003", "Metric": "100"},{"Iface": "eth0", "Destination": "10.0.0.0", "Gateway": "0.0.0.0", "Mask": "255.255.255.0", "Flags": "0x0001", "Metric": "0"},{"Iface": "eth0", "Destination": "168.63.129.16", "Gateway": "10.0.0.1", "Mask": "255.255.255.255", "Flags": "0x0007", "Metric": "100"},{"Iface": "eth0", "Destination": "169.254.169.254", "Gateway": "10.0.0.1", "Mask": "255.255.255.255", "Flags": "0x0007", "Metric": "100"}] 2021/04/08 21:29:03.707151 INFO ExtHandler Started tracking new cgroup: walinuxagent.service, path: /sys/fs/cgroup/memory/system.slice/walinuxagent.service 2021/04/08 21:29:03.804181 INFO ExtHandler Initial NIC state: [{ "name": "lo", "link": "<LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN mode DEFAULT group default qlen 1000\ link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00" }, { "name": "eth0", "link": "<BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP mode DEFAULT group default qlen 1000\ link/ether 00:22:48:1f:78:15 brd ff:ff:ff:ff:ff:ff" }] 2021/04/08 21:29:03.971736 INFO ExtHandler Successfully added Azure fabric firewall rules 2021/04/08 21:29:04.014093 INFO ExtHandler Firewall rules: Chain INPUT (policy ACCEPT 0 packets, 0 bytes) pkts bytes target prot opt in out source destination

Chain FORWARD (policy ACCEPT 0 packets, 0 bytes) pkts bytes target prot opt in out source destination

Chain OUTPUT (policy ACCEPT 0 packets, 0 bytes) pkts bytes target prot opt in out source destination 0 0 ACCEPT tcp -- 0.0.0.0/0 168.63.129.16 owner UID match 0 0 0 DROP tcp -- 0.0.0.0/0 168.63.129.16 ctstate INVALID,NEW

2021/04/08 21:29:04.052093 INFO ExtHandler Created slice for walinuxagent extensions system-walinuxagent.extensions.slice 2021/04/08 21:29:04.058332 INFO ExtHandler Set block dev timeout: sdb with timeout: 300 2021/04/08 21:29:04.064162 INFO ExtHandler Wire server endpoint:168.63.129.16 2021/04/08 21:29:04.067774 INFO ExtHandler Set block dev timeout: sda with timeout: 300 2021/04/08 21:29:32.961628 INFO ExtHandler Agent WALinuxAgent-2.2.45 discovered update WALinuxAgent-2.2.54.2 -- exiting 2021/04/08 21:29:33.420610 INFO Daemon Agent WALinuxAgent-2.2.45 launched with command 'python3 -u /usr/sbin/waagent -run-exthandlers' is successfully running 2021/04/08 21:29:33.434981 INFO Daemon Determined Agent WALinuxAgent-2.2.54.2 to be the latest agent 2021-04-08T21:29:34.125335Z INFO ExtHandler ExtHandler The agent will now check for updates and then will process extensions. Output to /dev/console will be suspended during those operations. 2021-04-08T21:29:34.313581Z INFO ExtHandler ExtHandler Agent WALinuxAgent-2.2.54.2 is running as the goal state agent 2021-04-08T21:29:34.315316Z INFO ExtHandler ExtHandler WireServer endpoint 168.63.129.16 read from file 2021-04-08T21:29:34.315616Z INFO ExtHandler ExtHandler Wire server endpoint:168.63.129.16 2021-04-08T21:29:34.327258Z INFO ExtHandler ExtHandler Fetching new goal state [incarnation 1 (force update)] 2021-04-08T21:29:34.392346Z INFO ExtHandler ExtHandler Certificate with thumbprint E95246F76D8648E4A57C2BC0F344C2D5DE9A050C has no matching private key. 2021-04-08T21:29:34.399431Z INFO ExtHandler ExtHandler Fetch goal state completed 2021-04-08T21:29:34.421890Z INFO ExtHandler ExtHandler Distro: ubuntu-18.04; OSUtil: Ubuntu18OSUtil; AgentService: walinuxagent; Python: 3.6.9; systemd: True; LISDrivers: Failed; logrotate: ; 2021-04-08T21:29:34.434651Z INFO ExtHandler ExtHandler WALinuxAgent-2.2.54.2 running as process 1939 2021-04-08T21:29:34.451886Z INFO ExtHandler ExtHandler systemd version: systemd 237 +PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid

2021-04-08T21:29:34.517253Z INFO ExtHandler ExtHandler Failed to query the agent's DropInPaths: Can't find property DropInPaths of walinuxagent 2021-04-08T21:29:34.525434Z INFO ExtHandler ExtHandler The CPU cgroup controller is mounted at /sys/fs/cgroup/cpu,cpuacct 2021-04-08T21:29:34.525857Z INFO ExtHandler ExtHandler The memory cgroup controller is mounted at /sys/fs/cgroup/memory 2021-04-08T21:29:34.529567Z INFO ExtHandler ExtHandler cgroups v2 mounted at /sys/fs/cgroup/unified. Controllers: [] 2021-04-08T21:29:34.539014Z INFO ExtHandler ExtHandler CPUAccounting: no 2021-04-08T21:29:34.557377Z INFO ExtHandler ExtHandler MemoryAccounting: no 2021-04-08T21:29:34.559792Z INFO ExtHandler ExtHandler Agent CPU cgroup: /sys/fs/cgroup/cpu,cpuacct/system.slice/walinuxagent.service 2021-04-08T21:29:34.560660Z INFO ExtHandler ExtHandler Started tracking cgroup: walinuxagent.service, path: /sys/fs/cgroup/cpu,cpuacct/system.slice/walinuxagent.service 2021-04-08T21:29:34.562872Z INFO ExtHandler ExtHandler Agent Memory cgroup: /sys/fs/cgroup/memory/system.slice/walinuxagent.service 2021-04-08T21:29:34.563471Z INFO ExtHandler ExtHandler Started tracking cgroup: walinuxagent.service, path: /sys/fs/cgroup/memory/system.slice/walinuxagent.service 2021-04-08T21:29:34.563698Z INFO ExtHandler ExtHandler Cgroups enabled: True 2021-04-08T21:29:34.564478Z INFO ExtHandler ExtHandler Created slice for Azure VM Agent and Extensions azure.slice 2021-04-08T21:29:34.565032Z INFO ExtHandler ExtHandler Created slice for Azure VM Extensions azure-vmextensions.slice 2021-04-08T21:29:34.567331Z INFO ExtHandler ExtHandler Starting setup for Persistent firewall rules 2021-04-08T21:29:34.575459Z INFO ExtHandler ExtHandler Firewalld service not running/unavailable, trying to set up walinuxagent-network-setup.service 2021-04-08T21:29:34.582038Z INFO ExtHandler ExtHandler Service: walinuxagent-network-setup.service not enabled. Adding it now 2021-04-08T21:29:34.789089Z INFO ExtHandler ExtHandler Successfully added and enabled the walinuxagent-network-setup.service 2021-04-08T21:29:34.789857Z INFO ExtHandler ExtHandler Drop-in file /lib/systemd/system/walinuxagent-network-setup.service.d/10-environment.conf successfully updated 2021-04-08T21:29:34.790129Z INFO ExtHandler ExtHandler Persistent firewall rules setup successfully 2021-04-08T21:29:34.794240Z INFO ExtHandler ExtHandler Checking if log collection is allowed at this time [False]. All three conditions must be met: configuration enabled [False], systemd present [True], python supported: [True] 2021-04-08T21:29:34.795343Z INFO ExtHandler ExtHandler Start env monitor service. 2021-04-08T21:29:34.795700Z INFO ExtHandler ExtHandler Configure routes 2021-04-08T21:29:34.796117Z INFO ExtHandler ExtHandler Gateway:None 2021-04-08T21:29:34.796501Z INFO ExtHandler ExtHandler Routes:None 2021-04-08T21:29:34.798367Z INFO MonitorHandler ExtHandler WireServer endpoint 168.63.129.16 read from file 2021-04-08T21:29:34.805064Z INFO MonitorHandler ExtHandler Wire server endpoint:168.63.129.16 2021-04-08T21:29:34.805784Z INFO MonitorHandler ExtHandler Monitor.NetworkConfigurationChanges is disabled. 2021-04-08T21:29:34.806116Z INFO MonitorHandler ExtHandler Routing table from /proc/net/route: Iface Destination Gateway Flags RefCnt Use Metric Mask MTU Window IRTT eth0 00000000 0100000A 0003 0 0 100 00000000 0 0 0 eth0 0000000A 00000000 0001 0 0 0 00FFFFFF 0 0 0 eth0 10813FA8 0100000A 0007 0 0 100 FFFFFFFF 0 0 0 eth0 FEA9FEA9 0100000A 0007 0 0 100 FFFFFFFF 0 0 0 docker0 000011AC 00000000 0001 0 0 0 0000FFFF 0 0 0

2021-04-08T21:29:34.811675Z INFO ExtHandler ExtHandler Start SendTelemetryHandler service. 2021-04-08T21:29:34.812618Z INFO EnvHandler ExtHandler WireServer endpoint 168.63.129.16 read from file 2021-04-08T21:29:34.812898Z INFO EnvHandler ExtHandler Wire server endpoint:168.63.129.16 2021-04-08T21:29:34.824112Z INFO ExtHandler ExtHandler Start Extension Telemetry service. 2021-04-08T21:29:34.823303Z INFO SendTelemetryHandler ExtHandler Successfully started the SendTelemetryHandler thread 2021-04-08T21:29:34.830088Z INFO TelemetryEventsCollector ExtHandler Extension Telemetry pipeline enabled: True 2021-04-08T21:29:34.836652Z INFO ExtHandler ExtHandler Checking for agent updates (family: Prod) 2021-04-08T21:29:34.840363Z INFO MonitorHandler ExtHandler Network interfaces: Executing ['ip', '-a', '-o', 'link']: 1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN mode DEFAULT group default qlen 1000\ link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00 2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP mode DEFAULT group default qlen 1000\ link/ether 00:22:48:1f:78:15 brd ff:ff:ff:ff:ff:ff 3: docker0: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc noqueue state DOWN mode DEFAULT group default \ link/ether 02:42:00:36:33:0a brd ff:ff:ff:ff:ff:ff

Executing ['ip', '-4', '-a', '-o', 'address']: 1: lo inet 127.0.0.1/8 scope host lo\ valid_lft forever preferred_lft forever 2: eth0 inet 10.0.0.6/24 brd 10.0.0.255 scope global eth0\ valid_lft forever preferred_lft forever 3: docker0 inet 172.17.0.1/16 brd 172.17.255.255 scope global docker0\ valid_lft forever preferred_lft forever

Executing ['ip', '-6', '-a', '-o', 'address']: 1: lo inet6 ::1/128 scope host \ valid_lft forever preferred_lft forever 2: eth0 inet6 fe80::222:48ff:fe1f:7815/64 scope link \ valid_lft forever preferred_lft forever

2021-04-08T21:29:34.838267Z INFO TelemetryEventsCollector ExtHandler Successfully started the TelemetryEventsCollector thread 2021-04-08T21:29:34.913515Z INFO ExtHandler ExtHandler ProcessGoalState started [Incarnation: 1; Activity Id: 273d2043-b749-4600-8f47-650bda31ee32; Correlation Id: 173601bd-7b59-40f6-b981-5b5f277939b4; GS Creation Time: 2021-04-08T21:27:06.220406Z] 2021-04-08T21:29:34.913965Z INFO ExtHandler ExtHandler No extension handlers found, not processing anything. 2021-04-08T21:29:34.939869Z INFO ExtHandler ExtHandler Looking for existing remote access users. 2021-04-08T21:29:34.941683Z INFO ExtHandler ExtHandler ProcessGoalState completed [Incarnation: 1; 55 ms; Activity Id: 273d2043-b749-4600-8f47-650bda31ee32; Correlation Id: 173601bd-7b59-40f6-b981-5b5f277939b4; GS Creation Time: 2021-04-08T21:27:06.220406Z] 2021-04-08T21:29:34.950012Z INFO ExtHandler ExtHandler [HEARTBEAT] Agent WALinuxAgent-2.2.54.2 is running as the goal state agent [DEBUG HeartbeatCounter: 0;HeartbeatId: FD6C394D-6FF1-45AB-B426-208A91BB88F5;DroppedPackets: 0;UpdateGSErrors: 0;AutoUpdate: 1] 2021-04-08T21:30:41.293397Z INFO ExtHandler ExtHandler Fetching new goal state [incarnation 2 (new incarnation)] 2021-04-08T21:30:41.333016Z INFO ExtHandler ExtHandler Certificate with thumbprint E95246F76D8648E4A57C2BC0F344C2D5DE9A050C has no matching private key. 2021-04-08T21:30:41.336875Z INFO ExtHandler ExtHandler Fetch goal state completed 2021-04-08T21:30:41.349878Z INFO ExtHandler ExtHandler ProcessGoalState started [Incarnation: 2; Activity Id: 2660cd3b-4c32-4649-bbed-c76de8d7a159; Correlation Id: 173601bd-7b59-40f6-b981-5b5f277939b4; GS Creation Time: 2021-04-08T21:27:06.220406Z] 2021-04-08T21:30:41.350201Z INFO ExtHandler ExtHandler No extension handlers found, not processing anything. 2021-04-08T21:30:41.356236Z INFO ExtHandler ExtHandler ProcessGoalState completed [Incarnation: 2; 18 ms; Activity Id: 2660cd3b-4c32-4649-bbed-c76de8d7a159; Correlation Id: 173601bd-7b59-40f6-b981-5b5f277939b4; GS Creation Time: 2021-04-08T21:27:06.220406Z] 2021/04/08 21:44:33.457960 INFO Daemon Agent WALinuxAgent-2.2.54.2 launched with command 'python3 -u bin/WALinuxAgent-2.2.54.2-py2.7.egg -run-exthandlers' is successfully running 2021-04-08T21:59:38.667562Z INFO ExtHandler ExtHandler [HEARTBEAT] Agent WALinuxAgent-2.2.54.2 is running as the goal state agent [DEBUG HeartbeatCounter: 1;HeartbeatId: FD6C394D-6FF1-45AB-B426-208A91BB88F5;DroppedPackets: 0;UpdateGSErrors: 0;AutoUpdate: 1] 2021-04-08T22:29:36.145459Z INFO ExtHandler ExtHandler Checking for agent updates (family: Prod) 2021-04-08T22:29:42.243293Z INFO ExtHandler ExtHandler [HEARTBEAT] Agent WALinuxAgent-2.2.54.2 is running as the goal state agent [DEBUG HeartbeatCounter: 2;HeartbeatId: FD6C394D-6FF1-45AB-B426-208A91BB88F5;DroppedPackets: 0;UpdateGSErrors: 0;AutoUpdate: 1] 2021-04-08T22:59:45.803511Z INFO ExtHandler ExtHandler [HEARTBEAT] Agent WALinuxAgent-2.2.54.2 is running as the goal state agent [DEBUG HeartbeatCounter: 3;HeartbeatId: FD6C394D-6FF1-45AB-B426-208A91BB88F5;DroppedPackets: 0;UpdateGSErrors: 0;AutoUpdate: 1] ```

piotch commented 6 months ago

With vmss you need to "Upgrade" the instances to trigger the script actions.

From the portal go to the VMSS resource, then Operations > Update, then Hosts Updates > Go to instances, select the instances and click "Upgrade" in the top menu.

Alternatively you can set the Update Policy to automatic (I have not tried this).

rquarry commented 3 weeks ago

I have spend the last three weeks struggling with the same issue as @adilliadil with my terraform project. I was able to confirm that using the "Upgrade" option does in fact trigger the script actions in the portal after issuing terraform apply

Now to figure out how to get this to trigger via IaC.