Improve logging when signature checks fail (#12925)

* Raise a dedicated `InvalidEventSignatureError` from `_check_sigs_on_pdu`

* Downgrade logging about redactions to DEBUG

this can be very spammy during a room join, and it's not very useful.

* Raise `InvalidEventSignatureError` from `_check_sigs_and_hash`

... and, more importantly, move the logging out to the callers.

* changelog

1 files changed, 42 insertions, 47 deletions

diff --git a/synapse/federation/federation_base.py b/synapse/federation/federation_base.py
index 7bc54b9988..a6232e048b 100644
--- a/synapse/federation/federation_base.py
+++ b/synapse/federation/federation_base.py
@@ -32,6 +32,18 @@ if TYPE_CHECKING:
 logger = logging.getLogger(__name__)
 
 
+class InvalidEventSignatureError(RuntimeError):
+    """Raised when the signature on an event is invalid.
+
+    The stringification of this exception is just the error message without reference
+    to the event id. The event id is available as a property.
+    """
+
+    def __init__(self, message: str, event_id: str):
+        super().__init__(message)
+        self.event_id = event_id
+
+
 class FederationBase:
     def __init__(self, hs: "HomeServer"):
         self.hs = hs
@@ -59,20 +71,13 @@ class FederationBase:
         Returns:
               * the original event if the checks pass
               * a redacted version of the event (if the signature
-                matched but the hash did not)
+                matched but the hash did not). In this case a warning will be logged.
 
         Raises:
-              SynapseError if the signature check failed.
+          InvalidEventSignatureError if the signature check failed. Nothing
+             will be logged in this case.
         """
-        try:
-            await _check_sigs_on_pdu(self.keyring, room_version, pdu)
-        except SynapseError as e:
-            logger.warning(
-                "Signature check failed for %s: %s",
-                pdu.event_id,
-                e,
-            )
-            raise
+        await _check_sigs_on_pdu(self.keyring, room_version, pdu)
 
         if not check_event_content_hash(pdu):
             # let's try to distinguish between failures because the event was
@@ -87,7 +92,7 @@ class FederationBase:
             if set(redacted_event.keys()) == set(pdu.keys()) and set(
                 redacted_event.content.keys()
             ) == set(pdu.content.keys()):
-                logger.info(
+                logger.debug(
                     "Event %s seems to have been redacted; using our redacted copy",
                     pdu.event_id,
                 )
@@ -116,12 +121,13 @@ async def _check_sigs_on_pdu(
 ) -> None:
     """Check that the given events are correctly signed
 
-    Raise a SynapseError if the event wasn't correctly signed.
-
     Args:
         keyring: keyring object to do the checks
         room_version: the room version of the PDUs
         pdus: the events to be checked
+
+    Raises:
+        InvalidEventSignatureError if the event wasn't correctly signed.
     """
 
     # we want to check that the event is signed by:
@@ -147,44 +153,38 @@ async def _check_sigs_on_pdu(
 
     # First we check that the sender event is signed by the sender's domain
     # (except if its a 3pid invite, in which case it may be sent by any server)
+    sender_domain = get_domain_from_id(pdu.sender)
     if not _is_invite_via_3pid(pdu):
         try:
             await keyring.verify_event_for_server(
-                get_domain_from_id(pdu.sender),
+                sender_domain,
                 pdu,
                 pdu.origin_server_ts if room_version.enforce_key_validity else 0,
             )
         except Exception as e:
-            errmsg = "event id %s: unable to verify signature for sender %s: %s" % (
+            raise InvalidEventSignatureError(
+                f"unable to verify signature for sender domain {sender_domain}: {e}",
                 pdu.event_id,
-                get_domain_from_id(pdu.sender),
-                e,
-            )
-            raise SynapseError(403, errmsg, Codes.FORBIDDEN)
+            ) from None
 
     # now let's look for events where the sender's domain is different to the
     # event id's domain (normally only the case for joins/leaves), and add additional
     # checks. Only do this if the room version has a concept of event ID domain
     # (ie, the room version uses old-style non-hash event IDs).
-    if room_version.event_format == EventFormatVersions.V1 and get_domain_from_id(
-        pdu.event_id
-    ) != get_domain_from_id(pdu.sender):
-        try:
-            await keyring.verify_event_for_server(
-                get_domain_from_id(pdu.event_id),
-                pdu,
-                pdu.origin_server_ts if room_version.enforce_key_validity else 0,
-            )
-        except Exception as e:
-            errmsg = (
-                "event id %s: unable to verify signature for event id domain %s: %s"
-                % (
-                    pdu.event_id,
-                    get_domain_from_id(pdu.event_id),
-                    e,
+    if room_version.event_format == EventFormatVersions.V1:
+        event_domain = get_domain_from_id(pdu.event_id)
+        if event_domain != sender_domain:
+            try:
+                await keyring.verify_event_for_server(
+                    event_domain,
+                    pdu,
+                    pdu.origin_server_ts if room_version.enforce_key_validity else 0,
                 )
-            )
-            raise SynapseError(403, errmsg, Codes.FORBIDDEN)
+            except Exception as e:
+                raise InvalidEventSignatureError(
+                    f"unable to verify signature for event domain {event_domain}: {e}",
+                    pdu.event_id,
+                ) from None
 
     # If this is a join event for a restricted room it may have been authorised
     # via a different server from the sending server. Check those signatures.
@@ -204,15 +204,10 @@ async def _check_sigs_on_pdu(
                 pdu.origin_server_ts if room_version.enforce_key_validity else 0,
             )
         except Exception as e:
-            errmsg = (
-                "event id %s: unable to verify signature for authorising server %s: %s"
-                % (
-                    pdu.event_id,
-                    authorising_server,
-                    e,
-                )
-            )
-            raise SynapseError(403, errmsg, Codes.FORBIDDEN)
+            raise InvalidEventSignatureError(
+                f"unable to verify signature for authorising serve {authorising_server}: {e}",
+                pdu.event_id,
+            ) from None
 
 
 def _is_invite_via_3pid(event: EventBase) -> bool: