Fixes to live logs

_pytest/logging.py

@@ -337,6 +337,11 @@ def __init__(self, config):
         """
         self._config = config
 
+        # enable live logs if log_cli_level is explicitly set
+        log_cli_level = get_actual_log_level(self._config, 'log_cli_level', 'log_level')
+        if log_cli_level is not None:
+            # enable live logs if log_cli_level is explicitly set
+            config._inicache['log_cli'] = config._parser._inidict['log_cli'] = True
         # enable verbose output automatically if live logging is enabled
         if self._config.getini('log_cli') and not config.getoption('verbose'):
             # sanity check: terminal reporter should not have been loaded at this point
@@ -371,18 +376,20 @@ def _runtest_for(self, item, when):
                            formatter=self.formatter, level=self.log_level) as log_handler:
             if self.log_cli_handler:
                 self.log_cli_handler.set_when(when)
-            if not hasattr(item, 'catch_log_handlers'):
+            if item and not hasattr(item, 'catch_log_handlers'):
                 item.catch_log_handlers = {}
-            item.catch_log_handlers[when] = log_handler
-            item.catch_log_handler = log_handler
+            if item:
+                item.catch_log_handlers[when] = log_handler
+                item.catch_log_handler = log_handler
             try:
                 yield  # run test
             finally:
-                del item.catch_log_handler
+                if item:
+                    del item.catch_log_handler
                 if when == 'teardown':
                     del item.catch_log_handlers
 
-            if self.print_logs:
+            if self.print_logs and item:
                 # Add a captured log section to the report.
                 log = log_handler.stream.getvalue().strip()
                 item.add_report_section(when, 'log', log)
@@ -402,9 +409,17 @@ def pytest_runtest_teardown(self, item):
         with self._runtest_for(item, 'teardown'):
             yield
 
+    @pytest.hookimpl(hookwrapper=True)
     def pytest_runtest_logstart(self):
         if self.log_cli_handler:
             self.log_cli_handler.reset()
+        with self._runtest_for(None, 'start'):
+            yield
+
+    @pytest.hookimpl(hookwrapper=True)
+    def pytest_runtest_logfinish(self):
+        with self._runtest_for(None, 'finish'):
+            yield
 
     @pytest.hookimpl(hookwrapper=True)
     def pytest_runtestloop(self, session):
@@ -474,10 +489,10 @@ def emit(self, record):
         if self.capture_manager is not None:
             self.capture_manager.suspend_global_capture()
         try:
-            if not self._first_record_emitted or self._when == 'teardown':
+            if not self._first_record_emitted or self._when in ('teardown', 'finish'):
                 self.stream.write('\n')
                 self._first_record_emitted = True
-            if not self._section_name_shown:
+            if not self._section_name_shown and self._when:
                 self.stream.section('live log ' + self._when, sep='-', bold=True)
                 self._section_name_shown = True
             logging.StreamHandler.emit(self, record)

changelog/3175.bugfix

@@ -0,0 +1 @@
+Don't traceback when logging on unknown(unhandled) sections.

changelog/3175.feature

@@ -0,0 +1 @@
+Enable live logs is log_cli_level is passed/set explicitly

changelog/3175.trivial

@@ -0,0 +1 @@
+Allow the logging plugin, when live logs are enabled, to handle the hooks `pytest_runtest_logstart` and `pytest_runtest_logfinish`.

testing/logging/test_reporting.py

@@ -226,8 +226,20 @@ def test_log_2():
 
 
 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."""
+    """Check that with live logging enable we are printing the correct headers during
+    start/setup/call/teardown/finish."""
     filename = request.node.name + '.py'
+    testdir.makeconftest('''
+        import pytest
+        import logging
+
+        def pytest_runtest_logstart():
+            logging.warning('>>>>> START >>>>>')
+
+        def pytest_runtest_logfinish():
+            logging.warning('<<<<< END <<<<<<<')
+    ''')
+
     testdir.makepyfile('''
         import pytest
         import logging
@@ -252,26 +264,90 @@ def test_log_2(fix):
     result = testdir.runpytest()
     result.stdout.fnmatch_lines([
         '{}::test_log_1 '.format(filename),
+        '*-- live log start --*',
+        '*WARNING* >>>>> START >>>>>*',
         '*-- live log setup --*',
         '*WARNING*log message from setup of test_log_1*',
         '*-- live log call --*',
         '*WARNING*log message from test_log_1*',
         'PASSED *50%*',
         '*-- live log teardown --*',
         '*WARNING*log message from teardown of test_log_1*',
+        '*-- live log finish --*',
+        '*WARNING* <<<<< END <<<<<<<*',
 
         '{}::test_log_2 '.format(filename),
+        '*-- live log start --*',
+        '*WARNING* >>>>> START >>>>>*',
         '*-- live log setup --*',
         '*WARNING*log message from setup of test_log_2*',
         '*-- live log call --*',
         '*WARNING*log message from test_log_2*',
         'PASSED *100%*',
         '*-- live log teardown --*',
         '*WARNING*log message from teardown of test_log_2*',
+        '*-- live log finish --*',
+        '*WARNING* <<<<< END <<<<<<<*',
         '=* 2 passed in *=',
     ])
 
 
+def test_live_logs_unknown_sections(testdir, request):
+    """Check that with live logging enable we are printing the correct headers during
+    start/setup/call/teardown/finish."""
+    filename = request.node.name + '.py'
+    testdir.makeconftest('''
+        import pytest
+        import logging
+
+        def pytest_runtest_protocol(item, nextitem):
+            logging.warning('Unknown Section!')
+
+        def pytest_runtest_logstart():
+            logging.warning('>>>>> START >>>>>')
+
+        def pytest_runtest_logfinish():
+            logging.warning('<<<<< END <<<<<<<')
+    ''')
+
+    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")
+
+    ''')
+    testdir.makeini('''
+        [pytest]
+        log_cli=true
+    ''')
+
+    result = testdir.runpytest()
+    result.stdout.fnmatch_lines([
+        '*WARNING*Unknown Section*',
+        '{}::test_log_1 '.format(filename),
+        '*-- live log start --*',
+        '*WARNING* >>>>> START >>>>>*',
+        '*-- live log setup --*',
+        '*WARNING*log message from setup of test_log_1*',
+        '*-- live log call --*',
+        '*WARNING*log message from test_log_1*',
+        'PASSED *100%*',
+        '*-- live log teardown --*',
+        '*WARNING*log message from teardown of test_log_1*',
+        '*-- live log finish --*',
+        '*WARNING* <<<<< END <<<<<<<*',
+        '=* 1 passed in *=',
+    ])
+
+
 def test_log_cli_level(testdir):
     # Default log file level
     testdir.makepyfile('''