Add LoggingHandler and ErrorLogger mixins.

README.rst

@@ -14,13 +14,15 @@ This library runs Tornado HTTP server applications intelligently.
 
 Example Usage
 -------------
+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 +32,79 @@ Example Usage
    if __name__ == '__main__':
        sprockets.http.run(make_app)
 
+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`` 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``.
+
+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.
+
+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.

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,60 @@ 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:

docs/history.rst

@@ -3,6 +3,11 @@
 Release History
 ===============
 
+`Next Release`_
+---------------
+- Add ``sprockets.http.mixins.LoggingHandler``
+- Add ``sprockets.http.mixins.ErrorLogger``
+
 `0.4.0`_ (24 Sep 2015)
 ----------------------
 - Run callbacks from ``application.runner_callbacks['shutdown']`` when
@@ -31,3 +36,4 @@ Release History
 .. _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
+.. _Next Release: https://github.com/sprockets/sprockets.http/compare/0.4.0...master

examples.py

@@ -0,0 +1,38 @@
+import os
+
+from tornado import web
+
+from sprockets.http import mixins, run
+
+
+class StatusHandler(mixins.ErrorLogger, web.RequestHandler):
+    """Example that exercises the status code handling of the ErrorLogger."""
+
+    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:
+            if self.get_query_argument('reason', None):
+                self.send_error(status_code=status_code,
+                                reason=self.get_query_argument('reason'))
+            else:
+                self.send_error(status_code=status_code)
+        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)

sprockets/http/mixins.py

@@ -0,0 +1,60 @@
+"""
+HTTP related utility mixins.
+
+- :class:`LoggingHandler`: adds ``self.logger``
+- :class:`ErrorLogger`: extends ``send_error`` to log useful information
+
+"""
+import logging
+
+from tornado import httputil
+
+
+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):
+        # Oh, and make non-standard HTTP status codes NOT explode!
+        if kwargs.get('reason', None) is None:
+            kwargs['reason'] = httputil.responses.get(status_code, 'Unknown')
+        super(ErrorLogger, self).send_error(status_code, **kwargs)
+
+    def write_error(self, status_code=500, **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 %d: %s', self.request.method,
+                     self.request.uri, status_code, kwargs['reason'])
+        super(ErrorLogger, self).write_error(status_code, **kwargs)

tests.py

@@ -0,0 +1,70 @@
+import logging
+
+from tornado import httputil, testing
+
+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 ErrorWriterTests(testing.AsyncHTTPTestCase):
+
+    def setUp(self):
+        super(ErrorWriterTests, self).setUp()
+        self.access_log = logging.getLogger('tornado.access')
+        self.app_log = logging.getLogger('tornado.application')
+        self.gen_log = logging.getLogger('tornado.general')
+        self.handler_log = logging.getLogger('StatusHandler')
+        for logger in (self.access_log, self.app_log, self.gen_log,
+                       self.handler_log):
+            logger.disabled = False
+
+        self.recorder = RecordingHandler()
+        root_logger = logging.getLogger()
+        root_logger.addHandler(self.recorder)
+
+    def tearDown(self):
+        super(ErrorWriterTests, self).tearDown()
+        logging.getLogger().removeHandler(self.recorder)
+
+    def get_app(self):
+        return examples.make_app()
+
+    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.name == self.handler_log.name:
+                self.assertEqual(record.levelno, level)
+                self.assertTrue(
+                    message.endswith(suffix),
+                    'Expected "{}" to end with "{}"'.format(message, suffix))
+                break
+        else:
+            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')