fix: RotatingFileHandler reopens on external deletion/rotation
Mirrors the inode-check fix from 935a9a5 (collector worker) for the
stdlib-handler-based log paths. Both decnet.system.log (config.py) and
decnet.log (logging/file_handler.py) now use a subclass that stats the
target path before each emit and reopens on inode/device mismatch —
matching the behavior of stdlib WatchedFileHandler while preserving
size-based rotation.
Previously: rm decnet.system.log → handler kept writing to the orphaned
inode until maxBytes triggered; all lines between were lost.
This commit is contained in:
@@ -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
|
||||
|
||||
@@ -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,
|
||||
|
||||
52
decnet/logging/inode_aware_handler.py
Normal file
52
decnet/logging/inode_aware_handler.py
Normal file
@@ -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)
|
||||
91
tests/test_inode_aware_handler.py
Normal file
91
tests/test_inode_aware_handler.py
Normal file
@@ -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()
|
||||
Reference in New Issue
Block a user