[PATCH v2 0/4] Fix several small errors in log time handling

newer
[PATCH] conf, pasta: Make -g and...

David Gibson

6 Aug 2024 6 Aug '24

8:18 a.m.

While working on the deduplication of clock_gettime() in the logging code, I noticed a few other minor issues. Changes since v1: * Dropped merged change making logfile_write() static * Handle errors from clock_gettime() * Added fixes for some additional problems I noticed David Gibson (4): util: Some corrections for timespec_diff_us log: Correct formatting of timestamps log: Handle errors from clock_gettime() log: Avoid duplicate calls to logtime() log.c | 70 ++++++++++++++++++++++++++++++++++++++++------------------ util.c | 4 ++-- util.h | 2 +- 3 files changed, 52 insertions(+), 24 deletions(-) -- 2.45.2

Show replies by date

David Gibson

6 Aug 6 Aug

8:18 a.m.

New subject: [PATCH v2 1/4] util: Some corrections for timespec_diff_us

The comment for timespec_diff_us() claims it will wrap after 2^64µs. This is incorrect for two reasons: * It returns a long long, which is probably 64-bits, but might not be * It returns a signed value, so even if it is 64 bits it will wrap after 2^63µs Correct the comment and use an explicitly 64-bit type to avoid that imprecision. Signed-off-by: David Gibson --- util.c | 4 ++-- util.h | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/util.c b/util.c index f2e26a7a..0cc908a5 100644 --- a/util.c +++ b/util.c @@ -244,9 +244,9 @@ void sock_probe_mem(struct ctx *c) * @a: Minuend timestamp * @b: Subtrahend timestamp * - * Return: difference in microseconds (wraps after 2^64 / 10^6s ~= 585k years) + * Return: difference in microseconds (wraps after 2^63 / 10^6s ~= 292k years) */ -long long timespec_diff_us(const struct timespec *a, const struct timespec *b) +int64_t 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 + diff --git a/util.h b/util.h index b7541ce2..d0fec7b3 100644 --- a/util.h +++ b/util.h @@ -168,7 +168,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); +int64_t 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); -- 2.45.2

David Gibson

8:18 a.m.

New subject: [PATCH v2 2/4] log: Correct formatting of timestamps

logtime_fmt_and_arg() is a rather odd macro, producing both a format string and an argument, which can only be used in quite specific printf() like formulations. It also has a significant bug: it tries to display 4 digits after the decimal point (so down to tenths of milliseconds) using %04i. But the field width in printf() is always a *minimum* not maximum field width, so this will not truncate the given value, but will redisplay the entire tenth-of-milliseconds difference again after the decimal point. Replace the macro with an snprintf() like function which will format the timestamp, and use an explicit % to correct the display. Signed-off-by: David Gibson --- log.c | 36 ++++++++++++++++++++++++------------ 1 file changed, 24 insertions(+), 12 deletions(-) diff --git a/log.c b/log.c index eb3a780a..e60852f7 100644 --- a/log.c +++ b/log.c @@ -46,14 +46,24 @@ int log_trace; /* --trace mode enabled */ bool log_conf_parsed; /* Logging options already parsed */ bool log_runtime; /* Daemonised, or ready in foreground */ +#define LL_STRLEN (sizeof("-9223372036854775808")) +#define LOGTIME_STRLEN (LL_STRLEN + 5) + /** - * logtime_fmt_and_arg() - Build format and arguments to print relative log time - * @x: Current timestamp + * logtime_fmt() - Format timestamp into a string for the log + * @buf: Buffer into which to format the time + * @size: Size of @buf + * @ts: Time to format + * + * Return: number of characters written to @buf (excluding \0) */ -#define logtime_fmt_and_arg(x) \ - "%lli.%04lli", \ - (timespec_diff_us((x), &log_start) / 1000000LL), \ - (timespec_diff_us((x), &log_start) / 100LL) +int logtime_fmt(char *buf, size_t size, const struct timespec *ts) +{ + int64_t delta = timespec_diff_us(ts, &log_start); + + return snprintf(buf, size, "%lli.%04lli", delta / 1000000LL, + (delta / 100LL) % 10000); +} /* Prefixes for log file messages, indexed by priority */ const char *logfile_prefix[] = { @@ -85,7 +95,7 @@ static void logfile_rotate_fallocate(int fd, const struct timespec *now) return; n = snprintf(buf, BUFSIZ, "%s - log truncated at ", log_header); - n += snprintf(buf + n, BUFSIZ - n, logtime_fmt_and_arg(now)); + n += logtime_fmt(buf + n, BUFSIZ - n, now); /* Avoid partial lines by padding the header with spaces */ nl = memchr(buf + n + 1, '\n', BUFSIZ - n - 1); @@ -117,8 +127,7 @@ static void logfile_rotate_move(int fd, const struct timespec *now) 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)); + header_len += logtime_fmt(buf + header_len, BUFSIZ - header_len, now); if (lseek(fd, 0, SEEK_SET) == -1) return; @@ -211,7 +220,7 @@ static void logfile_write(bool newline, int pri, const char *format, va_list ap) if (clock_gettime(CLOCK_MONOTONIC, &now)) return; - n = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(&now)); + n = logtime_fmt(buf, BUFSIZ, &now); n += snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]); n += vsnprintf(buf + n, BUFSIZ - n, format, ap); @@ -239,9 +248,12 @@ void vlogmsg(bool newline, int pri, const char *format, va_list ap) struct timespec tp; if (debug_print) { + char logtime[LOGTIME_STRLEN]; + clock_gettime(CLOCK_MONOTONIC, &tp); - fprintf(stderr, logtime_fmt_and_arg(&tp)); - fprintf(stderr, ": "); + + logtime_fmt(logtime, sizeof(logtime), &tp); + fprintf(stderr, "%s: ", logtime); } if ((log_mask & LOG_MASK(LOG_PRI(pri))) || !log_conf_parsed) { -- 2.45.2

Stefano Brivio

9:08 p.m.

New subject: [PATCH v2 2/4] log: Correct formatting of timestamps

On Tue, 6 Aug 2024 16:18:37 +1000 David Gibson wrote:

...

logtime_fmt_and_arg() is a rather odd macro, producing both a format string and an argument, which can only be used in quite specific printf() like formulations. It also has a significant bug: it tries to display 4 digits after the decimal point (so down to tenths of milliseconds) using %04i. But the field width in printf() is always a *minimum* not maximum field width, so this will not truncate the given value, but will redisplay the entire tenth-of-milliseconds difference again after the decimal point.

Weird, not for me (glibc 2.38). But anyway, yes, it's much better this way, and definitely, it's specified as minimum width (I never noticed). Just one nit:

...

Replace the macro with an snprintf() like function which will format the timestamp, and use an explicit % to correct the display.

Signed-off-by: David Gibson --- log.c | 36 ++++++++++++++++++++++++------------ 1 file changed, 24 insertions(+), 12 deletions(-)

diff --git a/log.c b/log.c index eb3a780a..e60852f7 100644 --- a/log.c +++ b/log.c @@ -46,14 +46,24 @@ int log_trace; /* --trace mode enabled */ bool log_conf_parsed; /* Logging options already parsed */ bool log_runtime; /* Daemonised, or ready in foreground */

+#define LL_STRLEN (sizeof("-9223372036854775808")) +#define LOGTIME_STRLEN (LL_STRLEN + 5) + /** - * logtime_fmt_and_arg() - Build format and arguments to print relative log time - * @x: Current timestamp + * logtime_fmt() - Format timestamp into a string for the log + * @buf: Buffer into which to format the time + * @size: Size of @buf + * @ts: Time to format + * + * Return: number of characters written to @buf (excluding \0) */ -#define logtime_fmt_and_arg(x) \ - "%lli.%04lli", \ - (timespec_diff_us((x), &log_start) / 1000000LL), \ - (timespec_diff_us((x), &log_start) / 100LL) +int logtime_fmt(char *buf, size_t size, const struct timespec *ts)

Shouldn't this be static? The rest of the series looks good to me, so I can also fix this up on merge, as you prefer. -- Stefano

David Gibson

7 Aug 7 Aug

3:06 a.m.

New subject: [PATCH v2 2/4] log: Correct formatting of timestamps

On Tue, Aug 06, 2024 at 09:08:07PM +0200, Stefano Brivio wrote:

...

On Tue, 6 Aug 2024 16:18:37 +1000 David Gibson wrote:

...
logtime_fmt_and_arg() is a rather odd macro, producing both a format string and an argument, which can only be used in quite specific printf() like formulations. It also has a significant bug: it tries to display 4 digits after the decimal point (so down to tenths of milliseconds) using %04i. But the field width in printf() is always a *minimum* not maximum field width, so this will not truncate the given value, but will redisplay the entire tenth-of-milliseconds difference again after the decimal point.

Weird, not for me (glibc 2.38). But anyway, yes, it's much better this way, and definitely, it's specified as minimum width (I never noticed).

Just one nit:

...
Replace the macro with an snprintf() like function which will format the timestamp, and use an explicit % to correct the display.

Signed-off-by: David Gibson --- log.c | 36 ++++++++++++++++++++++++------------ 1 file changed, 24 insertions(+), 12 deletions(-)

diff --git a/log.c b/log.c index eb3a780a..e60852f7 100644 --- a/log.c +++ b/log.c @@ -46,14 +46,24 @@ int log_trace; /* --trace mode enabled */ bool log_conf_parsed; /* Logging options already parsed */ bool log_runtime; /* Daemonised, or ready in foreground */

+#define LL_STRLEN (sizeof("-9223372036854775808")) +#define LOGTIME_STRLEN (LL_STRLEN + 5) + /** - * logtime_fmt_and_arg() - Build format and arguments to print relative log time - * @x: Current timestamp + * logtime_fmt() - Format timestamp into a string for the log + * @buf: Buffer into which to format the time + * @size: Size of @buf + * @ts: Time to format + * + * Return: number of characters written to @buf (excluding \0) */ -#define logtime_fmt_and_arg(x) \ - "%lli.%04lli", \ - (timespec_diff_us((x), &log_start) / 1000000LL), \ - (timespec_diff_us((x), &log_start) / 100LL) +int logtime_fmt(char *buf, size_t size, const struct timespec *ts)

Shouldn't this be static?

Yes, yes it should.

...

The rest of the series looks good to me, so I can also fix this up on merge, as you prefer.

If you can fix on merge that would be great. -- 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

Stefano Brivio

10:17 a.m.

New subject: [PATCH v2 2/4] log: Correct formatting of timestamps

On Wed, 7 Aug 2024 11:06:52 +1000 David Gibson wrote:

...

On Tue, Aug 06, 2024 at 09:08:07PM +0200, Stefano Brivio wrote:

...
On Tue, 6 Aug 2024 16:18:37 +1000 David Gibson wrote:

...
logtime_fmt_and_arg() is a rather odd macro, producing both a format string and an argument, which can only be used in quite specific printf() like formulations. It also has a significant bug: it tries to display 4 digits after the decimal point (so down to tenths of milliseconds) using %04i. But the field width in printf() is always a *minimum* not maximum field width, so this will not truncate the given value, but will redisplay the entire tenth-of-milliseconds difference again after the decimal point.

Weird, not for me (glibc 2.38). But anyway, yes, it's much better this way, and definitely, it's specified as minimum width (I never noticed).

Just one nit:

...
Replace the macro with an snprintf() like function which will format the timestamp, and use an explicit % to correct the display.

Signed-off-by: David Gibson --- log.c | 36 ++++++++++++++++++++++++------------ 1 file changed, 24 insertions(+), 12 deletions(-)

diff --git a/log.c b/log.c index eb3a780a..e60852f7 100644 --- a/log.c +++ b/log.c @@ -46,14 +46,24 @@ int log_trace; /* --trace mode enabled */ bool log_conf_parsed; /* Logging options already parsed */ bool log_runtime; /* Daemonised, or ready in foreground */

