QueueHandler logs exc_info twice

[avdd]

BPO	34334
Nosy	@vsajip, @ned-deily, @csabella, @tirkarthi, @danishprakash
PRs	bpo-34334: Don't log traceback twice in QueueHandler #9537 [3.7] bpo-34334: Don't log traceback twice in QueueHandler (GH-9537) #9581

^{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 = <Date 2018-10-07.04:34:18.187>
created_at = <Date 2018-08-04.10:08:12.697>
labels = ['3.7', '3.8', 'type-bug', 'library']
title = 'QueueHandler logs exc_info twice'
updated_at = <Date 2018-10-07.04:34:18.187>
user = 'https://bugs.python.org/avdd'

bugs.python.org fields:

activity = <Date 2018-10-07.04:34:18.187>
actor = 'ned.deily'
assignee = 'none'
closed = True
closed_date = <Date 2018-10-07.04:34:18.187>
closer = 'ned.deily'
components = ['Library (Lib)']
creation = <Date 2018-08-04.10:08:12.697>
creator = 'avdd'
dependencies = []
files = []
hgrepos = []
issue_num = 34334
keywords = ['patch']
message_count = 11.0
messages = ['323100', '324053', '324102', '324103', '326242', '326270', '326341', '326353', '326411', '326412', '327264']
nosy_count = 6.0
nosy_names = ['vinay.sajip', 'ned.deily', 'avdd', 'cheryl.sabella', 'xtreak', 'danishprakash']
pr_nums = ['9537', '9581']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue34334'
versions = ['Python 3.7', 'Python 3.8']

[avdd]

Since Python 3.7 logging.handlers.QueueHandler logs tracebacks twice::

>>> import logging
>>> from logging.handlers import QueueHandler, QueueListener
>>> from queue import Queue
>>> q = Queue()
>>> logging.getLogger().addHandler(QueueHandler(q))
>>> listener = QueueListener(q, logging.StreamHandler())
>>> listener.start()
>>> try: 1/0
... except: logging.exception('Look out!')
... 
Look out!
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
ZeroDivisionError: division by zero
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
ZeroDivisionError: division by zero

Patching QueueHandler.prepare() to set exc_text to None seems to fix this.

[danishprakash]

I would like to work on this, just making sure you are not.

[vsajip]

Patching QueueHandler.prepare() to set exc_text to None seems to fix this.

I'm not sure that's the right fix. The change appears to have come from this commit:

adfe344

Specifically, the prepare() method.

[vsajip]

Possibly a test needs to be added for this, as it appears to be a regression that went unnoticed.

[csabella]

I debugged this issue and found that format() is being called twice and appending the traceback twice.

The first call -
QueueHandler.emit() -> QueueHandler.prepare() -> self.format() (which is the default Formatter) -- this gets called with self.msg = 'Look out!' in this example.

The second call -
StreamHandler.emit() -> self.format() -- gets called with a record.msg = 'Look out!' + the traceback added in the first call above. This call to format also appends the traceback because even though record.exc_info is None, record.exc_text is still set.

Because of the following note in format():

        if record.exc_info:
            # 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)

Even when record.exc_info has been set to None before the second call, record.exc_text still contains the cached value, which is re-appended in the next line:
if record.exc_text:
if s[-1:] != "\n":
s = s + "\n"
s = s + record.exc_text

So the traceback appears twice.

Based on the design of this, my guess is the record.msg was never intended to contain the value with the traceback already appended to it, so I've made a PR with that change. This will still allow record.message to have the change from bpo-31084, but record.msg won't get the traceback twice.

[vsajip]

Having looked at it again, Adrian Dries might be right that setting exc_text to None will also do the trick, and perhaps in a better way. The reasoning:

Handler.format() formats record.msg % record.args, and caches it in record.message. If there is exception information, it will format that and cache it in record.exc_text, then append the exception text to the message and return that.

So prepare() calling

msg = self.format(record)

will return the complete message and exception text in msg, and record will have record.message = record.msg % record.args, and record.exc_info and record.exc_text will have exception info.

When preparing, the prepare() method pretends that the already-formatted message was logged - record.msg % record.args is equivalent to record.message with no args, so it does

record.msg = msg (contains formatted message + exception info)
record.args = None (since the args have already been used)
record.exc_info = None (since the exception info has already been used)

but I forgot that record.exc_text should also be zapped, as it should always reflect the contents of record.exc_info. So I think that setting record.exc_text to None is perhaps the correct thing to do here, as Adrian originally suggested.

There should be a test that specifically exercises this with a QueueHandler and QueueListener - test_queue_listener needs to test for this case in case a regression reappears.

The reason for converting record.msg, record.args, record.exc_info and record.exc_text to record.msg = fully formatted message, None, None and None is that the arguments and exception trace may not be pickleable, which is a consideration when using multiprocessing queues. Otherwise we could just have passed them over unchanged.

Are you OK with changing the PR in line with the above, Cheryl?

[csabella]

Hi Vinay,

Thanks for the explanation! I'm good with changing the PR. I do have one question though.

You wrote -

but I forgot that record.exc_text should also be zapped, as it should always reflect the contents of record.exc_info.

Based on the 'always reflect' statement, I'm wondering if there should be a change to format() to add an else to the record.exc_info check:
if record.exc_info:
if not record.exc_text:
record.exc_text = self.formatException(record.exc_info)
else:
record.exc_text = None

Or if should just be in the prepare().

I hope to have the new PR sometime today. I think the cutoff for 3.7.1 was yesterday, but if you want to try to get this in to that release feel free to make changes.

[vsajip]

I'm wondering if there should be a change to format() to add an else

There's no need; the field is initialised to None in the LogRecord constructor and then only set later if there is a traceback to be cached.

I think the cutoff for 3.7.1 was yesterday, but if you want to try to get this in to that

There's no need to deviate from the normal process to get it into this release, from my point of view.

[csabella]

Great, thanks. I've made the other changes to the PR.

[vsajip]

New changeset d345bb4 by Vinay Sajip (Cheryl Sabella) in branch 'master':
bpo-34334: Don't log traceback twice in QueueHandler (GH-9537)
d345bb4

[ned-deily]

New changeset 1a21893 by Ned Deily (Miss Islington (bot)) in branch '3.7':
bpo-34334: Don't log traceback twice in QueueHandler (GH-9537) (GH-9581)
1a21893