[issue34334] QueueHandler logs exc_info twice

[Ned Deily]

Ned Deily  added the comment:


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


--
nosy: +ned.deily

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34334] QueueHandler logs exc_info twice

[Ned Deily]

Change by Ned Deily :


--
resolution:  -> fixed
stage: patch review -> resolved
status: open -> closed

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34334] QueueHandler logs exc_info twice

[miss-islington]

Change by miss-islington :


--
pull_requests: +8982

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34334] QueueHandler logs exc_info twice

[Vinay Sajip]

Vinay Sajip  added the comment:


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


--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34334] QueueHandler logs exc_info twice

[Cheryl Sabella]

Cheryl Sabella  added the comment:

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

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34334] QueueHandler logs exc_info twice

[Vinay Sajip]

Change by Vinay Sajip :


--
versions: +Python 3.8

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34334] QueueHandler logs exc_info twice

[Vinay Sajip]

Vinay Sajip  added the comment:

> 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.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34334] QueueHandler logs exc_info twice

[Cheryl Sabella]

Cheryl Sabella  added the comment:

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.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34334] QueueHandler logs exc_info twice

[Vinay Sajip]

Vinay Sajip  added the comment:

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?

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34334] QueueHandler logs exc_info twice

[Cheryl Sabella]

Change by Cheryl Sabella :


--
keywords: +patch
pull_requests: +8939
stage:  -> patch review

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34334] QueueHandler logs exc_info twice

[Cheryl Sabella]

Cheryl Sabella  added the comment:

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.

--
nosy: +cheryl.sabella

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34334] QueueHandler logs exc_info twice

[Karthikeyan Singaravelan]

Change by Karthikeyan Singaravelan :


--
nosy: +xtreak

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34334] QueueHandler logs exc_info twice

[Vinay Sajip]

Vinay Sajip  added the comment:

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

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34334] QueueHandler logs exc_info twice

[Vinay Sajip]

Vinay Sajip  added the comment:

> 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.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34334] QueueHandler logs exc_info twice

[Danish Prakash]

Danish Prakash  added the comment:

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

--
nosy: +prakashdanish

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34334] QueueHandler logs exc_info twice

[Xiang Zhang]

Change by Xiang Zhang :


--
nosy: +vinay.sajip

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34334] QueueHandler logs exc_info twice

[Adrian Dries]

New submission from Adrian Dries :

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 "", line 1, in 
ZeroDivisionError: division by zero
Traceback (most recent call last):
  File "", line 1, in 
ZeroDivisionError: division by zero


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

--
components: Library (Lib)
messages: 323100
nosy: avdd
priority: normal
severity: normal
status: open
title: QueueHandler logs exc_info twice
type: behavior
versions: Python 3.7

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com