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(a)redhat.com>Reviewed-by: David Gibson <david(a)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