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/internal/crypto/tasks/SendToDeviceTask.kt

@@ -17,14 +17,21 @@
 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.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
@@ -42,15 +49,17 @@ 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 = decorateWithToDeviceTracingIds(params)
+        val sendToDeviceBody = SendToDeviceBody(
+                messages = decorated.first
+        )
+
         return executeRequest(
                 globalErrorReceiver,
                 canRetry = true,
@@ -61,8 +70,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 tracingId:${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} id:${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,161 @@
+/*
+ * Copyright (c) 2022 New Vector Ltd
+ *
+ * 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.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
+import org.matrix.android.sdk.internal.network.GlobalErrorReceiver
+
+class DefaultSendToDeviceTaskTest {
+
+    val users = listOf(
+            "@alice:example.com" to listOf("D0", "D1"),
+            "bob@example.com" to listOf("D2", "D3")
+    )
+
+    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"
+                    )
+            )
+    )
+
+    @Test
+    fun `tracing id should be added to all to_device contents`() {
+        val fakeCryptoAPi = FakeCryptoApi()
+
+        val sendToDeviceTask = DefaultSendToDeviceTask(
+                cryptoApi = fakeCryptoAPi,
+                globalErrorReceiver = mockk<GlobalErrorReceiver>(relaxed = true)
+        )
+
+        val contentMap = MXUsersDevicesMap<Any>()
+
+        users.forEach {
+            val userId = it.first
+            it.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 {
+            val userId = it.first
+            it.second.forEach {
+                val modifiedContent = fakeCryptoAPi.body!!.messages!![userId]!![it] as Map<String, *>
+                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}")
+    }
+
+    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")
+        }
+    }
+}