New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
QueueHandler logs exc_info twice #78515
Comments
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. |
I would like to work on this, just making sure you are not. |
I'm not sure that's the right fix. The change appears to have come from this commit: Specifically, the prepare() method. |
Possibly a test needs to be added for this, as it appears to be a regression that went unnoticed. |
I debugged this issue and found that The first call - The second call - Because of the following note in 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: 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. |
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? |
Hi Vinay, Thanks for the explanation! I'm good with changing the PR. I do have one question though. You wrote -
Based on the 'always reflect' statement, I'm wondering if there should be a change to Or if should just be in the 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. |
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.
There's no need to deviate from the normal process to get it into this release, from my point of view. |
Great, thanks. I've made the other changes to the PR. |
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:
bugs.python.org fields:
The text was updated successfully, but these errors were encountered: