[issue44924] logging.handlers.QueueHandler does not maintain the exc_text

[Jack_B]

Jack_B <barraclough.jack at gmail.com> added the comment:

This also tripped me up recently.  More broadly, I assumed that handlers downstream of the QueueHandler/QueueListener would get complete log records. Having looked at it, I can see they need to be pickled, and that means stripping some information. But like Mikael, I found the current behaviour a bit confusing.

The solution I am using is to override logging.Formatter.format and QueueHandler.Prepare like so:

class _OptionalExcFormatter(logging.Formatter):
    def format(self, record, with_exc=True, with_stack=True):
        """
        Format the specified record as text.

        Same as superclass except it only adds the exc_info and stack_info if
        the corresponding arguments are True.
        """
        record.message = record.getMessage()
        if self.usesTime():
            record.asctime = self.formatTime(record, self.datefmt)
        s = self.formatMessage(record)
        if record.exc_info and with_exc:
            # Cache the traceback text to avoid converting it multiple times
            # (it's constant anyway)
            if not record.exc_text:
                record.exc_text = self.formatException(record.exc_info)
        if record.exc_text and with_exc:
            if s[-1:] != "\n":
                s = s + "\n"
            s = s + record.exc_text
        if record.stack_info and with_stack:
            if s[-1:] != "\n":
                s = s + "\n"
            s = s + self.formatStack(record.stack_info)
        return s

class _QueueHandlerExc(QueueHandler):
    def prepare(self, record):
        # bpo-35726: make copy of record to avoid affecting other handlers in the chain.
        record = copy.copy(record)
        # Get a formatter. It must support the with_exc and with_stack args to f.format
        if self.formatter is None:
            f = _OptionalExcFormatter()
        else:
            f = self.formatter
        # Merge args into message and strip them as they may not be pickleable
        msg = f.format(record, with_exc=False, with_stack=False)
        record.message = msg
        record.msg = msg
        record.args = None
        # Convert exc_info into exc_text and strip it as it may not be pickleable
        if record.exc_info is not None:
            record.exc_text = f.formatException(record.exc_info)
        record.exc_info = None
        return record

Pros:
 - The record feels "less mangled"
 - It does not require another formatter to have already populated exc_text, and allows the use of a specific formatter to do so.
 - Having the message and exc_text separate seems logical, and allows downstream handlers/formatters to treat them differently.
 - logging.Formatter can get the changes above in a back-compatible way
Cons:
 - exc_text now contains the stack trace as well as the usual exc_info, which is a little odd, but it still seems to be a better place for it than the message.
 - If QueueHandler gets the changes above, it will break code where QueueHandler is used with a custom Formatter which overrides Formatter.format. This is probably not OK. 

I think the changes to logging.Formatter might also be useful elsewhere, as it would enable you to do:
class _NoStackFormatter(logging.Formatter):
    def format(self, record):
        return super().format(record, with_exc=True, with_stack=False)
to have a formatter which omits stack traces.

----------
nosy: +Jack_B

_______________________________________
Python tracker <report at bugs.python.org>
<https://bugs.python.org/issue44924>
_______________________________________