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

[Andy Kittner]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA512


Hi all,

first I hope I'm asking at the right place here, if not feel free to
kick me in the right direction.

Now, for my problem:

I have several encrypted partions set up via /etc/crypttab
Since the update to systemd-212 (from 207 I think) the following happens

- - Oh, here is a partition from crypttab, lets uncrypt it
- - Crypto for /home done
- - Hey, this block device for /home just turned up, lets fsck it
- - Stopping crypto for /home (WTF? why would you do that?)
- - Surprise fsck'ing the home partition failed because the device just
  disappeared

I'm pretty sure it is some kind of race-condition/ timing problem,
because about 1 in 10 boots works just fine.
Also, the same setup worked fine before.

I've been kind of living with this for a while now (login at the
admin-shell and systemctl isolate default.target --> system goes up
normally) because I was to lazy to dig through the logs, but today I
finally got fed up enough with it to get of my lazy but.


Sadly the logs didn't tell me much of *why* things happen the way they
do, so maybe someone here as an idea how to investigate this further.

These are the relevant parts of the log:
| May 13 18:50:31 pinky systemd[1]: Received SIGCHLD from PID 2647
(systemd-cryptse).
| May 13 18:50:31 pinky systemd[1]: Child 2647 (systemd-cryptse) died
(code=exited, status=0/SUCCESS)
| May 13 18:50:31 pinky systemd[1]: Child 2647 belongs to
systemd-cryptsetup at swap.service
| May 13 18:50:31 pinky systemd[1]: systemd-cryptsetup at swap.service:
main process exited, code=exited, status=0/SUCCESS
| May 13 18:50:31 pinky systemd[1]: systemd-cryptsetup at swap.service
changed start -> exited
| May 13 18:50:31 pinky systemd[1]: Job
systemd-cryptsetup at swap.service/start finished, result=done
| May 13 18:50:31 pinky systemd[1]: Started Cryptography Setup for swap.
| May 13 18:50:31 pinky systemd[1]: systemd-cryptsetup at swap.service:
cgroup is empty
| May 13 18:50:33 pinky systemd-udevd[2751]: conflicting device node
'/dev/mapper/swap' found, link to '/dev/dm-1' will not be created
Thats the first one I find a bit fishy, but it doesn't sound fatal
either...

| May 13 18:50:33 pinky systemd[1]: dev-mapper-swap.device changed
dead -> plugged
| May 13 18:50:33 pinky systemd[1]: Job dev-mapper-swap.device/start
finished, result=done
| May 13 18:50:33 pinky systemd[1]: Found device /dev/mapper/swap.
| May 13 18:50:33 pinky systemd[1]:
dev-disk-by\x2duuid-e51117ad\x2db39b\x2d4ca3\x2da3cf\x2d81016a3b0190.device
changed dead -> plugged
| May 13 18:50:33 pinky systemd[1]: Job
dev-disk-by\x2duuid-e51117ad\x2db39b\x2d4ca3\x2da3cf\x2d81016a3b0190.device/start
finished, result=done
| May 13 18:50:33 pinky systemd[1]: Found device
/dev/disk/by-uuid/e51117ad-b39b-4ca3-a3cf-81016a3b0190.
| May 13 18:50:33 pinky systemd[1]:
dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2db1c029d2515b47a1becf59c1f5191e43\x2dswap.device
changed dead -> plugged
| May 13 18:50:33 pinky systemd[1]:
dev-disk-by\x2did-dm\x2dname\x2dswap.device changed dead -> plugged
| May 13 18:50:33 pinky systemd[1]: dev-dm\x2d1.device changed dead ->
plugged
| May 13 18:50:33 pinky systemd[1]:
sys-devices-virtual-block-dm\x2d1.device changed dead -> plugged
So far, so good

| May 13 18:50:33 pinky systemd[1]: dev-mapper-swap.device changed
plugged -> dead
And here I think is the root of my problem, but I have no idea what
causes this or how to get more information about that,

| May 13 18:50:33 pinky systemd[1]: Trying to enqueue job
systemd-cryptsetup at swap.service/stop/replace
| May 13 18:50:33 pinky systemd[1]: Installed new job
systemd-cryptsetup at swap.service/stop as 282
| May 13 18:50:33 pinky systemd[1]: Job cryptsetup.target/start
finished, result=canceled
| May 13 18:50:33 pinky systemd[1]: Installed new job
cryptsetup.target/stop as 283
| May 13 18:50:33 pinky systemd[1]: Enqueued job
systemd-cryptsetup at swap.service/stop as 282
| May 13 18:50:33 pinky systemd[1]:
dev-disk-by\x2duuid-e51117ad\x2db39b\x2d4ca3\x2da3cf\x2d81016a3b0190.device
changed plugged -> dead
| May 13 18:50:33 pinky systemd[1]:
dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2db1c029d2515b47a1becf59c1f5191e43\x2dswap.device
changed plugged -> dead
| May 13 18:50:33 pinky systemd[1]:
dev-disk-by\x2did-dm\x2dname\x2dswap.device changed plugged -> dead
| May 13 18:50:33 pinky systemd[1]: dev-dm\x2d1.device changed plugged
- -> dead
| May 13 18:50:33 pinky systemd[1]:
sys-devices-virtual-block-dm\x2d1.device changed plugged -> dead
| May 13 18:50:33 pinky systemd[1]: Collecting
sys-devices-virtual-block-dm\x2d1.device
| May 13 18:50:33 pinky systemd[1]: Collecting dev-dm\x2d1.device
| May 13 18:50:33 pinky systemd[1]: Collecting
dev-disk-by\x2did-dm\x2dname\x2dswap.device
| May 13 18:50:33 pinky systemd[1]: Collecting
dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2db1c029d2515b47a1becf59c1f5191e43\x2dswap.device
| May 13 18:50:33 pinky systemd[1]: Stopped target Encrypted Volumes.
| May 13 18:50:33 pinky systemd[1]: Stopping Cryptography Setup for
swap...
| May 13 18:50:33 pinky systemd[1]: About to execute:
/usr/lib/systemd/systemd-cryptsetup detach swap
| May 13 18:50:33 pinky systemd[1]: Forked
/usr/lib/systemd/systemd-cryptsetup as 2903
| May 13 18:50:33 pinky systemd[1]: systemd-cryptsetup at swap.service
changed exited -> stop
So much for our nice uncrypted block device :(

| May 13 18:50:33 pinky systemd[1]: Activating swap
/dev/disk/by-uuid/e51117ad-b39b-4ca3-a3cf-81016a3b0190...
| May 13 18:50:33 pinky systemd[2903]: Executing:
/usr/lib/systemd/systemd-cryptsetup detach swap
| May 13 18:50:33 pinky systemd[1]: About to execute: /sbin/swapon
/dev/disk/by-uuid/e51117ad-b39b-4ca3-a3cf-81016a3b0190
| May 13 18:50:33 pinky systemd[1]: Forked /sbin/swapon as 2904
| May 13 18:50:33 pinky systemd[1]:
dev-disk-by\x2duuid-e51117ad\x2db39b\x2d4ca3\x2da3cf\x2d81016a3b0190.swap
changed dead -> activating
| May 13 18:50:33 pinky systemd[2904]: Executing: /sbin/swapon
/dev/disk/by-uuid/e51117ad-b39b-4ca3-a3cf-81016a3b0190
| May 13 18:50:33 pinky swapon[2904]: swapon: stat failed
/dev/disk/by-uuid/e51117ad-b39b-4ca3-a3cf-81016a3b0190: No such file
or directory
And now swapon is unhappy because it's block device ran away, same thing
happens with other partitions and fsck


Additional information:
The system is running Gentoo, the root partition is also crypted and
unlocked via an initrd (genkernel-next generated, uses udev)
The kernel is a self-compiled vanilla 3.14.2


So, does anyone have an idea on what I could try to get to the bottom of
this?


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

iQIcBAEBCgAGBQJTcl3xAAoJED4ymUd/KFGwoEwP/jWXKJyVkd0uO5gVARsbrAun
mfPxF56wMZBpObVIHkDReSgO+VxuHJ32R2OjUPwKu9VK+W+ks85oz2u5JdP4Hjq1
8O/tCztT2C0bPH5g6h/gY7QRxhGCDn9XdNqE4TNcYASsV4tGS5dwAhPMprdTpxeQ
YqjneIKW97ExucDsFVwFUTaNXSlZXjFqm2uVD6f60la2Bo0pp9pBoIBojRFH7rc5
0vk7z6BThlP4Q/s9JY4BlziFT2/0f0xacBnCC2TlympnxNMnpwTl0K+tKA5LXgqJ
eZZpBt0xYtUjMYgjGhrqVVR2RFwWZDrdGCFmL7hjRV23VkL5hc2+k5alLmFLAcLp
3vYTl1Lm5KxIl9vdljHrYdsqeSus/soKJYORL2BYNqgO0DxE78fSkwT0Hby3Xj85
vKY02Zr1xcYOdvH4xLsSQVdPqBehjFCiVoUvrmtw1HViYhblds+3vESYDCRMXAkf
MlrDg+qvCHVDzyDSW5zFZaXpY78CremfJNs7+Obs3C48UUtSNEuR083KPAbb2MVV
HOOLFsGzfiX3vgGQNf7+IDLABh6nbltSNDwxWOgMd12hUqzc4tx2E98hAplYgxW8
3VypcHnDqa9KbS3ozcmYl6jpp5Csw3U8hMnsgMyaz2Xg9fWY0jU9ZxqwPM5K3Y3e
5WpUGps+VGrdqQtuCIYu
=3e7G
-----END PGP SIGNATURE-----