From aedbce8e8d4cc851dd69706be3fd32b697cbcdee Mon Sep 17 00:00:00 2001 From: Jorge Martin Espinosa Date: Thu, 18 Jul 2024 15:16:20 +0200 Subject: [PATCH] Add logging to help debug forced logout issues (#3208) * Add logging to help debug forced logout issues * Use tags instead of manually adding the values to the logs. - Also add extension functions to easily get anonymized tokens from `Session`/`SessionData`. * Make sure only 1 operation related to token persistence can run at the same time --- .../api/tracing/TracingFilterConfiguration.kt | 2 + .../libraries/matrix/impl/RustMatrixClient.kt | 42 ++++++++++++------- .../matrix/impl/RustMatrixClientFactory.kt | 8 +++- .../libraries/matrix/impl/util/Token.kt | 38 +++++++++++++++++ 4 files changed, 74 insertions(+), 16 deletions(-) create mode 100644 libraries/matrix/impl/src/main/kotlin/io/element/android/libraries/matrix/impl/util/Token.kt diff --git a/libraries/matrix/api/src/main/kotlin/io/element/android/libraries/matrix/api/tracing/TracingFilterConfiguration.kt b/libraries/matrix/api/src/main/kotlin/io/element/android/libraries/matrix/api/tracing/TracingFilterConfiguration.kt index 84d4d61da5..5ef123f35d 100644 --- a/libraries/matrix/api/src/main/kotlin/io/element/android/libraries/matrix/api/tracing/TracingFilterConfiguration.kt +++ b/libraries/matrix/api/src/main/kotlin/io/element/android/libraries/matrix/api/tracing/TracingFilterConfiguration.kt @@ -30,6 +30,8 @@ data class TracingFilterConfiguration( Target.MATRIX_SDK_SLIDING_SYNC to LogLevel.INFO, Target.MATRIX_SDK_BASE_SLIDING_SYNC to LogLevel.INFO, Target.MATRIX_SDK_UI_TIMELINE to LogLevel.INFO, + // To debug OIDC logouts + Target.MATRIX_SDK_OIDC to LogLevel.TRACE, ) fun getLogLevel(target: Target): LogLevel { diff --git a/libraries/matrix/impl/src/main/kotlin/io/element/android/libraries/matrix/impl/RustMatrixClient.kt b/libraries/matrix/impl/src/main/kotlin/io/element/android/libraries/matrix/impl/RustMatrixClient.kt index ad37b0c917..db86e1a2a5 100644 --- a/libraries/matrix/impl/src/main/kotlin/io/element/android/libraries/matrix/impl/RustMatrixClient.kt +++ b/libraries/matrix/impl/src/main/kotlin/io/element/android/libraries/matrix/impl/RustMatrixClient.kt @@ -65,6 +65,7 @@ import io.element.android.libraries.matrix.impl.sync.RustSyncService import io.element.android.libraries.matrix.impl.usersearch.UserProfileMapper import io.element.android.libraries.matrix.impl.usersearch.UserSearchResultMapper import io.element.android.libraries.matrix.impl.util.SessionDirectoryProvider +import io.element.android.libraries.matrix.impl.util.anonymizedTokens import io.element.android.libraries.matrix.impl.util.cancelAndDestroy import io.element.android.libraries.matrix.impl.util.mxCallbackFlow import io.element.android.libraries.matrix.impl.verification.RustSessionVerificationService @@ -132,6 +133,9 @@ class RustMatrixClient( private val innerRoomListService = syncService.roomListService() private val sessionDispatcher = dispatchers.io.limitedParallelism(64) + + // To make sure only one coroutine affecting the token persistence can run at a time + private val tokenRefreshDispatcher = sessionDispatcher.limitedParallelism(1) private val rustSyncService = RustSyncService(syncService, sessionCoroutineScope) private val pushersService = RustPushersService( client = client, @@ -159,15 +163,20 @@ class RustMatrixClient( private val isLoggingOut = AtomicBoolean(false) private val clientDelegate = object : ClientDelegate { + private val clientLog get() = Timber.tag(this@RustMatrixClient.toString()) + override fun didReceiveAuthError(isSoftLogout: Boolean) { - Timber.w("didReceiveAuthError(isSoftLogout=$isSoftLogout)") + clientLog.w("didReceiveAuthError(isSoftLogout=$isSoftLogout)") if (isLoggingOut.getAndSet(true).not()) { - Timber.v("didReceiveAuthError -> do the cleanup") + clientLog.v("didReceiveAuthError -> do the cleanup") // TODO handle isSoftLogout parameter. - appCoroutineScope.launch { + appCoroutineScope.launch(tokenRefreshDispatcher) { val existingData = sessionStore.getSession(client.userId()) - val anonymizedToken = existingData?.accessToken?.takeLast(4) - Timber.d("Removing session data with token: '...$anonymizedToken'.") + val (anonymizedAccessToken, anonymizedRefreshToken) = existingData.anonymizedTokens() + clientLog.d( + "Removing session data with access token '$anonymizedAccessToken' " + + "and refresh token '$anonymizedRefreshToken'." + ) if (existingData != null) { // Set isTokenValid to false val newData = client.session().toSessionData( @@ -177,27 +186,30 @@ class RustMatrixClient( sessionPath = existingData.sessionPath, ) sessionStore.updateData(newData) - Timber.d("Removed session data with token: '...$anonymizedToken'.") + clientLog.d("Removed session data with access token: '$anonymizedAccessToken'.") } else { - Timber.d("No session data found.") + clientLog.d("No session data found.") } doLogout(doRequest = false, removeSession = false, ignoreSdkError = false) }.invokeOnCompletion { if (it != null) { - Timber.e(it, "Failed to remove session data.") + clientLog.e(it, "Failed to remove session data.") } } } else { - Timber.v("didReceiveAuthError -> already cleaning up") + clientLog.v("didReceiveAuthError -> already cleaning up") } } override fun didRefreshTokens() { - Timber.w("didRefreshTokens()") - appCoroutineScope.launch { + clientLog.w("didRefreshTokens()") + appCoroutineScope.launch(tokenRefreshDispatcher) { val existingData = sessionStore.getSession(client.userId()) ?: return@launch - val anonymizedToken = client.session().accessToken.takeLast(4) - Timber.d("Saving new session data with token: '...$anonymizedToken'. Was token valid: ${existingData.isTokenValid}") + val (anonymizedAccessToken, anonymizedRefreshToken) = client.session().anonymizedTokens() + clientLog.d( + "Saving new session data with token: access token '$anonymizedAccessToken' and refresh token '$anonymizedRefreshToken'. " + + "Was token valid: ${existingData.isTokenValid}" + ) val newData = client.session().toSessionData( isTokenValid = true, loginType = existingData.loginType, @@ -205,10 +217,10 @@ class RustMatrixClient( sessionPath = existingData.sessionPath, ) sessionStore.updateData(newData) - Timber.d("Saved new session data with token: '...$anonymizedToken'.") + clientLog.d("Saved new session data with access token: '$anonymizedAccessToken'.") }.invokeOnCompletion { if (it != null) { - Timber.e(it, "Failed to save new session data.") + clientLog.e(it, "Failed to save new session data.") } } } diff --git a/libraries/matrix/impl/src/main/kotlin/io/element/android/libraries/matrix/impl/RustMatrixClientFactory.kt b/libraries/matrix/impl/src/main/kotlin/io/element/android/libraries/matrix/impl/RustMatrixClientFactory.kt index ad563f39f3..7ddf54a300 100644 --- a/libraries/matrix/impl/src/main/kotlin/io/element/android/libraries/matrix/impl/RustMatrixClientFactory.kt +++ b/libraries/matrix/impl/src/main/kotlin/io/element/android/libraries/matrix/impl/RustMatrixClientFactory.kt @@ -21,6 +21,7 @@ import io.element.android.libraries.di.CacheDirectory import io.element.android.libraries.matrix.impl.analytics.UtdTracker import io.element.android.libraries.matrix.impl.certificates.UserCertificatesProvider import io.element.android.libraries.matrix.impl.proxy.ProxyProvider +import io.element.android.libraries.matrix.impl.util.anonymizedTokens import io.element.android.libraries.network.useragent.UserAgentProvider import io.element.android.libraries.sessionstorage.api.SessionData import io.element.android.libraries.sessionstorage.api.SessionStore @@ -30,6 +31,7 @@ import kotlinx.coroutines.withContext import org.matrix.rustcomponents.sdk.ClientBuilder import org.matrix.rustcomponents.sdk.Session import org.matrix.rustcomponents.sdk.use +import timber.log.Timber import java.io.File import javax.inject.Inject @@ -57,6 +59,8 @@ class RustMatrixClientFactory @Inject constructor( .withUtdHook(utdTracker) .finish() + val (anonymizedAccessToken, anonymizedRefreshToken) = sessionData.anonymizedTokens() + RustMatrixClient( client = client, syncService = syncService, @@ -66,7 +70,9 @@ class RustMatrixClientFactory @Inject constructor( baseDirectory = baseDirectory, baseCacheDirectory = cacheDirectory, clock = clock, - ) + ).also { + Timber.tag(it.toString()).d("Creating Client with access token '$anonymizedAccessToken' and refresh token '$anonymizedRefreshToken'") + } } internal fun getBaseClientBuilder( diff --git a/libraries/matrix/impl/src/main/kotlin/io/element/android/libraries/matrix/impl/util/Token.kt b/libraries/matrix/impl/src/main/kotlin/io/element/android/libraries/matrix/impl/util/Token.kt new file mode 100644 index 0000000000..ea07dc16c7 --- /dev/null +++ b/libraries/matrix/impl/src/main/kotlin/io/element/android/libraries/matrix/impl/util/Token.kt @@ -0,0 +1,38 @@ +/* + * Copyright (c) 2024 New Vector Ltd + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * https://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package io.element.android.libraries.matrix.impl.util + +import io.element.android.libraries.sessionstorage.api.SessionData +import org.matrix.rustcomponents.sdk.Session +import java.security.MessageDigest + +private val sha256 by lazy { MessageDigest.getInstance("SHA-256") } + +@OptIn(ExperimentalStdlibApi::class) +private fun anonymizeToken(token: String): String { + return sha256.digest(token.toByteArray()).toHexString() +} + +fun SessionData?.anonymizedTokens(): Pair { + if (this == null) return null to null + return anonymizeToken(accessToken) to refreshToken?.let { anonymizeToken(it) } +} + +fun Session?.anonymizedTokens(): Pair { + if (this == null) return null to null + return anonymizeToken(accessToken) to refreshToken?.let { anonymizeToken(it) } +}