From 1de307e15dee34be90b362149dbf9c5a423fe8ec Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gina=20H=C3=A4u=C3=9Fge?= Date: Fri, 24 Feb 2017 10:53:16 +0100 Subject: [PATCH] Log version, safe mode & plugins to log on log roll over We want to make sure that information is ALWAYS in each and every log. --- src/octoprint/__init__.py | 10 ++- src/octoprint/cli/server.py | 35 +++++++- src/octoprint/logging/__init__.py | 135 +++++++++++++++++++++++++++++- src/octoprint/logging/handlers.py | 15 ++++ src/octoprint/plugin/core.py | 31 ++++--- 5 files changed, 209 insertions(+), 17 deletions(-) diff --git a/src/octoprint/__init__.py b/src/octoprint/__init__.py index 065ac99c..7d6d07ce 100644 --- a/src/octoprint/__init__.py +++ b/src/octoprint/__init__.py @@ -58,7 +58,8 @@ class FatalStartupError(BaseException): def init_platform(basedir, configfile, use_logging_file=True, logging_file=None, logging_config=None, debug=False, verbosity=0, uncaught_logger=None, uncaught_handler=None, safe_mode=False, after_preinit_logging=None, - after_settings=None, after_logging=None, after_safe_mode=None): + after_settings=None, after_logging=None, after_safe_mode=None, + after_plugin_manager=None): kwargs = dict() logger, recorder = preinit_logging(debug, verbosity, uncaught_logger, uncaught_handler) @@ -94,6 +95,11 @@ def init_platform(basedir, configfile, use_logging_file=True, logging_file=None, after_safe_mode(**kwargs) plugin_manager = init_pluginsystem(settings, safe_mode=safe_mode) + kwargs["plugin_manager"] = plugin_manager + + if callable(after_plugin_manager): + after_plugin_manager(**kwargs) + return settings, logger, safe_mode, plugin_manager @@ -176,7 +182,7 @@ def init_logging(settings, use_logging_file=True, logging_file=None, default_con "stream": "ext://sys.stdout" }, "file": { - "class": "octoprint.logging.handlers.CleaningTimedRotatingFileHandler", + "class": "octoprint.logging.handlers.OctoPrintLogHandler", "level": "DEBUG", "formatter": "simple", "when": "D", diff --git a/src/octoprint/cli/server.py b/src/octoprint/cli/server.py index 8f410eb3..ca2d93ef 100644 --- a/src/octoprint/cli/server.py +++ b/src/octoprint/cli/server.py @@ -17,20 +17,24 @@ def run_server(basedir, configfile, host, port, debug, allow_root, logging_confi from octoprint import init_platform, __display_version__, FatalStartupError def log_startup(recorder=None, safe_mode=None, **kwargs): + from octoprint.logging import get_divider_line + logger = logging.getLogger("octoprint.server") + + logger.info(get_divider_line("*")) logger.info("Starting OctoPrint {}".format(__display_version__)) if safe_mode: logger.info("Starting in SAFE MODE. Third party plugins will be disabled!") if recorder and len(recorder): - logger.info("--- Logged during platform initialization: ---") + logger.info(get_divider_line("-", "Logged during platform initialization:")) from octoprint.logging.handlers import CombinedLogHandler handler = CombinedLogHandler(*logging.getLogger().handlers) recorder.setTarget(handler) recorder.flush() - logger.info("----------------------------------------------") + logger.info(get_divider_line("-")) from octoprint import urllib3_ssl if not urllib3_ssl: @@ -41,6 +45,30 @@ def run_server(basedir, configfile, host, port, debug, allow_root, logging_confi "update to a Python version >= 2.7.9 or alternatively " "install PyOpenSSL plus its dependencies. For details see " "https://urllib3.readthedocs.org/en/latest/security.html#openssl-pyopenssl") + logger.info(get_divider_line("*")) + + def log_register_rollover(safe_mode=None, plugin_manager=None, **kwargs): + from octoprint.logging import get_handler, log_to_handler, get_divider_line + from octoprint.logging.handlers import OctoPrintLogHandler + + def rollover_callback(): + handler = get_handler("file") + if handler is None: + return + + logger = logging.getLogger("octoprint.server") + + def _log(message, level=logging.INFO): + log_to_handler(logger, handler, level, message) + + _log(get_divider_line("-", "Log roll over detected")) + _log("OctoPrint {}".format(__display_version__)) + if safe_mode: + _log("SAFE MODE is active. Third party plugins are disabled!") + plugin_manager.log_all_plugins(only_to_handler=handler) + _log(get_divider_line("-")) + + OctoPrintLogHandler.registerRolloverCallback(rollover_callback) try: settings, _, safe_mode, plugin_manager = init_platform(basedir, @@ -50,7 +78,8 @@ def run_server(basedir, configfile, host, port, debug, allow_root, logging_confi verbosity=verbosity, uncaught_logger=__name__, safe_mode=safe_mode, - after_safe_mode=log_startup) + after_safe_mode=log_startup, + after_plugin_manager=log_register_rollover) except FatalStartupError as e: click.echo(e.message, err=True) click.echo("There was a fatal error starting up OctoPrint.", err=True) diff --git a/src/octoprint/logging/__init__.py b/src/octoprint/logging/__init__.py index 6e016b16..1f78abae 100644 --- a/src/octoprint/logging/__init__.py +++ b/src/octoprint/logging/__init__.py @@ -1,4 +1,137 @@ # coding=utf-8 from __future__ import absolute_import -from . import handlers +from octoprint.logging import handlers + +def log_to_handler(logger, handler, level, msg, exc_info=None, extra=None, *args): + """ + Logs to the provided handler only. + + Arguments: + logger: logger to log to + handler: handler to restrict logging to + level: level to log at + msg: message to log + exc_info: optional exception info + extra: optional extra data + *args: log args + """ + from logging import _srcfile + import sys + + # this is just the same as logging.Logger._log + + if _srcfile: + # IronPython doesn't track Python frames, so findCaller raises an + # exception on some versions of IronPython. We trap it here so that + # IronPython can use logging. + try: + fn, lno, func = logger.findCaller() + except ValueError: + fn, lno, func = "(unknown file)", 0, "(unknown function)" + else: + fn, lno, func = "(unknown file)", 0, "(unknown function)" + if exc_info: + if not isinstance(exc_info, tuple): + exc_info = sys.exc_info() + + record = logger.makeRecord(logger.name, level, fn, lno, msg, args, exc_info, func, extra) + + # and this is a mixture of logging.Logger.handle and logging.Logger.callHandlers + + if (not logger.disabled) and logger.filter(record): + if record.levelno >= handler.level: + handler.handle(record) + + +def get_handler(name, logger=None): + """ + Retrieves the handler named ``name``. + + If optional ``logger`` is provided, search will be + limited to that logger, otherwise the root logger will be + searched. + + Arguments: + name: the name of the handler to look for + logger: (optional) the logger to search in, root logger if not provided + + Returns: + the handler if it could be found, None otherwise + """ + import logging + + if logger is None: + logger = logging.getLogger() + + for handler in logger.handlers: + if handler.get_name() == name: + return handler + + return None + + +def get_divider_line(c, message=None, length=78, indent=3): + """ + Generate a divider line for logging, optionally with included message. + + Examples: + + >>> get_divider_line("-") + '------------------------------------------------------------------------------' + >>> get_divider_line("=", length=10) + '==========' + >>> get_divider_line("-", message="Hi", length=10) + '--- Hi ---' + >>> get_divider_line("-", message="A slightly longer text") + '--- A slightly longer text ---------------------------------------------------' + >>> get_divider_line("-", message="A slightly longer text", indent=5) + '----- A slightly longer text -------------------------------------------------' + >>> get_divider_line("-", message="Hello World!", length=10) + '--- Hello World!' + >>> get_divider_line(None) + Traceback (most recent call last): + ... + AssertionError: c is not text + >>> get_divider_line("ยด`") + Traceback (most recent call last): + ... + AssertionError: c is not a single character + >>> get_divider_line("-", message=3) + Traceback (most recent call last): + ... + AssertionError: message is not text + >>> get_divider_line("-", length="hello") + Traceback (most recent call last): + ... + AssertionError: length is not an int + >>> get_divider_line("-", indent="hi") + Traceback (most recent call last): + ... + AssertionError: indent is not an int + + Arguments: + c: character to use for the line + message: message to print in the line + length: length of the line + indent: indentation of message in line + + Returns: + formatted divider line + """ + + assert isinstance(c, (str, unicode, bytes)), "c is not text" + assert len(c) == 1, "c is not a single character" + assert isinstance(length, int), "length is not an int" + assert isinstance(indent, int), "indent is not an int" + + if message is None: + return c * length + + assert isinstance(message, (str, unicode, bytes)), "message is not text" + + space = length - 2 * (indent + 1) + if space >= len(message): + return c * indent + " " + message + " " + c * (length - indent - 2 - len(message)) + else: + return c * indent + " " + message diff --git a/src/octoprint/logging/handlers.py b/src/octoprint/logging/handlers.py index fc2d5e43..7d106a4b 100644 --- a/src/octoprint/logging/handlers.py +++ b/src/octoprint/logging/handlers.py @@ -17,6 +17,21 @@ class CleaningTimedRotatingFileHandler(logging.handlers.TimedRotatingFileHandler os.remove(s) +class OctoPrintLogHandler(CleaningTimedRotatingFileHandler): + rollover_callbacks = [] + + @classmethod + def registerRolloverCallback(cls, callback, *args, **kwargs): + cls.rollover_callbacks.append((callback, args, kwargs)) + + def doRollover(self): + CleaningTimedRotatingFileHandler.doRollover(self) + + for rcb in self.__class__.rollover_callbacks: + callback, args, kwargs = rcb + callback(*args, **kwargs) + + class SerialLogHandler(logging.handlers.RotatingFileHandler): _do_rollover = False diff --git a/src/octoprint/plugin/core.py b/src/octoprint/plugin/core.py index 61ba0ff7..62da7633 100644 --- a/src/octoprint/plugin/core.py +++ b/src/octoprint/plugin/core.py @@ -1062,21 +1062,30 @@ class PluginManager(object): return True - def log_all_plugins(self, show_bundled=True, bundled_str=(" (bundled)", ""), show_location=True, location_str=" = {location}", show_enabled=True, enabled_str=(" ", "!")): + def log_all_plugins(self, show_bundled=True, bundled_str=(" (bundled)", ""), show_location=True, + location_str=" = {location}", show_enabled=True, enabled_str=(" ", "!"), + only_to_handler=None): all_plugins = self.enabled_plugins.values() + self.disabled_plugins.values() + def _log(message, level=logging.INFO): + if only_to_handler is not None: + import octoprint.logging + octoprint.logging.log_to_handler(self.logger, only_to_handler, level, message, []) + else: + self.logger.log(level, message) + if len(all_plugins) <= 0: - self.logger.info("No plugins available") + _log("No plugins available") else: - self.logger.info("{count} plugin(s) registered with the system:\n{plugins}".format(count=len(all_plugins), plugins="\n".join( - map(lambda x: "| " + x.long_str(show_bundled=show_bundled, - bundled_strs=bundled_str, - show_location=show_location, - location_str=location_str, - show_enabled=show_enabled, - enabled_strs=enabled_str), - sorted(self.plugins.values(), key=lambda x: str(x).lower())) - ))) + formatted_plugins = "\n".join(map(lambda x: "| " + x.long_str(show_bundled=show_bundled, + bundled_strs=bundled_str, + show_location=show_location, + location_str=location_str, + show_enabled=show_enabled, + enabled_strs=enabled_str), + sorted(self.plugins.values(), key=lambda x: str(x).lower()))) + _log("{count} plugin(s) registered with the system:\n{plugins}".format(count=len(all_plugins), + plugins=formatted_plugins)) def get_plugin(self, identifier, require_enabled=True): """