Using cloud-init for cloudless provisioning of Raspberry Pi

README.md

Installing cloud-init on a fresh Raspbian Lite image

This is a work in Progress!

Purpose

This mainly demonstrates my goal of preparing a Raspberry Pi to be provisioned prior to its first boot. To do this I have chosen to use the same cloud-init that is the standard for provisioning servers at Amazon EC2, Microsoft Azure, OpenStack, etc.

I found this to be quite challenging because there is little information available for using cloud-init without a cloud. So, this project also servers as a demonstration for anyone on any version of Linux who may want to install from source, and/or use without a cloud. If you fall into that later group, you probably just want to read the code. It's bash so everything I do, you could also do at the command line. (Even the for loop.)

Usage

1. Download the lastest Raspbian Lite release and write it to a microSD card. (This can be done from Mac, Windows, or of course Linux.)
2. On the microSD card, create an empty file named ssh and one named wpa_supplicant.conf (If you are on a Linux machine, you'll have to make sure this is going into the boot partition. On any other OS, the boot partition is the only one that can be mounted.)
3. Put your wifi settings into the wpa_supplicant.conf file. (There is a pretty handy online generator you can use.)
4. Save this script onto the microSD card.
5. Eject the card. Place it in your Raspberry Pi. Boot it up.
6. Locate your Raspberry Pi on your network.
   • Most modern routers will allow you to reach it via the hostname it declares, like so: raspberrypi.local
   • If that doesn't work in the next step, find the IP address via:
     • sudo nmap -sP $(route -n get 8.8.8.8 | awk '$1=="gateway:"{print $2}')/24 | awk '/^Nmap/{ip=$NF}/B8:27:EB/{print ip}'
     • That works for Mac and Linux. I have no idea how to do that in Windows.
7. SSH into the Raspberry Pi like so:
   • ssh [email protected]
   • The password is raspberry.
8. Run the script that we saved in Step 4 above.
   • /boot/cloud-init-setup.sh
   • You will be prompted for a password. Again, it is raspberry.

Result

Before rebooting you will find this:

pi@raspberrypi:~ $ find /boot/per*
/boot/per-boot
/boot/per-boot/01_get_ready.sh
/boot/per-boot/02_do_it.sh
/boot/per-once
/boot/per-once/01_prepare.sh
/boot/per-once/02_install_stuff.sh

After 1 reboot you will find this:

pi@raspberrypi:~ $ find /boot/per*
/boot/per-boot
/boot/per-boot/01_get_ready.sh
/boot/per-boot/02_do_it.sh
/boot/per-once
/boot/per-once/[email protected]
/boot/per-once/[email protected]
pi@raspberrypi:~ $ ls -l
-rw-r--r--  1 root root      62 Feb 21 10:04 per-boot.out
-rw-r--r--  1 root root      68 Feb 21 10:04 per-once.out
pi@raspberrypi:~ $ for f in per*; do echo $f; cat $f; done
per-boot.out
21/02/18 10:04:52 - 01_get_ready
21/02/18 10:04:52 - 02_do_it
per-once.out
21/02/18 10:04:52 - 01_prepare
21/02/18 10:04:52 - 02_install_stuff

After a 2nd reboot you will find this:

pi@raspberrypi:~ $ for f in per*; do echo $f; cat $f; done
per-boot.out
21/02/18 10:04:52 - 01_get_ready
21/02/18 10:04:52 - 02_do_it
21/02/18 10:06:12 - 01_get_ready
21/02/18 10:06:12 - 02_do_it
per-once.out
21/02/18 10:04:52 - 01_prepare
21/02/18 10:04:52 - 02_install_stuff

As you can see, the scripts in /boot/per-boot/ run on every boot. The scripts in /boot/per-once/ ran once and then got renamed. If you were to change their extension back to .sh they would run once again..

cloud-init-setup.sh

#!/bin/bash -e
set -x

# Get cloud-init
sudo apt update
sudo debconf-set-selections -v <<<"cloud-init cloud-init/datasources multiselect NoCloud, None" 2>/dev/null
sudo apt install -y cloud-init
#sudo debconf-set-selections -v <<<"cloud-init cloud-init/datasources multiselect NoCloud, None" 2>/dev/null; sudo dpkg-reconfigure cloud-init -f noninteractive 2>/dev/null;

# Prepare datasource
sudo tee /etc/cloud/cloud.cfg <<'YAML'
# The top level settings are used as module
# and system configuration.
datasource:
  NoCloud:
    seedfrom: /boot/

# A set of users which may be applied and/or used by various modules
# when a 'default' entry is found it will reference the 'default_user'
# from the distro configuration specified below
users:
   - default

# If this is set, 'root' will not be able to ssh in and they
# will get a message to login instead as the above $user (debian)
disable_root: true

# This will cause the set+update hostname module to not operate (if true)
preserve_hostname: false

# Example datasource config
# datasource:
#    Ec2:
#      metadata_urls: [ 'blah.com' ]
#      timeout: 5 # (defaults to 50 seconds)
#      max_wait: 10 # (defaults to 120 seconds)

# The modules that run in the 'init' stage
cloud_init_modules:
 - migrator
 - bootcmd
 - write-files
 - mounts
 - rsyslog
 - users-groups
 #- ssh

# The modules that run in the 'config' stage
cloud_config_modules:
# Emit the cloud config ready event
# this can be used by upstart jobs for 'start on cloud-config'.
 - ssh-import-id
 - locale
 - set-passwords
 - ntp
 - timezone
 - runcmd

# The modules that run in the 'final' stage
cloud_final_modules:
 - package-update-upgrade-install
 - scripts-vendor
 - scripts-per-once
 - scripts-per-boot
 - scripts-per-instance
 - scripts-user
 - phone-home
 - final-message

# System and/or distro specific settings
# (not accessible to handlers/transforms)
system_info:
   # This will affect which distro class gets used
   distro: debian
   # Default user name + that default users groups (if added/used)
   default_user:
     name: pi
     #lock_passwd: True
   # Other config here will be given to the distro class and/or path classes
   paths:
      cloud_dir: /var/lib/cloud/
      templates_dir: /etc/cloud/templates/
YAML

# Create meta-data
sudo tee /boot/meta-data <<'YAML'
instance-id: iid-raspberrypi-nocloud
YAML

# Create user-data
sudo tee /boot/user-data <<'YAML'
#cloud-config
packages:
 - vim
 - python3-pip
ssh_authorized_keys:
 - ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQC5UXba62TkiA6VqlBPxXdronnGDDdZ5Tcv0+wLLbb5k7A4Mn/XBZom/mKxbYhKVLDLHPYjpYub2piHOq//hP0qqqYJWMMvmRMGvyU9SAH7p+TLTLflfv8Th2jXAM+WOFESmWAY0uut2O0D7cCN5ILXcPNoGKqWI2Fyyx237pMHYOHYB82rAqdjbBZCJMd/Gd+fD0rogoCX3KZdDStzzl8u4C5aSB3rD7WvGNaqwDoQr+DakKnFXrgJG/rQSDcYuvMmi99bjyYm93riSNJ3QxnFz4eFQSpG28al54IkU1E9/aYfJLImCFfeMVNmbbHxtq9CpWR/HEoK3J4yExglyqCORTciDuydgqgHyVuqREBuxjGS4pldpcvuacqF2El2p6Saias1uv3JuoVLnLCCva4Us+m8p4Z2AQNm0I0Bl1OgJLLQUoe1dFomREBocnuwMByHoYCDYTjxw5DqehuTpSO7RtBVCa6492JnmKmwy1K9jPqsWrdCfEA9DVcnNSYsvqJmfcTHOJJ0pkC/f6QgfuAD3tWVSIZqYKnqkpCtixOS14+uCVe24Q4n8rBZF/8xNXThcbs9kWVi7k3aLgnLOLIosKZkHl1R3n+ss6TBH8D/Z19vuWJpiUNc1GbOpqsRPPFKwEtCUpZbj/D77zgMaRx3YX8w/dLcDZXUwDlwFdK1AQ==
 - ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDTcJk15RmarEQiZ7im3F6i5o0OOvPKCOmKKFwpGPJ3MZmYEXW3FRlsdGwRomNWdH6dTiDROQ9Cut0CMbeRrPvp6Y4H2iTXEnKShLYj5h7H00KLZGRcalC/BlpvNIBgasvaHq1Lu1oLJGQg62RErCWk2cdevQkJMAB9QObxukVp1uVBRWxGVlrVk2JbqZZ7zh8Lf81f6k9Lw9F3d03vHKARLIfXZVFpEY+qnTp0oXAJ1xTjrqY5reKNswiLtjyJwR6y16sOFQ4AE7rZI/q4zIcKgeBj/DHx2kqJxB/FSpnPRE0kDaAdbhljC7G8ulXptbd/OAtDLUIhYwvRr+AQKeZt [email protected]

YAML

# Initialize cloud-init
sudo cloud-init init --local

# Create a script to run per boot
sudo tee /var/lib/cloud/scripts/per-boot/00_run-parts.sh <<'BASH'
#!/bin/bash

# Prevent *.sh from returning itself if there are no matches
shopt -s nullglob

# Run every per-once script
run-parts --regex '.*\.sh$' /boot/per-once

# Rename every per-once script
for f in /boot/per-once/*.sh; do
    mv $f $(dirname $f)/$(basename $f .sh).$(date +%F@%H.%M.%S)
done

# Run every per-boot script
run-parts --regex '.*\.sh$' /boot/per-boot
BASH
sudo chmod +x /var/lib/cloud/scripts/per-boot/00_run-parts.sh

# Create sample per-boot and per-once scripts
sudo mkdir -p /boot/{per-boot,per-once}
sudo tee /boot/per-boot/01_get_ready.sh \
         /boot/per-boot/02_do_it.sh \
         /boot/per-once/01_prepare.sh \
         /boot/per-once/02_install_stuff.sh <<'BASH'
#!/bin/bash

date="$(date +"%x %X")"
script_path="$( cd "$( dirname "${BASH_SOURCE[0]}" )" && pwd )"
script_name="$(basename ${BASH_SOURCE[0]} .sh)"
log_name="$(basename $script_path)"

echo "$date - $script_name" >> /home/pi/${log_name}.out
BASH

echo "Cloud-Init setup is complete."
# vim: et sw=4 ts=4 sts=4 syntax=sh

logs.cloud-init-output.log

Cloud-init v. 0.7.9 running 'init-local' at Thu, 22 Feb 2018 04:03:23 +0000. Up 2626.88 seconds.
Cloud-init v. 0.7.9 running 'init-local' at Thu, 22 Feb 2018 04:07:31 +0000. Up 9.60 seconds.
Cloud-init v. 0.7.9 running 'init' at Thu, 22 Feb 2018 04:07:39 +0000. Up 17.22 seconds.
ci-info: +++++++++++++++++++++++++++Net device info++++++++++++++++++++++++++++
ci-info: +--------+-------+-----------+-----------+-------+-------------------+
ci-info: | Device |   Up  |  Address  |    Mask   | Scope |     Hw-Address    |
ci-info: +--------+-------+-----------+-----------+-------+-------------------+
ci-info: | wlan0: | False |     .     |     .     |   .   | b8:27:eb:00:e2:03 |
ci-info: |  lo:   |  True | 127.0.0.1 | 255.0.0.0 |   .   |         .         |
ci-info: |  lo:   |  True |     .     |     .     |   d   |         .         |
ci-info: | eth0:  | False |     .     |     .     |   .   | b8:27:eb:55:b7:56 |
ci-info: +--------+-------+-----------+-----------+-------+-------------------+
2018-02-22 04:07:42,134 - cc_resizefs.py[WARNING]: Device '/dev/PARTUUID=a00bdab5-02' did not exist. cannot resize: dev=/dev/root mnt_point=/ path=/
Generating public/private rsa key pair.
Your identification has been saved in /etc/ssh/ssh_host_rsa_key.
Your public key has been saved in /etc/ssh/ssh_host_rsa_key.pub.
The key fingerprint is:
SHA256:CZSzYvr7cD1/bLtIiAbrzBvgFrRQ91wA2gsGfSmgTnw root@raspberrypi
The key's randomart image is:
+---[RSA 2048]----+
|oo. oooo.        |
|ooo+o+o.         |
|oo=E. +o         |
|o+.oo... .       |
| .+oo.  S        |
| ..o o o .       |
|  o.+ + + ..     |
| . +.=   + .+    |
|    *+.   oooo   |
+----[SHA256]-----+
Generating public/private dsa key pair.
Your identification has been saved in /etc/ssh/ssh_host_dsa_key.
Your public key has been saved in /etc/ssh/ssh_host_dsa_key.pub.
The key fingerprint is:
SHA256:APHOBmdFICSPHyFvxgUSArF4xzGIWuKMy8aDqhfXEzQ root@raspberrypi
The key's randomart image is:
+---[DSA 1024]----+
|=o=+Xoooo        |
|+ooX OE.         |
|Boo @.=.         |
|o+ = B..         |
|+.  ..+.S        |
|o=. ..o          |
|o .o   .         |
|. .              |
|o.               |
+----[SHA256]-----+
Generating public/private ecdsa key pair.
Your identification has been saved in /etc/ssh/ssh_host_ecdsa_key.
Your public key has been saved in /etc/ssh/ssh_host_ecdsa_key.pub.
The key fingerprint is:
SHA256:OqnNkoOn0VusMHqUZ3L0uiNQ0jp0aiVAosy3hM0GnPM root@raspberrypi
The key's randomart image is:
+---[ECDSA 256]---+
|+o.              |
|*+=              |
|o=o*             |
|.o*Eo            |
|.+=+ .  S        |
|+o+.+..o         |
|.++*.o*          |
| .++BB .         |
|...+==o          |
+----[SHA256]-----+
Generating public/private ed25519 key pair.
Your identification has been saved in /etc/ssh/ssh_host_ed25519_key.
Your public key has been saved in /etc/ssh/ssh_host_ed25519_key.pub.
The key fingerprint is:
SHA256:K/+JFIOeJwpmaiLogGrj6oXP5sVh0PY9RaxYFU345qc root@raspberrypi
The key's randomart image is:
+--[ED25519 256]--+
|          o+=.   |
|    .    ..o .   |
|   . o  o ...    |
|    o .o...  o   |
|     o..So  o    |
|. . o... +.  . . |
|+.+. o= +     o  |
|*B+o.. * . . E   |
|&+++.   o.o      |
+----[SHA256]-----+
Generating locales (this might take a while)...
  en_GB.UTF-8... done
Generation complete.
Cloud-init v. 0.7.9 running 'modules:config' at Thu, 22 Feb 2018 04:08:04 +0000. Up 35.80 seconds.
Cloud-init v. 0.7.9 running 'modules:final' at Thu, 22 Feb 2018 04:08:15 +0000. Up 46.44 seconds.
ci-info: no authorized ssh keys fingerprints found for user debian.
Cloud-init v. 0.7.9 finished at Thu, 22 Feb 2018 04:08:16 +0000. Datasource DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net].  Up 47.36 seconds
Cloud-init v. 0.7.9 running 'init-local' at Thu, 22 Feb 2018 04:10:31 +0000. Up 9.63 seconds.
Cloud-init v. 0.7.9 running 'init' at Thu, 22 Feb 2018 04:10:38 +0000. Up 17.29 seconds.
ci-info: +++++++++++++++++++++++++++Net device info++++++++++++++++++++++++++++
ci-info: +--------+-------+-----------+-----------+-------+-------------------+
ci-info: | Device |   Up  |  Address  |    Mask   | Scope |     Hw-Address    |
ci-info: +--------+-------+-----------+-----------+-------+-------------------+
ci-info: | wlan0: | False |     .     |     .     |   .   | b8:27:eb:00:e2:03 |
ci-info: | eth0:  | False |     .     |     .     |   .   | b8:27:eb:55:b7:56 |
ci-info: |  lo:   |  True | 127.0.0.1 | 255.0.0.0 |   .   |         .         |
ci-info: |  lo:   |  True |     .     |     .     |   d   |         .         |
ci-info: +--------+-------+-----------+-----------+-------+-------------------+
2018-02-22 04:10:40,904 - cc_resizefs.py[WARNING]: Device '/dev/PARTUUID=a00bdab5-02' did not exist. cannot resize: dev=/dev/root mnt_point=/ path=/
Cloud-init v. 0.7.9 running 'modules:config' at Thu, 22 Feb 2018 04:10:50 +0000. Up 28.95 seconds.
Cloud-init v. 0.7.9 running 'modules:final' at Thu, 22 Feb 2018 04:10:54 +0000. Up 32.77 seconds.
Cloud-init v. 0.7.9 finished at Thu, 22 Feb 2018 04:10:55 +0000. Datasource DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net].  Up 33.45 seconds

logs.cloud-init.log

2018-02-22 04:03:24,131 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'init-local' at Thu, 22 Feb 2018 04:03:23 +0000. Up 2626.88 seconds.
2018-02-22 04:03:24,159 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [420] 0 bytes
2018-02-22 04:03:24,164 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 0:4
2018-02-22 04:03:24,166 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance/boot-finished
2018-02-22 04:03:24,167 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/data/no-net
2018-02-22 04:03:24,168 - handlers.py[DEBUG]: start: init-local/check-cache: attempting to read from cache [check]
2018-02-22 04:03:24,168 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
2018-02-22 04:03:24,168 - stages.py[DEBUG]: no cache found
2018-02-22 04:03:24,169 - handlers.py[DEBUG]: finish: init-local/check-cache: SUCCESS: no cache found
2018-02-22 04:03:24,169 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance
2018-02-22 04:03:24,180 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'>
2018-02-22 04:03:24,182 - __init__.py[DEBUG]: Looking for for data source in: ['NoCloud', 'ConfigDrive', 'OpenNebula', 'Azure', 'AltCloud', 'OVF', 'MAAS', 'GCE', 'OpenStack', 'CloudSigma', 'SmartOS', 'Ec2', 'CloudStack', 'None'], via packages ['', 'cloudinit.sources'] that matches dependencies ['FILESYSTEM']
2018-02-22 04:03:24,378 - __init__.py[DEBUG]: Searching for local data source in: ['DataSourceNoCloud', 'DataSourceConfigDrive', 'DataSourceOpenNebula', 'DataSourceOVF', 'DataSourceCloudSigma', 'DataSourceSmartOS']
2018-02-22 04:03:24,379 - handlers.py[DEBUG]: start: init-local/search-NoCloud: searching for local data from DataSourceNoCloud
2018-02-22 04:03:24,379 - __init__.py[DEBUG]: Seeing if we can get any data from <class 'cloudinit.sources.DataSourceNoCloud.DataSourceNoCloud'>
2018-02-22 04:03:24,380 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/user-data (quiet=False)
2018-02-22 04:03:24,381 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/meta-data (quiet=False)
2018-02-22 04:03:24,381 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/vendor-data (quiet=False)
2018-02-22 04:03:24,381 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/network-config (quiet=False)
2018-02-22 04:03:24,382 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/user-data (quiet=False)
2018-02-22 04:03:24,382 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/meta-data (quiet=False)
2018-02-22 04:03:24,382 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/vendor-data (quiet=False)
2018-02-22 04:03:24,383 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/network-config (quiet=False)
2018-02-22 04:03:24,383 - util.py[DEBUG]: Running command ['/sbin/blkid', '-odevice', '/dev/sr0'] with allowed return codes [0, 2] (shell=False, capture=True)
2018-02-22 04:03:24,396 - util.py[DEBUG]: Running command ['/sbin/blkid', '-odevice', '/dev/sr1'] with allowed return codes [0, 2] (shell=False, capture=True)
2018-02-22 04:03:24,404 - util.py[DEBUG]: Running command ['/sbin/blkid', '-tTYPE=vfat', '-odevice'] with allowed return codes [0, 2] (shell=False, capture=True)
2018-02-22 04:03:24,437 - util.py[DEBUG]: Running command ['/sbin/blkid', '-tTYPE=iso9660', '-odevice'] with allowed return codes [0, 2] (shell=False, capture=True)
2018-02-22 04:03:24,458 - util.py[DEBUG]: Running command ['/sbin/blkid', '-tLABEL=cidata', '-odevice'] with allowed return codes [0, 2] (shell=False, capture=True)
2018-02-22 04:03:24,479 - util.py[DEBUG]: Reading from /boot/meta-data (quiet=False)
2018-02-22 04:03:24,480 - util.py[DEBUG]: Read 37 bytes from /boot/meta-data
2018-02-22 04:03:24,480 - util.py[DEBUG]: Attempting to load yaml from string of length 37 with allowed root types (<class 'dict'>,)
2018-02-22 04:03:24,484 - util.py[DEBUG]: Reading from /boot/user-data (quiet=False)
2018-02-22 04:03:24,484 - util.py[DEBUG]: Read 60 bytes from /boot/user-data
2018-02-22 04:03:24,484 - DataSourceNoCloud.py[DEBUG]: Using seeded cache data from /boot/
2018-02-22 04:03:24,487 - handlers.py[DEBUG]: finish: init-local/search-NoCloud: SUCCESS: found local data from DataSourceNoCloud
2018-02-22 04:03:24,487 - stages.py[INFO]: Loaded datasource DataSourceNoCloud - DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net]
2018-02-22 04:03:24,488 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2018-02-22 04:03:24,489 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg
2018-02-22 04:03:24,489 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,)
2018-02-22 04:03:24,585 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/datasource.cfg (quiet=False)
2018-02-22 04:03:24,585 - util.py[DEBUG]: Read 45 bytes from /etc/cloud/cloud.cfg.d/datasource.cfg
2018-02-22 04:03:24,586 - util.py[DEBUG]: Attempting to load yaml from string of length 45 with allowed root types (<class 'dict'>,)
2018-02-22 04:03:24,591 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2018-02-22 04:03:24,591 - util.py[DEBUG]: Read 197 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2018-02-22 04:03:24,592 - util.py[DEBUG]: Attempting to load yaml from string of length 197 with allowed root types (<class 'dict'>,)
2018-02-22 04:03:24,603 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2018-02-22 04:03:24,604 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2018-02-22 04:03:24,604 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2018-02-22 04:03:24,640 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False)
2018-02-22 04:03:24,641 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg
2018-02-22 04:03:24,641 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,)
2018-02-22 04:03:24,651 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2018-02-22 04:03:24,652 - util.py[DEBUG]: load_yaml given empty string, returning default
2018-02-22 04:03:24,656 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance
2018-02-22 04:03:24,656 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/iid-raspberrypi-nocloud'
2018-02-22 04:03:24,664 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/iid-raspberrypi-nocloud/datasource (quiet=False)
2018-02-22 04:03:24,665 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/datasource - wb: [420] 82 bytes
2018-02-22 04:03:24,668 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [420] 82 bytes
2018-02-22 04:03:24,671 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False)
2018-02-22 04:03:24,671 - stages.py[DEBUG]: previous iid found to be NO_PREVIOUS_INSTANCE_ID
2018-02-22 04:03:24,672 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [420] 24 bytes
2018-02-22 04:03:24,675 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [420] 24 bytes
2018-02-22 04:03:24,677 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [420] 24 bytes
2018-02-22 04:03:24,681 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [256] 5259 bytes
2018-02-22 04:03:24,684 - main.py[DEBUG]: [local] init will now be targeting instance id: iid-raspberrypi-nocloud. new=True
2018-02-22 04:03:24,685 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2018-02-22 04:03:24,686 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg
2018-02-22 04:03:24,686 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,)
2018-02-22 04:03:24,776 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/datasource.cfg (quiet=False)
2018-02-22 04:03:24,776 - util.py[DEBUG]: Read 45 bytes from /etc/cloud/cloud.cfg.d/datasource.cfg
2018-02-22 04:03:24,777 - util.py[DEBUG]: Attempting to load yaml from string of length 45 with allowed root types (<class 'dict'>,)
2018-02-22 04:03:24,781 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2018-02-22 04:03:24,782 - util.py[DEBUG]: Read 197 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2018-02-22 04:03:24,782 - util.py[DEBUG]: Attempting to load yaml from string of length 197 with allowed root types (<class 'dict'>,)
2018-02-22 04:03:24,794 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2018-02-22 04:03:24,795 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2018-02-22 04:03:24,795 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2018-02-22 04:03:24,831 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False)
2018-02-22 04:03:24,832 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg
2018-02-22 04:03:24,832 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,)
2018-02-22 04:03:24,842 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2018-02-22 04:03:24,843 - util.py[DEBUG]: load_yaml given empty string, returning default
2018-02-22 04:03:24,848 - util.py[DEBUG]: Reading from /sys/class/net/eth0/carrier (quiet=False)
2018-02-22 04:03:24,849 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/eth0/carrier
2018-02-22 04:03:24,849 - util.py[DEBUG]: Reading from /sys/class/net/eth0/dormant (quiet=False)
2018-02-22 04:03:24,850 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/eth0/dormant
2018-02-22 04:03:24,850 - util.py[DEBUG]: Reading from /sys/class/net/eth0/operstate (quiet=False)
2018-02-22 04:03:24,851 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/eth0/operstate
2018-02-22 04:03:24,851 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/carrier (quiet=False)
2018-02-22 04:03:24,852 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/wlan0/carrier
2018-02-22 04:03:24,852 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/address (quiet=False)
2018-02-22 04:03:24,852 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/wlan0/address
2018-02-22 04:03:24,853 - stages.py[DEBUG]: applying net config names for {'version': 1, 'config': [{'type': 'physical', 'subnets': [{'type': 'dhcp'}], 'mac_address': 'b8:27:eb:00:e2:03', 'name': 'wlan0'}]}
2018-02-22 04:03:24,856 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'>
2018-02-22 04:03:24,857 - util.py[DEBUG]: Reading from /sys/class/net/eth0/operstate (quiet=False)
2018-02-22 04:03:24,857 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/eth0/operstate
2018-02-22 04:03:24,857 - util.py[DEBUG]: Reading from /sys/class/net/eth0/address (quiet=False)
2018-02-22 04:03:24,858 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/eth0/address
2018-02-22 04:03:24,858 - util.py[DEBUG]: Reading from /sys/class/net/lo/operstate (quiet=False)
2018-02-22 04:03:24,859 - util.py[DEBUG]: Read 8 bytes from /sys/class/net/lo/operstate
2018-02-22 04:03:24,859 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False)
2018-02-22 04:03:24,860 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address
2018-02-22 04:03:24,860 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/operstate (quiet=False)
2018-02-22 04:03:24,860 - util.py[DEBUG]: Read 3 bytes from /sys/class/net/wlan0/operstate
2018-02-22 04:03:24,861 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/address (quiet=False)
2018-02-22 04:03:24,861 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/wlan0/address
2018-02-22 04:03:24,863 - util.py[DEBUG]: Running command ['ip', '-6', 'addr', 'show', 'permanent', 'scope', 'global'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:03:24,873 - util.py[DEBUG]: Running command ['ip', '-4', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:03:24,884 - __init__.py[DEBUG]: no work necessary for renaming of [['b8:27:eb:00:e2:03', 'wlan0']]
2018-02-22 04:03:24,886 - stages.py[INFO]: Applying network configuration from fallback bringup=False: {'version': 1, 'config': [{'type': 'physical', 'subnets': [{'type': 'dhcp'}], 'mac_address': 'b8:27:eb:00:e2:03', 'name': 'wlan0'}]}
2018-02-22 04:03:24,899 - util.py[DEBUG]: Writing to /etc/network/interfaces.d/50-cloud-init.cfg - wb: [420] 369 bytes
2018-02-22 04:03:24,902 - main.py[DEBUG]: [local] Exiting. datasource DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net] not in local mode.
2018-02-22 04:03:24,905 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2018-02-22 04:03:24,905 - util.py[DEBUG]: Read 17 bytes from /proc/uptime
2018-02-22 04:03:24,906 - util.py[DEBUG]: cloud-init mode 'init' took 0.994 seconds (0.99)
2018-02-22 04:03:24,906 - handlers.py[DEBUG]: finish: init-local: SUCCESS: searching for local datasources
2018-02-22 04:07:32,386 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'init-local' at Thu, 22 Feb 2018 04:07:31 +0000. Up 9.60 seconds.
2018-02-22 04:07:32,420 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [420] 0 bytes
2018-02-22 04:07:32,429 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 0:4
2018-02-22 04:07:32,433 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance/boot-finished
2018-02-22 04:07:32,434 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/data/no-net
2018-02-22 04:07:32,436 - handlers.py[DEBUG]: start: init-local/check-cache: attempting to read from cache [check]
2018-02-22 04:07:32,436 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
2018-02-22 04:07:32,440 - util.py[DEBUG]: Read 5259 bytes from /var/lib/cloud/instance/obj.pkl
2018-02-22 04:07:32,460 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/meta-data (quiet=False)
2018-02-22 04:07:32,462 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/meta-data (quiet=False)
2018-02-22 04:07:32,464 - stages.py[DEBUG]: cache invalid in datasource: DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net]
2018-02-22 04:07:32,465 - handlers.py[DEBUG]: finish: init-local/check-cache: SUCCESS: cache invalid in datasource: DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net]
2018-02-22 04:07:32,465 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance
2018-02-22 04:07:32,480 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'>
2018-02-22 04:07:32,484 - __init__.py[DEBUG]: Looking for for data source in: ['NoCloud', 'ConfigDrive', 'OpenNebula', 'Azure', 'AltCloud', 'OVF', 'MAAS', 'GCE', 'OpenStack', 'CloudSigma', 'SmartOS', 'Ec2', 'CloudStack', 'None'], via packages ['', 'cloudinit.sources'] that matches dependencies ['FILESYSTEM']
2018-02-22 04:07:32,887 - __init__.py[DEBUG]: Searching for local data source in: ['DataSourceNoCloud', 'DataSourceConfigDrive', 'DataSourceOpenNebula', 'DataSourceOVF', 'DataSourceCloudSigma', 'DataSourceSmartOS']
2018-02-22 04:07:32,889 - handlers.py[DEBUG]: start: init-local/search-NoCloud: searching for local data from DataSourceNoCloud
2018-02-22 04:07:32,890 - __init__.py[DEBUG]: Seeing if we can get any data from <class 'cloudinit.sources.DataSourceNoCloud.DataSourceNoCloud'>
2018-02-22 04:07:32,891 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/user-data (quiet=False)
2018-02-22 04:07:32,892 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/meta-data (quiet=False)
2018-02-22 04:07:32,893 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/vendor-data (quiet=False)
2018-02-22 04:07:32,894 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/network-config (quiet=False)
2018-02-22 04:07:32,894 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/user-data (quiet=False)
2018-02-22 04:07:32,895 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/meta-data (quiet=False)
2018-02-22 04:07:32,896 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/vendor-data (quiet=False)
2018-02-22 04:07:32,896 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/network-config (quiet=False)
2018-02-22 04:07:32,897 - util.py[DEBUG]: Running command ['/sbin/blkid', '-odevice', '/dev/sr0'] with allowed return codes [0, 2] (shell=False, capture=True)
2018-02-22 04:07:32,915 - util.py[DEBUG]: Running command ['/sbin/blkid', '-odevice', '/dev/sr1'] with allowed return codes [0, 2] (shell=False, capture=True)
2018-02-22 04:07:32,929 - util.py[DEBUG]: Running command ['/sbin/blkid', '-tTYPE=vfat', '-odevice'] with allowed return codes [0, 2] (shell=False, capture=True)
2018-02-22 04:07:32,983 - util.py[DEBUG]: Running command ['/sbin/blkid', '-tTYPE=iso9660', '-odevice'] with allowed return codes [0, 2] (shell=False, capture=True)
2018-02-22 04:07:33,020 - util.py[DEBUG]: Running command ['/sbin/blkid', '-tLABEL=cidata', '-odevice'] with allowed return codes [0, 2] (shell=False, capture=True)
2018-02-22 04:07:33,057 - util.py[DEBUG]: Reading from /boot/meta-data (quiet=False)
2018-02-22 04:07:33,060 - util.py[DEBUG]: Read 37 bytes from /boot/meta-data
2018-02-22 04:07:33,061 - util.py[DEBUG]: Attempting to load yaml from string of length 37 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:33,067 - util.py[DEBUG]: Reading from /boot/user-data (quiet=False)
2018-02-22 04:07:33,070 - util.py[DEBUG]: Read 60 bytes from /boot/user-data
2018-02-22 04:07:33,070 - DataSourceNoCloud.py[DEBUG]: Using seeded cache data from /boot/
2018-02-22 04:07:33,075 - handlers.py[DEBUG]: finish: init-local/search-NoCloud: SUCCESS: found local data from DataSourceNoCloud
2018-02-22 04:07:33,076 - stages.py[INFO]: Loaded datasource DataSourceNoCloud - DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net]
2018-02-22 04:07:33,078 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2018-02-22 04:07:33,079 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg
2018-02-22 04:07:33,080 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:33,267 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/datasource.cfg (quiet=False)
2018-02-22 04:07:33,268 - util.py[DEBUG]: Read 45 bytes from /etc/cloud/cloud.cfg.d/datasource.cfg
2018-02-22 04:07:33,268 - util.py[DEBUG]: Attempting to load yaml from string of length 45 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:33,278 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2018-02-22 04:07:33,279 - util.py[DEBUG]: Read 197 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2018-02-22 04:07:33,280 - util.py[DEBUG]: Attempting to load yaml from string of length 197 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:33,303 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2018-02-22 04:07:33,304 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2018-02-22 04:07:33,305 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:33,375 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False)
2018-02-22 04:07:33,377 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg
2018-02-22 04:07:33,377 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:33,396 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:33,398 - util.py[DEBUG]: load_yaml given empty string, returning default
2018-02-22 04:07:33,405 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance
2018-02-22 04:07:33,406 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/iid-raspberrypi-nocloud'
2018-02-22 04:07:33,414 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/iid-raspberrypi-nocloud/datasource (quiet=False)
2018-02-22 04:07:33,417 - util.py[DEBUG]: Read 82 bytes from /var/lib/cloud/instances/iid-raspberrypi-nocloud/datasource
2018-02-22 04:07:33,418 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/datasource - wb: [420] 82 bytes
2018-02-22 04:07:33,424 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [420] 82 bytes
2018-02-22 04:07:33,431 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False)
2018-02-22 04:07:33,433 - util.py[DEBUG]: Read 24 bytes from /var/lib/cloud/data/instance-id
2018-02-22 04:07:33,434 - stages.py[DEBUG]: previous iid found to be iid-raspberrypi-nocloud
2018-02-22 04:07:33,435 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [420] 24 bytes
2018-02-22 04:07:33,441 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [420] 24 bytes
2018-02-22 04:07:33,447 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [420] 24 bytes
2018-02-22 04:07:33,454 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [256] 5259 bytes
2018-02-22 04:07:33,461 - main.py[DEBUG]: [local] init will now be targeting instance id: iid-raspberrypi-nocloud. new=False
2018-02-22 04:07:33,463 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2018-02-22 04:07:33,464 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg
2018-02-22 04:07:33,464 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:33,644 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/datasource.cfg (quiet=False)
2018-02-22 04:07:33,645 - util.py[DEBUG]: Read 45 bytes from /etc/cloud/cloud.cfg.d/datasource.cfg
2018-02-22 04:07:33,646 - util.py[DEBUG]: Attempting to load yaml from string of length 45 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:33,655 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2018-02-22 04:07:33,656 - util.py[DEBUG]: Read 197 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2018-02-22 04:07:33,657 - util.py[DEBUG]: Attempting to load yaml from string of length 197 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:33,681 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2018-02-22 04:07:33,682 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2018-02-22 04:07:33,682 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:33,753 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False)
2018-02-22 04:07:33,754 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg
2018-02-22 04:07:33,755 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:33,774 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:33,775 - util.py[DEBUG]: load_yaml given empty string, returning default
2018-02-22 04:07:33,786 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/carrier (quiet=False)
2018-02-22 04:07:33,787 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/dormant (quiet=False)
2018-02-22 04:07:33,788 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/operstate (quiet=False)
2018-02-22 04:07:33,789 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/wlan0/operstate
2018-02-22 04:07:33,790 - util.py[DEBUG]: Reading from /sys/class/net/eth0/carrier (quiet=False)
2018-02-22 04:07:33,791 - util.py[DEBUG]: Reading from /sys/class/net/eth0/dormant (quiet=False)
2018-02-22 04:07:33,792 - util.py[DEBUG]: Reading from /sys/class/net/eth0/operstate (quiet=False)
2018-02-22 04:07:33,793 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/eth0/operstate
2018-02-22 04:07:33,794 - util.py[DEBUG]: Reading from /sys/class/net/eth0/address (quiet=False)
2018-02-22 04:07:33,794 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/eth0/address
2018-02-22 04:07:33,795 - stages.py[DEBUG]: applying net config names for {'config': [{'subnets': [{'type': 'dhcp'}], 'name': 'eth0', 'mac_address': 'b8:27:eb:55:b7:56', 'type': 'physical'}], 'version': 1}
2018-02-22 04:07:33,801 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'>
2018-02-22 04:07:33,802 - util.py[DEBUG]: Reading from /sys/class/net/eth0/operstate (quiet=False)
2018-02-22 04:07:33,803 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/eth0/operstate
2018-02-22 04:07:33,804 - util.py[DEBUG]: Reading from /sys/class/net/eth0/address (quiet=False)
2018-02-22 04:07:33,805 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/eth0/address
2018-02-22 04:07:33,806 - util.py[DEBUG]: Reading from /sys/class/net/lo/operstate (quiet=False)
2018-02-22 04:07:33,806 - util.py[DEBUG]: Read 8 bytes from /sys/class/net/lo/operstate
2018-02-22 04:07:33,807 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False)
2018-02-22 04:07:33,808 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address
2018-02-22 04:07:33,809 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/operstate (quiet=False)
2018-02-22 04:07:33,809 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/wlan0/operstate
2018-02-22 04:07:33,810 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/address (quiet=False)
2018-02-22 04:07:33,811 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/wlan0/address
2018-02-22 04:07:33,814 - util.py[DEBUG]: Running command ['ip', '-6', 'addr', 'show', 'permanent', 'scope', 'global'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:33,849 - util.py[DEBUG]: Running command ['ip', '-4', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:33,865 - __init__.py[DEBUG]: no work necessary for renaming of [['b8:27:eb:55:b7:56', 'eth0']]
2018-02-22 04:07:33,870 - stages.py[DEBUG]: not a new instance. network config is not applied.
2018-02-22 04:07:33,870 - main.py[DEBUG]: [local] Exiting. datasource DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net] not in local mode.
2018-02-22 04:07:33,875 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2018-02-22 04:07:33,877 - util.py[DEBUG]: Read 12 bytes from /proc/uptime
2018-02-22 04:07:33,877 - util.py[DEBUG]: cloud-init mode 'init' took 1.924 seconds (1.92)
2018-02-22 04:07:33,879 - handlers.py[DEBUG]: finish: init-local: SUCCESS: searching for local datasources
2018-02-22 04:07:39,940 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'init' at Thu, 22 Feb 2018 04:07:39 +0000. Up 17.22 seconds.
2018-02-22 04:07:39,972 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [420] 0 bytes
2018-02-22 04:07:39,981 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 0:4
2018-02-22 04:07:39,982 - util.py[DEBUG]: Running command ['ifconfig', '-a'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:40,543 - util.py[DEBUG]: Running command ['netstat', '-rn'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:40,566 - util.py[DEBUG]: Running command ['netstat', '-A', 'inet6', '-n'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:40,582 - main.py[DEBUG]: Checking to see if files that we need already exist from a previous run that would allow us to stop early.
2018-02-22 04:07:40,584 - main.py[DEBUG]: Execution continuing, no previous run detected that would allow us to stop early.
2018-02-22 04:07:40,585 - handlers.py[DEBUG]: start: init-network/check-cache: attempting to read from cache [trust]
2018-02-22 04:07:40,586 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
2018-02-22 04:07:40,587 - util.py[DEBUG]: Read 5259 bytes from /var/lib/cloud/instance/obj.pkl
2018-02-22 04:07:40,599 - util.py[DEBUG]: Reading from /run/cloud-init/.instance-id (quiet=False)
2018-02-22 04:07:40,600 - util.py[DEBUG]: Read 24 bytes from /run/cloud-init/.instance-id
2018-02-22 04:07:40,601 - stages.py[DEBUG]: restored from cache with run check: DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net]
2018-02-22 04:07:40,603 - handlers.py[DEBUG]: finish: init-network/check-cache: SUCCESS: restored from cache with run check: DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net]
2018-02-22 04:07:40,605 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2018-02-22 04:07:40,606 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg
2018-02-22 04:07:40,607 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:40,785 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/datasource.cfg (quiet=False)
2018-02-22 04:07:40,786 - util.py[DEBUG]: Read 45 bytes from /etc/cloud/cloud.cfg.d/datasource.cfg
2018-02-22 04:07:40,787 - util.py[DEBUG]: Attempting to load yaml from string of length 45 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:40,796 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2018-02-22 04:07:40,797 - util.py[DEBUG]: Read 197 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2018-02-22 04:07:40,798 - util.py[DEBUG]: Attempting to load yaml from string of length 197 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:40,821 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2018-02-22 04:07:40,822 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2018-02-22 04:07:40,823 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:40,894 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False)
2018-02-22 04:07:40,895 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg
2018-02-22 04:07:40,895 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:40,914 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:40,916 - util.py[DEBUG]: load_yaml given empty string, returning default
2018-02-22 04:07:40,923 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance
2018-02-22 04:07:40,924 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/iid-raspberrypi-nocloud'
2018-02-22 04:07:40,932 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/iid-raspberrypi-nocloud/datasource (quiet=False)
2018-02-22 04:07:40,933 - util.py[DEBUG]: Read 82 bytes from /var/lib/cloud/instances/iid-raspberrypi-nocloud/datasource
2018-02-22 04:07:40,934 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/datasource - wb: [420] 82 bytes
2018-02-22 04:07:40,939 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [420] 82 bytes
2018-02-22 04:07:40,945 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False)
2018-02-22 04:07:40,946 - util.py[DEBUG]: Read 24 bytes from /var/lib/cloud/data/instance-id
2018-02-22 04:07:40,947 - stages.py[DEBUG]: previous iid found to be iid-raspberrypi-nocloud
2018-02-22 04:07:40,948 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [420] 24 bytes
2018-02-22 04:07:40,954 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [420] 24 bytes
2018-02-22 04:07:40,959 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [420] 24 bytes
2018-02-22 04:07:40,966 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [256] 5343 bytes
2018-02-22 04:07:40,972 - main.py[DEBUG]: [net] init will now be targeting instance id: iid-raspberrypi-nocloud. new=False
2018-02-22 04:07:40,974 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2018-02-22 04:07:40,975 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg
2018-02-22 04:07:40,976 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:41,154 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/datasource.cfg (quiet=False)
2018-02-22 04:07:41,155 - util.py[DEBUG]: Read 45 bytes from /etc/cloud/cloud.cfg.d/datasource.cfg
2018-02-22 04:07:41,155 - util.py[DEBUG]: Attempting to load yaml from string of length 45 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:41,165 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2018-02-22 04:07:41,166 - util.py[DEBUG]: Read 197 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2018-02-22 04:07:41,166 - util.py[DEBUG]: Attempting to load yaml from string of length 197 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:41,190 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2018-02-22 04:07:41,191 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2018-02-22 04:07:41,192 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:41,262 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False)
2018-02-22 04:07:41,264 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg
2018-02-22 04:07:41,264 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:41,283 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:41,285 - util.py[DEBUG]: load_yaml given empty string, returning default
2018-02-22 04:07:41,295 - util.py[DEBUG]: Reading from /sys/class/net/eth0/carrier (quiet=False)
2018-02-22 04:07:41,296 - util.py[DEBUG]: Reading from /sys/class/net/eth0/dormant (quiet=False)
2018-02-22 04:07:41,297 - util.py[DEBUG]: Reading from /sys/class/net/eth0/operstate (quiet=False)
2018-02-22 04:07:41,298 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/eth0/operstate
2018-02-22 04:07:41,299 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/carrier (quiet=False)
2018-02-22 04:07:41,300 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/dormant (quiet=False)
2018-02-22 04:07:41,301 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/operstate (quiet=False)
2018-02-22 04:07:41,302 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/wlan0/operstate
2018-02-22 04:07:41,302 - util.py[DEBUG]: Reading from /sys/class/net/eth0/address (quiet=False)
2018-02-22 04:07:41,303 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/eth0/address
2018-02-22 04:07:41,304 - stages.py[DEBUG]: applying net config names for {'config': [{'type': 'physical', 'name': 'eth0', 'mac_address': 'b8:27:eb:55:b7:56', 'subnets': [{'type': 'dhcp'}]}], 'version': 1}
2018-02-22 04:07:41,310 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'>
2018-02-22 04:07:41,314 - util.py[DEBUG]: Reading from /sys/class/net/eth0/operstate (quiet=False)
2018-02-22 04:07:41,315 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/eth0/operstate
2018-02-22 04:07:41,316 - util.py[DEBUG]: Reading from /sys/class/net/eth0/address (quiet=False)
2018-02-22 04:07:41,317 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/eth0/address
2018-02-22 04:07:41,317 - util.py[DEBUG]: Reading from /sys/class/net/lo/operstate (quiet=False)
2018-02-22 04:07:41,318 - util.py[DEBUG]: Read 8 bytes from /sys/class/net/lo/operstate
2018-02-22 04:07:41,319 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False)
2018-02-22 04:07:41,320 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address
2018-02-22 04:07:41,320 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/operstate (quiet=False)
2018-02-22 04:07:41,321 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/wlan0/operstate
2018-02-22 04:07:41,322 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/address (quiet=False)
2018-02-22 04:07:41,323 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/wlan0/address
2018-02-22 04:07:41,325 - util.py[DEBUG]: Running command ['ip', '-6', 'addr', 'show', 'permanent', 'scope', 'global'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:41,340 - util.py[DEBUG]: Running command ['ip', '-4', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:41,355 - __init__.py[DEBUG]: no work necessary for renaming of [['b8:27:eb:55:b7:56', 'eth0']]
2018-02-22 04:07:41,359 - stages.py[DEBUG]: not a new instance. network config is not applied.
2018-02-22 04:07:41,360 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/user-data.txt - wb: [384] 60 bytes
2018-02-22 04:07:41,369 - util.py[DEBUG]: Attempting to load yaml from string of length 60 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:41,401 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/user-data.txt.i - wb: [384] 338 bytes
2018-02-22 04:07:41,407 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/vendor-data.txt - wb: [384] 0 bytes
2018-02-22 04:07:41,422 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/vendor-data.txt.i - wb: [384] 281 bytes
2018-02-22 04:07:41,433 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/consume_data - wb: [420] 24 bytes
2018-02-22 04:07:41,438 - helpers.py[DEBUG]: Running consume_data using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/consume_data'>)
2018-02-22 04:07:41,440 - handlers.py[DEBUG]: start: init-network/consume-user-data: reading and applying user-data
2018-02-22 04:07:41,444 - stages.py[DEBUG]: Added default handler for {'text/cloud-config', 'text/cloud-config-jsonp'} from CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']]
2018-02-22 04:07:41,445 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript'} from ShellScriptPartHandler: [['text/x-shellscript']]
2018-02-22 04:07:41,446 - stages.py[DEBUG]: Added default handler for {'text/cloud-boothook'} from BootHookPartHandler: [['text/cloud-boothook']]
2018-02-22 04:07:41,446 - stages.py[DEBUG]: Added default handler for {'text/upstart-job'} from UpstartJobPartHandler: [['text/upstart-job']]
2018-02-22 04:07:41,450 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__begin__, None, 3) with frequency once-per-instance
2018-02-22 04:07:41,451 - __init__.py[DEBUG]: Calling handler UpstartJobPartHandler: [['text/upstart-job']] (__begin__, None, 2) with frequency once-per-instance
2018-02-22 04:07:41,452 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__begin__, None, 2) with frequency once-per-instance
2018-02-22 04:07:41,453 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__begin__, None, 2) with frequency once-per-instance
2018-02-22 04:07:41,454 - __init__.py[DEBUG]: {'Content-Type': 'text/cloud-config', 'MIME-Version': '1.0', 'Content-Disposition': 'attachment; filename="part-001"'}
2018-02-22 04:07:41,455 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (text/cloud-config, part-001, 3) with frequency once-per-instance
2018-02-22 04:07:41,456 - util.py[DEBUG]: Attempting to load yaml from string of length 60 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:41,466 - cloud_config.py[DEBUG]: Merging by applying [('dict', ['replace']), ('list', []), ('str', [])]
2018-02-22 04:07:41,467 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__end__, None, 3) with frequency once-per-instance
2018-02-22 04:07:41,474 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/cloud-config.txt - wb: [384] 96 bytes
2018-02-22 04:07:41,482 - __init__.py[DEBUG]: Calling handler UpstartJobPartHandler: [['text/upstart-job']] (__end__, None, 2) with frequency once-per-instance
2018-02-22 04:07:41,483 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__end__, None, 2) with frequency once-per-instance
2018-02-22 04:07:41,484 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__end__, None, 2) with frequency once-per-instance
2018-02-22 04:07:41,485 - handlers.py[DEBUG]: finish: init-network/consume-user-data: SUCCESS: reading and applying user-data
2018-02-22 04:07:41,486 - handlers.py[DEBUG]: start: init-network/consume-vendor-data: reading and applying vendor-data
2018-02-22 04:07:41,487 - stages.py[DEBUG]: no vendordata from datasource
2018-02-22 04:07:41,488 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data: SUCCESS: reading and applying vendor-data
2018-02-22 04:07:41,490 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2018-02-22 04:07:41,490 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg
2018-02-22 04:07:41,491 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:41,670 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/datasource.cfg (quiet=False)
2018-02-22 04:07:41,671 - util.py[DEBUG]: Read 45 bytes from /etc/cloud/cloud.cfg.d/datasource.cfg
2018-02-22 04:07:41,672 - util.py[DEBUG]: Attempting to load yaml from string of length 45 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:41,681 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2018-02-22 04:07:41,682 - util.py[DEBUG]: Read 197 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2018-02-22 04:07:41,683 - util.py[DEBUG]: Attempting to load yaml from string of length 197 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:41,706 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2018-02-22 04:07:41,707 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2018-02-22 04:07:41,708 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:41,779 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False)
2018-02-22 04:07:41,780 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg
2018-02-22 04:07:41,781 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:41,800 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:41,801 - util.py[DEBUG]: load_yaml given empty string, returning default
2018-02-22 04:07:41,804 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2018-02-22 04:07:41,805 - util.py[DEBUG]: Read 96 bytes from /var/lib/cloud/instance/cloud-config.txt
2018-02-22 04:07:41,806 - util.py[DEBUG]: Attempting to load yaml from string of length 96 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:41,829 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2018-02-22 04:07:41,830 - util.py[DEBUG]: Read 96 bytes from /var/lib/cloud/instance/cloud-config.txt
2018-02-22 04:07:41,830 - util.py[DEBUG]: Attempting to load yaml from string of length 96 with allowed root types (<class 'dict'>,)
2018-02-22 04:07:41,867 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [256] 4555 bytes
2018-02-22 04:07:42,001 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'>
2018-02-22 04:07:42,007 - stages.py[DEBUG]: Running module migrator (<module 'cloudinit.config.cc_migrator' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_migrator.py'>) with frequency always
2018-02-22 04:07:42,011 - handlers.py[DEBUG]: start: init-network/config-migrator: running config-migrator with frequency always
2018-02-22 04:07:42,012 - helpers.py[DEBUG]: Running config-migrator using lock (<cloudinit.helpers.DummyLock object at 0x75bf93b0>)
2018-02-22 04:07:42,014 - cc_migrator.py[DEBUG]: Migrated 0 semaphore files to there canonicalized names
2018-02-22 04:07:42,018 - handlers.py[DEBUG]: finish: init-network/config-migrator: SUCCESS: config-migrator ran successfully
2018-02-22 04:07:42,019 - stages.py[DEBUG]: Running module seed_random (<module 'cloudinit.config.cc_seed_random' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_seed_random.py'>) with frequency once-per-instance
2018-02-22 04:07:42,022 - handlers.py[DEBUG]: start: init-network/config-seed_random: running config-seed_random with frequency once-per-instance
2018-02-22 04:07:42,024 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_seed_random - wb: [420] 24 bytes
2018-02-22 04:07:42,030 - helpers.py[DEBUG]: Running config-seed_random using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_seed_random'>)
2018-02-22 04:07:42,031 - cc_seed_random.py[DEBUG]: no command provided
2018-02-22 04:07:42,033 - handlers.py[DEBUG]: finish: init-network/config-seed_random: SUCCESS: config-seed_random ran successfully
2018-02-22 04:07:42,033 - stages.py[DEBUG]: Running module bootcmd (<module 'cloudinit.config.cc_bootcmd' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_bootcmd.py'>) with frequency always
2018-02-22 04:07:42,036 - handlers.py[DEBUG]: start: init-network/config-bootcmd: running config-bootcmd with frequency always
2018-02-22 04:07:42,037 - helpers.py[DEBUG]: Running config-bootcmd using lock (<cloudinit.helpers.DummyLock object at 0x75bf9030>)
2018-02-22 04:07:42,037 - cc_bootcmd.py[DEBUG]: Skipping module named bootcmd, no 'bootcmd' key in configuration
2018-02-22 04:07:42,039 - handlers.py[DEBUG]: finish: init-network/config-bootcmd: SUCCESS: config-bootcmd ran successfully
2018-02-22 04:07:42,039 - stages.py[DEBUG]: Running module write-files (<module 'cloudinit.config.cc_write_files' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_write_files.py'>) with frequency once-per-instance
2018-02-22 04:07:42,042 - handlers.py[DEBUG]: start: init-network/config-write-files: running config-write-files with frequency once-per-instance
2018-02-22 04:07:42,044 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_write_files - wb: [420] 24 bytes
2018-02-22 04:07:42,050 - helpers.py[DEBUG]: Running config-write-files using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_write_files'>)
2018-02-22 04:07:42,051 - cc_write_files.py[DEBUG]: Skipping module named write-files, no/empty 'write_files' key in configuration
2018-02-22 04:07:42,052 - handlers.py[DEBUG]: finish: init-network/config-write-files: SUCCESS: config-write-files ran successfully
2018-02-22 04:07:42,053 - stages.py[DEBUG]: Running module growpart (<module 'cloudinit.config.cc_growpart' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_growpart.py'>) with frequency always
2018-02-22 04:07:42,056 - handlers.py[DEBUG]: start: init-network/config-growpart: running config-growpart with frequency always
2018-02-22 04:07:42,057 - helpers.py[DEBUG]: Running config-growpart using lock (<cloudinit.helpers.DummyLock object at 0x75bf9c90>)
2018-02-22 04:07:42,057 - cc_growpart.py[DEBUG]: No 'growpart' entry in cfg.  Using default: {'devices': ['/'], 'mode': 'auto', 'ignore_growroot_disabled': False}
2018-02-22 04:07:42,058 - util.py[DEBUG]: Running command ['growpart', '--help'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:42,070 - cc_growpart.py[DEBUG]: growpart unable to find resizer for 'auto': No resizers available
2018-02-22 04:07:42,072 - handlers.py[DEBUG]: finish: init-network/config-growpart: SUCCESS: config-growpart ran successfully
2018-02-22 04:07:42,073 - stages.py[DEBUG]: Running module resizefs (<module 'cloudinit.config.cc_resizefs' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_resizefs.py'>) with frequency always
2018-02-22 04:07:42,076 - handlers.py[DEBUG]: start: init-network/config-resizefs: running config-resizefs with frequency always
2018-02-22 04:07:42,077 - helpers.py[DEBUG]: Running config-resizefs using lock (<cloudinit.helpers.DummyLock object at 0x75c4e510>)
2018-02-22 04:07:42,078 - util.py[DEBUG]: Reading from /proc/358/mountinfo (quiet=False)
2018-02-22 04:07:42,079 - util.py[DEBUG]: Read 2086 bytes from /proc/358/mountinfo
2018-02-22 04:07:42,081 - cc_resizefs.py[DEBUG]: resize_info: dev=/dev/root mnt_point=/ path=/
2018-02-22 04:07:42,081 - util.py[DEBUG]: Running command ['systemd-detect-virt', '--quiet', '--container'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:42,106 - util.py[DEBUG]: Running command ['running-in-container'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:42,117 - util.py[DEBUG]: Running command ['lxc-is-container'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:42,129 - util.py[DEBUG]: Reading from /proc/1/environ (quiet=False)
2018-02-22 04:07:42,130 - util.py[DEBUG]: Read 18 bytes from /proc/1/environ
2018-02-22 04:07:42,131 - util.py[DEBUG]: Reading from /proc/self/status (quiet=False)
2018-02-22 04:07:42,132 - util.py[DEBUG]: Read 925 bytes from /proc/self/status
2018-02-22 04:07:42,133 - cc_resizefs.py[DEBUG]: Converted /dev/root to '/dev/PARTUUID=a00bdab5-02' per kernel cmdline
2018-02-22 04:07:42,134 - cc_resizefs.py[WARNING]: Device '/dev/PARTUUID=a00bdab5-02' did not exist. cannot resize: dev=/dev/root mnt_point=/ path=/
2018-02-22 04:07:42,136 - handlers.py[DEBUG]: finish: init-network/config-resizefs: SUCCESS: config-resizefs ran successfully
2018-02-22 04:07:42,137 - stages.py[DEBUG]: Running module disk_setup (<module 'cloudinit.config.cc_disk_setup' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_disk_setup.py'>) with frequency once-per-instance
2018-02-22 04:07:42,140 - handlers.py[DEBUG]: start: init-network/config-disk_setup: running config-disk_setup with frequency once-per-instance
2018-02-22 04:07:42,142 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_disk_setup - wb: [420] 24 bytes
2018-02-22 04:07:42,150 - helpers.py[DEBUG]: Running config-disk_setup using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_disk_setup'>)
2018-02-22 04:07:42,152 - handlers.py[DEBUG]: finish: init-network/config-disk_setup: SUCCESS: config-disk_setup ran successfully
2018-02-22 04:07:42,152 - stages.py[DEBUG]: Running module mounts (<module 'cloudinit.config.cc_mounts' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_mounts.py'>) with frequency once-per-instance
2018-02-22 04:07:42,156 - handlers.py[DEBUG]: start: init-network/config-mounts: running config-mounts with frequency once-per-instance
2018-02-22 04:07:42,158 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_mounts - wb: [420] 23 bytes
2018-02-22 04:07:42,165 - helpers.py[DEBUG]: Running config-mounts using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_mounts'>)
2018-02-22 04:07:42,166 - cc_mounts.py[DEBUG]: mounts configuration is []
2018-02-22 04:07:42,167 - cc_mounts.py[DEBUG]: Attempting to determine the real name of ephemeral0
2018-02-22 04:07:42,167 - cc_mounts.py[DEBUG]: Ignoring nonexistant default named mount ephemeral0
2018-02-22 04:07:42,168 - cc_mounts.py[DEBUG]: Attempting to determine the real name of swap
2018-02-22 04:07:42,168 - cc_mounts.py[DEBUG]: Ignoring nonexistant default named mount swap
2018-02-22 04:07:42,169 - cc_mounts.py[DEBUG]: no need to setup swap
2018-02-22 04:07:42,170 - cc_mounts.py[DEBUG]: No modifications to fstab needed.
2018-02-22 04:07:42,171 - handlers.py[DEBUG]: finish: init-network/config-mounts: SUCCESS: config-mounts ran successfully
2018-02-22 04:07:42,171 - stages.py[DEBUG]: Running module set_hostname (<module 'cloudinit.config.cc_set_hostname' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_set_hostname.py'>) with frequency once-per-instance
2018-02-22 04:07:42,175 - handlers.py[DEBUG]: start: init-network/config-set_hostname: running config-set_hostname with frequency once-per-instance
2018-02-22 04:07:42,176 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_set_hostname - wb: [420] 24 bytes
2018-02-22 04:07:42,183 - helpers.py[DEBUG]: Running config-set_hostname using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_set_hostname'>)
2018-02-22 04:07:42,184 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False)
2018-02-22 04:07:42,185 - util.py[DEBUG]: Read 131 bytes from /etc/hosts
2018-02-22 04:07:42,185 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False)
2018-02-22 04:07:42,186 - util.py[DEBUG]: Read 131 bytes from /etc/hosts
2018-02-22 04:07:42,187 - cc_set_hostname.py[DEBUG]: Setting the hostname to raspberrypi (raspberrypi)
2018-02-22 04:07:42,188 - util.py[DEBUG]: Reading from /etc/hostname (quiet=False)
2018-02-22 04:07:42,188 - util.py[DEBUG]: Read 12 bytes from /etc/hostname
2018-02-22 04:07:42,189 - util.py[DEBUG]: Writing to /etc/hostname - wb: [420] 12 bytes
2018-02-22 04:07:42,196 - __init__.py[DEBUG]: Non-persistently setting the system hostname to raspberrypi
2018-02-22 04:07:42,197 - util.py[DEBUG]: Running command ['hostname', 'raspberrypi'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:42,213 - handlers.py[DEBUG]: finish: init-network/config-set_hostname: SUCCESS: config-set_hostname ran successfully
2018-02-22 04:07:42,214 - stages.py[DEBUG]: Running module update_hostname (<module 'cloudinit.config.cc_update_hostname' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_update_hostname.py'>) with frequency always
2018-02-22 04:07:42,218 - handlers.py[DEBUG]: start: init-network/config-update_hostname: running config-update_hostname with frequency always
2018-02-22 04:07:42,219 - helpers.py[DEBUG]: Running config-update_hostname using lock (<cloudinit.helpers.DummyLock object at 0x75c53e70>)
2018-02-22 04:07:42,219 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False)
2018-02-22 04:07:42,220 - util.py[DEBUG]: Read 131 bytes from /etc/hosts
2018-02-22 04:07:42,221 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False)
2018-02-22 04:07:42,222 - util.py[DEBUG]: Read 131 bytes from /etc/hosts
2018-02-22 04:07:42,223 - cc_update_hostname.py[DEBUG]: Updating hostname to raspberrypi (raspberrypi)
2018-02-22 04:07:42,223 - util.py[DEBUG]: Reading from /etc/hostname (quiet=False)
2018-02-22 04:07:42,224 - util.py[DEBUG]: Read 12 bytes from /etc/hostname
2018-02-22 04:07:42,225 - __init__.py[DEBUG]: Attempting to update hostname to raspberrypi in 1 files
2018-02-22 04:07:42,226 - util.py[DEBUG]: Reading from /var/lib/cloud/data/previous-hostname (quiet=False)
2018-02-22 04:07:42,227 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-hostname - wb: [420] 12 bytes
2018-02-22 04:07:42,234 - handlers.py[DEBUG]: finish: init-network/config-update_hostname: SUCCESS: config-update_hostname ran successfully
2018-02-22 04:07:42,235 - stages.py[DEBUG]: Running module update_etc_hosts (<module 'cloudinit.config.cc_update_etc_hosts' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_update_etc_hosts.py'>) with frequency always
2018-02-22 04:07:42,238 - handlers.py[DEBUG]: start: init-network/config-update_etc_hosts: running config-update_etc_hosts with frequency always
2018-02-22 04:07:42,239 - helpers.py[DEBUG]: Running config-update_etc_hosts using lock (<cloudinit.helpers.DummyLock object at 0x75c53210>)
2018-02-22 04:07:42,239 - cc_update_etc_hosts.py[DEBUG]: Configuration option 'manage_etc_hosts' is not set, not managing /etc/hosts in module update_etc_hosts
2018-02-22 04:07:42,240 - handlers.py[DEBUG]: finish: init-network/config-update_etc_hosts: SUCCESS: config-update_etc_hosts ran successfully
2018-02-22 04:07:42,241 - stages.py[DEBUG]: Running module ca-certs (<module 'cloudinit.config.cc_ca_certs' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_ca_certs.py'>) with frequency once-per-instance
2018-02-22 04:07:42,244 - handlers.py[DEBUG]: start: init-network/config-ca-certs: running config-ca-certs with frequency once-per-instance
2018-02-22 04:07:42,246 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_ca_certs - wb: [420] 23 bytes
2018-02-22 04:07:42,252 - helpers.py[DEBUG]: Running config-ca-certs using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_ca_certs'>)
2018-02-22 04:07:42,253 - cc_ca_certs.py[DEBUG]: Skipping module named ca-certs, no 'ca-certs' key in configuration
2018-02-22 04:07:42,254 - handlers.py[DEBUG]: finish: init-network/config-ca-certs: SUCCESS: config-ca-certs ran successfully
2018-02-22 04:07:42,255 - stages.py[DEBUG]: Running module rsyslog (<module 'cloudinit.config.cc_rsyslog' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_rsyslog.py'>) with frequency once-per-instance
2018-02-22 04:07:42,258 - handlers.py[DEBUG]: start: init-network/config-rsyslog: running config-rsyslog with frequency once-per-instance
2018-02-22 04:07:42,259 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_rsyslog - wb: [420] 24 bytes
2018-02-22 04:07:42,266 - helpers.py[DEBUG]: Running config-rsyslog using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_rsyslog'>)
2018-02-22 04:07:42,267 - cc_rsyslog.py[DEBUG]: Skipping module named rsyslog, no 'rsyslog' key in configuration
2018-02-22 04:07:42,268 - handlers.py[DEBUG]: finish: init-network/config-rsyslog: SUCCESS: config-rsyslog ran successfully
2018-02-22 04:07:42,268 - stages.py[DEBUG]: Running module users-groups (<module 'cloudinit.config.cc_users_groups' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_users_groups.py'>) with frequency once-per-instance
2018-02-22 04:07:42,272 - handlers.py[DEBUG]: start: init-network/config-users-groups: running config-users-groups with frequency once-per-instance
2018-02-22 04:07:42,273 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_users_groups - wb: [420] 24 bytes
2018-02-22 04:07:42,280 - helpers.py[DEBUG]: Running config-users-groups using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_users_groups'>)
2018-02-22 04:07:42,284 - util.py[DEBUG]: Reading from /etc/system-image/channel.ini (quiet=True)
2018-02-22 04:07:42,284 - util.py[DEBUG]: Read 0 bytes from /etc/system-image/channel.ini
2018-02-22 04:07:42,287 - __init__.py[DEBUG]: Adding user debian
2018-02-22 04:07:42,287 - util.py[DEBUG]: Running hidden command to protect sensitive input/output logstring: ['useradd', 'debian', '--comment', 'Debian', '--groups', 'adm,audio,cdrom,dialout,dip,floppy,netdev,plugdev,sudo,video', '--shell', '/bin/bash', '-m']
2018-02-22 04:07:42,600 - util.py[DEBUG]: Running command ['passwd', '-l', 'debian'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:42,682 - util.py[DEBUG]: Reading from /etc/sudoers (quiet=False)
2018-02-22 04:07:42,684 - util.py[DEBUG]: Read 669 bytes from /etc/sudoers
2018-02-22 04:07:42,692 - util.py[DEBUG]: Writing to /etc/sudoers.d/90-cloud-init-users - wb: [288] 123 bytes
2018-02-22 04:07:42,700 - handlers.py[DEBUG]: finish: init-network/config-users-groups: SUCCESS: config-users-groups ran successfully
2018-02-22 04:07:42,701 - stages.py[DEBUG]: Running module ssh (<module 'cloudinit.config.cc_ssh' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_ssh.py'>) with frequency once-per-instance
2018-02-22 04:07:42,704 - handlers.py[DEBUG]: start: init-network/config-ssh: running config-ssh with frequency once-per-instance
2018-02-22 04:07:42,706 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_ssh - wb: [420] 24 bytes
2018-02-22 04:07:42,712 - helpers.py[DEBUG]: Running config-ssh using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_ssh'>)
2018-02-22 04:07:42,717 - util.py[DEBUG]: Attempting to remove /etc/ssh/ssh_host_ecdsa_key.pub
2018-02-22 04:07:42,718 - util.py[DEBUG]: Attempting to remove /etc/ssh/ssh_host_rsa_key
2018-02-22 04:07:42,719 - util.py[DEBUG]: Attempting to remove /etc/ssh/ssh_host_ecdsa_key
2018-02-22 04:07:42,720 - util.py[DEBUG]: Attempting to remove /etc/ssh/ssh_host_dsa_key.pub
2018-02-22 04:07:42,720 - util.py[DEBUG]: Attempting to remove /etc/ssh/ssh_host_ed25519_key.pub
2018-02-22 04:07:42,721 - util.py[DEBUG]: Attempting to remove /etc/ssh/ssh_host_rsa_key.pub
2018-02-22 04:07:42,722 - util.py[DEBUG]: Attempting to remove /etc/ssh/ssh_host_ed25519_key
2018-02-22 04:07:42,723 - util.py[DEBUG]: Attempting to remove /etc/ssh/ssh_host_dsa_key
2018-02-22 04:07:42,727 - util.py[DEBUG]: Running command ['ssh-keygen', '-t', 'rsa', '-N', '', '-f', '/etc/ssh/ssh_host_rsa_key'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:44,690 - util.py[DEBUG]: Running command ['ssh-keygen', '-t', 'dsa', '-N', '', '-f', '/etc/ssh/ssh_host_dsa_key'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:46,994 - util.py[DEBUG]: Running command ['ssh-keygen', '-t', 'ecdsa', '-N', '', '-f', '/etc/ssh/ssh_host_ecdsa_key'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:47,031 - util.py[DEBUG]: Running command ['ssh-keygen', '-t', 'ed25519', '-N', '', '-f', '/etc/ssh/ssh_host_ed25519_key'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:07:47,082 - util.py[DEBUG]: Changing the ownership of /home/debian/.ssh to 1001:1001
2018-02-22 04:07:47,087 - util.py[DEBUG]: Reading from /etc/ssh/sshd_config (quiet=False)
2018-02-22 04:07:47,089 - util.py[DEBUG]: Read 3298 bytes from /etc/ssh/sshd_config
2018-02-22 04:07:47,099 - util.py[DEBUG]: Writing to /home/debian/.ssh/authorized_keys - wb: [384] 0 bytes
2018-02-22 04:07:47,105 - util.py[DEBUG]: Changing the ownership of /home/debian/.ssh/authorized_keys to 1001:1001
2018-02-22 04:07:47,112 - util.py[DEBUG]: Changing the ownership of /root/.ssh to 0:0
2018-02-22 04:07:47,116 - util.py[DEBUG]: Reading from /etc/ssh/sshd_config (quiet=False)
2018-02-22 04:07:47,117 - util.py[DEBUG]: Read 3298 bytes from /etc/ssh/sshd_config
2018-02-22 04:07:47,127 - util.py[DEBUG]: Writing to /root/.ssh/authorized_keys - wb: [384] 0 bytes
2018-02-22 04:07:47,133 - util.py[DEBUG]: Changing the ownership of /root/.ssh/authorized_keys to 0:0
2018-02-22 04:07:47,135 - handlers.py[DEBUG]: finish: init-network/config-ssh: SUCCESS: config-ssh ran successfully
2018-02-22 04:07:47,135 - main.py[DEBUG]: Ran 15 modules with 0 failures
2018-02-22 04:07:47,140 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2018-02-22 04:07:47,141 - util.py[DEBUG]: Read 12 bytes from /proc/uptime
2018-02-22 04:07:47,142 - util.py[DEBUG]: cloud-init mode 'init' took 7.618 seconds (7.62)
2018-02-22 04:07:47,143 - handlers.py[DEBUG]: finish: init-network: SUCCESS: searching for network datasources
2018-02-22 04:08:05,225 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'modules:config' at Thu, 22 Feb 2018 04:08:04 +0000. Up 35.80 seconds.
2018-02-22 04:08:05,283 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'>
2018-02-22 04:08:05,289 - stages.py[DEBUG]: Running module emit_upstart (<module 'cloudinit.config.cc_emit_upstart' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_emit_upstart.py'>) with frequency always
2018-02-22 04:08:05,291 - handlers.py[DEBUG]: start: modules-config/config-emit_upstart: running config-emit_upstart with frequency always
2018-02-22 04:08:05,291 - helpers.py[DEBUG]: Running config-emit_upstart using lock (<cloudinit.helpers.DummyLock object at 0x75c4c590>)
2018-02-22 04:08:05,292 - cc_emit_upstart.py[DEBUG]: no /sbin/initctl located
2018-02-22 04:08:05,292 - cc_emit_upstart.py[DEBUG]: not upstart system, 'emit_upstart' disabled
2018-02-22 04:08:05,293 - handlers.py[DEBUG]: finish: modules-config/config-emit_upstart: SUCCESS: config-emit_upstart ran successfully
2018-02-22 04:08:05,294 - stages.py[DEBUG]: Running module ssh-import-id (<module 'cloudinit.config.cc_ssh_import_id' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_ssh_import_id.py'>) with frequency once-per-instance
2018-02-22 04:08:05,296 - handlers.py[DEBUG]: start: modules-config/config-ssh-import-id: running config-ssh-import-id with frequency once-per-instance
2018-02-22 04:08:05,298 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_ssh_import_id - wb: [420] 24 bytes
2018-02-22 04:08:05,301 - helpers.py[DEBUG]: Running config-ssh-import-id using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_ssh_import_id'>)
2018-02-22 04:08:05,304 - handlers.py[DEBUG]: finish: modules-config/config-ssh-import-id: SUCCESS: config-ssh-import-id ran successfully
2018-02-22 04:08:05,304 - stages.py[DEBUG]: Running module locale (<module 'cloudinit.config.cc_locale' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_locale.py'>) with frequency once-per-instance
2018-02-22 04:08:05,306 - handlers.py[DEBUG]: start: modules-config/config-locale: running config-locale with frequency once-per-instance
2018-02-22 04:08:05,307 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_locale - wb: [420] 23 bytes
2018-02-22 04:08:05,310 - helpers.py[DEBUG]: Running config-locale using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_locale'>)
2018-02-22 04:08:05,311 - cc_locale.py[DEBUG]: Setting locale to en_US.UTF-8
2018-02-22 04:08:05,312 - util.py[DEBUG]: Running command ['locale-gen', 'en_US.UTF-8'] with allowed return codes [0] (shell=False, capture=False)
2018-02-22 04:08:09,257 - util.py[DEBUG]: Running command ['update-locale', 'en_US.UTF-8'] with allowed return codes [0] (shell=False, capture=False)
2018-02-22 04:08:09,479 - util.py[DEBUG]: Writing to /etc/default/locale - wb: [420] 87 bytes
2018-02-22 04:08:09,483 - handlers.py[DEBUG]: finish: modules-config/config-locale: SUCCESS: config-locale ran successfully
2018-02-22 04:08:09,484 - stages.py[DEBUG]: Running module set-passwords (<module 'cloudinit.config.cc_set_passwords' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_set_passwords.py'>) with frequency once-per-instance
2018-02-22 04:08:09,485 - handlers.py[DEBUG]: start: modules-config/config-set-passwords: running config-set-passwords with frequency once-per-instance
2018-02-22 04:08:09,486 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_set_passwords - wb: [420] 24 bytes
2018-02-22 04:08:09,489 - helpers.py[DEBUG]: Running config-set-passwords using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_set_passwords'>)
2018-02-22 04:08:09,491 - cc_set_passwords.py[DEBUG]: Changing password for ['debian']:
2018-02-22 04:08:09,493 - util.py[DEBUG]: Running command ['chpasswd'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:08:09,615 - util.py[DEBUG]: Running command ['passwd', '--expire', 'debian'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:08:09,660 - cc_set_passwords.py[DEBUG]: Expired passwords for: ['debian'] users
2018-02-22 04:08:09,662 - handlers.py[DEBUG]: finish: modules-config/config-set-passwords: SUCCESS: config-set-passwords ran successfully
2018-02-22 04:08:09,662 - stages.py[DEBUG]: Running module grub-dpkg (<module 'cloudinit.config.cc_grub_dpkg' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_grub_dpkg.py'>) with frequency once-per-instance
2018-02-22 04:08:09,664 - handlers.py[DEBUG]: start: modules-config/config-grub-dpkg: running config-grub-dpkg with frequency once-per-instance
2018-02-22 04:08:09,665 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_grub_dpkg - wb: [420] 24 bytes
2018-02-22 04:08:09,668 - helpers.py[DEBUG]: Running config-grub-dpkg using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_grub_dpkg'>)
2018-02-22 04:08:09,669 - cc_grub_dpkg.py[DEBUG]: Setting grub debconf-set-selections with '/dev/sda','false'
2018-02-22 04:08:09,669 - util.py[DEBUG]: Running command ['debconf-set-selections'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:08:11,642 - handlers.py[DEBUG]: finish: modules-config/config-grub-dpkg: SUCCESS: config-grub-dpkg ran successfully
2018-02-22 04:08:11,643 - stages.py[DEBUG]: Running module apt-pipelining (<module 'cloudinit.config.cc_apt_pipelining' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_apt_pipelining.py'>) with frequency once-per-instance
2018-02-22 04:08:11,646 - handlers.py[DEBUG]: start: modules-config/config-apt-pipelining: running config-apt-pipelining with frequency once-per-instance
2018-02-22 04:08:11,648 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_apt_pipelining - wb: [420] 24 bytes
2018-02-22 04:08:11,654 - helpers.py[DEBUG]: Running config-apt-pipelining using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_apt_pipelining'>)
2018-02-22 04:08:11,655 - util.py[DEBUG]: Writing to /etc/apt/apt.conf.d/90cloud-init-pipelining - wb: [420] 80 bytes
2018-02-22 04:08:11,661 - cc_apt_pipelining.py[DEBUG]: Wrote /etc/apt/apt.conf.d/90cloud-init-pipelining with apt pipeline depth setting 0
2018-02-22 04:08:11,662 - handlers.py[DEBUG]: finish: modules-config/config-apt-pipelining: SUCCESS: config-apt-pipelining ran successfully
2018-02-22 04:08:11,663 - stages.py[DEBUG]: Running module apt-configure (<module 'cloudinit.config.cc_apt_configure' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_apt_configure.py'>) with frequency once-per-instance
2018-02-22 04:08:11,666 - handlers.py[DEBUG]: start: modules-config/config-apt-configure: running config-apt-configure with frequency once-per-instance
2018-02-22 04:08:11,668 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_apt_configure - wb: [420] 24 bytes
2018-02-22 04:08:11,673 - helpers.py[DEBUG]: Running config-apt-configure using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_apt_configure'>)
2018-02-22 04:08:11,674 - cc_apt_configure.py[DEBUG]: handling apt (module apt-configure) with apt config '{}'
2018-02-22 04:08:11,675 - util.py[DEBUG]: Running command ['lsb_release', '--all'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:08:12,448 - util.py[DEBUG]: Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:08:12,458 - cc_apt_configure.py[DEBUG]: got primary mirror: None
2018-02-22 04:08:12,461 - cc_apt_configure.py[DEBUG]: got security mirror: None
2018-02-22 04:08:12,461 - util.py[DEBUG]: Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:08:12,471 - __init__.py[DEBUG]: filtered distro mirror info: {'security': 'http://security.debian.org/', 'primary': 'http://deb.debian.org/debian'}
2018-02-22 04:08:12,472 - cc_apt_configure.py[DEBUG]: Apt Mirror info: {'PRIMARY': 'http://deb.debian.org/debian', 'SECURITY': 'http://security.debian.org/', 'security': 'http://security.debian.org/', 'MIRROR': 'http://deb.debian.org/debian', 'primary': 'http://deb.debian.org/debian'}
2018-02-22 04:08:12,473 - cc_apt_configure.py[DEBUG]: debconf_selections was not set in config
2018-02-22 04:08:12,473 - cc_apt_configure.py[INFO]: No custom template provided, fall back to builtin
2018-02-22 04:08:12,475 - util.py[DEBUG]: Reading from /etc/cloud/templates/sources.list.debian.tmpl (quiet=False)
2018-02-22 04:08:12,476 - util.py[DEBUG]: Read 1435 bytes from /etc/cloud/templates/sources.list.debian.tmpl
2018-02-22 04:08:12,510 - util.py[DEBUG]: Writing to /etc/apt/sources.list - wb: [420] 1515 bytes
2018-02-22 04:08:12,514 - util.py[DEBUG]: Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:08:12,528 - handlers.py[DEBUG]: finish: modules-config/config-apt-configure: SUCCESS: config-apt-configure ran successfully
2018-02-22 04:08:12,528 - stages.py[DEBUG]: Running module ntp (<module 'cloudinit.config.cc_ntp' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_ntp.py'>) with frequency once-per-instance
2018-02-22 04:08:12,530 - handlers.py[DEBUG]: start: modules-config/config-ntp: running config-ntp with frequency once-per-instance
2018-02-22 04:08:12,531 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_ntp - wb: [420] 24 bytes
2018-02-22 04:08:12,534 - helpers.py[DEBUG]: Running config-ntp using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_ntp'>)
2018-02-22 04:08:12,534 - cc_ntp.py[DEBUG]: Skipping module named ntp,not present or disabled by cfg
2018-02-22 04:08:12,535 - handlers.py[DEBUG]: finish: modules-config/config-ntp: SUCCESS: config-ntp ran successfully
2018-02-22 04:08:12,535 - stages.py[DEBUG]: Running module timezone (<module 'cloudinit.config.cc_timezone' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_timezone.py'>) with frequency once-per-instance
2018-02-22 04:08:12,537 - handlers.py[DEBUG]: start: modules-config/config-timezone: running config-timezone with frequency once-per-instance
2018-02-22 04:08:12,538 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_timezone - wb: [420] 24 bytes
2018-02-22 04:08:12,541 - helpers.py[DEBUG]: Running config-timezone using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_timezone'>)
2018-02-22 04:08:12,541 - cc_timezone.py[DEBUG]: Skipping module named timezone, no 'timezone' specified
2018-02-22 04:08:12,542 - handlers.py[DEBUG]: finish: modules-config/config-timezone: SUCCESS: config-timezone ran successfully
2018-02-22 04:08:12,542 - stages.py[DEBUG]: Running module disable-ec2-metadata (<module 'cloudinit.config.cc_disable_ec2_metadata' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_disable_ec2_metadata.py'>) with frequency always
2018-02-22 04:08:12,544 - handlers.py[DEBUG]: start: modules-config/config-disable-ec2-metadata: running config-disable-ec2-metadata with frequency always
2018-02-22 04:08:12,544 - helpers.py[DEBUG]: Running config-disable-ec2-metadata using lock (<cloudinit.helpers.DummyLock object at 0x75c4c4b0>)
2018-02-22 04:08:12,545 - cc_disable_ec2_metadata.py[DEBUG]: Skipping module named disable-ec2-metadata, disabling the ec2 route not enabled
2018-02-22 04:08:12,545 - handlers.py[DEBUG]: finish: modules-config/config-disable-ec2-metadata: SUCCESS: config-disable-ec2-metadata ran successfully
2018-02-22 04:08:12,545 - stages.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
2018-02-22 04:08:12,547 - handlers.py[DEBUG]: start: modules-config/config-runcmd: running config-runcmd with frequency once-per-instance
2018-02-22 04:08:12,548 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_runcmd - wb: [420] 23 bytes
2018-02-22 04:08:12,551 - helpers.py[DEBUG]: Running config-runcmd using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_runcmd'>)
2018-02-22 04:08:12,551 - cc_runcmd.py[DEBUG]: Skipping module named runcmd, no 'runcmd' key in configuration
2018-02-22 04:08:12,552 - handlers.py[DEBUG]: finish: modules-config/config-runcmd: SUCCESS: config-runcmd ran successfully
2018-02-22 04:08:12,552 - stages.py[DEBUG]: Running module byobu (<module 'cloudinit.config.cc_byobu' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_byobu.py'>) with frequency once-per-instance
2018-02-22 04:08:12,554 - handlers.py[DEBUG]: start: modules-config/config-byobu: running config-byobu with frequency once-per-instance
2018-02-22 04:08:12,554 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_byobu - wb: [420] 23 bytes
2018-02-22 04:08:12,557 - helpers.py[DEBUG]: Running config-byobu using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_byobu'>)
2018-02-22 04:08:12,558 - cc_byobu.py[DEBUG]: Skipping module named byobu, no 'byobu' values found
2018-02-22 04:08:12,558 - handlers.py[DEBUG]: finish: modules-config/config-byobu: SUCCESS: config-byobu ran successfully
2018-02-22 04:08:12,559 - main.py[DEBUG]: Ran 12 modules with 0 failures
2018-02-22 04:08:12,562 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2018-02-22 04:08:12,562 - util.py[DEBUG]: Read 13 bytes from /proc/uptime
2018-02-22 04:08:12,563 - util.py[DEBUG]: cloud-init mode 'modules' took 7.793 seconds (7.80)
2018-02-22 04:08:12,563 - handlers.py[DEBUG]: finish: modules-config: SUCCESS: running modules for config
2018-02-22 04:08:15,817 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'modules:final' at Thu, 22 Feb 2018 04:08:15 +0000. Up 46.44 seconds.
2018-02-22 04:08:15,931 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'>
2018-02-22 04:08:15,936 - stages.py[DEBUG]: Running module package-update-upgrade-install (<module 'cloudinit.config.cc_package_update_upgrade_install' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_package_update_upgrade_install.py'>) with frequency once-per-instance
2018-02-22 04:08:15,938 - handlers.py[DEBUG]: start: modules-final/config-package-update-upgrade-install: running config-package-update-upgrade-install with frequency once-per-instance
2018-02-22 04:08:15,939 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_package_update_upgrade_install - wb: [420] 24 bytes
2018-02-22 04:08:15,942 - helpers.py[DEBUG]: Running config-package-update-upgrade-install using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_package_update_upgrade_install'>)
2018-02-22 04:08:15,943 - handlers.py[DEBUG]: finish: modules-final/config-package-update-upgrade-install: SUCCESS: config-package-update-upgrade-install ran successfully
2018-02-22 04:08:15,944 - stages.py[DEBUG]: Running module fan (<module 'cloudinit.config.cc_fan' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_fan.py'>) with frequency once-per-instance
2018-02-22 04:08:15,945 - handlers.py[DEBUG]: start: modules-final/config-fan: running config-fan with frequency once-per-instance
2018-02-22 04:08:15,946 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_fan - wb: [420] 24 bytes
2018-02-22 04:08:15,949 - helpers.py[DEBUG]: Running config-fan using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_fan'>)
2018-02-22 04:08:15,950 - cc_fan.py[DEBUG]: fan: no 'fan' config entry. disabling
2018-02-22 04:08:15,951 - handlers.py[DEBUG]: finish: modules-final/config-fan: SUCCESS: config-fan ran successfully
2018-02-22 04:08:15,951 - stages.py[DEBUG]: Running module puppet (<module 'cloudinit.config.cc_puppet' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_puppet.py'>) with frequency once-per-instance
2018-02-22 04:08:15,953 - handlers.py[DEBUG]: start: modules-final/config-puppet: running config-puppet with frequency once-per-instance
2018-02-22 04:08:15,953 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_puppet - wb: [420] 24 bytes
2018-02-22 04:08:15,956 - helpers.py[DEBUG]: Running config-puppet using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_puppet'>)
2018-02-22 04:08:15,957 - cc_puppet.py[DEBUG]: Skipping module named puppet, no 'puppet' configuration found
2018-02-22 04:08:15,957 - handlers.py[DEBUG]: finish: modules-final/config-puppet: SUCCESS: config-puppet ran successfully
2018-02-22 04:08:15,958 - stages.py[DEBUG]: Running module chef (<module 'cloudinit.config.cc_chef' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_chef.py'>) with frequency once-per-instance
2018-02-22 04:08:15,959 - handlers.py[DEBUG]: start: modules-final/config-chef: running config-chef with frequency once-per-instance
2018-02-22 04:08:15,960 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_chef - wb: [420] 23 bytes
2018-02-22 04:08:15,963 - helpers.py[DEBUG]: Running config-chef using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_chef'>)
2018-02-22 04:08:15,964 - cc_chef.py[DEBUG]: Skipping module named chef, no 'chef' key in configuration
2018-02-22 04:08:15,964 - handlers.py[DEBUG]: finish: modules-final/config-chef: SUCCESS: config-chef ran successfully
2018-02-22 04:08:15,964 - stages.py[DEBUG]: Running module salt-minion (<module 'cloudinit.config.cc_salt_minion' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_salt_minion.py'>) with frequency once-per-instance
2018-02-22 04:08:15,966 - handlers.py[DEBUG]: start: modules-final/config-salt-minion: running config-salt-minion with frequency once-per-instance
2018-02-22 04:08:15,967 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_salt_minion - wb: [420] 24 bytes
2018-02-22 04:08:15,970 - helpers.py[DEBUG]: Running config-salt-minion using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_salt_minion'>)
2018-02-22 04:08:15,970 - cc_salt_minion.py[DEBUG]: Skipping module named salt-minion, no 'salt_minion' key in configuration
2018-02-22 04:08:15,971 - handlers.py[DEBUG]: finish: modules-final/config-salt-minion: SUCCESS: config-salt-minion ran successfully
2018-02-22 04:08:15,971 - stages.py[DEBUG]: Running module mcollective (<module 'cloudinit.config.cc_mcollective' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_mcollective.py'>) with frequency once-per-instance
2018-02-22 04:08:15,973 - handlers.py[DEBUG]: start: modules-final/config-mcollective: running config-mcollective with frequency once-per-instance
2018-02-22 04:08:15,974 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_mcollective - wb: [420] 24 bytes
2018-02-22 04:08:15,977 - helpers.py[DEBUG]: Running config-mcollective using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_mcollective'>)
2018-02-22 04:08:15,977 - cc_mcollective.py[DEBUG]: Skipping module named mcollective, no 'mcollective' key in configuration
2018-02-22 04:08:15,978 - handlers.py[DEBUG]: finish: modules-final/config-mcollective: SUCCESS: config-mcollective ran successfully
2018-02-22 04:08:15,978 - stages.py[DEBUG]: Running module rightscale_userdata (<module 'cloudinit.config.cc_rightscale_userdata' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_rightscale_userdata.py'>) with frequency once-per-instance
2018-02-22 04:08:15,979 - handlers.py[DEBUG]: start: modules-final/config-rightscale_userdata: running config-rightscale_userdata with frequency once-per-instance
2018-02-22 04:08:15,980 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_rightscale_userdata - wb: [420] 24 bytes
2018-02-22 04:08:15,983 - helpers.py[DEBUG]: Running config-rightscale_userdata using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_rightscale_userdata'>)
2018-02-22 04:08:15,984 - cc_rightscale_userdata.py[DEBUG]: Failed to get raw userdata in module rightscale_userdata
2018-02-22 04:08:15,984 - handlers.py[DEBUG]: finish: modules-final/config-rightscale_userdata: SUCCESS: config-rightscale_userdata ran successfully
2018-02-22 04:08:15,985 - stages.py[DEBUG]: Running module scripts-vendor (<module 'cloudinit.config.cc_scripts_vendor' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_scripts_vendor.py'>) with frequency once-per-instance
2018-02-22 04:08:15,986 - handlers.py[DEBUG]: start: modules-final/config-scripts-vendor: running config-scripts-vendor with frequency once-per-instance
2018-02-22 04:08:15,987 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_scripts_vendor - wb: [420] 24 bytes
2018-02-22 04:08:15,990 - helpers.py[DEBUG]: Running config-scripts-vendor using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_scripts_vendor'>)
2018-02-22 04:08:15,992 - handlers.py[DEBUG]: finish: modules-final/config-scripts-vendor: SUCCESS: config-scripts-vendor ran successfully
2018-02-22 04:08:15,992 - stages.py[DEBUG]: Running module scripts-per-once (<module 'cloudinit.config.cc_scripts_per_once' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_scripts_per_once.py'>) with frequency once
2018-02-22 04:08:15,994 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-once: running config-scripts-per-once with frequency once
2018-02-22 04:08:15,995 - util.py[DEBUG]: Writing to /var/lib/cloud/sem/config_scripts_per_once.once - wb: [420] 24 bytes
2018-02-22 04:08:15,998 - helpers.py[DEBUG]: Running config-scripts-per-once using lock (<FileLock using file '/var/lib/cloud/sem/config_scripts_per_once.once'>)
2018-02-22 04:08:15,999 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-once: SUCCESS: config-scripts-per-once ran successfully
2018-02-22 04:08:16,000 - stages.py[DEBUG]: Running module scripts-per-boot (<module 'cloudinit.config.cc_scripts_per_boot' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_scripts_per_boot.py'>) with frequency always
2018-02-22 04:08:16,001 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-boot: running config-scripts-per-boot with frequency always
2018-02-22 04:08:16,002 - helpers.py[DEBUG]: Running config-scripts-per-boot using lock (<cloudinit.helpers.DummyLock object at 0x75c8cdf0>)
2018-02-22 04:08:16,003 - util.py[DEBUG]: Running command ['/var/lib/cloud/scripts/per-boot/00_run-parts.sh'] with allowed return codes [0] (shell=False, capture=False)
2018-02-22 04:08:16,187 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-boot: SUCCESS: config-scripts-per-boot ran successfully
2018-02-22 04:08:16,188 - stages.py[DEBUG]: Running module scripts-per-instance (<module 'cloudinit.config.cc_scripts_per_instance' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_scripts_per_instance.py'>) with frequency once-per-instance
2018-02-22 04:08:16,189 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-instance: running config-scripts-per-instance with frequency once-per-instance
2018-02-22 04:08:16,190 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_scripts_per_instance - wb: [420] 24 bytes
2018-02-22 04:08:16,194 - helpers.py[DEBUG]: Running config-scripts-per-instance using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_scripts_per_instance'>)
2018-02-22 04:08:16,196 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-instance: SUCCESS: config-scripts-per-instance ran successfully
2018-02-22 04:08:16,196 - stages.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
2018-02-22 04:08:16,198 - handlers.py[DEBUG]: start: modules-final/config-scripts-user: running config-scripts-user with frequency once-per-instance
2018-02-22 04:08:16,199 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_scripts_user - wb: [420] 23 bytes
2018-02-22 04:08:16,202 - helpers.py[DEBUG]: Running config-scripts-user using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_scripts_user'>)
2018-02-22 04:08:16,203 - handlers.py[DEBUG]: finish: modules-final/config-scripts-user: SUCCESS: config-scripts-user ran successfully
2018-02-22 04:08:16,203 - stages.py[DEBUG]: Running module ssh-authkey-fingerprints (<module 'cloudinit.config.cc_ssh_authkey_fingerprints' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_ssh_authkey_fingerprints.py'>) with frequency once-per-instance
2018-02-22 04:08:16,205 - handlers.py[DEBUG]: start: modules-final/config-ssh-authkey-fingerprints: running config-ssh-authkey-fingerprints with frequency once-per-instance
2018-02-22 04:08:16,205 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_ssh_authkey_fingerprints - wb: [420] 24 bytes
2018-02-22 04:08:16,208 - helpers.py[DEBUG]: Running config-ssh-authkey-fingerprints using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_ssh_authkey_fingerprints'>)
2018-02-22 04:08:16,212 - util.py[DEBUG]: Reading from /etc/ssh/sshd_config (quiet=False)
2018-02-22 04:08:16,213 - util.py[DEBUG]: Read 3298 bytes from /etc/ssh/sshd_config
2018-02-22 04:08:16,215 - util.py[DEBUG]: Reading from /home/debian/.ssh/authorized_keys (quiet=False)
2018-02-22 04:08:16,216 - util.py[DEBUG]: Read 0 bytes from /home/debian/.ssh/authorized_keys
2018-02-22 04:08:16,218 - handlers.py[DEBUG]: finish: modules-final/config-ssh-authkey-fingerprints: SUCCESS: config-ssh-authkey-fingerprints ran successfully
2018-02-22 04:08:16,219 - stages.py[DEBUG]: Running module keys-to-console (<module 'cloudinit.config.cc_keys_to_console' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_keys_to_console.py'>) with frequency once-per-instance
2018-02-22 04:08:16,220 - handlers.py[DEBUG]: start: modules-final/config-keys-to-console: running config-keys-to-console with frequency once-per-instance
2018-02-22 04:08:16,221 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_keys_to_console - wb: [420] 24 bytes
2018-02-22 04:08:16,224 - helpers.py[DEBUG]: Running config-keys-to-console using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_keys_to_console'>)
2018-02-22 04:08:16,226 - util.py[DEBUG]: Running command ['/usr/lib/cloud-init/write-ssh-key-fingerprints', '', 'ssh-dss'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:08:16,326 - handlers.py[DEBUG]: finish: modules-final/config-keys-to-console: SUCCESS: config-keys-to-console ran successfully
2018-02-22 04:08:16,326 - stages.py[DEBUG]: Running module phone-home (<module 'cloudinit.config.cc_phone_home' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_phone_home.py'>) with frequency once-per-instance
2018-02-22 04:08:16,328 - handlers.py[DEBUG]: start: modules-final/config-phone-home: running config-phone-home with frequency once-per-instance
2018-02-22 04:08:16,329 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_phone_home - wb: [420] 23 bytes
2018-02-22 04:08:16,332 - helpers.py[DEBUG]: Running config-phone-home using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_phone_home'>)
2018-02-22 04:08:16,333 - cc_phone_home.py[DEBUG]: Skipping module named phone-home, no 'phone_home' configuration found
2018-02-22 04:08:16,333 - handlers.py[DEBUG]: finish: modules-final/config-phone-home: SUCCESS: config-phone-home ran successfully
2018-02-22 04:08:16,334 - stages.py[DEBUG]: Running module final-message (<module 'cloudinit.config.cc_final_message' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_final_message.py'>) with frequency always
2018-02-22 04:08:16,335 - handlers.py[DEBUG]: start: modules-final/config-final-message: running config-final-message with frequency always
2018-02-22 04:08:16,336 - helpers.py[DEBUG]: Running config-final-message using lock (<cloudinit.helpers.DummyLock object at 0x75c55970>)
2018-02-22 04:08:16,336 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2018-02-22 04:08:16,337 - util.py[DEBUG]: Read 13 bytes from /proc/uptime
2018-02-22 04:08:16,357 - util.py[DEBUG]: Cloud-init v. 0.7.9 finished at Thu, 22 Feb 2018 04:08:16 +0000. Datasource DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net].  Up 47.36 seconds
2018-02-22 04:08:16,358 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/boot-finished - wb: [420] 51 bytes
2018-02-22 04:08:16,361 - handlers.py[DEBUG]: finish: modules-final/config-final-message: SUCCESS: config-final-message ran successfully
2018-02-22 04:08:16,361 - stages.py[DEBUG]: Running module power-state-change (<module 'cloudinit.config.cc_power_state_change' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_power_state_change.py'>) with frequency once-per-instance
2018-02-22 04:08:16,363 - handlers.py[DEBUG]: start: modules-final/config-power-state-change: running config-power-state-change with frequency once-per-instance
2018-02-22 04:08:16,364 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_power_state_change - wb: [420] 23 bytes
2018-02-22 04:08:16,367 - helpers.py[DEBUG]: Running config-power-state-change using lock (<FileLock using file '/var/lib/cloud/instances/iid-raspberrypi-nocloud/sem/config_power_state_change'>)
2018-02-22 04:08:16,367 - cc_power_state_change.py[DEBUG]: no power_state provided. doing nothing
2018-02-22 04:08:16,368 - handlers.py[DEBUG]: finish: modules-final/config-power-state-change: SUCCESS: config-power-state-change ran successfully
2018-02-22 04:08:16,368 - main.py[DEBUG]: Ran 17 modules with 0 failures
2018-02-22 04:08:16,372 - util.py[DEBUG]: Creating symbolic link from '/run/cloud-init/result.json' => '../../var/lib/cloud/data/result.json'
2018-02-22 04:08:16,373 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2018-02-22 04:08:16,373 - util.py[DEBUG]: Read 13 bytes from /proc/uptime
2018-02-22 04:08:16,374 - util.py[DEBUG]: cloud-init mode 'modules' took 0.968 seconds (0.97)
2018-02-22 04:08:16,374 - handlers.py[DEBUG]: finish: modules-final: SUCCESS: running modules for final
2018-02-22 04:10:31,609 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'init-local' at Thu, 22 Feb 2018 04:10:31 +0000. Up 9.63 seconds.
2018-02-22 04:10:31,644 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [420] 0 bytes
2018-02-22 04:10:31,653 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 0:4
2018-02-22 04:10:31,658 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance/boot-finished
2018-02-22 04:10:31,659 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/data/no-net
2018-02-22 04:10:31,660 - handlers.py[DEBUG]: start: init-local/check-cache: attempting to read from cache [check]
2018-02-22 04:10:31,661 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
2018-02-22 04:10:31,663 - util.py[DEBUG]: Read 4555 bytes from /var/lib/cloud/instance/obj.pkl
2018-02-22 04:10:31,684 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/meta-data (quiet=False)
2018-02-22 04:10:31,686 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/meta-data (quiet=False)
2018-02-22 04:10:31,687 - stages.py[DEBUG]: cache invalid in datasource: DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net]
2018-02-22 04:10:31,688 - handlers.py[DEBUG]: finish: init-local/check-cache: SUCCESS: cache invalid in datasource: DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net]
2018-02-22 04:10:31,689 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance
2018-02-22 04:10:31,704 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'>
2018-02-22 04:10:31,708 - __init__.py[DEBUG]: Looking for for data source in: ['NoCloud', 'ConfigDrive', 'OpenNebula', 'Azure', 'AltCloud', 'OVF', 'MAAS', 'GCE', 'OpenStack', 'CloudSigma', 'SmartOS', 'Ec2', 'CloudStack', 'None'], via packages ['', 'cloudinit.sources'] that matches dependencies ['FILESYSTEM']
2018-02-22 04:10:32,114 - __init__.py[DEBUG]: Searching for local data source in: ['DataSourceNoCloud', 'DataSourceConfigDrive', 'DataSourceOpenNebula', 'DataSourceOVF', 'DataSourceCloudSigma', 'DataSourceSmartOS']
2018-02-22 04:10:32,116 - handlers.py[DEBUG]: start: init-local/search-NoCloud: searching for local data from DataSourceNoCloud
2018-02-22 04:10:32,116 - __init__.py[DEBUG]: Seeing if we can get any data from <class 'cloudinit.sources.DataSourceNoCloud.DataSourceNoCloud'>
2018-02-22 04:10:32,118 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/user-data (quiet=False)
2018-02-22 04:10:32,119 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/meta-data (quiet=False)
2018-02-22 04:10:32,119 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/vendor-data (quiet=False)
2018-02-22 04:10:32,120 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/network-config (quiet=False)
2018-02-22 04:10:32,121 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/user-data (quiet=False)
2018-02-22 04:10:32,121 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/meta-data (quiet=False)
2018-02-22 04:10:32,122 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/vendor-data (quiet=False)
2018-02-22 04:10:32,123 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/network-config (quiet=False)
2018-02-22 04:10:32,123 - util.py[DEBUG]: Running command ['/sbin/blkid', '-odevice', '/dev/sr0'] with allowed return codes [0, 2] (shell=False, capture=True)
2018-02-22 04:10:32,142 - util.py[DEBUG]: Running command ['/sbin/blkid', '-odevice', '/dev/sr1'] with allowed return codes [0, 2] (shell=False, capture=True)
2018-02-22 04:10:32,155 - util.py[DEBUG]: Running command ['/sbin/blkid', '-tTYPE=vfat', '-odevice'] with allowed return codes [0, 2] (shell=False, capture=True)
2018-02-22 04:10:32,209 - util.py[DEBUG]: Running command ['/sbin/blkid', '-tTYPE=iso9660', '-odevice'] with allowed return codes [0, 2] (shell=False, capture=True)
2018-02-22 04:10:32,245 - util.py[DEBUG]: Running command ['/sbin/blkid', '-tLABEL=cidata', '-odevice'] with allowed return codes [0, 2] (shell=False, capture=True)
2018-02-22 04:10:32,282 - util.py[DEBUG]: Reading from /boot/meta-data (quiet=False)
2018-02-22 04:10:32,285 - util.py[DEBUG]: Read 37 bytes from /boot/meta-data
2018-02-22 04:10:32,286 - util.py[DEBUG]: Attempting to load yaml from string of length 37 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:32,292 - util.py[DEBUG]: Reading from /boot/user-data (quiet=False)
2018-02-22 04:10:32,294 - util.py[DEBUG]: Read 60 bytes from /boot/user-data
2018-02-22 04:10:32,295 - DataSourceNoCloud.py[DEBUG]: Using seeded cache data from /boot/
2018-02-22 04:10:32,300 - handlers.py[DEBUG]: finish: init-local/search-NoCloud: SUCCESS: found local data from DataSourceNoCloud
2018-02-22 04:10:32,301 - stages.py[INFO]: Loaded datasource DataSourceNoCloud - DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net]
2018-02-22 04:10:32,303 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2018-02-22 04:10:32,304 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg
2018-02-22 04:10:32,305 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:32,493 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/datasource.cfg (quiet=False)
2018-02-22 04:10:32,495 - util.py[DEBUG]: Read 45 bytes from /etc/cloud/cloud.cfg.d/datasource.cfg
2018-02-22 04:10:32,495 - util.py[DEBUG]: Attempting to load yaml from string of length 45 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:32,505 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2018-02-22 04:10:32,506 - util.py[DEBUG]: Read 197 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2018-02-22 04:10:32,506 - util.py[DEBUG]: Attempting to load yaml from string of length 197 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:32,530 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2018-02-22 04:10:32,531 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2018-02-22 04:10:32,532 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:32,604 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False)
2018-02-22 04:10:32,605 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg
2018-02-22 04:10:32,605 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:32,624 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:32,626 - util.py[DEBUG]: load_yaml given empty string, returning default
2018-02-22 04:10:32,633 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance
2018-02-22 04:10:32,634 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/iid-raspberrypi-nocloud'
2018-02-22 04:10:32,643 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/iid-raspberrypi-nocloud/datasource (quiet=False)
2018-02-22 04:10:32,645 - util.py[DEBUG]: Read 82 bytes from /var/lib/cloud/instances/iid-raspberrypi-nocloud/datasource
2018-02-22 04:10:32,646 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/datasource - wb: [420] 82 bytes
2018-02-22 04:10:32,652 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [420] 82 bytes
2018-02-22 04:10:32,658 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False)
2018-02-22 04:10:32,660 - util.py[DEBUG]: Read 24 bytes from /var/lib/cloud/data/instance-id
2018-02-22 04:10:32,661 - stages.py[DEBUG]: previous iid found to be iid-raspberrypi-nocloud
2018-02-22 04:10:32,661 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [420] 24 bytes
2018-02-22 04:10:32,668 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [420] 24 bytes
2018-02-22 04:10:32,673 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [420] 24 bytes
2018-02-22 04:10:32,681 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [256] 5331 bytes
2018-02-22 04:10:32,687 - main.py[DEBUG]: [local] init will now be targeting instance id: iid-raspberrypi-nocloud. new=False
2018-02-22 04:10:32,689 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2018-02-22 04:10:32,690 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg
2018-02-22 04:10:32,690 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:32,870 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/datasource.cfg (quiet=False)
2018-02-22 04:10:32,871 - util.py[DEBUG]: Read 45 bytes from /etc/cloud/cloud.cfg.d/datasource.cfg
2018-02-22 04:10:32,872 - util.py[DEBUG]: Attempting to load yaml from string of length 45 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:32,881 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2018-02-22 04:10:32,882 - util.py[DEBUG]: Read 197 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2018-02-22 04:10:32,883 - util.py[DEBUG]: Attempting to load yaml from string of length 197 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:32,907 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2018-02-22 04:10:32,908 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2018-02-22 04:10:32,908 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:32,980 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False)
2018-02-22 04:10:32,981 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg
2018-02-22 04:10:32,982 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:33,001 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:33,002 - util.py[DEBUG]: load_yaml given empty string, returning default
2018-02-22 04:10:33,005 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2018-02-22 04:10:33,006 - util.py[DEBUG]: Read 96 bytes from /var/lib/cloud/instance/cloud-config.txt
2018-02-22 04:10:33,007 - util.py[DEBUG]: Attempting to load yaml from string of length 96 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:33,028 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/carrier (quiet=False)
2018-02-22 04:10:33,029 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/dormant (quiet=False)
2018-02-22 04:10:33,030 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/operstate (quiet=False)
2018-02-22 04:10:33,031 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/wlan0/operstate
2018-02-22 04:10:33,032 - util.py[DEBUG]: Reading from /sys/class/net/eth0/carrier (quiet=False)
2018-02-22 04:10:33,033 - util.py[DEBUG]: Reading from /sys/class/net/eth0/dormant (quiet=False)
2018-02-22 04:10:33,033 - util.py[DEBUG]: Reading from /sys/class/net/eth0/operstate (quiet=False)
2018-02-22 04:10:33,034 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/eth0/operstate
2018-02-22 04:10:33,035 - util.py[DEBUG]: Reading from /sys/class/net/eth0/address (quiet=False)
2018-02-22 04:10:33,036 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/eth0/address
2018-02-22 04:10:33,037 - stages.py[DEBUG]: applying net config names for {'config': [{'type': 'physical', 'name': 'eth0', 'subnets': [{'type': 'dhcp'}], 'mac_address': 'b8:27:eb:55:b7:56'}], 'version': 1}
2018-02-22 04:10:33,043 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'>
2018-02-22 04:10:33,044 - util.py[DEBUG]: Reading from /sys/class/net/eth0/operstate (quiet=False)
2018-02-22 04:10:33,045 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/eth0/operstate
2018-02-22 04:10:33,046 - util.py[DEBUG]: Reading from /sys/class/net/eth0/address (quiet=False)
2018-02-22 04:10:33,047 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/eth0/address
2018-02-22 04:10:33,048 - util.py[DEBUG]: Reading from /sys/class/net/lo/operstate (quiet=False)
2018-02-22 04:10:33,049 - util.py[DEBUG]: Read 8 bytes from /sys/class/net/lo/operstate
2018-02-22 04:10:33,049 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False)
2018-02-22 04:10:33,050 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address
2018-02-22 04:10:33,051 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/operstate (quiet=False)
2018-02-22 04:10:33,052 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/wlan0/operstate
2018-02-22 04:10:33,052 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/address (quiet=False)
2018-02-22 04:10:33,053 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/wlan0/address
2018-02-22 04:10:33,056 - util.py[DEBUG]: Running command ['ip', '-6', 'addr', 'show', 'permanent', 'scope', 'global'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:10:33,092 - util.py[DEBUG]: Running command ['ip', '-4', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:10:33,108 - __init__.py[DEBUG]: no work necessary for renaming of [['b8:27:eb:55:b7:56', 'eth0']]
2018-02-22 04:10:33,112 - stages.py[DEBUG]: not a new instance. network config is not applied.
2018-02-22 04:10:33,113 - main.py[DEBUG]: [local] Exiting. datasource DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net] not in local mode.
2018-02-22 04:10:33,118 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2018-02-22 04:10:33,119 - util.py[DEBUG]: Read 12 bytes from /proc/uptime
2018-02-22 04:10:33,120 - util.py[DEBUG]: cloud-init mode 'init' took 1.961 seconds (1.96)
2018-02-22 04:10:33,121 - handlers.py[DEBUG]: finish: init-local: SUCCESS: searching for local datasources
2018-02-22 04:10:39,208 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'init' at Thu, 22 Feb 2018 04:10:38 +0000. Up 17.29 seconds.
2018-02-22 04:10:39,241 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [420] 0 bytes
2018-02-22 04:10:39,250 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 0:4
2018-02-22 04:10:39,251 - util.py[DEBUG]: Running command ['ifconfig', '-a'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:10:39,307 - util.py[DEBUG]: Running command ['netstat', '-rn'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:10:39,329 - util.py[DEBUG]: Running command ['netstat', '-A', 'inet6', '-n'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:10:39,346 - main.py[DEBUG]: Checking to see if files that we need already exist from a previous run that would allow us to stop early.
2018-02-22 04:10:39,347 - main.py[DEBUG]: Execution continuing, no previous run detected that would allow us to stop early.
2018-02-22 04:10:39,348 - handlers.py[DEBUG]: start: init-network/check-cache: attempting to read from cache [trust]
2018-02-22 04:10:39,349 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
2018-02-22 04:10:39,350 - util.py[DEBUG]: Read 5331 bytes from /var/lib/cloud/instance/obj.pkl
2018-02-22 04:10:39,363 - util.py[DEBUG]: Reading from /run/cloud-init/.instance-id (quiet=False)
2018-02-22 04:10:39,365 - util.py[DEBUG]: Read 24 bytes from /run/cloud-init/.instance-id
2018-02-22 04:10:39,365 - stages.py[DEBUG]: restored from cache with run check: DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net]
2018-02-22 04:10:39,367 - handlers.py[DEBUG]: finish: init-network/check-cache: SUCCESS: restored from cache with run check: DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net]
2018-02-22 04:10:39,368 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2018-02-22 04:10:39,369 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg
2018-02-22 04:10:39,370 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:39,547 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/datasource.cfg (quiet=False)
2018-02-22 04:10:39,548 - util.py[DEBUG]: Read 45 bytes from /etc/cloud/cloud.cfg.d/datasource.cfg
2018-02-22 04:10:39,549 - util.py[DEBUG]: Attempting to load yaml from string of length 45 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:39,558 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2018-02-22 04:10:39,559 - util.py[DEBUG]: Read 197 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2018-02-22 04:10:39,560 - util.py[DEBUG]: Attempting to load yaml from string of length 197 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:39,583 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2018-02-22 04:10:39,584 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2018-02-22 04:10:39,585 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:39,655 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False)
2018-02-22 04:10:39,656 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg
2018-02-22 04:10:39,657 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:39,676 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:39,677 - util.py[DEBUG]: load_yaml given empty string, returning default
2018-02-22 04:10:39,680 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2018-02-22 04:10:39,681 - util.py[DEBUG]: Read 96 bytes from /var/lib/cloud/instance/cloud-config.txt
2018-02-22 04:10:39,682 - util.py[DEBUG]: Attempting to load yaml from string of length 96 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:39,699 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance
2018-02-22 04:10:39,700 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/iid-raspberrypi-nocloud'
2018-02-22 04:10:39,708 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/iid-raspberrypi-nocloud/datasource (quiet=False)
2018-02-22 04:10:39,709 - util.py[DEBUG]: Read 82 bytes from /var/lib/cloud/instances/iid-raspberrypi-nocloud/datasource
2018-02-22 04:10:39,710 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/datasource - wb: [420] 82 bytes
2018-02-22 04:10:39,716 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [420] 82 bytes
2018-02-22 04:10:39,722 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False)
2018-02-22 04:10:39,723 - util.py[DEBUG]: Read 24 bytes from /var/lib/cloud/data/instance-id
2018-02-22 04:10:39,724 - stages.py[DEBUG]: previous iid found to be iid-raspberrypi-nocloud
2018-02-22 04:10:39,725 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [420] 24 bytes
2018-02-22 04:10:39,731 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [420] 24 bytes
2018-02-22 04:10:39,736 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [420] 24 bytes
2018-02-22 04:10:39,744 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [256] 5421 bytes
2018-02-22 04:10:39,750 - main.py[DEBUG]: [net] init will now be targeting instance id: iid-raspberrypi-nocloud. new=False
2018-02-22 04:10:39,752 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2018-02-22 04:10:39,753 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg
2018-02-22 04:10:39,753 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:39,931 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/datasource.cfg (quiet=False)
2018-02-22 04:10:39,932 - util.py[DEBUG]: Read 45 bytes from /etc/cloud/cloud.cfg.d/datasource.cfg
2018-02-22 04:10:39,932 - util.py[DEBUG]: Attempting to load yaml from string of length 45 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:39,942 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2018-02-22 04:10:39,943 - util.py[DEBUG]: Read 197 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2018-02-22 04:10:39,943 - util.py[DEBUG]: Attempting to load yaml from string of length 197 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:39,967 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2018-02-22 04:10:39,968 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2018-02-22 04:10:39,968 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:40,038 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False)
2018-02-22 04:10:40,039 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg
2018-02-22 04:10:40,040 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:40,059 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:40,060 - util.py[DEBUG]: load_yaml given empty string, returning default
2018-02-22 04:10:40,063 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2018-02-22 04:10:40,064 - util.py[DEBUG]: Read 96 bytes from /var/lib/cloud/instance/cloud-config.txt
2018-02-22 04:10:40,065 - util.py[DEBUG]: Attempting to load yaml from string of length 96 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:40,085 - util.py[DEBUG]: Reading from /sys/class/net/eth0/carrier (quiet=False)
2018-02-22 04:10:40,087 - util.py[DEBUG]: Reading from /sys/class/net/eth0/dormant (quiet=False)
2018-02-22 04:10:40,088 - util.py[DEBUG]: Reading from /sys/class/net/eth0/operstate (quiet=False)
2018-02-22 04:10:40,088 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/eth0/operstate
2018-02-22 04:10:40,089 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/carrier (quiet=False)
2018-02-22 04:10:40,090 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/dormant (quiet=False)
2018-02-22 04:10:40,091 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/operstate (quiet=False)
2018-02-22 04:10:40,092 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/wlan0/operstate
2018-02-22 04:10:40,092 - util.py[DEBUG]: Reading from /sys/class/net/eth0/address (quiet=False)
2018-02-22 04:10:40,093 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/eth0/address
2018-02-22 04:10:40,094 - stages.py[DEBUG]: applying net config names for {'config': [{'mac_address': 'b8:27:eb:55:b7:56', 'subnets': [{'type': 'dhcp'}], 'name': 'eth0', 'type': 'physical'}], 'version': 1}
2018-02-22 04:10:40,100 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'>
2018-02-22 04:10:40,104 - util.py[DEBUG]: Reading from /sys/class/net/eth0/operstate (quiet=False)
2018-02-22 04:10:40,105 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/eth0/operstate
2018-02-22 04:10:40,106 - util.py[DEBUG]: Reading from /sys/class/net/eth0/address (quiet=False)
2018-02-22 04:10:40,107 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/eth0/address
2018-02-22 04:10:40,108 - util.py[DEBUG]: Reading from /sys/class/net/lo/operstate (quiet=False)
2018-02-22 04:10:40,108 - util.py[DEBUG]: Read 8 bytes from /sys/class/net/lo/operstate
2018-02-22 04:10:40,109 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False)
2018-02-22 04:10:40,110 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address
2018-02-22 04:10:40,111 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/operstate (quiet=False)
2018-02-22 04:10:40,111 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/wlan0/operstate
2018-02-22 04:10:40,112 - util.py[DEBUG]: Reading from /sys/class/net/wlan0/address (quiet=False)
2018-02-22 04:10:40,113 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/wlan0/address
2018-02-22 04:10:40,116 - util.py[DEBUG]: Running command ['ip', '-6', 'addr', 'show', 'permanent', 'scope', 'global'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:10:40,130 - util.py[DEBUG]: Running command ['ip', '-4', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:10:40,145 - __init__.py[DEBUG]: no work necessary for renaming of [['b8:27:eb:55:b7:56', 'eth0']]
2018-02-22 04:10:40,149 - stages.py[DEBUG]: not a new instance. network config is not applied.
2018-02-22 04:10:40,150 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/user-data.txt - wb: [384] 60 bytes
2018-02-22 04:10:40,159 - util.py[DEBUG]: Attempting to load yaml from string of length 60 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:40,187 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/user-data.txt.i - wb: [384] 338 bytes
2018-02-22 04:10:40,194 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/vendor-data.txt - wb: [384] 0 bytes
2018-02-22 04:10:40,209 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/vendor-data.txt.i - wb: [384] 281 bytes
2018-02-22 04:10:40,219 - helpers.py[DEBUG]: consume_data already ran (freq=once-per-instance)
2018-02-22 04:10:40,221 - handlers.py[DEBUG]: start: init-network/consume-user-data: reading and applying user-data
2018-02-22 04:10:40,225 - stages.py[DEBUG]: Added default handler for {'text/cloud-config-jsonp', 'text/cloud-config'} from CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']]
2018-02-22 04:10:40,226 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript'} from ShellScriptPartHandler: [['text/x-shellscript']]
2018-02-22 04:10:40,227 - stages.py[DEBUG]: Added default handler for {'text/cloud-boothook'} from BootHookPartHandler: [['text/cloud-boothook']]
2018-02-22 04:10:40,228 - stages.py[DEBUG]: Added default handler for {'text/upstart-job'} from UpstartJobPartHandler: [['text/upstart-job']]
2018-02-22 04:10:40,232 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__begin__, None, 3) with frequency always
2018-02-22 04:10:40,232 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__begin__, None, 2) with frequency always
2018-02-22 04:10:40,233 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__begin__, None, 2) with frequency always
2018-02-22 04:10:40,235 - __init__.py[DEBUG]: {'MIME-Version': '1.0', 'Content-Type': 'text/cloud-config', 'Content-Disposition': 'attachment; filename="part-001"'}
2018-02-22 04:10:40,236 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (text/cloud-config, part-001, 3) with frequency always
2018-02-22 04:10:40,236 - util.py[DEBUG]: Attempting to load yaml from string of length 60 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:40,247 - cloud_config.py[DEBUG]: Merging by applying [('dict', ['replace']), ('list', []), ('str', [])]
2018-02-22 04:10:40,248 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__end__, None, 3) with frequency always
2018-02-22 04:10:40,255 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-raspberrypi-nocloud/cloud-config.txt - wb: [384] 96 bytes
2018-02-22 04:10:40,264 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__end__, None, 2) with frequency always
2018-02-22 04:10:40,265 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__end__, None, 2) with frequency always
2018-02-22 04:10:40,266 - handlers.py[DEBUG]: finish: init-network/consume-user-data: SUCCESS: reading and applying user-data
2018-02-22 04:10:40,267 - handlers.py[DEBUG]: start: init-network/consume-vendor-data: reading and applying vendor-data
2018-02-22 04:10:40,268 - stages.py[DEBUG]: no vendordata from datasource
2018-02-22 04:10:40,269 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data: SUCCESS: reading and applying vendor-data
2018-02-22 04:10:40,271 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2018-02-22 04:10:40,271 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg
2018-02-22 04:10:40,272 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:40,450 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/datasource.cfg (quiet=False)
2018-02-22 04:10:40,451 - util.py[DEBUG]: Read 45 bytes from /etc/cloud/cloud.cfg.d/datasource.cfg
2018-02-22 04:10:40,452 - util.py[DEBUG]: Attempting to load yaml from string of length 45 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:40,461 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2018-02-22 04:10:40,462 - util.py[DEBUG]: Read 197 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2018-02-22 04:10:40,463 - util.py[DEBUG]: Attempting to load yaml from string of length 197 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:40,486 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2018-02-22 04:10:40,487 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2018-02-22 04:10:40,488 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:40,558 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False)
2018-02-22 04:10:40,559 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg
2018-02-22 04:10:40,560 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:40,579 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:40,580 - util.py[DEBUG]: load_yaml given empty string, returning default
2018-02-22 04:10:40,583 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2018-02-22 04:10:40,584 - util.py[DEBUG]: Read 96 bytes from /var/lib/cloud/instance/cloud-config.txt
2018-02-22 04:10:40,585 - util.py[DEBUG]: Attempting to load yaml from string of length 96 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:40,608 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2018-02-22 04:10:40,609 - util.py[DEBUG]: Read 96 bytes from /var/lib/cloud/instance/cloud-config.txt
2018-02-22 04:10:40,610 - util.py[DEBUG]: Attempting to load yaml from string of length 96 with allowed root types (<class 'dict'>,)
2018-02-22 04:10:40,647 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [256] 4555 bytes
2018-02-22 04:10:40,782 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'>
2018-02-22 04:10:40,789 - stages.py[DEBUG]: Running module migrator (<module 'cloudinit.config.cc_migrator' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_migrator.py'>) with frequency always
2018-02-22 04:10:40,792 - handlers.py[DEBUG]: start: init-network/config-migrator: running config-migrator with frequency always
2018-02-22 04:10:40,793 - helpers.py[DEBUG]: Running config-migrator using lock (<cloudinit.helpers.DummyLock object at 0x75c3b390>)
2018-02-22 04:10:40,799 - cc_migrator.py[DEBUG]: Migrated 0 semaphore files to there canonicalized names
2018-02-22 04:10:40,805 - handlers.py[DEBUG]: finish: init-network/config-migrator: SUCCESS: config-migrator ran successfully
2018-02-22 04:10:40,806 - stages.py[DEBUG]: Running module seed_random (<module 'cloudinit.config.cc_seed_random' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_seed_random.py'>) with frequency once-per-instance
2018-02-22 04:10:40,809 - handlers.py[DEBUG]: start: init-network/config-seed_random: running config-seed_random with frequency once-per-instance
2018-02-22 04:10:40,810 - helpers.py[DEBUG]: config-seed_random already ran (freq=once-per-instance)
2018-02-22 04:10:40,811 - handlers.py[DEBUG]: finish: init-network/config-seed_random: SUCCESS: config-seed_random previously ran
2018-02-22 04:10:40,811 - stages.py[DEBUG]: Running module bootcmd (<module 'cloudinit.config.cc_bootcmd' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_bootcmd.py'>) with frequency always
2018-02-22 04:10:40,815 - handlers.py[DEBUG]: start: init-network/config-bootcmd: running config-bootcmd with frequency always
2018-02-22 04:10:40,815 - helpers.py[DEBUG]: Running config-bootcmd using lock (<cloudinit.helpers.DummyLock object at 0x75c3b610>)
2018-02-22 04:10:40,816 - cc_bootcmd.py[DEBUG]: Skipping module named bootcmd, no 'bootcmd' key in configuration
2018-02-22 04:10:40,817 - handlers.py[DEBUG]: finish: init-network/config-bootcmd: SUCCESS: config-bootcmd ran successfully
2018-02-22 04:10:40,818 - stages.py[DEBUG]: Running module write-files (<module 'cloudinit.config.cc_write_files' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_write_files.py'>) with frequency once-per-instance
2018-02-22 04:10:40,821 - handlers.py[DEBUG]: start: init-network/config-write-files: running config-write-files with frequency once-per-instance
2018-02-22 04:10:40,822 - helpers.py[DEBUG]: config-write-files already ran (freq=once-per-instance)
2018-02-22 04:10:40,822 - handlers.py[DEBUG]: finish: init-network/config-write-files: SUCCESS: config-write-files previously ran
2018-02-22 04:10:40,823 - stages.py[DEBUG]: Running module growpart (<module 'cloudinit.config.cc_growpart' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_growpart.py'>) with frequency always
2018-02-22 04:10:40,827 - handlers.py[DEBUG]: start: init-network/config-growpart: running config-growpart with frequency always
2018-02-22 04:10:40,827 - helpers.py[DEBUG]: Running config-growpart using lock (<cloudinit.helpers.DummyLock object at 0x76346090>)
2018-02-22 04:10:40,828 - cc_growpart.py[DEBUG]: No 'growpart' entry in cfg.  Using default: {'devices': ['/'], 'mode': 'auto', 'ignore_growroot_disabled': False}
2018-02-22 04:10:40,829 - util.py[DEBUG]: Running command ['growpart', '--help'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:10:40,841 - cc_growpart.py[DEBUG]: growpart unable to find resizer for 'auto': No resizers available
2018-02-22 04:10:40,843 - handlers.py[DEBUG]: finish: init-network/config-growpart: SUCCESS: config-growpart ran successfully
2018-02-22 04:10:40,843 - stages.py[DEBUG]: Running module resizefs (<module 'cloudinit.config.cc_resizefs' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_resizefs.py'>) with frequency always
2018-02-22 04:10:40,847 - handlers.py[DEBUG]: start: init-network/config-resizefs: running config-resizefs with frequency always
2018-02-22 04:10:40,848 - helpers.py[DEBUG]: Running config-resizefs using lock (<cloudinit.helpers.DummyLock object at 0x75c93f50>)
2018-02-22 04:10:40,849 - util.py[DEBUG]: Reading from /proc/349/mountinfo (quiet=False)
2018-02-22 04:10:40,850 - util.py[DEBUG]: Read 2086 bytes from /proc/349/mountinfo
2018-02-22 04:10:40,851 - cc_resizefs.py[DEBUG]: resize_info: dev=/dev/root mnt_point=/ path=/
2018-02-22 04:10:40,852 - util.py[DEBUG]: Running command ['systemd-detect-virt', '--quiet', '--container'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:10:40,876 - util.py[DEBUG]: Running command ['running-in-container'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:10:40,887 - util.py[DEBUG]: Running command ['lxc-is-container'] with allowed return codes [0] (shell=False, capture=True)
2018-02-22 04:10:40,899 - util.py[DEBUG]: Reading from /proc/1/environ (quiet=False)
2018-02-22 04:10:40,900 - util.py[DEBUG]: Read 18 bytes from /proc/1/environ
2018-02-22 04:10:40,901 - util.py[DEBUG]: Reading from /proc/self/status (quiet=False)
2018-02-22 04:10:40,902 - util.py[DEBUG]: Read 925 bytes from /proc/self/status
2018-02-22 04:10:40,903 - cc_resizefs.py[DEBUG]: Converted /dev/root to '/dev/PARTUUID=a00bdab5-02' per kernel cmdline
2018-02-22 04:10:40,904 - cc_resizefs.py[WARNING]: Device '/dev/PARTUUID=a00bdab5-02' did not exist. cannot resize: dev=/dev/root mnt_point=/ path=/
2018-02-22 04:10:40,906 - handlers.py[DEBUG]: finish: init-network/config-resizefs: SUCCESS: config-resizefs ran successfully
2018-02-22 04:10:40,907 - stages.py[DEBUG]: Running module disk_setup (<module 'cloudinit.config.cc_disk_setup' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_disk_setup.py'>) with frequency once-per-instance
2018-02-22 04:10:40,910 - handlers.py[DEBUG]: start: init-network/config-disk_setup: running config-disk_setup with frequency once-per-instance
2018-02-22 04:10:40,912 - helpers.py[DEBUG]: config-disk_setup already ran (freq=once-per-instance)
2018-02-22 04:10:40,913 - handlers.py[DEBUG]: finish: init-network/config-disk_setup: SUCCESS: config-disk_setup previously ran
2018-02-22 04:10:40,914 - stages.py[DEBUG]: Running module mounts (<module 'cloudinit.config.cc_mounts' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_mounts.py'>) with frequency once-per-instance
2018-02-22 04:10:40,917 - handlers.py[DEBUG]: start: init-network/config-mounts: running config-mounts with frequency once-per-instance
2018-02-22 04:10:40,918 - helpers.py[DEBUG]: config-mounts already ran (freq=once-per-instance)
2018-02-22 04:10:40,919 - handlers.py[DEBUG]: finish: init-network/config-mounts: SUCCESS: config-mounts previously ran
2018-02-22 04:10:40,920 - stages.py[DEBUG]: Running module set_hostname (<module 'cloudinit.config.cc_set_hostname' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_set_hostname.py'>) with frequency once-per-instance
2018-02-22 04:10:40,923 - handlers.py[DEBUG]: start: init-network/config-set_hostname: running config-set_hostname with frequency once-per-instance
2018-02-22 04:10:40,924 - helpers.py[DEBUG]: config-set_hostname already ran (freq=once-per-instance)
2018-02-22 04:10:40,925 - handlers.py[DEBUG]: finish: init-network/config-set_hostname: SUCCESS: config-set_hostname previously ran
2018-02-22 04:10:40,926 - stages.py[DEBUG]: Running module update_hostname (<module 'cloudinit.config.cc_update_hostname' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_update_hostname.py'>) with frequency always
2018-02-22 04:10:40,929 - handlers.py[DEBUG]: start: init-network/config-update_hostname: running config-update_hostname with frequency always
2018-02-22 04:10:40,930 - helpers.py[DEBUG]: Running config-update_hostname using lock (<cloudinit.helpers.DummyLock object at 0x75c71bb0>)
2018-02-22 04:10:40,931 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False)
2018-02-22 04:10:40,932 - util.py[DEBUG]: Read 131 bytes from /etc/hosts
2018-02-22 04:10:40,933 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False)
2018-02-22 04:10:40,934 - util.py[DEBUG]: Read 131 bytes from /etc/hosts
2018-02-22 04:10:40,935 - cc_update_hostname.py[DEBUG]: Updating hostname to raspberrypi (raspberrypi)
2018-02-22 04:10:40,936 - util.py[DEBUG]: Reading from /var/lib/cloud/data/previous-hostname (quiet=False)
2018-02-22 04:10:40,938 - util.py[DEBUG]: Read 12 bytes from /var/lib/cloud/data/previous-hostname
2018-02-22 04:10:40,939 - util.py[DEBUG]: Reading from /etc/hostname (quiet=False)
2018-02-22 04:10:40,940 - util.py[DEBUG]: Read 12 bytes from /etc/hostname
2018-02-22 04:10:40,941 - __init__.py[DEBUG]: Attempting to update hostname to raspberrypi in 0 files
2018-02-22 04:10:40,942 - handlers.py[DEBUG]: finish: init-network/config-update_hostname: SUCCESS: config-update_hostname ran successfully
2018-02-22 04:10:40,942 - stages.py[DEBUG]: Running module update_etc_hosts (<module 'cloudinit.config.cc_update_etc_hosts' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_update_etc_hosts.py'>) with frequency always
2018-02-22 04:10:40,946 - handlers.py[DEBUG]: start: init-network/config-update_etc_hosts: running config-update_etc_hosts with frequency always
2018-02-22 04:10:40,947 - helpers.py[DEBUG]: Running config-update_etc_hosts using lock (<cloudinit.helpers.DummyLock object at 0x75c71650>)
2018-02-22 04:10:40,947 - cc_update_etc_hosts.py[DEBUG]: Configuration option 'manage_etc_hosts' is not set, not managing /etc/hosts in module update_etc_hosts
2018-02-22 04:10:40,948 - handlers.py[DEBUG]: finish: init-network/config-update_etc_hosts: SUCCESS: config-update_etc_hosts ran successfully
2018-02-22 04:10:40,949 - stages.py[DEBUG]: Running module ca-certs (<module 'cloudinit.config.cc_ca_certs' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_ca_certs.py'>) with frequency once-per-instance
2018-02-22 04:10:40,952 - handlers.py[DEBUG]: start: init-network/config-ca-certs: running config-ca-certs with frequency once-per-instance
2018-02-22 04:10:40,953 - helpers.py[DEBUG]: config-ca-certs already ran (freq=once-per-instance)
2018-02-22 04:10:40,954 - handlers.py[DEBUG]: finish: init-network/config-ca-certs: SUCCESS: config-ca-certs previously ran
2018-02-22 04:10:40,954 - stages.py[DEBUG]: Running module rsyslog (<module 'cloudinit.config.cc_rsyslog' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_rsyslog.py'>) with frequency once-per-instance
2018-02-22 04:10:40,958 - handlers.py[DEBUG]: start: init-network/config-rsyslog: running config-rsyslog with frequency once-per-instance
2018-02-22 04:10:40,959 - helpers.py[DEBUG]: config-rsyslog already ran (freq=once-per-instance)
2018-02-22 04:10:40,960 - handlers.py[DEBUG]: finish: init-network/config-rsyslog: SUCCESS: config-rsyslog previously ran
2018-02-22 04:10:40,960 - stages.py[DEBUG]: Running module users-groups (<module 'cloudinit.config.cc_users_groups' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_users_groups.py'>) with frequency once-per-instance
2018-02-22 04:10:40,963 - handlers.py[DEBUG]: start: init-network/config-users-groups: running config-users-groups with frequency once-per-instance
2018-02-22 04:10:40,964 - helpers.py[DEBUG]: config-users-groups already ran (freq=once-per-instance)
2018-02-22 04:10:40,965 - handlers.py[DEBUG]: finish: init-network/config-users-groups: SUCCESS: config-users-groups previously ran
2018-02-22 04:10:40,966 - stages.py[DEBUG]: Running module ssh (<module 'cloudinit.config.cc_ssh' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_ssh.py'>) with frequency once-per-instance
2018-02-22 04:10:40,969 - handlers.py[DEBUG]: start: init-network/config-ssh: running config-ssh with frequency once-per-instance
2018-02-22 04:10:40,970 - helpers.py[DEBUG]: config-ssh already ran (freq=once-per-instance)
2018-02-22 04:10:40,971 - handlers.py[DEBUG]: finish: init-network/config-ssh: SUCCESS: config-ssh previously ran
2018-02-22 04:10:40,971 - main.py[DEBUG]: Ran 15 modules with 0 failures
2018-02-22 04:10:40,976 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2018-02-22 04:10:40,978 - util.py[DEBUG]: Read 12 bytes from /proc/uptime
2018-02-22 04:10:40,978 - util.py[DEBUG]: cloud-init mode 'init' took 2.200 seconds (2.20)
2018-02-22 04:10:40,979 - handlers.py[DEBUG]: finish: init-network: SUCCESS: searching for network datasources
2018-02-22 04:10:50,893 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'modules:config' at Thu, 22 Feb 2018 04:10:50 +0000. Up 28.95 seconds.
2018-02-22 04:10:51,458 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'>
2018-02-22 04:10:51,462 - stages.py[DEBUG]: Running module emit_upstart (<module 'cloudinit.config.cc_emit_upstart' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_emit_upstart.py'>) with frequency always
2018-02-22 04:10:51,464 - handlers.py[DEBUG]: start: modules-config/config-emit_upstart: running config-emit_upstart with frequency always
2018-02-22 04:10:51,465 - helpers.py[DEBUG]: Running config-emit_upstart using lock (<cloudinit.helpers.DummyLock object at 0x75c90ef0>)
2018-02-22 04:10:51,465 - cc_emit_upstart.py[DEBUG]: no /sbin/initctl located
2018-02-22 04:10:51,465 - cc_emit_upstart.py[DEBUG]: not upstart system, 'emit_upstart' disabled
2018-02-22 04:10:51,466 - handlers.py[DEBUG]: finish: modules-config/config-emit_upstart: SUCCESS: config-emit_upstart ran successfully
2018-02-22 04:10:51,467 - stages.py[DEBUG]: Running module ssh-import-id (<module 'cloudinit.config.cc_ssh_import_id' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_ssh_import_id.py'>) with frequency once-per-instance
2018-02-22 04:10:51,469 - handlers.py[DEBUG]: start: modules-config/config-ssh-import-id: running config-ssh-import-id with frequency once-per-instance
2018-02-22 04:10:51,470 - helpers.py[DEBUG]: config-ssh-import-id already ran (freq=once-per-instance)
2018-02-22 04:10:51,470 - handlers.py[DEBUG]: finish: modules-config/config-ssh-import-id: SUCCESS: config-ssh-import-id previously ran
2018-02-22 04:10:51,470 - stages.py[DEBUG]: Running module locale (<module 'cloudinit.config.cc_locale' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_locale.py'>) with frequency once-per-instance
2018-02-22 04:10:51,472 - handlers.py[DEBUG]: start: modules-config/config-locale: running config-locale with frequency once-per-instance
2018-02-22 04:10:51,472 - helpers.py[DEBUG]: config-locale already ran (freq=once-per-instance)
2018-02-22 04:10:51,473 - handlers.py[DEBUG]: finish: modules-config/config-locale: SUCCESS: config-locale previously ran
2018-02-22 04:10:51,473 - stages.py[DEBUG]: Running module set-passwords (<module 'cloudinit.config.cc_set_passwords' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_set_passwords.py'>) with frequency once-per-instance
2018-02-22 04:10:51,475 - handlers.py[DEBUG]: start: modules-config/config-set-passwords: running config-set-passwords with frequency once-per-instance
2018-02-22 04:10:51,475 - helpers.py[DEBUG]: config-set-passwords already ran (freq=once-per-instance)
2018-02-22 04:10:51,476 - handlers.py[DEBUG]: finish: modules-config/config-set-passwords: SUCCESS: config-set-passwords previously ran
2018-02-22 04:10:51,476 - stages.py[DEBUG]: Running module grub-dpkg (<module 'cloudinit.config.cc_grub_dpkg' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_grub_dpkg.py'>) with frequency once-per-instance
2018-02-22 04:10:51,478 - handlers.py[DEBUG]: start: modules-config/config-grub-dpkg: running config-grub-dpkg with frequency once-per-instance
2018-02-22 04:10:51,478 - helpers.py[DEBUG]: config-grub-dpkg already ran (freq=once-per-instance)
2018-02-22 04:10:51,479 - handlers.py[DEBUG]: finish: modules-config/config-grub-dpkg: SUCCESS: config-grub-dpkg previously ran
2018-02-22 04:10:51,479 - stages.py[DEBUG]: Running module apt-pipelining (<module 'cloudinit.config.cc_apt_pipelining' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_apt_pipelining.py'>) with frequency once-per-instance
2018-02-22 04:10:51,480 - handlers.py[DEBUG]: start: modules-config/config-apt-pipelining: running config-apt-pipelining with frequency once-per-instance
2018-02-22 04:10:51,481 - helpers.py[DEBUG]: config-apt-pipelining already ran (freq=once-per-instance)
2018-02-22 04:10:51,481 - handlers.py[DEBUG]: finish: modules-config/config-apt-pipelining: SUCCESS: config-apt-pipelining previously ran
2018-02-22 04:10:51,482 - stages.py[DEBUG]: Running module apt-configure (<module 'cloudinit.config.cc_apt_configure' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_apt_configure.py'>) with frequency once-per-instance
2018-02-22 04:10:51,483 - handlers.py[DEBUG]: start: modules-config/config-apt-configure: running config-apt-configure with frequency once-per-instance
2018-02-22 04:10:51,484 - helpers.py[DEBUG]: config-apt-configure already ran (freq=once-per-instance)
2018-02-22 04:10:51,484 - handlers.py[DEBUG]: finish: modules-config/config-apt-configure: SUCCESS: config-apt-configure previously ran
2018-02-22 04:10:51,484 - stages.py[DEBUG]: Running module ntp (<module 'cloudinit.config.cc_ntp' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_ntp.py'>) with frequency once-per-instance
2018-02-22 04:10:51,486 - handlers.py[DEBUG]: start: modules-config/config-ntp: running config-ntp with frequency once-per-instance
2018-02-22 04:10:51,487 - helpers.py[DEBUG]: config-ntp already ran (freq=once-per-instance)
2018-02-22 04:10:51,487 - handlers.py[DEBUG]: finish: modules-config/config-ntp: SUCCESS: config-ntp previously ran
2018-02-22 04:10:51,487 - stages.py[DEBUG]: Running module timezone (<module 'cloudinit.config.cc_timezone' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_timezone.py'>) with frequency once-per-instance
2018-02-22 04:10:51,489 - handlers.py[DEBUG]: start: modules-config/config-timezone: running config-timezone with frequency once-per-instance
2018-02-22 04:10:51,489 - helpers.py[DEBUG]: config-timezone already ran (freq=once-per-instance)
2018-02-22 04:10:51,490 - handlers.py[DEBUG]: finish: modules-config/config-timezone: SUCCESS: config-timezone previously ran
2018-02-22 04:10:51,490 - stages.py[DEBUG]: Running module disable-ec2-metadata (<module 'cloudinit.config.cc_disable_ec2_metadata' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_disable_ec2_metadata.py'>) with frequency always
2018-02-22 04:10:51,492 - handlers.py[DEBUG]: start: modules-config/config-disable-ec2-metadata: running config-disable-ec2-metadata with frequency always
2018-02-22 04:10:51,492 - helpers.py[DEBUG]: Running config-disable-ec2-metadata using lock (<cloudinit.helpers.DummyLock object at 0x75c764d0>)
2018-02-22 04:10:51,492 - cc_disable_ec2_metadata.py[DEBUG]: Skipping module named disable-ec2-metadata, disabling the ec2 route not enabled
2018-02-22 04:10:51,493 - handlers.py[DEBUG]: finish: modules-config/config-disable-ec2-metadata: SUCCESS: config-disable-ec2-metadata ran successfully
2018-02-22 04:10:51,493 - stages.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
2018-02-22 04:10:51,495 - handlers.py[DEBUG]: start: modules-config/config-runcmd: running config-runcmd with frequency once-per-instance
2018-02-22 04:10:51,495 - helpers.py[DEBUG]: config-runcmd already ran (freq=once-per-instance)
2018-02-22 04:10:51,496 - handlers.py[DEBUG]: finish: modules-config/config-runcmd: SUCCESS: config-runcmd previously ran
2018-02-22 04:10:51,496 - stages.py[DEBUG]: Running module byobu (<module 'cloudinit.config.cc_byobu' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_byobu.py'>) with frequency once-per-instance
2018-02-22 04:10:51,498 - handlers.py[DEBUG]: start: modules-config/config-byobu: running config-byobu with frequency once-per-instance
2018-02-22 04:10:51,498 - helpers.py[DEBUG]: config-byobu already ran (freq=once-per-instance)
2018-02-22 04:10:51,498 - handlers.py[DEBUG]: finish: modules-config/config-byobu: SUCCESS: config-byobu previously ran
2018-02-22 04:10:51,499 - main.py[DEBUG]: Ran 12 modules with 0 failures
2018-02-22 04:10:51,501 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2018-02-22 04:10:51,502 - util.py[DEBUG]: Read 12 bytes from /proc/uptime
2018-02-22 04:10:51,502 - util.py[DEBUG]: cloud-init mode 'modules' took 1.010 seconds (1.01)
2018-02-22 04:10:51,503 - handlers.py[DEBUG]: finish: modules-config: SUCCESS: running modules for config
2018-02-22 04:10:54,718 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'modules:final' at Thu, 22 Feb 2018 04:10:54 +0000. Up 32.77 seconds.
2018-02-22 04:10:54,831 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'>
2018-02-22 04:10:54,836 - stages.py[DEBUG]: Running module package-update-upgrade-install (<module 'cloudinit.config.cc_package_update_upgrade_install' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_package_update_upgrade_install.py'>) with frequency once-per-instance
2018-02-22 04:10:54,838 - handlers.py[DEBUG]: start: modules-final/config-package-update-upgrade-install: running config-package-update-upgrade-install with frequency once-per-instance
2018-02-22 04:10:54,839 - helpers.py[DEBUG]: config-package-update-upgrade-install already ran (freq=once-per-instance)
2018-02-22 04:10:54,839 - handlers.py[DEBUG]: finish: modules-final/config-package-update-upgrade-install: SUCCESS: config-package-update-upgrade-install previously ran
2018-02-22 04:10:54,839 - stages.py[DEBUG]: Running module fan (<module 'cloudinit.config.cc_fan' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_fan.py'>) with frequency once-per-instance
2018-02-22 04:10:54,841 - handlers.py[DEBUG]: start: modules-final/config-fan: running config-fan with frequency once-per-instance
2018-02-22 04:10:54,842 - helpers.py[DEBUG]: config-fan already ran (freq=once-per-instance)
2018-02-22 04:10:54,842 - handlers.py[DEBUG]: finish: modules-final/config-fan: SUCCESS: config-fan previously ran
2018-02-22 04:10:54,842 - stages.py[DEBUG]: Running module puppet (<module 'cloudinit.config.cc_puppet' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_puppet.py'>) with frequency once-per-instance
2018-02-22 04:10:54,844 - handlers.py[DEBUG]: start: modules-final/config-puppet: running config-puppet with frequency once-per-instance
2018-02-22 04:10:54,844 - helpers.py[DEBUG]: config-puppet already ran (freq=once-per-instance)
2018-02-22 04:10:54,845 - handlers.py[DEBUG]: finish: modules-final/config-puppet: SUCCESS: config-puppet previously ran
2018-02-22 04:10:54,845 - stages.py[DEBUG]: Running module chef (<module 'cloudinit.config.cc_chef' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_chef.py'>) with frequency once-per-instance
2018-02-22 04:10:54,847 - handlers.py[DEBUG]: start: modules-final/config-chef: running config-chef with frequency once-per-instance
2018-02-22 04:10:54,847 - helpers.py[DEBUG]: config-chef already ran (freq=once-per-instance)
2018-02-22 04:10:54,848 - handlers.py[DEBUG]: finish: modules-final/config-chef: SUCCESS: config-chef previously ran
2018-02-22 04:10:54,848 - stages.py[DEBUG]: Running module salt-minion (<module 'cloudinit.config.cc_salt_minion' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_salt_minion.py'>) with frequency once-per-instance
2018-02-22 04:10:54,850 - handlers.py[DEBUG]: start: modules-final/config-salt-minion: running config-salt-minion with frequency once-per-instance
2018-02-22 04:10:54,850 - helpers.py[DEBUG]: config-salt-minion already ran (freq=once-per-instance)
2018-02-22 04:10:54,851 - handlers.py[DEBUG]: finish: modules-final/config-salt-minion: SUCCESS: config-salt-minion previously ran
2018-02-22 04:10:54,851 - stages.py[DEBUG]: Running module mcollective (<module 'cloudinit.config.cc_mcollective' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_mcollective.py'>) with frequency once-per-instance
2018-02-22 04:10:54,853 - handlers.py[DEBUG]: start: modules-final/config-mcollective: running config-mcollective with frequency once-per-instance
2018-02-22 04:10:54,853 - helpers.py[DEBUG]: config-mcollective already ran (freq=once-per-instance)
2018-02-22 04:10:54,853 - handlers.py[DEBUG]: finish: modules-final/config-mcollective: SUCCESS: config-mcollective previously ran
2018-02-22 04:10:54,854 - stages.py[DEBUG]: Running module rightscale_userdata (<module 'cloudinit.config.cc_rightscale_userdata' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_rightscale_userdata.py'>) with frequency once-per-instance
2018-02-22 04:10:54,856 - handlers.py[DEBUG]: start: modules-final/config-rightscale_userdata: running config-rightscale_userdata with frequency once-per-instance
2018-02-22 04:10:54,856 - helpers.py[DEBUG]: config-rightscale_userdata already ran (freq=once-per-instance)
2018-02-22 04:10:54,856 - handlers.py[DEBUG]: finish: modules-final/config-rightscale_userdata: SUCCESS: config-rightscale_userdata previously ran
2018-02-22 04:10:54,857 - stages.py[DEBUG]: Running module scripts-vendor (<module 'cloudinit.config.cc_scripts_vendor' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_scripts_vendor.py'>) with frequency once-per-instance
2018-02-22 04:10:54,858 - handlers.py[DEBUG]: start: modules-final/config-scripts-vendor: running config-scripts-vendor with frequency once-per-instance
2018-02-22 04:10:54,859 - helpers.py[DEBUG]: config-scripts-vendor already ran (freq=once-per-instance)
2018-02-22 04:10:54,859 - handlers.py[DEBUG]: finish: modules-final/config-scripts-vendor: SUCCESS: config-scripts-vendor previously ran
2018-02-22 04:10:54,860 - stages.py[DEBUG]: Running module scripts-per-once (<module 'cloudinit.config.cc_scripts_per_once' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_scripts_per_once.py'>) with frequency once
2018-02-22 04:10:54,861 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-once: running config-scripts-per-once with frequency once
2018-02-22 04:10:54,862 - helpers.py[DEBUG]: config-scripts-per-once already ran (freq=once)
2018-02-22 04:10:54,862 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-once: SUCCESS: config-scripts-per-once previously ran
2018-02-22 04:10:54,862 - stages.py[DEBUG]: Running module scripts-per-boot (<module 'cloudinit.config.cc_scripts_per_boot' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_scripts_per_boot.py'>) with frequency always
2018-02-22 04:10:54,864 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-boot: running config-scripts-per-boot with frequency always
2018-02-22 04:10:54,864 - helpers.py[DEBUG]: Running config-scripts-per-boot using lock (<cloudinit.helpers.DummyLock object at 0x75c9dcb0>)
2018-02-22 04:10:54,866 - util.py[DEBUG]: Running command ['/var/lib/cloud/scripts/per-boot/00_run-parts.sh'] with allowed return codes [0] (shell=False, capture=False)
2018-02-22 04:10:54,981 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-boot: SUCCESS: config-scripts-per-boot ran successfully
2018-02-22 04:10:54,981 - stages.py[DEBUG]: Running module scripts-per-instance (<module 'cloudinit.config.cc_scripts_per_instance' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_scripts_per_instance.py'>) with frequency once-per-instance
2018-02-22 04:10:54,983 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-instance: running config-scripts-per-instance with frequency once-per-instance
2018-02-22 04:10:54,984 - helpers.py[DEBUG]: config-scripts-per-instance already ran (freq=once-per-instance)
2018-02-22 04:10:54,984 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-instance: SUCCESS: config-scripts-per-instance previously ran
2018-02-22 04:10:54,985 - stages.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
2018-02-22 04:10:54,986 - handlers.py[DEBUG]: start: modules-final/config-scripts-user: running config-scripts-user with frequency once-per-instance
2018-02-22 04:10:54,987 - helpers.py[DEBUG]: config-scripts-user already ran (freq=once-per-instance)
2018-02-22 04:10:54,987 - handlers.py[DEBUG]: finish: modules-final/config-scripts-user: SUCCESS: config-scripts-user previously ran
2018-02-22 04:10:54,987 - stages.py[DEBUG]: Running module ssh-authkey-fingerprints (<module 'cloudinit.config.cc_ssh_authkey_fingerprints' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_ssh_authkey_fingerprints.py'>) with frequency once-per-instance
2018-02-22 04:10:54,989 - handlers.py[DEBUG]: start: modules-final/config-ssh-authkey-fingerprints: running config-ssh-authkey-fingerprints with frequency once-per-instance
2018-02-22 04:10:54,990 - helpers.py[DEBUG]: config-ssh-authkey-fingerprints already ran (freq=once-per-instance)
2018-02-22 04:10:54,990 - handlers.py[DEBUG]: finish: modules-final/config-ssh-authkey-fingerprints: SUCCESS: config-ssh-authkey-fingerprints previously ran
2018-02-22 04:10:54,990 - stages.py[DEBUG]: Running module keys-to-console (<module 'cloudinit.config.cc_keys_to_console' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_keys_to_console.py'>) with frequency once-per-instance
2018-02-22 04:10:54,992 - handlers.py[DEBUG]: start: modules-final/config-keys-to-console: running config-keys-to-console with frequency once-per-instance
2018-02-22 04:10:54,992 - helpers.py[DEBUG]: config-keys-to-console already ran (freq=once-per-instance)
2018-02-22 04:10:54,993 - handlers.py[DEBUG]: finish: modules-final/config-keys-to-console: SUCCESS: config-keys-to-console previously ran
2018-02-22 04:10:54,993 - stages.py[DEBUG]: Running module phone-home (<module 'cloudinit.config.cc_phone_home' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_phone_home.py'>) with frequency once-per-instance
2018-02-22 04:10:54,995 - handlers.py[DEBUG]: start: modules-final/config-phone-home: running config-phone-home with frequency once-per-instance
2018-02-22 04:10:54,995 - helpers.py[DEBUG]: config-phone-home already ran (freq=once-per-instance)
2018-02-22 04:10:54,996 - handlers.py[DEBUG]: finish: modules-final/config-phone-home: SUCCESS: config-phone-home previously ran
2018-02-22 04:10:54,996 - stages.py[DEBUG]: Running module final-message (<module 'cloudinit.config.cc_final_message' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_final_message.py'>) with frequency always
2018-02-22 04:10:54,998 - handlers.py[DEBUG]: start: modules-final/config-final-message: running config-final-message with frequency always
2018-02-22 04:10:54,998 - helpers.py[DEBUG]: Running config-final-message using lock (<cloudinit.helpers.DummyLock object at 0x75c662b0>)
2018-02-22 04:10:54,999 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2018-02-22 04:10:54,999 - util.py[DEBUG]: Read 12 bytes from /proc/uptime
2018-02-22 04:10:55,020 - util.py[DEBUG]: Cloud-init v. 0.7.9 finished at Thu, 22 Feb 2018 04:10:55 +0000. Datasource DataSourceNoCloud [seed=ds_config_seedfrom,/boot/][dsmode=net].  Up 33.45 seconds
2018-02-22 04:10:55,021 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/boot-finished - wb: [420] 51 bytes
2018-02-22 04:10:55,025 - handlers.py[DEBUG]: finish: modules-final/config-final-message: SUCCESS: config-final-message ran successfully
2018-02-22 04:10:55,025 - stages.py[DEBUG]: Running module power-state-change (<module 'cloudinit.config.cc_power_state_change' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_power_state_change.py'>) with frequency once-per-instance
2018-02-22 04:10:55,027 - handlers.py[DEBUG]: start: modules-final/config-power-state-change: running config-power-state-change with frequency once-per-instance
2018-02-22 04:10:55,027 - helpers.py[DEBUG]: config-power-state-change already ran (freq=once-per-instance)
2018-02-22 04:10:55,028 - handlers.py[DEBUG]: finish: modules-final/config-power-state-change: SUCCESS: config-power-state-change previously ran
2018-02-22 04:10:55,028 - main.py[DEBUG]: Ran 17 modules with 0 failures
2018-02-22 04:10:55,032 - util.py[DEBUG]: Creating symbolic link from '/run/cloud-init/result.json' => '../../var/lib/cloud/data/result.json'
2018-02-22 04:10:55,033 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2018-02-22 04:10:55,033 - util.py[DEBUG]: Read 12 bytes from /proc/uptime
2018-02-22 04:10:55,034 - util.py[DEBUG]: cloud-init mode 'modules' took 0.719 seconds (0.72)
2018-02-22 04:10:55,034 - handlers.py[DEBUG]: finish: modules-final: SUCCESS: running modules for final