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

AUTHORS

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

changelog/8711.improvement.rst

@@ -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)``.

src/_pytest/config/__init__.py

@@ -49,7 +49,7 @@
 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

src/_pytest/logging.py

@@ -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:
@@ -453,13 +458,49 @@ 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 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.
 
         .. 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.
         """
@@ -470,6 +511,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(
@@ -479,6 +523,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.
         """
@@ -487,11 +533,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

testing/logging/test_fixture.py

@@ -1,3 +1,4 @@
+# mypy: disable-error-code="attr-defined"
 import logging
 
 import pytest
@@ -8,6 +9,19 @@
 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 test2(caplog):
     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")