classification
Title: Deferred logging may use outdated references
Type: behavior Stage:
Components: Library (Lib) Versions: Python 2.7
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: Jonas.Diemer, r.david.murray, vinay.sajip
Priority: normal Keywords:

Created on 2014-07-03 12:44 by Jonas.Diemer, last changed 2014-07-03 17:09 by vinay.sajip. This issue is now closed.

Files
File name Uploaded Description Edit
testlogging.py Jonas.Diemer, 2014-07-03 12:55 test script showing the issue
Messages (10)
msg222171 - (view) Author: Jonas Diemer (Jonas.Diemer) Date: 2014-07-03 12:44
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?
msg222172 - (view) Author: Jonas Diemer (Jonas.Diemer) Date: 2014-07-03 12:55
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).
msg222176 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2014-07-03 13:21
The whole point of the logging API is that the message is *not* formatted unless the message is actually emitted.  So this is just how logging works, not something that can be fixed, as far as I can see.
msg222177 - (view) Author: Jonas Diemer (Jonas.Diemer) Date: 2014-07-03 13:26
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).
msg222183 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2014-07-03 14:09
The decision as to whether or not to pass the message along to the next stage is made at numerous points in the pipeline.
msg222185 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2014-07-03 14:20
> I don't see a reason to defer the formatting to the actual output of the messages (other than the current implementation of logging).

The current implementation of logging is like that for a reason, even though you may not see it - it defers doing work until it is needed (which improves throughput). This idiom is hardly uncommon.

If you don't want to delay formatting until output, you can always do

logger.debug("My object: %s" % myObject)
msg222187 - (view) Author: Jonas Diemer (Jonas.Diemer) Date: 2014-07-03 14:33
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.
msg222189 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2014-07-03 14:42
> but it means that the string formatting is always done

Not if you use logger.isEnabledFor(level) as a guard to avoid unnecessary work :-)

> 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.
msg222194 - (view) Author: Jonas Diemer (Jonas.Diemer) Date: 2014-07-03 15:21
2014-07-03 16:42 GMT+02:00 Vinay Sajip <report@bugs.python.org>:

> > 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.
msg222201 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2014-07-03 17:09
> Still, I suggest adding this behavior to the documentation.

It is already in the documentation. For example,

https://docs.python.org/2/library/logging.html#logging.Formatter.format
https://docs.python.org/2/howto/logging.html#optimization

This behaviour has been in logging from the beginning. Generally, people have regarded it as desirable (when an opinion has been expressed).
History
Date User Action Args
2014-07-03 17:09:47vinay.sajipsetmessages: + msg222201
2014-07-03 15:21:52Jonas.Diemersetmessages: + msg222194
2014-07-03 14:42:31vinay.sajipsetmessages: + msg222189
2014-07-03 14:33:38Jonas.Diemersetmessages: + msg222187
2014-07-03 14:20:52vinay.sajipsetstatus: open -> closed
resolution: not a bug
messages: + msg222185
2014-07-03 14:09:05r.david.murraysetmessages: + msg222183
2014-07-03 13:26:11Jonas.Diemersetmessages: + msg222177
2014-07-03 13:21:47r.david.murraysetnosy: + r.david.murray
messages: + msg222176
2014-07-03 13:14:34zach.waresetnosy: + vinay.sajip
2014-07-03 12:55:28Jonas.Diemersetfiles: + testlogging.py

messages: + msg222172
2014-07-03 12:44:01Jonas.Diemercreate