What's up with "A stop job is running for User Manager for UID 1000"?

TheJooomes · 08-14-2021, 04:07 AM

I've seen this issue on pretty much every distro across all sorts of hardware; Fedora, Debian, Arch, you name it. It stalls shutdown for 1m 30s. There's a roughly 1/3 chance this happens on my Debian 11 laptop. It was also an issue on Debian 10 on a different laptop. I'm assuming every distro that uses systemd has this issue. So what's up with it? Why is it such an issue and why can't any distro solve it?

JuanKenobi · 08-14-2021, 04:54 AM

It is a case of fixing something that isn't/wasn't broken. I know of one distro that hasn't had any problems thus far...Slackware. Hopefully Pat can keep holding them off.

Quote:

systemd is a suite of basic building blocks for a Linux system. It provides a system and service manager that runs as PID 1 and starts the rest of the system. systemd provides aggressive parallelization capabilities, uses socket and D-Bus activation for starting services, offers on-demand starting of daemons, keeps track of processes using Linux control groups, maintains mount and automount points, and implements an elaborate transactional dependency-based service control logic. systemd supports SysV and LSB init scripts and works as a replacement for sysvinit. Other parts include a logging daemon, utilities to control basic system configuration like the hostname, date, locale, maintain a list of logged-in users and running containers and virtual machines, system accounts, runtime directories and settings, and daemons to manage simple network configuration, network time synchronization, log forwarding, and name resolution.

Looks awful close to being a single point of failure, IMHO. systemd is wearing too many hats.

ondoho · 08-14-2021, 06:52 AM

Quote:

Originally Posted by TheJooomes

I've seen this issue on pretty much every distro across all sorts of hardware; Fedora, Debian, Arch, you name it. It stalls shutdown for 1m 30s. There's a roughly 1/3 chance this happens on my Debian 11 laptop. It was also an issue on Debian 10 on a different laptop. I'm assuming every distro that uses systemd has this issue. So what's up with it? Why is it such an issue and why can't any distro solve it?

It doesn't aslways happen; it rarely happens for me, but yes, I have seen this message. Not often enough to be annoyed by it and do something about it.
However, it should be fixable.

What you can do:

