Suspend stdout/stderr capturing when emitting live logging messages

_pytest/logging.py

@@ -319,6 +319,8 @@ class LoggingPlugin(object):
 
     @pytest.hookimpl(hookwrapper=True)
     def pytest_runtest_setup(self, item):
+        if self.log_cli_handler is not None:
+            self.log_cli_handler.reset()
         with self._runtest_for(item, 'setup'):
             yield
 
@@ -352,12 +354,13 @@ class LoggingPlugin(object):
         """
         terminal_reporter = self._config.pluginmanager.get_plugin('terminalreporter')
         if self._config.getini('log_cli') and terminal_reporter is not None:
-            log_cli_handler = _LiveLoggingStreamHandler(terminal_reporter._tw)
+            capture_manager = self._config.pluginmanager.get_plugin('capturemanager')
+            log_cli_handler = _LiveLoggingStreamHandler(terminal_reporter, capture_manager)
             log_cli_format = get_option_ini(self._config, 'log_cli_format', 'log_format')
             log_cli_date_format = get_option_ini(self._config, 'log_cli_date_format', 'log_date_format')
             log_cli_formatter = logging.Formatter(log_cli_format, datefmt=log_cli_date_format)
             log_cli_level = get_actual_log_level(self._config, 'log_cli_level', 'log_level')
-            self.log_cli_handler = log_cli_handler  # needed for a single unittest
+            self.log_cli_handler = log_cli_handler
             self.live_logs_context = catching_logs(log_cli_handler, formatter=log_cli_formatter, level=log_cli_level)
         else:
             self.log_cli_handler = None
@@ -368,12 +371,33 @@ class _LiveLoggingStreamHandler(logging.StreamHandler):
     """
     Custom StreamHandler used by the live logging feature: it will write a newline before the first log message
     in each test.
+
+    During live logging we must also explicitly disable stdout/stderr capturing otherwise it will get captured
+    and won't appear in the terminal.
     """
 
+    def __init__(self, terminal_reporter, capture_manager):
+        """
+        :param _pytest.terminal.TerminalReporter terminal_reporter:
+        :param _pytest.capture.CaptureManager capture_manager:
+        """
+        logging.StreamHandler.__init__(self, stream=terminal_reporter)
+        self.capture_manager = capture_manager
+        self._first_record_emitted = False
+
+    def reset(self):
+        self._first_record_emitted = False
+
     def emit(self, record):
-        if not getattr(self, '_first_record_emitted', False):
-            self.stream.write('\n')
-            # we might consider adding a header at this point using self.stream.sep('-', 'live log') or something
-            # similar when we improve live logging output
-            self._first_record_emitted = True
-        logging.StreamHandler.emit(self, record)
+        if self.capture_manager is not None:
+            self.capture_manager.suspend_global_capture()
+        try:
+            if not self._first_record_emitted:
+                self.stream.write('\n')
+                # we might consider adding a header at this point using self.stream.section('live log', sep='-')
+                # or something similar when we improve live logging output
+                self._first_record_emitted = True
+            logging.StreamHandler.emit(self, record)
+        finally:
+            if self.capture_manager is not None:
+                self.capture_manager.resume_global_capture()

testing/logging/test_reporting.py

@@ -1,5 +1,8 @@
 # -*- coding: utf-8 -*-
 import os
+
+import six
+
 import pytest
 
 
@@ -193,6 +196,36 @@ def test_log_cli_default_level(testdir):
     assert result.ret == 0
 
 
+def test_log_cli_default_level_multiple_tests(testdir):
+    """Ensure we reset the first newline added by the live logger between tests"""
+    # Default log file level
+    testdir.makepyfile('''
+        import pytest
+        import logging
+
+        def test_log_1(request):
+            logging.warning("log message from test_log_1")
+
+        def test_log_2(request):
+            logging.warning("log message from test_log_2")
+    ''')
+    testdir.makeini('''
+        [pytest]
+        log_cli=true
+    ''')
+
+    result = testdir.runpytest()
+    result.stdout.fnmatch_lines([
+        'test_log_cli_default_level_multiple_tests.py::test_log_1 ',
+        '*WARNING*log message from test_log_1*',
+        'PASSED *50%*',
+        'test_log_cli_default_level_multiple_tests.py::test_log_2 ',
+        '*WARNING*log message from test_log_2*',
+        'PASSED *100%*',
+        '=* 2 passed in *=',
+    ])
+
+
 def test_log_cli_level(testdir):
     # Default log file level
     testdir.makepyfile('''
@@ -410,3 +443,55 @@ def test_log_file_ini_level(testdir):
         contents = rfh.read()
         assert "This log message will be shown" in contents
         assert "This log message won't be shown" not in contents
+
+
+@pytest.mark.parametrize('has_capture_manager', [True, False])
+def test_live_logging_suspends_capture(has_capture_manager, request):
+    """Test that capture manager is suspended when we emitting messages for live logging.
+
+    This tests the implementation calls instead of behavior because it is difficult/impossible to do it using
+    ``testdir`` facilities because they do their own capturing.
+
+    We parametrize the test to also make sure _LiveLoggingStreamHandler works correctly if no capture manager plugin
+    is installed.
+    """
+    import logging
+    from functools import partial
+    from _pytest.capture import CaptureManager
+    from _pytest.logging import _LiveLoggingStreamHandler
+
+    if six.PY2:
+        # need to use the 'generic' StringIO instead of io.StringIO because we might receive both bytes
+        # and unicode objects; io.StringIO only accepts unicode
+        from StringIO import StringIO
+    else:
+        from io import StringIO
+
+    class MockCaptureManager:
+        calls = []
+
+        def suspend_global_capture(self):
+            self.calls.append('suspend_global_capture')
+
+        def resume_global_capture(self):
+            self.calls.append('resume_global_capture')
+
+    # sanity check
+    assert CaptureManager.suspend_capture_item
+    assert CaptureManager.resume_global_capture
+
+    capture_manager = MockCaptureManager() if has_capture_manager else None
+    out_file = StringIO()
+
+    handler = _LiveLoggingStreamHandler(out_file, capture_manager)
+
+    logger = logging.getLogger(__file__ + '.test_live_logging_suspends_capture')
+    logger.addHandler(handler)
+    request.addfinalizer(partial(logger.removeHandler, handler))
+
+    logger.critical('some message')
+    if has_capture_manager:
+        assert MockCaptureManager.calls == ['suspend_global_capture', 'resume_global_capture']
+    else:
+        assert MockCaptureManager.calls == []
+    assert out_file.getvalue() == '\nsome message\n'