From 6a0dd8a61f8c6c512cd004631a9df7b8127dc576 Mon Sep 17 00:00:00 2001 From: "Gavin M. Roy" Date: Wed, 17 Jun 2015 22:01:18 -0400 Subject: [PATCH 1/4] Add JSON logging bits for Tornado --- setup.py | 3 +- sprockets/logging.py | 77 +++++++++++++++++++++++++++++++- tests.py | 104 ++++++++++++++++++++++++++++++++++++++++++- 3 files changed, 181 insertions(+), 3 deletions(-) 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)) From 467bd5d0f7fceedbc956345976c4d832de8874b3 Mon Sep 17 00:00:00 2001 From: "Gavin M. Roy" Date: Wed, 17 Jun 2015 22:01:26 -0400 Subject: [PATCH 2/4] Update the docs --- docs/conf.py | 4 +++- docs/history.rst | 13 +++++++++++++ examples/tornado-app.py | 23 +++++++++++------------ 3 files changed, 27 insertions(+), 13 deletions(-) diff --git a/docs/conf.py b/docs/conf.py index 57c8488..5f8b6b6 100644 --- a/docs/conf.py +++ b/docs/conf.py @@ -13,7 +13,8 @@ templates_path = [] 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 @@ html_theme_path = [sphinx_rtd_theme.get_html_theme_path()] intersphinx_mapping = { 'python': ('https://docs.python.org/', None), 'sprockets': ('https://sprockets.readthedocs.org/en/latest/', None), + 'tornado': ('http://www.tornadoweb.org/en/stable/', None), } diff --git a/docs/history.rst b/docs/history.rst index 54a5d64..bec3adf 100644 --- a/docs/history.rst +++ b/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 diff --git a/examples/tornado-app.py b/examples/tornado-app.py index d88a852..fb0652d 100644 --- a/examples/tornado-app.py +++ b/examples/tornado-app.py @@ -13,31 +13,30 @@ LOG_CONFIG = { 'class': 'logging.StreamHandler', 'stream': 'ext://sys.stdout', 'formatter': 'simple', - 'filters': ['context'], - }, + 'filters': ['context'] + } }, 'formatters': { 'simple': { - 'class': 'logging.Formatter', - 'format': '%(levelname)s %(name)s: %(message)s [%(context)s]', - }, + '()': sprockets.logging.JSONRequestFormatter + } }, 'filters': { 'context': { '()': 'sprockets.logging.ContextFilter', - 'properties': ['context'], - }, + 'properties': ['context'] + } }, 'loggers': { 'tornado': { - 'level': 'DEBUG', - }, + 'level': 'DEBUG' + } }, 'root': { 'handlers': ['console'], - 'level': 'DEBUG', + 'level': 'DEBUG' }, - 'incremental': False, + 'incremental': False } @@ -69,7 +68,7 @@ if __name__ == '__main__': app = web.Application([ web.url('/(?P\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) From 80beb20c2e159f601e7116afdabe16b4758e1b2e Mon Sep 17 00:00:00 2001 From: "Gavin M. Roy" Date: Wed, 17 Jun 2015 22:04:04 -0400 Subject: [PATCH 3/4] Update travis config for new deps --- .travis.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.travis.yml b/.travis.yml index d4ab8e9..c434ea3 100644 --- a/.travis.yml +++ b/.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 From 553688c87a63155dd2909cb6dbf72ec9aafad828 Mon Sep 17 00:00:00 2001 From: "Gavin M. Roy" Date: Thu, 18 Jun 2015 09:36:51 -0400 Subject: [PATCH 4/4] Update docs, revert tornado-app.py example, add new one --- docs/examples.rst | 13 ++++++ examples/tornado-app.py | 23 +++++----- examples/tornado-json-logger.py | 76 +++++++++++++++++++++++++++++++++ 3 files changed, 101 insertions(+), 11 deletions(-) create mode 100644 examples/tornado-json-logger.py diff --git a/docs/examples.rst b/docs/examples.rst index db435cb..b48d6e1 100644 --- a/docs/examples.rst +++ b/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 diff --git a/examples/tornado-app.py b/examples/tornado-app.py index fb0652d..d88a852 100644 --- a/examples/tornado-app.py +++ b/examples/tornado-app.py @@ -13,30 +13,31 @@ LOG_CONFIG = { 'class': 'logging.StreamHandler', 'stream': 'ext://sys.stdout', 'formatter': 'simple', - 'filters': ['context'] - } + 'filters': ['context'], + }, }, 'formatters': { 'simple': { - '()': sprockets.logging.JSONRequestFormatter - } + 'class': 'logging.Formatter', + 'format': '%(levelname)s %(name)s: %(message)s [%(context)s]', + }, }, 'filters': { 'context': { '()': 'sprockets.logging.ContextFilter', - 'properties': ['context'] - } + 'properties': ['context'], + }, }, 'loggers': { 'tornado': { - 'level': 'DEBUG' - } + 'level': 'DEBUG', + }, }, 'root': { 'handlers': ['console'], - 'level': 'DEBUG' + 'level': 'DEBUG', }, - 'incremental': False + 'incremental': False, } @@ -68,7 +69,7 @@ if __name__ == '__main__': app = web.Application([ web.url('/(?P\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) diff --git a/examples/tornado-json-logger.py b/examples/tornado-json-logger.py new file mode 100644 index 0000000..fb0652d --- /dev/null +++ b/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\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')