Merge pull request #37 from lsst/tickets/DM-17651

DM-17651: Allow lsst.log to forward to Python logging

.gitignore

@@ -21,3 +21,5 @@ version.py
 .coverage
 *.gcda
 *.gcno
+.pytest_cache
+pytest_session.txt

python/lsst/log/log/logContinued.py

@@ -40,6 +40,34 @@
 
 @continueClass  # noqa F811 redefinition
 class Log:
+    UsePythonLogging = False
+    """Forward Python `lsst.log` messages to Python `logging` package."""
+
+    @classmethod
+    def usePythonLogging(cls):
+        """Forward log messages to Python `logging`
+
+        Notes
+        -----
+        This is useful for unit testing when you want to ensure
+        that log messages are captured by the testing environment
+        as distinct from standard output.
+
+        This state only affects messages sent to the `lsst.log`
+        package from Python.
+        """
+        cls.UsePythonLogging = True
+
+    @classmethod
+    def doNotUsePythonLogging(cls):
+        """Forward log messages to LSST logging system.
+
+        Notes
+        -----
+        This is the default state.
+        """
+        cls.UsePythonLogging = False
+
     def trace(self, fmt, *args):
         self._log(Log.TRACE, False, fmt, *args)
 
@@ -52,6 +80,9 @@ def info(self, fmt, *args):
     def warn(self, fmt, *args):
         self._log(Log.WARN, False, fmt, *args)
 
+    def warning(self, fmt, *args):
+        self.warn(fmt, *args)
+
     def error(self, fmt, *args):
         self._log(Log.ERROR, False, fmt, *args)
 
@@ -86,7 +117,14 @@ def _log(self, level, use_format, fmt, *args, **kwargs):
                 msg = fmt.format(*args, **kwargs) if args or kwargs else fmt
             else:
                 msg = fmt % args if args else fmt
-            self.logMsg(level, filename, funcname, frame.f_lineno, msg)
+            if self.UsePythonLogging:
+                pylog = logging.getLogger(self.getName())
+                # Python logging level is 1000 times smaller than log4cxx level
+                record = logging.LogRecord(self.getName(), int(level/1000), filename,
+                                           frame.f_lineno, msg, None, False, func=funcname)
+                pylog.handle(record)
+            else:
+                self.logMsg(level, filename, funcname, frame.f_lineno, msg)
 
 
 # Export static functions from Log class to module namespace
@@ -156,6 +194,10 @@ def warn(fmt, *args):
     Log.getDefaultLogger()._log(WARN, False, fmt, *args)
 
 
+def warning(fmt, *args):
+    warn(fmt, *args)
+
+
 def error(fmt, *args):
     Log.getDefaultLogger()._log(ERROR, False, fmt, *args)
 
@@ -196,6 +238,14 @@ def lwpID():
     return Log.lwpID
 
 
+def usePythonLogging():
+    Log.usePythonLogging()
+
+
+def doNotUsePythonLogging():
+    Log.doNotUsePythonLogging()
+
+
 class LogContext(object):
     """Context manager for logging."""
 
@@ -234,11 +284,38 @@ def isEnabledFor(self, level):
         return Log.getDefaultLogger().isEnabledFor(level)
 
 
+class UsePythonLogging:
+    """Context manager to enable Python log forwarding temporarily."""
+
+    def __init__(self):
+        self.current = Log.UsePythonLogging
+
+    def __enter__(self):
+        Log.usePythonLogging()
+
+    def __exit__(self, exc_type, exc_value, traceback):
+        Log.UsePythonLogging = self.current
+
+
 class LogHandler(logging.Handler):
-    """Handler for Python logging module that emits to LSST logging."""
+    """Handler for Python logging module that emits to LSST logging.
+
+    Notes
+    -----
+    If this handler is enabled and `lsst.log` has been configured to use
+    Python `logging`, the handler will do nothing itself if any other
+    handler has been registered with the Python logger.  If it does not
+    think that anything else is handling the message it will attempt to
+    send the message via a default `~logging.StreamHandler`.  The safest
+    approach is to configure the logger with an additional handler
+    (possibly the ROOT logger) if `lsst.log` is to be configured to use
+    Python logging.
+    """
 
     def __init__(self, level=logging.NOTSET):
         logging.Handler.__init__(self, level=level)
+        # Format as a simple message because lsst.log will format the
+        # message a second time.
         self.formatter = logging.Formatter(fmt="%(message)s")
 
     def handle(self, record):
@@ -247,9 +324,37 @@ def handle(self, record):
             logging.Handler.handle(self, record)
 
     def emit(self, record):
+        if Log.UsePythonLogging:
+            # Do not forward this message to lsst.log since this may cause
+            # a logging loop.
+
+            # Work out whether any other handler is going to be invoked
+            # for this logger.
+            pylgr = logging.getLogger(record.name)
+
+            # If another handler is registered that is not LogHandler
+            # we ignore this request
+            if any(not isinstance(h, self.__class__) for h in pylgr.handlers):
+                return
+
+            # If the parent has handlers and propagation is enabled
+            # we punt as well (and if a LogHandler is involved then we will
+            # ask the same question when we get to it).
+            if pylgr.parent and pylgr.parent.hasHandlers() and pylgr.propagate:
+                return
+
+            # Force this message to appear somewhere.
+            # If something else should happen then the caller should add a
+            # second Handler.
+            stream = logging.StreamHandler()
+            stream.setFormatter(logging.Formatter(fmt="%(name)s %(levelname)s (fallback): %(message)s"))
+            stream.handle(record)
+            return
+
         logger = Log.getLogger(record.name)
         # Use standard formatting class to format message part of the record
         message = self.formatter.format(record)
+
         logger.logMsg(self.translateLevel(record.levelno),
                       record.filename, record.funcName,
                       record.lineno, message)

tests/test_log.py

@@ -29,7 +29,7 @@
 import tempfile
 import threading
 import unittest
-
+import logging
 import lsst.log as log
 
 
@@ -63,7 +63,8 @@ def setUp(self):
         self.stdout = None
 
     def tearDown(self):
-        """Remove the temporary directory."""
+        """Remove the temporary directory and clean up Python forwarding."""
+        log.doNotUsePythonLogging()
         shutil.rmtree(self.tempDir)
 
     def configure(self, configuration):
@@ -101,7 +102,7 @@ def testBasic(self):
             log.warn("This is WARN")
             log.error("This is ERROR")
             log.fatal("This is FATAL")
-            log.warn("Format %d %g %s", 3, 2.71828, "foo")
+            log.warning("Format %d %g %s", 3, 2.71828, "foo")
         self.check("""
 root INFO: This is INFO
 root INFO: This is unicode INFO
@@ -242,7 +243,7 @@ def testPattern(self):
 DEBUG component  testPattern (test_log.py:{0[7]}) test_log.py({0[7]}) - This is DEBUG 4 - {{{{y,foo}}}}
 INFO  root  testPattern (test_log.py:{0[8]}) test_log.py({0[8]}) - This is INFO 5 - {{{{y,foo}}}}
 DEBUG root  testPattern (test_log.py:{0[9]}) test_log.py({0[9]}) - This is DEBUG 5 - {{{{y,foo}}}}
-""".format([x + 206 for x in (0, 1, 8, 9, 14, 15, 18, 19, 22, 23)], __name__))  # noqa E501 line too long
+""".format([x + 207 for x in (0, 1, 8, 9, 14, 15, 18, 19, 22, 23)], __name__))  # noqa E501 line too long
 
     def testMDCPutPid(self):
         """
@@ -274,7 +275,7 @@ def testMDCPutPid(self):
 
             with TestLog.StdoutCapture(self.outputFilename):
                 log.info(msg)
-                line = 276
+                line = 277
         finally:
             log.MDCRemove("PID")
 
@@ -310,17 +311,22 @@ def testFileAppender(self):
     def testPythonLogging(self):
         """Test logging through the Python logging interface."""
         with TestLog.StdoutCapture(self.outputFilename):
-            import logging
             lgr = logging.getLogger()
             lgr.setLevel(logging.INFO)
-            lgr.addHandler(log.LogHandler())
             log.configure()
-            lgr.info("This is INFO")
-            lgr.debug("This is DEBUG")
-            lgr.warning("This is %s", "WARNING")
-            # message can be arbitrary Python object
-            lgr.info(((1, 2), (3, 4)))
-            lgr.info({1: 2})
+            with self.assertLogs(level="INFO") as cm:
+                # Force the lsst.log handler to be applied as well as the
+                # unittest log handler
+                lgr.addHandler(log.LogHandler())
+                lgr.info("This is INFO")
+                lgr.debug("This is DEBUG")
+                lgr.warning("This is %s", "WARNING")
+                # message can be arbitrary Python object
+                lgr.info(((1, 2), (3, 4)))
+                lgr.info({1: 2})
+
+            # Confirm that Python logging also worked
+            self.assertEqual(len(cm.output), 4, f"Got output: {cm.output}")
             logging.shutdown()
 
         self.check("""
@@ -488,6 +494,135 @@ def testMsgWithPercentS(self):
 root DEBUG: DEBUG with %s
 """)
 
