ꦫꦣꦺꦤ꧀ꦄꦤ꧀ꦠꦱꦺꦤ

PATH: var / log / installer

2021-11-03 14:41:37,906 INFO subiquity:127 Starting Subiquity revision 1772
2021-11-03 14:41:37,906 INFO subiquity:128 Arguments passed: ['/snap/subiquity/1772/usr/bin/subiquity']
2021-11-03 14:41:37,906 DEBUG subiquitycore.utils:48 run_command called: ['cloud-init', 'status', '--wait']
2021-11-03 14:41:59,393 DEBUG subiquitycore.utils:61 run_command ['cloud-init', 'status', '--wait'] exited with code 0
2021-11-03 14:41:59,394 DEBUG subiquity:133 waited 21.487617015838623s for cloud-init
2021-11-03 14:41:59,395 DEBUG subiquity:135 loading cloud config
2021-11-03 14:41:59,396 DEBUG cloudinit.util:1359 Reading from /etc/cloud/cloud.cfg (quiet=False)
2021-11-03 14:41:59,396 DEBUG cloudinit.util:1370 Read 4017 bytes from /etc/cloud/cloud.cfg
2021-11-03 14:41:59,396 DEBUG cloudinit.util:959 Attempting to load yaml from string of length 4017 with allowed root types (<class 'dict'>,)
2021-11-03 14:41:59,415 DEBUG cloudinit.util:1359 Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2021-11-03 14:41:59,416 DEBUG cloudinit.util:1370 Read 285 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2021-11-03 14:41:59,416 DEBUG cloudinit.util:959 Attempting to load yaml from string of length 285 with allowed root types (<class 'dict'>,)
2021-11-03 14:41:59,418 DEBUG cloudinit.util:1359 Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2021-11-03 14:41:59,418 DEBUG cloudinit.util:1370 Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2021-11-03 14:41:59,418 DEBUG cloudinit.util:959 Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2021-11-03 14:41:59,425 DEBUG cloudinit.util:1359 Reading from /run/cloud-init/cloud.cfg (quiet=False)
2021-11-03 14:41:59,425 DEBUG cloudinit.util:1370 Read 35 bytes from /run/cloud-init/cloud.cfg
2021-11-03 14:41:59,425 DEBUG cloudinit.util:959 Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2021-11-03 14:41:59,426 DEBUG cloudinit.util:2029 Running command ['systemd-detect-virt', '--quiet', '--container'] with allowed return codes [0] (shell=False, capture=True)
2021-11-03 14:41:59,433 DEBUG cloudinit.util:2029 Running command ['running-in-container'] with allowed return codes [0] (shell=False, capture=True)
2021-11-03 14:41:59,445 DEBUG cloudinit.util:2029 Running command ['lxc-is-container'] with allowed return codes [0] (shell=False, capture=True)
2021-11-03 14:41:59,448 DEBUG cloudinit.util:1359 Reading from /proc/1/environ (quiet=False)
2021-11-03 14:41:59,449 DEBUG cloudinit.util:1370 Read 239 bytes from /proc/1/environ
2021-11-03 14:41:59,449 DEBUG cloudinit.util:1359 Reading from /proc/self/status (quiet=False)
2021-11-03 14:41:59,449 DEBUG cloudinit.util:1370 Read 1305 bytes from /proc/self/status
2021-11-03 14:41:59,449 DEBUG cloudinit.util:1359 Reading from /proc/cmdline (quiet=False)
2021-11-03 14:41:59,449 DEBUG cloudinit.util:1370 Read 48 bytes from /proc/cmdline
2021-11-03 14:41:59,450 DEBUG cloudinit.util:959 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2021-11-03 14:41:59,450 DEBUG cloudinit.util:962 loaded blob returned None, returning default.
2021-11-03 14:41:59,451 DEBUG cloudinit.util:1359 Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2021-11-03 14:41:59,451 DEBUG cloudinit.util:1370 Read 0 bytes from /var/lib/cloud/instance/cloud-config.txt
2021-11-03 14:41:59,451 DEBUG cloudinit.util:959 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2021-11-03 14:41:59,451 DEBUG cloudinit.util:962 loaded blob returned None, returning default.
2021-11-03 14:41:59,452 DEBUG cloudinit.util:1359 Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
2021-11-03 14:41:59,452 DEBUG cloudinit.util:1370 Read 7245 bytes from /var/lib/cloud/instance/obj.pkl
2021-11-03 14:41:59,463 DEBUG cloudinit.util:1359 Reading from /run/cloud-init/.instance-id (quiet=False)
2021-11-03 14:41:59,463 DEBUG cloudinit.util:1370 Read 8 bytes from /run/cloud-init/.instance-id
2021-11-03 14:41:59,463 DEBUG cloudinit.stages:250 restored from cache with run check: DataSourceNoCloud [seed=/var/lib/cloud/seed/nocloud][dsmode=net]
2021-11-03 14:41:59,464 DEBUG cloudinit.util:1359 Reading from /etc/cloud/cloud.cfg (quiet=False)
2021-11-03 14:41:59,464 DEBUG cloudinit.util:1370 Read 4017 bytes from /etc/cloud/cloud.cfg
2021-11-03 14:41:59,464 DEBUG cloudinit.util:959 Attempting to load yaml from string of length 4017 with allowed root types (<class 'dict'>,)
2021-11-03 14:41:59,479 DEBUG cloudinit.util:1359 Reading from /etc/cloud/cloud.cfg.d/90_dpkg.cfg (quiet=False)
2021-11-03 14:41:59,479 DEBUG cloudinit.util:1370 Read 285 bytes from /etc/cloud/cloud.cfg.d/90_dpkg.cfg
2021-11-03 14:41:59,479 DEBUG cloudinit.util:959 Attempting to load yaml from string of length 285 with allowed root types (<class 'dict'>,)
2021-11-03 14:41:59,481 DEBUG cloudinit.util:1359 Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2021-11-03 14:41:59,482 DEBUG cloudinit.util:1370 Read 2057 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2021-11-03 14:41:59,482 DEBUG cloudinit.util:959 Attempting to load yaml from string of length 2057 with allowed root types (<class 'dict'>,)
2021-11-03 14:41:59,486 DEBUG cloudinit.util:1359 Reading from /run/cloud-init/cloud.cfg (quiet=False)
2021-11-03 14:41:59,486 DEBUG cloudinit.util:1370 Read 35 bytes from /run/cloud-init/cloud.cfg
2021-11-03 14:41:59,486 DEBUG cloudinit.util:959 Attempting to load yaml from string of length 35 with allowed root types (<class 'dict'>,)
2021-11-03 14:41:59,486 DEBUG cloudinit.util:959 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2021-11-03 14:41:59,487 DEBUG cloudinit.util:962 loaded blob returned None, returning default.
2021-11-03 14:41:59,487 DEBUG cloudinit.util:1359 Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2021-11-03 14:41:59,487 DEBUG cloudinit.util:1370 Read 0 bytes from /var/lib/cloud/instance/cloud-config.txt
2021-11-03 14:41:59,487 DEBUG cloudinit.util:959 Attempting to load yaml from string of length 0 with allowed root types (<class 'dict'>,)
2021-11-03 14:41:59,487 DEBUG cloudinit.util:962 loaded blob returned None, returning default.
2021-11-03 14:41:59,488 DEBUG cloudinit.stages:85 Using distro class <class 'cloudinit.distros.ubuntu.Distro'>
2021-11-03 14:41:59,491 DEBUG subiquitycore.prober:35 Prober() init finished, data:None
2021-11-03 14:41:59,493 DEBUG subiquitycore.core:99 KDGKBTYPE returned b'\x02', is_linux_tty True
2021-11-03 14:41:59,494 DEBUG asyncio:54 Using selector: EpollSelector
2021-11-03 14:41:59,496 DEBUG subiquity.signals:50 connect_signal: network-proxy-set -> <function Subiquity.__init__.<locals>.<lambda> at 0x7f81bb286f28>
2021-11-03 14:41:59,496 DEBUG subiquity.signals:50 connect_signal: network-change -> Subiquity._network_change
2021-11-03 14:41:59,496 DEBUG subiquitycore.core:650 Application.run
2021-11-03 14:41:59,499 DEBUG curtin:89 Running command ['dpkg', '--print-architecture'] with allowed return codes [0] (capture=True)
2021-11-03 14:41:59,506 DEBUG subiquitycore.core:272 Importing controller: Early
2021-11-03 14:41:59,506 DEBUG subiquitycore.core:272 Importing controller: Reporting
2021-11-03 14:41:59,506 DEBUG subiquitycore.core:272 Importing controller: Error
2021-11-03 14:41:59,507 DEBUG subiquitycore.core:272 Importing controller: Userdata
2021-11-03 14:41:59,507 DEBUG subiquitycore.core:272 Importing controller: Package
2021-11-03 14:41:59,507 DEBUG subiquitycore.core:272 Importing controller: Debconf
2021-11-03 14:41:59,507 DEBUG subiquitycore.core:272 Importing controller: Welcome
2021-11-03 14:41:59,507 DEBUG subiquitycore.core:272 Importing controller: Refresh
2021-11-03 14:41:59,507 DEBUG subiquitycore.core:272 Importing controller: Keyboard
2021-11-03 14:41:59,507 DEBUG subiquitycore.core:272 Importing controller: Network
2021-11-03 14:41:59,511 DEBUG subiquitycore.netplan:88 config for zz-all-en = {'dhcp4': True, 'match': {'name': 'en*'}}
2021-11-03 14:41:59,511 DEBUG subiquitycore.netplan:88 config for zz-all-eth = {'dhcp4': True, 'match': {'name': 'eth*'}}
2021-11-03 14:41:59,512 DEBUG subiquitycore.core:272 Importing controller: Proxy
2021-11-03 14:41:59,512 DEBUG subiquitycore.core:272 Importing controller: Mirror
2021-11-03 14:41:59,512 DEBUG subiquitycore.core:272 Importing controller: Refresh
2021-11-03 14:41:59,512 DEBUG subiquitycore.core:272 Importing controller: Filesystem
2021-11-03 14:41:59,512 DEBUG subiquitycore.core:272 Importing controller: Identity
2021-11-03 14:41:59,513 DEBUG subiquitycore.core:272 Importing controller: SSH
2021-11-03 14:41:59,513 DEBUG subiquitycore.core:272 Importing controller: SnapList
2021-11-03 14:41:59,513 DEBUG subiquitycore.core:272 Importing controller: InstallProgress
2021-11-03 14:41:59,515 DEBUG subiquitycore.core:272 Importing controller: Late
2021-11-03 14:41:59,516 DEBUG subiquity.signals:50 connect_signal: snapd-network-change -> RefreshController.snapd_network_changed
2021-11-03 14:41:59,516 DEBUG subiquity.signals:50 connect_signal: l10n:language-selected -> KeyboardController.language_selected
2021-11-03 14:41:59,516 DEBUG subiquity.signals:50 connect_signal: snapd-network-change -> MirrorController.snapd_network_changed
2021-11-03 14:41:59,516 DEBUG subiquity.signals:50 connect_signal: snapd-network-change -> SnapListController.snapd_network_changed
2021-11-03 14:41:59,516 DEBUG subiquitycore.core:419 known signals: ['network-proxy-set', 'network-change', 'snapd-network-change', 'l10n:language-selected']
2021-11-03 14:41:59,516 DEBUG subiquitycore.core:580 starting controllers
2021-11-03 14:41:59,523 DEBUG probert.network:584 event for link_change: NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2021-11-03 14:41:59,523 DEBUG probert.network:584 event for link_change: NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'ens18'}
2021-11-03 14:41:59,523 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-11-03 14:41:59,523 DEBUG probert.network:584 event for addr_change: NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2021-11-03 14:41:59,524 DEBUG probert.network:584 event for addr_change: NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::3c25:2cff:fe8e:6445/64'}
2021-11-03 14:41:59,524 DEBUG probert.network:671 link_change NEW {'ifindex': 1, 'flags': 65609, 'arptype': 772, 'family': 0, 'is_vlan': False, 'name': b'lo'}
2021-11-03 14:41:59,604 DEBUG subiquitycore.models.network:268 new_link 1 lo lo
2021-11-03 14:41:59,604 DEBUG probert.network:671 link_change NEW {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'ens18'}
2021-11-03 14:41:59,701 DEBUG subiquitycore.models.network:268 new_link 2 ens18 eth
2021-11-03 14:41:59,702 DEBUG subiquitycore.models.network:296 new_link 2 ens18 with config {'dhcp4': True}
2021-11-03 14:41:59,702 DEBUG probert.network:716 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 2, 'scope': 254, 'local': b'127.0.0.1/8'}
2021-11-03 14:41:59,703 DEBUG probert.network:716 addr_change NEW {'ifindex': 1, 'flags': 128, 'family': 10, 'scope': 254, 'local': b'::1'}
2021-11-03 14:41:59,703 DEBUG probert.network:716 addr_change NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::3c25:2cff:fe8e:6445/64'}
2021-11-03 14:41:59,703 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'127.0.0.0', 'ifindex': 1}
2021-11-03 14:41:59,703 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.0/8', 'ifindex': 1}
2021-11-03 14:41:59,703 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'127.0.0.1', 'ifindex': 1}
2021-11-03 14:41:59,703 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'127.255.255.255', 'ifindex': 1}
2021-11-03 14:41:59,703 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'::1', 'ifindex': 1}
2021-11-03 14:41:59,703 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'fe80::/64', 'ifindex': 2}
2021-11-03 14:41:59,703 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'::1', 'ifindex': 1}
2021-11-03 14:41:59,704 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'fe80::3c25:2cff:fe8e:6445', 'ifindex': 2}
2021-11-03 14:41:59,704 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 1, 'table': 255, 'dst': b'ff00::/8', 'ifindex': 2}
2021-11-03 14:41:59,755 DEBUG subiquitycore.core:583 controllers started
2021-11-03 14:41:59,756 DEBUG subiquitycore.core:461 skipping screen Early
2021-11-03 14:41:59,756 DEBUG subiquitycore.core:461 skipping screen Reporting
2021-11-03 14:41:59,756 DEBUG subiquitycore.core:461 skipping screen Error
2021-11-03 14:41:59,756 DEBUG subiquity.models.subiquity:132 model userdata is configured
2021-11-03 14:41:59,756 DEBUG subiquitycore.core:461 skipping screen Userdata
2021-11-03 14:41:59,756 DEBUG subiquity.models.subiquity:132 model packages is configured
2021-11-03 14:41:59,756 DEBUG subiquitycore.core:461 skipping screen Package
2021-11-03 14:41:59,756 DEBUG subiquity.models.subiquity:132 model debconf_selections is configured
2021-11-03 14:41:59,756 DEBUG subiquitycore.core:461 skipping screen Debconf
2021-11-03 14:41:59,757 INFO root:39 start: subiquity/Welcome: starting UI
2021-11-03 14:41:59,939 DEBUG root:39 start: subiquity/Refresh/configure_snapd: 
2021-11-03 14:41:59,940 DEBUG root:39 start: subiquity/Refresh/configure_snapd/get_details: 
2021-11-03 14:41:59,954 DEBUG root:39 start: subiquity/Filesystem/_probe: 
2021-11-03 14:41:59,954 DEBUG root:39 start: subiquity/Filesystem/_probe/probe_once: restricted=False
2021-11-03 14:41:59,969 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/snaps/subiquity HTTP/1.1" 200 1085
2021-11-03 14:41:59,972 DEBUG root:39 finish: subiquity/Refresh/configure_snapd/get_details: SUCCESS: current version of snap is: '20.04.3'
2021-11-03 14:41:59,975 DEBUG root:39 start: subiquity/Refresh/configure_snapd/switching: switching subiquity to stable/ubuntu-20.04
2021-11-03 14:41:59,984 DEBUG urllib3.connectionpool:396 http://localhost:None "POST /v2/snaps/subiquity HTTP/1.1" 202 81
2021-11-03 14:41:59,988 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/changes/4 HTTP/1.1" 200 513
2021-11-03 14:41:59,989 DEBUG root:39 finish: subiquity/Refresh/configure_snapd/switching: SUCCESS: switched to stable/ubuntu-20.04
2021-11-03 14:41:59,990 DEBUG root:39 finish: subiquity/Refresh/configure_snapd: SUCCESS: 
2021-11-03 14:41:59,990 DEBUG root:39 start: subiquity/Refresh/check_for_update: 
2021-11-03 14:42:00,383 DEBUG probert.multipath:49 Extracted multipath paths fields: ['sda', '', '[orphan]', '[undef]', '[undef]', '[undef]', '[undef]', '[undef]']
2021-11-03 14:42:00,406 DEBUG probert.dasd:116 Probing DASD devies
2021-11-03 14:42:00,406 DEBUG probert.dasd:119 DASD devices only present on s390x, arch=x86_64
2021-11-03 14:42:00,455 DEBUG curtin:1270 Extracting storage config from probe data
2021-11-03 14:42:00,474 DEBUG curtin:1277 Sorting extracted configurations
2021-11-03 14:42:00,474 INFO curtin:1296 Validating extracted storage config components
2021-11-03 14:42:00,487 DEBUG curtin:1315 Extracted (unmerged) storage config:
storage:
-   id: disk-sda
    path: /dev/sda
    serial: 0QEMU_QEMU_HARDDISK_drive-scsi0
    type: disk

