diff options
Diffstat (limited to '')
| -rwxr-xr-x | synapse/app/homeserver.py | 64 | ||||
| -rw-r--r-- | synapse/http/server.py | 90 |
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 |