On Mon, Jun 17, 2024 at 02:03:16PM +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. Then, set LOG_PERROR only as we set this internal
> flag, to make sure we don't duplicate messages.
> 
> Reported-by: Yalan Zhang <yalzhang@redhat.com>
> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
> ---
>  log.c   |  4 +++-
>  log.h   |  1 +
>  passt.1 |  3 ++-
>  passt.c | 17 ++++++++++-------
>  4 files changed, 16 insertions(+), 9 deletions(-)
> 
> diff --git a/log.c b/log.c
> index 3b5a1c6..939bb93 100644
> --- a/log.c
> +++ b/log.c
> @@ -49,6 +49,7 @@ int		log_trace;		/* --trace mode enabled */
>  void vlogmsg(int pri, const char *format, va_list ap)
>  {
>  	bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1;
> +	bool before_daemon = !(log_flags & LOG_FLAG_DAEMON_READY);

As in 2/6 would just a global bool be simpler than flags.

>  	bool early_print = !(log_flags & LOG_FLAG_CONF_PARSED);
>  	struct timespec tp;
>  
> @@ -71,7 +72,8 @@ 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 || early_print ||
> +	    (before_daemon && (log_mask & LOG_MASK(LOG_PRI(pri))))) {
>  		(void)vfprintf(stderr, format, ap);
>  		if (format[strlen(format)] != '\n')
>  			fprintf(stderr, "\n");
> diff --git a/log.h b/log.h
> index 6a3224a..680baab 100644
> --- a/log.h
> +++ b/log.h
> @@ -10,6 +10,7 @@
>  #include <syslog.h>
>  
>  #define LOG_FLAG_CONF_PARSED	BIT(0)	/* We already parsed logging options */
> +#define LOG_FLAG_DAEMON_READY	BIT(1)	/* Daemonised, or ready in foreground */
>  
>  #define LOGFILE_SIZE_DEFAULT		(1024 * 1024UL)
>  #define LOGFILE_CUT_RATIO		30	/* When full, cut ~30% size */
> diff --git a/passt.1 b/passt.1
> index 3a23a43..31e528e 100644
> --- a/passt.1
> +++ b/passt.1
> @@ -99,7 +99,8 @@ terminal, and to both system logger and standard error otherwise.
>  
>  .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, not to standard error (once initialisation is complete),
> +and not to the system logger.

IIUC when -l is set we'll log to the logfile _as well as_ stderr
before we daemonize.  The description above doesn't exactly contradict
that, but seems to imply something different.

>  .TP
>  .BR \-\-log-size " " \fISIZE\fR
> diff --git a/passt.c b/passt.c
> index aa9648a..fa86164 100644
> --- a/passt.c
> +++ b/passt.c
> @@ -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(log_name = "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(log_name = "passt", 0, LOG_DAEMON);
>  
>  		c.mode = MODE_PASST;
>  	} else {
> @@ -302,13 +302,16 @@ 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))))
> -		__openlog(log_name, 0, LOG_DAEMON);
> -
> -	if (!c.foreground)
> +	if (!c.foreground) {
>  		__daemon(c.pidfile_fd, devnull_fd);
> -	else
> +	} else {
> +		if (c.force_stderr || isatty(fileno(stderr)))
> +			__openlog(log_name, LOG_PERROR, LOG_DAEMON);
> +
>  		pidfile_write(c.pidfile_fd, getpid());
> +	}
> +
> +	log_set_flag(LOG_FLAG_DAEMON_READY);
>  
>  	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