Endianness issues with systemd <-> dbus communication

[Simon McVittie]

On 12/03/14 11:55, Fridrich Strba wrote:
> dbus-daemon will assign a unique name, like "1.0" to the
> connection.

More like ":1.0", but yes.

> It sends back a METHOD_RETURN message indicating success (cookie
> 1), followed by a NameAcquired signal (cookie 2).

Terminology note: systemd's "cookie" is the D-Bus specification's
"serial number". I assume the rename is because the protocol does not
strictly require them to increase by 1 every time, so "serial number"
is slightly misleading.

> Next, systemd will try to grab its bus name by calling RequestName 
> with a name of "org.freedesktop.systemd1". This message will use a 
> cookie of 2.
> 
> Then, in sd_bus_call, we block a moment waiting for data to
> arrive. When the next message hits our queue, it will be the
> NameAcquired signal with a cookie of 2. Note, this matches the
> cookie we were looking for, hence we execute this:
> 
> if (incoming->reply_cookie == cookie) {

But that's not true in this situation: there are separate message
header fields for "the serial number of this message" and "the serial
number of the message to which this is a reply". Each sender of
messages maintains their own sequence of serial numbers (or cookies,
if you prefer) for their own outgoing messages.

The real situation here would be something like this. I'm using "s1"
to mean "serial number 1 in the namespace managed by systemd" and "d1"
to mean "serial number 1 in the namespace managed by dbus-daemon", in
attempt to improve clarity - in the actual message stream, they're
both just "1", but you can tell from context which one is meant
(serial number = newly allocated by this message's sender, in-reply-to
= already allocated by this message's destination).

  systemd                                    dbus-daemon
    -> method call Hello (s1, in reply to = nothing)
    <- method reply for Hello (d1, in reply to = s1)
  { in an undefined order:
    -> method call RequestName (s2, in reply to = nothing)
    <- signal NameAcquired (d2, in reply to = nothing)
  }
    <- method reply for RequestName (d3, in reply to = s2)

>From the code you quoted, it seems sd_bus correctly distinguishes
between those two two header fields (at least in that snippet - there
might be a bug elsewhere).

> The major difference between x86_64 and s390x seems to be the
> start order. On x86_64 the systemd-logind is installed and started
> before dbus while on s390x the systemd-logind is started after
> dbus.
...
> Any hints what could one try to check?

dbus still doesn't have regression tests for activation of services
via systemd <https://bugs.freedesktop.org/show_bug.cgi?id=57952> so
maybe writing one, making sure it passes on x86_64, then running it on
s390x would produce interesting results.

My proof-of-concept patches to make dbus-daemon log the entire message
stream, from the beginning, in pcap format
<https://bugs.freedesktop.org/show_bug.cgi?id=60859> might also be
useful here: if you can capture the stream on a working x86_64 machine
and on a non-working s390x machine, comparing them might be
enlightening. Bustle <http://www.willthompson.co.uk/bustle/> knows how
to read those pcap traces, and writing a standalone decoder/hex-dumper
using GDBus would probably also be pretty easy.

dbus-monitor is not the right answer for monitoring the system bus,
partly because it would need to start before systemd tries to connect
in order to be fully useful here, but mostly because the design of the
system bus security policy makes it basically impossible to allow root
to eavesdrop using dbus-monitor without also changing the method calls
that other users are allowed to send, undermining system security. I
hope kdbus will have a read-only monitoring interface available to
suitably privileged/capable processes that fixes that design flaw? I
would advocate pcap as the output format if you don't already have one
in mind - it's really simple, and there are already tools that
understand it.

    S