2023-08-10 15:53:56,000 INFO subiquity:190 Starting Subiquity server revision 1197 of snap /snap/ubuntu-desktop-installer/1197
2023-08-10 15:53:56,000 INFO subiquity:191 Arguments passed: ['/snap/ubuntu-desktop-installer/1197/bin/subiquity/subiquity/cmd/server.py', '--use-os-prober', '--storage-version=2', '--postinst-hooks-dir=/snap/ubuntu-desktop-installer/1197/etc/subiquity/postinst.d']
2023-08-10 15:53:56,000 DEBUG subiquity:192 Kernel commandline: CommandLineParams(_raw='BOOT_IMAGE=/casper/vmlinuz layerfs-path=minimal.standard.live.squashfs ---\n', _tokens={'---'}, _values={'BOOT_IMAGE': '/casper/vmlinuz', 'layerfs-path': 'minimal.standard.live.squashfs'})
2023-08-10 15:53:56,000 DEBUG subiquity:193 Environment: environ({'SNAP_REVISION': '1197', 'SNAP_REAL_HOME': '/root', 'SNAP_USER_COMMON': '/root/snap/ubuntu-desktop-installer/common', 'PATH_ORIG': '/snap/ubuntu-desktop-installer/1197/usr/sbin:/snap/ubuntu-desktop-installer/1197/usr/bin:/snap/ubuntu-desktop-installer/1197/sbin:/snap/ubuntu-desktop-installer/1197/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/1197/bin/subiquity', 'SYSTEMD_EXEC_PID': '1842', 'SNAP_CONTEXT': 'w-Gy1zrVY6O8BTzq2o6CvmWWgX_lr8oGz3uPl_ZVqC0AsnAScPUB', 'LANG': 'C.UTF-8', 'SNAP_ARCH': 'amd64', 'PY3OR2_PYTHON': '/snap/ubuntu-desktop-installer/1197/usr/bin/python3.10', 'SNAP_INSTANCE_NAME': 'ubuntu-desktop-installer', 'SNAP_USER_DATA': '/root/snap/ubuntu-desktop-installer/1197', 'INVOCATION_ID': '6628bf6cb1114dee98a414b8f2be9308', '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/1197/lib:/snap/ubuntu-desktop-installer/1197/usr/lib:/snap/ubuntu-desktop-installer/1197/lib/x86_64-linux-gnu:/snap/ubuntu-desktop-installer/1197/usr/lib/x86_64-linux-gnu', 'PYTHONPATH_ORIG': '', 'PYTHONPATH': '/snap/ubuntu-desktop-installer/1197/lib/python3.10/site-packages:/snap/ubuntu-desktop-installer/1197/usr/lib/python3/dist-packages:/snap/ubuntu-desktop-installer/1197/usr/lib/python3/site-packages:', 'PYTHON': '/snap/ubuntu-desktop-installer/1197/usr/bin/python3.10', 'PYTHONIOENCODING': 'utf-8', 'SNAP': '/snap/ubuntu-desktop-installer/1197', 'SNAP_COMMON': '/var/snap/ubuntu-desktop-installer/common', 'SNAP_VERSION': '0+git.c24733e4', 'DISPLAY': ':0', 'SHLVL': '1', 'SNAP_LIBRARY_PATH': '/var/lib/snapd/lib/gl:/var/lib/snapd/lib/gl32:/var/lib/snapd/void', 'SNAP_COOKIE': 'w-Gy1zrVY6O8BTzq2o6CvmWWgX_lr8oGz3uPl_ZVqC0AsnAScPUB', 'SNAP_DATA': '/var/snap/ubuntu-desktop-installer/1197', 'LD_LIBRARY_PATH': '/var/lib/snapd/lib/gl:/var/lib/snapd/lib/gl32:/var/lib/snapd/void:/snap/ubuntu-desktop-installer/1197/lib:/snap/ubuntu-desktop-installer/1197/usr/lib:/snap/ubuntu-desktop-installer/1197/lib/x86_64-linux-gnu:/snap/ubuntu-desktop-installer/1197/usr/lib/x86_64-linux-gnu', 'SNAP_NAME': 'ubuntu-desktop-installer', 'JOURNAL_STREAM': '8:23824', 'PATH': '/snap/ubuntu-desktop-installer/1197/bin/subiquity/bin:/snap/ubuntu-desktop-installer/1197/bin/subiquity/usr/bin:/snap/ubuntu-desktop-installer/1197/bin:/snap/ubuntu-desktop-installer/1197/sbin:/snap/ubuntu-desktop-installer/1197/usr/sbin:/snap/ubuntu-desktop-installer/1197/usr/bin:/snap/ubuntu-desktop-installer/1197/sbin:/snap/ubuntu-desktop-installer/1197/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/1197/bin/subiquity', 'OLDPWD': '/var/snap/ubuntu-desktop-installer/1197', '_': '/snap/ubuntu-desktop-installer/1197/usr/bin/python3.10', 'APPORT_DATA_DIR': '/snap/ubuntu-desktop-installer/1197/bin/subiquity/share/apport'})
2023-08-10 15:53:56,000 DEBUG asyncio:54 Using selector: EpollSelector
2023-08-10 15:53:56,001 DEBUG subiquitycore.prober:33 Prober() init finished, data:None
2023-08-10 15:53:56,034 DEBUG curtin:95 Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (capture=True)
2023-08-10 15:53:56,041 DEBUG subiquitycore.netplan:113 config for zz-all-en = {'dhcp4': True, 'match': {'name': 'en*'}}
2023-08-10 15:53:56,041 DEBUG subiquitycore.netplan:113 config for zz-all-eth = {'dhcp4': True, 'match': {'name': 'eth*'}}
2023-08-10 15:53:56,051 DEBUG subiquitycore.utils:118 arun_command called: ['cloud-init', 'status', '--wait']
2023-08-10 15:53:57,910 DEBUG subiquitycore.utils:132 arun_command ['cloud-init', 'status', '--wait'] exited with code 0
2023-08-10 15:53:57,910 DEBUG subiquity.server.server:568 waited 1.8596596717834473s for cloud-init
2023-08-10 15:53:57,911 DEBUG subiquity.cloudinit:14 Loaded cloud config from /run/cloud-init/combined-cloud-config.json
2023-08-10 15:53:57,911 DEBUG subiquity.server.server:552 no autoinstall found in cloud-config
2023-08-10 15:53:57,911 DEBUG subiquitycore.utils:76 run_command called: ['ssh-keygen', '-lf', '/home/installer/.ssh/authorized_keys']
2023-08-10 15:53:57,915 DEBUG subiquitycore.utils:95 run_command ['ssh-keygen', '-lf', '/home/installer/.ssh/authorized_keys'] exited with code 255
2023-08-10 15:53:57,915 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-08-10 15:53:57,915 DEBUG subiquitycore.utils:76 run_command called: chpasswd
2023-08-10 15:53:58,209 DEBUG subiquitycore.utils:95 run_command chpasswd exited with code 0
2023-08-10 15:53:58,250 DEBUG subiquity.server.server:469 load_autoinstall_config only_early True file None
2023-08-10 15:53:58,250 DEBUG subiquity.server.server:469 load_autoinstall_config only_early False file None
2023-08-10 15:53:58,251 DEBUG subiquitycore.core:118 starting controllers
2023-08-10 15:53:58,258 DEBUG subiquity.server.controllers.kernel:66 Using default kernel linux-generic
2023-08-10 15:53:58,265 DEBUG subiquity.models.source:93 loaded 2 sources from '/cdrom/casper/install-sources.yaml'
2023-08-10 15:53:58,266 DEBUG probert.network:585 event for link_change: NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2023-08-10 15:53:58,266 DEBUG probert.network:585 event for link_change: NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'enp1s0'}
2023-08-10 15:53:58,266 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-08-10 15:53:58,266 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 2, 'flags': 512, 'family': 2, 'scope': 0, 'local': b'192.168.122.41/24'}
2023-08-10 15:53:58,266 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2023-08-10 15:53:58,266 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::5054:ff:fe39:9b42/64'}
2023-08-10 15:53:58,266 DEBUG probert.network:672 link_change NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2023-08-10 15:53:58,352 DEBUG subiquitycore.models.network:455 new_link 1 lo lo
2023-08-10 15:53:58,352 DEBUG subiquitycore.models.network:457 ignoring based on type
2023-08-10 15:53:58,352 DEBUG probert.network:672 link_change NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'enp1s0'}
2023-08-10 15:53:58,420 DEBUG subiquitycore.models.network:455 new_link 2 enp1s0 eth
2023-08-10 15:53:58,420 DEBUG subiquitycore.models.network:486 new_link 2 enp1s0 with config {'dhcp4': True}
2023-08-10 15:53:58,420 DEBUG root:30 start: subiquity/Network/_send_update: NEW enp1s0
2023-08-10 15:53:58,420 DEBUG subiquity.server.controllers.network:319 dev_info enp1s0 {'dhcp4': True}
2023-08-10 15:53:58,420 DEBUG root:30 finish: subiquity/Network/_send_update: SUCCESS: NEW enp1s0
2023-08-10 15:53:58,421 DEBUG probert.network:717 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'}
2023-08-10 15:53:58,421 DEBUG probert.network:717 addr_change NEW {'ifindex': 2, 'flags': 512, 'family': 2, 'scope': 0, 'local': b'192.168.122.41/24'}
2023-08-10 15:53:58,421 DEBUG root:30 start: subiquity/Network/_send_update: CHANGE enp1s0
2023-08-10 15:53:58,421 DEBUG subiquity.server.controllers.network:319 dev_info enp1s0 {'dhcp4': True}
2023-08-10 15:53:58,421 DEBUG root:30 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp1s0
2023-08-10 15:53:58,428 DEBUG probert.network:717 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2023-08-10 15:53:58,428 DEBUG probert.network:717 addr_change NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::5054:ff:fe39:9b42/64'}
2023-08-10 15:53:58,428 DEBUG root:30 start: subiquity/Network/_send_update: CHANGE enp1s0
2023-08-10 15:53:58,428 DEBUG subiquity.server.controllers.network:319 dev_info enp1s0 {'dhcp4': True}
2023-08-10 15:53:58,428 DEBUG root:30 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp1s0
2023-08-10 15:53:58,429 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2023-08-10 15:53:58,484 DEBUG pyroute2.ndb.139698235007392.sources.localhost:74 init
2023-08-10 15:53:58,485 DEBUG pyroute2.ndb.139698235007392.sources.localhost:384 starting the source
2023-08-10 15:53:58,485 DEBUG pyroute2.ndb.139698235007392.sources.localhost/nsmanager:74 init
2023-08-10 15:53:58,485 DEBUG pyroute2.ndb.139698235007392.sources.localhost/nsmanager:384 starting the source
2023-08-10 15:53:58,485 DEBUG pyroute2.ndb.139698235007392.sources.localhost:74 connecting
2023-08-10 15:53:58,487 DEBUG pyroute2.ndb.139698235007392.sources.localhost:74 loading
2023-08-10 15:53:58,487 DEBUG pyroute2.ndb.139698235007392.sources.localhost/nsmanager:74 connecting
2023-08-10 15:53:58,497 DEBUG pyroute2.ndb.139698235007392.sources.localhost/nsmanager:74 loading
2023-08-10 15:53:58,522 DEBUG pyroute2.ndb.139698235007392.sources.localhost:74 running
2023-08-10 15:53:58,529 DEBUG pyroute2.ndb.139698235007392.sources.localhost/nsmanager:74 running
2023-08-10 15:53:58,531 DEBUG pyroute2.ndb.139698235007392.sources.localhost:399 source shutdown
2023-08-10 15:53:58,531 DEBUG pyroute2.ndb.139698235007392.sources.localhost:374 sync
2023-08-10 15:53:58,531 DEBUG pyroute2.ndb.139698235007392.sources.localhost:369 shutdown handled by the main thread
2023-08-10 15:53:58,531 DEBUG pyroute2.ndb.139698235007392.sources.localhost:74 stopped
2023-08-10 15:53:58,534 DEBUG pyroute2.ndb.139698235007392.main:851 flush DB for the target localhost
2023-08-10 15:53:58,535 DEBUG pyroute2.ndb.139698235007392.sources.localhost/nsmanager:399 source shutdown
2023-08-10 15:53:58,535 DEBUG pyroute2.ndb.139698235007392.sources.localhost/nsmanager:374 sync
2023-08-10 15:53:58,535 DEBUG pyroute2.ndb.139698235007392.sources.localhost/nsmanager:369 shutdown handled by the main thread
2023-08-10 15:53:58,535 DEBUG pyroute2.ndb.139698235007392.sources.localhost/nsmanager:74 stopped
2023-08-10 15:53:58,547 DEBUG pyroute2.ndb.139698235007392.main:851 flush DB for the target localhost/nsmanager
2023-08-10 15:53:58,548 DEBUG subiquitycore.controllers.network:102 default routes True
2023-08-10 15:53:58,548 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'169.254.0.0/16', 'ifindex': 2}
2023-08-10 15:53:58,549 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'192.168.122.0/24', 'ifindex': 2}
2023-08-10 15:53:58,549 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.0/8', 'ifindex': 1}
2023-08-10 15:53:58,549 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.1', 'ifindex': 1}
2023-08-10 15:53:58,549 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'127.255.255.255', 'ifindex': 1}
2023-08-10 15:53:58,549 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'192.168.122.41', 'ifindex': 2}
2023-08-10 15:53:58,549 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'192.168.122.255', 'ifindex': 2}
2023-08-10 15:53:58,549 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'::1', 'ifindex': 1}
2023-08-10 15:53:58,549 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'fe80::/64', 'ifindex': 2}
2023-08-10 15:53:58,549 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'::1', 'ifindex': 1}
2023-08-10 15:53:58,549 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'fe80::5054:ff:fe39:9b42', 'ifindex': 2}
2023-08-10 15:53:58,549 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 5, 'table': 255, 'dst': b'ff00::/8', 'ifindex': 2}
2023-08-10 15:53:58,590 DEBUG subiquitycore.core:121 controllers started
2023-08-10 15:53:58,590 INFO root:30 start: subiquity/apply_autoinstall_config: 
2023-08-10 15:53:58,590 DEBUG root:30 start: subiquity/Early/apply_autoinstall_config: 
2023-08-10 15:53:58,591 DEBUG root:30 finish: subiquity/Early/apply_autoinstall_config: SUCCESS: 
2023-08-10 15:53:58,592 DEBUG root:30 start: subiquity/Reporting/apply_autoinstall_config: 
2023-08-10 15:53:58,593 DEBUG root:30 finish: subiquity/Reporting/apply_autoinstall_config: SUCCESS: 
2023-08-10 15:53:58,594 DEBUG root:30 start: subiquity/Error/apply_autoinstall_config: 
2023-08-10 15:53:58,594 DEBUG root:30 finish: subiquity/Error/apply_autoinstall_config: SUCCESS: 
2023-08-10 15:53:58,595 DEBUG root:30 start: subiquity/Userdata/apply_autoinstall_config: 
2023-08-10 15:53:58,595 DEBUG root:30 finish: subiquity/Userdata/apply_autoinstall_config: SUCCESS: 
2023-08-10 15:53:58,605 DEBUG subiquity.models.subiquity:252 model userdata for postinstall stage is configured, to go {'ubuntu_pro', 'drivers', 'identity', 'ssh', 'snaplist', 'locale', 'network', 'packages'}
2023-08-10 15:53:58,605 DEBUG root:30 start: subiquity/Package/apply_autoinstall_config: 
2023-08-10 15:53:58,606 DEBUG root:30 finish: subiquity/Package/apply_autoinstall_config: SUCCESS: 
2023-08-10 15:53:58,606 DEBUG subiquity.models.subiquity:252 model packages for postinstall stage is configured, to go {'ubuntu_pro', 'drivers', 'ssh', 'identity', 'snaplist', 'locale', 'network'}
2023-08-10 15:53:58,606 DEBUG root:30 start: subiquity/Debconf/apply_autoinstall_config: 
2023-08-10 15:53:58,606 DEBUG root:30 finish: subiquity/Debconf/apply_autoinstall_config: SUCCESS: 
2023-08-10 15:53:58,607 DEBUG subiquity.models.subiquity:252 model debconf_selections for install stage is configured, to go {'kernel', 'proxy', 'source', 'keyboard', 'network', 'filesystem'}
2023-08-10 15:53:58,607 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping Locale as interactive
2023-08-10 15:53:58,607 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping Refresh as interactive
2023-08-10 15:53:58,607 DEBUG root:30 start: subiquity/Kernel/apply_autoinstall_config: 
2023-08-10 15:53:58,609 DEBUG root:30 finish: subiquity/Kernel/apply_autoinstall_config: SUCCESS: 
2023-08-10 15:53:58,610 DEBUG subiquity.models.subiquity:252 model kernel for install stage is configured, to go {'proxy', 'source', 'keyboard', 'network', 'filesystem'}
2023-08-10 15:53:58,610 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping Integrity as interactive
2023-08-10 15:53:58,610 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping Keyboard as interactive
2023-08-10 15:53:58,610 DEBUG root:30 start: subiquity/Zdev/apply_autoinstall_config: 
2023-08-10 15:53:58,615 DEBUG root:30 finish: subiquity/Zdev/apply_autoinstall_config: SUCCESS: 
2023-08-10 15:53:58,620 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping Source as interactive
2023-08-10 15:53:58,620 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping Network as interactive
2023-08-10 15:53:58,620 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping UbuntuPro as interactive
2023-08-10 15:53:58,620 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping Proxy as interactive
2023-08-10 15:53:58,620 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping Mirror as interactive
2023-08-10 15:53:58,620 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping Filesystem as interactive
2023-08-10 15:53:58,620 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping Identity as interactive
2023-08-10 15:53:58,620 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping SSH as interactive
2023-08-10 15:53:58,620 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping SnapList as interactive
2023-08-10 15:53:58,621 DEBUG root:30 start: subiquity/Ad/apply_autoinstall_config: 
2023-08-10 15:53:58,621 DEBUG root:30 finish: subiquity/Ad/apply_autoinstall_config: SUCCESS: 
2023-08-10 15:53:58,621 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping Codecs as interactive
2023-08-10 15:53:58,621 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping Drivers as interactive
2023-08-10 15:53:58,621 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping OEM as interactive
2023-08-10 15:53:58,621 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping TimeZone as interactive
2023-08-10 15:53:58,621 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping Install as interactive
2023-08-10 15:53:58,621 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping Updates as interactive
2023-08-10 15:53:58,621 DEBUG root:30 start: subiquity/Late/apply_autoinstall_config: 
2023-08-10 15:53:58,622 DEBUG root:30 finish: subiquity/Late/apply_autoinstall_config: SUCCESS: 
2023-08-10 15:53:58,622 DEBUG subiquity.server.server:460 apply_autoinstall_config: skipping Shutdown as interactive
2023-08-10 15:53:58,622 INFO root:30 finish: subiquity/apply_autoinstall_config: SUCCESS: 
2023-08-10 15:53:58,622 DEBUG subiquity.models.subiquity:252 model locale for postinstall stage is configured, to go {'ubuntu_pro', 'drivers', 'ssh', 'identity', 'snaplist', 'network'}
2023-08-10 15:53:58,622 DEBUG root:30 start: subiquity/Refresh/configure_snapd: 
2023-08-10 15:53:58,622 DEBUG root:30 start: subiquity/Refresh/configure_snapd/get_details: 
2023-08-10 15:53:58,640 DEBUG root:30 start: subiquity/Refresh/check_for_update: 
2023-08-10 15:53:58,647 DEBUG root:30 start: subiquity/OEM/load_metapackages_list: 
2023-08-10 15:53:58,648 DEBUG root:30 start: subiquity/OEM/load_metapackages_list/wait_confirmation: 
2023-08-10 15:53:58,648 DEBUG root:30 start: subiquity/Install/install: 
2023-08-10 15:53:58,649 DEBUG subiquity.server.controllers.snaplist:79 loading list of snaps
2023-08-10 15:53:58,662 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/snaps/ubuntu-desktop-installer HTTP/1.1" 200 1612
2023-08-10 15:53:58,799 DEBUG root:30 start: subiquity/Filesystem/_probe: 
2023-08-10 15:53:58,800 DEBUG root:30 start: subiquity/Refresh/check_for_update: 
2023-08-10 15:53:58,800 DEBUG root:30 start: subiquity/SnapList/loader: 
2023-08-10 15:53:58,800 DEBUG root:30 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2023-08-10 15:53:58,809 ERROR root:30 finish: subiquity/Refresh/check_for_update: FAIL: cancelled
2023-08-10 15:53:58,809 DEBUG root:30 start: subiquity/SnapList/loader/list: 
2023-08-10 15:53:58,809 DEBUG asyncio:54 Using selector: EpollSelector
2023-08-10 15:53:58,914 DEBUG root:30 finish: subiquity/Refresh/configure_snapd/get_details: SUCCESS: current version of snap is: '0+git.c24733e4'
2023-08-10 15:53:58,916 DEBUG subiquity.server.controllers.refresh:139 snap tracking , not resetting based on .disk/info
2023-08-10 15:53:58,916 DEBUG root:30 finish: subiquity/Refresh/configure_snapd: SUCCESS: 
2023-08-10 15:53:58,917 ERROR probert.multipath:38 Failed to run cmd: ['multipathd', 'show', 'maps', 'raw', 'format', '%w,%d,%N']
2023-08-10 15:53:58,931 ERROR probert.multipath:38 Failed to run cmd: ['multipathd', 'show', 'paths', 'raw', 'format', '%d,%z,%m,%N,%n,%R,%r,%a']
2023-08-10 15:53:59,498 DEBUG subiquity.server.geoip:124 no CountryCode found in '<?xml version="1.0" encoding="UTF-8"?><Response><Ip>10.172.68.114</Ip><Status>IP NOT FOUND</Status></Response>\n'
2023-08-10 15:53:59,523 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?select=refresh HTTP/1.1" 200 59
2023-08-10 15:53:59,524 DEBUG subiquity.server.controllers.refresh:201 check_for_update received []
2023-08-10 15:53:59,524 DEBUG root:30 finish: subiquity/Refresh/check_for_update: SUCCESS: no new version of snap available
2023-08-10 15:53:59,748 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?section=server HTTP/1.1" 200 None
2023-08-10 15:53:59,749 DEBUG root:30 finish: subiquity/SnapList/loader/list: SUCCESS: 
2023-08-10 15:53:59,750 DEBUG subiquity.server.controllers.snaplist:92 fetched list of 23 snaps
2023-08-10 15:53:59,750 DEBUG root:30 start: subiquity/SnapList/loader/fetch/microk8s: 
2023-08-10 15:54:00,456 DEBUG probert.dasd:134 Probing DASD devies
2023-08-10 15:54:00,456 DEBUG probert.dasd:137 DASD devices only present on s390x, arch=x86_64
2023-08-10 15:54:00,921 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=microk8s HTTP/1.1" 200 None
2023-08-10 15:54:00,936 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/microk8s: SUCCESS: 
2023-08-10 15:54:00,937 DEBUG root:30 start: subiquity/SnapList/loader/fetch/nextcloud: 
2023-08-10 15:54:01,004 DEBUG curtin:1316 Extracting storage config from probe data
2023-08-10 15:54:01,004 DEBUG curtin:73 /dev/vda is multipath device member? False
2023-08-10 15:54:01,004 DEBUG curtin:86 /dev/vda is multipath device partition? False
2023-08-10 15:54:01,004 DEBUG curtin:61 /dev/vda is multipath device? False
2023-08-10 15:54:01,004 DEBUG curtin:86 /dev/vda is multipath device partition? False
2023-08-10 15:54:01,005 DEBUG curtin:61 /dev/vda is multipath device? False
2023-08-10 15:54:01,024 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2023-08-10 15:54:01,024 DEBUG curtin:86 /dev/sr0 is multipath device partition? False
2023-08-10 15:54:01,024 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2023-08-10 15:54:01,024 DEBUG curtin:1323 Sorting extracted configurations
2023-08-10 15:54:01,024 INFO curtin:1342 Validating extracted storage config components
2023-08-10 15:54:01,046 DEBUG curtin:1359 Extracted (unmerged) storage config:
storage:
-   id: disk-vda
    path: /dev/vda
    type: disk

