From 8460e48d0639a7f575fd3e57dcd5cf263a6d6a19 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 9 May 2018 23:00:11 +0100 Subject: [PATCH] Move request_id management into SynapseRequest --- synapse/http/server.py | 31 ++++++++++++++++--------------- synapse/http/site.py | 9 +++++++++ 2 files changed, 25 insertions(+), 15 deletions(-) diff --git a/synapse/http/server.py b/synapse/http/server.py index 37b26b908..369f7bbdd 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -46,38 +46,40 @@ import simplejson logger = logging.getLogger(__name__) -_next_request_id = 0 - - def request_handler(include_metrics=False): """Decorator for ``wrap_request_handler``""" return lambda request_handler: wrap_request_handler(request_handler, include_metrics) def wrap_request_handler(request_handler, include_metrics=False): - """Wraps a method that acts as a request handler with the necessary logging - and exception handling. + """Wraps a request handler method with the necessary logging and exception + handling. - The method must have a signature of "handle_foo(self, request)". The - argument "self" must have "version_string" and "clock" attributes. The - argument "request" must be a twisted HTTP request. + The handler method must have a signature of "handle_foo(self, request)", + where "self" must have "version_string" and "clock" attributes (and + "request" must be a SynapseRequest). - The method must return a deferred. If the deferred succeeds we assume that + The handler must return a deferred. If the deferred succeeds we assume that a response has been sent. If the deferred fails with a SynapseError we use it to send a JSON response with the appropriate HTTP reponse code. If the deferred fails with any other type of error we send a 500 reponse. - We insert a unique request-id into the logging context for this request and - log the response and duration for this request. + As well as calling `request.processing` (which will log the response and + duration for this request), the wrapped request handler will insert the + request id into the logging context. """ @defer.inlineCallbacks def wrapped_request_handler(self, request): - global _next_request_id - request_id = "%s-%s" % (request.method, _next_request_id) - _next_request_id += 1 + """ + Args: + self: + request (synapse.http.site.SynapseRequest): + """ + request_id = request.get_request_id() with LoggingContext(request_id) as request_context: + request_context.request = request_id with Measure(self.clock, "wrapped_request_handler"): request_metrics = RequestMetrics() # we start the request metrics timer here with an initial stab @@ -87,7 +89,6 @@ def wrap_request_handler(request_handler, include_metrics=False): servlet_name = self.__class__.__name__ request_metrics.start(self.clock, name=servlet_name) - request_context.request = request_id with request.processing(): try: with PreserveLoggingContext(request_context): diff --git a/synapse/http/site.py b/synapse/http/site.py index c8b46e1af..6af276e69 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -22,6 +22,8 @@ import time ACCESS_TOKEN_RE = re.compile(br'(\?.*access(_|%5[Ff])token=)[^&]*(.*)$') +_next_request_seq = 0 + class SynapseRequest(Request): def __init__(self, site, *args, **kw): @@ -30,6 +32,10 @@ class SynapseRequest(Request): self.authenticated_entity = None self.start_time = 0 + global _next_request_seq + self.request_seq = _next_request_seq + _next_request_seq += 1 + def __repr__(self): # We overwrite this so that we don't log ``access_token`` return '<%s at 0x%x method=%s uri=%s clientproto=%s site=%s>' % ( @@ -41,6 +47,9 @@ class SynapseRequest(Request): self.site.site_tag, ) + def get_request_id(self): + return "%s-%i" % (self.method, self.request_seq) + def get_redacted_uri(self): return ACCESS_TOKEN_RE.sub( br'\1\3',