3

I have installed Debian 10 Desktop. I notice shutdown is frequently delayed, by 1 minute 30 seconds. I do not have this problem on my Debian 9 install. (Or at least, not nearly so often).

I can also see the delay when I look at the system log afterwards (journalctl). I would like to analyze these logs.

In one case, the problem appeared to be the user service pulseaudio.service. If so, it would be easy to work around this specifically, e.g by setting TimeoutStopSec=2 on the service. (Note this is not a system service, it is a user service. There is no system service pulseaudio.service).

In the second case I looked at, pulseaudio.service appears to shut down as soon as it is asked. If so, setting a timeout there would not help :-). Instead, there appears to be this long delay before systemd even asks pulseaudio.service to stop. When I look at this second log, I can't work out where the problem is.

There is a broader workaround that might work (see end). But I want to know specifically where the problem is.

Question

  1. Does the second log below show a specific problem, i.e. one that I failed to identify?
  2. Is there any expected or known case, where a software error could cause the log below, and the log would not identify the specific problem?

My current systemd package version is 241-5.

UPDATE

I thought this issue sounded the same as issue #12262. The fix for that issue was "cgroup-util: kill also threads" (PR #12621), merged in systemd version 243.

The discussion in the PR link, suggests that bug is specific to cgroupsv2 ("unified control group hierarchy"). Debian 10 uses cgroupsv2, and Debian 9 does not. More specifically, Debian 10 uses a transitional, "hybrid" hierarchy.

Therefore I tried adding systemd.legacy_systemd_cgroup_controller to the kernel boot options. When using this option, I can see the cgroup2 filesystem is not mounted anywhere, only cgroup. Sadly, I still saw this unexplained type of shutdown delay.

Full log: log-shutdown-delay2.txt

Sep 08 16:24:25 drystone kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-4.19.0-5-amd64 root=UUID=f10753fb-0a2d-4288-971d-5f33682ab5c0 ro systemd.legacy_systemd_cgroup_controller quiet

Sep 08 16:54:28 drystone systemd[1]: Stopped Firmware update daemon.
Sep 08 16:55:58 drystone systemd[1442]: Stopping D-Bus User Message Bus...
Sep 08 16:55:58 drystone systemd[1442]: Stopped target Default.
Sep 08 16:55:58 drystone systemd[1442]: Stopping Sound Service...
Sep 08 16:55:58 drystone systemd[1442]: pulseaudio.service: Succeeded.
Sep 08 16:55:58 drystone systemd[1442]: Stopped Sound Service.
Sep 08 16:55:58 drystone systemd[1442]: dbus.service: Main process exited, code=killed, status=15/TERM
Sep 08 16:55:58 drystone systemd[1442]: dbus.service: Succeeded.
Sep 08 16:55:58 drystone systemd[1442]: Stopped D-Bus User Message Bus.
Sep 08 16:55:58 drystone systemd[1442]: Stopped target Basic System.
Sep 08 16:55:58 drystone systemd[1442]: Stopped target Paths.
Sep 08 16:55:58 drystone systemd[1442]: Stopped target Timers.

Also according to the PR discussion, an alternative fix is to use a Linux kernel version 5.2 or above. The kernel fix commit is "cgroup: Include dying leaders with live threads in PROCS iterations". This has also been included in the stable kernel series 4.19.x. The stable commit is dated 2019-06-10. However at the time of writing, the current Debian 10 kernel is based on 4.19.67, which was released around 2019-04-27. So this Debian kernel does not include the fix yet.


1. pulseaudio shutdown delay

Aug 31 08:40:28 drystone systemd[1862]: Stopped target Default.
Aug 31 08:40:28 drystone systemd[1862]: Stopping Sound Service...
Aug 31 08:40:28 drystone systemd[1]: Stopping User Manager for UID 1005...

...

Aug 31 08:41:57 drystone systemd[1862]: Stopping D-Bus User Message Bus...
Aug 31 08:41:57 drystone systemd[1862]: pulseaudio.service: Succeeded.
Aug 31 08:41:57 drystone systemd[1862]: Stopped Sound Service.
Aug 31 08:41:57 drystone systemd[1862]: dbus.service: Main process
exited, code=killed, status=15/TERM
Aug 31 08:41:57 drystone systemd[1862]: dbus.service: Succeeded.
Aug 31 08:41:57 drystone systemd[1862]: Stopped D-Bus User Message Bus.
Aug 31 08:41:57 drystone systemd[1862]: Stopped target Basic System.

