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.