logging.handlers.QueueHandler does not maintain the exc_text

[Miksus]

BPO	44924
Nosy	@vsajip, @zware, @Miksus

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = None
created_at = <Date 2021-08-16.10:11:14.110>
labels = ['type-bug', 'library', '3.9', '3.10', '3.11']
title = 'logging.handlers.QueueHandler does not maintain the exc_text'
updated_at = <Date 2021-11-13.16:24:58.477>
user = 'https://github.com/Miksus'

bugs.python.org fields:

activity = <Date 2021-11-13.16:24:58.477>
actor = 'Jack_B'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Library (Lib)']
creation = <Date 2021-08-16.10:11:14.110>
creator = 'Miksus'
dependencies = []
files = []
hgrepos = []
issue_num = 44924
keywords = []
message_count = 8.0
messages = ['399642', '399643', '399674', '399679', '399716', '406283', '406285', '406286']
nosy_count = 4.0
nosy_names = ['vinay.sajip', 'zach.ware', 'Miksus', 'Jack_B']
pr_nums = []
priority = 'normal'
resolution = None
stage = None
status = 'open'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue44924'
versions = ['Python 3.9', 'Python 3.10', 'Python 3.11']

[Miksus]

The reason why logging.handlers.QueueHandler does not maintain exc_text is obvious:

    def prepare(self, record):
        ...
        record = copy.copy(record)
        record.message = msg
        record.msg = msg
        record.args = None
        record.exc_info = None
        record.exc_text = None
        return record

The record.exc_text is set to None. The reason for this is to prevent the exception text showing up multiple times to the message. See https://bugs.python.org/issue34334.

However, there are a couple of situations this may cause a problem. First, it's not currently possible to format the exception of the record in a handler on the other side of the queue. Second, it's not possible to let the handler on the other side of the queue utilize exc_text. The default handlers do not behave in such a way but one could prefer to create their own handler that does so, such as log the records to a database with a column for the exception text.

Possible solution:
Don't override the record.msg and don't set the record.exc_text to None. I think it could be done simply:

    def prepare(self, record):
        ...
        record = copy.copy(record)
        record.message = msg
        # record.msg = msg
        record.args = None
        record.exc_info = None
        # record.exc_text = None
        return record

This way one can format the record later again without multiple exception text showing up in the message. Doing so will fail the test 'test_logging.QueueHandlerTest.test_formatting' as this tests the record.msg is the same as record.message. This may cause issues if someone relies on record.msg. On the other hand, now other formatters and handlers down the line could use the exc_text attribute. I'm not sure if this is too breaking change or not.

The failing test:

    def test_formatting(self):
        msg = self.next_message()
        levelname = logging.getLevelName(logging.WARNING)
        log_format_str = '{name} -> {levelname}: {message}'
        formatted_msg = log_format_str.format(name=self.name,
                                              levelname=levelname, message=msg)
        formatter = logging.Formatter(self.log_format)
        self.que_hdlr.setFormatter(formatter)
        self.que_logger.warning(msg)
        log_record = self.queue.get_nowait()
        self.assertEqual(formatted_msg, log_record.msg) # <Fails here, if commented out it's a pass>
        self.assertEqual(formatted_msg, log_record.message)

I tested this issue with the following test (which is a pass with the current build):

class QueueHandlerTest(BaseTest):

    def test_formatting_exc_text(self):
        formatter = logging.Formatter(self.log_format)
        self.que_hdlr.setFormatter(formatter)
        try:
            raise RuntimeError('deliberate mistake')
        except:
            self.que_logger.exception('failed', stack_info=True)
        log_record = self.queue.get_nowait()
        self.assertTrue(log_record.exc_text.startswith('Traceback (most recent '
                                                       'call last):\n'))

[Miksus]

And the reason why overriding attribute 'record.msg' with the formatted message is problematic is that the method 'record.getMessage' (which is used by Formatter) fetches the log message from the variable 'record.msg'. Therefore the exc_text needs to be set to None as Formatter checks the existence of this attribute to decide whether or not to format the exception. Otherwise the exception text may be formatted multiple of time.

I think it may be more correct solution to not override the record.msg and let the other formatters down the queue reformat the message if required.

[vsajip]

Why can you not subclass QueueHandler and override the prepare method to do what you want/need?

[Miksus]

I did subclass the QueueHandler and it did circumvent the issue for me. But after spending some time to find out why I could not access the exc_text I thought maybe there is something that could be done to make it more intuitive and save others' time. I find the current behaviour somewhat confusing.

[vsajip]

It might be inadvisable to make your suggested change because of backward compatibility and breakage of existing code. However, I don't mind updating the logging cookbook to mention your suggested method of resolving the issue for this use case. I'll leave the issue open until I've done that.

[jackb]

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.

[jackb]

Whoops! I've been a bit inconsistent between the code and my pros and cons about whether exc_text gets record.stack_info as well as record.exc_info. But either option is possible. As an aside, I'm not sure why stack info is not cached in e.g. record.stack_text for the same reasons that exc_text is cached.

[jackb]

OK, I had a misunderstanding about what record.stack_info was. I see it is a string, so doesn't need to be stripped. Ignore my first con and the previous message. Sorry for the noise.