From 6b0b386146e48470d889e0f1b22c7a5d5798149c Mon Sep 17 00:00:00 2001 From: Zane Bitter Date: Mon, 16 Oct 2017 16:41:44 -0400 Subject: [PATCH] Allow logging of unhashable exceptions in Python 3 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 --- oslo_log/formatters.py | 58 +++++++++++++++++++------- oslo_log/tests/unit/test_formatters.py | 58 ++++++++++++++++++++++++++ 2 files changed, 100 insertions(+), 16 deletions(-) diff --git a/oslo_log/formatters.py b/oslo_log/formatters.py index bc1ae0d2..ae2d04d8 100644 --- a/oslo_log/formatters.py +++ b/oslo_log/formatters.py @@ -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 = "" % 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 = ['\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 = ['\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 '\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('\n' % msg) + lines = stringbuffer.getvalue().split('\n') stringbuffer.close() diff --git a/oslo_log/tests/unit/test_formatters.py b/oslo_log/tests/unit/test_formatters.py index 3bb2cd45..1a70d6fe 100644 --- a/oslo_log/tests/unit/test_formatters.py +++ b/oslo_log/tests/unit/test_formatters.py @@ -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)