From f2952f2deee61693de49e6b703b913ba0d5d8d6d Mon Sep 17 00:00:00 2001 From: valere Date: Mon, 5 Dec 2022 18:15:30 +0100 Subject: [PATCH] add to device tracing id --- changelog.d/7708.misc | 1 + .../internal/crypto/tasks/SendToDeviceTask.kt | 44 ++++- .../session/sync/handler/CryptoSyncHandler.kt | 5 +- .../crypto/DefaultSendToDeviceTaskTest.kt | 161 ++++++++++++++++++ 4 files changed, 206 insertions(+), 5 deletions(-) create mode 100644 changelog.d/7708.misc create mode 100644 matrix-sdk-android/src/test/java/org/matrix/android/sdk/internal/crypto/DefaultSendToDeviceTaskTest.kt diff --git a/changelog.d/7708.misc b/changelog.d/7708.misc new file mode 100644 index 0000000000..6273330395 --- /dev/null +++ b/changelog.d/7708.misc @@ -0,0 +1 @@ +Add tracing Id for to device messages diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/tasks/SendToDeviceTask.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/tasks/SendToDeviceTask.kt index fc4d422360..1e6ceeb138 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/tasks/SendToDeviceTask.kt +++ b/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 { 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>, List> { + val tracingInfo = mutableListOf() + 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() diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/handler/CryptoSyncHandler.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/handler/CryptoSyncHandler.kt index b2fe12ebc3..291e785aa5 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/handler/CryptoSyncHandler.kt +++ b/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()?.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) } diff --git a/matrix-sdk-android/src/test/java/org/matrix/android/sdk/internal/crypto/DefaultSendToDeviceTaskTest.kt b/matrix-sdk-android/src/test/java/org/matrix/android/sdk/internal/crypto/DefaultSendToDeviceTaskTest.kt new file mode 100644 index 0000000000..72d166c1f4 --- /dev/null +++ b/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(relaxed = true) + ) + + val contentMap = MXUsersDevicesMap() + + 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() + users.forEach { + val userId = it.first + it.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}") + } + + 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?): 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") + } + } +}