Activation with systemd-cryptsetup on boot races with tmpfiles for lock dir creation
Finally gotten around to report this. Please see systemd/systemd
#11090 for context.
I'm not sure if this is still relevant, but I'm not seeing any significant changes in lib/utils_device_locking.[ch]
since v2.0.6 (which was packaged in Arch at the time the original bug was observed and reported). That said, from my understanding of the code in there, the original bug should not have happened at all, so I'm not sure...
It would appear that libcryptsetup (as used in systemd) depends on its lock directory (/run/cryptsetup
) being already created by systemd-tmpfiles, which is not the case for volumes activated on boot. Judging from the code, it should create the lock directory itself in open_lock_dir()
, so I'm not sure what is happening.
Log traces (available in the original issue as well):
$ LC_ALL=C journalctl -b-1 -u systemd-cryptsetup@storage1
-- Logs begin at Sat 2019-01-05 14:00:12 MSK, end at Mon 2019-01-07 19:19:40 MSK. --
Jan 07 19:09:22 stratofortress systemd-cryptsetup[324]: Set cipher aes, mode xts-plain64, key size 256 bits for device /dev/disk/by-uuid/6ff0637e-bb58-4ecb-bd0e-e1e6cb9bc7ce.
Jan 07 19:10:23 stratofortress systemd-cryptsetup[324]: Failed to acquire read lock on device /dev/disk/by-uuid/6ff0637e-bb58-4ecb-bd0e-e1e6cb9bc7ce.
Jan 07 19:10:23 stratofortress systemd-cryptsetup[324]: Failed to activate with key file '/etc/admin/keyfiles/storage1': Device or resource busy
Jan 07 19:10:55 stratofortress systemd-cryptsetup[324]: Failed to add password to keyring: Invalid argument
Jan 07 19:10:55 stratofortress systemd-cryptsetup[324]: Failed to acquire read lock on device /dev/disk/by-uuid/6ff0637e-bb58-4ecb-bd0e-e1e6cb9bc7ce.
Jan 07 19:10:55 stratofortress systemd-cryptsetup[324]: crypt_load() failed on device /dev/disk/by-uuid/6ff0637e-bb58-4ecb-bd0e-e1e6cb9bc7ce.
Jan 07 19:10:55 stratofortress systemd-cryptsetup[324]: Failed to activate: Device or resource busy
Jan 07 19:10:55 stratofortress systemd[1]: systemd-cryptsetup@storage1.service: Main process exited, code=exited, status=1/FAILURE
Jan 07 19:10:55 stratofortress systemd[1]: systemd-cryptsetup@storage1.service: Failed with result 'exit-code'.
Jan 07 19:10:55 stratofortress systemd[1]: Failed to start Cryptography Setup for storage1.
Jan 07 19:10:55 stratofortress systemd[1]: systemd-cryptsetup@storage1.service: Consumed 6.286s CPU time, received 0B IP traffic, sent 0B IP traffic
$ LC_ALL=C journalctl -b-1 -u systemd-cryptsetup@storage2
-- Logs begin at Sat 2019-01-05 14:00:12 MSK, end at Mon 2019-01-07 19:20:12 MSK. --
Jan 07 19:09:22 stratofortress systemd-cryptsetup[326]: WARNING: Locking directory /run/cryptsetup is missing!
Jan 07 19:09:22 stratofortress systemd-cryptsetup[326]: Set cipher aes, mode xts-plain64, key size 256 bits for device /dev/disk/by-uuid/19a4f5a6-7ef9-4b76-ae95-bc2c4f03d8fe.
Jan 07 19:10:23 stratofortress systemd-cryptsetup[326]: Failed to acquire read lock on device /dev/disk/by-uuid/19a4f5a6-7ef9-4b76-ae95-bc2c4f03d8fe.
Jan 07 19:10:23 stratofortress systemd-cryptsetup[326]: Failed to activate with key file '/etc/admin/keyfiles/storage2': Device or resource busy
Jan 07 19:10:23 stratofortress systemd[1]: systemd-cryptsetup@storage2.service: Main process exited, code=killed, status=15/TERM
Jan 07 19:10:23 stratofortress systemd[1]: systemd-cryptsetup@storage2.service: Failed with result 'signal'.
Jan 07 19:10:23 stratofortress systemd[1]: Stopped Cryptography Setup for storage2.
Jan 07 19:10:23 stratofortress systemd[1]: systemd-cryptsetup@storage2.service: Consumed 6.476s CPU time, received 0B IP traffic, sent 0B IP traffic
Jan 07 19:11:53 stratofortress systemd[1]: Dependency failed for Cryptography Setup for storage2.
Jan 07 19:11:53 stratofortress systemd[1]: systemd-cryptsetup@storage2.service: Job systemd-cryptsetup@storage2.service/start failed with result 'dependency'.
$ LC_ALL=C journalctl -b-1 -u systemd-cryptsetup@storage3
-- Logs begin at Sat 2019-01-05 14:00:12 MSK, end at Mon 2019-01-07 19:20:43 MSK. --
Jan 07 19:09:22 stratofortress systemd-cryptsetup[325]: Set cipher aes, mode xts-plain64, key size 256 bits for device /dev/disk/by-uuid/4781976a-58b9-40ad-b490-d7269304b56a.
Jan 07 19:10:23 stratofortress systemd-cryptsetup[325]: Failed to acquire read lock on device /dev/disk/by-uuid/4781976a-58b9-40ad-b490-d7269304b56a.
Jan 07 19:10:23 stratofortress systemd-cryptsetup[325]: Failed to activate with key file '/etc/admin/keyfiles/storage3': Device or resource busy
Jan 07 19:10:23 stratofortress systemd[1]: systemd-cryptsetup@storage3.service: Main process exited, code=killed, status=15/TERM
Jan 07 19:10:23 stratofortress systemd[1]: systemd-cryptsetup@storage3.service: Failed with result 'signal'.
Jan 07 19:10:23 stratofortress systemd[1]: Stopped Cryptography Setup for storage3.
Jan 07 19:10:23 stratofortress systemd[1]: systemd-cryptsetup@storage3.service: Consumed 6.566s CPU time, received 0B IP traffic, sent 0B IP traffic
Jan 07 19:11:53 stratofortress systemd[1]: Dependency failed for Cryptography Setup for storage3.
Jan 07 19:11:53 stratofortress systemd[1]: systemd-cryptsetup@storage3.service: Job systemd-cryptsetup@storage3.service/start failed with result 'dependency'.
$ LC_ALL=C journalctl -b-1 -u systemd-cryptsetup@storage4
-- Logs begin at Sat 2019-01-05 14:00:12 MSK, end at Mon 2019-01-07 19:20:57 MSK. --
Jan 07 19:09:22 stratofortress systemd-cryptsetup[327]: Set cipher aes, mode xts-plain64, key size 256 bits for device /dev/disk/by-uuid/dfdac573-0f19-40eb-ad29-1d0a6599b222.
Jan 07 19:10:23 stratofortress systemd-cryptsetup[327]: Failed to acquire read lock on device /dev/disk/by-uuid/dfdac573-0f19-40eb-ad29-1d0a6599b222.
Jan 07 19:10:23 stratofortress systemd-cryptsetup[327]: Failed to activate with key file '/etc/admin/keyfiles/storage4': Device or resource busy
Jan 07 19:10:55 stratofortress systemd-cryptsetup[327]: Failed to add password to keyring: Invalid argument
Jan 07 19:10:55 stratofortress systemd-cryptsetup[327]: Failed to acquire read lock on device /dev/disk/by-uuid/dfdac573-0f19-40eb-ad29-1d0a6599b222.
Jan 07 19:10:55 stratofortress systemd-cryptsetup[327]: crypt_load() failed on device /dev/disk/by-uuid/dfdac573-0f19-40eb-ad29-1d0a6599b222.
Jan 07 19:10:55 stratofortress systemd-cryptsetup[327]: Failed to activate: Device or resource busy
Jan 07 19:10:55 stratofortress systemd[1]: systemd-cryptsetup@storage4.service: Main process exited, code=exited, status=1/FAILURE
Jan 07 19:10:55 stratofortress systemd[1]: systemd-cryptsetup@storage4.service: Failed with result 'exit-code'.
Jan 07 19:10:55 stratofortress systemd[1]: systemd-cryptsetup@storage4.service: Consumed 6.473s CPU time, received 0B IP traffic, sent 0B IP traffic
Jan 07 19:11:53 stratofortress systemd[1]: Dependency failed for Cryptography Setup for storage4.
Jan 07 19:11:53 stratofortress systemd[1]: systemd-cryptsetup@storage4.service: Job systemd-cryptsetup@storage4.service/start failed with result 'dependency'.
Unfortunately there's no debug logging from libcryptsetup itself because (as I've just noticed) systemd-cryptsetup does not enable debug logging in libcryptsetup even if overall debug logging is requested. If you need debug traces, I'll patch it around and attempt to reproduce the problem again.