2021-11-12 09:32:38,669 INFO subiquity:102 Starting Subiquity server revision 2651
2021-11-12 09:32:38,669 INFO subiquity:103 Arguments passed: ['/snap/subiquity/2651/usr/bin/subiquity-server']
2021-11-12 09:32:38,670 DEBUG asyncio:54 Using selector: EpollSelector
2021-11-12 09:32:38,672 DEBUG subiquitycore.prober:34 Prober() init finished, data:None
2021-11-12 09:32:38,674 DEBUG curtin:89 Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (capture=True)
2021-11-12 09:32:38,688 DEBUG subiquitycore.netplan:111 config for zz-all-en = {'dhcp4': True, 'match': {'name': 'en*'}}
2021-11-12 09:32:38,688 DEBUG subiquitycore.netplan:111 config for zz-all-eth = {'dhcp4': True, 'match': {'name': 'eth*'}}
2021-11-12 09:32:38,696 DEBUG subiquitycore.utils:74 arun_command called: ['cloud-init', 'status', '--wait']
2021-11-12 09:32:39,066 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET: 
2021-11-12 09:32:39,067 DEBUG curtin.reporting.finish.subiquity/Meta/status_GET:45 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "CLOUD_INIT_WAIT", "confirming_tty": "", "error": null, "cloud_init...
2021-11-12 09:32:39,067 INFO aiohttp.access:206  [12/Nov/2021:09:32:39 +0000] "GET /meta/status HTTP/1.1" 200 425 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:32:39,097 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET: 
2021-11-12 09:33:07,784 DEBUG subiquitycore.utils:83 arun_command ['cloud-init', 'status', '--wait'] exited with code 0
2021-11-12 09:33:07,785 DEBUG subiquity.server.server:436 waited 29.08920192718506s for cloud-init
2021-11-12 09:33:07,788 DEBUG subiquity.server.server:438 loading cloud config
2021-11-12 09:33:07,788 DEBUG cloudinit.util:1308 Reading from /etc/cloud/cloud.cfg (quiet=False)
2021-11-12 09:33:07,789 DEBUG cloudinit.util:1319 Read 3487 bytes from /etc/cloud/cloud.cfg
2021-11-12 09:33:07,789 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 3487 with allowed root types (<class 'dict'>,)
2021-11-12 09:33:07,816 DEBUG cloudinit.util:1308 Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2021-11-12 09:33:07,816 DEBUG cloudinit.util:1319 Read 301 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2021-11-12 09:33:07,817 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 301 with allowed root types (<class 'dict'>,)
2021-11-12 09:33:07,821 DEBUG cloudinit.util:1308 Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2021-11-12 09:33:07,821 DEBUG cloudinit.util:1319 Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2021-11-12 09:33:07,821 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 2070 with allowed root types (<class 'dict'>,)
2021-11-12 09:33:07,834 DEBUG cloudinit.util:1308 Reading from /run/cloud-init/cloud.cfg (quiet=False)
2021-11-12 09:33:07,834 DEBUG cloudinit.util:1319 Read 35 bytes from /run/cloud-init/cloud.cfg
2021-11-12 09:33:07,834 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2021-11-12 09:33:07,836 DEBUG cloudinit.subp:221 Running command ['systemd-detect-virt', '--quiet', '--container'] with allowed return codes [0] (shell=False, capture=True)
2021-11-12 09:33:07,850 DEBUG cloudinit.util:1308 Reading from /etc/os-release (quiet=False)
2021-11-12 09:33:07,851 DEBUG cloudinit.util:1319 Read 382 bytes from /etc/os-release
2021-11-12 09:33:07,853 DEBUG cloudinit.util:1308 Reading from /proc/1/environ (quiet=False)
2021-11-12 09:33:07,853 DEBUG cloudinit.util:1319 Read 239 bytes from /proc/1/environ
2021-11-12 09:33:07,853 DEBUG cloudinit.util:1308 Reading from /proc/self/status (quiet=False)
2021-11-12 09:33:07,853 DEBUG cloudinit.util:1319 Read 1348 bytes from /proc/self/status
2021-11-12 09:33:07,854 DEBUG cloudinit.util:1308 Reading from /proc/cmdline (quiet=False)
2021-11-12 09:33:07,854 DEBUG cloudinit.util:1319 Read 48 bytes from /proc/cmdline
2021-11-12 09:33:07,854 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2021-11-12 09:33:07,854 DEBUG cloudinit.util:819 loaded blob returned None, returning default.
2021-11-12 09:33:07,855 DEBUG cloudinit.util:1308 Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2021-11-12 09:33:07,855 DEBUG cloudinit.util:1319 Read 0 bytes from /var/lib/cloud/instance/cloud-config.txt
2021-11-12 09:33:07,855 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2021-11-12 09:33:07,856 DEBUG cloudinit.util:819 loaded blob returned None, returning default.
2021-11-12 09:33:07,857 DEBUG cloudinit.util:1308 Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
2021-11-12 09:33:07,857 DEBUG cloudinit.util:1319 Read 7436 bytes from /var/lib/cloud/instance/obj.pkl
2021-11-12 09:33:07,876 DEBUG cloudinit.util:1308 Reading from /run/cloud-init/.instance-id (quiet=False)
2021-11-12 09:33:07,876 DEBUG cloudinit.util:1319 Read 8 bytes from /run/cloud-init/.instance-id
2021-11-12 09:33:07,876 DEBUG cloudinit.stages:248 restored from cache with run check: DataSourceNoCloud [seed=/var/lib/cloud/seed/nocloud][dsmode=net]
2021-11-12 09:33:07,877 DEBUG cloudinit.util:1308 Reading from /etc/cloud/cloud.cfg (quiet=False)
2021-11-12 09:33:07,877 DEBUG cloudinit.util:1319 Read 3487 bytes from /etc/cloud/cloud.cfg
2021-11-12 09:33:07,877 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 3487 with allowed root types (<class 'dict'>,)
2021-11-12 09:33:07,903 DEBUG cloudinit.util:1308 Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2021-11-12 09:33:07,903 DEBUG cloudinit.util:1319 Read 301 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2021-11-12 09:33:07,903 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 301 with allowed root types (<class 'dict'>,)
2021-11-12 09:33:07,905 DEBUG cloudinit.util:1308 Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2021-11-12 09:33:07,905 DEBUG cloudinit.util:1319 Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2021-11-12 09:33:07,905 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 2070 with allowed root types (<class 'dict'>,)
2021-11-12 09:33:07,909 DEBUG cloudinit.util:1308 Reading from /run/cloud-init/cloud.cfg (quiet=False)
2021-11-12 09:33:07,909 DEBUG cloudinit.util:1319 Read 35 bytes from /run/cloud-init/cloud.cfg
2021-11-12 09:33:07,909 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2021-11-12 09:33:07,910 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2021-11-12 09:33:07,910 DEBUG cloudinit.util:819 loaded blob returned None, returning default.
2021-11-12 09:33:07,910 DEBUG cloudinit.util:1308 Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2021-11-12 09:33:07,910 DEBUG cloudinit.util:1319 Read 0 bytes from /var/lib/cloud/instance/cloud-config.txt
2021-11-12 09:33:07,910 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2021-11-12 09:33:07,911 DEBUG cloudinit.util:819 loaded blob returned None, returning default.
2021-11-12 09:33:07,912 DEBUG cloudinit.stages:83 Using distro class <class 'cloudinit.distros.ubuntu.Distro'>
2021-11-12 09:33:07,915 DEBUG subiquitycore.utils:48 run_command called: ['ssh-keygen', '-lf', '/home/installer/.ssh/authorized_keys']
2021-11-12 09:33:08,013 DEBUG subiquitycore.utils:61 run_command ['ssh-keygen', '-lf', '/home/installer/.ssh/authorized_keys'] exited with code 255
2021-11-12 09:33:08,013 DEBUG subiquitycore.ssh:49 ssh-keygen -lf /home/installer/.ssh/authorized_keys failed '/home/installer/.ssh/authorized_keys is not a public key file.\r\n'
2021-11-12 09:33:08,013 DEBUG subiquitycore.utils:48 run_command called: chpasswd
2021-11-12 09:33:08,038 DEBUG subiquitycore.utils:61 run_command chpasswd exited with code 0
2021-11-12 09:33:08,038 DEBUG subiquity.server.server:390 load_autoinstall_config only_early True
2021-11-12 09:33:08,040 DEBUG subiquity.server.server:390 load_autoinstall_config only_early False
2021-11-12 09:33:08,041 DEBUG subiquitycore.core:113 starting controllers
2021-11-12 09:33:08,041 DEBUG subiquity.models.subiquity:162 model locale for postinstall is configured, to go {'ssh', 'timezone', 'identity', 'packages', 'userdata', 'snaplist'}
2021-11-12 09:33:08,047 DEBUG probert.network:585 event for link_change: NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2021-11-12 09:33:08,047 DEBUG probert.network:585 event for link_change: NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth0'}
2021-11-12 09:33:08,047 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'}
2021-11-12 09:33:08,047 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2021-11-12 09:33:08,047 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::94b1:a2ff:fe46:ddaf/64'}
2021-11-12 09:33:08,049 DEBUG probert.network:672 link_change NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2021-11-12 09:33:08,109 DEBUG subiquitycore.models.network:421 new_link 1 lo lo
2021-11-12 09:33:08,109 DEBUG subiquitycore.models.network:423 ignoring based on type
2021-11-12 09:33:08,109 DEBUG probert.network:672 link_change NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth0'}
2021-11-12 09:33:08,165 DEBUG subiquitycore.models.network:421 new_link 2 eth0 eth
2021-11-12 09:33:08,166 DEBUG subiquitycore.models.network:454 new_link 2 eth0 with config {'dhcp4': True}
2021-11-12 09:33:08,166 DEBUG root:39 start: subiquity/Network/_send_update: NEW eth0
2021-11-12 09:33:08,166 DEBUG subiquity.server.controllers.network:354 dev_info eth0 {'dhcp4': True}
2021-11-12 09:33:08,166 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: NEW eth0
2021-11-12 09:33:08,166 DEBUG probert.network:717 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'}
2021-11-12 09:33:08,167 DEBUG probert.network:717 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2021-11-12 09:33:08,167 DEBUG probert.network:717 addr_change NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::94b1:a2ff:fe46:ddaf/64'}
2021-11-12 09:33:08,167 DEBUG root:39 start: subiquity/Network/_send_update: CHANGE eth0
2021-11-12 09:33:08,167 DEBUG subiquity.server.controllers.network:354 dev_info eth0 {'dhcp4': True}
2021-11-12 09:33:08,167 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: CHANGE eth0
2021-11-12 09:33:08,167 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'127.0.0.0', 'ifindex': 1}
2021-11-12 09:33:08,167 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.0/8', 'ifindex': 1}
2021-11-12 09:33:08,167 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.1', 'ifindex': 1}
2021-11-12 09:33:08,167 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'127.255.255.255', 'ifindex': 1}
2021-11-12 09:33:08,167 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'::1', 'ifindex': 1}
2021-11-12 09:33:08,167 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'fe80::/64', 'ifindex': 2}
2021-11-12 09:33:08,167 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'::1', 'ifindex': 1}
2021-11-12 09:33:08,167 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'fe80::94b1:a2ff:fe46:ddaf', 'ifindex': 2}
2021-11-12 09:33:08,168 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 5, 'table': 255, 'dst': b'ff00::/8', 'ifindex': 2}
2021-11-12 09:33:08,220 DEBUG subiquitycore.core:116 controllers started
2021-11-12 09:33:08,220 INFO root:39 start: subiquity/apply_autoinstall_config: 
2021-11-12 09:33:08,220 DEBUG root:39 start: subiquity/Early/apply_autoinstall_config: 
2021-11-12 09:33:08,233 DEBUG root:39 finish: subiquity/Early/apply_autoinstall_config: SUCCESS: 
2021-11-12 09:33:08,233 DEBUG root:39 start: subiquity/Reporting/apply_autoinstall_config: 
2021-11-12 09:33:08,233 DEBUG root:39 finish: subiquity/Reporting/apply_autoinstall_config: SUCCESS: 
2021-11-12 09:33:08,234 DEBUG root:39 start: subiquity/Error/apply_autoinstall_config: 
2021-11-12 09:33:08,234 DEBUG root:39 finish: subiquity/Error/apply_autoinstall_config: SUCCESS: 
2021-11-12 09:33:08,234 DEBUG root:39 start: subiquity/Userdata/apply_autoinstall_config: 
2021-11-12 09:33:08,234 DEBUG root:39 finish: subiquity/Userdata/apply_autoinstall_config: SUCCESS: 
2021-11-12 09:33:08,235 DEBUG subiquity.models.subiquity:162 model userdata for postinstall is configured, to go {'ssh', 'timezone', 'identity', 'packages', 'snaplist'}
2021-11-12 09:33:08,235 DEBUG root:39 start: subiquity/Package/apply_autoinstall_config: 
2021-11-12 09:33:08,235 DEBUG root:39 finish: subiquity/Package/apply_autoinstall_config: SUCCESS: 
2021-11-12 09:33:08,235 DEBUG subiquity.models.subiquity:162 model packages for postinstall is configured, to go {'ssh', 'snaplist', 'timezone', 'identity'}
2021-11-12 09:33:08,235 DEBUG root:39 start: subiquity/Debconf/apply_autoinstall_config: 
2021-11-12 09:33:08,235 DEBUG root:39 finish: subiquity/Debconf/apply_autoinstall_config: SUCCESS: 
2021-11-12 09:33:08,236 DEBUG subiquity.models.subiquity:162 model debconf_selections for install is configured, to go {'filesystem', 'mirror', 'kernel', 'keyboard', 'network', 'proxy'}
2021-11-12 09:33:08,236 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Locale as interactive
2021-11-12 09:33:08,236 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Refresh as interactive
2021-11-12 09:33:08,236 DEBUG root:39 start: subiquity/Kernel/apply_autoinstall_config: 
2021-11-12 09:33:08,236 DEBUG root:39 finish: subiquity/Kernel/apply_autoinstall_config: SUCCESS: 
2021-11-12 09:33:08,236 DEBUG subiquity.models.subiquity:162 model kernel for install is configured, to go {'filesystem', 'mirror', 'keyboard', 'network', 'proxy'}
2021-11-12 09:33:08,237 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Keyboard as interactive
2021-11-12 09:33:08,237 DEBUG root:39 start: subiquity/Zdev/apply_autoinstall_config: 
2021-11-12 09:33:08,237 DEBUG root:39 finish: subiquity/Zdev/apply_autoinstall_config: SUCCESS: 
2021-11-12 09:33:08,237 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Network as interactive
2021-11-12 09:33:08,237 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Proxy as interactive
2021-11-12 09:33:08,237 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Mirror as interactive
2021-11-12 09:33:08,237 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Filesystem as interactive
2021-11-12 09:33:08,237 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Identity as interactive
2021-11-12 09:33:08,237 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping SSH as interactive
2021-11-12 09:33:08,237 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping SnapList as interactive
2021-11-12 09:33:08,237 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping TimeZone as interactive
2021-11-12 09:33:08,237 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Install as interactive
2021-11-12 09:33:08,238 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Updates as interactive
2021-11-12 09:33:08,238 DEBUG root:39 start: subiquity/Late/apply_autoinstall_config: 
2021-11-12 09:33:08,238 DEBUG root:39 finish: subiquity/Late/apply_autoinstall_config: SUCCESS: 
2021-11-12 09:33:08,238 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Reboot as interactive
2021-11-12 09:33:08,238 INFO root:39 finish: subiquity/apply_autoinstall_config: SUCCESS: 
2021-11-12 09:33:08,239 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2021-11-12 09:33:08,239 INFO aiohttp.access:206  [12/Nov/2021:09:32:39 +0000] "GET /meta/status?cur=%22CLOUD_INIT_WAIT%22 HTTP/1.1" 200 417 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:33:08,239 DEBUG root:39 start: subiquity/Refresh/configure_snapd: 
2021-11-12 09:33:08,240 DEBUG root:39 start: subiquity/Refresh/configure_snapd/get_details: 
2021-11-12 09:33:08,252 DEBUG root:39 start: subiquity/Refresh/check_for_update: 
2021-11-12 09:33:08,277 DEBUG root:39 start: subiquity/Install/install: 
2021-11-12 09:33:08,278 DEBUG root:39 start: subiquity/Filesystem/_probe: 
2021-11-12 09:33:08,278 DEBUG root:39 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2021-11-12 09:33:08,279 INFO root:39 start: subiquity/Meta/status_GET: 
2021-11-12 09:33:08,280 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2021-11-12 09:33:08,280 INFO aiohttp.access:206  [12/Nov/2021:09:33:08 +0000] "GET /meta/status?cur=null HTTP/1.1" 200 417 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:33:08,281 INFO root:39 start: subiquity/Meta/client_variant_POST: 
2021-11-12 09:33:08,281 DEBUG subiquity.models.subiquity:162 model timezone for postinstall is configured, to go {'ssh', 'snaplist', 'identity'}
2021-11-12 09:33:08,281 INFO root:39 finish: subiquity/Meta/client_variant_POST: SUCCESS: 200 null
2021-11-12 09:33:08,282 INFO aiohttp.access:206  [12/Nov/2021:09:33:08 +0000] "POST /meta/client_variant?variant=%22server%22 HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:33:08,282 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/snaps/subiquity HTTP/1.1" 200 975
2021-11-12 09:33:08,283 DEBUG root:39 finish: subiquity/Refresh/configure_snapd/get_details: SUCCESS: current version of snap is: '21.08.2'
2021-11-12 09:33:08,283 DEBUG root:39 start: subiquity/Refresh/configure_snapd/switching: switching subiquity to stable/ubuntu-20.04.3
2021-11-12 09:33:08,291 INFO root:39 start: subiquity/Meta/status_GET: 
2021-11-12 09:33:08,292 DEBUG root:39 start: subiquity/Locale/GET: 
2021-11-12 09:33:08,293 DEBUG root:39 finish: subiquity/Locale/GET: SUCCESS: 200 "C.UTF-8"
2021-11-12 09:33:08,293 INFO aiohttp.access:206  [12/Nov/2021:09:33:08 +0000] "GET /locale HTTP/1.1" 200 200 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:33:08,296 DEBUG urllib3.connectionpool:396 http://localhost:None "POST /v2/snaps/subiquity HTTP/1.1" 202 81
2021-11-12 09:33:08,334 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/changes/4 HTTP/1.1" 200 594
2021-11-12 09:33:08,335 DEBUG root:39 finish: subiquity/Refresh/configure_snapd/switching: SUCCESS: switched to stable/ubuntu-20.04.3
2021-11-12 09:33:08,336 DEBUG root:39 finish: subiquity/Refresh/configure_snapd: SUCCESS: 
2021-11-12 09:33:08,727 DEBUG probert.dasd:131 Probing DASD devies
2021-11-12 09:33:08,729 DEBUG probert.dasd:134 DASD devices only present on s390x, arch=x86_64
2021-11-12 09:33:08,858 DEBUG curtin:1294 Extracting storage config from probe data
2021-11-12 09:33:08,858 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2021-11-12 09:33:08,859 DEBUG curtin:86 /dev/sr0 is multipath device partition? False
2021-11-12 09:33:08,859 DEBUG curtin:73 /dev/xvda is multipath device member? False
2021-11-12 09:33:08,859 DEBUG curtin:86 /dev/xvda is multipath device partition? False
2021-11-12 09:33:08,859 DEBUG curtin:61 /dev/xvda is multipath device? False
2021-11-12 09:33:08,859 DEBUG curtin:86 /dev/xvda is multipath device partition? False
2021-11-12 09:33:08,859 DEBUG curtin:61 /dev/xvda is multipath device? False
2021-11-12 09:33:08,894 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2021-11-12 09:33:08,895 DEBUG curtin:1301 Sorting extracted configurations
2021-11-12 09:33:08,895 INFO curtin:1320 Validating extracted storage config components
2021-11-12 09:33:08,925 DEBUG curtin:1339 Extracted (unmerged) storage config:
storage:
-   id: disk-xvda
    path: /dev/xvda
    type: disk

