Move request_id management into SynapseRequest

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
+    """Wraps a request handler method with the necessary logging and exception
-    and exception handling.
+     handling.
 
-    The method must have a signature of "handle_foo(self, request)". The
+    The handler method must have a signature of "handle_foo(self, request)",
-    argument "self" must have "version_string" and "clock" attributes. The
+    where "self" must have "version_string" and "clock" attributes (and
-    argument "request" must be a twisted HTTP request.
+    "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
+    As well as calling `request.processing` (which will log the response and
-    log the response and duration for this request.
+    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)
+        Args:
-        _next_request_id += 1
+            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):

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<redacted>\3',