From: Lukáš Ondráček Date: Tue, 18 Mar 2025 15:46:10 +0000 (+0100) Subject: daemon/defer: pass loglevel to systemd with sigsafe_log X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=a1eb8ec2bd99be9fa5d52a517895bf38ef82d1ba;p=thirdparty%2Fknot-resolver.git daemon/defer: pass loglevel to systemd with sigsafe_log --- diff --git a/daemon/defer.c b/daemon/defer.c index d10728512..d1705301c 100644 --- a/daemon/defer.c +++ b/daemon/defer.c @@ -62,14 +62,7 @@ V6_CONF = {1, V6_PREFIXES_CNT, V6_PREFIXES, V6_RATE_MULT, V6_SUBPRIO}; #define VERBOSE_LOG(...) kr_log_debug(DEFER, " | " __VA_ARGS__) // Uses NON-STANDARD format string, see sigsafe_format. -#define SIGSAFE_LOG(max_size, ...) { \ - char msg[max_size]; \ - int len = sigsafe_format(msg, sizeof(msg), "[defer ] "__VA_ARGS__); \ - write(kr_log_target == LOG_TARGET_STDOUT ? 1 : 2, msg, len); \ -} -#define SIGSAFE_VERBOSE_LOG(max_size, ...) { \ - if (kr_log_is_debug(DEFER, NULL)) /* NOLINT */\ - { SIGSAFE_LOG(max_size, " | " __VA_ARGS__)}} +#define SIGSAFE_VERBOSE_LOG(max_size, ...) sigsafe_log(LOG_DEBUG, DEFER, max_size, " | " __VA_ARGS__) struct defer { @@ -673,7 +666,7 @@ static void defer_alarm(int signum) if (rest_to_timeout_ms <= 0) { defer_charge(elapsed, &defer_sample_state.addr, defer_sample_state.stream); bool coredump = kr_log_period(defer->coredump_period, &defer->coredump_time); - SIGSAFE_LOG(KR_STRADDR_MAXLEN + 100, + sigsafe_log(LOG_CRIT, DEFER, KR_STRADDR_MAXLEN + 100, "Host %r used %f s of cpu time continuously, interrupting kresd (%s).\n", &defer_sample_state.addr.ip, elapsed / 1000000000.0, coredump ? "abort" : "exit"); diff --git a/lib/log.c b/lib/log.c index e1f4d5436..a52fd7f32 100644 --- a/lib/log.c +++ b/lib/log.c @@ -22,9 +22,7 @@ bool use_journal = false; kr_log_level_t kr_log_level = LOG_DEFAULT_LEVEL; kr_log_target_t kr_log_target = LOG_TARGET_DEFAULT; - -/** Set of log-groups that are on debug level. It's a bitmap over 1 << enum kr_log_group. */ -static uint64_t kr_log_groups = 0; +uint64_t kr_log_groups = 0; typedef struct { const char *g_name; diff --git a/lib/log.h b/lib/log.h index 30fc29373..b441453e4 100644 --- a/lib/log.h +++ b/lib/log.h @@ -140,6 +140,9 @@ enum kr_log_group { #define LOG_GRP_REQDBG_TAG "reqdbg" /**< ``reqdbg``: debug logs enabled by policy actions */ ///@} +// Async-signal-safe variant of the lowercase function; fails silently. +#define KR_LOG_GROUP_IS_SET(grp) ((LOG_GRP_ ## grp < 1) || (kr_log_groups & (1ULL << LOG_GRP_ ## grp))) + KR_EXPORT bool kr_log_group_is_set(enum kr_log_group group); KR_EXPORT @@ -160,6 +163,10 @@ typedef int kr_log_level_t; KR_EXPORT extern kr_log_level_t kr_log_level; +/** Set of log-groups that are on debug level. It's a bitmap over 1 << enum kr_log_group. Read only. */ +KR_EXPORT extern +uint64_t kr_log_groups; + /** Set the current logging level. */ KR_EXPORT void kr_log_level_set(kr_log_level_t level); diff --git a/lib/sigsafe.h b/lib/sigsafe.h index 710fcfbc8..efc3372c8 100644 --- a/lib/sigsafe.h +++ b/lib/sigsafe.h @@ -4,6 +4,7 @@ #pragma once #include "lib/defines.h" +#include "lib/log.h" /// Async-signal-safe snprintf-like formatting function, it supports: /// * %% prints %; @@ -16,3 +17,15 @@ KR_EXPORT int sigsafe_format(char *str, size_t size, const char *fmt, ...); #define sigsafe_format(...) sigsafe_format(__VA_ARGS__) // NOLINT, all calls are async-signal-safe + +/// Log according to the set target to stdout or stderr; +/// for syslog, print to stderr prefixed with , as syslog() is not async-signal-safe. +#define sigsafe_log(level, grp, max_size, fmt, ...) { \ + if ((KR_LOG_LEVEL_IS(level) || KR_LOG_GROUP_IS_SET(grp))) { \ + char msg[max_size + 12]; \ + int len = 0; \ + if (kr_log_target == LOG_TARGET_SYSLOG) \ + len += sigsafe_format(msg, sizeof(msg), "<%u>", level); \ + len += sigsafe_format(msg + len, sizeof(msg) - len, "[%-6s] " fmt, LOG_GRP_ ## grp ## _TAG, ## __VA_ARGS__); \ + write(kr_log_target == LOG_TARGET_STDOUT ? 1 : 2, msg, len); \ + }} diff --git a/python/knot_resolver/controller/supervisord/config_file.py b/python/knot_resolver/controller/supervisord/config_file.py index 05e380dcf..743ca4b57 100644 --- a/python/knot_resolver/controller/supervisord/config_file.py +++ b/python/knot_resolver/controller/supervisord/config_file.py @@ -140,6 +140,8 @@ class ProcessTypeConfig: logfile=Path(""), # this will be ignored ) +def sd_booted(): + return os.path.lexists("/run/systemd/system") # same as in libsystemd @dataclass class SupervisordConfig: @@ -149,6 +151,7 @@ class SupervisordConfig: logfile: Path loglevel: Literal["critical", "error", "warn", "info", "debug", "trace", "blather"] target: LogTargetEnum + systemd_logfile: Literal["NONE", "PASS"] @staticmethod def create(config: KresConfig) -> "SupervisordConfig": @@ -165,6 +168,12 @@ class SupervisordConfig: "debug": "debug", }[config.logging.level] cwd = str(os.getcwd()) + + # Keep stderr FD unchanged if logging to systemd (it is likely to be handled by systemd as well as syslog); + # reformat `` line prefixes in supervisord's patch_logger module, otherwise. + # Use as the value of `stderr_logfile` where desired. + systemd_logfile = "" if config.logging.target == "syslog" and sd_booted() else "NONE" + return SupervisordConfig( # type: ignore[call-arg] unix_http_server=supervisord_sock_file(config), pid_file=supervisord_pid_file(config), @@ -172,6 +181,7 @@ class SupervisordConfig: logfile=Path("syslog" if config.logging.target == "syslog" else "/dev/null"), loglevel=loglevel, # type: ignore[arg-type] target=config.logging.target, + systemd_logfile = systemd_logfile, ) diff --git a/python/knot_resolver/controller/supervisord/plugin/patch_logger.py b/python/knot_resolver/controller/supervisord/plugin/patch_logger.py index db27f105c..223271baf 100644 --- a/python/knot_resolver/controller/supervisord/plugin/patch_logger.py +++ b/python/knot_resolver/controller/supervisord/plugin/patch_logger.py @@ -4,11 +4,13 @@ import os import sys import traceback +import re from typing import Any, Literal from supervisor.dispatchers import POutputDispatcher from supervisor.loggers import LevelsByName, StreamHandler, SyslogHandler from supervisor.supervisord import Supervisor +from supervisor.process import Subprocess FORWARD_LOG_LEVEL = LevelsByName.CRIT # to make sure it's always printed @@ -17,8 +19,10 @@ def empty_function(*args, **kwargs): pass -FORWARD_MSG_FORMAT: str = "%(name)s[%(pid)d]%(stream)s: %(data)s" +FORWARD_MSG_FORMAT: str = "%(prefix)s%(name)s[%(pid)d]%(stream)s: %(data)s" +FORWARD_MSG_PREFIX: str = "" +loglevel_re = re.compile(r"<(\d)>(.*)") def p_output_dispatcher_log(self: POutputDispatcher, data: bytearray): if data: @@ -36,10 +40,19 @@ def p_output_dispatcher_log(self: POutputDispatcher, data: bytearray): config.options.logger.handlers = forward_handlers for line in text.splitlines(): stream = "" - if self.channel == "stderr": - stream = " (stderr)" + prefix = "" + loglevel_match = loglevel_re.match(line) + if loglevel_match: + # just strip the loglevel as supervisor cannot handle it; + # used only for target=syslog without systemd + line = loglevel_match.group(2) + else: + # no loglevel found, mark as stdio output to retain previous behaviour + if self.channel == "stderr": + stream = " (stderr)" + prefix = FORWARD_MSG_PREFIX config.options.logger.log( - FORWARD_LOG_LEVEL, FORWARD_MSG_FORMAT, name=config.name, stream=stream, data=line, pid=self.process.pid + FORWARD_LOG_LEVEL, FORWARD_MSG_FORMAT, prefix=prefix, name=config.name, stream=stream, data=line, pid=self.process.pid ) config.options.logger.handlers = supervisord_handlers @@ -54,10 +67,24 @@ def _create_handler(fmt, level, target: Literal["stdout", "stderr", "syslog"]) - return handler +# keep stderr FD unchanged if stderr_logfile is empty; same behavior as originally otherwise; +# we use "" as other strings involve creation of file of that name (bool("") == False) +def _prepare_child_fds(self): + options = self.config.options + options.dup2(self.pipes['child_stdin'], 0) + options.dup2(self.pipes['child_stdout'], 1) + if self.config.stderr_logfile != "": + if self.config.redirect_stderr: + options.dup2(self.pipes['child_stdout'], 2) + else: + options.dup2(self.pipes['child_stderr'], 2) + for i in range(3, options.minfds): + options.close_fd(i) + + supervisord_handlers = [] forward_handlers = [] - def inject(supervisord: Supervisor, **config: Any) -> Any: # pylint: disable=useless-return try: # reconfigure log handlers @@ -77,12 +104,15 @@ def inject(supervisord: Supervisor, **config: Any) -> Any: # pylint: disable=us # replace output handler for subprocesses POutputDispatcher._log = p_output_dispatcher_log # noqa: SLF001 + # replace setting FDs of subprocesses + Subprocess._prepare_child_fds = _prepare_child_fds + # we forward stdio in all cases, even when logging to syslog. This should prevent the unforturtunate # case of swallowing an error message leaving the users confused. To make the forwarded lines obvious # we just prepend a explanatory string at the beginning of all messages if config["target"] == "syslog": - global FORWARD_MSG_FORMAT - FORWARD_MSG_FORMAT = "captured stdio output from " + FORWARD_MSG_FORMAT + global FORWARD_MSG_PREFIX + FORWARD_MSG_PREFIX = "captured stdio output from " # this method is called by supervisord when loading the plugin, # it should return XML-RPC object, which we don't care about diff --git a/python/knot_resolver/controller/supervisord/supervisord.conf.j2 b/python/knot_resolver/controller/supervisord/supervisord.conf.j2 index 4179d5221..354647850 100644 --- a/python/knot_resolver/controller/supervisord/supervisord.conf.j2 +++ b/python/knot_resolver/controller/supervisord/supervisord.conf.j2 @@ -66,7 +66,7 @@ killasgroup=true startsecs=60 environment={{ kresd.environment }} stdout_logfile=NONE -stderr_logfile=NONE +stderr_logfile={{ config.systemd_logfile }} # empty string has special meaning defined in patch_logger [program:policy-loader] directory={{ loader.workdir }} @@ -77,7 +77,7 @@ killasgroup=true startsecs=300 environment={{ loader.environment }} stdout_logfile=NONE -stderr_logfile=NONE +stderr_logfile={{ config.systemd_logfile }} # empty string has special meaning defined in patch_logger [program:cache-gc] redirect_stderr=false