search the whole or partial error message on the web (I'm sure someone will be along shortly and do that for you)
after a reboot, have a good look at
Code:
```
journalctl -b -1 -e
```

TheJooomes · 08-14-2021, 01:27 PM

Quote:

Originally Posted by ondoho

[*]after a reboot, have a good look at

Code:

journalctl -b -1 -e

[/list]

Possibly of interest

Code:

Aug 14 03:58:20 debian evolution-addre[1822]: Error setting property 'ConnectionStatus' on interface org.gnome.evolution.dataserver.Source: The connection is closed (g-io-error-quark, 18)
Aug 14 03:58:20 debian systemd[1355]: run-user-1000-doc.mount: Succeeded.
Aug 14 03:58:20 debian systemd[1355]: dbus.service: Succeeded.
Aug 14 03:58:20 debian systemd[1355]: Stopped D-Bus User Message Bus.
Aug 14 03:58:20 debian systemd[1355]: dbus.service: Consumed 1min 46.136s CPU time.
Aug 14 03:58:20 debian systemd-logind[604]: System is powering down.
Aug 14 03:58:20 debian systemd[1]: run-user-1000-doc.mount: Succeeded.
Aug 14 03:58:20 debian systemd[1355]: xdg-desktop-portal.service: Succeeded.
Aug 14 03:58:20 debian systemd[1355]: xdg-document-portal.service: Main process exited, code=exited, status=20/n/a
Aug 14 03:58:20 debian systemd[1355]: Started D-Bus User Message Bus.
Aug 14 03:58:20 debian systemd[1355]: evolution-source-registry.service: Succeeded.
Aug 14 03:58:20 debian systemd[1355]: evolution-source-registry.service: Consumed 1.208s CPU time.
Aug 14 03:58:20 debian systemd[1355]: evolution-calendar-factory.service: Succeeded.
Aug 14 03:58:20 debian systemd[1355]: evolution-calendar-factory.service: Consumed 1.989s CPU time.
Aug 14 03:58:20 debian systemd[1355]: evolution-addressbook-factory.service: Succeeded.

Here it looks like some services crashed while the system was shutting down.

Code:

Aug 14 03:58:20 debian pulseaudio[1387]: ICE default IO error handler doing an exit(), pid = 1387, errno = 32
Aug 14 03:58:20 debian systemd[1355]: xdg-document-portal.service: Failed with result 'exit-code'.
Aug 14 03:58:20 debian systemd[1355]: pulseaudio.service: Main process exited, code=exited, status=1/FAILURE
Aug 14 03:58:20 debian systemd[1355]: pulseaudio.service: Failed with result 'exit-code'.
Aug 14 03:58:20 debian systemd[1355]: pulseaudio.service: Consumed 10min 28.931s CPU time.
Aug 14 03:58:20 debian lightdm[1276]: pam_unix(lightdm:session): session closed for user james
Aug 14 03:58:20 debian at-spi-bus-launcher[1468]: X connection to :0 broken (explicit kill or server shutdown).
Aug 14 03:58:20 debian systemd[1355]: at-spi-dbus-bus.service: Main process exited, code=exited, status=1/FAILURE
Aug 14 03:58:20 debian systemd[1355]: at-spi-dbus-bus.service: Failed with result 'exit-code'.
Aug 14 03:58:20 debian systemd[1355]: at-spi-dbus-bus.service: Consumed 2.059s CPU time.

Here is where I think the 1m30s delay happened. I find it strange that there's a pipewire service running. I've never set it up and Debian 11 doesn't come with it enabled be default. I'm using the MATE desktop so no Wayland either.

Code:

Aug 14 03:58:21 debian systemd[1]: Stopped VirtualBox Linux kernel module.
Aug 14 03:59:50 debian systemd[1355]: Stopping D-Bus User Message Bus...
Aug 14 03:59:50 debian systemd[1355]: Stopping Multimedia Service...
Aug 14 03:59:50 debian systemd[1355]: dbus.service: Succeeded.
Aug 14 03:59:50 debian systemd[1355]: Stopped D-Bus User Message Bus.
Aug 14 03:59:50 debian systemd[1355]: pipewire.service: Succeeded.
Aug 14 03:59:50 debian systemd[1355]: Stopped Multimedia Service.

And a short while later in the log, "User Manager for UID 1000" finally ends, with the highest consumed CPU time I've seen in the log.

Code:

Aug 14 03:59:50 debian systemd[1]: Stopped User Manager for UID 1000.
Aug 14 03:59:50 debian systemd[1]: user@1000.service: Consumed 12min 23.571s CPU time.

Here's the entire log, starting from the time of shutdown. https://pastebin.com/knBdWr8Z

ondoho · 08-15-2021, 01:37 AM

Did it take 12min to shut down?

No, I don't think this means what you think it means. It probably means how much CPU time that service consumed during its entire life, not just during shutdown.

Anyhow, dbus.service seems to be the culprit, directly or indirectly.
Things to look at:

Code:

systemctl status -n999 dbus.service
journalctl -b -1 | grep -EC2 'dbus.s|D-Bus'
systemctl list-dependencies dbus.service

Rinse and repeat for all dbus.service dependencies.

How reproducible are those problematic shutdowns?
It is possible that the crash you mentioned has something to do with it, or not.
Also look at journal entries from unproblematic shutdowns. If it crashes there too, chances are its unrelated.

If all the above still doesn't clarify things you might need to start disabling services.

BTW, some people recommend simply reducing systemd's stop job timeout from 1:30 to something less, but I don't think that's a solution at all.

TheJooomes · 08-15-2021, 02:02 AM

Quote:

Originally Posted by ondoho

How reproducible are those problematic shutdowns?

About a 1/3 or 1/4 chance of happening.

It might be by chance, but it does seem more likely to happen if the system is woken from suspend then shutdown shortly after. Like if I'm not sure if I'll use the laptop for the rest of the day, I'll put it in suspend, then later I'll wake it and shutdown before I go to bed.

I'll have a look at dbus stuff after a problematic shutdown. Might be as much as a week, I don't feel like swimming through an ocean of text to find something from the other day. I'll look for stuff like that pulseaudio crash tomorrow though, since tonight was a successful shutdown for the laptop.

Thanks for the ideas of what to check.

altPOCA · 08-15-2021, 02:03 PM

Here on SparkyLinux and altLinux, too. It's SystemD's problem. Sometimes you shutdown or reboot too fast after you closed the last application (usually your browser, mine is Firefox) and you found you are caught in this situation. The only way is to wait.

altPOCA · 08-16-2021, 12:02 AM

Quote:

Originally Posted by TheJooomes

About a 1/3 or 1/4 chance of happening.

It might be by chance, but it does seem more likely to happen if the system is woken from suspend then shutdown shortly after. Like if I'm not sure if I'll use the laptop for the rest of the day, I'll put it in suspend, then later I'll wake it and shutdown before I go to bed.

It seems your situation is very different from me. I'm using a desktop and I never use suspend, only reboot and shutdown. I found if you shutdown or reboot too fast after you closed the last application (usually your browser, mine is Firefox) then sometimes you are caught in this situation. The only way is to wait. Very rarely it just stuck forever and you can only have one choice which is a cold reboot to reset the system. Luckily most of the time there is no data corruption and the system is just work after that.