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.
2012-10-26 12:44:15 +02:00
parent 28114f66d5
commit 3f255b628a
2 changed files with 94 additions and 70 deletions
--- 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);

--- 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,