Bug 620913 – More control with G_DBUS_DEBUG

This commit adds the following G_DBUS_DEBUG flags

 - emission
 - incoming
 - call
 - signal
 - payload

https://bugzilla.gnome.org/show_bug.cgi?id=620913

Signed-off-by: David Zeuthen <davidz@redhat.com>

docs/reference/gio/overview.xml

@@ -343,6 +343,26 @@
              <term>message</term>
              <listitem><para>Show all sent and received D-Bus messages</para></listitem>
            </varlistentry>
+           <varlistentry>
+             <term>payload</term>
+             <listitem><para>Show payload for all sent and received D-Bus messages (implies message)</para></listitem>
+           </varlistentry>
+           <varlistentry>
+             <term>call</term>
+             <listitem><para>Trace g_dbus_connection_call() and g_dbus_connection_call_sync() API usage</para></listitem>
+           </varlistentry>
+           <varlistentry>
+             <term>signal</term>
+             <listitem><para>Show when a D-Bus signal is received</para></listitem>
+           </varlistentry>
+           <varlistentry>
+             <term>incoming</term>
+             <listitem><para>Show when an incoming D-Bus method call is received</para></listitem>
+           </varlistentry>
+           <varlistentry>
+             <term>emission</term>
+             <listitem><para>Trace g_dbus_connection_emit_signal() API usage</para></listitem>
+           </varlistentry>
            <varlistentry>
              <term>authentication</term>
              <listitem><para>Information about authentication</para></listitem>

gio/gdbusconnection.c

@@ -71,7 +71,7 @@
  *   - see g_dbus_address_connect() in gdbusaddress.c
  *
  * - would be cute to use kernel-specific APIs to resolve fds for
- *   debug output when using G_DBUS_DEBUG=messages, e.g. in addition to
+ *   debug output when using G_DBUS_DEBUG=message, e.g. in addition to
  *
  *     fd 21: dev=8:1,mode=0100644,ino=1171231,uid=0,gid=0,rdev=0:0,size=234,atime=1273070640,mtime=1267126160,ctime=1267126160
  *
