WIP amplify/debug testQualifiedUsers

[martinpitt]

Trying to debug this common flake. I don't get it locally, and there's nothing useful in the journal.

[martinpitt]

Interesting - - so there is no ipaclient-uninstall.log at all. So this smells like the "closed connection" is from realmd when cockpit tries to call .leave().

At first sight this smells like a race condition with an idle timer. But I sit()ed right before clicking the Leave button, and realmd.service still stays alive after several minutes. And neither does the journal show that the service stopped. Also, if I stop realmd.service manually and then continue the test, it fails differently:

warning: Failed to leave domain: No such interface “org.freedesktop.realmd.Realm” on object at path /org/freedesktop/realmd/Sssd/cockpit_lan_2

As the next step I'll enable D-Bus debugging. But that log shows no realmd related D-Bus methods at all, just a lot of packagekit and systemd noise. I'll disable preloads and enable debug messages earlier.

But with that it's no good -- I retried the test about 7 times, and it always succeeds. Heisenbug/timing change.. So I reenabled preloads again, that reproduces it again

Next step, I added some console.logs() to trace what happens at leaving the domain, and to inspect the proxy state and close signals. This shows that it's really the D-Bus Deconfigure() call, not the cleanupWSCredentials(). But the D-Bus debug log does not actually show a Deconfigure call.

Next step, COCKPIT_DEBUG=all ; failed tests, and journal. But that doesn't reveal anything new -- the last D-Bus message is the add_match from getting the Kerberos interface.

There is no disconnected log message anywhere, but there are a few dbus close: console debug messages -- let's investigate them. The run shows no D-Bus debug messages for the realm leave, and no related close messages. Just at the very beginning there is

> wait: ph_is_present("#system_information_domain_button:not([disabled]):not([aria-disabled=true])")    
> debug: dbus close(): org.freedesktop.realmd  have channel: true     
> debug: dbus on_close: org.freedesktop.realmd {"command":"close","channel":"1:2!7"}    
> debug: dbus close_perform: org.freedesktop.realmd {"command":"close","channel":"1:2!7"}    
> debug: dbus open:    
> debug: dbus: {"watch":{"path":"/org/freedesktop/realmd"},"id":"1"}    
> debug: dbus: {"add-match":{"interface":"org.freedesktop.realmd.Realm","path_namespace":"/org/freedesktop/realmd"}}    
> debug: dbus: {"watch":{"interface":"org.freedesktop.realmd.Realm","path_namespace":"/org/freedesktop/realmd"},"id":"2"}    

which I think is just for the overview page to show/check for the current realm. But that happens waay earlier than opening the leave dialog.

[mvollmer]

I'll take over for a while.

First let's disable the D-Bus logging again and start tracing backwards from the dialog error. :)

[mvollmer]

Ok, the issue is a race between the Superuser level, RealmdClient, and LeaveDialog. RealmdClient listens to superuser level changes and will call its own initProxy method twice during every login, once when constructed, and once when superuser.allowed changes from null to true or false. If a LeaveDialog is open when initProxy is called, the internal state of the dialog will become invalid. It will call Deconfigure on a DBusProxy that has been closed by initProxy.

The LeaveDialog could do useEvent(realmd_client, "changed") but that would just expose another race: There is a time where initProxy has already closed the old proxies but the new proxies have not been installed and have not been announced with a "changed" signal. (The amplified tests here hit that pretty reliably.) That could be fixed by closing the old proxies only once the new ones are available.

Another fix is to only call initProxy when superuser.allowed is not null. This is the usual pattern to avoid initializing things twice during page load that depend on the superuser level. I make a PR for that.

[mvollmer]

. But that log shows no realmd related D-Bus methods at all

This is the truth: the Deconfigure method call was never made since the channel was closed when the code tried to make that call. This was super helpful information, thanks!

[mvollmer]

> debug: dbus close(): org.freedesktop.realmd have channel: true

This is initProxy in realmd.jsx closing the old DBusClient before opening a new one. The LeaveDialog was already open at that time but didn't update itself with the new proxies.