diff options
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 |