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

4 files changed, 95 insertions, 65 deletions

diff --git a/changelog.d/12925.misc b/changelog.d/12925.misc
new file mode 100644
index 0000000000..71ca956dc5
--- /dev/null
+++ b/changelog.d/12925.misc
@@ -0,0 +1 @@
+Improve the logging when signature checks on events fail.
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:
diff --git a/synapse/federation/federation_client.py b/synapse/federation/federation_client.py
index b60b8983ea..ad475a913b 100644
--- a/synapse/federation/federation_client.py
+++ b/synapse/federation/federation_client.py
@@ -54,7 +54,11 @@ from synapse.api.room_versions import (
     RoomVersions,
 )
 from synapse.events import EventBase, builder
-from synapse.federation.federation_base import FederationBase, event_from_pdu_json
+from synapse.federation.federation_base import (
+    FederationBase,
+    InvalidEventSignatureError,
+    event_from_pdu_json,
+)
 from synapse.federation.transport.client import SendJoinResponse
 from synapse.http.types import QueryParams
 from synapse.types import JsonDict, UserID, get_domain_from_id
@@ -319,7 +323,13 @@ class FederationClient(FederationBase):
             pdu = pdu_list[0]
 
             # Check signatures are correct.
-            signed_pdu = await self._check_sigs_and_hash(room_version, pdu)
+            try:
+                signed_pdu = await self._check_sigs_and_hash(room_version, pdu)
+            except InvalidEventSignatureError as e:
+                errmsg = f"event id {pdu.event_id}: {e}"
+                logger.warning("%s", errmsg)
+                raise SynapseError(403, errmsg, Codes.FORBIDDEN)
+
             return signed_pdu
 
         return None
@@ -555,20 +565,24 @@ class FederationClient(FederationBase):
 
         Returns:
             The PDU (possibly redacted) if it has valid signatures and hashes.
+            None if no valid copy could be found.
         """
 
-        res = None
         try:
-            res = await self._check_sigs_and_hash(room_version, pdu)
-        except SynapseError:
-            pass
-
-        if not res:
-            # Check local db.
-            res = await self.store.get_event(
-                pdu.event_id, allow_rejected=True, allow_none=True
+            return await self._check_sigs_and_hash(room_version, pdu)
+        except InvalidEventSignatureError as e:
+            logger.warning(
+                "Signature on retrieved event %s was invalid (%s). "
+                "Checking local store/orgin server",
+                pdu.event_id,
+                e,
             )
 
+        # Check local db.
+        res = await self.store.get_event(
+            pdu.event_id, allow_rejected=True, allow_none=True
+        )
+
         pdu_origin = get_domain_from_id(pdu.sender)
         if not res and pdu_origin != origin:
             try:
@@ -1043,9 +1057,14 @@ class FederationClient(FederationBase):
         pdu = event_from_pdu_json(pdu_dict, room_version)
 
         # Check signatures are correct.
-        pdu = await self._check_sigs_and_hash(room_version, pdu)
+        try:
+            pdu = await self._check_sigs_and_hash(room_version, pdu)
+        except InvalidEventSignatureError as e:
+            errmsg = f"event id {pdu.event_id}: {e}"
+            logger.warning("%s", errmsg)
+            raise SynapseError(403, errmsg, Codes.FORBIDDEN)
 
-        # FIXME: We should handle signature failures more gracefully.
+            # FIXME: We should handle signature failures more gracefully.
 
         return pdu
 
diff --git a/synapse/federation/federation_server.py b/synapse/federation/federation_server.py
index 3ecede22d9..12591dc8db 100644
--- a/synapse/federation/federation_server.py
+++ b/synapse/federation/federation_server.py
@@ -48,7 +48,11 @@ from synapse.api.room_versions import KNOWN_ROOM_VERSIONS, RoomVersion
 from synapse.crypto.event_signing import compute_event_signature
 from synapse.events import EventBase
 from synapse.events.snapshot import EventContext
-from synapse.federation.federation_base import FederationBase, event_from_pdu_json
+from synapse.federation.federation_base import (
+    FederationBase,
+    InvalidEventSignatureError,
+    event_from_pdu_json,
+)
 from synapse.federation.persistence import TransactionActions
 from synapse.federation.units import Edu, Transaction
 from synapse.http.servlet import assert_params_in_dict
@@ -631,7 +635,12 @@ class FederationServer(FederationBase):
         pdu = event_from_pdu_json(content, room_version)
         origin_host, _ = parse_server_name(origin)
         await self.check_server_matches_acl(origin_host, pdu.room_id)
-        pdu = await self._check_sigs_and_hash(room_version, pdu)
+        try:
+            pdu = await self._check_sigs_and_hash(room_version, pdu)
+        except InvalidEventSignatureError as e:
+            errmsg = f"event id {pdu.event_id}: {e}"
+            logger.warning("%s", errmsg)
+            raise SynapseError(403, errmsg, Codes.FORBIDDEN)
         ret_pdu = await self.handler.on_invite_request(origin, pdu, room_version)
         time_now = self._clock.time_msec()
         return {"event": ret_pdu.get_pdu_json(time_now)}
@@ -864,7 +873,12 @@ class FederationServer(FederationBase):
                 )
             )
 
-        event = await self._check_sigs_and_hash(room_version, event)
+        try:
+            event = await self._check_sigs_and_hash(room_version, event)
+        except InvalidEventSignatureError as e:
+            errmsg = f"event id {event.event_id}: {e}"
+            logger.warning("%s", errmsg)
+            raise SynapseError(403, errmsg, Codes.FORBIDDEN)
 
         return await self._federation_event_handler.on_send_membership_event(
             origin, event
@@ -1016,8 +1030,9 @@ class FederationServer(FederationBase):
         # Check signature.
         try:
             pdu = await self._check_sigs_and_hash(room_version, pdu)
-        except SynapseError as e:
-            raise FederationError("ERROR", e.code, e.msg, affected=pdu.event_id)
+        except InvalidEventSignatureError as e:
+            logger.warning("event id %s: %s", pdu.event_id, e)
+            raise FederationError("ERROR", 403, str(e), affected=pdu.event_id)
 
         if await self._spam_checker.should_drop_federated_event(pdu):
             logger.warning(