File: //var/log/installer/subiquity-server-debug.log.1873
2022-01-22 14:28:56,636 INFO subiquity:102 Starting Subiquity server revision 2651
2022-01-22 14:28:56,636 INFO subiquity:103 Arguments passed: ['/snap/subiquity/2651/usr/bin/subiquity-server']
2022-01-22 14:28:56,636 DEBUG asyncio:54 Using selector: EpollSelector
2022-01-22 14:28:56,639 DEBUG subiquitycore.prober:34 Prober() init finished, data:None
2022-01-22 14:28:56,641 DEBUG curtin:89 Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (capture=True)
2022-01-22 14:28:56,651 DEBUG subiquitycore.netplan:111 config for zz-all-en = {'dhcp4': True, 'match': {'name': 'en*'}}
2022-01-22 14:28:56,651 DEBUG subiquitycore.netplan:111 config for zz-all-eth = {'dhcp4': True, 'match': {'name': 'eth*'}}
2022-01-22 14:28:56,660 DEBUG subiquitycore.utils:74 arun_command called: ['cloud-init', 'status', '--wait']
2022-01-22 14:28:57,084 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET:
2022-01-22 14:28:57,088 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...
2022-01-22 14:28:57,096 INFO aiohttp.access:206 [22/Jan/2022:14:28:57 +0000] "GET /meta/status HTTP/1.1" 200 425 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:28:57,112 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET:
2022-01-22 14:29:25,378 DEBUG subiquitycore.utils:83 arun_command ['cloud-init', 'status', '--wait'] exited with code 0
2022-01-22 14:29:25,378 DEBUG subiquity.server.server:436 waited 28.718003511428833s for cloud-init
2022-01-22 14:29:25,380 DEBUG subiquity.server.server:438 loading cloud config
2022-01-22 14:29:25,380 DEBUG cloudinit.util:1308 Reading from /etc/cloud/cloud.cfg (quiet=False)
2022-01-22 14:29:25,380 DEBUG cloudinit.util:1319 Read 3487 bytes from /etc/cloud/cloud.cfg
2022-01-22 14:29:25,380 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 3487 with allowed root types (<class 'dict'>,)
2022-01-22 14:29:25,415 DEBUG cloudinit.util:1308 Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2022-01-22 14:29:25,415 DEBUG cloudinit.util:1319 Read 301 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2022-01-22 14:29:25,415 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 301 with allowed root types (<class 'dict'>,)
2022-01-22 14:29:25,423 DEBUG cloudinit.util:1308 Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2022-01-22 14:29:25,423 DEBUG cloudinit.util:1319 Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2022-01-22 14:29:25,424 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 2070 with allowed root types (<class 'dict'>,)
2022-01-22 14:29:25,439 DEBUG cloudinit.util:1308 Reading from /run/cloud-init/cloud.cfg (quiet=False)
2022-01-22 14:29:25,439 DEBUG cloudinit.util:1319 Read 35 bytes from /run/cloud-init/cloud.cfg
2022-01-22 14:29:25,439 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2022-01-22 14:29:25,440 DEBUG cloudinit.subp:221 Running command ['systemd-detect-virt', '--quiet', '--container'] with allowed return codes [0] (shell=False, capture=True)
2022-01-22 14:29:25,464 DEBUG cloudinit.util:1308 Reading from /etc/os-release (quiet=False)
2022-01-22 14:29:25,464 DEBUG cloudinit.util:1319 Read 382 bytes from /etc/os-release
2022-01-22 14:29:25,466 DEBUG cloudinit.util:1308 Reading from /proc/1/environ (quiet=False)
2022-01-22 14:29:25,466 DEBUG cloudinit.util:1319 Read 239 bytes from /proc/1/environ
2022-01-22 14:29:25,466 DEBUG cloudinit.util:1308 Reading from /proc/self/status (quiet=False)
2022-01-22 14:29:25,466 DEBUG cloudinit.util:1319 Read 1347 bytes from /proc/self/status
2022-01-22 14:29:25,466 DEBUG cloudinit.util:1308 Reading from /proc/cmdline (quiet=False)
2022-01-22 14:29:25,466 DEBUG cloudinit.util:1319 Read 48 bytes from /proc/cmdline
2022-01-22 14:29:25,466 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2022-01-22 14:29:25,466 DEBUG cloudinit.util:819 loaded blob returned None, returning default.
2022-01-22 14:29:25,467 DEBUG cloudinit.util:1308 Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2022-01-22 14:29:25,467 DEBUG cloudinit.util:1319 Read 0 bytes from /var/lib/cloud/instance/cloud-config.txt
2022-01-22 14:29:25,467 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2022-01-22 14:29:25,467 DEBUG cloudinit.util:819 loaded blob returned None, returning default.
2022-01-22 14:29:25,468 DEBUG cloudinit.util:1308 Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
2022-01-22 14:29:25,468 DEBUG cloudinit.util:1319 Read 7436 bytes from /var/lib/cloud/instance/obj.pkl
2022-01-22 14:29:25,491 DEBUG cloudinit.util:1308 Reading from /run/cloud-init/.instance-id (quiet=False)
2022-01-22 14:29:25,491 DEBUG cloudinit.util:1319 Read 8 bytes from /run/cloud-init/.instance-id
2022-01-22 14:29:25,492 DEBUG cloudinit.stages:248 restored from cache with run check: DataSourceNoCloud [seed=/var/lib/cloud/seed/nocloud][dsmode=net]
2022-01-22 14:29:25,492 DEBUG cloudinit.util:1308 Reading from /etc/cloud/cloud.cfg (quiet=False)
2022-01-22 14:29:25,492 DEBUG cloudinit.util:1319 Read 3487 bytes from /etc/cloud/cloud.cfg
2022-01-22 14:29:25,492 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 3487 with allowed root types (<class 'dict'>,)
2022-01-22 14:29:25,532 DEBUG cloudinit.util:1308 Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2022-01-22 14:29:25,532 DEBUG cloudinit.util:1319 Read 301 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2022-01-22 14:29:25,533 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 301 with allowed root types (<class 'dict'>,)
2022-01-22 14:29:25,548 DEBUG cloudinit.util:1308 Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2022-01-22 14:29:25,548 DEBUG cloudinit.util:1319 Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2022-01-22 14:29:25,549 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 2070 with allowed root types (<class 'dict'>,)
2022-01-22 14:29:25,560 DEBUG cloudinit.util:1308 Reading from /run/cloud-init/cloud.cfg (quiet=False)
2022-01-22 14:29:25,561 DEBUG cloudinit.util:1319 Read 35 bytes from /run/cloud-init/cloud.cfg
2022-01-22 14:29:25,561 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2022-01-22 14:29:25,566 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2022-01-22 14:29:25,566 DEBUG cloudinit.util:819 loaded blob returned None, returning default.
2022-01-22 14:29:25,566 DEBUG cloudinit.util:1308 Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2022-01-22 14:29:25,566 DEBUG cloudinit.util:1319 Read 0 bytes from /var/lib/cloud/instance/cloud-config.txt
2022-01-22 14:29:25,567 DEBUG cloudinit.util:816 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2022-01-22 14:29:25,567 DEBUG cloudinit.util:819 loaded blob returned None, returning default.
2022-01-22 14:29:25,568 DEBUG cloudinit.stages:83 Using distro class <class 'cloudinit.distros.ubuntu.Distro'>
2022-01-22 14:29:25,585 DEBUG subiquitycore.utils:48 run_command called: ['ssh-keygen', '-lf', '/home/installer/.ssh/authorized_keys']
2022-01-22 14:29:25,806 DEBUG subiquitycore.utils:61 run_command ['ssh-keygen', '-lf', '/home/installer/.ssh/authorized_keys'] exited with code 255
2022-01-22 14:29:25,807 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'
2022-01-22 14:29:25,807 DEBUG subiquitycore.utils:48 run_command called: chpasswd
2022-01-22 14:29:25,863 DEBUG subiquitycore.utils:61 run_command chpasswd exited with code 0
2022-01-22 14:29:25,863 DEBUG subiquity.server.server:390 load_autoinstall_config only_early True
2022-01-22 14:29:25,870 DEBUG subiquity.server.server:390 load_autoinstall_config only_early False
2022-01-22 14:29:25,871 DEBUG subiquitycore.core:113 starting controllers
2022-01-22 14:29:25,871 DEBUG subiquity.models.subiquity:162 model locale for postinstall is configured, to go {'userdata', 'identity', 'packages', 'timezone', 'snaplist', 'ssh'}
2022-01-22 14:29:25,895 DEBUG probert.network:585 event for link_change: NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2022-01-22 14:29:25,895 DEBUG probert.network:585 event for link_change: NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth0'}
2022-01-22 14:29:25,895 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'}
2022-01-22 14:29:25,895 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2022-01-22 14:29:25,895 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::f841:cff:fe4a:cc65/64'}
2022-01-22 14:29:25,901 DEBUG probert.network:672 link_change NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2022-01-22 14:29:26,031 DEBUG subiquitycore.models.network:421 new_link 1 lo lo
2022-01-22 14:29:26,031 DEBUG subiquitycore.models.network:423 ignoring based on type
2022-01-22 14:29:26,031 DEBUG probert.network:672 link_change NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth0'}
2022-01-22 14:29:26,157 DEBUG subiquitycore.models.network:421 new_link 2 eth0 eth
2022-01-22 14:29:26,158 DEBUG subiquitycore.models.network:454 new_link 2 eth0 with config {'dhcp4': True}
2022-01-22 14:29:26,158 DEBUG root:39 start: subiquity/Network/_send_update: NEW eth0
2022-01-22 14:29:26,158 DEBUG subiquity.server.controllers.network:354 dev_info eth0 {'dhcp4': True}
2022-01-22 14:29:26,158 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: NEW eth0
2022-01-22 14:29:26,159 DEBUG probert.network:717 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'}
2022-01-22 14:29:26,159 DEBUG probert.network:717 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2022-01-22 14:29:26,159 DEBUG probert.network:717 addr_change NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::f841:cff:fe4a:cc65/64'}
2022-01-22 14:29:26,159 DEBUG root:39 start: subiquity/Network/_send_update: CHANGE eth0
2022-01-22 14:29:26,159 DEBUG subiquity.server.controllers.network:354 dev_info eth0 {'dhcp4': True}
2022-01-22 14:29:26,159 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: CHANGE eth0
2022-01-22 14:29:26,160 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'127.0.0.0', 'ifindex': 1}
2022-01-22 14:29:26,160 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.0/8', 'ifindex': 1}
2022-01-22 14:29:26,160 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.1', 'ifindex': 1}
2022-01-22 14:29:26,160 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'127.255.255.255', 'ifindex': 1}
2022-01-22 14:29:26,160 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'::1', 'ifindex': 1}
2022-01-22 14:29:26,160 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'fe80::/64', 'ifindex': 2}
2022-01-22 14:29:26,160 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'::1', 'ifindex': 1}
2022-01-22 14:29:26,160 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'fe80::f841:cff:fe4a:cc65', 'ifindex': 2}
2022-01-22 14:29:26,160 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 5, 'table': 255, 'dst': b'ff00::/8', 'ifindex': 2}
2022-01-22 14:29:26,277 DEBUG subiquitycore.core:116 controllers started
2022-01-22 14:29:26,277 INFO root:39 start: subiquity/apply_autoinstall_config:
2022-01-22 14:29:26,277 DEBUG root:39 start: subiquity/Early/apply_autoinstall_config:
2022-01-22 14:29:26,298 DEBUG root:39 finish: subiquity/Early/apply_autoinstall_config: SUCCESS:
2022-01-22 14:29:26,299 DEBUG root:39 start: subiquity/Reporting/apply_autoinstall_config:
2022-01-22 14:29:26,299 DEBUG root:39 finish: subiquity/Reporting/apply_autoinstall_config: SUCCESS:
2022-01-22 14:29:26,299 DEBUG root:39 start: subiquity/Error/apply_autoinstall_config:
2022-01-22 14:29:26,300 DEBUG root:39 finish: subiquity/Error/apply_autoinstall_config: SUCCESS:
2022-01-22 14:29:26,300 DEBUG root:39 start: subiquity/Userdata/apply_autoinstall_config:
2022-01-22 14:29:26,301 DEBUG root:39 finish: subiquity/Userdata/apply_autoinstall_config: SUCCESS:
2022-01-22 14:29:26,305 DEBUG subiquity.models.subiquity:162 model userdata for postinstall is configured, to go {'identity', 'packages', 'timezone', 'snaplist', 'ssh'}
2022-01-22 14:29:26,305 DEBUG root:39 start: subiquity/Package/apply_autoinstall_config:
2022-01-22 14:29:26,306 DEBUG root:39 finish: subiquity/Package/apply_autoinstall_config: SUCCESS:
2022-01-22 14:29:26,306 DEBUG subiquity.models.subiquity:162 model packages for postinstall is configured, to go {'timezone', 'identity', 'snaplist', 'ssh'}
2022-01-22 14:29:26,306 DEBUG root:39 start: subiquity/Debconf/apply_autoinstall_config:
2022-01-22 14:29:26,307 DEBUG root:39 finish: subiquity/Debconf/apply_autoinstall_config: SUCCESS:
2022-01-22 14:29:26,307 DEBUG subiquity.models.subiquity:162 model debconf_selections for install is configured, to go {'keyboard', 'mirror', 'proxy', 'kernel', 'filesystem', 'network'}
2022-01-22 14:29:26,307 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Locale as interactive
2022-01-22 14:29:26,308 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Refresh as interactive
2022-01-22 14:29:26,308 DEBUG root:39 start: subiquity/Kernel/apply_autoinstall_config:
2022-01-22 14:29:26,308 DEBUG root:39 finish: subiquity/Kernel/apply_autoinstall_config: SUCCESS:
2022-01-22 14:29:26,309 DEBUG subiquity.models.subiquity:162 model kernel for install is configured, to go {'keyboard', 'mirror', 'proxy', 'filesystem', 'network'}
2022-01-22 14:29:26,309 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Keyboard as interactive
2022-01-22 14:29:26,309 DEBUG root:39 start: subiquity/Zdev/apply_autoinstall_config:
2022-01-22 14:29:26,313 DEBUG root:39 finish: subiquity/Zdev/apply_autoinstall_config: SUCCESS:
2022-01-22 14:29:26,314 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Network as interactive
2022-01-22 14:29:26,314 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Proxy as interactive
2022-01-22 14:29:26,314 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Mirror as interactive
2022-01-22 14:29:26,314 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Filesystem as interactive
2022-01-22 14:29:26,314 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Identity as interactive
2022-01-22 14:29:26,315 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping SSH as interactive
2022-01-22 14:29:26,315 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping SnapList as interactive
2022-01-22 14:29:26,315 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping TimeZone as interactive
2022-01-22 14:29:26,315 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Install as interactive
2022-01-22 14:29:26,315 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Updates as interactive
2022-01-22 14:29:26,315 DEBUG root:39 start: subiquity/Late/apply_autoinstall_config:
2022-01-22 14:29:26,317 DEBUG root:39 finish: subiquity/Late/apply_autoinstall_config: SUCCESS:
2022-01-22 14:29:26,318 DEBUG subiquity.server.server:384 apply_autoinstall_config: skipping Reboot as interactive
2022-01-22 14:29:26,318 INFO root:39 finish: subiquity/apply_autoinstall_config: SUCCESS:
2022-01-22 14:29:26,318 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2022-01-22 14:29:26,325 INFO aiohttp.access:206 [22/Jan/2022:14:28:57 +0000] "GET /meta/status?cur=%22CLOUD_INIT_WAIT%22 HTTP/1.1" 200 417 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:29:26,325 DEBUG root:39 start: subiquity/Refresh/configure_snapd:
2022-01-22 14:29:26,326 DEBUG root:39 start: subiquity/Refresh/configure_snapd/get_details:
2022-01-22 14:29:26,327 DEBUG root:39 start: subiquity/Refresh/check_for_update:
2022-01-22 14:29:26,363 DEBUG root:39 start: subiquity/Install/install:
2022-01-22 14:29:26,364 DEBUG root:39 start: subiquity/Filesystem/_probe:
2022-01-22 14:29:26,373 DEBUG root:39 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2022-01-22 14:29:26,412 INFO root:39 start: subiquity/Meta/status_GET:
2022-01-22 14:29:26,413 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2022-01-22 14:29:26,423 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/snaps/subiquity HTTP/1.1" 200 975
2022-01-22 14:29:26,434 INFO aiohttp.access:206 [22/Jan/2022:14:29:26 +0000] "GET /meta/status?cur=null HTTP/1.1" 200 417 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:29:26,437 DEBUG root:39 finish: subiquity/Refresh/configure_snapd/get_details: SUCCESS: current version of snap is: '21.08.2'
2022-01-22 14:29:26,449 DEBUG root:39 start: subiquity/Refresh/configure_snapd/switching: switching subiquity to stable/ubuntu-20.04.3
2022-01-22 14:29:26,471 DEBUG urllib3.connectionpool:396 http://localhost:None "POST /v2/snaps/subiquity HTTP/1.1" 202 81
2022-01-22 14:29:26,474 INFO root:39 start: subiquity/Meta/status_GET:
2022-01-22 14:29:26,474 INFO root:39 start: subiquity/Meta/client_variant_POST:
2022-01-22 14:29:26,474 DEBUG subiquity.models.subiquity:162 model timezone for postinstall is configured, to go {'identity', 'snaplist', 'ssh'}
2022-01-22 14:29:26,475 INFO root:39 finish: subiquity/Meta/client_variant_POST: SUCCESS: 200 null
2022-01-22 14:29:26,487 INFO aiohttp.access:206 [22/Jan/2022:14:29:26 +0000] "POST /meta/client_variant?variant=%22server%22 HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:29:26,503 DEBUG root:39 start: subiquity/Locale/GET:
2022-01-22 14:29:26,503 DEBUG root:39 finish: subiquity/Locale/GET: SUCCESS: 200 "C.UTF-8"
2022-01-22 14:29:26,509 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/changes/4 HTTP/1.1" 200 594
2022-01-22 14:29:26,517 INFO aiohttp.access:206 [22/Jan/2022:14:29:26 +0000] "GET /locale HTTP/1.1" 200 200 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:29:26,518 DEBUG root:39 finish: subiquity/Refresh/configure_snapd/switching: SUCCESS: switched to stable/ubuntu-20.04.3
2022-01-22 14:29:26,518 DEBUG root:39 finish: subiquity/Refresh/configure_snapd: SUCCESS:
2022-01-22 14:29:26,915 DEBUG probert.dasd:131 Probing DASD devies
2022-01-22 14:29:26,915 DEBUG probert.dasd:134 DASD devices only present on s390x, arch=x86_64
2022-01-22 14:29:27,211 DEBUG curtin:1294 Extracting storage config from probe data
2022-01-22 14:29:27,211 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2022-01-22 14:29:27,211 DEBUG curtin:86 /dev/sr0 is multipath device partition? False
2022-01-22 14:29:27,211 DEBUG curtin:73 /dev/xvda is multipath device member? False
2022-01-22 14:29:27,211 DEBUG curtin:86 /dev/xvda is multipath device partition? False
2022-01-22 14:29:27,212 DEBUG curtin:61 /dev/xvda is multipath device? False
2022-01-22 14:29:27,212 DEBUG curtin:86 /dev/xvda is multipath device partition? False
2022-01-22 14:29:27,212 DEBUG curtin:61 /dev/xvda is multipath device? False
2022-01-22 14:29:27,261 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2022-01-22 14:29:27,261 DEBUG curtin:1301 Sorting extracted configurations
2022-01-22 14:29:27,261 INFO curtin:1320 Validating extracted storage config components
2022-01-22 14:29:27,300 DEBUG curtin:1339 Extracted (unmerged) storage config:
storage:
- id: disk-xvda
path: /dev/xvda
type: disk
2022-01-22 14:29:27,300 DEBUG curtin:1341 Generating storage config dependencies
2022-01-22 14:29:27,300 DEBUG curtin:1347 Merging storage config dependencies
2022-01-22 14:29:27,300 DEBUG curtin:1354 Merged storage config:
storage:
config:
- id: disk-xvda
path: /dev/xvda
type: disk
version: 1
2022-01-22 14:29:27,301 DEBUG subiquity.models.filesystem:1121 exclusions set()
2022-01-22 14:29:27,307 DEBUG root:39 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False
2022-01-22 14:29:27,307 DEBUG root:39 finish: subiquity/Filesystem/_probe: SUCCESS:
2022-01-22 14:29:28,560 INFO root:39 start: subiquity/Meta/status_GET:
2022-01-22 14:29:28,561 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2022-01-22 14:29:28,561 INFO aiohttp.access:206 [22/Jan/2022:14:29:28 +0000] "GET /meta/status HTTP/1.1" 200 417 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:29:28,571 INFO root:39 start: subiquity/Meta/status_GET:
2022-01-22 14:29:28,571 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2022-01-22 14:29:28,571 INFO aiohttp.access:206 [22/Jan/2022:14:29:28 +0000] "GET /meta/status?cur=null HTTP/1.1" 200 417 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:29:28,577 INFO root:39 start: subiquity/Meta/client_variant_POST:
2022-01-22 14:29:28,578 DEBUG subiquity.models.subiquity:162 model timezone for postinstall is configured, to go {'identity', 'snaplist', 'ssh'}
2022-01-22 14:29:28,578 INFO root:39 finish: subiquity/Meta/client_variant_POST: SUCCESS: 200 null
2022-01-22 14:29:28,578 INFO aiohttp.access:206 [22/Jan/2022:14:29:28 +0000] "POST /meta/client_variant?variant=%22server%22 HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:29:28,579 INFO root:39 start: subiquity/Meta/status_GET:
2022-01-22 14:29:28,581 INFO root:39 start: subiquity/Meta/ssh_info_GET:
2022-01-22 14:29:28,581 INFO root:39 finish: subiquity/Meta/ssh_info_GET: SUCCESS: 200 null
2022-01-22 14:29:28,581 INFO aiohttp.access:206 [22/Jan/2022:14:29:28 +0000] "GET /meta/ssh_info HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:29:58,819 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?select=refresh HTTP/1.1" 500 257
2022-01-22 14:29:58,821 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
2022-01-22 14:29:58,822 DEBUG root:39 finish: subiquity/Refresh/check_for_update: SUCCESS: checking for snap update failed
2022-01-22 14:43:22,628 DEBUG root:39 start: subiquity/Locale/POST: "en_US.UTF-8"
2022-01-22 14:43:22,628 DEBUG subiquity.models.subiquity:162 model locale for postinstall is configured, to go {'identity', 'snaplist', 'ssh'}
2022-01-22 14:43:22,628 DEBUG root:39 finish: subiquity/Locale/POST: SUCCESS: 200 null
2022-01-22 14:43:22,629 INFO aiohttp.access:206 [22/Jan/2022:14:43:22 +0000] "POST /locale HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:43:22,630 DEBUG root:39 start: subiquity/Refresh/GET:
2022-01-22 14:43:22,631 DEBUG root:39 finish: subiquity/Refresh/GET: SUCCESS: 200 {"availability": "UNKNOWN", "current_snap_version": "21.08.2", "new_snap_vers...
2022-01-22 14:43:22,631 INFO aiohttp.access:206 [22/Jan/2022:14:43:22 +0000] "GET /refresh HTTP/1.1" 200 278 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:43:22,633 DEBUG root:39 start: subiquity/Keyboard/GET:
2022-01-22 14:43:22,653 DEBUG root:39 finish: subiquity/Keyboard/GET: SUCCESS: 200 {"setting": {"layout": "us", "variant": "", "toggle": null}, "layouts": [{"co...
2022-01-22 14:43:22,657 INFO aiohttp.access:206 [22/Jan/2022:14:43:22 +0000] "GET /keyboard HTTP/1.1" 200 39094 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:43:29,036 DEBUG root:39 start: subiquity/Keyboard/needs_toggle_GET:
2022-01-22 14:43:29,036 DEBUG root:39 finish: subiquity/Keyboard/needs_toggle_GET: SUCCESS: 200 false
2022-01-22 14:43:29,036 INFO aiohttp.access:206 [22/Jan/2022:14:43:29 +0000] "GET /keyboard/needs_toggle?layout_code=%22us%22&variant_code=%22%22 HTTP/1.1" 200 196 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:43:29,039 DEBUG root:39 start: subiquity/Keyboard/POST: {"layout": "us", "variant": "", "toggle": null}
2022-01-22 14:43:29,039 DEBUG subiquity.models.subiquity:162 model keyboard for install is configured, to go {'mirror', 'filesystem', 'proxy', 'network'}
2022-01-22 14:43:29,039 DEBUG root:39 finish: subiquity/Keyboard/POST: SUCCESS: 200 null
2022-01-22 14:43:29,039 INFO aiohttp.access:206 [22/Jan/2022:14:43:29 +0000] "POST /keyboard HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:43:29,042 INFO aiohttp.access:206 [22/Jan/2022:14:43:29 +0000] "GET /zdev HTTP/1.1" 200 186 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:43:29,043 DEBUG root:39 start: subiquity/Network/GET:
2022-01-22 14:43:29,044 DEBUG root:39 finish: subiquity/Network/GET: SUCCESS: 200 {"devices": [{"name": "eth0", "type": "eth", "is_connected": true, "bond_mast...
2022-01-22 14:43:29,048 INFO aiohttp.access:206 [22/Jan/2022:14:43:29 +0000] "GET /network HTTP/1.1" 200 899 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:43:29,048 INFO root:39 start: subiquity/Network/apply_config: silent=True
2022-01-22 14:43:29,053 DEBUG subiquitycore.controller.network:240 network config:
network:
ethernets:
eth0:
dhcp4: true
version: 2
2022-01-22 14:43:29,062 DEBUG subiquitycore.netplan:111 config for eth0 = {'dhcp4': True}
2022-01-22 14:43:29,063 DEBUG subiquitycore.utils:74 arun_command called: ['netplan', 'apply']
2022-01-22 14:43:29,076 DEBUG root:39 start: subiquity/Network/subscription_PUT:
2022-01-22 14:43:29,078 DEBUG subiquity.server.controllers.network:300 added subscription /tmp/tmpa598j069/socket
2022-01-22 14:43:29,079 DEBUG root:39 finish: subiquity/Network/subscription_PUT: SUCCESS: 200 null
2022-01-22 14:43:29,083 INFO aiohttp.access:206 [22/Jan/2022:14:43:29 +0000] "PUT /network/subscription?socket_path=%22/tmp/tmpa598j069/socket%22 HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:43:29,083 DEBUG subiquity.server.controllers.network:320 _call_client route_watch /tmp/tmpa598j069/socket
2022-01-22 14:43:30,392 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2022-01-22 14:43:30,451 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2022-01-22 14:43:30,451 DEBUG probert.network:585 event for link_change: CHANGE {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth0'}
2022-01-22 14:43:30,451 DEBUG probert.network:672 link_change CHANGE {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'eth0'}
2022-01-22 14:43:30,452 DEBUG root:39 start: subiquity/Network/_send_update: CHANGE eth0
2022-01-22 14:43:30,452 DEBUG subiquity.server.controllers.network:354 dev_info eth0 {'dhcp4': True}
2022-01-22 14:43:30,452 DEBUG subiquity.server.controllers.network:331 creating _call_client task /tmp/tmpa598j069/socket update_link
2022-01-22 14:43:30,453 DEBUG root:39 finish: subiquity/Network/_send_update: SUCCESS: CHANGE eth0
2022-01-22 14:43:30,453 DEBUG subiquity.server.controllers.network:320 _call_client update_link /tmp/tmpa598j069/socket
2022-01-22 14:43:30,505 DEBUG subiquitycore.utils:83 arun_command ['netplan', 'apply'] exited with code 0
2022-01-22 14:43:34,072 DEBUG root:39 start: subiquity/Network/POST:
2022-01-22 14:43:34,073 DEBUG subiquity.models.subiquity:162 model network for install is configured, to go {'mirror', 'filesystem', 'proxy'}
2022-01-22 14:43:34,073 DEBUG root:39 finish: subiquity/Network/POST: SUCCESS: 200 null
2022-01-22 14:43:34,073 INFO aiohttp.access:206 [22/Jan/2022:14:43:34 +0000] "POST /network HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:43:34,075 DEBUG root:39 start: subiquity/Proxy/GET:
2022-01-22 14:43:34,076 DEBUG root:39 finish: subiquity/Proxy/GET: SUCCESS: 200 ""
2022-01-22 14:43:34,076 INFO aiohttp.access:206 [22/Jan/2022:14:43:34 +0000] "GET /proxy HTTP/1.1" 200 193 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:43:34,081 DEBUG root:39 start: subiquity/Network/subscription_DELETE:
2022-01-22 14:43:34,081 DEBUG subiquity.server.controllers.network:313 removed subscription /tmp/tmpa598j069/socket
2022-01-22 14:43:34,081 DEBUG root:39 finish: subiquity/Network/subscription_DELETE: SUCCESS: 200 null
2022-01-22 14:43:34,081 INFO aiohttp.access:206 [22/Jan/2022:14:43:34 +0000] "DELETE /network/subscription?socket_path=%22/tmp/tmpa598j069/socket%22 HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:43:39,865 DEBUG root:39 start: subiquity/Proxy/POST: ""
2022-01-22 14:43:39,866 DEBUG subiquity.models.subiquity:162 model proxy for install is configured, to go {'mirror', 'filesystem'}
2022-01-22 14:43:39,866 DEBUG root:39 finish: subiquity/Proxy/POST: SUCCESS: 200 null
2022-01-22 14:43:39,867 INFO aiohttp.access:206 [22/Jan/2022:14:43:39 +0000] "POST /proxy HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:43:39,867 DEBUG subiquitycore.snapd:58 restarting snapd to pick up proxy config
2022-01-22 14:43:39,868 DEBUG subiquitycore.utils:48 run_command called: ['systemctl', 'daemon-reload']
2022-01-22 14:43:39,876 DEBUG root:39 start: subiquity/Mirror/GET:
2022-01-22 14:43:39,880 DEBUG root:39 finish: subiquity/Mirror/GET: SUCCESS: 200 "http://archive.ubuntu.com/ubuntu"
2022-01-22 14:43:39,885 INFO aiohttp.access:206 [22/Jan/2022:14:43:39 +0000] "GET /mirror HTTP/1.1" 200 226 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:43:40,287 DEBUG subiquitycore.utils:61 run_command ['systemctl', 'daemon-reload'] exited with code 0
2022-01-22 14:43:40,287 DEBUG subiquitycore.utils:48 run_command called: ['systemctl', 'restart', 'snapd.service']
2022-01-22 14:43:40,510 INFO root:39 finish: subiquity/Network/apply_config: SUCCESS: silent=True
2022-01-22 14:43:40,789 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2022-01-22 14:43:40,870 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 1
2022-01-22 14:43:40,870 DEBUG subiquity.server.controller.filesystem:381 waiting 0.1 to let udev event queue settle
2022-01-22 14:43:40,903 DEBUG subiquitycore.utils:61 run_command ['systemctl', 'restart', 'snapd.service'] exited with code 0
2022-01-22 14:43:40,904 DEBUG subiquity.server.controllers.snaplist:59 loading list of snaps
2022-01-22 14:43:40,912 DEBUG urllib3.connectionpool:826 Starting new HTTPS connection (1): geoip.ubuntu.com
2022-01-22 14:43:40,915 DEBUG root:39 start: subiquity/Refresh/check_for_update:
2022-01-22 14:43:40,918 DEBUG root:39 start: subiquity/SnapList/loader:
2022-01-22 14:43:40,923 DEBUG root:39 start: subiquity/SnapList/loader/list:
2022-01-22 14:43:40,935 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 0x7f9ffc1d6828>: 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 0x7f9ffc1d6828>: 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 0x7f9ffc1d6828>: Failed to establish a new connection: [Errno -3] Temporary failure in name resolution',))
2022-01-22 14:43:40,972 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2022-01-22 14:43:41,002 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2022-01-22 14:43:41,003 DEBUG subiquity.server.controller.filesystem:393 _udev_event change Device('/sys/devices/virtual/block/loop7')
2022-01-22 14:43:41,003 DEBUG subiquity.server.controller.filesystem:393 _udev_event change Device('/sys/devices/virtual/block/loop7')
2022-01-22 14:43:41,003 DEBUG subiquity.server.controller.filesystem:393 _udev_event change Device('/sys/devices/virtual/block/loop7')
2022-01-22 14:43:41,004 DEBUG root:39 start: subiquity/Filesystem/_probe:
2022-01-22 14:43:41,005 DEBUG root:39 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2022-01-22 14:43:41,245 DEBUG probert.dasd:131 Probing DASD devies
2022-01-22 14:43:41,246 DEBUG probert.dasd:134 DASD devices only present on s390x, arch=x86_64
2022-01-22 14:43:41,330 DEBUG curtin:1294 Extracting storage config from probe data
2022-01-22 14:43:41,331 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2022-01-22 14:43:41,331 DEBUG curtin:86 /dev/sr0 is multipath device partition? False
2022-01-22 14:43:41,331 DEBUG curtin:73 /dev/xvda is multipath device member? False
2022-01-22 14:43:41,331 DEBUG curtin:86 /dev/xvda is multipath device partition? False
2022-01-22 14:43:41,331 DEBUG curtin:61 /dev/xvda is multipath device? False
2022-01-22 14:43:41,331 DEBUG curtin:86 /dev/xvda is multipath device partition? False
2022-01-22 14:43:41,331 DEBUG curtin:61 /dev/xvda is multipath device? False
2022-01-22 14:43:41,359 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2022-01-22 14:43:41,360 DEBUG curtin:1301 Sorting extracted configurations
2022-01-22 14:43:41,360 INFO curtin:1320 Validating extracted storage config components
2022-01-22 14:43:41,381 DEBUG curtin:1339 Extracted (unmerged) storage config:
storage:
- id: disk-xvda
path: /dev/xvda
type: disk
2022-01-22 14:43:41,381 DEBUG curtin:1341 Generating storage config dependencies
2022-01-22 14:43:41,382 DEBUG curtin:1347 Merging storage config dependencies
2022-01-22 14:43:41,382 DEBUG curtin:1354 Merged storage config:
storage:
config:
- id: disk-xvda
path: /dev/xvda
type: disk
version: 1
2022-01-22 14:43:41,383 DEBUG subiquity.models.filesystem:1121 exclusions set()
2022-01-22 14:43:41,383 DEBUG root:39 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False
2022-01-22 14:43:41,383 DEBUG root:39 finish: subiquity/Filesystem/_probe: SUCCESS:
2022-01-22 14:43:43,266 DEBUG root:39 start: subiquity/Mirror/POST: "http://archive.ubuntu.com/ubuntu"
2022-01-22 14:43:43,267 DEBUG subiquity.models.subiquity:162 model mirror for install is configured, to go {'filesystem'}
2022-01-22 14:43:43,267 DEBUG root:39 finish: subiquity/Mirror/POST: SUCCESS: 200 null
2022-01-22 14:43:43,268 INFO aiohttp.access:206 [22/Jan/2022:14:43:43 +0000] "POST /mirror HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:43:43,271 DEBUG root:39 start: subiquity/Refresh/GET:
2022-01-22 14:43:43,271 DEBUG root:39 finish: subiquity/Refresh/GET: SUCCESS: 200 {"availability": "UNKNOWN", "current_snap_version": "21.08.2", "new_snap_vers...
2022-01-22 14:43:43,272 INFO aiohttp.access:206 [22/Jan/2022:14:43:43 +0000] "GET /refresh HTTP/1.1" 200 278 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:43:43,277 DEBUG root:39 start: subiquity/Refresh/GET:
2022-01-22 14:43:54,961 DEBUG root:39 start: subiquity/Filesystem/guided_GET:
2022-01-22 14:43:54,962 DEBUG root:39 finish: subiquity/Filesystem/guided_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-xvda", "label...
2022-01-22 14:43:54,962 INFO aiohttp.access:206 [22/Jan/2022:14:43:54 +0000] "GET /storage/guided?min_size=6442450944 HTTP/1.1" 200 398 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:44:01,987 DEBUG root:39 start: subiquity/Filesystem/guided_POST:
2022-01-22 14:44:01,987 DEBUG subiquity.models.filesystem:1186 mountpoints {}
2022-01-22 14:44:01,988 DEBUG root:39 finish: subiquity/Filesystem/guided_POST: SUCCESS: 200 {"status": "DONE", "error_report": null, "bootloader": "BIOS", "orig_config":...
2022-01-22 14:44:01,988 INFO aiohttp.access:206 [22/Jan/2022:14:44:01 +0000] "POST /storage/guided?choice=null HTTP/1.1" 200 4076 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:44:13,163 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?section=server HTTP/1.1" 400 543
2022-01-22 14:44:13,165 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
2022-01-22 14:44:13,165 DEBUG root:39 finish: subiquity/SnapList/loader/list: SUCCESS:
2022-01-22 14:44:13,166 DEBUG subiquity.server.controllers.snaplist:67 fetched list of 0 snaps
2022-01-22 14:44:13,171 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?select=refresh HTTP/1.1" 500 257
2022-01-22 14:44:13,171 DEBUG root:39 finish: subiquity/SnapList/loader: SUCCESS:
2022-01-22 14:44:13,172 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
2022-01-22 14:44:13,172 DEBUG root:39 finish: subiquity/Refresh/check_for_update: SUCCESS: checking for snap update failed
2022-01-22 14:44:13,175 DEBUG root:39 finish: subiquity/Refresh/GET: SUCCESS: 200 {"availability": "UNKNOWN", "current_snap_version": "21.08.2", "new_snap_vers...
2022-01-22 14:44:13,176 INFO aiohttp.access:206 [22/Jan/2022:14:43:43 +0000] "GET /refresh?wait=true HTTP/1.1" 200 278 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:45:06,096 DEBUG root:39 start: subiquity/Filesystem/POST: [{"ptable": "gpt", "path": "/dev/xvda", "wipe": "superblock-recursive", "pres...
2022-01-22 14:45:06,097 DEBUG subiquity.models.filesystem:1121 exclusions set()
2022-01-22 14:45:06,097 DEBUG subiquity.models.subiquity:162 model filesystem for install is configured, to go set()
2022-01-22 14:45:06,098 DEBUG root:39 finish: subiquity/Filesystem/POST: SUCCESS: 200 null
2022-01-22 14:45:06,098 INFO aiohttp.access:206 [22/Jan/2022:14:45:06 +0000] "POST /storage HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:45:06,099 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "NEEDS_CONFIRMATION", "confirming_tty": "", "error": null, "cloud_i...
2022-01-22 14:45:06,099 INFO aiohttp.access:206 [22/Jan/2022:14:29:26 +0000] "GET /meta/status?cur=%22WAITING%22 HTTP/1.1" 200 428 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:45:06,099 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "NEEDS_CONFIRMATION", "confirming_tty": "", "error": null, "cloud_i...
2022-01-22 14:45:06,102 INFO aiohttp.access:206 [22/Jan/2022:14:29:28 +0000] "GET /meta/status?cur=%22WAITING%22 HTTP/1.1" 200 428 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:45:06,103 INFO root:39 start: subiquity/Meta/status_GET:
2022-01-22 14:45:06,105 INFO aiohttp.access:206 [22/Jan/2022:14:45:06 +0000] "GET /identity HTTP/1.1" 200 189 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:45:06,108 INFO root:39 start: subiquity/Meta/status_GET:
2022-01-22 14:45:08,999 INFO root:39 start: subiquity/Meta/confirm_POST:
2022-01-22 14:45:08,999 INFO root:39 finish: subiquity/Meta/confirm_POST: SUCCESS: 200 null
2022-01-22 14:45:09,000 INFO aiohttp.access:206 [22/Jan/2022:14:45:08 +0000] "POST /meta/confirm?tty=%22/dev/tty1%22 HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:45:09,001 INFO root:39 start: subiquity/Install/install/curtin_install: installing system
2022-01-22 14:45:09,002 DEBUG subiquity.server.controllers.install:187 curtin_install
2022-01-22 14:45:09,003 DEBUG subiquity.models.subiquity:346 merging config from <subiquity.models.subiquity.DebconfSelectionsModel object at 0x7f9ffdf26320>
2022-01-22 14:45:09,005 DEBUG subiquity.models.subiquity:346 merging config from <subiquity.models.filesystem.FilesystemModel object at 0x7f9ffdf26358>
2022-01-22 14:45:09,012 DEBUG subiquity.models.filesystem:1186 mountpoints {'/': 'mount-1', '/boot': 'mount-0'}
2022-01-22 14:45:09,013 DEBUG subiquity.models.subiquity:346 merging config from <subiquity.models.kernel.KernelModel object at 0x7f9ffdf15550>
2022-01-22 14:45:09,014 DEBUG subiquity.models.subiquity:346 merging config from <subiquity.models.keyboard.KeyboardModel object at 0x7f9ffdf15470>
2022-01-22 14:45:09,021 DEBUG subiquity.models.subiquity:346 merging config from <subiquity.models.mirror.MirrorModel object at 0x7f9ffdf15400>
2022-01-22 14:45:09,022 DEBUG subiquity.models.subiquity:346 merging config from <subiquity.models.network.NetworkModel object at 0x7f9ffdbc39b0>
2022-01-22 14:45:09,024 DEBUG subiquity.models.subiquity:346 merging config from <subiquity.models.proxy.ProxyModel object at 0x7f9ffdbc3f60>
2022-01-22 14:45:09,042 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']
2022-01-22 14:45:09,042 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1873', '/snap/subiquity/2651/usr/bin/python3', '-m', 'curtin', '--showtrace', '-c', '/var/log/installer/subiquity-curtin-install.conf', 'install']
2022-01-22 14:45:09,063 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini...
2022-01-22 14:45:09,069 INFO aiohttp.access:206 [22/Jan/2022:14:45:06 +0000] "GET /meta/status?cur=%22NEEDS_CONFIRMATION%22 HTTP/1.1" 200 426 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:45:09,070 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini...
2022-01-22 14:45:09,072 INFO aiohttp.access:206 [22/Jan/2022:14:45:06 +0000] "GET /meta/status?cur=%22NEEDS_CONFIRMATION%22 HTTP/1.1" 200 426 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:45:09,073 DEBUG root:39 start: subiquity/Identity/GET:
2022-01-22 14:45:09,077 DEBUG root:39 finish: subiquity/Identity/GET: SUCCESS: 200 {"realname": "", "username": "", "crypted_password": "", "hostname": ""}
2022-01-22 14:45:09,085 INFO aiohttp.access:206 [22/Jan/2022:14:45:09 +0000] "GET /identity HTTP/1.1" 200 264 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:45:09,086 INFO root:39 start: subiquity/Meta/status_GET:
2022-01-22 14:45:09,086 INFO root:39 start: subiquity/Meta/status_GET:
2022-01-22 14:45:10,477 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install: curtin command install
2022-01-22 14:45:10,478 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-early: preparing for installation
2022-01-22 14:45:10,479 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-early: SUCCESS: preparing for installation
2022-01-22 14:45:10,479 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning: configuring storage
2022-01-22 14:45:10,480 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin: running 'curtin block-meta simple'
2022-01-22 14:45:11,518 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: curtin command block-meta
2022-01-22 14:45:11,777 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/clear-holders: removing previous storage devices
2022-01-22 14:45:14,554 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/clear-holders: SUCCESS: removing previous storage devices
2022-01-22 14:45:14,557 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/: configuring disk: disk-xvda
2022-01-22 14:45:15,094 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/: SUCCESS: configuring disk: disk-xvda
2022-01-22 14:45:15,095 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-0
2022-01-22 14:45:17,222 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring partition: partition-0
2022-01-22 14:45:17,229 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-1
2022-01-22 14:45:18,629 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring partition: partition-1
2022-01-22 14:45:18,631 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring format: format-0
2022-01-22 14:45:19,449 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring format: format-0
2022-01-22 14:45:19,725 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-2
2022-01-22 14:45:21,158 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring partition: partition-2
2022-01-22 14:45:21,471 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring format: format-1
2022-01-22 14:45:22,245 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring format: format-1
2022-01-22 14:45:22,247 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring mount: mount-1
2022-01-22 14:45:23,285 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring mount: mount-1
2022-01-22 14:45:23,286 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring mount: mount-0
2022-01-22 14:45:23,981 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring mount: mount-0
2022-01-22 14:45:23,984 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning/builtin: SUCCESS: running 'curtin block-meta simple'
2022-01-22 14:45:23,985 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-partitioning: SUCCESS: configuring storage
2022-01-22 14:45:23,985 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-extract: writing install sources to disk
2022-01-22 14:45:23,986 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-extract/builtin: running 'curtin extract'
2022-01-22 14:45:25,230 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-extract/builtin/cmd-extract: curtin command extract
2022-01-22 14:45:25,232 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-extract/builtin/cmd-extract/: acquiring and extracting image from cp:///media/filesystem
2022-01-22 14:46:23,789 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
2022-01-22 14:46:24,982 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-extract/builtin: SUCCESS: running 'curtin extract'
2022-01-22 14:46:24,984 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-extract: SUCCESS: writing install sources to disk
2022-01-22 14:46:24,985 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks: configuring installed system
2022-01-22 14:46:24,986 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'
2022-01-22 14:46:26,967 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-apt-config: curtin command apt-config
2022-01-22 14:46:27,990 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-apt-config: SUCCESS: curtin command apt-config
2022-01-22 14:46:29,856 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-in-target: curtin command in-target
2022-01-22 14:46:32,229 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-in-target: SUCCESS: curtin command in-target
2022-01-22 14:46:32,231 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'
2022-01-22 14:46:32,233 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin: running 'curtin curthooks'
2022-01-22 14:46:33,479 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks: curtin command curthooks
2022-01-22 14:46:33,481 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-apt-config: configuring apt configuring apt
2022-01-22 14:46:34,012 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-apt-config: SUCCESS: configuring apt configuring apt
2022-01-22 14:46:34,015 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-missing-packages: installing missing packages
2022-01-22 14:46:34,280 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-missing-packages: SUCCESS: installing missing packages
2022-01-22 14:46:34,283 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-iscsi-service: configuring iscsi service
2022-01-22 14:46:34,285 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-iscsi-service: SUCCESS: configuring iscsi service
2022-01-22 14:46:34,285 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-mdadm-service: configuring raid (mdadm) service
2022-01-22 14:46:34,286 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-mdadm-service: SUCCESS: configuring raid (mdadm) service
2022-01-22 14:46:34,287 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-kernel: installing kernel
2022-01-22 14:47:42,657 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-kernel: SUCCESS: installing kernel
2022-01-22 14:47:42,658 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/setting-up-swap: setting up swap
2022-01-22 14:47:42,658 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/setting-up-swap: SUCCESS: setting up swap
2022-01-22 14:47:42,680 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/apply-networking-config: apply networking config
2022-01-22 14:47:42,691 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/apply-networking-config: SUCCESS: apply networking config
2022-01-22 14:47:42,694 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-etc-fstab: writing etc/fstab
2022-01-22 14:47:42,712 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-etc-fstab: SUCCESS: writing etc/fstab
2022-01-22 14:47:42,721 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-multipath: configuring multipath
2022-01-22 14:47:44,978 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-multipath: SUCCESS: configuring multipath
2022-01-22 14:47:44,979 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/system-upgrade: updating packages on target system
2022-01-22 14:47:44,980 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/system-upgrade: SUCCESS: updating packages on target system
2022-01-22 14:47:44,980 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
2022-01-22 14:47:44,981 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
2022-01-22 14:47:44,981 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/updating-initramfs-configuration: updating initramfs configuration
2022-01-22 14:48:20,226 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/updating-initramfs-configuration: SUCCESS: updating initramfs configuration
2022-01-22 14:48:20,226 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-bootloader: configuring target system bootloader
2022-01-22 14:48:20,227 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/install-grub: installing grub to target devices
2022-01-22 14:48:24,439 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/install-grub: SUCCESS: installing grub to target devices
2022-01-22 14:48:24,441 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-bootloader: SUCCESS: configuring target system bootloader
2022-01-22 14:48:24,441 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks: SUCCESS: curtin command curthooks
2022-01-22 14:48:25,474 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks/builtin: SUCCESS: running 'curtin curthooks'
2022-01-22 14:48:25,476 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-curthooks: SUCCESS: configuring installed system
2022-01-22 14:48:25,476 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-hook: finalizing installation
2022-01-22 14:48:25,477 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-hook/builtin: running 'curtin hook'
2022-01-22 14:48:27,254 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1873', '/snap/subiquity/2651/usr/bin/python3', '-m', 'curtin', '--showtrace', '-c', '/var/log/installer/subiquity-curtin-install.conf', 'install'] exited with code 0
2022-01-22 14:48:27,254 DEBUG subiquity.server.controllers.install:196 curtin_install completed: 0
2022-01-22 14:48:27,254 INFO root:39 finish: subiquity/Install/install/curtin_install: SUCCESS: installing system
2022-01-22 14:48:27,471 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-hook/builtin/cmd-hook: curtin command hook
2022-01-22 14:48:27,472 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-hook/builtin/cmd-hook: SUCCESS: curtin command hook
2022-01-22 14:48:27,472 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-hook/builtin: SUCCESS: running 'curtin hook'
2022-01-22 14:48:27,473 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-hook: SUCCESS: finalizing installation
2022-01-22 14:48:27,473 DEBUG root:39 start: subiquity/Install/install/curtin_install/cmd-install/stage-late: executing late commands
2022-01-22 14:48:27,474 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install/stage-late: SUCCESS: executing late commands
2022-01-22 14:48:27,475 DEBUG root:39 finish: subiquity/Install/install/curtin_install/cmd-install: SUCCESS: curtin command install
2022-01-22 14:48:27,557 DEBUG subiquity.server.controllers.install:248 waited 0.30000000000000004 seconds for events to drain
2022-01-22 14:48:27,572 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "POST_WAIT", "confirming_tty": "/dev/tty1", "error": null, "cloud_i...
2022-01-22 14:48:27,753 INFO aiohttp.access:206 [22/Jan/2022:14:45:09 +0000] "GET /meta/status?cur=%22RUNNING%22 HTTP/1.1" 200 428 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:48:27,754 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "POST_WAIT", "confirming_tty": "/dev/tty1", "error": null, "cloud_i...
2022-01-22 14:48:27,757 INFO aiohttp.access:206 [22/Jan/2022:14:45:09 +0000] "GET /meta/status?cur=%22RUNNING%22 HTTP/1.1" 200 428 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:48:27,758 INFO root:39 start: subiquity/Meta/status_GET:
2022-01-22 14:48:27,758 INFO root:39 start: subiquity/Meta/status_GET:
2022-01-22 14:48:50,407 DEBUG root:39 start: subiquity/Identity/POST: {"realname": "root", "username": "ubuntu", "crypted_password": "$6$u1Iif4ltxA...
2022-01-22 14:48:50,408 DEBUG subiquity.models.subiquity:162 model identity for postinstall is configured, to go {'snaplist', 'ssh'}
2022-01-22 14:48:50,408 DEBUG root:39 finish: subiquity/Identity/POST: SUCCESS: 200 null
2022-01-22 14:48:50,408 INFO aiohttp.access:206 [22/Jan/2022:14:48:50 +0000] "POST /identity HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:48:50,410 DEBUG root:39 start: subiquity/SSH/GET:
2022-01-22 14:48:50,410 DEBUG root:39 finish: subiquity/SSH/GET: SUCCESS: 200 {"install_server": false, "allow_pw": true, "authorized_keys": []}
2022-01-22 14:48:50,410 INFO aiohttp.access:206 [22/Jan/2022:14:48:50 +0000] "GET /ssh HTTP/1.1" 200 258 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:48:56,791 DEBUG root:39 start: subiquity/SSH/POST: {"install_server": true, "allow_pw": true, "authorized_keys": []}
2022-01-22 14:48:56,792 DEBUG subiquity.models.subiquity:162 model ssh for postinstall is configured, to go {'snaplist'}
2022-01-22 14:48:56,792 DEBUG root:39 finish: subiquity/SSH/POST: SUCCESS: 200 null
2022-01-22 14:48:56,793 INFO aiohttp.access:206 [22/Jan/2022:14:48:56 +0000] "POST /ssh HTTP/1.1" 200 195 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:48:56,794 DEBUG root:39 start: subiquity/SnapList/GET:
2022-01-22 14:48:56,795 DEBUG subiquity.models.subiquity:162 model snaplist for postinstall is configured, to go set()
2022-01-22 14:48:56,795 DEBUG root:39 finish: subiquity/SnapList/GET: SUCCESS: 200 {"status": "FAILED", "snaps": [], "selections": []}
2022-01-22 14:48:56,795 INFO aiohttp.access:206 [22/Jan/2022:14:48:56 +0000] "GET /snaplist HTTP/1.1" 200 243 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:48:56,795 INFO root:39 start: subiquity/Install/install/postinstall: final system configuration
2022-01-22 14:48:56,797 DEBUG subiquity.models.filesystem:1186 mountpoints {'/': 'mount-1', '/boot': 'mount-0'}
2022-01-22 14:48:56,815 DEBUG root:39 start: subiquity/Install/install/postinstall/configure_cloud_init: configuring cloud-init
2022-01-22 14:48:56,843 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2022-01-22 14:48:56,843 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "POST_RUNNING", "confirming_tty": "/dev/tty1", "error": null, "clou...
2022-01-22 14:48:56,860 INFO aiohttp.access:206 [22/Jan/2022:14:48:27 +0000] "GET /meta/status?cur=%22POST_WAIT%22 HTTP/1.1" 200 431 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:48:56,862 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "POST_RUNNING", "confirming_tty": "/dev/tty1", "error": null, "clou...
2022-01-22 14:48:56,865 INFO aiohttp.access:206 [22/Jan/2022:14:48:27 +0000] "GET /meta/status?cur=%22POST_WAIT%22 HTTP/1.1" 200 431 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:48:56,870 INFO root:39 start: subiquity/Meta/status_GET:
2022-01-22 14:48:56,873 INFO root:39 start: subiquity/Meta/status_GET:
2022-01-22 14:48:56,879 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2022-01-22 14:48:56,879 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2022-01-22 14:48:56,886 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2022-01-22 14:48:56,886 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2022-01-22 14:48:56,893 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2022-01-22 14:48:56,893 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2022-01-22 14:48:56,900 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2022-01-22 14:48:56,901 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2022-01-22 14:48:56,907 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2022-01-22 14:48:56,908 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2022-01-22 14:48:56,914 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2022-01-22 14:48:56,915 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2022-01-22 14:48:56,921 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2022-01-22 14:48:56,921 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2022-01-22 14:48:56,926 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2022-01-22 14:48:56,927 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2022-01-22 14:48:56,932 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2022-01-22 14:48:56,933 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2022-01-22 14:48:56,940 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2022-01-22 14:48:56,950 DEBUG root:39 finish: subiquity/Install/install/postinstall/configure_cloud_init: SUCCESS: configuring cloud-init
2022-01-22 14:48:56,951 DEBUG root:39 start: subiquity/Install/install/postinstall/install_openssh-server: installing openssh-server
2022-01-22 14:48:56,951 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1873', '/snap/subiquity/2651/usr/bin/python3', '-m', 'curtin', 'system-install', '-t', '/target', '--', 'openssh-server']
2022-01-22 14:49:04,141 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1873', '/snap/subiquity/2651/usr/bin/python3', '-m', 'curtin', 'system-install', '-t', '/target', '--', 'openssh-server'] exited with code 0
2022-01-22 14:49:04,142 DEBUG root:39 finish: subiquity/Install/install/postinstall/install_openssh-server: SUCCESS: installing openssh-server
2022-01-22 14:49:04,143 DEBUG root:39 start: subiquity/Install/install/postinstall/restore_apt_config: restoring apt configuration
2022-01-22 14:49:04,144 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1873', 'umount', '/target/etc/apt']
2022-01-22 14:49:04,166 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1873', 'umount', '/target/etc/apt'] exited with code 0
2022-01-22 14:49:04,166 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1873', 'umount', '/target/var/lib/apt/lists']
2022-01-22 14:49:04,188 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1873', 'umount', '/target/var/lib/apt/lists'] exited with code 0
2022-01-22 14:49:04,189 DEBUG root:39 finish: subiquity/Install/install/postinstall/restore_apt_config: SUCCESS: restoring apt configuration
2022-01-22 14:49:04,189 INFO root:39 finish: subiquity/Install/install/postinstall: SUCCESS: final system configuration
2022-01-22 14:49:04,190 DEBUG root:39 finish: subiquity/Install/install: SUCCESS:
2022-01-22 14:49:04,191 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "DONE", "confirming_tty": "/dev/tty1", "error": null, "cloud_init_o...
2022-01-22 14:49:04,193 INFO aiohttp.access:206 [22/Jan/2022:14:48:56 +0000] "GET /meta/status?cur=%22POST_RUNNING%22 HTTP/1.1" 200 423 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:49:04,194 INFO root:39 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "DONE", "confirming_tty": "/dev/tty1", "error": null, "cloud_init_o...
2022-01-22 14:49:04,196 INFO aiohttp.access:206 [22/Jan/2022:14:48:56 +0000] "GET /meta/status?cur=%22POST_RUNNING%22 HTTP/1.1" 200 423 "-" "Python/3.6 aiohttp/3.7.4.post0"
2022-01-22 14:49:04,196 DEBUG root:39 start: subiquity/Late/run:
2022-01-22 14:49:04,197 DEBUG root:39 finish: subiquity/Late/run: SUCCESS:
2022-01-22 14:49:04,202 DEBUG root:39 start: subiquity/Reboot/copy_logs_to_target:
2022-01-22 14:49:04,202 DEBUG subiquitycore.utils:74 arun_command called: ['cp', '-aT', '/var/log/installer', '/target/var/log/installer']
2022-01-22 14:49:04,245 INFO root:39 start: subiquity/Meta/status_GET:
2022-01-22 14:49:04,246 INFO root:39 start: subiquity/Meta/status_GET: