Stopped (with error) /dev/dm-1 #1620

Open
rumpelsepp opened this Issue Oct 20, 2015 · 94 comments

Comments

Projects
None yet

I am using full disk encryption and an encrypted swap partition. On every shutdown I get the following Error:

Okt 20 09:03:52 kronos systemd[1]: Deactivated swap /dev/dm-1.
Okt 20 09:03:52 kronos systemd[1]: Stopped (with error) /dev/dm-1.
Okt 20 09:03:54 kronos systemd[1]: Stopped /sys/devices/virtual/block/dm-1.
# /etc/crypttab
swap           /dev/sda3                         /dev/urandom            swap,discard
# /etc/crypttab.initramfs
cryptroot   /dev/sda2   none    discard
$ uname -a
Linux kronos 4.2.3-1-ARCH #1 SMP PREEMPT Sat Oct 3 18:52:50 CEST 2015 x86_64 GNU/Linux

$ systemctl --version
systemd 227
+PAM -AUDIT -SELINUX -IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN

$ lsblk
NAME                                          MAJ:MIN RM   SIZE RO TYPE  MOUNTPOINT
sda                                             8:0    0 335,4G  0 disk  
├─sda1                                          8:1    0   500M  0 part  /boot
├─sda2                                          8:2    0 319,9G  0 part  
│ └─cryptroot                                 254:0    0 319,9G  0 crypt /
└─sda3                                          8:3    0    15G  0 part  
  └─swap                                      254:1    0    15G  0 crypt [SWAP]
Owner

poettering commented Oct 20, 2015

You could please boot with "systemd.log_level=debug", then reboot and shutdown, and provide us with a longer excerpt of the logs this generates, around the issue you are trying to debug? This should provide us with more information about what's precisely failing there.

sure, will look if I have a few minutes time for that this afternoon.

Enough?

Okt 20 12:51:25 kronos systemd[1]: dev-disk-by\x2duuid-fa4c42b1\x2dff6d\x2d4d23\x2d9b69\x2d3bbc65abbb42.swap: Changed active -> dead
Okt 20 12:51:25 kronos systemd[1]: dev-disk-by\x2duuid-fa4c42b1\x2dff6d\x2d4d23\x2d9b69\x2d3bbc65abbb42.swap: Job dev-disk-by\x2duuid-fa4c42b1\x2dff6d\x2d4d23\x2d9b69\x2d3bbc65abbb42.swap/stop finished, result=done
Okt 20 12:51:25 kronos systemd[1]: Deactivated swap /dev/disk/by-uuid/fa4c42b1-ff6d-4d23-9b69-3bbc65abbb42.
Okt 20 12:51:25 kronos systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobRemoved cookie=587 reply_cookie=0 error=n/a
Okt 20 12:51:25 kronos systemd[1]: dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dPLAIN\x2dswap.swap: Changed active -> dead
Okt 20 12:51:25 kronos systemd[1]: dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dPLAIN\x2dswap.swap: Job dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dPLAIN\x2dswap.swap/stop finished, result=done
Okt 20 12:51:25 kronos systemd[1]: Deactivated swap /dev/disk/by-id/dm-uuid-CRYPT-PLAIN-swap.
Okt 20 12:51:25 kronos systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobRemoved cookie=588 reply_cookie=0 error=n/a
Okt 20 12:51:25 kronos systemd[1]: dev-disk-by\x2did-dm\x2dname\x2dswap.swap: Changed active -> dead
Okt 20 12:51:25 kronos systemd[1]: dev-disk-by\x2did-dm\x2dname\x2dswap.swap: Job dev-disk-by\x2did-dm\x2dname\x2dswap.swap/stop finished, result=done
Okt 20 12:51:25 kronos systemd[1]: Deactivated swap /dev/disk/by-id/dm-name-swap.
Okt 20 12:51:25 kronos systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobRemoved cookie=589 reply_cookie=0 error=n/a
Okt 20 12:51:25 kronos systemd[1]: dev-dm\x2d1.swap: Changed active -> dead
Okt 20 12:51:25 kronos systemd[1]: dev-dm\x2d1.swap: Job dev-dm\x2d1.swap/stop finished, result=done
Okt 20 12:51:25 kronos systemd[1]: Deactivated swap /dev/dm-1.
Okt 20 12:51:25 kronos systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobRemoved cookie=590 reply_cookie=0 error=n/a
Okt 20 12:51:25 kronos systemd[1]: dev-dm\x2d1.device: Job dev-dm\x2d1.device/stop finished, result=failed
Okt 20 12:51:25 kronos systemd[1]: Stopped (with error) /dev/dm-1.
Okt 20 12:51:25 kronos systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobRemoved cookie=591 reply_cookie=0 error=n/a
Okt 20 12:51:25 kronos systemd[1]: dev-dm\x2d1.swap: Collecting.
Okt 20 12:51:25 kronos systemd[1]: dev-disk-by\x2did-dm\x2dname\x2dswap.swap: Collecting.
Okt 20 12:51:25 kronos systemd[1]: dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dPLAIN\x2dswap.swap: Collecting.
Okt 20 12:51:25 kronos systemd[1]: dev-disk-by\x2duuid-fa4c42b1\x2dff6d\x2d4d23\x2d9b69\x2d3bbc65abbb42.swap: Collecting.
Contributor

arvidjaar commented Oct 20, 2015

dev-dm\x2d1.device: Job dev-dm\x2d1.device/stop finished, result=failed

Devices do not even have stop method so failure is pretty much expected here; but why it attempts to stop device in the first place? Can you make full log available?

I prefer to send it to an email address, but yeah, I can do.

igalic commented Mar 31, 2016

i just did a reboot with debug enabled. here are 12k lines of glorious log (it starts from logind noticing that we're rebooting, but i can give you more if necessary): https://gist.github.com/e032493159fbc8cda780f773c261dc03

db0451 commented May 30, 2016

I get this too, for dm-0 via ecryptfs-setup-swap, on Debian unstable.

Am I correct to infer that this is harmless and the fix is to deactivate a nonsensical 'stop device' service somewhere? How would I do that? Should we file bugs somewhere else against this?

thanks

djgera commented Oct 14, 2016

I get this "Stopped (with error) /dev/mapper/home" if fstab line uses UUID=, otherwise no error if /dev/mapper/home is used.

On Debian Stable, with systemd 230-7~bpo8+2, I got this error as well on a /home in RAID1 configuration on top on dm-crypt/luks.
Using only label designations in /etc/fstab and /etc/crypttab I got the errors:

Stopped (with error) /dev/disk/by-id/dm-uuid-CRYPT-LUKS1-2814d5a159c1237c95155b0e2efdg3e1-enc1.
Stopped (with error) /dev/dm-1.
Stopped (with error) /dev/disk/by-id/dm-name-enc1.
Stopped (with error) /dev/disk/by-id/dm-uuid-CRYPT-LUKS1-43759e562s4df5gh2z4r8teca4dbbad9-enc0.
Stopped (with error) /dev/disk/by-uuid/dea9dd5d-a129-414d-dfe546789347.
Stopped (with error) /dev/disk/by-label/vol0.
Stopped (with error) /dev/mapper/enc1.
Stopped (with error) /sys/devices/virtual/block/dm-0.
Stopped (with error) /dev/disk/by-id/dm-name-enc0.
Stopped (with error) /dev/dm-0.
Stopped (with error) /sys/devices/virtual/block/dm-1.

Using only UUID designations in /etc/fstab and /etc/crypttab I got the errors:

Stopped (with error) /dev/mapper/enc0.
Stopped (with error) /dev/dm-1.
Stopped (with error) /dev/disk/by-id/dm-uuid-CRYPT-LUKS1-2814d5a159c1237c95155b0e2efdg3e1-enc1.
Stopped (with error) /dev/mapper/enc1.
Stopped (with error) /sys/devices/virtual/block/dm-1.
Stopped (with error) /dev/disk/by-id/dm-uuid-CRYPT-LUKS1-43759e562s4df5gh2z4r8teca4dbbad9-enc0.
Stopped (with error) /dev/disk/by-id/dm-name-enc1.
Stopped (with error) /dev/dm-0.
Stopped (with error) /sys/devices/virtual/block/dm-0.
Stopped (with error) /dev/disk/by-id/dm-name-enc0.
Stopped (with error) /dev/disk/by-label/vol0.

So for me the workaround doesn't work.
However it seems that /home is correctly unmounted afterwards, but it would be nice if someone can confirm that these error messages are harmless.

Am I correct to infer that this is harmless and the fix is to deactivate a nonsensical 'stop device'
service somewhere? How would I do that? Should we file bugs somewhere else against this?

@db0451 did you find out anything regarding your question? I'm also interested if this is harmless of in fact something that I should look into ASAP?

db0451 commented Oct 26, 2016

@denibertovic The only info I have on this issue is this thread.

This continues to occur for me, though admittedly my system seems to work OK anyway. But it is always worrying to see red ERROR text anywhere, so if this is ultimately a non-issue and can/should be worked around, then I wish it would be.

iKarith commented Oct 26, 2016

I did not find it harmless. I found my disks would be dirty on the next boot often because they did not unmount cleanly, with errors introduced that required fixing. And this is really difficult to fix on systemd systems because even in "single user" mode, you can't really remount your root directory ro. And that's when I determined that LUKS + bcache + systemd were not, for the moment, something I should be trying to use on the same system.

@iKarith Thanks for the info. As a workaround, I will therefore unmount manually, before shutting down (or include an unmount script somewhere).
I'll keep monitoring this issue to see if there is something I can do toward solving this issue.

ledoge commented Oct 28, 2016

I also encounter Stopped (with error) /dev/dm-1. on Arch Linux. I set up an encrypted swap partition with /dev/urandom as the password and mounted by its label as described here under "UUID and Label".

camoz commented Nov 18, 2016

I too have that issue since one year.
Described it in the Arch Forums back then: https://bbs.archlinux.org/viewtopic.php?id=205275
For me, not using UUIDs in /etc/fstab solves it, too.

I have the same use case as @ledoge has. I already temporary tried to use device names (sda5) in the fstab / crypttab files. The same error message appears. Here is the log regarding this error during shutdown.

systemd_shutdown_stopped_with_error_dm-1_version_231.txt

mnfdev commented Nov 28, 2016

I also had the "Stopped (with error) /dev/dm.." problem with encrypted swap, then found that "generator" doesn't add deps to swap unit in /var/run/systemd/generator.

Instead of crypttab/fstab entries I just wrote simple .service and .swap units and now it stops w/out error.

Examples from my local computer (HITACHI-SWAP - LVM volume, HITACHI-SWAP-OPEN - encrypted swap on HITACHI-SWAP):

/etc/systemd/system/systemd-cryptsetup@HITACHI\x2dSWAP\x2dOPEN.service:

[Unit]
Description=Setup swap on /dev/mapper/HITACHI-SWAP-OPEN
Requires=dev-mapper-HITACHI\x2dSWAP.device
After=dev-mapper-HITACHI\x2dSWAP.device
DefaultDependencies=no

[Service]
Type=oneshot
RemainAfterExit=yes
ExecStart=/lib/systemd/systemd-cryptsetup attach 'HITACHI-SWAP-OPEN' '/dev/mapper/HITACHI-SWAP' '/dev/urandom' 'swap'
ExecStop=/lib/systemd/systemd-cryptsetup detach 'HITACHI-SWAP-OPEN'
ExecStartPost=/sbin/mkswap '/dev/mapper/HITACHI-SWAP-OPEN'

/etc/systemd/system/dev-mapper-HITACHI\x2dSWAP\x2dOPEN.swap:

[Unit]
Description=Start swap on /dev/mapper/HITACHI-SWAP-OPEN
Requires=systemd-cryptsetup@HITACHI\x2dSWAP\x2dOPEN.service
After=systemd-cryptsetup@HITACHI\x2dSWAP\x2dOPEN.service
Before=swap.target
DefaultDependencies=no

[Swap]
What=/dev/mapper/HITACHI-SWAP-OPEN

[Install]
WantedBy=swap.target

(added to the default swap.target with systemctl enable 'dev-mapper-HITACHI\x2dSWAP\x2dOPEN.swap')

siwyd commented Nov 30, 2016

Same issue here with an encrypted swap partition.

RalfJung commented Dec 6, 2016

I am also seeing these errors on Debian testing on two systems with root and /home on an encrypted LVM. One also has swap on that LVM, one has no swap.

@poettering Why is the tag "needs-reporter-feedback" still set? Which feedback is missing? I'd be happy to provide more data if helpful.

pdefreitas commented Dec 6, 2016

same issue here with encrypted swap partition, ubuntu 16.04.

marchom commented Dec 6, 2016

same on ubuntu 16.10

same error on Debian 8.6
If you need any Logfiles, I also will be Happy to send them.

Also having this issue on ubuntu 16.10 / systemd 231 / LVM on LUKS on mdadm/Mirrored Raid 1

Can a project member please remove the "needs-reporter-feedback" tag? Not sure if this tag is preventing developers from getting started on this bug, but I believe all the necessary info has already been supplied. If not, please let us know how we can help.

Contributor

arvidjaar commented Dec 15, 2016

@sky-lake

Well, we do not know what info was requested ... :)

As far as I can tell, the reason for this error message is the fact, that crypto container device Requires corresponding cryptsetup service. Cryptsetup service is in turn configured to be stopped on shutdown. According to Requires behavior stopping cryptsetup unit initiates stopping of crypto container device. And as I mentioned before, devices do not have "stop" method at all which results in this error message.

@arvidjaar, given your above diagnosis, do you know how we can fix or work around this problem?

Vrihub commented Jan 15, 2017

FYI: I'm having the same problem on all my LUKS encrypted devices (the underlying devices are LVM logical volumes), on Debian stretch, systemd version 232-8.

I don't have UUIDs in /etc/fstab, so the workaround discussed above doesn't work in my case.

eturner commented Feb 1, 2017

This is a brand new error for me. I just got done moving everything around, and ended up with three LUKS volumes on top of LVM for /boot, /, and swap, so I can use the lvmcache on / without having everything encrypted twice as with two LUKS volumes.
I've always used init hooks to decrypt. If it's systemd related, then it's because my /boot and swap are in crypttab now I guess. I'm only getting one error message though.
I'm not using UUID's anywhere since LVM figures that out well enough.

Same error on a fresh Debian Stretch install and a crypted swap...

Contributor

mbiebl commented Feb 11, 2017

@poettering Seems I can reliably reproduce the issue in a VM which was setup with a default LVM+luks-cryptsetup configuration generated by the Debian installer. It uses two partitions:

/dev/vda1 →/boot
/dev/vda5 → luks/cryptsetup container

root@debian# cat /etc/crypttab 
vda5_crypt UUID=56892e58-2603-44c0-8681-d8aec1645016 none luks

Then LVM on top

root@debian:~# pvscan 
  PV /dev/mapper/vda5_crypt   VG debian-vg       lvm2 [9,75 GiB / 0    free]
  Total: 1 [9,75 GiB] / in use: 1 [9,75 GiB] / in no VG: 0 [0   ]
root@debian:~# vgscan 
  Reading volume groups from cache.
  Found volume group "debian-vg" using metadata type lvm2
root@debian:~# lvscan 
  ACTIVE            '/dev/debian-vg/root' [2,23 GiB] inherit
  ACTIVE            '/dev/debian-vg/var' [1,05 GiB] inherit
  ACTIVE            '/dev/debian-vg/swap_1' [1020,00 MiB] inherit
  ACTIVE            '/dev/debian-vg/tmp' [264,00 MiB] inherit
  ACTIVE            '/dev/debian-vg/home' [5,22 GiB] inherit
root@debian# cat /etc/fstab

/dev/mapper/debian--vg-root /               ext4    errors=remount-ro 0       1
# /boot was on /dev/vda1 during installation
UUID=e7870192-32b7-427a-a259-2842f242423d /boot           ext2    defaults        0       2
/dev/mapper/debian--vg-home /home           ext4    defaults        0       2
/dev/mapper/debian--vg-tmp /tmp            ext4    defaults        0       2
/dev/mapper/debian--vg-var /var            ext4    defaults        0       2
/dev/mapper/debian--vg-swap_1 none            swap    sw              0       0

root@debian# ls -la /dev/mapper/

lrwxrwxrwx  1 root root       7 Feb 11 16:27 debian--vg-home -> ../dm-5
lrwxrwxrwx  1 root root       7 Feb 11 16:27 debian--vg-root -> ../dm-1
lrwxrwxrwx  1 root root       7 Feb 11 16:27 debian--vg-swap_1 -> ../dm-3
lrwxrwxrwx  1 root root       7 Feb 11 16:27 debian--vg-tmp -> ../dm-4
lrwxrwxrwx  1 root root       7 Feb 11 16:27 debian--vg-var -> ../dm-2
lrwxrwxrwx  1 root root       7 Feb 11 16:27 vda5_crypt -> ../dm-0

From the shutdown log, systemd tries to stop the cryptsetup device /dev/dm-0 for some reason. This is bound to fail obviously, as it contains all the still active file systems. I'm happy to provide more targetted information.

         Stopping User Manager for UID 0...
[  OK  ] Stopped target Graphical Interface.
[  OK  ] Stopped target Timers.
[  OK  ] Stopped target Multi-User System.
         Stopping OpenBSD Secure Shell server...
         Stopping Regular background program processing daemon...
[  OK  ] Stopped Daily apt activities.
         Stopping Session 1 of user root.
[  OK  ] Stopped target Sound Card.
[  OK  ] Stopped target Login Prompts.
         Stopping Getty on tty1...
         Stopping Serial Getty on ttyS0...
         Stopping System Logging Service...
[  OK  ] Stopped target System Time Synchronized.
         Stopping D-Bus System Message Bus...
[  OK  ] Stopped Daily Cleanup of Temporary Directories.
[  OK  ] Stopped System Logging Service.
[  OK  ] Stopped Regular background program processing daemon.
[  OK  ] Stopped D-Bus System Message Bus.
[  OK  ] Stopped OpenBSD Secure Shell server.
[  OK  ] Stopped Getty on tty1.
[  OK  ] Stopped Serial Getty on ttyS0.
[  OK  ] Stopped User Manager for UID 0.
[  OK  ] Stopped Session 1 of user root.
Failed to propagate agent release message: Transport endpoint is not connected
Failed to propagate agent release message: Transport endpoint is not connected
Failed to propagate agent release message: Transport endpoint is not connected
Failed to propagate agent release message: Transport endpoint is not connected
Failed to propagate agent release message: Transport endpoint is not connected
Failed to propagate agent release message: Transport endpoint is not connected
Failed to propagate agent release message: Transport endpoint is not connected
Failed to propagate agent release message: Transport endpoint is not connected
Failed to propagate agent release message: Transport endpoint is not connected
Failed to propagate agent release message: Transport endpoint is not connected
Failed to propagate agent release message: Transport endpoint is not connected
Failed to propagate agent release message: Transport endpoint is not connected
[  OK  ] Removed slice User Slice of root.
         Stopping Login Service...
[  OK  ] Removed slice system-serial\x2dgetty.slice.
         Stopping Permit User Sessions...
[  OK  ] Removed slice system-getty.slice.
[  OK  ] Stopped Login Service.
[  OK  ] Stopped Permit User Sessions.
[  OK  ] Stopped target Network.
         Stopping Raise network interfaces...
         Stopping ifup for ens3...
[  OK  ] Stopped target Remote File Systems.
[  OK  ] Stopped target Basic System.
[  OK  ] Stopped target Paths.
[  OK  ] Stopped target Slices.
[  OK  ] Removed slice User and Session Slice.
[  OK  ] Stopped target Sockets.
[  OK  ] Closed Syslog Socket.
[  OK  ] Closed D-Bus System Message Bus Socket.
[  OK  ] Stopped target System Initialization.
[  OK  ] Stopped target Encrypted Volumes.
[  OK  ] Stopped Dispatch Password Requests to Console Directory Watch.
[  OK  ] Stopped Forward Password Requests to Wall Directory Watch.
         Stopping Cryptography Setup for vda5_crypt...
         Stopping Network Time Synchronization...
         Stopping Load/Save Random Seed...
[  OK  ] Stopped target Swap.
         Deactivating swap /dev/debian-vg/swap_1...
         Stopping Update UTMP about System Boot/Shutdown...
[  OK  ] Stopped Network Time Synchronization.
[  OK  ] Deactivated swap /dev/disk/by-uuid/…d03e0-736a-48ab-afce-0864f64c6154.
[  OK  ] Deactivated swap /dev/disk/by-id/dm…mBErryep61K37oLHkYWnsMXUAEGfOlrCz.
[  OK  ] Deactivated swap /dev/disk/by-id/dm-name-debian--vg-swap_1.
[  OK  ] Deactivated swap /dev/debian-vg/swap_1.
[  OK  ] Deactivated swap /dev/dm-3.
[  OK  ] Stopped Load/Save Random Seed.
[  OK  ] Deactivated swap /dev/mapper/debian--vg-swap_1.
[  OK  ] Stopped Update UTMP about System Boot/Shutdown.
[  OK  ] Stopped Create Volatile Files and Directories.
[  OK  ] Stopped Flush Journal to Persistent Storage.
Reloading.
[FAILED] Stopped (with error) /dev/disk/by-id/dm-name-vda5_crypt.
[FAILED] Stopped (with error) /sys/devices/virtual/block/dm-0.
[FAILED] Stopped (with error) /dev/mapper/vda5_crypt.
[FAILED] Stopped (with error) /dev/disk/by-i…0344c08681d8aec1645016-vda5_crypt.
[FAILED] Stopped (with error) /dev/disk/by-i…r-0srK-HqO4-eIyK-X1AF-wtox-W7SPa5.
[FAILED] Stopped (with error) /dev/dm-0.
Reloading.
[  OK  ] Stopped ifup for ens3.
[  OK  ] Stopped Raise network interfaces.
[  OK  ] Stopped target Local File Systems.
         Unmounting /var...
         Unmounting /boot...
         Unmounting /tmp...
         Unmounting /home...
         Unmounting /run/user/0...
[  OK  ] Stopped Apply Kernel Variables.
[  OK  ] Stopped Load Kernel Modules.
var.mount: Mount process exited, code=exited status=32
[FAILED] Failed unmounting /var.
[  OK  ] Unmounted /boot.
[  OK  ] Unmounted /tmp.
[  OK  ] Unmounted /home.
[  OK  ] Unmounted /run/user/0.
[  OK  ] Stopped File System Check on /dev/mapper/debian--vg-home.
[  OK  ] Stopped File System Check on /dev/mapper/debian--vg-tmp.
[  OK  ] Stopped File System Check on /dev/d…70192-32b7-427a-a259-2842f242423d.
[  OK  ] Stopped File System Check on /dev/mapper/debian--vg-var.
[  OK  ] Removed slice system-systemd\x2dfsck.slice.
[  OK  ] Stopped target Local File Systems (Pre).
[  OK  ] Stopped Create Static Device Nodes in /dev.
[  OK  ] Stopped Remount Root and Kernel File Systems.
         Stopping Monitoring of LVM2 mirrors…ng dmeventd or progress polling...
[  OK  ] Stopped Monitoring of LVM2 mirrors,…sing dmeventd or progress polling.
         Stopping LVM2 metadata daemon...
[  OK  ] Stopped LVM2 metadata daemon.
systemd-cryptsetup@vda5_crypt.service: Control process exited, code=exited status=1
[  OK  ] Stopped Cryptography Setup for vda5_crypt.
systemd-cryptsetup@vda5_crypt.service: Unit entered failed state.
systemd-cryptsetup@vda5_crypt.service: Failed with result 'exit-code'.
[  OK  ] Reached target Unmount All Filesystems.
[  OK  ] Removed slice system-systemd\x2dcryptsetup.slice.
[  OK  ] Reached target Shutdown.
Shutting down.
Sending SIGTERM to remaining processes...
Sending SIGKILL to remaining processes...
Unmounting file systems.
Remounting '/var' read-only with options 'data=ordered'.
[   29.843803] EXT4-fs (dm-2): re-mounted. Opts: data=ordered
Unmounting /var.
Remounting '/' read-only with options 'errors=remount-ro,data=ordered'.
[   29.865792] EXT4-fs (dm-1): re-mounted. Opts: errors=remount-ro,data=ordered
Remounting '/' read-only with options 'errors=remount-ro,data=ordered'.
[   29.868977] EXT4-fs (dm-1): re-mounted. Opts: errors=remount-ro,data=ordered
Remounting '/' read-only with options 'errors=remount-ro,data=ordered'.
[   29.871226] EXT4-fs (dm-1): re-mounted. Opts: errors=remount-ro,data=ordered
All filesystems unmounted.
Deactivating swaps.
All swaps deactivated.
Detaching loop devices.
All loop devices detached.
Detaching DM devices.
Detaching DM 253:5.
Detaching DM 253:4.
Detaching DM 253:3.
Detaching DM 253:2.
Detaching DM 253:0.
Could not detach DM /dev/dm-0: Device or resource busy
Not all DM devices detached, 2 left.
Detaching DM devices.
Detaching DM 253:0.
Could not detach DM /dev/dm-0: Device or resource busy
Not all DM devices detached, 2 left.
Cannot finalize remaining DM devices, continuing.
Failed to finalize  DM devices, ignoring
Halting system.
[   29.947232] reboot: System halted
Contributor

arvidjaar commented Feb 12, 2017

         Stopping Cryptography Setup for vda5_crypt...
...
[  OK  ] Stopped target Local File Systems.
         Unmounting /var...
         Unmounting /boot...
         Unmounting /tmp...
         Unmounting /home...
...
systemd-cryptsetup@vda5_crypt.service: Control process exited, code=exited status=1
[  OK  ] Stopped Cryptography Setup for vda5_crypt.
systemd-cryptsetup@vda5_crypt.service: Unit entered failed state.
systemd-cryptsetup@vda5_crypt.service: Failed with result 'exit-code'.

This cannot be right. You cannot (try to) stop crypto container before unmounting and stopping all filesystems and logical volumes on top of it. Some dependency is apparently missing here. Could you provide systemctl show *?

Contributor

mbiebl commented Feb 12, 2017

@arvidjaar Attached the systemd-analyze dump output
systemd-analyze-dump-v232.txt

wavexx commented Feb 12, 2017

Contributor

arvidjaar commented Feb 12, 2017

https://gemex.eurac.edu/dl/?t=91da60f4461ff75f0821f31256dc7136

This looks truncated in some strange way.

Contributor

arvidjaar commented Feb 12, 2017

Reloading.
[FAILED] Stopped (with error) /dev/disk/by-id/dm-name-vda5_crypt.
[FAILED] Stopped (with error) /sys/devices/virtual/block/dm-0.
[FAILED] Stopped (with error) /dev/mapper/vda5_crypt.
[FAILED] Stopped (with error) /dev/disk/by-i…0344c08681d8aec1645016-vda5_crypt.
[FAILED] Stopped (with error) /dev/disk/by-i…r-0srK-HqO4-eIyK-X1AF-wtox-W7SPa5.
[FAILED] Stopped (with error) /dev/dm-0.

OK, so my best guess is - you call systemctl daemon-reload during shutdown. This enumerates existing units (including devices) and performs coldplug which at some point calls unit_notify for each device. And unit_notify does

                case JOB_STOP:
                case JOB_RESTART:
                case JOB_TRY_RESTART:

                        if (UNIT_IS_INACTIVE_OR_FAILED(ns))
                                job_finish_and_invalidate(u->job, JOB_DONE, true, false);
                        else if (u->job->state == JOB_RUNNING && ns != UNIT_DEACTIVATING) {
                                unexpected = true;
                                job_finish_and_invalidate(u->job, JOB_FAILED, true, false);
                        }

                        break;

But for all I can tell, devices do not have UNIT_DEACTIVATING state, and new state is really ACTIVE which means systemd aborts jobs.

At least this is the only code path I can find that can result in Stopped (with error) message.

wavexx commented Feb 12, 2017

Contributor

arvidjaar commented Feb 12, 2017

At least this is the only code path I can find that can result in Stopped (with error) message.

And it is trivial to reproduce now by doing systemctl stop sys-devices-platform-serial8250-tty-ttyS12.device in one terminal and systemctl daemon-reload in another with immediate

Feb 12 21:21:08 10 systemd[1]: Reloading.
Feb 12 21:21:12 10 systemd[1]: nss-lookup.target: Dependency Before=nss-lookup.target dropped
Feb 12 21:21:12 10 systemd[1]: Stopped (with error) /sys/devices/platform/serial8250/tty/ttyS12.
Feb 12 21:21:12 10 systemd[1]: Stopped (with error) /dev/ttyS12.

And, BTW, systemctl stop sys-devices-platform-serial8250-tty-ttyS12.device still appears to be waiting for job completion, but that is another glitch^Wbug.

Contributor

arvidjaar commented Feb 12, 2017

In which way?

It contains too little information, some information does not belong to any unit, etc.

wavexx commented Feb 12, 2017

wavexx commented Feb 12, 2017

Contributor

arvidjaar commented Feb 12, 2017

@wavexx Sorry, I must have misinterpreted something, file looks OK. But in any case, we know the reason for at least @mbiebl errors. Would be interesting to know if others also see Reloading... message in logs immediately before (or close to) failure lines.

3point2 commented Feb 12, 2017

I am running Arch Linux with an encrypted swap. My issue is exactly as described by @rumpelsepp's inital report and I've been following this issue for a while.

I don't see "Reloading" in my logs as @mbiebl does. The relevant lines around the error message on shutdown are here: shutdown-swap.txt and the full logs from boot to shutdown are here: boot-shutdown.txt (both with systemd.log_level=debug)

My setup:

# /etc/crypttab
home		/dev/disk/by-uuid/d1e70eda-ed2b-45e3-8db0-fd52c19a8e3a		/etc/keys/home	discard
swap            /dev/disk/by-id/ata-SanDisk_SDSSDHP256G_134200401167-part4	/dev/urandom	swap,discard

$ lsblk
NAME     MAJ:MIN RM   SIZE RO TYPE  MOUNTPOINT
sda        8:0    0 238.5G  0 disk  
├─sda1     8:1    0   100M  0 part  /boot
├─sda2     8:2    0  11.9G  0 part  
│ └─root 254:0    0  11.9G  0 crypt /
├─sda3     8:3    0 224.5G  0 part  
│ └─home 254:2    0 224.5G  0 crypt /home
└─sda4     8:4    0     2G  0 part  
  └─swap 254:1    0     2G  0 crypt [SWAP]
sr0       11:0    1  1024M  0 rom   

$ systemctl --version
systemd 232
+PAM -AUDIT -SELINUX -IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN

$ uname -a
Linux hal 4.9.7-1-ck-core2 #1 SMP PREEMPT Wed Feb 1 16:28:11 EST 2017 x86_64 GNU/Linux

Finally, here is the output of systemd-analyze dump: systemd-analyze-dump.txt

Contributor

mbiebl commented Feb 12, 2017

@evverx the Reloading bit is a red herring from what I can tell. It's caused by an if-up.d hook which is run when you run ifdown for a network interface.
Disabling that hook, systemd is no longer reloaded, the error message remains exactly the same

Contributor

mbiebl commented Feb 12, 2017

Sorry, this was supposed to go to @arvidjaar

Contributor

mbiebl commented Feb 12, 2017

root@debian:~# halt
         Stopping User Manager for UID 0...
[  OK  ] Stopped target Timers.
[  OK  ] Stopped Daily Cleanup of Temporary Directories.
[  OK  ] Stopped Daily apt activities.
         Stopping Session 1 of user root.
[  OK  ] Stopped D-Bus System Message Bus.
[  OK  ] Stopped OpenBSD Secure Shell server.
[  OK  ] Stopped Getty on tty1.
[  OK  ] Stopped Serial Getty on ttyS0.
[  OK  ] Stopped User Manager for UID 0.
[  OK  ] Stopped Session 1 of user root.
[  OK  ] Removed slice User Slice of root.
         Stopping Login Service...
[  OK  ] Removed slice system-serial\x2dgetty.slice.
         Stopping Permit User Sessions...
[  OK  ] Removed slice system-getty.slice.
[  OK  ] Stopped Login Service.
[  OK  ] Stopped LSB: exim Mail Transport Agent.
[  OK  ] Stopped Permit User Sessions.
[  OK  ] Stopped target Network is Online.
[  OK  ] Stopped target Network.
         Stopping Raise network interfaces...
[  OK  ] Stopped target Remote File Systems.
[  OK  ] Stopped target System Time Synchronized.
[  OK  ] Stopped target Basic System.
[  OK  ] Stopped target Sockets.
[  OK  ] Closed Syslog Socket.
[  OK  ] Stopped target Slices.
[  OK  ] Stopped target Paths.
[  OK  ] Closed D-Bus System Message Bus Socket.
[  OK  ] Stopped target System Initialization.
         Stopping Network Time Synchronization...
[  OK  ] Stopped target Swap.
         Deactivating swap /dev/disk/by-id/d…Erryep61K37oLHkYWnsMXUAEGfOlrCz...
         Stopping Update UTMP about System Boot/Shutdown...
         Stopping Load/Save Random Seed...
[  OK  ] Stopped target Encrypted Volumes.
[  OK  ] Stopped Forward Password Requests to Wall Directory Watch.
         Stopping Cryptography Setup for vda5_crypt...
[  OK  ] Stopped Dispatch Password Requests to Console Directory Watch.
[  OK  ] Removed slice User and Session Slice.
[  OK  ] Deactivated swap /dev/disk/by-uuid/…d03e0-736a-48ab-afce-0864f64c6154.
[  OK  ] Deactivated swap /dev/disk/by-id/dm…mBErryep61K37oLHkYWnsMXUAEGfOlrCz.
[  OK  ] Deactivated swap /dev/disk/by-id/dm-name-debian--vg-swap_1.
[  OK  ] Deactivated swap /dev/debian-vg/swap_1.
[  OK  ] Deactivated swap /dev/dm-3.
[  OK  ] Stopped Network Time Synchronization.
[  OK  ] Deactivated swap /dev/mapper/debian--vg-swap_1.
[  OK  ] Stopped Load/Save Random Seed.
[  OK  ] Stopped Update UTMP about System Boot/Shutdown.
[   23.287068] systemd[1]: Stopped (with error) /dev/dm-0.
[FAILED] Stopped (with error) /dev/dm-0.
[FAILED] Stopped (with error) /dev/mapper/vda5_crypt.
[FAILED] Stopped (with error) /dev/disk/by-i…0344c08681d8aec1645016-vda5_crypt.
[FAILED] Stopped (with error) /dev/disk/by-id/dm-name-vda5_crypt.
[FAILED] Stopped (with error) /sys/devices/virtual/block/dm-0.
[FAILED] Stopped (with error) /dev/disk/by-i…r-0srK-HqO4-eIyK-X1AF-wtox-W7SPa5.
[  OK  ] Stopped Raise network interfaces.
[  OK  ] Stopped Create Volatile Files and Directories.
[  OK  ] Stopped target Local File Systems.
         Unmounting /tmp...
         Unmounting /home...
         Unmounting /run/user/0...
         Unmounting /boot...
[  OK  ] Stopped Flush Journal to Persistent Storage.
         Unmounting /var...
[  OK  ] Stopped Apply Kernel Variables.
[  OK  ] Stopped Load Kernel Modules.
[  OK  ] Unmounted /home.
[  OK  ] Unmounted /run/user/0.
[  OK  ] Unmounted /boot.
[FAILED] Failed unmounting /var.
[  OK  ] Stopped File System Check on /dev/mapper/debian--vg-var.
[  OK  ] Stopped File System Check on /dev/d…70192-32b7-427a-a259-2842f242423d.
[  OK  ] Stopped File System Check on /dev/mapper/debian--vg-home.
[  OK  ] Unmounted /tmp.
[  OK  ] Stopped File System Check on /dev/mapper/debian--vg-tmp.
[  OK  ] Removed slice system-systemd\x2dfsck.slice.
[  OK  ] Stopped target Local File Systems (Pre).
[  OK  ] Stopped Remount Root and Kernel File Systems.
[  OK  ] Stopped Create Static Device Nodes in /dev.
         Stopping Monitoring of LVM2 mirrors…ng dmeventd or progress polling...
[  OK  ] Stopped Monitoring of LVM2 mirrors,…sing dmeventd or progress polling.
         Stopping LVM2 metadata daemon...
[  OK  ] Stopped LVM2 metadata daemon.
[  OK  ] Stopped Cryptography Setup for vda5_crypt.
[  OK  ] Reached target Unmount All Filesystems.
[  OK  ] Removed slice system-systemd\x2dcryptsetup.slice.
[  OK  ] Reached target Shutdown.
[   28.073561] systemd-shutdow: 41 output lines suppressed due to ratelimiting
[   28.128491] systemd-shutdown[1]: Sending SIGTERM to remaining processes...
[   28.133578] systemd-journald[286]: Received SIGTERM from PID 1 (systemd-shutdow).
[   28.152721] systemd-shutdown[1]: Sending SIGKILL to remaining processes...
[   28.156435] systemd-shutdown[1]: Unmounting file systems.
[   28.158873] systemd-shutdown[1]: Remounting '/var' read-only with options 'data=ordered'.
[   28.181220] EXT4-fs (dm-2): re-mounted. Opts: data=ordered
[   28.183117] systemd-shutdown[1]: Unmounting /var.
[   28.185023] systemd-shutdown[1]: Remounting '/' read-only with options 'errors=remount-ro,data=ordered'.
[   28.197008] EXT4-fs (dm-1): re-mounted. Opts: errors=remount-ro,data=ordered
[   28.199483] systemd-shutdown[1]: Remounting '/' read-only with options 'errors=remount-ro,data=ordered'.
[   28.201488] EXT4-fs (dm-1): re-mounted. Opts: errors=remount-ro,data=ordered
[   28.203421] systemd-shutdown[1]: Remounting '/' read-only with options 'errors=remount-ro,data=ordered'.
[   28.206063] EXT4-fs (dm-1): re-mounted. Opts: errors=remount-ro,data=ordered
[   28.208218] systemd-shutdown[1]: All filesystems unmounted.
[   28.209894] systemd-shutdown[1]: Deactivating swaps.
[   28.299569] reboot: System halted

@arvidjaar arvidjaar referenced this issue Mar 5, 2017

Closed

cryptsetup errors on shutdown #5527

1 of 2 tasks complete

shmerl commented Mar 6, 2017

I'm affected by this issue as well (current Debian testing). What is the safe way of shutting down / restarting to work around this bug? I don't want to potentially lose any data on each reboot.

db0451 commented Mar 6, 2017

I wasn't aware there was any evidence of this issue having any possible risk to data.

Rather, it seems to be a purely cosmetic/semantic problem of systemd trying to stop a device, which does not make sense.

shmerl commented Mar 6, 2017

@db0451 : See this comment. From it, it appears that there can be potential data loss. Can anyone please confirm whether these errors are safe or not?

@BPaden BPaden referenced this issue Mar 11, 2017

Closed

Encrypted devices #5568

1 of 2 tasks complete

jodumont commented Mar 13, 2017

I have 2systems running with Debian testing
One have this issue and is a brand new install
Both are built as a LVM in a dm-crypt on 1 SSD and use only XFS.

For the one with the issue:

  1. I remove the swap but I still have the issue
  2. I put /dev/mapper/vg-partition / in /etc/cryptsetup (it was like that by default anyway) but I still have the issue
  3. I seems to be on my vg-usr or vg-var partitions because others partitions are shutted down properly, so I start to play with fstab option without change

4. But wait: At the beginning I didn't had this issue it must be a services.

  1. than I reformat with just 3 partitions in my lvm (root, home, swap) and the problem disappear.
    5.1 But wait, Yes I have all the same software and the same services because I install through a script.

So what the difference ?

What I understand is it was unmounting / before /usr and /var and didn't like it. So far so good I don't have more explanation and hope it will help you to resolve your issue.

