On Thu, Jul 25, 2024 at 06:26:32PM +0200, Stefano Brivio wrote:
> For some reason, in commit 01efc71ddd25 ("log, conf: Add support for
> logging to file"), I added calculations for relative logging
> timestamps using the difference for the seconds part only, not for
> accounting for the fractional part.
> 
> Fix that by storing the initial timestamp, log_start, as a timespec
> struct, and by calculating the difference from the starting time. Do
> this in a macro as we need the same format in a few places.
> 
> To calculate the difference, turn the existing timespec_diff_ms() to
> microseconds, timespec_diff_us(), and rewrite timespec_diff_ms() to
> use that.
> 
> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>

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

> ---
>  log.c  | 42 ++++++++++++++++++++++--------------------
>  util.c | 25 ++++++++++++++++++-------
>  util.h |  1 +
>  3 files changed, 41 insertions(+), 27 deletions(-)
> 
> diff --git a/log.c b/log.c
> index 54483e7..32157a8 100644
> --- a/log.c
> +++ b/log.c
> @@ -40,12 +40,21 @@ static size_t	log_written;		/* Currently used bytes in log file */
>  static size_t	log_cut_size;		/* Bytes to cut at start on rotation */
>  static char	log_header[BUFSIZ];	/* File header, written back on cuts */
>  
> -static time_t	log_start;		/* Start timestamp */
> +static struct timespec log_start;	/* Start timestamp */
>  
>  int		log_trace;		/* --trace mode enabled */
>  bool		log_conf_parsed;	/* Logging options already parsed */
>  bool		log_runtime;		/* Daemonised, or ready in foreground */
>  
> +/**
> + * logtime_fmt_and_arg() - Build format and arguments to print relative log time
> + * @x:		Current timestamp
> + */
> +#define logtime_fmt_and_arg(x)						\
> +	"%lli.%04lli",							\
> +	(timespec_diff_us((x), &log_start) / 1000000LL),		\
> +	(timespec_diff_us((x), &log_start) / 100LL)
> +
>  /**
>   * vlogmsg() - Print or send messages to log or output files as configured
>   * @newline:	Append newline at the end of the message, if missing
> @@ -60,9 +69,8 @@ void vlogmsg(bool newline, int pri, const char *format, va_list ap)
>  
>  	if (debug_print) {
>  		clock_gettime(CLOCK_REALTIME, &tp);
> -		fprintf(stderr, "%lli.%04lli: ",
> -			(long long int)tp.tv_sec - log_start,
> -			(long long int)tp.tv_nsec / (100L * 1000));
> +		fprintf(stderr, logtime_fmt_and_arg(&tp));
> +		fprintf(stderr, ": ");
>  	}
>  
>  	if ((log_mask & LOG_MASK(LOG_PRI(pri))) || !log_conf_parsed) {
> @@ -144,12 +152,9 @@ void trace_init(int enable)
>   */
>  void __openlog(const char *ident, int option, int facility)
>  {
> -	struct timespec tp;
> -
>  	(void)option;
>  
> -	clock_gettime(CLOCK_REALTIME, &tp);
> -	log_start = tp.tv_sec;
> +	clock_gettime(CLOCK_REALTIME, &log_start);
>  
>  	if (log_sock < 0) {
>  		struct sockaddr_un a = { .sun_family = AF_UNIX, };
> @@ -255,10 +260,8 @@ static void logfile_rotate_fallocate(int fd, const struct timespec *now)
>  	if (read(fd, buf, BUFSIZ) == -1)
>  		return;
>  
> -	n = snprintf(buf, BUFSIZ,
> -		     "%s - log truncated at %lli.%04lli", log_header,
> -		     (long long int)(now->tv_sec - log_start),
> -		     (long long int)(now->tv_nsec / (100L * 1000)));
> +	n =  snprintf(buf, BUFSIZ, "%s - log truncated at ", log_header);
> +	n += snprintf(buf + n, BUFSIZ - n, logtime_fmt_and_arg(now));
>  
>  	/* Avoid partial lines by padding the header with spaces */
>  	nl = memchr(buf + n + 1, '\n', BUFSIZ - n - 1);
> @@ -288,10 +291,11 @@ static void logfile_rotate_move(int fd, const struct timespec *now)
>  	char buf[BUFSIZ];
>  	const char *nl;
>  
> -	header_len = snprintf(buf, BUFSIZ,
> -			      "%s - log truncated at %lli.%04lli\n", log_header,
> -			      (long long int)(now->tv_sec - log_start),
> -			      (long long int)(now->tv_nsec / (100L * 1000)));
> +	header_len =  snprintf(buf, BUFSIZ, "%s - log truncated at ",
> +			       log_header);
> +	header_len += snprintf(buf + header_len, BUFSIZ - header_len,
> +			       logtime_fmt_and_arg(now));
> +
>  	if (lseek(fd, 0, SEEK_SET) == -1)
>  		return;
>  	if (write(fd, buf, header_len) == -1)
> @@ -383,10 +387,8 @@ void logfile_write(bool newline, int pri, const char *format, va_list ap)
>  	if (clock_gettime(CLOCK_REALTIME, &now))
>  		return;
>  
> -	n = snprintf(buf, BUFSIZ, "%lli.%04lli: %s",
> -		     (long long int)(now.tv_sec - log_start),
> -		     (long long int)(now.tv_nsec / (100L * 1000)),
> -		     logfile_prefix[pri]);
> +	n  = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(&now));
> +	n += snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]);
>  
>  	n += vsnprintf(buf + n, BUFSIZ - n, format, ap);
>  
> diff --git a/util.c b/util.c
> index c275b14..f2e26a7 100644
> --- a/util.c
> +++ b/util.c
> @@ -239,6 +239,23 @@ void sock_probe_mem(struct ctx *c)
>  	close(s);
>  }
>  
> +/**
> + * timespec_diff_us() - Report difference in microseconds between two timestamps
> + * @a:		Minuend timestamp
> + * @b:		Subtrahend timestamp
> + *
> + * Return: difference in microseconds (wraps after 2^64 / 10^6s ~= 585k years)
> + */
> +long long timespec_diff_us(const struct timespec *a, const struct timespec *b)
> +{
> +	if (a->tv_nsec < b->tv_nsec) {
> +		return (b->tv_nsec - a->tv_nsec) / 1000 +
> +		       (a->tv_sec - b->tv_sec - 1) * 1000000;
> +	}
> +
> +	return (a->tv_nsec - b->tv_nsec) / 1000 +
> +	       (a->tv_sec - b->tv_sec) * 1000000;
> +}
>  
>  /**
>   * timespec_diff_ms() - Report difference in milliseconds between two timestamps
> @@ -249,13 +266,7 @@ void sock_probe_mem(struct ctx *c)
>   */
>  long timespec_diff_ms(const struct timespec *a, const struct timespec *b)
>  {
> -	if (a->tv_nsec < b->tv_nsec) {
> -		return (b->tv_nsec - a->tv_nsec) / 1000000 +
> -		       (a->tv_sec - b->tv_sec - 1) * 1000;
> -	}
> -
> -	return (a->tv_nsec - b->tv_nsec) / 1000000 +
> -	       (a->tv_sec - b->tv_sec) * 1000;
> +	return timespec_diff_us(a, b) / 1000;
>  }
>  
>  /**
> diff --git a/util.h b/util.h
> index 826614c..6f44eab 100644
> --- a/util.h
> +++ b/util.h
> @@ -152,6 +152,7 @@ int sock_l4(const struct ctx *c, sa_family_t af, enum epoll_type type,
>  	    uint32_t data);
>  void sock_probe_mem(struct ctx *c);
>  long timespec_diff_ms(const struct timespec *a, const struct timespec *b);
> +long long timespec_diff_us(const struct timespec *a, const struct timespec *b);
>  void bitmap_set(uint8_t *map, unsigned bit);
>  void bitmap_clear(uint8_t *map, unsigned bit);
>  bool bitmap_isset(const uint8_t *map, unsigned bit);

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