How can I identify which systemd service(s) are timing out from this log ? eg. Timed out stopping /dev/dm-0

Question

In the partial log below, those dev-disk and dev-dm lines with timed out and timeout, how can I find out which service(eg. that.service) is responsible for them, so that I can for example append an After=that.service in my qubes-core.service (seen below as Qubes Dom0 startup setup) to ensure it is stopped first ?

[ 3866.707545] systemd[1]: Started Show Plymouth Reboot Screen.
[ 3866.777998] qmemman.systemstate[1620]: mem-set domain 3 to 4194304000
[ 3866.778860] qmemman.systemstate[1620]: mem-set domain 7 to 4194304000
[ 3866.779587] qmemman.systemstate[1620]: mem-set domain 6 to 4194304000
[ 3866.951011] systemd[1]: Stopped Restore /run/initramfs on shutdown.
[ 3871.685359] systemd[1]: Received SIGRTMIN+20 from PID 9952 (plymouthd).
[ 3956.361763] systemd[1]: dev-disk-by\x2did-dm\x2dname\x2dluks\x2d9ed952b5\x2d2aa8\x2d4564\x2db700\x2dfb23f5c9e94b.device: Job dev-disk-by\x2did-dm\x2dname\x2dluks\x2d9ed952b5\x2d2aa8\x2d4564\x2db700\x2dfb23f5c9e94b.device/stop timed out.
[ 3956.362322] systemd[1]: Timed out stopping /dev/disk/by-id/dm-name-luks-9ed952b5-2aa8-4564-b700-fb23f5c9e94b.
[ 3956.362945] systemd[1]: dev-disk-by\x2did-dm\x2dname\x2dluks\x2d9ed952b5\x2d2aa8\x2d4564\x2db700\x2dfb23f5c9e94b.device: Job dev-disk-by\x2did-dm\x2dname\x2dluks\x2d9ed952b5\x2d2aa8\x2d4564\x2db700\x2dfb23f5c9e94b.device/stop failed with result 'timeout'.
[ 3956.363698] systemd[1]: dev-disk-by\x2did-lvm\x2dpv\x2duuid\x2dpxC3ch\x2d0MF0\x2dOzJs\x2dJogd\x2d9rOz\x2dJkSt\x2dCf8G7m.device: Job dev-disk-by\x2did-lvm\x2dpv\x2duuid\x2dpxC3ch\x2d0MF0\x2dOzJs\x2dJogd\x2d9rOz\x2dJkSt\x2dCf8G7m.device/stop timed out.
[ 3956.363702] systemd[1]: Timed out stopping /dev/disk/by-id/lvm-pv-uuid-pxC3ch-0MF0-OzJs-Jogd-9rOz-JkSt-Cf8G7m.
[ 3956.366332] systemd[1]: dev-disk-by\x2did-lvm\x2dpv\x2duuid\x2dpxC3ch\x2d0MF0\x2dOzJs\x2dJogd\x2d9rOz\x2dJkSt\x2dCf8G7m.device: Job dev-disk-by\x2did-lvm\x2dpv\x2duuid\x2dpxC3ch\x2d0MF0\x2dOzJs\x2dJogd\x2d9rOz\x2dJkSt\x2dCf8G7m.device/stop failed with result 'timeout'.
[ 3956.367093] systemd[1]: dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2d9ed952b52aa84564b700fb23f5c9e94b\x2dluks\x2d9ed952b5\x2d2aa8\x2d4564\x2db700\x2dfb23f5c9e94b.device: Job dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2d9ed952b52aa84564b700fb23f5c9e94b\x2dluks\x2d9ed952b5\x2d2aa8\x2d4564\x2db700\x2dfb23f5c9e94b.device/stop timed out.
[ 3956.367098] systemd[1]: Timed out stopping /dev/disk/by-id/dm-uuid-CRYPT-LUKS1-9ed952b52aa84564b700fb23f5c9e94b-luks-9ed952b5-2aa8-4564-b700-fb23f5c9e94b.
[ 3956.368768] systemd[1]: dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2d9ed952b52aa84564b700fb23f5c9e94b\x2dluks\x2d9ed952b5\x2d2aa8\x2d4564\x2db700\x2dfb23f5c9e94b.device: Job dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2d9ed952b52aa84564b700fb23f5c9e94b\x2dluks\x2d9ed952b5\x2d2aa8\x2d4564\x2db700\x2dfb23f5c9e94b.device/stop failed with result 'timeout'.
[ 3956.368789] systemd[1]: dev-dm\x2d0.device: Job dev-dm\x2d0.device/stop timed out.
[ 3956.368808] systemd[1]: Timed out stopping /dev/dm-0.
[ 3956.372748] systemd[1]: dev-dm\x2d0.device: Job dev-dm\x2d0.device/stop failed with result 'timeout'.
[ 3956.372769] systemd[1]: sys-devices-virtual-block-dm\x2d0.device: Job sys-devices-virtual-block-dm\x2d0.device/stop timed out.
[ 3956.372774] systemd[1]: Timed out stopping /sys/devices/virtual/block/dm-0.
[ 3956.375485] systemd[1]: sys-devices-virtual-block-dm\x2d0.device: Job sys-devices-virtual-block-dm\x2d0.device/stop failed with result 'timeout'.
[ 3956.375509] systemd[1]: session-2.scope: Stopping timed out. Killing.
[ 3956.375570] systemd[1]: session-2.scope: Killing process 3576 (qubes-guid) with signal SIGKILL.
[ 3956.376535] systemd[1]: Stopped Session 2 of user ctor.
[ 3956.381215] systemd[1]: session-2.scope: Unit entered failed state.
[ 3956.381915] systemd[1]: Removed slice User Slice of ctor.
[ 3956.385125] systemd[1]: Stopping Login Service...
[ 3956.389095] systemd[1]: Stopping Permit User Sessions...
[ 3956.393457] systemd[1]: Stopped Permit User Sessions.
[ 3956.396533] systemd[1]: Stopped Start Qubes VM sys-firewall.
[ 3956.399094] systemd[1]: Stopped Start Qubes VM sys-net.
[ 3956.402260] systemd[1]: Removed slice system-qubes\x2dvm.slice.
[ 3956.405398] systemd[1]: Stopping Qubes memory information reporter...
[ 3956.409027] systemd[1]: Stopped Qubes memory information reporter.
[ 3956.413280] systemd[1]: Stopping Qubes Dom0 startup setup...
[ 3956.433905] preshutdown[9971]: Name                                        ID   Mem VCPUs    State   Time(s)
[ 3956.438400] preshutdown[9971]: Domain-0                                     0  4071     6     r-----     706.6
[ 3956.439730] preshutdown[9971]: sys-net                                      1   384     2     -b----      10.7
[ 3956.441032] preshutdown[9971]: sys-net-dm                                   2   144     1     -b----     151.6
[ 3956.442332] preshutdown[9971]: sys-firewall                                 3  3983     2     -b----      15.0

