diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/logger/LoggerTag.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/logger/LoggerTag.kt index 0d204edceed..44ac439d7b0 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/logger/LoggerTag.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/logger/LoggerTag.kt @@ -26,6 +26,7 @@ open class LoggerTag(_value: String, parentTag: LoggerTag? = null) { object SYNC : LoggerTag("SYNC") object VOIP : LoggerTag("VOIP") + object CRYPTO : LoggerTag("CRYPTO") val value: String = if (parentTag == null) { _value diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/DefaultCryptoService.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/DefaultCryptoService.kt index 7b96148e2e5..18f344882c6 100755 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/DefaultCryptoService.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/DefaultCryptoService.kt @@ -36,6 +36,7 @@ import org.matrix.android.sdk.api.crypto.MXCryptoConfig import org.matrix.android.sdk.api.extensions.tryOrNull import org.matrix.android.sdk.api.failure.Failure import org.matrix.android.sdk.api.listeners.ProgressListener +import org.matrix.android.sdk.api.logger.LoggerTag import org.matrix.android.sdk.api.session.crypto.CryptoService import org.matrix.android.sdk.api.session.crypto.MXCryptoError import org.matrix.android.sdk.api.session.crypto.crosssigning.KEYBACKUP_SECRET_SSSS_NAME @@ -110,6 +111,9 @@ import kotlin.math.max * CryptoService maintains all necessary keys and their sharing with other devices required for the crypto. * Specially, it tracks all room membership changes events in order to do keys updates. */ + +private val loggerTag = LoggerTag("DefaultCryptoService", LoggerTag.CRYPTO) + @SessionScope internal class DefaultCryptoService @Inject constructor( // Olm Manager @@ -346,7 +350,7 @@ internal class DefaultCryptoService @Inject constructor( deviceListManager.startTrackingDeviceList(listOf(userId)) deviceListManager.refreshOutdatedDeviceLists() } catch (failure: Throwable) { - Timber.e(failure, "## CRYPTO onSyncWillProcess ") + Timber.tag(loggerTag.value).e(failure, "onSyncWillProcess ") } } } @@ -379,7 +383,7 @@ internal class DefaultCryptoService @Inject constructor( { isStarting.set(false) isStarted.set(false) - Timber.e(it, "Start failed") + Timber.tag(loggerTag.value).e(it, "Start failed") } ) } @@ -551,14 +555,14 @@ internal class DefaultCryptoService @Inject constructor( val existingAlgorithm = cryptoStore.getRoomAlgorithm(roomId) if (!existingAlgorithm.isNullOrEmpty() && existingAlgorithm != algorithm) { - Timber.e("## CRYPTO | setEncryptionInRoom() : Ignoring m.room.encryption event which requests a change of config in $roomId") + Timber.tag(loggerTag.value).e("setEncryptionInRoom() : Ignoring m.room.encryption event which requests a change of config in $roomId") return false } val encryptingClass = MXCryptoAlgorithms.hasEncryptorClassForAlgorithm(algorithm) if (!encryptingClass) { - Timber.e("## CRYPTO | setEncryptionInRoom() : Unable to encrypt room $roomId with $algorithm") + Timber.tag(loggerTag.value).e("setEncryptionInRoom() : Unable to encrypt room $roomId with $algorithm") return false } @@ -577,7 +581,7 @@ internal class DefaultCryptoService @Inject constructor( // e2e rooms with them, so there is room for optimisation here, but for now // we just invalidate everyone in the room. if (null == existingAlgorithm) { - Timber.v("Enabling encryption in $roomId for the first time; invalidating device lists for all users therein") + Timber.tag(loggerTag.value).d("Enabling encryption in $roomId for the first time; invalidating device lists for all users therein") val userIds = ArrayList(membersId) @@ -655,17 +659,17 @@ internal class DefaultCryptoService @Inject constructor( val safeAlgorithm = alg if (safeAlgorithm != null) { val t0 = System.currentTimeMillis() - Timber.v("## CRYPTO | encryptEventContent() starts") + Timber.tag(loggerTag.value).v("encryptEventContent() starts") runCatching { val content = safeAlgorithm.encryptEventContent(eventContent, eventType, userIds) - Timber.v("## CRYPTO | encryptEventContent() : succeeds after ${System.currentTimeMillis() - t0} ms") + Timber.tag(loggerTag.value).v("## CRYPTO | encryptEventContent() : succeeds after ${System.currentTimeMillis() - t0} ms") MXEncryptEventContentResult(content, EventType.ENCRYPTED) }.foldToCallback(callback) } else { val algorithm = getEncryptionAlgorithm(roomId) val reason = String.format(MXCryptoError.UNABLE_TO_ENCRYPT_REASON, algorithm ?: MXCryptoError.NO_MORE_ALGORITHM_REASON) - Timber.e("## CRYPTO | encryptEventContent() : $reason") + Timber.tag(loggerTag.value).e("encryptEventContent() : failed $reason") callback.onFailure(Failure.CryptoError(MXCryptoError.Base(MXCryptoError.ErrorType.UNABLE_TO_ENCRYPT, reason))) } } @@ -677,7 +681,7 @@ internal class DefaultCryptoService @Inject constructor( if (roomEncryptor is IMXGroupEncryption) { roomEncryptor.discardSessionKey() } else { - Timber.e("## CRYPTO | discardOutboundSession() for:$roomId: Unable to handle IMXGroupEncryption") + Timber.tag(loggerTag.value).e("discardOutboundSession() for:$roomId: Unable to handle IMXGroupEncryption") } } } @@ -768,14 +772,14 @@ internal class DefaultCryptoService @Inject constructor( */ private fun onRoomKeyEvent(event: Event) { val roomKeyContent = event.getClearContent().toModel() ?: return - Timber.i("## CRYPTO | onRoomKeyEvent() from: ${event.senderId} type<${event.getClearType()}> , sessionId<${roomKeyContent.sessionId}>") + Timber.tag(loggerTag.value).i("onRoomKeyEvent() from: ${event.senderId} type<${event.getClearType()}> , sessionId<${roomKeyContent.sessionId}>") if (roomKeyContent.roomId.isNullOrEmpty() || roomKeyContent.algorithm.isNullOrEmpty()) { - Timber.e("## CRYPTO | onRoomKeyEvent() : missing fields") + Timber.tag(loggerTag.value).e("onRoomKeyEvent() : missing fields") return } val alg = roomDecryptorProvider.getOrCreateRoomDecryptor(roomKeyContent.roomId, roomKeyContent.algorithm) if (alg == null) { - Timber.e("## CRYPTO | GOSSIP onRoomKeyEvent() : Unable to handle keys for ${roomKeyContent.algorithm}") + Timber.tag(loggerTag.value).e("GOSSIP onRoomKeyEvent() : Unable to handle keys for ${roomKeyContent.algorithm}") return } alg.onRoomKeyEvent(event, keysBackupService) @@ -783,29 +787,29 @@ internal class DefaultCryptoService @Inject constructor( private fun onKeyWithHeldReceived(event: Event) { val withHeldContent = event.getClearContent().toModel() ?: return Unit.also { - Timber.i("## CRYPTO | Malformed onKeyWithHeldReceived() : missing fields") + Timber.tag(loggerTag.value).i("Malformed onKeyWithHeldReceived() : missing fields") } - Timber.i("## CRYPTO | onKeyWithHeldReceived() received from:${event.senderId}, content <$withHeldContent>") + Timber.tag(loggerTag.value).i("onKeyWithHeldReceived() received from:${event.senderId}, content <$withHeldContent>") val alg = roomDecryptorProvider.getOrCreateRoomDecryptor(withHeldContent.roomId, withHeldContent.algorithm) if (alg is IMXWithHeldExtension) { alg.onRoomKeyWithHeldEvent(withHeldContent) } else { - Timber.e("## CRYPTO | onKeyWithHeldReceived() from:${event.senderId}: Unable to handle WithHeldContent for ${withHeldContent.algorithm}") + Timber.tag(loggerTag.value).e("onKeyWithHeldReceived() from:${event.senderId}: Unable to handle WithHeldContent for ${withHeldContent.algorithm}") return } } private fun onSecretSendReceived(event: Event) { - Timber.i("## CRYPTO | GOSSIP onSecretSend() from ${event.senderId} : onSecretSendReceived ${event.content?.get("sender_key")}") + Timber.tag(loggerTag.value).i("GOSSIP onSecretSend() from ${event.senderId} : onSecretSendReceived ${event.content?.get("sender_key")}") if (!event.isEncrypted()) { // secret send messages must be encrypted - Timber.e("## CRYPTO | GOSSIP onSecretSend() :Received unencrypted secret send event") + Timber.tag(loggerTag.value).e("GOSSIP onSecretSend() :Received unencrypted secret send event") return } // Was that sent by us? if (event.senderId != userId) { - Timber.e("## CRYPTO | GOSSIP onSecretSend() : Ignore secret from other user ${event.senderId}") + Timber.tag(loggerTag.value).e("GOSSIP onSecretSend() : Ignore secret from other user ${event.senderId}") return } @@ -815,13 +819,13 @@ internal class DefaultCryptoService @Inject constructor( .getOutgoingSecretKeyRequests().firstOrNull { it.requestId == secretContent.requestId } if (existingRequest == null) { - Timber.i("## CRYPTO | GOSSIP onSecretSend() : Ignore secret that was not requested: ${secretContent.requestId}") + Timber.tag(loggerTag.value).i("GOSSIP onSecretSend() : Ignore secret that was not requested: ${secretContent.requestId}") return } if (!handleSDKLevelGossip(existingRequest.secretName, secretContent.secretValue)) { // TODO Ask to application layer? - Timber.v("## CRYPTO | onSecretSend() : secret not handled by SDK") + Timber.tag(loggerTag.value).v("onSecretSend() : secret not handled by SDK") } } @@ -858,7 +862,7 @@ internal class DefaultCryptoService @Inject constructor( private fun onRoomEncryptionEvent(roomId: String, event: Event) { if (!event.isStateEvent()) { // Ignore - Timber.w("Invalid encryption event") + Timber.tag(loggerTag.value).w("Invalid encryption event") return } cryptoCoroutineScope.launch(coroutineDispatchers.crypto) { @@ -912,7 +916,7 @@ internal class DefaultCryptoService @Inject constructor( */ private suspend fun uploadDeviceKeys() { if (cryptoStore.areDeviceKeysUploaded()) { - Timber.d("Keys already uploaded, nothing to do") + Timber.tag(loggerTag.value).d("Keys already uploaded, nothing to do") return } // Prepare the device keys data to send @@ -971,13 +975,13 @@ internal class DefaultCryptoService @Inject constructor( password: String, progressListener: ProgressListener?): ImportRoomKeysResult { return withContext(coroutineDispatchers.crypto) { - Timber.v("## CRYPTO | importRoomKeys starts") + Timber.tag(loggerTag.value).v("importRoomKeys starts") val t0 = System.currentTimeMillis() val roomKeys = MXMegolmExportEncryption.decryptMegolmKeyFile(roomKeysAsArray, password) val t1 = System.currentTimeMillis() - Timber.v("## CRYPTO | importRoomKeys : decryptMegolmKeyFile done in ${t1 - t0} ms") + Timber.tag(loggerTag.value).v("importRoomKeys : decryptMegolmKeyFile done in ${t1 - t0} ms") val importedSessions = MoshiProvider.providesMoshi() .adapter>(Types.newParameterizedType(List::class.java, MegolmSessionData::class.java)) @@ -985,7 +989,7 @@ internal class DefaultCryptoService @Inject constructor( val t2 = System.currentTimeMillis() - Timber.v("## CRYPTO | importRoomKeys : JSON parsing ${t2 - t1} ms") + Timber.tag(loggerTag.value).v("importRoomKeys : JSON parsing ${t2 - t1} ms") if (importedSessions == null) { throw Exception("Error") @@ -1122,7 +1126,7 @@ internal class DefaultCryptoService @Inject constructor( */ override fun reRequestRoomKeyForEvent(event: Event) { val wireContent = event.content.toModel() ?: return Unit.also { - Timber.e("## CRYPTO | reRequestRoomKeyForEvent Failed to re-request key, null content") + Timber.tag(loggerTag.value).e("reRequestRoomKeyForEvent Failed to re-request key, null content") } val requestBody = RoomKeyRequestBody( @@ -1137,7 +1141,7 @@ internal class DefaultCryptoService @Inject constructor( override fun requestRoomKeyForEvent(event: Event) { val wireContent = event.content.toModel() ?: return Unit.also { - Timber.e("## CRYPTO | requestRoomKeyForEvent Failed to request key, null content eventId: ${event.eventId}") + Timber.tag(loggerTag.value).e("requestRoomKeyForEvent Failed to request key, null content eventId: ${event.eventId}") } cryptoCoroutineScope.launch(coroutineDispatchers.crypto) { @@ -1148,7 +1152,7 @@ internal class DefaultCryptoService @Inject constructor( roomDecryptorProvider .getOrCreateRoomDecryptor(event.roomId, wireContent.algorithm) ?.requestKeysForEvent(event, false) ?: run { - Timber.v("## CRYPTO | requestRoomKeyForEvent() : No room decryptor for roomId:${event.roomId} algorithm:${wireContent.algorithm}") + Timber.tag(loggerTag.value).v("requestRoomKeyForEvent() : No room decryptor for roomId:${event.roomId} algorithm:${wireContent.algorithm}") } } } @@ -1287,12 +1291,12 @@ internal class DefaultCryptoService @Inject constructor( override fun prepareToEncrypt(roomId: String, callback: MatrixCallback) { cryptoCoroutineScope.launch(coroutineDispatchers.crypto) { - Timber.d("## CRYPTO | prepareToEncrypt() : Check room members up to date") + Timber.tag(loggerTag.value).d("prepareToEncrypt() roomId:$roomId Check room members up to date") // Ensure to load all room members try { loadRoomMembersTask.execute(LoadRoomMembersTask.Params(roomId)) } catch (failure: Throwable) { - Timber.e("## CRYPTO | prepareToEncrypt() : Failed to load room members") + Timber.tag(loggerTag.value).e("prepareToEncrypt() : Failed to load room members") callback.onFailure(failure) return@launch } @@ -1305,7 +1309,7 @@ internal class DefaultCryptoService @Inject constructor( if (alg == null) { val reason = String.format(MXCryptoError.UNABLE_TO_ENCRYPT_REASON, MXCryptoError.NO_MORE_ALGORITHM_REASON) - Timber.e("## CRYPTO | prepareToEncrypt() : $reason") + Timber.tag(loggerTag.value).e("prepareToEncrypt() : $reason") callback.onFailure(IllegalArgumentException("Missing algorithm")) return@launch } @@ -1315,7 +1319,7 @@ internal class DefaultCryptoService @Inject constructor( }.fold( { callback.onSuccess(Unit) }, { - Timber.e("## CRYPTO | prepareToEncrypt() failed.") + Timber.tag(loggerTag.value).e(it, "prepareToEncrypt() failed.") callback.onFailure(it) } ) diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/actions/EnsureOlmSessionsForDevicesAction.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/actions/EnsureOlmSessionsForDevicesAction.kt index 3979ff1fb48..df7a2924fd1 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/actions/EnsureOlmSessionsForDevicesAction.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/actions/EnsureOlmSessionsForDevicesAction.kt @@ -21,6 +21,7 @@ import org.matrix.android.sdk.internal.crypto.model.CryptoDeviceInfo import org.matrix.android.sdk.internal.crypto.model.MXKey import org.matrix.android.sdk.internal.crypto.model.MXOlmSessionResult import org.matrix.android.sdk.internal.crypto.model.MXUsersDevicesMap +import org.matrix.android.sdk.internal.crypto.model.toDebugString import org.matrix.android.sdk.internal.crypto.tasks.ClaimOneTimeKeysForUsersDeviceTask import timber.log.Timber import javax.inject.Inject @@ -36,15 +37,22 @@ internal class EnsureOlmSessionsForDevicesAction @Inject constructor( val results = MXUsersDevicesMap() - for ((userId, deviceInfos) in devicesByUser) { - for (deviceInfo in deviceInfos) { + for ((userId, deviceInfo) in devicesByUser) { + for (deviceInfo in deviceInfo) { val deviceId = deviceInfo.deviceId val key = deviceInfo.identityKey() + if (key == null) { + Timber.w("## CRYPTO | Ignoring device (${deviceInfo.userId}|$deviceId) without identity key") + continue + } - val sessionId = olmDevice.getSessionId(key!!) + val sessionId = olmDevice.getSessionId(key) if (sessionId.isNullOrEmpty() || force) { + Timber.d("## CRYPTO | Found no existing olm session (${deviceInfo.userId}|$deviceId) (force=$force)") devicesWithoutSession.add(deviceInfo) + } else { + Timber.d("## CRYPTO | using olm session $sessionId for (${deviceInfo.userId}|$deviceId)") } val olmSessionResult = MXOlmSessionResult(deviceInfo, sessionId) @@ -52,6 +60,8 @@ internal class EnsureOlmSessionsForDevicesAction @Inject constructor( } } + Timber.d("## CRYPTO | Devices without olm session (count:${devicesWithoutSession.size}) :" + + " ${devicesWithoutSession.joinToString { "${it.userId}|${it.deviceId}" }}") if (devicesWithoutSession.size == 0) { return results } @@ -71,7 +81,7 @@ internal class EnsureOlmSessionsForDevicesAction @Inject constructor( // // That should eventually resolve itself, but it's poor form. - Timber.i("## CRYPTO | claimOneTimeKeysForUsersDevices() : $usersDevicesToClaim") + Timber.i("## CRYPTO | claimOneTimeKeysForUsersDevices() : ${usersDevicesToClaim.toDebugString()}") val claimParams = ClaimOneTimeKeysForUsersDeviceTask.Params(usersDevicesToClaim) val oneTimeKeys = oneTimeKeysForUsersDeviceTask.executeRetry(claimParams, remainingRetry = ONE_TIME_KEYS_RETRY_COUNT) @@ -83,7 +93,7 @@ internal class EnsureOlmSessionsForDevicesAction @Inject constructor( if (null != deviceIds) { for (deviceId in deviceIds) { val olmSessionResult = results.getObject(userId, deviceId) - if (olmSessionResult!!.sessionId != null && !force) { + if (olmSessionResult?.sessionId != null && !force) { // We already have a result for this device continue } @@ -92,12 +102,11 @@ internal class EnsureOlmSessionsForDevicesAction @Inject constructor( oneTimeKey = key } if (oneTimeKey == null) { - Timber.w("## CRYPTO | ensureOlmSessionsForDevices() : No one-time keys " + oneTimeKeyAlgorithm + - " for device " + userId + " : " + deviceId) + Timber.d("## CRYPTO: No one time key for $userId|$deviceId") continue } // Update the result for this device in results - olmSessionResult.sessionId = verifyKeyAndStartSession(oneTimeKey, userId, deviceInfo) + olmSessionResult?.sessionId = verifyKeyAndStartSession(oneTimeKey, userId, deviceInfo) } } } @@ -112,27 +121,33 @@ internal class EnsureOlmSessionsForDevicesAction @Inject constructor( val signKeyId = "ed25519:$deviceId" val signature = oneTimeKey.signatureForUserId(userId, signKeyId) - if (!signature.isNullOrEmpty() && !deviceInfo.fingerprint().isNullOrEmpty()) { + val fingerprint = deviceInfo.fingerprint() + if (!signature.isNullOrEmpty() && !fingerprint.isNullOrEmpty()) { var isVerified = false var errorMessage: String? = null try { - olmDevice.verifySignature(deviceInfo.fingerprint()!!, oneTimeKey.signalableJSONDictionary(), signature) + olmDevice.verifySignature(fingerprint, oneTimeKey.signalableJSONDictionary(), signature) isVerified = true } catch (e: Exception) { + Timber.d(e, "## CRYPTO | verifyKeyAndStartSession() : Verify error for otk: ${oneTimeKey.signalableJSONDictionary()}," + + " signature:$signature fingerprint:$fingerprint") + Timber.e("## CRYPTO | verifyKeyAndStartSession() : Verify error for ${deviceInfo.userId}|${deviceInfo.deviceId} " + + " - signable json ${oneTimeKey.signalableJSONDictionary()}") errorMessage = e.message } // Check one-time key signature if (isVerified) { - sessionId = olmDevice.createOutboundSession(deviceInfo.identityKey()!!, oneTimeKey.value) + sessionId = deviceInfo.identityKey()?.let { identityKey -> + olmDevice.createOutboundSession(identityKey, oneTimeKey.value) + } - if (!sessionId.isNullOrEmpty()) { - Timber.v("## CRYPTO | verifyKeyAndStartSession() : Started new sessionid " + sessionId + - " for device " + deviceInfo + "(theirOneTimeKey: " + oneTimeKey.value + ")") - } else { + if (sessionId.isNullOrEmpty()) { // Possibly a bad key Timber.e("## CRYPTO | verifyKeyAndStartSession() : Error starting session with device $userId:$deviceId") + } else { + Timber.d("## CRYPTO | verifyKeyAndStartSession() : Started new sessionId $sessionId for device $userId:$deviceId") } } else { Timber.e("## CRYPTO | verifyKeyAndStartSession() : Unable to verify signature on one-time key for device " + userId + diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/algorithms/megolm/MXMegolmDecryption.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/algorithms/megolm/MXMegolmDecryption.kt index d7411ad0be7..8bbc71543cf 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/algorithms/megolm/MXMegolmDecryption.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/algorithms/megolm/MXMegolmDecryption.kt @@ -19,6 +19,7 @@ package org.matrix.android.sdk.internal.crypto.algorithms.megolm import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.launch import org.matrix.android.sdk.api.MatrixCoroutineDispatchers +import org.matrix.android.sdk.api.logger.LoggerTag import org.matrix.android.sdk.api.session.crypto.MXCryptoError import org.matrix.android.sdk.api.session.events.model.Event import org.matrix.android.sdk.api.session.events.model.EventType @@ -44,6 +45,8 @@ import org.matrix.android.sdk.internal.crypto.store.IMXCryptoStore import org.matrix.android.sdk.internal.crypto.tasks.SendToDeviceTask import timber.log.Timber +private val loggerTag = LoggerTag("MXMegolmDecryption", LoggerTag.CRYPTO) + internal class MXMegolmDecryption(private val userId: String, private val olmDevice: MXOlmDevice, private val deviceListManager: DeviceListManager, @@ -74,7 +77,7 @@ internal class MXMegolmDecryption(private val userId: String, @Throws(MXCryptoError::class) private fun decryptEvent(event: Event, timeline: String, requestKeysOnFail: Boolean): MXEventDecryptionResult { - Timber.v("## CRYPTO | decryptEvent ${event.eventId}, requestKeysOnFail:$requestKeysOnFail") + Timber.tag(loggerTag.value).v("decryptEvent ${event.eventId}, requestKeysOnFail:$requestKeysOnFail") if (event.roomId.isNullOrBlank()) { throw MXCryptoError.Base(MXCryptoError.ErrorType.MISSING_FIELDS, MXCryptoError.MISSING_FIELDS_REASON) } @@ -230,7 +233,7 @@ internal class MXMegolmDecryption(private val userId: String, * @param event the key event. */ override fun onRoomKeyEvent(event: Event, defaultKeysBackupService: DefaultKeysBackupService) { - Timber.v("## CRYPTO | onRoomKeyEvent()") + Timber.tag(loggerTag.value).v("onRoomKeyEvent()") var exportFormat = false val roomKeyContent = event.getClearContent().toModel() ?: return @@ -239,11 +242,11 @@ internal class MXMegolmDecryption(private val userId: String, val forwardingCurve25519KeyChain: MutableList = ArrayList() if (roomKeyContent.roomId.isNullOrEmpty() || roomKeyContent.sessionId.isNullOrEmpty() || roomKeyContent.sessionKey.isNullOrEmpty()) { - Timber.e("## CRYPTO | onRoomKeyEvent() : Key event is missing fields") + Timber.tag(loggerTag.value).e("onRoomKeyEvent() : Key event is missing fields") return } if (event.getClearType() == EventType.FORWARDED_ROOM_KEY) { - Timber.i("## CRYPTO | onRoomKeyEvent(), forward adding key : ${roomKeyContent.roomId}|${roomKeyContent.sessionId}") + Timber.tag(loggerTag.value).i("onRoomKeyEvent(), forward adding key : ${roomKeyContent.roomId}|${roomKeyContent.sessionId}") val forwardedRoomKeyContent = event.getClearContent().toModel() ?: return @@ -252,7 +255,7 @@ internal class MXMegolmDecryption(private val userId: String, } if (senderKey == null) { - Timber.e("## CRYPTO | onRoomKeyEvent() : event is missing sender_key field") + Timber.tag(loggerTag.value).e("onRoomKeyEvent() : event is missing sender_key field") return } @@ -261,20 +264,20 @@ internal class MXMegolmDecryption(private val userId: String, exportFormat = true senderKey = forwardedRoomKeyContent.senderKey if (null == senderKey) { - Timber.e("## CRYPTO | onRoomKeyEvent() : forwarded_room_key event is missing sender_key field") + Timber.tag(loggerTag.value).e("onRoomKeyEvent() : forwarded_room_key event is missing sender_key field") return } if (null == forwardedRoomKeyContent.senderClaimedEd25519Key) { - Timber.e("## CRYPTO | forwarded_room_key_event is missing sender_claimed_ed25519_key field") + Timber.tag(loggerTag.value).e("forwarded_room_key_event is missing sender_claimed_ed25519_key field") return } keysClaimed["ed25519"] = forwardedRoomKeyContent.senderClaimedEd25519Key } else { - Timber.i("## CRYPTO | onRoomKeyEvent(), Adding key : ${roomKeyContent.roomId}|${roomKeyContent.sessionId}") + Timber.tag(loggerTag.value).i("onRoomKeyEvent(), Adding key : ${roomKeyContent.roomId}|${roomKeyContent.sessionId}") if (null == senderKey) { - Timber.e("## onRoomKeyEvent() : key event has no sender key (not encrypted?)") + Timber.tag(loggerTag.value).e("## onRoomKeyEvent() : key event has no sender key (not encrypted?)") return } @@ -282,7 +285,7 @@ internal class MXMegolmDecryption(private val userId: String, keysClaimed = event.getKeysClaimed().toMutableMap() } - Timber.i("## CRYPTO | onRoomKeyEvent addInboundGroupSession ${roomKeyContent.sessionId}") + Timber.tag(loggerTag.value).i("onRoomKeyEvent addInboundGroupSession ${roomKeyContent.sessionId}") val added = olmDevice.addInboundGroupSession(roomKeyContent.sessionId, roomKeyContent.sessionKey, roomKeyContent.roomId, @@ -314,7 +317,7 @@ internal class MXMegolmDecryption(private val userId: String, * @param sessionId the session id */ override fun onNewSession(senderKey: String, sessionId: String) { - Timber.v(" CRYPTO | ON NEW SESSION $sessionId - $senderKey") + Timber.tag(loggerTag.value).v("ON NEW SESSION $sessionId - $senderKey") newSessionListener?.onNewSession(null, senderKey, sessionId) } @@ -346,10 +349,10 @@ internal class MXMegolmDecryption(private val userId: String, if (olmSessionResult?.sessionId == null) { // no session with this device, probably because there // were no one-time keys. - Timber.e("no session with this device $deviceId, probably because there were no one-time keys.") + Timber.tag(loggerTag.value).e("no session with this device $deviceId, probably because there were no one-time keys.") return@mapCatching } - Timber.i("## CRYPTO | shareKeysWithDevice() : sharing session ${body.sessionId} with device $userId:$deviceId") + Timber.tag(loggerTag.value).i("shareKeysWithDevice() : sharing session ${body.sessionId} with device $userId:$deviceId") val payloadJson = mutableMapOf("type" to EventType.FORWARDED_ROOM_KEY) runCatching { olmDevice.getInboundGroupSession(body.sessionId, body.senderKey, body.roomId) } @@ -360,7 +363,7 @@ internal class MXMegolmDecryption(private val userId: String, }, { // TODO - Timber.e(it, "## CRYPTO | shareKeysWithDevice: failed to get session for request $body") + Timber.tag(loggerTag.value).e(it, "shareKeysWithDevice: failed to get session for request $body") } ) @@ -368,12 +371,12 @@ internal class MXMegolmDecryption(private val userId: String, val encodedPayload = messageEncrypter.encryptMessage(payloadJson, listOf(deviceInfo)) val sendToDeviceMap = MXUsersDevicesMap() sendToDeviceMap.setObject(userId, deviceId, encodedPayload) - Timber.i("## CRYPTO | shareKeysWithDevice() : sending ${body.sessionId} to $userId:$deviceId") + Timber.tag(loggerTag.value).i("shareKeysWithDevice() : sending ${body.sessionId} to $userId:$deviceId") val sendToDeviceParams = SendToDeviceTask.Params(EventType.ENCRYPTED, sendToDeviceMap) try { sendToDeviceTask.execute(sendToDeviceParams) } catch (failure: Throwable) { - Timber.e(failure, "## CRYPTO | shareKeysWithDevice() : Failed to send ${body.sessionId} to $userId:$deviceId") + Timber.tag(loggerTag.value).e(failure, "shareKeysWithDevice() : Failed to send ${body.sessionId} to $userId:$deviceId") } } } diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/algorithms/megolm/MXMegolmEncryption.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/algorithms/megolm/MXMegolmEncryption.kt index 031bb4e194f..9e8cc63702e 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/algorithms/megolm/MXMegolmEncryption.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/algorithms/megolm/MXMegolmEncryption.kt @@ -19,6 +19,7 @@ package org.matrix.android.sdk.internal.crypto.algorithms.megolm import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.launch import org.matrix.android.sdk.api.MatrixCoroutineDispatchers +import org.matrix.android.sdk.api.logger.LoggerTag import org.matrix.android.sdk.api.session.crypto.MXCryptoError import org.matrix.android.sdk.api.session.events.model.Content import org.matrix.android.sdk.api.session.events.model.Event @@ -36,6 +37,8 @@ import org.matrix.android.sdk.internal.crypto.model.MXUsersDevicesMap import org.matrix.android.sdk.internal.crypto.model.event.RoomKeyWithHeldContent import org.matrix.android.sdk.internal.crypto.model.event.WithHeldCode import org.matrix.android.sdk.internal.crypto.model.forEach +import org.matrix.android.sdk.internal.crypto.model.toDebugCount +import org.matrix.android.sdk.internal.crypto.model.toDebugString import org.matrix.android.sdk.internal.crypto.repository.WarnOnUnknownDeviceRepository import org.matrix.android.sdk.internal.crypto.store.IMXCryptoStore import org.matrix.android.sdk.internal.crypto.tasks.SendToDeviceTask @@ -43,6 +46,8 @@ import org.matrix.android.sdk.internal.util.JsonCanonicalizer import org.matrix.android.sdk.internal.util.convertToUTF8 import timber.log.Timber +private val loggerTag = LoggerTag("MXMegolmEncryption", LoggerTag.CRYPTO) + internal class MXMegolmEncryption( // The id of the room we will be sending to. private val roomId: String, @@ -51,8 +56,8 @@ internal class MXMegolmEncryption( private val cryptoStore: IMXCryptoStore, private val deviceListManager: DeviceListManager, private val ensureOlmSessionsForDevicesAction: EnsureOlmSessionsForDevicesAction, - private val userId: String, - private val deviceId: String, + private val myUserId: String, + private val myDeviceId: String, private val sendToDeviceTask: SendToDeviceTask, private val messageEncrypter: MessageEncrypter, private val warnOnUnknownDevicesRepository: WarnOnUnknownDeviceRepository, @@ -80,9 +85,10 @@ internal class MXMegolmEncryption( eventType: String, userIds: List): Content { val ts = System.currentTimeMillis() - Timber.v("## CRYPTO | encryptEventContent : getDevicesInRoom") + Timber.tag(loggerTag.value).v("encryptEventContent : getDevicesInRoom") val devices = getDevicesInRoom(userIds) - Timber.v("## CRYPTO | encryptEventContent ${System.currentTimeMillis() - ts}: getDevicesInRoom ${devices.allowedDevices.map}") + Timber.tag(loggerTag.value).d("encrypt event in room=$roomId - devices count in room ${devices.allowedDevices.toDebugCount()}") + Timber.tag(loggerTag.value).v("encryptEventContent ${System.currentTimeMillis() - ts}: getDevicesInRoom ${devices.allowedDevices.map}") val outboundSession = ensureOutboundSession(devices.allowedDevices) return encryptContent(outboundSession, eventType, eventContent) @@ -91,7 +97,7 @@ internal class MXMegolmEncryption( // annoyingly we have to serialize again the saved outbound session to store message index :/ // if not we would see duplicate message index errors olmDevice.storeOutboundGroupSessionForRoom(roomId, outboundSession.sessionId) - Timber.v("## CRYPTO | encryptEventContent: Finished in ${System.currentTimeMillis() - ts} millis") + Timber.tag(loggerTag.value).d("encrypt event in room=$roomId Finished in ${System.currentTimeMillis() - ts} millis") } } @@ -118,13 +124,13 @@ internal class MXMegolmEncryption( override suspend fun preshareKey(userIds: List) { val ts = System.currentTimeMillis() - Timber.v("## CRYPTO | preshareKey : getDevicesInRoom") + Timber.tag(loggerTag.value).d("preshareKey started in $roomId ...") val devices = getDevicesInRoom(userIds) val outboundSession = ensureOutboundSession(devices.allowedDevices) notifyWithheldForSession(devices.withHeldDevices, outboundSession) - Timber.v("## CRYPTO | preshareKey ${System.currentTimeMillis() - ts} millis") + Timber.tag(loggerTag.value).d("preshareKey in $roomId done in ${System.currentTimeMillis() - ts} millis") } /** @@ -133,7 +139,7 @@ internal class MXMegolmEncryption( * @return the session description */ private fun prepareNewSessionInRoom(): MXOutboundSessionInfo { - Timber.v("## CRYPTO | prepareNewSessionInRoom() ") + Timber.tag(loggerTag.value).v("prepareNewSessionInRoom() ") val sessionId = olmDevice.createOutboundGroupSessionForRoom(roomId) val keysClaimedMap = HashMap() @@ -153,13 +159,14 @@ internal class MXMegolmEncryption( * @param devicesInRoom the devices list */ private suspend fun ensureOutboundSession(devicesInRoom: MXUsersDevicesMap): MXOutboundSessionInfo { - Timber.v("## CRYPTO | ensureOutboundSession start") + Timber.tag(loggerTag.value).v("ensureOutboundSession roomId:$roomId") var session = outboundSession if (session == null || // Need to make a brand new session? session.needsRotation(sessionRotationPeriodMsgs, sessionRotationPeriodMs) || // Determine if we have shared with anyone we shouldn't have session.sharedWithTooManyDevices(devicesInRoom)) { + Timber.tag(loggerTag.value).d("roomId:$roomId Starting new megolm session because we need to rotate.") session = prepareNewSessionInRoom() outboundSession = session } @@ -176,6 +183,8 @@ internal class MXMegolmEncryption( } } } + val devicesCount = shareMap.entries.fold(0) { acc, new -> acc + new.value.size } + Timber.tag(loggerTag.value).d("roomId:$roomId found $devicesCount devices without megolm session(${session.sessionId})") shareKey(safeSession, shareMap) return safeSession } @@ -190,7 +199,7 @@ internal class MXMegolmEncryption( devicesByUsers: Map>) { // nothing to send, the task is done if (devicesByUsers.isEmpty()) { - Timber.v("## CRYPTO | shareKey() : nothing more to do") + Timber.tag(loggerTag.value).v("shareKey() : nothing more to do") return } // reduce the map size to avoid request timeout when there are too many devices (Users size * devices per user) @@ -203,7 +212,7 @@ internal class MXMegolmEncryption( break } } - Timber.v("## CRYPTO | shareKey() ; sessionId<${session.sessionId}> userId ${subMap.keys}") + Timber.tag(loggerTag.value).v("shareKey() ; sessionId<${session.sessionId}> userId ${subMap.keys}") shareUserDevicesKey(session, subMap) val remainingDevices = devicesByUsers - subMap.keys shareKey(session, remainingDevices) @@ -232,11 +241,11 @@ internal class MXMegolmEncryption( payload["content"] = submap var t0 = System.currentTimeMillis() - Timber.v("## CRYPTO | shareUserDevicesKey() : starts") + Timber.tag(loggerTag.value).v("shareUserDevicesKey() : starts") val results = ensureOlmSessionsForDevicesAction.handle(devicesByUser) - Timber.v( - """## CRYPTO | shareUserDevicesKey(): ensureOlmSessionsForDevices succeeds after ${System.currentTimeMillis() - t0} ms""" + Timber.tag(loggerTag.value).v( + """shareUserDevicesKey(): ensureOlmSessionsForDevices succeeds after ${System.currentTimeMillis() - t0} ms""" .trimMargin() ) val contentMap = MXUsersDevicesMap() @@ -254,10 +263,11 @@ internal class MXMegolmEncryption( // MSC 2399 // send withheld m.no_olm: an olm session could not be established. // This may happen, for example, if the sender was unable to obtain a one-time key from the recipient. + Timber.tag(loggerTag.value).v("shareUserDevicesKey() : No Olm Session for $userId:$deviceID mark for withheld") noOlmToNotify.add(UserDevice(userId, deviceID)) continue } - Timber.i("## CRYPTO | shareUserDevicesKey() : Add to share keys contentMap for $userId:$deviceID") + Timber.tag(loggerTag.value).v("shareUserDevicesKey() : Add to share keys contentMap for $userId:$deviceID") contentMap.setObject(userId, deviceID, messageEncrypter.encryptMessage(payload, listOf(sessionResult.deviceInfo))) haveTargets = true } @@ -275,7 +285,7 @@ internal class MXMegolmEncryption( gossipingEventBuffer.add( Event( type = EventType.ROOM_KEY, - senderId = this.userId, + senderId = this.myUserId, content = submap.apply { this["session_key"] = "" // we add a fake key for trail @@ -289,17 +299,18 @@ internal class MXMegolmEncryption( if (haveTargets) { t0 = System.currentTimeMillis() - Timber.i("## CRYPTO | shareUserDevicesKey() ${session.sessionId} : has target") + Timber.tag(loggerTag.value).i("shareUserDevicesKey() ${session.sessionId} : has target") + Timber.tag(loggerTag.value).d("sending to device room key for ${session.sessionId} to ${contentMap.toDebugString()}") val sendToDeviceParams = SendToDeviceTask.Params(EventType.ENCRYPTED, contentMap) try { sendToDeviceTask.execute(sendToDeviceParams) - Timber.i("## CRYPTO | shareUserDevicesKey() : sendToDevice succeeds after ${System.currentTimeMillis() - t0} ms") + Timber.tag(loggerTag.value).i("shareUserDevicesKey() : sendToDevice succeeds after ${System.currentTimeMillis() - t0} ms") } catch (failure: Throwable) { // What to do here... - Timber.e("## CRYPTO | shareUserDevicesKey() : Failed to share session <${session.sessionId}> with $devicesByUser ") + Timber.tag(loggerTag.value).e("shareUserDevicesKey() : Failed to share session <${session.sessionId}> with $devicesByUser ") } } else { - Timber.i("## CRYPTO | shareUserDevicesKey() : no need to sharekey") + Timber.tag(loggerTag.value).i("shareUserDevicesKey() : no need to share key") } if (noOlmToNotify.isNotEmpty()) { @@ -317,7 +328,8 @@ internal class MXMegolmEncryption( sessionId: String, senderKey: String?, code: WithHeldCode) { - Timber.i("## CRYPTO | notifyKeyWithHeld() :sending withheld key for $targets session:$sessionId and code $code") + Timber.tag(loggerTag.value).d("notifyKeyWithHeld() :sending withheld for session:$sessionId and code $code to" + + " ${targets.joinToString { "${it.userId}|${it.deviceId}" }}") val withHeldContent = RoomKeyWithHeldContent( roomId = roomId, senderKey = senderKey, @@ -336,7 +348,7 @@ internal class MXMegolmEncryption( try { sendToDeviceTask.execute(params) } catch (failure: Throwable) { - Timber.e("## CRYPTO | notifyKeyWithHeld() : Failed to notify withheld key for $targets session: $sessionId ") + Timber.tag(loggerTag.value).e("notifyKeyWithHeld() : Failed to notify withheld key for $targets session: $sessionId ") } } @@ -363,7 +375,7 @@ internal class MXMegolmEncryption( // Include our device ID so that recipients can send us a // m.new_device message if they don't have our session key. - map["device_id"] = deviceId + map["device_id"] = myDeviceId session.useCount++ return map } @@ -424,9 +436,9 @@ internal class MXMegolmEncryption( userId: String, deviceId: String, senderKey: String): Boolean { - Timber.i("## Crypto process reshareKey for $sessionId to $userId:$deviceId") + Timber.tag(loggerTag.value).i("process reshareKey for $sessionId to $userId:$deviceId") val deviceInfo = cryptoStore.getUserDevice(userId, deviceId) ?: return false - .also { Timber.w("## Crypto reshareKey: Device not found") } + .also { Timber.tag(loggerTag.value).w("reshareKey: Device not found") } // Get the chain index of the key we previously sent this device val wasSessionSharedWithUser = cryptoStore.getSharedSessionInfo(roomId, sessionId, deviceInfo) @@ -434,13 +446,13 @@ internal class MXMegolmEncryption( // This session was never shared with this user // Send a room key with held notifyKeyWithHeld(listOf(UserDevice(userId, deviceId)), sessionId, senderKey, WithHeldCode.UNAUTHORISED) - Timber.w("## Crypto reshareKey: ERROR : Never shared megolm with this device") + Timber.tag(loggerTag.value).w("reshareKey: ERROR : Never shared megolm with this device") return false } // if found chain index should not be null val chainIndex = wasSessionSharedWithUser.chainIndex ?: return false .also { - Timber.w("## Crypto reshareKey: Null chain index") + Timber.tag(loggerTag.value).w("reshareKey: Null chain index") } val devicesByUser = mapOf(userId to listOf(deviceInfo)) @@ -449,10 +461,10 @@ internal class MXMegolmEncryption( olmSessionResult?.sessionId // no session with this device, probably because there were no one-time keys. // ensureOlmSessionsForDevicesAction has already done the logging, so just skip it. ?: return false.also { - Timber.w("## Crypto reshareKey: no session with this device, probably because there were no one-time keys") + Timber.tag(loggerTag.value).w("reshareKey: no session with this device, probably because there were no one-time keys") } - Timber.i("[MXMegolmEncryption] reshareKey: sharing keys for session $senderKey|$sessionId:$chainIndex with device $userId:$deviceId") + Timber.tag(loggerTag.value).i(" reshareKey: sharing keys for session $senderKey|$sessionId:$chainIndex with device $userId:$deviceId") val payloadJson = mutableMapOf("type" to EventType.FORWARDED_ROOM_KEY) @@ -464,7 +476,7 @@ internal class MXMegolmEncryption( }, { // TODO - Timber.e(it, "[MXMegolmEncryption] reshareKey: failed to get session $sessionId|$senderKey|$roomId") + Timber.tag(loggerTag.value).e(it, "reshareKey: failed to get session $sessionId|$senderKey|$roomId") } ) @@ -472,14 +484,14 @@ internal class MXMegolmEncryption( val encodedPayload = messageEncrypter.encryptMessage(payloadJson, listOf(deviceInfo)) val sendToDeviceMap = MXUsersDevicesMap() sendToDeviceMap.setObject(userId, deviceId, encodedPayload) - Timber.i("## CRYPTO | reshareKey() : sending session $sessionId to $userId:$deviceId") + Timber.tag(loggerTag.value).i("reshareKey() : sending session $sessionId to $userId:$deviceId") val sendToDeviceParams = SendToDeviceTask.Params(EventType.ENCRYPTED, sendToDeviceMap) return try { sendToDeviceTask.execute(sendToDeviceParams) - Timber.i("## CRYPTO reshareKey() : successfully send <$sessionId> to $userId:$deviceId") + Timber.tag(loggerTag.value).i("reshareKey() : successfully send <$sessionId> to $userId:$deviceId") true } catch (failure: Throwable) { - Timber.e(failure, "## CRYPTO reshareKey() : fail to send <$sessionId> to $userId:$deviceId") + Timber.tag(loggerTag.value).e(failure, "reshareKey() : fail to send <$sessionId> to $userId:$deviceId") false } } diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/algorithms/megolm/MXMegolmEncryptionFactory.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/algorithms/megolm/MXMegolmEncryptionFactory.kt index 238d7eed880..136fdc05f51 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/algorithms/megolm/MXMegolmEncryptionFactory.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/algorithms/megolm/MXMegolmEncryptionFactory.kt @@ -52,8 +52,8 @@ internal class MXMegolmEncryptionFactory @Inject constructor( cryptoStore = cryptoStore, deviceListManager = deviceListManager, ensureOlmSessionsForDevicesAction = ensureOlmSessionsForDevicesAction, - userId = userId, - deviceId = deviceId!!, + myUserId = userId, + myDeviceId = deviceId!!, sendToDeviceTask = sendToDeviceTask, messageEncrypter = messageEncrypter, warnOnUnknownDevicesRepository = warnOnUnknownDevicesRepository, diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/model/MXUsersDevicesMap.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/model/MXUsersDevicesMap.kt index 9d7f2d9883e..662541428e9 100755 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/model/MXUsersDevicesMap.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/model/MXUsersDevicesMap.kt @@ -129,3 +129,11 @@ inline fun MXUsersDevicesMap.forEach(action: (String, String, T) -> Unit) } } } + +internal fun MXUsersDevicesMap.toDebugString() = + map.entries.joinToString { "${it.key} [${it.value.keys.joinToString { it }}]" } + +internal fun MXUsersDevicesMap.toDebugCount() = + map.entries.fold(0) { acc, new -> + acc + new.value.keys.size + } diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/tasks/SendEventTask.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/tasks/SendEventTask.kt index e40db6af67c..bdfe818c620 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/tasks/SendEventTask.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/tasks/SendEventTask.kt @@ -23,6 +23,7 @@ import org.matrix.android.sdk.internal.session.room.RoomAPI import org.matrix.android.sdk.internal.session.room.membership.LoadRoomMembersTask import org.matrix.android.sdk.internal.session.room.send.LocalEchoRepository import org.matrix.android.sdk.internal.task.Task +import timber.log.Timber import javax.inject.Inject internal interface SendEventTask : Task { @@ -60,7 +61,9 @@ internal class DefaultSendEventTask @Inject constructor( ) } localEchoRepository.updateSendState(localId, params.event.roomId, SendState.SENT) - return response.eventId + return response.eventId.also { + Timber.d("Event: $it just sent in ${params.event.roomId}") + } } catch (e: Throwable) { // localEchoRepository.updateSendState(params.event.eventId!!, SendState.UNDELIVERED) throw e 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 c5ec34176c6..477508a58c0 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 @@ -16,6 +16,7 @@ package org.matrix.android.sdk.internal.session.sync.handler +import org.matrix.android.sdk.api.logger.LoggerTag import org.matrix.android.sdk.api.session.crypto.MXCryptoError import org.matrix.android.sdk.api.session.events.model.Event import org.matrix.android.sdk.api.session.events.model.EventType @@ -32,6 +33,8 @@ import org.matrix.android.sdk.internal.session.initsync.ProgressReporter import timber.log.Timber import javax.inject.Inject +private val loggerTag = LoggerTag("MXMegolmEncryption", LoggerTag.CRYPTO) + internal class CryptoSyncHandler @Inject constructor(private val cryptoService: DefaultCryptoService, private val verificationService: DefaultVerificationService) { @@ -40,11 +43,11 @@ internal class CryptoSyncHandler @Inject constructor(private val cryptoService: toDevice.events?.forEachIndexed { index, event -> progressReporter?.reportProgress(index * 100F / total) // Decrypt event if necessary - Timber.i("## CRYPTO | To device event from ${event.senderId} of type:${event.type}") + Timber.tag(loggerTag.value).i("To device event from ${event.senderId} of type:${event.type}") decryptToDeviceEvent(event, null) if (event.getClearType() == EventType.MESSAGE && event.getClearContent()?.toModel()?.msgType == "m.bad.encrypted") { - Timber.e("## CRYPTO | handleToDeviceEvent() : Warning: Unable to decrypt to-device event : ${event.content}") + Timber.tag(loggerTag.value).e("handleToDeviceEvent() : Warning: Unable to decrypt to-device event : ${event.content}") } else { verificationService.onToDeviceEvent(event) cryptoService.onToDeviceEvent(event)