From e967d4587a771106353232c410d5d2644d161ebe Mon Sep 17 00:00:00 2001 From: Thomas Hisch Date: Sat, 15 Sep 2018 01:41:07 +0200 Subject: [PATCH 1/4] Add support for logging in collection-phase The logging plugin does not output log messages generated during the collection-phase when live-logging is enabled. This fixes this. Fixes #3964 --- changelog/3964.rst | 2 ++ src/_pytest/logging.py | 41 ++++++++++++++++++++----------- testing/logging/test_reporting.py | 20 +++++++++++++++ 3 files changed, 48 insertions(+), 15 deletions(-) create mode 100644 changelog/3964.rst diff --git a/changelog/3964.rst b/changelog/3964.rst new file mode 100644 index 000000000..79ecd62a1 --- /dev/null +++ b/changelog/3964.rst @@ -0,0 +1,2 @@ +Log messages generated in the collection phase are now shown when +live-logging is enabled. diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index c9c65c4c1..f4a4801b8 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -2,7 +2,7 @@ from __future__ import absolute_import, division, print_function import logging -from contextlib import closing, contextmanager +from contextlib import contextmanager import re import six @@ -414,7 +414,6 @@ class LoggingPlugin(object): else: self.log_file_handler = None - # initialized during pytest_runtestloop self.log_cli_handler = None def _log_cli_enabled(self): @@ -425,6 +424,22 @@ class LoggingPlugin(object): "--log-cli-level" ) is not None or self._config.getini("log_cli") + @pytest.hookimpl(hookwrapper=True, tryfirst=True) + def pytest_collection(self): + # This has to be called before the first log message is logged, + # so we can access the terminal reporter plugin. + self._setup_cli_logging() + + with self.live_logs_context(): + if self.log_cli_handler: + self.log_cli_handler.set_when("collection") + + if self.log_file_handler is not None: + with catching_logs(self.log_file_handler, level=self.log_file_level): + yield # run all the tests + else: + yield + @contextmanager def _runtest_for(self, item, when): """Implements the internals of pytest_runtest_xxx() hook.""" @@ -484,22 +499,15 @@ class LoggingPlugin(object): @pytest.hookimpl(hookwrapper=True) def pytest_runtestloop(self, session): """Runs all collected test items.""" - self._setup_cli_logging() - with self.live_logs_context: + with self.live_logs_context(): if self.log_file_handler is not None: - with closing(self.log_file_handler): - with catching_logs( - self.log_file_handler, level=self.log_file_level - ): - yield # run all the tests + with catching_logs(self.log_file_handler, level=self.log_file_level): + yield # run all the tests else: yield # run all the tests def _setup_cli_logging(self): - """Sets up the handler and logger for the Live Logs feature, if enabled. - - This must be done right before starting the loop so we can access the terminal reporter plugin. - """ + """Sets up the handler and logger for the Live Logs feature, if enabled.""" terminal_reporter = self._config.pluginmanager.get_plugin("terminalreporter") if self._log_cli_enabled() and terminal_reporter is not None: capture_manager = self._config.pluginmanager.get_plugin("capturemanager") @@ -529,11 +537,14 @@ class LoggingPlugin(object): self._config, "log_cli_level", "log_level" ) self.log_cli_handler = log_cli_handler - self.live_logs_context = catching_logs( + self.live_logs_context = lambda: catching_logs( log_cli_handler, formatter=log_cli_formatter, level=log_cli_level ) else: - self.live_logs_context = dummy_context_manager() + self.live_logs_context = lambda: dummy_context_manager() + # Note that the lambda for the live_logs_context is needed because + # live_logs_context can otherwise not be entered multiple times due + # to limitations of contextlib.contextmanager class _LiveLoggingStreamHandler(logging.StreamHandler): diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 363982cf9..085df1ebc 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -908,3 +908,23 @@ def test_live_logging_suspends_capture(has_capture_manager, request): else: assert MockCaptureManager.calls == [] assert out_file.getvalue() == "\nsome message\n" + + +def test_collection_live_logging(testdir): + testdir.makepyfile( + """ + import logging + + logging.getLogger().info("Normal message") + """ + ) + + result = testdir.runpytest("--log-cli-level=INFO") + result.stdout.fnmatch_lines( + [ + "collecting*", + "*--- live log collection ---*", + "*Normal message*", + "collected 0 items", + ] + ) From d1a3aa7b2bb0919348ba6a38a2c5ea99c8c3b118 Mon Sep 17 00:00:00 2001 From: Thomas Hisch Date: Tue, 18 Sep 2018 21:31:20 +0200 Subject: [PATCH 2/4] Update 3964.rst --- changelog/3964.rst | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/changelog/3964.rst b/changelog/3964.rst index 79ecd62a1..37788c6f7 100644 --- a/changelog/3964.rst +++ b/changelog/3964.rst @@ -1,2 +1,2 @@ -Log messages generated in the collection phase are now shown when -live-logging is enabled. +Log messages generated in the collection phase are shown when +live-logging is enabled and/or when they are logged to a file. From 048342817b587ef0839331ca55a8f3f479a0d675 Mon Sep 17 00:00:00 2001 From: Thomas Hisch Date: Tue, 18 Sep 2018 21:47:42 +0200 Subject: [PATCH 3/4] Add testcase for logging to file --- testing/logging/test_reporting.py | 38 +++++++++++++++++++++++++++++++ 1 file changed, 38 insertions(+) diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 085df1ebc..498b4c5bd 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -928,3 +928,41 @@ def test_collection_live_logging(testdir): "collected 0 items", ] ) + + +def test_collection_logging_to_file(testdir): + log_file = testdir.tmpdir.join("pytest.log").strpath + + testdir.makeini( + """ + [pytest] + log_file={} + log_file_level = INFO + """.format( + log_file + ) + ) + + testdir.makepyfile( + """ + import logging + + logging.getLogger().info("Normal message") + + def test_simple(): + logging.getLogger().debug("debug message in test_simple") + logging.getLogger().info("info message in test_simple") + """ + ) + + result = testdir.runpytest() + + assert "--- live log collection ---" not in result.stdout.str() + + assert result.ret == 0 + assert os.path.isfile(log_file) + with open(log_file, encoding="utf-8") as rfh: + contents = rfh.read() + assert "Normal message" in contents + assert "debug message in test_simple" not in contents + assert "info message in test_simple" in contents From 18cc74b8d0cc788f0162775412a618477571ad35 Mon Sep 17 00:00:00 2001 From: Thomas Hisch Date: Wed, 19 Sep 2018 15:18:37 +0200 Subject: [PATCH 4/4] Remove useless comment --- src/_pytest/logging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index f4a4801b8..ba55ebb42 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -436,7 +436,7 @@ class LoggingPlugin(object): if self.log_file_handler is not None: with catching_logs(self.log_file_handler, level=self.log_file_level): - yield # run all the tests + yield else: yield