diff --git a/src/broker/shutdown.c b/src/broker/shutdown.c index 762720e848c8..a6f2a014f868 100644 --- a/src/broker/shutdown.c +++ b/src/broker/shutdown.c @@ -21,6 +21,7 @@ #include #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) diff --git a/src/common/libflux/flog.c b/src/common/libflux/flog.c index 95a6f91bbbdf..c7f33b13154f 100644 --- a/src/common/libflux/flog.c +++ b/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,21 +174,52 @@ 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. @@ -171,10 +227,12 @@ int flux_vlog (flux_t *h, int level, const char *fmt, va_list ap) if (xtra) flux_log (h, level, "%s", xtra); free (xtra); + free (mbuf); errno = saved_errno; return 0; fatal: free (xtra); + free (mbuf); return -1; } diff --git a/src/common/libflux/flog.h b/src/common/libflux/flog.h index 4399fb8ba2df..6d207e864b42 100644 --- a/src/common/libflux/flog.h +++ b/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. diff --git a/src/common/libflux/test/log.c b/src/common/libflux/test/log.c index 345cecc2ab2b..f546d034efdc 100644 --- a/src/common/libflux/test/log.c +++ b/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(); diff --git a/t/t0009-dmesg.t b/t/t0009-dmesg.t index 1484a19699c8..c140e29e7be9 100755 --- a/t/t0009-dmesg.t +++ b/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