[PATCH v2 0/3] Some improvements to log functions

[PATCH v2 0/3] Some improvements to log functions

[David Gibson]

Several small improvements to the logging functions.

Changes since v1:
 * Added printf warning attributes
 * Added vlogmsg()

David Gibson (3):
  log: Don't define logging function 4 times
  log: Enable format warnings
  log: Add vlogmsg()

 Makefile |  3 ++-
 conf.c   |  2 +-
 log.c    | 72 +++++++++++++++++++++++++++++---------------------------
 log.h    | 14 +++++++----
 packet.c |  7 +++---
 pasta.c  |  2 +-
 tcp.c    | 13 ++++++----
 7 files changed, 63 insertions(+), 50 deletions(-)

-- 
2.41.0

[PATCH v2 1/3] log: Don't define logging function 4 times

[David Gibson]

In log.c we use a macro to define logging functions for each of 4 priority
levels.  The only difference between these is the priority we pass to
vsyslog() and similar functions.  Because it's done as a macro, however,
the entire functions code is included in the binary 4 times.

Rearrange this to take the priority level as a parameter to a regular
function, then just use macros to define trivial wrappers which pass the
priority level.

This saves about 600 bytes of text in the executable (x86, non-AVX2).

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

diff --git a/log.c b/log.c
index c57bc8d..fd33f64 100644
--- a/log.c
+++ b/log.c
@@ -47,36 +47,36 @@ int		log_to_stdout;		/* Print to stdout instead of stderr */
 
 #define BEFORE_DAEMON		(setlogmask(0) == LOG_MASK(LOG_EMERG))
 
