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
|
