diff --git a/decnet/config.py b/decnet/config.py index 15fa764..f1925b3 100644 --- a/decnet/config.py +++ b/decnet/config.py @@ -64,6 +64,7 @@ def _configure_logging(dev: bool) -> None: produce readable logs. File handler is skipped under pytest. """ import logging.handlers as _lh + from decnet.logging.inode_aware_handler import InodeAwareRotatingFileHandler root = logging.getLogger() # Guard: if our StreamHandler is already installed, all handlers are set. @@ -82,7 +83,7 @@ def _configure_logging(dev: bool) -> None: _in_pytest = any(k.startswith("PYTEST") for k in os.environ) if not _in_pytest: _log_path = os.environ.get("DECNET_SYSTEM_LOGS", "decnet.system.log") - file_handler = _lh.RotatingFileHandler( + file_handler = InodeAwareRotatingFileHandler( _log_path, mode="a", maxBytes=10 * 1024 * 1024, # 10 MB diff --git a/decnet/logging/file_handler.py b/decnet/logging/file_handler.py index d095a77..e806c39 100644 --- a/decnet/logging/file_handler.py +++ b/decnet/logging/file_handler.py @@ -13,6 +13,7 @@ import logging.handlers import os from pathlib import Path +from decnet.logging.inode_aware_handler import InodeAwareRotatingFileHandler from decnet.privdrop import chown_to_invoking_user, chown_tree_to_invoking_user from decnet.telemetry import traced as _traced @@ -21,7 +22,7 @@ _DEFAULT_LOG_FILE = "/var/log/decnet/decnet.log" _MAX_BYTES = 10 * 1024 * 1024 # 10 MB _BACKUP_COUNT = 5 -_handler: logging.handlers.RotatingFileHandler | None = None +_handler: InodeAwareRotatingFileHandler | None = None _logger: logging.Logger | None = None @@ -36,7 +37,7 @@ def _init_file_handler() -> logging.Logger: # so a subsequent non-root `decnet api` can also write to it. chown_tree_to_invoking_user(log_path.parent) - _handler = logging.handlers.RotatingFileHandler( + _handler = InodeAwareRotatingFileHandler( log_path, maxBytes=_MAX_BYTES, backupCount=_BACKUP_COUNT, diff --git a/decnet/logging/inode_aware_handler.py b/decnet/logging/inode_aware_handler.py new file mode 100644 index 0000000..9b03b63 --- /dev/null +++ b/decnet/logging/inode_aware_handler.py @@ -0,0 +1,52 @@ +""" +RotatingFileHandler that detects external deletion or rotation. + +Stdlib ``RotatingFileHandler`` holds an open file descriptor for the +lifetime of the handler. If the target file is deleted (``rm``) or +rotated out (``logrotate`` without ``copytruncate``), the handler keeps +writing to the now-orphaned inode until its own size-based rotation +finally triggers — silently losing every line in between. + +Stdlib ``WatchedFileHandler`` solves exactly this problem but doesn't +rotate by size. This subclass combines both: before each emit we stat +the configured path and compare its inode/device to the currently open +file; on mismatch we close and reopen. + +Cheap: one ``os.stat`` per log record. Matches the pattern used by +``decnet/collector/worker.py:_reopen_if_needed``. +""" +from __future__ import annotations + +import logging +import logging.handlers +import os + + +class InodeAwareRotatingFileHandler(logging.handlers.RotatingFileHandler): + """RotatingFileHandler that reopens the target on external rotation/deletion.""" + + def _should_reopen(self) -> bool: + if self.stream is None: + return True + try: + disk_stat = os.stat(self.baseFilename) + except FileNotFoundError: + return True + except OSError: + return False + try: + open_stat = os.fstat(self.stream.fileno()) + except OSError: + return True + return (disk_stat.st_ino != open_stat.st_ino + or disk_stat.st_dev != open_stat.st_dev) + + def emit(self, record: logging.LogRecord) -> None: + if self._should_reopen(): + try: + if self.stream is not None: + self.close() + except Exception: # nosec B110 + pass + self.stream = self._open() + super().emit(record) diff --git a/tests/test_inode_aware_handler.py b/tests/test_inode_aware_handler.py new file mode 100644 index 0000000..b066888 --- /dev/null +++ b/tests/test_inode_aware_handler.py @@ -0,0 +1,91 @@ +""" +Tests for InodeAwareRotatingFileHandler. + +Simulates the two scenarios that break plain RotatingFileHandler: + 1. External `rm` of the log file + 2. External rename (logrotate-style rotation) + +In both cases, the next log record must end up in a recreated file on +disk, not the orphaned inode held by the old file descriptor. +""" +import logging +import os + +import pytest + +from decnet.logging.inode_aware_handler import InodeAwareRotatingFileHandler + + +def _make_handler(path) -> logging.Handler: + h = InodeAwareRotatingFileHandler(str(path), maxBytes=10_000_000, backupCount=1) + h.setFormatter(logging.Formatter("%(message)s")) + return h + + +def _record(msg: str) -> logging.LogRecord: + return logging.LogRecord("t", logging.INFO, __file__, 1, msg, None, None) + + +def test_writes_land_in_file(tmp_path): + path = tmp_path / "app.log" + h = _make_handler(path) + h.emit(_record("hello")) + h.close() + assert path.read_text().strip() == "hello" + + +def test_reopens_after_unlink(tmp_path): + path = tmp_path / "app.log" + h = _make_handler(path) + h.emit(_record("first")) + os.remove(path) # simulate `rm decnet.system.log` + assert not path.exists() + + h.emit(_record("second")) + h.close() + + assert path.exists() + assert path.read_text().strip() == "second" + + +def test_reopens_after_rename(tmp_path): + """logrotate rename-and-create: the old path is renamed, then we expect + writes to go to a freshly created file at the original path.""" + path = tmp_path / "app.log" + h = _make_handler(path) + h.emit(_record("pre-rotation")) + + rotated = tmp_path / "app.log.1" + os.rename(path, rotated) # simulate logrotate move + + h.emit(_record("post-rotation")) + h.close() + + assert rotated.read_text().strip() == "pre-rotation" + assert path.read_text().strip() == "post-rotation" + + +def test_no_reopen_when_file_is_stable(tmp_path, monkeypatch): + """Ensure we don't thrash: back-to-back emits must share one FD.""" + path = tmp_path / "app.log" + h = _make_handler(path) + h.emit(_record("one")) + fd_before = h.stream.fileno() + h.emit(_record("two")) + fd_after = h.stream.fileno() + assert fd_before == fd_after + h.close() + assert path.read_text().splitlines() == ["one", "two"] + + +def test_rotation_by_size_still_works(tmp_path): + """maxBytes-triggered rotation must still function on top of the inode check.""" + path = tmp_path / "app.log" + h = InodeAwareRotatingFileHandler(str(path), maxBytes=50, backupCount=1) + h.setFormatter(logging.Formatter("%(message)s")) + for i in range(20): + h.emit(_record(f"line-{i:03d}-xxxxxxxxxxxxxxx")) + h.close() + + assert path.exists() + assert (tmp_path / "app.log.1").exists()