Howto debug SystemD stuck in shutdown waiting for process timeout

This is a simple howto about how to know what makes your shutdown or reboot process being stuck for a few minutes.

The reason is basically because there's a process which didn't ended correctly (and systemd doesn't tell you which one is :man_facepalming: ) so let's use this small howto to know what is happening:

First create a small script file that will debug the process, just copy-paste this piece of code in your terminal, in root mode (run first "sudo su") :

mkdir -p /usr/lib/systemd/system-shutdown
cat > /usr/lib/systemd/system-shutdown/debug.sh << EOF
#!/bin/sh
mount -o remount,rw /
dmesg > /shutdown-log.txt
mount -o remount,ro /
EOF
chmod a+x  /usr/lib/systemd/system-shutdown/debug.sh

Reboot your computer and in your boot (grub) menu press the key e to edit the "linux" line and append these parameters: systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M printk.devkmsg=on enforcing=0, then press F10 to boot from them

Optionally, another option is to edit the grub parameters to always include it, especially if you want to run this debug in multiple boots

Instead, before to reboot, edit your /etc/default/grub file and duplicate your line containing GRUB_CMDLINE_LINUX_DEFAULT to add some needed parameters, like on this example:

#GRUB_CMDLINE_LINUX_DEFAULT="quiet splash resume=/dev/disk/by-uuid/2b88d226-2a70-46c6-9cbf-8086bacf4343"
GRUB_CMDLINE_LINUX_DEFAULT="quiet splash resume=/dev/disk/by-uuid/2b88d226-2a70-46c6-9cbf-8086bacf4343  systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M printk.devkmsg=on enforcing=0
"

Update your grub to use them:

sudo update-grub

Remember to disable it once you finished with your debug


Now, boot your computer to have this setting take effect, and shutdown it after it booted correctly (do not force the shutdown, it may take a few minutes stuck)

Boot your computer again, you will find a file in your / directory which includes details of what was happening, check especially the times where you can find the biggest pauses, for example on my case I found:

[  110.228515] systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=3826 reply_cookie=0 signature=so error-name=n/a error-message=n/a
[  110.228585] systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=3827 reply_cookie=0 signature=so error-name=n/a error-message=n/a
[  136.706495] systemd[1]: systemd-logind.service: Got notification message from PID 788 (WATCHDOG=1)
[  137.461212] systemd[1]: systemd-udevd.service: Got notification message from PID 437 (WATCHDOG=1)
[  196.677655] systemd[1]: session-1.scope: Stopping timed out. Killing.
[  196.678313] systemd[1]: session-1.scope: Killing process 1330 (VBoxClient) with signal SIGKILL.

We can read in these last two lines that there was a big pause with the previous one, session-1.scope had a timeout and required a kill of a process, in the next line we can see the name of that process, it was the VBoxClient process which was stuck for some unknown reason. After to have removed all my virtualbox packages (and updated the initramfs files and grub), the next shutdowns didn't had the stuck delay

Important: remember to remove the boot options and delete the debug script after you finished