[PATCH v5 0/9] Fixes for early logging/prints and related cleanups

[PATCH v5 0/9] Fixes for early logging/prints and related cleanups

[Stefano Brivio]

The most apparent issue fixed by this series is the one from 4/6: with
a log file configured, we wouldn't print to standard error anymore,
during initialisation, which means that users such as libvirt lost
the ability to report meaningful error messages that occurred during
initialisation, in that case.

v5:
- in 4/8, rename the new flag once more to 'log_runtime': we don't
  want to log to standard error if we're running in foreground, a
  log file is given, and initialisation is done, otherwise debugging
  pasta when it spawns its own shell becomes rather impractical
- add 9/8, taking care of a direct stderr print left-over

v4:
- in 4/8, name the new flag 'log_daemonised' instead of
  'log_daemon_ready'

v3:
- add 2/8: we don't really need --stderr anymore
- in 5/8, save errno at the beginning of the _perror() helper
- in 7/8, avoid assigning errno to whatever return code we have just
  for the sake of using the new helpers: strerror() is actually less
  convoluted than that
- add 8/8: there's no need to call __openlog() with a log file

v2:
- turn flag bitmap into simple, separate boolean flags
- move errno description after message in _perror() functions
- make some of the old perror() messages more descriptive
*** BLURB HERE ***

Stefano Brivio (9):
  conf, passt: Don't try to log to stderr after we close it
  conf, passt: Make --stderr do nothing, and deprecate it
  conf, log: Instead of abusing log levels, add log_conf_parsed flag
  log, passt: Always print to stderr before initialisation is complete
  log: Add _perror() logging function variants
  treewide: Replace perror() calls with calls to logging functions
  treewide: Replace strerror() calls
  conf, passt: Don't call __openlog() if a log file is used
  log: Don't report syslog failures to stderr after initialisation

 arch.c      | 10 ++++-----
 conf.c      | 41 ++++++++++++---------------------
 fwd.c       |  2 +-
 isolation.c | 46 ++++++++++++++++---------------------
 log.c       | 65 ++++++++++++++++++++++++++++++++---------------------
 log.h       | 25 +++++++++++++++++----
 netlink.c   |  4 ++--
 passt.1     |  9 ++++----
 passt.c     | 64 +++++++++++++++++++---------------------------------
 passt.h     |  2 --
 pasta.c     | 27 +++++++++-------------
 pcap.c      |  8 +++----
 tap.c       | 14 ++++++------
 tcp.c       | 24 +++++++-------------
 util.c      | 12 +++++-----
 15 files changed, 164 insertions(+), 189 deletions(-)

-- 
2.43.0

[PATCH v5 1/9] conf, passt: Don't try to log to stderr after we close it

[Stefano Brivio]

If we don't run in foreground, we close standard error as we
daemonise, so it makes no sense to check if the controlling terminal
is an interactive terminal or if --force-stderr was given, to decide
if we want to log to standard error.

Make --force-stderr depend on --foreground.

Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
---
 conf.c  | 3 +++
 passt.c | 2 +-
 2 files changed, 4 insertions(+), 1 deletion(-)

diff --git a/conf.c b/conf.c
index 94b3ed6..dbdbb62 100644
--- a/conf.c
+++ b/conf.c
@@ -1693,6 +1693,9 @@ void conf(struct ctx *c, int argc, char **argv)
 
 	conf_ugid(runas, &uid, &gid);
 
