passt/log.h, branch 2025_06_11.0293c6f

log: Don't export passt_vsyslog()

2025-03-07T01:21:24+00:00

passt_vsyslog() is an exposed function in log.h.  However it shouldn't
be called from outside log.c: it writes specifically to the system log,
and most code should call passt's logging helpers which might go to the
syslog or to a log file.

Make passt_vsyslog() local to log.c.  This requires a code motion to avoid
a forward declaration.

Signed-off-by: David Gibson 
Signed-off-by: Stefano Brivio

treewide: use _exit() over exit()

2025-02-05T14:19:02+00:00

In the podman CI I noticed many seccomp denials in our logs even though
tests passed:
comm="pasta.avx2" exe="/usr/bin/pasta.avx2" sig=31 arch=c000003e
syscall=202 compat=0 ip=0x7fb3d31f69db code=0x80000000

Which is futex being called and blocked by the pasta profile. After a
few tries I managed to reproduce locally with this loop in ~20 min:
while :;
  do podman run -d --network bridge quay.io/libpod/testimage:20241011 \
	sleep 100 && \
  sleep 10 && \
  podman rm -fa -t0
done

And using a pasta version with prctl(PR_SET_DUMPABLE, 1); set I got the
following stack trace:
Stack trace of thread 1:
  #0  0x00007fc95e6de91b __lll_lock_wait_private (libc.so.6 + 0x9491b)
  #1  0x00007fc95e68d6de __run_exit_handlers (libc.so.6 + 0x436de)
  #2  0x00007fc95e68d70e exit (libc.so.6 + 0x4370e)
  #3  0x000055f31b78c50b n/a (n/a + 0x0)
  #4  0x00007fc95e68d70e exit (libc.so.6 + 0x4370e)
  #5  0x000055f31b78d5a2 n/a (n/a + 0x0)

Pasta got killed in exit(), it seems glibc is trying to use a lock when
running exit handlers even though no exit handlers are defined.

Given no exit handlers are needed we can call _exit() instead. This
skips exit handlers and does not flush stdio streams compared to exit()
which should be fine for the use here.

Based on the input from Stefano I did not change the test/doc programs
or qrap as they do not use seccomp filters.

Signed-off-by: Paul Holzinger 
Signed-off-by: Stefano Brivio

log: Don't prefix message with timestamp on --debug if it's a continuation

2024-08-12T14:21:53+00:00

If we prefix the second part of messages printed through
logmsg_perror() by the timestamp, on debug, we'll have two timestamps
and a weird separator in the result, such as this beauty:

  0.0013: Failed to clone process with detached namespaces0.0013: : Operation not permitted

Add a parameter to logmsg() and vlogmsg() which indicates a message
continuation. If that's set, don't print the timestamp in vlogmsg().

Link: https://github.com/moby/moby/issues/48257#issuecomment-2282875092
Signed-off-by: Stefano Brivio 
Reviewed-by: David Gibson

log, passt: Keep printing to stderr when passt is running in foreground

2024-08-06T13:03:48+00:00

There are two cases where we want to stop printing to stderr: if it's
closed, and if pasta spawned a shell (and --debug wasn't given).

But if passt is running in foreground, we currently stop to report any
message, even error messages, once we're ready, as reported by
Laurent, because we set the log_runtime flag, which we use to indicate
we're ready, regardless of whether we're running in foreground or not.

Turn that flag (back) to log_stderr, and set it only when we really
want to stop printing to stderr.

Reported-by: Laurent Vivier 
Fixes: afd9cdc9bb48 ("log, passt: Always print to stderr before initialisation is complete")
Signed-off-by: Stefano Brivio

log: Make logfile_write() private

2024-08-05T13:03:33+00:00

logfile_write() is not used outside log.c, nor should it be.  It should
only be used externall via the general logging functions.  Make it static
in log.c.  To avoid forward declarations this requires moving a bunch of
functions earlier in the file.

Signed-off-by: David Gibson 
Signed-off-by: Stefano Brivio

log: Initialise timestamp for relative log time also if we use a log file

2024-07-26T11:47:34+00:00

...not just for debug messages. Otherwise, timestamps in the log file
are consistent but the starting point is not zero.

Do this right away as we enter main(), so that the resulting
timestamps are as closely as possible relative to when we start.

Signed-off-by: Stefano Brivio 
Reviewed-by: David Gibson

log: Drop newlines in the middle of the perror()-like messages

2024-07-25T10:25:31+00:00

Calling vlogmsg() twice from logmsg_perror() results in this beauty:

  $ ./pasta -i foo
  Invalid interface name foo
  : No such device

because the first part of the message, corresponding to the first
call, doesn't end with a newline, and vlogmsg() adds it.

Given that we can't easily append an argument (error description) to
a variadic list, add a 'newline' parameter to all the functions that
currently add a newline if missing, and disable that on the first call
to vlogmsg() from logmsg_perror(). Not very pretty but I can't think
of any solution that's less messy than this.

Signed-off-by: Stefano Brivio 
Reviewed-by: David Gibson

log: Add _perror() logging function variants

2024-06-21T13:32:40+00:00

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 
Reviewed-by: David Gibson

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

2024-06-21T13:32:34+00:00

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 
Signed-off-by: Stefano Brivio 
Reviewed-by: David Gibson

conf, log: Instead of abusing log levels, add log_conf_parsed flag

2024-06-21T13:32:31+00:00

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 
Reviewed-by: David Gibson