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

Merge pull request #2429 from vector-im/feature/bca/e2e_logs 

Better e2e log reporting
This commit is contained in:
Benoit Marty 2020-11-24 17:04:11 +01:00 committed by GitHub
parent 920856512e 1f69c7e992
commit c0a83d1916
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
9 changed files with 69 additions and 43 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

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

@ -767,9 +767,9 @@ internal class DefaultCryptoService @Inject constructor(
*/
private fun onRoomKeyEvent(event: Event) {
val roomKeyContent = event.getClearContent().toModel<RoomKeyContent>() ?: return
Timber.v("## CRYPTO | GOSSIP onRoomKeyEvent() : type<${event.getClearType()}> , sessionId<${roomKeyContent.sessionId}>")
Timber.i("## CRYPTO | onRoomKeyEvent() from: ${event.senderId} type<${event.getClearType()}> , sessionId<${roomKeyContent.sessionId}>")
if (roomKeyContent.roomId.isNullOrEmpty() || roomKeyContent.algorithm.isNullOrEmpty()) {
Timber.e("## CRYPTO | GOSSIP onRoomKeyEvent() : missing fields")
Timber.e("## CRYPTO | onRoomKeyEvent() : missing fields")
return
}
val alg = roomDecryptorProvider.getOrCreateRoomDecryptor(roomKeyContent.roomId, roomKeyContent.algorithm)
@ -782,20 +782,20 @@ internal class DefaultCryptoService @Inject constructor(
private fun onKeyWithHeldReceived(event: Event) {
val withHeldContent = event.getClearContent().toModel<RoomKeyWithHeldContent>() ?: return Unit.also {
Timber.e("## CRYPTO | Malformed onKeyWithHeldReceived() : missing fields")
Timber.i("## CRYPTO | Malformed onKeyWithHeldReceived() : missing fields")
}
Timber.d("## CRYPTO | onKeyWithHeldReceived() received : content <$withHeldContent>")
Timber.i("## CRYPTO | 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() : Unable to handle WithHeldContent for ${withHeldContent.algorithm}")
Timber.e("## CRYPTO | onKeyWithHeldReceived() from:${event.senderId}: Unable to handle WithHeldContent for ${withHeldContent.algorithm}")
return
}
}
private fun onSecretSendReceived(event: Event) {
Timber.i("## CRYPTO | GOSSIP onSecretSend() : onSecretSendReceived ${event.content?.get("sender_key")}")
Timber.i("## CRYPTO | 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")

16
matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/EventDecryptor.kt
View File

@ -119,7 +119,7 @@ internal class EventDecryptor @Inject constructor(
markOlmSessionForUnwedging(event.senderId ?: "", it)
}
?: run {
Timber.v("## CRYPTO | markOlmSessionForUnwedging() : Failed to find sender crypto device")
Timber.i("## CRYPTO | internalDecryptEvent() : Failed to find sender crypto device for unwedging")
}
}
}
@ -137,16 +137,18 @@ internal class EventDecryptor @Inject constructor(
val lastForcedDate = lastNewSessionForcedDates.getObject(senderId, deviceKey) ?: 0
val now = System.currentTimeMillis()
if (now - lastForcedDate < DefaultCryptoService.CRYPTO_MIN_FORCE_SESSION_PERIOD_MILLIS) {
Timber.d("## CRYPTO | markOlmSessionForUnwedging: New session already forced with device at $lastForcedDate. Not forcing another")
Timber.w("## CRYPTO | markOlmSessionForUnwedging: New session already forced with device at $lastForcedDate. Not forcing another")
return
}
Timber.d("## CRYPTO | markOlmSessionForUnwedging from $senderId:${deviceInfo.deviceId}")
Timber.i("## CRYPTO | markOlmSessionForUnwedging from $senderId:${deviceInfo.deviceId}")
lastNewSessionForcedDates.setObject(senderId, deviceKey, now)
// offload this from crypto thread (?)
cryptoCoroutineScope.launch(coroutineDispatchers.computation) {
ensureOlmSessionsForDevicesAction.handle(mapOf(senderId to listOf(deviceInfo)), force = true)
val ensured = ensureOlmSessionsForDevicesAction.handle(mapOf(senderId to listOf(deviceInfo)), force = true)
Timber.i("## CRYPTO | markOlmSessionForUnwedging() : ensureOlmSessionsForDevicesAction isEmpty:${ensured.isEmpty}")
// Now send a blank message on that session so the other side knows about it.
// (The keyshare request is sent in the clear so that won't do)
@ -159,10 +161,14 @@ internal class EventDecryptor @Inject constructor(
val encodedPayload = messageEncrypter.encryptMessage(payloadJson, listOf(deviceInfo))
val sendToDeviceMap = MXUsersDevicesMap<Any>()
sendToDeviceMap.setObject(senderId, deviceInfo.deviceId, encodedPayload)
Timber.v("## CRYPTO | markOlmSessionForUnwedging() : sending to $senderId:${deviceInfo.deviceId}")
Timber.i("## CRYPTO | markOlmSessionForUnwedging() : sending dummy to $senderId:${deviceInfo.deviceId}")
withContext(coroutineDispatchers.io) {
val sendToDeviceParams = SendToDeviceTask.Params(EventType.ENCRYPTED, sendToDeviceMap)
try {
sendToDeviceTask.execute(sendToDeviceParams)
} catch (failure: Throwable) {
Timber.e(failure, "## CRYPTO | markOlmSessionForUnwedging() : failed to send dummy to $senderId:${deviceInfo.deviceId}")
}
}
}
}

3
matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/IncomingGossipingRequestManager.kt
View File

@ -54,6 +54,7 @@ internal class IncomingGossipingRequestManager @Inject constructor(
private val cryptoCoroutineScope: CoroutineScope) {
private val executor = Executors.newSingleThreadExecutor()
// list of IncomingRoomKeyRequests/IncomingRoomKeyRequestCancellations
// we received in the current sync.
private val receivedGossipingRequests = ArrayList<IncomingShareRequestCommon>()
@ -103,8 +104,8 @@ internal class IncomingGossipingRequestManager @Inject constructor(
* @param event the announcement event.
*/
fun onGossipingRequestEvent(event: Event) {
Timber.v("## CRYPTO | GOSSIP onGossipingRequestEvent type ${event.type} from user ${event.senderId}")
val roomKeyShare = event.getClearContent().toModel<GossipingDefaultContent>()
Timber.i("## CRYPTO | GOSSIP onGossipingRequestEvent received type ${event.type} from user:${event.senderId}, content:$roomKeyShare")
// val ageLocalTs = event.unsignedData?.age?.let { System.currentTimeMillis() - it }
when (roomKeyShare?.action) {
GossipingToDeviceObject.ACTION_SHARE_REQUEST -> {

2
matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/MXOlmDevice.kt
View File

@ -760,7 +760,7 @@ internal class MXOlmDevice @Inject constructor(
return session
}
} else {
Timber.v("## getInboundGroupSession() : Cannot retrieve inbound group session $sessionId")
Timber.w("## getInboundGroupSession() : Cannot retrieve inbound group session $sessionId")
throw MXCryptoError.Base(MXCryptoError.ErrorType.UNKNOWN_INBOUND_SESSION_ID, MXCryptoError.UNKNOWN_INBOUND_SESSION_ID_REASON)
}
}

2
matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/crypto/SendGossipWorker.kt
View File

@ -100,7 +100,7 @@ internal class SendGossipWorker(context: Context,
requestId = params.requestId,
state = GossipingRequestState.FAILED_TO_ACCEPTED
)
Timber.e("no session with this device, probably because there were no one-time keys.")
Timber.e("no session with this device $requestingDeviceId, probably because there were no one-time keys.")
}
}

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

@ -69,7 +69,7 @@ internal class EnsureOlmSessionsForDevicesAction @Inject constructor(
//
// That should eventually resolve itself, but it's poor form.
Timber.v("## CRYPTO | claimOneTimeKeysForUsersDevices() : $usersDevicesToClaim")
Timber.i("## CRYPTO | claimOneTimeKeysForUsersDevices() : $usersDevicesToClaim")
val claimParams = ClaimOneTimeKeysForUsersDeviceTask.Params(usersDevicesToClaim)
val oneTimeKeys = oneTimeKeysForUsersDeviceTask.execute(claimParams)
@ -90,7 +90,7 @@ internal class EnsureOlmSessionsForDevicesAction @Inject constructor(
oneTimeKey = key
}
if (oneTimeKey == null) {
Timber.v("## CRYPTO | ensureOlmSessionsForDevices() : No one-time keys " + oneTimeKeyAlgorithm
Timber.w("## CRYPTO | ensureOlmSessionsForDevices() : No one-time keys " + oneTimeKeyAlgorithm
+ " for device " + userId + " : " + deviceId)
continue
}

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

@ -243,8 +243,7 @@ internal class MXMegolmDecryption(private val userId: String,
return
}
if (event.getClearType() == EventType.FORWARDED_ROOM_KEY) {
Timber.v("## CRYPTO | onRoomKeyEvent(), forward adding key : roomId ${roomKeyContent.roomId}" +
" sessionId ${roomKeyContent.sessionId} sessionKey ${roomKeyContent.sessionKey}")
Timber.i("## CRYPTO | onRoomKeyEvent(), forward adding key : ${roomKeyContent.roomId}|${roomKeyContent.sessionId}")
val forwardedRoomKeyContent = event.getClearContent().toModel<ForwardedRoomKeyContent>()
?: return
@ -273,9 +272,7 @@ internal class MXMegolmDecryption(private val userId: String,
keysClaimed["ed25519"] = forwardedRoomKeyContent.senderClaimedEd25519Key
} else {
Timber.v("## CRYPTO | onRoomKeyEvent(), Adding key : roomId " + roomKeyContent.roomId + " sessionId " + roomKeyContent.sessionId
+ " sessionKey " + roomKeyContent.sessionKey) // from " + event);
Timber.i("## CRYPTO | onRoomKeyEvent(), Adding key : ${roomKeyContent.roomId}|${roomKeyContent.sessionId}")
if (null == senderKey) {
Timber.e("## onRoomKeyEvent() : key event has no sender key (not encrypted?)")
return
@ -285,7 +282,7 @@ internal class MXMegolmDecryption(private val userId: String,
keysClaimed = event.getKeysClaimed().toMutableMap()
}
Timber.e("## CRYPTO | onRoomKeyEvent addInboundGroupSession ${roomKeyContent.sessionId}")
Timber.i("## CRYPTO | onRoomKeyEvent addInboundGroupSession ${roomKeyContent.sessionId}")
val added = olmDevice.addInboundGroupSession(roomKeyContent.sessionId,
roomKeyContent.sessionKey,
roomKeyContent.roomId,
@ -349,10 +346,10 @@ internal class MXMegolmDecryption(private val userId: String,
if (olmSessionResult?.sessionId == null) {
// no session with this device, probably because there
// were no one-time keys.
Timber.e("no session with this device $deviceId, probably because there were no one-time keys.")
return@mapCatching
}
Timber.v("## CRYPTO | shareKeysWithDevice() : sharing keys for session" +
" ${body.senderKey}|${body.sessionId} with device $userId:$deviceId")
Timber.i("## CRYPTO | shareKeysWithDevice() : sharing session ${body.sessionId} with device $userId:$deviceId")
val payloadJson = mutableMapOf<String, Any>("type" to EventType.FORWARDED_ROOM_KEY)
runCatching { olmDevice.getInboundGroupSession(body.sessionId, body.senderKey, body.roomId) }
@ -363,6 +360,7 @@ internal class MXMegolmDecryption(private val userId: String,
},
{
// TODO
Timber.e(it, "## CRYPTO | shareKeysWithDevice: failed to get session for request $body")
}
)
@ -370,9 +368,13 @@ internal class MXMegolmDecryption(private val userId: String,
val encodedPayload = messageEncrypter.encryptMessage(payloadJson, listOf(deviceInfo))
val sendToDeviceMap = MXUsersDevicesMap<Any>()
sendToDeviceMap.setObject(userId, deviceId, encodedPayload)
Timber.v("## CRYPTO | shareKeysWithDevice() : sending to $userId:$deviceId")
Timber.i("## CRYPTO | shareKeysWithDevice() : sending ${body.sessionId} to $userId:$deviceId")
val sendToDeviceParams = SendToDeviceTask.Params(EventType.ENCRYPTED, sendToDeviceMap)
try {
sendToDeviceTask.execute(sendToDeviceParams)
} catch (failure: Throwable) {
Timber.e(failure, "## CRYPTO | shareKeysWithDevice() : Failed to send ${body.sessionId} to $userId:$deviceId")
}
}
}
}

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

@ -217,8 +217,10 @@ internal class MXMegolmEncryption(
Timber.v("## CRYPTO | shareUserDevicesKey() : starts")
val results = ensureOlmSessionsForDevicesAction.handle(devicesByUser)
Timber.v("## CRYPTO | shareUserDevicesKey() : ensureOlmSessionsForDevices succeeds after "
+ (System.currentTimeMillis() - t0) + " ms")
Timber.v(
"""## CRYPTO | shareUserDevicesKey(): ensureOlmSessionsForDevices succeeds after ${System.currentTimeMillis() - t0} ms"""
.trimMargin()
)
val contentMap = MXUsersDevicesMap<Any>()
var haveTargets = false
val userIds = results.userIds
@ -242,7 +244,7 @@ internal class MXMegolmEncryption(
continue
}
Timber.v("## CRYPTO | shareUserDevicesKey() : Sharing keys with device $userId:$deviceID")
Timber.i("## CRYPTO | shareUserDevicesKey() : Sharing keys with device $userId:$deviceID")
contentMap.setObject(userId, deviceID, messageEncrypter.encryptMessage(payload, listOf(sessionResult.deviceInfo)))
haveTargets = true
}
@ -270,21 +272,22 @@ internal class MXMegolmEncryption(
if (haveTargets) {
t0 = System.currentTimeMillis()
Timber.v("## CRYPTO | shareUserDevicesKey() : has target")
Timber.i("## CRYPTO | shareUserDevicesKey() ${session.sessionId} : has target")
val sendToDeviceParams = SendToDeviceTask.Params(EventType.ENCRYPTED, contentMap)
try {
sendToDeviceTask.execute(sendToDeviceParams)
Timber.v("## CRYPTO | shareUserDevicesKey() : sendToDevice succeeds after ${System.currentTimeMillis() - t0} ms")
Timber.i("## CRYPTO | shareUserDevicesKey() : sendToDevice succeeds after ${System.currentTimeMillis() - t0} ms")
} catch (failure: Throwable) {
// What to do here...
Timber.e("## CRYPTO | shareUserDevicesKey() : Failed to share session <${session.sessionId}> with $devicesByUser ")
}
} else {
Timber.v("## CRYPTO | shareUserDevicesKey() : no need to sharekey")
Timber.i("## CRYPTO | shareUserDevicesKey() : no need to sharekey")
}
}
private fun notifyKeyWithHeld(targets: List<UserDevice>, sessionId: String, senderKey: String?, code: WithHeldCode) {
Timber.i("## CRYPTO | notifyKeyWithHeld() :sending withheld key for $targets session:$sessionId ")
val withHeldContent = RoomKeyWithHeldContent(
roomId = roomId,
senderKey = senderKey,
@ -393,16 +396,16 @@ internal class MXMegolmEncryption(
userId: String,
deviceId: String,
senderKey: String): Boolean {
Timber.d("[MXMegolmEncryption] reshareKey: $sessionId to $userId:$deviceId")
Timber.i("## Crypto process reshareKey for $sessionId to $userId:$deviceId")
val deviceInfo = cryptoStore.getUserDevice(userId, deviceId) ?: return false
.also { Timber.w("Device not found") }
.also { Timber.w("## Crypto reshareKey: Device not found") }
// Get the chain index of the key we previously sent this device
val chainIndex = outboundSession?.sharedWithHelper?.wasSharedWith(userId, deviceId) ?: return false
.also {
// Send a room key with held
notifyKeyWithHeld(listOf(UserDevice(userId, deviceId)), sessionId, senderKey, WithHeldCode.UNAUTHORISED)
Timber.w("[MXMegolmEncryption] reshareKey : ERROR : Never share megolm with this device")
Timber.w("## Crypto reshareKey: ERROR : Never share megolm with this device")
}
val devicesByUser = mapOf(userId to listOf(deviceInfo))
@ -411,9 +414,11 @@ internal class MXMegolmEncryption(
olmSessionResult?.sessionId
?: // no session with this device, probably because there were no one-time keys.
// ensureOlmSessionsForDevicesAction has already done the logging, so just skip it.
return false
return false.also {
Timber.w("## Crypto reshareKey: no session with this device, probably because there were no one-time keys")
}
Timber.d("[MXMegolmEncryption] reshareKey: sharing keys for session $senderKey|$sessionId:$chainIndex with device $userId:$deviceId")
Timber.i("[MXMegolmEncryption] reshareKey: sharing keys for session $senderKey|$sessionId:$chainIndex with device $userId:$deviceId")
val payloadJson = mutableMapOf<String, Any>("type" to EventType.FORWARDED_ROOM_KEY)
@ -425,6 +430,7 @@ internal class MXMegolmEncryption(
},
{
// TODO
Timber.e(it, "[MXMegolmEncryption] reshareKey: failed to get session $sessionId|$senderKey|$roomId")
}
)
@ -432,13 +438,14 @@ internal class MXMegolmEncryption(
val encodedPayload = messageEncrypter.encryptMessage(payloadJson, listOf(deviceInfo))
val sendToDeviceMap = MXUsersDevicesMap<Any>()
sendToDeviceMap.setObject(userId, deviceId, encodedPayload)
Timber.v("## CRYPTO | CRYPTO | reshareKey() : sending to $userId:$deviceId")
Timber.i("## CRYPTO | reshareKey() : sending session $sessionId to $userId:$deviceId")
val sendToDeviceParams = SendToDeviceTask.Params(EventType.ENCRYPTED, sendToDeviceMap)
return try {
sendToDeviceTask.execute(sendToDeviceParams)
Timber.i("## CRYPTO reshareKey() : successfully send <$sessionId> to $userId:$deviceId")
true
} catch (failure: Throwable) {
Timber.e(failure, "## CRYPTO | CRYPTO | reshareKey() : fail to send <$sessionId> to $userId:$deviceId")
Timber.e(failure, "## CRYPTO reshareKey() : fail to send <$sessionId> to $userId:$deviceId")
false
}
}

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

@ -24,6 +24,7 @@ import org.matrix.android.sdk.api.session.room.model.message.MessageContent
import org.matrix.android.sdk.internal.crypto.DefaultCryptoService
import org.matrix.android.sdk.internal.crypto.MXEventDecryptionResult
import org.matrix.android.sdk.internal.crypto.algorithms.olm.OlmDecryptionResult
import org.matrix.android.sdk.internal.crypto.model.event.OlmEventContent
import org.matrix.android.sdk.internal.crypto.verification.DefaultVerificationService
import org.matrix.android.sdk.internal.session.DefaultInitialSyncProgressService
import org.matrix.android.sdk.internal.session.sync.model.SyncResponse
@ -39,6 +40,7 @@ internal class CryptoSyncHandler @Inject constructor(private val cryptoService:
toDevice.events?.forEachIndexed { index, event ->
initialSyncProgressService?.reportProgress(((index / total.toFloat()) * 100).toInt())
// Decrypt event if necessary
Timber.i("## CRYPTO | To device event from ${event.senderId} of type:${event.type}")
decryptToDeviceEvent(event, null)
if (event.getClearType() == EventType.MESSAGE
&& event.getClearContent()?.toModel<MessageContent>()?.msgType == "m.bad.encrypted") {
@ -69,7 +71,12 @@ internal class CryptoSyncHandler @Inject constructor(private val cryptoService:
result = cryptoService.decryptEvent(event, timelineId ?: "")
} catch (exception: MXCryptoError) {
event.mCryptoError = (exception as? MXCryptoError.Base)?.errorType // setCryptoError(exception.cryptoError)
Timber.e("## CRYPTO | Failed to decrypt to device event: ${event.mCryptoError ?: exception}")
val senderKey = event.content.toModel<OlmEventContent>()?.senderKey ?: "<unknown sender key>"
// try to find device id to ease log reading
val deviceId = cryptoService.getCryptoDeviceInfo(event.senderId!!).firstOrNull {
it.identityKey() == senderKey
}?.deviceId ?: senderKey
Timber.e("## CRYPTO | Failed to decrypt to device event from ${event.senderId}|$deviceId reason:<${event.mCryptoError ?: exception}>")
}
if (null != result) {
@ -80,6 +87,9 @@ internal class CryptoSyncHandler @Inject constructor(private val cryptoService:
forwardingCurve25519KeyChain = result.forwardingCurve25519KeyChain
)
return true
} else {
// should not happen
Timber.e("## CRYPTO | ERROR NULL DECRYPTION RESULT from ${event.senderId}")
}
}