classification
Title: Logging cache not cleared properly when setting level
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.9, Python 3.8, Python 3.7
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: David Wang, vinay.sajip, xtreak
Priority: normal Keywords: patch

Created on 2019-06-12 21:48 by David Wang, last changed 2019-06-19 16:06 by vinay.sajip. This issue is now closed.

Files
File name Uploaded Description Edit
test.py David Wang, 2019-06-12 21:48
Pull Requests
URL Status Linked Edit
PR 14229 merged vinay.sajip, 2019-06-19 10:26
PR 14230 merged miss-islington, 2019-06-19 10:47
PR 14231 merged miss-islington, 2019-06-19 10:47
Messages (6)
msg345414 - (view) Author: David Wang (David Wang) Date: 2019-06-12 21:48
If you call setLevel() on a subclass of logging.Logger, it does not reset the cache for that logger. This mean that if you make some logging calls, then call setLevel(), the logger still acts like it still has its old level. See the attached python file for a reference.

Currently, the user has to call logger._cache.clear() to manually clear the cache after calling setLevel(). To fix this in Python, we would have to change Logger.setLevel() in /logging/__init__.py to have the following code
```
self.level = _checkLevel(level)
self.manager._clear_cache()
self._cache.clear()
```

Note the following:
- I made sure the subclass has a handler attached so setLevel() should work
- This bug does not occur if you use logging.getLogger(). This is because logging.getLogger() returns the root logger, and the cache clear specifically targets the root logger's cache to be cleared. It occurs when the logger is specifically subclassed from logging.getLoggerClass()
- The cache was added in Python 3.7, so this bug is specific to this version of python.
msg345490 - (view) Author: Karthikeyan Singaravelan (xtreak) * (Python committer) Date: 2019-06-13 10:01
A unittest patch for this issue. This occurs in master and 3.8 too.

diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py
index 50148dc2f2..30fd9ee37a 100644
--- a/Lib/test/test_logging.py
+++ b/Lib/test/test_logging.py
@@ -4172,6 +4172,27 @@ class ModuleLevelMiscTest(BaseTest):
         logging.setLoggerClass(logging.Logger)
         self.assertEqual(logging.getLoggerClass(), logging.Logger)

+    def test_subclass_logger_cache(self):
+
+        class MyLogger(logging.getLoggerClass()):
+            pass
+
+        logger = MyLogger('test')
+        stream = io.StringIO()
+        h = logging.StreamHandler(stream)
+        logger.addHandler(h)
+
+        logger.setLevel(logging.DEBUG)
+        logger.debug("hello")
+        self.assertEqual(stream.getvalue().strip(), "hello")
+
+        stream.truncate(0)
+        stream.seek(0)
+
+        logger.setLevel(logging.INFO)
+        logger.debug("hello")
+        self.assertEqual(stream.getvalue(), "")
+
     @support.requires_type_collecting
     def test_logging_at_shutdown(self):
         # Issue #20037
msg346036 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2019-06-19 10:12
This is not actually a bug, but happens because the logger is instantiated directly, rather than through logging.getLogger(...). Because of the direct instantiation, the logger cache isn't tracked via setLevel() - because the logger doesn't end up in logging.manager.loggerDict.

However, I will incorporate Karthikeyan's test (modified to avoid direct instantiation), and update the documentation to strengthen the information to avoid direct instantiation of loggers.
msg346037 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2019-06-19 10:47
New changeset 015000165373f8db263ef5bc682f02d74e5782ac by Vinay Sajip in branch 'master':
bpo-37258: Not a bug, but added a unit test and updated documentation. (GH-14229)
https://github.com/python/cpython/commit/015000165373f8db263ef5bc682f02d74e5782ac
msg346046 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2019-06-19 13:46
New changeset 9eb4b2c8a3387ea901dad793e8d5586880a5968e by Vinay Sajip (Miss Islington (bot)) in branch '3.7':
bpo-37258: Not a bug, but added a unit test and updated documentation. (GH-14229) (GH-14231)
https://github.com/python/cpython/commit/9eb4b2c8a3387ea901dad793e8d5586880a5968e
msg346047 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2019-06-19 13:46
New changeset 95ff622028b4f5d2eefbff557eadbb08fbcd42b1 by Vinay Sajip (Miss Islington (bot)) in branch '3.8':
bpo-37258: Not a bug, but added a unit test and updated documentation. (GH-14229) (GH-14230)
https://github.com/python/cpython/commit/95ff622028b4f5d2eefbff557eadbb08fbcd42b1
History
Date User Action Args
2019-06-19 16:06:11vinay.sajipsetstage: resolved
2019-06-19 16:05:48vinay.sajipsetstage: resolved -> (no value)
2019-06-19 13:47:45vinay.sajipsetstatus: open -> closed
stage: patch review -> resolved
2019-06-19 13:46:59vinay.sajipsetmessages: + msg346047
2019-06-19 13:46:43vinay.sajipsetmessages: + msg346046
2019-06-19 10:47:33miss-islingtonsetpull_requests: + pull_request14067
2019-06-19 10:47:20miss-islingtonsetpull_requests: + pull_request14066
2019-06-19 10:47:17vinay.sajipsetmessages: + msg346037
2019-06-19 10:26:07vinay.sajipsetkeywords: + patch
stage: patch review
pull_requests: + pull_request14065
2019-06-19 10:12:42vinay.sajipsetresolution: not a bug
messages: + msg346036
2019-06-14 05:21:05rhettingersetassignee: vinay.sajip
2019-06-13 10:01:27xtreaksetnosy: + xtreak

messages: + msg345490
versions: + Python 3.8, Python 3.9
2019-06-13 00:33:50xtreaksetnosy: + vinay.sajip
2019-06-12 21:48:28David Wangcreate