From 8e81528e1a89948db9015dc581a8468a5b3ba837 Mon Sep 17 00:00:00 2001 From: spacemanspiff2007 <10754716+spacemanspiff2007@users.noreply.github.com> Date: Mon, 14 Oct 2024 12:55:22 +0200 Subject: [PATCH] reworked some logging setup --- src/HABApp/config/debug.py | 15 +-- src/HABApp/config/loader.py | 19 ++- src/HABApp/config/logging/__init__.py | 3 +- src/HABApp/config/logging/config.py | 180 ++++++++++++++------------ src/HABApp/config/logging/handler.py | 5 +- src/HABApp/config/logging/utils.py | 25 ++++ tests/test_config/test_logging.py | 83 ++++++++++++ 7 files changed, 221 insertions(+), 109 deletions(-) create mode 100644 src/HABApp/config/logging/utils.py create mode 100644 tests/test_config/test_logging.py diff --git a/src/HABApp/config/debug.py b/src/HABApp/config/debug.py index 170807a3..91ef20ae 100644 --- a/src/HABApp/config/debug.py +++ b/src/HABApp/config/debug.py @@ -4,6 +4,7 @@ from pathlib import Path import HABApp +from HABApp.config.logging import rotate_file from HABApp.core.asyncio import create_task from HABApp.core.items.base_valueitem import datetime @@ -12,7 +13,7 @@ def _get_file_path(nr: int) -> Path: assert nr >= 0 # noqa: S101 log_dir = HABApp.CONFIG.directories.logging ctr = f'.{nr}' if nr else '' - return log_dir / f'HABApp_traceback{ctr:s}.log' + return log_dir / f'HABApp_traceback.log{ctr:s}' def setup_debug() -> None: @@ -23,17 +24,7 @@ def setup_debug() -> None: file = _get_file_path(0) logging.getLogger('HABApp').info(f'Dumping traceback to {file}') - # rotate files - keep = 3 - _get_file_path(keep).unlink(missing_ok=True) - for i in range(keep - 1, -1, -1): - src = _get_file_path(i) - if not src.is_file(): - continue - - dst = _get_file_path(i + 1) - dst.unlink(missing_ok=True) - src.rename(dst) + rotate_file(file, 3) task = create_task( dump_traceback_task( diff --git a/src/HABApp/config/loader.py b/src/HABApp/config/loader.py index 76abf23b..55b3fbf8 100644 --- a/src/HABApp/config/loader.py +++ b/src/HABApp/config/loader.py @@ -8,11 +8,11 @@ import HABApp from HABApp import __version__ from HABApp.config.config import CONFIG -from HABApp.config.logging import HABAppQueueHandler +from HABApp.config.logging import HABAppQueueHandler, load_logging_file from .debug import setup_debug from .errors import AbsolutePathExpected, InvalidConfigError -from .logging import create_default_logfile, get_logging_dict, inject_log_buffer, rotate_files +from .logging import create_default_logfile, get_logging_dict from .logging.buffered_logger import BufferedLogger @@ -111,17 +111,16 @@ def stop_queue_handlers() -> None: qh.stop() -def load_logging_cfg(path: Path): +def load_logging_cfg(path: Path) -> None: + # If the logging file gets accidentally deleted we do nothing + if (logging_yaml := load_logging_file(path)) is None: + return None + # stop buffered handlers stop_queue_handlers() buf_log = BufferedLogger() - cfg = get_logging_dict(path, buf_log) - - if CONFIG.habapp.logging.use_buffer: - q_handlers = inject_log_buffer(cfg, buf_log) - else: - q_handlers = [] + cfg, q_handlers = get_logging_dict(logging_yaml, buf_log) # load prepared logging try: @@ -131,8 +130,6 @@ def load_logging_cfg(path: Path): log.error(f'Error loading logging config: {e}') raise InvalidConfigError from None - rotate_files() - # start buffered handlers for qh in q_handlers: QUEUE_HANDLER.append(qh) diff --git a/src/HABApp/config/logging/__init__.py b/src/HABApp/config/logging/__init__.py index b0c0e311..edc0c3da 100644 --- a/src/HABApp/config/logging/__init__.py +++ b/src/HABApp/config/logging/__init__.py @@ -1,7 +1,8 @@ from .handler import MidnightRotatingFileHandler, CompressedMidnightRotatingFileHandler +from .utils import rotate_file # isort: split -from .config import get_logging_dict, rotate_files, inject_log_buffer +from .config import load_logging_file, get_logging_dict, inject_queue_handler from .default_logfile import get_default_logfile, create_default_logfile from .queue_handler import HABAppQueueHandler diff --git a/src/HABApp/config/logging/config.py b/src/HABApp/config/logging/config.py index 758582f9..fdd2f3e6 100644 --- a/src/HABApp/config/logging/config.py +++ b/src/HABApp/config/logging/config.py @@ -1,139 +1,117 @@ import logging import logging.config -from logging.handlers import RotatingFileHandler, TimedRotatingFileHandler from pathlib import Path from queue import Queue from typing import Any from easyconfig.yaml import yaml_safe as _yaml_safe -import HABApp from HABApp.config.config import CONFIG from HABApp.config.errors import AbsolutePathExpected +from HABApp.config.logging import rotate_file from HABApp.core.const.const import PYTHON_312, PYTHON_313 +from HABApp.core.const.log import TOPIC_EVENTS from .buffered_logger import BufferedLogger from .queue_handler import HABAppQueueHandler, SimpleQueue -def remove_memory_handler_from_cfg(cfg: dict, log: BufferedLogger) -> None: +def fix_old_logger_location(handlers_cfg: dict, log: BufferedLogger) -> None: + src = 'HABApp.core.lib.handler.MidnightRotatingFileHandler' + dst = 'HABApp.config.logging.MidnightRotatingFileHandler' + + # fix filenames + for handler, cfg in handlers_cfg.items(): + # migrate handler + if cfg.get('class', '-') == src: + cfg['class'] = dst + log.warning(f'Replaced class for handler "{handler:s}" with {dst:s}') + + +def fix_log_filenames(handlers_cfg: dict) -> None: + for cfg in handlers_cfg.values(): + if (filename := cfg.get('filename')) is None: + continue + + # fix encoding for FileHandlers - we always log utf-8 + if 'file' in cfg.get('class', '').lower() and cfg.get('encoding', '') != 'utf-8': + cfg['encoding'] = 'utf-8' + + # make Filenames absolute path in the log folder if not specified + p = Path(filename) + if not p.is_absolute(): + # Our log folder ist not yet converted to path -> it is not loaded + if not CONFIG.directories.logging.is_absolute(): + raise AbsolutePathExpected() + + # Use defined parent folder + p = (CONFIG.directories.logging / p).resolve() + cfg['filename'] = str(p) + + +def remove_memory_handler_from_cfg(handlers_cfg: dict, loggers_cfg: dict, log: BufferedLogger) -> None: # find memory handlers - m_handlers = {} - for handler, handler_cfg in cfg.get('handlers', {}).items(): + memory_targets = {} + for handler, handler_cfg in handlers_cfg.items(): if handler_cfg.get('class', '') == 'logging.handlers.MemoryHandler': log.error(f'"logging.handlers.MemoryHandler" is no longer required. Please remove from config ({handler})!') if 'target' in handler_cfg: - m_handlers[handler] = handler_cfg['target'] + memory_targets[handler] = handler_cfg['target'] # remove them from config - for h_name in m_handlers: - cfg['handlers'].pop(h_name) + for h_name in memory_targets: + handlers_cfg.pop(h_name) log.warning(f'Removed {h_name:s} from handlers') # replace handlers in logger with target - for logger_name, logger_cfg in cfg.get('loggers', {}).items(): + for logger_name, logger_cfg in loggers_cfg.items(): logger_handlers = logger_cfg.get('handlers', []) for i, logger_handler in enumerate(logger_handlers): - replacement_handler = m_handlers.get(logger_handler) - if replacement_handler is None: + if (replacement_handler := memory_targets.get(logger_handler)) is None: continue log.warning(f'Replaced {logger_handler} with {replacement_handler} for logger {logger_name}') logger_handlers[i] = replacement_handler -def get_logging_dict(path: Path, log: BufferedLogger) -> dict | None: - # config gets created on startup - if it gets deleted we do nothing here +def load_logging_file(path: Path) -> dict[str, Any] | None: if not path.is_file(): return None with path.open('r', encoding='utf-8') as file: cfg: dict[str, Any] = _yaml_safe.load(file) - - # fix filenames - for handler, handler_cfg in cfg.get('handlers', {}).items(): - # migrate handler - if handler_cfg.get('class', '-') == 'HABApp.core.lib.handler.MidnightRotatingFileHandler': - dst = 'HABApp.config.logging.MidnightRotatingFileHandler' - handler_cfg['class'] = dst - log.warning(f'Replaced class for handler "{handler:s}" with {dst}') - - if 'filename' not in handler_cfg: - continue - - # fix encoding for FileHandlers - we always log utf-8 - if 'file' in handler_cfg.get('class', '').lower(): - enc = handler_cfg.get('encoding', '') - if enc != 'utf-8': - handler_cfg['encoding'] = 'utf-8' - - # make Filenames absolute path in the log folder if not specified - p = Path(handler_cfg['filename']) - if not p.is_absolute(): - # Our log folder ist not yet converted to path -> it is not loaded - if not CONFIG.directories.logging.is_absolute(): - raise AbsolutePathExpected() - - # Use defined parent folder - p = (CONFIG.directories.logging / p).resolve() - handler_cfg['filename'] = str(p) - - # remove memory handlers - remove_memory_handler_from_cfg(cfg, log) - - # make file version optional for config file - if 'version' not in cfg: - cfg['version'] = 1 - else: - log.warning('Entry "version" is no longer required in the logging configuration file') - - # Allow the user to set his own logging levels (with aliases) - for level, alias in cfg.pop('levels', {}).items(): - if not isinstance(level, int): - level = logging._nameToLevel[level] - logging.addLevelName(level, str(alias)) - log.debug(f'Added custom Level "{alias!s}" ({level})') - return cfg -def rotate_files() -> None: - for wr in logging._handlerList: - handler = wr() # weakref -> call it to get object - - # only rotate these types - if not isinstance(handler, (RotatingFileHandler, TimedRotatingFileHandler)): +def rotate_handler_files(handlers_cfg: dict) -> None: + for cfg in handlers_cfg.values(): + if (filename := cfg.get('filename')) is None: continue - - # Rotate only if files have content - logfile = Path(handler.baseFilename) - if not logfile.is_file() or logfile.stat().st_size <= 10: + if (backup_count := cfg.get('backupCount')) is None: continue + file = Path(filename) - try: - handler.acquire() - handler.flush() - handler.doRollover() - except Exception as e: - HABApp.core.wrapper.process_exception(rotate_files, e) - finally: - handler.release() + # If the file is empty we do not rotate + if not file.is_file() or file.stat().st_size <= 10: # noqa: PLR2004 + continue + rotate_file(file, backup_count) -def inject_log_buffer(cfg: dict, log: BufferedLogger): - from HABApp.core.const.log import TOPIC_EVENTS - handler_cfg = cfg.setdefault('handlers', {}) +def inject_queue_handler(handlers_cfg: dict, loggers_cfg: dict, log: BufferedLogger) -> list[HABAppQueueHandler]: + if not CONFIG.habapp.logging.use_buffer: + return [] prefix = 'HABAppQueue_' # Check that the prefix is unique - for handler_name in handler_cfg: + for handler_name in handlers_cfg: if handler_name.startswith(prefix): - raise ValueError(f'Handler may not start with {prefix:s}') + msg = f'Handler may not start with {prefix:s}' + raise ValueError(msg) # replace the event logs with the buffered one buffered_handlers = {} - for log_name, log_cfg in cfg.get('loggers', {}).items(): + for log_name, log_cfg in loggers_cfg.items(): if not log_name.startswith(TOPIC_EVENTS): continue _handlers = {n: f'{prefix}{n}' for n in log_cfg['handlers']} @@ -148,7 +126,6 @@ def inject_log_buffer(cfg: dict, log: BufferedLogger): if not buffered_handlers: return [] - handler_cfg = cfg.setdefault('handlers', {}) q_handlers: list[HABAppQueueHandler] = [] for handler_name, buffered_handler_name in buffered_handlers.items(): @@ -159,9 +136,44 @@ def inject_log_buffer(cfg: dict, log: BufferedLogger): q = Queue() else: q: SimpleQueue = SimpleQueue() - handler_cfg[buffered_handler_name] = {'class': 'logging.handlers.QueueHandler', 'queue': q} + handlers_cfg[buffered_handler_name] = {'class': 'logging.handlers.QueueHandler', 'queue': q} qh = HABAppQueueHandler(q, handler_name, f'LogBuffer{handler_name:s}') q_handlers.append(qh) return q_handlers + + +def process_custom_levels(cfg: dict[str, Any], log: BufferedLogger) -> None: + for level, alias in cfg.pop('levels', {}).items(): + if not isinstance(level, int): + # noinspection PyProtectedMember + level = logging._nameToLevel[level] # noqa: PLW2901 + logging.addLevelName(level, str(alias)) + log.debug(f'Added custom log level "{alias!s}" ({level})') + + +def get_logging_dict(cfg: dict[str, Any] | None, + log: BufferedLogger | logging.Logger) -> tuple[dict[str, Any], list[HABAppQueueHandler]]: + + # make file version optional for config file + if 'version' in cfg: + log.warning('Entry "version" is no longer required in the logging configuration file') + else: + cfg['version'] = 1 + + handlers_cfg = cfg.get('handlers', {}) + loggers_cfg = cfg.get('loggers', {}) + + fix_old_logger_location(handlers_cfg, log) + fix_log_filenames(handlers_cfg) + remove_memory_handler_from_cfg(handlers_cfg, loggers_cfg, log) + + # Rotate files before opening the handlers + rotate_handler_files(handlers_cfg) + + # Allow the user to set his own logging levels (with aliases) + process_custom_levels(cfg, log) + + q_handler = inject_queue_handler(handlers_cfg, loggers_cfg, log) + return cfg, q_handler diff --git a/src/HABApp/config/logging/handler.py b/src/HABApp/config/logging/handler.py index 097b7506..9a08d7d7 100644 --- a/src/HABApp/config/logging/handler.py +++ b/src/HABApp/config/logging/handler.py @@ -1,8 +1,10 @@ import gzip import shutil from datetime import date, datetime +from logging import LogRecord from logging.handlers import RotatingFileHandler from pathlib import Path +from typing import override class MidnightRotatingFileHandler(RotatingFileHandler): @@ -14,7 +16,8 @@ def __init__(self, *args, **kwargs) -> None: super().__init__(*args, **kwargs) self.last_check: date = datetime.now().date() - def shouldRollover(self, record): + @override + def shouldRollover(self, record: LogRecord) -> int: date = datetime.now().date() if date == self.last_check: return 0 diff --git a/src/HABApp/config/logging/utils.py b/src/HABApp/config/logging/utils.py new file mode 100644 index 00000000..ed9f7256 --- /dev/null +++ b/src/HABApp/config/logging/utils.py @@ -0,0 +1,25 @@ +from pathlib import Path + + +def _get_file_name(file: Path, nr: int) -> Path: + if nr < 0: + raise ValueError() + + if nr: + return file.with_name(f'{file.name:s}.{nr:d}') + return file + + +def rotate_file(file: Path, backup_count: int) -> None: + if not isinstance(backup_count, int): + raise TypeError() + + _get_file_name(file, backup_count).unlink(missing_ok=True) + for i in range(backup_count - 1, -1, -1): + src = _get_file_name(file, i) + if not src.is_file(): + continue + + dst = _get_file_name(file, i + 1) + dst.unlink(missing_ok=True) + src.rename(dst) diff --git a/tests/test_config/test_logging.py b/tests/test_config/test_logging.py new file mode 100644 index 00000000..bef9b574 --- /dev/null +++ b/tests/test_config/test_logging.py @@ -0,0 +1,83 @@ +import logging + +from HABApp.config.logging import get_logging_dict +from HABApp.config.logging.config import remove_memory_handler_from_cfg, inject_queue_handler + +log = logging.getLogger('test') + + +def test_add_version(test_logs): + assert get_logging_dict({}, log)[0] == {'version': 1} + + +def get_unpack(log_dict): + value = get_logging_dict(log_dict, log)[0] + value.pop('version') + return value + + +def test_fix_old_logger(test_logs): + cfg = {'handlers': {'my_handler': {'class': 'HABApp.core.lib.handler.MidnightRotatingFileHandler'}}} + dst = {'handlers': {'my_handler': {'class': 'HABApp.config.logging.MidnightRotatingFileHandler'}}} + test_logs.add_expected( + 'test', logging.WARNING, + 'Replaced class for handler "my_handler" with HABApp.config.logging.MidnightRotatingFileHandler' + ) + + assert get_unpack(cfg) == dst + + +def test_remove_memory_handler(test_logs): + cfg = { + 'handlers': { + 'BufferEventFile': {'class': 'logging.handlers.MemoryHandler', 'target': 'EventFile'}, + 'EventFile': {'class': 'logging.handlers.RotatingFileHandler', 'filename': 'events.log'}, + }, + 'loggers': { + 'HABApp.EventBus': {'handlers': ['BufferEventFile'], 'level': 'DEBUG', 'propagate': False} + } + } + + dst = { + 'handlers': { + 'EventFile': {'class': 'logging.handlers.RotatingFileHandler', 'filename': 'events.log'}, + }, + 'loggers': { + 'HABApp.EventBus': {'handlers': ['EventFile'], 'level': 'DEBUG', 'propagate': False} + } + } + + remove_memory_handler_from_cfg(cfg['handlers'], cfg['loggers'], log) + assert cfg == dst + + test_logs.add_expected( + 'test', logging.ERROR, + '"logging.handlers.MemoryHandler" is no longer required. Please remove from config (BufferEventFile)!' + ) + test_logs.add_expected('test', logging.WARNING, 'Removed BufferEventFile from handlers') + test_logs.add_expected('test', logging.WARNING, 'Replaced BufferEventFile with EventFile for logger HABApp.EventBus') + + +def test_inject_queue_handler(): + cfg = { + 'handlers': { + 'EventFile': {'class': 'logging.handlers.RotatingFileHandler', 'filename': 'events.log'}, + }, + 'loggers': { + 'HABApp.EventBus': {'handlers': ['BufferEventFile'], 'level': 'DEBUG', 'propagate': False} + } + } + + handlers = inject_queue_handler(cfg['handlers'], cfg['loggers'], log) + + dst = { + 'handlers': { + 'EventFile': {'class': 'logging.handlers.RotatingFileHandler', 'filename': 'events.log'}, + 'HABAppQueue_BufferEventFile': {'class': 'logging.handlers.QueueHandler', 'queue': handlers[0]._queue}, + }, + 'loggers': { + 'HABApp.EventBus': {'handlers': ['HABAppQueue_BufferEventFile'], 'level': 'DEBUG', 'propagate': False} + } + } + + assert cfg == dst