clearer logging when things fail, too

synapse/federation/federation_base.py

@@ -143,11 +143,31 @@ class FederationBase(object):
         def callback(_, pdu):
             with logcontext.PreserveLoggingContext(ctx):
                 if not check_event_content_hash(pdu):
-                    logger.warn(
+                    # let's try to distinguish between failures because the event was
-                        "Event content has been tampered, redacting %s: %s",
+                    # redacted (which are somewhat expected) vs actual ball-tampering
-                        pdu.event_id, pdu.get_pdu_json()
+                    # incidents.
+                    #
+                    # This is just a heuristic, so we just assume that if the keys are
+                    # about the same between the redacted and received events, then the
+                    # received event was probably a redacted copy (but we then use our
+                    # *actual* redacted copy to be on the safe side.)
+                    redacted_event = prune_event(pdu)
+                    if (
+                        set(six.iterkeys(redacted_event)) == set(six.iterkeys(pdu)) and
+                        set(six.iterkeys(redacted_event.content))
+                            == set(six.iterkeys(pdu.content))
+                    ):
+                        logger.info(
+                            "Event %s seems to have been redacted; using our redacted "
+                            "copy",
+                            pdu.event_id,
                         )
-                    return prune_event(pdu)
+                    else:
+                        logger.warning(
+                            "Event %s content has been tampered, redacting",
+                            pdu.event_id, pdu.get_pdu_json(),
+                        )
+                    return redacted_event
 
                 if self.spam_checker.check_event_for_spam(pdu):
                     logger.warn(
@@ -162,8 +182,8 @@ class FederationBase(object):
             failure.trap(SynapseError)
             with logcontext.PreserveLoggingContext(ctx):
                 logger.warn(
-                    "Signature check failed for %s",
+                    "Signature check failed for %s: %s",
-                    pdu.event_id,
+                    pdu.event_id, failure.getErrorMessage(),
                 )
             return failure
 

synapse/storage/keys.py

@@ -134,6 +134,7 @@ class KeyStore(SQLBaseStore):
         """
         key_id = "%s:%s" % (verify_key.alg, verify_key.version)
 
+        # XXX fix this to not need a lock (#3819)
         def _txn(txn):
             self._simple_upsert_txn(
                 txn,