customization with gosc (Guest OS Customization from VMware) and cloud-init has no consistent results

betweenclouds commented 2 years ago

Describe the bug

We struggling since a long time with the correct customization steps from a default ubuntu cloud image in one step (not create a template first and clone from this). We use govc to clone the imported ubuntu OVA, change the IP and add a minimal user-data, then start the VM. The VM reboots one time (initiated from gosc?) and is then configured.

The resulting VMs sometimes has the correct hostname (from the VM name) and sometimes just "ubuntu".

Why is this incosistent? Is there a documentation about the interaction of cloud-init and gosc (which part runs when and do they interact)?

vCenter: 6.7.0 Build: 19299595
Baseimage: ubuntu-focal-20.04-cloudimg
vmware-toolbox-cmd -v 11.0.5.17716 (build-15389592)

I'm happy to deliver logs if needed.

Reproduction steps

import a default ubuntu cloudimage OVA (ubuntu-focal-20.04-cloudimg)

create a userdata:

#cloud-config
groups:
- docker
users:
- default
- name: ubuntu
ssh-authorized-keys:
  - ssh-rsa AAAA...
sudo: ALL=(ALL) NOPASSWD:ALL
groups: sudo, docker
shell: /bin/bash
write_files:
- path: /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg
content: |
disable_vmware_customization: false

from this user-data (b64 encoded) create a env.xml

<?xml version="1.0" encoding="UTF-8"?>
<Environment
 xmlns="http://schemas.dmtf.org/ovf/environment/1"
 xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
 xmlns:oe="http://schemas.dmtf.org/ovf/environment/1"
 xmlns:ve="http://www.vmware.com/schema/ovfenv">
<PropertySection>
     <Property oe:key="instance-id" oe:value="id-ovf"/>
     <Property oe:key="user-data" oe:value="I2N...zIgo="/>
</PropertySection>
</Environment>

setup and start (multiple) VMs

govc vm.clone -vm ubuntu-focal-20.04-cloudimg -ds=MY_DS -pool=/MYDC/host/MYCLUSTER -folder=/MYFOLDER -on=false MY_VM_01
govc vm.customize -vm MY_VM_01 -ip 192.168.1.10 -netmask 255.255.255.0 -gateway=192.168.1.1 -dns-server=192.168.1.100,192.168.1.101 -dns-suffix=mydomain.io
govc vm.network.change -vm MY_VM_01 -net=MYNETWORK ethernet-0
govc vm.change -vm MY_VM_01 -f guestinfo.ovfEnv="env.xml"
govc vm.power -on MY_VM_01

Expected behavior

Every clone should be configured correct and consistent.

Additional context

To rule out any doubled user-data, I also tried this with the cdrom removed and vapp options disabled in the template with the same results.

xiaofengw-vmware commented 2 years ago

@betweenclouds gosc could customize the VM through 2 ways: one is traditional customization, which calls its own engine to apply the customization specification. Another is cloud-init, which converts the customization specification to cloud-init meta data and delegate the customization to cloud-init. These 2 types of customization are controlled by flag disable_vmware_customization of file /etc/cloud/cloud.cfg

Regarding to cloud-init, its meta data/user data could read from:

meta data converted from gosc customization specification or
guestinfo.ovfEnv

You can't customize a VM with gosc + guestinfo.ovfEnv at the same time. As you know, traditional gosc customization will reboot the VM, this will interrupt the guestinfo.ovfEnv (cloud-init) and lead to unexpected results. You could provide us below logs for further analysis. Thanks. /var/log/vmware-imc/*.log /var/log/cloud-init.log

@PengpengSun Do you have any documentation about the interaction of cloud-init and gosc? Thanks.

PengpengSun commented 2 years ago

Do you have any documentation about the interaction of cloud-init and gosc? Thanks.

Yes, there is a KB https://kb.vmware.com/s/article/59557 on how to enable or disable Linux guest customization with cloud-init.

As @xiaofengw-vmware mentioned, gosc traditional(legacy) workflow could interrupt cloud-init execution since there is a reboot triggered by gosc workflow. And vice versa, cloud-init execution could cause gosc traditional(legacy) workflow fail. For ubuntu, the suggestion way is use either gosc or cloud-init, not both of them at the same boot.

