On Mon, Aug 12, 2024 at 10:24:58AM +0200, Stefano Brivio wrote:

If we prefix the second part of messages printed through logmsg_perror() by the timestamp, on debug, we'll have two timestamps and a weird separator in the result, such as this beauty:

0.0013: Failed to clone process with detached namespaces0.0013: : Operation not permitted

Add a parameter to logmsg() and vlogmsg() which indicates a message continuation. If that's set, don't print the timestamp in vlogmsg().

Link: https://github.com/moby/moby/issues/48257#issuecomment-2282875092 Signed-off-by: Stefano Brivio

Reviewed-by: David Gibson

--- flow.c | 3 ++- log.c | 14 ++++++++------ log.h | 22 +++++++++++----------- 3 files changed, 21 insertions(+), 18 deletions(-)

diff --git a/flow.c b/flow.c index bd5fa2b..687e9fd 100644 --- a/flow.c +++ b/flow.c @@ -279,7 +279,8 @@ void flow_log_(const struct flow_common *f, int pri, const char *fmt, ...) else type_or_state = FLOW_TYPE(f);

- logmsg(true, pri, "Flow %u (%s): %s", flow_idx(f), type_or_state, msg); + logmsg(true, false, pri, + "Flow %u (%s): %s", flow_idx(f), type_or_state, msg); }

/** diff --git a/log.c b/log.c index 0c377cc..e7202d0 100644 --- a/log.c +++ b/log.c @@ -253,11 +253,12 @@ static void logfile_write(bool newline, int pri, const struct timespec *now, /** * vlogmsg() - Print or send messages to log or output files as configured * @newline: Append newline at the end of the message, if missing + * @cont: Continuation of a previous message, on the same line * @pri: Facility and level map, same as priority for vsyslog() * @format: Message * @ap: Variable argument list */ -void vlogmsg(bool newline, int pri, const char *format, va_list ap) +void vlogmsg(bool newline, bool cont, int pri, const char *format, va_list ap) { bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1; const struct timespec *now; @@ -265,7 +266,7 @@ void vlogmsg(bool newline, int pri, const char *format, va_list ap)

now = logtime(&ts);

- if (debug_print) { + if (debug_print && !cont) { char timestr[LOGTIME_STRLEN];

logtime_fmt(timestr, sizeof(timestr), now); @@ -295,15 +296,16 @@ void vlogmsg(bool newline, int pri, const char *format, va_list ap) /** * logmsg() - vlogmsg() wrapper for variable argument lists * @newline: Append newline at the end of the message, if missing + * @cont: Continuation of a previous message, on the same line * @pri: Facility and level map, same as priority for vsyslog() * @format: Message */ -void logmsg(bool newline, int pri, const char *format, ...) +void logmsg(bool newline, bool cont, int pri, const char *format, ...) { va_list ap;

va_start(ap, format); - vlogmsg(newline, pri, format, ap); + vlogmsg(newline, cont, pri, format, ap); va_end(ap); }

@@ -318,10 +320,10 @@ void logmsg_perror(int pri, const char *format, ...) va_list ap;

va_start(ap, format); - vlogmsg(false, pri, format, ap); + vlogmsg(false, false, pri, format, ap); va_end(ap);

- logmsg(true, pri, ": %s", strerror(errno_copy)); + logmsg(true, true, pri, ": %s", strerror(errno_copy)); }

/** diff --git a/log.h b/log.h index ba17f79..a30b091 100644 --- a/log.h +++ b/log.h @@ -13,21 +13,21 @@ #define LOGFILE_CUT_RATIO 30 /* When full, cut ~30% size */ #define LOGFILE_SIZE_MIN (5UL * MAX(BUFSIZ, PAGE_SIZE))

-void vlogmsg(bool newline, int pri, const char *format, va_list ap); -void logmsg(bool newline, int pri, const char *format, ...) - __attribute__((format(printf, 3, 4))); +void vlogmsg(bool newline, bool cont, int pri, const char *format, va_list ap); +void logmsg(bool newline, bool cont, int pri, const char *format, ...) + __attribute__((format(printf, 4, 5))); void logmsg_perror(int pri, const char *format, ...) __attribute__((format(printf, 2, 3)));

-#define err(...) logmsg(true, LOG_ERR, __VA_ARGS__) -#define warn(...) logmsg(true, LOG_WARNING, __VA_ARGS__) -#define info(...) logmsg(true, LOG_INFO, __VA_ARGS__) -#define debug(...) logmsg(true, LOG_DEBUG, __VA_ARGS__) +#define err(...) logmsg(true, false, LOG_ERR, __VA_ARGS__) +#define warn(...) logmsg(true, false, LOG_WARNING, __VA_ARGS__) +#define info(...) logmsg(true, false, LOG_INFO, __VA_ARGS__) +#define debug(...) logmsg(true, false, LOG_DEBUG, __VA_ARGS__)

-#define err_perror(...) logmsg_perror( LOG_ERR, __VA_ARGS__) -#define warn_perror(...) logmsg_perror( LOG_WARNING, __VA_ARGS__) -#define info_perror(...) logmsg_perror( LOG_INFO, __VA_ARGS__) -#define debug_perror(...) logmsg_perror( LOG_DEBUG, __VA_ARGS__) +#define err_perror(...) logmsg_perror( LOG_ERR, __VA_ARGS__) +#define warn_perror(...) logmsg_perror( LOG_WARNING, __VA_ARGS__) +#define info_perror(...) logmsg_perror( LOG_INFO, __VA_ARGS__) +#define debug_perror(...) logmsg_perror( LOG_DEBUG, __VA_ARGS__)

#define die(...) \ do { \

-- David Gibson (he or they) | I'll have my music baroque, and my code david AT gibson.dropbear.id.au | minimalist, thank you, not the other way | around. http://www.ozlabs.org/~dgibson