Live logs (-s / --capture=no)

pytest_catchlog.py

@@ -118,25 +118,40 @@ def __init__(self, config):
         The formatter can be safely shared across all handlers so
         create a single one for the entire test session here.
         """
+        self.capture_logs = (config.getoption('capture', 'no') != 'no')
         self.print_logs = config.getoption('log_print')
         self.formatter = logging.Formatter(
                 get_option_ini(config, 'log_format'),
                 get_option_ini(config, 'log_date_format'))
 
+        handler = logging.StreamHandler()  # streams to stderr by default
+        handler.setFormatter(self.formatter)
+
+        self.handler = handler
+
+    @pytest.mark.hookwrapper
+    def pytest_runtestloop(self, session):
+        """Runs all collected test items."""
+        with catching_logs(self.handler):
+            yield  # run all the tests
+
     @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
+        if not self.capture_logs:
+            yield
+            return
+        with closing(py.io.TextIO()) as stream:
+            orig_stream = self.handler.stream
+            self.handler.stream = stream
             try:
                 yield  # run test
             finally:
-                del item.catch_log_handler
+                self.handler.stream = orig_stream
 
             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
@@ -155,44 +170,24 @@ def pytest_runtest_teardown(self, item):
             yield
 
 
-class LogCaptureHandler(logging.StreamHandler):
-    """A logging handler that stores log records and the log text."""
+class RecordingHandler(logging.Handler, object):  # Python 2.6: new-style class
+    """A logging handler that stores log records into a buffer."""
 
     def __init__(self):
-        """Creates a new log handler."""
-
-        logging.StreamHandler.__init__(self)
-        self.stream = py.io.TextIO()
+        super(RecordingHandler, self).__init__()
         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."""
-
+    def emit(self, record):  # Called with the lock acquired.
         self.records.append(record)
-        logging.StreamHandler.emit(self, 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
-
-    @property
-    def text(self):
-        """Returns the log text."""
-        return self.handler.stream.getvalue()
+        super(LogCaptureFixture, self).__init__()
+        self.handler = handler
 
     @property
     def records(self):
@@ -210,6 +205,12 @@ def record_tuples(self):
         """
         return [(r.name, r.levelno, r.getMessage()) for r in self.records]
 
+    @property
+    def text(self):
+        """Returns the log text."""
+        record_fmt = logging.BASIC_FORMAT + '\n'  # always the standard format
+        return ''.join(record_fmt % r.__dict__ for r in self.records)
+
     def set_level(self, level, logger=None):
         """Sets the level for capturing of logs.
 
@@ -268,6 +269,11 @@ class CallableStr(CallablePropertyMixin, str):
 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"
@@ -296,7 +302,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.
 
@@ -306,6 +312,7 @@ 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()) as handler:
+        yield CompatLogCaptureFixture(handler, item=request.node)
 
 capturelog = caplog

test_pytest_catchlog.py

@@ -100,17 +100,13 @@ def test_foo(caplog):
             log.warning('logger WARNING level')
             log.critical('logger CRITICAL level')
 
-            assert False
+            assert 'DEBUG' not in caplog.text
+            assert 'INFO' in caplog.text
+            assert 'WARNING' not in caplog.text
+            assert 'CRITICAL' in caplog.text
         ''')
     result = testdir.runpytest()
-    assert result.ret == 1
-    result.stdout.fnmatch_lines(['*- Captured *log call -*',
-                                 '*handler INFO level*',
-                                 '*logger CRITICAL level*'])
-    py.test.raises(Exception, result.stdout.fnmatch_lines,
-                   ['*- Captured *log call -*', '*handler DEBUG level*'])
-    py.test.raises(Exception, result.stdout.fnmatch_lines,
-                   ['*- Captured *log call -*', '*logger WARNING level*'])
+    assert result.ret == 0
 
 
 @py.test.mark.skipif('sys.version_info < (2,5)')
@@ -131,17 +127,13 @@ def test_foo(caplog):
                     log.warning('logger WARNING level')
                     log.critical('logger CRITICAL level')
 
-            assert False
+            assert 'DEBUG' not in caplog.text
+            assert 'INFO' in caplog.text
+            assert 'WARNING' not in caplog.text
+            assert 'CRITICAL' in caplog.text
         ''')
     result = testdir.runpytest()
-    assert result.ret == 1
-    result.stdout.fnmatch_lines(['*- Captured *log call -*',
-                                 '*handler INFO level*',
-                                 '*logger CRITICAL level*'])
-    py.test.raises(Exception, result.stdout.fnmatch_lines,
-                   ['*- Captured *log call -*', '*handler DEBUG level*'])
-    py.test.raises(Exception, result.stdout.fnmatch_lines,
-                   ['*- Captured *log call -*', '*logger WARNING level*'])
+    assert result.ret == 0
 
 
 def test_log_access(testdir):
@@ -231,6 +223,22 @@ def test_foo(caplog):
     ''')
 
 
+def test_live_logs(testdir):
+    testdir.makepyfile('''
+        import sys
+        import logging
+
+        logger = logging.getLogger()
+
+        def test_foo(caplog):
+            logger.warning("I'm logging, I'm alive!")
+            sys.stderr.write('text going to stderr')
+        ''')
+    result = testdir.runpytest('-s')
+    result.stderr.fnmatch_lines(["*WARNING*I'm logging, I'm alive!*",
+                                 'text going to stderr'])
+
+
 def test_disable_log_capturing(testdir):
     testdir.makepyfile('''
         import sys