@@ -3007,6 +3007,21 @@ distribute_signals (GDBusConnection *connection,
 
   sender = g_dbus_message_get_sender (message);
 
+  if (G_UNLIKELY (_g_dbus_debug_signal ()))
+    {
+      _g_dbus_debug_print_lock ();
+      g_print ("========================================================================\n"
+               "GDBus-debug:Signal:\n"
+               " >>>> SIGNAL %s.%s\n"
+               "      on object %s\n"
+               "      sent by name %s\n",
+               g_dbus_message_get_interface (message),
+               g_dbus_message_get_member (message),
+               g_dbus_message_get_path (message),
+               sender != NULL ? sender : "(none)");
+      _g_dbus_debug_print_unlock ();
+    }
+
   /* collect subscribers that match on sender */
   if (sender != NULL)
     {
@@ -4273,6 +4288,20 @@ g_dbus_connection_emit_signal (GDBusConnection  *connection,
   g_return_val_if_fail (signal_name != NULL && g_dbus_is_member_name (signal_name), FALSE);
   g_return_val_if_fail (parameters == NULL || g_variant_is_of_type (parameters, G_VARIANT_TYPE_TUPLE), FALSE);
 
+  if (G_UNLIKELY (_g_dbus_debug_emission ()))
+    {
+      _g_dbus_debug_print_lock ();
+      g_print ("========================================================================\n"
+               "GDBus-debug:Emission:\n"
+               " >>>> SIGNAL EMISSION %s.%s()\n"
+               "      on object %s\n"
+               "      destination %s\n",
+               interface_name, signal_name,
+               object_path,
+               destination_bus_name != NULL ? destination_bus_name : "(none)");
+      _g_dbus_debug_print_unlock ();
+    }
+
   message = g_dbus_message_new_signal (object_path,
                                        interface_name,
                                        signal_name);
@@ -4356,6 +4385,7 @@ typedef struct
   GSimpleAsyncResult *simple;
   GVariantType *reply_type;
   gchar *method_name; /* for error message */
+  guint32 serial;
 } CallState;
 
 static void
@@ -4365,12 +4395,36 @@ g_dbus_connection_call_done (GObject      *source,
 {
   GDBusConnection *connection = G_DBUS_CONNECTION (source);
   CallState *state = user_data;
-  GError *error = NULL;
+  GError *error;
   GDBusMessage *reply;
   GVariant *value;
 
+  error = NULL;
   reply = g_dbus_connection_send_message_with_reply_finish (connection,
-                                                            result, &error);
+                                                            result,
+                                                            &error);
+
+  if (G_UNLIKELY (_g_dbus_debug_call ()))
+    {
+      _g_dbus_debug_print_lock ();
+      g_print ("========================================================================\n"
+               "GDBus-debug:Call:\n"
+               " >>>> ASYNC COMPLETE %s() (serial %d)\n"
+               "      ",
+               state->method_name,
+               state->serial);
+      if (reply != NULL)
+        {
+          g_print ("SUCCESS\n");
+        }
+      else
+        {
+          g_print ("FAILED: %s\n",
+                   error->message);
+        }
+      _g_dbus_debug_print_unlock ();
+    }
+
 
   if (reply != NULL)
     {
@@ -4503,11 +4557,27 @@ g_dbus_connection_call (GDBusConnection        *connection,
   g_dbus_connection_send_message_with_reply (connection,
                                              message,
                                              timeout_msec,
-                                             NULL, /* volatile guint32 *out_serial */
+                                             &state->serial,
                                              cancellable,
                                              g_dbus_connection_call_done,
                                              state);
 
+  if (G_UNLIKELY (_g_dbus_debug_call ()))
+    {
+      _g_dbus_debug_print_lock ();
+      g_print ("========================================================================\n"
+               "GDBus-debug:Call:\n"
+               " >>>> ASYNC %s.%s()\n"
+               "      on object %s\n"
+               "      owned by name %s (serial %d)\n",
+               interface_name,
+               method_name,
+               object_path,
+               bus_name != NULL ? bus_name : "(none)",
+               state->serial);
+      _g_dbus_debug_print_unlock ();
+    }
+
   if (message != NULL)
     g_object_unref (message);
 }
@@ -4619,6 +4689,7 @@ g_dbus_connection_call_sync (GDBusConnection         *connection,
   GDBusMessage *message;
   GDBusMessage *reply;
   GVariant *result;
+  GError *local_error;
 
   message = NULL;
   reply = NULL;
@@ -4643,15 +4714,58 @@ g_dbus_connection_call_sync (GDBusConnection         *connection,
   if (parameters != NULL)
     g_dbus_message_set_body (message, parameters);
 
+  if (G_UNLIKELY (_g_dbus_debug_call ()))
+    {
+      _g_dbus_debug_print_lock ();
+      g_print ("========================================================================\n"
+               "GDBus-debug:Call:\n"
+               " >>>> SYNC %s.%s()\n"
+               "      on object %s\n"
+               "      owned by name %s\n",
+               interface_name,
+               method_name,
+               object_path,
+               bus_name != NULL ? bus_name : "(none)");
+      _g_dbus_debug_print_unlock ();
+    }
+
+  local_error = NULL;
   reply = g_dbus_connection_send_message_with_reply_sync (connection,
                                                           message,
                                                           timeout_msec,
                                                           NULL, /* volatile guint32 *out_serial */
                                                           cancellable,
-                                                          error);
+                                                          &local_error);
+
+  if (G_UNLIKELY (_g_dbus_debug_call ()))
+    {
+      _g_dbus_debug_print_lock ();
+      g_print ("========================================================================\n"
+               "GDBus-debug:Call:\n"
+               " <<<< SYNC COMPLETE %s.%s()\n"
+               "      ",
+               interface_name,
+               method_name);
+      if (reply != NULL)
+        {
+          g_print ("SUCCESS\n");
+        }
+      else
+        {
+          g_print ("FAILED: %s\n",
+                   local_error->message);
+        }
+      _g_dbus_debug_print_unlock ();
+    }
 
   if (reply == NULL)
+    {
+      if (error != NULL)
+        *error = local_error;
+      else
+        g_error_free (local_error);
       goto out;
+    }
 
   result = decode_method_reply (reply, method_name, reply_type, error);
 
@@ -5380,6 +5494,21 @@ distribute_method_call (GDBusConnection *connection,
       subtree_path = NULL;
     }
 
+
+  if (G_UNLIKELY (_g_dbus_debug_incoming ()))
+    {
+      _g_dbus_debug_print_lock ();
+      g_print ("========================================================================\n"
+               "GDBus-debug:Incoming:\n"
+               " >>>> METHOD INVOCATION %s.%s()\n"
+               "      on object %s\n"
+               "      invoked by name %s\n",
+               interface_name, member,
+               path,
+               g_dbus_message_get_sender (message) != NULL ? g_dbus_message_get_sender (message) : "(none)");
+      _g_dbus_debug_print_unlock ();
+    }
+
 #if 0
   g_debug ("interface    = `%s'", interface_name);
   g_debug ("member       = `%s'", member);

gio/gdbusprivate.c

@@ -698,6 +698,7 @@ _g_dbus_worker_do_read_cb (GInputStream  *input_stream,
           if (G_UNLIKELY (_g_dbus_debug_message ()))
             {
               gchar *s;
+              _g_dbus_debug_print_lock ();
               g_print ("========================================================================\n"
                        "GDBus-debug:Message:\n"
                        "  <<<< RECEIVED D-Bus message (%" G_GSIZE_FORMAT " bytes)\n",
@@ -705,10 +706,14 @@ _g_dbus_worker_do_read_cb (GInputStream  *input_stream,
               s = g_dbus_message_print (message, 2);
               g_print ("%s", s);
               g_free (s);
+              if (G_UNLIKELY (_g_dbus_debug_payload ()))
+                {
                   s = _g_dbus_hexdump (worker->read_buffer, worker->read_buffer_cur_size, 2);
                   g_print ("%s\n", s);
                   g_free (s);
                 }
+              _g_dbus_debug_print_unlock ();
+            }
 
           /* yay, got a message, go deliver it */
           _g_dbus_worker_queue_or_deliver_received_message (worker, message);
@@ -906,6 +911,7 @@ write_message (GDBusWorker         *worker,
   if (G_UNLIKELY (_g_dbus_debug_message ()))
     {
       gchar *s;
+      _g_dbus_debug_print_lock ();
       g_print ("========================================================================\n"
                "GDBus-debug:Message:\n"
                "  >>>> SENT D-Bus message (%" G_GSIZE_FORMAT " bytes)\n",
@@ -913,10 +919,14 @@ write_message (GDBusWorker         *worker,
       s = g_dbus_message_print (data->message, 2);
       g_print ("%s", s);
       g_free (s);
+      if (G_UNLIKELY (_g_dbus_debug_payload ()))
+        {
           s = _g_dbus_hexdump (data->blob, data->blob_size, 2);
           g_print ("%s\n", s);
           g_free (s);
         }
+      _g_dbus_debug_print_unlock ();
+    }
 
  out:
   return ret;
@@ -1084,6 +1094,11 @@ _g_dbus_worker_stop (GDBusWorker *worker)
 
 #define G_DBUS_DEBUG_AUTHENTICATION (1<<0)
 #define G_DBUS_DEBUG_MESSAGE        (1<<1)
+#define G_DBUS_DEBUG_PAYLOAD        (1<<2)
+#define G_DBUS_DEBUG_CALL           (1<<3)
+#define G_DBUS_DEBUG_SIGNAL         (1<<4)
+#define G_DBUS_DEBUG_INCOMING       (1<<5)
+#define G_DBUS_DEBUG_EMISSION       (1<<6)
 #define G_DBUS_DEBUG_ALL            0xffffffff
 static gint _gdbus_debug_flags = 0;
 
@@ -1101,6 +1116,55 @@ _g_dbus_debug_message (void)
   return (_gdbus_debug_flags & G_DBUS_DEBUG_MESSAGE) != 0;
 }
 
+gboolean
+_g_dbus_debug_payload (void)
+{
+  _g_dbus_initialize ();
+  return (_gdbus_debug_flags & G_DBUS_DEBUG_PAYLOAD) != 0;
+}
+
+gboolean
+_g_dbus_debug_call (void)
+{
+  _g_dbus_initialize ();
+  return (_gdbus_debug_flags & G_DBUS_DEBUG_CALL) != 0;
+}
+
+gboolean
+_g_dbus_debug_signal (void)
+{
+  _g_dbus_initialize ();
+  return (_gdbus_debug_flags & G_DBUS_DEBUG_SIGNAL) != 0;
+}
+
+gboolean
+_g_dbus_debug_incoming (void)
+{
+  _g_dbus_initialize ();
+  return (_gdbus_debug_flags & G_DBUS_DEBUG_INCOMING) != 0;
+}
+
+gboolean
+_g_dbus_debug_emission (void)
+{
+  _g_dbus_initialize ();
+  return (_gdbus_debug_flags & G_DBUS_DEBUG_EMISSION) != 0;
+}
+
+G_LOCK_DEFINE_STATIC (print_lock);
+
+void
+_g_dbus_debug_print_lock (void)
+{
+  G_LOCK (print_lock);
+}
+
+void
+_g_dbus_debug_print_unlock (void)
+{
+  G_UNLOCK (print_lock);
+}
+
 /*
  * _g_dbus_initialize:
  *
@@ -1133,6 +1197,16 @@ _g_dbus_initialize (void)
                 _gdbus_debug_flags |= G_DBUS_DEBUG_AUTHENTICATION;
               else if (g_strcmp0 (tokens[n], "message") == 0)
                 _gdbus_debug_flags |= G_DBUS_DEBUG_MESSAGE;
+              else if (g_strcmp0 (tokens[n], "payload") == 0) /* implies `message' */
+                _gdbus_debug_flags |= (G_DBUS_DEBUG_MESSAGE | G_DBUS_DEBUG_PAYLOAD);
+              else if (g_strcmp0 (tokens[n], "call") == 0)
+                _gdbus_debug_flags |= G_DBUS_DEBUG_CALL;
+              else if (g_strcmp0 (tokens[n], "signal") == 0)
+                _gdbus_debug_flags |= G_DBUS_DEBUG_SIGNAL;
+              else if (g_strcmp0 (tokens[n], "incoming") == 0)
+                _gdbus_debug_flags |= G_DBUS_DEBUG_INCOMING;
+              else if (g_strcmp0 (tokens[n], "emission") == 0)
+                _gdbus_debug_flags |= G_DBUS_DEBUG_EMISSION;
               else if (g_strcmp0 (tokens[n], "all") == 0)
                 _gdbus_debug_flags |= G_DBUS_DEBUG_ALL;
             }

gio/gdbusprivate.h

@@ -76,6 +76,13 @@ void         _g_dbus_worker_unfreeze     (GDBusWorker    *worker);
 void _g_dbus_initialize (void);
 gboolean _g_dbus_debug_authentication (void);
 gboolean _g_dbus_debug_message (void);
+gboolean _g_dbus_debug_payload (void);
+gboolean _g_dbus_debug_call    (void);
+gboolean _g_dbus_debug_signal  (void);
+gboolean _g_dbus_debug_incoming (void);
+gboolean _g_dbus_debug_emission (void);
+void     _g_dbus_debug_print_lock (void);
+void     _g_dbus_debug_print_unlock (void);
 
 gboolean _g_dbus_address_parse_entry (const gchar  *address_entry,
                                       gchar       **out_transport_name,