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

[David Gibson <david@gibson.dropbear.id.au>]

[-- Attachment #1: Type: text/plain, Size: 5548 bytes --]

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 <sbrivio@redhat.com>

Reviewed-by: David Gibson <david@gibson.dropbear.id.au>

> ---
>  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

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]