2021-11-03 14:42:00,487 DEBUG curtin:1317 Generating storage config dependencies
2021-11-03 14:42:00,488 DEBUG curtin:1323 Merging storage config dependencies
2021-11-03 14:42:00,488 DEBUG curtin:1330 Merged storage config:
storage:
    config:
    -   id: disk-sda
        path: /dev/sda
        serial: 0QEMU_QEMU_HARDDISK_drive-scsi0
        type: disk
    version: 1

2021-11-03 14:42:00,489 DEBUG subiquity.models.filesystem:1461 exclusions set()
2021-11-03 14:42:00,489 DEBUG root:39 finish: subiquity/Filesystem/_probe/probe_once: SUCCESS: restricted=False
2021-11-03 14:42:00,490 DEBUG root:39 finish: subiquity/Filesystem/_probe: SUCCESS: 
2021-11-03 14:42:00,490 DEBUG subiquitycore.controller.filesystem:160 self.ai_data = {}
2021-11-03 14:42:22,560 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?select=refresh HTTP/1.1" 500 257
2021-11-03 14:42:22,562 ERROR root:39 finish: subiquity/Refresh/check_for_update: FAIL: 500 Server Error: Internal Server Error for url: http+unix://%2Frun%2Fsnapd.socket/v2/find?select=refresh
2021-11-03 14:44:39,865 DEBUG subiquity.views.welcome:64 WelcomeView en_US
2021-11-03 14:44:39,866 DEBUG subiquity.controllers.welcome:55 WelcomeController.done en_US next_screen
2021-11-03 14:44:39,866 DEBUG subiquity.controllers.keyboard:54 language_selected en_US
2021-11-03 14:44:39,971 DEBUG subiquity.controllers.keyboard:59 loading launguage C
2021-11-03 14:44:40,005 DEBUG subiquity.models.subiquity:132 model locale is configured
2021-11-03 14:44:40,006 INFO root:39 finish: subiquity/Welcome: SUCCESS: completed
2021-11-03 14:44:40,007 INFO root:39 start: subiquity/Refresh: starting UI
2021-11-03 14:44:40,014 INFO root:39 finish: subiquity/Refresh: SUCCESS: (skipped)
2021-11-03 14:44:40,014 DEBUG subiquitycore.core:461 skipping screen Refresh
2021-11-03 14:44:40,014 INFO root:39 start: subiquity/Keyboard: starting UI
2021-11-03 14:44:48,822 DEBUG subiquity.ui.views.keyboard:477 select_layout hu
2021-11-03 14:44:51,947 DEBUG subiquitycore.utils:74 arun_command called: ['setupcon', '--save', '--force', '--keyboard-only']
2021-11-03 14:44:52,581 DEBUG subiquitycore.utils:83 arun_command ['setupcon', '--save', '--force', '--keyboard-only'] exited with code 0
2021-11-03 14:44:52,582 DEBUG subiquitycore.utils:74 arun_command called: ['/snap/bin/subiquity.subiquity-loadkeys']
2021-11-03 14:44:52,632 DEBUG subiquitycore.utils:83 arun_command ['/snap/bin/subiquity.subiquity-loadkeys'] exited with code 0
2021-11-03 14:44:52,632 DEBUG subiquity.controllers.keyboard:74 KeyboardController next_screen
2021-11-03 14:44:52,632 DEBUG subiquity.models.subiquity:132 model keyboard is configured
2021-11-03 14:44:52,633 INFO root:39 finish: subiquity/Keyboard: SUCCESS: completed
2021-11-03 14:44:52,633 INFO root:39 start: subiquity/Network: starting UI
2021-11-03 14:44:52,633 DEBUG subiquitycore.controller.network:278 updating initial NIC config
2021-11-03 14:44:52,633 DEBUG subiquitycore.controller.network:290 disabling ens18
2021-11-03 14:44:52,638 DEBUG subiquitycore.views.network:149 view route_watcher set()
2021-11-03 14:44:52,639 INFO root:39 start: subiquity/Network/apply_config: silent=True
2021-11-03 14:44:52,641 DEBUG subiquitycore.controller.network:343 network config: 
network:
  ethernets: {}
  version: 2

