2023-11-09 23:48:50,829 INFO subiquity:199 Starting Subiquity server revision 1269 of snap /snap/ubuntu-desktop-installer/1269 2023-11-09 23:48:50,829 INFO subiquity:200 Arguments passed: ['/snap/ubuntu-desktop-installer/1269/bin/subiquity/subiquity/cmd/server.py', '--use-os-prober', '--storage-version=2', '--postinst-hooks-dir=/snap/ubuntu-desktop-installer/1269/etc/subiquity/postinst.d'] 2023-11-09 23:48:50,829 DEBUG subiquity:201 Kernel commandline: CommandLineParams(_raw='BOOT_IMAGE=/casper/vmlinuz layerfs-path=minimal.standard.live.squashfs --- quiet splash\n', _tokens={'splash', '---', 'quiet'}, _values={'BOOT_IMAGE': '/casper/vmlinuz', 'layerfs-path': 'minimal.standard.live.squashfs'}) 2023-11-09 23:48:50,829 DEBUG subiquity:202 Environment: environ({'SNAP_REVISION': '1269', 'SNAP_REAL_HOME': '/root', 'SNAP_USER_COMMON': '/root/snap/ubuntu-desktop-installer/common', 'PATH_ORIG': '/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/bin/subiquity', 'SYSTEMD_EXEC_PID': '1869', 'SNAP_CONTEXT': 'xCei6OwLH_j0abkSwQlp5C_xexWVpx2fRC81WZiXPi3RdS6PrQel', 'LANG': 'C.UTF-8', 'SNAP_ARCH': 'amd64', 'PY3OR2_PYTHON': '/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', 'SNAP_INSTANCE_NAME': 'ubuntu-desktop-installer', 'SNAP_USER_DATA': '/root/snap/ubuntu-desktop-installer/1269', 'INVOCATION_ID': 'bb8dc45549084e8790c8589f25e155eb', '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/1269/lib:/snap/ubuntu-desktop-installer/1269/usr/lib:/snap/ubuntu-desktop-installer/1269/lib/x86_64-linux-gnu:/snap/ubuntu-desktop-installer/1269/usr/lib/x86_64-linux-gnu', 'PYTHONPATH_ORIG': '', 'PYTHONPATH': '/snap/ubuntu-desktop-installer/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', 'PYTHON': '/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', 'PYTHONIOENCODING': 'utf-8', 'SNAP': '/snap/ubuntu-desktop-installer/1269', 'SNAP_COMMON': '/var/snap/ubuntu-desktop-installer/common', 'SNAP_VERSION': '0+git.1c719695', 'DISPLAY': ':0', 'SHLVL': '1', 'SNAP_LIBRARY_PATH': '/var/lib/snapd/lib/gl:/var/lib/snapd/lib/gl32:/var/lib/snapd/void', 'SNAP_COOKIE': 'xCei6OwLH_j0abkSwQlp5C_xexWVpx2fRC81WZiXPi3RdS6PrQel', 'SNAP_DATA': '/var/snap/ubuntu-desktop-installer/1269', 'LD_LIBRARY_PATH': '/var/lib/snapd/lib/gl:/var/lib/snapd/lib/gl32:/var/lib/snapd/void:/snap/ubuntu-desktop-installer/1269/lib:/snap/ubuntu-desktop-installer/1269/usr/lib:/snap/ubuntu-desktop-installer/1269/lib/x86_64-linux-gnu:/snap/ubuntu-desktop-installer/1269/usr/lib/x86_64-linux-gnu', 'SNAP_NAME': 'ubuntu-desktop-installer', 'JOURNAL_STREAM': '8:21274', 'PATH': '/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/bin/subiquity', 'OLDPWD': '/var/snap/ubuntu-desktop-installer/1269', '_': '/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', 'APPORT_DATA_DIR': '/snap/ubuntu-desktop-installer/1269/bin/subiquity/share/apport'}) 2023-11-09 23:48:50,829 DEBUG asyncio:54 Using selector: EpollSelector 2023-11-09 23:48:50,830 DEBUG subiquitycore.prober:33 Prober() init finished, data:None 2023-11-09 23:48:50,860 DEBUG curtin:95 Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (capture=True) 2023-11-09 23:48:50,866 DEBUG subiquitycore.netplan:113 config for zz-all-en = {'dhcp4': True, 'match': {'name': 'en*'}} 2023-11-09 23:48:50,867 DEBUG subiquitycore.netplan:113 config for zz-all-eth = {'dhcp4': True, 'match': {'name': 'eth*'}} 2023-11-09 23:48:50,875 DEBUG subiquitycore.utils:121 arun_command called: ['cloud-init', 'status', '--wait'] 2023-11-09 23:49:07,674 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET: 2023-11-09 23:49:07,674 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-11-09 23:49:08,680 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET: 2023-11-09 23:49:08,680 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-11-09 23:49:09,683 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET: 2023-11-09 23:49:09,684 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-11-09 23:49:10,687 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET: 2023-11-09 23:49:10,687 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-11-09 23:49:11,691 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET: 2023-11-09 23:49:11,691 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-11-09 23:49:12,705 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET: 2023-11-09 23:49:12,708 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-11-09 23:49:13,154 DEBUG subiquitycore.utils:135 arun_command ['cloud-init', 'status', '--wait'] exited with code 0 2023-11-09 23:49:13,154 DEBUG subiquity.server.server:569 waited 22.27974033355713s for cloud-init 2023-11-09 23:49:13,155 DEBUG subiquity.cloudinit:14 Loaded cloud config from /run/cloud-init/combined-cloud-config.json 2023-11-09 23:49:13,155 DEBUG subiquity.server.server:553 no autoinstall found in cloud-config 2023-11-09 23:49:13,155 DEBUG subiquitycore.utils:79 run_command called: ['ssh-keygen', '-lf', '/home/installer/.ssh/authorized_keys'] 2023-11-09 23:49:13,162 DEBUG subiquitycore.utils:98 run_command ['ssh-keygen', '-lf', '/home/installer/.ssh/authorized_keys'] exited with code 255 2023-11-09 23:49:13,162 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-11-09 23:49:13,162 DEBUG subiquitycore.utils:79 run_command called: chpasswd 2023-11-09 23:49:13,281 DEBUG subiquitycore.utils:98 run_command chpasswd exited with code 0 2023-11-09 23:49:13,282 DEBUG subiquity.server.server:470 load_autoinstall_config only_early True file None 2023-11-09 23:49:13,282 DEBUG subiquity.server.server:470 load_autoinstall_config only_early False file None 2023-11-09 23:49:13,282 DEBUG subiquitycore.core:118 starting controllers 2023-11-09 23:49:13,286 DEBUG subiquity.server.controllers.kernel:63 Using kernel linux-generic-hwe-22.04 due to /etc/subiquity/kernel-meta-package 2023-11-09 23:49:13,291 DEBUG subiquity.models.source:93 loaded 2 sources from '/cdrom/casper/install-sources.yaml' 2023-11-09 23:49:13,292 DEBUG probert.network:585 event for link_change: NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'} 2023-11-09 23:49:13,292 DEBUG probert.network:585 event for link_change: NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'enp1s0'} 2023-11-09 23:49:13,292 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-11-09 23:49:13,292 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 2, 'flags': 512, 'family': 2, 'scope': 0, 'local': b'192.168.1.90/24'} 2023-11-09 23:49:13,292 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'} 2023-11-09 23:49:13,292 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::5054:ff:fed0:4689/64'} 2023-11-09 23:49:13,292 DEBUG probert.network:672 link_change NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'} 2023-11-09 23:49:13,349 DEBUG subiquitycore.models.network:475 new_link 1 lo lo 2023-11-09 23:49:13,349 DEBUG subiquitycore.models.network:477 ignoring based on type 2023-11-09 23:49:13,349 DEBUG probert.network:672 link_change NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'enp1s0'} 2023-11-09 23:49:13,403 DEBUG subiquitycore.models.network:475 new_link 2 enp1s0 eth 2023-11-09 23:49:13,404 DEBUG subiquitycore.models.network:506 new_link 2 enp1s0 with config {'dhcp4': True} 2023-11-09 23:49:13,404 DEBUG root:30 start: subiquity/Network/_send_update: NEW enp1s0 2023-11-09 23:49:13,404 DEBUG root:30 finish: subiquity/Network/_send_update: SUCCESS: NEW enp1s0 2023-11-09 23:49:13,404 DEBUG probert.network:717 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'} 2023-11-09 23:49:13,404 DEBUG probert.network:717 addr_change NEW {'ifindex': 2, 'flags': 512, 'family': 2, 'scope': 0, 'local': b'192.168.1.90/24'} 2023-11-09 23:49:13,404 DEBUG root:30 start: subiquity/Network/_send_update: CHANGE enp1s0 2023-11-09 23:49:13,404 DEBUG root:30 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp1s0 2023-11-09 23:49:13,404 DEBUG probert.network:717 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'} 2023-11-09 23:49:13,404 DEBUG probert.network:717 addr_change NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::5054:ff:fed0:4689/64'} 2023-11-09 23:49:13,404 DEBUG root:30 start: subiquity/Network/_send_update: CHANGE enp1s0 2023-11-09 23:49:13,405 DEBUG root:30 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp1s0 2023-11-09 23:49:13,405 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2} 2023-11-09 23:49:13,457 DEBUG pyroute2.ndb.140465574951040.sources.localhost:74 init 2023-11-09 23:49:13,457 DEBUG pyroute2.ndb.140465574951040.sources.localhost:384 starting the source 2023-11-09 23:49:13,458 DEBUG pyroute2.ndb.140465574951040.sources.localhost/nsmanager:74 init 2023-11-09 23:49:13,458 DEBUG pyroute2.ndb.140465574951040.sources.localhost/nsmanager:384 starting the source 2023-11-09 23:49:13,458 DEBUG pyroute2.ndb.140465574951040.sources.localhost:74 connecting 2023-11-09 23:49:13,458 DEBUG pyroute2.ndb.140465574951040.sources.localhost:74 loading 2023-11-09 23:49:13,459 DEBUG pyroute2.ndb.140465574951040.sources.localhost/nsmanager:74 connecting 2023-11-09 23:49:13,461 DEBUG pyroute2.ndb.140465574951040.sources.localhost/nsmanager:74 loading 2023-11-09 23:49:13,485 DEBUG pyroute2.ndb.140465574951040.sources.localhost:74 running 2023-11-09 23:49:13,486 DEBUG pyroute2.ndb.140465574951040.sources.localhost/nsmanager:74 running 2023-11-09 23:49:13,488 DEBUG pyroute2.ndb.140465574951040.sources.localhost:399 source shutdown 2023-11-09 23:49:13,492 DEBUG pyroute2.ndb.140465574951040.sources.localhost:374 sync 2023-11-09 23:49:13,492 DEBUG pyroute2.ndb.140465574951040.sources.localhost:369 shutdown handled by the main thread 2023-11-09 23:49:13,492 DEBUG pyroute2.ndb.140465574951040.sources.localhost:74 stopped 2023-11-09 23:49:13,492 DEBUG pyroute2.ndb.140465574951040.main:851 flush DB for the target localhost 2023-11-09 23:49:13,493 DEBUG pyroute2.ndb.140465574951040.sources.localhost/nsmanager:399 source shutdown 2023-11-09 23:49:13,508 DEBUG pyroute2.ndb.140465574951040.sources.localhost/nsmanager:374 sync 2023-11-09 23:49:13,508 DEBUG pyroute2.ndb.140465574951040.sources.localhost/nsmanager:369 shutdown handled by the main thread 2023-11-09 23:49:13,508 DEBUG pyroute2.ndb.140465574951040.sources.localhost/nsmanager:74 stopped 2023-11-09 23:49:13,508 DEBUG pyroute2.ndb.140465574951040.main:851 flush DB for the target localhost/nsmanager 2023-11-09 23:49:13,508 DEBUG subiquitycore.controllers.network:102 default routes True 2023-11-09 23:49:13,509 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'169.254.0.0/16', 'ifindex': 2} 2023-11-09 23:49:13,509 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'192.168.1.0/24', 'ifindex': 2} 2023-11-09 23:49:13,509 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.0/8', 'ifindex': 1} 2023-11-09 23:49:13,509 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.1', 'ifindex': 1} 2023-11-09 23:49:13,509 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'127.255.255.255', 'ifindex': 1} 2023-11-09 23:49:13,509 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'192.168.1.90', 'ifindex': 2} 2023-11-09 23:49:13,509 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'192.168.1.255', 'ifindex': 2} 2023-11-09 23:49:13,509 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'::1', 'ifindex': 1} 2023-11-09 23:49:13,509 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'fe80::/64', 'ifindex': 2} 2023-11-09 23:49:13,509 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'::1', 'ifindex': 1} 2023-11-09 23:49:13,509 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'fe80::5054:ff:fed0:4689', 'ifindex': 2} 2023-11-09 23:49:13,509 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 5, 'table': 255, 'dst': b'ff00::/8', 'ifindex': 2} 2023-11-09 23:49:13,624 DEBUG subiquitycore.core:121 controllers started 2023-11-09 23:49:13,624 INFO root:30 start: subiquity/apply_autoinstall_config: 2023-11-09 23:49:13,624 DEBUG root:30 start: subiquity/Early/apply_autoinstall_config: 2023-11-09 23:49:13,625 DEBUG root:30 finish: subiquity/Early/apply_autoinstall_config: SUCCESS: 2023-11-09 23:49:13,625 DEBUG root:30 start: subiquity/Reporting/apply_autoinstall_config: 2023-11-09 23:49:13,626 DEBUG root:30 finish: subiquity/Reporting/apply_autoinstall_config: SUCCESS: 2023-11-09 23:49:13,626 DEBUG root:30 start: subiquity/Error/apply_autoinstall_config: 2023-11-09 23:49:13,626 DEBUG root:30 finish: subiquity/Error/apply_autoinstall_config: SUCCESS: 2023-11-09 23:49:13,627 DEBUG root:30 start: subiquity/Userdata/apply_autoinstall_config: 2023-11-09 23:49:13,627 DEBUG root:30 finish: subiquity/Userdata/apply_autoinstall_config: SUCCESS: 2023-11-09 23:49:13,627 DEBUG subiquity.models.subiquity:256 model userdata for postinstall stage is configured, to go {'locale', 'packages', 'identity', 'snaplist', 'ssh', 'drivers', 'ubuntu_pro'} 2023-11-09 23:49:13,627 DEBUG root:30 start: subiquity/Package/apply_autoinstall_config: 2023-11-09 23:49:13,627 DEBUG root:30 finish: subiquity/Package/apply_autoinstall_config: SUCCESS: 2023-11-09 23:49:13,634 DEBUG subiquity.models.subiquity:256 model packages for postinstall stage is configured, to go {'locale', 'identity', 'snaplist', 'ssh', 'drivers', 'ubuntu_pro'} 2023-11-09 23:49:13,635 DEBUG root:30 start: subiquity/Debconf/apply_autoinstall_config: 2023-11-09 23:49:13,635 DEBUG root:30 finish: subiquity/Debconf/apply_autoinstall_config: SUCCESS: 2023-11-09 23:49:13,635 DEBUG subiquity.models.subiquity:256 model debconf_selections for install stage is configured, to go {'filesystem', 'keyboard', 'source', 'kernel', 'proxy'} 2023-11-09 23:49:13,635 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Locale as interactive 2023-11-09 23:49:13,636 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Refresh as interactive 2023-11-09 23:49:13,636 DEBUG root:30 start: subiquity/Kernel/apply_autoinstall_config: 2023-11-09 23:49:13,636 DEBUG root:30 finish: subiquity/Kernel/apply_autoinstall_config: SUCCESS: 2023-11-09 23:49:13,636 DEBUG subiquity.models.subiquity:256 model kernel for install stage is configured, to go {'filesystem', 'keyboard', 'source', 'proxy'} 2023-11-09 23:49:13,636 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Integrity as interactive 2023-11-09 23:49:13,636 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Keyboard as interactive 2023-11-09 23:49:13,637 DEBUG root:30 start: subiquity/Zdev/apply_autoinstall_config: 2023-11-09 23:49:13,637 DEBUG root:30 finish: subiquity/Zdev/apply_autoinstall_config: SUCCESS: 2023-11-09 23:49:13,637 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Source as interactive 2023-11-09 23:49:13,637 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Network as interactive 2023-11-09 23:49:13,637 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping UbuntuPro as interactive 2023-11-09 23:49:13,637 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Proxy as interactive 2023-11-09 23:49:13,637 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Mirror as interactive 2023-11-09 23:49:13,637 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Filesystem as interactive 2023-11-09 23:49:13,638 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Identity as interactive 2023-11-09 23:49:13,638 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping SSH as interactive 2023-11-09 23:49:13,638 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping SnapList as interactive 2023-11-09 23:49:13,638 DEBUG root:30 start: subiquity/Ad/apply_autoinstall_config: 2023-11-09 23:49:13,638 DEBUG root:30 finish: subiquity/Ad/apply_autoinstall_config: SUCCESS: 2023-11-09 23:49:13,639 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Codecs as interactive 2023-11-09 23:49:13,639 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Drivers as interactive 2023-11-09 23:49:13,639 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping OEM as interactive 2023-11-09 23:49:13,639 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping TimeZone as interactive 2023-11-09 23:49:13,639 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Install as interactive 2023-11-09 23:49:13,639 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Updates as interactive 2023-11-09 23:49:13,661 DEBUG root:30 start: subiquity/Late/apply_autoinstall_config: 2023-11-09 23:49:13,662 DEBUG root:30 finish: subiquity/Late/apply_autoinstall_config: SUCCESS: 2023-11-09 23:49:13,662 DEBUG subiquity.server.server:461 apply_autoinstall_config: skipping Shutdown as interactive 2023-11-09 23:49:13,662 INFO root:30 finish: subiquity/apply_autoinstall_config: SUCCESS: 2023-11-09 23:49:13,663 DEBUG subiquity.models.subiquity:256 model locale for postinstall stage is configured, to go {'identity', 'snaplist', 'ssh', 'drivers', 'ubuntu_pro'} 2023-11-09 23:49:13,663 DEBUG root:30 start: subiquity/Refresh/configure_snapd: 2023-11-09 23:49:13,663 DEBUG root:30 start: subiquity/Refresh/configure_snapd/get_details: 2023-11-09 23:49:13,674 DEBUG root:30 start: subiquity/Refresh/check_for_update: 2023-11-09 23:49:13,675 DEBUG subiquitycore.utils:121 arun_command called: ['/usr/sbin/realm', 'discover'] 2023-11-09 23:49:13,694 DEBUG root:30 start: subiquity/OEM/load_metapackages_list: 2023-11-09 23:49:13,694 DEBUG root:30 start: subiquity/OEM/load_metapackages_list/wait_confirmation: 2023-11-09 23:49:13,694 DEBUG root:30 start: subiquity/Install/install: 2023-11-09 23:49:13,695 DEBUG subiquity.server.controllers.snaplist:79 loading list of snaps 2023-11-09 23:49:13,729 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/snaps/ubuntu-desktop-installer HTTP/1.1" 200 1560 2023-11-09 23:49:13,804 DEBUG root:30 start: subiquity/Filesystem/_probe: 2023-11-09 23:49:13,804 DEBUG root:30 start: subiquity/Refresh/check_for_update: 2023-11-09 23:49:13,805 DEBUG root:30 start: subiquity/SnapList/loader: 2023-11-09 23:49:13,805 DEBUG root:30 start: subiquity/Filesystem/_probe/probe_once: restricted=False 2023-11-09 23:49:13,811 ERROR root:30 finish: subiquity/Refresh/check_for_update: FAIL: cancelled 2023-11-09 23:49:13,811 DEBUG root:30 start: subiquity/SnapList/loader/list: 2023-11-09 23:49:13,813 DEBUG asyncio:54 Using selector: EpollSelector 2023-11-09 23:49:13,821 DEBUG root:30 finish: subiquity/Refresh/configure_snapd/get_details: SUCCESS: current version of snap is: '0+git.1c719695' 2023-11-09 23:49:13,821 DEBUG subiquity.server.controllers.refresh:139 snap tracking , not resetting based on .disk/info 2023-11-09 23:49:13,821 DEBUG root:30 finish: subiquity/Refresh/configure_snapd: SUCCESS: 2023-11-09 23:49:13,822 INFO root:30 start: subiquity/Meta/status_GET: 2023-11-09 23:49:13,822 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr... 2023-11-09 23:49:13,830 INFO root:30 start: subiquity/Meta/status_GET: 2023-11-09 23:49:13,830 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr... 2023-11-09 23:49:13,831 INFO root:30 start: subiquity/Meta/status_GET: 2023-11-09 23:49:13,832 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr... 2023-11-09 23:49:13,836 INFO root:30 start: subiquity/Meta/client_variant_POST: 2023-11-09 23:49:13,837 INFO root:30 finish: subiquity/Meta/client_variant_POST: SUCCESS: 200 null 2023-11-09 23:49:13,837 DEBUG subiquitycore.utils:135 arun_command ['/usr/sbin/realm', 'discover'] exited with code 1 2023-11-09 23:49:13,837 INFO root:30 start: subiquity/Meta/status_GET: 2023-11-09 23:49:13,838 INFO root:30 start: subiquity/Meta/interactive_sections_GET: 2023-11-09 23:49:13,838 INFO root:30 finish: subiquity/Meta/interactive_sections_GET: SUCCESS: 200 null 2023-11-09 23:49:13,840 INFO root:30 start: subiquity/Meta/status_GET: 2023-11-09 23:49:13,848 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr... 2023-11-09 23:49:13,850 DEBUG root:30 start: subiquity/Locale/GET: 2023-11-09 23:49:13,851 DEBUG root:30 finish: subiquity/Locale/GET: SUCCESS: 200 "C.UTF-8" 2023-11-09 23:49:13,857 INFO root:30 start: subiquity/Meta/mark_configured_POST: 2023-11-09 23:49:13,857 DEBUG subiquity.models.subiquity:256 model ubuntu_pro for postinstall stage is configured, to go {'identity', 'snaplist', 'network', 'ssh', 'drivers', 'timezone', 'codecs'} 2023-11-09 23:49:13,857 DEBUG subiquity.models.subiquity:256 model proxy for install stage is configured, to go {'mirror', 'network', 'filesystem', 'keyboard', 'source'} 2023-11-09 23:49:13,857 DEBUG subiquity.models.subiquity:256 model mirror for install stage is configured, to go {'network', 'filesystem', 'keyboard', 'source'} 2023-11-09 23:49:13,858 DEBUG subiquity.models.subiquity:256 model ssh for postinstall stage is configured, to go {'identity', 'snaplist', 'network', 'drivers', 'timezone', 'codecs'} 2023-11-09 23:49:13,858 DEBUG subiquity.models.subiquity:256 model snaplist for postinstall stage is configured, to go {'identity', 'network', 'drivers', 'timezone', 'codecs'} 2023-11-09 23:49:13,858 INFO root:30 finish: subiquity/Meta/mark_configured_POST: SUCCESS: 200 null 2023-11-09 23:49:14,132 DEBUG root:30 start: subiquity/Refresh/GET: 2023-11-09 23:49:14,161 DEBUG probert.dasd:134 Probing DASD devies 2023-11-09 23:49:14,161 DEBUG probert.dasd:137 DASD devices only present on s390x, arch=x86_64 2023-11-09 23:49:14,197 ERROR probert.multipath:38 Failed to run cmd: ['multipathd', 'show', 'maps', 'raw', 'format', '%w,%d,%N'] 2023-11-09 23:49:14,202 ERROR probert.multipath:38 Failed to run cmd: ['multipathd', 'show', 'paths', 'raw', 'format', '%d,%z,%m,%N,%n,%R,%r,%a'] 2023-11-09 23:49:15,188 DEBUG curtin:1325 Extracting storage config from probe data 2023-11-09 23:49:15,188 DEBUG curtin:73 /dev/sr0 is multipath device member? False 2023-11-09 23:49:15,188 DEBUG curtin:86 /dev/sr0 is multipath device partition? False 2023-11-09 23:49:15,188 DEBUG curtin:73 /dev/sda is multipath device member? False 2023-11-09 23:49:15,188 DEBUG curtin:86 /dev/sda is multipath device partition? False 2023-11-09 23:49:15,188 DEBUG curtin:61 /dev/sda is multipath device? False 2023-11-09 23:49:15,188 DEBUG curtin:86 /dev/sda is multipath device partition? False 2023-11-09 23:49:15,188 DEBUG curtin:61 /dev/sda is multipath device? False 2023-11-09 23:49:15,203 DEBUG curtin:73 /dev/sr0 is multipath device member? False 2023-11-09 23:49:15,203 DEBUG curtin:1332 Sorting extracted configurations 2023-11-09 23:49:15,203 INFO curtin:1351 Validating extracted storage config components 2023-11-09 23:49:15,215 DEBUG curtin:1368 Extracted (unmerged) storage config: storage: - id: disk-sda path: /dev/sda serial: QEMU_HARDDISK_QM00003 type: disk 2023-11-09 23:49:15,215 DEBUG curtin:1372 Generating storage config dependencies 2023-11-09 23:49:15,215 DEBUG curtin:1378 Merging storage config dependencies 2023-11-09 23:49:15,215 DEBUG curtin:1383 Merged storage config: storage: config: - id: disk-sda path: /dev/sda serial: QEMU_HARDDISK_QM00003 type: disk version: 2 2023-11-09 23:49:15,216 DEBUG subiquity.models.filesystem:1463 majmin_to_dev {'8:0': Disk(serial='QEMU_HARDDISK_QM00003', path='/dev/sda', preserve=True, id='disk-sda', type='disk')} 2023-11-09 23:49:15,216 DEBUG subiquity.models.filesystem:1475 considering mount of 0:28 2023-11-09 23:49:15,216 DEBUG subiquity.models.filesystem:1475 considering mount of 0:22 2023-11-09 23:49:15,216 DEBUG subiquity.models.filesystem:1475 considering mount of 0:23 2023-11-09 23:49:15,216 DEBUG subiquity.models.filesystem:1475 considering mount of 0:5 2023-11-09 23:49:15,216 DEBUG subiquity.models.filesystem:1475 considering mount of 0:25 2023-11-09 23:49:15,216 DEBUG subiquity.models.filesystem:1475 considering mount of 11:0 2023-11-09 23:49:15,216 DEBUG subiquity.models.filesystem:1475 considering mount of 7:0 2023-11-09 23:49:15,216 DEBUG subiquity.models.filesystem:1475 considering mount of 0:28 2023-11-09 23:49:15,216 DEBUG subiquity.models.filesystem:1475 considering mount of 0:45 2023-11-09 23:49:15,216 DEBUG subiquity.models.filesystem:1475 considering mount of 7:3 2023-11-09 23:49:15,216 DEBUG subiquity.models.filesystem:1475 considering mount of 7:6 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 7:4 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 7:5 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 7:7 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 7:8 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 7:11 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 7:12 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 7:10 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 7:9 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:28 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:26 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:6 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:35 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:36 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:37 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:7 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:12 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:21 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:40 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:38 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:24 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:33 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:39 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:20 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:34 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:41 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:42 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:43 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:25 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:46 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:48 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 0:90 2023-11-09 23:49:15,221 DEBUG subiquity.models.filesystem:1475 considering mount of 7:3 2023-11-09 23:49:15,222 DEBUG subiquity.models.filesystem:1475 considering mount of 7:6 2023-11-09 23:49:15,222 DEBUG subiquity.models.filesystem:1475 considering mount of 7:4 2023-11-09 23:49:15,222 DEBUG subiquity.models.filesystem:1475 considering mount of 7:5 2023-11-09 23:49:15,222 DEBUG subiquity.models.filesystem:1475 considering mount of 7:7 2023-11-09 23:49:15,222 DEBUG subiquity.models.filesystem:1475 considering mount of 7:8 2023-11-09 23:49:15,222 DEBUG subiquity.models.filesystem:1475 considering mount of 7:11 2023-11-09 23:49:15,222 DEBUG subiquity.models.filesystem:1475 considering mount of 7:12 2023-11-09 23:49:15,222 DEBUG subiquity.models.filesystem:1475 considering mount of 7:10 2023-11-09 23:49:15,222 DEBUG subiquity.models.filesystem:1475 considering mount of 7:9 2023-11-09 23:49:15,222 DEBUG subiquity.models.filesystem:1475 considering mount of 0:51 2023-11-09 23:49:15,222 DEBUG subiquity.models.filesystem:1475 considering mount of 0:4 2023-11-09 23:49:15,222 DEBUG subiquity.models.filesystem:1475 considering mount of 0:4 2023-11-09 23:49:15,222 DEBUG subiquity.models.filesystem:1475 considering mount of 0:4 2023-11-09 23:49:15,222 DEBUG subiquity.models.filesystem:1475 considering mount of 0:4 2023-11-09 23:49:15,222 DEBUG subiquity.models.filesystem:1475 considering mount of 0:63 2023-11-09 23:49:15,222 DEBUG subiquity.models.filesystem:1475 considering mount of 0:91 2023-11-09 23:49:15,222 DEBUG root:30 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False 2023-11-09 23:49:15,222 DEBUG subiquity.server.controllers.filesystem:1297 block probing took 1.4 seconds 2023-11-09 23:49:15,222 DEBUG subiquity.server.controllers.filesystem:1474 start_monitor 2023-11-09 23:49:15,223 DEBUG root:30 finish: subiquity/Filesystem/_probe: SUCCESS: 2023-11-09 23:49:15,771 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?select=refresh HTTP/1.1" 200 59 2023-11-09 23:49:15,771 DEBUG subiquity.server.controllers.refresh:201 check_for_update received [] 2023-11-09 23:49:15,772 DEBUG root:30 finish: subiquity/Refresh/check_for_update: SUCCESS: no new version of snap available 2023-11-09 23:49:15,772 DEBUG root:30 finish: subiquity/Refresh/GET: SUCCESS: 200 {"availability": "UNAVAILABLE", "current_snap_version": "0+git.1c719695", "ne... 2023-11-09 23:49:15,981 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?section=server HTTP/1.1" 200 None 2023-11-09 23:49:15,982 DEBUG root:30 finish: subiquity/SnapList/loader/list: SUCCESS: 2023-11-09 23:49:15,982 DEBUG subiquity.server.controllers.snaplist:92 fetched list of 22 snaps 2023-11-09 23:49:15,983 DEBUG root:30 start: subiquity/SnapList/loader/fetch/microk8s: 2023-11-09 23:49:16,844 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=microk8s HTTP/1.1" 200 None 2023-11-09 23:49:16,853 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/microk8s: SUCCESS: 2023-11-09 23:49:16,853 DEBUG root:30 start: subiquity/SnapList/loader/fetch/nextcloud: 2023-11-09 23:49:17,429 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=nextcloud HTTP/1.1" 200 None 2023-11-09 23:49:17,430 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/nextcloud: SUCCESS: 2023-11-09 23:49:17,431 DEBUG root:30 start: subiquity/SnapList/loader/fetch/wekan: 2023-11-09 23:49:17,846 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=wekan HTTP/1.1" 200 None 2023-11-09 23:49:17,847 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/wekan: SUCCESS: 2023-11-09 23:49:17,847 DEBUG root:30 start: subiquity/SnapList/loader/fetch/kata-containers: 2023-11-09 23:49:18,300 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=kata-containers HTTP/1.1" 200 None 2023-11-09 23:49:18,301 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/kata-containers: SUCCESS: 2023-11-09 23:49:18,301 DEBUG root:30 start: subiquity/SnapList/loader/fetch/docker: 2023-11-09 23:49:18,711 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=docker HTTP/1.1" 200 None 2023-11-09 23:49:18,712 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/docker: SUCCESS: 2023-11-09 23:49:18,712 DEBUG root:30 start: subiquity/SnapList/loader/fetch/canonical-livepatch: 2023-11-09 23:49:19,138 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=canonical-livepatch HTTP/1.1" 200 None 2023-11-09 23:49:19,139 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/canonical-livepatch: SUCCESS: 2023-11-09 23:49:19,139 DEBUG root:30 start: subiquity/SnapList/loader/fetch/rocketchat-server: 2023-11-09 23:49:19,599 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=rocketchat-server HTTP/1.1" 200 None 2023-11-09 23:49:19,600 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/rocketchat-server: SUCCESS: 2023-11-09 23:49:19,600 DEBUG root:30 start: subiquity/SnapList/loader/fetch/mosquitto: 2023-11-09 23:49:19,992 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=mosquitto HTTP/1.1" 200 None 2023-11-09 23:49:19,993 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/mosquitto: SUCCESS: 2023-11-09 23:49:19,993 DEBUG root:30 start: subiquity/SnapList/loader/fetch/etcd: 2023-11-09 23:49:20,536 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=etcd HTTP/1.1" 200 None 2023-11-09 23:49:20,537 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/etcd: SUCCESS: 2023-11-09 23:49:20,538 DEBUG root:30 start: subiquity/SnapList/loader/fetch/powershell: 2023-11-09 23:49:20,972 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=powershell HTTP/1.1" 200 None 2023-11-09 23:49:20,973 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/powershell: SUCCESS: 2023-11-09 23:49:20,973 DEBUG root:30 start: subiquity/SnapList/loader/fetch/sabnzbd: 2023-11-09 23:49:21,405 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=sabnzbd HTTP/1.1" 200 None 2023-11-09 23:49:21,407 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/sabnzbd: SUCCESS: 2023-11-09 23:49:21,407 DEBUG root:30 start: subiquity/SnapList/loader/fetch/wormhole: 2023-11-09 23:49:21,848 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=wormhole HTTP/1.1" 200 None 2023-11-09 23:49:21,849 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/wormhole: SUCCESS: 2023-11-09 23:49:21,849 DEBUG root:30 start: subiquity/SnapList/loader/fetch/aws-cli: 2023-11-09 23:49:22,289 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=aws-cli HTTP/1.1" 200 None 2023-11-09 23:49:22,290 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/aws-cli: SUCCESS: 2023-11-09 23:49:22,290 DEBUG root:30 start: subiquity/SnapList/loader/fetch/google-cloud-sdk: 2023-11-09 23:49:22,418 DEBUG root:30 start: subiquity/Locale/POST: 2023-11-09 23:49:22,418 DEBUG subiquity.server.controllers.locale:68 en_US.UTF-8 2023-11-09 23:49:22,419 DEBUG subiquity.models.subiquity:256 model locale for postinstall stage is configured, to go {'identity', 'network', 'drivers', 'timezone', 'codecs'} 2023-11-09 23:49:22,419 DEBUG root:30 finish: subiquity/Locale/POST: SUCCESS: 200 null 2023-11-09 23:49:22,419 DEBUG subiquitycore.utils:121 arun_command called: ['localectl', 'set-locale', 'en_US.UTF-8'] 2023-11-09 23:49:22,753 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=google-cloud-sdk HTTP/1.1" 200 1799 2023-11-09 23:49:22,754 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/google-cloud-sdk: SUCCESS: 2023-11-09 23:49:22,754 DEBUG root:30 start: subiquity/SnapList/loader/fetch/slcli: 2023-11-09 23:49:23,111 DEBUG subiquitycore.utils:135 arun_command ['localectl', 'set-locale', 'en_US.UTF-8'] exited with code 0 2023-11-09 23:49:23,203 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=slcli HTTP/1.1" 200 None 2023-11-09 23:49:23,204 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/slcli: SUCCESS: 2023-11-09 23:49:23,204 DEBUG root:30 start: subiquity/SnapList/loader/fetch/doctl: 2023-11-09 23:49:23,640 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=doctl HTTP/1.1" 200 None 2023-11-09 23:49:23,641 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/doctl: SUCCESS: 2023-11-09 23:49:23,641 DEBUG root:30 start: subiquity/SnapList/loader/fetch/conjure-up: 2023-11-09 23:49:24,045 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=conjure-up HTTP/1.1" 200 None 2023-11-09 23:49:24,046 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/conjure-up: SUCCESS: 2023-11-09 23:49:24,046 DEBUG root:30 start: subiquity/SnapList/loader/fetch/postgresql10: 2023-11-09 23:49:24,462 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=postgresql10 HTTP/1.1" 200 1523 2023-11-09 23:49:24,462 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/postgresql10: SUCCESS: 2023-11-09 23:49:24,463 DEBUG root:30 start: subiquity/SnapList/loader/fetch/heroku: 2023-11-09 23:49:24,900 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=heroku HTTP/1.1" 200 None 2023-11-09 23:49:24,900 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/heroku: SUCCESS: 2023-11-09 23:49:24,900 DEBUG root:30 start: subiquity/SnapList/loader/fetch/keepalived: 2023-11-09 23:49:25,324 DEBUG root:30 start: subiquity/Filesystem/has_rst_GET: 2023-11-09 23:49:25,324 DEBUG root:30 finish: subiquity/Filesystem/has_rst_GET: SUCCESS: 200 false 2023-11-09 23:49:25,327 DEBUG root:30 start: subiquity/Keyboard/GET: 2023-11-09 23:49:25,342 DEBUG root:30 finish: subiquity/Keyboard/GET: SUCCESS: 200 {"setting": {"layout": "us", "variant": "", "toggle": null}, "layouts": [{"co... 2023-11-09 23:49:25,346 DEBUG root:30 start: subiquity/Keyboard/GET: 2023-11-09 23:49:25,354 DEBUG root:30 finish: subiquity/Keyboard/GET: SUCCESS: 200 {"setting": {"layout": "us", "variant": "", "toggle": null}, "layouts": [{"co... 2023-11-09 23:49:25,357 DEBUG root:30 start: subiquity/Keyboard/input_source_POST: 2023-11-09 23:49:25,358 DEBUG subiquitycore.utils:121 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-11-09 23:49:25,368 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=keepalived HTTP/1.1" 200 None 2023-11-09 23:49:25,373 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/keepalived: SUCCESS: 2023-11-09 23:49:25,373 DEBUG root:30 start: subiquity/SnapList/loader/fetch/prometheus: 2023-11-09 23:49:25,439 DEBUG subiquitycore.utils:135 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-11-09 23:49:25,440 DEBUG root:30 finish: subiquity/Keyboard/input_source_POST: SUCCESS: 200 null 2023-11-09 23:49:25,798 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=prometheus HTTP/1.1" 200 None 2023-11-09 23:49:25,798 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/prometheus: SUCCESS: 2023-11-09 23:49:25,798 DEBUG root:30 start: subiquity/SnapList/loader/fetch/juju: 2023-11-09 23:49:26,285 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=juju HTTP/1.1" 200 None 2023-11-09 23:49:26,286 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/juju: SUCCESS: 2023-11-09 23:49:26,286 DEBUG root:30 finish: subiquity/SnapList/loader: SUCCESS: 2023-11-09 23:49:26,502 DEBUG root:30 start: subiquity/Keyboard/POST: 2023-11-09 23:49:26,502 DEBUG subiquity.server.controllers.keyboard:221 KeyboardSetting(layout='us', variant='', toggle=None) 2023-11-09 23:49:26,502 DEBUG subiquity.models.subiquity:256 model keyboard for install stage is configured, to go {'network', 'filesystem', 'source'} 2023-11-09 23:49:26,502 DEBUG root:30 finish: subiquity/Keyboard/POST: SUCCESS: 200 null 2023-11-09 23:49:27,160 DEBUG subiquity.server.controllers.integrity:61 casper-md5check results: {'checksum_missmatch': [], 'result': 'pass'} 2023-11-09 23:49:27,723 DEBUG root:30 start: subiquity/Refresh/GET: 2023-11-09 23:49:27,723 DEBUG root:30 finish: subiquity/Refresh/GET: SUCCESS: 200 {"availability": "UNAVAILABLE", "current_snap_version": "0+git.1c719695", "ne... 2023-11-09 23:49:27,724 DEBUG root:30 start: subiquity/Source/GET: 2023-11-09 23:49:27,725 DEBUG root:30 finish: subiquity/Source/GET: SUCCESS: 200 {"sources": [{"name": "Ubuntu Desktop (minimized)", "description": "A minimal... 2023-11-09 23:49:27,725 DEBUG root:30 start: subiquity/Drivers/GET: 2023-11-09 23:49:27,725 DEBUG root:30 finish: subiquity/Drivers/GET: SUCCESS: 200 {"install": false, "drivers": null, "local_only": true, "search_drivers": false} 2023-11-09 23:49:27,726 DEBUG root:30 start: subiquity/Codecs/GET: 2023-11-09 23:49:27,726 DEBUG root:30 finish: subiquity/Codecs/GET: SUCCESS: 200 {"install": false} 2023-11-09 23:49:28,761 DEBUG root:30 start: subiquity/Source/POST: 2023-11-09 23:49:28,761 DEBUG subiquity.models.subiquity:256 model source for install stage is configured, to go {'network', 'filesystem'} 2023-11-09 23:49:28,761 DEBUG subiquity.server.controllers.drivers:89 source variant has been set. Querying list of drivers. 2023-11-09 23:49:28,761 DEBUG root:30 finish: subiquity/Source/POST: SUCCESS: 200 null 2023-11-09 23:49:28,761 DEBUG root:30 start: subiquity/Drivers/POST: 2023-11-09 23:49:28,762 DEBUG subiquity.models.subiquity:256 model drivers for postinstall stage is configured, to go {'network', 'identity', 'timezone', 'codecs'} 2023-11-09 23:49:28,762 DEBUG root:30 finish: subiquity/Drivers/POST: SUCCESS: 200 null 2023-11-09 23:49:28,762 DEBUG root:30 start: subiquity/Codecs/POST: 2023-11-09 23:49:28,762 DEBUG subiquity.models.subiquity:256 model codecs for postinstall stage is configured, to go {'network', 'identity', 'timezone'} 2023-11-09 23:49:28,762 DEBUG root:30 finish: subiquity/Codecs/POST: SUCCESS: 200 null 2023-11-09 23:49:28,763 DEBUG subiquity.server.controllers.filesystem:414 got system None for variation minimal 2023-11-09 23:49:28,763 DEBUG curtin:117 Setting up Layered Source for stack ['///cdrom/casper/minimal.squashfs', '///cdrom/casper/minimal.enhanced-secureboot.squashfs', '///cdrom/casper/minimal.enhanced-secureboot.en.squashfs'] 2023-11-09 23:49:28,763 DEBUG curtin:95 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/minimal.squashfs', '/tmp/tmpxthdjvrd/minimal.squashfs.dir'] with allowed return codes [0] (capture=True) 2023-11-09 23:49:28,777 DEBUG curtin:95 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/minimal.enhanced-secureboot.squashfs', '/tmp/tmpxthdjvrd/minimal.enhanced-secureboot.squashfs.dir'] with allowed return codes [0] (capture=True) 2023-11-09 23:49:28,793 DEBUG curtin:95 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/minimal.enhanced-secureboot.en.squashfs', '/tmp/tmpxthdjvrd/minimal.enhanced-secureboot.en.squashfs.dir'] with allowed return codes [0] (capture=True) 2023-11-09 23:49:28,818 DEBUG curtin:95 Running command ['mount', '-o', 'lowerdir=/tmp/tmpxthdjvrd/minimal.enhanced-secureboot.en.squashfs.dir:/tmp/tmpxthdjvrd/minimal.enhanced-secureboot.squashfs.dir:/tmp/tmpxthdjvrd/minimal.squashfs.dir', '-t', 'overlay', 'overlay', '/tmp/tmpxthdjvrd/root.dir'] with allowed return codes [0] (capture=True) 2023-11-09 23:49:28,834 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', 'mount', '-o', 'bind', '/tmp/tmpxthdjvrd/root.dir/var/lib/snapd/seed/systems', '/var/lib/snapd/seed/systems'] 2023-11-09 23:49:28,842 DEBUG root:30 start: subiquity/Drivers/_list_drivers: 2023-11-09 23:49:28,842 DEBUG root:30 start: subiquity/Drivers/_list_drivers/wait_apt: 2023-11-09 23:49:28,843 DEBUG root:30 start: subiquity/Filesystem/v2_GET: 2023-11-09 23:49:28,852 DEBUG subiquity.server.controllers.filesystem:1487 stop_monitor 2023-11-09 23:49:28,852 DEBUG subiquitycore.utils:79 run_command called: ['udevadm', 'settle', '-t', '0'] 2023-11-09 23:49:28,888 DEBUG subiquitycore.utils:98 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0 2023-11-09 23:49:28,888 DEBUG subiquity.server.controllers.filesystem:1499 Triggered Probert run on udev event 2023-11-09 23:49:28,888 DEBUG root:30 start: subiquity/Filesystem/_probe: 2023-11-09 23:49:28,888 DEBUG root:30 start: subiquity/Filesystem/_probe/probe_once: restricted=False 2023-11-09 23:49:28,889 DEBUG asyncio:54 Using selector: EpollSelector 2023-11-09 23:49:28,895 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', 'mount', '-o', 'bind', '/tmp/tmpxthdjvrd/root.dir/var/lib/snapd/seed/snaps/pc-kernel_1500.snap', '/var/lib/snapd/seed/snaps/pc-kernel_1500.snap'] 2023-11-09 23:49:28,947 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', 'mount', '-o', 'bind', '/tmp/tmpxthdjvrd/root.dir/var/lib/snapd/seed/snaps/pc_161.snap', '/var/lib/snapd/seed/snaps/pc_161.snap'] 2023-11-09 23:49:29,014 DEBUG probert.dasd:134 Probing DASD devies 2023-11-09 23:49:29,014 DEBUG probert.dasd:137 DASD devices only present on s390x, arch=x86_64 2023-11-09 23:49:29,023 ERROR probert.multipath:38 Failed to run cmd: ['multipathd', 'show', 'maps', 'raw', 'format', '%w,%d,%N'] 2023-11-09 23:49:29,024 ERROR probert.multipath:38 Failed to run cmd: ['multipathd', 'show', 'paths', 'raw', 'format', '%d,%z,%m,%N,%n,%R,%r,%a'] 2023-11-09 23:49:29,405 DEBUG curtin:1325 Extracting storage config from probe data 2023-11-09 23:49:29,406 DEBUG curtin:73 /dev/sr0 is multipath device member? False 2023-11-09 23:49:29,406 DEBUG curtin:86 /dev/sr0 is multipath device partition? False 2023-11-09 23:49:29,406 DEBUG curtin:73 /dev/sda is multipath device member? False 2023-11-09 23:49:29,406 DEBUG curtin:86 /dev/sda is multipath device partition? False 2023-11-09 23:49:29,406 DEBUG curtin:61 /dev/sda is multipath device? False 2023-11-09 23:49:29,406 DEBUG curtin:86 /dev/sda is multipath device partition? False 2023-11-09 23:49:29,406 DEBUG curtin:61 /dev/sda is multipath device? False 2023-11-09 23:49:29,428 DEBUG curtin:73 /dev/sr0 is multipath device member? False 2023-11-09 23:49:29,429 DEBUG curtin:1332 Sorting extracted configurations 2023-11-09 23:49:29,429 INFO curtin:1351 Validating extracted storage config components 2023-11-09 23:49:29,449 DEBUG curtin:1368 Extracted (unmerged) storage config: storage: - id: disk-sda path: /dev/sda serial: QEMU_HARDDISK_QM00003 type: disk 2023-11-09 23:49:29,449 DEBUG curtin:1372 Generating storage config dependencies 2023-11-09 23:49:29,449 DEBUG curtin:1378 Merging storage config dependencies 2023-11-09 23:49:29,450 DEBUG curtin:1383 Merged storage config: storage: config: - id: disk-sda path: /dev/sda serial: QEMU_HARDDISK_QM00003 type: disk version: 2 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1463 majmin_to_dev {'8:0': Disk(serial='QEMU_HARDDISK_QM00003', path='/dev/sda', preserve=True, id='disk-sda', type='disk')} 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 0:28 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 0:22 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 0:23 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 0:5 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 0:25 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 11:0 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 7:0 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 0:28 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 0:45 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 7:3 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 7:6 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 7:4 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 7:5 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 7:7 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 7:8 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 7:11 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 7:12 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 7:10 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 7:9 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 0:28 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 0:89 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 0:89 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 0:89 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 0:26 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 0:6 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 0:35 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 0:36 2023-11-09 23:49:29,450 DEBUG subiquity.models.filesystem:1475 considering mount of 0:37 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:7 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:12 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:21 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:40 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:38 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:24 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:33 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:39 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:20 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:34 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:41 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:42 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:43 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:25 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:46 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:48 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:90 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 7:3 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 7:6 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 7:4 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 7:5 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 7:7 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 7:8 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 7:11 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 7:12 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 7:10 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 7:9 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 7:0 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 7:13 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 7:14 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:89 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:51 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:4 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:4 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:4 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:4 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:63 2023-11-09 23:49:29,451 DEBUG subiquity.models.filesystem:1475 considering mount of 0:91 2023-11-09 23:49:29,451 DEBUG root:30 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False 2023-11-09 23:49:29,451 DEBUG subiquity.server.controllers.filesystem:1297 block probing took 0.6 seconds 2023-11-09 23:49:29,451 DEBUG subiquity.server.controllers.filesystem:1474 start_monitor 2023-11-09 23:49:29,452 DEBUG root:30 finish: subiquity/Filesystem/_probe: SUCCESS: 2023-11-09 23:49:30,930 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/systems/enhanced-secureboot-desktop HTTP/1.1" 200 None 2023-11-09 23:49:30,931 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', 'umount', '/var/lib/snapd/seed/snaps/pc_161.snap'] 2023-11-09 23:49:30,972 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', 'umount', '/var/lib/snapd/seed/snaps/pc-kernel_1500.snap'] 2023-11-09 23:49:31,008 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', 'umount', '/var/lib/snapd/seed/systems'] 2023-11-09 23:49:31,056 DEBUG curtin:95 Running command ['umount', '/tmp/tmpxthdjvrd/root.dir'] with allowed return codes [0] (capture=True) 2023-11-09 23:49:31,059 DEBUG curtin:95 Running command ['umount', '/tmp/tmpxthdjvrd/minimal.enhanced-secureboot.en.squashfs.dir'] with allowed return codes [0] (capture=True) 2023-11-09 23:49:31,063 DEBUG curtin:95 Running command ['umount', '/tmp/tmpxthdjvrd/minimal.enhanced-secureboot.squashfs.dir'] with allowed return codes [0] (capture=True) 2023-11-09 23:49:31,093 DEBUG curtin:95 Running command ['umount', '/tmp/tmpxthdjvrd/minimal.squashfs.dir'] with allowed return codes [0] (capture=True) 2023-11-09 23:49:31,097 DEBUG subiquity.server.controllers.filesystem:344 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=3, 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)], update=VolumeUpdate(edition=2, 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=, storage_safety=, encryption_type=, unavailable_reason='')) 2023-11-09 23:49:31,097 DEBUG subiquity.server.controllers.filesystem:414 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=3, 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)], update=VolumeUpdate(edition=2, 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=, storage_safety=, encryption_type=, unavailable_reason='')) for variation minimal-enhanced-secureboot 2023-11-09 23:49:31,098 DEBUG subiquity.server.controllers.filesystem:996 suggested install minimum size: 8.330G 2023-11-09 23:49:31,111 DEBUG root:30 finish: subiquity/Filesystem/v2_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-sda", "label"... 2023-11-09 23:49:31,112 DEBUG subiquity.server.controllers.filesystem:1487 stop_monitor 2023-11-09 23:49:31,112 DEBUG subiquitycore.utils:79 run_command called: ['udevadm', 'settle', '-t', '0'] 2023-11-09 23:49:31,116 DEBUG subiquitycore.utils:98 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0 2023-11-09 23:49:31,116 DEBUG subiquity.server.controllers.filesystem:1499 Triggered Probert run on udev event 2023-11-09 23:49:31,116 DEBUG root:30 start: subiquity/Filesystem/_probe: 2023-11-09 23:49:31,116 DEBUG root:30 start: subiquity/Filesystem/_probe/probe_once: restricted=False 2023-11-09 23:49:31,117 DEBUG root:30 start: subiquity/Filesystem/v2_GET: 2023-11-09 23:49:31,117 DEBUG asyncio:54 Using selector: EpollSelector 2023-11-09 23:49:31,172 DEBUG probert.dasd:134 Probing DASD devies 2023-11-09 23:49:31,172 DEBUG probert.dasd:137 DASD devices only present on s390x, arch=x86_64 2023-11-09 23:49:31,175 ERROR probert.multipath:38 Failed to run cmd: ['multipathd', 'show', 'maps', 'raw', 'format', '%w,%d,%N'] 2023-11-09 23:49:31,176 ERROR probert.multipath:38 Failed to run cmd: ['multipathd', 'show', 'paths', 'raw', 'format', '%d,%z,%m,%N,%n,%R,%r,%a'] 2023-11-09 23:49:31,479 DEBUG curtin:1325 Extracting storage config from probe data 2023-11-09 23:49:31,479 DEBUG curtin:73 /dev/sr0 is multipath device member? False 2023-11-09 23:49:31,479 DEBUG curtin:86 /dev/sr0 is multipath device partition? False 2023-11-09 23:49:31,480 DEBUG curtin:73 /dev/sda is multipath device member? False 2023-11-09 23:49:31,480 DEBUG curtin:86 /dev/sda is multipath device partition? False 2023-11-09 23:49:31,480 DEBUG curtin:61 /dev/sda is multipath device? False 2023-11-09 23:49:31,480 DEBUG curtin:86 /dev/sda is multipath device partition? False 2023-11-09 23:49:31,480 DEBUG curtin:61 /dev/sda is multipath device? False 2023-11-09 23:49:31,497 DEBUG curtin:73 /dev/sr0 is multipath device member? False 2023-11-09 23:49:31,497 DEBUG curtin:1332 Sorting extracted configurations 2023-11-09 23:49:31,497 INFO curtin:1351 Validating extracted storage config components 2023-11-09 23:49:31,512 DEBUG curtin:1368 Extracted (unmerged) storage config: storage: - id: disk-sda path: /dev/sda serial: QEMU_HARDDISK_QM00003 type: disk 2023-11-09 23:49:31,512 DEBUG curtin:1372 Generating storage config dependencies 2023-11-09 23:49:31,512 DEBUG curtin:1378 Merging storage config dependencies 2023-11-09 23:49:31,512 DEBUG curtin:1383 Merged storage config: storage: config: - id: disk-sda path: /dev/sda serial: QEMU_HARDDISK_QM00003 type: disk version: 2 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1463 majmin_to_dev {'8:0': Disk(serial='QEMU_HARDDISK_QM00003', path='/dev/sda', preserve=True, id='disk-sda', type='disk')} 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 0:28 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 0:22 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 0:23 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 0:5 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 0:25 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 11:0 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 7:0 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 0:28 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 0:45 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 7:3 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 7:6 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 7:4 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 7:5 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 7:7 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 7:8 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 7:11 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 7:12 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 7:10 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 7:9 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 0:28 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 0:26 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 0:6 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 0:35 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 0:36 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 0:37 2023-11-09 23:49:31,513 DEBUG subiquity.models.filesystem:1475 considering mount of 0:7 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:12 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:21 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:40 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:38 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:24 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:33 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:39 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:20 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:34 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:41 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:42 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:43 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:25 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:46 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:48 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:90 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 7:3 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 7:6 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 7:4 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 7:5 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 7:7 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 7:8 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 7:11 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 7:12 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 7:10 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 7:9 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:51 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:4 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:4 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:4 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:4 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:63 2023-11-09 23:49:31,514 DEBUG subiquity.models.filesystem:1475 considering mount of 0:91 2023-11-09 23:49:31,515 DEBUG root:30 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False 2023-11-09 23:49:31,515 DEBUG subiquity.server.controllers.filesystem:1297 block probing took 0.4 seconds 2023-11-09 23:49:31,515 DEBUG subiquity.server.controllers.filesystem:1474 start_monitor 2023-11-09 23:49:31,515 DEBUG root:30 finish: subiquity/Filesystem/_probe: SUCCESS: 2023-11-09 23:49:31,515 DEBUG subiquity.server.controllers.filesystem:996 suggested install minimum size: 8.330G 2023-11-09 23:49:31,516 DEBUG root:30 finish: subiquity/Filesystem/v2_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-sda", "label"... 2023-11-09 23:49:31,517 DEBUG root:30 start: subiquity/Filesystem/v2_guided_GET: 2023-11-09 23:49:31,517 DEBUG subiquity.server.controllers.filesystem:996 suggested install minimum size: 8.330G 2023-11-09 23:49:31,518 DEBUG root:30 finish: subiquity/Filesystem/v2_guided_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "configured": null, "targets": [{"di... 2023-11-09 23:49:31,518 DEBUG root:30 start: subiquity/Filesystem/has_bitlocker_GET: 2023-11-09 23:49:31,519 DEBUG root:30 finish: subiquity/Filesystem/has_bitlocker_GET: SUCCESS: 200 [] 2023-11-09 23:49:34,496 DEBUG root:30 start: subiquity/Filesystem/has_bitlocker_GET: 2023-11-09 23:49:34,496 DEBUG root:30 finish: subiquity/Filesystem/has_bitlocker_GET: SUCCESS: 200 [] 2023-11-09 23:49:34,497 DEBUG root:30 start: subiquity/Filesystem/v2_GET: 2023-11-09 23:49:34,497 DEBUG subiquity.server.controllers.filesystem:996 suggested install minimum size: 8.330G 2023-11-09 23:49:34,498 DEBUG root:30 finish: subiquity/Filesystem/v2_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-sda", "label"... 2023-11-09 23:49:34,499 DEBUG root:30 start: subiquity/Filesystem/v2_guided_GET: 2023-11-09 23:49:34,499 DEBUG subiquity.server.controllers.filesystem:996 suggested install minimum size: 8.330G 2023-11-09 23:49:34,499 DEBUG root:30 finish: subiquity/Filesystem/v2_guided_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "configured": null, "targets": [{"di... 2023-11-09 23:49:34,500 DEBUG root:30 start: subiquity/Filesystem/v2_guided_POST: 2023-11-09 23:49:34,500 DEBUG subiquity.server.controllers.filesystem:1152 GuidedChoiceV2(target=GuidedStorageTargetReformat(disk_id='disk-sda', allowed=[, , , , ], disallowed=[]), capability=, recovery_key=None, sizing_policy=, reset_partition=False) 2023-11-09 23:49:34,501 DEBUG subiquity.models.filesystem:2105 adding fat32 to Partition(device=disk-sda, size=1127219200, wipe='superblock', flag='boot', number=1, grub_device=True, offset=1048576, id='partition-0') 2023-11-09 23:49:34,501 DEBUG subiquity.models.filesystem:2105 adding ext4 to Partition(device=disk-sda, size=31082938368, wipe='superblock', number=2, grub_device=None, offset=1128267776, id='partition-1') 2023-11-09 23:49:34,501 DEBUG subiquity.server.controllers.filesystem:996 suggested install minimum size: 8.330G 2023-11-09 23:49:34,502 DEBUG root:30 finish: subiquity/Filesystem/v2_guided_POST: SUCCESS: 200 {"status": "DONE", "error_report": null, "configured": {"target": {"disk_id":... 2023-11-09 23:49:34,502 DEBUG root:30 start: subiquity/Filesystem/v2_POST: 2023-11-09 23:49:34,502 DEBUG subiquity.models.subiquity:256 model filesystem for install stage is configured, to go {'network'} 2023-11-09 23:49:34,503 DEBUG subiquity.server.controllers.filesystem:1487 stop_monitor 2023-11-09 23:49:34,503 DEBUG subiquity.server.controllers.filesystem:996 suggested install minimum size: 8.330G 2023-11-09 23:49:34,504 DEBUG root:30 finish: subiquity/Filesystem/v2_POST: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-sda", "label"... 2023-11-09 23:49:34,504 DEBUG root:30 start: subiquity/Filesystem/v2_GET: 2023-11-09 23:49:34,504 DEBUG subiquity.server.controllers.filesystem:996 suggested install minimum size: 8.330G 2023-11-09 23:49:34,505 DEBUG root:30 finish: subiquity/Filesystem/v2_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-sda", "label"... 2023-11-09 23:49:34,506 DEBUG root:30 start: subiquity/Filesystem/v2_orig_config_GET: 2023-11-09 23:49:34,506 DEBUG curtin:1325 Extracting storage config from probe data 2023-11-09 23:49:34,506 DEBUG curtin:73 /dev/sr0 is multipath device member? False 2023-11-09 23:49:34,506 DEBUG curtin:86 /dev/sr0 is multipath device partition? False 2023-11-09 23:49:34,506 DEBUG curtin:73 /dev/sda is multipath device member? False 2023-11-09 23:49:34,506 DEBUG curtin:86 /dev/sda is multipath device partition? False 2023-11-09 23:49:34,506 DEBUG curtin:61 /dev/sda is multipath device? False 2023-11-09 23:49:34,507 DEBUG curtin:86 /dev/sda is multipath device partition? False 2023-11-09 23:49:34,507 DEBUG curtin:61 /dev/sda is multipath device? False 2023-11-09 23:49:34,520 DEBUG curtin:73 /dev/sr0 is multipath device member? False 2023-11-09 23:49:34,520 DEBUG curtin:1332 Sorting extracted configurations 2023-11-09 23:49:34,520 INFO curtin:1351 Validating extracted storage config components 2023-11-09 23:49:34,527 DEBUG curtin:1368 Extracted (unmerged) storage config: storage: - id: disk-sda path: /dev/sda serial: QEMU_HARDDISK_QM00003 type: disk 2023-11-09 23:49:34,528 DEBUG curtin:1372 Generating storage config dependencies 2023-11-09 23:49:34,528 DEBUG curtin:1378 Merging storage config dependencies 2023-11-09 23:49:34,528 DEBUG curtin:1383 Merged storage config: storage: config: - id: disk-sda path: /dev/sda serial: QEMU_HARDDISK_QM00003 type: disk version: 2 2023-11-09 23:49:34,528 DEBUG subiquity.models.filesystem:1463 majmin_to_dev {'8:0': Disk(serial='QEMU_HARDDISK_QM00003', path='/dev/sda', preserve=True, id='disk-sda', type='disk')} 2023-11-09 23:49:34,528 DEBUG subiquity.models.filesystem:1475 considering mount of 0:28 2023-11-09 23:49:34,528 DEBUG subiquity.models.filesystem:1475 considering mount of 0:22 2023-11-09 23:49:34,528 DEBUG subiquity.models.filesystem:1475 considering mount of 0:23 2023-11-09 23:49:34,528 DEBUG subiquity.models.filesystem:1475 considering mount of 0:5 2023-11-09 23:49:34,528 DEBUG subiquity.models.filesystem:1475 considering mount of 0:25 2023-11-09 23:49:34,528 DEBUG subiquity.models.filesystem:1475 considering mount of 11:0 2023-11-09 23:49:34,528 DEBUG subiquity.models.filesystem:1475 considering mount of 7:0 2023-11-09 23:49:34,528 DEBUG subiquity.models.filesystem:1475 considering mount of 0:28 2023-11-09 23:49:34,528 DEBUG subiquity.models.filesystem:1475 considering mount of 0:45 2023-11-09 23:49:34,528 DEBUG subiquity.models.filesystem:1475 considering mount of 7:3 2023-11-09 23:49:34,528 DEBUG subiquity.models.filesystem:1475 considering mount of 7:6 2023-11-09 23:49:34,528 DEBUG subiquity.models.filesystem:1475 considering mount of 7:4 2023-11-09 23:49:34,528 DEBUG subiquity.models.filesystem:1475 considering mount of 7:5 2023-11-09 23:49:34,528 DEBUG subiquity.models.filesystem:1475 considering mount of 7:7 2023-11-09 23:49:34,528 DEBUG subiquity.models.filesystem:1475 considering mount of 7:8 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 7:11 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 7:12 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 7:10 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 7:9 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:28 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:26 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:6 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:35 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:36 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:37 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:7 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:12 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:21 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:40 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:38 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:24 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:33 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:39 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:20 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:34 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:41 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:42 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:43 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:25 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:46 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:48 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:90 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 7:3 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 7:6 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 7:4 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 7:5 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 7:7 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 7:8 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 7:11 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 7:12 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 7:10 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 7:9 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:51 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:4 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:4 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:4 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:4 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:63 2023-11-09 23:49:34,529 DEBUG subiquity.models.filesystem:1475 considering mount of 0:91 2023-11-09 23:49:34,530 DEBUG subiquity.server.controllers.filesystem:996 suggested install minimum size: 8.330G 2023-11-09 23:49:34,531 DEBUG root:30 finish: subiquity/Filesystem/v2_orig_config_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-sda", "label"... 2023-11-09 23:49:35,776 DEBUG root:30 start: subiquity/TimeZone/GET: 2023-11-09 23:49:35,776 DEBUG root:30 finish: subiquity/TimeZone/GET: SUCCESS: 200 {"timezone": "Pacific/Auckland", "from_geoip": true} 2023-11-09 23:49:35,980 INFO root:30 start: subiquity/Meta/mark_configured_POST: 2023-11-09 23:49:35,980 DEBUG subiquitycore.models.network:467 has_network True 2023-11-09 23:49:35,980 DEBUG subiquity.models.subiquity:256 model network for install stage is configured, to go set() 2023-11-09 23:49:35,980 DEBUG subiquity.models.subiquity:256 model network for postinstall stage is configured, to go {'identity', 'timezone'} 2023-11-09 23:49:35,980 INFO root:30 finish: subiquity/Meta/mark_configured_POST: SUCCESS: 200 null 2023-11-09 23:49:35,981 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "NEEDS_CONFIRMATION", "confirming_tty": "", "error": null, "cloud_i... 2023-11-09 23:49:35,994 INFO root:30 start: subiquity/Meta/confirm_POST: 2023-11-09 23:49:35,994 DEBUG subiquity.models.subiquity:256 model ssh for postinstall stage is configured, to go {'identity', 'timezone'} 2023-11-09 23:49:35,995 DEBUG subiquity.models.subiquity:256 model snaplist for postinstall stage is configured, to go {'identity', 'timezone'} 2023-11-09 23:49:35,995 INFO root:30 finish: subiquity/Meta/confirm_POST: SUCCESS: 200 null 2023-11-09 23:49:35,995 DEBUG root:30 finish: subiquity/OEM/load_metapackages_list/wait_confirmation: SUCCESS: 2023-11-09 23:49:35,995 DEBUG root:30 start: subiquity/OEM/load_metapackages_list/wait_apt: 2023-11-09 23:49:35,995 INFO root:30 start: subiquity/Install/install/configure_apt: configuring apt 2023-11-09 23:49:35,996 DEBUG root:30 start: subiquity/Mirror/waiting: 2023-11-09 23:49:35,996 DEBUG root:30 finish: subiquity/Mirror/waiting: SUCCESS: 2023-11-09 23:49:35,996 DEBUG subiquity.server.controllers.mirror:202 Iterating over country-mirror 2023-11-09 23:49:35,996 DEBUG curtin:117 Setting up Layered Source for stack ['///cdrom/casper/minimal.squashfs', '///cdrom/casper/minimal.en.squashfs'] 2023-11-09 23:49:35,996 DEBUG curtin:95 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/minimal.squashfs', '/tmp/tmpvdqi7t4x/minimal.squashfs.dir'] with allowed return codes [0] (capture=True) 2023-11-09 23:49:36,005 DEBUG curtin:95 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/minimal.en.squashfs', '/tmp/tmpvdqi7t4x/minimal.en.squashfs.dir'] with allowed return codes [0] (capture=True) 2023-11-09 23:49:36,014 DEBUG curtin:95 Running command ['mount', '-o', 'lowerdir=/tmp/tmpvdqi7t4x/minimal.en.squashfs.dir:/tmp/tmpvdqi7t4x/minimal.squashfs.dir', '-t', 'overlay', 'overlay', '/tmp/tmpvdqi7t4x/root.dir'] with allowed return codes [0] (capture=True) 2023-11-09 23:49:36,017 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', 'mount', '-o', 'lowerdir=/tmp/tmpvdqi7t4x/root.dir,upperdir=/tmp/tmpcc8xjyui/upper,workdir=/tmp/tmpcc8xjyui/work', '-t', 'overlay', 'overlay', '/tmp/tmpcc8xjyui/mount'] 2023-11-09 23:49:36,022 INFO root:30 start: subiquity/Meta/status_GET: 2023-11-09 23:49:36,023 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini... 2023-11-09 23:49:36,031 INFO root:30 start: subiquity/Meta/status_GET: 2023-11-09 23:49:36,061 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', '/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1883.1"}}', '-c', '/var/log/installer/subiquity-curtin-apt.conf', 'apt-config', '-t', '/tmp/tmpcc8xjyui/mount'] 2023-11-09 23:49:37,493 DEBUG root:30 start: subiquity/Mirror/cmd-apt-config: curtin command apt-config 2023-11-09 23:49:37,890 DEBUG subiquity.server.curtin:130 waited 0.1 seconds for events to drain 2023-11-09 23:49:37,991 DEBUG subiquity.server.curtin:130 waited 0.2 seconds for events to drain 2023-11-09 23:49:38,091 DEBUG subiquity.server.curtin:130 waited 0.30000000000000004 seconds for events to drain 2023-11-09 23:49:38,159 DEBUG root:30 finish: subiquity/Mirror/cmd-apt-config: SUCCESS: curtin command apt-config 2023-11-09 23:49:38,192 DEBUG subiquity.server.curtin:130 waited 0.4 seconds for events to drain 2023-11-09 23:49:38,195 DEBUG subiquitycore.utils:154 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-11-09 23:49:39,868 DEBUG root:30 start: subiquity/TimeZone/POST: 2023-11-09 23:49:40,080 DEBUG subiquity.models.subiquity:256 model timezone for postinstall stage is configured, to go {'identity'} 2023-11-09 23:49:40,080 DEBUG root:30 finish: subiquity/TimeZone/POST: SUCCESS: 200 null 2023-11-09 23:49:40,081 DEBUG root:30 start: subiquity/Identity/GET: 2023-11-09 23:49:40,081 DEBUG root:30 finish: subiquity/Identity/GET: SUCCESS: 200 {"realname": "", "username": "", "crypted_password": "", "hostname": ""} 2023-11-09 23:49:40,085 DEBUG root:30 start: subiquity/Ad/has_support_GET: 2023-11-09 23:49:40,086 DEBUG root:30 finish: subiquity/Ad/has_support_GET: SUCCESS: 200 true 2023-11-09 23:49:41,415 DEBUG subiquity.server.controllers.mirror:176 Mirror checking successful 2023-11-09 23:49:41,415 DEBUG subiquity.server.controllers.mirror:178 APT output follows 2023-11-09 23:49:41,415 DEBUG subiquity.server.controllers.mirror:180 Get:1 http://nz.archive.ubuntu.com/ubuntu noble InRelease [240 kB] 2023-11-09 23:49:41,415 DEBUG subiquity.server.controllers.mirror:180 Hit:2 http://nz.archive.ubuntu.com/ubuntu noble-updates InRelease 2023-11-09 23:49:41,415 DEBUG subiquity.server.controllers.mirror:180 Get:3 http://nz.archive.ubuntu.com/ubuntu noble-backports InRelease [74.9 kB] 2023-11-09 23:49:41,415 DEBUG subiquity.server.controllers.mirror:180 Fetched 315 kB in 1s (398 kB/s) 2023-11-09 23:49:41,415 DEBUG subiquity.server.controllers.mirror:180 Reading package lists... 2023-11-09 23:49:41,415 DEBUG curtin:117 Setting up Layered Source for stack ['///cdrom/casper/minimal.squashfs', '///cdrom/casper/minimal.en.squashfs'] 2023-11-09 23:49:41,416 DEBUG curtin:95 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/minimal.squashfs', '/tmp/tmp4f3u8tiv/minimal.squashfs.dir'] with allowed return codes [0] (capture=True) 2023-11-09 23:49:41,433 DEBUG curtin:95 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/minimal.en.squashfs', '/tmp/tmp4f3u8tiv/minimal.en.squashfs.dir'] with allowed return codes [0] (capture=True) 2023-11-09 23:49:41,443 DEBUG curtin:95 Running command ['mount', '-o', 'lowerdir=/tmp/tmp4f3u8tiv/minimal.en.squashfs.dir:/tmp/tmp4f3u8tiv/minimal.squashfs.dir', '-t', 'overlay', 'overlay', '/tmp/tmp4f3u8tiv/root.dir'] with allowed return codes [0] (capture=True) 2023-11-09 23:49:41,453 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', 'mount', '-o', 'lowerdir=/tmp/tmp4f3u8tiv/root.dir,upperdir=/tmp/tmpxq3n_gpt/upper,workdir=/tmp/tmpxq3n_gpt/work', '-t', 'overlay', 'overlay', '/tmp/tmpxq3n_gpt/mount'] 2023-11-09 23:49:41,492 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', '/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1883.2"}}', '-c', '/var/log/installer/subiquity-curtin-apt.conf', 'apt-config', '-t', '/tmp/tmpxq3n_gpt/mount'] 2023-11-09 23:49:42,589 DEBUG root:30 start: subiquity/Mirror/cmd-apt-config: curtin command apt-config 2023-11-09 23:49:42,881 DEBUG root:30 finish: subiquity/Mirror/cmd-apt-config: SUCCESS: curtin command apt-config 2023-11-09 23:49:42,884 DEBUG root:30 start: subiquity/Identity/validate_username_GET: 2023-11-09 23:49:42,884 DEBUG root:30 finish: subiquity/Identity/validate_username_GET: SUCCESS: 200 "OK" 2023-11-09 23:49:42,933 DEBUG subiquity.server.curtin:130 waited 0.1 seconds for events to drain 2023-11-09 23:49:42,933 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', 'mount', '-o', 'lowerdir=/tmp/tmpxq3n_gpt/upper:/tmp/tmp4f3u8tiv/root.dir,upperdir=/tmp/tmp9w2s5_jl/upper,workdir=/tmp/tmp9w2s5_jl/work', '-t', 'overlay', 'overlay', '/tmp/tmp9w2s5_jl/mount'] 2023-11-09 23:49:43,001 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', 'mount', '-o', 'bind', '/cdrom', '/tmp/tmp9w2s5_jl/mount/cdrom'] 2023-11-09 23:49:43,051 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', '/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1883.3"}}', 'in-target', '-t', '/tmp/tmp9w2s5_jl/mount', '--', 'apt-get', 'update'] 2023-11-09 23:49:43,359 DEBUG root:30 start: subiquity/Identity/validate_username_GET: 2023-11-09 23:49:43,359 DEBUG root:30 finish: subiquity/Identity/validate_username_GET: SUCCESS: 200 "OK" 2023-11-09 23:49:43,489 DEBUG root:30 start: subiquity/Identity/validate_username_GET: 2023-11-09 23:49:43,489 DEBUG root:30 finish: subiquity/Identity/validate_username_GET: SUCCESS: 200 "OK" 2023-11-09 23:49:43,744 DEBUG root:30 start: subiquity/Identity/validate_username_GET: 2023-11-09 23:49:43,745 DEBUG root:30 finish: subiquity/Identity/validate_username_GET: SUCCESS: 200 "OK" 2023-11-09 23:49:44,004 DEBUG root:30 start: subiquity/Install/install/configure_apt/cmd-in-target: curtin command in-target 2023-11-09 23:49:58,475 DEBUG subiquity.server.curtin:130 waited 0.1 seconds for events to drain 2023-11-09 23:49:58,575 DEBUG subiquity.server.curtin:130 waited 0.2 seconds for events to drain 2023-11-09 23:49:58,659 DEBUG root:30 finish: subiquity/Install/install/configure_apt/cmd-in-target: SUCCESS: curtin command in-target 2023-11-09 23:49:58,676 DEBUG subiquity.server.curtin:130 waited 0.30000000000000004 seconds for events to drain 2023-11-09 23:49:58,676 INFO root:30 finish: subiquity/Install/install/configure_apt: SUCCESS: configuring apt 2023-11-09 23:49:58,677 INFO root:30 start: subiquity/Install/install/curtin_install: installing system 2023-11-09 23:49:58,677 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step: executing curtin install initial step 2023-11-09 23:49:58,679 DEBUG root:30 finish: subiquity/Drivers/_list_drivers/wait_apt: SUCCESS: 2023-11-09 23:49:58,679 DEBUG root:30 finish: subiquity/Drivers/_list_drivers: SUCCESS: 2023-11-09 23:49:58,679 DEBUG root:30 finish: subiquity/OEM/load_metapackages_list/wait_apt: SUCCESS: 2023-11-09 23:49:58,679 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', 'mount', '-o', 'lowerdir=/tmp/tmp9w2s5_jl/upper:/tmp/tmpxq3n_gpt/upper:/tmp/tmp4f3u8tiv/root.dir,upperdir=/tmp/tmp56aemzde/upper,workdir=/tmp/tmp56aemzde/work', '-t', 'overlay', 'overlay', '/tmp/tmp56aemzde/mount'] 2023-11-09 23:49:58,680 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', '/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1883.4"}}', '-c', '/var/log/installer/curtin-install/subiquity-initial.conf', 'install', '--set', 'json:stages=[]'] 2023-11-09 23:49:58,723 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', 'chroot', '/tmp/tmp56aemzde/mount', 'sh', '-c', 'command -v ubuntu-drivers'] 2023-11-09 23:49:58,740 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--property', 'PrivateMounts=yes', '--pipe', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', '/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1883.5"}}', 'in-target', '-t', '/tmp/tmp56aemzde/mount', '--', 'ubuntu-drivers', 'list-oem'] 2023-11-09 23:49:59,536 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step: SUCCESS: executing curtin install initial step 2023-11-09 23:49:59,536 DEBUG subiquity.models.filesystem:1838 mountpoints {'/boot/efi': 'mount-0', '/': 'mount-1'} 2023-11-09 23:49:59,536 DEBUG subiquity.models.filesystem:1828 cannot emit action to mount /boot/efi until that for / is emitted 2023-11-09 23:49:59,536 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step: executing curtin install partitioning step 2023-11-09 23:49:59,540 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', '/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1883.6"}}', '-c', '/var/log/installer/curtin-install/subiquity-partitioning.conf', 'install', '--set', 'json:stages=["partitioning"]', 'cp:///tmp/tmp9w2s5_jl/mount'] 2023-11-09 23:49:59,909 DEBUG root:30 start: subiquity/OEM/load_metapackages_list/cmd-in-target: curtin command in-target 2023-11-09 23:50:00,909 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install: curtin command install 2023-11-09 23:50:00,909 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning: configuring storage 2023-11-09 23:50:00,909 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin: running 'curtin block-meta simple' 2023-11-09 23:50:01,189 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-11-09 23:50:01,189 DEBUG root:30 finish: subiquity/OEM/load_metapackages_list/cmd-in-target: SUCCESS: curtin command in-target 2023-11-09 23:50:01,217 DEBUG subiquity.server.curtin:130 waited 0.1 seconds for events to drain 2023-11-09 23:50:01,218 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', 'umount', '/tmp/tmp56aemzde/mount'] 2023-11-09 23:50:01,244 DEBUG subiquity.server.controllers.oem:192 OEM meta-packages to install: [] 2023-11-09 23:50:01,244 DEBUG root:30 finish: subiquity/OEM/load_metapackages_list: SUCCESS: 2023-11-09 23:50:01,475 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-11-09 23:50:01,753 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-11-09 23:50:01,754 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta/: configuring disk: disk-sda 2023-11-09 23:50:02,523 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta/: SUCCESS: configuring disk: disk-sda 2023-11-09 23:50:02,526 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-11-09 23:50:02,784 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-11-09 23:50:02,785 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-11-09 23:50:03,205 INFO root:30 start: subiquity/Meta/mark_configured_POST: 2023-11-09 23:50:03,205 DEBUG subiquity.models.subiquity:256 model active_directory for postinstall stage is configured, to go {'identity'} 2023-11-09 23:50:03,205 INFO root:30 finish: subiquity/Meta/mark_configured_POST: SUCCESS: 200 null 2023-11-09 23:50:03,292 DEBUG root:30 start: subiquity/Identity/POST: 2023-11-09 23:50:03,293 DEBUG subiquity.models.subiquity:256 model identity for postinstall stage is configured, to go set() 2023-11-09 23:50:03,293 DEBUG root:30 finish: subiquity/Identity/POST: SUCCESS: 200 null 2023-11-09 23:50:03,494 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-11-09 23:50:03,495 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-11-09 23:50:03,672 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-11-09 23:50:03,672 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring format: format-1 2023-11-09 23:50:04,502 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring format: format-1 2023-11-09 23:50:04,502 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring mount: mount-1 2023-11-09 23:50:04,775 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring mount: mount-1 2023-11-09 23:50:04,775 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-11-09 23:50:04,776 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-11-09 23:50:04,776 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin: SUCCESS: running 'curtin block-meta simple' 2023-11-09 23:50:04,776 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning: SUCCESS: configuring storage 2023-11-09 23:50:04,776 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install: SUCCESS: curtin command install 2023-11-09 23:50:04,777 DEBUG subiquity.server.controllers.filesystem:504 recording path '/dev/sda' for device disk-sda 2023-11-09 23:50:04,777 DEBUG subiquity.server.controllers.filesystem:504 recording path '/dev/sda1' for device partition-0 2023-11-09 23:50:04,777 DEBUG subiquity.server.controllers.filesystem:504 recording path '/dev/sda2' for device partition-1 2023-11-09 23:50:04,777 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step: SUCCESS: executing curtin install partitioning step 2023-11-09 23:50:04,777 DEBUG subiquity.models.subiquity:532 merging config from 2023-11-09 23:50:04,778 DEBUG subiquity.models.subiquity:532 merging config from 2023-11-09 23:50:04,778 DEBUG subiquity.models.filesystem:1838 mountpoints {'/boot/efi': 'mount-0', '/': 'mount-1'} 2023-11-09 23:50:04,778 DEBUG subiquity.models.filesystem:1828 cannot emit action to mount /boot/efi until that for / is emitted 2023-11-09 23:50:04,778 DEBUG subiquity.models.subiquity:532 merging config from 2023-11-09 23:50:04,778 DEBUG subiquity.models.subiquity:532 merging config from 2023-11-09 23:50:04,779 DEBUG subiquity.cloudinit:14 Loaded cloud config from /run/cloud-init/combined-cloud-config.json 2023-11-09 23:50:04,779 DEBUG subiquity.models.subiquity:532 merging config from 2023-11-09 23:50:04,779 DEBUG subiquity.models.subiquity:532 merging config from 2023-11-09 23:50:04,779 DEBUG subiquity.models.subiquity:532 merging config from 2023-11-09 23:50:04,780 DEBUG subiquity.models.subiquity:532 merging config from 2023-11-09 23:50:04,780 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step: executing curtin install extract step 2023-11-09 23:50:04,785 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', '/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1883.7"}}', '-c', '/var/log/installer/curtin-install/subiquity-extract.conf', 'install', '--set', 'json:stages=["extract"]', 'cp:///tmp/tmp9w2s5_jl/mount'] 2023-11-09 23:50:05,809 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install: curtin command install 2023-11-09 23:50:05,809 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-extract: writing install sources to disk 2023-11-09 23:50:05,810 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-extract/builtin: running 'curtin extract' 2023-11-09 23:50:05,810 INFO root:30 start: subiquity/Meta/status_GET: 2023-11-09 23:50:05,811 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini... 2023-11-09 23:50:06,211 INFO root:30 start: subiquity/Meta/status_GET: 2023-11-09 23:50:06,211 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini... 2023-11-09 23:50:06,283 INFO root:30 start: subiquity/Meta/status_GET: 2023-11-09 23:50:06,659 DEBUG root:30 start: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-extract/builtin/cmd-extract: curtin command extract 2023-11-09 23:50:06,659 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/tmp9w2s5_jl/mount 2023-11-09 23:52:30,655 DEBUG subiquity.server.curtin:130 waited 0.1 seconds for events to drain 2023-11-09 23:52:30,756 DEBUG subiquity.server.curtin:130 waited 0.2 seconds for events to drain 2023-11-09 23:52:30,856 DEBUG subiquity.server.curtin:130 waited 0.30000000000000004 seconds for events to drain 2023-11-09 23:52:30,909 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/tmp9w2s5_jl/mount 2023-11-09 23:52:30,909 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-extract/builtin: SUCCESS: running 'curtin extract' 2023-11-09 23:52:30,909 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-extract: SUCCESS: writing install sources to disk 2023-11-09 23:52:30,909 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install: SUCCESS: curtin command install 2023-11-09 23:52:30,957 DEBUG subiquity.server.curtin:130 waited 0.4 seconds for events to drain 2023-11-09 23:52:30,957 DEBUG root:30 finish: subiquity/Install/install/curtin_install/run_curtin_step: SUCCESS: executing curtin install extract step 2023-11-09 23:52:30,958 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', 'mount', '-o', 'bind', '/cdrom', '/target/cdrom'] 2023-11-09 23:52:31,040 DEBUG root:30 start: subiquity/Install/install/curtin_install/setup_target: configuring keyboard 2023-11-09 23:52:31,041 DEBUG subiquitycore.utils:154 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.1883', '--setenv', 'PATH=/snap/ubuntu-desktop-installer/1269/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1269/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1269/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/usr/sbin:/snap/ubuntu-desktop-installer/1269/usr/bin:/snap/ubuntu-desktop-installer/1269/sbin:/snap/ubuntu-desktop-installer/1269/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/1269/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1269/usr/lib/python3/site-packages:', '--setenv', 'PYTHON=/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '--setenv', 'SNAP=/snap/ubuntu-desktop-installer/1269', '--', '/snap/ubuntu-desktop-installer/1269/usr/bin/python3.10', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1883.8"}}', 'in-target', '-t', '/target', '--', 'setupcon', '--save-only'] 2023-11-09 23:52:32,641 DEBUG root:30 start: subiquity/Install/install/curtin_install/setup_target/cmd-in-target: curtin command in-target 2023-11-09 23:52:32,828 DEBUG subiquity.server.curtin:130 waited 0.1 seconds for events to drain 2023-11-09 23:52:32,909 DEBUG root:30 finish: subiquity/Install/install/curtin_install/setup_target/cmd-in-target: SUCCESS: curtin command in-target 2023-11-09 23:52:32,929 DEBUG subiquity.server.curtin:130 waited 0.2 seconds for events to drain 2023-11-09 23:52:32,929 DEBUG root:30 finish: subiquity/Install/install/curtin_install/setup_target: SUCCESS: configuring keyboard 2023-11-09 23:52:32,930 DEBUG subiquitycore.utils:121 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-11-09 23:52:32,934 ERROR root:30 finish: subiquity/Install/install/curtin_install: FAIL: [Errno 2] No such file or directory: 'grep-status' 2023-11-09 23:52:32,934 DEBUG subiquity.common.errorreport:394 generating crash report 2023-11-09 23:52:33,000 INFO subiquity.common.errorreport:415 saving crash report 'install failed crashed with FileNotFoundError' to /var/crash/1699573952.935059309.install_fail.crash 2023-11-09 23:52:33,000 ERROR root:30 finish: subiquity/Install/install: FAIL: [Errno 2] No such file or directory: 'grep-status' 2023-11-09 23:52:33,000 INFO root:30 start: subiquity/ErrorReporter/1699573952.935059309.install_fail/add_info: