diff --git a/nova/log.py b/nova/log.py index a99147a7..f941d0a0 100644 --- a/nova/log.py +++ b/nova/log.py @@ -31,6 +31,8 @@ It also allows setting of formatting information through flags. import cStringIO import inspect +import itertools +import json import logging import logging.config import logging.handlers @@ -159,10 +161,56 @@ class NovaContextAdapter(logging.LoggerAdapter): extra.update({'instance': instance_extra}) extra.update({"nova_version": version.version_string_with_vcs()}) - + extra['extra'] = extra.copy() return msg, kwargs +class JSONFormatter(logging.Formatter): + def __init__(self, fmt=None, datefmt=None): + # NOTE(jkoelker) we ignore the fmt argument, but its still there + # since logging.config.fileConfig passes it. + self.datefmt = datefmt + + def formatException(self, ei, strip_newlines=True): + lines = traceback.format_exception(*ei) + if strip_newlines: + lines = [itertools.ifilter(lambda x: x, + line.rstrip().splitlines()) + for line in lines] + lines = list(itertools.chain(*lines)) + return lines + + def format(self, record): + message = {'message': record.getMessage(), + 'asctime': self.formatTime(record, self.datefmt), + 'name': record.name, + 'msg': record.msg, + 'args': record.args, + 'levelname': record.levelname, + 'levelno': record.levelno, + 'pathname': record.pathname, + 'filename': record.filename, + 'module': record.module, + 'lineno': record.lineno, + 'funcname': record.funcName, + 'created': record.created, + 'msecs': record.msecs, + 'relative_created': record.relativeCreated, + 'thread': record.thread, + 'thread_name': record.threadName, + 'process_name': record.processName, + 'process': record.process, + 'traceback': None} + + if hasattr(record, 'extra'): + message['extra'] = record.extra + + if record.exc_info: + message['traceback'] = self.formatException(record.exc_info) + + return json.dumps(message) + + class LegacyNovaFormatter(logging.Formatter): """A nova.context.RequestContext aware formatter configured through flags. diff --git a/nova/tests/test_log.py b/nova/tests/test_log.py index 6a4e2b67..3fd8dad9 100644 --- a/nova/tests/test_log.py +++ b/nova/tests/test_log.py @@ -1,4 +1,5 @@ import cStringIO +import json import logging from nova import context @@ -124,3 +125,56 @@ class NovaLoggerTestCase(test.TestCase): def test_child_log_has_level_of_parent_flag(self): l = log.getLogger('nova-test.foo') self.assertEqual(logging.AUDIT, l.logger.getEffectiveLevel()) + + +class JSONFormatterTestCase(test.TestCase): + def setUp(self): + super(JSONFormatterTestCase, self).setUp() + self.log = log.getLogger('test-json') + self.stream = cStringIO.StringIO() + handler = logging.StreamHandler(self.stream) + handler.setFormatter(log.JSONFormatter()) + self.log.logger.addHandler(handler) + self.log.logger.setLevel(logging.DEBUG) + + def test_json(self): + test_msg = 'This is a %(test)s line' + test_data = {'test': 'log'} + self.log.debug(test_msg, test_data) + + data = json.loads(self.stream.getvalue()) + self.assertTrue(data) + self.assertTrue('extra' in data) + self.assertEqual('test-json', data['name']) + + self.assertEqual(test_msg % test_data, data['message']) + self.assertEqual(test_msg, data['msg']) + self.assertEqual(test_data, data['args']) + + self.assertEqual('test_log.py', data['filename']) + self.assertEqual('test_json', data['funcname']) + + self.assertEqual('DEBUG', data['levelname']) + self.assertEqual(logging.DEBUG, data['levelno']) + self.assertFalse(data['traceback']) + + def test_json_exception(self): + test_msg = 'This is %s' + test_data = 'exceptional' + try: + raise Exception('This is exceptional') + except Exception: + self.log.exception(test_msg, test_data) + + data = json.loads(self.stream.getvalue()) + self.assertTrue(data) + self.assertTrue('extra' in data) + self.assertEqual('test-json', data['name']) + + self.assertEqual(test_msg % test_data, data['message']) + self.assertEqual(test_msg, data['msg']) + self.assertEqual([test_data], data['args']) + + self.assertEqual('ERROR', data['levelname']) + self.assertEqual(logging.ERROR, data['levelno']) + self.assertTrue(data['traceback'])