Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

MediaLibraryService throws ForegroundServiceDidNotStartInTimeException #167

Open
1 task
graymind75 opened this issue Sep 19, 2022 · 166 comments
Open
1 task

Comments

@graymind75
Copy link

graymind75 commented Sep 19, 2022

Media3 Version

1.0.0-beta02

Devices that reproduce the issue

Firebase crashlytics report these devices:

  • Galaxy Note20 running Android 12
  • Galaxy S21 FE 5G running Android 12
  • Xiaomi 11T Pro running Android 12
  • Redmi Note 9 Pro running Android 11

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
Copy link

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

@marcbaechinger marcbaechinger self-assigned this Sep 19, 2022
@marcbaechinger
Copy link
Contributor

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
Copy link

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
Copy link
Author

graymind75 commented Sep 21, 2022

@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
Copy link
Author

graymind75 commented Sep 23, 2022

***** 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
Copy link
Contributor

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
Copy link
Author

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

@marcbaechinger
Copy link
Contributor

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

@yschimke
Copy link
Contributor

yschimke commented Oct 3, 2022

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

This comment was marked as off-topic.

@marcbaechinger
Copy link
Contributor

@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
Copy link
Contributor

yschimke commented Oct 3, 2022

Thanks for clarifying.

marcbaechinger pushed a commit that referenced this issue Oct 17, 2022
A follow up to stopping speaker playback with a Player decorator from
#15.

It looks like we will need to change to using playback suppression to avoid
errors like #167, when we don't start
a foreground service.

We may not have this implemented by 1.0, but would like it in the API and it seems to be appropriate.

PiperOrigin-RevId: 478835686
marcbaechinger pushed a commit to google/ExoPlayer that referenced this issue Oct 20, 2022
A follow up to stopping speaker playback with a Player decorator from
androidx/media#15.

It looks like we will need to change to using playback suppression to avoid
errors like androidx/media#167, when we don't start
a foreground service.

We may not have this implemented by 1.0, but would like it in the API and it seems to be appropriate.

PiperOrigin-RevId: 478835686
@AndrazP
Copy link

AndrazP commented Oct 21, 2022

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

@marcelpallares
Copy link

marcelpallares commented Oct 26, 2022

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?

@BejanCorneliu
Copy link

BejanCorneliu commented Nov 24, 2023

@marcbaechinger thanks for replay.

Prev onPlaybackResumption() implementation was for testing ( just to see my log).

Now i'm trying to implementend like you said.
All media item data will be saved before playing, in data store preff (media url, title, subtitle..) just in case onPlaybackResumption() will be triggered
The problem now is when app is dismissed all data should be fetch from data store preff in onPlaybackResumption() ( my app is dismissed so no cache)
To load up my data from data store i need a coroutine or suspend function.

without "Thread.sleep(2000)" (which is not ok to put) betweend loadup (my data from data store preff) and return in onPlaybackResumption() i can not ensure that the media item i need to return will have valid data

Do you have any other solution?

LE : Also now i notice if i open app, play, wait for sound, pause and then dismiss app i can start only form headphones. If i tap "play" on notification nothing happens : no service restart, no onPlaybackResumption(), no sound
Play/Pause from media3 notification works only if app background/foreground. If dismissed it's not working

@marcbaechinger
Copy link
Contributor

I'm not sure I understand what the problem is I'm afraid. In case you mean that you need to load the data asynchronously to return it in onPlaybackResumption, then this shouldn't be a problem as the method returns a Future<MediaItemsWithStartPosition>, so you can do an async call and then complete the future when you have loaded the required data.

Also now i notice if i open app, play, wait for sound, pause and then dismiss app i can start only
form headphones. If i tap "play" on notification nothing happens : no service restart, no
onPlaybackResumption(), no sound Play/Pause from media3 notification works only if app
background/foreground. If dismissed it's not working

If you can repro this with the session demo app, please file another issue with reproduction steps and a bug report attached. It would be unrelated to this issue.

@adoudech
Copy link

adoudech commented Dec 7, 2023

Hello,

I'm facing the same issue when I start a media service from an automotive application. I'm using an automotive emulator API 32. The compile and the target sdk are the same 34. I'm using media3 1.2.0 version.