2023-08-10 15:54:01,046 DEBUG curtin:1363 Generating storage config dependencies
2023-08-10 15:54:01,046 DEBUG curtin:1369 Merging storage config dependencies
2023-08-10 15:54:01,046 DEBUG curtin:1374 Merged storage config:
storage:
    config:
    -   id: disk-vda
        path: /dev/vda
        type: disk
    version: 2

2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1307 majmin_to_dev {'252:0': Disk(path='/dev/vda', preserve=True, id='disk-vda', type='disk')}
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:28
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:21
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:22
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:5
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:24
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 11:0
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 7:0
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:44
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 7:4
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:28
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 7:3
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 7:5
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:25
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:6
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:35
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:36
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:37
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:7
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:12
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:20
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:40
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:38
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:23
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:33
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:39
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:19
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:34
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:43
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:41
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:42
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:45
2023-08-10 15:54:01,047 DEBUG subiquity.models.filesystem:1319 considering mount of 0:48
2023-08-10 15:54:01,048 DEBUG subiquity.models.filesystem:1319 considering mount of 0:61
2023-08-10 15:54:01,048 DEBUG subiquity.models.filesystem:1319 considering mount of 7:4
2023-08-10 15:54:01,048 DEBUG subiquity.models.filesystem:1319 considering mount of 7:3
2023-08-10 15:54:01,048 DEBUG subiquity.models.filesystem:1319 considering mount of 7:5
2023-08-10 15:54:01,048 DEBUG subiquity.models.filesystem:1319 considering mount of 0:46
2023-08-10 15:54:01,048 DEBUG root:30 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False
2023-08-10 15:54:01,048 DEBUG subiquity.server.controllers.filesystem:1177 block probing took 2.2 seconds
2023-08-10 15:54:01,048 DEBUG root:30 finish: subiquity/Filesystem/_probe: SUCCESS: 
2023-08-10 15:54:01,500 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=nextcloud HTTP/1.1" 200 None
2023-08-10 15:54:01,503 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/nextcloud: SUCCESS: 
2023-08-10 15:54:01,503 DEBUG root:30 start: subiquity/SnapList/loader/fetch/wekan: 
2023-08-10 15:54:01,923 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=wekan HTTP/1.1" 200 None
2023-08-10 15:54:01,924 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/wekan: SUCCESS: 
2023-08-10 15:54:01,924 DEBUG root:30 start: subiquity/SnapList/loader/fetch/kata-containers: 
2023-08-10 15:54:02,284 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=kata-containers HTTP/1.1" 200 None
2023-08-10 15:54:02,285 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/kata-containers: SUCCESS: 
2023-08-10 15:54:02,285 DEBUG root:30 start: subiquity/SnapList/loader/fetch/docker: 
2023-08-10 15:54:02,599 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=docker HTTP/1.1" 200 None
2023-08-10 15:54:02,600 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/docker: SUCCESS: 
2023-08-10 15:54:02,600 DEBUG root:30 start: subiquity/SnapList/loader/fetch/canonical-livepatch: 
2023-08-10 15:54:03,130 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=canonical-livepatch HTTP/1.1" 200 None
2023-08-10 15:54:03,131 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/canonical-livepatch: SUCCESS: 
2023-08-10 15:54:03,131 DEBUG root:30 start: subiquity/SnapList/loader/fetch/rocketchat-server: 
2023-08-10 15:54:03,462 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=rocketchat-server HTTP/1.1" 200 None
2023-08-10 15:54:03,463 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/rocketchat-server: SUCCESS: 
2023-08-10 15:54:03,463 DEBUG root:30 start: subiquity/SnapList/loader/fetch/mosquitto: 
2023-08-10 15:54:03,766 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=mosquitto HTTP/1.1" 200 None
2023-08-10 15:54:03,767 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/mosquitto: SUCCESS: 
2023-08-10 15:54:03,767 DEBUG root:30 start: subiquity/SnapList/loader/fetch/etcd: 
2023-08-10 15:54:04,503 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=etcd HTTP/1.1" 200 None
2023-08-10 15:54:04,505 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/etcd: SUCCESS: 
2023-08-10 15:54:04,505 DEBUG root:30 start: subiquity/SnapList/loader/fetch/powershell: 
2023-08-10 15:54:04,749 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=powershell HTTP/1.1" 200 None
2023-08-10 15:54:04,750 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/powershell: SUCCESS: 
2023-08-10 15:54:04,751 DEBUG root:30 start: subiquity/SnapList/loader/fetch/stress-ng: 
2023-08-10 15:54:05,077 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=stress-ng HTTP/1.1" 200 None
2023-08-10 15:54:05,078 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/stress-ng: SUCCESS: 
2023-08-10 15:54:05,078 DEBUG root:30 start: subiquity/SnapList/loader/fetch/sabnzbd: 
2023-08-10 15:54:05,584 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=sabnzbd HTTP/1.1" 200 None
2023-08-10 15:54:05,585 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/sabnzbd: SUCCESS: 
2023-08-10 15:54:05,585 DEBUG root:30 start: subiquity/SnapList/loader/fetch/wormhole: 
2023-08-10 15:54:05,871 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=wormhole HTTP/1.1" 200 None
2023-08-10 15:54:05,872 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/wormhole: SUCCESS: 
2023-08-10 15:54:05,872 DEBUG root:30 start: subiquity/SnapList/loader/fetch/aws-cli: 
2023-08-10 15:54:06,152 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=aws-cli HTTP/1.1" 200 None
2023-08-10 15:54:06,153 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/aws-cli: SUCCESS: 
2023-08-10 15:54:06,153 DEBUG root:30 start: subiquity/SnapList/loader/fetch/google-cloud-sdk: 
2023-08-10 15:54:06,481 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=google-cloud-sdk HTTP/1.1" 200 1799
2023-08-10 15:54:06,482 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/google-cloud-sdk: SUCCESS: 
2023-08-10 15:54:06,482 DEBUG root:30 start: subiquity/SnapList/loader/fetch/slcli: 
2023-08-10 15:54:06,991 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=slcli HTTP/1.1" 200 None
2023-08-10 15:54:06,992 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/slcli: SUCCESS: 
2023-08-10 15:54:06,992 DEBUG root:30 start: subiquity/SnapList/loader/fetch/doctl: 
2023-08-10 15:54:07,249 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=doctl HTTP/1.1" 200 None
2023-08-10 15:54:07,250 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/doctl: SUCCESS: 
2023-08-10 15:54:07,251 DEBUG root:30 start: subiquity/SnapList/loader/fetch/conjure-up: 
2023-08-10 15:54:07,559 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=conjure-up HTTP/1.1" 200 None
2023-08-10 15:54:07,560 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/conjure-up: SUCCESS: 
2023-08-10 15:54:07,560 DEBUG root:30 start: subiquity/SnapList/loader/fetch/postgresql10: 
2023-08-10 15:54:07,841 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=postgresql10 HTTP/1.1" 200 1523
2023-08-10 15:54:07,842 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/postgresql10: SUCCESS: 
2023-08-10 15:54:07,842 DEBUG root:30 start: subiquity/SnapList/loader/fetch/heroku: 
2023-08-10 15:54:08,184 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=heroku HTTP/1.1" 200 None
2023-08-10 15:54:08,185 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/heroku: SUCCESS: 
2023-08-10 15:54:08,185 DEBUG root:30 start: subiquity/SnapList/loader/fetch/keepalived: 
2023-08-10 15:54:08,594 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=keepalived HTTP/1.1" 200 None
2023-08-10 15:54:08,595 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/keepalived: SUCCESS: 
2023-08-10 15:54:08,595 DEBUG root:30 start: subiquity/SnapList/loader/fetch/prometheus: 
2023-08-10 15:54:09,078 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=prometheus HTTP/1.1" 200 None
2023-08-10 15:54:09,079 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/prometheus: SUCCESS: 
2023-08-10 15:54:09,079 DEBUG root:30 start: subiquity/SnapList/loader/fetch/juju: 
2023-08-10 15:54:09,557 DEBUG urllib3.connectionpool:452 http://localhost:None "GET /v2/find?name=juju HTTP/1.1" 200 None
2023-08-10 15:54:09,558 DEBUG root:30 finish: subiquity/SnapList/loader/fetch/juju: SUCCESS: 
2023-08-10 15:54:09,558 DEBUG root:30 finish: subiquity/SnapList/loader: SUCCESS: 
2023-08-10 15:55:37,348 DEBUG subiquity.server.controllers.integrity:61 casper-md5check results: {'checksum_missmatch': [], 'result': 'pass'}
2023-08-10 16:03:01,187 DEBUG subiquitycore.utils:76 run_command called: ['udevadm', 'settle', '-t', '0']
2023-08-10 16:03:01,259 DEBUG subiquitycore.utils:95 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2023-08-10 16:03:01,259 DEBUG subiquity.server.controllers.filesystem:1370 _udev_event change Device('/sys/devices/pci0000:00/0000:00:02.3/0000:04:00.0/virtio2/block/vda')
2023-08-10 16:03:01,259 DEBUG subiquity.server.controllers.filesystem:1370 _udev_event change Device('/sys/devices/virtual/block/loop1')
2023-08-10 16:03:01,259 DEBUG subiquity.server.controllers.filesystem:1370 _udev_event change Device('/sys/devices/virtual/block/loop7')
2023-08-10 16:03:01,259 DEBUG subiquity.server.controllers.filesystem:1370 _udev_event change Device('/sys/devices/virtual/block/loop6')
2023-08-10 16:03:01,259 DEBUG subiquity.server.controllers.filesystem:1370 _udev_event change Device('/sys/devices/virtual/block/loop2')
2023-08-10 16:03:01,259 DEBUG subiquity.server.controllers.filesystem:1370 _udev_event change Device('/sys/devices/virtual/block/loop0')
2023-08-10 16:03:01,259 DEBUG subiquity.server.controllers.filesystem:1370 _udev_event change Device('/sys/devices/virtual/block/loop5')
2023-08-10 16:03:01,260 DEBUG subiquity.server.controllers.filesystem:1370 _udev_event change Device('/sys/devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sr0')
2023-08-10 16:03:01,260 DEBUG subiquity.server.controllers.filesystem:1370 _udev_event change Device('/sys/devices/virtual/block/loop4')
2023-08-10 16:03:01,260 DEBUG subiquity.server.controllers.filesystem:1370 _udev_event change Device('/sys/devices/virtual/block/loop3')
2023-08-10 16:03:01,260 DEBUG subiquity.server.controllers.filesystem:1353 Triggered Probert run on udev event
2023-08-10 16:03:01,260 DEBUG root:30 start: subiquity/Filesystem/_probe: 
2023-08-10 16:03:01,260 DEBUG root:30 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2023-08-10 16:03:01,270 DEBUG asyncio:54 Using selector: EpollSelector
2023-08-10 16:03:01,273 ERROR probert.multipath:38 Failed to run cmd: ['multipathd', 'show', 'maps', 'raw', 'format', '%w,%d,%N']
2023-08-10 16:03:01,274 ERROR probert.multipath:38 Failed to run cmd: ['multipathd', 'show', 'paths', 'raw', 'format', '%d,%z,%m,%N,%n,%R,%r,%a']
2023-08-10 16:03:01,691 DEBUG probert.dasd:134 Probing DASD devies
2023-08-10 16:03:01,691 DEBUG probert.dasd:137 DASD devices only present on s390x, arch=x86_64
2023-08-10 16:03:01,701 DEBUG curtin:1316 Extracting storage config from probe data
2023-08-10 16:03:01,701 DEBUG curtin:73 /dev/vda is multipath device member? False
2023-08-10 16:03:01,701 DEBUG curtin:86 /dev/vda is multipath device partition? False
2023-08-10 16:03:01,701 DEBUG curtin:61 /dev/vda is multipath device? False
2023-08-10 16:03:01,701 DEBUG curtin:86 /dev/vda is multipath device partition? False
2023-08-10 16:03:01,701 DEBUG curtin:61 /dev/vda is multipath device? False
2023-08-10 16:03:01,716 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2023-08-10 16:03:01,716 DEBUG curtin:86 /dev/sr0 is multipath device partition? False
2023-08-10 16:03:01,716 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2023-08-10 16:03:01,716 DEBUG curtin:1323 Sorting extracted configurations
2023-08-10 16:03:01,716 INFO curtin:1342 Validating extracted storage config components
2023-08-10 16:03:01,731 DEBUG curtin:1359 Extracted (unmerged) storage config:
storage:
-   id: disk-vda
    path: /dev/vda
    type: disk

