androidx / media

Jetpack Media3 support libraries for media use cases, including ExoPlayer, an extensible media player for Android
https://developer.android.com/media/media3
Apache License 2.0
1.52k stars 360 forks source link

MediaLibraryService throws ForegroundServiceDidNotStartInTimeException #167

Open graymind75 opened 1 year ago

graymind75 commented 1 year ago

Media3 Version

1.0.0-beta02

Devices that reproduce the issue

Firebase crashlytics report these devices:

Devices that do not reproduce the issue

No response

Reproducible in the demo app?

Not tested

Reproduction steps

It's happened on some devices. I think It has related to MediaController not properly handling the service.

Expected result

not crash?

Actual result

Fatal Exception: android.app.ForegroundServiceDidNotStartInTimeException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{ac0645b u0 player.PlaybackService}
       at android.app.ActivityThread.throwRemoteServiceException(ActivityThread.java:2147)
       at android.app.ActivityThread.access$2900(ActivityThread.java:310)
       at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2376)
       at android.os.Handler.dispatchMessage(Handler.java:106)
       at android.os.Looper.loopOnce(Looper.java:226)
       at android.os.Looper.loop(Looper.java:313)
       at android.app.ActivityThread.main(ActivityThread.java:8669)
       at java.lang.reflect.Method.invoke(Method.java)
       at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:571)
       at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1135)

Media

-

Bug Report

vanniktech commented 1 year ago

I've also seen this in Crashlytics, although I'm myself have been unable to reproduce this.

marcbaechinger commented 1 year ago

Thanks for reporting!

Do you have some more context what command has been sent to the service when this happens?

I'm asking because I probably have found an execution path that could cause this problem, but I can not repro this and hence I can not verify a fix.

I think the reason for this could be that the pending intent of 'pause' is starting a foreground service and then does not call Service.startForeground().

I will provide a fix for the case described above. However, I can't be really sure whether this is the root case of the exception above because I can't repro now. I think it may be a corner case that sends the pause command when the service actually has been destroyed, but that's a wild guess.

You have already reported that this happens on Android 12. Can you let me know the targetSkdVersion that you use for the app that is producing the stack trace above?

vanniktech commented 1 year ago

So in my case, I have both target & compile SDK set to 33.

Screen Shot 2022-09-20 at 21 10 05

Full stacktrace:

Fatal Exception: android.app.RemoteServiceException$ForegroundServiceDidNotStartInTimeException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{ad7d394 u0 com.vanniktech.rssreader/com.vanniktech.feature.rssreader.itemdownload.RssReaderItemDownloadBackgroundService}
       at android.app.ActivityThread.generateForegroundServiceDidNotStartInTimeException(ActivityThread.java:2006)
       at android.app.ActivityThread.throwRemoteServiceException(ActivityThread.java:1977)
       at android.app.ActivityThread.-$$Nest$mthrowRemoteServiceException()
       at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2242)
       at android.os.Handler.dispatchMessage(Handler.java:106)
       at android.os.Looper.loopOnce(Looper.java:201)
       at android.os.Looper.loop(Looper.java:288)
       at android.app.ActivityThread.main(ActivityThread.java:7898)
       at java.lang.reflect.Method.invoke(Method.java)
       at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:548)
       at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:936)
graymind75 commented 1 year ago

@marcbaechinger My project is an online streaming application that streams songs. So basic commands are play/pause/seek/stop. and the targetSkdVersion is 32

This crash is reported a lot And when are we gonna get stable v1? any news?

graymind75 commented 1 year ago

EDIT I found the reason. when you play a song and then pause it and close the app the notification remains If you click on play, after a few seconds it will crash. service is not foreground but notification is not dismissed and the problem is when pressing the play button it will crash


Hi, I reproduce the crash with media session demo app here is the stack trace. I don't know if It's the exact same, but in bottom of crash it contains the ForegroundServiceDidNotStartInTimeException exception. It happens in the background playing when pressing play/pause a few times On both the Lock screen and unlocked. Also, the crash is insanely reporting in crashlytics for me!

2022-09-23 11:59:43.721 7087-7087/androidx.media3.demo.session E/AbstractFuture: RuntimeException while executing runnable androidx.media3.demo.session.MainActivity$$ExternalSyntheticLambda2@51ce0f3 with executor MoreExecutors.directExecutor()
    java.util.concurrent.CancellationException: Task was cancelled.
        at com.google.common.util.concurrent.AbstractFuture.cancellationExceptionWithCause(AbstractFuture.java:1496)
        at com.google.common.util.concurrent.AbstractFuture.getDoneValue(AbstractFuture.java:586)
        at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:547)
        at androidx.media3.demo.session.MainActivity.getBrowser(MainActivity.kt:42)
        at androidx.media3.demo.session.MainActivity.pushRoot(MainActivity.kt:160)
        at androidx.media3.demo.session.MainActivity.initializeBrowser$lambda-3(MainActivity.kt:108)
        at androidx.media3.demo.session.MainActivity.$r8$lambda$zcr2almQqmFxiCBoT1PwekCQLVg(Unknown Source:0)
        at androidx.media3.demo.session.MainActivity$$ExternalSyntheticLambda2.run(Unknown Source:2)
        at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:31)
        at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1277)
        at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:1038)
        at com.google.common.util.concurrent.AbstractFuture.cancel(AbstractFuture.java:665)
        at androidx.media3.session.MediaController.releaseFuture(MediaController.java:479)
        at androidx.media3.demo.session.MainActivity.releaseBrowser(MainActivity.kt:112)
        at androidx.media3.demo.session.MainActivity.onStop(MainActivity.kt:97)
        at android.app.Instrumentation.callActivityOnStop(Instrumentation.java:1496)
        at android.app.Activity.performStop(Activity.java:8502)
        at android.app.ActivityThread.callActivityOnStop(ActivityThread.java:5298)
        at android.app.ActivityThread.performStopActivityInner(ActivityThread.java:5278)
        at android.app.ActivityThread.handleStopActivity(ActivityThread.java:5343)
        at android.app.servertransaction.StopActivityItem.execute(StopActivityItem.java:43)
        at android.app.servertransaction.ActivityTransactionItem.execute(ActivityTransactionItem.java:45)
        at android.app.servertransaction.TransactionExecutor.executeLifecycleState(TransactionExecutor.java:176)
        at android.app.servertransaction.TransactionExecutor.execute(TransactionExecutor.java:97)
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2282)
        at android.os.Handler.dispatchMessage(Handler.java:106)
        at android.os.Looper.loopOnce(Looper.java:210)
        at android.os.Looper.loop(Looper.java:299)
        at android.app.ActivityThread.main(ActivityThread.java:8250)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:556)
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1045)
2022-09-23 11:59:43.800 7087-7087/androidx.media3.demo.session E/AbstractFuture: RuntimeException while executing runnable androidx.media3.demo.session.PlayerActivity$$ExternalSyntheticLambda3@82c155b with executor MoreExecutors.directExecutor()
    java.util.concurrent.CancellationException: Task was cancelled.
        at com.google.common.util.concurrent.AbstractFuture.cancellationExceptionWithCause(AbstractFuture.java:1496)
        at com.google.common.util.concurrent.AbstractFuture.getDoneValue(AbstractFuture.java:586)
        at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:547)
        at androidx.media3.demo.session.PlayerActivity.getController(PlayerActivity.kt:44)
        at androidx.media3.demo.session.PlayerActivity.setController(PlayerActivity.kt:128)
        at androidx.media3.demo.session.PlayerActivity.initializeController$lambda-4(PlayerActivity.kt:120)
        at androidx.media3.demo.session.PlayerActivity.$r8$lambda$_NhsfsieB1wweFfLvjToeliIJGM(Unknown Source:0)
        at androidx.media3.demo.session.PlayerActivity$$ExternalSyntheticLambda3.run(Unknown Source:2)
        at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:31)
        at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1277)
        at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:1038)
        at com.google.common.util.concurrent.AbstractFuture.cancel(AbstractFuture.java:665)
        at androidx.media3.session.MediaController.releaseFuture(MediaController.java:479)
        at androidx.media3.demo.session.PlayerActivity.releaseController(PlayerActivity.kt:124)
        at androidx.media3.demo.session.PlayerActivity.onStop(PlayerActivity.kt:102)
        at android.app.Instrumentation.callActivityOnStop(Instrumentation.java:1496)
        at android.app.Activity.performStop(Activity.java:8502)
        at android.app.ActivityThread.callActivityOnStop(ActivityThread.java:5298)
        at android.app.ActivityThread.performStopActivityInner(ActivityThread.java:5278)
        at android.app.ActivityThread.handleStopActivity(ActivityThread.java:5343)
        at android.app.servertransaction.StopActivityItem.execute(StopActivityItem.java:43)
        at android.app.servertransaction.ActivityTransactionItem.execute(ActivityTransactionItem.java:45)
        at android.app.servertransaction.TransactionExecutor.executeLifecycleState(TransactionExecutor.java:176)
        at android.app.servertransaction.TransactionExecutor.execute(TransactionExecutor.java:97)
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2282)
        at android.os.Handler.dispatchMessage(Handler.java:106)
        at android.os.Looper.loopOnce(Looper.java:210)
        at android.os.Looper.loop(Looper.java:299)
        at android.app.ActivityThread.main(ActivityThread.java:8250)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:556)
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1045)
2022-09-23 11:59:48.639 8393-8393/androidx.media3.demo.session E/AndroidRuntime: FATAL EXCEPTION: main
    Process: androidx.media3.demo.session, PID: 8393
    android.app.ForegroundServiceDidNotStartInTimeException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{73168c0 u0 androidx.media3.demo.session/.PlaybackService}
        at android.app.ActivityThread.throwRemoteServiceException(ActivityThread.java:1995)
        at android.app.ActivityThread.access$2800(ActivityThread.java:271)
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2220)
        at android.os.Handler.dispatchMessage(Handler.java:106)
        at android.os.Looper.loopOnce(Looper.java:210)
        at android.os.Looper.loop(Looper.java:299)
        at android.app.ActivityThread.main(ActivityThread.java:8250)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:556)
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1045)
marcbaechinger commented 1 year ago

Thanks for digging some further. That give me some further data points.

when you play a song and then pause it and close the app the notification remains.

Yes, indeed, these cases are always about closing the app and having only the service playing in the background. As soon as your app is in the foreground with a controller connected you are bound to the service, and you will never see such an exception.

If you click on play, after a few seconds it will crash.

With the default behaviour of the MediaSessionService (your app does not override updateNotification()), I don't think that play should produce a ForegroundServiceDidNotStartInTimeException, because after you pressed play, playWhenReady is true and the player is not STATE_IDLE which results in service.startForeground() being called. With play I would only expect a ForegroundServiceStartNotAllowedException in some cases but not when pressing PLAY on a notification on Android 12 (PendingIntent with exception) and Android 13 (MediaSession with exemption).

I still think it's the PAUSE case for which we will provide a fix.

graymind75 commented 1 year ago

Hi @marcbaechinger, When we can expect this bug fix on the repo? and any news about the next release?

marcbaechinger commented 1 year ago

This should be fixed with this commit. Please re-open if you think you still see this issue with this commit.