Steps to reproduce the ForegroundServiceDidNotStartInTimeException:

  1. Launch application from automotive OS
  2. Application launches the home screen then crash android.app.RemoteServiceException$ForegroundServiceDidNotStartInTimeException: Context.startForegroundService() did not then call Service.startForeground()
screenshot_crash_automotive

The startForegroundService is called from onCreate() in application.
Is there something that I'm doing wrong?

I remain available if you need more information about this issue.

Thank you!

@marcbaechinger
Copy link
Contributor

marcbaechinger commented Dec 8, 2023

Thanks for your report!

The Media3 Automotive Demo app works well for me with the new emulator running Android 33. I can start playback after installing.

I see an issue when I install the app again from Android Studio. In such a case the UI of the emulator doesn't seems to be happy. The service can be started though and adb shell dumpsys media_session shows confirms this.

I can't see the exception you are reporting. If you can repro this with the Automotive Demo app, please provide us with some repro steps so we can look into this.

@adoudech
Copy link

Hello, thank you for your quick answer.
I looked into the demo session automotive app and I figured out that the MediaSessionServiceListener overrides onForegroundServiceStartNotAllowedException as follows:

    override fun onForegroundServiceStartNotAllowedException() {
      if (
        Build.VERSION.SDK_INT >= 33 &&
          checkSelfPermission(Manifest.permission.POST_NOTIFICATIONS) !=
            PackageManager.PERMISSION_GRANTED
      ) {
        // Notification permission is required but not granted
        return
      }
      val notificationManagerCompat = NotificationManagerCompat.from(this@DemoPlaybackService)
      ensureNotificationChannel(notificationManagerCompat)
      val builder =
        NotificationCompat.Builder(this@DemoPlaybackService, CHANNEL_ID)
          .setSmallIcon(R.drawable.media3_notification_small_icon)
          .setContentTitle(getString(R.string.notification_content_title))
          .setStyle(
            NotificationCompat.BigTextStyle().bigText(getString(R.string.notification_content_text))
          )
          .setPriority(NotificationCompat.PRIORITY_DEFAULT)
          .setAutoCancel(true)
          .also { builder -> getBackStackedActivity()?.let { builder.setContentIntent(it) } }
      notificationManagerCompat.notify(NOTIFICATION_ID, builder.build())
    }

Can you please explain why you override this exception and why you create a notification inside?

FYI:
I tried to reproduce the issue in the demo automotive application and I was unable to reproduce it.

Thank you!

@marcbaechinger
Copy link
Contributor

marcbaechinger commented Dec 11, 2023

I tried to reproduce the issue in the demo automotive application and I was unable to reproduce it.

Thanks for confirming. Looks like an app issue rather than a problem in the library.

The startForegroundService is called from onCreate() in application.
Is there something that I'm doing wrong?

You don't have to call startForegroundService yourself.

From what you report I think that playback fails somehow when it should start playing. I would start investigating what calls you get from Automotive and then how these calls are execueyd by your service. I would expect Automotive calls Callback methods like onConnect(), onGetLibraryRoot, onGetChildren(). It will also call onAddMediaItems() or onSetMediaItems where your app needs to convert the mediaIds to actual playable MediaItems. After these calls, playback should start which puts the service into the foreground else you possibly see the exception. The last part is missing according to the ForegroundServiceDidNotStartInTimeException that you are seeing.

You need what your app does differently than the demo app. I suggest to add an EventLogger to your app so you can see what the player is actually doing when it should play.

Can you please explain why you override this exception and why you create a notification inside?

I don't think this is relevant in the case you are looking into.

This is overridden for a bug in Android 12, where a media controller that calls play when being in the background misses the exemption to start the service. The notification allows the user to continue manually in such a case.

Please note that this issue is about ForegroundServiceDidNotStartInTimeException while the code you are mentioning is about ForegroundServiceStartNotAllowedException. These are two different kind of exceptions.

@volbat
Copy link

volbat commented Dec 18, 2023

Hi!
I ran into a similar problem. Our application has about 100k users, the number of crashes with this error has increased significantly, after we migrated from MediaCompat to Media3 (in MediaCompat sometimes similar errors occurred, but they were very few, no more than 100 crashes per release).
This causes some confusion because we don't call Context.startForegroundService(), we just connect to the session according to the documentation. We use only one service, with the implementation of media3. I provide more detailed information below. In the first screenshot, all crashes are related to this problem.

