Logging cache not cleared properly when setting level

[DavidWang]

BPO	37258
Nosy	@vsajip, @tirkarthi
PRs	bpo-37258: Not a bug, but added a unit test and updated documentation. #14229 [3.8] bpo-37258: Not a bug, but added a unit test and updated documentation. (GH-14229) #14230 [3.7] bpo-37258: Not a bug, but added a unit test and updated documentation. (GH-14229) #14231
Files	test.py

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = 'https://github.com/vsajip'
closed_at = <Date 2019-06-19.13:47:45.769>
created_at = <Date 2019-06-12.21:48:28.353>
labels = ['type-bug', '3.8', '3.9', 'invalid', '3.7', 'library']
title = 'Logging cache not cleared properly when setting level'
updated_at = <Date 2019-06-19.16:06:11.017>
user = 'https://bugs.python.org/DavidWang'

bugs.python.org fields:

activity = <Date 2019-06-19.16:06:11.017>
actor = 'vinay.sajip'
assignee = 'vinay.sajip'
closed = True
closed_date = <Date 2019-06-19.13:47:45.769>
closer = 'vinay.sajip'
components = ['Library (Lib)']
creation = <Date 2019-06-12.21:48:28.353>
creator = 'David Wang'
dependencies = []
files = ['48416']
hgrepos = []
issue_num = 37258
keywords = ['patch']
message_count = 6.0
messages = ['345414', '345490', '346036', '346037', '346046', '346047']
nosy_count = 3.0
nosy_names = ['vinay.sajip', 'xtreak', 'David Wang']
pr_nums = ['14229', '14230', '14231']
priority = 'normal'
resolution = 'not a bug'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue37258'
versions = ['Python 3.7', 'Python 3.8', 'Python 3.9']

[DavidWang]

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.

[tirkarthi]

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 bpo-20037

[vsajip]

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.

[vsajip]

New changeset 0150001 by Vinay Sajip in branch 'master':
bpo-37258: Not a bug, but added a unit test and updated documentation. (GH-14229)
0150001

[vsajip]

New changeset 9eb4b2c 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)
9eb4b2c

[vsajip]

New changeset 95ff622 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)
95ff622