cloud-init

user-data ignored in DataSourceNoCloud

Bug #1718959 reported by Klaus Franken on 2017-09-22

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	cloud-init	Expired	Undecided	Unassigned

Bug Description

We have some OS-Templates with the official cloud-init packages.
We use a ISO-Image to push the configuration to the VM. The ISO is always the same expect IP number, SSH-Key etc. (generated from the same template).

[root@iptest-centos mnt]# cat meta-data
instance-id: iptest-centos.saas.noris.de
local-hostname: iptest-centos.saas.noris.de
fqdn: iptest-centos.saas.noris.de

network-interfaces: |
  auto eth0
  allow-hotplug eth0
  iface eth0 inet static
    dns-nameservers 62.128.1.42 62.128.1.53
    address 10.4.252.8
    netmask 255.255.0.0
    gateway 10.4.0.1

manage-resolv-conf: true
resolv_conf:
nameservers: ['62.128.1.42', '62.128.1.53'][root@iptest-centos mnt]#
[root@iptest-centos mnt]# cat user-data
#cloud-config

ssh_authorized_keys:
- ssh-rsa A....

chpasswd:
  list: |
    root:secret
  expire: False

#power_state:
  #mode: reboot
  #message: Reboot after first Cloud-Init configuration
  #timeout: 10

final_message: "$TIMESTAMP: System successfully configured with cloud-init from datasource $DATASOURCE."

runcmd:
# CD auswerfen, damit vCenter nicht stehen bleibt
- [ eject, /dev/sr0 ]

Template Status cloud-init Version

Debian8 OK 0.7.6~bzr976-2
Debian9 ERROR 0.7.9 (python3)
CentOS7 OK 0.7.9-9.el7.centos.2 (python2)
RHEL7 OK 0.7.6 Downgrade 0.7.9->0.7.6 due to other troubles
Ubuntu1604 ERROR 0.7.9-233-ge586fe35-0ubuntu1~16.0 (python3)
Ubuntu1704 ERROR 0.7.9-233-ge586fe35-0ubuntu1~17.0 (python3)
Ubuntu1404 OK 0.7.5
SLES12 ERROR 0.7.8 (python2) Some kind of other trouble.

Systems with status "OK" are loading meta-data and user-data and execute the config.
Systems with status "ERRIR" load meta-data only and ignoring the user-data completly.

