[PATCH 0/2] Avoid duplicated clock_gettime() in logging

[PATCH 0/2] Avoid duplicated clock_gettime() in logging

[David Gibson]

Remove a small nit in the logging code.

David Gibson (2):
  log: Make logfile_write() private
  log: Avoid duplicate calls to clock_gettime()

 log.c | 344 +++++++++++++++++++++++++++++-----------------------------
 log.h |   1 -
 2 files changed, 172 insertions(+), 173 deletions(-)

-- 
2.45.2

[PATCH 1/2] log: Make logfile_write() private

[David Gibson]

logfile_write() is not used outside log.c, nor should it be.  It should
only be used externall via the general logging functions.  Make it static
in log.c.  To avoid forward declarations this requires moving a bunch of
functions earlier in the file.

Signed-off-by: David Gibson <david@gibson.dropbear.id.au>
---
 log.c | 341 +++++++++++++++++++++++++++++-----------------------------
 log.h |   1 -
 2 files changed, 171 insertions(+), 171 deletions(-)

diff --git a/log.c b/log.c
index 0fb25b77..eb3a780a 100644
--- a/log.c
+++ b/log.c
@@ -55,6 +55,177 @@ bool		log_runtime;		/* Daemonised, or ready in foreground */
 	(timespec_diff_us((x), &log_start) / 1000000LL),		\
 	(timespec_diff_us((x), &log_start) / 100LL)
 
