Crash because of the foreground service did not start in time

[kevinguitar]

Media3 Version

1.0.0-beta01

Devices that reproduce the issue

Google Pixel 6, Android 13 Samsung Galaxy A32 5G, Android 12 Samsung Galaxy A13 5G, Android 12 Xiaomi POCO X3 Pro, Android 12 Samsung Galaxy A12, Android 11 Samsung Galaxy A10s, Android 11

Devices that do not reproduce the issue

Can't reproduce manually, got those stats from Crashlytics. Not sure how we can deal with this crash, do you have any idea why this crash may happen?

Reproducible in the demo app?

Not tested

Reproduction steps

We extended our playback service by your MediaSessionService, the crash happened approximately 70% in the background (stats in Crashlytics), we can't manage to reproduce it in any way.

Expected result

Actual result

There are several types of exception grouped by the Android OS, but the reason looks exactly the same

Android 11

Fatal Exception: android.app.RemoteServiceException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{bc3065 u0 com.bandlab.bandlab/com.bandlab.media.player.notification.MediaPlaybackService}
       at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2269)
       at android.os.Handler.dispatchMessage(Handler.java:106)
       at android.os.Looper.loop(Looper.java:246)
       at android.app.ActivityThread.main(ActivityThread.java:8653)
       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)

Android 12

Fatal Exception: android.app.ForegroundServiceDidNotStartInTimeException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{782cd47 u0 com.bandlab.bandlab/com.bandlab.media.player.notification.MediaPlaybackService}
       at android.app.ActivityThread.throwRemoteServiceException(ActivityThread.java:2147)
       at android.app.ActivityThread.access$2800(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)

Android 13

Fatal Exception: android.app.RemoteServiceException$ForegroundServiceDidNotStartInTimeException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{2c98e95 u0 com.bandlab.bandlab/com.bandlab.media.player.notification.MediaPlaybackService}
       at android.app.ActivityThread.generateForegroundServiceDidNotStartInTimeException(ActivityThread.java:2013)
       at android.app.ActivityThread.throwRemoteServiceException(ActivityThread.java:1984)
       at android.app.ActivityThread.-$$Nest$mthrowRemoteServiceException()
       at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2249)
       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:7929)
       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)

Media

Nothing particular, just normal audio streaming

Bug Report

• [ ] You will email the zip file produced by adb bugreport to [email protected] after filing this issue.

[kvn-stgl]

I have the same issue in my app (at least I can see it in crashlytics). But in my case, the issue is a bit stranger: It only happens at Samsung Devices and only with Android 12. The other things are identical (we can not reproduce it manually and it happens around 70% in the background). Also, the crashlog is (almost) identical (Android 12):

Fatal Exception: android.app.ForegroundServiceDidNotStartInTimeException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{4e97eb7 u0 ***}
       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)

[christosts]

Some context:

This error indicates that Context.startForegroundService() was called but Service.startForeground() was not called soon enough. The Android docs say that the second should be called within

an amount of time comparable to the ANR interval

so let's say that's 5 seconds. In beta01, Context.startForegroundService() is called when the library posts notifications itself and specifically in two cases:

1. When the user taps on the play button of the notification. The play button's PendingIntent is built with PendingIntent.getForegroundService()
2. When playback starts as a result of that. The library will call Context.startForegroundService() and immediately call Service.startForeground(). Notice that Context.startForegroundService() is called again here, because playback may have started from a BT headset button and not from the notification.

If you don't let the library post notifications, e.g. you override MediaSessionService.onUpdateNotification(), then the above will not be triggered, in which case it's a matter of how your app is handling notifications and the service lifecycle. @kevinguitar shared in #111 that they use the library notifications, but I'm mentioning this for @kvn-stgl.

If the library is posting notifications, then my investigation starting point would be if the user tapped play on the notification (1) but for some reason the player did not start playback within 5 seconds, so that the control flow reaches (2) after 5 seconds or never. This could happen if the app's main thread was busy executing other code for 5 seconds between tapping the play icon and starting playback. Or, the app has logic such that even when the play button is pressed on the notification, playback does not start, in which case (2) does not happen.

Is there a case that anything of the above is happening in your app?

[kvn-stgl]

Hi @christosts, thanks for your explanation.

We don't override the the MediaSessionService.onUpdateNotification method in our implementation. Here you can look at our implementation to get a bit more information about it: https://gist.github.com/kvn-stgl/ca019f18b9b8eab556b53b0d48c01641

I don't think there is a valid way in our app where the playback doesn't start within 5 seconds (except the internet connection is down and the exoplayer can not load the next media item from the web but I think this shouldn't be a problem here).

But I looked at the crashlog again and the crash is always direct at the beginning. So the app starts and 5 seconds later it will crash. So maybe there is some ANR at our app start which prevents foreground service. I will look a bit deeper into it.

[XuQK]

I have the same problem, it crash 10 times in a row, about ten seconds apart, the Crashlytics tell me they are all in the background. This information may be helpful.

[christosts]

I spotted a bug that occurs after the player has finished playback. The notification still shows a pause button (which does nothing) and the MediaSessionService remains in the foreground.

I don't think this is the root cause for the exceptions you are seeing reported, but I'm going to link the commit to this issue anyway since I spotted it while investigating this issue. Thank you for reports and for helping us.

[dpreussler]

We have the same issue on WearOS, all Android 11: Galaxy Watch5 Pro Galaxy Watch4 Classic Galaxy Watch4

Dont have much more info but its early in the application start

[yschimke]

Is this related https://github.com/androidx/media/issues/167?

[christosts]

Is this related #167?

Yes. I am going to close this issue, as #167 provided a fix, more on this comment. The fix will be included in the next release, if you see the issue persisting, please report here or at #167.