Merge pull request #4 from sprockets/json-logging

Add JSON logging functionality for Tornado

.travis.yml

@@ -4,7 +4,7 @@ python:
 - pypy
 - 3.4
 before_install:
-- pip install nose coverage codecov
+- pip install nose coverage codecov mock tornado
 install:
 - pip install -e .
 script: nosetests

docs/conf.py

@@ -13,7 +13,8 @@
 source_suffix = '.rst'
 master_doc = 'index'
 project = 'sprockets.logging'
-copyright = '2015, Dave Shawley'
+author = 'Dave Shawley'
+copyright = '2015, AWeber Communications'
 version = '.'.join(__version__.split('.')[0:1])
 release = __version__
 if len(version_info) > 3:
@@ -25,4 +26,5 @@
 intersphinx_mapping = {
     'python': ('https://docs.python.org/', None),
     'sprockets': ('https://sprockets.readthedocs.org/en/latest/', None),
+    'tornado': ('http://www.tornadoweb.org/en/stable/', None),
 }

docs/examples.rst

@@ -17,3 +17,16 @@ the custom filter and format string into the logging infrastructure and
 insert context easily with :class:`logging.LoggerAdapter`.
 
 .. literalinclude:: ../examples/tornado-app.py
+
+
+Tornado Application JSON Logging
+--------------------------------
+If you're looking to log Tornado requests as JSON, the
+:class:`sprockets.logging.JSONRequestFormatter` class works in conjunction with
+the :method:`tornado_log_function` method to output all Tornado log entries as
+JSON objects. In the following example, the dictionary-based configuration is
+expanded upon to include specify the :class:`sprockets.logging.JSONRequestFormatter`
+as the formatter and passes :method:`tornado_log_function` in as the ``log_function``
+when creating the Tornado application.
+
+.. literalinclude:: ../examples/tornado-json-logger.py

docs/history.rst

@@ -1,8 +1,21 @@
 Version History
 ===============
+`1.1.0`_ Jun 18, 2015
+---------------------
+ - Added :class:`sprockets.logging.JSONRequestFormatter`
+ - Added :method:`sprockets.logging.tornado_log_function`
+ - Added convenience constants and methods as a pass through to Python's logging package:
+  - :data:`sprockets.logging.DEBUG` to :data:`logging.DEBUG`
+  - :data:`sprockets.logging.ERROR` to :data:`logging.ERROR`
+  - :data:`sprockets.logging.INFO` to :data:`logging.INFO`
+  - :data:`sprockets.logging.WARN` to :data:`logging.WARN`
+  - :data:`sprockets.logging.WARNING` to :data:`logging.WARNING`
+  - :method:`sprockets.logging.dictConfig` to :method:`logging.config.dictConfig`
+  - :method:`sprockets.logging.getLogger` to :method:`logging.getLogger`
 
 `1.0.0`_ Jun 09, 2015
 ---------------------
  - Added :class:`sprockets.logging.ContextFilter`
 
+.. _1.1.0: https://github.com/sprockets/sprockets.logging/compare/1.0.0...1.1.0
 .. _1.0.0: https://github.com/sprockets/sprockets.logging/compare/0.0.0...1.0.0

examples/tornado-json-logger.py

