| msg283888 - (view) |
Author: Dan Passaro (daniel.passaro) |
Date: 2016-12-23 17:26 |
| If two formatters maintain the default implementation of Formatter.format(), but provide custom behavior for Formatter.formatException(), whichever formatException() is called first and returns something truthy is the only formatException() that is used. This is due to a misplaced check for a cached value. logging.Formatter.format() sets (maybe monkey-patches?) an exc_text attribute onto the record it receives, with a comment indicating it's to prevent needlessly re-formatting the exception. If this value is set, it avoids the call to formatException() and just returns the exc_text attribute. If this check for exc_text is moved to Formatter.formatException() instead, I am sure this behavior will be fixed. I.e. Formatter.formatException()'s first few lines turn into something like: if record.exc_text: return record.exc_text sio = cString.StringIO() # ... and so on (rest of current impl) This way the default implementation still caches, and subclass implementation changes still have an effect. The only problem here is this method has no access to the record object. It's not clear to me what is the best way to solve this. I don't have experience making changes to Python or projects of this size but these are my thoughts: * Since the formatException() API is public it shouldn't be changed (e.g. to add record) * Removing the caching might have a significant performance penalty for certain users, although I haven't really tested it * Users who care can copy format() source code into their subclasses and remove the caching code. Alternatively, a class-level flag can be added to determine whether the cache should be used. Documentation in formatException() is added to indicate this issue. This seems like a very poor solution to me. * Adding @functools.lru_cache() in front of the base implementation (after e.g. making it a staticmethod() or something like that) seems clean from a code POV but could negatively impact memory usage, and might also negatively impact CPU usage if the cache isn't effective. * Adding `self._record = record` to format(), before the call to formatException(), probably has the lowest performance impact and is the change I'd lean towards personally, but seems like bad coding practice. I've attached a script that demonstrates the buggy behavior. If someone can weigh in on what a good strategy is to resolve this issue I'd be glad to supply a patch. |
|
|
| msg283895 - (view) |
Author: Dan Passaro (daniel.passaro) |
Date: 2016-12-23 19:08 |
| Working around this issue can be done by overriding format() in subclasses like so: def format(self, record): record.exc_text = '' try: return super().format(record) finally: record.exc_text = '' |
|
|
| msg284035 - (view) |
Author: Vinay Sajip (vinay.sajip) *  |
Date: 2016-12-26 18:37 |
| I don't consider this a bug, as the logging documentation for the Handler.format() method states: "Note that the formatted exception information is cached in attribute exc_text. This is useful because the exception information can be pickled and sent across the wire, but you should be careful if you have more than one Formatter subclass which customizes the formatting of exception information. In this case, you will have to clear the cached value after a formatter has done its formatting, so that the next formatter to handle the event doesn’t use the cached value but recalculates it afresh." So, your suggested workaround is following the approach suggested in the documentation. We could change the implementation to allow a cache_exception_text attribute (defaulting to True, set in the Handler class), then it could be set to False for individual instances by application developers. This does introduce another attribute to the handler class, so this would have to be added in 3.7 and not in 3.6. I'm not sure it's worth making this change, because the use case for it is not that common. |
|
|
| msg284085 - (view) |
Author: Raymond Hettinger (rhettinger) * |
Date: 2016-12-27 11:33 |
| Can we close this? |
|
|
| msg284102 - (view) |
Author: Dan Passaro (daniel.passaro) |
Date: 2016-12-27 14:33 |
| If there's no interest in changing the behavior I'd at least suggest that this caching is mentioned in the docs for the formatException() method specifically, with some kind of attention-grabbing note. (Right now this behavior is only explained in the format() method's docs which, as you might be able to infer, I did not think to check.) |
|
|
| msg284104 - (view) |
Author: Vinay Sajip (vinay.sajip) * |
Date: 2016-12-27 14:47 |
| Perhaps I will try to make it even clearer, but to be fair, the format() documentation is just a few paragraphs above the formatException() documentation. It's all in the section entitled "Formatter Objects", and it's IMO reasonable to expect the whole reasonably short section to be scanned before going to the trouble of raising an issue. |
|
|
| msg374062 - (view) |
Author: Matthew Davis (matt-davis) |
Date: 2020-07-21 10:39 |
| The documentation says "you will have to clear the cached value" What does that mean? How do I clear the cached value? Is there a flush function somewhere? Do I `del` the attribute? Set the attribute to None? The documentation as it stands today does not provide enough detail about this workaround. |
|
|