2021-11-03 14:44:52,644 DEBUG subiquitycore.utils:74 arun_command called: ['systemctl', 'mask', '--runtime', 'systemd-networkd.service', 'systemd-networkd.socket']
2021-11-03 14:44:52,958 DEBUG subiquitycore.utils:83 arun_command ['systemctl', 'mask', '--runtime', 'systemd-networkd.service', 'systemd-networkd.socket'] exited with code 0
2021-11-03 14:44:52,959 DEBUG subiquitycore.utils:74 arun_command called: ['systemctl', 'stop', 'systemd-networkd.service', 'systemd-networkd.socket']
2021-11-03 14:44:52,997 DEBUG subiquitycore.utils:83 arun_command ['systemctl', 'stop', 'systemd-networkd.service', 'systemd-networkd.socket'] exited with code 0
2021-11-03 14:44:52,998 DEBUG subiquitycore.controller.network:320 downing ens18
2021-11-03 14:44:52,999 ERROR subiquitycore.controller.network:324 unset_link_flags failed for ens18
Traceback (most recent call last):
  File "/snap/subiquity/1772/lib/python3.6/site-packages/subiquitycore/controllers/network.py", line 321, in _down_devs
    self.observer.rtlistener.unset_link_flags(dev.ifindex, IFF_UP)
