Merge "Use buffer to log media timeout events" into tm-dev am: 6037653177

Original change: https://googleplex-android-review.googlesource.com/c/platform/frameworks/base/+/17900544

Change-Id: Ia49faf9125bfbdc86051ff2591972afd81d16441
Ignore-AOSP-First: this is an automerge
Signed-off-by: Automerger Merge Worker <android-build-automerger-merge-worker@system.gserviceaccount.com>

5 files changed, 223 insertions, 37 deletions

diff --git a/packages/SystemUI/src/com/android/systemui/log/dagger/LogModule.java b/packages/SystemUI/src/com/android/systemui/log/dagger/LogModule.java
index 39f00f45aac2..24671696f3bd 100644
--- a/packages/SystemUI/src/com/android/systemui/log/dagger/LogModule.java
+++ b/packages/SystemUI/src/com/android/systemui/log/dagger/LogModule.java
@@ -208,6 +208,16 @@ public class LogModule {
         return factory.create("MediaView", 100);
     }
 
+    /**
+     * Provides a buffer for media playback state changes
+     */
+    @Provides
+    @SysUISingleton
+    @MediaTimeoutListenerLog
+    public static LogBuffer providesMediaTimeoutListenerLogBuffer(LogBufferFactory factory) {
+        return factory.create("MediaTimeout", 100);
+    }
+
     /** Allows logging buffers to be tweaked via adb on debug builds but not on prod builds. */
     @Provides
     @SysUISingleton
diff --git a/packages/SystemUI/src/com/android/systemui/log/dagger/MediaTimeoutListenerLog.java b/packages/SystemUI/src/com/android/systemui/log/dagger/MediaTimeoutListenerLog.java
new file mode 100644
index 000000000000..53963fc8d431
--- /dev/null
+++ b/packages/SystemUI/src/com/android/systemui/log/dagger/MediaTimeoutListenerLog.java
@@ -0,0 +1,35 @@
+/*
+ * Copyright (C) 2022 The Android Open Source Project
+ *
+ * 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
+ *
+ *      http://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 com.android.systemui.log.dagger;
+
+import static java.lang.annotation.RetentionPolicy.RUNTIME;
+
+import com.android.systemui.log.LogBuffer;
+
+import java.lang.annotation.Documented;
+import java.lang.annotation.Retention;
+
+import javax.inject.Qualifier;
+
+/**
+ * A {@link LogBuffer} for {@link com.android.systemui.media.MediaTimeoutLogger}
+ */
+@Qualifier
+@Documented
+@Retention(RUNTIME)
+public @interface MediaTimeoutListenerLog {
+}
diff --git a/packages/SystemUI/src/com/android/systemui/media/MediaTimeoutListener.kt b/packages/SystemUI/src/com/android/systemui/media/MediaTimeoutListener.kt
index 51755065d4b6..8c6710a6fd68 100644
--- a/packages/SystemUI/src/com/android/systemui/media/MediaTimeoutListener.kt
+++ b/packages/SystemUI/src/com/android/systemui/media/MediaTimeoutListener.kt
@@ -19,7 +19,6 @@ package com.android.systemui.media
 import android.media.session.MediaController
 import android.media.session.PlaybackState
 import android.os.SystemProperties
-import android.util.Log
 import com.android.internal.annotations.VisibleForTesting
 import com.android.systemui.dagger.SysUISingleton
 import com.android.systemui.dagger.qualifiers.Main
@@ -28,9 +27,6 @@ import com.android.systemui.util.concurrency.DelayableExecutor
 import java.util.concurrent.TimeUnit
 import javax.inject.Inject
 
-private const val DEBUG = true
-private const val TAG = "MediaTimeout"
-
 @VisibleForTesting
 val PAUSED_MEDIA_TIMEOUT = SystemProperties
         .getLong("debug.sysui.media_timeout", TimeUnit.MINUTES.toMillis(10))
