Split out the JsonResource request logging and error handling into a separate wrapper function

synapse/http/server.py

@@ -51,6 +51,71 @@ response_timer = metrics.register_distribution(
     labels=["method", "servlet"]
 )
 
+_next_request_id = 0
+
+
+def request_handler(request_handler):
+    """Wraps a method that acts as a request handler with the necessary logging
+    and exception handling.
+    The method must have a signature of "handle_foo(self, request)".
+    The argument "self" must have "version_string" and "clock" attributes.
+    The argument "request" must be a twisted HTTP request.
+    """
+
+    @defer.inlineCallbacks
+    def wrapped_request_handler(self, request):
+        global _next_request_id
+        request_id = "%s-%s" % (request.method, _next_request_id)
+        _next_request_id += 1
+        with LoggingContext(request_id) as request_context:
+            request_context.request = request_id
+            code = None
+            start = self.clock.time_msec()
+            try:
+                logger.info(
+                    "Received request: %s %s",
+                    request.method, request.path
+                )
+                yield request_handler(self, request)
+                code = request.code
+            except CodeMessageException as e:
+                code = e.code
+                if isinstance(e, SynapseError):
+                    logger.info(
+                        "%s SynapseError: %s - %s", request, code, e.msg
+                    )
+                else:
+                    logger.exception(e)
+                outgoing_responses_counter.inc(request.method, str(code))
+                respond_with_json(
+                    request, code, cs_exception(e), send_cors=True,
+                    pretty_print=_request_user_agent_is_curl(request),
+                    version_string=self.version_string,
+                )
+            except:
+                code = 500
+                logger.exception(
+                    "Failed handle request %s.%s on %r: %r",
+                    request_handler.__module__,
+                    request_handler.__name__,
+                    self,
+                    request
+                )
+                respond_with_json(
+                    request,
+                    500,
+                    {"error": "Internal server error"},
+                    send_cors=True
+                )
+            finally:
+                code = str(code) if code else "-"
+                end = self.clock.time_msec()
+                logger.info(
+                    "Processed request: %dms %s %s %s",
+                    end-start, code, request.method, request.path
+                )
+    return wrapped_request_handler
+
 
 class HttpServer(object):
     """ Interface for registering callbacks on a HTTP server
@@ -115,102 +180,56 @@ class JsonResource(HttpServer, resource.Resource):
     def render(self, request):
         """ This get's called by twisted every time someone sends us a request.
         """
-        self._async_render_with_logging_context(request)
+        self._async_render(request)
         return server.NOT_DONE_YET
 
-    _request_id = 0
+    @request_handler
-
-    @defer.inlineCallbacks
-    def _async_render_with_logging_context(self, request):
-        request_id = "%s-%s" % (request.method, JsonResource._request_id)
-        JsonResource._request_id += 1
-        with LoggingContext(request_id) as request_context:
-            request_context.request = request_id
-            yield self._async_render(request)
-
     @defer.inlineCallbacks
     def _async_render(self, request):
         """ This get's called by twisted every time someone sends us a request.
             This checks if anyone has registered a callback for that method and
             path.
         """
-        code = None
         start = self.clock.time_msec()
-        try:
+        if request.method == "OPTIONS":
-            # Just say yes to OPTIONS.
+            self._send_response(request, 200, {})
-            if request.method == "OPTIONS":
+            return
-                self._send_response(request, 200, {})
+        # Loop through all the registered callbacks to check if the method
-                return
+        # and path regex match
+        for path_entry in self.path_regexs.get(request.method, []):
+            m = path_entry.pattern.match(request.path)
+            if not m:
+                continue
 
-            # Loop through all the registered callbacks to check if the method
+            # We found a match! Trigger callback and then return the
-            # and path regex match
+            # returned response. We pass both the request and any
-            for path_entry in self.path_regexs.get(request.method, []):
+            # matched groups from the regex to the callback.
-                m = path_entry.pattern.match(request.path)
-                if not m:
-                    continue
 
-                # We found a match! Trigger callback and then return the
+            callback = path_entry.callback
-                # returned response. We pass both the request and any
-                # matched groups from the regex to the callback.
 
-                callback = path_entry.callback
+            servlet_instance = getattr(callback, "__self__", None)
-
+            if servlet_instance is not None:
-                servlet_instance = getattr(callback, "__self__", None)
+                servlet_classname = servlet_instance.__class__.__name__
-                if servlet_instance is not None:
-                    servlet_classname = servlet_instance.__class__.__name__
-                else:
-                    servlet_classname = "%r" % callback
-                incoming_requests_counter.inc(request.method, servlet_classname)
-
-                args = [
-                    urllib.unquote(u).decode("UTF-8") for u in m.groups()
-                ]
-
-                logger.info(
-                    "Received request: %s %s",
-                    request.method, request.path
-                )
-
-                code, response = yield callback(request, *args)
-
-                self._send_response(request, code, response)
-                response_timer.inc_by(
-                    self.clock.time_msec() - start, request.method, servlet_classname
-                )
-
-                return
-
-            # Huh. No one wanted to handle that? Fiiiiiine. Send 400.
-            raise UnrecognizedRequestError()
-        except CodeMessageException as e:
-            if isinstance(e, SynapseError):
-                logger.info("%s SynapseError: %s - %s", request, e.code, e.msg)
             else:
-                logger.exception(e)
+                servlet_classname = "%r" % callback
+            incoming_requests_counter.inc(request.method, servlet_classname)
 
-            code = e.code
+            args = [
-            self._send_response(
+                urllib.unquote(u).decode("UTF-8") for u in m.groups()
-                request,
+            ]
-                code,
-                cs_exception(e),
-                response_code_message=e.response_code_message
-            )
-        except Exception as e:
-            logger.exception(e)
-            self._send_response(
-                request,
-                500,
-                {"error": "Internal server error"}
-            )
-        finally:
-            code = str(code) if code else "-"
 
-            end = self.clock.time_msec()
+            code, response = yield callback(request, *args)
-            logger.info(
+
-                "Processed request: %dms %s %s %s",
+            self._send_response(request, code, response)
-                end-start, code, request.method, request.path
+            response_timer.inc_by(
+                self.clock.time_msec() - start, request.method, servlet_classname
             )
 
+            return
+
+        # Huh. No one wanted to handle that? Fiiiiiine. Send 400.
+        raise UnrecognizedRequestError()
+
     def _send_response(self, request, code, response_json_object,
                        response_code_message=None):
         # could alternatively use request.notifyFinish() and flip a flag when
@@ -229,20 +248,10 @@ class JsonResource(HttpServer, resource.Resource):
             request, code, response_json_object,
             send_cors=True,
             response_code_message=response_code_message,
-            pretty_print=self._request_user_agent_is_curl,
+            pretty_print=_request_user_agent_is_curl(request),
             version_string=self.version_string,
         )
 
-    @staticmethod
-    def _request_user_agent_is_curl(request):
-        user_agents = request.requestHeaders.getRawHeaders(
-            "User-Agent", default=[]
-        )
-        for user_agent in user_agents:
-            if "curl" in user_agent:
-                return True
-        return False
-
 
 class RootRedirect(resource.Resource):
     """Redirects the root '/' path to another path."""
@@ -263,8 +272,8 @@ class RootRedirect(resource.Resource):
 def respond_with_json(request, code, json_object, send_cors=False,
                       response_code_message=None, pretty_print=False,
                       version_string=""):
-    if not pretty_print:
+    if pretty_print:
-        json_bytes = encode_pretty_printed_json(json_object)
+        json_bytes = encode_pretty_printed_json(json_object) + "\n"
     else:
         json_bytes = encode_canonical_json(json_object)
 
@@ -304,3 +313,13 @@ def respond_with_json_bytes(request, code, json_bytes, send_cors=False,
     request.write(json_bytes)
     request.finish()
     return NOT_DONE_YET
+
+
+def _request_user_agent_is_curl(request):
+    user_agents = request.requestHeaders.getRawHeaders(
+        "User-Agent", default=[]
+    )
+    for user_agent in user_agents:
+        if "curl" in user_agent:
+            return True
+    return False