Repository: desihub/desiutil

Issue:
Questions/suggestions for logging module
I have some questions/suggestions about `log.get_logger()` after adapting `desisurvey` and `surveysim` to use it.

Environment variables usually set a default that can be overridden via the API, but `$DESI_LOGLEVEL` overrides the API `level` parameter.  I found this confusing and wonder if we should change this.

A command-line script should be able to set the log-level (e.g., via cmd-line options) and then have all library code respect this level.  I believe the way this is supposed to work is:
```
# script.py
log = get_logger(WARNING)

# module.py
log = get_logger()
log.info('...')
```
I found two issues with how this works in practice:
1. Calling `get_logger()` always sets the log-level to `INFO`, even after a previous call where a different level was specified.
2. Nothing prevents library code from calling `get_logger(DEBUG)` and changing the log level specified by the top-level script.  Library code should probably always call `get_logger()` but we could enforce this by raising an exception on attempts to change an already specified level. Even better, I think, would be to provide separate `get_logger()` (with no level arg) and `set_log_level(level)` methods.

Finally, it could be useful to support a hierarchy of DESI loggers with different levels.  For example, I might want to enable DEBUG messages from the arc calibration only, without being flooded with other DEBUG messages.  In practice, this could be implemented by passing an optional component arg to `get_logger()` that uses dot notation to express hierarchy.  The level of a child component would then default to the lowest level of any parent, and setting a parent level enforces a maximum level for all children.

Discussion:

Patch:
diff --git a/doc/changes.rst b/doc/changes.rst
index 362be2b..6cb18fc 100644
--- a/doc/changes.rst
+++ b/doc/changes.rst
@@ -7,9 +7,13 @@ Change Log
 
 * Enhance :mod:`desiutil.log` with a context manager (PR `#92`_), and
   change the way the log level is set.
+* Avoid logging interference with :func:`desiutil.log.get_logger` is called
+  with different log levels (PR `#93`_).
 * Use :mod:`unittest.mock` to increase test coverage.
 
 .. _`#92`: https://github.com/desihub/desiutil/pull/92
+.. _`#93`: https://github.com/desihub/desiutil/pull/93
+
 
 1.9.8 (2017-11-09)
 ------------------
diff --git a/py/desiutil/log.py b/py/desiutil/log.py
index 6efe7c6..6e9fedb 100644
--- a/py/desiutil/log.py
+++ b/py/desiutil/log.py
@@ -27,6 +27,11 @@ Examples
 
 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 @@ Create the logger with a different log level:
 
 """
 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,50 @@ class DesiLogContext(object):
         #     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')
+        fmtfields.append(' %(message)s')
+        formatter = logging.Formatter(delimiter.join(fmtfields),
+                                      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 +197,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()


Test patch:
diff --git a/py/desiutil/test/test_census.py b/py/desiutil/test/test_census.py
index bc5053c..26831ad 100644
--- a/py/desiutil/test/test_census.py
+++ b/py/desiutil/test/test_census.py
@@ -64,21 +64,23 @@ class TestCensus(unittest.TestCase):
         """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 @@ class TestCensus(unittest.TestCase):
         #
         # 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 @@ class TestCensus(unittest.TestCase):
         #
         # 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 @@ class TestCensus(unittest.TestCase):
         #
         # 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
diff --git a/py/desiutil/test/test_depend.py b/py/desiutil/test/test_depend.py
index 41e3be0..0949643 100644
--- a/py/desiutil/test/test_depend.py
+++ b/py/desiutil/test/test_depend.py
@@ -127,6 +127,23 @@ class TestDepend(unittest.TestCase):
 
         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 @@ class TestDepend(unittest.TestCase):
         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'))
 
diff --git a/py/desiutil/test/test_install.py b/py/desiutil/test/test_install.py
index a6307f0..2e7aabf 100644
--- a/py/desiutil/test/test_install.py
+++ b/py/desiutil/test/test_install.py
@@ -11,6 +11,7 @@ from os.path import dirname, isdir, join
 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 @@ class TestInstall(unittest.TestCase):
         # 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 @@ class TestInstall(unittest.TestCase):
     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)
 