Please help to solve this problem!

......

override fun onCreate() {
    super.onCreate()
    AndroidInjection.inject(this)
    initializeSessionAndPlayer()
    observeData()
}

 override fun onStartCommand(intent: Intent?, flags: Int, startId: Int): Int {
    super.onStartCommand(intent, flags, startId)
    return START_STICKY
}

 override fun onGetSession(controllerInfo: ControllerInfo): MediaLibrarySession {
    return mediaLibrarySession
}

override fun onTaskRemoved(rootIntent: Intent?) {
        mediaLibrarySession.player.stop()
        stopSelf()
}

override fun onDestroy() {
        mediaLibrarySession.setSessionActivity(getBackStackedActivity())
        mediaLibrarySession.release()
        player.release()
        clearListener()
    super.onDestroy()
}
..........


..........
  override fun initializeController() {
        browserFuture =
            MediaBrowser.Builder(
                context,
                SessionToken(context, ComponentName(context, PlaybackService::class.java))
            ).buildAsync()

        browserFuture?.addListener(
            {
                controller?.addListener(playerListener)
            },
            ContextCompat.getMainExecutor(context)
        )
}

..........

photo_5188209769767359664_y
Screenshot 2023-12-18 105255
Screenshot 2023-12-18 105422
Screenshot 2023-12-18 105640
Screenshot 2023-12-18 110749
Screenshot 2023-12-18 110841

bb4242 added a commit to dharmaseed/dharmaseed-android that referenced this issue Dec 19, 2023
For background on the issue, and why this change may help, see
androidx/media#890. I had hoped that upgrading
the Media3 library version back in #92 would completely solve the
problems we had been seeing in production. While it did help in some
ways, by eliminating `ForegroundServiceDidNotStartInTimeException`s (see
androidx/media#167), it also seems to have
morphed a lot of problems into a new form, namely App Not Responding
(ANR) problems that arise in `MiniPlayerFragment`.

The basic idea here is to reduce the rate at which we create and release
`MediaController`s in `MiniPlayerFragment`, by moving the creation and
releasing to fragment lifecycle callbacks that are invoked less
frequently than `onResume()` and `onPause()`. My hypothesis is that
rapid creation and releasing of `MediaController`s results in some kind
of race condition that is very hard to reproduce locally but will occur
in production with enough use of the app.

It's not completely clear that this PR will definitely solve the
problems we're seeing in production, but it seems like a worthwhile
experiment to try. Other than potentially decreasing the rate of ANRs,
it should not have any other noticeable effects on the behavior of the
app.
@volbat
Copy link

volbat commented Dec 26, 2023

Hello guys! Any updates on how to resolve this issue?

@marcbaechinger
Copy link
Contributor

marcbaechinger commented Dec 29, 2023

As a summary from the comments above you would need to figure out what or who is trying to attempt to start the service based on which signal that Media3 or your app is giving.

There are many reasons why this can go wrong, including Media3 bugs that have been removed as tracked in this issue. Assuming you are using the most recent release version of the library, it's difficult to tell without further information. Most advice I can give can possibly and alternatively be found in comments above.

Seeing that one crash in your stats above is happening for different vendors, makes me think something may be wrong on the app side for some edge cases. General, library things on would generate more reports I think.

A questionary would probably start somewhere in asking whether your app does declare the MediaButtonReceiver in the manifest?

If yes: do you have Callback.onPlaybackResumption implemented and does never return an empty playlist. Can playback always start when playback resumption is requested? In any case, not managing to get the player playing does result in the service not starting into the foreground with the stack trace you see above.

If no: Do you see crashes of your service that somehow leak a media button receiver configuration when the session isn't properly released? As in adb shell dumpsys media_session after these crashes that usually can be identified by ActivityManager attempting to restart a crashed service (see for instance this comment).

@johngray1965
Copy link

johngray1965 commented Jan 25, 2024

@marcbaechinger what is the proper thing to do if implementing Callback.onPlaybackResumption if we don't have the data to populate the playlist? (Note, that's a rare case, but it can happen, an example would be most recently played item was deleted).

@Digipom
Copy link

Digipom commented Feb 8, 2024

This issue is still happening on media3 1.2.1, at about roughly the same frequency as it did on 1.2.0. Here is an example stack trace:

Fatal Exception: android.app.RemoteServiceException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{962f9e3 u0 com.xyz.123/.MyService}
       at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2261)
       at android.os.Handler.dispatchMessage(Handler.java:106)
       at android.os.Looper.loop(Looper.java:246)
       at android.app.ActivityThread.main(ActivityThread.java:8645)
       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)
image

I'm using pretty much standard media3 code without any custom calls to startForegroundService.

Manifest:

 <service
            android:name=".MyService"
            android:exported="false"
            android:foregroundServiceType="mediaPlayback">
            <intent-filter>
                <action android:name="androidx.media3.session.MediaSessionService" />
            </intent-filter>
        </service>
<receiver
            android:name="androidx.media3.session.MediaButtonReceiver"
            android:exported="true">
            <intent-filter>
                <action android:name="android.intent.action.MEDIA_BUTTON" />
            </intent-filter>
        </receiver>

I don't seem to have any reports on Android 12+.

@johngray1965
Copy link

I was seeing crashes, now they are very rare. My issue was that I was implementing Callback.onPlaybackResumption, but had a bug that caused it to not reliably save the most recently played time. After I fix that, I still see a ForegroundServiceDidNotStartInTimeException occasionally, but it's really quite rare now.

@bamatson
Copy link

bamatson commented Feb 26, 2024

I've been seeing this crash for quite awhile, from at least media3 version 1.0.0-beta02 through 1.2.0 now. For what it's worth I did see a large reduction after the update from 1.1.0 to 1.2.0. It went from impacting about 5-8% of users to now ~2%.

Same stacktrace:

Fatal Exception: android.app.RemoteServiceException$ForegroundServiceDidNotStartInTimeException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{f73dbf4 u0 com.my.app/.noiseplayer.NoisePlayerService}
       at android.app.ActivityThread.generateForegroundServiceDidNotStartInTimeException(ActivityThread.java:2315)
       at android.app.ActivityThread.throwRemoteServiceException(ActivityThread.java:2286)
       at android.app.ActivityThread.-$$Nest$mthrowRemoteServiceException()
       at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2611)
       at android.os.Handler.dispatchMessage(Handler.java:106)
       at android.os.Looper.loopOnce(Looper.java:230)
       at android.os.Looper.loop(Looper.java:319)
       at android.app.ActivityThread.main(ActivityThread.java:8893)
       at java.lang.reflect.Method.invoke(Method.java)
       at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:608)
       at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1103)
Screenshot 2024-02-26 at 2 11 22 PM

Impacts Android 12+ and is pretty much exclusively a Samsung problem:

Screenshot 2024-02-26 at 2 30 43 PM Screenshot 2024-02-26 at 2 29 58 PM

My app's compile and target SDKs are 34 and I'm using media3 version 1.2.0. The app is not currently using androidx.media.session.MediaButtonReceiver.

Am I understanding correctly that implementing playback resumption may reduce instances of this crash? My app doesn't currently implement playback resumption.

@marcbaechinger
Copy link
Contributor

marcbaechinger commented Feb 27, 2024

The app is not currently using androidx.media.session.MediaButtonReceiver.

If your app is not using the receiver, then Media3 is not registering a MBR when the app is closed. So it is unclear why someone or something (System/app) attempts to restart your app this way. Similar to other cases from above, it would be important to know how and why a user on the affected devices tries to restart the app despite the app not registering itself for this.

The fix you are mentioning has removed a problem on Samsung devices as described in this comment.

If we find, how users attempt to start the app on these devices we are a step closer to remove this entirely. We haven't found this yet I'm afraid and it seems that our users don't see that either. My attempts to contact Samsung were unsuccessful I'm afraid. Happy to fix this if we get to the ground of this device-specific problem.

Am I understanding correctly that implementing playback resumption may reduce instances of this crash?

This probably can help to remove the symptom of crashes. The source of the problem on these devices is still unclear.

@TomasValenta
Copy link

I am facing a similar new crash ForegroundServiceDidNotStartInTimeException with Media3 1.2.1 from androidx.media3.session.MediaButtonReceiver.onReceive on Samsung phones:

