#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 {
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");
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;
#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
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);
#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); \
+ }}
logfile=Path(""), # this will be ignored
)
+def sd_booted():
+ return os.path.lexists("/run/systemd/system") # same as in libsystemd
@dataclass
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":
"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),
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,
)
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
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:
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
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
# 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
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 }}
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