Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

QubesOS 4.1 installer over Heads ISO boot: blivet doesn't find mount attribute on already mounted loopback device for install when installing packages #6792

Closed
tlaurion opened this issue Jul 24, 2021 · 25 comments
Labels
C: installer diagnosed Technical diagnosis has been performed (see issue comments). P: default Priority: default. Default priority for new issues, to be replaced given sufficient information. r4.1-dom0-stable T: bug Type: bug report. A problem or defect resulting in unintended behavior in something that exists.
Milestone

Comments

@tlaurion
Copy link
Contributor

tlaurion commented Jul 24, 2021

Qubes OS version

QubesOS 4.1 ISO (Qubes-R4.1.0-beta1pre1-x86_64)

Affected component(s) or functionality

QubesOS Installer over Heads (USB boot of verified detached signed ISO)


Brief summary

@marmarek @fepitre : The following happens in blivet after default partitioning of the system, right before installing packages:

Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:              DeviceTree.get_device_by_name: name: /run/initramfs/isoscan/Qubes-R4.1.0-beta1pre1-x86_64.iso ; incomplete: True ; hidden: True ;
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:              DeviceTree.get_device_by_name returned existing 0 B file /run/initramfs/isoscan/Qubes-R4.1.0-beta1pre1-x86_64.iso (44)
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: WARNING:dasbus.server.handler:The call org.fedoraproject.Anaconda.Modules.Storage.DeviceTree.Handler.MountDevice has failed with an exception:
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: Traceback (most recent call last):
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   File "/usr/lib/python3.8/site-packages/dasbus/server/handler.py", line 409, in _method_callback
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:     result = self._handle_call(
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   File "/usr/lib/python3.8/site-packages/dasbus/server/handler.py", line 234, in _handle_call
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:     return handler(*parameters)
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   File "/usr/lib64/python3.8/site-packages/pyanaconda/modules/storage/devicetree/handler_interface.py", line 56, in MountDevice
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:     self.implementation.mount_device(device_name, mount_point)
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   File "/usr/lib64/python3.8/site-packages/pyanaconda/modules/storage/devicetree/handler.py", line 94, in mount_device
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:     device.format.mount(mountpoint=mount_point)
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: AttributeError: 'DeviceFormat' object has no attribute 'mount'
Jul 24 14:56:01 localhost anaconda[1577]: anaconda: threading: Thread Failed: AnaInstallThread (136346816538368)
Jul 24 14:56:01 localhost anaconda[1577]: anaconda: exception: running handleException
Jul 24 14:56:01 localhost anaconda[1577]: anaconda: exception: Traceback (most recent call last):
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/threading.py", line 280, in run
                                              threading.Thread.run(self)
                                          
                                            File "/usr/lib64/python3.8/threading.py", line 870, in run
                                              self._target(*self._args, **self._kwargs)
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/installation.py", line 382, in run_installation
                                              queue.start()
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/installation_tasks.py", line 311, in start
                                              item.start()
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/installation_tasks.py", line 311, in start
                                              item.start()
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/installation_tasks.py", line 311, in start
                                              item.start()
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/installation_tasks.py", line 490, in start
                                              self.run_task()
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/installation_tasks.py", line 456, in run_task
                                              self._task(*self._task_args, **self._task_kwargs)
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/payload/dnfpayload.py", line 1041, in install
                                              self._setup_media(self.install_device)
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/payload/__init__.py", line 744, in _setup_media
                                              payload_utils.mount_device(device, INSTALL_TREE)
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/payload/utils.py", line 74, in mount_device
                                              device_tree.MountDevice(device_name, mount_point)
                                          
                                            File "/usr/lib/python3.8/site-packages/dasbus/client/handler.py", line 442, in _call_method
                                              return self._get_method_reply(
                                          
                                            File "/usr/lib/python3.8/site-packages/dasbus/client/handler.py", line 474, in _get_method_reply
                                              return self._handle_method_error(error)
                                          
                                            File "/usr/lib/python3.8/site-packages/dasbus/client/handler.py", line 496, in _handle_method_error
                                              raise exception from None
                                          
                                          dasbus.error.DBusError: 'DeviceFormat' object has no attribute 'mount'
Jul 24 14:56:01 localhost anaconda[1577]: anaconda: exception: Gtk running, queuing exception handler to the main loop
Jul 24 14:56:01 localhost anaconda[1577]: anaconda: threading: Thread Done: AnaInstallThread (136346816538368)
Jul 24 14:56:04 localhost systemd[1]: [email protected]: Succeeded.

Full journalctl > file output here
Search for AttributeError in the whole dumped log.

How reproducible

Each install attempt fails at the same point above. Also tested https://qubes.notset.fr/iso/Qubes-20210717-x86_64.iso

Steps to reproduce

  1. Have x230-hotp-maximized Heads build flashed
  2. Boot from ISO with a self detached signed iso on USB device (gpg --detach-sign QubesOS.iso, then boot from it)
  3. Do normal install, see above error

Expected behavior

I am not sure why blivet checks again for mountable property of the loop device. Expected behavior would be to continue installation of packages since the ISO is properly mounted already, partitioning has happened and software packages were discovered and are ready to install.

QubesOS 4.0 installers don't show this behavior.

Actual behavior

Installation fails just before package installation with above error.

Solutions you've tried

Heads permits to boot from USB a dd'ed copy of the ISO. This works, but is untrusted (unverified).
But the goal here would be to have fepitre-bot key added into Heads distribution signing keys to validate detached signed ISO images.

Additional context


Relevant documentation you've consulted

Related, non-duplicate issues

@tlaurion tlaurion added P: default Priority: default. Default priority for new issues, to be replaced given sufficient information. T: bug Type: bug report. A problem or defect resulting in unintended behavior in something that exists. labels Jul 24, 2021
@andrewdavidwong andrewdavidwong added C: installer needs diagnosis Requires technical diagnosis from developer. Replace with "diagnosed" or remove if otherwise closed. labels Jul 24, 2021
@andrewdavidwong andrewdavidwong added this to the Release 4.1 milestone Jul 24, 2021
@fepitre
Copy link
Member

fepitre commented Jul 25, 2021

I'll try to have a look today.

@fepitre
Copy link
Member

fepitre commented Jul 25, 2021

Is this is specific to your hardware? Because I don't and neither openQA reproduce the issue? If so, I cannot perform a diagnostic I don't have your hardware, only @marmarek.

@tlaurion
Copy link
Contributor Author

tlaurion commented Jul 25, 2021

@fepitre : This happens when booting QubesOS 4.1 latest installer under Heads when verifying iso.

The important pieces are under blivet debug trace above, where for some reason a mount property is checked and returned false

Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:              DeviceTree.get_device_by_name: name: /run/initramfs/isoscan/Qubes-R4.1.0-beta1pre1-x86_64.iso ; incomplete: True ; hidden: True ;
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:              DeviceTree.get_device_by_name returned existing 0 B file /run/initramfs/isoscan/Qubes-R4.1.0-beta1pre1-x86_64.iso (44)
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: WARNING:dasbus.server.handler:The call org.fedoraproject.Anaconda.Modules.Storage.DeviceTree.Handler.MountDevice has failed with an exception:
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: Traceback (most recent call last):
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   File "/usr/lib/python3.8/site-packages/dasbus/server/handler.py", line 409, in _method_callback
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:     result = self._handle_call(
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   File "/usr/lib/python3.8/site-packages/dasbus/server/handler.py", line 234, in _handle_call
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:     return handler(*parameters)
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   File "/usr/lib64/python3.8/site-packages/pyanaconda/modules/storage/devicetree/handler_interface.py", line 56, in MountDevice
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:     self.implementation.mount_device(device_name, mount_point)
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   File "/usr/lib64/python3.8/site-packages/pyanaconda/modules/storage/devicetree/handler.py", line 94, in mount_device
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:     device.format.mount(mountpoint=mount_point)
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: AttributeError: 'DeviceFormat' object has no attribute 'mount'

The ISO is already mounted, user is created, packages are ready to be installed (as seen in full logs).
This check prevents packages to be actually installed:
signal-2021-07-25-111307

If the ISO is dd'ed to a USB drive, the ISO boots and installs properly, hence not hardware related.

This bug is limited to booting directly from ISO (kexec) under Heads while having the ISO verified against detached signature before offering boot options and kexec'ing into the mounted ISO. As said, behavior was not present under QubesOS 4.0 installer so something changed there in that code path to validate mount attribute on DeviceFormat, which results in the error observed here.

As pointed above, the whole journalctl logtrace was uploaded here

@tlaurion
Copy link
Contributor Author

Let's go into this more for the sake of clarity based on full journalctl output

  1. Heads instructs to boot from iso from kexec'ed command line:
    Jul 24 14:51:21 localhost kernel: Command line: inst.stage2=hd:LABEL=QUBES-R4-1-0-BETA1-X86-64 plymouth.ignore-serial-consoles i915.alpha_support=1 rhgb intel_iommu=on intel_iommu=igfx_off fromiso=/dev/disk/by-uuid/a61421d0-9b90-40c5-a125-9ff36fbb92b2/Qubes-R4.1.0-beta1pre1-x86_64.iso iso-scan/filename=/Qubes-R4.1.0-beta1pre1-x86_64.iso
  2. isoscan picks it, finding hosting partition by UUID a61421d0-9b90-40c5-a125-9ff36fbb92b2 and is mounted under /run/initramfs/isoscan
    Jul 24 14:51:31 localhost systemd[1]: run-initramfs-isoscan.mount: Succeeded.
  3. Anaconda starts using it from loop device loop0
    Jul 24 14:51:31 localhost dracut-initqueue[1084]: anaconda using disk root at /dev/loop0
  4. dracut finds squashfs...
    Jul 24 14:51:31 localhost dracut-initqueue[1084]: anaconda: found /run/install/repo//LiveOS/squashfs.img
  5. blivet takes over and is asked to check discoverable filesystems inside of probed storage devices
    Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: INFO:blivet:devices to scan: ['sdb', 'sdb1', 'sda', 'sda1', 'loop0', 'loop1', 'loop2', 'loop3', 'live-rw', 'live-base']
  6. blivet loops into those found drives, where loop0 device is being of interest here:
    • loop0, the iso file itself which is detected as being iso9660
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                 DeviceTree.handle_device: name: loop0 ; info: {'DEVLINKS': '/dev/disk/by-uuid/2021-07-10-17-09-38-00 '
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:              '/dev/disk/by-label/QUBES-R4-1-0-BETA1-X86-64',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'DEVNAME': '/dev/loop0',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'DEVPATH': '/devices/virtual/block/loop0',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'DEVTYPE': 'disk',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'ID_FS_BOOT_SYSTEM_ID': 'EL\\x20TORITO\\x20SPECIFICATION',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'ID_FS_LABEL': 'QUBES-R4-1-0-BETA1-X86-64',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'ID_FS_LABEL_ENC': 'QUBES-R4-1-0-BETA1-X86-64',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'ID_FS_TYPE': 'iso9660',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'ID_FS_USAGE': 'filesystem',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'ID_FS_UUID': '2021-07-10-17-09-38-00',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'ID_FS_UUID_ENC': '2021-07-10-17-09-38-00',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'ID_FS_VERSION': 'Joliet Extension',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'ID_PART_TABLE_TYPE': 'dos',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'ID_PART_TABLE_UUID': '765b4d1e',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'MAJOR': '7',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'MINOR': '0',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'SUBSYSTEM': 'block',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'SYS_NAME': 'loop0',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'SYS_PATH': '/sys/devices/virtual/block/loop0',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'TAGS': ':systemd:',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'USEC_INITIALIZED': '26720619'} ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: INFO:blivet:scanning loop0 (/sys/devices/virtual/block/loop0)...
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                   DeviceTree.get_device_by_name: name: loop0 ; incomplete: False ; hidden: False ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                   DeviceTree.get_device_by_name returned None
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                  LoopDevicePopulator.run: name: loop0 ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                    DeviceTree.get_device_by_name: name: /run/initramfs/isoscan/Qubes-R4.1.0-beta1pre1-x86_64.iso ; incomplete: False ; hidden: False ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                    DeviceTree.get_device_by_name returned None
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('None') returning DeviceFormat instance with object id 45
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('None') returning DeviceFormat instance with object id 46
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                          FileDevice._set_format: /run/initramfs/isoscan/Qubes-R4.1.0-beta1pre1-x86_64.iso ; type: None ; current: None ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: INFO:blivet:added file /run/initramfs/isoscan/Qubes-R4.1.0-beta1pre1-x86_64.iso (id 44) to device tree
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('None') returning DeviceFormat instance with object id 49
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                               FileDevice.add_child: name: /run/initramfs/isoscan/Qubes-R4.1.0-beta1pre1-x86_64.iso ; child: loop0 ; kids: 0 ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('None') returning DeviceFormat instance with object id 50
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                          LoopDevice._set_format: loop0 ; type: None ; current: None ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: INFO:blivet:added loop loop0 (id 48) to device tree
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: INFO:blivet:got device: LoopDevice instance (0x74fd22165220) --
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   name = loop0  status = False  id = 48
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   children = []
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   parents = ['existing 0 B file /run/initramfs/isoscan/Qubes-R4.1.0-beta1pre1-x86_64.iso '
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  '(44)']
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   uuid = None  size = 0 B
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   format = existing None
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   major = 0  minor = 0  exists = True  protected = False
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   sysfs path =
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   target size = 0 B  path = /dev/loop0
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   format args = []  original_format = None
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:testdata:sysfs attr /sys/devices/virtual/block/loop0/ro: 310a
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                   DeviceTree.handle_format: name: loop0 ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                               AppleBootstrapFS.supported: supported: True ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('appleboot') returning AppleBootstrapFS instance with object id 52
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                               EFIFS.supported: supported: True ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('efi') returning EFIFS instance with object id 53
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                                 MacEFIFS.supported: supported: True ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('macefi') returning MacEFIFS instance with object id 54
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                                  MacEFIFS.supported: supported: True ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('macefi') returning MacEFIFS instance with object id 55
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: INFO:blivet:type detected on 'loop0' is 'iso9660'
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                         Iso9660FS.supported: supported: True ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('iso9660') returning Iso9660FS instance with object id 56
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                        LoopDevice._set_format: loop0 ; type: iso9660 ; current: None ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: INFO:blivet:got format: existing iso9660 filesystem
  • loop1: squasfs live system image, detected as None as final stored format type
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                 DeviceTree.handle_device: name: loop1 ; info: {'DEVNAME': '/dev/loop1',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'DEVPATH': '/devices/virtual/block/loop1',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'DEVTYPE': 'disk',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'ID_FS_TYPE': 'squashfs',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'ID_FS_USAGE': 'filesystem',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'ID_FS_VERSION': '4.0',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'MAJOR': '7',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'MINOR': '1',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'SUBSYSTEM': 'block',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'SYS_NAME': 'loop1',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'SYS_PATH': '/sys/devices/virtual/block/loop1',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'TAGS': ':systemd:',
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:  'USEC_INITIALIZED': '26731129'} ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: INFO:blivet:scanning loop1 (/sys/devices/virtual/block/loop1)...
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                   DeviceTree.get_device_by_name: name: loop1 ; incomplete: False ; hidden: False ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                   DeviceTree.get_device_by_name returned None
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                  LoopDevicePopulator.run: name: loop1 ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                    DeviceTree.get_device_by_name: name: /run/install/repo/LiveOS/squashfs.img ; incomplete: False ; hidden: False ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                    DeviceTree.get_device_by_name returned None
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('None') returning DeviceFormat instance with object id 59
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('None') returning DeviceFormat instance with object id 60
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                          FileDevice._set_format: /run/install/repo/LiveOS/squashfs.img ; type: None ; current: None ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: INFO:blivet:added file /run/install/repo/LiveOS/squashfs.img (id 58) to device tree
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('None') returning DeviceFormat instance with object id 63
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                               FileDevice.add_child: name: /run/install/repo/LiveOS/squashfs.img ; child: loop1 ; kids: 0 ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('None') returning DeviceFormat instance with object id 64
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                          LoopDevice._set_format: loop1 ; type: None ; current: None ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: INFO:blivet:added loop loop1 (id 62) to device tree
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: INFO:blivet:got device: LoopDevice instance (0x74fd2218e160) --
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   name = loop1  status = False  id = 62
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   children = []
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   parents = ['existing 0 B file /run/install/repo/LiveOS/squashfs.img (58)']
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   uuid = None  size = 0 B
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   format = existing None
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   major = 0  minor = 0  exists = True  protected = False
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   sysfs path =
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   target size = 0 B  path = /dev/loop1
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   format args = []  original_format = None
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:testdata:sysfs attr /sys/devices/virtual/block/loop1/ro: 310a
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                   DeviceTree.handle_format: name: loop1 ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                               AppleBootstrapFS.supported: supported: True ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('appleboot') returning AppleBootstrapFS instance with object id 66
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                               EFIFS.supported: supported: True ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('efi') returning EFIFS instance with object id 67
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                                 MacEFIFS.supported: supported: True ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('macefi') returning MacEFIFS instance with object id 68
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                                  MacEFIFS.supported: supported: True ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('macefi') returning MacEFIFS instance with object id 69
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: INFO:blivet:type detected on 'loop1' is 'squashfs'
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('squashfs') returning DeviceFormat instance with object id 70
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                        LoopDevice._set_format: loop1 ; type: None ; current: None ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: INFO:blivet:got format: existing None
  • loop3...
  1. Fastforwarding after QubeSOS selection of installation destination disk, user creation, partitioning. Installer gets ready and find proper created partitions on encrypted LUKS container:
Jul 24 14:55:22 localhost anaconda[1577]: packaging: Input mount points: {'/dev': Size (1.8679656982421875 GiB), '/dev/shm': Size (1.9091339111328125 GiB), '/run': Size (1.8847503662109375 GiB), '/run/initramfs/isoscan': Size (1.82743072509765625 GiB), '/run/install/repo': Size (0 B), '/': Size (1.743816375732421875 GiB), '/tmp': Size (1.90472412109375 GiB), '/mnt/sysroot/boot': 912680550, '/mnt/sysroot': 18253611007}
Jul 24 14:55:22 localhost anaconda[1577]: packaging: Estimated size: download 1.09 GiB & install 5.03 GiB
Jul 24 14:55:22 localhost anaconda[1577]: packaging: Sufficient mountpoints found: {'/mnt/sysroot': 18253611007}
Jul 24 14:55:22 localhost anaconda[1577]: packaging: Install + download space required 6.12 GiB
Jul 24 14:55:22 localhost anaconda[1577]: anaconda: ui.lib.space: fs space: 17 GiB  needed: 9.48 GiB
Jul 24 14:55:22 localhost anaconda[1577]: anaconda: ui.gui.spokes.custom_storage: Populating accordion for devices ['/LiveOS/rootfs.img', '/overlay (deleted)', '/run/initramfs/isoscan/Qubes-R4.1.0-beta1pre1-x86_64.iso', '/run/install/repo/LiveOS/squashfs.img', 'live-base', 'live-rw', 'loop0', 'loop1', 'loop2', 'loop3', 'luks-sda2', 'qubes_dom0', 'qubes_dom0-root', 'qubes_dom0-root-pool', 'qubes_dom0-swap', 'qubes_dom0-vm-pool', 'sda', 'sda1', 'sda2'] (unused ['qubes_dom0-vm-pool'], new ['qubes_dom0-root', 'qubes_dom0-swap', 'sda1']).
  1. Installing stage starts, but seem to complain about iso being detected as having size of 0, staying in "incomplete" state:
Jul 24 14:56:01 localhost anaconda[1577]: anaconda: progress: Find additional packages & run pre_install()
Jul 24 14:56:01 localhost anaconda[1577]: anaconda: installation: Task completed: Find additional packages & run pre_install() (11/42) (0.1 s)
Jul 24 14:56:01 localhost anaconda[1577]: anaconda: progress: Installing.
Jul 24 14:56:01 localhost anaconda[1577]: anaconda: installation: Queue started: Payload installation (6/16)
Jul 24 14:56:01 localhost anaconda[1577]: anaconda: installation: Task started: Install the payload (12/42)
Jul 24 14:56:01 localhost anaconda[1577]: anaconda: progress: Starting package installation process
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:              DeviceTree.get_device_by_name: name: /run/initramfs/isoscan/Qubes-R4.1.0-beta1pre1-x86_64.iso ; incomplete: True ; hidden: True ;
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:              DeviceTree.get_device_by_name returned existing 0 B file /run/initramfs/isoscan/Qubes-R4.1.0-beta1pre1-x86_64.iso (44)
Jul 24 14:56:01 localhost anaconda[1577]: program: Running... udevadm settle --timeout=300
Jul 24 14:56:01 localhost anaconda[1577]: program: Return code: 0
Jul 24 14:56:01 localhost anaconda[1577]: program: Running... udevadm settle --timeout=300
Jul 24 14:56:01 localhost anaconda[1577]: program: Return code: 0
Jul 24 14:56:01 localhost anaconda[1577]: program: Running... udevadm settle --timeout=300
Jul 24 14:56:01 localhost anaconda[1577]: program: Return code: 0
Jul 24 14:56:01 localhost anaconda[1577]: program: Running... udevadm settle --timeout=300
Jul 24 14:56:01 localhost anaconda[1577]: program: Return code: 0
Jul 24 14:56:01 localhost anaconda[1577]: program: Running... udevadm settle --timeout=300
Jul 24 14:56:01 localhost anaconda[1577]: program: Return code: 0
Jul 24 14:56:01 localhost anaconda[1577]: program: Running... udevadm settle --timeout=300
Jul 24 14:56:01 localhost anaconda[1577]: program: Return code: 0
Jul 24 14:56:01 localhost anaconda[1577]: program: Running... udevadm settle --timeout=300
Jul 24 14:56:01 localhost anaconda[1577]: program: Return code: 0
Jul 24 14:56:01 localhost anaconda[1577]: program: Running... udevadm settle --timeout=300
Jul 24 14:56:01 localhost anaconda[1577]: program: Return code: 0
  1. Just right after, the actual bug happens:
Jul 24 14:56:01 localhost anaconda[1577]: program: Running... udevadm settle --timeout=300
Jul 24 14:56:01 localhost anaconda[1577]: program: Return code: 0
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:              DeviceTree.get_device_by_name: name: /run/initramfs/isoscan/Qubes-R4.1.0-beta1pre1-x86_64.iso ; incomplete: True ; hidden: True ;
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:              DeviceTree.get_device_by_name returned existing 0 B file /run/initramfs/isoscan/Qubes-R4.1.0-beta1pre1-x86_64.iso (44)
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: WARNING:dasbus.server.handler:The call org.fedoraproject.Anaconda.Modules.Storage.DeviceTree.Handler.MountDevice has failed with an exception:
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: Traceback (most recent call last):
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   File "/usr/lib/python3.8/site-packages/dasbus/server/handler.py", line 409, in _method_callback
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:     result = self._handle_call(
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   File "/usr/lib/python3.8/site-packages/dasbus/server/handler.py", line 234, in _handle_call
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:     return handler(*parameters)
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   File "/usr/lib64/python3.8/site-packages/pyanaconda/modules/storage/devicetree/handler_interface.py", line 56, in MountDevice
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:     self.implementation.mount_device(device_name, mount_point)
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:   File "/usr/lib64/python3.8/site-packages/pyanaconda/modules/storage/devicetree/handler.py", line 94, in mount_device
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]:     device.format.mount(mountpoint=mount_point)
Jul 24 14:56:01 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: AttributeError: 'DeviceFormat' object has no attribute 'mount'
Jul 24 14:56:01 localhost anaconda[1577]: anaconda: threading: Thread Failed: AnaInstallThread (136346816538368)
Jul 24 14:56:01 localhost anaconda[1577]: anaconda: exception: running handleException
Jul 24 14:56:01 localhost anaconda[1577]: anaconda: exception: Traceback (most recent call last):
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/threading.py", line 280, in run
                                              threading.Thread.run(self)
                                          
                                            File "/usr/lib64/python3.8/threading.py", line 870, in run
                                              self._target(*self._args, **self._kwargs)
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/installation.py", line 382, in run_installation
                                              queue.start()
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/installation_tasks.py", line 311, in start
                                              item.start()
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/installation_tasks.py", line 311, in start
                                              item.start()
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/installation_tasks.py", line 311, in start
                                              item.start()
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/installation_tasks.py", line 490, in start
                                              self.run_task()
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/installation_tasks.py", line 456, in run_task
                                              self._task(*self._task_args, **self._task_kwargs)
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/payload/dnfpayload.py", line 1041, in install
                                              self._setup_media(self.install_device)
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/payload/__init__.py", line 744, in _setup_media
                                              payload_utils.mount_device(device, INSTALL_TREE)
                                          
                                            File "/usr/lib64/python3.8/site-packages/pyanaconda/payload/utils.py", line 74, in mount_device
                                              device_tree.MountDevice(device_name, mount_point)
                                          
                                            File "/usr/lib/python3.8/site-packages/dasbus/client/handler.py", line 442, in _call_method
                                              return self._get_method_reply(
                                          
                                            File "/usr/lib/python3.8/site-packages/dasbus/client/handler.py", line 474, in _get_method_reply
                                              return self._handle_method_error(error)
                                          
                                            File "/usr/lib/python3.8/site-packages/dasbus/client/handler.py", line 496, in _handle_method_error
                                              raise exception from None
                                          
                                          dasbus.error.DBusError: 'DeviceFormat' object has no attribute 'mount'
Jul 24 14:56:01 localhost anaconda[1577]: anaconda: exception: Gtk running, queuing exception handler to the main loop
Jul 24 14:56:01 localhost anaconda[1577]: anaconda: threading: Thread Done: AnaInstallThread (136346816538368)

@fepitre : any insights?

@tlaurion
Copy link
Contributor Author

First:
Jul 24 14:52:00 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: INFO:program:Running... udevadm settle --timeout=300
Last:
Jul 24 14:56:01 localhost anaconda[1577]: program: Running... udevadm settle --timeout=300

300 seconds is 5 minutes, this is 4. Thought it could be linked to timeout having occured.

@tlaurion
Copy link
Contributor Author

@fepitre

From my understanding, it seems blivet forgot that the iso is actually loop0 which is mounted. Why is it constantly trying to figure out the mapping and mount option and flagging detection as incomplete?

Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: INFO:blivet:added file /run/initramfs/isoscan/Qubes-R4.1.0-beta1pre1-x86_64.iso (id 44) to device tree
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('None') returning DeviceFormat instance with object id 49
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                               FileDevice.add_child: name: /run/initramfs/isoscan/Qubes-R4.1.0-beta1pre1-x86_64.iso ; child: loop0 ; kids: 0 ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:get_format('None') returning DeviceFormat instance with object id 50
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: DEBUG:blivet:                          LoopDevice._set_format: loop0 ; type: None ; current: None ;
Jul 24 14:52:07 localhost org.fedoraproject.Anaconda.Modules.Storage[1649]: INFO:blivet:added loop loop0 (id 48) to device tree

Will boot QubesOS 4.0 installer and get journalctl output to compare on same test laptop.

@fepitre
Copy link
Member

fepitre commented Jul 25, 2021

@tlaurion we can certainly workaround this but, for the sake of completeness, what happen if you try with a standard Fedora 32 ISO?

@tlaurion
Copy link
Contributor Author

tlaurion commented Jul 25, 2021

@tlaurion we can certainly workaround this but, for the sake of completeness, what happen if you try with a standard Fedora 32 ISO?

@fepitre : Will test https://ftp.fau.de/fedora/linux/releases/32/Workstation/x86_64/iso/Fedora-Workstation-Live-x86_64-32-1.6.iso

@tlaurion
Copy link
Contributor Author

tlaurion commented Jul 25, 2021

@tlaurion we can certainly workaround this but, for the sake of completeness, what happen if you try with a standard Fedora 32 ISO?

@fepitre : Will test https://ftp.fau.de/fedora/linux/releases/32/Workstation/x86_64/iso/Fedora-Workstation-Live-x86_64-32-1.6.iso

@fepitre : installation from verified ISO happening right now.

So here:
QubesOS 4.1 installer failing:
Q41_blivet_rechecks_for_iso_and_no_mount_attribute_late_at_install.log

Qubesos 4.0 installer going into package install:
qubesos_40_journalctl.log

Fedora32 installer going into package install:
fedora_32_live_install.log

Let me know if you have anything for me to test/report on @fepitre!

@fepitre
Copy link
Member

fepitre commented Jul 25, 2021

@tlaurion thank you, I'll investigate tomorrow morning as much as I can (it's past 10pm around here).

@tlaurion
Copy link
Contributor Author

@fepitre : Full bug report logs as suggested by installer, dumped under remounted RW usb drive:
anaconda-2021-07-25-16:44:58.607476-1568.tar.gz

@tlaurion
Copy link
Contributor Author

@fepitre : Full bug report logs as suggested by installer, dumped under remounted RW usb drive:
anaconda-2021-07-25-16:44:58.607476-1568.tar.gz

I think its unrelated, but under syslog file

20:42:21,993 WARNING kernel:[  131.773236] device-mapper: thin: Data device (dm-4) discard unsupported: Disabling discard passdown.
20:42:22,251 WARNING kernel:[  132.030729] ------------[ cut here ]------------
20:42:22,251 WARNING kernel:[  132.030746] WARNING: CPU: 0 PID: 2962 at block/blk-lib.c:51 __blkdev_issue_discard+0x24d/0x2b0
20:42:22,251 WARNING kernel:[  132.030748] Modules linked in: dm_thin_pool dm_persistent_data dm_bio_prison libfc scsi_transport_fc ath9k ath9k_common ath9k_hw intel_rapl_msr intel_rapl_common mac80211 at24 intel_powerclamp ath cfg80211 mei_me mei rfkill joydev i2c_i801 pcspkr libarc4 i2c_smbus lpc_ich fuse binfmt_misc nls_utf8 isofs loop uas usb_storage 8021q garp mrp stp llc i915 crct10dif_pclmul crc32_pclmul crc32c_intel i2c_algo_bit drm_kms_helper cec sdhci_pci ghash_clmulni_intel drm cqhci sdhci ehci_pci serio_raw mmc_core xhci_pci xhci_pci_renesas e1000e ehci_hcd xhci_hcd video sunrpc sha256_ssse3 dm_crypt dm_round_robin dm_multipath linear raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx raid1 raid0 iscsi_ibft scsi_dh_rdac scsi_dh_hp_sw scsi_dh_emc scsi_dh_alua squashfs cramfs be2iscsi bnx2i cnic uio cxgb4i cxgb4 tls cxgb3i cxgb3 mdio libcxgbi libcxgb qla4xxx iscsi_boot_sysfs iscsi_tcp libiscsi_tcp libiscsi xen_acpi_processor xen_privcmd xen_pciback xen_blkback xen_gntalloc xen_gntdev
20:42:22,251 WARNING kernel:[  132.030871]  scsi_transport_iscsi xen_evtchn
20:42:22,251 WARNING kernel:[  132.030878] CPU: 0 PID: 2962 Comm: mke2fs Not tainted 5.10.47-1.fc32.qubes.x86_64 #1
20:42:22,251 WARNING kernel:[  132.030881] Hardware name: LENOVO 232424J/232424J, BIOS CBET4000 Heads-v0.2.0-1046-gc9effc9-dirty 01/01/1970
20:42:22,251 WARNING kernel:[  132.030886] RIP: e030:__blkdev_issue_discard+0x24d/0x2b0
20:42:22,251 WARNING kernel:[  132.030890] Code: 48 8b 44 24 48 65 48 2b 04 25 28 00 00 00 75 6c 8b 44 24 1c 48 83 c4 50 5b 5d 41 5c 41 5d 41 5e 41 5f c3 0f 0b e9 f1 fe ff ff <0f> 0b 48 8d 74 24 28 4c 89 ef e8 94 c8 00 00 48 c7 c6 e0 49 2b 82
20:42:22,251 WARNING kernel:[  132.030893] RSP: e02b:ffffc900409a7d88 EFLAGS: 00010246
20:42:22,251 WARNING kernel:[  132.030896] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000cc0
20:42:22,251 WARNING kernel:[  132.030898] RDX: 0000000000008000 RSI: 0000000000000000 RDI: ffff888100446700
20:42:22,251 WARNING kernel:[  132.030900] RBP: 0000000000008000 R08: 0000000000000000 R09: ffffc900409a7e10
20:42:22,251 WARNING kernel:[  132.030902] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
20:42:22,251 WARNING kernel:[  132.030904] R13: ffff888100446700 R14: ffff88811650e730 R15: 0000000000000000
20:42:22,251 WARNING kernel:[  132.030929] FS:  00007f534cb89780(0000) GS:ffff88813fe00000(0000) knlGS:0000000000000000
20:42:22,251 WARNING kernel:[  132.030932] CS:  e030 DS: 0000 ES: 0000 CR0: 0000000080050033
20:42:22,251 WARNING kernel:[  132.030934] CR2: 00005a1e3ec97568 CR3: 0000000010912000 CR4: 0000000000050660
20:42:22,251 WARNING kernel:[  132.030950] Call Trace:
20:42:22,251 WARNING kernel:[  132.030963]  blkdev_issue_discard+0x86/0xe0
20:42:22,251 WARNING kernel:[  132.030970]  blk_ioctl_discard+0xee/0x120
20:42:22,251 WARNING kernel:[  132.030974]  blkdev_ioctl+0xad/0x2d0
20:42:22,251 WARNING kernel:[  132.030980]  ? do_user_addr_fault+0x1cc/0x3f0
20:42:22,251 WARNING kernel:[  132.030987]  block_ioctl+0x39/0x40
20:42:22,251 WARNING kernel:[  132.030992]  __x64_sys_ioctl+0x83/0xb0
20:42:22,251 WARNING kernel:[  132.031001]  do_syscall_64+0x33/0x40
20:42:22,251 WARNING kernel:[  132.031007]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
20:42:22,252 WARNING kernel:[  132.031012] RIP: 0033:0x7f534cca817b
20:42:22,252 WARNING kernel:[  132.031016] Code: 0f 1e fa 48 8b 05 1d ad 0c 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 0f 1f 44 00 00 f3 0f 1e fa b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d ed ac 0c 00 f7 d8 64 89 01 48
20:42:22,252 WARNING kernel:[  132.031018] RSP: 002b:00007ffc37ce9068 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
20:42:22,252 WARNING kernel:[  132.031022] RAX: ffffffffffffffda RBX: 00007f534ce52660 RCX: 00007f534cca817b
20:42:22,252 WARNING kernel:[  132.031024] RDX: 00007ffc37ce9070 RSI: 0000000000001277 RDI: 0000000000000003
20:42:22,252 WARNING kernel:[  132.031026] RBP: 0000000000040000 R08: 00005a1e3ec76650 R09: 0000000000000000
20:42:22,252 WARNING kernel:[  132.031028] R10: 00005a1e3ecb8000 R11: 0000000000000246 R12: 0000000000000000
20:42:22,252 WARNING kernel:[  132.031030] R13: 000000000284d000 R14: 00005a1e3ec76310 R15: 000000000284d000
20:42:22,252 WARNING kernel:[  132.031035] ---[ end trace 81f8374d41fb17c2 ]---
20:42:22,252 ERR kernel:[  132.031042] dm-5: Error: discard_granularity is 0.
20:42:21,993 WARNING kernel:device-mapper: thin: Data device (dm-4) discard unsupported: Disabling discard passdown.

@fepitre
Copy link
Member

fepitre commented Jul 26, 2021

@tlaurion have you already tried from a bare Fedora/Debian as livecd to kexec Qubes OS iso install?

For example, I'm attempting without any success to kexec Xen from Fedora 33/Debian 11 livecd:

mount /dev/sr1 /mnt/
mount /mnt/Qubes-R4.1.0-beta1-x86_64.iso /media/
mkdir /tmp/qubes
cp /media/isolinux/vmlinuz /tmp/qubes
cp /media/isolinux/initrd.img /tmp/qubes
cp /media/isolinux/xen.gz /tmp/qubes
umount /media
umount /mnt
kexec -l --module "/tmp/qubes/vmlinuz" --module /tmp/qubes/initrd.img --command-line "console=com1 no-real-mode" /tmp/qubes/xen.gz
kexec -d -e

In this piece of code, I've removed the fromiso and iso-scan part because I originally thought it was that making hang the kexec but no. /dev/sr1 holds an ISO having Qubes ISO into. Also, the bunch of cp seem useless too. I've added after for isolating any issue with already mounted devices but no luck. Any idea?

The idea is to create a similar workflow (also for reproducing your issue) until we can plug certified hardware into openQA.

@tlaurion
Copy link
Contributor Author

tlaurion commented Jul 26, 2021

@tlaurion have you already tried from a bare Fedora/Debian as livecd to kexec Qubes OS iso install?

I never had to do that before. Can try...

For example, I'm attempting without any success to kexec Xen from Fedora 33/Debian 11 livecd:

mount /dev/sr1 /mnt/
mount /mnt/Qubes-R4.1.0-beta1-x86_64.iso /media/
mkdir /tmp/qubes
cp /media/isolinux/vmlinuz /tmp/qubes
cp /media/isolinux/initrd.img /tmp/qubes
cp /media/isolinux/xen.gz /tmp/qubes
umount /media
umount /mnt
kexec -l --module "/tmp/qubes/vmlinuz" --module /tmp/qubes/initrd.img --command-line "console=com1 no-real-mode" /tmp/qubes/xen.gz
kexec -d -e

In this piece of code, I've removed the fromiso and iso-scan part because I originally thought it was that making hang the kexec but no. /dev/sr1 holds an ISO having Qubes ISO into. Also, the bunch of cp seem useless too. I've added after for isolating any issue with already mounted devices but no luck. Any idea?

Under heads, what happens on the following lines is that the ISO (first partition) after having been verified is mounted under /boot.

Then
kexec -l /boot/isolinux/xen.xz --command-line "console=none no-real-mode reboot=no vga=current" --module="/boot/isolinux/vmlinuz inst.stage2=hd:LABEL=QUBES-R4-1-0-BETA1-X86-64 plymouth.ignore-serial-consoles i915.alpha_support=1 rhgb intel_iommu=on intel_iommu=igfx_off fromiso=/dev/disk/by-uuid/a61421d0-9b90-40c5-a125-9ff36fbb92b2/Qubes-R4.1.0-beta1pre1-x86_64.iso iso-scan/filename=/Qubes-R4.1.0-beta1pre1-x86_64.iso" --module "/boot/isolinux/initrd/.img"

The trick applied here with fromiso/iso-scan is that the initrd and kexec'ed kernel are not aware of where the iso was launched from. This is what the step 1 2 3 here are doing to find back the medium.

So here, by passing UUID of the filestystem where the ISO can be found,, the kexec'ed environment can discover that device again and search it for actual referred installation media. You need to pass this iso-scan statement to replicate this under fedora, where fromiso is for debian and where other distros differs.

FYI: Kexec is being patched with the following

@fepitre : let me know if I can be of any other help.

@marmarek
Copy link
Member

marmarek commented Jul 27, 2021

FYI: Kexec is being patched with the following

This seems to be the missing piece. With kexec-tools modified this way, I can successfully kexec into qubes installer from fedora 34 live image. Without the patch, it hangs.

@marmarek
Copy link
Member

@tlaurion is there any chance to get this (or likely - more generalized) patch upstream?

@fepitre
Copy link
Member

fepitre commented Jul 27, 2021

@tlaurion you can stop holding your breathe, we have reproduce it locally! Now it's debug part.

@tlaurion
Copy link
Contributor Author

tlaurion commented Jul 27, 2021

@tlaurion is there any chance to get this (or likely - more generalized) patch upstream?

@marmarek Here is the thread that led to that change.
If Xen is patched to not require EBD in no-real-mode, then kexec doesn't need to be patched.
Your thoughts are more then welcome, here down: linuxboot/heads#227 (comment)

More specifically: linuxboot/heads#227 (comment)

I thought the patch was brought upstream into Xen:
linuxboot/heads#227 (comment)

You running into it means the patch has not found its way into Xen.

Current state: We use kexec patches stil waiting for patchset to be merged under Xen
linuxboot/heads#227 (comment)

@fepitre
Copy link
Member

fepitre commented Jul 28, 2021

Ok so here is a draft of a script to generated a Qubes OS ISO embedded into a raw disk image named embedded_iso.img.

In order to test similar setup to Insurgo (e.g. on openQA first or locally on KVM), one has to create a virtual machine with first disk to be the destination disk for Qubes OS installation, then attaching as a second drive, embedded_iso.img and start the VM by booting on this second drive first.

#!/usr/bin/bash

## DEPENDENCIES: grub2-mkrescue, genisoimage and xorriso

set -xe

LOCALDIR="$(readlink -f "$(dirname "$0")")"
QUBES_ISO="$(readlink -f "$1")"
QUBES_ISO_NAME="$(basename "$QUBES_ISO")"

if [[ $EUID -ne 0 ]]; then
   echo "ERROR: This script must be run with root permissions." 
   exit 1
fi

if [ ! -e "$QUBES_ISO" ]; then
    echo "ERROR: Cannot find $QUBES_ISO."
    exit 1
fi

exit_clean() {
    local exit_code=$?
    if [ -n "$TMPMOUNTDIR" ]; then
        umount "$TMPMOUNTDIR" || true
        rm -rf "$TMPMOUNTDIR"
    fi
    if [[ $LOOP_DEVICE =~ /dev/loop[0-9] ]]; then
        losetup -d "${LOOP_DEVICE}" || true
    fi
    exit "$exit_code"
}

qemu-img create -f raw embedded_iso.img +6G
LOOP_DEVICE="$(losetup -f --show -P embedded_iso.img)"

trap 'exit_clean' 0 1 2 3 6 15
TMPMOUNTDIR="$(mktemp -d)"
if [[ $LOOP_DEVICE =~ /dev/loop[0-9] ]] && [ -n "$TMPMOUNTDIR" ]; then
    printf "o\nn\n\n\n\n\nw\n" | sudo fdisk "$LOOP_DEVICE"
    if [ -e "${LOOP_DEVICE}p1" ]; then
        mkfs.ext4 "${LOOP_DEVICE}p1"
        mount "${LOOP_DEVICE}p1" "$TMPMOUNTDIR"
        cp "$QUBES_ISO" "$TMPMOUNTDIR"
    
        cd "$TMPDIR"
        mkdir -p "$TMPMOUNTDIR/boot/grub"
        VOLID="$(isoinfo -d -i "$QUBES_ISO" | grep -oP 'Volume id: \K[\w-]*')"
        LOOP_UUID="$(lsblk -no uuid "${LOOP_DEVICE}p1")"
        ## (hd0,msdos1) is the first bootable disk which will be embedded_iso.img
        cat > "$TMPMOUNTDIR/boot/grub/grub.cfg" << EOF
set timeout=3
set default=0

menuentry 'Qubes OS R4.1.0 Installation' {
        set isofile='(hd0,msdos1)/$QUBES_ISO_NAME'
        loopback loop \$isofile
        multiboot2 (loop)/isolinux/xen.gz console=com1 no-real-mode edd=off
        module2 (loop)/isolinux/vmlinuz inst.stage2=hd:LABEL=$VOLID findiso=/dev/disk/by-uuid/${LOOP_UUID}/$QUBES_ISO_NAME iso-scan/filename=/$QUBES_ISO_NAME
        module2 --nounzip (loop)/isolinux/initrd.img
}
EOF
        cat > loop_device.map <<EOF
(hd0) ${LOOP_DEVICE}
EOF
        if [ -e /usr/sbin/grub2-install ]; then
            GRUB_INSTALL=/usr/sbin/grub2-install
        else
            GRUB_INSTALL=/usr/sbin/grub-install
        fi
        $GRUB_INSTALL --no-floppy --boot-directory="$TMPMOUNTDIR/boot" --grub-mkdevicemap=loop_device.map --modules="part_msdos" "${LOOP_DEVICE}"
    fi
fi

In order to this setup to work, we need to have the patch provided in QubesOS/qubes-anaconda#17.

@fepitre
Copy link
Member

fepitre commented Jul 29, 2021

I've updated my previous comment with a all in one bootable drive.

@qubesos-bot
Copy link

Automated announcement from builder-github

The package anaconda-32.24.5-4.fc32 has been pushed to the r4.1 testing repository for dom0.
To test this update, please install it with the following command:

sudo qubes-dom0-update --enablerepo=qubes-dom0-current-testing

Changes included in this update

@marmarek
Copy link
Member

@tlaurion today's builds on https://qubes.notset.fr/iso/ contain the fix already, can you confirm it indeed works for you too?

@andrewdavidwong andrewdavidwong added diagnosed Technical diagnosis has been performed (see issue comments). and removed needs diagnosis Requires technical diagnosis from developer. Replace with "diagnosed" or remove if otherwise closed. labels Jul 31, 2021
@tlaurion
Copy link
Contributor Author

tlaurion commented Aug 1, 2021

@marmarek Installing packages from https://qubes.notset.fr/iso/Qubes-20210731-x86_64.iso
The fix works and finally resolves linuxboot/heads#789

@fepitre
Copy link
Member

fepitre commented Aug 1, 2021

@tlaurion at least we have now a similar boot case for Insurgo until we have certified laptop plugged into openQA instance :)

marmarek added a commit to QubesOS/openqa-tests-qubesos that referenced this issue Aug 1, 2021
This is similar setup used in HEADs to boot the installer after verification of
a detached signature.
QubesOS/qubes-issues#6792
marmarek added a commit to marmarek/anaconda that referenced this issue Aug 3, 2021
This fixes checking if given (disk image) file is mounted somewhere,
especially as /run/initramfs/repo.
PackagePayload._device_is_mounted_as_source() depends on it.

Some more details at QubesOS/qubes-issues#6792
@qubesos-bot
Copy link

Automated announcement from builder-github

The package anaconda-32.24.5-4.fc32 has been pushed to the r4.1 stable repository for dom0.
To install this update, please use the standard update command:

sudo qubes-dom0-update

Or update dom0 via Qubes Manager.

Changes included in this update

fepitre pushed a commit to fepitre/anaconda that referenced this issue Oct 16, 2021
This fixes checking if given (disk image) file is mounted somewhere,
especially as /run/initramfs/repo.
PackagePayload._device_is_mounted_as_source() depends on it.

QubesOS/qubes-issues#6792
fepitre pushed a commit to fepitre/anaconda that referenced this issue Dec 27, 2022
This fixes checking if given (disk image) file is mounted somewhere,
especially as /run/initramfs/repo.
PackagePayload._device_is_mounted_as_source() depends on it.

QubesOS/qubes-issues#6792
fepitre pushed a commit to fepitre/anaconda that referenced this issue Jan 4, 2023
This fixes checking if given (disk image) file is mounted somewhere,
especially as /run/initramfs/repo.
PackagePayload._device_is_mounted_as_source() depends on it.

QubesOS/qubes-issues#6792
fepitre pushed a commit to fepitre/anaconda that referenced this issue Jan 4, 2023
This fixes checking if given (disk image) file is mounted somewhere,
especially as /run/initramfs/repo.
PackagePayload._device_is_mounted_as_source() depends on it.

QubesOS/qubes-issues#6792
fepitre pushed a commit to fepitre/anaconda that referenced this issue Jan 10, 2023
This fixes checking if given (disk image) file is mounted somewhere,
especially as /run/initramfs/repo.
PackagePayload._device_is_mounted_as_source() depends on it.

QubesOS/qubes-issues#6792
marmarek added a commit to marmarek/qubes-lorax-templates that referenced this issue Feb 14, 2023
stage2 defaults to inst.repo= so stage2 is is found normally. But
fallback the other way around doesn't work in all the cases -
specifically if the source is a loop device (mounted via
iso-scan/filename= feature).
See rhinstaller/anaconda#3552 for details.

QubesOS/qubes-issues#6792
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
C: installer diagnosed Technical diagnosis has been performed (see issue comments). P: default Priority: default. Default priority for new issues, to be replaced given sufficient information. r4.1-dom0-stable T: bug Type: bug report. A problem or defect resulting in unintended behavior in something that exists.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants