Log more when we have processed the request

4 files changed, 23 insertions, 4 deletions

diff --git a/synapse/api/auth.py b/synapse/api/auth.py
index d5bf0be85c..4da62e5d8d 100644
--- a/synapse/api/auth.py
+++ b/synapse/api/auth.py
@@ -370,6 +370,8 @@ class Auth(object):
                     user_agent=user_agent
                 )
 
+            request.authenticated_entity = user.to_string()
+
             defer.returnValue((user, ClientInfo(device_id, token_id)))
         except KeyError:
             raise AuthError(
diff --git a/synapse/app/homeserver.py b/synapse/app/homeserver.py
index 7c1ad6bc13..fca6f06e3b 100755
--- a/synapse/app/homeserver.py
+++ b/synapse/app/homeserver.py
@@ -143,6 +143,7 @@ class SynapseHomeServer(HomeServer):
         port = listener_config["port"]
         bind_address = listener_config.get("bind_address", "")
         tls = listener_config.get("tls", False)
+        site_tag = listener_config.get("tag", port)
 
         if tls and config.no_tls:
             return
@@ -199,6 +200,7 @@ class SynapseHomeServer(HomeServer):
                 port,
                 SynapseSite(
                     "synapse.access.https",
+                    site_tag,
                     listener_config,
                     root_resource,
                 ),
@@ -210,6 +212,7 @@ class SynapseHomeServer(HomeServer):
                 port,
                 SynapseSite(
                     "synapse.access.https",
+                    site_tag,
                     listener_config,
                     root_resource,
                 ),
@@ -458,6 +461,9 @@ class SynapseRequest(Request):
             self.uri
         )
 
+    def get_user_agent(self):
+        return self.requestHeaders.getRawHeaders("User-Agent", [None])[-1]
+
 
 class XForwardedForRequest(SynapseRequest):
     def __init__(self, *args, **kw):
@@ -494,11 +500,11 @@ class SynapseSite(Site):
     Subclass of a twisted http Site that does access logging with python's
     standard logging
     """
-    def __init__(self, logger_name, config, resource, *args, **kwargs):
+    def __init__(self, logger_name, tag, config, resource, *args, **kwargs):
         Site.__init__(self, resource, *args, **kwargs)
 
         proxied = config.get("x_forwarded", False)
-        self.requestFactory = SynapseRequestFactory(None, proxied)
+        self.requestFactory = SynapseRequestFactory(tag, proxied)
 
         if proxied:
             self._log_formatter = proxiedLogFormatter
diff --git a/synapse/federation/transport/server.py b/synapse/federation/transport/server.py
index 31190e700a..bad93c6b2f 100644
--- a/synapse/federation/transport/server.py
+++ b/synapse/federation/transport/server.py
@@ -94,6 +94,7 @@ class TransportLayerServer(object):
         yield self.keyring.verify_json_for_server(origin, json_request)
 
         logger.info("Request from %s", origin)
+        request.authenticated_entity = origin
 
         defer.returnValue((origin, content))
 
diff --git a/synapse/http/server.py b/synapse/http/server.py
index 7f8b9dbb29..34645a371a 100644
--- a/synapse/http/server.py
+++ b/synapse/http/server.py
@@ -125,8 +125,18 @@ def request_handler(request_handler):
                 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
+                    "%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