diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/logger/LoggerTag.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/logger/LoggerTag.kt index 51f9b50699..0d204edcee 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/logger/LoggerTag.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/api/logger/LoggerTag.kt @@ -24,6 +24,7 @@ package org.matrix.android.sdk.api.logger */ open class LoggerTag(_value: String, parentTag: LoggerTag? = null) { + object SYNC : LoggerTag("SYNC") object VOIP : LoggerTag("VOIP") val value: String = if (parentTag == null) { diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/SyncTask.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/SyncTask.kt index abdceab35c..35e072ad0c 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/SyncTask.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/SyncTask.kt @@ -17,6 +17,7 @@ package org.matrix.android.sdk.internal.session.sync import okhttp3.ResponseBody +import org.matrix.android.sdk.api.logger.LoggerTag import org.matrix.android.sdk.api.session.initsync.InitSyncStep import org.matrix.android.sdk.api.session.initsync.InitialSyncProgressService import org.matrix.android.sdk.internal.di.SessionFilesDirectory @@ -41,6 +42,8 @@ import java.io.File import java.net.SocketTimeoutException import javax.inject.Inject +private val loggerTag = LoggerTag("SyncTask", LoggerTag.SYNC) + internal interface SyncTask : Task { data class Params( @@ -76,7 +79,7 @@ internal class DefaultSyncTask @Inject constructor( } private suspend fun doSync(params: SyncTask.Params) { - Timber.v("Sync task started on Thread: ${Thread.currentThread().name}") + Timber.tag(loggerTag.value).d("Sync task started on Thread: ${Thread.currentThread().name}") val requestParams = HashMap() var timeout = 0L @@ -101,9 +104,9 @@ internal class DefaultSyncTask @Inject constructor( val readTimeOut = (params.timeout + TIMEOUT_MARGIN).coerceAtLeast(TimeOutInterceptor.DEFAULT_LONG_TIMEOUT) if (isInitialSync) { - Timber.d("INIT_SYNC with filter: ${requestParams["filter"]}") + Timber.tag(loggerTag.value).d("INIT_SYNC with filter: ${requestParams["filter"]}") val initSyncStrategy = initialSyncStrategy - logDuration("INIT_SYNC strategy: $initSyncStrategy") { + logDuration("INIT_SYNC strategy: $initSyncStrategy", loggerTag) { if (initSyncStrategy is InitialSyncStrategy.Optimized) { roomSyncEphemeralTemporaryStore.reset() workingDir.mkdirs() @@ -114,7 +117,7 @@ internal class DefaultSyncTask @Inject constructor( // Delete all files workingDir.deleteRecursively() } else { - val syncResponse = logDuration("INIT_SYNC Request") { + val syncResponse = logDuration("INIT_SYNC Request", loggerTag) { executeRequest(globalErrorReceiver) { syncAPI.sync( params = requestParams, @@ -123,13 +126,14 @@ internal class DefaultSyncTask @Inject constructor( } } - logDuration("INIT_SYNC Database insertion") { + logDuration("INIT_SYNC Database insertion", loggerTag) { syncResponseHandler.handleResponse(syncResponse, token, initialSyncProgressService) } } } initialSyncProgressService.endAll() } else { + Timber.tag(loggerTag.value).d("Start incremental sync request") initialSyncProgressService.setStatus(InitialSyncProgressService.Status.IncrementalSyncIdle) val syncResponse = try { executeRequest(globalErrorReceiver) { @@ -139,37 +143,42 @@ internal class DefaultSyncTask @Inject constructor( ) } } catch (throwable: Throwable) { + Timber.tag(loggerTag.value).e(throwable, "Incremental sync request error") initialSyncProgressService.setStatus(InitialSyncProgressService.Status.IncrementalSyncError) throw throwable } + val nbRooms = syncResponse.rooms?.invite.orEmpty().size + syncResponse.rooms?.join.orEmpty().size + syncResponse.rooms?.leave.orEmpty().size + val nbToDevice = syncResponse.toDevice?.events.orEmpty().size + Timber.tag(loggerTag.value).d("Incremental sync request parsing, $nbRooms room(s) $nbToDevice toDevice(s)") initialSyncProgressService.setStatus(InitialSyncProgressService.Status.IncrementalSyncParsing( - rooms = syncResponse.rooms?.invite.orEmpty().size + syncResponse.rooms?.join.orEmpty().size + syncResponse.rooms?.leave.orEmpty().size, - toDevice = syncResponse.toDevice?.events.orEmpty().size + rooms = nbRooms, + toDevice = nbToDevice )) syncResponseHandler.handleResponse(syncResponse, token, null) + Timber.tag(loggerTag.value).d("Incremental sync done") initialSyncProgressService.setStatus(InitialSyncProgressService.Status.IncrementalSyncDone) } - Timber.v("Sync task finished on Thread: ${Thread.currentThread().name}") + Timber.tag(loggerTag.value).d("Sync task finished on Thread: ${Thread.currentThread().name}") } private suspend fun downloadInitSyncResponse(requestParams: Map): File { val workingFile = File(workingDir, "initSync.json") val status = initialSyncStatusRepository.getStep() if (workingFile.exists() && status >= InitialSyncStatus.STEP_DOWNLOADED) { - Timber.d("INIT_SYNC file is already here") + Timber.tag(loggerTag.value).d("INIT_SYNC file is already here") reportSubtask(initialSyncProgressService, InitSyncStep.Downloading, 1, 0.3f) { // Empty task } } else { initialSyncStatusRepository.setStep(InitialSyncStatus.STEP_DOWNLOADING) - val syncResponse = logDuration("INIT_SYNC Perform server request") { + val syncResponse = logDuration("INIT_SYNC Perform server request", loggerTag) { reportSubtask(initialSyncProgressService, InitSyncStep.ServerComputing, 1, 0.2f) { getSyncResponse(requestParams, MAX_NUMBER_OF_RETRY_AFTER_TIMEOUT) } } if (syncResponse.isSuccessful) { - logDuration("INIT_SYNC Download and save to file") { + logDuration("INIT_SYNC Download and save to file", loggerTag) { reportSubtask(initialSyncProgressService, InitSyncStep.Downloading, 1, 0.1f) { syncResponse.body()?.byteStream()?.use { inputStream -> workingFile.outputStream().use { outputStream -> @@ -180,7 +189,7 @@ internal class DefaultSyncTask @Inject constructor( } } else { throw syncResponse.toFailure(globalErrorReceiver) - .also { Timber.w("INIT_SYNC request failure: $this") } + .also { Timber.tag(loggerTag.value).w("INIT_SYNC request failure: $this") } } initialSyncStatusRepository.setStep(InitialSyncStatus.STEP_DOWNLOADED) } @@ -197,9 +206,9 @@ internal class DefaultSyncTask @Inject constructor( ).awaitResponse() } catch (throwable: Throwable) { if (throwable is SocketTimeoutException && retry > 0) { - Timber.w("INIT_SYNC timeout retry left: $retry") + Timber.tag(loggerTag.value).w("INIT_SYNC timeout retry left: $retry") } else { - Timber.e(throwable, "INIT_SYNC timeout, no retry left, or other error") + Timber.tag(loggerTag.value).e(throwable, "INIT_SYNC timeout, no retry left, or other error") throw throwable } } @@ -207,17 +216,17 @@ internal class DefaultSyncTask @Inject constructor( } private suspend fun handleSyncFile(workingFile: File, initSyncStrategy: InitialSyncStrategy.Optimized) { - logDuration("INIT_SYNC handleSyncFile()") { - val syncResponse = logDuration("INIT_SYNC Read file and parse") { + logDuration("INIT_SYNC handleSyncFile()", loggerTag) { + val syncResponse = logDuration("INIT_SYNC Read file and parse", loggerTag) { syncResponseParser.parse(initSyncStrategy, workingFile) } initialSyncStatusRepository.setStep(InitialSyncStatus.STEP_PARSED) // Log some stats val nbOfJoinedRooms = syncResponse.rooms?.join?.size ?: 0 val nbOfJoinedRoomsInFile = syncResponse.rooms?.join?.values?.count { it.ephemeral is LazyRoomSyncEphemeral.Stored } - Timber.d("INIT_SYNC $nbOfJoinedRooms rooms, $nbOfJoinedRoomsInFile ephemeral stored into files") + Timber.tag(loggerTag.value).d("INIT_SYNC $nbOfJoinedRooms rooms, $nbOfJoinedRoomsInFile ephemeral stored into files") - logDuration("INIT_SYNC Database insertion") { + logDuration("INIT_SYNC Database insertion", loggerTag) { syncResponseHandler.handleResponse(syncResponse, null, initialSyncProgressService) } initialSyncStatusRepository.setStep(InitialSyncStatus.STEP_SUCCESS) diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/job/SyncThread.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/job/SyncThread.kt index de8d009892..b3a6cafb7d 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/job/SyncThread.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/sync/job/SyncThread.kt @@ -36,6 +36,7 @@ import kotlinx.coroutines.cancelChildren import kotlinx.coroutines.delay import kotlinx.coroutines.launch import kotlinx.coroutines.runBlocking +import org.matrix.android.sdk.api.logger.LoggerTag import org.matrix.android.sdk.api.session.call.MxCall import org.matrix.android.sdk.internal.session.call.ActiveCallHandler import org.matrix.android.sdk.internal.session.sync.SyncPresence @@ -49,6 +50,8 @@ import kotlin.concurrent.schedule private const val RETRY_WAIT_TIME_MS = 10_000L private const val DEFAULT_LONG_POOL_TIMEOUT = 30_000L +private val loggerTag = LoggerTag("SyncThread", LoggerTag.SYNC) + internal class SyncThread @Inject constructor(private val syncTask: SyncTask, private val networkConnectivityChecker: NetworkConnectivityChecker, private val backgroundDetectionObserver: BackgroundDetectionObserver, @@ -83,7 +86,7 @@ internal class SyncThread @Inject constructor(private val syncTask: SyncTask, fun restart() = synchronized(lock) { if (!isStarted) { - Timber.v("Resume sync...") + Timber.tag(loggerTag.value).d("Resume sync...") isStarted = true // Check again server availability and the token validity canReachServer = true @@ -94,7 +97,7 @@ internal class SyncThread @Inject constructor(private val syncTask: SyncTask, fun pause() = synchronized(lock) { if (isStarted) { - Timber.v("Pause sync...") + Timber.tag(loggerTag.value).d("Pause sync...") isStarted = false retryNoNetworkTask?.cancel() syncScope.coroutineContext.cancelChildren() @@ -102,7 +105,7 @@ internal class SyncThread @Inject constructor(private val syncTask: SyncTask, } fun kill() = synchronized(lock) { - Timber.v("Kill sync...") + Timber.tag(loggerTag.value).d("Kill sync...") updateStateTo(SyncState.Killing) retryNoNetworkTask?.cancel() syncScope.coroutineContext.cancelChildren() @@ -124,21 +127,21 @@ internal class SyncThread @Inject constructor(private val syncTask: SyncTask, } override fun run() { - Timber.v("Start syncing...") + Timber.tag(loggerTag.value).d("Start syncing...") isStarted = true networkConnectivityChecker.register(this) backgroundDetectionObserver.register(this) registerActiveCallsObserver() while (state != SyncState.Killing) { - Timber.v("Entering loop, state: $state") + Timber.tag(loggerTag.value).d("Entering loop, state: $state") if (!isStarted) { - Timber.v("Sync is Paused. Waiting...") + Timber.tag(loggerTag.value).d("Sync is Paused. Waiting...") updateStateTo(SyncState.Paused) synchronized(lock) { lock.wait() } - Timber.v("...unlocked") + Timber.tag(loggerTag.value).d("...unlocked") } else if (!canReachServer) { - Timber.v("No network. Waiting...") + Timber.tag(loggerTag.value).d("No network. Waiting...") updateStateTo(SyncState.NoNetwork) // We force retrying in RETRY_WAIT_TIME_MS maximum. Otherwise it will be unlocked by onConnectivityChanged() or restart() retryNoNetworkTask = Timer(SyncState.NoNetwork.toString(), false).schedule(RETRY_WAIT_TIME_MS) { @@ -148,19 +151,19 @@ internal class SyncThread @Inject constructor(private val syncTask: SyncTask, } } synchronized(lock) { lock.wait() } - Timber.v("...retry") + Timber.tag(loggerTag.value).d("...retry") } else if (!isTokenValid) { - Timber.v("Token is invalid. Waiting...") + Timber.tag(loggerTag.value).d("Token is invalid. Waiting...") updateStateTo(SyncState.InvalidToken) synchronized(lock) { lock.wait() } - Timber.v("...unlocked") + Timber.tag(loggerTag.value).d("...unlocked") } else { if (state !is SyncState.Running) { updateStateTo(SyncState.Running(afterPause = true)) } // No timeout after a pause val timeout = state.let { if (it is SyncState.Running && it.afterPause) 0 else DEFAULT_LONG_POOL_TIMEOUT } - Timber.v("Execute sync request with timeout $timeout") + Timber.tag(loggerTag.value).d("Execute sync request with timeout $timeout") val params = SyncTask.Params(timeout, SyncPresence.Online) val sync = syncScope.launch { doSync(params) @@ -168,10 +171,10 @@ internal class SyncThread @Inject constructor(private val syncTask: SyncTask, runBlocking { sync.join() } - Timber.v("...Continue") + Timber.tag(loggerTag.value).d("...Continue") } } - Timber.v("Sync killed") + Timber.tag(loggerTag.value).d("Sync killed") updateStateTo(SyncState.Killed) backgroundDetectionObserver.unregister(this) networkConnectivityChecker.unregister(this) @@ -199,19 +202,19 @@ internal class SyncThread @Inject constructor(private val syncTask: SyncTask, } if (failure is Failure.NetworkConnection && failure.cause is SocketTimeoutException) { // Timeout are not critical - Timber.v("Timeout") + Timber.tag(loggerTag.value).d("Timeout") } else if (failure is CancellationException) { - Timber.v("Cancelled") + Timber.tag(loggerTag.value).d("Cancelled") } else if (failure.isTokenError()) { // No token or invalid token, stop the thread - Timber.w(failure, "Token error") + Timber.tag(loggerTag.value).w(failure, "Token error") isStarted = false isTokenValid = false } else { - Timber.e(failure) + Timber.tag(loggerTag.value).e(failure) if (failure !is Failure.NetworkConnection || failure.cause is JsonEncodingException) { // Wait 10s before retrying - Timber.v("Wait 10s") + Timber.tag(loggerTag.value).d("Wait 10s") delay(RETRY_WAIT_TIME_MS) } } @@ -225,7 +228,7 @@ internal class SyncThread @Inject constructor(private val syncTask: SyncTask, } private fun updateStateTo(newState: SyncState) { - Timber.v("Update state from $state to $newState") + Timber.tag(loggerTag.value).d("Update state from $state to $newState") if (newState == state) { return } diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/util/LogUtil.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/util/LogUtil.kt index 4656856bf7..6fd907d397 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/util/LogUtil.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/util/LogUtil.kt @@ -17,6 +17,7 @@ package org.matrix.android.sdk.internal.util import org.matrix.android.sdk.BuildConfig +import org.matrix.android.sdk.api.logger.LoggerTag import timber.log.Timber internal fun Collection.logLimit(maxQuantity: Int = 5): String { @@ -32,14 +33,15 @@ internal fun Collection.logLimit(maxQuantity: Int = 5): String { } internal suspend fun logDuration(message: String, + loggerTag: LoggerTag, block: suspend () -> T): T { - Timber.d("$message -- BEGIN") + Timber.tag(loggerTag.value).d("$message -- BEGIN") val start = System.currentTimeMillis() val result = logRamUsage(message) { block() } val duration = System.currentTimeMillis() - start - Timber.d("$message -- END duration: $duration ms") + Timber.tag(loggerTag.value).d("$message -- END duration: $duration ms") return result } diff --git a/vector/src/gplay/java/im/vector/app/gplay/push/fcm/VectorFirebaseMessagingService.kt b/vector/src/gplay/java/im/vector/app/gplay/push/fcm/VectorFirebaseMessagingService.kt index aaa81d7bc4..ddedfb93e3 100755 --- a/vector/src/gplay/java/im/vector/app/gplay/push/fcm/VectorFirebaseMessagingService.kt +++ b/vector/src/gplay/java/im/vector/app/gplay/push/fcm/VectorFirebaseMessagingService.kt @@ -47,11 +47,14 @@ import kotlinx.coroutines.SupervisorJob import kotlinx.coroutines.launch import kotlinx.coroutines.runBlocking import org.matrix.android.sdk.api.extensions.tryOrNull +import org.matrix.android.sdk.api.logger.LoggerTag import org.matrix.android.sdk.api.pushrules.Action import org.matrix.android.sdk.api.session.Session import org.matrix.android.sdk.api.session.events.model.Event import timber.log.Timber +private val loggerTag = LoggerTag("Push", LoggerTag.SYNC) + /** * Class extending FirebaseMessagingService. */ @@ -92,9 +95,9 @@ class VectorFirebaseMessagingService : FirebaseMessagingService() { */ override fun onMessageReceived(message: RemoteMessage) { if (BuildConfig.LOW_PRIVACY_LOG_ENABLE) { - Timber.d("## onMessageReceived() %s", message.data.toString()) + Timber.tag(loggerTag.value).d("## onMessageReceived() %s", message.data.toString()) } - Timber.d("## onMessageReceived() from FCM with priority %s", message.priority) + Timber.tag(loggerTag.value).d("## onMessageReceived() from FCM with priority %s", message.priority) runBlocking { vectorDataStore.incrementPushCounter() @@ -108,14 +111,14 @@ class VectorFirebaseMessagingService : FirebaseMessagingService() { } if (!vectorPreferences.areNotificationEnabledForDevice()) { - Timber.i("Notification are disabled for this device") + Timber.tag(loggerTag.value).i("Notification are disabled for this device") return } mUIHandler.post { if (ProcessLifecycleOwner.get().lifecycle.currentState.isAtLeast(Lifecycle.State.STARTED)) { // we are in foreground, let the sync do the things? - Timber.d("PUSH received in a foreground state, ignore") + Timber.tag(loggerTag.value).d("PUSH received in a foreground state, ignore") } else { onMessageReceivedInternal(message.data) } @@ -129,7 +132,7 @@ class VectorFirebaseMessagingService : FirebaseMessagingService() { * you retrieve the token. */ override fun onNewToken(refreshedToken: String) { - Timber.i("onNewToken: FCM Token has been updated") + Timber.tag(loggerTag.value).i("onNewToken: FCM Token has been updated") FcmHelper.storeFcmToken(this, refreshedToken) if (vectorPreferences.areNotificationEnabledForDevice() && activeSessionHolder.hasActiveSession()) { pusherManager.registerPusherWithFcmKey(refreshedToken) @@ -146,7 +149,7 @@ class VectorFirebaseMessagingService : FirebaseMessagingService() { * It is recommended that the app do a full sync with the app server after receiving this call. */ override fun onDeletedMessages() { - Timber.v("## onDeletedMessages()") + Timber.tag(loggerTag.value).v("## onDeletedMessages()") } /** @@ -158,9 +161,9 @@ class VectorFirebaseMessagingService : FirebaseMessagingService() { private fun onMessageReceivedInternal(data: Map) { try { if (BuildConfig.LOW_PRIVACY_LOG_ENABLE) { - Timber.d("## onMessageReceivedInternal() : $data") + Timber.tag(loggerTag.value).d("## onMessageReceivedInternal() : $data") } else { - Timber.d("## onMessageReceivedInternal()") + Timber.tag(loggerTag.value).d("## onMessageReceivedInternal()") } // update the badge counter @@ -170,24 +173,24 @@ class VectorFirebaseMessagingService : FirebaseMessagingService() { val session = activeSessionHolder.getSafeActiveSession() if (session == null) { - Timber.w("## Can't sync from push, no current session") + Timber.tag(loggerTag.value).w("## Can't sync from push, no current session") } else { val eventId = data["event_id"] val roomId = data["room_id"] if (isEventAlreadyKnown(eventId, roomId)) { - Timber.d("Ignoring push, event already known") + Timber.tag(loggerTag.value).d("Ignoring push, event already known") } else { // Try to get the Event content faster - Timber.d("Requesting event in fast lane") + Timber.tag(loggerTag.value).d("Requesting event in fast lane") getEventFastLane(session, roomId, eventId) - Timber.d("Requesting background sync") + Timber.tag(loggerTag.value).d("Requesting background sync") session.requireBackgroundSync() } } } catch (e: Exception) { - Timber.e(e, "## onMessageReceivedInternal() failed") + Timber.tag(loggerTag.value).e(e, "## onMessageReceivedInternal() failed") } } @@ -201,18 +204,18 @@ class VectorFirebaseMessagingService : FirebaseMessagingService() { } if (wifiDetector.isConnectedToWifi().not()) { - Timber.d("No WiFi network, do not get Event") + Timber.tag(loggerTag.value).d("No WiFi network, do not get Event") return } coroutineScope.launch { - Timber.d("Fast lane: start request") + Timber.tag(loggerTag.value).d("Fast lane: start request") val event = tryOrNull { session.getEvent(roomId, eventId) } ?: return@launch val resolvedEvent = notifiableEventResolver.resolveInMemoryEvent(session, event) resolvedEvent - ?.also { Timber.d("Fast lane: notify drawer") } + ?.also { Timber.tag(loggerTag.value).d("Fast lane: notify drawer") } ?.let { it.isPushGatewayEvent = true notificationDrawerManager.onNotifiableEventReceived(it) @@ -230,7 +233,7 @@ class VectorFirebaseMessagingService : FirebaseMessagingService() { val room = session.getRoom(roomId) ?: return false return room.getTimeLineEvent(eventId) != null } catch (e: Exception) { - Timber.e(e, "## isEventAlreadyKnown() : failed to check if the event was already defined") + Timber.tag(loggerTag.value).e(e, "## isEventAlreadyKnown() : failed to check if the event was already defined") } } return false @@ -238,7 +241,7 @@ class VectorFirebaseMessagingService : FirebaseMessagingService() { private fun handleNotificationWithoutSyncingMode(data: Map, session: Session?) { if (session == null) { - Timber.e("## handleNotificationWithoutSyncingMode cannot find session") + Timber.tag(loggerTag.value).e("## handleNotificationWithoutSyncingMode cannot find session") return } @@ -271,9 +274,9 @@ class VectorFirebaseMessagingService : FirebaseMessagingService() { val notifiableEvent = notifiableEventResolver.resolveEvent(event, session) if (notifiableEvent == null) { - Timber.e("Unsupported notifiable event $eventId") + Timber.tag(loggerTag.value).e("Unsupported notifiable event $eventId") if (BuildConfig.LOW_PRIVACY_LOG_ENABLE) { - Timber.e("--> $event") + Timber.tag(loggerTag.value).e("--> $event") } } else { if (notifiableEvent is NotifiableMessageEvent) {