CSE executed before cloud-init

Start with the custom-script extension's enable handler and the ARM template dependency described in the issue. Compare the custom-script handler.log timestamps with cloud-init's journal entries, then trace how startup ordering is determined. Done means the CSE does not run its command until cloud-init has completed and the installed az command is available.

Hello,

I have an ARM template with VM + CSE script to be executed.
I've provided a cloud-init config through customData parameter.

My cloud-init looks as follows:

#cloud-config
package_upgrade: true
package_update: true
packages:
  - libssl-dev
  - libffi-dev
  - python-dev
runcmd:
  - curl -sL https://aka.ms/InstallAzureCLIDeb | sudo bash
  - az aks install-cli

Within the CSE script, I'm trying to run az login command, but I keep getting an error az: command not found.

When I ssh into VM, I can see az working just fine.

Actual behavior

I've looked through logs, and this is what I saw:

$ journalctl -b | grep cloud-init
Feb 10 16:25:14 kch-test-cluster-setupvm cloud-init[1613]: The following NEW packages will be installed:
Feb 10 16:25:14 kch-test-cluster-setupvm cloud-init[1613]:   azure-cli
Feb 10 16:25:14 kch-test-cluster-setupvm cloud-init[1613]: 0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded.
Feb 10 16:25:14 kch-test-cluster-setupvm cloud-init[1613]: Need to get 46.4 MB of archives.
Feb 10 16:25:14 kch-test-cluster-setupvm cloud-init[1613]: After this operation, 490 MB of additional disk space will be used.
Feb 10 16:25:14 kch-test-cluster-setupvm cloud-init[1613]: Get:1 https://packages.microsoft.com/repos/azure-cli bionic/main amd64 azure-cli all 2.0.81-1~bionic [46.4 MB]
Feb 10 16:25:15 kch-test-cluster-setupvm cloud-init[1613]: Fetched 46.4 MB in 1s (48.9 MB/s)
Feb 10 16:25:24 kch-test-cluster-setupvm cloud-init[1613]: Selecting previously unselected package azure-cli.
Feb 10 16:25:24 kch-test-cluster-setupvm cloud-init[1613]: [614B blob data]
Feb 10 16:25:24 kch-test-cluster-setupvm cloud-init[1613]: Preparing to unpack .../azure-cli_2.0.81-1~bionic_all.deb ...
Feb 10 16:25:24 kch-test-cluster-setupvm cloud-init[1613]: Unpacking azure-cli (2.0.81-1~bionic) ...
Feb 10 16:26:47 kch-test-cluster-setupvm cloud-init[1613]: Setting up azure-cli (2.0.81-1~bionic) ...
...

Please, note the time.

Then I've looked through custom script logs

$ cat /var/log/azure/custom-script/handler.log
...
time=2020-02-10T16:24:35Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="executing command" output=/var/lib/waagent/custom-script/download/0
time=2020-02-10T16:24:35Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="executing protected commandToExecute" output=/var/lib/waagent/custom-script/download/0
time=2020-02-10T16:24:36Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="failed to execute command" error="command terminated with exit status=1" output=/var/lib/waagent/custom-script/download/0
time=2020-02-10T16:24:36Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="enable failed"
time=2020-02-10T16:24:36Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="failed to handle" error="failed to execute command: command terminated with exit status=1"
...

Again, notice the time.

It turns out, CSE executed before cloud-init.

Expected behavior

I would expect CSE to be executed after cloud-init, especially since in my ARM template I have defined a dependency for CSE on VM deployment.

Best,
Karol