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 <arksine.code@gmail.com>
This commit is contained in:
Eric Callahan 2023-01-05 19:36:36 -05:00
parent 24dc8914d0
commit 53eda78b11
No known key found for this signature in database
GPG Key ID: 5A1EB336DFB4C71B
3 changed files with 163 additions and 88 deletions

153
moonraker/loghelper.py Normal file
View File

@ -0,0 +1,153 @@
# Log Management
#
# Copyright (C) 2023 Eric Callahan <arksine.code@gmail.com>
#
# 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

View File

@ -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)

View File

@ -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],