Add new logging backend infrastructure

py/desiutil/log.py

@@ -27,6 +27,11 @@
 
 Simplest possible use:
 
+>>> from desiutil.log import log
+>>> log.info('This is some information.')
+
+This is exactly equivalent to:
+
 >>> from desiutil.log import get_logger
 >>> log = get_logger()
 >>> log.info('This is some information.')
@@ -51,12 +56,31 @@
 
 """
 from __future__ import absolute_import, division, print_function
+import os
+import sys
 import logging
-from os import environ
-from sys import stdout
 from warnings import warn
 
-desi_logger = None
+
+_desiutil_log_root = dict()
+_good_levels = {'DEBUG': logging.DEBUG,
+                'INFO': logging.INFO,
+                'WARNING': logging.WARNING,
+                'ERROR': logging.ERROR,
+                'CRITICAL': logging.CRITICAL,
+                logging.DEBUG: logging.DEBUG,
+                logging.INFO: logging.INFO,
+                logging.WARNING: logging.WARNING,
+                logging.ERROR: logging.ERROR,
+                logging.CRITICAL: logging.CRITICAL,
+                }
+_level_children = {logging.DEBUG: 'debug',
+                   logging.INFO: 'info',
+                   logging.WARNING: 'warning',
+                   logging.ERROR: 'error',
+                   logging.CRITICAL: 'critical',
+                   }
+
 
 # Just for convenience to avoid importing logging, we duplicate the logging levels
 DEBUG = logging.DEBUG        # Detailed information, typically of interest only when diagnosing problems.
@@ -112,17 +136,49 @@ def __exit__(self, et, ev, tb):
         #     self.handler.close()
 
 
+def _configure_root_logger(timestamp=False, delimiter=':'):
+    """Configure a root logger.
+
+    Parameters
+    ----------
+    timestamp : :class:`bool`, optional
+        If ``True``, add a timestamp to the log message.
+    delimiter : :class:`str`, optional
+        Use `delimiter` to separate fields in the log message (default ``:``).
+
+    Returns
+    -------
+    :class:`str`
+        The name of the root logger, suitable for input to :func:`logging.getLogger`.
+    """
+    root_name = "desiutil.log.dlm" + ''.join(map(str, map(ord, delimiter)))
+    if timestamp:
+        root_name += 'timestamp'
+    if root_name not in _desiutil_log_root:
+        ch = logging.StreamHandler(sys.stdout)
+        fmtfields = ['%(levelname)s', '%(filename)s', '%(lineno)s', '%(funcName)s']
+        if timestamp:
+            fmtfields.append('%(asctime)s')
+        fmt = delimiter.join(fmtfields)
+        formatter = logging.Formatter(fmt + ': %(message)s', datefmt='%Y-%m-%dT%H:%M:%S')
+        ch.setFormatter(formatter)
+        _desiutil_log_root[root_name] = logging.getLogger(root_name)
+        _desiutil_log_root[root_name].addHandler(ch)
+        _desiutil_log_root[root_name].setLevel(logging.INFO)
+    return root_name
+
+
 def get_logger(level=None, timestamp=False, delimiter=':'):
     """Returns a default DESI logger.
 
     Parameters
     ----------
     level : :class:`int` or :class:`str`, optional
-        Debugging level.
+        Set the logging level (default ``INFO``).
     timestamp : :class:`bool`, optional
-        If set, include a time stamp in the log message.
+        If ``True``, add a timestamp to the log message.
     delimiter : :class:`str`, optional
-        Use this string to separate fields in the log messages, default ':'.
+        Use `delimiter` to separate fields in the log messages (default ``:``).
 
     Returns
     -------
