openstack/oslo.log
Code Issues Proposed changes

Allow logging of unhashable exceptions in Python 3

Browse Source 
A bug in the Python 3 standard library,
https://bugs.python.org/issue28603 means that calling the traceback
module with an exception chain that includes an unhashable exception
results in a TypeError being raised. (In Python 3, any classes that
define __eq__() without also explicitly defining - not inheriting -
__hash__() will be unhashable.) The TypeError itself is also part of
such a chain, since its __context__ will be the unhashable exception. If
we don't catch it then the thread will simply exit mysteriously, and no
amount of logging will be able to reveal to the user what happened.

Change-Id: I6768574f38b075c15e829df5593a45c6be66b1bc
Closes-Bug: #1724366
This commit is contained in:
Zane Bitter 2017-10-16 16:41:44 -04:00
parent b52e68acef
commit 6b0b386146
2 changed files with 100 additions and 16 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

58
oslo_log/formatters.py
View File

@ -138,17 +138,22 @@ def _get_error_summary(record):
# If we have an exception, format it to be included in the
# output.
if exc_info:
# Build the exception summary in the line with the
# primary log message, to serve as a mnemonic for error
# and warning cases.
error_summary = traceback.format_exception_only(
exc_info[0],
exc_info[1],
)[0].rstrip()
# Remove the local reference to the exception and
# traceback to avoid a memory leak through the frame
# references.
del exc_info
try:
# Build the exception summary in the line with the
# primary log message, to serve as a mnemonic for error
# and warning cases.
error_summary = traceback.format_exception_only(
exc_info[0],
exc_info[1],
)[0].rstrip()
except TypeError as type_err:
# Work around https://bugs.python.org/issue28603
error_summary = "<exception with %s>" % six.text_type(type_err)
finally:
# Remove the local reference to the exception and
# traceback to avoid a memory leak through the frame
# references.
del exc_info
return error_summary
@ -169,7 +174,12 @@ class JSONFormatter(logging.Formatter):
self.hostname = None
def formatException(self, ei, strip_newlines=True):
lines = traceback.format_exception(*ei)
try:
lines = traceback.format_exception(*ei)
except TypeError as type_error:
# Work around https://bugs.python.org/issue28603
msg = six.text_type(type_error)
lines = ['<Unprintable exception due to %s>\n' % msg]
if strip_newlines:
lines = [moves.filter(
lambda x: x,
@ -245,7 +255,12 @@ class FluentFormatter(logging.Formatter):
self.hostname = None
def formatException(self, exc_info, strip_newlines=True):
lines = traceback.format_exception(*exc_info)
try:
lines = traceback.format_exception(*exc_info)
except TypeError as type_error:
# Work around https://bugs.python.org/issue28603
msg = six.text_type(type_error)
lines = ['<Unprintable exception due to %s>\n' % msg]
if strip_newlines:
lines = reduce(lambda a, line: a + line.rstrip().splitlines(),
lines, [])
@ -450,11 +465,22 @@ class ContextFormatter(logging.Formatter):
def formatException(self, exc_info, record=None):
"""Format exception output with CONF.logging_exception_prefix."""
if not record:
return logging.Formatter.formatException(self, exc_info)
try:
return logging.Formatter.formatException(self, exc_info)
except TypeError as type_error:
# Work around https://bugs.python.org/issue28603
msg = six.text_type(type_error)
return '<Unprintable exception due to %s>\n' % msg
stringbuffer = moves.StringIO()
traceback.print_exception(exc_info[0], exc_info[1], exc_info[2],
None, stringbuffer)
try:
traceback.print_exception(exc_info[0], exc_info[1], exc_info[2],
None, stringbuffer)
except TypeError as type_error:
# Work around https://bugs.python.org/issue28603
msg = six.text_type(type_error)
stringbuffer.write('<Unprintable exception due to %s>\n' % msg)
lines = stringbuffer.getvalue().split('\n')
stringbuffer.close()

58
oslo_log/tests/unit/test_formatters.py
View File

@ -16,8 +16,14 @@
import mock
import logging
import sys
from oslo_config import cfg
from oslo_config import fixture as config_fixture
from oslo_context import context
from oslo_log import formatters
from oslo_log import log
from oslotest import base as test_base
@ -83,3 +89,55 @@ class FormatterTest(test_base.BaseTestCase):
'method should be defined for logging context specific '
'information. The to_dict() method is deprecated '
'for oslo.log use.', removal_version='5.0.0', version='3.8.0')
# Test for https://bugs.python.org/issue28603
class FormatUnhashableExceptionTest(test_base.BaseTestCase):
def setUp(self):
super(FormatUnhashableExceptionTest, self).setUp()
self.config_fixture = self.useFixture(
config_fixture.Config(cfg.ConfigOpts()))
self.conf = self.config_fixture.conf
log.register_options(self.conf)
def _unhashable_exception_info(self):
class UnhashableException(Exception):
__hash__ = None
try:
raise UnhashableException()
except UnhashableException:
return sys.exc_info()
def test_error_summary(self):
exc_info = self._unhashable_exception_info()
record = logging.LogRecord('test', logging.ERROR, 'test', 0,
'test message', [], exc_info)
err_summary = formatters._get_error_summary(record)
self.assertTrue(err_summary)
def test_json_format_exception(self):
exc_info = self._unhashable_exception_info()
formatter = formatters.JSONFormatter()
tb = ''.join(formatter.formatException(exc_info))
self.assertTrue(tb)
def test_fluent_format_exception(self):
exc_info = self._unhashable_exception_info()
formatter = formatters.FluentFormatter()
tb = formatter.formatException(exc_info)
self.assertTrue(tb)
def test_context_format_exception_norecord(self):
exc_info = self._unhashable_exception_info()
formatter = formatters.ContextFormatter(config=self.conf)
tb = formatter.formatException(exc_info)
self.assertTrue(tb)
def test_context_format_exception(self):
exc_info = self._unhashable_exception_info()
formatter = formatters.ContextFormatter(config=self.conf)
record = logging.LogRecord('test', logging.ERROR, 'test', 0,
'test message', [], exc_info)
tb = formatter.format(record)
self.assertTrue(tb)