+/* Prefixes for log file messages, indexed by priority */
+const char *logfile_prefix[] = {
+	NULL, NULL, NULL,	/* Unused: LOG_EMERG, LOG_ALERT, LOG_CRIT */
+	"ERROR:   ",
+	"WARNING: ",
+	NULL,			/* Unused: LOG_NOTICE */
+	"info:    ",
+	"         ",		/* LOG_DEBUG */
+};
+
+#ifdef FALLOC_FL_COLLAPSE_RANGE
+/**
+ * logfile_rotate_fallocate() - Write header, set log_written after fallocate()
+ * @fd:		Log file descriptor
+ * @now:	Current timestamp
+ *
+ * #syscalls lseek ppc64le:_llseek ppc64:_llseek arm:_llseek
+ */
+static void logfile_rotate_fallocate(int fd, const struct timespec *now)
+{
+	char buf[BUFSIZ];
+	const char *nl;
+	int n;
+
+	if (lseek(fd, 0, SEEK_SET) == -1)
+		return;
+	if (read(fd, buf, BUFSIZ) == -1)
+		return;
+
+	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);
+	if (nl)
+		memset(buf + n, ' ', nl - (buf + n));
+
+	if (lseek(fd, 0, SEEK_SET) == -1)
+		return;
+	if (write(fd, buf, BUFSIZ) == -1)
+		return;
+
+	log_written -= log_cut_size;
+}
+#endif /* FALLOC_FL_COLLAPSE_RANGE */
+
+/**
+ * logfile_rotate_move() - Fallback: move recent entries toward start, then cut
+ * @fd:		Log file descriptor
+ * @now:	Current timestamp
+ *
+ * #syscalls lseek ppc64le:_llseek ppc64:_llseek arm:_llseek
+ * #syscalls ftruncate
+ */
+static void logfile_rotate_move(int fd, const struct timespec *now)
+{
+	int header_len, write_offset, end, discard, n;
+	char buf[BUFSIZ];
+	const char *nl;
+
+	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)
+		return;
+
+	end = write_offset = header_len;
+	discard = log_cut_size + header_len;
+
+	/* Try to cut cleanly at newline */
+	if (lseek(fd, discard, SEEK_SET) == -1)
+		goto out;
+	if ((n = read(fd, buf, BUFSIZ)) <= 0)
+		goto out;
+	if ((nl = memchr(buf, '\n', n)))
+		discard += (nl - buf) + 1;
+
+	/* Go to first block to be moved */
+	if (lseek(fd, discard, SEEK_SET) == -1)
+		goto out;
+
+	while ((n = read(fd, buf, BUFSIZ)) > 0) {
+		end = header_len;
+
+		if (lseek(fd, write_offset, SEEK_SET) == -1)
+			goto out;
+		if ((n = write(fd, buf, n)) == -1)
+			goto out;
+		write_offset += n;
+
+		if ((n = lseek(fd, 0, SEEK_CUR)) == -1)
+			goto out;
+
+		if (lseek(fd, discard - header_len, SEEK_CUR) == -1)
+			goto out;
+
+		end = n;
+	}
+
+out:
+	if (ftruncate(fd, end))
+		return;
+
+	log_written = end;
+}
+
+/**
+ * logfile_rotate() - "Rotate" log file once it's full
+ * @fd:		Log file descriptor
+ * @now:	Current timestamp
+ *
+ * Return: 0 on success, negative error code on failure
+ *
+ * #syscalls fcntl
+ *
+ * fallocate() passed as EXTRA_SYSCALL only if FALLOC_FL_COLLAPSE_RANGE is there
+ */
+static int logfile_rotate(int fd, const struct timespec *now)
+{
+	if (fcntl(fd, F_SETFL, O_RDWR /* Drop O_APPEND: explicit lseek() */))
+		return -errno;
+
+#ifdef FALLOC_FL_COLLAPSE_RANGE
+	/* Only for Linux >= 3.15, extent-based ext4 or XFS, glibc >= 2.18 */
+	if (!fallocate(fd, FALLOC_FL_COLLAPSE_RANGE, 0, log_cut_size))
+		logfile_rotate_fallocate(fd, now);
+	else
+#endif
+		logfile_rotate_move(fd, now);
+
+	if (fcntl(fd, F_SETFL, O_RDWR | O_APPEND))
+		return -errno;
+
+	return 0;
+}
+
+/**
+ * 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()
+ * @format:	Same as vsyslog() format
+ * @ap:		Same as vsyslog() ap
+ */
+static void logfile_write(bool newline, int pri, const char *format, va_list ap)
+{
+	struct timespec now;
+	char buf[BUFSIZ];
+	int n;
+
+	if (clock_gettime(CLOCK_MONOTONIC, &now))
+		return;
+
+	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);
+
+	if (newline && format[strlen(format)] != '\n')
+		n += snprintf(buf + n, BUFSIZ - n, "\n");
+
+	if ((log_written + n >= log_size) && logfile_rotate(log_file, &now))
+		return;
+
+	if ((n = write(log_file, buf, n)) >= 0)
+		log_written += n;
+}
+
 /**
  * vlogmsg() - Print or send messages to log or output files as configured
  * @newline:	Append newline at the end of the message, if missing
@@ -125,16 +296,6 @@ void logmsg_perror(int pri, const char *format, ...)
 	logmsg(true, pri, ": %s", strerror(errno_copy));
 }
 
-/* Prefixes for log file messages, indexed by priority */
-const char *logfile_prefix[] = {
-	NULL, NULL, NULL,	/* Unused: LOG_EMERG, LOG_ALERT, LOG_CRIT */
-	"ERROR:   ",
-	"WARNING: ",
-	NULL,			/* Unused: LOG_NOTICE */
-	"info:    ",
-	"         ",		/* LOG_DEBUG */
-};
-
 /**
  * trace_init() - Set log_trace depending on trace (debug) mode
  * @enable:	Tracing debug mode enabled if non-zero
@@ -239,163 +400,3 @@ void logfile_init(const char *name, const char *path, size_t size)
 	log_cut_size = ROUND_UP(log_size * LOGFILE_CUT_RATIO / 100, PAGE_SIZE);
 }
 
-#ifdef FALLOC_FL_COLLAPSE_RANGE
-/**
- * logfile_rotate_fallocate() - Write header, set log_written after fallocate()
- * @fd:		Log file descriptor
- * @now:	Current timestamp
- *
- * #syscalls lseek ppc64le:_llseek ppc64:_llseek arm:_llseek
- */
-static void logfile_rotate_fallocate(int fd, const struct timespec *now)
-{
-	char buf[BUFSIZ];
-	const char *nl;
-	int n;
-
-	if (lseek(fd, 0, SEEK_SET) == -1)
-		return;
-	if (read(fd, buf, BUFSIZ) == -1)
-		return;
-
-	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);
-	if (nl)
-		memset(buf + n, ' ', nl - (buf + n));
-
-	if (lseek(fd, 0, SEEK_SET) == -1)
-		return;
-	if (write(fd, buf, BUFSIZ) == -1)
-		return;
-
-	log_written -= log_cut_size;
-}
-#endif /* FALLOC_FL_COLLAPSE_RANGE */
-
-/**
- * logfile_rotate_move() - Fallback: move recent entries toward start, then cut
- * @fd:		Log file descriptor
- * @now:	Current timestamp
- *
- * #syscalls lseek ppc64le:_llseek ppc64:_llseek arm:_llseek
- * #syscalls ftruncate
- */
-static void logfile_rotate_move(int fd, const struct timespec *now)
-{
-	int header_len, write_offset, end, discard, n;
-	char buf[BUFSIZ];
-	const char *nl;
-
-	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)
-		return;
-
-	end = write_offset = header_len;
-	discard = log_cut_size + header_len;
-
-	/* Try to cut cleanly at newline */
-	if (lseek(fd, discard, SEEK_SET) == -1)
-		goto out;
-	if ((n = read(fd, buf, BUFSIZ)) <= 0)
-		goto out;
-	if ((nl = memchr(buf, '\n', n)))
-		discard += (nl - buf) + 1;
-
-	/* Go to first block to be moved */
-	if (lseek(fd, discard, SEEK_SET) == -1)
-		goto out;
-
-	while ((n = read(fd, buf, BUFSIZ)) > 0) {
-		end = header_len;
-
-		if (lseek(fd, write_offset, SEEK_SET) == -1)
-			goto out;
-		if ((n = write(fd, buf, n)) == -1)
-			goto out;
-		write_offset += n;
-
-		if ((n = lseek(fd, 0, SEEK_CUR)) == -1)
-			goto out;
-
-		if (lseek(fd, discard - header_len, SEEK_CUR) == -1)
-			goto out;
-
-		end = n;
-	}
-
-out:
-	if (ftruncate(fd, end))
-		return;
-
-	log_written = end;
-}
-
-/**
- * logfile_rotate() - "Rotate" log file once it's full
- * @fd:		Log file descriptor
- * @now:	Current timestamp
- *
- * Return: 0 on success, negative error code on failure
- *
- * #syscalls fcntl
- *
- * fallocate() passed as EXTRA_SYSCALL only if FALLOC_FL_COLLAPSE_RANGE is there
- */
-static int logfile_rotate(int fd, const struct timespec *now)
-{
-	if (fcntl(fd, F_SETFL, O_RDWR /* Drop O_APPEND: explicit lseek() */))
-		return -errno;
-
-#ifdef FALLOC_FL_COLLAPSE_RANGE
-	/* Only for Linux >= 3.15, extent-based ext4 or XFS, glibc >= 2.18 */
-	if (!fallocate(fd, FALLOC_FL_COLLAPSE_RANGE, 0, log_cut_size))
-		logfile_rotate_fallocate(fd, now);
-	else
-#endif
-		logfile_rotate_move(fd, now);
-
-	if (fcntl(fd, F_SETFL, O_RDWR | O_APPEND))
-		return -errno;
-
-	return 0;
-}
-
-/**
- * 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()
- * @format:	Same as vsyslog() format
- * @ap:		Same as vsyslog() ap
- */
-void logfile_write(bool newline, int pri, const char *format, va_list ap)
-{
-	struct timespec now;
-	char buf[BUFSIZ];
-	int n;
-
-	if (clock_gettime(CLOCK_MONOTONIC, &now))
-		return;
-
-	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);
-
-	if (newline && format[strlen(format)] != '\n')
-		n += snprintf(buf + n, BUFSIZ - n, "\n");
-
-	if ((log_written + n >= log_size) && logfile_rotate(log_file, &now))
-		return;
-
-	if ((n = write(log_file, buf, n)) >= 0)
-		log_written += n;
-}
diff --git a/log.h b/log.h
index e03199c6..5cb16d6f 100644
--- a/log.h
+++ b/log.h
@@ -56,7 +56,6 @@ void trace_init(int enable);
 void __openlog(const char *ident, int option, int facility);
 void logfile_init(const char *name, const char *path, size_t size);
 void passt_vsyslog(bool newline, int pri, const char *format, va_list ap);