@@ -140,59 +196,27 @@ def get_logger(level=None, timestamp=False, delimiter=':'):
     * If :envvar:`DESI_LOGLEVEL` is not set and `level` is ``None``,
       the default level is set to INFO.
     """
-    global desi_logger
-    good_levels = {"DEBUG": DEBUG,
-                   "INFO": INFO,
-                   "WARNING": WARNING,
-                   "ERROR": ERROR,
-                   "CRITICAL": CRITICAL,
-                   DEBUG: DEBUG,
-                   INFO: INFO,
-                   WARNING: WARNING,
-                   ERROR: ERROR,
-                   CRITICAL: CRITICAL}
+    root_name = _configure_root_logger(timestamp=timestamp, delimiter=delimiter)
     if level is None:
         try:
-            level = environ["DESI_LOGLEVEL"].upper()
+            ul = os.environ["DESI_LOGLEVEL"].upper()
         except KeyError:
-            level = INFO
+            ul = logging.INFO
     else:
         try:
-            level = level.upper()
+            ul = level.upper()
         except AttributeError:
             # level should be an integer in this case.
-            pass
-    if level not in good_levels:
-        message = ("Ignore level='{0}' " +
-                   "(only recognize {1}).").format(str(level),
-                                                   ', '.join(map(str, good_levels.keys())))
+            ul = level
+    try:
+        gl = _good_levels[ul]
+    except KeyError:
+        message = "Invalid level='{0}' ignored.  Setting INFO.".format(str(ul))
         warn(message, DesiLogWarning)
-        level = INFO
-
-    if desi_logger is not None:
-        if level is not None:
-            desi_logger.setLevel(level)
-        return desi_logger
-
-    desi_logger = logging.getLogger("DESI")
-
-    desi_logger.setLevel(level)
-
-    while len(desi_logger.handlers) > 0:
-        h = desi_logger.handlers[0]
-        desi_logger.removeHandler(h)
-
-    ch = logging.StreamHandler(stdout)
-
-    fmtfields = ['%(levelname)s', '%(filename)s', '%(lineno)s', '%(funcName)s']
-    if timestamp:
-        fmtfields.append('%(asctime)s')
-    fmt = delimiter.join(fmtfields)
-
-    formatter = logging.Formatter(fmt + ': %(message)s', datefmt='%Y-%m-%dT%H:%M:%S')
-
-    ch.setFormatter(formatter)
+        gl = logging.INFO
+    log = logging.getLogger(root_name + '.' + _level_children[gl])
+    log.setLevel(gl)
+    return log
 
-    desi_logger.addHandler(ch)
 
-    return desi_logger
+log = get_logger()

py/desiutil/test/test_census.py

@@ -64,21 +64,23 @@ def test_walk_error(self):
         """Test error-handling function for os.walk().
         """
         from ..census import walk_error
-        with patch('desiutil.log.desi_logger') as mock:
+        with patch('desiutil.log.get_logger') as mock_get_logger:
+            mock = Mock()
+            mock_get_logger.return_value = mock
             try:
                 raise OSError(2, 'File not found', 'foo.txt')
             except OSError as e:
                 walk_error(e)
-            calls = [call.setLevel(20),
-                     call.error("[Errno 2] File not found: 'foo.txt'")]
+            calls = [call.error("[Errno 2] File not found: 'foo.txt'")]
             self.assertListEqual(mock.mock_calls, calls)
-        with patch('desiutil.log.desi_logger') as mock:
+        with patch('desiutil.log.get_logger') as mock_get_logger:
+            mock = Mock()
+            mock_get_logger.return_value = mock
             try:
                 raise OSError(2, 'File not found', 'foo.txt', None, 'bar.txt')
             except OSError as e:
                 walk_error(e)
-            calls = [call.setLevel(20),
-                     call.error("[Errno 2] File not found: 'foo.txt' -> " +
+            calls = [call.error("[Errno 2] File not found: 'foo.txt' -> " +
                                 "'bar.txt'")]
             self.assertListEqual(mock.mock_calls, calls)
 
@@ -110,12 +112,13 @@ def test_scan_file(self):
         #
         # Simulate a simple file.
         #
-        calls = [call.setLevel(20),
-                 call.debug("os.stat('{0}')".format(fd)),
+        calls = [call.debug("os.stat('{0}')".format(fd)),
                  call.warning("{0} does not have correct group id!".format(fd))]
-        with patch('desiutil.log.desi_logger') as mock_log:
+        mock_log = Mock()
+        with patch('desiutil.log.get_logger') as mock_get_logger:
             with patch.dict('sys.modules', {'os': mock_os,
                                             'os.path': mock_os.path}):
+                mock_get_logger.return_value = mock_log
                 mock_os.environ = dict()
                 mock_os.stat.return_value = s
                 mock_os.path.islink.return_value = False
@@ -128,15 +131,16 @@ def test_scan_file(self):
         #
         # Simulate an internal link.
         #
-        calls = [call.setLevel(20),
-                 call.debug("os.stat('{0}')".format(fd)),
+        calls = [call.debug("os.stat('{0}')".format(fd)),
                  call.warning("{0} does not have correct group id!".format(fd)),
                  call.debug("os.lstat('{0}')".format(fd)),
                  call.warning("{0} does not have correct group id!".format(fd)),
                  call.debug("Found internal link {0} -> {0}.link.".format(fd))]
-        with patch('desiutil.log.desi_logger') as mock_log:
+        mock_log = Mock()
+        with patch('desiutil.log.get_logger') as mock_get_logger:
             with patch.dict('sys.modules', {'os': mock_os,
                                             'os.path': mock_os.path}):
+                mock_get_logger.return_value = mock_log
                 mock_os.environ = dict()
                 mock_os.stat.return_value = s
                 mock_os.lstat.return_value = s
@@ -154,15 +158,16 @@ def test_scan_file(self):
         #
         # Simulate an external link.
         #
-        calls = [call.setLevel(20),
-                 call.debug("os.stat('{0}')".format(fd)),
+        calls = [call.debug("os.stat('{0}')".format(fd)),
                  call.warning("{0} does not have correct group id!".format(fd)),
                  call.debug("os.lstat('{0}')".format(fd)),
                  call.warning("{0} does not have correct group id!".format(fd)),
                  call.debug("Found external link {0} -> {1}.".format(fd, extlink))]
-        with patch('desiutil.log.desi_logger') as mock_log:
+        mock_log = Mock()
+        with patch('desiutil.log.get_logger') as mock_get_logger:
             with patch.dict('sys.modules', {'os': mock_os,
                                             'os.path': mock_os.path}):
+                mock_get_logger.return_value = mock_log
                 mock_os.environ = dict()
                 mock_os.stat.return_value = s
                 mock_os.lstat.return_value = s

py/desiutil/test/test_depend.py

@@ -127,6 +127,23 @@ def test_iter(self):
 
         for name, version in iterdep(hdr):
             self.assertEqual(version, getdep(hdr, name))
+        #
+        # Test dependency index starting from one.
+        #
+        hdr = dict()
+        for j in range(1, 20):
+            hdr["DEPNAM{0:02d}".format(i)] = "test{0:03d}".format(i)
+            hdr["DEPVER{0:02d}".format(i)] = "v{0:d}.0.1".format(i)
+        y = Dependencies(hdr)
+        for name in y:
+            self.assertEqual(y[name], getdep(hdr, name))
+
+        for name, version in y.items():
+            self.assertEqual(version, getdep(hdr, name))
+
+        for name, version in iterdep(hdr):
+            self.assertEqual(version, getdep(hdr, name))
+
 
     def test_class(self):
         """Test the Dependencies object.
