[PATCH] passt, log: Call __openlog() earlier, log to stderr until we detach

[PATCH] passt, log: Call __openlog() earlier, log to stderr until we detach

[Stefano Brivio]

Paul reports that, with commit 15001b39ef1d ("conf: set the log level
much earlier"), early messages aren't reported to standard error
anymore.

The reason is that, once the log mask is changed from LOG_EARLY, we
don't force logging to stderr, and this mechanism was abused to have
early errors on stderr. Now that we drop LOG_EARLY earlier on, this
doesn't work anymore.

Call __openlog() as soon as we know the mode we're running as, using
LOG_PERROR. Then, once we detach, if we're not running from an
interactive terminal and logging to standard error is not forced,
drop LOG_PERROR from the options.

While at it, make sure we don't print messages to standard error
reporting that we couldn't log to the system logger, if we didn't
open a connection yet. That's expected.

Reported-by: Paul Holzinger <pholzing@redhat.com>
Fixes: 15001b39ef1d ("conf: set the log level much earlier")
Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
---
 log.c   |  2 +-
 passt.c | 14 +++++++-------
 2 files changed, 8 insertions(+), 8 deletions(-)

diff --git a/log.c b/log.c
index eafaca2..bdd31b4 100644
--- a/log.c
+++ b/log.c
@@ -174,7 +174,7 @@ void passt_vsyslog(int pri, const char *format, va_list ap)
 	if (log_opt & LOG_PERROR)
 		fprintf(stderr, "%s", buf + prefix_len);
 
-	if (send(log_sock, buf, n, 0) != n)
+	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/passt.c b/passt.c
index f430648..e4cb11e 100644
--- a/passt.c
+++ b/passt.c
@@ -225,6 +225,8 @@ 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);
+
 		sa.sa_handler = pasta_child_handler;
 		if (sigaction(SIGCHLD, &sa, NULL)) {
 			die("Couldn't install signal handlers: %s",
@@ -237,18 +239,16 @@ int main(int argc, char **argv)
 		}
 
 		c.mode = MODE_PASTA;
-		log_name = "pasta";
 	} else if (strstr(name, "passt")) {
+		__openlog(log_name = "passt", LOG_PERROR, LOG_DAEMON);
+
 		c.mode = MODE_PASST;
-		log_name = "passt";
 	} else {
 		exit(EXIT_FAILURE);
 	}
 
 	madvise(pkt_buf, TAP_BUF_BYTES, MADV_HUGEPAGE);
 
-	__openlog(log_name, 0, LOG_DAEMON);
-
 	c.epollfd = epoll_create1(EPOLL_CLOEXEC);
 	if (c.epollfd == -1) {
 		perror("epoll_create1");
@@ -269,9 +269,6 @@ int main(int argc, char **argv)
 	conf(&c, argc, argv);
 	trace_init(c.trace);
 
-	if (c.force_stderr || isatty(fileno(stdout)))
-		__openlog(log_name, LOG_PERROR, LOG_DAEMON);
-
 	pasta_netns_quit_init(&c);
 
 	tap_sock_init(&c);
@@ -314,6 +311,9 @@ int main(int argc, char **argv)
 	if (isolate_prefork(&c))
 		die("Failed to sandbox process, exiting");
 
+	if (!c.force_stderr && !isatty(fileno(stdout)))
+		__openlog(log_name, 0, LOG_DAEMON);
+
 	if (!c.foreground)
 		__daemon(pidfile_fd, devnull_fd);
 	else
-- 
@@ -225,6 +225,8 @@ 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);
+
 		sa.sa_handler = pasta_child_handler;
 		if (sigaction(SIGCHLD, &sa, NULL)) {
 			die("Couldn't install signal handlers: %s",
@@ -237,18 +239,16 @@ int main(int argc, char **argv)
 		}
 
 		c.mode = MODE_PASTA;
-		log_name = "pasta";
 	} else if (strstr(name, "passt")) {
+		__openlog(log_name = "passt", LOG_PERROR, LOG_DAEMON);
+
 		c.mode = MODE_PASST;
-		log_name = "passt";
 	} else {
 		exit(EXIT_FAILURE);
 	}
 
 	madvise(pkt_buf, TAP_BUF_BYTES, MADV_HUGEPAGE);
 
-	__openlog(log_name, 0, LOG_DAEMON);
-
 	c.epollfd = epoll_create1(EPOLL_CLOEXEC);
 	if (c.epollfd == -1) {
 		perror("epoll_create1");
@@ -269,9 +269,6 @@ int main(int argc, char **argv)
 	conf(&c, argc, argv);
 	trace_init(c.trace);
 
-	if (c.force_stderr || isatty(fileno(stdout)))
-		__openlog(log_name, LOG_PERROR, LOG_DAEMON);
-
 	pasta_netns_quit_init(&c);
 
 	tap_sock_init(&c);
@@ -314,6 +311,9 @@ int main(int argc, char **argv)
 	if (isolate_prefork(&c))
 		die("Failed to sandbox process, exiting");
 
+	if (!c.force_stderr && !isatty(fileno(stdout)))
+		__openlog(log_name, 0, LOG_DAEMON);
+
 	if (!c.foreground)
 		__daemon(pidfile_fd, devnull_fd);
 	else
-- 
2.39.2

Re: [PATCH] passt, log: Call __openlog() earlier, log to stderr until we detach

[Paul Holzinger]

Thanks for the quick patch.

On 12/03/2024 23:34, Stefano Brivio wrote:
> Paul reports that, with commit 15001b39ef1d ("conf: set the log level
> much earlier"), early messages aren't reported to standard error
> anymore.
>
> The reason is that, once the log mask is changed from LOG_EARLY, we
> don't force logging to stderr, and this mechanism was abused to have
> early errors on stderr. Now that we drop LOG_EARLY earlier on, this
> doesn't work anymore.
>
> Call __openlog() as soon as we know the mode we're running as, using
> LOG_PERROR. Then, once we detach, if we're not running from an
> interactive terminal and logging to standard error is not forced,
> drop LOG_PERROR from the options.
>
> While at it, make sure we don't print messages to standard error
> reporting that we couldn't log to the system logger, if we didn't
> open a connection yet. That's expected.
>
> Reported-by: Paul Holzinger <pholzing@redhat.com>
> Fixes: 15001b39ef1d ("conf: set the log level much earlier")
> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
Tested-by: Paul Holzinger <pholzing@redhat.com>
> ---
>   log.c   |  2 +-
>   passt.c | 14 +++++++-------
>   2 files changed, 8 insertions(+), 8 deletions(-)
>
> diff --git a/log.c b/log.c
> index eafaca2..bdd31b4 100644
> --- a/log.c
> +++ b/log.c
> @@ -174,7 +174,7 @@ void passt_vsyslog(int pri, const char *format, va_list ap)
>   	if (log_opt & LOG_PERROR)
>   		fprintf(stderr, "%s", buf + prefix_len);
>   
> -	if (send(log_sock, buf, n, 0) != n)
> +	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/passt.c b/passt.c
> index f430648..e4cb11e 100644
> --- a/passt.c
> +++ b/passt.c
> @@ -225,6 +225,8 @@ 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);
> +
>   		sa.sa_handler = pasta_child_handler;
>   		if (sigaction(SIGCHLD, &sa, NULL)) {
>   			die("Couldn't install signal handlers: %s",
> @@ -237,18 +239,16 @@ int main(int argc, char **argv)
>   		}
>   
>   		c.mode = MODE_PASTA;
> -		log_name = "pasta";
>   	} else if (strstr(name, "passt")) {
> +		__openlog(log_name = "passt", LOG_PERROR, LOG_DAEMON);
> +
>   		c.mode = MODE_PASST;
> -		log_name = "passt";
>   	} else {
>   		exit(EXIT_FAILURE);
>   	}
>   
>   	madvise(pkt_buf, TAP_BUF_BYTES, MADV_HUGEPAGE);
>   
> -	__openlog(log_name, 0, LOG_DAEMON);
> -
>   	c.epollfd = epoll_create1(EPOLL_CLOEXEC);
>   	if (c.epollfd == -1) {
>   		perror("epoll_create1");
> @@ -269,9 +269,6 @@ int main(int argc, char **argv)
>   	conf(&c, argc, argv);
>   	trace_init(c.trace);
>   
> -	if (c.force_stderr || isatty(fileno(stdout)))
> -		__openlog(log_name, LOG_PERROR, LOG_DAEMON);
> -
>   	pasta_netns_quit_init(&c);
>   
>   	tap_sock_init(&c);
> @@ -314,6 +311,9 @@ int main(int argc, char **argv)
>   	if (isolate_prefork(&c))
>   		die("Failed to sandbox process, exiting");
>   
> +	if (!c.force_stderr && !isatty(fileno(stdout)))
I still have the feeling this should check the stderr fd instead of 
stdout as it is logging to stderr. But I guess it shouldn't make a big 
difference in real situations so not a big deal.
> +		__openlog(log_name, 0, LOG_DAEMON);
> +
>   	if (!c.foreground)
>   		__daemon(pidfile_fd, devnull_fd);
>   	else

Re: [PATCH] passt, log: Call __openlog() earlier, log to stderr until we detach

[Stefano Brivio]

On Wed, 13 Mar 2024 11:23:56 +0100
Paul Holzinger <pholzing@redhat.com> wrote:

> Thanks for the quick patch.
> 
> On 12/03/2024 23:34, Stefano Brivio wrote:
> > Paul reports that, with commit 15001b39ef1d ("conf: set the log level
> > much earlier"), early messages aren't reported to standard error
> > anymore.
> >
> > The reason is that, once the log mask is changed from LOG_EARLY, we
> > don't force logging to stderr, and this mechanism was abused to have
> > early errors on stderr. Now that we drop LOG_EARLY earlier on, this
> > doesn't work anymore.
> >
> > Call __openlog() as soon as we know the mode we're running as, using
> > LOG_PERROR. Then, once we detach, if we're not running from an
> > interactive terminal and logging to standard error is not forced,
> > drop LOG_PERROR from the options.
> >
> > While at it, make sure we don't print messages to standard error
> > reporting that we couldn't log to the system logger, if we didn't
> > open a connection yet. That's expected.
> >
> > Reported-by: Paul Holzinger <pholzing@redhat.com>
> > Fixes: 15001b39ef1d ("conf: set the log level much earlier")
> > Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
>
> Tested-by: Paul Holzinger <pholzing@redhat.com>

And thanks for the quick test.

> > ---
> >   log.c   |  2 +-
> >   passt.c | 14 +++++++-------
> >   2 files changed, 8 insertions(+), 8 deletions(-)
> >
> > diff --git a/log.c b/log.c
> > index eafaca2..bdd31b4 100644
> > --- a/log.c
> > +++ b/log.c
> > @@ -174,7 +174,7 @@ void passt_vsyslog(int pri, const char *format, va_list ap)
> >   	if (log_opt & LOG_PERROR)
> >   		fprintf(stderr, "%s", buf + prefix_len);
> >   
> > -	if (send(log_sock, buf, n, 0) != n)
> > +	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/passt.c b/passt.c
> > index f430648..e4cb11e 100644
> > --- a/passt.c
> > +++ b/passt.c
> > @@ -225,6 +225,8 @@ 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);
> > +
> >   		sa.sa_handler = pasta_child_handler;
> >   		if (sigaction(SIGCHLD, &sa, NULL)) {
> >   			die("Couldn't install signal handlers: %s",
> > @@ -237,18 +239,16 @@ int main(int argc, char **argv)
> >   		}
> >   
> >   		c.mode = MODE_PASTA;
> > -		log_name = "pasta";
> >   	} else if (strstr(name, "passt")) {
> > +		__openlog(log_name = "passt", LOG_PERROR, LOG_DAEMON);
> > +
> >   		c.mode = MODE_PASST;
> > -		log_name = "passt";
> >   	} else {
> >   		exit(EXIT_FAILURE);
> >   	}
> >   
> >   	madvise(pkt_buf, TAP_BUF_BYTES, MADV_HUGEPAGE);
> >   
> > -	__openlog(log_name, 0, LOG_DAEMON);
> > -
> >   	c.epollfd = epoll_create1(EPOLL_CLOEXEC);
> >   	if (c.epollfd == -1) {
> >   		perror("epoll_create1");
> > @@ -269,9 +269,6 @@ int main(int argc, char **argv)
> >   	conf(&c, argc, argv);
> >   	trace_init(c.trace);
> >   
> > -	if (c.force_stderr || isatty(fileno(stdout)))
> > -		__openlog(log_name, LOG_PERROR, LOG_DAEMON);
> > -
> >   	pasta_netns_quit_init(&c);
> >   
> >   	tap_sock_init(&c);
> > @@ -314,6 +311,9 @@ int main(int argc, char **argv)
> >   	if (isolate_prefork(&c))
> >   		die("Failed to sandbox process, exiting");
> >   
> > +	if (!c.force_stderr && !isatty(fileno(stdout)))
>
> I still have the feeling this should check the stderr fd instead of 
> stdout as it is logging to stderr. But I guess it shouldn't make a big 
> difference in real situations so not a big deal.

Now that you mention this, I'm quite undecided: true, we're checking if
we want to print to standard error, but what we want to check here is
if we're running from an interactive terminal, for which testing if
stdout is a terminal is quite idiomatic.

On the other hand:

$ cat isatty.c
#include <stdio.h>
#include <unistd.h>

int main()
{
    return isatty(fileno(stdout));
}
$ gcc -o isatty isatty.c 
$ ./isatty >/dev/null; echo $?
0
$ ./isatty 2>/dev/null; echo $?
1

so we would (fail to) print to stderr if it's redirected to /dev/null,
but not print to stderr if stdout is redirected.

At this point I would have a slight preference toward changing it like
you suggested.

-- 
Stefano