Improve logging when event-signature checking fails

changelog.d/5100.misc

@@ -0,0 +1 @@
+Improve logging when event-signature checks fail.

synapse/crypto/keyring.py

@@ -114,40 +114,54 @@ def verify_json_objects_for_server(self, server_and_json):
                 server_name. The deferreds run their callbacks in the sentinel
                 logcontext.
         """
+        # a list of VerifyKeyRequests
         verify_requests = []
+        handle = preserve_fn(_handle_key_deferred)
 
-        for server_name, json_object in server_and_json:
+        def process(server_name, json_object):
+            """Process an entry in the request list
 
+            Given a (server_name, json_object) pair from the request list,
+            adds a key request to verify_requests, and returns a deferred which will
+            complete or fail (in the sentinel context) when verification completes.
+            """
             key_ids = signature_ids(json_object, server_name)
+
             if not key_ids:
-                logger.warn("Request from %s: no supported signature keys",
-                            server_name)
-                deferred = defer.fail(SynapseError(
-                    400,
-                    "Not signed with a supported algorithm",
-                    Codes.UNAUTHORIZED,
-                ))
-            else:
-                deferred = defer.Deferred()
+                return defer.fail(
+                    SynapseError(
+                        400,
+                        "Not signed by %s" % (server_name,),
+                        Codes.UNAUTHORIZED,
+                    )
+                )
 
             logger.debug("Verifying for %s with key_ids %s",
                          server_name, key_ids)
 
+            # add the key request to the queue, but don't start it off yet.
             verify_request = VerifyKeyRequest(
-                server_name, key_ids, json_object, deferred
+                server_name, key_ids, json_object, defer.Deferred(),
             )
-
             verify_requests.append(verify_request)
 
-        run_in_background(self._start_key_lookups, verify_requests)
+            # now run _handle_key_deferred, which will wait for the key request
+            # to complete and then do the verification.
+            #
+            # We want _handle_key_request to log to the right context, so we
+            # wrap it with preserve_fn (aka run_in_background)
+            return handle(verify_request)
 
-        # Pass those keys to handle_key_deferred so that the json object
-        # signatures can be verified
-        handle = preserve_fn(_handle_key_deferred)
-        return [
-            handle(rq) for rq in verify_requests
+        results = [
+            process(server_name, json_object)
+            for server_name, json_object in server_and_json
         ]
 
+        if verify_requests:
+            run_in_background(self._start_key_lookups, verify_requests)
+
+        return results
+
     @defer.inlineCallbacks
     def _start_key_lookups(self, verify_requests):
         """Sets off the key fetches for each verify request

synapse/federation/federation_base.py

@@ -269,7 +269,18 @@ def _check_sigs_on_pdus(keyring, room_version, pdus):
         for p in pdus_to_check_sender
     ])
 
+    def sender_err(e, pdu_to_check):
+        errmsg = "event id %s: unable to verify signature for sender %s: %s" % (
+            pdu_to_check.pdu.event_id,
+            pdu_to_check.sender_domain,
+            e.getErrorMessage(),
+        )
+        # XX not really sure if these are the right codes, but they are what
+        # we've done for ages
+        raise SynapseError(400, errmsg, Codes.UNAUTHORIZED)
+
     for p, d in zip(pdus_to_check_sender, more_deferreds):
+        d.addErrback(sender_err, p)
         p.deferreds.append(d)
 
     # now let's look for events where the sender's domain is different to the
@@ -291,7 +302,18 @@ def _check_sigs_on_pdus(keyring, room_version, pdus):
             for p in pdus_to_check_event_id
         ])
 
+        def event_err(e, pdu_to_check):
+            errmsg = (
+                "event id %s: unable to verify signature for event id domain: %s" % (
+                    pdu_to_check.pdu.event_id,
+                    e.getErrorMessage(),
+                )
+            )
+            # XX as above: not really sure if these are the right codes
+            raise SynapseError(400, errmsg, Codes.UNAUTHORIZED)
+
         for p, d in zip(pdus_to_check_event_id, more_deferreds):
+            d.addErrback(event_err, p)
             p.deferreds.append(d)
 
     # replace lists of deferreds with single Deferreds