+	if (!c->foreground && c->force_stderr)
+		die("Can't log to standard error if not running in foreground");
+
 	if (logfile) {
 		logfile_init(c->mode == MODE_PASTA ? "pasta" : "passt",
 			     logfile, logsize);
diff --git a/passt.c b/passt.c
index a5e2c5a..aa9648a 100644
--- a/passt.c
+++ b/passt.c
@@ -302,7 +302,7 @@ int main(int argc, char **argv)
 	if (isolate_prefork(&c))
 		die("Failed to sandbox process, exiting");
 
-	if (!c.force_stderr && !isatty(fileno(stderr)))
+	if (!c.foreground || (!c.force_stderr && !isatty(fileno(stderr))))
 		__openlog(log_name, 0, LOG_DAEMON);
 
 	if (!c.foreground)
-- 
@@ -302,7 +302,7 @@ int main(int argc, char **argv)
 	if (isolate_prefork(&c))
 		die("Failed to sandbox process, exiting");
 
-	if (!c.force_stderr && !isatty(fileno(stderr)))
+	if (!c.foreground || (!c.force_stderr && !isatty(fileno(stderr))))
 		__openlog(log_name, 0, LOG_DAEMON);
 
 	if (!c.foreground)
-- 
2.43.0

[PATCH v5 2/9] conf, passt: Make --stderr do nothing, and deprecate it

[Stefano Brivio]

The original behaviour of printing messages to standard error by
default when running from a non-interactive terminal was introduced
because the first KubeVirt integration draft used to start passt in
foreground and get messages via standard error.

For development purposes, the system logger was more convenient at
that point, and passt was running from interactive terminals only if
not started by the KubeVirt integration.

This behaviour was introduced by 84a62b79a2bc ("passt: Also log to
stderr, don't fork to background if not interactive").

Later, I added command-line options in 1e49d194d017 ("passt, pasta:
Introduce command-line options and port re-mapping") and accidentally
reversed this condition, which wasn't a problem as --stderr could
force printing to standard error anyway (and it was used by KubeVirt).

Nowadays, the KubeVirt integration uses a log file (requested via
libvirt configuration), and the same applies for Podman if one
actually needs to look at runtime logs. There are no use cases left,
as far as I know, where passt runs in foreground in non-interactive
terminals.

Seize the chance to reintroduce some sanity here. If we fork to
background, standard error is closed, so --stderr is useless in that
case.

If we run in foreground, there's no harm in printing messages to
standard error, and that accidentally became the default behaviour
anyway, so --stderr is not needed in that case.

It would be needed for non-interactive terminals, but there are no
use cases, and if there were, let's log to standard error anyway:
the user can always redirect standard error to /dev/null if needed.

Before we're up and running, we need to print to standard error anyway
if something happens, otherwise we can't report failure to start in
any kind of usage, stand-alone or in integrations.

So, make --stderr do nothing, and deprecate it.

While at it, drop a left-over comment about --foreground being the
default only for interactive terminals, because it's not the case
anymore.

Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
---
 conf.c  | 18 ++----------------
 passt.1 |  9 +++++----
 passt.c |  2 +-
 passt.h |  2 --
 4 files changed, 8 insertions(+), 23 deletions(-)

diff --git a/conf.c b/conf.c
index dbdbb62..9f869f5 100644
--- a/conf.c
+++ b/conf.c
@@ -730,9 +730,7 @@ static void usage(const char *name, FILE *f, int status)
 		"      --trace		Be extra verbose, implies --debug\n"
 		"  -q, --quiet		Don't print informational messages\n"
 		"  -f, --foreground	Don't run in background\n"
-		"    default: run in background if started from a TTY\n"
-		"  -e, --stderr		Log to stderr too\n"
-		"    default: log to system logger only if started from a TTY\n"
+		"    default: run in background\n"
 		"  -l, --log-file PATH	Log (only) to given file\n"
 		"  --log-size BYTES	Maximum size of log file\n"
 		"    default: 1 MiB\n"
@@ -1405,18 +1403,9 @@ void conf(struct ctx *c, int argc, char **argv)
 			c->debug = 1;
 			break;
 		case 'e':
-			if (logfile)
-				die("Can't log to both file and stderr");
-
-			if (c->force_stderr)
-				die("Multiple --stderr options given");
-
-			c->force_stderr = 1;
+			warn("--stderr will be dropped soon");
 			break;
 		case 'l':
-			if (c->force_stderr)
-				die("Can't log to both stderr and file");
-
 			if (logfile)
 				die("Multiple --log-file options given");
 
@@ -1693,9 +1682,6 @@ void conf(struct ctx *c, int argc, char **argv)
 
 	conf_ugid(runas, &uid, &gid);
 
-	if (!c->foreground && c->force_stderr)
-		die("Can't log to standard error if not running in foreground");
-
 	if (logfile) {
 		logfile_init(c->mode == MODE_PASTA ? "pasta" : "passt",
 			     logfile, logsize);
diff --git a/passt.1 b/passt.1
index 7676fe3..6c8f932 100644
--- a/passt.1
+++ b/passt.1
@@ -93,13 +93,14 @@ Default is to fork into background.
 
 .TP
 .BR \-e ", " \-\-stderr
-Log to standard error too.
-Default is to log to the system logger only, if started from an interactive
-terminal, and to both system logger and standard error otherwise.
+This option has no effect, and is maintained for compatibility purposes only.
+
+Note that this configuration option is \fBdeprecated\fR and will be removed in a
+future version.
 
 .TP
 .BR \-l ", " \-\-log-file " " \fIPATH\fR
-Log to file \fIPATH\fR, not to standard error, and not to the system logger.
+Log to file \fIPATH\fR, and not to the system logger.
 
 .TP
 .BR \-\-log-size " " \fISIZE\fR
diff --git a/passt.c b/passt.c
index aa9648a..19ecd68 100644
--- a/passt.c
+++ b/passt.c
@@ -302,7 +302,7 @@ int main(int argc, char **argv)
 	if (isolate_prefork(&c))
 		die("Failed to sandbox process, exiting");
 
-	if (!c.foreground || (!c.force_stderr && !isatty(fileno(stderr))))
+	if (!c.foreground)
 		__openlog(log_name, 0, LOG_DAEMON);
 
 	if (!c.foreground)
diff --git a/passt.h b/passt.h
index 46d073a..21cf4c1 100644
--- a/passt.h
+++ b/passt.h
@@ -180,7 +180,6 @@ struct ip6_ctx {
  * @trace:		Enable tracing (extra debug) mode
  * @quiet:		Don't print informational messages
  * @foreground:		Run in foreground, don't log to stderr by default
- * @force_stderr:	Force logging to stderr
  * @nofile:		Maximum number of open files (ulimit -n)
  * @sock_path:		Path for UNIX domain socket
  * @pcap:		Path for packet capture file
@@ -231,7 +230,6 @@ struct ctx {
 	int trace;
 	int quiet;
 	int foreground;
-	int force_stderr;
 	int nofile;
 	char sock_path[UNIX_PATH_MAX];
 	char pcap[PATH_MAX];
-- 
@@ -180,7 +180,6 @@ struct ip6_ctx {
  * @trace:		Enable tracing (extra debug) mode
  * @quiet:		Don't print informational messages
  * @foreground:		Run in foreground, don't log to stderr by default
- * @force_stderr:	Force logging to stderr
  * @nofile:		Maximum number of open files (ulimit -n)
  * @sock_path:		Path for UNIX domain socket
  * @pcap:		Path for packet capture file
@@ -231,7 +230,6 @@ struct ctx {
 	int trace;
 	int quiet;
 	int foreground;
-	int force_stderr;
 	int nofile;
 	char sock_path[UNIX_PATH_MAX];
 	char pcap[PATH_MAX];
-- 
2.43.0

[PATCH v5 3/9] conf, log: Instead of abusing log levels, add log_conf_parsed flag

[Stefano Brivio]

We currently use a LOG_EMERG log mask to represent the fact that we
don't know yet what the mask resulting from configuration should be,
before the command line is parsed.

However, we have the necessity of representing another phase as well,
that is, configuration is parsed but we didn't daemonise yet, or
we're not ready for operation yet. The next patch will add that
notion explicitly.

Mapping these cases to further log levels isn't really practical.
Introduce boolean log flags to represent them, instead of abusing
log priorities.

Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
---
 conf.c |  5 ++---
 log.c  | 12 +++++-------
 log.h  |  3 +++
 3 files changed, 10 insertions(+), 10 deletions(-)

diff --git a/conf.c b/conf.c
index 9f869f5..726efaf 100644
--- a/conf.c
+++ b/conf.c
@@ -1687,9 +1687,6 @@ void conf(struct ctx *c, int argc, char **argv)
 			     logfile, logsize);
 	}
 
-	/* Once the log mask is not LOG_EARLY, we will no longer log to stderr
-	 * if there was a log file specified.
-	 */
 	if (c->debug)
 		__setlogmask(LOG_UPTO(LOG_DEBUG));
 	else if (c->quiet)
@@ -1697,6 +1694,8 @@ void conf(struct ctx *c, int argc, char **argv)
 	else
 		__setlogmask(LOG_UPTO(LOG_INFO));
 
+	log_conf_parsed = true;		/* Stop printing everything */
+
 	nl_sock_init(c, false);
 	if (!v6_only)
 		c->ifi4 = conf_ip4(ifi4, &c->ip4, c->mac);
diff --git a/log.c b/log.c
index aaf2beb..05b7f80 100644
--- a/log.c
+++ b/log.c
@@ -30,12 +30,9 @@
 #include "util.h"
 #include "passt.h"
 
-/* LOG_EARLY means we don't know yet: log everything. LOG_EMERG is unused */
-#define LOG_EARLY		LOG_MASK(LOG_EMERG)
-
 static int	log_sock = -1;		/* Optional socket to system logger */
 static char	log_ident[BUFSIZ];	/* Identifier string for openlog() */
-static int	log_mask = LOG_EARLY;	/* Current log priority mask */
+static int	log_mask;		/* Current log priority mask */
 static int	log_opt;		/* Options for openlog() */
 
 static int	log_file = -1;		/* Optional log file descriptor */
@@ -45,12 +42,13 @@ 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 */
+
 int		log_trace;		/* --trace mode enabled */
+bool		log_conf_parsed;	/* Logging options already parsed */
 
 void vlogmsg(int pri, const char *format, va_list ap)
 {
 	bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1;
-	bool early_print = LOG_PRI(log_mask) == LOG_EARLY;
 	struct timespec tp;
 
 	if (debug_print) {
@@ -60,7 +58,7 @@ void vlogmsg(int pri, const char *format, va_list ap)
 			(long long int)tp.tv_nsec / (100L * 1000));
 	}
 
-	if ((log_mask & LOG_MASK(LOG_PRI(pri))) || early_print) {
+	if ((log_mask & LOG_MASK(LOG_PRI(pri))) || !log_conf_parsed) {
 		va_list ap2;
 
 		va_copy(ap2, ap); /* Don't clobber ap, we need it again */
@@ -72,7 +70,7 @@ void vlogmsg(int pri, const char *format, va_list ap)
 		va_end(ap2);
 	}
 
-	if (debug_print || (early_print && !(log_opt & LOG_PERROR))) {
+	if (debug_print || (!log_conf_parsed && !(log_opt & LOG_PERROR))) {
 		(void)vfprintf(stderr, format, ap);
 		if (format[strlen(format)] != '\n')
 			fprintf(stderr, "\n");
diff --git a/log.h b/log.h
index e0aab5a..3dab284 100644
--- a/log.h
+++ b/log.h
@@ -6,6 +6,7 @@
 #ifndef LOG_H
 #define LOG_H
 
+#include <stdbool.h>
 #include <syslog.h>
 
 #define LOGFILE_SIZE_DEFAULT		(1024 * 1024UL)
@@ -28,6 +29,8 @@ void logmsg(int pri, const char *format, ...)
 	} while (0)
 
 extern int log_trace;
+extern bool log_conf_parsed;
+
 void trace_init(int enable);
 #define trace(...)							\
 	do {								\
-- 
@@ -6,6 +6,7 @@
 #ifndef LOG_H
 #define LOG_H
 
+#include <stdbool.h>
 #include <syslog.h>
 
 #define LOGFILE_SIZE_DEFAULT		(1024 * 1024UL)
@@ -28,6 +29,8 @@ void logmsg(int pri, const char *format, ...)
 	} while (0)
 
 extern int log_trace;
+extern bool log_conf_parsed;
+
 void trace_init(int enable);
 #define trace(...)							\
 	do {								\
-- 
2.43.0

[PATCH v5 4/9] log, passt: Always print to stderr before initialisation is complete

[Stefano Brivio]

After commit 15001b39ef1d ("conf: set the log level much earlier"), we
had a phase during initialisation when messages wouldn't be printed to
standard error anymore.

Commit f67238aa864d ("passt, log: Call __openlog() earlier, log to
stderr until we detach") fixed that, but only for the case where no
log files are given.

If a log file is configured, vlogmsg() will not call passt_vsyslog(),
but during initialisation, LOG_PERROR is set, so to avoid duplicated
prints (which would result from passt_vsyslog() printing to stderr),
we don't call fprintf() from vlogmsg() either.

This is getting a bit too complicated. Instead of abusing LOG_PERROR,
define an internal logging flag that clearly represents that we're not
done with the initialisation phase yet.

If this flag is not set, make sure we always print to stderr, if the
log mask matches.

Reported-by: Yalan Zhang <yalzhang@redhat.com>
Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
---
 log.c   | 17 ++++++++---------
 log.h   |  1 +
 passt.c | 11 +++++------
 3 files changed, 14 insertions(+), 15 deletions(-)

diff --git a/log.c b/log.c
index 05b7f80..0199eb4 100644
--- a/log.c
+++ b/log.c
@@ -33,7 +33,6 @@
 static int	log_sock = -1;		/* Optional socket to system logger */
 static char	log_ident[BUFSIZ];	/* Identifier string for openlog() */
 static int	log_mask;		/* Current log priority mask */
-static int	log_opt;		/* Options for openlog() */
 
 static int	log_file = -1;		/* Optional log file descriptor */
 static size_t	log_size;		/* Maximum log file size in bytes */
@@ -45,6 +44,7 @@ static time_t	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 */
 
 void vlogmsg(int pri, const char *format, va_list ap)
 {
@@ -70,7 +70,8 @@ void vlogmsg(int pri, const char *format, va_list ap)
 		va_end(ap2);
 	}
 
-	if (debug_print || (!log_conf_parsed && !(log_opt & LOG_PERROR))) {
+	if (debug_print || !log_conf_parsed ||
+	    (!log_runtime && (log_mask & LOG_MASK(LOG_PRI(pri))))) {
 		(void)vfprintf(stderr, format, ap);
 		if (format[strlen(format)] != '\n')
 			fprintf(stderr, "\n");
@@ -108,13 +109,15 @@ void trace_init(int enable)
 /**
  * __openlog() - Non-optional openlog() implementation, for custom vsyslog()
  * @ident:	openlog() identity (program name)
- * @option:	openlog() options
+ * @option:	openlog() options, unused
  * @facility:	openlog() facility (LOG_DAEMON)
  */
 void __openlog(const char *ident, int option, int facility)
 {
 	struct timespec tp;
 
+	(void)option;
+
 	clock_gettime(CLOCK_REALTIME, &tp);
 	log_start = tp.tv_sec;
 
@@ -135,7 +138,6 @@ void __openlog(const char *ident, int option, int facility)
 
 	log_mask |= facility;
 	strncpy(log_ident, ident, sizeof(log_ident) - 1);
-	log_opt = option;
 }
 
 /**
@@ -156,20 +158,17 @@ void __setlogmask(int mask)
  */
 void passt_vsyslog(int pri, const char *format, va_list ap)
 {
-	int prefix_len, n;
 	char buf[BUFSIZ];
+	int n;
 
 	/* Send without timestamp, the system logger should add it */
-	n = prefix_len = snprintf(buf, BUFSIZ, "<%i> %s: ", pri, log_ident);
+	n = snprintf(buf, BUFSIZ, "<%i> %s: ", pri, log_ident);
 
 	n += vsnprintf(buf + n, BUFSIZ - n, format, ap);
 
 	if (format[strlen(format)] != '\n')
 		n += snprintf(buf + n, BUFSIZ - n, "\n");
 
-	if (log_opt & LOG_PERROR)
-		fprintf(stderr, "%s", buf + prefix_len);
-
 	if (log_sock >= 0 && send(log_sock, buf, n, 0) != n)
 		fprintf(stderr, "Failed to send %i bytes to syslog\n", n);
 }
diff --git a/log.h b/log.h
index 3dab284..77d74a2 100644
--- a/log.h
+++ b/log.h
@@ -30,6 +30,7 @@ void logmsg(int pri, const char *format, ...)
 
 extern int log_trace;
 extern bool log_conf_parsed;
+extern bool log_runtime;
 
 void trace_init(int enable);
 #define trace(...)							\
diff --git a/passt.c b/passt.c
index 19ecd68..e5cfd62 100644
--- a/passt.c
+++ b/passt.c
@@ -200,8 +200,8 @@ void exit_handler(int signal)
 int main(int argc, char **argv)
 {
 	struct epoll_event events[EPOLL_EVENTS];
-	char *log_name, argv0[PATH_MAX], *name;
 	int nfds, i, devnull_fd = -1;
+	char argv0[PATH_MAX], *name;
 	struct ctx c = { 0 };
 	struct rlimit limit;
 	struct timespec now;
@@ -225,7 +225,7 @@ int main(int argc, char **argv)
 	strncpy(argv0, argv[0], PATH_MAX - 1);
 	name = basename(argv0);
 	if (strstr(name, "pasta")) {
-		__openlog(log_name = "pasta", LOG_PERROR, LOG_DAEMON);
+		__openlog("pasta", 0, LOG_DAEMON);
 
 		sa.sa_handler = pasta_child_handler;
 		if (sigaction(SIGCHLD, &sa, NULL)) {
@@ -240,7 +240,7 @@ int main(int argc, char **argv)
 
 		c.mode = MODE_PASTA;
 	} else if (strstr(name, "passt")) {
-		__openlog(log_name = "passt", LOG_PERROR, LOG_DAEMON);
+		__openlog("passt", 0, LOG_DAEMON);
 
 		c.mode = MODE_PASST;
 	} else {
@@ -302,14 +302,13 @@ int main(int argc, char **argv)
 	if (isolate_prefork(&c))
 		die("Failed to sandbox process, exiting");
 
-	if (!c.foreground)
-		__openlog(log_name, 0, LOG_DAEMON);
-
 	if (!c.foreground)
 		__daemon(c.pidfile_fd, devnull_fd);
 	else
 		pidfile_write(c.pidfile_fd, getpid());
 
+	log_runtime = true;
+
 	if (pasta_child_pid)
 		kill(pasta_child_pid, SIGUSR1);
 
-- 
@@ -200,8 +200,8 @@ void exit_handler(int signal)
 int main(int argc, char **argv)
 {
 	struct epoll_event events[EPOLL_EVENTS];
-	char *log_name, argv0[PATH_MAX], *name;
 	int nfds, i, devnull_fd = -1;
+	char argv0[PATH_MAX], *name;
 	struct ctx c = { 0 };
 	struct rlimit limit;
 	struct timespec now;
@@ -225,7 +225,7 @@ int main(int argc, char **argv)
 	strncpy(argv0, argv[0], PATH_MAX - 1);
 	name = basename(argv0);
 	if (strstr(name, "pasta")) {
-		__openlog(log_name = "pasta", LOG_PERROR, LOG_DAEMON);
+		__openlog("pasta", 0, LOG_DAEMON);
 
 		sa.sa_handler = pasta_child_handler;
 		if (sigaction(SIGCHLD, &sa, NULL)) {
@@ -240,7 +240,7 @@ int main(int argc, char **argv)
 
 		c.mode = MODE_PASTA;
 	} else if (strstr(name, "passt")) {
-		__openlog(log_name = "passt", LOG_PERROR, LOG_DAEMON);
+		__openlog("passt", 0, LOG_DAEMON);
 
 		c.mode = MODE_PASST;
 	} else {
@@ -302,14 +302,13 @@ int main(int argc, char **argv)
 	if (isolate_prefork(&c))
 		die("Failed to sandbox process, exiting");
 
-	if (!c.foreground)
-		__openlog(log_name, 0, LOG_DAEMON);
-
 	if (!c.foreground)
 		__daemon(c.pidfile_fd, devnull_fd);
 	else
 		pidfile_write(c.pidfile_fd, getpid());
 
+	log_runtime = true;
+
 	if (pasta_child_pid)
 		kill(pasta_child_pid, SIGUSR1);
 
-- 
2.43.0

Re: [PATCH v5 4/9] log, passt: Always print to stderr before initialisation is complete

[David Gibson]

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

On Thu, Jun 20, 2024 at 06:15:13PM +0200, Stefano Brivio wrote:
> After commit 15001b39ef1d ("conf: set the log level much earlier"), we
> had a phase during initialisation when messages wouldn't be printed to
> standard error anymore.
> 
> Commit f67238aa864d ("passt, log: Call __openlog() earlier, log to
> stderr until we detach") fixed that, but only for the case where no
> log files are given.
> 
> If a log file is configured, vlogmsg() will not call passt_vsyslog(),
> but during initialisation, LOG_PERROR is set, so to avoid duplicated
> prints (which would result from passt_vsyslog() printing to stderr),
> we don't call fprintf() from vlogmsg() either.
> 
> This is getting a bit too complicated. Instead of abusing LOG_PERROR,
> define an internal logging flag that clearly represents that we're not
> done with the initialisation phase yet.
> 
> If this flag is not set, make sure we always print to stderr, if the
> log mask matches.
> 
> Reported-by: Yalan Zhang <yalzhang@redhat.com>
> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>

Reviewed-by: David Gibson <david@gibson.dropbear.id.au>

Modulo some concerns that I'll comment on for the series as a whole.

> ---
>  log.c   | 17 ++++++++---------
>  log.h   |  1 +
>  passt.c | 11 +++++------
>  3 files changed, 14 insertions(+), 15 deletions(-)
> 
> diff --git a/log.c b/log.c
> index 05b7f80..0199eb4 100644
> --- a/log.c
> +++ b/log.c
> @@ -33,7 +33,6 @@
>  static int	log_sock = -1;		/* Optional socket to system logger */
>  static char	log_ident[BUFSIZ];	/* Identifier string for openlog() */
>  static int	log_mask;		/* Current log priority mask */
> -static int	log_opt;		/* Options for openlog() */
>  
>  static int	log_file = -1;		/* Optional log file descriptor */
>  static size_t	log_size;		/* Maximum log file size in bytes */
> @@ -45,6 +44,7 @@ static time_t	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 */
>  
>  void vlogmsg(int pri, const char *format, va_list ap)
>  {
> @@ -70,7 +70,8 @@ void vlogmsg(int pri, const char *format, va_list ap)
>  		va_end(ap2);
>  	}
>  
> -	if (debug_print || (!log_conf_parsed && !(log_opt & LOG_PERROR))) {
> +	if (debug_print || !log_conf_parsed ||
> +	    (!log_runtime && (log_mask & LOG_MASK(LOG_PRI(pri))))) {
>  		(void)vfprintf(stderr, format, ap);
>  		if (format[strlen(format)] != '\n')
>  			fprintf(stderr, "\n");
> @@ -108,13 +109,15 @@ void trace_init(int enable)
>  /**
>   * __openlog() - Non-optional openlog() implementation, for custom vsyslog()
>   * @ident:	openlog() identity (program name)
> - * @option:	openlog() options
> + * @option:	openlog() options, unused
>   * @facility:	openlog() facility (LOG_DAEMON)
>   */
>  void __openlog(const char *ident, int option, int facility)
>  {
>  	struct timespec tp;
>  
> +	(void)option;
> +
>  	clock_gettime(CLOCK_REALTIME, &tp);
>  	log_start = tp.tv_sec;
>  
> @@ -135,7 +138,6 @@ void __openlog(const char *ident, int option, int facility)
>  
>  	log_mask |= facility;
>  	strncpy(log_ident, ident, sizeof(log_ident) - 1);
> -	log_opt = option;
>  }
>  
>  /**
> @@ -156,20 +158,17 @@ void __setlogmask(int mask)
>   */
>  void passt_vsyslog(int pri, const char *format, va_list ap)
>  {
> -	int prefix_len, n;
>  	char buf[BUFSIZ];
> +	int n;
>  
>  	/* Send without timestamp, the system logger should add it */
> -	n = prefix_len = snprintf(buf, BUFSIZ, "<%i> %s: ", pri, log_ident);
> +	n = snprintf(buf, BUFSIZ, "<%i> %s: ", pri, log_ident);
>  
>  	n += vsnprintf(buf + n, BUFSIZ - n, format, ap);
>  
>  	if (format[strlen(format)] != '\n')
>  		n += snprintf(buf + n, BUFSIZ - n, "\n");
>  
> -	if (log_opt & LOG_PERROR)
> -		fprintf(stderr, "%s", buf + prefix_len);
> -
>  	if (log_sock >= 0 && send(log_sock, buf, n, 0) != n)
>  		fprintf(stderr, "Failed to send %i bytes to syslog\n", n);
>  }
> diff --git a/log.h b/log.h
> index 3dab284..77d74a2 100644
> --- a/log.h
> +++ b/log.h
> @@ -30,6 +30,7 @@ void logmsg(int pri, const char *format, ...)
>  
>  extern int log_trace;
>  extern bool log_conf_parsed;
> +extern bool log_runtime;
>  
>  void trace_init(int enable);
>  #define trace(...)							\
> diff --git a/passt.c b/passt.c
> index 19ecd68..e5cfd62 100644
> --- a/passt.c
> +++ b/passt.c
> @@ -200,8 +200,8 @@ void exit_handler(int signal)
>  int main(int argc, char **argv)
>  {
>  	struct epoll_event events[EPOLL_EVENTS];
> -	char *log_name, argv0[PATH_MAX], *name;
>  	int nfds, i, devnull_fd = -1;
> +	char argv0[PATH_MAX], *name;
>  	struct ctx c = { 0 };
>  	struct rlimit limit;
>  	struct timespec now;
> @@ -225,7 +225,7 @@ int main(int argc, char **argv)
>  	strncpy(argv0, argv[0], PATH_MAX - 1);
>  	name = basename(argv0);
>  	if (strstr(name, "pasta")) {
> -		__openlog(log_name = "pasta", LOG_PERROR, LOG_DAEMON);
> +		__openlog("pasta", 0, LOG_DAEMON);
>  
>  		sa.sa_handler = pasta_child_handler;
>  		if (sigaction(SIGCHLD, &sa, NULL)) {
> @@ -240,7 +240,7 @@ int main(int argc, char **argv)
>  
>  		c.mode = MODE_PASTA;
>  	} else if (strstr(name, "passt")) {
> -		__openlog(log_name = "passt", LOG_PERROR, LOG_DAEMON);
> +		__openlog("passt", 0, LOG_DAEMON);
>  
>  		c.mode = MODE_PASST;
>  	} else {
> @@ -302,14 +302,13 @@ int main(int argc, char **argv)
>  	if (isolate_prefork(&c))
>  		die("Failed to sandbox process, exiting");
>  
> -	if (!c.foreground)
> -		__openlog(log_name, 0, LOG_DAEMON);
> -
>  	if (!c.foreground)
>  		__daemon(c.pidfile_fd, devnull_fd);
>  	else
>  		pidfile_write(c.pidfile_fd, getpid());
>  
> +	log_runtime = true;
> +
>  	if (pasta_child_pid)
>  		kill(pasta_child_pid, SIGUSR1);
>  

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

[PATCH v5 5/9] log: Add _perror() logging function variants

[Stefano Brivio]

In many places, we have direct perror() calls, which completely bypass
logging functions and log files.

They are definitely convenient: offer similar convenience with
_perror() logging variants, so that we can drop those direct perror()
calls.

Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
---
 log.c | 22 ++++++++++++++++++++++
 log.h | 21 +++++++++++++++++----
 2 files changed, 39 insertions(+), 4 deletions(-)

diff --git a/log.c b/log.c
index 0199eb4..7182acb 100644
--- a/log.c
+++ b/log.c
@@ -78,6 +78,11 @@ void vlogmsg(int pri, const char *format, va_list ap)
 	}
 }
 
+/**
+ * logmsg() - vlogmsg() wrapper for variable argument lists
+ * @pri:	Facility and level map, same as priority for vsyslog()
+ * @format:	Message
+ */
 void logmsg(int pri, const char *format, ...)
 {
 	va_list ap;
@@ -87,6 +92,23 @@ void logmsg(int pri, const char *format, ...)
 	va_end(ap);
 }
 
+/**
+ * logmsg_perror() - vlogmsg() wrapper with perror()-like functionality
+ * @pri:	Facility and level map, same as priority for vsyslog()
+ * @format:	Message
+ */
+void logmsg_perror(int pri, const char *format, ...)
+{
+	int errno_copy = errno;
+	va_list ap;
+
+	va_start(ap, format);
+	vlogmsg(pri, format, ap);
+	va_end(ap);
+
+	logmsg(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 */
diff --git a/log.h b/log.h
index 77d74a2..6f34e8d 100644
--- a/log.h
+++ b/log.h
@@ -16,11 +16,18 @@
 void vlogmsg(int pri, const char *format, va_list ap);
 void logmsg(int pri, const char *format, ...)
 	__attribute__((format(printf, 2, 3)));
+void logmsg_perror(int pri, const char *format, ...)
+	__attribute__((format(printf, 2, 3)));
+
+#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 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 err_perror(...)		logmsg_perror(	LOG_ERR,	__VA_ARGS__)
+#define warn_perror(...)	logmsg_perror(	LOG_WARNING,	__VA_ARGS__)
+#define info_perror(...)	logmsg_perror(	LOG_INFO,	__VA_ARGS__)
+#define debug_perror(...)	logmsg_perror(	LOG_DEBUG,	__VA_ARGS__)
 
 #define die(...)							\
 	do {								\
@@ -28,6 +35,12 @@ void logmsg(int pri, const char *format, ...)
 		exit(EXIT_FAILURE);					\
 	} while (0)
 
+#define die_perror(...)							\
+	do {								\
+		err_perror(__VA_ARGS__);				\
+		exit(EXIT_FAILURE);					\
+	} while (0)
+
 extern int log_trace;
 extern bool log_conf_parsed;
 extern bool log_runtime;
-- 
@@ -16,11 +16,18 @@
 void vlogmsg(int pri, const char *format, va_list ap);
 void logmsg(int pri, const char *format, ...)
 	__attribute__((format(printf, 2, 3)));
+void logmsg_perror(int pri, const char *format, ...)
+	__attribute__((format(printf, 2, 3)));
+
+#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 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 err_perror(...)		logmsg_perror(	LOG_ERR,	__VA_ARGS__)
+#define warn_perror(...)	logmsg_perror(	LOG_WARNING,	__VA_ARGS__)
+#define info_perror(...)	logmsg_perror(	LOG_INFO,	__VA_ARGS__)
+#define debug_perror(...)	logmsg_perror(	LOG_DEBUG,	__VA_ARGS__)
 
 #define die(...)							\
 	do {								\
@@ -28,6 +35,12 @@ void logmsg(int pri, const char *format, ...)
 		exit(EXIT_FAILURE);					\
 	} while (0)
 
+#define die_perror(...)							\
+	do {								\
+		err_perror(__VA_ARGS__);				\
+		exit(EXIT_FAILURE);					\
+	} while (0)
+
 extern int log_trace;
 extern bool log_conf_parsed;
 extern bool log_runtime;
-- 
2.43.0

[PATCH v5 6/9] treewide: Replace perror() calls with calls to logging functions

[Stefano Brivio]

perror() prints directly to standard error, but in many cases standard
error might be already closed, or we might want to skip logging, based
on configuration. Our logging functions provide all that.

While at it, make errors more descriptive, replacing some of the
existing basic perror-style messages.

Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
---
 arch.c      | 10 +++++-----
 conf.c      |  6 ++----
 isolation.c | 18 ++++++++----------
 log.c       | 12 ++++--------
 passt.c     | 41 ++++++++++++++++-------------------------
 pasta.c     |  9 +++------
 6 files changed, 38 insertions(+), 58 deletions(-)

diff --git a/arch.c b/arch.c
index 80a41bc..04bebfc 100644
--- a/arch.c
+++ b/arch.c
@@ -18,6 +18,8 @@
 #include <string.h>
 #include <unistd.h>
 
+#include "log.h"
+
 /**
  * arch_avx2_exec() - Switch to AVX2 build if supported
  * @argv:	Arguments from command line
@@ -28,10 +30,8 @@ void arch_avx2_exec(char **argv)
 	char exe[PATH_MAX] = { 0 };
 	const char *p;
 
-	if (readlink("/proc/self/exe", exe, PATH_MAX - 1) < 0) {
-		perror("readlink /proc/self/exe");
-		exit(EXIT_FAILURE);
-	}
+	if (readlink("/proc/self/exe", exe, PATH_MAX - 1) < 0)
+		die_perror("Failed to read own /proc/self/exe link");
 
 	p = strstr(exe, ".avx2");
 	if (p && strlen(p) == strlen(".avx2"))
@@ -42,7 +42,7 @@ void arch_avx2_exec(char **argv)
 
 		snprintf(new_path, PATH_MAX + sizeof(".avx2"), "%s.avx2", exe);
 		execve(new_path, argv, environ);
-		perror("Can't run AVX2 build, using non-AVX2 version");
+		warn_perror("Can't run AVX2 build, using non-AVX2 version");
 	}
 }
 #else
diff --git a/conf.c b/conf.c
index 726efaf..b8247c4 100644
--- a/conf.c
+++ b/conf.c
@@ -1096,10 +1096,8 @@ static void conf_ugid(char *runas, uid_t *uid, gid_t *gid)
 		const struct passwd *pw;
 		/* cppcheck-suppress getpwnamCalled */
 		pw = getpwnam("nobody");
-		if (!pw) {
-			perror("getpwnam");
-			exit(EXIT_FAILURE);
-		}
+		if (!pw)
+			die_perror("Can't get password file entry for nobody");
 
 		*uid = pw->pw_uid;
 		*gid = pw->pw_gid;
diff --git a/isolation.c b/isolation.c
index ca2c68b..c936674 100644
--- a/isolation.c
+++ b/isolation.c
@@ -316,34 +316,34 @@ int isolate_prefork(const struct ctx *c)
 		flags |= CLONE_NEWPID;
 
 	if (unshare(flags)) {
-		perror("unshare");
+		err_perror("Failed to detach isolating namespaces");
 		return -errno;
 	}
 
 	if (mount("", "/", "", MS_UNBINDABLE | MS_REC, NULL)) {
-		perror("mount /");
+		err_perror("Failed to remount /");
 		return -errno;
 	}
 
 	if (mount("", TMPDIR, "tmpfs",
 		  MS_NODEV | MS_NOEXEC | MS_NOSUID | MS_RDONLY,
 		  "nr_inodes=2,nr_blocks=0")) {
-		perror("mount tmpfs");
+		err_perror("Failed to mount empty tmpfs for pivot_root()");
 		return -errno;
 	}
 
 	if (chdir(TMPDIR)) {
-		perror("chdir");
+		err_perror("Failed to change directory into empty tmpfs");
 		return -errno;
 	}
 
 	if (syscall(SYS_pivot_root, ".", ".")) {
-		perror("pivot_root");
+		err_perror("Failed to pivot_root() into empty tmpfs");
 		return -errno;
 	}
 
 	if (umount2(".", MNT_DETACH | UMOUNT_NOFOLLOW)) {
-		perror("umount2");
+		err_perror("Failed to unmount original root filesystem");
 		return -errno;
 	}
 
@@ -388,8 +388,6 @@ void isolate_postfork(const struct ctx *c)
 	}
 
 	if (prctl(PR_SET_NO_NEW_PRIVS, 1, 0, 0, 0) ||
-	    prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, &prog)) {
-		perror("prctl");
-		exit(EXIT_FAILURE);
-	}
+	    prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, &prog))
+		die_perror("Failed to apply seccomp filter");
 }
diff --git a/log.c b/log.c
index 7182acb..528ee51 100644
--- a/log.c
+++ b/log.c
@@ -206,10 +206,8 @@ void logfile_init(const char *name, const char *path, size_t size)
 	char nl = '\n', exe[PATH_MAX] = { 0 };
 	int n;
 
-	if (readlink("/proc/self/exe", exe, PATH_MAX - 1) < 0) {
-		perror("readlink /proc/self/exe");
-		exit(EXIT_FAILURE);
-	}
+	if (readlink("/proc/self/exe", exe, PATH_MAX - 1) < 0)
+		die_perror("Failed to read own /proc/self/exe link");
 
 	log_file = open(path, O_CREAT | O_TRUNC | O_APPEND | O_RDWR | O_CLOEXEC,
 			S_IRUSR | S_IWUSR);
@@ -222,10 +220,8 @@ void logfile_init(const char *name, const char *path, size_t size)
 		     name, exe, getpid());
 
 	if (write(log_file, log_header, n) <= 0 ||
-	    write(log_file, &nl, 1) <= 0) {
-		perror("Couldn't write to log file\n");
-		exit(EXIT_FAILURE);
-	}
+	    write(log_file, &nl, 1) <= 0)
+		die_perror("Couldn't write to log file");
 
 	/* For FALLOC_FL_COLLAPSE_RANGE: VFS block size can be up to one page */
 	log_cut_size = ROUND_UP(log_size * LOGFILE_CUT_RATIO / 100, PAGE_SIZE);
diff --git a/passt.c b/passt.c
index e5cfd62..a48c5f6 100644
--- a/passt.c
+++ b/passt.c
@@ -136,14 +136,13 @@ static void secret_init(struct ctx *c)
 	}
 	if (dev_random >= 0)
 		close(dev_random);
-	if (random_read < sizeof(c->hash_secret)) {
+
+	if (random_read < sizeof(c->hash_secret))
 #else
 	if (getrandom(&c->hash_secret, sizeof(c->hash_secret),
-		      GRND_RANDOM) < 0) {
+		      GRND_RANDOM) < 0)
 #endif /* !HAS_GETRANDOM */
-		perror("TCP initial sequence getrandom");
-		exit(EXIT_FAILURE);
-	}
+		die_perror("Failed to get random bytes for hash table and TCP");
 }
 
 /**
@@ -250,20 +249,16 @@ int main(int argc, char **argv)
 	madvise(pkt_buf, TAP_BUF_BYTES, MADV_HUGEPAGE);
 
 	c.epollfd = epoll_create1(EPOLL_CLOEXEC);
-	if (c.epollfd == -1) {
-		perror("epoll_create1");
-		exit(EXIT_FAILURE);
-	}
+	if (c.epollfd == -1)
+		die_perror("Failed to create epoll file descriptor");
+
+	if (getrlimit(RLIMIT_NOFILE, &limit))
+		die_perror("Failed to get maximum value of open files limit");
 
-	if (getrlimit(RLIMIT_NOFILE, &limit)) {
-		perror("getrlimit");
-		exit(EXIT_FAILURE);
-	}
 	c.nofile = limit.rlim_cur = limit.rlim_max;
-	if (setrlimit(RLIMIT_NOFILE, &limit)) {
-		perror("setrlimit");
-		exit(EXIT_FAILURE);
-	}
+	if (setrlimit(RLIMIT_NOFILE, &limit))
+		die_perror("Failed to set current limit for open files");
+
 	sock_probe_mem(&c);
 
 	conf(&c, argc, argv);
@@ -293,10 +288,8 @@ int main(int argc, char **argv)
 	pcap_init(&c);
 
 	if (!c.foreground) {
-		if ((devnull_fd = open("/dev/null", O_RDWR | O_CLOEXEC)) < 0) {
-			perror("/dev/null open");
-			exit(EXIT_FAILURE);
-		}
+		if ((devnull_fd = open("/dev/null", O_RDWR | O_CLOEXEC)) < 0)
+			die_perror("Failed to open /dev/null");
 	}
 
 	if (isolate_prefork(&c))
@@ -320,10 +313,8 @@ loop:
 	/* NOLINTNEXTLINE(bugprone-branch-clone): intervals can be the same */
 	/* cppcheck-suppress [duplicateValueTernary, unmatchedSuppression] */
 	nfds = epoll_wait(c.epollfd, events, EPOLL_EVENTS, TIMER_INTERVAL);
-	if (nfds == -1 && errno != EINTR) {
-		perror("epoll_wait");
-		exit(EXIT_FAILURE);
-	}
+	if (nfds == -1 && errno != EINTR)
+		die_perror("epoll_wait() failed in main loop");
 
 	clock_gettime(CLOCK_MONOTONIC, &now);
 
diff --git a/pasta.c b/pasta.c
index b85ea2b..d08391f 100644
--- a/pasta.c
+++ b/pasta.c
@@ -197,8 +197,7 @@ static int pasta_spawn_cmd(void *arg)
 	a = (const struct pasta_spawn_cmd_arg *)arg;
 	execvp(a->exe, a->argv);
 
-	perror("execvp");
-	exit(EXIT_FAILURE);
+	die_perror("Failed to start command or shell");
 }
 
 /**
@@ -261,10 +260,8 @@ void pasta_start_ns(struct ctx *c, uid_t uid, gid_t gid,
 				   CLONE_NEWUTS | CLONE_NEWNS  | SIGCHLD,
 				   (void *)&arg);
 
-	if (pasta_child_pid == -1) {
-		perror("clone");
-		exit(EXIT_FAILURE);
-	}
+	if (pasta_child_pid == -1)
+		die_perror("Failed to clone process with detached namespaces");
 
 	NS_CALL(pasta_wait_for_ns, c);
 	if (c->pasta_netns_fd < 0)
-- 
@@ -197,8 +197,7 @@ static int pasta_spawn_cmd(void *arg)
 	a = (const struct pasta_spawn_cmd_arg *)arg;
 	execvp(a->exe, a->argv);
 
-	perror("execvp");
-	exit(EXIT_FAILURE);
+	die_perror("Failed to start command or shell");
 }
 
 /**
@@ -261,10 +260,8 @@ void pasta_start_ns(struct ctx *c, uid_t uid, gid_t gid,
 				   CLONE_NEWUTS | CLONE_NEWNS  | SIGCHLD,
 				   (void *)&arg);
 
-	if (pasta_child_pid == -1) {
-		perror("clone");
-		exit(EXIT_FAILURE);
-	}
+	if (pasta_child_pid == -1)
+		die_perror("Failed to clone process with detached namespaces");
 
 	NS_CALL(pasta_wait_for_ns, c);
 	if (c->pasta_netns_fd < 0)
-- 
2.43.0

[PATCH v5 7/9] treewide: Replace strerror() calls

[Stefano Brivio]

Now that we have logging functions embedding perror() functionality,
we can make _some_ calls more terse by using them. In many places,
the strerror() calls are still more convenient because, for example,
they are used in flow debugging functions, or because the return code
variable of interest is not 'errno'.

While at it, convert a few error messages from a scant perror style
to proper failure descriptions.

Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
---
 conf.c      |  6 +++---
 fwd.c       |  2 +-
 isolation.c | 28 +++++++++++-----------------
 log.c       |  2 +-
 netlink.c   |  4 ++--
 passt.c     | 12 ++++--------
 pasta.c     | 18 ++++++++----------
 pcap.c      |  8 +++-----
 tap.c       | 14 +++++++-------
 tcp.c       | 24 ++++++++----------------
 util.c      | 12 +++++-------
 11 files changed, 53 insertions(+), 77 deletions(-)

diff --git a/conf.c b/conf.c
index b8247c4..09bf6dd 100644
--- a/conf.c
+++ b/conf.c
@@ -461,7 +461,7 @@ static void get_dns(struct ctx *c)
 	}
 
 	if (line_len < 0)
-		warn("Error reading /etc/resolv.conf: %s", strerror(errno));
+		warn_perror("Error reading /etc/resolv.conf");
 	close(fd);
 
 out:
@@ -626,6 +626,7 @@ static unsigned int conf_ip4(unsigned int ifi,
 		int rc = nl_link_get_mac(nl_sock, ifi, mac);
 		if (rc < 0) {
 			char ifname[IFNAMSIZ];
+
 			err("Couldn't discover MAC address for %s: %s",
 			    if_indextoname(ifi, ifname), strerror(-rc));
 			return 0;
@@ -1549,8 +1550,7 @@ void conf(struct ctx *c, int argc, char **argv)
 				die("Redundant interface: %s", optarg);
 
 			if (!(ifi4 = ifi6 = if_nametoindex(optarg)))
-				die("Invalid interface name %s: %s", optarg,
-				    strerror(errno));
+				die_perror("Invalid interface name %s", optarg);
 			break;
 		case 'o':
 			if (IN6_IS_ADDR_UNSPECIFIED(&c->ip6.addr_out)	  &&
diff --git a/fwd.c b/fwd.c
index b3d5a37..d3f1798 100644
--- a/fwd.c
+++ b/fwd.c
@@ -52,7 +52,7 @@ static void procfs_scan_listen(int fd, unsigned int lstate,
 		return;
 
 	if (lseek(fd, 0, SEEK_SET)) {
-		warn("lseek() failed on /proc/net file: %s", strerror(errno));
+		warn_perror("lseek() failed on /proc/net file");
 		return;
 	}
 
diff --git a/isolation.c b/isolation.c
index c936674..4956d7e 100644
--- a/isolation.c
+++ b/isolation.c
@@ -105,7 +105,7 @@ static void drop_caps_ep_except(uint64_t keep)
 	int i;
 
 	if (syscall(SYS_capget, &hdr, data))
-		die("Couldn't get current capabilities: %s", strerror(errno));
+		die_perror("Couldn't get current capabilities");
 
 	for (i = 0; i < CAP_WORDS; i++) {
 		uint32_t mask = keep >> (32 * i);
@@ -115,7 +115,7 @@ static void drop_caps_ep_except(uint64_t keep)
 	}
 
 	if (syscall(SYS_capset, &hdr, data))
-		die("Couldn't drop capabilities: %s", strerror(errno));
+		die_perror("Couldn't drop capabilities");
 }
 
 /**
@@ -152,19 +152,17 @@ static void clamp_caps(void)
 		 */
 		if (prctl(PR_CAPBSET_DROP, i, 0, 0, 0) &&
 		    errno != EINVAL && errno != EPERM)
-			die("Couldn't drop cap %i from bounding set: %s",
-			    i, strerror(errno));
+			die_perror("Couldn't drop cap %i from bounding set", i);
 	}
 
 	if (syscall(SYS_capget, &hdr, data))
-		die("Couldn't get current capabilities: %s", strerror(errno));
+		die_perror("Couldn't get current capabilities");
 
 	for (i = 0; i < CAP_WORDS; i++)
 		data[i].inheritable = 0;
 
 	if (syscall(SYS_capset, &hdr, data))
-		die("Couldn't drop inheritable capabilities: %s",
-		    strerror(errno));
+		die_perror("Couldn't drop inheritable capabilities");
 }
 
 /**
@@ -234,34 +232,30 @@ void isolate_user(uid_t uid, gid_t gid, bool use_userns, const char *userns,
 	if (setgroups(0, NULL)) {
 		/* If we don't have CAP_SETGID, this will EPERM */
 		if (errno != EPERM)
-			die("Can't drop supplementary groups: %s",
-			    strerror(errno));
+			die_perror("Can't drop supplementary groups");
 	}
 
 	if (setgid(gid) != 0)
-		die("Can't set GID to %u: %s", gid, strerror(errno));
+		die_perror("Can't set GID to %u", gid);
 
 	if (setuid(uid) != 0)
-		die("Can't set UID to %u: %s", uid, strerror(errno));
+		die_perror("Can't set UID to %u", uid);
 
 	if (*userns) { /* If given a userns, join it */
 		int ufd;
 
 		ufd = open(userns, O_RDONLY | O_CLOEXEC);
 		if (ufd < 0)
-			die("Couldn't open user namespace %s: %s",
-			    userns, strerror(errno));
+			die_perror("Couldn't open user namespace %s", userns);
 
 		if (setns(ufd, CLONE_NEWUSER) != 0)
-			die("Couldn't enter user namespace %s: %s",
-			    userns, strerror(errno));
+			die_perror("Couldn't enter user namespace %s", userns);
 
 		close(ufd);
 
 	} else if (use_userns) { /* Create and join a new userns */
 		if (unshare(CLONE_NEWUSER) != 0)
-			die("Couldn't create user namespace: %s",
-			    strerror(errno));
+			die_perror("Couldn't create user namespace");
 	}
 
 	/* Joining a new userns gives us full capabilities; drop the
diff --git a/log.c b/log.c
index 528ee51..a72b871 100644
--- a/log.c
+++ b/log.c
@@ -212,7 +212,7 @@ void logfile_init(const char *name, const char *path, size_t size)
 	log_file = open(path, O_CREAT | O_TRUNC | O_APPEND | O_RDWR | O_CLOEXEC,
 			S_IRUSR | S_IWUSR);
 	if (log_file == -1)
-		die("Couldn't open log file %s: %s", path, strerror(errno));
+		die_perror("Couldn't open log file %s", path);
 
 	log_size = size ? size : LOGFILE_SIZE_DEFAULT;
 
diff --git a/netlink.c b/netlink.c
index c082991..093de26 100644
--- a/netlink.c
+++ b/netlink.c
@@ -133,7 +133,7 @@ static uint32_t nl_send(int s, void *req, uint16_t type,
 
 	n = send(s, req, len, 0);
 	if (n < 0)
-		die("netlink: Failed to send(): %s", strerror(errno));
+		die_perror("netlink: Failed to send()");
 	else if (n < len)
 		die("netlink: Short send (%zd of %zd bytes)", n, len);
 
@@ -189,7 +189,7 @@ static struct nlmsghdr *nl_next(int s, char *buf, struct nlmsghdr *nh, ssize_t *
 
 	*n = recv(s, buf, NLBUFSIZ, 0);
 	if (*n < 0)
-		die("netlink: Failed to recv(): %s", strerror(errno));
+		die_perror("netlink: Failed to recv()");
 
 	nh = (struct nlmsghdr *)buf;
 	if (!NLMSG_OK(nh, *n))
diff --git a/passt.c b/passt.c
index a48c5f6..13f3eb6 100644
--- a/passt.c
+++ b/passt.c
@@ -227,15 +227,11 @@ int main(int argc, char **argv)
 		__openlog("pasta", 0, LOG_DAEMON);
 
 		sa.sa_handler = pasta_child_handler;
-		if (sigaction(SIGCHLD, &sa, NULL)) {
-			die("Couldn't install signal handlers: %s",
-			    strerror(errno));
-		}
+		if (sigaction(SIGCHLD, &sa, NULL))
+			die_perror("Couldn't install signal handlers");
 
-		if (signal(SIGPIPE, SIG_IGN) == SIG_ERR) {
-			die("Couldn't set disposition for SIGPIPE: %s",
-			    strerror(errno));
-		}
+		if (signal(SIGPIPE, SIG_IGN) == SIG_ERR)
+			die_perror("Couldn't set disposition for SIGPIPE");
 
 		c.mode = MODE_PASTA;
 	} else if (strstr(name, "passt")) {
diff --git a/pasta.c b/pasta.c
index d08391f..084288c 100644
--- a/pasta.c
+++ b/pasta.c
@@ -138,17 +138,15 @@ void pasta_open_ns(struct ctx *c, const char *netns)
 	int nfd = -1;
 
 	nfd = open(netns, O_RDONLY | O_CLOEXEC);
-	if (nfd < 0) {
-		die("Couldn't open network namespace %s: %s",
-		    netns, strerror(errno));
-	}
+	if (nfd < 0)
+		die_perror("Couldn't open network namespace %s", netns);
 
 	c->pasta_netns_fd = nfd;
 
 	NS_CALL(ns_check, c);
 
 	if (c->pasta_netns_fd < 0)
-		die("Couldn't switch to pasta namespaces: %s", strerror(errno));
+		die_perror("Couldn't switch to pasta namespaces");
 
 	if (!c->no_netns_quit) {
 		char buf[PATH_MAX] = { 0 };
@@ -184,7 +182,7 @@ static int pasta_spawn_cmd(void *arg)
 
 	/* We run in a detached PID and mount namespace: mount /proc over */
 	if (mount("", "/proc", "proc", 0, NULL))
-		warn("Couldn't mount /proc: %s", strerror(errno));
+		warn_perror("Couldn't mount /proc");
 
 	if (write_file("/proc/sys/net/ipv4/ping_group_range", "0 0"))
 		warn("Cannot set ping_group_range, ICMP requests might fail");
@@ -265,7 +263,7 @@ void pasta_start_ns(struct ctx *c, uid_t uid, gid_t gid,
 
 	NS_CALL(pasta_wait_for_ns, c);
 	if (c->pasta_netns_fd < 0)
-		die("Failed to join network namespace: %s", strerror(errno));
+		die_perror("Failed to join network namespace");
 }
 
 /**
@@ -369,12 +367,12 @@ static int pasta_netns_quit_timer(void)
 	struct itimerspec it = { { 1, 0 }, { 1, 0 } }; /* one-second interval */
 
 	if (fd == -1) {
-		err("timerfd_create(): %s", strerror(errno));
+		err_perror("Failed to create timerfd for quit timer");
 		return -errno;
 	}
 
 	if (timerfd_settime(fd, 0, &it, NULL) < 0) {
-		err("timerfd_settime(): %s", strerror(errno));
+		err_perror("Failed to set interval for quit timer");
 		close(fd);
 		return -errno;
 	}
@@ -467,7 +465,7 @@ void pasta_netns_quit_timer_handler(struct ctx *c, union epoll_ref ref)
 
 	n = read(ref.fd, &expirations, sizeof(expirations));
 	if (n < 0)
-		die("Namespace watch timer read() error: %s", strerror(errno));
+		die_perror("Namespace watch timer read() error");
 	if ((size_t)n < sizeof(expirations))
 		warn("Namespace watch timer: short read(): %zi", n);
 
diff --git a/pcap.c b/pcap.c
index 507be2a..46cc4b0 100644
--- a/pcap.c
+++ b/pcap.c
@@ -89,10 +89,8 @@ static void pcap_frame(const struct iovec *iov, size_t iovcnt,
 	struct iovec hiov = { &h, sizeof(h) };
 
 	if (write_remainder(pcap_fd, &hiov, 1, 0) < 0 ||
-	    write_remainder(pcap_fd, iov, iovcnt, offset) < 0) {
-		debug("Cannot log packet, length %zu: %s",
-		      l2len, strerror(errno));
-	}
+	    write_remainder(pcap_fd, iov, iovcnt, offset) < 0)
+		debug_perror("Cannot log packet, length %zu", l2len);
 }
 
 /**
@@ -178,5 +176,5 @@ void pcap_init(struct ctx *c)
 	info("Saving packet capture to %s", c->pcap);
 
 	if (write(pcap_fd, &pcap_hdr, sizeof(pcap_hdr)) < 0)
-		warn("Cannot write PCAP header: %s", strerror(errno));
+		warn_perror("Cannot write PCAP header");
 }
diff --git a/tap.c b/tap.c
index c9aeff1..ec994a2 100644
--- a/tap.c
+++ b/tap.c
@@ -325,7 +325,7 @@ static size_t tap_send_frames_pasta(const struct ctx *c,
 		size_t framelen = iov_size(iov + i, bufs_per_frame);
 
 		if (rc < 0) {
-			debug("tap write: %s", strerror(errno));
+			debug_perror("tap write");
 
 			switch (errno) {
 			case EAGAIN:
@@ -387,7 +387,7 @@ static size_t tap_send_frames_passt(const struct ctx *c,
 		size_t rembufs = bufs_per_frame - (i % bufs_per_frame);
 
 		if (write_remainder(c->fd_tap, &iov[i], rembufs, buf_offset) < 0) {
-			err("tap: partial frame send: %s", strerror(errno));
+			err_perror("tap: partial frame send");
 			return i;
 		}
 		i += rembufs;
@@ -1122,7 +1122,7 @@ int tap_sock_unix_open(char *sock_path)
 	int i;
 
 	if (fd < 0)
-		die("UNIX socket: %s", strerror(errno));
+		die_perror("Failed to open UNIX domain socket");
 
 	for (i = 1; i < UNIX_SOCK_MAX; i++) {
 		char *path = addr.sun_path;
@@ -1135,7 +1135,7 @@ int tap_sock_unix_open(char *sock_path)
 
 		ex = socket(AF_UNIX, SOCK_STREAM | SOCK_NONBLOCK, 0);
 		if (ex < 0)
-			die("UNIX domain socket check: %s", strerror(errno));
+			die_perror("Failed to check for UNIX domain conflicts");
 
 		ret = connect(ex, (const struct sockaddr *)&addr, sizeof(addr));
 		if (!ret || (errno != ENOENT && errno != ECONNREFUSED &&
@@ -1155,7 +1155,7 @@ int tap_sock_unix_open(char *sock_path)
 	}
 
 	if (i == UNIX_SOCK_MAX)
-		die("UNIX socket bind: %s", strerror(errno));
+		die_perror("Failed to bind UNIX domain socket");
 
 	info("UNIX domain socket bound at %s", addr.sun_path);
 	if (!*sock_path)
@@ -1261,11 +1261,11 @@ static int tap_ns_tun(void *arg)
 
 	fd = open("/dev/net/tun", flags);
 	if (fd < 0)
-		die("Failed to open() /dev/net/tun: %s", strerror(errno));
+		die_perror("Failed to open() /dev/net/tun");
 
 	rc = ioctl(fd, TUNSETIFF, &ifr);
 	if (rc < 0)
-		die("TUNSETIFF failed: %s", strerror(errno));
+		die_perror("TUNSETIFF ioctl on /dev/net/tun failed");
 
 	if (!(c->pasta_ifi = if_nametoindex(c->pasta_ifn)))
 		die("Tap device opened but no network interface found");
diff --git a/tcp.c b/tcp.c
index a2e81d5..698e7ec 100644
--- a/tcp.c
+++ b/tcp.c
@@ -1553,19 +1553,15 @@ static void tcp_bind_outbound(const struct ctx *c, int s, sa_family_t af)
 				.sin_addr = c->ip4.addr_out,
 			};
 
-			if (bind(s, (struct sockaddr *)&addr4, sizeof(addr4))) {
-				debug("Can't bind IPv4 TCP socket address: %s",
-				      strerror(errno));
-			}
+			if (bind(s, (struct sockaddr *)&addr4, sizeof(addr4)))
+				debug_perror("IPv4 TCP socket address bind");
 		}
 
 		if (*c->ip4.ifname_out) {
 			if (setsockopt(s, SOL_SOCKET, SO_BINDTODEVICE,
 				       c->ip4.ifname_out,
-				       strlen(c->ip4.ifname_out))) {
-				debug("Can't bind IPv4 TCP socket to interface:"
-				      " %s", strerror(errno));
-			}
+				       strlen(c->ip4.ifname_out)))
+				debug_perror("IPv4 TCP socket interface bind");
 		}
 	} else if (af == AF_INET6) {
 		if (!IN6_IS_ADDR_UNSPECIFIED(&c->ip6.addr_out)) {
@@ -1575,19 +1571,15 @@ static void tcp_bind_outbound(const struct ctx *c, int s, sa_family_t af)
 				.sin6_addr = c->ip6.addr_out,
 			};
 
-			if (bind(s, (struct sockaddr *)&addr6, sizeof(addr6))) {
-				debug("Can't bind IPv6 TCP socket address: %s",
-				      strerror(errno));
-			}
+			if (bind(s, (struct sockaddr *)&addr6, sizeof(addr6)))
+				debug_perror("IPv6 TCP socket address bind");
 		}
 
 		if (*c->ip6.ifname_out) {
 			if (setsockopt(s, SOL_SOCKET, SO_BINDTODEVICE,
 				       c->ip6.ifname_out,
-				       strlen(c->ip6.ifname_out))) {
-				debug("Can't bind IPv6 TCP socket to interface:"
-				      " %s", strerror(errno));
-			}
+				       strlen(c->ip6.ifname_out)))
+				debug_perror("IPv6 TCP socket interface bind");
 		}
 	}
 }
diff --git a/util.c b/util.c
index 77448ec..dd2e57f 100644
--- a/util.c
+++ b/util.c
@@ -315,7 +315,7 @@ void bitmap_or(uint8_t *dst, size_t size, const uint8_t *a, const uint8_t *b)
 void ns_enter(const struct ctx *c)
 {
 	if (setns(c->pasta_netns_fd, CLONE_NEWNET))
-		die("setns() failed entering netns: %s", strerror(errno));
+		die_perror("setns() failed entering netns");
 }
 
 /**
@@ -330,10 +330,8 @@ bool ns_is_init(void)
 	bool ret = true;
 	int fd;
 
-	if ((fd = open("/proc/self/uid_map", O_RDONLY | O_CLOEXEC)) < 0) {
-		die("Can't determine if we're in init namespace: %s",
-		    strerror(errno));
-	}
+	if ((fd = open("/proc/self/uid_map", O_RDONLY | O_CLOEXEC)) < 0)
+		die_perror("Can't determine if we're in init namespace");
 
 	if (read(fd, buf, sizeof(root_uid_map)) != sizeof(root_uid_map) - 1 ||
 	    strncmp(buf, root_uid_map, sizeof(root_uid_map)))
@@ -509,7 +507,7 @@ int write_file(const char *path, const char *buf)
 	size_t len = strlen(buf);
 
 	if (fd < 0) {
-		warn("Could not open %s: %s", path, strerror(errno));
+		warn_perror("Could not open %s", path);
 		return -1;
 	}
 
@@ -517,7 +515,7 @@ int write_file(const char *path, const char *buf)
 		ssize_t rc = write(fd, buf, len);
 
 		if (rc <= 0) {
-			warn("Couldn't write to %s: %s", path, strerror(errno));
+			warn_perror("Couldn't write to %s", path);
 			break;
 		}
 
-- 
@@ -315,7 +315,7 @@ void bitmap_or(uint8_t *dst, size_t size, const uint8_t *a, const uint8_t *b)
 void ns_enter(const struct ctx *c)
 {
 	if (setns(c->pasta_netns_fd, CLONE_NEWNET))
-		die("setns() failed entering netns: %s", strerror(errno));
+		die_perror("setns() failed entering netns");
 }
 
 /**
@@ -330,10 +330,8 @@ bool ns_is_init(void)
 	bool ret = true;
 	int fd;
 
-	if ((fd = open("/proc/self/uid_map", O_RDONLY | O_CLOEXEC)) < 0) {
-		die("Can't determine if we're in init namespace: %s",
-		    strerror(errno));
-	}
+	if ((fd = open("/proc/self/uid_map", O_RDONLY | O_CLOEXEC)) < 0)
+		die_perror("Can't determine if we're in init namespace");
 
 	if (read(fd, buf, sizeof(root_uid_map)) != sizeof(root_uid_map) - 1 ||
 	    strncmp(buf, root_uid_map, sizeof(root_uid_map)))
@@ -509,7 +507,7 @@ int write_file(const char *path, const char *buf)
 	size_t len = strlen(buf);
 
 	if (fd < 0) {
-		warn("Could not open %s: %s", path, strerror(errno));
+		warn_perror("Could not open %s", path);
 		return -1;
 	}
 
@@ -517,7 +515,7 @@ int write_file(const char *path, const char *buf)
 		ssize_t rc = write(fd, buf, len);
 
 		if (rc <= 0) {
-			warn("Couldn't write to %s: %s", path, strerror(errno));
+			warn_perror("Couldn't write to %s", path);
 			break;
 		}
 
-- 
2.43.0

[PATCH v5 8/9] conf, passt: Don't call __openlog() if a log file is used

[Stefano Brivio]

If a log file is configured, we would otherwise open a connection to
the system logger (if any), print any message that we might have
before we initialise the log file, and then keep that connection
around for no particular reason.

Call __openlog() as an alternative to the log file setup, instead.

This way, we might skip printing some messages during the
initialisation phase, but they're probably not really valuable to
have in a system log, and we're going to print them to standard
error anyway.

Suggested-by: David Gibson <david@gibson.dropbear.id.au>
Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
---
 conf.c  | 9 +++++----
 passt.c | 4 ----
 2 files changed, 5 insertions(+), 8 deletions(-)

diff --git a/conf.c b/conf.c
index 09bf6dd..5a4f559 100644
--- a/conf.c
+++ b/conf.c
@@ -1220,6 +1220,7 @@ void conf(struct ctx *c, int argc, char **argv)
 		{"no-copy-addrs", no_argument,		NULL,		19 },
 		{ 0 },
 	};
+	const char *logname = (c->mode == MODE_PASTA) ? "pasta" : "passt";
 	char userns[PATH_MAX] = { 0 }, netns[PATH_MAX] = { 0 };
 	bool copy_addrs_opt = false, copy_routes_opt = false;
 	struct in6_addr *dns6 = c->ip6.dns, dns6_tmp;
@@ -1680,10 +1681,10 @@ void conf(struct ctx *c, int argc, char **argv)
 
 	conf_ugid(runas, &uid, &gid);
 
-	if (logfile) {
-		logfile_init(c->mode == MODE_PASTA ? "pasta" : "passt",
-			     logfile, logsize);
-	}
+	if (logfile)
+		logfile_init(logname, logfile, logsize);
+	else
+		__openlog(logname, 0, LOG_DAEMON);
 
 	if (c->debug)
 		__setlogmask(LOG_UPTO(LOG_DEBUG));
diff --git a/passt.c b/passt.c
index 13f3eb6..e4d45da 100644
--- a/passt.c
+++ b/passt.c
@@ -224,8 +224,6 @@ int main(int argc, char **argv)
 	strncpy(argv0, argv[0], PATH_MAX - 1);
 	name = basename(argv0);
 	if (strstr(name, "pasta")) {
-		__openlog("pasta", 0, LOG_DAEMON);
-
 		sa.sa_handler = pasta_child_handler;
 		if (sigaction(SIGCHLD, &sa, NULL))
 			die_perror("Couldn't install signal handlers");
@@ -235,8 +233,6 @@ int main(int argc, char **argv)
 
 		c.mode = MODE_PASTA;
 	} else if (strstr(name, "passt")) {
-		__openlog("passt", 0, LOG_DAEMON);
-
 		c.mode = MODE_PASST;
 	} else {
 		exit(EXIT_FAILURE);
-- 
@@ -224,8 +224,6 @@ int main(int argc, char **argv)
 	strncpy(argv0, argv[0], PATH_MAX - 1);
 	name = basename(argv0);
 	if (strstr(name, "pasta")) {
-		__openlog("pasta", 0, LOG_DAEMON);
-
 		sa.sa_handler = pasta_child_handler;
 		if (sigaction(SIGCHLD, &sa, NULL))
 			die_perror("Couldn't install signal handlers");
@@ -235,8 +233,6 @@ int main(int argc, char **argv)
 
 		c.mode = MODE_PASTA;
 	} else if (strstr(name, "passt")) {
-		__openlog("passt", 0, LOG_DAEMON);
-
 		c.mode = MODE_PASST;
 	} else {
 		exit(EXIT_FAILURE);
-- 
2.43.0

[PATCH v5 9/9] log: Don't report syslog failures to stderr after initialisation

[Stefano Brivio]

If we daemonised, we can't use standard error. If we didn't, it's
rather annoying to have all those messages on standard error anyway,
and kind of pointless too, as the messages we wanted to print were
printed to standard error anyway.

Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
---
 log.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/log.c b/log.c
index a72b871..9ed6bc1 100644
--- a/log.c
+++ b/log.c
@@ -191,7 +191,7 @@ void passt_vsyslog(int pri, const char *format, va_list ap)
 	if (format[strlen(format)] != '\n')
 		n += snprintf(buf + n, BUFSIZ - n, "\n");
 
-	if (log_sock >= 0 && send(log_sock, buf, n, 0) != n)
+	if (log_sock >= 0 && send(log_sock, buf, n, 0) != n && !log_runtime)
 		fprintf(stderr, "Failed to send %i bytes to syslog\n", n);
 }
 
-- 
@@ -191,7 +191,7 @@ void passt_vsyslog(int pri, const char *format, va_list ap)
 	if (format[strlen(format)] != '\n')
 		n += snprintf(buf + n, BUFSIZ - n, "\n");
 
-	if (log_sock >= 0 && send(log_sock, buf, n, 0) != n)
+	if (log_sock >= 0 && send(log_sock, buf, n, 0) != n && !log_runtime)
 		fprintf(stderr, "Failed to send %i bytes to syslog\n", n);
 }
 
-- 
2.43.0

Re: [PATCH v5 9/9] log: Don't report syslog failures to stderr after initialisation

[David Gibson]

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

On Thu, Jun 20, 2024 at 06:15:18PM +0200, Stefano Brivio wrote:
> If we daemonised, we can't use standard error. If we didn't, it's
> rather annoying to have all those messages on standard error anyway,
> and kind of pointless too, as the messages we wanted to print were
> printed to standard error anyway.
> 
> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>

Reviewed-by: David Gibson <david@gibson.dropbear.id.au>

> ---
>  log.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/log.c b/log.c
> index a72b871..9ed6bc1 100644
> --- a/log.c
> +++ b/log.c
> @@ -191,7 +191,7 @@ void passt_vsyslog(int pri, const char *format, va_list ap)
>  	if (format[strlen(format)] != '\n')
>  		n += snprintf(buf + n, BUFSIZ - n, "\n");
>  
> -	if (log_sock >= 0 && send(log_sock, buf, n, 0) != n)
> +	if (log_sock >= 0 && send(log_sock, buf, n, 0) != n && !log_runtime)
>  		fprintf(stderr, "Failed to send %i bytes to syslog\n", n);
>  }
>  

-- 
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 v5 0/9] Fixes for early logging/prints and related cleanups

[David Gibson]

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

On Thu, Jun 20, 2024 at 06:15:09PM +0200, Stefano Brivio wrote:
> The most apparent issue fixed by this series is the one from 4/6: with
> a log file configured, we wouldn't print to standard error anymore,
> during initialisation, which means that users such as libvirt lost
> the ability to report meaningful error messages that occurred during
> initialisation, in that case.
> 
> v5:
> - in 4/8, rename the new flag once more to 'log_runtime': we don't
>   want to log to standard error if we're running in foreground, a
>   log file is given, and initialisation is done, otherwise debugging
>   pasta when it spawns its own shell becomes rather impractical

Ah.. right.  See, I still think the semantics of always printing to
stderr when foreground make more sense, but I guess I do see the point
that having pasta messages appear in your pasta-spawned shell is ugly.

My preferred approach for that would to keep the basic semantics that
we always log to stderr when foreground, but when we're spawning a
pasta shell we default to 'quiet' log level.  That way if you really
do want messages to stderr along with your shell/command (which I
sometimes do), you can get that by using --debug or whatever.

Regardless of that quibble, though, the semantics are substantially
saner with this series than without so I'm happy to go ahead with it.

> - add 9/8, taking care of a direct stderr print left-over
> 
> v4:
> - in 4/8, name the new flag 'log_daemonised' instead of
>   'log_daemon_ready'
> 
> v3:
> - add 2/8: we don't really need --stderr anymore
> - in 5/8, save errno at the beginning of the _perror() helper
> - in 7/8, avoid assigning errno to whatever return code we have just
>   for the sake of using the new helpers: strerror() is actually less
>   convoluted than that
> - add 8/8: there's no need to call __openlog() with a log file
> 
> v2:
> - turn flag bitmap into simple, separate boolean flags
> - move errno description after message in _perror() functions
> - make some of the old perror() messages more descriptive
> *** BLURB HERE ***
> 
> Stefano Brivio (9):
>   conf, passt: Don't try to log to stderr after we close it
>   conf, passt: Make --stderr do nothing, and deprecate it
>   conf, log: Instead of abusing log levels, add log_conf_parsed flag
>   log, passt: Always print to stderr before initialisation is complete
>   log: Add _perror() logging function variants
>   treewide: Replace perror() calls with calls to logging functions
>   treewide: Replace strerror() calls
>   conf, passt: Don't call __openlog() if a log file is used
>   log: Don't report syslog failures to stderr after initialisation
> 
>  arch.c      | 10 ++++-----
>  conf.c      | 41 ++++++++++++---------------------
>  fwd.c       |  2 +-
>  isolation.c | 46 ++++++++++++++++---------------------
>  log.c       | 65 ++++++++++++++++++++++++++++++++---------------------
>  log.h       | 25 +++++++++++++++++----
>  netlink.c   |  4 ++--
>  passt.1     |  9 ++++----
>  passt.c     | 64 +++++++++++++++++++---------------------------------
>  passt.h     |  2 --
>  pasta.c     | 27 +++++++++-------------
>  pcap.c      |  8 +++----
>  tap.c       | 14 ++++++------
>  tcp.c       | 24 +++++++-------------
>  util.c      | 12 +++++-----
>  15 files changed, 164 insertions(+), 189 deletions(-)
> 

-- 
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 v5 0/9] Fixes for early logging/prints and related cleanups

[Stefano Brivio]

On Fri, 21 Jun 2024 11:17:34 +1000
David Gibson <david@gibson.dropbear.id.au> wrote:

> On Thu, Jun 20, 2024 at 06:15:09PM +0200, Stefano Brivio wrote:
> > The most apparent issue fixed by this series is the one from 4/6: with
> > a log file configured, we wouldn't print to standard error anymore,
> > during initialisation, which means that users such as libvirt lost
> > the ability to report meaningful error messages that occurred during
> > initialisation, in that case.
> > 
> > v5:
> > - in 4/8, rename the new flag once more to 'log_runtime': we don't
> >   want to log to standard error if we're running in foreground, a
> >   log file is given, and initialisation is done, otherwise debugging
> >   pasta when it spawns its own shell becomes rather impractical  
> 
> Ah.. right.  See, I still think the semantics of always printing to
> stderr when foreground make more sense, but I guess I do see the point
> that having pasta messages appear in your pasta-spawned shell is ugly.
> 
> My preferred approach for that would to keep the basic semantics that
> we always log to stderr when foreground, but when we're spawning a
> pasta shell we default to 'quiet' log level.  That way if you really
> do want messages to stderr along with your shell/command (which I
> sometimes do), you can get that by using --debug or whatever.

That's already the default, see pasta_start_ns():

	if (!c->debug)
		c->quiet = 1;

the problem is that if you want to debug something, and use a pasta
shell (which is the most indicated way to debug something in most
cases, I would say), you would usually pass --debug and a log file.

Before and after this series (v5, but not v4), if you pass a log file,
that debug output stays in the log file.

If you don't give a log file, debug information will printed to stderr
as usual.

-- 
Stefano

Re: [PATCH v5 0/9] Fixes for early logging/prints and related cleanups

[David Gibson]

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

On Fri, Jun 21, 2024 at 11:33:55AM +0200, Stefano Brivio wrote:
> On Fri, 21 Jun 2024 11:17:34 +1000
> David Gibson <david@gibson.dropbear.id.au> wrote:
> 
> > On Thu, Jun 20, 2024 at 06:15:09PM +0200, Stefano Brivio wrote:
> > > The most apparent issue fixed by this series is the one from 4/6: with
> > > a log file configured, we wouldn't print to standard error anymore,
> > > during initialisation, which means that users such as libvirt lost
> > > the ability to report meaningful error messages that occurred during
> > > initialisation, in that case.
> > > 
> > > v5:
> > > - in 4/8, rename the new flag once more to 'log_runtime': we don't
> > >   want to log to standard error if we're running in foreground, a
> > >   log file is given, and initialisation is done, otherwise debugging
> > >   pasta when it spawns its own shell becomes rather impractical  
> > 
> > Ah.. right.  See, I still think the semantics of always printing to
> > stderr when foreground make more sense, but I guess I do see the point
> > that having pasta messages appear in your pasta-spawned shell is ugly.
> > 
> > My preferred approach for that would to keep the basic semantics that
> > we always log to stderr when foreground, but when we're spawning a
> > pasta shell we default to 'quiet' log level.  That way if you really
> > do want messages to stderr along with your shell/command (which I
> > sometimes do), you can get that by using --debug or whatever.
> 
> That's already the default, see pasta_start_ns():
> 
> 	if (!c->debug)
> 		c->quiet = 1;
> 
> the problem is that if you want to debug something, and use a pasta
> shell (which is the most indicated way to debug something in most
> cases, I would say), you would usually pass --debug and a log file.

Oh... good point.

> Before and after this series (v5, but not v4), if you pass a log file,
> that debug output stays in the log file.
> 
> If you don't give a log file, debug information will printed to stderr
> as usual.

I understand the choice in the short term, but this still doesn't feel
quite right to me.

I'm wondering if we should treat spawning a a pasta command as though
we're going into the background.  It's not in the Unix technical
sense, but it is going to the background in the loose sense that pasta
is no longer the thing that the user is primarily looking at on this
terminal.

But then, it would be nice to have a way to force output to stderr
even with a pasta command - I find that pretty useful when debugging a
specific problem, particularly when using a specific command rather
than a shell.  Maybe we could allow "-l -" or "-l stderr" or something
with a special meaning?

-- 
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 v5 0/9] Fixes for early logging/prints and related cleanups

[Stefano Brivio]

On Mon, 24 Jun 2024 15:32:20 +1000
David Gibson <david@gibson.dropbear.id.au> wrote:

> On Fri, Jun 21, 2024 at 11:33:55AM +0200, Stefano Brivio wrote:
> > On Fri, 21 Jun 2024 11:17:34 +1000
> > David Gibson <david@gibson.dropbear.id.au> wrote:
> >   
> > > On Thu, Jun 20, 2024 at 06:15:09PM +0200, Stefano Brivio wrote:  
> > > > The most apparent issue fixed by this series is the one from 4/6: with
> > > > a log file configured, we wouldn't print to standard error anymore,
> > > > during initialisation, which means that users such as libvirt lost
> > > > the ability to report meaningful error messages that occurred during
> > > > initialisation, in that case.
> > > > 
> > > > v5:
> > > > - in 4/8, rename the new flag once more to 'log_runtime': we don't
> > > >   want to log to standard error if we're running in foreground, a
> > > >   log file is given, and initialisation is done, otherwise debugging
> > > >   pasta when it spawns its own shell becomes rather impractical    
> > > 
> > > Ah.. right.  See, I still think the semantics of always printing to
> > > stderr when foreground make more sense, but I guess I do see the point
> > > that having pasta messages appear in your pasta-spawned shell is ugly.
> > > 
> > > My preferred approach for that would to keep the basic semantics that
> > > we always log to stderr when foreground, but when we're spawning a
> > > pasta shell we default to 'quiet' log level.  That way if you really
> > > do want messages to stderr along with your shell/command (which I
> > > sometimes do), you can get that by using --debug or whatever.  
> > 
> > That's already the default, see pasta_start_ns():
> > 
> > 	if (!c->debug)
> > 		c->quiet = 1;
> > 
> > the problem is that if you want to debug something, and use a pasta
> > shell (which is the most indicated way to debug something in most
> > cases, I would say), you would usually pass --debug and a log file.  
> 
> Oh... good point.
> 
> > Before and after this series (v5, but not v4), if you pass a log file,
> > that debug output stays in the log file.
> > 
> > If you don't give a log file, debug information will printed to stderr
> > as usual.  
> 
> I understand the choice in the short term, but this still doesn't feel
> quite right to me.
> 
> I'm wondering if we should treat spawning a a pasta command as though
> we're going into the background.  It's not in the Unix technical
> sense, but it is going to the background in the loose sense that pasta
> is no longer the thing that the user is primarily looking at on this
> terminal.
> 
> But then, it would be nice to have a way to force output to stderr
> even with a pasta command - I find that pretty useful when debugging a
> specific problem, particularly when using a specific command rather
> than a shell.  Maybe we could allow "-l -" or "-l stderr" or something
> with a special meaning?

But that's already the case if you give --debug (or --trace) but no log
file, isn't that enough?

-- 
Stefano

Re: [PATCH v5 0/9] Fixes for early logging/prints and related cleanups

[David Gibson]

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

On Mon, Jun 24, 2024 at 11:45:32AM +0200, Stefano Brivio wrote:
> On Mon, 24 Jun 2024 15:32:20 +1000
> David Gibson <david@gibson.dropbear.id.au> wrote:
> 
> > On Fri, Jun 21, 2024 at 11:33:55AM +0200, Stefano Brivio wrote:
> > > On Fri, 21 Jun 2024 11:17:34 +1000
> > > David Gibson <david@gibson.dropbear.id.au> wrote:
> > >   
> > > > On Thu, Jun 20, 2024 at 06:15:09PM +0200, Stefano Brivio wrote:  
> > > > > The most apparent issue fixed by this series is the one from 4/6: with
> > > > > a log file configured, we wouldn't print to standard error anymore,
> > > > > during initialisation, which means that users such as libvirt lost
> > > > > the ability to report meaningful error messages that occurred during
> > > > > initialisation, in that case.
> > > > > 
> > > > > v5:
> > > > > - in 4/8, rename the new flag once more to 'log_runtime': we don't
> > > > >   want to log to standard error if we're running in foreground, a
> > > > >   log file is given, and initialisation is done, otherwise debugging
> > > > >   pasta when it spawns its own shell becomes rather impractical    
> > > > 
> > > > Ah.. right.  See, I still think the semantics of always printing to
> > > > stderr when foreground make more sense, but I guess I do see the point
> > > > that having pasta messages appear in your pasta-spawned shell is ugly.
> > > > 
> > > > My preferred approach for that would to keep the basic semantics that
> > > > we always log to stderr when foreground, but when we're spawning a
> > > > pasta shell we default to 'quiet' log level.  That way if you really
> > > > do want messages to stderr along with your shell/command (which I
> > > > sometimes do), you can get that by using --debug or whatever.  
> > > 
> > > That's already the default, see pasta_start_ns():
> > > 
> > > 	if (!c->debug)
> > > 		c->quiet = 1;
> > > 
> > > the problem is that if you want to debug something, and use a pasta
> > > shell (which is the most indicated way to debug something in most
> > > cases, I would say), you would usually pass --debug and a log file.  
> > 
> > Oh... good point.
> > 
> > > Before and after this series (v5, but not v4), if you pass a log file,
> > > that debug output stays in the log file.
> > > 
> > > If you don't give a log file, debug information will printed to stderr
> > > as usual.  
> > 
> > I understand the choice in the short term, but this still doesn't feel
> > quite right to me.
> > 
> > I'm wondering if we should treat spawning a a pasta command as though
> > we're going into the background.  It's not in the Unix technical
> > sense, but it is going to the background in the loose sense that pasta
> > is no longer the thing that the user is primarily looking at on this
> > terminal.
> > 
> > But then, it would be nice to have a way to force output to stderr
> > even with a pasta command - I find that pretty useful when debugging a
> > specific problem, particularly when using a specific command rather
> > than a shell.  Maybe we could allow "-l -" or "-l stderr" or something
> > with a special meaning?
> 
> But that's already the case if you give --debug (or --trace) but no log
> file, isn't that enough?

It's the case now, but wouldn't be if we treated spawning a pasta
shell like going into the background, although that approach seems
more sensible to to me in other ways.

Eh, I can't quickly see a better way than what you have now, so never
mind.

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