From e967d4587a771106353232c410d5d2644d161ebe Mon Sep 17 00:00:00 2001
From: Thomas Hisch <t.hisch@gmail.com>
Date: Sat, 15 Sep 2018 01:41:07 +0200
Subject: [PATCH] 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 00000000000..79ecd62a1d5
--- /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 c9c65c4c18d..f4a4801b880 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 @@ def __init__(self, config):
         else:
             self.log_file_handler = None
 
-        # initialized during pytest_runtestloop
         self.log_cli_handler = None
 
     def _log_cli_enabled(self):
@@ -425,6 +424,22 @@ def _log_cli_enabled(self):
             "--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 @@ def pytest_runtest_logfinish(self):
     @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 @@ def _setup_cli_logging(self):
                 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 363982cf915..085df1ebc08 100644
--- a/testing/logging/test_reporting.py
+++ b/testing/logging/test_reporting.py
@@ -908,3 +908,23 @@ def section(self, *args, **kwargs):
     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",
+        ]
+    )