I have this error on each shutdown with my m.2 drive. I think it's causing my m.2 to show unsafe shutdowns. smartmontools shows: Unsafe Shutdowns: 156.

Stopped (with error) /dev/dm-3
Stopped (with error) /dev/dm-0
Stopped (with error) /dev/mapper/nvme0n1p5_crypt.
Stopped (with error) /sys/devices/virtual/block/dm-0
Stopped (with error) /dev/disk/by-id/dm-uuid-CRYPT-LUKS1-......................
Stopped (with error) /dev/disk/by-id/dm-name-nvme0n1p5_crypt.
Stopped (with error) /dev/disk/by-id/lvm-pv-uuid-......................

Olotila commented Apr 23, 2017

I get this on Ubuntu Gnome 17.04 with encrypted home folder, after shutdown. I get pass this only if I press Ctrl + Alt +F7:

Systemd[1]: Stopped (with error) /dev/devices/virtual/block/dm-0.
Systemd[1]: Stopped (with error) /dev/disk/by-uuid/xxx.
Systemd[1]: Stopped (with error) /dev/disk/by-id/dm-uuid-CRYPT-PLAIN-cryptswap1.
Systemd[1]: Stopped (with error) /dev/disk/by-id/raid-cryptswap1.
Systemd[1]: Stopped (with error) /dev/dm-0.
Systemd[1]: Stopped (with error) /dev/disk/by-id/dm-name-crytpswap1.

shahn commented Apr 24, 2017

@poettering please remove the needs-reporter-feedback label on this or state which kind of additional feedback is needed.

I'm affected by this too, running Kubuntu 17.04 (Linux 4.10.0-19-generic). As I've got 16GB of RAM and don't use hibernation, I don't have any swap activated or any partition for it at all. My fstab already uses /dev/mapper names and no UUIDs for the "normal" partitions / and /home, which are both encrypted (but it does use UUIDs for /boot and /boot/efi). Is there any other workaround on this? At all, it seems this has potential for loss of data. Removing encryption shouldn't be the only way to ensure that disks unmount properly and won't crash. Especially not if this is known for about a year and a half. :/

Same problem here, with Arch linux. I have the following setup: harddrive -> crypto -> filesystem, so no LVM and the like.

Interestingly, the problem did not occur up to recently, where I replaced the drive and went from ext4 to btrfs. Everything else is exactly the same setup (UUID/no-UUID in fstab/crypttab, ...). Also, looking at my logs, I see that the commands are in fact issued in the right order (first unmount filesystems, then close crypto device), but closing the crypto device is attempted before unmount succeeded. So maybe this is a race condition like issue?

Same problem here, Ubuntu 17.04, LUKS, no UUID used.

Can someone confirm that it is only cosmetic ? No risk of data loss ?

wavexx commented Jun 7, 2017