-#define logfn(name, level)						\
-void name(const char *format, ...) {					\
-	FILE *out = log_to_stdout ? stdout : stderr;			\
-	struct timespec tp;						\
-	va_list args;							\
-									\
-	if (setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file == -1) {	\
-		clock_gettime(CLOCK_REALTIME, &tp);			\
-		fprintf(out, "%lli.%04lli: ",				\
-			(long long int)tp.tv_sec - log_start,		\
-			(long long int)tp.tv_nsec / (100L * 1000));	\
-	}								\
-									\
-	if ((LOG_MASK(LOG_PRI(level)) & log_mask) || BEFORE_DAEMON) {	\
-		va_start(args, format);					\
-		if (log_file != -1)					\
-			logfile_write(level, format, args);		\
-		else if (!(setlogmask(0) & LOG_MASK(LOG_DEBUG)))	\
-			passt_vsyslog(level, format, args);		\
-		va_end(args);						\
-	}								\
-									\
-	if ((setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file == -1) ||	\
-	    (BEFORE_DAEMON && !(log_opt & LOG_PERROR))) {		\
-		va_start(args, format);					\
-		(void)vfprintf(out, format, args); 			\
-		va_end(args);						\
-		if (format[strlen(format)] != '\n')			\
-			fprintf(out, "\n");				\
-	}								\
+void logmsg(int pri, const char *format, ...)
+{
+	FILE *out = log_to_stdout ? stdout : stderr;
+	struct timespec tp;
+	va_list args;
+
+	if (setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file == -1) {
+		clock_gettime(CLOCK_REALTIME, &tp);
+		fprintf(out, "%lli.%04lli: ",
+			(long long int)tp.tv_sec - log_start,
+			(long long int)tp.tv_nsec / (100L * 1000));
+	}
+
+	if ((LOG_MASK(LOG_PRI(pri)) & log_mask) || BEFORE_DAEMON) {
+		va_start(args, format);
+		if (log_file != -1)
+			logfile_write(pri, format, args);
+		else if (!(setlogmask(0) & LOG_MASK(LOG_DEBUG)))
+			passt_vsyslog(pri, format, args);
+		va_end(args);
+	}
+
+	if ((setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file == -1) ||
+	    (BEFORE_DAEMON && !(log_opt & LOG_PERROR))) {
+		va_start(args, format);
+		(void)vfprintf(out, format, args);
+		va_end(args);
+		if (format[strlen(format)] != '\n')
+			fprintf(out, "\n");
+	}
 }
 
 /* Prefixes for log file messages, indexed by priority */
@@ -89,11 +89,6 @@ const char *logfile_prefix[] = {
 	"         ",		/* LOG_DEBUG */
 };
 
-logfn(err,  LOG_ERR)
-logfn(warn, LOG_WARNING)
-logfn(info, LOG_INFO)
-logfn(debug,LOG_DEBUG)
-
 /**
  * trace_init() - Set log_trace depending on trace (debug) mode
  * @enable:	Tracing debug mode enabled if non-zero
diff --git a/log.h b/log.h
index a17171a..b4fb7e9 100644
--- a/log.h
+++ b/log.h
@@ -6,14 +6,18 @@
 #ifndef LOG_H
 #define LOG_H
 
+#include <syslog.h>
+
 #define LOGFILE_SIZE_DEFAULT		(1024 * 1024UL)
 #define LOGFILE_CUT_RATIO		30	/* When full, cut ~30% size */
 #define LOGFILE_SIZE_MIN		(5UL * MAX(BUFSIZ, PAGE_SIZE))
 
-void err(const char *format, ...);
-void warn(const char *format, ...);
-void info(const char *format, ...);
-void debug(const char *format, ...);
+void logmsg(int pri, const char *format, ...);
+
+#define err(...)	logmsg(LOG_ERR, __VA_ARGS__)
+#define warn(...)	logmsg(LOG_WARNING, __VA_ARGS__)
+#define info(...)	logmsg(LOG_INFO, __VA_ARGS__)
+#define debug(...)	logmsg(LOG_DEBUG, __VA_ARGS__)
 
 #define die(...)							\
 	do {								\
-- 
@@ -6,14 +6,18 @@
 #ifndef LOG_H
 #define LOG_H
 
+#include <syslog.h>
+
 #define LOGFILE_SIZE_DEFAULT		(1024 * 1024UL)
 #define LOGFILE_CUT_RATIO		30	/* When full, cut ~30% size */
 #define LOGFILE_SIZE_MIN		(5UL * MAX(BUFSIZ, PAGE_SIZE))
 
-void err(const char *format, ...);
-void warn(const char *format, ...);
-void info(const char *format, ...);
-void debug(const char *format, ...);
+void logmsg(int pri, const char *format, ...);
+
+#define err(...)	logmsg(LOG_ERR, __VA_ARGS__)
+#define warn(...)	logmsg(LOG_WARNING, __VA_ARGS__)
+#define info(...)	logmsg(LOG_INFO, __VA_ARGS__)
+#define debug(...)	logmsg(LOG_DEBUG, __VA_ARGS__)
 
 #define die(...)							\
 	do {								\
-- 
2.41.0

[PATCH v2 2/3] log: Enable format warnings

[David Gibson]

logmsg() takes printf like arguments, but because it's not a built in, the
compiler won't generate warnings if the format string and parameters don't
match.  Enable those by using the format attribute.

Strictly speaking this is a gcc extension, but I believe it is also
supported by some other common compilers.  We already use some other
attributes in various places.  For now, just use it and we can worry about
compilers that don't support it if it comes up.

This exposes some warnings from existing callers, both in gcc and in
clang-tidy:
 - Some are straight out bugs, which we correct
 - It's occasionally useful to invoke the logging functions with an empty
   string, which gcc objects to, so disable that specific warning in the
   Makefile
 - Strictly speaking the C standard requires that the parameter for a %p
   be a (void *), not some other pointer type.  That's only likely to cause
   problems in practice on weird architectures with different sized
   representations for pointers to different types.  Nonetheless add the
   casts to make it happy.

Signed-off-by: David Gibson <david@gibson.dropbear.id.au>
---
 Makefile |  3 ++-
 conf.c   |  2 +-
 log.h    |  3 ++-
 packet.c |  7 ++++---
 pasta.c  |  2 +-
 tcp.c    | 13 ++++++++-----
 6 files changed, 18 insertions(+), 12 deletions(-)

diff --git a/Makefile b/Makefile
index 941086a..dd28e50 100644
--- a/Makefile
+++ b/Makefile
@@ -33,7 +33,8 @@ AUDIT_ARCH := $(shell echo $(AUDIT_ARCH) | sed 's/MIPS64EL/MIPSEL64/')
 AUDIT_ARCH := $(shell echo $(AUDIT_ARCH) | sed 's/HPPA/PARISC/')
 AUDIT_ARCH := $(shell echo $(AUDIT_ARCH) | sed 's/SH4/SH/')
 
-FLAGS := -Wall -Wextra -pedantic -std=c11 -D_XOPEN_SOURCE=700 -D_GNU_SOURCE
+FLAGS := -Wall -Wextra -Wno-format-zero-length
+FLAGS += -pedantic -std=c11 -D_XOPEN_SOURCE=700 -D_GNU_SOURCE
 FLAGS += -D_FORTIFY_SOURCE=2 -O2 -pie -fPIE
 FLAGS += -DPAGE_SIZE=$(shell getconf PAGE_SIZE)
 FLAGS += -DNETNS_RUN_DIR=\"/run/netns\"
diff --git a/conf.c b/conf.c
index a235b31..b8ebb4e 100644
--- a/conf.c
+++ b/conf.c
@@ -559,7 +559,7 @@ static void conf_netns_opt(char *netns, const char *arg)
 	}
 
 	if (ret <= 0 || ret > PATH_MAX)
-		die("Network namespace name/path %s too long");
+		die("Network namespace name/path %s too long", arg);
 }
 
 /**
diff --git a/log.h b/log.h
index b4fb7e9..df72f9a 100644
--- a/log.h
+++ b/log.h
@@ -12,7 +12,8 @@
 #define LOGFILE_CUT_RATIO		30	/* When full, cut ~30% size */
 #define LOGFILE_SIZE_MIN		(5UL * MAX(BUFSIZ, PAGE_SIZE))
 
-void logmsg(int pri, const char *format, ...);
+void logmsg(int pri, const char *format, ...)
+	__attribute__((format(printf, 2, 3)));
 
 #define err(...)	logmsg(LOG_ERR, __VA_ARGS__)
 #define warn(...)	logmsg(LOG_WARNING, __VA_ARGS__)
diff --git a/packet.c b/packet.c
index 693e034..9589824 100644
--- a/packet.c
+++ b/packet.c
@@ -43,13 +43,14 @@ void packet_add_do(struct pool *p, size_t len, const char *start,
 
 	if (start < p->buf) {
 		trace("add packet start %p before buffer start %p, %s:%i",
-		      start, p->buf, func, line);
+		      (void *)start, (void *)p->buf, func, line);
 		return;
 	}
 
 	if (start + len > p->buf + p->buf_size) {
 		trace("add packet start %p, length: %lu, buffer end %p, %s:%i",
-		      start, len, p->buf + p->buf_size, func, line);
+		      (void *)start, len, (void *)(p->buf + p->buf_size),
+		      func, line);
 		return;
 	}
 
