Log when we receive a request, when we send a response and how long it took to process it.

4 files changed, 24 insertions, 5 deletions

diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py
index f20ccfb5b6..0f175ec3f4 100755
--- a/synapse/app/homeserver.py
+++ b/synapse/app/homeserver.py
@@ -67,7 +67,7 @@ class SynapseHomeServer(HomeServer):
         return ClientV2AlphaRestResource(self)
 
     def build_resource_for_federation(self):
-        return JsonResource()
+        return JsonResource(self)
 
     def build_resource_for_web_client(self):
         syweb_path = os.path.dirname(syweb.__file__)
diff --git a/synapse/http/server.py b/synapse/http/server.py
index 0f6539e1be..6d084fa33c 100644
--- a/synapse/http/server.py
+++ b/synapse/http/server.py
@@ -69,9 +69,10 @@ class JsonResource(HttpServer, resource.Resource):
 
     _PathEntry = collections.namedtuple("_PathEntry", ["pattern", "callback"])
 
-    def __init__(self):
+    def __init__(self, hs):
         resource.Resource.__init__(self)
 
+        self.clock = hs.get_clock()
         self.path_regexs = {}
 
     def register_path(self, method, path_pattern, callback):
@@ -111,6 +112,7 @@ class JsonResource(HttpServer, resource.Resource):
             This checks if anyone has registered a callback for that method and
             path.
         """
+        code = None
         try:
             # Just say yes to OPTIONS.
             if request.method == "OPTIONS":
@@ -130,6 +132,13 @@ class JsonResource(HttpServer, resource.Resource):
                         urllib.unquote(u).decode("UTF-8") for u in m.groups()
                     ]
 
+                    logger.info(
+                        "Received request: %s %s",
+                        request.method, request.path
+                    )
+
+                    start = self.clock.time_msec()
+
                     code, response = yield path_entry.callback(
                         request,
                         *args
@@ -145,9 +154,11 @@ class JsonResource(HttpServer, resource.Resource):
                 logger.info("%s SynapseError: %s - %s", request, e.code, e.msg)
             else:
                 logger.exception(e)
+
+            code = e.code
             self._send_response(
                 request,
-                e.code,
+                code,
                 cs_exception(e),
                 response_code_message=e.response_code_message
             )
@@ -158,6 +169,14 @@ class JsonResource(HttpServer, resource.Resource):
                 500,
                 {"error": "Internal server error"}
             )
+        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
+            )
 
     def _send_response(self, request, code, response_json_object,
                        response_code_message=None):
diff --git a/synapse/rest/client/v1/__init__.py b/synapse/rest/client/v1/__init__.py
index d8d01cdd16..21876b3487 100644
--- a/synapse/rest/client/v1/__init__.py
+++ b/synapse/rest/client/v1/__init__.py
@@ -25,7 +25,7 @@ class ClientV1RestResource(JsonResource):
     """A resource for version 1 of the matrix client API."""
 
     def __init__(self, hs):
-        JsonResource.__init__(self)
+        JsonResource.__init__(self, hs)
         self.register_servlets(self, hs)
 
     @staticmethod
diff --git a/synapse/rest/client/v2_alpha/__init__.py b/synapse/rest/client/v2_alpha/__init__.py
index 8f611de3a8..bca65f2a6a 100644
--- a/synapse/rest/client/v2_alpha/__init__.py
+++ b/synapse/rest/client/v2_alpha/__init__.py
@@ -25,7 +25,7 @@ class ClientV2AlphaRestResource(JsonResource):
     """A resource for version 2 alpha of the matrix client API."""
 
     def __init__(self, hs):
-        JsonResource.__init__(self)
+        JsonResource.__init__(self, hs)
         self.register_servlets(self, hs)
 
     @staticmethod