From f2d2ae03dae519a4f2035f1466fdd3429c71edc8 Mon Sep 17 00:00:00 2001
From: David Baker <dbkr@users.noreply.github.com>
Date: Tue, 18 Jun 2019 22:51:24 +0100
Subject: [PATCH] Add some logging to 3pid invite sig verification (#5015)

I had to add quite a lot of logging to diagnose a problem with 3pid
invites - we only logged the one failure which isn't all that
informative.

NB. I'm not convinced the logic of this loop is right: I think it
should just accept a single valid signature from a trusted source
rather than fail if *any* signature is invalid. Also it should
probably not skip the rest of middle loop if a check fails? However,
I'm deliberately not changing the logic here.
---
 changelog.d/5015.misc          |  1 +
 synapse/handlers/federation.py | 46 ++++++++++++++++++++++++++++------
 2 files changed, 39 insertions(+), 8 deletions(-)
 create mode 100644 changelog.d/5015.misc

diff --git a/changelog.d/5015.misc b/changelog.d/5015.misc
new file mode 100644
index 000000000..eeec85b92
--- /dev/null
+++ b/changelog.d/5015.misc
@@ -0,0 +1 @@
+Add logging to 3pid invite signature verification.
diff --git a/synapse/handlers/federation.py b/synapse/handlers/federation.py
index 93e064cda..51d7eb274 100644
--- a/synapse/handlers/federation.py
+++ b/synapse/handlers/federation.py
@@ -2744,25 +2744,55 @@ class FederationHandler(BaseHandler):
         if not invite_event:
             raise AuthError(403, "Could not find invite")
 
+        logger.debug("Checking auth on event %r", event.content)
+
         last_exception = None
+        # for each public key in the 3pid invite event
         for public_key_object in self.hs.get_auth().get_public_keys(invite_event):
             try:
+                # for each sig on the third_party_invite block of the actual invite
                 for server, signature_block in signed["signatures"].items():
                     for key_name, encoded_signature in signature_block.items():
                         if not key_name.startswith("ed25519:"):
                             continue
 
-                        public_key = public_key_object["public_key"]
-                        verify_key = decode_verify_key_bytes(
-                            key_name,
-                            decode_base64(public_key)
+                        logger.debug(
+                            "Attempting to verify sig with key %s from %r "
+                            "against pubkey %r",
+                            key_name, server, public_key_object,
                         )
-                        verify_signed_json(signed, server, verify_key)
-                        if "key_validity_url" in public_key_object:
-                            yield self._check_key_revocation(
-                                public_key,
+
+                        try:
+                            public_key = public_key_object["public_key"]
+                            verify_key = decode_verify_key_bytes(
+                                key_name,
+                                decode_base64(public_key)
+                            )
+                            verify_signed_json(signed, server, verify_key)
+                            logger.debug(
+                                "Successfully verified sig with key %s from %r "
+                                "against pubkey %r",
+                                key_name, server, public_key_object,
+                            )
+                        except Exception:
+                            logger.info(
+                                "Failed to verify sig with key %s from %r "
+                                "against pubkey %r",
+                                key_name, server, public_key_object,
+                            )
+                            raise
+                        try:
+                            if "key_validity_url" in public_key_object:
+                                yield self._check_key_revocation(
+                                    public_key,
+                                    public_key_object["key_validity_url"]
+                                )
+                        except Exception:
+                            logger.info(
+                                "Failed to query key_validity_url %s",
                                 public_key_object["key_validity_url"]
                             )
+                            raise
                         return
             except Exception as e:
                 last_exception = e