This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: logging in 3.7 behaves different due to caching
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.8, Python 3.7
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: Thomas.Waldmann, pitrou, vinay.sajip, xtreak
Priority: normal Keywords:

Created on 2018-07-29 09:03 by Thomas.Waldmann, last changed 2022-04-11 14:59 by admin. This issue is now closed.

Files
File name Uploaded Description Edit
bpo34269.py xtreak, 2018-07-31 10:21
Messages (7)
msg322617 - (view) Author: Thomas Waldmann (Thomas.Waldmann) Date: 2018-07-29 09:03
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:
https://github.com/borgbackup/borg/issues/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.
msg322634 - (view) Author: Thomas Waldmann (Thomas.Waldmann) Date: 2018-07-29 12:50
https://github.com/borgbackup/borg/pull/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?
msg322753 - (view) Author: Karthikeyan Singaravelan (xtreak) * (Python committer) Date: 2018-07-31 10:21
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
msg322790 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-07-31 15:42
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.
msg322797 - (view) Author: Karthikeyan Singaravelan (xtreak) * (Python committer) Date: 2018-07-31 16:14
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
msg322806 - (view) Author: Thomas Waldmann (Thomas.Waldmann) Date: 2018-07-31 19:10
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.
msg322840 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-08-01 05:01
> 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.
History
Date User Action Args
2022-04-11 14:59:04adminsetgithub: 78450
2018-08-01 05:01:55vinay.sajipsetstatus: open -> closed
resolution: not a bug
messages: + msg322840

stage: resolved
2018-07-31 19:10:02Thomas.Waldmannsetmessages: + msg322806
2018-07-31 16:15:07vstinnersetnosy: - vstinner
2018-07-31 16:14:47xtreaksetmessages: + msg322797
2018-07-31 15:42:57vinay.sajipsetmessages: + msg322790
2018-07-31 10:21:47xtreaksetversions: + Python 3.8
2018-07-31 10:21:16xtreaksetfiles: + bpo34269.py
nosy: + vinay.sajip, pitrou, vstinner
messages: + msg322753

2018-07-29 13:14:44xtreaksetnosy: + xtreak
2018-07-29 12:50:45Thomas.Waldmannsetmessages: + msg322634
2018-07-29 09:07:11Thomas.Waldmannsettype: behavior
components: + Library (Lib)
2018-07-29 09:03:56Thomas.Waldmanncreate