Return request ID in HTTP response headers

synapse/app/generic_worker.py

@@ -377,6 +377,7 @@ def _listen_http(self, listener_config: ListenerConfig):
                 self.version_string,
                 max_request_body_size=max_request_body_size(self.config),
                 reactor=self.get_reactor(),
+                instance_name=f"generic_worker_{site_tag}",
             ),
             reactor=self.get_reactor(),
         )

synapse/app/homeserver.py

@@ -142,6 +142,7 @@ def _listener_http(self, config: HomeServerConfig, listener_config: ListenerConf
             self.version_string,
             max_request_body_size=max_request_body_size(self.config),
             reactor=self.get_reactor(),
+            instance_name="homeserver",
         )
 
         if tls:

synapse/http/site.py

@@ -14,7 +14,7 @@
 import contextlib
 import logging
 import time
-from typing import Optional, Tuple, Union
+from typing import Optional, Tuple, Union, cast
 
 import attr
 from zope.interface import implementer
@@ -61,9 +61,17 @@ class SynapseRequest(Request):
         logcontext: the log context for this request
     """
 
-    def __init__(self, channel, *args, max_request_body_size=1024, **kw):
+    def __init__(
+        self,
+        channel,
+        *args,
+        instance_name: str,
+        max_request_body_size: int = 1024,
+        **kw,
+    ):
         Request.__init__(self, channel, *args, **kw)
         self._max_request_body_size = max_request_body_size
+        self._instance_name = instance_name
         self.site: SynapseSite = channel.site
         self._channel = channel  # this is used by the tests
         self.start_time = 0.0
@@ -83,11 +91,11 @@ def __init__(self, channel, *args, max_request_body_size=1024, **kw):
         self._is_processing = False
 
         # the time when the asynchronous request handler completed its processing
-        self._processing_finished_time = None
+        self._processing_finished_time: Optional[float] = None
 
         # what time we finished sending the response to the client (or the connection
         # dropped)
-        self.finish_time = None
+        self.finish_time: Optional[float] = None
 
     def __repr__(self):
         # We overwrite this so that we don't log ``access_token``
@@ -139,8 +147,8 @@ def requester(self, value: Union[Requester, str]) -> None:
         # If there's no authenticated entity, it was the requester.
         self.logcontext.request.authenticated_entity = authenticated_entity or requester
 
-    def get_request_id(self):
-        return "%s-%i" % (self.get_method(), self.request_seq)
+    def get_request_id(self) -> str:
+        return f"{self._instance_name}/{self.get_method()}-{self.request_seq}"
 
     def get_redacted_uri(self) -> str:
         """Gets the redacted URI associated with the request (or placeholder if the URI
@@ -208,9 +216,10 @@ def get_authenticated_entity(self) -> Tuple[Optional[str], Optional[str]]:
     def render(self, resrc):
         # this is called once a Resource has been found to serve the request; in our
         # case the Resource in question will normally be a JsonResource.
+        request_id = self.get_request_id()
+        self.setHeader("X-Request-ID", request_id)
 
         # create a LogContext for this request
-        request_id = self.get_request_id()
         self.logcontext = LoggingContext(
             request_id,
             request=ContextRequest(
@@ -355,7 +364,11 @@ def _started_processing(self, servlet_name):
         )
 
     def _finished_processing(self):
-        """Log the completion of this request and update the metrics"""
+        """Log the completion of this request and update the metrics.
+
+        Doing so requires the `finish_time` to be non-`None` so we can compute
+        the response send time.
+        """
         assert self.logcontext is not None
         usage = self.logcontext.get_resource_usage()
 
@@ -368,7 +381,10 @@ def _finished_processing(self):
 
         # the time between the request handler finishing and the response being sent
         # to the client (nb may be negative)
-        response_send_time = self.finish_time - self._processing_finished_time
+        # TODO can we avoid the cast? Maybe take finish_time as an explicit float param?
+        response_send_time = (
+            cast(float, self.finish_time) - self._processing_finished_time
+        )
 
         user_agent = get_request_user_agent(self, "-")
 
@@ -523,6 +539,7 @@ def __init__(
         server_version_string,
         max_request_body_size: int,
         reactor: IReactorTime,
+        instance_name: str,
     ):
         """
 
@@ -547,7 +564,10 @@ def __init__(
 
         def request_factory(channel, queued) -> Request:
             return request_class(
-                channel, max_request_body_size=max_request_body_size, queued=queued
+                channel,
+                max_request_body_size=max_request_body_size,
+                queued=queued,
+                instance_name=instance_name,
             )
 
         self.requestFactory = request_factory  # type: ignore

tests/replication/_base.py

@@ -361,6 +361,7 @@ def make_worker_hs(
             server_version_string="1",
             max_request_body_size=4096,
             reactor=self.reactor,
+            instance_name="test",
         )
 
         if worker_hs.config.redis.redis_enabled:

tests/test_server.py

@@ -204,6 +204,7 @@ def _make_request(self, method, path):
             "1.0",
             max_request_body_size=1234,
             reactor=self.reactor,
+            instance_name="test",
         )
 
         # render the request and return the channel

tests/unittest.py

@@ -250,6 +250,7 @@ def setUp(self):
             server_version_string="1",
             max_request_body_size=1234,
             reactor=self.reactor,
+            instance_name="test",
         )
 
         from tests.rest.client.utils import RestHelper