Log file from Debian9 (with '--debug'):
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,767 - handlers.py[DEBUG]: start: modules-config: running modules for config
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,768 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,769 - util.py[DEBUG]: Read 11 bytes from /proc/uptime
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,769 - util.py[DEBUG]: Reading from /var/lib/cloud/data/status.json (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,770 - util.py[DEBUG]: Read 465 bytes from /var/lib/cloud/data/status.json
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,770 - util.py[DEBUG]: Creating symbolic link from '/run/cloud-init/status.json' => '../../var/lib/cloud/data/status.json'
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,771 - util.py[DEBUG]: Attempting to remove /run/cloud-init/status.json
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,772 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,772 - util.py[DEBUG]: Read 11 bytes from /proc/uptime
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,772 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,773 - util.py[DEBUG]: Read 1146 bytes from /etc/cloud/cloud.cfg
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,773 - util.py[DEBUG]: Attempting to load yaml from string of length 1146 with allowed root types (<class 'dict'>,)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,783 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99_noris.cfg (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,784 - util.py[DEBUG]: Read 427 bytes from /etc/cloud/cloud.cfg.d/99_noris.cfg
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,784 - util.py[DEBUG]: Attempting to load yaml from string of length 427 with allowed root types (<class 'dict'>,)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,787 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,788 - util.py[DEBUG]: Read 197 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,788 - util.py[DEBUG]: Attempting to load yaml from string of length 197 with allowed root types (<class 'dict'>,)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,789 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,789 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,789 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,791 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,792 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,792 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,793 - util.py[DEBUG]: Running command ['systemd-detect-virt', '--quiet', '--container'] with allowed return codes [0] (shell=False, capture=True)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,794 - util.py[DEBUG]: Running command ['running-in-container'] with allowed return codes [0] (shell=False, capture=True)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,796 - util.py[DEBUG]: Running command ['lxc-is-container'] with allowed return codes [0] (shell=False, capture=True)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,797 - util.py[DEBUG]: Reading from /proc/1/environ (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,797 - util.py[DEBUG]: Read 156 bytes from /proc/1/environ
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,797 - util.py[DEBUG]: Reading from /proc/self/status (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,797 - util.py[DEBUG]: Read 1003 bytes from /proc/self/status
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,797 - util.py[DEBUG]: Reading from /proc/cmdline (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,797 - util.py[DEBUG]: Read 92 bytes from /proc/cmdline
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,797 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,797 - util.py[DEBUG]: load_yaml given empty string, returning default
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,797 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,797 - util.py[DEBUG]: Read 26 bytes from /var/lib/cloud/instance/cloud-config.txt
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,797 - util.py[DEBUG]: Attempting to load yaml from string of length 26 with allowed root types (<class 'dict'>,)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,797 - handlers.py[DEBUG]: start: modules-config/check-cache: attempting to read from cache [trust]
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,797 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,797 - util.py[DEBUG]: Read 9853 bytes from /var/lib/cloud/instance/obj.pkl
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,811 - util.py[DEBUG]: Reading from /run/cloud-init/.instance-id (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,812 - util.py[DEBUG]: Read 29 bytes from /run/cloud-init/.instance-id
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,812 - stages.py[DEBUG]: restored from cache with run check: DataSourceNoCloud [seed=/dev/sr0][dsmode=net]
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,813 - handlers.py[DEBUG]: finish: modules-config/check-cache: SUCCESS: restored from cache with run check: DataSourceNoCloud [seed=/dev/sr0][dsmode=net]
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,815 - main.py[DEBUG]: Closing stdin
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,816 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,816 - util.py[DEBUG]: Read 1146 bytes from /etc/cloud/cloud.cfg
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,816 - util.py[DEBUG]: Attempting to load yaml from string of length 1146 with allowed root types (<class 'dict'>,)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,823 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99_noris.cfg (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,824 - util.py[DEBUG]: Read 427 bytes from /etc/cloud/cloud.cfg.d/99_noris.cfg
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,824 - util.py[DEBUG]: Attempting to load yaml from string of length 427 with allowed root types (<class 'dict'>,)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,825 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,825 - util.py[DEBUG]: Read 197 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,825 - util.py[DEBUG]: Attempting to load yaml from string of length 197 with allowed root types (<class 'dict'>,)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,827 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,828 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,828 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,831 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,832 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,832 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,833 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,833 - util.py[DEBUG]: load_yaml given empty string, returning default
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,834 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,836 - util.py[DEBUG]: Read 26 bytes from /var/lib/cloud/instance/cloud-config.txt
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,836 - util.py[DEBUG]: Attempting to load yaml from string of length 26 with allowed root types (<class 'dict'>,)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,836 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,836 - util.py[DEBUG]: Read 26 bytes from /var/lib/cloud/instance/cloud-config.txt
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,836 - util.py[DEBUG]: Attempting to load yaml from string of length 26 with allowed root types (<class 'dict'>,)
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,836 - util.py[DEBUG]: Redirecting <_io.TextIOWrapper name='<stdout>' mode='w' encoding='UTF-8'> to | tee -a /var/log/cloud-init-output.log
Sep 22 13:53:52 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,838 - util.py[DEBUG]: Redirecting <_io.TextIOWrapper name='<stderr>' mode='w' encoding='UTF-8'> to | tee -a /var/log/cloud-init-output.log
Sep 22 13:53:53 iptest-debian9 cloud-init[767]: 2017-09-22 13:53:52,838 - main.py[DEBUG]: Logging being reset, this logger may no longer be active shortly
Sep 22 13:53:53 iptest-debian9 cloud-init[767]: Cloud-init v. 0.7.9 running 'modules:config' at Fri, 22 Sep 2017 11:53:52 +0000. Up 10.60 seconds.
Sep 22 13:53:53 iptest-debian9 systemd[1]: Started Apply the settings specified in cloud-config.
Sep 22 13:53:53 iptest-debian9 systemd[1]: Starting Execute cloud user/final scripts...
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,754 - handlers.py[DEBUG]: start: modules-final: running modules for final
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,790 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,790 - util.py[DEBUG]: Read 11 bytes from /proc/uptime
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,790 - util.py[DEBUG]: Reading from /var/lib/cloud/data/status.json (quiet=False)
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,790 - util.py[DEBUG]: Read 493 bytes from /var/lib/cloud/data/status.json
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,791 - util.py[DEBUG]: Creating symbolic link from '/run/cloud-init/status.json' => '../../var/lib/cloud/data/status.json'
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,791 - util.py[DEBUG]: Attempting to remove /run/cloud-init/status.json
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,792 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,792 - util.py[DEBUG]: Read 11 bytes from /proc/uptime
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,792 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,792 - util.py[DEBUG]: Read 1146 bytes from /etc/cloud/cloud.cfg
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,792 - util.py[DEBUG]: Attempting to load yaml from string of length 1146 with allowed root types (<class 'dict'>,)
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,800 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99_noris.cfg (quiet=False)
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,801 - util.py[DEBUG]: Read 427 bytes from /etc/cloud/cloud.cfg.d/99_noris.cfg
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,801 - util.py[DEBUG]: Attempting to load yaml from string of length 427 with allowed root types (<class 'dict'>,)
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,803 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
Sep 22 13:53:54 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,803 - util.py[DEBUG]: Read 197 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,803 - util.py[DEBUG]: Attempting to load yaml from string of length 197 with allowed root types (<class 'dict'>,)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,805 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,805 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,805 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,891 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,891 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,891 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,894 - util.py[DEBUG]: Running command ['systemd-detect-virt', '--quiet', '--container'] with allowed return codes [0] (shell=False, capture=True)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,898 - util.py[DEBUG]: Running command ['running-in-container'] with allowed return codes [0] (shell=False, capture=True)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,900 - util.py[DEBUG]: Running command ['lxc-is-container'] with allowed return codes [0] (shell=False, capture=True)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,901 - util.py[DEBUG]: Reading from /proc/1/environ (quiet=False)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,902 - util.py[DEBUG]: Read 156 bytes from /proc/1/environ
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,902 - util.py[DEBUG]: Reading from /proc/self/status (quiet=False)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,902 - util.py[DEBUG]: Read 1003 bytes from /proc/self/status
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,902 - util.py[DEBUG]: Reading from /proc/cmdline (quiet=False)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,902 - util.py[DEBUG]: Read 92 bytes from /proc/cmdline
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,902 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,902 - util.py[DEBUG]: load_yaml given empty string, returning default
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,903 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,903 - util.py[DEBUG]: Read 26 bytes from /var/lib/cloud/instance/cloud-config.txt
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,903 - util.py[DEBUG]: Attempting to load yaml from string of length 26 with allowed root types (<class 'dict'>,)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,904 - handlers.py[DEBUG]: start: modules-final/check-cache: attempting to read from cache [trust]
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,904 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,904 - util.py[DEBUG]: Read 9853 bytes from /var/lib/cloud/instance/obj.pkl
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,998 - util.py[DEBUG]: Reading from /run/cloud-init/.instance-id (quiet=False)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,999 - util.py[DEBUG]: Read 29 bytes from /run/cloud-init/.instance-id
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,999 - stages.py[DEBUG]: restored from cache with run check: DataSourceNoCloud [seed=/dev/sr0][dsmode=net]
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,999 - handlers.py[DEBUG]: finish: modules-final/check-cache: SUCCESS: restored from cache with run check: DataSourceNoCloud [seed=/dev/sr0][dsmode=net]
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,999 - main.py[DEBUG]: Closing stdin
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,999 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,999 - util.py[DEBUG]: Read 1146 bytes from /etc/cloud/cloud.cfg
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:54,999 - util.py[DEBUG]: Attempting to load yaml from string of length 1146 with allowed root types (<class 'dict'>,)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,090 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99_noris.cfg (quiet=False)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,091 - util.py[DEBUG]: Read 427 bytes from /etc/cloud/cloud.cfg.d/99_noris.cfg
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,091 - util.py[DEBUG]: Attempting to load yaml from string of length 427 with allowed root types (<class 'dict'>,)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,094 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,094 - util.py[DEBUG]: Read 197 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,094 - util.py[DEBUG]: Attempting to load yaml from string of length 197 with allowed root types (<class 'dict'>,)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,096 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,096 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,096 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,100 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,100 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,100 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,102 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,102 - util.py[DEBUG]: load_yaml given empty string, returning default
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,102 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,102 - util.py[DEBUG]: Read 26 bytes from /var/lib/cloud/instance/cloud-config.txt
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,102 - util.py[DEBUG]: Attempting to load yaml from string of length 26 with allowed root types (<class 'dict'>,)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,103 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,103 - util.py[DEBUG]: Read 26 bytes from /var/lib/cloud/instance/cloud-config.txt
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,103 - util.py[DEBUG]: Attempting to load yaml from string of length 26 with allowed root types (<class 'dict'>,)
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,104 - util.py[DEBUG]: Redirecting <_io.TextIOWrapper name='<stdout>' mode='w' encoding='UTF-8'> to | tee -a /var/log/cloud-init-output.log
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,105 - util.py[DEBUG]: Redirecting <_io.TextIOWrapper name='<stderr>' mode='w' encoding='UTF-8'> to | tee -a /var/log/cloud-init-output.log
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: 2017-09-22 13:53:55,105 - main.py[DEBUG]: Logging being reset, this logger may no longer be active shortly
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: Cloud-init v. 0.7.9 running 'modules:final' at Fri, 22 Sep 2017 11:53:54 +0000. Up 12.62 seconds.
Sep 22 13:53:55 iptest-debian9 cloud-init[789]: Cloud-init v. 0.7.9 finished at Fri, 22 Sep 2017 11:53:55 +0000. Datasource DataSourceNoCloud [seed=/dev/sr0][dsmode=net]. Up 13.12 seconds
Sep 22 13:53:55 iptest-debian9 systemd[1]: Started Execute cloud user/final scripts.
Sep 22 13:53:55 iptest-debian9 systemd[1]: Reached target Cloud-init target.
Sep 22 13:53:55 iptest-debian9 systemd[1]: Startup finished in 5.090s (kernel) + 8.342s (userspace) = 13.433s.

Revision history for this message

Klaus Franken (kfranken) wrote on 2017-09-22:

cloud-init.tar Edit (870.0 KiB, application/x-tar)

Revision history for this message

Joshua Powers (powersj) wrote on 2017-09-22:

Hey! Thanks for taking the time to file a bug and include all the requested logs!

From /var/log/cloud-init-output.log

2017-09-22 10:43:51,199 - util.py[WARNING]: Failed loading yaml blob
2017-09-22 10:43:51,212 - util.py[WARNING]: Failed at merging in cloud config part from part-001

From /var/log/cloud-init.log:

2017-09-22 13:53:52,103 - util.py[DEBUG]: Attempting to load yaml from string of length 2641 with allowed root types (<class 'dict'>,)
2017-09-22 13:53:52,104 - util.py[WARNING]: Failed loading yaml blob
2017-09-22 13:53:52,108 - util.py[DEBUG]: Failed loading yaml blob
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/cloudinit/util.py", line 898, in load_yaml
    converted = safeyaml.load(blob)
  File "/usr/lib/python3/dist-packages/cloudinit/safeyaml.py", line 21, in load
    return(yaml.load(blob, Loader=_CustomSafeLoader))
  File "/usr/lib/python3/dist-packages/yaml/__init__.py", line 70, in load
    loader = Loader(stream)
  File "/usr/lib/python3/dist-packages/yaml/loader.py", line 24, in __init__
    Reader.__init__(self, stream)
  File "/usr/lib/python3/dist-packages/yaml/reader.py", line 74, in __init__
    self.check_printable(stream)
  File "/usr/lib/python3/dist-packages/yaml/reader.py", line 144, in check_printable
    'unicode', "special characters are not allowed")
yaml.reader.ReaderError: unacceptable character #xdcf6: special characters are not allowed
  in "<unicode string>", position 1851
2017-09-22 13:53:52,112 - util.py[WARNING]: Failed at merging in cloud config part from part-001
2017-09-22 13:53:52,113 - util.py[DEBUG]: Failed at merging in cloud config part from part-001
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/cloudinit/handlers/cloud_config.py", line 144, in handle_part
    self._merge_part(payload, headers)
  File "/usr/lib/python3/dist-packages/cloudinit/handlers/cloud_config.py", line 120, in _merge_part
    (payload_yaml, my_mergers) = self._extract_mergers(payload, headers)
  File "/usr/lib/python3/dist-packages/cloudinit/handlers/cloud_config.py", line 99, in _extract_mergers
    mergers_yaml = mergers.dict_extract_mergers(payload_yaml)
  File "/usr/lib/python3/dist-packages/cloudinit/mergers/__init__.py", line 83, in dict_extract_mergers
    raw_mergers = config.pop('merge_how', None)
AttributeError: 'NoneType' object has no attribute 'pop'

Hey! Thanks for taking the time to file a bug and include all the requested logs!

From /var/log/cloud-init-output.log

2017-09-22 10:43:51,199 - util.py[WARNING]: Failed loading yaml blob
2017-09-22 10:43:51,212 - util.py[WARNING]: Failed at merging in cloud config part from part-001

From /var/log/cloud-init.log:

Revision history for this message

Joshua Powers (powersj) wrote on 2017-09-22:

Looks like something is up with your cloud-config that the newer versions of cloud-init do not like, possibly some special unicode character?

I don't see anything standing out on the limited part of your cloud-config that you pasted in. The formatting looks good and as you noticed worked on some of the older versions of cloud-init.

Revision history for this message

Scott Moser (smoser) wrote on 2017-09-22:

Can you just attach 'dd if=/dev/sr0 of=my-nocloud.img'
or otherwise give the complete contents of what is there? Just grabbing the file you attach from the host would be fine.

it does seem like the yaml you provided in user-data is probably invaalid, but I suspect that hasn't made it through your paste.

Also, 'network-interfaces' is really deprecated.
I'd suggest you use network-config instead, which allows you to provide a more declarative/complete format for networking configuration.

Thanks

Joshua Powers (powersj) on 2017-09-22

Changed in cloud-init:
status:	New → Incomplete

Revision history for this message

Scott Moser (smoser) wrote on 2017-09-22:

Please set the status of the bug back to 'New' when you've attached the image.
Thanks.

Revision history for this message

Klaus Franken (kfranken) wrote on 2017-09-23:

user-data Edit (2.2 KiB, text/plain)

Hi Joshua,
Hi Scott,

you're right, it was an encoding problem! Thanks for your help.

There was a german umlaut in a comment in the user-data file, see attachment.

I tried to reproduce the problem, but I don't understand in the deep how the file is loaded as "blob". This code works correct in all situations:

----
import yaml
import sys
import six

# from util.py +146
def decode_binary(blob, encoding='utf-8'):
    # Converts a binary type into a text type using given encoding.
    if isinstance(blob, six.string_types):
        return blob
    return blob.decode(encoding)

# safeyaml.py
class _CustomSafeLoader(yaml.SafeLoader):
def construct_python_unicode(self, node):
return self.construct_scalar(node)

_CustomSafeLoader.add_constructor(
u'tag:yaml.org,2002:python/unicode',
_CustomSafeLoader.construct_python_unicode)

with open(sys.argv[1], "r") as stream:
    try:
        blob = stream.read()
        print(yaml.load(decode_binary(blob), Loader=_CustomSafeLoader))
    except yaml.YAMLError as exc:
        print(exc)
----

It seems that the file is loaded in another was to the blob object. I guess the utf-8 code is decoded twice in decode_binary(). Why it is necessary in util.py?

Anyway:
1. My primary problem is solved.
2. But it was really hard to debug. I think it is a bug that ther is no clear log entry "cannot read 'user_data' due to ....".
Ok, I'm shocked about myself that I didn't noticed the Traceback in cloud-init.log (because I only read deamon.log) and nowhere is "user-data" logged.
3. I think it is a bug that utf8 is not possible in "user-data" and possibly other files.

Thank you,
Klaus

Changed in cloud-init:
status:	Incomplete → New

Dan Watkins (oddbloke) on 2019-02-22

summary:	- user-data ignored in DataSourceNoCloud + UTF-8 characters in cloud-config cause cloud-init to fail
summary:	- UTF-8 characters in cloud-config cause cloud-init to fail + user-data ignored in DataSourceNoCloud

Revision history for this message

Dan Watkins (oddbloke) wrote on 2019-02-22:

I thought I was able to reproduce this issue, but I was actually seeing an unrelated issue. If someone can give us concrete reproducing steps, please set this bug back to New.

Thanks!

Dan