logging in 3.7 behaves different due to caching

[thomaswaldmann]

BPO	34269
Nosy	@vsajip, @pitrou, @ThomasWaldmann, @tirkarthi
Files	bpo34269.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 = None
closed_at = <Date 2018-08-01.05:01:55.033>
created_at = <Date 2018-07-29.09:03:56.221>
labels = ['3.7', '3.8', 'type-bug', 'library', 'invalid']
title = 'logging in 3.7 behaves different due to caching'
updated_at = <Date 2018-08-01.05:01:55.031>
user = 'https://github.com/ThomasWaldmann'

bugs.python.org fields:

activity = <Date 2018-08-01.05:01:55.031>
actor = 'vinay.sajip'
assignee = 'none'
closed = True
closed_date = <Date 2018-08-01.05:01:55.033>
closer = 'vinay.sajip'
components = ['Library (Lib)']
creation = <Date 2018-07-29.09:03:56.221>
creator = 'Thomas.Waldmann'
dependencies = []
files = ['47721']
hgrepos = []
issue_num = 34269
keywords = []
message_count = 7.0
messages = ['322617', '322634', '322753', '322790', '322797', '322806', '322840']
nosy_count = 4.0
nosy_names = ['vinay.sajip', 'pitrou', 'Thomas.Waldmann', 'xtreak']
pr_nums = []
priority = 'normal'
resolution = 'not a bug'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue34269'
versions = ['Python 3.7', 'Python 3.8']

[thomaswaldmann]

When running the borgbackup tests on 3.7.0, quite some tests will be broken because expected log output is not emitted.

I traced this down up the point when I noticed that reverting the caching feature change of isEnabledFor method in Logger makes the tests work on 3.7.

I reviewed the logging code and the caching change, but could not easily find what is broken. There is of course some suspicion that cache invalidation might be the issue (it is present, but maybe it does not cover all the cases).

See there for more info:
borgbackup/borg#3805

So, I suggest to first revert the caching feature change so we get a fixed logging in 3.7.1 and then to retry to add caching.

Note: I'm at EuroPython sprints today at the borgbackup table.

[thomaswaldmann]

borgbackup/borg#3998

Looks like this fix to our test tearDown method makes the tests work again.

If one looks at what this dirty/problematic hack was done, it might be because of a missing logging reset functionality?

[tirkarthi]

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() (

cpython/Lib/logging/__init__.py

Line 1265 in 9c18b1a

for logger in self.loggerDict.values():

) 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 bpo-34269.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 bpo-34269.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 bpo-34269.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 bpo-34269.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 bpo-34269.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

[vsajip]

Well, loggerDict is an internal implementation detail which shouldn't be directly called by the code in borgbackup. Hence I'm not sure you can call it a bug. When messing around with internals of objects, caveats apply.

Note that loggerDict isn't mentioned in the documentation: this is deliberate.

[tirkarthi]

Okay, I did some code search on GitHub for logging.Logger.manager.loggerDict.clear() (https://github.com/search?q=logging.Logger.manager.loggerDict.clear%28%29&type=Code) and there was some code in the test_logging where it was used in tearDown and setUp so I thought it's a public function. My bad on not reading the docs. I agree that it's not a bug if it's an undocumented internal implementation related change that one should not rely upon.

Thanks

[thomaswaldmann]

I agree that we should not dig that deep into logging internals and clear that dict from borg code.

But, seems like one has no public api to reinitialize logging to a like-fresh state, right? So maybe THAT is the real problem.

Add some .reset() method to do that?

BTW, removing that .clear() from our code made our tests work again. I am not sure why that was added in the first place as I could not find regressions after removing it.

[vsajip]

But, seems like one has no public api to reinitialize logging to a like-fresh state

For the use case of testing, you could use a context manager approach as described here in the logging cookbook:

https://docs.python.org/3/howto/logging-cookbook.html#using-a-context-manager-for-selective-logging

The approach outlined can be built on to add more convenience according to the specifics of your use case.

In this way, you can restore logging to "the state in which you found it" which is a potentially more useful thing than just clearing out everything.