Merge pull request #6554 from grondo/issue#6545

prevent log message truncation

src/broker/shutdown.c

@@ -21,6 +21,7 @@
 #include <flux/core.h>
 
 #include "src/common/libutil/stdlog.h"
+#include "src/common/libutil/errno_safe.h"
 
 #include "shutdown.h"
 #include "state_machine.h"
@@ -66,30 +67,27 @@ static int forward_logbuf (flux_t *h,
     struct stdlog_header hdr;
     const char *txt;
     size_t txtlen;
-    char buf[FLUX_MAX_LOGBUF];
+    int len = strlen (stdlog);
+    char *buf;
     int loglevel;
+    int rc;
 
     if (flux_msg_unpack (request, "{s:i}", "loglevel", &loglevel) < 0)
         loglevel = LOG_ERR;
 
-    if (stdlog_decode (stdlog,
-                       strlen (stdlog),
-                       &hdr,
-                       NULL,
-                       NULL,
-                       &txt,
-                       &txtlen) < 0
+    if (stdlog_decode (stdlog, len, &hdr, NULL, NULL, &txt, &txtlen) < 0
         || STDLOG_SEVERITY (hdr.pri) > loglevel
-        || snprintf (buf,
-                     sizeof (buf),
+        || asprintf (&buf,
                      "%s.%s[%lu]: %.*s\n",
                      hdr.appname,
                      stdlog_severity_to_string (STDLOG_SEVERITY (hdr.pri)),
                      strtoul (hdr.hostname, NULL, 10),
                      (int)txtlen,
-                     txt) >= sizeof (buf))
+                     txt) < 0)
         return 0;
-    return flux_respond_pack (h, request, "{s:s}", "log", buf);
+    rc = flux_respond_pack (h, request, "{s:s}", "log", buf);
+    ERRNO_SAFE_WRAP (free, buf);
+    return rc;
 }
 
 static void dmesg_continuation (flux_future_t *f, void *arg)

src/common/libflux/flog.c

@@ -24,6 +24,9 @@
 
 #include "src/common/libutil/wallclock.h"
 #include "src/common/libutil/stdlog.h"
+#include "src/common/libutil/errno_safe.h"
+
+#define FLUX_MAX_LOGBUF     2048
 
 typedef struct {
     char appname[STDLOG_MAX_APPNAME + 1];
@@ -111,6 +114,32 @@ static int log_rpc (flux_t *h, const char *buf, size_t len)
     return 0;
 }
 