+    def testForwardToPython(self):
+        """Test that `lsst.log` log messages can be forwarded to `logging`."""
+        log.configure()
+
+        # Without forwarding we only get python logger messages captured
+        with self.assertLogs(level="WARNING") as cm:
+            log.warn("lsst.log warning message that will not be forwarded to Python")
+            logging.warning("Python logging message that will be captured")
+        self.assertEqual(len(cm.output), 1)
+
+        log.usePythonLogging()
+
+        # With forwarding we get 2 logging messages captured
+        with self.assertLogs(level="WARNING") as cm:
+            log.warn("This is a warning from lsst log meant for python logging")
+            logging.warning("Python warning log message to be captured")
+        self.assertEqual(len(cm.output), 2)
+
+        loggername = "newlogger"
+        log2 = log.Log.getLogger(loggername)
+        with self.assertLogs(level="INFO", logger=loggername):
+            log2.info("Info message to non-root lsst logger")
+
+        # Check that debug and info are working properly
+        # This test should return a single log message
+        with self.assertLogs(level="INFO", logger=loggername) as cm:
+            log2.info("Second INFO message to non-root lsst logger")
+            log.debug("Debug message to root lsst logger")
+
+        self.assertEqual(len(cm.output), 1, f"Got output: {cm.output}")
+
+        logging.shutdown()
+
+    def testLogLoop(self):
+        """Test that Python log forwarding works even if Python logging has
+        been forwarded to lsst.log"""
+
+        log.configure()
+
+        # Note that assertLogs causes a specialists Python logging handler
+        # to be added.
+
+        # Set up some Python loggers
+        loggername = "testLogLoop"
+        lgr = logging.getLogger(loggername)
+        lgr.setLevel(logging.INFO)
+        rootlgr = logging.getLogger()
+        rootlgr.setLevel(logging.INFO)
+
+        # Declare that we are using the Python logger and that this will
+        # not cause a log loop if we also are forwarding Python logging to
+        # lsst.log
+        log.usePythonLogging()
+
+        # Ensure that we can log both in lsst.log and Python
+        rootlgr.addHandler(log.LogHandler())
+
+        # All three of these messages go through LogHandler
+        # The first two because they have the handler added explicitly, the
+        # the final one because the lsst.log logger is forwarded to the
+        # ROOT Python logger which has the LogHandler registered.
+
+        with open(self.outputFilename, "w") as fd:
+            # Adding a StreamHandler will cause the LogHandler to no-op
+            streamHandler = logging.StreamHandler(stream=fd)
+            rootlgr.addHandler(streamHandler)
+
+            # Do not use assertLogs since that messes with handlers
+            lgr.info("INFO message: Python child logger, lsst.log.LogHandler + PythonLogging")
+            rootlgr.info("INFO message: Python root logger, lsst.log.logHandler + PythonLogging")
+
+            # This will use a ROOT python logger which has a LogHandler attached
+            log.info("INFO message: lsst.log root logger, PythonLogging")
+
+            rootlgr.removeHandler(streamHandler)
+
+        self.check("""
+INFO message: Python child logger, lsst.log.LogHandler + PythonLogging
+INFO message: Python root logger, lsst.log.logHandler + PythonLogging
+INFO message: lsst.log root logger, PythonLogging""")
+
+        with open(self.outputFilename, "w") as fd:
+            # Adding a StreamHandler will cause the LogHandler to no-op
+            streamHandler = logging.StreamHandler(stream=fd)
+            rootlgr.addHandler(streamHandler)
+
+            # Do not use assertLogs since that messes with handlers
+            lgr.info("INFO message: Python child logger, lsst.log.LogHandler + PythonLogging")
+            rootlgr.info("INFO message: Python root logger, lsst.log.logHandler + PythonLogging")
+
+            # This will use a ROOT python logger which has a LogHandler attached
+            log.info("INFO message: lsst.log root logger, PythonLogging")
+
+            rootlgr.removeHandler(streamHandler)
+
+        self.check("""
+INFO message: Python child logger, lsst.log.LogHandler + PythonLogging
+INFO message: Python root logger, lsst.log.logHandler + PythonLogging
+INFO message: lsst.log root logger, PythonLogging""")
+
+        with self.assertLogs(level="INFO") as cm:
+            rootlgr.info("Python log message forward to lsst.log")
+            log.info("lsst.log message forwarded to Python")
+
+        self.assertEqual(len(cm.output), 2, f"Got output: {cm.output}")
+
+        logging.shutdown()
+
+    def testForwardToPythonContextManager(self):
+        """Test that `lsst.log` log messages can be forwarded to `logging`
+        using context manager"""
+        log.configure()
+
+        # Without forwarding we only get python logger messages captured
+        with self.assertLogs(level="WARNING") as cm:
+            log.warning("lsst.log: not forwarded")
+            logging.warning("Python logging: captured")
+        self.assertEqual(len(cm.output), 1)
+
+        # Temporarily turn on forwarding
+        with log.UsePythonLogging():
+            with self.assertLogs(level="WARNING") as cm:
+                log.warn("lsst.log: forwarded")
+                logging.warning("Python logging: also captured")
+            self.assertEqual(len(cm.output), 2)
+
+        # Verify that forwarding is disabled
+        self.assertFalse(log.Log.UsePythonLogging)
+
 
 if __name__ == "__main__":
     unittest.main()