@@ -166,9 +183,11 @@ def test_add_dependencies(self):
         self.assertFalse(hasdep(hdr, 'quatlarm'))
 
         # no .__version__
-        add_dependencies(hdr, ['os.path', 'sys'])
+        add_dependencies(hdr, ['os.path', 'unittest', 'sys'])
         self.assertTrue(hasdep(hdr, 'os.path'))
         self.assertTrue(getdep(hdr, 'os.path').startswith('unknown'))
+        self.assertTrue(hasdep(hdr, 'unittest'))
+        self.assertTrue(getdep(hdr, 'unittest').startswith('unknown'))
         self.assertTrue(hasdep(hdr, 'sys'))
         self.assertTrue(getdep(hdr, 'sys').startswith('unknown'))
 

py/desiutil/test/test_install.py

@@ -11,6 +11,7 @@
 from shutil import rmtree
 from argparse import Namespace
 from tempfile import mkdtemp
+from logging import getLogger
 from pkg_resources import resource_filename
 from ..log import DEBUG
 from ..install import DesiInstall, DesiInstallException, dependencies
@@ -41,13 +42,14 @@ def setUp(self):
         # Create a "fresh" DesiInstall object for every test.
         self.desiInstall = DesiInstall()
         # Replace the log handler with something that writes to memory.
-        while len(self.desiInstall.log.handlers) > 0:
-            h = self.desiInstall.log.handlers[0]
+        root_logger = getLogger(self.desiInstall.log.name.rsplit('.', 1)[0])
+        while len(root_logger.handlers) > 0:
+            h = root_logger.handlers[0]
             fmt = h.formatter
-            self.desiInstall.log.removeHandler(h)
+            root_logger.removeHandler(h)
         mh = TestHandler()
         mh.setFormatter(fmt)
-        self.desiInstall.log.addHandler(mh)
+        root_logger.addHandler(mh)
         self.desiInstall.log.setLevel(DEBUG)
         # Create a temporary directory.
         self.data_dir = mkdtemp()
@@ -58,7 +60,7 @@ def tearDown(self):
     def assertLog(self, order=-1, message=''):
         """Examine the log messages.
         """
-        handler = self.desiInstall.log.handlers[0]
+        handler = getLogger(self.desiInstall.log.name.rsplit('.', 1)[0]).handlers[0]
         record = handler.buffer[order]
         self.assertEqual(record.getMessage(), message)