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

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 {

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)
+                    val (anonymizedAccessToken, anonymizedRefreshToken) = existingData.anonymizedTokens()
-                    Timber.d("Removing session data with token: '...$anonymizedToken'.")
+                    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()")
+            clientLog.w("didRefreshTokens()")
-            appCoroutineScope.launch {
+            appCoroutineScope.launch(tokenRefreshDispatcher) {
                 val existingData = sessionStore.getSession(client.userId()) ?: return@launch
-                val anonymizedToken = client.session().accessToken.takeLast(4)
+                val (anonymizedAccessToken, anonymizedRefreshToken) = client.session().anonymizedTokens()
-                Timber.d("Saving new session data with token: '...$anonymizedToken'. Was token valid: ${existingData.isTokenValid}")
+                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.")
                 }
             }
         }

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(

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<String?, String?> {
+    if (this == null) return null to null
+    return anonymizeToken(accessToken) to refreshToken?.let { anonymizeToken(it) }
+}
+
+fun Session?.anonymizedTokens(): Pair<String?, String?> {
+    if (this == null) return null to null
+    return anonymizeToken(accessToken) to refreshToken?.let { anonymizeToken(it) }
+}