[issue44924] logging.handlers.QueueHandler does not maintain the exc_text

[Jack_B]

Jack_B  added the comment:

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.

--

___
Python tracker 

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

[issue44924] logging.handlers.QueueHandler does not maintain the exc_text

[Jack_B]

Jack_B  added the comment:

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.

--

___
Python tracker 

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

[issue44924] logging.handlers.QueueHandler does not maintain the exc_text

[Jack_B]

Jack_B  added the comment:

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.

--
nosy: +Jack_B

___
Python tracker 

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

[issue44924] logging.handlers.QueueHandler does not maintain the exc_text

[Vinay Sajip]

Vinay Sajip  added the comment:

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.

--

___
Python tracker 

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

[issue44924] logging.handlers.QueueHandler does not maintain the exc_text

[Mikael Koli]

Mikael Koli  added the comment:

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.

--

___
Python tracker 

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

[issue44924] logging.handlers.QueueHandler does not maintain the exc_text

[Vinay Sajip]

Vinay Sajip  added the comment:

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

--

___
Python tracker 

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

[issue44924] logging.handlers.QueueHandler does not maintain the exc_text

[Zachary Ware]

Change by Zachary Ware :


--
nosy: +vinay.sajip, zach.ware
versions:  -Python 3.6, Python 3.7, Python 3.8

___
Python tracker 

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

[issue44924] logging.handlers.QueueHandler does not maintain the exc_text

[Mikael Koli]

Mikael Koli  added the comment:

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.

--

___
Python tracker 

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

[issue44924] logging.handlers.QueueHandler does not maintain the exc_text

[Mikael Koli]

New submission from Mikael Koli :

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) # 
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'))

--
components: Library (Lib)
messages: 399642
nosy: Miksus
priority: normal
severity: normal
status: open
title: logging.handlers.QueueHandler does not maintain the exc_text
type: behavior
versions: Python 3.10, Python 3.11, Python 3.6, Python 3.7, Python 3.8, Python 
3.9

___
Python tracker 

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