def testMdcUpdate(self):
"""Test for overwriting MDC.
"""
expected_msg = \
"INFO - Message one {}\n" \
"INFO - Message two {{LABEL,123456}}\n" \
"INFO - Message three {{LABEL,654321}}\n" \
"INFO - Message four {}\n"
with TestLog.StdoutCapture(self.outputFilename):
self.configure("""
log4j.rootLogger=DEBUG, CA
log4j.appender.CA=ConsoleAppender
log4j.appender.CA.layout=PatternLayout
log4j.appender.CA.layout.ConversionPattern=%-5p - %m %X%n
""")
log.info("Message one")
log.MDC("LABEL", "123456")
log.info("Message two")
log.MDC("LABEL", "654321")
log.info("Message three")
log.MDCRemove("LABEL")
log.info("Message four")
self.check(expected_msg)
def testPattern(self):
"""
Test a complex pattern for log messages, including Mapped
Diagnostic Context (MDC).
"""
with TestLog.StdoutCapture(self.outputFilename):
self.configure("""
log4j.rootLogger=DEBUG, CA
log4j.appender.CA=ConsoleAppender
log4j.appender.CA.layout=PatternLayout
log4j.appender.CA.layout.ConversionPattern=%-5p %c %C %M (%F:%L) %l - %m - %X%n
""")
log.trace("This is TRACE")
log.info("This is INFO")
log.debug("This is DEBUG")
log.MDC("x", 3)
log.MDC("y", "foo")
log.MDC("z", TestLog)
log.trace("This is TRACE 2")
log.info("This is INFO 2")
log.debug("This is DEBUG 2")
log.MDCRemove("z")
with log.LogContext("component"):
log.trace("This is TRACE 3")
log.info("This is INFO 3")
log.debug("This is DEBUG 3")
log.MDCRemove("x")
log.trace("This is TRACE 4")
log.info("This is INFO 4")
log.debug("This is DEBUG 4")
log.trace("This is TRACE 5")
log.info("This is INFO 5")
log.debug("This is DEBUG 5")
log.MDCRemove("y")
# Use format to make line numbers easier to change.
self.check("""
INFO root testPattern (test_log.py:{0[0]}) test_log.py({0[0]}) - This is INFO - {{}}
DEBUG root testPattern (test_log.py:{0[1]}) test_log.py({0[1]}) - This is DEBUG - {{}}
INFO root testPattern (test_log.py:{0[2]}) test_log.py({0[2]}) - This is INFO 2 - {{{{x,3}}{{y,foo}}{{z,<class '{1}.TestLog'>}}}}
DEBUG root testPattern (test_log.py:{0[3]}) test_log.py({0[3]}) - This is DEBUG 2 - {{{{x,3}}{{y,foo}}{{z,<class '{1}.TestLog'>}}}}
INFO component testPattern (test_log.py:{0[4]}) test_log.py({0[4]}) - This is INFO 3 - {{{{x,3}}{{y,foo}}}}
DEBUG component testPattern (test_log.py:{0[5]}) test_log.py({0[5]}) - This is DEBUG 3 - {{{{x,3}}{{y,foo}}}}
INFO component testPattern (test_log.py:{0[6]}) test_log.py({0[6]}) - This is INFO 4 - {{{{y,foo}}}}
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 + 209 for x in (0, 1, 8, 9, 14, 15, 18, 19, 22, 23)],
__name__)) # noqa E501 line too long
def testHostNameAndProcessId(self):
testEnv = EventsEnvironment()
topic = testEnv.getLoggingTopic()
confStr = "log4j.rootLogger=TRACE, EA\n"
confStr += "log4j.appender.EA=EventAppender\n"
confStr += "log4j.appender.EA.BROKER=" + testEnv.getBroker() + "\n"
confStr += "log4j.appender.EA.TOPIC=" + topic + "\n"
self.configure(confStr)
recv = events.EventReceiver(testEnv.getBroker(), topic)
log.MDC("x", 3)
with log.LogContext("component"):
log.trace("This is TRACE")
log.MDCRemove("x")
e = recv.receiveEvent()
self.assertValidMessage(e, "This is TRACE")
ps = e.getPropertySet()
# the host name should be the same since we're sending and receiving
# from the same host
host = ps.get(events.LogEvent.ORIG_HOSTNAME)
self.assertEqual(host, socket.gethostname())
# the process id should be the same since we're sending and receiving
# from the same process
pid = ps.get(events.LogEvent.ORIG_PROCESSID)
self.assertEqual(os.getpid(), pid)
t = ps.get(events.LogEvent.TYPE)
self.assertEqual(t, events.EventTypes.LOG)
def jobLog(job):
"""Add a job-specific log destination"""
if job is None or job == "None":
return
packageDir = getPackageDir("ctrl_pool")
# Set the environment variable which names the output file
os.environ['JOBNAME'] = job
lsstLog.configure(os.path.join(packageDir, "config/log4cxx.properties"))
lsstLog.MDC("PID", os.getpid())
def a(visit):
# Set subcomponent to "a" (sets component to "main.a")
with log.LogContext("a"):
# Clean out any previous MDC for visit
log.MDCRemove("visit")
# All subsequent log messages will have visit id
log.MDC("visit", visit)
log.info("In a, %d", visit)
log.debug("Debug message in a")
b()
log.info("Leaving a")
def testForwardToPythonAppenderWithMDC(self):
"""Test that `log4cxx` appender forwards it all to logging and modifies
message with MDC info"""
self.configure("""
log4j.rootLogger=DEBUG, PyLog
log4j.appender.PyLog = PyLogAppender
log4j.appender.PyLog.MessagePattern = %m (LABEL=%X{{LABEL}})
""")
log.MDC("LABEL", "some.task")
with self.assertLogs(level="WARNING") as cm:
log.warn("lsst.log: forwarded")
log.MDCRemove("LABEL")
self.assertEqual(len(cm.records), 1)
self.assertEqual(cm.records[0].MDC, {"LABEL": "some.task"})
self.assertEqual(cm.records[0].msg,
"lsst.log: forwarded (LABEL=some.task)")
def testFileAppender(self):
"""Test configuring logging to go to a file."""
self.configure("""
log4j.rootLogger=DEBUG, FA
log4j.appender.FA=FileAppender
log4j.appender.FA.file={0}
log4j.appender.FA.layout=SimpleLayout
""")
log.MDC("x", 3)
log.trace("This is TRACE")
log.info("This is INFO")
log.debug("This is DEBUG")
log.MDCRemove("x")
self.check("""
INFO - This is INFO
DEBUG - This is DEBUG
""")
def testForwardToPythonAppender(self):
"""Test that `log4cxx` appender forwards it all to logging"""
self.configure("""
log4j.rootLogger=DEBUG, PyLog
log4j.appender.PyLog = PyLogAppender
""")
with self.assertLogs(level="WARNING") as cm:
log.warn("lsst.log: forwarded")
logging.warning("Python logging: also captured")
self.assertEqual(len(cm.output), 2)
# check that MDC is stored in LogRecord
log.MDC("LABEL", "some.task")
with self.assertLogs(level="WARNING") as cm:
log.warn("lsst.log: forwarded")
log.MDCRemove("LABEL")
self.assertEqual(len(cm.records), 1)
self.assertEqual(cm.records[0].MDC, {"LABEL": "some.task"})
self.assertEqual(cm.records[0].msg, "lsst.log: forwarded")
def testMDCPutPid(self):
"""
Test add of PID Mapped Diagnostic Context (MDC).
"""
pid = os.fork()
try:
log.MDC("PID", os.getpid())
self.configure("""
log4j.rootLogger=DEBUG, CA
log4j.appender.CA=ConsoleAppender
log4j.appender.CA.layout=PatternLayout
log4j.appender.CA.layout.ConversionPattern=%-5p PID:%X{{PID}} %c %C %M (%F:%L) %l - %m%n
""") # noqa E501 line too long
self.assertGreaterEqual(pid, 0, "Failed to fork")
msg = "This is INFO"
if pid == 0:
self.tempDir = tempfile.mkdtemp()
self.outputFilename = os.path.join(self.tempDir,
"log-child.out")
msg += " in child process"
elif pid > 0:
child_pid, child_status = os.wait()
self.assertEqual(child_status, 0,
"Child returns incorrect code")
msg += " in parent process"
with TestLog.StdoutCapture(self.outputFilename):
log.info(msg)
line = 279
finally:
log.MDCRemove("PID")
# Use format to make line numbers easier to change.
self.check("""
INFO PID:{1} root testMDCPutPid (test_log.py:{0}) test_log.py({0}) - {2}
""".format(line, os.getpid(), msg))
# don't pass other tests in child process
if pid is 0:
os._exit(0)
def testBrokerOption(self):
testEnv = EventsEnvironment()
topic = testEnv.getLoggingTopic()
confStr = "log4j.rootLogger=TRACE, EA\n"
confStr += "log4j.appender.EA=EventAppender\n"
confStr += "log4j.appender.EA.BROKER=" + testEnv.getBroker() + "\n"
confStr += "log4j.appender.EA.TOPIC=" + topic + "\n"
self.configure(confStr)
recv = events.EventReceiver(testEnv.getBroker(), topic)
log.MDC("x", 3)
with log.LogContext("component"):
log.trace("This is TRACE")
log.info("This is INFO")
log.debug("This is DEBUG")
log.MDCRemove("x")
self.assertValidMessage(recv.receiveEvent(), "This is TRACE")
self.assertValidMessage(recv.receiveEvent(), "This is INFO")
self.assertValidMessage(recv.receiveEvent(), "This is DEBUG")
def testRunidSelector(self):
testEnv = EventsEnvironment()
topic = testEnv.getLoggingTopic()
confStr = "log4j.rootLogger=TRACE, EA\n"
confStr += "log4j.appender.EA=EventAppender\n"
confStr += "log4j.appender.EA.BROKER=" + testEnv.getBroker() + "\n"
confStr += "log4j.appender.EA.RUNID=" + str(os.getpid()) + "\n"
confStr += "log4j.appender.EA.TOPIC=" + topic + "\n"
self.configure(confStr)
# receive for all events
recvALL = events.EventReceiver(testEnv.getBroker(), topic)
# receive for events for this runid
recv = events.EventReceiver(testEnv.getBroker(), topic,
"RUNID = '%s'" % str(os.getpid()))
# send log messages
log.MDC("x", 3)
with log.LogContext("component"):
log.trace("This is TRACE")
log.info("This is INFO")
log.debug("This is DEBUG")
log.MDCRemove("x")
# make sure we got all the events we should have
self.assertValidMessage(recv.receiveEvent(), "This is TRACE")
self.assertValidMessage(recv.receiveEvent(), "This is INFO")
self.assertValidMessage(recv.receiveEvent(), "This is DEBUG")
# make sure we didn't get any more than we should have
ev = recv.receiveEvent(100)
self.assertIsNone(ev)
# reconfigure with a new run id
confStr2 = "log4j.rootLogger=TRACE, EA\n"
confStr2 += "log4j.appender.EA=EventAppender\n"
confStr2 += "log4j.appender.EA.BROKER=" + testEnv.getBroker() + "\n"
confStr2 += "log4j.appender.EA.RUNID=" + "blah_" + str(
os.getpid()) + "\n"
confStr2 += "log4j.appender.EA.TOPIC=" + topic + "\n"
self.configure(confStr2)
# set up a receiver for the new run id
recv2 = events.EventReceiver(testEnv.getBroker(), topic,
"RUNID = 'blah_%s'" % str(os.getpid()))
# send log messages
log.MDC("x", 3)
with log.LogContext("component"):
log.trace("This is TRACE")
log.info("This is INFO")
log.debug("This is DEBUG")
log.MDCRemove("x")
# make sure we didn't receive any events from another run id
ev = recv.receiveEvent(100)
self.assertIsNone(ev)
# make sure we got all the events we should have
self.assertValidMessage(recv2.receiveEvent(), "This is TRACE")
self.assertValidMessage(recv2.receiveEvent(), "This is INFO")
self.assertValidMessage(recv2.receiveEvent(), "This is DEBUG")
# make sure we didn't get any more than we should have
ev = recv2.receiveEvent(100)
self.assertIsNone(ev)
# make sure we got all the events, for all messages on this topic
self.assertValidMessage(recvALL.receiveEvent(), "This is TRACE")
self.assertValidMessage(recvALL.receiveEvent(), "This is INFO")
self.assertValidMessage(recvALL.receiveEvent(), "This is DEBUG")
self.assertValidMessage(recvALL.receiveEvent(), "This is TRACE")
self.assertValidMessage(recvALL.receiveEvent(), "This is INFO")
self.assertValidMessage(recvALL.receiveEvent(), "This is DEBUG")
# make sure we didn't get any more than we should have
ev = recvALL.receiveEvent(100)
self.assertIsNone(ev)
def fun():
log.MDC("MDC_INIT", "OK")
def testForwardToPythonAppenderFormatMDC(self):
"""Test that we can format `log4cxx` MDC on Python side"""
# remember old record factory
old_factory = logging.getLogRecordFactory()
# configure things using convenience method
log.configure_pylog_MDC("INFO")
with self.assertLogs(level="WARNING") as cm:
log.warn("lsst.log: forwarded 1")
log.MDC("LABEL", "task1")
log.warn("lsst.log: forwarded 2")
log.MDC("LABEL-X", "task2")
log.warn("lsst.log: forwarded 3")
logging.warning("Python logging: also captured")
log.MDCRemove("LABEL")
log.MDCRemove("LABEL-X")
self.assertEqual(len(cm.records), 4)
# restore factory
logging.setLogRecordFactory(old_factory)
# %-style formatting, only works on whole MDC
formatter = logging.Formatter(fmt="%(levelname)s:%(name)s:%(message)s",
style="%")
self.assertEqual(formatter.format(cm.records[0]),
"WARNING:root:lsst.log: forwarded 1")
formatter = logging.Formatter(
fmt="%(levelname)s:%(name)s:%(message)s:%(MDC)s", style="%")
self.assertEqual(formatter.format(cm.records[0]),
"WARNING:root:lsst.log: forwarded 1:{}")
self.assertEqual(formatter.format(cm.records[1]),
"WARNING:root:lsst.log: forwarded 2:{LABEL=task1}")
self.assertEqual(
formatter.format(cm.records[2]),
"WARNING:root:lsst.log: forwarded 3:{LABEL=task1, LABEL-X=task2}")
self.assertEqual(formatter.format(cm.records[3]),
"WARNING:root:Python logging: also captured:{}")
# format-style formatting, without MDC first
formatter = logging.Formatter(fmt="{levelname}:{name}:{message}",
style="{")
self.assertEqual(formatter.format(cm.records[0]),
"WARNING:root:lsst.log: forwarded 1")
# format-style formatting, with full MDC
formatter = logging.Formatter(fmt="{levelname}:{name}:{message}:{MDC}",
style="{")
self.assertEqual(formatter.format(cm.records[0]),
"WARNING:root:lsst.log: forwarded 1:{}")
self.assertEqual(formatter.format(cm.records[1]),
"WARNING:root:lsst.log: forwarded 2:{LABEL=task1}")
self.assertEqual(
formatter.format(cm.records[2]),
"WARNING:root:lsst.log: forwarded 3:{LABEL=task1, LABEL-X=task2}")
self.assertEqual(formatter.format(cm.records[3]),
"WARNING:root:Python logging: also captured:{}")
# format-style, using index access to MDC items, works for almost any
# item names
formatter = logging.Formatter(
fmt="{levelname}:{name}:{message}:{MDC[LABEL-X]}", style="{")
self.assertEqual(formatter.format(cm.records[0]),
"WARNING:root:lsst.log: forwarded 1:")
self.assertEqual(formatter.format(cm.records[1]),
"WARNING:root:lsst.log: forwarded 2:")
self.assertEqual(formatter.format(cm.records[2]),
"WARNING:root:lsst.log: forwarded 3:task2")
self.assertEqual(formatter.format(cm.records[3]),
"WARNING:root:Python logging: also captured:")