sd-bus: make sure type=error messages are also dumped

[haraldh]

No description provided.

[dvdhrm]

Isn't this also missing for method-replies in sd_bus_call()? That is, directly above your log_debug_bus_message() call for type=error we also directly return.

Maybe I'm missing something, but why not move your log_debug_...() call below the memmove() call above? That is, after unlinking the message from the rqueue, we print it.

[utezduyar]

Haven't looked at the code but replies work fine:

[root@axis-00408cecff49 /mnt/flash/root]1132# SYSTEMD_LOG_LEVEL=debug busctl tree com.a.b
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=Hello cookie=1 reply_cookie=0 error=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.227 object=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 error=n/a
Sent message type=method_call sender=n/a destination=com.a.b object=/ interface=org.freedesktop.DBus.Introspectable member=Introspect cookie=2 reply_cookie=0 error=n/a
Failed to introspect object / of service com.a.b: The name com.a.b was not provided by any .service files
No objects discovered.

WITH THE PATCH

[root@axis-00408cecff49 /mnt/flash/root]1132# SYSTEMD_LOG_LEVEL=debug busctl tree com.a.b
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=Hello cookie=1 reply_cookie=0 error=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.228 object=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 error=n/a
Sent message type=method_call sender=n/a destination=com.a.b object=/ interface=org.freedesktop.DBus.Introspectable member=Introspect cookie=2 reply_cookie=0 error=n/a
Got message type=error sender=org.freedesktop.DBus destination=:1.228 object=n/a interface=n/a member=n/a cookie=3 reply_cookie=2 error=The name com.a.b was not provided by any .service files
Failed to introspect object / of service com.a.b: The name com.a.b was not provided by any .service files
No objects discovered.

[dvdhrm]

Replies work only fine for asynchronously read messages. In those cases, errors also work fine, btw. The bug which is tried to get fixed here is about synchronously read messages. In those cases, neither return nor error messages are printed.

See this example:

david@david-t2 ~ $ SYSTEMD_LOG_LEVEL=7 busctl call org.freedesktop.login1 /org/freedesktop/login1 org.freedesktop.login1.Manager ListSessions
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=Hello cookie=1 reply_cookie=0 error=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.22 object=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 error=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.login1 object=/org/freedesktop/login1 interface=org.freedesktop.login1.Manager member=ListSessions cookie=2 reply_cookie=0 error=n/a
a(susso) 1 "c1" 1000 "david" "seat0" "/org/freedesktop/login1/session/c1"

As you can see, the async Hello message gets a method_return. But the sync ListSessions does not (even though the result is displayed).

[utezduyar]

Continuing from harald's pull request instead of creating a new one... Btw, thanks David.

From 2e6520ffd6efbb2bf26462008a4c2371b70c8fb8 Mon Sep 17 00:00:00 2001
From: Umut Tezduyar Lindskog <[email protected]>
Date: Fri, 29 May 2015 09:48:11 +0200
Subject: [PATCH] sd-bus: make sure type=error messages are also dumped

---
 src/libsystemd/sd-bus/sd-bus.c | 23 +++++++++++++----------
 1 file changed, 13 insertions(+), 10 deletions(-)

diff --git a/src/libsystemd/sd-bus/sd-bus.c b/src/libsystemd/sd-bus/sd-bus.c
index edc27ae..096564d 100644
--- a/src/libsystemd/sd-bus/sd-bus.c
+++ b/src/libsystemd/sd-bus/sd-bus.c
@@ -49,6 +49,17 @@
 #include "bus-track.h"
 #include "bus-slot.h"

+#define log_debug_bus_message(m) log_debug("Got message type=%s sender=%s destination=%s object=%s interface=%s member=%s cookie=%" PRIu64 " reply_cookie=%" PRIu64 " error=%s", \
+                  bus_message_type_to_string(m->header->type), \
+                  strna(sd_bus_message_get_sender(m)), \
+                  strna(sd_bus_message_get_destination(m)), \
+                  strna(sd_bus_message_get_path(m)), \
+                  strna(sd_bus_message_get_interface(m)), \
+                  strna(sd_bus_message_get_member(m)), \
+                  BUS_MESSAGE_COOKIE(m), \
+                  m->reply_cookie, \
+                  strna(m->error.message))
+
 static int bus_poll(sd_bus *bus, bool need_more, uint64_t timeout_usec);
 static int attach_io_events(sd_bus *b);
 static void detach_io_events(sd_bus *b);
@@ -1992,6 +2003,7 @@ _public_ int sd_bus_call(

                                 memmove(bus->rqueue + i, bus->rqueue + i + 1, sizeof(sd_bus_message*) * (bus->rqueue_size - i - 1));
                                 bus->rqueue_size--;
+                                log_debug_bus_message(incoming);

                                 if (incoming->header->type == SD_BUS_MESSAGE_METHOD_RETURN) {

@@ -2480,16 +2492,7 @@ static int process_message(sd_bus *bus, sd_bus_message *m) {
         bus->current_message = m;
         bus->iteration_counter++;

-        log_debug("Got message type=%s sender=%s destination=%s object=%s interface=%s member=%s cookie=%" PRIu64 " reply_cookie=%" PRIu64 " error=%s",
-                  bus_message_type_to_string(m->header->type),
-                  strna(sd_bus_message_get_sender(m)),
-                  strna(sd_bus_message_get_destination(m)),
-                  strna(sd_bus_message_get_path(m)),
-                  strna(sd_bus_message_get_interface(m)),
-                  strna(sd_bus_message_get_member(m)),
-                  BUS_MESSAGE_COOKIE(m),
-                  m->reply_cookie,
-                  strna(m->error.message));
+        log_debug_bus_message(m);

         r = process_hello(bus, m);
         if (r != 0)
-- 
2.1.4

[poettering]

@utezduyar your last patch looks good, can you post this as new PR please refencing this one so that we can merge it?

[utezduyar]

Moved to #117
Please close this PR.