Re: Fixes for cloud-init in Debian Stretch

Hello Noah,

Problem happens on every new launch of ASG instance. Started to happen with upgrade to Debian 9.7 i guess.

During startup we execute salt that cleans default admin user, but that was always there and worked fine until latest Debian upgrades from 9.6 to 9.7 and then 9.8.

Also salt should be executed after ssh key step.

Please also check cloud-init logs attached. I stripped out salt part as it contains some sensitive information.

Regards,

Konstantin

web: www.prolinux.org

im: http://t.me/bamaboy

On Thu, 21 Feb 2019 at 19:31, Noah Meyerhans <noahm@debian.org> wrote:

On Wed, Feb 20, 2019 at 05:17:11PM +0100, Konstantin wrote:
> Seems that Debian Stretch suffers from this
> bug [1]https://bugzilla.redhat.com/show_bug.cgi?id=1430511
> Please check if this patch can be added to cloud-init
> package [2]https://github.com/larsks/cloud-init/commit/3f8d6dbbbc9ab4679a4820d7cc60265fa67807cd
> Affected cloud-init version is 0.7.9-2
> Error from AWS instance:
> 2019-02-20 13:44:29,180 - util.py[WARNING]: 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'>)
> failed

How often does this problem happen for you? I build the Amazon EC2 AMIs
and use them quite regularly, and have never encountered this problem.
So unless there's something non-deterministic about systemd's dependency
handling, I don't think this is your issue.

Are you able to extract the contents /var/log/cloud-init-output.log from
your instances? I'd be curious to see if it provides more insight into
what's failing.

noah

