Author daniel.passaro
Recipients daniel.passaro
Date 2016-12-23.17:26:55
SpamBayes Score -1.0
Marked as misclassified Yes
Message-id <1482514016.63.0.534341960628.issue29056@psf.upfronthosting.co.za>
In-reply-to
Content
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.
History
Date User Action Args
2016-12-23 17:26:56daniel.passarosetrecipients: + daniel.passaro
2016-12-23 17:26:56daniel.passarosetmessageid: <1482514016.63.0.534341960628.issue29056@psf.upfronthosting.co.za>
2016-12-23 17:26:56daniel.passarolinkissue29056 messages
2016-12-23 17:26:55daniel.passarocreate