2021-05-04 15:14:53,606 INFO subiquity:109 Starting Subiquity server revision 2280
2021-05-04 15:14:53,606 INFO subiquity:110 Arguments passed: ['/snap/subiquity/2280/usr/bin/subiquity-server']
2021-05-04 15:14:53,606 DEBUG subiquitycore.utils:48 run_command called: ['cloud-init', 'status', '--wait']
2021-05-04 15:14:54,914 DEBUG subiquitycore.utils:61 run_command ['cloud-init', 'status', '--wait'] exited with code 0
2021-05-04 15:14:54,914 DEBUG subiquity:121 waited 1.3081560134887695s for cloud-init
2021-05-04 15:14:54,916 DEBUG subiquity:123 loading cloud config
2021-05-04 15:14:54,916 DEBUG cloudinit.util:1278 Reading from /etc/cloud/cloud.cfg (quiet=False)
2021-05-04 15:14:54,916 DEBUG cloudinit.util:1289 Read 4017 bytes from /etc/cloud/cloud.cfg
2021-05-04 15:14:54,916 DEBUG cloudinit.util:786 Attempting to load yaml from string of length 4017 with allowed root types (<class 'dict'>,)
2021-05-04 15:14:54,932 DEBUG cloudinit.util:1278 Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2021-05-04 15:14:54,933 DEBUG cloudinit.util:1289 Read 285 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2021-05-04 15:14:54,933 DEBUG cloudinit.util:786 Attempting to load yaml from string of length 285 with allowed root types (<class 'dict'>,)
2021-05-04 15:14:54,935 DEBUG cloudinit.util:1278 Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2021-05-04 15:14:54,935 DEBUG cloudinit.util:1289 Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2021-05-04 15:14:54,935 DEBUG cloudinit.util:786 Attempting to load yaml from string of length 2070 with allowed root types (<class 'dict'>,)
2021-05-04 15:14:54,942 DEBUG cloudinit.util:1278 Reading from /run/cloud-init/cloud.cfg (quiet=False)
2021-05-04 15:14:54,942 DEBUG cloudinit.util:1289 Read 35 bytes from /run/cloud-init/cloud.cfg
2021-05-04 15:14:54,942 DEBUG cloudinit.util:786 Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2021-05-04 15:14:54,942 DEBUG cloudinit.subp:221 Running command ['systemd-detect-virt', '--quiet', '--container'] with allowed return codes [0] (shell=False, capture=True)
2021-05-04 15:14:54,951 DEBUG cloudinit.util:1278 Reading from /etc/os-release (quiet=False)
2021-05-04 15:14:54,951 DEBUG cloudinit.util:1289 Read 382 bytes from /etc/os-release
2021-05-04 15:14:54,952 DEBUG cloudinit.util:1278 Reading from /proc/1/environ (quiet=False)
2021-05-04 15:14:54,952 DEBUG cloudinit.util:1289 Read 239 bytes from /proc/1/environ
2021-05-04 15:14:54,952 DEBUG cloudinit.util:1278 Reading from /proc/self/status (quiet=False)
2021-05-04 15:14:54,953 DEBUG cloudinit.util:1289 Read 1346 bytes from /proc/self/status
2021-05-04 15:14:54,953 DEBUG cloudinit.util:1278 Reading from /proc/cmdline (quiet=False)
2021-05-04 15:14:54,953 DEBUG cloudinit.util:1289 Read 48 bytes from /proc/cmdline
2021-05-04 15:14:54,953 DEBUG cloudinit.util:786 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2021-05-04 15:14:54,953 DEBUG cloudinit.util:789 loaded blob returned None, returning default.
2021-05-04 15:14:54,953 DEBUG cloudinit.util:1278 Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2021-05-04 15:14:54,953 DEBUG cloudinit.util:1289 Read 0 bytes from /var/lib/cloud/instance/cloud-config.txt
2021-05-04 15:14:54,954 DEBUG cloudinit.util:786 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2021-05-04 15:14:54,954 DEBUG cloudinit.util:789 loaded blob returned None, returning default.
2021-05-04 15:14:54,954 DEBUG cloudinit.util:1278 Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
2021-05-04 15:14:54,954 DEBUG cloudinit.util:1289 Read 7376 bytes from /var/lib/cloud/instance/obj.pkl
2021-05-04 15:14:54,962 DEBUG cloudinit.util:1278 Reading from /run/cloud-init/.instance-id (quiet=False)
2021-05-04 15:14:54,962 DEBUG cloudinit.util:1289 Read 8 bytes from /run/cloud-init/.instance-id
2021-05-04 15:14:54,962 DEBUG cloudinit.stages:248 restored from cache with run check: DataSourceNoCloud [seed=/var/lib/cloud/seed/nocloud][dsmode=net]
2021-05-04 15:14:54,962 DEBUG cloudinit.util:1278 Reading from /etc/cloud/cloud.cfg (quiet=False)
2021-05-04 15:14:54,963 DEBUG cloudinit.util:1289 Read 4017 bytes from /etc/cloud/cloud.cfg
2021-05-04 15:14:54,963 DEBUG cloudinit.util:786 Attempting to load yaml from string of length 4017 with allowed root types (<class 'dict'>,)
2021-05-04 15:14:54,980 DEBUG cloudinit.util:1278 Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2021-05-04 15:14:54,980 DEBUG cloudinit.util:1289 Read 285 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2021-05-04 15:14:54,980 DEBUG cloudinit.util:786 Attempting to load yaml from string of length 285 with allowed root types (<class 'dict'>,)
2021-05-04 15:14:54,982 DEBUG cloudinit.util:1278 Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2021-05-04 15:14:54,982 DEBUG cloudinit.util:1289 Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2021-05-04 15:14:54,982 DEBUG cloudinit.util:786 Attempting to load yaml from string of length 2070 with allowed root types (<class 'dict'>,)
2021-05-04 15:14:54,986 DEBUG cloudinit.util:1278 Reading from /run/cloud-init/cloud.cfg (quiet=False)
2021-05-04 15:14:54,986 DEBUG cloudinit.util:1289 Read 35 bytes from /run/cloud-init/cloud.cfg
2021-05-04 15:14:54,986 DEBUG cloudinit.util:786 Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2021-05-04 15:14:54,987 DEBUG cloudinit.util:786 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2021-05-04 15:14:54,987 DEBUG cloudinit.util:789 loaded blob returned None, returning default.
2021-05-04 15:14:54,987 DEBUG cloudinit.util:1278 Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2021-05-04 15:14:54,987 DEBUG cloudinit.util:1289 Read 0 bytes from /var/lib/cloud/instance/cloud-config.txt
2021-05-04 15:14:54,988 DEBUG cloudinit.util:786 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2021-05-04 15:14:54,988 DEBUG cloudinit.util:789 loaded blob returned None, returning default.
2021-05-04 15:14:54,989 DEBUG cloudinit.stages:83 Using distro class <class 'cloudinit.distros.ubuntu.Distro'>
2021-05-04 15:14:54,991 DEBUG asyncio:54 Using selector: EpollSelector
2021-05-04 15:14:54,992 DEBUG subiquitycore.prober:35 Prober() init finished, data:None
2021-05-04 15:14:54,992 DEBUG subiquity.signals:50 connect_signal: network-proxy-set -> <function SubiquityServer.__init__.<locals>.<lambda> at 0x7f2b029cd598>
2021-05-04 15:14:54,992 DEBUG subiquity.signals:50 connect_signal: network-change -> SubiquityServer._network_change
2021-05-04 15:14:54,994 DEBUG curtin:89 Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (capture=True)
2021-05-04 15:14:55,004 DEBUG subiquitycore.netplan:111 config for zz-all-en = {'dhcp4': True, 'match': {'name': 'en*'}}
2021-05-04 15:14:55,004 DEBUG subiquitycore.netplan:111 config for zz-all-eth = {'dhcp4': True, 'match': {'name': 'eth*'}}
2021-05-04 15:14:55,010 DEBUG subiquity.server.server:314 load_autoinstall_config only_early True
2021-05-04 15:14:55,011 DEBUG subiquity.server.server:314 load_autoinstall_config only_early False
2021-05-04 15:14:55,012 DEBUG subiquity.signals:50 connect_signal: snapd-network-change -> RefreshController.snapd_network_changed
2021-05-04 15:14:55,012 DEBUG subiquity.signals:50 connect_signal: snapd-network-change -> MirrorController.snapd_network_changed
2021-05-04 15:14:55,012 DEBUG subiquity.signals:50 connect_signal: snapd-network-change -> SnapListController.snapd_network_changed
2021-05-04 15:14:55,012 DEBUG subiquitycore.core:92 known signals: ['network-proxy-set', 'network-change', 'snapd-network-change']
2021-05-04 15:14:55,012 DEBUG subiquitycore.core:120 starting controllers
2021-05-04 15:14:55,018 DEBUG probert.network:586 event for link_change: NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2021-05-04 15:14:55,019 DEBUG probert.network:586 event for link_change: NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth0'}
2021-05-04 15:14:55,019 DEBUG probert.network:586 event for link_change: NEW {'ifindex': 3, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth1'}
2021-05-04 15:14:55,019 DEBUG probert.network:586 event for link_change: NEW {'ifindex': 4, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth2'}
2021-05-04 15:14:55,019 DEBUG probert.network:586 event for link_change: NEW {'ifindex': 5, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth3'}
2021-05-04 15:14:55,019 DEBUG probert.network:586 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'}
2021-05-04 15:14:55,019 DEBUG probert.network:586 event for addr_change: NEW {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'192.168.0.198/24'}
2021-05-04 15:14:55,019 DEBUG probert.network:586 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2021-05-04 15:14:55,019 DEBUG probert.network:586 event for addr_change: NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::9055:77ff:fef2:82ca/64'}
2021-05-04 15:14:55,019 DEBUG probert.network:586 event for addr_change: NEW {'ifindex': 3, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::c8f1:f1ff:fecd:77f9/64'}
2021-05-04 15:14:55,019 DEBUG probert.network:586 event for addr_change: NEW {'ifindex': 4, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::cef:d4ff:fe6a:509c/64'}
2021-05-04 15:14:55,019 DEBUG probert.network:586 event for addr_change: NEW {'ifindex': 5, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::b088:2cff:fece:51b5/64'}
2021-05-04 15:14:55,019 DEBUG probert.network:673 link_change NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2021-05-04 15:14:55,076 DEBUG subiquitycore.models.network:422 new_link 1 lo lo
2021-05-04 15:14:55,076 DEBUG probert.network:673 link_change NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth0'}
2021-05-04 15:14:55,127 DEBUG subiquitycore.models.network:422 new_link 2 eth0 eth
2021-05-04 15:14:55,128 DEBUG subiquitycore.models.network:450 new_link 2 eth0 with config {'dhcp4': True}
2021-05-04 15:14:55,128 DEBUG root:39 start: subiquity/Network/_send_update: NEW eth0
2021-05-04 15:14:55,128 DEBUG subiquity.server.controllers.network:269 dev_info eth0 {'dhcp4': True}
2021-05-04 15:14:55,128 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: NEW eth0
2021-05-04 15:14:55,128 DEBUG probert.network:673 link_change NEW {'ifindex': 3, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth1'}
2021-05-04 15:14:55,183 DEBUG subiquitycore.models.network:422 new_link 3 eth1 eth
2021-05-04 15:14:55,183 DEBUG subiquitycore.models.network:450 new_link 3 eth1 with config {'dhcp4': True}
2021-05-04 15:14:55,184 DEBUG root:39 start: subiquity/Network/_send_update: NEW eth1
2021-05-04 15:14:55,184 DEBUG subiquity.server.controllers.network:269 dev_info eth1 {'dhcp4': True}
2021-05-04 15:14:55,184 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: NEW eth1
2021-05-04 15:14:55,185 DEBUG probert.network:673 link_change NEW {'ifindex': 4, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth2'}
2021-05-04 15:14:55,278 DEBUG subiquitycore.models.network:422 new_link 4 eth2 eth
2021-05-04 15:14:55,278 DEBUG subiquitycore.models.network:450 new_link 4 eth2 with config {'dhcp4': True}
2021-05-04 15:14:55,279 DEBUG root:39 start: subiquity/Network/_send_update: NEW eth2
2021-05-04 15:14:55,279 DEBUG subiquity.server.controllers.network:269 dev_info eth2 {'dhcp4': True}
2021-05-04 15:14:55,279 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: NEW eth2
2021-05-04 15:14:55,279 DEBUG probert.network:673 link_change NEW {'ifindex': 5, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth3'}
2021-05-04 15:14:55,336 DEBUG subiquitycore.models.network:422 new_link 5 eth3 eth
2021-05-04 15:14:55,336 DEBUG subiquitycore.models.network:450 new_link 5 eth3 with config {'dhcp4': True}
2021-05-04 15:14:55,336 DEBUG root:39 start: subiquity/Network/_send_update: NEW eth3
2021-05-04 15:14:55,336 DEBUG subiquity.server.controllers.network:269 dev_info eth3 {'dhcp4': True}
2021-05-04 15:14:55,336 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: NEW eth3
2021-05-04 15:14:55,336 DEBUG probert.network:718 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'}
2021-05-04 15:14:55,337 DEBUG probert.network:718 addr_change NEW {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'192.168.0.198/24'}
2021-05-04 15:14:55,337 DEBUG root:39 start: subiquity/Network/_send_update: CHANGE eth0
2021-05-04 15:14:55,337 DEBUG subiquity.server.controllers.network:269 dev_info eth0 {'dhcp4': True}
2021-05-04 15:14:55,337 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: CHANGE eth0
2021-05-04 15:14:55,337 DEBUG probert.network:718 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2021-05-04 15:14:55,337 DEBUG probert.network:718 addr_change NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::9055:77ff:fef2:82ca/64'}
2021-05-04 15:14:55,338 DEBUG root:39 start: subiquity/Network/_send_update: CHANGE eth0
2021-05-04 15:14:55,338 DEBUG subiquity.server.controllers.network:269 dev_info eth0 {'dhcp4': True}
2021-05-04 15:14:55,338 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: CHANGE eth0
2021-05-04 15:14:55,338 DEBUG probert.network:718 addr_change NEW {'ifindex': 3, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::c8f1:f1ff:fecd:77f9/64'}
2021-05-04 15:14:55,338 DEBUG root:39 start: subiquity/Network/_send_update: CHANGE eth1
2021-05-04 15:14:55,338 DEBUG subiquity.server.controllers.network:269 dev_info eth1 {'dhcp4': True}
2021-05-04 15:14:55,338 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: CHANGE eth1
2021-05-04 15:14:55,338 DEBUG probert.network:718 addr_change NEW {'ifindex': 4, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::cef:d4ff:fe6a:509c/64'}
2021-05-04 15:14:55,338 DEBUG root:39 start: subiquity/Network/_send_update: CHANGE eth2
2021-05-04 15:14:55,339 DEBUG subiquity.server.controllers.network:269 dev_info eth2 {'dhcp4': True}
2021-05-04 15:14:55,339 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: CHANGE eth2
2021-05-04 15:14:55,339 DEBUG probert.network:718 addr_change NEW {'ifindex': 5, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::b088:2cff:fece:51b5/64'}
2021-05-04 15:14:55,339 DEBUG root:39 start: subiquity/Network/_send_update: CHANGE eth3
2021-05-04 15:14:55,339 DEBUG subiquity.server.controllers.network:269 dev_info eth3 {'dhcp4': True}
2021-05-04 15:14:55,339 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: CHANGE eth3
2021-05-04 15:14:55,339 DEBUG probert.network:732 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2021-05-04 15:14:55,339 DEBUG subiquitycore.controller.network:93 default routes {2}
2021-05-04 15:14:55,341 DEBUG subiquity.server.controllers.snaplist:59 loading list of snaps
2021-05-04 15:14:55,341 DEBUG probert.network:732 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'192.168.0.0/24', 'ifindex': 2}
2021-05-04 15:14:55,341 DEBUG probert.network:732 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'192.168.0.1', 'ifindex': 2}
2021-05-04 15:14:55,341 DEBUG probert.network:732 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'127.0.0.0', 'ifindex': 1}
2021-05-04 15:14:55,341 DEBUG probert.network:732 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.0/8', 'ifindex': 1}
2021-05-04 15:14:55,341 DEBUG probert.network:732 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.1', 'ifindex': 1}
2021-05-04 15:14:55,341 DEBUG probert.network:732 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'127.255.255.255', 'ifindex': 1}
2021-05-04 15:14:55,342 DEBUG probert.network:732 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'192.168.0.0', 'ifindex': 2}
2021-05-04 15:14:55,342 DEBUG probert.network:732 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'192.168.0.198', 'ifindex': 2}
2021-05-04 15:14:55,342 DEBUG probert.network:732 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'192.168.0.255', 'ifindex': 2}
2021-05-04 15:14:55,342 DEBUG probert.network:732 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'::1', 'ifindex': 1}
2021-05-04 15:14:55,342 DEBUG probert.network:732 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'fe80::/64', 'ifindex': 5}
2021-05-04 15:14:55,342 DEBUG probert.network:732 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'::1', 'ifindex': 1}
2021-05-04 15:14:55,342 DEBUG probert.network:732 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'fe80::cef:d4ff:fe6a:509c', 'ifindex': 4}
2021-05-04 15:14:55,342 DEBUG probert.network:732 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'fe80::9055:77ff:fef2:82ca', 'ifindex': 2}
2021-05-04 15:14:55,342 DEBUG probert.network:732 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'fe80::b088:2cff:fece:51b5', 'ifindex': 5}
2021-05-04 15:14:55,342 DEBUG probert.network:732 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'fe80::c8f1:f1ff:fecd:77f9', 'ifindex': 3}
2021-05-04 15:14:55,342 DEBUG probert.network:732 route_change NEW {'family': 10, 'type': 1, 'table': 255, 'dst': b'ff00::/8', 'ifindex': 5}
2021-05-04 15:14:55,465 DEBUG subiquitycore.core:123 controllers started
2021-05-04 15:14:55,466 INFO root:39 start: subiquity/apply_autoinstall_config: 
2021-05-04 15:14:55,466 DEBUG root:39 start: subiquity/Early/apply_autoinstall_config: 
2021-05-04 15:14:55,491 DEBUG root:39 finish: subiquity/Early/apply_autoinstall_config: SUCCESS: 
2021-05-04 15:14:55,492 DEBUG root:39 start: subiquity/Reporting/apply_autoinstall_config: 
2021-05-04 15:14:55,493 DEBUG root:39 finish: subiquity/Reporting/apply_autoinstall_config: SUCCESS: 
2021-05-04 15:14:55,493 DEBUG root:39 start: subiquity/Error/apply_autoinstall_config: 
2021-05-04 15:14:55,494 DEBUG root:39 finish: subiquity/Error/apply_autoinstall_config: SUCCESS: 
2021-05-04 15:14:55,495 DEBUG root:39 start: subiquity/Userdata/apply_autoinstall_config: 
2021-05-04 15:14:55,495 DEBUG root:39 finish: subiquity/Userdata/apply_autoinstall_config: SUCCESS: 
2021-05-04 15:14:55,496 DEBUG subiquity.models.subiquity:146 model userdata is configured, to go set()
2021-05-04 15:14:55,496 DEBUG root:39 start: subiquity/Package/apply_autoinstall_config: 
2021-05-04 15:14:55,497 DEBUG root:39 finish: subiquity/Package/apply_autoinstall_config: SUCCESS: 
2021-05-04 15:14:55,497 DEBUG subiquity.models.subiquity:146 model packages is configured, to go set()
2021-05-04 15:14:55,497 DEBUG root:39 start: subiquity/Debconf/apply_autoinstall_config: 
2021-05-04 15:14:55,498 DEBUG root:39 finish: subiquity/Debconf/apply_autoinstall_config: SUCCESS: 
2021-05-04 15:14:55,499 DEBUG subiquity.models.subiquity:146 model debconf_selections is configured, to go set()
2021-05-04 15:14:55,499 DEBUG subiquity.server.server:308 apply_autoinstall_config: skipping Locale as interactive
2021-05-04 15:14:55,499 DEBUG subiquity.server.server:308 apply_autoinstall_config: skipping Refresh as interactive
2021-05-04 15:14:55,499 DEBUG subiquity.server.server:308 apply_autoinstall_config: skipping Keyboard as interactive
2021-05-04 15:14:55,499 DEBUG root:39 start: subiquity/Zdev/apply_autoinstall_config: 
2021-05-04 15:14:55,500 DEBUG root:39 finish: subiquity/Zdev/apply_autoinstall_config: SUCCESS: 
2021-05-04 15:14:55,500 DEBUG subiquity.server.server:308 apply_autoinstall_config: skipping Network as interactive
2021-05-04 15:14:55,501 DEBUG subiquity.server.server:308 apply_autoinstall_config: skipping Proxy as interactive
2021-05-04 15:14:55,501 DEBUG subiquity.server.server:308 apply_autoinstall_config: skipping Mirror as interactive
2021-05-04 15:14:55,501 DEBUG subiquity.server.server:308 apply_autoinstall_config: skipping Filesystem as interactive
2021-05-04 15:14:55,501 DEBUG subiquity.server.server:308 apply_autoinstall_config: skipping Identity as interactive
2021-05-04 15:14:55,501 DEBUG subiquity.server.server:308 apply_autoinstall_config: skipping SSH as interactive
2021-05-04 15:14:55,501 DEBUG subiquity.server.server:308 apply_autoinstall_config: skipping SnapList as interactive
2021-05-04 15:14:55,501 DEBUG subiquity.server.server:308 apply_autoinstall_config: skipping Install as interactive
2021-05-04 15:14:55,501 DEBUG root:39 start: subiquity/Late/apply_autoinstall_config: 
2021-05-04 15:14:55,502 DEBUG root:39 finish: subiquity/Late/apply_autoinstall_config: SUCCESS: 
2021-05-04 15:14:55,503 DEBUG subiquity.server.server:308 apply_autoinstall_config: skipping Reboot as interactive
2021-05-04 15:14:55,503 INFO root:39 finish: subiquity/apply_autoinstall_config: SUCCESS: 
2021-05-04 15:14:55,503 DEBUG root:39 start: subiquity/Refresh/configure_snapd: 
2021-05-04 15:14:55,503 DEBUG root:39 start: subiquity/Refresh/configure_snapd/get_details: 
2021-05-04 15:14:55,510 DEBUG root:39 start: subiquity/Refresh/check_for_update: 
2021-05-04 15:14:55,511 DEBUG root:39 start: subiquity/Refresh/check_for_update: 
2021-05-04 15:14:55,512 DEBUG root:39 start: subiquity/Mirror/lookup: 
2021-05-04 15:14:55,522 DEBUG root:39 start: subiquity/SnapList/loader: 
2021-05-04 15:14:55,526 DEBUG urllib3.connectionpool:826 Starting new HTTPS connection (1): geoip.ubuntu.com
2021-05-04 15:14:55,546 DEBUG root:39 start: subiquity/Install/install: 
2021-05-04 15:14:55,547 ERROR root:39 finish: subiquity/Refresh/check_for_update: FAIL: cancelled
2021-05-04 15:14:55,547 DEBUG root:39 start: subiquity/SnapList/loader/list: 
2021-05-04 15:14:55,552 DEBUG root:39 start: subiquity/Filesystem/_probe: 
2021-05-04 15:14:55,553 DEBUG root:39 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2021-05-04 15:14:55,590 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/snaps/subiquity HTTP/1.1" 200 1175
2021-05-04 15:14:55,593 DEBUG root:39 finish: subiquity/Refresh/configure_snapd/get_details: SUCCESS: current version of snap is: '21.01.2'
2021-05-04 15:14:55,595 DEBUG root:39 start: subiquity/Refresh/configure_snapd/switching: switching subiquity to stable/ubuntu-20.04.2
2021-05-04 15:14:55,680 DEBUG urllib3.connectionpool:396 http://localhost:None "POST /v2/snaps/subiquity HTTP/1.1" 202 81
2021-05-04 15:14:55,692 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/changes/4 HTTP/1.1" 200 596
2021-05-04 15:14:55,694 DEBUG root:39 finish: subiquity/Refresh/configure_snapd/switching: SUCCESS: switched to stable/ubuntu-20.04.2
2021-05-04 15:14:55,694 DEBUG root:39 finish: subiquity/Refresh/configure_snapd: SUCCESS: 
2021-05-04 15:14:55,720 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:14:55,723 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2021-05-04 15:14:55,736 INFO aiohttp.access:206  [04/May/2021:15:14:55 +0000] "GET /meta/status HTTP/1.1" 200 411 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:14:55,773 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:14:55,773 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2021-05-04 15:14:55,774 INFO aiohttp.access:206  [04/May/2021:15:14:55 +0000] "GET /meta/status?cur=null HTTP/1.1" 200 411 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:14:55,775 DEBUG root:39 start: subiquity/Locale/GET: 
2021-05-04 15:14:55,775 DEBUG root:39 finish: subiquity/Locale/GET: SUCCESS: 200 "C"
2021-05-04 15:14:55,775 INFO aiohttp.access:206  [04/May/2021:15:14:55 +0000] "GET /locale HTTP/1.1" 200 188 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:14:55,783 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:14:55,896 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:14:55,897 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2021-05-04 15:14:55,897 INFO aiohttp.access:206  [04/May/2021:15:14:55 +0000] "GET /meta/status HTTP/1.1" 200 411 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:14:55,927 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:14:55,929 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2021-05-04 15:14:55,935 INFO aiohttp.access:206  [04/May/2021:15:14:55 +0000] "GET /meta/status?cur=null HTTP/1.1" 200 411 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:14:55,936 DEBUG root:39 start: subiquity/Locale/GET: 
2021-05-04 15:14:55,936 DEBUG root:39 finish: subiquity/Locale/GET: SUCCESS: 200 "C"
2021-05-04 15:14:55,937 INFO aiohttp.access:206  [04/May/2021:15:14:55 +0000] "GET /locale HTTP/1.1" 200 188 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:14:55,937 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:14:55,940 DEBUG root:39 start: subiquity/Network/global_addresses_GET: 
2021-05-04 15:14:55,941 DEBUG root:39 finish: subiquity/Network/global_addresses_GET: SUCCESS: 200 ["192.168.0.198"]
2021-05-04 15:14:55,947 INFO aiohttp.access:206  [04/May/2021:15:14:55 +0000] "GET /network/global_addresses HTTP/1.1" 200 203 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:14:56,124 DEBUG urllib3.connectionpool:396 https://geoip.ubuntu.com:443 "GET /lookup HTTP/1.1" 200 None
2021-05-04 15:14:56,129 DEBUG root:39 finish: subiquity/Mirror/lookup: SUCCESS: 
2021-05-04 15:14:56,224 DEBUG probert.dasd:131 Probing DASD devies
2021-05-04 15:14:56,225 DEBUG probert.dasd:134 DASD devices only present on s390x, arch=x86_64
2021-05-04 15:14:56,238 DEBUG curtin:1312 Extracting storage config from probe data
2021-05-04 15:14:56,280 DEBUG curtin:1319 Sorting extracted configurations
2021-05-04 15:14:56,280 INFO curtin:1338 Validating extracted storage config components
2021-05-04 15:14:56,322 DEBUG curtin:1357 Extracted (unmerged) storage config:
storage:
-   id: disk-xvda
    path: /dev/xvda
    type: disk

