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.
This commit is contained in:
Gina Häußge 2017-02-24 10:53:16 +01:00
parent aab7b7f797
commit 1de307e15d
5 changed files with 209 additions and 17 deletions

View file

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

View file

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

View file

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

View file

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

View file

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