New tornado logging bits that output logs as JSON

setup.py

@@ -9,7 +9,7 @@ import sprockets.logging
 
 install_requires = []
 setup_requires = []
-tests_require = ['nose>=1.3,<2']
+tests_require = ['nose>=1.3,<2', 'mock>1,<2', 'tornado>3,<5']
 
 if sys.version_info < (3, 0):
     tests_require.append('mock')
@@ -23,6 +23,7 @@ setuptools.setup(
     author='Dave Shawley',
     author_email='daves@aweber.com',
     license='BSD',
+    extras_require={'tornado': ['tornado>3,<5']},
     classifiers=[
         'Development Status :: 4 - Beta',
         'Intended Audience :: Developers',

sprockets/logging.py

@@ -2,16 +2,36 @@
 Make good log output easier.
 
 - :class:`ContextFilter` adds fixed properties to a log record
+- :class:`JSONRequestFormatter` formats log records as JSON output
+- :method:`tornado_log_function` is for use as the
+    :class`tornado.web.Application.log_function` in conjunction with
+    :class:`JSONRequestFormatter` to output log lines as JSON.
 
 """
 from __future__ import absolute_import
 
+from logging import config
+import json
 import logging
 
+try:
+    from tornado import log
+except ImportError:
+    log = None
 
-version_info = (1, 0, 0)
+version_info = (1, 1, 0)
 __version__ = '.'.join(str(v) for v in version_info)
 
+# Shortcut methods and constants to avoid needing to import logging directly
+dictConfig = config.dictConfig
+getLogger = logging.getLogger
+
+DEBUG = logging.DEBUG
+INFO = logging.INFO
+WARN = logging.WARN
+WARNING = logging.WARNING
+ERROR = logging.ERROR
+
 
 class ContextFilter(logging.Filter):
     """
@@ -37,3 +57,58 @@ class ContextFilter(logging.Filter):
             if not hasattr(record, property_name):
                 setattr(record, property_name, None)
         return True
+
+
+class JSONRequestFormatter(logging.Formatter):
+    """Instead of spitting out a "human readable" log line, this outputs
+    the log data as JSON.
+
+    """
+    def format(self, record):
+        """Return the log data as JSON
+
+        :param record logging.LogRecord: The record to format
+        :rtype: str
+
+        """
+        return json.dumps({'name': record.name,
+                           'module': record.module,
+                           'level': logging.getLevelName(record.levelno),
+                           'line_number': record.lineno,
+                           'process': record.processName,
+                           'timestamp': self.formatTime(record),
+                           'thread': record.threadName,
+                           'file': record.filename,
+                           'request': record.args})
+
+
+def tornado_log_function(handler):
+    """Assigned when creating a :py:class:`tornado.web.Application` instance
+    by passing the method as the ``log_function`` argument:
+
+    .. code:: python
+
+        app = tornado.web.Application([('/', RequestHandler)],
+                                      log_function=tornado_log_function)
+
+    :type handler: :py:class:`tornado.web.RequestHandler`
+
+    """
+    status_code = handler.get_status()
+    if status_code < 400:
+        log_method = log.access_log.info
+    elif status_code < 500:
+        log_method = log.access_log.warning
+    else:
+        log_method = log.access_log.error
+    correlation_id = (getattr(handler, 'correlation_id', None) or
+                      handler.request.headers.get('Correlation-ID', None))
+    log_method('', {'correlation_id': correlation_id,
+                    'duration': 1000.0 * handler.request.request_time(),
+                    'headers': handler.request.headers,
+                    'method': handler.request.method,
+                    'path': handler.request.path,
+                    'protocol': handler.request.protocol,
+                    'query_args': handler.request.query_arguments,
+                    'remote_ip': handler.request.remote_ip,
+                    'status_code': status_code})

tests.py

@@ -1,9 +1,16 @@
+import json
 import logging
-import uuid
+from os import path
+import random
+import threading
 import unittest
+import uuid
 
+import mock
 import sprockets.logging
 
+LOGGER = logging.getLogger(__name__)
+
 
 class Prototype(object):
     pass
@@ -42,3 +49,95 @@ class ContextFilterTests(unittest.TestCase):
             properties=['context']))
         self.logger.info('hi there', extra={'context': 'foo'})
         self.assertEqual(self.handler.log_lines[-1], 'hi there [foo]')
+
+
+class MockRequest(object):
+
+    headers = {u'Accept': u'application/msgpack',
+               u'Correlation-ID': str(uuid.uuid4()).decode('utf-8')}
+    method = u'GET'
+    path = u'/test'
+    protocol = u'http'
+    remote_ip = u'127.0.0.1'
+    query_arguments = {u'mock': True}
+
+    def __init__(self):
+        self.duration = random.randint(10, 200)
+
+    def request_time(self):
+        return self.duration
+
+
+class MockHandler(object):
+
+    def __init__(self, status_code=200):
+        self.status_code = status_code
+        self.request = MockRequest()
+
+    def get_status(self):
+        return self.status_code
+
+
+class TornadoLogFunctionTestCase(unittest.TestCase):
+
+    @mock.patch('tornado.log.access_log')
+    def test_log_function_return_value(self, access_log):
+        handler = MockHandler()
+        expectation = ('', {u'correlation_id':
+                            handler.request.headers['Correlation-ID'],
+                            u'duration': handler.request.duration * 1000.0,
+                            u'headers': handler.request.headers,
+                            u'method': handler.request.method,
+                            u'path': handler.request.path,
+                            u'protocol': handler.request.protocol,
+                            u'query_args': handler.request.query_arguments,
+                            u'remote_ip': handler.request.remote_ip,
+                            u'status_code': handler.status_code})
+        sprockets.logging.tornado_log_function(handler)
+        access_log.assertCalledOnceWith(expectation)
+
+
+class JSONRequestHandlerTestCase(unittest.TestCase):
+
+    def test_log_function_return_value(self):
+        class LoggingHandler(logging.Handler):
+            def __init__(self, level):
+                super(LoggingHandler, self).__init__(level)
+                self.formatter = sprockets.logging.JSONRequestFormatter()
+                self.records = []
+                self.results = []
+
+            def handle(self, value):
+                self.records.append(value)
+                self.results.append(self.formatter.format(value))
+
+        logging_handler = LoggingHandler(logging.INFO)
+        LOGGER.addHandler(logging_handler)
+
+        handler = MockHandler()
+        args = {u'correlation_id':
+                handler.request.headers['Correlation-ID'],
+                u'duration': handler.request.duration * 1000.0,
+                u'headers': handler.request.headers,
+                u'method': handler.request.method,
+                u'path': handler.request.path,
+                u'protocol': handler.request.protocol,
+                u'query_args': handler.request.query_arguments,
+                u'remote_ip': handler.request.remote_ip,
+                u'status_code': handler.status_code}
+
+        LOGGER.info('', args)
+        record = logging_handler.records.pop(0)
+        result = logging_handler.results.pop(0)
+        expectation = \
+            {u'line_number': 130,
+             u'file': path.basename(globals()['__file__']),
+             u'level': u'INFO',
+             u'module': globals()['__name__'].decode('utf-8'),
+             u'name': globals()['__name__'].decode('utf-8'),
+             u'process': u'MainProcess',
+             u'thread': threading.current_thread().name.decode('utf-8'),
+             u'timestamp':
+               logging_handler.formatter.formatTime(record).decode('utf-8'),
+             u'request': args}
+        self.assertDictEqual(json.loads(result), expectation)