Skip to content

Commit

Permalink
Handle disabled logging in 'caplog.set_level' and 'caplog.at_level' p…
Browse files Browse the repository at this point in the history
…ytest-dev#8711

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.

Issue: pytest-dev#8711
  • Loading branch information
Alex Lambson authored and alexlambson committed May 18, 2023
1 parent 739408b commit e480dfe
Show file tree
Hide file tree
Showing 4 changed files with 135 additions and 2 deletions.
1 change: 1 addition & 0 deletions AUTHORS
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@ Akiomi Kamakura
Alan Velasco
Alessio Izzo
Alex Jones
Alex Lambson
Alexander Johnson
Alexander King
Alexei Kozlenok
Expand Down
3 changes: 3 additions & 0 deletions changelog/8711.improvement.rst
Original file line number Diff line number Diff line change
@@ -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)``.
49 changes: 48 additions & 1 deletion src/_pytest/logging.py
Original file line number Diff line number Diff line change
Expand Up @@ -376,18 +376,23 @@ def __init__(self, item: nodes.Node, *, _ispytest: bool = False) -> None:
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:
self.handler.setLevel(self._initial_handler_level)
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:
Expand Down Expand Up @@ -453,13 +458,48 @@ def clear(self) -> None:
"""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 level was disabled.
Only enables logging levels equal too and higher than the requested ``level``.
Does nothing if the desired ``level`` wasn't disabled.
:param Union[int, str] 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 logger_obj: The logger object to check.
:return int: The original disabled logging level.
"""
original_disable_level: int = logger_obj.manager.disable # type: ignore[attr-defined]

if isinstance(level, str):
level = logging.getLevelName(level)

if not isinstance(level, int):
logging.disable(logging.NOTSET)
return original_disable_level
if logger_obj.isEnabledFor(level):
return original_disable_level

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.
.. versionchanged:: 3.4
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.
"""
Expand All @@ -470,6 +510,9 @@ def set_level(self, level: Union[int, str], logger: Optional[str] = None) -> Non
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(
Expand All @@ -479,6 +522,8 @@ def at_level(
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.
"""
Expand All @@ -487,11 +532,13 @@ def at_level(
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
Expand Down
84 changes: 83 additions & 1 deletion testing/logging/test_fixture.py
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
# type: ignore[attr-defined]
import logging

import pytest
Expand Down Expand Up @@ -28,10 +29,30 @@ def test_change_level(caplog):
assert "CRITICAL" in caplog.text


def test_change_level_logging_disabled(caplog):
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

# logging.disable needs to be reset because it's global and causes future tests will break.
logging.disable(logging.NOTSET)


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(
"""
Expand All @@ -54,6 +75,38 @@ def test2(caplog):
result.stdout.no_fnmatch_line("*log from test2*")


def test_change_disabled_level_undo(pytester: Pytester) -> 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*")

# logging.disable needs to be reset because it's global and causes future tests will break.
logging.disable(logging.NOTSET)


def test_change_level_undos_handler_level(pytester: Pytester) -> None:
"""Ensure that 'set_level' is undone after the end of the test (handler).
Expand Down Expand Up @@ -97,6 +150,35 @@ def test_with_statement(caplog):
assert "CRITICAL" in caplog.text


def test_with_statement_logging_disabled(caplog):
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

# logging.disable needs to be reset because it's global and causes future tests will break.
logging.disable(logging.NOTSET)


def test_log_access(caplog):
caplog.set_level(logging.INFO)
logger.info("boo %s", "arg")
Expand Down

0 comments on commit e480dfe

Please sign in to comment.