AttributeError: catch_log_handler

[ionelmc]

So I have this mind boggling issue for a test like this:

test_bug.py:

import logging

import pytest


def test_skip():
    logging.info('blabla')
    pytest.skip('muahaha')

conftest.py:

from __future__ import print_function
import pytest


@pytest.mark.hookwrapper
def pytest_runtest_call(item):
    if hasattr(item, 'funcargs'):
        for _ in item.funcargs.items():
            pass # i'd pull some data from fixtures here

    result = yield
    try:
        result.get_result()
    except Exception:
        capman = item.config.pluginmanager.getplugin("capturemanager")
        if capman:
            capman.resume_global_capture()

        print("""#####
##### DEBUG STUFF WHEN TEST FAILS
#####
""" % filename, file=sys.stderr)
        if capman:
            capman.suspend_capture_item(item, "setup")

tox.ini:

[tox]
envlist = py27
skipsdist = true

[testenv]
commands =
    pytest test_bug.py {posargs:}
deps =
    pytest==3.3.2
    pytest-splinter==1.8.5
    pytest-xvfb==1.0.0
    pytest-xdist==1.21.0

[pytest]
norecursedirs =
    .git
    .tox
    .ve
python_files =
    test_*.py
    *_test.py
    tests.py
addopts =
    -rxEfsw
    --strict
    --doctest-modules
    --doctest-glob=\*.rst
    --tb=native
    --max-slave-restart=5
xvfb_xauth = false

Sometimes it pass and I get this:

platform linux2 -- Python 2.7.12, pytest-3.3.2, py-1.5.2, pluggy-0.6.0 -- /home/ionel/sandbox/.tox/py27/bin/python2.7
cachedir: .cache
rootdir: /home/ionel/sandbox, inifile: tox.ini
plugins: xvfb-1.0.0, xdist-1.21.0, splinter-1.8.5, forked-0.2
collected 1 item

test_bug.py::test_skip SKIPPED                                                                                                                                       [100%]
========================================================================= short test summary info ==========================================================================
SKIP [1] /home/ionel/sandbox/test_bug.py:9: muahaha

======================================================================== 1 skipped in 0.02 seconds =========================================================================
Exception AttributeError: AttributeError('catch_log_handler',) in <generator object pytest_runtest_call at 0x7f7efb1130a0> ignored
_________________________________________________________________________________ summary __________________________________________________________________________________
  py27: commands succeeded
  congratulations :)

And sometimes it fails:

platform linux2 -- Python 2.7.12, pytest-3.3.2, py-1.5.2, pluggy-0.6.0 -- /home/ionel/sandbox/.tox/py27/bin/python2.7
cachedir: .cache
rootdir: /home/ionel/sandbox, inifile: tox.ini
plugins: xvfb-1.0.0, xdist-1.21.0, splinter-1.8.5, forked-0.2
collected 1 item

test_bug.py::test_skip SKIPPED                                                                                                                                       [100%]
test_bug.py::test_skip ERROR                                                                                                                                         [200%]
========================================================================= short test summary info ==========================================================================
ERROR test_bug.py::test_skip
SKIP [1] /home/ionel/sandbox/test_bug.py:9: muahaha

================================================================================== ERRORS ==================================================================================
______________________________________________________________________ ERROR at teardown of test_skip ______________________________________________________________________
Traceback (most recent call last):
  File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
    self.gen.next()
  File "/home/ionel/sandbox/.tox/py27/local/lib/python2.7/site-packages/_pytest/logging.py", line 294, in _runtest_for
    del item.catch_log_handler
AttributeError: catch_log_handler
==================================================================== 1 skipped, 1 error in 0.02 seconds ====================================================================
ERROR: InvocationError: '/home/ionel/sandbox/.tox/py27/bin/pytest test_bug.py -vv'
_________________________________________________________________________________ summary __________________________________________________________________________________
ERROR:   py27: commands failed

Removing my weird helper from conftest makes the problem go away but I need it.

Also, if I remove some of those pytest plugins it doesn't error so often.

Any clue what's going on here?

[pytestbot]

GitMate.io thinks the contributor most likely able to help you is @nicoddemus.

[ionelmc]

So I'm running this: while tox -- -vv; do sleep 1; done - after a dozen runs or so I get the failure.

If I remove plugins it doesn't seem to happen (I only get the ignored exception). Seems like generators aren't properly cleaned up?

[RonnyPfannschmidt]

based on

pytest/_pytest/logging.py

Lines 290 to 294 in a8d3d32

	item.catch_log_handler = log_handler
	try:
	yield # run test
	finally:
	del item.catch_log_handler

this should never happen - i'm curious what triggers it, as it seems something nests incorrectly

[RonnyPfannschmidt]

also we need a correct api for this storage stuff, its by now a freaking mess

[ionelmc]

I suspect there's absolutely no nesting and the finally clause is triggered by the garbage collector (iow: generators aren't properly cleaned up). I don't have proof of course :)

[RonnyPfannschmidt]

@ionelmc can we please get a traceback with --fulltrace - it seems something is missing

[ionelmc]

Here it is:

=========================================================================== test session starts ============================================================================
platform linux2 -- Python 2.7.12, pytest-3.3.2, py-1.5.2, pluggy-0.6.0 -- /home/ionel/sandbox/.tox/py27/bin/python2.7
cachedir: .cache
rootdir: /home/ionel/sandbox, inifile: tox.ini
plugins: xvfb-1.0.0, xdist-1.21.0, splinter-1.8.5, forked-0.2
collected 1 item

test_bug.py::test_skip SKIPPED                                                                                                                                       [100%]
========================================================================= short test summary info ==========================================================================
SKIP [1] /home/ionel/sandbox/test_bug.py:9: muahaha

======================================================================== 1 skipped in 0.02 seconds =========================================================================
Exception AttributeError: AttributeError('catch_log_handler',) in <generator object pytest_runtest_call at 0x7f61f5f9bfa0> ignored
_________________________________________________________________________________ summary __________________________________________________________________________________
  py27: commands succeeded
  congratulations :)
py27 installed: apipkg==1.4,attrs==17.4.0,EasyProcess==0.2.3,execnet==1.5.0,funcsigs==1.0.2,pluggy==0.6.0,py==1.5.2,pytest==3.3.2,pytest-forked==0.2,pytest-splinter==1.8.5,pytest-xdist==1.21.0,pytest-xvfb==1.0.0,PyVirtualDisplay==0.2.1,selenium==3.8.1,six==1.11.0,splinter==0.7.7
py27 runtests: PYTHONHASHSEED='499239232'
py27 runtests: commands[0] | pytest test_bug.py -vv
=========================================================================== test session starts ============================================================================
platform linux2 -- Python 2.7.12, pytest-3.3.2, py-1.5.2, pluggy-0.6.0 -- /home/ionel/sandbox/.tox/py27/bin/python2.7
cachedir: .cache
rootdir: /home/ionel/sandbox, inifile: tox.ini
plugins: xvfb-1.0.0, xdist-1.21.0, splinter-1.8.5, forked-0.2
collected 1 item

test_bug.py::test_skip SKIPPED                                                                                                                                       [100%]
test_bug.py::test_skip ERROR                                                                                                                                         [200%]
========================================================================= short test summary info ==========================================================================
ERROR test_bug.py::test_skip
SKIP [1] /home/ionel/sandbox/test_bug.py:9: muahaha

================================================================================== ERRORS ==================================================================================
______________________________________________________________________ ERROR at teardown of test_skip ______________________________________________________________________

self = <CallInfo when='teardown' exception: catch_log_handler>, func = <function <lambda> at 0x7f2dc8ad8b18>, when = 'teardown'

    def __init__(self, func, when):
        #: context of invocation: one of "setup", "call",
        #: "teardown", "memocollect"
        self.when = when
        self.start = time()
        try:
>           self.result = func()

.tox/py27/local/lib/python2.7/site-packages/_pytest/runner.py:189:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

>   return CallInfo(lambda: ihook(item=item, **kwds), when=when)

.tox/py27/local/lib/python2.7/site-packages/_pytest/runner.py:175:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <_HookCaller 'pytest_runtest_teardown'>, args = (), kwargs = {'item': <Function 'test_skip'>, 'nextitem': None}, notincall = set([])

    def __call__(self, *args, **kwargs):
        if args:
            raise TypeError("hook calling supports only keyword arguments")
        assert not self.is_historic()
        if self.argnames:
            notincall = set(self.argnames) - set(['__multicall__']) - set(
                kwargs.keys())
            if notincall:
                warnings.warn(
                    "Argument(s) {} which are declared in the hookspec "
                    "can not be found in this hook call"
                    .format(tuple(notincall)),
                    stacklevel=2,
                )
>       return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)

.tox/py27/local/lib/python2.7/site-packages/pluggy/__init__.py:617:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <_pytest.config.PytestPluginManager object at 0x7f2dcc4c0450>, hook = <_HookCaller 'pytest_runtest_teardown'>
methods = [<pluggy.HookImpl object at 0x7f2dc99df650>, <pluggy.HookImpl object at 0x7f2dc99a5310>, <pluggy.HookImpl object at 0x7f2dc8d330d0>, <pluggy.HookImpl object at 0x7f2dc8d454d0>]
kwargs = {'item': <Function 'test_skip'>, 'nextitem': None}

    def _hookexec(self, hook, methods, kwargs):
        # called from all hookcaller instances.
        # enable_tracing will set its own wrapping function at self._inner_hookexec
>       return self._inner_hookexec(hook, methods, kwargs)

.tox/py27/local/lib/python2.7/site-packages/pluggy/__init__.py:222:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

hook = <_HookCaller 'pytest_runtest_teardown'>
methods = [<pluggy.HookImpl object at 0x7f2dc99df650>, <pluggy.HookImpl object at 0x7f2dc99a5310>, <pluggy.HookImpl object at 0x7f2dc8d330d0>, <pluggy.HookImpl object at 0x7f2dc8d454d0>]
kwargs = {'item': <Function 'test_skip'>, 'nextitem': None}

    self._inner_hookexec = lambda hook, methods, kwargs: \
        hook.multicall(
            methods, kwargs,
>           firstresult=hook.spec_opts.get('firstresult'),
        )

.tox/py27/local/lib/python2.7/site-packages/pluggy/__init__.py:216:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <_pytest.logging.LoggingPlugin object at 0x7f2dc8d45250>, item = <Function 'test_skip'>

    @pytest.hookimpl(hookwrapper=True)
    def pytest_runtest_teardown(self, item):
        with self._runtest_for(item, 'teardown'):
>           yield

.tox/py27/local/lib/python2.7/site-packages/_pytest/logging.py:314:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <contextlib.GeneratorContextManager object at 0x7f2dc8a7d190>, type = None, value = None, traceback = None

    def __exit__(self, type, value, traceback):
        if type is None:
            try:
>               self.gen.next()

/usr/lib/python2.7/contextlib.py:24:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <_pytest.logging.LoggingPlugin object at 0x7f2dc8d45250>, item = <Function 'test_skip'>, when = 'teardown'

    @contextmanager
    def _runtest_for(self, item, when):
        """Implements the internals of pytest_runtest_xxx() hook."""
        with catching_logs(LogCaptureHandler(),
                           formatter=self.formatter) as log_handler:
            item.catch_log_handler = log_handler
            try:
                yield  # run test
            finally:
>               del item.catch_log_handler
E               AttributeError: catch_log_handler

.tox/py27/local/lib/python2.7/site-packages/_pytest/logging.py:294: AttributeError
==================================================================== 1 skipped, 1 error in 0.10 seconds ====================================================================
ERROR: InvocationError: '/home/ionel/sandbox/.tox/py27/bin/pytest test_bug.py -vv'

[RonnyPfannschmidt]

thanks, now that one is a real puzzle

[volans-]

I'm hitting the same bug with a much more simple case, just trying to access caplog.text.

Code for foo.py:

import logging

logger = logging.getLogger()


def foo():
    logger.info('foo')

Code for test_foo.py:

import foo


def test_foo(caplog):
    foo.foo()
    assert 'foo' in caplog.text

Versions installed:

py36-unit runtests: commands[0] | py.test -p no:logging --strict --fulltrace --cov-report=term-missing --cov=foo foo/tests

platform darwin -- Python 3.6.5, pytest-3.6.3, py-1.5.4, pluggy-0.6.0
rootdir: ~/foo, inifile:
plugins: xdist-1.22.3, forked-0.2, cov-2.5.1

Full stacktrace:

_____________________________________________________________________________________________ test_foo ______________________________________________________________________________________________

self = <CallInfo when='call' exception: 'Function' object has no attribute 'catch_log_handler'>, func = <function call_runtest_hook.<locals>.<lambda> at 0x110a09048>, when = 'call'
treat_keyboard_interrupt_as_exception = False

    def __init__(self, func, when, treat_keyboard_interrupt_as_exception=False):
        #: context of invocation: one of "setup", "call",
        #: "teardown", "memocollect"
        self.when = when
        self.start = time()
        try:
>           self.result = func()

.tox/py36-tests/lib/python3.6/site-packages/_pytest/runner.py:199:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

>   lambda: ihook(item=item, **kwds),
    when=when,
    treat_keyboard_interrupt_as_exception=item.config.getvalue("usepdb"),
        )

.tox/py36-tests/lib/python3.6/site-packages/_pytest/runner.py:181:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <_HookCaller 'pytest_runtest_call'>, args = (), kwargs = {'item': <Function 'test_foo'>}, notincall = set()

    def __call__(self, *args, **kwargs):
        if args:
            raise TypeError("hook calling supports only keyword arguments")
        assert not self.is_historic()
        if self.argnames:
            notincall = set(self.argnames) - set(['__multicall__']) - set(
                kwargs.keys())
            if notincall:
                warnings.warn(
                    "Argument(s) {} which are declared in the hookspec "
                    "can not be found in this hook call"
                    .format(tuple(notincall)),
                    stacklevel=2,
                )
>       return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)

.tox/py36-tests/lib/python3.6/site-packages/pluggy/__init__.py:617:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <_pytest.config.PytestPluginManager object at 0x10f81a828>, hook = <_HookCaller 'pytest_runtest_call'>
methods = [<pluggy.HookImpl object at 0x110173550>, <pluggy.HookImpl object at 0x110819828>], kwargs = {'item': <Function 'test_foo'>}

    def _hookexec(self, hook, methods, kwargs):
        # called from all hookcaller instances.
        # enable_tracing will set its own wrapping function at self._inner_hookexec
>       return self._inner_hookexec(hook, methods, kwargs)

.tox/py36-tests/lib/python3.6/site-packages/pluggy/__init__.py:222:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

hook = <_HookCaller 'pytest_runtest_call'>, methods = [<pluggy.HookImpl object at 0x110173550>, <pluggy.HookImpl object at 0x110819828>], kwargs = {'item': <Function 'test_foo'>}

    self._inner_hookexec = lambda hook, methods, kwargs: \
        hook.multicall(
            methods, kwargs,
>           firstresult=hook.spec_opts.get('firstresult'),
        )

.tox/py36-tests/lib/python3.6/site-packages/pluggy/__init__.py:216:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

item = <Function 'test_foo'>

    def pytest_runtest_call(item):
        _update_current_test_var(item, "call")
        sys.last_type, sys.last_value, sys.last_traceback = (None, None, None)
        try:
>           item.runtest()

.tox/py36-tests/lib/python3.6/site-packages/_pytest/runner.py:109:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <Function 'test_foo'>

    def runtest(self):
        """ execute the underlying test function. """
>       self.ihook.pytest_pyfunc_call(pyfuncitem=self)

.tox/py36-tests/lib/python3.6/site-packages/_pytest/python.py:1316:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <_HookCaller 'pytest_pyfunc_call'>, args = (), kwargs = {'pyfuncitem': <Function 'test_foo'>}, notincall = set()

    def __call__(self, *args, **kwargs):
        if args:
            raise TypeError("hook calling supports only keyword arguments")
        assert not self.is_historic()
        if self.argnames:
            notincall = set(self.argnames) - set(['__multicall__']) - set(
                kwargs.keys())
            if notincall:
                warnings.warn(
                    "Argument(s) {} which are declared in the hookspec "
                    "can not be found in this hook call"
                    .format(tuple(notincall)),
                    stacklevel=2,
                )
>       return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)

.tox/py36-tests/lib/python3.6/site-packages/pluggy/__init__.py:617:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <_pytest.config.PytestPluginManager object at 0x10f81a828>, hook = <_HookCaller 'pytest_pyfunc_call'>
methods = [<pluggy.HookImpl object at 0x110173ba8>, <pluggy.HookImpl object at 0x110196470>], kwargs = {'pyfuncitem': <Function 'test_foo'>}

    def _hookexec(self, hook, methods, kwargs):
        # called from all hookcaller instances.
        # enable_tracing will set its own wrapping function at self._inner_hookexec
>       return self._inner_hookexec(hook, methods, kwargs)

.tox/py36-tests/lib/python3.6/site-packages/pluggy/__init__.py:222:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

hook = <_HookCaller 'pytest_pyfunc_call'>, methods = [<pluggy.HookImpl object at 0x110173ba8>, <pluggy.HookImpl object at 0x110196470>], kwargs = {'pyfuncitem': <Function 'test_foo'>}

    self._inner_hookexec = lambda hook, methods, kwargs: \
        hook.multicall(
            methods, kwargs,
>           firstresult=hook.spec_opts.get('firstresult'),
        )

.tox/py36-tests/lib/python3.6/site-packages/pluggy/__init__.py:216:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

pyfuncitem = <Function 'test_foo'>

    @hookimpl(trylast=True)
    def pytest_pyfunc_call(pyfuncitem):
        testfunction = pyfuncitem.obj
        if pyfuncitem._isyieldedfunction():
            testfunction(*pyfuncitem._args)
        else:
            funcargs = pyfuncitem.funcargs
            testargs = {}
            for arg in pyfuncitem._fixtureinfo.argnames:
                testargs[arg] = funcargs[arg]
>           testfunction(**testargs)

.tox/py36-tests/lib/python3.6/site-packages/_pytest/python.py:196:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

caplog = <_pytest.logging.LogCaptureFixture object at 0x110a2dc50>

    def test_foo(caplog):
        foo.foo()
>       assert 'foo' in caplog.text

tests/test_foo.py:6:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <_pytest.logging.LogCaptureFixture object at 0x110a2dc50>

    @property
    def text(self):
        """Returns the log text."""
>       return self.handler.stream.getvalue()

.tox/py36-tests/lib/python3.6/site-packages/_pytest/logging.py:255:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <_pytest.logging.LogCaptureFixture object at 0x110a2dc50>

    @property
    def handler(self):
        """
            :rtype: LogCaptureHandler
            """
>       return self._item.catch_log_handler
E       AttributeError: 'Function' object has no attribute 'catch_log_handler'

.tox/py36-tests/lib/python3.6/site-packages/_pytest/logging.py:232: AttributeError

I've quickly printed the self._item type and is a <class '_pytest.python.Function'>.

[volans-]

At least in my case the culprit was that a -p no:logging was left from some previous testing and that was the cause of the error, so totally my fault, sorry for the confusion. The only thing I might suggest is to catch this and give the user a more nicer error message if caplog is used when logging is disabled.

[RonnyPfannschmidt]

thanks for that note, we should totally protect against that case in some way

[gaborbernat]

I ran into this myself, spent a few hours trying to figure out what's up. Did not manage to pin-point the faulty location, but the problem seems to boil down to the fixture tearing down before the test finishes running. I think it has to do with some kind of exceptions generated during the logging handler; perhaps a loose yield that does not have it's teardown code inside a finally block.

[blueyed]

@volans-
I think yours in more related to #3560 (which was reverted).
We should focus here on the case where it fails to be there with the del.
@gaborbernat
Was it happening with the del for you?

[blueyed]

Maybe #3998 helps with some of the issues mentioned here?

[nicoddemus]

I think this has been fixed by #3998