@@ -61,7 +62,7 @@ void packet_add_do(struct pool *p, size_t len, const char *start,
 #if UINTPTR_MAX == UINT64_MAX
 	if ((uintptr_t)start - (uintptr_t)p->buf > UINT32_MAX) {
 		trace("add packet start %p, buffer start %p, %s:%i",
-		      start, p->buf, func, line);
+		      (void *)start, (void *)p->buf, func, line);
 		return;
 	}
 #endif
diff --git a/pasta.c b/pasta.c
index 5fd44fe..94807a3 100644
--- a/pasta.c
+++ b/pasta.c
@@ -239,7 +239,7 @@ void pasta_start_ns(struct ctx *c, uid_t uid, gid_t gid,
 
 		if ((size_t)snprintf(sh_arg0, sizeof(sh_arg0),
 				     "-%s", arg.exe) >= sizeof(sh_arg0))
-			die("$SHELL is too long (%u bytes)", strlen(arg.exe));
+			die("$SHELL is too long (%zu bytes)", strlen(arg.exe));
 
 		sh_argv[0] = sh_arg0;
 		arg.argv = sh_argv;
diff --git a/tcp.c b/tcp.c
index 945023c..8e3d822 100644
--- a/tcp.c
+++ b/tcp.c
@@ -1215,7 +1215,8 @@ static void tcp_hash_insert(const struct ctx *c, struct tcp_tap_conn *conn)
 	tc_hash[b] = conn;
 
 	debug("TCP: hash table insert: index %li, sock %i, bucket: %i, next: "
-	      "%p", CONN_IDX(conn), conn->sock, b, conn_at_idx(conn->next_index));
+	      "%p", CONN_IDX(conn), conn->sock, b,
+	      (void *)conn_at_idx(conn->next_index));
 }
 
 /**
@@ -1242,7 +1243,7 @@ static void tcp_hash_remove(const struct ctx *c,
 
 	debug("TCP: hash table remove: index %li, sock %i, bucket: %i, new: %p",
 	      CONN_IDX(conn), conn->sock, b,
-	      prev ? conn_at_idx(prev->next_index) : tc_hash[b]);
+	      (void *)(prev ? conn_at_idx(prev->next_index) : tc_hash[b]));
 }
 
 /**
@@ -1270,7 +1271,8 @@ static void tcp_tap_conn_update(const struct ctx *c, struct tcp_tap_conn *old,
 
 	debug("TCP: hash table update: old index %li, new index %li, sock %i, "
 	      "bucket: %i, old: %p, new: %p",
-	      CONN_IDX(old), CONN_IDX(new), new->sock, b, old, new);
+	      CONN_IDX(old), CONN_IDX(new), new->sock, b,
+	      (void *)old, (void *)new);
 
 	tcp_epoll_ctl(c, new);
 }
@@ -1314,7 +1316,7 @@ void tcp_table_compact(struct ctx *c, union tcp_conn *hole)
 
 	if (CONN_IDX(hole) == --c->tcp.conn_count) {
 		debug("TCP: table compaction: maximum index was %li (%p)",
-		      CONN_IDX(hole), hole);
+		      CONN_IDX(hole), (void *)hole);
 		memset(hole, 0, sizeof(*hole));
 		return;
 	}
@@ -1329,7 +1331,8 @@ void tcp_table_compact(struct ctx *c, union tcp_conn *hole)
 
 	debug("TCP: table compaction (spliced=%d): old index %li, new index %li, "
 	      "from: %p, to: %p",
-	      from->c.spliced, CONN_IDX(from), CONN_IDX(hole), from, hole);
+	      from->c.spliced, CONN_IDX(from), CONN_IDX(hole),
+	      (void *)from, (void *)hole);
 
 	memset(from, 0, sizeof(*from));
 }
-- 
@@ -1215,7 +1215,8 @@ static void tcp_hash_insert(const struct ctx *c, struct tcp_tap_conn *conn)
 	tc_hash[b] = conn;
 
 	debug("TCP: hash table insert: index %li, sock %i, bucket: %i, next: "
-	      "%p", CONN_IDX(conn), conn->sock, b, conn_at_idx(conn->next_index));
+	      "%p", CONN_IDX(conn), conn->sock, b,
+	      (void *)conn_at_idx(conn->next_index));
 }
 
 /**
@@ -1242,7 +1243,7 @@ static void tcp_hash_remove(const struct ctx *c,
 
 	debug("TCP: hash table remove: index %li, sock %i, bucket: %i, new: %p",
 	      CONN_IDX(conn), conn->sock, b,
-	      prev ? conn_at_idx(prev->next_index) : tc_hash[b]);
+	      (void *)(prev ? conn_at_idx(prev->next_index) : tc_hash[b]));
 }
 
 /**
@@ -1270,7 +1271,8 @@ static void tcp_tap_conn_update(const struct ctx *c, struct tcp_tap_conn *old,
 
 	debug("TCP: hash table update: old index %li, new index %li, sock %i, "
 	      "bucket: %i, old: %p, new: %p",
-	      CONN_IDX(old), CONN_IDX(new), new->sock, b, old, new);
+	      CONN_IDX(old), CONN_IDX(new), new->sock, b,
+	      (void *)old, (void *)new);
 
 	tcp_epoll_ctl(c, new);
 }
@@ -1314,7 +1316,7 @@ void tcp_table_compact(struct ctx *c, union tcp_conn *hole)
 
 	if (CONN_IDX(hole) == --c->tcp.conn_count) {
 		debug("TCP: table compaction: maximum index was %li (%p)",
-		      CONN_IDX(hole), hole);
+		      CONN_IDX(hole), (void *)hole);
 		memset(hole, 0, sizeof(*hole));
 		return;
 	}
@@ -1329,7 +1331,8 @@ void tcp_table_compact(struct ctx *c, union tcp_conn *hole)
 
 	debug("TCP: table compaction (spliced=%d): old index %li, new index %li, "
 	      "from: %p, to: %p",
-	      from->c.spliced, CONN_IDX(from), CONN_IDX(hole), from, hole);
+	      from->c.spliced, CONN_IDX(from), CONN_IDX(hole),
+	      (void *)from, (void *)hole);
 
 	memset(from, 0, sizeof(*from));
 }
-- 
2.41.0

[PATCH v2 3/3] log: Add vlogmsg()

[David Gibson]

Currently logmsg() is only available as a variadic function.  This is fine
for normal use, but is awkward if we ever want to write wrappers around it
which (for example) add standardised prefix information.  To allow that,
add a vlogmsg() function which takes a va_list instead, and implement
logmsg() in terms of it.

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

diff --git a/log.c b/log.c
index fd33f64..95c4fa4 100644
--- a/log.c
+++ b/log.c
@@ -47,11 +47,10 @@ int		log_to_stdout;		/* Print to stdout instead of stderr */
 
 #define BEFORE_DAEMON		(setlogmask(0) == LOG_MASK(LOG_EMERG))
 
