aboutgitcodebugslistschat
diff options
context:
space:
mode:
authorStefano Brivio <sbrivio@redhat.com>2024-07-24 17:21:12 +0200
committerStefano Brivio <sbrivio@redhat.com>2024-07-26 13:43:19 +0200
commit327d9d482fd4480ca16e993fe2699c8bbc166251 (patch)
treedbfb4ddf7b70c8a490c999621aab225d67b8076b
parent2ce1d3783184ecc637d8e9be997a42e1c78a908e (diff)
downloadpasst-327d9d482fd4480ca16e993fe2699c8bbc166251.tar
passt-327d9d482fd4480ca16e993fe2699c8bbc166251.tar.gz
passt-327d9d482fd4480ca16e993fe2699c8bbc166251.tar.bz2
passt-327d9d482fd4480ca16e993fe2699c8bbc166251.tar.lz
passt-327d9d482fd4480ca16e993fe2699c8bbc166251.tar.xz
passt-327d9d482fd4480ca16e993fe2699c8bbc166251.tar.zst
passt-327d9d482fd4480ca16e993fe2699c8bbc166251.zip
log, util: Fix sub-second part in relative log time calculation
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>
-rw-r--r--log.c42
-rw-r--r--util.c25
-rw-r--r--util.h1
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,13 +40,22 @@ 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
* @pri: Facility and level map, same as priority for vsyslog()
@@ -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);