...

Aug 31 08:41:57 drystone systemd[1862]: Reached target Shutdown.
Aug 31 08:41:57 drystone systemd[1862]: systemd-exit.service: Succeeded.
Aug 31 08:41:57 drystone systemd[1862]: Started Exit the Session.
Aug 31 08:41:57 drystone systemd[1862]: Reached target Exit the Session.
Aug 31 08:41:57 drystone systemd[1863]:
pam_unix(systemd-user:session): session closed for user mike

...

Aug 31 08:41:57 drystone systemd[1]: user@1005.service: Succeeded.
Aug 31 08:41:57 drystone systemd[1]: Stopped User Manager for UID 1005.

2. unexplained shutdown delay

Full log: log-shutdown-delay.txt

Sep 03 11:42:47 drystone systemd[1]: Stopping User Manager for UID 1001...

...

Sep 03 11:42:47 drystone systemd[1]: Stopped Login Service.
Sep 03 11:44:16 drystone systemd[1359]: Stopping D-Bus User Message Bus...
Sep 03 11:44:16 drystone systemd[1359]: Stopping Sound Service...
Sep 03 11:44:16 drystone systemd[1359]: pulseaudio.service: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Stopped Sound Service.
Sep 03 11:44:16 drystone systemd[1359]: dbus.service: Main process exited, code=killed, status=15/TERM
Sep 03 11:44:16 drystone systemd[1359]: dbus.service: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Stopped D-Bus User Message Bus.
Sep 03 11:44:16 drystone systemd[1359]: Stopped target Basic System.
Sep 03 11:44:16 drystone systemd[1359]: Stopped target Sockets.
Sep 03 11:44:16 drystone systemd[1359]: gpg-agent.socket: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Closed GnuPG cryptographic agent and passphrase cache.
Sep 03 11:44:16 drystone systemd[1359]: gpg-agent-ssh.socket: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Closed GnuPG cryptographic agent (ssh-agent emulation).
Sep 03 11:44:16 drystone systemd[1359]: dbus.socket: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Closed D-Bus User Message Bus Socket.
Sep 03 11:44:16 drystone systemd[1359]: gpg-agent-browser.socket: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Closed GnuPG cryptographic agent and passphrase cache (access for web browsers).
Sep 03 11:44:16 drystone systemd[1359]: gpg-agent-extra.socket: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Closed GnuPG cryptographic agent and passphrase cache (restricted).
Sep 03 11:44:16 drystone systemd[1359]: dirmngr.socket: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Closed GnuPG network certificate management daemon.
Sep 03 11:44:16 drystone systemd[1359]: Stopped target Timers.
Sep 03 11:44:16 drystone systemd[1359]: Stopped target Paths.
Sep 03 11:44:16 drystone systemd[1359]: pulseaudio.socket: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Closed Sound System.
Sep 03 11:44:16 drystone systemd[1359]: Reached target Shutdown.
Sep 03 11:44:16 drystone systemd[1359]: systemd-exit.service: Succeeded.
Sep 03 11:44:16 drystone systemd[1359]: Started Exit the Session.
Sep 03 11:44:16 drystone systemd[1359]: Reached target Exit the Session.
Sep 03 11:44:16 drystone systemd[1360]: pam_unix(systemd-user:session): session closed for user alan-sysop
Sep 03 11:44:16 drystone systemd[1]: user@1001.service: Succeeded.
Sep 03 11:44:16 drystone systemd[1]: Stopped User Manager for UID 1001.

Disclosure: this linked log also includes 13 lines systemd[1]: Received SIGINT. These are from me pressing Ctrl+Alt+Del. AFAIK this had no effect, except to toggle the plymouth boot splash. And the first such message is after the system has hung for 30 seconds. So I think we can ignore this.

I cannot find ordering dependencies that would delay pulseaudio.service

No service file has an explicit ordering dependency on pulseaudio.service:

$ grep -r pulseaudio.service /usr/lib/systemd/user/
$

Nor vice versa:

$ systemctl --user cat pulseaudio.service
# /usr/lib/systemd/user/pulseaudio.service
[Unit]
Description=Sound Service