yschimke commented 1 year ago

I'm still a little bit concerned it's not a complete fix.

    if (Util.SDK_INT >= 26 && command == COMMAND_PLAY_PAUSE) {
    if (Util.SDK_INT >= 26
        && command == COMMAND_PLAY_PAUSE
        && !mediaSession.getPlayer().getPlayWhenReady()) {

Seems racy, the pending intent in the notification can be clicked on after something else has just toggled this.

Also do you have a test for playback stopped by suppression? I assume this will work because it's temporary and the session is still active?

marcbaechinger commented 1 year ago

Assigning to @christosts who is working on mapping commands to the MediaSessionCompat actions. The commit above restored to what we had before and has afterwards been removed by myself by mistake.

We should probably consider splitting COMMAND_PLAY_PAUSE to COMMAND_PLAY and COMMAND_PAUSE?

marcbaechinger commented 1 year ago

@yschimke This issue is about a ForegroundServiceDidNotStartInTimeException of the MediaSessionService. My understanding/hypothesis is that this is related to the first command arriving in onStartCommand as a pending intent when the service is not yet running (onCreate called immediately before onStartCommand). My understanding is based on a possibly faulty code path that I found and described above and that the exception is observed on Android 12 and 11 where the notification still sends pending intents (as opposed to Android 13). Where do you see the risk of a race condition with another intent or media session command in such a case when the service is not yet started?

By design, the service is started by creating a controller/browser and binding to the service. The service shouldn't be started by a pending intent (not Context.startForegroundService(intent)) that are only coming from the notification - which needs a running service.

For this reason, I agree that this is about a race condition or an invalid state but elsewhere (stale notification?). I couldn't repro, because I do not understand from where a pending intent for PAUSE arrives when the service is not running. When the service is stopped, the notification is removed and there shouldn't be a way to send a PAUSE intent in this case. If such an intent is sent by an app, the app is just not using the service correctly I think. Not saying this is the case, as I have no evidence that this is an app problem.

I agree that I'm not sure that this fixes the problem, but I think it removes the ForegroundServiceDidNotStartInTimeException (admittedly to the expense of another Exception that we hopefully better understand). Because in such a case of a PAUSE command when the service is not yet started, we probably now are at risk of a ForegroundStartNotAllowedException.

If you have any way to repro this ForegroundServiceDidNotStartInTimeException please let me know. I'm thankful for any input that makes me understand better how this exception is produced.

yschimke commented 1 year ago

Thanks for clarifying.

AndrazP commented 1 year ago

When can we expect a new release of the media3 library? This issue is affecting almost 2% of our users.

marcelpallares commented 1 year ago

We have many reports in Crashlytics of users facing this issue, however I believe it's not causing crashes (although they get reported as one), as I can see in our database that the users who face the crash can listen to the app audios and complete the full playback. We have not been able to reproduce it ourselves so far.

Another annoying thing is that we get different reports in Crashlytics that are not getting grouped as the same issue, and it's spamming us with many different issues that are essentially the same.

Android 12 examples:

Fatal Exception: android.app.ForegroundServiceDidNotStartInTimeException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{eac8ccc u0 xxx/.feature.player.service.PlayerService}
       at android.app.ActivityThread.throwRemoteServiceException(ActivityThread.java:2152)
       at android.app.ActivityThread.access$2800(ActivityThread.java:315)
       at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2381)
       at android.os.Handler.dispatchMessage(Handler.java:106)
       at android.os.Looper.loopOnce(Looper.java:226)
       at android.os.Looper.loop(Looper.java:313)
       at android.app.ActivityThread.main(ActivityThread.java:8751)
       at java.lang.reflect.Method.invoke(Method.java)
       at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:571)
       at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1135)

Different report, same issue:

Fatal Exception: android.app.ForegroundServiceDidNotStartInTimeException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{24fb927 u0 xxx/.feature.player.service.PlayerService}
       at android.app.ActivityThread.throwRemoteServiceException(ActivityThread.java:2147)
       at android.app.ActivityThread.access$2900(ActivityThread.java:310)
       at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2376)
       at android.os.Handler.dispatchMessage(Handler.java:106)
       at android.os.Looper.loopOnce(Looper.java:226)
       at android.os.Looper.loop(Looper.java:313)
       at android.app.ActivityThread.main(ActivityThread.java:8663)
       at java.lang.reflect.Method.invoke(Method.java)
       at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:567)
       at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1135)

Another:

Fatal Exception: android.app.RemoteServiceException$ForegroundServiceDidNotStartInTimeException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{9086cb9 u0 xxx/.feature.player.service.PlayerService}
       at android.app.ActivityThread.generateForegroundServiceDidNotStartInTimeException(ActivityThread.java:2206)
       at android.app.ActivityThread.throwRemoteServiceException(ActivityThread.java:2177)
       at android.app.ActivityThread.access$2900(ActivityThread.java:324)
       at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2435)
       at android.os.Handler.dispatchMessage(Handler.java:106)
       at android.os.Looper.loopOnce(Looper.java:226)
       at android.os.Looper.loop(Looper.java:313)
       at android.app.ActivityThread.main(ActivityThread.java:8855)
       at java.lang.reflect.Method.invoke(Method.java)
       at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:571)
       at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1135)

And many more.

Android 11 example:

Fatal Exception: android.app.RemoteServiceException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{5632ffb u0 xxx/.feature.player.service.PlayerService}
       at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2248)
       at android.os.Handler.dispatchMessage(Handler.java:106)
       at android.os.Looper.loop(Looper.java:246)
       at android.app.ActivityThread.main(ActivityThread.java:8550)
       at java.lang.reflect.Method.invoke(Method.java)
       at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:602)
       at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1130)

We have around 15 different reports of this same issue with slightly different line numbers throwing the error in the last 7 days. Do you have any insights or recommendations on what to do?

phucynwa commented 1 year ago

Any update ?

marcbaechinger commented 1 year ago

If you still see this problem please expand your comment a bit and provide some more infos to make your ask actionable. You should at least tell us the version of the library you are using (should be 1.0.0-beta03 that has the latest fixes), what OS you are running on and what is the targetSdk of your app. Then please add the evidence of the issue that you are seeing. Best is a bug report right after you see this issue. Happy to look into this, else I consider this issue fixed as per the commits above and will close.

AndrazP commented 1 year ago

Our app release with media3 updated to 1.0.0-beta03 is just being rolled out. But we already received 2 crash reports. From Pixel 6 and 7, both on Android 13. targetSdk is 33.

Fatal Exception: android.app.RemoteServiceException$ForegroundServiceDidNotStartInTimeException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{2a2abb8 u0 com.package.name/.feature.player.service.PlayerService}
       at android.app.ActivityThread.generateForegroundServiceDidNotStartInTimeException(ActivityThread.java:2006)
       at android.app.ActivityThread.throwRemoteServiceException(ActivityThread.java:1977)
       at android.app.ActivityThread.-$$Nest$mthrowRemoteServiceException(ActivityThread.java)
       at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2242)
       at android.os.Handler.dispatchMessage(Handler.java:106)
       at android.os.Looper.loopOnce(Looper.java:201)
       at android.os.Looper.loop(Looper.java:288)
       at android.app.ActivityThread.main(ActivityThread.java:7898)
       at java.lang.reflect.Method.invoke(Method.java)
       at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:548)
       at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:936)
ghost commented 1 year ago

same here with beta3 and target sdk 33. Devices are 100% samsung with android 12 and 13

for Android 13 got this stacktrace:

Fatal Exception: android.app.RemoteServiceException$ForegroundServiceDidNotStartInTimeException
Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{4d9015f u0 com.package.name/.feature.player.service.PlayerService}
android.app.ActivityThread.generateForegroundServiceDidNotStartInTimeException (ActivityThread.java:2242)
android.app.ActivityThread.throwRemoteServiceException (ActivityThread.java:2213)
android.app.ActivityThread.-$$Nest$mthrowRemoteServiceException (ActivityThread.java)
android.app.ActivityThread$H.handleMessage (ActivityThread.java:2505)
android.os.Handler.dispatchMessage (Handler.java:106)
android.os.Looper.loopOnce (Looper.java:226)
android.os.Looper.loop (Looper.java:313)
android.app.ActivityThread.main (ActivityThread.java:8741)
java.lang.reflect.Method.invoke (Method.java)
com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:571)
com.android.internal.os.ZygoteInit.main (ZygoteInit.java:1067)

and for android 12:

Fatal Exception: android.app.ForegroundServiceDidNotStartInTimeException
Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{d5a5909 u0 com.package.name/.feature.player.service.PlayerService}
android.app.ActivityThread.throwRemoteServiceException (ActivityThread.java:2147)
android.app.ActivityThread.access$2900 (ActivityThread.java:310)
android.app.ActivityThread$H.handleMessage (ActivityThread.java:2376)
android.os.Handler.dispatchMessage (Handler.java:106)
android.os.Looper.loopOnce (Looper.java:226)
android.os.Looper.loop (Looper.java:313)
android.app.ActivityThread.main (ActivityThread.java:8663)
java.lang.reflect.Method.invoke (Method.java)
com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:567)
com.android.internal.os.ZygoteInit.main (ZygoteInit.java:1135)

It occurs 100% in background and considered as a repeated crash by firebase

marcbaechinger commented 1 year ago

@AndrazP @tfighieraFreebox

Is you app using a androidx.media.session.MediaButtonReceiver? If your app is having a media button receiver, then the system may start your service and then sends an Intent with action android.intent.action.MEDIA_BUTTON.

I'm asking because in such a case the service is allowed to be started as a foreground service (ContextCompat.startForegroundService(...)) as per exemption. Your service then needs to handle that intent and immediately start playback to make the MediaNotificationManager start in the foreground.

This is a potential source for a ForegroundServiceDidNotStartInTimeException that I was just able to repro. Just adding this as for your information and investigation.

ghost commented 1 year ago

We don't use MediaButtonReceiver but we use a custom media notification provider

internal class MusicNotificationProvider(private val context: Context, private val session: MediaSession) : MediaNotification.Provider {
    private val notificationManager = context.getSystemService(Context.NOTIFICATION_SERVICE) as NotificationManager
    private val coverLoader = MusicCoverLoader() // basically use SimpleBitmapLoader()
    private val defaultCoverBitmap by lazy { ContextCompat.getDrawable(context, R.drawable.img_music)!!.toBitmap() }

