Improve crypto log to debug UISI

changelog.d/4507.misc

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

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

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,44 +772,44 @@ internal class DefaultCryptoService @Inject constructor(
      */
     private fun onRoomKeyEvent(event: Event) {
         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()) {
-            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)
     }
 
     private fun onKeyWithHeldReceived(event: Event) {
         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)
         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,21 +975,21 @@ 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<List<MegolmSessionData>>(Types.newParameterizedType(List::class.java, MegolmSessionData::class.java))
                     .fromJson(roomKeys)
 
             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<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(
@@ -1137,7 +1141,7 @@ internal class DefaultCryptoService @Inject constructor(
 
     override fun requestRoomKeyForEvent(event: Event) {
         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) {
@@ -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<Unit>) {
         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)
                     }
             )