Looks like it's `/usr/lib/systemd/system/udisks2.service` but I don't remember how I figured it out! So an answer is still welcome. — , Sep 04 '18 at 00:01
No, that wasn't it: it's not udisks2.service ! (funny thing is, the next boot worked as if it were it, but next after that is back to timeouts, without me changing anything) — , Sep 04 '18 at 00:28

slm · Accepted Answer · 2018-09-04T02:07:29.103

You can use the systemctl show <device> to see more details on the unit file that's handling the *.device.

For example, on my CentOS 7.x system if we look through the journalctl -b for some devices:

$ journalctl -b | grep 'systemd\[1\]: dev-disk-by' | head -3
Sep 03 17:48:57 centos7 systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:00:01.1\x2data\x2d1.0.device changed dead -> plugged
Sep 03 17:48:57 centos7 systemd[1]: dev-disk-by\x2did-ata\x2dVBOX_HARDDISK_VBc5aaf476\x2df419b1f1.device changed dead -> plugged
Sep 03 17:48:57 centos7 systemd[1]: dev-disk-by\x2duuid-013c42ea\x2daa00\x2d4713\x2d926a\x2daca57c0bd552.device changed dead -> plugged

Now if we inquire to systemd about one of these .device files:

$ systemctl show 'dev-disk-by\x2duuid-013c42ea\x2daa00\x2d4713\x2d926a\x2daca57c0bd552.device'
SysFSPath=/sys/devices/pci0000:00/0000:00:01.1/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda2
Id=dev-disk-by\x5cx2duuid-013c42ea\x5cx2daa00\x5cx2d4713\x5cx2d926a\x5cx2daca57c0bd552.device
Names=dev-disk-by\x5cx2duuid-013c42ea\x5cx2daa00\x5cx2d4713\x5cx2d926a\x5cx2daca57c0bd552.device
Following=sys-devices-pci0000:00-0000:00:01.1-ata1-host0-target0:0:0-0:0:0:0-block-sda-sda2.device
Description=VBOX_HARDDISK 2
LoadState=loaded
ActiveState=active
SubState=plugged
InactiveExitTimestamp=Mon 2018-09-03 21:48:59 EDT
InactiveExitTimestampMonotonic=4178671
ActiveEnterTimestamp=Mon 2018-09-03 21:48:59 EDT
ActiveEnterTimestampMonotonic=4178671
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
CanStart=no
CanStop=no
CanReload=no
CanIsolate=no
StopWhenUnneeded=no
RefuseManualStart=no
RefuseManualStop=no
AllowIsolate=no
DefaultDependencies=yes
OnFailureJobMode=replace
IgnoreOnIsolate=yes
IgnoreOnSnapshot=yes
NeedDaemonReload=no
JobTimeoutUSec=1min 30s
JobTimeoutAction=none
ConditionResult=no
AssertResult=no
ConditionTimestampMonotonic=0
AssertTimestampMonotonic=0
Transient=no

