classification
Title: QueueHandler logs exc_info twice
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.8, Python 3.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: avdd, cheryl.sabella, danishprakash, ned.deily, vinay.sajip, xtreak
Priority: normal Keywords: patch

Created on 2018-08-04 10:08 by avdd, last changed 2018-10-07 04:34 by ned.deily. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 9537 merged cheryl.sabella, 2018-09-24 14:57
PR 9581 merged miss-islington, 2018-09-25 23:00
Messages (11)
msg323100 - (view) Author: Adrian Dries (avdd) Date: 2018-08-04 10:08
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.
msg324053 - (view) Author: Danish Prakash (danishprakash) * Date: 2018-08-25 08:54
I would like to work on this, just making sure you are not.
msg324102 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-08-25 21:11
> 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:

https://github.com/python/cpython/commit/adfe3440f65dfd6cf4463db6cd02cdc78e77ce17

Specifically, the prepare() method.
msg324103 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-08-25 21:12
Possibly a test needs to be added for this, as it appears to be a regression that went unnoticed.
msg326242 - (view) Author: Cheryl Sabella (cheryl.sabella) * (Python committer) Date: 2018-09-24 14:41
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 issue31084, but record.msg won't get the traceback twice.
msg326270 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-09-24 17:04
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?
msg326341 - (view) Author: Cheryl Sabella (cheryl.sabella) * (Python committer) Date: 2018-09-25 11:15
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.
msg326353 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-09-25 13:34
> 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.
msg326411 - (view) Author: Cheryl Sabella (cheryl.sabella) * (Python committer) Date: 2018-09-25 22:53
Great, thanks.  I've made the other changes to the PR.
msg326412 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-09-25 23:00
New changeset d345bb4d9b6e16c681cd8a4e1fff94ecd6b0bb09 by Vinay Sajip (Cheryl Sabella) in branch 'master':
bpo-34334: Don't log traceback twice in QueueHandler (GH-9537)
https://github.com/python/cpython/commit/d345bb4d9b6e16c681cd8a4e1fff94ecd6b0bb09
msg327264 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2018-10-07 04:33
New changeset 1a2189353f744f79a43511707c090c3807a4978e by Ned Deily (Miss Islington (bot)) in branch '3.7':
bpo-34334: Don't log traceback twice in QueueHandler (GH-9537) (GH-9581)
https://github.com/python/cpython/commit/1a2189353f744f79a43511707c090c3807a4978e
History
Date User Action Args
2018-10-07 04:34:18ned.deilysetstatus: open -> closed
resolution: fixed
stage: patch review -> resolved
2018-10-07 04:33:44ned.deilysetnosy: + ned.deily
messages: + msg327264
2018-09-25 23:00:37miss-islingtonsetpull_requests: + pull_request8982
2018-09-25 23:00:19vinay.sajipsetmessages: + msg326412
2018-09-25 22:53:36cheryl.sabellasetmessages: + msg326411
2018-09-25 13:35:48vinay.sajipsetversions: + Python 3.8
2018-09-25 13:34:16vinay.sajipsetmessages: + msg326353
2018-09-25 11:15:59cheryl.sabellasetmessages: + msg326341
2018-09-24 17:04:56vinay.sajipsetmessages: + msg326270
2018-09-24 14:57:45cheryl.sabellasetkeywords: + patch
stage: patch review
pull_requests: + pull_request8939
2018-09-24 14:41:31cheryl.sabellasetnosy: + cheryl.sabella
messages: + msg326242
2018-08-27 08:19:47xtreaksetnosy: + xtreak
2018-08-25 21:12:16vinay.sajipsetmessages: + msg324103
2018-08-25 21:11:01vinay.sajipsetmessages: + msg324102
2018-08-25 08:54:43danishprakashsetnosy: + danishprakash
messages: + msg324053
2018-08-25 07:47:38xiang.zhangsetnosy: + vinay.sajip
2018-08-04 10:08:13avddcreate