diff --git a/src/ecli/utils/logging_config.py b/src/ecli/utils/logging_config.py index eb42684..340b7b5 100755 --- a/src/ecli/utils/logging_config.py +++ b/src/ecli/utils/logging_config.py @@ -24,7 +24,8 @@ - Optional separate error log file (error.log) for ERROR and CRITICAL events. - Optional key event tracing (keytrace.log) enabled via the MOOPS2_KEYTRACE environment variable. - Automatic creation of log directories, with fallback to the system temp directory on failure. - - Safe reconfiguration: clears existing handlers to avoid duplicate logs when called multiple times. + - Safe reconfiguration: removes and closes existing handlers to avoid duplicate logs + and stale file descriptors when called multiple times. - Never raises exceptions; setup-time failures use explicit stderr fallback before curses takes ownership. Usage: @@ -49,6 +50,7 @@ import os import sys import tempfile +import threading from types import TracebackType from typing import Any, Optional @@ -60,6 +62,64 @@ KEY_LOGGER = logging.getLogger("ecli.keyevents") # raw key-press trace +class SafeRotatingFileHandler(logging.handlers.RotatingFileHandler): + """Rotating file handler that never lets rollover failures reach stderr.""" + + _rollover_lock = threading.RLock() + + def doRollover(self) -> None: + """Perform rollover with in-process serialization and recovery.""" + with self._rollover_lock: + try: + super().doRollover() + except FileNotFoundError: + self._recover_base_stream() + except OSError: + self._recover_base_stream() + + def handleError(self, record: logging.LogRecord) -> None: + """Suppress logging-internal stderr writes during curses runtime.""" + del record + return + + def _recover_base_stream(self) -> None: + """Best-effort reopen of the base log after a failed rollover.""" + self._close_stream_quietly() + if self.delay: + return + try: + log_dir = os.path.dirname(self.baseFilename) + if log_dir: + os.makedirs(log_dir, exist_ok=True) + self.stream = self._open() + except OSError: + self.stream = None + + def _close_stream_quietly(self) -> None: + stream = self.stream + self.stream = None + if stream is None: + return + try: + stream.close() + except OSError: + return + + +def _remove_and_close_handlers(target_logger: logging.Logger) -> None: + """Detach, flush, and close all handlers currently on ``target_logger``.""" + for handler in target_logger.handlers[:]: + target_logger.removeHandler(handler) + try: + handler.flush() + except (OSError, ValueError): + pass + try: + handler.close() + except (OSError, ValueError): + pass + + def log_exception_to_file_handlers( message: str, exc: BaseException, @@ -135,9 +195,9 @@ def setup_logging(config: Optional[dict[str, Any]] = None) -> None: when the environment variable ``MOOPS2_KEYTRACE`` is set to ``1/true/yes``; attached to the ``ecli.keyevents`` logger. - Existing handlers on the root logger are cleared to avoid duplicate - records when the function is invoked multiple times (e.g. in unit - tests). + Existing handlers on the root and key-event loggers are removed and closed + to avoid duplicate records and stale file descriptors when the function is + invoked multiple times (e.g. in unit tests). Args: config (dict | None): Optional application configuration blob. @@ -156,7 +216,7 @@ def setup_logging(config: Optional[dict[str, Any]] = None) -> None: Side Effects: - Creates directories for log files if they don’t exist; falls back to the system temp directory on failure. - - Replaces all handlers on the root logger. + - Replaces all handlers on the root logger after closing old handlers. - Configures the namespace logger ``ecli.keyevents`` to not propagate and attaches/clears its handlers independently. @@ -176,6 +236,8 @@ def setup_logging(config: Optional[dict[str, Any]] = None) -> None: ... } >>> setup_logging(config) """ + logging.raiseExceptions = False + if config is None: config = {} # Main Application Logger (e.g., for editor.log). The log directory follows @@ -204,9 +266,14 @@ def setup_logging(config: Optional[dict[str, Any]] = None) -> None: file_formatter = logging.Formatter( "%(asctime)s - %(levelname)-8s - %(name)-15s - %(message)s (%(filename)s:%(lineno)d)" ) + root_logger = logging.getLogger() + key_event_logger = logging.getLogger("ecli.keyevents") + _remove_and_close_handlers(root_logger) + _remove_and_close_handlers(key_event_logger) + file_handler = None try: - file_handler = logging.handlers.RotatingFileHandler( + file_handler = SafeRotatingFileHandler( log_filename, maxBytes=2 * 1024 * 1024, backupCount=5, encoding="utf-8" ) file_handler.setFormatter(file_formatter) @@ -242,7 +309,7 @@ def setup_logging(config: Optional[dict[str, Any]] = None) -> None: if error_log_dir and not os.path.exists(error_log_dir): os.makedirs(error_log_dir, exist_ok=True) - error_file_handler = logging.handlers.RotatingFileHandler( + error_file_handler = SafeRotatingFileHandler( error_log_filename, maxBytes=1 * 1024 * 1024, backupCount=3, @@ -257,9 +324,6 @@ def setup_logging(config: Optional[dict[str, Any]] = None) -> None: ) # Configure the root logger - root_logger = logging.getLogger() - root_logger.handlers = [] # Clear existing root handlers to avoid duplicates - if file_handler: root_logger.addHandler(file_handler) if console_handler: @@ -280,11 +344,9 @@ def setup_logging(config: Optional[dict[str, Any]] = None) -> None: logging.getLogger("asyncio").setLevel(logging.INFO) # Key Event Logger - key_event_logger = logging.getLogger("ecli.keyevents") key_event_logger.propagate = False key_event_logger.setLevel(logging.DEBUG) - # Clear any handlers that might have been added if setup_logging is called multiple times - key_event_logger.handlers = [] + key_event_logger.disabled = False if os.environ.get("MOOPS2_KEYTRACE", "").lower() in {"1", "true", "yes"}: try: @@ -293,7 +355,7 @@ def setup_logging(config: Optional[dict[str, Any]] = None) -> None: if key_trace_log_dir and not os.path.exists(key_trace_log_dir): os.makedirs(key_trace_log_dir, exist_ok=True) - key_trace_handler = logging.handlers.RotatingFileHandler( + key_trace_handler = SafeRotatingFileHandler( key_trace_filename, maxBytes=1 * 1024 * 1024, backupCount=3, diff --git a/tests/utils/test_logging_config.py b/tests/utils/test_logging_config.py new file mode 100644 index 0000000..bc90adc --- /dev/null +++ b/tests/utils/test_logging_config.py @@ -0,0 +1,233 @@ +# SPDX-License-Identifier: GPL-2.0-only +# +# Project: Ecli +# File: tests/utils/test_logging_config.py +# Website: https://www.ecli.io +# Repository: https://github.com/SSobol77/ecli +# PyPI: https://pypi.org/project/ecli-editor/0.0.1/ +# +# Copyright (c) 2026 Siergej Sobolewski +# +# Licensed under the GNU General Public License version 2 only. +# See the LICENSE file in the project root for full license text. + +from __future__ import annotations + +import logging +import sys +from collections.abc import Iterator +from pathlib import Path + +import pytest + +from ecli.utils.logging_config import SafeRotatingFileHandler, setup_logging + + +@pytest.fixture(autouse=True) +def isolated_logging(monkeypatch: pytest.MonkeyPatch) -> Iterator[None]: + root_logger = logging.getLogger() + key_logger = logging.getLogger("ecli.keyevents") + + old_root_handlers = root_logger.handlers[:] + old_root_level = root_logger.level + old_key_handlers = key_logger.handlers[:] + old_key_level = key_logger.level + old_key_propagate = key_logger.propagate + old_key_disabled = key_logger.disabled + old_raise_exceptions = logging.raiseExceptions + + for handler in old_root_handlers: + root_logger.removeHandler(handler) + for handler in old_key_handlers: + key_logger.removeHandler(handler) + + monkeypatch.delenv("ECLI_LOG_DIR", raising=False) + monkeypatch.delenv("MOOPS2_KEYTRACE", raising=False) + + yield + + _close_attached_handlers(root_logger) + _close_attached_handlers(key_logger) + + root_logger.setLevel(old_root_level) + key_logger.setLevel(old_key_level) + key_logger.propagate = old_key_propagate + key_logger.disabled = old_key_disabled + logging.raiseExceptions = old_raise_exceptions + + for handler in old_root_handlers: + root_logger.addHandler(handler) + for handler in old_key_handlers: + key_logger.addHandler(handler) + + +def _close_attached_handlers(target_logger: logging.Logger) -> None: + for handler in target_logger.handlers[:]: + target_logger.removeHandler(handler) + handler.close() + + +def _is_closed(handler: logging.Handler) -> bool: + if isinstance(handler, logging.FileHandler): + return handler.stream is None + return bool(getattr(handler, "_closed", False)) + + +def test_setup_logging_twice_does_not_duplicate_handlers( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + monkeypatch.setenv("ECLI_LOG_DIR", str(tmp_path / "logs")) + config = {"logging": {"file_level": "DEBUG", "separate_error_log": True}} + + setup_logging(config) + first_handlers = logging.getLogger().handlers[:] + + setup_logging(config) + second_handlers = logging.getLogger().handlers[:] + + assert len(second_handlers) == 2 + assert all( + isinstance(handler, SafeRotatingFileHandler) for handler in second_handlers + ) + assert {Path(handler.baseFilename).name for handler in second_handlers} == { + "editor.log", + "error.log", + } + assert {id(handler) for handler in first_handlers}.isdisjoint( + {id(handler) for handler in second_handlers} + ) + + +def test_old_handlers_are_closed_on_reconfiguration( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + root_logger = logging.getLogger() + key_logger = logging.getLogger("ecli.keyevents") + old_root_handler = logging.FileHandler(tmp_path / "old-root.log", encoding="utf-8") + old_key_handler = logging.FileHandler(tmp_path / "old-key.log", encoding="utf-8") + root_logger.addHandler(old_root_handler) + key_logger.addHandler(old_key_handler) + + monkeypatch.setenv("ECLI_LOG_DIR", str(tmp_path / "logs")) + + setup_logging() + + assert _is_closed(old_root_handler) + assert _is_closed(old_key_handler) + + +def test_repeated_setup_closes_replaced_file_descriptors( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + monkeypatch.setenv("ECLI_LOG_DIR", str(tmp_path / "logs")) + + setup_logging() + first_handlers = logging.getLogger().handlers[:] + + setup_logging() + + assert first_handlers + assert all(_is_closed(handler) for handler in first_handlers) + + +def test_rollover_file_not_found_does_not_raise_or_write_to_terminal( + tmp_path: Path, + monkeypatch: pytest.MonkeyPatch, + capsys: pytest.CaptureFixture[str], +) -> None: + log_file = tmp_path / "editor.log" + log_file.write_text("seed\n", encoding="utf-8") + calls = 0 + + def fail_rollover(_handler: logging.handlers.RotatingFileHandler) -> None: + nonlocal calls + calls += 1 + raise FileNotFoundError( + "[Errno 2] No such file or directory: 'editor.log.3' -> 'editor.log.4'" + ) + + monkeypatch.setattr( + logging.handlers.RotatingFileHandler, "doRollover", fail_rollover + ) + old_raise_exceptions = logging.raiseExceptions + logging.raiseExceptions = True + logger = logging.getLogger("ecli.test.rollover") + logger.setLevel(logging.INFO) + logger.propagate = False + logger.disabled = False + _close_attached_handlers(logger) + handler = SafeRotatingFileHandler( + log_file, maxBytes=1, backupCount=1, encoding="utf-8" + ) + handler.setFormatter(logging.Formatter("%(message)s")) + logger.addHandler(handler) + + try: + logger.info("after rollover failure") + handler.flush() + finally: + logging.raiseExceptions = old_raise_exceptions + _close_attached_handlers(logger) + + captured = capsys.readouterr() + assert calls == 1 + assert captured.err == "" + assert captured.out == "" + assert "after rollover failure" in log_file.read_text(encoding="utf-8") + + +def test_safe_handler_preserves_successful_rotation(tmp_path: Path) -> None: + log_file = tmp_path / "editor.log" + logger = logging.getLogger("ecli.test.rotation-success") + logger.setLevel(logging.INFO) + logger.propagate = False + logger.disabled = False + _close_attached_handlers(logger) + handler = SafeRotatingFileHandler( + log_file, maxBytes=24, backupCount=1, encoding="utf-8" + ) + handler.setFormatter(logging.Formatter("%(message)s")) + logger.addHandler(handler) + + try: + logger.info("first message that fills the file") + logger.info("second message that rotates it") + handler.flush() + finally: + _close_attached_handlers(logger) + + assert log_file.exists() + assert (tmp_path / "editor.log.1").exists() + + +def test_normal_runtime_attaches_no_stdout_or_stderr_stream_handler( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + monkeypatch.setenv("ECLI_LOG_DIR", str(tmp_path / "logs")) + + setup_logging({"logging": {"log_to_console": True, "file_level": "DEBUG"}}) + + handlers = ( + logging.getLogger().handlers + logging.getLogger("ecli.keyevents").handlers + ) + terminal_streams = {sys.stdout, sys.stderr} + assert all( + getattr(handler, "stream", None) not in terminal_streams for handler in handlers + ) + assert logging.raiseExceptions is False + + +def test_keytrace_uses_safe_rotating_handler_when_enabled( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + monkeypatch.setenv("ECLI_LOG_DIR", str(tmp_path / "logs")) + monkeypatch.setenv("MOOPS2_KEYTRACE", "1") + + setup_logging() + + key_logger = logging.getLogger("ecli.keyevents") + assert key_logger.disabled is False + assert len(key_logger.handlers) == 1 + keytrace_handler = key_logger.handlers[0] + assert isinstance(keytrace_handler, SafeRotatingFileHandler) + assert Path(keytrace_handler.baseFilename).name == "keytrace.log"