[issue21912] Deferred logging may use outdated references
New submission from Jonas Diemer:
I was having trouble with the logging module under Jython: I was getting
seemingly sporadic wierd null pointer exceptions in the logging code.
The problem seemed to be related to references that were passed to the logger,
e.g.
logger.debug("My object: %s", myObject)
It seems that logging defers the actual string formatting (maybe only when
logging to files). By the time the string is formatted, the reference to the
object may no longer be valid. In my case, myObject was a reference to a
Java-class that had been invalidated.
Initially, I thought this was only a Java issue. But it seems like this could
be an issue with pure Python scripts as well. E.g., what happens if the object
behind myObject is changed after the call to debug(), but before the actual log
message is formatted?
--
components: Library (Lib)
messages: 222171
nosy: Jonas.Diemer
priority: normal
severity: normal
status: open
title: Deferred logging may use outdated references
type: behavior
versions: Python 2.7
___
Python tracker
<http://bugs.python.org/issue21912>
___
___
Python-bugs-list mailing list
Unsubscribe:
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
[issue21912] Deferred logging may use outdated references
Jonas Diemer added the comment: Find attached a demo script that causes the erratic behavior in regular Python (2.7.5 on Windows). The log file contains two lines, both show the new name of the object, although the first debug() was called befor the name change. I think this problem could be avoided if the message was formatted earlier (i.e. synchronous to the debug() call). -- Added file: http://bugs.python.org/file35839/testlogging.py ___ Python tracker <http://bugs.python.org/issue21912> ___ ___ Python-bugs-list mailing list Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
[issue21912] Deferred logging may use outdated references
Jonas Diemer added the comment: I see your point. The decision whether to log or not is actually made synchronously to the actual logging call, as far as I can tell (i.e. "if self.isEnabledFor..." is checked directly in debug()). So at this place, the formatting could already happen. I don't see a reason to defer the formatting to the actual output of the messages (other than the current implementation of logging). -- ___ Python tracker <http://bugs.python.org/issue21912> ___ ___ Python-bugs-list mailing list Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
[issue21912] Deferred logging may use outdated references
Jonas Diemer added the comment: Thanks for the explanation. Throughput is a valid reason. Your workaround does of course work, but it means that the string formatting is always done, even if the message is filtered out. Is this delayed logging behavior documented in any way (maybe I have overread it)? I am just trying to help people who may stumble upon this, as it cost me quite some time to figure out the resulting weird errors (especially in conjunction with Jython, which doesn't make debugging easier). By the way, my workaround is a little different: I "forked" logging and am catching exceptions during the string formatting. This way, I can at least print out the affected logging calls for me to fix. -- ___ Python tracker <http://bugs.python.org/issue21912> ___ ___ Python-bugs-list mailing list Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
[issue21912] Deferred logging may use outdated references
Jonas Diemer added the comment: 2014-07-03 16:42 GMT+02:00 Vinay Sajip : > > I "forked" logging and am catching exceptions during the string > formatting > > That might work with Jython and invalidated objects, but in the case of > e.g. CPython (where the objects can't be invalidated/garbage collected as > there is a reference to them in the LogRecord for the logged event) I don't > see how that approach is generally applicable. True, it only helps for Jython. Still, I suggest adding this behavior to the documentation. -- ___ Python tracker <http://bugs.python.org/issue21912> ___ ___ Python-bugs-list mailing list Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
