plugin-manager,plugin: improve logging

Logging which are the reasons for a plugin to filter a given port really help
when trying to debug user issues. Some other general logging improvements also
done.

2 files changed, 94 insertions, 70 deletions

diff --git a/src/mm-plugin-manager.c b/src/mm-plugin-manager.c
index 67fb670d..e456c73d 100644
--- a/src/mm-plugin-manager.c
+++ b/src/mm-plugin-manager.c
@@ -135,8 +135,7 @@ port_probe_context_finished (PortProbeContext *port_probe_ctx)
         gboolean cancel_remaining;
         GList *l;
 
-        mm_dbg ("(%s/%s): not supported by any plugin",
-                g_udev_device_get_subsystem (port_probe_ctx->port),
+        mm_dbg ("(Plugin Manager) [%s] not supported by any plugin",
                 g_udev_device_get_name (port_probe_ctx->port));
 
         /* Tell the device to ignore this port */
@@ -175,10 +174,9 @@ port_probe_context_finished (PortProbeContext *port_probe_ctx)
              device_plugin != port_probe_ctx->best_plugin)) {
             /* Only log best plugin if it's not the generic one */
             if (!g_str_equal (mm_plugin_get_name (port_probe_ctx->best_plugin), MM_PLUGIN_GENERIC_NAME))
-                mm_dbg ("(%s/%s): found best plugin (%s) for device (%s)",
-                        g_udev_device_get_subsystem (port_probe_ctx->port),
-                        g_udev_device_get_name (port_probe_ctx->port),
+                mm_dbg ("(Plugin Manager) (%s) [%s]: found best plugin for device (%s)",
                         mm_plugin_get_name (port_probe_ctx->best_plugin),
+                        g_udev_device_get_name (port_probe_ctx->port),
                         mm_device_get_path (ctx->device));
 
             mm_device_set_plugin (ctx->device, G_OBJECT (port_probe_ctx->best_plugin));
@@ -190,8 +188,7 @@ port_probe_context_finished (PortProbeContext *port_probe_ctx)
          * best plugin found for the the first probed port */
         else if (!g_str_equal (mm_plugin_get_name (device_plugin),
                                mm_plugin_get_name (port_probe_ctx->best_plugin)))
-            mm_warn ("(%s/%s): plugin mismatch error (expected: '%s', got: '%s')",
-                     g_udev_device_get_subsystem (port_probe_ctx->port),
+            mm_warn ("(Plugin Manager) (%s): plugin mismatch error (expected: '%s', got: '%s')",
                      g_udev_device_get_name (port_probe_ctx->port),
                      mm_plugin_get_name (MM_PLUGIN (mm_device_peek_plugin (ctx->device))),
                      mm_plugin_get_name (port_probe_ctx->best_plugin));
@@ -249,17 +246,15 @@ suggest_port_probe_result (FindDeviceSupportContext *ctx,
              * complete it */
             if (port_probe_ctx->defer_until_suggested) {
                 if (suggested_plugin) {
-                    mm_dbg ("(%s/%s) deferred task completed, got suggested plugin (%s)",
-                            g_udev_device_get_subsystem (port_probe_ctx->port),
-                            g_udev_device_get_name (port_probe_ctx->port),
-                            mm_plugin_get_name (suggested_plugin));
+                    mm_dbg ("(Plugin Manager) (%s) [%s] deferred task completed, got suggested plugin",
+                            mm_plugin_get_name (suggested_plugin),
+                            g_udev_device_get_name (port_probe_ctx->port));
                     /* Advance to the suggested plugin and re-check support there */
                     port_probe_ctx->suggested_plugin = g_object_ref (suggested_plugin);
                     port_probe_ctx->current = g_list_find (port_probe_ctx->current,
                                                            port_probe_ctx->suggested_plugin);
                 } else {
-                    mm_dbg ("(%s/%s) deferred task cancelled, no suggested plugin",
-                            g_udev_device_get_subsystem (port_probe_ctx->port),
+                    mm_dbg ("(Plugin Manager) [%s] deferred task cancelled, no suggested plugin",
                             g_udev_device_get_name (port_probe_ctx->port));
                     port_probe_ctx->best_plugin = NULL;
                     port_probe_ctx->current = NULL;
@@ -277,9 +272,8 @@ suggest_port_probe_result (FindDeviceSupportContext *ctx,
                      /* The GENERIC plugin is NEVER suggested to others */
                      !g_str_equal (mm_plugin_get_name (suggested_plugin),
                                    MM_PLUGIN_GENERIC_NAME)) {
-                mm_dbg ("(%s): (%s/%s) suggested plugin for port",
+                mm_dbg ("(Plugin Manager) (%s) [%s] suggested plugin for port",
                         mm_plugin_get_name (suggested_plugin),
-                        g_udev_device_get_subsystem (port_probe_ctx->port),
                         g_udev_device_get_name (port_probe_ctx->port));
                 port_probe_ctx->suggested_plugin = g_object_ref (suggested_plugin);
             }
@@ -299,9 +293,8 @@ plugin_supports_port_ready (MMPlugin *plugin,
     support_result = mm_plugin_supports_port_finish (plugin, result, &error);
 
     if (error) {
-        mm_warn ("(%s): (%s/%s) error when checking support: '%s'",
+        mm_warn ("(Plugin Manager) (%s) [%s] error when checking support: '%s'",
                  mm_plugin_get_name (plugin),
-                 g_udev_device_get_subsystem (port_probe_ctx->port),
                  g_udev_device_get_name (port_probe_ctx->port),
                  error->message);
         g_error_free (error);
@@ -319,9 +312,8 @@ plugin_supports_port_ready (MMPlugin *plugin,
             g_warn_if_reached ();
         }
 
-        mm_dbg ("(%s): (%s/%s) found best plugin for port",
+        mm_dbg ("(Plugin Manager) (%s) [%s] found best plugin for port",
                 mm_plugin_get_name (port_probe_ctx->best_plugin),
-                g_udev_device_get_subsystem (port_probe_ctx->port),
                 g_udev_device_get_name (port_probe_ctx->port));
         port_probe_ctx->current = NULL;
 
@@ -338,8 +330,7 @@ plugin_supports_port_ready (MMPlugin *plugin,
                  * right plugin since it claimed this port's physical modem,
                  * just drop the port.
                  */
-                mm_dbg ("(%s/%s): ignoring port unsupported by physical modem's plugin",
-                        g_udev_device_get_subsystem (port_probe_ctx->port),
+                mm_dbg ("(Plugin Manager) [%s] ignoring port unsupported by physical modem's plugin",
                         g_udev_device_get_name (port_probe_ctx->port));
                 port_probe_ctx->best_plugin = NULL;
                 port_probe_ctx->current = NULL;
@@ -365,17 +356,15 @@ plugin_supports_port_ready (MMPlugin *plugin,
     case MM_PLUGIN_SUPPORTS_PORT_DEFER:
         /* Try with the suggested one after being deferred */
         if (port_probe_ctx->suggested_plugin) {
-            mm_dbg ("(%s): (%s/%s) deferring support check, suggested: %s",
+            mm_dbg ("(Plugin Manager) (%s) [%s] deferring support check, suggested: %s",
                     mm_plugin_get_name (MM_PLUGIN (port_probe_ctx->current->data)),
-                    g_udev_device_get_subsystem (port_probe_ctx->port),
                     g_udev_device_get_name (port_probe_ctx->port),
                     mm_plugin_get_name (MM_PLUGIN (port_probe_ctx->suggested_plugin)));
             port_probe_ctx->current = g_list_find (port_probe_ctx->current,
                                                    port_probe_ctx->suggested_plugin);
         } else {
-            mm_dbg ("(%s): (%s/%s) deferring support check",
+            mm_dbg ("(Plugin Manager) (%s) [%s] deferring support check",
                     mm_plugin_get_name (MM_PLUGIN (port_probe_ctx->current->data)),
-                    g_udev_device_get_subsystem (port_probe_ctx->port),
                     g_udev_device_get_name (port_probe_ctx->port));
         }
 
@@ -390,16 +379,14 @@ plugin_supports_port_ready (MMPlugin *plugin,
         /* If we arrived here and we already have a plugin suggested, use it */
         if (port_probe_ctx->suggested_plugin) {
             if (port_probe_ctx->suggested_plugin == plugin) {
-                mm_dbg ("(%s): (%s/%s) task completed, got suggested plugin",
+                mm_dbg ("(Plugin Manager) (%s) [%s] task completed, got suggested plugin",
                         mm_plugin_get_name (port_probe_ctx->suggested_plugin),
-                        g_udev_device_get_subsystem (port_probe_ctx->port),
                         g_udev_device_get_name (port_probe_ctx->port));
                 port_probe_ctx->best_plugin = g_object_ref (port_probe_ctx->suggested_plugin);
                 port_probe_ctx->current = NULL;
             } else {
-                mm_dbg ("(%s): (%s/%s) re-checking support on deferred task, got suggested plugin",
+                mm_dbg ("(Plugin Manager) (%s) [%s] re-checking support on deferred task, got suggested plugin",
                         mm_plugin_get_name (port_probe_ctx->suggested_plugin),
-                        g_udev_device_get_subsystem (port_probe_ctx->port),
                         g_udev_device_get_name (port_probe_ctx->port));
                 port_probe_ctx->current = g_list_find (port_probe_ctx->current,
                                                        port_probe_ctx->suggested_plugin);
@@ -413,8 +400,7 @@ plugin_supports_port_ready (MMPlugin *plugin,
         /* We are deferred until a suggested plugin is given. If last supports task
          * of a given device is finished without finding a best plugin, this task
          * will get finished reporting unsupported. */
-        mm_dbg ("(%s/%s) deferring support check until result suggested",
-                g_udev_device_get_subsystem (port_probe_ctx->port),
+        mm_dbg ("(Plugin Manager) [%s] deferring support check until result suggested",
                 g_udev_device_get_name (port_probe_ctx->port));
         port_probe_ctx->defer_until_suggested = TRUE;
         return;
@@ -697,12 +683,6 @@ mm_plugin_manager_init (MMPluginManager *manager)
     manager->priv = G_TYPE_INSTANCE_GET_PRIVATE (manager,
                                                  MM_TYPE_PLUGIN_MANAGER,
                                                  MMPluginManagerPrivate);
-
-    /* manager->priv->supports = g_hash_table_new_full ( */
-    /*     g_str_hash, */
-    /*     g_str_equal, */
-    /*     g_free, */
-    /*     (GDestroyNotify)supports_info_list_free); */
 }
 
 static gboolean
@@ -719,13 +699,6 @@ finalize (GObject *object)
 {
     MMPluginManager *self = MM_PLUGIN_MANAGER (object);
 
-	/* /\* The Plugin Manager will only be finalized when all support tasks have */
-    /*  * been finished (as the GSimpleAsyncResult takes a reference to the object. */
-    /*  * Therefore, the hash table of support tasks should always be empty. */
-    /*  *\/ */
-    /* g_assert (g_hash_table_size (self->priv->supports) == 0); */
-    /* g_hash_table_destroy (self->priv->supports); */
-
     /* Cleanup list of plugins */
     g_list_free_full (self->priv->plugins, (GDestroyNotify)g_object_unref);
 
diff --git a/src/mm-plugin.c b/src/mm-plugin.c
index 8db4c049..a6768369 100644
--- a/src/mm-plugin.c
+++ b/src/mm-plugin.c
@@ -35,10 +35,8 @@
 #include "mm-serial-parsers.h"
 #include "mm-marshal.h"
 #include "mm-private-boxed-types.h"
-#include "libqcdm/src/commands.h"
-#include "libqcdm/src/utils.h"
-#include "libqcdm/src/errors.h"
 #include "mm-log.h"
+#include "mm-daemon-enums-types.h"
 
 G_DEFINE_TYPE (MMPlugin, mm_plugin, G_TYPE_OBJECT)
 
@@ -197,8 +195,12 @@ apply_pre_probing_filters (MMPlugin *self,
         }
 
         /* If we didn't match any subsystem: unsupported */
-        if (!self->priv->subsystems[i])
+        if (!self->priv->subsystems[i]) {
+            mm_dbg ("(%s) [%s] filtered by subsystem",
+                    self->priv->name,
+                    g_udev_device_get_name (port));
             return TRUE;
+        }
     }
 
     /* The plugin may specify that only some drivers are supported, or that some
@@ -214,8 +216,12 @@ apply_pre_probing_filters (MMPlugin *self,
                    mm_device_get_drivers (device));
 
         /* If error retrieving driver: unsupported */
-        if (!drivers)
+        if (!drivers) {
+            mm_dbg ("(%s) [%s] filtered as couldn't retrieve drivers",
+                    self->priv->name,
+                    g_udev_device_get_name (port));
             return TRUE;
+        }
 
         /* Filtering by allowed drivers */
         if (self->priv->drivers) {
@@ -231,8 +237,12 @@ apply_pre_probing_filters (MMPlugin *self,
             }
 
             /* If we didn't match any driver: unsupported */
-            if (!found)
+            if (!found) {
+                mm_dbg ("(%s) [%s] filtered by drivers",
+                        self->priv->name,
+                        g_udev_device_get_name (port));
                 return TRUE;
+            }
         }
         /* Filtering by forbidden drivers */
         else {
@@ -241,8 +251,12 @@ apply_pre_probing_filters (MMPlugin *self,
 
                 for (j = 0; drivers[j]; j++) {
                     /* If we match a forbidden driver: unsupported */
-                    if (g_str_equal (drivers[j], self->priv->forbidden_drivers[i]))
+                    if (g_str_equal (drivers[j], self->priv->forbidden_drivers[i])) {
+                        mm_dbg ("(%s) [%s] filtered by forbidden drivers",
+                                self->priv->name,
+                                g_udev_device_get_name (port));
                         return TRUE;
+                    }
                 }
             }
         }
@@ -291,16 +305,26 @@ apply_pre_probing_filters (MMPlugin *self,
     if ((vendor_filtered || product_filtered) &&
         !self->priv->vendor_strings &&
         !self->priv->product_strings &&
-        !self->priv->forbidden_product_strings)
+        !self->priv->forbidden_product_strings) {
+        mm_dbg ("(%s) [%s] filtered by vendor/product IDs",
+                self->priv->name,
+                g_udev_device_get_name (port));
         return TRUE;
+    }
 
     /* The plugin may specify that some product IDs are not supported. If
      * that is the case, filter by forbidden vendor+product ID pair */
-    if (self->priv->forbidden_product_ids && product && vendor)
-        for (i = 0; self->priv->forbidden_product_ids[i].l; i++)
+    if (self->priv->forbidden_product_ids && product && vendor) {
+        for (i = 0; self->priv->forbidden_product_ids[i].l; i++) {
             if (vendor == self->priv->forbidden_product_ids[i].l &&
-                product == self->priv->forbidden_product_ids[i].r)
+                product == self->priv->forbidden_product_ids[i].r) {
+                mm_dbg ("(%s) [%s] filtered by forbidden vendor/product IDs",
+                        self->priv->name,
+                        g_udev_device_get_name (port));
                 return TRUE;
+            }
+        }
+    }
 
     /* If we need to filter by vendor/product strings, need to probe for both.
      * This covers the case where a RS232 modem is connected via a USB<->RS232
@@ -324,8 +348,12 @@ apply_pre_probing_filters (MMPlugin *self,
         }
 
         /* If we didn't match any udev tag: unsupported */
-        if (!self->priv->udev_tags[i])
+        if (!self->priv->udev_tags[i]) {
+            mm_dbg ("(%s) [%s] filtered by udev tags",
+                    self->priv->name,
+                    g_udev_device_get_name (port));
             return TRUE;
+        }
     }
 
     return FALSE;
@@ -367,8 +395,12 @@ apply_post_probing_filters (MMPlugin *self,
         }
 
         if (vendor_filtered) {
-            if (!self->priv->product_strings)
+            if (!self->priv->product_strings) {
+                mm_dbg ("(%s) [%s] filtered by vendor strings",
+                        self->priv->name,
+                        mm_port_probe_get_port_name (probe));
                 return TRUE;
+            }
         } else
             /* Vendor matched */
             return FALSE;
@@ -387,8 +419,12 @@ apply_post_probing_filters (MMPlugin *self,
 
         if (self->priv->product_strings) {
             /* If we didn't get any vendor or product: filtered */
-            if (!vendor || !product)
+            if (!vendor || !product) {
+                mm_dbg ("(%s) [%s] filtered as no vendor/product strings given",
+                        self->priv->name,
+                        mm_port_probe_get_port_name (probe));
                 return TRUE;
+            }
             else {
                 for (i = 0; self->priv->product_strings[i].l; i++) {
                     gboolean found;
@@ -406,8 +442,12 @@ apply_post_probing_filters (MMPlugin *self,
                 }
 
                 /* If we didn't match any product: unsupported */
-                if (!self->priv->product_strings[i].l)
+                if (!self->priv->product_strings[i].l) {
+                    mm_dbg ("(%s) [%s] filtered by vendor/product strings",
+                            self->priv->name,
+                            mm_port_probe_get_port_name (probe));
                     return TRUE;
+                }
             }
         }
 
@@ -423,9 +463,13 @@ apply_post_probing_filters (MMPlugin *self,
                          !!strstr (product, casefolded_product));
                 g_free (casefolded_vendor);
                 g_free (casefolded_product);
-                if (found)
+                if (found) {
                     /* If we match a forbidden product: unsupported */
+                    mm_dbg ("(%s) [%s] filtered by forbidden vendor/product strings",
+                            self->priv->name,
+                            mm_port_probe_get_port_name (probe));
                     return TRUE;
+                }
             }
         }
 
@@ -437,6 +481,9 @@ apply_post_probing_filters (MMPlugin *self,
     if (self->priv->allowed_icera &&
         !mm_port_probe_is_icera (probe)) {
         /* Unsupported! */
+        mm_dbg ("(%s) [%s] filtered as modem is not icera",
+                self->priv->name,
+                mm_port_probe_get_port_name (probe));
         return TRUE;
     }
 
@@ -445,6 +492,9 @@ apply_post_probing_filters (MMPlugin *self,
     if (self->priv->forbidden_icera &&
         mm_port_probe_is_icera (probe)) {
         /* Unsupported! */
+        mm_dbg ("(%s) [%s] filtered as modem is icera",
+                self->priv->name,
+                mm_port_probe_get_port_name (probe));
         return TRUE;
     }
 
@@ -564,6 +614,7 @@ mm_plugin_supports_port (MMPlugin *self,
     gboolean need_vendor_probing;
     gboolean need_product_probing;
     MMPortProbeFlag probe_run_flags;
+    gchar *probe_list_str;
 
     async_result = g_simple_async_result_new (G_OBJECT (self),
                                               callback,
@@ -600,13 +651,11 @@ mm_plugin_supports_port (MMPlugin *self,
         goto out;
     }
 
-    mm_dbg ("(%s) checking port support (%s,%s)",
-            self->priv->name,
-            g_udev_device_get_subsystem (port),
-            g_udev_device_get_name (port));
-
     /* Before launching any probing, check if the port is a net device. */
     if (g_str_equal (g_udev_device_get_subsystem (port), "net")) {
+        mm_dbg ("(%s) [%s] probing deferred until result suggested",
+                self->priv->name,
+                g_udev_device_get_name (port));
         g_simple_async_result_set_op_res_gpointer (
             async_result,
             GUINT_TO_POINTER (MM_PLUGIN_SUPPORTS_PORT_DEFER_UNTIL_SUGGESTED),
@@ -644,10 +693,9 @@ mm_plugin_supports_port (MMPlugin *self,
     if (self->priv->single_at &&
         mm_port_probe_list_has_at_port (mm_device_peek_port_probe_list (device)) &&
         !mm_port_probe_is_at (probe)) {
-        mm_dbg ("(%s)   not setting up AT probing tasks for (%s,%s): "
+        mm_dbg ("(%s) [%s] not setting up AT probing tasks: "
                 "modem already has the expected single AT port",
                 self->priv->name,
-                g_udev_device_get_subsystem (port),
                 g_udev_device_get_name (port));
 
         /* Assuming it won't be an AT port. We still run the probe anyway, in
@@ -663,10 +711,13 @@ mm_plugin_supports_port (MMPlugin *self,
     ctx->flags = probe_run_flags;
 
     /* Launch the probe */
-    mm_dbg ("(%s)   launching probe for (%s,%s)",
+    probe_list_str = mm_port_probe_flag_build_string_from_mask (ctx->flags);
+    mm_dbg ("(%s) [%s] probe required: '%s'",
             self->priv->name,
-            g_udev_device_get_subsystem (port),
-            g_udev_device_get_name (port));
+            g_udev_device_get_name (port),
+            probe_list_str);
+    g_free (probe_list_str);
+
     mm_port_probe_run (probe,
                        ctx->flags,
                        self->priv->send_delay,