Improve log to track push and sync request

Also change some log level from d to v
This commit is contained in:
Benoit Marty 2021-09-20 17:14:56 +02:00 committed by Benoit Marty
parent 93506d18fa
commit 306e3cf055
5 changed files with 78 additions and 60 deletions

View file

@ -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) {

View file

@ -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<SyncTask.Params, Unit> {
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<String, String>()
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<String, String>): 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)

View file

@ -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
}

View file

@ -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 <T> Collection<T>.logLimit(maxQuantity: Int = 5): String {
@ -32,14 +33,15 @@ internal fun <T> Collection<T>.logLimit(maxQuantity: Int = 5): String {
}
internal suspend fun <T> 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
}

View file

@ -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<String, String>) {
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<String, String>, 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) {