This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

Author Jack_B
Recipients Jack_B, Miksus, vinay.sajip, zach.ware
Date 2021-11-13.15:51:10
SpamBayes Score -1.0
Marked as misclassified Yes
Message-id <1636818671.21.0.782364096479.issue44924@roundup.psfhosted.org>
In-reply-to
Content
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.
History
Date User Action Args
2021-11-13 15:51:11Jack_Bsetrecipients: + Jack_B, vinay.sajip, zach.ware, Miksus
2021-11-13 15:51:11Jack_Bsetmessageid: <1636818671.21.0.782364096479.issue44924@roundup.psfhosted.org>
2021-11-13 15:51:11Jack_Blinkissue44924 messages
2021-11-13 15:51:10Jack_Bcreate