pytest-dev / pytest-dev/pytest

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

Open
#9,236 14 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

plugin: capture plugin: logging status: help wanted type: bug
Dominant language
Python
Stars
14.5k
Forks
3.4k
Avg merge
2d 9h
Merged PRs (30d)
35

Description

  • 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.

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start by running the reported test.py and conftest.py reproducer, then inspect pytest's caplog fixture and LogCaptureHandler implementation. Trace why gc.collect() removes handlers from logging.root.handlers, and add a regression test demonstrating that captured messages and records remain available after collection. Done means the reproducer passes and the relevant logging tests pass.

Written by the indexing model from the issue text.

Assessment

Tech stack
python
Domain
testing-qa
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Quiet
Clarity
Mostly clear
Newbie friendliness
45/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.