@@ -45,7 +41,8 @@ val RESUME_MEDIA_TIMEOUT = SystemProperties
 @SysUISingleton
 class MediaTimeoutListener @Inject constructor(
     private val mediaControllerFactory: MediaControllerFactory,
-    @Main private val mainExecutor: DelayableExecutor
+    @Main private val mainExecutor: DelayableExecutor,
+    private val logger: MediaTimeoutLogger
 ) : MediaDataManager.Listener {
 
     private val mediaListeners: MutableMap<String, PlaybackStateListener> = mutableMapOf()
@@ -75,9 +72,7 @@ class MediaTimeoutListener @Inject constructor(
             }
 
             // If listener was destroyed previously, we'll need to re-register it
-            if (DEBUG) {
-                Log.d(TAG, "Reusing destroyed listener $key")
-            }
+            logger.logReuseListener(key)
             reusedListener = it
         }
 
@@ -86,16 +81,12 @@ class MediaTimeoutListener @Inject constructor(
         val migrating = oldKey != null && key != oldKey
         if (migrating) {
             reusedListener = mediaListeners.remove(oldKey)
-            if (reusedListener != null) {
-                if (DEBUG) Log.d(TAG, "migrating key $oldKey to $key, for resumption")
-            } else {
-                Log.w(TAG, "Old key $oldKey for player $key doesn't exist. Continuing...")
-            }
+            logger.logMigrateListener(oldKey, key, reusedListener != null)
         }
 
         reusedListener?.let {
             val wasPlaying = it.playing ?: false
-            if (DEBUG) Log.d(TAG, "updating listener for $key, was playing? $wasPlaying")
+            logger.logUpdateListener(key, wasPlaying)
             it.mediaData = data
             it.key = key
             mediaListeners[key] = it
@@ -105,7 +96,7 @@ class MediaTimeoutListener @Inject constructor(
                 // until we're done.
                 mainExecutor.execute {
                     if (mediaListeners[key]?.playing == true) {
-                        if (DEBUG) Log.d(TAG, "deliver delayed playback state for $key")
+                        logger.logDelayedUpdate(key)
                         timeoutCallback.invoke(key, false /* timedOut */)
                     }
                 }
@@ -169,10 +160,7 @@ class MediaTimeoutListener @Inject constructor(
         }
 
         override fun onSessionDestroyed() {
-            if (DEBUG) {
-                Log.d(TAG, "Session destroyed for $key")
-            }
-
+            logger.logSessionDestroyed(key)
             if (resumption == true) {
                 // Some apps create a session when MBS is queried. We should unregister the
                 // controller since it will no longer be valid, but don't cancel the timeout
@@ -185,9 +173,7 @@ class MediaTimeoutListener @Inject constructor(
         }
 
         private fun processState(state: PlaybackState?, dispatchEvents: Boolean) {
-            if (DEBUG) {
-                Log.v(TAG, "processState $key: $state")
-            }
+            logger.logPlaybackState(key, state)
 
             val isPlaying = state != null && isPlayingState(state.state)
             val resumptionChanged = resumption != mediaData.resumption
@@ -198,12 +184,10 @@ class MediaTimeoutListener @Inject constructor(
             resumption = mediaData.resumption
 
             if (!isPlaying) {
-                if (DEBUG) {
-                    Log.v(TAG, "schedule timeout for $key playing $isPlaying, $resumption")
-                }
+                logger.logScheduleTimeout(key, isPlaying, resumption!!)
                 if (cancellation != null && !resumptionChanged) {
                     // if the media changed resume state, we'll need to adjust the timeout length
-                    if (DEBUG) Log.d(TAG, "cancellation already exists, continuing.")
+                    logger.logCancelIgnored(key)
                     return
                 }
                 expireMediaTimeout(key, "PLAYBACK STATE CHANGED - $state, $resumption")
@@ -214,9 +198,7 @@ class MediaTimeoutListener @Inject constructor(
                 }
                 cancellation = mainExecutor.executeDelayed({
                     cancellation = null
-                    if (DEBUG) {
-                        Log.v(TAG, "Execute timeout for $key")
-                    }
+                    logger.logTimeout(key)
                     timedOut = true
                     // this event is async, so it's safe even when `dispatchEvents` is false
                     timeoutCallback(key, timedOut)
@@ -232,9 +214,7 @@ class MediaTimeoutListener @Inject constructor(
 
         private fun expireMediaTimeout(mediaKey: String, reason: String) {
             cancellation?.apply {
-                if (DEBUG) {
-                    Log.v(TAG, "media timeout cancelled for  $mediaKey, reason: $reason")
-                }
+                logger.logTimeoutCancelled(mediaKey, reason)
                 run()
             }
             cancellation = null
diff --git a/packages/SystemUI/src/com/android/systemui/media/MediaTimeoutLogger.kt b/packages/SystemUI/src/com/android/systemui/media/MediaTimeoutLogger.kt
new file mode 100644
index 000000000000..a86515990fcb
--- /dev/null
+++ b/packages/SystemUI/src/com/android/systemui/media/MediaTimeoutLogger.kt
@@ -0,0 +1,151 @@
+/*
+ * Copyright (C) 2022 The Android Open Source Project
+ *
+ * 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
+ *
+ *      http://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 com.android.systemui.media
+
+import android.media.session.PlaybackState
+import com.android.systemui.dagger.SysUISingleton
+import com.android.systemui.log.LogBuffer
+import com.android.systemui.log.LogLevel
+import com.android.systemui.log.dagger.MediaTimeoutListenerLog
+import javax.inject.Inject
+
+private const val TAG = "MediaTimeout"
+
+/**
+ * A buffered log for [MediaTimeoutListener] events
+ */
+@SysUISingleton
+class MediaTimeoutLogger @Inject constructor(
+    @MediaTimeoutListenerLog private val buffer: LogBuffer
+) {
+    fun logReuseListener(key: String) = buffer.log(
+        TAG,
+        LogLevel.DEBUG,
+        {
+            str1 = key
+        },
+        {
+            "reuse listener: $str1"
+        }
+    )
+
+    fun logMigrateListener(oldKey: String?, newKey: String?, hadListener: Boolean) = buffer.log(
+        TAG,
+        LogLevel.DEBUG,
+        {
+            str1 = oldKey
+            str2 = newKey
+            bool1 = hadListener
+        },
+        {
+            "migrate from $str1 to $str2, had listener? $bool1"
+        }
+    )
+
+    fun logUpdateListener(key: String, wasPlaying: Boolean) = buffer.log(
+        TAG,
+        LogLevel.DEBUG,
+        {
+            str1 = key
+            bool1 = wasPlaying
+        },
+        {
+            "updating $str1, was playing? $bool1"
+        }
+    )
+
+    fun logDelayedUpdate(key: String) = buffer.log(
+        TAG,
+        LogLevel.DEBUG,
+        {
+            str1 = key
+        },
+        {
+            "deliver delayed playback state for $str1"
+        }
+    )
+
+    fun logSessionDestroyed(key: String) = buffer.log(
+        TAG,
+        LogLevel.DEBUG,
+        {
+            str1 = key
+        },
+        {
+            "session destroyed $str1"
+        }
+    )
+
+    fun logPlaybackState(key: String, state: PlaybackState?) = buffer.log(
+        TAG,
+        LogLevel.VERBOSE,
+        {
+            str1 = key
+            str2 = state?.toString()
+        },
+        {
+            "state update: key=$str1 state=$str2"
+        }
+    )
+
+    fun logScheduleTimeout(key: String, playing: Boolean, resumption: Boolean) = buffer.log(
+        TAG,
+        LogLevel.DEBUG,
+        {
+            str1 = key
+            bool1 = playing
+            bool2 = resumption
+        },
+        {
+            "schedule timeout $str1, playing=$bool1 resumption=$bool2"
+        }
+    )
+
+    fun logCancelIgnored(key: String) = buffer.log(
+        TAG,
+        LogLevel.DEBUG,
+        {
+            str1 = key
+        },
+        {
+            "cancellation already exists for $str1"
+        }
+    )
+
+    fun logTimeout(key: String) = buffer.log(
+        TAG,
+        LogLevel.DEBUG,
+        {
+            str1 = key
+        },
+        {
+            "execute timeout for $str1"
+        }
+    )
+
+    fun logTimeoutCancelled(key: String, reason: String) = buffer.log(
+        TAG,
+        LogLevel.VERBOSE,
+        {
+            str1 = key
+            str2 = reason
+        },
+        {
+            "media timeout cancelled for $str1, reason: $str2"
+        }
+    )
+}
\ No newline at end of file
diff --git a/packages/SystemUI/tests/src/com/android/systemui/media/MediaTimeoutListenerTest.kt b/packages/SystemUI/tests/src/com/android/systemui/media/MediaTimeoutListenerTest.kt
index 91169834752e..60cbb1754db6 100644
--- a/packages/SystemUI/tests/src/com/android/systemui/media/MediaTimeoutListenerTest.kt
+++ b/packages/SystemUI/tests/src/com/android/systemui/media/MediaTimeoutListenerTest.kt
@@ -24,6 +24,7 @@ import android.testing.AndroidTestingRunner
 import androidx.test.filters.SmallTest
 import com.android.systemui.SysuiTestCase
 import com.android.systemui.util.concurrency.FakeExecutor
+import com.android.systemui.util.mockito.any
 import com.android.systemui.util.mockito.capture
 import com.android.systemui.util.mockito.eq
 import com.android.systemui.util.time.FakeSystemClock
@@ -33,7 +34,6 @@ import org.junit.Rule
 import org.junit.Test
 import org.junit.runner.RunWith
 import org.mockito.ArgumentCaptor
-import org.mockito.ArgumentMatchers.any
 import org.mockito.ArgumentMatchers.anyBoolean
 import org.mockito.ArgumentMatchers.anyString
 import org.mockito.Captor
@@ -62,6 +62,7 @@ class MediaTimeoutListenerTest : SysuiTestCase() {
 
     @Mock private lateinit var mediaControllerFactory: MediaControllerFactory
     @Mock private lateinit var mediaController: MediaController
+    @Mock private lateinit var logger: MediaTimeoutLogger
     private lateinit var executor: FakeExecutor
     @Mock private lateinit var timeoutCallback: (String, Boolean) -> Unit
     @Captor private lateinit var mediaCallbackCaptor: ArgumentCaptor<MediaController.Callback>
@@ -77,7 +78,7 @@ class MediaTimeoutListenerTest : SysuiTestCase() {
     fun setup() {
         `when`(mediaControllerFactory.create(any())).thenReturn(mediaController)
         executor = FakeExecutor(FakeSystemClock())
-        mediaTimeoutListener = MediaTimeoutListener(mediaControllerFactory, executor)
+        mediaTimeoutListener = MediaTimeoutListener(mediaControllerFactory, executor, logger)
         mediaTimeoutListener.timeoutCallback = timeoutCallback
 
         // Create a media session and notification for testing.
@@ -112,8 +113,9 @@ class MediaTimeoutListenerTest : SysuiTestCase() {
         `when`(mediaController.playbackState).thenReturn(playingState)
         mediaTimeoutListener.onMediaDataLoaded(KEY, null, mediaData)
         verify(mediaController).registerCallback(capture(mediaCallbackCaptor))
+        verify(logger).logPlaybackState(eq(KEY), eq(playingState))
 
-        // Ignores is same key
+        // Ignores if same key
         clearInvocations(mediaController)
         mediaTimeoutListener.onMediaDataLoaded(KEY, KEY, mediaData)
         verify(mediaController, never()).registerCallback(anyObject())
@@ -125,6 +127,7 @@ class MediaTimeoutListenerTest : SysuiTestCase() {
         verify(mediaController).registerCallback(capture(mediaCallbackCaptor))
         assertThat(executor.numPending()).isEqualTo(1)
         verify(timeoutCallback, never()).invoke(anyString(), anyBoolean())
+        verify(logger).logScheduleTimeout(eq(KEY), eq(false), eq(false))
         assertThat(executor.advanceClockToNext()).isEqualTo(PAUSED_MEDIA_TIMEOUT)
     }
 
@@ -153,6 +156,7 @@ class MediaTimeoutListenerTest : SysuiTestCase() {
 
     @Test
     fun testOnMediaDataLoaded_migratesKeys() {
+        val newKey = "NEWKEY"
         // From not playing
         mediaTimeoutListener.onMediaDataLoaded(KEY, null, mediaData)
         clearInvocations(mediaController)
@@ -161,9 +165,10 @@ class MediaTimeoutListenerTest : SysuiTestCase() {
         val playingState = mock(android.media.session.PlaybackState::class.java)
         `when`(playingState.state).thenReturn(PlaybackState.STATE_PLAYING)
         `when`(mediaController.playbackState).thenReturn(playingState)
-        mediaTimeoutListener.onMediaDataLoaded("NEWKEY", KEY, mediaData)
+        mediaTimeoutListener.onMediaDataLoaded(newKey, KEY, mediaData)
         verify(mediaController).unregisterCallback(anyObject())
         verify(mediaController).registerCallback(anyObject())
+        verify(logger).logMigrateListener(eq(KEY), eq(newKey), eq(true))
 
         // Enqueues callback
         assertThat(executor.numPending()).isEqualTo(1)
@@ -171,6 +176,7 @@ class MediaTimeoutListenerTest : SysuiTestCase() {
 
     @Test
     fun testOnMediaDataLoaded_migratesKeys_noTimeoutExtension() {
+        val newKey = "NEWKEY"
         // From not playing
         mediaTimeoutListener.onMediaDataLoaded(KEY, null, mediaData)
         clearInvocations(mediaController)
@@ -179,11 +185,12 @@ class MediaTimeoutListenerTest : SysuiTestCase() {
         val playingState = mock(android.media.session.PlaybackState::class.java)
         `when`(playingState.state).thenReturn(PlaybackState.STATE_PAUSED)
         `when`(mediaController.playbackState).thenReturn(playingState)
-        mediaTimeoutListener.onMediaDataLoaded("NEWKEY", KEY, mediaData)
+        mediaTimeoutListener.onMediaDataLoaded(newKey, KEY, mediaData)
 
         // The number of queued timeout tasks remains the same. The timeout task isn't cancelled nor
         // is another scheduled
         assertThat(executor.numPending()).isEqualTo(1)
+        verify(logger).logUpdateListener(eq(newKey), eq(false))
     }
 
     @Test
@@ -205,6 +212,7 @@ class MediaTimeoutListenerTest : SysuiTestCase() {
         mediaCallbackCaptor.value.onPlaybackStateChanged(PlaybackState.Builder()
                 .setState(PlaybackState.STATE_PLAYING, 0L, 0f).build())
         assertThat(executor.numPending()).isEqualTo(0)
+        verify(logger).logTimeoutCancelled(eq(KEY), any())
     }
 
     @Test
@@ -249,6 +257,7 @@ class MediaTimeoutListenerTest : SysuiTestCase() {
         // THEN the controller is unregistered and timeout run
         verify(mediaController).unregisterCallback(anyObject())
         assertThat(executor.numPending()).isEqualTo(0)
+        verify(logger).logSessionDestroyed(eq(KEY))
     }
 
     @Test
@@ -270,6 +279,7 @@ class MediaTimeoutListenerTest : SysuiTestCase() {
             runAllReady()
         }
         verify(timeoutCallback).invoke(eq(KEY), eq(false))
+        verify(logger).logReuseListener(eq(KEY))
     }
 
     @Test