From 53eda78b11c092256476c68f36942451ec0df226 Mon Sep 17 00:00:00 2001 From: Eric Callahan Date: Thu, 5 Jan 2023 19:36:36 -0500 Subject: [PATCH] loghelper: moonraker log management Move logger initialization out of the utils module into its own module, loghelper.py. This manager class simplifies access to the underlying logger implementation and the queue listener. Additionally it allows for endpoint registration. Signed-off-by: Eric Callahan --- moonraker/loghelper.py | 153 +++++++++++++++++++++++++++++++++++++++++ moonraker/moonraker.py | 22 +++--- moonraker/utils.py | 76 -------------------- 3 files changed, 163 insertions(+), 88 deletions(-) create mode 100644 moonraker/loghelper.py diff --git a/moonraker/loghelper.py b/moonraker/loghelper.py new file mode 100644 index 0000000..7ed89a0 --- /dev/null +++ b/moonraker/loghelper.py @@ -0,0 +1,153 @@ +# Log Management +# +# Copyright (C) 2023 Eric Callahan +# +# This file may be distributed under the terms of the GNU GPLv3 license + +from __future__ import annotations +import logging +import logging.handlers +import os +import sys +import asyncio +from queue import SimpleQueue as Queue + +# Annotation imports +from typing import ( + TYPE_CHECKING, + Optional, + Awaitable, + Dict, + List, + Any, +) + +if TYPE_CHECKING: + from moonraker import Server + from websockets import WebRequest + from klippy_connection import KlippyConnection + +# Coroutine friendly QueueHandler courtesy of Martjin Pieters: +# https://www.zopatista.com/python/2019/05/11/asyncio-logging/ +class LocalQueueHandler(logging.handlers.QueueHandler): + def emit(self, record: logging.LogRecord) -> None: + # Removed the call to self.prepare(), handle task cancellation + try: + self.enqueue(record) + except asyncio.CancelledError: + raise + except Exception: + self.handleError(record) + +# Timed Rotating File Handler, based on Klipper's implementation +class MoonrakerLoggingHandler(logging.handlers.TimedRotatingFileHandler): + def __init__(self, app_args: Dict[str, Any], **kwargs) -> None: + super().__init__(app_args['log_file'], **kwargs) + self.rollover_info: Dict[str, str] = { + 'header': f"{'-'*20}Moonraker Log Start{'-'*20}" + } + self.rollover_info['application_args'] = "\n".join( + [f"{k}: {v}" for k, v in app_args.items()]) + lines = [line for line in self.rollover_info.values() if line] + if self.stream is not None: + self.stream.write("\n".join(lines) + "\n") + + def set_rollover_info(self, name: str, item: str) -> None: + self.rollover_info[name] = item + + def doRollover(self) -> None: + super().doRollover() + lines = [line for line in self.rollover_info.values() if line] + if self.stream is not None: + self.stream.write("\n".join(lines) + "\n") + +class LogManager: + def __init__( + self, app_args: Dict[str, Any], startup_warnings: List[str] + ) -> None: + root_logger = logging.getLogger() + queue: Queue = Queue() + queue_handler = LocalQueueHandler(queue) + root_logger.addHandler(queue_handler) + root_logger.setLevel(logging.INFO) + stdout_hdlr = logging.StreamHandler(sys.stdout) + stdout_fmt = logging.Formatter( + '[%(filename)s:%(funcName)s()] - %(message)s') + stdout_hdlr.setFormatter(stdout_fmt) + for name, val in app_args.items(): + logging.info(f"{name}: {val}") + self.file_hdlr: Optional[MoonrakerLoggingHandler] = None + self.listener: Optional[logging.handlers.QueueListener] = None + log_file: str = app_args.get('log_file', "") + if log_file: + try: + self.file_hdlr = MoonrakerLoggingHandler( + app_args, when='midnight', backupCount=2) + formatter = logging.Formatter( + '%(asctime)s [%(filename)s:%(funcName)s()] - %(message)s') + self.file_hdlr.setFormatter(formatter) + self.listener = logging.handlers.QueueListener( + queue, self.file_hdlr, stdout_hdlr) + except Exception: + log_file = os.path.normpath(log_file) + dir_name = os.path.dirname(log_file) + startup_warnings.append( + f"Unable to create log file at '{log_file}'. " + f"Make sure that the folder '{dir_name}' exists " + "and Moonraker has Read/Write access to the folder. " + ) + if self.listener is None: + self.listener = logging.handlers.QueueListener( + queue, stdout_hdlr) + self.listener.start() + + def set_server(self, server: Server) -> None: + self.server = server + self.server.register_endpoint( + "/server/logs/rollover", ['POST'], self._handle_log_rollover + ) + + def set_rollover_info(self, name: str, item: str) -> None: + if self.file_hdlr is not None: + self.file_hdlr.set_rollover_info(name, item) + + def rollover_log(self) -> Awaitable[None]: + if self.file_hdlr is None: + raise self.server.error("File Logging Disabled") + eventloop = self.server.get_event_loop() + return eventloop.run_in_thread(self.file_hdlr.doRollover) + + def stop_logging(self): + self.listener.stop() + + async def _handle_log_rollover( + self, web_request: WebRequest + ) -> Dict[str, Any]: + log_apps = ["moonraker", "klipper"] + app = web_request.get_str("application", None) + result: Dict[str, Any] = {"rolled_over": [], "failed": {}} + if app is not None: + if app not in log_apps: + raise self.server.error(f"Unknown application {app}") + log_apps = [app] + if "moonraker" in log_apps: + try: + ret = self.rollover_log() + if ret is not None: + await ret + except asyncio.CancelledError: + raise + except Exception as e: + result["failed"]["moonraker"] = str(e) + else: + result["rolled_over"].append("moonraker") + if "klipper" in log_apps: + kconn: KlippyConnection + kconn = self.server.lookup_component("klippy_connection") + try: + await kconn.rollover_log() + except self.server.error as e: + result["failed"]["klipper"] = str(e) + else: + result["rolled_over"].append("klipper") + return result diff --git a/moonraker/moonraker.py b/moonraker/moonraker.py index 568ca45..5e71d4e 100755 --- a/moonraker/moonraker.py +++ b/moonraker/moonraker.py @@ -17,12 +17,12 @@ import socket import logging import signal import confighelper -import utils import asyncio from eventloop import EventLoop from app import MoonrakerApp from klippy_connection import KlippyConnection -from utils import ServerError, SentinelClass +from utils import ServerError, SentinelClass, get_software_version +from loghelper import LogManager # Annotation imports from typing import ( @@ -59,11 +59,11 @@ class Server: error = ServerError def __init__(self, args: Dict[str, Any], - file_logger: Optional[utils.MoonrakerLoggingHandler], + log_manager: LogManager, event_loop: EventLoop ) -> None: self.event_loop = event_loop - self.file_logger = file_logger + self.log_manager = log_manager self.app_args = args self.events: Dict[str, List[FlexCallback]] = {} self.components: Dict[str, Any] = {} @@ -92,6 +92,7 @@ class Server: self.register_static_file_handler = app.register_static_file_handler self.register_upload_handler = app.register_upload_handler self.register_api_transport = app.register_api_transport + self.log_manager.set_server(self) for warning in args.get("startup_warnings", []): self.add_warning(warning) @@ -190,8 +191,7 @@ class Server: def add_log_rollover_item(self, name: str, item: str, log: bool = True) -> None: - if self.file_logger is not None: - self.file_logger.set_rollover_info(name, item) + self.log_manager.set_rollover_info(name, item) if log and item is not None: logging.info(item) @@ -479,7 +479,7 @@ def main(cmd_line_args: argparse.Namespace) -> None: } # Setup Logging - version = utils.get_software_version() + version = get_software_version() if cmd_line_args.nologfile: app_args["log_file"] = "" elif cmd_line_args.logfile: @@ -489,9 +489,7 @@ def main(cmd_line_args: argparse.Namespace) -> None: app_args["log_file"] = str(data_path.joinpath("logs/moonraker.log")) app_args["software_version"] = version app_args["python_version"] = sys.version.replace("\n", " ") - ql, file_logger, warning = utils.setup_logging(app_args) - if warning is not None: - startup_warnings.append(warning) + log_manager = LogManager(app_args, startup_warnings) # Start asyncio event loop and server event_loop = EventLoop() @@ -499,7 +497,7 @@ def main(cmd_line_args: argparse.Namespace) -> None: estatus = 0 while True: try: - server = Server(app_args, file_logger, event_loop) + server = Server(app_args, log_manager, event_loop) server.load_components() except confighelper.ConfigError as e: backup_cfg = confighelper.find_config_backup(cfg_file) @@ -548,7 +546,7 @@ def main(cmd_line_args: argparse.Namespace) -> None: event_loop.reset() event_loop.close() logging.info("Server Shutdown") - ql.stop() + log_manager.stop_logging() exit(estatus) diff --git a/moonraker/utils.py b/moonraker/utils.py index f6c8876..fe8cd3a 100644 --- a/moonraker/utils.py +++ b/moonraker/utils.py @@ -6,7 +6,6 @@ from __future__ import annotations import logging -import logging.handlers import os import glob import importlib @@ -20,7 +19,6 @@ import shlex import re import struct import socket -from queue import SimpleQueue as Queue # Annotation imports from typing import ( @@ -30,7 +28,6 @@ from typing import ( ClassVar, Tuple, Dict, - Any, ) if TYPE_CHECKING: @@ -56,40 +53,6 @@ class SentinelClass: SentinelClass._instance = SentinelClass() return SentinelClass._instance -# Coroutine friendly QueueHandler courtesy of Martjin Pieters: -# https://www.zopatista.com/python/2019/05/11/asyncio-logging/ -class LocalQueueHandler(logging.handlers.QueueHandler): - def emit(self, record: logging.LogRecord) -> None: - # Removed the call to self.prepare(), handle task cancellation - try: - self.enqueue(record) - except asyncio.CancelledError: - raise - except Exception: - self.handleError(record) - -# Timed Rotating File Handler, based on Klipper's implementation -class MoonrakerLoggingHandler(logging.handlers.TimedRotatingFileHandler): - def __init__(self, app_args: Dict[str, Any], **kwargs) -> None: - super().__init__(app_args['log_file'], **kwargs) - self.rollover_info: Dict[str, str] = { - 'header': f"{'-'*20}Moonraker Log Start{'-'*20}" - } - self.rollover_info['application_args'] = "\n".join( - [f"{k}: {v}" for k, v in app_args.items()]) - lines = [line for line in self.rollover_info.values() if line] - if self.stream is not None: - self.stream.write("\n".join(lines) + "\n") - - def set_rollover_info(self, name: str, item: str) -> None: - self.rollover_info[name] = item - - def doRollover(self) -> None: - super().doRollover() - lines = [line for line in self.rollover_info.values() if line] - if self.stream is not None: - self.stream.write("\n".join(lines) + "\n") - def _run_git_command(cmd: str) -> str: prog = shlex.split(cmd) process = subprocess.Popen(prog, stdout=subprocess.PIPE, @@ -139,45 +102,6 @@ def get_software_version() -> str: version = "?" return version -def setup_logging(app_args: Dict[str, Any] - ) -> Tuple[logging.handlers.QueueListener, - Optional[MoonrakerLoggingHandler], - Optional[str]]: - root_logger = logging.getLogger() - queue: Queue = Queue() - queue_handler = LocalQueueHandler(queue) - root_logger.addHandler(queue_handler) - root_logger.setLevel(logging.INFO) - stdout_hdlr = logging.StreamHandler(sys.stdout) - stdout_fmt = logging.Formatter( - '[%(filename)s:%(funcName)s()] - %(message)s') - stdout_hdlr.setFormatter(stdout_fmt) - for name, val in app_args.items(): - logging.info(f"{name}: {val}") - warning: Optional[str] = None - file_hdlr: Optional[MoonrakerLoggingHandler] = None - listener: Optional[logging.handlers.QueueListener] = None - log_file: str = app_args.get('log_file', "") - if log_file: - try: - file_hdlr = MoonrakerLoggingHandler( - app_args, when='midnight', backupCount=2) - formatter = logging.Formatter( - '%(asctime)s [%(filename)s:%(funcName)s()] - %(message)s') - file_hdlr.setFormatter(formatter) - listener = logging.handlers.QueueListener( - queue, file_hdlr, stdout_hdlr) - except Exception: - log_file = os.path.normpath(log_file) - dir_name = os.path.dirname(log_file) - warning = f"Unable to create log file at '{log_file}'. " \ - f"Make sure that the folder '{dir_name}' exists " \ - f"and Moonraker has Read/Write access to the folder. " - if listener is None: - listener = logging.handlers.QueueListener( - queue, stdout_hdlr) - listener.start() - return listener, file_hdlr, warning def hash_directory(dir_path: str, ignore_exts: List[str],