aboutgitcodebugslistschat
path: root/log.c
Commit message (Collapse)AuthorAgeFilesLines
* log: Don't prefix message with timestamp on --debug if it's a continuationStefano Brivio2024-08-121-6/+8
| | | | | | | | | | | | | | | 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 <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* log: Avoid duplicate calls to logtime()David Gibson2024-08-071-9/+8
| | | | | | | | | | | | | | | | | We use logtime() to get a timestamp for the log in two places: - in vlogmsg(), which is used only for debug_print messages - in logfile_write() which is only used messages to the log file These cases are mutually exclusive, so we don't ever print the same message with different timestamps, but that's not particularly obvious to see. It's possible future tweaks to logging logic could mean we log to two different places with different timestamps, which would be confusing. Refactor to have a single logtime() call in vlogmsg() and use it for all the places we need it. Signed-off-by: David Gibson <david@gibson.dropbear.id.au> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* log: Handle errors from clock_gettime()David Gibson2024-08-071-15/+32
| | | | | | | | | | | | | | | | | | clock_gettime() can, theoretically, fail, although it probably won't until 2038 on old 32-bit systems. Still, it's possible someone could run with a wildly out of sync clock, or new errors could be added, or it could fail due to a bug in libc or the kernel. We don't handle this well. In the debug_print case in vlogmsg we'll just ignore the failure, and print a timestamp based on uninitialised garbage. In logfile_write() we exit early and won't log anything at all, which seems like a good way to make an already weird situation undebuggable. Add some helpers to instead handle this by using "<error>" in place of a timestamp if something goes wrong with clock_gettime(). Signed-off-by: David Gibson <david@gibson.dropbear.id.au> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* log: Correct formatting of timestampsDavid Gibson2024-08-071-12/+24
| | | | | | | | | | | | | | | | | logtime_fmt_and_arg() is a rather odd macro, producing both a format string and an argument, which can only be used in quite specific printf() like formulations. It also has a significant bug: it tries to display 4 digits after the decimal point (so down to tenths of milliseconds) using %04i. But the field width in printf() is always a *minimum* not maximum field width, so this will not truncate the given value, but will redisplay the entire tenth-of-milliseconds difference again after the decimal point. Replace the macro with an snprintf() like function which will format the timestamp, and use an explicit % to correct the display. Signed-off-by: David Gibson <david@gibson.dropbear.id.au> [sbrivio: Make logtime_fmt() static] Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* log, passt: Keep printing to stderr when passt is running in foreground2024_08_06.ee36266Stefano Brivio2024-08-061-3/+3
| | | | | | | | | | | | | | | | | 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 <lvivier@redhat.com> Fixes: afd9cdc9bb48 ("log, passt: Always print to stderr before initialisation is complete") Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* log: Make logfile_write() privateDavid Gibson2024-08-051-170/+171
| | | | | | | | | | 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 <david@gibson.dropbear.id.au> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* log: Fetch log times with CLOCK_MONOTONIC, not CLOCK_REALTIMEStefano Brivio2024-07-261-2/+2
| | | | | | | | | We report relative timestamps in logs, so we want to avoid jumps in the system time. Suggested-by: David Gibson <david@gibson.dropbear.id.au> Signed-off-by: Stefano Brivio <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* log: Initialise timestamp for relative log time also if we use a log fileStefano Brivio2024-07-261-3/+1
| | | | | | | | | | | ...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 <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* log, util: Fix sub-second part in relative log time calculationStefano Brivio2024-07-261-20/+22
| | | | | | | | | | | | | | | | | | For some reason, in commit 01efc71ddd25 ("log, conf: Add support for logging to file"), I added calculations for relative logging timestamps using the difference for the seconds part only, not for accounting for the fractional part. Fix that by storing the initial timestamp, log_start, as a timespec struct, and by calculating the difference from the starting time. Do this in a macro as we need the same format in a few places. To calculate the difference, turn the existing timespec_diff_ms() to microseconds, timespec_diff_us(), and rewrite timespec_diff_ms() to use that. Signed-off-by: Stefano Brivio <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* log: Drop newlines in the middle of the perror()-like messagesStefano Brivio2024-07-251-12/+22
| | | | | | | | | | | | | | | | | | | | 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 <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* log: Don't report syslog failures to stderr after initialisationStefano Brivio2024-06-211-1/+1
| | | | | | | | | If we daemonised, we can't use standard error. If we didn't, it's rather annoying to have all those messages on standard error anyway, and kind of pointless too, as the messages we wanted to print were printed to standard error anyway. Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* treewide: Replace strerror() callsStefano Brivio2024-06-211-1/+1
| | | | | | | | | | | | | | Now that we have logging functions embedding perror() functionality, we can make _some_ calls more terse by using them. In many places, the strerror() calls are still more convenient because, for example, they are used in flow debugging functions, or because the return code variable of interest is not 'errno'. While at it, convert a few error messages from a scant perror style to proper failure descriptions. Signed-off-by: Stefano Brivio <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* treewide: Replace perror() calls with calls to logging functionsStefano Brivio2024-06-211-8/+4
| | | | | | | | | | | | perror() prints directly to standard error, but in many cases standard error might be already closed, or we might want to skip logging, based on configuration. Our logging functions provide all that. While at it, make errors more descriptive, replacing some of the existing basic perror-style messages. Signed-off-by: Stefano Brivio <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* log: Add _perror() logging function variantsStefano Brivio2024-06-211-0/+22
| | | | | | | | | | | | 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 <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* log, passt: Always print to stderr before initialisation is completeStefano Brivio2024-06-211-9/+8
| | | | | | | | | | | | | | | | | | | | | | | | | | 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>
* conf, log: Instead of abusing log levels, add log_conf_parsed flagStefano Brivio2024-06-211-7/+5
| | | | | | | | | | | | | | | | | | 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 <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* log: Remove log_to_stdout optionDavid Gibson2024-06-051-5/+3
| | | | | | | | Now that we've simplified how usage() works, nothing ever sets the log_to_stdout flag. Eliminate it. Signed-off-by: David Gibson <david@gibson.dropbear.id.au> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* treewide: Compilers' name for armv6l and armv7l is "arm"Stefano Brivio2024-04-111-2/+2
| | | | | | | | | | | | | | When I switched from 'uname -m' to 'gcc -dumpmachine' to fetch the architecture name for, among others, seccomp.sh, I didn't realise that "armv6l" and "armv7l" are just Linux kernel names -- compilers just call that "arm". Fix the "syscalls" annotation we use to define seccomp profiles accordingly, otherwise pasta will be terminated on sigreturn() on armv6l and armv7l. Fixes: 213c397492bd ("passt, pasta: Run-time selection of AVX2 build") Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* passt, log: Call __openlog() earlier, log to stderr until we detachStefano Brivio2024-03-141-1/+1
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | 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, check if the standard error descriptor refers to a terminal, instead of checking standard output: if the user redirects standard output to /dev/null, they might still want to see messages from standard error. Further, 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> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* log: setlogmask(0) can actually result in a system call, don't use itStefano Brivio2024-02-141-8/+10
| | | | | | | | | | | | | | | | | | | | Before commit 32d07f5e59f2 ("passt, pasta: Completely avoid dynamic memory allocation"), we didn't store the current log mask in a variable, and we fetched it using setlogmask(0) wherever needed. But after that commit, we can use our log_mask copy instead. And we should: with recent glibc versions, setlogmask(0) actually results in a system call, which causes a substantial overhead with high transfer rates: we use setlogmask(0) even to decide we don't want to print debug messages. Now that we rely on log_mask in early stages, before setlogmask() is called, we need to initialise that variable to the special LOG_EMERG mask value right away: define LOG_EARLY to make this clearer, and, while at it, group conditions in vlogmsg() into something more terse. Signed-off-by: Stefano Brivio <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* treewide: Standardise on 'now' for current timestamp variablesDavid Gibson2024-01-221-17/+17
| | | | | | | | | In a number of places we pass around a struct timespec representing the (more or less) current time. Sometimes we call it 'now', and sometimes we call it 'ts'. Standardise on the more informative 'now'. Signed-off-by: David Gibson <david@gibson.dropbear.id.au> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* treewide: Make a bunch of pointer variables pointers to constDavid Gibson2024-01-161-2/+4
| | | | | | | | | | Sufficiently recent cppcheck (I'm using 2.13.0) seems to have added another warning for pointer variables which could be pointer to const but aren't. Use this to make a bunch of variables const pointers where they previously weren't for no particular reason. Signed-off-by: David Gibson <david@gibson.dropbear.id.au> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* log: Match implicit va_start() with va_end() in vlogmsg()Stefano Brivio2023-11-071-0/+2
| | | | | | | | | | | | | | | | According to C99, 7.15.1: Each invocation of the va_start and va_copy macros shall be matched by a corresponding invocation of the va_end macro in the same function and the same applies to C11. I still have to come across a platform where va_end() actually does something, but thus spake the standard. This would be reported by Coverity as "Missing varargs init or cleanup" (CWE-573). Fixes: c0426ff10bc9 ("log: Add vlogmsg()") Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* log: Add vlogmsg()David Gibson2023-11-071-9/+16
| | | | | | | | | | | Currently logmsg() is only available as a variadic function. This is fine for normal use, but is awkward if we ever want to write wrappers around it which (for example) add standardised prefix information. To allow that, add a vlogmsg() function which takes a va_list instead, and implement logmsg() in terms of it. Signed-off-by: David Gibson <david@gibson.dropbear.id.au> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* log: Don't define logging function 4 timesDavid Gibson2023-11-071-35/+30
| | | | | | | | | | | | | | | | In log.c we use a macro to define logging functions for each of 4 priority levels. The only difference between these is the priority we pass to vsyslog() and similar functions. Because it's done as a macro, however, the entire functions code is included in the binary 4 times. Rearrange this to take the priority level as a parameter to a regular function, then just use macros to define trivial wrappers which pass the priority level. This saves about 600 bytes of text in the executable (x86, non-AVX2). Signed-off-by: David Gibson <david@gibson.dropbear.id.au> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* cppcheck: Make many pointers constDavid Gibson2023-10-041-3/+3
| | | | | | | | | Newer versions of cppcheck (as of 2.12.0, at least) added a warning for pointers which could be declared to point at const data, but aren't. Based on that, make many pointers throughout the codebase const. Signed-off-by: David Gibson <david@gibson.dropbear.id.au> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* conf, log: On -h / --help, print usage to stdout, not stderrStefano Brivio2023-06-231-3/+5
| | | | | | | | | | | | | | Erik suggests that this makes it easier to grep for options, and with --help we're anyway printing usage information as expected, not as part of an error report. While at it: on -h, we should exit with 0. Reported-by: Erik Sjölund <erik.sjolund@gmail.com> Link: https://bugs.passt.top/show_bug.cgi?id=52 Link: https://bugs.passt.top/show_bug.cgi?id=53 Signed-off-by: Stefano Brivio <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* passt: Relicense to GPL 2.0, or any later versionStefano Brivio2023-04-061-1/+1
| | | | | | | | | | | | | | | | | | | In practical terms, passt doesn't benefit from the additional protection offered by the AGPL over the GPL, because it's not suitable to be executed over a computer network. Further, restricting the distribution under the version 3 of the GPL wouldn't provide any practical advantage either, as long as the passt codebase is concerned, and might cause unnecessary compatibility dilemmas. Change licensing terms to the GNU General Public License Version 2, or any later version, with written permission from all current and past contributors, namely: myself, David Gibson, Laine Stump, Andrea Bolognani, Paul Holzinger, Richard W.M. Jones, Chris Kuhn, Florian Weimer, Giuseppe Scrivano, Stefan Hajnoczi, and Vasiliy Ulyanov. Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* log: Avoid time_t/__syscall_slong_t format mismatch with long int on X32 ABIStefano Brivio2023-03-171-10/+12
| | | | | | | | | | | | | | | | | On X32 (ILP32 using AMD64 system call ABI) and glibc, struct timespec::tv_nsec is __syscall_slong_t and not a long int, see also https://sourceware.org/bugzilla/show_bug.cgi?id=16437 and timespec(3type). Fine, we could cast that down to long and be done with it. But it turns out that also time_t (not guaranteed to be equivalent to any type) is a long long int, and there we can't downcast. To keep it simple, cast both to long long int, and change formats to %lli, to avoid format warnings from gcc. Signed-off-by: Stefano Brivio <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* log, conf, tap: Define die() as err() plus exit(), drop cppcheck workaroundsStefano Brivio2023-02-271-9/+5
| | | | | | | | | | | If we define die() as a variadic macro, passing __VA_ARGS__ to err(), and calling exit() outside err() itself, we can drop the workarounds introduced in commit 36f0199f6ef4 ("conf, tap: Silence two false positive invalidFunctionArg from cppcheck"). Suggested-by: David Gibson <david@gibson.dropbear.id.au> Signed-off-by: Stefano Brivio <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* log: Send identifier string in log messages, openlog() won't work for usStefano Brivio2023-02-271-7/+5
| | | | | | | | | | | | | | | | | openlog() can be used to set "ident" and have all the log messages prefixed by it, but only if we call syslog() -- this is implemented by C libraries. We don't log messages with syslog(), though, as we have a custom implementation to ensure we don't need dynamic memory allocation. This means that it's perfectly useless to call openlog(), and that we have to prefix every message we log by the identifier on our own. Reported-by: Andrea Bolognani <abologna@redhat.com> Signed-off-by: Stefano Brivio <sbrivio@redhat.com> Tested-by: Andrea Bolognani <abologna@redhat.com> Reviewed-by: Andrea Bolognani <abologna@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* log: Don't duplicate messages on stderr before daemonisingStefano Brivio2023-02-161-3/+4
| | | | | | | | | | | | | | | | | | | Now that logging functions force printing messages to stderr before passt forks to background, we'll have duplicate messages when running from an interactive terminal, or if --stderr is passed, because at some point we set LOG_PERROR in our __openlog() wrapper. We could defer setting LOG_PERROR, but that would change option semantics in other, unexpected ways. We could force calling passt_vsyslog() as long as the mask is set to LOG_EMERG, but that complicates the logic in logging functions even further. Go the easy way for now: don't force printing to stderr with LOG_EMERG if LOG_PERROR is already set. We should seriously consider a rework of those logging functions at this point. Signed-off-by: Stefano Brivio <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* convert all remaining err() followed by exit() to die()Laine Stump2023-02-161-4/+2
| | | | | | | | This actually leaves us with 0 uses of err(), but someone could want to use it in the future, so we may as well leave it around. Signed-off-by: Laine Stump <laine@redhat.com> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* add die() to log an error message and exit with a single callLaine Stump2023-02-161-5/+9
| | | | | | | | | | | | | Almost all occurences of err() are either immediately followed by exit(EXIT_FAILURE), usage(argv[0]) (which itself then calls exit(EXIT_FAILURE), or that is what's done immediately after returning from the function that calls err(). Modify the errfn macro so that its instantiations can include exit(EXIT_FAILURE) at the end, and use that to create a new function die() that will log an error and then exit. Signed-off-by: Laine Stump <laine@redhat.com> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* log to stderr until process is daemonized, even if a log file is setLaine Stump2023-02-161-2/+2
| | | | | | | | | | | | | | | | | | | | | | | | | | | Once a log file (specified on the commandline) is opened, the logging functions will stop sending error logs to stderr, which is annoying if passt has been started by another process that wants to collect error messages from stderr so it can report why passt failed to start. It would be much nicer if passt continued sending all log messages to stderr until it daemonizes itself (at which point the process that started passt can assume that it was started successfully). The system log mask is set to LOG_EMERG when the process starts, and we're already using that to do "special" logging during the period from process start until the log level requested on the commandline is processed (setting the log mask to something else). This period *almost* matches with "the time before the process is daemonized"; if we just delay setting the log mask a tiny bit, then it will match exactly, and we can use it to determine if we need to send log messages to stderr even when a log file has been specified and opened. This patch delays the setting of the log mask until immediately before the call to __daemon(). It also modifies logfn() slightly, so that it will log to stderr any time log mask is LOG_EMERG, even if a log file has been opened. Signed-off-by: Laine Stump <laine@redhat.com> Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* conf, log, Makefile: Add versioning informationStefano Brivio2022-10-151-2/+2
| | | | | | | Add a --version option displaying that, and also include this information in the log files. Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
* log: Add missing function comment for trace_init()Stefano Brivio2022-10-141-0/+4
| | | | | Signed-off-by: Stefano Brivio <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* log, conf: Add support for logging to fileStefano Brivio2022-10-141-18/+240
| | | | | | | | | | | | | | | | | | | | | | In some environments, such as KubeVirt pods, we might not have a system logger available. We could choose to run in foreground, but this takes away the convenient synchronisation mechanism derived from forking to background when interfaces are ready. Add optional logging to file with -l/--log-file and --log-size. Unfortunately, this means we need to duplicate features that are more appropriately implemented by a system logger, such as rotation. Keep that reasonably simple, by using fallocate() with range collapsing where supported (Linux kernel >= 3.15, extent-based ext4 and XFS) and falling back to an unsophisticated block-by-block moving of entries toward the beginning of the file once we reach the (mandatory) size limit. While at it, clarify the role of LOG_EMERG in passt.c. Signed-off-by: Stefano Brivio <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>
* Move logging functions to a new file, log.cStefano Brivio2022-10-141-0/+143
Logging to file is going to add some further complexity that we don't want to squeeze into util.c. Signed-off-by: Stefano Brivio <sbrivio@redhat.com> Reviewed-by: David Gibson <david@gibson.dropbear.id.au>