Disable twisted access logging. Move access logging to SynapseRequest object

2 files changed, 79 insertions, 75 deletions

diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py
index fca6f06e3b..7effedf7dc 100755
--- a/synapse/app/homeserver.py
+++ b/synapse/app/homeserver.py
@@ -35,7 +35,6 @@ from twisted.enterprise import adbapi
 from twisted.web.resource import Resource, EncodingResourceWrapper
 from twisted.web.static import File
 from twisted.web.server import Site, GzipEncoderFactory, Request
-from twisted.web.http import proxiedLogFormatter, combinedLogFormatter
 from synapse.http.server import JsonResource, RootRedirect
 from synapse.rest.media.v0.content_repository import ContentRepoResource
 from synapse.rest.media.v1.media_repository import MediaRepositoryResource
@@ -61,11 +60,13 @@ import twisted.manhole.telnet
 
 import synapse
 
+import contextlib
 import logging
 import os
 import re
 import resource
 import subprocess
+import time
 
 
 logger = logging.getLogger("synapse.app.homeserver")
@@ -438,10 +439,11 @@ class SynapseService(service.Service):
 
 
 class SynapseRequest(Request):
-    def __init__(self, site_tag, *args, **kw):
+    def __init__(self, site, *args, **kw):
         Request.__init__(self, *args, **kw)
-        self.site_tag = site_tag
+        self.site = site
         self.authenticated_entity = None
+        self.start_time = 0
 
     def __repr__(self):
         # We overwrite this so that we don't log ``access_token``
@@ -451,7 +453,7 @@ class SynapseRequest(Request):
             self.method,
             self.get_redacted_uri(),
             self.clientproto,
-            self.site_tag,
+            self.site.site_tag,
         )
 
     def get_redacted_uri(self):
@@ -464,6 +466,38 @@ class SynapseRequest(Request):
     def get_user_agent(self):
         return self.requestHeaders.getRawHeaders("User-Agent", [None])[-1]
 
+    def started_processing(self):
+        self.site.access_logger.info(
+            "%s - %s - Received request: %s %s",
+            self.getClientIP(),
+            self.site.site_tag,
+            self.method,
+            self.get_redacted_uri()
+        )
+        self.start_time = int(time.time() * 1000)
+
+    def finished_processing(self):
+        self.site.access_logger.info(
+            "%s - %s - {%s}"
+            " Processed request: %dms %sB %s \"%s %s %s\" \"%s\"",
+            self.getClientIP(),
+            self.site.site_tag,
+            self.authenticated_entity,
+            int(time.time() * 1000) - self.start_time,
+            self.sentLength,
+            self.code,
+            self.method,
+            self.get_redacted_uri(),
+            self.clientproto,
+            self.get_user_agent(),
+        )
+
+    @contextlib.contextmanager
+    def processing(self):
+        self.started_processing()
+        yield
+        self.finished_processing()
+
 
 class XForwardedForRequest(SynapseRequest):
     def __init__(self, *args, **kw):
@@ -484,15 +518,15 @@ class XForwardedForRequest(SynapseRequest):
 
 
 class SynapseRequestFactory(object):
-    def __init__(self, site_tag, x_forwarded_for):
-        self.site_tag = site_tag
+    def __init__(self, site, x_forwarded_for):
+        self.site = site
         self.x_forwarded_for = x_forwarded_for
 
     def __call__(self, *args, **kwargs):
         if self.x_forwarded_for:
-            return XForwardedForRequest(self.site_tag, *args, **kwargs)
+            return XForwardedForRequest(self.site, *args, **kwargs)
         else:
-            return SynapseRequest(self.site_tag, *args, **kwargs)
+            return SynapseRequest(self.site, *args, **kwargs)
 
 
 class SynapseSite(Site):
@@ -500,21 +534,17 @@ class SynapseSite(Site):
     Subclass of a twisted http Site that does access logging with python's
     standard logging
     """
-    def __init__(self, logger_name, tag, config, resource, *args, **kwargs):
+    def __init__(self, logger_name, site_tag, config, resource, *args, **kwargs):
         Site.__init__(self, resource, *args, **kwargs)
 
-        proxied = config.get("x_forwarded", False)
-        self.requestFactory = SynapseRequestFactory(tag, proxied)
+        self.site_tag = site_tag
 
-        if proxied:
-            self._log_formatter = proxiedLogFormatter
-        else:
-            self._log_formatter = combinedLogFormatter
+        proxied = config.get("x_forwarded", False)
+        self.requestFactory = SynapseRequestFactory(self, proxied)
         self.access_logger = logging.getLogger(logger_name)
 
     def log(self, request):
-        line = self._log_formatter(self._logDateTime, request)
-        self.access_logger.info(line)
+        pass
 
 
 def create_resource_tree(desired_tree, redirect_root_to_web_client=True):
diff --git a/synapse/http/server.py b/synapse/http/server.py
index 34645a371a..807ff95c65 100644
--- a/synapse/http/server.py
+++ b/synapse/http/server.py
@@ -79,65 +79,39 @@ def request_handler(request_handler):
         _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(
-                    "%s - Received request: %s %s",
-                    request.getClientIP(),
-                    request.method,
-                    request.get_redacted_uri()
-                )
-                d = request_handler(self, request)
-                with PreserveLoggingContext():
-                    yield d
-                code = request.code
-            except CodeMessageException as e:
-                code = e.code
-                if isinstance(e, SynapseError):
-                    logger.info(
-                        "%s SynapseError: %s - %s", request, code, e.msg
+            with request.processing():
+                try:
+                    d = request_handler(self, request)
+                    with PreserveLoggingContext():
+                        yield d
+                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:
+                    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
                     )
-                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(
-                    "%s - %s - {%s}"
-                    " Processed request: %dms %sB %s \"%s %s %s\" \"%s\"",
-                    request.getClientIP(),
-                    request.site_tag,
-                    request.authenticated_entity,
-                    end-start,
-                    request.sentLength,
-                    code,
-                    request.method,
-                    request.get_redacted_uri(),
-                    request.clientproto,
-                    request.get_user_agent(),
-                )
     return wrapped_request_handler