Nicer tracing

synapse/handlers/device.py

@@ -307,7 +307,9 @@ class DeviceHandler(DeviceWorkerHandler):
             if e.code == 404:
                 # no match
                 opentracing.set_tag("error", True)
-                opentracing.set_tag("reason", "User doesn't have that device id.")
+                opentracing.log_kv(
+                    {"reason": "User doesn't have device id.", "device_id": device_id}
+                )
                 pass
             else:
                 raise
@@ -509,6 +511,15 @@ class DeviceListEduUpdater(object):
                 device_id,
                 origin,
             )
+
+            opentracing.set_tag("error", True)
+            opentracing.log_kv(
+                {
+                    "message": "Got a device list update edu from a user and device which does not match the origin of the request.",
+                    "user_id": user_id,
+                    "device_id": device_id,
+                }
+            )
             return
 
         room_ids = yield self.store.get_rooms_for_user(user_id)
@@ -518,8 +529,9 @@ class DeviceListEduUpdater(object):
             opentracing.set_tag("error", True)
             opentracing.log_kv(
                 {
-                    "message": "Got an update from a user which "
-                    + "doesn't share a room with the current user."
+                    "message": "Got an update from a user for which "
+                    + "we don't share any rooms",
+                    "other user_id": user_id,
                 }
             )
             logger.warning(
@@ -564,6 +576,7 @@ class DeviceListEduUpdater(object):
             logger.debug("Need to re-sync devices for %r? %r", user_id, resync)
 
             if resync:
+                opentracing.log_kv({"message": "Doing resync to update device list."})
                 # Fetch all devices for the user.
                 origin = get_domain_from_id(user_id)
                 try:

synapse/handlers/devicemessage.py

@@ -79,10 +79,10 @@ class DeviceMessageHandler(object):
             "to_device_key", stream_id, users=local_messages.keys()
         )
 
-    @opentracing.trace_defered_function
     @defer.inlineCallbacks
     def send_device_message(self, sender_user_id, message_type, messages):
-
+        opentracing.set_tag("number of messages", len(messages))
+        opentracing.set_tag("sender", sender_user_id)
         local_messages = {}
         remote_messages = {}
         for user_id, by_device in messages.items():
@@ -121,7 +121,7 @@ class DeviceMessageHandler(object):
                     else "",
                 }
 
-        opentracing.log_kv(local_messages)
+        opentracing.log_kv({"local_messages": local_messages})
         stream_id = yield self.store.add_messages_to_device_inbox(
             local_messages, remote_edu_contents
         )
@@ -130,7 +130,7 @@ class DeviceMessageHandler(object):
             "to_device_key", stream_id, users=local_messages.keys()
         )
 
-        opentracing.log_kv(remote_messages)
+        opentracing.log_kv({"remote_messages": remote_messages})
         for destination in remote_messages.keys():
             # Enqueue a new federation transaction to send the new
             # device messages to each remote destination.

synapse/rest/client/v2_alpha/keys.py

@@ -182,20 +182,24 @@ class KeyChangesServlet(RestServlet):
         self.auth = hs.get_auth()
         self.device_handler = hs.get_device_handler()
 
+    @opentracing.trace_defered_function
     @defer.inlineCallbacks
     def on_GET(self, request):
         requester = yield self.auth.get_user_by_req(request, allow_guest=True)
 
         from_token_string = parse_string(request, "from")
+        opentracing.set_tag("from", from_token_string)
 
         # We want to enforce they do pass us one, but we ignore it and return
         # changes after the "to" as well as before.
-        parse_string(request, "to")
+        opentracing.set_tag("to", parse_string(request, "to"))
 
         from_token = StreamToken.from_string(from_token_string)
 
         user_id = requester.user.to_string()
 
+        opentracing.set_tag("user_id", user_id)
+
         results = yield self.device_handler.get_user_ids_changed(user_id, from_token)
 
         defer.returnValue((200, results))

synapse/rest/client/v2_alpha/sendtodevice.py

@@ -43,7 +43,7 @@ class SendToDeviceRestServlet(servlet.RestServlet):
         self.txns = HttpTransactionCache(hs)
         self.device_message_handler = hs.get_device_message_handler()
 
-    @opentracing.trace_function_using_operation_name("sendToDevice")
+    @opentracing.trace_defered_function_using_operation_name("sendToDevice")
     def on_PUT(self, request, message_type, txn_id):
         opentracing.set_tag("message_type", message_type)
         opentracing.set_tag("txn_id", txn_id)

synapse/storage/end_to_end_keys.py

@@ -235,7 +235,7 @@ class EndToEndKeyStore(EndToEndKeyWorkerStore, SQLBaseStore):
             new_key_json = encode_canonical_json(device_keys).decode("utf-8")
 
             if old_key_json == new_key_json:
-                opentracing.log_kv({"Message", "Device key already stored."})
+                opentracing.log_kv({"Message": "Device key already stored."})
                 return False
 
             self._simple_upsert_txn(
@@ -291,10 +291,14 @@ class EndToEndKeyStore(EndToEndKeyWorkerStore, SQLBaseStore):
         return self.runInteraction("claim_e2e_one_time_keys", _claim_e2e_one_time_keys)
 
     def delete_e2e_keys_by_device(self, user_id, device_id):
-        @opentracing.trace_function
         def delete_e2e_keys_by_device_txn(txn):
-            opentracing.set_tag("user_id", user_id)
-            opentracing.set_tag("device_id", device_id)
+            opentracing.log_kv(
+                {
+                    "message": "Deleting keys for device",
+                    "device_id": device_id,
+                    "user_id": user_id,
+                }
+            )
             self._simple_delete_txn(
                 txn,
                 table="e2e_device_keys_json",