[issue34269] logging in 3.7 behaves different due to caching

[Karthikeyan Singaravelan]

Karthikeyan Singaravelan <tir.karthi at gmail.com> added the comment:

I think I have found the bug. When we call setLevel then to clear the cache value of Logger objects  `logging.Logger.manager.loggerDict.values()` (https://github.com/python/cpython/blob/9c18b1ae527346bc178250ad1ca07bffdacde5dd/Lib/logging/__init__.py#L1265) is called but since somewhere you have called `logging.Logger.manager.loggerDict.clear()` before changing the level and hence it doesn't iterate through the dict to clear the logger object cache. This is not present in 3.6 since there is no Logger._cache and works fine.

Don't do logging.Logger.manager.loggerDict.clear() and you can see logging enabled for error as False because while doing setLevel we clear the cache of Logger objects of logging.Logger.manager.loggerDict.values()

➜  cpython git:(master) ✗ cat bpo34269.py
import sys
import logging

logger1 = logging.getLogger('abc')
logger2 = logging.getLogger('cde')

logger1.setLevel(logging.ERROR)
logger2.setLevel(logging.ERROR)

print("logging error : ", logger1.isEnabledFor(logging.ERROR))

print("logger dict : ", logging.Logger.manager.loggerDict)

print("Not clearing logging dict ")
# logging.Logger.manager.loggerDict.clear()
print("logger dict : ", logging.Logger.manager.loggerDict)
print("logging enabled for error : ", logger1.isEnabledFor(logging.ERROR))

if sys.version_info >= (3,7): # Print cache only for python 3.7 and above
    # Since we clear logging.Logger.manager.loggerDict.clear() the cache is not reset
    print("Cache ", logger1._cache)

print("Setting to critical")
logger1.setLevel(logging.CRITICAL)
if sys.version_info >= (3,7):
    print("Cache after setting to critical ", logger1._cache)
print("logging enabled for error : ", logger1.isEnabledFor(logging.ERROR))

➜  cpython git:(master) ✗ ./python.exe bpo34269.py
logging error :  True
logger dict :  {'abc': <Logger abc (ERROR)>, 'cde': <Logger cde (ERROR)>}
Not clearing logging dict
logger dict :  {'abc': <Logger abc (ERROR)>, 'cde': <Logger cde (ERROR)>}
logging enabled for error :  True
Cache  {40: True}
Setting to critical
Cache after setting to critical  {}
logging enabled for error :  False

call logging.Logger.manager.loggerDict.clear() and you can see logging enabled for error as True because while doing setLevel we clear the cache of Logger objects of logging.Logger.manager.loggerDict.values() will be empty.

➜  cpython git:(master) ✗ cat bpo34269.py
import sys
import logging

logger1 = logging.getLogger('abc')
logger2 = logging.getLogger('cde')

logger1.setLevel(logging.ERROR)
logger2.setLevel(logging.ERROR)

print("logging error : ", logger1.isEnabledFor(logging.ERROR))

print("logger dict : ", logging.Logger.manager.loggerDict)

print("clearing logging dict ")
logging.Logger.manager.loggerDict.clear()
print("logger dict : ", logging.Logger.manager.loggerDict)
print("logging enabled for error : ", logger1.isEnabledFor(logging.ERROR))

if sys.version_info >= (3,7):
    # Since we clear logging.Logger.manager.loggerDict.clear() the cache is not reset
    print("Cache ", logger1._cache)

print("Setting to critical")
logger1.setLevel(logging.CRITICAL)
if sys.version_info >= (3,7):
    print("Cache after setting to critical ", logger1._cache)
print("logging enabled for error : ", logger1.isEnabledFor(logging.ERROR))

➜  cpython git:(master) ✗ ./python.exe bpo34269.py
logging error :  True
logger dict :  {'abc': <Logger abc (ERROR)>, 'cde': <Logger cde (ERROR)>}
clearing logging dict
logger dict :  {}
logging enabled for error :  True
Cache  {40: True}
Setting to critical
Cache after setting to critical  {40: True} # Cache is not cleared due to logging.Logger.manager.loggerDict.clear()
logging enabled for error :  True # True not False

Above script on Python 3.6 there is no Logger._cache and hence there is no cache invalidation to be done though logging.Logger.manager.loggerDict.clear() is called.

➜  cpython git:(master) ✗ python3.6 bpo34269.py
logging error :  True
logger dict :  {'abc': <Logger abc (ERROR)>, 'cde': <Logger cde (ERROR)>}
clearing logging dict
logger dict :  {}
logging enabled for error :  True
Setting to critical
logging enabled for error :  False # False since there is no cache


I have attached the test file that reproduces this. I think this is a bug. I don't know how to fix it since we can restrict the user from calling `logging.Logger.manager.loggerDict.clear()` and depend on it for cache invalidation. Either this can be documented but I think there might be old code depending on this. I am adding original reviewers to see if they can add some thoughts on this. Feel free to unassign yourself. I will check for a fix for this in the meantime with the above test case so that it can make it to next Python 3.7 bug fix release. @Thomas.Waldmann for the moment I think from the above disabling the loggerDict.clear() call will make tests pass.

Thanks

----------
nosy: +pitrou, vinay.sajip, vstinner
Added file: https://bugs.python.org/file47721/bpo34269.py

_______________________________________
Python tracker <report at bugs.python.org>
<https://bugs.python.org/issue34269>
_______________________________________