From 48d44ab1425ffac721b7d407823c2315cda1929a Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 8 Apr 2021 08:01:14 -0400 Subject: Record more information into structured logs. (#9654) Records additional request information into the structured logs, e.g. the requester, IP address, etc. --- synapse/http/site.py | 112 ++++++++++++++++++++++++++++++++++++++++----------- 1 file changed, 88 insertions(+), 24 deletions(-) (limited to 'synapse/http/site.py') diff --git a/synapse/http/site.py b/synapse/http/site.py index 47754aff43..c0c873ce32 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -14,7 +14,7 @@ import contextlib import logging import time -from typing import Optional, Type, Union +from typing import Optional, Tuple, Type, Union import attr from zope.interface import implementer @@ -26,7 +26,11 @@ from twisted.web.server import Request, Site from synapse.config.server import ListenerConfig from synapse.http import get_request_user_agent, redact_uri from synapse.http.request_metrics import RequestMetrics, requests_counter -from synapse.logging.context import LoggingContext, PreserveLoggingContext +from synapse.logging.context import ( + ContextRequest, + LoggingContext, + PreserveLoggingContext, +) from synapse.types import Requester logger = logging.getLogger(__name__) @@ -63,7 +67,7 @@ class SynapseRequest(Request): # The requester, if authenticated. For federation requests this is the # server name, for client requests this is the Requester object. - self.requester = None # type: Optional[Union[Requester, str]] + self._requester = None # type: Optional[Union[Requester, str]] # we can't yet create the logcontext, as we don't know the method. self.logcontext = None # type: Optional[LoggingContext] @@ -93,6 +97,31 @@ class SynapseRequest(Request): self.site.site_tag, ) + @property + def requester(self) -> Optional[Union[Requester, str]]: + return self._requester + + @requester.setter + def requester(self, value: Union[Requester, str]) -> None: + # Store the requester, and update some properties based on it. + + # This should only be called once. + assert self._requester is None + + self._requester = value + + # A logging context should exist by now (and have a ContextRequest). + assert self.logcontext is not None + assert self.logcontext.request is not None + + ( + requester, + authenticated_entity, + ) = self.get_authenticated_entity() + self.logcontext.request.requester = requester + # 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) @@ -126,13 +155,60 @@ class SynapseRequest(Request): return self.method.decode("ascii") return method + def get_authenticated_entity(self) -> Tuple[Optional[str], Optional[str]]: + """ + Get the "authenticated" entity of the request, which might be the user + performing the action, or a user being puppeted by a server admin. + + Returns: + A tuple: + The first item is a string representing the user making the request. + + The second item is a string or None representing the user who + authenticated when making this request. See + Requester.authenticated_entity. + """ + # Convert the requester into a string that we can log + if isinstance(self._requester, str): + return self._requester, None + elif isinstance(self._requester, Requester): + requester = self._requester.user.to_string() + 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 return both. + if self._requester.user.to_string() != authenticated_entity: + return requester, authenticated_entity + + return requester, None + 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), None # type: ignore[unreachable] + + return None, 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. # create a LogContext for this request request_id = self.get_request_id() - self.logcontext = LoggingContext(request_id, request=request_id) + self.logcontext = LoggingContext( + request_id, + request=ContextRequest( + request_id=request_id, + ip_address=self.getClientIP(), + site_tag=self.site.site_tag, + # The requester is going to be unknown at this point. + requester=None, + authenticated_entity=None, + method=self.get_method(), + url=self.get_redacted_uri(), + protocol=self.clientproto.decode("ascii", errors="replace"), + user_agent=get_request_user_agent(self), + ), + ) # override the Server header which is set by twisted self.setHeader("Server", self.site.server_version_string) @@ -277,25 +353,6 @@ class SynapseRequest(Request): # to the client (nb may be negative) response_send_time = self.finish_time - self._processing_finished_time - # Convert the requester into a string that we can log - authenticated_entity = None - if isinstance(self.requester, str): - authenticated_entity = 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: - authenticated_entity = "{},{}".format( - authenticated_entity, - self.requester.user.to_string(), - ) - 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. - authenticated_entity = repr(self.requester) # type: ignore[unreachable] - user_agent = get_request_user_agent(self, "-") code = str(self.code) @@ -305,6 +362,13 @@ class SynapseRequest(Request): code += "!" log_level = logging.INFO if self._should_log_request() else logging.DEBUG + + # 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. + requester, authenticated_entity = self.get_authenticated_entity() + if authenticated_entity: + requester = "{}.{}".format(authenticated_entity, requester) + self.site.access_logger.log( log_level, "%s - %s - {%s}" @@ -312,7 +376,7 @@ class SynapseRequest(Request): ' %sB %s "%s %s %s" "%s" [%d dbevts]', self.getClientIP(), self.site.site_tag, - authenticated_entity, + requester, processing_time, response_send_time, usage.ru_utime, -- cgit 1.5.1 From 1d5f0e3529ec5acd889037c8ebcca2820ad003d5 Mon Sep 17 00:00:00 2001 From: Dan Callahan Date: Tue, 13 Apr 2021 10:41:34 +0100 Subject: Bump black configuration to target py36 (#9781) Signed-off-by: Dan Callahan --- changelog.d/9781.misc | 1 + pyproject.toml | 2 +- synapse/config/tls.py | 2 +- synapse/handlers/presence.py | 2 +- synapse/http/matrixfederationclient.py | 2 +- synapse/http/site.py | 2 +- synapse/storage/database.py | 8 ++++---- tests/replication/slave/storage/test_events.py | 2 +- tests/test_state.py | 2 +- tests/test_utils/event_injection.py | 6 +++--- tests/utils.py | 2 +- 11 files changed, 16 insertions(+), 15 deletions(-) create mode 100644 changelog.d/9781.misc (limited to 'synapse/http/site.py') diff --git a/changelog.d/9781.misc b/changelog.d/9781.misc new file mode 100644 index 0000000000..d1c73fc741 --- /dev/null +++ b/changelog.d/9781.misc @@ -0,0 +1 @@ +Update Black configuration to target Python 3.6. diff --git a/pyproject.toml b/pyproject.toml index cd880d4e39..8bca1fa4ef 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -35,7 +35,7 @@ showcontent = true [tool.black] -target-version = ['py35'] +target-version = ['py36'] exclude = ''' ( diff --git a/synapse/config/tls.py b/synapse/config/tls.py index ad37b93c02..85b5db4c40 100644 --- a/synapse/config/tls.py +++ b/synapse/config/tls.py @@ -270,7 +270,7 @@ class TlsConfig(Config): tls_certificate_path, tls_private_key_path, acme_domain, - **kwargs + **kwargs, ): """If the acme_domain is specified acme will be enabled. If the TLS paths are not specified the default will be certs in the diff --git a/synapse/handlers/presence.py b/synapse/handlers/presence.py index c817f2952d..0047907cd9 100644 --- a/synapse/handlers/presence.py +++ b/synapse/handlers/presence.py @@ -1071,7 +1071,7 @@ class PresenceEventSource: room_ids=None, include_offline=True, explicit_room_id=None, - **kwargs + **kwargs, ) -> Tuple[List[UserPresenceState], int]: # The process for getting presence events are: # 1. Get the rooms the user is in. diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py index 5f01ebd3d4..ab47dec8f2 100644 --- a/synapse/http/matrixfederationclient.py +++ b/synapse/http/matrixfederationclient.py @@ -272,7 +272,7 @@ class MatrixFederationHttpClient: self, request: MatrixFederationRequest, try_trailing_slash_on_400: bool = False, - **send_request_args + **send_request_args, ) -> IResponse: """Wrapper for _send_request which can optionally retry the request upon receiving a combination of a 400 HTTP response code and a diff --git a/synapse/http/site.py b/synapse/http/site.py index c0c873ce32..32b5e19c09 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -497,7 +497,7 @@ class SynapseSite(Site): resource, server_version_string, *args, - **kwargs + **kwargs, ): Site.__init__(self, resource, *args, **kwargs) diff --git a/synapse/storage/database.py b/synapse/storage/database.py index fa15b0ce5b..77ef29ec71 100644 --- a/synapse/storage/database.py +++ b/synapse/storage/database.py @@ -488,7 +488,7 @@ class DatabasePool: exception_callbacks: List[_CallbackListEntry], func: "Callable[..., R]", *args: Any, - **kwargs: Any + **kwargs: Any, ) -> R: """Start a new database transaction with the given connection. @@ -622,7 +622,7 @@ class DatabasePool: func: "Callable[..., R]", *args: Any, db_autocommit: bool = False, - **kwargs: Any + **kwargs: Any, ) -> R: """Starts a transaction on the database and runs a given function @@ -682,7 +682,7 @@ class DatabasePool: func: "Callable[..., R]", *args: Any, db_autocommit: bool = False, - **kwargs: Any + **kwargs: Any, ) -> R: """Wraps the .runWithConnection() method on the underlying db_pool. @@ -775,7 +775,7 @@ class DatabasePool: desc: str, decoder: Optional[Callable[[Cursor], R]], query: str, - *args: Any + *args: Any, ) -> R: """Runs a single query for a result set. diff --git a/tests/replication/slave/storage/test_events.py b/tests/replication/slave/storage/test_events.py index 333374b183..db80a0bdbd 100644 --- a/tests/replication/slave/storage/test_events.py +++ b/tests/replication/slave/storage/test_events.py @@ -340,7 +340,7 @@ class SlavedEventStoreTestCase(BaseSlavedStoreTestCase): prev_state: Optional[list] = None, redacts=None, push_actions: Iterable = frozenset(), - **content + **content, ): prev_events = prev_events or [] auth_events = auth_events or [] diff --git a/tests/test_state.py b/tests/test_state.py index 83383d8872..0d626f49f6 100644 --- a/tests/test_state.py +++ b/tests/test_state.py @@ -38,7 +38,7 @@ def create_event( depth=2, event_id=None, prev_events: Optional[List[str]] = None, - **kwargs + **kwargs, ): global _next_event_id diff --git a/tests/test_utils/event_injection.py b/tests/test_utils/event_injection.py index c3c4a93e1f..3dfbf8f8a9 100644 --- a/tests/test_utils/event_injection.py +++ b/tests/test_utils/event_injection.py @@ -33,7 +33,7 @@ async def inject_member_event( membership: str, target: Optional[str] = None, extra_content: Optional[dict] = None, - **kwargs + **kwargs, ) -> EventBase: """Inject a membership event into a room.""" if target is None: @@ -58,7 +58,7 @@ async def inject_event( hs: synapse.server.HomeServer, room_version: Optional[str] = None, prev_event_ids: Optional[List[str]] = None, - **kwargs + **kwargs, ) -> EventBase: """Inject a generic event into a room @@ -83,7 +83,7 @@ async def create_event( hs: synapse.server.HomeServer, room_version: Optional[str] = None, prev_event_ids: Optional[List[str]] = None, - **kwargs + **kwargs, ) -> Tuple[EventBase, EventContext]: if room_version is None: room_version = await hs.get_datastore().get_room_version_id(kwargs["room_id"]) diff --git a/tests/utils.py b/tests/utils.py index 2e34fad11c..c78d3e5ba7 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -190,7 +190,7 @@ def setup_test_homeserver( config=None, reactor=None, homeserver_to_use: Type[HomeServer] = TestHomeServer, - **kwargs + **kwargs, ): """ Setup a homeserver suitable for running tests against. Keyword arguments -- cgit 1.5.1