From 1ff0ee525698f0368d40318348884c52adc16160 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jan=20=C4=8Cerm=C3=A1k?= Date: Wed, 9 Jul 2025 14:52:47 +0200 Subject: [PATCH] Implement logging through Systemd native Journal protocol Use JournaldLogHandler from logging-journald [1] to log events from Python logging to Systemd journal directly. This makes it possible to better filter the log messages based on priority and persist more useful metadata (like filename and line number) for the log events in the Journal. The Journal log priority is also distingushed based on different log priorities of logging events. Another advantage is that stack traces are saved as a single log event rather than multiple separated lines printed to container stdout/stderr. The coloring isn't done using ANSI escape sequences from the ColoredFormatter anymore, resulting in plaintext MESSAGE fields (instead of byte arrays). Colors are added based on the priority metadata when the events are read from the Systemd Journal Gatewayd to maintain backwards compatibility. To correctly match non-Python error logs, log entries must be written to the Journal with the same SYSLOG_IDENTIFIER field as the logs coming form the container directly (e.g. from s6, bashio, etc.). To obtain the Python logs through the docker logs command, container ID (obtained though a hacky method currently) is added to the log records as well - this is useful to keep the falllback method for getting the logs working. [1] https://github.com/mosquito/logging-journald/ [2] https://systemd.io/JOURNAL_NATIVE_PROTOCOL/ --- requirements.txt | 1 + supervisor/bootstrap.py | 38 +++++++++++++++-------- supervisor/host/sound.py | 2 +- supervisor/utils/logging.py | 48 +++++++++++++++++++++++++++++ supervisor/utils/systemd_journal.py | 41 ++++++++++++++++++++++-- 5 files changed, 114 insertions(+), 16 deletions(-) diff --git a/requirements.txt b/requirements.txt index 29eb5e041..744a4bf17 100644 --- a/requirements.txt +++ b/requirements.txt @@ -17,6 +17,7 @@ faust-cchardet==2.1.19 gitpython==3.1.44 jinja2==3.1.6 log-rate-limit==1.4.2 +logging-journald==0.6.11 orjson==3.10.18 pulsectl==24.12.0 pyudev==0.24.3 diff --git a/supervisor/bootstrap.py b/supervisor/bootstrap.py index a77587bfb..f7a36c186 100644 --- a/supervisor/bootstrap.py +++ b/supervisor/bootstrap.py @@ -46,6 +46,7 @@ from .services import ServiceManager from .store import StoreManager from .supervisor import Supervisor from .updater import Updater +from .utils.logging import HAOSLogHandler from .utils.sentry import capture_exception, init_sentry _LOGGER: logging.Logger = logging.getLogger(__name__) @@ -246,20 +247,31 @@ def initialize_logging() -> None: # suppress overly verbose logs from libraries that aren't helpful logging.getLogger("aiohttp.access").setLevel(logging.WARNING) - logging.getLogger().handlers[0].setFormatter( - ColoredFormatter( - colorfmt, - datefmt=datefmt, - reset=True, - log_colors={ - "DEBUG": "cyan", - "INFO": "green", - "WARNING": "yellow", - "ERROR": "red", - "CRITICAL": "red", - }, + default_handler = logging.getLogger().handlers[0] + + if HAOSLogHandler.is_available(): + # replace the default logging handler with JournaldLogHandler + logging.getLogger().removeHandler(default_handler) + supervisor_name = os.environ[ENV_SUPERVISOR_NAME] + journald_handler = HAOSLogHandler(identifier=supervisor_name) + journald_handler.setFormatter(logging.Formatter(fmt, datefmt=datefmt)) + logging.getLogger().addHandler(journald_handler) + else: + default_handler.setFormatter( + ColoredFormatter( + colorfmt, + datefmt=datefmt, + reset=True, + log_colors={ + "DEBUG": "cyan", + "INFO": "green", + "WARNING": "yellow", + "ERROR": "red", + "CRITICAL": "red", + }, + ) ) - ) + warnings.showwarning = warning_handler diff --git a/supervisor/host/sound.py b/supervisor/host/sound.py index 39583c22c..991c7ea0f 100644 --- a/supervisor/host/sound.py +++ b/supervisor/host/sound.py @@ -339,7 +339,7 @@ class SoundControl(CoreSysAttributes): profile.name == card.profile_active.name, ) for profile in card.profile_list - if profile.available + if profile.is_available ], ) for card in pulse.card_list() diff --git a/supervisor/utils/logging.py b/supervisor/utils/logging.py index e43d8c45d..22587c372 100644 --- a/supervisor/utils/logging.py +++ b/supervisor/utils/logging.py @@ -7,6 +7,8 @@ import logging.handlers import queue from typing import Any +from logging_journald import Facility, JournaldLogHandler + class AddonLoggerAdapter(logging.LoggerAdapter): """Logging Adapter which prepends log entries with add-on name.""" @@ -59,6 +61,52 @@ class SupervisorQueueHandler(logging.handlers.QueueHandler): self.listener = None +class HAOSLogHandler(JournaldLogHandler): + """Log handler for writing logs to the Home Assistant OS Systemd Journal.""" + + SYSLOG_FACILITY = Facility.LOCAL7 + + def __init__(self, identifier: str | None = None) -> None: + """Initialize the HAOS log handler.""" + super().__init__(identifier=identifier, facility=HAOSLogHandler.SYSLOG_FACILITY) + self._container_id = self._get_container_id() + + @staticmethod + def _get_container_id() -> str | None: + """Get the container ID if running inside a Docker container.""" + # Currently we only have this hacky way of getting the container ID, + # we (probably) cannot get it without having some cgroup namespaces + # mounted in the container or passed it there using other means. + # Not obtaining it will only result in the logs not being available + # through `docker logs` command, so it is not a critical issue. + with open("/proc/self/mountinfo") as f: + for line in f: + if "/docker/containers/" in line: + container_id = line.split("/docker/containers/")[-1] + return container_id.split("/")[0] + return None + + @classmethod + def is_available(cls) -> bool: + """Check if the HAOS log handler can be used.""" + return cls.SOCKET_PATH.exists() + + def emit(self, record: logging.LogRecord) -> None: + """Emit formatted log record to the Systemd Journal. + + If CONTAINER_ID is known, add it to the fields to make the log record + available through `docker logs` command. + """ + try: + formatted = self._format_record(record) + if self._container_id: + # only container ID is needed for interpretation through `docker logs` + formatted.append(("CONTAINER_ID", self._container_id)) + self.transport.send(formatted) + except Exception: + self._fallback(record) + + def activate_log_queue_handler() -> None: """Migrate the existing log handlers to use the queue. diff --git a/supervisor/utils/systemd_journal.py b/supervisor/utils/systemd_journal.py index 4169f8339..e71cd1d2c 100644 --- a/supervisor/utils/systemd_journal.py +++ b/supervisor/utils/systemd_journal.py @@ -5,11 +5,25 @@ from collections.abc import AsyncGenerator from datetime import UTC, datetime from functools import wraps import json +import logging +from types import MappingProxyType from aiohttp import ClientResponse +from colorlog.escape_codes import escape_codes, parse_colors from supervisor.exceptions import MalformedBinaryEntryError from supervisor.host.const import LogFormatter +from supervisor.utils.logging import HAOSLogHandler + +_LOG_COLORS = MappingProxyType( + { + HAOSLogHandler.LEVELS[logging.DEBUG]: "cyan", + HAOSLogHandler.LEVELS[logging.INFO]: "green", + HAOSLogHandler.LEVELS[logging.WARNING]: "yellow", + HAOSLogHandler.LEVELS[logging.ERROR]: "red", + HAOSLogHandler.LEVELS[logging.CRITICAL]: "red", + } +) def formatter(required_fields: list[str]): @@ -24,15 +38,34 @@ def formatter(required_fields: list[str]): def wrapper(*args, **kwargs): return func(*args, **kwargs) - wrapper.required_fields = ["__CURSOR"] + required_fields + implicit_fields = ["__CURSOR", "SYSLOG_FACILITY", "PRIORITY"] + wrapper.required_fields = implicit_fields + required_fields return wrapper return decorator +def _entry_is_haos_log(entry: dict[str, str]) -> bool: + """Check if the entry is a Home Assistant Operating System log entry.""" + return entry.get("SYSLOG_FACILITY") == str(HAOSLogHandler.SYSLOG_FACILITY) + + +def colorize_message(message: str, priority: str | None = None) -> str: + """Colorize a log message using ANSI escape codes based on its priority.""" + if priority and priority.isdigit(): + color = _LOG_COLORS.get(int(priority)) + if color is not None: + escape_code = parse_colors(color) + return f"{escape_code}{message}{escape_codes['reset']}" + return message + + @formatter(["MESSAGE"]) def journal_plain_formatter(entries: dict[str, str]) -> str: """Format parsed journal entries as a plain message.""" + if _entry_is_haos_log(entries): + return colorize_message(entries["MESSAGE"], entries.get("PRIORITY")) + return entries["MESSAGE"] @@ -58,7 +91,11 @@ def journal_verbose_formatter(entries: dict[str, str]) -> str: else entries.get("SYSLOG_IDENTIFIER", "_UNKNOWN_") ) - return f"{ts} {entries.get('_HOSTNAME', '')} {identifier}: {entries.get('MESSAGE', '')}" + message = entries.get("MESSAGE", "") + if message and _entry_is_haos_log(entries): + message = colorize_message(message, entries.get("PRIORITY")) + + return f"{ts} {entries.get('_HOSTNAME', '')} {identifier}: {message}" async def journal_logs_reader(