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

Thu May 15 14:15:26 PDT 2014

-----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...

Anyway, my conclusion from this is that either the LVM guys need to
use another method to detect that udev is running, or systemd should
not start the cryptsetup stuff until udev is fully initialized.

Personally I'd be leaning towards the latter since the check looks
sensible to me, but since I'm not familiar with either I'll defer to your
judgement:

Should I open a bug for LVM or for systemd?
Or could this still be a configuration issue?

Regards,
Andy
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.22 (GNU/Linux)
Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/

iQIcBAEBCgAGBQJTdS5uAAoJED4ymUd/KFGwG0AQAI1KNp8QuyE8ca/UTWcMxHAB
N4EI1BbKaWw6KxrIcai3iXn91kqq5CxaZLjqg/ZWjflcoQfJLKnOMMQdKg6d3hkp
27UeM8OHk5MadLFK2NQnKtAAmTxuzZYpsjtmUp9dmV/MxGjQYBbP9BuovIch3JHV
aenG+MRbquG3JYj4WNATgZZtL0Aii4mANepw2pV8hLHS81y/hYYUg6GjNx5JEK6K
jkJG4CvgQCxrwpsUVTyl9pvNpAdx0zCczT/7XMqP+4Y1W1XHe5T8YVdXB52OHBnK
XRgiU3FRrtPV20SgLJgCYzoOPuFeRIijvMvg+eipGf2im2Mx+/TlpEr0j32iSjqN
qYsSNfhHG+C2aIbTBqhlaesqUOiWB8vbIRNzxXBAmQ9tFUJcMxMUcape2o0e0o6Y
vCXVjt6c4jdlUkKYPZpz5tmehvYAGx4F0FgnPUqt44Pi3kUNwLcvEp7uHhSzI5CT
Yqx0s94bw/BxX77awPZ8J5/W3DUeSQhwM3Q6BihqVi4E0tScSYeLR49Nwwy5MN7e
Oe7baSSsaNr8l4l4AL2i5xhOubtPjOGJvEMzMtzn2uSzy6xkj8iV1XmmCBexKYh2
VfoXg4MB1z3N4xsv0Z/6MYg7U/HgfLP78PD8OH10oNMdL65BHkuXNs46iIJLkv9k
cJxf/x4EBwIeyra7YS/J
=CFTb
-----END PGP SIGNATURE-----