Comment 17 for bug 1211514

Revision history for this message
Martin Pitt (pitti) wrote :

I now ran everything with D-BUS monitoring and GDBUS debugging in shim.

When selecting "Shutdown" from the indicator, on the session bus there's nothing surprising:

method call sender=:1.18 -> dest=:1.34 serial=53 path=/org/gnome/SessionManager/EndSessionDialog; interface=org
.gnome.SessionManager.EndSessionDialog; member=Open
method call sender=:1.34 -> dest=:1.13 serial=538 path=/org/gnome/SessionManager; interface=org.gnome.SessionManager; member=Shutdown

gnome-session then calls to systemd for the actual shutdown on the system bus:

signal sender=:1.2 -> dest=(null destination) serial=156 path=/org/freedesktop/login1; interface=org.freedeskto
p.login1.Manager; member=PrepareForShutdown
   boolean true

method call sender=:1.2 -> dest=org.freedesktop.systemd1 serial=165 path=/org/freedesktop/systemd1; interface=org.freedesktop.systemd1.Manager; member=StartUnit
   string "poweroff.target"
   string "replace-irreversibly"

Notably this is the only method call to systemd-shim in the whole process (I don't see a suspend.target call!), and there are no calls to UPower or logind.

However, there is no corresponding entry in systemd-shim's debug output. Instead, I only see:

18:06:24 O: interface -> 'org.freedesktop.systemd1.Manager'
18:06:24 O: member -> 'StartUnit'
18:06:24 O: destination -> 'org.freedesktop.systemd1'
18:06:24 O: sender -> ':1.2'
18:06:24 O: signature -> signature 'ss'
18:06:24 O: Body: ('suspend.target', 'replace-irreversibly')

so something (presumably logind) indeed calls systemd-shim's suspend target when I close the lid. Conversely, I don't see *that* call in the system D-BUS monitor.

However, monitoring D-BUS during shutdown is a rather wonky business in the first place, as during shutdown the system D-BUS itself is being killed. So I figure it wasn't actually running any more, or being shut down when I closed the lid, and I missed logind's suspend call to systemd-shim.

The main oddity which points out why this happens is that systemd-shim does *not* stay running as one would expect:

18:28:17 I: Started /usr/lib/x86_64-linux-gnu/systemd-shim
18:28:17 E:
18:28:17 E: ** (process:3919): WARNING **: going into in_shutdown mode now
[...] # ^ I manually added that warning for debugging the in_shutdown flag
18:28:18 O: GDBus-debug:Call:
18:28:18 O: >>>> ASYNC org.freedesktop.DBus.RequestName()
[...] # this does not get very far:
18:28:18 O: GDBus-debug:Transport:
18:28:18 O: <<<< READ 16 bytes of message with serial 3 and
18:28:18 O: size 189 to offset 0 from a GSocketInputStream
Terminated

and immediately afterwards:
18:28:19 I: Started /usr/lib/x86_64-linux-gnu/systemd-shim
[...] # so at that point we definitively lost the call to poweroff.target and the in_shutdown flag.
18:28:19 O: GDBus-debug:Message:
[...]
18:28:19 O: Body: ('suspend.target', 'replace-irreversibly')
   # this would then actually be executed as it's a fresh instance.

So as far as I can see, we need to keep systemd-shim alive even if the system D-BUS is being shut down. It still seems to be alive enough to spawn new requests, but it already *seems* to kill existing instances; at least that's how I interpret the "Terminated". It now needs to be confirmed what exactly terminates the shim.