Merge pull request #7713 from vector-im/feature/bca/to_device_tracing

add to device tracing id

changelog.d/7708.misc

@@ -0,0 +1 @@
+Add tracing Id for to device messages

matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/events/model/EventType.kt

@@ -16,6 +16,8 @@
 
 package org.matrix.android.sdk.api.session.events.model
 
+import org.matrix.android.sdk.api.session.room.model.message.MessageType.MSGTYPE_VERIFICATION_REQUEST
+
 /**
  * Constants defining known event types from Matrix specifications.
  */
@@ -126,6 +128,7 @@ object EventType {
 
     fun isVerificationEvent(type: String): Boolean {
         return when (type) {
+            MSGTYPE_VERIFICATION_REQUEST,
             KEY_VERIFICATION_START,
             KEY_VERIFICATION_ACCEPT,
             KEY_VERIFICATION_KEY,

matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/tasks/SendToDeviceTask.kt

@@ -17,14 +17,22 @@
 package org.matrix.android.sdk.internal.crypto.tasks
 
 import org.matrix.android.sdk.api.session.crypto.model.MXUsersDevicesMap
+import org.matrix.android.sdk.api.session.events.model.Event
+import org.matrix.android.sdk.api.session.events.model.EventType
+import org.matrix.android.sdk.api.session.events.model.toContent
 import org.matrix.android.sdk.internal.crypto.api.CryptoApi
 import org.matrix.android.sdk.internal.crypto.model.rest.SendToDeviceBody
 import org.matrix.android.sdk.internal.network.GlobalErrorReceiver
 import org.matrix.android.sdk.internal.network.executeRequest
 import org.matrix.android.sdk.internal.task.Task
+import timber.log.Timber
 import java.util.UUID
 import javax.inject.Inject
 
+const val TO_DEVICE_TRACING_ID_KEY = "org.matrix.msgid"
+
+fun Event.toDeviceTracingId(): String? = content?.get(TO_DEVICE_TRACING_ID_KEY) as? String
+
 internal interface SendToDeviceTask : Task<SendToDeviceTask.Params, Unit> {
     data class Params(
             // the type of event to send
@@ -32,7 +40,9 @@ internal interface SendToDeviceTask : Task<SendToDeviceTask.Params, Unit> {
             // the content to send. Map from user_id to device_id to content dictionary.
             val contentMap: MXUsersDevicesMap<Any>,
             // the transactionId. If not provided, a transactionId will be created by the task
-            val transactionId: String? = null
+            val transactionId: String? = null,
+            // add tracing id, notice that to device events that do signature on content might be broken by it
+            val addTracingIds: Boolean = !EventType.isVerificationEvent(eventType),
     )
 }
 
@@ -42,15 +52,22 @@ internal class DefaultSendToDeviceTask @Inject constructor(
 ) : SendToDeviceTask {
 
     override suspend fun execute(params: SendToDeviceTask.Params) {
-        val sendToDeviceBody = SendToDeviceBody(
-                messages = params.contentMap.map
-        )
-
         // If params.transactionId is not provided, we create a unique txnId.
         // It's important to do that outside the requestBlock parameter of executeRequest()
         // to use the same value if the request is retried
         val txnId = params.transactionId ?: createUniqueTxnId()
 
+        // add id tracing to debug
+        val decorated = if (params.addTracingIds) {
+            decorateWithToDeviceTracingIds(params)
+        } else {
+            params.contentMap.map to emptyList()
+        }
+
+        val sendToDeviceBody = SendToDeviceBody(
+                messages = decorated.first
+        )
+
         return executeRequest(
                 globalErrorReceiver,
                 canRetry = true,
@@ -61,8 +78,35 @@ internal class DefaultSendToDeviceTask @Inject constructor(
                     transactionId = txnId,
                     body = sendToDeviceBody
             )
+            Timber.i("Sent to device type=${params.eventType} txnid=$txnId [${decorated.second.joinToString(",")}]")
         }
     }
+
+    /**
+     * To make it easier to track down where to-device messages are getting lost,
+     * add a custom property to each one, and that will be logged after sent and on reception. Synapse will also log
+     * this property.
+     * @return A pair, first is the decorated content, and second info to log out after sending
+     */
+    private fun decorateWithToDeviceTracingIds(params: SendToDeviceTask.Params): Pair<Map<String, Map<String, Any>>, List<String>> {
+        val tracingInfo = mutableListOf<String>()
+        val decoratedContent = params.contentMap.map.map { userToDeviceMap ->
+            val userId = userToDeviceMap.key
+            userId to userToDeviceMap.value.map {
+                val deviceId = it.key
+                deviceId to it.value.toContent().toMutableMap().apply {
+                    put(
+                            TO_DEVICE_TRACING_ID_KEY,
+                            UUID.randomUUID().toString().also {
+                                tracingInfo.add("$userId/$deviceId (msgid $it)")
+                            }
+                    )
+                }
+            }.toMap()
+        }.toMap()
+
+        return decoratedContent to tracingInfo
+    }
 }
 
 internal fun createUniqueTxnId() = UUID.randomUUID().toString()

matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/handler/CryptoSyncHandler.kt

@@ -29,6 +29,7 @@ import org.matrix.android.sdk.api.session.room.model.message.MessageContent
 import org.matrix.android.sdk.api.session.sync.model.SyncResponse
 import org.matrix.android.sdk.api.session.sync.model.ToDeviceSyncResponse
 import org.matrix.android.sdk.internal.crypto.DefaultCryptoService
+import org.matrix.android.sdk.internal.crypto.tasks.toDeviceTracingId
 import org.matrix.android.sdk.internal.crypto.verification.DefaultVerificationService
 import org.matrix.android.sdk.internal.session.sync.ProgressReporter
 import timber.log.Timber
@@ -48,12 +49,14 @@ internal class CryptoSyncHandler @Inject constructor(
                 ?.forEachIndexed { index, event ->
                     progressReporter?.reportProgress(index * 100F / total)
                     // Decrypt event if necessary
-                    Timber.tag(loggerTag.value).i("To device event from ${event.senderId} of type:${event.type}")
+                    Timber.tag(loggerTag.value).d("To device event msgid:${event.toDeviceTracingId()}")
                     decryptToDeviceEvent(event, null)
+
                     if (event.getClearType() == EventType.MESSAGE &&
                             event.getClearContent()?.toModel<MessageContent>()?.msgType == "m.bad.encrypted") {
                         Timber.tag(loggerTag.value).e("handleToDeviceEvent() : Warning: Unable to decrypt to-device event : ${event.content}")
                     } else {
+                        Timber.tag(loggerTag.value).d("received to-device ${event.getClearType()} from:${event.senderId} msgid:${event.toDeviceTracingId()}")
                         verificationService.onToDeviceEvent(event)
                         cryptoService.onToDeviceEvent(event)
                     }

matrix-sdk-android/src/test/java/org/matrix/android/sdk/internal/crypto/DefaultSendToDeviceTaskTest.kt

@@ -0,0 +1,255 @@
+/*
+ * Copyright 2022 The Matrix.org Foundation C.I.C.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.matrix.android.sdk.internal.crypto
+
+import io.mockk.mockk
+import kotlinx.coroutines.runBlocking
+import org.amshove.kluent.internal.assertEquals
+import org.junit.Assert
+import org.junit.Test
+import org.matrix.android.sdk.api.session.crypto.model.DeviceInfo
+import org.matrix.android.sdk.api.session.crypto.model.DevicesListResponse
+import org.matrix.android.sdk.api.session.crypto.model.MXUsersDevicesMap
+import org.matrix.android.sdk.api.session.events.model.EventType
+import org.matrix.android.sdk.api.session.room.model.message.MessageType
+import org.matrix.android.sdk.internal.crypto.api.CryptoApi
+import org.matrix.android.sdk.internal.crypto.model.rest.DeleteDeviceParams
+import org.matrix.android.sdk.internal.crypto.model.rest.DeleteDevicesParams
+import org.matrix.android.sdk.internal.crypto.model.rest.KeyChangesResponse
+import org.matrix.android.sdk.internal.crypto.model.rest.KeysClaimBody
+import org.matrix.android.sdk.internal.crypto.model.rest.KeysClaimResponse
+import org.matrix.android.sdk.internal.crypto.model.rest.KeysQueryBody
+import org.matrix.android.sdk.internal.crypto.model.rest.KeysQueryResponse
+import org.matrix.android.sdk.internal.crypto.model.rest.KeysUploadBody
+import org.matrix.android.sdk.internal.crypto.model.rest.KeysUploadResponse
+import org.matrix.android.sdk.internal.crypto.model.rest.SendToDeviceBody
+import org.matrix.android.sdk.internal.crypto.model.rest.SignatureUploadResponse
+import org.matrix.android.sdk.internal.crypto.model.rest.UpdateDeviceInfoBody
+import org.matrix.android.sdk.internal.crypto.model.rest.UploadSigningKeysBody
+import org.matrix.android.sdk.internal.crypto.tasks.DefaultSendToDeviceTask
+import org.matrix.android.sdk.internal.crypto.tasks.SendToDeviceTask
+
+class DefaultSendToDeviceTaskTest {
+
+    private val users = listOf(
+            "@alice:example.com" to listOf("D0", "D1"),
+            "bob@example.com" to listOf("D2", "D3")
+    )
+
+    private val fakeEncryptedContent = mapOf(
+            "algorithm" to "m.olm.v1.curve25519-aes-sha2",
+            "sender_key" to "gMObR+/4dqL5T4DisRRRYBJpn+OjzFnkyCFOktP6Eyw",
+            "ciphertext" to mapOf(
+                    "tdwXf7006FDgzmufMCVI4rDdVPO51ecRTTT6HkRxUwE" to mapOf(
+                            "type" to 0,
+                            "body" to "AwogCA1ULEc0abGIFxMDIC9iv7ul3jqJSnapTHQ+8JJx"
+                    )
+            )
+    )
+
+    private val fakeStartVerificationContent = mapOf(
+            "method" to "m.sas.v1",
+            "from_device" to "MNQHVEISFQ",
+            "key_agreement_protocols" to listOf(
+                    "curve25519-hkdf-sha256",
+                    "curve25519"
+            ),
+            "hashes" to listOf("sha256"),
+            "message_authentication_codes" to listOf(
+                    "org.matrix.msc3783.hkdf-hmac-sha256",
+                    "hkdf-hmac-sha256",
+                    "hmac-sha256"
+            ),
+            "short_authentication_string" to listOf(
+                    "decimal",
+                    "emoji"
+            ),
+            "transaction_id" to "4wNOpkHGwGZPXjkZToooCDWfb8hsf7vW"
+    )
+
+    @Test
+    fun `tracing id should be added to to_device contents`() {
+        val fakeCryptoAPi = FakeCryptoApi()
+
+        val sendToDeviceTask = DefaultSendToDeviceTask(
+                cryptoApi = fakeCryptoAPi,
+                globalErrorReceiver = mockk(relaxed = true)
+        )
+
+        val contentMap = MXUsersDevicesMap<Any>()
+
+        users.forEach { pairOfUserDevices ->
+            val userId = pairOfUserDevices.first
+            pairOfUserDevices.second.forEach {
+                contentMap.setObject(userId, it, fakeEncryptedContent)
+            }
+        }
+
+        val params = SendToDeviceTask.Params(
+                eventType = EventType.ENCRYPTED,
+                contentMap = contentMap
+        )
+
+        runBlocking {
+            sendToDeviceTask.execute(params)
+        }
+
+        val generatedIds = mutableListOf<String>()
+        users.forEach { pairOfUserDevices ->
+            val userId = pairOfUserDevices.first
+            pairOfUserDevices.second.forEach {
+                val modifiedContent = fakeCryptoAPi.body!!.messages!![userId]!![it] as Map<*, *>
+                Assert.assertNotNull("Tracing id should have been added", modifiedContent["org.matrix.msgid"])
+                generatedIds.add(modifiedContent["org.matrix.msgid"] as String)
+
+                assertEquals(
+                        "The rest of the content should be the same",
+                        fakeEncryptedContent.keys,
+                        modifiedContent.toMutableMap().apply { remove("org.matrix.msgid") }.keys
+                )
+            }
+        }
+
+        assertEquals("Id should be unique per content", generatedIds.size, generatedIds.toSet().size)
+        println("modified content ${fakeCryptoAPi.body}")
+    }
+
+    @Test
+    fun `tracing id should not be added to verification start to_device contents`() {
+        val fakeCryptoAPi = FakeCryptoApi()
+
+        val sendToDeviceTask = DefaultSendToDeviceTask(
+                cryptoApi = fakeCryptoAPi,
+                globalErrorReceiver = mockk(relaxed = true)
+        )
+        val contentMap = MXUsersDevicesMap<Any>()
+        contentMap.setObject("@alice:example.com", "MNQHVEISFQ", fakeStartVerificationContent)
+
+        val params = SendToDeviceTask.Params(
+                eventType = EventType.KEY_VERIFICATION_START,
+                contentMap = contentMap
+        )
+
+        runBlocking {
+            sendToDeviceTask.execute(params)
+        }
+
+        val modifiedContent = fakeCryptoAPi.body!!.messages!!["@alice:example.com"]!!["MNQHVEISFQ"] as Map<*, *>
+        Assert.assertNull("Tracing id should not have been added", modifiedContent["org.matrix.msgid"])
+
+        // try to force
+        runBlocking {
+            sendToDeviceTask.execute(
+                    SendToDeviceTask.Params(
+                            eventType = EventType.KEY_VERIFICATION_START,
+                            contentMap = contentMap,
+                            addTracingIds = true
+                    )
+            )
+        }
+
+        val modifiedContentForced = fakeCryptoAPi.body!!.messages!!["@alice:example.com"]!!["MNQHVEISFQ"] as Map<*, *>
+        Assert.assertNotNull("Tracing id should have been added", modifiedContentForced["org.matrix.msgid"])
+    }
+
+    @Test
+    fun `tracing id should not be added to all verification to_device contents`() {
+        val fakeCryptoAPi = FakeCryptoApi()
+
+        val sendToDeviceTask = DefaultSendToDeviceTask(
+                cryptoApi = fakeCryptoAPi,
+                globalErrorReceiver = mockk(relaxed = true)
+        )
+        val contentMap = MXUsersDevicesMap<Any>()
+        contentMap.setObject("@alice:example.com", "MNQHVEISFQ", emptyMap<String, Any>())
+
+        val verificationEvents = listOf(
+                MessageType.MSGTYPE_VERIFICATION_REQUEST,
+                EventType.KEY_VERIFICATION_START,
+                EventType.KEY_VERIFICATION_ACCEPT,
+                EventType.KEY_VERIFICATION_KEY,
+                EventType.KEY_VERIFICATION_MAC,
+                EventType.KEY_VERIFICATION_CANCEL,
+                EventType.KEY_VERIFICATION_DONE,
+                EventType.KEY_VERIFICATION_READY
+        )
+
+        for (type in verificationEvents) {
+            val params = SendToDeviceTask.Params(
+                    eventType = type,
+                    contentMap = contentMap
+            )
+            runBlocking {
+                sendToDeviceTask.execute(params)
+            }
+
+            val modifiedContent = fakeCryptoAPi.body!!.messages!!["@alice:example.com"]!!["MNQHVEISFQ"] as Map<*, *>
+            Assert.assertNull("Tracing id should not have been added", modifiedContent["org.matrix.msgid"])
+        }
+    }
+
+    internal class FakeCryptoApi : CryptoApi {
+        override suspend fun getDevices(): DevicesListResponse {
+            throw java.lang.AssertionError("Should not be called")
+        }
+
+        override suspend fun getDeviceInfo(deviceId: String): DeviceInfo {
+            throw java.lang.AssertionError("Should not be called")
+        }
+
+        override suspend fun uploadKeys(body: KeysUploadBody): KeysUploadResponse {
+            throw java.lang.AssertionError("Should not be called")
+        }
+
+        override suspend fun downloadKeysForUsers(params: KeysQueryBody): KeysQueryResponse {
+            throw java.lang.AssertionError("Should not be called")
+        }
+
+        override suspend fun uploadSigningKeys(params: UploadSigningKeysBody): KeysQueryResponse {
+            throw java.lang.AssertionError("Should not be called")
+        }
+
+        override suspend fun uploadSignatures(params: Map<String, Any>?): SignatureUploadResponse {
+            throw java.lang.AssertionError("Should not be called")
+        }
+
+        override suspend fun claimOneTimeKeysForUsersDevices(body: KeysClaimBody): KeysClaimResponse {
+            throw java.lang.AssertionError("Should not be called")
+        }
+
+        var body: SendToDeviceBody? = null
+        override suspend fun sendToDevice(eventType: String, transactionId: String, body: SendToDeviceBody) {
+            this.body = body
+        }
+
+        override suspend fun deleteDevice(deviceId: String, params: DeleteDeviceParams) {
+            throw java.lang.AssertionError("Should not be called")
+        }
+
+        override suspend fun deleteDevices(params: DeleteDevicesParams) {
+            throw java.lang.AssertionError("Should not be called")
+        }
+
+        override suspend fun updateDeviceInfo(deviceId: String, params: UpdateDeviceInfoBody) {
+            throw java.lang.AssertionError("Should not be called")
+        }
+
+        override suspend fun getKeyChanges(oldToken: String, newToken: String): KeyChangesResponse {
+            throw java.lang.AssertionError("Should not be called")
+        }
+    }
+}