Cloud-init fails to mount datasource from iso disk sometimes

[Harsha Vardhan R]

cloud-init fails to mount the Datasource disk to /tmp/<tmpfolder> sometimes. This happens only sometimes not always.

Looks like systemd-tmpfiles-setup-dev.service is running almost at the same time when cloud-init-local.service starts. The systemd systemd-tmpfiles-setup-dev.service is wiping out the /tmp directory created by the cloud-init before the mount. Looks like there needs to be ordering dependency added on the cloud-init-local.service such that it starts after (or before?) systemd-tmpfiles-setup-dev.service

Description: Ubuntu 16.04.1 LTS
Release: 16.04

cloud-init:
  Installed: 0.7.8-49-g9e904bb-0ubuntu1~16.04.4
  Candidate: 0.7.9-48-g1c795b9-0ubuntu1~16.04.1
  Version table:
     0.7.9-48-g1c795b9-0ubuntu1~16.04.1 500
        500 http://archive.ubuntu.com/ubuntu xenial-updates/main amd64 Packages
 *** 0.7.8-49-g9e904bb-0ubuntu1~16.04.4 100
        100 /var/lib/dpkg/status
     0.7.7~bzr1212-0ubuntu1 500
        500 http://archive.ubuntu.com/ubuntu xenial/main amd64 Packages

