log, passt: Always print to stderr before initialisation is complete

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>

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 {
@@ -303,13 +303,12 @@ int main(int argc, char **argv)
 		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);