Handle disabled logging in 'caplog.set_level' and 'caplog.at_level' p…

…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

AUTHORS

@@ -12,6 +12,7 @@ Adam Uhlir
 Ahn Ki-Wook
 Akiomi Kamakura
 Alan Velasco
+Alex Lambson
 Alexander Johnson
 Alexei Kozlenok
 Allan Feldman

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

@@ -46,7 +46,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.compat import LEGACY_PATH
 from _pytest.compat import legacy_path
 from _pytest.outcomes import fail

src/_pytest/logging.py

@@ -353,18 +353,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:
@@ -431,13 +436,48 @@ def clear(self) -> None:
         """Reset the list of log records and the captured log text."""
         self.handler.reset()
 
+    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 requesed logging level if it was disabled via :meth:`logging.disable`.
+
         :param int level: The level.
         :param str logger: The logger to update. If not given, the root logger.
         """
@@ -448,6 +488,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(
@@ -457,6 +500,8 @@ def at_level(
         the end of the 'with' statement the level is restored to its original
         value.
 
+        Will enable the requesed logging level if it was disabled via :meth:`logging.disable`.
+
         :param int level: The level.
         :param str logger: The logger to update. If not given, the root logger.
         """
@@ -465,11 +510,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 @@
+# type: ignore[attr-defined]
 import logging
 
 import pytest
@@ -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(
         """
@@ -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).
 
@@ -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")