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 1/2] 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 29eb5e0412f..744a4bf1738 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 a77587bfb62..f7a36c18656 100644 --- a/supervisor/bootstrap.py +++ b/supervisor/bootstrap.py @@ -46,6 +46,7 @@ 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 39583c22cbe..991c7ea0f67 100644 --- a/supervisor/host/sound.py +++ b/supervisor/host/sound.py @@ -339,7 +339,7 @@ def _get_pulse_data() -> PulseData: 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 e43d8c45d93..22587c37289 100644 --- a/supervisor/utils/logging.py +++ b/supervisor/utils/logging.py @@ -7,6 +7,8 @@ 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 @@ def close(self) -> None: 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 4169f8339ae..e71cd1d2cde 100644 --- a/supervisor/utils/systemd_journal.py +++ b/supervisor/utils/systemd_journal.py @@ -5,11 +5,25 @@ 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 decorator(func): 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( From e440429e48d49649d0e7efdaac3f944c81d4ea38 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jan=20=C4=8Cerm=C3=A1k?= Date: Wed, 9 Jul 2025 15:23:22 +0200 Subject: [PATCH 2/2] Read mountinfo as binary file, ignore board-except for emit fallback --- supervisor/utils/logging.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/supervisor/utils/logging.py b/supervisor/utils/logging.py index 22587c37289..86a48769995 100644 --- a/supervisor/utils/logging.py +++ b/supervisor/utils/logging.py @@ -79,11 +79,11 @@ def _get_container_id() -> str | None: # 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: + with open("/proc/self/mountinfo", mode="rb") as f: for line in f: - if "/docker/containers/" in line: - container_id = line.split("/docker/containers/")[-1] - return container_id.split("/")[0] + if b"/docker/containers/" in line: + container_id = line.split(b"/docker/containers/")[-1] + return str(container_id.split(b"/")[0]) return None @classmethod @@ -103,7 +103,7 @@ def emit(self, record: logging.LogRecord) -> None: # only container ID is needed for interpretation through `docker logs` formatted.append(("CONTAINER_ID", self._container_id)) self.transport.send(formatted) - except Exception: + except Exception: # pylint: disable=broad-except self._fallback(record)