diff --git a/changelog.d/5100.misc b/changelog.d/5100.misc new file mode 100644 index 000000000000..db5eb1b1565a --- /dev/null +++ b/changelog.d/5100.misc @@ -0,0 +1 @@ +Improve logging when event-signature checks fail. diff --git a/synapse/crypto/keyring.py b/synapse/crypto/keyring.py index ed2e9944374e..d8ba870cca5e 100644 --- a/synapse/crypto/keyring.py +++ b/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 diff --git a/synapse/federation/federation_base.py b/synapse/federation/federation_base.py index dfe6b4aa5c13..cffa831d8099 100644 --- a/synapse/federation/federation_base.py +++ b/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