[PATCH] log: Don't prefix message with timestamp on --debug if it's a continuation - dev

12 Aug 2024

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 &lt;sbrivio(a)redhat.com&gt;
---
 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 {								\
-- 
2.43.0


    