]> git.ipfire.org Git - thirdparty/knot-resolver.git/commitdiff
daemon/defer: pass loglevel to systemd with sigsafe_log docs-develop-defe-yjbb02/deployments/6425
authorLukáš Ondráček <lukas.ondracek@nic.cz>
Tue, 18 Mar 2025 15:46:10 +0000 (16:46 +0100)
committerLukáš Ondráček <lukas.ondracek@nic.cz>
Tue, 18 Mar 2025 15:59:13 +0000 (16:59 +0100)
daemon/defer.c
lib/log.c
lib/log.h
lib/sigsafe.h
python/knot_resolver/controller/supervisord/config_file.py
python/knot_resolver/controller/supervisord/plugin/patch_logger.py
python/knot_resolver/controller/supervisord/supervisord.conf.j2

index d10728512d037bd6e29711cc2ea4a3b8f468de95..d1705301c1abedfd537f5e2f8e0b836830322705 100644 (file)
@@ -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");
index e1f4d543676cc9c7233ca3068853150c648839f7..a52fd7f324ecb77274506237762770110e11cd5d 100644 (file)
--- 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;
index 30fc29373808fe482d8510e2cefe48aa10af9b8b..b441453e4f132988a0b18f319b645f6f580a991c 100644 (file)
--- 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);
index 710fcfbc84f4a9ceb381f1255c6f11f1644a51cd..efc3372c85ecd86f449541f0c2747740654a2974 100644 (file)
@@ -4,6 +4,7 @@
 
 #pragma once
 #include "lib/defines.h"
+#include "lib/log.h"
 
 /// Async-signal-safe snprintf-like formatting function, it supports:
 ///   * %% prints %;
 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 <loglevel>, 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); \
+       }}
index 05e380dcf6c5bf0407df60eafd9d2c20c54e8dd2..743ca4b5790e0e8e8635e31c3ed425b9a5cbfa22 100644 (file)
@@ -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 `<N>` 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,
         )
 
 
index db27f105c19a12dbfabf00f656fc1bd586de910a..223271baf9c433b3d5424d9f29369e67749454b2 100644 (file)
@@ -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
index 4179d522114e3885946c6705155e501f0e1392f7..3546478500f68b73d95b9c27c0385ed14e1769a6 100644 (file)
@@ -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