NOTE: That the \x2d is actually the ASCII code for a dash.

$ printf '\x2d\n'
-

After=?

What does one set in other services so that they'll start after the .device files? For this you'll want to use this, After=system.device. You can see this device's status like this, though it isn't very telling:

$ systemctl status system.device
● system.device
   Loaded: loaded
   Active: inactive (dead)

Sep 03 21:49:52 centos7 systemd[1]: Collecting system.device

NOTE: You can also interchangeably use systemd.device.

References

Is there a parent service that's starting/stopping those? I need to be able to do `After=thatparent.service` on my service, so that my service stops first before these disks get unmounted. I mean for example I used `After=dev-block-253:0.device` and it worked for 2 consecutive reboots, as expected; but the 3rd one acted as if the change wasn't made so it timed out again: https://gist.github.com/constantoverride/61207ebf622263d25fb1e5b1f11d0148#gistcomment-2696607 — , Sep 04 '18 at 01:17
@MarcusLinsner - for the `After=` you want to make it `After=system.device`. — slm, Sep 04 '18 at 01:50
Perhaps somewhat unexpectedly, this also works: `systemctl show '*.device'` (or `systemctl show \*.device` ) — , Sep 04 '18 at 08:20
How does [this](https://github.com/systemd/systemd/issues/10058#issuecomment-420217581) comment by a systemd dev. affect this q/a ? It seems like I should be looking for a service (other than system(d).service) that's starting those DM/LVM, and yet something like `lvm2-pvscan@253:0.service` doesn't seem to be the answer [because](https://gist.github.com/constantoverride/b9e94210007c6b50503dbe804ebaf657/162c89d5485e48fb43dbd45dd14749c62458c7ec#gistcomment-2704027) devices still stop(and wait until the 90sec timeout) before my service's ExecStop, even tho they shouldn't be stopped before my serv — , Sep 11 '18 at 20:03

How can I identify which systemd service(s) are timing out from this log ? eg. Timed out stopping /dev/dm-0

1 Answers1

After=?

References

Linked

Related