+#define LL_STRLEN (sizeof("-9223372036854775808")) +#define LOGTIME_STRLEN (LL_STRLEN + 5) + /** - * logtime_fmt_and_arg() - Build format and arguments to print relative log time - * @x: Current timestamp + * logtime_fmt() - Format timestamp into a string for the log + * @buf: Buffer into which to format the time + * @size: Size of @buf + * @ts: Time to format + * + * Return: number of characters written to @buf (excluding \0) */ -#define logtime_fmt_and_arg(x) \ - "%lli.%04lli", \ - (timespec_diff_us((x), &log_start) / 1000000LL), \ - (timespec_diff_us((x), &log_start) / 100LL) +int logtime_fmt(char *buf, size_t size, const struct timespec *ts)

Shouldn't this be static?

Yes, yes it should.

...
The rest of the series looks good to me, so I can also fix this up on merge, as you prefer.

If you can fix on merge that would be great.

Done. Series applied. -- Stefano

David Gibson

6 Aug 6 Aug

8:18 a.m.

New subject: [PATCH v2 3/4] log: Handle errors from clock_gettime()

clock_gettime() can, theoretically, fail, although it probably won't until 2038 on old 32-bit systems. Still, it's possible someone could run with a wildly out of sync clock, or new errors could be added, or it could fail due to a bug in libc or the kernel. We don't handle this well. In the debug_print case in vlogmsg we'll just ignore the failure, and print a timestamp based on uninitialised garbage. In logfile_write() we exit early and won't log anything at all, which seems like a good way to make an already weird situation undebuggable. Add some helpers to instead handle this by using "<error>" in place of a timestamp if something goes wrong with clock_gettime(). Signed-off-by: David Gibson --- log.c | 47 ++++++++++++++++++++++++++++++++--------------- 1 file changed, 32 insertions(+), 15 deletions(-) diff --git a/log.c b/log.c index e60852f7..9f4cb7fc 100644 --- a/log.c +++ b/log.c @@ -49,20 +49,37 @@ bool log_runtime; /* Daemonised, or ready in foreground */ #define LL_STRLEN (sizeof("-9223372036854775808")) #define LOGTIME_STRLEN (LL_STRLEN + 5) +/** + * logtime() - Get the current time for logging purposes + * @ts: Buffer into which to store the timestamp + * + * Return: pointer to @now, or NULL if there was an error retrieving the time + */ +const struct timespec *logtime(struct timespec *ts) +{ + if (clock_gettime(CLOCK_MONOTONIC, ts)) + return NULL; + return ts; +} + /** * logtime_fmt() - Format timestamp into a string for the log * @buf: Buffer into which to format the time * @size: Size of @buf - * @ts: Time to format + * @ts: Time to format (or NULL on error) * * Return: number of characters written to @buf (excluding \0) */ int logtime_fmt(char *buf, size_t size, const struct timespec *ts) { - int64_t delta = timespec_diff_us(ts, &log_start); + if (ts) { + int64_t delta = timespec_diff_us(ts, &log_start); + + return snprintf(buf, size, "%lli.%04lli", delta / 1000000LL, + (delta / 100LL) % 10000); + } - return snprintf(buf, size, "%lli.%04lli", delta / 1000000LL, - (delta / 100LL) % 10000); + return snprintf(buf, size, "<error>"); } /* Prefixes for log file messages, indexed by priority */ @@ -213,14 +230,14 @@ static int logfile_rotate(int fd, const struct timespec *now) */ static void logfile_write(bool newline, int pri, const char *format, va_list ap) { - struct timespec now; + const struct timespec *now; + struct timespec ts; char buf[BUFSIZ]; int n; - if (clock_gettime(CLOCK_MONOTONIC, &now)) - return; + now = logtime(&ts); - n = logtime_fmt(buf, BUFSIZ, &now); + n = logtime_fmt(buf, BUFSIZ, now); n += snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]); n += vsnprintf(buf + n, BUFSIZ - n, format, ap); @@ -228,7 +245,7 @@ static void logfile_write(bool newline, int pri, const char *format, va_list ap) if (newline && format[strlen(format)] != '\n') n += snprintf(buf + n, BUFSIZ - n, "\n"); - if ((log_written + n >= log_size) && logfile_rotate(log_file, &now)) + if ((log_written + n >= log_size) && logfile_rotate(log_file, now)) return; if ((n = write(log_file, buf, n)) >= 0) @@ -245,15 +262,15 @@ static void logfile_write(bool newline, int pri, const char *format, va_list ap) void vlogmsg(bool newline, int pri, const char *format, va_list ap) { bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1; - struct timespec tp; if (debug_print) { - char logtime[LOGTIME_STRLEN]; - - clock_gettime(CLOCK_MONOTONIC, &tp); + char timestr[LOGTIME_STRLEN]; + const struct timespec *now; + struct timespec ts; - logtime_fmt(logtime, sizeof(logtime), &tp); - fprintf(stderr, "%s: ", logtime); + now = logtime(&ts); + logtime_fmt(timestr, sizeof(timestr), now); + fprintf(stderr, "%s: ", timestr); } if ((log_mask & LOG_MASK(LOG_PRI(pri))) || !log_conf_parsed) { -- 2.45.2

