[issue21912] Deferred logging may use outdated references

2014-07-03 Thread Jonas Diemer

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



[issue21912] Deferred logging may use outdated references

2014-07-03 Thread Jonas Diemer

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

2014-07-03 Thread Jonas Diemer

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

2014-07-03 Thread Jonas Diemer

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

2014-07-03 Thread Jonas Diemer

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