Merge pull request #3986 from thisch/fb3964

Add support for logging in collection-phase

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.

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
-                    ):
+                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):

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