Cloud-init v. 0.7.9 running 'init-local' at Wed, 13 Feb 2019 12:00:00 +0000. Up 1.91 seconds. Cloud-init v. 0.7.9 running 'init' at Wed, 13 Feb 2019 12:00:03 +0000. Up 4.84 seconds. ci-info: ++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++ ci-info: +--------+------+--------------+---------------+-------+-------------------+ ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | ci-info: +--------+------+--------------+---------------+-------+-------------------+ ci-info: | lo: | True | 127.0.0.1 | 255.0.0.0 | . | . | ci-info: | lo: | True | . | . | d | . | ci-info: | eth0: | True | 172.16.65.81 | 255.255.255.0 | . | 02:c1:d0:c5:77:d6 | ci-info: | eth0: | True | . | . | d | 02:c1:d0:c5:77:d6 | ci-info: +--------+------+--------------+---------------+-------+-------------------+ ci-info: +++++++++++++++++++++++++++++Route IPv4 info+++++++++++++++++++++++++++++ ci-info: +-------+-------------+-------------+---------------+-----------+-------+ ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | ci-info: +-------+-------------+-------------+---------------+-----------+-------+ ci-info: | 0 | 0.0.0.0 | 172.16.65.1 | 0.0.0.0 | eth0 | UG | ci-info: | 1 | 172.16.65.0 | 0.0.0.0 | 255.255.255.0 | eth0 | U | ci-info: +-------+-------------+-------------+---------------+-----------+-------+ 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:MegWYg6TeUe1Xlvoosev8TbKkeNoax0u4AunTWuxBOY root@ip-172-16-65-81 The key's randomart image is: +---[RSA 2048]----+ | ... | | o . . . . | | = + + + o . | | o* + o = o | | o .. o S o | | E +. o.o | | .oo+.oB. | | *+.+=o*o | | ..++oo=+o. | +----[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:8x5YgI5BGbZPfTQTV5Pk8UpRIbY3kT2ShHu7B1narzo root@ip-172-16-65-81 The key's randomart image is: +---[DSA 1024]----+ | +o =.+*B==| | o.. o . =.++Bo| | o o o . ..+oo| | * o . o.o.| | . o S . . B | | = = . | | . o o .| | . .E. ..| | . .oo. | +----[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:hINDqlbtYUudbo0+jbIxVhKuD9Y+dqvp5r7U9MEYCmg root@ip-172-16-65-81 The key's randomart image is: +---[ECDSA 256]---+ | . | | .o..... | | E.oo*o+. | |... *.*o* | |.. * BS+ | |. o B + . | | + B = 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:GmfQp9jSUh6kulA3RiTClBpKTTKO6DAke2CscYNa4ic root@ip-172-16-65-81 The key's randomart image is: +--[ED25519 256]--+ |+O=o..o . | |%=Oo o + | |%O... * + . | |BE o + O + | | .+ . = S | | . . B | | . . | | | | | +----[SHA256]-----+ Generating locales (this might take a while)... en_US.UTF-8... done Generation complete. Cloud-init v. 0.7.9 running 'modules:config' at Wed, 13 Feb 2019 12:00:05 +0000. Up 6.78 seconds. Cloud-init v. 0.7.9 running 'modules:final' at Wed, 13 Feb 2019 12:00:07 +0000. Up 8.26 seconds. Cloud-init v. 0.7.9 finished at Wed, 13 Feb 2019 12:00:07 +0000. Datasource DataSourceEc2. Up 8.51 seconds Cloud-init v. 0.7.9 running 'init-local' at Fri, 22 Feb 2019 16:21:00 +0000. Up 8.94 seconds. Cloud-init v. 0.7.9 running 'init' at Fri, 22 Feb 2019 16:21:03 +0000. Up 11.35 seconds. ci-info: ++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++ ci-info: +--------+------+--------------+---------------+-------+-------------------+ ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | ci-info: +--------+------+--------------+---------------+-------+-------------------+ ci-info: | lo: | True | 127.0.0.1 | 255.0.0.0 | . | . | ci-info: | lo: | True | . | . | d | . | ci-info: | eth0: | True | 172.18.5.192 | 255.255.255.0 | . | 06:9f:55:76:3d:e0 | ci-info: | eth0: | True | . | . | d | 06:9f:55:76:3d:e0 | ci-info: +--------+------+--------------+---------------+-------+-------------------+ ci-info: ++++++++++++++++++++++++++++Route IPv4 info+++++++++++++++++++++++++++++ ci-info: +-------+-------------+------------+---------------+-----------+-------+ ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | ci-info: +-------+-------------+------------+---------------+-----------+-------+ ci-info: | 0 | 0.0.0.0 | 172.18.5.1 | 0.0.0.0 | eth0 | UG | ci-info: | 1 | 172.18.5.0 | 0.0.0.0 | 255.255.255.0 | eth0 | U | ci-info: +-------+-------------+------------+---------------+-----------+-------+ 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:v/qFzSrgN2jM6mC0bHLfMKNA+PIKb37Mq9lqcGagrWo root@ip-172-18-5-192 The key's randomart image is: +---[RSA 2048]----+ | | | | | | |o | |o+. S | |++=. . . + | |=*Oo++ o o + | |oEo*+=* + + | |==O=*+...=+ | +----[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:ck1WEQ31A8Opt6lWnU2pPnM4K+UchQjeWUqdZ/YL8Rk root@ip-172-18-5-192 The key's randomart image is: +---[DSA 1024]----+ | BO+ | | . o B+E | | . * * B.*| | = * + =+| | . S . . B.+| | o B +.| | B 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:WR4AIEGaJk0531KWG/yjABFesJk5wQRKm1URIrPixec root@ip-172-18-5-192 The key's randomart image is: +---[ECDSA 256]---+ |.O@O+*+o. | |o*&O. * . | |*=O* = + o | |= ..* o o+ . | | . E .S.. | | . | | | | | | | +----[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:OVUEX841vh3qiYjKiD8hcVsRh7BGcqjwxgE8wNEhN04 root@ip-172-18-5-192 The key's randomart image is: +--[ED25519 256]--+ |*=+Eo.o. .oo ...| |.=X.oo. o +...| |oo.= . . . oo | |..=. . o . +| | .o o S . ..| | . o ... o . | | . . . . . o | | ..o . | | ..o.o | +----[SHA256]-----+ Generating locales (this might take a while)... en_US.UTF-8... done Generation complete. Cloud-init v. 0.7.9 running 'modules:config' at Fri, 22 Feb 2019 16:21:26 +0000. Up 34.14 seconds. Get:1 http://security.debian.org stretch/updates InRelease [94.3 kB] Ign:2 http://cloudfront.debian.net/debian stretch InRelease Get:3 http://cloudfront.debian.net/debian stretch-updates InRelease [91.0 kB] Get:4 http://cloudfront.debian.net/debian stretch-backports InRelease [91.8 kB] Get:5 http://apt.auto1.team stretch InRelease [7,223 B] Get:6 http://cloudfront.debian.net/debian stretch Release [118 kB] Get:7 https://download.docker.com/linux/debian stretch InRelease [44.8 kB] Get:8 http://cloudfront.debian.net/debian stretch Release.gpg [2,434 B] Ign:9 https://artifacts.elastic.co/packages/6.x/apt stable InRelease Get:10 https://artifacts.elastic.co/packages/6.x/apt stable Release [5,116 B] Hit:11 http://repo.saltstack.com/apt/debian/9/amd64/2017.7 stretch InRelease Get:12 https://artifacts.elastic.co/packages/6.x/apt stable Release.gpg [473 B] Get:13 http://cloudfront.debian.net/debian stretch-updates/main amd64 Packages.diff/Index [7,624 B] Get:14 http://cloudfront.debian.net/debian stretch-updates/main Translation-en.diff/Index [4,672 B] Get:15 http://cloudfront.debian.net/debian stretch-updates/main amd64 Contents (deb).diff/Index [6,640 B] Get:16 http://cloudfront.debian.net/debian stretch-updates/main amd64 Packages 2019-02-21-2009.35.pdiff [4,149 B] Get:17 http://security.debian.org stretch/updates/main amd64 Packages [474 kB] Get:18 http://security.debian.org stretch/updates/main Translation-en [210 kB] Get:19 http://security.debian.org stretch/updates/contrib amd64 Packages [1,760 B] Get:20 http://apt.auto1.team stretch/main amd64 Packages [13.4 kB] Get:21 http://cloudfront.debian.net/debian stretch-updates/main Translation-en 2019-02-21-2009.35.pdiff [5,483 B] Get:16 http://cloudfront.debian.net/debian stretch-updates/main amd64 Packages 2019-02-21-2009.35.pdiff [4,149 B] Get:21 http://cloudfront.debian.net/debian stretch-updates/main Translation-en 2019-02-21-2009.35.pdiff [5,483 B] Get:22 http://cloudfront.debian.net/debian stretch-backports/main amd64 Packages.diff/Index [27.8 kB] Get:23 http://cloudfront.debian.net/debian stretch-backports/main Translation-en.diff/Index [27.8 kB] Get:24 http://cloudfront.debian.net/debian stretch-backports/main amd64 Contents (deb).diff/Index [28.0 kB] Get:25 https://download.docker.com/linux/debian stretch/stable amd64 Packages [6,830 B] Get:26 http://cloudfront.debian.net/debian stretch-backports/contrib amd64 Packages.diff/Index [27.8 kB] Get:27 https://artifacts.elastic.co/packages/6.x/apt stable/main amd64 Packages [41.2 kB] Get:28 http://cloudfront.debian.net/debian stretch-backports/contrib Translation-en.diff/Index [7,132 B] Get:29 http://cloudfront.debian.net/debian stretch-backports/contrib amd64 Contents (deb).diff/Index [19.4 kB] Get:30 http://cloudfront.debian.net/debian stretch-updates/main amd64 Contents (deb) 2019-02-21-2009.35.pdiff [327 kB] Get:30 http://cloudfront.debian.net/debian stretch-updates/main amd64 Contents (deb) 2019-02-21-2009.35.pdiff [327 kB] Get:31 http://cloudfront.debian.net/debian stretch-backports/main amd64 Packages 2019-02-13-1415.43.pdiff [1,429 B] Get:32 http://cloudfront.debian.net/debian stretch-backports/main amd64 Packages 2019-02-13-2020.07.pdiff [2,363 B] Get:33 http://cloudfront.debian.net/debian stretch-backports/main amd64 Packages 2019-02-14-0214.01.pdiff [788 B] Get:34 http://cloudfront.debian.net/debian stretch-backports/main amd64 Packages 2019-02-14-0817.45.pdiff [471 B] Get:35 http://cloudfront.debian.net/debian stretch-backports/main amd64 Packages 2019-02-15-1412.52.pdiff [448 B] Get:36 http://cloudfront.debian.net/debian stretch-backports/main amd64 Packages 2019-02-17-1416.05.pdiff [224 B] Get:37 http://cloudfront.debian.net/debian stretch-backports/main amd64 Packages 2019-02-18-0809.24.pdiff [643 B] Get:38 http://cloudfront.debian.net/debian stretch-backports/main amd64 Packages 2019-02-18-1416.48.pdiff [223 B] Get:39 http://cloudfront.debian.net/debian stretch-backports/main amd64 Packages 2019-02-20-0217.52.pdiff [1,358 B] Get:40 http://cloudfront.debian.net/debian stretch-backports/main amd64 Packages 2019-02-21-0209.55.pdiff [623 B] Get:41 http://cloudfront.debian.net/debian stretch-backports/main amd64 Packages 2019-02-21-1412.34.pdiff [81 B] Get:42 http://cloudfront.debian.net/debian stretch-backports/main amd64 Packages 2019-02-21-2009.35.pdiff [1,134 B] Get:42 http://cloudfront.debian.net/debian stretch-backports/main amd64 Packages 2019-02-21-2009.35.pdiff [1,134 B] Get:43 http://cloudfront.debian.net/debian stretch-backports/main Translation-en 2019-02-13-2020.07.pdiff [1,934 B] Get:44 http://cloudfront.debian.net/debian stretch-backports/main Translation-en 2019-02-20-0217.52.pdiff [330 B] Get:45 http://cloudfront.debian.net/debian stretch-backports/main Translation-en 2019-02-21-1412.34.pdiff [152 B] Get:46 http://cloudfront.debian.net/debian stretch-backports/main Translation-en 2019-02-22-0208.16.pdiff [276 B] Get:47 http://cloudfront.debian.net/debian stretch-backports/main Translation-en 2019-02-22-0809.15.pdiff [46 B] Get:47 http://cloudfront.debian.net/debian stretch-backports/main Translation-en 2019-02-22-0809.15.pdiff [46 B] Get:48 http://cloudfront.debian.net/debian stretch-backports/main amd64 Contents (deb) 2019-02-13-1415.43.pdiff [5,114 B] Get:49 http://cloudfront.debian.net/debian stretch-backports/main amd64 Contents (deb) 2019-02-13-2020.07.pdiff [71.7 kB] Get:50 http://cloudfront.debian.net/debian stretch-backports/main amd64 Contents (deb) 2019-02-14-0214.01.pdiff [277 B] Get:51 http://cloudfront.debian.net/debian stretch-backports/main amd64 Contents (deb) 2019-02-14-0817.45.pdiff [183 B] Get:52 http://cloudfront.debian.net/debian stretch-backports/main amd64 Contents (deb) 2019-02-15-1412.52.pdiff [71 B] Get:53 http://cloudfront.debian.net/debian stretch-backports/main amd64 Contents (deb) 2019-02-17-1416.05.pdiff [28 B] Get:54 http://cloudfront.debian.net/debian stretch-backports/main amd64 Contents (deb) 2019-02-18-0809.24.pdiff [1,478 B] Get:55 http://cloudfront.debian.net/debian stretch-backports/main amd64 Contents (deb) 2019-02-18-1416.48.pdiff [100 B] Get:56 http://cloudfront.debian.net/debian stretch-backports/main amd64 Contents (deb) 2019-02-20-0217.52.pdiff [933 B] Get:57 http://cloudfront.debian.net/debian stretch-backports/main amd64 Contents (deb) 2019-02-21-0209.55.pdiff [364 B] Get:58 http://cloudfront.debian.net/debian stretch-backports/main amd64 Contents (deb) 2019-02-21-1412.34.pdiff [142 B] Get:58 http://cloudfront.debian.net/debian stretch-backports/main amd64 Contents (deb) 2019-02-21-1412.34.pdiff [142 B] Get:59 http://cloudfront.debian.net/debian stretch-backports/contrib amd64 Packages 2019-02-13-2020.07.pdiff [3,454 B] Get:60 http://cloudfront.debian.net/debian stretch-backports/contrib amd64 Packages 2019-02-18-0809.24.pdiff [2,346 B] Get:60 http://cloudfront.debian.net/debian stretch-backports/contrib amd64 Packages 2019-02-18-0809.24.pdiff [2,346 B] Get:61 http://cloudfront.debian.net/debian stretch-backports/contrib Translation-en 2019-02-13-2020.07.pdiff [662 B] Get:61 http://cloudfront.debian.net/debian stretch-backports/contrib Translation-en 2019-02-13-2020.07.pdiff [662 B] Get:62 http://cloudfront.debian.net/debian stretch-backports/contrib amd64 Contents (deb) 2019-02-13-2020.07.pdiff [6,622 B] Get:63 http://cloudfront.debian.net/debian stretch-backports/contrib amd64 Contents (deb) 2019-02-18-0809.24.pdiff [4,665 B] Get:63 http://cloudfront.debian.net/debian stretch-backports/contrib amd64 Contents (deb) 2019-02-18-0809.24.pdiff [4,665 B] Get:64 http://cloudfront.debian.net/debian stretch/main amd64 Packages [7,084 kB] Get:65 http://cloudfront.debian.net/debian stretch/main Translation-en [5,384 kB] Get:66 http://cloudfront.debian.net/debian stretch/main amd64 Contents (deb) [31.4 MB] Get:67 http://cloudfront.debian.net/debian stretch/contrib amd64 Packages [50.9 kB] Get:68 http://cloudfront.debian.net/debian stretch/contrib amd64 Contents (deb) [90.3 kB] Get:69 http://cloudfront.debian.net/debian stretch/non-free amd64 Packages [78.3 kB] Get:70 http://cloudfront.debian.net/debian stretch/non-free Translation-en [80.3 kB] Get:71 http://cloudfront.debian.net/debian stretch/non-free amd64 Contents (deb) [809 kB] Fetched 46.8 MB in 10s (4,289 kB/s) Reading package lists... Reading package lists... Building dependency tree... Reading state information... nfs-common is already the newest version (1:1.3.4-2.1). The following packages were automatically installed and are no longer required: libtomcrypt0 libtommath1 Use 'apt autoremove' to remove them. 0 upgraded, 0 newly installed, 0 to remove and 34 not upgraded. Cloud-init v. 0.7.9 running 'modules:final' at Fri, 22 Feb 2019 16:21:30 +0000. Up 38.56 seconds. 2019-02-22 17:23:54,684 - util.py[WARNING]: 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'>) failed Cloud-init v. 0.7.9 finished at Fri, 22 Feb 2019 16:23:54 +0000. Datasource DataSourceEc2. Up 182.68 seconds

2019-02-13 12:00:00,768 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'init-local' at Wed, 13 Feb 2019 12:00:00 +0000. Up 1.91 seconds. 2019-02-13 12:00:00,772 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [420] 0 bytes 2019-02-13 12:00:00,773 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 0:4 2019-02-13 12:00:00,773 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance/boot-finished 2019-02-13 12:00:00,773 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/data/no-net 2019-02-13 12:00:00,773 - handlers.py[DEBUG]: start: init-local/check-cache: attempting to read from cache [check] 2019-02-13 12:00:00,773 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False) 2019-02-13 12:00:00,773 - stages.py[DEBUG]: no cache found 2019-02-13 12:00:00,773 - handlers.py[DEBUG]: finish: init-local/check-cache: SUCCESS: no cache found 2019-02-13 12:00:00,774 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2019-02-13 12:00:00,776 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'> 2019-02-13 12:00:00,777 - __init__.py[DEBUG]: Looking for for data source in: ['Ec2'], via packages ['', 'cloudinit.sources'] that matches dependencies ['FILESYSTEM'] 2019-02-13 12:00:00,778 - __init__.py[DEBUG]: Searching for local data source in: [] 2019-02-13 12:00:00,778 - main.py[DEBUG]: No local datasource found 2019-02-13 12:00:00,779 - stages.py[DEBUG]: network config disabled by system_cfg 2019-02-13 12:00:00,779 - stages.py[INFO]: network config is disabled by system_cfg 2019-02-13 12:00:00,779 - main.py[DEBUG]: [local] Exiting without datasource in local mode 2019-02-13 12:00:00,779 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2019-02-13 12:00:00,780 - util.py[DEBUG]: Read 10 bytes from /proc/uptime 2019-02-13 12:00:00,780 - util.py[DEBUG]: cloud-init mode 'init' took 0.046 seconds (0.05) 2019-02-13 12:00:00,780 - handlers.py[DEBUG]: finish: init-local: SUCCESS: searching for local datasources 2019-02-13 12:00:03,690 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'init' at Wed, 13 Feb 2019 12:00:03 +0000. Up 4.84 seconds. 2019-02-13 12:00:03,692 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [420] 0 bytes 2019-02-13 12:00:03,693 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 0:4 2019-02-13 12:00:03,693 - util.py[DEBUG]: Running command ['ifconfig', '-a'] with allowed return codes [0] (shell=False, capture=True) 2019-02-13 12:00:03,698 - util.py[DEBUG]: Running command ['netstat', '-rn'] with allowed return codes [0] (shell=False, capture=True) 2019-02-13 12:00:03,702 - util.py[DEBUG]: Running command ['netstat', '-A', 'inet6', '-n'] with allowed return codes [0] (shell=False, capture=True) 2019-02-13 12:00:03,705 - main.py[DEBUG]: Checking to see if files that we need already exist from a previous run that would allow us to stop early. 2019-02-13 12:00:03,705 - main.py[DEBUG]: Execution continuing, no previous run detected that would allow us to stop early. 2019-02-13 12:00:03,705 - handlers.py[DEBUG]: start: init-network/check-cache: attempting to read from cache [trust] 2019-02-13 12:00:03,706 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False) 2019-02-13 12:00:03,706 - stages.py[DEBUG]: no cache found 2019-02-13 12:00:03,706 - handlers.py[DEBUG]: finish: init-network/check-cache: SUCCESS: no cache found 2019-02-13 12:00:03,706 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2019-02-13 12:00:03,708 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'> 2019-02-13 12:00:03,708 - __init__.py[DEBUG]: Looking for for data source in: ['Ec2'], via packages ['', 'cloudinit.sources'] that matches dependencies ['FILESYSTEM', 'NETWORK'] 2019-02-13 12:00:03,709 - __init__.py[DEBUG]: Searching for network data source in: ['DataSourceEc2'] 2019-02-13 12:00:03,709 - handlers.py[DEBUG]: start: init-network/search-Ec2: searching for network data from DataSourceEc2 2019-02-13 12:00:03,709 - __init__.py[DEBUG]: Seeing if we can get any data from <class 'cloudinit.sources.DataSourceEc2.DataSourceEc2'> 2019-02-13 12:00:03,710 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/ec2/meta-data (quiet=False) 2019-02-13 12:00:03,819 - DataSourceEc2.py[DEBUG]: Removed the following from metadata urls: ['http://instance-data.:8773'] 2019-02-13 12:00:03,820 - url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'timeout': 50.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,829 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/instance-id (200, 19b) after 1 attempts 2019-02-13 12:00:03,829 - DataSourceEc2.py[DEBUG]: Using metadata source: 'http://169.254.169.254' 2019-02-13 12:00:03,829 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/user-data' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/user-data', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,832 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/user-data (200, 0b) after 1 attempts 2019-02-13 12:00:03,832 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,835 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/ (200, 231b) after 1 attempts 2019-02-13 12:00:03,835 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,837 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ (200, 8b) after 1 attempts 2019-02-13 12:00:03,837 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ami' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ami', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,840 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ami (200, 4b) after 1 attempts 2019-02-13 12:00:03,840 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/root' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/root', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,843 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/root (200, 4b) after 1 attempts 2019-02-13 12:00:03,843 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/placement/' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/placement/', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,846 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/placement/ (200, 17b) after 1 attempts 2019-02-13 12:00:03,846 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/placement/availability-zone' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/placement/availability-zone', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,849 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/placement/availability-zone (200, 13b) after 1 attempts 2019-02-13 12:00:03,849 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/public-keys/' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/public-keys/', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,852 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/public-keys/ (200, 45b) after 1 attempts 2019-02-13 12:00:03,852 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/public-keys/0/openssh-key' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/public-keys/0/openssh-key', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,854 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/public-keys/0/openssh-key (200, 425b) after 1 attempts 2019-02-13 12:00:03,855 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/public-hostname' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/public-hostname', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,857 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/public-hostname (200, 52b) after 1 attempts 2019-02-13 12:00:03,858 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/hostname' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/hostname', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,860 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/hostname (200, 34b) after 1 attempts 2019-02-13 12:00:03,860 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/security-groups' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/security-groups', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,863 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/security-groups (200, 53b) after 1 attempts 2019-02-13 12:00:03,863 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/local-hostname' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/local-hostname', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,865 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/local-hostname (200, 34b) after 1 attempts 2019-02-13 12:00:03,866 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/reservation-id' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/reservation-id', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,868 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/reservation-id (200, 19b) after 1 attempts 2019-02-13 12:00:03,868 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/profile' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/profile', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,871 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/profile (200, 11b) after 1 attempts 2019-02-13 12:00:03,871 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/instance-type' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-type', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,874 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/instance-type (200, 9b) after 1 attempts 2019-02-13 12:00:03,874 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/ami-id' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/ami-id', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,877 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/ami-id (200, 21b) after 1 attempts 2019-02-13 12:00:03,877 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/instance-action' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-action', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,879 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/instance-action (200, 4b) after 1 attempts 2019-02-13 12:00:03,880 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/ami-launch-index' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/ami-launch-index', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,882 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/ami-launch-index (200, 1b) after 1 attempts 2019-02-13 12:00:03,882 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/public-ipv4' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/public-ipv4', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,885 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/public-ipv4 (200, 13b) after 1 attempts 2019-02-13 12:00:03,885 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/local-ipv4' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/local-ipv4', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,888 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/local-ipv4 (200, 12b) after 1 attempts 2019-02-13 12:00:03,888 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,890 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/instance-id (200, 19b) after 1 attempts 2019-02-13 12:00:03,891 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/ami-manifest-path' with {'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}, 'url': 'http://169.254.169.254/2009-04-04/meta-data/ami-manifest-path', 'method': 'GET', 'allow_redirects': True} configuration 2019-02-13 12:00:03,893 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/ami-manifest-path (200, 9b) after 1 attempts 2019-02-13 12:00:03,893 - DataSourceEc2.py[DEBUG]: Crawl of metadata service took 0 seconds 2019-02-13 12:00:03,894 - handlers.py[DEBUG]: finish: init-network/search-Ec2: SUCCESS: found network data from DataSourceEc2 2019-02-13 12:00:03,894 - stages.py[INFO]: Loaded datasource DataSourceEc2 - DataSourceEc2 2019-02-13 12:00:03,894 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2019-02-13 12:00:03,894 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg 2019-02-13 12:00:03,894 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,904 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99-disable-network-config.cfg (quiet=False) 2019-02-13 12:00:03,904 - util.py[DEBUG]: Read 28 bytes from /etc/cloud/cloud.cfg.d/99-disable-network-config.cfg 2019-02-13 12:00:03,904 - util.py[DEBUG]: Attempting to load yaml from string of length 28 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,905 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2019-02-13 12:00:03,905 - util.py[DEBUG]: Read 87 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2019-02-13 12:00:03,905 - util.py[DEBUG]: Attempting to load yaml from string of length 87 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,905 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2019-02-13 12:00:03,906 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2019-02-13 12:00:03,906 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,909 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/01_debian_cloud.cfg (quiet=False) 2019-02-13 12:00:03,909 - util.py[DEBUG]: Read 336 bytes from /etc/cloud/cloud.cfg.d/01_debian_cloud.cfg 2019-02-13 12:00:03,909 - util.py[DEBUG]: Attempting to load yaml from string of length 336 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,912 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False) 2019-02-13 12:00:03,912 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg 2019-02-13 12:00:03,912 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,913 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,913 - util.py[DEBUG]: load_yaml given empty string, returning default 2019-02-13 12:00:03,914 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2019-02-13 12:00:03,914 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/i-01d620471b1d427ac' 2019-02-13 12:00:03,915 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/i-01d620471b1d427ac/datasource (quiet=False) 2019-02-13 12:00:03,915 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/datasource - wb: [420] 29 bytes 2019-02-13 12:00:03,916 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [420] 29 bytes 2019-02-13 12:00:03,916 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False) 2019-02-13 12:00:03,916 - stages.py[DEBUG]: previous iid found to be NO_PREVIOUS_INSTANCE_ID 2019-02-13 12:00:03,916 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [420] 20 bytes 2019-02-13 12:00:03,917 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [420] 20 bytes 2019-02-13 12:00:03,917 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [420] 24 bytes 2019-02-13 12:00:03,918 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [256] 6187 bytes 2019-02-13 12:00:03,918 - main.py[DEBUG]: [net] init will now be targeting instance id: i-01d620471b1d427ac. new=True 2019-02-13 12:00:03,918 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2019-02-13 12:00:03,918 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg 2019-02-13 12:00:03,918 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,928 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99-disable-network-config.cfg (quiet=False) 2019-02-13 12:00:03,928 - util.py[DEBUG]: Read 28 bytes from /etc/cloud/cloud.cfg.d/99-disable-network-config.cfg 2019-02-13 12:00:03,928 - util.py[DEBUG]: Attempting to load yaml from string of length 28 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,929 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2019-02-13 12:00:03,929 - util.py[DEBUG]: Read 87 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2019-02-13 12:00:03,929 - util.py[DEBUG]: Attempting to load yaml from string of length 87 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,929 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2019-02-13 12:00:03,929 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2019-02-13 12:00:03,929 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,933 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/01_debian_cloud.cfg (quiet=False) 2019-02-13 12:00:03,933 - util.py[DEBUG]: Read 336 bytes from /etc/cloud/cloud.cfg.d/01_debian_cloud.cfg 2019-02-13 12:00:03,933 - util.py[DEBUG]: Attempting to load yaml from string of length 336 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,936 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False) 2019-02-13 12:00:03,936 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg 2019-02-13 12:00:03,936 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,937 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,937 - util.py[DEBUG]: load_yaml given empty string, returning default 2019-02-13 12:00:03,938 - stages.py[DEBUG]: network config disabled by system_cfg 2019-02-13 12:00:03,938 - stages.py[INFO]: network config is disabled by system_cfg 2019-02-13 12:00:03,938 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/user-data.txt - wb: [384] 0 bytes 2019-02-13 12:00:03,941 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/user-data.txt.i - wb: [384] 308 bytes 2019-02-13 12:00:03,942 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/vendor-data.txt - wb: [384] 0 bytes 2019-02-13 12:00:03,943 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/vendor-data.txt.i - wb: [384] 308 bytes 2019-02-13 12:00:03,944 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'> 2019-02-13 12:00:03,944 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/consume_data - wb: [420] 24 bytes 2019-02-13 12:00:03,944 - helpers.py[DEBUG]: Running consume_data using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/consume_data'>) 2019-02-13 12:00:03,944 - handlers.py[DEBUG]: start: init-network/consume-user-data: reading and applying user-data 2019-02-13 12:00:03,944 - launch_index.py[DEBUG]: Discarding 0 multipart messages which do not match launch index 0 2019-02-13 12:00:03,945 - stages.py[DEBUG]: Added default handler for {'text/cloud-config-jsonp', 'text/cloud-config'} from CloudConfigPartHandler: [['text/cloud-config-jsonp', 'text/cloud-config']] 2019-02-13 12:00:03,945 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript'} from ShellScriptPartHandler: [['text/x-shellscript']] 2019-02-13 12:00:03,945 - stages.py[DEBUG]: Added default handler for {'text/cloud-boothook'} from BootHookPartHandler: [['text/cloud-boothook']] 2019-02-13 12:00:03,945 - stages.py[DEBUG]: Added default handler for {'text/upstart-job'} from UpstartJobPartHandler: [['text/upstart-job']] 2019-02-13 12:00:03,945 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__begin__, None, 2) with frequency once-per-instance 2019-02-13 12:00:03,945 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config-jsonp', 'text/cloud-config']] (__begin__, None, 3) with frequency once-per-instance 2019-02-13 12:00:03,945 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__begin__, None, 2) with frequency once-per-instance 2019-02-13 12:00:03,945 - __init__.py[DEBUG]: Calling handler UpstartJobPartHandler: [['text/upstart-job']] (__begin__, None, 2) with frequency once-per-instance 2019-02-13 12:00:03,946 - __init__.py[DEBUG]: {'Content-Type': 'text/x-not-multipart', 'Content-Disposition': 'attachment; filename="part-001"', 'MIME-Version': '1.0'} 2019-02-13 12:00:03,946 - __init__.py[DEBUG]: Empty payload of type text/x-not-multipart 2019-02-13 12:00:03,946 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__end__, None, 2) with frequency once-per-instance 2019-02-13 12:00:03,946 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config-jsonp', 'text/cloud-config']] (__end__, None, 3) with frequency once-per-instance 2019-02-13 12:00:03,946 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/cloud-config.txt - wb: [384] 0 bytes 2019-02-13 12:00:03,946 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__end__, None, 2) with frequency once-per-instance 2019-02-13 12:00:03,947 - __init__.py[DEBUG]: Calling handler UpstartJobPartHandler: [['text/upstart-job']] (__end__, None, 2) with frequency once-per-instance 2019-02-13 12:00:03,947 - handlers.py[DEBUG]: finish: init-network/consume-user-data: SUCCESS: reading and applying user-data 2019-02-13 12:00:03,947 - handlers.py[DEBUG]: start: init-network/consume-vendor-data: reading and applying vendor-data 2019-02-13 12:00:03,947 - stages.py[DEBUG]: no vendordata from datasource 2019-02-13 12:00:03,947 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data: SUCCESS: reading and applying vendor-data 2019-02-13 12:00:03,947 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2019-02-13 12:00:03,947 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg 2019-02-13 12:00:03,947 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,957 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99-disable-network-config.cfg (quiet=False) 2019-02-13 12:00:03,957 - util.py[DEBUG]: Read 28 bytes from /etc/cloud/cloud.cfg.d/99-disable-network-config.cfg 2019-02-13 12:00:03,957 - util.py[DEBUG]: Attempting to load yaml from string of length 28 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,957 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2019-02-13 12:00:03,958 - util.py[DEBUG]: Read 87 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2019-02-13 12:00:03,958 - util.py[DEBUG]: Attempting to load yaml from string of length 87 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,958 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2019-02-13 12:00:03,958 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2019-02-13 12:00:03,958 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,962 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/01_debian_cloud.cfg (quiet=False) 2019-02-13 12:00:03,962 - util.py[DEBUG]: Read 336 bytes from /etc/cloud/cloud.cfg.d/01_debian_cloud.cfg 2019-02-13 12:00:03,962 - util.py[DEBUG]: Attempting to load yaml from string of length 336 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,964 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False) 2019-02-13 12:00:03,965 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg 2019-02-13 12:00:03,965 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,966 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,966 - util.py[DEBUG]: load_yaml given empty string, returning default 2019-02-13 12:00:03,966 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2019-02-13 12:00:03,966 - util.py[DEBUG]: Read 0 bytes from /var/lib/cloud/instance/cloud-config.txt 2019-02-13 12:00:03,966 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,967 - util.py[DEBUG]: load_yaml given empty string, returning default 2019-02-13 12:00:03,967 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2019-02-13 12:00:03,967 - util.py[DEBUG]: Read 0 bytes from /var/lib/cloud/instance/cloud-config.txt 2019-02-13 12:00:03,967 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,) 2019-02-13 12:00:03,967 - util.py[DEBUG]: load_yaml given empty string, returning default 2019-02-13 12:00:03,969 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [256] 5116 bytes 2019-02-13 12:00:03,985 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'> 2019-02-13 12:00:03,985 - 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 2019-02-13 12:00:03,986 - handlers.py[DEBUG]: start: init-network/config-migrator: running config-migrator with frequency always 2019-02-13 12:00:03,986 - helpers.py[DEBUG]: Running config-migrator using lock (<cloudinit.helpers.DummyLock object at 0x7f63096b37b8>) 2019-02-13 12:00:03,986 - cc_migrator.py[DEBUG]: Migrated 0 semaphore files to there canonicalized names 2019-02-13 12:00:03,986 - handlers.py[DEBUG]: finish: init-network/config-migrator: SUCCESS: config-migrator ran successfully 2019-02-13 12:00:03,986 - 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 2019-02-13 12:00:03,986 - handlers.py[DEBUG]: start: init-network/config-seed_random: running config-seed_random with frequency once-per-instance 2019-02-13 12:00:03,986 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_seed_random - wb: [420] 24 bytes 2019-02-13 12:00:03,987 - helpers.py[DEBUG]: Running config-seed_random using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_seed_random'>) 2019-02-13 12:00:03,987 - cc_seed_random.py[DEBUG]: no command provided 2019-02-13 12:00:03,987 - handlers.py[DEBUG]: finish: init-network/config-seed_random: SUCCESS: config-seed_random ran successfully 2019-02-13 12:00:03,987 - 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 2019-02-13 12:00:03,987 - handlers.py[DEBUG]: start: init-network/config-bootcmd: running config-bootcmd with frequency always 2019-02-13 12:00:03,987 - helpers.py[DEBUG]: Running config-bootcmd using lock (<cloudinit.helpers.DummyLock object at 0x7f63096b3d30>) 2019-02-13 12:00:03,988 - cc_bootcmd.py[DEBUG]: Skipping module named bootcmd, no 'bootcmd' key in configuration 2019-02-13 12:00:03,988 - handlers.py[DEBUG]: finish: init-network/config-bootcmd: SUCCESS: config-bootcmd ran successfully 2019-02-13 12:00:03,988 - 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 2019-02-13 12:00:03,988 - handlers.py[DEBUG]: start: init-network/config-write-files: running config-write-files with frequency once-per-instance 2019-02-13 12:00:03,988 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_write_files - wb: [420] 24 bytes 2019-02-13 12:00:03,988 - helpers.py[DEBUG]: Running config-write-files using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_write_files'>) 2019-02-13 12:00:03,989 - cc_write_files.py[DEBUG]: Skipping module named write-files, no/empty 'write_files' key in configuration 2019-02-13 12:00:03,989 - handlers.py[DEBUG]: finish: init-network/config-write-files: SUCCESS: config-write-files ran successfully 2019-02-13 12:00:03,989 - 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 2019-02-13 12:00:03,989 - handlers.py[DEBUG]: start: init-network/config-growpart: running config-growpart with frequency always 2019-02-13 12:00:03,989 - helpers.py[DEBUG]: Running config-growpart using lock (<cloudinit.helpers.DummyLock object at 0x7f63096b3c18>) 2019-02-13 12:00:03,989 - cc_growpart.py[DEBUG]: No 'growpart' entry in cfg. Using default: {'devices': ['/'], 'ignore_growroot_disabled': False, 'mode': 'auto'} 2019-02-13 12:00:03,989 - util.py[DEBUG]: Running command ['growpart', '--help'] with allowed return codes [0] (shell=False, capture=True) 2019-02-13 12:00:03,994 - util.py[DEBUG]: Reading from /proc/441/mountinfo (quiet=False) 2019-02-13 12:00:03,994 - util.py[DEBUG]: Read 2470 bytes from /proc/441/mountinfo 2019-02-13 12:00:03,999 - util.py[DEBUG]: Reading from /sys/class/block/xvda1/partition (quiet=False) 2019-02-13 12:00:03,999 - util.py[DEBUG]: Read 2 bytes from /sys/class/block/xvda1/partition 2019-02-13 12:00:03,999 - util.py[DEBUG]: Reading from /sys/devices/vbd-51712/block/xvda/dev (quiet=False) 2019-02-13 12:00:03,999 - util.py[DEBUG]: Read 6 bytes from /sys/devices/vbd-51712/block/xvda/dev 2019-02-13 12:00:03,999 - util.py[DEBUG]: Running command ['growpart', '--dry-run', '/dev/xvda', '1'] with allowed return codes [0] (shell=False, capture=True) 2019-02-13 12:00:04,024 - util.py[DEBUG]: resize_devices took 0.030 seconds 2019-02-13 12:00:04,024 - cc_growpart.py[DEBUG]: '/' NOCHANGE: no change necessary (/dev/xvda, 1) 2019-02-13 12:00:04,024 - handlers.py[DEBUG]: finish: init-network/config-growpart: SUCCESS: config-growpart ran successfully 2019-02-13 12:00:04,024 - 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 2019-02-13 12:00:04,025 - handlers.py[DEBUG]: start: init-network/config-resizefs: running config-resizefs with frequency always 2019-02-13 12:00:04,025 - helpers.py[DEBUG]: Running config-resizefs using lock (<cloudinit.helpers.DummyLock object at 0x7f63096adb00>) 2019-02-13 12:00:04,025 - util.py[DEBUG]: Reading from /proc/441/mountinfo (quiet=False) 2019-02-13 12:00:04,025 - util.py[DEBUG]: Read 2470 bytes from /proc/441/mountinfo 2019-02-13 12:00:04,025 - cc_resizefs.py[DEBUG]: resize_info: dev=/dev/xvda1 mnt_point=/ path=/ 2019-02-13 12:00:04,025 - util.py[DEBUG]: Running command ['systemd-detect-virt', '--quiet', '--container'] with allowed return codes [0] (shell=False, capture=True) 2019-02-13 12:00:04,029 - util.py[DEBUG]: Running command ['running-in-container'] with allowed return codes [0] (shell=False, capture=True) 2019-02-13 12:00:04,030 - util.py[DEBUG]: Running command ['lxc-is-container'] with allowed return codes [0] (shell=False, capture=True) 2019-02-13 12:00:04,032 - util.py[DEBUG]: Reading from /proc/1/environ (quiet=False) 2019-02-13 12:00:04,032 - util.py[DEBUG]: Read 139 bytes from /proc/1/environ 2019-02-13 12:00:04,032 - util.py[DEBUG]: Reading from /proc/self/status (quiet=False) 2019-02-13 12:00:04,032 - util.py[DEBUG]: Read 1009 bytes from /proc/self/status 2019-02-13 12:00:04,033 - cc_resizefs.py[DEBUG]: Resizing / (ext4) using resize2fs /dev/xvda1 2019-02-13 12:00:04,033 - util.py[DEBUG]: Running command ('resize2fs', '/dev/xvda1') with allowed return codes [0] (shell=False, capture=True) 2019-02-13 12:00:04,039 - util.py[DEBUG]: Resizing took 0.006 seconds 2019-02-13 12:00:04,039 - cc_resizefs.py[DEBUG]: Resized root filesystem (type=ext4, val=True) 2019-02-13 12:00:04,039 - handlers.py[DEBUG]: finish: init-network/config-resizefs: SUCCESS: config-resizefs ran successfully 2019-02-13 12:00:04,039 - 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 2019-02-13 12:00:04,040 - handlers.py[DEBUG]: start: init-network/config-disk_setup: running config-disk_setup with frequency once-per-instance 2019-02-13 12:00:04,040 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_disk_setup - wb: [420] 23 bytes 2019-02-13 12:00:04,041 - helpers.py[DEBUG]: Running config-disk_setup using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_disk_setup'>) 2019-02-13 12:00:04,041 - handlers.py[DEBUG]: finish: init-network/config-disk_setup: SUCCESS: config-disk_setup ran successfully 2019-02-13 12:00:04,041 - 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 2019-02-13 12:00:04,041 - handlers.py[DEBUG]: start: init-network/config-mounts: running config-mounts with frequency once-per-instance 2019-02-13 12:00:04,042 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_mounts - wb: [420] 24 bytes 2019-02-13 12:00:04,042 - helpers.py[DEBUG]: Running config-mounts using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_mounts'>) 2019-02-13 12:00:04,042 - cc_mounts.py[DEBUG]: mounts configuration is [] 2019-02-13 12:00:04,042 - cc_mounts.py[DEBUG]: Attempting to determine the real name of ephemeral0 2019-02-13 12:00:04,042 - DataSourceEc2.py[DEBUG]: Unable to convert ephemeral0 to a device 2019-02-13 12:00:04,042 - cc_mounts.py[DEBUG]: Ignoring nonexistant default named mount ephemeral0 2019-02-13 12:00:04,042 - cc_mounts.py[DEBUG]: Attempting to determine the real name of swap 2019-02-13 12:00:04,042 - DataSourceEc2.py[DEBUG]: Unable to convert swap to a device 2019-02-13 12:00:04,043 - cc_mounts.py[DEBUG]: Ignoring nonexistant default named mount swap 2019-02-13 12:00:04,043 - cc_mounts.py[DEBUG]: no need to setup swap 2019-02-13 12:00:04,043 - cc_mounts.py[DEBUG]: No modifications to fstab needed. 2019-02-13 12:00:04,043 - handlers.py[DEBUG]: finish: init-network/config-mounts: SUCCESS: config-mounts ran successfully 2019-02-13 12:00:04,043 - 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 2019-02-13 12:00:04,043 - handlers.py[DEBUG]: start: init-network/config-set_hostname: running config-set_hostname with frequency once-per-instance 2019-02-13 12:00:04,043 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_set_hostname - wb: [420] 24 bytes 2019-02-13 12:00:04,044 - helpers.py[DEBUG]: Running config-set_hostname using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_set_hostname'>) 2019-02-13 12:00:04,044 - cc_set_hostname.py[DEBUG]: Setting the hostname to ip-172-16-65-81.eu-central-qa.wkda (ip-172-16-65-81) 2019-02-13 12:00:04,044 - util.py[DEBUG]: Reading from /etc/hostname (quiet=False) 2019-02-13 12:00:04,044 - util.py[DEBUG]: Read 7 bytes from /etc/hostname 2019-02-13 12:00:04,044 - util.py[DEBUG]: Writing to /etc/hostname - wb: [420] 16 bytes 2019-02-13 12:00:04,045 - __init__.py[DEBUG]: Non-persistently setting the system hostname to ip-172-16-65-81 2019-02-13 12:00:04,045 - util.py[DEBUG]: Running command ['hostname', 'ip-172-16-65-81'] with allowed return codes [0] (shell=False, capture=True) 2019-02-13 12:00:04,047 - handlers.py[DEBUG]: finish: init-network/config-set_hostname: SUCCESS: config-set_hostname ran successfully 2019-02-13 12:00:04,047 - 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 2019-02-13 12:00:04,047 - handlers.py[DEBUG]: start: init-network/config-update_hostname: running config-update_hostname with frequency always 2019-02-13 12:00:04,047 - helpers.py[DEBUG]: Running config-update_hostname using lock (<cloudinit.helpers.DummyLock object at 0x7f63096ab128>) 2019-02-13 12:00:04,047 - cc_update_hostname.py[DEBUG]: Updating hostname to ip-172-16-65-81.eu-central-qa.wkda (ip-172-16-65-81) 2019-02-13 12:00:04,048 - util.py[DEBUG]: Reading from /etc/hostname (quiet=False) 2019-02-13 12:00:04,048 - util.py[DEBUG]: Read 16 bytes from /etc/hostname 2019-02-13 12:00:04,048 - __init__.py[DEBUG]: Attempting to update hostname to ip-172-16-65-81 in 1 files 2019-02-13 12:00:04,048 - util.py[DEBUG]: Reading from /var/lib/cloud/data/previous-hostname (quiet=False) 2019-02-13 12:00:04,048 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-hostname - wb: [420] 16 bytes 2019-02-13 12:00:04,049 - handlers.py[DEBUG]: finish: init-network/config-update_hostname: SUCCESS: config-update_hostname ran successfully 2019-02-13 12:00:04,049 - 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 2019-02-13 12:00:04,049 - handlers.py[DEBUG]: start: init-network/config-update_etc_hosts: running config-update_etc_hosts with frequency always 2019-02-13 12:00:04,049 - helpers.py[DEBUG]: Running config-update_etc_hosts using lock (<cloudinit.helpers.DummyLock object at 0x7f63096ab2b0>) 2019-02-13 12:00:04,049 - util.py[DEBUG]: Reading from /etc/cloud/templates/hosts.debian.tmpl (quiet=False) 2019-02-13 12:00:04,050 - util.py[DEBUG]: Read 887 bytes from /etc/cloud/templates/hosts.debian.tmpl 2019-02-13 12:00:04,050 - templater.py[DEBUG]: Rendering content of '/etc/cloud/templates/hosts.debian.tmpl' using renderer jinja 2019-02-13 12:00:04,053 - util.py[DEBUG]: Writing to /etc/hosts - wb: [420] 625 bytes 2019-02-13 12:00:04,053 - handlers.py[DEBUG]: finish: init-network/config-update_etc_hosts: SUCCESS: config-update_etc_hosts ran successfully 2019-02-13 12:00:04,054 - 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 2019-02-13 12:00:04,054 - handlers.py[DEBUG]: start: init-network/config-ca-certs: running config-ca-certs with frequency once-per-instance 2019-02-13 12:00:04,054 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_ca_certs - wb: [420] 23 bytes 2019-02-13 12:00:04,054 - helpers.py[DEBUG]: Running config-ca-certs using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_ca_certs'>) 2019-02-13 12:00:04,054 - cc_ca_certs.py[DEBUG]: Skipping module named ca-certs, no 'ca-certs' key in configuration 2019-02-13 12:00:04,055 - handlers.py[DEBUG]: finish: init-network/config-ca-certs: SUCCESS: config-ca-certs ran successfully 2019-02-13 12:00:04,055 - 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 2019-02-13 12:00:04,055 - handlers.py[DEBUG]: start: init-network/config-rsyslog: running config-rsyslog with frequency once-per-instance 2019-02-13 12:00:04,055 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_rsyslog - wb: [420] 24 bytes 2019-02-13 12:00:04,055 - helpers.py[DEBUG]: Running config-rsyslog using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_rsyslog'>) 2019-02-13 12:00:04,056 - cc_rsyslog.py[DEBUG]: Skipping module named rsyslog, no 'rsyslog' key in configuration 2019-02-13 12:00:04,056 - handlers.py[DEBUG]: finish: init-network/config-rsyslog: SUCCESS: config-rsyslog ran successfully 2019-02-13 12:00:04,056 - 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 2019-02-13 12:00:04,056 - handlers.py[DEBUG]: start: init-network/config-users-groups: running config-users-groups with frequency once-per-instance 2019-02-13 12:00:04,056 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_users_groups - wb: [420] 24 bytes 2019-02-13 12:00:04,057 - helpers.py[DEBUG]: Running config-users-groups using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_users_groups'>) 2019-02-13 12:00:04,057 - util.py[DEBUG]: Reading from /etc/system-image/channel.ini (quiet=True) 2019-02-13 12:00:04,057 - util.py[DEBUG]: Read 0 bytes from /etc/system-image/channel.ini 2019-02-13 12:00:04,057 - __init__.py[DEBUG]: Adding user admin 2019-02-13 12:00:04,057 - util.py[DEBUG]: Running hidden command to protect sensitive input/output logstring: ['useradd', 'admin', '--comment', 'Debian', '--groups', 'adm,audio,cdrom,dialout,dip,floppy,netdev,plugdev,sudo,video', '--shell', '/bin/bash', '-m'] 2019-02-13 12:00:04,118 - util.py[DEBUG]: Running command ['passwd', '-l', 'admin'] with allowed return codes [0] (shell=False, capture=True) 2019-02-13 12:00:04,130 - util.py[DEBUG]: Reading from /etc/sudoers (quiet=False) 2019-02-13 12:00:04,131 - util.py[DEBUG]: Read 669 bytes from /etc/sudoers 2019-02-13 12:00:04,132 - util.py[DEBUG]: Writing to /etc/sudoers.d/90-cloud-init-users - wb: [288] 121 bytes 2019-02-13 12:00:04,133 - handlers.py[DEBUG]: finish: init-network/config-users-groups: SUCCESS: config-users-groups ran successfully 2019-02-13 12:00:04,133 - 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 2019-02-13 12:00:04,133 - handlers.py[DEBUG]: start: init-network/config-ssh: running config-ssh with frequency once-per-instance 2019-02-13 12:00:04,133 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_ssh - wb: [420] 24 bytes 2019-02-13 12:00:04,134 - helpers.py[DEBUG]: Running config-ssh using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_ssh'>) 2019-02-13 12:00:04,135 - 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) 2019-02-13 12:00:04,179 - 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) 2019-02-13 12:00:04,495 - 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) 2019-02-13 12:00:04,500 - 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) 2019-02-13 12:00:04,506 - util.py[DEBUG]: Changing the ownership of /home/admin/.ssh to 1000:1000 2019-02-13 12:00:04,507 - util.py[DEBUG]: Reading from /etc/ssh/sshd_config (quiet=False) 2019-02-13 12:00:04,508 - util.py[DEBUG]: Read 3344 bytes from /etc/ssh/sshd_config 2019-02-13 12:00:04,509 - util.py[DEBUG]: Writing to /home/admin/.ssh/authorized_keys - wb: [384] 425 bytes 2019-02-13 12:00:04,509 - util.py[DEBUG]: Changing the ownership of /home/admin/.ssh/authorized_keys to 1000:1000 2019-02-13 12:00:04,510 - util.py[DEBUG]: Changing the ownership of /root/.ssh to 0:0 2019-02-13 12:00:04,510 - util.py[DEBUG]: Reading from /etc/ssh/sshd_config (quiet=False) 2019-02-13 12:00:04,510 - util.py[DEBUG]: Read 3344 bytes from /etc/ssh/sshd_config 2019-02-13 12:00:04,511 - util.py[DEBUG]: Writing to /root/.ssh/authorized_keys - wb: [384] 579 bytes 2019-02-13 12:00:04,511 - util.py[DEBUG]: Changing the ownership of /root/.ssh/authorized_keys to 0:0 2019-02-13 12:00:04,512 - handlers.py[DEBUG]: finish: init-network/config-ssh: SUCCESS: config-ssh ran successfully 2019-02-13 12:00:04,512 - main.py[DEBUG]: Ran 15 modules with 0 failures 2019-02-13 12:00:04,513 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2019-02-13 12:00:04,513 - util.py[DEBUG]: Read 10 bytes from /proc/uptime 2019-02-13 12:00:04,513 - util.py[DEBUG]: cloud-init mode 'init' took 0.855 seconds (0.85) 2019-02-13 12:00:04,513 - handlers.py[DEBUG]: finish: init-network: SUCCESS: searching for network datasources 2019-02-13 12:00:05,656 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'modules:config' at Wed, 13 Feb 2019 12:00:05 +0000. Up 6.78 seconds. 2019-02-13 12:00:05,665 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'> 2019-02-13 12:00:05,666 - 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 2019-02-13 12:00:05,666 - handlers.py[DEBUG]: start: modules-config/config-emit_upstart: running config-emit_upstart with frequency always 2019-02-13 12:00:05,666 - helpers.py[DEBUG]: Running config-emit_upstart using lock (<cloudinit.helpers.DummyLock object at 0x7f247e541e80>) 2019-02-13 12:00:05,667 - cc_emit_upstart.py[DEBUG]: no /sbin/initctl located 2019-02-13 12:00:05,667 - cc_emit_upstart.py[DEBUG]: not upstart system, 'emit_upstart' disabled 2019-02-13 12:00:05,667 - handlers.py[DEBUG]: finish: modules-config/config-emit_upstart: SUCCESS: config-emit_upstart ran successfully 2019-02-13 12:00:05,667 - 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 2019-02-13 12:00:05,667 - handlers.py[DEBUG]: start: modules-config/config-ssh-import-id: running config-ssh-import-id with frequency once-per-instance 2019-02-13 12:00:05,667 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_ssh_import_id - wb: [420] 23 bytes 2019-02-13 12:00:05,668 - helpers.py[DEBUG]: Running config-ssh-import-id using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_ssh_import_id'>) 2019-02-13 12:00:05,668 - handlers.py[DEBUG]: finish: modules-config/config-ssh-import-id: SUCCESS: config-ssh-import-id ran successfully 2019-02-13 12:00:05,668 - 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 2019-02-13 12:00:05,668 - handlers.py[DEBUG]: start: modules-config/config-locale: running config-locale with frequency once-per-instance 2019-02-13 12:00:05,669 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_locale - wb: [420] 24 bytes 2019-02-13 12:00:05,669 - helpers.py[DEBUG]: Running config-locale using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_locale'>) 2019-02-13 12:00:05,669 - cc_locale.py[DEBUG]: Setting locale to en_US.UTF-8 2019-02-13 12:00:05,669 - util.py[DEBUG]: Running command ['locale-gen', 'en_US.UTF-8'] with allowed return codes [0] (shell=False, capture=False) 2019-02-13 12:00:06,462 - util.py[DEBUG]: Running command ['update-locale', 'en_US.UTF-8'] with allowed return codes [0] (shell=False, capture=False) 2019-02-13 12:00:06,505 - util.py[DEBUG]: Writing to /etc/default/locale - wb: [420] 87 bytes 2019-02-13 12:00:06,506 - handlers.py[DEBUG]: finish: modules-config/config-locale: SUCCESS: config-locale ran successfully 2019-02-13 12:00:06,506 - 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 2019-02-13 12:00:06,506 - handlers.py[DEBUG]: start: modules-config/config-set-passwords: running config-set-passwords with frequency once-per-instance 2019-02-13 12:00:06,506 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_set_passwords - wb: [420] 24 bytes 2019-02-13 12:00:06,507 - helpers.py[DEBUG]: Running config-set-passwords using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_set_passwords'>) 2019-02-13 12:00:06,507 - handlers.py[DEBUG]: finish: modules-config/config-set-passwords: SUCCESS: config-set-passwords ran successfully 2019-02-13 12:00:06,507 - 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 2019-02-13 12:00:06,507 - handlers.py[DEBUG]: start: modules-config/config-grub-dpkg: running config-grub-dpkg with frequency once-per-instance 2019-02-13 12:00:06,507 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_grub_dpkg - wb: [420] 23 bytes 2019-02-13 12:00:06,507 - helpers.py[DEBUG]: Running config-grub-dpkg using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_grub_dpkg'>) 2019-02-13 12:00:06,508 - cc_grub_dpkg.py[DEBUG]: Setting grub debconf-set-selections with '/dev/xvda','false' 2019-02-13 12:00:06,508 - util.py[DEBUG]: Running command ['debconf-set-selections'] with allowed return codes [0] (shell=False, capture=True) 2019-02-13 12:00:06,640 - handlers.py[DEBUG]: finish: modules-config/config-grub-dpkg: SUCCESS: config-grub-dpkg ran successfully 2019-02-13 12:00:06,640 - 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 2019-02-13 12:00:06,641 - handlers.py[DEBUG]: start: modules-config/config-apt-pipelining: running config-apt-pipelining with frequency once-per-instance 2019-02-13 12:00:06,641 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_apt_pipelining - wb: [420] 24 bytes 2019-02-13 12:00:06,641 - helpers.py[DEBUG]: Running config-apt-pipelining using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_apt_pipelining'>) 2019-02-13 12:00:06,642 - util.py[DEBUG]: Writing to /etc/apt/apt.conf.d/90cloud-init-pipelining - wb: [420] 80 bytes 2019-02-13 12:00:06,643 - cc_apt_pipelining.py[DEBUG]: Wrote /etc/apt/apt.conf.d/90cloud-init-pipelining with apt pipeline depth setting 0 2019-02-13 12:00:06,643 - handlers.py[DEBUG]: finish: modules-config/config-apt-pipelining: SUCCESS: config-apt-pipelining ran successfully 2019-02-13 12:00:06,643 - 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 2019-02-13 12:00:06,644 - handlers.py[DEBUG]: start: modules-config/config-apt-configure: running config-apt-configure with frequency once-per-instance 2019-02-13 12:00:06,644 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_apt_configure - wb: [420] 24 bytes 2019-02-13 12:00:06,644 - helpers.py[DEBUG]: Running config-apt-configure using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_apt_configure'>) 2019-02-13 12:00:06,644 - cc_apt_configure.py[DEBUG]: apt config: convert V2 to V3 format for keys 'apt_preserve_sources_list' 2019-02-13 12:00:06,644 - cc_apt_configure.py[DEBUG]: handling apt (module apt-configure) with apt config '{'preserve_sources_list': True}' 2019-02-13 12:00:06,644 - util.py[DEBUG]: Running command ['lsb_release', '--all'] with allowed return codes [0] (shell=False, capture=True) 2019-02-13 12:00:06,694 - util.py[DEBUG]: Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (shell=False, capture=True) 2019-02-13 12:00:06,700 - cc_apt_configure.py[DEBUG]: got primary mirror: None 2019-02-13 12:00:06,701 - cc_apt_configure.py[DEBUG]: got security mirror: None 2019-02-13 12:00:06,701 - util.py[DEBUG]: Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (shell=False, capture=True) 2019-02-13 12:00:06,704 - __init__.py[DEBUG]: filtered distro mirror info: {'primary': 'http://deb.debian.org/debian', 'security': 'http://security.debian.org/'} 2019-02-13 12:00:06,704 - cc_apt_configure.py[DEBUG]: Apt Mirror info: {'PRIMARY': 'http://deb.debian.org/debian', 'primary': 'http://deb.debian.org/debian', 'security': 'http://security.debian.org/', 'MIRROR': 'http://deb.debian.org/debian', 'SECURITY': 'http://security.debian.org/'} 2019-02-13 12:00:06,704 - cc_apt_configure.py[DEBUG]: debconf_selections was not set in config 2019-02-13 12:00:06,704 - handlers.py[DEBUG]: finish: modules-config/config-apt-configure: SUCCESS: config-apt-configure ran successfully 2019-02-13 12:00:06,705 - 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 2019-02-13 12:00:06,705 - handlers.py[DEBUG]: start: modules-config/config-ntp: running config-ntp with frequency once-per-instance 2019-02-13 12:00:06,705 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_ntp - wb: [420] 24 bytes 2019-02-13 12:00:06,706 - helpers.py[DEBUG]: Running config-ntp using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_ntp'>) 2019-02-13 12:00:06,706 - cc_ntp.py[DEBUG]: Skipping module named ntp,not present or disabled by cfg 2019-02-13 12:00:06,706 - handlers.py[DEBUG]: finish: modules-config/config-ntp: SUCCESS: config-ntp ran successfully 2019-02-13 12:00:06,706 - 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 2019-02-13 12:00:06,706 - handlers.py[DEBUG]: start: modules-config/config-timezone: running config-timezone with frequency once-per-instance 2019-02-13 12:00:06,706 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_timezone - wb: [420] 24 bytes 2019-02-13 12:00:06,707 - helpers.py[DEBUG]: Running config-timezone using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_timezone'>) 2019-02-13 12:00:06,707 - cc_timezone.py[DEBUG]: Skipping module named timezone, no 'timezone' specified 2019-02-13 12:00:06,707 - handlers.py[DEBUG]: finish: modules-config/config-timezone: SUCCESS: config-timezone ran successfully 2019-02-13 12:00:06,707 - 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 2019-02-13 12:00:06,707 - handlers.py[DEBUG]: start: modules-config/config-disable-ec2-metadata: running config-disable-ec2-metadata with frequency always 2019-02-13 12:00:06,707 - helpers.py[DEBUG]: Running config-disable-ec2-metadata using lock (<cloudinit.helpers.DummyLock object at 0x7f247e544d30>) 2019-02-13 12:00:06,707 - cc_disable_ec2_metadata.py[DEBUG]: Skipping module named disable-ec2-metadata, disabling the ec2 route not enabled 2019-02-13 12:00:06,707 - handlers.py[DEBUG]: finish: modules-config/config-disable-ec2-metadata: SUCCESS: config-disable-ec2-metadata ran successfully 2019-02-13 12:00:06,707 - 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 2019-02-13 12:00:06,707 - handlers.py[DEBUG]: start: modules-config/config-runcmd: running config-runcmd with frequency once-per-instance 2019-02-13 12:00:06,708 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_runcmd - wb: [420] 23 bytes 2019-02-13 12:00:06,708 - helpers.py[DEBUG]: Running config-runcmd using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_runcmd'>) 2019-02-13 12:00:06,708 - cc_runcmd.py[DEBUG]: Skipping module named runcmd, no 'runcmd' key in configuration 2019-02-13 12:00:06,708 - handlers.py[DEBUG]: finish: modules-config/config-runcmd: SUCCESS: config-runcmd ran successfully 2019-02-13 12:00:06,708 - 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 2019-02-13 12:00:06,708 - handlers.py[DEBUG]: start: modules-config/config-byobu: running config-byobu with frequency once-per-instance 2019-02-13 12:00:06,709 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_byobu - wb: [420] 24 bytes 2019-02-13 12:00:06,709 - helpers.py[DEBUG]: Running config-byobu using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_byobu'>) 2019-02-13 12:00:06,709 - cc_byobu.py[DEBUG]: Skipping module named byobu, no 'byobu' values found 2019-02-13 12:00:06,709 - handlers.py[DEBUG]: finish: modules-config/config-byobu: SUCCESS: config-byobu ran successfully 2019-02-13 12:00:06,709 - main.py[DEBUG]: Ran 12 modules with 0 failures 2019-02-13 12:00:06,710 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2019-02-13 12:00:06,710 - util.py[DEBUG]: Read 10 bytes from /proc/uptime 2019-02-13 12:00:06,710 - util.py[DEBUG]: cloud-init mode 'modules' took 1.108 seconds (1.11) 2019-02-13 12:00:06,710 - handlers.py[DEBUG]: finish: modules-config: SUCCESS: running modules for config 2019-02-13 12:00:07,137 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'modules:final' at Wed, 13 Feb 2019 12:00:07 +0000. Up 8.26 seconds. 2019-02-13 12:00:07,155 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'> 2019-02-13 12:00:07,156 - 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 2019-02-13 12:00:07,156 - handlers.py[DEBUG]: start: modules-final/config-package-update-upgrade-install: running config-package-update-upgrade-install with frequency once-per-instance 2019-02-13 12:00:07,156 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_package_update_upgrade_install - wb: [420] 24 bytes 2019-02-13 12:00:07,157 - helpers.py[DEBUG]: Running config-package-update-upgrade-install using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_package_update_upgrade_install'>) 2019-02-13 12:00:07,157 - handlers.py[DEBUG]: finish: modules-final/config-package-update-upgrade-install: SUCCESS: config-package-update-upgrade-install ran successfully 2019-02-13 12:00:07,157 - 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 2019-02-13 12:00:07,157 - handlers.py[DEBUG]: start: modules-final/config-fan: running config-fan with frequency once-per-instance 2019-02-13 12:00:07,157 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_fan - wb: [420] 24 bytes 2019-02-13 12:00:07,158 - helpers.py[DEBUG]: Running config-fan using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_fan'>) 2019-02-13 12:00:07,158 - cc_fan.py[DEBUG]: fan: no 'fan' config entry. disabling 2019-02-13 12:00:07,158 - handlers.py[DEBUG]: finish: modules-final/config-fan: SUCCESS: config-fan ran successfully 2019-02-13 12:00:07,158 - 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 2019-02-13 12:00:07,158 - handlers.py[DEBUG]: start: modules-final/config-puppet: running config-puppet with frequency once-per-instance 2019-02-13 12:00:07,158 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_puppet - wb: [420] 24 bytes 2019-02-13 12:00:07,159 - helpers.py[DEBUG]: Running config-puppet using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_puppet'>) 2019-02-13 12:00:07,159 - cc_puppet.py[DEBUG]: Skipping module named puppet, no 'puppet' configuration found 2019-02-13 12:00:07,159 - handlers.py[DEBUG]: finish: modules-final/config-puppet: SUCCESS: config-puppet ran successfully 2019-02-13 12:00:07,159 - 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 2019-02-13 12:00:07,159 - handlers.py[DEBUG]: start: modules-final/config-chef: running config-chef with frequency once-per-instance 2019-02-13 12:00:07,159 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_chef - wb: [420] 23 bytes 2019-02-13 12:00:07,160 - helpers.py[DEBUG]: Running config-chef using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_chef'>) 2019-02-13 12:00:07,160 - cc_chef.py[DEBUG]: Skipping module named chef, no 'chef' key in configuration 2019-02-13 12:00:07,160 - handlers.py[DEBUG]: finish: modules-final/config-chef: SUCCESS: config-chef ran successfully 2019-02-13 12:00:07,160 - 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 2019-02-13 12:00:07,160 - handlers.py[DEBUG]: start: modules-final/config-salt-minion: running config-salt-minion with frequency once-per-instance 2019-02-13 12:00:07,160 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_salt_minion - wb: [420] 24 bytes 2019-02-13 12:00:07,161 - helpers.py[DEBUG]: Running config-salt-minion using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_salt_minion'>) 2019-02-13 12:00:07,161 - cc_salt_minion.py[DEBUG]: Skipping module named salt-minion, no 'salt_minion' key in configuration 2019-02-13 12:00:07,161 - handlers.py[DEBUG]: finish: modules-final/config-salt-minion: SUCCESS: config-salt-minion ran successfully 2019-02-13 12:00:07,161 - 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 2019-02-13 12:00:07,161 - handlers.py[DEBUG]: start: modules-final/config-mcollective: running config-mcollective with frequency once-per-instance 2019-02-13 12:00:07,161 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_mcollective - wb: [420] 24 bytes 2019-02-13 12:00:07,162 - helpers.py[DEBUG]: Running config-mcollective using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_mcollective'>) 2019-02-13 12:00:07,162 - cc_mcollective.py[DEBUG]: Skipping module named mcollective, no 'mcollective' key in configuration 2019-02-13 12:00:07,162 - handlers.py[DEBUG]: finish: modules-final/config-mcollective: SUCCESS: config-mcollective ran successfully 2019-02-13 12:00:07,162 - 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 2019-02-13 12:00:07,162 - handlers.py[DEBUG]: start: modules-final/config-rightscale_userdata: running config-rightscale_userdata with frequency once-per-instance 2019-02-13 12:00:07,162 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_rightscale_userdata - wb: [420] 24 bytes 2019-02-13 12:00:07,163 - helpers.py[DEBUG]: Running config-rightscale_userdata using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_rightscale_userdata'>) 2019-02-13 12:00:07,163 - cc_rightscale_userdata.py[DEBUG]: Failed to get raw userdata in module rightscale_userdata 2019-02-13 12:00:07,163 - handlers.py[DEBUG]: finish: modules-final/config-rightscale_userdata: SUCCESS: config-rightscale_userdata ran successfully 2019-02-13 12:00:07,163 - 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 2019-02-13 12:00:07,163 - handlers.py[DEBUG]: start: modules-final/config-scripts-vendor: running config-scripts-vendor with frequency once-per-instance 2019-02-13 12:00:07,163 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_scripts_vendor - wb: [420] 24 bytes 2019-02-13 12:00:07,164 - helpers.py[DEBUG]: Running config-scripts-vendor using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_scripts_vendor'>) 2019-02-13 12:00:07,164 - handlers.py[DEBUG]: finish: modules-final/config-scripts-vendor: SUCCESS: config-scripts-vendor ran successfully 2019-02-13 12:00:07,164 - 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 2019-02-13 12:00:07,164 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-once: running config-scripts-per-once with frequency once 2019-02-13 12:00:07,164 - util.py[DEBUG]: Writing to /var/lib/cloud/sem/config_scripts_per_once.once - wb: [420] 24 bytes 2019-02-13 12:00:07,165 - helpers.py[DEBUG]: Running config-scripts-per-once using lock (<FileLock using file '/var/lib/cloud/sem/config_scripts_per_once.once'>) 2019-02-13 12:00:07,165 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-once: SUCCESS: config-scripts-per-once ran successfully 2019-02-13 12:00:07,165 - 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 2019-02-13 12:00:07,165 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-boot: running config-scripts-per-boot with frequency always 2019-02-13 12:00:07,165 - helpers.py[DEBUG]: Running config-scripts-per-boot using lock (<cloudinit.helpers.DummyLock object at 0x7fe991a6e5f8>) 2019-02-13 12:00:07,165 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-boot: SUCCESS: config-scripts-per-boot ran successfully 2019-02-13 12:00:07,165 - 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 2019-02-13 12:00:07,166 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-instance: running config-scripts-per-instance with frequency once-per-instance 2019-02-13 12:00:07,166 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_scripts_per_instance - wb: [420] 23 bytes 2019-02-13 12:00:07,166 - helpers.py[DEBUG]: Running config-scripts-per-instance using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_scripts_per_instance'>) 2019-02-13 12:00:07,166 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-instance: SUCCESS: config-scripts-per-instance ran successfully 2019-02-13 12:00:07,166 - 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 2019-02-13 12:00:07,167 - handlers.py[DEBUG]: start: modules-final/config-scripts-user: running config-scripts-user with frequency once-per-instance 2019-02-13 12:00:07,167 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_scripts_user - wb: [420] 23 bytes 2019-02-13 12:00:07,167 - helpers.py[DEBUG]: Running config-scripts-user using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_scripts_user'>) 2019-02-13 12:00:07,167 - handlers.py[DEBUG]: finish: modules-final/config-scripts-user: SUCCESS: config-scripts-user ran successfully 2019-02-13 12:00:07,167 - 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 2019-02-13 12:00:07,168 - handlers.py[DEBUG]: start: modules-final/config-ssh-authkey-fingerprints: running config-ssh-authkey-fingerprints with frequency once-per-instance 2019-02-13 12:00:07,168 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_ssh_authkey_fingerprints - wb: [420] 24 bytes 2019-02-13 12:00:07,168 - helpers.py[DEBUG]: Running config-ssh-authkey-fingerprints using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_ssh_authkey_fingerprints'>) 2019-02-13 12:00:07,169 - util.py[DEBUG]: Reading from /etc/ssh/sshd_config (quiet=False) 2019-02-13 12:00:07,169 - util.py[DEBUG]: Read 3344 bytes from /etc/ssh/sshd_config 2019-02-13 12:00:07,170 - util.py[DEBUG]: Reading from /home/admin/.ssh/authorized_keys (quiet=False) 2019-02-13 12:00:07,170 - util.py[DEBUG]: Read 425 bytes from /home/admin/.ssh/authorized_keys 2019-02-13 12:00:07,247 - handlers.py[DEBUG]: finish: modules-final/config-ssh-authkey-fingerprints: SUCCESS: config-ssh-authkey-fingerprints ran successfully 2019-02-13 12:00:07,247 - 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 2019-02-13 12:00:07,248 - handlers.py[DEBUG]: start: modules-final/config-keys-to-console: running config-keys-to-console with frequency once-per-instance 2019-02-13 12:00:07,248 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_keys_to_console - wb: [420] 24 bytes 2019-02-13 12:00:07,248 - helpers.py[DEBUG]: Running config-keys-to-console using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_keys_to_console'>) 2019-02-13 12:00:07,249 - util.py[DEBUG]: Running command ['/usr/lib/cloud-init/write-ssh-key-fingerprints', '', 'ssh-dss'] with allowed return codes [0] (shell=False, capture=True) 2019-02-13 12:00:07,336 - handlers.py[DEBUG]: finish: modules-final/config-keys-to-console: SUCCESS: config-keys-to-console ran successfully 2019-02-13 12:00:07,336 - 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 2019-02-13 12:00:07,337 - handlers.py[DEBUG]: start: modules-final/config-phone-home: running config-phone-home with frequency once-per-instance 2019-02-13 12:00:07,337 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_phone_home - wb: [420] 24 bytes 2019-02-13 12:00:07,337 - helpers.py[DEBUG]: Running config-phone-home using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_phone_home'>) 2019-02-13 12:00:07,338 - cc_phone_home.py[DEBUG]: Skipping module named phone-home, no 'phone_home' configuration found 2019-02-13 12:00:07,338 - handlers.py[DEBUG]: finish: modules-final/config-phone-home: SUCCESS: config-phone-home ran successfully 2019-02-13 12:00:07,338 - 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 2019-02-13 12:00:07,338 - handlers.py[DEBUG]: start: modules-final/config-final-message: running config-final-message with frequency always 2019-02-13 12:00:07,338 - helpers.py[DEBUG]: Running config-final-message using lock (<cloudinit.helpers.DummyLock object at 0x7fe991a79048>) 2019-02-13 12:00:07,338 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2019-02-13 12:00:07,338 - util.py[DEBUG]: Read 10 bytes from /proc/uptime 2019-02-13 12:00:07,341 - util.py[DEBUG]: Cloud-init v. 0.7.9 finished at Wed, 13 Feb 2019 12:00:07 +0000. Datasource DataSourceEc2. Up 8.51 seconds 2019-02-13 12:00:07,341 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/boot-finished - wb: [420] 50 bytes 2019-02-13 12:00:07,342 - handlers.py[DEBUG]: finish: modules-final/config-final-message: SUCCESS: config-final-message ran successfully 2019-02-13 12:00:07,342 - 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 2019-02-13 12:00:07,342 - handlers.py[DEBUG]: start: modules-final/config-power-state-change: running config-power-state-change with frequency once-per-instance 2019-02-13 12:00:07,342 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_power_state_change - wb: [420] 23 bytes 2019-02-13 12:00:07,343 - helpers.py[DEBUG]: Running config-power-state-change using lock (<FileLock using file '/var/lib/cloud/instances/i-01d620471b1d427ac/sem/config_power_state_change'>) 2019-02-13 12:00:07,343 - cc_power_state_change.py[DEBUG]: no power_state provided. doing nothing 2019-02-13 12:00:07,343 - handlers.py[DEBUG]: finish: modules-final/config-power-state-change: SUCCESS: config-power-state-change ran successfully 2019-02-13 12:00:07,343 - main.py[DEBUG]: Ran 17 modules with 0 failures 2019-02-13 12:00:07,344 - util.py[DEBUG]: Creating symbolic link from '/run/cloud-init/result.json' => '../../var/lib/cloud/data/result.json' 2019-02-13 12:00:07,344 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2019-02-13 12:00:07,344 - util.py[DEBUG]: Read 10 bytes from /proc/uptime 2019-02-13 12:00:07,344 - util.py[DEBUG]: cloud-init mode 'modules' took 0.260 seconds (0.26) 2019-02-13 12:00:07,344 - handlers.py[DEBUG]: finish: modules-final: SUCCESS: running modules for final 2019-02-22 17:21:00,873 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'init-local' at Fri, 22 Feb 2019 16:21:00 +0000. Up 8.94 seconds. 2019-02-22 17:21:00,875 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [420] 0 bytes 2019-02-22 17:21:00,875 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 0:4 2019-02-22 17:21:00,875 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance/boot-finished 2019-02-22 17:21:00,876 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/data/no-net 2019-02-22 17:21:00,876 - handlers.py[DEBUG]: start: init-local/check-cache: attempting to read from cache [check] 2019-02-22 17:21:00,876 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False) 2019-02-22 17:21:00,877 - util.py[DEBUG]: Read 5116 bytes from /var/lib/cloud/instance/obj.pkl 2019-02-22 17:21:00,879 - stages.py[DEBUG]: cache invalid in datasource: DataSourceEc2 2019-02-22 17:21:00,880 - handlers.py[DEBUG]: finish: init-local/check-cache: SUCCESS: cache invalid in datasource: DataSourceEc2 2019-02-22 17:21:00,880 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2019-02-22 17:21:00,966 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'> 2019-02-22 17:21:00,966 - __init__.py[DEBUG]: Looking for for data source in: ['Ec2'], via packages ['', 'cloudinit.sources'] that matches dependencies ['FILESYSTEM'] 2019-02-22 17:21:00,967 - __init__.py[DEBUG]: Searching for local data source in: [] 2019-02-22 17:21:00,967 - main.py[DEBUG]: No local datasource found 2019-02-22 17:21:00,967 - stages.py[DEBUG]: network config disabled by system_cfg 2019-02-22 17:21:00,967 - stages.py[INFO]: network config is disabled by system_cfg 2019-02-22 17:21:00,967 - main.py[DEBUG]: [local] Exiting without datasource in local mode 2019-02-22 17:21:00,968 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2019-02-22 17:21:00,968 - util.py[DEBUG]: Read 11 bytes from /proc/uptime 2019-02-22 17:21:00,968 - util.py[DEBUG]: cloud-init mode 'init' took 0.126 seconds (0.13) 2019-02-22 17:21:00,968 - handlers.py[DEBUG]: finish: init-local: SUCCESS: searching for local datasources 2019-02-22 17:21:03,272 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'init' at Fri, 22 Feb 2019 16:21:03 +0000. Up 11.35 seconds. 2019-02-22 17:21:03,273 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [420] 0 bytes 2019-02-22 17:21:03,274 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 0:4 2019-02-22 17:21:03,274 - util.py[DEBUG]: Running command ['ifconfig', '-a'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:03,278 - util.py[DEBUG]: Running command ['netstat', '-rn'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:03,376 - util.py[DEBUG]: Running command ['netstat', '-A', 'inet6', '-n'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:03,380 - main.py[DEBUG]: Checking to see if files that we need already exist from a previous run that would allow us to stop early. 2019-02-22 17:21:03,380 - main.py[DEBUG]: Execution continuing, no previous run detected that would allow us to stop early. 2019-02-22 17:21:03,380 - handlers.py[DEBUG]: start: init-network/check-cache: attempting to read from cache [trust] 2019-02-22 17:21:03,380 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False) 2019-02-22 17:21:03,380 - stages.py[DEBUG]: no cache found 2019-02-22 17:21:03,380 - handlers.py[DEBUG]: finish: init-network/check-cache: SUCCESS: no cache found 2019-02-22 17:21:03,380 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2019-02-22 17:21:03,382 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'> 2019-02-22 17:21:03,382 - __init__.py[DEBUG]: Looking for for data source in: ['Ec2'], via packages ['', 'cloudinit.sources'] that matches dependencies ['FILESYSTEM', 'NETWORK'] 2019-02-22 17:21:03,383 - __init__.py[DEBUG]: Searching for network data source in: ['DataSourceEc2'] 2019-02-22 17:21:03,383 - handlers.py[DEBUG]: start: init-network/search-Ec2: searching for network data from DataSourceEc2 2019-02-22 17:21:03,383 - __init__.py[DEBUG]: Seeing if we can get any data from <class 'cloudinit.sources.DataSourceEc2.DataSourceEc2'> 2019-02-22 17:21:03,384 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/ec2/meta-data (quiet=False) 2019-02-22 17:21:03,493 - DataSourceEc2.py[DEBUG]: Removed the following from metadata urls: ['http://instance-data.:8773'] 2019-02-22 17:21:03,493 - url_helper.py[DEBUG]: [0/1] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 50.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,501 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/instance-id (200, 19b) after 1 attempts 2019-02-22 17:21:03,501 - DataSourceEc2.py[DEBUG]: Using metadata source: 'http://169.254.169.254' 2019-02-22 17:21:03,501 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/user-data' with {'url': 'http://169.254.169.254/2009-04-04/user-data', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,503 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/user-data (200, 4848b) after 1 attempts 2019-02-22 17:21:03,504 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,505 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/ (200, 203b) after 1 attempts 2019-02-22 17:21:03,506 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,507 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ (200, 291b) after 1 attempts 2019-02-22 17:21:03,508 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral4' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral4', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,509 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral4 (200, 5b) after 1 attempts 2019-02-22 17:21:03,509 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral0' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral0', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,511 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral0 (200, 5b) after 1 attempts 2019-02-22 17:21:03,511 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/root' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/root', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,513 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/root (200, 4b) after 1 attempts 2019-02-22 17:21:03,513 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral8' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral8', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,515 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral8 (200, 5b) after 1 attempts 2019-02-22 17:21:03,515 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral12' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral12', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,516 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral12 (200, 5b) after 1 attempts 2019-02-22 17:21:03,517 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ami' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ami', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,518 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ami (200, 4b) after 1 attempts 2019-02-22 17:21:03,518 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral5' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral5', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,520 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral5 (200, 5b) after 1 attempts 2019-02-22 17:21:03,520 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral22' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral22', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,522 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral22 (200, 5b) after 1 attempts 2019-02-22 17:21:03,522 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral6' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral6', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,523 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral6 (200, 5b) after 1 attempts 2019-02-22 17:21:03,524 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral10' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral10', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,525 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral10 (200, 5b) after 1 attempts 2019-02-22 17:21:03,525 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral17' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral17', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,527 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral17 (200, 5b) after 1 attempts 2019-02-22 17:21:03,527 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral13' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral13', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,529 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral13 (200, 5b) after 1 attempts 2019-02-22 17:21:03,529 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral15' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral15', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,531 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral15 (200, 5b) after 1 attempts 2019-02-22 17:21:03,531 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral19' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral19', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,532 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral19 (200, 5b) after 1 attempts 2019-02-22 17:21:03,533 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral1' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral1', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,534 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral1 (200, 5b) after 1 attempts 2019-02-22 17:21:03,534 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral18' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral18', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,536 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral18 (200, 5b) after 1 attempts 2019-02-22 17:21:03,536 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral20' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral20', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,538 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral20 (200, 5b) after 1 attempts 2019-02-22 17:21:03,538 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral21' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral21', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,539 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral21 (200, 5b) after 1 attempts 2019-02-22 17:21:03,539 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral7' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral7', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,541 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral7 (200, 5b) after 1 attempts 2019-02-22 17:21:03,541 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral16' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral16', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,543 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral16 (200, 5b) after 1 attempts 2019-02-22 17:21:03,543 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral11' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral11', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,545 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral11 (200, 5b) after 1 attempts 2019-02-22 17:21:03,545 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral14' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral14', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,547 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral14 (200, 5b) after 1 attempts 2019-02-22 17:21:03,547 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral23' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral23', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,549 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral23 (200, 5b) after 1 attempts 2019-02-22 17:21:03,549 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ebs1' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ebs1', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,550 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ebs1 (200, 4b) after 1 attempts 2019-02-22 17:21:03,550 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral9' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral9', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,552 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral9 (200, 5b) after 1 attempts 2019-02-22 17:21:03,552 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral2' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral2', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,554 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral2 (200, 5b) after 1 attempts 2019-02-22 17:21:03,554 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral3' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral3', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,555 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/block-device-mapping/ephemeral3 (200, 5b) after 1 attempts 2019-02-22 17:21:03,556 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/placement/' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/placement/', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,557 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/placement/ (200, 17b) after 1 attempts 2019-02-22 17:21:03,557 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/placement/availability-zone' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/placement/availability-zone', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,559 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/placement/availability-zone (200, 10b) after 1 attempts 2019-02-22 17:21:03,559 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/public-keys/' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/public-keys/', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,561 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/public-keys/ (200, 17b) after 1 attempts 2019-02-22 17:21:03,561 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/public-keys/0/openssh-key' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/public-keys/0/openssh-key', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,562 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/public-keys/0/openssh-key (200, 397b) after 1 attempts 2019-02-22 17:21:03,563 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/reservation-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/reservation-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,564 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/reservation-id (200, 19b) after 1 attempts 2019-02-22 17:21:03,564 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/ami-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/ami-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,566 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/ami-id (200, 21b) after 1 attempts 2019-02-22 17:21:03,566 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/ami-launch-index' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/ami-launch-index', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,568 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/ami-launch-index (200, 1b) after 1 attempts 2019-02-22 17:21:03,568 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/security-groups' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/security-groups', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,569 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/security-groups (200, 67b) after 1 attempts 2019-02-22 17:21:03,570 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/local-hostname' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/local-hostname', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,571 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/local-hostname (200, 28b) after 1 attempts 2019-02-22 17:21:03,571 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/hostname' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/hostname', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,573 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/hostname (200, 28b) after 1 attempts 2019-02-22 17:21:03,573 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/instance-action' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-action', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,575 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/instance-action (200, 4b) after 1 attempts 2019-02-22 17:21:03,575 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/instance-type' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-type', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,577 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/instance-type (200, 10b) after 1 attempts 2019-02-22 17:21:03,577 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/local-ipv4' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/local-ipv4', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,578 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/local-ipv4 (200, 12b) after 1 attempts 2019-02-22 17:21:03,579 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/ami-manifest-path' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/ami-manifest-path', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,580 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/ami-manifest-path (200, 9b) after 1 attempts 2019-02-22 17:21:03,580 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/instance-id' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/instance-id', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,582 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/instance-id (200, 19b) after 1 attempts 2019-02-22 17:21:03,582 - url_helper.py[DEBUG]: [0/6] open 'http://169.254.169.254/2009-04-04/meta-data/profile' with {'url': 'http://169.254.169.254/2009-04-04/meta-data/profile', 'allow_redirects': True, 'method': 'GET', 'timeout': 5.0, 'headers': {'User-Agent': 'Cloud-Init/0.7.9'}} configuration 2019-02-22 17:21:03,584 - url_helper.py[DEBUG]: Read from http://169.254.169.254/2009-04-04/meta-data/profile (200, 11b) after 1 attempts 2019-02-22 17:21:03,584 - DataSourceEc2.py[DEBUG]: Crawl of metadata service took 0 seconds 2019-02-22 17:21:03,584 - handlers.py[DEBUG]: finish: init-network/search-Ec2: SUCCESS: found network data from DataSourceEc2 2019-02-22 17:21:03,584 - stages.py[INFO]: Loaded datasource DataSourceEc2 - DataSourceEc2 2019-02-22 17:21:03,584 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2019-02-22 17:21:03,584 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg 2019-02-22 17:21:03,584 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,592 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99-disable-network-config.cfg (quiet=False) 2019-02-22 17:21:03,593 - util.py[DEBUG]: Read 28 bytes from /etc/cloud/cloud.cfg.d/99-disable-network-config.cfg 2019-02-22 17:21:03,593 - util.py[DEBUG]: Attempting to load yaml from string of length 28 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,593 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2019-02-22 17:21:03,593 - util.py[DEBUG]: Read 87 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2019-02-22 17:21:03,593 - util.py[DEBUG]: Attempting to load yaml from string of length 87 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,593 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2019-02-22 17:21:03,593 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2019-02-22 17:21:03,594 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,596 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/01_debian_cloud.cfg (quiet=False) 2019-02-22 17:21:03,596 - util.py[DEBUG]: Read 336 bytes from /etc/cloud/cloud.cfg.d/01_debian_cloud.cfg 2019-02-22 17:21:03,597 - util.py[DEBUG]: Attempting to load yaml from string of length 336 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,598 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False) 2019-02-22 17:21:03,599 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg 2019-02-22 17:21:03,599 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,600 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,600 - util.py[DEBUG]: load_yaml given empty string, returning default 2019-02-22 17:21:03,600 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2019-02-22 17:21:03,600 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/i-00a7b461305b62f02' 2019-02-22 17:21:03,602 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/i-00a7b461305b62f02/datasource (quiet=False) 2019-02-22 17:21:03,602 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/datasource - wb: [420] 29 bytes 2019-02-22 17:21:03,602 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [420] 29 bytes 2019-02-22 17:21:03,603 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False) 2019-02-22 17:21:03,603 - util.py[DEBUG]: Read 20 bytes from /var/lib/cloud/data/instance-id 2019-02-22 17:21:03,603 - stages.py[DEBUG]: previous iid found to be i-01d620471b1d427ac 2019-02-22 17:21:03,603 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [420] 20 bytes 2019-02-22 17:21:03,603 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [420] 20 bytes 2019-02-22 17:21:03,604 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [420] 20 bytes 2019-02-22 17:21:03,604 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [256] 11742 bytes 2019-02-22 17:21:03,604 - main.py[DEBUG]: [net] init will now be targeting instance id: i-00a7b461305b62f02. new=True 2019-02-22 17:21:03,605 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2019-02-22 17:21:03,605 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg 2019-02-22 17:21:03,605 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,612 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99-disable-network-config.cfg (quiet=False) 2019-02-22 17:21:03,612 - util.py[DEBUG]: Read 28 bytes from /etc/cloud/cloud.cfg.d/99-disable-network-config.cfg 2019-02-22 17:21:03,613 - util.py[DEBUG]: Attempting to load yaml from string of length 28 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,613 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2019-02-22 17:21:03,613 - util.py[DEBUG]: Read 87 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2019-02-22 17:21:03,613 - util.py[DEBUG]: Attempting to load yaml from string of length 87 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,613 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2019-02-22 17:21:03,613 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2019-02-22 17:21:03,613 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,616 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/01_debian_cloud.cfg (quiet=False) 2019-02-22 17:21:03,616 - util.py[DEBUG]: Read 336 bytes from /etc/cloud/cloud.cfg.d/01_debian_cloud.cfg 2019-02-22 17:21:03,616 - util.py[DEBUG]: Attempting to load yaml from string of length 336 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,618 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False) 2019-02-22 17:21:03,619 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg 2019-02-22 17:21:03,619 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,620 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,620 - util.py[DEBUG]: load_yaml given empty string, returning default 2019-02-22 17:21:03,620 - stages.py[DEBUG]: network config disabled by system_cfg 2019-02-22 17:21:03,620 - stages.py[INFO]: network config is disabled by system_cfg 2019-02-22 17:21:03,620 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/user-data.txt - wb: [384] 4848 bytes 2019-02-22 17:21:03,622 - util.py[DEBUG]: Attempting to load yaml from string of length 1607 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,626 - util.py[DEBUG]: Attempting to load yaml from string of length 666 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,628 - util.py[DEBUG]: Attempting to load yaml from string of length 277 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:03,631 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/user-data.txt.i - wb: [384] 5196 bytes 2019-02-22 17:21:03,632 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/vendor-data.txt - wb: [384] 0 bytes 2019-02-22 17:21:03,633 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/vendor-data.txt.i - wb: [384] 308 bytes 2019-02-22 17:21:03,633 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'> 2019-02-22 17:21:03,633 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/consume_data - wb: [420] 24 bytes 2019-02-22 17:21:03,634 - helpers.py[DEBUG]: Running consume_data using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/consume_data'>) 2019-02-22 17:21:03,634 - handlers.py[DEBUG]: start: init-network/consume-user-data: reading and applying user-data 2019-02-22 17:21:03,634 - launch_index.py[DEBUG]: Discarding 0 multipart messages which do not match launch index 0 2019-02-22 17:21:03,634 - stages.py[DEBUG]: Added default handler for {'text/cloud-config-jsonp', 'text/cloud-config'} from CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] 2019-02-22 17:21:03,634 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript'} from ShellScriptPartHandler: [['text/x-shellscript']] 2019-02-22 17:21:03,635 - stages.py[DEBUG]: Added default handler for {'text/cloud-boothook'} from BootHookPartHandler: [['text/cloud-boothook']] 2019-02-22 17:21:03,635 - stages.py[DEBUG]: Added default handler for {'text/upstart-job'} from UpstartJobPartHandler: [['text/upstart-job']] 2019-02-22 17:21:03,635 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__begin__, None, 3) with frequency once-per-instance 2019-02-22 17:21:03,635 - __init__.py[DEBUG]: Calling handler UpstartJobPartHandler: [['text/upstart-job']] (__begin__, None, 2) with frequency once-per-instance 2019-02-22 17:21:03,635 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__begin__, None, 2) with frequency once-per-instance 2019-02-22 17:21:03,635 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__begin__, None, 2) with frequency once-per-instance 2019-02-22 17:21:03,635 - __init__.py[DEBUG]: {'Content-Type': 'text/cloud-boothook', 'Content-Transfer-Encoding': '7bit', 'Mime-Version': '1.0', 'Content-Disposition': 'attachment; filename="part-001"'} 2019-02-22 17:21:03,635 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (text/cloud-boothook, part-001, 2) with frequency once-per-instance 2019-02-22 17:21:03,635 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/boothooks/part-001 - wb: [448] 1620 bytes 2019-02-22 17:21:03,636 - util.py[DEBUG]: Running command ['/var/lib/cloud/instances/i-00a7b461305b62f02/boothooks/part-001'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:24,095 - __init__.py[DEBUG]: {'X-Merge-Type': 'list(append)+dict(recurse_array)+str()', 'Content-Type': 'text/cloud-config', 'Content-Transfer-Encoding': '7bit', 'Mime-Version': '1.0', 'Content-Disposition': 'attachment; filename="part-002"'} 2019-02-22 17:21:24,095 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (text/cloud-config, part-002, 3) with frequency once-per-instance 2019-02-22 17:21:24,096 - util.py[DEBUG]: Attempting to load yaml from string of length 1607 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:24,100 - cloud_config.py[DEBUG]: Merging by applying [('list', ['append']), ('dict', ['recurse_array']), ('str', [])] 2019-02-22 17:21:24,100 - __init__.py[DEBUG]: {'X-Merge-Type': 'list(append)+dict(recurse_array)+str()', 'Content-Type': 'text/cloud-config', 'Content-Transfer-Encoding': '7bit', 'Mime-Version': '1.0', 'Content-Disposition': 'attachment; filename="part-003"'} 2019-02-22 17:21:24,100 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (text/cloud-config, part-003, 3) with frequency once-per-instance 2019-02-22 17:21:24,100 - util.py[DEBUG]: Attempting to load yaml from string of length 666 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:24,102 - cloud_config.py[DEBUG]: Merging by applying [('list', ['append']), ('dict', ['recurse_array']), ('str', [])] 2019-02-22 17:21:24,102 - __init__.py[DEBUG]: {'X-Merge-Type': 'list(append)+dict(recurse_array)+str()', 'Content-Type': 'text/cloud-config', 'Content-Transfer-Encoding': '7bit', 'Mime-Version': '1.0', 'Content-Disposition': 'attachment; filename="part-004"'} 2019-02-22 17:21:24,103 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (text/cloud-config, part-004, 3) with frequency once-per-instance 2019-02-22 17:21:24,103 - util.py[DEBUG]: Attempting to load yaml from string of length 277 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:24,103 - cloud_config.py[DEBUG]: Merging by applying [('list', ['append']), ('dict', ['recurse_array']), ('str', [])] 2019-02-22 17:21:24,104 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__end__, None, 3) with frequency once-per-instance 2019-02-22 17:21:24,107 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/cloud-config.txt - wb: [384] 2322 bytes 2019-02-22 17:21:24,107 - __init__.py[DEBUG]: Calling handler UpstartJobPartHandler: [['text/upstart-job']] (__end__, None, 2) with frequency once-per-instance 2019-02-22 17:21:24,108 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__end__, None, 2) with frequency once-per-instance 2019-02-22 17:21:24,108 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__end__, None, 2) with frequency once-per-instance 2019-02-22 17:21:24,108 - handlers.py[DEBUG]: finish: init-network/consume-user-data: SUCCESS: reading and applying user-data 2019-02-22 17:21:24,108 - handlers.py[DEBUG]: start: init-network/consume-vendor-data: reading and applying vendor-data 2019-02-22 17:21:24,108 - stages.py[DEBUG]: no vendordata from datasource 2019-02-22 17:21:24,108 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data: SUCCESS: reading and applying vendor-data 2019-02-22 17:21:24,108 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2019-02-22 17:21:24,108 - util.py[DEBUG]: Read 2518 bytes from /etc/cloud/cloud.cfg 2019-02-22 17:21:24,108 - util.py[DEBUG]: Attempting to load yaml from string of length 2518 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:24,116 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99-disable-network-config.cfg (quiet=False) 2019-02-22 17:21:24,116 - util.py[DEBUG]: Read 28 bytes from /etc/cloud/cloud.cfg.d/99-disable-network-config.cfg 2019-02-22 17:21:24,116 - util.py[DEBUG]: Attempting to load yaml from string of length 28 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:24,116 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2019-02-22 17:21:24,116 - util.py[DEBUG]: Read 87 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2019-02-22 17:21:24,116 - util.py[DEBUG]: Attempting to load yaml from string of length 87 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:24,117 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2019-02-22 17:21:24,117 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2019-02-22 17:21:24,117 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:24,120 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/01_debian_cloud.cfg (quiet=False) 2019-02-22 17:21:24,120 - util.py[DEBUG]: Read 336 bytes from /etc/cloud/cloud.cfg.d/01_debian_cloud.cfg 2019-02-22 17:21:24,120 - util.py[DEBUG]: Attempting to load yaml from string of length 336 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:24,122 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/00_debian.cfg (quiet=False) 2019-02-22 17:21:24,122 - util.py[DEBUG]: Read 93 bytes from /etc/cloud/cloud.cfg.d/00_debian.cfg 2019-02-22 17:21:24,122 - util.py[DEBUG]: Attempting to load yaml from string of length 93 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:24,123 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:24,123 - util.py[DEBUG]: load_yaml given empty string, returning default 2019-02-22 17:21:24,123 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2019-02-22 17:21:24,123 - util.py[DEBUG]: Read 2322 bytes from /var/lib/cloud/instance/cloud-config.txt 2019-02-22 17:21:24,123 - util.py[DEBUG]: Attempting to load yaml from string of length 2322 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:24,130 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2019-02-22 17:21:24,130 - util.py[DEBUG]: Read 2322 bytes from /var/lib/cloud/instance/cloud-config.txt 2019-02-22 17:21:24,130 - util.py[DEBUG]: Attempting to load yaml from string of length 2322 with allowed root types (<class 'dict'>,) 2019-02-22 17:21:24,137 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [256] 16166 bytes 2019-02-22 17:21:24,150 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'> 2019-02-22 17:21:24,150 - 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 2019-02-22 17:21:24,151 - handlers.py[DEBUG]: start: init-network/config-migrator: running config-migrator with frequency always 2019-02-22 17:21:24,151 - helpers.py[DEBUG]: Running config-migrator using lock (<cloudinit.helpers.DummyLock object at 0x7f33cfe71ac8>) 2019-02-22 17:21:24,151 - cc_migrator.py[DEBUG]: Migrated 0 semaphore files to there canonicalized names 2019-02-22 17:21:24,151 - handlers.py[DEBUG]: finish: init-network/config-migrator: SUCCESS: config-migrator ran successfully 2019-02-22 17:21:24,151 - 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 2019-02-22 17:21:24,152 - handlers.py[DEBUG]: start: init-network/config-seed_random: running config-seed_random with frequency once-per-instance 2019-02-22 17:21:24,152 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_seed_random - wb: [420] 24 bytes 2019-02-22 17:21:24,152 - helpers.py[DEBUG]: Running config-seed_random using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_seed_random'>) 2019-02-22 17:21:24,152 - cc_seed_random.py[DEBUG]: no command provided 2019-02-22 17:21:24,152 - handlers.py[DEBUG]: finish: init-network/config-seed_random: SUCCESS: config-seed_random ran successfully 2019-02-22 17:21:24,152 - 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 2019-02-22 17:21:24,153 - handlers.py[DEBUG]: start: init-network/config-bootcmd: running config-bootcmd with frequency always 2019-02-22 17:21:24,153 - helpers.py[DEBUG]: Running config-bootcmd using lock (<cloudinit.helpers.DummyLock object at 0x7f33d0360f28>) 2019-02-22 17:21:24,153 - util.py[DEBUG]: Created temporary file /tmp/tmpvyyv7khu.sh 2019-02-22 17:21:24,153 - util.py[DEBUG]: Shellified 1 commands. 2019-02-22 17:21:24,153 - util.py[DEBUG]: Running command ['/bin/sh', '/tmp/tmpvyyv7khu.sh'] with allowed return codes [0] (shell=False, capture=False) 2019-02-22 17:21:24,155 - handlers.py[DEBUG]: finish: init-network/config-bootcmd: SUCCESS: config-bootcmd ran successfully 2019-02-22 17:21:24,155 - 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 2019-02-22 17:21:24,155 - handlers.py[DEBUG]: start: init-network/config-write-files: running config-write-files with frequency once-per-instance 2019-02-22 17:21:24,156 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_write_files - wb: [420] 24 bytes 2019-02-22 17:21:24,156 - helpers.py[DEBUG]: Running config-write-files using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_write_files'>) 2019-02-22 17:21:24,156 - util.py[DEBUG]: Writing to /etc/ecs/ecs.config - wb: [420] 261 bytes 2019-02-22 17:21:24,157 - util.py[DEBUG]: Changing the ownership of /etc/ecs/ecs.config to 0:0 2019-02-22 17:21:24,157 - util.py[DEBUG]: Writing to /etc/salt/grains - wb: [420] 18 bytes 2019-02-22 17:21:24,157 - util.py[DEBUG]: Changing the ownership of /etc/salt/grains to 0:0 2019-02-22 17:21:24,158 - util.py[DEBUG]: Writing to /etc/salt/minion - wb: [420] 154 bytes 2019-02-22 17:21:24,158 - util.py[DEBUG]: Changing the ownership of /etc/salt/minion to 0:0 2019-02-22 17:21:24,158 - handlers.py[DEBUG]: finish: init-network/config-write-files: SUCCESS: config-write-files ran successfully 2019-02-22 17:21:24,158 - 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 2019-02-22 17:21:24,158 - handlers.py[DEBUG]: start: init-network/config-growpart: running config-growpart with frequency always 2019-02-22 17:21:24,158 - helpers.py[DEBUG]: Running config-growpart using lock (<cloudinit.helpers.DummyLock object at 0x7f33cfe77710>) 2019-02-22 17:21:24,158 - cc_growpart.py[DEBUG]: No 'growpart' entry in cfg. Using default: {'ignore_growroot_disabled': False, 'mode': 'auto', 'devices': ['/']} 2019-02-22 17:21:24,158 - util.py[DEBUG]: Running command ['growpart', '--help'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:24,162 - util.py[DEBUG]: Reading from /proc/543/mountinfo (quiet=False) 2019-02-22 17:21:24,163 - util.py[DEBUG]: Read 2552 bytes from /proc/543/mountinfo 2019-02-22 17:21:24,166 - util.py[DEBUG]: Reading from /sys/class/block/nvme0n1p1/partition (quiet=False) 2019-02-22 17:21:24,167 - util.py[DEBUG]: Read 2 bytes from /sys/class/block/nvme0n1p1/partition 2019-02-22 17:21:24,167 - util.py[DEBUG]: Reading from /sys/devices/pci0000:00/0000:00:04.0/nvme/nvme0/nvme0n1/dev (quiet=False) 2019-02-22 17:21:24,167 - util.py[DEBUG]: Read 6 bytes from /sys/devices/pci0000:00/0000:00:04.0/nvme/nvme0/nvme0n1/dev 2019-02-22 17:21:24,167 - util.py[DEBUG]: Running command ['growpart', '--dry-run', '/dev/nvme0n1', '1'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:24,275 - util.py[DEBUG]: Running command ['growpart', '/dev/nvme0n1', '1'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:24,329 - util.py[DEBUG]: resize_devices took 0.167 seconds 2019-02-22 17:21:24,330 - cc_growpart.py[INFO]: '/' resized: changed (/dev/nvme0n1, 1) from 8588886016 to 21473771008 2019-02-22 17:21:24,330 - handlers.py[DEBUG]: finish: init-network/config-growpart: SUCCESS: config-growpart ran successfully 2019-02-22 17:21:24,330 - 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 2019-02-22 17:21:24,330 - handlers.py[DEBUG]: start: init-network/config-resizefs: running config-resizefs with frequency always 2019-02-22 17:21:24,330 - helpers.py[DEBUG]: Running config-resizefs using lock (<cloudinit.helpers.DummyLock object at 0x7f33cfe77a58>) 2019-02-22 17:21:24,330 - util.py[DEBUG]: Reading from /proc/543/mountinfo (quiet=False) 2019-02-22 17:21:24,330 - util.py[DEBUG]: Read 2552 bytes from /proc/543/mountinfo 2019-02-22 17:21:24,331 - cc_resizefs.py[DEBUG]: resize_info: dev=/dev/nvme0n1p1 mnt_point=/ path=/ 2019-02-22 17:21:24,331 - util.py[DEBUG]: Running command ['systemd-detect-virt', '--quiet', '--container'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:24,333 - util.py[DEBUG]: Running command ['running-in-container'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:24,335 - util.py[DEBUG]: Running command ['lxc-is-container'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:24,337 - util.py[DEBUG]: Reading from /proc/1/environ (quiet=False) 2019-02-22 17:21:24,337 - util.py[DEBUG]: Read 139 bytes from /proc/1/environ 2019-02-22 17:21:24,337 - util.py[DEBUG]: Reading from /proc/self/status (quiet=False) 2019-02-22 17:21:24,337 - util.py[DEBUG]: Read 1006 bytes from /proc/self/status 2019-02-22 17:21:24,337 - cc_resizefs.py[DEBUG]: Resizing / (ext4) using resize2fs /dev/nvme0n1p1 2019-02-22 17:21:24,337 - util.py[DEBUG]: Running command ('resize2fs', '/dev/nvme0n1p1') with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:25,001 - util.py[DEBUG]: Resizing took 0.664 seconds 2019-02-22 17:21:25,001 - cc_resizefs.py[DEBUG]: Resized root filesystem (type=ext4, val=True) 2019-02-22 17:21:25,001 - handlers.py[DEBUG]: finish: init-network/config-resizefs: SUCCESS: config-resizefs ran successfully 2019-02-22 17:21:25,001 - 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 2019-02-22 17:21:25,002 - handlers.py[DEBUG]: start: init-network/config-disk_setup: running config-disk_setup with frequency once-per-instance 2019-02-22 17:21:25,002 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_disk_setup - wb: [420] 24 bytes 2019-02-22 17:21:25,002 - helpers.py[DEBUG]: Running config-disk_setup using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_disk_setup'>) 2019-02-22 17:21:25,002 - handlers.py[DEBUG]: finish: init-network/config-disk_setup: SUCCESS: config-disk_setup ran successfully 2019-02-22 17:21:25,002 - 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 2019-02-22 17:21:25,003 - handlers.py[DEBUG]: start: init-network/config-mounts: running config-mounts with frequency once-per-instance 2019-02-22 17:21:25,003 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_mounts - wb: [420] 24 bytes 2019-02-22 17:21:25,003 - helpers.py[DEBUG]: Running config-mounts using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_mounts'>) 2019-02-22 17:21:25,003 - cc_mounts.py[DEBUG]: mounts configuration is [['/dev/ebs/data', '/mnt', 'xfs', 'defaults,nofail,noatime,pquota', 0, 2]] 2019-02-22 17:21:25,003 - cc_mounts.py[DEBUG]: Attempting to determine the real name of /dev/ebs/data 2019-02-22 17:21:25,003 - cc_mounts.py[DEBUG]: Attempting to determine the real name of ephemeral0 2019-02-22 17:21:25,003 - cc_mounts.py[DEBUG]: Ignoring nonexistant default named mount ephemeral0 2019-02-22 17:21:25,003 - cc_mounts.py[DEBUG]: Attempting to determine the real name of swap 2019-02-22 17:21:25,003 - DataSourceEc2.py[DEBUG]: Unable to convert swap to a device 2019-02-22 17:21:25,004 - cc_mounts.py[DEBUG]: Ignoring nonexistant default named mount swap 2019-02-22 17:21:25,004 - cc_mounts.py[DEBUG]: no need to setup swap 2019-02-22 17:21:25,004 - util.py[DEBUG]: Reading from /etc/fstab (quiet=False) 2019-02-22 17:21:25,004 - util.py[DEBUG]: Read 232 bytes from /etc/fstab 2019-02-22 17:21:25,004 - util.py[DEBUG]: Writing to /etc/fstab - wb: [420] 310 bytes 2019-02-22 17:21:25,004 - cc_mounts.py[DEBUG]: Changes to fstab: ['+ /dev/ebs/data /mnt xfs defaults,nofail,noatime,pquota,comment=cloudconfig 0 2'] 2019-02-22 17:21:25,004 - util.py[DEBUG]: Running command ['mount', '-a'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:25,032 - cc_mounts.py[DEBUG]: Activate mounts: PASS:mount -a 2019-02-22 17:21:25,032 - util.py[DEBUG]: Running command ['systemctl', 'daemon-reload'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:25,064 - cc_mounts.py[DEBUG]: Activate mounts: PASS:systemctl daemon-reload 2019-02-22 17:21:25,064 - handlers.py[DEBUG]: finish: init-network/config-mounts: SUCCESS: config-mounts ran successfully 2019-02-22 17:21:25,065 - 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 2019-02-22 17:21:25,065 - handlers.py[DEBUG]: start: init-network/config-set_hostname: running config-set_hostname with frequency once-per-instance 2019-02-22 17:21:25,065 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_set_hostname - wb: [420] 24 bytes 2019-02-22 17:21:25,066 - helpers.py[DEBUG]: Running config-set_hostname using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_set_hostname'>) 2019-02-22 17:21:25,066 - cc_set_hostname.py[DEBUG]: Setting the hostname to ip-172-18-5-192.eu-prod.wkda (ip-172-18-5-192) 2019-02-22 17:21:25,066 - util.py[DEBUG]: Reading from /etc/hostname (quiet=False) 2019-02-22 17:21:25,066 - util.py[DEBUG]: Read 16 bytes from /etc/hostname 2019-02-22 17:21:25,066 - util.py[DEBUG]: Writing to /etc/hostname - wb: [420] 16 bytes 2019-02-22 17:21:25,066 - __init__.py[DEBUG]: Non-persistently setting the system hostname to ip-172-18-5-192 2019-02-22 17:21:25,066 - util.py[DEBUG]: Running command ['hostname', 'ip-172-18-5-192'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:25,068 - handlers.py[DEBUG]: finish: init-network/config-set_hostname: SUCCESS: config-set_hostname ran successfully 2019-02-22 17:21:25,068 - 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 2019-02-22 17:21:25,069 - handlers.py[DEBUG]: start: init-network/config-update_hostname: running config-update_hostname with frequency always 2019-02-22 17:21:25,069 - helpers.py[DEBUG]: Running config-update_hostname using lock (<cloudinit.helpers.DummyLock object at 0x7f33cfe77a20>) 2019-02-22 17:21:25,069 - cc_update_hostname.py[DEBUG]: Updating hostname to ip-172-18-5-192.eu-prod.wkda (ip-172-18-5-192) 2019-02-22 17:21:25,069 - util.py[DEBUG]: Reading from /var/lib/cloud/data/previous-hostname (quiet=False) 2019-02-22 17:21:25,070 - util.py[DEBUG]: Read 16 bytes from /var/lib/cloud/data/previous-hostname 2019-02-22 17:21:25,070 - util.py[DEBUG]: Reading from /etc/hostname (quiet=False) 2019-02-22 17:21:25,070 - util.py[DEBUG]: Read 16 bytes from /etc/hostname 2019-02-22 17:21:25,070 - __init__.py[INFO]: /var/lib/cloud/data/previous-hostname differs from /etc/hostname, assuming user maintained hostname. 2019-02-22 17:21:25,070 - handlers.py[DEBUG]: finish: init-network/config-update_hostname: SUCCESS: config-update_hostname ran successfully 2019-02-22 17:21:25,070 - 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 2019-02-22 17:21:25,070 - handlers.py[DEBUG]: start: init-network/config-update_etc_hosts: running config-update_etc_hosts with frequency always 2019-02-22 17:21:25,070 - helpers.py[DEBUG]: Running config-update_etc_hosts using lock (<cloudinit.helpers.DummyLock object at 0x7f33cfe77eb8>) 2019-02-22 17:21:25,071 - util.py[DEBUG]: Reading from /etc/cloud/templates/hosts.debian.tmpl (quiet=False) 2019-02-22 17:21:25,071 - util.py[DEBUG]: Read 887 bytes from /etc/cloud/templates/hosts.debian.tmpl 2019-02-22 17:21:25,071 - templater.py[DEBUG]: Rendering content of '/etc/cloud/templates/hosts.debian.tmpl' using renderer jinja 2019-02-22 17:21:25,074 - util.py[DEBUG]: Writing to /etc/hosts - wb: [420] 619 bytes 2019-02-22 17:21:25,074 - handlers.py[DEBUG]: finish: init-network/config-update_etc_hosts: SUCCESS: config-update_etc_hosts ran successfully 2019-02-22 17:21:25,074 - 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 2019-02-22 17:21:25,075 - handlers.py[DEBUG]: start: init-network/config-ca-certs: running config-ca-certs with frequency once-per-instance 2019-02-22 17:21:25,075 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_ca_certs - wb: [420] 24 bytes 2019-02-22 17:21:25,075 - helpers.py[DEBUG]: Running config-ca-certs using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_ca_certs'>) 2019-02-22 17:21:25,075 - cc_ca_certs.py[DEBUG]: Skipping module named ca-certs, no 'ca-certs' key in configuration 2019-02-22 17:21:25,075 - handlers.py[DEBUG]: finish: init-network/config-ca-certs: SUCCESS: config-ca-certs ran successfully 2019-02-22 17:21:25,075 - 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 2019-02-22 17:21:25,076 - handlers.py[DEBUG]: start: init-network/config-rsyslog: running config-rsyslog with frequency once-per-instance 2019-02-22 17:21:25,076 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_rsyslog - wb: [420] 24 bytes 2019-02-22 17:21:25,076 - helpers.py[DEBUG]: Running config-rsyslog using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_rsyslog'>) 2019-02-22 17:21:25,076 - cc_rsyslog.py[DEBUG]: Skipping module named rsyslog, no 'rsyslog' key in configuration 2019-02-22 17:21:25,076 - handlers.py[DEBUG]: finish: init-network/config-rsyslog: SUCCESS: config-rsyslog ran successfully 2019-02-22 17:21:25,076 - 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 2019-02-22 17:21:25,076 - handlers.py[DEBUG]: start: init-network/config-users-groups: running config-users-groups with frequency once-per-instance 2019-02-22 17:21:25,076 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_users_groups - wb: [420] 24 bytes 2019-02-22 17:21:25,077 - helpers.py[DEBUG]: Running config-users-groups using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_users_groups'>) 2019-02-22 17:21:25,077 - __init__.py[INFO]: User admin already exists, skipping. 2019-02-22 17:21:25,077 - util.py[DEBUG]: Running command ['passwd', '-l', 'admin'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:25,089 - util.py[DEBUG]: Reading from /etc/sudoers (quiet=False) 2019-02-22 17:21:25,089 - util.py[DEBUG]: Read 487 bytes from /etc/sudoers 2019-02-22 17:21:25,090 - util.py[DEBUG]: Writing to /etc/sudoers.d/90-cloud-init-users - ab: [None] 53 bytes 2019-02-22 17:21:25,091 - handlers.py[DEBUG]: finish: init-network/config-users-groups: SUCCESS: config-users-groups ran successfully 2019-02-22 17:21:25,091 - 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 2019-02-22 17:21:25,091 - handlers.py[DEBUG]: start: init-network/config-ssh: running config-ssh with frequency once-per-instance 2019-02-22 17:21:25,091 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_ssh - wb: [420] 24 bytes 2019-02-22 17:21:25,092 - helpers.py[DEBUG]: Running config-ssh using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_ssh'>) 2019-02-22 17:21:25,092 - util.py[DEBUG]: Attempting to remove /etc/ssh/ssh_host_rsa_key.pub 2019-02-22 17:21:25,093 - util.py[DEBUG]: Attempting to remove /etc/ssh/ssh_host_dsa_key 2019-02-22 17:21:25,093 - util.py[DEBUG]: Attempting to remove /etc/ssh/ssh_host_dsa_key.pub 2019-02-22 17:21:25,093 - util.py[DEBUG]: Attempting to remove /etc/ssh/ssh_host_rsa_key 2019-02-22 17:21:25,093 - util.py[DEBUG]: Attempting to remove /etc/ssh/ssh_host_ecdsa_key.pub 2019-02-22 17:21:25,093 - util.py[DEBUG]: Attempting to remove /etc/ssh/ssh_host_ed25519_key.pub 2019-02-22 17:21:25,093 - util.py[DEBUG]: Attempting to remove /etc/ssh/ssh_host_ed25519_key 2019-02-22 17:21:25,093 - util.py[DEBUG]: Attempting to remove /etc/ssh/ssh_host_ecdsa_key 2019-02-22 17:21:25,093 - 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) 2019-02-22 17:21:25,362 - 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) 2019-02-22 17:21:25,392 - 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) 2019-02-22 17:21:25,396 - 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) 2019-02-22 17:21:25,404 - util.py[DEBUG]: Reading from /etc/ssh/sshd_config (quiet=False) 2019-02-22 17:21:25,493 - util.py[DEBUG]: Read 2977 bytes from /etc/ssh/sshd_config 2019-02-22 17:21:25,494 - util.py[DEBUG]: Reading from /home/admin/.ssh/authorized_keys (quiet=False) 2019-02-22 17:21:25,556 - util.py[DEBUG]: Read 425 bytes from /home/admin/.ssh/authorized_keys 2019-02-22 17:21:25,557 - util.py[DEBUG]: Writing to /home/admin/.ssh/authorized_keys - wb: [384] 822 bytes 2019-02-22 17:21:25,557 - util.py[DEBUG]: Changing the ownership of /home/admin/.ssh/authorized_keys to 1000:1000 2019-02-22 17:21:25,558 - util.py[DEBUG]: Reading from /etc/ssh/sshd_config (quiet=False) 2019-02-22 17:21:25,558 - util.py[DEBUG]: Read 2977 bytes from /etc/ssh/sshd_config 2019-02-22 17:21:25,558 - util.py[DEBUG]: Reading from /root/.ssh/authorized_keys (quiet=False) 2019-02-22 17:21:25,559 - util.py[DEBUG]: Read 579 bytes from /root/.ssh/authorized_keys 2019-02-22 17:21:25,559 - util.py[DEBUG]: Writing to /root/.ssh/authorized_keys - wb: [384] 1130 bytes 2019-02-22 17:21:25,559 - util.py[DEBUG]: Changing the ownership of /root/.ssh/authorized_keys to 0:0 2019-02-22 17:21:25,560 - handlers.py[DEBUG]: finish: init-network/config-ssh: SUCCESS: config-ssh ran successfully 2019-02-22 17:21:25,560 - main.py[DEBUG]: Ran 15 modules with 0 failures 2019-02-22 17:21:25,560 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2019-02-22 17:21:25,560 - util.py[DEBUG]: Read 13 bytes from /proc/uptime 2019-02-22 17:21:25,560 - util.py[DEBUG]: cloud-init mode 'init' took 22.315 seconds (22.31) 2019-02-22 17:21:25,560 - handlers.py[DEBUG]: finish: init-network: SUCCESS: searching for network datasources 2019-02-22 17:21:26,108 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'modules:config' at Fri, 22 Feb 2019 16:21:26 +0000. Up 34.14 seconds. 2019-02-22 17:21:26,117 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'> 2019-02-22 17:21:26,118 - 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 2019-02-22 17:21:26,118 - handlers.py[DEBUG]: start: modules-config/config-emit_upstart: running config-emit_upstart with frequency always 2019-02-22 17:21:26,118 - helpers.py[DEBUG]: Running config-emit_upstart using lock (<cloudinit.helpers.DummyLock object at 0x7faaa540a358>) 2019-02-22 17:21:26,118 - cc_emit_upstart.py[DEBUG]: no /sbin/initctl located 2019-02-22 17:21:26,118 - cc_emit_upstart.py[DEBUG]: not upstart system, 'emit_upstart' disabled 2019-02-22 17:21:26,119 - handlers.py[DEBUG]: finish: modules-config/config-emit_upstart: SUCCESS: config-emit_upstart ran successfully 2019-02-22 17:21:26,119 - 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 2019-02-22 17:21:26,119 - handlers.py[DEBUG]: start: modules-config/config-ssh-import-id: running config-ssh-import-id with frequency once-per-instance 2019-02-22 17:21:26,119 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_ssh_import_id - wb: [420] 25 bytes 2019-02-22 17:21:26,119 - helpers.py[DEBUG]: Running config-ssh-import-id using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_ssh_import_id'>) 2019-02-22 17:21:26,120 - handlers.py[DEBUG]: finish: modules-config/config-ssh-import-id: SUCCESS: config-ssh-import-id ran successfully 2019-02-22 17:21:26,120 - 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 2019-02-22 17:21:26,120 - handlers.py[DEBUG]: start: modules-config/config-locale: running config-locale with frequency once-per-instance 2019-02-22 17:21:26,120 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_locale - wb: [420] 25 bytes 2019-02-22 17:21:26,120 - helpers.py[DEBUG]: Running config-locale using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_locale'>) 2019-02-22 17:21:26,120 - cc_locale.py[DEBUG]: Setting locale to en_US.UTF-8 2019-02-22 17:21:26,120 - util.py[DEBUG]: Running command ['locale-gen', 'en_US.UTF-8'] with allowed return codes [0] (shell=False, capture=False) 2019-02-22 17:21:27,798 - util.py[DEBUG]: Running command ['update-locale', 'en_US.UTF-8'] with allowed return codes [0] (shell=False, capture=False) 2019-02-22 17:21:28,413 - util.py[DEBUG]: Writing to /etc/default/locale - wb: [420] 87 bytes 2019-02-22 17:21:28,414 - handlers.py[DEBUG]: finish: modules-config/config-locale: SUCCESS: config-locale ran successfully 2019-02-22 17:21:28,414 - 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 2019-02-22 17:21:28,414 - handlers.py[DEBUG]: start: modules-config/config-set-passwords: running config-set-passwords with frequency once-per-instance 2019-02-22 17:21:28,414 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_set_passwords - wb: [420] 24 bytes 2019-02-22 17:21:28,415 - helpers.py[DEBUG]: Running config-set-passwords using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_set_passwords'>) 2019-02-22 17:21:28,415 - handlers.py[DEBUG]: finish: modules-config/config-set-passwords: SUCCESS: config-set-passwords ran successfully 2019-02-22 17:21:28,415 - 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 2019-02-22 17:21:28,415 - handlers.py[DEBUG]: start: modules-config/config-grub-dpkg: running config-grub-dpkg with frequency once-per-instance 2019-02-22 17:21:28,415 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_grub_dpkg - wb: [420] 25 bytes 2019-02-22 17:21:28,415 - helpers.py[DEBUG]: Running config-grub-dpkg using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_grub_dpkg'>) 2019-02-22 17:21:28,416 - cc_grub_dpkg.py[DEBUG]: Setting grub debconf-set-selections with '/dev/sda','false' 2019-02-22 17:21:28,416 - util.py[DEBUG]: Running command ['debconf-set-selections'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:29,945 - handlers.py[DEBUG]: finish: modules-config/config-grub-dpkg: SUCCESS: config-grub-dpkg ran successfully 2019-02-22 17:21:29,945 - 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 2019-02-22 17:21:29,946 - handlers.py[DEBUG]: start: modules-config/config-apt-pipelining: running config-apt-pipelining with frequency once-per-instance 2019-02-22 17:21:29,946 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_apt_pipelining - wb: [420] 25 bytes 2019-02-22 17:21:29,946 - helpers.py[DEBUG]: Running config-apt-pipelining using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_apt_pipelining'>) 2019-02-22 17:21:29,947 - util.py[DEBUG]: Writing to /etc/apt/apt.conf.d/90cloud-init-pipelining - wb: [420] 80 bytes 2019-02-22 17:21:29,947 - cc_apt_pipelining.py[DEBUG]: Wrote /etc/apt/apt.conf.d/90cloud-init-pipelining with apt pipeline depth setting 0 2019-02-22 17:21:29,947 - handlers.py[DEBUG]: finish: modules-config/config-apt-pipelining: SUCCESS: config-apt-pipelining ran successfully 2019-02-22 17:21:29,947 - 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 2019-02-22 17:21:29,947 - handlers.py[DEBUG]: start: modules-config/config-apt-configure: running config-apt-configure with frequency once-per-instance 2019-02-22 17:21:29,947 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_apt_configure - wb: [420] 25 bytes 2019-02-22 17:21:29,948 - helpers.py[DEBUG]: Running config-apt-configure using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_apt_configure'>) 2019-02-22 17:21:29,948 - cc_apt_configure.py[DEBUG]: apt config: convert V2 to V3 format for keys 'apt_preserve_sources_list' 2019-02-22 17:21:29,948 - cc_apt_configure.py[DEBUG]: handling apt (module apt-configure) with apt config '{'preserve_sources_list': True}' 2019-02-22 17:21:29,948 - util.py[DEBUG]: Running command ['lsb_release', '--all'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:30,066 - util.py[DEBUG]: Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:30,069 - cc_apt_configure.py[DEBUG]: got primary mirror: None 2019-02-22 17:21:30,070 - cc_apt_configure.py[DEBUG]: got security mirror: None 2019-02-22 17:21:30,070 - util.py[DEBUG]: Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:21:30,073 - __init__.py[DEBUG]: filtered distro mirror info: {'security': 'http://security.debian.org/', 'primary': 'http://deb.debian.org/debian'} 2019-02-22 17:21:30,073 - cc_apt_configure.py[DEBUG]: Apt Mirror info: {'security': 'http://security.debian.org/', 'MIRROR': 'http://deb.debian.org/debian', 'SECURITY': 'http://security.debian.org/', 'primary': 'http://deb.debian.org/debian', 'PRIMARY': 'http://deb.debian.org/debian'} 2019-02-22 17:21:30,073 - cc_apt_configure.py[DEBUG]: debconf_selections was not set in config 2019-02-22 17:21:30,073 - handlers.py[DEBUG]: finish: modules-config/config-apt-configure: SUCCESS: config-apt-configure ran successfully 2019-02-22 17:21:30,073 - 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 2019-02-22 17:21:30,074 - handlers.py[DEBUG]: start: modules-config/config-ntp: running config-ntp with frequency once-per-instance 2019-02-22 17:21:30,074 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_ntp - wb: [420] 25 bytes 2019-02-22 17:21:30,074 - helpers.py[DEBUG]: Running config-ntp using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_ntp'>) 2019-02-22 17:21:30,074 - cc_ntp.py[DEBUG]: Skipping module named ntp,not present or disabled by cfg 2019-02-22 17:21:30,075 - handlers.py[DEBUG]: finish: modules-config/config-ntp: SUCCESS: config-ntp ran successfully 2019-02-22 17:21:30,075 - 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 2019-02-22 17:21:30,075 - handlers.py[DEBUG]: start: modules-config/config-timezone: running config-timezone with frequency once-per-instance 2019-02-22 17:21:30,075 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_timezone - wb: [420] 25 bytes 2019-02-22 17:21:30,075 - helpers.py[DEBUG]: Running config-timezone using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_timezone'>) 2019-02-22 17:21:30,075 - util.py[DEBUG]: Writing to /etc/timezone - wb: [420] 14 bytes 2019-02-22 17:21:30,076 - util.py[DEBUG]: Attempting to remove /etc/localtime 2019-02-22 17:21:30,076 - handlers.py[DEBUG]: finish: modules-config/config-timezone: SUCCESS: config-timezone ran successfully 2019-02-22 17:21:30,076 - 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 2019-02-22 17:21:30,076 - handlers.py[DEBUG]: start: modules-config/config-disable-ec2-metadata: running config-disable-ec2-metadata with frequency always 2019-02-22 17:21:30,076 - helpers.py[DEBUG]: Running config-disable-ec2-metadata using lock (<cloudinit.helpers.DummyLock object at 0x7faaa542a320>) 2019-02-22 17:21:30,076 - cc_disable_ec2_metadata.py[DEBUG]: Skipping module named disable-ec2-metadata, disabling the ec2 route not enabled 2019-02-22 17:21:30,076 - handlers.py[DEBUG]: finish: modules-config/config-disable-ec2-metadata: SUCCESS: config-disable-ec2-metadata ran successfully 2019-02-22 17:21:30,076 - 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 2019-02-22 17:21:30,077 - handlers.py[DEBUG]: start: modules-config/config-runcmd: running config-runcmd with frequency once-per-instance 2019-02-22 17:21:30,077 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_runcmd - wb: [420] 25 bytes 2019-02-22 17:21:30,077 - helpers.py[DEBUG]: Running config-runcmd using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_runcmd'>) 2019-02-22 17:21:30,077 - util.py[DEBUG]: Shellified 17 commands. 2019-02-22 17:21:30,077 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/scripts/runcmd - wb: [448] 1114 bytes 2019-02-22 17:21:30,078 - handlers.py[DEBUG]: finish: modules-config/config-runcmd: SUCCESS: config-runcmd ran successfully 2019-02-22 17:21:30,078 - 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 2019-02-22 17:21:30,078 - handlers.py[DEBUG]: start: modules-config/config-byobu: running config-byobu with frequency once-per-instance 2019-02-22 17:21:30,078 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_byobu - wb: [420] 24 bytes 2019-02-22 17:21:30,079 - helpers.py[DEBUG]: Running config-byobu using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_byobu'>) 2019-02-22 17:21:30,079 - cc_byobu.py[DEBUG]: Skipping module named byobu, no 'byobu' values found 2019-02-22 17:21:30,079 - handlers.py[DEBUG]: finish: modules-config/config-byobu: SUCCESS: config-byobu ran successfully 2019-02-22 17:21:30,079 - main.py[DEBUG]: Ran 12 modules with 0 failures 2019-02-22 17:21:30,079 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2019-02-22 17:21:30,079 - util.py[DEBUG]: Read 13 bytes from /proc/uptime 2019-02-22 17:21:30,079 - util.py[DEBUG]: cloud-init mode 'modules' took 4.034 seconds (4.03) 2019-02-22 17:21:30,080 - handlers.py[DEBUG]: finish: modules-config: SUCCESS: running modules for config 2019-02-22 17:21:30,531 - util.py[DEBUG]: Cloud-init v. 0.7.9 running 'modules:final' at Fri, 22 Feb 2019 16:21:30 +0000. Up 38.56 seconds. 2019-02-22 17:21:30,547 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.debian.Distro'> 2019-02-22 17:21:30,547 - 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 2019-02-22 17:21:30,548 - handlers.py[DEBUG]: start: modules-final/config-package-update-upgrade-install: running config-package-update-upgrade-install with frequency once-per-instance 2019-02-22 17:21:30,548 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_package_update_upgrade_install - wb: [420] 25 bytes 2019-02-22 17:21:30,548 - helpers.py[DEBUG]: Running config-package-update-upgrade-install using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_package_update_upgrade_install'>) 2019-02-22 17:21:30,548 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/update_sources - wb: [420] 25 bytes 2019-02-22 17:21:30,548 - helpers.py[DEBUG]: Running update-sources using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/update_sources'>) 2019-02-22 17:21:30,549 - util.py[DEBUG]: Running command ['apt-get', '--option=Dpkg::Options::=--force-confold', '--option=Dpkg::options::=--force-unsafe-io', '--assume-yes', '--quiet', 'update'] with allowed return codes [0] (shell=False, capture=False) 2019-02-22 17:21:43,328 - util.py[DEBUG]: apt-update [apt-get --option=Dpkg::Options::=--force-confold --option=Dpkg::options::=--force-unsafe-io --assume-yes --quiet update] took 12.779 seconds 2019-02-22 17:21:43,328 - helpers.py[DEBUG]: update-sources already ran (freq=once-per-instance) 2019-02-22 17:21:43,328 - util.py[DEBUG]: Running command ['apt-get', '--option=Dpkg::Options::=--force-confold', '--option=Dpkg::options::=--force-unsafe-io', '--assume-yes', '--quiet', 'install', 'nfs-common'] with allowed return codes [0] (shell=False, capture=False) 2019-02-22 17:21:43,672 - util.py[DEBUG]: apt-install [apt-get --option=Dpkg::Options::=--force-confold --option=Dpkg::options::=--force-unsafe-io --assume-yes --quiet install nfs-common] took 0.343 seconds 2019-02-22 17:21:43,672 - handlers.py[DEBUG]: finish: modules-final/config-package-update-upgrade-install: SUCCESS: config-package-update-upgrade-install ran successfully 2019-02-22 17:21:43,672 - 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 2019-02-22 17:21:43,672 - handlers.py[DEBUG]: start: modules-final/config-fan: running config-fan with frequency once-per-instance 2019-02-22 17:21:43,673 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_fan - wb: [420] 25 bytes 2019-02-22 17:21:43,673 - helpers.py[DEBUG]: Running config-fan using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_fan'>) 2019-02-22 17:21:43,673 - cc_fan.py[DEBUG]: fan: no 'fan' config entry. disabling 2019-02-22 17:21:43,673 - handlers.py[DEBUG]: finish: modules-final/config-fan: SUCCESS: config-fan ran successfully 2019-02-22 17:21:43,673 - 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 2019-02-22 17:21:43,674 - handlers.py[DEBUG]: start: modules-final/config-puppet: running config-puppet with frequency once-per-instance 2019-02-22 17:21:43,674 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_puppet - wb: [420] 25 bytes 2019-02-22 17:21:43,674 - helpers.py[DEBUG]: Running config-puppet using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_puppet'>) 2019-02-22 17:21:43,674 - cc_puppet.py[DEBUG]: Skipping module named puppet, no 'puppet' configuration found 2019-02-22 17:21:43,674 - handlers.py[DEBUG]: finish: modules-final/config-puppet: SUCCESS: config-puppet ran successfully 2019-02-22 17:21:43,674 - 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 2019-02-22 17:21:43,674 - handlers.py[DEBUG]: start: modules-final/config-chef: running config-chef with frequency once-per-instance 2019-02-22 17:21:43,674 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_chef - wb: [420] 25 bytes 2019-02-22 17:21:43,675 - helpers.py[DEBUG]: Running config-chef using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_chef'>) 2019-02-22 17:21:43,675 - cc_chef.py[DEBUG]: Skipping module named chef, no 'chef' key in configuration 2019-02-22 17:21:43,675 - handlers.py[DEBUG]: finish: modules-final/config-chef: SUCCESS: config-chef ran successfully 2019-02-22 17:21:43,675 - 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 2019-02-22 17:21:43,675 - handlers.py[DEBUG]: start: modules-final/config-salt-minion: running config-salt-minion with frequency once-per-instance 2019-02-22 17:21:43,675 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_salt_minion - wb: [420] 25 bytes 2019-02-22 17:21:43,676 - helpers.py[DEBUG]: Running config-salt-minion using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_salt_minion'>) 2019-02-22 17:21:43,676 - cc_salt_minion.py[DEBUG]: Skipping module named salt-minion, no 'salt_minion' key in configuration 2019-02-22 17:21:43,676 - handlers.py[DEBUG]: finish: modules-final/config-salt-minion: SUCCESS: config-salt-minion ran successfully 2019-02-22 17:21:43,676 - 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 2019-02-22 17:21:43,676 - handlers.py[DEBUG]: start: modules-final/config-mcollective: running config-mcollective with frequency once-per-instance 2019-02-22 17:21:43,676 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_mcollective - wb: [420] 25 bytes 2019-02-22 17:21:43,677 - helpers.py[DEBUG]: Running config-mcollective using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_mcollective'>) 2019-02-22 17:21:43,677 - cc_mcollective.py[DEBUG]: Skipping module named mcollective, no 'mcollective' key in configuration 2019-02-22 17:21:43,677 - handlers.py[DEBUG]: finish: modules-final/config-mcollective: SUCCESS: config-mcollective ran successfully 2019-02-22 17:21:43,677 - 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 2019-02-22 17:21:43,677 - handlers.py[DEBUG]: start: modules-final/config-rightscale_userdata: running config-rightscale_userdata with frequency once-per-instance 2019-02-22 17:21:43,677 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_rightscale_userdata - wb: [420] 25 bytes 2019-02-22 17:21:43,677 - helpers.py[DEBUG]: Running config-rightscale_userdata using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_rightscale_userdata'>) 2019-02-22 17:21:43,678 - cc_rightscale_userdata.py[DEBUG]: Failed to get raw userdata in module rightscale_userdata 2019-02-22 17:21:43,678 - handlers.py[DEBUG]: finish: modules-final/config-rightscale_userdata: SUCCESS: config-rightscale_userdata ran successfully 2019-02-22 17:21:43,678 - 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 2019-02-22 17:21:43,678 - handlers.py[DEBUG]: start: modules-final/config-scripts-vendor: running config-scripts-vendor with frequency once-per-instance 2019-02-22 17:21:43,678 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_scripts_vendor - wb: [420] 25 bytes 2019-02-22 17:21:43,678 - helpers.py[DEBUG]: Running config-scripts-vendor using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_scripts_vendor'>) 2019-02-22 17:21:43,678 - handlers.py[DEBUG]: finish: modules-final/config-scripts-vendor: SUCCESS: config-scripts-vendor ran successfully 2019-02-22 17:21:43,678 - 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 2019-02-22 17:21:43,679 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-once: running config-scripts-per-once with frequency once 2019-02-22 17:21:43,679 - helpers.py[DEBUG]: config-scripts-per-once already ran (freq=once) 2019-02-22 17:21:43,679 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-once: SUCCESS: config-scripts-per-once previously ran 2019-02-22 17:21:43,679 - 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 2019-02-22 17:21:43,679 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-boot: running config-scripts-per-boot with frequency always 2019-02-22 17:21:43,679 - helpers.py[DEBUG]: Running config-scripts-per-boot using lock (<cloudinit.helpers.DummyLock object at 0x7f7373347748>) 2019-02-22 17:21:43,680 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-boot: SUCCESS: config-scripts-per-boot ran successfully 2019-02-22 17:21:43,680 - 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 2019-02-22 17:21:43,680 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-instance: running config-scripts-per-instance with frequency once-per-instance 2019-02-22 17:21:43,680 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_scripts_per_instance - wb: [420] 25 bytes 2019-02-22 17:21:43,680 - helpers.py[DEBUG]: Running config-scripts-per-instance using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_scripts_per_instance'>) 2019-02-22 17:21:43,681 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-instance: SUCCESS: config-scripts-per-instance ran successfully 2019-02-22 17:21:43,681 - 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 2019-02-22 17:21:43,681 - handlers.py[DEBUG]: start: modules-final/config-scripts-user: running config-scripts-user with frequency once-per-instance 2019-02-22 17:21:43,681 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_scripts_user - wb: [420] 25 bytes 2019-02-22 17:21:43,682 - helpers.py[DEBUG]: Running config-scripts-user using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_scripts_user'>) 2019-02-22 17:21:43,682 - util.py[DEBUG]: Running command ['/var/lib/cloud/instance/scripts/runcmd'] with allowed return codes [0] (shell=False, capture=False) 2019-02-22 17:23:54,682 - handlers.py[DEBUG]: finish: modules-final/config-scripts-user: SUCCESS: config-scripts-user ran successfully 2019-02-22 17:23:54,682 - 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 2019-02-22 17:23:54,682 - handlers.py[DEBUG]: start: modules-final/config-ssh-authkey-fingerprints: running config-ssh-authkey-fingerprints with frequency once-per-instance 2019-02-22 17:23:54,683 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_ssh_authkey_fingerprints - wb: [420] 25 bytes 2019-02-22 17:23:54,684 - helpers.py[DEBUG]: Running config-ssh-authkey-fingerprints using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_ssh_authkey_fingerprints'>) 2019-02-22 17:23:54,684 - handlers.py[DEBUG]: finish: modules-final/config-ssh-authkey-fingerprints: FAIL: running config-ssh-authkey-fingerprints with frequency once-per-instance 2019-02-22 17:23:54,684 - util.py[WARNING]: 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'>) failed 2019-02-22 17:23:54,685 - util.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'>) failed Traceback (most recent call last): File "/usr/lib/python3/dist-packages/cloudinit/stages.py", line 776, in _run_modules freq=freq) File "/usr/lib/python3/dist-packages/cloudinit/cloud.py", line 54, in run return self._runners.run(name, functor, args, freq, clear_on_fail) File "/usr/lib/python3/dist-packages/cloudinit/helpers.py", line 187, in run results = functor(*args) File "/usr/lib/python3/dist-packages/cloudinit/config/cc_ssh_authkey_fingerprints.py", line 108, in handle (key_fn, key_entries) = ssh_util.extract_authorized_keys(user_name) File "/usr/lib/python3/dist-packages/cloudinit/ssh_util.py", line 209, in extract_authorized_keys (ssh_dir, pw_ent) = users_ssh_info(username) File "/usr/lib/python3/dist-packages/cloudinit/ssh_util.py", line 202, in users_ssh_info pw_ent = pwd.getpwnam(username) KeyError: 'getpwnam(): name not found: admin' 2019-02-22 17:23:54,947 - 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 2019-02-22 17:23:54,948 - handlers.py[DEBUG]: start: modules-final/config-keys-to-console: running config-keys-to-console with frequency once-per-instance 2019-02-22 17:23:54,948 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_keys_to_console - wb: [420] 25 bytes 2019-02-22 17:23:54,948 - helpers.py[DEBUG]: Running config-keys-to-console using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_keys_to_console'>) 2019-02-22 17:23:54,948 - util.py[DEBUG]: Running command ['/usr/lib/cloud-init/write-ssh-key-fingerprints', '', 'ssh-dss'] with allowed return codes [0] (shell=False, capture=True) 2019-02-22 17:23:54,960 - handlers.py[DEBUG]: finish: modules-final/config-keys-to-console: SUCCESS: config-keys-to-console ran successfully 2019-02-22 17:23:54,961 - 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 2019-02-22 17:23:54,961 - handlers.py[DEBUG]: start: modules-final/config-phone-home: running config-phone-home with frequency once-per-instance 2019-02-22 17:23:54,961 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_phone_home - wb: [420] 25 bytes 2019-02-22 17:23:54,962 - helpers.py[DEBUG]: Running config-phone-home using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_phone_home'>) 2019-02-22 17:23:54,962 - cc_phone_home.py[DEBUG]: Skipping module named phone-home, no 'phone_home' configuration found 2019-02-22 17:23:54,962 - handlers.py[DEBUG]: finish: modules-final/config-phone-home: SUCCESS: config-phone-home ran successfully 2019-02-22 17:23:54,962 - 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 2019-02-22 17:23:54,962 - handlers.py[DEBUG]: start: modules-final/config-final-message: running config-final-message with frequency always 2019-02-22 17:23:54,962 - helpers.py[DEBUG]: Running config-final-message using lock (<cloudinit.helpers.DummyLock object at 0x7f73767b8588>) 2019-02-22 17:23:54,962 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2019-02-22 17:23:54,962 - util.py[DEBUG]: Read 15 bytes from /proc/uptime 2019-02-22 17:23:54,965 - util.py[DEBUG]: Cloud-init v. 0.7.9 finished at Fri, 22 Feb 2019 16:23:54 +0000. Datasource DataSourceEc2. Up 182.68 seconds 2019-02-22 17:23:54,965 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/boot-finished - wb: [420] 52 bytes 2019-02-22 17:23:54,965 - handlers.py[DEBUG]: finish: modules-final/config-final-message: SUCCESS: config-final-message ran successfully 2019-02-22 17:23:54,965 - 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 2019-02-22 17:23:54,966 - handlers.py[DEBUG]: start: modules-final/config-power-state-change: running config-power-state-change with frequency once-per-instance 2019-02-22 17:23:54,966 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_power_state_change - wb: [420] 25 bytes 2019-02-22 17:23:54,966 - helpers.py[DEBUG]: Running config-power-state-change using lock (<FileLock using file '/var/lib/cloud/instances/i-00a7b461305b62f02/sem/config_power_state_change'>) 2019-02-22 17:23:54,966 - cc_power_state_change.py[DEBUG]: no power_state provided. doing nothing 2019-02-22 17:23:54,966 - handlers.py[DEBUG]: finish: modules-final/config-power-state-change: SUCCESS: config-power-state-change ran successfully 2019-02-22 17:23:54,966 - main.py[DEBUG]: Ran 17 modules with 1 failures 2019-02-22 17:23:54,967 - util.py[DEBUG]: Creating symbolic link from '/run/cloud-init/result.json' => '../../var/lib/cloud/data/result.json' 2019-02-22 17:23:54,967 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2019-02-22 17:23:54,967 - util.py[DEBUG]: Read 15 bytes from /proc/uptime 2019-02-22 17:23:54,967 - util.py[DEBUG]: cloud-init mode 'modules' took 144.504 seconds (144.13) 2019-02-22 17:23:54,967 - handlers.py[DEBUG]: finish: modules-final: FAIL: running modules for final

Reply to: