From 0052af88b23001659dab112bc0912d178d9fdc30 Mon Sep 17 00:00:00 2001 From: Ion Reguera Date: Wed, 29 Jul 2026 15:07:13 +0200 Subject: [PATCH] fix(log): record each message once in the journal, with its real priority MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Every CUEMS log line was reaching journald three times, and none of the copies could be filtered by level. 1. pyossia calls the module-level logging.info() helper at import time (reached via cuemsengine.osc). With no handler on the root logger yet, Python runs logging.basicConfig() implicitly, attaching a StreamHandler(stderr) using BASIC_FORMAT. Module loggers here propagate, so from then on every record was re-emitted through it as a second, differently formatted line. Seeding root with a NullHandler makes that implicit basicConfig() a no-op. Propagation is left enabled on purpose: pytest's caplog captures through a root handler and depends on it. 2. Under systemd, stdout and /dev/log both terminate in the same journal, so attaching both handlers recorded every message twice more. Keep only the syslog handler there — it is the only copy carrying the record's real priority, because systemd stamps every stdout line PRIORITY=6 regardless of level, which left journalctl -p (and so `cuems-logs -l/--level` and `-e/--errors`) unable to tell DEBUG from ERROR. Detection is JOURNAL_STREAM, set by systemd exactly when stdout is wired to the journal, so interactive runs and pytest still print to stdout. 3. Give the syslog handler an ident. journald parses SYSLOG_IDENTIFIER off a leading 'TAG:'; without one the entry has no identifier and journalctl falls back to _COMM, truncated by the kernel to 15 characters, so 'controller-engine' appeared as 'controller-engi' and read as a separate process. The PID is left out of the tag so journald's _PID, taken from the socket credentials, stays correct across a fork. Verified on the test2 controller: one journal entry per message, priorities DEBUG=7/WARNING=4/ERROR=3, full identifier, and stdout still used when JOURNAL_STREAM is absent. Test suite 552 passed, unchanged from baseline. --- src/cuemsutils/log.py | 63 ++++++++++++++++++++++++++++++++++++++----- 1 file changed, 57 insertions(+), 6 deletions(-) diff --git a/src/cuemsutils/log.py b/src/cuemsutils/log.py index e10ca1c..87a19ba 100644 --- a/src/cuemsutils/log.py +++ b/src/cuemsutils/log.py @@ -1,12 +1,28 @@ import sys -from logging import getLogger, LoggerAdapter, StreamHandler, Formatter, DEBUG, INFO, ERROR, WARNING, CRITICAL +from logging import getLogger, LoggerAdapter, NullHandler, StreamHandler, Formatter, DEBUG, INFO, ERROR, WARNING, CRITICAL from logging.handlers import SysLogHandler from functools import wraps from os import environ +from os.path import basename import inspect cuemsFormatter = Formatter('[%(asctime)s][%(levelname)s] \tFormitGo (PID: %(process)d)-(%(threadName)-9s)-(%(name)s:%(funcName)s:%(caller)s)> %(message)s') +# Third-party libraries sometimes call the module-level logging.info()/ +# warning() helpers at import time (pyossia does, from cuemsengine.osc). +# Those helpers run logging.basicConfig() whenever the root logger has no +# handlers, which attaches a StreamHandler(stderr) using logging.BASIC_FORMAT +# to root. Since the loggers built below propagate, every CUEMS record then +# gets re-emitted through that handler as a second, differently formatted +# line — on top of the stdout and syslog copies. Under systemd all of them +# land in the same journal, so each message was recorded three times. +# +# Seeding root with a NullHandler makes the implicit basicConfig() a no-op: +# it returns early once root has any handler. Propagation is deliberately +# left enabled — pytest's caplog fixture captures through a root handler and +# depends on records reaching it. +getLogger().addHandler(NullHandler()) + # Cache for module-specific loggers to avoid duplicate handlers _logger_cache = {} @@ -41,22 +57,42 @@ def process(self, msg, kwargs): kwargs['extra'] = extra return msg, kwargs +def _syslog_ident(): + """ + Tag to prefix onto /dev/log datagrams, e.g. 'controller-engine: '. + + journald derives SYSLOG_IDENTIFIER by parsing a leading 'TAG:' or + 'TAG[PID]:' off the datagram. Without one the entry carries no + identifier and journalctl falls back to _COMM, which the kernel + truncates to 15 characters — 'controller-engine' rendered as + 'controller-engi', looking like a second, unrelated process. + + The PID is deliberately left out: journald fills _PID from the socket + credentials, so it is always right, whereas a tag built once at handler + creation would go stale across a fork. + """ + name = basename(sys.argv[0] or '') or 'cuems' + return f'{name}: ' + def main_logger(module_name = None, with_syslog = True, with_stdout = True): """ Create a root logger with a custom formatter. - + Args: module_name: Name of the module to create logger for. Defaults to __name__ if None. with_syslog: Whether to add syslog handler. with_stdout: Whether to add stdout handler. + + Under systemd both handlers terminate in the same journal, so only the + syslog one is attached there — see the comment on the stdout branch. """ if module_name is None: module_name = __name__ - + # Return cached logger if it exists if module_name in _logger_cache: return _logger_cache[module_name] - + logger = getLogger(module_name) try: log_level = log_level_to_obj(environ['CUEMS_LOG_LEVEL'].upper()) @@ -64,16 +100,31 @@ def main_logger(module_name = None, with_syslog = True, with_stdout = True): log_level = DEBUG logger.setLevel(log_level) - if with_stdout: + # Under systemd, stdout and /dev/log both terminate in journald, so + # attaching both handlers records every message twice. Keep the syslog + # one: it is the only copy that carries the record's real priority. + # systemd stamps every stdout line PRIORITY=6 (info) regardless of the + # Python level, so a journalctl -p filter — which is what + # `cuems-logs -l/--level` and `-e/--errors` are built on — cannot tell a + # DEBUG line from an ERROR one on the stdout copy. + # + # JOURNAL_STREAM is set by systemd exactly when stdout/stderr are wired + # to the journal. When it is absent (interactive runs, pytest, a + # container logging elsewhere) stdout is attached as before, so running + # a component by hand still prints to the terminal. + journald_stdout = with_syslog and 'JOURNAL_STREAM' in environ + + if with_stdout and not journald_stdout: sh = StreamHandler(sys.stdout) sh.setFormatter(cuemsFormatter) logger.addHandler(sh) - + if with_syslog: syslog_handler = SysLogHandler( address = '/dev/log', facility = 'local0' ) syslog_handler.setFormatter(cuemsFormatter) + syslog_handler.ident = _syslog_ident() logger.addHandler(syslog_handler) logger_adapter = CuemsLoggerAdapter(logger, {})