-void logfile_write(bool newline, int pri, const char *format, va_list ap);
 void __setlogmask(int mask);
 
 #endif /* LOG_H */
-- 
@@ -56,7 +56,6 @@ void trace_init(int enable);
 void __openlog(const char *ident, int option, int facility);
 void logfile_init(const char *name, const char *path, size_t size);
 void passt_vsyslog(bool newline, int pri, const char *format, va_list ap);
-void logfile_write(bool newline, int pri, const char *format, va_list ap);
 void __setlogmask(int mask);
 
 #endif /* LOG_H */
-- 
2.45.2

[PATCH 2/2] log: Avoid duplicate calls to clock_gettime()

[David Gibson]

We use clock_gettime() 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.

Refactor to have a single clock_gettime() call in vlogmsg() and use it for
all the places we need it.

Signed-off-by: David Gibson <david@gibson.dropbear.id.au>
---
 log.c | 17 ++++++++---------
 1 file changed, 8 insertions(+), 9 deletions(-)

diff --git a/log.c b/log.c
index eb3a780a..418bdefd 100644
--- a/log.c
+++ b/log.c
@@ -199,19 +199,17 @@ 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()
+ * @tp:		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 *tp,
+			  const char *format, va_list ap)
 {
-	struct timespec now;
 	char buf[BUFSIZ];
 	int n;
 
-	if (clock_gettime(CLOCK_MONOTONIC, &now))
-		return;
-
-	n  = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(&now));
+	n  = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(tp));
 	n += snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]);
 
 	n += vsnprintf(buf + n, BUFSIZ - n, format, ap);
