All messages logged from exec_spawn() are attributed to the unit
and as such we should set the log level to the unit's max log level
for the duration of the function.
This is a lot of stuff, and sometimes quite wild, let's turn this into
its own header.
All stuff color-related that just generates sequences is now in
ansi-color.h (no .c file!), and everything more complex that
probes/ineracts with terminals remains in termina-util.[ch]
We shouldn't try to use any ANSI escape sequences if TERM=dumb.
Also, the "\r\n" we output can get interpreted as a double newline
(for example by Github Actions), so let's output just "\n" when
TERM=dumb to clean up the CI logs.
If we're already running in a unit with delegation turned on, let's
skip allocation of a scope unit and cgroup subroot. This allows journald
to correctly attribute the logs of all subprocesses spawned by tests such
as test-execute to the test-execute service when the test is running in a service.
For CI in mkosi, I want to configure systemd to log at debug level
to the journal, but not to the console. While we already have max
level settings for journald's forwarding settings, not every log line
goes to the journal, specifically during early boot and when units
are connected directly to the console (think systemd-firstboot), so
let's extend the log level options we already have to allow specifying
a comma separated list of values and lets allow prefixing values with
the log target they apply to to make this possible.
The glibc API is behind the wrapper is called "secure_getenv()", hence
our wrapper really should keep the order too, otherwise things are just
too confusing.
Triggering assert_return() should be a bug in general, and we should
really fix that. But, previously, it is hard to notice such bug, as
it was not critical.
This is for making CI or our testing environment fail if we unexpectedly
trigger assert_return(). So, hopefully we can easily find such bugs.
This should make sure our log lines look nice even if the tty we are
connected to is in raw mode. Normally, it's the TTY's job to turn an NL
we output into a CRNL and interpret it accordingly. However, if the tty
is in "raw" mode it won't do that. Specifically, this is controlled by
the ONLCR flag on the TTY. A TTY might be in raw mode if our "ptyfwd"
logic is used for example, where a 2nd tty is bi-directionally connected
to the primary tty, and duplicate processing is not desired.
Hence, let's just write out the CR on our own. This will make sure that
whenever we output something subsequent output always continues on the
beginning of the next line again, regardless the mode the TTY is in. Of
course, if the TTY is *not* in raw mode, then the extra CR we now
generate is redundant, but it shouldn't hurt either, as it just moves
the cursor to the front of the line even though already is just there.
We only to that if we actually talk to a TTY though, since we don't want
the extra CRs if we are redirected to a pipe or file or so. We are not
on Windows after all.
Fixes: #30155
Even more than with the previous commit, this is not a trivial function
and there's no reason to believe this will actually be inlined nor that
it would be beneficial.
This is preparation for #28891, which adds a bunch more helpers around
"struct iovec", at which point this really deserves its own .c/.h file.
The idea is that we sooner or later can consider "struct iovec" as an
entirely generic mechanism to reference some binary blob, and is the
go-to type for this purpose whenever we need one.
When trying to log, if we fail we try to close the journal FD. If
it is bad, safe_close() will fail and assert, which will try to log,
which will fail, which will try to close the journal FD...
Infinite recursion looks very pretty live in gdb, but let's avoid
that by immediately invalidating the journal FD before closing it.
Follow-up for: #27734
It makes sense to propagate the select log level we maintain also into
glibc, so that any code that uses syslog() directly that ends up in our
processes (libraries and such) are affected by our settings the same way
as we are ourselves.
Let's avoid confusing developers and users when log messages suddenly
stop getting logged to kmsg because of ratelimiting by logging an
additional message if we start ratelimiting log messages to kmsg.
LOG_SET_PREFIX() sets a logging prefix for the current block. The
prefix is prepended to every logging message in the block, followed
by ": ". If a logging prefix is already configured, it is overridden
for the duration of the block, after which it is restored.
A use case for this macro is when we're operating on an image or
directory (using --root or --image). We can use LOG_SET_PREFIX() to
prefix all logging messages with the directory or image that we're
operating on.
Whenever we're going to close all file descriptors, we tend to close
the log and set it into open when needed mode. When this is done with
the logging target set to LOG_TARGET_AUTO, we run into issues because
for every logging call, we'll check if stderr is connected to the
journal to determine where to send the logging message. This check
obviously stops working when we close stderr, so we settle the log
target before we do that so that we keep using the same logging
target even after stderr is closed.
Now that we have reference counting, it's useful to be able to push
single key values onto the log context separately, so that we don't
have to allocate new storage to join the separate string together into
a single field which means we won't be able to reuse a context containing
the same field.
Let's try to optimize against pushing the same fields multiple times
onto the log context. To achieve this we make the log context reference
counted and return an existing context object if it's using the same
fields.
A consequence of this is that we have to make sure attaching/detaching
is coupled to the lifetime of the context object, so we make the attach
and detach functions private for now. If we need independent attach/detach
in the future, we can make that work with some extra complexity but since
we don't need it yet, let's not support it for now.
IN C23, thread_local is a reserved keyword and we shall therefore
do nothing to redefine it. glibc has it defined for older standard
version with the right conditions.
v2 by Yu Watanabe:
Move the definition to missing_threads.h like the way we define e.g.
missing syscalls or missing definitions, and include it by the users.
Co-authored-by: Yu Watanabe <watanabe.yu+github@gmail.com>
This commit adds support for attaching extra metadata to log
messages written to the journal via log.h. We keep track of a
thread local log context in log.c onto which we can push extra
metadata fields that should be logged. Once a field is no longer
relevant, it can be popped again from the log context.
On top of this, we then add macros to allow pushing extra fields
onto the log context.
LOG_CONTEXT_PUSH() will push the provided field onto the log context
and pop the last field from the log context when the current block
ends. LOG_CONTEXT_PUSH_STRV() will do the same but for all fields in
the given strv.
Using the macros is as simple as putting them anywhere inside a block
to add a field to all following log messages logged from inside that
block.
void myfunction(...) {
...
LOG_CONTEXT_PUSH("MYMETADATA=abc");
// Every journal message logged will now have the MYMETADATA=abc
// field included.
}
For convenience, there's also LOG_CONTEXT_PUSHF() to allow constructing
the field to be logged using printf() syntax.
log_context_new()/log_context_free() can be used to attach a log context
to an async operation by storing it in the associated userdata struct.
-1 was used everywhere, but -EBADF or -EBADFD started being used in various
places. Let's make things consistent in the new style.
Note that there are two candidates:
EBADF 9 Bad file descriptor
EBADFD 77 File descriptor in bad state
Since we're initializating the fd, we're just assigning a value that means
"no fd yet", so it's just a bad file descriptor, and the first errno fits
better. If instead we had a valid file descriptor that became invalid because
of some operation or state change, the other errno would fit better.
In some places, initialization is dropped if unnecessary.
I wanted to move saved_arg[cv] to process-util.c+h, but this causes problems:
process-util.h includes format-util.h which includes net/if.h, which conflicts
with linux/if.h. So we can't include process-util.h in some files.
But process-util.c is very long anyway, so it seems nice to create a new file.
rename_process(), invoked_as(), invoked_by_systemd(), and argv_looks_like_help()
which lived in process-util.c refer to saved_argc and saved_argv, so it seems
reasonable to move them to the new file too.
util.c is now empty, so it is removed. util.h remains.
In general, log_syntax_internal() must keep errno unchanged. But the
call to log_syntax_callback() was added outside of the block protected
by PROTECT_ERRNO.
log_parse_environment() uses should_parse_proc_cmdline() to determine whether
it should parse settings from the kernel command line. But the checks that
should_parse_proc_cmdline() apply to the whole process, and we could get a positive
answer also when log_parse_environment() was called from one of the nss modules.
In case of nss-modules, we don't want to look at the kernel command line.
log_parse_environment_variables() that only looks at the environment variables
is split out and used in the nss modules.
Fixes#22020.
Previously, we discarded any kmsg messages coming from journald
itself to avoid infinite loops where potentially the processing
of a kmsg message causes journald to log one or more messages to
kmsg which then get read again by the kmsg handler, ...
However, if we completely disable logging whenever we're processing
a kmsg message coming from journald itself, we also prevent any
infinite loops as we can be sure that journald won't accidentally
generate logging messages while processing a kmsg log message.
This change allows us to store all journald logs generated during
the processing of log messages from other services in the system
journal. Previously these could only be found in kmsg which has
low retention, can't be queried using journalctl and whose logs
don't survive reboots.
Let's define two helpers strdupa_safe() + strndupa_safe() which do the
same as their non-safe counterparts, except that they abort if called
with allocations larger than ALLOCA_MAX.
This should ensure that all our alloca() based allocations are subject
to this limit.
afaics glibc offers three alloca() based APIs: alloca() itself,
strndupa() + strdupa(). With this we have now replacements for all of
them, that take the limit into account.
The commit introduces a callback invoked from log_syntax_internal.
Use it from systemd-analyze to gather a list of units that contain
syntax warnings. A new command line option is added to make use of this.
The new option --recursive-errors takes in three possible modes:
1. yes - which is the default. systemd-analyze exits with an error when syntax warnings arise during verification of the
specified units or any of their dependencies.
3. no - systemd-analyze exits with an error when syntax warnings arise during verification of only the selected unit.
Analyzing and loading any dependencies will be skipped.
4. one - systemd-analyze exits with an error when syntax warnings arise during verification
of only the selected units and their direct dependencies.
Below are two service unit files that I created for the purposes of testing:
1. First, we run the commands on a unit that does not have dependencies but has a non-existing key-value setting (i.e. foo = bar).
> cat <<EOF>testcase.service
[Unit]
foo = bar
[Service]
ExecStart = echo hello
EOF
OUTPUT:
maanya-goenka@debian:~/systemd (log-error)$ sudo build/systemd-analyze verify testcase.service
/home/maanya-goenka/systemd/testcase.service:2: Unknown key name 'foo' in section 'Unit', ignoring.
/usr/lib/systemd/system/plymouth-start.service:15: Unit configured to use KillMode=none. This is unsafe, as it disables systemd's process lifecycle management for the service. Please update your service to use a safer KillMode=, such as 'mixed' or 'control-group'. Support for KillMode=none is deprecated and will eventually be removed.
/usr/lib/systemd/system/dbus.socket:5: ListenStream= references a path below legacy directory /var/run/, updating /var/run/dbus/system_bus_socket → /run/dbus/system_bus_socket; please update the unit file accordingly.
/usr/lib/systemd/system/gdm.service:30: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
maanya-goenka@debian:~/systemd (log-error)$ echo $?
1
maanya-goenka@debian:~/systemd (log-error)$ sudo build/systemd-analyze verify --recursive-errors=yes testcase.service
/home/maanya-goenka/systemd/testcase.service:2: Unknown key name 'foo' in section 'Unit', ignoring.
/usr/lib/systemd/system/plymouth-start.service:15: Unit configured to use KillMode=none. This is unsafe, as it disables systemd's process lifecycle management for the service. Please update your service to use a safer KillMode=, such as 'mixed' or 'control-group'. Support for KillMode=none is deprecated and will eventually be removed.
/usr/lib/systemd/system/dbus.socket:5: ListenStream= references a path below legacy directory /var/run/, updating /var/run/dbus/system_bus_socket → /run/dbus/system_bus_socket; please update the unit file accordingly.
/usr/lib/systemd/system/gdm.service:30: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
maanya-goenka@debian:~/systemd (log-error)$ echo $?
1
maanya-goenka@debian:~/systemd (log-error)$ sudo build/systemd-analyze verify --recursive-errors=no testcase.service
/home/maanya-goenka/systemd/testcase.service:2: Unknown key name 'foo' in section 'Unit', ignoring.
maanya-goenka@debian:~/systemd (log-error)$ echo $?
1
maanya-goenka@debian:~/systemd (log-error)$ sudo build/systemd-analyze verify --recursive-errors=one testcase.service
/home/maanya-goenka/systemd/testcase.service:2: Unknown key name 'foo' in section 'Unit', ignoring.
/usr/lib/systemd/system/plymouth-start.service:15: Unit configured to use KillMode=none. This is unsafe, as it disables systemd's process lifecycle management for the service. Please update your service to use a safer KillMode=, such as 'mixed' or 'control-group'. Support for KillMode=none is deprecated and will eventually be removed.
/usr/lib/systemd/system/dbus.socket:5: ListenStream= references a path below legacy directory /var/run/, updating /var/run/dbus/system_bus_socket → /run/dbus/system_bus_socket; please update the unit file accordingly.
/usr/lib/systemd/system/gdm.service:30: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
maanya-goenka@debian:~/systemd (log-error)$ echo $?
1
2. Next, we run the commands on a unit that is syntactically valid but has a non-existing dependency (i.e. foo2.service)
> cat <<EOF>foobar.service
[Unit]
Requires = foo2.service
[Service]
ExecStart = echo hello
EOF
OUTPUT:
maanya-goenka@debian:~/systemd (log-error)$ sudo build/systemd-analyze verify foobar.service
/usr/lib/systemd/system/plymouth-start.service:15: Unit configured to use KillMode=none. This is unsafe, as it disables systemd's process lifecycle management for the service. Please update your service to use a safer KillMode=, such as 'mixed' or 'control-group'. Support for KillMode=none is deprecated and will eventually be removed.
/usr/lib/systemd/system/dbus.socket:5: ListenStream= references a path below legacy directory /var/run/, updating /var/run/dbus/system_bus_socket → /run/dbus/system_bus_socket; please update the unit file accordingly.
/usr/lib/systemd/system/gdm.service:30: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
foobar.service: Failed to create foobar.service/start: Unit foo2.service not found.
maanya-goenka@debian:~/systemd (log-error)$ echo $?
1
maanya-goenka@debian:~/systemd (log-error)$ sudo build/systemd-analyze verify --recursive-errors=yes foobar.service
/usr/lib/systemd/system/plymouth-start.service:15: Unit configured to use KillMode=none. This is unsafe, as it disables systemd's process lifecycle management for the service. Please update your service to use a safer KillMode=, such as 'mixed' or 'control-group'. Support for KillMode=none is deprecated and will eventually be removed.
/usr/lib/systemd/system/dbus.socket:5: ListenStream= references a path below legacy directory /var/run/, updating /var/run/dbus/system_bus_socket → /run/dbus/system_bus_socket; please update the unit file accordingly.
/usr/lib/systemd/system/gdm.service:30: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
foobar.service: Failed to create foobar.service/start: Unit foo2.service not found.
maanya-goenka@debian:~/systemd (log-error)$ echo $?
1
maanya-goenka@debian:~/systemd (log-error)$ sudo build/systemd-analyze verify --recursive-errors=no foobar.service
maanya-goenka@debian:~/systemd (log-error)$ echo $?
0
maanya-goenka@debian:~/systemd (log-error)$ sudo build/systemd-analyze verify --recursive-errors=one foobar.service
/usr/lib/systemd/system/plymouth-start.service:15: Unit configured to use KillMode=none. This is unsafe, as it disables systemd's process lifecycle management for the service. Please update your service to use a safer KillMode=, such as 'mixed' or 'control-group'. Support for KillMode=none is deprecated and will eventually be removed.
/usr/lib/systemd/system/dbus.socket:5: ListenStream= references a path below legacy directory /var/run/, updating /var/run/dbus/system_bus_socket → /run/dbus/system_bus_socket; please update the unit file accordingly.
/usr/lib/systemd/system/gdm.service:30: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
foobar.service: Failed to create foobar.service/start: Unit foo2.service not found.
maanya-goenka@debian:~/systemd (log-error)$ echo $?
1
We had 'msghdr' and 'mh' in various places. Now 'const struct msghdr msghdr' is
used consistently. With structured init the variable is only used in the call
to sendmsg(), so let's make it a bit more descriptive.
In general we almost never hit those asserts in production code, so users see
them very rarely, if ever. But either way, we just need something that users
can pass to the developers.
We have quite a few of those asserts, and some have fairly nice messages, but
many are like "WTF?" or "???" or "unexpected something". The error that is
printed includes the file location, and function name. In almost all functions
there's at most one assert, so the function name alone is enough to identify
the failure for a developer. So we don't get much extra from the message, and
we might just as well drop them.
Dropping them makes our code a tiny bit smaller, and most importantly, improves
development experience by making it easy to insert such an assert in the code
without thinking how to phrase the argument.