+static int vlog_stderr (int level, const char *fmt, va_list ap)
+{
+    char buf[FLUX_MAX_LOGBUF];
+    char *result = buf;
+    char *mbuf = NULL;
+    const char *lstr = stdlog_severity_to_string (LOG_PRI (level));
+    int rc;
+    va_list ap_copy;
+
+    /* Copy va_list ap in case it reused on truncation below:
+     */
+    va_copy (ap_copy, ap);
+
+    if (vsnprintf (result, sizeof (buf), fmt, ap) >= sizeof (buf)) {
+        /* Message truncation occurred. Fall back to malloc. If that
+         * fails, just print the truncated message:
+         */
+        if (vasprintf (&mbuf, fmt, ap_copy) == 0)
+            result = mbuf;
+    }
+    rc = fprintf (stderr, "%s: %s\n", lstr, result);
+    va_end (ap_copy);
+    ERRNO_SAFE_WRAP (free, mbuf);
+    return rc < 0 ? -1 : 0;
+}
+
 int flux_vlog (flux_t *h, int level, const char *fmt, va_list ap)
 {
     logctx_t *ctx;
@@ -122,16 +151,12 @@ int flux_vlog (flux_t *h, int level, const char *fmt, va_list ap)
     char hostname[STDLOG_MAX_HOSTNAME + 1];
     struct stdlog_header hdr;
     char *xtra = NULL;
+    char *mbuf = NULL;
+    char *result;
+    va_list ap_copy;
 
-    if (!h) {
-        char buf[FLUX_MAX_LOGBUF];
-        const char *lstr = stdlog_severity_to_string (LOG_PRI (level));
-
-        (void)vsnprintf (buf, sizeof (buf), fmt, ap);
-        if (fprintf (stderr, "%s: %s\n", lstr, buf) < 0)
-            return -1;
-        return 0;
-    }
+    if (!h)
+        return vlog_stderr (level, fmt, ap);
 
     if (!(ctx = getctx (h))) {
         errno = ENOMEM;
@@ -149,32 +174,65 @@ int flux_vlog (flux_t *h, int level, const char *fmt, va_list ap)
     hdr.appname = ctx->appname;
     hdr.procid = ctx->procid;
 
+    /* Copy va_list ap in case it reused on truncation below:
+     */
+    va_copy (ap_copy, ap);
+
     n = stdlog_vencodef (ctx->buf,
                          sizeof (ctx->buf),
                          &hdr,
                          STDLOG_NILVALUE,
                          fmt,
                          ap);
+    result = ctx->buf;
     len = n >= sizeof (ctx->buf) ? sizeof (ctx->buf) : n;
+
+    /* Unlikely: On overflow, try again with a buffer allocated on the heap.
+     * If this fails for any reason, fall back to truncated output.
+     */
+    if (n >= sizeof (ctx->buf)) {
+       if ((mbuf = malloc (n + 1))) {
+            /* Note: `n` returned from stdlog_vencodef() may be > actual
+             * length because if there's truncation then this function cannot
+             * drop trailing \r, \n from the result. Therefore, ignore return
+             * of stdlog_vencodef() here (if malloc(3) succeeds) because it is
+             * known the result will fit in the allocated buffer, but the
+             * expected return value is not known.
+             */
+            (void) stdlog_vencodef (mbuf,
+                                    n + 1,
+                                    &hdr,
+                                    STDLOG_NILVALUE,
+                                    fmt,
+                                    ap_copy);
+            result = mbuf;
+            len = n;
+        }
+    }
+
+    va_end (ap_copy);
+
     /* If log message contains multiple lines, log the first
      * line and save the rest.
      */
-    xtra = stdlog_split_message (ctx->buf, &len, "\r\n");
+    xtra = stdlog_split_message (result, &len, "\r\n");
     if (ctx->cb) {
-        ctx->cb (ctx->buf, len, ctx->cb_arg);
+        ctx->cb (result, len, ctx->cb_arg);
     } else {
-        if (log_rpc (h, ctx->buf, len) < 0)
+        if (log_rpc (h, result, len) < 0)
             goto fatal;
     }
     /* If addition log lines were saved above, log them separately.
      */
     if (xtra)
         flux_log (h, level, "%s", xtra);
     free (xtra);
+    free (mbuf);
     errno = saved_errno;
     return 0;
 fatal:
     free (xtra);
+    free (mbuf);
     return -1;
 }
 

src/common/libflux/flog.h

@@ -20,9 +20,6 @@
 extern "C" {
 #endif
 
-
-#define FLUX_MAX_LOGBUF     2048
-
 typedef void (*flux_log_f)(const char *buf, int len, void *arg);
 
 /* Set log appname for handle instance.

src/common/libflux/test/log.c

@@ -20,6 +20,8 @@
 int main (int argc, char *argv[])
 {
     flux_t *h;
+    char *s;
+    int truncation_size = 3073;
 
     plan (NO_PLAN);
 
@@ -41,6 +43,14 @@ int main (int argc, char *argv[])
     ok (flux_log (NULL, LOG_INFO, "# flux_t=NULL") == 0,
        "flux_log h=NULL works");
 
+    if (!(s = calloc (1, truncation_size)))
+        BAIL_OUT ("Failed to allocate memory for truncation test");
+    memset (s, 'a', truncation_size - 2);
+
+    ok (flux_log (NULL, LOG_INFO, "# %s", s) == 0,
+        "flux_log h=NULL works with long message");
+
+    free (s);
     test_server_stop (h);
     flux_close (h);
     done_testing();

t/t0009-dmesg.t

@@ -171,4 +171,11 @@ test_expect_success 'dmesg with invalid --color option fails' '
 	test_must_fail flux dmesg --color=foo
 '
 
+test_expect_success 'dmesg: long lines are not truncated' '
+	python3 -c "print(\"x\"*3000)" | flux logger --appname=truncate &&
+	result=$(flux dmesg | sed -n "/truncate/s/^.*: //p" | wc -c) &&
+	test_debug "echo logged 3001 characters, got $result" &&
+	test $result -eq 3001
+'
+
 test_done