Thanks for the reply.
So we have a pretty serious (but common) issue, involving risk of data loss.
And nobody paid attention for about 20 months ? (I read **"No one assigned **)
What can we do to drag attention ?

ledoge commented Jun 8, 2017

I do not get the error anymore using systemd 233.

wavexx commented Jun 8, 2017

ioguix commented Jun 8, 2017

As a journaling FS such as ext4 or xfs will recover quickly, often too quickly to be spotted during boot, so you probably won't notice until a file is zeroed, lost or corrupted.

Oh, thank you, I had such a corruption some time ago in some local files, but I totally forgot about this issue and did not thought it could come from there...

I will probably not be able to investigate on this old corruption now though :/

I currently run a sync(1) job before shutdown.target.

@wavexx

Could you please describe this workaround ? Which script do you create/modify ?

wavexx commented Jun 12, 2017

For me I'm using the following workaround service with my encrypted /home:

[Unit]
Description=Unmount home on shutdown
Before=umount.target shutdown.target reboot.target halt.target

[Service]
Type=oneshot
RemainAfterExit=true
ExecStart=/bin/true
ExecStop=/bin/sh -c "umount /home"

[Install]
WantedBy=multi-user.target

It works except if someone is accessing /home (tracker for instance). I may have to somehow force the unmount if I don't find another solution.

clehner commented Jun 16, 2017

I have been experiencing this bug for some time on Raspbian 9 with encrypted root partition. Every time I boot the machine, i have to wait to for it to fsck the root partition that got uncleanly unmounted during shutdown. This is regardless of using UUID or the device name in fstab. I am going to try using a workaround service like @saintger suggested, to try to remount the partition as read-only ("mount -o remount,ro /") before the machine powers off. Edit: it didn't work.

Same problem here since updating to Ubuntu Gnome 17.04. Full-disk encryption on 3 separate machines and it happens on all of them.

It seems that Debian 9 has same problem, but Fedora 25 is unaffected.
Can someone confirm ?

I am using Debian 9 now for about one week on various machines including virtual ones. Three of the machines have an encrypted swap partition and they all do show the described issue on shutdown while unmounting swap: "Stopped (with error) /dev/dm-0".

Besides that those three machines have an encrypted home partiton either a regular partiton or a raid1. So far only one of them shows a related error on shutdown when /home umounts.

Some background: All machines use GPT partition scheme and dm-crypt/LUKS encrypted home is always mounted manually on the command line.

During the next weekend I am going to upgrade my last physical machine from Jessie to Stretch and I am interested to know how this machine will behave. I will further investigate the issue and will report back here.

shmerl commented Jun 29, 2017

This issue is gone for me (current Debian testing).

systemd: 233-9
Linux 4.11.0-1-amd64 #1 SMP Debian 4.11.6-1 (2017-06-19)

I'm not seeing the issue anymore.

systemd: 233-9
Linux 4.9.0-3-amd64 #1 SMP Debian 4.9.30-2 (2017-06-12) x86_64 GNU/Linux

petvoigt commented Jul 5, 2017

I'm not seeing the issue anymore.

systemd: 233-9
Linux 4.9.0-3-amd64 #1 SMP Debian 4.9.30-2 (2017-06-12) x86_64 GNU/Linux

Current versions of systemd and kernel of Debian Stretch are:

Linux kirk 4.9.0-3-amd64 #1 SMP Debian 4.9.30-2+deb9u2 (2017-06-26) x86_64 GNU/Linux
systemd: 232-25

Where did you install your systemd from?

shmerl commented Jul 5, 2017

Debian testing has systemd 233-9 and kernel 4.11.6.

petvoigt commented Jul 5, 2017

@shmerl: Thanks, I will try kernel and systemd from testing in a VM. But I hope, the Debian Stretch team will either fix systemd232-25 or upgrade it.

Grinderz commented Jul 5, 2017

error gone on Arch
systemd 233-6

Contributor

mbiebl commented Jul 5, 2017

See my comment in #5527 (comment)
"So, I've just upgraded that test VM to v233 and the errors were gone on shutdown.
Running a git bisect showed that it was fixed by c5a97ed

Posting it here, just in case someone else runs into this problem as well"

Why exactly this fixes those errors on shutdown is unclear to me.
As for Debian Stretch and v232: This patch seems too invasive to be backported for stretch

wavexx commented Jul 5, 2017

zifxify commented Jul 6, 2017

@mbiebl
So if we no do not upgrade systemd manually, pin to testing,sid or wait for stretch-backports we'll have this issue still for a long time in debian stable ? :(

Owner

keszybz commented Jul 10, 2017

@mbiebl I tried reproducing the bug using your recipe from #1620 (comment). I used the normal stretch amd64 installer, and got the same partition layout that you did, except with sda instead of vda, but I doubt that matters. It has systemd-232-5 and shuts down cleanly.

Can you maybe upload the image that exhibits the issue somewhere where I can download it?

--

Looking at the dependency graph, systemd-cryptsetup@vda5_crypt.service has After=dev-disk-by\x5cx2duuid-dd643cf7\x5cx2d01c4\x5cx2d497e\x5cx2db7a8\x5cx2dc8004fc8d8e3.device, and RequiredBy=dev-mapper-sda5_crypt.device, but there's no Before=dev-mapper-sda5_crypt.device. So when shutting down, systemd will could run the stop job for system-cryptsetup@.service before the stop job for the device(s) that depend on it.

I did systemctl stop systemd-cryptsetup@vda5_crypt.service and the logs show:

Jul 09 22:31:27 debianx systemd[1]: Stopped target Encrypted Volumes.
Jul 09 22:31:27 debianx systemd[1]: Stopping Cryptography Setup for sda5_crypt...
Jul 09 22:31:32 debianx systemd-cryptsetup[857]: Failed to deactivate: Device or resource busy
Jul 09 22:31:32 debianx systemd[1]: systemd-cryptsetup@sda5_crypt.service: Control process exited, code=exited status=1
Jul 09 22:31:32 debianx systemd[1]: Stopped Cryptography Setup for sda5_crypt.
Jul 09 22:31:32 debianx systemd[1]: systemd-cryptsetup@sda5_crypt.service: Unit entered failed state.
Jul 09 22:31:32 debianx systemd[1]: systemd-cryptsetup@sda5_crypt.service: Failed with result 'exit-code'.
Jul 09 22:32:57 debianx systemd[1]: sys-devices-virtual-block-dm\x2d0.device: Job sys-devices-virtual-block-dm\x2d0.device/stop timed out.
Jul 09 22:32:57 debianx systemd[1]: Timed out stopping /sys/devices/virtual/block/dm-0.
Jul 09 22:32:57 debianx systemd[1]: sys-devices-virtual-block-dm\x2d0.device: Job sys-devices-virtual-block-dm\x2d0.device/stop failed with result 'timeout'.
Jul 09 22:32:57 debianx systemd[1]: dev-disk-by\x2did-lvm\x2dpv\x2duuid\x2dn9ZuZI\x2d9tgU\x2d2Yoj\x2dirT8\x2dR4Bf\x2dSsGw\x2da6eoYP.device: Job dev-disk-by\x2did-lvm\x2dpv\x2duuid\x2dn9ZuZI\x2d9tgU\x2
Jul 09 22:32:57 debianx systemd[1]: Timed out stopping /dev/disk/by-id/lvm-pv-uuid-n9ZuZI-9tgU-2Yoj-irT8-R4Bf-SsGw-a6eoYP.
Jul 09 22:32:57 debianx systemd[1]: dev-disk-by\x2did-lvm\x2dpv\x2duuid\x2dn9ZuZI\x2d9tgU\x2d2Yoj\x2dirT8\x2dR4Bf\x2dSsGw\x2da6eoYP.device: Job dev-disk-by\x2did-lvm\x2dpv\x2duuid\x2dn9ZuZI\x2d9tgU\x2
Jul 09 22:32:57 debianx systemd[1]: dev-dm\x2d0.device: Job dev-dm\x2d0.device/stop timed out.
Jul 09 22:32:57 debianx systemd[1]: Timed out stopping /dev/dm-0.
Jul 09 22:32:57 debianx systemd[1]: dev-dm\x2d0.device: Job dev-dm\x2d0.device/stop failed with result 'timeout'.
Jul 09 22:32:57 debianx systemd[1]: dev-disk-by\x2did-dm\x2dname\x2dsda5_crypt.device: Job dev-disk-by\x2did-dm\x2dname\x2dsda5_crypt.device/stop timed out.
Jul 09 22:32:57 debianx systemd[1]: Timed out stopping /dev/disk/by-id/dm-name-sda5_crypt.
Jul 09 22:32:57 debianx systemd[1]: dev-disk-by\x2did-dm\x2dname\x2dsda5_crypt.device: Job dev-disk-by\x2did-dm\x2dname\x2dsda5_crypt.device/stop failed with result 'timeout'.
Jul 09 22:32:57 debianx systemd[1]: dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2ddd643cf701c4497eb7a8c8004fc8d8e3\x2dsda5_crypt.device: Job dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2ddd643
Jul 09 22:32:57 debianx systemd[1]: Timed out stopping /dev/disk/by-id/dm-uuid-CRYPT-LUKS1-dd643cf701c4497eb7a8c8004fc8d8e3-sda5_crypt.
Jul 09 22:32:57 debianx systemd[1]: dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2ddd643cf701c4497eb7a8c8004fc8d8e3\x2dsda5_crypt.device: Job dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2ddd643

Essentially, everything fails to stop, because stuff is mounted and devices are used, but systemd doesn't seem to know that.

Contributor

arvidjaar commented Jul 10, 2017

systemd will could run the stop job for system-cryptsetup@.service before the stop job for the device(s) that depend on it

stop job for device just waits for device to "disappear" so unless timeouts are set very low or cryptsetup takes very long it should not matter in this case.

This error is returned when "stop" job for device completes without timeout but device state at time of completion is not "stopped" (or device is still present in system from systemd PoV). One possible cause is systemd reload as I have demonstrated earlier. This is a bug that needs fixing. It is possible that some device event may cause premature job completion, I could not find it by code review.

All those countless "me too"s do not help - we are facing race condition so unless there is clearly understood root cause with deterministic reproducer it is impossible to claim it has been fixed. Relative timings may change from boot to boot, not to mention from version to version.

keszybz added a commit to keszybz/systemd that referenced this issue Jul 10, 2017

cryptsetup-generator: add Before=[luks device] to cryptsetup@ units
This simply adds one line to the generated unit:

  [Unit]
  Before=cryptsetup.target
  BindsTo=dev-disk-by\x2duuid-8db85dcf\x2d6230\x2d4e88\x2d940d\x2dba176d062b31.device
  After=dev-disk-by\x2duuid-8db85dcf\x2d6230\x2d4e88\x2d940d\x2dba176d062b31.device
  Before=umount.target
+ Before=dev-mapper-luks\x2d8db85dcf\x2d6230\x2d4e88\x2d940d\x2dba176d062b31.device
  BindsTo=dev-disk-by\x2duuid-8db85dcf\x2d6230\x2d4e88\x2d940d\x2dba176d062b31.device
  After=dev-disk-by\x2duuid-8db85dcf\x2d6230\x2d4e88\x2d940d\x2dba176d062b31.device
  Before=umount.target

Might fix #1620 — please test!
Owner

keszybz commented Jul 10, 2017

@arvidjaar it's likely that we're dealing with more than one bug here.

I started working on patch to test my theory about missing Before= dep, but now I see that won't work, because Before=*.device deps are not allowed. But I think I might be onto something — I don't see how systemd should know that the systemd-cryptsetup@.service should stay around until all devices it creates are unmounted. Afaics, there's no ordering that goes .mountluks.devicecryptsetup@.servicedev-disk.device.

Contributor

mbiebl commented Jul 10, 2017

@keszybz I can no longer reproduce it

Contributor

arvidjaar commented Jul 10, 2017

@keszybz

it's likely that we're dealing with more than one bug here

This issue is about quite specific error message. Users see this error message in conjunction with cryptsetup simply because cryptsetup is one of very few cases when device is (attempted to be) actively stopped. But cryptsetup itself does not cause this error. I completely agree that we have rather bad situation with proper ordering of units here but this needs its own report that makes it obvious, not buried in this hundred pages long one.

@mbiebl I can still easily trigger this error using 233 on openSUSE Tumbleweed. If you mean you do not see it during real shutdown - well, that's the nature of all races ... :)

rumpelsepp commented Jul 19, 2017

@keszybz I can no longer reproduce it

Problem seems to be gone now, at least on my machine. Since some update the error disappeared. I am on debian testing/sid:

$ systemctl --version
systemd 233
+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN default-hierarchy=hybrid
$ apt show systemd
Package: systemd
Version: 233-10
...

I have this issue with fresh installation of openSUSE 42.3 in my production servers.
While we are waiting for a fix, I've created small workaround for this issue - it seems sufficient for my case. If you brave enough you can try it too : https://github.com/DarkCaster/Systemd-Issue1620-Workaround

jugovic commented Oct 12, 2017

I have the same issue, using Ubuntu Gnome 17.04 .................. Absolutely same thing. Crypted Partition and Swap issue.....

Is there any solution (REAL SOLUTION) for this problem??

I will gladly pay someone to make it... if someone would like to do so.

All the best & please help folks

zifxify commented Oct 14, 2017

Tried systemd 234-3~bpo9+1 and 232-25+deb9u1, same results

NAME           MAJ:MIN RM   SIZE RO TYPE  MOUNTPOINT
sda              8:0    0 238.5G  0 disk  
└─sda1           8:1    0 235.9G  0 part  
  └─lvm        254:0    0 235.9G  0 crypt 
    ├─vg0-swap 254:1    0    16G  0 lvm   [SWAP]
    ├─vg0-root 254:2    0    25G  0 lvm   /
    ├─vg0-home 254:3    0   100G  0 lvm   /home
    ├─vg0-var  254:4    0    15G  0 lvm   /var
    └─vg0-qemu 254:5    0    60G  0 lvm   
Oct 14 11:55:01 kwicero systemd[1682]: systemd-cryptsetup@lvm.service: Executing: /lib/systemd/systemd-cryptsetup detach lvm
Oct 14 11:55:01 kwicero systemd[1683]: systemd-random-seed.service: Executing: /lib/systemd/systemd-random-seed save
Oct 14 11:55:01 kwicero systemd-cryptsetup[1682]: device-mapper: remove ioctl on lvm failed: Device or resource busy
Oct 14 11:55:01 kwicero systemd[1685]: systemd-backlight@leds:dell::kbd_backlight.service: Executing: /lib/systemd/systemd-backlight save leds:dell::kbd_backlight
Oct 14 11:55:01 kwicero systemd-timesyncd[724]: Removed server 0.debian.pool.ntp.org.
Oct 14 11:55:01 kwicero systemd-timesyncd[724]: Removed server 1.debian.pool.ntp.org.
Oct 14 11:55:01 kwicero systemd-timesyncd[724]: Removed server 2.debian.pool.ntp.org.
Oct 14 11:55:01 kwicero systemd-timesyncd[724]: Removed server 3.debian.pool.ntp.org.
Oct 14 11:55:01 kwicero systemd[1687]: dev-mapper-vg0\x2dswap.swap: Executing: /sbin/swapoff /dev/mapper/vg0-swap
Oct 14 11:55:01 kwicero systemd[1688]: systemd-update-utmp.service: Executing: /lib/systemd/systemd-update-utmp shutdown
Oct 14 11:55:01 kwicero systemd-update-utmp[1688]: systemd-update-utmp running as pid 1688
Oct 14 11:55:01 kwicero systemd-update-utmp[1688]: systemd-update-utmp stopped as pid 1688
Oct 14 11:55:02 kwicero systemd[1701]: home-zifxify-Bestanden-3._Werk.mount: Executing: /bin/umount /home/zifxify/Bestanden/3._Werk
Oct 14 11:55:02 kwicero systemd[1702]: tmp.mount: Executing: /bin/umount /tmp
Oct 14 11:55:02 kwicero systemd[1703]: run-user-1000.mount: Executing: /bin/umount /run/user/1000
Oct 14 11:55:02 kwicero systemd[1704]: var.mount: Executing: /bin/umount /var
Oct 14 11:55:02 kwicero systemd[1709]: home.mount: Executing: /bin/umount /home
Oct 14 11:55:02 kwicero systemd[1712]: lvm2-monitor.service: Executing: /sbin/lvm vgchange --monitor n --ignoreskippedcluster
Oct 14 11:55:02 kwicero lvm[1712]:   5 logical volume(s) in volume group "vg0" unmonitored
Oct 14 11:55:02 kwicero lvmetad[392]: Failed to accept connection errno 11.
Oct 14 11:55:02 kwicero systemd-cryptsetup[1682]: device-mapper: remove ioctl on lvm failed: Device or resource busy
Oct 14 11:55:02 kwicero systemd-cryptsetup[1682]: device-mapper: remove ioctl on lvm failed: Device or resource busy
Oct 14 11:55:02 kwicero systemd-cryptsetup[1682]: device-mapper: remove ioctl on lvm failed: Device or resource busy
Oct 14 11:55:02 kwicero systemd-cryptsetup[1682]: device-mapper: remove ioctl on lvm failed: Device or resource busy
Oct 14 11:55:02 kwicero systemd-cryptsetup[1682]: device-mapper: remove ioctl on lvm failed: Device or resource busy
Oct 14 11:55:03 kwicero systemd-cryptsetup[1682]: device-mapper: remove ioctl on lvm failed: Device or resource busy
Oct 14 11:55:03 kwicero systemd-cryptsetup[1682]: device-mapper: remove ioctl on lvm failed: Device or resource busy
Oct 14 11:55:03 kwicero systemd-cryptsetup[1682]: device-mapper: remove ioctl on lvm failed: Device or resource busy
Oct 14 11:55:03 kwicero systemd-cryptsetup[1682]: device-mapper: remove ioctl on lvm failed: Device or resource busy
Oct 14 11:55:06 kwicero kernel: systemd-cryptse: 17 output lines suppressed due to ratelimiting
Oct 14 11:55:06 kwicero systemd[1]: systemd-journald.service: Received EPOLLHUP on stored fd 33 (stored), closing.
Oct 14 11:55:06 kwicero systemd[1]: Received SIGCHLD from PID 1682 (systemd-cryptse).
Oct 14 11:55:06 kwicero systemd[1]: Child 1682 (systemd-cryptse) died (code=exited, status=1/FAILURE)
Oct 14 11:55:06 kwicero systemd[1]: systemd-cryptsetup@lvm.service: Child 1682 belongs to systemd-cryptsetup@lvm.service
Oct 14 11:55:06 kwicero systemd[1]: systemd-cryptsetup@lvm.service: Control process exited, code=exited status=1
Oct 14 11:55:06 kwicero systemd[1]: systemd-cryptsetup@lvm.service: Got final SIGCHLD for state stop.
Oct 14 11:55:06 kwicero systemd[1]: systemd-cryptsetup@lvm.service: Changed stop -> failed
Oct 14 11:55:06 kwicero systemd[1]: systemd-cryptsetup@lvm.service: Job systemd-cryptsetup@lvm.service/stop finished, result=done
Oct 14 11:55:06 kwicero systemd[1]: Stopped Cryptography Setup for lvm.
Oct 14 11:55:06 kwicero systemd[1]: systemd-cryptsetup@lvm.service: Unit entered failed state.
Oct 14 11:55:06 kwicero systemd[1720]: systemd-poweroff.service: Executing: /bin/systemctl --force poweroff
Oct 14 11:55:06 kwicero systemctl[1720]: Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=PowerOff cookie=1 reply_cookie=0 error=n/a
Oct 14 11:55:06 kwicero systemctl[1720]: Got message type=method_return sender=n/a destination=n/a object=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 error=n/a
Oct 14 11:55:06 kwicero kernel: systemd-shutdow: 4636 output lines suppressed due to ratelimiting
Oct 14 11:55:06 kwicero systemd-journald[352]: Journal stopped

vsespb commented Nov 5, 2017

happens in ubuntu 16.04 (only visible in logs!) and debian 9 (either delay 90 seconds or red lines in logs).

is there any workaround to minimize chance of data loss ? i.e. sync disks?

wavexx commented Nov 5, 2017

vsespb commented Nov 6, 2017

At least is there way to setup new system with LUKS, with workaround for the issue making it safe against data-loss: for example maybe use separate partitions for root, /var and /tmp, and remount root as readonly (or it's already remounted?) before shutdown?

Contributor

mbiebl commented Nov 6, 2017

I'm not aware that this is actually causing data loss

wavexx commented Nov 6, 2017

Contributor

mbiebl commented Nov 6, 2017

@wavexx where exactly das systemd fail to unmount a filesystem or remount it ro?

wavexx commented Nov 6, 2017

Contributor

mbiebl commented Nov 6, 2017

@wavexx which log shows that the file system is not unmounted? I don't see a complete log anywhere which shows that the file system was not unmounted

wavexx commented Nov 7, 2017

Contributor

mbiebl commented Nov 12, 2017

@wavexx please follow the instructions at https://freedesktop.org/wiki/Software/systemd/Debugging
Specifically "Diagnosing Shutdown Problems". Adjust the kernel parameters (to avoid the kernel rate limiting). Keep in mind that on Debian/Ubuntu the debug.sh script location should be /lib/systemd/system-shutdown/debug.sh

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment