diff --git a/changelog/3964.rst b/changelog/3964.rst new file mode 100644 index 000000000..37788c6f7 --- /dev/null +++ b/changelog/3964.rst @@ -0,0 +1,2 @@ +Log messages generated in the collection phase are shown when +live-logging is enabled and/or when they are logged to a file. diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index c9c65c4c1..ba55ebb42 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 + 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..498b4c5bd 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -908,3 +908,61 @@ 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", + ] + ) + + +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