cloud-init.log
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Cloud-init v. 0.7.8 running 'init-local' at Wed, 12 Apr 2017 07:56:29 +0000. Up 8.03 seconds.
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [420] 0 bytes
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 104:4
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance/boot-finished
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Attempting to remove /var/lib/cloud/data/no-net
Apr 12 07:56:33 ubuntu [CLOUDINIT] handlers.py[DEBUG]: start: init-local/check-cache: attempting to read from cache [check]
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
Apr 12 07:56:33 ubuntu [CLOUDINIT] stages.py[DEBUG]: no cache found
Apr 12 07:56:33 ubuntu [CLOUDINIT] handlers.py[DEBUG]: finish: init-local/check-cache: SUCCESS: no cache found
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance
Apr 12 07:56:33 ubuntu [CLOUDINIT] stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.ubuntu.Distro'>
Apr 12 07:56:33 ubuntu [CLOUDINIT] __init__.py[DEBUG]: Looking for for data source in: ['NoCloud', 'ConfigDrive', 'OpenNebula', 'DigitalOcean', 'Azure', 'AltCloud', 'OVF', 'MAAS', 'GCE', 'OpenStack', 'CloudSigma', 'SmartOS', 'Ec2', 'CloudStack', 'None'], via packages ['', 'cloudinit.sources'] that matches dependencies ['FILESYSTEM']
Apr 12 07:56:33 ubuntu [CLOUDINIT] __init__.py[DEBUG]: Searching for local data source in: ['DataSourceNoCloud', 'DataSourceConfigDrive', 'DataSourceOpenNebula', 'DataSourceDigitalOcean', 'DataSourceOVF', 'DataSourceCloudSigma', 'DataSourceSmartOS']
Apr 12 07:56:33 ubuntu [CLOUDINIT] handlers.py[DEBUG]: start: init-local/search-NoCloud: searching for local data from DataSourceNoCloud
Apr 12 07:56:33 ubuntu [CLOUDINIT] __init__.py[DEBUG]: Seeing if we can get any data from <class 'cloudinit.sources.DataSourceNoCloud.DataSourceNoCloud'>
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/user-data (quiet=False)
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/meta-data (quiet=False)
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/vendor-data (quiet=False)
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/network-config (quiet=False)
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/user-data (quiet=False)
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/meta-data (quiet=False)
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/vendor-data (quiet=False)
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/network-config (quiet=False)
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Running command ['blkid', '-odevice', '/dev/sr0'] with allowed return codes [0, 2] (shell=False, capture=True)
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Running command ['blkid', '-odevice', '/dev/sr1'] with allowed return codes [0, 2] (shell=False, capture=True)
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Running command ['blkid', '-tTYPE=vfat', '-odevice'] with allowed return codes [0, 2] (shell=False, capture=True)
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Running command ['blkid', '-tTYPE=iso9660', '-odevice'] with allowed return codes [0, 2] (shell=False, capture=True)
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Running command ['blkid', '-tLABEL=cidata', '-odevice'] with allowed return codes [0, 2] (shell=False, capture=True)
Apr 12 07:56:33 ubuntu [CLOUDINIT] DataSourceNoCloud.py[DEBUG]: Attempting to use data from /dev/sr0
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Reading from /proc/mounts (quiet=False)
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Read 2046 bytes from /proc/mounts
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Fetched {'fusectl': {'opts': 'rw,relatime', 'fstype': 'fusectl', 'mountpoint': '/sys/fs/fuse/connections'}, '/dev/sda1': {'opts': 'rw,relatime,data=ordered', 'fstype': 'ext4', 'mountpoint': '/'}, 'devpts': {'opts': 'rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000', 'fstype': 'devpts', 'mountpoint': '/dev/pts'}, 'systemd-1': {'opts': 'rw,relatime,fd=23,pgrp=1,timeout=0,minproto=5,maxproto=5,direct', 'fstype': 'autofs', 'mountpoint': '/proc/sys/fs/binfmt_misc'}, 'debugfs': {'opts': 'rw,relatime', 'fstype': 'debugfs', 'mountpoint': '/sys/kernel/debug'}, 'proc': {'opts': 'rw,nosuid,nodev,noexec,relatime', 'fstype': 'proc', 'mountpoint': '/proc'}, 'pstore': {'opts': 'rw,nosuid,nodev,noexec,relatime', 'fstype': 'pstore', 'mountpoint': '/sys/fs/pstore'}, 'hugetlbfs': {'opts': 'rw,relatime', 'fstype': 'hugetlbfs', 'mountpoint': '/dev/hugepages'}, 'tmpfs': {'opts': 'ro,relatime,size=817448k,mode=755', 'fstype': 'tmpfs', 'mountpoint': '/etc/machine-id'}, 'sysfs': {'opts': 'rw,nosuid,nodev,noexec,relatime', 'fstype': 'sysfs', 'mountpoint': '/sys'}, 'mqueue': {'opts': 'rw,relatime', 'fstype': 'mqueue', 'mountpoint': '/dev/mqueue'}, 'cgroup': {'opts': 'rw,nosuid,nodev,noexec,relatime,pids', 'fstype': 'cgroup', 'mountpoint': '/sys/fs/cgroup/pids'}, 'udev': {'opts': 'rw,nosuid,relatime,size=4078112k,nr_inodes=1019528,mode=755', 'fstype': 'devtmpfs', 'mountpoint': '/dev'}, 'securityfs': {'opts': 'rw,nosuid,nodev,noexec,relatime', 'fstype': 'securityfs', 'mountpoint': '/sys/kernel/security'}} mounts from proc
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Running command ['mount', '-o', 'ro,sync', '-t', 'auto', '/dev/sr0', '/tmp/tmpzq70nqyi'] with allowed return codes [0] (shell=False, capture=True)
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Failed mount of '/dev/sr0' as 'auto': Unexpected error while running command.#012Command: ['mount', '-o', 'ro,sync', '-t', 'auto', '/dev/sr0', '/tmp/tmpzq70nqyi']#012Exit code: 32#012Reason: -#012Stdout: ''#012Stderr: 'mount: mount point /tmp/tmpzq70nqyi does not exist\n'
Apr 12 07:56:33 ubuntu [CLOUDINIT] util.py[DEBUG]: Recursively deleting /tmp/tmpzq70nqyi
Apr 12 07:56:33 ubuntu [CLOUDINIT] handlers.py[DEBUG]: finish: init-local/search-NoCloud: SUCCESS: no local data found from DataSourceNoCloud

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[fxpester (a-yurtaykin)]

to fix this bug add: After=systemd-tmpfiles-setup-dev.service

to /lib/systemd/system/cloud-init-local.service