The logs will tell us more details on what happened, we probably will see the conflict happened between gosc and cloud-init. Beside /var/log/vmware-imc/*.log, please run 'cloud-init collect-logs' and share the tar file.

betweenclouds commented 2 years ago

Thank you both for looking into this.

So, do you think that the issue here is that I set the IP with govc (this happend with gosc?) and then trigger the cloud-init with the guestinfo.ovfEnv var? I did this because I did not found any other clean way to set a fixed IP to the VM.

I tried both disable_vmware_customization=true and false, but get the same results. is it possible to config, gosc that it waits for cloud-init or is this the wrong way? Are there any options to configure gosc from outside, like the guestinfo vars? How do I give gosc the user-data to handover to cloud-init like @xiaofengw-vmware describes in point 1? Is this done in vCenter with a "VM Customization Specifications"? But then I cannot add any own user-data?

I will collect and attach the logs now.

betweenclouds commented 2 years ago

/var/log/cloud-init.log

``` 2022-04-07 12:31:11,877 - util.py[DEBUG]: Cloud-init v. 21.4-0ubuntu1~20.04.1 running 'init-local' at Thu, 07 Apr 2022 12:31:11 +0000. Up 4.93 seconds. 2022-04-07 12:31:11,877 - main.py[DEBUG]: No kernel command line url found. 2022-04-07 12:31:11,877 - main.py[DEBUG]: Closing stdin. 2022-04-07 12:31:11,879 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [644] 0 bytes 2022-04-07 12:31:11,879 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 104:4 2022-04-07 12:31:11,879 - util.py[DEBUG]: Writing to /var/lib/cloud/data/python-version - wb: [644] 3 bytes 2022-04-07 12:31:11,880 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance/boot-finished 2022-04-07 12:31:11,880 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/data/no-net 2022-04-07 12:31:11,880 - handlers.py[DEBUG]: start: init-local/check-cache: attempting to read from cache [check] 2022-04-07 12:31:11,880 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False) 2022-04-07 12:31:11,880 - stages.py[DEBUG]: no cache found 2022-04-07 12:31:11,880 - handlers.py[DEBUG]: finish: init-local/check-cache: SUCCESS: no cache found 2022-04-07 12:31:11,880 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2022-04-07 12:31:11,882 - stages.py[DEBUG]: Using distro class 2022-04-07 12:31:11,882 - __init__.py[DEBUG]: Looking for data source in: ['OVF', 'None'], via packages ['', 'cloudinit.sources'] that matches dependencies ['FILESYSTEM'] 2022-04-07 12:31:11,891 - __init__.py[DEBUG]: Searching for local data source in: ['DataSourceOVF'] 2022-04-07 12:31:11,891 - handlers.py[DEBUG]: start: init-local/search-OVF: searching for local data from DataSourceOVF 2022-04-07 12:31:11,891 - __init__.py[DEBUG]: Seeing if we can get any data from 2022-04-07 12:31:11,891 - __init__.py[DEBUG]: Update datasource metadata and network config due to events: boot-new-instance 2022-04-07 12:31:11,891 - dmi.py[DEBUG]: querying dmi data /sys/class/dmi/id/product_name 2022-04-07 12:31:11,891 - DataSourceOVF.py[DEBUG]: VMware Virtualization Platform found 2022-04-07 12:31:11,891 - DataSourceOVF.py[DEBUG]: Found the customization plugin at /usr/lib/open-vm-tools/plugins/vmsvc/libdeployPkgPlugin.so 2022-04-07 12:31:11,891 - DataSourceOVF.py[DEBUG]: Waiting for VMware Customization Config File 2022-04-07 12:31:16,896 - DataSourceOVF.py[DEBUG]: Waiting for VMware Customization Config File 2022-04-07 12:31:21,901 - DataSourceOVF.py[DEBUG]: Waiting for VMware Customization Config File 2022-04-07 12:31:26,907 - util.py[DEBUG]: waiting for configuration file took 15.016 seconds 2022-04-07 12:31:26,907 - DataSourceOVF.py[DEBUG]: Did not find VMware Customization Config File 2022-04-07 12:31:26,907 - subp.py[DEBUG]: Running command ['vmware-rpctool', 'info-get guestinfo.ovfEnv'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:26,912 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False) 2022-04-07 12:31:26,912 - util.py[DEBUG]: Read 221 bytes from /etc/hosts 2022-04-07 12:31:26,912 - dmi.py[DEBUG]: querying dmi data /sys/class/dmi/id/product_name 2022-04-07 12:31:26,913 - atomic_helper.py[DEBUG]: Atomically writing to file /run/cloud-init/instance-data-sensitive.json (via temporary file /run/cloud-init/tmpxzahffyi) - w: [600] 4624 bytes/chars 2022-04-07 12:31:26,913 - atomic_helper.py[DEBUG]: Atomically writing to file /run/cloud-init/instance-data.json (via temporary file /run/cloud-init/tmpc0czgyvl) - w: [644] 1348 bytes/chars 2022-04-07 12:31:26,913 - handlers.py[DEBUG]: finish: init-local/search-OVF: SUCCESS: found local data from DataSourceOVF 2022-04-07 12:31:26,913 - stages.py[INFO]: Loaded datasource DataSourceOVF - DataSourceOVF [seed=com.vmware.guestInfo] 2022-04-07 12:31:26,913 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2022-04-07 12:31:26,913 - util.py[DEBUG]: Read 3807 bytes from /etc/cloud/cloud.cfg 2022-04-07 12:31:26,914 - util.py[DEBUG]: Attempting to load yaml from string of length 3807 with allowed root types (,) 2022-04-07 12:31:26,921 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2022-04-07 12:31:26,921 - util.py[DEBUG]: Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2022-04-07 12:31:26,921 - util.py[DEBUG]: Attempting to load yaml from string of length 314 with allowed root types (,) 2022-04-07 12:31:26,922 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2022-04-07 12:31:26,922 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2022-04-07 12:31:26,922 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2022-04-07 12:31:26,924 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2022-04-07 12:31:26,924 - util.py[DEBUG]: Read 31 bytes from /run/cloud-init/cloud.cfg 2022-04-07 12:31:26,924 - util.py[DEBUG]: Attempting to load yaml from string of length 31 with allowed root types (,) 2022-04-07 12:31:26,925 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2022-04-07 12:31:26,925 - util.py[DEBUG]: loaded blob returned None, returning default. 2022-04-07 12:31:26,925 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2022-04-07 12:31:26,925 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/iid-dsovf' 2022-04-07 12:31:26,926 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/iid-dsovf/datasource (quiet=False) 2022-04-07 12:31:26,926 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/datasource - wb: [644] 57 bytes 2022-04-07 12:31:26,926 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [644] 57 bytes 2022-04-07 12:31:26,926 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False) 2022-04-07 12:31:26,926 - stages.py[DEBUG]: previous iid found to be NO_PREVIOUS_INSTANCE_ID 2022-04-07 12:31:26,926 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [644] 10 bytes 2022-04-07 12:31:26,926 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [644] 10 bytes 2022-04-07 12:31:26,926 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [644] 24 bytes 2022-04-07 12:31:26,927 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [400] 9503 bytes 2022-04-07 12:31:26,927 - main.py[DEBUG]: [local] init will now be targeting instance id: iid-dsovf. new=True 2022-04-07 12:31:26,927 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2022-04-07 12:31:26,927 - util.py[DEBUG]: Read 3807 bytes from /etc/cloud/cloud.cfg 2022-04-07 12:31:26,927 - util.py[DEBUG]: Attempting to load yaml from string of length 3807 with allowed root types (,) 2022-04-07 12:31:26,934 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2022-04-07 12:31:26,935 - util.py[DEBUG]: Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2022-04-07 12:31:26,935 - util.py[DEBUG]: Attempting to load yaml from string of length 314 with allowed root types (,) 2022-04-07 12:31:26,936 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2022-04-07 12:31:26,936 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2022-04-07 12:31:26,936 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2022-04-07 12:31:26,938 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2022-04-07 12:31:26,938 - util.py[DEBUG]: Read 31 bytes from /run/cloud-init/cloud.cfg 2022-04-07 12:31:26,938 - util.py[DEBUG]: Attempting to load yaml from string of length 31 with allowed root types (,) 2022-04-07 12:31:26,938 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2022-04-07 12:31:26,938 - util.py[DEBUG]: loaded blob returned None, returning default. 2022-04-07 12:31:26,939 - stages.py[DEBUG]: Using distro class 2022-04-07 12:31:26,939 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False) 2022-04-07 12:31:26,939 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address 2022-04-07 12:31:26,939 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:31:26,939 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:31:26,940 - util.py[DEBUG]: Reading from /sys/class/net/ens192/name_assign_type (quiet=False) 2022-04-07 12:31:26,940 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/name_assign_type 2022-04-07 12:31:26,940 - util.py[DEBUG]: Reading from /sys/class/net/ens192/carrier (quiet=False) 2022-04-07 12:31:26,940 - util.py[DEBUG]: Reading from /sys/class/net/ens192/dormant (quiet=False) 2022-04-07 12:31:26,940 - util.py[DEBUG]: Reading from /sys/class/net/ens192/operstate (quiet=False) 2022-04-07 12:31:26,940 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/ens192/operstate 2022-04-07 12:31:26,940 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:31:26,940 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:31:26,940 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:31:26,940 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:31:26,940 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False) 2022-04-07 12:31:26,940 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address 2022-04-07 12:31:26,940 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:31:26,940 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:31:26,940 - util.py[DEBUG]: Reading from /sys/class/net/ens192/name_assign_type (quiet=False) 2022-04-07 12:31:26,940 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/name_assign_type 2022-04-07 12:31:26,940 - util.py[DEBUG]: Reading from /sys/class/net/ens192/carrier (quiet=False) 2022-04-07 12:31:26,940 - util.py[DEBUG]: Reading from /sys/class/net/ens192/dormant (quiet=False) 2022-04-07 12:31:26,941 - util.py[DEBUG]: Reading from /sys/class/net/ens192/operstate (quiet=False) 2022-04-07 12:31:26,941 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/ens192/operstate 2022-04-07 12:31:26,941 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:31:26,941 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:31:26,941 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:31:26,941 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:31:26,941 - util.py[DEBUG]: Reading from /sys/class/net/ens192/device/device (quiet=False) 2022-04-07 12:31:26,941 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/ens192/device/device 2022-04-07 12:31:26,941 - util.py[DEBUG]: Reading from /sys/class/net/lo/addr_assign_type (quiet=False) 2022-04-07 12:31:26,941 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/lo/addr_assign_type 2022-04-07 12:31:26,941 - util.py[DEBUG]: Reading from /sys/class/net/lo/uevent (quiet=False) 2022-04-07 12:31:26,941 - util.py[DEBUG]: Read 23 bytes from /sys/class/net/lo/uevent 2022-04-07 12:31:26,941 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False) 2022-04-07 12:31:26,941 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address 2022-04-07 12:31:26,941 - __init__.py[DEBUG]: ovs-vsctl not in PATH; not detecting Open vSwitch interfaces 2022-04-07 12:31:26,941 - util.py[DEBUG]: Reading from /sys/class/net/lo/device/device (quiet=False) 2022-04-07 12:31:26,941 - util.py[DEBUG]: Reading from /sys/class/net/ens192/addr_assign_type (quiet=False) 2022-04-07 12:31:26,941 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/addr_assign_type 2022-04-07 12:31:26,941 - util.py[DEBUG]: Reading from /sys/class/net/ens192/uevent (quiet=False) 2022-04-07 12:31:26,941 - util.py[DEBUG]: Read 27 bytes from /sys/class/net/ens192/uevent 2022-04-07 12:31:26,941 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:31:26,941 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:31:26,941 - util.py[DEBUG]: Reading from /sys/class/net/ens192/device/device (quiet=False) 2022-04-07 12:31:26,941 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/ens192/device/device 2022-04-07 12:31:26,941 - util.py[DEBUG]: Reading from /sys/class/net/lo/type (quiet=False) 2022-04-07 12:31:26,941 - util.py[DEBUG]: Read 4 bytes from /sys/class/net/lo/type 2022-04-07 12:31:26,941 - util.py[DEBUG]: Reading from /sys/class/net/ens192/type (quiet=False) 2022-04-07 12:31:26,942 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/type 2022-04-07 12:31:26,942 - networking.py[DEBUG]: net: all expected physical devices present 2022-04-07 12:31:26,942 - stages.py[DEBUG]: applying net config names for {'ethernets': {'ens192': {'dhcp4': True, 'set-name': 'ens192', 'match': {'macaddress': '00:50:56:a5:f6:80'}}}, 'version': 2} 2022-04-07 12:31:26,942 - util.py[DEBUG]: Reading from /sys/class/net/ens192/device/device (quiet=False) 2022-04-07 12:31:26,942 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/ens192/device/device 2022-04-07 12:31:26,942 - util.py[DEBUG]: Reading from /sys/class/net/lo/addr_assign_type (quiet=False) 2022-04-07 12:31:26,942 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/lo/addr_assign_type 2022-04-07 12:31:26,942 - util.py[DEBUG]: Reading from /sys/class/net/lo/uevent (quiet=False) 2022-04-07 12:31:26,942 - util.py[DEBUG]: Read 23 bytes from /sys/class/net/lo/uevent 2022-04-07 12:31:26,942 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False) 2022-04-07 12:31:26,942 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address 2022-04-07 12:31:26,942 - util.py[DEBUG]: Reading from /sys/class/net/lo/device/device (quiet=False) 2022-04-07 12:31:26,942 - util.py[DEBUG]: Reading from /sys/class/net/ens192/addr_assign_type (quiet=False) 2022-04-07 12:31:26,942 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/addr_assign_type 2022-04-07 12:31:26,942 - util.py[DEBUG]: Reading from /sys/class/net/ens192/uevent (quiet=False) 2022-04-07 12:31:26,942 - util.py[DEBUG]: Read 27 bytes from /sys/class/net/ens192/uevent 2022-04-07 12:31:26,942 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:31:26,942 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:31:26,942 - util.py[DEBUG]: Reading from /sys/class/net/ens192/device/device (quiet=False) 2022-04-07 12:31:26,942 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/ens192/device/device 2022-04-07 12:31:26,942 - util.py[DEBUG]: Reading from /sys/class/net/lo/operstate (quiet=False) 2022-04-07 12:31:26,942 - util.py[DEBUG]: Read 8 bytes from /sys/class/net/lo/operstate 2022-04-07 12:31:26,942 - util.py[DEBUG]: Reading from /sys/class/net/ens192/operstate (quiet=False) 2022-04-07 12:31:26,942 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/ens192/operstate 2022-04-07 12:31:26,942 - subp.py[DEBUG]: Running command ['ip', '-6', 'addr', 'show', 'permanent', 'scope', 'global'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:26,944 - subp.py[DEBUG]: Running command ['ip', '-4', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:26,946 - __init__.py[DEBUG]: Detected interfaces {'lo': {'downable': False, 'device_id': None, 'driver': None, 'mac': '00:00:00:00:00:00', 'name': 'lo', 'up': True}, 'ens192': {'downable': True, 'device_id': '0x07b0', 'driver': 'vmxnet3', 'mac': '00:50:56:a5:f6:80', 'name': 'ens192', 'up': False}} 2022-04-07 12:31:26,946 - __init__.py[DEBUG]: no work necessary for renaming of [['00:50:56:a5:f6:80', 'ens192', 'vmxnet3', '0x07b0']] 2022-04-07 12:31:26,946 - stages.py[INFO]: Applying network configuration from fallback bringup=False: {'ethernets': {'ens192': {'dhcp4': True, 'set-name': 'ens192', 'match': {'macaddress': '00:50:56:a5:f6:80'}}}, 'version': 2} 2022-04-07 12:31:26,946 - util.py[DEBUG]: Writing to /run/cloud-init/sem/apply_network_config.once - wb: [644] 23 bytes 2022-04-07 12:31:26,947 - network_state.py[DEBUG]: v2(ethernets) -> v1(physical): {'type': 'physical', 'name': 'ens192', 'mac_address': '00:50:56:a5:f6:80', 'match': {'macaddress': '00:50:56:a5:f6:80'}, 'subnets': [{'type': 'dhcp4'}]} 2022-04-07 12:31:26,948 - network_state.py[DEBUG]: v2_common: handling config: {'ens192': {'dhcp4': True, 'set-name': 'ens192', 'match': {'macaddress': '00:50:56:a5:f6:80'}}} 2022-04-07 12:31:26,949 - __init__.py[DEBUG]: Selected renderer 'netplan' from priority list: ['netplan', 'eni', 'sysconfig'] 2022-04-07 12:31:26,949 - netplan.py[DEBUG]: V2 to V2 passthrough 2022-04-07 12:31:26,949 - util.py[DEBUG]: Writing to /etc/netplan/50-cloud-init.yaml - wb: [644] 485 bytes 2022-04-07 12:31:26,949 - subp.py[DEBUG]: Running command ['netplan', 'generate'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:27,036 - subp.py[DEBUG]: Running command ['udevadm', 'test-builtin', 'net_setup_link', '/sys/class/net/lo'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:27,038 - subp.py[DEBUG]: Running command ['udevadm', 'test-builtin', 'net_setup_link', '/sys/class/net/ens192'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:27,041 - __init__.py[DEBUG]: Not bringing up newly configured network interfaces 2022-04-07 12:31:27,041 - main.py[DEBUG]: [local] Exiting. datasource DataSourceOVF [seed=com.vmware.guestInfo] not in local mode. 2022-04-07 12:31:27,041 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmp4q894pmx) - w: [644] 513 bytes/chars 2022-04-07 12:31:27,041 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2022-04-07 12:31:27,041 - util.py[DEBUG]: Read 12 bytes from /proc/uptime 2022-04-07 12:31:27,041 - util.py[DEBUG]: cloud-init mode 'init' took 15.196 seconds (15.20) 2022-04-07 12:31:27,041 - handlers.py[DEBUG]: finish: init-local: SUCCESS: searching for local datasources 2022-04-07 12:31:34,064 - util.py[DEBUG]: Cloud-init v. 21.4-0ubuntu1~20.04.1 running 'init' at Thu, 07 Apr 2022 12:31:34 +0000. Up 27.12 seconds. 2022-04-07 12:31:34,064 - main.py[DEBUG]: No kernel command line url found. 2022-04-07 12:31:34,064 - main.py[DEBUG]: Closing stdin. 2022-04-07 12:31:34,065 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [644] 0 bytes 2022-04-07 12:31:34,065 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 104:4 2022-04-07 12:31:34,066 - subp.py[DEBUG]: Running command ['ip', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:34,068 - subp.py[DEBUG]: Running command ['ip', '-o', 'route', 'list'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:34,070 - subp.py[DEBUG]: Running command ['ip', '--oneline', '-6', 'route', 'list', 'table', 'all'] with allowed return codes [0, 1] (shell=False, capture=True) 2022-04-07 12:31:34,072 - main.py[DEBUG]: Checking to see if files that we need already exist from a previous run that would allow us to stop early. 2022-04-07 12:31:34,072 - main.py[DEBUG]: Execution continuing, no previous run detected that would allow us to stop early. 2022-04-07 12:31:34,072 - handlers.py[DEBUG]: start: init-network/check-cache: attempting to read from cache [trust] 2022-04-07 12:31:34,072 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False) 2022-04-07 12:31:34,072 - util.py[DEBUG]: Read 9503 bytes from /var/lib/cloud/instance/obj.pkl 2022-04-07 12:31:34,077 - util.py[DEBUG]: Reading from /run/cloud-init/.instance-id (quiet=False) 2022-04-07 12:31:34,077 - util.py[DEBUG]: Read 10 bytes from /run/cloud-init/.instance-id 2022-04-07 12:31:34,077 - stages.py[DEBUG]: restored from cache with run check: DataSourceOVF [seed=com.vmware.guestInfo] 2022-04-07 12:31:34,077 - handlers.py[DEBUG]: finish: init-network/check-cache: SUCCESS: restored from cache with run check: DataSourceOVF [seed=com.vmware.guestInfo] 2022-04-07 12:31:34,077 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2022-04-07 12:31:34,077 - util.py[DEBUG]: Read 3807 bytes from /etc/cloud/cloud.cfg 2022-04-07 12:31:34,077 - util.py[DEBUG]: Attempting to load yaml from string of length 3807 with allowed root types (,) 2022-04-07 12:31:34,085 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2022-04-07 12:31:34,085 - util.py[DEBUG]: Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2022-04-07 12:31:34,085 - util.py[DEBUG]: Attempting to load yaml from string of length 314 with allowed root types (,) 2022-04-07 12:31:34,086 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2022-04-07 12:31:34,086 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2022-04-07 12:31:34,086 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2022-04-07 12:31:34,088 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2022-04-07 12:31:34,088 - util.py[DEBUG]: Read 31 bytes from /run/cloud-init/cloud.cfg 2022-04-07 12:31:34,088 - util.py[DEBUG]: Attempting to load yaml from string of length 31 with allowed root types (,) 2022-04-07 12:31:34,089 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2022-04-07 12:31:34,089 - util.py[DEBUG]: loaded blob returned None, returning default. 2022-04-07 12:31:34,089 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2022-04-07 12:31:34,089 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/iid-dsovf' 2022-04-07 12:31:34,089 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/iid-dsovf/datasource (quiet=False) 2022-04-07 12:31:34,089 - util.py[DEBUG]: Read 57 bytes from /var/lib/cloud/instances/iid-dsovf/datasource 2022-04-07 12:31:34,089 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/datasource - wb: [644] 57 bytes 2022-04-07 12:31:34,090 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [644] 57 bytes 2022-04-07 12:31:34,090 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False) 2022-04-07 12:31:34,090 - util.py[DEBUG]: Read 10 bytes from /var/lib/cloud/data/instance-id 2022-04-07 12:31:34,090 - stages.py[DEBUG]: previous iid found to be iid-dsovf 2022-04-07 12:31:34,090 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [644] 10 bytes 2022-04-07 12:31:34,090 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [644] 10 bytes 2022-04-07 12:31:34,090 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [644] 10 bytes 2022-04-07 12:31:34,091 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [400] 9515 bytes 2022-04-07 12:31:34,091 - main.py[DEBUG]: [net] init will now be targeting instance id: iid-dsovf. new=False 2022-04-07 12:31:34,091 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2022-04-07 12:31:34,091 - util.py[DEBUG]: Read 3807 bytes from /etc/cloud/cloud.cfg 2022-04-07 12:31:34,091 - util.py[DEBUG]: Attempting to load yaml from string of length 3807 with allowed root types (,) 2022-04-07 12:31:34,098 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2022-04-07 12:31:34,098 - util.py[DEBUG]: Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2022-04-07 12:31:34,098 - util.py[DEBUG]: Attempting to load yaml from string of length 314 with allowed root types (,) 2022-04-07 12:31:34,099 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2022-04-07 12:31:34,100 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2022-04-07 12:31:34,100 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2022-04-07 12:31:34,102 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2022-04-07 12:31:34,102 - util.py[DEBUG]: Read 31 bytes from /run/cloud-init/cloud.cfg 2022-04-07 12:31:34,102 - util.py[DEBUG]: Attempting to load yaml from string of length 31 with allowed root types (,) 2022-04-07 12:31:34,102 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2022-04-07 12:31:34,102 - util.py[DEBUG]: loaded blob returned None, returning default. 2022-04-07 12:31:34,103 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False) 2022-04-07 12:31:34,103 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address 2022-04-07 12:31:34,103 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:31:34,103 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:31:34,103 - stages.py[DEBUG]: Using distro class 2022-04-07 12:31:34,103 - util.py[DEBUG]: Reading from /sys/class/net/ens192/name_assign_type (quiet=False) 2022-04-07 12:31:34,103 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/name_assign_type 2022-04-07 12:31:34,103 - util.py[DEBUG]: Reading from /sys/class/net/ens192/carrier (quiet=False) 2022-04-07 12:31:34,103 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/carrier 2022-04-07 12:31:34,103 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:31:34,103 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:31:34,104 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:31:34,104 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:31:34,104 - stages.py[DEBUG]: Allowed events: {: {}} 2022-04-07 12:31:34,104 - stages.py[DEBUG]: Event Denied: scopes=['network'] EventType=boot-legacy 2022-04-07 12:31:34,104 - stages.py[DEBUG]: No network config applied. Neither a new instance nor datasource network update allowed 2022-04-07 12:31:34,104 - stages.py[DEBUG]: applying net config names for {'ethernets': {'ens192': {'dhcp4': True, 'set-name': 'ens192', 'match': {'macaddress': '00:50:56:a5:f6:80'}}}, 'version': 2} 2022-04-07 12:31:34,104 - util.py[DEBUG]: Reading from /sys/class/net/ens192/device/device (quiet=False) 2022-04-07 12:31:34,104 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/ens192/device/device 2022-04-07 12:31:34,104 - util.py[DEBUG]: Reading from /sys/class/net/lo/addr_assign_type (quiet=False) 2022-04-07 12:31:34,104 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/lo/addr_assign_type 2022-04-07 12:31:34,104 - util.py[DEBUG]: Reading from /sys/class/net/lo/uevent (quiet=False) 2022-04-07 12:31:34,104 - util.py[DEBUG]: Read 23 bytes from /sys/class/net/lo/uevent 2022-04-07 12:31:34,104 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False) 2022-04-07 12:31:34,104 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address 2022-04-07 12:31:34,104 - __init__.py[DEBUG]: ovs-vsctl not in PATH; not detecting Open vSwitch interfaces 2022-04-07 12:31:34,104 - util.py[DEBUG]: Reading from /sys/class/net/lo/device/device (quiet=False) 2022-04-07 12:31:34,104 - util.py[DEBUG]: Reading from /sys/class/net/ens192/addr_assign_type (quiet=False) 2022-04-07 12:31:34,105 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/addr_assign_type 2022-04-07 12:31:34,105 - util.py[DEBUG]: Reading from /sys/class/net/ens192/uevent (quiet=False) 2022-04-07 12:31:34,105 - util.py[DEBUG]: Read 27 bytes from /sys/class/net/ens192/uevent 2022-04-07 12:31:34,105 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:31:34,105 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:31:34,105 - util.py[DEBUG]: Reading from /sys/class/net/ens192/device/device (quiet=False) 2022-04-07 12:31:34,105 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/ens192/device/device 2022-04-07 12:31:34,105 - util.py[DEBUG]: Reading from /sys/class/net/lo/operstate (quiet=False) 2022-04-07 12:31:34,105 - util.py[DEBUG]: Read 8 bytes from /sys/class/net/lo/operstate 2022-04-07 12:31:34,105 - util.py[DEBUG]: Reading from /sys/class/net/ens192/operstate (quiet=False) 2022-04-07 12:31:34,105 - util.py[DEBUG]: Read 3 bytes from /sys/class/net/ens192/operstate 2022-04-07 12:31:34,105 - subp.py[DEBUG]: Running command ['ip', '-6', 'addr', 'show', 'permanent', 'scope', 'global'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:34,106 - subp.py[DEBUG]: Running command ['ip', '-4', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:34,108 - __init__.py[DEBUG]: Detected interfaces {'lo': {'downable': False, 'device_id': None, 'driver': None, 'mac': '00:00:00:00:00:00', 'name': 'lo', 'up': True}, 'ens192': {'downable': False, 'device_id': '0x07b0', 'driver': 'vmxnet3', 'mac': '00:50:56:a5:f6:80', 'name': 'ens192', 'up': True}} 2022-04-07 12:31:34,108 - __init__.py[DEBUG]: no work necessary for renaming of [['00:50:56:a5:f6:80', 'ens192', 'vmxnet3', '0x07b0']] 2022-04-07 12:31:34,108 - handlers.py[DEBUG]: start: init-network/setup-datasource: setting up datasource 2022-04-07 12:31:34,108 - handlers.py[DEBUG]: finish: init-network/setup-datasource: SUCCESS: setting up datasource 2022-04-07 12:31:34,108 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/user-data.txt - wb: [600] 1454 bytes 2022-04-07 12:31:34,109 - util.py[DEBUG]: Attempting to load yaml from string of length 1454 with allowed root types (,) 2022-04-07 12:31:34,112 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/user-data.txt.i - wb: [600] 1759 bytes 2022-04-07 12:31:34,112 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/vendor-data.txt - wb: [600] 0 bytes 2022-04-07 12:31:34,113 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/vendor-data.txt.i - wb: [600] 308 bytes 2022-04-07 12:31:34,113 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/vendor-data2.txt - wb: [600] 0 bytes 2022-04-07 12:31:34,113 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/vendor-data2.txt.i - wb: [600] 308 bytes 2022-04-07 12:31:34,114 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/consume_data - wb: [644] 24 bytes 2022-04-07 12:31:34,114 - helpers.py[DEBUG]: Running consume_data using lock () 2022-04-07 12:31:34,114 - handlers.py[DEBUG]: start: init-network/consume-user-data: reading and applying user-data 2022-04-07 12:31:34,115 - stages.py[DEBUG]: Added default handler for {'text/cloud-config-jsonp', 'text/cloud-config'} from CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] 2022-04-07 12:31:34,115 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript'} from ShellScriptPartHandler: [['text/x-shellscript']] 2022-04-07 12:31:34,115 - stages.py[DEBUG]: Added default handler for {'text/cloud-boothook'} from BootHookPartHandler: [['text/cloud-boothook']] 2022-04-07 12:31:34,115 - stages.py[DEBUG]: Added default handler for {'text/upstart-job'} from UpstartJobPartHandler: [['text/upstart-job']] 2022-04-07 12:31:34,115 - stages.py[DEBUG]: Added default handler for {'text/jinja2'} from JinjaTemplatePartHandler: [['text/jinja2']] 2022-04-07 12:31:34,115 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__begin__, None, 3) with frequency once-per-instance 2022-04-07 12:31:34,115 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__begin__, None, 2) with frequency once-per-instance 2022-04-07 12:31:34,115 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__begin__, None, 2) with frequency once-per-instance 2022-04-07 12:31:34,115 - __init__.py[DEBUG]: Calling handler UpstartJobPartHandler: [['text/upstart-job']] (__begin__, None, 2) with frequency once-per-instance 2022-04-07 12:31:34,115 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__begin__, None, 3) with frequency once-per-instance 2022-04-07 12:31:34,115 - __init__.py[DEBUG]: {'MIME-Version': '1.0', 'Content-Type': 'text/cloud-config', 'Content-Disposition': 'attachment; filename="part-001"'} 2022-04-07 12:31:34,115 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (text/cloud-config, part-001, 3) with frequency once-per-instance 2022-04-07 12:31:34,115 - util.py[DEBUG]: Attempting to load yaml from string of length 1454 with allowed root types (,) 2022-04-07 12:31:34,117 - cloud_config.py[DEBUG]: Merging by applying [('dict', ['replace']), ('list', []), ('str', [])] 2022-04-07 12:31:34,117 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__end__, None, 3) with frequency once-per-instance 2022-04-07 12:31:34,118 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/cloud-config.txt - wb: [600] 918 bytes 2022-04-07 12:31:34,118 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__end__, None, 2) with frequency once-per-instance 2022-04-07 12:31:34,119 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__end__, None, 2) with frequency once-per-instance 2022-04-07 12:31:34,119 - __init__.py[DEBUG]: Calling handler UpstartJobPartHandler: [['text/upstart-job']] (__end__, None, 2) with frequency once-per-instance 2022-04-07 12:31:34,119 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__end__, None, 3) with frequency once-per-instance 2022-04-07 12:31:34,119 - handlers.py[DEBUG]: finish: init-network/consume-user-data: SUCCESS: reading and applying user-data 2022-04-07 12:31:34,119 - handlers.py[DEBUG]: start: init-network/consume-vendor-data: reading and applying vendor-data 2022-04-07 12:31:34,119 - stages.py[DEBUG]: no vendordata from datasource 2022-04-07 12:31:34,119 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data: SUCCESS: reading and applying vendor-data 2022-04-07 12:31:34,119 - handlers.py[DEBUG]: start: init-network/consume-vendor-data2: reading and applying vendor-data2 2022-04-07 12:31:34,119 - stages.py[DEBUG]: no vendordata2 from datasource 2022-04-07 12:31:34,119 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data2: SUCCESS: reading and applying vendor-data2 2022-04-07 12:31:34,119 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2022-04-07 12:31:34,119 - util.py[DEBUG]: Read 3807 bytes from /etc/cloud/cloud.cfg 2022-04-07 12:31:34,119 - util.py[DEBUG]: Attempting to load yaml from string of length 3807 with allowed root types (,) 2022-04-07 12:31:34,126 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2022-04-07 12:31:34,126 - util.py[DEBUG]: Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2022-04-07 12:31:34,126 - util.py[DEBUG]: Attempting to load yaml from string of length 314 with allowed root types (,) 2022-04-07 12:31:34,127 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2022-04-07 12:31:34,127 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2022-04-07 12:31:34,127 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2022-04-07 12:31:34,129 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2022-04-07 12:31:34,129 - util.py[DEBUG]: Read 31 bytes from /run/cloud-init/cloud.cfg 2022-04-07 12:31:34,129 - util.py[DEBUG]: Attempting to load yaml from string of length 31 with allowed root types (,) 2022-04-07 12:31:34,130 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2022-04-07 12:31:34,130 - util.py[DEBUG]: loaded blob returned None, returning default. 2022-04-07 12:31:34,130 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2022-04-07 12:31:34,130 - util.py[DEBUG]: Read 918 bytes from /var/lib/cloud/instance/cloud-config.txt 2022-04-07 12:31:34,130 - util.py[DEBUG]: Attempting to load yaml from string of length 918 with allowed root types (,) 2022-04-07 12:31:34,132 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2022-04-07 12:31:34,132 - util.py[DEBUG]: Read 918 bytes from /var/lib/cloud/instance/cloud-config.txt 2022-04-07 12:31:34,132 - util.py[DEBUG]: Attempting to load yaml from string of length 918 with allowed root types (,) 2022-04-07 12:31:34,134 - handlers.py[DEBUG]: start: init-network/activate-datasource: activating datasource 2022-04-07 12:31:34,135 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [400] 13064 bytes 2022-04-07 12:31:34,135 - handlers.py[DEBUG]: finish: init-network/activate-datasource: SUCCESS: activating datasource 2022-04-07 12:31:34,135 - main.py[DEBUG]: no di_report found in config. 2022-04-07 12:31:34,149 - stages.py[DEBUG]: Using distro class 2022-04-07 12:31:34,149 - stages.py[DEBUG]: Running module migrator () with frequency always 2022-04-07 12:31:34,149 - handlers.py[DEBUG]: start: init-network/config-migrator: running config-migrator with frequency always 2022-04-07 12:31:34,149 - helpers.py[DEBUG]: Running config-migrator using lock () 2022-04-07 12:31:34,149 - cc_migrator.py[DEBUG]: Migrated 0 semaphore files to there canonicalized names 2022-04-07 12:31:34,149 - handlers.py[DEBUG]: finish: init-network/config-migrator: SUCCESS: config-migrator ran successfully 2022-04-07 12:31:34,149 - stages.py[DEBUG]: Running module seed_random () with frequency once-per-instance 2022-04-07 12:31:34,150 - handlers.py[DEBUG]: start: init-network/config-seed_random: running config-seed_random with frequency once-per-instance 2022-04-07 12:31:34,150 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_seed_random - wb: [644] 24 bytes 2022-04-07 12:31:34,150 - helpers.py[DEBUG]: Running config-seed_random using lock () 2022-04-07 12:31:34,150 - cc_seed_random.py[DEBUG]: no command provided 2022-04-07 12:31:34,150 - handlers.py[DEBUG]: finish: init-network/config-seed_random: SUCCESS: config-seed_random ran successfully 2022-04-07 12:31:34,150 - stages.py[DEBUG]: Running module bootcmd () with frequency always 2022-04-07 12:31:34,150 - handlers.py[DEBUG]: start: init-network/config-bootcmd: running config-bootcmd with frequency always 2022-04-07 12:31:34,150 - helpers.py[DEBUG]: Running config-bootcmd using lock () 2022-04-07 12:31:34,150 - cc_bootcmd.py[DEBUG]: Skipping module named bootcmd, no 'bootcmd' key in configuration 2022-04-07 12:31:34,150 - handlers.py[DEBUG]: finish: init-network/config-bootcmd: SUCCESS: config-bootcmd ran successfully 2022-04-07 12:31:34,150 - stages.py[DEBUG]: Running module write-files () with frequency once-per-instance 2022-04-07 12:31:34,150 - handlers.py[DEBUG]: start: init-network/config-write-files: running config-write-files with frequency once-per-instance 2022-04-07 12:31:34,150 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_write_files - wb: [644] 23 bytes 2022-04-07 12:31:34,151 - helpers.py[DEBUG]: Running config-write-files using lock () 2022-04-07 12:31:34,194 - util.py[DEBUG]: Writing to /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg - wb: [644] 39 bytes 2022-04-07 12:31:34,195 - util.py[DEBUG]: Changing the ownership of /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg to 0:0 2022-04-07 12:31:34,195 - handlers.py[DEBUG]: finish: init-network/config-write-files: SUCCESS: config-write-files ran successfully 2022-04-07 12:31:34,195 - stages.py[DEBUG]: Running module growpart () with frequency always 2022-04-07 12:31:34,195 - handlers.py[DEBUG]: start: init-network/config-growpart: running config-growpart with frequency always 2022-04-07 12:31:34,195 - helpers.py[DEBUG]: Running config-growpart using lock () 2022-04-07 12:31:34,195 - cc_growpart.py[DEBUG]: No 'growpart' entry in cfg. Using default: {'mode': 'auto', 'devices': ['/'], 'ignore_growroot_disabled': False} 2022-04-07 12:31:34,195 - subp.py[DEBUG]: Running command ['growpart', '--help'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:34,198 - util.py[DEBUG]: Reading from /proc/844/mountinfo (quiet=False) 2022-04-07 12:31:34,198 - util.py[DEBUG]: Read 3550 bytes from /proc/844/mountinfo 2022-04-07 12:31:34,198 - util.py[DEBUG]: Reading from /sys/class/block/sda1/partition (quiet=False) 2022-04-07 12:31:34,198 - util.py[DEBUG]: Read 2 bytes from /sys/class/block/sda1/partition 2022-04-07 12:31:34,198 - util.py[DEBUG]: Reading from /sys/devices/pci0000:00/0000:00:15.0/0000:03:00.0/host2/target2:0:0/2:0:0:0/block/sda/dev (quiet=False) 2022-04-07 12:31:34,198 - util.py[DEBUG]: Read 4 bytes from /sys/devices/pci0000:00/0000:00:15.0/0000:03:00.0/host2/target2:0:0/2:0:0:0/block/sda/dev 2022-04-07 12:31:34,198 - subp.py[DEBUG]: Running command ['growpart', '--dry-run', '/dev/sda', '1'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:34,221 - subp.py[DEBUG]: Running command ['growpart', '/dev/sda', '1'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:34,503 - util.py[DEBUG]: resize_devices took 0.306 seconds 2022-04-07 12:31:34,503 - cc_growpart.py[INFO]: '/' resized: changed (/dev/sda, 1) from 2244984320 to 10621009408 2022-04-07 12:31:34,504 - handlers.py[DEBUG]: finish: init-network/config-growpart: SUCCESS: config-growpart ran successfully 2022-04-07 12:31:34,504 - stages.py[DEBUG]: Running module resizefs () with frequency always 2022-04-07 12:31:34,504 - handlers.py[DEBUG]: start: init-network/config-resizefs: running config-resizefs with frequency always 2022-04-07 12:31:34,504 - helpers.py[DEBUG]: Running config-resizefs using lock () 2022-04-07 12:31:34,504 - util.py[DEBUG]: Reading from /proc/844/mountinfo (quiet=False) 2022-04-07 12:31:34,504 - util.py[DEBUG]: Read 3550 bytes from /proc/844/mountinfo 2022-04-07 12:31:34,504 - cc_resizefs.py[DEBUG]: resize_info: dev=/dev/sda1 mnt_point=/ path=/ 2022-04-07 12:31:34,504 - cc_resizefs.py[DEBUG]: Resizing / (ext4) using resize2fs /dev/sda1 2022-04-07 12:31:34,505 - subp.py[DEBUG]: Running command ('resize2fs', '/dev/sda1') with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:34,549 - util.py[DEBUG]: Resizing took 0.044 seconds 2022-04-07 12:31:34,549 - cc_resizefs.py[DEBUG]: Resized root filesystem (type=ext4, val=True) 2022-04-07 12:31:34,549 - handlers.py[DEBUG]: finish: init-network/config-resizefs: SUCCESS: config-resizefs ran successfully 2022-04-07 12:31:34,549 - stages.py[DEBUG]: Running module disk_setup () with frequency once-per-instance 2022-04-07 12:31:34,549 - handlers.py[DEBUG]: start: init-network/config-disk_setup: running config-disk_setup with frequency once-per-instance 2022-04-07 12:31:34,549 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_disk_setup - wb: [644] 24 bytes 2022-04-07 12:31:34,550 - helpers.py[DEBUG]: Running config-disk_setup using lock () 2022-04-07 12:31:34,550 - handlers.py[DEBUG]: finish: init-network/config-disk_setup: SUCCESS: config-disk_setup ran successfully 2022-04-07 12:31:34,550 - stages.py[DEBUG]: Running module mounts () with frequency once-per-instance 2022-04-07 12:31:34,550 - handlers.py[DEBUG]: start: init-network/config-mounts: running config-mounts with frequency once-per-instance 2022-04-07 12:31:34,550 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_mounts - wb: [644] 24 bytes 2022-04-07 12:31:34,550 - helpers.py[DEBUG]: Running config-mounts using lock () 2022-04-07 12:31:34,550 - cc_mounts.py[DEBUG]: mounts configuration is [] 2022-04-07 12:31:34,550 - util.py[DEBUG]: Reading from /etc/fstab (quiet=False) 2022-04-07 12:31:34,550 - util.py[DEBUG]: Read 84 bytes from /etc/fstab 2022-04-07 12:31:34,550 - cc_mounts.py[DEBUG]: Attempting to determine the real name of ephemeral0 2022-04-07 12:31:34,551 - cc_mounts.py[DEBUG]: changed default device ephemeral0 => None 2022-04-07 12:31:34,551 - cc_mounts.py[DEBUG]: Ignoring nonexistent default named mount ephemeral0 2022-04-07 12:31:34,551 - cc_mounts.py[DEBUG]: Attempting to determine the real name of swap 2022-04-07 12:31:34,551 - cc_mounts.py[DEBUG]: changed default device swap => None 2022-04-07 12:31:34,551 - cc_mounts.py[DEBUG]: Ignoring nonexistent default named mount swap 2022-04-07 12:31:34,551 - cc_mounts.py[DEBUG]: no need to setup swap 2022-04-07 12:31:34,551 - cc_mounts.py[DEBUG]: No modifications to fstab needed 2022-04-07 12:31:34,551 - handlers.py[DEBUG]: finish: init-network/config-mounts: SUCCESS: config-mounts ran successfully 2022-04-07 12:31:34,551 - stages.py[DEBUG]: Running module set_hostname () with frequency once-per-instance 2022-04-07 12:31:34,551 - handlers.py[DEBUG]: start: init-network/config-set_hostname: running config-set_hostname with frequency once-per-instance 2022-04-07 12:31:34,551 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_set_hostname - wb: [644] 24 bytes 2022-04-07 12:31:34,551 - helpers.py[DEBUG]: Running config-set_hostname using lock () 2022-04-07 12:31:34,551 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False) 2022-04-07 12:31:34,551 - util.py[DEBUG]: Read 244 bytes from /etc/hosts 2022-04-07 12:31:34,551 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False) 2022-04-07 12:31:34,551 - util.py[DEBUG]: Read 244 bytes from /etc/hosts 2022-04-07 12:31:34,551 - cc_set_hostname.py[DEBUG]: Setting the hostname to ubuntu (ubuntu) 2022-04-07 12:31:34,551 - util.py[DEBUG]: Reading from /etc/hostname (quiet=False) 2022-04-07 12:31:34,551 - util.py[DEBUG]: Read 7 bytes from /etc/hostname 2022-04-07 12:31:34,551 - util.py[DEBUG]: Writing to /etc/hostname - wb: [644] 7 bytes 2022-04-07 12:31:34,552 - __init__.py[DEBUG]: Non-persistently setting the system hostname to ubuntu 2022-04-07 12:31:34,552 - subp.py[DEBUG]: Running command ['hostname', 'ubuntu'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:34,553 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/set-hostname (via temporary file /var/lib/cloud/data/tmpedbzf_vy) - w: [644] 45 bytes/chars 2022-04-07 12:31:34,553 - handlers.py[DEBUG]: finish: init-network/config-set_hostname: SUCCESS: config-set_hostname ran successfully 2022-04-07 12:31:34,553 - stages.py[DEBUG]: Running module update_hostname () with frequency always 2022-04-07 12:31:34,554 - handlers.py[DEBUG]: start: init-network/config-update_hostname: running config-update_hostname with frequency always 2022-04-07 12:31:34,554 - helpers.py[DEBUG]: Running config-update_hostname using lock () 2022-04-07 12:31:34,554 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False) 2022-04-07 12:31:34,554 - util.py[DEBUG]: Read 244 bytes from /etc/hosts 2022-04-07 12:31:34,554 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False) 2022-04-07 12:31:34,554 - util.py[DEBUG]: Read 244 bytes from /etc/hosts 2022-04-07 12:31:34,554 - cc_update_hostname.py[DEBUG]: Updating hostname to ubuntu (ubuntu) 2022-04-07 12:31:34,554 - util.py[DEBUG]: Reading from /etc/hostname (quiet=False) 2022-04-07 12:31:34,554 - util.py[DEBUG]: Read 7 bytes from /etc/hostname 2022-04-07 12:31:34,554 - __init__.py[DEBUG]: Attempting to update hostname to ubuntu in 1 files 2022-04-07 12:31:34,554 - util.py[DEBUG]: Reading from /var/lib/cloud/data/previous-hostname (quiet=False) 2022-04-07 12:31:34,554 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-hostname - wb: [644] 7 bytes 2022-04-07 12:31:34,554 - handlers.py[DEBUG]: finish: init-network/config-update_hostname: SUCCESS: config-update_hostname ran successfully 2022-04-07 12:31:34,554 - stages.py[DEBUG]: Running module update_etc_hosts () with frequency always 2022-04-07 12:31:34,554 - handlers.py[DEBUG]: start: init-network/config-update_etc_hosts: running config-update_etc_hosts with frequency always 2022-04-07 12:31:34,555 - helpers.py[DEBUG]: Running config-update_etc_hosts using lock () 2022-04-07 12:31:34,555 - cc_update_etc_hosts.py[DEBUG]: Configuration option 'manage_etc_hosts' is not set, not managing /etc/hosts in module update_etc_hosts 2022-04-07 12:31:34,555 - handlers.py[DEBUG]: finish: init-network/config-update_etc_hosts: SUCCESS: config-update_etc_hosts ran successfully 2022-04-07 12:31:34,555 - stages.py[DEBUG]: Running module ca-certs () with frequency once-per-instance 2022-04-07 12:31:34,555 - handlers.py[DEBUG]: start: init-network/config-ca-certs: running config-ca-certs with frequency once-per-instance 2022-04-07 12:31:34,555 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_ca_certs - wb: [644] 23 bytes 2022-04-07 12:31:34,555 - helpers.py[DEBUG]: Running config-ca-certs using lock () 2022-04-07 12:31:34,555 - cc_ca_certs.py[DEBUG]: Skipping module named ca-certs, no 'ca-certs' key in configuration 2022-04-07 12:31:34,555 - handlers.py[DEBUG]: finish: init-network/config-ca-certs: SUCCESS: config-ca-certs ran successfully 2022-04-07 12:31:34,555 - stages.py[DEBUG]: Running module rsyslog () with frequency once-per-instance 2022-04-07 12:31:34,555 - handlers.py[DEBUG]: start: init-network/config-rsyslog: running config-rsyslog with frequency once-per-instance 2022-04-07 12:31:34,555 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_rsyslog - wb: [644] 24 bytes 2022-04-07 12:31:34,555 - helpers.py[DEBUG]: Running config-rsyslog using lock () 2022-04-07 12:31:34,556 - cc_rsyslog.py[DEBUG]: Skipping module named rsyslog, no 'rsyslog' key in configuration 2022-04-07 12:31:34,556 - handlers.py[DEBUG]: finish: init-network/config-rsyslog: SUCCESS: config-rsyslog ran successfully 2022-04-07 12:31:34,556 - stages.py[DEBUG]: Running module users-groups () with frequency once-per-instance 2022-04-07 12:31:34,556 - handlers.py[DEBUG]: start: init-network/config-users-groups: running config-users-groups with frequency once-per-instance 2022-04-07 12:31:34,556 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_users_groups - wb: [644] 23 bytes 2022-04-07 12:31:34,556 - helpers.py[DEBUG]: Running config-users-groups using lock () 2022-04-07 12:31:34,556 - util.py[DEBUG]: Reading from /etc/os-release (quiet=True) 2022-04-07 12:31:34,556 - util.py[DEBUG]: Read 382 bytes from /etc/os-release 2022-04-07 12:31:34,557 - util.py[DEBUG]: Reading from /etc/system-image/channel.ini (quiet=True) 2022-04-07 12:31:34,557 - util.py[DEBUG]: Read 0 bytes from /etc/system-image/channel.ini 2022-04-07 12:31:34,557 - subp.py[DEBUG]: Running command ['groupadd', 'docker'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:34,566 - __init__.py[INFO]: Created new group docker 2022-04-07 12:31:34,566 - util.py[DEBUG]: Reading from /etc/os-release (quiet=True) 2022-04-07 12:31:34,566 - util.py[DEBUG]: Read 382 bytes from /etc/os-release 2022-04-07 12:31:34,567 - util.py[DEBUG]: Reading from /etc/system-image/channel.ini (quiet=True) 2022-04-07 12:31:34,567 - util.py[DEBUG]: Read 0 bytes from /etc/system-image/channel.ini 2022-04-07 12:31:34,567 - __init__.py[DEBUG]: Adding user ubuntu 2022-04-07 12:31:34,567 - subp.py[DEBUG]: Running hidden command to protect sensitive input/output logstring: ['useradd', 'ubuntu', '--comment', 'Ubuntu', '--groups', 'docker,adm,audio,cdrom,dialout,dip,floppy,lxd,netdev,plugdev,sudo,video', '--shell', '/bin/bash', '-m'] 2022-04-07 12:31:34,590 - subp.py[DEBUG]: Running command ['passwd', '-l', 'ubuntu'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:31:34,595 - util.py[DEBUG]: Reading from /etc/sudoers (quiet=False) 2022-04-07 12:31:34,596 - util.py[DEBUG]: Read 755 bytes from /etc/sudoers 2022-04-07 12:31:34,597 - util.py[DEBUG]: Writing to /etc/sudoers.d/90-cloud-init-users - wb: [440] 139 bytes 2022-04-07 12:31:34,597 - util.py[DEBUG]: Reading from /etc/ssh/sshd_config (quiet=False) 2022-04-07 12:31:34,598 - util.py[DEBUG]: Read 3287 bytes from /etc/ssh/sshd_config 2022-04-07 12:31:34,598 - util.py[DEBUG]: Changing the ownership of /home/ubuntu/.ssh to 1000:1001 2022-04-07 12:31:34,598 - util.py[DEBUG]: Writing to /home/ubuntu/.ssh/authorized_keys - wb: [600] 0 bytes 2022-04-07 12:31:34,598 - util.py[DEBUG]: Changing the ownership of /home/ubuntu/.ssh/authorized_keys to 1000:1001 2022-04-07 12:31:34,598 - util.py[DEBUG]: Reading from /home/ubuntu/.ssh/authorized_keys (quiet=False) 2022-04-07 12:31:34,598 - util.py[DEBUG]: Read 0 bytes from /home/ubuntu/.ssh/authorized_keys 2022-04-07 12:31:34,598 - util.py[DEBUG]: Writing to /home/ubuntu/.ssh/authorized_keys - wb: [600] 569 bytes 2022-04-07 12:31:34,599 - handlers.py[DEBUG]: finish: init-network/config-users-groups: SUCCESS: config-users-groups ran successfully 2022-04-07 12:31:34,599 - stages.py[DEBUG]: Running module ssh () with frequency once-per-instance 2022-04-07 12:31:34,599 - handlers.py[DEBUG]: start: init-network/config-ssh: running config-ssh with frequency once-per-instance 2022-04-07 12:31:34,599 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_ssh - wb: [644] 23 bytes 2022-04-07 12:31:34,599 - helpers.py[DEBUG]: Running config-ssh using lock () 2022-04-07 12:31:34,600 - subp.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) 2022-04-07 12:31:34,684 - util.py[DEBUG]: Group ssh_keys is not a valid group name 2022-04-07 12:31:34,685 - subp.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) 2022-04-07 12:31:34,727 - util.py[DEBUG]: Group ssh_keys is not a valid group name 2022-04-07 12:31:34,727 - subp.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) 2022-04-07 12:31:34,730 - util.py[DEBUG]: Group ssh_keys is not a valid group name 2022-04-07 12:31:34,731 - subp.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) 2022-04-07 12:31:34,734 - util.py[DEBUG]: Group ssh_keys is not a valid group name 2022-04-07 12:31:34,735 - util.py[DEBUG]: Reading from /etc/ssh/ssh_host_ecdsa_key.pub (quiet=False) 2022-04-07 12:31:34,735 - util.py[DEBUG]: Read 173 bytes from /etc/ssh/ssh_host_ecdsa_key.pub 2022-04-07 12:31:34,735 - util.py[DEBUG]: Reading from /etc/ssh/ssh_host_rsa_key.pub (quiet=False) 2022-04-07 12:31:34,735 - util.py[DEBUG]: Read 565 bytes from /etc/ssh/ssh_host_rsa_key.pub 2022-04-07 12:31:34,735 - util.py[DEBUG]: Reading from /etc/ssh/ssh_host_ed25519_key.pub (quiet=False) 2022-04-07 12:31:34,735 - util.py[DEBUG]: Read 93 bytes from /etc/ssh/ssh_host_ed25519_key.pub 2022-04-07 12:31:34,735 - util.py[DEBUG]: Reading from /etc/ssh/sshd_config (quiet=False) 2022-04-07 12:31:34,736 - util.py[DEBUG]: Read 3287 bytes from /etc/ssh/sshd_config 2022-04-07 12:31:34,736 - util.py[DEBUG]: Reading from /home/ubuntu/.ssh/authorized_keys (quiet=False) 2022-04-07 12:31:34,736 - util.py[DEBUG]: Read 569 bytes from /home/ubuntu/.ssh/authorized_keys 2022-04-07 12:31:34,736 - util.py[DEBUG]: Writing to /home/ubuntu/.ssh/authorized_keys - wb: [600] 569 bytes 2022-04-07 12:31:34,736 - util.py[DEBUG]: Reading from /etc/ssh/sshd_config (quiet=False) 2022-04-07 12:31:34,736 - util.py[DEBUG]: Read 3287 bytes from /etc/ssh/sshd_config 2022-04-07 12:31:34,737 - util.py[DEBUG]: Changing the ownership of /root/.ssh to 0:0 2022-04-07 12:31:34,737 - util.py[DEBUG]: Writing to /root/.ssh/authorized_keys - wb: [600] 0 bytes 2022-04-07 12:31:34,737 - util.py[DEBUG]: Changing the ownership of /root/.ssh/authorized_keys to 0:0 2022-04-07 12:31:34,737 - util.py[DEBUG]: Reading from /root/.ssh/authorized_keys (quiet=False) 2022-04-07 12:31:34,737 - util.py[DEBUG]: Read 0 bytes from /root/.ssh/authorized_keys 2022-04-07 12:31:34,737 - util.py[DEBUG]: Writing to /root/.ssh/authorized_keys - wb: [600] 0 bytes 2022-04-07 12:31:34,737 - handlers.py[DEBUG]: finish: init-network/config-ssh: SUCCESS: config-ssh ran successfully 2022-04-07 12:31:34,737 - main.py[DEBUG]: Ran 15 modules with 0 failures 2022-04-07 12:31:34,738 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmpapmh0p1k) - w: [644] 540 bytes/chars 2022-04-07 12:31:34,738 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2022-04-07 12:31:34,738 - util.py[DEBUG]: Read 13 bytes from /proc/uptime 2022-04-07 12:31:34,738 - util.py[DEBUG]: cloud-init mode 'init' took 0.702 seconds (0.71) 2022-04-07 12:31:34,738 - handlers.py[DEBUG]: finish: init-network: SUCCESS: searching for network datasources 2022-04-07 12:32:12,665 - util.py[DEBUG]: Cloud-init v. 21.4-0ubuntu1~20.04.1 running 'init-local' at Thu, 07 Apr 2022 12:32:12 +0000. Up 4.68 seconds. 2022-04-07 12:32:12,666 - main.py[DEBUG]: No kernel command line url found. 2022-04-07 12:32:12,666 - main.py[DEBUG]: Closing stdin. 2022-04-07 12:32:12,667 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [644] 0 bytes 2022-04-07 12:32:12,667 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 104:4 2022-04-07 12:32:12,668 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance/boot-finished 2022-04-07 12:32:12,668 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/data/no-net 2022-04-07 12:32:12,668 - handlers.py[DEBUG]: start: init-local/check-cache: attempting to read from cache [check] 2022-04-07 12:32:12,668 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False) 2022-04-07 12:32:12,668 - util.py[DEBUG]: Read 13064 bytes from /var/lib/cloud/instance/obj.pkl 2022-04-07 12:32:12,683 - stages.py[DEBUG]: cache invalid in datasource: DataSourceOVF [seed=com.vmware.guestInfo] 2022-04-07 12:32:12,683 - handlers.py[DEBUG]: finish: init-local/check-cache: SUCCESS: cache invalid in datasource: DataSourceOVF [seed=com.vmware.guestInfo] 2022-04-07 12:32:12,683 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2022-04-07 12:32:12,683 - stages.py[DEBUG]: Using distro class 2022-04-07 12:32:12,684 - __init__.py[DEBUG]: Looking for data source in: ['OVF', 'None'], via packages ['', 'cloudinit.sources'] that matches dependencies ['FILESYSTEM'] 2022-04-07 12:32:12,684 - __init__.py[DEBUG]: Searching for local data source in: ['DataSourceOVF'] 2022-04-07 12:32:12,684 - handlers.py[DEBUG]: start: init-local/search-OVF: searching for local data from DataSourceOVF 2022-04-07 12:32:12,684 - __init__.py[DEBUG]: Seeing if we can get any data from 2022-04-07 12:32:12,684 - __init__.py[DEBUG]: Update datasource metadata and network config due to events: boot-new-instance 2022-04-07 12:32:12,684 - dmi.py[DEBUG]: querying dmi data /sys/class/dmi/id/product_name 2022-04-07 12:32:12,685 - DataSourceOVF.py[DEBUG]: VMware Virtualization Platform found 2022-04-07 12:32:12,685 - DataSourceOVF.py[DEBUG]: Found the customization plugin at /usr/lib/open-vm-tools/plugins/vmsvc/libdeployPkgPlugin.so 2022-04-07 12:32:12,685 - DataSourceOVF.py[DEBUG]: Waiting for VMware Customization Config File 2022-04-07 12:32:17,690 - DataSourceOVF.py[DEBUG]: Waiting for VMware Customization Config File 2022-04-07 12:32:22,695 - DataSourceOVF.py[DEBUG]: Waiting for VMware Customization Config File 2022-04-07 12:32:27,700 - util.py[DEBUG]: waiting for configuration file took 15.016 seconds 2022-04-07 12:32:27,700 - DataSourceOVF.py[DEBUG]: Did not find VMware Customization Config File 2022-04-07 12:32:27,701 - subp.py[DEBUG]: Running command ['vmware-rpctool', 'info-get guestinfo.ovfEnv'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:32:27,704 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False) 2022-04-07 12:32:27,704 - util.py[DEBUG]: Read 244 bytes from /etc/hosts 2022-04-07 12:32:27,704 - dmi.py[DEBUG]: querying dmi data /sys/class/dmi/id/product_name 2022-04-07 12:32:27,705 - atomic_helper.py[DEBUG]: Atomically writing to file /run/cloud-init/instance-data-sensitive.json (via temporary file /run/cloud-init/tmp4n0s8jsr) - w: [600] 5592 bytes/chars 2022-04-07 12:32:27,706 - atomic_helper.py[DEBUG]: Atomically writing to file /run/cloud-init/instance-data.json (via temporary file /run/cloud-init/tmpib9umoda) - w: [644] 1348 bytes/chars 2022-04-07 12:32:27,706 - handlers.py[DEBUG]: finish: init-local/search-OVF: SUCCESS: found local data from DataSourceOVF 2022-04-07 12:32:27,706 - stages.py[INFO]: Loaded datasource DataSourceOVF - DataSourceOVF [seed=com.vmware.guestInfo] 2022-04-07 12:32:27,706 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2022-04-07 12:32:27,706 - util.py[DEBUG]: Read 3807 bytes from /etc/cloud/cloud.cfg 2022-04-07 12:32:27,706 - util.py[DEBUG]: Attempting to load yaml from string of length 3807 with allowed root types (,) 2022-04-07 12:32:27,713 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg (quiet=False) 2022-04-07 12:32:27,713 - util.py[DEBUG]: Read 39 bytes from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg 2022-04-07 12:32:27,713 - util.py[DEBUG]: Attempting to load yaml from string of length 39 with allowed root types (,) 2022-04-07 12:32:27,714 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2022-04-07 12:32:27,714 - util.py[DEBUG]: Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2022-04-07 12:32:27,714 - util.py[DEBUG]: Attempting to load yaml from string of length 314 with allowed root types (,) 2022-04-07 12:32:27,715 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2022-04-07 12:32:27,715 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2022-04-07 12:32:27,715 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2022-04-07 12:32:27,717 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2022-04-07 12:32:27,717 - util.py[DEBUG]: Read 31 bytes from /run/cloud-init/cloud.cfg 2022-04-07 12:32:27,717 - util.py[DEBUG]: Attempting to load yaml from string of length 31 with allowed root types (,) 2022-04-07 12:32:27,717 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2022-04-07 12:32:27,717 - util.py[DEBUG]: loaded blob returned None, returning default. 2022-04-07 12:32:27,718 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2022-04-07 12:32:27,718 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/iid-dsovf' 2022-04-07 12:32:27,718 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/iid-dsovf/datasource (quiet=False) 2022-04-07 12:32:27,718 - util.py[DEBUG]: Read 57 bytes from /var/lib/cloud/instances/iid-dsovf/datasource 2022-04-07 12:32:27,718 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/datasource - wb: [644] 57 bytes 2022-04-07 12:32:27,719 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [644] 57 bytes 2022-04-07 12:32:27,719 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False) 2022-04-07 12:32:27,719 - util.py[DEBUG]: Read 10 bytes from /var/lib/cloud/data/instance-id 2022-04-07 12:32:27,719 - stages.py[DEBUG]: previous iid found to be iid-dsovf 2022-04-07 12:32:27,719 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [644] 10 bytes 2022-04-07 12:32:27,719 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [644] 10 bytes 2022-04-07 12:32:27,719 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [644] 10 bytes 2022-04-07 12:32:27,720 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [400] 10385 bytes 2022-04-07 12:32:27,720 - main.py[DEBUG]: [local] init will now be targeting instance id: iid-dsovf. new=False 2022-04-07 12:32:27,720 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2022-04-07 12:32:27,720 - util.py[DEBUG]: Read 3807 bytes from /etc/cloud/cloud.cfg 2022-04-07 12:32:27,720 - util.py[DEBUG]: Attempting to load yaml from string of length 3807 with allowed root types (,) 2022-04-07 12:32:27,727 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg (quiet=False) 2022-04-07 12:32:27,727 - util.py[DEBUG]: Read 39 bytes from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg 2022-04-07 12:32:27,727 - util.py[DEBUG]: Attempting to load yaml from string of length 39 with allowed root types (,) 2022-04-07 12:32:27,728 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2022-04-07 12:32:27,728 - util.py[DEBUG]: Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2022-04-07 12:32:27,728 - util.py[DEBUG]: Attempting to load yaml from string of length 314 with allowed root types (,) 2022-04-07 12:32:27,729 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2022-04-07 12:32:27,729 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2022-04-07 12:32:27,729 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2022-04-07 12:32:27,731 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2022-04-07 12:32:27,731 - util.py[DEBUG]: Read 31 bytes from /run/cloud-init/cloud.cfg 2022-04-07 12:32:27,731 - util.py[DEBUG]: Attempting to load yaml from string of length 31 with allowed root types (,) 2022-04-07 12:32:27,731 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2022-04-07 12:32:27,731 - util.py[DEBUG]: loaded blob returned None, returning default. 2022-04-07 12:32:27,731 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2022-04-07 12:32:27,731 - util.py[DEBUG]: Read 918 bytes from /var/lib/cloud/instance/cloud-config.txt 2022-04-07 12:32:27,731 - util.py[DEBUG]: Attempting to load yaml from string of length 918 with allowed root types (,) 2022-04-07 12:32:27,733 - stages.py[DEBUG]: Using distro class 2022-04-07 12:32:27,734 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:32:27,734 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:32:27,734 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False) 2022-04-07 12:32:27,734 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address 2022-04-07 12:32:27,734 - util.py[DEBUG]: Reading from /sys/class/net/ens192/name_assign_type (quiet=False) 2022-04-07 12:32:27,734 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/name_assign_type 2022-04-07 12:32:27,734 - util.py[DEBUG]: Reading from /sys/class/net/ens192/carrier (quiet=False) 2022-04-07 12:32:27,734 - util.py[DEBUG]: Reading from /sys/class/net/ens192/dormant (quiet=False) 2022-04-07 12:32:27,734 - util.py[DEBUG]: Reading from /sys/class/net/ens192/operstate (quiet=False) 2022-04-07 12:32:27,734 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/ens192/operstate 2022-04-07 12:32:27,734 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:32:27,734 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:32:27,734 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:32:27,735 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:32:27,735 - stages.py[DEBUG]: Allowed events: {: {}} 2022-04-07 12:32:27,735 - stages.py[DEBUG]: Event Denied: scopes=['network'] EventType=boot 2022-04-07 12:32:27,735 - stages.py[DEBUG]: Allowed events: {: {}} 2022-04-07 12:32:27,735 - stages.py[DEBUG]: Event Denied: scopes=['network'] EventType=boot-legacy 2022-04-07 12:32:27,735 - stages.py[DEBUG]: No network config applied. Neither a new instance nor datasource network update allowed 2022-04-07 12:32:27,735 - stages.py[DEBUG]: applying net config names for {'ethernets': {'ens192': {'dhcp4': True, 'set-name': 'ens192', 'match': {'macaddress': '00:50:56:a5:f6:80'}}}, 'version': 2} 2022-04-07 12:32:27,735 - util.py[DEBUG]: Reading from /sys/class/net/ens192/device/device (quiet=False) 2022-04-07 12:32:27,735 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/ens192/device/device 2022-04-07 12:32:27,735 - util.py[DEBUG]: Reading from /sys/class/net/ens192/addr_assign_type (quiet=False) 2022-04-07 12:32:27,735 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/addr_assign_type 2022-04-07 12:32:27,735 - util.py[DEBUG]: Reading from /sys/class/net/ens192/uevent (quiet=False) 2022-04-07 12:32:27,735 - util.py[DEBUG]: Read 27 bytes from /sys/class/net/ens192/uevent 2022-04-07 12:32:27,736 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:32:27,736 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:32:27,736 - __init__.py[DEBUG]: ovs-vsctl not in PATH; not detecting Open vSwitch interfaces 2022-04-07 12:32:27,736 - util.py[DEBUG]: Reading from /sys/class/net/ens192/device/device (quiet=False) 2022-04-07 12:32:27,736 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/ens192/device/device 2022-04-07 12:32:27,736 - util.py[DEBUG]: Reading from /sys/class/net/lo/addr_assign_type (quiet=False) 2022-04-07 12:32:27,736 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/lo/addr_assign_type 2022-04-07 12:32:27,736 - util.py[DEBUG]: Reading from /sys/class/net/lo/uevent (quiet=False) 2022-04-07 12:32:27,736 - util.py[DEBUG]: Read 23 bytes from /sys/class/net/lo/uevent 2022-04-07 12:32:27,736 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False) 2022-04-07 12:32:27,736 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address 2022-04-07 12:32:27,736 - util.py[DEBUG]: Reading from /sys/class/net/lo/device/device (quiet=False) 2022-04-07 12:32:27,736 - util.py[DEBUG]: Reading from /sys/class/net/ens192/operstate (quiet=False) 2022-04-07 12:32:27,736 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/ens192/operstate 2022-04-07 12:32:27,736 - util.py[DEBUG]: Reading from /sys/class/net/lo/operstate (quiet=False) 2022-04-07 12:32:27,736 - util.py[DEBUG]: Read 8 bytes from /sys/class/net/lo/operstate 2022-04-07 12:32:27,736 - subp.py[DEBUG]: Running command ['ip', '-6', 'addr', 'show', 'permanent', 'scope', 'global'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:32:27,740 - subp.py[DEBUG]: Running command ['ip', '-4', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:32:27,742 - __init__.py[DEBUG]: Detected interfaces {'ens192': {'downable': True, 'device_id': '0x07b0', 'driver': 'vmxnet3', 'mac': '00:50:56:a5:f6:80', 'name': 'ens192', 'up': False}, 'lo': {'downable': False, 'device_id': None, 'driver': None, 'mac': '00:00:00:00:00:00', 'name': 'lo', 'up': True}} 2022-04-07 12:32:27,742 - __init__.py[DEBUG]: no work necessary for renaming of [['00:50:56:a5:f6:80', 'ens192', 'vmxnet3', '0x07b0']] 2022-04-07 12:32:27,742 - main.py[DEBUG]: [local] Exiting. datasource DataSourceOVF [seed=com.vmware.guestInfo] not in local mode. 2022-04-07 12:32:27,743 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmprte2ipnc) - w: [644] 514 bytes/chars 2022-04-07 12:32:27,743 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2022-04-07 12:32:27,743 - util.py[DEBUG]: Read 12 bytes from /proc/uptime 2022-04-07 12:32:27,743 - util.py[DEBUG]: cloud-init mode 'init' took 15.110 seconds (15.11) 2022-04-07 12:32:27,743 - handlers.py[DEBUG]: finish: init-local: SUCCESS: searching for local datasources 2022-04-07 12:32:29,925 - util.py[DEBUG]: Cloud-init v. 21.4-0ubuntu1~20.04.1 running 'init' at Thu, 07 Apr 2022 12:32:29 +0000. Up 21.94 seconds. 2022-04-07 12:32:29,925 - main.py[DEBUG]: No kernel command line url found. 2022-04-07 12:32:29,925 - main.py[DEBUG]: Closing stdin. 2022-04-07 12:32:29,926 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [644] 0 bytes 2022-04-07 12:32:29,926 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 104:4 2022-04-07 12:32:29,926 - subp.py[DEBUG]: Running command ['ip', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:32:29,929 - subp.py[DEBUG]: Running command ['ip', '-o', 'route', 'list'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:32:29,930 - subp.py[DEBUG]: Running command ['ip', '--oneline', '-6', 'route', 'list', 'table', 'all'] with allowed return codes [0, 1] (shell=False, capture=True) 2022-04-07 12:32:29,932 - main.py[DEBUG]: Checking to see if files that we need already exist from a previous run that would allow us to stop early. 2022-04-07 12:32:29,932 - main.py[DEBUG]: Execution continuing, no previous run detected that would allow us to stop early. 2022-04-07 12:32:29,933 - handlers.py[DEBUG]: start: init-network/check-cache: attempting to read from cache [trust] 2022-04-07 12:32:29,933 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False) 2022-04-07 12:32:29,933 - util.py[DEBUG]: Read 10385 bytes from /var/lib/cloud/instance/obj.pkl 2022-04-07 12:32:29,938 - util.py[DEBUG]: Reading from /run/cloud-init/.instance-id (quiet=False) 2022-04-07 12:32:29,938 - util.py[DEBUG]: Read 10 bytes from /run/cloud-init/.instance-id 2022-04-07 12:32:29,938 - stages.py[DEBUG]: restored from cache with run check: DataSourceOVF [seed=com.vmware.guestInfo] 2022-04-07 12:32:29,938 - handlers.py[DEBUG]: finish: init-network/check-cache: SUCCESS: restored from cache with run check: DataSourceOVF [seed=com.vmware.guestInfo] 2022-04-07 12:32:29,938 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2022-04-07 12:32:29,938 - util.py[DEBUG]: Read 3807 bytes from /etc/cloud/cloud.cfg 2022-04-07 12:32:29,938 - util.py[DEBUG]: Attempting to load yaml from string of length 3807 with allowed root types (,) 2022-04-07 12:32:29,946 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg (quiet=False) 2022-04-07 12:32:29,946 - util.py[DEBUG]: Read 39 bytes from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg 2022-04-07 12:32:29,946 - util.py[DEBUG]: Attempting to load yaml from string of length 39 with allowed root types (,) 2022-04-07 12:32:29,946 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2022-04-07 12:32:29,946 - util.py[DEBUG]: Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2022-04-07 12:32:29,946 - util.py[DEBUG]: Attempting to load yaml from string of length 314 with allowed root types (,) 2022-04-07 12:32:29,947 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2022-04-07 12:32:29,947 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2022-04-07 12:32:29,947 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2022-04-07 12:32:29,949 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2022-04-07 12:32:29,949 - util.py[DEBUG]: Read 31 bytes from /run/cloud-init/cloud.cfg 2022-04-07 12:32:29,949 - util.py[DEBUG]: Attempting to load yaml from string of length 31 with allowed root types (,) 2022-04-07 12:32:29,950 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2022-04-07 12:32:29,950 - util.py[DEBUG]: loaded blob returned None, returning default. 2022-04-07 12:32:29,950 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2022-04-07 12:32:29,950 - util.py[DEBUG]: Read 918 bytes from /var/lib/cloud/instance/cloud-config.txt 2022-04-07 12:32:29,950 - util.py[DEBUG]: Attempting to load yaml from string of length 918 with allowed root types (,) 2022-04-07 12:32:29,951 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2022-04-07 12:32:29,951 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/iid-dsovf' 2022-04-07 12:32:29,952 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/iid-dsovf/datasource (quiet=False) 2022-04-07 12:32:29,952 - util.py[DEBUG]: Read 57 bytes from /var/lib/cloud/instances/iid-dsovf/datasource 2022-04-07 12:32:29,952 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/datasource - wb: [644] 57 bytes 2022-04-07 12:32:29,952 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [644] 57 bytes 2022-04-07 12:32:29,952 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False) 2022-04-07 12:32:29,952 - util.py[DEBUG]: Read 10 bytes from /var/lib/cloud/data/instance-id 2022-04-07 12:32:29,952 - stages.py[DEBUG]: previous iid found to be iid-dsovf 2022-04-07 12:32:29,952 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [644] 10 bytes 2022-04-07 12:32:29,952 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [644] 10 bytes 2022-04-07 12:32:29,953 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [644] 10 bytes 2022-04-07 12:32:29,953 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [400] 10397 bytes 2022-04-07 12:32:29,954 - main.py[DEBUG]: [net] init will now be targeting instance id: iid-dsovf. new=False 2022-04-07 12:32:29,954 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2022-04-07 12:32:29,954 - util.py[DEBUG]: Read 3807 bytes from /etc/cloud/cloud.cfg 2022-04-07 12:32:29,954 - util.py[DEBUG]: Attempting to load yaml from string of length 3807 with allowed root types (,) 2022-04-07 12:32:29,961 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg (quiet=False) 2022-04-07 12:32:29,961 - util.py[DEBUG]: Read 39 bytes from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg 2022-04-07 12:32:29,961 - util.py[DEBUG]: Attempting to load yaml from string of length 39 with allowed root types (,) 2022-04-07 12:32:29,962 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2022-04-07 12:32:29,962 - util.py[DEBUG]: Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2022-04-07 12:32:29,962 - util.py[DEBUG]: Attempting to load yaml from string of length 314 with allowed root types (,) 2022-04-07 12:32:29,963 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2022-04-07 12:32:29,963 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2022-04-07 12:32:29,963 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2022-04-07 12:32:29,965 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2022-04-07 12:32:29,965 - util.py[DEBUG]: Read 31 bytes from /run/cloud-init/cloud.cfg 2022-04-07 12:32:29,965 - util.py[DEBUG]: Attempting to load yaml from string of length 31 with allowed root types (,) 2022-04-07 12:32:29,965 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2022-04-07 12:32:29,965 - util.py[DEBUG]: loaded blob returned None, returning default. 2022-04-07 12:32:29,965 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2022-04-07 12:32:29,965 - util.py[DEBUG]: Read 918 bytes from /var/lib/cloud/instance/cloud-config.txt 2022-04-07 12:32:29,965 - util.py[DEBUG]: Attempting to load yaml from string of length 918 with allowed root types (,) 2022-04-07 12:32:29,967 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:32:29,967 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:32:29,967 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False) 2022-04-07 12:32:29,967 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address 2022-04-07 12:32:29,967 - stages.py[DEBUG]: Using distro class 2022-04-07 12:32:29,968 - util.py[DEBUG]: Reading from /sys/class/net/ens192/name_assign_type (quiet=False) 2022-04-07 12:32:29,968 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/name_assign_type 2022-04-07 12:32:29,968 - util.py[DEBUG]: Reading from /sys/class/net/ens192/carrier (quiet=False) 2022-04-07 12:32:29,968 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/carrier 2022-04-07 12:32:29,968 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:32:29,968 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:32:29,968 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:32:29,968 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:32:29,968 - stages.py[DEBUG]: Allowed events: {: {}} 2022-04-07 12:32:29,968 - stages.py[DEBUG]: Event Denied: scopes=['network'] EventType=boot 2022-04-07 12:32:29,969 - stages.py[DEBUG]: Allowed events: {: {}} 2022-04-07 12:32:29,969 - stages.py[DEBUG]: Event Denied: scopes=['network'] EventType=boot-legacy 2022-04-07 12:32:29,969 - stages.py[DEBUG]: No network config applied. Neither a new instance nor datasource network update allowed 2022-04-07 12:32:29,969 - stages.py[DEBUG]: applying net config names for {'ethernets': {'ens192': {'dhcp4': True, 'set-name': 'ens192', 'match': {'macaddress': '00:50:56:a5:f6:80'}}}, 'version': 2} 2022-04-07 12:32:29,969 - util.py[DEBUG]: Reading from /sys/class/net/ens192/device/device (quiet=False) 2022-04-07 12:32:29,969 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/ens192/device/device 2022-04-07 12:32:29,969 - util.py[DEBUG]: Reading from /sys/class/net/ens192/addr_assign_type (quiet=False) 2022-04-07 12:32:29,969 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/addr_assign_type 2022-04-07 12:32:29,969 - util.py[DEBUG]: Reading from /sys/class/net/ens192/uevent (quiet=False) 2022-04-07 12:32:29,969 - util.py[DEBUG]: Read 27 bytes from /sys/class/net/ens192/uevent 2022-04-07 12:32:29,969 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-07 12:32:29,969 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-07 12:32:29,969 - __init__.py[DEBUG]: ovs-vsctl not in PATH; not detecting Open vSwitch interfaces 2022-04-07 12:32:29,969 - util.py[DEBUG]: Reading from /sys/class/net/ens192/device/device (quiet=False) 2022-04-07 12:32:29,969 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/ens192/device/device 2022-04-07 12:32:29,969 - util.py[DEBUG]: Reading from /sys/class/net/lo/addr_assign_type (quiet=False) 2022-04-07 12:32:29,969 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/lo/addr_assign_type 2022-04-07 12:32:29,969 - util.py[DEBUG]: Reading from /sys/class/net/lo/uevent (quiet=False) 2022-04-07 12:32:29,969 - util.py[DEBUG]: Read 23 bytes from /sys/class/net/lo/uevent 2022-04-07 12:32:29,969 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False) 2022-04-07 12:32:29,969 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address 2022-04-07 12:32:29,969 - util.py[DEBUG]: Reading from /sys/class/net/lo/device/device (quiet=False) 2022-04-07 12:32:29,969 - util.py[DEBUG]: Reading from /sys/class/net/ens192/operstate (quiet=False) 2022-04-07 12:32:29,969 - util.py[DEBUG]: Read 3 bytes from /sys/class/net/ens192/operstate 2022-04-07 12:32:29,969 - util.py[DEBUG]: Reading from /sys/class/net/lo/operstate (quiet=False) 2022-04-07 12:32:29,969 - util.py[DEBUG]: Read 8 bytes from /sys/class/net/lo/operstate 2022-04-07 12:32:29,970 - subp.py[DEBUG]: Running command ['ip', '-6', 'addr', 'show', 'permanent', 'scope', 'global'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:32:29,971 - subp.py[DEBUG]: Running command ['ip', '-4', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:32:29,972 - __init__.py[DEBUG]: Detected interfaces {'ens192': {'downable': False, 'device_id': '0x07b0', 'driver': 'vmxnet3', 'mac': '00:50:56:a5:f6:80', 'name': 'ens192', 'up': True}, 'lo': {'downable': False, 'device_id': None, 'driver': None, 'mac': '00:00:00:00:00:00', 'name': 'lo', 'up': True}} 2022-04-07 12:32:29,973 - __init__.py[DEBUG]: no work necessary for renaming of [['00:50:56:a5:f6:80', 'ens192', 'vmxnet3', '0x07b0']] 2022-04-07 12:32:29,973 - handlers.py[DEBUG]: start: init-network/setup-datasource: setting up datasource 2022-04-07 12:32:29,973 - handlers.py[DEBUG]: finish: init-network/setup-datasource: SUCCESS: setting up datasource 2022-04-07 12:32:29,973 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/user-data.txt - wb: [600] 1454 bytes 2022-04-07 12:32:29,973 - util.py[DEBUG]: Attempting to load yaml from string of length 1454 with allowed root types (,) 2022-04-07 12:32:29,976 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/user-data.txt.i - wb: [600] 1759 bytes 2022-04-07 12:32:29,976 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/vendor-data.txt - wb: [600] 0 bytes 2022-04-07 12:32:29,977 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/vendor-data.txt.i - wb: [600] 308 bytes 2022-04-07 12:32:29,977 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/vendor-data2.txt - wb: [600] 0 bytes 2022-04-07 12:32:29,978 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/vendor-data2.txt.i - wb: [600] 308 bytes 2022-04-07 12:32:29,979 - helpers.py[DEBUG]: consume_data already ran (freq=once-per-instance) 2022-04-07 12:32:29,979 - handlers.py[DEBUG]: start: init-network/consume-user-data: reading and applying user-data 2022-04-07 12:32:29,979 - stages.py[DEBUG]: Added default handler for {'text/cloud-config-jsonp', 'text/cloud-config'} from CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] 2022-04-07 12:32:29,979 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript'} from ShellScriptPartHandler: [['text/x-shellscript']] 2022-04-07 12:32:29,979 - stages.py[DEBUG]: Added default handler for {'text/cloud-boothook'} from BootHookPartHandler: [['text/cloud-boothook']] 2022-04-07 12:32:29,979 - stages.py[DEBUG]: Added default handler for {'text/upstart-job'} from UpstartJobPartHandler: [['text/upstart-job']] 2022-04-07 12:32:29,979 - stages.py[DEBUG]: Added default handler for {'text/jinja2'} from JinjaTemplatePartHandler: [['text/jinja2']] 2022-04-07 12:32:29,979 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__begin__, None, 3) with frequency always 2022-04-07 12:32:29,979 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__begin__, None, 2) with frequency always 2022-04-07 12:32:29,979 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__begin__, None, 2) with frequency always 2022-04-07 12:32:29,979 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__begin__, None, 3) with frequency always 2022-04-07 12:32:29,980 - __init__.py[DEBUG]: {'MIME-Version': '1.0', 'Content-Type': 'text/cloud-config', 'Content-Disposition': 'attachment; filename="part-001"'} 2022-04-07 12:32:29,980 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (text/cloud-config, part-001, 3) with frequency always 2022-04-07 12:32:29,980 - util.py[DEBUG]: Attempting to load yaml from string of length 1454 with allowed root types (,) 2022-04-07 12:32:29,981 - cloud_config.py[DEBUG]: Merging by applying [('dict', ['replace']), ('list', []), ('str', [])] 2022-04-07 12:32:29,981 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__end__, None, 3) with frequency always 2022-04-07 12:32:29,983 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/cloud-config.txt - wb: [600] 918 bytes 2022-04-07 12:32:29,983 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__end__, None, 2) with frequency always 2022-04-07 12:32:29,983 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__end__, None, 2) with frequency always 2022-04-07 12:32:29,983 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__end__, None, 3) with frequency always 2022-04-07 12:32:29,983 - handlers.py[DEBUG]: finish: init-network/consume-user-data: SUCCESS: reading and applying user-data 2022-04-07 12:32:29,983 - handlers.py[DEBUG]: start: init-network/consume-vendor-data: reading and applying vendor-data 2022-04-07 12:32:29,983 - stages.py[DEBUG]: no vendordata from datasource 2022-04-07 12:32:29,983 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data: SUCCESS: reading and applying vendor-data 2022-04-07 12:32:29,983 - handlers.py[DEBUG]: start: init-network/consume-vendor-data2: reading and applying vendor-data2 2022-04-07 12:32:29,983 - stages.py[DEBUG]: no vendordata2 from datasource 2022-04-07 12:32:29,983 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data2: SUCCESS: reading and applying vendor-data2 2022-04-07 12:32:29,983 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2022-04-07 12:32:29,983 - util.py[DEBUG]: Read 3807 bytes from /etc/cloud/cloud.cfg 2022-04-07 12:32:29,983 - util.py[DEBUG]: Attempting to load yaml from string of length 3807 with allowed root types (,) 2022-04-07 12:32:29,991 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg (quiet=False) 2022-04-07 12:32:29,991 - util.py[DEBUG]: Read 39 bytes from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg 2022-04-07 12:32:29,991 - util.py[DEBUG]: Attempting to load yaml from string of length 39 with allowed root types (,) 2022-04-07 12:32:29,991 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2022-04-07 12:32:29,991 - util.py[DEBUG]: Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2022-04-07 12:32:29,991 - util.py[DEBUG]: Attempting to load yaml from string of length 314 with allowed root types (,) 2022-04-07 12:32:29,992 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2022-04-07 12:32:29,992 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2022-04-07 12:32:29,992 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2022-04-07 12:32:29,994 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2022-04-07 12:32:29,994 - util.py[DEBUG]: Read 31 bytes from /run/cloud-init/cloud.cfg 2022-04-07 12:32:29,994 - util.py[DEBUG]: Attempting to load yaml from string of length 31 with allowed root types (,) 2022-04-07 12:32:29,994 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2022-04-07 12:32:29,994 - util.py[DEBUG]: loaded blob returned None, returning default. 2022-04-07 12:32:29,995 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2022-04-07 12:32:29,995 - util.py[DEBUG]: Read 918 bytes from /var/lib/cloud/instance/cloud-config.txt 2022-04-07 12:32:29,995 - util.py[DEBUG]: Attempting to load yaml from string of length 918 with allowed root types (,) 2022-04-07 12:32:29,996 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2022-04-07 12:32:29,996 - util.py[DEBUG]: Read 918 bytes from /var/lib/cloud/instance/cloud-config.txt 2022-04-07 12:32:29,996 - util.py[DEBUG]: Attempting to load yaml from string of length 918 with allowed root types (,) 2022-04-07 12:32:29,999 - handlers.py[DEBUG]: start: init-network/activate-datasource: activating datasource 2022-04-07 12:32:30,000 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [400] 13946 bytes 2022-04-07 12:32:30,000 - handlers.py[DEBUG]: finish: init-network/activate-datasource: SUCCESS: activating datasource 2022-04-07 12:32:30,000 - main.py[DEBUG]: no di_report found in config. 2022-04-07 12:32:30,008 - stages.py[DEBUG]: Using distro class 2022-04-07 12:32:30,009 - stages.py[DEBUG]: Running module migrator () with frequency always 2022-04-07 12:32:30,009 - handlers.py[DEBUG]: start: init-network/config-migrator: running config-migrator with frequency always 2022-04-07 12:32:30,009 - helpers.py[DEBUG]: Running config-migrator using lock () 2022-04-07 12:32:30,009 - cc_migrator.py[DEBUG]: Migrated 0 semaphore files to there canonicalized names 2022-04-07 12:32:30,009 - handlers.py[DEBUG]: finish: init-network/config-migrator: SUCCESS: config-migrator ran successfully 2022-04-07 12:32:30,009 - stages.py[DEBUG]: Running module seed_random () with frequency once-per-instance 2022-04-07 12:32:30,009 - handlers.py[DEBUG]: start: init-network/config-seed_random: running config-seed_random with frequency once-per-instance 2022-04-07 12:32:30,009 - helpers.py[DEBUG]: config-seed_random already ran (freq=once-per-instance) 2022-04-07 12:32:30,009 - handlers.py[DEBUG]: finish: init-network/config-seed_random: SUCCESS: config-seed_random previously ran 2022-04-07 12:32:30,009 - stages.py[DEBUG]: Running module bootcmd () with frequency always 2022-04-07 12:32:30,009 - handlers.py[DEBUG]: start: init-network/config-bootcmd: running config-bootcmd with frequency always 2022-04-07 12:32:30,009 - helpers.py[DEBUG]: Running config-bootcmd using lock () 2022-04-07 12:32:30,010 - cc_bootcmd.py[DEBUG]: Skipping module named bootcmd, no 'bootcmd' key in configuration 2022-04-07 12:32:30,010 - handlers.py[DEBUG]: finish: init-network/config-bootcmd: SUCCESS: config-bootcmd ran successfully 2022-04-07 12:32:30,010 - stages.py[DEBUG]: Running module write-files () with frequency once-per-instance 2022-04-07 12:32:30,010 - handlers.py[DEBUG]: start: init-network/config-write-files: running config-write-files with frequency once-per-instance 2022-04-07 12:32:30,010 - helpers.py[DEBUG]: config-write-files already ran (freq=once-per-instance) 2022-04-07 12:32:30,010 - handlers.py[DEBUG]: finish: init-network/config-write-files: SUCCESS: config-write-files previously ran 2022-04-07 12:32:30,010 - stages.py[DEBUG]: Running module growpart () with frequency always 2022-04-07 12:32:30,010 - handlers.py[DEBUG]: start: init-network/config-growpart: running config-growpart with frequency always 2022-04-07 12:32:30,010 - helpers.py[DEBUG]: Running config-growpart using lock () 2022-04-07 12:32:30,010 - cc_growpart.py[DEBUG]: No 'growpart' entry in cfg. Using default: {'mode': 'auto', 'devices': ['/'], 'ignore_growroot_disabled': False} 2022-04-07 12:32:30,010 - subp.py[DEBUG]: Running command ['growpart', '--help'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:32:30,012 - util.py[DEBUG]: Reading from /proc/681/mountinfo (quiet=False) 2022-04-07 12:32:30,013 - util.py[DEBUG]: Read 3550 bytes from /proc/681/mountinfo 2022-04-07 12:32:30,013 - util.py[DEBUG]: Reading from /sys/class/block/sda1/partition (quiet=False) 2022-04-07 12:32:30,013 - util.py[DEBUG]: Read 2 bytes from /sys/class/block/sda1/partition 2022-04-07 12:32:30,013 - util.py[DEBUG]: Reading from /sys/devices/pci0000:00/0000:00:15.0/0000:03:00.0/host2/target2:0:0/2:0:0:0/block/sda/dev (quiet=False) 2022-04-07 12:32:30,013 - util.py[DEBUG]: Read 4 bytes from /sys/devices/pci0000:00/0000:00:15.0/0000:03:00.0/host2/target2:0:0/2:0:0:0/block/sda/dev 2022-04-07 12:32:30,013 - subp.py[DEBUG]: Running command ['growpart', '--dry-run', '/dev/sda', '1'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:32:30,032 - util.py[DEBUG]: resize_devices took 0.019 seconds 2022-04-07 12:32:30,032 - cc_growpart.py[DEBUG]: '/' NOCHANGE: no change necessary (/dev/sda, 1) 2022-04-07 12:32:30,032 - handlers.py[DEBUG]: finish: init-network/config-growpart: SUCCESS: config-growpart ran successfully 2022-04-07 12:32:30,032 - stages.py[DEBUG]: Running module resizefs () with frequency always 2022-04-07 12:32:30,032 - handlers.py[DEBUG]: start: init-network/config-resizefs: running config-resizefs with frequency always 2022-04-07 12:32:30,032 - helpers.py[DEBUG]: Running config-resizefs using lock () 2022-04-07 12:32:30,066 - util.py[DEBUG]: Reading from /proc/681/mountinfo (quiet=False) 2022-04-07 12:32:30,066 - util.py[DEBUG]: Read 3550 bytes from /proc/681/mountinfo 2022-04-07 12:32:30,066 - cc_resizefs.py[DEBUG]: resize_info: dev=/dev/sda1 mnt_point=/ path=/ 2022-04-07 12:32:30,066 - cc_resizefs.py[DEBUG]: Resizing / (ext4) using resize2fs /dev/sda1 2022-04-07 12:32:30,066 - subp.py[DEBUG]: Running command ('resize2fs', '/dev/sda1') with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:32:30,068 - util.py[DEBUG]: Resizing took 0.002 seconds 2022-04-07 12:32:30,068 - cc_resizefs.py[DEBUG]: Resized root filesystem (type=ext4, val=True) 2022-04-07 12:32:30,069 - handlers.py[DEBUG]: finish: init-network/config-resizefs: SUCCESS: config-resizefs ran successfully 2022-04-07 12:32:30,069 - stages.py[DEBUG]: Running module disk_setup () with frequency once-per-instance 2022-04-07 12:32:30,069 - handlers.py[DEBUG]: start: init-network/config-disk_setup: running config-disk_setup with frequency once-per-instance 2022-04-07 12:32:30,069 - helpers.py[DEBUG]: config-disk_setup already ran (freq=once-per-instance) 2022-04-07 12:32:30,069 - handlers.py[DEBUG]: finish: init-network/config-disk_setup: SUCCESS: config-disk_setup previously ran 2022-04-07 12:32:30,069 - stages.py[DEBUG]: Running module mounts () with frequency once-per-instance 2022-04-07 12:32:30,069 - handlers.py[DEBUG]: start: init-network/config-mounts: running config-mounts with frequency once-per-instance 2022-04-07 12:32:30,069 - helpers.py[DEBUG]: config-mounts already ran (freq=once-per-instance) 2022-04-07 12:32:30,069 - handlers.py[DEBUG]: finish: init-network/config-mounts: SUCCESS: config-mounts previously ran 2022-04-07 12:32:30,069 - stages.py[DEBUG]: Running module set_hostname () with frequency once-per-instance 2022-04-07 12:32:30,069 - handlers.py[DEBUG]: start: init-network/config-set_hostname: running config-set_hostname with frequency once-per-instance 2022-04-07 12:32:30,069 - helpers.py[DEBUG]: config-set_hostname already ran (freq=once-per-instance) 2022-04-07 12:32:30,069 - handlers.py[DEBUG]: finish: init-network/config-set_hostname: SUCCESS: config-set_hostname previously ran 2022-04-07 12:32:30,069 - stages.py[DEBUG]: Running module update_hostname () with frequency always 2022-04-07 12:32:30,069 - handlers.py[DEBUG]: start: init-network/config-update_hostname: running config-update_hostname with frequency always 2022-04-07 12:32:30,069 - helpers.py[DEBUG]: Running config-update_hostname using lock () 2022-04-07 12:32:30,069 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False) 2022-04-07 12:32:30,070 - util.py[DEBUG]: Read 244 bytes from /etc/hosts 2022-04-07 12:32:30,070 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False) 2022-04-07 12:32:30,070 - util.py[DEBUG]: Read 244 bytes from /etc/hosts 2022-04-07 12:32:30,070 - cc_update_hostname.py[DEBUG]: Updating hostname to ubuntu (ubuntu) 2022-04-07 12:32:30,070 - util.py[DEBUG]: Reading from /var/lib/cloud/data/previous-hostname (quiet=False) 2022-04-07 12:32:30,070 - util.py[DEBUG]: Read 7 bytes from /var/lib/cloud/data/previous-hostname 2022-04-07 12:32:30,070 - util.py[DEBUG]: Reading from /etc/hostname (quiet=False) 2022-04-07 12:32:30,070 - util.py[DEBUG]: Read 7 bytes from /etc/hostname 2022-04-07 12:32:30,070 - __init__.py[DEBUG]: Attempting to update hostname to ubuntu in 0 files 2022-04-07 12:32:30,070 - handlers.py[DEBUG]: finish: init-network/config-update_hostname: SUCCESS: config-update_hostname ran successfully 2022-04-07 12:32:30,070 - stages.py[DEBUG]: Running module update_etc_hosts () with frequency always 2022-04-07 12:32:30,070 - handlers.py[DEBUG]: start: init-network/config-update_etc_hosts: running config-update_etc_hosts with frequency always 2022-04-07 12:32:30,070 - helpers.py[DEBUG]: Running config-update_etc_hosts using lock () 2022-04-07 12:32:30,070 - cc_update_etc_hosts.py[DEBUG]: Configuration option 'manage_etc_hosts' is not set, not managing /etc/hosts in module update_etc_hosts 2022-04-07 12:32:30,070 - handlers.py[DEBUG]: finish: init-network/config-update_etc_hosts: SUCCESS: config-update_etc_hosts ran successfully 2022-04-07 12:32:30,070 - stages.py[DEBUG]: Running module ca-certs () with frequency once-per-instance 2022-04-07 12:32:30,070 - handlers.py[DEBUG]: start: init-network/config-ca-certs: running config-ca-certs with frequency once-per-instance 2022-04-07 12:32:30,070 - helpers.py[DEBUG]: config-ca-certs already ran (freq=once-per-instance) 2022-04-07 12:32:30,070 - handlers.py[DEBUG]: finish: init-network/config-ca-certs: SUCCESS: config-ca-certs previously ran 2022-04-07 12:32:30,070 - stages.py[DEBUG]: Running module rsyslog () with frequency once-per-instance 2022-04-07 12:32:30,071 - handlers.py[DEBUG]: start: init-network/config-rsyslog: running config-rsyslog with frequency once-per-instance 2022-04-07 12:32:30,071 - helpers.py[DEBUG]: config-rsyslog already ran (freq=once-per-instance) 2022-04-07 12:32:30,071 - handlers.py[DEBUG]: finish: init-network/config-rsyslog: SUCCESS: config-rsyslog previously ran 2022-04-07 12:32:30,071 - stages.py[DEBUG]: Running module users-groups () with frequency once-per-instance 2022-04-07 12:32:30,071 - handlers.py[DEBUG]: start: init-network/config-users-groups: running config-users-groups with frequency once-per-instance 2022-04-07 12:32:30,071 - helpers.py[DEBUG]: config-users-groups already ran (freq=once-per-instance) 2022-04-07 12:32:30,071 - handlers.py[DEBUG]: finish: init-network/config-users-groups: SUCCESS: config-users-groups previously ran 2022-04-07 12:32:30,071 - stages.py[DEBUG]: Running module ssh () with frequency once-per-instance 2022-04-07 12:32:30,071 - handlers.py[DEBUG]: start: init-network/config-ssh: running config-ssh with frequency once-per-instance 2022-04-07 12:32:30,071 - helpers.py[DEBUG]: config-ssh already ran (freq=once-per-instance) 2022-04-07 12:32:30,071 - handlers.py[DEBUG]: finish: init-network/config-ssh: SUCCESS: config-ssh previously ran 2022-04-07 12:32:30,071 - main.py[DEBUG]: Ran 15 modules with 0 failures 2022-04-07 12:32:30,071 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmpt1w773ky) - w: [644] 542 bytes/chars 2022-04-07 12:32:30,071 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2022-04-07 12:32:30,072 - util.py[DEBUG]: Read 12 bytes from /proc/uptime 2022-04-07 12:32:30,072 - util.py[DEBUG]: cloud-init mode 'init' took 0.176 seconds (0.18) 2022-04-07 12:32:30,072 - handlers.py[DEBUG]: finish: init-network: SUCCESS: searching for network datasources 2022-04-07 12:35:50,112 - util.py[DEBUG]: Cloud-init v. 21.4-0ubuntu1~20.04.1 running 'modules:config' at Thu, 07 Apr 2022 12:35:50 +0000. Up 222.10 seconds. 2022-04-07 12:35:50,126 - stages.py[DEBUG]: Using distro class 2022-04-07 12:35:50,127 - stages.py[DEBUG]: Running module emit_upstart () with frequency always 2022-04-07 12:35:50,127 - handlers.py[DEBUG]: start: modules-config/config-emit_upstart: running config-emit_upstart with frequency always 2022-04-07 12:35:50,127 - helpers.py[DEBUG]: Running config-emit_upstart using lock () 2022-04-07 12:35:50,127 - cc_emit_upstart.py[DEBUG]: no /sbin/initctl located 2022-04-07 12:35:50,127 - cc_emit_upstart.py[DEBUG]: not upstart system, 'emit_upstart' disabled 2022-04-07 12:35:50,127 - handlers.py[DEBUG]: finish: modules-config/config-emit_upstart: SUCCESS: config-emit_upstart ran successfully 2022-04-07 12:35:50,127 - stages.py[DEBUG]: Running module snap () with frequency once-per-instance 2022-04-07 12:35:50,127 - handlers.py[DEBUG]: start: modules-config/config-snap: running config-snap with frequency once-per-instance 2022-04-07 12:35:50,127 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_snap - wb: [644] 25 bytes 2022-04-07 12:35:50,128 - helpers.py[DEBUG]: Running config-snap using lock () 2022-04-07 12:35:50,128 - cc_snap.py[DEBUG]: Skipping module named snap, no 'snap' key in configuration 2022-04-07 12:35:50,128 - handlers.py[DEBUG]: finish: modules-config/config-snap: SUCCESS: config-snap ran successfully 2022-04-07 12:35:50,128 - stages.py[DEBUG]: Running module ssh-import-id () with frequency once-per-instance 2022-04-07 12:35:50,128 - handlers.py[DEBUG]: start: modules-config/config-ssh-import-id: running config-ssh-import-id with frequency once-per-instance 2022-04-07 12:35:50,128 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_ssh_import_id - wb: [644] 25 bytes 2022-04-07 12:35:50,128 - helpers.py[DEBUG]: Running config-ssh-import-id using lock () 2022-04-07 12:35:50,128 - handlers.py[DEBUG]: finish: modules-config/config-ssh-import-id: SUCCESS: config-ssh-import-id ran successfully 2022-04-07 12:35:50,128 - stages.py[DEBUG]: Running module locale () with frequency once-per-instance 2022-04-07 12:35:50,128 - handlers.py[DEBUG]: start: modules-config/config-locale: running config-locale with frequency once-per-instance 2022-04-07 12:35:50,128 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_locale - wb: [644] 24 bytes 2022-04-07 12:35:50,129 - helpers.py[DEBUG]: Running config-locale using lock () 2022-04-07 12:35:50,129 - util.py[DEBUG]: Reading from /etc/default/locale (quiet=False) 2022-04-07 12:35:50,129 - util.py[DEBUG]: Read 13 bytes from /etc/default/locale 2022-04-07 12:35:50,144 - cc_locale.py[DEBUG]: Setting locale to C.UTF-8 2022-04-07 12:35:50,144 - debian.py[DEBUG]: System has 'LANG=C.UTF-8' requested 'C.UTF-8', skipping regeneration. 2022-04-07 12:35:50,144 - handlers.py[DEBUG]: finish: modules-config/config-locale: SUCCESS: config-locale ran successfully 2022-04-07 12:35:50,144 - stages.py[DEBUG]: Running module set-passwords () with frequency once-per-instance 2022-04-07 12:35:50,144 - handlers.py[DEBUG]: start: modules-config/config-set-passwords: running config-set-passwords with frequency once-per-instance 2022-04-07 12:35:50,144 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_set_passwords - wb: [644] 24 bytes 2022-04-07 12:35:50,145 - helpers.py[DEBUG]: Running config-set-passwords using lock () 2022-04-07 12:35:50,145 - cc_set_passwords.py[DEBUG]: Leaving SSH config 'PasswordAuthentication' unchanged. ssh_pwauth=None 2022-04-07 12:35:50,145 - handlers.py[DEBUG]: finish: modules-config/config-set-passwords: SUCCESS: config-set-passwords ran successfully 2022-04-07 12:35:50,145 - stages.py[DEBUG]: Running module grub-dpkg () with frequency once-per-instance 2022-04-07 12:35:50,145 - handlers.py[DEBUG]: start: modules-config/config-grub-dpkg: running config-grub-dpkg with frequency once-per-instance 2022-04-07 12:35:50,145 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_grub_dpkg - wb: [644] 24 bytes 2022-04-07 12:35:50,145 - helpers.py[DEBUG]: Running config-grub-dpkg using lock () 2022-04-07 12:35:50,145 - subp.py[DEBUG]: Running command ['grub-probe', '-t', 'disk', '/boot'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:35:50,153 - subp.py[DEBUG]: Running command ['udevadm', 'info', '--root', '--query=symlink', '/dev/sda'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:35:50,155 - cc_grub_dpkg.py[DEBUG]: considering these device symlinks: /dev/disk/by-path/pci-0000:03:00.0-scsi-0:0:0:0 2022-04-07 12:35:50,155 - cc_grub_dpkg.py[DEBUG]: filtered to these disk/by-id symlinks: 2022-04-07 12:35:50,155 - cc_grub_dpkg.py[DEBUG]: selected /dev/sda 2022-04-07 12:35:50,155 - cc_grub_dpkg.py[DEBUG]: Setting grub debconf-set-selections with '/dev/sda','false' 2022-04-07 12:35:50,155 - subp.py[DEBUG]: Running command ['debconf-set-selections'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:35:50,296 - handlers.py[DEBUG]: finish: modules-config/config-grub-dpkg: SUCCESS: config-grub-dpkg ran successfully 2022-04-07 12:35:50,297 - stages.py[DEBUG]: Running module apt-pipelining () with frequency once-per-instance 2022-04-07 12:35:50,297 - handlers.py[DEBUG]: start: modules-config/config-apt-pipelining: running config-apt-pipelining with frequency once-per-instance 2022-04-07 12:35:50,297 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_apt_pipelining - wb: [644] 24 bytes 2022-04-07 12:35:50,297 - helpers.py[DEBUG]: Running config-apt-pipelining using lock () 2022-04-07 12:35:50,297 - handlers.py[DEBUG]: finish: modules-config/config-apt-pipelining: SUCCESS: config-apt-pipelining ran successfully 2022-04-07 12:35:50,297 - stages.py[DEBUG]: Running module apt-configure () with frequency once-per-instance 2022-04-07 12:35:50,298 - handlers.py[DEBUG]: start: modules-config/config-apt-configure: running config-apt-configure with frequency once-per-instance 2022-04-07 12:35:50,298 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_apt_configure - wb: [644] 25 bytes 2022-04-07 12:35:50,298 - helpers.py[DEBUG]: Running config-apt-configure using lock () 2022-04-07 12:35:50,298 - cc_apt_configure.py[DEBUG]: debconf_selections was not set in config 2022-04-07 12:35:50,298 - util.py[DEBUG]: Reading from /etc/os-release (quiet=True) 2022-04-07 12:35:50,298 - util.py[DEBUG]: Read 382 bytes from /etc/os-release 2022-04-07 12:35:50,299 - util.py[DEBUG]: Reading from /etc/system-image/channel.ini (quiet=True) 2022-04-07 12:35:50,299 - util.py[DEBUG]: Read 0 bytes from /etc/system-image/channel.ini 2022-04-07 12:35:50,299 - cc_apt_configure.py[DEBUG]: handling apt config: {} 2022-04-07 12:35:50,299 - subp.py[DEBUG]: Running command ['lsb_release', '--all'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:35:50,330 - subp.py[DEBUG]: Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:35:50,332 - cc_apt_configure.py[DEBUG]: got primary mirror: None 2022-04-07 12:35:50,333 - cc_apt_configure.py[DEBUG]: got security mirror: None 2022-04-07 12:35:50,333 - subp.py[DEBUG]: Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:35:50,335 - util.py[DEBUG]: search for mirror in candidates: '[]' 2022-04-07 12:35:50,335 - util.py[DEBUG]: search for mirror in candidates: '[]' 2022-04-07 12:35:50,335 - __init__.py[DEBUG]: filtered distro mirror info: {'primary': 'http://archive.ubuntu.com/ubuntu', 'security': 'http://security.ubuntu.com/ubuntu'} 2022-04-07 12:35:50,335 - 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'} 2022-04-07 12:35:50,335 - cc_apt_configure.py[INFO]: No custom template provided, fall back to builtin 2022-04-07 12:35:50,336 - util.py[DEBUG]: Reading from /etc/cloud/templates/sources.list.ubuntu.tmpl (quiet=False) 2022-04-07 12:35:50,336 - util.py[DEBUG]: Read 2858 bytes from /etc/cloud/templates/sources.list.ubuntu.tmpl 2022-04-07 12:35:50,354 - util.py[DEBUG]: Writing to /etc/apt/sources.list - wb: [644] 3120 bytes 2022-04-07 12:35:50,354 - handlers.py[DEBUG]: finish: modules-config/config-apt-configure: SUCCESS: config-apt-configure ran successfully 2022-04-07 12:35:50,354 - stages.py[DEBUG]: Running module ubuntu-advantage () with frequency once-per-instance 2022-04-07 12:35:50,354 - handlers.py[DEBUG]: start: modules-config/config-ubuntu-advantage: running config-ubuntu-advantage with frequency once-per-instance 2022-04-07 12:35:50,355 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_ubuntu_advantage - wb: [644] 25 bytes 2022-04-07 12:35:50,355 - helpers.py[DEBUG]: Running config-ubuntu-advantage using lock () 2022-04-07 12:35:50,355 - cc_ubuntu_advantage.py[DEBUG]: Skipping module named ubuntu-advantage, no 'ubuntu_advantage' configuration found 2022-04-07 12:35:50,355 - handlers.py[DEBUG]: finish: modules-config/config-ubuntu-advantage: SUCCESS: config-ubuntu-advantage ran successfully 2022-04-07 12:35:50,355 - stages.py[DEBUG]: Running module ntp () with frequency once-per-instance 2022-04-07 12:35:50,355 - handlers.py[DEBUG]: start: modules-config/config-ntp: running config-ntp with frequency once-per-instance 2022-04-07 12:35:50,355 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_ntp - wb: [644] 25 bytes 2022-04-07 12:35:50,355 - helpers.py[DEBUG]: Running config-ntp using lock () 2022-04-07 12:35:50,355 - cc_ntp.py[DEBUG]: Skipping module named ntp, not present or disabled by cfg 2022-04-07 12:35:50,355 - handlers.py[DEBUG]: finish: modules-config/config-ntp: SUCCESS: config-ntp ran successfully 2022-04-07 12:35:50,355 - stages.py[DEBUG]: Running module timezone () with frequency once-per-instance 2022-04-07 12:35:50,355 - handlers.py[DEBUG]: start: modules-config/config-timezone: running config-timezone with frequency once-per-instance 2022-04-07 12:35:50,355 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_timezone - wb: [644] 25 bytes 2022-04-07 12:35:50,356 - helpers.py[DEBUG]: Running config-timezone using lock () 2022-04-07 12:35:50,356 - cc_timezone.py[DEBUG]: Skipping module named timezone, no 'timezone' specified 2022-04-07 12:35:50,356 - handlers.py[DEBUG]: finish: modules-config/config-timezone: SUCCESS: config-timezone ran successfully 2022-04-07 12:35:50,356 - stages.py[DEBUG]: Running module disable-ec2-metadata () with frequency always 2022-04-07 12:35:50,356 - handlers.py[DEBUG]: start: modules-config/config-disable-ec2-metadata: running config-disable-ec2-metadata with frequency always 2022-04-07 12:35:50,356 - helpers.py[DEBUG]: Running config-disable-ec2-metadata using lock () 2022-04-07 12:35:50,356 - cc_disable_ec2_metadata.py[DEBUG]: Skipping module named disable-ec2-metadata, disabling the ec2 route not enabled 2022-04-07 12:35:50,356 - handlers.py[DEBUG]: finish: modules-config/config-disable-ec2-metadata: SUCCESS: config-disable-ec2-metadata ran successfully 2022-04-07 12:35:50,356 - stages.py[DEBUG]: Running module runcmd () with frequency once-per-instance 2022-04-07 12:35:50,356 - handlers.py[DEBUG]: start: modules-config/config-runcmd: running config-runcmd with frequency once-per-instance 2022-04-07 12:35:50,356 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_runcmd - wb: [644] 24 bytes 2022-04-07 12:35:50,356 - helpers.py[DEBUG]: Running config-runcmd using lock () 2022-04-07 12:35:50,356 - cc_runcmd.py[DEBUG]: Skipping module named runcmd, no 'runcmd' key in configuration 2022-04-07 12:35:50,356 - handlers.py[DEBUG]: finish: modules-config/config-runcmd: SUCCESS: config-runcmd ran successfully 2022-04-07 12:35:50,357 - stages.py[DEBUG]: Running module byobu () with frequency once-per-instance 2022-04-07 12:35:50,357 - handlers.py[DEBUG]: start: modules-config/config-byobu: running config-byobu with frequency once-per-instance 2022-04-07 12:35:50,357 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_byobu - wb: [644] 25 bytes 2022-04-07 12:35:50,357 - helpers.py[DEBUG]: Running config-byobu using lock () 2022-04-07 12:35:50,357 - cc_byobu.py[DEBUG]: Skipping module named byobu, no 'byobu' values found 2022-04-07 12:35:50,357 - handlers.py[DEBUG]: finish: modules-config/config-byobu: SUCCESS: config-byobu ran successfully 2022-04-07 12:35:50,357 - main.py[DEBUG]: Ran 14 modules with 0 failures 2022-04-07 12:35:50,357 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmpxbun6mk4) - w: [644] 569 bytes/chars 2022-04-07 12:35:50,357 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2022-04-07 12:35:50,357 - util.py[DEBUG]: Read 14 bytes from /proc/uptime 2022-04-07 12:35:50,357 - util.py[DEBUG]: cloud-init mode 'modules' took 0.296 seconds (0.29) 2022-04-07 12:35:50,357 - handlers.py[DEBUG]: finish: modules-config: SUCCESS: running modules for config 2022-04-07 12:35:50,657 - util.py[DEBUG]: Cloud-init v. 21.4-0ubuntu1~20.04.1 running 'modules:final' at Thu, 07 Apr 2022 12:35:50 +0000. Up 222.64 seconds. 2022-04-07 12:35:50,673 - stages.py[DEBUG]: Using distro class 2022-04-07 12:35:50,674 - stages.py[DEBUG]: Running module package-update-upgrade-install () with frequency once-per-instance 2022-04-07 12:35:50,674 - handlers.py[DEBUG]: start: modules-final/config-package-update-upgrade-install: running config-package-update-upgrade-install with frequency once-per-instance 2022-04-07 12:35:50,674 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_package_update_upgrade_install - wb: [644] 24 bytes 2022-04-07 12:35:50,674 - helpers.py[DEBUG]: Running config-package-update-upgrade-install using lock () 2022-04-07 12:35:50,674 - handlers.py[DEBUG]: finish: modules-final/config-package-update-upgrade-install: SUCCESS: config-package-update-upgrade-install ran successfully 2022-04-07 12:35:50,674 - stages.py[DEBUG]: Running module fan () with frequency once-per-instance 2022-04-07 12:35:50,674 - handlers.py[DEBUG]: start: modules-final/config-fan: running config-fan with frequency once-per-instance 2022-04-07 12:35:50,675 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_fan - wb: [644] 25 bytes 2022-04-07 12:35:50,675 - helpers.py[DEBUG]: Running config-fan using lock () 2022-04-07 12:35:50,675 - cc_fan.py[DEBUG]: fan: no 'fan' config entry. disabling 2022-04-07 12:35:50,675 - handlers.py[DEBUG]: finish: modules-final/config-fan: SUCCESS: config-fan ran successfully 2022-04-07 12:35:50,675 - stages.py[DEBUG]: Running module landscape () with frequency once-per-instance 2022-04-07 12:35:50,675 - handlers.py[DEBUG]: start: modules-final/config-landscape: running config-landscape with frequency once-per-instance 2022-04-07 12:35:50,675 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_landscape - wb: [644] 25 bytes 2022-04-07 12:35:50,675 - helpers.py[DEBUG]: Running config-landscape using lock () 2022-04-07 12:35:50,675 - handlers.py[DEBUG]: finish: modules-final/config-landscape: SUCCESS: config-landscape ran successfully 2022-04-07 12:35:50,675 - stages.py[DEBUG]: Running module lxd () with frequency once-per-instance 2022-04-07 12:35:50,675 - handlers.py[DEBUG]: start: modules-final/config-lxd: running config-lxd with frequency once-per-instance 2022-04-07 12:35:50,675 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_lxd - wb: [644] 25 bytes 2022-04-07 12:35:50,676 - helpers.py[DEBUG]: Running config-lxd using lock () 2022-04-07 12:35:50,676 - cc_lxd.py[DEBUG]: Skipping module named lxd, not present or disabled by cfg 2022-04-07 12:35:50,676 - handlers.py[DEBUG]: finish: modules-final/config-lxd: SUCCESS: config-lxd ran successfully 2022-04-07 12:35:50,676 - stages.py[DEBUG]: Running module ubuntu-drivers () with frequency once-per-instance 2022-04-07 12:35:50,676 - handlers.py[DEBUG]: start: modules-final/config-ubuntu-drivers: running config-ubuntu-drivers with frequency once-per-instance 2022-04-07 12:35:50,676 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_ubuntu_drivers - wb: [644] 24 bytes 2022-04-07 12:35:50,676 - helpers.py[DEBUG]: Running config-ubuntu-drivers using lock () 2022-04-07 12:35:50,676 - cc_ubuntu_drivers.py[DEBUG]: Skipping module named ubuntu-drivers, no 'drivers' key in config 2022-04-07 12:35:50,676 - handlers.py[DEBUG]: finish: modules-final/config-ubuntu-drivers: SUCCESS: config-ubuntu-drivers ran successfully 2022-04-07 12:35:50,676 - stages.py[DEBUG]: Running module write-files-deferred () with frequency once-per-instance 2022-04-07 12:35:50,676 - handlers.py[DEBUG]: start: modules-final/config-write-files-deferred: running config-write-files-deferred with frequency once-per-instance 2022-04-07 12:35:50,676 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_write_files_deferred - wb: [644] 25 bytes 2022-04-07 12:35:50,677 - helpers.py[DEBUG]: Running config-write-files-deferred using lock () 2022-04-07 12:35:50,692 - cc_write_files_deferred.py[DEBUG]: Skipping module named write-files-deferred, no deferred file defined in configuration 2022-04-07 12:35:50,692 - handlers.py[DEBUG]: finish: modules-final/config-write-files-deferred: SUCCESS: config-write-files-deferred ran successfully 2022-04-07 12:35:50,692 - stages.py[DEBUG]: Running module puppet () with frequency once-per-instance 2022-04-07 12:35:50,693 - handlers.py[DEBUG]: start: modules-final/config-puppet: running config-puppet with frequency once-per-instance 2022-04-07 12:35:50,693 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_puppet - wb: [644] 25 bytes 2022-04-07 12:35:50,693 - helpers.py[DEBUG]: Running config-puppet using lock () 2022-04-07 12:35:50,693 - cc_puppet.py[DEBUG]: Skipping module named puppet, no 'puppet' configuration found 2022-04-07 12:35:50,693 - handlers.py[DEBUG]: finish: modules-final/config-puppet: SUCCESS: config-puppet ran successfully 2022-04-07 12:35:50,693 - stages.py[DEBUG]: Running module chef () with frequency always 2022-04-07 12:35:50,693 - handlers.py[DEBUG]: start: modules-final/config-chef: running config-chef with frequency always 2022-04-07 12:35:50,693 - helpers.py[DEBUG]: Running config-chef using lock () 2022-04-07 12:35:50,693 - cc_chef.py[DEBUG]: Skipping module named chef, no 'chef' key in configuration 2022-04-07 12:35:50,693 - handlers.py[DEBUG]: finish: modules-final/config-chef: SUCCESS: config-chef ran successfully 2022-04-07 12:35:50,693 - stages.py[DEBUG]: Running module mcollective () with frequency once-per-instance 2022-04-07 12:35:50,693 - handlers.py[DEBUG]: start: modules-final/config-mcollective: running config-mcollective with frequency once-per-instance 2022-04-07 12:35:50,693 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_mcollective - wb: [644] 25 bytes 2022-04-07 12:35:50,694 - helpers.py[DEBUG]: Running config-mcollective using lock () 2022-04-07 12:35:50,694 - cc_mcollective.py[DEBUG]: Skipping module named mcollective, no 'mcollective' key in configuration 2022-04-07 12:35:50,694 - handlers.py[DEBUG]: finish: modules-final/config-mcollective: SUCCESS: config-mcollective ran successfully 2022-04-07 12:35:50,694 - stages.py[DEBUG]: Running module salt-minion () with frequency once-per-instance 2022-04-07 12:35:50,694 - handlers.py[DEBUG]: start: modules-final/config-salt-minion: running config-salt-minion with frequency once-per-instance 2022-04-07 12:35:50,694 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_salt_minion - wb: [644] 24 bytes 2022-04-07 12:35:50,694 - helpers.py[DEBUG]: Running config-salt-minion using lock () 2022-04-07 12:35:50,694 - cc_salt_minion.py[DEBUG]: Skipping module named salt-minion, no 'salt_minion' key in configuration 2022-04-07 12:35:50,694 - handlers.py[DEBUG]: finish: modules-final/config-salt-minion: SUCCESS: config-salt-minion ran successfully 2022-04-07 12:35:50,694 - stages.py[DEBUG]: Running module reset_rmc () with frequency once-per-instance 2022-04-07 12:35:50,694 - handlers.py[DEBUG]: start: modules-final/config-reset_rmc: running config-reset_rmc with frequency once-per-instance 2022-04-07 12:35:50,694 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_reset_rmc - wb: [644] 25 bytes 2022-04-07 12:35:50,695 - helpers.py[DEBUG]: Running config-reset_rmc using lock () 2022-04-07 12:35:50,695 - cc_reset_rmc.py[DEBUG]: module disabled, RSCT_PATH not present 2022-04-07 12:35:50,695 - handlers.py[DEBUG]: finish: modules-final/config-reset_rmc: SUCCESS: config-reset_rmc ran successfully 2022-04-07 12:35:50,695 - stages.py[DEBUG]: Running module refresh_rmc_and_interface () with frequency always 2022-04-07 12:35:50,695 - handlers.py[DEBUG]: start: modules-final/config-refresh_rmc_and_interface: running config-refresh_rmc_and_interface with frequency always 2022-04-07 12:35:50,695 - helpers.py[DEBUG]: Running config-refresh_rmc_and_interface using lock () 2022-04-07 12:35:50,695 - cc_refresh_rmc_and_interface.py[DEBUG]: No 'rmcctrl' in path, disabled 2022-04-07 12:35:50,695 - handlers.py[DEBUG]: finish: modules-final/config-refresh_rmc_and_interface: SUCCESS: config-refresh_rmc_and_interface ran successfully 2022-04-07 12:35:50,695 - stages.py[DEBUG]: Running module rightscale_userdata () with frequency once-per-instance 2022-04-07 12:35:50,696 - handlers.py[DEBUG]: start: modules-final/config-rightscale_userdata: running config-rightscale_userdata with frequency once-per-instance 2022-04-07 12:35:50,696 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_rightscale_userdata - wb: [644] 25 bytes 2022-04-07 12:35:50,696 - helpers.py[DEBUG]: Running config-rightscale_userdata using lock () 2022-04-07 12:35:50,696 - cc_rightscale_userdata.py[DEBUG]: Failed to get raw userdata in module rightscale_userdata 2022-04-07 12:35:50,696 - handlers.py[DEBUG]: finish: modules-final/config-rightscale_userdata: SUCCESS: config-rightscale_userdata ran successfully 2022-04-07 12:35:50,696 - stages.py[DEBUG]: Running module scripts-vendor () with frequency once-per-instance 2022-04-07 12:35:50,696 - handlers.py[DEBUG]: start: modules-final/config-scripts-vendor: running config-scripts-vendor with frequency once-per-instance 2022-04-07 12:35:50,696 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_scripts_vendor - wb: [644] 25 bytes 2022-04-07 12:35:50,696 - helpers.py[DEBUG]: Running config-scripts-vendor using lock () 2022-04-07 12:35:50,697 - handlers.py[DEBUG]: finish: modules-final/config-scripts-vendor: SUCCESS: config-scripts-vendor ran successfully 2022-04-07 12:35:50,697 - stages.py[DEBUG]: Running module scripts-per-once () with frequency once 2022-04-07 12:35:50,697 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-once: running config-scripts-per-once with frequency once 2022-04-07 12:35:50,697 - util.py[DEBUG]: Writing to /var/lib/cloud/sem/config_scripts_per_once.once - wb: [644] 25 bytes 2022-04-07 12:35:50,697 - helpers.py[DEBUG]: Running config-scripts-per-once using lock () 2022-04-07 12:35:50,698 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-once: SUCCESS: config-scripts-per-once ran successfully 2022-04-07 12:35:50,698 - stages.py[DEBUG]: Running module scripts-per-boot () with frequency always 2022-04-07 12:35:50,698 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-boot: running config-scripts-per-boot with frequency always 2022-04-07 12:35:50,698 - helpers.py[DEBUG]: Running config-scripts-per-boot using lock () 2022-04-07 12:35:50,698 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-boot: SUCCESS: config-scripts-per-boot ran successfully 2022-04-07 12:35:50,698 - stages.py[DEBUG]: Running module scripts-per-instance () with frequency once-per-instance 2022-04-07 12:35:50,698 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-instance: running config-scripts-per-instance with frequency once-per-instance 2022-04-07 12:35:50,698 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_scripts_per_instance - wb: [644] 25 bytes 2022-04-07 12:35:50,699 - helpers.py[DEBUG]: Running config-scripts-per-instance using lock () 2022-04-07 12:35:50,699 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-instance: SUCCESS: config-scripts-per-instance ran successfully 2022-04-07 12:35:50,699 - stages.py[DEBUG]: Running module scripts-user () with frequency once-per-instance 2022-04-07 12:35:50,699 - handlers.py[DEBUG]: start: modules-final/config-scripts-user: running config-scripts-user with frequency once-per-instance 2022-04-07 12:35:50,699 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_scripts_user - wb: [644] 24 bytes 2022-04-07 12:35:50,699 - helpers.py[DEBUG]: Running config-scripts-user using lock () 2022-04-07 12:35:50,699 - handlers.py[DEBUG]: finish: modules-final/config-scripts-user: SUCCESS: config-scripts-user ran successfully 2022-04-07 12:35:50,699 - stages.py[DEBUG]: Running module ssh-authkey-fingerprints () with frequency once-per-instance 2022-04-07 12:35:50,700 - handlers.py[DEBUG]: start: modules-final/config-ssh-authkey-fingerprints: running config-ssh-authkey-fingerprints with frequency once-per-instance 2022-04-07 12:35:50,700 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_ssh_authkey_fingerprints - wb: [644] 25 bytes 2022-04-07 12:35:50,700 - helpers.py[DEBUG]: Running config-ssh-authkey-fingerprints using lock () 2022-04-07 12:35:50,700 - util.py[DEBUG]: Reading from /etc/ssh/sshd_config (quiet=False) 2022-04-07 12:35:50,700 - util.py[DEBUG]: Read 3287 bytes from /etc/ssh/sshd_config 2022-04-07 12:35:50,710 - util.py[DEBUG]: Reading from /home/ubuntu/.ssh/authorized_keys (quiet=False) 2022-04-07 12:35:50,710 - util.py[DEBUG]: Read 569 bytes from /home/ubuntu/.ssh/authorized_keys 2022-04-07 12:35:50,711 - handlers.py[DEBUG]: finish: modules-final/config-ssh-authkey-fingerprints: SUCCESS: config-ssh-authkey-fingerprints ran successfully 2022-04-07 12:35:50,711 - stages.py[DEBUG]: Running module keys-to-console () with frequency once-per-instance 2022-04-07 12:35:50,711 - handlers.py[DEBUG]: start: modules-final/config-keys-to-console: running config-keys-to-console with frequency once-per-instance 2022-04-07 12:35:50,711 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_keys_to_console - wb: [644] 25 bytes 2022-04-07 12:35:50,711 - helpers.py[DEBUG]: Running config-keys-to-console using lock () 2022-04-07 12:35:50,712 - subp.py[DEBUG]: Running command ['/usr/lib/cloud-init/write-ssh-key-fingerprints', '', 'ssh-dss'] with allowed return codes [0] (shell=False, capture=True) 2022-04-07 12:35:50,737 - handlers.py[DEBUG]: finish: modules-final/config-keys-to-console: SUCCESS: config-keys-to-console ran successfully 2022-04-07 12:35:50,737 - stages.py[DEBUG]: Running module install-hotplug () with frequency once-per-instance 2022-04-07 12:35:50,737 - handlers.py[DEBUG]: start: modules-final/config-install-hotplug: running config-install-hotplug with frequency once-per-instance 2022-04-07 12:35:50,737 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_install_hotplug - wb: [644] 25 bytes 2022-04-07 12:35:50,737 - helpers.py[DEBUG]: Running config-install-hotplug using lock () 2022-04-07 12:35:50,738 - stages.py[DEBUG]: Allowed events: {: {}} 2022-04-07 12:35:50,738 - stages.py[DEBUG]: Event Denied: scopes=['network'] EventType=hotplug 2022-04-07 12:35:50,738 - cc_install_hotplug.py[DEBUG]: Skipping hotplug install, not enabled 2022-04-07 12:35:50,738 - handlers.py[DEBUG]: finish: modules-final/config-install-hotplug: SUCCESS: config-install-hotplug ran successfully 2022-04-07 12:35:50,738 - stages.py[DEBUG]: Running module phone-home () with frequency once-per-instance 2022-04-07 12:35:50,738 - handlers.py[DEBUG]: start: modules-final/config-phone-home: running config-phone-home with frequency once-per-instance 2022-04-07 12:35:50,738 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_phone_home - wb: [644] 25 bytes 2022-04-07 12:35:50,738 - helpers.py[DEBUG]: Running config-phone-home using lock () 2022-04-07 12:35:50,739 - cc_phone_home.py[DEBUG]: Skipping module named phone-home, no 'phone_home' configuration found 2022-04-07 12:35:50,739 - handlers.py[DEBUG]: finish: modules-final/config-phone-home: SUCCESS: config-phone-home ran successfully 2022-04-07 12:35:50,739 - stages.py[DEBUG]: Running module final-message () with frequency always 2022-04-07 12:35:50,739 - handlers.py[DEBUG]: start: modules-final/config-final-message: running config-final-message with frequency always 2022-04-07 12:35:50,739 - helpers.py[DEBUG]: Running config-final-message using lock () 2022-04-07 12:35:50,739 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2022-04-07 12:35:50,739 - util.py[DEBUG]: Read 14 bytes from /proc/uptime 2022-04-07 12:35:50,741 - util.py[DEBUG]: Cloud-init v. 21.4-0ubuntu1~20.04.1 finished at Thu, 07 Apr 2022 12:35:50 +0000. Datasource DataSourceOVF [seed=com.vmware.guestInfo]. Up 222.77 seconds 2022-04-07 12:35:50,741 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/boot-finished - wb: [644] 68 bytes 2022-04-07 12:35:50,741 - handlers.py[DEBUG]: finish: modules-final/config-final-message: SUCCESS: config-final-message ran successfully 2022-04-07 12:35:50,741 - stages.py[DEBUG]: Running module power-state-change () with frequency once-per-instance 2022-04-07 12:35:50,741 - handlers.py[DEBUG]: start: modules-final/config-power-state-change: running config-power-state-change with frequency once-per-instance 2022-04-07 12:35:50,741 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/sem/config_power_state_change - wb: [644] 24 bytes 2022-04-07 12:35:50,741 - helpers.py[DEBUG]: Running config-power-state-change using lock () 2022-04-07 12:35:50,742 - cc_power_state_change.py[DEBUG]: no power_state provided. doing nothing 2022-04-07 12:35:50,742 - handlers.py[DEBUG]: finish: modules-final/config-power-state-change: SUCCESS: config-power-state-change ran successfully 2022-04-07 12:35:50,742 - main.py[DEBUG]: Ran 24 modules with 0 failures 2022-04-07 12:35:50,742 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmplh9ith_i) - w: [644] 596 bytes/chars 2022-04-07 12:35:50,742 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/result.json (via temporary file /var/lib/cloud/data/tmpcixepm2l) - w: [644] 92 bytes/chars 2022-04-07 12:35:50,742 - util.py[DEBUG]: Creating symbolic link from '/run/cloud-init/result.json' => '../../var/lib/cloud/data/result.json' 2022-04-07 12:35:50,742 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2022-04-07 12:35:50,742 - util.py[DEBUG]: Read 14 bytes from /proc/uptime 2022-04-07 12:35:50,742 - util.py[DEBUG]: cloud-init mode 'modules' took 0.135 seconds (0.14) 2022-04-07 12:35:50,742 - handlers.py[DEBUG]: finish: modules-final: SUCCESS: running modules for final 2022-04-11 05:59:23,807 - util.py[DEBUG]: Cloud-init v. 21.4-0ubuntu1~20.04.1 running 'init-local' at Mon, 11 Apr 2022 05:59:23 +0000. Up 4.85 seconds. 2022-04-11 05:59:23,807 - main.py[DEBUG]: No kernel command line url found. 2022-04-11 05:59:23,807 - main.py[DEBUG]: Closing stdin. 2022-04-11 05:59:23,809 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [644] 0 bytes 2022-04-11 05:59:23,809 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 104:4 2022-04-11 05:59:23,809 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance/boot-finished 2022-04-11 05:59:23,809 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/data/no-net 2022-04-11 05:59:23,810 - handlers.py[DEBUG]: start: init-local/check-cache: attempting to read from cache [check] 2022-04-11 05:59:23,810 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False) 2022-04-11 05:59:23,810 - util.py[DEBUG]: Read 13946 bytes from /var/lib/cloud/instance/obj.pkl 2022-04-11 05:59:23,827 - stages.py[DEBUG]: cache invalid in datasource: DataSourceOVF [seed=com.vmware.guestInfo] 2022-04-11 05:59:23,827 - handlers.py[DEBUG]: finish: init-local/check-cache: SUCCESS: cache invalid in datasource: DataSourceOVF [seed=com.vmware.guestInfo] 2022-04-11 05:59:23,827 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2022-04-11 05:59:23,827 - stages.py[DEBUG]: Using distro class 2022-04-11 05:59:23,827 - __init__.py[DEBUG]: Looking for data source in: ['OVF', 'None'], via packages ['', 'cloudinit.sources'] that matches dependencies ['FILESYSTEM'] 2022-04-11 05:59:23,828 - __init__.py[DEBUG]: Searching for local data source in: ['DataSourceOVF'] 2022-04-11 05:59:23,828 - handlers.py[DEBUG]: start: init-local/search-OVF: searching for local data from DataSourceOVF 2022-04-11 05:59:23,828 - __init__.py[DEBUG]: Seeing if we can get any data from 2022-04-11 05:59:23,828 - __init__.py[DEBUG]: Update datasource metadata and network config due to events: boot-new-instance 2022-04-11 05:59:23,828 - dmi.py[DEBUG]: querying dmi data /sys/class/dmi/id/product_name 2022-04-11 05:59:23,828 - DataSourceOVF.py[DEBUG]: VMware Virtualization Platform found 2022-04-11 05:59:23,828 - DataSourceOVF.py[DEBUG]: Found the customization plugin at /usr/lib/open-vm-tools/plugins/vmsvc/libdeployPkgPlugin.so 2022-04-11 05:59:23,829 - DataSourceOVF.py[DEBUG]: Waiting for VMware Customization Config File 2022-04-11 05:59:28,834 - DataSourceOVF.py[DEBUG]: Waiting for VMware Customization Config File 2022-04-11 05:59:33,839 - DataSourceOVF.py[DEBUG]: Waiting for VMware Customization Config File 2022-04-11 05:59:38,844 - util.py[DEBUG]: waiting for configuration file took 15.015 seconds 2022-04-11 05:59:38,844 - DataSourceOVF.py[DEBUG]: Did not find VMware Customization Config File 2022-04-11 05:59:38,844 - subp.py[DEBUG]: Running command ['vmware-rpctool', 'info-get guestinfo.ovfEnv'] with allowed return codes [0] (shell=False, capture=True) 2022-04-11 05:59:38,848 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False) 2022-04-11 05:59:38,848 - util.py[DEBUG]: Read 244 bytes from /etc/hosts 2022-04-11 05:59:38,848 - dmi.py[DEBUG]: querying dmi data /sys/class/dmi/id/product_name 2022-04-11 05:59:38,849 - atomic_helper.py[DEBUG]: Atomically writing to file /run/cloud-init/instance-data-sensitive.json (via temporary file /run/cloud-init/tmp1mm2zhbh) - w: [600] 5592 bytes/chars 2022-04-11 05:59:38,849 - atomic_helper.py[DEBUG]: Atomically writing to file /run/cloud-init/instance-data.json (via temporary file /run/cloud-init/tmpmr267m21) - w: [644] 1348 bytes/chars 2022-04-11 05:59:38,849 - handlers.py[DEBUG]: finish: init-local/search-OVF: SUCCESS: found local data from DataSourceOVF 2022-04-11 05:59:38,849 - stages.py[INFO]: Loaded datasource DataSourceOVF - DataSourceOVF [seed=com.vmware.guestInfo] 2022-04-11 05:59:38,850 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2022-04-11 05:59:38,850 - util.py[DEBUG]: Read 3807 bytes from /etc/cloud/cloud.cfg 2022-04-11 05:59:38,850 - util.py[DEBUG]: Attempting to load yaml from string of length 3807 with allowed root types (,) 2022-04-11 05:59:38,857 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg (quiet=False) 2022-04-11 05:59:38,857 - util.py[DEBUG]: Read 39 bytes from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg 2022-04-11 05:59:38,857 - util.py[DEBUG]: Attempting to load yaml from string of length 39 with allowed root types (,) 2022-04-11 05:59:38,857 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2022-04-11 05:59:38,857 - util.py[DEBUG]: Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2022-04-11 05:59:38,857 - util.py[DEBUG]: Attempting to load yaml from string of length 314 with allowed root types (,) 2022-04-11 05:59:38,859 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2022-04-11 05:59:38,859 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2022-04-11 05:59:38,859 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2022-04-11 05:59:38,861 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2022-04-11 05:59:38,861 - util.py[DEBUG]: Read 31 bytes from /run/cloud-init/cloud.cfg 2022-04-11 05:59:38,861 - util.py[DEBUG]: Attempting to load yaml from string of length 31 with allowed root types (,) 2022-04-11 05:59:38,861 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2022-04-11 05:59:38,861 - util.py[DEBUG]: loaded blob returned None, returning default. 2022-04-11 05:59:38,861 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2022-04-11 05:59:38,861 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/iid-dsovf' 2022-04-11 05:59:38,862 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/iid-dsovf/datasource (quiet=False) 2022-04-11 05:59:38,862 - util.py[DEBUG]: Read 57 bytes from /var/lib/cloud/instances/iid-dsovf/datasource 2022-04-11 05:59:38,862 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/datasource - wb: [644] 57 bytes 2022-04-11 05:59:38,863 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [644] 57 bytes 2022-04-11 05:59:38,863 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False) 2022-04-11 05:59:38,863 - util.py[DEBUG]: Read 10 bytes from /var/lib/cloud/data/instance-id 2022-04-11 05:59:38,863 - stages.py[DEBUG]: previous iid found to be iid-dsovf 2022-04-11 05:59:38,863 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [644] 10 bytes 2022-04-11 05:59:38,863 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [644] 10 bytes 2022-04-11 05:59:38,864 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [644] 10 bytes 2022-04-11 05:59:38,864 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [400] 10385 bytes 2022-04-11 05:59:38,864 - main.py[DEBUG]: [local] init will now be targeting instance id: iid-dsovf. new=False 2022-04-11 05:59:38,864 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2022-04-11 05:59:38,864 - util.py[DEBUG]: Read 3807 bytes from /etc/cloud/cloud.cfg 2022-04-11 05:59:38,864 - util.py[DEBUG]: Attempting to load yaml from string of length 3807 with allowed root types (,) 2022-04-11 05:59:38,872 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg (quiet=False) 2022-04-11 05:59:38,872 - util.py[DEBUG]: Read 39 bytes from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg 2022-04-11 05:59:38,872 - util.py[DEBUG]: Attempting to load yaml from string of length 39 with allowed root types (,) 2022-04-11 05:59:38,872 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2022-04-11 05:59:38,872 - util.py[DEBUG]: Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2022-04-11 05:59:38,872 - util.py[DEBUG]: Attempting to load yaml from string of length 314 with allowed root types (,) 2022-04-11 05:59:38,873 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2022-04-11 05:59:38,873 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2022-04-11 05:59:38,873 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2022-04-11 05:59:38,875 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2022-04-11 05:59:38,875 - util.py[DEBUG]: Read 31 bytes from /run/cloud-init/cloud.cfg 2022-04-11 05:59:38,875 - util.py[DEBUG]: Attempting to load yaml from string of length 31 with allowed root types (,) 2022-04-11 05:59:38,875 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2022-04-11 05:59:38,875 - util.py[DEBUG]: loaded blob returned None, returning default. 2022-04-11 05:59:38,875 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2022-04-11 05:59:38,876 - util.py[DEBUG]: Read 918 bytes from /var/lib/cloud/instance/cloud-config.txt 2022-04-11 05:59:38,876 - util.py[DEBUG]: Attempting to load yaml from string of length 918 with allowed root types (,) 2022-04-11 05:59:38,877 - stages.py[DEBUG]: Using distro class 2022-04-11 05:59:38,878 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-11 05:59:38,878 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-11 05:59:38,878 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False) 2022-04-11 05:59:38,878 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address 2022-04-11 05:59:38,878 - util.py[DEBUG]: Reading from /sys/class/net/ens192/name_assign_type (quiet=False) 2022-04-11 05:59:38,878 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/name_assign_type 2022-04-11 05:59:38,879 - util.py[DEBUG]: Reading from /sys/class/net/ens192/carrier (quiet=False) 2022-04-11 05:59:38,879 - util.py[DEBUG]: Reading from /sys/class/net/ens192/dormant (quiet=False) 2022-04-11 05:59:38,879 - util.py[DEBUG]: Reading from /sys/class/net/ens192/operstate (quiet=False) 2022-04-11 05:59:38,879 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/ens192/operstate 2022-04-11 05:59:38,879 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-11 05:59:38,879 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-11 05:59:38,879 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-11 05:59:38,879 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-11 05:59:38,879 - stages.py[DEBUG]: Allowed events: {: {}} 2022-04-11 05:59:38,879 - stages.py[DEBUG]: Event Denied: scopes=['network'] EventType=boot 2022-04-11 05:59:38,879 - stages.py[DEBUG]: Allowed events: {: {}} 2022-04-11 05:59:38,879 - stages.py[DEBUG]: Event Denied: scopes=['network'] EventType=boot-legacy 2022-04-11 05:59:38,879 - stages.py[DEBUG]: No network config applied. Neither a new instance nor datasource network update allowed 2022-04-11 05:59:38,880 - stages.py[DEBUG]: applying net config names for {'ethernets': {'ens192': {'dhcp4': True, 'set-name': 'ens192', 'match': {'macaddress': '00:50:56:a5:f6:80'}}}, 'version': 2} 2022-04-11 05:59:38,880 - util.py[DEBUG]: Reading from /sys/class/net/ens192/device/device (quiet=False) 2022-04-11 05:59:38,880 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/ens192/device/device 2022-04-11 05:59:38,880 - util.py[DEBUG]: Reading from /sys/class/net/ens192/addr_assign_type (quiet=False) 2022-04-11 05:59:38,880 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/addr_assign_type 2022-04-11 05:59:38,880 - util.py[DEBUG]: Reading from /sys/class/net/ens192/uevent (quiet=False) 2022-04-11 05:59:38,880 - util.py[DEBUG]: Read 27 bytes from /sys/class/net/ens192/uevent 2022-04-11 05:59:38,880 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-11 05:59:38,880 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-11 05:59:38,880 - __init__.py[DEBUG]: ovs-vsctl not in PATH; not detecting Open vSwitch interfaces 2022-04-11 05:59:38,880 - util.py[DEBUG]: Reading from /sys/class/net/ens192/device/device (quiet=False) 2022-04-11 05:59:38,880 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/ens192/device/device 2022-04-11 05:59:38,880 - util.py[DEBUG]: Reading from /sys/class/net/lo/addr_assign_type (quiet=False) 2022-04-11 05:59:38,880 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/lo/addr_assign_type 2022-04-11 05:59:38,880 - util.py[DEBUG]: Reading from /sys/class/net/lo/uevent (quiet=False) 2022-04-11 05:59:38,880 - util.py[DEBUG]: Read 23 bytes from /sys/class/net/lo/uevent 2022-04-11 05:59:38,880 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False) 2022-04-11 05:59:38,880 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address 2022-04-11 05:59:38,880 - util.py[DEBUG]: Reading from /sys/class/net/lo/device/device (quiet=False) 2022-04-11 05:59:38,880 - util.py[DEBUG]: Reading from /sys/class/net/ens192/operstate (quiet=False) 2022-04-11 05:59:38,880 - util.py[DEBUG]: Read 5 bytes from /sys/class/net/ens192/operstate 2022-04-11 05:59:38,880 - util.py[DEBUG]: Reading from /sys/class/net/lo/operstate (quiet=False) 2022-04-11 05:59:38,880 - util.py[DEBUG]: Read 8 bytes from /sys/class/net/lo/operstate 2022-04-11 05:59:38,881 - subp.py[DEBUG]: Running command ['ip', '-6', 'addr', 'show', 'permanent', 'scope', 'global'] with allowed return codes [0] (shell=False, capture=True) 2022-04-11 05:59:38,889 - subp.py[DEBUG]: Running command ['ip', '-4', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True) 2022-04-11 05:59:38,891 - __init__.py[DEBUG]: Detected interfaces {'ens192': {'downable': True, 'device_id': '0x07b0', 'driver': 'vmxnet3', 'mac': '00:50:56:a5:f6:80', 'name': 'ens192', 'up': False}, 'lo': {'downable': False, 'device_id': None, 'driver': None, 'mac': '00:00:00:00:00:00', 'name': 'lo', 'up': True}} 2022-04-11 05:59:38,891 - __init__.py[DEBUG]: no work necessary for renaming of [['00:50:56:a5:f6:80', 'ens192', 'vmxnet3', '0x07b0']] 2022-04-11 05:59:38,891 - main.py[DEBUG]: [local] Exiting. datasource DataSourceOVF [seed=com.vmware.guestInfo] not in local mode. 2022-04-11 05:59:38,891 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmplz_d3n_z) - w: [644] 513 bytes/chars 2022-04-11 05:59:38,892 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2022-04-11 05:59:38,892 - util.py[DEBUG]: Read 12 bytes from /proc/uptime 2022-04-11 05:59:38,892 - util.py[DEBUG]: cloud-init mode 'init' took 15.119 seconds (15.12) 2022-04-11 05:59:38,892 - handlers.py[DEBUG]: finish: init-local: SUCCESS: searching for local datasources 2022-04-11 05:59:40,403 - util.py[DEBUG]: Cloud-init v. 21.4-0ubuntu1~20.04.1 running 'init' at Mon, 11 Apr 2022 05:59:40 +0000. Up 21.45 seconds. 2022-04-11 05:59:40,403 - main.py[DEBUG]: No kernel command line url found. 2022-04-11 05:59:40,403 - main.py[DEBUG]: Closing stdin. 2022-04-11 05:59:40,404 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [644] 0 bytes 2022-04-11 05:59:40,404 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 104:4 2022-04-11 05:59:40,405 - subp.py[DEBUG]: Running command ['ip', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True) 2022-04-11 05:59:40,407 - subp.py[DEBUG]: Running command ['ip', '-o', 'route', 'list'] with allowed return codes [0] (shell=False, capture=True) 2022-04-11 05:59:40,409 - subp.py[DEBUG]: Running command ['ip', '--oneline', '-6', 'route', 'list', 'table', 'all'] with allowed return codes [0, 1] (shell=False, capture=True) 2022-04-11 05:59:40,411 - main.py[DEBUG]: Checking to see if files that we need already exist from a previous run that would allow us to stop early. 2022-04-11 05:59:40,411 - main.py[DEBUG]: Execution continuing, no previous run detected that would allow us to stop early. 2022-04-11 05:59:40,411 - handlers.py[DEBUG]: start: init-network/check-cache: attempting to read from cache [trust] 2022-04-11 05:59:40,411 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False) 2022-04-11 05:59:40,411 - util.py[DEBUG]: Read 10385 bytes from /var/lib/cloud/instance/obj.pkl 2022-04-11 05:59:40,416 - util.py[DEBUG]: Reading from /run/cloud-init/.instance-id (quiet=False) 2022-04-11 05:59:40,416 - util.py[DEBUG]: Read 10 bytes from /run/cloud-init/.instance-id 2022-04-11 05:59:40,416 - stages.py[DEBUG]: restored from cache with run check: DataSourceOVF [seed=com.vmware.guestInfo] 2022-04-11 05:59:40,416 - handlers.py[DEBUG]: finish: init-network/check-cache: SUCCESS: restored from cache with run check: DataSourceOVF [seed=com.vmware.guestInfo] 2022-04-11 05:59:40,416 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2022-04-11 05:59:40,416 - util.py[DEBUG]: Read 3807 bytes from /etc/cloud/cloud.cfg 2022-04-11 05:59:40,416 - util.py[DEBUG]: Attempting to load yaml from string of length 3807 with allowed root types (,) 2022-04-11 05:59:40,424 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg (quiet=False) 2022-04-11 05:59:40,424 - util.py[DEBUG]: Read 39 bytes from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg 2022-04-11 05:59:40,424 - util.py[DEBUG]: Attempting to load yaml from string of length 39 with allowed root types (,) 2022-04-11 05:59:40,424 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2022-04-11 05:59:40,424 - util.py[DEBUG]: Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2022-04-11 05:59:40,424 - util.py[DEBUG]: Attempting to load yaml from string of length 314 with allowed root types (,) 2022-04-11 05:59:40,425 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2022-04-11 05:59:40,425 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2022-04-11 05:59:40,425 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2022-04-11 05:59:40,427 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2022-04-11 05:59:40,427 - util.py[DEBUG]: Read 31 bytes from /run/cloud-init/cloud.cfg 2022-04-11 05:59:40,427 - util.py[DEBUG]: Attempting to load yaml from string of length 31 with allowed root types (,) 2022-04-11 05:59:40,428 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2022-04-11 05:59:40,428 - util.py[DEBUG]: loaded blob returned None, returning default. 2022-04-11 05:59:40,428 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2022-04-11 05:59:40,428 - util.py[DEBUG]: Read 918 bytes from /var/lib/cloud/instance/cloud-config.txt 2022-04-11 05:59:40,428 - util.py[DEBUG]: Attempting to load yaml from string of length 918 with allowed root types (,) 2022-04-11 05:59:40,430 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2022-04-11 05:59:40,430 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/iid-dsovf' 2022-04-11 05:59:40,430 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/iid-dsovf/datasource (quiet=False) 2022-04-11 05:59:40,430 - util.py[DEBUG]: Read 57 bytes from /var/lib/cloud/instances/iid-dsovf/datasource 2022-04-11 05:59:40,430 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/datasource - wb: [644] 57 bytes 2022-04-11 05:59:40,430 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [644] 57 bytes 2022-04-11 05:59:40,430 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False) 2022-04-11 05:59:40,430 - util.py[DEBUG]: Read 10 bytes from /var/lib/cloud/data/instance-id 2022-04-11 05:59:40,430 - stages.py[DEBUG]: previous iid found to be iid-dsovf 2022-04-11 05:59:40,430 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [644] 10 bytes 2022-04-11 05:59:40,431 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [644] 10 bytes 2022-04-11 05:59:40,431 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [644] 10 bytes 2022-04-11 05:59:40,431 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [400] 10397 bytes 2022-04-11 05:59:40,432 - main.py[DEBUG]: [net] init will now be targeting instance id: iid-dsovf. new=False 2022-04-11 05:59:40,432 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2022-04-11 05:59:40,432 - util.py[DEBUG]: Read 3807 bytes from /etc/cloud/cloud.cfg 2022-04-11 05:59:40,432 - util.py[DEBUG]: Attempting to load yaml from string of length 3807 with allowed root types (,) 2022-04-11 05:59:40,439 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg (quiet=False) 2022-04-11 05:59:40,439 - util.py[DEBUG]: Read 39 bytes from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg 2022-04-11 05:59:40,439 - util.py[DEBUG]: Attempting to load yaml from string of length 39 with allowed root types (,) 2022-04-11 05:59:40,439 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2022-04-11 05:59:40,439 - util.py[DEBUG]: Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2022-04-11 05:59:40,439 - util.py[DEBUG]: Attempting to load yaml from string of length 314 with allowed root types (,) 2022-04-11 05:59:40,440 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2022-04-11 05:59:40,441 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2022-04-11 05:59:40,441 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2022-04-11 05:59:40,442 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2022-04-11 05:59:40,443 - util.py[DEBUG]: Read 31 bytes from /run/cloud-init/cloud.cfg 2022-04-11 05:59:40,443 - util.py[DEBUG]: Attempting to load yaml from string of length 31 with allowed root types (,) 2022-04-11 05:59:40,443 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2022-04-11 05:59:40,443 - util.py[DEBUG]: loaded blob returned None, returning default. 2022-04-11 05:59:40,443 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2022-04-11 05:59:40,443 - util.py[DEBUG]: Read 918 bytes from /var/lib/cloud/instance/cloud-config.txt 2022-04-11 05:59:40,443 - util.py[DEBUG]: Attempting to load yaml from string of length 918 with allowed root types (,) 2022-04-11 05:59:40,445 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-11 05:59:40,445 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-11 05:59:40,445 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False) 2022-04-11 05:59:40,445 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address 2022-04-11 05:59:40,445 - stages.py[DEBUG]: Using distro class 2022-04-11 05:59:40,446 - util.py[DEBUG]: Reading from /sys/class/net/ens192/name_assign_type (quiet=False) 2022-04-11 05:59:40,446 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/name_assign_type 2022-04-11 05:59:40,446 - util.py[DEBUG]: Reading from /sys/class/net/ens192/carrier (quiet=False) 2022-04-11 05:59:40,446 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/carrier 2022-04-11 05:59:40,446 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-11 05:59:40,446 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-11 05:59:40,446 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-11 05:59:40,446 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-11 05:59:40,446 - stages.py[DEBUG]: Allowed events: {: {}} 2022-04-11 05:59:40,446 - stages.py[DEBUG]: Event Denied: scopes=['network'] EventType=boot 2022-04-11 05:59:40,446 - stages.py[DEBUG]: Allowed events: {: {}} 2022-04-11 05:59:40,447 - stages.py[DEBUG]: Event Denied: scopes=['network'] EventType=boot-legacy 2022-04-11 05:59:40,447 - stages.py[DEBUG]: No network config applied. Neither a new instance nor datasource network update allowed 2022-04-11 05:59:40,447 - stages.py[DEBUG]: applying net config names for {'ethernets': {'ens192': {'dhcp4': True, 'set-name': 'ens192', 'match': {'macaddress': '00:50:56:a5:f6:80'}}}, 'version': 2} 2022-04-11 05:59:40,447 - util.py[DEBUG]: Reading from /sys/class/net/ens192/device/device (quiet=False) 2022-04-11 05:59:40,447 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/ens192/device/device 2022-04-11 05:59:40,447 - util.py[DEBUG]: Reading from /sys/class/net/ens192/addr_assign_type (quiet=False) 2022-04-11 05:59:40,447 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/ens192/addr_assign_type 2022-04-11 05:59:40,447 - util.py[DEBUG]: Reading from /sys/class/net/ens192/uevent (quiet=False) 2022-04-11 05:59:40,447 - util.py[DEBUG]: Read 27 bytes from /sys/class/net/ens192/uevent 2022-04-11 05:59:40,447 - util.py[DEBUG]: Reading from /sys/class/net/ens192/address (quiet=False) 2022-04-11 05:59:40,447 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/ens192/address 2022-04-11 05:59:40,447 - __init__.py[DEBUG]: ovs-vsctl not in PATH; not detecting Open vSwitch interfaces 2022-04-11 05:59:40,447 - util.py[DEBUG]: Reading from /sys/class/net/ens192/device/device (quiet=False) 2022-04-11 05:59:40,447 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/ens192/device/device 2022-04-11 05:59:40,447 - util.py[DEBUG]: Reading from /sys/class/net/lo/addr_assign_type (quiet=False) 2022-04-11 05:59:40,447 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/lo/addr_assign_type 2022-04-11 05:59:40,447 - util.py[DEBUG]: Reading from /sys/class/net/lo/uevent (quiet=False) 2022-04-11 05:59:40,447 - util.py[DEBUG]: Read 23 bytes from /sys/class/net/lo/uevent 2022-04-11 05:59:40,447 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False) 2022-04-11 05:59:40,447 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address 2022-04-11 05:59:40,447 - util.py[DEBUG]: Reading from /sys/class/net/lo/device/device (quiet=False) 2022-04-11 05:59:40,447 - util.py[DEBUG]: Reading from /sys/class/net/ens192/operstate (quiet=False) 2022-04-11 05:59:40,447 - util.py[DEBUG]: Read 3 bytes from /sys/class/net/ens192/operstate 2022-04-11 05:59:40,447 - util.py[DEBUG]: Reading from /sys/class/net/lo/operstate (quiet=False) 2022-04-11 05:59:40,447 - util.py[DEBUG]: Read 8 bytes from /sys/class/net/lo/operstate 2022-04-11 05:59:40,448 - subp.py[DEBUG]: Running command ['ip', '-6', 'addr', 'show', 'permanent', 'scope', 'global'] with allowed return codes [0] (shell=False, capture=True) 2022-04-11 05:59:40,449 - subp.py[DEBUG]: Running command ['ip', '-4', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True) 2022-04-11 05:59:40,450 - __init__.py[DEBUG]: Detected interfaces {'ens192': {'downable': False, 'device_id': '0x07b0', 'driver': 'vmxnet3', 'mac': '00:50:56:a5:f6:80', 'name': 'ens192', 'up': True}, 'lo': {'downable': False, 'device_id': None, 'driver': None, 'mac': '00:00:00:00:00:00', 'name': 'lo', 'up': True}} 2022-04-11 05:59:40,450 - __init__.py[DEBUG]: no work necessary for renaming of [['00:50:56:a5:f6:80', 'ens192', 'vmxnet3', '0x07b0']] 2022-04-11 05:59:40,451 - handlers.py[DEBUG]: start: init-network/setup-datasource: setting up datasource 2022-04-11 05:59:40,451 - handlers.py[DEBUG]: finish: init-network/setup-datasource: SUCCESS: setting up datasource 2022-04-11 05:59:40,451 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/user-data.txt - wb: [600] 1454 bytes 2022-04-11 05:59:40,451 - util.py[DEBUG]: Attempting to load yaml from string of length 1454 with allowed root types (,) 2022-04-11 05:59:40,454 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/user-data.txt.i - wb: [600] 1759 bytes 2022-04-11 05:59:40,454 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/vendor-data.txt - wb: [600] 0 bytes 2022-04-11 05:59:40,455 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/vendor-data.txt.i - wb: [600] 308 bytes 2022-04-11 05:59:40,455 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/vendor-data2.txt - wb: [600] 0 bytes 2022-04-11 05:59:40,456 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/vendor-data2.txt.i - wb: [600] 308 bytes 2022-04-11 05:59:40,456 - helpers.py[DEBUG]: consume_data already ran (freq=once-per-instance) 2022-04-11 05:59:40,457 - handlers.py[DEBUG]: start: init-network/consume-user-data: reading and applying user-data 2022-04-11 05:59:40,457 - stages.py[DEBUG]: Added default handler for {'text/cloud-config-jsonp', 'text/cloud-config'} from CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] 2022-04-11 05:59:40,457 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript'} from ShellScriptPartHandler: [['text/x-shellscript']] 2022-04-11 05:59:40,457 - stages.py[DEBUG]: Added default handler for {'text/cloud-boothook'} from BootHookPartHandler: [['text/cloud-boothook']] 2022-04-11 05:59:40,457 - stages.py[DEBUG]: Added default handler for {'text/upstart-job'} from UpstartJobPartHandler: [['text/upstart-job']] 2022-04-11 05:59:40,457 - stages.py[DEBUG]: Added default handler for {'text/jinja2'} from JinjaTemplatePartHandler: [['text/jinja2']] 2022-04-11 05:59:40,457 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__begin__, None, 3) with frequency always 2022-04-11 05:59:40,458 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__begin__, None, 2) with frequency always 2022-04-11 05:59:40,458 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__begin__, None, 2) with frequency always 2022-04-11 05:59:40,458 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__begin__, None, 3) with frequency always 2022-04-11 05:59:40,458 - __init__.py[DEBUG]: {'MIME-Version': '1.0', 'Content-Type': 'text/cloud-config', 'Content-Disposition': 'attachment; filename="part-001"'} 2022-04-11 05:59:40,458 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (text/cloud-config, part-001, 3) with frequency always 2022-04-11 05:59:40,458 - util.py[DEBUG]: Attempting to load yaml from string of length 1454 with allowed root types (,) 2022-04-11 05:59:40,459 - cloud_config.py[DEBUG]: Merging by applying [('dict', ['replace']), ('list', []), ('str', [])] 2022-04-11 05:59:40,460 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__end__, None, 3) with frequency always 2022-04-11 05:59:40,461 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/iid-dsovf/cloud-config.txt - wb: [600] 918 bytes 2022-04-11 05:59:40,461 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__end__, None, 2) with frequency always 2022-04-11 05:59:40,461 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__end__, None, 2) with frequency always 2022-04-11 05:59:40,461 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__end__, None, 3) with frequency always 2022-04-11 05:59:40,461 - handlers.py[DEBUG]: finish: init-network/consume-user-data: SUCCESS: reading and applying user-data 2022-04-11 05:59:40,461 - handlers.py[DEBUG]: start: init-network/consume-vendor-data: reading and applying vendor-data 2022-04-11 05:59:40,461 - stages.py[DEBUG]: no vendordata from datasource 2022-04-11 05:59:40,461 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data: SUCCESS: reading and applying vendor-data 2022-04-11 05:59:40,461 - handlers.py[DEBUG]: start: init-network/consume-vendor-data2: reading and applying vendor-data2 2022-04-11 05:59:40,461 - stages.py[DEBUG]: no vendordata2 from datasource 2022-04-11 05:59:40,462 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data2: SUCCESS: reading and applying vendor-data2 2022-04-11 05:59:40,462 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2022-04-11 05:59:40,462 - util.py[DEBUG]: Read 3807 bytes from /etc/cloud/cloud.cfg 2022-04-11 05:59:40,462 - util.py[DEBUG]: Attempting to load yaml from string of length 3807 with allowed root types (,) 2022-04-11 05:59:40,469 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg (quiet=False) 2022-04-11 05:59:40,469 - util.py[DEBUG]: Read 39 bytes from /etc/cloud/cloud.cfg.d/99-vmware_customization.cfg 2022-04-11 05:59:40,469 - util.py[DEBUG]: Attempting to load yaml from string of length 39 with allowed root types (,) 2022-04-11 05:59:40,469 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False) 2022-04-11 05:59:40,469 - util.py[DEBUG]: Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg 2022-04-11 05:59:40,469 - util.py[DEBUG]: Attempting to load yaml from string of length 314 with allowed root types (,) 2022-04-11 05:59:40,470 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2022-04-11 05:59:40,470 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2022-04-11 05:59:40,470 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2022-04-11 05:59:40,472 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2022-04-11 05:59:40,472 - util.py[DEBUG]: Read 31 bytes from /run/cloud-init/cloud.cfg 2022-04-11 05:59:40,472 - util.py[DEBUG]: Attempting to load yaml from string of length 31 with allowed root types (,) 2022-04-11 05:59:40,473 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2022-04-11 05:59:40,473 - util.py[DEBUG]: loaded blob returned None, returning default. 2022-04-11 05:59:40,473 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2022-04-11 05:59:40,473 - util.py[DEBUG]: Read 918 bytes from /var/lib/cloud/instance/cloud-config.txt 2022-04-11 05:59:40,473 - util.py[DEBUG]: Attempting to load yaml from string of length 918 with allowed root types (,) 2022-04-11 05:59:40,474 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2022-04-11 05:59:40,475 - util.py[DEBUG]: Read 918 bytes from /var/lib/cloud/instance/cloud-config.txt 2022-04-11 05:59:40,475 - util.py[DEBUG]: Attempting to load yaml from string of length 918 with allowed root types (,) 2022-04-11 05:59:40,477 - handlers.py[DEBUG]: start: init-network/activate-datasource: activating datasource 2022-04-11 05:59:40,478 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [400] 13946 bytes 2022-04-11 05:59:40,478 - handlers.py[DEBUG]: finish: init-network/activate-datasource: SUCCESS: activating datasource 2022-04-11 05:59:40,478 - main.py[DEBUG]: no di_report found in config. 2022-04-11 05:59:40,489 - stages.py[DEBUG]: Using distro class 2022-04-11 05:59:40,490 - stages.py[DEBUG]: Running module migrator () with frequency always 2022-04-11 05:59:40,490 - handlers.py[DEBUG]: start: init-network/config-migrator: running config-migrator with frequency always 2022-04-11 05:59:40,490 - helpers.py[DEBUG]: Running config-migrator using lock () 2022-04-11 05:59:40,491 - cc_migrator.py[DEBUG]: Migrated 0 semaphore files to there canonicalized names 2022-04-11 05:59:40,491 - handlers.py[DEBUG]: finish: init-network/config-migrator: SUCCESS: config-migrator ran successfully 2022-04-11 05:59:40,491 - stages.py[DEBUG]: Running module seed_random () with frequency once-per-instance 2022-04-11 05:59:40,491 - handlers.py[DEBUG]: start: init-network/config-seed_random: running config-seed_random with frequency once-per-instance 2022-04-11 05:59:40,491 - helpers.py[DEBUG]: config-seed_random already ran (freq=once-per-instance) 2022-04-11 05:59:40,491 - handlers.py[DEBUG]: finish: init-network/config-seed_random: SUCCESS: config-seed_random previously ran 2022-04-11 05:59:40,491 - stages.py[DEBUG]: Running module bootcmd () with frequency always 2022-04-11 05:59:40,491 - handlers.py[DEBUG]: start: init-network/config-bootcmd: running config-bootcmd with frequency always 2022-04-11 05:59:40,491 - helpers.py[DEBUG]: Running config-bootcmd using lock () 2022-04-11 05:59:40,491 - cc_bootcmd.py[DEBUG]: Skipping module named bootcmd, no 'bootcmd' key in configuration 2022-04-11 05:59:40,491 - handlers.py[DEBUG]: finish: init-network/config-bootcmd: SUCCESS: config-bootcmd ran successfully 2022-04-11 05:59:40,491 - stages.py[DEBUG]: Running module write-files () with frequency once-per-instance 2022-04-11 05:59:40,491 - handlers.py[DEBUG]: start: init-network/config-write-files: running config-write-files with frequency once-per-instance 2022-04-11 05:59:40,491 - helpers.py[DEBUG]: config-write-files already ran (freq=once-per-instance) 2022-04-11 05:59:40,491 - handlers.py[DEBUG]: finish: init-network/config-write-files: SUCCESS: config-write-files previously ran 2022-04-11 05:59:40,492 - stages.py[DEBUG]: Running module growpart () with frequency always 2022-04-11 05:59:40,492 - handlers.py[DEBUG]: start: init-network/config-growpart: running config-growpart with frequency always 2022-04-11 05:59:40,492 - helpers.py[DEBUG]: Running config-growpart using lock () 2022-04-11 05:59:40,492 - cc_growpart.py[DEBUG]: No 'growpart' entry in cfg. Using default: {'mode': 'auto', 'devices': ['/'], 'ignore_growroot_disabled': False} 2022-04-11 05:59:40,492 - subp.py[DEBUG]: Running command ['growpart', '--help'] with allowed return codes [0] (shell=False, capture=True) 2022-04-11 05:59:40,495 - util.py[DEBUG]: Reading from /proc/713/mountinfo (quiet=False) 2022-04-11 05:59:40,495 - util.py[DEBUG]: Read 3550 bytes from /proc/713/mountinfo 2022-04-11 05:59:40,495 - util.py[DEBUG]: Reading from /sys/class/block/sda1/partition (quiet=False) 2022-04-11 05:59:40,495 - util.py[DEBUG]: Read 2 bytes from /sys/class/block/sda1/partition 2022-04-11 05:59:40,495 - util.py[DEBUG]: Reading from /sys/devices/pci0000:00/0000:00:15.0/0000:03:00.0/host2/target2:0:0/2:0:0:0/block/sda/dev (quiet=False) 2022-04-11 05:59:40,495 - util.py[DEBUG]: Read 4 bytes from /sys/devices/pci0000:00/0000:00:15.0/0000:03:00.0/host2/target2:0:0/2:0:0:0/block/sda/dev 2022-04-11 05:59:40,495 - subp.py[DEBUG]: Running command ['growpart', '--dry-run', '/dev/sda', '1'] with allowed return codes [0] (shell=False, capture=True) 2022-04-11 05:59:40,526 - util.py[DEBUG]: resize_devices took 0.031 seconds 2022-04-11 05:59:40,526 - cc_growpart.py[DEBUG]: '/' NOCHANGE: no change necessary (/dev/sda, 1) 2022-04-11 05:59:40,526 - handlers.py[DEBUG]: finish: init-network/config-growpart: SUCCESS: config-growpart ran successfully 2022-04-11 05:59:40,526 - stages.py[DEBUG]: Running module resizefs () with frequency always 2022-04-11 05:59:40,526 - handlers.py[DEBUG]: start: init-network/config-resizefs: running config-resizefs with frequency always 2022-04-11 05:59:40,526 - helpers.py[DEBUG]: Running config-resizefs using lock () 2022-04-11 05:59:40,573 - util.py[DEBUG]: Reading from /proc/713/mountinfo (quiet=False) 2022-04-11 05:59:40,573 - util.py[DEBUG]: Read 3550 bytes from /proc/713/mountinfo 2022-04-11 05:59:40,573 - cc_resizefs.py[DEBUG]: resize_info: dev=/dev/sda1 mnt_point=/ path=/ 2022-04-11 05:59:40,573 - cc_resizefs.py[DEBUG]: Resizing / (ext4) using resize2fs /dev/sda1 2022-04-11 05:59:40,573 - subp.py[DEBUG]: Running command ('resize2fs', '/dev/sda1') with allowed return codes [0] (shell=False, capture=True) 2022-04-11 05:59:40,579 - util.py[DEBUG]: Resizing took 0.006 seconds 2022-04-11 05:59:40,579 - cc_resizefs.py[DEBUG]: Resized root filesystem (type=ext4, val=True) 2022-04-11 05:59:40,579 - handlers.py[DEBUG]: finish: init-network/config-resizefs: SUCCESS: config-resizefs ran successfully 2022-04-11 05:59:40,579 - stages.py[DEBUG]: Running module disk_setup () with frequency once-per-instance 2022-04-11 05:59:40,579 - handlers.py[DEBUG]: start: init-network/config-disk_setup: running config-disk_setup with frequency once-per-instance 2022-04-11 05:59:40,579 - helpers.py[DEBUG]: config-disk_setup already ran (freq=once-per-instance) 2022-04-11 05:59:40,579 - handlers.py[DEBUG]: finish: init-network/config-disk_setup: SUCCESS: config-disk_setup previously ran 2022-04-11 05:59:40,579 - stages.py[DEBUG]: Running module mounts () with frequency once-per-instance 2022-04-11 05:59:40,580 - handlers.py[DEBUG]: start: init-network/config-mounts: running config-mounts with frequency once-per-instance 2022-04-11 05:59:40,580 - helpers.py[DEBUG]: config-mounts already ran (freq=once-per-instance) 2022-04-11 05:59:40,580 - handlers.py[DEBUG]: finish: init-network/config-mounts: SUCCESS: config-mounts previously ran 2022-04-11 05:59:40,580 - stages.py[DEBUG]: Running module set_hostname () with frequency once-per-instance 2022-04-11 05:59:40,580 - handlers.py[DEBUG]: start: init-network/config-set_hostname: running config-set_hostname with frequency once-per-instance 2022-04-11 05:59:40,580 - helpers.py[DEBUG]: config-set_hostname already ran (freq=once-per-instance) 2022-04-11 05:59:40,580 - handlers.py[DEBUG]: finish: init-network/config-set_hostname: SUCCESS: config-set_hostname previously ran 2022-04-11 05:59:40,580 - stages.py[DEBUG]: Running module update_hostname () with frequency always 2022-04-11 05:59:40,580 - handlers.py[DEBUG]: start: init-network/config-update_hostname: running config-update_hostname with frequency always 2022-04-11 05:59:40,580 - helpers.py[DEBUG]: Running config-update_hostname using lock () 2022-04-11 05:59:40,580 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False) 2022-04-11 05:59:40,580 - util.py[DEBUG]: Read 244 bytes from /etc/hosts 2022-04-11 05:59:40,580 - util.py[DEBUG]: Reading from /etc/hosts (quiet=False) 2022-04-11 05:59:40,580 - util.py[DEBUG]: Read 244 bytes from /etc/hosts 2022-04-11 05:59:40,580 - cc_update_hostname.py[DEBUG]: Updating hostname to ubuntu (ubuntu) 2022-04-11 05:59:40,580 - util.py[DEBUG]: Reading from /var/lib/cloud/data/previous-hostname (quiet=False) 2022-04-11 05:59:40,581 - util.py[DEBUG]: Read 7 bytes from /var/lib/cloud/data/previous-hostname 2022-04-11 05:59:40,581 - util.py[DEBUG]: Reading from /etc/hostname (quiet=False) 2022-04-11 05:59:40,581 - util.py[DEBUG]: Read 7 bytes from /etc/hostname 2022-04-11 05:59:40,581 - __init__.py[DEBUG]: Attempting to update hostname to ubuntu in 0 files 2022-04-11 05:59:40,581 - handlers.py[DEBUG]: finish: init-network/config-update_hostname: SUCCESS: config-update_hostname ran successfully 2022-04-11 05:59:40,581 - stages.py[DEBUG]: Running module update_etc_hosts () with frequency always 2022-04-11 05:59:40,581 - handlers.py[DEBUG]: start: init-network/config-update_etc_hosts: running config-update_etc_hosts with frequency always 2022-04-11 05:59:40,581 - helpers.py[DEBUG]: Running config-update_etc_hosts using lock () 2022-04-11 05:59:40,581 - cc_update_etc_hosts.py[DEBUG]: Configuration option 'manage_etc_hosts' is not set, not managing /etc/hosts in module update_etc_hosts 2022-04-11 05:59:40,581 - handlers.py[DEBUG]: finish: init-network/config-update_etc_hosts: SUCCESS: config-update_etc_hosts ran successfully 2022-04-11 05:59:40,581 - stages.py[DEBUG]: Running module ca-certs () with frequency once-per-instance 2022-04-11 05:59:40,581 - handlers.py[DEBUG]: start: init-network/config-ca-certs: running config-ca-certs with frequency once-per-instance 2022-04-11 05:59:40,581 - helpers.py[DEBUG]: config-ca-certs already ran (freq=once-per-instance) 2022-04-11 05:59:40,581 - handlers.py[DEBUG]: finish: init-network/config-ca-certs: SUCCESS: config-ca-certs previously ran 2022-04-11 05:59:40,581 - stages.py[DEBUG]: Running module rsyslog () with frequency once-per-instance 2022-04-11 05:59:40,581 - handlers.py[DEBUG]: start: init-network/config-rsyslog: running config-rsyslog with frequency once-per-instance 2022-04-11 05:59:40,581 - helpers.py[DEBUG]: config-rsyslog already ran (freq=once-per-instance) 2022-04-11 05:59:40,581 - handlers.py[DEBUG]: finish: init-network/config-rsyslog: SUCCESS: config-rsyslog previously ran 2022-04-11 05:59:40,581 - stages.py[DEBUG]: Running module users-groups () with frequency once-per-instance 2022-04-11 05:59:40,582 - handlers.py[DEBUG]: start: init-network/config-users-groups: running config-users-groups with frequency once-per-instance 2022-04-11 05:59:40,582 - helpers.py[DEBUG]: config-users-groups already ran (freq=once-per-instance) 2022-04-11 05:59:40,582 - handlers.py[DEBUG]: finish: init-network/config-users-groups: SUCCESS: config-users-groups previously ran 2022-04-11 05:59:40,582 - stages.py[DEBUG]: Running module ssh () with frequency once-per-instance 2022-04-11 05:59:40,582 - handlers.py[DEBUG]: start: init-network/config-ssh: running config-ssh with frequency once-per-instance 2022-04-11 05:59:40,582 - helpers.py[DEBUG]: config-ssh already ran (freq=once-per-instance) 2022-04-11 05:59:40,582 - handlers.py[DEBUG]: finish: init-network/config-ssh: SUCCESS: config-ssh previously ran 2022-04-11 05:59:40,582 - main.py[DEBUG]: Ran 15 modules with 0 failures 2022-04-11 05:59:40,582 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmp18zml64w) - w: [644] 540 bytes/chars 2022-04-11 05:59:40,582 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2022-04-11 05:59:40,582 - util.py[DEBUG]: Read 12 bytes from /proc/uptime 2022-04-11 05:59:40,582 - util.py[DEBUG]: cloud-init mode 'init' took 0.210 seconds (0.21) 2022-04-11 05:59:40,582 - handlers.py[DEBUG]: finish: init-network: SUCCESS: searching for network datasources 2022-04-11 05:59:41,273 - util.py[DEBUG]: Cloud-init v. 21.4-0ubuntu1~20.04.1 running 'modules:config' at Mon, 11 Apr 2022 05:59:41 +0000. Up 22.29 seconds. 2022-04-11 05:59:41,287 - stages.py[DEBUG]: Using distro class 2022-04-11 05:59:41,288 - stages.py[DEBUG]: Running module emit_upstart () with frequency always 2022-04-11 05:59:41,288 - handlers.py[DEBUG]: start: modules-config/config-emit_upstart: running config-emit_upstart with frequency always 2022-04-11 05:59:41,288 - helpers.py[DEBUG]: Running config-emit_upstart using lock () 2022-04-11 05:59:41,288 - cc_emit_upstart.py[DEBUG]: no /sbin/initctl located 2022-04-11 05:59:41,288 - cc_emit_upstart.py[DEBUG]: not upstart system, 'emit_upstart' disabled 2022-04-11 05:59:41,288 - handlers.py[DEBUG]: finish: modules-config/config-emit_upstart: SUCCESS: config-emit_upstart ran successfully 2022-04-11 05:59:41,288 - stages.py[DEBUG]: Running module snap () with frequency once-per-instance 2022-04-11 05:59:41,288 - handlers.py[DEBUG]: start: modules-config/config-snap: running config-snap with frequency once-per-instance 2022-04-11 05:59:41,288 - helpers.py[DEBUG]: config-snap already ran (freq=once-per-instance) 2022-04-11 05:59:41,288 - handlers.py[DEBUG]: finish: modules-config/config-snap: SUCCESS: config-snap previously ran 2022-04-11 05:59:41,288 - stages.py[DEBUG]: Running module ssh-import-id () with frequency once-per-instance 2022-04-11 05:59:41,288 - handlers.py[DEBUG]: start: modules-config/config-ssh-import-id: running config-ssh-import-id with frequency once-per-instance 2022-04-11 05:59:41,288 - helpers.py[DEBUG]: config-ssh-import-id already ran (freq=once-per-instance) 2022-04-11 05:59:41,288 - handlers.py[DEBUG]: finish: modules-config/config-ssh-import-id: SUCCESS: config-ssh-import-id previously ran 2022-04-11 05:59:41,289 - stages.py[DEBUG]: Running module locale () with frequency once-per-instance 2022-04-11 05:59:41,289 - handlers.py[DEBUG]: start: modules-config/config-locale: running config-locale with frequency once-per-instance 2022-04-11 05:59:41,289 - helpers.py[DEBUG]: config-locale already ran (freq=once-per-instance) 2022-04-11 05:59:41,289 - handlers.py[DEBUG]: finish: modules-config/config-locale: SUCCESS: config-locale previously ran 2022-04-11 05:59:41,289 - stages.py[DEBUG]: Running module set-passwords () with frequency once-per-instance 2022-04-11 05:59:41,289 - handlers.py[DEBUG]: start: modules-config/config-set-passwords: running config-set-passwords with frequency once-per-instance 2022-04-11 05:59:41,289 - helpers.py[DEBUG]: config-set-passwords already ran (freq=once-per-instance) 2022-04-11 05:59:41,289 - handlers.py[DEBUG]: finish: modules-config/config-set-passwords: SUCCESS: config-set-passwords previously ran 2022-04-11 05:59:41,289 - stages.py[DEBUG]: Running module grub-dpkg () with frequency once-per-instance 2022-04-11 05:59:41,289 - handlers.py[DEBUG]: start: modules-config/config-grub-dpkg: running config-grub-dpkg with frequency once-per-instance 2022-04-11 05:59:41,289 - helpers.py[DEBUG]: config-grub-dpkg already ran (freq=once-per-instance) 2022-04-11 05:59:41,289 - handlers.py[DEBUG]: finish: modules-config/config-grub-dpkg: SUCCESS: config-grub-dpkg previously ran 2022-04-11 05:59:41,289 - stages.py[DEBUG]: Running module apt-pipelining () with frequency once-per-instance 2022-04-11 05:59:41,289 - handlers.py[DEBUG]: start: modules-config/config-apt-pipelining: running config-apt-pipelining with frequency once-per-instance 2022-04-11 05:59:41,289 - helpers.py[DEBUG]: config-apt-pipelining already ran (freq=once-per-instance) 2022-04-11 05:59:41,289 - handlers.py[DEBUG]: finish: modules-config/config-apt-pipelining: SUCCESS: config-apt-pipelining previously ran 2022-04-11 05:59:41,289 - stages.py[DEBUG]: Running module apt-configure () with frequency once-per-instance 2022-04-11 05:59:41,289 - handlers.py[DEBUG]: start: modules-config/config-apt-configure: running config-apt-configure with frequency once-per-instance 2022-04-11 05:59:41,289 - helpers.py[DEBUG]: config-apt-configure already ran (freq=once-per-instance) 2022-04-11 05:59:41,289 - handlers.py[DEBUG]: finish: modules-config/config-apt-configure: SUCCESS: config-apt-configure previously ran 2022-04-11 05:59:41,290 - stages.py[DEBUG]: Running module ubuntu-advantage () with frequency once-per-instance 2022-04-11 05:59:41,290 - handlers.py[DEBUG]: start: modules-config/config-ubuntu-advantage: running config-ubuntu-advantage with frequency once-per-instance 2022-04-11 05:59:41,290 - helpers.py[DEBUG]: config-ubuntu-advantage already ran (freq=once-per-instance) 2022-04-11 05:59:41,290 - handlers.py[DEBUG]: finish: modules-config/config-ubuntu-advantage: SUCCESS: config-ubuntu-advantage previously ran 2022-04-11 05:59:41,290 - stages.py[DEBUG]: Running module ntp () with frequency once-per-instance 2022-04-11 05:59:41,290 - handlers.py[DEBUG]: start: modules-config/config-ntp: running config-ntp with frequency once-per-instance 2022-04-11 05:59:41,290 - helpers.py[DEBUG]: config-ntp already ran (freq=once-per-instance) 2022-04-11 05:59:41,290 - handlers.py[DEBUG]: finish: modules-config/config-ntp: SUCCESS: config-ntp previously ran 2022-04-11 05:59:41,290 - stages.py[DEBUG]: Running module timezone () with frequency once-per-instance 2022-04-11 05:59:41,290 - handlers.py[DEBUG]: start: modules-config/config-timezone: running config-timezone with frequency once-per-instance 2022-04-11 05:59:41,290 - helpers.py[DEBUG]: config-timezone already ran (freq=once-per-instance) 2022-04-11 05:59:41,290 - handlers.py[DEBUG]: finish: modules-config/config-timezone: SUCCESS: config-timezone previously ran 2022-04-11 05:59:41,290 - stages.py[DEBUG]: Running module disable-ec2-metadata () with frequency always 2022-04-11 05:59:41,290 - handlers.py[DEBUG]: start: modules-config/config-disable-ec2-metadata: running config-disable-ec2-metadata with frequency always 2022-04-11 05:59:41,290 - helpers.py[DEBUG]: Running config-disable-ec2-metadata using lock () 2022-04-11 05:59:41,290 - cc_disable_ec2_metadata.py[DEBUG]: Skipping module named disable-ec2-metadata, disabling the ec2 route not enabled 2022-04-11 05:59:41,290 - handlers.py[DEBUG]: finish: modules-config/config-disable-ec2-metadata: SUCCESS: config-disable-ec2-metadata ran successfully 2022-04-11 05:59:41,290 - stages.py[DEBUG]: Running module runcmd () with frequency once-per-instance 2022-04-11 05:59:41,290 - handlers.py[DEBUG]: start: modules-config/config-runcmd: running config-runcmd with frequency once-per-instance 2022-04-11 05:59:41,290 - helpers.py[DEBUG]: config-runcmd already ran (freq=once-per-instance) 2022-04-11 05:59:41,290 - handlers.py[DEBUG]: finish: modules-config/config-runcmd: SUCCESS: config-runcmd previously ran 2022-04-11 05:59:41,290 - stages.py[DEBUG]: Running module byobu () with frequency once-per-instance 2022-04-11 05:59:41,291 - handlers.py[DEBUG]: start: modules-config/config-byobu: running config-byobu with frequency once-per-instance 2022-04-11 05:59:41,291 - helpers.py[DEBUG]: config-byobu already ran (freq=once-per-instance) 2022-04-11 05:59:41,291 - handlers.py[DEBUG]: finish: modules-config/config-byobu: SUCCESS: config-byobu previously ran 2022-04-11 05:59:41,291 - main.py[DEBUG]: Ran 14 modules with 0 failures 2022-04-11 05:59:41,291 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmpa36ktd1c) - w: [644] 567 bytes/chars 2022-04-11 05:59:41,291 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2022-04-11 05:59:41,291 - util.py[DEBUG]: Read 12 bytes from /proc/uptime 2022-04-11 05:59:41,291 - util.py[DEBUG]: cloud-init mode 'modules' took 0.071 seconds (0.07) 2022-04-11 05:59:41,291 - handlers.py[DEBUG]: finish: modules-config: SUCCESS: running modules for config 2022-04-11 05:59:51,138 - util.py[DEBUG]: Cloud-init v. 21.4-0ubuntu1~20.04.1 running 'modules:final' at Mon, 11 Apr 2022 05:59:51 +0000. Up 32.16 seconds. 2022-04-11 05:59:51,158 - stages.py[DEBUG]: Using distro class 2022-04-11 05:59:51,159 - stages.py[DEBUG]: Running module package-update-upgrade-install () with frequency once-per-instance 2022-04-11 05:59:51,159 - handlers.py[DEBUG]: start: modules-final/config-package-update-upgrade-install: running config-package-update-upgrade-install with frequency once-per-instance 2022-04-11 05:59:51,159 - helpers.py[DEBUG]: config-package-update-upgrade-install already ran (freq=once-per-instance) 2022-04-11 05:59:51,159 - handlers.py[DEBUG]: finish: modules-final/config-package-update-upgrade-install: SUCCESS: config-package-update-upgrade-install previously ran 2022-04-11 05:59:51,159 - stages.py[DEBUG]: Running module fan () with frequency once-per-instance 2022-04-11 05:59:51,159 - handlers.py[DEBUG]: start: modules-final/config-fan: running config-fan with frequency once-per-instance 2022-04-11 05:59:51,159 - helpers.py[DEBUG]: config-fan already ran (freq=once-per-instance) 2022-04-11 05:59:51,159 - handlers.py[DEBUG]: finish: modules-final/config-fan: SUCCESS: config-fan previously ran 2022-04-11 05:59:51,159 - stages.py[DEBUG]: Running module landscape () with frequency once-per-instance 2022-04-11 05:59:51,160 - handlers.py[DEBUG]: start: modules-final/config-landscape: running config-landscape with frequency once-per-instance 2022-04-11 05:59:51,160 - helpers.py[DEBUG]: config-landscape already ran (freq=once-per-instance) 2022-04-11 05:59:51,160 - handlers.py[DEBUG]: finish: modules-final/config-landscape: SUCCESS: config-landscape previously ran 2022-04-11 05:59:51,160 - stages.py[DEBUG]: Running module lxd () with frequency once-per-instance 2022-04-11 05:59:51,160 - handlers.py[DEBUG]: start: modules-final/config-lxd: running config-lxd with frequency once-per-instance 2022-04-11 05:59:51,160 - helpers.py[DEBUG]: config-lxd already ran (freq=once-per-instance) 2022-04-11 05:59:51,160 - handlers.py[DEBUG]: finish: modules-final/config-lxd: SUCCESS: config-lxd previously ran 2022-04-11 05:59:51,160 - stages.py[DEBUG]: Running module ubuntu-drivers () with frequency once-per-instance 2022-04-11 05:59:51,160 - handlers.py[DEBUG]: start: modules-final/config-ubuntu-drivers: running config-ubuntu-drivers with frequency once-per-instance 2022-04-11 05:59:51,160 - helpers.py[DEBUG]: config-ubuntu-drivers already ran (freq=once-per-instance) 2022-04-11 05:59:51,160 - handlers.py[DEBUG]: finish: modules-final/config-ubuntu-drivers: SUCCESS: config-ubuntu-drivers previously ran 2022-04-11 05:59:51,160 - stages.py[DEBUG]: Running module write-files-deferred () with frequency once-per-instance 2022-04-11 05:59:51,160 - handlers.py[DEBUG]: start: modules-final/config-write-files-deferred: running config-write-files-deferred with frequency once-per-instance 2022-04-11 05:59:51,160 - helpers.py[DEBUG]: config-write-files-deferred already ran (freq=once-per-instance) 2022-04-11 05:59:51,160 - handlers.py[DEBUG]: finish: modules-final/config-write-files-deferred: SUCCESS: config-write-files-deferred previously ran 2022-04-11 05:59:51,160 - stages.py[DEBUG]: Running module puppet () with frequency once-per-instance 2022-04-11 05:59:51,160 - handlers.py[DEBUG]: start: modules-final/config-puppet: running config-puppet with frequency once-per-instance 2022-04-11 05:59:51,160 - helpers.py[DEBUG]: config-puppet already ran (freq=once-per-instance) 2022-04-11 05:59:51,160 - handlers.py[DEBUG]: finish: modules-final/config-puppet: SUCCESS: config-puppet previously ran 2022-04-11 05:59:51,160 - stages.py[DEBUG]: Running module chef () with frequency always 2022-04-11 05:59:51,161 - handlers.py[DEBUG]: start: modules-final/config-chef: running config-chef with frequency always 2022-04-11 05:59:51,161 - helpers.py[DEBUG]: Running config-chef using lock () 2022-04-11 05:59:51,161 - cc_chef.py[DEBUG]: Skipping module named chef, no 'chef' key in configuration 2022-04-11 05:59:51,161 - handlers.py[DEBUG]: finish: modules-final/config-chef: SUCCESS: config-chef ran successfully 2022-04-11 05:59:51,161 - stages.py[DEBUG]: Running module mcollective () with frequency once-per-instance 2022-04-11 05:59:51,161 - handlers.py[DEBUG]: start: modules-final/config-mcollective: running config-mcollective with frequency once-per-instance 2022-04-11 05:59:51,161 - helpers.py[DEBUG]: config-mcollective already ran (freq=once-per-instance) 2022-04-11 05:59:51,161 - handlers.py[DEBUG]: finish: modules-final/config-mcollective: SUCCESS: config-mcollective previously ran 2022-04-11 05:59:51,161 - stages.py[DEBUG]: Running module salt-minion () with frequency once-per-instance 2022-04-11 05:59:51,161 - handlers.py[DEBUG]: start: modules-final/config-salt-minion: running config-salt-minion with frequency once-per-instance 2022-04-11 05:59:51,161 - helpers.py[DEBUG]: config-salt-minion already ran (freq=once-per-instance) 2022-04-11 05:59:51,161 - handlers.py[DEBUG]: finish: modules-final/config-salt-minion: SUCCESS: config-salt-minion previously ran 2022-04-11 05:59:51,161 - stages.py[DEBUG]: Running module reset_rmc () with frequency once-per-instance 2022-04-11 05:59:51,161 - handlers.py[DEBUG]: start: modules-final/config-reset_rmc: running config-reset_rmc with frequency once-per-instance 2022-04-11 05:59:51,161 - helpers.py[DEBUG]: config-reset_rmc already ran (freq=once-per-instance) 2022-04-11 05:59:51,161 - handlers.py[DEBUG]: finish: modules-final/config-reset_rmc: SUCCESS: config-reset_rmc previously ran 2022-04-11 05:59:51,161 - stages.py[DEBUG]: Running module refresh_rmc_and_interface () with frequency always 2022-04-11 05:59:51,161 - handlers.py[DEBUG]: start: modules-final/config-refresh_rmc_and_interface: running config-refresh_rmc_and_interface with frequency always 2022-04-11 05:59:51,161 - helpers.py[DEBUG]: Running config-refresh_rmc_and_interface using lock () 2022-04-11 05:59:51,162 - cc_refresh_rmc_and_interface.py[DEBUG]: No 'rmcctrl' in path, disabled 2022-04-11 05:59:51,162 - handlers.py[DEBUG]: finish: modules-final/config-refresh_rmc_and_interface: SUCCESS: config-refresh_rmc_and_interface ran successfully 2022-04-11 05:59:51,162 - stages.py[DEBUG]: Running module rightscale_userdata () with frequency once-per-instance 2022-04-11 05:59:51,162 - handlers.py[DEBUG]: start: modules-final/config-rightscale_userdata: running config-rightscale_userdata with frequency once-per-instance 2022-04-11 05:59:51,162 - helpers.py[DEBUG]: config-rightscale_userdata already ran (freq=once-per-instance) 2022-04-11 05:59:51,162 - handlers.py[DEBUG]: finish: modules-final/config-rightscale_userdata: SUCCESS: config-rightscale_userdata previously ran 2022-04-11 05:59:51,162 - stages.py[DEBUG]: Running module scripts-vendor () with frequency once-per-instance 2022-04-11 05:59:51,162 - handlers.py[DEBUG]: start: modules-final/config-scripts-vendor: running config-scripts-vendor with frequency once-per-instance 2022-04-11 05:59:51,162 - helpers.py[DEBUG]: config-scripts-vendor already ran (freq=once-per-instance) 2022-04-11 05:59:51,162 - handlers.py[DEBUG]: finish: modules-final/config-scripts-vendor: SUCCESS: config-scripts-vendor previously ran 2022-04-11 05:59:51,162 - stages.py[DEBUG]: Running module scripts-per-once () with frequency once 2022-04-11 05:59:51,162 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-once: running config-scripts-per-once with frequency once 2022-04-11 05:59:51,162 - helpers.py[DEBUG]: config-scripts-per-once already ran (freq=once) 2022-04-11 05:59:51,162 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-once: SUCCESS: config-scripts-per-once previously ran 2022-04-11 05:59:51,162 - stages.py[DEBUG]: Running module scripts-per-boot () with frequency always 2022-04-11 05:59:51,162 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-boot: running config-scripts-per-boot with frequency always 2022-04-11 05:59:51,162 - helpers.py[DEBUG]: Running config-scripts-per-boot using lock () 2022-04-11 05:59:51,163 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-boot: SUCCESS: config-scripts-per-boot ran successfully 2022-04-11 05:59:51,163 - stages.py[DEBUG]: Running module scripts-per-instance () with frequency once-per-instance 2022-04-11 05:59:51,163 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-instance: running config-scripts-per-instance with frequency once-per-instance 2022-04-11 05:59:51,163 - helpers.py[DEBUG]: config-scripts-per-instance already ran (freq=once-per-instance) 2022-04-11 05:59:51,163 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-instance: SUCCESS: config-scripts-per-instance previously ran 2022-04-11 05:59:51,163 - stages.py[DEBUG]: Running module scripts-user () with frequency once-per-instance 2022-04-11 05:59:51,163 - handlers.py[DEBUG]: start: modules-final/config-scripts-user: running config-scripts-user with frequency once-per-instance 2022-04-11 05:59:51,163 - helpers.py[DEBUG]: config-scripts-user already ran (freq=once-per-instance) 2022-04-11 05:59:51,163 - handlers.py[DEBUG]: finish: modules-final/config-scripts-user: SUCCESS: config-scripts-user previously ran 2022-04-11 05:59:51,163 - stages.py[DEBUG]: Running module ssh-authkey-fingerprints () with frequency once-per-instance 2022-04-11 05:59:51,164 - handlers.py[DEBUG]: start: modules-final/config-ssh-authkey-fingerprints: running config-ssh-authkey-fingerprints with frequency once-per-instance 2022-04-11 05:59:51,164 - helpers.py[DEBUG]: config-ssh-authkey-fingerprints already ran (freq=once-per-instance) 2022-04-11 05:59:51,164 - handlers.py[DEBUG]: finish: modules-final/config-ssh-authkey-fingerprints: SUCCESS: config-ssh-authkey-fingerprints previously ran 2022-04-11 05:59:51,164 - stages.py[DEBUG]: Running module keys-to-console () with frequency once-per-instance 2022-04-11 05:59:51,164 - handlers.py[DEBUG]: start: modules-final/config-keys-to-console: running config-keys-to-console with frequency once-per-instance 2022-04-11 05:59:51,164 - helpers.py[DEBUG]: config-keys-to-console already ran (freq=once-per-instance) 2022-04-11 05:59:51,164 - handlers.py[DEBUG]: finish: modules-final/config-keys-to-console: SUCCESS: config-keys-to-console previously ran 2022-04-11 05:59:51,164 - stages.py[DEBUG]: Running module install-hotplug () with frequency once-per-instance 2022-04-11 05:59:51,164 - handlers.py[DEBUG]: start: modules-final/config-install-hotplug: running config-install-hotplug with frequency once-per-instance 2022-04-11 05:59:51,164 - helpers.py[DEBUG]: config-install-hotplug already ran (freq=once-per-instance) 2022-04-11 05:59:51,164 - handlers.py[DEBUG]: finish: modules-final/config-install-hotplug: SUCCESS: config-install-hotplug previously ran 2022-04-11 05:59:51,164 - stages.py[DEBUG]: Running module phone-home () with frequency once-per-instance 2022-04-11 05:59:51,164 - handlers.py[DEBUG]: start: modules-final/config-phone-home: running config-phone-home with frequency once-per-instance 2022-04-11 05:59:51,164 - helpers.py[DEBUG]: config-phone-home already ran (freq=once-per-instance) 2022-04-11 05:59:51,164 - handlers.py[DEBUG]: finish: modules-final/config-phone-home: SUCCESS: config-phone-home previously ran 2022-04-11 05:59:51,164 - stages.py[DEBUG]: Running module final-message () with frequency always 2022-04-11 05:59:51,164 - handlers.py[DEBUG]: start: modules-final/config-final-message: running config-final-message with frequency always 2022-04-11 05:59:51,164 - helpers.py[DEBUG]: Running config-final-message using lock () 2022-04-11 05:59:51,164 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2022-04-11 05:59:51,165 - util.py[DEBUG]: Read 13 bytes from /proc/uptime 2022-04-11 05:59:51,166 - util.py[DEBUG]: Cloud-init v. 21.4-0ubuntu1~20.04.1 finished at Mon, 11 Apr 2022 05:59:51 +0000. Datasource DataSourceOVF [seed=com.vmware.guestInfo]. Up 32.23 seconds 2022-04-11 05:59:51,166 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/boot-finished - wb: [644] 67 bytes 2022-04-11 05:59:51,167 - handlers.py[DEBUG]: finish: modules-final/config-final-message: SUCCESS: config-final-message ran successfully 2022-04-11 05:59:51,167 - stages.py[DEBUG]: Running module power-state-change () with frequency once-per-instance 2022-04-11 05:59:51,167 - handlers.py[DEBUG]: start: modules-final/config-power-state-change: running config-power-state-change with frequency once-per-instance 2022-04-11 05:59:51,167 - helpers.py[DEBUG]: config-power-state-change already ran (freq=once-per-instance) 2022-04-11 05:59:51,167 - handlers.py[DEBUG]: finish: modules-final/config-power-state-change: SUCCESS: config-power-state-change previously ran 2022-04-11 05:59:51,167 - main.py[DEBUG]: Ran 24 modules with 0 failures 2022-04-11 05:59:51,167 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmp0p9g_5zp) - w: [644] 595 bytes/chars 2022-04-11 05:59:51,167 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/result.json (via temporary file /var/lib/cloud/data/tmpq20zrtcw) - w: [644] 92 bytes/chars 2022-04-11 05:59:51,167 - util.py[DEBUG]: Creating symbolic link from '/run/cloud-init/result.json' => '../../var/lib/cloud/data/result.json' 2022-04-11 05:59:51,167 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False) 2022-04-11 05:59:51,168 - util.py[DEBUG]: Read 13 bytes from /proc/uptime 2022-04-11 05:59:51,168 - util.py[DEBUG]: cloud-init mode 'modules' took 0.081 seconds (0.08) 2022-04-11 05:59:51,168 - handlers.py[DEBUG]: finish: modules-final: SUCCESS: running modules for final ```

betweenclouds commented 2 years ago

/var/log/vmware-imc/toolsDeployPkg.log

``` [2022-04-07T12:31:11.365Z] [ debug] ## Starting deploy pkg operation [2022-04-07T12:31:11.365Z] [ debug] Deploying /var/run/128f7312/imcf-TWzzzt [2022-04-07T12:31:11.365Z] [ info] Initializing deployment module. [2022-04-07T12:31:11.365Z] [ info] Cleaning old state file from tmp directory. [2022-04-07T12:31:11.365Z] [ info] EXIT STATE 'INPROGRESS'. [2022-04-07T12:31:11.365Z] [ debug] Setting deploy error: 'Error removing lock '/tmp/.vmware-deploy.INPROGRESS'.(No such file or directory)'. [2022-04-07T12:31:11.365Z] [ info] EXIT STATE 'Done'. [2022-04-07T12:31:11.365Z] [ debug] Setting deploy error: 'Error removing lock '/tmp/.vmware-deploy.Done'.(No such file or directory)'. [2022-04-07T12:31:11.365Z] [ info] EXIT STATE 'ERRORED'. [2022-04-07T12:31:11.365Z] [ debug] Setting deploy error: 'Error removing lock '/tmp/.vmware-deploy.ERRORED'.(No such file or directory)'. [2022-04-07T12:31:11.365Z] [ debug] Setting deploy error: 'Success.'. [2022-04-07T12:31:11.365Z] [ info] Deploying cabinet file '/var/run/128f7312/imcf-TWzzzt'. [2022-04-07T12:31:11.365Z] [ info] Transitioning from state '(null)' to state 'INPROGRESS'. [2022-04-07T12:31:11.365Z] [ info] ENTER STATE 'INPROGRESS'. [2022-04-07T12:31:11.366Z] [ info] Reading cabinet file '/var/run/128f7312/imcf-TWzzzt' and will extract it to '/var/run/.vmware-imgcust-djZzthS'. [2022-04-07T12:31:11.366Z] [ info] Flags in the header: 0. [2022-04-07T12:31:11.366Z] [ info] Original deployment command: '/usr/bin/perl -I/tmp/.vmware/linux/deploy/scripts /tmp/.vmware/linux/deploy/scripts/Customize.pl /tmp/.vmware/linux/deploy/cust.cfg'. [2022-04-07T12:31:11.366Z] [ info] Actual deployment command: '/usr/bin/perl -I/var/run/.vmware-imgcust-djZzthS/scripts /var/run/.vmware-imgcust-djZzthS/scripts/Customize.pl /var/run/.vmware-imgcust-djZzthS/cust.cfg'. [2022-04-07T12:31:11.366Z] [ info] Extracting package files. [2022-04-07T12:31:11.375Z] [ debug] Check if cust.cfg exists. [2022-04-07T12:31:11.375Z] [ info] cust.cfg is found in '/var/run/.vmware-imgcust-djZzthS' directory. [2022-04-07T12:31:11.375Z] [ debug] Command to exec : '/usr/bin/cloud-init'. [2022-04-07T12:31:11.375Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:11.375Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:11.375Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:11.878Z] [ info] Saving output from stdout [2022-04-07T12:31:11.978Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:11.978Z] [ info] No more output from stdout [2022-04-07T12:31:11.978Z] [ info] No more output from stderr [2022-04-07T12:31:11.978Z] [ info] Customization command output: '/usr/bin/cloud-init 21.4-0ubuntu1~20.04.1 '. [2022-04-07T12:31:11.978Z] [ info] cloud-init is installed. [2022-04-07T12:31:11.978Z] [ info] Checking if cloud.cfg exists and if cloud-init is enabled. [2022-04-07T12:31:11.978Z] [ info] Executing traditional GOSC workflow. [2022-04-07T12:31:11.978Z] [ debug] Command to exec : '/usr/bin/perl'. [2022-04-07T12:31:11.978Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:11.978Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:11.978Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:12.078Z] [ info] Saving output from stdout [2022-04-07T12:31:12.078Z] [ info] Saving output from stdout [2022-04-07T12:31:12.078Z] [ info] Saving output from stdout [2022-04-07T12:31:12.078Z] [ info] Saving output from stdout [2022-04-07T12:31:12.078Z] [ info] Saving output from stdout [2022-04-07T12:31:12.078Z] [ info] Saving output from stdout [2022-04-07T12:31:13.079Z] [ info] Saving output from stdout [2022-04-07T12:31:14.080Z] [ info] Saving output from stdout [2022-04-07T12:31:15.080Z] [ info] Saving output from stdout [2022-04-07T12:31:16.081Z] [ info] Saving output from stdout [2022-04-07T12:31:17.082Z] [ info] Saving output from stdout [2022-04-07T12:31:18.082Z] [ info] Saving output from stdout [2022-04-07T12:31:19.083Z] [ info] Saving output from stdout [2022-04-07T12:31:20.184Z] [ info] Saving output from stdout [2022-04-07T12:31:21.185Z] [ info] Saving output from stdout [2022-04-07T12:31:22.185Z] [ info] Saving output from stdout [2022-04-07T12:31:22.185Z] [ info] Saving output from stdout [2022-04-07T12:31:27.189Z] [ info] Process exited normally after 15 seconds, returned 0 [2022-04-07T12:31:27.189Z] [ info] Saving output from stdout [2022-04-07T12:31:27.189Z] [ info] Saving output from stdout [2022-04-07T12:31:27.189Z] [ info] Saving output from stdout [2022-04-07T12:31:27.189Z] [ info] No more output from stdout [2022-04-07T12:31:27.189Z] [ info] No more output from stderr [2022-04-07T12:31:27.189Z] [ info] Customization command output: 'DEBUG: Creating directory /var/lock/vmware DEBUG: Opening /var/lock/vmware/gosc in O_CREAT|O_EXCL|O_WRONLY mode INFO: Opening file name /var/run/.vmware-imgcust-djZzthS/cust.cfg. DEBUG: Processing line: '[NETWORK]' DEBUG: FOUND CATEGORY = NETWORK DEBUG: Processing line: 'NETWORKING = yes' DEBUG: ADDED KEY-VAL :: 'NETWORK|NETWORKING' = 'yes' DEBUG: Processing line: 'BOOTPROTO = dhcp' DEBUG: ADDED KEY-VAL :: 'NETWORK|BOOTPROTO' = 'dhcp' DEBUG: Processing line: 'HOSTNAME = myvm-01' DEBUG: ADDED KEY-VAL :: 'NETWORK|HOSTNAME' = 'myvm-01' DEBUG: Processing line: '' DEBUG: Empty line. Ignored. DEBUG: Processing line: '[NIC-CONFIG]' DEBUG: FOUND CATEGORY = NIC-CONFIG DEBUG: Processing line: 'NICS = NIC1' DEBUG: ADDED KEY-VAL :: 'NIC-CONFIG|NICS' = 'NIC1' DEBUG: Processing line: '' DEBUG: Empty line. Ignored. DEBUG: Processing line: '[NIC1]' DEBUG: FOUND CATEGORY = NIC1 DEBUG: Processing line: 'MACADDR = 00:50:56:a5:f6:80' DEBUG: ADDED KEY-VAL :: 'NIC1|MACADDR' = '00:50:56:a5:f6:80' DEBUG: Processing line: 'PRIMARY = yes' DEBUG: ADDED KEY-VAL :: 'NIC1|PRIMARY' = 'yes' DEBUG: Processing line: 'ONBOOT = yes' DEBUG: ADDED KEY-VAL :: 'NIC1|ONBOOT' = 'yes' DEBUG: Processing line: 'IPv4_MODE = BACKWARDS_COMPATIBLE' DEBUG: ADDED KEY-VAL :: 'NIC1|IPv4_MODE' = 'BACKWARDS_COMPATIBLE' DEBUG: Processing line: 'BOOTPROTO = static' DEBUG: ADDED KEY-VAL :: 'NIC1|BOOTPROTO' = 'static' DEBUG: Processing line: 'IPADDR = 172.31.169.24' DEBUG: ADDED KEY-VAL :: 'NIC1|IPADDR' = '172.31.169.24' DEBUG: Processing line: 'NETMASK = 255.255.255.224' DEBUG: ADDED KEY-VAL :: 'NIC1|NETMASK' = '255.255.255.224' DEBUG: Processing line: 'GATEWAY = 172.31.169.1' DEBUG: ADDED KEY-VAL :: 'NIC1|GATEWAY' = '172.31.169.1' DEBUG: Processing line: '' DEBUG: Empty line. Ignored. DEBUG: Processing line: '' DEBUG: Empty line. Ignored. DEBUG: Processing line: '[DNS]' DEBUG: FOUND CATEGORY = DNS DEBUG: Processing line: 'DNSFROMDHCP=no' DEBUG: ADDED KEY-VAL :: 'DNS|DNSFROMDHCP' = 'no' DEBUG: Processing line: 'SUFFIX|1 = mydomain.com' DEBUG: ADDED KEY-VAL :: 'DNS|SUFFIX|1' = 'mydomain.com' DEBUG: Processing line: 'NAMESERVER|1 = 10.233.1.12' DEBUG: ADDED KEY-VAL :: 'DNS|NAMESERVER|1' = '10.233.1.12' DEBUG: Processing line: 'NAMESERVER|2 = 10.233.1.2' DEBUG: ADDED KEY-VAL :: 'DNS|NAMESERVER|2' = '10.233.1.2' DEBUG: Reading issue file ... DEBUG: Command: 'cat /etc/issue' DEBUG: Result: Ubuntu 20.04.4 LTS \n \l DEBUG: Exit Code: 0 DEBUG: Reading /etc/os-release file ... DEBUG: opening file /etc/os-release. DEBUG: Match found : Line = PRETTY_NAME="Ubuntu 20.04.4 LTS" DEBUG: Actual String : "Ubuntu 20.04.4 LTS" DEBUG: Reading issue file ... DEBUG: Command: 'cat /etc/issue' DEBUG: Result: Ubuntu 20.04.4 LTS \n \l DEBUG: Exit Code: 0 DEBUG: Ubuntu 20.04.4 LTS \n \l DEBUG: Reading /etc/os-release file ... DEBUG: opening file /etc/os-release. DEBUG: Match found : Line = ID=ubuntu DEBUG: Actual String : ubuntu DEBUG: ID: ubuntu DEBUG: opening file /etc/os-release. DEBUG: Match found : Line = VERSION_ID="20.04" DEBUG: Actual String : "20.04" DEBUG: Version: "20.04" WARNING: Amazon Linux flavor not detected DEBUG: Reading issue file ... DEBUG: Command: 'cat /etc/issue' DEBUG: Result: Ubuntu 20.04.4 LTS \n \l DEBUG: Exit Code: 0 DEBUG: Ubuntu 20.04.4 LTS \n \l WARNING: RedHat release file not available. Ignoring it. WARNING: Redhat flavor not detected DEBUG: Reading issue file ... DEBUG: Command: 'cat /etc/issue' DEBUG: Result: Ubuntu 20.04.4 LTS \n \l DEBUG: Exit Code: 0 DEBUG: Ubuntu 20.04.4 LTS \n \l WARNING: RedHat release file not available. Ignoring it. WARNING: Redhat flavor not detected DEBUG: Command: 'cat /etc/lsb-release' DEBUG: Result: DISTRIB_ID=Ubuntu DISTRIB_RELEASE=20.04 DISTRIB_CODENAME=focal DISTRIB_DESCRIPTION="Ubuntu 20.04.4 LTS" DEBUG: Exit Code: 0 DEBUG: Command: 'cat /etc/issue' DEBUG: Result: Ubuntu 20.04.4 LTS \n \l DEBUG: Exit Code: 0 DEBUG: Command: 'cat /etc/issue' DEBUG: Result: Ubuntu 20.04.4 LTS \n \l DEBUG: Exit Code: 0 DEBUG: Reading issue file ... DEBUG: Command: 'cat /etc/issue' DEBUG: Result: Ubuntu 20.04.4 LTS \n \l DEBUG: Exit Code: 0 DEBUG: Ubuntu 20.04.4 LTS \n \l INFO: Detected distribution: Ubuntu 20.04 DEBUG: Reading issue file ... DEBUG: Command: 'cat /etc/issue' DEBUG: Result: Ubuntu 20.04.4 LTS \n \l DEBUG: Exit Code: 0 DEBUG: Ubuntu 20.04.4 LTS \n \l INFO: Detected distribution flavour: Ubuntu 20.04 INFO: Customization instance Ubuntu1910Customization loaded. INFO: Customization started DEBUG: Command: 'hostname 2>/dev/null' DEBUG: Result: ubuntu DEBUG: Exit Code: 0 DEBUG: TimedCommand: 'hostname -f 2>/dev/null' with timeout of 5 sec DEBUG: Fetching result from /tmp/timed_out_tmp_file_678 DEBUG: TimedResult: DEBUG: opening file /etc/hostname. DEBUG: Match found : Line = ubuntu DEBUG: Actual String : ubuntu INFO: OLD HOST NAME = ubuntu INFO: Marker file exists or is undefined, pre-customization is not needed INFO: Customizing Network settings ... INFO: Erasing DHCP leases DEBUG: Command: 'pkill dhclient' DEBUG: Result: DEBUG: Exit Code: 256 DEBUG: Command: 'rm -f /var/lib/dhcp/*' DEBUG: Result: DEBUG: Exit Code: 0 DEBUG: Check if command [hostnamectl] is available INFO: Check if hostnamectl is available DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr' DEBUG: Result: DEBUG: Exit Code: 256 DEBUG: Stderr: Failed to create bus connection: No such file or directory INFO: Check if hostnamectl is available DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr' DEBUG: Result: DEBUG: Exit Code: 256 DEBUG: Stderr: Failed to create bus connection: No such file or directory INFO: Check if hostnamectl is available DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr' DEBUG: Result: DEBUG: Exit Code: 256 DEBUG: Stderr: Failed to create bus connection: No such file or directory INFO: Check if hostnamectl is available DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr' DEBUG: Result: DEBUG: Exit Code: 256 DEBUG: Stderr: Failed to create bus connection: No such file or directory INFO: Check if hostnamectl is available DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr' DEBUG: Result: DEBUG: Exit Code: 256 DEBUG: Stderr: Failed to create bus connection: No such file or directory INFO: Check if hostnamectl is available DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr' DEBUG: Result: DEBUG: Exit Code: 256 DEBUG: Stderr: Failed to create bus connection: No such file or directory INFO: Check if hostnamectl is available DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr' DEBUG: Result: DEBUG: Exit Code: 256 DEBUG: Stderr: Failed to create bus connection: No such file or directory INFO: Check if hostnamectl is available DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr' DEBUG: Result: DEBUG: Exit Code: 256 DEBUG: Stderr: Failed to create bus connection: No such file or directory INFO: Check if hostnamectl is available DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr' DEBUG: Result: DEBUG: Exit Code: 256 DEBUG: Stderr: Failed to create bus connection: No such file or directory INFO: Check if hostnamectl is available DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr' DEBUG: Result: DEBUG: Exit Code: 256 DEBUG: Stderr: Failed to create bus connection: No such file or directory DEBUG: Host name is myvm-01 DEBUG: opening file for writing (/etc/hostname). DEBUG: Command: 'chmod 644 /etc/hostname' DEBUG: Result: DEBUG: Exit Code: 0 INFO: Customizing NICS ... INFO: Customizing NICS. { NIC1 } INFO: Customizing NIC NIC1 DEBUG: Get interface name for MAC 00:50:56:a5:f6:80, via [ip addr show] DEBUG: Command: 'whereis ip' DEBUG: Result: ip: /usr/bin/ip /usr/sbin/ip /usr/share/man/man7/ip.7.gz /usr/share/man/man8/ip.8.gz DEBUG: Exit Code: 0 DEBUG: Command: '/usr/bin/ip addr show' DEBUG: Result: 1: lo: mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000 link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00 inet 127.0.0.1/8 scope host lo valid_lft forever preferred_lft forever inet6 ::1/128 scope host valid_lft forever preferred_lft forever 2: ens192: mtu 1500 qdisc noop state DOWN group default qlen 1000 link/ether 00:50:56:a5:f6:80 brd ff:ff:ff:ff:ff:ff DEBUG: Exit Code: 0 INFO: NIC suffix = ens192 INFO: Query config for ^(NIC1\|IPv6ADDR\|) INFO: Query config for ^(NIC1\|IPv6NETMASK\|) INFO: Configuring gateway from the primary NIC 'NIC1'. INFO: Query config for ^NIC1(\|IPv6GATEWAY\|) INFO: Query config for ^(DNS\|SUFFIX\|) DEBUG: Match Found : DNS|SUFFIX|1 DEBUG: 0 INFO: Query config for ^(DNS\|NAMESERVER\|) DEBUG: Match Found : DNS|NAMESERVER|1 DEBUG: 0 DEBUG: Match Found : DNS|NAMESERVER|2 DEBUG: 1 DEBUG: opening file for writing (/etc/netplan/99-netcfg-vmware.yaml). DEBUG: Command: 'chmod 644 /etc/netplan/99-netcfg-vmware.yaml' DEBUG: Result: DEBUG: Exit Code: 0 INFO: Apply Netplan Settings DEBUG: Command: '/usr/sbin/netplan apply 2>&1' DEBUG: Result: inactive Warning: The unit file, source configuration file or drop-ins of netplan-ovs-cleanup.service changed on disk. Run 'systemctl daemon-reload' to reload units. DEBUG: Exit Code: 0 INFO: Customizing Hosts file ... DEBUG: Old hostname=[ubuntu] DEBUG: Old FQDN=[] DEBUG: New hostname=[myvm-01] DEBUG: Building FQDN. HostnameFQDN: myvm-01, Domainname: DEBUG: New FQDN=[myvm-01] DEBUG: opening file /etc/hosts. DEBUG: Line (inp): 127.0.0.1 localhost DEBUG: Line (inp): DEBUG: Line (inp): # The following lines are desirable for IPv6 capable hosts DEBUG: Line (inp): ::1 ip6-localhost ip6-loopback DEBUG: Line (inp): fe00::0 ip6-localnet DEBUG: Line (inp): ff00::0 ip6-mcastprefix DEBUG: Line (inp): ff02::1 ip6-allnodes DEBUG: Line (inp): ff02::2 ip6-allrouters DEBUG: Line (inp): ff02::3 ip6-allhosts DEBUG: Static ip entry added DEBUG: Line (out): 127.0.0.1 localhost DEBUG: Line (out): DEBUG: Line (out): # The following lines are desirable for IPv6 capable hosts DEBUG: Line (out): ::1 ip6-localhost ip6-loopback DEBUG: Line (out): fe00::0 ip6-localnet DEBUG: Line (out): ff00::0 ip6-mcastprefix DEBUG: Line (out): ff02::1 ip6-allnodes DEBUG: Line (out): ff02::2 ip6-allrouters DEBUG: Line (out): ff02::3 ip6-allhosts DEBUG: Line (out): 172.31.169.24 myvm-01 DEBUG: opening file for writing (/etc/hosts). DEBUG: Command: 'chmod 644 /etc/hosts' DEBUG: Result: DEBUG: Exit Code: 0 INFO: Customizing DNS ... DEBUG: opening file /etc/nsswitch.conf. DEBUG: opening file for writing (/etc/nsswitch.conf). DEBUG: Command: 'chmod 644 /etc/nsswitch.conf' DEBUG: Result: DEBUG: Exit Code: 0 INFO: Leave /etc/resolv.conf unchanged. INFO: Query config for ^(DNS\|SUFFIX\|) DEBUG: Match Found : DNS|SUFFIX|1 DEBUG: 0 DEBUG: opening file for writing (/etc/dhcp/dhclient.conf). DEBUG: Command: 'chmod 644 /etc/dhcp/dhclient.conf' DEBUG: Result: DEBUG: Exit Code: 0 INFO: Query config for ^(DNS\|NAMESERVER\|) DEBUG: Match Found : DNS|NAMESERVER|1 DEBUG: 0 DEBUG: Match Found : DNS|NAMESERVER|2 DEBUG: 1 DEBUG: opening file for writing (/etc/dhcp/dhclient.conf). DEBUG: Command: 'chmod 644 /etc/dhcp/dhclient.conf' DEBUG: Result: DEBUG: Exit Code: 0 INFO: Customizing Date&Time ... INFO: Marker file exists or is undefined, password settings are not needed INFO: Marker file exists or is undefined, post-customization is not needed INFO: Marker creation is not needed INFO: Customization completed. DEBUG: Removing lock file /var/lock/vmware/gosc. '. [2022-04-07T12:31:32.189Z] [ info] Wait before set enable-nics stats in vmx. [2022-04-07T12:31:32.189Z] [ debug] Trying to connect network interfaces, attempt 1. [2022-04-07T12:31:32.190Z] [ debug] Got VMX response 'queryNicsSupported'. [2022-04-07T12:31:32.190Z] [ debug] Got VMX response 'disconnected'. [2022-04-07T12:31:33.191Z] [ debug] Got VMX response 'connected'. [2022-04-07T12:31:33.191Z] [ info] The network interfaces are connected on 1 second. [2022-04-07T12:31:35.194Z] [ info] Transitioning from state 'INPROGRESS' to state 'Done'. [2022-04-07T12:31:35.194Z] [ info] ENTER STATE 'Done'. [2022-04-07T12:31:35.194Z] [ info] EXIT STATE 'INPROGRESS'. [2022-04-07T12:31:35.194Z] [ info] Deployment succeeded. [2022-04-07T12:31:35.194Z] [ info] Launching cleanup. [2022-04-07T12:31:35.194Z] [ debug] Command to exec : '/bin/rm'. [2022-04-07T12:31:35.194Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:35.194Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:35.194Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:35.294Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:35.294Z] [ info] No more output from stdout [2022-04-07T12:31:35.294Z] [ info] No more output from stderr [2022-04-07T12:31:35.294Z] [ info] Customization command output: ''. [2022-04-07T12:31:35.294Z] [ info] sSkipReboot: 'false', forceSkipReboot 'false'. [2022-04-07T12:31:35.295Z] [ debug] Ran DeployPkg_DeployPackageFromFile successfully [2022-04-07T12:31:35.295Z] [ debug] ## Closing log [2022-04-07T12:31:35.295Z] [ info] Trigger reboot. [2022-04-07T12:31:35.295Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:35.295Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:35.295Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:35.295Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:35.395Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:35.395Z] [ info] No more output from stdout [2022-04-07T12:31:35.395Z] [ info] No more output from stderr [2022-04-07T12:31:35.395Z] [ info] Customization command output: ''. [2022-04-07T12:31:36.395Z] [ info] Rebooting. [2022-04-07T12:31:36.395Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:36.395Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:36.395Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:36.395Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:36.495Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:36.495Z] [ info] No more output from stdout [2022-04-07T12:31:36.495Z] [ info] No more output from stderr [2022-04-07T12:31:36.495Z] [ info] Customization command output: ''. [2022-04-07T12:31:37.496Z] [ info] Rebooting. [2022-04-07T12:31:37.496Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:37.496Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:37.496Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:37.496Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:37.596Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:37.596Z] [ info] No more output from stdout [2022-04-07T12:31:37.596Z] [ info] No more output from stderr [2022-04-07T12:31:37.596Z] [ info] Customization command output: ''. [2022-04-07T12:31:38.596Z] [ info] Rebooting. [2022-04-07T12:31:38.596Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:38.596Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:38.596Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:38.596Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:38.696Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:38.696Z] [ info] No more output from stdout [2022-04-07T12:31:38.696Z] [ info] No more output from stderr [2022-04-07T12:31:38.696Z] [ info] Customization command output: ''. [2022-04-07T12:31:39.697Z] [ info] Rebooting. [2022-04-07T12:31:39.697Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:39.697Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:39.697Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:39.697Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:39.797Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:39.797Z] [ info] No more output from stdout [2022-04-07T12:31:39.797Z] [ info] No more output from stderr [2022-04-07T12:31:39.797Z] [ info] Customization command output: ''. [2022-04-07T12:31:40.797Z] [ info] Rebooting. [2022-04-07T12:31:40.797Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:40.797Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:40.797Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:40.797Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:40.897Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:40.897Z] [ info] No more output from stdout [2022-04-07T12:31:40.897Z] [ info] No more output from stderr [2022-04-07T12:31:40.897Z] [ info] Customization command output: ''. [2022-04-07T12:31:41.897Z] [ info] Rebooting. [2022-04-07T12:31:41.897Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:41.897Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:41.898Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:41.898Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:41.998Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:41.998Z] [ info] No more output from stdout [2022-04-07T12:31:41.998Z] [ info] No more output from stderr [2022-04-07T12:31:41.998Z] [ info] Customization command output: ''. [2022-04-07T12:31:42.998Z] [ info] Rebooting. [2022-04-07T12:31:42.998Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:42.998Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:42.998Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:42.998Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:43.098Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:43.098Z] [ info] No more output from stdout [2022-04-07T12:31:43.098Z] [ info] No more output from stderr [2022-04-07T12:31:43.098Z] [ info] Customization command output: ''. [2022-04-07T12:31:44.098Z] [ info] Rebooting. [2022-04-07T12:31:44.098Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:44.098Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:44.099Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:44.099Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:44.199Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:44.199Z] [ info] No more output from stdout [2022-04-07T12:31:44.199Z] [ info] No more output from stderr [2022-04-07T12:31:44.199Z] [ info] Customization command output: ''. [2022-04-07T12:31:45.199Z] [ info] Rebooting. [2022-04-07T12:31:45.199Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:45.199Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:45.199Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:45.199Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:45.299Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:45.299Z] [ info] No more output from stdout [2022-04-07T12:31:45.299Z] [ info] No more output from stderr [2022-04-07T12:31:45.299Z] [ info] Customization command output: ''. [2022-04-07T12:31:46.299Z] [ info] Rebooting. [2022-04-07T12:31:46.299Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:46.299Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:46.299Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:46.299Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:46.399Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:46.399Z] [ info] No more output from stdout [2022-04-07T12:31:46.399Z] [ info] No more output from stderr [2022-04-07T12:31:46.400Z] [ info] Customization command output: ''. [2022-04-07T12:31:47.400Z] [ info] Rebooting. [2022-04-07T12:31:47.400Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:47.400Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:47.400Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:47.400Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:47.500Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:47.500Z] [ info] No more output from stdout [2022-04-07T12:31:47.500Z] [ info] No more output from stderr [2022-04-07T12:31:47.500Z] [ info] Customization command output: ''. [2022-04-07T12:31:48.500Z] [ info] Rebooting. [2022-04-07T12:31:48.500Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:48.500Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:48.500Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:48.500Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:48.600Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:48.600Z] [ info] No more output from stdout [2022-04-07T12:31:48.600Z] [ info] No more output from stderr [2022-04-07T12:31:48.600Z] [ info] Customization command output: ''. [2022-04-07T12:31:49.600Z] [ info] Rebooting. [2022-04-07T12:31:49.600Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:49.600Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:49.601Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:49.601Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:49.701Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:49.701Z] [ info] No more output from stdout [2022-04-07T12:31:49.701Z] [ info] No more output from stderr [2022-04-07T12:31:49.701Z] [ info] Customization command output: ''. [2022-04-07T12:31:50.701Z] [ info] Rebooting. [2022-04-07T12:31:50.701Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:50.701Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:50.701Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:50.701Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:50.801Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:50.801Z] [ info] No more output from stdout [2022-04-07T12:31:50.801Z] [ info] No more output from stderr [2022-04-07T12:31:50.801Z] [ info] Customization command output: ''. [2022-04-07T12:31:51.801Z] [ info] Rebooting. [2022-04-07T12:31:51.801Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:51.801Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:51.801Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:51.801Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:51.901Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:51.901Z] [ info] No more output from stdout [2022-04-07T12:31:51.901Z] [ info] No more output from stderr [2022-04-07T12:31:51.901Z] [ info] Customization command output: ''. [2022-04-07T12:31:52.902Z] [ info] Rebooting. [2022-04-07T12:31:52.902Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:52.902Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:52.902Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:52.902Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:53.002Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:53.002Z] [ info] No more output from stdout [2022-04-07T12:31:53.002Z] [ info] No more output from stderr [2022-04-07T12:31:53.002Z] [ info] Customization command output: ''. [2022-04-07T12:31:54.002Z] [ info] Rebooting. [2022-04-07T12:31:54.002Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:54.002Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:54.002Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:54.002Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:54.102Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:54.102Z] [ info] No more output from stdout [2022-04-07T12:31:54.102Z] [ info] No more output from stderr [2022-04-07T12:31:54.102Z] [ info] Customization command output: ''. [2022-04-07T12:31:55.102Z] [ info] Rebooting. [2022-04-07T12:31:55.102Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:55.102Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:55.103Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:55.103Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:55.203Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:55.203Z] [ info] No more output from stdout [2022-04-07T12:31:55.203Z] [ info] No more output from stderr [2022-04-07T12:31:55.203Z] [ info] Customization command output: ''. [2022-04-07T12:31:56.203Z] [ info] Rebooting. [2022-04-07T12:31:56.203Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:56.203Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:56.203Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:56.203Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:56.303Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:56.303Z] [ info] No more output from stdout [2022-04-07T12:31:56.303Z] [ info] No more output from stderr [2022-04-07T12:31:56.303Z] [ info] Customization command output: ''. [2022-04-07T12:31:57.303Z] [ info] Rebooting. [2022-04-07T12:31:57.303Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:57.303Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:57.303Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:57.303Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:57.403Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:57.403Z] [ info] No more output from stdout [2022-04-07T12:31:57.403Z] [ info] No more output from stderr [2022-04-07T12:31:57.403Z] [ info] Customization command output: ''. [2022-04-07T12:31:58.404Z] [ info] Rebooting. [2022-04-07T12:31:58.404Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:58.404Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:58.404Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:58.404Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:58.504Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:58.504Z] [ info] No more output from stdout [2022-04-07T12:31:58.504Z] [ info] No more output from stderr [2022-04-07T12:31:58.504Z] [ info] Customization command output: ''. [2022-04-07T12:31:59.504Z] [ info] Rebooting. [2022-04-07T12:31:59.504Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:31:59.504Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:31:59.504Z] [ info] Returning, pending output from stdout [2022-04-07T12:31:59.504Z] [ info] Returning, pending output from stderr [2022-04-07T12:31:59.604Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:31:59.604Z] [ info] No more output from stdout [2022-04-07T12:31:59.604Z] [ info] No more output from stderr [2022-04-07T12:31:59.604Z] [ info] Customization command output: ''. [2022-04-07T12:32:00.604Z] [ info] Rebooting. [2022-04-07T12:32:00.604Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:32:00.604Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:32:00.605Z] [ info] Returning, pending output from stdout [2022-04-07T12:32:00.605Z] [ info] Returning, pending output from stderr [2022-04-07T12:32:00.705Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:32:00.705Z] [ info] No more output from stdout [2022-04-07T12:32:00.705Z] [ info] No more output from stderr [2022-04-07T12:32:00.705Z] [ info] Customization command output: ''. [2022-04-07T12:32:01.705Z] [ info] Rebooting. [2022-04-07T12:32:01.705Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:32:01.705Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:32:01.705Z] [ info] Returning, pending output from stdout [2022-04-07T12:32:01.705Z] [ info] Returning, pending output from stderr [2022-04-07T12:32:01.805Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:32:01.805Z] [ info] No more output from stdout [2022-04-07T12:32:01.805Z] [ info] No more output from stderr [2022-04-07T12:32:01.805Z] [ info] Customization command output: ''. [2022-04-07T12:32:02.805Z] [ info] Rebooting. [2022-04-07T12:32:02.806Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:32:02.806Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:32:02.806Z] [ info] Returning, pending output from stdout [2022-04-07T12:32:02.806Z] [ info] Returning, pending output from stderr [2022-04-07T12:32:02.906Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:32:02.906Z] [ info] No more output from stdout [2022-04-07T12:32:02.906Z] [ info] No more output from stderr [2022-04-07T12:32:02.906Z] [ info] Customization command output: ''. [2022-04-07T12:32:03.906Z] [ info] Rebooting. [2022-04-07T12:32:03.906Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:32:03.906Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:32:03.906Z] [ info] Returning, pending output from stdout [2022-04-07T12:32:03.906Z] [ info] Returning, pending output from stderr [2022-04-07T12:32:04.006Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:32:04.006Z] [ info] No more output from stdout [2022-04-07T12:32:04.006Z] [ info] No more output from stderr [2022-04-07T12:32:04.006Z] [ info] Customization command output: ''. [2022-04-07T12:32:05.006Z] [ info] Rebooting. [2022-04-07T12:32:05.006Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:32:05.006Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:32:05.007Z] [ info] Returning, pending output from stdout [2022-04-07T12:32:05.007Z] [ info] Returning, pending output from stderr [2022-04-07T12:32:05.107Z] [ info] Process exited normally after 0 seconds, returned 0 [2022-04-07T12:32:05.107Z] [ info] No more output from stdout [2022-04-07T12:32:05.107Z] [ info] No more output from stderr [2022-04-07T12:32:05.107Z] [ info] Customization command output: ''. [2022-04-07T12:32:05.536Z] [ info] Rebooting. [2022-04-07T12:32:05.536Z] [ debug] Command to exec : '/sbin/telinit'. [2022-04-07T12:32:05.536Z] [ info] sizeof ProcessInternal is 56 [2022-04-07T12:32:05.536Z] [ info] Returning, pending output from stdout [2022-04-07T12:32:05.536Z] [ info] Returning, pending output from stderr [2022-04-07T12:32:05.636Z] [ info] Process exited normally after 0 seconds, returned 1 [2022-04-07T12:32:05.636Z] [ info] No more output from stdout [2022-04-07T12:32:05.636Z] [ info] Saving output from stderr [2022-04-07T12:32:05.636Z] [ info] No more output from stderr [2022-04-07T12:32:05.636Z] [ info] Customization command output: ''. [2022-04-07T12:32:05.636Z] [ error] Customization command failed with exitcode: 1, stderr: 'Failed to connect to bus: Connection refused Failed to open initctl fifo: No such device or address Failed to talk to init daemon. '. [2022-04-07T12:32:06.636Z] [ info] Reboot has been triggered. [2022-04-07T12:32:06.636Z] [ debug] Ran DeployPkg_DeployPackageFromFile successfully [2022-04-07T12:32:06.636Z] [ debug] ## Closing log ```

cloud-init-logs-2022-04-11.tar.gz

PengpengSun commented 2 years ago

@betweenclouds Thanks for the detailed logs. In short words, using gosc and cloud-init at the same boot will create conflict. In your case, the mandatory reboot in gosc terminated cloud-init execution, and gosc hostname set was blocked by cloud-init services.

Details per logs: gosc started at 12:31:11.365

[2022-04-07T12:31:11.365Z] [ debug] ## Starting deploy pkg operation

cloud-init started at 12:31:11,877

2022-04-07 12:31:11,877 - util.py[DEBUG]: Cloud-init v. 21.4-0ubuntu1~20.04.1 running 'init-local' at Thu, 07 Apr 2022 12:31:11 +0000. Up 4.93 seconds.

gosc failed to call hostnamectl to set hostname, hostnamectl depends on dbus.service which did NOT start at that time due to blocked by cloud-init.service

INFO: Check if hostnamectl is available DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr' DEBUG: Result: DEBUG: Exit Code: 256 DEBUG: Stderr: Failed to create bus connection: No such file or directory

gosc triggered reboot at 12:31:35.295

[2022-04-07T12:31:35.295Z] [ info] Trigger reboot.

cloud-init was terminated and then started from beginning after reboot from 12:31:34,738 to 12:32:12,665

2022-04-07 12:31:34,738 - handlers.py[DEBUG]: finish: init-network: SUCCESS: searching for network datasources 2022-04-07 12:32:12,665 - util.py[DEBUG]: Cloud-init v. 21.4-0ubuntu1~20.04.1 running 'init-local' at Thu, 07 Apr 2022 12:32:12 +0000. Up 4.68 seconds.

Solution I understand you are using a cloud image, a user and it's ssh key must be set by cloud-init at the first boot. so I suggest you split the cloud-init and gosc to 2 boots, I have not verified this solution in real testbed, you can check if it fulfills your workflow or not. ex: // power-on MY_VM_01 without gosc, cloud-init will process data from guestinfo.ovfEnv govc vm.clone -vm ubuntu-focal-20.04-cloudimg -ds=MY_DS -pool=/MYDC/host/MYCLUSTER -folder=/MYFOLDER -on=false MY_VM_01 govc vm.network.change -vm MY_VM_01 -net=MYNETWORK ethernet-0 govc vm.change -vm MY_VM_01 -f guestinfo.ovfEnv="env.xml" govc vm.power -on MY_VM_01

// sleep some seconds here or detect if cloud-init finish by check 'cloud-init status', see https://cloudinit.readthedocs.io/en/latest/topics/cli.html code to sleep or do the detection

//power-off VM govc vm.power -off MY_VM_01 //unset data in guestinfo.ovfEnv to prevent cloud-init running. govc vm.change -vm MY_VM_01 -f guestinfo.ovfEnv="" //do gosc govc vm.customize -vm MY_VM_01 -ip 192.168.1.10 -netmask 255.255.255.0 -gateway=192.168.1.1 -dns-server=192.168.1.100,192.168.1.101 -dns-suffix=mydomain.io //At the second boot, only gosc executes and will set hostname and ip correctly. govc vm.power -on MY_VM_01

PengpengSun commented 2 years ago

And you don't need write 'disable_vmware_customization: false' to a cloud-init config file, it will make gosc go to cloud-init workflow, so the user data could just be:

#cloud-config
groups:
  - docker
users:
  - default
  - name: ubuntu
    ssh-authorized-keys:
      - ssh-rsa AAAA...
    sudo: ALL=(ALL) NOPASSWD:ALL
    groups: sudo, docker
    shell: /bin/bash

betweenclouds commented 2 years ago

@PengpengSun Thank you for your detailed analysis and explanation, I appreciate this.

I already tried the "two step" method and this works, but it needs more interaction and on some use-cases its only doable with some workarounds.

Just for my understanding: Is there no way to make gosc wait until cloud-init finishes and then do the reboot? On some docs I read about the "customization script" (https://kb.vmware.com/s/article/74880). Can this be a way to wait after or before gosc? Is this script supplied only trough VCenter or is it possible to set this like the user-data with a guestinfo var? If you set some data (ip, hostname,...) for gosc, how get the OS and the vmware tools this settings, also by the guestinfo vars?

xiaofengw-vmware commented 2 years ago

@PengpengSun Thank you for your detailed analysis and explanation, I appreciate this.

I already tried the "two step" method and this works, but it needs more interaction and on some use-cases its only doable with some workarounds.

Just for my understanding: Is there no way to make gosc wait until cloud-init finishes and then do the reboot? On some docs I read about the "customization script" (https://kb.vmware.com/s/article/74880). Can this be a way to wait after or before gosc? Is this script supplied only trough VCenter or is it possible to set this like the user-data with a guestinfo var? If you set some data (ip, hostname,...) for gosc, how get the OS and the vmware tools this settings, also by the guestinfo vars?

The "customization script" feature is supported from vSphere 7.0, so you couldn't leverage this as a solution on vCenter 6.7 build. If you could upgrade to 7.0, you could add your own codes as "customization script" to wait until cloud-init is finished. The cloud-init status could be checked via command "cloud-init status", the output of the command is either "status: running" or "status: done". There is no way to launch cloud-init after gosc is finished in the same boot. This script could only be set from vCenter. vCenter will generate a configuration file including ip, hostname, customization script etc and upload it to the target VM. Once the VM is powered on, it will read from the configuration file and apply the settings to the VM.

xiaofengw-vmware commented 2 years ago

@betweenclouds If you want to apply the static ip settings and user data to your VM, there is another choice. From cloud-init 21.3, there is a new data source named "DataSourceVMware" which is inherit from "Cloud-Init Datasource for VMware GuestInfo". For details please check: https://github.com/vmware-archive/cloud-init-vmware-guestinfo https://github.com/canonical/cloud-init/blob/main/cloudinit/sources/DataSourceVMware.py

This data source will allow you to pull cloud-init meta, user, and vendor data from VMware vSphere's GuestInfo interface. Please follow the first URL for detail steps. You could refer to this URL about the network settings in meta data: https://cloudinit.readthedocs.io/en/latest/topics/network-config.html#

betweenclouds commented 2 years ago

@xiaofengw-vmware Thank you, for elaborating this.

Maybe then its the best way to setup everything with cloud-init.

I was not aware that you also can supply metadata and setup the network through this way, because the ubuntu OVA has only "user-data" and "seedfrom" in the options.

I will try the "guestinfo.metadata" as described in your link: https://github.com/vmware-archive/cloud-init-vmware-guestinfo#configuration

betweenclouds commented 2 years ago

Got it working now, thank you both. For future reference:

Import an ubuntu cloudimage to a template, clone to a new VM and customize it

get the ubuntu cloudimage

wget -N https://cloud-images.ubuntu.com/focal/current/focal-server-cloudimg-amd64.ova

create a very minimal import.spec (it's also possible to add userdata and more here at this point, see: import.spec)
```
echo '{"NetworkMapping": [{"Name": "VM Network","Network": "net_10.10.20.0"}]}' > spec.json
```

import template

govc import.ova -options=spec.json -name focal-server-cloudimg-amd64 focal-server-cloudimg-amd64.ova

create a userdata.yaml

#cloud-config
users:
- default
- name: ubuntu
ssh-authorized-keys:
  - ssh-rsa AAAAB...
sudo: ALL=(ALL) NOPASSWD:ALL
groups: sudo
shell: /bin/bash

create a metadata.yaml (metadata network config)

instance-id: cloud-vm
local-hostname: cloud-vm
network:
version: 2
ethernets:
nics:
  match:
    name: ens192
  addresses:
    - 10.10.10.10/27
  gateway4: 10.10.10.1
  nameservers:
    search: [mycorp.local, home]
    addresses: [10.10.10.2, 10.10.10.3]

clone VM

govc vm.clone -vm focal-server-cloudimg-amd64 -on=false cloud-vm

set metadata and userdata

govc vm.change -vm cloud-vm -e guestinfo.metadata=$(base64 -w0 metadata.yaml) -e guestinfo.metadata.encoding="base64" -e guestinfo.userdata=$(base64 -w0 userdata.yaml) -e guestinfo.userdata.encoding="base64"

remove the floppy and cdrom (because cloud-init shold use our guestinfo vars and not the info from the iso)
```
govc device.remove -vm cloud-vm cdrom-3002
govc device.remove -vm cloud-vm floppy-8000
```

change network if needed

govc vm.network.change -vm cloud-vm -net=net_10.10.10.0 ethernet-0

start VM
```
govc vm.power -on cloud-vm
```

More details: DataSourceVMware

Edit:

add OVA import
change link to cloud-init as mentioned by @PengpengSun

xiaofengw-vmware commented 2 years ago

@betweenclouds glad to know that. Thanks for your summary which could help others.

PengpengSun commented 2 years ago

@betweenclouds nice job! I was not aware of ubuntu-focal-20.04-cloudimg has cloud-init version 22.1 already. People can find more details about DataSourceVMware at here, it's available since cloud-init version 21.3.

vmware / open-vm-tools