Use yielding pytest_runtest_call() hook wrapper

Take advantage of `@pytest.mark.hookwrapper` facility and use more
idiomatic pytest_runtest_call(item) hook for performing capturing (in
fact, the same is used by the core 'pytest.capture' module).

Instead of messing around `report.longrepr` internals and since we
don't have a `report` instance at the moment of executing
pytest_runtest_call() anyway (it used to be created within a more late
pytest_runtest_makereport() hook), use a higher-level
item.add_report_section() method to attach log output to a report.

However, there is a drawback that now reports show sections named like
'Captured stdlog ...' ('std' is hardcoded). This is an issue of the
pytest itself addressed in pytest-dev/pytest#1052. That PR also
contains a discussion on deprecating Item.add_report_section(),
however the same approach is still used by 'pytest.capture', so it
should be fine to use it here as well.

This change also removes the use of the deprecated '__multicall__', so
that fixes #3.

README.rst

@@ -30,11 +30,11 @@ Running without options::
 
 Shows failed tests like so::
 
-    -------------------------- Captured log ---------------------------
+    ----------------------- Captured stdlog call ----------------------
     test_pytest_catchlog.py    26 INFO     text going to logger
-    ------------------------- Captured stdout -------------------------
+    ----------------------- Captured stdout call ----------------------
     text going to stdout
-    ------------------------- Captured stderr -------------------------
+    ----------------------- Captured stderr call ----------------------
     text going to stderr
     ==================== 2 failed in 0.02 seconds =====================
 
@@ -50,11 +50,11 @@ Running pytest specifying formatting options::
 
 Shows failed tests like so::
 
-    -------------------------- Captured log ---------------------------
+    ----------------------- Captured stdlog call ----------------------
     2010-04-10 14:48:44 INFO text going to logger
-    ------------------------- Captured stdout -------------------------
+    ----------------------- Captured stdout call ----------------------
     text going to stdout
-    ------------------------- Captured stderr -------------------------
+    ----------------------- Captured stderr call ----------------------
     text going to stderr
     ==================== 2 failed in 0.02 seconds =====================
 
@@ -77,39 +77,39 @@ completely with::
 
 Shows failed tests in the normal manner as no logs were captured::
 
-    ------------------------- Captured stdout -------------------------
+    ----------------------- Captured stdout call ----------------------
     text going to stdout
-    ------------------------- Captured stderr -------------------------
+    ----------------------- Captured stderr call ----------------------
     text going to stderr
     ==================== 2 failed in 0.02 seconds =====================
 
 Inside tests it is possible to change the log level for the captured
 log messages.  This is supported by the ``caplog`` funcarg::
 
     def test_foo(caplog):
-        caplog.setLevel(logging.INFO)
+        caplog.set_level(logging.INFO)
         pass
 
 By default the level is set on the handler used to catch the log
 messages, however as a convenience it is also possible to set the log
 level of any logger::
 
     def test_foo(caplog):
-        caplog.setLevel(logging.CRITICAL, logger='root.baz')
+        caplog.set_level(logging.CRITICAL, logger='root.baz')
         pass
 
 It is also possible to use a context manager to temporarily change the
 log level::
 
     def test_bar(caplog):
-        with caplog.atLevel(logging.INFO):
+        with caplog.at_level(logging.INFO):
             pass
 
 Again, by default the level of the handler is affected but the level
 of any logger can be changed instead with::
 
     def test_bar(caplog):
-        with caplog.atLevel(logging.CRITICAL, logger='root.baz'):
+        with caplog.at_level(logging.CRITICAL, logger='root.baz'):
             pass
 
 Lastly all the logs sent to the logger during the test run are made

pytest_catchlog.py

@@ -2,6 +2,7 @@
 from __future__ import absolute_import, division, print_function
 
 import logging
+from contextlib import closing, contextmanager
 
 import pytest
 import py
@@ -62,55 +63,40 @@ def __init__(self, config):
                 get_option_ini(config, 'log_format'),
                 get_option_ini(config, 'log_date_format'))
 
-    def pytest_runtest_setup(self, item):
-        """Start capturing log messages for this test.
-
-        Creating a specific handler for each test ensures that we
-        avoid multi threading issues.
-
-        Attaching the handler and setting the level at the beginning
-        of each test ensures that we are setup to capture log
-        messages.
-        """
-
+    @pytest.mark.hookwrapper
+    def pytest_runtest_call(self, item):
         # Create a handler for this test.
-        item.catch_log_handler = CatchLogHandler()
-        item.catch_log_handler.setFormatter(self.formatter)
+        # Creating a specific handler for each test ensures that we
+        # avoid multi threading issues.
+        with closing(CatchLogHandler()) as log_handler:
+            log_handler.setFormatter(self.formatter)
 
-        # Attach the handler to the root logger and ensure that the
-        # root logger is set to log all levels.
-        root_logger = logging.getLogger()
-        root_logger.addHandler(item.catch_log_handler)
-        root_logger.setLevel(logging.NOTSET)
+            # Attach the handler to the root logger and ensure that the
+            # root logger is set to log all levels.
+            root_logger = logging.getLogger()
+            root_logger.addHandler(log_handler)
 
-    def pytest_runtest_makereport(self, __multicall__, item, call):
-        """Add captured log messages for this report."""
+            root_level = root_logger.level
+            root_logger.setLevel(logging.NOTSET)
 
-        report = __multicall__.execute()
+            item.catch_log_handler = log_handler
+            try:
 
-        # This fn called after setup, call and teardown.  Only
-        # interested in just after test call has finished.
-        if call.when == 'call':
+                yield  # run test
 
-            # Detach the handler from the root logger to ensure no
-            # further access to the handler.
-            root_logger = logging.getLogger()
-            root_logger.removeHandler(item.catch_log_handler)
+            finally:
+                del item.catch_log_handler
 
-            # For failed tests that have captured log messages add a
-            # captured log section to the report if desired.
-            if not report.passed and self.print_logs:
-                long_repr = getattr(report, 'longrepr', None)
-                if hasattr(long_repr, 'addsection'):
-                    log = item.catch_log_handler.stream.getvalue().strip()
-                    if log:
-                        long_repr.addsection('Captured log', log)
+                root_logger.level = root_level
 
-            # Release the handler resources.
-            item.catch_log_handler.close()
-            del item.catch_log_handler
+                # Detach the handler from the root logger to ensure no
+                # further access to the handler.
+                root_logger.removeHandler(log_handler)
 
-        return report
+            if self.print_logs:
+                # Add a captured log section to the report.
+                log = log_handler.stream.getvalue().strip()
+                item.add_report_section('call', 'log', log)
 
 
 class CatchLogHandler(logging.StreamHandler):
@@ -139,10 +125,13 @@ def emit(self, record):
 class CatchLogFuncArg(object):
     """Provides access and control of log capturing."""
 
-    def __init__(self, handler):
-        """Creates a new funcarg."""
+    @property
+    def handler(self):
+        return self._item.catch_log_handler
 
-        self.handler = handler
+    def __init__(self, item):
+        """Creates a new funcarg."""
+        self._item = item
 
     def text(self):
         """Returns the log text."""
@@ -218,6 +207,6 @@ def caplog(request):
     * caplog.records()       -> list of logging.LogRecord instances
     * caplog.record_tuples() -> list of (logger_name, level, message) tuples
     """
-    return CatchLogFuncArg(request._pyfuncitem.catch_log_handler)
+    return CatchLogFuncArg(request.node)
 
 capturelog = caplog

test_pytest_catchlog.py

@@ -22,7 +22,7 @@ def test_foo():
     result.stdout.fnmatch_lines(['*- Captured stderr call -*',
                                  'text going to stderr'])
     py.test.raises(Exception, result.stdout.fnmatch_lines,
-                   ['*- Captured log -*'])
+                   ['*- Captured *log call -*'])
 
 
 def test_messages_logged(testdir):
@@ -40,7 +40,7 @@ def test_foo():
         ''')
     result = testdir.runpytest()
     assert result.ret == 1
-    result.stdout.fnmatch_lines(['*- Captured log -*',
+    result.stdout.fnmatch_lines(['*- Captured *log call -*',
                                  '*text going to logger*'])
     result.stdout.fnmatch_lines(['*- Captured stdout call -*',
                                  'text going to stdout'])
@@ -70,13 +70,13 @@ def test_foo(caplog):
         ''')
     result = testdir.runpytest()
     assert result.ret == 1
-    result.stdout.fnmatch_lines(['*- Captured log -*',
+    result.stdout.fnmatch_lines(['*- Captured *log call -*',
                                  '*handler INFO level*',
                                  '*logger CRITICAL level*'])
     py.test.raises(Exception, result.stdout.fnmatch_lines,
-                   ['*- Captured log -*', '*handler DEBUG level*'])
+                   ['*- Captured *log call -*', '*handler DEBUG level*'])
     py.test.raises(Exception, result.stdout.fnmatch_lines,
-                   ['*- Captured log -*', '*logger WARNING level*'])
+                   ['*- Captured *log call -*', '*logger WARNING level*'])
 
 
 @py.test.mark.skipif('sys.version_info < (2,5)')
@@ -103,13 +103,13 @@ def test_foo(caplog):
         ''')
     result = testdir.runpytest()
     assert result.ret == 1
-    result.stdout.fnmatch_lines(['*- Captured log -*',
+    result.stdout.fnmatch_lines(['*- Captured *log call -*',
                                  '*handler INFO level*',
                                  '*logger CRITICAL level*'])
     py.test.raises(Exception, result.stdout.fnmatch_lines,
-                   ['*- Captured log -*', '*handler DEBUG level*'])
+                   ['*- Captured *log call -*', '*handler DEBUG level*'])
     py.test.raises(Exception, result.stdout.fnmatch_lines,
-                   ['*- Captured log -*', '*logger WARNING level*'])
+                   ['*- Captured *log call -*', '*logger WARNING level*'])
 
 
 def test_log_access(testdir):
@@ -173,4 +173,4 @@ def test_foo(caplog):
     result.stdout.fnmatch_lines(['*- Captured stderr call -*',
                                  'text going to stderr'])
     py.test.raises(Exception, result.stdout.fnmatch_lines,
-                   ['*- Captured log -*'])
+                   ['*- Captured *log call -*'])