@@ -219,7 +217,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, tp))
 		return;
 
 	if ((n = write(log_file, buf, n)) >= 0)
@@ -238,8 +236,9 @@ 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;
 
+	clock_gettime(CLOCK_MONOTONIC, &tp);
+
 	if (debug_print) {
-		clock_gettime(CLOCK_MONOTONIC, &tp);
 		fprintf(stderr, logtime_fmt_and_arg(&tp));
 		fprintf(stderr, ": ");
 	}
@@ -249,7 +248,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, &tp, format, ap2);
 		else if (!(log_mask & LOG_MASK(LOG_DEBUG)))
 			passt_vsyslog(newline, pri, format, ap2);
 
-- 
@@ -199,19 +199,17 @@ 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()
+ * @tp:		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 *tp,
+			  const char *format, va_list ap)
 {
-	struct timespec now;
 	char buf[BUFSIZ];
 	int n;
 
-	if (clock_gettime(CLOCK_MONOTONIC, &now))
-		return;
-
-	n  = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(&now));
+	n  = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(tp));
 	n += snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]);
 
 	n += vsnprintf(buf + n, BUFSIZ - n, format, ap);
@@ -219,7 +217,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, tp))
 		return;
 
 	if ((n = write(log_file, buf, n)) >= 0)
@@ -238,8 +236,9 @@ 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;
 
