Bug 432460

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