Bug 404783

I'm experiencing the same exact problem on a fresh Debian/unstable install.

In addition, I've checked (running htop on a separate console on CTRL+ALT+F1) that /usr/bin/plasmashell is running at 100% CPU during those 15 seconds after I click logout.

I tried to quit everything on the tray bar, to disable the compositor at startup (and thus all graphical effects), to stop pulseaudio, and to uninstall libpam-kwallet5. No luck.

Debian unstable
Linux 4.19.20-1 (2019-02-11)
plasmashell 5.14.5
Qt: 5.11.3
KDE Frameworks: 5.54.0
kf5-config: 1.0

Relevant parts from journalctl:

Feb 24 14:26:02 debian polkitd(authority=local)[617]: Unregistered Authentication Agent for unix-session:41 (system bus name :1.1320, object path /org/kde/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
Feb 24 14:26:02 debian sddm[626]: kwalletd5: Checking for pam module
Feb 24 14:26:02 debian sddm[626]: kwalletd5: Got pam-login param
Feb 24 14:26:02 debian sddm[626]: kwalletd5: Waiting for hash on 7-
Feb 24 14:26:02 debian sddm[626]: kwalletd5: waitingForEnvironment on: 3
Feb 24 14:26:02 debian sddm[626]: kwalletd5: client connected
Feb 24 14:26:02 debian sddm[626]: kwalletd5: client disconnected
Feb 24 14:26:17 debian sddm-helper[12052]: [PAM] Closing session
Feb 24 14:26:17 debian sddm-helper[12052]: pam_unix(sddm:session): session closed for user marco
Feb 24 14:26:17 debian sddm-helper[12052]: pam_kwallet5(sddm:session): pam_kwallet5: pam_sm_close_session
Feb 24 14:26:17 debian sddm-helper[12052]: [PAM] Ended.
Feb 24 14:26:17 debian sddm-helper[12052]: pam_kwallet5(sddm:setcred): pam_kwallet5: pam_sm_setcred
Feb 24 14:26:17 debian sddm[626]: Auth: sddm-helper exited successfully
Feb 24 14:26:17 debian pulseaudio[11433]: XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":0"
Feb 24 14:26:17 debian pulseaudio[11433]:       after 19 requests (19 known processed) with 0 events remaining.
Feb 24 14:26:17 debian sddm[626]: Socket server stopping...
Feb 24 14:26:17 debian org.kde.kuiserver[981]: The X11 connection broke (error 1). Did the X11 server die?
Feb 24 14:26:17 debian org.kde.kglobalaccel[981]: The X11 connection broke (error 1). Did the X11 server die?
Feb 24 14:26:17 debian org.kde.ActivityManager[981]: The X11 connection broke (error 1). Did the X11 server die?
Feb 24 14:26:17 debian org.kde.KScreen[981]: The X11 connection broke (error 1). Did the X11 server die?
Feb 24 14:26:17 debian sddm[626]: Socket server stopped.
Feb 24 14:26:17 debian sddm[626]: Display server stopping...

I've been investigating, and I think we're misreading the logs.

What should happen is Plasmashell disables session management and immediately responds to the session manager that it is ignoring the request.

As soon as all session controlled apps have finished, ksmserver starts killing everything else, including plasmashell.
A bit quirky, but does seem to work.

The fact that we're in SMSDie is fine, the fact that it's timing out is weird.

---

There's a bug in plasmashell, somewhere - ideally I need a gdb trace of plasmashell when it's in this high CPU state. Though I appreciate that will be hard to get.

---

What's also weird is it thinks kwin_x11 is a client, it should detect that it's the WM and treat it differently.
Can I have your ~/.config/ksmserverrc
---

Also can you add 
export QT_LOGGING_RULES='org.kde.kf5.ksmserver.debug=true'

to something that gets sourced before login (/etc/profile.d/debug.sh is one of the most reliable)

and then reattach a new log if you can reproduce after starting with this env set. It'll print a lot more for ksmserver.

Created attachment 118361 [details]
Another journal, with QT_LOGGING_RULES

As for the ~/.config/ksmserverrc, this is everything it contains:

[General]
confirmLogout=false
excludeApps=
loginMode=default
offerShutdown=true
shutdownType=0

In the full log, only the end is relevant as I have only relogged in after setting the environment variable. The relevant part starts at 19:24:21.

I also experience very slow start and shutdown, also Plasma 5 on Arch, system on SSD.

Someone suggested it may be my desktop widgets - and teh widgets load exactly the moment the 10-15 sec long "hang time" in the middle of teh GUI loading ends. Does the reporter here use widgets?

Also, I'm a noob so please let me know what logs should I uploaded and how to get them.

Journal from the moment of logging in via console: https://pastebin.com/vjMN7Y0y

Some interesting parts with several sec delays:


Mar 09 07:19:31 Camelot systemd[1]: Started Session 1 of user storm.
Mar 09 07:19:32 Camelot kernel: resource sanity check: requesting [mem 0x000c0000-0x000fffff], which spans more than PCI Bus 0000:00 [mem 0x000d0000-0x000d3fff window]
Mar 09 07:19:32 Camelot kernel: caller _nv001094rm+0xe3/0x1d0 [nvidia] mapping multiple BARs
Mar 09 07:19:33 Camelot systemd[659]: Started D-Bus User Message Bus.
Mar 09 07:19:35 Camelot systemd-timesyncd[585]: Synchronized to time server 5.39.184.5:123 (2.arch.pool.ntp.org).
Mar 09 07:19:38 Camelot dbus-daemon[705]: [session uid=1000 pid=705] Activating service name='org.kde.kglobalaccel' requested by ':1.5' (uid=1000 pid=739 comm="kded5 [kdeinit5]                                  ")
Mar 09 07:19:38 Camelot dbus-daemon[705]: [session uid=1000 pid=705] Successfully activated service 'org.kde.kglobalaccel'
Mar 09 07:19:39 Camelot dbus-daemon[589]: [system] Activating via systemd: service name='org.freedesktop.ColorManager' unit='colord.service' requested by ':1.23' (uid=1000 pid=739 comm="kded5 [kdeinit5]                                  ")


Mar 09 07:19:45 Camelot dbus-daemon[589]: [system] Activating via systemd: service name='org.freedesktop.UDisks2' unit='udisks2.service' requested by ':1.59' (uid=1000 pid=888 comm="/usr/bin/dolphin -session 10afd0e16500015516182050")
Mar 09 07:19:45 Camelot systemd[1]: Starting Disk Manager...
Mar 09 07:19:45 Camelot udisksd[1053]: udisks daemon version 2.8.1 starting
Mar 09 07:19:58 Camelot dbus-daemon[705]: [session uid=1000 pid=705] Activating service name='org.kde.kuiserver' requested by ':1.20' (uid=1000 pid=840 comm="/usr/bin/plasmashell ")
Mar 09 07:19:58 Camelot dbus-daemon[705]: [session uid=1000 pid=705] Successfully activated service 'org.kde.kuiserver'
Mar 09 07:20:10 Camelot dbus-daemon[589]: [system] Failed to activate service 'org.freedesktop.UDisks2': timed out (service_start_timeout=25000ms)
Mar 09 07:20:14 Camelot dbus-daemon[589]: [system] Activating via systemd: service name='org.freedesktop.UDisks2' unit='udisks2.service' requested by ':1.59' (uid=1000 pid=888 comm="/usr/bin/dolphin -session 10afd0e16500015516182050")
Mar 09 07:20:18 Camelot dbus-daemon[589]: [system] Successfully activated service 'org.freedesktop.UDisks2'
Mar 09 07:20:18 Camelot systemd[1]: Started Disk Manager.


Not sure if my issue is related.

[storm@Camelot] (~) $ systemd-analyze blame
         32.659s udisks2.service
          8.064s dhcpcd@enp3s0.service
           724ms lvm2-monitor.service
           680ms systemd-logind.service
           631ms systemd-journal-flush.service
           555ms dev-sda2.device
           396ms home-storm-misc-swapfile.swap
           273ms systemd-timesyncd.service
           207ms upower.service
           198ms systemd-fsck@dev-disk-by\x2duuid-68CB\x2d49A9.service
           198ms systemd-fsck@dev-disk-by\x2duuid-6140ad0c\x2dca18\x2d42ca\x2dacd4\x2d0ed77f7f0700.service
           192ms systemd-udevd.service
           172ms systemd-fsck@dev-disk-by\x2duuid-9b9b2009\x2d57e5\x2d473c\x2d97cd\x2deaa63c3dc8b8.service
           127ms user@1000.service
           113ms polkit.service
            94ms systemd-modules-load.service
            71ms systemd-udev-trigger.service
            69ms home.mount
            58ms systemd-journald.service
            52ms systemd-tmpfiles-setup-dev.service
            47ms boot.mount
            38ms systemd-binfmt.service
            35ms systemd-tmpfiles-clean.service
            34ms home-storm-misc.mount
            33ms systemd-tmpfiles-setup.service [...]


This corresponds with my second snippet above.

Sorry for the comment spam.

Apparently udisk2 is not the culprit. I remoed that issue via disabling Dropbox (see: https://bbs.archlinux.org/viewtopic.php?id=239449 ) but that didn't solve the problem. Now:

systemd-analyze blame
          8.213s dhcpcd@enp3s0.service
          2.833s udisks2.service
           682ms systemd-journal-flush.service
           675ms systemd-logind.service
           619ms lvm2-monitor.service
           551ms dev-sda2.device
           388ms home-storm-misc-swapfile.swap
           289ms systemd-timesyncd.service
           269ms upower.service
           255ms systemd-fsck@dev-disk-by\x2duuid-68CB\x2d49A9.service
           191ms systemd-fsck@dev-disk-by\x2duuid-6140ad0c\x2dca18\x2d42ca\x2dacd4\x2d0ed77f7f0700.service
           189ms systemd-udevd.service
           160ms systemd-fsck@dev-disk-by\x2duuid-9b9b2009\x2d57e5\x2d473c\x2d97cd\x2deaa63c3dc8b8.service
           156ms user@1000.service
           116ms polkit.service
           103ms packagekit.service
            85ms systemd-udev-trigger.service
            83ms systemd-modules-load.service
            78ms home.mount
            66ms systemd-journald.service
            60ms boot.mount
            45ms systemd-tmpfiles-setup-dev.service


systemd-analyze critical-chain:

multi-user.target @10.253s
└─getty.target @10.252s
  └─getty@tty1.service @10.251s
    └─systemd-user-sessions.service @10.242s +7ms
      └─network.target @10.240s
        └─dhcpcd@enp3s0.service @2.025s +8.213s
          └─basic.target @2.023s
            └─sockets.target @2.022s
              └─dbus.socket @2.021s
                └─sysinit.target @2.019s
                  └─systemd-timesyncd.service @1.729s +289ms
                    └─systemd-tmpfiles-setup.service @1.692s +33ms
                      └─local-fs.target @1.690s
                        └─tmp.mount @1.686s +3ms
                          └─swap.target @1.681s
                            └─home-storm-misc-swapfile.swap @1.292s +388ms
                              └─home-storm-misc.mount @1.262s +28ms
                                └─home.mount @1.141s +78ms
                                  └─systemd-fsck@dev-disk-by\x2duuid-6140ad0c\x2dca18\x2d42ca\x2dacd4\x2d0ed77f7f0700.service @949ms +191ms
                                    └─local-fs-pre.target @939ms
                                      └─lvm2-monitor.service @318ms +619ms
                                        └─lvm2-lvmetad.service @364ms
                                          └─systemd-journald.socket @312ms
                                            └─system.slice @295ms
                                              └─-.slice @295ms

(Ignore the 8 sec for DHCP, that happens before login and is due to my crap router)

Journal: https://pastebin.com/q8CRRte0

New information was provided; changing status for inspection.

This problem occurs on a fresh openSUSE Tumbleweed install too.

After clicking shutdown menu option, KDE hang about 20s, then system begin shutdown.

SOFTWARE/OS VERSIONS

Operating System: openSUSE Tumbleweed 20201030
KDE Plasma Version: 5.20.2
KDE Frameworks Version: 5.75.0
Qt Version: 5.15.1
Kernel Version: 5.9.1-1-default
OS Type: 64-bit

ADDITIONAL INFORMATION

Relevant logs:

Nov 07 10:14:48 suse ksmserver[1658]: org.kde.kf5.ksmserver: SmsDie timeout, client  "/usr/bin/plasma-discover" ( 1073757365000160456969200000017050037 )
Nov 07 10:14:38 suse systemd[1503]: app-\x2fusr\x2fbin\x2fdolphin-bd8fcda6dbba4b208896911902a680ba.scope: Succeeded.
Nov 07 10:14:38 suse kded5[1635]: Service  ":1.33" unregistered
Nov 07 10:14:38 suse systemd[1503]: app-\x2fusr\x2flib64\x2flibexec\x2fxdg\x2ddesktop\x2dportal\x2dkde-13a33e03223a4d46aca604f39886be7c.scope: Succeeded.
Nov 07 10:14:38 suse systemd[1503]: app-\x2fusr\x2flib64\x2flibexec\x2fbaloorunner-909ba7e66bf3436da20c1563151d663f.scope: Succeeded.
Nov 07 10:14:38 suse polkitd[1028]: Unregistered Authentication Agent for unix-session:2 (system bus name :1.34, object path /org/kde/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
Nov 07 10:14:38 suse polkit-kde-authentication-agent-1[1675]: Removing listener  PolkitQt1::Agent::Listener(0x5569ca7467f0)
Nov 07 10:14:38 suse polkit-kde-authentication-agent-1[1675]: Destroying listener
Nov 07 10:14:23 suse dbus-daemon[1522]: [session uid=1000 pid=1522] Successfully activated service 'org.kde.Shutdown'
Nov 07 10:14:22 suse dbus-daemon[1522]: [session uid=1000 pid=1522] Activating service name='org.kde.Shutdown' requested by ':1.16' (uid=1000 pid=1658 comm="/usr/bin/ksmserver ")
Nov 07 10:14:20 suse ksmserver-logout-greeter[5055]: kf.plasma.core: findInCache with a lastModified timestamp of 0 is deprecated
Nov 07 10:14:20 suse ksmserver-logout-greeter[5055]: kf.plasma.core: findInCache with a lastModified timestamp of 0 is deprecated
Nov 07 10:14:20 suse ksmserver-logout-greeter[5055]: kf.plasma.core: findInCache with a lastModified timestamp of 0 is deprecated
Nov 07 10:14:20 suse ksmserver-logout-greeter[5055]: qt.svg: <input>:413:631: Could not add child element to parent element because the types are incorrect.
Nov 07 10:14:20 suse ksmserver-logout-greeter[5055]: qt.svg: <input>:413:379: Could not add child element to parent element because the types are incorrect.
Nov 07 10:14:20 suse ksmserver-logout-greeter[5055]: qt.svg: <input>:413:129: Could not add child element to parent element because the types are incorrect.
Nov 07 10:14:20 suse ksmserver-logout-greeter[5055]: qt.svg: <input>:412:129: Could not add child element to parent element because the types are incorrect.
Nov 07 10:14:20 suse ksmserver-logout-greeter[5055]: qt.svg: <input>:411:129: Could not add child element to parent element because the types are incorrect.
Nov 07 10:14:20 suse ksmserver-logout-greeter[5055]: qt.svg: <input>:410:129: Could not add child element to parent element because the types are incorrect.
Nov 07 10:14:20 suse ksmserver-logout-greeter[5055]: qt.svg: <input>:409:130: Could not add child element to parent element because the types are incorrect.
Nov 07 10:14:20 suse ksmserver-logout-greeter[5055]: qt.svg: <input>:408:393: Could not add child element to parent element because the types are incorrect.
Nov 07 10:14:20 suse ksmserver-logout-greeter[5055]: qt.svg: <input>:408:130: Could not add child element to parent element because the types are incorrect.
Nov 07 10:14:20 suse ksmserver-logout-greeter[5055]: qt.svg: <input>:407:130: Could not add child element to parent element because the types are incorrect.
Nov 07 10:14:20 suse ksmserver-logout-greeter[5055]: qt.svg: <input>:406:376: Could not add child element to parent element because the types are incorrect.
Nov 07 10:14:20 suse ksmserver-logout-greeter[5055]: kf.plasma.core: findInCache with a lastModified timestamp of 0 is deprecated
Nov 07 10:14:20 suse ksmserver-logout-greeter[5055]: Cyclic dependency detected between "file:///usr/lib64/qt5/qml/org/kde/kirigami.2/styles/org.kde.desktop.plasma/Units.qml" and "file:///usr/lib64/qt5/qml/org/kde/kirigami.2/styles/org.kde.desktop.plasma/Units.qml"
Nov 07 10:14:20 suse dbus-daemon[1522]: [session uid=1000 pid=1522] Successfully activated service 'org.kde.LogoutPrompt'
Nov 07 10:14:20 suse dbus-daemon[1522]: [session uid=1000 pid=1522] Activating service name='org.kde.LogoutPrompt' requested by ':1.20' (uid=1000 pid=1672 comm="/usr/bin/plasmashell ")


WORKAROUND:

The default KDE settings, "System Settings -> Startup and Shutdown -> Desktop Session -> On Login"  is "Restroe previous session", change it to "Start with an empty session", this problem will disappear.

It seems that "/usr/bin/plasma-discover" prevent KDE from really shutdown.

After killing plasma-discover process manually before shutdown, this problem disappear too.

Yes, I can confirm the same thing.

*** This bug has been marked as a duplicate of bug 428175 ***