From dab36c23aa14358ac976c6ca94d774a02cab6173 Mon Sep 17 00:00:00 2001
From: Patrick Cloke <patrickc@matrix.org>
Date: Thu, 10 Dec 2020 14:20:58 -0500
Subject: [PATCH] Add additional request information to structured logs.

---
 synapse/http/site.py             | 24 +++++++++++++++++++++++-
 synapse/logging/context.py       | 16 ++++++++++++++++
 tests/logging/test_terse_json.py | 17 +++++++++++++++--
 3 files changed, 54 insertions(+), 3 deletions(-)

diff --git a/synapse/http/site.py b/synapse/http/site.py
index 6584e92950a9..40f9b4acd354 100644
--- a/synapse/http/site.py
+++ b/synapse/http/site.py
@@ -126,6 +126,28 @@ def get_method(self) -> str:
             return self.method.decode("ascii")
         return method
 
+    def get_authenticated_entity(self) -> Optional[str]:
+        # Convert the requester into a string that we can log
+        if isinstance(self.requester, str):
+            return self.requester
+        elif isinstance(self.requester, Requester):
+            authenticated_entity = self.requester.authenticated_entity
+
+            # If this is a request where the target user doesn't match the user who
+            # authenticated (e.g. and admin is puppetting a user) then we log both.
+            if self.requester.user.to_string() != authenticated_entity:
+                return "{},{}".format(
+                    authenticated_entity,
+                    self.requester.user.to_string(),
+                )
+            return authenticated_entity
+        elif self.requester is not None:
+            # This shouldn't happen, but we log it so we don't lose information
+            # and can see that we're doing something wrong.
+            return repr(self.requester)  # type: ignore[unreachable]
+
+        return None
+
     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.
@@ -312,7 +334,7 @@ def _finished_processing(self):
             ' %sB %s "%s %s %s" "%s" [%d dbevts]',
             self.getClientIP(),
             self.site.site_tag,
-            authenticated_entity,
+            self.get_authenticated_entity(),
             processing_time,
             response_send_time,
             usage.ru_utime,
diff --git a/synapse/logging/context.py b/synapse/logging/context.py
index 1bce8ed45c88..b15932fb0931 100644
--- a/synapse/logging/context.py
+++ b/synapse/logging/context.py
@@ -564,6 +564,22 @@ def filter(self, record: logging.LogRecord) -> Literal[True]:
             # compatibility this is stored as the "request" on the record.
             record.request = str(context)  # type: ignore
 
+            # Add some data from the HTTP request.
+            request = context.request
+            if request is None:
+                return True
+
+            # Avoid a circular import.
+            from synapse.http import get_request_user_agent
+
+            record.ip_address = request.getClientIP()  # type: ignore
+            record.site_tag = request.site.site_tag  # type: ignore
+            record.authenticated_entity = request.get_authenticated_entity()  # type: ignore
+            record.method = request.get_method()  # type: ignore
+            record.url = request.get_redacted_uri()  # type: ignore
+            record.protocol = request.clientproto.decode("ascii", errors="replace")  # type: ignore
+            record.user_agent = get_request_user_agent(request)  # type: ignore
+
         return True
 
 
diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py
index 0ecff16a52da..cc91f7ee2dd2 100644
--- a/tests/logging/test_terse_json.py
+++ b/tests/logging/test_terse_json.py
@@ -12,7 +12,6 @@
 # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 # See the License for the specific language governing permissions and
 # limitations under the License.
-
 import json
 import logging
 from io import BytesIO, StringIO
@@ -163,13 +162,27 @@ def test_with_request_context(self):
 
         log = self.get_log_line()
 
-        # The terse logger should give us these keys.
+        # The terse logger includes additional request information, if possible.
         expected_log_keys = [
             "log",
             "level",
             "namespace",
             "request",
+            "ip_address",
+            "site_tag",
+            "authenticated_entity",
+            "method",
+            "url",
+            "protocol",
+            "user_agent",
         ]
         self.assertCountEqual(log.keys(), expected_log_keys)
         self.assertEqual(log["log"], "Hello there, wally!")
         self.assertTrue(log["request"].startswith("POST-"))
+        self.assertEqual(log["ip_address"], "127.0.0.1")
+        self.assertEqual(log["site_tag"], "test-site")
+        self.assertIsNone(log["authenticated_entity"])
+        self.assertEqual(log["method"], "POST")
+        self.assertEqual(log["url"], "/_matrix/client/versions")
+        self.assertEqual(log["protocol"], "1.1")
+        self.assertEqual(log["user_agent"], "")