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

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

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:

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