From ba32a3bd87e92d87d777a62414972374cbbfddf2 Mon Sep 17 00:00:00 2001 From: Alex Lambson Date: Thu, 18 May 2023 07:18:59 -0600 Subject: [PATCH] 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 | 1 + changelog/8711.improvement.rst | 3 + src/_pytest/config/__init__.py | 2 +- src/_pytest/logging.py | 50 ++++++++++++- testing/logging/test_fixture.py | 123 +++++++++++++++++++++++++++++++- 5 files changed, 176 insertions(+), 3 deletions(-) create mode 100644 changelog/8711.improvement.rst diff --git a/AUTHORS b/AUTHORS index a6112565e..92b0b2a1a 100644 --- a/AUTHORS +++ b/AUTHORS @@ -15,6 +15,7 @@ Akiomi Kamakura Alan Velasco Alessio Izzo Alex Jones +Alex Lambson Alexander Johnson Alexander King Alexei Kozlenok diff --git a/changelog/8711.improvement.rst b/changelog/8711.improvement.rst new file mode 100644 index 000000000..20805e9f9 --- /dev/null +++ b/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)``. diff --git a/src/_pytest/config/__init__.py b/src/_pytest/config/__init__.py index 74905ff4c..6df06f7b2 100644 --- a/src/_pytest/config/__init__.py +++ b/src/_pytest/config/__init__.py @@ -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 diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 2480a5edd..95774dd14 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -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 diff --git a/testing/logging/test_fixture.py b/testing/logging/test_fixture.py index e9e73d05f..8eaa2de96 100644 --- a/testing/logging/test_fixture.py +++ b/testing/logging/test_fixture.py @@ -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")