Merge pull request #21 from percival-detector/debug_request_logging

Implemented debug request logging - closes #20

odin/http/server.py

@@ -9,6 +9,7 @@
 import tornado.gen
 import tornado.web
 import tornado.ioloop
+from tornado.log import access_log
 
 from odin.http.routes.api import ApiRoute
 from odin.http.routes.default import DefaultRoute
@@ -26,6 +27,7 @@ def __init__(self, debug_mode=False, static_path='./static', adapters=None):
         """
         settings = {
             "debug": debug_mode,
+            "log_function": self.log_request,
         }
 
         # Create an API route
@@ -52,6 +54,26 @@ def listen(self, port, host=''):
         """
         self.application.listen(port, host)
 
+    def log_request(self, handler):
+        """Log completed request information.
+
+        This method is passed to the tornado.web.Application instance to override the
+        default request logging behaviour. In doing so, successful requests are logged
+        at debug level rather than info in order to reduce the rate of logging under
+        normal conditions.
+
+        :param handler: currently active request handler
+        """
+        if handler.get_status() < 400:
+            log_method = access_log.debug
+        elif handler.get_status() < 500:
+            log_method = access_log.warning
+        else:
+            log_method = access_log.error
+        request_time = 1000.0 * handler.request.request_time()
+        log_method("%d %s %.2fms", handler.get_status(),
+                   handler._request_summary(), request_time)
+
     def cleanup_adapters(self):
         """Clean up state of registered adapters.
         """

odin/testing/test_server.py

@@ -1,11 +1,15 @@
-from nose.tools import *
-
+import sys
+if sys.version_info[0] == 3:  # pragma: no cover
+    from unittest.mock import Mock
+else:                         # pragma: no cover
+    from mock import Mock
 import requests
 import json
+from nose.tools import *
 
-from odin.testing.utils import OdinTestServer
+from odin.testing.utils import OdinTestServer, LogCaptureFilter
 from odin import server
-
+from odin.http.server import HttpServer
 
 class TestOdinServer(OdinTestServer):
 
@@ -136,6 +140,41 @@ def test_server_missing_adapters(self):
 
         assert_true(no_adapters_msg_seen)
 
+class TestOdinHttpServerLogging():
+
+    @classmethod
+    def setup_class(cls):
+        cls.http_server = HttpServer(adapters=[])
+        cls.handler = Mock()
+        cls.handler.get_status = Mock(return_value=200)
+        cls.request_summary = 'request'
+        cls.handler._request_summary = Mock(return_value=cls.request_summary)
+        cls.handler.request = Mock()
+        cls.request_time = 1234
+        cls.handler.request.request_time = Mock(return_value=cls.request_time)
+        cls.log_capture_filter = LogCaptureFilter()
+
+    def do_log_request(self, http_status, capture_filter_getter):
+
+        self.handler.get_status.return_value = http_status
+        self.http_server.log_request(self.handler)
+
+        msg_seen = False
+        for msg in capture_filter_getter:
+            if msg == '{:d} {:s} {:.2f}ms'.format(
+                    http_status, self.request_summary, self.request_time*1000.0):
+                msg_seen = True
+        return msg_seen
+
+    def test_success_logging(self):
+        assert_true(self.do_log_request(200, self.log_capture_filter.log_debug()))
+
+    def test_warning_logging(self):
+        assert_true(self.do_log_request(404, self.log_capture_filter.log_warning()))
+
+    def test_error_logging(self):
+        assert_true(self.do_log_request(503, self.log_capture_filter.log_error()))
+
 if __name__ == '__main__': #pragma: no cover
 
     import nose