+	clock_gettime(CLOCK_MONOTONIC, &tp);
+
 	if (debug_print) {
-		clock_gettime(CLOCK_MONOTONIC, &tp);
 		fprintf(stderr, logtime_fmt_and_arg(&tp));
 		fprintf(stderr, ": ");
 	}
@@ -249,7 +248,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, &tp, format, ap2);
 		else if (!(log_mask & LOG_MASK(LOG_DEBUG)))
 			passt_vsyslog(newline, pri, format, ap2);
 
-- 
2.45.2

Re: [PATCH 2/2] log: Avoid duplicate calls to clock_gettime()

[Stefano Brivio]

On Mon, 29 Jul 2024 14:23:00 +1000
David Gibson <david@gibson.dropbear.id.au> wrote:

> We use clock_gettime() 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.
> 
> Refactor to have a single clock_gettime() call in vlogmsg() and use it for
> all the places we need it.
> 
> Signed-off-by: David Gibson <david@gibson.dropbear.id.au>
> ---
>  log.c | 17 ++++++++---------
>  1 file changed, 8 insertions(+), 9 deletions(-)
> 
> diff --git a/log.c b/log.c
> index eb3a780a..418bdefd 100644
> --- a/log.c
> +++ b/log.c
> @@ -199,19 +199,17 @@ 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()
> + * @tp:		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 *tp,
> +			  const char *format, va_list ap)
>  {
> -	struct timespec now;
>  	char buf[BUFSIZ];
>  	int n;
>  
> -	if (clock_gettime(CLOCK_MONOTONIC, &now))
> -		return;
> -
> -	n  = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(&now));
> +	n  = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(tp));
>  	n += snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]);
>  
>  	n += vsnprintf(buf + n, BUFSIZ - n, format, ap);
> @@ -219,7 +217,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, tp))
>  		return;
>  
>  	if ((n = write(log_file, buf, n)) >= 0)
> @@ -238,8 +236,9 @@ 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;
>  
> +	clock_gettime(CLOCK_MONOTONIC, &tp);

Maybe it's more readable now, but this has two disadvantages:

1. this way, we call clock_gettime() also when it's not needed (that's
   what I meant by "a bit of refactoring in vlogmsg()").

   If we log to the system logger, which is the default, we'll fetch a
   timestamp for no reason, because the system logger adds it.

   It's not that bad as we're not verbose in that case, so I'm actually
   fine with this patch, but I wanted to point that out to you anyway,
   first.

2. POSIX.1-2024 has only one error defined for clock_gettime():

    The clock_gettime() function shall fail if:

    [EOVERFLOW]
        The number of seconds will not fit in an object of type time_t. 

   which should only happen on quite old systems (assuming their C
   library even knows about clock_gettime()) in 2038 (assuming
   CLOCK_REALTIME is used as initial CLOCK_MONOTONIC), but still, C
   libraries often decide to add errors on their own, and we would
   print stack contents if that happens.

   Before this patch, that could only happen with --debug. Perhaps we
   should simply initialise struct timespec to all zeroes (better to
   print with the wrong timestamp than not printing at all) or to
   log_start.

> +
>  	if (debug_print) {
> -		clock_gettime(CLOCK_MONOTONIC, &tp);
>  		fprintf(stderr, logtime_fmt_and_arg(&tp));
>  		fprintf(stderr, ": ");
>  	}
> @@ -249,7 +248,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, &tp, format, ap2);
>  		else if (!(log_mask & LOG_MASK(LOG_DEBUG)))
>  			passt_vsyslog(newline, pri, format, ap2);
>  

-- 
Stefano

Re: [PATCH 2/2] log: Avoid duplicate calls to clock_gettime()

[David Gibson]

