From 26a8efc340a000193f19a63c61e45977aaaee4ea Mon Sep 17 00:00:00 2001 From: Avram Lubkin Date: Tue, 18 Jul 2017 16:06:26 -0400 Subject: [PATCH 1/7] Add caching to Logger.isEnabledFor() --- Lib/logging/__init__.py | 26 +++++++++++++++++++++++--- 1 file changed, 23 insertions(+), 3 deletions(-) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 64e24eef50e75a..8f13d7a3c6d3e6 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -1244,6 +1244,17 @@ def _fixupChildren(self, ph, alogger): alogger.parent = c.parent c.parent = alogger + def _clear_cache(self): + """ + Clear the cache for all loggers in loggerDict + Called when level changes are made + """ + + _acquireLock() + for logger in self.loggerDict.values(): + logger._cache.clear() + _releaseLock() + #--------------------------------------------------------------------------- # Logger classes and functions #--------------------------------------------------------------------------- @@ -1274,12 +1285,14 @@ def __init__(self, name, level=NOTSET): self.propagate = True self.handlers = [] self.disabled = False + self._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): """ @@ -1543,9 +1556,15 @@ def isEnabledFor(self, level): """ Is this logger enabled for level 'level'? """ - if self.manager.disable >= level: - return False - return level >= self.getEffectiveLevel() + if level not in self._cache: + _acquireLock() + if self.manager.disable >= level: + self._cache[level] = False + else: + self._cache[level] = level >= self.getEffectiveLevel() + _releaseLock() + + return self._cache[level] def getChild(self, suffix): """ @@ -1910,6 +1929,7 @@ def disable(level=CRITICAL): Disable all logging calls of severity 'level' and below. """ root.manager.disable = level + root.manager._clear_cache() def shutdown(handlerList=_handlerList): """ From aeec4d92165a92e5c72e3b5d1114f85aed0278a8 Mon Sep 17 00:00:00 2001 From: Avram Lubkin Date: Tue, 18 Jul 2017 16:58:48 -0400 Subject: [PATCH 2/7] Fix bugs in proposed caching mechanism --- Lib/logging/__init__.py | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 8f13d7a3c6d3e6..ac4360ba7a802d 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -1252,7 +1252,8 @@ def _clear_cache(self): _acquireLock() for logger in self.loggerDict.values(): - logger._cache.clear() + if isinstance(logger, Logger): + logger._cache.clear() _releaseLock() #--------------------------------------------------------------------------- @@ -1556,7 +1557,9 @@ def isEnabledFor(self, level): """ Is this logger enabled for level 'level'? """ - if level not in self._cache: + try: + return self._cache[level] + except KeyError: _acquireLock() if self.manager.disable >= level: self._cache[level] = False @@ -1564,7 +1567,7 @@ def isEnabledFor(self, level): self._cache[level] = level >= self.getEffectiveLevel() _releaseLock() - return self._cache[level] + return self._cache[level] def getChild(self, suffix): """ From 7deaaab25ed8e73692eff619caa1798883840682 Mon Sep 17 00:00:00 2001 From: Avram Lubkin Date: Tue, 18 Jul 2017 17:14:36 -0400 Subject: [PATCH 3/7] Save newly cached result to local variable to avoid race condition --- Lib/logging/__init__.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index ac4360ba7a802d..8a57b0be584d91 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -1562,12 +1562,12 @@ def isEnabledFor(self, level): except KeyError: _acquireLock() if self.manager.disable >= level: - self._cache[level] = False + is_enabled = self._cache[level] = False else: - self._cache[level] = level >= self.getEffectiveLevel() + is_enabled = self._cache[level] = level >= self.getEffectiveLevel() _releaseLock() - return self._cache[level] + return is_enabled def getChild(self, suffix): """ From f3b23adf96823cf50c0f9025c72430a016a3152c Mon Sep 17 00:00:00 2001 From: Avram Lubkin Date: Tue, 18 Jul 2017 20:43:44 -0400 Subject: [PATCH 4/7] Missing clearing of root logger cache --- Lib/logging/__init__.py | 1 + 1 file changed, 1 insertion(+) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 8a57b0be584d91..f9bfb79ae66b80 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -1254,6 +1254,7 @@ def _clear_cache(self): for logger in self.loggerDict.values(): if isinstance(logger, Logger): logger._cache.clear() + self.root._cache.clear() _releaseLock() #--------------------------------------------------------------------------- From d10e0e2ef0e14c19e098883946ce630e3ea4b978 Mon Sep 17 00:00:00 2001 From: Avram Lubkin Date: Fri, 28 Jul 2017 08:57:42 -0400 Subject: [PATCH 5/7] Add test for log caching --- Lib/test/test_logging.py | 23 +++++++++++++++++++++++ 1 file changed, 23 insertions(+) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 880f4e89fb03b5..470a573f0e30b8 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -4406,6 +4406,29 @@ def test_basic(self): self.assertTrue(found, msg=msg) +class CachingTest(BaseTest): + def test_caching(self): + root = self.root_logger + level1 = logging.getLogger("abc") + level2 = logging.getLogger("abc.def") + + root.setLevel(logging.ERROR) + self.assertEqual(level2._cache, {}) # Cache is empty + + self.assertTrue(level2.isEnabledFor(logging.ERROR)) + self.assertEqual(level2._cache, {logging.ERROR: True}) # Cache is populated + self.assertEqual(root._cache, {}) # Root cache is empty + self.assertTrue(level2.isEnabledFor(logging.ERROR)) + + level1.setLevel(logging.CRITICAL) + self.assertEqual(level2._cache, {}) # Cache is empty + self.assertEqual(root._cache, {}) # Root cache is empty + + self.assertFalse(level2.isEnabledFor(logging.ERROR)) + self.assertTrue(root.isEnabledFor(logging.ERROR)) + self.assertEqual(root._cache, {logging.ERROR: True}) # Root cache is populated + + class MiscTestCase(unittest.TestCase): def test__all__(self): blacklist = {'logThreads', 'logMultiprocessing', From d6d28ec484ab06c31f89402876a98866642e68fd Mon Sep 17 00:00:00 2001 From: Avram Lubkin Date: Fri, 28 Jul 2017 12:08:48 -0400 Subject: [PATCH 6/7] Update log caching tests --- Lib/test/test_logging.py | 79 ++++++++++++++++++++++++++++------------ 1 file changed, 56 insertions(+), 23 deletions(-) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 470a573f0e30b8..008c59f8a13293 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -4094,6 +4094,62 @@ def test_pickling(self): unpickled = pickle.loads(s) self.assertIs(unpickled, logger) + def test_caching(self): + root = self.root_logger + logger1 = logging.getLogger("abc") + logger2 = logging.getLogger("abc.def") + + # Set root logger level and ensure cache is empty + root.setLevel(logging.ERROR) + self.assertEqual(logger2.getEffectiveLevel(), logging.ERROR) + self.assertEqual(logger2._cache, {}) + + # Ensure cache is populated and calls are consistent + self.assertTrue(logger2.isEnabledFor(logging.ERROR)) + self.assertFalse(logger2.isEnabledFor(logging.DEBUG)) + self.assertEqual(logger2._cache, {logging.ERROR: True, logging.DEBUG: False}) + self.assertEqual(root._cache, {}) + self.assertTrue(logger2.isEnabledFor(logging.ERROR)) + + # Ensure root cache gets populated + self.assertEqual(root._cache, {}) + self.assertTrue(root.isEnabledFor(logging.ERROR)) + self.assertEqual(root._cache, {logging.ERROR: True}) + + # Set parent logger level and ensure caches are emptied + logger1.setLevel(logging.CRITICAL) + self.assertEqual(logger2.getEffectiveLevel(), logging.CRITICAL) + self.assertEqual(logger2._cache, {}) + + # Ensure logger2 uses parent logger's effective level + self.assertFalse(logger2.isEnabledFor(logging.ERROR)) + + # Set level to NOTSET and ensure caches are empty + logger2.setLevel(logging.NOTSET) + self.assertEqual(logger2.getEffectiveLevel(), logging.CRITICAL) + self.assertEqual(logger2._cache, {}) + self.assertEqual(logger1._cache, {}) + self.assertEqual(root._cache, {}) + + # Verify logger2 follows parent and not root + self.assertFalse(logger2.isEnabledFor(logging.ERROR)) + self.assertTrue(logger2.isEnabledFor(logging.CRITICAL)) + self.assertFalse(logger1.isEnabledFor(logging.ERROR)) + self.assertTrue(logger1.isEnabledFor(logging.CRITICAL)) + self.assertTrue(root.isEnabledFor(logging.ERROR)) + + # Disable logging in manager and ensure caches are clear + logging.disable() + self.assertEqual(logger2.getEffectiveLevel(), logging.CRITICAL) + self.assertEqual(logger2._cache, {}) + self.assertEqual(logger1._cache, {}) + self.assertEqual(root._cache, {}) + + # Ensure no loggers are enabled + self.assertFalse(logger1.isEnabledFor(logging.CRITICAL)) + self.assertFalse(logger2.isEnabledFor(logging.CRITICAL)) + self.assertFalse(root.isEnabledFor(logging.CRITICAL)) + class BaseFileTest(BaseTest): "Base class for handler tests that write log files" @@ -4406,29 +4462,6 @@ def test_basic(self): self.assertTrue(found, msg=msg) -class CachingTest(BaseTest): - def test_caching(self): - root = self.root_logger - level1 = logging.getLogger("abc") - level2 = logging.getLogger("abc.def") - - root.setLevel(logging.ERROR) - self.assertEqual(level2._cache, {}) # Cache is empty - - self.assertTrue(level2.isEnabledFor(logging.ERROR)) - self.assertEqual(level2._cache, {logging.ERROR: True}) # Cache is populated - self.assertEqual(root._cache, {}) # Root cache is empty - self.assertTrue(level2.isEnabledFor(logging.ERROR)) - - level1.setLevel(logging.CRITICAL) - self.assertEqual(level2._cache, {}) # Cache is empty - self.assertEqual(root._cache, {}) # Root cache is empty - - self.assertFalse(level2.isEnabledFor(logging.ERROR)) - self.assertTrue(root.isEnabledFor(logging.ERROR)) - self.assertEqual(root._cache, {logging.ERROR: True}) # Root cache is populated - - class MiscTestCase(unittest.TestCase): def test__all__(self): blacklist = {'logThreads', 'logMultiprocessing', From 11fee13d20a7e20fa086a01457447acc7fbf06db Mon Sep 17 00:00:00 2001 From: Avram Lubkin Date: Fri, 28 Jul 2017 12:30:01 -0400 Subject: [PATCH 7/7] reset manager.disable on log test teardown --- Lib/test/test_logging.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 008c59f8a13293..88845629614a3e 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -135,7 +135,9 @@ def tearDown(self): logging._handlers.clear() logging._handlers.update(self.saved_handlers) logging._handlerList[:] = self.saved_handler_list - loggerDict = logging.getLogger().manager.loggerDict + manager = logging.getLogger().manager + manager.disable = 0 + loggerDict = manager.loggerDict loggerDict.clear() loggerDict.update(self.saved_loggers) logger_states = self.logger_states