android.app.ContextImpl.startServiceCommon (ContextImpl.java:1988)
android.app.ContextImpl.startForegroundService (ContextImpl.java:1933)
android.content.ContextWrapper.startForegroundService (ContextWrapper.java:839)
android.content.ContextWrapper.startForegroundService (ContextWrapper.java:839)
androidx.core.content.ContextCompat$Api26Impl.startForegroundService (ContextCompat.java:1189)
androidx.core.content.ContextCompat.startForegroundService (ContextCompat.java:752)
androidx.media3.session.MediaButtonReceiver.onReceive (MediaButtonReceiver.java:147)
android.app.ActivityThread.handleReceiver (ActivityThread.java:4894)
android.app.ActivityThread.-$$Nest$mhandleReceiver
android.app.ActivityThread$H.handleMessage (ActivityThread.java:2420)
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:8762)
java.lang.reflect.Method.invoke (Method.java)
com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:604)
com.android.internal.os.ZygoteInit.main (ZygoteInit.java:1067)

All the mentioned suggestions from Marc's comment 1705708010: #167 (comment) are already implemented.

I think it might be related with the fact that I don't always have something valid to playback (for example, the user has logged out in the meantime), consulted with Marc here: #770. So currently, when I have nothing valid to return, I return:

override fun onPlaybackResumption(
    mediaSession: MediaSession,
    controller: MediaSession.ControllerInfo,
): ListenableFuture<MediaSession.MediaItemsWithStartPosition> {
    try {
        val playbackResumptionData = getPlaybackResumptionData()
        if (playbackResumptionData == null) {
            return Futures.immediateFuture(MediaSession.MediaItemsWithStartPosition(emptyList(), 0, 0))
        }

        ...
    } catch (e: Exception) {
        Timber.d(e)
        return Futures.immediateFuture(MediaSession.MediaItemsWithStartPosition(emptyList(), 0, 0))
    }
}

@marcbaechinger Can Futures.immediateFuture(MediaSession.MediaItemsWithStartPosition(emptyList(), 0, 0)) cause the crash? Can I return something else (except the mentioned dummy data in the comment 1705708010)?

@johngray1965
Copy link

Yesterday I update to gradle 8.4 and the matching Android Gradle Plugin. I pushed an otherwise small change. Something with the new gradle/plugin and Futures.immediateFuture went completely south and app was completely unusable. Reverting the gradle changes fixed the issue. But Android Studio is nagging to update them. Not sure if its media3 issue with gradle issue, but the crash was decidedly in the media3, but definitely due the gradle update. @TomasValenta are you Gradle 8.4?

@icbaker
Copy link
Collaborator

icbaker commented Mar 4, 2024

@johngray1965 Please can you file a separate issue about your Gradle 8.4 upgrade issue with repro steps? e.g. are you depending on media3 via maven dependencies or using local source code?

@SiarheiSm
Copy link

It appears that when the MediaLibraryService is started, it retains the application context, preventing the application from being killed (when removed from resents). So, the next time the app is started, the application is not recreated.

@GilangJS
Copy link

Hi, our app is also producing this error on Samsung devices Android 11.

We can reproduce the issue by following #167 (comment) on the device setting and do the following steps:

  1. Minimize the app using the home button
  2. Notification controller not dismissed
  3. Press pause then play on the notification controller

We only use MediaSessionService and don't implement the media button receiver on our manifest.
When logs were added to onStartCommand it produced the following:

onStartCommand Intent { act=android.intent.action.MEDIA_BUTTON dat=androidx.media3.session.e3:/our_media_session/3364926311 cmp=com.packagename/.ourpackage.OurMediaSessionService (has extras) }

Is it normal for onStartCommand to get invoked from the media button while we didn't implement the media button receiver?

@marcbaechinger
Copy link
Contributor

marcbaechinger commented Mar 13, 2024

@GilangJS Thanks for reporting.

The intent you are seeing on Android 11 with your repro steps above is coming from the notification that Media3 posts. It's the PendingIntent that is sent from the notification. This is expected. The app is still running in that state. When this intent arrives, playback must start else the exception is thrown as you report. I guess there is something wrong when playback should resume.

In case you haven't customized the MediaSessionService this should just work. From your report I understand this is the case and it works on all other devices you've tested. TBH, the string .ourpackage.OurMediaSessionService looks a bit temporary still, so it may be an app issue as well? However, if you want me to look into this some further you can do a bug report right after this exception has been thrown. If you add an EventLogger before you do that, we can tell probably a bit more what is happening.

@kelmer44
Copy link

