Tails Cloner sometimes fails to format the newly created system partition
Summary
This happens only when installing, not when upgrading (in that case we don't create nor format a partition).
It happens when cloning:
- to a pristine USB drive
- to a USB drive with a non-Tails partition table and filesystem
- to a Tails USB drive with a persistent storage
This probably affects:
- Scenario: Installing Tails with Tails Cloner to a used USB drive
- Scenario: Installing Tails with Tails Cloner to a pristine USB drive
- Scenario: Re-installing Tails over an existing USB installation with a persistent partition
Details
The failures start like this:
May 11 15:30:53 amnesia tails-installer[9104]: 2022-05-11 15:30:53,025 [creator.py:428 (popen)] DEBUG: /sbin/sgdisk --print /dev/sda1
May 11 15:30:53 amnesia tails-installer[9104]: 2022-05-11 15:30:53,064 [creator.py:608 (_set_drive)] DEBUG: /dev/sda selected: {'udi': '/org/freedesktop/UDisks2/block_devices/sda', 'is_optical': False, 'label': 'QEMU-QEMU-HARDDISK-1-0000:00:01.2:00.0-2', 'vendor': 'QEMU', 'model': 'QEMU HARDDISK', 'fstype': '', 'fsversion': '', 'uuid': '', 'device': '/dev/sda', 'mount': None, 'bootable': None, 'parent': None, 'parent_udi': None, 'parent_size': None, 'parent_data': None, 'size': 7549747200, 'mounted_partitions': {}, 'is_device_big_enough_for_installation': True, 'is_device_big_enough_for_upgrade': True, 'is_device_big_enough_for_reinstall': True, 'removable': True, 'free': None}
May 11 15:30:53 amnesia tails-installer[9104]: 2022-05-11 15:30:53,064 [creator.py:760 (partition_device)] INFO: Partitioning device /dev/sda
May 11 15:30:53 amnesia tails-installer[9104]: 2022-05-11 15:30:53,064 [creator.py:764 (partition_device)] DEBUG: Creating partition table
May 11 15:30:53 amnesia udisksd[2708]: Error determining whether device '/dev/sda1' seems to be encrypted: Failed to open device (g-bd-crypto-error-quark, 0)
May 11 15:30:53 amnesia kernel: sda:
May 11 15:30:54 amnesia kernel: sda:
May 11 15:30:54 amnesia tails-installer[9104]: 2022-05-11 15:30:54,124 [creator.py:784 (partition_device)] DEBUG: Creating partition
May 11 15:30:54 amnesia udisksd[2708]: Requested start of the logical partition overlaps with extended partition metadata. Start of the partition moved to 1.
May 11 15:30:56 amnesia kernel: sda: sda1
May 11 15:30:56 amnesia tails-installer[9104]: 2022-05-11 15:30:56,491 [creator.py:428 (popen)] DEBUG: sync
[…]
May 11 15:32:30 amnesia tails-installer[9104]: 2022-05-11 15:32:30,078 [creator.py:156 (_get_udisks_object_data)] DEBUG: looking at /org/freedesktop/UDisks2/block_devices/sda1
May 11 15:32:30 amnesia tails-installer[9104]: 2022-05-11 15:32:30,079 [creator.py:279 (_get_udisks_object_data)] DEBUG: {'bootable': None,
May 11 15:32:30 amnesia tails-installer[9104]: 'device': '/dev/sda1',
May 11 15:32:30 amnesia tails-installer[9104]: 'free': None,
May 11 15:32:30 amnesia tails-installer[9104]: 'fstype': '',
May 11 15:32:30 amnesia tails-installer[9104]: 'fsversion': '',
May 11 15:32:30 amnesia tails-installer[9104]: 'is_device_big_enough_for_installation': True,
May 11 15:32:30 amnesia tails-installer[9104]: 'is_device_big_enough_for_reinstall': True,
May 11 15:32:30 amnesia tails-installer[9104]: 'is_device_big_enough_for_upgrade': True,
May 11 15:32:30 amnesia tails-installer[9104]: 'is_optical': False,
May 11 15:32:30 amnesia tails-installer[9104]: 'label': 'Tails',
May 11 15:32:30 amnesia tails-installer[9104]: 'model': 'QEMU HARDDISK',
May 11 15:32:30 amnesia kernel: sda: sda1
May 11 15:32:30 amnesia tails-installer[9104]: 'mount': None,
May 11 15:32:30 amnesia tails-installer[9104]: 'mounted_partitions': {},
May 11 15:32:30 amnesia tails-installer[9104]: 'parent': '/dev/sda',
May 11 15:32:30 amnesia tails-installer[9104]: 'parent_data': None,
May 11 15:32:30 amnesia tails-installer[9104]: 'parent_size': 7549747200,
May 11 15:32:30 amnesia tails-installer[9104]: 'parent_udi': '/org/freedesktop/UDisks2/block_devices/sda',
May 11 15:32:30 amnesia tails-installer[9104]: 'removable': True,
May 11 15:32:30 amnesia tails-installer[9104]: 'size': 4294967296,
May 11 15:32:30 amnesia tails-installer[9104]: 'udi': '/org/freedesktop/UDisks2/block_devices/sda1',
May 11 15:32:30 amnesia tails-installer[9104]: 'uuid': '',
May 11 15:32:30 amnesia tails-installer[9104]: 'vendor': 'QEMU'}
May 11 15:32:30 amnesia tails-installer[9104]: 2022-05-11 15:32:30,079 [creator.py:608 (_set_drive)] DEBUG: /dev/sda1 selected: {'udi': '/org/freedesktop/UDisks2/block_devices/sda1', 'is_optical': False, 'label': 'Tails', 'vendor': 'QEMU', 'model': 'QEMU HARDDISK', 'fstype': '', 'fsversion': '', 'uuid': '', 'device': '/dev/sda1', 'mount': None, 'bootable': None, 'parent': '/dev/sda', 'parent_udi': '/org/freedesktop/UDisks2/block_devices/sda', 'parent_size': 7549747200, 'parent_data': {'udi': '/org/freedesktop/UDisks2/block_devices/sda', 'is_optical': False, 'label': 'QEMU-QEMU-HARDDISK-1-0000:00:01.2:00.0-2', 'vendor': 'QEMU', 'model': 'QEMU HARDDISK', 'fstype': '', 'fsversion': '', 'uuid': '', 'device': '/dev/sda', 'mount': None, 'bootable': None, 'parent': None, 'parent_udi': None, 'parent_size': None, 'parent_data': None, 'size': 7549747200, 'mounted_partitions': {}, 'is_device_big_enough_for_installation': True, 'is_device_big_enough_for_upgrade': True, 'is_device_big_enough_for_reinstall': True, 'removable': True,
May 11 15:32:30 amnesia tails-installer[9104]: 'free': None}, 'size': 4294967296, 'mounted_partitions': {}, 'is_device_big_enough_for_installation': True, 'is_device_big_enough_for_upgrade': True, 'is_device_big_enough_for_reinstall': True, 'removable': True, 'free': None}
May 11 15:32:30 amnesia tails-installer[9104]: 2022-05-11 15:32:30,079 [creator.py:1057 (format_device)] INFO: Formatting /dev/sda1 as FAT32
Note in particular this: udisksd[2708]: Requested start of the logical partition overlaps with extended partition metadata. Start of the partition moved to 1.
We passed offset=0 to udisks which does that: https://sources.debian.org/src/udisks2/2.9.4-1/src/udiskslinuxpartitiontable.c/?hl=429#L429, which calls https://sources.debian.org/src/libblockdev/2.26-1/src/plugins/part.c/?hl=532#L532, which calls https://sources.debian.org/src/parted/3.5-1/libparted/disk.c/?hl=1616#L1610.
When we see this warning in the logs, the formatting operation later always fails.
The formatting operation can fail in 2 distinct manners:
May 11 15:32:30 amnesia tails-installer[9104]: 2022-05-11 15:32:30,084 [gui.py:186 (run)] ERROR: g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.UnknownMethod: No such interface “org.freedesktop.UDisks2.Block†on object at path /org/freedesktop/UDisks2/block_devices/sda1 (19)
May 11 15:32:30 amnesia tails-installer[9104]: Traceback (most recent call last):
May 11 15:32:30 amnesia tails-installer[9104]: File "/usr/lib/python3/dist-packages/tails_installer/gui.py", line 141, in run
May 11 15:32:30 amnesia tails-installer[9104]: self.live.format_device()
May 11 15:32:30 amnesia tails-installer[9104]: File "/usr/lib/python3/dist-packages/tails_installer/creator.py", line 1061, in format_device
May 11 15:32:30 amnesia tails-installer[9104]: block.call_format_sync(
May 11 15:32:30 amnesia tails-installer[9104]: gi.repository.GLib.GError: g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.UnknownMethod: No such interface “org.freedesktop.UDisks2.Block†on object at path /org/freedesktop/UDisks2/block_devices/sda1 (19)
May 11 15:32:30 amnesia tails-installer[9104]: 2022-05-11 15:32:30,084 [gui.py:187 (run)] DEBUG: Traceback (most recent call last):
May 11 15:32:30 amnesia tails-installer[9104]: File "/usr/lib/python3/dist-packages/tails_installer/gui.py", line 141, in run
May 11 15:32:30 amnesia tails-installer[9104]: self.live.format_device()
May 11 15:32:30 amnesia tails-installer[9104]: File "/usr/lib/python3/dist-packages/tails_installer/creator.py", line 1061, in format_device
May 11 15:32:30 amnesia tails-installer[9104]: block.call_format_sync(
May 11 15:32:30 amnesia tails-installer[9104]: gi.repository.GLib.GError: g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.UnknownMethod: No such interface “org.freedesktop.UDisks2.Block†on object at path /org/freedesktop/UDisks2/block_devices/sda1 (19)
or:
Apr 21 08:12:21 amnesia tails-installer[9448]: 2022-04-21 08:12:21,089 [gui.py:186 (run)] ERROR: 'NoneType' object has no attribute 'props'
Apr 21 08:12:21 amnesia tails-installer[9448]: Traceback (most recent call last):
Apr 21 08:12:21 amnesia tails-installer[9448]: File "/usr/lib/python3/dist-packages/tails_installer/gui.py", line 141, in run
Apr 21 08:12:21 amnesia tails-installer[9448]: self.live.format_device()
Apr 21 08:12:21 amnesia tails-installer[9448]: File "/usr/lib/python3/dist-packages/tails_installer/creator.py", line 1059, in format_device
Apr 21 08:12:21 amnesia tails-installer[9448]: block = dev.props.block
Apr 21 08:12:21 amnesia tails-installer[9448]: AttributeError: 'NoneType' object has no attribute 'props'
Apr 21 08:12:21 amnesia tails-installer[9448]: 2022-04-21 08:12:21,091 [gui.py:187 (run)] DEBUG: Traceback (most recent call last):
Apr 21 08:12:21 amnesia tails-installer[9448]: File "/usr/lib/python3/dist-packages/tails_installer/gui.py", line 141, in run
Apr 21 08:12:21 amnesia tails-installer[9448]: self.live.format_device()
Apr 21 08:12:21 amnesia tails-installer[9448]: File "/usr/lib/python3/dist-packages/tails_installer/creator.py", line 1059, in format_device
Apr 21 08:12:21 amnesia tails-installer[9448]: block = dev.props.block
Apr 21 08:12:21 amnesia tails-installer[9448]: AttributeError: 'NoneType' object has no attribute 'props'
Our hypotheses
- We use udisks incorrectly when we ask it to create the new partition table and/or the new partition.
- The udisks/libblockdev/parted sometimes incorrectly creates the new partition table and/or the new partition.
- We incorrectly get/update the udisks object for the newly created partition ⇒ it lacks the interface needed to be formatted.
Priority
As far as we know, this problem only happens on Jenkins, and only rarely. If that's true, then the main goal is to fix false positives in our test suite.
Our options
We could try:
- Pass offset = 2 MiB (!832 (merged)) and come back to it in a few weeks
- Add debug logging and come back to it in a few weeks
- Dive into the code, try to understand what's going on exactly and to fix it
- Probably not worth the effort at this point