`caplog.at_level` affects caplog handler too?

[znicholls]

• a detailed description of the bug or suggestion
• output of pip list from the virtual environment you are using
• pytest and operating system versions
• minimal example if possible

For clarity, I'm not sure if this is a bug or whether we are just using pytest incorrectly.

In fcbaab8, the behaviour of at_level was changed so that it affects self.handler too. Was this on purpose? It means that adding the following code to testing/logging/test_fixture.py causes the tests to fail.

# now failing test code
otherlogger = logging.getLogger("tpytest")

def test_with_statement_root_messages_still_logged(caplog):
    with caplog.at_level(logging.INFO):
        with caplog.at_level(logging.CRITICAL, logger=otherlogger.name):
            # doesn't come through because root logger is at INFO level
            logger.debug("root DEBUG level")
            # Is this meant to come through because setting the level of otherlogger
            # should not affect the root logger or have I missed something?
            logger.info("root INFO level")

            # doesn't come through because otherlogger is at CRITICAL level
            otherlogger.warning("otherlogger WARNING level")
            # does come through
            otherlogger.critical("otherlogger CRITICAL level")

    assert "DEBUG" not in caplog.text
    # This test fails. Is the root logger meant to be affected when we change
    # the otherlogger's level?
    assert "INFO" in caplog.text
    assert "WARNING" not in caplog.text
    assert "CRITICAL" in caplog.text

I'm on macOS Mojave 10.14.6, Python 3.7

# pip list output
$ pip list
Package            Version                Location
------------------ ---------------------- ------------------------------------------------
appdirs            1.4.4
argcomplete        1.12.0
attrs              19.3.0
certifi            2020.6.20
cfgv               3.2.0
chardet            3.0.4
distlib            0.3.1
elementpath        2.0.0
filelock           3.0.12
hypothesis         5.25.0
identify           1.4.28
idna               2.10
importlib-metadata 1.7.0
iniconfig          1.0.1
line-profiler      2.1.1
mock               4.0.2
nodeenv            1.4.0
nose               1.3.7
packaging          20.4
pip                20.2.2
pluggy             0.13.1
pre-commit         2.6.0
py                 1.9.0
pyparsing          2.4.7
pytest             6.0.1.dev94+g3f0abcc6a ...Documents/pytest/src
PyYAML             5.3.1
requests           2.24.0
setuptools         49.6.0.post20200814
six                1.15.0
sortedcontainers   2.2.2
toml               0.10.1
tox                3.19.0
urllib3            1.25.10
virtualenv         20.0.30
wheel              0.35.1
xmlschema          1.2.3
zipp               3.1.0

[znicholls]

For what it's worth, I think this test would have passed with pytest <6.0 (see IAMconsortium/pyam#422 and adobe-type-tools/psautohint#264).

[bluetech]

Thanks for the report @znicholls.

I was a little confused by the issue title "caplog.at_level affects root logger too?" at first, because the main purpose of at_level is to set the level of a logger, and that's what it always did. But in your description the issue is that at_level also changes the level of the caplog handler, not only the logger, which is new.

I think there are some things we can improve here, will try to dig into it more when I get the chance.

[znicholls]

thanks @bluetech! I just updated the title so hopefully it is clearer. If you see a way forward I'm happy to have a go at implementing.

[plannigan]

This also effects caplog.set_level(). The same commit seems to be the source of the change.

import logging

def test_caplog_set_level__set_for_specific_logger__root_logger_captured(caplog):
    root_logger = logging.getLogger()
    root_logger.setLevel(logging.INFO)
    otherlogger = logging.getLogger("otherlogger")

    caplog.set_level(logging.CRITICAL, logger=otherlogger.name)

    root_logger.debug("root DEBUG")
    root_logger.info("root INFO")

    otherlogger.warning("specific_logger WARNING")
    otherlogger.critical("specific_logger CRITICAL")

    print(caplog.text)

    assert "DEBUG" not in caplog.text
    # This test fails. Is the root logger meant to be affected when we change
    # the otherlogger's level?
    assert "INFO" in caplog.text
    assert "WARNING" not in caplog.text
    assert "CRITICAL" in caplog.text

This code passes with pytest 5.4.3

 pytest test_caplog.py 
================================================== test session starts ===========================
platform linux -- Python 3.8.2, pytest-5.4.3, py-1.9.0, pluggy-0.13.1
rootdir: /mnt/code-drive/code/pyplats-automation, inifile: pytest.ini
collected 1 item                                                                                                         

test_caplog.py .                                                           100%]

=================================================== 1 passed in 0.01s ===========================

But fails with pytest 6.1.2

================================================== test session starts ===================================================
platform linux -- Python 3.8.2, pytest-6.1.2, py-1.9.0, pluggy-0.13.1
rootdir: /mnt/code-drive/code/pyplats-automation, configfile: pytest.ini
collected 1 item                                                                                                         

test_caplog.py F                                                                                                   [100%]

======================================================== FAILURES ========================================================
__________________________ test_caplog_set_level__set_for_specific_logger__root_logger_captured __________________________

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

    def test_caplog_set_level__set_for_specific_logger__root_logger_captured(caplog):
        root_logger = logging.getLogger()
        root_logger.setLevel(logging.INFO)
        otherlogger = logging.getLogger("otherlogger")
    
        caplog.set_level(logging.CRITICAL, logger=otherlogger.name)
    
        root_logger.debug("root DEBUG")
        root_logger.info("root INFO")
    
        otherlogger.warning("specific_logger WARNING")
        otherlogger.critical("specific_logger CRITICAL")
    
        print(caplog.text)
    
        assert "DEBUG" not in caplog.text
        # This test fails. Is the root logger meant to be affected when we change
        # the otherlogger's level?
>       assert "INFO" in caplog.text
E       AssertionError: assert 'INFO' in 'CRITICAL otherlogger:test_caplog.py:15 specific_logger CRITICAL\n'
E        +  where 'CRITICAL otherlogger:test_caplog.py:15 specific_logger CRITICAL\n' = <_pytest.logging.LogCaptureFixture object at 0x7f1543bcc850>.text

test_caplog.py:22: AssertionError
-------------------------------------------------- Captured stdout call --------------------------------------------------
CRITICAL otherlogger:test_caplog.py:15 specific_logger CRITICAL

--------------------------------------------------- Captured log call ----------------------------------------------------
INFO     root:test_caplog.py:12 root INFO
CRITICAL otherlogger:test_caplog.py:15 specific_logger CRITICAL
================================================ short test summary info =================================================
FAILED test_caplog.py::test_caplog_set_level__set_for_specific_logger__root_logger_captured - AssertionError: assert 'I...
=================================================== 1 failed in 0.04s ====================================================

Reading the documentation for set_level(), it is a bit ambiguous if the function is intended to affect the level that caplog captures or the level of the given logger (root if not given). However, the docstring for set_level() seems to provide a more definitive answer of affecting the logger.

[peytondmurray]

Sorry for bumping this ancient issue, but I just spent a bunch of time debugging what I think is the same issue. I have an autouse fixture which modifies the logging level of a logger:

@pytest.fixture(autouse=True)
def urllib3_logger_error(caplog):
    caplog.set_level(logging.ERROR, logger="urllib3.connectionpool")

Elsewhere, running a test that needs to capture log messages from a completely different logger fails to do so:

def test_run_fails(caplog):
    logger = logging.getLogger('foo')

    logger.warning("ack!")
    assert len(caplog.records) > 0  # <-- fails here


def test_run_succeeds(caplog):
    logger = logging.getLogger('foo')

    with caplog.at_level(logging.WARNING):
        logger.warning("ack!")
    assert len(caplog.records) > 0  # <-- this works as intended

From the documentation it seems like the fixture should only target the urllib3.connectionpool logger:

By default the level is set on the root logger, however as a convenience it is also possible to set the log level of any logger

but it seems like this affects every log message - I guess because caplog.set_level sets the level of the caplog handler itself as mentioned in the first post. What's the right course of action here? The current behavior goes against my expectations. I'd be willing to contribute a solution, but I'd like to hear input from other folks as well.