TpConnectionManager, TpProtocol: improve debug output

Bug: https://bugs.freedesktop.org/show_bug.cgi?id=68390
Reviewed-by: Guillaume Desmottes <guillaume.desmottes@collabora.co.uk>

4 files changed, 125 insertions, 26 deletions

diff --git a/telepathy-glib/connection-manager.c b/telepathy-glib/connection-manager.c
index c816bfcbb..2dd1c4ec8 100644
--- a/telepathy-glib/connection-manager.c
+++ b/telepathy-glib/connection-manager.c
@@ -600,10 +600,16 @@ tp_connection_manager_got_parameters (TpConnectionManager *self,
 
   if (error != NULL)
     {
-      DEBUG ("Error getting params for %s, skipping it", protocol);
+      DEBUG ("%s/%s: error from legacy GetParameters, skipping protocol: "
+          "%s #%d: %s",
+          self->name, protocol,
+          g_quark_to_string (error->domain), error->code, error->message);
       goto out;
     }
 
+  DEBUG ("%s/%s: legacy GetParameters() returned %d parameters",
+      self->name, protocol, parameters->len);
+
   immutables = tp_asv_new (
       TP_PROP_PROTOCOL_PARAMETERS, TP_ARRAY_TYPE_PARAM_SPEC_LIST, parameters,
       NULL);
@@ -661,7 +667,10 @@ tp_connection_manager_end_introspection (TpConnectionManager *self,
 {
   tp_connection_manager_reset_introspection (self);
 
-  DEBUG ("End of introspection, info source %u", self->info_source);
+  DEBUG ("%s: end of introspection, info source %s (%d)",
+      self->name,
+      _tp_enum_to_nick_nonnull (TP_TYPE_CM_INFO_SOURCE, self->info_source),
+      self->info_source);
   g_signal_emit (self, signals[SIGNAL_GOT_INFO], 0, self->info_source);
   tp_connection_manager_ready_or_failed (self, error);
 }
@@ -722,7 +731,8 @@ tp_connection_manager_get_all_cb (TpProxy *proxy,
           GHashTableIter iter;
           gpointer k, v;
 
-          DEBUG ("%u Protocols from D-Bus", g_hash_table_size (protocols));
+          DEBUG ("%s: %u Protocols from GetAll()",
+              self->name, g_hash_table_size (protocols));
 
           g_assert (self->priv->found_protocols == NULL);
           self->priv->found_protocols = g_hash_table_new_full (g_str_hash,
@@ -755,10 +765,17 @@ tp_connection_manager_get_all_cb (TpProxy *proxy,
                 }
             }
         }
+      else
+        {
+          DEBUG ("%s: no Protocols property in GetAll() (old CM?)",
+              self->name);
+        }
     }
   else
     {
-      DEBUG ("Ignoring error getting ConnectionManager properties: %s %d: %s",
+      DEBUG ("%s: ignoring error getting CM properties (old CM?): "
+          "%s %d: %s",
+          self->name,
           g_quark_to_string (error->domain), error->code, error->message);
     }
 
@@ -776,9 +793,11 @@ tp_connection_manager_continue_introspection (TpConnectionManager *self)
 {
   gchar *next_protocol;
 
+  DEBUG ("%s", self->name);
+
   if (self->priv->introspection_step == INTROSPECT_IDLE)
     {
-      DEBUG ("calling GetAll on CM");
+      DEBUG ("%s: calling GetAll on CM", self->name);
       self->priv->introspection_step = INTROSPECT_GETTING_PROPERTIES;
       self->priv->introspection_call = tp_cli_dbus_properties_call_get_all (
           self, -1, TP_IFACE_CONNECTION_MANAGER,
@@ -792,7 +811,7 @@ tp_connection_manager_continue_introspection (TpConnectionManager *self)
 
       if (self->priv->found_protocols == NULL)
         {
-          DEBUG ("calling ListProtocols on CM");
+          DEBUG ("%s: calling legacy ListProtocols on CM", self->name);
           self->priv->introspection_step = INTROSPECT_LISTING_PROTOCOLS;
           self->priv->introspection_call =
             tp_cli_connection_manager_call_list_protocols (self, -1,
@@ -832,6 +851,8 @@ tp_connection_manager_continue_introspection (TpConnectionManager *self)
       next_protocol = g_ptr_array_remove_index_fast (
           self->priv->pending_protocols, 0);
       self->priv->introspection_step = INTROSPECT_GETTING_PARAMETERS;
+      DEBUG ("%s/%s: calling legacy ListProtocols",
+          self->name, next_protocol);
       self->priv->introspection_call =
           tp_cli_connection_manager_call_get_parameters (self, -1,
               next_protocol, tp_connection_manager_got_parameters,
@@ -854,12 +875,16 @@ tp_connection_manager_got_protocols (TpConnectionManager *self,
 
   if (error != NULL)
     {
-      DEBUG ("Failed: %s", error->message);
+      DEBUG ("%s: legacy GetProtocols() failed: %s #%d: %s",
+          self->name,
+          g_quark_to_string (error->domain), error->code, error->message);
 
       if (!self->running)
         {
           /* ListProtocols failed to start it - we assume this is because
            * activation failed */
+          DEBUG ("%s: ListProtocols didn't start it: activation failure?",
+              self->name);
           g_signal_emit (self, signals[SIGNAL_EXITED], 0);
         }
 
@@ -870,7 +895,7 @@ tp_connection_manager_got_protocols (TpConnectionManager *self,
   for (iter = protocols; *iter != NULL; iter++)
     i++;
 
-  DEBUG ("Succeeded with %u protocols", i);
+  DEBUG ("%s: legacy GetProtocols() returned %u protocols", self->name, i);
 
   g_assert (self->priv->found_protocols == NULL);
   self->priv->found_protocols = g_hash_table_new_full (g_str_hash,
@@ -883,7 +908,7 @@ tp_connection_manager_got_protocols (TpConnectionManager *self,
     {
       if (!tp_connection_manager_check_valid_protocol_name (*iter, NULL))
         {
-          DEBUG ("Protocol %s has an invalid name", *iter);
+          DEBUG ("%s: protocol %s has an invalid name", self->name, *iter);
           continue;
         }
 
@@ -943,13 +968,14 @@ tp_connection_manager_name_owner_changed_cb (TpDBusDaemon *bus,
         {
           if (self->priv->retried_introspection)
             {
-              DEBUG ("%s, twice: assuming fatal and not retrying", e.message);
+              DEBUG ("%s: %s, twice: assuming fatal and not retrying",
+                  self->name, e.message);
               tp_connection_manager_end_introspection (self, &e);
             }
           else
             {
               self->priv->retried_introspection = TRUE;
-              DEBUG ("%s: retrying", e.message);
+              DEBUG ("%s: %s: retrying", self->name, e.message);
               tp_connection_manager_reset_introspection (self);
               tp_connection_manager_continue_introspection (self);
             }
@@ -959,6 +985,7 @@ tp_connection_manager_name_owner_changed_cb (TpDBusDaemon *bus,
        * state, so we didn't *exit* as such. */
       if (self->priv->name_known)
         {
+          DEBUG ("%s: exited", self->name);
           g_signal_emit (self, signals[SIGNAL_EXITED], 0);
         }
     }
@@ -967,8 +994,14 @@ tp_connection_manager_name_owner_changed_cb (TpDBusDaemon *bus,
       /* represent an atomic change of ownership as if it was an exit and
        * restart */
       if (self->running)
-        tp_connection_manager_name_owner_changed_cb (bus, name, "", self);
+        {
+          DEBUG ("%s: atomic name owner change, behaving as if it exited",
+              self->name);
+          tp_connection_manager_name_owner_changed_cb (bus, name, "", self);
+          DEBUG ("%s: back to normal handling", self->name);
+        }
 
+      DEBUG ("%s: is now running", self->name);
       self->running = TRUE;
       g_signal_emit (self, signals[SIGNAL_ACTIVATED], 0);
 
@@ -980,6 +1013,9 @@ tp_connection_manager_name_owner_changed_cb (TpDBusDaemon *bus,
   /* if we haven't started introspecting yet, now would be a good time */
   if (!self->priv->name_known)
     {
+      DEBUG ("%s: starting introspection now we know the name owner",
+          self->name);
+
       g_assert (self->priv->manager_file_read_idle_id == 0);
 
       /* now we know whether we're running or not, we can try reading the
@@ -989,6 +1025,9 @@ tp_connection_manager_name_owner_changed_cb (TpDBusDaemon *bus,
 
       if (self->priv->want_activation && self->priv->introspect_idle_id == 0)
         {
+          DEBUG ("%s: forcing introspection for its side-effect of "
+              "activation",
+              self->name);
           /* ... but if activation was requested, we should also do that */
           self->priv->introspect_idle_id = g_idle_add (
               tp_connection_manager_idle_introspect, self);
@@ -1087,14 +1126,16 @@ tp_connection_manager_idle_read_manager_file (gpointer data)
           GHashTable *protocols;
           GStrv interfaces = NULL;
 
-          DEBUG ("Reading %s", self->priv->manager_file);
+          DEBUG ("%s: reading %s", self->name, self->priv->manager_file);
 
           if (!tp_connection_manager_read_file (
               tp_proxy_get_dbus_daemon (self),
               self->name, self->priv->manager_file, &protocols, &interfaces,
               &error))
             {
-              DEBUG ("Failed to load %s: %s", self->priv->manager_file,
+              DEBUG ("%s: failed to load %s: %s #%d: %s",
+                  self->name, self->priv->manager_file,
+                  g_quark_to_string (error->domain), error->code,
                   error->message);
               g_error_free (error);
               error = NULL;
@@ -1108,7 +1149,7 @@ tp_connection_manager_idle_read_manager_file (gpointer data)
               self->priv->protocol_objects = protocols;
               tp_connection_manager_update_protocol_structs (self);
 
-              DEBUG ("Got info from file");
+              DEBUG ("%s: got info from file", self->name);
               /* previously it must have been NONE */
               self->info_source = TP_CM_INFO_SOURCE_FILE;
 
@@ -1126,15 +1167,21 @@ tp_connection_manager_idle_read_manager_file (gpointer data)
 
       if (self->priv->introspect_idle_id == 0)
         {
-          DEBUG ("no .manager file or failed to parse it, trying to activate "
-              "CM instead");
+          DEBUG ("%s: no .manager file or failed to parse it, trying to "
+              "activate CM instead",
+              self->name);
           tp_connection_manager_idle_introspect (self);
         }
       else
         {
-          DEBUG ("no .manager file, but will activate CM soon anyway");
+          DEBUG ("%s: no .manager file, but will activate CM soon anyway",
+              self->name);
         }
-      /* else we're going to introspect soon anyway */
+    }
+  else
+    {
+      DEBUG ("%s: not reading manager file, %u protocols already discovered",
+          self->name, g_hash_table_size (self->priv->protocol_objects));
     }
 
 out:
@@ -1653,18 +1700,26 @@ tp_connection_manager_activate (TpConnectionManager *self)
     {
       if (self->running)
         {
-          DEBUG ("already running");
+          DEBUG ("%s: already running", self->name);
           return FALSE;
         }
 
       if (self->priv->introspect_idle_id == 0)
-        self->priv->introspect_idle_id = g_idle_add (
-            tp_connection_manager_idle_introspect, self);
+        {
+          DEBUG ("%s: adding idle introspection", self->name);
+          self->priv->introspect_idle_id = g_idle_add (
+              tp_connection_manager_idle_introspect, self);
+        }
+      else
+        {
+          DEBUG ("%s: idle introspection already added", self->name);
+        }
     }
   else
     {
       /* we'll activate later, when we know properly whether we're running */
-      DEBUG ("queueing activation for when we know what's going on");
+      DEBUG ("%s: queueing activation for when we know what's going on",
+          self->name);
       self->priv->want_activation = TRUE;
     }
 
diff --git a/telepathy-glib/protocol.c b/telepathy-glib/protocol.c
index e60005918..b2935c042 100644
--- a/telepathy-glib/protocol.c
+++ b/telepathy-glib/protocol.c
@@ -411,15 +411,22 @@ tp_protocol_check_for_core (TpProtocol *self)
   value = tp_asv_lookup (props, TP_PROP_PROTOCOL_CONNECTION_INTERFACES);
 
   if (value == NULL || !G_VALUE_HOLDS (value, G_TYPE_STRV))
-    return FALSE;
+    {
+      DEBUG ("Interfaces not found");
+      return FALSE;
+    }
 
   if (tp_asv_get_boxed (props, TP_PROP_PROTOCOL_REQUESTABLE_CHANNEL_CLASSES,
         TP_ARRAY_TYPE_REQUESTABLE_CHANNEL_CLASS_LIST) == NULL)
-    return FALSE;
+    {
+      DEBUG ("Requestable channel classes not found");
+      return FALSE;
+    }
 
   /* Interfaces has a sensible default, the empty list.
    * VCardField, EnglishName and Icon have a sensible default, "". */
 
+  DEBUG ("Core feature ready");
   return TRUE;
 }
 
@@ -464,12 +471,20 @@ tp_protocol_constructed (GObject *object)
 
   g_assert (self->priv->protocol_struct.name != NULL);
 
+  DEBUG ("%s/%s: new Protocol", self->priv->cm_name,
+      self->priv->protocol_struct.name);
+
   if (self->priv->protocol_properties == NULL)
     {
+      DEBUG ("immutable properties not supplied");
       had_immutables = FALSE;
       self->priv->protocol_properties = g_hash_table_new_full (g_str_hash,
           g_str_equal, g_free, (GDestroyNotify) tp_g_value_slice_free);
     }
+  else
+    {
+      DEBUG ("immutable properties already supplied");
+    }
 
   self->priv->protocol_struct.params = tp_protocol_params_from_param_specs (
         tp_asv_get_boxed (self->priv->protocol_properties,
@@ -1529,10 +1544,12 @@ _tp_protocol_parse_manager_file (GKeyFile *file,
 
   if (!tp_connection_manager_check_valid_protocol_name (name, NULL))
     {
-      DEBUG ("Protocol '%s' has an invalid name", name);
+      DEBUG ("%s: protocol '%s' has an invalid name", cm_debug_name, name);
       return NULL;
     }
 
+  DEBUG ("%s: reading protocol '%s' from manager file", cm_debug_name, name);
+
   keys = g_key_file_get_keys (file, group, NULL, NULL);
 
   i = 0;
diff --git a/telepathy-glib/util-internal.h b/telepathy-glib/util-internal.h
index b1ecaa414..bf15a0a9a 100644
--- a/telepathy-glib/util-internal.h
+++ b/telepathy-glib/util-internal.h
@@ -50,6 +50,7 @@ GList * _tp_create_channel_request_list (TpSimpleClientFactory *factory,
 
 gboolean _tp_enum_from_nick (GType enum_type, const gchar *nick, gint *value);
 const gchar *_tp_enum_to_nick (GType enum_type, gint value);
+const gchar *_tp_enum_to_nick_nonnull (GType enum_type, gint value);
 
 #define _tp_implement_finish_void(source, tag) \
     if (g_simple_async_result_propagate_error (\
diff --git a/telepathy-glib/util.c b/telepathy-glib/util.c
index c89bc66d7..e01dd2291 100644
--- a/telepathy-glib/util.c
+++ b/telepathy-glib/util.c
@@ -1764,6 +1764,32 @@ _tp_enum_to_nick (
     return NULL;
 }
 
+/*
+ * _tp_enum_to_nick_nonnull:
+ *
+ * The same as _tp_enum_to_nick, but always returns non-NULL.
+ */
+const gchar *
+_tp_enum_to_nick_nonnull (
+    GType enum_type,
+    gint value)
+{
+  GEnumClass *klass = g_type_class_ref (enum_type);
+  GEnumValue *enum_value;
+
+  g_return_val_if_fail (klass != NULL, "(incorrect class)");
+
+  enum_value = g_enum_get_value (klass, value);
+  g_type_class_unref (klass);
+
+  if (enum_value == NULL)
+    return "(out-of-range value)";
+  else if (enum_value->value_nick == NULL)
+    return "(value with no nickname)";
+  else
+    return enum_value->value_nick;
+}
+
 gboolean
 _tp_bind_connection_status_to_boolean (GBinding *binding,
     const GValue *src_value,