Long delay on shutdown: pcmanfm [SOLVED]

coolion · 2020-04-28 19:40:53

Hi,

I got a very long delay on shutdown of my laptop. So I enabled the systemd output during boot and shutdown and saw that systemd is waiting for a service to be killed, respectively it just waits for the timeout (I have set it down to 30seconds for convenience). A look into the journal gave me the following (I stripped it a little bit to make it more readable):

Apr 27 18:13:30 os-xps13 systemd-logind[448]: Power key pressed.
Apr 27 18:13:30 os-xps13 systemd-logind[448]: Powering Off...
Apr 27 18:13:30 os-xps13 systemd-logind[448]: System is powering down.
...
Apr 27 18:13:30 os-xps13 systemd[1]: rtkit-daemon.service: Succeeded.
Apr 27 18:13:30 os-xps13 systemd[1]: Stopped RealtimeKit Scheduling Policy Service.
Apr 27 18:13:30 os-xps13 at-spi-bus-launcher[1284]: X connection to :0 broken (explicit kill or server shutdown).
Apr 27 18:13:30 os-xps13 pulseaudio[1107]: X connection to :0 broken (explicit kill or server shutdown).
Apr 27 18:13:30 os-xps13 systemd[1]: alsa-restore.service: Succeeded.
Apr 27 18:13:30 os-xps13 systemd[1]: Stopped Save/Restore Sound Card State.
Apr 27 18:13:30 os-xps13 systemd[1]: systemd-random-seed.service: Succeeded.
Apr 27 18:13:30 os-xps13 systemd[1]: Stopped Load/Save Random Seed.
Apr 27 18:13:30 os-xps13 udisksd[449]: udisks daemon version 2.8.4 exiting
Apr 27 18:13:30 os-xps13 systemd[1]: polkit.service: Succeeded.
Apr 27 18:13:30 os-xps13 systemd-logind[448]: Session 1 logged out. Waiting for processes to exit.
Apr 27 18:13:30 os-xps13 systemd[1]: Stopped Authorization Manager.
Apr 27 18:13:30 os-xps13 systemd[1086]: pulseaudio.service: Main process exited, code=exited, status=1/FAILURE
Apr 27 18:13:30 os-xps13 systemd[1086]: pulseaudio.service: Failed with result 'exit-code'.
Apr 27 18:13:30 os-xps13 systemd[1]: udisks2.service: Succeeded.
Apr 27 18:13:30 os-xps13 systemd[1]: Stopped Disk Manager.
Apr 27 18:13:30 os-xps13 mkinitcpio[2905]: ==> Starting build: none
Apr 27 18:13:30 os-xps13 mkinitcpio[2905]:   -> Running build hook: [sd-shutdown]
Apr 27 18:13:30 os-xps13 mkinitcpio[2905]: ==> Build complete.
Apr 27 18:13:30 os-xps13 systemd[1]: mkinitcpio-generate-shutdown-ramfs.service: Succeeded.
Apr 27 18:13:30 os-xps13 systemd[1]: Finished Generate shutdown-ramfs.
Apr 27 18:13:30 os-xps13 systemd[1086]: pulseaudio.service: Scheduled restart job, restart counter is at 1.
Apr 27 18:13:30 os-xps13 systemd[1086]: Stopped Sound Service.
Apr 27 18:13:30 os-xps13 systemd[1086]: Starting Sound Service...
Apr 27 18:13:31 os-xps13 dbus-daemon[446]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.344' (uid=1000 pid=3019 comm="/usr/bin/pulseaudio --daemonize=no ")
Apr 27 18:13:31 os-xps13 dbus-daemon[446]: [system] Activation via systemd failed for unit 'rtkit-daemon.service': Refusing activation, D-Bus is shutting down.
...
Apr 27 18:13:31 os-xps13 dbus-daemon[446]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.354' (uid=1000 pid=3019 comm="/usr/bin/pulseaudio --daemonize=no ")
Apr 27 18:13:31 os-xps13 dbus-daemon[446]: [system] Activation via systemd failed for unit 'rtkit-daemon.service': Refusing activation, D-Bus is shutting down.
Apr 27 18:13:31 os-xps13 pulseaudio[3019]: W: [pulseaudio] pid.c: Stale PID file, overwriting.
Apr 27 18:13:31 os-xps13 systemd[1]: lxdm.service: Succeeded.
Apr 27 18:13:31 os-xps13 systemd[1]: Stopped LXDE Display Manager.
Apr 27 18:13:31 os-xps13 dbus-daemon[446]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.355' (uid=1000 pid=3019 comm="/usr/bin/pulseaudio --daemonize=no ")
Apr 27 18:13:31 os-xps13 dbus-daemon[446]: [system] Activation via systemd failed for unit 'rtkit-daemon.service': Refusing activation, D-Bus is shutting down.
...
Apr 27 18:13:31 os-xps13 dbus-daemon[446]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.369' (uid=1000 pid=3019 comm="/usr/bin/pulseaudio --daemonize=no ")
Apr 27 18:13:31 os-xps13 dbus-daemon[446]: [system] Activation via systemd failed for unit 'rtkit-daemon.service': Refusing activation, D-Bus is shutting down.
Apr 27 18:13:31 os-xps13 systemd[1086]: Started Sound Service.
Apr 27 18:14:00 os-xps13 systemd[1]: session-1.scope: Stopping timed out. Killing.
...

