From c1349ba8b2f4efa425147ec7a655fc074260ee18 Mon Sep 17 00:00:00 2001 From: Dave Shawley Date: Mon, 14 Sep 2015 07:27:47 -0400 Subject: [PATCH 01/10] Rewrite tests for sprockets.logging.tornado_log_function This exposes the defect that we found in production --- tests.py | 238 +++++++++++++++++++++++-------------------------------- 1 file changed, 97 insertions(+), 141 deletions(-) diff --git a/tests.py b/tests.py index d2aba0e..6fbba6d 100644 --- a/tests.py +++ b/tests.py @@ -1,172 +1,128 @@ import json import logging import os -import random import unittest import uuid -import mock - -import sprockets.logging from tornado import web, testing -LOGGER = logging.getLogger(__name__) -os.environ['ENVIRONMENT'] = 'testing' - -class Prototype(object): - pass +import sprockets.logging -class RecordingHandler(logging.FileHandler): - def __init__(self): - logging.FileHandler.__init__(self, filename='/dev/null') - self.log_lines = [] - - def format(self, record): - log_line = logging.FileHandler.format(self, record) - self.log_lines.append(log_line) - return log_line +def setup_module(): + os.environ.setdefault('ENVIRONMENT', 'development') -class ContextFilterTests(unittest.TestCase): +class SimpleHandler(web.RequestHandler): - def setUp(self): - super(ContextFilterTests, self).setUp() - self.logger = logging.getLogger(uuid.uuid4().hex) - self.handler = RecordingHandler() - self.logger.addHandler(self.handler) - - def test_that_filter_blocks_key_errors(self): - formatter = logging.Formatter('%(message)s [%(context)s]') - self.handler.setFormatter(formatter) - self.handler.addFilter(sprockets.logging.ContextFilter( - properties=['context'])) - self.logger.info('hi there') - - def test_that_filter_does_not_overwrite_extras(self): - formatter = logging.Formatter('%(message)s [%(context)s]') - self.handler.setFormatter(formatter) - self.handler.addFilter(sprockets.logging.ContextFilter( - properties=['context'])) - self.logger.info('hi there', extra={'context': 'foo'}) - self.assertEqual(self.handler.log_lines[-1], 'hi there [foo]') + def get(self): + if self.get_query_argument('runtime_error', default=None): + raise RuntimeError(self.get_query_argument('runtime_error')) + if self.get_query_argument('status_code', default=None) is not None: + self.set_status(int(self.get_query_argument('status_code'))) + else: + self.set_status(204) -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} +class RecordingHandler(logging.Handler): def __init__(self): - self.duration = random.randint(10, 200) + super(RecordingHandler, self).__init__() + self.emitted = [] - def request_time(self): - return self.duration + def emit(self, record): + self.emitted.append((record, self.format(record))) -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, - 'environment': os.environ['ENVIRONMENT']}) - sprockets.logging.tornado_log_function(handler) - access_log.info.assert_called_once_with(*expectation) - - - -class JSONRequestHandlerTestCase(unittest.TestCase): +class TornadoLoggingTestMixin(object): def setUp(self): - self.maxDiff = 32768 + super(TornadoLoggingTestMixin, self).setUp() + self.access_log = logging.getLogger('tornado.access') + self.app_log = logging.getLogger('tornado.application') + self.gen_log = logging.getLogger('tornado.general') + for logger in (self.access_log, self.app_log, self.gen_log): + logger.disabled = False - 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) - result = logging_handler.results.pop(0) - keys = ['line_number', 'file', 'level', 'module', 'name', - 'process', 'thread', 'timestamp', 'request'] - value = json.loads(result) - for key in keys: - self.assertIn(key, value) - - -class JSONRequestFormatterTestCase(testing.AsyncHTTPTestCase): - - def setUp(self): - super(JSONRequestFormatterTestCase, self).setUp() self.recorder = RecordingHandler() - self.formatter = sprockets.logging.JSONRequestFormatter() - self.recorder.setFormatter(self.formatter) - web.app_log.addHandler(self.recorder) + root_logger = logging.getLogger() + root_logger.addHandler(self.recorder) def tearDown(self): - super(JSONRequestFormatterTestCase, self).tearDown() - web.app_log.removeHandler(self.recorder) + super(TornadoLoggingTestMixin, self).tearDown() + logging.getLogger().removeHandler(self.recorder) + + +class TornadoLogFunctionTests(TornadoLoggingTestMixin, + testing.AsyncHTTPTestCase): def get_app(self): - class JustFail(web.RequestHandler): - def get(self): - raise RuntimeError('something busted') + return web.Application( + [web.url('/', SimpleHandler)], + log_function=sprockets.logging.tornado_log_function) - return web.Application([web.url('/', JustFail)]) + @property + def access_record(self): + for record, _ in self.recorder.emitted: + if record.name == 'tornado.access': + return record - def test_that_things_happen(self): - self.fetch('/') - self.assertEqual(len(self.recorder.log_lines), 1) + def test_that_redirect_logged_as_info(self): + self.fetch('?status_code=303') + self.assertEqual(self.access_record.levelno, logging.INFO) - failure_info = json.loads(self.recorder.log_lines[0]) - self.assertEqual(failure_info['traceback']['type'], 'RuntimeError') - self.assertEqual(failure_info['traceback']['message'], - 'something busted') - self.assertEqual(len(failure_info['traceback']['stack']), 2) + def test_that_client_error_logged_as_warning(self): + self.fetch('?status_code=400') + self.assertEqual(self.access_record.levelno, logging.WARNING) + + def test_that_exception_is_logged_as_error(self): + self.fetch('/?runtime_error=something%20bad%20happened') + self.assertEqual(self.access_record.levelno, logging.ERROR) + + def test_that_log_includes_correlation_id(self): + self.fetch('/?runtime_error=something%20bad%20happened') + self.assertIn('correlation_id', self.access_record.args) + + def test_that_log_includes_duration(self): + self.fetch('/?runtime_error=something%20bad%20happened') + self.assertIn('duration', self.access_record.args) + + def test_that_log_includes_headers(self): + self.fetch('/?runtime_error=something%20bad%20happened') + self.assertIn('headers', self.access_record.args) + + def test_that_log_includes_method(self): + self.fetch('/?runtime_error=something%20bad%20happened') + self.assertEqual(self.access_record.args['method'], 'GET') + + def test_that_log_includess_path(self): + self.fetch('/?runtime_error=something%20bad%20happened') + self.assertEqual(self.access_record.args['path'], '/') + + def test_that_log_includes_protocol(self): + self.fetch('/?runtime_error=something%20bad%20happened') + self.assertEqual(self.access_record.args['protocol'], 'http') + + def test_that_log_includes_query_arguments(self): + self.fetch('/?runtime_error=something%20bad%20happened') + self.assertEqual(self.access_record.args['query_args'], + {'runtime_error': ['something bad happened']}) + + def test_that_log_includes_remote_ip(self): + self.fetch('/?runtime_error=something%20bad%20happened') + self.assertIn('remote_ip', self.access_record.args) + + def test_that_log_includes_status_code(self): + self.fetch('/?runtime_error=something%20bad%20happened') + self.assertEqual(self.access_record.args['status_code'], 500) + + def test_that_log_includes_environment(self): + self.fetch('/?runtime_error=something%20bad%20happened') + self.assertEqual(self.access_record.args['environment'], + os.environ['ENVIRONMENT']) + + def test_that_log_includes_correlation_id_from_header(self): + cid = str(uuid.uuid4()) + self.fetch('/?runtime_error=something%20bad%20happened', + headers={'Correlation-ID': cid}) + self.assertEqual(self.access_record.args['correlation_id'], cid) From 5ae094d9be14e29eaad0d6c35d91b681bf338c28 Mon Sep 17 00:00:00 2001 From: Dave Shawley Date: Mon, 14 Sep 2015 07:28:23 -0400 Subject: [PATCH 02/10] Fix query-arg escaping defect uncovered by proper testing. --- sprockets/logging.py | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/sprockets/logging.py b/sprockets/logging.py index d6a85f8..56ef471 100644 --- a/sprockets/logging.py +++ b/sprockets/logging.py @@ -18,8 +18,9 @@ import sys import traceback try: - from tornado import log -except ImportError: + from tornado import escape, log +except ImportError: # pragma no cover + escape = None log = None version_info = (1, 3, 0) @@ -148,7 +149,8 @@ def tornado_log_function(handler): 'method': handler.request.method, 'path': handler.request.path, 'protocol': handler.request.protocol, - 'query_args': handler.request.query_arguments, + 'query_args': escape.recursive_unicode( + handler.request.query_arguments), 'remote_ip': handler.request.remote_ip, 'status_code': status_code, 'environment': os.environ.get('ENVIRONMENT')}) From fb39993583c8377b245cca13a04f2a9792f4a092 Mon Sep 17 00:00:00 2001 From: Dave Shawley Date: Mon, 14 Sep 2015 07:32:43 -0400 Subject: [PATCH 03/10] Add JSONRequestFormatter tests. --- tests.py | 34 ++++++++++++++++++++++++++++++++++ 1 file changed, 34 insertions(+) diff --git a/tests.py b/tests.py index 6fbba6d..21aee31 100644 --- a/tests.py +++ b/tests.py @@ -126,3 +126,37 @@ class TornadoLogFunctionTests(TornadoLoggingTestMixin, self.fetch('/?runtime_error=something%20bad%20happened', headers={'Correlation-ID': cid}) self.assertEqual(self.access_record.args['correlation_id'], cid) + + +class JSONFormatterTests(TornadoLoggingTestMixin, testing.AsyncHTTPTestCase): + + def setUp(self): + super(JSONFormatterTests, self).setUp() + self.recorder.setFormatter(sprockets.logging.JSONRequestFormatter()) + + def get_app(self): + return web.Application( + [web.url('/', SimpleHandler)], + log_function=sprockets.logging.tornado_log_function) + + def get_log_line(self, log_name): + for record, line in self.recorder.emitted: + if record.name == log_name: + return json.loads(line) + + def test_that_messages_are_json_encoded(self): + self.fetch('/') + for record, line in self.recorder.emitted: + json.loads(line) + + def test_that_exception_has_traceback(self): + self.fetch('/?runtime_error=foo') + entry = self.get_log_line('tornado.application') + self.assertIsNotNone(entry.get('traceback')) + self.assertNotEqual(entry['traceback'], []) + + def test_that_successes_do_not_have_traceback(self): + self.fetch('/') + for record, line in self.recorder.emitted: + entry = json.loads(line) + self.assertNotIn('traceback', entry) From 6f476f3fc88e3f55224d24fc4b27a1d846cd77de Mon Sep 17 00:00:00 2001 From: Dave Shawley Date: Mon, 14 Sep 2015 07:32:59 -0400 Subject: [PATCH 04/10] Add ContextFilter tests. --- tests.py | 29 +++++++++++++++++++++++++++++ 1 file changed, 29 insertions(+) diff --git a/tests.py b/tests.py index 21aee31..55a0404 100644 --- a/tests.py +++ b/tests.py @@ -160,3 +160,32 @@ class JSONFormatterTests(TornadoLoggingTestMixin, testing.AsyncHTTPTestCase): for record, line in self.recorder.emitted: entry = json.loads(line) self.assertNotIn('traceback', entry) + + +class ContextFilterTests(TornadoLoggingTestMixin, unittest.TestCase): + + def setUp(self): + super(ContextFilterTests, self).setUp() + self.logger = logging.getLogger('test-logger') + self.recorder.setFormatter( + logging.Formatter('%(message)s {CID %(correlation_id)s}')) + self.recorder.addFilter(sprockets.logging.ContextFilter( + properties=['correlation_id'])) + + def test_that_property_is_set_to_none_by_filter_when_missing(self): + self.logger.error('error message') + _, line = self.recorder.emitted[0] + self.assertEqual(line, 'error message {CID None}') + + def test_that_extras_property_is_used(self): + self.logger.error('error message', + extra={'correlation_id': 'CORRELATION-ID'}) + _, line = self.recorder.emitted[0] + self.assertEqual(line, 'error message {CID CORRELATION-ID}') + + def test_that_property_from_logging_adapter_works(self): + cid = uuid.uuid4() + logger = logging.LoggerAdapter(self.logger, {'correlation_id': cid}) + logger.error('error message') + _, line = self.recorder.emitted[0] + self.assertEqual(line, 'error message {CID %s}' % cid) From 6b56545b8d9271d6535f5b660c5bd48fa10a85d8 Mon Sep 17 00:00:00 2001 From: Dave Shawley Date: Mon, 14 Sep 2015 07:33:57 -0400 Subject: [PATCH 05/10] Adjust nosetests default parameters. --- setup.cfg | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/setup.cfg b/setup.cfg index 36b7d39..6181740 100644 --- a/setup.cfg +++ b/setup.cfg @@ -2,6 +2,6 @@ universal = 1 [nosetests] -with-coverage = 1 +cover-branches = 1 cover-erase = 1 cover-package = sprockets.logging From ce107d8d1ec4f7ef74bc79ad5fec2e620a8ab8b2 Mon Sep 17 00:00:00 2001 From: Dave Shawley Date: Mon, 14 Sep 2015 07:34:19 -0400 Subject: [PATCH 06/10] Add testing against tornado3 via tox. --- tox.ini | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/tox.ini b/tox.ini index 7159afe..4d2e5ad 100644 --- a/tox.ini +++ b/tox.ini @@ -1,5 +1,5 @@ [tox] -envlist = py27,py34 +envlist = py27,py34,tornado3 indexserver = default = https://pypi.python.org/simple toxworkdir = build/tox @@ -11,3 +11,9 @@ deps = nose mock tornado + +[testenv:tornado3] +deps = + nose + mock + tornado>=3,<4 From 5c0b5b239cbb393af4a9fb06516c914330b2c8b9 Mon Sep 17 00:00:00 2001 From: Dave Shawley Date: Mon, 14 Sep 2015 07:37:17 -0400 Subject: [PATCH 07/10] Remove mock from requirements set. --- .travis.yml | 2 +- setup.py | 3 --- tox.ini | 4 +--- 3 files changed, 2 insertions(+), 7 deletions(-) diff --git a/.travis.yml b/.travis.yml index c434ea3..025e9ea 100644 --- a/.travis.yml +++ b/.travis.yml @@ -4,7 +4,7 @@ python: - pypy - 3.4 before_install: -- pip install nose coverage codecov mock tornado +- pip install nose coverage codecov tornado install: - pip install -e . script: nosetests diff --git a/setup.py b/setup.py index 0b1c765..e6dbfcd 100755 --- a/setup.py +++ b/setup.py @@ -11,9 +11,6 @@ install_requires = [] setup_requires = [] tests_require = ['nose>=1.3,<2', 'tornado>3,<5'] -if sys.version_info < (3, 0): - tests_require.append('mock') - setuptools.setup( name='sprockets.logging', version=sprockets.logging.__version__, diff --git a/tox.ini b/tox.ini index 4d2e5ad..3ca1f94 100644 --- a/tox.ini +++ b/tox.ini @@ -1,5 +1,5 @@ [tox] -envlist = py27,py34,tornado3 +envlist = py27,py34,pypy,pypy3,tornado3 indexserver = default = https://pypi.python.org/simple toxworkdir = build/tox @@ -9,11 +9,9 @@ skip_missing_interpreters = true commands = nosetests [] deps = nose - mock tornado [testenv:tornado3] deps = nose - mock tornado>=3,<4 From f72a1a665dfce93f54e268689cfd3a9128298462 Mon Sep 17 00:00:00 2001 From: Dave Shawley Date: Mon, 14 Sep 2015 07:48:00 -0400 Subject: [PATCH 08/10] Documentation corrections. --- docs/examples.rst | 4 ++-- docs/history.rst | 10 +++++++--- 2 files changed, 9 insertions(+), 5 deletions(-) diff --git a/docs/examples.rst b/docs/examples.rst index b48d6e1..691ebda 100644 --- a/docs/examples.rst +++ b/docs/examples.rst @@ -23,10 +23,10 @@ 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 +the :func:`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`` +as the formatter and passes :func:`tornado_log_function` in as the ``log_function`` when creating the Tornado application. .. literalinclude:: ../examples/tornado-json-logger.py diff --git a/docs/history.rst b/docs/history.rst index 5fd23c8..56057b6 100644 --- a/docs/history.rst +++ b/docs/history.rst @@ -17,19 +17,23 @@ Version History `1.1.0`_ Jun 18, 2015 --------------------- - Added :class:`sprockets.logging.JSONRequestFormatter` - - Added :method:`sprockets.logging.tornado_log_function` + - Added :func:`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` + - :func:`sprockets.logging.dictConfig` to :func:`logging.config.dictConfig` + - :func:`sprockets.logging.getLogger` to :func:`logging.getLogger` `1.0.0`_ Jun 09, 2015 --------------------- - Added :class:`sprockets.logging.ContextFilter` +.. _1.3.0: https://github.com/sprockets/sprockets.logging/compare/1.2.1...1.3.0 +.. _1.2.1: https://github.com/sprockets/sprockets.logging/compare/1.2.0...1.2.1 +.. _1.2.0: https://github.com/sprockets/sprockets.logging/compare/1.1.0...1.2.0 .. _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 From 8a37300bf64c75acc193e382bdb7f6d51f4219b1 Mon Sep 17 00:00:00 2001 From: Dave Shawley Date: Mon, 14 Sep 2015 07:48:23 -0400 Subject: [PATCH 09/10] Remove redundancies from index.rst. --- docs/index.rst | 11 +---------- 1 file changed, 1 insertion(+), 10 deletions(-) diff --git a/docs/index.rst b/docs/index.rst index a75654d..9a14c6f 100644 --- a/docs/index.rst +++ b/docs/index.rst @@ -1,22 +1,13 @@ .. include:: ../README.rst -API Documentation ------------------ .. toctree:: :maxdepth: 2 + :hidden: api examples history -Version History ---------------- -See :doc:`history` - -Issues ------- -Please report any issues to the Github project at `https://github.com/sprockets/sprockets.logging/issues `_ - Indices and tables ------------------ From 22e302395df0a6db985cde94f1534a24bb67ec25 Mon Sep 17 00:00:00 2001 From: Dave Shawley Date: Mon, 14 Sep 2015 07:49:12 -0400 Subject: [PATCH 10/10] Version bump to 1.3.1 --- docs/history.rst | 5 +++++ sprockets/logging.py | 2 +- 2 files changed, 6 insertions(+), 1 deletion(-) diff --git a/docs/history.rst b/docs/history.rst index 56057b6..fa20add 100644 --- a/docs/history.rst +++ b/docs/history.rst @@ -1,6 +1,10 @@ Version History =============== +`1.3.1`_ Sep 14, 2015 +--------------------- +- Fix query_arguments handling in Python 3 + `1.3.0`_ Aug 28, 2015 --------------------- - Add the traceback and environment if set @@ -32,6 +36,7 @@ Version History --------------------- - Added :class:`sprockets.logging.ContextFilter` +.. _1.3.1: https://github.com/sprockets/sprockets.logging/compare/1.3.0...1.3.1 .. _1.3.0: https://github.com/sprockets/sprockets.logging/compare/1.2.1...1.3.0 .. _1.2.1: https://github.com/sprockets/sprockets.logging/compare/1.2.0...1.2.1 .. _1.2.0: https://github.com/sprockets/sprockets.logging/compare/1.1.0...1.2.0 diff --git a/sprockets/logging.py b/sprockets/logging.py index 56ef471..df72f9c 100644 --- a/sprockets/logging.py +++ b/sprockets/logging.py @@ -23,7 +23,7 @@ except ImportError: # pragma no cover escape = None log = None -version_info = (1, 3, 0) +version_info = (1, 3, 1) __version__ = '.'.join(str(v) for v in version_info) # Shortcut methods and constants to avoid needing to import logging directly