rei-forks/element-android
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Merge pull request #4507 from vector-im/feature/bca/crypto_better_logs

Browse Source 
Improve crypto log to debug UISI
This commit is contained in:
Benoit Marty 2021-11-23 15:35:28 +01:00 committed by GitHub
commit c72dd5eec6
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
10 changed files with 157 additions and 105 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
changelog.d/4507.misc Normal file
View File

@ -0,0 +1 @@
Improve crypto logs to help debug decryption failures

1
matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/logger/LoggerTag.kt
View File

@ -26,6 +26,7 @@ open class LoggerTag(_value: String, parentTag: LoggerTag? = null) {
object SYNC : LoggerTag("SYNC") object SYNC : LoggerTag("SYNC")
object VOIP : LoggerTag("VOIP") object VOIP : LoggerTag("VOIP")
object CRYPTO : LoggerTag("CRYPTO")
val value: String = if (parentTag == null) { val value: String = if (parentTag == null) {
_value _value

68
matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/DefaultCryptoService.kt
View File

@ -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.extensions.tryOrNull
import org.matrix.android.sdk.api.failure.Failure import org.matrix.android.sdk.api.failure.Failure
import org.matrix.android.sdk.api.listeners.ProgressListener 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.CryptoService
import org.matrix.android.sdk.api.session.crypto.MXCryptoError import org.matrix.android.sdk.api.session.crypto.MXCryptoError
import org.matrix.android.sdk.api.session.crypto.crosssigning.KEYBACKUP_SECRET_SSSS_NAME 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. * 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. * Specially, it tracks all room membership changes events in order to do keys updates.
*/ */
private val loggerTag = LoggerTag("DefaultCryptoService", LoggerTag.CRYPTO)
@SessionScope @SessionScope
internal class DefaultCryptoService @Inject constructor( internal class DefaultCryptoService @Inject constructor(
// Olm Manager // Olm Manager
@ -346,7 +350,7 @@ internal class DefaultCryptoService @Inject constructor(
deviceListManager.startTrackingDeviceList(listOf(userId)) deviceListManager.startTrackingDeviceList(listOf(userId))
deviceListManager.refreshOutdatedDeviceLists() deviceListManager.refreshOutdatedDeviceLists()
} catch (failure: Throwable) { } 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) isStarting.set(false)
isStarted.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) val existingAlgorithm = cryptoStore.getRoomAlgorithm(roomId)
if (!existingAlgorithm.isNullOrEmpty() && existingAlgorithm != algorithm) { 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 return false
} }
val encryptingClass = MXCryptoAlgorithms.hasEncryptorClassForAlgorithm(algorithm) val encryptingClass = MXCryptoAlgorithms.hasEncryptorClassForAlgorithm(algorithm)
if (!encryptingClass) { 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 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 // e2e rooms with them, so there is room for optimisation here, but for now
// we just invalidate everyone in the room. // we just invalidate everyone in the room.
if (null == existingAlgorithm) { 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) val userIds = ArrayList(membersId)
@ -655,17 +659,17 @@ internal class DefaultCryptoService @Inject constructor(
val safeAlgorithm = alg val safeAlgorithm = alg
if (safeAlgorithm != null) { if (safeAlgorithm != null) {
val t0 = System.currentTimeMillis() val t0 = System.currentTimeMillis()
Timber.v("## CRYPTO | encryptEventContent() starts") Timber.tag(loggerTag.value).v("encryptEventContent() starts")
runCatching { runCatching {
val content = safeAlgorithm.encryptEventContent(eventContent, eventType, userIds) 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) MXEncryptEventContentResult(content, EventType.ENCRYPTED)
}.foldToCallback(callback) }.foldToCallback(callback)
} else { } else {
val algorithm = getEncryptionAlgorithm(roomId) val algorithm = getEncryptionAlgorithm(roomId)
val reason = String.format(MXCryptoError.UNABLE_TO_ENCRYPT_REASON, val reason = String.format(MXCryptoError.UNABLE_TO_ENCRYPT_REASON,
algorithm ?: MXCryptoError.NO_MORE_ALGORITHM_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))) 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) { if (roomEncryptor is IMXGroupEncryption) {
roomEncryptor.discardSessionKey() roomEncryptor.discardSessionKey()
} else { } 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) { private fun onRoomKeyEvent(event: Event) {
val roomKeyContent = event.getClearContent().toModel<RoomKeyContent>() ?: return val roomKeyContent = event.getClearContent().toModel<RoomKeyContent>() ?: 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()) { if (roomKeyContent.roomId.isNullOrEmpty() || roomKeyContent.algorithm.isNullOrEmpty()) {
Timber.e("## CRYPTO | onRoomKeyEvent() : missing fields") Timber.tag(loggerTag.value).e("onRoomKeyEvent() : missing fields")
return return
} }
val alg = roomDecryptorProvider.getOrCreateRoomDecryptor(roomKeyContent.roomId, roomKeyContent.algorithm) val alg = roomDecryptorProvider.getOrCreateRoomDecryptor(roomKeyContent.roomId, roomKeyContent.algorithm)
if (alg == null) { 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 return
} }
alg.onRoomKeyEvent(event, keysBackupService) alg.onRoomKeyEvent(event, keysBackupService)
@ -783,29 +787,29 @@ internal class DefaultCryptoService @Inject constructor(
private fun onKeyWithHeldReceived(event: Event) { private fun onKeyWithHeldReceived(event: Event) {
val withHeldContent = event.getClearContent().toModel<RoomKeyWithHeldContent>() ?: return Unit.also { val withHeldContent = event.getClearContent().toModel<RoomKeyWithHeldContent>() ?: 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) val alg = roomDecryptorProvider.getOrCreateRoomDecryptor(withHeldContent.roomId, withHeldContent.algorithm)
if (alg is IMXWithHeldExtension) { if (alg is IMXWithHeldExtension) {
alg.onRoomKeyWithHeldEvent(withHeldContent) alg.onRoomKeyWithHeldEvent(withHeldContent)
} else { } 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 return
} }
} }
private fun onSecretSendReceived(event: Event) { 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()) { if (!event.isEncrypted()) {
// secret send messages must be encrypted // 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 return
} }
// Was that sent by us? // Was that sent by us?
if (event.senderId != userId) { 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 return
} }
@ -815,13 +819,13 @@ internal class DefaultCryptoService @Inject constructor(
.getOutgoingSecretKeyRequests().firstOrNull { it.requestId == secretContent.requestId } .getOutgoingSecretKeyRequests().firstOrNull { it.requestId == secretContent.requestId }
if (existingRequest == null) { 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 return
} }
if (!handleSDKLevelGossip(existingRequest.secretName, secretContent.secretValue)) { if (!handleSDKLevelGossip(existingRequest.secretName, secretContent.secretValue)) {
// TODO Ask to application layer? // 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) { private fun onRoomEncryptionEvent(roomId: String, event: Event) {
if (!event.isStateEvent()) { if (!event.isStateEvent()) {
// Ignore // Ignore
Timber.w("Invalid encryption event") Timber.tag(loggerTag.value).w("Invalid encryption event")
return return
} }
cryptoCoroutineScope.launch(coroutineDispatchers.crypto) { cryptoCoroutineScope.launch(coroutineDispatchers.crypto) {
@ -912,7 +916,7 @@ internal class DefaultCryptoService @Inject constructor(
*/ */
private suspend fun uploadDeviceKeys() { private suspend fun uploadDeviceKeys() {
if (cryptoStore.areDeviceKeysUploaded()) { if (cryptoStore.areDeviceKeysUploaded()) {
Timber.d("Keys already uploaded, nothing to do") Timber.tag(loggerTag.value).d("Keys already uploaded, nothing to do")
return return
} }
// Prepare the device keys data to send // Prepare the device keys data to send
@ -971,13 +975,13 @@ internal class DefaultCryptoService @Inject constructor(
password: String, password: String,
progressListener: ProgressListener?): ImportRoomKeysResult { progressListener: ProgressListener?): ImportRoomKeysResult {
return withContext(coroutineDispatchers.crypto) { return withContext(coroutineDispatchers.crypto) {
Timber.v("## CRYPTO | importRoomKeys starts") Timber.tag(loggerTag.value).v("importRoomKeys starts")
val t0 = System.currentTimeMillis() val t0 = System.currentTimeMillis()
val roomKeys = MXMegolmExportEncryption.decryptMegolmKeyFile(roomKeysAsArray, password) val roomKeys = MXMegolmExportEncryption.decryptMegolmKeyFile(roomKeysAsArray, password)
val t1 = System.currentTimeMillis() 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() val importedSessions = MoshiProvider.providesMoshi()
.adapter<List<MegolmSessionData>>(Types.newParameterizedType(List::class.java, MegolmSessionData::class.java)) .adapter<List<MegolmSessionData>>(Types.newParameterizedType(List::class.java, MegolmSessionData::class.java))
@ -985,7 +989,7 @@ internal class DefaultCryptoService @Inject constructor(
val t2 = System.currentTimeMillis() 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) { if (importedSessions == null) {
throw Exception("Error") throw Exception("Error")
@ -1122,7 +1126,7 @@ internal class DefaultCryptoService @Inject constructor(
*/ */
override fun reRequestRoomKeyForEvent(event: Event) { override fun reRequestRoomKeyForEvent(event: Event) {
val wireContent = event.content.toModel<EncryptedEventContent>() ?: return Unit.also { val wireContent = event.content.toModel<EncryptedEventContent>() ?: 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( val requestBody = RoomKeyRequestBody(
@ -1137,7 +1141,7 @@ internal class DefaultCryptoService @Inject constructor(
override fun requestRoomKeyForEvent(event: Event) { override fun requestRoomKeyForEvent(event: Event) {
val wireContent = event.content.toModel<EncryptedEventContent>() ?: return Unit.also { val wireContent = event.content.toModel<EncryptedEventContent>() ?: 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) { cryptoCoroutineScope.launch(coroutineDispatchers.crypto) {
@ -1148,7 +1152,7 @@ internal class DefaultCryptoService @Inject constructor(
roomDecryptorProvider roomDecryptorProvider
.getOrCreateRoomDecryptor(event.roomId, wireContent.algorithm) .getOrCreateRoomDecryptor(event.roomId, wireContent.algorithm)
?.requestKeysForEvent(event, false) ?: run { ?.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<Unit>) { override fun prepareToEncrypt(roomId: String, callback: MatrixCallback<Unit>) {
cryptoCoroutineScope.launch(coroutineDispatchers.crypto) { 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 // Ensure to load all room members
try { try {
loadRoomMembersTask.execute(LoadRoomMembersTask.Params(roomId)) loadRoomMembersTask.execute(LoadRoomMembersTask.Params(roomId))
} catch (failure: Throwable) { } 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) callback.onFailure(failure)
return@launch return@launch
} }
@ -1305,7 +1309,7 @@ internal class DefaultCryptoService @Inject constructor(
if (alg == null) { if (alg == null) {
val reason = String.format(MXCryptoError.UNABLE_TO_ENCRYPT_REASON, MXCryptoError.NO_MORE_ALGORITHM_REASON) 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")) callback.onFailure(IllegalArgumentException("Missing algorithm"))
return@launch return@launch
} }
@ -1315,7 +1319,7 @@ internal class DefaultCryptoService @Inject constructor(
}.fold( }.fold(
{ callback.onSuccess(Unit) }, { callback.onSuccess(Unit) },
{ {
Timber.e("## CRYPTO | prepareToEncrypt() failed.") Timber.tag(loggerTag.value).e(it, "prepareToEncrypt() failed.")
callback.onFailure(it) callback.onFailure(it)
} }
) )

55
matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/actions/EnsureOlmSessionsForDevicesAction.kt
View File

@ -16,17 +16,21 @@
package org.matrix.android.sdk.internal.crypto.actions package org.matrix.android.sdk.internal.crypto.actions
import org.matrix.android.sdk.api.logger.LoggerTag
import org.matrix.android.sdk.internal.crypto.MXOlmDevice import org.matrix.android.sdk.internal.crypto.MXOlmDevice
import org.matrix.android.sdk.internal.crypto.model.CryptoDeviceInfo 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.MXKey
import org.matrix.android.sdk.internal.crypto.model.MXOlmSessionResult 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.MXUsersDevicesMap
import org.matrix.android.sdk.internal.crypto.model.toDebugString
import org.matrix.android.sdk.internal.crypto.tasks.ClaimOneTimeKeysForUsersDeviceTask import org.matrix.android.sdk.internal.crypto.tasks.ClaimOneTimeKeysForUsersDeviceTask
import timber.log.Timber import timber.log.Timber
import javax.inject.Inject import javax.inject.Inject
private const val ONE_TIME_KEYS_RETRY_COUNT = 3 private const val ONE_TIME_KEYS_RETRY_COUNT = 3
private val loggerTag = LoggerTag("EnsureOlmSessionsForDevicesAction", LoggerTag.CRYPTO)
internal class EnsureOlmSessionsForDevicesAction @Inject constructor( internal class EnsureOlmSessionsForDevicesAction @Inject constructor(
private val olmDevice: MXOlmDevice, private val olmDevice: MXOlmDevice,
private val oneTimeKeysForUsersDeviceTask: ClaimOneTimeKeysForUsersDeviceTask) { private val oneTimeKeysForUsersDeviceTask: ClaimOneTimeKeysForUsersDeviceTask) {
@ -36,15 +40,22 @@ internal class EnsureOlmSessionsForDevicesAction @Inject constructor(
val results = MXUsersDevicesMap<MXOlmSessionResult>() val results = MXUsersDevicesMap<MXOlmSessionResult>()
for ((userId, deviceInfos) in devicesByUser) { for ((userId, deviceList) in devicesByUser) {
for (deviceInfo in deviceInfos) { for (deviceInfo in deviceList) {
val deviceId = deviceInfo.deviceId val deviceId = deviceInfo.deviceId
val key = deviceInfo.identityKey() 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) { if (sessionId.isNullOrEmpty() || force) {
Timber.tag(loggerTag.value).d("Found no existing olm session (${deviceInfo.userId}|$deviceId) (force=$force)")
devicesWithoutSession.add(deviceInfo) devicesWithoutSession.add(deviceInfo)
} else {
Timber.tag(loggerTag.value).d("using olm session $sessionId for (${deviceInfo.userId}|$deviceId)")
} }
val olmSessionResult = MXOlmSessionResult(deviceInfo, sessionId) val olmSessionResult = MXOlmSessionResult(deviceInfo, sessionId)
@ -52,6 +63,8 @@ internal class EnsureOlmSessionsForDevicesAction @Inject constructor(
} }
} }
Timber.tag(loggerTag.value).d("Devices without olm session (count:${devicesWithoutSession.size}) :" +
" ${devicesWithoutSession.joinToString { "${it.userId}|${it.deviceId}" }}")
if (devicesWithoutSession.size == 0) { if (devicesWithoutSession.size == 0) {
return results return results
} }
@ -71,11 +84,11 @@ internal class EnsureOlmSessionsForDevicesAction @Inject constructor(
// //
// That should eventually resolve itself, but it's poor form. // That should eventually resolve itself, but it's poor form.
Timber.i("## CRYPTO | claimOneTimeKeysForUsersDevices() : $usersDevicesToClaim") Timber.tag(loggerTag.value).i("claimOneTimeKeysForUsersDevices() : ${usersDevicesToClaim.toDebugString()}")
val claimParams = ClaimOneTimeKeysForUsersDeviceTask.Params(usersDevicesToClaim) val claimParams = ClaimOneTimeKeysForUsersDeviceTask.Params(usersDevicesToClaim)
val oneTimeKeys = oneTimeKeysForUsersDeviceTask.executeRetry(claimParams, remainingRetry = ONE_TIME_KEYS_RETRY_COUNT) val oneTimeKeys = oneTimeKeysForUsersDeviceTask.executeRetry(claimParams, remainingRetry = ONE_TIME_KEYS_RETRY_COUNT)
Timber.v("## CRYPTO | claimOneTimeKeysForUsersDevices() : keysClaimResponse.oneTimeKeys: $oneTimeKeys") Timber.tag(loggerTag.value).v("claimOneTimeKeysForUsersDevices() : keysClaimResponse.oneTimeKeys: $oneTimeKeys")
for ((userId, deviceInfos) in devicesByUser) { for ((userId, deviceInfos) in devicesByUser) {
for (deviceInfo in deviceInfos) { for (deviceInfo in deviceInfos) {
var oneTimeKey: MXKey? = null var oneTimeKey: MXKey? = null
@ -83,7 +96,7 @@ internal class EnsureOlmSessionsForDevicesAction @Inject constructor(
if (null != deviceIds) { if (null != deviceIds) {
for (deviceId in deviceIds) { for (deviceId in deviceIds) {
val olmSessionResult = results.getObject(userId, deviceId) val olmSessionResult = results.getObject(userId, deviceId)
if (olmSessionResult!!.sessionId != null && !force) { if (olmSessionResult?.sessionId != null && !force) {
// We already have a result for this device // We already have a result for this device
continue continue
} }
@ -92,12 +105,11 @@ internal class EnsureOlmSessionsForDevicesAction @Inject constructor(
oneTimeKey = key oneTimeKey = key
} }
if (oneTimeKey == null) { if (oneTimeKey == null) {
Timber.w("## CRYPTO | ensureOlmSessionsForDevices() : No one-time keys " + oneTimeKeyAlgorithm + Timber.tag(loggerTag.value).d("No one time key for $userId|$deviceId")
" for device " + userId + " : " + deviceId)
continue continue
} }
// Update the result for this device in results // Update the result for this device in results
olmSessionResult.sessionId = verifyKeyAndStartSession(oneTimeKey, userId, deviceInfo) olmSessionResult?.sessionId = verifyKeyAndStartSession(oneTimeKey, userId, deviceInfo)
} }
} }
} }
@ -112,31 +124,36 @@ internal class EnsureOlmSessionsForDevicesAction @Inject constructor(
val signKeyId = "ed25519:$deviceId" val signKeyId = "ed25519:$deviceId"
val signature = oneTimeKey.signatureForUserId(userId, signKeyId) 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 isVerified = false
var errorMessage: String? = null var errorMessage: String? = null
try { try {
olmDevice.verifySignature(deviceInfo.fingerprint()!!, oneTimeKey.signalableJSONDictionary(), signature) olmDevice.verifySignature(fingerprint, oneTimeKey.signalableJSONDictionary(), signature)
isVerified = true isVerified = true
} catch (e: Exception) { } catch (e: Exception) {
Timber.tag(loggerTag.value).d(e, "verifyKeyAndStartSession() : Verify error for otk: ${oneTimeKey.signalableJSONDictionary()}," +
" signature:$signature fingerprint:$fingerprint")
Timber.tag(loggerTag.value).e("verifyKeyAndStartSession() : Verify error for ${deviceInfo.userId}|${deviceInfo.deviceId} " +
" - signable json ${oneTimeKey.signalableJSONDictionary()}")
errorMessage = e.message errorMessage = e.message
} }
// Check one-time key signature // Check one-time key signature
if (isVerified) { if (isVerified) {
sessionId = olmDevice.createOutboundSession(deviceInfo.identityKey()!!, oneTimeKey.value) sessionId = deviceInfo.identityKey()?.let { identityKey ->
olmDevice.createOutboundSession(identityKey, oneTimeKey.value)
}
if (!sessionId.isNullOrEmpty()) { if (sessionId.isNullOrEmpty()) {
Timber.v("## CRYPTO | verifyKeyAndStartSession() : Started new sessionid " + sessionId +
" for device " + deviceInfo + "(theirOneTimeKey: " + oneTimeKey.value + ")")
} else {
// Possibly a bad key // Possibly a bad key
Timber.e("## CRYPTO | verifyKeyAndStartSession() : Error starting session with device $userId:$deviceId") Timber.tag(loggerTag.value).e("verifyKeyAndStartSession() : Error starting session with device $userId:$deviceId")
} else {
Timber.tag(loggerTag.value).d("verifyKeyAndStartSession() : Started new sessionId $sessionId for device $userId:$deviceId")
} }
} else { } else {
Timber.e("## CRYPTO | verifyKeyAndStartSession() : Unable to verify signature on one-time key for device " + userId + Timber.tag(loggerTag.value).e("verifyKeyAndStartSession() : Unable to verify otk signature for $userId:$deviceId: $errorMessage")
":" + deviceId + " Error " + errorMessage)
} }
} }

35
matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/algorithms/megolm/MXMegolmDecryption.kt
View File

@ -19,6 +19,7 @@ package org.matrix.android.sdk.internal.crypto.algorithms.megolm
import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.CoroutineScope
import kotlinx.coroutines.launch import kotlinx.coroutines.launch
import org.matrix.android.sdk.api.MatrixCoroutineDispatchers 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.crypto.MXCryptoError
import org.matrix.android.sdk.api.session.events.model.Event 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.EventType
@ -44,6 +45,8 @@ import org.matrix.android.sdk.internal.crypto.store.IMXCryptoStore
import org.matrix.android.sdk.internal.crypto.tasks.SendToDeviceTask import org.matrix.android.sdk.internal.crypto.tasks.SendToDeviceTask
import timber.log.Timber import timber.log.Timber
private val loggerTag = LoggerTag("MXMegolmDecryption", LoggerTag.CRYPTO)
internal class MXMegolmDecryption(private val userId: String, internal class MXMegolmDecryption(private val userId: String,
private val olmDevice: MXOlmDevice, private val olmDevice: MXOlmDevice,
private val deviceListManager: DeviceListManager, private val deviceListManager: DeviceListManager,
@ -74,7 +77,7 @@ internal class MXMegolmDecryption(private val userId: String,
@Throws(MXCryptoError::class) @Throws(MXCryptoError::class)
private fun decryptEvent(event: Event, timeline: String, requestKeysOnFail: Boolean): MXEventDecryptionResult { 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()) { if (event.roomId.isNullOrBlank()) {
throw MXCryptoError.Base(MXCryptoError.ErrorType.MISSING_FIELDS, MXCryptoError.MISSING_FIELDS_REASON) 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. * @param event the key event.
*/ */
override fun onRoomKeyEvent(event: Event, defaultKeysBackupService: DefaultKeysBackupService) { override fun onRoomKeyEvent(event: Event, defaultKeysBackupService: DefaultKeysBackupService) {
Timber.v("## CRYPTO | onRoomKeyEvent()") Timber.tag(loggerTag.value).v("onRoomKeyEvent()")
var exportFormat = false var exportFormat = false
val roomKeyContent = event.getClearContent().toModel<RoomKeyContent>() ?: return val roomKeyContent = event.getClearContent().toModel<RoomKeyContent>() ?: return
@ -239,11 +242,11 @@ internal class MXMegolmDecryption(private val userId: String,
val forwardingCurve25519KeyChain: MutableList<String> = ArrayList() val forwardingCurve25519KeyChain: MutableList<String> = ArrayList()
if (roomKeyContent.roomId.isNullOrEmpty() || roomKeyContent.sessionId.isNullOrEmpty() || roomKeyContent.sessionKey.isNullOrEmpty()) { 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 return
} }
if (event.getClearType() == EventType.FORWARDED_ROOM_KEY) { 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<ForwardedRoomKeyContent>() val forwardedRoomKeyContent = event.getClearContent().toModel<ForwardedRoomKeyContent>()
?: return ?: return
@ -252,7 +255,7 @@ internal class MXMegolmDecryption(private val userId: String,
} }
if (senderKey == null) { 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 return
} }
@ -261,20 +264,20 @@ internal class MXMegolmDecryption(private val userId: String,
exportFormat = true exportFormat = true
senderKey = forwardedRoomKeyContent.senderKey senderKey = forwardedRoomKeyContent.senderKey
if (null == 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 return
} }
if (null == forwardedRoomKeyContent.senderClaimedEd25519Key) { 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 return
} }
keysClaimed["ed25519"] = forwardedRoomKeyContent.senderClaimedEd25519Key keysClaimed["ed25519"] = forwardedRoomKeyContent.senderClaimedEd25519Key
} else { } 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) { 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 return
} }
@ -282,7 +285,7 @@ internal class MXMegolmDecryption(private val userId: String,
keysClaimed = event.getKeysClaimed().toMutableMap() 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, val added = olmDevice.addInboundGroupSession(roomKeyContent.sessionId,
roomKeyContent.sessionKey, roomKeyContent.sessionKey,
roomKeyContent.roomId, roomKeyContent.roomId,
@ -314,7 +317,7 @@ internal class MXMegolmDecryption(private val userId: String,
* @param sessionId the session id * @param sessionId the session id
*/ */
override fun onNewSession(senderKey: String, sessionId: String) { 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) newSessionListener?.onNewSession(null, senderKey, sessionId)
} }
@ -346,10 +349,10 @@ internal class MXMegolmDecryption(private val userId: String,
if (olmSessionResult?.sessionId == null) { if (olmSessionResult?.sessionId == null) {
// no session with this device, probably because there // no session with this device, probably because there
// were no one-time keys. // 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 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<String, Any>("type" to EventType.FORWARDED_ROOM_KEY) val payloadJson = mutableMapOf<String, Any>("type" to EventType.FORWARDED_ROOM_KEY)
runCatching { olmDevice.getInboundGroupSession(body.sessionId, body.senderKey, body.roomId) } runCatching { olmDevice.getInboundGroupSession(body.sessionId, body.senderKey, body.roomId) }
@ -360,7 +363,7 @@ internal class MXMegolmDecryption(private val userId: String,
}, },
{ {
// TODO // 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 encodedPayload = messageEncrypter.encryptMessage(payloadJson, listOf(deviceInfo))
val sendToDeviceMap = MXUsersDevicesMap<Any>() val sendToDeviceMap = MXUsersDevicesMap<Any>()
sendToDeviceMap.setObject(userId, deviceId, encodedPayload) 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) val sendToDeviceParams = SendToDeviceTask.Params(EventType.ENCRYPTED, sendToDeviceMap)
try { try {
sendToDeviceTask.execute(sendToDeviceParams) sendToDeviceTask.execute(sendToDeviceParams)
} catch (failure: Throwable) { } 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")
} }
} }
} }

78
matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/algorithms/megolm/MXMegolmEncryption.kt
View File

@ -19,6 +19,7 @@ package org.matrix.android.sdk.internal.crypto.algorithms.megolm
import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.CoroutineScope
import kotlinx.coroutines.launch import kotlinx.coroutines.launch
import org.matrix.android.sdk.api.MatrixCoroutineDispatchers 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.crypto.MXCryptoError
import org.matrix.android.sdk.api.session.events.model.Content import org.matrix.android.sdk.api.session.events.model.Content
import org.matrix.android.sdk.api.session.events.model.Event 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.RoomKeyWithHeldContent
import org.matrix.android.sdk.internal.crypto.model.event.WithHeldCode 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.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.repository.WarnOnUnknownDeviceRepository
import org.matrix.android.sdk.internal.crypto.store.IMXCryptoStore import org.matrix.android.sdk.internal.crypto.store.IMXCryptoStore
import org.matrix.android.sdk.internal.crypto.tasks.SendToDeviceTask 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 org.matrix.android.sdk.internal.util.convertToUTF8
import timber.log.Timber import timber.log.Timber
private val loggerTag = LoggerTag("MXMegolmEncryption", LoggerTag.CRYPTO)
internal class MXMegolmEncryption( internal class MXMegolmEncryption(
// The id of the room we will be sending to. // The id of the room we will be sending to.
private val roomId: String, private val roomId: String,
@ -51,8 +56,8 @@ internal class MXMegolmEncryption(
private val cryptoStore: IMXCryptoStore, private val cryptoStore: IMXCryptoStore,
private val deviceListManager: DeviceListManager, private val deviceListManager: DeviceListManager,
private val ensureOlmSessionsForDevicesAction: EnsureOlmSessionsForDevicesAction, private val ensureOlmSessionsForDevicesAction: EnsureOlmSessionsForDevicesAction,
private val userId: String, private val myUserId: String,
private val deviceId: String, private val myDeviceId: String,
private val sendToDeviceTask: SendToDeviceTask, private val sendToDeviceTask: SendToDeviceTask,
private val messageEncrypter: MessageEncrypter, private val messageEncrypter: MessageEncrypter,
private val warnOnUnknownDevicesRepository: WarnOnUnknownDeviceRepository, private val warnOnUnknownDevicesRepository: WarnOnUnknownDeviceRepository,
@ -80,9 +85,10 @@ internal class MXMegolmEncryption(
eventType: String, eventType: String,
userIds: List<String>): Content { userIds: List<String>): Content {
val ts = System.currentTimeMillis() val ts = System.currentTimeMillis()
Timber.v("## CRYPTO | encryptEventContent : getDevicesInRoom") Timber.tag(loggerTag.value).v("encryptEventContent : getDevicesInRoom")
val devices = getDevicesInRoom(userIds) 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) val outboundSession = ensureOutboundSession(devices.allowedDevices)
return encryptContent(outboundSession, eventType, eventContent) 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 :/ // annoyingly we have to serialize again the saved outbound session to store message index :/
// if not we would see duplicate message index errors // if not we would see duplicate message index errors
olmDevice.storeOutboundGroupSessionForRoom(roomId, outboundSession.sessionId) 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<String>) { override suspend fun preshareKey(userIds: List<String>) {
val ts = System.currentTimeMillis() val ts = System.currentTimeMillis()
Timber.v("## CRYPTO | preshareKey : getDevicesInRoom") Timber.tag(loggerTag.value).d("preshareKey started in $roomId ...")
val devices = getDevicesInRoom(userIds) val devices = getDevicesInRoom(userIds)
val outboundSession = ensureOutboundSession(devices.allowedDevices) val outboundSession = ensureOutboundSession(devices.allowedDevices)
notifyWithheldForSession(devices.withHeldDevices, outboundSession) 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 * @return the session description
*/ */
private fun prepareNewSessionInRoom(): MXOutboundSessionInfo { private fun prepareNewSessionInRoom(): MXOutboundSessionInfo {
Timber.v("## CRYPTO | prepareNewSessionInRoom() ") Timber.tag(loggerTag.value).v("prepareNewSessionInRoom() ")
val sessionId = olmDevice.createOutboundGroupSessionForRoom(roomId) val sessionId = olmDevice.createOutboundGroupSessionForRoom(roomId)
val keysClaimedMap = HashMap<String, String>() val keysClaimedMap = HashMap<String, String>()
@ -153,13 +159,14 @@ internal class MXMegolmEncryption(
* @param devicesInRoom the devices list * @param devicesInRoom the devices list
*/ */
private suspend fun ensureOutboundSession(devicesInRoom: MXUsersDevicesMap<CryptoDeviceInfo>): MXOutboundSessionInfo { private suspend fun ensureOutboundSession(devicesInRoom: MXUsersDevicesMap<CryptoDeviceInfo>): MXOutboundSessionInfo {
Timber.v("## CRYPTO | ensureOutboundSession start") Timber.tag(loggerTag.value).v("ensureOutboundSession roomId:$roomId")
var session = outboundSession var session = outboundSession
if (session == null || if (session == null ||
// Need to make a brand new session? // Need to make a brand new session?
session.needsRotation(sessionRotationPeriodMsgs, sessionRotationPeriodMs) || session.needsRotation(sessionRotationPeriodMsgs, sessionRotationPeriodMs) ||
// Determine if we have shared with anyone we shouldn't have // Determine if we have shared with anyone we shouldn't have
session.sharedWithTooManyDevices(devicesInRoom)) { session.sharedWithTooManyDevices(devicesInRoom)) {
Timber.tag(loggerTag.value).d("roomId:$roomId Starting new megolm session because we need to rotate.")
session = prepareNewSessionInRoom() session = prepareNewSessionInRoom()
outboundSession = session 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) shareKey(safeSession, shareMap)
return safeSession return safeSession
} }
@ -190,7 +199,7 @@ internal class MXMegolmEncryption(
devicesByUsers: Map<String, List<CryptoDeviceInfo>>) { devicesByUsers: Map<String, List<CryptoDeviceInfo>>) {
// nothing to send, the task is done // nothing to send, the task is done
if (devicesByUsers.isEmpty()) { if (devicesByUsers.isEmpty()) {
Timber.v("## CRYPTO | shareKey() : nothing more to do") Timber.tag(loggerTag.value).v("shareKey() : nothing more to do")
return return
} }
// reduce the map size to avoid request timeout when there are too many devices (Users size * devices per user) // 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 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) shareUserDevicesKey(session, subMap)
val remainingDevices = devicesByUsers - subMap.keys val remainingDevices = devicesByUsers - subMap.keys
shareKey(session, remainingDevices) shareKey(session, remainingDevices)
@ -232,11 +241,11 @@ internal class MXMegolmEncryption(
payload["content"] = submap payload["content"] = submap
var t0 = System.currentTimeMillis() var t0 = System.currentTimeMillis()
Timber.v("## CRYPTO | shareUserDevicesKey() : starts") Timber.tag(loggerTag.value).v("shareUserDevicesKey() : starts")
val results = ensureOlmSessionsForDevicesAction.handle(devicesByUser) val results = ensureOlmSessionsForDevicesAction.handle(devicesByUser)
Timber.v( Timber.tag(loggerTag.value).v(
"""## CRYPTO | shareUserDevicesKey(): ensureOlmSessionsForDevices succeeds after ${System.currentTimeMillis() - t0} ms""" """shareUserDevicesKey(): ensureOlmSessionsForDevices succeeds after ${System.currentTimeMillis() - t0} ms"""
.trimMargin() .trimMargin()
) )
val contentMap = MXUsersDevicesMap<Any>() val contentMap = MXUsersDevicesMap<Any>()
@ -254,10 +263,11 @@ internal class MXMegolmEncryption(
// MSC 2399 // MSC 2399
// send withheld m.no_olm: an olm session could not be established. // 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. // 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)) noOlmToNotify.add(UserDevice(userId, deviceID))
continue 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))) contentMap.setObject(userId, deviceID, messageEncrypter.encryptMessage(payload, listOf(sessionResult.deviceInfo)))
haveTargets = true haveTargets = true
} }
@ -275,7 +285,7 @@ internal class MXMegolmEncryption(
gossipingEventBuffer.add( gossipingEventBuffer.add(
Event( Event(
type = EventType.ROOM_KEY, type = EventType.ROOM_KEY,
senderId = this.userId, senderId = myUserId,
content = submap.apply { content = submap.apply {
this["session_key"] = "" this["session_key"] = ""
// we add a fake key for trail // we add a fake key for trail
@ -289,17 +299,18 @@ internal class MXMegolmEncryption(
if (haveTargets) { if (haveTargets) {
t0 = System.currentTimeMillis() 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) val sendToDeviceParams = SendToDeviceTask.Params(EventType.ENCRYPTED, contentMap)
try { try {
sendToDeviceTask.execute(sendToDeviceParams) 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) { } catch (failure: Throwable) {
// What to do here... // 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 { } else {
Timber.i("## CRYPTO | shareUserDevicesKey() : no need to sharekey") Timber.tag(loggerTag.value).i("shareUserDevicesKey() : no need to share key")
} }
if (noOlmToNotify.isNotEmpty()) { if (noOlmToNotify.isNotEmpty()) {
@ -317,7 +328,8 @@ internal class MXMegolmEncryption(
sessionId: String, sessionId: String,
senderKey: String?, senderKey: String?,
code: WithHeldCode) { 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( val withHeldContent = RoomKeyWithHeldContent(
roomId = roomId, roomId = roomId,
senderKey = senderKey, senderKey = senderKey,
@ -336,7 +348,7 @@ internal class MXMegolmEncryption(
try { try {
sendToDeviceTask.execute(params) sendToDeviceTask.execute(params)
} catch (failure: Throwable) { } 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 // Include our device ID so that recipients can send us a
// m.new_device message if they don't have our session key. // m.new_device message if they don't have our session key.
map["device_id"] = deviceId map["device_id"] = myDeviceId
session.useCount++ session.useCount++
return map return map
} }
@ -424,9 +436,9 @@ internal class MXMegolmEncryption(
userId: String, userId: String,
deviceId: String, deviceId: String,
senderKey: String): Boolean { 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 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 // Get the chain index of the key we previously sent this device
val wasSessionSharedWithUser = cryptoStore.getSharedSessionInfo(roomId, sessionId, deviceInfo) val wasSessionSharedWithUser = cryptoStore.getSharedSessionInfo(roomId, sessionId, deviceInfo)
@ -434,13 +446,13 @@ internal class MXMegolmEncryption(
// This session was never shared with this user // This session was never shared with this user
// Send a room key with held // Send a room key with held
notifyKeyWithHeld(listOf(UserDevice(userId, deviceId)), sessionId, senderKey, WithHeldCode.UNAUTHORISED) 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 return false
} }
// if found chain index should not be null // if found chain index should not be null
val chainIndex = wasSessionSharedWithUser.chainIndex ?: return false val chainIndex = wasSessionSharedWithUser.chainIndex ?: return false
.also { .also {
Timber.w("## Crypto reshareKey: Null chain index") Timber.tag(loggerTag.value).w("reshareKey: Null chain index")
} }
val devicesByUser = mapOf(userId to listOf(deviceInfo)) 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. 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. // ensureOlmSessionsForDevicesAction has already done the logging, so just skip it.
?: return false.also { ?: 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<String, Any>("type" to EventType.FORWARDED_ROOM_KEY) val payloadJson = mutableMapOf<String, Any>("type" to EventType.FORWARDED_ROOM_KEY)
@ -464,7 +476,7 @@ internal class MXMegolmEncryption(
}, },
{ {
// TODO // 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 encodedPayload = messageEncrypter.encryptMessage(payloadJson, listOf(deviceInfo))
val sendToDeviceMap = MXUsersDevicesMap<Any>() val sendToDeviceMap = MXUsersDevicesMap<Any>()
sendToDeviceMap.setObject(userId, deviceId, encodedPayload) 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) val sendToDeviceParams = SendToDeviceTask.Params(EventType.ENCRYPTED, sendToDeviceMap)
return try { return try {
sendToDeviceTask.execute(sendToDeviceParams) 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 true
} catch (failure: Throwable) { } 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 false
} }
} }

4
matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/algorithms/megolm/MXMegolmEncryptionFactory.kt
View File

@ -52,8 +52,8 @@ internal class MXMegolmEncryptionFactory @Inject constructor(
cryptoStore = cryptoStore, cryptoStore = cryptoStore,
deviceListManager = deviceListManager, deviceListManager = deviceListManager,
ensureOlmSessionsForDevicesAction = ensureOlmSessionsForDevicesAction, ensureOlmSessionsForDevicesAction = ensureOlmSessionsForDevicesAction,
userId = userId, myUserId = userId,
deviceId = deviceId!!, myDeviceId = deviceId!!,
sendToDeviceTask = sendToDeviceTask, sendToDeviceTask = sendToDeviceTask,
messageEncrypter = messageEncrypter, messageEncrypter = messageEncrypter,
warnOnUnknownDevicesRepository = warnOnUnknownDevicesRepository, warnOnUnknownDevicesRepository = warnOnUnknownDevicesRepository,

8
matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/model/MXUsersDevicesMap.kt
View File

@ -129,3 +129,11 @@ inline fun <T> MXUsersDevicesMap<T>.forEach(action: (String, String, T) -> Unit)
} }
} }
} }
internal fun <T> MXUsersDevicesMap<T>.toDebugString() =
map.entries.joinToString { "${it.key} [${it.value.keys.joinToString { it }}]" }
internal fun <T> MXUsersDevicesMap<T>.toDebugCount() =
map.entries.fold(0) { acc, new ->
acc + new.value.keys.size
}

5
matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/tasks/SendEventTask.kt
View File

@ -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.membership.LoadRoomMembersTask
import org.matrix.android.sdk.internal.session.room.send.LocalEchoRepository import org.matrix.android.sdk.internal.session.room.send.LocalEchoRepository
import org.matrix.android.sdk.internal.task.Task import org.matrix.android.sdk.internal.task.Task
import timber.log.Timber
import javax.inject.Inject import javax.inject.Inject
internal interface SendEventTask : Task<SendEventTask.Params, String> { internal interface SendEventTask : Task<SendEventTask.Params, String> {
@ -60,7 +61,9 @@ internal class DefaultSendEventTask @Inject constructor(
) )
} }
localEchoRepository.updateSendState(localId, params.event.roomId, SendState.SENT) 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) { } catch (e: Throwable) {
// localEchoRepository.updateSendState(params.event.eventId!!, SendState.UNDELIVERED) // localEchoRepository.updateSendState(params.event.eventId!!, SendState.UNDELIVERED)
throw e throw e

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

@ -16,6 +16,7 @@
package org.matrix.android.sdk.internal.session.sync.handler 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.crypto.MXCryptoError
import org.matrix.android.sdk.api.session.events.model.Event 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.EventType
@ -32,6 +33,8 @@ import org.matrix.android.sdk.internal.session.initsync.ProgressReporter
import timber.log.Timber import timber.log.Timber
import javax.inject.Inject import javax.inject.Inject
private val loggerTag = LoggerTag("CryptoSyncHandler", LoggerTag.CRYPTO)
internal class CryptoSyncHandler @Inject constructor(private val cryptoService: DefaultCryptoService, internal class CryptoSyncHandler @Inject constructor(private val cryptoService: DefaultCryptoService,
private val verificationService: DefaultVerificationService) { private val verificationService: DefaultVerificationService) {
@ -40,11 +43,11 @@ internal class CryptoSyncHandler @Inject constructor(private val cryptoService:
toDevice.events?.forEachIndexed { index, event -> toDevice.events?.forEachIndexed { index, event ->
progressReporter?.reportProgress(index * 100F / total) progressReporter?.reportProgress(index * 100F / total)
// Decrypt event if necessary // 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) decryptToDeviceEvent(event, null)
if (event.getClearType() == EventType.MESSAGE && if (event.getClearType() == EventType.MESSAGE &&
event.getClearContent()?.toModel<MessageContent>()?.msgType == "m.bad.encrypted") { event.getClearContent()?.toModel<MessageContent>()?.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 { } else {
verificationService.onToDeviceEvent(event) verificationService.onToDeviceEvent(event)
cryptoService.onToDeviceEvent(event) cryptoService.onToDeviceEvent(event)