Add JSONFormatter

* Allows formating log messages in JSON format

Change-Id: I9c5b4e20fff0a055b7178acaf862e838d62abaa0

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.
 

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