2023-09-28 13:23:20,146 INFO subiquity:199 Starting Subiquity server revision 1243 of snap /snap/ubuntu-desktop-installer/1243
2023-09-28 13:23:20,146 INFO subiquity:200 Arguments passed: ['/snap/ubuntu-desktop-installer/1243/bin/subiquity/subiquity/cmd/server.py', '--use-os-prober', '--storage-version=2', '--postinst-hooks-dir=/snap/ubuntu-desktop-installer/1243/etc/subiquity/postinst.d']
2023-09-28 13:23:20,146 DEBUG subiquity:201 Kernel commandline: CommandLineParams(_raw='BOOT_IMAGE=/casper/vmlinuz layerfs-path=minimal.standard.live.squashfs --- quiet splash\n', _tokens={'---', 'quiet', 'splash'}, _values={'BOOT_IMAGE': '/casper/vmlinuz', 'layerfs-path': 'minimal.standard.live.squashfs'})
2023-09-28 13:23:20,146 DEBUG subiquity:202 Environment: environ({'SNAP_REVISION': '1243', 'SNAP_REAL_HOME': '/root', 'SNAP_USER_COMMON': '/root/snap/ubuntu-desktop-installer/common', 'PATH_ORIG': '/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', 'SNAP_INSTANCE_KEY': '', 'SNAP_EUID': '0', 'PWD': '/snap/ubuntu-desktop-installer/1243/bin/subiquity', 'SYSTEMD_EXEC_PID': '1940', 'SNAP_CONTEXT': 'csLBmrY2f4QRkG4MSr3LzhrBi1B0_UIzot88-XPaYy9eZD55MyFb', 'LANG': 'C.UTF-8', 'SNAP_ARCH': 'amd64', 'PY3OR2_PYTHON': '/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', 'SNAP_INSTANCE_NAME': 'ubuntu-desktop-installer', 'SNAP_USER_DATA': '/root/snap/ubuntu-desktop-installer/1243', 'INVOCATION_ID': '778823b88f9f4e44b33acc171047952b', 'SNAP_REEXEC': '', 'SNAP_UID': '0', 'LD_LIBRARY_PATH_ORIG': '/var/lib/snapd/lib/gl:/var/lib/snapd/lib/gl32:/var/lib/snapd/void:/snap/ubuntu-desktop-installer/1243/lib:/snap/ubuntu-desktop-installer/1243/usr/lib:/snap/ubuntu-desktop-installer/1243/lib/x86_64-linux-gnu:/snap/ubuntu-desktop-installer/1243/usr/lib/x86_64-linux-gnu', 'PYTHONPATH_ORIG': '', 'PYTHONPATH': '/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', 'PYTHON': '/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', 'PYTHONIOENCODING': 'utf-8', 'SNAP': '/snap/ubuntu-desktop-installer/1243', 'SNAP_COMMON': '/var/snap/ubuntu-desktop-installer/common', 'SNAP_VERSION': '0+git.bf01a899', 'DISPLAY': ':0', 'SHLVL': '1', 'SNAP_LIBRARY_PATH': '/var/lib/snapd/lib/gl:/var/lib/snapd/lib/gl32:/var/lib/snapd/void', 'SNAP_COOKIE': 'csLBmrY2f4QRkG4MSr3LzhrBi1B0_UIzot88-XPaYy9eZD55MyFb', 'SNAP_DATA': '/var/snap/ubuntu-desktop-installer/1243', 'LD_LIBRARY_PATH': '/var/lib/snapd/lib/gl:/var/lib/snapd/lib/gl32:/var/lib/snapd/void:/snap/ubuntu-desktop-installer/1243/lib:/snap/ubuntu-desktop-installer/1243/usr/lib:/snap/ubuntu-desktop-installer/1243/lib/x86_64-linux-gnu:/snap/ubuntu-desktop-installer/1243/usr/lib/x86_64-linux-gnu', 'SNAP_NAME': 'ubuntu-desktop-installer', 'JOURNAL_STREAM': '8:21593', 'PATH': '/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', 'SUBIQUITY_ROOT': '/snap/ubuntu-desktop-installer/1243/bin/subiquity', 'OLDPWD': '/var/snap/ubuntu-desktop-installer/1243', '_': '/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', 'APPORT_DATA_DIR': '/snap/ubuntu-desktop-installer/1243/bin/subiquity/share/apport'})
2023-09-28 13:23:20,146 DEBUG asyncio:54 Using selector: EpollSelector
2023-09-28 13:23:20,146 DEBUG subiquitycore.prober:33 Prober() init finished, data:None
2023-09-28 13:23:20,173 DEBUG curtin:95 Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (capture=True)
2023-09-28 13:23:20,188 DEBUG subiquitycore.netplan:113 config for zz-all-en = {'dhcp4': True, 'match': {'name': 'en*'}}
2023-09-28 13:23:20,188 DEBUG subiquitycore.netplan:113 config for zz-all-eth = {'dhcp4': True, 'match': {'name': 'eth*'}}
2023-09-28 13:23:20,200 DEBUG subiquitycore.utils:118 arun_command called: ['cloud-init', 'status', '--wait']
2023-09-28 13:23:32,169 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET: 
2023-09-28 13:23:32,169 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...
2023-09-28 13:23:32,170 INFO aiohttp.access:206  [28/Sep/2023:13:23:32 +0000] "GET /meta/status HTTP/1.1" 200 420 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:33,172 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET: 
2023-09-28 13:23:33,173 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...
2023-09-28 13:23:33,173 INFO aiohttp.access:206  [28/Sep/2023:13:23:33 +0000] "GET /meta/status HTTP/1.1" 200 420 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:34,174 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET: 
2023-09-28 13:23:34,175 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...
2023-09-28 13:23:34,175 INFO aiohttp.access:206  [28/Sep/2023:13:23:34 +0000] "GET /meta/status HTTP/1.1" 200 420 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:35,177 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET: 
2023-09-28 13:23:35,178 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...
2023-09-28 13:23:35,178 INFO aiohttp.access:206  [28/Sep/2023:13:23:35 +0000] "GET /meta/status HTTP/1.1" 200 420 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:36,179 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET: 
2023-09-28 13:23:36,180 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...
2023-09-28 13:23:36,180 INFO aiohttp.access:206  [28/Sep/2023:13:23:36 +0000] "GET /meta/status HTTP/1.1" 200 420 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:37,181 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET: 
2023-09-28 13:23:37,182 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...
2023-09-28 13:23:37,182 INFO aiohttp.access:206  [28/Sep/2023:13:23:37 +0000] "GET /meta/status HTTP/1.1" 200 420 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:37,918 DEBUG subiquitycore.utils:132 arun_command ['cloud-init', 'status', '--wait'] exited with code 0
2023-09-28 13:23:37,918 DEBUG subiquity.server.server:569 waited 17.718086004257202s for cloud-init
2023-09-28 13:23:37,919 DEBUG subiquity.cloudinit:14 Loaded cloud config from /run/cloud-init/combined-cloud-config.json
2023-09-28 13:23:37,919 DEBUG subiquity.server.server:553 no autoinstall found in cloud-config
2023-09-28 13:23:37,919 DEBUG subiquitycore.utils:76 run_command called: ['ssh-keygen', '-lf', '/home/installer/.ssh/authorized_keys']
2023-09-28 13:23:37,925 DEBUG subiquitycore.utils:95 run_command ['ssh-keygen', '-lf', '/home/installer/.ssh/authorized_keys'] exited with code 255
2023-09-28 13:23:37,926 DEBUG subiquitycore.ssh:52 ssh-keygen -lf /home/installer/.ssh/authorized_keys failed '/home/installer/.ssh/authorized_keys is not a public key file.\r\n'
2023-09-28 13:23:37,926 DEBUG subiquitycore.utils:76 run_command called: chpasswd
2023-09-28 13:23:38,014 DEBUG subiquitycore.utils:95 run_command chpasswd exited with code 0
2023-09-28 13:23:38,015 DEBUG subiquity.server.server:470 load_autoinstall_config only_early True file None
2023-09-28 13:23:38,015 DEBUG subiquity.server.server:470 load_autoinstall_config only_early False file None
2023-09-28 13:23:38,015 DEBUG subiquitycore.core:118 starting controllers
2023-09-28 13:23:38,015 DEBUG subiquity.server.controllers.kernel:63 Using kernel linux-generic-hwe-22.04 due to /run/kernel-meta-package
2023-09-28 13:23:38,021 DEBUG subiquity.models.source:93 loaded 2 sources from '/cdrom/casper/install-sources.yaml'
2023-09-28 13:23:38,021 DEBUG probert.network:585 event for link_change: NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2023-09-28 13:23:38,022 DEBUG probert.network:585 event for link_change: NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'enp1s0'}
2023-09-28 13:23:38,022 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'}
2023-09-28 13:23:38,022 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 2, 'flags': 512, 'family': 2, 'scope': 0, 'local': b'192.168.122.252/24'}
2023-09-28 13:23:38,022 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2023-09-28 13:23:38,022 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::5054:ff:fe69:4945/64'}
2023-09-28 13:23:38,022 DEBUG probert.network:672 link_change NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2023-09-28 13:23:38,080 DEBUG subiquitycore.models.network:475 new_link 1 lo lo
2023-09-28 13:23:38,080 DEBUG subiquitycore.models.network:477 ignoring based on type
2023-09-28 13:23:38,080 DEBUG probert.network:672 link_change NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'enp1s0'}
2023-09-28 13:23:38,141 DEBUG subiquitycore.models.network:475 new_link 2 enp1s0 eth
2023-09-28 13:23:38,142 DEBUG subiquitycore.models.network:506 new_link 2 enp1s0 with config {'dhcp4': True}
2023-09-28 13:23:38,142 DEBUG root:30 start: subiquity/Network/_send_update: NEW enp1s0
2023-09-28 13:23:38,142 DEBUG subiquity.server.controllers.network:313 dev_info enp1s0 {'dhcp4': True}
2023-09-28 13:23:38,142 DEBUG root:30 finish: subiquity/Network/_send_update: SUCCESS: NEW enp1s0
2023-09-28 13:23:38,142 DEBUG probert.network:717 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'}
2023-09-28 13:23:38,143 DEBUG probert.network:717 addr_change NEW {'ifindex': 2, 'flags': 512, 'family': 2, 'scope': 0, 'local': b'192.168.122.252/24'}
2023-09-28 13:23:38,143 DEBUG root:30 start: subiquity/Network/_send_update: CHANGE enp1s0
2023-09-28 13:23:38,143 DEBUG subiquity.server.controllers.network:313 dev_info enp1s0 {'dhcp4': True}
2023-09-28 13:23:38,143 DEBUG root:30 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp1s0
2023-09-28 13:23:38,143 DEBUG probert.network:717 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2023-09-28 13:23:38,143 DEBUG probert.network:717 addr_change NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::5054:ff:fe69:4945/64'}
2023-09-28 13:23:38,143 DEBUG root:30 start: subiquity/Network/_send_update: CHANGE enp1s0
2023-09-28 13:23:38,143 DEBUG subiquity.server.controllers.network:313 dev_info enp1s0 {'dhcp4': True}
2023-09-28 13:23:38,143 DEBUG root:30 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp1s0
2023-09-28 13:23:38,143 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2023-09-28 13:23:38,200 DEBUG pyroute2.ndb.140714568272576.sources.localhost:74 init
2023-09-28 13:23:38,200 DEBUG pyroute2.ndb.140714568272576.sources.localhost:384 starting the source
2023-09-28 13:23:38,204 DEBUG pyroute2.ndb.140714568272576.sources.localhost/nsmanager:74 init
2023-09-28 13:23:38,204 DEBUG pyroute2.ndb.140714568272576.sources.localhost:74 connecting
2023-09-28 13:23:38,205 DEBUG pyroute2.ndb.140714568272576.sources.localhost:74 loading
2023-09-28 13:23:38,208 DEBUG pyroute2.ndb.140714568272576.sources.localhost/nsmanager:384 starting the source
2023-09-28 13:23:38,209 DEBUG pyroute2.ndb.140714568272576.sources.localhost/nsmanager:74 connecting
2023-09-28 13:23:38,224 DEBUG pyroute2.ndb.140714568272576.sources.localhost/nsmanager:74 loading
2023-09-28 13:23:38,228 DEBUG pyroute2.ndb.140714568272576.sources.localhost:74 running
2023-09-28 13:23:38,233 DEBUG pyroute2.ndb.140714568272576.sources.localhost/nsmanager:74 running
2023-09-28 13:23:38,236 DEBUG pyroute2.ndb.140714568272576.sources.localhost:399 source shutdown
2023-09-28 13:23:38,236 DEBUG pyroute2.ndb.140714568272576.sources.localhost:374 sync
2023-09-28 13:23:38,236 DEBUG pyroute2.ndb.140714568272576.sources.localhost:369 shutdown handled by the main thread
2023-09-28 13:23:38,236 DEBUG pyroute2.ndb.140714568272576.sources.localhost:74 stopped
2023-09-28 13:23:38,240 DEBUG pyroute2.ndb.140714568272576.main:851 flush DB for the target localhost
2023-09-28 13:23:38,240 DEBUG pyroute2.ndb.140714568272576.sources.localhost/nsmanager:399 source shutdown
2023-09-28 13:23:38,241 DEBUG pyroute2.ndb.140714568272576.sources.localhost/nsmanager:374 sync
2023-09-28 13:23:38,241 DEBUG pyroute2.ndb.140714568272576.sources.localhost/nsmanager:369 shutdown handled by the main thread
2023-09-28 13:23:38,241 DEBUG pyroute2.ndb.140714568272576.sources.localhost/nsmanager:74 stopped
2023-09-28 13:23:38,256 DEBUG pyroute2.ndb.140714568272576.main:851 flush DB for the target localhost/nsmanager
2023-09-28 13:23:38,257 DEBUG subiquitycore.controllers.network:102 default routes True
2023-09-28 13:23:38,257 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'169.254.0.0/16', 'ifindex': 2}
2023-09-28 13:23:38,257 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'192.168.122.0/24', 'ifindex': 2}
2023-09-28 13:23:38,257 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.0/8', 'ifindex': 1}
2023-09-28 13:23:38,257 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.1', 'ifindex': 1}
2023-09-28 13:23:38,257 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'127.255.255.255', 'ifindex': 1}
2023-09-28 13:23:38,257 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'192.168.122.252', 'ifindex': 2}
2023-09-28 13:23:38,257 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'192.168.122.255', 'ifindex': 2}
2023-09-28 13:23:38,257 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'::1', 'ifindex': 1}
2023-09-28 13:23:38,257 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'fe80::/64', 'ifindex': 2}
2023-09-28 13:23:38,257 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'::1', 'ifindex': 1}
2023-09-28 13:23:38,257 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'fe80::5054:ff:fe69:4945', 'ifindex': 2}
2023-09-28 13:23:38,257 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 5, 'table': 255, 'dst': b'ff00::/8', 'ifindex': 2}
2023-09-28 13:23:38,413 DEBUG subiquitycore.core:121 controllers started
2023-09-28 13:23:38,414 INFO root:30 start: subiquity/apply_autoinstall_config: 
2023-09-28 13:23:38,414 DEBUG root:30 start: subiquity/Early/apply_autoinstall_config: 
2023-09-28 13:23:38,414 DEBUG root:30 finish: subiquity/Early/apply_autoinstall_config: SUCCESS: 
2023-09-28 13:23:38,415 DEBUG root:30 start: subiquity/Reporting/apply_autoinstall_config: 
2023-09-28 13:23:38,415 DEBUG root:30 finish: subiquity/Reporting/apply_autoinstall_config: SUCCESS: 
2023-09-28 13:23:38,415 DEBUG root:30 start: subiquity/Error/apply_autoinstall_config: 
2023-09-28 13:23:38,415 DEBUG root:30 finish: subiquity/Error/apply_autoinstall_config: SUCCESS: 
2023-09-28 13:23:38,415 DEBUG root:30 start: subiquity/Userdata/apply_autoinstall_config: 
2023-09-28 13:23:38,415 DEBUG root:30 finish: subiquity/Userdata/apply_autoinstall_config: SUCCESS: 
2023-09-28 13:23:38,415 DEBUG subiquity.models.subiquity:252 model userdata for postinstall stage is configured, to go {'drivers', 'locale', 'identity', 'packages', 'ssh', 'ubuntu_pro', 'snaplist'}
2023-09-28 13:23:38,415 DEBUG root:30 start: subiquity/Package/apply_autoinstall_config: 
2023-09-28 13:23:38,415 DEBUG root:30 finish: subiquity/Package/apply_autoinstall_config: SUCCESS: 
2023-09-28 13:23:38,415 DEBUG subiquity.models.subiquity:252 model packages for postinstall stage is configured, to go {'drivers', 'locale', 'identity', 'ssh', 'ubuntu_pro', 'snaplist'}
2023-09-28 13:23:38,416 DEBUG root:30 start: subiquity/Debconf/apply_autoinstall_config: 
2023-09-28 13:23:38,416 DEBUG root:30 finish: subiquity/Debconf/apply_autoinstall_config: SUCCESS: 
2023-09-28 13:23:38,416 DEBUG subiquity.models.subiquity:252 model debconf_selections for install stage is configured, to go {'filesystem', 'keyboard', 'kernel', 'proxy', 'source'}
2023-09-28 13:23:38,416 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Locale as interactive
2023-09-28 13:23:38,416 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Refresh as interactive
2023-09-28 13:23:38,416 DEBUG root:30 start: subiquity/Kernel/apply_autoinstall_config: 
2023-09-28 13:23:38,416 DEBUG root:30 finish: subiquity/Kernel/apply_autoinstall_config: SUCCESS: 
2023-09-28 13:23:38,417 DEBUG subiquity.models.subiquity:252 model kernel for install stage is configured, to go {'source', 'filesystem', 'keyboard', 'proxy'}
2023-09-28 13:23:38,417 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Integrity as interactive
2023-09-28 13:23:38,417 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Keyboard as interactive
2023-09-28 13:23:38,417 DEBUG root:30 start: subiquity/Zdev/apply_autoinstall_config: 
2023-09-28 13:23:38,418 DEBUG root:30 finish: subiquity/Zdev/apply_autoinstall_config: SUCCESS: 
2023-09-28 13:23:38,422 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Source as interactive
2023-09-28 13:23:38,422 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Network as interactive
2023-09-28 13:23:38,422 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping UbuntuPro as interactive
2023-09-28 13:23:38,422 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Proxy as interactive
2023-09-28 13:23:38,422 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Mirror as interactive
2023-09-28 13:23:38,422 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Filesystem as interactive
2023-09-28 13:23:38,422 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Identity as interactive
2023-09-28 13:23:38,422 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping SSH as interactive
2023-09-28 13:23:38,422 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping SnapList as interactive
2023-09-28 13:23:38,423 DEBUG root:30 start: subiquity/Ad/apply_autoinstall_config: 
2023-09-28 13:23:38,423 DEBUG root:30 finish: subiquity/Ad/apply_autoinstall_config: SUCCESS: 
2023-09-28 13:23:38,423 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Codecs as interactive
2023-09-28 13:23:38,423 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Drivers as interactive
2023-09-28 13:23:38,423 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping OEM as interactive
2023-09-28 13:23:38,423 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping TimeZone as interactive
2023-09-28 13:23:38,423 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Install as interactive
2023-09-28 13:23:38,423 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Updates as interactive
2023-09-28 13:23:38,423 DEBUG root:30 start: subiquity/Late/apply_autoinstall_config: 
2023-09-28 13:23:38,423 DEBUG root:30 finish: subiquity/Late/apply_autoinstall_config: SUCCESS: 
2023-09-28 13:23:38,424 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Shutdown as interactive
2023-09-28 13:23:38,424 INFO root:30 finish: subiquity/apply_autoinstall_config: SUCCESS: 
2023-09-28 13:23:38,424 DEBUG subiquity.models.subiquity:252 model locale for postinstall stage is configured, to go {'drivers', 'identity', 'ssh', 'ubuntu_pro', 'snaplist'}
2023-09-28 13:23:38,424 DEBUG root:30 start: subiquity/Refresh/configure_snapd: 
2023-09-28 13:23:38,424 DEBUG root:30 start: subiquity/Refresh/configure_snapd/get_details: 
2023-09-28 13:23:38,429 DEBUG root:30 start: subiquity/Refresh/check_for_update: 
2023-09-28 13:23:38,430 DEBUG subiquitycore.utils:118 arun_command called: ['/usr/sbin/realm', 'discover']
2023-09-28 13:23:38,449 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/snaps/ubuntu-desktop-installer HTTP/1.1" 200 1560
2023-09-28 13:23:38,449 DEBUG root:30 start: subiquity/OEM/load_metapackages_list: 
2023-09-28 13:23:38,449 DEBUG root:30 start: subiquity/OEM/load_metapackages_list/wait_confirmation: 
2023-09-28 13:23:38,449 DEBUG root:30 start: subiquity/Install/install: 
2023-09-28 13:23:38,450 DEBUG subiquity.server.controllers.snaplist:79 loading list of snaps
2023-09-28 13:23:38,554 DEBUG root:30 start: subiquity/Filesystem/_probe: 
2023-09-28 13:23:38,554 DEBUG root:30 start: subiquity/Refresh/check_for_update: 
2023-09-28 13:23:38,554 DEBUG root:30 start: subiquity/SnapList/loader: 
2023-09-28 13:23:38,554 DEBUG root:30 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2023-09-28 13:23:38,562 DEBUG asyncio:54 Using selector: EpollSelector
2023-09-28 13:23:38,563 DEBUG root:30 finish: subiquity/Refresh/configure_snapd/get_details: SUCCESS: current version of snap is: '0+git.bf01a899'
2023-09-28 13:23:38,573 DEBUG subiquity.server.controllers.refresh:139 snap tracking , not resetting based on .disk/info
2023-09-28 13:23:38,573 DEBUG root:30 finish: subiquity/Refresh/configure_snapd: SUCCESS: 
2023-09-28 13:23:38,573 INFO root:30 start: subiquity/Meta/status_GET: 
2023-09-28 13:23:38,573 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2023-09-28 13:23:38,574 INFO aiohttp.access:206  [28/Sep/2023:13:23:38 +0000] "GET /meta/status HTTP/1.1" 200 412 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:38,574 ERROR root:30 finish: subiquity/Refresh/check_for_update: FAIL: cancelled
2023-09-28 13:23:38,574 DEBUG root:30 start: subiquity/SnapList/loader/list: 
2023-09-28 13:23:38,594 INFO root:30 start: subiquity/Meta/status_GET: 
2023-09-28 13:23:38,595 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2023-09-28 13:23:38,595 INFO aiohttp.access:206  [28/Sep/2023:13:23:38 +0000] "GET /meta/status HTTP/1.1" 200 412 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:38,595 INFO root:30 start: subiquity/Meta/status_GET: 
2023-09-28 13:23:38,595 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2023-09-28 13:23:38,595 INFO aiohttp.access:206  [28/Sep/2023:13:23:38 +0000] "GET /meta/status HTTP/1.1" 200 412 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:38,595 INFO root:30 start: subiquity/Meta/client_variant_POST: 
2023-09-28 13:23:38,596 INFO root:30 finish: subiquity/Meta/client_variant_POST: SUCCESS: 200 null
2023-09-28 13:23:38,596 INFO aiohttp.access:206  [28/Sep/2023:13:23:38 +0000] "POST /meta/client_variant?variant=%22desktop%22 HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:38,596 DEBUG subiquitycore.utils:132 arun_command ['/usr/sbin/realm', 'discover'] exited with code 1
2023-09-28 13:23:38,599 INFO root:30 start: subiquity/Meta/status_GET: 
2023-09-28 13:23:38,602 INFO root:30 start: subiquity/Meta/interactive_sections_GET: 
2023-09-28 13:23:38,603 INFO root:30 finish: subiquity/Meta/interactive_sections_GET: SUCCESS: 200 null
2023-09-28 13:23:38,603 INFO aiohttp.access:206  [28/Sep/2023:13:23:38 +0000] "GET /meta/interactive_sections HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:38,603 INFO root:30 start: subiquity/Meta/status_GET: 
2023-09-28 13:23:38,603 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2023-09-28 13:23:38,603 INFO aiohttp.access:206  [28/Sep/2023:13:23:38 +0000] "GET /meta/status HTTP/1.1" 200 412 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:38,627 DEBUG root:30 start: subiquity/Locale/GET: 
2023-09-28 13:23:38,627 DEBUG root:30 finish: subiquity/Locale/GET: SUCCESS: 200 "C.UTF-8"
2023-09-28 13:23:38,628 INFO aiohttp.access:206  [28/Sep/2023:13:23:38 +0000] "GET /locale HTTP/1.1" 200 195 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:38,628 INFO root:30 start: subiquity/Meta/mark_configured_POST: 
2023-09-28 13:23:38,629 DEBUG subiquity.models.subiquity:252 model ubuntu_pro for postinstall stage is configured, to go {'drivers', 'codecs', 'identity', 'network', 'ssh', 'snaplist', 'timezone'}
2023-09-28 13:23:38,629 DEBUG subiquity.models.subiquity:252 model proxy for install stage is configured, to go {'network', 'filesystem', 'keyboard', 'source', 'mirror'}
2023-09-28 13:23:38,629 DEBUG subiquity.models.subiquity:252 model mirror for install stage is configured, to go {'source', 'filesystem', 'keyboard', 'network'}
2023-09-28 13:23:38,629 DEBUG subiquity.models.subiquity:252 model ssh for postinstall stage is configured, to go {'drivers', 'codecs', 'identity', 'network', 'snaplist', 'timezone'}
2023-09-28 13:23:38,629 DEBUG subiquity.models.subiquity:252 model snaplist for postinstall stage is configured, to go {'drivers', 'codecs', 'identity', 'network', 'timezone'}
2023-09-28 13:23:38,629 INFO root:30 finish: subiquity/Meta/mark_configured_POST: SUCCESS: 200 null
2023-09-28 13:23:38,635 INFO aiohttp.access:206  [28/Sep/2023:13:23:38 +0000] "POST /meta/mark_configured?endpoint_names=%5B%22mirror%22%2C%22proxy%22%2C%22ssh%22%2C%22snaplist%22%2C%22ubuntu_pro%22%5D HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:38,639 DEBUG subiquity.server.geoip:124 no CountryCode found in '<?xml version="1.0" encoding="UTF-8"?><Response><Ip>10.172.200.64</Ip><Status>IP NOT FOUND</Status></Response>\n'
2023-09-28 13:23:38,877 DEBUG root:30 start: subiquity/Refresh/GET: 
2023-09-28 13:23:38,878 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?section=server HTTP/1.1" 200 None
2023-09-28 13:23:38,879 DEBUG root:30 finish: subiquity/SnapList/loader/list: SUCCESS: 
2023-09-28 13:23:38,879 DEBUG subiquity.server.controllers.snaplist:92 fetched list of 22 snaps
2023-09-28 13:23:38,879 DEBUG root:30 start: subiquity/SnapList/loader/fetch/microk8s: 
2023-09-28 13:23:38,894 DEBUG probert.dasd:134 Probing DASD devies
2023-09-28 13:23:38,894 DEBUG probert.dasd:137 DASD devices only present on s390x, arch=x86_64
2023-09-28 13:23:39,105 ERROR probert.multipath:38 Failed to run cmd: ['multipathd', 'show', 'maps', 'raw', 'format', '%w,%d,%N']
2023-09-28 13:23:39,106 ERROR probert.multipath:38 Failed to run cmd: ['multipathd', 'show', 'paths', 'raw', 'format', '%d,%z,%m,%N,%n,%R,%r,%a']
2023-09-28 13:23:39,380 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?select=refresh HTTP/1.1" 200 59
2023-09-28 13:23:39,388 DEBUG subiquity.server.controllers.refresh:201 check_for_update received []
2023-09-28 13:23:39,389 DEBUG root:30 finish: subiquity/Refresh/check_for_update: SUCCESS: no new version of snap available
2023-09-28 13:23:39,389 DEBUG root:30 finish: subiquity/Refresh/GET: SUCCESS: 200 {"availability": "UNAVAILABLE", "current_snap_version": "0+git.bf01a899", "ne...
2023-09-28 13:23:39,390 INFO aiohttp.access:206  [28/Sep/2023:13:23:38 +0000] "GET /refresh?wait=true HTTP/1.1" 200 284 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:39,596 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=microk8s HTTP/1.1" 200 None
2023-09-28 13:23:39,616 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/microk8s: SUCCESS: 
2023-09-28 13:23:39,617 DEBUG root:30 start: subiquity/SnapList/loader/fetch/nextcloud: 
2023-09-28 13:23:39,799 DEBUG curtin:1321 Extracting storage config from probe data
2023-09-28 13:23:39,799 DEBUG curtin:73 /dev/vda is multipath device member? False
2023-09-28 13:23:39,799 DEBUG curtin:86 /dev/vda is multipath device partition? False
2023-09-28 13:23:39,799 DEBUG curtin:61 /dev/vda is multipath device? False
2023-09-28 13:23:39,799 DEBUG curtin:86 /dev/vda is multipath device partition? False
2023-09-28 13:23:39,799 DEBUG curtin:61 /dev/vda is multipath device? False
2023-09-28 13:23:39,817 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2023-09-28 13:23:39,817 DEBUG curtin:86 /dev/sr0 is multipath device partition? False
2023-09-28 13:23:39,817 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2023-09-28 13:23:39,817 DEBUG curtin:1328 Sorting extracted configurations
2023-09-28 13:23:39,817 INFO curtin:1347 Validating extracted storage config components
2023-09-28 13:23:39,832 DEBUG curtin:1364 Extracted (unmerged) storage config:
storage:
-   id: disk-vda
    path: /dev/vda
    type: disk

2023-09-28 13:23:39,840 DEBUG curtin:1368 Generating storage config dependencies
2023-09-28 13:23:39,840 DEBUG curtin:1374 Merging storage config dependencies
2023-09-28 13:23:39,840 DEBUG curtin:1379 Merged storage config:
storage:
    config:
    -   id: disk-vda
        path: /dev/vda
        type: disk
    version: 2

2023-09-28 13:23:39,840 DEBUG subiquity.models.filesystem:1452 majmin_to_dev {'253:0': Disk(path='/dev/vda', preserve=True, id='disk-vda', type='disk')}
2023-09-28 13:23:39,840 DEBUG subiquity.models.filesystem:1464 considering mount of 0:28
2023-09-28 13:23:39,840 DEBUG subiquity.models.filesystem:1464 considering mount of 0:22
2023-09-28 13:23:39,840 DEBUG subiquity.models.filesystem:1464 considering mount of 0:23
2023-09-28 13:23:39,840 DEBUG subiquity.models.filesystem:1464 considering mount of 0:5
2023-09-28 13:23:39,840 DEBUG subiquity.models.filesystem:1464 considering mount of 0:25
2023-09-28 13:23:39,840 DEBUG subiquity.models.filesystem:1464 considering mount of 11:0
2023-09-28 13:23:39,840 DEBUG subiquity.models.filesystem:1464 considering mount of 7:0
2023-09-28 13:23:39,840 DEBUG subiquity.models.filesystem:1464 considering mount of 0:28
2023-09-28 13:23:39,840 DEBUG subiquity.models.filesystem:1464 considering mount of 0:44
2023-09-28 13:23:39,840 DEBUG subiquity.models.filesystem:1464 considering mount of 7:4
2023-09-28 13:23:39,840 DEBUG subiquity.models.filesystem:1464 considering mount of 7:3
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:7
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:5
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:6
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:8
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:9
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:11
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:10
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:12
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:28
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:6
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:35
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:36
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:37
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:7
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:12
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:40
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:21
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:38
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:24
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:33
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:20
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:39
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:34
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:41
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:42
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:43
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:45
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:48
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:25
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:89
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:4
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:3
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:7
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:5
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:6
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:8
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:9
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:11
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:10
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 7:12
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:50
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:4
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:4
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:4
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:4
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:62
2023-09-28 13:23:39,841 DEBUG subiquity.models.filesystem:1464 considering mount of 0:90
2023-09-28 13:23:39,841 DEBUG root:30 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False
2023-09-28 13:23:39,841 DEBUG subiquity.server.controllers.filesystem:1295 block probing took 1.3 seconds
2023-09-28 13:23:39,842 DEBUG root:30 finish: subiquity/Filesystem/_probe: SUCCESS: 
2023-09-28 13:23:40,191 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=nextcloud HTTP/1.1" 200 None
2023-09-28 13:23:40,192 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/nextcloud: SUCCESS: 
2023-09-28 13:23:40,192 DEBUG root:30 start: subiquity/SnapList/loader/fetch/wekan: 
2023-09-28 13:23:40,595 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=wekan HTTP/1.1" 200 None
2023-09-28 13:23:40,596 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/wekan: SUCCESS: 
2023-09-28 13:23:40,596 DEBUG root:30 start: subiquity/SnapList/loader/fetch/kata-containers: 
2023-09-28 13:23:41,003 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=kata-containers HTTP/1.1" 200 None
2023-09-28 13:23:41,004 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/kata-containers: SUCCESS: 
2023-09-28 13:23:41,004 DEBUG root:30 start: subiquity/SnapList/loader/fetch/docker: 
2023-09-28 13:23:41,414 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=docker HTTP/1.1" 200 None
2023-09-28 13:23:41,414 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/docker: SUCCESS: 
2023-09-28 13:23:41,414 DEBUG root:30 start: subiquity/SnapList/loader/fetch/canonical-livepatch: 
2023-09-28 13:23:41,925 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=canonical-livepatch HTTP/1.1" 200 None
2023-09-28 13:23:41,926 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/canonical-livepatch: SUCCESS: 
2023-09-28 13:23:41,926 DEBUG root:30 start: subiquity/SnapList/loader/fetch/rocketchat-server: 
2023-09-28 13:23:42,333 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=rocketchat-server HTTP/1.1" 200 None
2023-09-28 13:23:42,334 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/rocketchat-server: SUCCESS: 
2023-09-28 13:23:42,334 DEBUG root:30 start: subiquity/SnapList/loader/fetch/mosquitto: 
2023-09-28 13:23:42,742 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=mosquitto HTTP/1.1" 200 None
2023-09-28 13:23:42,742 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/mosquitto: SUCCESS: 
2023-09-28 13:23:42,743 DEBUG root:30 start: subiquity/SnapList/loader/fetch/etcd: 
2023-09-28 13:23:43,466 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=etcd HTTP/1.1" 200 None
2023-09-28 13:23:43,467 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/etcd: SUCCESS: 
2023-09-28 13:23:43,467 DEBUG root:30 start: subiquity/SnapList/loader/fetch/powershell: 
2023-09-28 13:23:43,969 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=powershell HTTP/1.1" 200 None
2023-09-28 13:23:43,970 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/powershell: SUCCESS: 
2023-09-28 13:23:43,970 DEBUG root:30 start: subiquity/SnapList/loader/fetch/sabnzbd: 
2023-09-28 13:23:44,378 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=sabnzbd HTTP/1.1" 200 None
2023-09-28 13:23:44,379 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/sabnzbd: SUCCESS: 
2023-09-28 13:23:44,380 DEBUG root:30 start: subiquity/SnapList/loader/fetch/wormhole: 
2023-09-28 13:23:44,689 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=wormhole HTTP/1.1" 200 None
2023-09-28 13:23:44,690 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/wormhole: SUCCESS: 
2023-09-28 13:23:44,690 DEBUG root:30 start: subiquity/SnapList/loader/fetch/aws-cli: 
2023-09-28 13:23:45,401 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=aws-cli HTTP/1.1" 200 None
2023-09-28 13:23:45,402 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/aws-cli: SUCCESS: 
2023-09-28 13:23:45,402 DEBUG root:30 start: subiquity/SnapList/loader/fetch/google-cloud-sdk: 
2023-09-28 13:23:45,913 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=google-cloud-sdk HTTP/1.1" 200 1799
2023-09-28 13:23:45,914 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/google-cloud-sdk: SUCCESS: 
2023-09-28 13:23:45,914 DEBUG root:30 start: subiquity/SnapList/loader/fetch/slcli: 
2023-09-28 13:23:46,324 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=slcli HTTP/1.1" 200 None
2023-09-28 13:23:46,324 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/slcli: SUCCESS: 
2023-09-28 13:23:46,325 DEBUG root:30 start: subiquity/SnapList/loader/fetch/doctl: 
2023-09-28 13:23:46,717 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=doctl HTTP/1.1" 200 None
2023-09-28 13:23:46,718 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/doctl: SUCCESS: 
2023-09-28 13:23:46,718 DEBUG root:30 start: subiquity/SnapList/loader/fetch/conjure-up: 
2023-09-28 13:23:47,244 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=conjure-up HTTP/1.1" 200 None
2023-09-28 13:23:47,245 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/conjure-up: SUCCESS: 
2023-09-28 13:23:47,245 DEBUG root:30 start: subiquity/SnapList/loader/fetch/postgresql10: 
2023-09-28 13:23:47,551 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=postgresql10 HTTP/1.1" 200 1523
2023-09-28 13:23:47,551 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/postgresql10: SUCCESS: 
2023-09-28 13:23:47,551 DEBUG root:30 start: subiquity/SnapList/loader/fetch/heroku: 
2023-09-28 13:23:47,962 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=heroku HTTP/1.1" 200 None
2023-09-28 13:23:47,962 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/heroku: SUCCESS: 
2023-09-28 13:23:47,962 DEBUG root:30 start: subiquity/SnapList/loader/fetch/keepalived: 
2023-09-28 13:23:48,268 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=keepalived HTTP/1.1" 200 None
2023-09-28 13:23:48,269 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/keepalived: SUCCESS: 
2023-09-28 13:23:48,269 DEBUG root:30 start: subiquity/SnapList/loader/fetch/prometheus: 
2023-09-28 13:23:49,085 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=prometheus HTTP/1.1" 200 None
2023-09-28 13:23:49,086 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/prometheus: SUCCESS: 
2023-09-28 13:23:49,086 DEBUG root:30 start: subiquity/SnapList/loader/fetch/juju: 
2023-09-28 13:23:49,301 DEBUG subiquity.server.controllers.integrity:61 casper-md5check results: {'checksum_missmatch': [], 'result': 'pass'}
2023-09-28 13:23:49,495 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=juju HTTP/1.1" 200 None
2023-09-28 13:23:49,496 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/juju: SUCCESS: 
2023-09-28 13:23:49,496 DEBUG root:30 finish: subiquity/SnapList/loader: SUCCESS: 
2023-09-28 13:23:51,612 DEBUG root:30 start: subiquity/Locale/POST: 
2023-09-28 13:23:51,613 DEBUG subiquity.server.controllers.locale:68 en_US.UTF-8
2023-09-28 13:23:51,613 DEBUG subiquity.models.subiquity:252 model locale for postinstall stage is configured, to go {'drivers', 'codecs', 'identity', 'network', 'timezone'}
2023-09-28 13:23:51,613 DEBUG root:30 finish: subiquity/Locale/POST: SUCCESS: 200 null
2023-09-28 13:23:51,613 INFO aiohttp.access:206  [28/Sep/2023:13:23:51 +0000] "POST /locale HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:51,613 DEBUG subiquitycore.utils:118 arun_command called: ['localectl', 'set-locale', 'en_US.UTF-8']
2023-09-28 13:23:52,093 DEBUG subiquitycore.utils:132 arun_command ['localectl', 'set-locale', 'en_US.UTF-8'] exited with code 0
2023-09-28 13:23:53,741 DEBUG root:30 start: subiquity/Filesystem/has_rst_GET: 
2023-09-28 13:23:53,741 DEBUG root:30 finish: subiquity/Filesystem/has_rst_GET: SUCCESS: 200 false
2023-09-28 13:23:53,741 INFO aiohttp.access:206  [28/Sep/2023:13:23:53 +0000] "GET /storage/has_rst HTTP/1.1" 200 191 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:53,746 DEBUG root:30 start: subiquity/Keyboard/GET: 
2023-09-28 13:23:53,753 DEBUG root:30 finish: subiquity/Keyboard/GET: SUCCESS: 200 {"setting": {"layout": "us", "variant": "", "toggle": null}, "layouts": [{"co...
2023-09-28 13:23:53,754 INFO aiohttp.access:206  [28/Sep/2023:13:23:53 +0000] "GET /keyboard HTTP/1.1" 200 41538 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:53,756 DEBUG root:30 start: subiquity/Keyboard/GET: 
2023-09-28 13:23:53,763 DEBUG root:30 finish: subiquity/Keyboard/GET: SUCCESS: 200 {"setting": {"layout": "us", "variant": "", "toggle": null}, "layouts": [{"co...
2023-09-28 13:23:53,763 INFO aiohttp.access:206  [28/Sep/2023:13:23:53 +0000] "GET /keyboard HTTP/1.1" 200 41538 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:53,765 DEBUG root:30 start: subiquity/Keyboard/input_source_POST: 
2023-09-28 13:23:53,766 DEBUG subiquitycore.utils:118 arun_command called: ['systemd-run', '--wait', '--uid=1000', '--setenv=DISPLAY=:0', '--setenv=XDG_RUNTIME_DIR=/run/user/1000', '--setenv=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus', '--', 'gsettings', 'set', 'org.gnome.desktop.input-sources', 'sources', "[('xkb','us')]"]
2023-09-28 13:23:53,840 DEBUG subiquitycore.utils:132 arun_command ['systemd-run', '--wait', '--uid=1000', '--setenv=DISPLAY=:0', '--setenv=XDG_RUNTIME_DIR=/run/user/1000', '--setenv=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus', '--', 'gsettings', 'set', 'org.gnome.desktop.input-sources', 'sources', "[('xkb','us')]"] exited with code 0
2023-09-28 13:23:53,840 DEBUG root:30 finish: subiquity/Keyboard/input_source_POST: SUCCESS: 200 null
2023-09-28 13:23:53,840 INFO aiohttp.access:206  [28/Sep/2023:13:23:53 +0000] "POST /keyboard/input_source?user=%22ubuntu%22 HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:54,898 DEBUG root:30 start: subiquity/Keyboard/input_source_POST: 
2023-09-28 13:23:54,899 DEBUG subiquitycore.utils:118 arun_command called: ['systemd-run', '--wait', '--uid=1000', '--setenv=DISPLAY=:0', '--setenv=XDG_RUNTIME_DIR=/run/user/1000', '--setenv=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus', '--', 'gsettings', 'set', 'org.gnome.desktop.input-sources', 'sources', "[('xkb','gb')]"]
2023-09-28 13:23:54,938 DEBUG subiquitycore.utils:132 arun_command ['systemd-run', '--wait', '--uid=1000', '--setenv=DISPLAY=:0', '--setenv=XDG_RUNTIME_DIR=/run/user/1000', '--setenv=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus', '--', 'gsettings', 'set', 'org.gnome.desktop.input-sources', 'sources', "[('xkb','gb')]"] exited with code 0
2023-09-28 13:23:54,938 DEBUG root:30 finish: subiquity/Keyboard/input_source_POST: SUCCESS: 200 null
2023-09-28 13:23:54,938 INFO aiohttp.access:206  [28/Sep/2023:13:23:54 +0000] "POST /keyboard/input_source?user=%22ubuntu%22 HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:56,124 DEBUG root:30 start: subiquity/Keyboard/POST: 
2023-09-28 13:23:56,124 DEBUG subiquity.server.controllers.keyboard:221 KeyboardSetting(layout='gb', variant='', toggle=None)
2023-09-28 13:23:56,125 DEBUG subiquitycore.utils:118 arun_command called: ['setupcon', '--save', '--force', '--keyboard-only']
2023-09-28 13:23:56,527 DEBUG subiquitycore.utils:132 arun_command ['setupcon', '--save', '--force', '--keyboard-only'] exited with code 0
2023-09-28 13:23:56,527 DEBUG subiquitycore.utils:118 arun_command called: ['/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin/subiquity-loadkeys']
2023-09-28 13:23:56,535 DEBUG subiquitycore.utils:132 arun_command ['/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin/subiquity-loadkeys'] exited with code 0
2023-09-28 13:23:56,535 DEBUG subiquity.models.subiquity:252 model keyboard for install stage is configured, to go {'filesystem', 'source', 'network'}
2023-09-28 13:23:56,535 DEBUG root:30 finish: subiquity/Keyboard/POST: SUCCESS: 200 null
2023-09-28 13:23:56,535 INFO aiohttp.access:206  [28/Sep/2023:13:23:56 +0000] "POST /keyboard HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:57,542 DEBUG root:30 start: subiquity/Refresh/GET: 
2023-09-28 13:23:57,543 DEBUG root:30 finish: subiquity/Refresh/GET: SUCCESS: 200 {"availability": "UNAVAILABLE", "current_snap_version": "0+git.bf01a899", "ne...
2023-09-28 13:23:57,543 INFO aiohttp.access:206  [28/Sep/2023:13:23:57 +0000] "GET /refresh?wait=true HTTP/1.1" 200 284 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:57,545 DEBUG root:30 start: subiquity/Source/GET: 
2023-09-28 13:23:57,545 DEBUG root:30 finish: subiquity/Source/GET: SUCCESS: 200 {"sources": [{"name": "Ubuntu Desktop (minimized)", "description": "A minimal...
2023-09-28 13:23:57,546 INFO aiohttp.access:206  [28/Sep/2023:13:23:57 +0000] "GET /source HTTP/1.1" 200 614 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:57,548 DEBUG root:30 start: subiquity/Drivers/GET: 
2023-09-28 13:23:57,548 DEBUG root:30 finish: subiquity/Drivers/GET: SUCCESS: 200 {"install": false, "drivers": null, "local_only": true, "search_drivers": false}
2023-09-28 13:23:57,549 INFO aiohttp.access:206  [28/Sep/2023:13:23:57 +0000] "GET /drivers HTTP/1.1" 200 267 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:57,550 DEBUG root:30 start: subiquity/Codecs/GET: 
2023-09-28 13:23:57,550 DEBUG root:30 finish: subiquity/Codecs/GET: SUCCESS: 200 {"install": false}
2023-09-28 13:23:57,551 INFO aiohttp.access:206  [28/Sep/2023:13:23:57 +0000] "GET /codecs HTTP/1.1" 200 205 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:58,667 DEBUG root:30 start: subiquity/Source/POST: 
2023-09-28 13:23:58,668 DEBUG subiquity.models.subiquity:252 model source for install stage is configured, to go {'filesystem', 'network'}
2023-09-28 13:23:58,668 DEBUG subiquity.server.controllers.drivers:89 source variant has been set. Querying list of drivers.
2023-09-28 13:23:58,668 DEBUG root:30 finish: subiquity/Source/POST: SUCCESS: 200 null
2023-09-28 13:23:58,669 INFO aiohttp.access:206  [28/Sep/2023:13:23:58 +0000] "POST /source?source_id=%22ubuntu-desktop-minimal%22&search_drivers=false HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:58,669 DEBUG subiquity.server.controllers.filesystem:412 got system None for variation minimal
2023-09-28 13:23:58,669 DEBUG curtin:95 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/minimal.squashfs', '/tmp/tmp347rtjbg/minimal.squashfs.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:23:58,686 DEBUG curtin:95 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/minimal.enhanced-secureboot.squashfs', '/tmp/tmp347rtjbg/minimal.enhanced-secureboot.squashfs.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:23:58,704 DEBUG curtin:95 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/minimal.enhanced-secureboot.en.squashfs', '/tmp/tmp347rtjbg/minimal.enhanced-secureboot.en.squashfs.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:23:58,736 DEBUG curtin:95 Running command ['mount', '-o', 'lowerdir=/tmp/tmp347rtjbg/minimal.enhanced-secureboot.en.squashfs.dir:/tmp/tmp347rtjbg/minimal.enhanced-secureboot.squashfs.dir:/tmp/tmp347rtjbg/minimal.squashfs.dir', '-t', 'overlay', 'overlay', '/tmp/tmp347rtjbg/root.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:23:58,740 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', 'mount', '-o', 'bind', '/tmp/tmp347rtjbg/root.dir/var/lib/snapd/seed/systems', '/var/lib/snapd/seed/systems']
2023-09-28 13:23:58,748 DEBUG root:30 start: subiquity/Drivers/_list_drivers: 
2023-09-28 13:23:58,748 DEBUG root:30 start: subiquity/Drivers/_list_drivers/wait_apt: 
2023-09-28 13:23:58,749 DEBUG root:30 start: subiquity/Drivers/POST: 
2023-09-28 13:23:58,749 DEBUG subiquity.models.subiquity:252 model drivers for postinstall stage is configured, to go {'codecs', 'identity', 'timezone', 'network'}
2023-09-28 13:23:58,749 DEBUG root:30 finish: subiquity/Drivers/POST: SUCCESS: 200 null
2023-09-28 13:23:58,749 INFO aiohttp.access:206  [28/Sep/2023:13:23:58 +0000] "POST /drivers HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:58,749 DEBUG root:30 start: subiquity/Codecs/POST: 
2023-09-28 13:23:58,749 DEBUG subiquity.models.subiquity:252 model codecs for postinstall stage is configured, to go {'timezone', 'identity', 'network'}
2023-09-28 13:23:58,750 DEBUG root:30 finish: subiquity/Codecs/POST: SUCCESS: 200 null
2023-09-28 13:23:58,750 INFO aiohttp.access:206  [28/Sep/2023:13:23:58 +0000] "POST /codecs HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:23:58,750 DEBUG root:30 start: subiquity/Filesystem/v2_GET: 
2023-09-28 13:23:58,754 DEBUG subiquitycore.utils:76 run_command called: ['udevadm', 'settle', '-t', '0']
2023-09-28 13:23:58,776 DEBUG subiquitycore.utils:95 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2023-09-28 13:23:58,776 DEBUG subiquity.server.controllers.filesystem:1497 _udev_event add Device('/sys/devices/virtual/block/loop14')
2023-09-28 13:23:58,776 DEBUG subiquity.server.controllers.filesystem:1480 Triggered Probert run on udev event
2023-09-28 13:23:58,776 DEBUG root:30 start: subiquity/Filesystem/_probe: 
2023-09-28 13:23:58,776 DEBUG root:30 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2023-09-28 13:23:58,777 DEBUG asyncio:54 Using selector: EpollSelector
2023-09-28 13:23:58,791 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', 'mount', '-o', 'bind', '/tmp/tmp347rtjbg/root.dir/var/lib/snapd/seed/snaps/pc-kernel_1415.snap', '/var/lib/snapd/seed/snaps/pc-kernel_1415.snap']
2023-09-28 13:23:58,893 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', 'mount', '-o', 'bind', '/tmp/tmp347rtjbg/root.dir/var/lib/snapd/seed/snaps/pc_154.snap', '/var/lib/snapd/seed/snaps/pc_154.snap']
2023-09-28 13:23:59,090 DEBUG probert.dasd:134 Probing DASD devies
2023-09-28 13:23:59,090 DEBUG probert.dasd:137 DASD devices only present on s390x, arch=x86_64
2023-09-28 13:23:59,211 ERROR probert.multipath:38 Failed to run cmd: ['multipathd', 'show', 'maps', 'raw', 'format', '%w,%d,%N']
2023-09-28 13:23:59,213 ERROR probert.multipath:38 Failed to run cmd: ['multipathd', 'show', 'paths', 'raw', 'format', '%d,%z,%m,%N,%n,%R,%r,%a']
2023-09-28 13:23:59,231 DEBUG curtin:1321 Extracting storage config from probe data
2023-09-28 13:23:59,231 DEBUG curtin:73 /dev/vda is multipath device member? False
2023-09-28 13:23:59,231 DEBUG curtin:86 /dev/vda is multipath device partition? False
2023-09-28 13:23:59,231 DEBUG curtin:61 /dev/vda is multipath device? False
2023-09-28 13:23:59,232 DEBUG curtin:86 /dev/vda is multipath device partition? False
2023-09-28 13:23:59,232 DEBUG curtin:61 /dev/vda is multipath device? False
2023-09-28 13:23:59,241 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2023-09-28 13:23:59,242 DEBUG curtin:86 /dev/sr0 is multipath device partition? False
2023-09-28 13:23:59,242 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2023-09-28 13:23:59,242 DEBUG curtin:1328 Sorting extracted configurations
2023-09-28 13:23:59,242 INFO curtin:1347 Validating extracted storage config components
2023-09-28 13:23:59,257 DEBUG curtin:1364 Extracted (unmerged) storage config:
storage:
-   id: disk-vda
    path: /dev/vda
    type: disk

2023-09-28 13:23:59,257 DEBUG curtin:1368 Generating storage config dependencies
2023-09-28 13:23:59,257 DEBUG curtin:1374 Merging storage config dependencies
2023-09-28 13:23:59,262 DEBUG curtin:1379 Merged storage config:
storage:
    config:
    -   id: disk-vda
        path: /dev/vda
        type: disk
    version: 2

2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1452 majmin_to_dev {'253:0': Disk(path='/dev/vda', preserve=True, id='disk-vda', type='disk')}
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:28
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:22
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:23
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:5
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:25
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 11:0
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:0
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:28
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:44
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:4
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:3
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:7
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:5
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:6
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:8
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:9
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:11
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:10
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:12
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:28
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:88
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:88
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:88
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:6
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:35
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:36
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:37
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:7
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:12
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:40
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:21
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:38
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:24
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:33
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:20
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:39
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:34
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:41
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:42
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:43
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:45
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:48
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:25
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 0:89
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:4
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:3
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:7
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:5
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:6
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:8
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:9
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:11
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:10
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:12
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:0
2023-09-28 13:23:59,263 DEBUG subiquity.models.filesystem:1464 considering mount of 7:13
2023-09-28 13:23:59,264 DEBUG subiquity.models.filesystem:1464 considering mount of 7:14
2023-09-28 13:23:59,264 DEBUG subiquity.models.filesystem:1464 considering mount of 0:88
2023-09-28 13:23:59,264 DEBUG subiquity.models.filesystem:1464 considering mount of 0:50
2023-09-28 13:23:59,264 DEBUG subiquity.models.filesystem:1464 considering mount of 0:4
2023-09-28 13:23:59,264 DEBUG subiquity.models.filesystem:1464 considering mount of 0:4
2023-09-28 13:23:59,264 DEBUG subiquity.models.filesystem:1464 considering mount of 0:4
2023-09-28 13:23:59,264 DEBUG subiquity.models.filesystem:1464 considering mount of 0:4
2023-09-28 13:23:59,264 DEBUG subiquity.models.filesystem:1464 considering mount of 0:62
2023-09-28 13:23:59,264 DEBUG subiquity.models.filesystem:1464 considering mount of 0:90
2023-09-28 13:23:59,264 DEBUG root:30 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False
2023-09-28 13:23:59,264 DEBUG subiquity.server.controllers.filesystem:1295 block probing took 0.5 seconds
2023-09-28 13:23:59,264 DEBUG root:30 finish: subiquity/Filesystem/_probe: SUCCESS: 
2023-09-28 13:24:00,833 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/systems/enhanced-secureboot-desktop HTTP/1.1" 200 None
2023-09-28 13:24:00,834 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', 'umount', '/var/lib/snapd/seed/snaps/pc_154.snap']
2023-09-28 13:24:00,875 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', 'umount', '/var/lib/snapd/seed/snaps/pc-kernel_1415.snap']
2023-09-28 13:24:00,919 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', 'umount', '/var/lib/snapd/seed/systems']
2023-09-28 13:24:00,959 DEBUG curtin:95 Running command ['umount', '/tmp/tmp347rtjbg/root.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:24:00,962 DEBUG curtin:95 Running command ['umount', '/tmp/tmp347rtjbg/minimal.enhanced-secureboot.en.squashfs.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:24:00,965 DEBUG curtin:95 Running command ['umount', '/tmp/tmp347rtjbg/minimal.enhanced-secureboot.squashfs.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:24:00,994 DEBUG curtin:95 Running command ['umount', '/tmp/tmp347rtjbg/minimal.squashfs.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:24:01,002 DEBUG subiquity.server.controllers.filesystem:343 got system SystemDetails(current=False, volumes={'pc': Volume(schema='gpt', bootloader='grub', id='', structure=[VolumeStructure(name='EFI System partition', label='ubuntu-seed', offset=1048576, offset_write=None, size=786432000, type='C12A7328-F81F-11D2-BA4B-00A0C93EC93B', role='system-seed-null', id='', filesystem='vfat', content=[VolumeContent(source='grubx64.efi', target='EFI/boot/grubx64.efi', image='', offset=None, offset_write=None, size=0, unpack=False), VolumeContent(source='shim.efi.signed', target='EFI/boot/bootx64.efi', image='', offset=None, offset_write=None, size=0, unpack=False)], update=VolumeUpdate(edition=2, preserve=None)), VolumeStructure(name='ubuntu-boot', label='ubuntu-boot', offset=787480576, offset_write=None, size=786432000, type='0FC63DAF-8483-4772-8E79-3D69D8477DE4', role='system-boot', id='', filesystem='ext4', content=[VolumeContent(source='grubx64.efi', target='EFI/boot/grubx64.efi', image='', offset=None, offset_write=None, size=0, unpack=False), VolumeContent(source='shim.efi.signed', target='EFI/boot/bootx64.efi', image='', offset=None, offset_write=None, size=0, unpack=False)], update=VolumeUpdate(edition=1, preserve=None)), VolumeStructure(name='ubuntu-save', label='ubuntu-save', offset=1573912576, offset_write=None, size=33554432, type='0FC63DAF-8483-4772-8E79-3D69D8477DE4', role='system-save', id='', filesystem='ext4', content=None, update=VolumeUpdate(edition=0, preserve=None)), VolumeStructure(name='ubuntu-data', label='ubuntu-data', offset=1607467008, offset_write=None, size=4294967296, type='0FC63DAF-8483-4772-8E79-3D69D8477DE4', role='system-data', id='', filesystem='ext4', content=None, update=VolumeUpdate(edition=0, preserve=None))])}, storage_encryption=StorageEncryption(support=<StorageEncryptionSupport.UNAVAILABLE: 'unavailable'>, storage_safety=<StorageSafety.PREFER_ENCRYPTED: 'prefer-encrypted'>, encryption_type=<EncryptionType.NONE: ''>, unavailable_reason='not encrypting device storage as checking TPM gave: not a supported EFI system'))
2023-09-28 13:24:01,003 DEBUG subiquity.server.controllers.filesystem:412 got system SystemDetails(current=False, volumes={'pc': Volume(schema='gpt', bootloader='grub', id='', structure=[VolumeStructure(name='EFI System partition', label='ubuntu-seed', offset=1048576, offset_write=None, size=786432000, type='C12A7328-F81F-11D2-BA4B-00A0C93EC93B', role='system-seed-null', id='', filesystem='vfat', content=[VolumeContent(source='grubx64.efi', target='EFI/boot/grubx64.efi', image='', offset=None, offset_write=None, size=0, unpack=False), VolumeContent(source='shim.efi.signed', target='EFI/boot/bootx64.efi', image='', offset=None, offset_write=None, size=0, unpack=False)], update=VolumeUpdate(edition=2, preserve=None)), VolumeStructure(name='ubuntu-boot', label='ubuntu-boot', offset=787480576, offset_write=None, size=786432000, type='0FC63DAF-8483-4772-8E79-3D69D8477DE4', role='system-boot', id='', filesystem='ext4', content=[VolumeContent(source='grubx64.efi', target='EFI/boot/grubx64.efi', image='', offset=None, offset_write=None, size=0, unpack=False), VolumeContent(source='shim.efi.signed', target='EFI/boot/bootx64.efi', image='', offset=None, offset_write=None, size=0, unpack=False)], update=VolumeUpdate(edition=1, preserve=None)), VolumeStructure(name='ubuntu-save', label='ubuntu-save', offset=1573912576, offset_write=None, size=33554432, type='0FC63DAF-8483-4772-8E79-3D69D8477DE4', role='system-save', id='', filesystem='ext4', content=None, update=VolumeUpdate(edition=0, preserve=None)), VolumeStructure(name='ubuntu-data', label='ubuntu-data', offset=1607467008, offset_write=None, size=4294967296, type='0FC63DAF-8483-4772-8E79-3D69D8477DE4', role='system-data', id='', filesystem='ext4', content=None, update=VolumeUpdate(edition=0, preserve=None))])}, storage_encryption=StorageEncryption(support=<StorageEncryptionSupport.UNAVAILABLE: 'unavailable'>, storage_safety=<StorageSafety.PREFER_ENCRYPTED: 'prefer-encrypted'>, encryption_type=<EncryptionType.NONE: ''>, unavailable_reason='not encrypting device storage as checking TPM gave: not a supported EFI system')) for variation minimal-enhanced-secureboot
2023-09-28 13:24:01,003 DEBUG subiquity.server.controllers.filesystem:421 Disabling core boot based install options on non-UEFI system
2023-09-28 13:24:01,003 DEBUG subiquity.server.controllers.filesystem:994 suggested install minimum size: 8.303G
2023-09-28 13:24:01,003 DEBUG root:30 finish: subiquity/Filesystem/v2_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-vda", "label"...
2023-09-28 13:24:01,004 INFO aiohttp.access:206  [28/Sep/2023:13:23:58 +0000] "GET /storage/v2?wait=true HTTP/1.1" 200 697 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:01,004 DEBUG subiquitycore.utils:76 run_command called: ['udevadm', 'settle', '-t', '0']
2023-09-28 13:24:01,020 DEBUG subiquitycore.utils:95 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2023-09-28 13:24:01,020 DEBUG subiquity.server.controllers.filesystem:1497 _udev_event change Device('/sys/devices/virtual/block/loop14')
2023-09-28 13:24:01,020 DEBUG subiquity.server.controllers.filesystem:1497 _udev_event change Device('/sys/devices/virtual/block/loop14')
2023-09-28 13:24:01,020 DEBUG subiquity.server.controllers.filesystem:1497 _udev_event change Device('/sys/devices/virtual/block/loop13')
2023-09-28 13:24:01,020 DEBUG subiquity.server.controllers.filesystem:1497 _udev_event change Device('/sys/devices/virtual/block/loop13')
2023-09-28 13:24:01,020 DEBUG subiquity.server.controllers.filesystem:1480 Triggered Probert run on udev event
2023-09-28 13:24:01,021 DEBUG root:30 start: subiquity/Filesystem/_probe: 
2023-09-28 13:24:01,021 DEBUG root:30 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2023-09-28 13:24:01,021 DEBUG root:30 start: subiquity/Filesystem/v2_GET: 
2023-09-28 13:24:01,022 DEBUG asyncio:54 Using selector: EpollSelector
2023-09-28 13:24:01,305 DEBUG probert.dasd:134 Probing DASD devies
2023-09-28 13:24:01,305 DEBUG probert.dasd:137 DASD devices only present on s390x, arch=x86_64
2023-09-28 13:24:01,346 ERROR probert.multipath:38 Failed to run cmd: ['multipathd', 'show', 'maps', 'raw', 'format', '%w,%d,%N']
2023-09-28 13:24:01,347 ERROR probert.multipath:38 Failed to run cmd: ['multipathd', 'show', 'paths', 'raw', 'format', '%d,%z,%m,%N,%n,%R,%r,%a']
2023-09-28 13:24:01,355 DEBUG curtin:1321 Extracting storage config from probe data
2023-09-28 13:24:01,355 DEBUG curtin:73 /dev/vda is multipath device member? False
2023-09-28 13:24:01,355 DEBUG curtin:86 /dev/vda is multipath device partition? False
2023-09-28 13:24:01,355 DEBUG curtin:61 /dev/vda is multipath device? False
2023-09-28 13:24:01,355 DEBUG curtin:86 /dev/vda is multipath device partition? False
2023-09-28 13:24:01,355 DEBUG curtin:61 /dev/vda is multipath device? False
2023-09-28 13:24:01,367 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2023-09-28 13:24:01,367 DEBUG curtin:86 /dev/sr0 is multipath device partition? False
2023-09-28 13:24:01,367 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2023-09-28 13:24:01,368 DEBUG curtin:1328 Sorting extracted configurations
2023-09-28 13:24:01,368 INFO curtin:1347 Validating extracted storage config components
2023-09-28 13:24:01,378 DEBUG curtin:1364 Extracted (unmerged) storage config:
storage:
-   id: disk-vda
    path: /dev/vda
    type: disk

2023-09-28 13:24:01,378 DEBUG curtin:1368 Generating storage config dependencies
2023-09-28 13:24:01,378 DEBUG curtin:1374 Merging storage config dependencies
2023-09-28 13:24:01,378 DEBUG curtin:1379 Merged storage config:
storage:
    config:
    -   id: disk-vda
        path: /dev/vda
        type: disk
    version: 2

2023-09-28 13:24:01,378 DEBUG subiquity.models.filesystem:1452 majmin_to_dev {'253:0': Disk(path='/dev/vda', preserve=True, id='disk-vda', type='disk')}
2023-09-28 13:24:01,378 DEBUG subiquity.models.filesystem:1464 considering mount of 0:28
2023-09-28 13:24:01,378 DEBUG subiquity.models.filesystem:1464 considering mount of 0:22
2023-09-28 13:24:01,378 DEBUG subiquity.models.filesystem:1464 considering mount of 0:23
2023-09-28 13:24:01,378 DEBUG subiquity.models.filesystem:1464 considering mount of 0:5
2023-09-28 13:24:01,378 DEBUG subiquity.models.filesystem:1464 considering mount of 0:25
2023-09-28 13:24:01,378 DEBUG subiquity.models.filesystem:1464 considering mount of 11:0
2023-09-28 13:24:01,378 DEBUG subiquity.models.filesystem:1464 considering mount of 7:0
2023-09-28 13:24:01,378 DEBUG subiquity.models.filesystem:1464 considering mount of 0:28
2023-09-28 13:24:01,378 DEBUG subiquity.models.filesystem:1464 considering mount of 0:44
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:4
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:3
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:7
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:5
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:6
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:8
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:9
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:11
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:10
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:12
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:28
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:6
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:35
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:36
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:37
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:7
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:12
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:40
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:21
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:38
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:24
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:33
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:20
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:39
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:34
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:41
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:42
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:43
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:45
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:48
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:25
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:89
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:4
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:3
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:7
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:5
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:6
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:8
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:9
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:11
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:10
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 7:12
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:50
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:4
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:4
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:4
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:4
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:62
2023-09-28 13:24:01,379 DEBUG subiquity.models.filesystem:1464 considering mount of 0:90
2023-09-28 13:24:01,379 DEBUG root:30 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False
2023-09-28 13:24:01,379 DEBUG subiquity.server.controllers.filesystem:1295 block probing took 0.4 seconds
2023-09-28 13:24:01,379 DEBUG root:30 finish: subiquity/Filesystem/_probe: SUCCESS: 
2023-09-28 13:24:01,380 DEBUG subiquity.server.controllers.filesystem:994 suggested install minimum size: 8.303G
2023-09-28 13:24:01,380 DEBUG root:30 finish: subiquity/Filesystem/v2_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-vda", "label"...
2023-09-28 13:24:01,381 INFO aiohttp.access:206  [28/Sep/2023:13:24:01 +0000] "GET /storage/v2?wait=true HTTP/1.1" 200 697 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:01,381 DEBUG root:30 start: subiquity/Filesystem/v2_guided_GET: 
2023-09-28 13:24:01,381 DEBUG subiquity.server.controllers.filesystem:994 suggested install minimum size: 8.303G
2023-09-28 13:24:01,382 DEBUG root:30 finish: subiquity/Filesystem/v2_guided_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "configured": null, "targets": [{"di...
2023-09-28 13:24:01,382 INFO aiohttp.access:206  [28/Sep/2023:13:24:01 +0000] "GET /storage/v2/guided?wait=true HTTP/1.1" 200 788 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:01,382 DEBUG root:30 start: subiquity/Filesystem/has_bitlocker_GET: 
2023-09-28 13:24:01,383 DEBUG root:30 finish: subiquity/Filesystem/has_bitlocker_GET: SUCCESS: 200 []
2023-09-28 13:24:01,383 INFO aiohttp.access:206  [28/Sep/2023:13:24:01 +0000] "GET /storage/has_bitlocker HTTP/1.1" 200 188 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:14,034 DEBUG root:30 start: subiquity/Filesystem/has_bitlocker_GET: 
2023-09-28 13:24:14,035 DEBUG root:30 finish: subiquity/Filesystem/has_bitlocker_GET: SUCCESS: 200 []
2023-09-28 13:24:14,035 INFO aiohttp.access:206  [28/Sep/2023:13:24:14 +0000] "GET /storage/has_bitlocker HTTP/1.1" 200 188 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:14,037 DEBUG root:30 start: subiquity/Filesystem/v2_GET: 
2023-09-28 13:24:14,037 DEBUG subiquity.server.controllers.filesystem:994 suggested install minimum size: 8.303G
2023-09-28 13:24:14,038 DEBUG root:30 finish: subiquity/Filesystem/v2_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-vda", "label"...
2023-09-28 13:24:14,038 INFO aiohttp.access:206  [28/Sep/2023:13:24:14 +0000] "GET /storage/v2?wait=true HTTP/1.1" 200 697 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:14,040 DEBUG root:30 start: subiquity/Filesystem/v2_guided_GET: 
2023-09-28 13:24:14,040 DEBUG subiquity.server.controllers.filesystem:994 suggested install minimum size: 8.303G
2023-09-28 13:24:14,041 DEBUG root:30 finish: subiquity/Filesystem/v2_guided_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "configured": null, "targets": [{"di...
2023-09-28 13:24:14,041 INFO aiohttp.access:206  [28/Sep/2023:13:24:14 +0000] "GET /storage/v2/guided?wait=true HTTP/1.1" 200 788 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:14,043 DEBUG root:30 start: subiquity/Filesystem/v2_guided_POST: 
2023-09-28 13:24:14,044 DEBUG subiquity.server.controllers.filesystem:1150 GuidedChoiceV2(target=GuidedStorageTargetReformat(disk_id='disk-vda', allowed=[<GuidedCapability.DIRECT: 2>, <GuidedCapability.LVM: 3>, <GuidedCapability.LVM_LUKS: 4>, <GuidedCapability.ZFS: 5>], disallowed=[GuidedDisallowedCapability(capability=<GuidedCapability.CORE_BOOT_ENCRYPTED: 6>, reason=<GuidedDisallowedCapabilityReason.CORE_BOOT_ENCRYPTION_UNAVAILABLE: 2>, message='not encrypting device storage as checking TPM gave: not a supported EFI system'), GuidedDisallowedCapability(capability=<GuidedCapability.CORE_BOOT_UNENCRYPTED: 7>, reason=<GuidedDisallowedCapabilityReason.NOT_UEFI: 3>, message='Enhanced secure boot options only available on UEFI systems.')]), capability=<GuidedCapability.ZFS: 5>, recovery_key=None, sizing_policy=<SizingPolicy.ALL: 2>, reset_partition=False)
2023-09-28 13:24:14,045 DEBUG curtin:37 swap suggestion analysis: available: 19G maxsize: 4G memsize: 3G size before decision: 3G suggested size: 3G reason: lesser of formula or maxsize
2023-09-28 13:24:14,045 DEBUG subiquity.models.filesystem:2094 adding swap to Partition(device=disk-vda, size=4096786432, wipe='superblock', number=3, grub_device=None, offset=2149580800, id='partition-2')
2023-09-28 13:24:14,046 DEBUG subiquity.server.controllers.filesystem:994 suggested install minimum size: 8.303G
2023-09-28 13:24:14,047 DEBUG root:30 finish: subiquity/Filesystem/v2_guided_POST: SUCCESS: 200 {"status": "DONE", "error_report": null, "configured": {"target": {"disk_id":...
2023-09-28 13:24:14,048 INFO aiohttp.access:206  [28/Sep/2023:13:24:14 +0000] "POST /storage/v2/guided HTTP/1.1" 200 1352 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:14,051 DEBUG root:30 start: subiquity/Filesystem/v2_POST: 
2023-09-28 13:24:14,051 DEBUG subiquity.models.subiquity:252 model filesystem for install stage is configured, to go {'network'}
2023-09-28 13:24:14,051 DEBUG subiquity.server.controllers.filesystem:994 suggested install minimum size: 8.303G
2023-09-28 13:24:14,053 DEBUG root:30 finish: subiquity/Filesystem/v2_POST: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-vda", "label"...
2023-09-28 13:24:14,053 INFO aiohttp.access:206  [28/Sep/2023:13:24:14 +0000] "POST /storage/v2 HTTP/1.1" 200 1910 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:14,054 DEBUG root:30 start: subiquity/Filesystem/v2_GET: 
2023-09-28 13:24:14,054 DEBUG subiquity.server.controllers.filesystem:994 suggested install minimum size: 8.303G
2023-09-28 13:24:14,055 DEBUG root:30 finish: subiquity/Filesystem/v2_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-vda", "label"...
2023-09-28 13:24:14,056 INFO aiohttp.access:206  [28/Sep/2023:13:24:14 +0000] "GET /storage/v2?wait=true HTTP/1.1" 200 1910 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:14,057 DEBUG root:30 start: subiquity/Filesystem/v2_orig_config_GET: 
2023-09-28 13:24:14,058 DEBUG curtin:1321 Extracting storage config from probe data
2023-09-28 13:24:14,058 DEBUG curtin:73 /dev/vda is multipath device member? False
2023-09-28 13:24:14,058 DEBUG curtin:86 /dev/vda is multipath device partition? False
2023-09-28 13:24:14,058 DEBUG curtin:61 /dev/vda is multipath device? False
2023-09-28 13:24:14,058 DEBUG curtin:86 /dev/vda is multipath device partition? False
2023-09-28 13:24:14,058 DEBUG curtin:61 /dev/vda is multipath device? False
2023-09-28 13:24:14,066 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2023-09-28 13:24:14,066 DEBUG curtin:86 /dev/sr0 is multipath device partition? False
2023-09-28 13:24:14,066 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2023-09-28 13:24:14,066 DEBUG curtin:1328 Sorting extracted configurations
2023-09-28 13:24:14,066 INFO curtin:1347 Validating extracted storage config components
2023-09-28 13:24:14,077 DEBUG curtin:1364 Extracted (unmerged) storage config:
storage:
-   id: disk-vda
    path: /dev/vda
    type: disk

2023-09-28 13:24:14,077 DEBUG curtin:1368 Generating storage config dependencies
2023-09-28 13:24:14,077 DEBUG curtin:1374 Merging storage config dependencies
2023-09-28 13:24:14,078 DEBUG curtin:1379 Merged storage config:
storage:
    config:
    -   id: disk-vda
        path: /dev/vda
        type: disk
    version: 2

2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1452 majmin_to_dev {'253:0': Disk(path='/dev/vda', preserve=True, id='disk-vda', type='disk')}
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:28
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:22
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:23
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:5
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:25
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 11:0
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 7:0
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:28
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:44
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 7:4
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 7:3
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 7:7
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 7:5
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 7:6
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 7:8
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 7:9
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 7:11
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 7:10
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 7:12
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:28
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:6
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:35
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:36
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:37
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:7
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:12
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:40
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:21
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:38
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:24
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:33
2023-09-28 13:24:14,078 DEBUG subiquity.models.filesystem:1464 considering mount of 0:20
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 0:39
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 0:34
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 0:41
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 0:42
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 0:43
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 0:45
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 0:48
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 0:25
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 0:89
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 7:4
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 7:3
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 7:7
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 7:5
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 7:6
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 7:8
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 7:9
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 7:11
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 7:10
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 7:12
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 0:50
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 0:4
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 0:4
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 0:4
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 0:4
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 0:62
2023-09-28 13:24:14,079 DEBUG subiquity.models.filesystem:1464 considering mount of 0:90
2023-09-28 13:24:14,079 DEBUG subiquity.server.controllers.filesystem:994 suggested install minimum size: 8.303G
2023-09-28 13:24:14,079 DEBUG root:30 finish: subiquity/Filesystem/v2_orig_config_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-vda", "label"...
2023-09-28 13:24:14,080 INFO aiohttp.access:206  [28/Sep/2023:13:24:14 +0000] "GET /storage/v2/orig_config HTTP/1.1" 200 697 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:14,654 DEBUG root:30 start: subiquity/TimeZone/GET: 
2023-09-28 13:24:14,769 DEBUG root:30 finish: subiquity/TimeZone/GET: SUCCESS: 200 {"timezone": "Etc/UTC", "from_geoip": false}
2023-09-28 13:24:14,770 INFO aiohttp.access:206  [28/Sep/2023:13:24:14 +0000] "GET /timezone HTTP/1.1" 200 231 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:14,849 INFO root:30 start: subiquity/Meta/mark_configured_POST: 
2023-09-28 13:24:14,849 DEBUG subiquitycore.models.network:467 has_network True
2023-09-28 13:24:14,850 DEBUG subiquity.models.subiquity:252 model network for install stage is configured, to go set()
2023-09-28 13:24:14,850 DEBUG subiquity.models.subiquity:252 model network for postinstall stage is configured, to go {'identity', 'timezone'}
2023-09-28 13:24:14,850 INFO root:30 finish: subiquity/Meta/mark_configured_POST: SUCCESS: 200 null
2023-09-28 13:24:14,850 INFO aiohttp.access:206  [28/Sep/2023:13:24:14 +0000] "POST /meta/mark_configured?endpoint_names=%5B%22network%22%5D HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:14,851 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "NEEDS_CONFIRMATION", "confirming_tty": "", "error": null, "cloud_i...
2023-09-28 13:24:14,851 INFO aiohttp.access:206  [28/Sep/2023:13:23:38 +0000] "GET /meta/status?cur=%22WAITING%22 HTTP/1.1" 200 423 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:14,852 INFO root:30 start: subiquity/Meta/confirm_POST: 
2023-09-28 13:24:14,852 DEBUG subiquity.models.subiquity:252 model ssh for postinstall stage is configured, to go {'identity', 'timezone'}
2023-09-28 13:24:14,852 DEBUG subiquity.models.subiquity:252 model snaplist for postinstall stage is configured, to go {'identity', 'timezone'}
2023-09-28 13:24:14,852 INFO root:30 finish: subiquity/Meta/confirm_POST: SUCCESS: 200 null
2023-09-28 13:24:14,852 INFO aiohttp.access:206  [28/Sep/2023:13:24:14 +0000] "POST /meta/confirm?tty=%22%2Fdev%2Ftty1%22 HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:14,852 DEBUG root:30 finish: subiquity/OEM/load_metapackages_list/wait_confirmation: SUCCESS: 
2023-09-28 13:24:14,852 DEBUG root:30 start: subiquity/OEM/load_metapackages_list/wait_apt: 
2023-09-28 13:24:14,852 INFO root:30 start: subiquity/Install/install/configure_apt: configuring apt
2023-09-28 13:24:14,853 DEBUG root:30 start: subiquity/Mirror/waiting: 
2023-09-28 13:24:14,853 INFO root:30 start: subiquity/Meta/status_GET: 
2023-09-28 13:24:14,853 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini...
2023-09-28 13:24:14,854 INFO aiohttp.access:206  [28/Sep/2023:13:24:14 +0000] "GET /meta/status?cur=%22NEEDS_CONFIRMATION%22 HTTP/1.1" 200 421 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:14,854 INFO root:30 start: subiquity/Meta/status_GET: 
2023-09-28 13:24:17,336 DEBUG root:30 start: subiquity/TimeZone/POST: 
2023-09-28 13:24:17,376 DEBUG subiquity.models.subiquity:252 model timezone for postinstall stage is configured, to go {'identity'}
2023-09-28 13:24:17,376 DEBUG root:30 finish: subiquity/TimeZone/POST: SUCCESS: 200 null
2023-09-28 13:24:17,377 INFO aiohttp.access:206  [28/Sep/2023:13:24:17 +0000] "POST /timezone?tz=%22Europe%2FLondon%22 HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:17,377 DEBUG root:30 start: subiquity/Identity/GET: 
2023-09-28 13:24:17,377 DEBUG root:30 finish: subiquity/Identity/GET: SUCCESS: 200 {"realname": "", "username": "", "crypted_password": "", "hostname": ""}
2023-09-28 13:24:17,377 INFO aiohttp.access:206  [28/Sep/2023:13:24:17 +0000] "GET /identity HTTP/1.1" 200 259 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:17,381 DEBUG root:30 start: subiquity/Ad/has_support_GET: 
2023-09-28 13:24:17,381 DEBUG root:30 finish: subiquity/Ad/has_support_GET: SUCCESS: 200 true
2023-09-28 13:24:17,382 INFO aiohttp.access:206  [28/Sep/2023:13:24:17 +0000] "GET /active_directory/has_support HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:19,091 DEBUG root:30 start: subiquity/Identity/validate_username_GET: 
2023-09-28 13:24:19,091 DEBUG root:30 finish: subiquity/Identity/validate_username_GET: SUCCESS: 200 "OK"
2023-09-28 13:24:19,092 INFO aiohttp.access:206  [28/Sep/2023:13:24:19 +0000] "GET /identity/validate_username?username=%22u%22 HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:19,233 DEBUG root:30 start: subiquity/Identity/validate_username_GET: 
2023-09-28 13:24:19,233 DEBUG root:30 finish: subiquity/Identity/validate_username_GET: SUCCESS: 200 "OK"
2023-09-28 13:24:19,233 INFO aiohttp.access:206  [28/Sep/2023:13:24:19 +0000] "GET /identity/validate_username?username=%22ub%22 HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:19,324 DEBUG root:30 start: subiquity/Identity/validate_username_GET: 
2023-09-28 13:24:19,324 DEBUG root:30 finish: subiquity/Identity/validate_username_GET: SUCCESS: 200 "OK"
2023-09-28 13:24:19,325 INFO aiohttp.access:206  [28/Sep/2023:13:24:19 +0000] "GET /identity/validate_username?username=%22ubu%22 HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:19,469 DEBUG root:30 start: subiquity/Identity/validate_username_GET: 
2023-09-28 13:24:19,470 DEBUG root:30 finish: subiquity/Identity/validate_username_GET: SUCCESS: 200 "OK"
2023-09-28 13:24:19,470 INFO aiohttp.access:206  [28/Sep/2023:13:24:19 +0000] "GET /identity/validate_username?username=%22ubun%22 HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:19,606 DEBUG root:30 start: subiquity/Identity/validate_username_GET: 
2023-09-28 13:24:19,606 DEBUG root:30 finish: subiquity/Identity/validate_username_GET: SUCCESS: 200 "OK"
2023-09-28 13:24:19,607 INFO aiohttp.access:206  [28/Sep/2023:13:24:19 +0000] "GET /identity/validate_username?username=%22ubunt%22 HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:19,700 DEBUG root:30 start: subiquity/Identity/validate_username_GET: 
2023-09-28 13:24:19,700 DEBUG root:30 finish: subiquity/Identity/validate_username_GET: SUCCESS: 200 "OK"
2023-09-28 13:24:19,700 INFO aiohttp.access:206  [28/Sep/2023:13:24:19 +0000] "GET /identity/validate_username?username=%22ubuntu%22 HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:24,190 INFO root:30 start: subiquity/Meta/mark_configured_POST: 
2023-09-28 13:24:24,190 DEBUG subiquity.models.subiquity:252 model active_directory for postinstall stage is configured, to go {'identity'}
2023-09-28 13:24:24,190 INFO root:30 finish: subiquity/Meta/mark_configured_POST: SUCCESS: 200 null
2023-09-28 13:24:24,190 INFO aiohttp.access:206  [28/Sep/2023:13:24:24 +0000] "POST /meta/mark_configured?endpoint_names=%5B%22active_directory%22%5D HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:24,233 DEBUG root:30 start: subiquity/Identity/POST: 
2023-09-28 13:24:24,233 DEBUG subiquity.models.subiquity:252 model identity for postinstall stage is configured, to go set()
2023-09-28 13:24:24,234 DEBUG root:30 finish: subiquity/Identity/POST: SUCCESS: 200 null
2023-09-28 13:24:24,234 INFO aiohttp.access:206  [28/Sep/2023:13:24:24 +0000] "POST /identity HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:24,854 ERROR root:30 finish: subiquity/Mirror/waiting: FAIL: 
2023-09-28 13:24:24,854 DEBUG subiquity.server.controllers.mirror:202 Iterating over country-mirror
2023-09-28 13:24:24,854 DEBUG subiquity.server.controllers.mirror:208 Skipping unresolved country mirror
2023-09-28 13:24:24,854 DEBUG subiquity.server.controllers.mirror:202 Iterating over {'uri': 'http://archive.ubuntu.com/ubuntu/', 'arches': ['amd64', 'i386']}
2023-09-28 13:24:24,854 DEBUG subiquity.server.controllers.mirror:205 Will check next candiate mirror after 10 seconds.
2023-09-28 13:24:24,963 INFO root:30 start: subiquity/Meta/status_GET: 
2023-09-28 13:24:24,963 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini...
2023-09-28 13:24:24,963 INFO aiohttp.access:206  [28/Sep/2023:13:24:24 +0000] "GET /meta/status HTTP/1.1" 200 421 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:25,358 INFO root:30 start: subiquity/Meta/status_GET: 
2023-09-28 13:24:25,358 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini...
2023-09-28 13:24:25,359 INFO aiohttp.access:206  [28/Sep/2023:13:24:25 +0000] "GET /meta/status HTTP/1.1" 200 421 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:24:25,364 INFO root:30 start: subiquity/Meta/status_GET: 
2023-09-28 13:24:34,856 DEBUG curtin:95 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/minimal.squashfs', '/tmp/tmp6m9sru5x/minimal.squashfs.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:24:34,865 DEBUG curtin:95 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/minimal.en.squashfs', '/tmp/tmp6m9sru5x/minimal.en.squashfs.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:24:34,874 DEBUG curtin:95 Running command ['mount', '-o', 'lowerdir=/tmp/tmp6m9sru5x/minimal.en.squashfs.dir:/tmp/tmp6m9sru5x/minimal.squashfs.dir', '-t', 'overlay', 'overlay', '/tmp/tmp6m9sru5x/root.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:24:34,879 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', 'mount', '-o', 'lowerdir=/tmp/tmp6m9sru5x/root.dir,upperdir=/tmp/tmpazb2nfo8/upper,workdir=/tmp/tmpazb2nfo8/work', '-t', 'overlay', 'overlay', '/tmp/tmpazb2nfo8/mount']
2023-09-28 13:24:34,925 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', '/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1954.1"}}', '-c', '/var/log/installer/subiquity-curtin-apt.conf', 'apt-config', '-t', '/tmp/tmpazb2nfo8/mount']
2023-09-28 13:24:36,506 DEBUG root:30 start: subiquity/Mirror/cmd-apt-config: curtin command apt-config
2023-09-28 13:24:36,748 DEBUG subiquity.server.curtin:130 waited 0.1 seconds for events to drain
2023-09-28 13:24:36,801 DEBUG root:30 finish: subiquity/Mirror/cmd-apt-config: SUCCESS: curtin command apt-config
2023-09-28 13:24:36,849 DEBUG subiquity.server.curtin:130 waited 0.2 seconds for events to drain
2023-09-28 13:24:36,850 DEBUG subiquitycore.utils:151 astart_command called: ['apt-get', 'update', '-oAPT::Update::Error-Mode=any', '-oAPT::Sandbox::User=root', '-oAcquire::IndexTargets::deb::Packages::DefaultEnabled=false', '-oAcquire::IndexTargets::deb::Translations::DefaultEnabled=false', '-oAcquire::IndexTargets::deb::DEP-11::DefaultEnabled=false', '-oAcquire::IndexTargets::deb::DEP-11-icons-small::DefaultEnabled=false', '-oAcquire::IndexTargets::deb::DEP-11-icons::DefaultEnabled=false', '-oAcquire::IndexTargets::deb::DEP-11-icons-hidpi::DefaultEnabled=false', '-oAcquire::IndexTargets::deb::DEP-11-icons-large::DefaultEnabled=false', '-oAcquire::IndexTargets::deb::DEP-11-icons-large-hidpi::DefaultEnabled=false', '-oAcquire::IndexTargets::deb::CNF::DefaultEnabled=false', '-oAcquire::IndexTargets::deb-src::Sources::DefaultEnabled=false']
2023-09-28 13:24:40,766 DEBUG subiquity.server.controllers.mirror:176 Mirror checking successful
2023-09-28 13:24:40,767 DEBUG subiquity.server.controllers.mirror:178 APT output follows
2023-09-28 13:24:40,767 DEBUG subiquity.server.controllers.mirror:180 Get:1 http://archive.ubuntu.com/ubuntu mantic InRelease [255 kB]
2023-09-28 13:24:40,767 DEBUG subiquity.server.controllers.mirror:180 Hit:2 http://archive.ubuntu.com/ubuntu mantic-updates InRelease
2023-09-28 13:24:40,767 DEBUG subiquity.server.controllers.mirror:180 Get:3 http://archive.ubuntu.com/ubuntu mantic-backports InRelease [90.7 kB]
2023-09-28 13:24:40,767 DEBUG subiquity.server.controllers.mirror:180 Fetched 346 kB in 1s (405 kB/s)
2023-09-28 13:24:40,767 DEBUG subiquity.server.controllers.mirror:180 Reading package lists...
2023-09-28 13:24:40,767 DEBUG curtin:95 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/minimal.squashfs', '/tmp/tmpwilo_7zi/minimal.squashfs.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:24:40,777 DEBUG curtin:95 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/minimal.en.squashfs', '/tmp/tmpwilo_7zi/minimal.en.squashfs.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:24:40,784 DEBUG curtin:95 Running command ['mount', '-o', 'lowerdir=/tmp/tmpwilo_7zi/minimal.en.squashfs.dir:/tmp/tmpwilo_7zi/minimal.squashfs.dir', '-t', 'overlay', 'overlay', '/tmp/tmpwilo_7zi/root.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:24:40,789 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', 'mount', '-o', 'lowerdir=/tmp/tmpwilo_7zi/root.dir,upperdir=/tmp/tmpzwj5l3j5/upper,workdir=/tmp/tmpzwj5l3j5/work', '-t', 'overlay', 'overlay', '/tmp/tmpzwj5l3j5/mount']
2023-09-28 13:24:40,822 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', '/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1954.2"}}', '-c', '/var/log/installer/subiquity-curtin-apt.conf', 'apt-config', '-t', '/tmp/tmpzwj5l3j5/mount']
2023-09-28 13:24:41,920 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', 'mount', '-o', 'lowerdir=/tmp/tmpzwj5l3j5/upper:/tmp/tmpwilo_7zi/root.dir,upperdir=/tmp/tmpf0cz3n9w/upper,workdir=/tmp/tmpf0cz3n9w/work', '-t', 'overlay', 'overlay', '/tmp/tmpf0cz3n9w/mount']
2023-09-28 13:24:41,952 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', 'mount', '-o', 'bind', '/cdrom', '/tmp/tmpf0cz3n9w/mount/cdrom']
2023-09-28 13:24:41,982 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', '/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1954.3"}}', 'in-target', '-t', '/tmp/tmpf0cz3n9w/mount', '--', 'apt-get', 'update']
2023-09-28 13:24:43,123 DEBUG root:30 start: subiquity/Install/install/configure_apt/cmd-in-target: curtin command in-target
2023-09-28 13:24:52,660 DEBUG subiquity.server.curtin:130 waited 0.1 seconds for events to drain
2023-09-28 13:24:52,761 DEBUG subiquity.server.curtin:130 waited 0.2 seconds for events to drain
2023-09-28 13:24:52,801 DEBUG root:30 finish: subiquity/Install/install/configure_apt/cmd-in-target: SUCCESS: curtin command in-target
2023-09-28 13:24:52,861 DEBUG subiquity.server.curtin:130 waited 0.30000000000000004 seconds for events to drain
2023-09-28 13:24:52,862 INFO root:30 finish: subiquity/Install/install/configure_apt: SUCCESS: configuring apt
2023-09-28 13:24:52,862 DEBUG root:30 start: subiquity/Install/install/live-packages: installing packages to live system
2023-09-28 13:24:52,862 DEBUG root:30 finish: subiquity/Drivers/_list_drivers/wait_apt: SUCCESS: 
2023-09-28 13:24:52,862 DEBUG root:30 finish: subiquity/Drivers/_list_drivers: SUCCESS: 
2023-09-28 13:24:52,862 DEBUG root:30 finish: subiquity/OEM/load_metapackages_list/wait_apt: SUCCESS: 
2023-09-28 13:24:52,862 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', 'mount', '-o', 'lowerdir=/tmp/tmpf0cz3n9w/upper:/tmp/tmpzwj5l3j5/upper:/tmp/tmpwilo_7zi/root.dir,upperdir=/tmp/tmpe6ry2rz4/upper,workdir=/tmp/tmpe6ry2rz4/work', '-t', 'overlay', 'overlay', '/tmp/tmpe6ry2rz4/mount']
2023-09-28 13:24:52,863 DEBUG subiquity.server.pkghelper:65 checking if zfsutils-linux is available
2023-09-28 13:24:56,726 DEBUG subiquity.server.pkghelper:71 zfsutils-linux already installed
2023-09-28 13:24:56,726 DEBUG root:30 finish: subiquity/Install/install/live-packages: SUCCESS: installing packages to live system
2023-09-28 13:24:56,727 INFO root:30 start: subiquity/Install/install/curtin_install: installing system
2023-09-28 13:24:56,728 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step: executing curtin install initial step
2023-09-28 13:24:56,733 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', '/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1954.4"}}', '-c', '/var/log/installer/curtin-install/subiquity-initial.conf', 'install', '--set', 'json:stages=[]']
2023-09-28 13:24:56,735 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', 'chroot', '/tmp/tmpe6ry2rz4/mount', 'sh', '-c', 'command -v ubuntu-drivers']
2023-09-28 13:24:56,777 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--property', 'PrivateMounts=yes', '--pipe', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', '/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1954.5"}}', 'in-target', '-t', '/tmp/tmpe6ry2rz4/mount', '--', 'ubuntu-drivers', 'list-oem']
2023-09-28 13:24:58,175 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step: SUCCESS: executing curtin install initial step
2023-09-28 13:24:58,175 DEBUG subiquity.models.filesystem:1827 mountpoints {'': 'mount-0', None: 'zfs-11', '/boot': 'zfs-1', '/': 'zfs-3', 'ROOT/ubuntu_srikxd/var/lib': 'zfs-5', 'ROOT/ubuntu_srikxd/var/lib/AccountsService': 'zfs-6', 'ROOT/ubuntu_srikxd/var/lib/apt': 'zfs-7', 'ROOT/ubuntu_srikxd/var/lib/dpkg': 'zfs-8', 'ROOT/ubuntu_srikxd/var/lib/NetworkManager': 'zfs-9', 'ROOT/ubuntu_srikxd/srv': 'zfs-10', 'ROOT/ubuntu_srikxd/usr/local': 'zfs-12', 'ROOT/ubuntu_srikxd/var/games': 'zfs-13', 'ROOT/ubuntu_srikxd/var/log': 'zfs-14', 'ROOT/ubuntu_srikxd/var/mail': 'zfs-15', 'ROOT/ubuntu_srikxd/var/snap': 'zfs-16', 'ROOT/ubuntu_srikxd/var/spool': 'zfs-17', 'ROOT/ubuntu_srikxd/var/www': 'zfs-18'}
2023-09-28 13:24:58,175 DEBUG subiquity.models.filesystem:1817 cannot emit action to mount /boot until that for / is emitted
2023-09-28 13:24:58,176 DEBUG curtin:145 ZFS cannot use swapfiles
2023-09-28 13:24:58,176 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step: executing curtin install partitioning step
2023-09-28 13:24:58,190 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', '/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1954.6"}}', '-c', '/var/log/installer/curtin-install/subiquity-partitioning.conf', 'install', '--set', 'json:stages=["partitioning"]', 'cp:///tmp/tmpf0cz3n9w/mount']
2023-09-28 13:24:58,553 DEBUG root:30 start: subiquity/OEM/load_metapackages_list/cmd-in-target: curtin command in-target
2023-09-28 13:24:59,801 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install: curtin command install
2023-09-28 13:24:59,802 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning: configuring storage
2023-09-28 13:24:59,803 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin: running 'curtin block-meta simple'
2023-09-28 13:25:01,246 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: curtin command block-meta
2023-09-28 13:25:01,503 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta/clear-holders: removing previous storage devices
2023-09-28 13:25:02,013 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta/clear-holders: SUCCESS: removing previous storage devices
2023-09-28 13:25:02,017 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta/: configuring disk: disk-vda
2023-09-28 13:25:02,237 DEBUG subiquity.server.curtin:130 waited 0.1 seconds for events to drain
2023-09-28 13:25:02,265 DEBUG root:30 finish: subiquity/OEM/load_metapackages_list/cmd-in-target: SUCCESS: curtin command in-target
2023-09-28 13:25:02,338 DEBUG subiquity.server.curtin:130 waited 0.2 seconds for events to drain
2023-09-28 13:25:02,342 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', 'umount', '/tmp/tmpe6ry2rz4/mount']
2023-09-28 13:25:02,421 DEBUG subiquity.server.controllers.oem:182 OEM meta-packages to install: []
2023-09-28 13:25:02,421 DEBUG root:30 finish: subiquity/OEM/load_metapackages_list: SUCCESS: 
2023-09-28 13:25:03,998 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta/: SUCCESS: configuring disk: disk-vda
2023-09-28 13:25:03,998 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-0
2023-09-28 13:25:04,303 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring partition: partition-0
2023-09-28 13:25:04,303 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-1
2023-09-28 13:25:04,562 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring partition: partition-1
2023-09-28 13:25:04,562 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-2
2023-09-28 13:25:04,842 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring partition: partition-2
2023-09-28 13:25:04,842 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring format: format-0
2023-09-28 13:25:05,098 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring format: format-0
2023-09-28 13:25:05,099 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring mount: mount-0
2023-09-28 13:25:05,693 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring mount: mount-0
2023-09-28 13:25:05,694 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-3
2023-09-28 13:25:05,949 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring partition: partition-3
2023-09-28 13:25:05,950 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zpool: zpool-0
2023-09-28 13:25:06,287 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zpool: zpool-0
2023-09-28 13:25:06,288 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-0
2023-09-28 13:25:06,288 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-0
2023-09-28 13:25:06,288 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zpool: zpool-1
2023-09-28 13:25:06,819 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zpool: zpool-1
2023-09-28 13:25:06,820 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-2
2023-09-28 13:25:06,820 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-2
2023-09-28 13:25:06,820 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-3
2023-09-28 13:25:06,820 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-3
2023-09-28 13:25:06,820 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-4
2023-09-28 13:25:06,820 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-4
2023-09-28 13:25:06,821 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-5
2023-09-28 13:25:06,821 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-5
2023-09-28 13:25:06,821 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-6
2023-09-28 13:25:06,821 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-6
2023-09-28 13:25:06,821 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-7
2023-09-28 13:25:07,085 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-7
2023-09-28 13:25:07,086 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-8
2023-09-28 13:25:07,086 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-8
2023-09-28 13:25:07,086 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-9
2023-09-28 13:25:07,086 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-9
2023-09-28 13:25:07,086 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-10
2023-09-28 13:25:07,086 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-10
2023-09-28 13:25:07,086 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-11
2023-09-28 13:25:07,086 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-11
2023-09-28 13:25:07,087 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-12
2023-09-28 13:25:07,087 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-12
2023-09-28 13:25:07,087 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-13
2023-09-28 13:25:07,087 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-13
2023-09-28 13:25:07,087 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-14
2023-09-28 13:25:07,087 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-14
2023-09-28 13:25:07,087 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-15
2023-09-28 13:25:07,374 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-15
2023-09-28 13:25:07,374 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-16
2023-09-28 13:25:07,374 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-16
2023-09-28 13:25:07,375 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-17
2023-09-28 13:25:07,375 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-17
2023-09-28 13:25:07,375 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-18
2023-09-28 13:25:07,375 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-18
2023-09-28 13:25:07,375 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring zfs: zfs-1
2023-09-28 13:25:07,375 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring zfs: zfs-1
2023-09-28 13:25:07,508 DEBUG subiquity.server.curtin:130 waited 0.1 seconds for events to drain
2023-09-28 13:25:07,609 DEBUG subiquity.server.curtin:130 waited 0.2 seconds for events to drain
2023-09-28 13:25:07,709 DEBUG subiquity.server.curtin:130 waited 0.30000000000000004 seconds for events to drain
2023-09-28 13:25:07,801 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin: SUCCESS: running 'curtin block-meta simple'
2023-09-28 13:25:07,801 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning: SUCCESS: configuring storage
2023-09-28 13:25:07,801 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install: SUCCESS: curtin command install
2023-09-28 13:25:07,811 DEBUG subiquity.server.curtin:130 waited 0.4 seconds for events to drain
2023-09-28 13:25:07,812 DEBUG subiquity.server.controllers.filesystem:502 recording path '/dev/vda' for device disk-vda
2023-09-28 13:25:07,812 DEBUG subiquity.server.controllers.filesystem:502 recording path '/dev/vda1' for device partition-0
2023-09-28 13:25:07,812 DEBUG subiquity.server.controllers.filesystem:502 recording path '/dev/vda2' for device partition-1
2023-09-28 13:25:07,812 DEBUG subiquity.server.controllers.filesystem:502 recording path '/dev/vda3' for device partition-2
2023-09-28 13:25:07,812 DEBUG subiquity.server.controllers.filesystem:502 recording path '/dev/vda4' for device partition-3
2023-09-28 13:25:07,812 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step: SUCCESS: executing curtin install partitioning step
2023-09-28 13:25:07,813 DEBUG subiquity.models.subiquity:526 merging config from <subiquity.models.network.NetworkModel object at 0x7ffaa9627fd0>
2023-09-28 13:25:07,814 DEBUG subiquity.cloudinit:14 Loaded cloud config from /run/cloud-init/combined-cloud-config.json
2023-09-28 13:25:07,814 DEBUG subiquity.models.subiquity:526 merging config from <subiquity.models.filesystem.FilesystemModel object at 0x7ffaa9702aa0>
2023-09-28 13:25:07,815 DEBUG subiquity.models.filesystem:1827 mountpoints {'': 'mount-0', None: 'zfs-11', '/boot': 'zfs-1', '/': 'zfs-3', 'ROOT/ubuntu_srikxd/var/lib': 'zfs-5', 'ROOT/ubuntu_srikxd/var/lib/AccountsService': 'zfs-6', 'ROOT/ubuntu_srikxd/var/lib/apt': 'zfs-7', 'ROOT/ubuntu_srikxd/var/lib/dpkg': 'zfs-8', 'ROOT/ubuntu_srikxd/var/lib/NetworkManager': 'zfs-9', 'ROOT/ubuntu_srikxd/srv': 'zfs-10', 'ROOT/ubuntu_srikxd/usr/local': 'zfs-12', 'ROOT/ubuntu_srikxd/var/games': 'zfs-13', 'ROOT/ubuntu_srikxd/var/log': 'zfs-14', 'ROOT/ubuntu_srikxd/var/mail': 'zfs-15', 'ROOT/ubuntu_srikxd/var/snap': 'zfs-16', 'ROOT/ubuntu_srikxd/var/spool': 'zfs-17', 'ROOT/ubuntu_srikxd/var/www': 'zfs-18'}
2023-09-28 13:25:07,815 DEBUG subiquity.models.filesystem:1817 cannot emit action to mount /boot until that for / is emitted
2023-09-28 13:25:07,816 DEBUG curtin:145 ZFS cannot use swapfiles
2023-09-28 13:25:07,816 DEBUG subiquity.models.subiquity:526 merging config from <subiquity.models.keyboard.KeyboardModel object at 0x7ffaa97021d0>
2023-09-28 13:25:07,816 DEBUG subiquity.models.subiquity:526 merging config from <subiquity.models.kernel.KernelModel object at 0x7ffaa9703af0>
2023-09-28 13:25:07,816 DEBUG subiquity.models.subiquity:526 merging config from <subiquity.models.proxy.ProxyModel object at 0x7ffaa9960a30>
2023-09-28 13:25:07,816 DEBUG subiquity.models.subiquity:526 merging config from <subiquity.models.source.SourceModel object at 0x7ffaa9963610>
2023-09-28 13:25:07,817 DEBUG subiquity.models.subiquity:526 merging config from <subiquity.models.subiquity.DebconfSelectionsModel object at 0x7ffaa97029e0>
2023-09-28 13:25:07,817 DEBUG subiquity.models.subiquity:526 merging config from <subiquity.models.mirror.MirrorModel object at 0x7ffaa9627ee0>
2023-09-28 13:25:07,817 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step: executing curtin install extract step
2023-09-28 13:25:07,828 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', '/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1954.7"}}', '-c', '/var/log/installer/curtin-install/subiquity-extract.conf', 'install', '--set', 'json:stages=["extract"]', 'cp:///tmp/tmpf0cz3n9w/mount']
2023-09-28 13:25:09,051 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install: curtin command install
2023-09-28 13:25:09,051 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-extract: writing install sources to disk
2023-09-28 13:25:09,051 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-extract/builtin: running 'curtin extract'
2023-09-28 13:25:09,800 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-extract/builtin/cmd-extract: curtin command extract
2023-09-28 13:25:09,801 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-extract/builtin/cmd-extract/: acquiring and extracting image from cp:///tmp/tmpf0cz3n9w/mount
2023-09-28 13:27:20,801 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-extract/builtin/cmd-extract/: SUCCESS: acquiring and extracting image from cp:///tmp/tmpf0cz3n9w/mount
2023-09-28 13:27:20,802 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-extract/builtin: SUCCESS: running 'curtin extract'
2023-09-28 13:27:20,802 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-extract: SUCCESS: writing install sources to disk
2023-09-28 13:27:20,802 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install: SUCCESS: curtin command install
2023-09-28 13:27:20,810 DEBUG subiquity.server.curtin:130 waited 0.1 seconds for events to drain
2023-09-28 13:27:20,811 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step: SUCCESS: executing curtin install extract step
2023-09-28 13:27:20,811 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', 'mount', '-o', 'bind', '/cdrom', '/target/cdrom']
2023-09-28 13:27:20,922 DEBUG root:30 start: subiquity/Install/install/curtin_install/setup_target: configuring keyboard
2023-09-28 13:27:20,922 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', '/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1954.8"}}', 'in-target', '-t', '/target', '--', 'setupcon', '--save-only']
2023-09-28 13:27:22,530 DEBUG root:30 start: subiquity/Install/install/curtin_install/setup_target/cmd-in-target: curtin command in-target
2023-09-28 13:27:22,733 DEBUG subiquity.server.curtin:130 waited 0.1 seconds for events to drain
2023-09-28 13:27:22,801 DEBUG root:30 finish: subiquity/Install/install/curtin_install/setup_target/cmd-in-target: SUCCESS: curtin command in-target
2023-09-28 13:27:22,835 DEBUG subiquity.server.curtin:130 waited 0.2 seconds for events to drain
2023-09-28 13:27:22,835 DEBUG root:30 finish: subiquity/Install/install/curtin_install/setup_target: SUCCESS: configuring keyboard
2023-09-28 13:27:22,835 DEBUG subiquitycore.utils:118 arun_command called: ['grep-status', '--whole-pkg', '-FProvides', 'linux-image', '--and', '-FStatus', 'installed', '--show-field=Package', '--no-field-names', '/target/var/lib/dpkg/status']
2023-09-28 13:27:22,845 DEBUG subiquitycore.utils:132 arun_command ['grep-status', '--whole-pkg', '-FProvides', 'linux-image', '--and', '-FStatus', 'installed', '--show-field=Package', '--no-field-names', '/target/var/lib/dpkg/status'] exited with code 1
2023-09-28 13:27:22,846 DEBUG subiquity.models.subiquity:526 merging config from <subiquity.models.network.NetworkModel object at 0x7ffaa9627fd0>
2023-09-28 13:27:22,846 DEBUG subiquity.cloudinit:14 Loaded cloud config from /run/cloud-init/combined-cloud-config.json
2023-09-28 13:27:22,847 DEBUG subiquity.models.subiquity:526 merging config from <subiquity.models.filesystem.FilesystemModel object at 0x7ffaa9702aa0>
2023-09-28 13:27:22,847 DEBUG subiquity.models.filesystem:1827 mountpoints {'': 'mount-0', None: 'zfs-11', '/boot': 'zfs-1', '/': 'zfs-3', 'ROOT/ubuntu_srikxd/var/lib': 'zfs-5', 'ROOT/ubuntu_srikxd/var/lib/AccountsService': 'zfs-6', 'ROOT/ubuntu_srikxd/var/lib/apt': 'zfs-7', 'ROOT/ubuntu_srikxd/var/lib/dpkg': 'zfs-8', 'ROOT/ubuntu_srikxd/var/lib/NetworkManager': 'zfs-9', 'ROOT/ubuntu_srikxd/srv': 'zfs-10', 'ROOT/ubuntu_srikxd/usr/local': 'zfs-12', 'ROOT/ubuntu_srikxd/var/games': 'zfs-13', 'ROOT/ubuntu_srikxd/var/log': 'zfs-14', 'ROOT/ubuntu_srikxd/var/mail': 'zfs-15', 'ROOT/ubuntu_srikxd/var/snap': 'zfs-16', 'ROOT/ubuntu_srikxd/var/spool': 'zfs-17', 'ROOT/ubuntu_srikxd/var/www': 'zfs-18'}
2023-09-28 13:27:22,847 DEBUG subiquity.models.filesystem:1817 cannot emit action to mount /boot until that for / is emitted
2023-09-28 13:27:22,847 DEBUG curtin:145 ZFS cannot use swapfiles
2023-09-28 13:27:22,847 DEBUG subiquity.models.subiquity:526 merging config from <subiquity.models.keyboard.KeyboardModel object at 0x7ffaa97021d0>
2023-09-28 13:27:22,847 DEBUG subiquity.models.subiquity:526 merging config from <subiquity.models.kernel.KernelModel object at 0x7ffaa9703af0>
2023-09-28 13:27:22,847 DEBUG subiquity.models.subiquity:526 merging config from <subiquity.models.proxy.ProxyModel object at 0x7ffaa9960a30>
2023-09-28 13:27:22,847 DEBUG subiquity.models.subiquity:526 merging config from <subiquity.models.source.SourceModel object at 0x7ffaa9963610>
2023-09-28 13:27:22,847 DEBUG subiquity.models.subiquity:526 merging config from <subiquity.models.subiquity.DebconfSelectionsModel object at 0x7ffaa97029e0>
2023-09-28 13:27:22,848 DEBUG subiquity.models.subiquity:526 merging config from <subiquity.models.mirror.MirrorModel object at 0x7ffaa9627ee0>
2023-09-28 13:27:22,848 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step: executing curtin install curthooks step
2023-09-28 13:27:22,859 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', '/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1954.9"}}', '-c', '/var/log/installer/curtin-install/subiquity-curthooks.conf', 'install', '--set', 'json:stages=["curthooks"]']
2023-09-28 13:27:23,801 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install: curtin command install
2023-09-28 13:27:23,801 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks: configuring installed system
2023-09-28 13:27:23,801 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin: running 'curtin curthooks'
2023-09-28 13:27:24,478 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks: curtin command curthooks
2023-09-28 13:27:24,479 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-apt-config: configuring apt configuring apt
2023-09-28 13:27:24,737 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-apt-config: SUCCESS: configuring apt configuring apt
2023-09-28 13:27:24,737 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-missing-packages: installing missing packages
2023-09-28 13:27:24,737 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/: Installing packages on target system: ['grub-pc', 'zfs-initramfs', 'zfsutils-linux']
2023-09-28 13:27:36,810 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/: SUCCESS: Installing packages on target system: ['grub-pc', 'zfs-initramfs', 'zfsutils-linux']
2023-09-28 13:27:36,810 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-missing-packages: SUCCESS: installing missing packages
2023-09-28 13:27:36,810 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-iscsi-service: configuring iscsi service
2023-09-28 13:27:36,810 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-iscsi-service: SUCCESS: configuring iscsi service
2023-09-28 13:27:36,810 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-mdadm-service: configuring raid (mdadm) service
2023-09-28 13:27:36,810 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-mdadm-service: SUCCESS: configuring raid (mdadm) service
2023-09-28 13:27:36,811 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-kernel: installing kernel
2023-09-28 13:28:02,302 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-kernel: SUCCESS: installing kernel
2023-09-28 13:28:02,303 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/setting-up-swap: setting up swap
2023-09-28 13:28:02,303 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/setting-up-swap: SUCCESS: setting up swap
2023-09-28 13:28:02,304 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/apply-networking-config: apply networking config
2023-09-28 13:28:02,304 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/apply-networking-config: SUCCESS: apply networking config
2023-09-28 13:28:02,304 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-etc-fstab: writing etc/fstab
2023-09-28 13:28:02,304 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-etc-fstab: SUCCESS: writing etc/fstab
2023-09-28 13:28:02,304 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-multipath: configuring multipath
2023-09-28 13:28:03,194 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-multipath: SUCCESS: configuring multipath
2023-09-28 13:28:03,195 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/system-upgrade: updating packages on target system
2023-09-28 13:28:03,195 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/system-upgrade: SUCCESS: updating packages on target system
2023-09-28 13:28:03,195 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/pollinate-user-agent: configuring pollinate user-agent on target
2023-09-28 13:28:03,195 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/pollinate-user-agent: SUCCESS: configuring pollinate user-agent on target
2023-09-28 13:28:03,195 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/updating-initramfs-configuration: updating initramfs configuration
2023-09-28 13:28:10,803 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/updating-initramfs-configuration: SUCCESS: updating initramfs configuration
2023-09-28 13:28:10,803 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-bootloader: configuring target system bootloader
2023-09-28 13:28:10,803 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/install-grub: installing grub to target devices
2023-09-28 13:28:14,606 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/install-grub: SUCCESS: installing grub to target devices
2023-09-28 13:28:14,606 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-bootloader: SUCCESS: configuring target system bootloader
2023-09-28 13:28:14,606 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks/builtin: SUCCESS: running 'curtin curthooks'
2023-09-28 13:28:14,607 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-curthooks: SUCCESS: configuring installed system
2023-09-28 13:28:14,607 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install: SUCCESS: curtin command install
2023-09-28 13:28:14,655 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step: SUCCESS: executing curtin install curthooks step
2023-09-28 13:28:14,655 INFO root:30 finish: subiquity/Install/install/curtin_install: SUCCESS: installing system
2023-09-28 13:28:14,656 INFO root:30 start: subiquity/Install/install/postinstall: final system configuration
2023-09-28 13:28:14,656 DEBUG subiquity.models.filesystem:1827 mountpoints {'': 'mount-0', None: 'zfs-11', '/boot': 'zfs-1', '/': 'zfs-3', 'ROOT/ubuntu_srikxd/var/lib': 'zfs-5', 'ROOT/ubuntu_srikxd/var/lib/AccountsService': 'zfs-6', 'ROOT/ubuntu_srikxd/var/lib/apt': 'zfs-7', 'ROOT/ubuntu_srikxd/var/lib/dpkg': 'zfs-8', 'ROOT/ubuntu_srikxd/var/lib/NetworkManager': 'zfs-9', 'ROOT/ubuntu_srikxd/srv': 'zfs-10', 'ROOT/ubuntu_srikxd/usr/local': 'zfs-12', 'ROOT/ubuntu_srikxd/var/games': 'zfs-13', 'ROOT/ubuntu_srikxd/var/log': 'zfs-14', 'ROOT/ubuntu_srikxd/var/mail': 'zfs-15', 'ROOT/ubuntu_srikxd/var/snap': 'zfs-16', 'ROOT/ubuntu_srikxd/var/spool': 'zfs-17', 'ROOT/ubuntu_srikxd/var/www': 'zfs-18'}
2023-09-28 13:28:14,656 DEBUG subiquity.models.filesystem:1817 cannot emit action to mount /boot until that for / is emitted
2023-09-28 13:28:14,657 DEBUG curtin:145 ZFS cannot use swapfiles
2023-09-28 13:28:14,675 DEBUG root:30 start: subiquity/Install/install/postinstall/configure_cloud_init: configuring cloud-init
2023-09-28 13:28:14,677 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini...
2023-09-28 13:28:14,687 INFO aiohttp.access:206  [28/Sep/2023:13:24:14 +0000] "GET /meta/status?cur=%22RUNNING%22 HTTP/1.1" 200 421 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:28:14,687 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini...
2023-09-28 13:28:14,687 INFO aiohttp.access:206  [28/Sep/2023:13:24:25 +0000] "GET /meta/status?cur=%22RUNNING%22 HTTP/1.1" 200 421 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:28:14,696 DEBUG subiquitycore.utils:76 run_command called: ['chroot', '/target', 'getent', 'group']
2023-09-28 13:28:14,704 DEBUG subiquitycore.utils:95 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2023-09-28 13:28:14,707 DEBUG cloudinit.util:1536 Reading from /snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2023-09-28 13:28:14,720 DEBUG cloudinit.util:1547 Read 135437 bytes from /snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2023-09-28 13:28:14,749 DEBUG subiquity.cloudinit:14 Loaded cloud config from /run/cloud-init/combined-cloud-config.json
2023-09-28 13:28:14,751 DEBUG root:30 finish: subiquity/Install/install/postinstall/configure_cloud_init: SUCCESS: configuring cloud-init
2023-09-28 13:28:14,752 DEBUG root:30 start: subiquity/Install/install/postinstall/get_target_packages: calculating extra packages to install
2023-09-28 13:28:14,752 DEBUG subiquitycore.utils:118 arun_command called: ['chroot', '/target', 'check-language-support', '-l', 'en_US']
2023-09-28 13:28:14,860 INFO root:30 start: subiquity/Meta/status_GET: 
2023-09-28 13:28:14,861 INFO root:30 start: subiquity/Meta/status_GET: 
2023-09-28 13:28:16,317 DEBUG subiquitycore.utils:132 arun_command ['chroot', '/target', 'check-language-support', '-l', 'en_US'] exited with code 0
2023-09-28 13:28:16,317 DEBUG root:30 finish: subiquity/Install/install/postinstall/get_target_packages: SUCCESS: calculating extra packages to install
2023-09-28 13:28:16,317 DEBUG root:30 start: subiquity/Install/install/postinstall/install_wbritish: installing wbritish
2023-09-28 13:28:16,317 DEBUG root:30 start: subiquity/Install/install/postinstall/install_wbritish/retrieving: retrieving wbritish
2023-09-28 13:28:16,318 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', '/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1954.10"}}', 'system-install', '-t', '/target', '--download-only', '--', 'wbritish']
2023-09-28 13:28:17,769 DEBUG root:30 start: subiquity/Install/install/postinstall/install_wbritish/cmd-system-install: curtin command system-install
2023-09-28 13:28:20,214 DEBUG subiquity.server.curtin:130 waited 0.1 seconds for events to drain
2023-09-28 13:28:20,300 DEBUG root:30 finish: subiquity/Install/install/postinstall/install_wbritish/cmd-system-install: SUCCESS: curtin command system-install
2023-09-28 13:28:20,315 DEBUG subiquity.server.curtin:130 waited 0.2 seconds for events to drain
2023-09-28 13:28:20,316 DEBUG root:30 finish: subiquity/Install/install/postinstall/install_wbritish/retrieving: SUCCESS: retrieving wbritish
2023-09-28 13:28:20,316 DEBUG root:30 start: subiquity/Install/install/postinstall/install_wbritish/unpacking: unpacking wbritish
2023-09-28 13:28:20,316 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', '/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1954.11"}}', 'system-install', '-t', '/target', '--assume-downloaded', '--', 'wbritish']
2023-09-28 13:28:21,551 DEBUG root:30 start: subiquity/Install/install/postinstall/install_wbritish/cmd-system-install: curtin command system-install
2023-09-28 13:28:24,801 DEBUG root:30 finish: subiquity/Install/install/postinstall/install_wbritish/cmd-system-install: SUCCESS: curtin command system-install
2023-09-28 13:28:24,837 DEBUG subiquity.server.curtin:130 waited 0.1 seconds for events to drain
2023-09-28 13:28:24,837 DEBUG root:30 finish: subiquity/Install/install/postinstall/install_wbritish/unpacking: SUCCESS: unpacking wbritish
2023-09-28 13:28:24,837 DEBUG root:30 finish: subiquity/Install/install/postinstall/install_wbritish: SUCCESS: installing wbritish
2023-09-28 13:28:24,838 DEBUG root:30 start: subiquity/Install/install/postinstall/run_unattended_upgrades: downloading and installing security updates
2023-09-28 13:28:24,838 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "UU_RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_...
2023-09-28 13:28:24,839 INFO aiohttp.access:206  [28/Sep/2023:13:28:14 +0000] "GET /meta/status?cur=%22RUNNING%22 HTTP/1.1" 200 424 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:28:24,839 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "UU_RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_...
2023-09-28 13:28:24,839 INFO aiohttp.access:206  [28/Sep/2023:13:28:14 +0000] "GET /meta/status?cur=%22RUNNING%22 HTTP/1.1" 200 424 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:28:24,839 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', '/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1954.12"}}', 'in-target', '-t', '/target', '--', 'unattended-upgrades', '-v']
2023-09-28 13:28:25,067 INFO root:30 start: subiquity/Meta/status_GET: 
2023-09-28 13:28:25,068 INFO root:30 start: subiquity/Meta/status_GET: 
2023-09-28 13:28:26,301 DEBUG root:30 start: subiquity/Install/install/postinstall/run_unattended_upgrades/cmd-in-target: curtin command in-target
2023-09-28 13:28:28,020 DEBUG subiquity.server.curtin:130 waited 0.1 seconds for events to drain
2023-09-28 13:28:28,051 DEBUG root:30 finish: subiquity/Install/install/postinstall/run_unattended_upgrades/cmd-in-target: SUCCESS: curtin command in-target
2023-09-28 13:28:28,121 DEBUG subiquity.server.curtin:130 waited 0.2 seconds for events to drain
2023-09-28 13:28:28,122 DEBUG root:30 finish: subiquity/Install/install/postinstall/run_unattended_upgrades: SUCCESS: downloading and installing security updates
2023-09-28 13:28:28,122 DEBUG root:30 start: subiquity/Install/install/postinstall/restore_apt_config: restoring apt configuration
2023-09-28 13:28:28,123 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', '/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1954.13"}}', 'in-target', '-t', '/target', '--', 'apt-get', 'update']
2023-09-28 13:28:29,277 DEBUG root:30 start: subiquity/Install/install/postinstall/restore_apt_config/cmd-in-target: curtin command in-target
2023-09-28 13:28:32,837 DEBUG subiquity.server.curtin:130 waited 0.1 seconds for events to drain
2023-09-28 13:28:32,938 DEBUG subiquity.server.curtin:130 waited 0.2 seconds for events to drain
2023-09-28 13:28:33,038 DEBUG subiquity.server.curtin:130 waited 0.30000000000000004 seconds for events to drain
2023-09-28 13:28:33,051 DEBUG root:30 finish: subiquity/Install/install/postinstall/restore_apt_config/cmd-in-target: SUCCESS: curtin command in-target
2023-09-28 13:28:33,139 DEBUG subiquity.server.curtin:130 waited 0.4 seconds for events to drain
2023-09-28 13:28:33,140 DEBUG curtin:95 Running command ['umount', '/tmp/tmpwilo_7zi/root.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:28:33,150 DEBUG curtin:95 Running command ['umount', '/tmp/tmpwilo_7zi/minimal.en.squashfs.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:28:33,152 DEBUG curtin:95 Running command ['umount', '/tmp/tmpwilo_7zi/minimal.squashfs.dir'] with allowed return codes [0] (capture=True)
2023-09-28 13:28:33,156 WARNING subiquity.server.apt:355 failed to rmdir /target/cdrom: [Errno 16] Device or resource busy: '/target/cdrom'
2023-09-28 13:28:33,156 DEBUG root:30 finish: subiquity/Install/install/postinstall/restore_apt_config: SUCCESS: restoring apt configuration
2023-09-28 13:28:33,157 INFO root:30 finish: subiquity/Install/install/postinstall: SUCCESS: final system configuration
2023-09-28 13:28:33,157 DEBUG root:30 finish: subiquity/Install/install: SUCCESS: 
2023-09-28 13:28:33,157 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "DONE", "confirming_tty": "/dev/tty1", "error": null, "cloud_init_o...
2023-09-28 13:28:33,157 INFO aiohttp.access:206  [28/Sep/2023:13:28:25 +0000] "GET /meta/status?cur=%22UU_RUNNING%22 HTTP/1.1" 200 418 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:28:33,157 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "DONE", "confirming_tty": "/dev/tty1", "error": null, "cloud_init_o...
2023-09-28 13:28:33,157 INFO aiohttp.access:206  [28/Sep/2023:13:28:25 +0000] "GET /meta/status?cur=%22UU_RUNNING%22 HTTP/1.1" 200 418 "-" "Dart/3.0 (dart:io)"
2023-09-28 13:28:33,157 DEBUG root:30 start: subiquity/Late/run: 
2023-09-28 13:28:33,158 DEBUG root:30 start: subiquity/Late/run/command_0: run-parts --debug -- /snap/ubuntu-desktop-installer/1243/etc/subiquity/postinst.d
2023-09-28 13:28:33,171 DEBUG subiquitycore.utils:118 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1954', 'run-parts', '--debug', '--', '/snap/ubuntu-desktop-installer/1243/etc/subiquity/postinst.d']
2023-09-28 13:28:35,486 DEBUG subiquitycore.utils:132 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=subiquity_log.1954', 'run-parts', '--debug', '--', '/snap/ubuntu-desktop-installer/1243/etc/subiquity/postinst.d'] exited with code 0
2023-09-28 13:28:35,486 DEBUG root:30 finish: subiquity/Late/run/command_0: SUCCESS: run-parts --debug -- /snap/ubuntu-desktop-installer/1243/etc/subiquity/postinst.d
2023-09-28 13:28:35,487 DEBUG root:30 finish: subiquity/Late/run: SUCCESS: 
2023-09-28 13:28:35,487 DEBUG root:30 start: subiquity/Shutdown/copy_logs_to_target: 
2023-09-28 13:28:35,487 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', 'cp', '-a', '/var/log/cloud-init.log', '/var/log/cloud-init-output.log', '/var/log/installer']
2023-09-28 13:28:35,521 DEBUG subiquitycore.utils:151 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1954', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1243/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1243/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1243/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/usr/sbin:/snap/ubuntu-desktop-installer/1243/usr/bin:/snap/ubuntu-desktop-installer/1243/sbin:/snap/ubuntu-desktop-installer/1243/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin', '--setenv', 'PYTHONPATH=/snap/ubuntu-desktop-installer/1243/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1243/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1243/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1243', '--', 'cp', '-aT', '/var/log/installer', '/target/var/log/installer']