You can see that something with pulseaudio is happening. I'm not sure if this is caused by pulseaudio or if this just a symptom of something else. I cannot see something else being wrong in the journal. Do you have any idea?

Oliver

P.S. I am not sure where this topic belongs, please help me to find the right category for it.

Last edited by coolion (2020-06-01 08:28:43)

V1del · 2020-04-28 20:16:58

Newbie corner is fine if you're unsure

For some reason pulseaudio cares about the xorg session, did you manually configure something here? How are you starting your session? What's the output of

systemctl status
systemctl --user status pulseaudio.{service,socket}

? during your "normal" session

coolion · 2020-05-01 13:30:30

Now that you say it. I had the following in the .profile

pactl set-sink-volume alsa_output.pci-0000_00_1f.3.analog-stereo 33%

After disabling this the shutdown looks ok. I just made two test reboots and it did not happen again. Still there is the line in the journal:

 pulseaudio[1107]: X connection to :0 broken (explicit kill or server shutdown).

Since you mentioned it, is this a problem?

Here is also the output of the two commands you suggested.

Unit status.service could not be found.
● pulseaudio.service - Sound Service
     Loaded: loaded (/usr/lib/systemd/user/pulseaudio.service; disabled; vendor preset: enabled)
     Active: active (running) since Fri 2020-05-01 14:54:54 CEST; 13min ago
TriggeredBy: ● pulseaudio.socket
   Main PID: 1229 (pulseaudio)
     CGroup: /user.slice/user-1000.slice/user@1000.service/pulseaudio.service
             ├─1229 /usr/bin/pulseaudio --daemonize=no
             └─1230 /usr/lib/pulse/gsettings-helper

Mai 01 14:54:53 os-xps13 systemd[512]: Starting Sound Service...
Mai 01 14:54:54 os-xps13 pulseaudio[1229]: W: [pulseaudio] pid.c: Stale PID file, overwriting.
Mai 01 14:54:54 os-xps13 systemd[512]: Started Sound Service.

● pulseaudio.socket - Sound System
     Loaded: loaded (/usr/lib/systemd/user/pulseaudio.socket; enabled; vendor preset: enabled)
     Active: active (running) since Fri 2020-05-01 14:45:42 CEST; 22min ago
   Triggers: ● pulseaudio.service
     Listen: /run/user/1000/pulse/native (Stream)
     CGroup: /user.slice/user-1000.slice/user@1000.service/pulseaudio.socket

