Return request ID in HTTP response headers

changelog.d/10854.misc

@@ -0,0 +1 @@
+Include a request id in Synapse's HTTP responses to aid debugging.

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"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/logging/test_terse_json.py

@@ -152,7 +152,7 @@ def test_with_request_context(self):
         site = Mock(spec=["site_tag", "server_version_string", "getResourceFor"])
         site.site_tag = "test-site"
         site.server_version_string = "Server v1"
-        request = SynapseRequest(FakeChannel(site, None))
+        request = SynapseRequest(FakeChannel(site, None), instance_name="test")
         # Call requestReceived to finish instantiating the object.
         request.content = BytesIO()
         # Partially skip some of the internal processing of SynapseRequest.
@@ -188,7 +188,7 @@ def test_with_request_context(self):
         ]
         self.assertCountEqual(log.keys(), expected_log_keys)
         self.assertEqual(log["log"], "Hello there, wally!")
-        self.assertTrue(log["request"].startswith("POST-"))
+        self.assertIn("POST-", log["request"])
         self.assertEqual(log["ip_address"], "127.0.0.1")
         self.assertEqual(log["site_tag"], "test-site")
         self.assertEqual(log["requester"], "@foo:test")

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/rest/key/v2/test_remote_key_resource.py

@@ -84,7 +84,7 @@ def make_notary_request(self, server_name: str, key_id: str) -> dict:
         Checks that the response is a 200 and returns the decoded json body.
         """
         channel = FakeChannel(self.site, self.reactor)
-        req = SynapseRequest(channel)
+        req = SynapseRequest(channel, instance_name="test")
         req.content = BytesIO(b"")
         req.requestReceived(
             b"GET",
@@ -183,7 +183,7 @@ async def post_json(destination, path, data):
             )
 
             channel = FakeChannel(self.site, self.reactor)
-            req = SynapseRequest(channel)
+            req = SynapseRequest(channel, instance_name="test")
             req.content = BytesIO(encode_canonical_json(data))
 
             req.requestReceived(

tests/server.py

@@ -268,7 +268,7 @@ def make_request(
 
     channel = FakeChannel(site, reactor, ip=client_ip)
 
-    req = request(channel)
+    req = request(channel, instance_name="test")
     req.content = BytesIO(content)
     # Twisted expects to be at the end of the content when parsing the request.
     req.content.seek(SEEK_END)

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