diff --git a/py/desiutil/test/test_log.py b/py/desiutil/test/test_log.py
index dea3b56..d2a71a1 100644
--- a/py/desiutil/test/test_log.py
+++ b/py/desiutil/test/test_log.py
@@ -6,7 +6,7 @@ from __future__ import absolute_import, print_function
 import os
 import re
 import unittest
-from logging import NullHandler
+from logging import getLogger, NullHandler
 from logging.handlers import MemoryHandler
 from warnings import catch_warnings, simplefilter
 
@@ -35,7 +35,7 @@ class TestHandler(MemoryHandler):
 
 
 class TestLog(unittest.TestCase):
-    """Test desispec.log
+    """Test desiutil.log
     """
 
     @classmethod
@@ -55,7 +55,7 @@ class TestLog(unittest.TestCase):
         (:|\s--\s)                                        # delimiter
         (run_logs|test_log_context)                       # function
         ((:|\s--\s)\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}|)  # optional timetamp
-        :\s                                               # start of message
+        (:|\s--\s)\s                                      # start of message
         """, re.VERBOSE)
 
     @classmethod
@@ -76,7 +76,8 @@ class TestLog(unittest.TestCase):
     def assertLog(self, logger, order=-1, message=''):
         """Examine the log messages.
         """
-        handler = logger.handlers[0]
+        root_logger = getLogger(logger.name.rsplit('.', 1)[0])
+        handler = root_logger.handlers[0]
         record = handler.buffer[order]
         self.assertEqual(record.getMessage(), message)
         formatted = handler.format(record)
@@ -88,15 +89,14 @@ class TestLog(unittest.TestCase):
         """Get the actual logging object, but swap out its default handler.
         """
         logger = dul.get_logger(level, **kwargs)
-        # actual_level = logger.level
-        while len(logger.handlers) > 0:
-            h = logger.handlers[0]
+        root_logger = getLogger(logger.name.rsplit('.', 1)[0])
+        while len(root_logger.handlers) > 0:
+            h = root_logger.handlers[0]
             fmt = h.formatter
-            logger.removeHandler(h)
+            root_logger.removeHandler(h)
         mh = TestHandler()
         mh.setFormatter(fmt)
-        logger.addHandler(mh)
-        # logger.setLevel(actual_level)
+        root_logger.addHandler(mh)
         return logger
 
     def run_logs(self, **kwargs):
@@ -126,7 +126,7 @@ class TestLog(unittest.TestCase):
                         self.assertTrue(issubclass(w[-1].category,
                                                    UserWarning))
                         # print(w[-1].message)
-                        self.assertTrue("Ignore level='FOOBAR'" in str(w[-1].message))
+                        self.assertIn("Invalid level='FOOBAR' ignored.", str(w[-1].message))
                     else:
                         self.assertEqual(logger.level, dul.WARNING)
             logger.debug("This is a debugging message.")
@@ -171,8 +171,7 @@ class TestLog(unittest.TestCase):
                 self.assertLog(logger, 0, "This is a warning message.")
                 self.assertLog(logger, 1, "This is an error message.")
                 self.assertLog(logger, 2, "This is a critical error message.")
-            logger.handlers[0].flush()
-            dul.desi_logger = None
+            getLogger(logger.name.rsplit('.', 1)[0]).handlers[0].flush()
 
     def test_log(self):
         """Test basic logging functionality.
@@ -186,6 +185,12 @@ class TestLog(unittest.TestCase):
         log2 = dul.get_logger()
         self.assertIs(log1, log2)
 
+    def test_log_singleton(self):
+        """Test the default pseudo-singleton created by the module.
+        """
+        log2 = dul.get_logger()
+        self.assertIs(log2, dul.log)
+
     @unittest.skipIf(skipMock, "Skipping test that requires unittest.mock.")
     def test_log_with_desi_loglevel(self):
         """Test basic logging functionality with DESI_LOGLEVEL set.