    override fun createNotification(
        mediaSession: MediaSession,
        customLayout: ImmutableList<CommandButton>,
        actionFactory: ActionFactory,
        onNotificationChangedCallback: MediaNotification.Provider.Callback
    ): MediaNotification {
        ensureNotificationChannel()

        val player = mediaSession.player
        val builder = NotificationCompat.Builder(context, NOTIFICATION_CHANNEL_ID)
        val mediaStyle = MediaStyleNotificationHelper.MediaStyle(session)
        MediaNotificationCommandProvider.getMediaButtons(context, player.availableCommands, player.playWhenReady && player.isPlaying)
            .also { buttons ->
                val commandRange = List(min(buttons.size, 3)) { it } // initialize a list from 0 to N
                mediaStyle.setShowActionsInCompactView(*commandRange.toIntArray())
            }
            .forEach { commandButton ->
                if (commandButton.sessionCommand != null) {
                    actionFactory.createCustomActionFromCustomCommandButton(mediaSession, commandButton)
                } else {
                    val icon = IconCompat.createWithResource(context, commandButton.iconResId)
                    actionFactory.createMediaAction(mediaSession, icon, commandButton.displayName, commandButton.playerCommand)
                }.let(builder::addAction)
            }

        // Set metadata info in the notification.
        val metadata = player.mediaMetadata
        coverLoader.loadArtworkBitmap(metadata) { bitmap: Bitmap?, fromCache: Boolean ->
            try {
                if (bitmap == null) {
                    builder.setLargeIcon(defaultCoverBitmap)
                } else {
                    builder.setLargeIcon(bitmap)
                }
            } catch (e: ExecutionException) {
                Log.w(javaClass.simpleName, "Failed to load bitmap", e)
            }
            if (!fromCache) {
                onNotificationChangedCallback.onNotificationChanged(MediaNotification(NOTIFICATION_ID, builder.build()))
            }
        }
        val contentIntent = createHierarchy(player.currentMediaItem, player.mediaItemCount)

        val notification = builder
            .setContentTitle(metadata.title)
            .setContentText(metadata.artist)
            .setDeleteIntent(actionFactory.createMediaActionPendingIntent(mediaSession, Player.COMMAND_STOP.toLong()))
            .setOnlyAlertOnce(true)
            .setSmallIcon(smallIconResId)
            .setStyle(mediaStyle)
            .setContentIntent(contentIntent)
            .setVisibility(NotificationCompat.VISIBILITY_PUBLIC)
            .setOngoing(false)
            .build()
        return MediaNotification(NOTIFICATION_ID, notification)
    }

    private fun createHierarchy(currentMediaItem: MediaItem?, mediaItemCount: Int): PendingIntent {
        val resumeExtras = createResumeExtras(currentMediaItem, mediaItemCount)
        return NavDeepLinkBuilder(context)
            .setGraph(R.navigation.main)
            .setDestination(R.id.main)
            .setArguments(resumeExtras)
            .createPendingIntent()
    }

    private fun createResumeExtras(currentMediaItem: MediaItem?, mediaItemCount: Int): Bundle? {
        // (...)
        return null
    }

    override fun handleCustomCommand(session: MediaSession, action: String, extras: Bundle): Boolean {
        return false
    }

