def testContext(self):
"""Test the log context/component stack."""
with TestLog.StdoutCapture(self.outputFilename):
log.configure()
log.setLevel('', log.DEBUG)
log.trace("This is TRACE")
log.info("This is INFO")
log.debug("This is DEBUG")
with log.LogContext("component"):
log.trace("This is TRACE")
log.info("This is INFO")
log.debug("This is DEBUG")
log.trace("This is TRACE 2")
log.info("This is INFO 2")
log.debug("This is DEBUG 2")
with log.LogContext("comp") as ctx:
log.trace("This is TRACE 3")
log.info("This is INFO 3")
log.debug("This is DEBUG 3")
ctx.setLevel(log.INFO)
self.assertEqual(ctx.getLevel(), log.INFO)
self.assertTrue(ctx.isEnabledFor(log.INFO))
log.trace("This is TRACE 3a")
log.info("This is INFO 3a")
log.debug("This is DEBUG 3a")
with log.LogContext("subcomp", log.TRACE) as ctx2:
self.assertEqual(ctx2.getLevel(), log.TRACE)
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")
self.check("""
root INFO: This is INFO
root DEBUG: This is DEBUG
component INFO: This is INFO
component DEBUG: This is DEBUG
root INFO: This is INFO 2
root DEBUG: This is DEBUG 2
comp INFO: This is INFO 3
comp DEBUG: This is DEBUG 3
comp INFO: This is INFO 3a
comp.subcomp TRACE: This is TRACE 4
comp.subcomp INFO: This is INFO 4
comp.subcomp DEBUG: This is DEBUG 4
comp INFO: This is INFO 5
""")
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 main():
# Set component to "main" (from "root")
with log.LogContext("main"):
log.info("In main")
visits = [12345, 67890, 27182, 31415]
pool = mp.Pool(processes=2)
pool.map_async(a, visits)
pool.close()
pool.join()
b()
log.info("Leaving main")
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 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 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)
with log.LogContext("component"):
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 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 b():
# Set subcomponent to "b" (sets component to "main.a.b" or "main.b")
with log.LogContext("b"):
log.info("In b")
log.debug("Testing; logged only when called by a")
log.info("Leaving b")