diff --git a/_pytest/logging.py b/_pytest/logging.py index 8086ea386..9b290c390 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -304,6 +304,8 @@ class LoggingPlugin(object): """Implements the internals of pytest_runtest_xxx() hook.""" with catching_logs(LogCaptureHandler(), formatter=self.formatter, level=self.log_level) as log_handler: + if self.log_cli_handler: + self.log_cli_handler.reset(item, when) if not hasattr(item, 'catch_log_handlers'): item.catch_log_handlers = {} item.catch_log_handlers[when] = log_handler @@ -322,8 +324,6 @@ 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 @@ -387,18 +387,28 @@ class _LiveLoggingStreamHandler(logging.StreamHandler): self.capture_manager = capture_manager self._first_record_emitted = False - def reset(self): - self._first_record_emitted = False + self._section_name_shown = False + self._when = None + self._run_tests = set() + + def reset(self, item, when): + self._when = when + self._section_name_shown = False + if item.name not in self._run_tests: + self._first_record_emitted = False + self._run_tests.add(item.name) def emit(self, record): if self.capture_manager is not None: self.capture_manager.suspend_global_capture() try: - if not self._first_record_emitted: + if not self._first_record_emitted or self._when == 'teardown': 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 + if not self._section_name_shown: + header = 'live log' if self._when == 'call' else 'live log ' + self._when + self.stream.section(header, sep='-', bold=True) + self._section_name_shown = True logging.StreamHandler.emit(self, record) finally: if self.capture_manager is not None: diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 4f605209c..492723ff6 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -196,17 +196,16 @@ def test_log_cli_default_level(testdir): assert result.ret == 0 -def test_log_cli_default_level_multiple_tests(testdir): +def test_log_cli_default_level_multiple_tests(testdir, request): """Ensure we reset the first newline added by the live logger between tests""" - # Default log file level + filename = request.node.name + '.py' testdir.makepyfile(''' - import pytest import logging - def test_log_1(request): + def test_log_1(): logging.warning("log message from test_log_1") - def test_log_2(request): + def test_log_2(): logging.warning("log message from test_log_2") ''') testdir.makeini(''' @@ -216,16 +215,63 @@ def test_log_cli_default_level_multiple_tests(testdir): result = testdir.runpytest() result.stdout.fnmatch_lines([ - 'test_log_cli_default_level_multiple_tests.py::test_log_1 ', + '{}::test_log_1 '.format(filename), '*WARNING*log message from test_log_1*', 'PASSED *50%*', - 'test_log_cli_default_level_multiple_tests.py::test_log_2 ', + '{}::test_log_2 '.format(filename), '*WARNING*log message from test_log_2*', 'PASSED *100%*', '=* 2 passed in *=', ]) +def test_log_cli_default_level_sections(testdir, request): + """Check that with live logging enable we are printing the correct headers during setup/call/teardown.""" + filename = request.node.name + '.py' + testdir.makepyfile(''' + import pytest + import logging + + @pytest.fixture + def fix(request): + logging.warning("log message from setup of {}".format(request.node.name)) + yield + logging.warning("log message from teardown of {}".format(request.node.name)) + + def test_log_1(fix): + logging.warning("log message from test_log_1") + + def test_log_2(fix): + logging.warning("log message from test_log_2") + ''') + testdir.makeini(''' + [pytest] + log_cli=true + ''') + + result = testdir.runpytest() + result.stdout.fnmatch_lines([ + '{}::test_log_1 '.format(filename), + '*-- live log setup --*', + '*WARNING*log message from setup of test_log_1*', + '*-- live log --*', + '*WARNING*log message from test_log_1*', + 'PASSED *50%*', + '*-- live log teardown --*', + '*WARNING*log message from teardown of test_log_1*', + + '{}::test_log_2 '.format(filename), + '*-- live log setup --*', + '*WARNING*log message from setup of test_log_2*', + '*-- live log --*', + '*WARNING*log message from test_log_2*', + 'PASSED *100%*', + '*-- live log teardown --*', + '*WARNING*log message from teardown of test_log_2*', + '=* 2 passed in *=', + ]) + + def test_log_cli_level(testdir): # Default log file level testdir.makepyfile(''' @@ -473,11 +519,19 @@ def test_live_logging_suspends_capture(has_capture_manager, request): assert CaptureManager.suspend_capture_item assert CaptureManager.resume_global_capture - capture_manager = MockCaptureManager() if has_capture_manager else None - out_file = six.StringIO() + class DummyTerminal(six.StringIO): + def section(self, *args, **kwargs): + pass + + out_file = DummyTerminal() + capture_manager = MockCaptureManager() if has_capture_manager else None handler = _LiveLoggingStreamHandler(out_file, capture_manager) + class DummyItem: + name = 'test_foo' + handler.reset(DummyItem(), 'call') + logger = logging.getLogger(__name__ + '.test_live_logging_suspends_capture') logger.addHandler(handler) request.addfinalizer(partial(logger.removeHandler, handler))