configure logging via env var, use LazyLogger

logging.raiseExceptions not needed any more for py >= 3.2

borg/archiver.py

@@ -1155,7 +1155,7 @@ class Archiver:
         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):

borg/logger.py

@@ -32,28 +32,70 @@ The way to use this is as follows:
 
 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 _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):
+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)

borg/testsuite/logger.py

@@ -10,7 +10,7 @@ logger = create_logger()
 @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")

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