Mai 01 14:45:42 os-xps13 systemd[512]: Listening on Sound System.

    State: running
     Jobs: 0 queued
   Failed: 0 units
    Since: Fri 2020-05-01 14:42:06 CEST; 32min ago
   CGroup: /
           ├─user.slice 
           │ └─user-1000.slice 
           │   ├─user@1000.service …
           │   │ ├─pulseaudio.service 
           │   │ │ ├─1229 /usr/bin/pulseaudio --daemonize=no
           │   │ │ └─1230 /usr/lib/pulse/gsettings-helper
           │   │ ├─gvfs-daemon.service 
           │   │ │ ├─1262 /usr/lib/gvfsd
           │   │ │ └─1362 /usr/lib/gvfsd-trash --spawner :1.55 /org/gtk/gvfs/exec_spaw/0
           │   │ ├─gvfs-udisks2-volume-monitor.service 
           │   │ │ └─1325 /usr/lib/gvfs-udisks2-volume-monitor
           │   │ ├─init.scope 
           │   │ │ ├─512 /usr/lib/systemd/systemd --user
           │   │ │ └─513 (sd-pam)
           │   │ ├─obex.service 
           │   │ │ └─1431 /usr/lib/bluetooth/obexd
           │   │ ├─at-spi-dbus-bus.service 
           │   │ │ ├─1527 /usr/lib/at-spi-bus-launcher
           │   │ │ └─1533 /usr/bin/dbus-daemon --config-file=/usr/share/defaults/at-spi2/accessibility.conf --nofork --print-address 3
           │   │ ├─gvfs-metadata.service 
           │   │ │ └─1312 /usr/lib/gvfsd-metadata
           │   │ ├─dbus.service 
           │   │ │ └─534 /usr/bin/dbus-daemon --session --address=systemd: --nofork --nopidfile --systemd-activation --syslog-only
           │   │ └─gvfs-mtp-volume-monitor.service 
           │   │   └─1345 /usr/lib/gvfs-mtp-volume-monitor
           │   └─session-3.scope 
           │     ├─1237 /usr/lib/lxdm/lxdm-session
           │     ├─1241 /usr/bin/gnome-keyring-daemon --daemonize --login
           │     ├─1244 /usr/bin/lxsession -s LXDE -e LXDE
           │     ├─1271 openbox --config-file /home/oliver/.config/openbox/lxde-rc.xml
           │     ├─1273 lxpolkit
           │     ├─1274 lxpanel --profile LXDE
           │     ├─1276 pcmanfm --desktop --profile LXDE
           │     ├─1280 lxclipboard
           │     ├─1289 /usr/bin/python /usr/bin/terminator
           │     ├─1291 /usr/bin/ssh-agent -s
           │     ├─1292 /usr/lib/geoclue-2.0/demos/agent
           │     ├─1303 nm-applet
           │     ├─1320 copyq
           │     ├─1329 /usr/bin/python /usr/bin/blueman-applet
           │     ├─1334 xpad
           │     ├─1356 /usr/lib/menu-cache/menu-cached /run/user/1000/menu-cached-:0
           │     ├─1389 /usr/bin/copyq --clipboard-access monitorClipboard
           │     ├─1399 /usr/bin/copyq eval -- runMenuCommandFilters()
           │     ├─1402 /usr/bin/python /usr/bin/blueman-tray
           │     ├─1407 /bin/zsh
           │     ├─1437 lxterminal -t DesktopConsoleW1Sec --command=sudo journalctl -f -n100
           │     ├─1440 sudo journalctl -f -n100
           │     ├─1441 journalctl -f -n100
           │     ├─1464 su
           │     ├─1465 zsh
           │     ├─1503 /usr/lib/firefox/firefox
           │     ├─1594 /usr/lib/firefox/firefox -contentproc -childID 1 -isForBrowser -prefsLen 1 -prefMapSize 220039 -parentBuildID 20200428114804 -appdir /usr/lib/firefox/browser 1503 true tab
           │     ├─1671 /usr/lib/firefox/firefox -contentproc -childID 3 -isForBrowser -prefsLen 6324 -prefMapSize 220039 -parentBuildID 20200428114804 -appdir /usr/lib/firefox/browser 1503 true tab
           │     ├─1715 /usr/lib/firefox/firefox -contentproc -childID 4 -isForBrowser -prefsLen 7093 -prefMapSize 220039 -parentBuildID 20200428114804 -appdir /usr/lib/firefox/browser 1503 true tab
           │     ├─1758 /usr/lib/firefox/firefox -contentproc -childID 5 -isForBrowser -prefsLen 7093 -prefMapSize 220039 -parentBuildID 20200428114804 -appdir /usr/lib/firefox/browser 1503 true tab
           │     ├─1810 /bin/zsh
           │     ├─1878 /usr/lib/firefox/firefox -contentproc -childID 6 -isForBrowser -prefsLen 7451 -prefMapSize 220039 -parentBuildID 20200428114804 -appdir /usr/lib/firefox/browser 1503 true tab
           │     └─2016 systemctl status
           ├─init.scope 
           │ └─1 /sbin/init
           └─system.slice 
             ├─systemd-udevd.service 
             │ └─290 /usr/lib/systemd/systemd-udevd
             ├─cronie.service 
             │ └─450 /usr/bin/crond -n
             ├─polkit.service 
             │ └─465 /usr/lib/polkit-1/polkitd --no-debug
             ├─rtkit-daemon.service 
             │ └─662 /usr/lib/rtkit-daemon
             ├─lxdm.service 
             │ ├─463 /usr/sbin/lxdm-binary
             │ └─467 /usr/lib/Xorg -background none :0 vt01 -nolisten tcp -novtswitch -auth /var/run/lxdm/lxdm-:0.auth
             ├─wpa_supplicant.service 
             │ └─498 /usr/bin/wpa_supplicant -u -s -O /run/wpa_supplicant
             ├─systemd-journald.service 
             │ └─277 /usr/lib/systemd/systemd-journald
             ├─atd.service 
             │ └─455 /usr/bin/atd -f
             ├─NetworkManager.service 
             │ └─452 /usr/bin/NetworkManager --no-daemon
             ├─lvm2-lvmetad.service 
             │ └─284 /usr/bin/lvmetad -f
             ├─udisks2.service 
             │ └─454 /usr/lib/udisks2/udisksd
             ├─dbus.service 
             │ └─451 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation --syslog-only
             ├─systemd-timesyncd.service 
             │ └─369 /usr/lib/systemd/systemd-timesyncd
             └─systemd-logind.service 
               └─453 /usr/lib/systemd/systemd-logind

coolion · 2020-05-01 19:45:01

nooo - the problem is still there. I was too quick in my response.

coolion · 2020-05-10 09:16:15

This is interesting, someone else reported a similar issue back in January this year https://bbs.archlinux.org/viewtopic.php?id=252538. The user reports also a pulseaudio event in the journal. And it look to me as this is also causing the delay. Systemd waits for the restarted pulseaudio service (user session) to come back, but it can't because dbus is spitting out these error that it is currently shutting down and the whole system runs into a timeout.

Does anyone else also have this in the journal?

V1del · 2020-05-10 16:07:59

Can you repost that status output from another tty during the timeouting phase? I wonder what is left that tries to reinvoke pulseaudio. Maybe also post an untruncated journalctl because you might be filtering the actual culprit. FWIW I don't have any of these issues.

Last edited by V1del (2020-05-10 16:08:28)

coolion · 2020-05-21 08:20:29

I have to rectify my initial statement, after some more testing I have come to the conclusion it has nothing to do with pulseaudio. The reason is, I have set the timeout for exiting to 30 seconds for the pulseaudio user-service, while the default is still set to 90 seconds and hey, I see a 90 seconds wait on shutdown. Also by completely disabling pulseaudio for a couple of days, I still experience the same problem but now I am getting closer because the log shows this:

Mai 20 21:49:14 os-xps13 systemd[1]: mkinitcpio-generate-shutdown-ramfs.service: Succeeded.
Mai 20 21:49:14 os-xps13 systemd[1]: Finished Generate shutdown-ramfs.
Mai 20 21:49:14 os-xps13 systemd[1]: lxdm.service: Succeeded.
Mai 20 21:49:14 os-xps13 systemd[1]: Stopped LXDE Display Manager.
Mai 20 21:49:15 os-xps13 wpa_supplicant[502]: wlp58s0: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
Mai 20 21:49:15 os-xps13 wpa_supplicant[502]: wlp58s0: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
Mai 20 21:50:44 os-xps13 systemd[1]: session-1.scope: Stopping timed out. Killing.
Mai 20 21:50:44 os-xps13 systemd[1]: session-1.scope: Killing process 556 (pcmanfm) with signal SIGKILL.
Mai 20 21:50:44 os-xps13 systemd[1]: session-1.scope: Killing process 574 (gdbus) with signal SIGKILL.
Mai 20 21:50:44 os-xps13 systemd[1]: session-1.scope: Failed with result 'timeout'.
Mai 20 21:50:44 os-xps13 systemd[1]: Stopped Session 1 of user oliver.
Mai 20 21:50:44 os-xps13 systemd[1]: Stopping Login Service...
Mai 20 21:50:44 os-xps13 systemd[1]: Stopping User Manager for UID 1000...
Mai 20 21:50:44 os-xps13 systemd[512]: Stopped target Main User Target.

and that is pointing to pcmanfm. This looks like pcmanfm is not cleanly exiting and is then killed by the session-1.scope. You can see the timout of about 90 seconds (21:49:15 to 21:50:44).

So the next experiment was to remove the pcmanfm from the startup in lxsession config (~/.config/lxsession/LXDE/autostart). And what should I say, by not using the file manager desktop-overlay the reboot/shutdown is now working fine since a couple of days.

coolion · 2020-05-31 08:41:41

Further investigation showed clearly that is related to pcmanfm. When killing the pcmanfm desktop proess with "killall" made the process not disappear, it got stuck in a zombie state. However yesterday I updated to pcmanfm "1.3.1-2" and that solved the problem. Thank you for your help and I apologize for pointing to pulseaudio.

Topic closed!

V1del · 2020-05-31 10:07:40

Cool, please adjust your title by editing it in the initial post to mark as [SOLVED] (and maybe point out that it's a pcmanfm issue after all)

Arch Linux

#1 2020-04-28 19:40:53

Long delay on shutdown: pcmanfm [SOLVED]

#2 2020-04-28 20:16:58

Re: Long delay on shutdown: pcmanfm [SOLVED]

#3 2020-05-01 13:30:30

Re: Long delay on shutdown: pcmanfm [SOLVED]

#4 2020-05-01 19:45:01

Re: Long delay on shutdown: pcmanfm [SOLVED]

#5 2020-05-10 09:16:15

Re: Long delay on shutdown: pcmanfm [SOLVED]

#6 2020-05-10 16:07:59

Re: Long delay on shutdown: pcmanfm [SOLVED]

#7 2020-05-21 08:20:29

Re: Long delay on shutdown: pcmanfm [SOLVED]

#8 2020-05-31 08:41:41

Re: Long delay on shutdown: pcmanfm [SOLVED]

#9 2020-05-31 10:07:40

Re: Long delay on shutdown: pcmanfm [SOLVED]

Board footer