2022-11-24 15:39:44,630 INFO subiquity:152 Starting Subiquity server revision 4003
2022-11-24 15:39:44,630 INFO subiquity:153 Arguments passed: ['/snap/subiquity/4003/lib/python3.8/site-packages/subiquity/cmd/server.py']
2022-11-24 15:39:44,630 DEBUG subiquity:154 Kernel commandline: CommandLineParams(_raw='BOOT_IMAGE=/casper/vmlinuz ---\n', _tokens={'---'}, _values={'BOOT_IMAGE': '/casper/vmlinuz'})
2022-11-24 15:39:44,630 DEBUG subiquity:155 Storage version: 1
2022-11-24 15:39:44,630 DEBUG asyncio:59 Using selector: EpollSelector
2022-11-24 15:39:44,630 DEBUG subiquitycore.prober:34 Prober() init finished, data:None
2022-11-24 15:39:44,639 DEBUG curtin:87 Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (capture=True)
2022-11-24 15:39:44,643 DEBUG subiquitycore.netplan:109 config for zz-all-en = {'dhcp4': True, 'match': {'name': 'en*'}}
2022-11-24 15:39:44,643 DEBUG subiquitycore.netplan:109 config for zz-all-eth = {'dhcp4': True, 'match': {'name': 'eth*'}}
2022-11-24 15:39:44,646 DEBUG subiquitycore.utils:92 arun_command called: ['cloud-init', 'status', '--wait']
2022-11-24 15:39:45,097 DEBUG subiquitycore.utils:101 arun_command ['cloud-init', 'status', '--wait'] exited with code 0
2022-11-24 15:39:45,097 DEBUG subiquity.server.server:530 waited 0.4511265754699707s for cloud-init
2022-11-24 15:39:45,098 DEBUG subiquity.server.server:532 loading cloud config
2022-11-24 15:39:45,098 DEBUG cloudinit.util:1474 Reading from /etc/cloud/cloud.cfg (quiet=False)
2022-11-24 15:39:45,098 DEBUG cloudinit.util:1485 Read 3487 bytes from /etc/cloud/cloud.cfg
2022-11-24 15:39:45,098 DEBUG cloudinit.util:903 Attempting to load yaml from string of length 3487 with allowed root types (<class 'dict'>,)
2022-11-24 15:39:45,103 DEBUG cloudinit.util:1474 Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2022-11-24 15:39:45,104 DEBUG cloudinit.util:1485 Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2022-11-24 15:39:45,104 DEBUG cloudinit.util:903 Attempting to load yaml from string of length 314 with allowed root types (<class 'dict'>,)
2022-11-24 15:39:45,104 DEBUG cloudinit.util:1474 Reading from /etc/cloud/cloud.cfg.d/06_quiet.cfg (quiet=False)
2022-11-24 15:39:45,104 DEBUG cloudinit.util:1485 Read 112 bytes from /etc/cloud/cloud.cfg.d/06_quiet.cfg
2022-11-24 15:39:45,104 DEBUG cloudinit.util:903 Attempting to load yaml from string of length 112 with allowed root types (<class 'dict'>,)
2022-11-24 15:39:45,105 DEBUG cloudinit.util:1474 Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2022-11-24 15:39:45,105 DEBUG cloudinit.util:1485 Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2022-11-24 15:39:45,105 DEBUG cloudinit.util:903 Attempting to load yaml from string of length 2070 with allowed root types (<class 'dict'>,)
2022-11-24 15:39:45,108 DEBUG cloudinit.util:1474 Reading from /run/cloud-init/cloud.cfg (quiet=False)
2022-11-24 15:39:45,108 DEBUG cloudinit.util:1485 Read 35 bytes from /run/cloud-init/cloud.cfg
2022-11-24 15:39:45,108 DEBUG cloudinit.util:903 Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2022-11-24 15:39:45,108 DEBUG cloudinit.subp:245 Running command ['systemd-detect-virt', '--quiet', '--container'] with allowed return codes [0] (shell=False, capture=True)
2022-11-24 15:39:45,116 DEBUG cloudinit.util:1474 Reading from /etc/os-release (quiet=False)
2022-11-24 15:39:45,116 DEBUG cloudinit.util:1485 Read 386 bytes from /etc/os-release
2022-11-24 15:39:45,117 DEBUG cloudinit.util:1474 Reading from /proc/1/environ (quiet=False)
2022-11-24 15:39:45,117 DEBUG cloudinit.util:1485 Read 266 bytes from /proc/1/environ
2022-11-24 15:39:45,117 DEBUG cloudinit.util:1474 Reading from /proc/self/status (quiet=False)
2022-11-24 15:39:45,117 DEBUG cloudinit.util:1485 Read 1390 bytes from /proc/self/status
2022-11-24 15:39:45,117 DEBUG cloudinit.util:1474 Reading from /proc/cmdline (quiet=False)
2022-11-24 15:39:45,117 DEBUG cloudinit.util:1485 Read 31 bytes from /proc/cmdline
2022-11-24 15:39:45,117 DEBUG cloudinit.util:903 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2022-11-24 15:39:45,117 DEBUG cloudinit.util:911 loaded blob returned None, returning default.
2022-11-24 15:39:45,117 DEBUG cloudinit.util:1474 Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2022-11-24 15:39:45,117 DEBUG cloudinit.util:1485 Read 0 bytes from /var/lib/cloud/instance/cloud-config.txt
2022-11-24 15:39:45,117 DEBUG cloudinit.util:903 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2022-11-24 15:39:45,117 DEBUG cloudinit.util:911 loaded blob returned None, returning default.
2022-11-24 15:39:45,118 DEBUG cloudinit.util:1474 Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
2022-11-24 15:39:45,118 DEBUG cloudinit.util:1485 Read 7460 bytes from /var/lib/cloud/instance/obj.pkl
2022-11-24 15:39:45,124 DEBUG cloudinit.util:1474 Reading from /run/cloud-init/.instance-id (quiet=False)
2022-11-24 15:39:45,124 DEBUG cloudinit.util:1485 Read 8 bytes from /run/cloud-init/.instance-id
2022-11-24 15:39:45,124 DEBUG cloudinit.stages:315 restored from cache with run check: DataSourceNoCloud [seed=/var/lib/cloud/seed/nocloud][dsmode=net]
2022-11-24 15:39:45,124 DEBUG cloudinit.util:1474 Reading from /etc/cloud/cloud.cfg (quiet=False)
2022-11-24 15:39:45,124 DEBUG cloudinit.util:1485 Read 3487 bytes from /etc/cloud/cloud.cfg
2022-11-24 15:39:45,124 DEBUG cloudinit.util:903 Attempting to load yaml from string of length 3487 with allowed root types (<class 'dict'>,)
2022-11-24 15:39:45,128 DEBUG cloudinit.util:1474 Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2022-11-24 15:39:45,128 DEBUG cloudinit.util:1485 Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2022-11-24 15:39:45,128 DEBUG cloudinit.util:903 Attempting to load yaml from string of length 314 with allowed root types (<class 'dict'>,)
2022-11-24 15:39:45,128 DEBUG cloudinit.util:1474 Reading from /etc/cloud/cloud.cfg.d/06_quiet.cfg (quiet=False)
2022-11-24 15:39:45,128 DEBUG cloudinit.util:1485 Read 112 bytes from /etc/cloud/cloud.cfg.d/06_quiet.cfg
2022-11-24 15:39:45,128 DEBUG cloudinit.util:903 Attempting to load yaml from string of length 112 with allowed root types (<class 'dict'>,)
2022-11-24 15:39:45,129 DEBUG cloudinit.util:1474 Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2022-11-24 15:39:45,129 DEBUG cloudinit.util:1485 Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2022-11-24 15:39:45,129 DEBUG cloudinit.util:903 Attempting to load yaml from string of length 2070 with allowed root types (<class 'dict'>,)
2022-11-24 15:39:45,130 DEBUG cloudinit.util:1474 Reading from /run/cloud-init/cloud.cfg (quiet=False)
2022-11-24 15:39:45,130 DEBUG cloudinit.util:1485 Read 35 bytes from /run/cloud-init/cloud.cfg
2022-11-24 15:39:45,130 DEBUG cloudinit.util:903 Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2022-11-24 15:39:45,130 DEBUG cloudinit.util:903 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2022-11-24 15:39:45,130 DEBUG cloudinit.util:911 loaded blob returned None, returning default.
2022-11-24 15:39:45,130 DEBUG cloudinit.util:1474 Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2022-11-24 15:39:45,130 DEBUG cloudinit.util:1485 Read 0 bytes from /var/lib/cloud/instance/cloud-config.txt
2022-11-24 15:39:45,130 DEBUG cloudinit.util:903 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2022-11-24 15:39:45,130 DEBUG cloudinit.util:911 loaded blob returned None, returning default.
2022-11-24 15:39:45,130 DEBUG cloudinit.stages:136 Using distro class <class 'cloudinit.distros.ubuntu.Distro'>
2022-11-24 15:39:45,131 DEBUG subiquity.server.server:477 load_autoinstall_config only_early True file None
2022-11-24 15:39:45,131 DEBUG subiquity.server.server:477 load_autoinstall_config only_early False file None
2022-11-24 15:39:45,131 DEBUG subiquitycore.core:120 starting controllers
2022-11-24 15:39:45,131 DEBUG subiquity.server.controllers.kernel:66 Using kernel linux-generic due to /run/kernel-meta-package
2022-11-24 15:39:45,132 DEBUG subiquity.models.source:87 loaded 2 sources from '/cdrom/casper/install-sources.yaml'
2022-11-24 15:39:45,135 DEBUG probert.network:585 event for link_change: NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2022-11-24 15:39:45,135 DEBUG probert.network:585 event for link_change: NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'enp14s0'}
2022-11-24 15:39:45,135 DEBUG probert.network:585 event for link_change: NEW {'ifindex': 3, 'flags': 4099, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'wlp15s0'}
2022-11-24 15:39:45,135 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'}
2022-11-24 15:39:45,135 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'10.30.0.20/24'}
2022-11-24 15:39:45,135 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2022-11-24 15:39:45,135 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::da5e:d3ff:fee4:94f8/64'}
2022-11-24 15:39:45,135 DEBUG probert.network:672 link_change NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2022-11-24 15:39:45,179 DEBUG subiquitycore.models.network:435 new_link 1 lo lo
2022-11-24 15:39:45,179 DEBUG subiquitycore.models.network:437 ignoring based on type
2022-11-24 15:39:45,179 DEBUG probert.network:672 link_change NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'enp14s0'}
2022-11-24 15:39:45,212 DEBUG subiquitycore.models.network:435 new_link 2 enp14s0 eth
2022-11-24 15:39:45,212 DEBUG subiquitycore.models.network:466 new_link 2 enp14s0 with config {'dhcp4': True}
2022-11-24 15:39:45,212 DEBUG root:37 start: subiquity/Network/_send_update: NEW enp14s0
2022-11-24 15:39:45,212 DEBUG subiquity.server.controllers.network:354 dev_info enp14s0 {'dhcp4': True}
2022-11-24 15:39:45,212 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: NEW enp14s0
2022-11-24 15:39:45,212 DEBUG probert.network:672 link_change NEW {'ifindex': 3, 'flags': 4099, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'wlp15s0'}
2022-11-24 15:39:45,240 DEBUG subiquitycore.models.network:435 new_link 3 wlp15s0 wlan
2022-11-24 15:39:45,240 DEBUG subiquitycore.models.network:466 new_link 3 wlp15s0 with config {}
2022-11-24 15:39:45,240 DEBUG subiquity.server.controllers.network:118 maybe_start_install_wpasupplicant
2022-11-24 15:39:45,240 DEBUG probert.network:717 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'}
2022-11-24 15:39:45,240 DEBUG probert.network:717 addr_change NEW {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'10.30.0.20/24'}
2022-11-24 15:39:45,240 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE enp14s0
2022-11-24 15:39:45,240 DEBUG subiquity.server.controllers.network:354 dev_info enp14s0 {'dhcp4': True}
2022-11-24 15:39:45,240 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp14s0
2022-11-24 15:39:45,240 DEBUG probert.network:717 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2022-11-24 15:39:45,240 DEBUG probert.network:717 addr_change NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::da5e:d3ff:fee4:94f8/64'}
2022-11-24 15:39:45,240 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE enp14s0
2022-11-24 15:39:45,240 DEBUG subiquity.server.controllers.network:354 dev_info enp14s0 {'dhcp4': True}
2022-11-24 15:39:45,240 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp14s0
2022-11-24 15:39:45,240 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2022-11-24 15:39:45,240 DEBUG subiquitycore.controllers.network:94 default routes {2}
2022-11-24 15:39:45,240 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'10.30.0.0/24', 'ifindex': 2}
2022-11-24 15:39:45,240 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'10.30.0.1', 'ifindex': 2}
2022-11-24 15:39:45,240 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'10.30.0.20', 'ifindex': 2}
2022-11-24 15:39:45,240 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'10.30.0.255', 'ifindex': 2}
2022-11-24 15:39:45,240 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.0/8', 'ifindex': 1}
2022-11-24 15:39:45,240 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.1', 'ifindex': 1}
2022-11-24 15:39:45,240 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'127.255.255.255', 'ifindex': 1}
2022-11-24 15:39:45,240 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'::1', 'ifindex': 1}
2022-11-24 15:39:45,240 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'fe80::/64', 'ifindex': 2}
2022-11-24 15:39:45,240 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'::1', 'ifindex': 1}
2022-11-24 15:39:45,240 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'fe80::da5e:d3ff:fee4:94f8', 'ifindex': 2}
2022-11-24 15:39:45,240 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 5, 'table': 255, 'dst': b'ff00::/8', 'ifindex': 2}
2022-11-24 15:39:45,240 DEBUG probert.network:741 wlan_event {'cmd': 'NEW_INTERFACE', 'ifindex': 3, 'ssids': []}
2022-11-24 15:39:45,269 DEBUG subiquitycore.core:123 controllers started
2022-11-24 15:39:45,269 INFO root:37 start: subiquity/apply_autoinstall_config: 
2022-11-24 15:39:45,269 DEBUG root:37 start: subiquity/Early/apply_autoinstall_config: 
2022-11-24 15:39:45,270 DEBUG root:37 finish: subiquity/Early/apply_autoinstall_config: SUCCESS: 
2022-11-24 15:39:45,270 DEBUG root:37 start: subiquity/Reporting/apply_autoinstall_config: 
2022-11-24 15:39:45,270 DEBUG root:37 finish: subiquity/Reporting/apply_autoinstall_config: SUCCESS: 
2022-11-24 15:39:45,270 DEBUG root:37 start: subiquity/Error/apply_autoinstall_config: 
2022-11-24 15:39:45,270 DEBUG root:37 finish: subiquity/Error/apply_autoinstall_config: SUCCESS: 
2022-11-24 15:39:45,270 DEBUG root:37 start: subiquity/Userdata/apply_autoinstall_config: 
2022-11-24 15:39:45,270 DEBUG root:37 finish: subiquity/Userdata/apply_autoinstall_config: SUCCESS: 
2022-11-24 15:39:45,270 DEBUG subiquity.models.subiquity:231 model userdata for postinstall stage is configured, to go {'snaplist', 'identity', 'packages', 'ssh', 'drivers', 'network', 'ubuntu_pro', 'locale'}
2022-11-24 15:39:45,270 DEBUG root:37 start: subiquity/Package/apply_autoinstall_config: 
2022-11-24 15:39:45,270 DEBUG root:37 finish: subiquity/Package/apply_autoinstall_config: SUCCESS: 
2022-11-24 15:39:45,270 DEBUG subiquity.models.subiquity:231 model packages for postinstall stage is configured, to go {'snaplist', 'identity', 'ssh', 'drivers', 'network', 'ubuntu_pro', 'locale'}
2022-11-24 15:39:45,270 DEBUG root:37 start: subiquity/Debconf/apply_autoinstall_config: 
2022-11-24 15:39:45,270 DEBUG root:37 finish: subiquity/Debconf/apply_autoinstall_config: SUCCESS: 
2022-11-24 15:39:45,270 DEBUG subiquity.models.subiquity:231 model debconf_selections for install stage is configured, to go {'source', 'kernel', 'network', 'mirror', 'proxy', 'filesystem', 'keyboard'}
2022-11-24 15:39:45,270 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping Locale as interactive
2022-11-24 15:39:45,270 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping Refresh as interactive
2022-11-24 15:39:45,270 DEBUG root:37 start: subiquity/Kernel/apply_autoinstall_config: 
2022-11-24 15:39:45,270 DEBUG root:37 finish: subiquity/Kernel/apply_autoinstall_config: SUCCESS: 
2022-11-24 15:39:45,271 DEBUG subiquity.models.subiquity:231 model kernel for install stage is configured, to go {'source', 'network', 'mirror', 'proxy', 'filesystem', 'keyboard'}
2022-11-24 15:39:45,271 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping Keyboard as interactive
2022-11-24 15:39:45,271 DEBUG root:37 start: subiquity/Zdev/apply_autoinstall_config: 
2022-11-24 15:39:45,271 DEBUG root:37 finish: subiquity/Zdev/apply_autoinstall_config: SUCCESS: 
2022-11-24 15:39:45,271 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping Source as interactive
2022-11-24 15:39:45,271 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping Network as interactive
2022-11-24 15:39:45,271 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping UbuntuPro as interactive
2022-11-24 15:39:45,271 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping Proxy as interactive
2022-11-24 15:39:45,271 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping Mirror as interactive
2022-11-24 15:39:45,271 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping Filesystem as interactive
2022-11-24 15:39:45,271 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping Identity as interactive
2022-11-24 15:39:45,271 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping SSH as interactive
2022-11-24 15:39:45,271 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping SnapList as interactive
2022-11-24 15:39:45,271 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping Drivers as interactive
2022-11-24 15:39:45,271 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping TimeZone as interactive
2022-11-24 15:39:45,271 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping Install as interactive
2022-11-24 15:39:45,271 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping Updates as interactive
2022-11-24 15:39:45,271 DEBUG root:37 start: subiquity/Late/apply_autoinstall_config: 
2022-11-24 15:39:45,271 DEBUG root:37 finish: subiquity/Late/apply_autoinstall_config: SUCCESS: 
2022-11-24 15:39:45,271 DEBUG subiquity.server.server:469 apply_autoinstall_config: skipping Shutdown as interactive
2022-11-24 15:39:45,271 INFO root:37 finish: subiquity/apply_autoinstall_config: SUCCESS: 
2022-11-24 15:39:45,271 DEBUG subiquity.models.subiquity:231 model locale for postinstall stage is configured, to go {'snaplist', 'identity', 'ssh', 'drivers', 'network', 'ubuntu_pro'}
2022-11-24 15:39:45,271 DEBUG root:37 start: subiquity/Refresh/configure_snapd: 
2022-11-24 15:39:45,271 DEBUG root:37 start: subiquity/Refresh/configure_snapd/get_details: 
2022-11-24 15:39:45,272 DEBUG root:37 start: subiquity/Refresh/check_for_update: 
2022-11-24 15:39:45,272 DEBUG subiquity.server.controllers.network:151 checking if wpasupplicant is available
2022-11-24 15:39:45,537 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/snaps/subiquity HTTP/1.1" 200 1144
2022-11-24 15:39:45,610 DEBUG subiquity.server.controllers.network:158 wpasupplicant already installed
2022-11-24 15:39:45,612 DEBUG subiquity.server.controllers.network:142 wlan_support_install_finished WLANSupportInstallState.DONE
2022-11-24 15:39:45,612 DEBUG root:37 start: subiquity/Network/_send_update: NEW wlp15s0
2022-11-24 15:39:45,612 DEBUG subiquity.server.controllers.network:354 dev_info wlp15s0 {}
2022-11-24 15:39:45,613 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: NEW wlp15s0
2022-11-24 15:39:45,616 DEBUG root:37 start: subiquity/Drivers/_list_drivers: 
2022-11-24 15:39:45,616 DEBUG root:37 start: subiquity/Drivers/_list_drivers/wait_apt: 
2022-11-24 15:39:45,616 DEBUG root:37 start: subiquity/Install/install: 
2022-11-24 15:39:45,616 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2022-11-24 15:39:45,632 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2022-11-24 15:39:45,632 DEBUG probert.network:741 wlan_event {'cmd': 'TRIGGER_SCAN', 'ifindex': 3}
2022-11-24 15:39:45,633 DEBUG subiquity.server.controllers.snaplist:87 loading list of snaps
2022-11-24 15:39:45,634 DEBUG root:37 start: subiquity/Filesystem/_probe: 
2022-11-24 15:39:45,634 DEBUG root:37 finish: subiquity/Refresh/configure_snapd/get_details: SUCCESS: current version of snap is: '22.10.1'
2022-11-24 15:39:45,634 DEBUG root:37 start: subiquity/Refresh/configure_snapd/switching: switching subiquity to stable/ubuntu-22.04.1
2022-11-24 15:39:45,634 DEBUG root:37 start: subiquity/Refresh/check_for_update: 
2022-11-24 15:39:45,634 DEBUG root:37 start: subiquity/SnapList/loader: 
2022-11-24 15:39:45,635 DEBUG root:37 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2022-11-24 15:39:45,636 ERROR root:37 finish: subiquity/Refresh/check_for_update: FAIL: cancelled
2022-11-24 15:39:45,636 DEBUG root:37 start: subiquity/SnapList/loader/list: 
2022-11-24 15:39:45,637 INFO root:37 start: subiquity/Meta/status_GET: 
2022-11-24 15:39:45,637 INFO root:37 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2022-11-24 15:39:45,638 INFO aiohttp.access:233  [24/Nov/2022:15:39:45 +0000] "GET /meta/status?cur=null HTTP/1.1" 200 412 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:39:45,639 DEBUG urllib3.connectionpool:456 http://localhost:None "POST /v2/snaps/subiquity HTTP/1.1" 202 81
2022-11-24 15:39:45,639 INFO root:37 start: subiquity/Meta/client_variant_GET: 
2022-11-24 15:39:45,639 INFO root:37 finish: subiquity/Meta/client_variant_GET: SUCCESS: 200 "server"
2022-11-24 15:39:45,639 INFO aiohttp.access:233  [24/Nov/2022:15:39:45 +0000] "GET /meta/client_variant HTTP/1.1" 200 194 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:39:45,643 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/changes/6 HTTP/1.1" 200 515
2022-11-24 15:39:45,643 DEBUG root:37 finish: subiquity/Refresh/configure_snapd/switching: SUCCESS: switched to stable/ubuntu-22.04.1
2022-11-24 15:39:45,643 DEBUG root:37 finish: subiquity/Refresh/configure_snapd: SUCCESS: 
2022-11-24 15:39:45,643 DEBUG root:37 finish: subiquity/Refresh/check_for_update: SUCCESS: not offered update when already updated
2022-11-24 15:39:45,644 INFO root:37 start: subiquity/Meta/status_GET: 
2022-11-24 15:39:45,644 INFO root:37 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2022-11-24 15:39:45,644 INFO aiohttp.access:233  [24/Nov/2022:15:39:45 +0000] "GET /meta/status?cur=null HTTP/1.1" 200 412 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:39:45,644 INFO root:37 start: subiquity/Meta/mark_configured_POST: 
2022-11-24 15:39:45,644 DEBUG subiquity.models.subiquity:231 model locale for postinstall stage is configured, to go {'snaplist', 'identity', 'ssh', 'drivers', 'network', 'ubuntu_pro'}
2022-11-24 15:39:45,644 INFO root:37 finish: subiquity/Meta/mark_configured_POST: SUCCESS: 200 null
2022-11-24 15:39:45,644 INFO aiohttp.access:233  [24/Nov/2022:15:39:45 +0000] "POST /meta/mark_configured?endpoint_names=%5B%22locale%22%5D HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:39:45,645 INFO root:37 start: subiquity/Meta/status_GET: 
2022-11-24 15:39:45,645 INFO root:37 start: subiquity/Meta/client_variant_POST: 
2022-11-24 15:39:45,645 DEBUG curtin:87 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/ubuntu-server-minimal.squashfs', '/tmp/tmpvcerqjue/ubuntu-server-minimal.squashfs.dir'] with allowed return codes [0] (capture=True)
2022-11-24 15:39:45,647 DEBUG curtin:87 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/ubuntu-server-minimal.ubuntu-server.squashfs', '/tmp/tmpvcerqjue/ubuntu-server-minimal.ubuntu-server.squashfs.dir'] with allowed return codes [0] (capture=True)
2022-11-24 15:39:45,649 DEBUG curtin:87 Running command ['mount', '-o', 'lowerdir=/tmp/tmpvcerqjue/ubuntu-server-minimal.ubuntu-server.squashfs.dir:/tmp/tmpvcerqjue/ubuntu-server-minimal.squashfs.dir', '-t', 'overlay', 'overlay', '/tmp/tmpvcerqjue/root.dir'] with allowed return codes [0] (capture=True)
2022-11-24 15:39:45,651 DEBUG subiquity.models.subiquity:231 model source for install stage is configured, to go {'network', 'mirror', 'proxy', 'filesystem', 'keyboard'}
2022-11-24 15:39:45,652 INFO root:37 finish: subiquity/Meta/client_variant_POST: SUCCESS: 200 null
2022-11-24 15:39:45,652 INFO aiohttp.access:233  [24/Nov/2022:15:39:45 +0000] "POST /meta/client_variant?variant=%22server%22 HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:39:45,652 DEBUG root:37 start: subiquity/Keyboard/GET: 
2022-11-24 15:39:45,656 DEBUG root:37 finish: subiquity/Keyboard/GET: SUCCESS: 200 {"setting": {"layout": "us", "variant": "", "toggle": null}, "layouts": [{"co...
2022-11-24 15:39:45,657 INFO aiohttp.access:233  [24/Nov/2022:15:39:45 +0000] "GET /keyboard HTTP/1.1" 200 41538 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:39:45,682 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?section=server HTTP/1.1" 200 None
2022-11-24 15:39:45,683 DEBUG root:37 finish: subiquity/SnapList/loader/list: SUCCESS: 
2022-11-24 15:39:45,683 DEBUG subiquity.server.controllers.snaplist:101 fetched list of 23 snaps
2022-11-24 15:39:45,683 DEBUG root:37 start: subiquity/SnapList/loader/fetch/microk8s: 
2022-11-24 15:39:45,890 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=microk8s HTTP/1.1" 200 None
2022-11-24 15:39:45,896 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/microk8s: SUCCESS: 
2022-11-24 15:39:45,897 DEBUG root:37 start: subiquity/SnapList/loader/fetch/nextcloud: 
2022-11-24 15:39:46,068 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=nextcloud HTTP/1.1" 200 None
2022-11-24 15:39:46,069 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/nextcloud: SUCCESS: 
2022-11-24 15:39:46,069 DEBUG root:37 start: subiquity/SnapList/loader/fetch/wekan: 
2022-11-24 15:39:46,200 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=wekan HTTP/1.1" 200 None
2022-11-24 15:39:46,201 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/wekan: SUCCESS: 
2022-11-24 15:39:46,201 DEBUG root:37 start: subiquity/SnapList/loader/fetch/kata-containers: 
2022-11-24 15:39:46,291 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=kata-containers HTTP/1.1" 200 None
2022-11-24 15:39:46,292 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/kata-containers: SUCCESS: 
2022-11-24 15:39:46,293 DEBUG root:37 start: subiquity/SnapList/loader/fetch/docker: 
2022-11-24 15:39:46,360 DEBUG probert.multipath:48 Extracted multipath maps fields: ['ok']
2022-11-24 15:39:46,360 DEBUG probert.multipath:52 Failed to parse multipath maps entry: ok: __new__() missing 2 required positional arguments: 'sysfs' and 'paths'
2022-11-24 15:39:46,364 DEBUG probert.multipath:48 Extracted multipath paths fields: ['nvme0n1', 'S5GXNX0T928425D     ', '[orphan]', '[undef]', '[undef]', '[undef]', '[undef]', '[undef]']
2022-11-24 15:39:46,364 DEBUG probert.multipath:48 Extracted multipath paths fields: ['sdb', 'ZDHBX28T', '[orphan]', '[undef]', 'ata-9.00', '[undef]', '[undef]', '[undef]']
2022-11-24 15:39:46,404 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=docker HTTP/1.1" 200 None
2022-11-24 15:39:46,405 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/docker: SUCCESS: 
2022-11-24 15:39:46,405 DEBUG root:37 start: subiquity/SnapList/loader/fetch/canonical-livepatch: 
2022-11-24 15:39:46,516 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=canonical-livepatch HTTP/1.1" 200 None
2022-11-24 15:39:46,517 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/canonical-livepatch: SUCCESS: 
2022-11-24 15:39:46,518 DEBUG root:37 start: subiquity/SnapList/loader/fetch/rocketchat-server: 
2022-11-24 15:39:46,583 DEBUG probert.dasd:134 Probing DASD devies
2022-11-24 15:39:46,583 DEBUG probert.dasd:137 DASD devices only present on s390x, arch=x86_64
2022-11-24 15:39:46,647 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=rocketchat-server HTTP/1.1" 200 None
2022-11-24 15:39:46,648 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/rocketchat-server: SUCCESS: 
2022-11-24 15:39:46,648 DEBUG root:37 start: subiquity/SnapList/loader/fetch/mosquitto: 
2022-11-24 15:39:46,777 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=mosquitto HTTP/1.1" 200 None
2022-11-24 15:39:46,778 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/mosquitto: SUCCESS: 
2022-11-24 15:39:46,778 DEBUG root:37 start: subiquity/SnapList/loader/fetch/etcd: 
2022-11-24 15:39:46,929 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=etcd HTTP/1.1" 200 None
2022-11-24 15:39:46,930 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/etcd: SUCCESS: 
2022-11-24 15:39:46,930 DEBUG root:37 start: subiquity/SnapList/loader/fetch/powershell: 
2022-11-24 15:39:47,085 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=powershell HTTP/1.1" 200 None
2022-11-24 15:39:47,086 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/powershell: SUCCESS: 
2022-11-24 15:39:47,086 DEBUG root:37 start: subiquity/SnapList/loader/fetch/stress-ng: 
2022-11-24 15:39:47,228 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=stress-ng HTTP/1.1" 200 None
2022-11-24 15:39:47,229 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/stress-ng: SUCCESS: 
2022-11-24 15:39:47,229 DEBUG root:37 start: subiquity/SnapList/loader/fetch/sabnzbd: 
2022-11-24 15:39:47,323 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=sabnzbd HTTP/1.1" 200 None
2022-11-24 15:39:47,323 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/sabnzbd: SUCCESS: 
2022-11-24 15:39:47,323 DEBUG root:37 start: subiquity/SnapList/loader/fetch/wormhole: 
2022-11-24 15:39:47,436 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=wormhole HTTP/1.1" 200 None
2022-11-24 15:39:47,436 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/wormhole: SUCCESS: 
2022-11-24 15:39:47,436 DEBUG root:37 start: subiquity/SnapList/loader/fetch/aws-cli: 
2022-11-24 15:39:47,465 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2022-11-24 15:39:47,492 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2022-11-24 15:39:47,492 DEBUG subiquity.server.controllers.filesystem:683 _udev_event change Device('/sys/devices/pci0000:00/0000:00:02.1/0000:03:00.0/0000:04:0c.0/0000:13:00.0/usb4/4-4/4-4:1.0/host12/target12:0:0/12:0:0:0/block/sda/sda4')
2022-11-24 15:39:47,492 DEBUG subiquity.server.controllers.filesystem:687 Skipping run of Probert - probe run already active
2022-11-24 15:39:47,493 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2022-11-24 15:39:47,516 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2022-11-24 15:39:47,516 DEBUG probert.network:741 wlan_event {'cmd': 'NEW_SCAN_RESULTS', 'ifindex': 3, 'ssids': [(b'A-CAP Guest', 'no status'), (b'Gradient0', 'no status'), (b'Gradient0 Guest', 'no status'), (b'A-CAP', 'no status'), (b'A-CAP Guest', 'no status'), (b'A-CAP', 'no status'), (b'Gradient0 Guest', 'no status'), (b'Gradient0', 'no status'), (b'A-CAP', 'no status'), (b'A-CAP Guest', 'no status'), (b'Gradient0', 'no status'), (b'Gradient0 Guest', 'no status')]}
2022-11-24 15:39:47,516 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2022-11-24 15:39:47,536 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2022-11-24 15:39:47,536 DEBUG probert.network:585 event for link_change: CHANGE {'ifindex': 3, 'flags': 4099, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'wlp15s0'}
2022-11-24 15:39:47,536 DEBUG probert.network:672 link_change CHANGE {'ifindex': 3, 'flags': 4099, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'wlp15s0'}
2022-11-24 15:39:47,536 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE wlp15s0
2022-11-24 15:39:47,536 DEBUG subiquity.server.controllers.network:354 dev_info wlp15s0 {}
2022-11-24 15:39:47,536 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE wlp15s0
2022-11-24 15:39:47,571 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=aws-cli HTTP/1.1" 200 1873
2022-11-24 15:39:47,572 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/aws-cli: SUCCESS: 
2022-11-24 15:39:47,572 DEBUG root:37 start: subiquity/SnapList/loader/fetch/google-cloud-sdk: 
2022-11-24 15:39:47,678 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=google-cloud-sdk HTTP/1.1" 200 1681
2022-11-24 15:39:47,678 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/google-cloud-sdk: SUCCESS: 
2022-11-24 15:39:47,679 DEBUG root:37 start: subiquity/SnapList/loader/fetch/slcli: 
2022-11-24 15:39:47,789 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=slcli HTTP/1.1" 200 2040
2022-11-24 15:39:47,789 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/slcli: SUCCESS: 
2022-11-24 15:39:47,789 DEBUG root:37 start: subiquity/SnapList/loader/fetch/doctl: 
2022-11-24 15:39:47,872 DEBUG curtin:1303 Extracting storage config from probe data
2022-11-24 15:39:47,872 DEBUG curtin:73 /dev/nvme0n1 is multipath device member? False
2022-11-24 15:39:47,872 DEBUG curtin:86 /dev/nvme0n1 is multipath device partition? False
2022-11-24 15:39:47,872 DEBUG curtin:61 /dev/nvme0n1 is multipath device? False
2022-11-24 15:39:47,872 DEBUG curtin:86 /dev/nvme0n1 is multipath device partition? False
2022-11-24 15:39:47,872 DEBUG curtin:61 /dev/nvme0n1 is multipath device? False
2022-11-24 15:39:47,877 DEBUG curtin:73 /dev/nvme0n1p1 is multipath device member? False
2022-11-24 15:39:47,877 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:39:47,877 DEBUG curtin:61 /dev/nvme0n1p1 is multipath device? False
2022-11-24 15:39:47,877 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:39:47,877 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:39:47,882 DEBUG curtin:73 /dev/sda is multipath device member? False
2022-11-24 15:39:47,882 DEBUG curtin:86 /dev/sda is multipath device partition? False
2022-11-24 15:39:47,882 DEBUG curtin:61 /dev/sda is multipath device? False
2022-11-24 15:39:47,882 DEBUG curtin:86 /dev/sda is multipath device partition? False
2022-11-24 15:39:47,882 DEBUG curtin:61 /dev/sda is multipath device? False
2022-11-24 15:39:47,887 DEBUG curtin:73 /dev/sda1 is multipath device member? False
2022-11-24 15:39:47,887 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:39:47,887 DEBUG curtin:61 /dev/sda1 is multipath device? False
2022-11-24 15:39:47,887 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:39:47,887 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:39:47,892 DEBUG curtin:73 /dev/sda2 is multipath device member? False
2022-11-24 15:39:47,892 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:39:47,892 DEBUG curtin:61 /dev/sda2 is multipath device? False
2022-11-24 15:39:47,892 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:39:47,892 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:39:47,897 DEBUG curtin:73 /dev/sda3 is multipath device member? False
2022-11-24 15:39:47,897 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:39:47,897 DEBUG curtin:61 /dev/sda3 is multipath device? False
2022-11-24 15:39:47,897 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:39:47,897 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:39:47,902 DEBUG curtin:73 /dev/sda4 is multipath device member? False
2022-11-24 15:39:47,902 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:39:47,902 DEBUG curtin:61 /dev/sda4 is multipath device? False
2022-11-24 15:39:47,902 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:39:47,902 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:39:47,907 DEBUG curtin:73 /dev/sdb is multipath device member? False
2022-11-24 15:39:47,907 DEBUG curtin:86 /dev/sdb is multipath device partition? False
2022-11-24 15:39:47,907 DEBUG curtin:61 /dev/sdb is multipath device? False
2022-11-24 15:39:47,907 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=doctl HTTP/1.1" 200 1971
2022-11-24 15:39:47,907 DEBUG curtin:86 /dev/sdb is multipath device partition? False
2022-11-24 15:39:47,908 DEBUG curtin:61 /dev/sdb is multipath device? False
2022-11-24 15:39:47,912 DEBUG curtin:73 /dev/sdb1 is multipath device member? False
2022-11-24 15:39:47,912 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:39:47,913 DEBUG curtin:61 /dev/sdb1 is multipath device? False
2022-11-24 15:39:47,913 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:39:47,913 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:39:47,917 DEBUG curtin:73 /dev/nvme0n1p1 is multipath device member? False
2022-11-24 15:39:47,922 DEBUG curtin:73 /dev/sda is multipath device member? False
2022-11-24 15:39:47,927 DEBUG curtin:73 /dev/sda1 is multipath device member? False
2022-11-24 15:39:47,931 DEBUG curtin:73 /dev/sda2 is multipath device member? False
2022-11-24 15:39:47,936 DEBUG curtin:73 /dev/sda4 is multipath device member? False
2022-11-24 15:39:47,940 DEBUG curtin:73 /dev/sdb1 is multipath device member? False
2022-11-24 15:39:47,949 DEBUG curtin:1310 Sorting extracted configurations
2022-11-24 15:39:47,949 INFO curtin:1329 Validating extracted storage config components
2022-11-24 15:39:47,956 DEBUG curtin:1346 Extracted (unmerged) storage config:
storage:
-   id: disk-nvme0n1
    path: /dev/nvme0n1
    ptable: dos
    serial: Samsung_SSD_980_PRO_1TB_S5GXNX0T928425D
    type: disk
    wwn: eui.002538b921b60521
-   id: disk-sda
    path: /dev/sda
    ptable: gpt
    serial: ADATA_USB_Flash_Drive_2811008210170075-0:0
    type: disk
-   id: disk-sdb
    path: /dev/sdb
    ptable: dos
    serial: ST4000VN008-2DR166_ZDHBX28T
    type: disk
    wwn: '0x5000c500e5bb0ccf'
-   device: disk-nvme0n1
    id: partition-nvme0n1p1
    number: 1
    offset: 1048576
    partition_type: '0x7'
    path: /dev/nvme0n1p1
    size: 1000202043392
    type: partition
-   device: disk-sda
    id: partition-sda1
    number: 1
    offset: 32768
    partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
    path: /dev/sda1
    size: 1470150656
    type: partition
-   device: disk-sda
    flag: boot
    id: partition-sda2
    number: 2
    offset: 1470183424
    partition_type: c12a7328-f81f-11d2-ba4b-00a0c93ec93b
    path: /dev/sda2
    size: 4349952
    type: partition
-   device: disk-sda
    id: partition-sda3
    number: 3
    offset: 1474533376
    partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
    path: /dev/sda3
    size: 307200
    type: partition
-   device: disk-sda
    flag: linux
    id: partition-sda4
    number: 4
    offset: 1476395008
    partition_type: 0fc63daf-8483-4772-8e79-3d69d8477de4
    path: /dev/sda4
    size: 14042497536
    type: partition
-   device: disk-sdb
    id: partition-sdb1
    number: 1
    offset: 1048576
    partition_type: '0x7'
    path: /dev/sdb1
    size: 2199022206976
    type: partition
-   fstype: ntfs
    id: format-partition-nvme0n1p1
    type: format
    volume: partition-nvme0n1p1
-   fstype: iso9660
    id: format-disk-sda
    type: format
    volume: disk-sda
-   fstype: iso9660
    id: format-partition-sda1
    type: format
    volume: partition-sda1
-   fstype: vfat
    id: format-partition-sda2
    type: format
    volume: partition-sda2
-   fstype: ext4
    id: format-partition-sda4
    type: format
    uuid: bd8a4591-a294-4e33-a2c7-9994a64fd352
    volume: partition-sda4
-   fstype: ntfs
    id: format-partition-sdb1
    type: format
    volume: partition-sdb1
-   device: format-partition-sda1
    id: mount-partition-sda1
    path: /cdrom
    type: mount

2022-11-24 15:39:47,956 DEBUG curtin:1350 Generating storage config dependencies
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: partition-nvme0n1p1:SourceType:partition -> (DepId:disk-nvme0n1 DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: partition-sda2:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: partition-sda3:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: partition-sda4:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: partition-sdb1:SourceType:partition -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: format-partition-nvme0n1p1:SourceType:format -> (DepId:partition-nvme0n1p1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: partition-nvme0n1p1:SourceType:partition -> (DepId:disk-nvme0n1 DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: format-disk-sda:SourceType:format -> (DepId:disk-sda DepType:disk) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: format-partition-sda1:SourceType:format -> (DepId:partition-sda1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: format-partition-sda2:SourceType:format -> (DepId:partition-sda2 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: partition-sda2:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: format-partition-sda4:SourceType:format -> (DepId:partition-sda4 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: partition-sda4:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: format-partition-sdb1:SourceType:format -> (DepId:partition-sdb1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: partition-sdb1:SourceType:partition -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: mount-partition-sda1:SourceType:mount -> (DepId:format-partition-sda1 DepType:format) in SourceDeps:{'format'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: format-partition-sda1:SourceType:format -> (DepId:partition-sda1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:39:47,957 DEBUG curtin:1356 Merging storage config dependencies
2022-11-24 15:39:47,959 DEBUG curtin:1361 Merged storage config:
storage:
    config:
    -   id: disk-nvme0n1
        path: /dev/nvme0n1
        ptable: dos
        serial: Samsung_SSD_980_PRO_1TB_S5GXNX0T928425D
        type: disk
        wwn: eui.002538b921b60521
    -   id: disk-sda
        path: /dev/sda
        ptable: gpt
        serial: ADATA_USB_Flash_Drive_2811008210170075-0:0
        type: disk
    -   id: disk-sdb
        path: /dev/sdb
        ptable: dos
        serial: ST4000VN008-2DR166_ZDHBX28T
        type: disk
        wwn: '0x5000c500e5bb0ccf'
    -   fstype: iso9660
        id: format-disk-sda
        type: format
        volume: disk-sda
    -   device: disk-nvme0n1
        id: partition-nvme0n1p1
        number: 1
        offset: 1048576
        partition_type: '0x7'
        path: /dev/nvme0n1p1
        size: 1000202043392
        type: partition
    -   device: disk-sdb
        id: partition-sdb1
        number: 1
        offset: 1048576
        partition_type: '0x7'
        path: /dev/sdb1
        size: 2199022206976
        type: partition
    -   fstype: ntfs
        id: format-partition-nvme0n1p1
        type: format
        volume: partition-nvme0n1p1
    -   fstype: ntfs
        id: format-partition-sdb1
        type: format
        volume: partition-sdb1
    -   device: disk-sda
        id: partition-sda1
        number: 1
        offset: 32768
        partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
        path: /dev/sda1
        size: 1470150656
        type: partition
    -   device: disk-sda
        flag: boot
        id: partition-sda2
        number: 2
        offset: 1470183424
        partition_type: c12a7328-f81f-11d2-ba4b-00a0c93ec93b
        path: /dev/sda2
        size: 4349952
        type: partition
    -   device: disk-sda
        id: partition-sda3
        number: 3
        offset: 1474533376
        partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
        path: /dev/sda3
        size: 307200
        type: partition
    -   device: disk-sda
        flag: linux
        id: partition-sda4
        number: 4
        offset: 1476395008
        partition_type: 0fc63daf-8483-4772-8e79-3d69d8477de4
        path: /dev/sda4
        size: 14042497536
        type: partition
    -   fstype: iso9660
        id: format-partition-sda1
        type: format
        volume: partition-sda1
    -   fstype: vfat
        id: format-partition-sda2
        type: format
        volume: partition-sda2
    -   fstype: ext4
        id: format-partition-sda4
        type: format
        uuid: bd8a4591-a294-4e33-a2c7-9994a64fd352
        volume: partition-sda4
    -   device: format-partition-sda1
        id: mount-partition-sda1
        path: /cdrom
        type: mount
    version: 2

2022-11-24 15:39:47,959 DEBUG subiquity.models.filesystem:1271 exclusions {'partition-sda2', 'partition-sda1', 'partition-sda3', 'format-partition-sda2', 'format-disk-sda', 'format-partition-sda1', 'format-partition-sda4', 'disk-sda', 'partition-sda4'}
2022-11-24 15:39:47,959 DEBUG root:37 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False
2022-11-24 15:39:47,959 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/doctl: SUCCESS: 
2022-11-24 15:39:47,959 DEBUG root:37 finish: subiquity/Filesystem/_probe: SUCCESS: 
2022-11-24 15:39:47,959 DEBUG root:37 start: subiquity/SnapList/loader/fetch/conjure-up: 
2022-11-24 15:39:48,061 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=conjure-up HTTP/1.1" 200 None
2022-11-24 15:39:48,062 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/conjure-up: SUCCESS: 
2022-11-24 15:39:48,062 DEBUG root:37 start: subiquity/SnapList/loader/fetch/postgresql10: 
2022-11-24 15:39:48,158 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=postgresql10 HTTP/1.1" 200 1450
2022-11-24 15:39:48,159 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/postgresql10: SUCCESS: 
2022-11-24 15:39:48,159 DEBUG root:37 start: subiquity/SnapList/loader/fetch/heroku: 
2022-11-24 15:39:48,288 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=heroku HTTP/1.1" 200 None
2022-11-24 15:39:48,289 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/heroku: SUCCESS: 
2022-11-24 15:39:48,289 DEBUG root:37 start: subiquity/SnapList/loader/fetch/keepalived: 
2022-11-24 15:39:48,387 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=keepalived HTTP/1.1" 200 None
2022-11-24 15:39:48,387 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/keepalived: SUCCESS: 
2022-11-24 15:39:48,392 DEBUG root:37 start: subiquity/SnapList/loader/fetch/prometheus: 
2022-11-24 15:39:48,496 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=prometheus HTTP/1.1" 200 None
2022-11-24 15:39:48,496 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/prometheus: SUCCESS: 
2022-11-24 15:39:48,496 DEBUG root:37 start: subiquity/SnapList/loader/fetch/juju: 
2022-11-24 15:39:48,661 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/find?name=juju HTTP/1.1" 200 None
2022-11-24 15:39:48,662 DEBUG root:37 finish: subiquity/SnapList/loader/fetch/juju: SUCCESS: 
2022-11-24 15:39:48,662 DEBUG root:37 finish: subiquity/SnapList/loader: SUCCESS: 
2022-11-24 15:40:03,542 DEBUG root:37 start: subiquity/Keyboard/steps_GET: 
2022-11-24 15:40:03,544 DEBUG root:37 finish: subiquity/Keyboard/steps_GET: SUCCESS: 200 {"symbols": ["*", "\u00a4", "n", "u", "v", "y", "\u03b3", "\u03bd", "\u03c5",...
2022-11-24 15:40:03,545 INFO aiohttp.access:233  [24/Nov/2022:15:40:03 +0000] "GET /keyboard/steps?index=null HTTP/1.1" 200 670 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:40:10,750 DEBUG root:37 start: subiquity/Keyboard/steps_GET: 
2022-11-24 15:40:10,750 DEBUG root:37 finish: subiquity/Keyboard/steps_GET: SUCCESS: 200 {"symbols": ["q"], "keycodes": [[30, "77"], [16, "79"]], "$type": "StepPressK...
2022-11-24 15:40:10,750 INFO aiohttp.access:233  [24/Nov/2022:15:40:10 +0000] "GET /keyboard/steps?index=%2276%22 HTTP/1.1" 200 268 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:40:13,405 DEBUG root:37 start: subiquity/Keyboard/steps_GET: 
2022-11-24 15:40:13,405 DEBUG root:37 finish: subiquity/Keyboard/steps_GET: SUCCESS: 200 {"symbols": ["z"], "keycodes": [[44, "80"], [21, "2"]], "$type": "StepPressKey"}
2022-11-24 15:40:13,405 INFO aiohttp.access:233  [24/Nov/2022:15:40:13 +0000] "GET /keyboard/steps?index=%2279%22 HTTP/1.1" 200 267 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:40:15,349 DEBUG root:37 start: subiquity/Keyboard/steps_GET: 
2022-11-24 15:40:15,349 DEBUG root:37 finish: subiquity/Keyboard/steps_GET: SUCCESS: 200 {"layout": "de", "variant": "nodeadkeys", "$type": "StepResult"}
2022-11-24 15:40:15,349 INFO aiohttp.access:233  [24/Nov/2022:15:40:15 +0000] "GET /keyboard/steps?index=%222%22 HTTP/1.1" 200 251 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:40:23,805 DEBUG root:37 start: subiquity/Keyboard/needs_toggle_GET: 
2022-11-24 15:40:23,805 DEBUG root:37 finish: subiquity/Keyboard/needs_toggle_GET: SUCCESS: 200 false
2022-11-24 15:40:23,805 INFO aiohttp.access:233  [24/Nov/2022:15:40:23 +0000] "GET /keyboard/needs_toggle?layout_code=%22de%22&variant_code=%22nodeadkeys%22 HTTP/1.1" 200 191 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:40:23,806 DEBUG root:37 start: subiquity/Keyboard/POST: 
2022-11-24 15:40:23,806 DEBUG subiquity.server.controllers.keyboard:222 KeyboardSetting(layout='de', variant='nodeadkeys', toggle=None)
2022-11-24 15:40:23,806 DEBUG subiquitycore.utils:92 arun_command called: ['setupcon', '--save', '--force', '--keyboard-only']
2022-11-24 15:40:23,902 DEBUG subiquitycore.utils:101 arun_command ['setupcon', '--save', '--force', '--keyboard-only'] exited with code 0
2022-11-24 15:40:23,902 DEBUG subiquitycore.utils:92 arun_command called: ['/snap/subiquity/4003/bin/subiquity-loadkeys']
2022-11-24 15:40:23,905 DEBUG subiquitycore.utils:101 arun_command ['/snap/subiquity/4003/bin/subiquity-loadkeys'] exited with code 0
2022-11-24 15:40:23,905 DEBUG subiquity.models.subiquity:231 model keyboard for install stage is configured, to go {'filesystem', 'network', 'mirror', 'proxy'}
2022-11-24 15:40:23,906 DEBUG root:37 finish: subiquity/Keyboard/POST: SUCCESS: 200 null
2022-11-24 15:40:23,906 INFO aiohttp.access:233  [24/Nov/2022:15:40:23 +0000] "POST /keyboard HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:40:24,908 DEBUG root:37 start: subiquity/Source/GET: 
2022-11-24 15:40:24,908 DEBUG root:37 finish: subiquity/Source/GET: SUCCESS: 200 {"sources": [{"name": "Ubuntu Server (minimized)", "description": "This versi...
2022-11-24 15:40:24,908 INFO aiohttp.access:233  [24/Nov/2022:15:40:24 +0000] "GET /source HTTP/1.1" 200 773 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:40:58,453 DEBUG root:37 start: subiquity/Source/POST: 
2022-11-24 15:40:58,453 DEBUG curtin:87 Running command ['umount', '/tmp/tmpvcerqjue/root.dir'] with allowed return codes [0] (capture=True)
2022-11-24 15:40:58,457 DEBUG curtin:87 Running command ['umount', '/tmp/tmpvcerqjue/ubuntu-server-minimal.ubuntu-server.squashfs.dir'] with allowed return codes [0] (capture=True)
2022-11-24 15:40:58,459 DEBUG curtin:87 Running command ['umount', '/tmp/tmpvcerqjue/ubuntu-server-minimal.squashfs.dir'] with allowed return codes [0] (capture=True)
2022-11-24 15:40:58,461 DEBUG curtin:87 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/ubuntu-server-minimal.squashfs', '/tmp/tmpi2d_s70_/ubuntu-server-minimal.squashfs.dir'] with allowed return codes [0] (capture=True)
2022-11-24 15:40:58,464 DEBUG curtin:87 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/ubuntu-server-minimal.ubuntu-server.squashfs', '/tmp/tmpi2d_s70_/ubuntu-server-minimal.ubuntu-server.squashfs.dir'] with allowed return codes [0] (capture=True)
2022-11-24 15:40:58,466 DEBUG curtin:87 Running command ['mount', '-o', 'lowerdir=/tmp/tmpi2d_s70_/ubuntu-server-minimal.ubuntu-server.squashfs.dir:/tmp/tmpi2d_s70_/ubuntu-server-minimal.squashfs.dir', '-t', 'overlay', 'overlay', '/tmp/tmpi2d_s70_/root.dir'] with allowed return codes [0] (capture=True)
2022-11-24 15:40:58,468 DEBUG subiquity.models.subiquity:231 model source for install stage is configured, to go {'filesystem', 'network', 'mirror', 'proxy'}
2022-11-24 15:40:58,468 DEBUG root:37 finish: subiquity/Source/POST: SUCCESS: 200 null
2022-11-24 15:40:58,469 INFO aiohttp.access:233  [24/Nov/2022:15:40:58 +0000] "POST /source?source_id=%22ubuntu-server%22&search_drivers=true HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:40:58,469 INFO aiohttp.access:233  [24/Nov/2022:15:40:58 +0000] "GET /zdev HTTP/1.1" 200 181 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:40:58,470 DEBUG root:37 start: subiquity/Network/GET: 
2022-11-24 15:40:58,471 DEBUG root:37 finish: subiquity/Network/GET: SUCCESS: 200 {"devices": [{"name": "enp14s0", "type": "eth", "is_connected": true, "bond_m...
2022-11-24 15:40:58,471 INFO root:37 start: subiquity/Network/apply_config: silent=True
2022-11-24 15:40:58,471 DEBUG subiquitycore.controllers.network:240 network config: 
network:
  ethernets:
    enp14s0:
      dhcp4: true
  version: 2
  wifis: {}

2022-11-24 15:40:58,473 DEBUG subiquitycore.netplan:109 config for enp14s0 = {'dhcp4': True}
2022-11-24 15:40:58,473 DEBUG subiquitycore.utils:92 arun_command called: ['netplan', 'apply']
2022-11-24 15:40:58,475 INFO aiohttp.access:233  [24/Nov/2022:15:40:58 +0000] "GET /network HTTP/1.1" 200 1726 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:40:58,479 DEBUG root:37 start: subiquity/Network/subscription_PUT: 
2022-11-24 15:40:58,479 DEBUG subiquity.server.controllers.network:300 added subscription /tmp/tmpt84ms4xd/socket
2022-11-24 15:40:58,480 DEBUG root:37 finish: subiquity/Network/subscription_PUT: SUCCESS: 200 null
2022-11-24 15:40:58,480 DEBUG subiquity.server.controllers.network:320 _call_client route_watch /tmp/tmpt84ms4xd/socket
2022-11-24 15:40:58,481 INFO aiohttp.access:233  [24/Nov/2022:15:40:58 +0000] "PUT /network/subscription?socket_path=%22/tmp/tmpt84ms4xd/socket%22 HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:40:58,820 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2022-11-24 15:40:58,868 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2022-11-24 15:40:58,868 DEBUG probert.network:585 event for addr_change: DEL {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'10.30.0.20/24'}
2022-11-24 15:40:58,868 DEBUG probert.network:731 route_change DEL {'family': 2, 'type': 1, 'table': 254, 'dst': b'10.30.0.1', 'ifindex': 2}
2022-11-24 15:40:58,868 DEBUG probert.network:731 route_change DEL {'family': 2, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2022-11-24 15:40:58,868 DEBUG subiquitycore.controllers.network:94 default routes set()
2022-11-24 15:40:58,868 DEBUG subiquity.server.controllers.network:331 creating _call_client task /tmp/tmpt84ms4xd/socket route_watch
2022-11-24 15:40:58,869 DEBUG probert.network:717 addr_change DEL {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'10.30.0.20/24'}
2022-11-24 15:40:58,869 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE enp14s0
2022-11-24 15:40:58,869 DEBUG subiquity.server.controllers.network:354 dev_info enp14s0 {'dhcp4': True}
2022-11-24 15:40:58,869 DEBUG subiquity.server.controllers.network:331 creating _call_client task /tmp/tmpt84ms4xd/socket update_link
2022-11-24 15:40:58,869 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp14s0
2022-11-24 15:40:58,869 DEBUG probert.network:731 route_change DEL {'family': 2, 'type': 1, 'table': 254, 'dst': b'10.30.0.0/24', 'ifindex': 2}
2022-11-24 15:40:58,869 DEBUG probert.network:731 route_change DEL {'family': 2, 'type': 3, 'table': 255, 'dst': b'10.30.0.255', 'ifindex': 2}
2022-11-24 15:40:58,869 DEBUG probert.network:731 route_change DEL {'family': 2, 'type': 2, 'table': 255, 'dst': b'10.30.0.20', 'ifindex': 2}
2022-11-24 15:40:58,869 DEBUG subiquity.server.controllers.network:320 _call_client route_watch /tmp/tmpt84ms4xd/socket
2022-11-24 15:40:58,871 DEBUG subiquity.server.controllers.network:320 _call_client update_link /tmp/tmpt84ms4xd/socket
2022-11-24 15:40:58,884 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2022-11-24 15:40:58,900 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2022-11-24 15:40:58,900 DEBUG probert.network:585 event for link_change: CHANGE {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'enp14s0'}
2022-11-24 15:40:58,900 DEBUG probert.network:672 link_change CHANGE {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'enp14s0'}
2022-11-24 15:40:58,900 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE enp14s0
2022-11-24 15:40:58,900 DEBUG subiquity.server.controllers.network:354 dev_info enp14s0 {'dhcp4': True}
2022-11-24 15:40:58,900 DEBUG subiquity.server.controllers.network:331 creating _call_client task /tmp/tmpt84ms4xd/socket update_link
2022-11-24 15:40:58,900 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp14s0
2022-11-24 15:40:58,900 DEBUG subiquity.server.controllers.network:320 _call_client update_link /tmp/tmpt84ms4xd/socket
2022-11-24 15:40:58,902 DEBUG subiquitycore.utils:101 arun_command ['netplan', 'apply'] exited with code 0
2022-11-24 15:40:58,976 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2022-11-24 15:40:58,992 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2022-11-24 15:40:59,040 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2022-11-24 15:40:59,056 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2022-11-24 15:40:59,057 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'10.30.0.20/24'}
2022-11-24 15:40:59,057 DEBUG probert.network:717 addr_change NEW {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'10.30.0.20/24'}
2022-11-24 15:40:59,057 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE enp14s0
2022-11-24 15:40:59,057 DEBUG subiquity.server.controllers.network:354 dev_info enp14s0 {'dhcp4': True}
2022-11-24 15:40:59,057 DEBUG subiquity.server.controllers.network:331 creating _call_client task /tmp/tmpt84ms4xd/socket update_link
2022-11-24 15:40:59,057 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp14s0
2022-11-24 15:40:59,057 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'10.30.0.20', 'ifindex': 2}
2022-11-24 15:40:59,057 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'10.30.0.255', 'ifindex': 2}
2022-11-24 15:40:59,057 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'10.30.0.0/24', 'ifindex': 2}
2022-11-24 15:40:59,057 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'10.30.0.1', 'ifindex': 2}
2022-11-24 15:40:59,057 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2022-11-24 15:40:59,057 DEBUG subiquitycore.controllers.network:94 default routes {2}
2022-11-24 15:40:59,057 DEBUG subiquity.server.controllers.network:331 creating _call_client task /tmp/tmpt84ms4xd/socket route_watch
2022-11-24 15:40:59,057 DEBUG subiquity.server.controllers.network:320 _call_client update_link /tmp/tmpt84ms4xd/socket
2022-11-24 15:40:59,058 INFO root:37 finish: subiquity/Network/apply_config: SUCCESS: silent=True
2022-11-24 15:40:59,060 DEBUG subiquity.server.controllers.network:320 _call_client route_watch /tmp/tmpt84ms4xd/socket
2022-11-24 15:41:32,493 DEBUG root:37 start: subiquity/Network/info_GET: 
2022-11-24 15:41:32,499 DEBUG root:37 finish: subiquity/Network/info_GET: SUCCESS: 200 "addresses:\n- address: fe80::da5e:d3ff:fee4:94f8/64\n  family: 10\n  scope: ...
2022-11-24 15:41:32,499 INFO aiohttp.access:233  [24/Nov/2022:15:41:32 +0000] "GET /network/info?dev_name=%22enp14s0%22 HTTP/1.1" 200 2456 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:41:44,604 DEBUG root:37 start: subiquity/Network/info_GET: 
2022-11-24 15:41:44,610 DEBUG root:37 finish: subiquity/Network/info_GET: SUCCESS: 200 "addresses: []\nbond:\n  is_master: false\n  is_slave: false\n  lacp_rate: nu...
2022-11-24 15:41:44,610 INFO aiohttp.access:233  [24/Nov/2022:15:41:44 +0000] "GET /network/info?dev_name=%22wlp15s0%22 HTTP/1.1" 200 2340 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:42:10,842 INFO aiohttp.access:233  [24/Nov/2022:15:42:10 +0000] "GET /zdev HTTP/1.1" 200 181 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:42:10,843 DEBUG root:37 start: subiquity/Network/subscription_DELETE: 
2022-11-24 15:42:10,843 DEBUG subiquity.server.controllers.network:313 removed subscription /tmp/tmpt84ms4xd/socket
2022-11-24 15:42:10,843 DEBUG root:37 finish: subiquity/Network/subscription_DELETE: SUCCESS: 200 null
2022-11-24 15:42:10,843 INFO aiohttp.access:233  [24/Nov/2022:15:42:10 +0000] "DELETE /network/subscription?socket_path=%22/tmp/tmpt84ms4xd/socket%22 HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:42:10,843 DEBUG root:37 start: subiquity/Source/GET: 
2022-11-24 15:42:10,843 DEBUG root:37 finish: subiquity/Source/GET: SUCCESS: 200 {"sources": [{"name": "Ubuntu Server (minimized)", "description": "This versi...
2022-11-24 15:42:10,843 INFO aiohttp.access:233  [24/Nov/2022:15:42:10 +0000] "GET /source HTTP/1.1" 200 772 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:42:13,004 DEBUG root:37 start: subiquity/Source/POST: 
2022-11-24 15:42:13,004 DEBUG curtin:87 Running command ['umount', '/tmp/tmpi2d_s70_/root.dir'] with allowed return codes [0] (capture=True)
2022-11-24 15:42:13,008 DEBUG curtin:87 Running command ['umount', '/tmp/tmpi2d_s70_/ubuntu-server-minimal.ubuntu-server.squashfs.dir'] with allowed return codes [0] (capture=True)
2022-11-24 15:42:13,010 DEBUG curtin:87 Running command ['umount', '/tmp/tmpi2d_s70_/ubuntu-server-minimal.squashfs.dir'] with allowed return codes [0] (capture=True)
2022-11-24 15:42:13,013 DEBUG curtin:87 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/ubuntu-server-minimal.squashfs', '/tmp/tmp0lzaqorp/ubuntu-server-minimal.squashfs.dir'] with allowed return codes [0] (capture=True)
2022-11-24 15:42:13,015 DEBUG curtin:87 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/ubuntu-server-minimal.ubuntu-server.squashfs', '/tmp/tmp0lzaqorp/ubuntu-server-minimal.ubuntu-server.squashfs.dir'] with allowed return codes [0] (capture=True)
2022-11-24 15:42:13,017 DEBUG curtin:87 Running command ['mount', '-o', 'lowerdir=/tmp/tmp0lzaqorp/ubuntu-server-minimal.ubuntu-server.squashfs.dir:/tmp/tmp0lzaqorp/ubuntu-server-minimal.squashfs.dir', '-t', 'overlay', 'overlay', '/tmp/tmp0lzaqorp/root.dir'] with allowed return codes [0] (capture=True)
2022-11-24 15:42:13,020 DEBUG subiquity.models.subiquity:231 model source for install stage is configured, to go {'filesystem', 'network', 'mirror', 'proxy'}
2022-11-24 15:42:13,020 DEBUG root:37 finish: subiquity/Source/POST: SUCCESS: 200 null
2022-11-24 15:42:13,020 INFO aiohttp.access:233  [24/Nov/2022:15:42:13 +0000] "POST /source?source_id=%22ubuntu-server%22&search_drivers=true HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:42:13,021 INFO aiohttp.access:233  [24/Nov/2022:15:42:13 +0000] "GET /zdev HTTP/1.1" 200 181 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:42:13,022 DEBUG root:37 start: subiquity/Network/GET: 
2022-11-24 15:42:13,023 DEBUG root:37 finish: subiquity/Network/GET: SUCCESS: 200 {"devices": [{"name": "enp14s0", "type": "eth", "is_connected": true, "bond_m...
2022-11-24 15:42:13,023 INFO aiohttp.access:233  [24/Nov/2022:15:42:13 +0000] "GET /network HTTP/1.1" 200 1734 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:42:13,027 DEBUG root:37 start: subiquity/Network/subscription_PUT: 
2022-11-24 15:42:13,028 DEBUG subiquity.server.controllers.network:300 added subscription /tmp/tmp_pd_1t3o/socket
2022-11-24 15:42:13,028 DEBUG root:37 finish: subiquity/Network/subscription_PUT: SUCCESS: 200 null
2022-11-24 15:42:13,028 DEBUG subiquity.server.controllers.network:320 _call_client route_watch /tmp/tmp_pd_1t3o/socket
2022-11-24 15:42:13,029 INFO aiohttp.access:233  [24/Nov/2022:15:42:13 +0000] "PUT /network/subscription?socket_path=%22/tmp/tmp_pd_1t3o/socket%22 HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:42:24,660 DEBUG root:37 start: subiquity/Network/POST: 
2022-11-24 15:42:24,660 DEBUG subiquitycore.models.network:427 has_network True
2022-11-24 15:42:24,660 DEBUG subiquity.models.subiquity:231 model network for install stage is configured, to go {'filesystem', 'mirror', 'proxy'}
2022-11-24 15:42:24,660 DEBUG subiquity.models.subiquity:231 model network for postinstall stage is configured, to go {'snaplist', 'identity', 'ssh', 'drivers', 'ubuntu_pro'}
2022-11-24 15:42:24,660 DEBUG root:37 finish: subiquity/Network/POST: SUCCESS: 200 null
2022-11-24 15:42:24,661 INFO aiohttp.access:233  [24/Nov/2022:15:42:24 +0000] "POST /network HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:42:24,661 DEBUG root:37 start: subiquity/Proxy/GET: 
2022-11-24 15:42:24,662 DEBUG root:37 finish: subiquity/Proxy/GET: SUCCESS: 200 ""
2022-11-24 15:42:24,662 INFO aiohttp.access:233  [24/Nov/2022:15:42:24 +0000] "GET /proxy HTTP/1.1" 200 188 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:42:24,662 DEBUG root:37 start: subiquity/Network/subscription_DELETE: 
2022-11-24 15:42:24,662 DEBUG subiquity.server.controllers.network:313 removed subscription /tmp/tmp_pd_1t3o/socket
2022-11-24 15:42:24,662 DEBUG root:37 finish: subiquity/Network/subscription_DELETE: SUCCESS: 200 null
2022-11-24 15:42:24,662 INFO aiohttp.access:233  [24/Nov/2022:15:42:24 +0000] "DELETE /network/subscription?socket_path=%22/tmp/tmp_pd_1t3o/socket%22 HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:42:27,036 DEBUG root:37 start: subiquity/Proxy/POST: 
2022-11-24 15:42:27,036 DEBUG subiquity.models.subiquity:231 model proxy for install stage is configured, to go {'filesystem', 'mirror'}
2022-11-24 15:42:27,036 DEBUG root:37 finish: subiquity/Proxy/POST: SUCCESS: 200 null
2022-11-24 15:42:27,037 DEBUG subiquitycore.snapd:59 restarting snapd to pick up proxy config
2022-11-24 15:42:27,037 INFO aiohttp.access:233  [24/Nov/2022:15:42:27 +0000] "POST /proxy HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:42:27,037 DEBUG subiquitycore.utils:64 run_command called: ['systemctl', 'daemon-reload']
2022-11-24 15:42:27,039 DEBUG root:37 start: subiquity/Mirror/GET: 
2022-11-24 15:42:27,039 DEBUG root:37 finish: subiquity/Mirror/GET: SUCCESS: 200 "http://at.archive.ubuntu.com/ubuntu"
2022-11-24 15:42:27,039 INFO aiohttp.access:233  [24/Nov/2022:15:42:27 +0000] "GET /mirror HTTP/1.1" 200 224 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:42:27,248 DEBUG subiquitycore.utils:77 run_command ['systemctl', 'daemon-reload'] exited with code 0
2022-11-24 15:42:27,248 DEBUG subiquitycore.utils:64 run_command called: ['systemctl', 'restart', 'snapd.service']
2022-11-24 15:42:27,343 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2022-11-24 15:42:27,346 DEBUG subiquitycore.utils:77 run_command ['systemctl', 'restart', 'snapd.service'] exited with code 0
2022-11-24 15:42:27,364 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 1
2022-11-24 15:42:27,364 DEBUG subiquity.server.controllers.filesystem:671 waiting 0.1 to let udev event queue settle
2022-11-24 15:42:27,465 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2022-11-24 15:42:27,480 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2022-11-24 15:42:27,480 DEBUG subiquity.server.controllers.filesystem:683 _udev_event add Device('/sys/devices/virtual/block/loop11')
2022-11-24 15:42:27,480 DEBUG subiquity.server.controllers.filesystem:683 _udev_event change Device('/sys/devices/virtual/block/loop11')
2022-11-24 15:42:27,480 DEBUG subiquity.server.controllers.filesystem:683 _udev_event change Device('/sys/devices/virtual/block/loop11')
2022-11-24 15:42:27,480 DEBUG subiquity.server.controllers.filesystem:683 _udev_event change Device('/sys/devices/virtual/block/loop11')
2022-11-24 15:42:27,480 DEBUG subiquity.server.controllers.filesystem:683 _udev_event change Device('/sys/devices/virtual/block/loop11')
2022-11-24 15:42:27,480 DEBUG subiquity.server.controllers.filesystem:689 Triggered Probert run on udev event
2022-11-24 15:42:27,480 DEBUG root:37 start: subiquity/Filesystem/_probe: 
2022-11-24 15:42:27,480 DEBUG root:37 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2022-11-24 15:42:28,051 DEBUG probert.multipath:48 Extracted multipath maps fields: ['ok']
2022-11-24 15:42:28,051 DEBUG probert.multipath:52 Failed to parse multipath maps entry: ok: __new__() missing 2 required positional arguments: 'sysfs' and 'paths'
2022-11-24 15:42:28,055 DEBUG probert.multipath:48 Extracted multipath paths fields: ['nvme0n1', 'S5GXNX0T928425D     ', '[orphan]', '[undef]', '[undef]', '[undef]', '[undef]', '[undef]']
2022-11-24 15:42:28,055 DEBUG probert.multipath:48 Extracted multipath paths fields: ['sdb', 'ZDHBX28T', '[orphan]', '[undef]', 'ata-9.00', '[undef]', '[undef]', '[undef]']
2022-11-24 15:42:28,269 DEBUG probert.dasd:134 Probing DASD devies
2022-11-24 15:42:28,269 DEBUG probert.dasd:137 DASD devices only present on s390x, arch=x86_64
2022-11-24 15:42:28,339 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2022-11-24 15:42:28,356 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2022-11-24 15:42:28,356 DEBUG subiquity.server.controllers.filesystem:683 _udev_event change Device('/sys/devices/pci0000:00/0000:00:02.1/0000:03:00.0/0000:04:0c.0/0000:13:00.0/usb4/4-4/4-4:1.0/host12/target12:0:0/12:0:0:0/block/sda/sda4')
2022-11-24 15:42:28,356 DEBUG subiquity.server.controllers.filesystem:687 Skipping run of Probert - probe run already active
2022-11-24 15:42:28,727 DEBUG curtin:1303 Extracting storage config from probe data
2022-11-24 15:42:28,727 DEBUG curtin:73 /dev/nvme0n1 is multipath device member? False
2022-11-24 15:42:28,727 DEBUG curtin:86 /dev/nvme0n1 is multipath device partition? False
2022-11-24 15:42:28,727 DEBUG curtin:61 /dev/nvme0n1 is multipath device? False
2022-11-24 15:42:28,727 DEBUG curtin:86 /dev/nvme0n1 is multipath device partition? False
2022-11-24 15:42:28,727 DEBUG curtin:61 /dev/nvme0n1 is multipath device? False
2022-11-24 15:42:28,735 DEBUG curtin:73 /dev/nvme0n1p1 is multipath device member? False
2022-11-24 15:42:28,735 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:42:28,735 DEBUG curtin:61 /dev/nvme0n1p1 is multipath device? False
2022-11-24 15:42:28,735 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:42:28,735 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:42:28,743 DEBUG curtin:73 /dev/sda is multipath device member? False
2022-11-24 15:42:28,743 DEBUG curtin:86 /dev/sda is multipath device partition? False
2022-11-24 15:42:28,743 DEBUG curtin:61 /dev/sda is multipath device? False
2022-11-24 15:42:28,743 DEBUG curtin:86 /dev/sda is multipath device partition? False
2022-11-24 15:42:28,743 DEBUG curtin:61 /dev/sda is multipath device? False
2022-11-24 15:42:28,751 DEBUG curtin:73 /dev/sda1 is multipath device member? False
2022-11-24 15:42:28,751 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:42:28,751 DEBUG curtin:61 /dev/sda1 is multipath device? False
2022-11-24 15:42:28,751 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:42:28,751 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:42:28,759 DEBUG curtin:73 /dev/sda2 is multipath device member? False
2022-11-24 15:42:28,759 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:42:28,759 DEBUG curtin:61 /dev/sda2 is multipath device? False
2022-11-24 15:42:28,759 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:42:28,759 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:42:28,767 DEBUG curtin:73 /dev/sda3 is multipath device member? False
2022-11-24 15:42:28,767 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:42:28,767 DEBUG curtin:61 /dev/sda3 is multipath device? False
2022-11-24 15:42:28,767 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:42:28,767 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:42:28,775 DEBUG curtin:73 /dev/sda4 is multipath device member? False
2022-11-24 15:42:28,775 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:42:28,775 DEBUG curtin:61 /dev/sda4 is multipath device? False
2022-11-24 15:42:28,775 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:42:28,775 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:42:28,782 DEBUG curtin:73 /dev/sdb is multipath device member? False
2022-11-24 15:42:28,782 DEBUG curtin:86 /dev/sdb is multipath device partition? False
2022-11-24 15:42:28,782 DEBUG curtin:61 /dev/sdb is multipath device? False
2022-11-24 15:42:28,782 DEBUG curtin:86 /dev/sdb is multipath device partition? False
2022-11-24 15:42:28,782 DEBUG curtin:61 /dev/sdb is multipath device? False
2022-11-24 15:42:28,789 DEBUG curtin:73 /dev/sdb1 is multipath device member? False
2022-11-24 15:42:28,789 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:42:28,789 DEBUG curtin:61 /dev/sdb1 is multipath device? False
2022-11-24 15:42:28,789 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:42:28,789 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:42:28,795 DEBUG curtin:73 /dev/nvme0n1p1 is multipath device member? False
2022-11-24 15:42:28,801 DEBUG curtin:73 /dev/sda is multipath device member? False
2022-11-24 15:42:28,807 DEBUG curtin:73 /dev/sda1 is multipath device member? False
2022-11-24 15:42:28,812 DEBUG curtin:73 /dev/sda2 is multipath device member? False
2022-11-24 15:42:28,817 DEBUG curtin:73 /dev/sda4 is multipath device member? False
2022-11-24 15:42:28,821 DEBUG curtin:73 /dev/sdb1 is multipath device member? False
2022-11-24 15:42:28,831 DEBUG curtin:1310 Sorting extracted configurations
2022-11-24 15:42:28,831 INFO curtin:1329 Validating extracted storage config components
2022-11-24 15:42:28,839 DEBUG curtin:1346 Extracted (unmerged) storage config:
storage:
-   id: disk-nvme0n1
    path: /dev/nvme0n1
    ptable: dos
    serial: Samsung_SSD_980_PRO_1TB_S5GXNX0T928425D
    type: disk
    wwn: eui.002538b921b60521
-   id: disk-sda
    path: /dev/sda
    ptable: gpt
    serial: ADATA_USB_Flash_Drive_2811008210170075-0:0
    type: disk
-   id: disk-sdb
    path: /dev/sdb
    ptable: dos
    serial: ST4000VN008-2DR166_ZDHBX28T
    type: disk
    wwn: '0x5000c500e5bb0ccf'
-   device: disk-nvme0n1
    id: partition-nvme0n1p1
    number: 1
    offset: 1048576
    partition_type: '0x7'
    path: /dev/nvme0n1p1
    size: 1000202043392
    type: partition
-   device: disk-sda
    id: partition-sda1
    number: 1
    offset: 32768
    partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
    path: /dev/sda1
    size: 1470150656
    type: partition
-   device: disk-sda
    flag: boot
    id: partition-sda2
    number: 2
    offset: 1470183424
    partition_type: c12a7328-f81f-11d2-ba4b-00a0c93ec93b
    path: /dev/sda2
    size: 4349952
    type: partition
-   device: disk-sda
    id: partition-sda3
    number: 3
    offset: 1474533376
    partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
    path: /dev/sda3
    size: 307200
    type: partition
-   device: disk-sda
    flag: linux
    id: partition-sda4
    number: 4
    offset: 1476395008
    partition_type: 0fc63daf-8483-4772-8e79-3d69d8477de4
    path: /dev/sda4
    size: 14042497536
    type: partition
-   device: disk-sdb
    id: partition-sdb1
    number: 1
    offset: 1048576
    partition_type: '0x7'
    path: /dev/sdb1
    size: 2199022206976
    type: partition
-   fstype: ntfs
    id: format-partition-nvme0n1p1
    type: format
    volume: partition-nvme0n1p1
-   fstype: iso9660
    id: format-disk-sda
    type: format
    volume: disk-sda
-   fstype: iso9660
    id: format-partition-sda1
    type: format
    volume: partition-sda1
-   fstype: vfat
    id: format-partition-sda2
    type: format
    volume: partition-sda2
-   fstype: ext4
    id: format-partition-sda4
    type: format
    uuid: bd8a4591-a294-4e33-a2c7-9994a64fd352
    volume: partition-sda4
-   fstype: ntfs
    id: format-partition-sdb1
    type: format
    volume: partition-sdb1
-   device: format-partition-sda1
    id: mount-partition-sda1
    path: /cdrom
    type: mount

2022-11-24 15:42:28,839 DEBUG curtin:1350 Generating storage config dependencies
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: partition-nvme0n1p1:SourceType:partition -> (DepId:disk-nvme0n1 DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: partition-sda2:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: partition-sda3:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: partition-sda4:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: partition-sdb1:SourceType:partition -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: format-partition-nvme0n1p1:SourceType:format -> (DepId:partition-nvme0n1p1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: partition-nvme0n1p1:SourceType:partition -> (DepId:disk-nvme0n1 DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: format-disk-sda:SourceType:format -> (DepId:disk-sda DepType:disk) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: format-partition-sda1:SourceType:format -> (DepId:partition-sda1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: format-partition-sda2:SourceType:format -> (DepId:partition-sda2 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: partition-sda2:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: format-partition-sda4:SourceType:format -> (DepId:partition-sda4 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: partition-sda4:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: format-partition-sdb1:SourceType:format -> (DepId:partition-sdb1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: partition-sdb1:SourceType:partition -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:42:28,839 DEBUG curtin:236 Validate: mount-partition-sda1:SourceType:mount -> (DepId:format-partition-sda1 DepType:format) in SourceDeps:{'format'} ? result=True
2022-11-24 15:42:28,840 DEBUG curtin:236 Validate: format-partition-sda1:SourceType:format -> (DepId:partition-sda1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:42:28,840 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:42:28,840 DEBUG curtin:1356 Merging storage config dependencies
2022-11-24 15:42:28,842 DEBUG curtin:1361 Merged storage config:
storage:
    config:
    -   id: disk-nvme0n1
        path: /dev/nvme0n1
        ptable: dos
        serial: Samsung_SSD_980_PRO_1TB_S5GXNX0T928425D
        type: disk
        wwn: eui.002538b921b60521
    -   id: disk-sda
        path: /dev/sda
        ptable: gpt
        serial: ADATA_USB_Flash_Drive_2811008210170075-0:0
        type: disk
    -   id: disk-sdb
        path: /dev/sdb
        ptable: dos
        serial: ST4000VN008-2DR166_ZDHBX28T
        type: disk
        wwn: '0x5000c500e5bb0ccf'
    -   fstype: iso9660
        id: format-disk-sda
        type: format
        volume: disk-sda
    -   device: disk-nvme0n1
        id: partition-nvme0n1p1
        number: 1
        offset: 1048576
        partition_type: '0x7'
        path: /dev/nvme0n1p1
        size: 1000202043392
        type: partition
    -   device: disk-sdb
        id: partition-sdb1
        number: 1
        offset: 1048576
        partition_type: '0x7'
        path: /dev/sdb1
        size: 2199022206976
        type: partition
    -   fstype: ntfs
        id: format-partition-nvme0n1p1
        type: format
        volume: partition-nvme0n1p1
    -   fstype: ntfs
        id: format-partition-sdb1
        type: format
        volume: partition-sdb1
    -   device: disk-sda
        id: partition-sda1
        number: 1
        offset: 32768
        partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
        path: /dev/sda1
        size: 1470150656
        type: partition
    -   device: disk-sda
        flag: boot
        id: partition-sda2
        number: 2
        offset: 1470183424
        partition_type: c12a7328-f81f-11d2-ba4b-00a0c93ec93b
        path: /dev/sda2
        size: 4349952
        type: partition
    -   device: disk-sda
        id: partition-sda3
        number: 3
        offset: 1474533376
        partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
        path: /dev/sda3
        size: 307200
        type: partition
    -   device: disk-sda
        flag: linux
        id: partition-sda4
        number: 4
        offset: 1476395008
        partition_type: 0fc63daf-8483-4772-8e79-3d69d8477de4
        path: /dev/sda4
        size: 14042497536
        type: partition
    -   fstype: iso9660
        id: format-partition-sda1
        type: format
        volume: partition-sda1
    -   fstype: vfat
        id: format-partition-sda2
        type: format
        volume: partition-sda2
    -   fstype: ext4
        id: format-partition-sda4
        type: format
        uuid: bd8a4591-a294-4e33-a2c7-9994a64fd352
        volume: partition-sda4
    -   device: format-partition-sda1
        id: mount-partition-sda1
        path: /cdrom
        type: mount
    version: 2

2022-11-24 15:42:28,842 DEBUG subiquity.models.filesystem:1271 exclusions {'partition-sda2', 'partition-sda3', 'partition-sda1', 'format-partition-sda2', 'format-disk-sda', 'format-partition-sda1', 'disk-sda', 'format-partition-sda4', 'partition-sda4'}
2022-11-24 15:42:28,842 DEBUG root:37 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False
2022-11-24 15:42:28,842 DEBUG root:37 finish: subiquity/Filesystem/_probe: SUCCESS: 
2022-11-24 15:42:29,948 DEBUG root:37 start: subiquity/Mirror/POST: 
2022-11-24 15:42:29,948 DEBUG subiquity.server.controllers.mirror:155 http://at.archive.ubuntu.com/ubuntu
2022-11-24 15:42:29,948 DEBUG subiquity.models.subiquity:231 model mirror for install stage is configured, to go {'filesystem'}
2022-11-24 15:42:29,949 DEBUG root:37 finish: subiquity/Mirror/POST: SUCCESS: 200 null
2022-11-24 15:42:29,949 INFO aiohttp.access:233  [24/Nov/2022:15:42:29 +0000] "POST /mirror HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:42:29,949 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', 'mount', '-o', 'lowerdir=/tmp/tmp0lzaqorp/root.dir,upperdir=/tmp/tmpheopm7ow/upper,workdir=/tmp/tmpheopm7ow/work', '-t', 'overlay', 'overlay', '/tmp/tmpheopm7ow/mount']
2022-11-24 15:42:29,956 DEBUG root:37 start: subiquity/Filesystem/guided_GET: 
2022-11-24 15:42:29,957 DEBUG root:37 finish: subiquity/Filesystem/guided_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-nvme0n1", "la...
2022-11-24 15:42:29,957 INFO aiohttp.access:233  [24/Nov/2022:15:42:29 +0000] "GET /storage/guided HTTP/1.1" 200 1500 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:42:29,991 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', '/snap/subiquity/4003/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.3294.1"}}', '-c', '/var/log/installer/subiquity-curtin-apt.conf', 'apt-config', '-t', '/tmp/tmpheopm7ow/mount']
2022-11-24 15:42:30,493 DEBUG root:37 start: subiquity/Mirror/cmd-apt-config: curtin command apt-config
2022-11-24 15:42:30,831 DEBUG subiquity.server.curtin:121 waited 0.1 seconds for events to drain
2022-11-24 15:42:30,843 DEBUG root:37 finish: subiquity/Mirror/cmd-apt-config: SUCCESS: curtin command apt-config
2022-11-24 15:42:30,931 DEBUG subiquity.server.curtin:121 waited 0.2 seconds for events to drain
2022-11-24 15:43:13,812 DEBUG root:37 start: subiquity/Filesystem/GET: 
2022-11-24 15:43:13,813 DEBUG subiquity.models.filesystem:1336 mountpoints {}
2022-11-24 15:43:13,813 DEBUG root:37 finish: subiquity/Filesystem/GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "bootloader": "UEFI", "orig_config":...
2022-11-24 15:43:13,814 INFO aiohttp.access:233  [24/Nov/2022:15:43:13 +0000] "GET /storage?use_cached_result=true HTTP/1.1" 200 27703 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:43:23,980 DEBUG root:37 start: subiquity/Filesystem/reset_POST: 
2022-11-24 15:43:23,980 INFO subiquity.server.controllers.filesystem:354 Resetting Filesystem model
2022-11-24 15:43:23,980 DEBUG curtin:1303 Extracting storage config from probe data
2022-11-24 15:43:23,980 DEBUG curtin:73 /dev/nvme0n1 is multipath device member? False
2022-11-24 15:43:23,980 DEBUG curtin:86 /dev/nvme0n1 is multipath device partition? False
2022-11-24 15:43:23,980 DEBUG curtin:61 /dev/nvme0n1 is multipath device? False
2022-11-24 15:43:23,980 DEBUG curtin:86 /dev/nvme0n1 is multipath device partition? False
2022-11-24 15:43:23,980 DEBUG curtin:61 /dev/nvme0n1 is multipath device? False
2022-11-24 15:43:23,988 DEBUG curtin:73 /dev/nvme0n1p1 is multipath device member? False
2022-11-24 15:43:23,988 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:43:23,988 DEBUG curtin:61 /dev/nvme0n1p1 is multipath device? False
2022-11-24 15:43:23,988 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:43:23,988 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:43:23,995 DEBUG curtin:73 /dev/sda is multipath device member? False
2022-11-24 15:43:23,996 DEBUG curtin:86 /dev/sda is multipath device partition? False
2022-11-24 15:43:23,996 DEBUG curtin:61 /dev/sda is multipath device? False
2022-11-24 15:43:23,996 DEBUG curtin:86 /dev/sda is multipath device partition? False
2022-11-24 15:43:23,996 DEBUG curtin:61 /dev/sda is multipath device? False
2022-11-24 15:43:24,003 DEBUG curtin:73 /dev/sda1 is multipath device member? False
2022-11-24 15:43:24,003 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:43:24,003 DEBUG curtin:61 /dev/sda1 is multipath device? False
2022-11-24 15:43:24,003 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:43:24,003 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:43:24,011 DEBUG curtin:73 /dev/sda2 is multipath device member? False
2022-11-24 15:43:24,011 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:43:24,011 DEBUG curtin:61 /dev/sda2 is multipath device? False
2022-11-24 15:43:24,011 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:43:24,011 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:43:24,018 DEBUG curtin:73 /dev/sda3 is multipath device member? False
2022-11-24 15:43:24,018 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:43:24,018 DEBUG curtin:61 /dev/sda3 is multipath device? False
2022-11-24 15:43:24,018 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:43:24,018 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:43:24,025 DEBUG curtin:73 /dev/sda4 is multipath device member? False
2022-11-24 15:43:24,025 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:43:24,025 DEBUG curtin:61 /dev/sda4 is multipath device? False
2022-11-24 15:43:24,025 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:43:24,026 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:43:24,033 DEBUG curtin:73 /dev/sdb is multipath device member? False
2022-11-24 15:43:24,033 DEBUG curtin:86 /dev/sdb is multipath device partition? False
2022-11-24 15:43:24,033 DEBUG curtin:61 /dev/sdb is multipath device? False
2022-11-24 15:43:24,033 DEBUG curtin:86 /dev/sdb is multipath device partition? False
2022-11-24 15:43:24,033 DEBUG curtin:61 /dev/sdb is multipath device? False
2022-11-24 15:43:24,039 DEBUG curtin:73 /dev/sdb1 is multipath device member? False
2022-11-24 15:43:24,039 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:43:24,039 DEBUG curtin:61 /dev/sdb1 is multipath device? False
2022-11-24 15:43:24,039 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:43:24,039 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:43:24,045 DEBUG curtin:73 /dev/nvme0n1p1 is multipath device member? False
2022-11-24 15:43:24,050 DEBUG curtin:73 /dev/sda is multipath device member? False
2022-11-24 15:43:24,055 DEBUG curtin:73 /dev/sda1 is multipath device member? False
2022-11-24 15:43:24,060 DEBUG curtin:73 /dev/sda2 is multipath device member? False
2022-11-24 15:43:24,064 DEBUG curtin:73 /dev/sda4 is multipath device member? False
2022-11-24 15:43:24,069 DEBUG curtin:73 /dev/sdb1 is multipath device member? False
2022-11-24 15:43:24,077 DEBUG curtin:1310 Sorting extracted configurations
2022-11-24 15:43:24,077 INFO curtin:1329 Validating extracted storage config components
2022-11-24 15:43:24,084 DEBUG curtin:1346 Extracted (unmerged) storage config:
storage:
-   id: disk-nvme0n1
    path: /dev/nvme0n1
    ptable: dos
    serial: Samsung_SSD_980_PRO_1TB_S5GXNX0T928425D
    type: disk
    wwn: eui.002538b921b60521
-   id: disk-sda
    path: /dev/sda
    ptable: gpt
    serial: ADATA_USB_Flash_Drive_2811008210170075-0:0
    type: disk
-   id: disk-sdb
    path: /dev/sdb
    ptable: dos
    serial: ST4000VN008-2DR166_ZDHBX28T
    type: disk
    wwn: '0x5000c500e5bb0ccf'
-   device: disk-nvme0n1
    id: partition-nvme0n1p1
    number: 1
    offset: 1048576
    partition_type: '0x7'
    path: /dev/nvme0n1p1
    size: 1000202043392
    type: partition
-   device: disk-sda
    id: partition-sda1
    number: 1
    offset: 32768
    partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
    path: /dev/sda1
    size: 1470150656
    type: partition
-   device: disk-sda
    flag: boot
    id: partition-sda2
    number: 2
    offset: 1470183424
    partition_type: c12a7328-f81f-11d2-ba4b-00a0c93ec93b
    path: /dev/sda2
    size: 4349952
    type: partition
-   device: disk-sda
    id: partition-sda3
    number: 3
    offset: 1474533376
    partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
    path: /dev/sda3
    size: 307200
    type: partition
-   device: disk-sda
    flag: linux
    id: partition-sda4
    number: 4
    offset: 1476395008
    partition_type: 0fc63daf-8483-4772-8e79-3d69d8477de4
    path: /dev/sda4
    size: 14042497536
    type: partition
-   device: disk-sdb
    id: partition-sdb1
    number: 1
    offset: 1048576
    partition_type: '0x7'
    path: /dev/sdb1
    size: 2199022206976
    type: partition
-   fstype: ntfs
    id: format-partition-nvme0n1p1
    type: format
    volume: partition-nvme0n1p1
-   fstype: iso9660
    id: format-disk-sda
    type: format
    volume: disk-sda
-   fstype: iso9660
    id: format-partition-sda1
    type: format
    volume: partition-sda1
-   fstype: vfat
    id: format-partition-sda2
    type: format
    volume: partition-sda2
-   fstype: ext4
    id: format-partition-sda4
    type: format
    uuid: bd8a4591-a294-4e33-a2c7-9994a64fd352
    volume: partition-sda4
-   fstype: ntfs
    id: format-partition-sdb1
    type: format
    volume: partition-sdb1
-   device: format-partition-sda1
    id: mount-partition-sda1
    path: /cdrom
    type: mount

2022-11-24 15:43:24,084 DEBUG curtin:1350 Generating storage config dependencies
2022-11-24 15:43:24,084 DEBUG curtin:236 Validate: partition-nvme0n1p1:SourceType:partition -> (DepId:disk-nvme0n1 DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:43:24,084 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:43:24,084 DEBUG curtin:236 Validate: partition-sda2:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:43:24,084 DEBUG curtin:236 Validate: partition-sda3:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:43:24,084 DEBUG curtin:236 Validate: partition-sda4:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:43:24,084 DEBUG curtin:236 Validate: partition-sdb1:SourceType:partition -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:43:24,084 DEBUG curtin:236 Validate: format-partition-nvme0n1p1:SourceType:format -> (DepId:partition-nvme0n1p1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:43:24,084 DEBUG curtin:236 Validate: partition-nvme0n1p1:SourceType:partition -> (DepId:disk-nvme0n1 DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:43:24,084 DEBUG curtin:236 Validate: format-disk-sda:SourceType:format -> (DepId:disk-sda DepType:disk) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:43:24,084 DEBUG curtin:236 Validate: format-partition-sda1:SourceType:format -> (DepId:partition-sda1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:43:24,084 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:43:24,085 DEBUG curtin:236 Validate: format-partition-sda2:SourceType:format -> (DepId:partition-sda2 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:43:24,085 DEBUG curtin:236 Validate: partition-sda2:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:43:24,085 DEBUG curtin:236 Validate: format-partition-sda4:SourceType:format -> (DepId:partition-sda4 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:43:24,085 DEBUG curtin:236 Validate: partition-sda4:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:43:24,085 DEBUG curtin:236 Validate: format-partition-sdb1:SourceType:format -> (DepId:partition-sdb1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:43:24,085 DEBUG curtin:236 Validate: partition-sdb1:SourceType:partition -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:43:24,085 DEBUG curtin:236 Validate: mount-partition-sda1:SourceType:mount -> (DepId:format-partition-sda1 DepType:format) in SourceDeps:{'format'} ? result=True
2022-11-24 15:43:24,085 DEBUG curtin:236 Validate: format-partition-sda1:SourceType:format -> (DepId:partition-sda1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:43:24,085 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:43:24,085 DEBUG curtin:1356 Merging storage config dependencies
2022-11-24 15:43:24,087 DEBUG curtin:1361 Merged storage config:
storage:
    config:
    -   id: disk-nvme0n1
        path: /dev/nvme0n1
        ptable: dos
        serial: Samsung_SSD_980_PRO_1TB_S5GXNX0T928425D
        type: disk
        wwn: eui.002538b921b60521
    -   id: disk-sda
        path: /dev/sda
        ptable: gpt
        serial: ADATA_USB_Flash_Drive_2811008210170075-0:0
        type: disk
    -   id: disk-sdb
        path: /dev/sdb
        ptable: dos
        serial: ST4000VN008-2DR166_ZDHBX28T
        type: disk
        wwn: '0x5000c500e5bb0ccf'
    -   fstype: iso9660
        id: format-disk-sda
        type: format
        volume: disk-sda
    -   device: disk-nvme0n1
        id: partition-nvme0n1p1
        number: 1
        offset: 1048576
        partition_type: '0x7'
        path: /dev/nvme0n1p1
        size: 1000202043392
        type: partition
    -   device: disk-sdb
        id: partition-sdb1
        number: 1
        offset: 1048576
        partition_type: '0x7'
        path: /dev/sdb1
        size: 2199022206976
        type: partition
    -   fstype: ntfs
        id: format-partition-nvme0n1p1
        type: format
        volume: partition-nvme0n1p1
    -   fstype: ntfs
        id: format-partition-sdb1
        type: format
        volume: partition-sdb1
    -   device: disk-sda
        id: partition-sda1
        number: 1
        offset: 32768
        partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
        path: /dev/sda1
        size: 1470150656
        type: partition
    -   device: disk-sda
        flag: boot
        id: partition-sda2
        number: 2
        offset: 1470183424
        partition_type: c12a7328-f81f-11d2-ba4b-00a0c93ec93b
        path: /dev/sda2
        size: 4349952
        type: partition
    -   device: disk-sda
        id: partition-sda3
        number: 3
        offset: 1474533376
        partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
        path: /dev/sda3
        size: 307200
        type: partition
    -   device: disk-sda
        flag: linux
        id: partition-sda4
        number: 4
        offset: 1476395008
        partition_type: 0fc63daf-8483-4772-8e79-3d69d8477de4
        path: /dev/sda4
        size: 14042497536
        type: partition
    -   fstype: iso9660
        id: format-partition-sda1
        type: format
        volume: partition-sda1
    -   fstype: vfat
        id: format-partition-sda2
        type: format
        volume: partition-sda2
    -   fstype: ext4
        id: format-partition-sda4
        type: format
        uuid: bd8a4591-a294-4e33-a2c7-9994a64fd352
        volume: partition-sda4
    -   device: format-partition-sda1
        id: mount-partition-sda1
        path: /cdrom
        type: mount
    version: 2

2022-11-24 15:43:24,087 DEBUG subiquity.models.filesystem:1271 exclusions {'partition-sda2', 'partition-sda1', 'partition-sda3', 'format-partition-sda2', 'format-disk-sda', 'format-partition-sda1', 'disk-sda', 'format-partition-sda4', 'partition-sda4'}
2022-11-24 15:43:24,087 DEBUG subiquity.models.filesystem:1336 mountpoints {}
2022-11-24 15:43:24,087 DEBUG root:37 finish: subiquity/Filesystem/reset_POST: SUCCESS: 200 {"status": "DONE", "error_report": null, "bootloader": "UEFI", "orig_config":...
2022-11-24 15:43:24,087 INFO aiohttp.access:233  [24/Nov/2022:15:43:23 +0000] "POST /storage/reset HTTP/1.1" 200 27703 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:43:24,087 DEBUG root:37 start: subiquity/Filesystem/guided_GET: 
2022-11-24 15:43:24,088 DEBUG root:37 finish: subiquity/Filesystem/guided_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-nvme0n1", "la...
2022-11-24 15:43:24,088 INFO aiohttp.access:233  [24/Nov/2022:15:43:24 +0000] "GET /storage/guided HTTP/1.1" 200 1500 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:43:26,514 DEBUG root:37 start: subiquity/Mirror/GET: 
2022-11-24 15:43:26,515 DEBUG root:37 finish: subiquity/Mirror/GET: SUCCESS: 200 "http://at.archive.ubuntu.com/ubuntu"
2022-11-24 15:43:26,515 INFO aiohttp.access:233  [24/Nov/2022:15:43:26 +0000] "GET /mirror HTTP/1.1" 200 224 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:43:28,252 DEBUG root:37 start: subiquity/Mirror/POST: 
2022-11-24 15:43:28,252 DEBUG subiquity.server.controllers.mirror:155 http://at.archive.ubuntu.com/ubuntu
2022-11-24 15:43:28,252 DEBUG subiquity.models.subiquity:231 model mirror for install stage is configured, to go {'filesystem'}
2022-11-24 15:43:28,252 DEBUG root:37 finish: subiquity/Mirror/POST: SUCCESS: 200 null
2022-11-24 15:43:28,252 INFO aiohttp.access:233  [24/Nov/2022:15:43:28 +0000] "POST /mirror HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:43:28,253 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', 'mount', '-o', 'lowerdir=/tmp/tmp0lzaqorp/root.dir,upperdir=/tmp/tmp3sh1vg5_/upper,workdir=/tmp/tmp3sh1vg5_/work', '-t', 'overlay', 'overlay', '/tmp/tmp3sh1vg5_/mount']
2022-11-24 15:43:28,255 DEBUG root:37 start: subiquity/Filesystem/guided_GET: 
2022-11-24 15:43:28,256 DEBUG root:37 finish: subiquity/Filesystem/guided_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-nvme0n1", "la...
2022-11-24 15:43:28,256 INFO aiohttp.access:233  [24/Nov/2022:15:43:28 +0000] "GET /storage/guided HTTP/1.1" 200 1500 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:43:28,299 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', '/snap/subiquity/4003/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.3294.2"}}', '-c', '/var/log/installer/subiquity-curtin-apt.conf', 'apt-config', '-t', '/tmp/tmp3sh1vg5_/mount']
2022-11-24 15:43:29,242 DEBUG root:37 start: subiquity/Mirror/GET: 
2022-11-24 15:43:29,242 DEBUG root:37 finish: subiquity/Mirror/GET: SUCCESS: 200 "http://at.archive.ubuntu.com/ubuntu"
2022-11-24 15:43:29,242 INFO aiohttp.access:233  [24/Nov/2022:15:43:29 +0000] "GET /mirror HTTP/1.1" 200 224 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:43:29,812 DEBUG root:37 start: subiquity/Mirror/POST: 
2022-11-24 15:43:29,812 DEBUG subiquity.server.controllers.mirror:155 http://at.archive.ubuntu.com/ubuntu
2022-11-24 15:43:29,812 DEBUG subiquity.models.subiquity:231 model mirror for install stage is configured, to go {'filesystem'}
2022-11-24 15:43:29,812 DEBUG root:37 finish: subiquity/Mirror/POST: SUCCESS: 200 null
2022-11-24 15:43:29,813 INFO aiohttp.access:233  [24/Nov/2022:15:43:29 +0000] "POST /mirror HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:43:29,813 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', 'mount', '-o', 'lowerdir=/tmp/tmp0lzaqorp/root.dir,upperdir=/tmp/tmpd_f01i21/upper,workdir=/tmp/tmpd_f01i21/work', '-t', 'overlay', 'overlay', '/tmp/tmpd_f01i21/mount']
2022-11-24 15:43:29,816 DEBUG root:37 start: subiquity/Filesystem/guided_GET: 
2022-11-24 15:43:29,817 DEBUG root:37 finish: subiquity/Filesystem/guided_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-nvme0n1", "la...
2022-11-24 15:43:29,817 INFO aiohttp.access:233  [24/Nov/2022:15:43:29 +0000] "GET /storage/guided HTTP/1.1" 200 1500 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:43:29,864 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', '/snap/subiquity/4003/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.3294.3"}}', '-c', '/var/log/installer/subiquity-curtin-apt.conf', 'apt-config', '-t', '/tmp/tmpd_f01i21/mount']
2022-11-24 15:43:30,107 DEBUG root:37 start: subiquity/Mirror/cmd-apt-config: curtin command apt-config
2022-11-24 15:43:30,313 DEBUG subiquity.server.curtin:121 waited 0.1 seconds for events to drain
2022-11-24 15:43:30,413 DEBUG subiquity.server.curtin:121 waited 0.2 seconds for events to drain
2022-11-24 15:43:30,514 DEBUG subiquity.server.curtin:121 waited 0.30000000000000004 seconds for events to drain
2022-11-24 15:43:30,594 DEBUG root:37 finish: subiquity/Mirror/cmd-apt-config: SUCCESS: curtin command apt-config
2022-11-24 15:43:30,614 DEBUG subiquity.server.curtin:121 waited 0.4 seconds for events to drain
2022-11-24 15:43:32,676 DEBUG root:37 start: subiquity/Filesystem/guided_POST: 
2022-11-24 15:43:32,676 DEBUG subiquity.server.controllers.filesystem:349 GuidedChoice(disk_id='disk-nvme0n1', use_lvm=True)
2022-11-24 15:43:32,677 DEBUG subiquity.models.filesystem:1450 add_partition: rounded size from 1127219200 to 1127219200
2022-11-24 15:43:32,677 DEBUG subiquity.models.filesystem:1526 adding fat32 to Partition(device=disk-nvme0n1, size=1127219200, wipe='superblock', flag='boot', number=1, grub_device=True, offset=1048576, id='partition-0')
2022-11-24 15:43:32,677 DEBUG subiquity.models.filesystem:1450 add_partition: rounded size from 2147483648 to 2147483648
2022-11-24 15:43:32,677 DEBUG subiquity.models.filesystem:1526 adding ext4 to Partition(device=disk-nvme0n1, size=2147483648, wipe='superblock', number=2, grub_device=None, offset=1128267776, id='partition-1')
2022-11-24 15:43:32,677 DEBUG subiquity.models.filesystem:1450 add_partition: rounded size from 996927340544 to 996927340544
2022-11-24 15:43:32,677 DEBUG subiquity.models.filesystem:1526 adding ext4 to LVM_LogicalVolume(name='ubuntu-lv', volgroup=lvm_volgroup-0, size=107374182400, wipe='superblock', id='lvm_partition-0')
2022-11-24 15:43:32,677 DEBUG subiquity.models.filesystem:1336 mountpoints {'/boot/efi': 'mount-0', '/boot': 'mount-1', '/': 'mount-2'}
2022-11-24 15:43:32,677 DEBUG subiquity.models.filesystem:1329 cannot emit action to mount /boot/efi until that for /boot is emitted
2022-11-24 15:43:32,677 DEBUG subiquity.models.filesystem:1329 cannot emit action to mount /boot until that for / is emitted
2022-11-24 15:43:32,677 DEBUG subiquity.models.filesystem:1329 cannot emit action to mount /boot/efi until that for /boot is emitted
2022-11-24 15:43:32,678 DEBUG root:37 finish: subiquity/Filesystem/guided_POST: SUCCESS: 200 {"status": "DONE", "error_report": null, "bootloader": "UEFI", "orig_config":...
2022-11-24 15:43:32,678 INFO aiohttp.access:233  [24/Nov/2022:15:43:32 +0000] "POST /storage/guided HTTP/1.1" 200 28762 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:47:38,965 DEBUG root:37 start: subiquity/Filesystem/reset_POST: 
2022-11-24 15:47:38,965 INFO subiquity.server.controllers.filesystem:354 Resetting Filesystem model
2022-11-24 15:47:38,965 DEBUG curtin:1303 Extracting storage config from probe data
2022-11-24 15:47:38,965 DEBUG curtin:73 /dev/nvme0n1 is multipath device member? False
2022-11-24 15:47:38,965 DEBUG curtin:86 /dev/nvme0n1 is multipath device partition? False
2022-11-24 15:47:38,965 DEBUG curtin:61 /dev/nvme0n1 is multipath device? False
2022-11-24 15:47:38,965 DEBUG curtin:86 /dev/nvme0n1 is multipath device partition? False
2022-11-24 15:47:38,965 DEBUG curtin:61 /dev/nvme0n1 is multipath device? False
2022-11-24 15:47:38,973 DEBUG curtin:73 /dev/nvme0n1p1 is multipath device member? False
2022-11-24 15:47:38,973 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:47:38,973 DEBUG curtin:61 /dev/nvme0n1p1 is multipath device? False
2022-11-24 15:47:38,973 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:47:38,973 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:47:38,981 DEBUG curtin:73 /dev/sda is multipath device member? False
2022-11-24 15:47:38,981 DEBUG curtin:86 /dev/sda is multipath device partition? False
2022-11-24 15:47:38,981 DEBUG curtin:61 /dev/sda is multipath device? False
2022-11-24 15:47:38,981 DEBUG curtin:86 /dev/sda is multipath device partition? False
2022-11-24 15:47:38,981 DEBUG curtin:61 /dev/sda is multipath device? False
2022-11-24 15:47:38,988 DEBUG curtin:73 /dev/sda1 is multipath device member? False
2022-11-24 15:47:38,988 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:47:38,988 DEBUG curtin:61 /dev/sda1 is multipath device? False
2022-11-24 15:47:38,988 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:47:38,988 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:47:38,996 DEBUG curtin:73 /dev/sda2 is multipath device member? False
2022-11-24 15:47:38,996 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:47:38,996 DEBUG curtin:61 /dev/sda2 is multipath device? False
2022-11-24 15:47:38,996 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:47:38,996 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:47:39,003 DEBUG curtin:73 /dev/sda3 is multipath device member? False
2022-11-24 15:47:39,003 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:47:39,003 DEBUG curtin:61 /dev/sda3 is multipath device? False
2022-11-24 15:47:39,003 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:47:39,003 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:47:39,010 DEBUG curtin:73 /dev/sda4 is multipath device member? False
2022-11-24 15:47:39,010 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:47:39,010 DEBUG curtin:61 /dev/sda4 is multipath device? False
2022-11-24 15:47:39,010 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:47:39,010 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:47:39,017 DEBUG curtin:73 /dev/sdb is multipath device member? False
2022-11-24 15:47:39,017 DEBUG curtin:86 /dev/sdb is multipath device partition? False
2022-11-24 15:47:39,017 DEBUG curtin:61 /dev/sdb is multipath device? False
2022-11-24 15:47:39,017 DEBUG curtin:86 /dev/sdb is multipath device partition? False
2022-11-24 15:47:39,017 DEBUG curtin:61 /dev/sdb is multipath device? False
2022-11-24 15:47:39,024 DEBUG curtin:73 /dev/sdb1 is multipath device member? False
2022-11-24 15:47:39,024 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:47:39,024 DEBUG curtin:61 /dev/sdb1 is multipath device? False
2022-11-24 15:47:39,024 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:47:39,024 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:47:39,029 DEBUG curtin:73 /dev/nvme0n1p1 is multipath device member? False
2022-11-24 15:47:39,035 DEBUG curtin:73 /dev/sda is multipath device member? False
2022-11-24 15:47:39,040 DEBUG curtin:73 /dev/sda1 is multipath device member? False
2022-11-24 15:47:39,044 DEBUG curtin:73 /dev/sda2 is multipath device member? False
2022-11-24 15:47:39,049 DEBUG curtin:73 /dev/sda4 is multipath device member? False
2022-11-24 15:47:39,053 DEBUG curtin:73 /dev/sdb1 is multipath device member? False
2022-11-24 15:47:39,062 DEBUG curtin:1310 Sorting extracted configurations
2022-11-24 15:47:39,062 INFO curtin:1329 Validating extracted storage config components
2022-11-24 15:47:39,069 DEBUG curtin:1346 Extracted (unmerged) storage config:
storage:
-   id: disk-nvme0n1
    path: /dev/nvme0n1
    ptable: dos
    serial: Samsung_SSD_980_PRO_1TB_S5GXNX0T928425D
    type: disk
    wwn: eui.002538b921b60521
-   id: disk-sda
    path: /dev/sda
    ptable: gpt
    serial: ADATA_USB_Flash_Drive_2811008210170075-0:0
    type: disk
-   id: disk-sdb
    path: /dev/sdb
    ptable: dos
    serial: ST4000VN008-2DR166_ZDHBX28T
    type: disk
    wwn: '0x5000c500e5bb0ccf'
-   device: disk-nvme0n1
    id: partition-nvme0n1p1
    number: 1
    offset: 1048576
    partition_type: '0x7'
    path: /dev/nvme0n1p1
    size: 1000202043392
    type: partition
-   device: disk-sda
    id: partition-sda1
    number: 1
    offset: 32768
    partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
    path: /dev/sda1
    size: 1470150656
    type: partition
-   device: disk-sda
    flag: boot
    id: partition-sda2
    number: 2
    offset: 1470183424
    partition_type: c12a7328-f81f-11d2-ba4b-00a0c93ec93b
    path: /dev/sda2
    size: 4349952
    type: partition
-   device: disk-sda
    id: partition-sda3
    number: 3
    offset: 1474533376
    partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
    path: /dev/sda3
    size: 307200
    type: partition
-   device: disk-sda
    flag: linux
    id: partition-sda4
    number: 4
    offset: 1476395008
    partition_type: 0fc63daf-8483-4772-8e79-3d69d8477de4
    path: /dev/sda4
    size: 14042497536
    type: partition
-   device: disk-sdb
    id: partition-sdb1
    number: 1
    offset: 1048576
    partition_type: '0x7'
    path: /dev/sdb1
    size: 2199022206976
    type: partition
-   fstype: ntfs
    id: format-partition-nvme0n1p1
    type: format
    volume: partition-nvme0n1p1
-   fstype: iso9660
    id: format-disk-sda
    type: format
    volume: disk-sda
-   fstype: iso9660
    id: format-partition-sda1
    type: format
    volume: partition-sda1
-   fstype: vfat
    id: format-partition-sda2
    type: format
    volume: partition-sda2
-   fstype: ext4
    id: format-partition-sda4
    type: format
    uuid: bd8a4591-a294-4e33-a2c7-9994a64fd352
    volume: partition-sda4
-   fstype: ntfs
    id: format-partition-sdb1
    type: format
    volume: partition-sdb1
-   device: format-partition-sda1
    id: mount-partition-sda1
    path: /cdrom
    type: mount

2022-11-24 15:47:39,069 DEBUG curtin:1350 Generating storage config dependencies
2022-11-24 15:47:39,069 DEBUG curtin:236 Validate: partition-nvme0n1p1:SourceType:partition -> (DepId:disk-nvme0n1 DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:47:39,069 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:47:39,069 DEBUG curtin:236 Validate: partition-sda2:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:47:39,069 DEBUG curtin:236 Validate: partition-sda3:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:47:39,069 DEBUG curtin:236 Validate: partition-sda4:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:47:39,069 DEBUG curtin:236 Validate: partition-sdb1:SourceType:partition -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:47:39,069 DEBUG curtin:236 Validate: format-partition-nvme0n1p1:SourceType:format -> (DepId:partition-nvme0n1p1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:47:39,069 DEBUG curtin:236 Validate: partition-nvme0n1p1:SourceType:partition -> (DepId:disk-nvme0n1 DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:47:39,069 DEBUG curtin:236 Validate: format-disk-sda:SourceType:format -> (DepId:disk-sda DepType:disk) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:47:39,069 DEBUG curtin:236 Validate: format-partition-sda1:SourceType:format -> (DepId:partition-sda1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:47:39,069 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:47:39,069 DEBUG curtin:236 Validate: format-partition-sda2:SourceType:format -> (DepId:partition-sda2 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:47:39,069 DEBUG curtin:236 Validate: partition-sda2:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:47:39,069 DEBUG curtin:236 Validate: format-partition-sda4:SourceType:format -> (DepId:partition-sda4 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:47:39,069 DEBUG curtin:236 Validate: partition-sda4:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:47:39,070 DEBUG curtin:236 Validate: format-partition-sdb1:SourceType:format -> (DepId:partition-sdb1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:47:39,070 DEBUG curtin:236 Validate: partition-sdb1:SourceType:partition -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:47:39,070 DEBUG curtin:236 Validate: mount-partition-sda1:SourceType:mount -> (DepId:format-partition-sda1 DepType:format) in SourceDeps:{'format'} ? result=True
2022-11-24 15:47:39,070 DEBUG curtin:236 Validate: format-partition-sda1:SourceType:format -> (DepId:partition-sda1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:47:39,070 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:47:39,070 DEBUG curtin:1356 Merging storage config dependencies
2022-11-24 15:47:39,072 DEBUG curtin:1361 Merged storage config:
storage:
    config:
    -   id: disk-nvme0n1
        path: /dev/nvme0n1
        ptable: dos
        serial: Samsung_SSD_980_PRO_1TB_S5GXNX0T928425D
        type: disk
        wwn: eui.002538b921b60521
    -   id: disk-sda
        path: /dev/sda
        ptable: gpt
        serial: ADATA_USB_Flash_Drive_2811008210170075-0:0
        type: disk
    -   id: disk-sdb
        path: /dev/sdb
        ptable: dos
        serial: ST4000VN008-2DR166_ZDHBX28T
        type: disk
        wwn: '0x5000c500e5bb0ccf'
    -   fstype: iso9660
        id: format-disk-sda
        type: format
        volume: disk-sda
    -   device: disk-nvme0n1
        id: partition-nvme0n1p1
        number: 1
        offset: 1048576
        partition_type: '0x7'
        path: /dev/nvme0n1p1
        size: 1000202043392
        type: partition
    -   device: disk-sdb
        id: partition-sdb1
        number: 1
        offset: 1048576
        partition_type: '0x7'
        path: /dev/sdb1
        size: 2199022206976
        type: partition
    -   fstype: ntfs
        id: format-partition-nvme0n1p1
        type: format
        volume: partition-nvme0n1p1
    -   fstype: ntfs
        id: format-partition-sdb1
        type: format
        volume: partition-sdb1
    -   device: disk-sda
        id: partition-sda1
        number: 1
        offset: 32768
        partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
        path: /dev/sda1
        size: 1470150656
        type: partition
    -   device: disk-sda
        flag: boot
        id: partition-sda2
        number: 2
        offset: 1470183424
        partition_type: c12a7328-f81f-11d2-ba4b-00a0c93ec93b
        path: /dev/sda2
        size: 4349952
        type: partition
    -   device: disk-sda
        id: partition-sda3
        number: 3
        offset: 1474533376
        partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
        path: /dev/sda3
        size: 307200
        type: partition
    -   device: disk-sda
        flag: linux
        id: partition-sda4
        number: 4
        offset: 1476395008
        partition_type: 0fc63daf-8483-4772-8e79-3d69d8477de4
        path: /dev/sda4
        size: 14042497536
        type: partition
    -   fstype: iso9660
        id: format-partition-sda1
        type: format
        volume: partition-sda1
    -   fstype: vfat
        id: format-partition-sda2
        type: format
        volume: partition-sda2
    -   fstype: ext4
        id: format-partition-sda4
        type: format
        uuid: bd8a4591-a294-4e33-a2c7-9994a64fd352
        volume: partition-sda4
    -   device: format-partition-sda1
        id: mount-partition-sda1
        path: /cdrom
        type: mount
    version: 2

2022-11-24 15:47:39,072 DEBUG subiquity.models.filesystem:1271 exclusions {'partition-sda2', 'partition-sda1', 'partition-sda3', 'format-partition-sda2', 'format-disk-sda', 'format-partition-sda1', 'disk-sda', 'format-partition-sda4', 'partition-sda4'}
2022-11-24 15:47:39,072 DEBUG subiquity.models.filesystem:1336 mountpoints {}
2022-11-24 15:47:39,072 DEBUG root:37 finish: subiquity/Filesystem/reset_POST: SUCCESS: 200 {"status": "DONE", "error_report": null, "bootloader": "UEFI", "orig_config":...
2022-11-24 15:47:39,072 INFO aiohttp.access:233  [24/Nov/2022:15:47:38 +0000] "POST /storage/reset HTTP/1.1" 200 27703 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:47:39,072 DEBUG root:37 start: subiquity/Filesystem/guided_GET: 
2022-11-24 15:47:39,073 DEBUG root:37 finish: subiquity/Filesystem/guided_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-nvme0n1", "la...
2022-11-24 15:47:39,073 INFO aiohttp.access:233  [24/Nov/2022:15:47:39 +0000] "GET /storage/guided HTTP/1.1" 200 1500 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:47:45,213 DEBUG root:37 start: subiquity/Filesystem/GET: 
2022-11-24 15:47:45,213 DEBUG subiquity.models.filesystem:1336 mountpoints {}
2022-11-24 15:47:45,213 DEBUG root:37 finish: subiquity/Filesystem/GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "bootloader": "UEFI", "orig_config":...
2022-11-24 15:47:45,214 INFO aiohttp.access:233  [24/Nov/2022:15:47:45 +0000] "GET /storage?use_cached_result=true HTTP/1.1" 200 27703 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:48:10,542 DEBUG root:37 start: subiquity/Filesystem/reset_POST: 
2022-11-24 15:48:10,542 INFO subiquity.server.controllers.filesystem:354 Resetting Filesystem model
2022-11-24 15:48:10,542 DEBUG curtin:1303 Extracting storage config from probe data
2022-11-24 15:48:10,542 DEBUG curtin:73 /dev/nvme0n1 is multipath device member? False
2022-11-24 15:48:10,542 DEBUG curtin:86 /dev/nvme0n1 is multipath device partition? False
2022-11-24 15:48:10,542 DEBUG curtin:61 /dev/nvme0n1 is multipath device? False
2022-11-24 15:48:10,542 DEBUG curtin:86 /dev/nvme0n1 is multipath device partition? False
2022-11-24 15:48:10,542 DEBUG curtin:61 /dev/nvme0n1 is multipath device? False
2022-11-24 15:48:10,548 DEBUG curtin:73 /dev/nvme0n1p1 is multipath device member? False
2022-11-24 15:48:10,548 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:48:10,548 DEBUG curtin:61 /dev/nvme0n1p1 is multipath device? False
2022-11-24 15:48:10,548 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:48:10,548 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:48:10,553 DEBUG curtin:73 /dev/sda is multipath device member? False
2022-11-24 15:48:10,553 DEBUG curtin:86 /dev/sda is multipath device partition? False
2022-11-24 15:48:10,553 DEBUG curtin:61 /dev/sda is multipath device? False
2022-11-24 15:48:10,553 DEBUG curtin:86 /dev/sda is multipath device partition? False
2022-11-24 15:48:10,553 DEBUG curtin:61 /dev/sda is multipath device? False
2022-11-24 15:48:10,558 DEBUG curtin:73 /dev/sda1 is multipath device member? False
2022-11-24 15:48:10,558 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:48:10,558 DEBUG curtin:61 /dev/sda1 is multipath device? False
2022-11-24 15:48:10,558 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:48:10,558 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:48:10,563 DEBUG curtin:73 /dev/sda2 is multipath device member? False
2022-11-24 15:48:10,563 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:48:10,563 DEBUG curtin:61 /dev/sda2 is multipath device? False
2022-11-24 15:48:10,563 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:48:10,563 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:48:10,568 DEBUG curtin:73 /dev/sda3 is multipath device member? False
2022-11-24 15:48:10,568 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:48:10,568 DEBUG curtin:61 /dev/sda3 is multipath device? False
2022-11-24 15:48:10,568 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:48:10,568 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:48:10,573 DEBUG curtin:73 /dev/sda4 is multipath device member? False
2022-11-24 15:48:10,573 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:48:10,573 DEBUG curtin:61 /dev/sda4 is multipath device? False
2022-11-24 15:48:10,573 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:48:10,573 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:48:10,578 DEBUG curtin:73 /dev/sdb is multipath device member? False
2022-11-24 15:48:10,578 DEBUG curtin:86 /dev/sdb is multipath device partition? False
2022-11-24 15:48:10,578 DEBUG curtin:61 /dev/sdb is multipath device? False
2022-11-24 15:48:10,578 DEBUG curtin:86 /dev/sdb is multipath device partition? False
2022-11-24 15:48:10,578 DEBUG curtin:61 /dev/sdb is multipath device? False
2022-11-24 15:48:10,583 DEBUG curtin:73 /dev/sdb1 is multipath device member? False
2022-11-24 15:48:10,583 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:48:10,583 DEBUG curtin:61 /dev/sdb1 is multipath device? False
2022-11-24 15:48:10,583 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:48:10,583 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:48:10,588 DEBUG curtin:73 /dev/nvme0n1p1 is multipath device member? False
2022-11-24 15:48:10,593 DEBUG curtin:73 /dev/sda is multipath device member? False
2022-11-24 15:48:10,597 DEBUG curtin:73 /dev/sda1 is multipath device member? False
2022-11-24 15:48:10,602 DEBUG curtin:73 /dev/sda2 is multipath device member? False
2022-11-24 15:48:10,606 DEBUG curtin:73 /dev/sda4 is multipath device member? False
2022-11-24 15:48:10,611 DEBUG curtin:73 /dev/sdb1 is multipath device member? False
2022-11-24 15:48:10,619 DEBUG curtin:1310 Sorting extracted configurations
2022-11-24 15:48:10,619 INFO curtin:1329 Validating extracted storage config components
2022-11-24 15:48:10,626 DEBUG curtin:1346 Extracted (unmerged) storage config:
storage:
-   id: disk-nvme0n1
    path: /dev/nvme0n1
    ptable: dos
    serial: Samsung_SSD_980_PRO_1TB_S5GXNX0T928425D
    type: disk
    wwn: eui.002538b921b60521
-   id: disk-sda
    path: /dev/sda
    ptable: gpt
    serial: ADATA_USB_Flash_Drive_2811008210170075-0:0
    type: disk
-   id: disk-sdb
    path: /dev/sdb
    ptable: dos
    serial: ST4000VN008-2DR166_ZDHBX28T
    type: disk
    wwn: '0x5000c500e5bb0ccf'
-   device: disk-nvme0n1
    id: partition-nvme0n1p1
    number: 1
    offset: 1048576
    partition_type: '0x7'
    path: /dev/nvme0n1p1
    size: 1000202043392
    type: partition
-   device: disk-sda
    id: partition-sda1
    number: 1
    offset: 32768
    partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
    path: /dev/sda1
    size: 1470150656
    type: partition
-   device: disk-sda
    flag: boot
    id: partition-sda2
    number: 2
    offset: 1470183424
    partition_type: c12a7328-f81f-11d2-ba4b-00a0c93ec93b
    path: /dev/sda2
    size: 4349952
    type: partition
-   device: disk-sda
    id: partition-sda3
    number: 3
    offset: 1474533376
    partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
    path: /dev/sda3
    size: 307200
    type: partition
-   device: disk-sda
    flag: linux
    id: partition-sda4
    number: 4
    offset: 1476395008
    partition_type: 0fc63daf-8483-4772-8e79-3d69d8477de4
    path: /dev/sda4
    size: 14042497536
    type: partition
-   device: disk-sdb
    id: partition-sdb1
    number: 1
    offset: 1048576
    partition_type: '0x7'
    path: /dev/sdb1
    size: 2199022206976
    type: partition
-   fstype: ntfs
    id: format-partition-nvme0n1p1
    type: format
    volume: partition-nvme0n1p1
-   fstype: iso9660
    id: format-disk-sda
    type: format
    volume: disk-sda
-   fstype: iso9660
    id: format-partition-sda1
    type: format
    volume: partition-sda1
-   fstype: vfat
    id: format-partition-sda2
    type: format
    volume: partition-sda2
-   fstype: ext4
    id: format-partition-sda4
    type: format
    uuid: bd8a4591-a294-4e33-a2c7-9994a64fd352
    volume: partition-sda4
-   fstype: ntfs
    id: format-partition-sdb1
    type: format
    volume: partition-sdb1
-   device: format-partition-sda1
    id: mount-partition-sda1
    path: /cdrom
    type: mount

2022-11-24 15:48:10,626 DEBUG curtin:1350 Generating storage config dependencies
2022-11-24 15:48:10,626 DEBUG curtin:236 Validate: partition-nvme0n1p1:SourceType:partition -> (DepId:disk-nvme0n1 DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:10,626 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:10,626 DEBUG curtin:236 Validate: partition-sda2:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: partition-sda3:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: partition-sda4:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: partition-sdb1:SourceType:partition -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: format-partition-nvme0n1p1:SourceType:format -> (DepId:partition-nvme0n1p1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: partition-nvme0n1p1:SourceType:partition -> (DepId:disk-nvme0n1 DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: format-disk-sda:SourceType:format -> (DepId:disk-sda DepType:disk) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: format-partition-sda1:SourceType:format -> (DepId:partition-sda1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: format-partition-sda2:SourceType:format -> (DepId:partition-sda2 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: partition-sda2:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: format-partition-sda4:SourceType:format -> (DepId:partition-sda4 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: partition-sda4:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: format-partition-sdb1:SourceType:format -> (DepId:partition-sdb1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: partition-sdb1:SourceType:partition -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: mount-partition-sda1:SourceType:mount -> (DepId:format-partition-sda1 DepType:format) in SourceDeps:{'format'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: format-partition-sda1:SourceType:format -> (DepId:partition-sda1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:10,627 DEBUG curtin:1356 Merging storage config dependencies
2022-11-24 15:48:10,629 DEBUG curtin:1361 Merged storage config:
storage:
    config:
    -   id: disk-nvme0n1
        path: /dev/nvme0n1
        ptable: dos
        serial: Samsung_SSD_980_PRO_1TB_S5GXNX0T928425D
        type: disk
        wwn: eui.002538b921b60521
    -   id: disk-sda
        path: /dev/sda
        ptable: gpt
        serial: ADATA_USB_Flash_Drive_2811008210170075-0:0
        type: disk
    -   id: disk-sdb
        path: /dev/sdb
        ptable: dos
        serial: ST4000VN008-2DR166_ZDHBX28T
        type: disk
        wwn: '0x5000c500e5bb0ccf'
    -   fstype: iso9660
        id: format-disk-sda
        type: format
        volume: disk-sda
    -   device: disk-nvme0n1
        id: partition-nvme0n1p1
        number: 1
        offset: 1048576
        partition_type: '0x7'
        path: /dev/nvme0n1p1
        size: 1000202043392
        type: partition
    -   device: disk-sdb
        id: partition-sdb1
        number: 1
        offset: 1048576
        partition_type: '0x7'
        path: /dev/sdb1
        size: 2199022206976
        type: partition
    -   fstype: ntfs
        id: format-partition-nvme0n1p1
        type: format
        volume: partition-nvme0n1p1
    -   fstype: ntfs
        id: format-partition-sdb1
        type: format
        volume: partition-sdb1
    -   device: disk-sda
        id: partition-sda1
        number: 1
        offset: 32768
        partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
        path: /dev/sda1
        size: 1470150656
        type: partition
    -   device: disk-sda
        flag: boot
        id: partition-sda2
        number: 2
        offset: 1470183424
        partition_type: c12a7328-f81f-11d2-ba4b-00a0c93ec93b
        path: /dev/sda2
        size: 4349952
        type: partition
    -   device: disk-sda
        id: partition-sda3
        number: 3
        offset: 1474533376
        partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
        path: /dev/sda3
        size: 307200
        type: partition
    -   device: disk-sda
        flag: linux
        id: partition-sda4
        number: 4
        offset: 1476395008
        partition_type: 0fc63daf-8483-4772-8e79-3d69d8477de4
        path: /dev/sda4
        size: 14042497536
        type: partition
    -   fstype: iso9660
        id: format-partition-sda1
        type: format
        volume: partition-sda1
    -   fstype: vfat
        id: format-partition-sda2
        type: format
        volume: partition-sda2
    -   fstype: ext4
        id: format-partition-sda4
        type: format
        uuid: bd8a4591-a294-4e33-a2c7-9994a64fd352
        volume: partition-sda4
    -   device: format-partition-sda1
        id: mount-partition-sda1
        path: /cdrom
        type: mount
    version: 2

2022-11-24 15:48:10,629 DEBUG subiquity.models.filesystem:1271 exclusions {'partition-sda2', 'partition-sda3', 'partition-sda1', 'format-partition-sda2', 'format-disk-sda', 'format-partition-sda1', 'format-partition-sda4', 'disk-sda', 'partition-sda4'}
2022-11-24 15:48:10,629 DEBUG subiquity.models.filesystem:1336 mountpoints {}
2022-11-24 15:48:10,629 DEBUG root:37 finish: subiquity/Filesystem/reset_POST: SUCCESS: 200 {"status": "DONE", "error_report": null, "bootloader": "UEFI", "orig_config":...
2022-11-24 15:48:10,629 INFO aiohttp.access:233  [24/Nov/2022:15:48:10 +0000] "POST /storage/reset HTTP/1.1" 200 27703 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:48:10,629 DEBUG root:37 start: subiquity/Filesystem/guided_GET: 
2022-11-24 15:48:10,630 DEBUG root:37 finish: subiquity/Filesystem/guided_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-nvme0n1", "la...
2022-11-24 15:48:10,630 INFO aiohttp.access:233  [24/Nov/2022:15:48:10 +0000] "GET /storage/guided HTTP/1.1" 200 1500 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:48:13,717 DEBUG root:37 start: subiquity/Filesystem/guided_POST: 
2022-11-24 15:48:13,718 DEBUG subiquity.server.controllers.filesystem:349 GuidedChoice(disk_id='disk-nvme0n1', use_lvm=True)
2022-11-24 15:48:13,718 DEBUG subiquity.models.filesystem:1450 add_partition: rounded size from 1127219200 to 1127219200
2022-11-24 15:48:13,718 DEBUG subiquity.models.filesystem:1526 adding fat32 to Partition(device=disk-nvme0n1, size=1127219200, wipe='superblock', flag='boot', number=1, grub_device=True, offset=1048576, id='partition-0')
2022-11-24 15:48:13,718 DEBUG subiquity.models.filesystem:1450 add_partition: rounded size from 2147483648 to 2147483648
2022-11-24 15:48:13,718 DEBUG subiquity.models.filesystem:1526 adding ext4 to Partition(device=disk-nvme0n1, size=2147483648, wipe='superblock', number=2, grub_device=None, offset=1128267776, id='partition-1')
2022-11-24 15:48:13,718 DEBUG subiquity.models.filesystem:1450 add_partition: rounded size from 996927340544 to 996927340544
2022-11-24 15:48:13,718 DEBUG subiquity.models.filesystem:1526 adding ext4 to LVM_LogicalVolume(name='ubuntu-lv', volgroup=lvm_volgroup-0, size=107374182400, wipe='superblock', id='lvm_partition-0')
2022-11-24 15:48:13,718 DEBUG subiquity.models.filesystem:1336 mountpoints {'/boot/efi': 'mount-0', '/boot': 'mount-1', '/': 'mount-2'}
2022-11-24 15:48:13,718 DEBUG subiquity.models.filesystem:1329 cannot emit action to mount /boot/efi until that for /boot is emitted
2022-11-24 15:48:13,718 DEBUG subiquity.models.filesystem:1329 cannot emit action to mount /boot until that for / is emitted
2022-11-24 15:48:13,718 DEBUG subiquity.models.filesystem:1329 cannot emit action to mount /boot/efi until that for /boot is emitted
2022-11-24 15:48:13,718 DEBUG root:37 finish: subiquity/Filesystem/guided_POST: SUCCESS: 200 {"status": "DONE", "error_report": null, "bootloader": "UEFI", "orig_config":...
2022-11-24 15:48:13,718 INFO aiohttp.access:233  [24/Nov/2022:15:48:13 +0000] "POST /storage/guided HTTP/1.1" 200 28762 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:48:35,358 DEBUG root:37 start: subiquity/Filesystem/reset_POST: 
2022-11-24 15:48:35,358 INFO subiquity.server.controllers.filesystem:354 Resetting Filesystem model
2022-11-24 15:48:35,358 DEBUG curtin:1303 Extracting storage config from probe data
2022-11-24 15:48:35,358 DEBUG curtin:73 /dev/nvme0n1 is multipath device member? False
2022-11-24 15:48:35,358 DEBUG curtin:86 /dev/nvme0n1 is multipath device partition? False
2022-11-24 15:48:35,358 DEBUG curtin:61 /dev/nvme0n1 is multipath device? False
2022-11-24 15:48:35,358 DEBUG curtin:86 /dev/nvme0n1 is multipath device partition? False
2022-11-24 15:48:35,359 DEBUG curtin:61 /dev/nvme0n1 is multipath device? False
2022-11-24 15:48:35,364 DEBUG curtin:73 /dev/nvme0n1p1 is multipath device member? False
2022-11-24 15:48:35,364 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:48:35,364 DEBUG curtin:61 /dev/nvme0n1p1 is multipath device? False
2022-11-24 15:48:35,364 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:48:35,364 DEBUG curtin:86 /dev/nvme0n1p1 is multipath device partition? False
2022-11-24 15:48:35,369 DEBUG curtin:73 /dev/sda is multipath device member? False
2022-11-24 15:48:35,369 DEBUG curtin:86 /dev/sda is multipath device partition? False
2022-11-24 15:48:35,369 DEBUG curtin:61 /dev/sda is multipath device? False
2022-11-24 15:48:35,369 DEBUG curtin:86 /dev/sda is multipath device partition? False
2022-11-24 15:48:35,369 DEBUG curtin:61 /dev/sda is multipath device? False
2022-11-24 15:48:35,374 DEBUG curtin:73 /dev/sda1 is multipath device member? False
2022-11-24 15:48:35,374 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:48:35,374 DEBUG curtin:61 /dev/sda1 is multipath device? False
2022-11-24 15:48:35,374 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:48:35,374 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2022-11-24 15:48:35,379 DEBUG curtin:73 /dev/sda2 is multipath device member? False
2022-11-24 15:48:35,379 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:48:35,379 DEBUG curtin:61 /dev/sda2 is multipath device? False
2022-11-24 15:48:35,379 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:48:35,379 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2022-11-24 15:48:35,384 DEBUG curtin:73 /dev/sda3 is multipath device member? False
2022-11-24 15:48:35,384 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:48:35,384 DEBUG curtin:61 /dev/sda3 is multipath device? False
2022-11-24 15:48:35,384 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:48:35,384 DEBUG curtin:86 /dev/sda3 is multipath device partition? False
2022-11-24 15:48:35,389 DEBUG curtin:73 /dev/sda4 is multipath device member? False
2022-11-24 15:48:35,389 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:48:35,389 DEBUG curtin:61 /dev/sda4 is multipath device? False
2022-11-24 15:48:35,389 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:48:35,389 DEBUG curtin:86 /dev/sda4 is multipath device partition? False
2022-11-24 15:48:35,394 DEBUG curtin:73 /dev/sdb is multipath device member? False
2022-11-24 15:48:35,394 DEBUG curtin:86 /dev/sdb is multipath device partition? False
2022-11-24 15:48:35,394 DEBUG curtin:61 /dev/sdb is multipath device? False
2022-11-24 15:48:35,394 DEBUG curtin:86 /dev/sdb is multipath device partition? False
2022-11-24 15:48:35,394 DEBUG curtin:61 /dev/sdb is multipath device? False
2022-11-24 15:48:35,399 DEBUG curtin:73 /dev/sdb1 is multipath device member? False
2022-11-24 15:48:35,399 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:48:35,399 DEBUG curtin:61 /dev/sdb1 is multipath device? False
2022-11-24 15:48:35,399 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:48:35,399 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2022-11-24 15:48:35,404 DEBUG curtin:73 /dev/nvme0n1p1 is multipath device member? False
2022-11-24 15:48:35,408 DEBUG curtin:73 /dev/sda is multipath device member? False
2022-11-24 15:48:35,413 DEBUG curtin:73 /dev/sda1 is multipath device member? False
2022-11-24 15:48:35,418 DEBUG curtin:73 /dev/sda2 is multipath device member? False
2022-11-24 15:48:35,422 DEBUG curtin:73 /dev/sda4 is multipath device member? False
2022-11-24 15:48:35,427 DEBUG curtin:73 /dev/sdb1 is multipath device member? False
2022-11-24 15:48:35,435 DEBUG curtin:1310 Sorting extracted configurations
2022-11-24 15:48:35,435 INFO curtin:1329 Validating extracted storage config components
2022-11-24 15:48:35,442 DEBUG curtin:1346 Extracted (unmerged) storage config:
storage:
-   id: disk-nvme0n1
    path: /dev/nvme0n1
    ptable: dos
    serial: Samsung_SSD_980_PRO_1TB_S5GXNX0T928425D
    type: disk
    wwn: eui.002538b921b60521
-   id: disk-sda
    path: /dev/sda
    ptable: gpt
    serial: ADATA_USB_Flash_Drive_2811008210170075-0:0
    type: disk
-   id: disk-sdb
    path: /dev/sdb
    ptable: dos
    serial: ST4000VN008-2DR166_ZDHBX28T
    type: disk
    wwn: '0x5000c500e5bb0ccf'
-   device: disk-nvme0n1
    id: partition-nvme0n1p1
    number: 1
    offset: 1048576
    partition_type: '0x7'
    path: /dev/nvme0n1p1
    size: 1000202043392
    type: partition
-   device: disk-sda
    id: partition-sda1
    number: 1
    offset: 32768
    partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
    path: /dev/sda1
    size: 1470150656
    type: partition
-   device: disk-sda
    flag: boot
    id: partition-sda2
    number: 2
    offset: 1470183424
    partition_type: c12a7328-f81f-11d2-ba4b-00a0c93ec93b
    path: /dev/sda2
    size: 4349952
    type: partition
-   device: disk-sda
    id: partition-sda3
    number: 3
    offset: 1474533376
    partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
    path: /dev/sda3
    size: 307200
    type: partition
-   device: disk-sda
    flag: linux
    id: partition-sda4
    number: 4
    offset: 1476395008
    partition_type: 0fc63daf-8483-4772-8e79-3d69d8477de4
    path: /dev/sda4
    size: 14042497536
    type: partition
-   device: disk-sdb
    id: partition-sdb1
    number: 1
    offset: 1048576
    partition_type: '0x7'
    path: /dev/sdb1
    size: 2199022206976
    type: partition
-   fstype: ntfs
    id: format-partition-nvme0n1p1
    type: format
    volume: partition-nvme0n1p1
-   fstype: iso9660
    id: format-disk-sda
    type: format
    volume: disk-sda
-   fstype: iso9660
    id: format-partition-sda1
    type: format
    volume: partition-sda1
-   fstype: vfat
    id: format-partition-sda2
    type: format
    volume: partition-sda2
-   fstype: ext4
    id: format-partition-sda4
    type: format
    uuid: bd8a4591-a294-4e33-a2c7-9994a64fd352
    volume: partition-sda4
-   fstype: ntfs
    id: format-partition-sdb1
    type: format
    volume: partition-sdb1
-   device: format-partition-sda1
    id: mount-partition-sda1
    path: /cdrom
    type: mount

2022-11-24 15:48:35,442 DEBUG curtin:1350 Generating storage config dependencies
2022-11-24 15:48:35,442 DEBUG curtin:236 Validate: partition-nvme0n1p1:SourceType:partition -> (DepId:disk-nvme0n1 DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:35,442 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:35,442 DEBUG curtin:236 Validate: partition-sda2:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:35,442 DEBUG curtin:236 Validate: partition-sda3:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:35,442 DEBUG curtin:236 Validate: partition-sda4:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:35,442 DEBUG curtin:236 Validate: partition-sdb1:SourceType:partition -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:35,442 DEBUG curtin:236 Validate: format-partition-nvme0n1p1:SourceType:format -> (DepId:partition-nvme0n1p1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:48:35,442 DEBUG curtin:236 Validate: partition-nvme0n1p1:SourceType:partition -> (DepId:disk-nvme0n1 DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:35,442 DEBUG curtin:236 Validate: format-disk-sda:SourceType:format -> (DepId:disk-sda DepType:disk) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:48:35,442 DEBUG curtin:236 Validate: format-partition-sda1:SourceType:format -> (DepId:partition-sda1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:48:35,442 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:35,443 DEBUG curtin:236 Validate: format-partition-sda2:SourceType:format -> (DepId:partition-sda2 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:48:35,443 DEBUG curtin:236 Validate: partition-sda2:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:35,443 DEBUG curtin:236 Validate: format-partition-sda4:SourceType:format -> (DepId:partition-sda4 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:48:35,443 DEBUG curtin:236 Validate: partition-sda4:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:35,443 DEBUG curtin:236 Validate: format-partition-sdb1:SourceType:format -> (DepId:partition-sdb1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:48:35,443 DEBUG curtin:236 Validate: partition-sdb1:SourceType:partition -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:35,443 DEBUG curtin:236 Validate: mount-partition-sda1:SourceType:mount -> (DepId:format-partition-sda1 DepType:format) in SourceDeps:{'format'} ? result=True
2022-11-24 15:48:35,443 DEBUG curtin:236 Validate: format-partition-sda1:SourceType:format -> (DepId:partition-sda1 DepType:partition) in SourceDeps:{'dm_crypt', 'raid', 'bcache', 'lvm_partition', 'disk', 'partition'} ? result=True
2022-11-24 15:48:35,443 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2022-11-24 15:48:35,443 DEBUG curtin:1356 Merging storage config dependencies
2022-11-24 15:48:35,445 DEBUG curtin:1361 Merged storage config:
storage:
    config:
    -   id: disk-nvme0n1
        path: /dev/nvme0n1
        ptable: dos
        serial: Samsung_SSD_980_PRO_1TB_S5GXNX0T928425D
        type: disk
        wwn: eui.002538b921b60521
    -   id: disk-sda
        path: /dev/sda
        ptable: gpt
        serial: ADATA_USB_Flash_Drive_2811008210170075-0:0
        type: disk
    -   id: disk-sdb
        path: /dev/sdb
        ptable: dos
        serial: ST4000VN008-2DR166_ZDHBX28T
        type: disk
        wwn: '0x5000c500e5bb0ccf'
    -   fstype: iso9660
        id: format-disk-sda
        type: format
        volume: disk-sda
    -   device: disk-nvme0n1
        id: partition-nvme0n1p1
        number: 1
        offset: 1048576
        partition_type: '0x7'
        path: /dev/nvme0n1p1
        size: 1000202043392
        type: partition
    -   device: disk-sdb
        id: partition-sdb1
        number: 1
        offset: 1048576
        partition_type: '0x7'
        path: /dev/sdb1
        size: 2199022206976
        type: partition
    -   fstype: ntfs
        id: format-partition-nvme0n1p1
        type: format
        volume: partition-nvme0n1p1
    -   fstype: ntfs
        id: format-partition-sdb1
        type: format
        volume: partition-sdb1
    -   device: disk-sda
        id: partition-sda1
        number: 1
        offset: 32768
        partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
        path: /dev/sda1
        size: 1470150656
        type: partition
    -   device: disk-sda
        flag: boot
        id: partition-sda2
        number: 2
        offset: 1470183424
        partition_type: c12a7328-f81f-11d2-ba4b-00a0c93ec93b
        path: /dev/sda2
        size: 4349952
        type: partition
    -   device: disk-sda
        id: partition-sda3
        number: 3
        offset: 1474533376
        partition_type: ebd0a0a2-b9e5-4433-87c0-68b6b72699c7
        path: /dev/sda3
        size: 307200
        type: partition
    -   device: disk-sda
        flag: linux
        id: partition-sda4
        number: 4
        offset: 1476395008
        partition_type: 0fc63daf-8483-4772-8e79-3d69d8477de4
        path: /dev/sda4
        size: 14042497536
        type: partition
    -   fstype: iso9660
        id: format-partition-sda1
        type: format
        volume: partition-sda1
    -   fstype: vfat
        id: format-partition-sda2
        type: format
        volume: partition-sda2
    -   fstype: ext4
        id: format-partition-sda4
        type: format
        uuid: bd8a4591-a294-4e33-a2c7-9994a64fd352
        volume: partition-sda4
    -   device: format-partition-sda1
        id: mount-partition-sda1
        path: /cdrom
        type: mount
    version: 2

2022-11-24 15:48:35,445 DEBUG subiquity.models.filesystem:1271 exclusions {'partition-sda2', 'partition-sda3', 'partition-sda1', 'format-partition-sda2', 'format-disk-sda', 'format-partition-sda1', 'disk-sda', 'format-partition-sda4', 'partition-sda4'}
2022-11-24 15:48:35,445 DEBUG subiquity.models.filesystem:1336 mountpoints {}
2022-11-24 15:48:35,445 DEBUG root:37 finish: subiquity/Filesystem/reset_POST: SUCCESS: 200 {"status": "DONE", "error_report": null, "bootloader": "UEFI", "orig_config":...
2022-11-24 15:48:35,445 INFO aiohttp.access:233  [24/Nov/2022:15:48:35 +0000] "POST /storage/reset HTTP/1.1" 200 27703 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:48:35,445 DEBUG root:37 start: subiquity/Filesystem/guided_GET: 
2022-11-24 15:48:35,446 DEBUG root:37 finish: subiquity/Filesystem/guided_GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "disks": [{"id": "disk-nvme0n1", "la...
2022-11-24 15:48:35,446 INFO aiohttp.access:233  [24/Nov/2022:15:48:35 +0000] "GET /storage/guided HTTP/1.1" 200 1500 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:48:39,150 DEBUG root:37 start: subiquity/Filesystem/GET: 
2022-11-24 15:48:39,150 DEBUG subiquity.models.filesystem:1336 mountpoints {}
2022-11-24 15:48:39,150 DEBUG root:37 finish: subiquity/Filesystem/GET: SUCCESS: 200 {"status": "DONE", "error_report": null, "bootloader": "UEFI", "orig_config":...
2022-11-24 15:48:39,151 INFO aiohttp.access:233  [24/Nov/2022:15:48:39 +0000] "GET /storage?use_cached_result=true HTTP/1.1" 200 27703 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:59:14,239 DEBUG root:37 start: subiquity/Filesystem/POST: 
2022-11-24 15:59:14,239 DEBUG subiquity.server.controllers.filesystem:305 [{'ptable': 'gpt', 'serial': 'Samsung_SSD_980_PRO_1TB_S5GXNX0T928425D', 'wwn': 'eui.002538b921b60521', 'path': '/dev/nvme0n1', 'wipe': 'superblock', 'preserve': False, 'name': '', 'grub_device': False, 'type': 'disk', 'id': 'disk-nvme0n1'}, {'serial': 'ST4000VN008-2DR166_ZDHBX28T', 'wwn': '0x5000c500e5bb0ccf', 'path': '/dev/sdb', 'wipe': 'superblock', 'preserve': False, 'name': '', 'grub_device': False, 'type': 'disk', 'id': 'disk-sdb'}, {'device': 'disk-nvme0n1', 'size': 1127219200, 'wipe': 'superblock', 'flag': 'boot', 'number': 1, 'preserve': False, 'grub_device': True, 'offset': 1048576, 'type': 'partition', 'id': 'partition-0'}, {'fstype': 'fat32', 'volume': 'partition-0', 'preserve': False, 'type': 'format', 'id': 'format-0'}, {'device': 'disk-nvme0n1', 'size': 2147483648, 'wipe': 'superblock', 'number': 2, 'preserve': False, 'offset': 1128267776, 'type': 'partition', 'id': 'partition-1'}, {'fstype': 'ext4', 'volume': 'partition-1', 'preserve': False, 'type': 'format', 'id': 'format-1'}, {'device': 'disk-nvme0n1', 'size': 996927340544, 'wipe': 'superblock', 'number': 3, 'preserve': False, 'offset': 3275751424, 'type': 'partition', 'id': 'partition-2'}, {'name': 'vg-ssd', 'devices': ['partition-2'], 'preserve': False, 'type': 'lvm_volgroup', 'id': 'lvm_volgroup-0'}, {'name': 'vg-hdd', 'devices': ['disk-sdb'], 'preserve': False, 'type': 'lvm_volgroup', 'id': 'lvm_volgroup-1'}, {'name': 'lv-ssd-ubuntu', 'volgroup': 'lvm_volgroup-0', 'size': '107374182400B', 'wipe': 'superblock', 'preserve': False, 'type': 'lvm_partition', 'id': 'lvm_partition-0'}, {'fstype': 'ext4', 'volume': 'lvm_partition-0', 'preserve': False, 'type': 'format', 'id': 'format-2'}, {'path': '/', 'device': 'format-2', 'type': 'mount', 'id': 'mount-2'}, {'name': 'lv-ssd-data', 'volgroup': 'lvm_volgroup-0', 'size': '644245094400B', 'wipe': 'superblock', 'preserve': False, 'type': 'lvm_partition', 'id': 'lvm_partition-1'}, {'fstype': 'ext4', 'volume': 'lvm_partition-1', 'preserve': False, 'type': 'format', 'id': 'format-3'}, {'path': '/data', 'device': 'format-3', 'type': 'mount', 'id': 'mount-3'}, {'name': 'lv-hdd-backup', 'volgroup': 'lvm_volgroup-1', 'size': '2199023255552B', 'wipe': 'superblock', 'preserve': False, 'type': 'lvm_partition', 'id': 'lvm_partition-2'}, {'fstype': 'ext4', 'volume': 'lvm_partition-2', 'preserve': False, 'type': 'format', 'id': 'format-4'}, {'path': '/backup', 'device': 'format-4', 'type': 'mount', 'id': 'mount-4'}, {'path': '/boot', 'device': 'format-1', 'type': 'mount', 'id': 'mount-1'}, {'path': '/boot/efi', 'device': 'format-0', 'type': 'mount', 'id': 'mount-0'}]
2022-11-24 15:59:14,239 DEBUG subiquity.models.filesystem:1271 exclusions set()
2022-11-24 15:59:14,239 DEBUG subiquity.models.subiquity:231 model filesystem for install stage is configured, to go set()
2022-11-24 15:59:14,239 DEBUG root:37 finish: subiquity/Filesystem/POST: SUCCESS: 200 null
2022-11-24 15:59:14,240 INFO aiohttp.access:233  [24/Nov/2022:15:59:14 +0000] "POST /storage HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:59:14,240 INFO root:37 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "NEEDS_CONFIRMATION", "confirming_tty": "", "error": null, "cloud_i...
2022-11-24 15:59:14,240 INFO aiohttp.access:233  [24/Nov/2022:15:39:45 +0000] "GET /meta/status?cur=%22WAITING%22 HTTP/1.1" 200 423 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:59:14,240 INFO aiohttp.access:233  [24/Nov/2022:15:59:14 +0000] "GET /identity HTTP/1.1" 200 184 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:59:14,241 INFO root:37 start: subiquity/Meta/status_GET: 
2022-11-24 15:59:19,798 INFO root:37 start: subiquity/Meta/confirm_POST: 
2022-11-24 15:59:19,798 INFO root:37 finish: subiquity/Meta/confirm_POST: SUCCESS: 200 null
2022-11-24 15:59:19,798 INFO aiohttp.access:233  [24/Nov/2022:15:59:19 +0000] "POST /meta/confirm?tty=%22/dev/tty1%22 HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:59:19,798 INFO root:37 start: subiquity/Install/install/configure_apt: configuring apt
2022-11-24 15:59:19,798 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', 'mount', '-o', 'lowerdir=/tmp/tmpd_f01i21/upper:/tmp/tmp0lzaqorp/root.dir,upperdir=/tmp/tmp13iwgflb/upper,workdir=/tmp/tmp13iwgflb/work', '-t', 'overlay', 'overlay', '/tmp/tmp13iwgflb/mount']
2022-11-24 15:59:19,801 INFO root:37 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini...
2022-11-24 15:59:19,802 INFO aiohttp.access:233  [24/Nov/2022:15:59:14 +0000] "GET /meta/status?cur=%22NEEDS_CONFIRMATION%22 HTTP/1.1" 200 421 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:59:19,802 DEBUG root:37 start: subiquity/Identity/GET: 
2022-11-24 15:59:19,802 DEBUG root:37 finish: subiquity/Identity/GET: SUCCESS: 200 {"realname": "", "username": "", "crypted_password": "", "hostname": ""}
2022-11-24 15:59:19,802 INFO aiohttp.access:233  [24/Nov/2022:15:59:19 +0000] "GET /identity HTTP/1.1" 200 259 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 15:59:19,803 INFO root:37 start: subiquity/Meta/status_GET: 
2022-11-24 15:59:19,835 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', 'mount', '-o', 'bind', '/cdrom', '/tmp/tmp13iwgflb/mount/cdrom']
2022-11-24 15:59:19,844 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', '/snap/subiquity/4003/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.3294.4"}}', 'in-target', '-t', '/tmp/tmp13iwgflb/mount', '--', 'apt-get', 'update']
2022-11-24 15:59:20,331 DEBUG root:37 start: subiquity/Install/install/configure_apt/cmd-in-target: curtin command in-target
2022-11-24 15:59:23,145 DEBUG subiquity.server.curtin:121 waited 0.1 seconds for events to drain
2022-11-24 15:59:23,246 DEBUG subiquity.server.curtin:121 waited 0.2 seconds for events to drain
2022-11-24 15:59:23,342 DEBUG root:37 finish: subiquity/Install/install/configure_apt/cmd-in-target: SUCCESS: curtin command in-target
2022-11-24 15:59:23,347 DEBUG subiquity.server.curtin:121 waited 0.30000000000000004 seconds for events to drain
2022-11-24 15:59:23,347 INFO root:37 finish: subiquity/Install/install/configure_apt: SUCCESS: configuring apt
2022-11-24 15:59:23,347 INFO root:37 start: subiquity/Install/install/curtin_install: installing system
2022-11-24 15:59:23,348 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step: executing curtin install initial step
2022-11-24 15:59:23,349 DEBUG root:37 finish: subiquity/Drivers/_list_drivers/wait_apt: SUCCESS: 
2022-11-24 15:59:23,349 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', 'mount', '-o', 'lowerdir=/tmp/tmp0lzaqorp/root.dir:/tmp/tmpd_f01i21/upper:/tmp/tmp13iwgflb/upper,upperdir=/tmp/tmp0807og4z/upper,workdir=/tmp/tmp0807og4z/work', '-t', 'overlay', 'overlay', '/tmp/tmp0807og4z/mount']
2022-11-24 15:59:23,352 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', '/snap/subiquity/4003/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.3294.5"}}', '-c', '/var/log/installer/curtin-install/subiquity-initial.conf', 'install', 'cp:///tmp/tmp13iwgflb/mount', '--set', 'json:stages=[]']
2022-11-24 15:59:23,383 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', 'chroot', '/tmp/tmp0807og4z/mount', 'sh', '-c', 'command -v ubuntu-drivers']
2022-11-24 15:59:23,391 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--property', 'PrivateMounts=yes', '--pipe', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', '/snap/subiquity/4003/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.3294.6"}}', 'in-target', '-t', '/tmp/tmp0807og4z/mount', '--', 'ubuntu-drivers', 'list', '--recommended', '--gpgpu']
2022-11-24 15:59:23,621 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step: SUCCESS: executing curtin install initial step
2022-11-24 15:59:23,621 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step: executing curtin install partitioning step
2022-11-24 15:59:23,622 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.source.SourceModel object at 0x7f28213bc970>
2022-11-24 15:59:23,622 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.kernel.KernelModel object at 0x7f28214651c0>
2022-11-24 15:59:23,622 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.network.NetworkModel object at 0x7f28213bc850>
2022-11-24 15:59:23,623 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.mirror.MirrorModel object at 0x7f28213bc820>
2022-11-24 15:59:23,623 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.proxy.ProxyModel object at 0x7f28213bcbb0>
2022-11-24 15:59:23,623 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.filesystem.FilesystemModel object at 0x7f2821465280>
2022-11-24 15:59:23,623 DEBUG subiquity.models.filesystem:1336 mountpoints {'/': 'mount-2', '/data': 'mount-3', '/backup': 'mount-4', '/boot': 'mount-1', '/boot/efi': 'mount-0'}
2022-11-24 15:59:23,624 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.keyboard.KeyboardModel object at 0x7f28214652e0>
2022-11-24 15:59:23,624 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.subiquity.DebconfSelectionsModel object at 0x7f28214651f0>
2022-11-24 15:59:23,632 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', '/snap/subiquity/4003/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.3294.7"}}', '-c', '/var/log/installer/curtin-install/subiquity-partitioning.conf', 'install', 'cp:///tmp/tmp13iwgflb/mount', '--set', 'json:stages=["partitioning"]']
2022-11-24 15:59:23,914 DEBUG root:37 start: subiquity/Drivers/_list_drivers/cmd-in-target: curtin command in-target
2022-11-24 15:59:24,172 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install: curtin command install
2022-11-24 15:59:24,173 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning: configuring storage
2022-11-24 15:59:24,173 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin: running 'curtin block-meta simple'
2022-11-24 15:59:24,592 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: curtin command block-meta
2022-11-24 15:59:24,763 DEBUG subiquity.server.curtin:121 waited 0.1 seconds for events to drain
2022-11-24 15:59:24,864 DEBUG subiquity.server.curtin:121 waited 0.2 seconds for events to drain
2022-11-24 15:59:24,959 DEBUG root:37 finish: subiquity/Drivers/_list_drivers/cmd-in-target: SUCCESS: curtin command in-target
2022-11-24 15:59:24,964 DEBUG subiquity.server.curtin:121 waited 0.30000000000000004 seconds for events to drain
2022-11-24 15:59:24,972 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', 'umount', '/tmp/tmp0807og4z/mount']
2022-11-24 15:59:25,021 DEBUG subiquity.server.controllers.drivers:100 Available drivers to install: []
2022-11-24 15:59:25,022 DEBUG subiquity.models.subiquity:231 model drivers for postinstall stage is configured, to go {'snaplist', 'ubuntu_pro', 'identity', 'ssh'}
2022-11-24 15:59:25,022 DEBUG root:37 finish: subiquity/Drivers/_list_drivers: SUCCESS: 
2022-11-24 15:59:25,745 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta/clear-holders: removing previous storage devices
2022-11-24 15:59:26,270 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta/clear-holders: SUCCESS: removing previous storage devices
2022-11-24 15:59:26,270 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta/: configuring disk: disk-nvme0n1
2022-11-24 15:59:26,270 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta/: SUCCESS: configuring disk: disk-nvme0n1
2022-11-24 15:59:26,270 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring disk: disk-sdb
2022-11-24 15:59:26,520 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring disk: disk-sdb
2022-11-24 15:59:26,520 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-0
2022-11-24 15:59:27,873 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring partition: partition-0
2022-11-24 15:59:27,874 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring format: format-0
2022-11-24 15:59:28,136 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring format: format-0
2022-11-24 15:59:28,136 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-1
2022-11-24 15:59:29,456 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring partition: partition-1
2022-11-24 15:59:29,456 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring format: format-1
2022-11-24 15:59:29,750 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring format: format-1
2022-11-24 15:59:29,750 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-2
2022-11-24 15:59:31,095 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring partition: partition-2
2022-11-24 15:59:31,095 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring lvm_volgroup: lvm_volgroup-0
2022-11-24 15:59:31,726 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring lvm_volgroup: lvm_volgroup-0
2022-11-24 15:59:31,727 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring lvm_volgroup: lvm_volgroup-1
2022-11-24 15:59:31,981 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring lvm_volgroup: lvm_volgroup-1
2022-11-24 15:59:31,981 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring lvm_partition: lvm_partition-0
2022-11-24 15:59:32,545 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring lvm_partition: lvm_partition-0
2022-11-24 15:59:32,546 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring format: format-2
2022-11-24 15:59:32,546 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring format: format-2
2022-11-24 15:59:32,546 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring mount: mount-2
2022-11-24 15:59:32,817 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring mount: mount-2
2022-11-24 15:59:32,817 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring lvm_partition: lvm_partition-1
2022-11-24 15:59:33,080 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring lvm_partition: lvm_partition-1
2022-11-24 15:59:33,081 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring format: format-3
2022-11-24 15:59:34,001 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring format: format-3
2022-11-24 15:59:34,001 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring mount: mount-3
2022-11-24 15:59:34,001 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring mount: mount-3
2022-11-24 15:59:34,001 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring lvm_partition: lvm_partition-2
2022-11-24 15:59:34,841 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring lvm_partition: lvm_partition-2
2022-11-24 15:59:34,842 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring format: format-4
2022-11-24 15:59:47,524 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring format: format-4
2022-11-24 15:59:47,525 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring mount: mount-4
2022-11-24 15:59:47,815 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring mount: mount-4
2022-11-24 15:59:47,815 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring mount: mount-1
2022-11-24 15:59:47,815 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring mount: mount-1
2022-11-24 15:59:47,815 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring mount: mount-0
2022-11-24 15:59:48,047 DEBUG subiquity.server.curtin:121 waited 0.1 seconds for events to drain
2022-11-24 15:59:48,092 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring mount: mount-0
2022-11-24 15:59:48,092 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin: SUCCESS: running 'curtin block-meta simple'
2022-11-24 15:59:48,092 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning: SUCCESS: configuring storage
2022-11-24 15:59:48,092 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install: SUCCESS: curtin command install
2022-11-24 15:59:48,148 DEBUG subiquity.server.curtin:121 waited 0.2 seconds for events to drain
2022-11-24 15:59:48,148 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step: SUCCESS: executing curtin install partitioning step
2022-11-24 15:59:48,148 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step: executing curtin install extract step
2022-11-24 15:59:48,149 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.source.SourceModel object at 0x7f28213bc970>
2022-11-24 15:59:48,149 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.kernel.KernelModel object at 0x7f28214651c0>
2022-11-24 15:59:48,149 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.network.NetworkModel object at 0x7f28213bc850>
2022-11-24 15:59:48,149 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.mirror.MirrorModel object at 0x7f28213bc820>
2022-11-24 15:59:48,149 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.proxy.ProxyModel object at 0x7f28213bcbb0>
2022-11-24 15:59:48,149 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.filesystem.FilesystemModel object at 0x7f2821465280>
2022-11-24 15:59:48,149 DEBUG subiquity.models.filesystem:1336 mountpoints {'/': 'mount-2', '/data': 'mount-3', '/backup': 'mount-4', '/boot': 'mount-1', '/boot/efi': 'mount-0'}
2022-11-24 15:59:48,150 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.keyboard.KeyboardModel object at 0x7f28214652e0>
2022-11-24 15:59:48,150 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.subiquity.DebconfSelectionsModel object at 0x7f28214651f0>
2022-11-24 15:59:48,158 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', '/snap/subiquity/4003/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.3294.8"}}', '-c', '/var/log/installer/curtin-install/subiquity-extract.conf', 'install', 'cp:///tmp/tmp13iwgflb/mount', '--set', 'json:stages=["extract"]']
2022-11-24 15:59:48,842 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install: curtin command install
2022-11-24 15:59:48,842 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-extract: writing install sources to disk
2022-11-24 15:59:48,842 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-extract/builtin: running 'curtin extract'
2022-11-24 15:59:48,842 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-extract/builtin/cmd-extract: curtin command extract
2022-11-24 15:59:48,842 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-extract/builtin/cmd-extract/: acquiring and extracting image from cp:///tmp/tmp13iwgflb/mount
2022-11-24 15:59:58,968 DEBUG subiquity.server.curtin:121 waited 0.1 seconds for events to drain
2022-11-24 15:59:59,068 DEBUG subiquity.server.curtin:121 waited 0.2 seconds for events to drain
2022-11-24 15:59:59,169 DEBUG subiquity.server.curtin:121 waited 0.30000000000000004 seconds for events to drain
2022-11-24 15:59:59,269 DEBUG subiquity.server.curtin:121 waited 0.4 seconds for events to drain
2022-11-24 15:59:59,342 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-extract/builtin/cmd-extract/: SUCCESS: acquiring and extracting image from cp:///tmp/tmp13iwgflb/mount
2022-11-24 15:59:59,342 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-extract/builtin: SUCCESS: running 'curtin extract'
2022-11-24 15:59:59,342 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-extract: SUCCESS: writing install sources to disk
2022-11-24 15:59:59,342 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install: SUCCESS: curtin command install
2022-11-24 15:59:59,370 DEBUG subiquity.server.curtin:121 waited 0.5 seconds for events to drain
2022-11-24 15:59:59,370 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step: SUCCESS: executing curtin install extract step
2022-11-24 15:59:59,371 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step: executing curtin install curthooks step
2022-11-24 15:59:59,371 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.source.SourceModel object at 0x7f28213bc970>
2022-11-24 15:59:59,371 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.kernel.KernelModel object at 0x7f28214651c0>
2022-11-24 15:59:59,371 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.network.NetworkModel object at 0x7f28213bc850>
2022-11-24 15:59:59,371 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.mirror.MirrorModel object at 0x7f28213bc820>
2022-11-24 15:59:59,371 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.proxy.ProxyModel object at 0x7f28213bcbb0>
2022-11-24 15:59:59,371 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.filesystem.FilesystemModel object at 0x7f2821465280>
2022-11-24 15:59:59,372 DEBUG subiquity.models.filesystem:1336 mountpoints {'/': 'mount-2', '/data': 'mount-3', '/backup': 'mount-4', '/boot': 'mount-1', '/boot/efi': 'mount-0'}
2022-11-24 15:59:59,372 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.keyboard.KeyboardModel object at 0x7f28214652e0>
2022-11-24 15:59:59,372 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.subiquity.DebconfSelectionsModel object at 0x7f28214651f0>
2022-11-24 15:59:59,379 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', '/snap/subiquity/4003/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.3294.9"}}', '-c', '/var/log/installer/curtin-install/subiquity-curthooks.conf', 'install', 'cp:///tmp/tmp13iwgflb/mount', '--set', 'json:stages=["curthooks"]']
2022-11-24 16:00:00,052 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install: curtin command install
2022-11-24 16:00:00,052 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks: configuring installed system
2022-11-24 16:00:00,052 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/001-mount-cdrom: running 'mount --bind /cdrom /target/cdrom'
2022-11-24 16:00:00,052 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/001-mount-cdrom: SUCCESS: running 'mount --bind /cdrom /target/cdrom'
2022-11-24 16:00:00,052 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/002-setupcon-save-only: running 'curtin in-target -- setupcon --save-only'
2022-11-24 16:00:00,052 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/002-setupcon-save-only/cmd-in-target: curtin command in-target
2022-11-24 16:00:00,341 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/002-setupcon-save-only/cmd-in-target: SUCCESS: curtin command in-target
2022-11-24 16:00:00,342 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/002-setupcon-save-only: SUCCESS: running 'curtin in-target -- setupcon --save-only'
2022-11-24 16:00:00,342 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin: running 'curtin curthooks'
2022-11-24 16:00:00,653 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks: curtin command curthooks
2022-11-24 16:00:00,653 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-apt-config: configuring apt configuring apt
2022-11-24 16:00:00,653 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-apt-config: SUCCESS: configuring apt configuring apt
2022-11-24 16:00:00,653 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-missing-packages: installing missing packages
2022-11-24 16:00:01,591 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/: Installing packages on target system: ['efibootmgr', 'grub-efi-amd64', 'grub-efi-amd64-signed', 'shim-signed']
2022-11-24 16:00:05,189 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/: SUCCESS: Installing packages on target system: ['efibootmgr', 'grub-efi-amd64', 'grub-efi-amd64-signed', 'shim-signed']
2022-11-24 16:00:05,189 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-missing-packages: SUCCESS: installing missing packages
2022-11-24 16:00:05,189 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-iscsi-service: configuring iscsi service
2022-11-24 16:00:05,189 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-iscsi-service: SUCCESS: configuring iscsi service
2022-11-24 16:00:05,190 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-mdadm-service: configuring raid (mdadm) service
2022-11-24 16:00:05,190 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-mdadm-service: SUCCESS: configuring raid (mdadm) service
2022-11-24 16:00:05,190 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-kernel: installing kernel
2022-11-24 16:00:32,648 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-kernel: SUCCESS: installing kernel
2022-11-24 16:00:32,648 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/setting-up-swap: setting up swap
2022-11-24 16:00:32,648 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/setting-up-swap: SUCCESS: setting up swap
2022-11-24 16:00:32,648 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/apply-networking-config: apply networking config
2022-11-24 16:00:32,648 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/apply-networking-config: SUCCESS: apply networking config
2022-11-24 16:00:32,648 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-etc-fstab: writing etc/fstab
2022-11-24 16:00:32,648 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-etc-fstab: SUCCESS: writing etc/fstab
2022-11-24 16:00:32,648 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-multipath: configuring multipath
2022-11-24 16:00:33,341 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-multipath: SUCCESS: configuring multipath
2022-11-24 16:00:33,342 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/system-upgrade: updating packages on target system
2022-11-24 16:00:33,342 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/system-upgrade: SUCCESS: updating packages on target system
2022-11-24 16:00:33,342 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/pollinate-user-agent: configuring pollinate user-agent on target
2022-11-24 16:00:33,342 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/pollinate-user-agent: SUCCESS: configuring pollinate user-agent on target
2022-11-24 16:00:33,342 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/updating-initramfs-configuration: updating initramfs configuration
2022-11-24 16:00:39,577 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/updating-initramfs-configuration: SUCCESS: updating initramfs configuration
2022-11-24 16:00:39,577 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-bootloader: configuring target system bootloader
2022-11-24 16:00:39,577 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/install-grub: installing grub to target devices
2022-11-24 16:00:45,736 DEBUG subiquity.server.curtin:121 waited 0.1 seconds for events to drain
2022-11-24 16:00:45,837 DEBUG subiquity.server.curtin:121 waited 0.2 seconds for events to drain
2022-11-24 16:00:45,842 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/install-grub: SUCCESS: installing grub to target devices
2022-11-24 16:00:45,842 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-bootloader: SUCCESS: configuring target system bootloader
2022-11-24 16:00:45,842 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/builtin: SUCCESS: running 'curtin curthooks'
2022-11-24 16:00:45,842 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks: SUCCESS: configuring installed system
2022-11-24 16:00:45,842 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install: SUCCESS: curtin command install
2022-11-24 16:00:45,937 DEBUG subiquity.server.curtin:121 waited 0.30000000000000004 seconds for events to drain
2022-11-24 16:00:45,938 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step: SUCCESS: executing curtin install curthooks step
2022-11-24 16:00:45,938 INFO root:37 finish: subiquity/Install/install/curtin_install: SUCCESS: installing system
2022-11-24 16:00:45,939 INFO root:37 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini...
2022-11-24 16:00:45,939 INFO aiohttp.access:233  [24/Nov/2022:15:59:19 +0000] "GET /meta/status?cur=%22RUNNING%22 HTTP/1.1" 200 421 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 16:00:45,940 INFO root:37 start: subiquity/Meta/status_GET: 
2022-11-24 16:06:00,354 DEBUG root:37 start: subiquity/Identity/validate_username_GET: 
2022-11-24 16:06:00,354 DEBUG root:37 finish: subiquity/Identity/validate_username_GET: SUCCESS: 200 "OK"
2022-11-24 16:06:00,355 INFO aiohttp.access:233  [24/Nov/2022:16:06:00 +0000] "GET /identity/validate_username?username=%22rm%22 HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 16:09:28,485 DEBUG root:37 start: subiquity/Identity/POST: 
2022-11-24 16:09:28,486 DEBUG subiquity.models.subiquity:231 model identity for postinstall stage is configured, to go {'snaplist', 'ubuntu_pro', 'ssh'}
2022-11-24 16:09:28,486 DEBUG root:37 finish: subiquity/Identity/POST: SUCCESS: 200 null
2022-11-24 16:09:28,486 INFO aiohttp.access:233  [24/Nov/2022:16:09:28 +0000] "POST /identity HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 16:09:28,487 DEBUG root:37 start: subiquity/UbuntuPro/skip_POST: 
2022-11-24 16:09:28,487 DEBUG subiquity.models.subiquity:231 model ubuntu_pro for postinstall stage is configured, to go {'snaplist', 'ssh'}
2022-11-24 16:09:28,487 DEBUG root:37 finish: subiquity/UbuntuPro/skip_POST: SUCCESS: 200 null
2022-11-24 16:09:28,487 INFO aiohttp.access:233  [24/Nov/2022:16:09:28 +0000] "POST /ubuntu_pro/skip HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 16:09:28,488 DEBUG root:37 start: subiquity/SSH/GET: 
2022-11-24 16:09:28,488 DEBUG root:37 finish: subiquity/SSH/GET: SUCCESS: 200 {"install_server": false, "allow_pw": true, "authorized_keys": []}
2022-11-24 16:09:28,488 INFO aiohttp.access:233  [24/Nov/2022:16:09:28 +0000] "GET /ssh HTTP/1.1" 200 253 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 16:09:53,516 DEBUG root:37 start: subiquity/SSH/POST: 
2022-11-24 16:09:53,516 DEBUG subiquity.models.subiquity:231 model ssh for postinstall stage is configured, to go {'snaplist'}
2022-11-24 16:09:53,516 DEBUG root:37 finish: subiquity/SSH/POST: SUCCESS: 200 null
2022-11-24 16:09:53,516 INFO aiohttp.access:233  [24/Nov/2022:16:09:53 +0000] "POST /ssh HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 16:09:53,517 DEBUG root:37 start: subiquity/Drivers/GET: 
2022-11-24 16:09:53,517 DEBUG root:37 finish: subiquity/Drivers/GET: SUCCESS: 200 {"install": false, "drivers": [], "local_only": false, "search_drivers": true}
2022-11-24 16:09:53,517 INFO aiohttp.access:233  [24/Nov/2022:16:09:53 +0000] "GET /drivers HTTP/1.1" 200 265 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 16:09:56,251 DEBUG root:37 start: subiquity/Drivers/POST: 
2022-11-24 16:09:56,251 DEBUG subiquity.models.subiquity:231 model drivers for postinstall stage is configured, to go {'snaplist'}
2022-11-24 16:09:56,252 DEBUG root:37 finish: subiquity/Drivers/POST: SUCCESS: 200 null
2022-11-24 16:09:56,252 INFO aiohttp.access:233  [24/Nov/2022:16:09:56 +0000] "POST /drivers HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 16:09:56,252 DEBUG root:37 start: subiquity/SnapList/GET: 
2022-11-24 16:09:56,256 DEBUG root:37 finish: subiquity/SnapList/GET: SUCCESS: 200 {"status": "DONE", "snaps": [{"name": "microk8s", "summary": "Kubernetes for ...
2022-11-24 16:09:56,257 INFO aiohttp.access:233  [24/Nov/2022:16:09:56 +0000] "GET /snaplist HTTP/1.1" 200 54327 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 16:10:59,597 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2022-11-24 16:10:59,616 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2022-11-24 16:10:59,616 DEBUG probert.network:585 event for addr_change: CHANGE {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'10.30.0.20/24'}
2022-11-24 16:10:59,616 DEBUG probert.network:717 addr_change CHANGE {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'10.30.0.20/24'}
2022-11-24 16:10:59,617 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE enp14s0
2022-11-24 16:10:59,617 DEBUG subiquity.server.controllers.network:354 dev_info enp14s0 {'dhcp4': True}
2022-11-24 16:10:59,617 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp14s0
2022-11-24 16:11:19,588 DEBUG root:37 start: subiquity/SnapList/POST: 
2022-11-24 16:11:19,588 DEBUG subiquity.server.controllers.snaplist:222 []
2022-11-24 16:11:19,589 DEBUG subiquity.models.subiquity:231 model snaplist for postinstall stage is configured, to go set()
2022-11-24 16:11:19,589 DEBUG root:37 finish: subiquity/SnapList/POST: SUCCESS: 200 null
2022-11-24 16:11:19,589 INFO root:37 start: subiquity/Install/install/postinstall: final system configuration
2022-11-24 16:11:19,589 DEBUG subiquity.models.filesystem:1336 mountpoints {'/': 'mount-2', '/data': 'mount-3', '/backup': 'mount-4', '/boot': 'mount-1', '/boot/efi': 'mount-0'}
2022-11-24 16:11:19,597 DEBUG root:37 start: subiquity/Install/install/postinstall/configure_cloud_init: configuring cloud-init
2022-11-24 16:11:19,598 INFO aiohttp.access:233  [24/Nov/2022:16:11:19 +0000] "POST /snaplist HTTP/1.1" 200 190 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 16:11:19,598 INFO root:37 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_ini...
2022-11-24 16:11:19,598 INFO aiohttp.access:233  [24/Nov/2022:16:00:45 +0000] "GET /meta/status?cur=%22WAITING%22 HTTP/1.1" 200 421 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 16:11:19,598 DEBUG subiquitycore.utils:64 run_command called: ['chroot', '/target', 'getent', 'group']
2022-11-24 16:11:19,600 INFO root:37 start: subiquity/Meta/status_GET: 
2022-11-24 16:11:19,601 DEBUG subiquitycore.utils:77 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2022-11-24 16:11:19,604 DEBUG root:37 finish: subiquity/Install/install/postinstall/configure_cloud_init: SUCCESS: configuring cloud-init
2022-11-24 16:11:19,604 DEBUG root:37 start: subiquity/Install/install/postinstall/get_target_packages: calculating extra packages to install
2022-11-24 16:11:19,604 DEBUG root:37 finish: subiquity/Install/install/postinstall/get_target_packages: SUCCESS: calculating extra packages to install
2022-11-24 16:11:19,604 DEBUG root:37 start: subiquity/Install/install/postinstall/install_openssh-server: installing openssh-server
2022-11-24 16:11:19,605 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', '/snap/subiquity/4003/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.3294.10"}}', 'system-install', '-t', '/target', '--', 'openssh-server']
2022-11-24 16:11:20,151 DEBUG root:37 start: subiquity/Install/install/postinstall/install_openssh-server/cmd-system-install: curtin command system-install
2022-11-24 16:11:20,445 DEBUG subiquity.server.curtin:121 waited 0.1 seconds for events to drain
2022-11-24 16:11:20,546 DEBUG subiquity.server.curtin:121 waited 0.2 seconds for events to drain
2022-11-24 16:11:20,592 DEBUG root:37 finish: subiquity/Install/install/postinstall/install_openssh-server/cmd-system-install: SUCCESS: curtin command system-install
2022-11-24 16:11:20,647 DEBUG subiquity.server.curtin:121 waited 0.30000000000000004 seconds for events to drain
2022-11-24 16:11:20,647 DEBUG root:37 finish: subiquity/Install/install/postinstall/install_openssh-server: SUCCESS: installing openssh-server
2022-11-24 16:11:20,648 DEBUG root:37 start: subiquity/Install/install/postinstall/install_wpasupplicant: installing wpasupplicant
2022-11-24 16:11:20,648 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', '/snap/subiquity/4003/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.3294.11"}}', 'system-install', '-t', '/target', '--', 'wpasupplicant']
2022-11-24 16:11:21,152 DEBUG root:37 start: subiquity/Install/install/postinstall/install_wpasupplicant/cmd-system-install: curtin command system-install
2022-11-24 16:11:23,088 DEBUG subiquity.server.curtin:121 waited 0.1 seconds for events to drain
2022-11-24 16:11:23,188 DEBUG subiquity.server.curtin:121 waited 0.2 seconds for events to drain
2022-11-24 16:11:23,289 DEBUG subiquity.server.curtin:121 waited 0.30000000000000004 seconds for events to drain
2022-11-24 16:11:23,342 DEBUG root:37 finish: subiquity/Install/install/postinstall/install_wpasupplicant/cmd-system-install: SUCCESS: curtin command system-install
2022-11-24 16:11:23,390 DEBUG subiquity.server.curtin:121 waited 0.4 seconds for events to drain
2022-11-24 16:11:23,390 DEBUG root:37 finish: subiquity/Install/install/postinstall/install_wpasupplicant: SUCCESS: installing wpasupplicant
2022-11-24 16:11:23,390 DEBUG root:37 start: subiquity/Install/install/postinstall/run_unattended_upgrades: downloading and installing security updates
2022-11-24 16:11:23,391 INFO root:37 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "UU_RUNNING", "confirming_tty": "/dev/tty1", "error": null, "cloud_...
2022-11-24 16:11:23,391 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', '/snap/subiquity/4003/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.3294.12"}}', 'in-target', '-t', '/target', '--', 'unattended-upgrades', '-v']
2022-11-24 16:11:23,394 INFO aiohttp.access:233  [24/Nov/2022:16:11:19 +0000] "GET /meta/status?cur=%22RUNNING%22 HTTP/1.1" 200 424 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 16:11:23,395 INFO root:37 start: subiquity/Meta/status_GET: 
2022-11-24 16:11:24,092 DEBUG root:37 start: subiquity/Install/install/postinstall/run_unattended_upgrades/cmd-in-target: curtin command in-target
2022-11-24 16:13:03,976 DEBUG subiquity.server.curtin:121 waited 0.1 seconds for events to drain
2022-11-24 16:13:04,076 DEBUG subiquity.server.curtin:121 waited 0.2 seconds for events to drain
2022-11-24 16:13:04,092 DEBUG root:37 finish: subiquity/Install/install/postinstall/run_unattended_upgrades/cmd-in-target: SUCCESS: curtin command in-target
2022-11-24 16:13:04,177 DEBUG subiquity.server.curtin:121 waited 0.30000000000000004 seconds for events to drain
2022-11-24 16:13:04,177 DEBUG root:37 finish: subiquity/Install/install/postinstall/run_unattended_upgrades: SUCCESS: downloading and installing security updates
2022-11-24 16:13:04,177 DEBUG root:37 start: subiquity/Install/install/postinstall/restore_apt_config: restoring apt configuration
2022-11-24 16:13:04,178 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', 'umount', '/target/cdrom']
2022-11-24 16:13:04,227 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', 'cp', '-aT', '/tmp/tmpd_f01i21/mount/etc/apt', '/target/etc/apt']
2022-11-24 16:13:04,236 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', '/snap/subiquity/4003/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.3294.13"}}', 'in-target', '-t', '/target', '--', 'apt-get', 'update']
2022-11-24 16:13:04,842 DEBUG root:37 start: subiquity/Install/install/postinstall/restore_apt_config/cmd-in-target: curtin command in-target
2022-11-24 16:13:05,991 DEBUG subiquity.server.curtin:121 waited 0.1 seconds for events to drain
2022-11-24 16:13:06,091 DEBUG subiquity.server.curtin:121 waited 0.2 seconds for events to drain
2022-11-24 16:13:06,092 DEBUG root:37 finish: subiquity/Install/install/postinstall/restore_apt_config/cmd-in-target: SUCCESS: curtin command in-target
2022-11-24 16:13:06,193 DEBUG subiquity.server.curtin:121 waited 0.30000000000000004 seconds for events to drain
2022-11-24 16:13:06,193 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', 'umount', '/tmp/tmp13iwgflb/mount/cdrom']
2022-11-24 16:13:06,234 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', 'umount', '/tmp/tmp13iwgflb/mount']
2022-11-24 16:13:06,272 DEBUG subiquitycore.utils:114 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.3294', '--setenv', 'PATH=/snap/subiquity/4003/bin:/snap/subiquity/4003/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4003/bin:/snap/subiquity/4003/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4003/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4003/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4003', '--', 'umount', '/tmp/tmpd_f01i21/mount']
2022-11-24 16:13:06,300 DEBUG root:37 finish: subiquity/Install/install/postinstall/restore_apt_config: SUCCESS: restoring apt configuration
2022-11-24 16:13:06,300 INFO root:37 finish: subiquity/Install/install/postinstall: SUCCESS: final system configuration
2022-11-24 16:13:06,300 DEBUG root:37 finish: subiquity/Install/install: SUCCESS: 
2022-11-24 16:13:06,301 INFO root:37 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "DONE", "confirming_tty": "/dev/tty1", "error": null, "cloud_init_o...
2022-11-24 16:13:06,301 DEBUG root:37 start: subiquity/Late/run: 
2022-11-24 16:13:06,301 DEBUG root:37 finish: subiquity/Late/run: SUCCESS: 
2022-11-24 16:13:06,301 DEBUG root:37 start: subiquity/Shutdown/copy_logs_to_target: 
2022-11-24 16:13:06,301 DEBUG subiquitycore.utils:92 arun_command called: ['cp', '-aT', '/var/log/installer', '/target/var/log/installer']
2022-11-24 16:13:06,304 INFO aiohttp.access:233  [24/Nov/2022:16:11:23 +0000] "GET /meta/status?cur=%22UU_RUNNING%22 HTTP/1.1" 200 418 "-" "Python/3.8 aiohttp/3.6.2"
2022-11-24 16:13:06,305 INFO root:37 start: subiquity/Meta/status_GET: