2021-01-20 11:24:01,245 INFO subiquity:135 Starting Subiquity revision 1966
2021-01-20 11:24:01,245 INFO subiquity:136 Arguments passed: ['/snap/subiquity/1966/usr/bin/subiquity']
2021-01-20 11:24:01,245 DEBUG subiquitycore.utils:48 run_command called: ['cloud-init', 'status', '--wait']
2021-01-20 11:24:04,014 DEBUG subiquitycore.utils:61 run_command ['cloud-init', 'status', '--wait'] exited with code 0
2021-01-20 11:24:04,015 DEBUG subiquity:141 waited 2.7694287300109863s for cloud-init
2021-01-20 11:24:04,017 DEBUG subiquity:143 loading cloud config
2021-01-20 11:24:04,017 DEBUG cloudinit.util:1419 Reading from /etc/cloud/cloud.cfg (quiet=False)
2021-01-20 11:24:04,018 DEBUG cloudinit.util:1430 Read 4017 bytes from /etc/cloud/cloud.cfg
2021-01-20 11:24:04,018 DEBUG cloudinit.util:942 Attempting to load yaml from string of length 4017 with allowed root types (<class 'dict'>,)
2021-01-20 11:24:04,047 DEBUG cloudinit.util:1419 Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2021-01-20 11:24:04,048 DEBUG cloudinit.util:1430 Read 285 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2021-01-20 11:24:04,048 DEBUG cloudinit.util:942 Attempting to load yaml from string of length 285 with allowed root types (<class 'dict'>,)
2021-01-20 11:24:04,052 DEBUG cloudinit.util:1419 Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2021-01-20 11:24:04,052 DEBUG cloudinit.util:1430 Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2021-01-20 11:24:04,052 DEBUG cloudinit.util:942 Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2021-01-20 11:24:04,064 DEBUG cloudinit.util:1419 Reading from /run/cloud-init/cloud.cfg (quiet=False)
2021-01-20 11:24:04,064 DEBUG cloudinit.util:1430 Read 35 bytes from /run/cloud-init/cloud.cfg
2021-01-20 11:24:04,064 DEBUG cloudinit.util:942 Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2021-01-20 11:24:04,065 DEBUG cloudinit.util:2091 Running command ['systemd-detect-virt', '--quiet', '--container'] with allowed return codes [0] (shell=False, capture=True)
2021-01-20 11:24:04,077 DEBUG cloudinit.util:2091 Running command ['running-in-container'] with allowed return codes [0] (shell=False, capture=True)
2021-01-20 11:24:04,080 DEBUG cloudinit.util:2091 Running command ['lxc-is-container'] with allowed return codes [0] (shell=False, capture=True)
2021-01-20 11:24:04,084 DEBUG cloudinit.util:1419 Reading from /proc/1/environ (quiet=False)
2021-01-20 11:24:04,084 DEBUG cloudinit.util:1430 Read 239 bytes from /proc/1/environ
2021-01-20 11:24:04,085 DEBUG cloudinit.util:1419 Reading from /proc/self/status (quiet=False)
2021-01-20 11:24:04,085 DEBUG cloudinit.util:1430 Read 1303 bytes from /proc/self/status
2021-01-20 11:24:04,085 DEBUG cloudinit.util:1419 Reading from /proc/cmdline (quiet=False)
2021-01-20 11:24:04,085 DEBUG cloudinit.util:1430 Read 33 bytes from /proc/cmdline
2021-01-20 11:24:04,085 DEBUG cloudinit.util:942 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2021-01-20 11:24:04,086 DEBUG cloudinit.util:945 loaded blob returned None, returning default.
2021-01-20 11:24:04,087 DEBUG cloudinit.util:1419 Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2021-01-20 11:24:04,087 DEBUG cloudinit.util:1430 Read 0 bytes from /var/lib/cloud/instance/cloud-config.txt
2021-01-20 11:24:04,087 DEBUG cloudinit.util:942 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2021-01-20 11:24:04,087 DEBUG cloudinit.util:945 loaded blob returned None, returning default.
2021-01-20 11:24:04,088 DEBUG cloudinit.util:1419 Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
2021-01-20 11:24:04,089 DEBUG cloudinit.util:1430 Read 7245 bytes from /var/lib/cloud/instance/obj.pkl
2021-01-20 11:24:04,103 DEBUG cloudinit.util:1419 Reading from /run/cloud-init/.instance-id (quiet=False)
2021-01-20 11:24:04,104 DEBUG cloudinit.util:1430 Read 8 bytes from /run/cloud-init/.instance-id
2021-01-20 11:24:04,104 DEBUG cloudinit.stages:248 restored from cache with run check: DataSourceNoCloud [seed=/var/lib/cloud/seed/nocloud][dsmode=net]
2021-01-20 11:24:04,104 DEBUG cloudinit.util:1419 Reading from /etc/cloud/cloud.cfg (quiet=False)
2021-01-20 11:24:04,104 DEBUG cloudinit.util:1430 Read 4017 bytes from /etc/cloud/cloud.cfg
2021-01-20 11:24:04,105 DEBUG cloudinit.util:942 Attempting to load yaml from string of length 4017 with allowed root types (<class 'dict'>,)
2021-01-20 11:24:04,132 DEBUG cloudinit.util:1419 Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2021-01-20 11:24:04,132 DEBUG cloudinit.util:1430 Read 285 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2021-01-20 11:24:04,133 DEBUG cloudinit.util:942 Attempting to load yaml from string of length 285 with allowed root types (<class 'dict'>,)
2021-01-20 11:24:04,136 DEBUG cloudinit.util:1419 Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2021-01-20 11:24:04,137 DEBUG cloudinit.util:1430 Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2021-01-20 11:24:04,137 DEBUG cloudinit.util:942 Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2021-01-20 11:24:04,143 DEBUG cloudinit.util:1419 Reading from /run/cloud-init/cloud.cfg (quiet=False)
2021-01-20 11:24:04,144 DEBUG cloudinit.util:1430 Read 35 bytes from /run/cloud-init/cloud.cfg
2021-01-20 11:24:04,144 DEBUG cloudinit.util:942 Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2021-01-20 11:24:04,145 DEBUG cloudinit.util:942 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2021-01-20 11:24:04,145 DEBUG cloudinit.util:945 loaded blob returned None, returning default.
2021-01-20 11:24:04,145 DEBUG cloudinit.util:1419 Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2021-01-20 11:24:04,146 DEBUG cloudinit.util:1430 Read 0 bytes from /var/lib/cloud/instance/cloud-config.txt
2021-01-20 11:24:04,146 DEBUG cloudinit.util:942 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2021-01-20 11:24:04,146 DEBUG cloudinit.util:945 loaded blob returned None, returning default.
2021-01-20 11:24:04,148 DEBUG cloudinit.stages:83 Using distro class <class 'cloudinit.distros.ubuntu.Distro'>
2021-01-20 11:24:04,170 DEBUG subiquitycore.prober:35 Prober() init finished, data:None
2021-01-20 11:24:04,171 DEBUG subiquitycore.core:99 KDGKBTYPE returned b'\x02', is_linux_tty True
2021-01-20 11:24:04,172 DEBUG asyncio:54 Using selector: EpollSelector
2021-01-20 11:24:04,174 DEBUG subiquity.signals:50 connect_signal: network-proxy-set -> <function Subiquity.__init__.<locals>.<lambda> at 0x7f6427d0ed08>
2021-01-20 11:24:04,175 DEBUG subiquity.signals:50 connect_signal: network-change -> Subiquity._network_change
2021-01-20 11:24:04,175 DEBUG subiquitycore.core:643 Application.run
2021-01-20 11:24:04,181 DEBUG curtin:89 Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (capture=True)
2021-01-20 11:24:04,188 DEBUG subiquitycore.core:262 Importing controller: Early
2021-01-20 11:24:04,188 DEBUG subiquitycore.core:262 Importing controller: Reporting
2021-01-20 11:24:04,189 DEBUG subiquitycore.core:262 Importing controller: Error
2021-01-20 11:24:04,189 DEBUG subiquitycore.core:262 Importing controller: Userdata
2021-01-20 11:24:04,189 DEBUG subiquitycore.core:262 Importing controller: Package
2021-01-20 11:24:04,189 DEBUG subiquitycore.core:262 Importing controller: Debconf
2021-01-20 11:24:04,190 DEBUG subiquitycore.core:262 Importing controller: Welcome
2021-01-20 11:24:04,190 DEBUG subiquitycore.core:262 Importing controller: Refresh
2021-01-20 11:24:04,190 DEBUG subiquitycore.core:262 Importing controller: Keyboard
2021-01-20 11:24:04,190 DEBUG subiquitycore.core:262 Importing controller: Network
2021-01-20 11:24:04,197 DEBUG subiquitycore.netplan:111 config for zz-all-en = {'dhcp4': True, 'match': {'name': 'en*'}}
2021-01-20 11:24:04,197 DEBUG subiquitycore.netplan:111 config for zz-all-eth = {'dhcp4': True, 'match': {'name': 'eth*'}}
2021-01-20 11:24:04,197 DEBUG subiquitycore.core:262 Importing controller: Proxy
2021-01-20 11:24:04,197 DEBUG subiquitycore.core:262 Importing controller: Mirror
2021-01-20 11:24:04,197 DEBUG subiquitycore.core:262 Importing controller: Refresh
2021-01-20 11:24:04,198 DEBUG subiquitycore.core:262 Importing controller: Filesystem
2021-01-20 11:24:04,199 DEBUG subiquitycore.core:262 Importing controller: Identity
2021-01-20 11:24:04,199 DEBUG subiquitycore.core:262 Importing controller: SSH
2021-01-20 11:24:04,199 DEBUG subiquitycore.core:262 Importing controller: SnapList
2021-01-20 11:24:04,199 DEBUG subiquitycore.core:262 Importing controller: InstallProgress
2021-01-20 11:24:04,203 DEBUG subiquitycore.core:262 Importing controller: Late
2021-01-20 11:24:04,203 DEBUG subiquitycore.core:262 Importing controller: Reboot
2021-01-20 11:24:04,204 DEBUG subiquity.signals:50 connect_signal: snapd-network-change -> RefreshController.snapd_network_changed
2021-01-20 11:24:04,204 DEBUG subiquity.signals:50 connect_signal: l10n:language-selected -> KeyboardController.language_selected
2021-01-20 11:24:04,204 DEBUG subiquity.signals:50 connect_signal: snapd-network-change -> MirrorController.snapd_network_changed
2021-01-20 11:24:04,204 DEBUG subiquity.signals:50 connect_signal: snapd-network-change -> SnapListController.snapd_network_changed
2021-01-20 11:24:04,204 DEBUG subiquitycore.core:410 known signals: ['network-proxy-set', 'network-change', 'snapd-network-change', 'l10n:language-selected']
2021-01-20 11:24:04,204 DEBUG subiquitycore.core:574 starting controllers
2021-01-20 11:24:04,214 DEBUG probert.network:584 event for link_change: NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2021-01-20 11:24:04,215 DEBUG probert.network:584 event for link_change: NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'ens32'}
2021-01-20 11:24:04,215 DEBUG probert.network:584 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'}
2021-01-20 11:24:04,215 DEBUG probert.network:584 event for addr_change: NEW {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'10.0.1.171/24'}
2021-01-20 11:24:04,215 DEBUG probert.network:584 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2021-01-20 11:24:04,215 DEBUG probert.network:584 event for addr_change: NEW {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:24:04,216 DEBUG probert.network:584 event for addr_change: NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::20c:29ff:fec8:51f/64'}
2021-01-20 11:24:04,216 DEBUG probert.network:671 link_change NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2021-01-20 11:24:04,395 DEBUG subiquitycore.models.network:266 new_link 1 lo lo
2021-01-20 11:24:04,395 DEBUG probert.network:671 link_change NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'ens32'}
2021-01-20 11:24:04,569 DEBUG subiquitycore.models.network:266 new_link 2 ens32 eth
2021-01-20 11:24:04,570 DEBUG subiquitycore.models.network:294 new_link 2 ens32 with config {'dhcp4': True}
2021-01-20 11:24:04,570 DEBUG probert.network:716 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'}
2021-01-20 11:24:04,571 DEBUG probert.network:716 addr_change NEW {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'10.0.1.171/24'}
2021-01-20 11:24:04,571 DEBUG probert.network:716 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2021-01-20 11:24:04,571 DEBUG probert.network:716 addr_change NEW {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:24:04,571 DEBUG probert.network:716 addr_change NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::20c:29ff:fec8:51f/64'}
2021-01-20 11:24:04,572 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2021-01-20 11:24:04,572 DEBUG subiquity.controllers.snaplist:54 loading list of snaps
2021-01-20 11:24:04,573 DEBUG subiquitycore.controller.network:96 default routes {2}
2021-01-20 11:24:04,574 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'10.0.1.0/24', 'ifindex': 2}
2021-01-20 11:24:04,575 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'10.0.1.254', 'ifindex': 2}
2021-01-20 11:24:04,575 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'10.0.1.0', 'ifindex': 2}
2021-01-20 11:24:04,575 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'10.0.1.171', 'ifindex': 2}
2021-01-20 11:24:04,575 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'10.0.1.255', 'ifindex': 2}
2021-01-20 11:24:04,575 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'127.0.0.0', 'ifindex': 1}
2021-01-20 11:24:04,575 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.0/8', 'ifindex': 1}
2021-01-20 11:24:04,575 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.1', 'ifindex': 1}
2021-01-20 11:24:04,576 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'127.255.255.255', 'ifindex': 1}
2021-01-20 11:24:04,576 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'::1', 'ifindex': 1}
2021-01-20 11:24:04,576 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'2001:3c8:2105:a::/64', 'ifindex': 2}
2021-01-20 11:24:04,576 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'fe80::/64', 'ifindex': 2}
2021-01-20 11:24:04,576 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2021-01-20 11:24:04,576 DEBUG subiquity.controllers.snaplist:54 loading list of snaps
2021-01-20 11:24:04,577 DEBUG subiquitycore.controller.network:96 default routes {2}
2021-01-20 11:24:04,577 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'::1', 'ifindex': 1}
2021-01-20 11:24:04,577 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'2001:3c8:2105:a:20c:29ff:fec8:51f', 'ifindex': 2}
2021-01-20 11:24:04,577 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'fe80::20c:29ff:fec8:51f', 'ifindex': 2}
2021-01-20 11:24:04,577 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 1, 'table': 255, 'dst': b'ff00::/8', 'ifindex': 2}
2021-01-20 11:24:04,652 DEBUG subiquitycore.core:577 controllers started
2021-01-20 11:24:04,654 DEBUG subiquitycore.core:452 skipping screen Early
2021-01-20 11:24:04,654 DEBUG subiquitycore.core:452 skipping screen Reporting
2021-01-20 11:24:04,655 DEBUG subiquitycore.core:452 skipping screen Error
2021-01-20 11:24:04,655 DEBUG subiquity.models.subiquity:133 model userdata is configured
2021-01-20 11:24:04,655 DEBUG subiquitycore.core:452 skipping screen Userdata
2021-01-20 11:24:04,655 DEBUG subiquity.models.subiquity:133 model packages is configured
2021-01-20 11:24:04,655 DEBUG subiquitycore.core:452 skipping screen Package
2021-01-20 11:24:04,655 DEBUG subiquity.models.subiquity:133 model debconf_selections is configured
2021-01-20 11:24:04,655 DEBUG subiquitycore.core:452 skipping screen Debconf
2021-01-20 11:24:04,656 INFO root:39 start: subiquity/Welcome: starting UI
2021-01-20 11:24:04,657 DEBUG subiquity.views.welcome:80 _build_model_inputs selected_language=C
2021-01-20 11:24:04,657 DEBUG subiquity.views.welcome:84 ('ast', 'C')
2021-01-20 11:24:04,658 DEBUG subiquity.views.welcome:84 ('id', 'C')
2021-01-20 11:24:04,658 DEBUG subiquity.views.welcome:84 ('ca', 'C')
2021-01-20 11:24:04,659 DEBUG subiquity.views.welcome:84 ('de', 'C')
2021-01-20 11:24:04,659 DEBUG subiquity.views.welcome:84 ('en_US', 'C')
2021-01-20 11:24:04,659 DEBUG subiquity.views.welcome:84 ('en_GB', 'C')
2021-01-20 11:24:04,660 DEBUG subiquity.views.welcome:84 ('es', 'C')
2021-01-20 11:24:04,660 DEBUG subiquity.views.welcome:84 ('fr', 'C')
2021-01-20 11:24:04,661 DEBUG subiquity.views.welcome:84 ('hr', 'C')
2021-01-20 11:24:04,661 DEBUG subiquity.views.welcome:84 ('lv', 'C')
2021-01-20 11:24:04,661 DEBUG subiquity.views.welcome:84 ('lt', 'C')
2021-01-20 11:24:04,662 DEBUG subiquity.views.welcome:84 ('hu', 'C')
2021-01-20 11:24:04,662 DEBUG subiquity.views.welcome:84 ('nl', 'C')
2021-01-20 11:24:04,662 DEBUG subiquity.views.welcome:84 ('nb', 'C')
2021-01-20 11:24:04,663 DEBUG subiquity.views.welcome:84 ('pl', 'C')
2021-01-20 11:24:04,663 DEBUG subiquity.views.welcome:84 ('fi', 'C')
2021-01-20 11:24:04,663 DEBUG subiquity.views.welcome:84 ('sv', 'C')
2021-01-20 11:24:04,664 DEBUG subiquity.views.welcome:84 ('cs', 'C')
2021-01-20 11:24:04,664 DEBUG subiquity.views.welcome:84 ('el', 'C')
2021-01-20 11:24:04,664 DEBUG subiquity.views.welcome:84 ('be', 'C')
2021-01-20 11:24:04,665 DEBUG subiquity.views.welcome:84 ('ru', 'C')
2021-01-20 11:24:04,665 DEBUG subiquity.views.welcome:84 ('sr', 'C')
2021-01-20 11:24:04,665 DEBUG subiquity.views.welcome:84 ('uk', 'C')
2021-01-20 11:24:04,667 DEBUG root:39 start: subiquity/Refresh/configure_snapd: 
2021-01-20 11:24:04,668 DEBUG root:39 start: subiquity/Refresh/configure_snapd/get_details: 
2021-01-20 11:24:04,669 DEBUG root:39 start: subiquity/Refresh/check_for_update: 
2021-01-20 11:24:04,670 DEBUG root:39 start: subiquity/Refresh/check_for_update: 
2021-01-20 11:24:04,670 DEBUG root:39 start: subiquity/Mirror/lookup: 
2021-01-20 11:24:04,675 DEBUG root:39 start: subiquity/Refresh/check_for_update: 
2021-01-20 11:24:04,675 DEBUG root:39 start: subiquity/Mirror/lookup: 
2021-01-20 11:24:04,684 DEBUG root:39 start: subiquity/SnapList/loader: 
2021-01-20 11:24:04,688 DEBUG urllib3.connectionpool:826 Starting new HTTPS connection (1): geoip.ubuntu.com
2021-01-20 11:24:04,693 DEBUG urllib3.connectionpool:826 Starting new HTTPS connection (1): geoip.ubuntu.com
2021-01-20 11:24:04,719 DEBUG root:39 start: subiquity/InstallProgress/install: 
2021-01-20 11:24:04,720 ERROR root:39 finish: subiquity/Refresh/check_for_update: FAIL: cancelled
2021-01-20 11:24:04,721 ERROR root:39 finish: subiquity/Refresh/check_for_update: FAIL: cancelled
2021-01-20 11:24:04,721 ERROR root:39 finish: subiquity/Mirror/lookup: FAIL: cancelled
2021-01-20 11:24:04,721 DEBUG root:39 start: subiquity/SnapList/loader/list: 
2021-01-20 11:24:04,728 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/snaps/subiquity HTTP/1.1" 200 1079
2021-01-20 11:24:04,734 DEBUG root:39 start: subiquity/Filesystem/_probe: 
2021-01-20 11:24:04,735 DEBUG subiquity.lockfile:36 locking shared /run/subiquity/installing
2021-01-20 11:24:04,761 DEBUG root:39 finish: subiquity/Refresh/configure_snapd/get_details: SUCCESS: current version of snap is: '20.07.1+git2.5de9df3e'
2021-01-20 11:24:04,761 DEBUG root:39 start: subiquity/Refresh/configure_snapd/switching: switching subiquity to stable/ubuntu-20.04.1
2021-01-20 11:24:04,768 DEBUG root:39 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2021-01-20 11:24:04,778 DEBUG urllib3.connectionpool:396 http://localhost:None "POST /v2/snaps/subiquity HTTP/1.1" 202 81
2021-01-20 11:24:04,808 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/changes/4 HTTP/1.1" 200 595
2021-01-20 11:24:04,812 DEBUG root:39 finish: subiquity/Refresh/configure_snapd/switching: SUCCESS: switched to stable/ubuntu-20.04.1
2021-01-20 11:24:04,812 DEBUG root:39 finish: subiquity/Refresh/configure_snapd: SUCCESS: 
2021-01-20 11:24:05,053 DEBUG probert.multipath:49 Extracted multipath paths fields: ['sda', '', '[orphan]', '[undef]', '[undef]', '[undef]', '[undef]', '[undef]']
2021-01-20 11:24:05,365 DEBUG probert.dasd:116 Probing DASD devies
2021-01-20 11:24:05,366 DEBUG probert.dasd:119 DASD devices only present on s390x, arch=x86_64
2021-01-20 11:24:05,436 DEBUG curtin:1298 Extracting storage config from probe data
2021-01-20 11:24:05,490 DEBUG curtin:1305 Sorting extracted configurations
2021-01-20 11:24:05,490 INFO curtin:1324 Validating extracted storage config components
2021-01-20 11:24:05,530 DEBUG curtin:1343 Extracted (unmerged) storage config:
storage:
-   id: disk-sda
    path: /dev/sda
    type: disk

2021-01-20 11:24:05,530 DEBUG curtin:1345 Generating storage config dependencies
2021-01-20 11:24:05,530 DEBUG curtin:1351 Merging storage config dependencies
2021-01-20 11:24:05,531 DEBUG curtin:1358 Merged storage config:
storage:
    config:
    -   id: disk-sda
        path: /dev/sda
        type: disk
    version: 1

2021-01-20 11:24:05,532 DEBUG subiquity.models.filesystem:1530 exclusions set()
2021-01-20 11:24:05,532 DEBUG root:39 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False
2021-01-20 11:24:05,533 DEBUG subiquity.lockfile:44 unlocking shared /run/subiquity/installing
2021-01-20 11:24:05,533 DEBUG root:39 finish: subiquity/Filesystem/_probe: SUCCESS: 
2021-01-20 11:24:05,664 DEBUG urllib3.connectionpool:396 https://geoip.ubuntu.com:443 "GET /lookup HTTP/1.1" 200 None
2021-01-20 11:24:05,672 DEBUG urllib3.connectionpool:396 https://geoip.ubuntu.com:443 "GET /lookup HTTP/1.1" 200 None
2021-01-20 11:24:05,676 DEBUG root:39 finish: subiquity/Mirror/lookup: SUCCESS: 
2021-01-20 11:24:06,270 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?section=server HTTP/1.1" 200 None
2021-01-20 11:24:06,278 DEBUG root:39 finish: subiquity/SnapList/loader/list: SUCCESS: 
2021-01-20 11:24:06,279 DEBUG subiquity.controllers.snaplist:62 fetched list of 24 snaps
2021-01-20 11:24:06,281 DEBUG root:39 start: subiquity/SnapList/loader/fetch/microk8s: 
2021-01-20 11:24:06,632 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?select=refresh HTTP/1.1" 200 None
2021-01-20 11:24:06,634 DEBUG subiquity.controllers.refresh:200 check_for_update received {'type': 'sync', 'status-code': 200, 'status': 'OK', 'result': [{'id': 'CSO04Jhav2yK0uz97cr0ipQRyqg0qQL6', 'title': 'Core 18', 'summary': 'Runtime environment based on Ubuntu 18.04', 'description': 'The base snap based on the Ubuntu 18.04 release.', 'download-size': 58073088, 'name': 'core18', 'publisher': {'id': 'canonical', 'username': 'canonical', 'display-name': 'Canonical', 'validation': 'verified'}, 'developer': 'canonical', 'status': 'available', 'type': 'base', 'version': '20201210', 'channel': 'latest/stable', 'ignore-validation': False, 'revision': '1944', 'confinement': 'strict', 'private': False, 'devmode': False, 'jailmode': False, 'contact': '', 'license': 'Other Open Source'}, {'id': 'PMrrV4ml8uWuEUDBT8dSGnKUYbevVhc4', 'title': 'snapd', 'summary': 'Background service that manages and maintains installed snaps', 'description': "**Note: you do not need to install _snapd_ manually if you already have _snap_ installed.**\n\nSnaps are app packages for desktop, cloud and IoT that update automatically, are easy to install, secure, cross-platform and dependency-free. They're being used on millions of Linux systems every day.\n\nAlongside its various service and management functions, snapd:\n- provides the _snap_ command that's used to install and remove snaps and interact with the wider snap ecosystem\n- implements the confinement policies that isolate snaps from the base system and from each other\n- governs the interfaces that allow snaps to access specific system resources outside of their confinement\n\nFor general details, including _installation_ and _Getting started_  guides, head over to our _Snap documentation_: https://snapcraft.io/docs\n\nIf you want to build your own snaps, start with our _Creating a snap_ documentation: https://snapcraft.io/docs/creating-a-snap\n\n**Get involved**\n\nThis is an _open source_ project and we warmly welcome community contributions, suggestions, and constructive feedback. If you're interested in contributing, please take a look at our _Code of Conduct_ first.\n\n- to report an issue, please file _a bug report_ (https://bugs.launchpad.net/snappy/+filebug) on our _Launchpad issue tracker_ (https://bugs.launchpad.net/snappy/)\n- for suggestions and constructive feedback, create a post on the _Snapcraft forum_ (https://forum.snapcraft.io/c/snapd)\n- to build snapd manually, or to get started with snapd development, see  _HACKING.md (https://raw.githubusercontent.com/snapcore/snapd/master/HACKING.md)\n\n**Get in touch**\n\nWe're friendly! We have a community forum at https://forum.snapcraft.io where we discuss feature plans, development news, issues, updates and troubleshooting. You can chat in realtime with the snapd team and our wider community on the _#snappy_ (https://webchat.freenode.net/?channels=snappy) IRC channel on _freenode_ (https://freenode.net/).\n\nFor news and updates, follow us on _Twitter_ (https://twitter.com/snapcraftio) and on _Facebook_ (https://www.facebook.com/snapcraftio).\n\nThe snapd source code can be found on GitHub: https://github.com/snapcore/snapd", 'download-size': 32600064, 'icon': 'https://dashboard.snapcraft.io/site_media/appmedia/2019/09/snapd.png', 'name': 'snapd', 'publisher': {'id': 'canonical', 'username': 'canonical', 'display-name': 'Canonical', 'validation': 'verified'}, 'developer': 'canonical', 'status': 'available', 'type': 'snapd', 'version': '2.48.2', 'channel': 'latest/stable', 'ignore-validation': False, 'revision': '10707', 'confinement': 'strict', 'private': False, 'devmode': False, 'jailmode': False, 'contact': '', 'license': 'GPL-3.0+', 'website': 'https://snapcraft.io', 'media': [{'type': 'icon', 'url': 'https://dashboard.snapcraft.io/site_media/appmedia/2019/09/snapd.png', 'width': 460, 'height': 460}, {'type': 'screenshot', 'url': 'https://dashboard.snapcraft.io/site_media/appmedia/2019/09/Screenshot_20190924_115756_hLcyetO.png', 'width': 956, 'height': 648}, {'type': 'screenshot', 'url': 'https://dashboard.snapcraft.io/site_media/appmedia/2019/09/Screenshot_20190924_115824_2v3y6l8.png', 'width': 956, 'height': 648}, {'type': 'screenshot', 'url': 'https://dashboard.snapcraft.io/site_media/appmedia/2019/09/Screenshot_20190924_115055_Uuq7KIb.png', 'width': 1023, 'height': 834}, {'type': 'screenshot', 'url': 'https://dashboard.snapcraft.io/site_media/appmedia/2019/09/Screenshot_20190924_125944.png', 'width': 956, 'height': 648}]}, {'id': 'ba2aj8guta0zSRlT3QM5aJNAUXPlBtf9', 'title': 'subiquity', 'summary': 'Ubuntu installer', 'description': 'The Ubuntu server installer', 'download-size': 53510144, 'name': 'subiquity', 'publisher': {'id': 'canonical', 'username': 'canonical', 'display-name': 'Canonical', 'validation': 'verified'}, 'developer': 'canonical', 'status': 'available', 'type': 'app', 'base': 'core18', 'version': '20.09.1+git1.67496d12', 'channel': 'latest/stable', 'ignore-validation': False, 'revision': '2099', 'confinement': 'classic', 'private': False, 'devmode': False, 'jailmode': False, 'contact': 'https://bugs.launchpad.net/subiquity', 'license': 'AGPL-3.0'}]}
2021-01-20 11:24:06,635 DEBUG root:39 finish: subiquity/Refresh/check_for_update: SUCCESS: new version of snap available: '20.09.1+git1.67496d12'
2021-01-20 11:24:07,164 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=microk8s HTTP/1.1" 200 None
2021-01-20 11:24:07,196 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/microk8s: SUCCESS: 
2021-01-20 11:24:07,197 DEBUG root:39 start: subiquity/SnapList/loader/fetch/nextcloud: 
2021-01-20 11:24:07,609 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=nextcloud HTTP/1.1" 200 None
2021-01-20 11:24:07,612 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/nextcloud: SUCCESS: 
2021-01-20 11:24:07,613 DEBUG root:39 start: subiquity/SnapList/loader/fetch/wekan: 
2021-01-20 11:24:07,985 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=wekan HTTP/1.1" 200 None
2021-01-20 11:24:07,986 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/wekan: SUCCESS: 
2021-01-20 11:24:07,987 DEBUG root:39 start: subiquity/SnapList/loader/fetch/kata-containers: 
2021-01-20 11:24:08,309 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=kata-containers HTTP/1.1" 200 None
2021-01-20 11:24:08,311 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/kata-containers: SUCCESS: 
2021-01-20 11:24:08,312 DEBUG root:39 start: subiquity/SnapList/loader/fetch/docker: 
2021-01-20 11:24:08,610 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=docker HTTP/1.1" 200 None
2021-01-20 11:24:08,612 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/docker: SUCCESS: 
2021-01-20 11:24:08,613 DEBUG root:39 start: subiquity/SnapList/loader/fetch/canonical-livepatch: 
2021-01-20 11:24:08,909 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=canonical-livepatch HTTP/1.1" 200 1462
2021-01-20 11:24:08,911 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/canonical-livepatch: SUCCESS: 
2021-01-20 11:24:08,911 DEBUG root:39 start: subiquity/SnapList/loader/fetch/rocketchat-server: 
2021-01-20 11:24:09,846 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=rocketchat-server HTTP/1.1" 200 None
2021-01-20 11:24:09,849 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/rocketchat-server: SUCCESS: 
2021-01-20 11:24:09,850 DEBUG root:39 start: subiquity/SnapList/loader/fetch/mosquitto: 
2021-01-20 11:24:10,176 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=mosquitto HTTP/1.1" 200 None
2021-01-20 11:24:10,178 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/mosquitto: SUCCESS: 
2021-01-20 11:24:10,179 DEBUG root:39 start: subiquity/SnapList/loader/fetch/etcd: 
2021-01-20 11:24:10,508 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=etcd HTTP/1.1" 200 None
2021-01-20 11:24:10,512 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/etcd: SUCCESS: 
2021-01-20 11:24:10,513 DEBUG root:39 start: subiquity/SnapList/loader/fetch/powershell: 
2021-01-20 11:24:10,826 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=powershell HTTP/1.1" 200 None
2021-01-20 11:24:10,828 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/powershell: SUCCESS: 
2021-01-20 11:24:10,829 DEBUG root:39 start: subiquity/SnapList/loader/fetch/stress-ng: 
2021-01-20 11:24:11,271 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=stress-ng HTTP/1.1" 200 None
2021-01-20 11:24:11,273 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/stress-ng: SUCCESS: 
2021-01-20 11:24:11,274 DEBUG root:39 start: subiquity/SnapList/loader/fetch/sabnzbd: 
2021-01-20 11:24:11,628 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=sabnzbd HTTP/1.1" 200 None
2021-01-20 11:24:11,630 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/sabnzbd: SUCCESS: 
2021-01-20 11:24:11,631 DEBUG root:39 start: subiquity/SnapList/loader/fetch/wormhole: 
2021-01-20 11:24:11,934 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=wormhole HTTP/1.1" 200 None
2021-01-20 11:24:11,936 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/wormhole: SUCCESS: 
2021-01-20 11:24:11,936 DEBUG root:39 start: subiquity/SnapList/loader/fetch/aws-cli: 
2021-01-20 11:24:12,289 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=aws-cli HTTP/1.1" 200 1873
2021-01-20 11:24:12,290 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/aws-cli: SUCCESS: 
2021-01-20 11:24:12,291 DEBUG root:39 start: subiquity/SnapList/loader/fetch/google-cloud-sdk: 
2021-01-20 11:24:13,198 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=google-cloud-sdk HTTP/1.1" 200 1735
2021-01-20 11:24:13,200 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/google-cloud-sdk: SUCCESS: 
2021-01-20 11:24:13,201 DEBUG root:39 start: subiquity/SnapList/loader/fetch/slcli: 
2021-01-20 11:24:13,516 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=slcli HTTP/1.1" 200 1883
2021-01-20 11:24:13,518 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/slcli: SUCCESS: 
2021-01-20 11:24:13,519 DEBUG root:39 start: subiquity/SnapList/loader/fetch/doctl: 
2021-01-20 11:24:13,863 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=doctl HTTP/1.1" 200 1941
2021-01-20 11:24:13,864 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/doctl: SUCCESS: 
2021-01-20 11:24:13,865 DEBUG root:39 start: subiquity/SnapList/loader/fetch/conjure-up: 
2021-01-20 11:24:14,179 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=conjure-up HTTP/1.1" 200 None
2021-01-20 11:24:14,180 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/conjure-up: SUCCESS: 
2021-01-20 11:24:14,181 DEBUG root:39 start: subiquity/SnapList/loader/fetch/minidlna-escoand: 
2021-01-20 11:24:15,073 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=minidlna-escoand HTTP/1.1" 200 1992
2021-01-20 11:24:15,075 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/minidlna-escoand: SUCCESS: 
2021-01-20 11:24:15,076 DEBUG root:39 start: subiquity/SnapList/loader/fetch/postgresql10: 
2021-01-20 11:24:15,371 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=postgresql10 HTTP/1.1" 200 1450
2021-01-20 11:24:15,372 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/postgresql10: SUCCESS: 
2021-01-20 11:24:15,373 DEBUG root:39 start: subiquity/SnapList/loader/fetch/heroku: 
2021-01-20 11:24:16,303 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=heroku HTTP/1.1" 200 None
2021-01-20 11:24:16,305 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/heroku: SUCCESS: 
2021-01-20 11:24:16,306 DEBUG root:39 start: subiquity/SnapList/loader/fetch/keepalived: 
2021-01-20 11:24:16,642 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=keepalived HTTP/1.1" 200 None
2021-01-20 11:24:16,644 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/keepalived: SUCCESS: 
2021-01-20 11:24:16,645 DEBUG root:39 start: subiquity/SnapList/loader/fetch/prometheus: 
2021-01-20 11:24:17,004 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=prometheus HTTP/1.1" 200 None
2021-01-20 11:24:17,006 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/prometheus: SUCCESS: 
2021-01-20 11:24:17,007 DEBUG root:39 start: subiquity/SnapList/loader/fetch/juju: 
2021-01-20 11:24:18,003 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=juju HTTP/1.1" 200 None
2021-01-20 11:24:18,007 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/juju: SUCCESS: 
2021-01-20 11:24:18,008 DEBUG root:39 finish: subiquity/SnapList/loader: SUCCESS: 
2021-01-20 11:26:12,681 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-01-20 11:26:12,711 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-01-20 11:26:12,712 DEBUG probert.network:584 event for addr_change: CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:26:12,712 DEBUG probert.network:716 addr_change CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:27:07,364 DEBUG subiquity.views.welcome:142 WelcomeView en_US
2021-01-20 11:27:07,365 DEBUG subiquity.controllers.welcome:56 WelcomeController.done en_US next_screen
2021-01-20 11:27:07,365 DEBUG subiquity.controllers.keyboard:56 language_selected en_US
2021-01-20 11:27:07,616 DEBUG subiquity.controllers.keyboard:61 loading launguage C
2021-01-20 11:27:07,681 DEBUG subiquity.models.subiquity:133 model locale is configured
2021-01-20 11:27:07,682 INFO root:39 finish: subiquity/Welcome: SUCCESS: completed
2021-01-20 11:27:07,682 INFO root:39 start: subiquity/Refresh: starting UI
2021-01-20 11:27:13,814 DEBUG subiquity.controllers.refresh:247 RefreshController.done next_screen
2021-01-20 11:27:13,815 INFO root:39 finish: subiquity/Refresh: SUCCESS: completed
2021-01-20 11:27:13,816 INFO root:39 start: subiquity/Keyboard: starting UI
2021-01-20 11:27:15,673 DEBUG subiquity.controllers.keyboard:76 KeyboardController next_screen
2021-01-20 11:27:15,673 DEBUG subiquity.models.subiquity:133 model keyboard is configured
2021-01-20 11:27:15,674 INFO root:39 finish: subiquity/Keyboard: SUCCESS: completed
2021-01-20 11:27:15,675 INFO root:39 start: subiquity/Network: starting UI
2021-01-20 11:27:15,675 DEBUG subiquitycore.controller.network:284 updating initial NIC config
2021-01-20 11:27:15,685 DEBUG subiquitycore.views.network:149 view route_watcher {2}
2021-01-20 11:27:15,687 INFO root:39 start: subiquity/Network/apply_config: silent=True
2021-01-20 11:27:15,691 DEBUG subiquitycore.controller.network:348 network config: 
network:
  ethernets:
    ens32:
      dhcp4: true
  version: 2

2021-01-20 11:27:15,700 DEBUG subiquitycore.netplan:111 config for ens32 = {'dhcp4': True}
2021-01-20 11:27:15,700 DEBUG subiquitycore.utils:74 arun_command called: ['netplan', 'apply']
2021-01-20 11:27:16,200 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-01-20 11:27:16,231 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-01-20 11:27:16,232 DEBUG probert.network:584 event for addr_change: DEL {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'10.0.1.171/24'}
2021-01-20 11:27:16,232 DEBUG probert.network:730 route_change DEL {'family': 2, 'type': 1, 'table': 254, 'dst': b'10.0.1.254', 'ifindex': 2}
2021-01-20 11:27:16,232 DEBUG probert.network:730 route_change DEL {'family': 2, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2021-01-20 11:27:16,233 DEBUG subiquitycore.views.network:149 view route_watcher set()
2021-01-20 11:27:16,238 DEBUG subiquitycore.controller.network:96 default routes set()
2021-01-20 11:27:16,238 DEBUG probert.network:716 addr_change DEL {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'10.0.1.171/24'}
2021-01-20 11:27:16,238 DEBUG subiquitycore.views.network:265 update_link ens32 2 True
2021-01-20 11:27:16,240 DEBUG probert.network:730 route_change DEL {'family': 2, 'type': 1, 'table': 254, 'dst': b'10.0.1.0/24', 'ifindex': 2}
2021-01-20 11:27:16,240 DEBUG probert.network:730 route_change DEL {'family': 2, 'type': 3, 'table': 255, 'dst': b'10.0.1.255', 'ifindex': 2}
2021-01-20 11:27:16,240 DEBUG probert.network:730 route_change DEL {'family': 2, 'type': 3, 'table': 255, 'dst': b'10.0.1.0', 'ifindex': 2}
2021-01-20 11:27:16,240 DEBUG probert.network:730 route_change DEL {'family': 2, 'type': 2, 'table': 255, 'dst': b'10.0.1.171', 'ifindex': 2}
2021-01-20 11:27:16,492 DEBUG subiquitycore.utils:83 arun_command ['netplan', 'apply'] exited with code 0
2021-01-20 11:27:16,535 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-01-20 11:27:16,578 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-01-20 11:27:16,579 DEBUG probert.network:584 event for link_change: CHANGE {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'ens32'}
2021-01-20 11:27:16,579 DEBUG probert.network:584 event for addr_change: DEL {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:27:16,580 DEBUG probert.network:584 event for addr_change: NEW {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'10.0.1.171/24'}
2021-01-20 11:27:16,580 DEBUG probert.network:671 link_change CHANGE {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'ens32'}
2021-01-20 11:27:16,581 DEBUG subiquitycore.views.network:265 update_link ens32 2 True
2021-01-20 11:27:16,582 DEBUG probert.network:716 addr_change DEL {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:27:16,583 DEBUG subiquitycore.views.network:265 update_link ens32 2 True
2021-01-20 11:27:16,583 DEBUG probert.network:730 route_change DEL {'family': 10, 'type': 2, 'table': 255, 'dst': b'2001:3c8:2105:a:20c:29ff:fec8:51f', 'ifindex': 2}
2021-01-20 11:27:16,583 DEBUG probert.network:730 route_change DEL {'family': 10, 'type': 1, 'table': 254, 'dst': b'2001:3c8:2105:a::/64', 'ifindex': 2}
2021-01-20 11:27:16,584 DEBUG probert.network:730 route_change DEL {'family': 10, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2021-01-20 11:27:16,584 DEBUG subiquitycore.views.network:149 view route_watcher set()
2021-01-20 11:27:16,584 DEBUG subiquitycore.controller.network:96 default routes set()
2021-01-20 11:27:16,584 DEBUG probert.network:716 addr_change NEW {'ifindex': 2, 'flags': 0, 'family': 2, 'scope': 0, 'local': b'10.0.1.171/24'}
2021-01-20 11:27:16,585 DEBUG subiquitycore.views.network:265 update_link ens32 2 True
2021-01-20 11:27:16,585 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'10.0.1.171', 'ifindex': 2}
2021-01-20 11:27:16,586 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'10.0.1.255', 'ifindex': 2}
2021-01-20 11:27:16,586 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'10.0.1.0/24', 'ifindex': 2}
2021-01-20 11:27:16,586 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'10.0.1.0', 'ifindex': 2}
2021-01-20 11:27:16,586 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'10.0.1.254', 'ifindex': 2}
2021-01-20 11:27:16,586 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2021-01-20 11:27:16,586 DEBUG subiquitycore.views.network:149 view route_watcher {2}
2021-01-20 11:27:16,587 DEBUG subiquitycore.controller.network:96 default routes {2}
2021-01-20 11:27:16,600 INFO root:39 finish: subiquity/Network/apply_config: SUCCESS: silent=True
2021-01-20 11:27:17,897 DEBUG subiquity.models.subiquity:133 model network is configured
2021-01-20 11:27:17,898 DEBUG subiquitycore.controller.network:211 NetworkController.done next_screen
2021-01-20 11:27:17,899 INFO root:39 finish: subiquity/Network: SUCCESS: completed
2021-01-20 11:27:17,899 INFO root:39 start: subiquity/Proxy: starting UI
2021-01-20 11:27:17,974 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-01-20 11:27:18,003 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-01-20 11:27:18,004 DEBUG probert.network:584 event for addr_change: NEW {'ifindex': 2, 'flags': 832, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:27:18,005 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2021-01-20 11:27:18,005 DEBUG subiquitycore.controller.network:96 default routes {2}
2021-01-20 11:27:18,006 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'2001:3c8:2105:a::/64', 'ifindex': 2}
2021-01-20 11:27:18,006 DEBUG probert.network:716 addr_change NEW {'ifindex': 2, 'flags': 832, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:27:19,184 DEBUG subiquity.ui.views.proxy:64 User input: {'url': ''}
2021-01-20 11:27:19,184 DEBUG subiquity.controllers.proxy:66 ProxyController.done next_screen proxy=
2021-01-20 11:27:19,184 DEBUG subiquity.models.subiquity:133 model proxy is configured
2021-01-20 11:27:19,186 INFO root:39 finish: subiquity/Proxy: SUCCESS: completed
2021-01-20 11:27:19,186 INFO root:39 start: subiquity/Mirror: starting UI
2021-01-20 11:27:19,799 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-01-20 11:27:19,839 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-01-20 11:27:19,840 DEBUG probert.network:584 event for addr_change: CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:27:19,841 DEBUG probert.network:716 addr_change CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:27:19,842 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'2001:3c8:2105:a:20c:29ff:fec8:51f', 'ifindex': 2}
2021-01-20 11:27:20,276 DEBUG subiquity.ui.mirror:61 User input: {'url': 'http://th.archive.ubuntu.com/ubuntu'}
2021-01-20 11:27:20,276 DEBUG subiquity.controllers.mirror:144 MirrorController.done next_screen mirror=http://th.archive.ubuntu.com/ubuntu
2021-01-20 11:27:20,276 DEBUG subiquity.models.subiquity:133 model mirror is configured
2021-01-20 11:27:20,278 INFO root:39 finish: subiquity/Mirror: SUCCESS: completed
2021-01-20 11:27:20,278 INFO root:39 start: subiquity/Refresh: starting UI
2021-01-20 11:27:20,279 INFO root:39 finish: subiquity/Refresh: SUCCESS: (skipped)
2021-01-20 11:27:20,279 DEBUG subiquitycore.core:452 skipping screen Refresh-2
2021-01-20 11:27:20,279 INFO root:39 start: subiquity/Filesystem: starting UI
2021-01-20 11:27:20,280 DEBUG root:39 start: subiquity/Filesystem/convert_autoinstall_config: 
2021-01-20 11:27:20,280 DEBUG subiquitycore.controller.filesystem:171 self.ai_data = {}
2021-01-20 11:27:20,281 DEBUG root:39 finish: subiquity/Filesystem/convert_autoinstall_config: SUCCESS: 
2021-01-20 11:27:26,675 DEBUG subiquitycore.controller.filesystem:467 _create_boot_partition - adding bios_grub partition
2021-01-20 11:27:26,676 DEBUG subiquity.models.filesystem:1690 add_partition: rounded size from 1048576 to 1048576
2021-01-20 11:27:26,676 DEBUG subiquity.models.filesystem:1690 add_partition: rounded size from 1073741824 to 1073741824
2021-01-20 11:27:26,677 DEBUG subiquity.models.filesystem:1759 adding ext4 to Partition(device=disk-sda, size=1073741824, wipe='superblock', flag='', grub_device=None, id='partition-1')
2021-01-20 11:27:26,677 DEBUG subiquity.models.filesystem:1690 add_partition: rounded size from 106297294848 to 106297294848
2021-01-20 11:27:26,678 DEBUG subiquity.models.filesystem:1759 adding ext4 to LVM_LogicalVolume(name='ubuntu-lv', volgroup=lvm_volgroup-0, size=53148123136, id='lvm_partition-0')
2021-01-20 11:27:28,307 DEBUG subiquitycore.controller.filesystem:382 FilesystemController.finish next_screen
2021-01-20 11:27:28,307 DEBUG subiquity.models.subiquity:133 model filesystem is configured
2021-01-20 11:27:28,307 DEBUG subiquity.core:324 showing InstallConfirmation over <FilesystemView selectable box/flow widget>
2021-01-20 11:27:30,292 INFO root:39 finish: subiquity/Filesystem: SUCCESS: completed
2021-01-20 11:27:30,293 INFO root:39 start: subiquity/Identity: starting UI
2021-01-20 11:27:30,303 INFO root:39 start: subiquity/InstallProgress/install/curtin_install: installing system
2021-01-20 11:27:30,303 DEBUG subiquitycore.controller.installprogress:259 curtin_install
2021-01-20 11:27:30,305 DEBUG subiquity.models.subiquity:324 merging config from <subiquity.models.subiquity.DebconfSelectionsModel object at 0x7f6427d220f0>
2021-01-20 11:27:30,307 DEBUG subiquity.models.subiquity:324 merging config from <subiquity.models.filesystem.FilesystemModel object at 0x7f6427d22208>
2021-01-20 11:27:30,308 DEBUG subiquity.models.filesystem:1595 mountpoints {'/boot': 'mount-0', '/': 'mount-1'}
2021-01-20 11:27:30,308 DEBUG subiquity.models.filesystem:1590 cannot emit action to mount /boot until that for / is emitted
2021-01-20 11:27:30,309 DEBUG subiquity.models.subiquity:324 merging config from <subiquity.models.keyboard.KeyboardModel object at 0x7f6427d22320>
2021-01-20 11:27:30,310 DEBUG subiquity.models.subiquity:324 merging config from <subiquity.models.mirror.MirrorModel object at 0x7f6427d224e0>
2021-01-20 11:27:30,314 DEBUG subiquity.models.subiquity:324 merging config from <subiquity.models.network.NetworkModel object at 0x7f6427d225c0>
2021-01-20 11:27:30,317 DEBUG subiquity.models.subiquity:324 merging config from <subiquity.models.proxy.ProxyModel object at 0x7f6427d225f8>
2021-01-20 11:27:30,352 DEBUG subiquitycore.controller.installprogress:270 curtin install cmd: ['/snap/subiquity/1966/usr/bin/python3', '-m', 'curtin', '--showtrace', '-c', '/var/log/installer/subiquity-curtin-install.conf', 'install']
2021-01-20 11:27:30,358 DEBUG subiquity.lockfile:36 locking exclusive /run/subiquity/installing
2021-01-20 11:27:30,389 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1953', '/snap/subiquity/1966/usr/bin/python3', '-m', 'curtin', '--showtrace', '-c', '/var/log/installer/subiquity-curtin-install.conf', 'install']
2021-01-20 11:27:32,215 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install: curtin command install
2021-01-20 11:27:32,223 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-early: preparing for installation
2021-01-20 11:27:32,224 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-early: SUCCESS: Status.SUCCESS
2021-01-20 11:27:32,225 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning: configuring storage
2021-01-20 11:27:32,230 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin: running 'curtin block-meta simple'
2021-01-20 11:27:34,763 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: curtin command block-meta
2021-01-20 11:27:35,342 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/clear-holders: removing previous storage devices
2021-01-20 11:27:38,312 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/clear-holders: SUCCESS: Status.SUCCESS
2021-01-20 11:27:38,312 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/: configuring disk: disk-sda
2021-01-20 11:27:38,621 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/: SUCCESS: Status.SUCCESS
2021-01-20 11:27:38,621 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-0
2021-01-20 11:27:41,045 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: Status.SUCCESS
2021-01-20 11:27:41,046 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-1
2021-01-20 11:27:42,842 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: Status.SUCCESS
2021-01-20 11:27:42,843 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring format: format-0
2021-01-20 11:27:44,009 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: Status.SUCCESS
2021-01-20 11:27:44,010 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-2
2021-01-20 11:27:46,035 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: Status.SUCCESS
2021-01-20 11:27:46,036 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring lvm_volgroup: lvm_volgroup-0
2021-01-20 11:27:47,132 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: Status.SUCCESS
2021-01-20 11:27:47,133 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring lvm_partition: lvm_partition-0
2021-01-20 11:27:48,226 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: Status.SUCCESS
2021-01-20 11:27:48,227 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring format: format-1
2021-01-20 11:27:49,770 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: Status.SUCCESS
2021-01-20 11:27:49,771 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring mount: mount-1
2021-01-20 11:27:50,044 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: Status.SUCCESS
2021-01-20 11:27:50,045 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring mount: mount-0
2021-01-20 11:27:50,578 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: Status.SUCCESS
2021-01-20 11:27:50,966 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning/builtin: SUCCESS: Status.SUCCESS
2021-01-20 11:27:50,967 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-partitioning: SUCCESS: Status.SUCCESS
2021-01-20 11:27:50,968 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-extract: writing install sources to disk
2021-01-20 11:27:50,969 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-extract/builtin: running 'curtin extract'
2021-01-20 11:27:52,665 DEBUG subiquity.controllers.identity:73 IdentityController.done next_screen user_spec={'hostname': 'bi', 'realname': 'ict', 'username': 'ict', 'password': '<REDACTED>'}
2021-01-20 11:27:52,665 DEBUG subiquity.models.subiquity:133 model identity is configured
2021-01-20 11:27:52,669 INFO root:39 finish: subiquity/Identity: SUCCESS: completed
2021-01-20 11:27:52,670 INFO root:39 start: subiquity/SSH: starting UI
2021-01-20 11:27:53,720 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-extract/builtin/cmd-extract: curtin command extract
2021-01-20 11:27:53,721 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-extract/builtin/cmd-extract/: acquiring and extracting image from cp:///media/filesystem
2021-01-20 11:27:56,111 DEBUG subiquity.ui.ssh:280 User input: {'install_server': True, 'ssh_import_id': None}
2021-01-20 11:27:56,112 DEBUG subiquity.controllers.ssh:138 SSHController.done next_screen result={'install_server': True, 'ssh_import_id': None}
2021-01-20 11:27:56,112 DEBUG subiquity.models.subiquity:133 model ssh is configured
2021-01-20 11:27:56,113 INFO root:39 finish: subiquity/SSH: SUCCESS: completed
2021-01-20 11:27:56,113 INFO root:39 start: subiquity/SnapList: starting UI
2021-01-20 11:27:56,143 DEBUG subiquity.views.snaplist:448 pre-seeded snaps {'lxd', 'core18', 'snapd'}
2021-01-20 11:27:58,372 DEBUG subiquity.views.snaplist:492 snaps to install {}
2021-01-20 11:27:58,372 DEBUG subiquity.controllers.snaplist:181 SnapListController.done next_screen snaps_to_install={}
2021-01-20 11:27:58,372 DEBUG subiquity.models.subiquity:133 model snaplist is configured
2021-01-20 11:27:58,373 INFO root:39 finish: subiquity/SnapList: SUCCESS: completed
2021-01-20 11:27:58,373 INFO root:39 start: subiquity/InstallProgress: starting UI
2021-01-20 11:28:45,964 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-extract/builtin/cmd-extract/: SUCCESS: Status.SUCCESS
2021-01-20 11:28:45,967 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-extract/builtin: SUCCESS: Status.SUCCESS
2021-01-20 11:28:45,968 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-extract: SUCCESS: Status.SUCCESS
2021-01-20 11:28:45,973 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks: configuring installed system
2021-01-20 11:28:45,975 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/000-configure-run: running '/snap/bin/subiquity.subiquity-configure-run'
2021-01-20 11:28:45,976 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/000-configure-run: SUCCESS: Status.SUCCESS
2021-01-20 11:28:45,977 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt: running '/snap/bin/subiquity.subiquity-configure-apt /snap/subiquity/1966/usr/bin/python3 true'
2021-01-20 11:28:47,596 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-apt-config: curtin command apt-config
2021-01-20 11:28:47,854 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-apt-config: SUCCESS: Status.SUCCESS
2021-01-20 11:28:49,965 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-in-target: curtin command in-target
2021-01-20 11:29:16,969 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-in-target: SUCCESS: Status.SUCCESS
2021-01-20 11:29:17,465 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/001-configure-apt: SUCCESS: Status.SUCCESS
2021-01-20 11:29:17,466 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin: running 'curtin curthooks'
2021-01-20 11:29:20,135 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks: curtin command curthooks
2021-01-20 11:29:20,136 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-apt-config: configuring apt configuring apt
2021-01-20 11:29:20,980 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-apt-config: SUCCESS: Status.SUCCESS
2021-01-20 11:29:20,990 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-missing-packages: installing missing packages
2021-01-20 11:29:21,236 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-missing-packages: SUCCESS: Status.SUCCESS
2021-01-20 11:29:21,236 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-iscsi-service: configuring iscsi service
2021-01-20 11:29:21,237 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-iscsi-service: SUCCESS: Status.SUCCESS
2021-01-20 11:29:21,243 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-mdadm-service: configuring raid (mdadm) service
2021-01-20 11:29:21,244 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-mdadm-service: SUCCESS: Status.SUCCESS
2021-01-20 11:29:21,245 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-kernel: installing kernel
2021-01-20 11:30:37,220 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-01-20 11:30:37,241 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-01-20 11:30:37,242 DEBUG probert.network:584 event for addr_change: CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:30:37,242 DEBUG probert.network:716 addr_change CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:31:25,093 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-kernel: SUCCESS: Status.SUCCESS
2021-01-20 11:31:25,093 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/setting-up-swap: setting up swap
2021-01-20 11:31:25,111 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/setting-up-swap: SUCCESS: Status.SUCCESS
2021-01-20 11:31:25,112 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/apply-networking-config: apply networking config
2021-01-20 11:31:25,112 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/apply-networking-config: SUCCESS: Status.SUCCESS
2021-01-20 11:31:25,113 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-etc-fstab: writing etc/fstab
2021-01-20 11:31:25,121 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-etc-fstab: SUCCESS: Status.SUCCESS
2021-01-20 11:31:25,124 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-multipath: configuring multipath
2021-01-20 11:31:26,679 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-multipath: SUCCESS: Status.SUCCESS
2021-01-20 11:31:26,680 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/system-upgrade: updating packages on target system
2021-01-20 11:31:26,680 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/system-upgrade: SUCCESS: Status.SUCCESS
2021-01-20 11:31:26,681 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/pollinate-user-agent: configuring pollinate user-agent on target
2021-01-20 11:31:26,687 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/pollinate-user-agent: SUCCESS: Status.SUCCESS
2021-01-20 11:31:26,688 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/updating-initramfs-configuration: updating initramfs configuration
2021-01-20 11:32:14,156 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/updating-initramfs-configuration: SUCCESS: Status.SUCCESS
2021-01-20 11:32:14,157 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-bootloader: configuring target system bootloader
2021-01-20 11:32:14,179 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/install-grub: installing grub to target devices
2021-01-20 11:32:20,254 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/install-grub: SUCCESS: Status.SUCCESS
2021-01-20 11:32:20,255 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-bootloader: SUCCESS: Status.SUCCESS
2021-01-20 11:32:20,256 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks: SUCCESS: Status.SUCCESS
2021-01-20 11:32:20,715 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks/builtin: SUCCESS: Status.SUCCESS
2021-01-20 11:32:20,717 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-curthooks: SUCCESS: Status.SUCCESS
2021-01-20 11:32:20,717 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-hook: finalizing installation
2021-01-20 11:32:20,723 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-hook/builtin: running 'curtin hook'
2021-01-20 11:32:23,118 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1953', '/snap/subiquity/1966/usr/bin/python3', '-m', 'curtin', '--showtrace', '-c', '/var/log/installer/subiquity-curtin-install.conf', 'install'] exited with code 0
2021-01-20 11:32:23,119 DEBUG subiquity.lockfile:44 unlocking exclusive /run/subiquity/installing
2021-01-20 11:32:23,119 DEBUG subiquitycore.controller.installprogress:283 curtin_install completed: 0
2021-01-20 11:32:23,119 DEBUG subiquitycore.controller.installprogress:286 After curtin install OK
2021-01-20 11:32:23,119 INFO root:39 finish: subiquity/InstallProgress/install/curtin_install: SUCCESS: installing system
2021-01-20 11:32:23,465 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-hook/builtin/cmd-hook: curtin command hook
2021-01-20 11:32:23,467 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-hook/builtin/cmd-hook: SUCCESS: Status.SUCCESS
2021-01-20 11:32:23,469 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-hook/builtin: SUCCESS: Status.SUCCESS
2021-01-20 11:32:23,471 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-hook: SUCCESS: Status.SUCCESS
2021-01-20 11:32:23,472 DEBUG root:39 start: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-late: executing late commands
2021-01-20 11:32:23,474 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install/stage-late: SUCCESS: Status.SUCCESS
2021-01-20 11:32:23,478 DEBUG root:39 finish: subiquity/InstallProgress/install/curtin_install/cmd-install: SUCCESS: Status.SUCCESS
2021-01-20 11:32:23,524 DEBUG subiquitycore.controller.installprogress:336 waited 0.4 seconds for events to drain
2021-01-20 11:32:23,524 INFO root:39 start: subiquity/InstallProgress/install/postinstall: final system configuration
2021-01-20 11:32:23,526 DEBUG subiquity.models.filesystem:1595 mountpoints {'/boot': 'mount-0', '/': 'mount-1'}
2021-01-20 11:32:23,527 DEBUG subiquity.models.filesystem:1590 cannot emit action to mount /boot until that for / is emitted
2021-01-20 11:32:23,553 DEBUG root:39 start: subiquity/InstallProgress/install/postinstall/configure_cloud_init: configuring cloud-init
2021-01-20 11:32:23,555 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-01-20 11:32:23,592 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-01-20 11:32:23,592 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-01-20 11:32:23,610 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-01-20 11:32:23,611 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-01-20 11:32:23,627 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-01-20 11:32:23,628 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-01-20 11:32:23,644 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-01-20 11:32:23,645 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-01-20 11:32:23,670 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-01-20 11:32:23,671 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-01-20 11:32:23,685 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-01-20 11:32:23,686 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-01-20 11:32:23,695 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-01-20 11:32:23,696 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-01-20 11:32:23,705 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-01-20 11:32:23,705 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-01-20 11:32:23,714 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-01-20 11:32:23,714 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-01-20 11:32:23,723 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-01-20 11:32:23,734 DEBUG root:39 finish: subiquity/InstallProgress/install/postinstall/configure_cloud_init: SUCCESS: configuring cloud-init
2021-01-20 11:32:23,735 DEBUG root:39 start: subiquity/InstallProgress/install/postinstall/install_openssh-server: installing openssh-server
2021-01-20 11:32:23,736 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1953', '/snap/subiquity/1966/usr/bin/python3', '-m', 'curtin', 'system-install', '-t', '/target', '--', 'openssh-server']
2021-01-20 11:32:40,957 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1953', '/snap/subiquity/1966/usr/bin/python3', '-m', 'curtin', 'system-install', '-t', '/target', '--', 'openssh-server'] exited with code 0
2021-01-20 11:32:40,958 DEBUG root:39 finish: subiquity/InstallProgress/install/postinstall/install_openssh-server: SUCCESS: installing openssh-server
2021-01-20 11:32:40,958 DEBUG root:39 start: subiquity/InstallProgress/install/postinstall/restore_apt_config: restoring apt configuration
2021-01-20 11:32:40,959 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1953', 'umount', '/target/etc/apt']
2021-01-20 11:32:40,993 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1953', 'umount', '/target/etc/apt'] exited with code 0
2021-01-20 11:32:40,996 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1953', '/snap/subiquity/1966/usr/bin/python3', '-m', 'curtin', 'in-target', '-t', '/target', '--', 'apt-get', 'update']
2021-01-20 11:32:49,235 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1953', '/snap/subiquity/1966/usr/bin/python3', '-m', 'curtin', 'in-target', '-t', '/target', '--', 'apt-get', 'update'] exited with code 0
2021-01-20 11:32:49,237 DEBUG root:39 finish: subiquity/InstallProgress/install/postinstall/restore_apt_config: SUCCESS: restoring apt configuration
2021-01-20 11:32:49,237 INFO root:39 finish: subiquity/InstallProgress/install/postinstall: SUCCESS: final system configuration
2021-01-20 11:32:49,248 DEBUG root:39 start: subiquity/InstallProgress/install/run_unattended_upgrades: downloading and installing security updates
2021-01-20 11:32:49,250 DEBUG subiquitycore.utils:94 astart_command called: ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1953', '/snap/subiquity/1966/usr/bin/python3', '-m', 'curtin', 'in-target', '-t', '/target', '--', 'unattended-upgrades', '-v']
2021-01-20 11:33:44,563 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-01-20 11:33:44,598 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-01-20 11:33:44,599 DEBUG probert.network:584 event for addr_change: CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:33:44,599 DEBUG probert.network:716 addr_change CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:37:00,807 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-01-20 11:37:00,834 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-01-20 11:37:00,835 DEBUG probert.network:584 event for addr_change: CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:37:00,835 DEBUG probert.network:716 addr_change CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:40:15,002 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-01-20 11:40:15,026 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-01-20 11:40:15,027 DEBUG probert.network:584 event for addr_change: CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:40:15,027 DEBUG probert.network:716 addr_change CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:42:59,937 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-01-20 11:42:59,970 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-01-20 11:42:59,971 DEBUG probert.network:584 event for addr_change: CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:42:59,971 DEBUG probert.network:716 addr_change CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:45:38,059 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-01-20 11:45:38,131 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-01-20 11:45:38,131 DEBUG probert.network:584 event for addr_change: CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:45:38,132 DEBUG probert.network:716 addr_change CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:48:31,832 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-01-20 11:48:31,870 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-01-20 11:48:31,871 DEBUG probert.network:584 event for addr_change: CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:48:31,871 DEBUG probert.network:716 addr_change CHANGE {'ifindex': 2, 'flags': 768, 'family': 10, 'scope': 0, 'local': b'2001:3c8:2105:a:20c:29ff:fec8:51f/64'}
2021-01-20 11:48:32,364 DEBUG root:39 finish: subiquity/InstallProgress/install/run_unattended_upgrades: SUCCESS: downloading and installing security updates
2021-01-20 11:48:32,373 DEBUG root:39 finish: subiquity/InstallProgress/install: SUCCESS: 
2021-01-20 11:48:32,374 INFO root:39 finish: subiquity/InstallProgress: SUCCESS: completed
2021-01-20 11:48:32,374 DEBUG subiquitycore.core:452 skipping screen Late
2021-01-20 11:48:32,375 INFO root:39 start: subiquity/Reboot: starting UI
2021-01-20 11:48:32,383 DEBUG root:39 start: subiquity/Reboot/copy_logs_to_target: 
2021-01-20 11:48:32,383 DEBUG subiquitycore.utils:74 arun_command called: ['cp', '-aT', '/var/log/installer', '/target/var/log/installer']