Show a header for each testing phase during live logging

As suggested during review

_pytest/logging.py

@@ -304,6 +304,8 @@ class LoggingPlugin(object):
         """Implements the internals of pytest_runtest_xxx() hook."""
         with catching_logs(LogCaptureHandler(),
                            formatter=self.formatter, level=self.log_level) as log_handler:
+            if self.log_cli_handler:
+                self.log_cli_handler.reset(item, when)
             if not hasattr(item, 'catch_log_handlers'):
                 item.catch_log_handlers = {}
             item.catch_log_handlers[when] = log_handler
@@ -322,8 +324,6 @@ class LoggingPlugin(object):
 
     @pytest.hookimpl(hookwrapper=True)
     def pytest_runtest_setup(self, item):
-        if self.log_cli_handler is not None:
-            self.log_cli_handler.reset()
         with self._runtest_for(item, 'setup'):
             yield
 
@@ -387,18 +387,28 @@ class _LiveLoggingStreamHandler(logging.StreamHandler):
         self.capture_manager = capture_manager
         self._first_record_emitted = False
 
-    def reset(self):
+        self._section_name_shown = False
-        self._first_record_emitted = False
+        self._when = None
+        self._run_tests = set()
+
+    def reset(self, item, when):
+        self._when = when
+        self._section_name_shown = False
+        if item.name not in self._run_tests:
+            self._first_record_emitted = False
+            self._run_tests.add(item.name)
 
     def emit(self, record):
         if self.capture_manager is not None:
             self.capture_manager.suspend_global_capture()
         try:
-            if not self._first_record_emitted:
+            if not self._first_record_emitted or self._when == 'teardown':
                 self.stream.write('\n')
-                # we might consider adding a header at this point using self.stream.section('live log', sep='-')
-                # or something similar when we improve live logging output
                 self._first_record_emitted = True
+            if not self._section_name_shown:
+                header = 'live log' if self._when == 'call' else 'live log ' + self._when
+                self.stream.section(header, sep='-', bold=True)
+                self._section_name_shown = True
             logging.StreamHandler.emit(self, record)
         finally:
             if self.capture_manager is not None:

testing/logging/test_reporting.py

@@ -196,17 +196,16 @@ def test_log_cli_default_level(testdir):
     assert result.ret == 0
 
 
-def test_log_cli_default_level_multiple_tests(testdir):
+def test_log_cli_default_level_multiple_tests(testdir, request):
     """Ensure we reset the first newline added by the live logger between tests"""
-    # Default log file level
+    filename = request.node.name + '.py'
     testdir.makepyfile('''
-        import pytest
         import logging
 
-        def test_log_1(request):
+        def test_log_1():
             logging.warning("log message from test_log_1")
 
-        def test_log_2(request):
+        def test_log_2():
             logging.warning("log message from test_log_2")
     ''')
     testdir.makeini('''
@@ -216,16 +215,63 @@ def test_log_cli_default_level_multiple_tests(testdir):
 
     result = testdir.runpytest()
     result.stdout.fnmatch_lines([
-        'test_log_cli_default_level_multiple_tests.py::test_log_1 ',
+        '{}::test_log_1 '.format(filename),
         '*WARNING*log message from test_log_1*',
         'PASSED *50%*',
-        'test_log_cli_default_level_multiple_tests.py::test_log_2 ',
+        '{}::test_log_2 '.format(filename),
         '*WARNING*log message from test_log_2*',
         'PASSED *100%*',
         '=* 2 passed in *=',
     ])
 
 
+def test_log_cli_default_level_sections(testdir, request):
+    """Check that with live logging enable we are printing the correct headers during setup/call/teardown."""
+    filename = request.node.name + '.py'
+    testdir.makepyfile('''
+        import pytest
+        import logging
+
+        @pytest.fixture
+        def fix(request):
+            logging.warning("log message from setup of {}".format(request.node.name))
+            yield
+            logging.warning("log message from teardown of {}".format(request.node.name))
+
+        def test_log_1(fix):
+            logging.warning("log message from test_log_1")
+
+        def test_log_2(fix):
+            logging.warning("log message from test_log_2")
+    ''')
+    testdir.makeini('''
+        [pytest]
+        log_cli=true
+    ''')
+
+    result = testdir.runpytest()
+    result.stdout.fnmatch_lines([
+        '{}::test_log_1 '.format(filename),
+        '*-- live log setup --*',
+        '*WARNING*log message from setup of test_log_1*',
+        '*-- live log --*',
+        '*WARNING*log message from test_log_1*',
+        'PASSED *50%*',
+        '*-- live log teardown --*',
+        '*WARNING*log message from teardown of test_log_1*',
+
+        '{}::test_log_2 '.format(filename),
+        '*-- live log setup --*',
+        '*WARNING*log message from setup of test_log_2*',
+        '*-- live log --*',
+        '*WARNING*log message from test_log_2*',
+        'PASSED *100%*',
+        '*-- live log teardown --*',
+        '*WARNING*log message from teardown of test_log_2*',
+        '=* 2 passed in *=',
+    ])
+
+
 def test_log_cli_level(testdir):
     # Default log file level
     testdir.makepyfile('''
@@ -473,11 +519,19 @@ def test_live_logging_suspends_capture(has_capture_manager, request):
     assert CaptureManager.suspend_capture_item
     assert CaptureManager.resume_global_capture
 
-    capture_manager = MockCaptureManager() if has_capture_manager else None
+    class DummyTerminal(six.StringIO):
-    out_file = six.StringIO()
 
+        def section(self, *args, **kwargs):
+            pass
+
+    out_file = DummyTerminal()
+    capture_manager = MockCaptureManager() if has_capture_manager else None
     handler = _LiveLoggingStreamHandler(out_file, capture_manager)
 
+    class DummyItem:
+        name = 'test_foo'
+    handler.reset(DummyItem(), 'call')
+
     logger = logging.getLogger(__name__ + '.test_live_logging_suspends_capture')
     logger.addHandler(handler)
     request.addfinalizer(partial(logger.removeHandler, handler))