From 7ca638c76135d7a0f86f6aa7981554bbe0b7a335 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Thu, 25 Apr 2019 20:53:10 +0100 Subject: [PATCH 1/4] Clarify logging when PDU signature checking fails --- synapse/crypto/keyring.py | 4 +--- synapse/federation/federation_base.py | 19 +++++++++++++++++++ 2 files changed, 20 insertions(+), 3 deletions(-) diff --git a/synapse/crypto/keyring.py b/synapse/crypto/keyring.py index ed2e9944374e..b6d1b4cf0b01 100644 --- a/synapse/crypto/keyring.py +++ b/synapse/crypto/keyring.py @@ -120,11 +120,9 @@ def verify_json_objects_for_server(self, server_and_json): 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", + "Not signed by %s" % (server_name, ), Codes.UNAUTHORIZED, )) else: diff --git a/synapse/federation/federation_base.py b/synapse/federation/federation_base.py index dfe6b4aa5c13..1d641337da67 100644 --- a/synapse/federation/federation_base.py +++ b/synapse/federation/federation_base.py @@ -269,7 +269,17 @@ def _check_sigs_on_pdus(keyring, room_version, pdus): for p in pdus_to_check_sender ]) + def sender_err(e, pdu_to_check): + logger.warning( + "event id %s: unable to verify signature for sender %s: %s", + pdu_to_check.pdu.event_id, + pdu_to_check.sender_domain, + e, + ) + return e + 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 +301,16 @@ def _check_sigs_on_pdus(keyring, room_version, pdus): for p in pdus_to_check_event_id ]) + def event_err(e, pdu_to_check): + logger.warning( + "event id %s: unable to verify signature for event id domain: %s", + pdu_to_check.pdu.event_id, + e, + ) + return e + 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 From fd8fb32bdd70b0ad68666e0f39a95ac90f9b1c27 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Thu, 25 Apr 2019 21:08:12 +0100 Subject: [PATCH 2/4] remove extraneous exception logging --- synapse/crypto/keyring.py | 48 ++++++++++++++++++--------- synapse/federation/federation_base.py | 4 +-- 2 files changed, 34 insertions(+), 18 deletions(-) diff --git a/synapse/crypto/keyring.py b/synapse/crypto/keyring.py index b6d1b4cf0b01..d8ba870cca5e 100644 --- a/synapse/crypto/keyring.py +++ b/synapse/crypto/keyring.py @@ -114,38 +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: - deferred = defer.fail(SynapseError( - 400, - "Not signed by %s" % (server_name, ), - 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 1d641337da67..832e2bdb9b31 100644 --- a/synapse/federation/federation_base.py +++ b/synapse/federation/federation_base.py @@ -274,7 +274,7 @@ def sender_err(e, pdu_to_check): "event id %s: unable to verify signature for sender %s: %s", pdu_to_check.pdu.event_id, pdu_to_check.sender_domain, - e, + e.getErrorMessage(), ) return e @@ -305,7 +305,7 @@ def event_err(e, pdu_to_check): logger.warning( "event id %s: unable to verify signature for event id domain: %s", pdu_to_check.pdu.event_id, - e, + e.getErrorMessage(), ) return e From 837d7f85a9d0a479487cd6205a3982f3981e4276 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Thu, 25 Apr 2019 22:17:59 +0100 Subject: [PATCH 3/4] more logging improvements --- synapse/federation/federation_base.py | 19 +++++++++++-------- 1 file changed, 11 insertions(+), 8 deletions(-) diff --git a/synapse/federation/federation_base.py b/synapse/federation/federation_base.py index 832e2bdb9b31..cffa831d8099 100644 --- a/synapse/federation/federation_base.py +++ b/synapse/federation/federation_base.py @@ -270,13 +270,14 @@ def _check_sigs_on_pdus(keyring, room_version, pdus): ]) def sender_err(e, pdu_to_check): - logger.warning( - "event id %s: unable to verify signature for sender %s: %s", + 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(), ) - return e + # 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) @@ -302,12 +303,14 @@ def sender_err(e, pdu_to_check): ]) def event_err(e, pdu_to_check): - logger.warning( - "event id %s: unable to verify signature for event id domain: %s", - pdu_to_check.pdu.event_id, - e.getErrorMessage(), + errmsg = ( + "event id %s: unable to verify signature for event id domain: %s" % ( + pdu_to_check.pdu.event_id, + e.getErrorMessage(), + ) ) - return e + # 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) From 0962d3cdffd91dec7472661d81b21a35800eb8b5 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Thu, 25 Apr 2019 23:05:06 +0100 Subject: [PATCH 4/4] changelog --- changelog.d/5100.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/5100.misc 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.