I am trying to debug some complex cloud-config user data and am having trouble finding the location of the log entries of the specific commands that cloud-init is running for the user data.
As an example, I am starting an EC2 instance and providing some simple cloud-config user data of
## template: jinja
#cloud-config
runcmd:
- echo 'unique-1234'
- echo 'Hello Cloud' > /tmp/cloud.log
I can confirm that cloud-init is running my user data commands:
/tmp/cloud.log exists and has the provided textvar/log/cloud-init-output.log file contains the echoed "unique-1234"However, what I want is some log information on what user data modules and commands were actually run.
That data should be in /var/log/cloud-init.log, but I can't find any evidence of it. There are lots of entries that look like:
Running command ['lsb_release', '--all'] with allowed return codes [0] (shell=False, capture=True)But a nothing about the user data provided commands I want to run. grep 'echo' /var/log/cloud-init.log has zero results.
After reading the logging documentation for cloud-init, I tried adding the following to my cloud-config yaml
reporting:
debug_log:
level: DEBUG
type: log
but the results were the same -- no new entries to cloud-init.log.
runcmd takes the commands specified and writes them to a shell script:
2024-06-17 15:32:54,101 - modules.py[DEBUG]: Running module runcmd (<module 'cloudinit.config.cc_runcmd' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_runcmd.py'>) with frequency once-per-instance
2024-06-17 15:32:54,101 - handlers.py[DEBUG]: start: modules-config/config-runcmd: running config-runcmd with frequency once-per-instance
2024-06-17 15:32:54,101 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/1ecf32de-49ab-47db-87f8-e0a20807c402/sem/config_runcmd - wb: [644] 24 bytes
2024-06-17 15:32:54,101 - helpers.py[DEBUG]: Running config-runcmd using lock (<FileLock using file '/var/lib/cloud/instances/1ecf32de-49ab-47db-87f8-e0a20807c402/sem/config_runcmd'>)
2024-06-17 15:32:54,101 - util.py[DEBUG]: Shellified 2 commands.
2024-06-17 15:32:54,101 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/1ecf32de-49ab-47db-87f8-e0a20807c402/scripts/runcmd - wb: [700] 65 bytes
2024-06-17 15:32:54,102 - handlers.py[DEBUG]: finish: modules-config/config-runcmd: SUCCESS: config-runcmd ran successfully
We can see it was written to /var/lib/cloud/instance/scripts/runcmd:
#!/bin/sh
echo 'unique-1234'
echo 'Hello Cloud' > /tmp/cloud.log
Taking a look at the runcmd documentation, we see
Note that the runcmd module only writes the script to be run later. The module that actually runs the script is scripts_user in the Final boot stage.
If we search the log from scripts_user, we can see that our script is getting run:
2024-06-17 15:32:54,722 - modules.py[DEBUG]: Running module scripts_user (<module 'cloudinit.config.cc_scripts_user' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_scripts_user.py'>) with frequency once-per-instance
2024-06-17 15:32:54,722 - handlers.py[DEBUG]: start: modules-final/config-scripts_user: running config-scripts_user with frequency once-per-instance
2024-06-17 15:32:54,722 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/1ecf32de-49ab-47db-87f8-e0a20807c402/sem/config_scripts_user - wb: [644] 24 bytes
2024-06-17 15:32:54,722 - helpers.py[DEBUG]: Running config-scripts_user using lock (<FileLock using file '/var/lib/cloud/instances/1ecf32de-49ab-47db-87f8-e0a20807c402/sem/config_scripts_user'>)
2024-06-17 15:32:54,722 - subp.py[DEBUG]: Running command ['/var/lib/cloud/instance/scripts/runcmd'] with allowed return codes [0] (shell=False, capture=False)
2024-06-17 15:32:54,723 - handlers.py[DEBUG]: finish: modules-final/config-scripts_user: SUCCESS: config-scripts_user ran successfully
Unfortunately, we'll only see anything about the script in cloud-init.log if the script encountered an error. Otherwise the stdout from the running the script goes into /var/log/cloud-init-output.log.
You can see the text that you echoed shows up there:
root@me:~# tail -3 /var/log/cloud-init-output.log
Cloud-init v. 24.1.6 running 'modules:final' at Mon, 17 Jun 2024 15:32:54 +0000. Up 3.32 seconds.
unique-1234
Cloud-init v. 24.1.6 finished at Mon, 17 Jun 2024 15:32:54 +0000. Datasource DataSourceLXD. Up 3.48 seconds