-void logmsg(int pri, const char *format, ...)
+void vlogmsg(int pri, const char *format, va_list ap)
 {
 	FILE *out = log_to_stdout ? stdout : stderr;
 	struct timespec tp;
-	va_list args;
 
 	if (setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file == -1) {
 		clock_gettime(CLOCK_REALTIME, &tp);
@@ -61,24 +60,32 @@ void logmsg(int pri, const char *format, ...)
 	}
 
 	if ((LOG_MASK(LOG_PRI(pri)) & log_mask) || BEFORE_DAEMON) {
-		va_start(args, format);
+		va_list ap2;
+
+		va_copy(ap2, ap); /* Don't clobber ap, we need it again */
 		if (log_file != -1)
-			logfile_write(pri, format, args);
+			logfile_write(pri, format, ap2);
 		else if (!(setlogmask(0) & LOG_MASK(LOG_DEBUG)))
-			passt_vsyslog(pri, format, args);
-		va_end(args);
+			passt_vsyslog(pri, format, ap2);
 	}
 
 	if ((setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file == -1) ||
 	    (BEFORE_DAEMON && !(log_opt & LOG_PERROR))) {
-		va_start(args, format);
-		(void)vfprintf(out, format, args);
-		va_end(args);
+		(void)vfprintf(out, format, ap);
 		if (format[strlen(format)] != '\n')
 			fprintf(out, "\n");
 	}
 }
 
