From 8750a06b6caa9c1d33872cb7b0fa077497ef9888 Mon Sep 17 00:00:00 2001 From: Daan De Meyer Date: Thu, 20 Apr 2023 10:31:37 +0200 Subject: [PATCH 1/7] log: Add knob to disable kmsg ratelimiting This allows us to disable kmsg ratelimiting in the integration tests and mkosi for easier debugging. --- man/common-variables.xml | 8 ++++++++ man/kernel-command-line.xml | 1 + man/systemd.xml | 14 +++++++++++--- src/basic/log.c | 22 +++++++++++++++++++++- 4 files changed, 41 insertions(+), 4 deletions(-) diff --git a/man/common-variables.xml b/man/common-variables.xml index 0e220b3f9e..81425e57e2 100644 --- a/man/common-variables.xml +++ b/man/common-variables.xml @@ -81,6 +81,14 @@ + + $SYSTEMD_LOG_RATELIMIT_KMSG + + Whether to ratelimit kmsg or not. Takes a boolean. + Defaults to true. If disabled, systemd will not ratelimit messages written to kmsg. + + + $SYSTEMD_PAGER diff --git a/man/kernel-command-line.xml b/man/kernel-command-line.xml index 27ef72da36..09f8ace4de 100644 --- a/man/kernel-command-line.xml +++ b/man/kernel-command-line.xml @@ -66,6 +66,7 @@ systemd.log_level= systemd.log_location= systemd.log_color + systemd.log_ratelimit_kmsg systemd.default_standard_output= systemd.default_standard_error= systemd.setenv= diff --git a/man/systemd.xml b/man/systemd.xml index 1a68301d50..ca9e4e9988 100644 --- a/man/systemd.xml +++ b/man/systemd.xml @@ -680,6 +680,11 @@ This can be overridden with . + + $SYSTEMD_LOG_RATELIMIT_KMSG + + + $XDG_CONFIG_HOME $XDG_CONFIG_DIRS @@ -865,13 +870,16 @@ systemd.log_target= systemd.log_time systemd.log_tid + systemd.log_ratelimit_kmsg Controls log output, with the same effect as the $SYSTEMD_LOG_COLOR, $SYSTEMD_LOG_LEVEL, $SYSTEMD_LOG_LOCATION, $SYSTEMD_LOG_TARGET, - $SYSTEMD_LOG_TIME, and $SYSTEMD_LOG_TID environment variables - described above. systemd.log_color, systemd.log_location, - systemd.log_time, and systemd.log_tid= can be specified without + $SYSTEMD_LOG_TIME, $SYSTEMD_LOG_TID and + $SYSTEMD_LOG_RATELIMIT_KMSG environment variables described above. + systemd.log_color, systemd.log_location, + systemd.log_time, systemd.log_tid and + systemd.log_ratelimit_kmsg can be specified without an argument, with the same effect as a positive boolean. diff --git a/src/basic/log.c b/src/basic/log.c index 75f59c4343..d0fef3554f 100644 --- a/src/basic/log.c +++ b/src/basic/log.c @@ -50,6 +50,7 @@ static void *log_syntax_callback_userdata = NULL; static LogTarget log_target = LOG_TARGET_CONSOLE; static int log_max_level = LOG_INFO; static int log_facility = LOG_DAEMON; +static bool ratelimit_kmsg = true; static int console_fd = STDERR_FILENO; static int syslog_fd = -EBADF; @@ -552,7 +553,7 @@ static int write_to_kmsg( if (kmsg_fd < 0) return 0; - if (!ratelimit_below(&ratelimit)) + if (ratelimit_kmsg && !ratelimit_below(&ratelimit)) return 0; xsprintf(header_priority, "<%i>", level); @@ -1178,6 +1179,17 @@ int log_set_max_level_from_string(const char *e) { return 0; } +static int log_set_ratelimit_kmsg_from_string(const char *e) { + int r; + + r = parse_boolean(e); + if (r < 0) + return r; + + ratelimit_kmsg = r; + return 0; +} + static int parse_proc_cmdline_item(const char *key, const char *value, void *data) { /* @@ -1228,6 +1240,10 @@ static int parse_proc_cmdline_item(const char *key, const char *value, void *dat if (log_show_time_from_string(value ?: "1") < 0) log_warning("Failed to parse log time setting '%s'. Ignoring.", value); + } else if (proc_cmdline_key_streq(key, "systemd.log_ratelimit_kmsg")) { + + if (log_set_ratelimit_kmsg_from_string(value ?: "1") < 0) + log_warning("Failed to parse log ratelimit kmsg boolean '%s'. Ignoring.", value); } return 0; @@ -1268,6 +1284,10 @@ void log_parse_environment_variables(void) { e = getenv("SYSTEMD_LOG_TID"); if (e && log_show_tid_from_string(e) < 0) log_warning("Failed to parse log tid '%s'. Ignoring.", e); + + e = getenv("SYSTEMD_LOG_RATELIMIT_KMSG"); + if (e && log_set_ratelimit_kmsg_from_string(e) < 0) + log_warning("Failed to parse log ratelimit kmsg boolean '%s'. Ignoring.", e); } void log_parse_environment(void) { From 3fe07e952515448fb04fd421376ca965947196ce Mon Sep 17 00:00:00 2001 From: Daan De Meyer Date: Thu, 20 Apr 2023 10:43:21 +0200 Subject: [PATCH 2/7] log: Log when kmsg is being ratelimited 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. --- src/basic/log.c | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/src/basic/log.c b/src/basic/log.c index d0fef3554f..4cd2d5a4ab 100644 --- a/src/basic/log.c +++ b/src/basic/log.c @@ -553,8 +553,12 @@ static int write_to_kmsg( if (kmsg_fd < 0) return 0; - if (ratelimit_kmsg && !ratelimit_below(&ratelimit)) - return 0; + if (ratelimit_kmsg && !ratelimit_below(&ratelimit)) { + if (ratelimit_num_dropped(&ratelimit) > 1) + return 0; + + buffer = "Too many messages being logged to kmsg, ignoring"; + } xsprintf(header_priority, "<%i>", level); xsprintf(header_pid, "["PID_FMT"]: ", getpid_cached()); From 85003d1296a636349dcd3a1743ec8675a8f0bdb6 Mon Sep 17 00:00:00 2001 From: Daan De Meyer Date: Thu, 20 Apr 2023 10:33:10 +0200 Subject: [PATCH 3/7] mkosi: Disable kmsg ratelimiting --- mkosi.conf.d/10-systemd.conf | 1 + 1 file changed, 1 insertion(+) diff --git a/mkosi.conf.d/10-systemd.conf b/mkosi.conf.d/10-systemd.conf index b7175fb705..2b02eba0d6 100644 --- a/mkosi.conf.d/10-systemd.conf +++ b/mkosi.conf.d/10-systemd.conf @@ -71,6 +71,7 @@ QemuMem=2G ExtraSearchPaths=build/ KernelCommandLineExtra=systemd.crash_shell systemd.log_level=debug + systemd.log_ratelimit_kmsg=0 systemd.journald.forward_to_console systemd.journald.max_level_console=warning systemd.mask=auditd From 70cc7ed97e474a5237f0ea183b9bd85ccb99f192 Mon Sep 17 00:00:00 2001 From: Daan De Meyer Date: Tue, 18 Apr 2023 13:11:45 +0200 Subject: [PATCH 4/7] string-util: Add startswith_strv() This is the function version of STARTSWITH_SET(). We also move STARTSWITH_SET() to string-util.h as it fits more there than in strv.h and reimplement it using startswith_strv(). --- src/basic/string-util.c | 12 ++++++++++++ src/basic/string-util.h | 5 +++++ src/basic/strv.h | 12 ------------ 3 files changed, 17 insertions(+), 12 deletions(-) diff --git a/src/basic/string-util.c b/src/basic/string-util.c index cc2f8ecdab..c74ee67dfe 100644 --- a/src/basic/string-util.c +++ b/src/basic/string-util.c @@ -1283,3 +1283,15 @@ char *find_line_startswith(const char *haystack, const char *needle) { return p + strlen(needle); } + +char *startswith_strv(const char *string, char **strv) { + char *found = NULL; + + STRV_FOREACH(i, strv) { + found = startswith(string, *i); + if (found) + break; + } + + return found; +} diff --git a/src/basic/string-util.h b/src/basic/string-util.h index 75483924af..4430910e22 100644 --- a/src/basic/string-util.h +++ b/src/basic/string-util.h @@ -267,3 +267,8 @@ char *strdupspn(const char *a, const char *accept); char *strdupcspn(const char *a, const char *reject); char *find_line_startswith(const char *haystack, const char *needle); + +char *startswith_strv(const char *string, char **strv); + +#define STARTSWITH_SET(p, ...) \ + startswith_strv(p, STRV_MAKE(__VA_ARGS__)) diff --git a/src/basic/strv.h b/src/basic/strv.h index b4d3f121f9..544d46a3f8 100644 --- a/src/basic/strv.h +++ b/src/basic/strv.h @@ -200,18 +200,6 @@ static inline void strv_print(char * const *l) { _x && strv_contains_case(STRV_MAKE(__VA_ARGS__), _x); \ }) -#define STARTSWITH_SET(p, ...) \ - ({ \ - const char *_p = (p); \ - char *_found = NULL; \ - STRV_FOREACH(_i, STRV_MAKE(__VA_ARGS__)) { \ - _found = startswith(_p, *_i); \ - if (_found) \ - break; \ - } \ - _found; \ - }) - #define ENDSWITH_SET(p, ...) \ ({ \ const char *_p = (p); \ From e1d8f702a2cacc12978bd7c17e22a8c312404cdf Mon Sep 17 00:00:00 2001 From: Daan De Meyer Date: Tue, 18 Apr 2023 10:47:13 +0200 Subject: [PATCH 5/7] kmod-setup: Introduce match_modalias_recurse_dir_cb() Let's make the logic around matching a modalias a bit more generic. --- src/core/kmod-setup.c | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/src/core/kmod-setup.c b/src/core/kmod-setup.c index adf817800f..d7abf4b7d8 100644 --- a/src/core/kmod-setup.c +++ b/src/core/kmod-setup.c @@ -31,7 +31,7 @@ static void systemd_kmod_log( REENABLE_WARNING; } -static int has_virtio_rng_recurse_dir_cb( +static int match_modalias_recurse_dir_cb( RecurseDirEvent event, const char *path, int dir_fd, @@ -41,6 +41,7 @@ static int has_virtio_rng_recurse_dir_cb( void *userdata) { _cleanup_free_ char *alias = NULL; + char **modaliases = ASSERT_PTR(userdata); int r; if (event != RECURSE_DIR_ENTRY) @@ -58,7 +59,7 @@ static int has_virtio_rng_recurse_dir_cb( return RECURSE_DIR_LEAVE_DIRECTORY; } - if (STARTSWITH_SET(alias, "pci:v00001AF4d00001005", "pci:v00001AF4d00001044")) + if (startswith_strv(alias, modaliases)) return 1; return RECURSE_DIR_LEAVE_DIRECTORY; @@ -77,8 +78,8 @@ static bool has_virtio_rng(void) { /* statx_mask= */ 0, /* n_depth_max= */ 2, RECURSE_DIR_ENSURE_TYPE, - has_virtio_rng_recurse_dir_cb, - NULL); + match_modalias_recurse_dir_cb, + STRV_MAKE("pci:v00001AF4d00001005", "pci:v00001AF4d00001044")); if (r < 0) log_debug_errno(r, "Failed to determine whether host has virtio-rng device, ignoring: %m"); From d2f57745d543e9981980f502deb55fcedb6767ce Mon Sep 17 00:00:00 2001 From: Daan De Meyer Date: Tue, 18 Apr 2023 13:15:20 +0200 Subject: [PATCH 6/7] core: Parse logging environment earlier Let's make sure we parse the logging environment ASAP so that the options apply to more code. e.g. to allow debugging kmod-setup.c for example. --- src/core/main.c | 14 ++++++++++---- 1 file changed, 10 insertions(+), 4 deletions(-) diff --git a/src/core/main.c b/src/core/main.c index b627916a25..932ea64e45 100644 --- a/src/core/main.c +++ b/src/core/main.c @@ -2798,12 +2798,18 @@ int main(int argc, char *argv[]) { error_message = "Failed to mount early API filesystems"; goto finish; } + } - /* Let's open the log backend a second time, in case the first time didn't - * work. Quite possibly we have mounted /dev just now, so /dev/kmsg became - * available, and it previously wasn't. */ - log_open(); + /* We might have just mounted /proc, so let's try to parse the kernel + * command line log arguments immediately. */ + log_parse_environment(); + /* Let's open the log backend a second time, in case the first time didn't + * work. Quite possibly we have mounted /dev just now, so /dev/kmsg became + * available, and it previously wasn't. */ + log_open(); + + if (!skip_setup) { disable_printk_ratelimit(); r = initialize_security( From a93aaede294258e51e4e2a6a9530ae0d29a45915 Mon Sep 17 00:00:00 2001 From: Daan De Meyer Date: Tue, 18 Apr 2023 13:20:37 +0200 Subject: [PATCH 7/7] kmod-setup: Add early loading for virtio_console getty-generator enables serial-getty@.service for virtualizer consoles that it can find in /sys/class/tty. To make sure this works for virtio consoles, let's make sure we load the module is loaded early so that the /sys/class/tty/hvc0 exists before we run getty-generator. --- src/core/kmod-setup.c | 41 +++++++++++++++++++++++++++++++++-------- 1 file changed, 33 insertions(+), 8 deletions(-) diff --git a/src/core/kmod-setup.c b/src/core/kmod-setup.c index d7abf4b7d8..c09e17f568 100644 --- a/src/core/kmod-setup.c +++ b/src/core/kmod-setup.c @@ -86,6 +86,27 @@ static bool has_virtio_rng(void) { return r > 0; } +static bool has_virtio_console(void) { + int r; + + /* Directory traversal might be slow, hence let's do a cheap check first if it's even worth it */ + if (detect_vm() == VIRTUALIZATION_NONE) + return false; + + r = recurse_dir_at( + AT_FDCWD, + "/sys/devices/pci0000:00", + /* statx_mask= */ 0, + /* n_depth_max= */ 3, + RECURSE_DIR_ENSURE_TYPE, + match_modalias_recurse_dir_cb, + STRV_MAKE("virtio:d00000003v", "virtio:d0000000Bv")); + if (r < 0) + log_debug_errno(r, "Failed to determine whether host has virtio-console device, ignoring: %m"); + + return r > 0; +} + static bool in_qemu(void) { return IN_SET(detect_vm(), VIRTUALIZATION_KVM, VIRTUALIZATION_QEMU); } @@ -103,31 +124,35 @@ int kmod_setup(void) { } kmod_table[] = { /* This one we need to load explicitly, since auto-loading on use doesn't work * before udev created the ghost device nodes, and we need it earlier than that. */ - { "autofs4", "/sys/class/misc/autofs", true, false, NULL }, + { "autofs4", "/sys/class/misc/autofs", true, false, NULL }, /* This one we need to load explicitly, since auto-loading of IPv6 is not done when * we try to configure ::1 on the loopback device. */ - { "ipv6", "/sys/module/ipv6", false, true, NULL }, + { "ipv6", "/sys/module/ipv6", false, true, NULL }, /* This should never be a module */ - { "unix", "/proc/net/unix", true, true, NULL }, + { "unix", "/proc/net/unix", true, true, NULL }, #if HAVE_LIBIPTC /* netfilter is needed by networkd, nspawn among others, and cannot be autoloaded */ - { "ip_tables", "/proc/net/ip_tables_names", false, false, NULL }, + { "ip_tables", "/proc/net/ip_tables_names", false, false, NULL }, #endif /* virtio_rng would be loaded by udev later, but real entropy might be needed very early */ - { "virtio_rng", NULL, false, false, has_virtio_rng }, + { "virtio_rng", NULL, false, false, has_virtio_rng }, + + /* we want early logging to hvc consoles if possible, and make sure systemd-getty-generator + * can rely on all consoles being probed already.*/ + { "virtio_console", NULL, false, false, has_virtio_console }, /* qemu_fw_cfg would be loaded by udev later, but we want to import credentials from it super early */ - { "qemu_fw_cfg", "/sys/firmware/qemu_fw_cfg", false, false, in_qemu }, + { "qemu_fw_cfg", "/sys/firmware/qemu_fw_cfg", false, false, in_qemu }, /* dmi-sysfs is needed to import credentials from it super early */ - { "dmi-sysfs", "/sys/firmware/dmi/entries", false, false, NULL }, + { "dmi-sysfs", "/sys/firmware/dmi/entries", false, false, NULL }, #if HAVE_TPM2 /* Make sure the tpm subsystem is available which ConditionSecurity=tpm2 depends on. */ - { "tpm", "/sys/class/tpmrm", false, false, efi_has_tpm2 }, + { "tpm", "/sys/class/tpmrm", false, false, efi_has_tpm2 }, #endif }; _cleanup_(kmod_unrefp) struct kmod_ctx *ctx = NULL;