On Wed, Jun 19, 2024 at 09:40:24PM +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>

Overall a good simplification, a couple of minor nits

> ---
>  log.c   | 17 ++++++++---------
>  log.h   |  1 +
>  passt.c | 15 +++++++--------
>  3 files changed, 16 insertions(+), 17 deletions(-)
> 
> diff --git a/log.c b/log.c
> index 05b7f80..7018bda 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_daemon_ready;	/* Daemonised, standard error is gone */

I find the name 'log_daemon_ready' kind of confusing (why would the
log daemon not be ready?).  Maybe "log_daemonised", or
"log_background"?

>  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_daemon_ready && (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..1d6dd1d 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_daemon_ready;
>  
>  void trace_init(int enable);
>  #define trace(...)							\
> diff --git a/passt.c b/passt.c
> index 19ecd68..c5538bd 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);

Nice to be rid of those assignments-in-parameters.

>  
>  		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,13 +302,12 @@ 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)
> +	if (!c.foreground) {
>  		__daemon(c.pidfile_fd, devnull_fd);
> -	else
> +		log_daemon_ready = true;
> +	} else {
>  		pidfile_write(c.pidfile_fd, getpid());
> +	}
>  
>  	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