2021-05-04 15:14:56,322 DEBUG curtin:1359 Generating storage config dependencies
2021-05-04 15:14:56,322 DEBUG curtin:1365 Merging storage config dependencies
2021-05-04 15:14:56,323 DEBUG curtin:1372 Merged storage config:
storage:
    config:
    -   id: disk-xvda
        path: /dev/xvda
        type: disk
    version: 1

2021-05-04 15:14:56,324 DEBUG subiquity.models.filesystem:1567 exclusions set()
2021-05-04 15:14:56,324 DEBUG root:39 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False
2021-05-04 15:14:56,324 DEBUG root:39 finish: subiquity/Filesystem/_probe: SUCCESS: 
2021-05-04 15:14:56,831 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?section=server HTTP/1.1" 200 None
2021-05-04 15:14:56,835 DEBUG root:39 finish: subiquity/SnapList/loader/list: SUCCESS: 
2021-05-04 15:14:56,835 DEBUG subiquity.server.controllers.snaplist:67 fetched list of 24 snaps
2021-05-04 15:14:56,837 DEBUG root:39 start: subiquity/SnapList/loader/fetch/microk8s: 
2021-05-04 15:14:57,100 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?select=refresh HTTP/1.1" 200 None
2021-05-04 15:14:57,101 DEBUG subiquity.server.controllers.refresh:179 check_for_update received {'type': 'sync', 'status-code': 200, 'status': 'OK', 'result': [{'id': 'CSO04Jhav2yK0uz97cr0ipQRyqg0qQL6', 'title': 'Core 18', 'summary': 'Runtime environment based on Ubuntu 18.04', 'description': 'The base snap based on the Ubuntu 18.04 release.', 'download-size': 58142720, 'name': 'core18', 'publisher': {'id': 'canonical', 'username': 'canonical', 'display-name': 'Canonical', 'validation': 'verified'}, 'developer': 'canonical', 'status': 'available', 'type': 'base', 'version': '20210309', 'channel': 'latest/stable', 'ignore-validation': False, 'revision': '1997', 'confinement': 'strict', 'private': False, 'devmode': False, 'jailmode': False, 'contact': '', 'license': 'Other Open Source'}, {'id': 'J60k4JY0HppjwOjW8dZdYc8obXKxujRu', 'title': 'LXD', 'summary': 'System container and virtual machine manager', 'description': "**LXD is a system container and virtual machine manager**\n\nWith LXD you can run hundreds of containers of a variety of Linux \ndistributions, apply resource limits, pass in directories, USB devices\nor GPUs and setup any network and storage you want.\n\nLXD containers are lightweight, secure by default and a great \nalternative to running Linux virtual machines.\n\nIf you want to run other Operating Systems or special Linux workloads,\nyou can use LXD virtual machines instead\n\n**Run any Linux distribution you want**\n\nPre-made images are available for Ubuntu, Alpine Linux, ArchLinux, \nCentOS, Debian, Fedora, Gentoo, OpenSUSE and more.\n\nA full list of available images can be found here: https://images.linuxcontainers.org\n\nCan't find the distribution you want? It's easy to make your own images too, either using our `distrobuilder` tool or by assembling your own image tarball by hand.\n\n\n**Containers and VMs at scale**\n\nLXD is network aware and all interactions go through a simple REST API, \nmaking it possible to remotely interact with instances on remote\nsystems, copying and moving them as you wish.\n\nWant to go big? LXD also has built-in clustering support,\nletting you turn dozens of servers into one big LXD server.\n\n\n**Configuration options**\n\nSupported options for the LXD snap (`snap set lxd KEY=VALUE`):\n   - ceph.builtin: Use snap-specific Ceph configuration [default=false]\n   - ceph.external: Use the system's ceph tools (ignores ceph.builtin) [default=false]\n   - criu.enable: Enable experimental live-migration support [default=false]\n   - daemon.debug: Increase logging to debug level [default=false]\n   - daemon.group: Set group of users that can interact with LXD [default=lxd]\n   - daemon.preseed: Pass a YAML configuration to `lxd init` on initial start\n   - daemon.syslog: Send LXD log events to syslog [default=false]\n   - lvm.external: Use the system's LVM tools [default=false]\n   - lxcfs.pidfd: Start per-container process tracking [default=false]\n   - lxcfs.loadavg: Start tracking per-container load average [default=false]\n   - lxcfs.cfs: Consider CPU shares for CPU usage [default=false]\n   - openvswitch.builtin: Run a snap-specific OVS daemon [default=false]\n   - shiftfs.enable: Enable shiftfs support [default=auto]\n\nDocumentation: https://linuxcontainers.org/lxd/docs/master/", 'download-size': 73797632, 'icon': 'https://dashboard.snapcraft.io/site_media/appmedia/2016/08/containers.png', 'name': 'lxd', 'publisher': {'id': 'canonical', 'username': 'canonical', 'display-name': 'Canonical', 'validation': 'verified'}, 'developer': 'canonical', 'status': 'available', 'type': 'app', 'base': 'core18', 'version': '4.0.5', 'channel': '4.0/stable', 'ignore-validation': False, 'revision': '19647', 'confinement': 'strict', 'private': False, 'devmode': False, 'jailmode': False, 'contact': 'https://github.com/lxc/lxd/issues', 'license': 'Apache-2.0', 'website': 'https://linuxcontainers.org/lxd', 'media': [{'type': 'icon', 'url': 'https://dashboard.snapcraft.io/site_media/appmedia/2016/08/containers.png', 'width': 256, 'height': 256}, {'type': 'screenshot', 'url': 'https://dashboard.snapcraft.io/site_media/appmedia/2018/10/Screenshot_from_2018-10-26_12-57-24.png', 'width': 977, 'height': 592}, {'type': 'screenshot', 'url': 'https://dashboard.snapcraft.io/site_media/appmedia/2018/10/Screenshot_from_2018-10-26_14-20-14.png', 'width': 1003, 'height': 592}, {'type': 'screenshot', 'url': 'https://dashboard.snapcraft.io/site_media/appmedia/2018/10/Screenshot_from_2018-10-26_14-21-43.png', 'width': 1003, 'height': 592}, {'type': 'video', 'url': 'https://asciinema.org/a/226224'}]}, {'id': 'PMrrV4ml8uWuEUDBT8dSGnKUYbevVhc4', 'title': 'snapd', 'summary': 'Background service that manages and maintains installed snaps', 'description': "**Note: you do not need to install _snapd_ manually if you already have _snap_ installed.**\n\nSnaps are app packages for desktop, cloud and IoT that update automatically, are easy to install, secure, cross-platform and dependency-free. They're being used on millions of Linux systems every day.\n\nAlongside its various service and management functions, snapd:\n- provides the _snap_ command that's used to install and remove snaps and interact with the wider snap ecosystem\n- implements the confinement policies that isolate snaps from the base system and from each other\n- governs the interfaces that allow snaps to access specific system resources outside of their confinement\n\nFor general details, including _installation_ and _Getting started_  guides, head over to our _Snap documentation_: https://snapcraft.io/docs\n\nIf you want to build your own snaps, start with our _Creating a snap_ documentation: https://snapcraft.io/docs/creating-a-snap\n\n**Get involved**\n\nThis is an _open source_ project and we warmly welcome community contributions, suggestions, and constructive feedback. If you're interested in contributing, please take a look at our _Code of Conduct_ first.\n\n- to report an issue, please file _a bug report_ (https://bugs.launchpad.net/snappy/+filebug) on our _Launchpad issue tracker_ (https://bugs.launchpad.net/snappy/)\n- for suggestions and constructive feedback, create a post on the _Snapcraft forum_ (https://forum.snapcraft.io/c/snapd)\n- to build snapd manually, or to get started with snapd development, see  _HACKING.md (https://raw.githubusercontent.com/snapcore/snapd/master/HACKING.md)\n\n**Get in touch**\n\nWe're friendly! We have a community forum at https://forum.snapcraft.io where we discuss feature plans, development news, issues, updates and troubleshooting. You can chat in realtime with the snapd team and our wider community on the _#snappy_ (https://webchat.freenode.net/?channels=snappy) IRC channel on _freenode_ (https://freenode.net/).\n\nFor news and updates, follow us on _Twitter_ (https://twitter.com/snapcraftio) and on _Facebook_ (https://www.facebook.com/snapcraftio).\n\nThe snapd source code can be found on GitHub: https://github.com/snapcore/snapd", 'download-size': 33841152, 'icon': 'https://dashboard.snapcraft.io/site_media/appmedia/2019/09/snapd.png', 'name': 'snapd', 'publisher': {'id': 'canonical', 'username': 'canonical', 'display-name': 'Canonical', 'validation': 'verified'}, 'developer': 'canonical', 'status': 'available', 'type': 'snapd', 'version': '2.49.2', 'channel': 'latest/stable', 'ignore-validation': False, 'revision': '11588', 'confinement': 'strict', 'private': False, 'devmode': False, 'jailmode': False, 'contact': '', 'license': 'GPL-3.0+', 'website': 'https://snapcraft.io', 'media': [{'type': 'icon', 'url': 'https://dashboard.snapcraft.io/site_media/appmedia/2019/09/snapd.png', 'width': 460, 'height': 460}, {'type': 'screenshot', 'url': 'https://dashboard.snapcraft.io/site_media/appmedia/2019/09/Screenshot_20190924_115756_hLcyetO.png', 'width': 956, 'height': 648}, {'type': 'screenshot', 'url': 'https://dashboard.snapcraft.io/site_media/appmedia/2019/09/Screenshot_20190924_115824_2v3y6l8.png', 'width': 956, 'height': 648}, {'type': 'screenshot', 'url': 'https://dashboard.snapcraft.io/site_media/appmedia/2019/09/Screenshot_20190924_115055_Uuq7KIb.png', 'width': 1023, 'height': 834}, {'type': 'screenshot', 'url': 'https://dashboard.snapcraft.io/site_media/appmedia/2019/09/Screenshot_20190924_125944.png', 'width': 956, 'height': 648}]}]}
2021-05-04 15:14:57,102 DEBUG root:39 finish: subiquity/Refresh/check_for_update: SUCCESS: no new version of snap available
2021-05-04 15:14:57,487 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=microk8s HTTP/1.1" 200 None
2021-05-04 15:14:57,505 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/microk8s: SUCCESS: 
2021-05-04 15:14:57,506 DEBUG root:39 start: subiquity/SnapList/loader/fetch/nextcloud: 
2021-05-04 15:14:57,946 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=nextcloud HTTP/1.1" 200 None
2021-05-04 15:14:57,948 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/nextcloud: SUCCESS: 
2021-05-04 15:14:57,949 DEBUG root:39 start: subiquity/SnapList/loader/fetch/wekan: 
2021-05-04 15:14:58,259 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=wekan HTTP/1.1" 200 None
2021-05-04 15:14:58,261 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/wekan: SUCCESS: 
2021-05-04 15:14:58,262 DEBUG root:39 start: subiquity/SnapList/loader/fetch/kata-containers: 
2021-05-04 15:14:58,528 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=kata-containers HTTP/1.1" 200 None
2021-05-04 15:14:58,530 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/kata-containers: SUCCESS: 
2021-05-04 15:14:58,531 DEBUG root:39 start: subiquity/SnapList/loader/fetch/docker: 
2021-05-04 15:14:58,794 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=docker HTTP/1.1" 200 None
2021-05-04 15:14:58,796 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/docker: SUCCESS: 
2021-05-04 15:14:58,796 DEBUG root:39 start: subiquity/SnapList/loader/fetch/canonical-livepatch: 
2021-05-04 15:14:59,084 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=canonical-livepatch HTTP/1.1" 200 1851
2021-05-04 15:14:59,086 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/canonical-livepatch: SUCCESS: 
2021-05-04 15:14:59,086 DEBUG root:39 start: subiquity/SnapList/loader/fetch/rocketchat-server: 
2021-05-04 15:14:59,384 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=rocketchat-server HTTP/1.1" 200 None
2021-05-04 15:14:59,386 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/rocketchat-server: SUCCESS: 
2021-05-04 15:14:59,387 DEBUG root:39 start: subiquity/SnapList/loader/fetch/mosquitto: 
2021-05-04 15:14:59,671 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=mosquitto HTTP/1.1" 200 None
2021-05-04 15:14:59,673 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/mosquitto: SUCCESS: 
2021-05-04 15:14:59,673 DEBUG root:39 start: subiquity/SnapList/loader/fetch/etcd: 
2021-05-04 15:15:00,023 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=etcd HTTP/1.1" 200 None
2021-05-04 15:15:00,026 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/etcd: SUCCESS: 
2021-05-04 15:15:00,027 DEBUG root:39 start: subiquity/SnapList/loader/fetch/powershell: 
2021-05-04 15:15:00,277 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=powershell HTTP/1.1" 200 None
2021-05-04 15:15:00,279 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/powershell: SUCCESS: 
2021-05-04 15:15:00,280 DEBUG root:39 start: subiquity/SnapList/loader/fetch/stress-ng: 
2021-05-04 15:15:00,581 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=stress-ng HTTP/1.1" 200 None
2021-05-04 15:15:00,582 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/stress-ng: SUCCESS: 
2021-05-04 15:15:00,583 DEBUG root:39 start: subiquity/SnapList/loader/fetch/sabnzbd: 
2021-05-04 15:15:00,855 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=sabnzbd HTTP/1.1" 200 None
2021-05-04 15:15:00,856 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/sabnzbd: SUCCESS: 
2021-05-04 15:15:00,857 DEBUG root:39 start: subiquity/SnapList/loader/fetch/wormhole: 
2021-05-04 15:15:01,245 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=wormhole HTTP/1.1" 200 None
2021-05-04 15:15:01,247 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/wormhole: SUCCESS: 
2021-05-04 15:15:01,247 DEBUG root:39 start: subiquity/SnapList/loader/fetch/aws-cli: 
2021-05-04 15:15:01,694 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=aws-cli HTTP/1.1" 200 1873
2021-05-04 15:15:01,696 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/aws-cli: SUCCESS: 
2021-05-04 15:15:01,696 DEBUG root:39 start: subiquity/SnapList/loader/fetch/google-cloud-sdk: 
2021-05-04 15:15:02,025 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=google-cloud-sdk HTTP/1.1" 200 1735
2021-05-04 15:15:02,026 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/google-cloud-sdk: SUCCESS: 
2021-05-04 15:15:02,027 DEBUG root:39 start: subiquity/SnapList/loader/fetch/slcli: 
2021-05-04 15:15:02,317 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=slcli HTTP/1.1" 200 1896
2021-05-04 15:15:02,318 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/slcli: SUCCESS: 
2021-05-04 15:15:02,319 DEBUG root:39 start: subiquity/SnapList/loader/fetch/doctl: 
2021-05-04 15:15:02,680 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=doctl HTTP/1.1" 200 1969
2021-05-04 15:15:02,682 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/doctl: SUCCESS: 
2021-05-04 15:15:02,682 DEBUG root:39 start: subiquity/SnapList/loader/fetch/conjure-up: 
2021-05-04 15:15:03,005 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=conjure-up HTTP/1.1" 200 None
2021-05-04 15:15:03,006 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/conjure-up: SUCCESS: 
2021-05-04 15:15:03,007 DEBUG root:39 start: subiquity/SnapList/loader/fetch/minidlna-escoand: 
2021-05-04 15:15:03,315 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=minidlna-escoand HTTP/1.1" 200 1992
2021-05-04 15:15:03,317 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/minidlna-escoand: SUCCESS: 
2021-05-04 15:15:03,317 DEBUG root:39 start: subiquity/SnapList/loader/fetch/postgresql10: 
2021-05-04 15:15:04,171 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=postgresql10 HTTP/1.1" 200 1450
2021-05-04 15:15:04,172 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/postgresql10: SUCCESS: 
2021-05-04 15:15:04,172 DEBUG root:39 start: subiquity/SnapList/loader/fetch/heroku: 
2021-05-04 15:15:04,221 DEBUG root:39 start: subiquity/Locale/POST: "en_US"
2021-05-04 15:15:04,221 DEBUG subiquity.models.subiquity:146 model locale is configured, to go set()
2021-05-04 15:15:04,222 DEBUG root:39 finish: subiquity/Locale/POST: SUCCESS: 200 null
2021-05-04 15:15:04,222 INFO aiohttp.access:206  [04/May/2021:15:15:04 +0000] "POST /locale HTTP/1.1" 200 189 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:04,223 DEBUG root:39 start: subiquity/Refresh/GET: 
2021-05-04 15:15:04,223 DEBUG root:39 finish: subiquity/Refresh/GET: SUCCESS: 200 {"availability": "UNAVAILABLE", "current_snap_version": "21.01.2", "new_snap_...
2021-05-04 15:15:04,224 INFO aiohttp.access:206  [04/May/2021:15:15:04 +0000] "GET /refresh HTTP/1.1" 200 276 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:04,225 DEBUG root:39 start: subiquity/Keyboard/GET: 
2021-05-04 15:15:04,225 DEBUG root:39 finish: subiquity/Keyboard/GET: SUCCESS: 200 {"layout": "us", "variant": "", "toggle": null}
2021-05-04 15:15:04,225 INFO aiohttp.access:206  [04/May/2021:15:15:04 +0000] "GET /keyboard HTTP/1.1" 200 233 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:04,941 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=heroku HTTP/1.1" 200 None
2021-05-04 15:15:04,942 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/heroku: SUCCESS: 
2021-05-04 15:15:04,943 DEBUG root:39 start: subiquity/SnapList/loader/fetch/keepalived: 
2021-05-04 15:15:05,247 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=keepalived HTTP/1.1" 200 None
2021-05-04 15:15:05,249 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/keepalived: SUCCESS: 
2021-05-04 15:15:05,250 DEBUG root:39 start: subiquity/SnapList/loader/fetch/prometheus: 
2021-05-04 15:15:05,576 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=prometheus HTTP/1.1" 200 None
2021-05-04 15:15:05,578 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/prometheus: SUCCESS: 
2021-05-04 15:15:05,579 DEBUG root:39 start: subiquity/SnapList/loader/fetch/juju: 
2021-05-04 15:15:06,437 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=juju HTTP/1.1" 200 None
2021-05-04 15:15:06,440 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/juju: SUCCESS: 
2021-05-04 15:15:06,440 DEBUG root:39 finish: subiquity/SnapList/loader: SUCCESS: 
2021-05-04 15:15:28,831 DEBUG root:39 start: subiquity/Keyboard/POST: {"layout": "es", "variant": "", "toggle": null}
2021-05-04 15:15:28,831 DEBUG subiquity.models.subiquity:146 model keyboard is configured, to go set()
2021-05-04 15:15:28,832 DEBUG root:39 finish: subiquity/Keyboard/POST: SUCCESS: 200 null
2021-05-04 15:15:28,832 INFO aiohttp.access:206  [04/May/2021:15:15:28 +0000] "POST /keyboard HTTP/1.1" 200 189 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:28,835 INFO aiohttp.access:206  [04/May/2021:15:15:28 +0000] "GET /zdev HTTP/1.1" 200 180 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:28,837 DEBUG root:39 start: subiquity/Network/GET: 
2021-05-04 15:15:28,840 DEBUG root:39 finish: subiquity/Network/GET: SUCCESS: 200 [{"name": "eth0", "type": "eth", "is_connected": true, "bond_master": null, "...
2021-05-04 15:15:28,840 INFO aiohttp.access:206  [04/May/2021:15:15:28 +0000] "GET /network HTTP/1.1" 200 2802 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:28,840 INFO root:39 start: subiquity/Network/apply_config: silent=True
2021-05-04 15:15:28,843 DEBUG subiquitycore.controller.network:240 network config: 
network:
  ethernets:
    eth0:
      dhcp4: true
    eth1:
      dhcp4: true
    eth2:
      dhcp4: true
    eth3:
      dhcp4: true
  version: 2

2021-05-04 15:15:28,862 DEBUG subiquitycore.netplan:111 config for eth0 = {'dhcp4': True}
2021-05-04 15:15:28,862 DEBUG subiquitycore.netplan:111 config for eth1 = {'dhcp4': True}
2021-05-04 15:15:28,862 DEBUG subiquitycore.netplan:111 config for eth2 = {'dhcp4': True}
2021-05-04 15:15:28,862 DEBUG subiquitycore.netplan:111 config for eth3 = {'dhcp4': True}
2021-05-04 15:15:28,862 DEBUG subiquitycore.utils:74 arun_command called: ['netplan', 'apply']
2021-05-04 15:15:28,883 DEBUG root:39 start: subiquity/Network/subscription_PUT: 
2021-05-04 15:15:28,883 DEBUG subiquity.server.controllers.network:218 added subscription /tmp/tmpxyrpzwun/socket
2021-05-04 15:15:28,885 DEBUG root:39 finish: subiquity/Network/subscription_PUT: SUCCESS: 200 null
2021-05-04 15:15:28,885 INFO aiohttp.access:206  [04/May/2021:15:15:28 +0000] "PUT /network/subscription?socket_path=%22/tmp/tmpxyrpzwun/socket%22 HTTP/1.1" 200 189 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:28,886 DEBUG subiquity.server.controllers.network:238 _call_client route_watch /tmp/tmpxyrpzwun/socket
2021-05-04 15:15:29,672 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-05-04 15:15:29,696 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-05-04 15:15:29,696 DEBUG probert.network:586 event for addr_change: DEL {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'192.168.0.198/24'}
2021-05-04 15:15:29,697 DEBUG probert.network:732 route_change DEL {'family': 2, 'type': 1, 'table': 254, 'dst': b'192.168.0.1', 'ifindex': 2}
2021-05-04 15:15:29,697 DEBUG probert.network:732 route_change DEL {'family': 2, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2021-05-04 15:15:29,697 DEBUG subiquitycore.controller.network:93 default routes set()
2021-05-04 15:15:29,697 DEBUG subiquity.server.controllers.network:246 creating _call_client task /tmp/tmpxyrpzwun/socket route_watch
2021-05-04 15:15:29,697 DEBUG probert.network:718 addr_change DEL {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'192.168.0.198/24'}
2021-05-04 15:15:29,697 DEBUG root:39 start: subiquity/Network/_send_update: CHANGE eth0
2021-05-04 15:15:29,697 DEBUG subiquity.server.controllers.network:269 dev_info eth0 {'dhcp4': True}
2021-05-04 15:15:29,698 DEBUG subiquity.server.controllers.network:246 creating _call_client task /tmp/tmpxyrpzwun/socket update_link
2021-05-04 15:15:29,698 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: CHANGE eth0
2021-05-04 15:15:29,698 DEBUG probert.network:732 route_change DEL {'family': 2, 'type': 1, 'table': 254, 'dst': b'192.168.0.0/24', 'ifindex': 2}
2021-05-04 15:15:29,698 DEBUG probert.network:732 route_change DEL {'family': 2, 'type': 3, 'table': 255, 'dst': b'192.168.0.255', 'ifindex': 2}
2021-05-04 15:15:29,698 DEBUG probert.network:732 route_change DEL {'family': 2, 'type': 3, 'table': 255, 'dst': b'192.168.0.0', 'ifindex': 2}
2021-05-04 15:15:29,698 DEBUG probert.network:732 route_change DEL {'family': 2, 'type': 2, 'table': 255, 'dst': b'192.168.0.198', 'ifindex': 2}
2021-05-04 15:15:29,698 DEBUG subiquity.server.controllers.network:238 _call_client route_watch /tmp/tmpxyrpzwun/socket
2021-05-04 15:15:29,702 DEBUG subiquity.server.controllers.network:238 _call_client update_link /tmp/tmpxyrpzwun/socket
2021-05-04 15:15:29,872 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-05-04 15:15:29,892 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-05-04 15:15:29,892 DEBUG probert.network:586 event for link_change: CHANGE {'ifindex': 5, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth3'}
2021-05-04 15:15:29,892 DEBUG probert.network:673 link_change CHANGE {'ifindex': 5, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth3'}
2021-05-04 15:15:29,893 DEBUG root:39 start: subiquity/Network/_send_update: CHANGE eth3
2021-05-04 15:15:29,893 DEBUG subiquity.server.controllers.network:269 dev_info eth3 {'dhcp4': True}
2021-05-04 15:15:29,893 DEBUG subiquity.server.controllers.network:246 creating _call_client task /tmp/tmpxyrpzwun/socket update_link
2021-05-04 15:15:29,893 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: CHANGE eth3
2021-05-04 15:15:29,893 DEBUG subiquity.server.controllers.network:238 _call_client update_link /tmp/tmpxyrpzwun/socket
2021-05-04 15:15:29,898 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-05-04 15:15:29,920 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-05-04 15:15:29,921 DEBUG probert.network:586 event for link_change: CHANGE {'ifindex': 4, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth2'}
2021-05-04 15:15:29,921 DEBUG probert.network:586 event for link_change: CHANGE {'ifindex': 3, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth1'}
2021-05-04 15:15:29,921 DEBUG probert.network:673 link_change CHANGE {'ifindex': 4, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth2'}
2021-05-04 15:15:29,922 DEBUG root:39 start: subiquity/Network/_send_update: CHANGE eth2
2021-05-04 15:15:29,922 DEBUG subiquity.server.controllers.network:269 dev_info eth2 {'dhcp4': True}
2021-05-04 15:15:29,922 DEBUG subiquity.server.controllers.network:246 creating _call_client task /tmp/tmpxyrpzwun/socket update_link
2021-05-04 15:15:29,922 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: CHANGE eth2
2021-05-04 15:15:29,923 DEBUG probert.network:673 link_change CHANGE {'ifindex': 3, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth1'}
2021-05-04 15:15:29,923 DEBUG root:39 start: subiquity/Network/_send_update: CHANGE eth1
2021-05-04 15:15:29,923 DEBUG subiquity.server.controllers.network:269 dev_info eth1 {'dhcp4': True}
2021-05-04 15:15:29,923 DEBUG subiquity.server.controllers.network:246 creating _call_client task /tmp/tmpxyrpzwun/socket update_link
2021-05-04 15:15:29,923 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: CHANGE eth1
2021-05-04 15:15:29,925 DEBUG subiquity.server.controllers.network:238 _call_client update_link /tmp/tmpxyrpzwun/socket
2021-05-04 15:15:29,927 DEBUG subiquitycore.utils:83 arun_command ['netplan', 'apply'] exited with code 0
2021-05-04 15:15:29,930 DEBUG subiquity.server.controllers.network:238 _call_client update_link /tmp/tmpxyrpzwun/socket
2021-05-04 15:15:29,936 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-05-04 15:15:29,988 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 1
2021-05-04 15:15:29,989 DEBUG subiquitycore.controller.network:178 waiting 0.1 to let udev event queue settle
2021-05-04 15:15:30,091 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-05-04 15:15:30,108 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-05-04 15:15:30,108 DEBUG probert.network:586 event for link_change: CHANGE {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth0'}
2021-05-04 15:15:30,108 DEBUG probert.network:586 event for addr_change: NEW {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'192.168.0.198/24'}
2021-05-04 15:15:30,108 DEBUG probert.network:673 link_change CHANGE {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth0'}
2021-05-04 15:15:30,109 DEBUG root:39 start: subiquity/Network/_send_update: CHANGE eth0
2021-05-04 15:15:30,109 DEBUG subiquity.server.controllers.network:269 dev_info eth0 {'dhcp4': True}
2021-05-04 15:15:30,109 DEBUG subiquity.server.controllers.network:246 creating _call_client task /tmp/tmpxyrpzwun/socket update_link
2021-05-04 15:15:30,109 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: CHANGE eth0
2021-05-04 15:15:30,109 DEBUG probert.network:718 addr_change NEW {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'192.168.0.198/24'}
2021-05-04 15:15:30,110 DEBUG root:39 start: subiquity/Network/_send_update: CHANGE eth0
2021-05-04 15:15:30,110 DEBUG subiquity.server.controllers.network:269 dev_info eth0 {'dhcp4': True}
2021-05-04 15:15:30,110 DEBUG subiquity.server.controllers.network:246 creating _call_client task /tmp/tmpxyrpzwun/socket update_link
2021-05-04 15:15:30,110 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: CHANGE eth0
2021-05-04 15:15:30,110 DEBUG probert.network:732 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'192.168.0.198', 'ifindex': 2}
2021-05-04 15:15:30,110 DEBUG probert.network:732 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'192.168.0.255', 'ifindex': 2}
2021-05-04 15:15:30,110 DEBUG probert.network:732 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'192.168.0.0/24', 'ifindex': 2}
2021-05-04 15:15:30,110 DEBUG probert.network:732 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'192.168.0.0', 'ifindex': 2}
2021-05-04 15:15:30,111 DEBUG probert.network:732 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'192.168.0.1', 'ifindex': 2}
2021-05-04 15:15:30,111 DEBUG probert.network:732 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2021-05-04 15:15:30,111 DEBUG subiquitycore.controller.network:93 default routes {2}
2021-05-04 15:15:30,111 DEBUG subiquity.server.controllers.network:246 creating _call_client task /tmp/tmpxyrpzwun/socket route_watch
2021-05-04 15:15:30,111 DEBUG subiquity.server.controllers.network:238 _call_client update_link /tmp/tmpxyrpzwun/socket
2021-05-04 15:15:30,116 DEBUG subiquity.server.controllers.network:238 _call_client update_link /tmp/tmpxyrpzwun/socket
2021-05-04 15:15:30,128 DEBUG subiquity.server.controllers.network:238 _call_client route_watch /tmp/tmpxyrpzwun/socket
2021-05-04 15:15:38,992 DEBUG root:39 start: subiquity/Network/POST: 
2021-05-04 15:15:38,993 DEBUG subiquity.models.subiquity:146 model network is configured, to go set()
2021-05-04 15:15:38,993 DEBUG root:39 finish: subiquity/Network/POST: SUCCESS: 200 null
2021-05-04 15:15:38,994 INFO aiohttp.access:206  [04/May/2021:15:15:38 +0000] "POST /network HTTP/1.1" 200 189 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:38,996 DEBUG root:39 start: subiquity/Proxy/GET: 
2021-05-04 15:15:38,997 DEBUG root:39 finish: subiquity/Proxy/GET: SUCCESS: 200 ""
2021-05-04 15:15:38,997 INFO aiohttp.access:206  [04/May/2021:15:15:38 +0000] "GET /proxy HTTP/1.1" 200 187 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:39,016 DEBUG root:39 start: subiquity/Network/subscription_DELETE: 
2021-05-04 15:15:39,016 DEBUG subiquity.server.controllers.network:231 removed subscription /tmp/tmpxyrpzwun/socket
2021-05-04 15:15:39,017 DEBUG root:39 finish: subiquity/Network/subscription_DELETE: SUCCESS: 200 null
2021-05-04 15:15:39,017 INFO aiohttp.access:206  [04/May/2021:15:15:39 +0000] "DELETE /network/subscription?socket_path=%22/tmp/tmpxyrpzwun/socket%22 HTTP/1.1" 200 189 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:39,930 INFO root:39 finish: subiquity/Network/apply_config: SUCCESS: silent=True
2021-05-04 15:15:40,375 DEBUG root:39 start: subiquity/Proxy/POST: ""
2021-05-04 15:15:40,376 DEBUG subiquity.models.subiquity:146 model proxy is configured, to go set()
2021-05-04 15:15:40,376 DEBUG root:39 finish: subiquity/Proxy/POST: SUCCESS: 200 null
2021-05-04 15:15:40,376 INFO aiohttp.access:206  [04/May/2021:15:15:40 +0000] "POST /proxy HTTP/1.1" 200 189 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:40,379 DEBUG root:39 start: subiquity/Mirror/GET: 
2021-05-04 15:15:40,380 DEBUG root:39 finish: subiquity/Mirror/GET: SUCCESS: 200 "http://mx.archive.ubuntu.com/ubuntu"
2021-05-04 15:15:40,380 INFO aiohttp.access:206  [04/May/2021:15:15:40 +0000] "GET /mirror HTTP/1.1" 200 223 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:40,380 DEBUG subiquitycore.snapd:58 restarting snapd to pick up proxy config
2021-05-04 15:15:40,381 DEBUG subiquitycore.utils:48 run_command called: ['systemctl', 'daemon-reload']
2021-05-04 15:15:40,746 DEBUG subiquitycore.utils:61 run_command ['systemctl', 'daemon-reload'] exited with code 0
2021-05-04 15:15:40,747 DEBUG subiquitycore.utils:48 run_command called: ['systemctl', 'restart', 'snapd.service']
2021-05-04 15:15:41,246 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-05-04 15:15:41,264 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 1
2021-05-04 15:15:41,264 DEBUG subiquity.server.controller.filesystem:233 waiting 0.1 to let udev event queue settle
2021-05-04 15:15:41,318 DEBUG subiquitycore.utils:61 run_command ['systemctl', 'restart', 'snapd.service'] exited with code 0
2021-05-04 15:15:41,365 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-05-04 15:15:41,381 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-05-04 15:15:41,382 DEBUG subiquity.server.controller.filesystem:245 _udev_event change Device('/sys/devices/virtual/block/loop7')
2021-05-04 15:15:41,383 DEBUG subiquity.server.controller.filesystem:245 _udev_event change Device('/sys/devices/virtual/block/loop7')
2021-05-04 15:15:41,383 DEBUG subiquity.server.controller.filesystem:245 _udev_event change Device('/sys/devices/virtual/block/loop7')
2021-05-04 15:15:41,384 DEBUG root:39 start: subiquity/Filesystem/_probe: 
2021-05-04 15:15:41,389 DEBUG root:39 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2021-05-04 15:15:41,396 DEBUG root:39 start: subiquity/Mirror/POST: "http://mx.archive.ubuntu.com/ubuntu"
2021-05-04 15:15:41,398 DEBUG subiquity.models.subiquity:146 model mirror is configured, to go set()
2021-05-04 15:15:41,398 DEBUG root:39 finish: subiquity/Mirror/POST: SUCCESS: 200 null
2021-05-04 15:15:41,401 INFO aiohttp.access:206  [04/May/2021:15:15:41 +0000] "POST /mirror HTTP/1.1" 200 189 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:41,402 DEBUG root:39 start: subiquity/Refresh/GET: 
2021-05-04 15:15:41,402 DEBUG root:39 finish: subiquity/Refresh/GET: SUCCESS: 200 {"availability": "UNAVAILABLE", "current_snap_version": "21.01.2", "new_snap_...
2021-05-04 15:15:41,403 INFO aiohttp.access:206  [04/May/2021:15:15:41 +0000] "GET /refresh HTTP/1.1" 200 276 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:41,405 DEBUG root:39 start: subiquity/Filesystem/GET: 
2021-05-04 15:15:41,405 DEBUG root:39 finish: subiquity/Filesystem/GET: SUCCESS: 200 {"status": "PROBING", "bootloader": null, "error_report": null, "orig_config"...
2021-05-04 15:15:41,411 INFO aiohttp.access:206  [04/May/2021:15:15:41 +0000] "GET /storage HTTP/1.1" 200 319 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:41,412 DEBUG root:39 start: subiquity/Filesystem/GET: 
2021-05-04 15:15:41,818 DEBUG probert.dasd:131 Probing DASD devies
2021-05-04 15:15:41,819 DEBUG probert.dasd:134 DASD devices only present on s390x, arch=x86_64
2021-05-04 15:15:41,827 DEBUG curtin:1312 Extracting storage config from probe data
2021-05-04 15:15:41,867 DEBUG curtin:1319 Sorting extracted configurations
2021-05-04 15:15:41,867 INFO curtin:1338 Validating extracted storage config components
2021-05-04 15:15:41,906 DEBUG curtin:1357 Extracted (unmerged) storage config:
storage:
-   id: disk-xvda
    path: /dev/xvda
    type: disk

2021-05-04 15:15:41,906 DEBUG curtin:1359 Generating storage config dependencies
2021-05-04 15:15:41,906 DEBUG curtin:1365 Merging storage config dependencies
2021-05-04 15:15:41,908 DEBUG curtin:1372 Merged storage config:
storage:
    config:
    -   id: disk-xvda
        path: /dev/xvda
        type: disk
    version: 1

2021-05-04 15:15:41,908 DEBUG subiquity.models.filesystem:1567 exclusions set()
2021-05-04 15:15:41,909 DEBUG root:39 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False
2021-05-04 15:15:41,909 DEBUG root:39 finish: subiquity/Filesystem/_probe: SUCCESS: 
2021-05-04 15:15:41,909 DEBUG subiquity.models.filesystem:1632 mountpoints {}
2021-05-04 15:15:41,910 DEBUG root:39 finish: subiquity/Filesystem/GET: SUCCESS: 200 {"status": "DONE", "bootloader": "BIOS", "error_report": null, "orig_config":...
2021-05-04 15:15:41,916 INFO aiohttp.access:206  [04/May/2021:15:15:41 +0000] "GET /storage?wait=true HTTP/1.1" 200 4069 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:49,630 DEBUG root:39 start: subiquity/Filesystem/POST: [{"ptable": "gpt", "path": "/dev/xvda", "wipe": "superblock-recursive", "pres...
2021-05-04 15:15:49,630 DEBUG subiquity.models.filesystem:1567 exclusions set()
2021-05-04 15:15:49,631 DEBUG subiquity.models.subiquity:146 model filesystem is configured, to go set()
2021-05-04 15:15:49,631 DEBUG root:39 finish: subiquity/Filesystem/POST: SUCCESS: 200 null
2021-05-04 15:15:49,632 INFO aiohttp.access:206  [04/May/2021:15:15:49 +0000] "POST /storage HTTP/1.1" 200 189 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:49,633 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "NEEDS_CONFIRMATION", "confirming_tty": "", "error": null, "cloud_i...
2021-05-04 15:15:49,633 INFO aiohttp.access:206  [04/May/2021:15:14:55 +0000] "GET /meta/status?cur=%22WAITING%22 HTTP/1.1" 200 422 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:49,633 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "NEEDS_CONFIRMATION", "confirming_tty": "", "error": null, "cloud_i...
2021-05-04 15:15:49,634 INFO aiohttp.access:206  [04/May/2021:15:14:55 +0000] "GET /meta/status?cur=%22WAITING%22 HTTP/1.1" 200 422 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:49,635 INFO aiohttp.access:206  [04/May/2021:15:15:49 +0000] "GET /identity HTTP/1.1" 200 183 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:49,636 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:15:49,638 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:15:51,605 INFO root:39 start: subiquity/Meta/confirm_POST: 
2021-05-04 15:15:51,605 INFO root:39 finish: subiquity/Meta/confirm_POST: SUCCESS: 200 null
2021-05-04 15:15:51,606 INFO aiohttp.access:206  [04/May/2021:15:15:51 +0000] "POST /meta/confirm?tty=%22/dev/tty1%22 HTTP/1.1" 200 189 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:51,606 INFO root:39 start: subiquity/Install/install/curtin_install: installing system
2021-05-04 15:15:51,607 DEBUG subiquity.server.controllers.install:188 curtin_install
2021-05-04 15:15:51,609 DEBUG subiquity.models.subiquity:343 merging config from <subiquity.models.subiquity.DebconfSelectionsModel object at 0x7f2b02aa6e10>
2021-05-04 15:15:51,612 DEBUG subiquity.models.subiquity:343 merging config from <subiquity.models.filesystem.FilesystemModel object at 0x7f2b02aa60f0>
2021-05-04 15:15:51,613 DEBUG subiquity.models.filesystem:1632 mountpoints {'/': 'mount-0'}
2021-05-04 15:15:51,614 DEBUG subiquity.models.subiquity:343 merging config from <subiquity.models.keyboard.KeyboardModel object at 0x7f2b02aaf2e8>
2021-05-04 15:15:51,616 DEBUG subiquity.models.subiquity:343 merging config from <subiquity.models.mirror.MirrorModel object at 0x7f2b02aaf438>
2021-05-04 15:15:51,617 DEBUG subiquity.models.subiquity:343 merging config from <subiquity.models.network.NetworkModel object at 0x7f2b02aaf710>
2021-05-04 15:15:51,621 DEBUG subiquity.models.subiquity:343 merging config from <subiquity.models.proxy.ProxyModel object at 0x7f2b02aaf0f0>
2021-05-04 15:15:51,640 DEBUG subiquity.server.controllers.install:200 curtin install cmd: ['/snap/subiquity/2280/usr/bin/python3', '-m', 'curtin', '--showtrace', '-c', '/var/log/installer/subiquity-curtin-install.conf', 'install']
2021-05-04 15:15:51,640 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1825', '/snap/subiquity/2280/usr/bin/python3', '-m', 'curtin', '--showtrace', '-c', '/var/log/installer/subiquity-curtin-install.conf', 'install']
2021-05-04 15:15:51,661 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini...
2021-05-04 15:15:51,662 INFO aiohttp.access:206  [04/May/2021:15:15:49 +0000] "GET /meta/status?cur=%22NEEDS_CONFIRMATION%22 HTTP/1.1" 200 420 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:51,663 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini...
2021-05-04 15:15:51,663 INFO aiohttp.access:206  [04/May/2021:15:15:49 +0000] "GET /meta/status?cur=%22NEEDS_CONFIRMATION%22 HTTP/1.1" 200 420 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:51,665 DEBUG root:39 start: subiquity/Identity/GET: 
2021-05-04 15:15:51,665 DEBUG root:39 finish: subiquity/Identity/GET: SUCCESS: 200 {"realname": "", "username": "", "crypted_password": "", "hostname": ""}
2021-05-04 15:15:51,666 INFO aiohttp.access:206  [04/May/2021:15:15:51 +0000] "GET /identity HTTP/1.1" 200 258 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:15:51,666 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:15:51,672 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:15:53,173 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install: curtin command install
2021-05-04 15:15:53,174 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-early: preparing for installation
2021-05-04 15:15:53,174 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-early: SUCCESS: preparing for installation
2021-05-04 15:15:53,175 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning: configuring storage
2021-05-04 15:15:53,175 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin: running 'curtin block-meta simple'
2021-05-04 15:15:54,980 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: curtin command block-meta
2021-05-04 15:15:55,241 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/clear-holders: removing previous storage devices
2021-05-04 15:15:57,732 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/clear-holders: SUCCESS: removing previous storage devices
2021-05-04 15:15:57,732 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/: configuring disk: disk-xvda
2021-05-04 15:15:57,997 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/: SUCCESS: configuring disk: disk-xvda
2021-05-04 15:15:57,999 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-0
2021-05-04 15:16:00,320 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring partition: partition-0
2021-05-04 15:16:00,323 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-1
2021-05-04 15:16:01,728 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring partition: partition-1
2021-05-04 15:16:01,729 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring format: format-0
2021-05-04 15:16:04,161 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring format: format-0
2021-05-04 15:16:04,166 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring mount: mount-0
2021-05-04 15:16:04,430 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring mount: mount-0
2021-05-04 15:16:04,920 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin: SUCCESS: running 'curtin block-meta simple'
2021-05-04 15:16:04,920 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning: SUCCESS: configuring storage
2021-05-04 15:16:04,921 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-extract: writing install sources to disk
2021-05-04 15:16:04,922 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-extract/builtin: running 'curtin extract'
2021-05-04 15:16:06,670 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-extract/builtin/cmd-extract: curtin command extract
2021-05-04 15:16:06,672 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-extract/builtin/cmd-extract/: acquiring and extracting image from cp:///media/filesystem
2021-05-04 15:16:25,596 DEBUG root:39 start: subiquity/Identity/POST: {"realname": "Arturo F Lever Bravo", "username": "afleverb", "crypted_passwor...
2021-05-04 15:16:25,597 DEBUG subiquity.models.subiquity:146 model identity is configured, to go set()
2021-05-04 15:16:25,597 DEBUG root:39 finish: subiquity/Identity/POST: SUCCESS: 200 null
2021-05-04 15:16:25,598 INFO aiohttp.access:206  [04/May/2021:15:16:25 +0000] "POST /identity HTTP/1.1" 200 189 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:16:25,600 DEBUG root:39 start: subiquity/SSH/GET: 
2021-05-04 15:16:25,601 DEBUG root:39 finish: subiquity/SSH/GET: SUCCESS: 200 {"install_server": false, "allow_pw": true, "authorized_keys": []}
2021-05-04 15:16:25,601 INFO aiohttp.access:206  [04/May/2021:15:16:25 +0000] "GET /ssh HTTP/1.1" 200 252 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:16:30,502 DEBUG root:39 start: subiquity/SSH/POST: {"install_server": true, "allow_pw": true, "authorized_keys": []}
2021-05-04 15:16:30,506 DEBUG subiquity.models.subiquity:146 model ssh is configured, to go set()
2021-05-04 15:16:30,507 DEBUG root:39 finish: subiquity/SSH/POST: SUCCESS: 200 null
2021-05-04 15:16:30,511 INFO aiohttp.access:206  [04/May/2021:15:16:30 +0000] "POST /ssh HTTP/1.1" 200 189 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:16:30,512 DEBUG root:39 start: subiquity/SnapList/GET: 
2021-05-04 15:16:30,650 DEBUG root:39 finish: subiquity/SnapList/GET: SUCCESS: 200 {"status": "DONE", "snaps": [{"name": "microk8s", "summary": "Lightweight Kub...
2021-05-04 15:16:30,650 INFO aiohttp.access:206  [04/May/2021:15:16:30 +0000] "GET /snaplist HTTP/1.1" 200 46939 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:16:34,974 DEBUG root:39 start: subiquity/SnapList/POST: []
2021-05-04 15:16:34,975 DEBUG subiquity.models.subiquity:146 model snaplist is configured, to go set()
2021-05-04 15:16:34,975 DEBUG root:39 finish: subiquity/SnapList/POST: SUCCESS: 200 null
2021-05-04 15:16:34,976 INFO aiohttp.access:206  [04/May/2021:15:16:34 +0000] "POST /snaplist HTTP/1.1" 200 189 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:17:16,215 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-extract/builtin/cmd-extract/: SUCCESS: acquiring and extracting image from cp:///media/filesystem
2021-05-04 15:17:17,419 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-extract/builtin: SUCCESS: running 'curtin extract'
2021-05-04 15:17:17,420 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-extract: SUCCESS: writing install sources to disk
2021-05-04 15:17:17,421 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks: configuring installed system
2021-05-04 15:17:17,421 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/000-configure-run: running '/snap/bin/subiquity.subiquity-configure-run'
2021-05-04 15:17:20,089 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/000-configure-run: SUCCESS: running '/snap/bin/subiquity.subiquity-configure-run'
2021-05-04 15:17:20,090 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt: running '/snap/bin/subiquity.subiquity-configure-apt /snap/subiquity/2280/usr/bin/python3 true'
2021-05-04 15:17:22,668 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-apt-config: curtin command apt-config
2021-05-04 15:17:23,418 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-apt-config: SUCCESS: curtin command apt-config
2021-05-04 15:17:24,820 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-in-target: curtin command in-target
2021-05-04 15:17:45,921 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-in-target: SUCCESS: curtin command in-target
2021-05-04 15:17:45,922 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt: SUCCESS: running '/snap/bin/subiquity.subiquity-configure-apt /snap/subiquity/2280/usr/bin/python3 true'
2021-05-04 15:17:45,922 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin: running 'curtin curthooks'
2021-05-04 15:17:48,303 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks: curtin command curthooks
2021-05-04 15:17:48,305 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-apt-config: configuring apt configuring apt
2021-05-04 15:17:48,958 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-apt-config: SUCCESS: configuring apt configuring apt
2021-05-04 15:17:49,245 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-missing-packages: installing missing packages
2021-05-04 15:17:49,246 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-missing-packages: SUCCESS: installing missing packages
2021-05-04 15:17:49,246 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-iscsi-service: configuring iscsi service
2021-05-04 15:17:49,246 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-iscsi-service: SUCCESS: configuring iscsi service
2021-05-04 15:17:49,247 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-mdadm-service: configuring raid (mdadm) service
2021-05-04 15:17:49,248 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-mdadm-service: SUCCESS: configuring raid (mdadm) service
2021-05-04 15:17:49,248 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-kernel: installing kernel
2021-05-04 15:20:13,630 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-kernel: SUCCESS: installing kernel
2021-05-04 15:20:13,631 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/setting-up-swap: setting up swap
2021-05-04 15:20:13,881 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/setting-up-swap: SUCCESS: setting up swap
2021-05-04 15:20:13,882 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/apply-networking-config: apply networking config
2021-05-04 15:20:13,883 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/apply-networking-config: SUCCESS: apply networking config
2021-05-04 15:20:13,884 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-etc-fstab: writing etc/fstab
2021-05-04 15:20:13,884 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-etc-fstab: SUCCESS: writing etc/fstab
2021-05-04 15:20:13,885 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-multipath: configuring multipath
2021-05-04 15:20:15,942 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-multipath: SUCCESS: configuring multipath
2021-05-04 15:20:15,942 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/system-upgrade: updating packages on target system
2021-05-04 15:20:15,943 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/system-upgrade: SUCCESS: updating packages on target system
2021-05-04 15:20:15,944 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/pollinate-user-agent: configuring pollinate user-agent on target
2021-05-04 15:20:15,944 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/pollinate-user-agent: SUCCESS: configuring pollinate user-agent on target
2021-05-04 15:20:15,945 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/updating-initramfs-configuration: updating initramfs configuration
2021-05-04 15:21:01,183 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/updating-initramfs-configuration: SUCCESS: updating initramfs configuration
2021-05-04 15:21:01,184 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-bootloader: configuring target system bootloader
2021-05-04 15:21:01,184 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/install-grub: installing grub to target devices
2021-05-04 15:21:07,668 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/install-grub: SUCCESS: installing grub to target devices
2021-05-04 15:21:07,669 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-bootloader: SUCCESS: configuring target system bootloader
2021-05-04 15:21:07,670 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks: SUCCESS: curtin command curthooks
2021-05-04 15:21:08,668 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin: SUCCESS: running 'curtin curthooks'
2021-05-04 15:21:08,669 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks: SUCCESS: configuring installed system
2021-05-04 15:21:08,670 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-hook: finalizing installation
2021-05-04 15:21:08,672 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-hook/builtin: running 'curtin hook'
2021-05-04 15:21:11,447 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1825', '/snap/subiquity/2280/usr/bin/python3', '-m', 'curtin', '--showtrace', '-c', '/var/log/installer/subiquity-curtin-install.conf', 'install'] exited with code 0
2021-05-04 15:21:11,448 DEBUG subiquity.server.controllers.install:209 curtin_install completed: 0
2021-05-04 15:21:11,448 INFO root:39 finish: subiquity/Install/install/curtin_install: SUCCESS: installing system
2021-05-04 15:21:11,453 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "POST_WAIT", "confirming_tty": "/dev/tty1", "error": null, "cloud_i...
2021-05-04 15:21:11,523 INFO aiohttp.access:206  [04/May/2021:15:15:51 +0000] "GET /meta/status?cur=%22RUNNING%22 HTTP/1.1" 200 422 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:21:11,523 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "POST_WAIT", "confirming_tty": "/dev/tty1", "error": null, "cloud_i...
2021-05-04 15:21:11,524 INFO aiohttp.access:206  [04/May/2021:15:15:51 +0000] "GET /meta/status?cur=%22RUNNING%22 HTTP/1.1" 200 422 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:21:11,531 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:21:11,532 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:21:16,641 DEBUG subiquity.server.controllers.install:262 waited 5.099999999999998 seconds for events to drain
2021-05-04 15:21:16,641 INFO root:39 start: subiquity/Install/install/postinstall: final system configuration
2021-05-04 15:21:16,642 DEBUG subiquity.models.filesystem:1632 mountpoints {'/': 'mount-0'}
2021-05-04 15:21:16,655 DEBUG root:39 start: subiquity/Install/install/postinstall/configure_cloud_init: configuring cloud-init
2021-05-04 15:21:16,658 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "POST_RUNNING", "confirming_tty": "/dev/tty1", "error": null, "clou...
2021-05-04 15:21:16,658 INFO aiohttp.access:206  [04/May/2021:15:21:11 +0000] "GET /meta/status?cur=%22POST_WAIT%22 HTTP/1.1" 200 425 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:21:16,659 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "POST_RUNNING", "confirming_tty": "/dev/tty1", "error": null, "clou...
2021-05-04 15:21:16,659 INFO aiohttp.access:206  [04/May/2021:15:21:11 +0000] "GET /meta/status?cur=%22POST_WAIT%22 HTTP/1.1" 200 425 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:21:16,663 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:21:16,673 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:21:16,696 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-05-04 15:21:16,739 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-05-04 15:21:16,740 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-05-04 15:21:16,749 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-05-04 15:21:16,749 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-05-04 15:21:16,759 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-05-04 15:21:16,759 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-05-04 15:21:16,767 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-05-04 15:21:16,767 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-05-04 15:21:16,776 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-05-04 15:21:16,776 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-05-04 15:21:16,784 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-05-04 15:21:16,785 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-05-04 15:21:16,793 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-05-04 15:21:16,793 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-05-04 15:21:16,801 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-05-04 15:21:16,801 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-05-04 15:21:16,809 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-05-04 15:21:16,809 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-05-04 15:21:16,817 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-05-04 15:21:16,827 DEBUG root:39 finish: subiquity/Install/install/postinstall/configure_cloud_init: SUCCESS: configuring cloud-init
2021-05-04 15:21:16,828 DEBUG root:39 start: subiquity/Install/install/postinstall/install_openssh-server: installing openssh-server
2021-05-04 15:21:16,829 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1825', '/snap/subiquity/2280/usr/bin/python3', '-m', 'curtin', 'system-install', '-t', '/target', '--', 'openssh-server']
2021-05-04 15:21:34,676 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1825', '/snap/subiquity/2280/usr/bin/python3', '-m', 'curtin', 'system-install', '-t', '/target', '--', 'openssh-server'] exited with code 0
2021-05-04 15:21:34,677 DEBUG root:39 finish: subiquity/Install/install/postinstall/install_openssh-server: SUCCESS: installing openssh-server
2021-05-04 15:21:34,677 DEBUG root:39 start: subiquity/Install/install/postinstall/restore_apt_config: restoring apt configuration
2021-05-04 15:21:34,677 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1825', 'umount', '/target/etc/apt']
2021-05-04 15:21:34,894 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1825', 'umount', '/target/etc/apt'] exited with code 0
2021-05-04 15:21:34,894 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1825', '/snap/subiquity/2280/usr/bin/python3', '-m', 'curtin', 'in-target', '-t', '/target', '--', 'apt-get', 'update']
2021-05-04 15:21:39,902 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1825', '/snap/subiquity/2280/usr/bin/python3', '-m', 'curtin', 'in-target', '-t', '/target', '--', 'apt-get', 'update'] exited with code 0
2021-05-04 15:21:39,903 DEBUG root:39 finish: subiquity/Install/install/postinstall/restore_apt_config: SUCCESS: restoring apt configuration
2021-05-04 15:21:39,904 INFO root:39 finish: subiquity/Install/install/postinstall: SUCCESS: final system configuration
2021-05-04 15:21:39,904 DEBUG root:39 start: subiquity/Install/install/run_unattended_upgrades: downloading and installing security updates
2021-05-04 15:21:39,905 DEBUG subiquitycore.utils:94 astart_command called: ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1825', '/snap/subiquity/2280/usr/bin/python3', '-m', 'curtin', 'in-target', '-t', '/target', '--', 'unattended-upgrades', '-v']
2021-05-04 15:21:39,913 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "UU_RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_...
2021-05-04 15:21:39,914 INFO aiohttp.access:206  [04/May/2021:15:21:16 +0000] "GET /meta/status?cur=%22POST_RUNNING%22 HTTP/1.1" 200 423 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:21:39,914 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "UU_RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_...
2021-05-04 15:21:39,915 INFO aiohttp.access:206  [04/May/2021:15:21:16 +0000] "GET /meta/status?cur=%22POST_RUNNING%22 HTTP/1.1" 200 423 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:21:39,918 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:21:39,926 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:25:02,934 DEBUG root:39 finish: subiquity/Install/install/run_unattended_upgrades: SUCCESS: downloading and installing security updates
2021-05-04 15:25:03,042 DEBUG root:39 finish: subiquity/Install/install: SUCCESS: 
2021-05-04 15:25:03,094 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "DONE", "confirming_tty": "/dev/tty1", "error": null, "cloud_init_o...
2021-05-04 15:25:03,215 INFO aiohttp.access:206  [04/May/2021:15:21:39 +0000] "GET /meta/status?cur=%22UU_RUNNING%22 HTTP/1.1" 200 417 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:25:03,216 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "DONE", "confirming_tty": "/dev/tty1", "error": null, "cloud_init_o...
2021-05-04 15:25:03,216 INFO aiohttp.access:206  [04/May/2021:15:21:39 +0000] "GET /meta/status?cur=%22UU_RUNNING%22 HTTP/1.1" 200 417 "-" "Python/3.6 aiohttp/3.7.3"
2021-05-04 15:25:03,216 DEBUG root:39 start: subiquity/Late/run: 
2021-05-04 15:25:03,217 DEBUG root:39 finish: subiquity/Late/run: SUCCESS: 
2021-05-04 15:25:03,218 DEBUG root:39 start: subiquity/Reboot/copy_logs_to_target: 
2021-05-04 15:25:03,218 DEBUG subiquitycore.utils:74 arun_command called: ['cp', '-aT', '/var/log/installer', '/target/var/log/installer']
2021-05-04 15:25:03,264 INFO root:39 start: subiquity/Meta/status_GET: 
2021-05-04 15:25:03,265 INFO root:39 start: subiquity/Meta/status_GET: