Handle disabled logging in 'caplog.set_level' and 'caplog.at_level' (#8758)

Forces requested `caplog` logging levels to be enabled if they were disabled via `logging.disable()`

`[attr-defined]` mypy error ignored in `logging.py` because there were existing errors with the imports
and `loggin.Logger.manager` is an attr set at runtime. Since it's in the standard lib I can't really fix that.

Ignored an attr-defined error in `src/_pytest/config/__init__.py` because the re-export is necessary.

Fixes #8711
This commit is contained in:
Alex Lambson 2023-05-18 07:18:59 -06:00 committed by GitHub
parent c8641f879f
commit ba32a3bd87
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
5 changed files with 176 additions and 3 deletions

View File

@ -15,6 +15,7 @@ Akiomi Kamakura
Alan Velasco
Alessio Izzo
Alex Jones
Alex Lambson
Alexander Johnson
Alexander King
Alexei Kozlenok

View File

@ -0,0 +1,3 @@
:func:`_pytest.logging.LogCaptureFixture.set_level` and :func:`_pytest.logging.LogCaptureFixture.at_level`
will temporarily enable the requested ``level`` if ``level`` was disabled globally via
``logging.disable(LEVEL)``.

View File

@ -49,7 +49,7 @@ from _pytest._code import ExceptionInfo
from _pytest._code import filter_traceback
from _pytest._io import TerminalWriter
from _pytest.compat import final
from _pytest.compat import importlib_metadata
from _pytest.compat import importlib_metadata # type: ignore[attr-defined]
from _pytest.outcomes import fail
from _pytest.outcomes import Skipped
from _pytest.pathlib import absolutepath

View File

@ -376,11 +376,12 @@ class LogCaptureFixture:
self._initial_handler_level: Optional[int] = None
# Dict of log name -> log level.
self._initial_logger_levels: Dict[Optional[str], int] = {}
self._initial_disabled_logging_level: Optional[int] = None
def _finalize(self) -> None:
"""Finalize the fixture.
This restores the log levels changed by :meth:`set_level`.
This restores the log levels and the disabled logging levels changed by :meth:`set_level`.
"""
# Restore log levels.
if self._initial_handler_level is not None:
@ -388,6 +389,10 @@ class LogCaptureFixture:
for logger_name, level in self._initial_logger_levels.items():
logger = logging.getLogger(logger_name)
logger.setLevel(level)
# Disable logging at the original disabled logging level.
if self._initial_disabled_logging_level is not None:
logging.disable(self._initial_disabled_logging_level)
self._initial_disabled_logging_level = None
@property
def handler(self) -> LogCaptureHandler:
@ -453,6 +458,40 @@ class LogCaptureFixture:
"""Reset the list of log records and the captured log text."""
self.handler.clear()
def _force_enable_logging(
self, level: Union[int, str], logger_obj: logging.Logger
) -> int:
"""Enable the desired logging level if the global level was disabled via ``logging.disabled``.
Only enables logging levels greater than or equal to the requested ``level``.
Does nothing if the desired ``level`` wasn't disabled.
:param level:
The logger level caplog should capture.
All logging is enabled if a non-standard logging level string is supplied.
Valid level strings are in :data:`logging._nameToLevel`.
:param logger_obj: The logger object to check.
:return: The original disabled logging level.
"""
original_disable_level: int = logger_obj.manager.disable # type: ignore[attr-defined]
if isinstance(level, str):
# Try to translate the level string to an int for `logging.disable()`
level = logging.getLevelName(level)
if not isinstance(level, int):
# The level provided was not valid, so just un-disable all logging.
logging.disable(logging.NOTSET)
elif not logger_obj.isEnabledFor(level):
# Each level is `10` away from other levels.
# https://docs.python.org/3/library/logging.html#logging-levels
disable_level = max(level - 10, logging.NOTSET)
logging.disable(disable_level)
return original_disable_level
def set_level(self, level: Union[int, str], logger: Optional[str] = None) -> None:
"""Set the level of a logger for the duration of a test.
@ -460,6 +499,8 @@ class LogCaptureFixture:
The levels of the loggers changed by this function will be
restored to their initial values at the end of the test.
Will enable the requested logging level if it was disabled via :meth:`logging.disable`.
:param level: The level.
:param logger: The logger to update. If not given, the root logger.
"""
@ -470,6 +511,9 @@ class LogCaptureFixture:
if self._initial_handler_level is None:
self._initial_handler_level = self.handler.level
self.handler.setLevel(level)
initial_disabled_logging_level = self._force_enable_logging(level, logger_obj)
if self._initial_disabled_logging_level is None:
self._initial_disabled_logging_level = initial_disabled_logging_level
@contextmanager
def at_level(
@ -479,6 +523,8 @@ class LogCaptureFixture:
the end of the 'with' statement the level is restored to its original
value.
Will enable the requested logging level if it was disabled via :meth:`logging.disable`.
:param level: The level.
:param logger: The logger to update. If not given, the root logger.
"""
@ -487,11 +533,13 @@ class LogCaptureFixture:
logger_obj.setLevel(level)
handler_orig_level = self.handler.level
self.handler.setLevel(level)
original_disable_level = self._force_enable_logging(level, logger_obj)
try:
yield
finally:
logger_obj.setLevel(orig_level)
self.handler.setLevel(handler_orig_level)
logging.disable(original_disable_level)
@fixture

View File

@ -1,3 +1,4 @@
# mypy: disable-error-code="attr-defined"
import logging
import pytest
@ -8,6 +9,19 @@ logger = logging.getLogger(__name__)
sublogger = logging.getLogger(__name__ + ".baz")
@pytest.fixture
def cleanup_disabled_logging():
"""Simple fixture that ensures that a test doesn't disable logging.
This is necessary because ``logging.disable()`` is global, so a test disabling logging
and not cleaning up after will break every test that runs after it.
This behavior was moved to a fixture so that logging will be un-disabled even if the test fails an assertion.
"""
yield
logging.disable(logging.NOTSET)
def test_fixture_help(pytester: Pytester) -> None:
result = pytester.runpytest("--fixtures")
result.stdout.fnmatch_lines(["*caplog*"])
@ -28,10 +42,27 @@ def test_change_level(caplog):
assert "CRITICAL" in caplog.text
def test_change_level_logging_disabled(caplog, cleanup_disabled_logging):
logging.disable(logging.CRITICAL)
assert logging.root.manager.disable == logging.CRITICAL
caplog.set_level(logging.WARNING)
logger.info("handler INFO level")
logger.warning("handler WARNING level")
caplog.set_level(logging.CRITICAL, logger=sublogger.name)
sublogger.warning("logger SUB_WARNING level")
sublogger.critical("logger SUB_CRITICAL level")
assert "INFO" not in caplog.text
assert "WARNING" in caplog.text
assert "SUB_WARNING" not in caplog.text
assert "SUB_CRITICAL" in caplog.text
def test_change_level_undo(pytester: Pytester) -> None:
"""Ensure that 'set_level' is undone after the end of the test.
Tests the logging output themselves (affacted both by logger and handler levels).
Tests the logging output themselves (affected both by logger and handler levels).
"""
pytester.makepyfile(
"""
@ -54,6 +85,37 @@ def test_change_level_undo(pytester: Pytester) -> None:
result.stdout.no_fnmatch_line("*log from test2*")
def test_change_disabled_level_undo(
pytester: Pytester, cleanup_disabled_logging
) -> None:
"""Ensure that '_force_enable_logging' in 'set_level' is undone after the end of the test.
Tests the logging output themselves (affected by disabled logging level).
"""
pytester.makepyfile(
"""
import logging
def test1(caplog):
logging.disable(logging.CRITICAL)
caplog.set_level(logging.INFO)
# using + operator here so fnmatch_lines doesn't match the code in the traceback
logging.info('log from ' + 'test1')
assert 0
def test2(caplog):
# using + operator here so fnmatch_lines doesn't match the code in the traceback
# use logging.warning because we need a level that will show up if logging.disabled
# isn't reset to ``CRITICAL`` after test1.
logging.warning('log from ' + 'test2')
assert 0
"""
)
result = pytester.runpytest()
result.stdout.fnmatch_lines(["*log from test1*", "*2 failed in *"])
result.stdout.no_fnmatch_line("*log from test2*")
def test_change_level_undos_handler_level(pytester: Pytester) -> None:
"""Ensure that 'set_level' is undone after the end of the test (handler).
@ -97,6 +159,65 @@ def test_with_statement(caplog):
assert "CRITICAL" in caplog.text
def test_with_statement_logging_disabled(caplog, cleanup_disabled_logging):
logging.disable(logging.CRITICAL)
assert logging.root.manager.disable == logging.CRITICAL
with caplog.at_level(logging.WARNING):
logger.debug("handler DEBUG level")
logger.info("handler INFO level")
logger.warning("handler WARNING level")
logger.error("handler ERROR level")
logger.critical("handler CRITICAL level")
assert logging.root.manager.disable == logging.INFO
with caplog.at_level(logging.CRITICAL, logger=sublogger.name):
sublogger.warning("logger SUB_WARNING level")
sublogger.critical("logger SUB_CRITICAL level")
assert "DEBUG" not in caplog.text
assert "INFO" not in caplog.text
assert "WARNING" in caplog.text
assert "ERROR" in caplog.text
assert " CRITICAL" in caplog.text
assert "SUB_WARNING" not in caplog.text
assert "SUB_CRITICAL" in caplog.text
assert logging.root.manager.disable == logging.CRITICAL
@pytest.mark.parametrize(
"level_str,expected_disable_level",
[
("CRITICAL", logging.ERROR),
("ERROR", logging.WARNING),
("WARNING", logging.INFO),
("INFO", logging.DEBUG),
("DEBUG", logging.NOTSET),
("NOTSET", logging.NOTSET),
("NOTVALIDLEVEL", logging.NOTSET),
],
)
def test_force_enable_logging_level_string(
caplog, cleanup_disabled_logging, level_str, expected_disable_level
):
"""Test _force_enable_logging using a level string.
``expected_disable_level`` is one level below ``level_str`` because the disabled log level
always needs to be *at least* one level lower than the level that caplog is trying to capture.
"""
test_logger = logging.getLogger("test_str_level_force_enable")
# Emulate a testing environment where all logging is disabled.
logging.disable(logging.CRITICAL)
# Make sure all logging is disabled.
assert not test_logger.isEnabledFor(logging.CRITICAL)
# Un-disable logging for `level_str`.
caplog._force_enable_logging(level_str, test_logger)
# Make sure that the disabled level is now one below the requested logging level.
# We don't use `isEnabledFor` here because that also checks the level set by
# `logging.setLevel()` which is irrelevant to `logging.disable()`.
assert test_logger.manager.disable == expected_disable_level
def test_log_access(caplog):
caplog.set_level(logging.INFO)
logger.info("boo %s", "arg")