diff --git a/README.rst b/README.rst index 18c9b2b..51c226c 100644 --- a/README.rst +++ b/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. diff --git a/docs/api.rst b/docs/api.rst index ef6573b..1e8f3e9 100644 --- a/docs/api.rst +++ b/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: diff --git a/docs/history.rst b/docs/history.rst index 68d9960..772914a 100644 --- a/docs/history.rst +++ b/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 diff --git a/examples.py b/examples.py new file mode 100644 index 0000000..4b35593 --- /dev/null +++ b/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\d+)', StatusHandler), + ], **settings) + + +if __name__ == '__main__': + run(make_app) diff --git a/sprockets/http/mixins.py b/sprockets/http/mixins.py new file mode 100644 index 0000000..c42fe89 --- /dev/null +++ b/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) diff --git a/tests.py b/tests.py new file mode 100644 index 0000000..b66837d --- /dev/null +++ b/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')