    private fun ensureNotificationChannel() {
        if (Build.VERSION.SDK_INT <= Build.VERSION_CODES.O || notificationManager.getNotificationChannel(NOTIFICATION_CHANNEL_ID) != null) {
            return
        }
        val channel = NotificationChannel(NOTIFICATION_CHANNEL_ID, NOTIFICATION_CHANNEL_NAME, NotificationManager.IMPORTANCE_LOW)
        notificationManager.createNotificationChannel(channel)
    }
antoineos commented 1 year ago

I found two way to reproduce the crash. With demo-session from this project (100%) :

Since onTaskRemoved is called but onDestroy is not from PlaybackService, the mediaLibrarySession is not released and mediaButtonIntent is not canceled from MediaSessionImpl.

With uamp, branch media 3 :

This case is different, onTaskRemoved and onDestroy are not called. Since uamp doesn't release MediaBrowser in Activity onStop, the service is not destroyed.

A possible solution could be a combination of the two projects. In the demo-session app, you can release the mediaLibrarySession in onTaskRemoved, and in uamp, you can release the MediaBrowserService in onStop from the Activity.

However, this solution doesn't meet my needs and seems quite fragile.

Do you see any restrictions to stop using getForegroundService in MediaSessionImpl ?

I would sugest :

Intent intent = new Intent(Intent.ACTION_MEDIA_BUTTON, sessionUri);
intent.setComponent(mbrComponent);
mediaButtonIntent = PendingIntent.getService(context, 0, intent, pendingIntentFlagMutable);
broadcastReceiver = null;

Or same approach as before media 3 :

Intent intent = new Intent(Intent.ACTION_MEDIA_BUTTON, sessionUri);
intent.setComponent(mbrComponent);
mediaButtonIntent = PendingIntent.getBroadcast(context, 0/* requestCode, ignored */, intent, pendingIntentFlagMutable);
broadcastReceiver = null;

@marcbaechinger let me know if you need a more detailed bug report.

marcbaechinger commented 1 year ago

Thanks for your report. Please add the Android version the session demo app is running on and the version of Media3 which is specifically important for this topic. I will then assume you didn't manually change the session demos targetSdkVersion.

With demo-session from this project (100%) :

- Play track
- Pause track
- Kill app
- Use a bluetooth command (e.g. play/pause from headphone)
- The app crashes after around 30 seconds.

Just for me to understand the theory. The session demo app does not use a MediaButtonReceiver. So from your understanding, what is starting the session demo app after the step Kill the app?

When you run adb shell dumpsys media_session after the step kill app, do you still see a session?

Since onTaskRemoved is called but onDestroy is not from PlaybackService,

This should not be indeed. Why do you think that onDestroy() is not called? What version of the session demo are you running? Do you still see the service not being terminated properly with the newest version? See also this comment and this commit

antoineos commented 1 year ago

I tested on Android 13 from the origin/release branch. I did not modify the code, only added some log statements.

From my understanding, since the MediaSession is not released, then the mediaButtonIntent is not cancelled, resulting in the mediaButtonIntent being the cause of the app starting.

The onDestroy() method is not called immediately after I close the app. If I send a Bluetooth command before it is called, the app crashes.

So yeah calling stopself() as you did in origin/main in onTaskremoved() solved the issue.

Additionally, my demo-session app has been crashing even though I wasn't using it and I had closed the app several hours before. I am unsure of how to reproduce this issue as I was not trying to do so

``` Logs when app crashes ``` ``` androidx.media3.demo.session ---------------------------- 2023-01-16 12:37:01.559 18892-18892 AudioMediaPlayerWrapper pid-18892 W The session was destroyed androidx.media3.demo.session 2023-01-16 12:37:01.559 18892-18892 MediaPlayerList pid-18892 D sessionUpdatedCallback(): packageName: androidx.media3.demo.session 2023-01-16 12:37:01.560 18892-18892 MediaPlayerList pid-18892 D Removing media player androidx.media3.demo.session 2023-01-16 12:37:01.560 18892-18892 MediaPlayerList pid-18892 D androidx.media3.demo.session doesn't have a browse service. Recycle player ID. 2023-01-16 12:37:01.562 4850-4850 smedia pid-4850 I SMediaSessionHelper.releaseActiveController(true): 'androidx.media3.demo.session' 2023-01-16 12:37:01.563 1529-4408 ActivityManager pid-1529 W Scheduling restart of crashed service androidx.media3.demo.session/.PlaybackService in 1000ms for start-requested 2023-01-16 12:37:01.563 4850-4850 smedia pid-4850 I SMediaSessionHelper.setActiveController(true): 'androidx.media3.demo.session' -> 'com.qobuz.music' [0] 2023-01-16 12:37:02.593 1529-1621 ActivityManager pid-1529 I Start proc 6290:androidx.media3.demo.session/u0a343 for service {androidx.media3.demo.session/androidx.media3.demo.session.PlaybackService} 2023-01-16 12:37:02.612 6290-6290 a3.demo.session pid-6290 I Late-enabling -Xcheck:jni 2023-01-16 12:37:02.668 1529-4408 ActivityManager pid-1529 W Stopping service due to app idle: u0a343 -27s89ms androidx.media3.demo.session/.PlaybackService ---------------------------- PROCESS STARTED (6290) for package androidx.media3.demo.session ---------------------------- 2023-01-16 12:37:02.708 6290-6290 ziparchive androidx.media3.demo.session W Unable to open '/data/app/~~1znDYYxwlJkA7hGgj1NJeQ==/androidx.media3.demo.session-WJZPDymZrypATPytlSBleA==/base.dm': No such file or directory 2023-01-16 12:37:02.708 6290-6290 ziparchive androidx.media3.demo.session W Unable to open '/data/app/~~1znDYYxwlJkA7hGgj1NJeQ==/androidx.media3.demo.session-WJZPDymZrypATPytlSBleA==/base.dm': No such file or directory 2023-01-16 12:37:02.844 1529-4388 PendingIntentHolder pid-1529 D Sending KeyEvent { action=ACTION_DOWN, keyCode=KEYCODE_MEDIA_PLAY, scanCode=0, metaState=0, flags=0x0, repeatCount=0, eventTime=0, downTime=0, deviceId=-1, source=0x0, displayId=0 } to the last known PendingIntent PendingIntent{b9f9cea: PendingIntentRecord{bc14bdb androidx.media3.demo.session startForegroundService}} 2023-01-16 12:37:02.849 1529-4388 ActivityManager pid-1529 I Background started FGS: Allowed [callingPackage: androidx.media3.demo.session; callingUid: 10343; uidState: SVC ; intent: Intent { act=android.intent.action.MEDIA_BUTTON dat=androidx.media3.session.MediaSessionImpl:/... flg=0x10000000 cmp=androidx.media3.demo.session/.PlaybackService (has extras) }; code:MEDIA_BUTTON; tempAllowListReason:<,reasonCode:MEDIA_BUTTON,duration:10000,callingUid:1000>; targetSdkVersion:30; callerTargetSdkVersion:30; startForegroundCount:0; bindFromPackage:null] 2023-01-16 12:37:02.890 1529-4388 PendingIntentHolder pid-1529 D Sending KeyEvent { action=ACTION_UP, keyCode=KEYCODE_MEDIA_PLAY, scanCode=0, metaState=0, flags=0x0, repeatCount=0, eventTime=0, downTime=0, deviceId=-1, source=0x0, displayId=0 } to the last known PendingIntent PendingIntent{b9f9cea: PendingIntentRecord{bc14bdb androidx.media3.demo.session startForegroundService}} 2023-01-16 12:37:02.929 6290-6290 nativeloader androidx.media3.demo.session D Configuring classloader-namespace for other apk /data/app/~~1znDYYxwlJkA7hGgj1NJeQ==/androidx.media3.demo.session-WJZPDymZrypATPytlSBleA==/base.apk. target_sdk_version=30, uses_libraries=, library_path=/data/app/~~1znDYYxwlJkA7hGgj1NJeQ==/androidx.media3.demo.session-WJZPDymZrypATPytlSBleA==/lib/arm64, permitted_path=/data:/mnt/expand:/data/user/0/androidx.media3.demo.session 2023-01-16 12:37:02.941 6290-6290 GraphicsEnvironment androidx.media3.demo.session V ANGLE Developer option for 'androidx.media3.demo.session' set to: 'default' 2023-01-16 12:37:02.942 6290-6290 GraphicsEnvironment androidx.media3.demo.session V ANGLE GameManagerService for androidx.media3.demo.session: false 2023-01-16 12:37:02.942 6290-6290 GraphicsEnvironment androidx.media3.demo.session V Neither updatable production driver nor prerelease driver is supported. 2023-01-16 12:37:02.944 6290-6290 NetworkSecurityConfig androidx.media3.demo.session D No Network Security Config specified, using platform default 2023-01-16 12:37:02.944 6290-6290 NetworkSecurityConfig androidx.media3.demo.session D No Network Security Config specified, using platform default 2023-01-16 12:37:02.945 6290-6290 MultiDex androidx.media3.demo.session I VM with version 2.1.0 has multidex support 2023-01-16 12:37:02.945 6290-6290 MultiDex androidx.media3.demo.session I Installing application 2023-01-16 12:37:02.945 6290-6290 MultiDex androidx.media3.demo.session I VM has multidex support, MultiDex support library is disabled. 2023-01-16 12:37:02.945 6290-6290 ActivityThread androidx.media3.demo.session I handleStopService: token=android.os.BinderProxy@41b3328 not found. 2023-01-16 12:37:02.954 6290-6290 MusicService: androidx.media3.demo.session I onCreate 2023-01-16 12:37:02.971 6290-6290 ExoPlayerImpl androidx.media3.demo.session I Init 21b2841 [AndroidXMedia3/1.0.0-beta03] [cheetah, Pixel 7 Pro, Google, 33] 2023-01-16 12:37:02.985 6290-6290 a3.demo.session androidx.media3.demo.session W Accessing hidden method Landroid/media/AudioTrack;->getLatency()I (unsupported, reflection, allowed) 2023-01-16 12:37:03.008 1529-1620 BroadcastQueue pid-1529 W Exported Denial: sending Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4200010 (has extras) }, action: android.net.conn.CONNECTIVITY_CHANGE from null (uid=-1) due to receiver ProcessRecord{789cd8c 6290:androidx.media3.demo.session/u0a343} (uid 10343) not specifying RECEIVER_EXPORTED 2023-01-16 12:37:03.071 6290-6290 Compatibil...geReporter androidx.media3.demo.session D Compat change id reported: 160794467; UID 10343; state: DISABLED 2023-01-16 12:37:03.086 1529-4388 MediaSessionService pid-1529 D Media button session is changed to androidx.media3.demo.session/androidx.media3.session.id. (userId=0) 2023-01-16 12:37:03.090 18892-18892 MediaPlayerList pid-18892 I Adding wrapped media player: androidx.media3.demo.session at key: 12 2023-01-16 12:37:03.090 18892-18892 MediaPlayerList pid-18892 I onMediaKeyEventSessionChanged: token=androidx.media3.demo.session 2023-01-16 12:37:03.092 18892-18892 MediaPlayerList pid-18892 D setActivePlayer(): setting player to androidx.media3.demo.session 2023-01-16 12:37:03.095 18892-18892 AudioMediaPlayerWrapper pid-18892 V onQueueChanged(): androidx.media3.demo.session tried to update with no queue 2023-01-16 12:37:03.098 18892-18892 AudioMediaPlayerWrapper pid-18892 V onPlaybackStateChanged(): androidx.media3.demo.session : PlaybackState {state=0, position=0, buffered position=0, speed=0.0, updated=77542300, actions=3669967, custom actions=[], active item id=0, error=null} 2023-01-16 12:37:03.099 18892-18892 MediaPlayerList pid-18892 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 12:37:03.099 18892-18892 MediaPlayerList pid-18892 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 12:37:03.099 6290-6290 MusicService: androidx.media3.demo.session I onDestroy 2023-01-16 12:37:03.099 6290-6290 ExoPlayerImpl androidx.media3.demo.session I Release 21b2841 [AndroidXMedia3/1.0.0-beta03] [cheetah, Pixel 7 Pro, Google, 33] [media3.common, media3.exoplayer, media3.decoder, media3.session] 2023-01-16 12:37:03.101 4850-4850 smedia pid-4850 I SMediaSessionUtils.findPlayingItem(): [1] P -> [androidx.media3.demo.session][0][null] 2023-01-16 12:37:03.102 18892-18892 MediaPlayerList pid-18892 I onMediaKeyEventSessionChanged: packageName=androidx.media3.demo.session 2023-01-16 12:37:03.102 18892-18892 MediaPlayerList pid-18892 W androidx.media3.demo.session is already the active player 2023-01-16 12:37:03.102 18892-18892 AudioMediaPlayerWrapper pid-18892 W The session was destroyed androidx.media3.demo.session 2023-01-16 12:37:03.102 18892-18892 MediaPlayerList pid-18892 D sessionUpdatedCallback(): packageName: androidx.media3.demo.session 2023-01-16 12:37:03.103 6290-6290 MusicService: androidx.media3.demo.session I onCreate 2023-01-16 12:37:03.103 1529-2784 ActivityManager pid-1529 W Service done with onDestroy, but executeNesting=2: ServiceRecord{5fb3e6a u0 androidx.media3.demo.session/.PlaybackService} 2023-01-16 12:37:03.103 6290-6290 ExoPlayerImpl androidx.media3.demo.session I Init 615b658 [AndroidXMedia3/1.0.0-beta03] [cheetah, Pixel 7 Pro, Google, 33] 2023-01-16 12:37:03.103 18892-18892 MediaPlayerList pid-18892 D Removing media player androidx.media3.demo.session 2023-01-16 12:37:03.103 18892-18892 MediaPlayerList pid-18892 D androidx.media3.demo.session doesn't have a browse service. Recycle player ID. 2023-01-16 12:37:03.110 1529-4388 MediaSessionService pid-1529 D Media button session is changed to androidx.media3.demo.session/androidx.media3.session.id. (userId=0) 2023-01-16 12:37:03.114 18892-18892 MediaPlayerList pid-18892 I Adding wrapped media player: androidx.media3.demo.session at key: 12 2023-01-16 12:37:03.114 18892-18892 MediaPlayerList pid-18892 I onMediaKeyEventSessionChanged: token=androidx.media3.demo.session 2023-01-16 12:37:03.115 18892-18892 MediaPlayerList pid-18892 D setActivePlayer(): setting player to androidx.media3.demo.session 2023-01-16 12:37:03.115 6290-6290 MusicService: androidx.media3.demo.session I onStartCommand 2023-01-16 12:37:03.117 18892-18892 MediaPlayerList pid-18892 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 12:37:03.117 18892-18892 MediaPlayerList pid-18892 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 12:37:03.118 4850-4850 smedia pid-4850 I SMediaSessionUtils.findPlayingItem(): [1] P -> [androidx.media3.demo.session][0][77542316] 2023-01-16 12:37:03.118 4850-4850 smedia pid-4850 I SMediaSessionUtils.findNonPlayingItem(): [1][androidx.media3.demo.session] META is NULL 2023-01-16 12:37:03.121 4850-4850 smedia pid-4850 I SMediaSessionUtils.findPlayingItem(): [1] P -> [androidx.media3.demo.session][0][77542316] 2023-01-16 12:37:03.122 4850-4850 smedia pid-4850 I SMediaSessionUtils.findNonPlayingItem(): [1][androidx.media3.demo.session] META is NULL 2023-01-16 12:37:03.134 6290-6290 MusicService: androidx.media3.demo.session I onStartCommand 2023-01-16 12:37:03.142 18892-18892 AudioMediaPlayerWrapper pid-18892 V onPlaybackStateChanged(): androidx.media3.demo.session : PlaybackState {state=1, position=0, buffered position=0, speed=0.0, updated=77542343, actions=3669967, custom actions=[Action:mName='Désactiver le mode aléatoire, mIcon=2131230853, mExtras=Bundle[EMPTY_PARCEL]], active item id=0, error=null} 2023-01-16 12:37:03.142 18892-18892 AudioMediaPlayerWrapper pid-18892 V trySendMediaUpdate(): Metadata has been updated for androidx.media3.demo.session 2023-01-16 12:37:03.143 1529-4388 MediaFocusControl pid-1529 I requestAudioFocus() from uid/pid 10343/6290 AA=USAGE_MEDIA/CONTENT_TYPE_UNKNOWN clientId=android.media.AudioManager@f707ab3androidx.media3.exoplayer.AudioFocusManager$AudioFocusListener@1b8f870 callingPack=androidx.media3.demo.session req=1 flags=0x0 sdk=30 2023-01-16 12:37:03.146 18892-18892 AudioMediaPlayerWrapper pid-18892 V onPlaybackStateChanged(): androidx.media3.demo.session : PlaybackState {state=1, position=0, buffered position=0, speed=0.0, updated=77542348, actions=3669967, custom actions=[Action:mName='Désactiver le mode aléatoire, mIcon=2131230853, mExtras=Bundle[EMPTY_PARCEL]], active item id=0, error=null} 2023-01-16 12:37:03.146 18892-18892 AudioMediaPlayerWrapper pid-18892 W onPlaybackStateChanged(): androidx.media3.demo.session tried to update with no new data 2023-01-16 12:37:04.611 4850-4850 smedia pid-4850 I SMediaSessionUtils.findPlayingItem(): [1] P -> [androidx.media3.demo.session][1][77542348] 2023-01-16 12:37:04.615 4850-4850 smedia pid-4850 I SMediaSessionUtils.findNonPlayingItem(): [1][androidx.media3.demo.session] META is NULL 2023-01-16 12:37:06.123 18892-18892 AudioMediaPlayerWrapper pid-18892 V onPlaybackStateChanged(): androidx.media3.demo.session : PlaybackState {state=1, position=0, buffered position=0, speed=0.0, updated=77545322, actions=3669967, custom actions=[Action:mName='Désactiver le mode aléatoire, mIcon=2131230853, mExtras=Bundle[EMPTY_PARCEL]], active item id=0, error=null} 2023-01-16 12:37:06.123 18892-18892 AudioMediaPlayerWrapper pid-18892 W onPlaybackStateChanged(): androidx.media3.demo.session tried to update with no new data 2023-01-16 12:37:07.610 4850-4850 smedia pid-4850 I SMediaSessionUtils.findPlayingItem(): [1] P -> [androidx.media3.demo.session][1][77545322] 2023-01-16 12:37:07.611 4850-4850 smedia pid-4850 I SMediaSessionUtils.findNonPlayingItem(): [1][androidx.media3.demo.session] META is NULL 2023-01-16 12:37:09.132 18892-18892 AudioMediaPlayerWrapper pid-18892 V onPlaybackStateChanged(): androidx.media3.demo.session : PlaybackState {state=1, position=0, buffered position=0, speed=0.0, updated=77548327, actions=3669967, custom actions=[Action:mName='Désactiver le mode aléatoire, mIcon=2131230853, mExtras=Bundle[EMPTY_PARCEL]], active item id=0, error=null} 2023-01-16 12:37:09.132 18892-18892 AudioMediaPlayerWrapper pid-18892 W onPlaybackStateChanged(): androidx.media3.demo.session tried to update with no new data 2023-01-16 12:37:10.625 4850-4850 smedia pid-4850 I SMediaSessionUtils.findPlayingItem(): [1] P -> [androidx.media3.demo.session][1][77548327] 2023-01-16 12:37:10.630 4850-4850 smedia pid-4850 I SMediaSessionUtils.findNonPlayingItem(): [1][androidx.media3.demo.session] META is NULL 2023-01-16 12:37:12.149 18892-18892 AudioMediaPlayerWrapper pid-18892 V onPlaybackStateChanged(): androidx.media3.demo.session : PlaybackState {state=1, position=0, buffered position=0, speed=0.0, updated=77551347, actions=3669967, custom actions=[Action:mName='Désactiver le mode aléatoire, mIcon=2131230853, mExtras=Bundle[EMPTY_PARCEL]], active item id=0, error=null} 2023-01-16 12:37:12.150 18892-18892 AudioMediaPlayerWrapper pid-18892 W onPlaybackStateChanged(): androidx.media3.demo.session tried to update with no new data 2023-01-16 12:37:13.634 4850-4850 smedia pid-4850 I SMediaSessionUtils.findPlayingItem(): [1] P -> [androidx.media3.demo.session][1][77551347] 2023-01-16 12:37:13.636 4850-4850 smedia pid-4850 I SMediaSessionUtils.findNonPlayingItem(): [1][androidx.media3.demo.session] META is NULL 2023-01-16 12:37:15.157 18892-18892 AudioMediaPlayerWrapper pid-18892 V onPlaybackStateChanged(): androidx.media3.demo.session : PlaybackState {state=1, position=0, buffered position=0, speed=0.0, updated=77554356, actions=3669967, custom actions=[Action:mName='Désactiver le mode aléatoire, mIcon=2131230853, mExtras=Bundle[EMPTY_PARCEL]], active item id=0, error=null} 2023-01-16 12:37:15.157 18892-18892 AudioMediaPlayerWrapper pid-18892 W onPlaybackStateChanged(): androidx.media3.demo.session tried to update with no new data 2023-01-16 12:37:16.638 4850-4850 smedia pid-4850 I SMediaSessionUtils.findPlayingItem(): [1] P -> [androidx.media3.demo.session][1][77554356] 2023-01-16 12:37:16.642 4850-4850 smedia pid-4850 I SMediaSessionUtils.findNonPlayingItem(): [1][androidx.media3.demo.session] META is NULL 2023-01-16 12:37:18.167 18892-18892 AudioMediaPlayerWrapper pid-18892 V onPlaybackStateChanged(): androidx.media3.demo.session : PlaybackState {state=1, position=0, buffered position=0, speed=0.0, updated=77557367, actions=3669967, custom actions=[Action:mName='Désactiver le mode aléatoire, mIcon=2131230853, mExtras=Bundle[EMPTY_PARCEL]], active item id=0, error=null} 2023-01-16 12:37:18.167 18892-18892 AudioMediaPlayerWrapper pid-18892 W onPlaybackStateChanged(): androidx.media3.demo.session tried to update with no new data 2023-01-16 12:37:19.643 4850-4850 smedia pid-4850 I SMediaSessionUtils.findPlayingItem(): [1] P -> [androidx.media3.demo.session][1][77557367] 2023-01-16 12:37:19.645 4850-4850 smedia pid-4850 I SMediaSessionUtils.findNonPlayingItem(): [1][androidx.media3.demo.session] META is NULL 2023-01-16 12:37:21.174 18892-18892 AudioMediaPlayerWrapper pid-18892 V onPlaybackStateChanged(): androidx.media3.demo.session : PlaybackState {state=1, position=0, buffered position=0, speed=0.0, updated=77560373, actions=3669967, custom actions=[Action:mName='Désactiver le mode aléatoire, mIcon=2131230853, mExtras=Bundle[EMPTY_PARCEL]], active item id=0, error=null} 2023-01-16 12:37:21.178 18892-18892 AudioMediaPlayerWrapper pid-18892 W onPlaybackStateChanged(): androidx.media3.demo.session tried to update with no new data 2023-01-16 12:37:22.659 4850-4850 smedia pid-4850 I SMediaSessionUtils.findPlayingItem(): [1] P -> [androidx.media3.demo.session][1][77560373] 2023-01-16 12:37:22.666 4850-4850 smedia pid-4850 I SMediaSessionUtils.findNonPlayingItem(): [1][androidx.media3.demo.session] META is NULL 2023-01-16 12:37:24.176 18892-18892 AudioMediaPlayerWrapper pid-18892 V onPlaybackStateChanged(): androidx.media3.demo.session : PlaybackState {state=1, position=0, buffered position=0, speed=0.0, updated=77563377, actions=3669967, custom actions=[Action:mName='Désactiver le mode aléatoire, mIcon=2131230853, mExtras=Bundle[EMPTY_PARCEL]], active item id=0, error=null} 2023-01-16 12:37:24.176 18892-18892 AudioMediaPlayerWrapper pid-18892 W onPlaybackStateChanged(): androidx.media3.demo.session tried to update with no new data 2023-01-16 12:37:25.670 4850-4850 smedia pid-4850 I SMediaSessionUtils.findPlayingItem(): [1] P -> [androidx.media3.demo.session][1][77563377] 2023-01-16 12:37:25.674 4850-4850 smedia pid-4850 I SMediaSessionUtils.findNonPlayingItem(): [1][androidx.media3.demo.session] META is NULL 2023-01-16 12:37:27.188 18892-18892 AudioMediaPlayerWrapper pid-18892 V onPlaybackStateChanged(): androidx.media3.demo.session : PlaybackState {state=1, position=0, buffered position=0, speed=0.0, updated=77566385, actions=3669967, custom actions=[Action:mName='Désactiver le mode aléatoire, mIcon=2131230853, mExtras=Bundle[EMPTY_PARCEL]], active item id=0, error=null} 2023-01-16 12:37:27.193 18892-18892 AudioMediaPlayerWrapper pid-18892 W onPlaybackStateChanged(): androidx.media3.demo.session tried to update with no new data 2023-01-16 12:37:28.684 4850-4850 smedia pid-4850 I SMediaSessionUtils.findPlayingItem(): [1] P -> [androidx.media3.demo.session][1][77566385] 2023-01-16 12:37:28.688 4850-4850 smedia pid-4850 I SMediaSessionUtils.findNonPlayingItem(): [1][androidx.media3.demo.session] META is NULL 2023-01-16 12:37:30.194 18892-18892 AudioMediaPlayerWrapper pid-18892 V onPlaybackStateChanged(): androidx.media3.demo.session : PlaybackState {state=1, position=0, buffered position=0, speed=0.0, updated=77569394, actions=3669967, custom actions=[Action:mName='Désactiver le mode aléatoire, mIcon=2131230853, mExtras=Bundle[EMPTY_PARCEL]], active item id=0, error=null} 2023-01-16 12:37:30.195 18892-18892 AudioMediaPlayerWrapper pid-18892 W onPlaybackStateChanged(): androidx.media3.demo.session tried to update with no new data 2023-01-16 12:37:31.693 4850-4850 smedia pid-4850 I SMediaSessionUtils.findPlayingItem(): [1] P -> [androidx.media3.demo.session][1][77569394] 2023-01-16 12:37:31.697 4850-4850 smedia pid-4850 I SMediaSessionUtils.findNonPlayingItem(): [1][androidx.media3.demo.session] META is NULL 2023-01-16 12:37:32.856 1529-1620 ActivityManager pid-1529 W Bringing down service while still waiting for start foreground: ServiceRecord{ccc3678 u0 androidx.media3.demo.session/.PlaybackService} 2023-01-16 12:37:32.863 6290-6290 MusicService: androidx.media3.demo.session I onDestroy 2023-01-16 12:37:32.863 6290-6290 ExoPlayerImpl androidx.media3.demo.session I Release 615b658 [AndroidXMedia3/1.0.0-beta03] [cheetah, Pixel 7 Pro, Google, 33] [media3.common, media3.exoplayer, media3.decoder, media3.session] 2023-01-16 12:37:32.879 18892-18892 MediaPlayerList pid-18892 I onMediaKeyEventSessionChanged: packageName=androidx.media3.demo.session 2023-01-16 12:37:32.879 18892-18892 MediaPlayerList pid-18892 W androidx.media3.demo.session is already the active player --------- beginning of crash 2023-01-16 12:37:32.885 6290-6290 AndroidRuntime androidx.media3.demo.session D Shutting down VM 2023-01-16 12:37:32.886 6290-6290 AndroidRuntime androidx.media3.demo.session E FATAL EXCEPTION: main Process: androidx.media3.demo.session, PID: 6290 android.app.RemoteServiceException$ForegroundServiceDidNotStartInTimeException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{ccc3678 u0 androidx.media3.demo.session/.PlaybackService} at android.app.ActivityThread.generateForegroundServiceDidNotStartInTimeException(ActivityThread.java:2005) at android.app.ActivityThread.throwRemoteServiceException(ActivityThread.java:1976) at android.app.ActivityThread.-$$Nest$mthrowRemoteServiceException(Unknown Source:0) at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2241) at android.os.Handler.dispatchMessage(Handler.java:106) at android.os.Looper.loopOnce(Looper.java:201) at android.os.Looper.loop(Looper.java:288) at android.app.ActivityThread.main(ActivityThread.java:7872) at java.lang.reflect.Method.invoke(Native Method) at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:548) at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:936) 2023-01-16 12:37:32.888 18892-18892 AudioMediaPlayerWrapper pid-18892 W The session was destroyed androidx.media3.demo.session 2023-01-16 12:37:32.888 18892-18892 MediaPlayerList pid-18892 D sessionUpdatedCallback(): packageName: androidx.media3.demo.session 2023-01-16 12:37:32.890 18892-18892 MediaPlayerList pid-18892 D Removing media player androidx.media3.demo.session 2023-01-16 12:37:32.890 18892-18892 MediaPlayerList pid-18892 D androidx.media3.demo.session doesn't have a browse service. Recycle player ID. 2023-01-16 12:37:32.895 1529-1609 ActivityManager pid-1529 I Showing crash dialog for package androidx.media3.demo.session u0 2023-01-16 12:37:32.946 1529-1609 CoreBackPreview pid-1529 D Window{332fc2d u0 Application Error: androidx.media3.demo.session}: Setting back callback OnBackInvokedCallbackInfo{mCallback=android.window.WindowOnBackInvokedDispatcher$OnBackInvokedCallbackWrapper@63483e5, mPriority=0} ```
antoineos commented 1 year ago

And to let you know, i wanted to share the log when i activate my bluetooth and the app is closed. It may explain why the app crashes after several hours.

``` Logs when bluetooth is activated ``` ``` 2023-01-16 13:20:26.084 1529-1649 AppsFilter pid-1529 I interaction: PackageSetting{7b0b2ba androidx.media3.demo.session/10343} -> PackageSetting{9e6b20d com.instagram.android/10266} BLOCKED 2023-01-16 13:20:33.189 16518-16518 AvrcpBrows...yerWrapper pid-16518 I Wrapping Media Browser androidx.media3.demo.session 2023-01-16 13:20:33.351 9925-9925 MusicService: androidx.media3.demo.session I onCreate 2023-01-16 13:20:33.351 9925-9925 ExoPlayerImpl androidx.media3.demo.session I Init 228b205 [AndroidXMedia3/1.0.0-beta03] [cheetah, Pixel 7 Pro, Google, 33] 2023-01-16 13:20:33.371 1529-3681 MediaSessionService pid-1529 D Media button session is changed to androidx.media3.demo.session/androidx.media3.session.id. (userId=0) 2023-01-16 13:20:33.376 9925-9925 MusicService: androidx.media3.demo.session I onBind 2023-01-16 13:20:33.521 16518-16518 MediaPlayerList pid-16518 I Adding wrapped media player: androidx.media3.demo.session at key: 6 2023-01-16 13:20:33.521 16518-16518 MediaPlayerList pid-16518 I onMediaKeyEventSessionChanged: token=androidx.media3.demo.session 2023-01-16 13:20:33.534 16518-16518 MediaPlayerList pid-16518 D setActivePlayer(): setting player to androidx.media3.demo.session 2023-01-16 13:20:33.559 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:33.559 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:33.563 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:33.563 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:33.567 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:33.567 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:33.572 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:33.572 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:33.589 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:33.589 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:33.651 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:33.651 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:33.689 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:33.689 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:33.721 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:33.721 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:33.777 16518-16518 AvrcpBrows...yerWrapper pid-16518 I onConnected: androidx.media3.demo.session is connected 2023-01-16 13:20:33.777 16518-16518 AvrcpBrows...rConnector pid-16518 D Browse player callback called: package=androidx.media3.demo.session : status=0 2023-01-16 13:20:33.787 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:33.787 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:33.798 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:33.798 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:33.802 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:33.802 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:33.819 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:33.819 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:33.851 16518-16518 AvrcpBrows...rConnector pid-16518 I Checking root contents for androidx.media3.demo.session 2023-01-16 13:20:33.860 9925-9925 MusicService: androidx.media3.demo.session I onDestroy 2023-01-16 13:20:33.863 9925-9925 ExoPlayerImpl androidx.media3.demo.session I Release 228b205 [AndroidXMedia3/1.0.0-beta03] [cheetah, Pixel 7 Pro, Google, 33] [media3.common, media3.exoplayer, media3.decoder, media3.session] 2023-01-16 13:20:33.974 9925-9925 MusicService: androidx.media3.demo.session I onCreate 2023-01-16 13:20:33.974 9925-9925 ExoPlayerImpl androidx.media3.demo.session I Init 3d6c7b9 [AndroidXMedia3/1.0.0-beta03] [cheetah, Pixel 7 Pro, Google, 33] 2023-01-16 13:20:33.981 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:33.981 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:34.016 16518-16518 MediaPlayerList pid-16518 I onMediaKeyEventSessionChanged: packageName=androidx.media3.demo.session 2023-01-16 13:20:34.016 16518-16518 MediaPlayerList pid-16518 W androidx.media3.demo.session is already the active player 2023-01-16 13:20:34.030 1529-4391 MediaSessionService pid-1529 D Media button session is changed to androidx.media3.demo.session/androidx.media3.session.id. (userId=0) 2023-01-16 13:20:34.040 9925-9925 MusicService: androidx.media3.demo.session I onBind 2023-01-16 13:20:34.074 16518-16518 AudioMediaPlayerWrapper pid-16518 W The session was destroyed androidx.media3.demo.session 2023-01-16 13:20:34.074 16518-16518 MediaPlayerList pid-16518 D sessionUpdatedCallback(): packageName: androidx.media3.demo.session 2023-01-16 13:20:34.080 16518-16518 MediaPlayerList pid-16518 D Removing media player androidx.media3.demo.session 2023-01-16 13:20:34.080 16518-16518 MediaPlayerList pid-16518 D androidx.media3.demo.session doesn't have a browse service. Recycle player ID. 2023-01-16 13:20:34.098 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:34.098 16518-16518 MediaPlayerList pid-16518 I Adding wrapped media player: androidx.media3.demo.session at key: 6 2023-01-16 13:20:34.098 16518-16518 MediaPlayerList pid-16518 I onMediaKeyEventSessionChanged: token=androidx.media3.demo.session 2023-01-16 13:20:34.100 16518-16518 MediaPlayerList pid-16518 D setActivePlayer(): setting player to androidx.media3.demo.session 2023-01-16 13:20:34.103 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:34.103 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:34.107 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:34.107 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:34.119 16518-16518 AvrcpBrows...yerWrapper pid-16518 I onConnected: androidx.media3.demo.session is connected 2023-01-16 13:20:34.119 16518-16518 AvrcpBrows...yerWrapper pid-16518 I getFolderItems: Connected to browsable player: androidx.media3.demo.session 2023-01-16 13:20:34.121 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:34.121 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:34.135 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:34.135 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:34.146 16518-16518 AvrcpBrows...rConnector pid-16518 I Successfully added package to results: androidx.media3.demo.session 2023-01-16 13:20:34.148 9925-9925 MusicService: androidx.media3.demo.session I onDestroy 2023-01-16 13:20:34.149 9925-9925 ExoPlayerImpl androidx.media3.demo.session I Release 3d6c7b9 [AndroidXMedia3/1.0.0-beta03] [cheetah, Pixel 7 Pro, Google, 33] [media3.common, media3.exoplayer, media3.decoder, media3.session] 2023-01-16 13:20:34.150 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:34.150 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:34.161 16518-16518 MediaPlayerList pid-16518 D onActiveSessionsChanged: controller: androidx.media3.demo.session 2023-01-16 13:20:34.161 16518-16518 MediaPlayerList pid-16518 D Already have a controller for the player: androidx.media3.demo.session, updating instead 2023-01-16 13:20:34.177 16518-16518 MediaPlayerList pid-16518 I onMediaKeyEventSessionChanged: packageName=androidx.media3.demo.session 2023-01-16 13:20:34.177 16518-16518 MediaPlayerList pid-16518 W androidx.media3.demo.session is already the active player 2023-01-16 13:20:34.177 16518-16518 AudioMediaPlayerWrapper pid-16518 W The session was destroyed androidx.media3.demo.session 2023-01-16 13:20:34.177 16518-16518 MediaPlayerList pid-16518 D sessionUpdatedCallback(): packageName: androidx.media3.demo.session 2023-01-16 13:20:34.178 16518-16518 MediaPlayerList pid-16518 D Removing media player androidx.media3.demo.session 2023-01-16 13:20:34.178 16518-16518 MediaPlayerList pid-16518 D androidx.media3.demo.session doesn't have a browse service. Recycle player ID. 2023-01-16 13:20:43.190 16518-16518 MediaPlayerList pid-16518 D Adding Browser Wrapper for androidx.media3.demo.session with id 6 ```
marcbaechinger commented 1 year ago

Thanks for the logs.

I'm not sure whether changing the media button intent to use startService is the right approach, because in the play case we actually want to start the service in the foreground. We would then run into another exception in such a case.

For your reported case documented by the logs above I think the service has been crashed by the system:

2023-01-16 12:37:01.563  1529-4408  ActivityManager         pid-1529                             W  Scheduling restart of crashed service androidx.media3.demo.session/.PlaybackService in 1000ms for start-requested

This happens because the service wasn't terminated when the user has removed the app from the list of tasks (aka. the user has killed the app). If the user does this while the service is not playing (aka the service is not in the foreground), the service needs to be properly terminated which you can do in onTaskRemoved.

I think the log line from above tells us that the user has removed the app from the list of recent apps and the ActivityManager crashes the service and restarts the service. I think then your service re-creates the session which puts the MediaButtonReceiver back in place. When the user then uses the media button on the BT headset, the session tries to start playback. The session exists but the player is still in STATE_IDLE, meaning it has an empty playlist and is not yet prepared. I conclude this from the logs at the moment when the BT command arrives that reports the session state:

2023-01-16 12:37:30.194 18892-18892 AudioMediaPlayerWrapper pid-18892                            V  onPlaybackStateChanged(): androidx.media3.demo.session : PlaybackState {state=1, position=0, buffered position=0, speed=0.0, updated=77569394, actions=3669967, custom actions=[Action:mName='Désactiver le mode aléatoire, mIcon=2131230853, mExtras=Bundle[EMPTY_PARCEL]], active item id=0, error=null}

state=1 => [STOPPED](https://developer.android.com/reference/android/support/v4/media/session/PlaybackStateCompat#STATE_STOPPED()), speed=0.0 => paused

So, the BT event now arrives and tries to start playback. If this would work, then the service is put in the foreground and we are all happy. However, the player is in state STATE_IDLE and can't start playback and accordingly the service is not put to foreground and produces the ForegroundServiceDidNotStartInTimeException that you report. I would expect this being a problem not only on Android 13 but since Android 8.

So unfortunately the answer to this report is that it's a bit more complicated and a bit more work for apps that want to support resuming playback after the app has been terminated by the user. The reasons is not that Media3 folks wants it like that, the reason is that Media3 needs to follow the platform restrictions to not make problems for apps. Full playback resumption support includes these three things:

  1. When the user terminates the app while playback being paused (while the service is not in Foreground), the service needs to be terminated.

If you see this line

2023-01-16 12:37:01.563  1529-4408  ActivityManager         pid-1529                             W  Scheduling restart of crashed service androidx.media3.demo.session/.PlaybackService in 1000ms for start-requested

something isn't well.

  1. An app that wants to support resuming playback by BT headset media button after termination, must use a MediaButtonReceiver to enable playback resumption.
  2. An app that want to support resuming playback from the notification after termination, must implement playback resumption with a MediaLibraryService/MediaBrowserService.

Summarizing this investigation I don't think there is a change in the service (like moving to an Intent from getService()) that would help. The current implementation works including playback resumption as explained above and there is no change that could make things easier for developers without running into exceptions that come from the restrictions around foreground services.

If there is a chance to make life easier for developers we are very happy to do that but as of now I don't know of such a case. Please tell me if you think differently.

marcbaechinger commented 1 year ago

In #299 the question was raised how an app can start playback when started by a BT headset play command with a media button receiver in place. In such a case the service is started with an Intent with action ACTION_MEDIA_BUTTON and an app needs to start playback to not run into a ForegroundServiceDidNotStartInTimeException.

There is currently no API for this. We are planning to add a media button receiver to Media3. When we do this we will probably add some API that makes the process easier. This is not a preview of that API, but simply a solution how apps can start playback after being started with a pending intent with action ACTION_MEDIA_BUTTON from a BT headset to avoid the ForegroundServiceDidNotStartInTimeException.

What worked for me in the session demo is the following. Roughly this includes:

  1. When the service is destroyed, the app needs to store the currently played item and the category that is playing (and probably the current playing position). It's up to the app what to store and how this is done. My sample code uses simple SharedPreferences to store and restore a basic media item.
  2. The app overrides onStartCommand and detects when the play key event is sent by the BT headset and the player has an empty playlist.
  3. In this case the app adds the last recent media to the player and returns the result of super.onStartCommand. The library will then prepare the player and call play with the first item. When this play command succeeds, the service is started in the foreground that prevents the ForegroundServiceDidNotStartInTimeException exception when started from BT headsets.
  4. Then the app can, optionally, start an async load all the items that were in the last playlist. In the code below for the demo session, the album of the lat played item is loaded. Once loaded, the items of the last playlist are added to the player (the currently playing item is untouched to not interrupt playback).

The code below shows how I implemented this as a prototype with the PlaybackService of the session demo app. This is not a recommendation of the best way to do it, but a proof of concept that worked well for me when I tested with the session demo app. If you experience the ForegroundServiceDidNotStartInTimeException when started from BT headsets, this can be a way to avoid that.

This is a minimal sample that show the idea only. You may want to persist more data like the category, the current position and the like. You also want to sanitize (eg. null-checks when restoring data) the code better than this example :)

  override fun onStartCommand(intent: Intent?, flags: Int, startId: Int): Int {
    if (isMediaButtonPlayEvent(intent) && player.mediaItemCount == 0) {
      val mediaItem = restoreLastRecentPlayedItem()
      // Set a media item here to not fall into ENDED state when the player is prepared with an empty playlist
      player.setMediaItem(mediaItem)
      scope.launch {
        // load category async
        val mediaItems = loadCategory("[artist]${mediaItem.mediaMetadata.artist}")
        // add all items of the category except the playing one is untouched to not interrupt playback
        var currentIndex = 0
        for (item in mediaItems!!) {
          if (item.mediaId == player.currentMediaItem?.mediaId) {
            break
          }
          currentIndex++
        }
        if (currentIndex > 0) {
          player.addMediaItems(0, mediaItems.subList(0, currentIndex))
        }
        if (currentIndex < mediaItems.size - 1) {
          player.addMediaItems(
            currentIndex + 1,
            mediaItems.subList(currentIndex + 1, mediaItems.size)
          )
        }
      }
    }
    return super.onStartCommand(intent, flags, startId)
  }

  private fun isMediaButtonPlayEvent(intent: Intent?): Boolean {
    intent ?: return false
    if (intent.action == Intent.ACTION_MEDIA_BUTTON) {
      val keyEvent = intent.getParcelableExtra<KeyEvent>(Intent.EXTRA_KEY_EVENT)
      if (
        keyEvent!!.keyCode == KeyEvent.KEYCODE_MEDIA_PLAY_PAUSE ||
          keyEvent.keyCode == KeyEvent.KEYCODE_MEDIA_PLAY
      ) {
        return true
      }
    }
    return false
  }

  private fun saveLastRecentPlayedItem(mediaItem: MediaItem?) {
    mediaItem ?: return
    val preferences = getSharedPreferences(RECENT_ITEM_SHARED_PREF_NAME, Context.MODE_PRIVATE)
    val editor = preferences.edit()
    editor.putString(RECENT_ITEM_SHARED_PREF_KEY_MEDIA_ID, mediaItem.mediaId)
    editor.putString(RECENT_ITEM_SHARED_PREF_KEY_URI, mediaItem.localConfiguration!!.uri.toString())
    editor.putString(RECENT_ITEM_SHARED_PREF_KEY_TITLE, mediaItem.mediaMetadata.title.toString())
    editor.putString(RECENT_ITEM_SHARED_PREF_KEY_ARTIST, mediaItem.mediaMetadata.artist.toString())
    editor.putString(
      RECENT_ITEM_SHARED_PREF_KEY_ARTWORK_URI,
      mediaItem.mediaMetadata.artworkUri.toString()
    )
    editor.apply()
  }

  private fun restoreLastRecentPlayedItem(): MediaItem {
    val preferences = getSharedPreferences(RECENT_ITEM_SHARED_PREF_NAME, Context.MODE_PRIVATE)
    val mediaUri = Uri.parse(preferences.getString(RECENT_ITEM_SHARED_PREF_KEY_URI, ""))
    val artworkUri = Uri.parse(preferences.getString(RECENT_ITEM_SHARED_PREF_KEY_ARTWORK_URI, ""))
    val mediaId =
      preferences.getString(RECENT_ITEM_SHARED_PREF_KEY_MEDIA_ID, UUID.randomUUID().toString())
    val mediaMetadata =
      MediaMetadata.Builder()
        .setTitle(preferences.getString(RECENT_ITEM_SHARED_PREF_KEY_TITLE, ""))
        .setArtist(preferences.getString(RECENT_ITEM_SHARED_PREF_KEY_ARTIST, ""))
        .setArtworkUri(artworkUri)
        .build()
    return MediaItem.Builder()
      .setUri(mediaUri)
      .setMediaId(mediaId!!)
      .setMediaMetadata(mediaMetadata)
      .build()
  }

  private suspend fun loadCategory(parentId: String): List<MediaItem>? {
    return withContext(Dispatchers.IO) {
      Thread.sleep(1_000L)
      MediaItemTree.getChildren(parentId)
    }
  }
eXaLy commented 1 year ago

Thanks for the code example.

Note that there are more potential KEYCODEs that would trigger this service as onStartCommand as well, besides KEYCODE_MEDIA_PLAY_PAUSE and KEYCODE_MEDIA_PLAY. Probably sufficient enough to check only on Intent.ACTION_MEDIA_BUTTON as action as condition.

marcbaechinger commented 1 year ago

I'm not sure I agree. I would be careful with selecting other events than play. The reason for this is that only a PLAY command will put the service into foreground. All other events will probably still result in a ForegroundServiceDidNotStartInTimeException.

I'm actually not sure where these other commands would come from. Can you clarify who you think would send such a ACTION_MEDIA_BUTTON that is not a play command when the app is not running? I haven't verified this, but I would expect that the system only delivers BT headset play commands when there is no active session. If you see that other key events are delivered to your service when the service/app is not yet started, can you please take a bug report and upload here so I can investigate this case? The reason is simply that in such a case there is not much an app can do to avoid the crash (except probably immediately terminating the service), so I'd think the system should drop all other events except play.

ziem commented 1 year ago

Not sure if someone mentioned it before, but here are the steps to reproduce ForegroundServiceDidNotStartInTimeException/ ANR: Context.startForegroundService() did not then call Service.startForeground()... in the demo-session app:

  1. Open demo-session app
  2. Click "Artist folder" then "The Kyoto Collection"
  3. Press the play button
  4. Press the pause button
  5. Hit the home button
  6. Run adb shell am kill androidx.media3.demo.session in your terminal
  7. Press play on the media notification
  8. Wait
  9. 💥
marcbaechinger commented 1 year ago

This is not a surprise. Without having tested this I think that in the scenario above onTaskRemoved is not called which is important to properly shut down the app and the service. The stale media notification still being there indicates that this is the case and the service wasn't destroyed.

Given the only way a user can terminate the app is by dismissing the activity from the recent apps, this method would be called and the app is terminated correctly. If you kill an app with adb which isn't a common way how users terminate the app, then the app is put in the inconsistent state that you describe.

The bug is that the notification is not removed and the reason for this is that the app is killed by a dev tool. I can imagine the same happens when you kill the app in the app info. There is a note that when doing this, apps may not properly work anymore.

RomanMinenok commented 1 year ago

We should do something about this or at least state in the docs about recommended way of handling the issue.

As currently it leads to dozens of crashes out of blue once an app hits production and devs have no way of expecting this behavior if they are not thinking about rare cases such as this.

Run adb shell am kill androidx.media3.demo.session in your terminal

Well, this is the way we can emulate how system kills the process due to some period of inactivity, nobody really expects users to do that.

marcbaechinger commented 1 year ago

I did the following with the session demo on SDK 29:

  1. Start the demo app and start playback of a media item
  2. Dismiss the app from the recent apps while playing
  3. In the notification I paused playback and did nothing waiting for the system to kill the process.

I got this logs (filtered for ActivityManager | ExoPlayerImpl | onDestroy) :

13:16:15.635 13771-13771 ExoPlayerImpl            I  Init 7daf441 [AndroidXMedia3/1.0.0] [generic_x86, Android SDK built for x86, Google, 29]
13:18:05.756  2021-2064  ActivityManager          W  Stopping service due to app idle: u0a153 -1m50s450ms androidx.media3.demo.session/.PlaybackService
13:18:05.766 13771-13771 onDestroy                D  onDestroy()
13:18:05.792 13771-13771 ExoPlayerImpl            I  Release 7daf441 [AndroidXMedia3/1.0.0] [generic_x86, Android SDK built for x86, Google, 29] [media3.common, media3.exoplayer, media3.decoder, media3.session, media3.datasource, media3.ui, media3.extractor]

The activity manager kills the app indeed but onDestroy of the service is called. In onDestroy the player and session are released which then removed the notification.

marcbaechinger commented 1 year ago

Doing the same as above but not waiting for the system to kill. Instead I call

adb shell am kill androidx.media3.demo.session

This gives me the service crash that is well known to lead to the stale exception. From this it seems that these two types of killing the app are not the same and in the timeout case an app can handle this gracefully like the PlaybackService does.

13:32:13.750 13771-13771 ExoPlayerImpl            I  Init 428846 [AndroidXMedia3/1.0.0] [generic_x86, Android SDK built for x86, Google, 29]
13:33:15.908  2021-3106  ActivityManager          I  Killing 13771:androidx.media3.demo.session/u0a153 (adj 905): kill background
13:33:15.925  2021-3106  ActivityManager          W  Scheduling restart of crashed service androidx.media3.demo.session/.PlaybackService in 1000ms
tobyworks commented 1 year ago

To me this is not really a solution because this is assuming that all apps that have a Browser Service and Library Service. Want apps to resume playback even when, in our case, it's a news app that also does podcasts.

If the player has never discovered the podcast feature of our app and he would press a BT Button. It doesn't make sense at all to start playing those.

I'm not sure if i get what you're saying about 'registered a receiver' afaik there is no way of registering a button receiver or deregistering it for that matter. Because if we could do that i would love to do that.

Do you know of a way to remove the registered intent from mediassession that comes up in

adb shell dumpsys media_session

Additionaly this error mainly occurs when targeting 33.

Note: for now we're investigating reverting the media3 investment because we have way to many users in production that are expierencing these crashes. 5k on a 5% rollout, which is unacceptable for a library that is marked as stable.

marcbaechinger commented 1 year ago

@tobyworks I think your issue is different from the above with the adb kill. Your case is clearly a bug that is related to attempting to restart the app with BT headset. I filed #314 for this. Media3 is registering a broadcast receiver even if an app has not implemented playback resumption. This is a bug. Instead the Media3 should remove the pending intent when the session is released. See the other bug please

AfigAliyev commented 1 year ago

@marcbaechinger,

Hi, Marc. I would like to bring to your attention that I have tested the demo-session app on a Xiaomi Redmi Note 8 (Android 11) physical device, and I encountered a ForegroundServiceDidNotStartInTimeException error when attempting to play media from a stale media notification. Additionally, I also tested the app on a Pixel 2 API 30 emulator, and while the stale notification was present but did not result in a ForegroundServiceDidNotStartInTimeException.

To reproduce the issue, please follow these steps:

  1. Launch the demo-session app.
  2. Start playing any media.
  3. Press the pause button.
  4. Press the home button to exit the app.
  5. Clear all apps from the recent apps list.
  6. Attempt to play media from the stale notification by pressing the play button.
  7. Wait for the error to occur in logcat.

Thank you for your attention to this matter.

marcbaechinger commented 1 year ago

Thanks for reporting and precise repro steps including API version! I can repro this with an emulator API 30/Android.

For context, API 30/Android 11 introduced media controls including playback resumption with a notification provided by System UI. See sections Media controls and Playback Resumption of this blog post for the legacy API. This applies if your service is exported with action android.media.browse.MediaBrowserService in the app manifest for backward compatibility.

Looks like this is an API 30 specific misbehavior that the PlaybackService of the demo app does not properly handle the attempt of System UI to provide a playback resumption notification. The 'stale notification' is actually not a notification from the demo app or the Media3 library, but a notification provided by System UI.

After adding some additional log statements I can see that System UI attempts with package com.android.systemui to initiate playback resumption:

04-23 18:03:27.970  4532  4532 I ExoPlayerImpl: Init ceb9f18 [AndroidXMedia3/1.0.1] [generic_x86, Android SDK built for x86, unknown, 30]
04-23 18:03:28.171  4532  4532 D ghi167  : onConnect: androidx.media3.demo.session
04-23 18:03:28.215  4532  4532 D ghi167  : onConnect: com.android.systemui
04-23 18:03:28.216  4532  4532 D ghi167  : onGetLibraryRoot: com.android.systemui with isRecent true
04-23 18:03:28.230  4532  4532 D ghi167  : onConnect: com.android.systemui
04-23 18:05:07.261  4742  4742 I ExoPlayerImpl: Init 44a157f [AndroidXMedia3/1.0.1] [generic_x86, Android SDK built for x86, unknown, 30]
04-23 18:05:08.289  4742  4742 D ghi167  : onConnect: androidx.media3.demo.session
04-23 18:05:08.305  4742  4742 D ghi167  : onConnect: androidx.media3.demo.session
04-23 18:05:08.312  4742  4742 D ghi167  : onGetLibraryRoot: androidx.media3.demo.session with isRecent null
04-23 18:05:54.844  4742  4742 D ghi167  : onConnect: androidx.media3.demo.session
04-23 18:05:54.851  4742  4742 D ghi167  : onGetItem: androidx.media3.demo.session with mediaId [artist]Kai Engel
04-23 18:05:57.786  4742  4742 D ghi167  : onConnect: androidx.media3.demo.session
04-23 18:05:57.881  4742  4742 D ghi167  : onConnect: com.android.systemui
04-23 18:05:57.882  4742  4742 D ghi167  : onGetLibraryRoot: com.android.systemui with isRecent true
04-23 18:05:57.902  4742  4742 D ghi167  : onConnect: com.android.systemui
04-23 18:05:57.908  4742  4742 D ghi167  : onGetLibraryRoot: com.android.systemui with isRecent true
04-23 18:06:02.443  4742  4742 I ExoPlayerImpl: Release 44a157f [AndroidXMedia3/1.0.1] [generic_x86, Android SDK built for x86, unknown, 30] [media3.common, media3.exoplayer, media3.decoder, media3.session, media3.datasource, media3.ui, media3.extractor]

// app terminated after step 5

04-23 18:06:13.500  4877  4877 I ExoPlayerImpl: Init ceb9f18 [AndroidXMedia3/1.0.1] [generic_x86, Android SDK built for x86, unknown, 30]
04-23 18:06:13.709  4877  4877 D ghi167  : onConnect: androidx.media3.demo.session
04-23 18:06:13.743  4877  4877 D ghi167  : onConnect: com.android.systemui
04-23 18:06:13.744  4877  4877 D ghi167  : onGetLibraryRoot: com.android.systemui with isRecent true
04-23 18:06:13.764  4877  4877 D ghi167  : onConnect: com.android.systemui
04-23 18:06:13.769  4877  4877 D ghi167  : receive play command from com.android.systemui
04-23 18:06:13.777  4877  4877 D ghi167  : receive play command from com.android.systemui

We can verify a few things (sorry for oversharing, it may be helpful for readers).

The log shows that the PlaybackService has been accessed by system UI to get 'recently played information'. It also shows that after the click on the play button of the 'stale notification', the system attempts a restart by creating a MediaBrowserCompat connecting against our service.

adb -s emulator-5560 shell dumpsys notification | grep -e "NotificationRecord" before and after step 5 of the repro steps to see whether the notification of the demo app package got removed.

adb -s emulator-5560 shell dumpsys media_session before and after step 5 shows that the session was released and media button receiver intent have been cleared.

Handling System UI playback resumption

To avoid problems with the observed attempts of System UI, the demo app and other apps needs to properly handle playback resumption attempts from System UI.

Currently, the session demo app does not support playback resumption and should not accept System UI's attempts to access the PlaybackService. There are various ways to do that, some that work for me with the session demo are:

  1. Apps that do not allow Android Auto or other apps to access their MediaLibraryService can set export="false" in the service in the manifest. The service is then not visible to SystemUI and it won't even try to connect:
<service
        android:name=".PlaybackService"
        android:foregroundServiceType="mediaPlayback"
        android:exported="false">
      <intent-filter>
        <action android:name="androidx.media3.session.MediaSessionService"/>
        <action android:name="android.media.browse.MediaBrowserService"/>
      </intent-filter>
    </service>
  1. Remove action android.media.browse.MediaBrowserService from service in manifest if you do not want backwards compatibility with MediaBrowserServiceCompat (for apps that only need to support Media3 controllers).

Alternatively, apps can fully implement playback resumption as documented for the legacy API or implemented by UAMP in the Media3 branch like here and here. This includes implementing resuming playback when the service is started as described fro 1.0.0 in the comment above.

We are currently working on supporting playback resumption with BT headsets and System UI notification with library support and the session demo app for 1.1.0. and documenting this on DAC.

AfigAliyev commented 1 year ago

Thanks for your detailed explanation! Just wanted to let you know that I have also tested this on Samsung Galaxy A23 (Android 13) and the stale media notification was still present. I have not had a chance to check if the ForegroundServiceDidNotStartInTimeException is there in this case.

marcbaechinger commented 1 year ago

If that still happens with the fix above, please do a bug report right after pressing the play button in the notification and then upload here. If you're unable to share bug reports publicly, please send them to dev.exoplayer@gmail.com using a subject in the format "Issue #167".

AfigAliyev commented 1 year ago

I have not checked with the fix solution yet, but I will try it and let you know.

AfigAliyev commented 1 year ago

Pixel 2 API 33 emulator.

I did not notice any stale notifications on the demo-session application. I checked it on another project. The second method made the media notification completely non-functional even during the app's runtime (it didn't respond to anything), and the stale media notification remained as well. The first and third methods did not work either, and the stale media notification persisted.

marcbaechinger commented 1 year ago

Yes, indeed. Option 2 was rubbish. Sorry. I have removed it from the comment above. The other two options work for me though.

I'll investigate how to tell System UI not to do a notification on all API levels with the isRecent contract. Will update here when I have news.

marcbaechinger commented 1 year ago

Thanks again for reporting @MaximillianLeonov . This is a bug on API 30 where the contract described in [1] is slightly different for rejecting the System UI playback resumption notification.

I have created #355 to track this.

[1] https://developer.android.com/guide/topics/media/media-controls#mediabrowserservice_implementation

s6joui commented 1 year ago

I'm on version 1.0.2. Seeing more than 100 of these crashes per day on Firebase and also getting user reports about playback randomly stopping when app is in background or phone is locked.

Mostly Samsung devices on android 13 but also seeing it for android 11 and 12.

Is there any plan to fix this?

And could the playback stopping be due to "battery optimization" settings killing the app on some of these devices? If so is there a solution for that?

graymind75 commented 1 year ago

@s6joui I'm on 1.1.0-beta01 and I have a few crashes due to this. This is a background crash, the user interacts with the notification but the application can't start playback, and the crash happens. In this comment from one of contributors there is a solution for playback resumption which helped me on some devices. But I discovered that for some Samsung devices, We have to use WakeLock to wake the device to playback actually starts playing. I don't have Samsung devices with Android 13, and 99% of crashes happen on that devices and most of them are 5G. So I couldn't test and fix this for my app.

And Yes, Battery Optimization is the reason to kill your app. You have to check with PowerManager.isIgnoringBatteryOptimizations(packageName) and if not, show a dialog and ask the user to disable Battery Optimization for your app.

PaulWoitaschek commented 1 year ago

I wonder two things:

https://github.com/androidx/media/commit/6a5ac19140253e7e78ea65745914b0746e527058

With this commit the demo now calls stopSelf in onTaskRemoved. But that alone should lead to a stale notfication as the session was never canceled (as described above). So:

  1. Shouldn't the player and session releasing not also happen in onTaskRemoved?
  2. If developers don't do that they end up with dead notifications. That means on the other hand that every developer now has to do that. In that case: Doesn't it make more sense to handle this logic in onTaskRemoved of the MediaSessionService / MediaLibraryService itself?
jackyhieu1211 commented 1 year ago

I use PlaybackService same as demo.

91% crashes on Samsung device 99%~100% crashes on android 12 and android 13

This is firebase crashlytics

Screen Shot 2023-07-09 at 12 19 58 Screen Shot 2023-07-09 at 12 23 49

I have reproduced the crash on my Samsung device

I have tried doing the debug as below and I am not getting any more crashes. You can try

 if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.S) {
            val foregroundServiceBehavior = Notification.FOREGROUND_SERVICE_IMMEDIATE
            notificationBuilder.foregroundServiceBehavior = foregroundServiceBehavior
        }

Full my code