David Gibson

8:18 a.m.

New subject: [PATCH v2 4/4] log: Avoid duplicate calls to logtime()

We use logtime() to get a timestamp for the log in two places: - in vlogmsg(), which is used only for debug_print messages - in logfile_write() which is only used messages to the log file These cases are mutually exclusive, so we don't ever print the same message with different timestamps, but that's not particularly obvious to see. It's possible future tweaks to logging logic could mean we log to two different places with different timestamps, which would be confusing. Refactor to have a single logtime() call in vlogmsg() and use it for all the places we need it. Signed-off-by: David Gibson --- log.c | 17 ++++++++--------- 1 file changed, 8 insertions(+), 9 deletions(-) diff --git a/log.c b/log.c index 9f4cb7fc..f3799224 100644 --- a/log.c +++ b/log.c @@ -225,18 +225,16 @@ static int logfile_rotate(int fd, const struct timespec *now) * logfile_write() - Write entry to log file, trigger rotation if full * @newline: Append newline at the end of the message, if missing * @pri: Facility and level map, same as priority for vsyslog() + * @now: Timestamp * @format: Same as vsyslog() format * @ap: Same as vsyslog() ap */ -static void logfile_write(bool newline, int pri, const char *format, va_list ap) +static void logfile_write(bool newline, int pri, const struct timespec *now, + const char *format, va_list ap) { - const struct timespec *now; - struct timespec ts; char buf[BUFSIZ]; int n; - now = logtime(&ts); - n = logtime_fmt(buf, BUFSIZ, now); n += snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]); @@ -262,13 +260,14 @@ static void logfile_write(bool newline, int pri, const char *format, va_list ap) void vlogmsg(bool newline, int pri, const char *format, va_list ap) { bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1; + const struct timespec *now; + struct timespec ts; + + now = logtime(&ts); if (debug_print) { char timestr[LOGTIME_STRLEN]; - const struct timespec *now; - struct timespec ts; - now = logtime(&ts); logtime_fmt(timestr, sizeof(timestr), now); fprintf(stderr, "%s: ", timestr); } @@ -278,7 +277,7 @@ void vlogmsg(bool newline, int pri, const char *format, va_list ap) va_copy(ap2, ap); /* Don't clobber ap, we need it again */ if (log_file != -1) - logfile_write(newline, pri, format, ap2); + logfile_write(newline, pri, now, format, ap2); else if (!(log_mask & LOG_MASK(LOG_DEBUG))) passt_vsyslog(newline, pri, format, ap2); -- 2.45.2

301

Age (days ago)

302

Last active (days ago)

List overview

Download

7 comments

2 participants

participants (2)

David Gibson
Stefano Brivio

[PATCH v2 0/4] Fix several small errors in log time handling

tags

participants (2)