2023-02-23 15:19:22,887 INFO subiquity:161 Starting Subiquity server revision 4380
2023-02-23 15:19:22,887 INFO subiquity:162 Arguments passed: ['/snap/subiquity/4380/lib/python3.8/site-packages/subiquity/cmd/server.py']
2023-02-23 15:19:22,888 DEBUG subiquity:163 Kernel commandline: CommandLineParams(_raw='vmlinuz initrd=initrd ip=dhcp url=http://boot.linuxgroove.com/ubuntu/22.04/iso/../install.iso cloud-config-url=/dev/null autoinstall ds=nocloud-net;s=http://boot.linuxgroove.com/ubuntu/22.04/ echo Booting Ubuntu 22.04 installer...\n', _tokens={'22.04', 'autoinstall', 'echo', 'vmlinuz', 'Booting', 'Ubuntu', 'installer...'}, _values={'initrd': 'initrd', 'ip': 'dhcp', 'url': 'http://boot.linuxgroove.com/ubuntu/22.04/iso/../install.iso', 'cloud-config-url': '/dev/null', 'ds': 'nocloud-net;s=http://boot.linuxgroove.com/ubuntu/22.04/'})
2023-02-23 15:19:22,888 DEBUG subiquity:164 Storage version: 1
2023-02-23 15:19:22,888 DEBUG asyncio:59 Using selector: EpollSelector
2023-02-23 15:19:22,888 DEBUG subiquitycore.prober:34 Prober() init finished, data:None
2023-02-23 15:19:22,909 DEBUG curtin:87 Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (capture=True)
2023-02-23 15:19:22,917 DEBUG subiquitycore.netplan:109 config for enp0s25 = {'critical': True, 'dhcp-identifier': 'mac', 'dhcp4': True, 'nameservers': {'addresses': ['192.168.1.254'], 'search': ['attlocal.net']}}
2023-02-23 15:19:22,917 DEBUG subiquitycore.netplan:109 config for zz-all-en = {'dhcp4': True, 'match': {'name': 'en*'}}
2023-02-23 15:19:22,917 DEBUG subiquitycore.netplan:109 config for zz-all-eth = {'dhcp4': True, 'match': {'name': 'eth*'}}
2023-02-23 15:19:22,925 DEBUG subiquitycore.utils:92 arun_command called: ['cloud-init', 'status', '--wait']
2023-02-23 15:19:23,704 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET: 
2023-02-23 15:19:23,705 DEBUG curtin.reporting.finish.subiquity/Meta/status_GET:45 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "CLOUD_INIT_WAIT", "confirming_tty": "", "error": null, "cloud_init...
2023-02-23 15:19:23,705 INFO aiohttp.access:233  [23/Feb/2023:15:19:23 +0000] "GET /meta/status?cur=null HTTP/1.1" 200 420 "-" "Python/3.8 aiohttp/3.6.2"
2023-02-23 15:19:23,727 DEBUG curtin.reporting.start.subiquity/Meta/status_GET:45 start: subiquity/Meta/status_GET: 
2023-02-23 15:19:23,935 DEBUG subiquitycore.utils:101 arun_command ['cloud-init', 'status', '--wait'] exited with code 0
2023-02-23 15:19:23,935 DEBUG subiquity.server.server:532 waited 1.0097510814666748s for cloud-init
2023-02-23 15:19:23,935 DEBUG subiquity.server.server:534 loading cloud config
2023-02-23 15:19:23,936 DEBUG cloudinit.util:1528 Reading from /etc/cloud/cloud.cfg (quiet=False)
2023-02-23 15:19:23,936 DEBUG cloudinit.util:1539 Read 3487 bytes from /etc/cloud/cloud.cfg
2023-02-23 15:19:23,936 DEBUG cloudinit.util:941 Attempting to load yaml from string of length 3487 with allowed root types (<class 'dict'>,)
2023-02-23 15:19:23,945 DEBUG cloudinit.util:1528 Reading from /etc/cloud/cloud.cfg.d/enp0s25.cfg (quiet=False)
2023-02-23 15:19:23,945 DEBUG cloudinit.util:1539 Read 203 bytes from /etc/cloud/cloud.cfg.d/enp0s25.cfg
2023-02-23 15:19:23,945 DEBUG cloudinit.util:941 Attempting to load yaml from string of length 203 with allowed root types (<class 'dict'>,)
2023-02-23 15:19:23,946 DEBUG cloudinit.util:1528 Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2023-02-23 15:19:23,946 DEBUG cloudinit.util:1539 Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2023-02-23 15:19:23,946 DEBUG cloudinit.util:941 Attempting to load yaml from string of length 314 with allowed root types (<class 'dict'>,)
2023-02-23 15:19:23,947 DEBUG cloudinit.util:1528 Reading from /etc/cloud/cloud.cfg.d/06_quiet.cfg (quiet=False)
2023-02-23 15:19:23,947 DEBUG cloudinit.util:1539 Read 112 bytes from /etc/cloud/cloud.cfg.d/06_quiet.cfg
2023-02-23 15:19:23,947 DEBUG cloudinit.util:941 Attempting to load yaml from string of length 112 with allowed root types (<class 'dict'>,)
2023-02-23 15:19:23,948 DEBUG cloudinit.util:1528 Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2023-02-23 15:19:23,948 DEBUG cloudinit.util:1539 Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2023-02-23 15:19:23,948 DEBUG cloudinit.util:941 Attempting to load yaml from string of length 2070 with allowed root types (<class 'dict'>,)
2023-02-23 15:19:23,953 DEBUG cloudinit.util:1528 Reading from /run/cloud-init/cloud.cfg (quiet=False)
2023-02-23 15:19:23,953 DEBUG cloudinit.util:1539 Read 35 bytes from /run/cloud-init/cloud.cfg
2023-02-23 15:19:23,953 DEBUG cloudinit.util:941 Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2023-02-23 15:19:23,953 DEBUG cloudinit.subp:245 Running command ['systemd-detect-virt', '--quiet', '--container'] with allowed return codes [0] (shell=False, capture=True)
2023-02-23 15:19:23,966 DEBUG cloudinit.util:1528 Reading from /etc/os-release (quiet=False)
2023-02-23 15:19:23,966 DEBUG cloudinit.util:1539 Read 386 bytes from /etc/os-release
2023-02-23 15:19:23,967 DEBUG cloudinit.util:1528 Reading from /proc/1/environ (quiet=False)
2023-02-23 15:19:23,967 DEBUG cloudinit.util:1539 Read 460 bytes from /proc/1/environ
2023-02-23 15:19:23,967 DEBUG cloudinit.util:1528 Reading from /proc/self/status (quiet=False)
2023-02-23 15:19:23,967 DEBUG cloudinit.util:1539 Read 1383 bytes from /proc/self/status
2023-02-23 15:19:23,967 DEBUG cloudinit.util:1528 Reading from /proc/cmdline (quiet=False)
2023-02-23 15:19:23,967 DEBUG cloudinit.util:1539 Read 231 bytes from /proc/cmdline
2023-02-23 15:19:23,967 DEBUG cloudinit.util:941 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2023-02-23 15:19:23,967 DEBUG cloudinit.util:949 loaded blob returned None, returning default.
2023-02-23 15:19:23,968 DEBUG cloudinit.util:1528 Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2023-02-23 15:19:23,968 DEBUG cloudinit.util:1539 Read 2581 bytes from /var/lib/cloud/instance/cloud-config.txt
2023-02-23 15:19:23,968 DEBUG cloudinit.util:941 Attempting to load yaml from string of length 2581 with allowed root types (<class 'dict'>,)
2023-02-23 15:19:23,974 DEBUG cloudinit.util:1528 Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
2023-02-23 15:19:23,974 DEBUG cloudinit.util:1539 Read 12089 bytes from /var/lib/cloud/instance/obj.pkl
2023-02-23 15:19:23,985 DEBUG cloudinit.util:1528 Reading from /run/cloud-init/.instance-id (quiet=False)
2023-02-23 15:19:23,985 DEBUG cloudinit.util:1539 Read 8 bytes from /run/cloud-init/.instance-id
2023-02-23 15:19:23,985 DEBUG cloudinit.stages:318 restored from cache with run check: DataSourceNoCloudNet [seed=cmdline,/var/lib/cloud/seed/nocloud,http://boot.linuxgroove.com/ubuntu/22.04/][dsmode=net]
2023-02-23 15:19:23,986 DEBUG cloudinit.util:1528 Reading from /etc/cloud/cloud.cfg (quiet=False)
2023-02-23 15:19:23,986 DEBUG cloudinit.util:1539 Read 3487 bytes from /etc/cloud/cloud.cfg
2023-02-23 15:19:23,986 DEBUG cloudinit.util:941 Attempting to load yaml from string of length 3487 with allowed root types (<class 'dict'>,)
2023-02-23 15:19:23,994 DEBUG cloudinit.util:1528 Reading from /etc/cloud/cloud.cfg.d/enp0s25.cfg (quiet=False)
2023-02-23 15:19:23,994 DEBUG cloudinit.util:1539 Read 203 bytes from /etc/cloud/cloud.cfg.d/enp0s25.cfg
2023-02-23 15:19:23,994 DEBUG cloudinit.util:941 Attempting to load yaml from string of length 203 with allowed root types (<class 'dict'>,)
2023-02-23 15:19:23,995 DEBUG cloudinit.util:1528 Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2023-02-23 15:19:23,995 DEBUG cloudinit.util:1539 Read 314 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2023-02-23 15:19:23,995 DEBUG cloudinit.util:941 Attempting to load yaml from string of length 314 with allowed root types (<class 'dict'>,)
2023-02-23 15:19:23,997 DEBUG cloudinit.util:1528 Reading from /etc/cloud/cloud.cfg.d/06_quiet.cfg (quiet=False)
2023-02-23 15:19:23,997 DEBUG cloudinit.util:1539 Read 112 bytes from /etc/cloud/cloud.cfg.d/06_quiet.cfg
2023-02-23 15:19:23,997 DEBUG cloudinit.util:941 Attempting to load yaml from string of length 112 with allowed root types (<class 'dict'>,)
2023-02-23 15:19:23,997 DEBUG cloudinit.util:1528 Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2023-02-23 15:19:23,997 DEBUG cloudinit.util:1539 Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2023-02-23 15:19:23,997 DEBUG cloudinit.util:941 Attempting to load yaml from string of length 2070 with allowed root types (<class 'dict'>,)
2023-02-23 15:19:24,000 DEBUG cloudinit.util:1528 Reading from /run/cloud-init/cloud.cfg (quiet=False)
2023-02-23 15:19:24,000 DEBUG cloudinit.util:1539 Read 35 bytes from /run/cloud-init/cloud.cfg
2023-02-23 15:19:24,000 DEBUG cloudinit.util:941 Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2023-02-23 15:19:24,000 DEBUG cloudinit.util:941 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2023-02-23 15:19:24,001 DEBUG cloudinit.util:949 loaded blob returned None, returning default.
2023-02-23 15:19:24,001 DEBUG cloudinit.util:1528 Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2023-02-23 15:19:24,001 DEBUG cloudinit.util:1539 Read 2581 bytes from /var/lib/cloud/instance/cloud-config.txt
2023-02-23 15:19:24,001 DEBUG cloudinit.util:941 Attempting to load yaml from string of length 2581 with allowed root types (<class 'dict'>,)
2023-02-23 15:19:24,007 DEBUG cloudinit.stages:136 Using distro class <class 'cloudinit.distros.ubuntu.Distro'>
2023-02-23 15:19:24,011 DEBUG subiquity.server.server:479 load_autoinstall_config only_early True file /autoinstall.yaml
2023-02-23 15:19:24,017 DEBUG curtin.reporting.start.subiquity/Reporting/load_autoinstall_data:45 start: subiquity/Reporting/load_autoinstall_data: 
2023-02-23 15:19:24,018 DEBUG curtin.reporting.finish.subiquity/Reporting/load_autoinstall_data:45 finish: subiquity/Reporting/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,018 DEBUG root:37 start: subiquity/Error/load_autoinstall_data: 
2023-02-23 15:19:24,019 DEBUG root:37 finish: subiquity/Error/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,019 INFO root:37 start: subiquity/core_validation: 
2023-02-23 15:19:24,020 INFO root:37 finish: subiquity/core_validation: SUCCESS: 
2023-02-23 15:19:24,020 DEBUG root:37 start: subiquity/Early/load_autoinstall_data: 
2023-02-23 15:19:24,020 DEBUG root:37 finish: subiquity/Early/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,021 DEBUG subiquity.server.server:479 load_autoinstall_config only_early False file /autoinstall.yaml
2023-02-23 15:19:24,026 DEBUG root:37 start: subiquity/Early/load_autoinstall_data: 
2023-02-23 15:19:24,026 DEBUG root:37 finish: subiquity/Early/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,026 DEBUG root:37 start: subiquity/Reporting/load_autoinstall_data: 
2023-02-23 15:19:24,026 DEBUG root:37 finish: subiquity/Reporting/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,027 DEBUG root:37 start: subiquity/Error/load_autoinstall_data: 
2023-02-23 15:19:24,027 DEBUG root:37 finish: subiquity/Error/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,027 DEBUG root:37 start: subiquity/Userdata/load_autoinstall_data: 
2023-02-23 15:19:24,028 DEBUG root:37 finish: subiquity/Userdata/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,028 DEBUG root:37 start: subiquity/Package/load_autoinstall_data: 
2023-02-23 15:19:24,028 DEBUG root:37 finish: subiquity/Package/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,028 DEBUG root:37 start: subiquity/Debconf/load_autoinstall_data: 
2023-02-23 15:19:24,029 DEBUG root:37 finish: subiquity/Debconf/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,029 DEBUG root:37 start: subiquity/Locale/load_autoinstall_data: 
2023-02-23 15:19:24,029 DEBUG root:37 finish: subiquity/Locale/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,029 DEBUG root:37 start: subiquity/Refresh/load_autoinstall_data: 
2023-02-23 15:19:24,030 DEBUG root:37 finish: subiquity/Refresh/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,030 DEBUG root:37 start: subiquity/Kernel/load_autoinstall_data: 
2023-02-23 15:19:24,031 DEBUG subiquity.server.controllers.kernel:90 Using kernel linux-generic-hwe-22.04 due to autoinstall
2023-02-23 15:19:24,031 DEBUG root:37 finish: subiquity/Kernel/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,031 DEBUG root:37 start: subiquity/Keyboard/load_autoinstall_data: 
2023-02-23 15:19:24,031 DEBUG root:37 finish: subiquity/Keyboard/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,032 DEBUG root:37 start: subiquity/Zdev/load_autoinstall_data: 
2023-02-23 15:19:24,032 DEBUG root:37 finish: subiquity/Zdev/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,032 DEBUG root:37 start: subiquity/Source/load_autoinstall_data: 
2023-02-23 15:19:24,032 DEBUG root:37 finish: subiquity/Source/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,032 DEBUG root:37 start: subiquity/Network/load_autoinstall_data: 
2023-02-23 15:19:24,033 DEBUG root:37 finish: subiquity/Network/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,033 DEBUG root:37 start: subiquity/UbuntuPro/load_autoinstall_data: 
2023-02-23 15:19:24,033 DEBUG root:37 finish: subiquity/UbuntuPro/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,033 DEBUG root:37 start: subiquity/Proxy/load_autoinstall_data: 
2023-02-23 15:19:24,033 DEBUG root:37 finish: subiquity/Proxy/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,033 DEBUG root:37 start: subiquity/Mirror/load_autoinstall_data: 
2023-02-23 15:19:24,034 DEBUG root:37 finish: subiquity/Mirror/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,034 DEBUG root:37 start: subiquity/Filesystem/load_autoinstall_data: 
2023-02-23 15:19:24,034 DEBUG subiquity.server.controllers.filesystem:115 load_autoinstall_data {'layout': {'name': 'direct'}}
2023-02-23 15:19:24,034 DEBUG subiquity.server.controllers.filesystem:125 self.ai_data = {'layout': {'name': 'direct'}}
2023-02-23 15:19:24,034 DEBUG root:37 finish: subiquity/Filesystem/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,034 DEBUG root:37 start: subiquity/Identity/load_autoinstall_data: 
2023-02-23 15:19:24,035 DEBUG root:37 finish: subiquity/Identity/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,035 DEBUG root:37 start: subiquity/SSH/load_autoinstall_data: 
2023-02-23 15:19:24,036 DEBUG root:37 finish: subiquity/SSH/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,036 DEBUG root:37 start: subiquity/SnapList/load_autoinstall_data: 
2023-02-23 15:19:24,036 DEBUG root:37 finish: subiquity/SnapList/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,036 DEBUG root:37 start: subiquity/Drivers/load_autoinstall_data: 
2023-02-23 15:19:24,037 DEBUG root:37 finish: subiquity/Drivers/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,037 DEBUG root:37 start: subiquity/TimeZone/load_autoinstall_data: 
2023-02-23 15:19:24,052 DEBUG root:37 finish: subiquity/TimeZone/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,052 DEBUG root:37 start: subiquity/Install/load_autoinstall_data: 
2023-02-23 15:19:24,052 DEBUG root:37 finish: subiquity/Install/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,052 DEBUG root:37 start: subiquity/Updates/load_autoinstall_data: 
2023-02-23 15:19:24,053 DEBUG root:37 finish: subiquity/Updates/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,053 DEBUG root:37 start: subiquity/Late/load_autoinstall_data: 
2023-02-23 15:19:24,054 DEBUG root:37 finish: subiquity/Late/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,054 DEBUG root:37 start: subiquity/Shutdown/load_autoinstall_data: 
2023-02-23 15:19:24,054 DEBUG root:37 finish: subiquity/Shutdown/load_autoinstall_data: SUCCESS: 
2023-02-23 15:19:24,055 DEBUG subiquitycore.core:120 starting controllers
2023-02-23 15:19:24,058 DEBUG subiquity.models.source:87 loaded 2 sources from '/cdrom/casper/install-sources.yaml'
2023-02-23 15:19:24,063 DEBUG probert.network:585 event for link_change: NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2023-02-23 15:19:24,063 DEBUG probert.network:585 event for link_change: NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'enp0s25'}
2023-02-23 15:19:24,063 DEBUG probert.network:585 event for link_change: NEW {'ifindex': 3, 'flags': 4099, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'wlp2s0'}
2023-02-23 15:19:24,063 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'}
2023-02-23 15:19:24,063 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 2, 'flags': 128, 'family': 2, 'scope': 0, 'local': b'192.168.1.67/24'}
2023-02-23 15:19:24,063 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2023-02-23 15:19:24,063 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 2, 'flags': 512, 'family': 10, 'scope': 0, 'local': b'2600:1700:f91:16e0::4a1'}
2023-02-23 15:19:24,063 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2600:1700:f91:16e0:c67d:46ff:fe17:9e01/64'}
2023-02-23 15:19:24,063 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::c67d:46ff:fe17:9e01/64'}
2023-02-23 15:19:24,064 DEBUG probert.network:672 link_change NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2023-02-23 15:19:24,154 DEBUG subiquitycore.models.network:435 new_link 1 lo lo
2023-02-23 15:19:24,155 DEBUG subiquitycore.models.network:437 ignoring based on type
2023-02-23 15:19:24,155 DEBUG probert.network:672 link_change NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'enp0s25'}
2023-02-23 15:19:24,216 DEBUG subiquitycore.models.network:435 new_link 2 enp0s25 eth
2023-02-23 15:19:24,216 DEBUG subiquitycore.models.network:466 new_link 2 enp0s25 with config {'critical': True, 'dhcp-identifier': 'mac', 'dhcp4': True, 'nameservers': {'addresses': ['192.168.1.254'], 'search': ['attlocal.net']}}
2023-02-23 15:19:24,216 DEBUG root:37 start: subiquity/Network/_send_update: NEW enp0s25
2023-02-23 15:19:24,216 DEBUG subiquity.server.controllers.network:354 dev_info enp0s25 {'critical': True, 'dhcp-identifier': 'mac', 'dhcp4': True, 'nameservers': {'addresses': ['192.168.1.254'], 'search': ['attlocal.net']}}
2023-02-23 15:19:24,217 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: NEW enp0s25
2023-02-23 15:19:24,217 DEBUG probert.network:672 link_change NEW {'ifindex': 3, 'flags': 4099, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'wlp2s0'}
2023-02-23 15:19:24,277 DEBUG subiquitycore.models.network:435 new_link 3 wlp2s0 wlan
2023-02-23 15:19:24,277 DEBUG subiquitycore.models.network:466 new_link 3 wlp2s0 with config {}
2023-02-23 15:19:24,277 DEBUG subiquity.server.controllers.network:118 maybe_start_install_wpasupplicant
2023-02-23 15:19:24,277 DEBUG probert.network:717 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'}
2023-02-23 15:19:24,278 DEBUG probert.network:717 addr_change NEW {'ifindex': 2, 'flags': 128, 'family': 2, 'scope': 0, 'local': b'192.168.1.67/24'}
2023-02-23 15:19:24,278 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE enp0s25
2023-02-23 15:19:24,278 DEBUG subiquity.server.controllers.network:354 dev_info enp0s25 {'critical': True, 'dhcp-identifier': 'mac', 'dhcp4': True, 'nameservers': {'addresses': ['192.168.1.254'], 'search': ['attlocal.net']}}
2023-02-23 15:19:24,278 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp0s25
2023-02-23 15:19:24,278 DEBUG probert.network:717 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2023-02-23 15:19:24,279 DEBUG probert.network:717 addr_change NEW {'ifindex': 2, 'flags': 512, 'family': 10, 'scope': 0, 'local': b'2600:1700:f91:16e0::4a1'}
2023-02-23 15:19:24,279 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE enp0s25
2023-02-23 15:19:24,279 DEBUG subiquity.server.controllers.network:354 dev_info enp0s25 {'critical': True, 'dhcp-identifier': 'mac', 'dhcp4': True, 'nameservers': {'addresses': ['192.168.1.254'], 'search': ['attlocal.net']}}
2023-02-23 15:19:24,279 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp0s25
2023-02-23 15:19:24,279 DEBUG probert.network:717 addr_change NEW {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2600:1700:f91:16e0:c67d:46ff:fe17:9e01/64'}
2023-02-23 15:19:24,279 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE enp0s25
2023-02-23 15:19:24,279 DEBUG subiquity.server.controllers.network:354 dev_info enp0s25 {'critical': True, 'dhcp-identifier': 'mac', 'dhcp4': True, 'nameservers': {'addresses': ['192.168.1.254'], 'search': ['attlocal.net']}}
2023-02-23 15:19:24,279 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp0s25
2023-02-23 15:19:24,280 DEBUG probert.network:717 addr_change NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::c67d:46ff:fe17:9e01/64'}
2023-02-23 15:19:24,280 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE enp0s25
2023-02-23 15:19:24,280 DEBUG subiquity.server.controllers.network:354 dev_info enp0s25 {'critical': True, 'dhcp-identifier': 'mac', 'dhcp4': True, 'nameservers': {'addresses': ['192.168.1.254'], 'search': ['attlocal.net']}}
2023-02-23 15:19:24,280 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp0s25
2023-02-23 15:19:24,280 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2023-02-23 15:19:24,280 DEBUG subiquitycore.controllers.network:94 default routes {2}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'192.168.1.0/24', 'ifindex': 2}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.0/8', 'ifindex': 1}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.1', 'ifindex': 1}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'127.255.255.255', 'ifindex': 1}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'192.168.1.67', 'ifindex': 2}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'192.168.1.255', 'ifindex': 2}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'::1', 'ifindex': 1}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'2600:1700:f91:16e0::/64', 'ifindex': 2}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'2600:1700:f91:16e0::/64', 'ifindex': 2}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'2600:1700:f91:16e0::/60', 'ifindex': 2}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'fe80::/64', 'ifindex': 2}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2023-02-23 15:19:24,281 DEBUG subiquitycore.controllers.network:94 default routes {2}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2023-02-23 15:19:24,281 DEBUG subiquitycore.controllers.network:94 default routes {2}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'::1', 'ifindex': 1}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'2600:1700:f91:16e0::4a1', 'ifindex': 2}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'2600:1700:f91:16e0:c67d:46ff:fe17:9e01', 'ifindex': 2}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'fe80::c67d:46ff:fe17:9e01', 'ifindex': 2}
2023-02-23 15:19:24,281 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 5, 'table': 255, 'dst': b'ff00::/8', 'ifindex': 2}
2023-02-23 15:19:24,281 DEBUG probert.network:741 wlan_event {'cmd': 'NEW_INTERFACE', 'ifindex': 3, 'ssids': []}
2023-02-23 15:19:24,283 DEBUG subiquitycore.core:123 controllers started
2023-02-23 15:19:24,283 INFO root:37 start: subiquity/apply_autoinstall_config: 
2023-02-23 15:19:24,283 DEBUG root:37 start: subiquity/Early/apply_autoinstall_config: 
2023-02-23 15:19:24,283 DEBUG root:37 finish: subiquity/Early/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:24,283 DEBUG root:37 start: subiquity/Reporting/apply_autoinstall_config: 
2023-02-23 15:19:24,283 DEBUG root:37 finish: subiquity/Reporting/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:24,284 DEBUG root:37 start: subiquity/Error/apply_autoinstall_config: 
2023-02-23 15:19:24,284 DEBUG root:37 finish: subiquity/Error/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:24,284 DEBUG root:37 start: subiquity/Userdata/apply_autoinstall_config: 
2023-02-23 15:19:24,284 DEBUG root:37 finish: subiquity/Userdata/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:24,284 DEBUG subiquity.models.subiquity:231 model userdata for postinstall stage is configured, to go {'drivers', 'packages', 'ubuntu_pro', 'ssh', 'locale', 'identity', 'snaplist', 'network'}
2023-02-23 15:19:24,284 DEBUG root:37 start: subiquity/Package/apply_autoinstall_config: 
2023-02-23 15:19:24,284 DEBUG root:37 finish: subiquity/Package/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:24,285 DEBUG subiquity.models.subiquity:231 model packages for postinstall stage is configured, to go {'drivers', 'ubuntu_pro', 'ssh', 'locale', 'identity', 'snaplist', 'network'}
2023-02-23 15:19:24,285 DEBUG root:37 start: subiquity/Debconf/apply_autoinstall_config: 
2023-02-23 15:19:24,285 DEBUG root:37 finish: subiquity/Debconf/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:24,285 DEBUG subiquity.models.subiquity:231 model debconf_selections for install stage is configured, to go {'source', 'proxy', 'filesystem', 'kernel', 'keyboard', 'network', 'mirror'}
2023-02-23 15:19:24,285 DEBUG root:37 start: subiquity/Locale/apply_autoinstall_config: 
2023-02-23 15:19:24,285 DEBUG root:37 finish: subiquity/Locale/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:24,285 DEBUG subiquity.models.subiquity:231 model locale for postinstall stage is configured, to go {'drivers', 'ubuntu_pro', 'ssh', 'identity', 'snaplist', 'network'}
2023-02-23 15:19:24,285 DEBUG root:37 start: subiquity/Refresh/apply_autoinstall_config: 
2023-02-23 15:19:24,286 INFO root:37 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "WAITING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2023-02-23 15:19:24,286 DEBUG subiquity.models.subiquity:231 model locale for postinstall stage is configured, to go {'drivers', 'ubuntu_pro', 'ssh', 'identity', 'snaplist', 'network'}
2023-02-23 15:19:24,286 DEBUG root:37 start: subiquity/Refresh/configure_snapd: 
2023-02-23 15:19:24,287 DEBUG root:37 start: subiquity/Refresh/configure_snapd/get_details: 
2023-02-23 15:19:24,287 DEBUG root:37 start: subiquity/Refresh/check_for_update: 
2023-02-23 15:19:24,288 DEBUG root:37 start: subiquity/Network/wait_for_initial_config: 
2023-02-23 15:19:24,290 DEBUG root:37 start: subiquity/Network/wait_for_initial_config/wait_dhcp: 
2023-02-23 15:19:24,290 DEBUG subiquity.server.controllers.network:151 checking if wpasupplicant is available
2023-02-23 15:19:24,363 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/snaps/subiquity HTTP/1.1" 200 1129
2023-02-23 15:19:25,269 DEBUG subiquity.server.controllers.network:158 wpasupplicant already installed
2023-02-23 15:19:25,272 DEBUG subiquity.server.controllers.network:142 wlan_support_install_finished WLANSupportInstallState.DONE
2023-02-23 15:19:25,273 DEBUG root:37 start: subiquity/Network/_send_update: NEW wlp2s0
2023-02-23 15:19:25,273 DEBUG subiquity.server.controllers.network:354 dev_info wlp2s0 {}
2023-02-23 15:19:25,273 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: NEW wlp2s0
2023-02-23 15:19:25,278 DEBUG root:37 start: subiquity/Drivers/_list_drivers: 
2023-02-23 15:19:25,279 DEBUG root:37 start: subiquity/Drivers/_list_drivers/wait_apt: 
2023-02-23 15:19:25,279 DEBUG root:37 start: subiquity/Install/install: 
2023-02-23 15:19:25,279 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2023-02-23 15:19:25,291 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2023-02-23 15:19:25,291 DEBUG probert.network:741 wlan_event {'cmd': 'TRIGGER_SCAN', 'ifindex': 3}
2023-02-23 15:19:25,292 INFO aiohttp.access:233  [23/Feb/2023:15:19:23 +0000] "GET /meta/status?cur=%22CLOUD_INIT_WAIT%22 HTTP/1.1" 200 413 "-" "Python/3.8 aiohttp/3.6.2"
2023-02-23 15:19:25,296 DEBUG root:37 start: subiquity/Filesystem/_probe: 
2023-02-23 15:19:25,297 DEBUG root:37 finish: subiquity/Refresh/configure_snapd/get_details: SUCCESS: current version of snap is: '23.02.1'
2023-02-23 15:19:25,297 DEBUG root:37 start: subiquity/Refresh/configure_snapd/switching: switching subiquity to stable
2023-02-23 15:19:25,298 DEBUG root:37 start: subiquity/Refresh/check_for_update: 
2023-02-23 15:19:25,299 DEBUG root:37 start: subiquity/Refresh/check_for_update: 
2023-02-23 15:19:25,300 DEBUG root:37 start: subiquity/Refresh/check_for_update: 
2023-02-23 15:19:25,301 DEBUG root:37 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2023-02-23 15:19:25,302 ERROR root:37 finish: subiquity/Refresh/check_for_update: FAIL: cancelled
2023-02-23 15:19:25,304 ERROR root:37 finish: subiquity/Refresh/check_for_update: FAIL: cancelled
2023-02-23 15:19:25,305 ERROR root:37 finish: subiquity/Refresh/check_for_update: FAIL: cancelled
2023-02-23 15:19:25,306 INFO root:37 start: subiquity/Meta/status_GET: 
2023-02-23 15:19:25,311 DEBUG urllib3.connectionpool:456 http://localhost:None "POST /v2/snaps/subiquity HTTP/1.1" 202 81
2023-02-23 15:19:25,315 DEBUG probert.dasd:134 Probing DASD devies
2023-02-23 15:19:25,315 DEBUG probert.dasd:137 DASD devices only present on s390x, arch=x86_64
2023-02-23 15:19:25,316 DEBUG urllib3.connectionpool:456 http://localhost:None "GET /v2/changes/6 HTTP/1.1" 200 499
2023-02-23 15:19:25,320 DEBUG root:37 finish: subiquity/Refresh/configure_snapd/switching: SUCCESS: switched to stable
2023-02-23 15:19:25,320 DEBUG root:37 finish: subiquity/Refresh/configure_snapd: SUCCESS: 
2023-02-23 15:19:25,321 DEBUG root:37 finish: subiquity/Refresh/check_for_update: SUCCESS: not offered update when already updated
2023-02-23 15:19:25,323 DEBUG root:37 finish: subiquity/Refresh/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:25,324 DEBUG root:37 start: subiquity/Kernel/apply_autoinstall_config: 
2023-02-23 15:19:25,324 DEBUG root:37 finish: subiquity/Kernel/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:25,325 DEBUG subiquity.models.subiquity:231 model kernel for install stage is configured, to go {'source', 'proxy', 'filesystem', 'keyboard', 'network', 'mirror'}
2023-02-23 15:19:25,325 DEBUG root:37 start: subiquity/Keyboard/apply_autoinstall_config: 
2023-02-23 15:19:25,325 DEBUG subiquitycore.utils:92 arun_command called: ['setupcon', '--save', '--force', '--keyboard-only']
2023-02-23 15:19:25,382 DEBUG subiquitycore.utils:101 arun_command ['setupcon', '--save', '--force', '--keyboard-only'] exited with code 1
2023-02-23 15:19:25,382 DEBUG subiquitycore.utils:92 arun_command called: ['/snap/subiquity/4380/bin/subiquity-loadkeys']
2023-02-23 15:19:25,386 DEBUG subiquitycore.utils:101 arun_command ['/snap/subiquity/4380/bin/subiquity-loadkeys'] exited with code 0
2023-02-23 15:19:25,386 DEBUG root:37 finish: subiquity/Keyboard/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:25,387 DEBUG subiquity.models.subiquity:231 model keyboard for install stage is configured, to go {'source', 'proxy', 'filesystem', 'network', 'mirror'}
2023-02-23 15:19:25,387 DEBUG root:37 start: subiquity/Zdev/apply_autoinstall_config: 
2023-02-23 15:19:25,387 DEBUG root:37 finish: subiquity/Zdev/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:25,388 DEBUG curtin:87 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/ubuntu-server-minimal.squashfs', '/tmp/tmpdxd4ul8a/ubuntu-server-minimal.squashfs.dir'] with allowed return codes [0] (capture=True)
2023-02-23 15:19:25,392 DEBUG curtin:87 Running command ['mount', '-o', 'loop,ro', '///cdrom/casper/ubuntu-server-minimal.ubuntu-server.squashfs', '/tmp/tmpdxd4ul8a/ubuntu-server-minimal.ubuntu-server.squashfs.dir'] with allowed return codes [0] (capture=True)
2023-02-23 15:19:25,399 DEBUG curtin:87 Running command ['mount', '-o', 'lowerdir=/tmp/tmpdxd4ul8a/ubuntu-server-minimal.ubuntu-server.squashfs.dir:/tmp/tmpdxd4ul8a/ubuntu-server-minimal.squashfs.dir', '-t', 'overlay', 'overlay', '/tmp/tmpdxd4ul8a/root.dir'] with allowed return codes [0] (capture=True)
2023-02-23 15:19:25,405 DEBUG subiquity.models.subiquity:231 model source for install stage is configured, to go {'network', 'proxy', 'filesystem', 'mirror'}
2023-02-23 15:19:25,405 DEBUG root:37 start: subiquity/Network/apply_autoinstall_config: 
2023-02-23 15:19:25,406 DEBUG root:37 start: subiquity/Network/apply_autoinstall_config/wait_initial_config: 
2023-02-23 15:19:25,676 ERROR probert.filesystems:46 Command '['/usr/sbin/resize2fs', '-P', '/dev/sda2']' returned non-zero exit status 1.
Traceback (most recent call last):
  File "/snap/subiquity/4380/lib/python3.8/site-packages/probert/filesystem.py", line 41, in run
    return subprocess.check_output(cmdarr, universal_newlines=True,
  File "/snap/subiquity/4380/usr/lib/python3.8/subprocess.py", line 415, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/snap/subiquity/4380/usr/lib/python3.8/subprocess.py", line 516, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['/usr/sbin/resize2fs', '-P', '/dev/sda2']' returned non-zero exit status 1.
2023-02-23 15:19:25,722 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2023-02-23 15:19:25,735 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 1
2023-02-23 15:19:25,735 DEBUG subiquity.server.controllers.filesystem:671 waiting 0.1 to let udev event queue settle
2023-02-23 15:19:25,836 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2023-02-23 15:19:25,855 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2023-02-23 15:19:25,855 DEBUG subiquity.server.controllers.filesystem:683 _udev_event change Device('/sys/devices/pci0000:00/0000:00:1f.2/ata5/host4/target4:0:0/4:0:0:0/block/sda/sda2')
2023-02-23 15:19:25,855 DEBUG subiquity.server.controllers.filesystem:683 _udev_event change Device('/sys/devices/pci0000:00/0000:00:1f.2/ata5/host4/target4:0:0/4:0:0:0/block/sda/sda2')
2023-02-23 15:19:25,856 DEBUG subiquity.server.controllers.filesystem:687 Skipping run of Probert - probe run already active
2023-02-23 15:19:25,970 DEBUG probert.multipath:48 Extracted multipath maps fields: ['ok']
2023-02-23 15:19:25,970 DEBUG probert.multipath:52 Failed to parse multipath maps entry: ok: __new__() missing 2 required positional arguments: 'sysfs' and 'paths'
2023-02-23 15:19:25,975 DEBUG probert.multipath:48 Extracted multipath paths fields: ['sda', 'S1ZFNXAG723260', '[orphan]', '[undef]', 'ata-5.00', '[undef]', '[undef]', '[undef]']
2023-02-23 15:19:25,982 DEBUG curtin:1303 Extracting storage config from probe data
2023-02-23 15:19:25,983 DEBUG curtin:73 /dev/sdb is multipath device member? False
2023-02-23 15:19:25,983 DEBUG curtin:86 /dev/sdb is multipath device partition? False
2023-02-23 15:19:25,983 DEBUG curtin:61 /dev/sdb is multipath device? False
2023-02-23 15:19:25,983 DEBUG curtin:86 /dev/sdb is multipath device partition? False
2023-02-23 15:19:25,983 DEBUG curtin:61 /dev/sdb is multipath device? False
2023-02-23 15:19:25,993 DEBUG curtin:73 /dev/sdb1 is multipath device member? False
2023-02-23 15:19:25,993 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2023-02-23 15:19:25,994 DEBUG curtin:61 /dev/sdb1 is multipath device? False
2023-02-23 15:19:25,994 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2023-02-23 15:19:25,994 DEBUG curtin:86 /dev/sdb1 is multipath device partition? False
2023-02-23 15:19:26,003 DEBUG curtin:73 /dev/sdb2 is multipath device member? False
2023-02-23 15:19:26,003 DEBUG curtin:86 /dev/sdb2 is multipath device partition? False
2023-02-23 15:19:26,003 DEBUG curtin:61 /dev/sdb2 is multipath device? False
2023-02-23 15:19:26,003 DEBUG curtin:86 /dev/sdb2 is multipath device partition? False
2023-02-23 15:19:26,003 DEBUG curtin:86 /dev/sdb2 is multipath device partition? False
2023-02-23 15:19:26,012 DEBUG curtin:73 /dev/sr0 is multipath device member? False
2023-02-23 15:19:26,012 DEBUG curtin:86 /dev/sr0 is multipath device partition? False
2023-02-23 15:19:26,012 DEBUG curtin:73 /dev/sda is multipath device member? False
2023-02-23 15:19:26,012 DEBUG curtin:86 /dev/sda is multipath device partition? False
2023-02-23 15:19:26,012 DEBUG curtin:61 /dev/sda is multipath device? False
2023-02-23 15:19:26,012 DEBUG curtin:86 /dev/sda is multipath device partition? False
2023-02-23 15:19:26,012 DEBUG curtin:61 /dev/sda is multipath device? False
2023-02-23 15:19:26,022 DEBUG curtin:73 /dev/sda1 is multipath device member? False
2023-02-23 15:19:26,022 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2023-02-23 15:19:26,022 DEBUG curtin:61 /dev/sda1 is multipath device? False
2023-02-23 15:19:26,022 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2023-02-23 15:19:26,022 DEBUG curtin:86 /dev/sda1 is multipath device partition? False
2023-02-23 15:19:26,031 DEBUG curtin:73 /dev/sda2 is multipath device member? False
2023-02-23 15:19:26,031 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2023-02-23 15:19:26,031 DEBUG curtin:61 /dev/sda2 is multipath device? False
2023-02-23 15:19:26,031 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2023-02-23 15:19:26,031 DEBUG curtin:86 /dev/sda2 is multipath device partition? False
2023-02-23 15:19:26,040 DEBUG curtin:73 /dev/sdb is multipath device member? False
2023-02-23 15:19:26,049 DEBUG curtin:73 /dev/sdb1 is multipath device member? False
2023-02-23 15:19:26,058 DEBUG curtin:73 /dev/sdb2 is multipath device member? False
2023-02-23 15:19:26,067 DEBUG curtin:73 /dev/sda1 is multipath device member? False
2023-02-23 15:19:26,076 DEBUG curtin:73 /dev/sda2 is multipath device member? False
2023-02-23 15:19:26,085 DEBUG curtin:1310 Sorting extracted configurations
2023-02-23 15:19:26,085 INFO curtin:1329 Validating extracted storage config components
2023-02-23 15:19:26,100 DEBUG curtin:1346 Extracted (unmerged) storage config:
storage:
-   id: disk-sdb
    path: /dev/sdb
    ptable: dos
    serial: Generic_Flash_Disk_5D05AC5F-0:0
    type: disk
-   id: disk-sda
    path: /dev/sda
    ptable: gpt
    serial: SAMSUNG_MZ7LN128HCHP-00000_S1ZFNXAG723260
    type: disk
    wwn: '0x5002538d40351483'
-   device: disk-sdb
    flag: boot
    id: partition-sdb1
    number: 1
    partition_type: '0x0'
    path: /dev/sdb1
    size: 4194304
    type: partition
-   device: disk-sdb
    id: partition-sdb2
    number: 2
    offset: 67584
    partition_type: '0xef'
    path: /dev/sdb2
    size: 2580480
    type: partition
-   device: disk-sda
    flag: boot
    id: partition-sda1
    number: 1
    offset: 1048576
    partition_type: c12a7328-f81f-11d2-ba4b-00a0c93ec93b
    path: /dev/sda1
    size: 1127219200
    type: partition
-   device: disk-sda
    flag: linux
    id: partition-sda2
    number: 2
    offset: 1128267776
    partition_type: 0fc63daf-8483-4772-8e79-3d69d8477de4
    path: /dev/sda2
    size: 126906007552
    type: partition
-   fstype: iso9660
    id: format-disk-sdb
    type: format
    volume: disk-sdb
-   fstype: iso9660
    id: format-partition-sdb1
    type: format
    volume: partition-sdb1
-   fstype: vfat
    id: format-partition-sdb2
    type: format
    volume: partition-sdb2
-   fstype: vfat
    id: format-partition-sda1
    type: format
    volume: partition-sda1
-   fstype: ext4
    id: format-partition-sda2
    type: format
    uuid: 5c5acc73-00a0-423f-8c12-847b4b1df775
    volume: partition-sda2

2023-02-23 15:19:26,100 DEBUG curtin:1350 Generating storage config dependencies
2023-02-23 15:19:26,100 DEBUG curtin:236 Validate: partition-sdb1:SourceType:partition -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2023-02-23 15:19:26,100 DEBUG curtin:236 Validate: partition-sdb2:SourceType:partition -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2023-02-23 15:19:26,100 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2023-02-23 15:19:26,100 DEBUG curtin:236 Validate: partition-sda2:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2023-02-23 15:19:26,100 DEBUG curtin:236 Validate: format-disk-sdb:SourceType:format -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'lvm_partition', 'partition', 'disk', 'raid', 'bcache', 'dm_crypt'} ? result=True
2023-02-23 15:19:26,100 DEBUG curtin:236 Validate: format-partition-sdb1:SourceType:format -> (DepId:partition-sdb1 DepType:partition) in SourceDeps:{'lvm_partition', 'partition', 'disk', 'raid', 'bcache', 'dm_crypt'} ? result=True
2023-02-23 15:19:26,100 DEBUG curtin:236 Validate: partition-sdb1:SourceType:partition -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2023-02-23 15:19:26,100 DEBUG curtin:236 Validate: format-partition-sdb2:SourceType:format -> (DepId:partition-sdb2 DepType:partition) in SourceDeps:{'lvm_partition', 'partition', 'disk', 'raid', 'bcache', 'dm_crypt'} ? result=True
2023-02-23 15:19:26,100 DEBUG curtin:236 Validate: partition-sdb2:SourceType:partition -> (DepId:disk-sdb DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2023-02-23 15:19:26,100 DEBUG curtin:236 Validate: format-partition-sda1:SourceType:format -> (DepId:partition-sda1 DepType:partition) in SourceDeps:{'lvm_partition', 'partition', 'disk', 'raid', 'bcache', 'dm_crypt'} ? result=True
2023-02-23 15:19:26,100 DEBUG curtin:236 Validate: partition-sda1:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2023-02-23 15:19:26,100 DEBUG curtin:236 Validate: format-partition-sda2:SourceType:format -> (DepId:partition-sda2 DepType:partition) in SourceDeps:{'lvm_partition', 'partition', 'disk', 'raid', 'bcache', 'dm_crypt'} ? result=True
2023-02-23 15:19:26,100 DEBUG curtin:236 Validate: partition-sda2:SourceType:partition -> (DepId:disk-sda DepType:disk) in SourceDeps:{'disk', 'raid', 'partition', 'bcache'} ? result=True
2023-02-23 15:19:26,101 DEBUG curtin:1356 Merging storage config dependencies
2023-02-23 15:19:26,104 DEBUG curtin:1361 Merged storage config:
storage:
    config:
    -   id: disk-sda
        path: /dev/sda
        ptable: gpt
        serial: SAMSUNG_MZ7LN128HCHP-00000_S1ZFNXAG723260
        type: disk
        wwn: '0x5002538d40351483'
    -   id: disk-sdb
        path: /dev/sdb
        ptable: dos
        serial: Generic_Flash_Disk_5D05AC5F-0:0
        type: disk
    -   fstype: iso9660
        id: format-disk-sdb
        type: format
        volume: disk-sdb
    -   device: disk-sdb
        flag: boot
        id: partition-sdb1
        number: 1
        partition_type: '0x0'
        path: /dev/sdb1
        size: 4194304
        type: partition
    -   device: disk-sda
        flag: boot
        id: partition-sda1
        number: 1
        offset: 1048576
        partition_type: c12a7328-f81f-11d2-ba4b-00a0c93ec93b
        path: /dev/sda1
        size: 1127219200
        type: partition
    -   device: disk-sdb
        id: partition-sdb2
        number: 2
        offset: 67584
        partition_type: '0xef'
        path: /dev/sdb2
        size: 2580480
        type: partition
    -   device: disk-sda
        flag: linux
        id: partition-sda2
        number: 2
        offset: 1128267776
        partition_type: 0fc63daf-8483-4772-8e79-3d69d8477de4
        path: /dev/sda2
        size: 126906007552
        type: partition
    -   fstype: vfat
        id: format-partition-sda1
        type: format
        volume: partition-sda1
    -   fstype: ext4
        id: format-partition-sda2
        type: format
        uuid: 5c5acc73-00a0-423f-8c12-847b4b1df775
        volume: partition-sda2
    -   fstype: iso9660
        id: format-partition-sdb1
        type: format
        volume: partition-sdb1
    -   fstype: vfat
        id: format-partition-sdb2
        type: format
        volume: partition-sdb2
    version: 2

2023-02-23 15:19:26,104 DEBUG subiquity.models.filesystem:1356 exclusions set()
2023-02-23 15:19:26,104 DEBUG root:37 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False
2023-02-23 15:19:26,105 DEBUG root:37 finish: subiquity/Filesystem/_probe: SUCCESS: 
2023-02-23 15:19:27,271 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2023-02-23 15:19:27,283 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2023-02-23 15:19:27,283 DEBUG probert.network:741 wlan_event {'cmd': 'NEW_SCAN_RESULTS', 'ifindex': 3, 'ssids': [(b'EasyBoy WiFi', 'no status'), (b'world peace guest', 'no status'), (b'Sturk_Wifi_Home', 'no status'), (b'Sturk_Wifi_Home', 'no status'), (b'NETGEAR22', 'no status'), (b'posey', 'no status'), (b'posey', 'no status'), (b'posey', 'no status'), (b'Nodrog', 'no status'), (b'', 'no status'), (b'posey', 'no status'), (b'posey', 'no status'), (b'SpectrumSetup-4F', 'no status'), (b'Spectrum Mobile', 'no status'), (b'DIRECT-E8-HP DeskJet 2700 series', 'no status'), (b'Sturk_Wifi_Home', 'no status'), (b'', 'no status'), (b'Sturk_Wifi_Home', 'no status'), (b'world peace eero Guest', 'no status'), (b'world peace eero', 'no status'), (b'', 'no status'), (b'world peace', 'no status'), (b'CIAoperative5J', 'no status'), (b'CIAoperative5J_Guest', 'no status'), (b'CIAoperative5J_link', 'no status'), (b'posey', 'no status'), (b'', 'no status'), (b'', 'no status'), (b'world peace eero Guest', 'no status'), (b'world peace eero', 'no status')]}
2023-02-23 15:19:27,283 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2023-02-23 15:19:27,295 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2023-02-23 15:19:27,295 DEBUG probert.network:585 event for link_change: CHANGE {'ifindex': 3, 'flags': 4099, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'wlp2s0'}
2023-02-23 15:19:27,295 DEBUG probert.network:672 link_change CHANGE {'ifindex': 3, 'flags': 4099, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'wlp2s0'}
2023-02-23 15:19:27,296 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE wlp2s0
2023-02-23 15:19:27,296 DEBUG subiquity.server.controllers.network:354 dev_info wlp2s0 {}
2023-02-23 15:19:27,296 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE wlp2s0
2023-02-23 15:19:34,299 DEBUG root:37 finish: subiquity/Network/wait_for_initial_config/wait_dhcp: SUCCESS: 
2023-02-23 15:19:34,300 DEBUG root:37 finish: subiquity/Network/wait_for_initial_config: SUCCESS: 
2023-02-23 15:19:34,300 DEBUG root:37 finish: subiquity/Network/apply_autoinstall_config/wait_initial_config: SUCCESS: 
2023-02-23 15:19:34,301 DEBUG subiquitycore.controllers.network:192 updating initial NIC config
2023-02-23 15:19:34,301 DEBUG root:37 start: subiquity/Network/apply_autoinstall_config/wait_for_apply: 
2023-02-23 15:19:34,302 INFO root:37 start: subiquity/Network/apply_autoinstall_config/apply_config: silent=False
2023-02-23 15:19:34,303 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE enp0s25
2023-02-23 15:19:34,303 DEBUG subiquity.server.controllers.network:354 dev_info enp0s25 {'critical': True, 'dhcp-identifier': 'mac', 'dhcp4': True, 'nameservers': {'addresses': ['192.168.1.254'], 'search': ['attlocal.net']}}
2023-02-23 15:19:34,304 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp0s25
2023-02-23 15:19:34,308 DEBUG subiquitycore.controllers.network:240 network config: 
network:
  ethernets:
    enp0s25:
      critical: true
      dhcp-identifier: mac
      dhcp4: true
      nameservers:
        addresses:
        - 192.168.1.254
        search:
        - attlocal.net
  version: 2
  wifis: {}

2023-02-23 15:19:34,319 DEBUG subiquitycore.netplan:109 config for enp0s25 = {'critical': True, 'dhcp-identifier': 'mac', 'dhcp4': True, 'nameservers': {'addresses': ['192.168.1.254'], 'search': ['attlocal.net']}}
2023-02-23 15:19:34,319 DEBUG subiquitycore.utils:92 arun_command called: ['netplan', 'apply']
2023-02-23 15:19:34,890 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2023-02-23 15:19:34,911 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2023-02-23 15:19:34,911 DEBUG probert.network:585 event for addr_change: DEL {'ifindex': 2, 'flags': 512, 'family': 10, 'scope': 0, 'local': b'2600:1700:f91:16e0::4a1'}
2023-02-23 15:19:34,912 DEBUG probert.network:585 event for link_change: CHANGE {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'enp0s25'}
2023-02-23 15:19:34,912 DEBUG probert.network:717 addr_change DEL {'ifindex': 2, 'flags': 512, 'family': 10, 'scope': 0, 'local': b'2600:1700:f91:16e0::4a1'}
2023-02-23 15:19:34,912 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE enp0s25
2023-02-23 15:19:34,913 DEBUG subiquity.server.controllers.network:354 dev_info enp0s25 {'critical': True, 'dhcp-identifier': 'mac', 'dhcp4': True, 'nameservers': {'addresses': ['192.168.1.254'], 'search': ['attlocal.net']}}
2023-02-23 15:19:34,913 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp0s25
2023-02-23 15:19:34,913 DEBUG probert.network:731 route_change DEL {'family': 10, 'type': 2, 'table': 255, 'dst': b'2600:1700:f91:16e0::4a1', 'ifindex': 2}
2023-02-23 15:19:34,913 DEBUG probert.network:731 route_change DEL {'family': 10, 'type': 1, 'table': 254, 'dst': b'2600:1700:f91:16e0::/64', 'ifindex': 2}
2023-02-23 15:19:34,913 DEBUG probert.network:731 route_change DEL {'family': 10, 'type': 1, 'table': 254, 'dst': b'2600:1700:f91:16e0::/60', 'ifindex': 2}
2023-02-23 15:19:34,913 DEBUG probert.network:731 route_change DEL {'family': 10, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2023-02-23 15:19:34,913 DEBUG subiquitycore.controllers.network:94 default routes set()
2023-02-23 15:19:34,913 DEBUG probert.network:731 route_change DEL {'family': 10, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2023-02-23 15:19:34,913 DEBUG subiquitycore.controllers.network:94 default routes set()
2023-02-23 15:19:34,913 DEBUG probert.network:731 route_change DEL {'family': 2, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2023-02-23 15:19:34,913 DEBUG subiquitycore.controllers.network:94 default routes set()
2023-02-23 15:19:34,913 DEBUG probert.network:672 link_change CHANGE {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'enp0s25'}
2023-02-23 15:19:34,914 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE enp0s25
2023-02-23 15:19:34,914 DEBUG subiquity.server.controllers.network:354 dev_info enp0s25 {'critical': True, 'dhcp-identifier': 'mac', 'dhcp4': True, 'nameservers': {'addresses': ['192.168.1.254'], 'search': ['attlocal.net']}}
2023-02-23 15:19:34,914 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp0s25
2023-02-23 15:19:34,946 DEBUG subiquitycore.utils:101 arun_command ['netplan', 'apply'] exited with code 0
2023-02-23 15:19:34,999 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2023-02-23 15:19:35,011 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2023-02-23 15:19:35,978 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2023-02-23 15:19:35,995 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2023-02-23 15:19:35,995 DEBUG probert.network:585 event for addr_change: CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2600:1700:f91:16e0:c67d:46ff:fe17:9e01/64'}
2023-02-23 15:19:35,995 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2023-02-23 15:19:35,995 DEBUG subiquitycore.controllers.network:94 default routes {2}
2023-02-23 15:19:35,996 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'2600:1700:f91:16e0::/64', 'ifindex': 2}
2023-02-23 15:19:35,996 DEBUG probert.network:717 addr_change CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2600:1700:f91:16e0:c67d:46ff:fe17:9e01/64'}
2023-02-23 15:19:35,996 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE enp0s25
2023-02-23 15:19:35,997 DEBUG subiquity.server.controllers.network:354 dev_info enp0s25 {'critical': True, 'dhcp-identifier': 'mac', 'dhcp4': True, 'nameservers': {'addresses': ['192.168.1.254'], 'search': ['attlocal.net']}}
2023-02-23 15:19:35,997 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp0s25
2023-02-23 15:19:35,997 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'2600:1700:f91:16e0::/60', 'ifindex': 2}
2023-02-23 15:19:38,172 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2023-02-23 15:19:38,191 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2023-02-23 15:19:38,191 DEBUG probert.network:585 event for addr_change: NEW {'ifindex': 2, 'flags': 576, 'family': 10, 'scope': 0, 'local': b'2600:1700:f91:16e0::4a1'}
2023-02-23 15:19:38,191 DEBUG probert.network:717 addr_change NEW {'ifindex': 2, 'flags': 576, 'family': 10, 'scope': 0, 'local': b'2600:1700:f91:16e0::4a1'}
2023-02-23 15:19:38,192 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE enp0s25
2023-02-23 15:19:38,192 DEBUG subiquity.server.controllers.network:354 dev_info enp0s25 {'critical': True, 'dhcp-identifier': 'mac', 'dhcp4': True, 'nameservers': {'addresses': ['192.168.1.254'], 'search': ['attlocal.net']}}
2023-02-23 15:19:38,192 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp0s25
2023-02-23 15:19:39,654 DEBUG subiquitycore.utils:64 run_command called: ['udevadm', 'settle', '-t', '0']
2023-02-23 15:19:39,675 DEBUG subiquitycore.utils:77 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2023-02-23 15:19:39,675 DEBUG probert.network:585 event for addr_change: CHANGE {'ifindex': 2, 'flags': 512, 'family': 10, 'scope': 0, 'local': b'2600:1700:f91:16e0::4a1'}
2023-02-23 15:19:39,675 DEBUG probert.network:717 addr_change CHANGE {'ifindex': 2, 'flags': 512, 'family': 10, 'scope': 0, 'local': b'2600:1700:f91:16e0::4a1'}
2023-02-23 15:19:39,676 DEBUG root:37 start: subiquity/Network/_send_update: CHANGE enp0s25
2023-02-23 15:19:39,676 DEBUG subiquity.server.controllers.network:354 dev_info enp0s25 {'critical': True, 'dhcp-identifier': 'mac', 'dhcp4': True, 'nameservers': {'addresses': ['192.168.1.254'], 'search': ['attlocal.net']}}
2023-02-23 15:19:39,677 DEBUG root:37 finish: subiquity/Network/_send_update: SUCCESS: CHANGE enp0s25
2023-02-23 15:19:39,677 DEBUG probert.network:731 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'2600:1700:f91:16e0::4a1', 'ifindex': 2}
2023-02-23 15:19:44,952 INFO root:37 finish: subiquity/Network/apply_autoinstall_config/apply_config: SUCCESS: silent=False
2023-02-23 15:19:44,953 DEBUG root:37 finish: subiquity/Network/apply_autoinstall_config/wait_for_apply: SUCCESS: 
2023-02-23 15:19:44,954 DEBUG subiquitycore.models.network:427 has_network True
2023-02-23 15:19:44,956 DEBUG root:37 finish: subiquity/Network/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:44,956 DEBUG subiquitycore.models.network:427 has_network True
2023-02-23 15:19:44,957 DEBUG subiquity.models.subiquity:231 model network for install stage is configured, to go {'proxy', 'filesystem', 'mirror'}
2023-02-23 15:19:44,957 DEBUG subiquity.models.subiquity:231 model network for postinstall stage is configured, to go {'drivers', 'ubuntu_pro', 'ssh', 'identity', 'snaplist'}
2023-02-23 15:19:44,958 DEBUG root:37 start: subiquity/UbuntuPro/apply_autoinstall_config: 
2023-02-23 15:19:44,958 DEBUG root:37 finish: subiquity/UbuntuPro/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:44,959 DEBUG subiquity.models.subiquity:231 model ubuntu_pro for postinstall stage is configured, to go {'drivers', 'ssh', 'identity', 'snaplist'}
2023-02-23 15:19:44,960 DEBUG root:37 start: subiquity/Proxy/apply_autoinstall_config: 
2023-02-23 15:19:44,961 DEBUG root:37 finish: subiquity/Proxy/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:44,962 DEBUG subiquity.models.subiquity:231 model proxy for install stage is configured, to go {'filesystem', 'mirror'}
2023-02-23 15:19:44,962 DEBUG root:37 start: subiquity/Mirror/apply_autoinstall_config: 
2023-02-23 15:19:44,963 DEBUG root:37 start: subiquity/Mirror/apply_autoinstall_config/waiting: 
2023-02-23 15:19:44,964 DEBUG root:37 finish: subiquity/Mirror/apply_autoinstall_config/waiting: SUCCESS: 
2023-02-23 15:19:44,965 DEBUG root:37 finish: subiquity/Mirror/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:44,966 DEBUG subiquity.models.subiquity:231 model mirror for install stage is configured, to go {'filesystem'}
2023-02-23 15:19:44,967 DEBUG root:37 start: subiquity/Filesystem/apply_autoinstall_config: 
2023-02-23 15:19:44,968 DEBUG root:37 start: subiquity/Filesystem/apply_autoinstall_config/convert_autoinstall_config: 
2023-02-23 15:19:44,968 DEBUG subiquity.server.controllers.filesystem:633 self.ai_data = {'layout': {'name': 'direct'}}
2023-02-23 15:19:44,969 INFO subiquity.server.controllers.filesystem:622 autoinstall: running guided direct install in mode reformat_disk using GuidedStorageTargetReformat(disk_id='disk-sda')
2023-02-23 15:19:44,972 DEBUG subiquity.models.filesystem:1535 add_partition: rounded size from 1127219200 to 1127219200
2023-02-23 15:19:44,972 DEBUG subiquity.models.filesystem:1611 adding fat32 to Partition(device=disk-sda, size=1127219200, wipe='superblock', flag='boot', number=1, grub_device=True, offset=1048576, id='partition-0')
2023-02-23 15:19:44,973 DEBUG subiquity.models.filesystem:1535 add_partition: rounded size from 126906007552 to 126906007552
2023-02-23 15:19:44,974 DEBUG subiquity.models.filesystem:1611 adding ext4 to Partition(device=disk-sda, size=126906007552, wipe='superblock', number=2, grub_device=None, offset=1128267776, id='partition-1')
2023-02-23 15:19:44,974 DEBUG root:37 finish: subiquity/Filesystem/apply_autoinstall_config/convert_autoinstall_config: SUCCESS: 
2023-02-23 15:19:44,975 DEBUG root:37 finish: subiquity/Filesystem/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:44,976 DEBUG subiquity.models.subiquity:231 model filesystem for install stage is configured, to go set()
2023-02-23 15:19:44,977 DEBUG root:37 start: subiquity/Identity/apply_autoinstall_config: 
2023-02-23 15:19:44,978 DEBUG root:37 finish: subiquity/Identity/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:44,979 DEBUG subiquity.models.subiquity:231 model identity for postinstall stage is configured, to go {'drivers', 'ssh', 'snaplist'}
2023-02-23 15:19:44,979 DEBUG root:37 start: subiquity/SSH/apply_autoinstall_config: 
2023-02-23 15:19:44,980 DEBUG root:37 finish: subiquity/SSH/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:44,981 DEBUG subiquity.models.subiquity:231 model ssh for postinstall stage is configured, to go {'drivers', 'snaplist'}
2023-02-23 15:19:44,982 DEBUG root:37 start: subiquity/SnapList/apply_autoinstall_config: 
2023-02-23 15:19:44,982 DEBUG root:37 finish: subiquity/SnapList/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:44,983 DEBUG subiquity.models.subiquity:231 model snaplist for postinstall stage is configured, to go {'drivers'}
2023-02-23 15:19:44,984 DEBUG root:37 start: subiquity/Drivers/apply_autoinstall_config: 
2023-02-23 15:19:44,985 DEBUG root:37 finish: subiquity/Drivers/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:44,986 DEBUG subiquity.models.subiquity:231 model drivers for postinstall stage is configured, to go set()
2023-02-23 15:19:44,986 DEBUG root:37 start: subiquity/TimeZone/apply_autoinstall_config: 
2023-02-23 15:19:44,987 DEBUG root:37 finish: subiquity/TimeZone/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:44,988 DEBUG subiquity.server.server:471 apply_autoinstall_config: skipping Install as interactive
2023-02-23 15:19:44,988 DEBUG root:37 start: subiquity/Updates/apply_autoinstall_config: 
2023-02-23 15:19:44,989 DEBUG root:37 finish: subiquity/Updates/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:44,991 DEBUG root:37 start: subiquity/Late/apply_autoinstall_config: 
2023-02-23 15:19:44,991 DEBUG root:37 finish: subiquity/Late/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:44,992 DEBUG root:37 start: subiquity/Shutdown/apply_autoinstall_config: 
2023-02-23 15:19:44,993 DEBUG root:37 finish: subiquity/Shutdown/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:44,994 INFO root:37 finish: subiquity/apply_autoinstall_config: SUCCESS: 
2023-02-23 15:19:44,997 INFO root:37 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "NEEDS_CONFIRMATION", "confirming_tty": "", "error": null, "cloud_i...
2023-02-23 15:19:44,998 INFO aiohttp.access:233  [23/Feb/2023:15:19:25 +0000] "GET /meta/status?cur=%22WAITING%22 HTTP/1.1" 200 424 "-" "Python/3.8 aiohttp/3.6.2"
2023-02-23 15:19:44,999 INFO root:37 start: subiquity/Install/install/configure_apt: configuring apt
2023-02-23 15:19:45,000 DEBUG subiquitycore.utils:115 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2720', '--setenv', 'PATH=/snap/subiquity/4380/bin:/snap/subiquity/4380/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4380/bin:/snap/subiquity/4380/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4380/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4380/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4380', '--', 'mount', '-o', 'lowerdir=/tmp/tmpdxd4ul8a/root.dir,upperdir=/tmp/tmppe47jdrp/upper,workdir=/tmp/tmppe47jdrp/work', '-t', 'overlay', 'overlay', '/tmp/tmppe47jdrp/mount']
2023-02-23 15:19:45,015 INFO root:37 start: subiquity/Meta/status_GET: 
2023-02-23 15:19:45,016 INFO root:37 finish: subiquity/Meta/status_GET: SUCCESS: 200 {"state": "RUNNING", "confirming_tty": "", "error": null, "cloud_init_ok": tr...
2023-02-23 15:19:45,017 INFO aiohttp.access:233  [23/Feb/2023:15:19:45 +0000] "GET /meta/status?cur=%22NEEDS_CONFIRMATION%22 HTTP/1.1" 200 413 "-" "Python/3.8 aiohttp/3.6.2"
2023-02-23 15:19:45,018 INFO root:37 start: subiquity/Meta/status_GET: 
2023-02-23 15:19:45,056 DEBUG subiquitycore.utils:115 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2720', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/subiquity/4380/bin:/snap/subiquity/4380/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4380/bin:/snap/subiquity/4380/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4380/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4380/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4380', '--', '/snap/subiquity/4380/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.2720.1"}}', '-c', '/var/log/installer/subiquity-curtin-apt.conf', 'apt-config', '-t', '/tmp/tmppe47jdrp/mount']
2023-02-23 15:19:45,851 DEBUG root:37 start: subiquity/Mirror/cmd-apt-config: curtin command apt-config
2023-02-23 15:19:48,178 DEBUG subiquity.server.curtin:121 waited 0.1 seconds for events to drain
2023-02-23 15:19:48,224 DEBUG root:37 finish: subiquity/Mirror/cmd-apt-config: SUCCESS: curtin command apt-config
2023-02-23 15:19:48,279 DEBUG subiquity.server.curtin:121 waited 0.2 seconds for events to drain
2023-02-23 15:19:48,280 DEBUG subiquitycore.utils:115 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2720', '--setenv', 'PATH=/snap/subiquity/4380/bin:/snap/subiquity/4380/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4380/bin:/snap/subiquity/4380/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4380/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4380/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4380', '--', 'mount', '-o', 'lowerdir=/tmp/tmppe47jdrp/upper:/tmp/tmpdxd4ul8a/root.dir,upperdir=/tmp/tmp1ordx03c/upper,workdir=/tmp/tmp1ordx03c/work', '-t', 'overlay', 'overlay', '/tmp/tmp1ordx03c/mount']
2023-02-23 15:19:48,320 DEBUG subiquitycore.utils:115 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2720', '--setenv', 'PATH=/snap/subiquity/4380/bin:/snap/subiquity/4380/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4380/bin:/snap/subiquity/4380/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4380/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4380/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4380', '--', 'mount', '-o', 'bind', '/cdrom', '/tmp/tmp1ordx03c/mount/cdrom']
2023-02-23 15:19:48,336 DEBUG subiquitycore.utils:115 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2720', '--property', 'PrivateMounts=yes', '--setenv', 'PATH=/snap/subiquity/4380/bin:/snap/subiquity/4380/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4380/bin:/snap/subiquity/4380/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4380/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4380/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4380', '--', '/snap/subiquity/4380/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.2720.2"}}', 'in-target', '-t', '/tmp/tmp1ordx03c/mount', '--', 'apt-get', 'update']
2023-02-23 15:19:49,227 DEBUG root:37 start: subiquity/Install/install/configure_apt/cmd-in-target: curtin command in-target
2023-02-23 15:19:59,786 DEBUG subiquity.server.curtin:121 waited 0.1 seconds for events to drain
2023-02-23 15:19:59,887 DEBUG subiquity.server.curtin:121 waited 0.2 seconds for events to drain
2023-02-23 15:19:59,973 DEBUG root:37 finish: subiquity/Install/install/configure_apt/cmd-in-target: SUCCESS: curtin command in-target
2023-02-23 15:19:59,988 DEBUG subiquity.server.curtin:121 waited 0.30000000000000004 seconds for events to drain
2023-02-23 15:19:59,988 INFO root:37 finish: subiquity/Install/install/configure_apt: SUCCESS: configuring apt
2023-02-23 15:19:59,990 INFO root:37 start: subiquity/Install/install/curtin_install: installing system
2023-02-23 15:19:59,992 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step: executing curtin install initial step
2023-02-23 15:19:59,996 DEBUG root:37 finish: subiquity/Drivers/_list_drivers/wait_apt: SUCCESS: 
2023-02-23 15:19:59,997 DEBUG subiquitycore.utils:115 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2720', '--setenv', 'PATH=/snap/subiquity/4380/bin:/snap/subiquity/4380/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4380/bin:/snap/subiquity/4380/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4380/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4380/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4380', '--', 'mount', '-o', 'lowerdir=/tmp/tmpdxd4ul8a/root.dir:/tmp/tmppe47jdrp/upper:/tmp/tmp1ordx03c/upper,upperdir=/tmp/tmp8bnzi1xz/upper,workdir=/tmp/tmp8bnzi1xz/work', '-t', 'overlay', 'overlay', '/tmp/tmp8bnzi1xz/mount']
2023-02-23 15:20:00,004 DEBUG subiquitycore.utils:115 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2720', '--setenv', 'PATH=/snap/subiquity/4380/bin:/snap/subiquity/4380/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4380/bin:/snap/subiquity/4380/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4380/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4380/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4380', '--', '/snap/subiquity/4380/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.2720.3"}}', '-c', '/var/log/installer/curtin-install/subiquity-initial.conf', 'install', 'cp:///tmp/tmp1ordx03c/mount', '--set', 'json:stages=[]']
2023-02-23 15:20:00,036 DEBUG subiquitycore.utils:115 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2720', '--setenv', 'PATH=/snap/subiquity/4380/bin:/snap/subiquity/4380/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4380/bin:/snap/subiquity/4380/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4380/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4380/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4380', '--', 'chroot', '/tmp/tmp8bnzi1xz/mount', 'sh', '-c', 'command -v ubuntu-drivers']
2023-02-23 15:20:00,054 DEBUG subiquitycore.utils:115 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2720', '--property', 'PrivateMounts=yes', '--pipe', '--setenv', 'PATH=/snap/subiquity/4380/bin:/snap/subiquity/4380/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4380/bin:/snap/subiquity/4380/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4380/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4380/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4380', '--', '/snap/subiquity/4380/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.2720.4"}}', 'in-target', '-t', '/tmp/tmp8bnzi1xz/mount', '--', 'ubuntu-drivers', 'list', '--recommended', '--gpgpu']
2023-02-23 15:20:00,605 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step: SUCCESS: executing curtin install initial step
2023-02-23 15:20:00,605 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step: executing curtin install partitioning step
2023-02-23 15:20:00,606 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.source.SourceModel object at 0x7f82bc119df0>
2023-02-23 15:20:00,606 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.proxy.ProxyModel object at 0x7f82bc119e80>
2023-02-23 15:20:00,606 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.filesystem.FilesystemModel object at 0x7f82bc1b5c40>
2023-02-23 15:20:00,607 DEBUG subiquity.models.filesystem:1421 mountpoints {'/boot/efi': 'mount-0', '/': 'mount-1'}
2023-02-23 15:20:00,607 DEBUG subiquity.models.filesystem:1414 cannot emit action to mount /boot/efi until that for / is emitted
2023-02-23 15:20:00,607 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.kernel.KernelModel object at 0x7f82bc1b5b80>
2023-02-23 15:20:00,607 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.keyboard.KeyboardModel object at 0x7f82bc1b5ca0>
2023-02-23 15:20:00,607 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.network.NetworkModel object at 0x7f82bc119cd0>
2023-02-23 15:20:00,609 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.subiquity.DebconfSelectionsModel object at 0x7f82bc1b5bb0>
2023-02-23 15:20:00,609 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.mirror.MirrorModel object at 0x7f82bc1b5d90>
2023-02-23 15:20:00,616 DEBUG subiquitycore.utils:115 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2720', '--setenv', 'PATH=/snap/subiquity/4380/bin:/snap/subiquity/4380/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4380/bin:/snap/subiquity/4380/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4380/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4380/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4380', '--', '/snap/subiquity/4380/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.2720.5"}}', '-c', '/var/log/installer/curtin-install/subiquity-partitioning.conf', 'install', 'cp:///tmp/tmp1ordx03c/mount', '--set', 'json:stages=["partitioning"]']
2023-02-23 15:20:00,974 DEBUG root:37 start: subiquity/Drivers/_list_drivers/cmd-in-target: curtin command in-target
2023-02-23 15:20:01,723 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install: curtin command install
2023-02-23 15:20:01,724 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning: configuring storage
2023-02-23 15:20:01,724 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin: running 'curtin block-meta simple'
2023-02-23 15:20:01,980 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
2023-02-23 15:20:03,522 DEBUG subiquity.server.curtin:121 waited 0.1 seconds for events to drain
2023-02-23 15:20:03,575 DEBUG root:37 finish: subiquity/Drivers/_list_drivers/cmd-in-target: SUCCESS: curtin command in-target
2023-02-23 15:20:03,576 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
2023-02-23 15:20:03,623 DEBUG subiquity.server.curtin:121 waited 0.2 seconds for events to drain
2023-02-23 15:20:03,624 DEBUG subiquitycore.utils:115 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2720', '--setenv', 'PATH=/snap/subiquity/4380/bin:/snap/subiquity/4380/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4380/bin:/snap/subiquity/4380/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4380/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4380/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4380', '--', 'umount', '/tmp/tmp8bnzi1xz/mount']
2023-02-23 15:20:03,665 DEBUG subiquity.server.controllers.drivers:100 Available drivers to install: []
2023-02-23 15:20:03,666 DEBUG subiquity.models.subiquity:231 model drivers for postinstall stage is configured, to go set()
2023-02-23 15:20:03,666 DEBUG root:37 finish: subiquity/Drivers/_list_drivers: SUCCESS: 
2023-02-23 15:20:04,566 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
2023-02-23 15:20:04,567 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin/cmd-block-meta/: configuring disk: disk-sda
2023-02-23 15:20:04,567 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-sda
2023-02-23 15:20:04,567 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
2023-02-23 15:20:06,249 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
2023-02-23 15:20:06,250 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
2023-02-23 15:20:06,902 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
2023-02-23 15:20:06,902 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
2023-02-23 15:20:08,521 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
2023-02-23 15:20:08,522 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
2023-02-23 15:20:12,713 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
2023-02-23 15:20:12,714 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
2023-02-23 15:20:12,963 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
2023-02-23 15:20:12,963 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
2023-02-23 15:20:13,221 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
2023-02-23 15:20:13,221 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning/builtin: SUCCESS: running 'curtin block-meta simple'
2023-02-23 15:20:13,221 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-partitioning: SUCCESS: configuring storage
2023-02-23 15:20:13,222 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install: SUCCESS: curtin command install
2023-02-23 15:20:13,230 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step: SUCCESS: executing curtin install partitioning step
2023-02-23 15:20:13,231 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step: executing curtin install extract step
2023-02-23 15:20:13,231 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.source.SourceModel object at 0x7f82bc119df0>
2023-02-23 15:20:13,231 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.proxy.ProxyModel object at 0x7f82bc119e80>
2023-02-23 15:20:13,231 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.filesystem.FilesystemModel object at 0x7f82bc1b5c40>
2023-02-23 15:20:13,231 DEBUG subiquity.models.filesystem:1421 mountpoints {'/boot/efi': 'mount-0', '/': 'mount-1'}
2023-02-23 15:20:13,232 DEBUG subiquity.models.filesystem:1414 cannot emit action to mount /boot/efi until that for / is emitted
2023-02-23 15:20:13,232 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.kernel.KernelModel object at 0x7f82bc1b5b80>
2023-02-23 15:20:13,232 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.keyboard.KeyboardModel object at 0x7f82bc1b5ca0>
2023-02-23 15:20:13,232 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.network.NetworkModel object at 0x7f82bc119cd0>
2023-02-23 15:20:13,233 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.subiquity.DebconfSelectionsModel object at 0x7f82bc1b5bb0>
2023-02-23 15:20:13,233 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.mirror.MirrorModel object at 0x7f82bc1b5d90>
2023-02-23 15:20:13,239 DEBUG subiquitycore.utils:115 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2720', '--setenv', 'PATH=/snap/subiquity/4380/bin:/snap/subiquity/4380/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4380/bin:/snap/subiquity/4380/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4380/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4380/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4380', '--', '/snap/subiquity/4380/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.2720.6"}}', '-c', '/var/log/installer/curtin-install/subiquity-extract.conf', 'install', 'cp:///tmp/tmp1ordx03c/mount', '--set', 'json:stages=["extract"]']
2023-02-23 15:20:14,223 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install: curtin command install
2023-02-23 15:20:14,223 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-extract: writing install sources to disk
2023-02-23 15:20:14,223 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-extract/builtin: running 'curtin extract'
2023-02-23 15:20:14,722 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-extract/builtin/cmd-extract: curtin command extract
2023-02-23 15:20:14,723 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/tmp1ordx03c/mount
2023-02-23 15:20:33,655 DEBUG subiquity.server.curtin:121 waited 0.1 seconds for events to drain
2023-02-23 15:20:33,755 DEBUG subiquity.server.curtin:121 waited 0.2 seconds for events to drain
2023-02-23 15:20:33,856 DEBUG subiquity.server.curtin:121 waited 0.30000000000000004 seconds for events to drain
2023-02-23 15:20:33,957 DEBUG subiquity.server.curtin:121 waited 0.4 seconds for events to drain
2023-02-23 15:20:33,975 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/tmp1ordx03c/mount
2023-02-23 15:20:33,977 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-extract/builtin: SUCCESS: running 'curtin extract'
2023-02-23 15:20:33,978 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-extract: SUCCESS: writing install sources to disk
2023-02-23 15:20:33,979 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install: SUCCESS: curtin command install
2023-02-23 15:20:34,058 DEBUG subiquity.server.curtin:121 waited 0.5 seconds for events to drain
2023-02-23 15:20:34,059 DEBUG root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step: SUCCESS: executing curtin install extract step
2023-02-23 15:20:34,059 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step: executing curtin install curthooks step
2023-02-23 15:20:34,060 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.source.SourceModel object at 0x7f82bc119df0>
2023-02-23 15:20:34,060 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.proxy.ProxyModel object at 0x7f82bc119e80>
2023-02-23 15:20:34,060 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.filesystem.FilesystemModel object at 0x7f82bc1b5c40>
2023-02-23 15:20:34,060 DEBUG subiquity.models.filesystem:1421 mountpoints {'/boot/efi': 'mount-0', '/': 'mount-1'}
2023-02-23 15:20:34,061 DEBUG subiquity.models.filesystem:1414 cannot emit action to mount /boot/efi until that for / is emitted
2023-02-23 15:20:34,061 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.kernel.KernelModel object at 0x7f82bc1b5b80>
2023-02-23 15:20:34,061 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.keyboard.KeyboardModel object at 0x7f82bc1b5ca0>
2023-02-23 15:20:34,061 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.network.NetworkModel object at 0x7f82bc119cd0>
2023-02-23 15:20:34,065 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.subiquity.DebconfSelectionsModel object at 0x7f82bc1b5bb0>
2023-02-23 15:20:34,065 DEBUG subiquity.models.subiquity:436 merging config from <subiquity.models.mirror.MirrorModel object at 0x7f82bc1b5d90>
2023-02-23 15:20:34,092 DEBUG subiquitycore.utils:115 astart_command called: ['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2720', '--setenv', 'PATH=/snap/subiquity/4380/bin:/snap/subiquity/4380/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4380/bin:/snap/subiquity/4380/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4380/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4380/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4380', '--', '/snap/subiquity/4380/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.2720.7"}}', '-c', '/var/log/installer/curtin-install/subiquity-curthooks.conf', 'install', 'cp:///tmp/tmp1ordx03c/mount', '--set', 'json:stages=["curthooks"]']
2023-02-23 15:20:34,973 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install: curtin command install
2023-02-23 15:20:34,973 DEBUG root:37 start: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks: configuring installed system
2023-02-23 15:20:34,973 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'
2023-02-23 15:20:34,974 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'
2023-02-23 15:20:34,974 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'
2023-02-23 15:20:35,225 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
2023-02-23 15:20:35,636 ERROR root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/002-setupcon-save-only/cmd-in-target: FAIL: curtin command in-target
2023-02-23 15:20:35,636 ERROR root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks/002-setupcon-save-only: FAIL: running 'curtin in-target -- setupcon --save-only'
2023-02-23 15:20:35,637 ERROR root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step/cmd-install/stage-curthooks: FAIL: configuring installed system
2023-02-23 15:20:36,316 ERROR root:37 finish: subiquity/Install/install/curtin_install/run_curtin_install_step: FAIL: Command '['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2720', '--setenv', 'PATH=/snap/subiquity/4380/bin:/snap/subiquity/4380/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4380/bin:/snap/subiquity/4380/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4380/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4380/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4380', '--', '/snap/subiquity/4380/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.2720.7"}}', '-c', '/var/log/installer/curtin-install/subiquity-curthooks.conf', 'install', 'cp:///tmp/tmp1ordx03c/mount', '--set', 'json:stages=["curthooks"]']' returned non-zero exit status 3.
2023-02-23 15:20:36,316 ERROR root:37 finish: subiquity/Install/install/curtin_install: FAIL: Command '['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2720', '--setenv', 'PATH=/snap/subiquity/4380/bin:/snap/subiquity/4380/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4380/bin:/snap/subiquity/4380/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4380/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4380/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4380', '--', '/snap/subiquity/4380/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.2720.7"}}', '-c', '/var/log/installer/curtin-install/subiquity-curthooks.conf', 'install', 'cp:///tmp/tmp1ordx03c/mount', '--set', 'json:stages=["curthooks"]']' returned non-zero exit status 3.
2023-02-23 15:20:36,317 DEBUG subiquity.common.errorreport:384 generating crash report
2023-02-23 15:20:36,320 INFO subiquity.common.errorreport:406 saving crash report 'install failed crashed with CalledProcessError' to /var/crash/1677165636.317376614.install_fail.crash
2023-02-23 15:20:36,321 ERROR root:37 finish: subiquity/Install/install: FAIL: Command '['systemd-run', '--wait', '--same-dir', '--property', 'SyslogIdentifier=subiquity_log.2720', '--setenv', 'PATH=/snap/subiquity/4380/bin:/snap/subiquity/4380/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/snap/subiquity/4380/bin:/snap/subiquity/4380/sbin', '--setenv', 'PYTHONPATH=:/snap/subiquity/4380/lib/python3.8/site-packages', '--setenv', 'PYTHON=/snap/subiquity/4380/usr/bin/python3.8', '--setenv', 'SNAP=/snap/subiquity/4380', '--', '/snap/subiquity/4380/usr/bin/python3.8', '-m', 'curtin', '--showtrace', '-vvv', '--set', 'json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.2720.7"}}', '-c', '/var/log/installer/curtin-install/subiquity-curthooks.conf', 'install', 'cp:///tmp/tmp1ordx03c/mount', '--set', 'json:stages=["curthooks"]']' returned non-zero exit status 3.
2023-02-23 15:20:36,321 INFO root:37 start: subiquity/ErrorReporter/1677165636.317376614.install_fail/add_info: