`LogCaptureHandler` can be garbage collected when `caplog` fixture is in use

[leamingrad]

• a detailed description of the bug or problem you are having

In our tests we have had issues with the caplog fixture not correctly saving every log into caplog.messages and caplog.records. From what I can tell, the underlying issue is that in some circumstances the LogCaptureHandlers that caplog relies on can get garbage collected.

There seem to be a lot of issues in this area (#5160, #8977, #7335 etc.), but I'm not sure if any of them are the specific case that I have experienced.

• minimal example if possible

Some debugging has got me to the stage where I have a MWE that reproduces the problem:

test.py:

import gc
import logging
import sys

import pytest

logging.basicConfig()
logger = logging.getLogger()


# No idea why this test must be an xfail, but we do not hit the error if this is an empty pass
@pytest.mark.xfail
def test_other_test():
    assert False


def test_a_test_with_caplog(caplog):
    print(logging.root.handlers)
    gc.collect()
    print(logging.root.handlers)
    logger.error("TEST")
    assert caplog.messages[0] == "TEST", caplog.messages

conftest.py:

# It is unclear if this makes a difference (as the number of objects is so small we would be
# unlikely to hit a GC anyway)
# import gc
# gc.disable()

import pytest


# Despite this being a noop, it is required to hit the issue
@pytest.hookimpl(hookwrapper=True)
def pytest_runtest_call(item):
    outcome = yield
    outcome.get_result()

If you run pytest test.py, then it fails with the following:

❯ pytest test.py
======================================================== test session starts ========================================================
platform darwin -- Python 3.8.3, pytest-6.2.5, py-1.10.0, pluggy-1.0.0
rootdir: /Users/james/code/pytest_example
collected 2 items                                                                                                                   

test.py xF                                                                                                                    [100%]

============================================================= FAILURES ==============================================================
______________________________________________________ test_a_test_with_caplog ______________________________________________________

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

    def test_a_test_with_caplog(caplog):
        print(logging.root.handlers)
        gc.collect()
        print(logging.root.handlers)
        logger.error("TEST")
>       assert caplog.messages[0] == "TEST", caplog.messages
E       IndexError: list index out of range

test.py:22: IndexError
------------------------------------------------------- Captured stdout call --------------------------------------------------------
[<_LiveLoggingNullHandler (NOTSET)>, <_FileHandler /dev/null (NOTSET)>, <LogCaptureHandler (NOTSET)>, <LogCaptureHandler (NOTSET)>]
[<_LiveLoggingNullHandler (NOTSET)>, <_FileHandler /dev/null (NOTSET)>]
====================================================== short test summary info ======================================================
FAILED test.py::test_a_test_with_caplog - IndexError: list index out of range
=================================================== 1 failed, 1 xfailed in 0.04s ====================================================

However, if you remove the gc.collect() call from the test, it passes:

❯ pytest test.py
======================================================== test session starts ========================================================
platform darwin -- Python 3.8.3, pytest-6.2.5, py-1.10.0, pluggy-1.0.0
rootdir: /Users/james/code/pytest_example
collected 2 items                                                                                                                   

test.py x.                                                                                                                    [100%]

=================================================== 1 passed, 1 xfailed in 0.04s ====================================================

• output of pip list from the virtual environment you are using

❯ pip list
Package                           Version  
--------------------------------- ---------
appdirs                           1.4.4    
attrs                             21.2.0   
backports.entry-points-selectable 1.1.0    
CacheControl                      0.12.6   
cachy                             0.3.0    
certifi                           2021.10.8
charset-normalizer                2.0.7    
cleo                              0.8.1    
clikit                            0.6.2    
crashtest                         0.3.1    
distlib                           0.3.3    
filelock                          3.0.12   
html5lib                          1.1      
idna                              3.2      
iniconfig                         1.1.1    
keyring                           21.8.0   
lockfile                          0.12.2   
msgpack                           1.0.2    
packaging                         20.9     
pastel                            0.2.1    
pbr                               5.4.5    
pexpect                           4.8.0    
pip                               19.2.3   
pkginfo                           1.7.1    
platformdirs                      2.4.0    
pluggy                            1.0.0    
poetry                            1.1.11   
poetry-core                       1.0.7    
ptyprocess                        0.7.0    
py                                1.10.0   
pylev                             1.4.0    
pyparsing                         2.4.7    
pytest                            6.2.5    
requests                          2.26.0   
requests-toolbelt                 0.9.1    
setuptools                        41.2.0   
shellingham                       1.4.0    
six                               1.15.0   
stevedore                         2.0.0    
toml                              0.10.2   
tomlkit                           0.7.2    
urllib3                           1.26.7   
virtualenv                        20.8.1   
virtualenv-clone                  0.5.4    
virtualenvwrapper                 4.8.4    
webencodings                      0.5.1    
WARNING: You are using pip version 19.2.3, however version 21.3.1 is available.
You should consider upgrading via the 'pip install --upgrade pip' command.

• pytest and operating system versions

pytest 6.2.5 and MacOS BigSur 11.6.

[twmr]

It is impressive that you managed to create a MWE for this issue.!

I've just tested your MWE and I can reproduce your reported issue 👍🏿. I also had a quick look at the code and did some test, however I don't yet know where the problem is.

What I know so far is that when _runtest_for is called with when='call' and item=<Function test_other_test>, the __enter__ of catching_logs ctx adds the LogCaptureHandler for the caplog-handler instance to the handlers of the root-logger. Exactly for this instance of the catching_logs ctx __exit__ is called and the handler (together with the other handler) is removed from the root logger when gc.collect() is called in test_a_test_with_caplog in your MWE. Don't ask me why.

[twmr]

So: gc.collect() deterministically triggers the __exit__ of a catching_logs instance (created in a previous test), which then removes a handler from the root-loggers handlers in the middle of test_a_test_with_caplog. Maybe someone else can figure out why this happens.

[twmr]

It's me again. In the call phase of test_other_test (the one that raises an AssertionError), the __exit__ methods of the two catching_logs contexts in _runtest_for are not called at least not immediately, but only when gc.collect() is called.

[twmr]

@leamingrad Why you do need a custom
pytest_runtest_call in conftest.py? Your custom pytest_runtest_call wrapper is causing a problem with the context manager(s) that are used in

pytest/src/_pytest/logging.py

Line 693 in d6e6b96

def _runtest_for(self, item: nodes.Item, when: str) -> Generator[None, None, None]:

. The problem is that when a simple

def test():
    assert False

test is executed, the code after the yield statement in the call-phase, i.e., when="call", in

pytest/src/_pytest/logging.py

Line 707 in d6e6b96

yield

is not executed.

Maybe @nicoddemus @bluetech or @RonnyPfannschmidt can help me explain why this can happen.

[nicoddemus]

Hmmm as with any context manager, that yield in src/_pytest/logging.py should be surrounded with a try/finally, otherwise the exception will prevent the code after yield from executing. Seems we missed that detail.

[twmr]

@nicoddemus I should have mentioned this before, but yield never raises at least not in the _runtest_for method.

@leamingrad what is the reason for you custom pytest_runtest_call implementation?

[leamingrad]

@Thisch Thanks for the investigation - let me know if there is any more info I can give to help.

The implementation of pytest_runtest_call in the suite I am working with is there to wrap some exceptions and give a more helpful message to the user (specifically, we catch some DB exceptions and replace them with a message to run the tests again with the --create-db option from pytest_django).

from django.db import utils

class CustomException(Exception):
    pass

@pytest.hookimpl(hookwrapper=True)
def pytest_runtest_call(item):
    try:
        outcome = yield
        outcome.get_result()
    except utils.ProgrammingError as e:
        raise CustomException("Try running again with --create-db") from e

[twmr]

@leamingrad

I just had a look again at your issue. If you fix your issue by adding a try: ... except: pass block around the outcome.get_result() line.

[twmr]

The problem was that your custom pytest_runtest_call hook raised, because you didn't catch the exception raised by get_result() in the case of failing tests. The exception raised by your hook lead to a non-graceful teardown of the other pytest_runtest_call hooks (e.g. the one from the logging plugin).

[leamingrad]

@Thisch: Thanks for looking at this again. If I make the change to the MWE, I can confirm that things start to pass.

However, I don't quite understand the reasoning above: why should my python_runtest_call hook catch all exceptions in outcome.get_result()?

Looking at the docs, it seems like outcome.get_result() in a hook wrapper is supposed to raise when called in a hook if the test has failed (and each hookwrapper should handle that as appropriate).

I've probably just misunderstood something though - it's not immediately obvious to me where the responsibility lies.

[twmr]

why should my python_runtest_call hook catch all exceptions in outcome.get_result()?

Because otherwise there is currently a non graceful teardown of at least one hook. This should probably be fixed on pytest's side, but I'm no expert on this.