From aa92f23f0c72d49e970409117d38e38ba60eff35 Mon Sep 17 00:00:00 2001
From: Aleksander Morgado <aleksandermj@chromium.org>
Date: Thu, 25 Aug 2022 15:14:42 +0000
Subject: [PATCH] log: split long messages before sending them to syslog()
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

It is known that syslog() has a size limitation, and long messages
won't make it to the syslog daemon. In order to avoid that, and so
that syslog() calls don´t end up with invalid reads reported by
valgrind, just limit the size of the log lines sent to some sane value
like 512, and make sure the long log entries (e.g. QMI or MBIM message
taces) get split before sending them.

  ModemManager[123834]: <debug> [1661440355.646049] [/dev/cdc-wdm0] received message...
  <<<<<< RAW:
  <<<<<<   length = 173
  <<<<<<   data   = 01:AC:00:80:00:00:01:02:21:00:A1:00...

  ==123834== Invalid read of size 1
  ==123834==    at 0x533EE58: __vsyslog_internal (syslog.c:230)
  ==123834==    by 0x533F299: syslog (syslog.c:90)
  ==123834==    by 0x29CD7D: log_backend_syslog (mm-log.c:167)
  ==123834==    by 0x29D1A7: _mm_log (mm-log.c:265)
  ==123834==    by 0x29D21F: log_handler (mm-log.c:274)
  ==123834==    by 0x5080824: g_logv (gmessages.c:1387)
  ==123834==    by 0x5080AD3: g_log (gmessages.c:1456)
  ==123834==    by 0x4A77D61: trace_message.part.0 (qmi-device.c:1720)
  ==123834==    by 0x4A7969F: trace_message (qmi-device.c:1679)
  ==123834==    by 0x4A7969F: process_message (qmi-device.c:1811)
  ==123834==    by 0x4A7CEE8: qmi_endpoint_parse_buffer (qmi-endpoint.c:106)
  ==123834==    by 0x4A77982: endpoint_new_data_cb (qmi-device.c:1607)
  ==123834==    by 0x4FF5D33: UnknownInlinedFun (gclosure.c:893)
  ==123834==    by 0x4FF5D33: g_signal_emit_valist (gsignal.c:3406)
  ==123834==  Address 0x8a8568f is 1 bytes before a block of size 43 alloc'd
  ==123834==    at 0x4841888: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
  ==123834==    by 0x533EDCC: __vsyslog_internal (syslog.c:206)
  ==123834==    by 0x533F299: syslog (syslog.c:90)
  ==123834==    by 0x29CD7D: log_backend_syslog (mm-log.c:167)
  ==123834==    by 0x29D1A7: _mm_log (mm-log.c:265)
  ==123834==    by 0x29D21F: log_handler (mm-log.c:274)
  ==123834==    by 0x5080824: g_logv (gmessages.c:1387)
  ==123834==    by 0x5080AD3: g_log (gmessages.c:1456)
  ==123834==    by 0x4A77D61: trace_message.part.0 (qmi-device.c:1720)
  ==123834==    by 0x4A7969F: trace_message (qmi-device.c:1679)
  ==123834==    by 0x4A7969F: process_message (qmi-device.c:1811)
  ==123834==    by 0x4A7CEE8: qmi_endpoint_parse_buffer (qmi-endpoint.c:106)
  ==123834==    by 0x4A77982: endpoint_new_data_cb (qmi-device.c:1607)
  ==123834==
  ==123834== Conditional jump or move depends on uninitialised value(s)
  ==123834==    at 0x4847D09: strlen (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
  ==123834==    by 0x529A5C7: __vfprintf_internal (vfprintf-process-arg.c:397)
  ==123834==    by 0x52BA6F9: __vdprintf_internal (iovdprintf.c:54)
  ==123834==    by 0x528DD89: dprintf (dprintf.c:30)
  ==123834==    by 0x533EE82: __vsyslog_internal (syslog.c:230)
  ==123834==    by 0x533F299: syslog (syslog.c:90)
  ==123834==    by 0x29CD7D: log_backend_syslog (mm-log.c:167)
  ==123834==    by 0x29D1A7: _mm_log (mm-log.c:265)
  ==123834==    by 0x29D21F: log_handler (mm-log.c:274)
  ==123834==    by 0x5080824: g_logv (gmessages.c:1387)
  ==123834==    by 0x5080AD3: g_log (gmessages.c:1456)
  ==123834==    by 0x4A77D61: trace_message.part.0 (qmi-device.c:1720)
---
 src/mm-log.c | 32 +++++++++++++++++++++++++++++++-
 1 file changed, 31 insertions(+), 1 deletion(-)

diff --git a/src/mm-log.c b/src/mm-log.c
index e86b61409..68db42fef 100644
--- a/src/mm-log.c
+++ b/src/mm-log.c
@@ -164,7 +164,37 @@ log_backend_syslog (const char *loc,
                     const char *message,
                     size_t      length)
 {
-    syslog (syslog_level, "%s", message);
+    gsize total_printed = 0;
+    guint print_size;
+
+#define MAX_SYSLOG_MSG_LENGTH 512
+    if (length <= MAX_SYSLOG_MSG_LENGTH) {
+        syslog (syslog_level, "%s", message);
+        return;
+    }
+
+    /* print first part with 3 dots at the end */
+    print_size = MAX_SYSLOG_MSG_LENGTH - 3;
+    syslog (syslog_level, "%.*s...", print_size, message);
+    total_printed += print_size;
+
+    while (total_printed < length) {
+        gsize    left;
+        gboolean last;
+
+        left = length - total_printed;
+
+        if (left <= (MAX_SYSLOG_MSG_LENGTH - 3)) {
+            last = TRUE;
+            print_size = (guint) left;
+        } else {
+            last = FALSE;
+            print_size = MAX_SYSLOG_MSG_LENGTH - 6;
+        }
+        syslog (syslog_level, "...%.*s%s", print_size, &message[total_printed], last ? "" : "...");
+        total_printed += print_size;
+    }
+#undef MAX_SYSLOG_MSG_LENGTH
 }
 
 #if defined WITH_SYSTEMD_JOURNAL
-- 
GitLab