def testPythonLogging(self):
"""Test logging through the Python logging interface."""
with TestLog.StdoutCapture(self.outputFilename):
lgr = logging.getLogger()
lgr.setLevel(logging.INFO)
log.configure()
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("""
root INFO: This is INFO
root WARN: This is WARNING
root INFO: ((1, 2), (3, 4))
root INFO: {1: 2}
""")
def initLog(cls, longlog):
"""Initialize logging. This should only be called once per program
execution. After the first call this will log a warning and return.
If lsst.log is importable, will add its log handler to the python
root logger's handlers.
Parameters
----------
longlog : `bool`
If True, make log messages appear in long format, by default False.
"""
if cls._initialized:
# Unit tests that execute more than one command do end up
# calling this function multiple times in one program execution,
# so do log a debug but don't log an error or fail, just make the
# re-initialization a no-op.
log = logging.getLogger(__name__)
log.debug(
"Log is already initialized, returning without re-initializing."
)
return
cls._initialized = True
if lsstLog is not None:
# Initialize global logging config. Skip if the env var
# LSST_LOG_CONFIG exists. The file it points to would already
# configure lsst.log.
if not os.path.isfile(os.environ.get("LSST_LOG_CONFIG", "")):
lsstLog.configure_prop(
_LOG_PROP.format(cls.lsstLog_longLogFmt
if longlog else cls.lsstLog_normalLogFmt))
cls._recordComponentSetting(None)
pythonLogger = logging.getLogger()
pythonLogger.setLevel(logging.INFO)
cls._lsstLogHandler = lsstLog.LogHandler()
# Forward all Python logging to lsstLog
pythonLogger.addHandler(cls._lsstLogHandler)
else:
cls._recordComponentSetting(None)
if longlog:
logging.basicConfig(level=logging.INFO,
format=cls.pylog_longLogFmt,
datefmt=cls.pylog_longLogDateFmt)
else:
logging.basicConfig(level=logging.INFO,
format=cls.pylog_normalFmt)
# also capture warnings and send them to logging
logging.captureWarnings(True)
# remember this call
cls.configState.append((cls.initLog, longlog))
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")
logging.shutdown()
self.check("""
root INFO: This is INFO
""")
def initLog(cls, longlog):
"""Initialize logging. This should only be called once per program
execution. After the first call this will log a warning and return.
If lsst.log is importable, will add its log handler to the python
root logger's handlers.
Parameters
----------
longlog : `bool`
If True, make log messages appear in long format, by default False.
"""
if cls._initialized:
# Unit tests that execute more than one command do end up
# calling this fucntion multiple times in one program execution,
# so do log a debug but don't log an error or fail, just make the
# re-initalization a no-op.
log = logging.getLogger(__name__.partition(".")[2])
log.debug(
"Log is already initialized, returning without re-initializing."
)
return
cls._initialized = True
if lsstLog is not None:
# global logging config
lsstLog.configure_prop(
_LOG_PROP.format(
cls.longLogFmt if longlog else cls.normalLogFmt))
cls._recordComponentSetting(None)
pythonLogger = logging.getLogger()
pythonLogger.setLevel(logging.INFO)
cls._lsstLogHandler = lsstLog.LogHandler()
# Forward all Python logging to lsstLog
pythonLogger.addHandler(cls._lsstLogHandler)
else:
cls._recordComponentSetting(None)
logging.basicConfig(level=logging.INFO)
# also capture warnings and send them to logging
logging.captureWarnings(True)
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()