openstack
/
oslo.log
Code Issues Proposed changes

add exception summaries to the main log line 

Normally when logging while there is an active exception, the exception
is formatted as a traceback and the log message string ends up on a
separate line. This change adds the 1-line summary of the exception,
including the exception class name and the text of the exception, to the
end of the log line. The traceback is retained, so that the full details
are still logged.

Adding the exception info in the formatter means that the default
excepthook function no longer needs to do that (otherwise we end up with
duplicate information on the lines logged by the excepthook). Fix the
duplication by replacing the extra traceback formatting with a static
message that there is an unhandled error.

Depends-On: Icb2e1c6d9fe40229119467e9261055d9464d331d
Change-Id: Ib29883a1b7aa665b5d3c728dd7bd53d449987191
Signed-off-by: Doug Hellmann <doug@doughellmann.com>
This commit is contained in:
Doug Hellmann 2017-04-24 14:35:48 -04:00
parent 84341f6201
commit 48d284a985
3 changed files with 64 additions and 31 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

46
oslo_log/formatters.py
View File

@ -267,7 +267,6 @@ class ContextFormatter(logging.Formatter):
def format(self, record):
"""Uses contextstring if request_id is set, otherwise default."""
if six.PY2:
should_use_unicode = True
args = (record.args.values() if isinstance(record.args, dict)
@ -358,10 +357,51 @@ class ContextFormatter(logging.Formatter):
else:
self._style = logging.PercentStyle(fmt)
self._fmt = self._style._fmt
# Cache this on the record, Logger will respect our formatted copy
# Cache the formatted traceback on the record, Logger will
# respect our formatted copy
if record.exc_info:
record.exc_text = self.formatException(record.exc_info, record)
return logging.Formatter.format(self, record)
# Save the exception we were given so we can include the
# summary in the log line.
exc_info = record.exc_info
else:
# Check to see if there is an active exception that was
# not given to us explicitly. If so, save it so we can
# include the summary in the log line.
exc_info = sys.exc_info()
# If we get (None, None, None) because there is no
# exception, convert it to a simple None to make the logic
# that uses the value simpler.
if not exc_info[0]:
exc_info = None
if exc_info:
# Include the exception summary in the line with the
# primary log message, to serve as a mnemonic for error
# and warning cases. Replace % with * to remove any
# patterns that look like they would be python string
# interpolation instructions, since we may not have the
# arguments for them and that will break the log
# formatter.
suffix = traceback.format_exception_only(
exc_info[0],
exc_info[1],
)[0].rstrip().replace('%', '*')
record.msg = '{}: {}'.format(record.msg, suffix)
# Remove the local reference to the exception and
# traceback to avoid a memory leak through the frame
# references.
del exc_info
try:
return logging.Formatter.format(self, record)
except TypeError as err:
# Something went wrong, report that instead so we at least
# get the error message.
record.msg = 'Error formatting log line msg={!r} err={!r}'.format(
record.msg, err).replace('%', '*')
return logging.Formatter.format(self, record)
def formatException(self, exc_info, record=None):
"""Format exception output with CONF.logging_exception_prefix."""

5
oslo_log/log.py
View File

@ -37,7 +37,6 @@ try:
import syslog
except ImportError:
syslog = None
import traceback
from oslo_config import cfg
from oslo_utils import importutils
@ -191,9 +190,7 @@ class KeywordArgumentAdapter(BaseLoggerAdapter):
def _create_logging_excepthook(product_name):
def logging_excepthook(exc_type, value, tb):
extra = {'exc_info': (exc_type, value, tb)}
getLogger(product_name).critical(
"".join(traceback.format_exception_only(exc_type, value)),
**extra)
getLogger(product_name).critical('Unhandled error', **extra)
return logging_excepthook

44
oslo_log/tests/unit/test_log.py
View File

@ -759,7 +759,7 @@ class ExceptionLoggingTestCase(LogTestBase):
except Exception:
excepthook(*sys.exc_info())
expected_string = ("CRITICAL somename [-] "
expected_string = ("CRITICAL somename [-] Unhandled error: "
"Exception: Some error happened")
self.assertIn(expected_string, self.stream.getvalue(),
message="Exception is not logged")
@ -834,15 +834,16 @@ class FancyRecordTestCase(LogTestBase):
warncolor = handlers.ColorHandler.LEVEL_COLORS[logging.WARN]
info_msg = 'info'
warn_msg = 'warn'
infoexpected = "%s %s %s\n" % (infocolor, keyed_log_string, info_msg)
warnexpected = "%s %s %s\n" % (warncolor, keyed_log_string, warn_msg)
infoexpected = "%s %s %s" % (infocolor, keyed_log_string, info_msg)
warnexpected = "%s %s %s" % (warncolor, keyed_log_string, warn_msg)
self.colorlog.info(info_msg, context=ctxt)
self.assertEqual(infoexpected, self.stream.getvalue())
self.assertIn(infoexpected, self.stream.getvalue())
self.assertEqual('\033[00;36m', infocolor)
self.colorlog.warn(warn_msg, context=ctxt)
self.assertEqual(infoexpected + warnexpected, self.stream.getvalue())
self.assertIn(infoexpected, self.stream.getvalue())
self.assertIn(warnexpected, self.stream.getvalue())
self.assertEqual('\033[01;33m', warncolor)
def test_fancy_key_in_log_msg(self):
@ -900,51 +901,47 @@ class InstanceRecordTestCase(LogTestBase):
fake_resource = {'uuid': uuid}
message = 'info'
self.log.info(message, context=ctxt, instance=fake_resource)
expected = ('[%s]: [instance: %s] %s\n' %
(ctxt.request_id, uuid, message))
self.assertEqual(expected, self.stream.getvalue())
expected = '[instance: %s]' % uuid
self.assertIn(expected, self.stream.getvalue())
def test_instance_dict_in_default_log_msg(self):
uuid = 'C9B7CCC6-8A12-4C53-A736-D7A1C36A62F3'
fake_resource = {'uuid': uuid}
message = 'info'
self.log.info(message, instance=fake_resource)
expected = '[instance: %s] %s\n' % (uuid, message)
self.assertEqual(expected, self.stream.getvalue())
expected = '[instance: %s]' % uuid
self.assertIn(expected, self.stream.getvalue())
def test_instance_uuid_as_arg_in_context_log_msg(self):
ctxt = _fake_context()
uuid = 'C9B7CCC6-8A12-4C53-A736-D7A1C36A62F3'
message = 'info'
self.log.info(message, context=ctxt, instance_uuid=uuid)
expected = ('[%s]: [instance: %s] %s\n' %
(ctxt.request_id, uuid, message))
self.assertEqual(expected, self.stream.getvalue())
expected = '[instance: %s]' % uuid
self.assertIn(expected, self.stream.getvalue())
def test_instance_uuid_as_arg_in_default_log_msg(self):
uuid = 'C9B7CCC6-8A12-4C53-A736-D7A1C36A62F3'
message = 'info'
self.log.info(message, instance_uuid=uuid)
expected = '[instance: %s] %s\n' % (uuid, message)
self.assertEqual(expected, self.stream.getvalue())
expected = '[instance: %s]' % uuid
self.assertIn(expected, self.stream.getvalue())
def test_instance_uuid_from_context_in_context_log_msg(self):
ctxt = _fake_context()
ctxt.instance_uuid = 'CCCCCCCC-8A12-4C53-A736-D7A1C36A62F3'
message = 'info'
self.log.info(message, context=ctxt)
expected = ('[%s]: [instance: %s] %s\n' %
(ctxt.request_id, ctxt.instance_uuid, message))
self.assertEqual(expected, self.stream.getvalue())
expected = '[instance: %s]' % ctxt.instance_uuid
self.assertIn(expected, self.stream.getvalue())
def test_resource_uuid_from_context_in_context_log_msg(self):
ctxt = _fake_context()
ctxt.resource_uuid = 'RRRRRRRR-8A12-4C53-A736-D7A1C36A62F3'
message = 'info'
self.log.info(message, context=ctxt)
expected = ('[%s]: [instance: %s] %s\n' %
(ctxt.request_id, ctxt.resource_uuid, message))
self.assertEqual(expected, self.stream.getvalue())
expected = '[instance: %s]' % ctxt.resource_uuid
self.assertIn(expected, self.stream.getvalue())
def test_instance_from_context_in_context_log_msg(self):
# NOTE: instance when passed in a context object is just a uuid.
@ -953,9 +950,8 @@ class InstanceRecordTestCase(LogTestBase):
ctxt.instance = 'IIIIIIII-8A12-4C53-A736-D7A1C36A62F3'
message = 'info'
self.log.info(message, context=ctxt)
values = (ctxt.request_id, ctxt.instance, message)
expected = '[%s]: [instance: %s] %s\n' % values
self.assertEqual(expected, self.stream.getvalue())
expected = '[instance: %s]' % ctxt.instance
self.assertIn(expected, self.stream.getvalue())
class TraceLevelTestCase(LogTestBase):