@@ -0,0 +1,76 @@
+import logging.config
+import signal
+import uuid
+
+from tornado import ioloop, web
+import sprockets.logging
+
+
+LOG_CONFIG = {
+   'version': 1,
+   'handlers': {
+      'console': {
+         'class': 'logging.StreamHandler',
+         'stream': 'ext://sys.stdout',
+         'formatter': 'simple',
+         'filters': ['context']
+      }
+   },
+   'formatters': {
+      'simple': {
+         '()': sprockets.logging.JSONRequestFormatter
+      }
+   },
+   'filters': {
+      'context': {
+         '()': 'sprockets.logging.ContextFilter',
+         'properties': ['context']
+      }
+   },
+   'loggers': {
+      'tornado': {
+         'level': 'DEBUG'
+      }
+   },
+   'root': {
+      'handlers': ['console'],
+      'level': 'DEBUG'
+   },
+   'incremental': False
+}
+
+
+class RequestHandler(web.RequestHandler):
+
+   def __init__(self, *args, **kwargs):
+      self.parent_log = kwargs.pop('parent_log')
+      super(RequestHandler, self).__init__(*args, **kwargs)
+
+   def prepare(self):
+      uniq_id = self.request.headers.get('X-UniqID', uuid.uuid4().hex)
+      self.logger = logging.LoggerAdapter(
+         self.parent_log.getChild('RequestHandler'),
+         extra={'context': uniq_id})
+
+   def get(self, object_id):
+      self.logger.debug('fetchin %s', object_id)
+      self.set_status(200)
+      return self.finish()
+
+def sig_handler(signo, frame):
+   logging.info('caught signal %d, stopping IO loop', signo)
+   iol = ioloop.IOLoop.instance()
+   iol.add_callback_from_signal(iol.stop)
+
+if __name__ == '__main__':
+   logging.config.dictConfig(LOG_CONFIG)
+   logger = logging.getLogger('app')
+   app = web.Application([
+      web.url('/(?P<object_id>\w+)', RequestHandler,
+              kwargs={'parent_log': logger}),
+   ], log_function=sprockets.logging.tornado_log_function)
+   app.listen(8000)
+   signal.signal(signal.SIGINT, sig_handler)
+   signal.signal(signal.SIGTERM, sig_handler)
+   ioloop.IOLoop.instance().start()
+   logger.info('IO loop stopped, exiting')

setup.py

@@ -9,7 +9,7 @@
 
 install_requires = []
 setup_requires = []
-tests_require = ['nose>=1.3,<2']
+tests_require = ['nose>=1.3,<2', 'tornado>3,<5']
 
 if sys.version_info < (3, 0):
     tests_require.append('mock')
@@ -23,6 +23,7 @@
     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 @@ def filter(self, record):
             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}, sort_keys=True)
+
+
+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,98 @@ def test_that_filter_does_not_overwrite_extras(self):
             properties=['context']))
         self.logger.info('hi there', extra={'context': 'foo'})
         self.assertEqual(self.handler.log_lines[-1], 'hi there [foo]')
+
+
+class MockRequest(object):
+
+    headers = {'Accept': 'application/msgpack',
+               'Correlation-ID': str(uuid.uuid4())}
+    method = 'GET'
+    path = '/test'
+    protocol = 'http'
+    remote_ip = '127.0.0.1'
+    query_arguments = {'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 = ('', {'correlation_id':
+                            handler.request.headers['Correlation-ID'],
+                            'duration': handler.request.duration * 1000.0,
+                            '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': handler.status_code})
+        sprockets.logging.tornado_log_function(handler)
+        access_log.assertCalledOnceWith(expectation)
+
+
+class JSONRequestHandlerTestCase(unittest.TestCase):
+
+    def setUp(self):
+        self.maxDiff = 32768
+
+    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 = {'correlation_id':
+                handler.request.headers['Correlation-ID'],
+                'duration': handler.request.duration * 1000.0,
+                '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': handler.status_code}
+
+        LOGGER.info('', args)
+        record = logging_handler.records.pop(0)
+        result = logging_handler.results.pop(0)
+        expectation = \
+            {'line_number': 132,
+             'file': path.basename(globals()['__file__']),
+             'level': 'INFO',
+             'module': globals()['__name__'],
+             'name': globals()['__name__'],
+             'process': 'MainProcess',
+             'thread': threading.current_thread().name,
+             'timestamp':
+                 logging_handler.formatter.formatTime(record),
+             'request': args}
+        self.assertEqual(result, json.dumps(expectation, sort_keys=True))