plugin-manager: allow new ports up to 1500ms since last port added

Until now we had only a 2500ms timeout initialized since the first
port was exposed until we decided we were ready to consider all ports
notified by the kernel.

With this new logic, we add an additional condition: even if the
2500ms initial timeout has elapsed already, we leave an additional
1500ms since the last port addition for new ports to appear.

This new logic is useful when relying on the ReportKernelEvent() DBus
method, as it is the user the one responsible for reporting the kernel
events instead of udev. Now, the user is not forced to make sure all
ports are exposed in 2500ms; instead, we also allow ports to be
reported in more than 2500ms as long as the time between port
additions reported is less than 1500ms.

Note that this does not mean that the whole probing time will now
always be 4000ms. On well behaved systems (like when based on udev)
this new 'extra' probing timeout may expire long before the 'min'
probing timeout we already had as well.

E.g. in this setup, the reporting of the NET port was done 1100ms
later than the last ttyUSB3, and that was already too late as the
original 2500ms threshold had already expired.

 [1573536994.593874] (tty/ttyUSB0): first port in device /sys/devices/platform/ehci-platform/usb1/1-1
 [1573536994.596659] [plugin manager] task 1: port grabbed: ttyUSB0
 [1573536995.093579] (tty/ttyUSB1): additional port in device /sys/devices/platform/ehci-platform/usb1/1-1
 [1573536995.094172] [plugin manager] task 1: port grabbed: ttyUSB1
 [1573536995.603206] (tty/ttyUSB2): additional port in device /sys/devices/platform/ehci-platform/usb1/1-1
 [1573536995.603822] [plugin manager] task 1: port grabbed: ttyUSB2
 [1573536996.111564] (tty/ttyUSB3): additional port in device /sys/devices/platform/ehci-platform/usb1/1-1
 [1573536996.112257] [plugin manager] task 1: port grabbed: ttyUSB3
 [1573536996.814816] [device /sys/devices/platform/ehci-platform/usb1/1-1] creating modem with plugin 'Quectel' and '4' ports
 [1573536997.265820] (net/wwan0): additional port in device /sys/devices/platform/ehci-platform/usb1/1-1
 [1573536997.296935] (usbmisc/cdc-wdm0): additional port in device /sys/devices/platform/ehci-platform/usb1/1-1

(cherry picked from commit b4dcb76d5a924d0f49850a2115a377cd8ae6ccf5)

1 files changed, 48 insertions, 4 deletions

diff --git a/src/mm-plugin-manager.c b/src/mm-plugin-manager.c
index e4c0356ca..5a2417939 100644
--- a/src/mm-plugin-manager.c
+++ b/src/mm-plugin-manager.c
@@ -681,6 +681,10 @@ port_context_new (MMPluginManager *self,
  * (needs to be > MIN_WAIT_TIME_MSECS!!) */
 #define MIN_PROBING_TIME_MSECS 2500
 
+/* Additional time to wait for other ports to appear after the last port is
+ * exposed in the system. */
+#define EXTRA_PROBING_TIME_MSECS 1500
+
 /* The wait time we define must always be less than the probing time */
 G_STATIC_ASSERT (MIN_WAIT_TIME_MSECS < MIN_PROBING_TIME_MSECS);
 
@@ -720,11 +724,18 @@ struct _DeviceContext {
     /* Port support check contexts waiting to be run after min wait time */
     GList *wait_port_contexts;
 
-    /* Minimum probing_time. The device support check task cannot be finished
-     * before this timeout expires. Once the timeout is expired, the id is reset
-     * to 0. */
+    /* Minimum probing time, which is a timeout initialized as soon as the first
+     * port is added to the device context. The device support check task cannot
+     * be finished before this timeout expires. Once the timeout is expired, the
+     * id is reset to 0. */
     guint min_probing_time_id;
 
+    /* Extra probing time, which is a timeout refreshed every time a new port
+     * is added to the device context. The device support check task cannot be
+     * finished before this timeout expires. Once the timeout is expired, the id
+     * is reset to 0. */
+    guint extra_probing_time_id;
+
     /* Signal connection ids for the grabbed/released signals from the device.
      * These are the signals that will give us notifications of what ports are
      * available (or suddenly unavailable) in the device. */
@@ -745,6 +756,7 @@ device_context_unref (DeviceContext *device_context)
         g_assert (!device_context->released_id);
         g_assert (!device_context->min_wait_time_id);
         g_assert (!device_context->min_probing_time_id);
+        g_assert (!device_context->extra_probing_time_id);
         g_assert (!device_context->port_contexts);
 
         /* The device support check task must have been completed previously */
@@ -816,7 +828,7 @@ device_context_complete (DeviceContext *device_context)
 {
     GTask *task;
 
-    /* If the context is completed before the minimum probing time, we need to wait
+    /* If the context is completed before the 2500ms minimum probing time, we need to wait
      * until that happens, so that we give enough time to udev/hotplug to report the
      * new port additions. */
     if (device_context->min_probing_time_id) {
@@ -825,6 +837,14 @@ device_context_complete (DeviceContext *device_context)
         return;
     }
 
+    /* If the context is completed less than 1500ms before the last port was exposed,
+     * wait some more. */
+    if (device_context->extra_probing_time_id) {
+        mm_dbg ("[plugin manager] task %s: all port probings completed, but not reached extra probing time yet",
+                device_context->name);
+        return;
+    }
+
     /* Steal the task from the context */
     g_assert (device_context->task);
     task = device_context->task;
@@ -1077,6 +1097,18 @@ device_context_min_probing_time_elapsed (DeviceContext *device_context)
     return G_SOURCE_REMOVE;
 }
 
+static gboolean
+device_context_extra_probing_time_elapsed (DeviceContext *device_context)
+{
+    device_context->extra_probing_time_id = 0;
+
+    mm_dbg ("[plugin manager] task %s: extra probing time elapsed", device_context->name);
+
+    /* Wakeup the device context logic */
+    device_context_continue (device_context);
+    return G_SOURCE_REMOVE;
+}
+
 static void
 device_context_run_port_context (DeviceContext *device_context,
                                  PortContext   *port_context)
@@ -1208,6 +1240,13 @@ device_context_port_grabbed (DeviceContext  *device_context,
         return;
     }
 
+    /* Refresh the extra probing timeout. */
+    if (device_context->extra_probing_time_id)
+        g_source_remove (device_context->extra_probing_time_id);
+    device_context->extra_probing_time_id = g_timeout_add (EXTRA_PROBING_TIME_MSECS,
+                                                           (GSourceFunc) device_context_extra_probing_time_elapsed,
+                                                           device_context);
+
     /* Setup a new port context for the newly grabbed port */
     port_context = port_context_new (self,
                                      device_context->name,
@@ -1271,6 +1310,10 @@ device_context_cancel (DeviceContext *device_context)
         g_source_remove (device_context->min_probing_time_id);
         device_context->min_probing_time_id = 0;
     }
+    if (device_context->extra_probing_time_id) {
+        g_source_remove (device_context->extra_probing_time_id);
+        device_context->extra_probing_time_id = 0;
+    }
 
     /* Wakeup the device context logic. If we were still waiting for the
      * min probing time, this will complete the device context. */
@@ -1289,6 +1332,7 @@ device_context_run (MMPluginManager     *self,
     g_assert (!device_context->released_id);
     g_assert (!device_context->min_wait_time_id);
     g_assert (!device_context->min_probing_time_id);
+    g_assert (!device_context->extra_probing_time_id);
 
     /* Connect to device port grabbed/released notifications from the device */
     device_context->grabbed_id = g_signal_connect_swapped (device_context->device,