Dedicated caplog recording handler

pytest_catchlog/fixture.py

@@ -10,16 +10,37 @@
 from pytest_catchlog.common import catching_logs, logging_at_level
 
 
+BASIC_FORMATTER = logging.Formatter(logging.BASIC_FORMAT)
+
+
+class RecordingHandler(logging.StreamHandler,
+                       object):  # Python 2.6: enforce new-style class
+    """A logging handler that stores log records and the log text."""
+
+    def __init__(self):
+        """Creates a new log handler."""
+        super(RecordingHandler, self).__init__()
+        self.stream = py.io.TextIO()
+        self.records = []
+
+    def close(self):
+        """Close this log handler and its underlying stream."""
+        super(RecordingHandler, self).close()
+        self.stream.close()
+
+    def emit(self, record):
+        """Keep the log records in a list in addition to the log text."""
+        super(RecordingHandler, self).emit(record)
+        self.records.append(record)
+
+
 class LogCaptureFixture(object):
     """Provides access and control of log capturing."""
 
-    @property
-    def handler(self):
-        return self._item.catch_log_handler
-
-    def __init__(self, item):
+    def __init__(self, handler):
         """Creates a new funcarg."""
-        self._item = item
+        super(LogCaptureFixture, self).__init__()
+        self.handler = handler
 
     @property
     def text(self):
@@ -40,7 +61,7 @@ def record_tuples(self):
 
             (logger_name, log_level, message)
         """
-        return [(r.name, r.levelno, r.getMessage()) for r in self.records]
+        return [(r.name, r.levelno, r.message) for r in self.records]
 
     def set_level(self, level, logger=None):
         """Sets the level for capturing of logs.
@@ -104,6 +125,11 @@ class CallableStr(CallablePropertyMixin, py.builtin.text):
 class CompatLogCaptureFixture(LogCaptureFixture):
     """Backward compatibility with pytest-capturelog."""
 
+    def __init__(self, handler, item):
+        """Creates a new funcarg."""
+        super(CompatLogCaptureFixture, self).__init__(handler)
+        self._item = item
+
     def _warn_compat(self, old, new):
         self._item.warn(code='L1',
                         message=("{0} is deprecated, use {1} instead"
@@ -132,7 +158,7 @@ def atLevel(self, level, logger=None):
         return self.at_level(level, logger)
 
 
-@pytest.fixture
+@pytest.yield_fixture
 def caplog(request):
     """Access and control log capturing.
 
@@ -142,6 +168,8 @@ def caplog(request):
     * caplog.records()       -> list of logging.LogRecord instances
     * caplog.record_tuples() -> list of (logger_name, level, message) tuples
     """
-    return CompatLogCaptureFixture(request.node)
+    with catching_logs(RecordingHandler(),
+                       formatter=BASIC_FORMATTER) as handler:
+        yield CompatLogCaptureFixture(handler, item=request.node)
 
 capturelog = caplog

pytest_catchlog/plugin.py

@@ -83,17 +83,14 @@ def __init__(self, config):
     @contextmanager
     def _runtest_for(self, item, when):
         """Implements the internals of pytest_runtest_xxx() hook."""
-        with catching_logs(LogCaptureHandler(),
-                           formatter=self.formatter) as log_handler:
-            item.catch_log_handler = log_handler
-            try:
+        with closing(py.io.TextIO()) as stream:
+            with catching_logs(logging.StreamHandler(stream),
+                               formatter=self.formatter):
                 yield  # run test
-            finally:
-                del item.catch_log_handler
 
             if self.print_logs:
                 # Add a captured log section to the report.
-                log = log_handler.stream.getvalue().strip()
+                log = stream.getvalue().strip()
                 item.add_report_section(when, 'log', log)
 
     @pytest.mark.hookwrapper
@@ -110,26 +107,3 @@ def pytest_runtest_call(self, item):
     def pytest_runtest_teardown(self, item):
         with self._runtest_for(item, 'teardown'):
             yield
-
-
-class LogCaptureHandler(logging.StreamHandler):
-    """A logging handler that stores log records and the log text."""
-
-    def __init__(self):
-        """Creates a new log handler."""
-
-        logging.StreamHandler.__init__(self)
-        self.stream = py.io.TextIO()
-        self.records = []
-
-    def close(self):
-        """Close this log handler and its underlying stream."""
-
-        logging.StreamHandler.close(self)
-        self.stream.close()
-
-    def emit(self, record):
-        """Keep the log records in a list in addition to the log text."""
-
-        self.records.append(record)
-        logging.StreamHandler.emit(self, record)

tests/test_fixture.py

@@ -1,6 +1,7 @@
 # -*- coding: utf-8 -*-
 import sys
 import logging
+from fnmatch import fnmatch
 
 import pytest
 
@@ -65,3 +66,21 @@ def test_unicode(caplog):
     assert caplog.records[0].levelname == 'INFO'
     assert caplog.records[0].msg == u('bū')
     assert u('bū') in caplog.text
+
+
+def test_mutable_arg(caplog):
+    mutable = {}
+    logger.info("Mutable dict %r empty", mutable)
+    mutable['foo'] = 'bar'
+    logger.info("Mutable dict %r bar", mutable)
+    mutable['foo'] = 'baz'
+    logger.info("Mutable dict %r baz", mutable)
+
+    assert caplog.record_tuples == [
+        (__name__, logging.INFO, "Mutable dict {} empty"),
+        (__name__, logging.INFO, "Mutable dict {'foo': 'bar'} bar"),
+        (__name__, logging.INFO, "Mutable dict {'foo': 'baz'} baz"),
+    ]
+    assert fnmatch(caplog.text, ("*Mutable dict {} empty\n"
+                                 "*Mutable dict {'foo': 'bar'} bar\n"
+                                 "*Mutable dict {'foo': 'baz'} baz\n"))

tests/test_reporting.py

@@ -138,3 +138,26 @@ def test_foo():
                                  'text going to stderr'])
     with pytest.raises(pytest.fail.Exception):
         result.stdout.fnmatch_lines(['*- Captured *log call -*'])
+
+
+def test_mutable_arg(testdir):
+    testdir.makepyfile('''
+        import logging
+
+        logger = logging.getLogger(__name__)
+
+        def test_it():
+            mutable = {}
+            logger.info("Mutable dict %r empty", mutable)
+            mutable['foo'] = 'bar'
+            logger.info("Mutable dict %r bar", mutable)
+            mutable['foo'] = 'baz'
+            logger.info("Mutable dict %r baz", mutable)
+            assert False
+        ''')
+    result = testdir.runpytest()
+    assert result.ret == 1
+    result.stdout.fnmatch_lines(['*- Captured *log call -*',
+                                 "*Mutable dict {} empty",
+                                 "*Mutable dict {'foo': 'bar'} bar",
+                                 "*Mutable dict {'foo': 'baz'} baz"])