Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 165c5c88 authored by András Kurucz's avatar András Kurucz
Browse files

Fix race condition in NotificationStatsLogger to avoid dupe logs 

Ensure that notification visibility state changes are processed
sequentially to avoid duplicate logging.

When the last HUN is animating away over launcher, and the shade becomes
non-interactible again, the NotificationStatsLogger receives two updates
over a short time. An onNotificationLocationsChanged call saying that
the HUN is no longer visible, and an onLockscreenOrShadeNotInteractive
call indicating that the HUN is not visible anymore.
The second update didn't wait for the previous job to complete, and it
was getting started before we clean up the last reported array. This was
leading to duplicate logs with the same data.

Fixes: 376667852
Test: Remove a HUN, and observe the logs
       - receive a HUN while the shade is closed
       - wait until it animates away
       - check that there is no duplicate IStatusBarService log
Flag: com.android.systemui.notifications_live_data_store_refactor
Change-Id: Ia9f5b40c77b9120192d5c02964967b42d300b125
parent 7acbff03

packages/SystemUI/multivalentTests/src/com/android/systemui/statusbar/notification/stack/ui/view/NotificationStatsLoggerTest.kt

+61 −21
Original line number Diff line number Diff line
@@ -171,6 +171,41 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
            }

        }



    @Test

    fun onNotificationVisibilityChanged_thenShadeNotInteractive_noDuplicateLogs() =

        testScope.runTest {

            // GIVEN a visible Notifications is reported

            val (ranks, locations) = fakeNotificationMaps("key0")

            val callable = Callable { locations }

            underTest.onNotificationLocationsChanged(callable, ranks)

            runCurrent()

            clearInvocations(mockStatusBarService, mockNotificationListenerService)



            // WHEN the same Notification becomins invisible

            val emptyCallable = Callable { emptyMap<String, Int>() }

            underTest.onNotificationLocationsChanged(emptyCallable, ranks)

            // AND notifications become non interactible

            underTest.onLockscreenOrShadeNotInteractive(emptyList())

            runCurrent()



            // THEN visibility changes are reported

            verify(mockStatusBarService)

                .onNotificationVisibilityChanged(eq(emptyArray()), visibilityArrayCaptor.capture())

            val noLongerVisible = visibilityArrayCaptor.value

            assertThat(noLongerVisible).hasLength(1)

            assertThat(noLongerVisible[0]).apply {

                isKeyEqualTo("key0")

                isRankEqualTo(0)

                notVisible()

                isInMainArea()

                isCountEqualTo(1)

            }



            // AND nothing else is logged

            verifyNoMoreInteractions(mockStatusBarService)

            verifyNoMoreInteractions(mockNotificationListenerService)

        }



    @Test

    fun onNotificationListUpdated_itemsChangedPositions_nothingLogged() =

        testScope.runTest {
@@ -255,14 +290,14 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                    activeNotificationModel(

                        key = "key0",

                        uid = 0,

                        packageName = "com.android.first"

                        packageName = "com.android.first",

                    ),

                    activeNotificationModel(

                        key = "key1",

                        uid = 1,

                        packageName = "com.android.second"

                        packageName = "com.android.second",

                    ),

                ),

                )

            )

            runCurrent()
@@ -288,7 +323,7 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                key = "key",

                isExpanded = true,

                location = ExpandableViewState.LOCATION_MAIN_AREA,

                isUserAction = true

                isUserAction = true,

            )

            runCurrent()
@@ -298,7 +333,7 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                    /* key = */ "key",

                    /* userAction = */ true,

                    /* expanded = */ true,

                    NotificationVisibility.NotificationLocation.LOCATION_MAIN_AREA.ordinal

                    NotificationVisibility.NotificationLocation.LOCATION_MAIN_AREA.ordinal,

                )

        }
@@ -310,7 +345,7 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                key = "key",

                isExpanded = true,

                location = ExpandableViewState.LOCATION_MAIN_AREA,

                isUserAction = true

                isUserAction = true,

            )

            runCurrent()

            clearInvocations(mockStatusBarService)
@@ -320,7 +355,7 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                key = "key",

                isExpanded = true,

                location = ExpandableViewState.LOCATION_MAIN_AREA,

                isUserAction = true

                isUserAction = true,

            )

            runCurrent()
@@ -336,7 +371,7 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                key = "key",

                isExpanded = true,

                location = ExpandableViewState.LOCATION_BOTTOM_STACK_HIDDEN,

                isUserAction = true

                isUserAction = true,

            )

            runCurrent()
@@ -352,7 +387,7 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                key = "key",

                isExpanded = true,

                location = ExpandableViewState.LOCATION_GONE,

                isUserAction = false

                isUserAction = false,

            )

            runCurrent()
@@ -368,7 +403,7 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                    /* key = */ "key",

                    /* userAction = */ false,

                    /* expanded = */ true,

                    NotificationVisibility.NotificationLocation.LOCATION_MAIN_AREA.ordinal

                    NotificationVisibility.NotificationLocation.LOCATION_MAIN_AREA.ordinal,

                )

        }
@@ -380,7 +415,7 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                key = "key",

                isExpanded = true,

                location = ExpandableViewState.LOCATION_GONE,

                isUserAction = false

                isUserAction = false,

            )

            runCurrent()

            // AND we open the shade, so we log its events
@@ -406,7 +441,7 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                    /* key = */ "key",

                    /* userAction = */ false,

                    /* expanded = */ true,

                    NotificationVisibility.NotificationLocation.LOCATION_MAIN_AREA.ordinal

                    NotificationVisibility.NotificationLocation.LOCATION_MAIN_AREA.ordinal,

                )

        }
@@ -418,7 +453,7 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                key = "key",

                isExpanded = false,

                location = ExpandableViewState.LOCATION_MAIN_AREA,

                isUserAction = false

                isUserAction = false,

            )

            runCurrent()
@@ -435,7 +470,7 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                key = "key",

                isExpanded = true,

                location = ExpandableViewState.LOCATION_MAIN_AREA,

                isUserAction = true

                isUserAction = true,

            )

            runCurrent()
@@ -445,7 +480,7 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                    /* key = */ "key",

                    /* userAction = */ true,

                    /* expanded = */ true,

                    NotificationVisibility.NotificationLocation.LOCATION_MAIN_AREA.ordinal

                    NotificationVisibility.NotificationLocation.LOCATION_MAIN_AREA.ordinal,

                )



            // AND the Notification is expanded again
@@ -453,7 +488,7 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                key = "key",

                isExpanded = false,

                location = ExpandableViewState.LOCATION_MAIN_AREA,

                isUserAction = true

                isUserAction = true,

            )

            runCurrent()
@@ -463,7 +498,7 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                    /* key = */ "key",

                    /* userAction = */ true,

                    /* expanded = */ false,

                    NotificationVisibility.NotificationLocation.LOCATION_MAIN_AREA.ordinal

                    NotificationVisibility.NotificationLocation.LOCATION_MAIN_AREA.ordinal,

                )

        }
@@ -475,14 +510,14 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                key = "key1",

                isExpanded = true,

                location = ExpandableViewState.LOCATION_MAIN_AREA,

                isUserAction = true

                isUserAction = true,

            )

            runCurrent()

            underTest.onNotificationExpansionChanged(

                key = "key2",

                isExpanded = true,

                location = ExpandableViewState.LOCATION_MAIN_AREA,

                isUserAction = true

                isUserAction = true,

            )

            runCurrent()

            clearInvocations(mockStatusBarService)
@@ -502,14 +537,14 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 
                key = "key1",

                isExpanded = true,

                location = ExpandableViewState.LOCATION_MAIN_AREA,

                isUserAction = true

                isUserAction = true,

            )

            runCurrent()

            underTest.onNotificationExpansionChanged(

                key = "key2",

                isExpanded = true,

                location = ExpandableViewState.LOCATION_MAIN_AREA,

                isUserAction = true

                isUserAction = true,

            )

            runCurrent()

            clearInvocations(mockStatusBarService)
@@ -537,10 +572,15 @@ class NotificationStatsLoggerTest : SysuiTestCase() { 


private class NotificationVisibilitySubject(private val visibility: NotificationVisibility) {

    fun isKeyEqualTo(key: String) = assertThat(visibility.key).isEqualTo(key)



    fun isRankEqualTo(rank: Int) = assertThat(visibility.rank).isEqualTo(rank)



    fun isCountEqualTo(count: Int) = assertThat(visibility.count).isEqualTo(count)



    fun isVisible() = assertThat(this.visibility.visible).isTrue()



    fun notVisible() = assertThat(this.visibility.visible).isFalse()



    fun isInMainArea() =

        assertThat(this.visibility.location)

            .isEqualTo(NotificationVisibility.NotificationLocation.LOCATION_MAIN_AREA)

packages/SystemUI/src/com/android/systemui/statusbar/notification/stack/ui/view/NotificationStatsLoggerImpl.kt

+57 −47
Original line number Diff line number Diff line
@@ -19,6 +19,7 @@ package com.android.systemui.statusbar.notification.stack.ui.view 
import android.service.notification.NotificationListenerService

import androidx.annotation.VisibleForTesting

import com.android.app.tracing.coroutines.TrackTracer

import com.android.app.tracing.coroutines.launchTraced as launch

import com.android.internal.statusbar.IStatusBarService

import com.android.internal.statusbar.NotificationVisibility

import com.android.systemui.dagger.SysUISingleton
@@ -33,8 +34,9 @@ import java.util.concurrent.ConcurrentHashMap 
import javax.inject.Inject

import kotlinx.coroutines.CoroutineDispatcher

import kotlinx.coroutines.CoroutineScope

import kotlinx.coroutines.Job

import com.android.app.tracing.coroutines.launchTraced as launch

import kotlinx.coroutines.channels.BufferOverflow

import kotlinx.coroutines.channels.Channel

import kotlinx.coroutines.channels.consumeEach

import kotlinx.coroutines.withContext



@VisibleForTesting const val UNKNOWN_RANK = -1
@@ -49,31 +51,55 @@ constructor( 
    private val notificationPanelLogger: NotificationPanelLogger,

    private val statusBarService: IStatusBarService,

) : NotificationStatsLogger {

    private val lastLoggedVisibilities = mutableMapOf<String, VisibilityState>()

    private var logVisibilitiesJob: Job? = null



    private val expansionStates: MutableMap<String, ExpansionState> =

        ConcurrentHashMap<String, ExpansionState>()

    @VisibleForTesting

    val lastReportedExpansionValues: MutableMap<String, Boolean> =

        ConcurrentHashMap<String, Boolean>()



    private val visibilityLogger =

        Channel<VisibilityAction>(capacity = 2, onBufferOverflow = BufferOverflow.DROP_OLDEST)



    init {

        applicationScope.launch { consumeVisibilityActions() }

    }



    private suspend fun consumeVisibilityActions() {

        val lastLoggedVisibilities = mutableMapOf<String, VisibilityState>()



        visibilityLogger.consumeEach { action ->

            val newVisibilities =

                when (action) {

                    is VisibilityAction.Change -> action.visibilities

                    is VisibilityAction.Clear -> emptyMap()

                }



            val newlyVisible = newVisibilities - lastLoggedVisibilities.keys

            val noLongerVisible = lastLoggedVisibilities - newVisibilities.keys



            maybeLogVisibilityChanges(newlyVisible, noLongerVisible, action.activeCount)

            updateExpansionStates(newlyVisible, noLongerVisible)

            TrackTracer.instantForGroup("Notifications", "Active", action.activeCount)

            TrackTracer.instantForGroup("Notifications", "Visible", newVisibilities.size)



            lastLoggedVisibilities.clear()

            lastLoggedVisibilities.putAll(newVisibilities)

        }

    }



    override fun onNotificationLocationsChanged(

        locationsProvider: Callable<Map<String, Int>>,

        notificationRanks: Map<String, Int>,

    ) {

        if (logVisibilitiesJob?.isActive == true) {

            return

        }



        logVisibilitiesJob =

            startLogVisibilitiesJob(

                newVisibilities =

        visibilityLogger.trySend(

            VisibilityAction.Change(

                visibilities =

                    combine(

                        visibilities = locationsProvider.call(),

                        rankingsMap = notificationRanks

                        rankingsMap = notificationRanks,

                    ),

                activeNotifCount = notificationRanks.size,

                activeCount = notificationRanks.size,

            )

        )

    }
@@ -125,7 +151,7 @@ constructor( 
                    /* expanded = */ expansionState.isExpanded,

                    /* notificationLocation = */ expansionState.location

                        .toNotificationLocation()

                        .ordinal

                        .ordinal,

                )

            }

        }
@@ -138,7 +164,7 @@ constructor( 
            withContext(bgDispatcher) {

                notificationPanelLogger.logPanelShown(

                    isOnLockScreen,

                    activeNotifications.toNotificationProto()

                    activeNotifications.toNotificationProto(),

                )

            }

        }
@@ -147,11 +173,7 @@ constructor( 
    override fun onLockscreenOrShadeNotInteractive(

        activeNotifications: List<ActiveNotificationModel>

    ) {

        logVisibilitiesJob =

            startLogVisibilitiesJob(

                newVisibilities = emptyMap(),

                activeNotifCount = activeNotifications.size

            )

        visibilityLogger.trySend(VisibilityAction.Clear(activeCount = activeNotifications.size))

    }



    override fun onNotificationRemoved(key: String) {
@@ -167,29 +189,12 @@ constructor( 


    private fun combine(

        visibilities: Map<String, Int>,

        rankingsMap: Map<String, Int>

        rankingsMap: Map<String, Int>,

    ): Map<String, VisibilityState> =

        visibilities.mapValues { entry ->

            VisibilityState(entry.key, entry.value, rankingsMap[entry.key] ?: UNKNOWN_RANK)

        }



    private fun startLogVisibilitiesJob(

        newVisibilities: Map<String, VisibilityState>,

        activeNotifCount: Int,

    ) =

        applicationScope.launch {

            val newlyVisible = newVisibilities - lastLoggedVisibilities.keys

            val noLongerVisible = lastLoggedVisibilities - newVisibilities.keys



            maybeLogVisibilityChanges(newlyVisible, noLongerVisible, activeNotifCount)

            updateExpansionStates(newlyVisible, noLongerVisible)

            TrackTracer.instantForGroup("Notifications", "Active", activeNotifCount)

            TrackTracer.instantForGroup("Notifications", "Visible", newVisibilities.size)



            lastLoggedVisibilities.clear()

            lastLoggedVisibilities.putAll(newVisibilities)

        }



    private suspend fun maybeLogVisibilityChanges(

        newlyVisible: Map<String, VisibilityState>,

        noLongerVisible: Map<String, VisibilityState>,
@@ -205,7 +210,7 @@ constructor( 
        val noLongerVisibleAr =

            noLongerVisible.mapToNotificationVisibilitiesAr(

                visible = false,

                count = activeNotifCount

                count = activeNotifCount,

            )



        withContext(bgDispatcher) {
@@ -218,7 +223,7 @@ constructor( 


    private fun updateExpansionStates(

        newlyVisible: Map<String, VisibilityState>,

        noLongerVisible: Map<String, VisibilityState>

        noLongerVisible: Map<String, VisibilityState>,

    ) {

        expansionStates.forEach { (key, expansionState) ->

            if (newlyVisible.contains(key)) {
@@ -241,11 +246,16 @@ constructor( 
        }

    }



    private data class VisibilityState(

        val key: String,

        val location: Int,

        val rank: Int,

    )

    private sealed class VisibilityAction(open val activeCount: Int) {

        data class Change(

            val visibilities: Map<String, VisibilityState>,

            override val activeCount: Int,

        ) : VisibilityAction(activeCount)



        data class Clear(override val activeCount: Int) : VisibilityAction(activeCount)

    }



    private data class VisibilityState(val key: String, val location: Int, val rank: Int)



    private data class ExpansionState(

        val key: String,
@@ -278,7 +288,7 @@ constructor( 
                    /* rank = */ state.rank,

                    /* count = */ count,

                    /* visible = */ visible,

                    /* location = */ state.location.toNotificationLocation()

                    /* location = */ state.location.toNotificationLocation(),

                )

            }

            .toTypedArray()

packages/SystemUI/tests/utils/src/com/android/systemui/statusbar/notification/stack/ui/view/NotificationStatsLoggerKosmos.kt

+1 −1
Original line number Diff line number Diff line
@@ -26,7 +26,7 @@ import com.android.systemui.statusbar.notification.logging.notificationPanelLogg 


val Kosmos.notificationStatsLogger by Fixture {

    NotificationStatsLoggerImpl(

        applicationScope = testScope,

        applicationScope = testScope.backgroundScope,

        bgDispatcher = testDispatcher,

        statusBarService = statusBarService,

        notificationListenerService = notificationListenerService,