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/api/session/events/model/EventType.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/events/model/EventType.kt index e5c14afa90..013b452ced 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/session/events/model/EventType.kt +++ b/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, 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..a7e93202ef 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,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 { data class Params( // the type of event to send @@ -32,7 +40,9 @@ internal interface SendToDeviceTask : Task { // the content to send. Map from user_id to device_id to content dictionary. val contentMap: MXUsersDevicesMap, // 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>, 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..551db52dbd 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 msgid:${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} msgid:${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..df6fc5f165 --- /dev/null +++ b/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() + + 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() + 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() + 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() + contentMap.setObject("@alice:example.com", "MNQHVEISFQ", emptyMap()) + + 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?): 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") + } + } +}