Log in subtests similar to stdout (#91)

Fix #87 

---------

Co-authored-by: Bruno Oliveira <nicoddemus@gmail.com>

Author: rhoban13

CHANGELOG.rst

@@ -4,11 +4,13 @@ CHANGELOG
 UNRELEASED
 ----------
 
+* Logging is displayed for failing subtests (`#92`_)
 * Passing subtests no longer turn the pytest output to yellow (as if warnings have been issued) (`#86`_). Thanks to `Andrew-Brock`_ for providing the solution.
 * Now the ``msg`` contents of a subtest is displayed when running pytest with ``-v`` (`#6`_).
 
 .. _#6: https://github.com/pytest-dev/pytest-subtests/issues/6
 .. _#86: https://github.com/pytest-dev/pytest-subtests/issues/86
+.. _#92: https://github.com/pytest-dev/pytest-subtests/issues/87
 
 .. _`Andrew-Brock`: https://github.com/Andrew-Brock
 

src/pytest_subtests.py

@@ -8,6 +8,7 @@
 from _pytest.capture import CaptureFixture
 from _pytest.capture import FDCapture
 from _pytest.capture import SysCapture
+from _pytest.logging import LogCaptureHandler, catching_logs
 from _pytest.outcomes import OutcomeException
 from _pytest.reports import TestReport
 from _pytest.runner import CallInfo
@@ -176,14 +177,27 @@ def _capturing_output(self):
                 fixture.close()
                 captured.out = out
                 captured.err = err
+    
+    @contextmanager
+    def _capturing_logs(self):
+        logging_plugin = self.request.config.pluginmanager.getplugin("logging-plugin")
+        if logging_plugin is None:
+            yield NullCapturedLogs()
+        else:
+            handler = LogCaptureHandler()
+            handler.setFormatter(logging_plugin.formatter)
+            
+            captured_logs = CapturedLogs(handler)
+            with catching_logs(handler):
+                yield captured_logs
 
     @contextmanager
     def test(self, msg=None, **kwargs):
         start = time.time()
         precise_start = time.perf_counter()
         exc_info = None
 
-        with self._capturing_output() as captured:
+        with self._capturing_output() as captured_output, self._capturing_logs() as captured_logs:
             try:
                 yield
             except (Exception, OutcomeException):
@@ -200,8 +214,9 @@ def test(self, msg=None, **kwargs):
         sub_report = SubTestReport._from_test_report(report)
         sub_report.context = SubTestContext(msg, kwargs.copy())
 
-        captured.update_report(sub_report)
-
+        captured_output.update_report(sub_report)
+        captured_logs.update_report(sub_report)
+    
         with self.suspend_capture_ctx():
             self.ihook.pytest_runtest_logreport(report=sub_report)
 
@@ -248,6 +263,19 @@ def update_report(self, report):
             report.sections.append(("Captured stderr call", self.err))
 
 
+class CapturedLogs:
+    def __init__(self, handler):
+        self._handler = handler
+    
+    def update_report(self, report):
+        report.sections.append(("Captured log call", self._handler.stream.getvalue()))
+
+
+class NullCapturedLogs:   
+    def update_report(self, report):
+        pass
+        
+
 def pytest_report_to_serializable(report):
     if isinstance(report, SubTestReport):
         return report._to_json()

tests/test_subtests.py

@@ -365,6 +365,91 @@ def test(subtests, {fixture}):
         )
 
 
+class TestLogging:
+    def create_file(self, testdir):
+        testdir.makepyfile(
+            """
+            import logging
+
+            def test_foo(subtests):
+                logging.info("before")
+
+                with subtests.test("sub1"):
+                    print("sub1 stdout")
+                    logging.info("sub1 logging")
+
+                with subtests.test("sub2"):
+                    print("sub2 stdout")
+                    logging.info("sub2 logging")
+                    assert False
+            """
+        )
+
+    def test_capturing(self, testdir):
+        self.create_file(testdir)
+        result = testdir.runpytest("--log-level=INFO")
+        result.stdout.fnmatch_lines(
+            [
+                "*___ test_foo [[]sub2[]] __*",
+                "*-- Captured stdout call --*",
+                "sub2 stdout",
+                "*-- Captured log call ---*",
+                "INFO     root:test_capturing.py:12 sub2 logging",
+                "*== short test summary info ==*"
+            ]
+        )
+
+    def test_caplog(self, testdir):
+        testdir.makepyfile(
+            """
+            import logging
+
+            def test(subtests, caplog):
+                caplog.set_level(logging.INFO)
+                logging.info("start test")
+
+                with subtests.test("sub1"):
+                    logging.info("inside %s", "subtest1")
+                
+                assert len(caplog.records) == 2
+                assert caplog.records[0].getMessage() == "start test"
+                assert caplog.records[1].getMessage() == "inside subtest1"
+            """
+        )
+        result = testdir.runpytest()
+        result.stdout.fnmatch_lines(
+            [
+                "*1 passed*",
+            ]
+        )
+
+    def test_no_logging(self, testdir):
+        testdir.makepyfile(
+            """
+            import logging
+
+            def test(subtests):
+                logging.info("start log line")
+
+                with subtests.test("sub passing"):
+                    logging.info("inside %s", "passing log line")
+                
+                with subtests.test("sub failing"):
+                    logging.info("inside %s", "failing log line")
+                    assert False
+
+                logging.info("end log line")
+            """
+        )
+        result = testdir.runpytest("-p no:logging")
+        result.stdout.fnmatch_lines(
+            [
+                "*1 passed*",
+            ]
+        )
+        result.stdout.no_fnmatch_line("*root:test_no_logging.py*log line*")
+
+
 class TestDebugging:
     """Check --pdb support for subtests fixture and TestCase.subTest."""