diff --git a/_pytest/logging.py b/_pytest/logging.py index 095115cd979..269d7ea01cb 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -371,14 +371,22 @@ def _runtest_for(self, item, when): formatter=self.formatter, level=self.log_level) as log_handler: if self.log_cli_handler: self.log_cli_handler.set_when(when) + + if item is None: + yield # run the test + return + if not hasattr(item, 'catch_log_handlers'): item.catch_log_handlers = {} + item.catch_log_handlers[when] = log_handler item.catch_log_handler = log_handler + try: yield # run test finally: - del item.catch_log_handler + if item: + del item.catch_log_handler if when == 'teardown': del item.catch_log_handlers @@ -402,9 +410,17 @@ def pytest_runtest_teardown(self, item): with self._runtest_for(item, 'teardown'): yield + @pytest.hookimpl(hookwrapper=True) def pytest_runtest_logstart(self): if self.log_cli_handler: self.log_cli_handler.reset() + with self._runtest_for(None, 'start'): + yield + + @pytest.hookimpl(hookwrapper=True) + def pytest_runtest_logfinish(self): + with self._runtest_for(None, 'finish'): + yield @pytest.hookimpl(hookwrapper=True) def pytest_runtestloop(self, session): @@ -474,7 +490,7 @@ def emit(self, record): if self.capture_manager is not None: self.capture_manager.suspend_global_capture() try: - if not self._first_record_emitted or self._when == 'teardown': + if not self._first_record_emitted or self._when in ('teardown', 'finish'): self.stream.write('\n') self._first_record_emitted = True if not self._section_name_shown: diff --git a/changelog/3189.feature b/changelog/3189.feature new file mode 100644 index 00000000000..5fd81f99fc5 --- /dev/null +++ b/changelog/3189.feature @@ -0,0 +1 @@ +Allow the logging plugin, when live logs are enabled, to handle the hooks `pytest_runtest_logstart` and `pytest_runtest_logfinish`. diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index f5272aa0983..40e2cdbc530 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -161,6 +161,7 @@ def test_log_cli(): if enabled: result.stdout.fnmatch_lines([ 'test_log_cli_enabled_disabled.py::test_log_cli ', + '*-- live log call --*', 'test_log_cli_enabled_disabled.py* CRITICAL critical message logged by test', 'PASSED*', ]) @@ -226,8 +227,20 @@ def test_log_2(): 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.""" + """Check that with live logging enable we are printing the correct headers during + start/setup/call/teardown/finish.""" filename = request.node.name + '.py' + testdir.makeconftest(''' + import pytest + import logging + + def pytest_runtest_logstart(): + logging.warning('>>>>> START >>>>>') + + def pytest_runtest_logfinish(): + logging.warning('<<<<< END <<<<<<<') + ''') + testdir.makepyfile(''' import pytest import logging @@ -252,6 +265,8 @@ def test_log_2(fix): result = testdir.runpytest() result.stdout.fnmatch_lines([ '{}::test_log_1 '.format(filename), + '*-- live log start --*', + '*WARNING* >>>>> START >>>>>*', '*-- live log setup --*', '*WARNING*log message from setup of test_log_1*', '*-- live log call --*', @@ -259,8 +274,12 @@ def test_log_2(fix): 'PASSED *50%*', '*-- live log teardown --*', '*WARNING*log message from teardown of test_log_1*', + '*-- live log finish --*', + '*WARNING* <<<<< END <<<<<<<*', '{}::test_log_2 '.format(filename), + '*-- live log start --*', + '*WARNING* >>>>> START >>>>>*', '*-- live log setup --*', '*WARNING*log message from setup of test_log_2*', '*-- live log call --*', @@ -268,6 +287,8 @@ def test_log_2(fix): 'PASSED *100%*', '*-- live log teardown --*', '*WARNING*log message from teardown of test_log_2*', + '*-- live log finish --*', + '*WARNING* <<<<< END <<<<<<<*', '=* 2 passed in *=', ])