# We require pulseaudio.socket to be active before starting the daemon, because
# while it is possible to use the service without the socket, it is not clear
# why it would be desirable.
#
# A user installing pulseaudio and doing `systemctl --user start pulseaudio`
# will not get the socket started, which might be confusing and problematic if
# the server is to be restarted later on, as the client autospawn feature
# might kick in. Also, a start of the socket unit will fail, adding to the
# confusion.
#
# After=pulseaudio.socket is not needed, as it is already implicit in the
# socket-service relationship, see systemd.socket(5).
Requires=pulseaudio.socket
ConditionUser=!root

[Service]
# Note that notify will only work if --daemonize=no
Type=notify
ExecStart=/usr/bin/pulseaudio --daemonize=no
Restart=on-failure

[Install]
Also=pulseaudio.socket
WantedBy=default.target

My current attempt at a workaround

diff --git a/systemd/system/user@.service.d/override.conf b/systemd/system/user@.service.d/override.conf
new file mode 100644
index 0000000..86734ef
--- /dev/null
+++ b/systemd/system/user@.service.d/override.conf
@@ -0,0 +1,2 @@
+[Service]
+TimeoutStopSec=7s
diff --git a/systemd/user.conf b/systemd/user.conf
index b427f1e..cb5b646 100644
--- a/systemd/user.conf
+++ b/systemd/user.conf
@@ -21,7 +21,7 @@
 #DefaultStandardOutput=inherit
 #DefaultStandardError=inherit
 #DefaultTimeoutStartSec=90s
-#DefaultTimeoutStopSec=90s
+DefaultTimeoutStopSec=5s
 #DefaultRestartSec=100ms
 #DefaultStartLimitIntervalSec=10s
 #DefaultStartLimitBurst=5
2
  • I have smth similar. However, I have Manjaro. Couldn't it be specifically Mate desktop env.?
    – Andra
    May 27 '20 at 15:55
  • @Andra I use(d) GNOME, not Mate. I stand by the answer, and the UPDATE in my question. There was a problem somewhere in systemd and/or the kernel, and it was not caused by a desktop environment. Hopefully the kernel fix I mentioned should be included in the current Debian 10 kernel, but I have not checked it.
    – sourcejedi
    May 27 '20 at 19:30
1

I want to know specifically where the problem is.

After I applied the broad workaround, when this problem happens, systemd says the problem is specific to - systemd :-).

Specifically, the system manager is forced to terminate the "User Manager". I see the "User Manager" has no child processes left to wait for. Otherwise, the log would have shown them being killed as well.

Of course, it is still possible the bug is not in systemd, but e.g. in the kernel.

Sep 13 20:21:58 drystone systemd[1]: Stopping User Manager for UID 1005...
Sep 13 20:21:58 drystone systemd[1531]: Stopping Sound Service...
Sep 13 20:22:05 drystone systemd[1]: user@1005.service: State 'stop-sigterm' timed out. Killing.
Sep 13 20:22:05 drystone systemd[1]: user@1005.service: Killing process 1531 (systemd) with signal SIGKILL.
Sep 13 20:22:05 drystone systemd[1]: user@1005.service: Main process exited, code=killed, status=9/KILL
Sep 13 20:22:05 drystone systemd[1]: user@1005.service: Failed with result 'timeout'.
Sep 13 20:22:05 drystone systemd[1]: Stopped User Manager for UID 1005.

And here is an example where pulseaudio is killed as well. This log is also very strange. The system manager asks the user manager to stop, but the user manager does not ask any of the user units to stop.

Sep 20 19:47:46 drystone systemd[1]: Stopping User Manager for UID 1005...
Sep 20 19:47:53 drystone systemd[1]: user@1005.service: State 'stop-sigterm' timed out. Killing.
Sep 20 19:47:53 drystone systemd[1]: user@1005.service: Killing process 1459 (systemd) with signal SIGKILL.
Sep 20 19:47:53 drystone systemd[1]: user@1005.service: Killing process 1551 (pulseaudio) with signal SIGKILL.
Sep 20 19:47:53 drystone systemd[1]: user@1005.service: Main process exited, code=killed, status=9/KILL
Sep 20 19:47:53 drystone systemd[1]: user@1005.service: Failed with result 'timeout'.
Sep 20 19:47:53 drystone systemd[1]: Stopped User Manager for UID 1005.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.