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 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 testMdcInit(self): expected_msg = \ "INFO - main thread {{MDC_INIT,OK}}\n" + \ "INFO - thread 1 {{MDC_INIT,OK}}\n" + \ "INFO - thread 2 {{MDC_INIT,OK}}\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 """) def fun(): log.MDC("MDC_INIT", "OK") log.MDCRegisterInit(fun) log.info("main thread") thread = threading.Thread(target=lambda: log.info("thread 1")) thread.start() thread.join() thread = threading.Thread(target=lambda: log.info("thread 2")) thread.start() thread.join() self.check(expected_msg) log.MDCRemove("MDC_INIT")
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 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:")