classification
Title: logging.Formatter doesn't respect more than one formatException()
Type: behavior Stage:
Components: Versions: Python 3.6
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: daniel.passaro, matt-davis, rhettinger, vinay.sajip
Priority: normal Keywords:

Created on 2016-12-23 17:26 by daniel.passaro, last changed 2020-07-21 10:39 by matt-davis. This issue is now closed.

Files
File name Uploaded Description Edit
logging_formatter_exc_bug.py daniel.passaro, 2016-12-23 17:26 Showcase of buggy caching behavior in Formatter.format()
Messages (7)
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) * (Python committer) 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) * (Python committer) 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) * (Python committer) 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.
History
Date User Action Args
2020-07-21 10:39:11matt-davissetnosy: + matt-davis
messages: + msg374062
2016-12-27 14:47:41vinay.sajipsetmessages: + msg284104
2016-12-27 14:33:49daniel.passarosetmessages: + msg284102
2016-12-27 13:14:30vinay.sajipsetstatus: open -> closed
2016-12-27 11:33:38rhettingersetstatus: pending -> open
nosy: + rhettinger
messages: + msg284085

2016-12-26 18:37:35vinay.sajipsetstatus: open -> pending
resolution: not a bug
messages: + msg284035
2016-12-26 15:32:30berker.peksagsetnosy: + vinay.sajip
2016-12-23 19:08:59daniel.passarosetmessages: + msg283895
2016-12-23 17:26:56daniel.passarocreate