RuntimeError: rtnl_link_change failed -16
2021-11-03 14:44:53,000 DEBUG subiquitycore.utils:74 arun_command called: ['systemctl', 'unmask', '--runtime', 'systemd-networkd.service', 'systemd-networkd.socket']
2021-11-03 14:44:53,004 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-11-03 14:44:53,028 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-11-03 14:44:53,028 DEBUG probert.network:584 event for link_change: CHANGE {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'ens18'}
2021-11-03 14:44:53,029 DEBUG probert.network:584 event for link_change: CHANGE {'ifindex': 2, 'flags': 4098, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'ens18'}
2021-11-03 14:44:53,029 DEBUG probert.network:584 event for addr_change: DEL {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::3c25:2cff:fe8e:6445/64'}
2021-11-03 14:44:53,029 DEBUG probert.network:671 link_change CHANGE {'ifindex': 2, 'flags': 4098, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'ens18'}
2021-11-03 14:44:53,030 DEBUG subiquitycore.views.network:260 update_link ens18 2 True
2021-11-03 14:44:53,031 DEBUG probert.network:730 route_change DEL {'family': 10, 'type': 1, 'table': 254, 'dst': b'fe80::/64', 'ifindex': 2}
2021-11-03 14:44:53,031 DEBUG probert.network:730 route_change DEL {'family': 10, 'type': 2, 'table': 255, 'dst': b'fe80::3c25:2cff:fe8e:6445', 'ifindex': 2}
2021-11-03 14:44:53,031 DEBUG probert.network:730 route_change DEL {'family': 10, 'type': 1, 'table': 255, 'dst': b'ff00::/8', 'ifindex': 2}
2021-11-03 14:44:53,031 DEBUG probert.network:716 addr_change DEL {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::3c25:2cff:fe8e:6445/64'}
2021-11-03 14:44:53,032 DEBUG subiquitycore.views.network:260 update_link ens18 2 True
2021-11-03 14:44:53,297 DEBUG subiquitycore.utils:83 arun_command ['systemctl', 'unmask', '--runtime', 'systemd-networkd.service', 'systemd-networkd.socket'] exited with code 0
2021-11-03 14:44:53,298 DEBUG subiquitycore.utils:74 arun_command called: ['netplan', 'apply']
2021-11-03 14:44:53,566 DEBUG subiquitycore.utils:83 arun_command ['netplan', 'apply'] exited with code 0
2021-11-03 14:44:53,567 DEBUG subiquitycore.utils:74 arun_command called: ['systemctl', 'start', 'systemd-networkd.socket']
2021-11-03 14:44:53,577 DEBUG subiquitycore.utils:83 arun_command ['systemctl', 'start', 'systemd-networkd.socket'] exited with code 0
2021-11-03 14:44:53,578 INFO root:39 finish: subiquity/Network/apply_config: SUCCESS: silent=True
2021-11-03 14:45:13,110 DEBUG subiquitycore.network.network_configure_ipv4_interface:188 manual_initial {}
2021-11-03 14:45:13,115 DEBUG root:39 start: subiquity/Network/ens18/EDIT_IPV4: opened
2021-11-03 14:53:10,922 DEBUG subiquitycore.network.network_configure_ipv4_interface:245 EditNetworkStretchy 4 manual result={'network': '109.69.119.128/25', 'address': '109.69.119.192', 'gateway': '109.69.119.129', 'nameservers': ['109.69.119.29', '109.69.119.32'], 'searchdomains': []}
2021-11-03 14:53:10,922 DEBUG subiquitycore.views.network:260 update_link ens18 2 True
2021-11-03 14:53:10,923 DEBUG root:39 finish: subiquity/Network/ens18/EDIT_IPV4: SUCCESS: closed
2021-11-03 14:53:10,923 INFO root:39 start: subiquity/Network/apply_config: silent=False
2021-11-03 14:53:10,925 DEBUG subiquitycore.controller.network:343 network config: 
network:
  ethernets:
    ens18:
      addresses:
      - 109.69.119.192/25
      gateway4: 109.69.119.129
      nameservers:
        addresses:
        - 109.69.119.29
        - 109.69.119.32
  version: 2

2021-11-03 14:53:10,929 DEBUG subiquitycore.netplan:88 config for ens18 = {'addresses': ['109.69.119.192/25'], 'gateway4': '109.69.119.129', 'nameservers': {'addresses': ['109.69.119.29', '109.69.119.32']}}
2021-11-03 14:53:10,930 DEBUG subiquitycore.utils:74 arun_command called: ['systemctl', 'mask', '--runtime', 'systemd-networkd.service', 'systemd-networkd.socket']
2021-11-03 14:53:11,294 DEBUG subiquitycore.utils:83 arun_command ['systemctl', 'mask', '--runtime', 'systemd-networkd.service', 'systemd-networkd.socket'] exited with code 0
2021-11-03 14:53:11,295 DEBUG subiquitycore.utils:74 arun_command called: ['systemctl', 'stop', 'systemd-networkd.service', 'systemd-networkd.socket']
2021-11-03 14:53:11,305 DEBUG subiquitycore.utils:83 arun_command ['systemctl', 'stop', 'systemd-networkd.service', 'systemd-networkd.socket'] exited with code 0
2021-11-03 14:53:11,305 DEBUG subiquitycore.controller.network:320 downing ens18
2021-11-03 14:53:11,312 ERROR subiquitycore.controller.network:324 unset_link_flags failed for ens18
Traceback (most recent call last):
  File "/snap/subiquity/1772/lib/python3.6/site-packages/subiquitycore/controllers/network.py", line 321, in _down_devs
    self.observer.rtlistener.unset_link_flags(dev.ifindex, IFF_UP)
RuntimeError: rtnl_link_change failed -16
2021-11-03 14:53:11,313 DEBUG subiquitycore.utils:74 arun_command called: ['systemctl', 'unmask', '--runtime', 'systemd-networkd.service', 'systemd-networkd.socket']
2021-11-03 14:53:11,320 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-11-03 14:53:11,341 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-11-03 14:53:11,342 DEBUG probert.network:584 event for link_change: CHANGE {'ifindex': 2, 'flags': 4098, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'ens18'}
2021-11-03 14:53:11,342 DEBUG probert.network:671 link_change CHANGE {'ifindex': 2, 'flags': 4098, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'ens18'}
2021-11-03 14:53:11,343 DEBUG subiquitycore.views.network:260 update_link ens18 2 True
2021-11-03 14:53:11,632 DEBUG subiquitycore.utils:83 arun_command ['systemctl', 'unmask', '--runtime', 'systemd-networkd.service', 'systemd-networkd.socket'] exited with code 0
2021-11-03 14:53:11,633 DEBUG subiquitycore.utils:74 arun_command called: ['netplan', 'apply']
2021-11-03 14:53:11,913 DEBUG subiquitycore.utils:83 arun_command ['netplan', 'apply'] exited with code 0
2021-11-03 14:53:11,913 DEBUG subiquitycore.utils:74 arun_command called: ['systemctl', 'start', 'systemd-networkd.socket']
2021-11-03 14:53:11,928 DEBUG subiquitycore.utils:83 arun_command ['systemctl', 'start', 'systemd-networkd.socket'] exited with code 1
2021-11-03 14:53:11,929 INFO root:39 finish: subiquity/Network/apply_config: SUCCESS: silent=False
2021-11-03 14:53:12,390 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-11-03 14:53:12,414 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-11-03 14:53:12,414 DEBUG probert.network:584 event for link_change: CHANGE {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'ens18'}
2021-11-03 14:53:12,415 DEBUG probert.network:584 event for addr_change: NEW {'ifindex': 2, 'flags': 128, 'family': 2, 'scope': 0, 'local': b'109.69.119.192/25'}
2021-11-03 14:53:12,416 DEBUG probert.network:671 link_change CHANGE {'ifindex': 2, 'flags': 69699, 'arptype': 1, 'family': 0, 'is_vlan': False, 'name': b'ens18'}
2021-11-03 14:53:12,416 DEBUG subiquitycore.views.network:260 update_link ens18 2 True
2021-11-03 14:53:12,418 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 1, 'table': 255, 'dst': b'ff00::/8', 'ifindex': 2}
2021-11-03 14:53:12,419 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 1, 'table': 254, 'dst': b'fe80::/64', 'ifindex': 2}
2021-11-03 14:53:12,419 DEBUG probert.network:716 addr_change NEW {'ifindex': 2, 'flags': 128, 'family': 2, 'scope': 0, 'local': b'109.69.119.192/25'}
2021-11-03 14:53:12,419 DEBUG subiquitycore.views.network:260 update_link ens18 2 True
2021-11-03 14:53:12,419 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 2, 'table': 255, 'dst': b'109.69.119.192', 'ifindex': 2}
2021-11-03 14:53:12,420 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'109.69.119.255', 'ifindex': 2}
2021-11-03 14:53:12,420 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'109.69.119.128/25', 'ifindex': 2}
2021-11-03 14:53:12,420 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 3, 'table': 255, 'dst': b'109.69.119.128', 'ifindex': 2}
2021-11-03 14:53:12,420 DEBUG probert.network:730 route_change NEW {'family': 2, 'type': 1, 'table': 254, 'dst': b'default', 'ifindex': 2}
2021-11-03 14:53:12,420 DEBUG subiquity.controllers.snaplist:53 loading list of snaps
2021-11-03 14:53:12,421 DEBUG subiquitycore.views.network:149 view route_watcher {2}
2021-11-03 14:53:12,421 DEBUG subiquitycore.controller.network:95 default routes {2}
2021-11-03 14:53:12,421 DEBUG root:39 start: subiquity/Mirror/lookup: 
2021-11-03 14:53:12,424 DEBUG root:39 start: subiquity/SnapList/loader: 
2021-11-03 14:53:12,431 DEBUG urllib3.connectionpool:826 Starting new HTTPS connection (1): geoip.ubuntu.com
2021-11-03 14:53:12,436 DEBUG root:39 start: subiquity/SnapList/loader/list: 
2021-11-03 14:53:13,823 DEBUG urllib3.connectionpool:396 https://geoip.ubuntu.com:443 "GET /lookup HTTP/1.1" 200 None
2021-11-03 14:53:13,826 DEBUG root:39 finish: subiquity/Mirror/lookup: SUCCESS: 
2021-11-03 14:53:13,993 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?section=server HTTP/1.1" 200 None
2021-11-03 14:53:13,995 DEBUG root:39 finish: subiquity/SnapList/loader/list: SUCCESS: 
2021-11-03 14:53:13,995 DEBUG subiquity.controllers.snaplist:61 fetched list of 23 snaps
2021-11-03 14:53:13,997 DEBUG root:39 start: subiquity/SnapList/loader/fetch/microk8s: 
2021-11-03 14:53:14,839 DEBUG subiquitycore.utils:48 run_command called: ['udevadm', 'settle', '-t', '0']
2021-11-03 14:53:14,851 DEBUG subiquitycore.utils:61 run_command ['udevadm', 'settle', '-t', '0'] exited with code 0
2021-11-03 14:53:14,851 DEBUG probert.network:584 event for addr_change: NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::3c25:2cff:fe8e:6445/64'}
2021-11-03 14:53:14,852 DEBUG probert.network:716 addr_change NEW {'ifindex': 2, 'flags': 128, 'family': 10, 'scope': 253, 'local': b'fe80::3c25:2cff:fe8e:6445/64'}
2021-11-03 14:53:14,852 DEBUG subiquitycore.views.network:260 update_link ens18 2 True
2021-11-03 14:53:14,853 DEBUG probert.network:730 route_change NEW {'family': 10, 'type': 2, 'table': 255, 'dst': b'fe80::3c25:2cff:fe8e:6445', 'ifindex': 2}
2021-11-03 14:53:15,225 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=microk8s HTTP/1.1" 200 None
2021-11-03 14:53:15,239 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/microk8s: SUCCESS: 
2021-11-03 14:53:15,240 DEBUG root:39 start: subiquity/SnapList/loader/fetch/nextcloud: 
2021-11-03 14:53:15,469 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=nextcloud HTTP/1.1" 200 None
2021-11-03 14:53:15,470 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/nextcloud: SUCCESS: 
2021-11-03 14:53:15,471 DEBUG root:39 start: subiquity/SnapList/loader/fetch/wekan: 
2021-11-03 14:53:15,591 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=wekan HTTP/1.1" 200 None
2021-11-03 14:53:15,592 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/wekan: SUCCESS: 
2021-11-03 14:53:15,592 DEBUG root:39 start: subiquity/SnapList/loader/fetch/kata-containers: 
2021-11-03 14:53:15,717 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=kata-containers HTTP/1.1" 200 None
2021-11-03 14:53:15,718 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/kata-containers: SUCCESS: 
2021-11-03 14:53:15,718 DEBUG root:39 start: subiquity/SnapList/loader/fetch/docker: 
2021-11-03 14:53:15,891 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=docker HTTP/1.1" 200 None
2021-11-03 14:53:15,892 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/docker: SUCCESS: 
2021-11-03 14:53:15,892 DEBUG root:39 start: subiquity/SnapList/loader/fetch/canonical-livepatch: 
2021-11-03 14:53:16,022 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=canonical-livepatch HTTP/1.1" 200 None
2021-11-03 14:53:16,023 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/canonical-livepatch: SUCCESS: 
2021-11-03 14:53:16,024 DEBUG root:39 start: subiquity/SnapList/loader/fetch/rocketchat-server: 
2021-11-03 14:53:16,228 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=rocketchat-server HTTP/1.1" 200 None
2021-11-03 14:53:16,229 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/rocketchat-server: SUCCESS: 
2021-11-03 14:53:16,230 DEBUG root:39 start: subiquity/SnapList/loader/fetch/mosquitto: 
2021-11-03 14:53:16,360 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=mosquitto HTTP/1.1" 200 None
2021-11-03 14:53:16,361 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/mosquitto: SUCCESS: 
2021-11-03 14:53:16,362 DEBUG root:39 start: subiquity/SnapList/loader/fetch/etcd: 
2021-11-03 14:53:16,541 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=etcd HTTP/1.1" 200 None
2021-11-03 14:53:16,543 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/etcd: SUCCESS: 
2021-11-03 14:53:16,543 DEBUG root:39 start: subiquity/SnapList/loader/fetch/powershell: 
2021-11-03 14:53:16,701 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=powershell HTTP/1.1" 200 None
2021-11-03 14:53:16,702 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/powershell: SUCCESS: 
2021-11-03 14:53:16,703 DEBUG root:39 start: subiquity/SnapList/loader/fetch/stress-ng: 
2021-11-03 14:53:16,847 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=stress-ng HTTP/1.1" 200 None
2021-11-03 14:53:16,849 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/stress-ng: SUCCESS: 
2021-11-03 14:53:16,849 DEBUG root:39 start: subiquity/SnapList/loader/fetch/sabnzbd: 
2021-11-03 14:53:17,006 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=sabnzbd HTTP/1.1" 200 None
2021-11-03 14:53:17,007 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/sabnzbd: SUCCESS: 
2021-11-03 14:53:17,007 DEBUG root:39 start: subiquity/SnapList/loader/fetch/wormhole: 
2021-11-03 14:53:17,139 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=wormhole HTTP/1.1" 200 None
2021-11-03 14:53:17,140 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/wormhole: SUCCESS: 
2021-11-03 14:53:17,140 DEBUG root:39 start: subiquity/SnapList/loader/fetch/aws-cli: 
2021-11-03 14:53:17,271 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=aws-cli HTTP/1.1" 200 1873
2021-11-03 14:53:17,272 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/aws-cli: SUCCESS: 
2021-11-03 14:53:17,272 DEBUG root:39 start: subiquity/SnapList/loader/fetch/google-cloud-sdk: 
2021-11-03 14:53:17,450 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=google-cloud-sdk HTTP/1.1" 200 1681
2021-11-03 14:53:17,451 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/google-cloud-sdk: SUCCESS: 
2021-11-03 14:53:17,451 DEBUG root:39 start: subiquity/SnapList/loader/fetch/slcli: 
2021-11-03 14:53:17,557 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=slcli HTTP/1.1" 200 2040
2021-11-03 14:53:17,558 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/slcli: SUCCESS: 
2021-11-03 14:53:17,559 DEBUG root:39 start: subiquity/SnapList/loader/fetch/doctl: 
2021-11-03 14:53:17,685 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=doctl HTTP/1.1" 200 1988
2021-11-03 14:53:17,686 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/doctl: SUCCESS: 
2021-11-03 14:53:17,686 DEBUG root:39 start: subiquity/SnapList/loader/fetch/conjure-up: 
2021-11-03 14:53:17,812 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=conjure-up HTTP/1.1" 200 None
2021-11-03 14:53:17,814 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/conjure-up: SUCCESS: 
2021-11-03 14:53:17,814 DEBUG root:39 start: subiquity/SnapList/loader/fetch/postgresql10: 
2021-11-03 14:53:17,935 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=postgresql10 HTTP/1.1" 200 1450
2021-11-03 14:53:17,936 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/postgresql10: SUCCESS: 
2021-11-03 14:53:17,937 DEBUG root:39 start: subiquity/SnapList/loader/fetch/heroku: 
2021-11-03 14:53:18,187 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=heroku HTTP/1.1" 200 None
2021-11-03 14:53:18,188 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/heroku: SUCCESS: 
2021-11-03 14:53:18,188 DEBUG root:39 start: subiquity/SnapList/loader/fetch/keepalived: 
2021-11-03 14:53:18,330 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=keepalived HTTP/1.1" 200 None
2021-11-03 14:53:18,331 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/keepalived: SUCCESS: 
2021-11-03 14:53:18,331 DEBUG root:39 start: subiquity/SnapList/loader/fetch/prometheus: 
2021-11-03 14:53:18,464 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=prometheus HTTP/1.1" 200 None
2021-11-03 14:53:18,466 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/prometheus: SUCCESS: 
2021-11-03 14:53:18,466 DEBUG root:39 start: subiquity/SnapList/loader/fetch/juju: 
2021-11-03 14:53:18,631 DEBUG urllib3.connectionpool:396 http://localhost:None "GET /v2/find?name=juju HTTP/1.1" 200 None
2021-11-03 14:53:18,632 DEBUG root:39 finish: subiquity/SnapList/loader/fetch/juju: SUCCESS: 
2021-11-03 14:53:18,632 DEBUG root:39 finish: subiquity/SnapList/loader: SUCCESS: 
2021-11-03 14:53:21,544 DEBUG subiquity.models.subiquity:132 model network is configured
2021-11-03 14:53:21,544 DEBUG subiquitycore.controller.network:205 NetworkController.done next_screen
2021-11-03 14:53:21,544 INFO root:39 finish: subiquity/Network: SUCCESS: completed
2021-11-03 14:53:21,545 INFO root:39 start: subiquity/Proxy: starting UI
2021-11-03 14:53:23,543 DEBUG subiquity.ui.views.proxy:64 User input: {'url': ''}
2021-11-03 14:53:23,543 DEBUG subiquity.controllers.proxy:63 ProxyController.done next_screen proxy=
2021-11-03 14:53:23,543 DEBUG subiquity.models.subiquity:132 model proxy is configured
2021-11-03 14:53:23,544 INFO root:39 finish: subiquity/Proxy: SUCCESS: completed
2021-11-03 14:53:23,544 INFO root:39 start: subiquity/Mirror: starting UI
2021-11-03 14:53:28,896 DEBUG subiquity.ui.mirror:61 User input: {'url': 'http://hu.archive.ubuntu.com/ubuntu'}
2021-11-03 14:53:28,896 DEBUG subiquity.controllers.mirror:139 MirrorController.done next_screen mirror=http://hu.archive.ubuntu.com/ubuntu
2021-11-03 14:53:28,896 DEBUG subiquity.models.subiquity:132 model mirror is configured
2021-11-03 14:53:28,897 INFO root:39 finish: subiquity/Mirror: SUCCESS: completed
2021-11-03 14:53:28,897 INFO root:39 start: subiquity/Refresh: starting UI
2021-11-03 14:53:28,897 INFO root:39 finish: subiquity/Refresh: SUCCESS: (skipped)
2021-11-03 14:53:28,897 DEBUG subiquitycore.core:461 skipping screen Refresh-2
2021-11-03 14:53:28,897 INFO root:39 start: subiquity/Filesystem: starting UI
2021-11-03 14:53:44,433 DEBUG subiquitycore.controller.filesystem:540 partition_disk_handler: Disk(serial='0QEMU_QEMU_HARDDISK_drive-scsi0', path='/dev/sda', wipe='superblock', type='disk', id='disk-sda') None {'size': 42947575808, 'fstype': 'ext4', 'mount': '/'}
2021-11-03 14:53:44,433 DEBUG subiquitycore.controller.filesystem:541 disk.freespace: 42947575808
2021-11-03 14:53:44,434 DEBUG subiquitycore.controller.filesystem:558 model needs a bootloader partition? True
2021-11-03 14:53:44,434 DEBUG subiquitycore.controller.filesystem:458 _create_boot_partition - adding bios_grub partition
2021-11-03 14:53:44,434 DEBUG subiquity.models.filesystem:1621 add_partition: rounded size from 1048576 to 1048576
2021-11-03 14:53:44,434 DEBUG subiquitycore.controller.filesystem:568 Adjusting request down: 42947575808 - 1048576 = 42946527232
2021-11-03 14:53:44,434 DEBUG subiquity.models.filesystem:1621 add_partition: rounded size from 42946527232 to 42946527232
2021-11-03 14:53:44,434 DEBUG subiquity.models.filesystem:1690 adding ext4 to Partition(device=disk-sda, size=42946527232, wipe='superblock', flag='', grub_device=None, id='partition-1')
2021-11-03 14:53:44,435 DEBUG subiquitycore.controller.filesystem:573 Successfully added partition
2021-11-03 14:53:51,241 DEBUG subiquitycore.controller.filesystem:373 FilesystemController.finish next_screen
2021-11-03 14:53:51,242 DEBUG subiquity.models.subiquity:132 model filesystem is configured
2021-11-03 14:53:51,242 DEBUG subiquity.core:300 showing InstallConfirmation over <FilesystemView selectable box/flow widget>
2021-11-03 14:53:58,199 INFO root:39 finish: subiquity/Filesystem: SUCCESS: completed
2021-11-03 14:53:58,199 INFO root:39 start: subiquity/Identity: starting UI
2021-11-03 14:53:58,204 INFO root:39 start: subiquity/InstallProgress/curtin_install: installing system
2021-11-03 14:53:58,204 DEBUG subiquitycore.controller.installprogress:274 curtin_install
2021-11-03 14:53:58,217 DEBUG subiquity.models.subiquity:306 merging config from <subiquity.models.subiquity.DebconfSelectionsModel object at 0x7f81bb30c518>
2021-11-03 14:53:58,217 DEBUG subiquity.models.subiquity:306 merging config from <subiquity.models.filesystem.FilesystemModel object at 0x7f81bb30c160>
2021-11-03 14:53:58,218 DEBUG subiquity.models.filesystem:1526 mountpoints {'/': 'mount-0'}
2021-11-03 14:53:58,218 DEBUG subiquity.models.subiquity:306 merging config from <subiquity.models.keyboard.KeyboardModel object at 0x7f81bb30c9b0>
2021-11-03 14:53:58,218 DEBUG subiquity.models.subiquity:306 merging config from <subiquity.models.mirror.MirrorModel object at 0x7f81bb30c908>
2021-11-03 14:53:58,219 DEBUG subiquity.models.subiquity:306 merging config from <subiquitycore.models.network.NetworkModel object at 0x7f81bb30c828>
2021-11-03 14:53:58,221 DEBUG subiquity.models.subiquity:306 merging config from <subiquity.models.proxy.ProxyModel object at 0x7f81bb30c8d0>
2021-11-03 14:53:58,230 DEBUG subiquitycore.controller.installprogress:284 curtin install cmd: ['/snap/subiquity/1772/usr/bin/python3', '-m', 'curtin', '--showtrace', '-c', '/var/log/installer/subiquity-curtin-install.conf', 'install']
2021-11-03 14:53:58,230 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1775', '/snap/subiquity/1772/usr/bin/python3', '-m', 'curtin', '--showtrace', '-c', '/var/log/installer/subiquity-curtin-install.conf', 'install']
2021-11-03 14:53:59,465 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install: curtin command install
2021-11-03 14:53:59,468 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-early: preparing for installation
2021-11-03 14:53:59,468 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-early: SUCCESS: Status.SUCCESS
2021-11-03 14:53:59,469 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning: configuring storage
2021-11-03 14:53:59,469 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning/builtin: running 'curtin block-meta simple'
2021-11-03 14:54:00,965 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: curtin command block-meta
2021-11-03 14:54:01,238 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/clear-holders: removing previous storage devices
2021-11-03 14:54:03,535 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/clear-holders: SUCCESS: Status.SUCCESS
2021-11-03 14:54:03,536 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/: configuring disk: disk-sda
2021-11-03 14:54:03,539 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta/: SUCCESS: Status.SUCCESS
2021-11-03 14:54:03,540 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-0
2021-11-03 14:54:05,465 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: Status.SUCCESS
2021-11-03 14:54:05,466 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: partition-1
2021-11-03 14:54:06,532 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: Status.SUCCESS
2021-11-03 14:54:06,533 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring format: format-0
2021-11-03 14:54:08,465 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: Status.SUCCESS
2021-11-03 14:54:08,466 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring mount: mount-0
2021-11-03 14:54:09,216 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: Status.SUCCESS
2021-11-03 14:54:09,218 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning/builtin: SUCCESS: Status.SUCCESS
2021-11-03 14:54:09,219 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-partitioning: SUCCESS: Status.SUCCESS
2021-11-03 14:54:09,219 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-network: configuring network
2021-11-03 14:54:09,220 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-network/builtin: running 'curtin net-meta auto'
2021-11-03 14:54:10,965 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-network/builtin/cmd-net-meta: curtin command net-meta
2021-11-03 14:54:10,966 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-network/builtin/cmd-net-meta: SUCCESS: Status.SUCCESS
2021-11-03 14:54:10,968 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-network/builtin: SUCCESS: Status.SUCCESS
2021-11-03 14:54:10,968 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-network: SUCCESS: Status.SUCCESS
2021-11-03 14:54:10,969 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-extract: writing install sources to disk
2021-11-03 14:54:10,969 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-extract/builtin: running 'curtin extract'
2021-11-03 14:54:12,465 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-extract/builtin/cmd-extract: curtin command extract
2021-11-03 14:54:12,466 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-extract/builtin/cmd-extract/: acquiring and extracting image from cp:///media/filesystem
2021-11-03 14:54:51,466 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-extract/builtin/cmd-extract/: SUCCESS: Status.SUCCESS
2021-11-03 14:54:51,468 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-extract/builtin: SUCCESS: Status.SUCCESS
2021-11-03 14:54:51,469 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-extract: SUCCESS: Status.SUCCESS
2021-11-03 14:54:51,469 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks: configuring installed system
2021-11-03 14:54:51,470 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/000-configure-run: running '/snap/bin/subiquity.subiquity-configure-run'
2021-11-03 14:54:51,471 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/000-configure-run: SUCCESS: Status.SUCCESS
2021-11-03 14:54:51,471 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/001-configure-apt: running '/snap/bin/subiquity.subiquity-configure-apt /snap/subiquity/1772/usr/bin/python3 true'
2021-11-03 14:54:52,373 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-apt-config: curtin command apt-config
2021-11-03 14:54:52,381 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-apt-config: SUCCESS: Status.SUCCESS
2021-11-03 14:54:53,455 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-in-target: curtin command in-target
2021-11-03 14:55:16,466 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/001-configure-apt/cmd-in-target: SUCCESS: Status.SUCCESS
2021-11-03 14:55:16,467 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/001-configure-apt: SUCCESS: Status.SUCCESS
2021-11-03 14:55:16,468 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin: running 'curtin curthooks'
2021-11-03 14:55:17,955 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks: curtin command curthooks
2021-11-03 14:55:17,957 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-apt-config: configuring apt configuring apt
2021-11-03 14:55:18,217 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-apt-config: SUCCESS: Status.SUCCESS
2021-11-03 14:55:18,218 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-missing-packages: installing missing packages
2021-11-03 14:55:18,219 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-missing-packages: SUCCESS: Status.SUCCESS
2021-11-03 14:55:18,219 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-iscsi-service: configuring iscsi service
2021-11-03 14:55:18,219 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-iscsi-service: SUCCESS: Status.SUCCESS
2021-11-03 14:55:18,220 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-mdadm-service: configuring raid (mdadm) service
2021-11-03 14:55:18,220 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-mdadm-service: SUCCESS: Status.SUCCESS
2021-11-03 14:55:18,221 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-kernel: installing kernel
2021-11-03 14:55:22,148 DEBUG subiquity.controllers.identity:70 IdentityController.done next_screen user_spec={'hostname': 'webhost2', 'realname': 'zalaszam', 'username': 'zalaszam', 'password': '<REDACTED>'}
2021-11-03 14:55:22,149 DEBUG subiquity.models.subiquity:132 model identity is configured
2021-11-03 14:55:22,150 INFO root:39 finish: subiquity/Identity: SUCCESS: completed
2021-11-03 14:55:22,150 INFO root:39 start: subiquity/SSH: starting UI
2021-11-03 14:55:32,096 DEBUG subiquity.ui.ssh:300 User input: {'install_server': True, 'ssh_import_id': None}
2021-11-03 14:55:32,096 DEBUG subiquity.controllers.ssh:133 SSHController.done next_screen result={'install_server': True, 'ssh_import_id': None}
2021-11-03 14:55:32,096 DEBUG subiquity.models.subiquity:132 model ssh is configured
2021-11-03 14:55:32,096 INFO root:39 finish: subiquity/SSH: SUCCESS: completed
2021-11-03 14:55:32,097 INFO root:39 start: subiquity/SnapList: starting UI
2021-11-03 14:55:32,100 DEBUG subiquity.views.snaplist:448 pre-seeded snaps {'snapd', 'lxd', 'core18'}
2021-11-03 14:55:46,239 DEBUG subiquity.views.snaplist:492 snaps to install {}
2021-11-03 14:55:46,240 DEBUG subiquity.controllers.snaplist:179 SnapListController.done next_screen snaps_to_install={}
2021-11-03 14:55:46,240 DEBUG subiquity.models.subiquity:132 model snaplist is configured
2021-11-03 14:55:46,240 INFO root:39 finish: subiquity/SnapList: SUCCESS: completed
2021-11-03 14:55:46,240 INFO root:39 start: subiquity/InstallProgress: starting UI
2021-11-03 14:56:22,716 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/installing-kernel: SUCCESS: Status.SUCCESS
2021-11-03 14:56:22,716 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/setting-up-swap: setting up swap
2021-11-03 14:56:22,717 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/setting-up-swap: SUCCESS: Status.SUCCESS
2021-11-03 14:56:22,718 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/apply-networking-config: apply networking config
2021-11-03 14:56:23,390 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/apply-networking-config: SUCCESS: Status.SUCCESS
2021-11-03 14:56:23,390 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-etc-fstab: writing etc/fstab
2021-11-03 14:56:23,391 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/writing-etc-fstab: SUCCESS: Status.SUCCESS
2021-11-03 14:56:23,391 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-multipath: configuring multipath
2021-11-03 14:56:23,715 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/configuring-multipath: SUCCESS: Status.SUCCESS
2021-11-03 14:56:23,715 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/system-upgrade: updating packages on target system
2021-11-03 14:56:23,716 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/system-upgrade: SUCCESS: Status.SUCCESS
2021-11-03 14:56:23,716 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/pollinate-user-agent: configuring pollinate user-agent on target
2021-11-03 14:56:23,717 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/pollinate-user-agent: SUCCESS: Status.SUCCESS
2021-11-03 14:56:23,717 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/updating-initramfs-configuration: updating initramfs configuration
2021-11-03 14:56:52,466 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks/updating-initramfs-configuration: SUCCESS: Status.SUCCESS
2021-11-03 14:56:56,970 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin/cmd-curthooks: SUCCESS: Status.SUCCESS
2021-11-03 14:56:56,970 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks/builtin: SUCCESS: Status.SUCCESS
2021-11-03 14:56:56,971 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-curthooks: SUCCESS: Status.SUCCESS
2021-11-03 14:56:56,971 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-hook: finalizing installation
2021-11-03 14:56:56,972 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-hook/builtin: running 'curtin hook'
2021-11-03 14:56:58,263 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1775', '/snap/subiquity/1772/usr/bin/python3', '-m', 'curtin', '--showtrace', '-c', '/var/log/installer/subiquity-curtin-install.conf', 'install'] exited with code 0
2021-11-03 14:56:58,264 DEBUG subiquitycore.controller.installprogress:289 curtin_install completed: 0
2021-11-03 14:56:58,264 DEBUG subiquitycore.controller.installprogress:292 After curtin install OK
2021-11-03 14:56:58,264 INFO root:39 finish: subiquity/InstallProgress/curtin_install: SUCCESS: installing system
2021-11-03 14:56:58,465 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-hook/builtin/cmd-hook: curtin command hook
2021-11-03 14:56:58,466 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-hook/builtin/cmd-hook: SUCCESS: Status.SUCCESS
2021-11-03 14:56:58,466 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-hook/builtin: SUCCESS: Status.SUCCESS
2021-11-03 14:56:58,467 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-hook: SUCCESS: Status.SUCCESS
2021-11-03 14:56:58,468 DEBUG root:39 start: subiquity/InstallProgress/curtin_install/cmd-install/stage-late: executing late commands
2021-11-03 14:56:58,468 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install/stage-late: SUCCESS: Status.SUCCESS
2021-11-03 14:56:58,469 DEBUG root:39 finish: subiquity/InstallProgress/curtin_install/cmd-install: SUCCESS: Status.SUCCESS
2021-11-03 14:56:58,477 DEBUG subiquitycore.controller.installprogress:344 waited 0.2 seconds for events to drain
2021-11-03 14:56:58,477 INFO root:39 start: subiquity/InstallProgress/postinstall: final system configuration
2021-11-03 14:56:58,478 DEBUG subiquity.models.filesystem:1526 mountpoints {'/': 'mount-0'}
2021-11-03 14:56:58,484 DEBUG root:39 start: subiquity/InstallProgress/postinstall/configure_cloud_init: configuring cloud-init
2021-11-03 14:56:58,494 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-03 14:56:58,510 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-03 14:56:58,510 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-03 14:56:58,517 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-03 14:56:58,517 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-03 14:56:58,523 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-03 14:56:58,524 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-03 14:56:58,530 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-03 14:56:58,530 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-03 14:56:58,536 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-03 14:56:58,537 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-03 14:56:58,543 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-03 14:56:58,543 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-03 14:56:58,549 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-03 14:56:58,550 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-03 14:56:58,556 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-03 14:56:58,557 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-03 14:56:58,563 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-03 14:56:58,564 DEBUG subiquitycore.utils:48 run_command called: ['chroot', '/target', 'getent', 'group']
2021-11-03 14:56:58,570 DEBUG subiquitycore.utils:61 run_command ['chroot', '/target', 'getent', 'group'] exited with code 0
2021-11-03 14:56:58,593 DEBUG root:39 finish: subiquity/InstallProgress/postinstall/configure_cloud_init: SUCCESS: configuring cloud-init
2021-11-03 14:56:58,594 DEBUG root:39 start: subiquity/InstallProgress/postinstall/install_openssh-server: installing openssh-server
2021-11-03 14:56:58,594 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1775', '/snap/subiquity/1772/usr/bin/python3', '-m', 'curtin', 'system-install', '-t', '/target', '--', 'openssh-server']
2021-11-03 14:57:13,208 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1775', '/snap/subiquity/1772/usr/bin/python3', '-m', 'curtin', 'system-install', '-t', '/target', '--', 'openssh-server'] exited with code 0
2021-11-03 14:57:13,209 DEBUG root:39 finish: subiquity/InstallProgress/postinstall/install_openssh-server: SUCCESS: installing openssh-server
2021-11-03 14:57:13,210 DEBUG root:39 start: subiquity/InstallProgress/postinstall/restore_apt_config: restoring apt configuration
2021-11-03 14:57:13,210 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1775', 'umount', '/target/etc/apt']
2021-11-03 14:57:13,229 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1775', 'umount', '/target/etc/apt'] exited with code 0
2021-11-03 14:57:13,229 DEBUG subiquitycore.utils:74 arun_command called: ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1775', '/snap/subiquity/1772/usr/bin/python3', '-m', 'curtin', 'in-target', '-t', '/target', '--', 'apt-get', 'update']
2021-11-03 14:57:17,411 DEBUG subiquitycore.utils:83 arun_command ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1775', '/snap/subiquity/1772/usr/bin/python3', '-m', 'curtin', 'in-target', '-t', '/target', '--', 'apt-get', 'update'] exited with code 0
2021-11-03 14:57:17,412 DEBUG root:39 finish: subiquity/InstallProgress/postinstall/restore_apt_config: SUCCESS: restoring apt configuration
2021-11-03 14:57:17,412 INFO root:39 finish: subiquity/InstallProgress/postinstall: SUCCESS: final system configuration
2021-11-03 14:57:17,414 DEBUG root:39 start: subiquity/InstallProgress/run_unattended_upgrades: downloading and installing security updates
2021-11-03 14:57:17,415 DEBUG subiquitycore.utils:94 astart_command called: ['systemd-cat', '--level-prefix=false', '--identifier=curtin_log.1775', '/snap/subiquity/1772/usr/bin/python3', '-m', 'curtin', 'in-target', '-t', '/target', '--', 'unattended-upgrades', '-v']
2021-11-03 15:18:58,765 DEBUG root:39 finish: subiquity/InstallProgress/run_unattended_upgrades: SUCCESS: downloading and installing security updates
2021-11-03 15:18:58,766 DEBUG root:39 start: subiquity/InstallProgress/copy_logs_to_target: copying logs to installed system
2021-11-03 15:18:58,766 DEBUG subiquitycore.utils:74 arun_command called: ['cp', '-aT', '/var/log/installer', '/target/var/log/installer']

[-] subiquity-info.log.1775 [edit]
[+] block
[-] casper-md5check.json [edit]
[-] media-info [edit]
[-] subiquity-curtin-install.conf [edit]
[-] subiquity-info.log [edit]
[-] subiquity-debug.log [edit]
[-] installer-journal.txt [edit]
[+] ..
[-] curtin-install.log [edit]
[-] curtin-install-cfg.yaml [edit]
[-] subiquity-debug.log.1775 [edit]
[-] autoinstall-user-data [edit]