From 9dbcac9af39a032e9ea224d6979a859568b277fd Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Thu, 18 Jan 2018 21:10:35 -0200 Subject: [PATCH] Suspend stdout/stderr capturing when emitting live logging messages --- _pytest/logging.py | 40 ++++++++++++--- testing/logging/test_reporting.py | 85 +++++++++++++++++++++++++++++++ 2 files changed, 117 insertions(+), 8 deletions(-) diff --git a/_pytest/logging.py b/_pytest/logging.py index 9e806e106..254740188 100644 --- a/_pytest/logging.py +++ b/_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() diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index c34d5f7dc..0bd017057 100644 --- a/testing/logging/test_reporting.py +++ b/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'