diff --git a/libraries/push/impl/build.gradle.kts b/libraries/push/impl/build.gradle.kts index 68d32dbd238..705c1c713c6 100644 --- a/libraries/push/impl/build.gradle.kts +++ b/libraries/push/impl/build.gradle.kts @@ -86,6 +86,7 @@ dependencies { testImplementation(projects.features.networkmonitor.test) testImplementation(projects.services.appnavstate.impl) testImplementation(projects.services.appnavstate.test) + testImplementation(projects.services.analytics.test) testImplementation(projects.services.toolbox.impl) testImplementation(projects.services.toolbox.test) testImplementation(projects.libraries.featureflag.test) diff --git a/libraries/push/impl/src/main/kotlin/io/element/android/libraries/push/impl/notifications/NotificationRenderer.kt b/libraries/push/impl/src/main/kotlin/io/element/android/libraries/push/impl/notifications/NotificationRenderer.kt index c26a495ce8c..6a2fc2e7622 100644 --- a/libraries/push/impl/src/main/kotlin/io/element/android/libraries/push/impl/notifications/NotificationRenderer.kt +++ b/libraries/push/impl/src/main/kotlin/io/element/android/libraries/push/impl/notifications/NotificationRenderer.kt @@ -25,6 +25,9 @@ import io.element.android.libraries.push.impl.notifications.model.NotifiableMess import io.element.android.libraries.push.impl.notifications.model.NotifiableRingingCallEvent import io.element.android.libraries.push.impl.notifications.model.SimpleNotifiableEvent import io.element.android.libraries.sessionstorage.api.SessionStore +import io.element.android.services.analytics.api.AnalyticsLongRunningTransaction +import io.element.android.services.analytics.api.AnalyticsService +import io.element.android.services.analytics.api.finishLongRunningTransaction import kotlinx.coroutines.flow.first import timber.log.Timber @@ -36,6 +39,7 @@ class NotificationRenderer( private val notificationDataFactory: NotificationDataFactory, private val enterpriseService: EnterpriseService, private val sessionStore: SessionStore, + private val analyticsService: AnalyticsService, ) { suspend fun render( currentUser: MatrixUser, @@ -124,6 +128,12 @@ class NotificationRenderer( notification = summaryNotification.notification ) } + + for (event in eventsToProcess) { + // Finish long-running transaction + val uploaded = analyticsService.finishLongRunningTransaction(AnalyticsLongRunningTransaction.PushToNotification(event.eventId.value)) + Timber.d("Push-to-notification for event ${event.eventId} uploaded: $uploaded") + } } } diff --git a/libraries/push/impl/src/main/kotlin/io/element/android/libraries/push/impl/push/DefaultPushHandler.kt b/libraries/push/impl/src/main/kotlin/io/element/android/libraries/push/impl/push/DefaultPushHandler.kt index 7aec7190842..3f13f338184 100644 --- a/libraries/push/impl/src/main/kotlin/io/element/android/libraries/push/impl/push/DefaultPushHandler.kt +++ b/libraries/push/impl/src/main/kotlin/io/element/android/libraries/push/impl/push/DefaultPushHandler.kt @@ -40,6 +40,8 @@ import io.element.android.libraries.pushproviders.api.PushData import io.element.android.libraries.pushproviders.api.PushHandler import io.element.android.libraries.pushstore.api.UserPushStoreFactory import io.element.android.libraries.pushstore.api.clientsecret.PushClientSecret +import io.element.android.services.analytics.api.AnalyticsLongRunningTransaction +import io.element.android.services.analytics.api.AnalyticsService import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.flow.first import kotlinx.coroutines.flow.launchIn @@ -69,6 +71,7 @@ class DefaultPushHandler( private val fallbackNotificationFactory: FallbackNotificationFactory, private val syncOnNotifiableEvent: SyncOnNotifiableEvent, private val featureFlagService: FeatureFlagService, + private val analyticsService: AnalyticsService, ) : PushHandler { init { processPushEventResults() @@ -215,6 +218,13 @@ class DefaultPushHandler( * @param providerInfo the provider info. */ override suspend fun handle(pushData: PushData, providerInfo: String) { + // Start measuring how long it takes to display a notification from when the push is received + Timber.d("Calculating push-to-notification for event ${pushData.eventId}") + val parent = analyticsService.startLongRunningTransaction(AnalyticsLongRunningTransaction.PushToNotification(pushData.eventId.value)) + if (featureFlagService.isFeatureEnabled(FeatureFlags.SyncNotificationsWithWorkManager)) { + analyticsService.startLongRunningTransaction(AnalyticsLongRunningTransaction.PushToWorkManager(pushData.eventId.value), parent) + } + Timber.tag(loggerTag.value).d("## handling pushData: ${pushData.roomId}/${pushData.eventId}") if (buildMeta.lowPrivacyLoggingEnabled) { Timber.tag(loggerTag.value).d("## pushData: $pushData") diff --git a/libraries/push/impl/src/main/kotlin/io/element/android/libraries/push/impl/workmanager/FetchNotificationsWorker.kt b/libraries/push/impl/src/main/kotlin/io/element/android/libraries/push/impl/workmanager/FetchNotificationsWorker.kt index eeac5ff66fa..72c3768debe 100644 --- a/libraries/push/impl/src/main/kotlin/io/element/android/libraries/push/impl/workmanager/FetchNotificationsWorker.kt +++ b/libraries/push/impl/src/main/kotlin/io/element/android/libraries/push/impl/workmanager/FetchNotificationsWorker.kt @@ -19,7 +19,6 @@ import dev.zacsweers.metro.ContributesIntoMap import dev.zacsweers.metro.binding import io.element.android.features.networkmonitor.api.NetworkMonitor import io.element.android.features.networkmonitor.api.NetworkStatus -import io.element.android.libraries.core.coroutine.CoroutineDispatchers import io.element.android.libraries.core.extensions.runCatchingExceptions import io.element.android.libraries.di.annotations.ApplicationContext import io.element.android.libraries.matrix.api.auth.SessionRestorationException @@ -31,10 +30,13 @@ import io.element.android.libraries.push.impl.notifications.NotificationResolver import io.element.android.libraries.workmanager.api.WorkManagerScheduler import io.element.android.libraries.workmanager.api.di.MetroWorkerFactory import io.element.android.libraries.workmanager.api.di.WorkerKey +import io.element.android.services.analytics.api.AnalyticsLongRunningTransaction +import io.element.android.services.analytics.api.AnalyticsService +import io.element.android.services.analytics.api.finishLongRunningTransaction +import io.element.android.services.analytics.api.recordTransaction import io.element.android.services.toolbox.api.sdk.BuildVersionSdkIntProvider import kotlinx.coroutines.flow.MutableSharedFlow import kotlinx.coroutines.flow.first -import kotlinx.coroutines.withContext import kotlinx.coroutines.withTimeoutOrNull import timber.log.Timber import kotlin.time.Duration.Companion.seconds @@ -48,22 +50,45 @@ class FetchNotificationsWorker( private val queue: NotificationResolverQueue, private val workManagerScheduler: WorkManagerScheduler, private val syncOnNotifiableEvent: SyncOnNotifiableEvent, - private val coroutineDispatchers: CoroutineDispatchers, private val workerDataConverter: SyncNotificationsWorkerDataConverter, private val buildVersionSdkIntProvider: BuildVersionSdkIntProvider, + private val analyticsService: AnalyticsService, ) : CoroutineWorker(context, workerParams) { - override suspend fun doWork(): Result = withContext(coroutineDispatchers.io) { + override suspend fun doWork(): Result { Timber.d("FetchNotificationsWorker started") - val requests = workerDataConverter.deserialize(inputData) ?: return@withContext Result.failure() + val requests = workerDataConverter.deserialize(inputData) ?: return Result.failure() // Wait for network to be available, but not more than 10 seconds + val networkTimeoutSpans = requests.mapNotNull { request -> + val parent = analyticsService.getLongRunningTransaction(AnalyticsLongRunningTransaction.PushToWorkManager(request.eventId.value)) + parent?.startChild("Waiting for network connectivity", "await_network") + } val hasNetwork = withTimeoutOrNull(10.seconds) { networkMonitor.connectivity.first { it == NetworkStatus.Connected } } != null + + for (span in networkTimeoutSpans) { + span.finish() + } + if (!hasNetwork) { Timber.w("No network, retrying later") - return@withContext Result.retry() + for (request in requests) { + val eventId = request.eventId.value + analyticsService.finishLongRunningTransaction(AnalyticsLongRunningTransaction.PushToWorkManager(eventId)) + val parent = analyticsService.getLongRunningTransaction(AnalyticsLongRunningTransaction.PushToNotification(eventId)) + // Since we're retrying, start a new transaction + analyticsService.startLongRunningTransaction(AnalyticsLongRunningTransaction.PushToWorkManager(eventId), parent) + } + return Result.retry() } + val pendingAnalyticTransactions = requests.mapNotNull { request -> + analyticsService.finishLongRunningTransaction(AnalyticsLongRunningTransaction.PushToWorkManager(request.eventId.value)) + val parent = analyticsService.getLongRunningTransaction(AnalyticsLongRunningTransaction.PushToNotification(request.eventId.value)) + val transactionName = "WorkManager to event fetched" + parent?.startChild(transactionName)?.let { request.eventId to it } + }.toMap() + val failedSyncForSessions = mutableMapOf() val groupedRequests = requests.groupBy { it.sessionId }.toMutableMap() @@ -72,10 +97,17 @@ class FetchNotificationsWorker( eventResolver.resolveEvents(sessionId, notificationRequests) .fold( onSuccess = { result -> + for ((_, transaction) in pendingAnalyticTransactions) { + transaction.finish() + } // Update the resolved results in the queue (queue.results as MutableSharedFlow).emit(requests to result) }, onFailure = { + for ((_, transaction) in pendingAnalyticTransactions) { + transaction.attachError(it) + transaction.finish() + } failedSyncForSessions[sessionId] = it Timber.e(it, "Failed to resolve notification events for session $sessionId") } @@ -92,6 +124,18 @@ class FetchNotificationsWorker( continue } val requestsToRetry = groupedRequests[failedSessionId] ?: continue + + for (request in requestsToRetry) { + val failedTransaction = pendingAnalyticTransactions[request.eventId] + failedTransaction?.attachError(exception) + failedTransaction?.finish() + + val eventId = request.eventId.value + val parent = analyticsService.getLongRunningTransaction(AnalyticsLongRunningTransaction.PushToNotification(eventId)) + // Since we're retrying, start a new transaction + analyticsService.startLongRunningTransaction(AnalyticsLongRunningTransaction.PushToWorkManager(eventId), parent) + } + Timber.d("Re-scheduling ${requestsToRetry.size} failed notification requests for session $failedSessionId") workManagerScheduler.submit( SyncNotificationWorkManagerRequest( @@ -106,9 +150,11 @@ class FetchNotificationsWorker( Timber.d("Notifications processed successfully") - performOpportunisticSyncIfNeeded(groupedRequests) + analyticsService.recordTransaction("Opportunistic sync", "opportunistic_sync") { + performOpportunisticSyncIfNeeded(groupedRequests) + } - Result.success() + return Result.success() } private suspend fun performOpportunisticSyncIfNeeded( diff --git a/libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/notifications/DefaultNotificationDrawerManagerTest.kt b/libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/notifications/DefaultNotificationDrawerManagerTest.kt index b080c77a2d1..04da6ef5566 100644 --- a/libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/notifications/DefaultNotificationDrawerManagerTest.kt +++ b/libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/notifications/DefaultNotificationDrawerManagerTest.kt @@ -40,6 +40,7 @@ import io.element.android.libraries.sessionstorage.api.SessionStore import io.element.android.libraries.sessionstorage.api.observer.SessionObserver import io.element.android.libraries.sessionstorage.test.InMemorySessionStore import io.element.android.libraries.sessionstorage.test.observer.FakeSessionObserver +import io.element.android.services.analytics.test.FakeAnalyticsService import io.element.android.services.appnavstate.api.AppNavigationState import io.element.android.services.appnavstate.api.AppNavigationStateService import io.element.android.services.appnavstate.test.FakeAppNavigationStateService @@ -508,6 +509,7 @@ fun TestScope.createDefaultNotificationDrawerManager( sessionStore: SessionStore = InMemorySessionStore(), enterpriseService: EnterpriseService = FakeEnterpriseService(), sessionObserver: SessionObserver = FakeSessionObserver(), + analyticsService: FakeAnalyticsService = FakeAnalyticsService(), ): DefaultNotificationDrawerManager { return DefaultNotificationDrawerManager( notificationDisplayer = notificationDisplayer, @@ -521,6 +523,7 @@ fun TestScope.createDefaultNotificationDrawerManager( ), enterpriseService = enterpriseService, sessionStore = sessionStore, + analyticsService = analyticsService, ), appNavigationStateService = appNavigationStateService, coroutineScope = backgroundScope, diff --git a/libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/notifications/NotificationRendererTest.kt b/libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/notifications/NotificationRendererTest.kt index db292fcc612..6ca19b7accf 100644 --- a/libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/notifications/NotificationRendererTest.kt +++ b/libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/notifications/NotificationRendererTest.kt @@ -29,6 +29,7 @@ import io.element.android.libraries.push.impl.notifications.fixtures.anInviteNot import io.element.android.libraries.push.impl.notifications.model.NotifiableEvent import io.element.android.libraries.sessionstorage.api.SessionStore import io.element.android.libraries.sessionstorage.test.InMemorySessionStore +import io.element.android.services.analytics.test.FakeAnalyticsService import io.element.android.tests.testutils.lambda.lambdaRecorder import io.element.android.tests.testutils.lambda.value import kotlinx.coroutines.test.runTest @@ -122,9 +123,11 @@ fun createNotificationRenderer( notificationDataFactory: NotificationDataFactory = FakeNotificationDataFactory(), enterpriseService: EnterpriseService = FakeEnterpriseService(), sessionStore: SessionStore = InMemorySessionStore(), + analyticsService: FakeAnalyticsService = FakeAnalyticsService(), ) = NotificationRenderer( notificationDisplayer = notificationDisplayer, notificationDataFactory = notificationDataFactory, enterpriseService = enterpriseService, sessionStore = sessionStore, + analyticsService = analyticsService, ) diff --git a/libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/push/DefaultPushHandlerTest.kt b/libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/push/DefaultPushHandlerTest.kt index fc072144c70..5d3af86eeac 100644 --- a/libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/push/DefaultPushHandlerTest.kt +++ b/libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/push/DefaultPushHandlerTest.kt @@ -56,6 +56,7 @@ import io.element.android.libraries.pushstore.test.userpushstore.FakeUserPushSto import io.element.android.libraries.pushstore.test.userpushstore.clientsecret.FakePushClientSecret import io.element.android.libraries.workmanager.api.WorkManagerRequest import io.element.android.libraries.workmanager.test.FakeWorkManagerScheduler +import io.element.android.services.analytics.test.FakeAnalyticsService import io.element.android.services.toolbox.test.sdk.FakeBuildVersionSdkIntProvider import io.element.android.services.toolbox.test.systemclock.FakeSystemClock import io.element.android.tests.testutils.lambda.any @@ -683,6 +684,7 @@ class DefaultPushHandlerTest { syncOnNotifiableEvent: SyncOnNotifiableEvent = SyncOnNotifiableEvent {}, featureFlagService: FakeFeatureFlagService = FakeFeatureFlagService(initialState = mapOf(FeatureFlags.SyncNotificationsWithWorkManager.key to false)), workManagerScheduler: FakeWorkManagerScheduler = FakeWorkManagerScheduler(), + analyticsService: FakeAnalyticsService = FakeAnalyticsService(), ): DefaultPushHandler { return DefaultPushHandler( onNotifiableEventReceived = FakeOnNotifiableEventReceived(onNotifiableEventsReceived), @@ -715,6 +717,7 @@ class DefaultPushHandlerTest { ), syncOnNotifiableEvent = syncOnNotifiableEvent, featureFlagService = featureFlagService, + analyticsService = analyticsService, ) } } diff --git a/libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/workmanager/FetchNotificationWorkerTest.kt b/libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/workmanager/FetchNotificationWorkerTest.kt index d40ef17b53e..c1e5d3c92fb 100644 --- a/libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/workmanager/FetchNotificationWorkerTest.kt +++ b/libraries/push/impl/src/test/kotlin/io/element/android/libraries/push/impl/workmanager/FetchNotificationWorkerTest.kt @@ -29,9 +29,9 @@ import io.element.android.libraries.push.test.notifications.FakeNotificationReso import io.element.android.libraries.workmanager.api.WorkManagerRequest import io.element.android.libraries.workmanager.api.di.MetroWorkerFactory import io.element.android.libraries.workmanager.test.FakeWorkManagerScheduler +import io.element.android.services.analytics.test.FakeAnalyticsService import io.element.android.services.toolbox.test.sdk.FakeBuildVersionSdkIntProvider import io.element.android.tests.testutils.lambda.lambdaRecorder -import io.element.android.tests.testutils.testCoroutineDispatchers import kotlinx.coroutines.ExperimentalCoroutinesApi import kotlinx.coroutines.test.TestScope import kotlinx.coroutines.test.advanceTimeBy @@ -168,6 +168,7 @@ class FetchNotificationWorkerTest { ), workManagerScheduler: FakeWorkManagerScheduler = FakeWorkManagerScheduler(), syncOnNotifiableEvent: SyncOnNotifiableEvent = SyncOnNotifiableEvent {}, + analyticsService: FakeAnalyticsService = FakeAnalyticsService(), ) = FetchNotificationsWorker( workerParams = createWorkerParams(workDataOf("requests" to input)), context = InstrumentationRegistry.getInstrumentation().context, @@ -176,9 +177,9 @@ class FetchNotificationWorkerTest { queue = queue, workManagerScheduler = workManagerScheduler, syncOnNotifiableEvent = syncOnNotifiableEvent, - coroutineDispatchers = testCoroutineDispatchers(), workerDataConverter = SyncNotificationsWorkerDataConverter(DefaultJsonProvider()), buildVersionSdkIntProvider = FakeBuildVersionSdkIntProvider(33), + analyticsService = analyticsService, ) private fun TestScope.createWorkerParams( diff --git a/services/analytics/api/src/main/kotlin/io/element/android/services/analytics/api/AnalyticsLongRunningTransaction.kt b/services/analytics/api/src/main/kotlin/io/element/android/services/analytics/api/AnalyticsLongRunningTransaction.kt index 9c991cfce20..ed0e0b3b0b3 100644 --- a/services/analytics/api/src/main/kotlin/io/element/android/services/analytics/api/AnalyticsLongRunningTransaction.kt +++ b/services/analytics/api/src/main/kotlin/io/element/android/services/analytics/api/AnalyticsLongRunningTransaction.kt @@ -28,4 +28,6 @@ sealed class AnalyticsLongRunningTransaction( data object LoadJoinedRoomFlow : AnalyticsLongRunningTransaction("Load joined room UI", "ui.load") data object LoadMessagesUi : AnalyticsLongRunningTransaction("Load messages UI", "ui.load") data object DisplayFirstTimelineItems : AnalyticsLongRunningTransaction("Get and display first timeline items", null) + data class PushToNotification(val eventId: String) : AnalyticsLongRunningTransaction(AnalyticsTransactions.pushToNotification) + data class PushToWorkManager(val eventId: String) : AnalyticsLongRunningTransaction("Push to WorkManager") } diff --git a/services/analytics/api/src/main/kotlin/io/element/android/services/analytics/api/AnalyticsService.kt b/services/analytics/api/src/main/kotlin/io/element/android/services/analytics/api/AnalyticsService.kt index 1449977d917..8c29f11197e 100644 --- a/services/analytics/api/src/main/kotlin/io/element/android/services/analytics/api/AnalyticsService.kt +++ b/services/analytics/api/src/main/kotlin/io/element/android/services/analytics/api/AnalyticsService.kt @@ -108,11 +108,12 @@ fun AnalyticsService.cancelLongRunningTransaction( fun AnalyticsService.finishLongRunningTransaction( longRunningTransaction: AnalyticsLongRunningTransaction, action: (AnalyticsTransaction) -> Unit = {}, -) { - removeLongRunningTransaction(longRunningTransaction)?.let { +): Boolean { + return removeLongRunningTransaction(longRunningTransaction)?.let { action(it) it.finish() - } + true + } ?: false } inline fun AnalyticsService.inBridgeSdkSpan(parentTraceId: String?, block: (AnalyticsSdkSpan) -> T): T { diff --git a/services/analytics/impl/build.gradle.kts b/services/analytics/impl/build.gradle.kts index 6ba29638533..15465b1727f 100644 --- a/services/analytics/impl/build.gradle.kts +++ b/services/analytics/impl/build.gradle.kts @@ -40,5 +40,6 @@ dependencies { testImplementation(projects.services.analytics.test) testImplementation(projects.services.analyticsproviders.test) testImplementation(projects.services.appnavstate.test) + testImplementation(projects.features.networkmonitor.test) testImplementation(projects.services.toolbox.test) } diff --git a/services/analyticsproviders/api/src/main/kotlin/io/element/android/services/analyticsproviders/api/AnalyticsTransactions.kt b/services/analyticsproviders/api/src/main/kotlin/io/element/android/services/analyticsproviders/api/AnalyticsTransactions.kt index 5c44cc9e322..171367ec550 100644 --- a/services/analyticsproviders/api/src/main/kotlin/io/element/android/services/analyticsproviders/api/AnalyticsTransactions.kt +++ b/services/analyticsproviders/api/src/main/kotlin/io/element/android/services/analyticsproviders/api/AnalyticsTransactions.kt @@ -37,6 +37,12 @@ object AnalyticsTransactions { operation = "ux", description = "Send to sent state in timeline", ) + + val pushToNotification = TransactionDefinition( + name = "Push to notification", + operation = "push_to_notification", + description = "Time from receiving a push notification until it's displayed", + ) } data class TransactionDefinition(