Merge pull request #8 from sprockets/fix-query-arg-handling

Fix query arg handling

.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

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

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
@@ -17,19 +21,24 @@ 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`
+  - :func:`sprockets.logging.dictConfig` to :func:`logging.config.dictConfig`
-  - :method:`sprockets.logging.getLogger` to :method:`logging.getLogger`
+  - :func:`sprockets.logging.getLogger` to :func:`logging.getLogger`
 
 `1.0.0`_ Jun 09, 2015
 ---------------------
  - 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
 .. _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

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 <https://github.com/sprockets/sprockets.logging/issues>`_
-
 Indices and tables
 ------------------
 

setup.cfg

@@ -2,6 +2,6 @@
 universal = 1
 
 [nosetests]
-with-coverage = 1
+cover-branches = 1
 cover-erase = 1
 cover-package = sprockets.logging

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__,

sprockets/logging.py

@@ -18,11 +18,12 @@ import sys
 import traceback
 
 try:
-    from tornado import log
+    from tornado import escape, log
-except ImportError:
+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
@@ -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')})

tests.py

@@ -1,172 +1,191 @@
 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__)
+import sprockets.logging
-os.environ['ENVIRONMENT'] = 'testing'
-
-class Prototype(object):
-    pass
 
 
-class RecordingHandler(logging.FileHandler):
+def setup_module():
+    os.environ.setdefault('ENVIRONMENT', 'development')
+
+
+class SimpleHandler(web.RequestHandler):
+
+    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 RecordingHandler(logging.Handler):
+
     def __init__(self):
-        logging.FileHandler.__init__(self, filename='/dev/null')
+        super(RecordingHandler, self).__init__()
-        self.log_lines = []
+        self.emitted = []
 
-    def format(self, record):
+    def emit(self, record):
-        log_line = logging.FileHandler.format(self, record)
+        self.emitted.append((record, self.format(record)))
-        self.log_lines.append(log_line)
-        return log_line
 
 
-class ContextFilterTests(unittest.TestCase):
+class TornadoLoggingTestMixin(object):
+
+    def setUp(self):
+        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
+
+        self.recorder = RecordingHandler()
+        root_logger = logging.getLogger()
+        root_logger.addHandler(self.recorder)
+
+    def tearDown(self):
+        super(TornadoLoggingTestMixin, self).tearDown()
+        logging.getLogger().removeHandler(self.recorder)
+
+
+class TornadoLogFunctionTests(TornadoLoggingTestMixin,
+                              testing.AsyncHTTPTestCase):
+
+    def get_app(self):
+        return web.Application(
+            [web.url('/', SimpleHandler)],
+            log_function=sprockets.logging.tornado_log_function)
+
+    @property
+    def access_record(self):
+        for record, _ in self.recorder.emitted:
+            if record.name == 'tornado.access':
+                return record
+
+    def test_that_redirect_logged_as_info(self):
+        self.fetch('?status_code=303')
+        self.assertEqual(self.access_record.levelno, logging.INFO)
+
+    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)
+
+
+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)
+
+
+class ContextFilterTests(TornadoLoggingTestMixin, unittest.TestCase):
 
     def setUp(self):
         super(ContextFilterTests, self).setUp()
-        self.logger = logging.getLogger(uuid.uuid4().hex)
+        self.logger = logging.getLogger('test-logger')
-        self.handler = RecordingHandler()
+        self.recorder.setFormatter(
-        self.logger.addHandler(self.handler)
+            logging.Formatter('%(message)s {CID %(correlation_id)s}'))
+        self.recorder.addFilter(sprockets.logging.ContextFilter(
+            properties=['correlation_id']))
 
-    def test_that_filter_blocks_key_errors(self):
+    def test_that_property_is_set_to_none_by_filter_when_missing(self):
-        formatter = logging.Formatter('%(message)s [%(context)s]')
+        self.logger.error('error message')
-        self.handler.setFormatter(formatter)
+        _, line = self.recorder.emitted[0]
-        self.handler.addFilter(sprockets.logging.ContextFilter(
+        self.assertEqual(line, 'error message {CID None}')
-            properties=['context']))
-        self.logger.info('hi there')
 
-    def test_that_filter_does_not_overwrite_extras(self):
+    def test_that_extras_property_is_used(self):
-        formatter = logging.Formatter('%(message)s [%(context)s]')
+        self.logger.error('error message',
-        self.handler.setFormatter(formatter)
+                          extra={'correlation_id': 'CORRELATION-ID'})
-        self.handler.addFilter(sprockets.logging.ContextFilter(
+        _, line = self.recorder.emitted[0]
-            properties=['context']))
+        self.assertEqual(line, 'error message {CID CORRELATION-ID}')
-        self.logger.info('hi there', extra={'context': 'foo'})
-        self.assertEqual(self.handler.log_lines[-1], 'hi there [foo]')
 
-
+    def test_that_property_from_logging_adapter_works(self):
-class MockRequest(object):
+        cid = uuid.uuid4()
-
+        logger = logging.LoggerAdapter(self.logger, {'correlation_id': cid})
-    headers = {'Accept': 'application/msgpack',
+        logger.error('error message')
-               'Correlation-ID': str(uuid.uuid4())}
+        _, line = self.recorder.emitted[0]
-    method = 'GET'
+        self.assertEqual(line, 'error message {CID %s}' % cid)
-    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,
-                            'environment': os.environ['ENVIRONMENT']})
-        sprockets.logging.tornado_log_function(handler)
-        access_log.info.assert_called_once_with(*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)
-        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)
-
-    def tearDown(self):
-        super(JSONRequestFormatterTestCase, self).tearDown()
-        web.app_log.removeHandler(self.recorder)
-
-    def get_app(self):
-        class JustFail(web.RequestHandler):
-            def get(self):
-                raise RuntimeError('something busted')
-
-        return web.Application([web.url('/', JustFail)])
-
-    def test_that_things_happen(self):
-        self.fetch('/')
-        self.assertEqual(len(self.recorder.log_lines), 1)
-
-        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)

tox.ini

@@ -1,5 +1,5 @@
 [tox]
-envlist = py27,py34
+envlist = py27,py34,pypy,pypy3,tornado3
 indexserver =
     default = https://pypi.python.org/simple
 toxworkdir = build/tox
@@ -9,5 +9,9 @@ skip_missing_interpreters = true
 commands = nosetests []
 deps =
     nose
-    mock
     tornado
+
+[testenv:tornado3]
+deps =
+	nose
+	tornado>=3,<4