Merge branch 'develop' of github.com:matrix-org/synapse into erikj/debug_direct_message_checks

To aid debugging we want to sanity check the device direct messages sent
between servers to try and make sure that remote servers have the
correct device lists.

changelog.d/6678.misc

@@ -0,0 +1 @@
+Check inbound to device messages for correct devices and log any inconsistencies.

synapse/handlers/devicemessage.py

@@ -19,6 +19,7 @@ from canonicaljson import json
 
 from twisted.internet import defer
 
+import synapse
 from synapse.api.errors import SynapseError
 from synapse.logging.opentracing import (
     get_active_span_text_map,
@@ -31,9 +32,11 @@ from synapse.util.stringutils import random_string
 
 logger = logging.getLogger(__name__)
 
+device_list_debugging_logger = logging.getLogger("synapse.devices.DEBUG_TRACKING")
+
 
 class DeviceMessageHandler(object):
-    def __init__(self, hs):
+    def __init__(self, hs: "synapse.server.HomeServer"):
         """
         Args:
             hs (synapse.server.HomeServer): server
@@ -65,6 +68,9 @@ class DeviceMessageHandler(object):
                 logger.warning("Request for keys for non-local user %s", user_id)
                 raise SynapseError(400, "Not a user here")
 
+            if not by_device:
+                continue
+
             messages_by_device = {
                 device_id: {
                     "content": message_content,
@@ -73,8 +79,65 @@ class DeviceMessageHandler(object):
                 }
                 for device_id, message_content in by_device.items()
             }
-            if messages_by_device:
-                local_messages[user_id] = messages_by_device
+            local_messages[user_id] = messages_by_device
+
+            if (
+                device_list_debugging_logger.isEnabledFor(logging.INFO)
+                and message_type == "m.room_key_request"
+            ):
+                # If we get a request to get keys then may mean the recipient
+                # didn't know about the sender's device (or might just mean
+                # things are being a bit slow to propogate).
+                received_devices = set(by_device)
+                requesting_device_id = list(by_device.values())[0].get(
+                    "requesting_device_id", "<unknown>"
+                )
+                request_id = list(by_device.values())[0].get("request_id", "<unknown>")
+                action = list(by_device.values())[0].get("action", "<unknown>")
+                device_list_debugging_logger.info(
+                    "Received room_key %s direct message (%s, %s, %s) from %s (%s) to %s (%s).",
+                    action,
+                    message_type,
+                    message_id,
+                    request_id,
+                    sender_user_id,
+                    requesting_device_id,
+                    user_id,
+                    received_devices,
+                )
+            elif device_list_debugging_logger.isEnabledFor(logging.INFO):
+                # We expect the sending user to send the message to all the devices
+                # to the user, if they don't then that is potentially suspicious and
+                # so we log for debugging purposes.
+
+                expected_devices = yield self.store.get_devices_by_user(user_id)
+                expected_devices = set(expected_devices)
+                received_devices = set(by_device)
+                if received_devices != {"*"} and received_devices != expected_devices:
+                    # Devices that the remote didn't send to
+                    missed = expected_devices - received_devices
+
+                    # Devices the remote sent to that we don't know bout
+                    extraneous = received_devices - expected_devices
+
+                    # We try and pull out the `sender_key` from the first message,
+                    # if it has one. This just helps figure out which device the
+                    # message came from.
+                    sender_key = list(by_device.values())[0].get(
+                        "sender_key", "<unknown>"
+                    )
+
+                    device_list_debugging_logger.info(
+                        "Received direct message (%s, %s) from %s (%s) to %s with mismatched devices."
+                        " Missing: %s, extraneous: %s",
+                        message_type,
+                        message_id,
+                        sender_user_id,
+                        sender_key,
+                        user_id,
+                        missed,
+                        extraneous,
+                    )
 
         stream_id = yield self.store.add_messages_from_remote_to_device_inbox(
             origin, message_id, local_messages