Found by openQA: https://openqa.opensuse.org/tests/1614300#step/user_gui_login/4 I can reproduce the issue locally as well. Sometimes (30-50%?), clicking on the log out button doesn't do anything. It happens both with no applications running and with some applications running. Trying to debug this by either attaching with gdb or even just enabling logging of org.kde.kf5.ksmserver makes the issue vanish, so it appears to be a race condition.
X or wayland?
Do you know if OpenQA has changed recently? Given it was found by openQA does that mean we have a rough idea when this happened?
[12:09] <fvogt> d__ed: So far only seen on X, but I didn't test wayland yet
(In reply to David Edmundson from comment #1) > X or wayland? So far I've only seen the issue on X, both locally and in openQA. Considering that it disappears if you simply look at it the right way that's not proof that it only happens in X sessions though. (In reply to David Edmundson from comment #2) > Do you know if OpenQA has changed recently? Tests with Plasma < 5.21 still run fine, with no observed logout/shutdown issues. > Given it was found by openQA does that mean we have a rough idea when this > happened? The particular test module which fails here is only part of the tests for submission to Tumbleweed, so it didn't run before Plasma 5.21 Beta. However, I've seen a similar failure in a different test, which shuts down the machine instead of logging out: https://openqa.opensuse.org/tests/1510701#step/shutdown/7 The openQA job history unfortunately doesn't go further back than two months, so I can only tell that it's already been present in the snapshot from 2020-12-15.
I enabled the ksmserver logging category in "production" builds and fortunately it did actually fail in one of the openQA runs! In one test, a click on "Ok" to confirm log out works (https://openqa.opensuse.org/tests/1628813#step/start_wayland_plasma5/15): Feb 13 02:01:27.715302 susetest dbus-daemon[1102]: [session uid=1000 pid=1102] Activating service name='org.kde.Shutdown' requested by ':1.33' (uid=1000 pid=2423 comm="/usr/lib64/libexec/ksmserver-logout-greeter ") Feb 13 02:01:27.796281 susetest dbus-daemon[1102]: [session uid=1000 pid=1102] Successfully activated service 'org.kde.Shutdown' Feb 13 02:01:27.798859 susetest ksmserver[1246]: org.kde.kf5.ksmserver: saveSession is true Feb 13 02:01:27.804912 susetest ksmserver[1246]: org.kde.kf5.ksmserver: Saving legacy session apps Feb 13 02:01:27.818564 susetest ksmserver[1246]: org.kde.kf5.ksmserver: Done saving 0 legacy session apps ... In another test, a click on the "shutdown" button did nothing: https://openqa.opensuse.org/tests/1628811#step/shutdown/5 Feb 13 01:59:47.923856 susetest dbus-daemon[1095]: [session uid=1000 pid=1095] Activating service name='org.kde.Shutdown' requested by ':1.33' (uid=1000 pid=2361 comm="/usr/lib64/libexec/ksmserver-logout-greeter ") Feb 13 01:59:48.094592 susetest dbus-daemon[1095]: [session uid=1000 pid=1095] Successfully activated service 'org.kde.Shutdown' Feb 13 02:00:18.774911 susetest systemd[1]: Started Timeline of Snapper Snapshots. ... Apparently the call to org.kde.Shutdown didn't reach ksmserver at all?
(In reply to Fabian Vogt from comment #5) > Apparently the call to org.kde.Shutdown didn't reach ksmserver at all? Confirmed. I built ksmserver debug output enabled and also added the "Close session called." message (but not the rest) from https://invent.kde.org/plasma/plasma-workspace/-/merge_requests/644 and started a few logout tests in openQA. It succeeded logout (and login again) four times in a row before it failed once: https://openqa.opensuse.org/tests/1629662 While the "Close session called." message appears for every successful logout directly after "Successfully activated service 'org.kde.Shutdown'", it doesn't appear at all for the failed try.
Created attachment 135693 [details] dbus-monitor output I started dbus-monitor logging to the serial console inside openQA tests and ran a few until it failed to log out. The output is attached. There's a successful logout at "method call time=1613378180.763732", another one at "method call time=1613378225.841574" and a failed one at "method call time=1613378261.646045". The difference appears to be that when it fails, ksmserver-logout-greeter exits before the call to org.kde.Shutdown.logout returns. Works (abbreviated): method call time=1613378225.841574 sender=:1.61 -> destination=org.kde.Shutdown serial=34 path=/Shutdown; interface=org.kde.Shutdown; member=logout method call time=1613378225.893315 sender=:1.62 -> destination=org.freedesktop.DBus serial=1 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=Hello method return time=1613378225.894808 sender=org.freedesktop.DBus -> destination=:1.62 serial=1 reply_serial=1 string ":1.62" signal time=1613378225.902475 sender=org.freedesktop.DBus -> destination=(null destination) serial=60 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged string "org.kde.Shutdown" string "" string ":1.62" method call time=1613378225.915596 sender=:1.62 -> destination=org.kde.ksmserver serial=5 path=/KSMServer; interface=org.kde.KSMServerInterface; member=closeSession method return time=1613378225.926302 sender=:1.62 -> destination=:1.61 serial=8 reply_serial=34 signal time=1613378225.930287 sender=org.freedesktop.DBus -> destination=:1.61 serial=111 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost string "org.kde.LogoutPrompt" Fails (abbreviated): method call time=1613378261.646045 sender=:1.89 -> destination=org.kde.Shutdown serial=34 path=/Shutdown; interface=org.kde.Shutdown; member=logout signal time=1613378261.785876 sender=org.freedesktop.DBus -> destination=:1.89 serial=215 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost string "org.kde.LogoutPrompt" method call time=1613378261.794569 sender=:1.90 -> destination=org.freedesktop.DBus serial=1 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=Hello method return time=1613378261.796309 sender=org.freedesktop.DBus -> destination=:1.90 serial=1 reply_serial=1 string ":1.90" signal time=1613378261.803800 sender=org.freedesktop.DBus -> destination=(null destination) serial=62 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged string "org.kde.Shutdown" string "" string ":1.90"
(In reply to Fabian Vogt from comment #7) > The difference appears to be that when it fails, ksmserver-logout-greeter > exits before the call to org.kde.Shutdown.logout returns. [10:42] <fvogt> Yep, that way I can 100% reproduce the issue [10:42] <fvogt> "killall plasma-shutdown" to force dbus activation, then "dbus-send --type=method_call --dest=org.kde.Shutdown /Shutdown org.kde.Shutdown.logout". No logout happens With --print-reply, it works all the time.
After hours of compiling dbus-daemon and reading logs, it turns out there's a bug report on it: https://gitlab.freedesktop.org/dbus/dbus/-/issues/72 Still, good to know where the bug is. I'll add the obvious fix.
A possibly relevant merge request was started @ https://invent.kde.org/plasma/plasma-workspace/-/merge_requests/651
A possibly relevant merge request was started @ https://invent.kde.org/plasma/plasma-workspace/-/merge_requests/652
Git commit 81d61861608012e4d7a19e6f85b8d136c298f31f by Fabian Vogt, on behalf of David Edmundson. Committed on 16/02/2021 at 16:46. Pushed by davidedmundson into branch 'master'. [libkworkspace] Interim fix for the logout issue Calls to a DBus activated service can fail if the sender quits whilst the service is spawning (https://gitlab.freedesktop.org/dbus/dbus/-/issues/72) and using dbus-daemon. This is a lazy interim fix that just makes these calls block as proper fixes will require more work. M +6 -6 libkworkspace/sessionmanagement.cpp https://invent.kde.org/plasma/plasma-workspace/commit/81d61861608012e4d7a19e6f85b8d136c298f31f
Git commit 74fef0a9973e62df16ff8fc97a795bce1fa2a273 by David Edmundson. Committed on 17/02/2021 at 09:32. Pushed by davidedmundson into branch 'Plasma/5.21'. [libkworkspace] Interim fix for the logout issue Calls to a DBus activated service can fail if the sender quits whilst the service is spawning (https://gitlab.freedesktop.org/dbus/dbus/-/issues/72) and using dbus-daemon. This is a lazy interim fix that just makes these calls block as proper fixes will require more work. (cherry picked from commit 81d61861608012e4d7a19e6f85b8d136c298f31f) M +6 -6 libkworkspace/sessionmanagement.cpp https://invent.kde.org/plasma/plasma-workspace/commit/74fef0a9973e62df16ff8fc97a795bce1fa2a273