Logging reduction changes

[Peter Naulls]

In an effort to reduce the repeated logging and trace issues, I've made some 
local changes for logging in libqmi, ModemManager (and its OpenWrt scripts) and
the qmi driver itself.

I don't necessarily recommend these specific patches, I just want to note them
for further improvement.

In libqmi:

--- a/src/libqmi-glib/qmi-device.c	2021-07-22 11:04:56.971937646 -0400
+++ b/src/libqmi-glib/qmi-device.c	2021-07-22 11:05:14.659980059 -0400
@@ -1324,8 +1324,8 @@
          input = qmi_message_ctl_allocate_cid_input_new ();
          qmi_message_ctl_allocate_cid_input_set_service (input, ctx->service, 
NULL);

-        g_debug ("[%s] Allocating new client ID...",
-                 qmi_file_get_path_display (self->priv->file));
+//        g_debug ("[%s] Allocating new client ID...",
+//                 qmi_file_get_path_display (self->priv->file));
          qmi_client_ctl_allocate_cid (self->priv->client_ctl,
                                       input,
                                       timeout,


This message is not very interesting, since it's immediately followed by another
message indicating the ID that was allocated (or presumably, the failure).


--- a/src/libqmi-glib/qmi-device.c	2021-06-03 12:06:40.442931910 -0400
+++ b/src/libqmi-glib/qmi-device.c	2021-06-03 12:07:05.435047942 -0400
@@ -346,7 +346,7 @@
      /* If the command is not abortable, we'll return the error right away
       * to the user. */
      if (!__qmi_message_is_abortable (tr->message, tr->message_context)) {
-        g_debug ("transaction 0x%x aborted, but message is not abortable", 
transaction_id);
+        //g_debug ("transaction 0x%x aborted, but message is not abortable", 
transaction_id);
          device_release_transaction (self, tr->wait_ctx->key);
          transaction_complete_and_free (tr, NULL, abort_error_take);
          g_error_free (abort_error_take);

I had to suppress this.  In my testing, this would happen every 30 seconds. I 
don't know if it was some side effect or other code we were running or what.
Sure, it's maybe interesting once, but not hundreds of times in a log:


Thu Jun  3 15:53:03 2021 daemon.debug [3678]: transaction 0xb2b aborted, but 
message is not abortable
Thu Jun  3 15:53:33 2021 daemon.debug [3678]: transaction 0xb2c aborted, but 
message is not abortable
Thu Jun  3 15:54:03 2021 daemon.debug [3678]: transaction 0xb2d aborted, but 
message is not abortable
Thu Jun  3 15:54:33 2021 daemon.debug [3678]: transaction 0xb2e aborted, but 
message is not abortable


This following is actually for the xhci driver, and therefore probably belongs 
elsewhere but I think it's worth mentioning for completeness.  It's triggered by
throughput testing with our modem.


--- a/drivers/usb/host/xhci-ring.c	2021-06-22 10:44:01.424458793 -0400
+++ b/drivers/usb/host/xhci-ring.c	2021-06-22 10:52:02.873047701 -0400
@@ -2742,10 +2742,16 @@
  		if ((le32_to_cpu(event->event_cmd.flags) & TRB_TYPE_BITMASK) >=
  		    TRB_TYPE(48))
  			handle_vendor_event(xhci, event);
-		else
-			xhci_warn(xhci, "ERROR unknown event type %d\n",
+		else {
+            static int count = 0;
+
+            if ((count % 100) == 0) {
+                xhci_warn(xhci, "ERROR unknown event type %d (count = %d)\n",
  				  TRB_FIELD_TO_TYPE(
-				  le32_to_cpu(event->event_cmd.flags)));
+				  le32_to_cpu(event->event_cmd.flags)), count);
+            }
+            count++;
+        }
  	}
  	/* Any of the above functions may drop and re-acquire the lock, so check
  	 * to make sure a watchdog timer didn't mark the host as non-responsive.


Obliviously this isn't going to be an acceptable upstream patch, however it
was occurring so often that the logging buffer in the kernel became very
large and the system would run out of memory.  Again, the message is important,
but it doesn't need to be seen very often.

I'm still working on the ModemManager script changes; I'll post those elsewhere
soon.