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
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 <david(a)gibson.dropbear.id.au>
---
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
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 <david(a)gibson.dropbear.id.au>
---
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
On Tue, 6 Aug 2024 16:18:37 +1000 David Gibson <david(a)gibson.dropbear.id.au> 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 <david(a)gibson.dropbear.id.au> --- 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
On Tue, Aug 06, 2024 at 09:08:07PM +0200, Stefano Brivio wrote:On Tue, 6 Aug 2024 16:18:37 +1000 David Gibson <david(a)gibson.dropbear.id.au> wrote:Yes, yes it should.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 <david(a)gibson.dropbear.id.au> --- 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.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
On Wed, 7 Aug 2024 11:06:52 +1000 David Gibson <david(a)gibson.dropbear.id.au> wrote:On Tue, Aug 06, 2024 at 09:08:07PM +0200, Stefano Brivio wrote:Done. Series applied. -- StefanoOn Tue, 6 Aug 2024 16:18:37 +1000 David Gibson <david(a)gibson.dropbear.id.au> wrote:Yes, yes it should.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 <david(a)gibson.dropbear.id.au> --- 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.If you can fix on merge that would be great.
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 <david(a)gibson.dropbear.id.au>
---
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
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 <david(a)gibson.dropbear.id.au>
---
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