From 7df111e1e4555cfd4f2ae4028ad6f50501f12476 Mon Sep 17 00:00:00 2001 From: Zane Bitter Date: Wed, 14 Aug 2019 13:50:32 -0400 Subject: [PATCH 1/5] bpo-37857: Invalidate cache when log level changed directly While the logging level of a Logger should really be changed only by calling the setLevel() method, there exists code in the wild that changes it by setting the public 'level' attribute directly. Prior to Python 3.7, this worked correctly. The addition of caching to Logger.isEnabledFor() by the fix for bpo-30962, 78c18a9b9a1445f7c755929917a790ba02b4a5e0, means that direct changes to the level now leave the cache in a state inconsistent with the Logger - an extraordinarily difficult thing to debug. Make 'level' a property that invalidates the cache when set. This ensures that existing application code will continue to work as it did with previous versions of Python. --- Lib/logging/__init__.py | 12 ++++++++++-- Lib/test/test_logging.py | 7 +++++++ .../Library/2019-08-14-16-17-57.bpo-37857.Ganisd.rst | 2 ++ 3 files changed, 19 insertions(+), 2 deletions(-) create mode 100644 Misc/NEWS.d/next/Library/2019-08-14-16-17-57.bpo-37857.Ganisd.rst diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 62a87a71b1a3bd..b6680df8e41c67 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -1397,19 +1397,27 @@ def __init__(self, name, level=NOTSET): """ Filterer.__init__(self) self.name = name - self.level = _checkLevel(level) + self._level = _checkLevel(level) self.parent = None self.propagate = True self.handlers = [] self.disabled = False self._cache = {} + @property + def level(self): + return self._level + + @level.setter + def level(self, level): + self._level = level + self.manager._clear_cache() + def setLevel(self, level): """ Set the logging level of this logger. level must be an int or a str. """ self.level = _checkLevel(level) - self.manager._clear_cache() def debug(self, msg, *args, **kwargs): """ diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index dca744c59092f4..3a2a1652b96105 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -4906,6 +4906,13 @@ def test_caching(self): # Ensure logger2 uses parent logger's effective level self.assertFalse(logger2.isEnabledFor(logging.ERROR)) + # Ensure setting level directly still clears cache + self.assertEqual(logger2._cache, {logging.ERROR: False}) + logger2.level = logging.ERROR + self.assertEqual(logger2._cache, {}) + self.assertTrue(logger2.isEnabledFor(logging.ERROR)) + self.assertEqual(logger2._cache, {logging.ERROR: True}) + # Set level to NOTSET and ensure caches are empty logger2.setLevel(logging.NOTSET) self.assertEqual(logger2.getEffectiveLevel(), logging.CRITICAL) diff --git a/Misc/NEWS.d/next/Library/2019-08-14-16-17-57.bpo-37857.Ganisd.rst b/Misc/NEWS.d/next/Library/2019-08-14-16-17-57.bpo-37857.Ganisd.rst new file mode 100644 index 00000000000000..f7adb956b12ff0 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2019-08-14-16-17-57.bpo-37857.Ganisd.rst @@ -0,0 +1,2 @@ +Setting the ``level`` attribute of a ``logger.Logger`` (instead of calling +``setLevel()``) no longer causes cache inconsistency. From 19c42fbb3b5acfc6641f54207d7e95fe9778204f Mon Sep 17 00:00:00 2001 From: Zane Bitter Date: Fri, 20 Sep 2019 12:59:07 -0400 Subject: [PATCH 2/5] Always use Logger.setLevel() in the standard library Never set the level attribute directly. --- Lib/logging/config.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/Lib/logging/config.py b/Lib/logging/config.py index cfd93116eeddbd..eb8242be25a927 100644 --- a/Lib/logging/config.py +++ b/Lib/logging/config.py @@ -173,9 +173,10 @@ def _handle_existing_loggers(existing, child_loggers, disable_existing): for log in existing: logger = root.manager.loggerDict[log] if log in child_loggers: - logger.level = logging.NOTSET - logger.handlers = [] - logger.propagate = True + if not isinstance(logger, logging.PlaceHolder): + logger.setLevel(logging.NOTSET) + logger.handlers = [] + logger.propagate = True else: logger.disabled = disable_existing From 42b6c5dd4750244447150d74080c78b0420dc76e Mon Sep 17 00:00:00 2001 From: Zane Bitter Date: Fri, 20 Sep 2019 12:48:02 -0400 Subject: [PATCH 3/5] Use Logger.setLevel() in unit test teardown Don't try to set the level attribute directly; use the setLevel() method. --- Lib/test/test_logging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 3a2a1652b96105..cf7f61f7e49ed0 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -4315,7 +4315,7 @@ def cleanup(self): logging._handlers.clear() logging._handlers.update(self.saved_handlers) logging._handlerList[:] = self.saved_handler_list - logging.root.level = self.original_logging_level + logging.root.setLevel(self.original_logging_level) def test_no_kwargs(self): logging.basicConfig() From baad702c0bd6d205279f3bd1d9cb50bbd078238c Mon Sep 17 00:00:00 2001 From: Zane Bitter Date: Fri, 20 Sep 2019 10:27:43 -0400 Subject: [PATCH 4/5] Deprecate setting Logger.level directly The level attribute of a Logger instance should never be set directly; the setLevel() method should be used instead. Deprecate the setter to warn anyone with code doing it incorrectly to change it. --- Lib/logging/__init__.py | 8 +++++--- Lib/test/test_logging.py | 4 +++- .../next/Library/2019-09-20-12-25-33.bpo-37857.s-Emp8.rst | 2 ++ 3 files changed, 10 insertions(+), 4 deletions(-) create mode 100644 Misc/NEWS.d/next/Library/2019-09-20-12-25-33.bpo-37857.s-Emp8.rst diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index b6680df8e41c67..8a358b6f8f0751 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -1410,14 +1410,16 @@ def level(self): @level.setter def level(self, level): - self._level = level - self.manager._clear_cache() + warnings.warn("Use the setLevel() method to set the log level", + DeprecationWarning, stacklevel=2) + self.setLevel(level) def setLevel(self, level): """ Set the logging level of this logger. level must be an int or a str. """ - self.level = _checkLevel(level) + self._level = _checkLevel(level) + self.manager._clear_cache() def debug(self, msg, *args, **kwargs): """ diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index cf7f61f7e49ed0..1e38f7ecc802f1 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -4908,7 +4908,9 @@ def test_caching(self): # Ensure setting level directly still clears cache self.assertEqual(logger2._cache, {logging.ERROR: False}) - logger2.level = logging.ERROR + with warnings.catch_warnings(record=True) as w: + logger2.level = logging.ERROR + self.assertEqual(1, len(w)) self.assertEqual(logger2._cache, {}) self.assertTrue(logger2.isEnabledFor(logging.ERROR)) self.assertEqual(logger2._cache, {logging.ERROR: True}) diff --git a/Misc/NEWS.d/next/Library/2019-09-20-12-25-33.bpo-37857.s-Emp8.rst b/Misc/NEWS.d/next/Library/2019-09-20-12-25-33.bpo-37857.s-Emp8.rst new file mode 100644 index 00000000000000..c5c54f06d19c59 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2019-09-20-12-25-33.bpo-37857.s-Emp8.rst @@ -0,0 +1,2 @@ +Setting the ``level`` attribute of a ``logger.Logger`` is deprecated. The +log level should only ever be set using the ``setLevel()`` method. From 7b6e0cf3b42c8980fcf92fee5417a13fd3376674 Mon Sep 17 00:00:00 2001 From: Zane Bitter Date: Mon, 23 Sep 2019 12:43:58 -0400 Subject: [PATCH 5/5] Micro-optimise Logger.getEffectiveLevel() Although getEffectiveLevel() is only called from isEnabledFor() in the slow path when there is a cache miss, using the new _level attribute directly means that the change to make the level attribute a property is be completely performance neutral for the stdlib code itself. (User code accessing the level propertly directly will still be slightly slower.) --- Lib/logging/__init__.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 8a358b6f8f0751..b419a733116a0e 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -1681,8 +1681,8 @@ def getEffectiveLevel(self): """ logger = self while logger: - if logger.level: - return logger.level + if logger._level: + return logger._level logger = logger.parent return NOTSET