I think the official docs on Playback Resumption are somewhat lacking. I found it hard to understand what was required to have playback resumption on my app, and only fully grasped that onPlaybackResumption needs to be implemented and returning a non-empty playlist, after reading this 150+ comment thread (to be honest reading this summary would have sufficed, but i only know that now 🙂).

The bit where pressing play on my BT headset triggers a Foreground Notification, but media3 will only call startForeground if able to play content, is not immediately clear and I would deem that very hidden logic happening behind the scenes of a coder implementing media3.

Additionally the sentence in the docs that says:

Important: You should aim to complete the ListenableFuture as quickly as possible to keep
startup latency low.

Is a bit of an understatement, as failing to provide a workable playlist within 5 seconds will result in the dreaded ForegroundServiceDidNotStartInTimeException that is discussed here (if I have understood this correctly).

I would suggest to make this a bit clearer in the docs, which probably would have prevented a good bunch of the comments in this thread :)

@kelmer44
Copy link

kelmer44 commented Mar 20, 2024

@marcbaechinger I do have an additional question (not sure its been asked). Our media content needs authentication to be played, how are clients expected to handle the scenario in which the user exits the app (i.e. swipes) after a logout operation, and media resumption happens? If we cant return an empty playlist or UnsupportedOperation in the onPlaybackResumption callback?

@TomasValenta
Copy link

@kelmer44 Look at my question here 2 weeks ago with no answer yet and #770.

@kelmer44
Copy link

@kelmer44 Look at my question here 2 weeks ago with no answer yet and #770.

I do think this functionality should be built in because this is a legitimate use case, but in the meantime I've done it like so:

@AndroidEntryPoint
internal class RuntimeSwitchMediaButtonReceiver : BroadcastReceiver() {
    
    private val delegate: MediaButtonReceiver = MediaButtonReceiver()

    @Inject
    lateinit var applicationScope: ApplicationScope

    @Inject
    lateinit var userStateStream: Flow<UserState>

    override fun onReceive(context: Context, intent: Intent?) {
        applicationScope.launch {
            val currentUserState = userStateStream.first()

            if (currentUserState == UserState.Authenticated) {
                delegate.onReceive(context, intent)
            } else {
                Log.i { "Ignoring playback resumption due to anonymous session!" }
            }
        }
    }
}

Then of course you need to declare this receiver instead of MediaButtonReceiver.

Hope that helps.

@marcbaechinger
Copy link
Contributor

@kelmer44 Thanks for you input.

and only fully grasped that onPlaybackResumption needs to be implemented and returning a non-empty playlist,
after reading this 150+ comment thread

I'm sorry for the inconvenience caused. Given that the two steps of adding the MBR and overriding the callback is documented on the page you linked, the uncertainties come from the fact that the app needs to return a non-empty list.

I will amend our documentation to make this clear on DAC as well.

how are clients expected to handle the scenario in which the user exits the app (i.e. swipes) after a logout operation,
and media resumption happens? If we cant return an empty playlist or UnsupportedOperation in the
onPlaybackResumption callback?

This is a known weak point of the implementation. To solve this Media3 needs two changes I think:

1 - separate BT resumption and System UI notification resumption. This is required because in the case of the System UI notification, there is no API that we can use to opt-out of the notification once we have opted-in. Media3 can't do something here as the system doesn't offer such an API.

Given the inability of opting-out once opted-in, you use case of a user that logs out can't really be implemented yet. The separation would give you the option to only use BT resumption without the notification resumption.

2 - Media3 needs to add a API that allows an app to opt-in and out of playback resumption at runtime. Currently this decision is based on the static inclusion of the MediaButtonReceiver in the manifest.

With 1) and 2) in place, the answer to your question would be you can opt-out from SysUI notification and then use the runtime API to opt-out from BT resumption when the user logs out. See #770 also.

@kelmer44
Copy link

@marcbaechinger looks like we posted at the same time :)

can you check my solution in the comment above

@marcbaechinger
Copy link
Contributor

marcbaechinger commented Mar 20, 2024

Yeah, this looks like a legitimate work around an app can try when it knows that there are no items that are returned from onPlaybackResumption()(like the app has something like your userStateStream.first() to query).

I think though this doesn't help for the System UI notification which would still show and try to start service and playback? So from a library perspective we would need a runtime approach as described in #770.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests