[systemd-devel] Race condition in a chain of external drive, cryptsetup, mount, and mount-bound service on unplug.
Arsenii Skvortsov
ettavolt at gmail.com
Thu Jun 1 00:20:50 UTC 2023
Hello!
Sorry, I think I've sent this initially during Spring break and it didn't get anyone's attention. ☺
I'd still like to hear your opinions.
I have a service in a form of a python script to copy OS profile to a LUKS-encrypted external drive on service stop and
restore from it back on service start. (If anyone is interested, this btrfs-progs
test: https://gist.github.com/ettavolt/b9e94c36a483f6045339c33fd90ce2e8 - might give an idea of the flow)
The service (backup-ask-rbr.service in the logs I'll attach below) is hooked to device connection via udev by adding
SYSTEMD_WANTS device property.
However, there is a race condition when I unplug the drive (e.g. to come with a laptop to a meeting).
1. disk-by-<…>.device is stopped (because unplugged).
2. systemd-cryptsetup@<…>.service is stopped, because it BindsTo=disk-by-<…>.device.
2.1. Fails, because drive is still mounted.
3. Service is stopped, because it BindsTo=<…>.mount, and that has stop propagated from blockdev at dev-mapper-<…>.target.
3.1. Fails, because IO can not go to device.
4. <…>.mount is unmounted.
4.1. Succeeds.
Note, that /dev/mapper/<name> is still there.
Now, when I plug the drive back, systemd tries to activate the main service (due to SYSTEMD_WANTS). Service
BindsTo=<…>.mount, so systemd goes to activate the mount. Mount sees /dev/mapper/<name>, doesn't activate systemd-
cryptsetup@<…>.service, fails. Consequently, the main service fails to start too.
BTW, /dev/sdc seems to be occupied, so the drive gets /dev/sdd (but that's not a problem for cryptsetup&mounts per se).
Things can get up properly on replug if I manually issue cryptsetup close <…> before plugging.
I've solved this race by adding overrides to <…>.mount and blockdev at dev-mapper-<…>.target so that the former
BindsTo=blockdev at dev-mapper-<…>.target and the latter BindsTo=systemd-cryptsetup@<…>.service. With that, things are
properly ordered on unplug:
1. disk-by-<…>.device is stopped (because unplugged).
2. Stop propagates through systemd-cryptsetup@<…>.service, blockdev at dev-mapper-<…>.target, <…>.mount to the main
service.
2.1. Fails to properly stop because of IO failure.
3. <…>.mount successfully unmounts (nothing tries IO).
4. systemd-cryptsetup@<…>.service successfully closes, because unmounted.
And units get up without manual interaction on plug.
What do you think about making systemd-fstab-generator to write BindsTo=blockdev@<…>.target instead of just Requires=,
and also somehow make sure that systemd-cryptsetup@<…>.service is BoundBy blockdev at dev-mapper-<…>.target?
Attached are statuses of device, crypt, mount, and service units after various actions, the units themselves (without
overrides), and journal excerpts after unplugging (with and without overrides).
Thanks
-------------- next part --------------
● dev-sdc.device - PSSD_T7
Follows: unit currently follows state of sys-devices-pci0000:00-0000:00:0d.0-usb3-3\x2d1-3\x2d1:1.0-host4-target4:0:0-4:0:0:0-block-sdc.device
Loaded: loaded
Active: active (plugged) since Fri 2023-04-07 11:32:57 EDT; 11s ago
Device: /sys/devices/pci0000:00/0000:00:0d.0/usb3/3-1/3-1:1.0/host4/target4:0:0/4:0:0:0/block/sdc
Apr 07 11:32:57 ptits-lt systemd[1]: Condition check resulted in PSSD_T7 being skipped.
● systemd-cryptsetup at rbrssd.service - Cryptography Setup for rbrssd
Loaded: loaded (/etc/crypttab; generated)
Active: active (exited) since Fri 2023-04-07 11:32:59 EDT; 9s ago
Docs: man:crypttab(5)
man:systemd-cryptsetup-generator(8)
man:systemd-cryptsetup at .service(8)
Process: 2753 ExecStart=/usr/lib/systemd/systemd-cryptsetup attach rbrssd /dev/disk/by-uuid/000db593-5c9b-492e-b100-3596d955701b - luks,discard,nofail (code=exited, status=0/SUCCESS)
Main PID: 2753 (code=exited, status=0/SUCCESS)
CPU: 7.486s
Apr 07 11:32:57 ptits-lt systemd[1]: Starting Cryptography Setup for rbrssd...
Apr 07 11:32:57 ptits-lt systemd-cryptsetup[2753]: Set cipher aes, mode xts-plain64, key size 512 bits for device /dev/disk/by-uuid/000db593-5c9b-492e-b100-3596d955701b.
Apr 07 11:32:59 ptits-lt systemd[1]: Finished Cryptography Setup for rbrssd.
● run-rbrssd.mount - /run/rbrssd
Loaded: loaded (/etc/fstab; generated)
Active: active (mounted) since Fri 2023-04-07 11:32:59 EDT; 9s ago
Where: /run/rbrssd
What: /dev/mapper/rbrssd
Docs: man:fstab(5)
man:systemd-fstab-generator(8)
Tasks: 0 (limit: 76832)
Memory: 872.0K
CPU: 4ms
CGroup: /system.slice/run-rbrssd.mount
Apr 07 11:32:59 ptits-lt systemd[1]: Mounting /run/rbrssd...
Apr 07 11:32:59 ptits-lt systemd[1]: Mounted /run/rbrssd.
● backup-ask-rbr.service - Sync ask-rbr with external drive on start and stop.
Loaded: loaded (/etc/systemd/system/backup-ask-rbr.service; static)
Active: active (exited) since Fri 2023-04-07 11:32:59 EDT; 9s ago
Process: 2953 ExecStart=/run/rbrssd/snapshot.py start (code=exited, status=0/SUCCESS)
Main PID: 2953 (code=exited, status=0/SUCCESS)
CPU: 19ms
Apr 07 11:32:59 ptits-lt systemd[1]: Starting Sync ask-rbr with external drive on start and stop....
Apr 07 11:32:59 ptits-lt systemd[1]: Finished Sync ask-rbr with external drive on start and stop..
-------------- next part --------------
023-04-07T11:31:30.306557-0400 ptits-lt kernel: usb 3-1: USB disconnect, device number 2
2023-04-07T11:31:30.390563-0400 ptits-lt systemd[1]: Stopping Sync ask-rbr with external drive on start and stop....
2023-04-07T11:31:30.392608-0400 ptits-lt systemd[1]: Stopping Cryptography Setup for rbrssd...
2023-04-07T11:31:30.398536-0400 ptits-lt systemd-cryptsetup[2528]: Underlying device for crypt device rbrssd disappeared.
2023-04-07T11:31:30.398699-0400 ptits-lt systemd-cryptsetup[2528]: Device rbrssd is still in use.
2023-04-07T11:31:30.398703-0400 ptits-lt systemd-cryptsetup[2528]: Failed to deactivate: Device or resource busy
2023-04-07T11:31:30.399122-0400 ptits-lt systemd[1]: systemd-cryptsetup at rbrssd.service: Control process exited, code=exited, status=1/FAILURE
2023-04-07T11:31:30.399327-0400 ptits-lt systemd[1]: systemd-cryptsetup at rbrssd.service: Failed with result 'exit-code'.
2023-04-07T11:31:30.413224-0400 ptits-lt kernel: sd 4:0:0:0: [sdc] Synchronizing SCSI cache
2023-04-07T11:31:30.430151-0400 ptits-lt systemd[1]: Stopped Cryptography Setup for rbrssd.
2023-04-07T11:31:30.433205-0400 ptits-lt snapshot.py[2529]: Create a readonly snapshot of '/home/ask-rbr' in '/home/.ask-rbr-snapshots/@2023-04-07T11'
2023-04-07T11:31:30.437904-0400 ptits-lt snapshot.py[2531]: At subvol /home/.ask-rbr-snapshots/@2023-04-07T11
2023-04-07T11:31:30.500056-0400 ptits-lt snapshot.py[2532]: ERROR: creating snapshot ask-arch-profile/@2023-04-06T13 -> @2023-04-07T11 failed: Input/output error
2023-04-07T11:31:30.500292-0400 ptits-lt snapshot.py[2532]: At snapshot @2023-04-07T11
2023-04-07T11:31:30.501630-0400 ptits-lt snapshot.py[2527]: Traceback (most recent call last):
2023-04-07T11:31:30.501630-0400 ptits-lt snapshot.py[2527]: File "/run/rbrssd/snapshot.py", line 51, in <module>
2023-04-07T11:31:30.501890-0400 ptits-lt snapshot.py[2527]: run([
2023-04-07T11:31:30.501890-0400 ptits-lt snapshot.py[2527]: File "/usr/lib/python3.10/subprocess.py", line 526, in run
2023-04-07T11:31:30.501991-0400 ptits-lt snapshot.py[2527]: raise CalledProcessError(retcode, process.args,
2023-04-07T11:31:30.502028-0400 ptits-lt snapshot.py[2527]: subprocess.CalledProcessError: Command '['sh', '-c', 'btrfs send -p /home/.ask-rbr-snapshots/@2023-04-06T13 /home/.ask-rbr-snapshots/@2023-04-07T11 | btrfs receive />
2023-04-07T11:31:30.503208-0400 ptits-lt kernel: BTRFS error (device dm-2: state A): Transaction aborted (error -5)
2023-04-07T11:31:30.503243-0400 ptits-lt kernel: BTRFS: error (device dm-2: state A) in add_to_free_space_tree:1056: errno=-5 IO failure
2023-04-07T11:31:30.503910-0400 ptits-lt kernel: BTRFS info (device dm-2: state EA): forced readonly
2023-04-07T11:31:30.505669-0400 ptits-lt kernel: BTRFS: error (device dm-2: state EA) in do_free_extent_accounting:2854: errno=-5 IO failure
2023-04-07T11:31:30.505733-0400 ptits-lt kernel: BTRFS error (device dm-2: state EA): failed to run delayed ref for logical 22544384 num_bytes 16384 type 176 action 2 ref_mod 1: -5
2023-04-07T11:31:30.505789-0400 ptits-lt kernel: BTRFS: error (device dm-2: state EA) in btrfs_run_delayed_refs:2151: errno=-5 IO failure
2023-04-07T11:31:30.505849-0400 ptits-lt kernel: BTRFS warning (device dm-2: state EA): Skipping commit of aborted transaction.
2023-04-07T11:31:30.505907-0400 ptits-lt kernel: BTRFS: error (device dm-2: state EA) in cleanup_transaction:1984: errno=-5 IO failure
2023-04-07T11:31:30.509774-0400 ptits-lt systemd[1]: backup-ask-rbr.service: Control process exited, code=exited, status=1/FAILURE
2023-04-07T11:31:30.509996-0400 ptits-lt systemd[1]: backup-ask-rbr.service: Failed with result 'exit-code'.
2023-04-07T11:31:30.546788-0400 ptits-lt systemd[1]: Stopped Sync ask-rbr with external drive on start and stop..
2023-04-07T11:31:30.567031-0400 ptits-lt systemd[1]: Unmounting /run/rbrssd...
2023-04-07T11:31:30.573148-0400 ptits-lt kernel: sd 4:0:0:0: [sdc] Synchronize Cache(10) failed: Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
2023-04-07T11:31:30.574020-0400 ptits-lt systemd[1]: run-rbrssd.mount: Deactivated successfully.
2023-04-07T11:31:30.614847-0400 ptits-lt dbus-daemon[636]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service' requested by ':1.101' (uid=124 pid=2541 comm="/usr/lib>
2023-04-07T11:31:30.633533-0400 ptits-lt systemd[1]: Unmounted /run/rbrssd.
2023-04-07T11:31:30.634122-0400 ptits-lt systemd[1]: Stopped target Block Device Preparation for /dev/mapper/rbrssd.
2023-04-07T11:31:30.634164-0400 ptits-lt systemd[1]: systemd-fsck at dev-mapper-rbrssd.service: Deactivated successfully.
2023-04-07T11:31:30.634440-0400 ptits-lt dbus-daemon[636]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.Avahi.service not found.
2023-04-07T11:31:30.663356-0400 ptits-lt systemd[1]: Stopped File System Check on /dev/mapper/rbrssd.
-------------- next part --------------
2023-04-07T11:44:56.089744-0400 ptits-lt kernel: usb 3-1: USB disconnect, device number 4
2023-04-07T11:44:56.150535-0400 ptits-lt systemd[1]: Stopping Sync ask-rbr with external drive on start and stop....
2023-04-07T11:44:56.173076-0400 ptits-lt kernel: sd 4:0:0:0: [sdc] Synchronizing SCSI cache
2023-04-07T11:44:56.197018-0400 ptits-lt snapshot.py[4430]: Create a readonly snapshot of '/home/ask-rbr' in '/home/.ask-rbr-snapshots/@2023-04-07T11:44'
2023-04-07T11:44:56.200681-0400 ptits-lt snapshot.py[4432]: At subvol /home/.ask-rbr-snapshots/@2023-04-07T11:44
2023-04-07T11:44:56.266632-0400 ptits-lt snapshot.py[4433]: ERROR: creating snapshot ask-arch-profile/@2023-04-06T13 -> @2023-04-07T11:44 failed: Input/output error
2023-04-07T11:44:56.266632-0400 ptits-lt snapshot.py[4433]: At snapshot @2023-04-07T11:44
2023-04-07T11:44:56.267337-0400 ptits-lt snapshot.py[4429]: Traceback (most recent call last):
2023-04-07T11:44:56.267337-0400 ptits-lt snapshot.py[4429]: File "/run/rbrssd/snapshot.py", line 51, in <module>
2023-04-07T11:44:56.267527-0400 ptits-lt snapshot.py[4429]: run([
2023-04-07T11:44:56.267527-0400 ptits-lt snapshot.py[4429]: File "/usr/lib/python3.10/subprocess.py", line 526, in run
2023-04-07T11:44:56.267581-0400 ptits-lt snapshot.py[4429]: raise CalledProcessError(retcode, process.args,
2023-04-07T11:44:56.267602-0400 ptits-lt snapshot.py[4429]: subprocess.CalledProcessError: Command '['sh', '-c', 'btrfs send -p /home/.ask-rbr-snapshots/@2023-04-06T13 /home/.ask-rbr-snapshots/@2023-04-07T11:44 | btrfs receiv>
2023-04-07T11:44:56.269811-0400 ptits-lt kernel: BTRFS error (device dm-2: state A): Transaction aborted (error -5)
2023-04-07T11:44:56.269854-0400 ptits-lt kernel: BTRFS: error (device dm-2: state A) in add_to_free_space_tree:1056: errno=-5 IO failure
2023-04-07T11:44:56.269898-0400 ptits-lt kernel: BTRFS info (device dm-2: state EA): forced readonly
2023-04-07T11:44:56.269969-0400 ptits-lt kernel: BTRFS: error (device dm-2: state EA) in do_free_extent_accounting:2854: errno=-5 IO failure
2023-04-07T11:44:56.269999-0400 ptits-lt kernel: BTRFS error (device dm-2: state EA): failed to run delayed ref for logical 22544384 num_bytes 16384 type 176 action 2 ref_mod 1: -5
2023-04-07T11:44:56.270106-0400 ptits-lt kernel: BTRFS: error (device dm-2: state EA) in btrfs_run_delayed_refs:2151: errno=-5 IO failure
2023-04-07T11:44:56.270135-0400 ptits-lt kernel: BTRFS warning (device dm-2: state EA): Skipping commit of aborted transaction.
2023-04-07T11:44:56.270181-0400 ptits-lt kernel: BTRFS: error (device dm-2: state EA) in cleanup_transaction:1984: errno=-5 IO failure
2023-04-07T11:44:56.270801-0400 ptits-lt systemd[1]: backup-ask-rbr.service: Control process exited, code=exited, status=1/FAILURE
2023-04-07T11:44:56.271030-0400 ptits-lt systemd[1]: backup-ask-rbr.service: Failed with result 'exit-code'.
2023-04-07T11:44:56.306751-0400 ptits-lt systemd[1]: Stopped Sync ask-rbr with external drive on start and stop..
2023-04-07T11:44:56.340586-0400 ptits-lt systemd[1]: Unmounting /run/rbrssd...
2023-04-07T11:44:56.346501-0400 ptits-lt systemd[1]: run-rbrssd.mount: Deactivated successfully.
2023-04-07T11:44:56.363219-0400 ptits-lt kernel: sd 4:0:0:0: [sdc] Synchronize Cache(10) failed: Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
2023-04-07T11:44:56.399918-0400 ptits-lt systemd[1]: Unmounted /run/rbrssd.
2023-04-07T11:44:56.400225-0400 ptits-lt systemd[1]: Stopped target Block Device Preparation for /dev/mapper/rbrssd.
2023-04-07T11:44:56.400870-0400 ptits-lt systemd[1]: Stopping Cryptography Setup for rbrssd...
2023-04-07T11:44:56.400885-0400 ptits-lt systemd[1]: systemd-fsck at dev-mapper-rbrssd.service: Deactivated successfully.
2023-04-07T11:44:56.403841-0400 ptits-lt systemd-cryptsetup[4449]: Underlying device for crypt device rbrssd disappeared.
2023-04-07T11:44:56.406383-0400 ptits-lt kernel: dm-2: detected capacity change from 976740400 to 0
2023-04-07T11:44:56.409930-0400 ptits-lt dbus-daemon[636]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service' requested by ':1.136' (uid=124 pid=4443 comm="/usr/lib>
2023-04-07T11:44:56.446906-0400 ptits-lt systemd[1]: Stopped File System Check on /dev/mapper/rbrssd.
2023-04-07T11:44:56.448415-0400 ptits-lt dbus-daemon[636]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.Avahi.service': Unit dbus-org.freedesktop.Avahi.service not found.
2023-04-07T11:44:56.453115-0400 ptits-lt systemd[1]: systemd-cryptsetup at rbrssd.service: Deactivated successfully.
2023-04-07T11:44:56.493245-0400 ptits-lt systemd[1]: Stopped Cryptography Setup for rbrssd.
-------------- next part --------------
● dev-sdc.device - PSSD_T7
Follows: unit currently follows state of sys-devices-pci0000:00-0000:00:0d.0-usb3-3\x2d1-3\x2d1:1.0-host4-target4:0:0-4:0:0:0-block-sdc.device
Loaded: loaded
Active: active (plugged) since Fri 2023-04-07 11:31:16 EDT; 9s ago
Device: /sys/devices/pci0000:00/0000:00:0d.0/usb3/3-1/3-1:1.0/host4/target4:0:0/4:0:0:0/block/sdc
● systemd-cryptsetup at rbrssd.service - Cryptography Setup for rbrssd
Loaded: loaded (/etc/crypttab; generated)
Active: active (exited) since Fri 2023-04-07 11:31:19 EDT; 7s ago
Docs: man:crypttab(5)
man:systemd-cryptsetup-generator(8)
man:systemd-cryptsetup at .service(8)
Process: 2301 ExecStart=/usr/lib/systemd/systemd-cryptsetup attach rbrssd /dev/disk/by-uuid/000db593-5c9b-492e-b100-3596d955701b - luks,discard,nofail (code=exited, status=0/SUCCESS)
Main PID: 2301 (code=exited, status=0/SUCCESS)
CPU: 7.474s
Apr 07 11:31:16 ptits-lt systemd[1]: Starting Cryptography Setup for rbrssd...
Apr 07 11:31:16 ptits-lt systemd-cryptsetup[2301]: Set cipher aes, mode xts-plain64, key size 512 bits for device /dev/disk/by-uuid/000db593-5c9b-492e-b100-3596d955701b.
Apr 07 11:31:19 ptits-lt systemd[1]: Finished Cryptography Setup for rbrssd.
● run-rbrssd.mount - /run/rbrssd
Loaded: loaded (/etc/fstab; generated)
Active: active (mounted) since Fri 2023-04-07 11:31:19 EDT; 7s ago
Where: /run/rbrssd
What: /dev/mapper/rbrssd
Docs: man:fstab(5)
man:systemd-fstab-generator(8)
Tasks: 0 (limit: 76832)
Memory: 868.0K
CPU: 3ms
CGroup: /system.slice/run-rbrssd.mount
Apr 07 11:31:19 ptits-lt systemd[1]: Mounting /run/rbrssd...
Apr 07 11:31:19 ptits-lt systemd[1]: Mounted /run/rbrssd.
● backup-ask-rbr.service - Sync ask-rbr with external drive on start and stop.
Loaded: loaded (/etc/systemd/system/backup-ask-rbr.service; static)
Active: active (exited) since Fri 2023-04-07 11:31:19 EDT; 7s ago
Process: 2501 ExecStart=/run/rbrssd/snapshot.py start (code=exited, status=0/SUCCESS)
Main PID: 2501 (code=exited, status=0/SUCCESS)
CPU: 20ms
Apr 07 11:31:19 ptits-lt systemd[1]: Starting Sync ask-rbr with external drive on start and stop....
Apr 07 11:31:19 ptits-lt systemd[1]: Finished Sync ask-rbr with external drive on start and stop..
-------------- next part --------------
○ dev-sdc.device - /dev/sdc
Loaded: loaded
Active: inactive (dead)
× systemd-cryptsetup at rbrssd.service - Cryptography Setup for rbrssd
Loaded: loaded (/etc/crypttab; generated)
Active: failed (Result: exit-code) since Fri 2023-04-07 11:31:30 EDT; 27s ago
Duration: 11.342s
Docs: man:crypttab(5)
man:systemd-cryptsetup-generator(8)
man:systemd-cryptsetup at .service(8)
Process: 2301 ExecStart=/usr/lib/systemd/systemd-cryptsetup attach rbrssd /dev/disk/by-uuid/000db593-5c9b-492e-b100-3596d955701b - luks,discard,nofail (code=exited, status=0/SUCCESS)
Process: 2528 ExecStop=/usr/lib/systemd/systemd-cryptsetup detach rbrssd (code=exited, status=1/FAILURE)
Main PID: 2301 (code=exited, status=0/SUCCESS)
CPU: 6ms
Apr 07 11:31:16 ptits-lt systemd[1]: Starting Cryptography Setup for rbrssd...
Apr 07 11:31:16 ptits-lt systemd-cryptsetup[2301]: Set cipher aes, mode xts-plain64, key size 512 bits for device /dev/disk/by-uuid/000db593-5c9b-492e-b100-3596d955701b.
Apr 07 11:31:19 ptits-lt systemd[1]: Finished Cryptography Setup for rbrssd.
Apr 07 11:31:30 ptits-lt systemd[1]: Stopping Cryptography Setup for rbrssd...
Apr 07 11:31:30 ptits-lt systemd-cryptsetup[2528]: Underlying device for crypt device rbrssd disappeared.
Apr 07 11:31:30 ptits-lt systemd-cryptsetup[2528]: Device rbrssd is still in use.
Apr 07 11:31:30 ptits-lt systemd-cryptsetup[2528]: Failed to deactivate: Device or resource busy
Apr 07 11:31:30 ptits-lt systemd[1]: systemd-cryptsetup at rbrssd.service: Control process exited, code=exited, status=1/FAILURE
Apr 07 11:31:30 ptits-lt systemd[1]: systemd-cryptsetup at rbrssd.service: Failed with result 'exit-code'.
Apr 07 11:31:30 ptits-lt systemd[1]: Stopped Cryptography Setup for rbrssd.
× run-rbrssd.mount - /run/rbrssd
Loaded: loaded (/etc/fstab; generated)
Active: failed (Result: exit-code) since Fri 2023-04-07 11:31:45 EDT; 12s ago
Duration: 11.386s
Where: /run/rbrssd
What: /dev/mapper/rbrssd
Docs: man:fstab(5)
man:systemd-fstab-generator(8)
CPU: 1ms
Apr 07 11:31:45 ptits-lt systemd[1]: Mounting /run/rbrssd...
Apr 07 11:31:45 ptits-lt mount[2591]: mount: /run/rbrssd: can't read superblock on /dev/mapper/rbrssd.
Apr 07 11:31:45 ptits-lt mount[2591]: dmesg(1) may have more information after failed mount system call.
Apr 07 11:31:45 ptits-lt systemd[1]: run-rbrssd.mount: Mount process exited, code=exited, status=32/n/a
Apr 07 11:31:45 ptits-lt systemd[1]: run-rbrssd.mount: Failed with result 'exit-code'.
Apr 07 11:31:45 ptits-lt systemd[1]: Failed to mount /run/rbrssd.
× backup-ask-rbr.service - Sync ask-rbr with external drive on start and stop.
Loaded: loaded (/etc/systemd/system/backup-ask-rbr.service; static)
Active: failed (Result: exit-code) since Fri 2023-04-07 11:31:30 EDT; 27s ago
Duration: 11.130s
Process: 2501 ExecStart=/run/rbrssd/snapshot.py start (code=exited, status=0/SUCCESS)
Process: 2527 ExecStop=/run/rbrssd/snapshot.py stop (code=exited, status=1/FAILURE)
Main PID: 2501 (code=exited, status=0/SUCCESS)
CPU: 46ms
Apr 07 11:31:30 ptits-lt snapshot.py[2527]: File "/run/rbrssd/snapshot.py", line 51, in <module>
Apr 07 11:31:30 ptits-lt snapshot.py[2527]: run([
Apr 07 11:31:30 ptits-lt snapshot.py[2527]: File "/usr/lib/python3.10/subprocess.py", line 526, in run
Apr 07 11:31:30 ptits-lt snapshot.py[2527]: raise CalledProcessError(retcode, process.args,
Apr 07 11:31:30 ptits-lt snapshot.py[2527]: subprocess.CalledProcessError: Command '['sh', '-c', 'btrfs send -p /home/.ask-rbr-snapshots/@2023-04-06T13 /home/.ask-rbr-snapshots/@2023-04-07T11 | btrfs receive /run/rbrssd/ask-arch-profile']' returned non-zero exit status 1.
Apr 07 11:31:30 ptits-lt systemd[1]: backup-ask-rbr.service: Control process exited, code=exited, status=1/FAILURE
Apr 07 11:31:30 ptits-lt systemd[1]: backup-ask-rbr.service: Failed with result 'exit-code'.
Apr 07 11:31:30 ptits-lt systemd[1]: Stopped Sync ask-rbr with external drive on start and stop..
Apr 07 11:31:45 ptits-lt systemd[1]: Dependency failed for Sync ask-rbr with external drive on start and stop..
Apr 07 11:31:45 ptits-lt systemd[1]: backup-ask-rbr.service: Job backup-ask-rbr.service/start failed with result 'dependency'.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: units
Type: text/x-systemd-unit
Size: 2015 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/systemd-devel/attachments/20230531/a6519139/attachment-0001.bin>
-------------- next part --------------
○ dev-sdc.device - /dev/sdc
Loaded: loaded
Active: inactive (dead)
× systemd-cryptsetup at rbrssd.service - Cryptography Setup for rbrssd
Loaded: loaded (/etc/crypttab; generated)
Active: failed (Result: exit-code) since Fri 2023-04-07 11:31:30 EDT; 5s ago
Duration: 11.342s
Docs: man:crypttab(5)
man:systemd-cryptsetup-generator(8)
man:systemd-cryptsetup at .service(8)
Process: 2301 ExecStart=/usr/lib/systemd/systemd-cryptsetup attach rbrssd /dev/disk/by-uuid/000db593-5c9b-492e-b100-3596d955701b - luks,discard,nofail (code=exited, status=0/SUCCESS)
Process: 2528 ExecStop=/usr/lib/systemd/systemd-cryptsetup detach rbrssd (code=exited, status=1/FAILURE)
Main PID: 2301 (code=exited, status=0/SUCCESS)
CPU: 6ms
Apr 07 11:31:16 ptits-lt systemd[1]: Starting Cryptography Setup for rbrssd...
Apr 07 11:31:16 ptits-lt systemd-cryptsetup[2301]: Set cipher aes, mode xts-plain64, key size 512 bits for device /dev/disk/by-uuid/000db593-5c9b-492e-b100-3596d955701b.
Apr 07 11:31:19 ptits-lt systemd[1]: Finished Cryptography Setup for rbrssd.
Apr 07 11:31:30 ptits-lt systemd[1]: Stopping Cryptography Setup for rbrssd...
Apr 07 11:31:30 ptits-lt systemd-cryptsetup[2528]: Underlying device for crypt device rbrssd disappeared.
Apr 07 11:31:30 ptits-lt systemd-cryptsetup[2528]: Device rbrssd is still in use.
Apr 07 11:31:30 ptits-lt systemd-cryptsetup[2528]: Failed to deactivate: Device or resource busy
Apr 07 11:31:30 ptits-lt systemd[1]: systemd-cryptsetup at rbrssd.service: Control process exited, code=exited, status=1/FAILURE
Apr 07 11:31:30 ptits-lt systemd[1]: systemd-cryptsetup at rbrssd.service: Failed with result 'exit-code'.
Apr 07 11:31:30 ptits-lt systemd[1]: Stopped Cryptography Setup for rbrssd.
○ run-rbrssd.mount - /run/rbrssd
Loaded: loaded (/etc/fstab; generated)
Active: inactive (dead) since Fri 2023-04-07 11:31:30 EDT; 4s ago
Duration: 11.386s
Where: /run/rbrssd
What: /dev/mapper/rbrssd
Docs: man:fstab(5)
man:systemd-fstab-generator(8)
CPU: 8ms
Apr 07 11:31:19 ptits-lt systemd[1]: Mounting /run/rbrssd...
Apr 07 11:31:19 ptits-lt systemd[1]: Mounted /run/rbrssd.
Apr 07 11:31:30 ptits-lt systemd[1]: Unmounting /run/rbrssd...
Apr 07 11:31:30 ptits-lt systemd[1]: run-rbrssd.mount: Deactivated successfully.
Apr 07 11:31:30 ptits-lt systemd[1]: Unmounted /run/rbrssd.
× backup-ask-rbr.service - Sync ask-rbr with external drive on start and stop.
Loaded: loaded (/etc/systemd/system/backup-ask-rbr.service; static)
Active: failed (Result: exit-code) since Fri 2023-04-07 11:31:30 EDT; 5s ago
Duration: 11.130s
Process: 2501 ExecStart=/run/rbrssd/snapshot.py start (code=exited, status=0/SUCCESS)
Process: 2527 ExecStop=/run/rbrssd/snapshot.py stop (code=exited, status=1/FAILURE)
Main PID: 2501 (code=exited, status=0/SUCCESS)
CPU: 46ms
Apr 07 11:31:30 ptits-lt snapshot.py[2532]: At snapshot @2023-04-07T11
Apr 07 11:31:30 ptits-lt snapshot.py[2527]: Traceback (most recent call last):
Apr 07 11:31:30 ptits-lt snapshot.py[2527]: File "/run/rbrssd/snapshot.py", line 51, in <module>
Apr 07 11:31:30 ptits-lt snapshot.py[2527]: run([
Apr 07 11:31:30 ptits-lt snapshot.py[2527]: File "/usr/lib/python3.10/subprocess.py", line 526, in run
Apr 07 11:31:30 ptits-lt snapshot.py[2527]: raise CalledProcessError(retcode, process.args,
Apr 07 11:31:30 ptits-lt snapshot.py[2527]: subprocess.CalledProcessError: Command '['sh', '-c', 'btrfs send -p /home/.ask-rbr-snapshots/@2023-04-06T13 /home/.ask-rbr-snapshots/@2023-04-07T11 | btrfs receive /run/rbrssd/ask-arch-profile']' returned non-zero exit status 1.
Apr 07 11:31:30 ptits-lt systemd[1]: backup-ask-rbr.service: Control process exited, code=exited, status=1/FAILURE
Apr 07 11:31:30 ptits-lt systemd[1]: backup-ask-rbr.service: Failed with result 'exit-code'.
Apr 07 11:31:30 ptits-lt systemd[1]: Stopped Sync ask-rbr with external drive on start and stop..
-------------- next part --------------
○ dev-sdc.device - /dev/sdc
Loaded: loaded
Active: inactive (dead)
Apr 07 11:32:57 ptits-lt systemd[1]: Condition check resulted in PSSD_T7 being skipped.
○ systemd-cryptsetup at rbrssd.service - Cryptography Setup for rbrssd
Loaded: loaded (/etc/crypttab; generated)
Active: inactive (dead) since Fri 2023-04-07 11:44:56 EDT; 2s ago
Duration: 11min 56.980s
Docs: man:crypttab(5)
man:systemd-cryptsetup-generator(8)
man:systemd-cryptsetup at .service(8)
Process: 4449 ExecStop=/usr/lib/systemd/systemd-cryptsetup detach rbrssd (code=exited, status=0/SUCCESS)
Main PID: 2753 (code=exited, status=0/SUCCESS)
CPU: 4ms
Apr 07 11:32:57 ptits-lt systemd[1]: Starting Cryptography Setup for rbrssd...
Apr 07 11:32:57 ptits-lt systemd-cryptsetup[2753]: Set cipher aes, mode xts-plain64, key size 512 bits for device /dev/disk/by-uuid/000db593-5c9b-492e-b100-3596d955701b.
Apr 07 11:32:59 ptits-lt systemd[1]: Finished Cryptography Setup for rbrssd.
Apr 07 11:44:56 ptits-lt systemd[1]: Stopping Cryptography Setup for rbrssd...
Apr 07 11:44:56 ptits-lt systemd-cryptsetup[4449]: Underlying device for crypt device rbrssd disappeared.
Apr 07 11:44:56 ptits-lt systemd[1]: systemd-cryptsetup at rbrssd.service: Deactivated successfully.
Apr 07 11:44:56 ptits-lt systemd[1]: Stopped Cryptography Setup for rbrssd.
○ run-rbrssd.mount - /run/rbrssd
Loaded: loaded (/etc/fstab; generated)
Drop-In: /etc/systemd/system/run-rbrssd.mount.d
└─override.conf
Active: inactive (dead) since Fri 2023-04-07 11:44:56 EDT; 2s ago
Duration: 11min 56.820s
Where: /run/rbrssd
What: /dev/mapper/rbrssd
Docs: man:fstab(5)
man:systemd-fstab-generator(8)
CPU: 8ms
Apr 07 11:32:59 ptits-lt systemd[1]: Mounting /run/rbrssd...
Apr 07 11:32:59 ptits-lt systemd[1]: Mounted /run/rbrssd.
Apr 07 11:44:56 ptits-lt systemd[1]: Unmounting /run/rbrssd...
Apr 07 11:44:56 ptits-lt systemd[1]: run-rbrssd.mount: Deactivated successfully.
Apr 07 11:44:56 ptits-lt systemd[1]: Unmounted /run/rbrssd.
× backup-ask-rbr.service - Sync ask-rbr with external drive on start and stop.
Loaded: loaded (/etc/systemd/system/backup-ask-rbr.service; static)
Active: failed (Result: exit-code) since Fri 2023-04-07 11:44:56 EDT; 2s ago
Duration: 11min 56.583s
Process: 4429 ExecStop=/run/rbrssd/snapshot.py stop (code=exited, status=1/FAILURE)
Main PID: 2953 (code=exited, status=0/SUCCESS)
CPU: 50ms
Apr 07 11:44:56 ptits-lt snapshot.py[4433]: At snapshot @2023-04-07T11:44
Apr 07 11:44:56 ptits-lt snapshot.py[4429]: Traceback (most recent call last):
Apr 07 11:44:56 ptits-lt snapshot.py[4429]: File "/run/rbrssd/snapshot.py", line 51, in <module>
Apr 07 11:44:56 ptits-lt snapshot.py[4429]: run([
Apr 07 11:44:56 ptits-lt snapshot.py[4429]: File "/usr/lib/python3.10/subprocess.py", line 526, in run
Apr 07 11:44:56 ptits-lt snapshot.py[4429]: raise CalledProcessError(retcode, process.args,
Apr 07 11:44:56 ptits-lt snapshot.py[4429]: subprocess.CalledProcessError: Command '['sh', '-c', 'btrfs send -p /home/.ask-rbr-snapshots/@2023-04-06T13 /home/.ask-rbr-snapshots/@2023-04-07T11:44 | btrfs receive /run/rbrssd/ask-arch-profile']' returned non-zero exit status 1.
Apr 07 11:44:56 ptits-lt systemd[1]: backup-ask-rbr.service: Control process exited, code=exited, status=1/FAILURE
Apr 07 11:44:56 ptits-lt systemd[1]: backup-ask-rbr.service: Failed with result 'exit-code'.
Apr 07 11:44:56 ptits-lt systemd[1]: Stopped Sync ask-rbr with external drive on start and stop..
More information about the systemd-devel
mailing list