Merge pull request #6 from sprockets/add-error-mixin-tooooooo

Add Error Reporting Mix-ins

README.rst

@@ -1,6 +1,9 @@
 sprockets.http
 ==============
-This library runs Tornado HTTP server applications intelligently.
+The goal of this library is to make it a little easier to develop great
+HTTP API services using the Tornado web framework.  It concentrates on
+running applications in a reliable & resilient manner and handling errors
+in a clean manner.
 
 * ``SIGTERM`` is gracefully handled with respect to outstanding timeouts
   and callbacks
@@ -12,15 +15,17 @@ This library runs Tornado HTTP server applications intelligently.
   - catches ``SIGINT`` (e.g., ``Ctrl+C``)
   - application run in a single process
 
-Example Usage
--------------
+Running Your Application
+------------------------
+Running a Tornado application intelligently should be very easy.  Ideally
+your application wrapping code should look something like the following.
 
 .. code-block:: python
 
    from tornado import web
    import sprockets.http
 
-   
+
    def make_app(**settings):
        return web.Application([
           # insert your handlers
@@ -30,3 +35,149 @@ Example Usage
    if __name__ == '__main__':
        sprockets.http.run(make_app)
 
+That's it.  The ``sprockets.http.run`` function will set up signal
+handlers and make sure that your application terminates gracefully
+when it is sent either an interrupt or terminate signal.
+
+It also takes care of configuring the standard `logging`_ module albeit
+in a opinionated way.  The goal is to let you write your application
+without worrying about figuring out how to run and monitor it reliably.
+
+.. _logging: https://docs.python.org/3/library/logging.html#module-logging
+
+Error Logging
+-------------
+Handling errors should be simple as well.  Tornado already does a great
+job of isolating the error handling into two methods on the request
+handler:
+
+- `send_error`_ is called by a request handler to send a HTTP error code
+  to the caller.  This is what you should be calling in your code.  It
+  handles setting the status, reporting the error, and finishing the
+  request out.
+
+- `write_error`_ is called by ``send_error`` when it needs to send an
+  error document to the caller.  This should be overridden when you need
+  to provide customized error pages.  The important thing to realize is
+  that ``send_error`` calls ``write_error``.
+
+.. _send_error: http://www.tornadoweb.org/en/branch4.0/web.html#tornado.web.RequestHandler.send_error
+.. _write_error: http://www.tornadoweb.org/en/branch4.0/web.html#tornado.web.RequestHandler.write_error
+
+So your request handlers are already doing something like the following:
+
+.. code-block:: python
+
+   class MyHandler(web.RequestHandler):
+       def get(self):
+          try:
+             do_something()
+          except:
+             self.send_error(500, reason='Uh oh!')
+             return
+
+In order for this to be really useful to you (the one that gets pinged
+when a failure happens), you need to have some information in your
+application logs that points to the problem.  Cool... so do something
+like this then:
+
+.. code-block:: python
+
+   class MyHandler(web.RequestHandler):
+       def get(self):
+          try:
+             do_something()
+          except:
+             LOGGER.exception('do_something exploded for %s - returning %s',
+                              self.request.uri, '500 Uh oh!')
+             self.send_error(500, reason='Uh oh!')
+             return
+
+Simple enough.  This works in the small, but think about how this approach
+scales.  After a while your error handling might end up looking like:
+
+.. code-block:: python
+
+   class MyHandler(web.RequestHandler):
+       def get(self):
+          try:
+             do_something()
+
+          except SomethingSerious:
+             LOGGER.exception('do_something exploded for %s - returning %s',
+                              self.request.uri, '500 Uh oh!')
+             self.send_error(500, reason='Uh oh!')
+             return
+
+          except SomethingYouDid:
+             LOGGER.exception('do_something exploded for %s - returning %s',
+                              self.request.uri, '400 Stop That')
+             self.send_error(400, reason='Stop That')
+             return
+
+Or maybe you are raising `tornado.web.HTTPError`_ instead of calling
+``send_error`` -- *send_error will be called for you in this case*.
+The ``sprockets.http.mixins.ErrorLogger`` mix-in extends ``write_error``
+to log the failure to the ``self.logger`` **BEFORE** calling the ``super``
+implementation.  This very simple piece of functionality ensures that when
+your application is calling ``send_error`` to signal errors you are writing
+the failure out somewhere so you will have it later.
+
+.. _tornado.web.HTTPError: http://www.tornadoweb.org/en/branch4.0/web.html#tornado.web.HTTPError
+
+It is also nice enough to log 4xx status codes as warnings, 5xx codes as
+errors, and include exception tracebacks if an exception is being handled.
+You can go back to writing ``self.send_error`` and let someone else keep
+track of what happened.
+
+Error Response Documents
+------------------------
+Now that we have useful information in our log files, we should be returning
+something useful as well.  By default, the Tornado provided ``send_error``
+implementation writes a simple HTML file as the response body.  The
+``sprockets.http.mixins.ErrorWriter`` mix-in provides an implementation of
+``write_error`` that is more ammenable to programmatic usage.  In particular,
+it uses a JSON body since that is the *defacto* format these days.  Let's
+look at our example again:
+
+.. code-block:: python
+
+   class MyHandler(web.RequestHandler):
+       def get(self):
+          try:
+             do_something()
+          except:
+             self.send_error(500, reason='Uh oh!')
+             return
+
+The implementation of ``tornado.web.RequestHandler.write_error`` will produce
+a response that looks something like:
+
+.. code-block:: http
+
+   HTTP/1.1 500 Uh oh!
+   Server: TornadoServer/4.2.1
+   Content-Type: text/html; charset=UTF-8
+   Date: Fri, 20 Nov 2015 08:10:25 GMT
+
+   <html><title>500: Uh oh!</title><body>500: Uh oh!</body></html>
+
+That is a lot better than nothing but not very useful when your user is
+someone else's code.  By adding ``sprockets.http.mixins.ErrorWriter`` to
+the handler's inheritance chain, we would get the following response
+instead:
+
+.. code-block:: http
+
+   HTTP/1.1 500 Uh oh!
+   Server: TornadoServer/4.2.1
+   Content-Type: application/json
+   Date: Fri, 20 Nov 2015 08:10:25 GMT
+
+   {"message": "Uh oh!", "type": null, "traceback": null}
+
+The ``traceback`` and ``type`` properties hint at the fact that exceptions
+are handled in a manner similar to what Tornado would do -- if the call to
+``send_error`` includes exception information, then the exception's type
+will be included in the response.  The ``traceback`` is only included when
+the standard ``serve_traceback`` Tornado option is enabled.

docs/api.rst

@@ -1,10 +1,12 @@
 API Documentation
 =================
-.. automodule:: sprockets.http
-   :members:
+
+Application Runner
+------------------
+.. autofunction:: sprockets.http.run
 
 Application Callbacks
----------------------
+~~~~~~~~~~~~~~~~~~~~~
 Starting with version 0.4.0, :func:`sprockets.http.run` augments the
 :class:`tornado.web.Application` instance with a new attribute named
 ``runner_callbacks`` which is a dictionary of lists of functions to
@@ -16,6 +18,70 @@ See :func:`sprockets.http.run` for a detailed description of how to
 install the runner callbacks.
 
 Internal Interfaces
--------------------
+~~~~~~~~~~~~~~~~~~~
 .. automodule:: sprockets.http.runner
    :members:
+
+Response Logging
+----------------
+Version 0.5.0 introduced the :mod:`sprockets.http.mixins` module with
+two simple classes - :class:`~sprockets.http.mixins.LoggingHandler`
+and :class:`~sprockets.http.mixins.ErrorLogger`.  Together they ensure
+that errors emitted from your handlers will be logged in a consistent
+manner.  All too often request handlers simply call ``write_error``
+to report a failure to the caller with code that looks something like:
+
+.. code-block:: python
+
+   class MyHandler(web.RequestHandler):
+
+      def get(self):
+         try:
+            do_something()
+         except Failure:
+            self.send_error(500, reason='Uh oh')
+            return
+
+This makes debugging an application fun since your caller generally
+has more information about the failure than you do :/
+
+By adding :class:`~sprockets.http.mixins.ErrorLogger` into the inheritance
+chain, your error will be emitted to the application log as if you had
+written the following instead:
+
+.. code-block:: python
+
+   class MyHandler(web.RequestHandler):
+      def initialize(self):
+         super(MyHandler, self).initialize()
+         self.logger = logging.getLogger('MyHandler')
+
+      def get(self):
+         try:
+            do_something()
+         except Failure:
+            self.logger.error('%s %s failed with %d: %s',
+                              self.request.method, self.request.uri,
+                              500, 'Uh oh')
+            self.send_error(500, reason='Uh oh')
+            return
+
+It doesn't look like much, but the error reporting is a little more
+interesting than that -- 4XX errors are reported as a warning,
+exceptions will include the stack traces, etc.
+
+.. autoclass:: sprockets.http.mixins.LoggingHandler
+   :members:
+
+.. autoclass:: sprockets.http.mixins.ErrorLogger
+   :members:
+
+Standardized Error Response Documents
+-------------------------------------
+Version 0.5.0 also introduced the :class:`~sprockets.http.mixins.ErrorWriter`
+class which implements ``write_error`` to provide a standard JSON
+document response instead of the default HTML response that Tornado
+implements.
+
+.. autoclass:: sprockets.http.mixins.ErrorWriter
+   :members:

docs/history.rst

@@ -3,6 +3,12 @@
 Release History
 ===============
 
+`1.0.0`_ (20 Nov 2015)
+----------------------
+- Add ``sprockets.http.mixins.LoggingHandler``
+- Add ``sprockets.http.mixins.ErrorLogger``
+- Add ``sprockets.http.mixins.ErrorWriter``
+
 `0.4.0`_ (24 Sep 2015)
 ----------------------
 - Run callbacks from ``application.runner_callbacks['shutdown']`` when
@@ -28,5 +34,8 @@ Release History
 
 .. _0.2.0: https://github.com/sprockets/sprockets.http/compare/0.0.0...0.2.0
 .. _0.2.1: https://github.com/sprockets/sprockets.http/compare/0.2.0...0.2.1
-.. _0.3.0: https://github.com/sprockets/sprockets.http/compare/0.2.0...0.3.0
+.. _0.2.2: https://github.com/sprockets/sprockets.http/compare/0.2.1...0.2.2
+.. _0.3.0: https://github.com/sprockets/sprockets.http/compare/0.2.2...0.3.0
 .. _0.4.0: https://github.com/sprockets/sprockets.http/compare/0.3.0...0.4.0
+.. _1.0.0: https://github.com/sprockets/sprockets.http/compare/0.4.0...1.0.0
+.. _Next Release: https://github.com/sprockets/sprockets.http/compare/1.0.0...master

examples.py

@@ -0,0 +1,38 @@
+from tornado import web
+
+from sprockets.http import mixins, run
+
+
+class StatusHandler(mixins.ErrorLogger, mixins.ErrorWriter,
+                    web.RequestHandler):
+    """Example that exercises the mix-ins in this library."""
+
+    def get(self, status_code):
+        """
+        Returns the requested status.
+
+        :param int status_code: the status code to return
+        :queryparam str reason: optional reason phrase
+
+        """
+        status_code = int(status_code)
+        if status_code >= 400:
+            kwargs = {'status_code': status_code}
+            if self.get_query_argument('reason', None):
+                kwargs['reason'] = self.get_query_argument('reason')
+            if self.get_query_argument('log_message', None):
+                kwargs['log_message'] = self.get_query_argument('log_message')
+            self.send_error(**kwargs)
+        else:
+            self.set_status(status_code)
+
+
+def make_app(**settings):
+    settings['debug'] = True  # disable JSON logging
+    return web.Application([
+        web.url(r'/status/(?P<status_code>\d+)', StatusHandler),
+    ], **settings)
+
+
+if __name__ == '__main__':
+    run(make_app)

requires/development.txt

@@ -1,5 +1,6 @@
 -rinstallation.txt
 -rtesting.txt
+coverage>=4.0,<5
 sphinx>=1.2,<2
 sphinxcontrib-httpdomain>=1.3,<2
 tox>=1.7,<2

setup.py

@@ -40,7 +40,7 @@ setuptools.setup(
     namespace_packages=['sprockets'],
     packages=setuptools.find_packages(),
     classifiers=[
-        'Development Status :: 4 - Beta',
+        'Development Status :: 5 - Production/Stable',
         'Environment :: No Input/Output (Daemon)',
         'Intended Audience :: Developers',
         'License :: OSI Approved :: BSD License',
@@ -50,7 +50,9 @@ setuptools.setup(
         'Programming Language :: Python :: 2.7',
         'Programming Language :: Python :: 3',
         'Programming Language :: Python :: 3.4',
+        'Programming Language :: Python :: 3.5',
         'Programming Language :: Python :: Implementation :: CPython',
+        'Programming Language :: Python :: Implementation :: PyPy',
         'Topic :: Internet :: WWW/HTTP',
         'Topic :: Software Development :: Libraries',
         'Topic :: Software Development :: Libraries :: Python Modules'],

sprockets/http/__init__.py

@@ -1,7 +1,7 @@
 import os
 
 
-version_info = (0, 4, 0)
+version_info = (1, 0, 0)
 __version__ = '.'.join(str(v) for v in version_info)
 
 

sprockets/http/mixins.py

@@ -0,0 +1,125 @@
+"""
+HTTP related utility mixins.
+
+- :class:`LoggingHandler`: adds ``self.logger``
+- :class:`ErrorLogger`: extends ``send_error`` to log useful information
+- :class:`ErrorWriter`: implements ``send_error`` to write a useful response
+
+"""
+import logging
+import json
+import traceback
+
+from tornado import httputil
+
+
+def _get_http_reason(status_code):
+    return httputil.responses.get(status_code, 'Unknown')
+
+
+class LoggingHandler(object):
+    """
+    Add ``self.logger``.
+
+    Mix this into your inheritance chain to add a ``logger``
+    attribute unless one already exists.
+
+    .. attribute:: logger
+
+       Instance of :class:`logging.Logger` with the same name as
+       the class.
+
+    """
+
+    def initialize(self):
+        super(LoggingHandler, self).initialize()
+        if not hasattr(self, 'logger'):
+            self.logger = logging.getLogger(self.__class__.__name__)
+
+
+class ErrorLogger(LoggingHandler, object):
+    """
+    Log a message in ``send_error``.
+
+    Mix this class into your inheritance chain to ensure that
+    errors sent via :meth:`tornado.web.RequestHandler.send_error`
+    and :meth:`tornado.web.RequestHandler.write_error` are written
+    to the log.
+
+    """
+
+    def send_error(self, status_code=500, **kwargs):
+        if kwargs.get('reason', None) is None:
+            # so... ReqehstHandler._handle_request_exception explicitly
+            # discards the exc.reason in the case of web.HTTPError...
+            _, exc, _ = kwargs.get('exc_info', (None, None, None))
+            if getattr(exc, 'reason', None):
+                kwargs['reason'] = exc.reason
+            else:
+                # Oh, and make non-standard HTTP status codes NOT explode!
+                kwargs['reason'] = _get_http_reason(status_code)
+        super(ErrorLogger, self).send_error(status_code, **kwargs)
+
+    def write_error(self, status_code, **kwargs):
+        log_function = self.logger.debug
+        if 400 <= status_code < 500:
+            log_function = self.logger.warning
+        else:
+            log_function = self.logger.error
+
+        # N.B. kwargs[reason] is set up by send_error
+        log_function('%s %s failed with %s: %s', self.request.method,
+                     self.request.uri, status_code,
+                     kwargs.get('log_message', kwargs['reason']))
+        super(ErrorLogger, self).write_error(status_code, **kwargs)
+
+
+class ErrorWriter(object):
+    """
+    Write error bodies out consistently.
+
+    Mix this class in to your inheritance chain to include error
+    bodies as a standard JSON document.  The error document has
+    three simple properties:
+
+    **type**
+        This is the type of exception that occurred or ``null``.
+        It is only set when :meth:`.write_error` is invoked with
+        a non-empty ``exc_info`` parameter.  In that case, it is
+        set to the name of the first value in the :class:`tuple`;
+        IOW, ``exc_type.__name__``.
+
+    **message**
+        This is a description of the error.  If exception info is
+        present, then the stringified exception value is used as
+        the message (e.g., ``str(exc_value)``); otherwise, the HTTP
+        ``reason`` will be used.  If a custom ``reason`` is not
+        present, then the standard HTTP reason phrase is used.  In
+        the final case of a non-standard HTTP status code with
+        neither an exception nor a custom reason, the string ``Unknown``
+        will be used.
+
+    **traceback**
+        If the application is configured to serve tracebacks and the
+        error was caused by an exception (based on ``exc_info`` kwarg),
+        then this is the formatted traceback as an array of strings
+        returned from :func:`traceback.format_exception`.  Otherwise,
+        this property is set to ``null``.
+
+    """
+
+    def write_error(self, status_code, **kwargs):
+        error_body = {'type': None, 'traceback': None}
+        exc_type, exc_value, _ = kwargs.get('exc_info', (None, None, None))
+        if exc_type and exc_value:
+            error_body['type'] = exc_type.__name__
+            error_body.setdefault('message', str(exc_value))
+            if self.settings.get('serve_traceback', False):
+                error_body['traceback'] = traceback.format_exception(
+                    *kwargs['exc_info'])
+        else:
+            reason = kwargs.get('reason', _get_http_reason(status_code))
+            error_body.setdefault('message', reason)
+
+        self.set_header('Content-Type', 'application/json')
+        self.write(json.dumps(error_body).encode('utf-8'))

tests.py

@@ -0,0 +1,163 @@
+import logging
+import json
+
+from tornado import httputil, testing, web
+
+from sprockets.http import mixins
+import examples
+
+
+class RecordingHandler(logging.Handler):
+
+    def __init__(self):
+        super(RecordingHandler, self).__init__()
+        self.emitted = []
+
+    def emit(self, record):
+        self.emitted.append((record, self.format(record)))
+
+
+class RaisingHandler(mixins.ErrorLogger, mixins.ErrorWriter,
+                     web.RequestHandler):
+
+    def get(self, status_code):
+        raise web.HTTPError(int(status_code),
+                            reason=self.get_query_argument('reason', None))
+
+
+class ErrorLoggerTests(testing.AsyncHTTPTestCase):
+
+    def setUp(self):
+        super(ErrorLoggerTests, self).setUp()
+        self.recorder = RecordingHandler()
+        root_logger = logging.getLogger()
+        root_logger.addHandler(self.recorder)
+
+    def tearDown(self):
+        super(ErrorLoggerTests, self).tearDown()
+        logging.getLogger().removeHandler(self.recorder)
+
+    def get_app(self):
+        return web.Application([
+            web.url(r'/status/(?P<status_code>\d+)', examples.StatusHandler),
+            web.url(r'/fail/(?P<status_code>\d+)', RaisingHandler),
+        ])
+
+    def assert_message_logged(self, level, msg_fmt, *msg_args):
+        suffix = msg_fmt.format(*msg_args)
+        for record, message in self.recorder.emitted:
+            if record.levelno == level and message.endswith(suffix):
+                return
+        self.fail('Expected message ending in "%s" to be logged in %r'
+                  % (suffix, self.recorder.emitted))
+
+    def test_that_client_error_logged_as_warning(self):
+        self.fetch('/status/400')
+        self.assert_message_logged(
+            logging.WARNING, 'failed with 400: {}', httputil.responses[400])
+
+    def test_that_server_error_logged_as_error(self):
+        self.fetch('/status/500')
+        self.assert_message_logged(
+            logging.ERROR, 'failed with 500: {}', httputil.responses[500])
+
+    def test_that_custom_status_codes_logged_as_unknown(self):
+        self.fetch('/status/623')
+        self.assert_message_logged(logging.ERROR, 'failed with 623: Unknown')
+
+    def test_that_custom_reasons_are_supported(self):
+        self.fetch('/status/456?reason=oops')
+        self.assert_message_logged(logging.WARNING, 'failed with 456: oops')
+
+    def test_that_status_code_extracted_from_http_errors(self):
+        self.fetch('/fail/400')
+        self.assert_message_logged(
+            logging.WARNING, 'failed with 400: {}', httputil.responses[400])
+
+    def test_that_reason_extracted_from_http_errors(self):
+        self.fetch('/fail/400?reason=oopsie')
+        self.assert_message_logged(logging.WARNING, 'failed with 400: oopsie')
+
+    def test_that_log_message_is_honored(self):
+        self.fetch('/status/400?log_message=injected%20message')
+        self.assert_message_logged(logging.WARNING,
+                                   'failed with 400: injected message')
+
+
+class ErrorWriterTests(testing.AsyncHTTPTestCase):
+
+    def setUp(self):
+        self._application = None
+        super(ErrorWriterTests, self).setUp()
+
+    @property
+    def application(self):
+        if self._application is None:
+            self._application = web.Application([
+                web.url(r'/status/(?P<status_code>\d+)',
+                        examples.StatusHandler),
+                web.url(r'/fail/(?P<status_code>\d+)', RaisingHandler),
+            ])
+        return self._application
+
+    def get_app(self):
+        return self.application
+
+    def _decode_response(self, response):
+        content_type = response.headers['Content-Type']
+        self.assertTrue(content_type.startswith('application/json'),
+                        'Incorrect content type received')
+        return json.loads(response.body.decode('utf-8'))
+
+    def test_that_error_json_contains_error_type(self):
+        response = self.fetch('/fail/400')
+        self.assertEqual(response.code, 400)
+
+        exc = web.HTTPError(400)
+        body = self._decode_response(response)
+        self.assertEqual(body['type'], exc.__class__.__name__)
+
+    def test_that_error_json_contains_error_message(self):
+        response = self.fetch('/fail/400')
+        self.assertEqual(response.code, 400)
+
+        exc = web.HTTPError(400)
+        body = self._decode_response(response)
+        self.assertEqual(body['message'], str(exc))
+
+    def test_that_error_json_ignores_the_log_message(self):
+        response = self.fetch('/status/500?log_message=something%20good')
+        self.assertEqual(response.code, 500)
+
+        body = self._decode_response(response)
+        self.assertEqual(body['message'], httputil.responses[500])
+
+    def test_that_error_json_contains_type_none_for_non_exceptions(self):
+        response = self.fetch('/status/500')
+        self.assertEqual(response.code, 500)
+
+        body = self._decode_response(response)
+        self.assertIsNone(body['type'])
+
+    def test_that_error_json_contains_reason_for_non_exceptions(self):
+        response = self.fetch('/status/500')
+        self.assertEqual(response.code, 500)
+
+        body = self._decode_response(response)
+        self.assertEqual(body['message'], httputil.responses[500])
+
+    def test_that_error_json_reason_contains_unknown_in_some_cases(self):
+        response = self.fetch('/status/567')
+        self.assertEqual(response.code, 567)
+
+        body = self._decode_response(response)
+        self.assertEqual(body['message'], 'Unknown')
+
+    def test_that_error_json_honors_serve_traceback(self):
+        self.application.settings['serve_traceback'] = True
+
+        response = self.fetch('/fail/400')
+        self.assertEqual(response.code, 400)
+
+        body = self._decode_response(response)
+        self.assertGreater(len(body['traceback']), 0)

tox.ini

@@ -1,8 +1,9 @@
 [tox]
-envlist = py27,py34
+envlist = py27,py34,py35,pypy,pypy3
 indexserver =
 	default = https://pypi.python.org/simple
 toxworkdir = build/tox
+skip_missing_interpreters = True
 
 [testenv]
 commands = nosetests []