Merge pull request #1341 from mhartmay/logforwarder-fix

master: Fix LogForwarder in case an own LogRecordFactory is used

mitogen/master.py

@@ -370,15 +370,19 @@ class LogForwarder(object):
         if logger is None:
             self._cache[logger_name] = logger = logging.getLogger(logger_name)
 
+        levelno = int(level_s)
         # See logging.Handler.makeRecord()
-        record = logging.LogRecord(
-            name=logger.name,
-            level=int(level_s),
-            pathname='(unknown file)',
-            lineno=0,
-            msg=s,
-            args=(),
-            exc_info=None,
+        record = logging.makeLogRecord(
+            {
+                "name": logger.name,
+                "levelname": logging.getLevelName(levelno),
+                "levelno": levelno,
+                "pathname": "(unknown file)",
+                "lineno": 0,
+                "msg": s,
+                "args": (),
+                "exc_info": None,
+            }
         )
         record.mitogen_message = s
         record.mitogen_context = self._router.context_by_id(msg.src_id)

tests/log_handler_test.py

@@ -14,11 +14,28 @@ import mitogen.parent
 import mitogen.utils
 from mitogen.core import b
 
+PY2 = sys.version_info[0] == 2
+if PY2:
+
+    def logging_getLogRecordFactory():
+        return logging.LogRecord
+
+    def logging_setLogRecordFactory(factory):
+        logging.LogRecord = factory
+
+else:
+    logging_getLogRecordFactory = logging.getLogRecordFactory
+    logging_setLogRecordFactory = logging.setLogRecordFactory
+
 
 def ping():
     pass
 
 
+def log_test():
+    logging.getLogger(__name__).info("This is a test")
+
+
 class BufferingTest(testlib.TestCase):
     klass = mitogen.core.LogHandler
 
@@ -89,6 +106,36 @@ class StartupTest(testlib.RouterMixin, testlib.TestCase):
         expect = 'Parent is context %s (%s)' % (c1.context_id, 'parent')
         self.assertIn(expect, logs)
 
+
+class LogRecordFactoryTest(testlib.RouterMixin, testlib.TestCase):
+    def setUp(self):
+        super(LogRecordFactoryTest, self).setUp()
+        self.original_factory = logging_getLogRecordFactory()
+
+    def tearDown(self):
+        logging_setLogRecordFactory(self.original_factory)
+        super(LogRecordFactoryTest, self).tearDown()
+
+    def test_logrecordfactory(self):
+        # Change logging factory and add a custom attribute
+        old_factory = logging_getLogRecordFactory()
+
+        def record_factory(*args, **kwargs):
+            record = old_factory(*args, **kwargs)
+            record.custom_attribute = 0xDEADBEEF
+            return record
+
+        logging_setLogRecordFactory(record_factory)
+        c1 = self.router.local(name="c1")
+        log = testlib.LogCapturer(
+            __name__, formatter=logging.Formatter("%(custom_attribute)x - %(message)s")
+        )
+        log.start()
+        c1.call(log_test)
+        logs = log.stop()
+        self.assertIn("deadbeef - This is a test", logs)
+
+
 StartupTest = unittest.skipIf(
     condition=sys.version_info < (2, 7) or sys.version_info >= (3, 6),
     reason="Message log flaky on Python < 2.7 or >= 3.6"

tests/testlib.py

@@ -393,10 +393,13 @@ class CaptureStreamHandler(logging.StreamHandler):
 
 
 class LogCapturer(object):
-    def __init__(self, name=None):
+    def __init__(self, name=None, formatter=None):
         self.sio = StringIO()
         self.logger = logging.getLogger(name)
-        self.handler = CaptureStreamHandler(self.sio)
+        handler = CaptureStreamHandler(self.sio)
+        if formatter is not None:
+            handler.setFormatter(formatter)
+        self.handler = handler
         self.old_propagate = self.logger.propagate
         self.old_handlers = self.logger.handlers
         self.old_level = self.logger.level