[systemd-devel] cryptsetup vs. swapon/fsck (some kind of race condition)

Thu May 15 14:33:27 PDT 2014

On Thu, May 15, 2014 at 11:15 PM, Andy Kittner <andy.kittner at gmail.com> wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA512
>
> On 15/05/14 18:27, Lennart Poettering wrote:
>> Well, something appears to create your device nodes, and it shouldn't do
>> that...
>>
>> On a udev system userspace never creates any device nodes, that's done
>> on its own by the kernel via devtmpfs, udev then just creates symlinks
>> on top, or changes access rights. It appears that your LVM/DM installation
>> for some reason created device nodes anyway, and you need to figure out
>> why it did that, and turn this off. It might be in your initrd...
>
> Hah, progress: I think I pinpointed the culprit.
> libdm checks whether udev is running and falls back to non-udev code
> otherwise.
>
> When the boot fails, this is what I get:
>
> | May 15 22:06:46 pinky systemd-udevd[1361]: starting version 212
> | May 15 22:06:46 pinky systemd[1]: Starting udev Kernel Socket.
> | May 15 22:06:46 pinky systemd[1]: Listening on udev Kernel Socket.
> | May 15 22:06:46 pinky systemd[1]: Starting udev Control Socket.
> | May 15 22:06:46 pinky systemd[1]: Listening on udev Control Socket.
> | May 15 22:06:46 pinky systemd[1]: Starting udev Coldplug all Devices...
> | May 15 22:06:46 pinky systemd[1]: Starting system-systemd\x2dcryptsetup.slice.
> | May 15 22:06:46 pinky systemd[1]: Created slice system-systemd\x2dcryptsetup.slice.
> | May 15 22:06:46 pinky systemd[1]: Starting Cryptography Setup for swap...
> | May 15 22:06:46 pinky systemd[1]: Starting Cryptography Setup for videos...
> | May 15 22:06:46 pinky systemd[1]: Starting Cryptography Setup for data...
> | May 15 22:06:46 pinky systemd[1]: Starting Cryptography Setup for home...
> | May 15 22:06:46 pinky systemd[1]: Started udev Coldplug all Devices.
> | May 15 22:06:46 pinky systemd[1]: Starting udev Wait for Complete Device Initialization...
> | May 15 22:06:46 pinky systemd-cryptsetup[2436]: Set cipher twofish, mode xts-essiv:wp256, key size 512 bits for device /dev/disk/by-uuid/57d30bae-878a-4931-bc39-10cc18b92486.
> | May 15 22:06:46 pinky systemd-cryptsetup[2434]: Set cipher twofish, mode xts-essiv:wp256, key size 512 bits for device /dev/disk/by-uuid/ee5e92a6-18b6-4247-a1d8-8379b01928fb.
> | May 15 22:06:46 pinky systemd-cryptsetup[2433]: Set cipher twofish, mode xts-essiv:wp256, key size 512 bits for device /dev/disk/by-uuid/b1c029d2-515b-47a1-becf-59c1f5191e43.
> | May 15 22:06:46 pinky systemd-cryptsetup[2435]: Set cipher twofish, mode xts-essiv:rmd256, key size 512 bits for device /dev/disk/by-uuid/72c01d1e-ac93-4263-93d7-fb293dfe49c0.
> | May 15 22:06:46 pinky systemd[1]: Started Create Static Device Nodes in /dev.
> | May 15 22:06:46 pinky systemd[1]: Starting udev Kernel Device Manager...
> | May 15 22:06:46 pinky systemd-udevd[2485]: starting version 212
> | May 15 22:06:47 pinky systemd[1]: Mounted Runtime Directory.
> | May 15 22:06:47 pinky systemd[1]: Mounted Lock Directory.
> | May 15 22:06:47 pinky systemd[1]: Started udev Kernel Device Manager.
> | May 15 22:06:47 pinky systemd-cryptsetup[2433]: AKI DEBUG udev: open_queue_file failed with errno 2
> | May 15 22:06:47 pinky systemd-cryptsetup[2433]: AKI DEBUG libdm:_check_udev_is_running: Udev is not running. Not using udev synchronisation code.
>
> So the udev queue file does not yet exist, libdm thinks the system is
> not running udev and things go wrong...
>
>
> I also was lucky enough to get one of the rare "good" boots right after
> I put in my debug prints (I was fearing a Heisenbug here for a minute)
>
> So here it is for comparison:
>
> | May 15 22:02:10 pinky systemd-udevd[1362]: starting version 212
> | May 15 22:02:10 pinky systemd[1]: Starting udev Kernel Socket.
> | May 15 22:02:10 pinky systemd[1]: Listening on udev Kernel Socket.
> | May 15 22:02:10 pinky systemd[1]: Starting udev Control Socket.
> | May 15 22:02:10 pinky systemd[1]: Listening on udev Control Socket.
> | May 15 22:02:10 pinky systemd[1]: Starting udev Coldplug all Devices...
> | May 15 22:02:10 pinky systemd[1]: Starting system-systemd\x2dcryptsetup.slice.
> | May 15 22:02:10 pinky systemd[1]: Created slice system-systemd\x2dcryptsetup.slice.
> | May 15 22:02:10 pinky systemd[1]: Starting Cryptography Setup for swap...
> | May 15 22:02:10 pinky systemd[1]: Starting Cryptography Setup for videos...
> | May 15 22:02:10 pinky systemd[1]: Starting Cryptography Setup for data...
> | May 15 22:02:10 pinky systemd[1]: Starting Cryptography Setup for home...
> | May 15 22:02:10 pinky systemd[1]: Starting File System Check on Root Device...
> | May 15 22:02:10 pinky systemd-udevd[2464]: starting version 212
> | May 15 22:02:10 pinky systemd[1]: Starting Create Static Device Nodes in /dev...
> | May 15 22:02:10 pinky systemd[1]: Started udev Coldplug all Devices.
> | May 15 22:02:10 pinky systemd[1]: Starting udev Wait for Complete Device Initialization...
> | May 15 22:02:10 pinky systemd[1]: Mounted Runtime Directory.
> | May 15 22:02:10 pinky systemd[1]: Mounted Lock Directory.
> | May 15 22:02:10 pinky systemd-cryptsetup[2437]: Set cipher twofish, mode xts-essiv:wp256, key size 512 bits for device /dev/disk/by-uuid/ee5e92a6-18b6-4247-a1d8-8379b01928fb.
> | May 15 22:02:10 pinky systemd-cryptsetup[2439]: Set cipher twofish, mode xts-essiv:wp256, key size 512 bits for device /dev/disk/by-uuid/57d30bae-878a-4931-bc39-10cc18b92486.
> | May 15 22:02:10 pinky systemd-cryptsetup[2436]: Set cipher twofish, mode xts-essiv:wp256, key size 512 bits for device /dev/disk/by-uuid/b1c029d2-515b-47a1-becf-59c1f5191e43.
> | May 15 22:02:12 pinky systemd-cryptsetup[2436]: AKI DEBUG libdm:_check_udev_is_running: Udev is running. goody
>
> And then the system boots like a charm.
>
> The main difference I spot is a longer interval between starting udev
> and the udev_is_running() check.
> Also, I guess "Mounted Runtime Directory" refers to /run, where the file
> in question resides? In the "bad" case this happens in the same second
> as the cryptsetup call...

"Starting udev Control Socket." is the indication for the API the
device mapper tools use to find out if udev is running.

What is "Mounted Runtime Directory"? Is that /run? That must be part
of PID1's own early initialization, nothing to run externally.

Kay