[-- Attachment #1: Type: text/plain, Size: 4856 bytes --]

On Mon, Jul 29, 2024 at 07:55:02PM +0200, Stefano Brivio wrote:
> On Mon, 29 Jul 2024 14:23:00 +1000
> David Gibson <david@gibson.dropbear.id.au> wrote:
> 
> > We use clock_gettime() 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.
> > 
> > Refactor to have a single clock_gettime() call in vlogmsg() and use it for
> > all the places we need it.
> > 
> > Signed-off-by: David Gibson <david@gibson.dropbear.id.au>
> > ---
> >  log.c | 17 ++++++++---------
> >  1 file changed, 8 insertions(+), 9 deletions(-)
> > 
> > diff --git a/log.c b/log.c
> > index eb3a780a..418bdefd 100644
> > --- a/log.c
> > +++ b/log.c
> > @@ -199,19 +199,17 @@ 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()
> > + * @tp:		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 *tp,
> > +			  const char *format, va_list ap)
> >  {
> > -	struct timespec now;
> >  	char buf[BUFSIZ];
> >  	int n;
> >  
> > -	if (clock_gettime(CLOCK_MONOTONIC, &now))
> > -		return;
> > -
> > -	n  = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(&now));
> > +	n  = snprintf(buf, BUFSIZ, logtime_fmt_and_arg(tp));
> >  	n += snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]);
> >  
> >  	n += vsnprintf(buf + n, BUFSIZ - n, format, ap);
> > @@ -219,7 +217,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, tp))
> >  		return;
> >  
> >  	if ((n = write(log_file, buf, n)) >= 0)
> > @@ -238,8 +236,9 @@ 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;
> >  
> > +	clock_gettime(CLOCK_MONOTONIC, &tp);
> 
> Maybe it's more readable now, but this has two disadvantages:
> 
> 1. this way, we call clock_gettime() also when it's not needed (that's
>    what I meant by "a bit of refactoring in vlogmsg()").
> 
>    If we log to the system logger, which is the default, we'll fetch a
>    timestamp for no reason, because the system logger adds it.

Ah, true.  Although I believe clock_gettime() is a vdso call which
should be very cheap.

>    It's not that bad as we're not verbose in that case, so I'm actually
>    fine with this patch, but I wanted to point that out to you anyway,
>    first.
> 
> 2. POSIX.1-2024 has only one error defined for clock_gettime():
> 
>     The clock_gettime() function shall fail if:
> 
>     [EOVERFLOW]
>         The number of seconds will not fit in an object of type time_t. 
> 
>    which should only happen on quite old systems (assuming their C
>    library even knows about clock_gettime()) in 2038 (assuming
>    CLOCK_REALTIME is used as initial CLOCK_MONOTONIC), but still, C
>    libraries often decide to add errors on their own, and we would
>    print stack contents if that happens.
> 
>    Before this patch, that could only happen with --debug. Perhaps we
>    should simply initialise struct timespec to all zeroes (better to
>    print with the wrong timestamp than not printing at all) or to
>    log_start.

Hm, true.

> 
> > +
> >  	if (debug_print) {
> > -		clock_gettime(CLOCK_MONOTONIC, &tp);
> >  		fprintf(stderr, logtime_fmt_and_arg(&tp));
> >  		fprintf(stderr, ": ");
> >  	}
> > @@ -249,7 +248,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, &tp, format, ap2);
> >  		else if (!(log_mask & LOG_MASK(LOG_DEBUG)))
> >  			passt_vsyslog(newline, pri, format, ap2);
> >  
> 

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

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: [PATCH 1/2] log: Make logfile_write() private

[Stefano Brivio]

On Mon, 29 Jul 2024 14:22:59 +1000
David Gibson <david@gibson.dropbear.id.au> wrote:

> logfile_write() is not used outside log.c, nor should it be.  It should
> only be used externall via the general logging functions.  Make it static
> in log.c.  To avoid forward declarations this requires moving a bunch of
> functions earlier in the file.
> 
> Signed-off-by: David Gibson <david@gibson.dropbear.id.au>

Applied (1/2 only, for the moment).

-- 
Stefano