diff --git a/borg/archiver.py b/borg/archiver.py index 12de588ea..73fc5098e 100644 --- a/borg/archiver.py +++ b/borg/archiver.py @@ -1155,7 +1155,7 @@ def run(self, args): self.verbose = args.verbose RemoteRepository.remote_path = args.remote_path RemoteRepository.umask = args.umask - setup_logging() + setup_logging() # do not use loggers before this! check_extension_modules() keys_dir = get_keys_dir() if not os.path.exists(keys_dir): diff --git a/borg/logger.py b/borg/logger.py index 2d4b49bc1..07bb37709 100644 --- a/borg/logger.py +++ b/borg/logger.py @@ -32,28 +32,70 @@ import inspect import logging - -# make it easy for PyInstaller (it does not discover the dependency on this -# module automatically, because it is lazy-loaded by logging, see #218): import logging.config +import logging.handlers # needed for handlers defined there being configurable in logging.conf file +import os +import warnings + +configured = False + +# use something like this to ignore warnings: +# warnings.filterwarnings('ignore', r'... regex for warning message to ignore ...') -def setup_logging(stream=None): +def _log_warning(message, category, filename, lineno, file=None, line=None): + # for warnings, we just want to use the logging system, not stderr or other files + msg = "{0}:{1}: {2}: {3}".format(filename, lineno, category.__name__, message) + logger = create_logger(__name__) + # Note: the warning will look like coming from here, + # but msg contains info about where it really comes from + logger.warning(msg) + + +def setup_logging(stream=None, conf_fname=None, env_var='BORG_LOGGING_CONF'): """setup logging module according to the arguments provided - this sets up a stream handler logger on stderr (by default, if no + if conf_fname is given (or the config file name can be determined via + the env_var, if given): load this logging configuration. + + otherwise, set up a stream handler logger on stderr (by default, if no stream is provided). """ - logging.raiseExceptions = False - l = logging.getLogger('') - sh = logging.StreamHandler(stream) - # other formatters will probably want this, but let's remove - # clutter on stderr + global configured + err_msg = None + if env_var: + conf_fname = os.environ.get(env_var, conf_fname) + if conf_fname: + try: + conf_fname = os.path.abspath(conf_fname) + # we open the conf file here to be able to give a reasonable + # error message in case of failure (if we give the filename to + # fileConfig(), it silently ignores unreadable files and gives + # unhelpful error msgs like "No section: 'formatters'"): + with open(conf_fname) as f: + logging.config.fileConfig(f) + configured = True + logger = logging.getLogger(__name__) + logger.debug('using logging configuration read from "{0}"'.format(conf_fname)) + warnings.showwarning = _log_warning + return None + except Exception as err: # XXX be more precise + err_msg = str(err) + # if we did not / not successfully load a logging configuration, fallback to this: + logger = logging.getLogger('') + handler = logging.StreamHandler(stream) + # other formatters will probably want this, but let's remove clutter on stderr # example: - # sh.setFormatter(logging.Formatter('%(name)s: %(message)s')) - l.addHandler(sh) - l.setLevel(logging.INFO) - return sh + # handler.setFormatter(logging.Formatter('%(name)s: %(message)s')) + logger.addHandler(handler) + logger.setLevel(logging.INFO) + configured = True + logger = logging.getLogger(__name__) + if err_msg: + logger.warning('setup_logging for "{0}" failed with "{1}".'.format(conf_fname, err_msg)) + logger.debug('using builtin fallback logging configuration') + warnings.showwarning = _log_warning + return handler def find_parent_module(): @@ -76,7 +118,7 @@ def find_parent_module(): def create_logger(name=None): - """create a Logger object with the proper path, which is returned by + """lazily create a Logger object with the proper path, which is returned by find_parent_module() by default, or is provided via the commandline this is really a shortcut for: @@ -84,5 +126,48 @@ def create_logger(name=None): logger = logging.getLogger(__name__) we use it to avoid errors and provide a more standard API. + + We must create the logger lazily, because this is usually called from + module level (and thus executed at import time - BEFORE setup_logging() + was called). By doing it lazily we can do the setup first, we just have to + be careful not to call any logger methods before the setup_logging() call. + If you try, you'll get an exception. """ - return logging.getLogger(name or find_parent_module()) + class LazyLogger: + def __init__(self, name=None): + self.__name = name or find_parent_module() + self.__real_logger = None + + @property + def __logger(self): + if self.__real_logger is None: + if not configured: + raise Exception("tried to call a logger before setup_logging() was called") + self.__real_logger = logging.getLogger(self.__name) + return self.__real_logger + + def setLevel(self, *args, **kw): + return self.__logger.setLevel(*args, **kw) + + def log(self, *args, **kw): + return self.__logger.log(*args, **kw) + + def exception(self, *args, **kw): + return self.__logger.exception(*args, **kw) + + def debug(self, *args, **kw): + return self.__logger.debug(*args, **kw) + + def info(self, *args, **kw): + return self.__logger.info(*args, **kw) + + def warning(self, *args, **kw): + return self.__logger.warning(*args, **kw) + + def error(self, *args, **kw): + return self.__logger.error(*args, **kw) + + def critical(self, *args, **kw): + return self.__logger.critical(*args, **kw) + + return LazyLogger(name) diff --git a/borg/testsuite/logger.py b/borg/testsuite/logger.py index ff8b0a03b..b6dc29653 100644 --- a/borg/testsuite/logger.py +++ b/borg/testsuite/logger.py @@ -10,7 +10,7 @@ @pytest.fixture() def io_logger(): io = StringIO() - handler = setup_logging(io) + handler = setup_logging(stream=io, env_var=None) handler.setFormatter(logging.Formatter('%(name)s: %(message)s')) logger.setLevel(logging.DEBUG) return io @@ -37,3 +37,18 @@ def test_multiple_loggers(io_logger): def test_parent_module(): assert find_parent_module() == __name__ + + +def test_lazy_logger(): + # just calling all the methods of the proxy + logger.setLevel(logging.DEBUG) + logger.debug("debug") + logger.info("info") + logger.warning("warning") + logger.error("error") + logger.critical("critical") + logger.log(logging.INFO, "info") + try: + raise Exception + except Exception: + logger.exception("exception") diff --git a/docs/usage.rst b/docs/usage.rst index 7a06ec8f5..d7515f679 100644 --- a/docs/usage.rst +++ b/docs/usage.rst @@ -47,6 +47,8 @@ General: can either leave it away or abbreviate as `::`, if a positional parameter is required. BORG_PASSPHRASE When set, use the value to answer the passphrase question for encrypted repositories. + BORG_LOGGING_CONF + When set, use the given filename as INI_-style logging configuration. BORG_RSH When set, use this command instead of ``ssh``. TMPDIR @@ -81,6 +83,8 @@ Please note: (e.g. mode 600, root:root). +.. _INI: https://docs.python.org/3.2/library/logging.config.html#configuration-file-format + Resource Usage ~~~~~~~~~~~~~~