 val notificationBuilder = NotificationCompat.Builder(context, channelId)
            .setSmallIcon(R.mipmap.icon_player_notification)
            .setColor(ContextCompat.getColor(context, R.color.colorV2BlackFilter))
            .setBadgeIconType(NotificationCompat.BADGE_ICON_LARGE)
            .setContentTitle(title)
            .setContentText(HtmlCompat.fromHtml(message, HtmlCompat.FROM_HTML_MODE_LEGACY))
            .setAutoCancel(true)
            .setSound(defaultSoundUri)
            .setDefaults(Notification.DEFAULT_ALL)
            .setPriority(NotificationCompat.PRIORITY_MAX)
            .setContentIntent(pendingIntent)

        if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.S) {
            val foregroundServiceBehavior = Notification.FOREGROUND_SERVICE_IMMEDIATE
            notificationBuilder.foregroundServiceBehavior = foregroundServiceBehavior
        }
        val notificationManager = context.getSystemService(NotificationManager::class.java)
        val channel = NotificationChannel(
            channelId, title, NotificationManager.IMPORTANCE_HIGH
        )
        notificationManager?.createNotificationChannel(channel)
        notificationManager?.notify(notificationId, notificationBuilder.build())

I will release on my app soon. I will update the latest information later Hope it's useful

s6joui commented 1 year ago

@jackyhieu1211 Thank you!! Seeing no crashes after applying your fix on our beta channel. Have you found any downsides to your fix? and also can I ask you how you managed to reproduce the crash?

jackyhieu1211 commented 1 year ago

@s6joui Have you found any downsides to your fix? : looks like Samsung removed ServiceInfo.FOREGROUND_SERVICE_TYPE_MEDIA_PLAYBACK in system device.

also can I ask you how you managed to reproduce the crash? : because I don't have a Samsung device. so i used emulator Samsung Skin (Galaxy Note10+) Link here

NOTE: If not reproducible. you can try Don't Allow Post notification permissison (For Android 13)

crash_media_player

ziem commented 1 year ago

@jackyhieu1211 where exactly did you put the code you posted above?