Skip to content

Commit

Permalink
Improve crypto log to debug UISI
Browse files Browse the repository at this point in the history
  • Loading branch information
@BillCarsonFr
BillCarsonFr committed Nov 18, 2021
1 parent 0c4dee8 commit fafb80f
Show file tree
Hide file tree
Showing 9 changed files with 150 additions and 101 deletions.
1 change: 1 addition & 0 deletions matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/logger/LoggerTag.kt
View file
Expand Up @@ -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
Expand Down
68 changes: 36 additions & 32 deletions ...-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/DefaultCryptoService.kt
View file
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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 ")
}
}
}
Expand Down Expand Up @@ -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")
}
)
}
Expand Down Expand Up @@ -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
}

Expand All @@ -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)

Expand Down Expand Up @@ -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)))
}
}
Expand All @@ -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")
}
}
}
Expand Down Expand Up @@ -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
}

Expand All @@ -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")
}
}

Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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")
Expand Down Expand Up @@ -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(
Expand All @@ -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) {
Expand All @@ -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}")
}
}
}
Expand Down Expand Up @@ -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
}
Expand All @@ -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
}
Expand All @@ -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)
}
)
Expand Down

0 comments on commit fafb80f

Please sign in to comment.