2021-11-12 09:33:08,925 DEBUG curtin:1341 Generating storage config dependencies
2021-11-12 09:33:08,926 DEBUG curtin:1347 Merging storage config dependencies
2021-11-12 09:33:08,929 DEBUG curtin:1354 Merged storage config:
storage:
    config:
    -   id: disk-xvda
        path: /dev/xvda
        type: disk
    version: 1

2021-11-12 09:33:08,929 DEBUG subiquity.models.filesystem:1121 exclusions set()
2021-11-12 09:33:08,931 DEBUG root:39 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False
2021-11-12 09:33:08,932 DEBUG root:39 finish: subiquity/Filesystem/_probe: SUCCESS: 
2021-11-12 09:33:09,384 INFO root:39 start: subiquity/Meta/status_GET: 
2021-11-12 09:33:09,385 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2021-11-12 09:33:09,385 INFO aiohttp.access:206  [12/Nov/2021:09:33:09 +0000] "GET /meta/status HTTP/1.1" 200 417 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:33:09,392 INFO root:39 start: subiquity/Meta/status_GET: 
2021-11-12 09:33:09,393 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2021-11-12 09:33:09,393 INFO aiohttp.access:206  [12/Nov/2021:09:33:09 +0000] "GET /meta/status?cur=null HTTP/1.1" 200 417 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:33:09,394 INFO root:39 start: subiquity/Meta/status_GET: 
2021-11-12 09:33:09,395 INFO root:39 start: subiquity/Meta/client_variant_POST: 
2021-11-12 09:33:09,396 DEBUG subiquity.models.subiquity:162 model timezone for postinstall is configured, to go {'ssh', 'snaplist', 'identity'}
2021-11-12 09:33:09,396 INFO root:39 finish: subiquity/Meta/client_variant_POST: SUCCESS: 200 null
2021-11-12 09:33:09,397 INFO aiohttp.access:206  [12/Nov/2021:09:33:09 +0000] "POST /meta/client_variant?variant=%22server%22 HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:33:09,398 INFO root:39 start: subiquity/Meta/ssh_info_GET: 
2021-11-12 09:33:09,399 INFO root:39 finish: subiquity/Meta/ssh_info_GET: SUCCESS: 200 null
2021-11-12 09:33:09,399 INFO aiohttp.access:206  [12/Nov/2021:09:33:09 +0000] "GET /meta/ssh_info HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:33:40,575 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?select=refresh HTTP/1.1" 500 257
2021-11-12 09:33:40,577 ERROR subiquity.server.controllers.refresh:173 checking for snap update failed
Traceback (most recent call last):
  File "/snap/subiquity/2651/lib/python3.6/site-packages/subiquity/server/controllers/refresh.py", line 171, in check_for_update
    result = await self.app.snapd.get('v2/find', select='refresh')
  File "/snap/subiquity/2651/lib/python3.6/site-packages/subiquitycore/snapd.py", line 180, in get
    response.raise_for_status()
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/requests/models.py", line 935, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 500 Server Error: Internal Server Error for url: http+unix://%2Frun%2Fsnapd.socket/v2/find?select=refresh
2021-11-12 09:33:40,579 DEBUG root:39 finish: subiquity/Refresh/check_for_update: SUCCESS: checking for snap update failed
2021-11-12 09:41:26,253 DEBUG root:39 start: subiquity/Locale/POST: "en_US.UTF-8"
2021-11-12 09:41:26,254 DEBUG subiquity.models.subiquity:162 model locale for postinstall is configured, to go {'ssh', 'snaplist', 'identity'}
2021-11-12 09:41:26,254 DEBUG root:39 finish: subiquity/Locale/POST: SUCCESS: 200 null
2021-11-12 09:41:26,255 INFO aiohttp.access:206  [12/Nov/2021:09:41:26 +0000] "POST /locale HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:41:26,257 DEBUG root:39 start: subiquity/Refresh/GET: 
2021-11-12 09:41:26,257 DEBUG root:39 finish: subiquity/Refresh/GET: SUCCESS: 200 {"availability": "UNKNOWN", "current_snap_version": "21.08.2", "new_snap_vers...
2021-11-12 09:41:26,258 INFO aiohttp.access:206  [12/Nov/2021:09:41:26 +0000] "GET /refresh HTTP/1.1" 200 278 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:41:26,261 DEBUG root:39 start: subiquity/Keyboard/GET: 
2021-11-12 09:41:26,290 DEBUG root:39 finish: subiquity/Keyboard/GET: SUCCESS: 200 {"setting": {"layout": "us", "variant": "", "toggle": null}, "layouts": [{"co...
2021-11-12 09:41:26,290 INFO aiohttp.access:206  [12/Nov/2021:09:41:26 +0000] "GET /keyboard HTTP/1.1" 200 39094 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:41:45,067 DEBUG root:39 start: subiquity/Keyboard/needs_toggle_GET: 
2021-11-12 09:41:45,068 DEBUG root:39 finish: subiquity/Keyboard/needs_toggle_GET: SUCCESS: 200 false
2021-11-12 09:41:45,068 INFO aiohttp.access:206  [12/Nov/2021:09:41:45 +0000] "GET /keyboard/needs_toggle?layout_code=%22it%22&variant_code=%22%22 HTTP/1.1" 200 196 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:41:45,071 DEBUG root:39 start: subiquity/Keyboard/POST: {"layout": "it", "variant": "", "toggle": null}
2021-11-12 09:41:45,072 DEBUG subiquitycore.utils:74 arun_command called: ['setupcon', '--save', '--force', '--keyboard-only']
2021-11-12 09:41:46,425 DEBUG subiquitycore.utils:83 arun_command ['setupcon', '--save', '--force', '--keyboard-only'] exited with code 0
2021-11-12 09:41:46,425 DEBUG subiquitycore.utils:74 arun_command called: ['/snap/subiquity/2651/bin/subiquity-loadkeys']
2021-11-12 09:41:46,436 DEBUG subiquitycore.utils:83 arun_command ['/snap/subiquity/2651/bin/subiquity-loadkeys'] exited with code 0
2021-11-12 09:41:46,437 DEBUG subiquity.models.subiquity:162 model keyboard for install is configured, to go {'filesystem', 'mirror', 'network', 'proxy'}
2021-11-12 09:41:46,438 DEBUG root:39 finish: subiquity/Keyboard/POST: SUCCESS: 200 null
2021-11-12 09:41:46,439 INFO aiohttp.access:206  [12/Nov/2021:09:41:45 +0000] "POST /keyboard HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:41:46,442 INFO aiohttp.access:206  [12/Nov/2021:09:41:46 +0000] "GET /zdev HTTP/1.1" 200 186 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:41:46,453 DEBUG root:39 start: subiquity/Network/GET: 
2021-11-12 09:41:46,455 DEBUG root:39 finish: subiquity/Network/GET: SUCCESS: 200 {"devices": [{"name": "eth0", "type": "eth", "is_connected": true, "bond_mast...
2021-11-12 09:41:46,459 INFO aiohttp.access:206  [12/Nov/2021:09:41:46 +0000] "GET /network HTTP/1.1" 200 899 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:41:46,459 INFO root:39 start: subiquity/Network/apply_config: silent=True
2021-11-12 09:41:46,461 DEBUG subiquitycore.controller.network:240 network config: 
network:
  ethernets:
    eth0:
      dhcp4: true
  version: 2

2021-11-12 09:41:46,467 DEBUG subiquitycore.netplan:111 config for eth0 = {'dhcp4': True}
2021-11-12 09:41:46,468 DEBUG subiquitycore.utils:74 arun_command called: ['netplan', 'apply']
2021-11-12 09:41:46,477 DEBUG root:39 start: subiquity/Network/subscription_PUT: 
2021-11-12 09:41:46,478 DEBUG subiquity.server.controllers.network:300 added subscription /tmp/tmpsj75t6qp/socket
2021-11-12 09:41:46,480 DEBUG root:39 finish: subiquity/Network/subscription_PUT: SUCCESS: 200 null
2021-11-12 09:41:46,489 INFO aiohttp.access:206  [12/Nov/2021:09:41:46 +0000] "PUT /network/subscription?socket_path=%22/tmp/tmpsj75t6qp/socket%22 HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:41:46,489 DEBUG subiquity.server.controllers.network:320 _call_client route_watch /tmp/tmpsj75t6qp/socket
2021-11-12 09:41:47,637 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-11-12 09:41:47,659 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-11-12 09:41:47,659 DEBUG probert.network:585 event for link_change: CHANGE {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth0'}
2021-11-12 09:41:47,659 DEBUG probert.network:672 link_change CHANGE {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth0'}
2021-11-12 09:41:47,660 DEBUG root:39 start: subiquity/Network/_send_update: CHANGE eth0
2021-11-12 09:41:47,661 DEBUG subiquity.server.controllers.network:354 dev_info eth0 {'dhcp4': True}
2021-11-12 09:41:47,661 DEBUG subiquity.server.controllers.network:331 creating _call_client task /tmp/tmpsj75t6qp/socket update_link
2021-11-12 09:41:47,661 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: CHANGE eth0
2021-11-12 09:41:47,662 DEBUG subiquity.server.controllers.network:320 _call_client update_link /tmp/tmpsj75t6qp/socket
2021-11-12 09:41:47,690 DEBUG subiquitycore.utils:83 arun_command ['netplan', 'apply'] exited with code 0
2021-11-12 09:41:57,692 INFO root:39 finish: subiquity/Network/apply_config: SUCCESS: silent=True
2021-11-12 09:43:28,074 DEBUG root:39 start: subiquity/Network/POST: 
2021-11-12 09:43:28,075 DEBUG subiquity.models.subiquity:162 model network for install is configured, to go {'filesystem', 'mirror', 'proxy'}
2021-11-12 09:43:28,075 DEBUG root:39 finish: subiquity/Network/POST: SUCCESS: 200 null
2021-11-12 09:43:28,076 INFO aiohttp.access:206  [12/Nov/2021:09:43:28 +0000] "POST /network HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:28,079 DEBUG root:39 start: subiquity/Proxy/GET: 
2021-11-12 09:43:28,080 DEBUG root:39 finish: subiquity/Proxy/GET: SUCCESS: 200 ""
2021-11-12 09:43:28,080 INFO aiohttp.access:206  [12/Nov/2021:09:43:28 +0000] "GET /proxy HTTP/1.1" 200 193 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:28,098 DEBUG root:39 start: subiquity/Network/subscription_DELETE: 
2021-11-12 09:43:28,099 DEBUG subiquity.server.controllers.network:313 removed subscription /tmp/tmpsj75t6qp/socket
2021-11-12 09:43:28,099 DEBUG root:39 finish: subiquity/Network/subscription_DELETE: SUCCESS: 200 null
2021-11-12 09:43:28,100 INFO aiohttp.access:206  [12/Nov/2021:09:43:28 +0000] "DELETE /network/subscription?socket_path=%22/tmp/tmpsj75t6qp/socket%22 HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:30,029 DEBUG root:39 start: subiquity/Proxy/POST: ""
2021-11-12 09:43:30,030 DEBUG subiquity.models.subiquity:162 model proxy for install is configured, to go {'filesystem', 'mirror'}
2021-11-12 09:43:30,030 DEBUG root:39 finish: subiquity/Proxy/POST: SUCCESS: 200 null
2021-11-12 09:43:30,031 INFO aiohttp.access:206  [12/Nov/2021:09:43:30 +0000] "POST /proxy HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:30,032 DEBUG subiquitycore.snapd:58 restarting snapd to pick up proxy config
2021-11-12 09:43:30,033 DEBUG subiquitycore.utils:48 run_command called: ['systemctl', 'daemon-reload']
2021-11-12 09:43:30,041 DEBUG root:39 start: subiquity/Mirror/GET: 
2021-11-12 09:43:30,041 DEBUG root:39 finish: subiquity/Mirror/GET: SUCCESS: 200 "http://archive.ubuntu.com/ubuntu"
2021-11-12 09:43:30,042 INFO aiohttp.access:206  [12/Nov/2021:09:43:30 +0000] "GET /mirror HTTP/1.1" 200 226 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:30,519 DEBUG subiquitycore.utils:61 run_command ['systemctl', 'daemon-reload'] exited with code 0
2021-11-12 09:43:30,520 DEBUG subiquitycore.utils:48 run_command called: ['systemctl', 'restart', 'snapd.service']
2021-11-12 09:43:30,660 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-11-12 09:43:30,694 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-11-12 09:43:30,694 DEBUG subiquity.server.controller.filesystem:393 _udev_event change Device('/sys/devices/virtual/block/loop7')
2021-11-12 09:43:30,695 DEBUG subiquity.server.controller.filesystem:393 _udev_event change Device('/sys/devices/virtual/block/loop7')
2021-11-12 09:43:30,695 DEBUG root:39 start: subiquity/Filesystem/_probe: 
2021-11-12 09:43:30,696 DEBUG root:39 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2021-11-12 09:43:30,722 DEBUG subiquitycore.utils:61 run_command ['systemctl', 'restart', 'snapd.service'] exited with code 0
2021-11-12 09:43:30,724 DEBUG subiquity.server.controllers.snaplist:59 loading list of snaps
2021-11-12 09:43:30,730 DEBUG urllib3.connectionpool:826 Starting new HTTPS connection (1): geoip.ubuntu.com
2021-11-12 09:43:30,734 DEBUG root:39 start: subiquity/Refresh/check_for_update: 
2021-11-12 09:43:30,740 DEBUG root:39 start: subiquity/SnapList/loader: 
2021-11-12 09:43:30,740 DEBUG root:39 start: subiquity/SnapList/loader/list: 
2021-11-12 09:43:30,744 ERROR subiquity.common.geoip:69 geoip lookup failed
Traceback (most recent call last):
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/urllib3/connection.py", line 144, in _new_conn
    (self.host, self.port), self.timeout, **extra_kw)
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/urllib3/util/connection.py", line 60, in create_connection
    for res in socket.getaddrinfo(host, port, family, socket.SOCK_STREAM):
  File "/snap/subiquity/2651/usr/lib/python3.6/socket.py", line 745, in getaddrinfo
    for res in _socket.getaddrinfo(host, port, family, type, proto, flags):
socket.gaierror: [Errno -3] Temporary failure in name resolution

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 601, in urlopen
    chunked=chunked)
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 346, in _make_request
    self._validate_conn(conn)
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 852, in _validate_conn
    conn.connect()
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/urllib3/connection.py", line 298, in connect
    conn = self._new_conn()
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/urllib3/connection.py", line 153, in _new_conn
    self, "Failed to establish a new connection: %s" % e)
urllib3.exceptions.NewConnectionError: <urllib3.connection.VerifiedHTTPSConnection object at 0x7fc7400e1a58>: Failed to establish a new connection: [Errno -3] Temporary failure in name resolution

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/requests/adapters.py", line 440, in send
    timeout=timeout
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 639, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/urllib3/util/retry.py", line 398, in increment
    raise MaxRetryError(_pool, url, error or ResponseError(cause))
urllib3.exceptions.MaxRetryError: HTTPSConnectionPool(host='geoip.ubuntu.com', port=443): Max retries exceeded with url: /lookup (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fc7400e1a58>: Failed to establish a new connection: [Errno -3] Temporary failure in name resolution',))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/snap/subiquity/2651/lib/python3.6/site-packages/subiquity/server/geoip.py", line 66, in _lookup
    requests.get, "https://geoip.ubuntu.com/lookup")
  File "/snap/subiquity/2651/lib/python3.6/site-packages/subiquitycore/async_helpers.py", line 46, in run_in_thread
    return await loop.run_in_executor(None, func, *args)
  File "/snap/subiquity/2651/usr/lib/python3.6/concurrent/futures/thread.py", line 56, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/requests/api.py", line 72, in get
    return request('get', url, params=params, **kwargs)
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/requests/api.py", line 58, in request
    return session.request(method=method, url=url, **kwargs)
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/requests/sessions.py", line 520, in request
    resp = self.send(prep, **send_kwargs)
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/requests/sessions.py", line 630, in send
    r = adapter.send(request, **kwargs)
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/requests/adapters.py", line 508, in send
    raise ConnectionError(e, request=request)
requests.exceptions.ConnectionError: HTTPSConnectionPool(host='geoip.ubuntu.com', port=443): Max retries exceeded with url: /lookup (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fc7400e1a58>: Failed to establish a new connection: [Errno -3] Temporary failure in name resolution',))
2021-11-12 09:43:31,104 DEBUG probert.dasd:131 Probing DASD devies
2021-11-12 09:43:31,105 DEBUG probert.dasd:134 DASD devices only present on s390x, arch=x86_64
2021-11-12 09:43:31,172 DEBUG curtin:1294 Extracting storage config from probe data
2021-11-12 09:43:31,173 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2021-11-12 09:43:31,173 DEBUG curtin:86 /dev/sr0 is multipath device partition? False
2021-11-12 09:43:31,173 DEBUG curtin:73 /dev/xvda is multipath device member? False
2021-11-12 09:43:31,173 DEBUG curtin:86 /dev/xvda is multipath device partition? False
2021-11-12 09:43:31,174 DEBUG curtin:61 /dev/xvda is multipath device? False
2021-11-12 09:43:31,174 DEBUG curtin:86 /dev/xvda is multipath device partition? False
2021-11-12 09:43:31,174 DEBUG curtin:61 /dev/xvda is multipath device? False
2021-11-12 09:43:31,205 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2021-11-12 09:43:31,205 DEBUG curtin:1301 Sorting extracted configurations
2021-11-12 09:43:31,205 INFO curtin:1320 Validating extracted storage config components
2021-11-12 09:43:31,241 DEBUG curtin:1339 Extracted (unmerged) storage config:
storage:
-   id: disk-xvda
    path: /dev/xvda
    type: disk

2021-11-12 09:43:31,241 DEBUG curtin:1341 Generating storage config dependencies
2021-11-12 09:43:31,242 DEBUG curtin:1347 Merging storage config dependencies
2021-11-12 09:43:31,244 DEBUG curtin:1354 Merged storage config:
storage:
    config:
    -   id: disk-xvda
        path: /dev/xvda
        type: disk
    version: 1

2021-11-12 09:43:31,246 DEBUG subiquity.models.filesystem:1121 exclusions set()
2021-11-12 09:43:31,246 DEBUG root:39 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False
2021-11-12 09:43:31,246 DEBUG root:39 finish: subiquity/Filesystem/_probe: SUCCESS: 
2021-11-12 09:43:31,655 DEBUG root:39 start: subiquity/Mirror/POST: "http://archive.ubuntu.com/ubuntu"
2021-11-12 09:43:31,655 DEBUG subiquity.models.subiquity:162 model mirror for install is configured, to go {'filesystem'}
2021-11-12 09:43:31,656 DEBUG root:39 finish: subiquity/Mirror/POST: SUCCESS: 200 null
2021-11-12 09:43:31,657 INFO aiohttp.access:206  [12/Nov/2021:09:43:31 +0000] "POST /mirror HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:31,660 DEBUG root:39 start: subiquity/Refresh/GET: 
2021-11-12 09:43:31,661 DEBUG root:39 finish: subiquity/Refresh/GET: SUCCESS: 200 {"availability": "UNKNOWN", "current_snap_version": "21.08.2", "new_snap_vers...
2021-11-12 09:43:31,661 INFO aiohttp.access:206  [12/Nov/2021:09:43:31 +0000] "GET /refresh HTTP/1.1" 200 278 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:31,666 DEBUG root:39 start: subiquity/Refresh/GET: 
2021-11-12 09:43:33,326 DEBUG root:39 start: subiquity/Filesystem/guided_GET: 
2021-11-12 09:43:33,327 DEBUG root:39 finish: subiquity/Filesystem/guided_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-xvda", "label...
2021-11-12 09:43:33,328 INFO aiohttp.access:206  [12/Nov/2021:09:43:33 +0000] "GET /storage/guided?min_size=6442450944 HTTP/1.1" 200 399 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:37,833 DEBUG root:39 start: subiquity/Filesystem/guided_POST: 
2021-11-12 09:43:37,833 DEBUG subiquity.common.filesystem.manipulator:371 bootloader Bootloader.BIOS
2021-11-12 09:43:37,837 DEBUG subiquity.common.filesystem.manipulator:115 _create_boot_partition - adding bios_grub partition
2021-11-12 09:43:37,837 DEBUG subiquity.models.filesystem:1302 add_partition: rounded size from 1048576 to 1048576
2021-11-12 09:43:37,837 DEBUG subiquity.models.filesystem:1302 add_partition: rounded size from 1073741824 to 1073741824
2021-11-12 09:43:37,837 DEBUG subiquity.models.filesystem:1372 adding ext4 to Partition(device=disk-xvda, size=1073741824, wipe='superblock', flag='', grub_device=None, id='partition-1')
2021-11-12 09:43:37,838 DEBUG subiquity.models.filesystem:1302 add_partition: rounded size from 52610203648 to 52610203648
2021-11-12 09:43:37,838 DEBUG subiquity.models.filesystem:1372 adding ext4 to LVM_LogicalVolume(name='ubuntu-lv', volgroup=lvm_volgroup-0, size=26304577536, wipe='superblock', id='lvm_partition-0')
2021-11-12 09:43:37,838 DEBUG subiquity.models.filesystem:1186 mountpoints {'/boot': 'mount-0', '/': 'mount-1'}
2021-11-12 09:43:37,839 DEBUG subiquity.models.filesystem:1181 cannot emit action to mount /boot until that for / is emitted
2021-11-12 09:43:37,841 DEBUG root:39 finish: subiquity/Filesystem/guided_POST: SUCCESS: 200 {"status": "DONE", "error_report": null, "bootloader": "BIOS", "orig_config":...
2021-11-12 09:43:37,849 INFO aiohttp.access:206  [12/Nov/2021:09:43:37 +0000] "POST /storage/guided?choice=%7B%22disk_id%22:+%22disk-xvda%22,+%22use_lvm%22:+true,+%22password%22:+null%7D HTTP/1.1" 200 5196 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:42,089 DEBUG root:39 start: subiquity/Filesystem/POST: [{"ptable": "gpt", "path": "/dev/xvda", "wipe": "superblock", "preserve": fal...
2021-11-12 09:43:42,090 DEBUG subiquity.models.filesystem:1121 exclusions set()
2021-11-12 09:43:42,091 DEBUG subiquity.models.subiquity:162 model filesystem for install is configured, to go set()
2021-11-12 09:43:42,091 DEBUG root:39 finish: subiquity/Filesystem/POST: SUCCESS: 200 null
2021-11-12 09:43:42,095 INFO aiohttp.access:206  [12/Nov/2021:09:43:42 +0000] "POST /storage HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:42,100 INFO aiohttp.access:206  [12/Nov/2021:09:43:42 +0000] "GET /identity HTTP/1.1" 200 189 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:42,101 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "NEEDS_CONFIRMATION", "confirming_tty": "", "error": null, "cloud_i...
2021-11-12 09:43:42,102 INFO aiohttp.access:206  [12/Nov/2021:09:33:08 +0000] "GET /meta/status?cur=%22WAITING%22 HTTP/1.1" 200 428 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:42,102 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "NEEDS_CONFIRMATION", "confirming_tty": "", "error": null, "cloud_i...
2021-11-12 09:43:42,103 INFO aiohttp.access:206  [12/Nov/2021:09:33:09 +0000] "GET /meta/status?cur=%22WAITING%22 HTTP/1.1" 200 428 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:42,107 INFO root:39 start: subiquity/Meta/status_GET: 
2021-11-12 09:43:42,124 INFO root:39 start: subiquity/Meta/status_GET: 
2021-11-12 09:43:44,750 INFO root:39 start: subiquity/Meta/confirm_POST: 
2021-11-12 09:43:44,751 INFO root:39 finish: subiquity/Meta/confirm_POST: SUCCESS: 200 null
2021-11-12 09:43:44,751 INFO aiohttp.access:206  [12/Nov/2021:09:43:44 +0000] "POST /meta/confirm?tty=%22/dev/tty1%22 HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:44,753 INFO root:39 start: subiquity/Install/install/curtin_install: installing system
2021-11-12 09:43:44,754 DEBUG subiquity.server.controllers.install:187 curtin_install
2021-11-12 09:43:44,755 DEBUG subiquity.models.subiquity:346 merging config from <subiquity.models.subiquity.DebconfSelectionsModel object at 0x7fc742e2f320>
2021-11-12 09:43:44,757 DEBUG subiquity.models.subiquity:346 merging config from <subiquity.models.filesystem.FilesystemModel object at 0x7fc742e2f358>
2021-11-12 09:43:44,759 DEBUG subiquity.models.filesystem:1186 mountpoints {'/': 'mount-1', '/boot': 'mount-0'}
2021-11-12 09:43:44,760 DEBUG subiquity.models.subiquity:346 merging config from <subiquity.models.kernel.KernelModel object at 0x7fc742e1f5c0>
2021-11-12 09:43:44,762 DEBUG subiquity.models.subiquity:346 merging config from <subiquity.models.keyboard.KeyboardModel object at 0x7fc742e1f4e0>
2021-11-12 09:43:44,764 DEBUG subiquity.models.subiquity:346 merging config from <subiquity.models.mirror.MirrorModel object at 0x7fc742e1f470>
2021-11-12 09:43:44,765 DEBUG subiquity.models.subiquity:346 merging config from <subiquity.models.network.NetworkModel object at 0x7fc742acea20>
2021-11-12 09:43:44,768 DEBUG subiquity.models.subiquity:346 merging config from <subiquity.models.proxy.ProxyModel object at 0x7fc742acefd0>
2021-11-12 09:43:44,796 DEBUG subiquity.server.controllers.install:192 curtin install cmd: ['/snap/subiquity/2651/usr/bin/python3', '-m', 'curtin', '--showtrace', '-c', '/var/log/installer/subiquity-curtin-install.conf', 'install']
2021-11-12 09:43:44,796 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1953', '/snap/subiquity/2651/usr/bin/python3', '-m', 'curtin', '--showtrace', '-c', '/var/log/installer/subiquity-curtin-install.conf', 'install']
2021-11-12 09:43:44,813 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini...
2021-11-12 09:43:44,829 INFO aiohttp.access:206  [12/Nov/2021:09:43:42 +0000] "GET /meta/status?cur=%22NEEDS_CONFIRMATION%22 HTTP/1.1" 200 426 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:44,829 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini...
2021-11-12 09:43:44,830 INFO aiohttp.access:206  [12/Nov/2021:09:43:42 +0000] "GET /meta/status?cur=%22NEEDS_CONFIRMATION%22 HTTP/1.1" 200 426 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:44,832 DEBUG root:39 start: subiquity/Identity/GET: 
2021-11-12 09:43:44,833 DEBUG root:39 finish: subiquity/Identity/GET: SUCCESS: 200 {"realname": "", "username": "", "crypted_password": "", "hostname": ""}
2021-11-12 09:43:44,833 INFO aiohttp.access:206  [12/Nov/2021:09:43:44 +0000] "GET /identity HTTP/1.1" 200 264 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:43:44,834 INFO root:39 start: subiquity/Meta/status_GET: 
2021-11-12 09:43:44,835 INFO root:39 start: subiquity/Meta/status_GET: 
2021-11-12 09:43:46,615 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install: curtin command install
2021-11-12 09:43:46,615 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-early: preparing for installation
2021-11-12 09:43:46,616 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-early: SUCCESS: preparing for installation
2021-11-12 09:43:46,616 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning: configuring storage
2021-11-12 09:43:46,616 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin: running 'curtin block-meta simple'
2021-11-12 09:43:47,596 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: curtin command block-meta
2021-11-12 09:43:47,859 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/clear-holders: removing previous storage devices
2021-11-12 09:43:50,667 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-11-12 09:43:50,676 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/: configuring disk: disk-xvda
2021-11-12 09:43:50,917 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/: SUCCESS: configuring disk: disk-xvda
2021-11-12 09:43:50,918 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-0
2021-11-12 09:43:52,174 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring partition: partition-0
2021-11-12 09:43:52,174 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-1
2021-11-12 09:43:53,828 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring partition: partition-1
2021-11-12 09:43:53,832 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring format: format-0
2021-11-12 09:43:54,701 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring format: format-0
2021-11-12 09:43:54,708 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-2
2021-11-12 09:43:56,815 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring partition: partition-2
2021-11-12 09:43:56,816 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring lvm_volgroup: lvm_volgroup-0
2021-11-12 09:43:57,409 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring lvm_volgroup: lvm_volgroup-0
2021-11-12 09:43:57,409 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring lvm_partition: lvm_partition-0
2021-11-12 09:43:58,367 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring lvm_partition: lvm_partition-0
2021-11-12 09:43:58,368 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring format: format-1
2021-11-12 09:43:58,818 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring format: format-1
2021-11-12 09:43:58,819 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring mount: mount-1
2021-11-12 09:43:59,082 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring mount: mount-1
2021-11-12 09:43:59,101 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring mount: mount-0
2021-11-12 09:43:59,613 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring mount: mount-0
2021-11-12 09:43:59,614 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin: SUCCESS: running 'curtin block-meta simple'
2021-11-12 09:43:59,615 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning: SUCCESS: configuring storage
2021-11-12 09:43:59,615 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-extract: writing install sources to disk
2021-11-12 09:43:59,616 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-extract/builtin: running 'curtin extract'
2021-11-12 09:44:01,110 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-extract/builtin/cmd-extract: curtin command extract
2021-11-12 09:44:01,110 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-11-12 09:44:02,971 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?select=refresh HTTP/1.1" 500 257
2021-11-12 09:44:02,974 ERROR subiquity.server.controllers.refresh:173 checking for snap update failed
Traceback (most recent call last):
  File "/snap/subiquity/2651/lib/python3.6/site-packages/subiquity/server/controllers/refresh.py", line 171, in check_for_update
    result = await self.app.snapd.get('v2/find', select='refresh')
  File "/snap/subiquity/2651/lib/python3.6/site-packages/subiquitycore/snapd.py", line 180, in get
    response.raise_for_status()
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/requests/models.py", line 935, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 500 Server Error: Internal Server Error for url: http+unix://%2Frun%2Fsnapd.socket/v2/find?select=refresh
2021-11-12 09:44:02,975 DEBUG root:39 finish: subiquity/Refresh/check_for_update: SUCCESS: checking for snap update failed
2021-11-12 09:44:02,981 DEBUG root:39 finish: subiquity/Refresh/GET: SUCCESS: 200 {"availability": "UNKNOWN", "current_snap_version": "21.08.2", "new_snap_vers...
2021-11-12 09:44:02,983 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?section=server HTTP/1.1" 400 543
2021-11-12 09:44:02,989 INFO aiohttp.access:206  [12/Nov/2021:09:43:31 +0000] "GET /refresh?wait=true HTTP/1.1" 200 278 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:44:02,990 ERROR subiquity.server.controllers.snaplist:80 loading list of snaps failed
Traceback (most recent call last):
  File "/snap/subiquity/2651/lib/python3.6/site-packages/subiquity/server/controllers/snaplist.py", line 78, in _load_list
    'v2/find', section=self.store_section)
  File "/snap/subiquity/2651/lib/python3.6/site-packages/subiquitycore/snapd.py", line 180, in get
    response.raise_for_status()
  File "/snap/subiquity/2651/usr/lib/python3/dist-packages/requests/models.py", line 935, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 400 Client Error: Bad Request for url: http+unix://%2Frun%2Fsnapd.socket/v2/find?section=server
2021-11-12 09:44:02,992 DEBUG root:39 finish: subiquity/SnapList/loader/list: SUCCESS: 
2021-11-12 09:44:02,992 DEBUG subiquity.server.controllers.snaplist:67 fetched list of 0 snaps
2021-11-12 09:44:03,007 DEBUG root:39 finish: subiquity/SnapList/loader: SUCCESS: 
2021-11-12 09:44:20,903 DEBUG root:39 start: subiquity/Identity/POST: {"realname": "ubuntu", "username": "ubuntu", "crypted_password": "$6$4AbBOXcX...
2021-11-12 09:44:20,904 DEBUG subiquity.models.subiquity:162 model identity for postinstall is configured, to go {'ssh', 'snaplist'}
2021-11-12 09:44:20,905 DEBUG root:39 finish: subiquity/Identity/POST: SUCCESS: 200 null
2021-11-12 09:44:20,905 INFO aiohttp.access:206  [12/Nov/2021:09:44:20 +0000] "POST /identity HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:44:20,909 DEBUG root:39 start: subiquity/SSH/GET: 
2021-11-12 09:44:20,909 DEBUG root:39 finish: subiquity/SSH/GET: SUCCESS: 200 {"install_server": false, "allow_pw": true, "authorized_keys": []}
2021-11-12 09:44:20,913 INFO aiohttp.access:206  [12/Nov/2021:09:44:20 +0000] "GET /ssh HTTP/1.1" 200 258 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:44:52,112 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-11-12 09:44:52,122 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-extract/builtin: SUCCESS: running 'curtin extract'
2021-11-12 09:44:52,123 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-extract: SUCCESS: writing install sources to disk
2021-11-12 09:44:52,124 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks: configuring installed system
2021-11-12 09:44:52,125 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt: running '/snap/subiquity/2651/bin/subiquity-configure-apt /snap/subiquity/2651/usr/bin/python3 false'
2021-11-12 09:44:53,255 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-apt-config: curtin command apt-config
2021-11-12 09:44:53,509 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-11-12 09:44:55,114 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-in-target: curtin command in-target
2021-11-12 09:44:55,866 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-11-12 09:44:55,867 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt: SUCCESS: running '/snap/subiquity/2651/bin/subiquity-configure-apt /snap/subiquity/2651/usr/bin/python3 false'
2021-11-12 09:44:55,868 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin: running 'curtin curthooks'
2021-11-12 09:44:57,277 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks: curtin command curthooks
2021-11-12 09:44:57,278 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-apt-config: configuring apt configuring apt
2021-11-12 09:44:57,538 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-11-12 09:44:57,539 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-missing-packages: installing missing packages
2021-11-12 09:44:57,796 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-missing-packages: SUCCESS: installing missing packages
2021-11-12 09:44:57,797 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-iscsi-service: configuring iscsi service
2021-11-12 09:44:57,798 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-iscsi-service: SUCCESS: configuring iscsi service
2021-11-12 09:44:57,798 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-mdadm-service: configuring raid (mdadm) service
2021-11-12 09:44:57,799 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-11-12 09:44:57,800 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-kernel: installing kernel
2021-11-12 09:45:48,767 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-kernel: SUCCESS: installing kernel
2021-11-12 09:45:48,768 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/setting-up-swap: setting up swap
2021-11-12 09:45:48,769 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/setting-up-swap: SUCCESS: setting up swap
2021-11-12 09:45:48,769 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/apply-networking-config: apply networking config
2021-11-12 09:45:48,770 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/apply-networking-config: SUCCESS: apply networking config
2021-11-12 09:45:48,770 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-etc-fstab: writing etc/fstab
2021-11-12 09:45:48,771 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-etc-fstab: SUCCESS: writing etc/fstab
2021-11-12 09:45:48,772 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-multipath: configuring multipath
2021-11-12 09:45:49,552 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-multipath: SUCCESS: configuring multipath
2021-11-12 09:45:49,553 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/system-upgrade: updating packages on target system
2021-11-12 09:45:49,554 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-11-12 09:45:49,554 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-11-12 09:45:49,576 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-11-12 09:45:49,585 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/updating-initramfs-configuration: updating initramfs configuration
2021-11-12 09:46:31,297 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/updating-initramfs-configuration: SUCCESS: updating initramfs configuration
2021-11-12 09:46:31,297 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-bootloader: configuring target system bootloader
2021-11-12 09:46:31,298 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/install-grub: installing grub to target devices
2021-11-12 09:46:37,611 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-11-12 09:46:37,612 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-bootloader: SUCCESS: configuring target system bootloader
2021-11-12 09:46:37,613 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks: SUCCESS: curtin command curthooks
2021-11-12 09:46:37,613 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin: SUCCESS: running 'curtin curthooks'
2021-11-12 09:46:37,614 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks: SUCCESS: configuring installed system
2021-11-12 09:46:37,614 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-hook: finalizing installation
2021-11-12 09:46:37,615 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-hook/builtin: running 'curtin hook'
2021-11-12 09:46:38,631 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1953', '/snap/subiquity/2651/usr/bin/python3', '-m', 'curtin', '--showtrace', '-c', '/var/log/installer/subiquity-curtin-install.conf', 'install'] exited with code 0
2021-11-12 09:46:38,631 DEBUG subiquity.server.controllers.install:196 curtin_install completed: 0
2021-11-12 09:46:38,631 INFO root:39 finish: subiquity/Install/install/curtin_install: SUCCESS: installing system
2021-11-12 09:46:38,862 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-hook/builtin/cmd-hook: curtin command hook
2021-11-12 09:46:38,863 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-hook/builtin/cmd-hook: SUCCESS: curtin command hook
2021-11-12 09:46:38,864 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-hook/builtin: SUCCESS: running 'curtin hook'
2021-11-12 09:46:38,865 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-hook: SUCCESS: finalizing installation
2021-11-12 09:46:38,866 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-late: executing late commands
2021-11-12 09:46:38,867 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-late: SUCCESS: executing late commands
2021-11-12 09:46:38,868 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install: SUCCESS: curtin command install
2021-11-12 09:46:38,934 DEBUG subiquity.server.controllers.install:248 waited 0.30000000000000004 seconds for events to drain
2021-11-12 09:46:38,936 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "POST_WAIT", "confirming_tty": "/dev/tty1", "error": null, "cloud_i...
2021-11-12 09:46:38,938 INFO aiohttp.access:206  [12/Nov/2021:09:43:44 +0000] "GET /meta/status?cur=%22RUNNING%22 HTTP/1.1" 200 428 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:46:38,938 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "POST_WAIT", "confirming_tty": "/dev/tty1", "error": null, "cloud_i...
2021-11-12 09:46:38,939 INFO aiohttp.access:206  [12/Nov/2021:09:43:44 +0000] "GET /meta/status?cur=%22RUNNING%22 HTTP/1.1" 200 428 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:46:38,942 INFO root:39 start: subiquity/Meta/status_GET: 
2021-11-12 09:46:38,943 INFO root:39 start: subiquity/Meta/status_GET: 
2021-11-12 09:50:58,547 DEBUG root:39 start: subiquity/SSH/POST: {"install_server": true, "allow_pw": true, "authorized_keys": []}
2021-11-12 09:50:58,548 DEBUG subiquity.models.subiquity:162 model ssh for postinstall is configured, to go {'snaplist'}
2021-11-12 09:50:58,548 DEBUG root:39 finish: subiquity/SSH/POST: SUCCESS: 200 null
2021-11-12 09:50:58,549 INFO aiohttp.access:206  [12/Nov/2021:09:50:58 +0000] "POST /ssh HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:50:58,551 DEBUG root:39 start: subiquity/SnapList/GET: 
2021-11-12 09:50:58,551 DEBUG subiquity.models.subiquity:162 model snaplist for postinstall is configured, to go set()
2021-11-12 09:50:58,552 DEBUG root:39 finish: subiquity/SnapList/GET: SUCCESS: 200 {"status": "FAILED", "snaps": [], "selections": []}
2021-11-12 09:50:58,552 INFO aiohttp.access:206  [12/Nov/2021:09:50:58 +0000] "GET /snaplist HTTP/1.1" 200 243 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:50:58,553 INFO root:39 start: subiquity/Install/install/postinstall: final system configuration
2021-11-12 09:50:58,555 DEBUG subiquity.models.filesystem:1186 mountpoints {'/': 'mount-1', '/boot': 'mount-0'}
2021-11-12 09:50:58,573 DEBUG root:39 start: subiquity/Install/install/postinstall/configure_cloud_init: configuring cloud-init
2021-11-12 09:50:58,576 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-12 09:50:58,583 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "POST_RUNNING", "confirming_tty": "/dev/tty1", "error": null, "clou...
2021-11-12 09:50:58,585 INFO aiohttp.access:206  [12/Nov/2021:09:46:38 +0000] "GET /meta/status?cur=%22POST_WAIT%22 HTTP/1.1" 200 431 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:50:58,585 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "POST_RUNNING", "confirming_tty": "/dev/tty1", "error": null, "clou...
2021-11-12 09:50:58,590 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-12 09:50:58,590 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-12 09:50:58,595 INFO aiohttp.access:206  [12/Nov/2021:09:46:38 +0000] "GET /meta/status?cur=%22POST_WAIT%22 HTTP/1.1" 200 431 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:50:58,600 INFO root:39 start: subiquity/Meta/status_GET: 
2021-11-12 09:50:58,601 INFO root:39 start: subiquity/Meta/status_GET: 
2021-11-12 09:50:58,603 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-12 09:50:58,603 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-12 09:50:58,612 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-12 09:50:58,613 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-12 09:50:58,623 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-12 09:50:58,623 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-12 09:50:58,634 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-12 09:50:58,635 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-12 09:50:58,645 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-12 09:50:58,646 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-12 09:50:58,656 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-12 09:50:58,656 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-12 09:50:58,665 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-12 09:50:58,666 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-12 09:50:58,676 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-12 09:50:58,676 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-12 09:50:58,686 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-12 09:50:58,696 DEBUG root:39 finish: subiquity/Install/install/postinstall/configure_cloud_init: SUCCESS: configuring cloud-init
2021-11-12 09:50:58,697 DEBUG root:39 start: subiquity/Install/install/postinstall/install_openssh-server: installing openssh-server
2021-11-12 09:50:58,697 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1953', '/snap/subiquity/2651/usr/bin/python3', '-m', 'curtin', 'system-install', '-t', '/target', '--', 'openssh-server']
2021-11-12 09:51:04,895 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1953', '/snap/subiquity/2651/usr/bin/python3', '-m', 'curtin', 'system-install', '-t', '/target', '--', 'openssh-server'] exited with code 0
2021-11-12 09:51:04,896 DEBUG root:39 finish: subiquity/Install/install/postinstall/install_openssh-server: SUCCESS: installing openssh-server
2021-11-12 09:51:04,898 DEBUG root:39 start: subiquity/Install/install/postinstall/restore_apt_config: restoring apt configuration
2021-11-12 09:51:04,899 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1953', 'umount', '/target/etc/apt']
2021-11-12 09:51:04,924 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1953', 'umount', '/target/etc/apt'] exited with code 0
2021-11-12 09:51:04,925 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1953', 'umount', '/target/var/lib/apt/lists']
2021-11-12 09:51:04,944 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1953', 'umount', '/target/var/lib/apt/lists'] exited with code 0
2021-11-12 09:51:04,945 DEBUG root:39 finish: subiquity/Install/install/postinstall/restore_apt_config: SUCCESS: restoring apt configuration
2021-11-12 09:51:04,946 INFO root:39 finish: subiquity/Install/install/postinstall: SUCCESS: final system configuration
2021-11-12 09:51:04,949 DEBUG root:39 finish: subiquity/Install/install: SUCCESS: 
2021-11-12 09:51:04,951 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "DONE", "confirming_tty": "/dev/tty1", "error": null, "cloud_init_o...
2021-11-12 09:51:04,955 INFO aiohttp.access:206  [12/Nov/2021:09:50:58 +0000] "GET /meta/status?cur=%22POST_RUNNING%22 HTTP/1.1" 200 423 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:51:04,956 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "DONE", "confirming_tty": "/dev/tty1", "error": null, "cloud_init_o...
2021-11-12 09:51:04,961 INFO aiohttp.access:206  [12/Nov/2021:09:50:58 +0000] "GET /meta/status?cur=%22POST_RUNNING%22 HTTP/1.1" 200 423 "-" "Python/3.6 aiohttp/3.7.4.post0"
2021-11-12 09:51:04,961 DEBUG root:39 start: subiquity/Late/run: 
2021-11-12 09:51:04,962 DEBUG root:39 finish: subiquity/Late/run: SUCCESS: 
2021-11-12 09:51:04,963 DEBUG root:39 start: subiquity/Reboot/copy_logs_to_target: 
2021-11-12 09:51:04,963 DEBUG subiquitycore.utils:74 arun_command called: ['cp', '-aT', '/var/log/installer', '/target/var/log/installer']
2021-11-12 09:51:04,971 INFO root:39 start: subiquity/Meta/status_GET: 
2021-11-12 09:51:04,972 INFO root:39 start: subiquity/Meta/status_GET: