From e480dfe48b5f011acdb7b06e2cce7b7453f2f44b Mon Sep 17 00:00:00 2001 From: Alex Lambson Date: Fri, 28 May 2021 17:08:55 -0600 Subject: [PATCH 1/4] Handle disabled logging in 'caplog.set_level' and 'caplog.at_level' #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: https://github.com/pytest-dev/pytest/issues/8711 --- AUTHORS | 1 + changelog/8711.improvement.rst | 3 ++ src/_pytest/logging.py | 49 ++++++++++++++++++- testing/logging/test_fixture.py | 84 ++++++++++++++++++++++++++++++++- 4 files changed, 135 insertions(+), 2 deletions(-) create mode 100644 changelog/8711.improvement.rst diff --git a/AUTHORS b/AUTHORS index a6112565e34..92b0b2a1a55 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 00000000000..20805e9f94d --- /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/logging.py b/src/_pytest/logging.py index 2480a5edd29..eab8b714280 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -376,11 +376,12 @@ 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: @@ -388,6 +389,10 @@ def _finalize(self) -> None: 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,39 @@ 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. @@ -460,6 +498,8 @@ def set_level(self, level: Union[int, str], logger: Optional[str] = None) -> Non 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 +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( @@ -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. """ @@ -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 diff --git a/testing/logging/test_fixture.py b/testing/logging/test_fixture.py index e9e73d05f98..49ff70847d3 100644 --- a/testing/logging/test_fixture.py +++ b/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") From bc5a27f2088ec583009be65e42e67df85d174d0a Mon Sep 17 00:00:00 2001 From: Alex Lambson Date: Fri, 5 Nov 2021 20:52:43 -0600 Subject: [PATCH 2/4] caplog un-disable logging, feedback per review #8711 - Resolves issues from review provided by https://github.com/andrewdotn - Fixed spelling errors - Improved logic in `force_enable_logging` - Make a fixture to un-disable logging after a test so that logging will be un-disabled even if the test fails due to an assertion error. The fixture is in `test_fixture.py` because we can't `import logging` in `conftest.py` because there is a module called `logging` in the same folder. - Mypy implicit import error. I can't commit without this. Issue: https://github.com/pytest-dev/pytest/issues/8711 PR: https://github.com/pytest-dev/pytest/pull/8758 --- src/_pytest/config/__init__.py | 2 +- src/_pytest/logging.py | 15 ++++++++------- testing/logging/test_fixture.py | 30 ++++++++++++++++++------------ 3 files changed, 27 insertions(+), 20 deletions(-) diff --git a/src/_pytest/config/__init__.py b/src/_pytest/config/__init__.py index 74905ff4c8e..6df06f7b281 100644 --- a/src/_pytest/config/__init__.py +++ b/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 diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index eab8b714280..707ececb1c7 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -463,7 +463,7 @@ def force_enable_logging( ) -> int: """Enable the desired logging level if the level was disabled. - Only enables logging levels equal too and higher than the requested ``level``. + Only enables logging levels greater than or equal to the requested ``level``. Does nothing if the desired ``level`` wasn't disabled. @@ -478,16 +478,17 @@ def force_enable_logging( 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) - return original_disable_level - if logger_obj.isEnabledFor(level): - return original_disable_level - - disable_level = max(level - 10, logging.NOTSET) - logging.disable(disable_level) + 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 diff --git a/testing/logging/test_fixture.py b/testing/logging/test_fixture.py index 49ff70847d3..7ead6b55810 100644 --- a/testing/logging/test_fixture.py +++ b/testing/logging/test_fixture.py @@ -9,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*"]) @@ -29,7 +42,7 @@ def test_change_level(caplog): assert "CRITICAL" in caplog.text -def test_change_level_logging_disabled(caplog): +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) @@ -45,9 +58,6 @@ def test_change_level_logging_disabled(caplog): 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. @@ -75,7 +85,9 @@ def test2(caplog): result.stdout.no_fnmatch_line("*log from test2*") -def test_change_disabled_level_undo(pytester: Pytester) -> None: +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). @@ -103,9 +115,6 @@ def test2(caplog): 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). @@ -150,7 +159,7 @@ def test_with_statement(caplog): assert "CRITICAL" in caplog.text -def test_with_statement_logging_disabled(caplog): +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): @@ -175,9 +184,6 @@ def test_with_statement_logging_disabled(caplog): 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) From 150914d70a4e4fb93d4b0b51a6d41281577d1b6c Mon Sep 17 00:00:00 2001 From: Alex Lambson Date: Wed, 10 Nov 2021 22:38:18 -0700 Subject: [PATCH 3/4] caplog un-disable logging, add missing test coverage - Adds test coverage for `force_enable_logging` with a string `level`. Fixes [code coverage check](https://github.com/pytest-dev/pytest/pull/8758/checks?check_run_id=4123920877) Issue: https://github.com/pytest-dev/pytest/issues/8711 PR: https://github.com/pytest-dev/pytest/pull/8758 --- testing/logging/test_fixture.py | 33 +++++++++++++++++++++++++++++++++ 1 file changed, 33 insertions(+) diff --git a/testing/logging/test_fixture.py b/testing/logging/test_fixture.py index 7ead6b55810..f500cc962df 100644 --- a/testing/logging/test_fixture.py +++ b/testing/logging/test_fixture.py @@ -185,6 +185,39 @@ def test_with_statement_logging_disabled(caplog, cleanup_disabled_logging): 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") From 7f899967170835e637aac165a9ba1184836b4296 Mon Sep 17 00:00:00 2001 From: Alex Lambson Date: Wed, 17 May 2023 21:42:08 -0600 Subject: [PATCH 4/4] caplog un-disable logging, add missing test coverage - Address review ad rebase to latest from main - Make `force_enable_logging` private. Issue: https://github.com/pytest-dev/pytest/issues/8711 PR: https://github.com/pytest-dev/pytest/pull/8758 --- src/_pytest/logging.py | 14 +++++++------- testing/logging/test_fixture.py | 8 ++++---- 2 files changed, 11 insertions(+), 11 deletions(-) diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 707ececb1c7..95774dd1472 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -458,22 +458,22 @@ def clear(self) -> None: """Reset the list of log records and the captured log text.""" self.handler.clear() - def force_enable_logging( + def _force_enable_logging( self, level: Union[int, str], logger_obj: logging.Logger ) -> int: - """Enable the desired logging level if the level was disabled. + """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 Union[int, str] level: + :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 logger_obj: The logger object to check. + :param logger_obj: The logger object to check. - :return int: The original disabled logging level. + :return: The original disabled logging level. """ original_disable_level: int = logger_obj.manager.disable # type: ignore[attr-defined] @@ -511,7 +511,7 @@ 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) + 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 @@ -533,7 +533,7 @@ 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) + original_disable_level = self._force_enable_logging(level, logger_obj) try: yield finally: diff --git a/testing/logging/test_fixture.py b/testing/logging/test_fixture.py index f500cc962df..8eaa2de96a8 100644 --- a/testing/logging/test_fixture.py +++ b/testing/logging/test_fixture.py @@ -1,4 +1,4 @@ -# type: ignore[attr-defined] +# mypy: disable-error-code="attr-defined" import logging import pytest @@ -88,7 +88,7 @@ def test2(caplog): 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. + """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). """ @@ -200,7 +200,7 @@ def test_with_statement_logging_disabled(caplog, cleanup_disabled_logging): def test_force_enable_logging_level_string( caplog, cleanup_disabled_logging, level_str, expected_disable_level ): - """Test force_enable_logging using a level string. + """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. @@ -211,7 +211,7 @@ def test_force_enable_logging_level_string( # 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) + 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()`.