2023-08-10 16:03:01,731 DEBUG curtin:1363 Generating storage config dependencies
2023-08-10 16:03:01,731 DEBUG curtin:1369 Merging storage config dependencies
2023-08-10 16:03:01,732 DEBUG curtin:1374 Merged storage config:
storage:
    config:
    -   id: disk-vda
        path: /dev/vda
        type: disk
    version: 2

2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1307 majmin_to_dev {'252:0': Disk(path='/dev/vda', preserve=True, id='disk-vda', type='disk')}
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:28
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:21
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:22
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:5
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:24
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 11:0
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 7:0
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:44
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 7:4
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:28
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 7:3
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 7:5
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:25
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:6
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:35
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:36
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:37
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:7
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:12
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:20
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:40
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:38
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:23
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:33
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:39
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:19
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:34
2023-08-10 16:03:01,732 DEBUG subiquity.models.filesystem:1319 considering mount of 0:43
2023-08-10 16:03:01,733 DEBUG subiquity.models.filesystem:1319 considering mount of 0:41
2023-08-10 16:03:01,733 DEBUG subiquity.models.filesystem:1319 considering mount of 0:42
2023-08-10 16:03:01,733 DEBUG subiquity.models.filesystem:1319 considering mount of 0:45
2023-08-10 16:03:01,733 DEBUG subiquity.models.filesystem:1319 considering mount of 0:48
2023-08-10 16:03:01,733 DEBUG subiquity.models.filesystem:1319 considering mount of 0:61
2023-08-10 16:03:01,733 DEBUG subiquity.models.filesystem:1319 considering mount of 7:4
2023-08-10 16:03:01,733 DEBUG subiquity.models.filesystem:1319 considering mount of 7:3
2023-08-10 16:03:01,733 DEBUG subiquity.models.filesystem:1319 considering mount of 7:5
2023-08-10 16:03:01,733 DEBUG subiquity.models.filesystem:1319 considering mount of 0:46
2023-08-10 16:03:01,733 DEBUG subiquity.models.filesystem:1319 considering mount of 0:62
2023-08-10 16:03:01,733 DEBUG subiquity.models.filesystem:1319 considering mount of 0:69
2023-08-10 16:03:01,733 DEBUG root:30 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False
2023-08-10 16:03:01,733 DEBUG subiquity.server.controllers.filesystem:1177 block probing took 0.5 seconds
2023-08-10 16:03:01,733 DEBUG root:30 finish: subiquity/Filesystem/_probe: SUCCESS: 
2023-08-10 16:03:04,273 INFO root:30 start: subiquity/Meta/status_GET: 
2023-08-10 16:03:04,273 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2023-08-10 16:03:04,273 INFO aiohttp.access:206  [10/Aug/2023:16:03:04 +0000] "GET /meta/status HTTP/1.1" 200 412 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:04,281 INFO root:30 start: subiquity/Meta/client_variant_POST: 
2023-08-10 16:03:04,281 INFO root:30 finish: subiquity/Meta/client_variant_POST: SUCCESS: 200 null
2023-08-10 16:03:04,281 INFO aiohttp.access:206  [10/Aug/2023:16:03:04 +0000] "POST /meta/client_variant?variant=%22desktop%22 HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:04,283 INFO root:30 start: subiquity/Meta/status_GET: 
2023-08-10 16:03:04,283 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2023-08-10 16:03:04,283 INFO aiohttp.access:206  [10/Aug/2023:16:03:04 +0000] "GET /meta/status HTTP/1.1" 200 412 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:04,284 INFO root:30 start: subiquity/Meta/mark_configured_POST: 
2023-08-10 16:03:04,284 DEBUG subiquity.models.subiquity:252 model ubuntu_pro for postinstall stage is configured, to go {'timezone', 'drivers', 'ssh', 'identity', 'snaplist', 'codecs', 'network'}
2023-08-10 16:03:04,284 DEBUG subiquity.models.subiquity:252 model proxy for install stage is configured, to go {'source', 'mirror', 'keyboard', 'network', 'filesystem'}
2023-08-10 16:03:04,284 DEBUG subiquity.models.subiquity:252 model mirror for install stage is configured, to go {'source', 'network', 'filesystem', 'keyboard'}
2023-08-10 16:03:04,284 DEBUG subiquity.models.subiquity:252 model ssh for postinstall stage is configured, to go {'timezone', 'drivers', 'identity', 'snaplist', 'codecs', 'network'}
2023-08-10 16:03:04,284 DEBUG subiquity.models.subiquity:252 model snaplist for postinstall stage is configured, to go {'timezone', 'drivers', 'identity', 'codecs', 'network'}
2023-08-10 16:03:04,285 INFO root:30 finish: subiquity/Meta/mark_configured_POST: SUCCESS: 200 null
2023-08-10 16:03:04,285 INFO aiohttp.access:206  [10/Aug/2023:16:03:04 +0000] "POST /meta/mark_configured?endpoint_names=%5B%22mirror%22%2C%22proxy%22%2C%22ssh%22%2C%22snaplist%22%2C%22ubuntu_pro%22%5D HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:04,455 DEBUG root:30 start: subiquity/Refresh/GET: 
2023-08-10 16:03:04,455 DEBUG root:30 finish: subiquity/Refresh/GET: SUCCESS: 200 {"availability": "UNAVAILABLE", "current_snap_version": "0+git.c24733e4", "ne...
2023-08-10 16:03:04,455 INFO aiohttp.access:206  [10/Aug/2023:16:03:04 +0000] "GET /refresh?wait=true HTTP/1.1" 200 284 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:04,853 INFO root:30 start: subiquity/Meta/status_GET: 
2023-08-10 16:03:04,853 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2023-08-10 16:03:04,854 INFO aiohttp.access:206  [10/Aug/2023:16:03:04 +0000] "GET /meta/status HTTP/1.1" 200 412 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:04,854 INFO root:30 start: subiquity/Meta/status_GET: 
2023-08-10 16:03:04,854 INFO root:30 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2023-08-10 16:03:04,854 INFO aiohttp.access:206  [10/Aug/2023:16:03:04 +0000] "GET /meta/status HTTP/1.1" 200 412 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:04,854 INFO root:30 start: subiquity/Meta/status_GET: 
2023-08-10 16:03:04,855 INFO root:30 start: subiquity/Meta/interactive_sections_GET: 
2023-08-10 16:03:04,855 INFO root:30 finish: subiquity/Meta/interactive_sections_GET: SUCCESS: 200 null
2023-08-10 16:03:04,855 INFO aiohttp.access:206  [10/Aug/2023:16:03:04 +0000] "GET /meta/interactive_sections HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:04,865 DEBUG root:30 start: subiquity/Locale/GET: 
2023-08-10 16:03:04,865 DEBUG root:30 finish: subiquity/Locale/GET: SUCCESS: 200 "C.UTF-8"
2023-08-10 16:03:04,866 INFO aiohttp.access:206  [10/Aug/2023:16:03:04 +0000] "GET /locale HTTP/1.1" 200 195 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:13,576 DEBUG root:30 start: subiquity/Locale/POST: 
2023-08-10 16:03:13,576 DEBUG subiquity.server.controllers.locale:68 en_US.UTF-8
2023-08-10 16:03:13,577 DEBUG subiquity.models.subiquity:252 model locale for postinstall stage is configured, to go {'timezone', 'drivers', 'identity', 'codecs', 'network'}
2023-08-10 16:03:13,577 DEBUG root:30 finish: subiquity/Locale/POST: SUCCESS: 200 null
2023-08-10 16:03:13,577 INFO aiohttp.access:206  [10/Aug/2023:16:03:13 +0000] "POST /locale HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:13,577 DEBUG subiquitycore.utils:118 arun_command called: ['localectl', 'set-locale', 'en_US.UTF-8']
2023-08-10 16:03:13,583 DEBUG root:30 start: subiquity/Filesystem/has_rst_GET: 
2023-08-10 16:03:13,584 DEBUG root:30 finish: subiquity/Filesystem/has_rst_GET: SUCCESS: 200 false
2023-08-10 16:03:13,584 INFO aiohttp.access:206  [10/Aug/2023:16:03:13 +0000] "GET /storage/has_rst HTTP/1.1" 200 191 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:13,585 DEBUG root:30 start: subiquity/Keyboard/GET: 
2023-08-10 16:03:13,603 DEBUG root:30 finish: subiquity/Keyboard/GET: SUCCESS: 200 {"setting": {"layout": "us", "variant": "", "toggle": null}, "layouts": [{"co...
2023-08-10 16:03:13,608 INFO aiohttp.access:206  [10/Aug/2023:16:03:13 +0000] "GET /keyboard HTTP/1.1" 200 41538 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:13,618 DEBUG root:30 start: subiquity/Keyboard/GET: 
2023-08-10 16:03:13,628 DEBUG root:30 finish: subiquity/Keyboard/GET: SUCCESS: 200 {"setting": {"layout": "us", "variant": "", "toggle": null}, "layouts": [{"co...
2023-08-10 16:03:13,628 INFO aiohttp.access:206  [10/Aug/2023:16:03:13 +0000] "GET /keyboard HTTP/1.1" 200 41538 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:13,634 DEBUG root:30 start: subiquity/Keyboard/input_source_POST: 
2023-08-10 16:03:13,637 DEBUG subiquitycore.utils:118 arun_command called: ['systemd-run', '--wait', '--uid=1000', '--setenv=DISPLAY=:0', '--setenv=XDG_RUNTIME_DIR=/run/user/1000', '--setenv=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus', '--', 'gsettings', 'set', 'org.gnome.desktop.input-sources', 'sources', "[('xkb','us')]"]
2023-08-10 16:03:14,334 DEBUG subiquitycore.utils:132 arun_command ['localectl', 'set-locale', 'en_US.UTF-8'] exited with code 0
2023-08-10 16:03:14,338 DEBUG subiquitycore.utils:132 arun_command ['systemd-run', '--wait', '--uid=1000', '--setenv=DISPLAY=:0', '--setenv=XDG_RUNTIME_DIR=/run/user/1000', '--setenv=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus', '--', 'gsettings', 'set', 'org.gnome.desktop.input-sources', 'sources', "[('xkb','us')]"] exited with code 0
2023-08-10 16:03:14,338 DEBUG root:30 finish: subiquity/Keyboard/input_source_POST: SUCCESS: 200 null
2023-08-10 16:03:14,338 INFO aiohttp.access:206  [10/Aug/2023:16:03:13 +0000] "POST /keyboard/input_source?user=%22ubuntu%22 HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:16,957 DEBUG root:30 start: subiquity/Keyboard/POST: 
2023-08-10 16:03:16,957 DEBUG subiquity.server.controllers.keyboard:221 KeyboardSetting(layout='us', variant='', toggle=None)
2023-08-10 16:03:16,957 DEBUG subiquity.models.subiquity:252 model keyboard for install stage is configured, to go {'source', 'network', 'filesystem'}
2023-08-10 16:03:16,958 DEBUG root:30 finish: subiquity/Keyboard/POST: SUCCESS: 200 null
2023-08-10 16:03:16,958 INFO aiohttp.access:206  [10/Aug/2023:16:03:16 +0000] "POST /keyboard HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:21,552 INFO root:30 start: subiquity/Meta/mark_configured_POST: 
2023-08-10 16:03:21,552 DEBUG subiquitycore.models.network:447 has_network True
2023-08-10 16:03:21,552 DEBUG subiquity.models.subiquity:252 model network for install stage is configured, to go {'source', 'filesystem'}
2023-08-10 16:03:21,552 DEBUG subiquity.models.subiquity:252 model network for postinstall stage is configured, to go {'timezone', 'codecs', 'identity', 'drivers'}
2023-08-10 16:03:21,552 INFO root:30 finish: subiquity/Meta/mark_configured_POST: SUCCESS: 200 null
2023-08-10 16:03:21,553 INFO aiohttp.access:206  [10/Aug/2023:16:03:21 +0000] "POST /meta/mark_configured?endpoint_names=%5B%22network%22%5D HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:21,554 DEBUG root:30 start: subiquity/Refresh/GET: 
2023-08-10 16:03:21,554 DEBUG root:30 finish: subiquity/Refresh/GET: SUCCESS: 200 {"availability": "UNAVAILABLE", "current_snap_version": "0+git.c24733e4", "ne...
2023-08-10 16:03:21,554 INFO aiohttp.access:206  [10/Aug/2023:16:03:21 +0000] "GET /refresh?wait=true HTTP/1.1" 200 284 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:21,555 DEBUG root:30 start: subiquity/Source/GET: 
2023-08-10 16:03:21,556 DEBUG root:30 finish: subiquity/Source/GET: SUCCESS: 200 {"sources": [{"name": "Ubuntu Desktop (minimized)", "description": "A minimal...
2023-08-10 16:03:21,556 INFO aiohttp.access:206  [10/Aug/2023:16:03:21 +0000] "GET /source HTTP/1.1" 200 606 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:21,557 DEBUG root:30 start: subiquity/Drivers/GET: 
2023-08-10 16:03:21,557 DEBUG root:30 finish: subiquity/Drivers/GET: SUCCESS: 200 {"install": false, "drivers": null, "local_only": false, "search_drivers": fa...
2023-08-10 16:03:21,557 INFO aiohttp.access:206  [10/Aug/2023:16:03:21 +0000] "GET /drivers HTTP/1.1" 200 268 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:21,558 DEBUG root:30 start: subiquity/Codecs/GET: 
2023-08-10 16:03:21,558 DEBUG root:30 finish: subiquity/Codecs/GET: SUCCESS: 200 {"install": false}
2023-08-10 16:03:21,558 INFO aiohttp.access:206  [10/Aug/2023:16:03:21 +0000] "GET /codecs HTTP/1.1" 200 205 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:26,074 DEBUG root:30 start: subiquity/Source/POST: 
2023-08-10 16:03:26,075 DEBUG subiquity.models.subiquity:252 model source for install stage is configured, to go {'filesystem'}
2023-08-10 16:03:26,075 DEBUG subiquity.server.controllers.drivers:88 source variant has been set. Querying list of drivers.
2023-08-10 16:03:26,075 DEBUG root:30 finish: subiquity/Source/POST: SUCCESS: 200 null
2023-08-10 16:03:26,076 INFO aiohttp.access:206  [10/Aug/2023:16:03:26 +0000] "POST /source?source_id=%22ubuntu-desktop%22 HTTP/1.1" 200 190 "-" "Dart/3.0 (dart:io)"
2023-08-10 16:03:26,076 DEBUG subiquity.server.controllers.filesystem:374 got system None for variation classic
2023-08-10 16:03:26,077 DEBUG root:30 start: subiquity/Drivers/_list_drivers: 
2023-08-10 16:03:26,077 DEBUG root:30 start: subiquity/Drivers/_list_drivers/wait_apt: 
2023-08-10 16:03:26,077 ERROR subiquity.server.server:414 top level error
Traceback (most recent call last):
  File "/snap/ubuntu-desktop-installer/1197/usr/lib/python3.10/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/snap/ubuntu-desktop-installer/1197/bin/subiquity/subiquitycore/async_helpers.py", line 25, in _done
    fut.result()
  File "/snap/ubuntu-desktop-installer/1197/bin/subiquity/subiquity/server/controllers/filesystem.py", line 373, in _examine_systems
    system = await self._get_system(name, label)
  File "/snap/ubuntu-desktop-installer/1197/bin/subiquity/subiquity/server/controllers/filesystem.py", line 298, in _get_system
    await self._mount_systems_dir(variation_name)
  File "/snap/ubuntu-desktop-installer/1197/bin/subiquity/subiquity/server/controllers/filesystem.py", line 268, in _mount_systems_dir
    source_path = self._source_handler.setup()
  File "/snap/ubuntu-desktop-installer/1197/lib/python3.10/site-packages/curtin/commands/extract.py", line 122, in setup
    raise ValueError(
ValueError: Failed to use fsimage: '///cdrom/casper/minimal.standard.enhanced-secureboot.en.squashfs' doesn't exist or is invalid
2023-08-10 16:03:26,083 DEBUG subiquity.common.errorreport:394 generating crash report
2023-08-10 16:03:26,086 INFO subiquity.common.errorreport:415 saving crash report 'unknown error crashed with ValueError' to /var/crash/1691683406.083851337.unknown.crash
2023-08-10 16:03:26,086 INFO root:30 start: subiquity/ErrorReporter/1691683406.083851337.unknown/add_info: