From e4d34f4130c5e604f31706be3f18adfe76eb9012 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gina=20H=C3=A4u=C3=9Fge?= Date: Fri, 18 Nov 2016 10:25:24 +0100 Subject: [PATCH] Fix logging during settings initialization We record the messages logged during that time to a recording log handler, then playback anything we caught after startup. --- src/octoprint/__init__.py | 59 +++++++++++++++++++++++++++---- src/octoprint/cli/server.py | 15 ++++++-- src/octoprint/logging/handlers.py | 53 +++++++++++++++++++++++++++ 3 files changed, 119 insertions(+), 8 deletions(-) diff --git a/src/octoprint/__init__.py b/src/octoprint/__init__.py index 389fd224..b27e14b2 100644 --- a/src/octoprint/__init__.py +++ b/src/octoprint/__init__.py @@ -18,10 +18,6 @@ __revision__ = versions.get('full-revisionid', versions.get('full', None)) del versions del get_versions -#~~ sane logging defaults - -log.basicConfig() - #~~ try to ensure a sound SSL environment urllib3_ssl = True @@ -61,7 +57,13 @@ 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, after_settings=None, after_logging=None): + uncaught_handler=None, after_preinit_logging=None, + after_settings=None, after_logging=None): + logger, recorder = preinit_logging(debug, verbosity, uncaught_logger, uncaught_handler) + + if callable(after_preinit_logging): + after_preinit_logging(logger, recorder) + settings = init_settings(basedir, configfile) if callable(after_settings): after_settings(settings) @@ -74,8 +76,9 @@ def init_platform(basedir, configfile, use_logging_file=True, logging_file=None, verbosity=verbosity, uncaught_logger=uncaught_logger, uncaught_handler=uncaught_handler) + if callable(after_logging): - after_logging(logger) + after_logging(logger, recorder) plugin_manager = init_pluginsystem(settings) return settings, logger, plugin_manager @@ -94,6 +97,45 @@ def init_settings(basedir, configfile): raise FatalStartupError(message) +def preinit_logging(debug=False, verbosity=0, uncaught_logger=None, uncaught_handler=None): + config = { + "version": 1, + "formatters": { + "simple": { + "format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + } + }, + "handlers": { + "console": { + "class": "logging.StreamHandler", + "level": "DEBUG", + "formatter": "simple", + "stream": "ext://sys.stdout" + } + }, + "loggers": { + "octoprint": { + "level": "DEBUG" if debug else "INFO" + }, + "octoprint.util": { + "level": "INFO" + } + }, + "root": { + "level": "WARN", + "handlers": ["console"] + } + } + + logger = set_logging_config(config, debug, verbosity, uncaught_logger, uncaught_handler) + + from octoprint.logging.handlers import RecordingLogHandler + recorder = RecordingLogHandler(level=log.DEBUG) + log.getLogger().addHandler(recorder) + + return logger, recorder + + def init_logging(settings, use_logging_file=True, logging_file=None, default_config=None, debug=False, verbosity=0, uncaught_logger=None, uncaught_handler=None): """Sets up logging.""" @@ -182,6 +224,11 @@ def init_logging(settings, use_logging_file=True, logging_file=None, default_con else: config = default_config + # configure logging globally + return set_logging_config(config, debug, verbosity, uncaught_logger, uncaught_handler) + + +def set_logging_config(config, debug, verbosity, uncaught_logger, uncaught_handler): # configure logging globally import logging.config as logconfig logconfig.dictConfig(config) diff --git a/src/octoprint/cli/server.py b/src/octoprint/cli/server.py index 3fb45f2c..0b187bd6 100644 --- a/src/octoprint/cli/server.py +++ b/src/octoprint/cli/server.py @@ -16,8 +16,19 @@ def run_server(basedir, configfile, host, port, debug, allow_root, logging_confi from octoprint import init_platform, __display_version__, FatalStartupError - def log_startup(_): - logging.getLogger("octoprint.server").info("Starting OctoPrint {}".format(__display_version__)) + def log_startup(_, recorder): + logger = logging.getLogger("octoprint.server") + logger.info("Starting OctoPrint {}".format(__display_version__)) + + if recorder and len(recorder): + logger.info("--- Logged during platform initialization: ---") + + from octoprint.logging.handlers import CombinedLogHandler + handler = CombinedLogHandler(*logging.getLogger().handlers) + recorder.setTarget(handler) + recorder.flush() + + logger.info("----------------------------------------------") from octoprint import urllib3_ssl if not urllib3_ssl: diff --git a/src/octoprint/logging/handlers.py b/src/octoprint/logging/handlers.py index fb613429..fc2d5e43 100644 --- a/src/octoprint/logging/handlers.py +++ b/src/octoprint/logging/handlers.py @@ -81,3 +81,56 @@ class SerialLogHandler(logging.handlers.RotatingFileHandler): self.cleanupFiles() if not self.delay: self.stream = self._open() + +class RecordingLogHandler(logging.Handler): + def __init__(self, target=None, level=logging.NOTSET): + logging.Handler.__init__(self, level=level) + self._buffer = [] + self._target = target + + def emit(self, record): + self._buffer.append(record) + + def setTarget(self, target): + self._target = target + + def flush(self): + if not self._target: + return + + self.acquire() + try: + for record in self._buffer: + self._target.handle(record) + self._buffer = [] + finally: + self.release() + + def close(self): + self.flush() + self.acquire() + try: + self._buffer = [] + finally: + self.release() + + def __len__(self): + return len(self._buffer) + + +class CombinedLogHandler(logging.Handler): + def __init__(self, *handlers): + logging.Handler.__init__(self) + self._handlers = handlers + + def setHandlers(self, *handlers): + self._handlers = handlers + + def handle(self, record): + self.acquire() + try: + if self._handlers: + for handler in self._handlers: + handler.handle(record) + finally: + self.release()