We’re in a situation where write_files from user_data within the maas controller /etc/maas/preseeds/curtin_userdata has recently started to fail to write out files on the maas node during instantiation. I’m trying to track down why. We have software that deploys maas nodes and which also uses write_files in userdata.
Is it possible that the respective write_files are colliding with one another? I have seen it work where one or the other works but neither works together.
Could you post a log? /var/log/cloud-init*.log should have the relevant info on a deployed system.
I’ll try and grab one soon. If I may also ask - regiond.log is giving me this error (it’s the default curtin_userdata_custom though)
2019-06-11 22:01:47 maasserver.preseed: [warn] WARNING: '/etc/maas/preseeds/curtin_userdata_custom' contains deprecated preseed variables. Please remove: main_archive_directory, ports_archive_directory
Here are the relevant logs (scrubbed as best I could scrub em):
cloud-init.log
2019-06-12 00:41:52,411 - util.py[DEBUG]: Cloud-init v. 19.1-1-gbaa47854-0ubuntu1~16.04.1 running 'init-local' at Wed, 12 Jun 2019 00:41:52 +0000. Up 10.22 seconds.
2019-06-12 00:41:52,411 - main.py[DEBUG]: No kernel command line url found.
2019-06-12 00:41:52,411 - main.py[DEBUG]: Closing stdin.
2019-06-12 00:41:52,414 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [644] 0 bytes
2019-06-12 00:41:52,415 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 104:4
2019-06-12 00:41:52,415 - main.py[DEBUG]: manual cache clean set from config
2019-06-12 00:41:52,415 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance/boot-finished
2019-06-12 00:41:52,415 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/data/no-net
2019-06-12 00:41:52,416 - handlers.py[DEBUG]: start: init-local/check-cache: attempting to read from cache [trust]
2019-06-12 00:41:52,429 - handlers.py[WARNING]: failed posting event: start: init-local/check-cache: attempting to read from cache [trust]
2019-06-12 00:41:52,429 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
2019-06-12 00:41:52,429 - stages.py[DEBUG]: no cache found
2019-06-12 00:41:52,429 - handlers.py[DEBUG]: finish: init-local/check-cache: SUCCESS: no cache found
2019-06-12 00:41:52,430 - handlers.py[WARNING]: failed posting event: finish: init-local/check-cache: SUCCESS: no cache found
2019-06-12 00:41:52,430 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance
2019-06-12 00:41:52,433 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.ubuntu.Distro'>
2019-06-12 00:41:52,433 - __init__.py[DEBUG]: Looking for data source in: ['MAAS'], via packages ['', 'cloudinit.sources'] that matches dependencies ['FILESYSTEM']
2019-06-12 00:41:52,434 - __init__.py[DEBUG]: Searching for local data source in: []
2019-06-12 00:41:52,434 - main.py[DEBUG]: No local datasource found
2019-06-12 00:41:52,434 - stages.py[DEBUG]: applying net config names for {'config': [{'id': 'eno1', 'mtu': 1500, 'type': 'physical', 'subnets': [{'type': 'manual'}], 'name': 'eno1', 'mac_address': '2c:60:0c:83:6c:f3'}, {'id': 'eno2', 'mtu': 1500, 'type': 'physical', 'subnets': [{'address': 'xxx.xxx.xxx.xxx/24', 'dns_search': ['maas'], 'dns_nameservers': ['8.8.8.8'], 'type': 'static', 'gateway': 'xxx.xxx.xxx.xxx'}], 'name': 'eno2', 'mac_address': '2c:60:0c:83:6c:f4'}, {'id': 'enp6s0f0', 'mtu': 1500, 'type': 'physical', 'subnets': [{'type': 'manual'}], 'name': 'enp6s0f0', 'mac_address': '90:e2:ba:7e:c4:c0'}, {'id': 'enp6s0f1', 'mtu': 1500, 'type': 'physical', 'subnets': [{'type': 'manual'}], 'name': 'enp6s0f1', 'mac_address': '90:e2:ba:7e:c4:c1'}, {'address': ['8.8.8.8'], 'search': ['maas'], 'type': 'nameserver'}], 'version': 1}
2019-06-12 00:41:52,434 - util.py[DEBUG]: Reading from /sys/class/net/eno1/device/device (quiet=False)
2019-06-12 00:41:52,434 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/eno1/device/device
2019-06-12 00:41:52,435 - util.py[DEBUG]: Reading from /sys/class/net/eno2/device/device (quiet=False)
2019-06-12 00:41:52,435 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/eno2/device/device
2019-06-12 00:41:52,435 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f0/device/device (quiet=False)
2019-06-12 00:41:52,435 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/enp6s0f0/device/device
2019-06-12 00:41:52,435 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f1/device/device (quiet=False)
2019-06-12 00:41:52,435 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/enp6s0f1/device/device
2019-06-12 00:41:52,435 - util.py[DEBUG]: Reading from /sys/class/net/lo/addr_assign_type (quiet=False)
2019-06-12 00:41:52,435 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/lo/addr_assign_type
2019-06-12 00:41:52,435 - util.py[DEBUG]: Reading from /sys/class/net/lo/uevent (quiet=False)
2019-06-12 00:41:52,435 - util.py[DEBUG]: Read 23 bytes from /sys/class/net/lo/uevent
2019-06-12 00:41:52,435 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False)
2019-06-12 00:41:52,435 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address
2019-06-12 00:41:52,435 - util.py[DEBUG]: Reading from /sys/class/net/lo/device/device (quiet=False)
2019-06-12 00:41:52,435 - util.py[DEBUG]: Reading from /sys/class/net/eno2/addr_assign_type (quiet=False)
2019-06-12 00:41:52,436 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/eno2/addr_assign_type
2019-06-12 00:41:52,436 - util.py[DEBUG]: Reading from /sys/class/net/eno2/uevent (quiet=False)
2019-06-12 00:41:52,436 - util.py[DEBUG]: Read 25 bytes from /sys/class/net/eno2/uevent
2019-06-12 00:41:52,436 - util.py[DEBUG]: Reading from /sys/class/net/eno2/address (quiet=False)
2019-06-12 00:41:52,436 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/eno2/address
2019-06-12 00:41:52,436 - util.py[DEBUG]: Reading from /sys/class/net/eno2/device/device (quiet=False)
2019-06-12 00:41:52,436 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/eno2/device/device
2019-06-12 00:41:52,436 - util.py[DEBUG]: Reading from /sys/class/net/eno1/addr_assign_type (quiet=False)
2019-06-12 00:41:52,436 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/eno1/addr_assign_type
2019-06-12 00:41:52,436 - util.py[DEBUG]: Reading from /sys/class/net/eno1/uevent (quiet=False)
2019-06-12 00:41:52,436 - util.py[DEBUG]: Read 25 bytes from /sys/class/net/eno1/uevent
2019-06-12 00:41:52,436 - util.py[DEBUG]: Reading from /sys/class/net/eno1/address (quiet=False)
2019-06-12 00:41:52,436 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/eno1/address
2019-06-12 00:41:52,436 - util.py[DEBUG]: Reading from /sys/class/net/eno1/device/device (quiet=False)
2019-06-12 00:41:52,436 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/eno1/device/device
2019-06-12 00:41:52,436 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f1/addr_assign_type (quiet=False)
2019-06-12 00:41:52,437 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/enp6s0f1/addr_assign_type
2019-06-12 00:41:52,437 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f1/uevent (quiet=False)
2019-06-12 00:41:52,437 - util.py[DEBUG]: Read 29 bytes from /sys/class/net/enp6s0f1/uevent
2019-06-12 00:41:52,437 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f1/address (quiet=False)
2019-06-12 00:41:52,437 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/enp6s0f1/address
2019-06-12 00:41:52,437 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f1/device/device (quiet=False)
2019-06-12 00:41:52,437 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/enp6s0f1/device/device
2019-06-12 00:41:52,437 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f0/addr_assign_type (quiet=False)
2019-06-12 00:41:52,437 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/enp6s0f0/addr_assign_type
2019-06-12 00:41:52,437 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f0/uevent (quiet=False)
2019-06-12 00:41:52,437 - util.py[DEBUG]: Read 29 bytes from /sys/class/net/enp6s0f0/uevent
2019-06-12 00:41:52,437 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f0/address (quiet=False)
2019-06-12 00:41:52,437 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/enp6s0f0/address
2019-06-12 00:41:52,437 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f0/device/device (quiet=False)
2019-06-12 00:41:52,437 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/enp6s0f0/device/device
2019-06-12 00:41:52,438 - util.py[DEBUG]: Reading from /sys/class/net/lo/operstate (quiet=False)
2019-06-12 00:41:52,438 - util.py[DEBUG]: Read 8 bytes from /sys/class/net/lo/operstate
2019-06-12 00:41:52,438 - util.py[DEBUG]: Reading from /sys/class/net/eno2/operstate (quiet=False)
2019-06-12 00:41:52,438 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/eno2/operstate
2019-06-12 00:41:52,438 - util.py[DEBUG]: Reading from /sys/class/net/eno1/operstate (quiet=False)
2019-06-12 00:41:52,438 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/eno1/operstate
2019-06-12 00:41:52,438 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f1/operstate (quiet=False)
2019-06-12 00:41:52,438 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/enp6s0f1/operstate
2019-06-12 00:41:52,438 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f0/operstate (quiet=False)
2019-06-12 00:41:52,438 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/enp6s0f0/operstate
2019-06-12 00:41:52,438 - util.py[DEBUG]: Running command ['ip', '-6', 'addr', 'show', 'permanent', 'scope', 'global'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:41:52,487 - util.py[DEBUG]: Running command ['ip', '-4', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:41:52,495 - __init__.py[DEBUG]: no work necessary for renaming of [['2c:60:0c:83:6c:f3', 'eno1', 'igb', '0x1521'], ['2c:60:0c:83:6c:f4', 'eno2', 'igb', '0x1521'], ['90:e2:ba:7e:c4:c0', 'enp6s0f0', 'ixgbe', '0x10fb'], ['90:e2:ba:7e:c4:c1', 'enp6s0f1', 'ixgbe', '0x10fb']]
2019-06-12 00:41:52,496 - stages.py[INFO]: Applying network configuration from system_cfg bringup=False: {'config': [{'id': 'eno1', 'mtu': 1500, 'type': 'physical', 'subnets': [{'type': 'manual'}], 'name': 'eno1', 'mac_address': '2c:60:0c:83:6c:f3'}, {'id': 'eno2', 'mtu': 1500, 'type': 'physical', 'subnets': [{'address': 'xxx.xxx.xxx.xxx/24', 'dns_search': ['maas'], 'dns_nameservers': ['8.8.8.8'], 'type': 'static', 'gateway': 'xxx.xxx.xxx.xxx'}], 'name': 'eno2', 'mac_address': '2c:60:0c:83:6c:f4'}, {'id': 'enp6s0f0', 'mtu': 1500, 'type': 'physical', 'subnets': [{'type': 'manual'}], 'name': 'enp6s0f0', 'mac_address': '90:e2:ba:7e:c4:c0'}, {'id': 'enp6s0f1', 'mtu': 1500, 'type': 'physical', 'subnets': [{'type': 'manual'}], 'name': 'enp6s0f1', 'mac_address': '90:e2:ba:7e:c4:c1'}, {'address': ['8.8.8.8'], 'search': ['maas'], 'type': 'nameserver'}], 'version': 1}
2019-06-12 00:41:52,496 - __init__.py[DEBUG]: Selected renderer 'eni' from priority list: None
2019-06-12 00:41:52,517 - util.py[DEBUG]: Writing to /etc/network/interfaces.d/50-cloud-init.cfg - wb: [644] 690 bytes
2019-06-12 00:41:52,518 - util.py[DEBUG]: Writing to /etc/udev/rules.d/70-persistent-net.rules - wb: [644] 392 bytes
2019-06-12 00:41:52,518 - main.py[DEBUG]: [local] Exiting without datasource
2019-06-12 00:41:52,546 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2019-06-12 00:41:52,546 - util.py[DEBUG]: Read 13 bytes from /proc/uptime
2019-06-12 00:41:52,546 - util.py[DEBUG]: cloud-init mode 'init' took 0.172 seconds (0.18)
2019-06-12 00:41:52,546 - handlers.py[DEBUG]: finish: init-local: SUCCESS: searching for local datasources
2019-06-12 00:41:52,548 - handlers.py[WARNING]: failed posting event: finish: init-local: SUCCESS: searching for local datasources
2019-06-12 00:41:53,758 - util.py[DEBUG]: Cloud-init v. 19.1-1-gbaa47854-0ubuntu1~16.04.1 running 'init' at Wed, 12 Jun 2019 00:41:53 +0000. Up 11.57 seconds.
2019-06-12 00:41:53,758 - main.py[DEBUG]: No kernel command line url found.
2019-06-12 00:41:53,759 - main.py[DEBUG]: Closing stdin.
2019-06-12 00:41:53,761 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [644] 0 bytes
2019-06-12 00:41:53,761 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 104:4
2019-06-12 00:41:53,762 - util.py[DEBUG]: Running command ['ip', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:41:53,765 - util.py[DEBUG]: Running command ['ip', '-o', 'route', 'list'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:41:53,766 - util.py[DEBUG]: Running command ['ip', '--oneline', '-6', 'route', 'list', 'table', 'all'] with allowed return codes [0, 1] (shell=False, capture=True)
2019-06-12 00:41:53,769 - 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-06-12 00:41:53,769 - main.py[DEBUG]: Execution continuing, no previous run detected that would allow us to stop early.
2019-06-12 00:41:53,780 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:53,780 - handlers.py[DEBUG]: start: init-network/check-cache: attempting to read from cache [trust]
2019-06-12 00:41:53,780 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
2019-06-12 00:41:53,780 - stages.py[DEBUG]: no cache found
2019-06-12 00:41:53,790 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:53,790 - handlers.py[DEBUG]: finish: init-network/check-cache: SUCCESS: no cache found
2019-06-12 00:41:53,790 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance
2019-06-12 00:41:53,792 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.ubuntu.Distro'>
2019-06-12 00:41:53,792 - __init__.py[DEBUG]: Looking for data source in: ['MAAS'], via packages ['', 'cloudinit.sources'] that matches dependencies ['FILESYSTEM', 'NETWORK']
2019-06-12 00:41:53,793 - __init__.py[DEBUG]: Searching for network data source in: ['DataSourceMAAS']
2019-06-12 00:41:53,796 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:53,796 - handlers.py[DEBUG]: start: init-network/search-MAAS: searching for network data from DataSourceMAAS
2019-06-12 00:41:53,796 - __init__.py[DEBUG]: Seeing if we can get any data from <class 'cloudinit.sources.DataSourceMAAS.DataSourceMAAS'>
2019-06-12 00:41:53,796 - __init__.py[DEBUG]: Update datasource metadata and network config due to events: New instance first boot
2019-06-12 00:41:53,830 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/2012-03-01/meta-data/instance-id (200, 6b) after 1 attempts
2019-06-12 00:41:53,830 - DataSourceMAAS.py[DEBUG]: Using metadata source: 'http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/2012-03-01/meta-data/instance-id'
2019-06-12 00:41:53,872 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/2012-03-01/meta-data/instance-id (200, 6b) after 1 attempts
2019-06-12 00:41:53,922 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/2012-03-01/meta-data/local-hostname (200, 12b) after 1 attempts
2019-06-12 00:41:53,955 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/2012-03-01/meta-data/public-keys (200, 380b) after 1 attempts
2019-06-12 00:41:54,014 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/2012-03-01/meta-data/vendor-data (200, 78b) after 1 attempts
2019-06-12 00:41:54,080 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/2012-03-01/user-data (200, 912b) after 1 attempts
2019-06-12 00:41:54,081 - util.py[DEBUG]: Attempting to load yaml from string of length 78 with allowed root types <class 'object'>
2019-06-12 00:41:54,084 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,085 - handlers.py[DEBUG]: finish: init-network/search-MAAS: SUCCESS: found network data from DataSourceMAAS
2019-06-12 00:41:54,085 - stages.py[INFO]: Loaded datasource DataSourceMAAS - DataSourceMAAS [http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/]
2019-06-12 00:41:54,085 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2019-06-12 00:41:54,085 - util.py[DEBUG]: Read 3612 bytes from /etc/cloud/cloud.cfg
2019-06-12 00:41:54,085 - util.py[DEBUG]: Attempting to load yaml from string of length 3612 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,097 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/curtin-preserve-sources.cfg (quiet=False)
2019-06-12 00:41:54,097 - util.py[DEBUG]: Read 35 bytes from /etc/cloud/cloud.cfg.d/curtin-preserve-sources.cfg
2019-06-12 00:41:54,097 - util.py[DEBUG]: Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,098 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg_maas.cfg (quiet=False)
2019-06-12 00:41:54,098 - util.py[DEBUG]: Read 316 bytes from /etc/cloud/cloud.cfg.d/90_dpkg_maas.cfg
2019-06-12 00:41:54,098 - util.py[DEBUG]: Attempting to load yaml from string of length 316 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,099 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg_local_cloud_config.cfg (quiet=False)
2019-06-12 00:41:54,099 - util.py[DEBUG]: Read 361 bytes from /etc/cloud/cloud.cfg.d/90_dpkg_local_cloud_config.cfg
2019-06-12 00:41:54,099 - util.py[DEBUG]: Attempting to load yaml from string of length 361 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,100 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2019-06-12 00:41:54,101 - util.py[DEBUG]: Read 81 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2019-06-12 00:41:54,101 - util.py[DEBUG]: Attempting to load yaml from string of length 81 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,101 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/50-curtin-networking.cfg (quiet=False)
2019-06-12 00:41:54,101 - util.py[DEBUG]: Read 762 bytes from /etc/cloud/cloud.cfg.d/50-curtin-networking.cfg
2019-06-12 00:41:54,101 - util.py[DEBUG]: Attempting to load yaml from string of length 762 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,106 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2019-06-12 00:41:54,106 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2019-06-12 00:41:54,106 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,110 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False)
2019-06-12 00:41:54,110 - util.py[DEBUG]: Read 45 bytes from /run/cloud-init/cloud.cfg
2019-06-12 00:41:54,110 - util.py[DEBUG]: Attempting to load yaml from string of length 45 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,110 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,111 - util.py[DEBUG]: loaded blob returned None, returning default.
2019-06-12 00:41:54,111 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance
2019-06-12 00:41:54,111 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/re6cck'
2019-06-12 00:41:54,112 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/re6cck/datasource (quiet=False)
2019-06-12 00:41:54,112 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/datasource - wb: [644] 75 bytes
2019-06-12 00:41:54,113 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [644] 75 bytes
2019-06-12 00:41:54,113 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False)
2019-06-12 00:41:54,113 - stages.py[DEBUG]: previous iid found to be NO_PREVIOUS_INSTANCE_ID
2019-06-12 00:41:54,113 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [644] 7 bytes
2019-06-12 00:41:54,113 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [644] 7 bytes
2019-06-12 00:41:54,114 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [644] 24 bytes
2019-06-12 00:41:54,114 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/manual-clean - w: [644] 0 characters
2019-06-12 00:41:54,115 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [400] 9526 bytes
2019-06-12 00:41:54,115 - main.py[DEBUG]: [net] init will now be targeting instance id: re6cck. new=True
2019-06-12 00:41:54,115 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2019-06-12 00:41:54,116 - util.py[DEBUG]: Read 3612 bytes from /etc/cloud/cloud.cfg
2019-06-12 00:41:54,116 - util.py[DEBUG]: Attempting to load yaml from string of length 3612 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,127 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/curtin-preserve-sources.cfg (quiet=False)
2019-06-12 00:41:54,127 - util.py[DEBUG]: Read 35 bytes from /etc/cloud/cloud.cfg.d/curtin-preserve-sources.cfg
2019-06-12 00:41:54,127 - util.py[DEBUG]: Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,128 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg_maas.cfg (quiet=False)
2019-06-12 00:41:54,128 - util.py[DEBUG]: Read 316 bytes from /etc/cloud/cloud.cfg.d/90_dpkg_maas.cfg
2019-06-12 00:41:54,128 - util.py[DEBUG]: Attempting to load yaml from string of length 316 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,129 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg_local_cloud_config.cfg (quiet=False)
2019-06-12 00:41:54,129 - util.py[DEBUG]: Read 361 bytes from /etc/cloud/cloud.cfg.d/90_dpkg_local_cloud_config.cfg
2019-06-12 00:41:54,129 - util.py[DEBUG]: Attempting to load yaml from string of length 361 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,131 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2019-06-12 00:41:54,131 - util.py[DEBUG]: Read 81 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2019-06-12 00:41:54,131 - util.py[DEBUG]: Attempting to load yaml from string of length 81 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,131 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/50-curtin-networking.cfg (quiet=False)
2019-06-12 00:41:54,131 - util.py[DEBUG]: Read 762 bytes from /etc/cloud/cloud.cfg.d/50-curtin-networking.cfg
2019-06-12 00:41:54,131 - util.py[DEBUG]: Attempting to load yaml from string of length 762 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,136 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2019-06-12 00:41:54,136 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2019-06-12 00:41:54,136 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,140 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False)
2019-06-12 00:41:54,140 - util.py[DEBUG]: Read 45 bytes from /run/cloud-init/cloud.cfg
2019-06-12 00:41:54,140 - util.py[DEBUG]: Attempting to load yaml from string of length 45 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,140 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,141 - util.py[DEBUG]: loaded blob returned None, returning default.
2019-06-12 00:41:54,142 - stages.py[DEBUG]: applying net config names for {'config': [{'name': 'eno1', 'mtu': 1500, 'subnets': [{'type': 'manual'}], 'type': 'physical', 'id': 'eno1', 'mac_address': '2c:60:0c:83:6c:f3'}, {'name': 'eno2', 'mtu': 1500, 'subnets': [{'gateway': '105.91.248.1', 'type': 'static', 'dns_nameservers': ['8.8.8.8'], 'address': '105.91.248.156/24', 'dns_search': ['maas']}], 'type': 'physical', 'id': 'eno2', 'mac_address': '2c:60:0c:83:6c:f4'}, {'name': 'enp6s0f0', 'mtu': 1500, 'subnets': [{'type': 'manual'}], 'type': 'physical', 'id': 'enp6s0f0', 'mac_address': '90:e2:ba:7e:c4:c0'}, {'name': 'enp6s0f1', 'mtu': 1500, 'subnets': [{'type': 'manual'}], 'type': 'physical', 'id': 'enp6s0f1', 'mac_address': '90:e2:ba:7e:c4:c1'}, {'search': ['maas'], 'type': 'nameserver', 'address': ['8.8.8.8']}], 'version': 1}
2019-06-12 00:41:54,142 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.ubuntu.Distro'>
2019-06-12 00:41:54,143 - util.py[DEBUG]: Reading from /sys/class/net/eno1/device/device (quiet=False)
2019-06-12 00:41:54,143 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/eno1/device/device
2019-06-12 00:41:54,143 - util.py[DEBUG]: Reading from /sys/class/net/eno2/device/device (quiet=False)
2019-06-12 00:41:54,143 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/eno2/device/device
2019-06-12 00:41:54,143 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f0/device/device (quiet=False)
2019-06-12 00:41:54,143 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/enp6s0f0/device/device
2019-06-12 00:41:54,143 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f1/device/device (quiet=False)
2019-06-12 00:41:54,143 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/enp6s0f1/device/device
2019-06-12 00:41:54,143 - util.py[DEBUG]: Reading from /sys/class/net/lo/addr_assign_type (quiet=False)
2019-06-12 00:41:54,143 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/lo/addr_assign_type
2019-06-12 00:41:54,143 - util.py[DEBUG]: Reading from /sys/class/net/lo/uevent (quiet=False)
2019-06-12 00:41:54,143 - util.py[DEBUG]: Read 23 bytes from /sys/class/net/lo/uevent
2019-06-12 00:41:54,143 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False)
2019-06-12 00:41:54,143 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address
2019-06-12 00:41:54,144 - util.py[DEBUG]: Reading from /sys/class/net/lo/device/device (quiet=False)
2019-06-12 00:41:54,144 - util.py[DEBUG]: Reading from /sys/class/net/eno2/addr_assign_type (quiet=False)
2019-06-12 00:41:54,144 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/eno2/addr_assign_type
2019-06-12 00:41:54,144 - util.py[DEBUG]: Reading from /sys/class/net/eno2/uevent (quiet=False)
2019-06-12 00:41:54,144 - util.py[DEBUG]: Read 25 bytes from /sys/class/net/eno2/uevent
2019-06-12 00:41:54,144 - util.py[DEBUG]: Reading from /sys/class/net/eno2/address (quiet=False)
2019-06-12 00:41:54,144 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/eno2/address
2019-06-12 00:41:54,144 - util.py[DEBUG]: Reading from /sys/class/net/eno2/device/device (quiet=False)
2019-06-12 00:41:54,144 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/eno2/device/device
2019-06-12 00:41:54,144 - util.py[DEBUG]: Reading from /sys/class/net/eno1/addr_assign_type (quiet=False)
2019-06-12 00:41:54,144 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/eno1/addr_assign_type
2019-06-12 00:41:54,144 - util.py[DEBUG]: Reading from /sys/class/net/eno1/uevent (quiet=False)
2019-06-12 00:41:54,144 - util.py[DEBUG]: Read 25 bytes from /sys/class/net/eno1/uevent
2019-06-12 00:41:54,144 - util.py[DEBUG]: Reading from /sys/class/net/eno1/address (quiet=False)
2019-06-12 00:41:54,144 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/eno1/address
2019-06-12 00:41:54,144 - util.py[DEBUG]: Reading from /sys/class/net/eno1/device/device (quiet=False)
2019-06-12 00:41:54,145 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/eno1/device/device
2019-06-12 00:41:54,145 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f1/addr_assign_type (quiet=False)
2019-06-12 00:41:54,145 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/enp6s0f1/addr_assign_type
2019-06-12 00:41:54,145 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f1/uevent (quiet=False)
2019-06-12 00:41:54,145 - util.py[DEBUG]: Read 29 bytes from /sys/class/net/enp6s0f1/uevent
2019-06-12 00:41:54,145 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f1/address (quiet=False)
2019-06-12 00:41:54,145 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/enp6s0f1/address
2019-06-12 00:41:54,145 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f1/device/device (quiet=False)
2019-06-12 00:41:54,145 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/enp6s0f1/device/device
2019-06-12 00:41:54,145 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f0/addr_assign_type (quiet=False)
2019-06-12 00:41:54,145 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/enp6s0f0/addr_assign_type
2019-06-12 00:41:54,145 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f0/uevent (quiet=False)
2019-06-12 00:41:54,145 - util.py[DEBUG]: Read 29 bytes from /sys/class/net/enp6s0f0/uevent
2019-06-12 00:41:54,145 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f0/address (quiet=False)
2019-06-12 00:41:54,145 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/enp6s0f0/address
2019-06-12 00:41:54,145 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f0/device/device (quiet=False)
2019-06-12 00:41:54,146 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/enp6s0f0/device/device
2019-06-12 00:41:54,146 - util.py[DEBUG]: Reading from /sys/class/net/lo/operstate (quiet=False)
2019-06-12 00:41:54,146 - util.py[DEBUG]: Read 8 bytes from /sys/class/net/lo/operstate
2019-06-12 00:41:54,146 - util.py[DEBUG]: Reading from /sys/class/net/eno2/operstate (quiet=False)
2019-06-12 00:41:54,146 - util.py[DEBUG]: Read 3 bytes from /sys/class/net/eno2/operstate
2019-06-12 00:41:54,146 - util.py[DEBUG]: Reading from /sys/class/net/eno1/operstate (quiet=False)
2019-06-12 00:41:54,146 - util.py[DEBUG]: Read 3 bytes from /sys/class/net/eno1/operstate
2019-06-12 00:41:54,146 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f1/operstate (quiet=False)
2019-06-12 00:41:54,146 - util.py[DEBUG]: Read 3 bytes from /sys/class/net/enp6s0f1/operstate
2019-06-12 00:41:54,146 - util.py[DEBUG]: Reading from /sys/class/net/enp6s0f0/operstate (quiet=False)
2019-06-12 00:41:54,146 - util.py[DEBUG]: Read 3 bytes from /sys/class/net/enp6s0f0/operstate
2019-06-12 00:41:54,146 - util.py[DEBUG]: Running command ['ip', '-6', 'addr', 'show', 'permanent', 'scope', 'global'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:41:54,148 - util.py[DEBUG]: Running command ['ip', '-4', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:41:54,150 - __init__.py[DEBUG]: no work necessary for renaming of [['2c:60:0c:83:6c:f3', 'eno1', 'igb', '0x1521'], ['2c:60:0c:83:6c:f4', 'eno2', 'igb', '0x1521'], ['90:e2:ba:7e:c4:c0', 'enp6s0f0', 'ixgbe', '0x10fb'], ['90:e2:ba:7e:c4:c1', 'enp6s0f1', 'ixgbe', '0x10fb']]
2019-06-12 00:41:54,150 - stages.py[INFO]: Applying network configuration from system_cfg bringup=True: {'config': [{'name': 'eno1', 'mtu': 1500, 'subnets': [{'type': 'manual'}], 'type': 'physical', 'id': 'eno1', 'mac_address': '2c:60:0c:83:6c:f3'}, {'name': 'eno2', 'mtu': 1500, 'subnets': [{'gateway': '105.91.248.1', 'type': 'static', 'dns_nameservers': ['8.8.8.8'], 'address': '105.91.248.156/24', 'dns_search': ['maas']}], 'type': 'physical', 'id': 'eno2', 'mac_address': '2c:60:0c:83:6c:f4'}, {'name': 'enp6s0f0', 'mtu': 1500, 'subnets': [{'type': 'manual'}], 'type': 'physical', 'id': 'enp6s0f0', 'mac_address': '90:e2:ba:7e:c4:c0'}, {'name': 'enp6s0f1', 'mtu': 1500, 'subnets': [{'type': 'manual'}], 'type': 'physical', 'id': 'enp6s0f1', 'mac_address': '90:e2:ba:7e:c4:c1'}, {'search': ['maas'], 'type': 'nameserver', 'address': ['8.8.8.8']}], 'version': 1}
2019-06-12 00:41:54,150 - __init__.py[DEBUG]: Selected renderer 'eni' from priority list: None
2019-06-12 00:41:54,172 - util.py[DEBUG]: Writing to /etc/network/interfaces.d/50-cloud-init.cfg - wb: [644] 690 bytes
2019-06-12 00:41:54,172 - util.py[DEBUG]: Writing to /etc/udev/rules.d/70-persistent-net.rules - wb: [644] 392 bytes
2019-06-12 00:41:54,178 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,179 - handlers.py[DEBUG]: start: init-network/setup-datasource: setting up datasource
2019-06-12 00:41:54,185 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,185 - handlers.py[DEBUG]: finish: init-network/setup-datasource: SUCCESS: setting up datasource
2019-06-12 00:41:54,185 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/user-data.txt - wb: [600] 912 bytes
2019-06-12 00:41:54,185 - util.py[DEBUG]: Attempting to load yaml from string of length 912 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,208 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/user-data.txt.i - wb: [600] 1217 bytes
2019-06-12 00:41:54,208 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/vendor-data.txt - wb: [600] 59 bytes
2019-06-12 00:41:54,209 - util.py[DEBUG]: Attempting to load yaml from string of length 59 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,210 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/vendor-data.txt.i - wb: [600] 364 bytes
2019-06-12 00:41:54,211 - cc_set_hostname.py[DEBUG]: Setting the hostname to cacpu04.maas (cacpu04)
2019-06-12 00:41:54,211 - util.py[DEBUG]: Reading from /etc/hostname (quiet=False)
2019-06-12 00:41:54,211 - util.py[DEBUG]: Read 7 bytes from /etc/hostname
2019-06-12 00:41:54,211 - util.py[DEBUG]: Writing to /etc/hostname - wb: [644] 8 bytes
2019-06-12 00:41:54,212 - __init__.py[DEBUG]: Non-persistently setting the system hostname to cacpu04
2019-06-12 00:41:54,212 - util.py[DEBUG]: Running command ['hostname', 'cacpu04'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:41:54,214 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/consume_data - wb: [644] 25 bytes
2019-06-12 00:41:54,215 - helpers.py[DEBUG]: Running consume_data using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/consume_data'>)
2019-06-12 00:41:54,220 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,220 - handlers.py[DEBUG]: start: init-network/consume-user-data: reading and applying user-data
2019-06-12 00:41:54,221 - stages.py[DEBUG]: Added default handler for {'text/cloud-config', 'text/cloud-config-jsonp'} from CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']]
2019-06-12 00:41:54,221 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript'} from ShellScriptPartHandler: [['text/x-shellscript']]
2019-06-12 00:41:54,221 - stages.py[DEBUG]: Added default handler for {'text/cloud-boothook'} from BootHookPartHandler: [['text/cloud-boothook']]
2019-06-12 00:41:54,221 - stages.py[DEBUG]: Added default handler for {'text/upstart-job'} from UpstartJobPartHandler: [['text/upstart-job']]
2019-06-12 00:41:54,221 - stages.py[DEBUG]: Added default handler for {'text/jinja2'} from JinjaTemplatePartHandler: [['text/jinja2']]
2019-06-12 00:41:54,221 - __init__.py[DEBUG]: Calling handler UpstartJobPartHandler: [['text/upstart-job']] (__begin__, None, 2) with frequency once-per-instance
2019-06-12 00:41:54,221 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__begin__, None, 3) with frequency once-per-instance
2019-06-12 00:41:54,221 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__begin__, None, 2) with frequency once-per-instance
2019-06-12 00:41:54,221 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__begin__, None, 3) with frequency once-per-instance
2019-06-12 00:41:54,221 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__begin__, None, 2) with frequency once-per-instance
2019-06-12 00:41:54,221 - __init__.py[DEBUG]: {'Content-Disposition': 'attachment; filename="part-001"', 'Content-Type': 'text/cloud-config', 'MIME-Version': '1.0'}
2019-06-12 00:41:54,221 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (text/cloud-config, part-001, 3) with frequency once-per-instance
2019-06-12 00:41:54,222 - util.py[DEBUG]: Attempting to load yaml from string of length 912 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,224 - cloud_config.py[DEBUG]: Merging by applying [('dict', ['replace']), ('list', []), ('str', [])]
2019-06-12 00:41:54,224 - __init__.py[DEBUG]: Calling handler UpstartJobPartHandler: [['text/upstart-job']] (__end__, None, 2) with frequency once-per-instance
2019-06-12 00:41:54,224 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__end__, None, 3) with frequency once-per-instance
2019-06-12 00:41:54,225 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__end__, None, 2) with frequency once-per-instance
2019-06-12 00:41:54,225 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__end__, None, 3) with frequency once-per-instance
2019-06-12 00:41:54,226 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/cloud-config.txt - wb: [600] 972 bytes
2019-06-12 00:41:54,227 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__end__, None, 2) with frequency once-per-instance
2019-06-12 00:41:54,230 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,230 - handlers.py[DEBUG]: finish: init-network/consume-user-data: SUCCESS: reading and applying user-data
2019-06-12 00:41:54,233 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,233 - handlers.py[DEBUG]: start: init-network/consume-vendor-data: reading and applying vendor-data
2019-06-12 00:41:54,234 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2019-06-12 00:41:54,234 - util.py[DEBUG]: Read 972 bytes from /var/lib/cloud/instance/cloud-config.txt
2019-06-12 00:41:54,234 - util.py[DEBUG]: Attempting to load yaml from string of length 972 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,236 - stages.py[DEBUG]: vendor data will be consumed. disabled_handlers=None
2019-06-12 00:41:54,237 - stages.py[DEBUG]: Added default handler for {'text/cloud-config', 'text/cloud-config-jsonp'} from CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']]
2019-06-12 00:41:54,237 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript'} from ShellScriptPartHandler: [['text/x-shellscript']]
2019-06-12 00:41:54,237 - stages.py[DEBUG]: Added default handler for {'text/cloud-boothook'} from BootHookPartHandler: [['text/cloud-boothook']]
2019-06-12 00:41:54,237 - stages.py[DEBUG]: Added default handler for {'text/upstart-job'} from UpstartJobPartHandler: [['text/upstart-job']]
2019-06-12 00:41:54,237 - stages.py[DEBUG]: Added default handler for {'text/jinja2'} from JinjaTemplatePartHandler: [['text/jinja2']]
2019-06-12 00:41:54,237 - __init__.py[DEBUG]: Calling handler UpstartJobPartHandler: [['text/upstart-job']] (__begin__, None, 2) with frequency once-per-instance
2019-06-12 00:41:54,237 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__begin__, None, 3) with frequency once-per-instance
2019-06-12 00:41:54,237 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__begin__, None, 2) with frequency once-per-instance
2019-06-12 00:41:54,238 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__begin__, None, 3) with frequency once-per-instance
2019-06-12 00:41:54,238 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__begin__, None, 2) with frequency once-per-instance
2019-06-12 00:41:54,238 - __init__.py[DEBUG]: {'Content-Disposition': 'attachment; filename="part-001"', 'Content-Type': 'text/cloud-config', 'MIME-Version': '1.0'}
2019-06-12 00:41:54,238 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (text/cloud-config, part-001, 3) with frequency once-per-instance
2019-06-12 00:41:54,238 - util.py[DEBUG]: Attempting to load yaml from string of length 59 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,238 - cloud_config.py[DEBUG]: Merging by applying [('dict', ['replace']), ('list', []), ('str', [])]
2019-06-12 00:41:54,239 - __init__.py[DEBUG]: Calling handler UpstartJobPartHandler: [['text/upstart-job']] (__end__, None, 2) with frequency once-per-instance
2019-06-12 00:41:54,239 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__end__, None, 3) with frequency once-per-instance
2019-06-12 00:41:54,239 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__end__, None, 2) with frequency once-per-instance
2019-06-12 00:41:54,239 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__end__, None, 3) with frequency once-per-instance
2019-06-12 00:41:54,239 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/vendor-cloud-config.txt - wb: [600] 103 bytes
2019-06-12 00:41:54,240 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__end__, None, 2) with frequency once-per-instance
2019-06-12 00:41:54,242 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,242 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data: SUCCESS: reading and applying vendor-data
2019-06-12 00:41:54,243 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2019-06-12 00:41:54,243 - util.py[DEBUG]: Read 3612 bytes from /etc/cloud/cloud.cfg
2019-06-12 00:41:54,243 - util.py[DEBUG]: Attempting to load yaml from string of length 3612 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,255 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/curtin-preserve-sources.cfg (quiet=False)
2019-06-12 00:41:54,255 - util.py[DEBUG]: Read 35 bytes from /etc/cloud/cloud.cfg.d/curtin-preserve-sources.cfg
2019-06-12 00:41:54,255 - util.py[DEBUG]: Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,255 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg_maas.cfg (quiet=False)
2019-06-12 00:41:54,255 - util.py[DEBUG]: Read 316 bytes from /etc/cloud/cloud.cfg.d/90_dpkg_maas.cfg
2019-06-12 00:41:54,255 - util.py[DEBUG]: Attempting to load yaml from string of length 316 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,256 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg_local_cloud_config.cfg (quiet=False)
2019-06-12 00:41:54,256 - util.py[DEBUG]: Read 361 bytes from /etc/cloud/cloud.cfg.d/90_dpkg_local_cloud_config.cfg
2019-06-12 00:41:54,256 - util.py[DEBUG]: Attempting to load yaml from string of length 361 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,258 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2019-06-12 00:41:54,258 - util.py[DEBUG]: Read 81 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2019-06-12 00:41:54,258 - util.py[DEBUG]: Attempting to load yaml from string of length 81 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,258 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/50-curtin-networking.cfg (quiet=False)
2019-06-12 00:41:54,258 - util.py[DEBUG]: Read 762 bytes from /etc/cloud/cloud.cfg.d/50-curtin-networking.cfg
2019-06-12 00:41:54,258 - util.py[DEBUG]: Attempting to load yaml from string of length 762 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,264 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2019-06-12 00:41:54,264 - util.py[DEBUG]: Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2019-06-12 00:41:54,264 - util.py[DEBUG]: Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,267 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False)
2019-06-12 00:41:54,267 - util.py[DEBUG]: Read 45 bytes from /run/cloud-init/cloud.cfg
2019-06-12 00:41:54,267 - util.py[DEBUG]: Attempting to load yaml from string of length 45 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,268 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,268 - util.py[DEBUG]: loaded blob returned None, returning default.
2019-06-12 00:41:54,268 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2019-06-12 00:41:54,268 - util.py[DEBUG]: Read 972 bytes from /var/lib/cloud/instance/cloud-config.txt
2019-06-12 00:41:54,268 - util.py[DEBUG]: Attempting to load yaml from string of length 972 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,271 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/vendor-cloud-config.txt (quiet=False)
2019-06-12 00:41:54,271 - util.py[DEBUG]: Read 103 bytes from /var/lib/cloud/instance/vendor-cloud-config.txt
2019-06-12 00:41:54,271 - util.py[DEBUG]: Attempting to load yaml from string of length 103 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,273 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2019-06-12 00:41:54,273 - util.py[DEBUG]: Read 972 bytes from /var/lib/cloud/instance/cloud-config.txt
2019-06-12 00:41:54,273 - util.py[DEBUG]: Attempting to load yaml from string of length 972 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,275 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/vendor-cloud-config.txt (quiet=False)
2019-06-12 00:41:54,275 - util.py[DEBUG]: Read 103 bytes from /var/lib/cloud/instance/vendor-cloud-config.txt
2019-06-12 00:41:54,275 - util.py[DEBUG]: Attempting to load yaml from string of length 103 with allowed root types (<class 'dict'>,)
2019-06-12 00:41:54,281 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,281 - handlers.py[DEBUG]: start: init-network/activate-datasource: activating datasource
2019-06-12 00:41:54,281 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/manual-clean - w: [644] 0 characters
2019-06-12 00:41:54,282 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [400] 12206 bytes
2019-06-12 00:41:54,289 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,289 - handlers.py[DEBUG]: finish: init-network/activate-datasource: SUCCESS: activating datasource
2019-06-12 00:41:54,289 - main.py[DEBUG]: used datasource 'DataSourceMAAS [http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/]' from 'MAAS' was in di_report's list: ['MAAS', 'None']
2019-06-12 00:41:54,303 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.ubuntu.Distro'>
2019-06-12 00:41:54,303 - 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-06-12 00:41:54,309 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,309 - handlers.py[DEBUG]: start: init-network/config-migrator: running config-migrator with frequency always
2019-06-12 00:41:54,309 - helpers.py[DEBUG]: Running config-migrator using lock (<cloudinit.helpers.DummyLock object at 0x7fbf9d042048>)
2019-06-12 00:41:54,309 - cc_migrator.py[DEBUG]: Migrated 0 semaphore files to there canonicalized names
2019-06-12 00:41:54,315 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,315 - handlers.py[DEBUG]: finish: init-network/config-migrator: SUCCESS: config-migrator ran successfully
2019-06-12 00:41:54,315 - 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-06-12 00:41:54,322 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,322 - handlers.py[DEBUG]: start: init-network/config-seed_random: running config-seed_random with frequency once-per-instance
2019-06-12 00:41:54,322 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_seed_random - wb: [644] 25 bytes
2019-06-12 00:41:54,323 - helpers.py[DEBUG]: Running config-seed_random using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_seed_random'>)
2019-06-12 00:41:54,323 - cc_seed_random.py[DEBUG]: no command provided
2019-06-12 00:41:54,326 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,327 - handlers.py[DEBUG]: finish: init-network/config-seed_random: SUCCESS: config-seed_random ran successfully
2019-06-12 00:41:54,327 - 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-06-12 00:41:54,330 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,330 - handlers.py[DEBUG]: start: init-network/config-bootcmd: running config-bootcmd with frequency always
2019-06-12 00:41:54,330 - helpers.py[DEBUG]: Running config-bootcmd using lock (<cloudinit.helpers.DummyLock object at 0x7fbf9cfb6358>)
2019-06-12 00:41:54,330 - cc_bootcmd.py[DEBUG]: Skipping module named bootcmd, no 'bootcmd' key in configuration
2019-06-12 00:41:54,333 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,333 - handlers.py[DEBUG]: finish: init-network/config-bootcmd: SUCCESS: config-bootcmd ran successfully
2019-06-12 00:41:54,333 - 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-06-12 00:41:54,336 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,336 - handlers.py[DEBUG]: start: init-network/config-write-files: running config-write-files with frequency once-per-instance
2019-06-12 00:41:54,336 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_write_files - wb: [644] 25 bytes
2019-06-12 00:41:54,337 - helpers.py[DEBUG]: Running config-write-files using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_write_files'>)
2019-06-12 00:41:54,337 - util.py[DEBUG]: Writing to /var/tmp/workerconfig.yaml - wb: [644] 461 bytes
2019-06-12 00:41:54,337 - util.py[DEBUG]: Changing the ownership of /var/tmp/workerconfig.yaml to 0:0
2019-06-12 00:41:54,340 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,340 - handlers.py[DEBUG]: finish: init-network/config-write-files: SUCCESS: config-write-files ran successfully
2019-06-12 00:41:54,340 - 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-06-12 00:41:54,343 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,344 - handlers.py[DEBUG]: start: init-network/config-growpart: running config-growpart with frequency always
2019-06-12 00:41:54,344 - helpers.py[DEBUG]: Running config-growpart using lock (<cloudinit.helpers.DummyLock object at 0x7fbf9cfb6358>)
2019-06-12 00:41:54,344 - cc_growpart.py[DEBUG]: No 'growpart' entry in cfg. Using default: {'mode': 'auto', 'devices': ['/'], 'ignore_growroot_disabled': False}
2019-06-12 00:41:54,344 - util.py[DEBUG]: Running command ['growpart', '--help'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:41:54,353 - util.py[DEBUG]: Reading from /proc/1608/mountinfo (quiet=False)
2019-06-12 00:41:54,353 - util.py[DEBUG]: Read 2717 bytes from /proc/1608/mountinfo
2019-06-12 00:41:54,353 - util.py[DEBUG]: Running command ['systemd-detect-virt', '--quiet', '--container'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:41:54,355 - util.py[DEBUG]: Running command ['running-in-container'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:41:54,357 - util.py[DEBUG]: Running command ['lxc-is-container'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:41:54,358 - util.py[DEBUG]: Reading from /proc/1/environ (quiet=False)
2019-06-12 00:41:54,358 - util.py[DEBUG]: Read 176 bytes from /proc/1/environ
2019-06-12 00:41:54,358 - util.py[DEBUG]: Reading from /proc/self/status (quiet=False)
2019-06-12 00:41:54,359 - util.py[DEBUG]: Read 951 bytes from /proc/self/status
2019-06-12 00:41:54,362 - util.py[DEBUG]: Reading from /etc/os-release (quiet=False)
2019-06-12 00:41:54,362 - util.py[DEBUG]: Read 298 bytes from /etc/os-release
2019-06-12 00:41:54,363 - util.py[DEBUG]: resize_devices took 0.010 seconds
2019-06-12 00:41:54,363 - cc_growpart.py[DEBUG]: '/' SKIPPED: device_part_info(/dev/mapper/vgroot-lvroot) failed: /dev/mapper/vgroot-lvroot not a partition
2019-06-12 00:41:54,367 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,368 - handlers.py[DEBUG]: finish: init-network/config-growpart: SUCCESS: config-growpart ran successfully
2019-06-12 00:41:54,368 - 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
continued
2019-06-12 00:41:54,371 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,371 - handlers.py[DEBUG]: start: init-network/config-resizefs: running config-resizefs with frequency always
2019-06-12 00:41:54,371 - helpers.py[DEBUG]: Running config-resizefs using lock (<cloudinit.helpers.DummyLock object at 0x7fbf9cfd7dd8>)
2019-06-12 00:41:54,371 - schema.py[DEBUG]: Ignoring schema validation. python-jsonschema is not present
2019-06-12 00:41:54,371 - util.py[DEBUG]: Reading from /proc/1608/mountinfo (quiet=False)
2019-06-12 00:41:54,371 - util.py[DEBUG]: Read 2717 bytes from /proc/1608/mountinfo
2019-06-12 00:41:54,372 - cc_resizefs.py[DEBUG]: resize_info: dev=/dev/mapper/vgroot-lvroot mnt_point=/ path=/
2019-06-12 00:41:54,372 - util.py[DEBUG]: Running command ['systemd-detect-virt', '--quiet', '--container'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:41:54,373 - util.py[DEBUG]: Running command ['running-in-container'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:41:54,375 - util.py[DEBUG]: Running command ['lxc-is-container'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:41:54,376 - util.py[DEBUG]: Reading from /proc/1/environ (quiet=False)
2019-06-12 00:41:54,377 - util.py[DEBUG]: Read 176 bytes from /proc/1/environ
2019-06-12 00:41:54,377 - util.py[DEBUG]: Reading from /proc/self/status (quiet=False)
2019-06-12 00:41:54,377 - util.py[DEBUG]: Read 951 bytes from /proc/self/status
2019-06-12 00:41:54,377 - cc_resizefs.py[DEBUG]: Resizing / (ext4) using resize2fs /dev/mapper/vgroot-lvroot
2019-06-12 00:41:54,377 - util.py[DEBUG]: Running command ('resize2fs', '/dev/mapper/vgroot-lvroot') with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:41:54,418 - util.py[DEBUG]: Resizing took 0.041 seconds
2019-06-12 00:41:54,418 - cc_resizefs.py[DEBUG]: Resized root filesystem (type=ext4, val=True)
2019-06-12 00:41:54,422 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,423 - handlers.py[DEBUG]: finish: init-network/config-resizefs: SUCCESS: config-resizefs ran successfully
2019-06-12 00:41:54,423 - 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-06-12 00:41:54,428 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,428 - handlers.py[DEBUG]: start: init-network/config-disk_setup: running config-disk_setup with frequency once-per-instance
2019-06-12 00:41:54,428 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_disk_setup - wb: [644] 25 bytes
2019-06-12 00:41:54,429 - helpers.py[DEBUG]: Running config-disk_setup using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_disk_setup'>)
2019-06-12 00:41:54,437 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,437 - handlers.py[DEBUG]: finish: init-network/config-disk_setup: SUCCESS: config-disk_setup ran successfully
2019-06-12 00:41:54,437 - 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-06-12 00:41:54,443 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,443 - handlers.py[DEBUG]: start: init-network/config-mounts: running config-mounts with frequency once-per-instance
2019-06-12 00:41:54,443 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_mounts - wb: [644] 25 bytes
2019-06-12 00:41:54,443 - helpers.py[DEBUG]: Running config-mounts using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_mounts'>)
2019-06-12 00:41:54,443 - cc_mounts.py[DEBUG]: mounts configuration is []
2019-06-12 00:41:54,443 - util.py[DEBUG]: Reading from /etc/fstab (quiet=False)
2019-06-12 00:41:54,444 - util.py[DEBUG]: Read 89 bytes from /etc/fstab
2019-06-12 00:41:54,444 - cc_mounts.py[DEBUG]: Attempting to determine the real name of ephemeral0
2019-06-12 00:41:54,444 - cc_mounts.py[DEBUG]: changed default device ephemeral0 => None
2019-06-12 00:41:54,444 - cc_mounts.py[DEBUG]: Ignoring nonexistent default named mount ephemeral0
2019-06-12 00:41:54,444 - cc_mounts.py[DEBUG]: Attempting to determine the real name of swap
2019-06-12 00:41:54,444 - cc_mounts.py[DEBUG]: changed default device swap => None
2019-06-12 00:41:54,444 - cc_mounts.py[DEBUG]: Ignoring nonexistent default named mount swap
2019-06-12 00:41:54,444 - cc_mounts.py[DEBUG]: no need to setup swap
2019-06-12 00:41:54,444 - cc_mounts.py[DEBUG]: No modifications to fstab needed
2019-06-12 00:41:54,453 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,454 - handlers.py[DEBUG]: finish: init-network/config-mounts: SUCCESS: config-mounts ran successfully
2019-06-12 00:41:54,454 - 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-06-12 00:41:54,458 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,458 - handlers.py[DEBUG]: start: init-network/config-set_hostname: running config-set_hostname with frequency once-per-instance
2019-06-12 00:41:54,458 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_set_hostname - wb: [644] 25 bytes
2019-06-12 00:41:54,459 - helpers.py[DEBUG]: Running config-set_hostname using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_set_hostname'>)
2019-06-12 00:41:54,459 - util.py[DEBUG]: Reading from /var/lib/cloud/data/set-hostname (quiet=False)
2019-06-12 00:41:54,459 - util.py[DEBUG]: Read 52 bytes from /var/lib/cloud/data/set-hostname
2019-06-12 00:41:54,459 - cc_set_hostname.py[DEBUG]: No hostname changes. Skipping set-hostname
2019-06-12 00:41:54,462 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,462 - handlers.py[DEBUG]: finish: init-network/config-set_hostname: SUCCESS: config-set_hostname ran successfully
2019-06-12 00:41:54,462 - 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-06-12 00:41:54,466 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,466 - handlers.py[DEBUG]: start: init-network/config-update_hostname: running config-update_hostname with frequency always
2019-06-12 00:41:54,467 - helpers.py[DEBUG]: Running config-update_hostname using lock (<cloudinit.helpers.DummyLock object at 0x7fbf9cfd8e10>)
2019-06-12 00:41:54,467 - cc_update_hostname.py[DEBUG]: Updating hostname to cacpu04.maas (cacpu04)
2019-06-12 00:41:54,467 - util.py[DEBUG]: Reading from /etc/hostname (quiet=False)
2019-06-12 00:41:54,467 - util.py[DEBUG]: Read 8 bytes from /etc/hostname
2019-06-12 00:41:54,467 - __init__.py[DEBUG]: Attempting to update hostname to cacpu04 in 1 files
2019-06-12 00:41:54,467 - util.py[DEBUG]: Reading from /var/lib/cloud/data/previous-hostname (quiet=False)
2019-06-12 00:41:54,467 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-hostname - wb: [644] 8 bytes
2019-06-12 00:41:54,470 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,470 - handlers.py[DEBUG]: finish: init-network/config-update_hostname: SUCCESS: config-update_hostname ran successfully
2019-06-12 00:41:54,470 - 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-06-12 00:41:54,478 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,478 - handlers.py[DEBUG]: start: init-network/config-update_etc_hosts: running config-update_etc_hosts with frequency always
2019-06-12 00:41:54,478 - helpers.py[DEBUG]: Running config-update_etc_hosts using lock (<cloudinit.helpers.DummyLock object at 0x7fbf9cfcc710>)
2019-06-12 00:41:54,492 - util.py[DEBUG]: Reading from /etc/cloud/templates/hosts.debian.tmpl (quiet=False)
2019-06-12 00:41:54,502 - util.py[DEBUG]: Read 901 bytes from /etc/cloud/templates/hosts.debian.tmpl
2019-06-12 00:41:54,502 - templater.py[DEBUG]: Rendering content of '/etc/cloud/templates/hosts.debian.tmpl' using renderer jinja
2019-06-12 00:41:54,504 - util.py[DEBUG]: Writing to /etc/hosts - wb: [644] 602 bytes
2019-06-12 00:41:54,508 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,508 - handlers.py[DEBUG]: finish: init-network/config-update_etc_hosts: SUCCESS: config-update_etc_hosts ran successfully
2019-06-12 00:41:54,509 - 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-06-12 00:41:54,511 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,511 - handlers.py[DEBUG]: start: init-network/config-ca-certs: running config-ca-certs with frequency once-per-instance
2019-06-12 00:41:54,511 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_ca_certs - wb: [644] 24 bytes
2019-06-12 00:41:54,512 - helpers.py[DEBUG]: Running config-ca-certs using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_ca_certs'>)
2019-06-12 00:41:54,512 - cc_ca_certs.py[DEBUG]: Skipping module named ca-certs, no 'ca-certs' key in configuration
2019-06-12 00:41:54,515 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,515 - handlers.py[DEBUG]: finish: init-network/config-ca-certs: SUCCESS: config-ca-certs ran successfully
2019-06-12 00:41:54,515 - 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-06-12 00:41:54,518 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,518 - handlers.py[DEBUG]: start: init-network/config-rsyslog: running config-rsyslog with frequency once-per-instance
2019-06-12 00:41:54,518 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_rsyslog - wb: [644] 25 bytes
2019-06-12 00:41:54,519 - helpers.py[DEBUG]: Running config-rsyslog using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_rsyslog'>)
2019-06-12 00:41:54,519 - cc_rsyslog.py[DEBUG]: Skipping module named rsyslog, no 'rsyslog' key in configuration
2019-06-12 00:41:54,521 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,521 - handlers.py[DEBUG]: finish: init-network/config-rsyslog: SUCCESS: config-rsyslog ran successfully
2019-06-12 00:41:54,521 - 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-06-12 00:41:54,527 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:54,527 - handlers.py[DEBUG]: start: init-network/config-users-groups: running config-users-groups with frequency once-per-instance
2019-06-12 00:41:54,527 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_users_groups - wb: [644] 25 bytes
2019-06-12 00:41:54,527 - helpers.py[DEBUG]: Running config-users-groups using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_users_groups'>)
2019-06-12 00:41:54,528 - util.py[DEBUG]: Reading from /etc/os-release (quiet=True)
2019-06-12 00:41:54,528 - util.py[DEBUG]: Read 298 bytes from /etc/os-release
2019-06-12 00:41:54,528 - util.py[DEBUG]: Reading from /etc/system-image/channel.ini (quiet=True)
2019-06-12 00:41:54,528 - util.py[DEBUG]: Read 0 bytes from /etc/system-image/channel.ini
2019-06-12 00:41:54,528 - __init__.py[DEBUG]: Adding user ubuntu
2019-06-12 00:41:54,528 - util.py[DEBUG]: Running hidden command to protect sensitive input/output logstring: ['useradd', 'ubuntu', '--comment', 'Ubuntu', '--groups', 'adm,audio,cdrom,dialout,dip,floppy,lxd,netdev,plugdev,sudo,video', '--shell', '/bin/bash', '-m']
2019-06-12 00:41:55,121 - util.py[DEBUG]: Running command ['passwd', '-l', 'ubuntu'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:41:55,204 - util.py[DEBUG]: Reading from /etc/sudoers (quiet=False)
2019-06-12 00:41:55,205 - util.py[DEBUG]: Read 755 bytes from /etc/sudoers
2019-06-12 00:41:55,206 - util.py[DEBUG]: Writing to /etc/sudoers.d/90-cloud-init-users - wb: [440] 151 bytes
2019-06-12 00:41:55,210 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:55,210 - handlers.py[DEBUG]: finish: init-network/config-users-groups: SUCCESS: config-users-groups ran successfully
2019-06-12 00:41:55,210 - 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-06-12 00:41:55,213 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:55,213 - handlers.py[DEBUG]: start: init-network/config-ssh: running config-ssh with frequency once-per-instance
2019-06-12 00:41:55,213 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_ssh - wb: [644] 25 bytes
2019-06-12 00:41:55,214 - helpers.py[DEBUG]: Running config-ssh using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_ssh'>)
2019-06-12 00:41:55,216 - 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-06-12 00:41:55,305 - 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-06-12 00:41:55,342 - 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-06-12 00:41:55,345 - 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-06-12 00:41:55,350 - util.py[DEBUG]: Changing the ownership of /home/ubuntu/.ssh to 1000:1000
2019-06-12 00:41:55,350 - util.py[DEBUG]: Reading from /etc/ssh/sshd_config (quiet=False)
2019-06-12 00:41:55,364 - util.py[DEBUG]: Read 2562 bytes from /etc/ssh/sshd_config
2019-06-12 00:41:55,364 - util.py[DEBUG]: Writing to /home/ubuntu/.ssh/authorized_keys - wb: [600] 381 bytes
2019-06-12 00:41:55,365 - util.py[DEBUG]: Changing the ownership of /home/ubuntu/.ssh/authorized_keys to 1000:1000
2019-06-12 00:41:55,385 - util.py[DEBUG]: Changing the ownership of /root/.ssh to 0:0
2019-06-12 00:41:55,385 - util.py[DEBUG]: Reading from /etc/ssh/sshd_config (quiet=False)
2019-06-12 00:41:55,385 - util.py[DEBUG]: Read 2562 bytes from /etc/ssh/sshd_config
2019-06-12 00:41:55,386 - util.py[DEBUG]: Writing to /root/.ssh/authorized_keys - wb: [600] 536 bytes
2019-06-12 00:41:55,386 - util.py[DEBUG]: Changing the ownership of /root/.ssh/authorized_keys to 0:0
2019-06-12 00:41:55,393 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:55,394 - handlers.py[DEBUG]: finish: init-network/config-ssh: SUCCESS: config-ssh ran successfully
2019-06-12 00:41:55,394 - main.py[DEBUG]: Ran 15 modules with 0 failures
2019-06-12 00:41:55,394 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2019-06-12 00:41:55,394 - util.py[DEBUG]: Read 13 bytes from /proc/uptime
2019-06-12 00:41:55,394 - util.py[DEBUG]: cloud-init mode 'init' took 1.674 seconds (1.67)
2019-06-12 00:41:55,440 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:41:55,440 - handlers.py[DEBUG]: finish: init-network: SUCCESS: searching for network datasources
2019-06-12 00:42:07,227 - util.py[DEBUG]: Cloud-init v. 19.1-1-gbaa47854-0ubuntu1~16.04.1 running 'modules:config' at Wed, 12 Jun 2019 00:42:07 +0000. Up 25.00 seconds.
2019-06-12 00:42:07,310 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.ubuntu.Distro'>
2019-06-12 00:42:07,311 - 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-06-12 00:42:07,312 - handlers.py[DEBUG]: start: modules-config/config-emit_upstart: running config-emit_upstart with frequency always
2019-06-12 00:42:07,324 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:07,324 - helpers.py[DEBUG]: Running config-emit_upstart using lock (<cloudinit.helpers.DummyLock object at 0x7fd5254e0048>)
2019-06-12 00:42:07,324 - cc_emit_upstart.py[DEBUG]: no /sbin/initctl located
2019-06-12 00:42:07,324 - cc_emit_upstart.py[DEBUG]: not upstart system, 'emit_upstart' disabled
2019-06-12 00:42:07,324 - handlers.py[DEBUG]: finish: modules-config/config-emit_upstart: SUCCESS: config-emit_upstart ran successfully
2019-06-12 00:42:07,329 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:07,329 - stages.py[DEBUG]: Running module snap (<module 'cloudinit.config.cc_snap' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_snap.py'>) with frequency once-per-instance
2019-06-12 00:42:07,329 - handlers.py[DEBUG]: start: modules-config/config-snap: running config-snap with frequency once-per-instance
2019-06-12 00:42:07,333 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:07,333 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_snap - wb: [644] 25 bytes
2019-06-12 00:42:07,334 - helpers.py[DEBUG]: Running config-snap using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_snap'>)
2019-06-12 00:42:07,334 - cc_snap.py[DEBUG]: Skipping module named snap, no 'snap' key in configuration
2019-06-12 00:42:07,334 - handlers.py[DEBUG]: finish: modules-config/config-snap: SUCCESS: config-snap ran successfully
2019-06-12 00:42:07,338 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:07,338 - stages.py[DEBUG]: Running module snap_config (<module 'cloudinit.config.cc_snap_config' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_snap_config.py'>) with frequency once-per-instance
2019-06-12 00:42:07,338 - handlers.py[DEBUG]: start: modules-config/config-snap_config: running config-snap_config with frequency once-per-instance
2019-06-12 00:42:07,342 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:07,342 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_snap_config - wb: [644] 25 bytes
2019-06-12 00:42:07,343 - helpers.py[DEBUG]: Running config-snap_config using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_snap_config'>)
2019-06-12 00:42:07,343 - cc_snap_config.py[DEBUG]: No snappy config provided, skipping
2019-06-12 00:42:07,343 - handlers.py[DEBUG]: finish: modules-config/config-snap_config: SUCCESS: config-snap_config ran successfully
2019-06-12 00:42:07,346 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:07,347 - 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-06-12 00:42:07,347 - handlers.py[DEBUG]: start: modules-config/config-ssh-import-id: running config-ssh-import-id with frequency once-per-instance
2019-06-12 00:42:07,351 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:07,351 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_ssh_import_id - wb: [644] 25 bytes
2019-06-12 00:42:07,351 - helpers.py[DEBUG]: Running config-ssh-import-id using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_ssh_import_id'>)
2019-06-12 00:42:07,352 - handlers.py[DEBUG]: finish: modules-config/config-ssh-import-id: SUCCESS: config-ssh-import-id ran successfully
2019-06-12 00:42:07,355 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:07,356 - 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-06-12 00:42:07,356 - handlers.py[DEBUG]: start: modules-config/config-locale: running config-locale with frequency once-per-instance
2019-06-12 00:42:07,360 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:07,360 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_locale - wb: [644] 24 bytes
2019-06-12 00:42:07,360 - helpers.py[DEBUG]: Running config-locale using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_locale'>)
2019-06-12 00:42:07,360 - util.py[DEBUG]: Reading from /etc/default/locale (quiet=False)
2019-06-12 00:42:07,360 - util.py[DEBUG]: Read 35 bytes from /etc/default/locale
2019-06-12 00:42:07,360 - cc_locale.py[DEBUG]: Setting locale to en_US.UTF-8
2019-06-12 00:42:07,360 - util.py[DEBUG]: Reading from /etc/default/locale (quiet=False)
2019-06-12 00:42:07,360 - util.py[DEBUG]: Read 35 bytes from /etc/default/locale
2019-06-12 00:42:07,361 - debian.py[DEBUG]: Generating locales for en_US.UTF-8
2019-06-12 00:42:07,361 - util.py[DEBUG]: Running command ['locale-gen', 'en_US.UTF-8'] with allowed return codes [0] (shell=False, capture=False)
2019-06-12 00:42:08,019 - debian.py[DEBUG]: Updating /etc/default/locale with locale setting LANG=en_US.UTF-8
2019-06-12 00:42:08,019 - util.py[DEBUG]: Running command ['update-locale', '--locale-file=/etc/default/locale', 'LANG=en_US.UTF-8'] with allowed return codes [0] (shell=False, capture=False)
2019-06-12 00:42:08,243 - handlers.py[DEBUG]: finish: modules-config/config-locale: SUCCESS: config-locale ran successfully
2019-06-12 00:42:08,249 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:08,249 - 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-06-12 00:42:08,249 - handlers.py[DEBUG]: start: modules-config/config-set-passwords: running config-set-passwords with frequency once-per-instance
2019-06-12 00:42:08,254 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:08,254 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_set_passwords - wb: [644] 25 bytes
2019-06-12 00:42:08,255 - helpers.py[DEBUG]: Running config-set-passwords using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_set_passwords'>)
2019-06-12 00:42:08,255 - cc_set_passwords.py[DEBUG]: Leaving ssh config 'PasswordAuthentication' unchanged. ssh_pwauth=None
2019-06-12 00:42:08,255 - handlers.py[DEBUG]: finish: modules-config/config-set-passwords: SUCCESS: config-set-passwords ran successfully
2019-06-12 00:42:08,260 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:08,260 - 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-06-12 00:42:08,260 - handlers.py[DEBUG]: start: modules-config/config-grub-dpkg: running config-grub-dpkg with frequency once-per-instance
2019-06-12 00:42:08,265 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:08,265 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_grub_dpkg - wb: [644] 25 bytes
2019-06-12 00:42:08,265 - helpers.py[DEBUG]: Running config-grub-dpkg using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_grub_dpkg'>)
2019-06-12 00:42:08,265 - cc_grub_dpkg.py[DEBUG]: Setting grub debconf-set-selections with '/dev/sda','false'
2019-06-12 00:42:08,265 - util.py[DEBUG]: Running command ['debconf-set-selections'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:42:08,733 - handlers.py[DEBUG]: finish: modules-config/config-grub-dpkg: SUCCESS: config-grub-dpkg ran successfully
2019-06-12 00:42:08,738 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:08,738 - 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-06-12 00:42:08,739 - handlers.py[DEBUG]: start: modules-config/config-apt-pipelining: running config-apt-pipelining with frequency once-per-instance
2019-06-12 00:42:08,743 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:08,744 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_apt_pipelining - wb: [644] 25 bytes
2019-06-12 00:42:08,744 - helpers.py[DEBUG]: Running config-apt-pipelining using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_apt_pipelining'>)
2019-06-12 00:42:08,744 - handlers.py[DEBUG]: finish: modules-config/config-apt-pipelining: SUCCESS: config-apt-pipelining ran successfully
2019-06-12 00:42:08,749 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:08,749 - 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-06-12 00:42:08,749 - handlers.py[DEBUG]: start: modules-config/config-apt-configure: running config-apt-configure with frequency once-per-instance
2019-06-12 00:42:08,753 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:08,753 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_apt_configure - wb: [644] 25 bytes
2019-06-12 00:42:08,754 - helpers.py[DEBUG]: Running config-apt-configure using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_apt_configure'>)
2019-06-12 00:42:08,754 - cc_apt_configure.py[DEBUG]: debconf_selections was not set in config
2019-06-12 00:42:08,754 - cc_apt_configure.py[DEBUG]: handling apt config: {'preserve_sources_list': True}
2019-06-12 00:42:08,754 - util.py[DEBUG]: Running command ['lsb_release', '--all'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:42:08,838 - util.py[DEBUG]: Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:42:08,840 - cc_apt_configure.py[DEBUG]: got primary mirror: None
2019-06-12 00:42:08,840 - cc_apt_configure.py[DEBUG]: got security mirror: None
2019-06-12 00:42:08,841 - util.py[DEBUG]: Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:42:08,843 - __init__.py[DEBUG]: filtered distro mirror info: {'primary': 'http://archive.ubuntu.com/ubuntu', 'security': 'http://security.ubuntu.com/ubuntu'}
2019-06-12 00:42:08,843 - cc_apt_configure.py[DEBUG]: Apt Mirror info: {'primary': 'http://archive.ubuntu.com/ubuntu', 'SECURITY': 'http://security.ubuntu.com/ubuntu', 'PRIMARY': 'http://archive.ubuntu.com/ubuntu', 'security': 'http://security.ubuntu.com/ubuntu', 'MIRROR': 'http://archive.ubuntu.com/ubuntu'}
2019-06-12 00:42:08,843 - handlers.py[DEBUG]: finish: modules-config/config-apt-configure: SUCCESS: config-apt-configure ran successfully
2019-06-12 00:42:08,848 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:08,848 - stages.py[DEBUG]: Running module ubuntu-advantage (<module 'cloudinit.config.cc_ubuntu_advantage' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_ubuntu_advantage.py'>) with frequency once-per-instance
2019-06-12 00:42:08,848 - handlers.py[DEBUG]: start: modules-config/config-ubuntu-advantage: running config-ubuntu-advantage with frequency once-per-instance
2019-06-12 00:42:08,853 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:08,853 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_ubuntu_advantage - wb: [644] 25 bytes
2019-06-12 00:42:08,854 - helpers.py[DEBUG]: Running config-ubuntu-advantage using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_ubuntu_advantage'>)
2019-06-12 00:42:08,854 - cc_ubuntu_advantage.py[DEBUG]: Skipping module named ubuntu-advantage, no 'ubuntu-advantage' key in configuration
2019-06-12 00:42:08,854 - handlers.py[DEBUG]: finish: modules-config/config-ubuntu-advantage: SUCCESS: config-ubuntu-advantage ran successfully
2019-06-12 00:42:08,858 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:08,858 - 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-06-12 00:42:08,858 - handlers.py[DEBUG]: start: modules-config/config-ntp: running config-ntp with frequency once-per-instance
2019-06-12 00:42:08,863 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:08,863 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_ntp - wb: [644] 25 bytes
2019-06-12 00:42:08,863 - helpers.py[DEBUG]: Running config-ntp using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_ntp'>)
2019-06-12 00:42:08,863 - schema.py[DEBUG]: Ignoring schema validation. python-jsonschema is not present
2019-06-12 00:42:08,866 - util.py[DEBUG]: Reading from /etc/os-release (quiet=False)
2019-06-12 00:42:08,866 - util.py[DEBUG]: Read 298 bytes from /etc/os-release
2019-06-12 00:42:08,867 - util.py[DEBUG]: Reading from /etc/os-release (quiet=True)
2019-06-12 00:42:08,867 - util.py[DEBUG]: Read 298 bytes from /etc/os-release
2019-06-12 00:42:08,867 - util.py[DEBUG]: Reading from /etc/system-image/channel.ini (quiet=True)
2019-06-12 00:42:08,867 - util.py[DEBUG]: Read 0 bytes from /etc/system-image/channel.ini
2019-06-12 00:42:08,867 - cc_ntp.py[DEBUG]: Selected distro preferred NTP client "ntp", not yet installed
2019-06-12 00:42:08,867 - util.py[DEBUG]: Reading from /etc/cloud/templates/ntp.conf.ubuntu.tmpl (quiet=False)
2019-06-12 00:42:08,878 - util.py[DEBUG]: Read 2509 bytes from /etc/cloud/templates/ntp.conf.ubuntu.tmpl
2019-06-12 00:42:08,878 - templater.py[DEBUG]: Rendering content of '/etc/cloud/templates/ntp.conf.ubuntu.tmpl' using renderer jinja
2019-06-12 00:42:08,883 - util.py[DEBUG]: Writing to /etc/ntp.conf - wb: [644] 2331 bytes
2019-06-12 00:42:08,884 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/update_sources - wb: [644] 25 bytes
2019-06-12 00:42:08,884 - helpers.py[DEBUG]: Running update-sources using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/update_sources'>)
2019-06-12 00:42:08,884 - util.py[DEBUG]: Running command ['eatmydata', '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-06-12 00:42:14,987 - util.py[DEBUG]: apt-update [eatmydata apt-get --option=Dpkg::Options::=--force-confold --option=Dpkg::options::=--force-unsafe-io --assume-yes --quiet update] took 6.102 seconds
2019-06-12 00:42:14,987 - util.py[DEBUG]: Running command ['eatmydata', 'apt-get', '--option=Dpkg::Options::=--force-confold', '--option=Dpkg::options::=--force-unsafe-io', '--assume-yes', '--quiet', 'install', 'ntp'] with allowed return codes [0] (shell=False, capture=False)
2019-06-12 00:42:19,606 - util.py[DEBUG]: apt-install [eatmydata apt-get --option=Dpkg::Options::=--force-confold --option=Dpkg::options::=--force-unsafe-io --assume-yes --quiet install ntp] took 4.618 seconds
2019-06-12 00:42:19,606 - util.py[DEBUG]: Running command ['systemctl', 'reload-or-restart', 'ntp'] with allowed return codes [0] (shell=False, capture=True)
2019-06-12 00:42:19,668 - handlers.py[DEBUG]: finish: modules-config/config-ntp: SUCCESS: config-ntp ran successfully
2019-06-12 00:42:19,675 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:19,675 - 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-06-12 00:42:19,675 - handlers.py[DEBUG]: start: modules-config/config-timezone: running config-timezone with frequency once-per-instance
2019-06-12 00:42:19,680 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:19,680 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_timezone - wb: [644] 25 bytes
2019-06-12 00:42:19,681 - helpers.py[DEBUG]: Running config-timezone using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_timezone'>)
2019-06-12 00:42:19,682 - cc_timezone.py[DEBUG]: Skipping module named timezone, no 'timezone' specified
2019-06-12 00:42:19,682 - handlers.py[DEBUG]: finish: modules-config/config-timezone: SUCCESS: config-timezone ran successfully
2019-06-12 00:42:19,692 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:19,692 - 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-06-12 00:42:19,693 - handlers.py[DEBUG]: start: modules-config/config-disable-ec2-metadata: running config-disable-ec2-metadata with frequency always
2019-06-12 00:42:19,697 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:19,697 - helpers.py[DEBUG]: Running config-disable-ec2-metadata using lock (<cloudinit.helpers.DummyLock object at 0x7fd525487cf8>)
2019-06-12 00:42:19,697 - cc_disable_ec2_metadata.py[DEBUG]: Skipping module named disable-ec2-metadata, disabling the ec2 route not enabled
2019-06-12 00:42:19,697 - handlers.py[DEBUG]: finish: modules-config/config-disable-ec2-metadata: SUCCESS: config-disable-ec2-metadata ran successfully
2019-06-12 00:42:19,702 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:19,702 - 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-06-12 00:42:19,702 - handlers.py[DEBUG]: start: modules-config/config-runcmd: running config-runcmd with frequency once-per-instance
2019-06-12 00:42:19,712 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:19,712 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_runcmd - wb: [644] 25 bytes
2019-06-12 00:42:19,713 - helpers.py[DEBUG]: Running config-runcmd using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_runcmd'>)
2019-06-12 00:42:19,713 - schema.py[DEBUG]: Ignoring schema validation. python-jsonschema is not present
2019-06-12 00:42:19,713 - util.py[DEBUG]: Shellified 3 commands.
2019-06-12 00:42:19,713 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/scripts/runcmd - wb: [700] 195 bytes
2019-06-12 00:42:19,714 - handlers.py[DEBUG]: finish: modules-config/config-runcmd: SUCCESS: config-runcmd ran successfully
2019-06-12 00:42:19,720 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:19,720 - 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-06-12 00:42:19,720 - handlers.py[DEBUG]: start: modules-config/config-byobu: running config-byobu with frequency once-per-instance
2019-06-12 00:42:19,726 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:19,726 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_byobu - wb: [644] 25 bytes
2019-06-12 00:42:19,726 - helpers.py[DEBUG]: Running config-byobu using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_byobu'>)
2019-06-12 00:42:19,726 - cc_byobu.py[DEBUG]: Skipping module named byobu, no 'byobu' values found
2019-06-12 00:42:19,726 - handlers.py[DEBUG]: finish: modules-config/config-byobu: SUCCESS: config-byobu ran successfully
2019-06-12 00:42:19,730 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:19,730 - main.py[DEBUG]: Ran 15 modules with 0 failures
2019-06-12 00:42:19,731 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2019-06-12 00:42:19,731 - util.py[DEBUG]: Read 14 bytes from /proc/uptime
2019-06-12 00:42:19,731 - util.py[DEBUG]: cloud-init mode 'modules' took 12.577 seconds (12.58)
2019-06-12 00:42:19,731 - handlers.py[DEBUG]: finish: modules-config: SUCCESS: running modules for config
2019-06-12 00:42:19,758 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,106 - util.py[DEBUG]: Cloud-init v. 19.1-1-gbaa47854-0ubuntu1~16.04.1 running 'modules:final' at Wed, 12 Jun 2019 00:42:20 +0000. Up 37.87 seconds.
2019-06-12 00:42:20,144 - stages.py[DEBUG]: Using distro class <class 'cloudinit.distros.ubuntu.Distro'>
2019-06-12 00:42:20,145 - stages.py[DEBUG]: Running module snappy (<module 'cloudinit.config.cc_snappy' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_snappy.py'>) with frequency once-per-instance
2019-06-12 00:42:20,145 - handlers.py[DEBUG]: start: modules-final/config-snappy: running config-snappy with frequency once-per-instance
2019-06-12 00:42:20,158 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,158 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_snappy - wb: [644] 24 bytes
continued
2019-06-12 00:42:20,158 - helpers.py[DEBUG]: Running config-snappy using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_snappy'>)
2019-06-12 00:42:20,158 - util.py[DEBUG]: Reading from /etc/os-release (quiet=True)
2019-06-12 00:42:20,159 - util.py[DEBUG]: Read 298 bytes from /etc/os-release
2019-06-12 00:42:20,159 - util.py[DEBUG]: Reading from /etc/system-image/channel.ini (quiet=True)
2019-06-12 00:42:20,159 - util.py[DEBUG]: Read 0 bytes from /etc/system-image/channel.ini
2019-06-12 00:42:20,159 - cc_snappy.py[DEBUG]: snappy: 'auto' mode, and system not snappy
2019-06-12 00:42:20,159 - handlers.py[DEBUG]: finish: modules-final/config-snappy: SUCCESS: config-snappy ran successfully
2019-06-12 00:42:20,164 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,164 - 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-06-12 00:42:20,164 - handlers.py[DEBUG]: start: modules-final/config-package-update-upgrade-install: running config-package-update-upgrade-install with frequency once-per-instance
2019-06-12 00:42:20,168 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,168 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_package_update_upgrade_install - wb: [644] 25 bytes
2019-06-12 00:42:20,169 - helpers.py[DEBUG]: Running config-package-update-upgrade-install using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_package_update_upgrade_install'>)
2019-06-12 00:42:20,169 - handlers.py[DEBUG]: finish: modules-final/config-package-update-upgrade-install: SUCCESS: config-package-update-upgrade-install ran successfully
2019-06-12 00:42:20,173 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,173 - 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-06-12 00:42:20,174 - handlers.py[DEBUG]: start: modules-final/config-fan: running config-fan with frequency once-per-instance
2019-06-12 00:42:20,178 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,178 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_fan - wb: [644] 24 bytes
2019-06-12 00:42:20,178 - helpers.py[DEBUG]: Running config-fan using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_fan'>)
2019-06-12 00:42:20,179 - cc_fan.py[DEBUG]: fan: no 'fan' config entry. disabling
2019-06-12 00:42:20,179 - handlers.py[DEBUG]: finish: modules-final/config-fan: SUCCESS: config-fan ran successfully
2019-06-12 00:42:20,187 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,187 - stages.py[DEBUG]: Running module landscape (<module 'cloudinit.config.cc_landscape' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_landscape.py'>) with frequency once-per-instance
2019-06-12 00:42:20,187 - handlers.py[DEBUG]: start: modules-final/config-landscape: running config-landscape with frequency once-per-instance
2019-06-12 00:42:20,190 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,190 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_landscape - wb: [644] 25 bytes
2019-06-12 00:42:20,191 - helpers.py[DEBUG]: Running config-landscape using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_landscape'>)
2019-06-12 00:42:20,191 - handlers.py[DEBUG]: finish: modules-final/config-landscape: SUCCESS: config-landscape ran successfully
2019-06-12 00:42:20,196 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,196 - stages.py[DEBUG]: Running module lxd (<module 'cloudinit.config.cc_lxd' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_lxd.py'>) with frequency once-per-instance
2019-06-12 00:42:20,196 - handlers.py[DEBUG]: start: modules-final/config-lxd: running config-lxd with frequency once-per-instance
2019-06-12 00:42:20,200 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,200 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_lxd - wb: [644] 24 bytes
2019-06-12 00:42:20,200 - helpers.py[DEBUG]: Running config-lxd using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_lxd'>)
2019-06-12 00:42:20,200 - cc_lxd.py[DEBUG]: Skipping module named lxd, not present or disabled by cfg
2019-06-12 00:42:20,200 - handlers.py[DEBUG]: finish: modules-final/config-lxd: SUCCESS: config-lxd ran successfully
2019-06-12 00:42:20,204 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,205 - stages.py[DEBUG]: Running module ubuntu-drivers (<module 'cloudinit.config.cc_ubuntu_drivers' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_ubuntu_drivers.py'>) with frequency once-per-instance
2019-06-12 00:42:20,205 - handlers.py[DEBUG]: start: modules-final/config-ubuntu-drivers: running config-ubuntu-drivers with frequency once-per-instance
2019-06-12 00:42:20,209 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,209 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_ubuntu_drivers - wb: [644] 25 bytes
2019-06-12 00:42:20,209 - helpers.py[DEBUG]: Running config-ubuntu-drivers using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_ubuntu_drivers'>)
2019-06-12 00:42:20,209 - cc_ubuntu_drivers.py[DEBUG]: Skipping module named ubuntu-drivers, no 'drivers' key in config
2019-06-12 00:42:20,209 - handlers.py[DEBUG]: finish: modules-final/config-ubuntu-drivers: SUCCESS: config-ubuntu-drivers ran successfully
2019-06-12 00:42:20,213 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,213 - 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-06-12 00:42:20,213 - handlers.py[DEBUG]: start: modules-final/config-puppet: running config-puppet with frequency once-per-instance
2019-06-12 00:42:20,217 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,217 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_puppet - wb: [644] 25 bytes
2019-06-12 00:42:20,218 - helpers.py[DEBUG]: Running config-puppet using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_puppet'>)
2019-06-12 00:42:20,218 - cc_puppet.py[DEBUG]: Skipping module named puppet, no 'puppet' configuration found
2019-06-12 00:42:20,218 - handlers.py[DEBUG]: finish: modules-final/config-puppet: SUCCESS: config-puppet ran successfully
2019-06-12 00:42:20,222 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,222 - 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-06-12 00:42:20,222 - handlers.py[DEBUG]: start: modules-final/config-chef: running config-chef with frequency once-per-instance
2019-06-12 00:42:20,229 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,229 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_chef - wb: [644] 25 bytes
2019-06-12 00:42:20,230 - helpers.py[DEBUG]: Running config-chef using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_chef'>)
2019-06-12 00:42:20,230 - cc_chef.py[DEBUG]: Skipping module named chef, no 'chef' key in configuration
2019-06-12 00:42:20,230 - handlers.py[DEBUG]: finish: modules-final/config-chef: SUCCESS: config-chef ran successfully
2019-06-12 00:42:20,234 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,234 - 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-06-12 00:42:20,235 - handlers.py[DEBUG]: start: modules-final/config-mcollective: running config-mcollective with frequency once-per-instance
2019-06-12 00:42:20,241 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,241 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_mcollective - wb: [644] 25 bytes
2019-06-12 00:42:20,241 - helpers.py[DEBUG]: Running config-mcollective using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_mcollective'>)
2019-06-12 00:42:20,242 - cc_mcollective.py[DEBUG]: Skipping module named mcollective, no 'mcollective' key in configuration
2019-06-12 00:42:20,242 - handlers.py[DEBUG]: finish: modules-final/config-mcollective: SUCCESS: config-mcollective ran successfully
2019-06-12 00:42:20,251 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,251 - 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-06-12 00:42:20,251 - handlers.py[DEBUG]: start: modules-final/config-salt-minion: running config-salt-minion with frequency once-per-instance
2019-06-12 00:42:20,255 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,256 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_salt_minion - wb: [644] 25 bytes
2019-06-12 00:42:20,256 - helpers.py[DEBUG]: Running config-salt-minion using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_salt_minion'>)
2019-06-12 00:42:20,256 - cc_salt_minion.py[DEBUG]: Skipping module named salt-minion, no 'salt_minion' key in configuration
2019-06-12 00:42:20,256 - handlers.py[DEBUG]: finish: modules-final/config-salt-minion: SUCCESS: config-salt-minion ran successfully
2019-06-12 00:42:20,262 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,263 - 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-06-12 00:42:20,263 - handlers.py[DEBUG]: start: modules-final/config-rightscale_userdata: running config-rightscale_userdata with frequency once-per-instance
2019-06-12 00:42:20,267 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,267 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_rightscale_userdata - wb: [644] 24 bytes
2019-06-12 00:42:20,267 - helpers.py[DEBUG]: Running config-rightscale_userdata using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_rightscale_userdata'>)
2019-06-12 00:42:20,267 - cc_rightscale_userdata.py[DEBUG]: Failed to get raw userdata in module rightscale_userdata
2019-06-12 00:42:20,268 - handlers.py[DEBUG]: finish: modules-final/config-rightscale_userdata: SUCCESS: config-rightscale_userdata ran successfully
2019-06-12 00:42:20,271 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,271 - 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-06-12 00:42:20,272 - handlers.py[DEBUG]: start: modules-final/config-scripts-vendor: running config-scripts-vendor with frequency once-per-instance
2019-06-12 00:42:20,276 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,276 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_scripts_vendor - wb: [644] 25 bytes
2019-06-12 00:42:20,276 - helpers.py[DEBUG]: Running config-scripts-vendor using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_scripts_vendor'>)
2019-06-12 00:42:20,276 - handlers.py[DEBUG]: finish: modules-final/config-scripts-vendor: SUCCESS: config-scripts-vendor ran successfully
2019-06-12 00:42:20,281 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,281 - 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-06-12 00:42:20,281 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-once: running config-scripts-per-once with frequency once
2019-06-12 00:42:20,284 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,285 - util.py[DEBUG]: Writing to /var/lib/cloud/sem/config_scripts_per_once.once - wb: [644] 24 bytes
2019-06-12 00:42:20,285 - helpers.py[DEBUG]: Running config-scripts-per-once using lock (<FileLock using file '/var/lib/cloud/sem/config_scripts_per_once.once'>)
2019-06-12 00:42:20,285 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-once: SUCCESS: config-scripts-per-once ran successfully
2019-06-12 00:42:20,288 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,288 - 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-06-12 00:42:20,289 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-boot: running config-scripts-per-boot with frequency always
2019-06-12 00:42:20,292 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,292 - helpers.py[DEBUG]: Running config-scripts-per-boot using lock (<cloudinit.helpers.DummyLock object at 0x7f421ecef208>)
2019-06-12 00:42:20,292 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-boot: SUCCESS: config-scripts-per-boot ran successfully
2019-06-12 00:42:20,295 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,295 - 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-06-12 00:42:20,295 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-instance: running config-scripts-per-instance with frequency once-per-instance
2019-06-12 00:42:20,298 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,298 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_scripts_per_instance - wb: [644] 25 bytes
2019-06-12 00:42:20,299 - helpers.py[DEBUG]: Running config-scripts-per-instance using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_scripts_per_instance'>)
2019-06-12 00:42:20,299 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-instance: SUCCESS: config-scripts-per-instance ran successfully
2019-06-12 00:42:20,306 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,306 - 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-06-12 00:42:20,306 - handlers.py[DEBUG]: start: modules-final/config-scripts-user: running config-scripts-user with frequency once-per-instance
2019-06-12 00:42:20,318 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:20,318 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_scripts_user - wb: [644] 25 bytes
2019-06-12 00:42:20,318 - helpers.py[DEBUG]: Running config-scripts-user using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_scripts_user'>)
2019-06-12 00:42:20,319 - util.py[DEBUG]: Running command ['/var/lib/cloud/instance/scripts/runcmd'] with allowed return codes [0] (shell=False, capture=False)
2019-06-12 00:42:23,990 - handlers.py[DEBUG]: finish: modules-final/config-scripts-user: SUCCESS: config-scripts-user ran successfully
2019-06-12 00:42:23,996 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:23,997 - 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-06-12 00:42:23,997 - handlers.py[DEBUG]: start: modules-final/config-ssh-authkey-fingerprints: running config-ssh-authkey-fingerprints with frequency once-per-instance
2019-06-12 00:42:24,002 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:24,002 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_ssh_authkey_fingerprints - wb: [644] 25 bytes
2019-06-12 00:42:24,003 - helpers.py[DEBUG]: Running config-ssh-authkey-fingerprints using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_ssh_authkey_fingerprints'>)
2019-06-12 00:42:24,003 - util.py[DEBUG]: Reading from /etc/ssh/sshd_config (quiet=False)
2019-06-12 00:42:24,003 - util.py[DEBUG]: Read 2562 bytes from /etc/ssh/sshd_config
2019-06-12 00:42:24,003 - util.py[DEBUG]: Reading from /home/ubuntu/.ssh/authorized_keys (quiet=False)
2019-06-12 00:42:24,004 - util.py[DEBUG]: Read 381 bytes from /home/ubuntu/.ssh/authorized_keys
2019-06-12 00:42:24,005 - handlers.py[DEBUG]: finish: modules-final/config-ssh-authkey-fingerprints: SUCCESS: config-ssh-authkey-fingerprints ran successfully
2019-06-12 00:42:24,009 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:24,009 - 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-06-12 00:42:24,010 - handlers.py[DEBUG]: start: modules-final/config-keys-to-console: running config-keys-to-console with frequency once-per-instance
2019-06-12 00:42:24,014 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:24,014 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_keys_to_console - wb: [644] 25 bytes
2019-06-12 00:42:24,015 - helpers.py[DEBUG]: Running config-keys-to-console using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_keys_to_console'>)
2019-06-12 00:42:24,015 - 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-06-12 00:42:24,047 - handlers.py[DEBUG]: finish: modules-final/config-keys-to-console: SUCCESS: config-keys-to-console ran successfully
2019-06-12 00:42:24,053 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:24,053 - 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-06-12 00:42:24,054 - handlers.py[DEBUG]: start: modules-final/config-phone-home: running config-phone-home with frequency once-per-instance
2019-06-12 00:42:24,058 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:24,058 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_phone_home - wb: [644] 25 bytes
2019-06-12 00:42:24,059 - helpers.py[DEBUG]: Running config-phone-home using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_phone_home'>)
2019-06-12 00:42:24,059 - cc_phone_home.py[DEBUG]: Skipping module named phone-home, no 'phone_home' configuration found
2019-06-12 00:42:24,059 - handlers.py[DEBUG]: finish: modules-final/config-phone-home: SUCCESS: config-phone-home ran successfully
2019-06-12 00:42:24,063 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:24,063 - 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-06-12 00:42:24,063 - handlers.py[DEBUG]: start: modules-final/config-final-message: running config-final-message with frequency always
2019-06-12 00:42:24,068 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:24,068 - helpers.py[DEBUG]: Running config-final-message using lock (<cloudinit.helpers.DummyLock object at 0x7f421ecef400>)
2019-06-12 00:42:24,068 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2019-06-12 00:42:24,068 - util.py[DEBUG]: Read 14 bytes from /proc/uptime
2019-06-12 00:42:24,071 - util.py[DEBUG]: Cloud-init v. 19.1-1-gbaa47854-0ubuntu1~16.04.1 finished at Wed, 12 Jun 2019 00:42:24 +0000. Datasource DataSourceMAAS [http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/]. Up 41.91 seconds
2019-06-12 00:42:24,071 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/boot-finished - wb: [644] 79 bytes
2019-06-12 00:42:24,071 - handlers.py[DEBUG]: finish: modules-final/config-final-message: SUCCESS: config-final-message ran successfully
2019-06-12 00:42:24,075 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:24,075 - 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-06-12 00:42:24,075 - handlers.py[DEBUG]: start: modules-final/config-power-state-change: running config-power-state-change with frequency once-per-instance
2019-06-12 00:42:24,080 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:24,080 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/re6cck/sem/config_power_state_change - wb: [644] 25 bytes
2019-06-12 00:42:24,081 - helpers.py[DEBUG]: Running config-power-state-change using lock (<FileLock using file '/var/lib/cloud/instances/re6cck/sem/config_power_state_change'>)
2019-06-12 00:42:24,081 - cc_power_state_change.py[DEBUG]: no power_state provided. doing nothing
2019-06-12 00:42:24,081 - handlers.py[DEBUG]: finish: modules-final/config-power-state-change: SUCCESS: config-power-state-change ran successfully
2019-06-12 00:42:24,084 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
2019-06-12 00:42:24,085 - main.py[DEBUG]: Ran 21 modules with 0 failures
2019-06-12 00:42:24,085 - util.py[DEBUG]: Creating symbolic link from '/run/cloud-init/result.json' => '../../var/lib/cloud/data/result.json'
2019-06-12 00:42:24,085 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2019-06-12 00:42:24,085 - util.py[DEBUG]: Read 14 bytes from /proc/uptime
2019-06-12 00:42:24,086 - util.py[DEBUG]: cloud-init mode 'modules' took 4.058 seconds (4.06)
2019-06-12 00:42:24,086 - handlers.py[DEBUG]: finish: modules-final: SUCCESS: running modules for final
2019-06-12 00:42:24,126 - url_helper.py[DEBUG]: Read from http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/status/re6cck (204, 0b) after 1 attempts
And cloud-init-output.log
Cloud-init v. 19.1-1-gbaa47854-0ubuntu1~16.04.1 running 'init-local' at Wed, 12 Jun 2019 00:41:52 +0000. Up 10.22 seconds.
2019-06-12 00:41:52,429 - handlers.py[WARNING]: failed posting event: start: init-local/check-cache: attempting to read from cache [trust]
2019-06-12 00:41:52,430 - handlers.py[WARNING]: failed posting event: finish: init-local/check-cache: SUCCESS: no cache found
2019-06-12 00:41:52,548 - handlers.py[WARNING]: failed posting event: finish: init-local: SUCCESS: searching for local datasources
Cloud-init v. 19.1-1-gbaa47854-0ubuntu1~16.04.1 running 'init' at Wed, 12 Jun 2019 00:41:53 +0000. Up 11.57 seconds.
ci-info: ++++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++++
ci-info: +----------+-------+------------------------------+---------------+--------+-------------------+
ci-info: | Device | Up | Address | Mask | Scope | Hw-Address |
ci-info: +----------+-------+------------------------------+---------------+--------+-------------------+
ci-info: | eno1 | True | fe80::2e60:cff:fe83:6cf3/64 | . | link | 2c:60:0c:83:6c:f3 |
ci-info: | eno2 | True | xxx.xxx.xxx.xxx:xxxxc:f4 |
ci-info: | eno2 | True | fe80::2e60:cff:fe83:6cf4/64 | . | link | 2c:60:0c:83:6c:f4 |
ci-info: | enp6s0f0 | True | fe80::92e2:baff:fe7e:c4c0/64 | . | link | 90:e2:ba:7e:c4:c0 |
ci-info: | enp6s0f1 | False | . | . | . | 90:e2:ba:7e:c4:c1 |
ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . |
ci-info: | lo | True | ::1/128 | . | host | . |
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 | xxx.xxx.xxx.xxx | 0.0.0.0 | eno2 | UG |
ci-info: | 1 | xxx.xxx.xxx.xxx | 0.0.0.0 | 255.255.255.0 | eno2 | U |
ci-info: +-------+--------------+--------------+---------------+-----------+-------+
ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++
ci-info: +-------+-------------+---------+-----------+-------+
ci-info: | Route | Destination | Gateway | Interface | Flags |
ci-info: +-------+-------------+---------+-----------+-------+
ci-info: | 0 | fe80::/64 | :: | eno1 | U |
ci-info: | 1 | fe80::/64 | :: | eno2 | U |
ci-info: | 2 | fe80::/64 | :: | enp6s0f0 | U |
ci-info: | 5 | ff00::/8 | :: | eno1 | U |
ci-info: | 6 | ff00::/8 | :: | eno2 | U |
ci-info: | 7 | ff00::/8 | :: | enp6s0f0 | 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:M5ZHg+f7tl0vWdSB0p7XtsBuaSrqD7vACgsuS4wz4pQ root@cacpu04
The key's randomart image is:
+---[RSA 2048]----+
| . . |
| . . o . |
| . + + . +|
| = . = .=|
| S o . +o.|
|o . . . + . = ..|
|*E o . . + o.|
|Ooo . . o. o..o..|
|o= . .=+...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:bRuWiLf4yzXg7rCiGZ8qoNJHH95sTkqdTGCowPvu3II root@cacpu04
The key's randomart image is:
+---[DSA 1024]----+
| |
|. . |
|.. . o |
| ... . o o . |
| .. . S * |
|. . . .B * o |
|o.oo o++B + |
|+E+=+ooO+. . |
|..=B+oo+B. |
+----[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:ND28X3sQmUhPUJ9TyZLiKgnlWIR3+CWME5JWOaGX4dM root@cacpu04
The key's randomart image is:
+---[ECDSA 256]---+
| .=*B oo= o|
| ++X+* + * *o|
| ..*=BEB o *o.|
| o.o.o + ..|
| . S o o |
| o . . . 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:+RBWCsjGYkcCg19UEebg+XZi2fJFwdZdnNULJ6foR+A root@cacpu04
The key's randomart image is:
+--[ED25519 256]--+
|+..=+o*o .o. . o*|
|..ooB= . ooo.o.+o|
| o =o . +.o o * .|
| . . + + E o . |
| B S o . |
| o = + . . |
| . . . |
| |
| |
+----[SHA256]-----+
Generating locales (this might take a while)...
en_US.UTF-8... done
Generation complete.
Get:1 https://apt.kubernetes.io kubernetes-xenial InRelease [161 B]
Hit:2 http://archive.ubuntu.com/ubuntu xenial InRelease
Hit:3 http://archive.ubuntu.com/ubuntu xenial-updates InRelease
Hit:1 https://apt.kubernetes.io kubernetes-xenial InRelease
Hit:4 http://archive.ubuntu.com/ubuntu xenial-security InRelease
Hit:5 http://archive.ubuntu.com/ubuntu xenial-backports InRelease
Get:6 http://archive.ubuntu.com/ubuntu xenial/multiverse Translation-en [106 kB]
Get:7 http://archive.ubuntu.com/ubuntu xenial/universe Translation-en [4354 kB]
Get:8 http://archive.ubuntu.com/ubuntu xenial/main Translation-en [568 kB]
Get:9 http://archive.ubuntu.com/ubuntu xenial/restricted Translation-en [2908 B]
Get:10 http://archive.ubuntu.com/ubuntu xenial-updates/multiverse Translation-en [8440 B]
Get:11 http://archive.ubuntu.com/ubuntu xenial-updates/universe Translation-en [312 kB]
Get:12 http://archive.ubuntu.com/ubuntu xenial-updates/main Translation-en [384 kB]
Get:13 http://archive.ubuntu.com/ubuntu xenial-updates/restricted Translation-en [2272 B]
Get:14 http://archive.ubuntu.com/ubuntu xenial-security/multiverse Translation-en [2676 B]
Get:15 http://archive.ubuntu.com/ubuntu xenial-security/universe Translation-en [178 kB]
Get:16 http://archive.ubuntu.com/ubuntu xenial-security/main Translation-en [270 kB]
Get:17 http://archive.ubuntu.com/ubuntu xenial-security/restricted Translation-en [2152 B]
Get:18 http://archive.ubuntu.com/ubuntu xenial-backports/universe Translation-en [4184 B]
Get:19 http://archive.ubuntu.com/ubuntu xenial-backports/main Translation-en [4456 B]
Fetched 6199 kB in 4s (1262 kB/s)
Reading package lists...
Reading package lists...
Building dependency tree...
Reading state information...
The following additional packages will be installed:
libopts25
Suggested packages:
ntp-doc
The following NEW packages will be installed:
libopts25 ntp
0 upgraded, 2 newly installed, 0 to remove and 23 not upgraded.
Need to get 576 kB of archives.
After this operation, 1792 kB of additional disk space will be used.
Get:1 http://archive.ubuntu.com/ubuntu xenial/main amd64 libopts25 amd64 1:5.18.7-3 [57.8 kB]
Get:2 http://archive.ubuntu.com/ubuntu xenial-updates/main amd64 ntp amd64 1:4.2.8p4+dfsg-3ubuntu5.9 [519 kB]
Fetched 576 kB in 0s (9655 kB/s)
Selecting previously unselected package libopts25:amd64.
(Reading database ...
(Reading database ... 5%
(Reading database ... 10%
(Reading database ... 15%
(Reading database ... 20%
(Reading database ... 25%
(Reading database ... 30%
(Reading database ... 35%
(Reading database ... 40%
(Reading database ... 45%
(Reading database ... 50%
(Reading database ... 55%
(Reading database ... 60%
(Reading database ... 65%
(Reading database ... 70%
(Reading database ... 75%
(Reading database ... 80%
(Reading database ... 85%
(Reading database ... 90%
(Reading database ... 95%
(Reading database ... 100%
(Reading database ... 60890 files and directories currently installed.)
Preparing to unpack .../libopts25_1%3a5.18.7-3_amd64.deb ...
Unpacking libopts25:amd64 (1:5.18.7-3) ...
Selecting previously unselected package ntp.
Preparing to unpack .../ntp_1%3a4.2.8p4+dfsg-3ubuntu5.9_amd64.deb ...
Unpacking ntp (1:4.2.8p4+dfsg-3ubuntu5.9) ...
Processing triggers for libc-bin (2.23-0ubuntu11) ...
Processing triggers for man-db (2.7.5-1) ...
Processing triggers for ureadahead (0.100.0-19.1) ...
Processing triggers for systemd (229-4ubuntu21.21) ...
Setting up libopts25:amd64 (1:5.18.7-3) ...
Setting up ntp (1:4.2.8p4+dfsg-3ubuntu5.9) ...
Configuration file '/etc/ntp.conf'
==> File on system created by you or by a script.
==> File also in package provided by package maintainer.
==> Using current old file as you requested.
ERROR: ld.so: object 'libeatmydata.so' from LD_PRELOAD cannot be preloaded (cannot open shared object file): ignored.
Processing triggers for libc-bin (2.23-0ubuntu11) ...
Processing triggers for ureadahead (0.100.0-19.1) ...
Processing triggers for systemd (229-4ubuntu21.21) ...
Cloud-init v. 19.1-1-gbaa47854-0ubuntu1~16.04.1 running 'modules:config' at Wed, 12 Jun 2019 00:42:07 +0000. Up 25.00 seconds.
[preflight] Running pre-flight checks
[WARNING SystemVerification]: this Docker version is not on the list of validated versions: 18.09.6. Latest validated version: 18.06
[WARNING Hostname]: hostname "worker-standard-7zth7" could not be reached
[WARNING Hostname]: hostname "worker-standard-7zth7": lookup worker-standard-7zth7 on 8.8.8.8:53: no such host
[discovery] Trying to connect to API Server "xxx.xxx.xxx.xxx:xxxx"
[discovery] Created cluster-info discovery client, requesting info from "https://xxx.xxx.xxx.xxx:xxxx"
[discovery] Requesting info from "https://xxx.xxx.xxx.xxx:xxxx" again to validate TLS against the pinned public key
[discovery] Cluster info signature and contents are valid and TLS certificate validates against pinned roots, will use API Server "xxx.xxx.xxx.xxx:xxxx"
[discovery] Successfully established connection with API Server "xxx.xxx.xxx.xxx:xxxx"
[join] Reading configuration from the cluster...
[join] FYI: You can look at this config file with 'kubectl -n kube-system get cm kubeadm-config -oyaml'
[kubelet] Downloading configuration for the kubelet from the "kubelet-config-1.13" ConfigMap in the kube-system namespace
[kubelet-start] Writing kubelet configuration to file "/var/lib/kubelet/config.yaml"
[kubelet-start] Writing kubelet environment file with flags to file "/var/lib/kubelet/kubeadm-flags.env"
[kubelet-start] Activating the kubelet service
[tlsbootstrap] Waiting for the kubelet to perform the TLS Bootstrap...
[patchnode] Uploading the CRI Socket information "/var/run/dockershim.sock" to the Node API object "worker-standard-7zth7" as an annotation
This node has joined the cluster:
* Certificate signing request was sent to apiserver and a response was received.
* The Kubelet was informed of the new secure connection details.
Run 'kubectl get nodes' on the master to see this node join the cluster.
Cloud-init v. 19.1-1-gbaa47854-0ubuntu1~16.04.1 running 'modules:final' at Wed, 12 Jun 2019 00:42:20 +0000. Up 37.87 seconds.
Cloud-init v. 19.1-1-gbaa47854-0ubuntu1~16.04.1 finished at Wed, 12 Jun 2019 00:42:24 +0000. Datasource DataSourceMAAS [http://xxx.xxx.xxx.xxx:xxxx/MAAS/metadata/]. Up 41.91 seconds