+void logmsg(int pri, const char *format, ...)
+{
+	va_list ap;
+
+	va_start(ap, format);
+	vlogmsg(pri, format, ap);
+	va_end(ap);
+}
+
 /* Prefixes for log file messages, indexed by priority */
 const char *logfile_prefix[] = {
 	NULL, NULL, NULL,	/* Unused: LOG_EMERG, LOG_ALERT, LOG_CRIT */
diff --git a/log.h b/log.h
index df72f9a..9c38182 100644
--- a/log.h
+++ b/log.h
@@ -12,6 +12,7 @@
 #define LOGFILE_CUT_RATIO		30	/* When full, cut ~30% size */
 #define LOGFILE_SIZE_MIN		(5UL * MAX(BUFSIZ, PAGE_SIZE))
 
+void vlogmsg(int pri, const char *format, va_list ap);
 void logmsg(int pri, const char *format, ...)
 	__attribute__((format(printf, 2, 3)));
 
-- 
@@ -12,6 +12,7 @@
 #define LOGFILE_CUT_RATIO		30	/* When full, cut ~30% size */
 #define LOGFILE_SIZE_MIN		(5UL * MAX(BUFSIZ, PAGE_SIZE))
 
+void vlogmsg(int pri, const char *format, va_list ap);
 void logmsg(int pri, const char *format, ...)
 	__attribute__((format(printf, 2, 3)));
 
-- 
2.41.0

Re: [PATCH v2 1/3] log: Don't define logging function 4 times

[Stefano Brivio]

On Fri, 13 Oct 2023 15:50:28 +1100
David Gibson <david@gibson.dropbear.id.au> wrote:

> In log.c we use a macro to define logging functions for each of 4 priority
> levels.  The only difference between these is the priority we pass to
> vsyslog() and similar functions.  Because it's done as a macro, however,
> the entire functions code is included in the binary 4 times.

If you've been wondering about the reason for this madness, by the way:
this comes from (much) earlier versions where we had separate debug
builds to avoid the cost of formatting debug messages (and in some
cases fetch further information) in the regular build.

It didn't actually make a measurable difference, though, and it doesn't
anyway make sense any longer.

-- 
Stefano

Re: [PATCH v2 0/3] Some improvements to log functions

[Stefano Brivio]

On Fri, 13 Oct 2023 15:50:27 +1100
David Gibson <david@gibson.dropbear.id.au> wrote:

> Several small improvements to the logging functions.
> 
> Changes since v1:
>  * Added printf warning attributes
>  * Added vlogmsg()
> 
> David Gibson (3):
>   log: Don't define logging function 4 times
>   log: Enable format warnings
>   log: Add vlogmsg()

Applied.

-- 
Stefano