Use buffer to log media timeout events (40e563d3) · Commits · e / os / android_frameworks_base

packages/SystemUI/src/com/android/systemui/log/dagger/LogModule.java

+10 −0

Original line number	Diff line number	Diff line
		@@ -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

packages/SystemUI/src/com/android/systemui/log/dagger/MediaTimeoutListenerLog.java

0 → 100644

+35 −0

Original line number	Diff line number	Diff line
		/*
		* 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 {
		}

packages/SystemUI/src/com/android/systemui/media/MediaTimeoutListener.kt

+12 −32

Original line number	Diff line number	Diff line
		@@ -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

packages/SystemUI/src/com/android/systemui/media/MediaTimeoutLogger.kt

0 → 100644

+151 −0

Original line number	Diff line number	Diff line
		/*
		* 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

packages/SystemUI/tests/src/com/android/systemui/media/MediaTimeoutListenerTest.kt

+15 −5

Original line number	Diff line number	Diff line
		@@ -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