diff --git a/setup.py b/setup.py index 93fe0ca..0b1c765 100755 --- a/setup.py +++ b/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', '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', diff --git a/sprockets/logging.py b/sprockets/logging.py index 433601d..1ef3d3f 100644 --- a/sprockets/logging.py +++ b/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}, 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}) diff --git a/tests.py b/tests.py index f3f36d3..c0d57f3 100644 --- a/tests.py +++ b/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 @@ 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 = {'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))