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
ItsBenyaamin opened this issue Sep 19, 2022 · 221 comments
Open
1 task

Comments

@ItsBenyaamin
Copy link

ItsBenyaamin 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

  • You will email the zip file produced by adb bugreport to [email protected] after filing this issue.
@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)

@ItsBenyaamin
Copy link
Author

ItsBenyaamin 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?

@ItsBenyaamin
Copy link
Author

ItsBenyaamin 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.

@ItsBenyaamin
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?

@johngray1965
Copy link

@johngray1965 does it work fine for Android 11 for you?

I do still see this some, but not on Android 11, I see on variant on 12 and another and on 13 and 14. Note, I'm audio only.

@debz-eight
Copy link

@johngray1965 Even my app is audio only. After onPlaybackResumption() implementation, my Android 11 crashes have literally disappeared. I've been monitoring for the last 10 days. But there are similar crashes related to ForegroundServiceDidNotStartInTimeException on majorly Samsung's Android 14.

After looking at stacktraces, logs and breadcrumbs, my speculation is that it is being caused by some dead notification of some sort.

@debz-eight
Copy link

@XilinJia I tried 6.5.7 a whole ago, kept playing some audio for the last 40 mins, did not face a crash on Samsung Android 14 and AOSP Android 14.

@johngray1965
Copy link

@debz-eight Some of mine may be from dead notification, but many of mine are coming in from MediaControllerButton and the app is in the background. I suppose I can work around them by playing silence. Though I'm not really sure what use case is causing this. I try to always find something to play.

@kelmer44
Copy link

kelmer44 commented Sep 8, 2024

With Samsung devices using Android 14, have you tried hitting play after pulling up the system menu and selecting media output (your last media session should be that of your app)? That triggers the resumption route as well, and I believe might be the source of your crashes?

@kelmer44
Copy link

kelmer44 commented Sep 8, 2024

@debz-eight Some of mine may be from dead notification, but many of mine are coming in from MediaControllerButton and the app is in the background. I suppose I can work around them by playing silence. Though I'm not really sure what use case is causing this. I try to always find something to play.

I play silent audio and the biggest issue is that the media notification stays for a little while

@debz-eight
Copy link

WhatsApp.Video.2024-09-08.at.19.48.49_e5b92c2e.mp4

@kelmer44 Are you referring to this? The playback resumption seems to work fine when the app is not in background.

@kelmer44
Copy link

kelmer44 commented Sep 8, 2024

WhatsApp.Video.2024-09-08.at.19.48.49_e5b92c2e.mp4
@kelmer44 Are you referring to this? The playback resumption seems to work fine when the app is not in background.

Yeah that used to give me trouble when testing with Samsung devices, glad it's not your case

@XilinJia
Copy link

XilinJia commented Sep 8, 2024

@XilinJia I tried 6.5.7 a whole ago, kept playing some audio for the last 40 mins, did not face a crash on Samsung Android 14 and AOSP Android 14.

As I said, it doesn't happen all the time. The most likely case is during construction of mediaItem/mediaSource there is some delay (due to network issue for instance), as I sometimes experience in a remote area.

@debz-eight
Copy link

@debz-eight Some of mine may be from dead notification, but many of mine are coming in from MediaControllerButton and the app is in the background. I suppose I can work around them by playing silence. Though I'm not really sure what use case is causing this. I try to always find something to play.

I play silent audio and the biggest issue is that the media notification stays for a little while

How are you doing this exactly? I am thinking of implementing the same.

@debz-eight
Copy link

@kelmer44

What I just implemented now is:

Inside my PlayerService.kt, when I am creating the player instance I am using setMediaSource(1msMediaSource) followed by player.prepare(), player.playWhenReady = true and player.clearMediaItems().

If I am not doing player.clearMediaItems(), then if the user immediately starts playing anything as soon as the app opens, it is causing me IndexOutOfBoundException.

Since I cannot reproduce the issue myself, I guess I'll have to test by pushing this to playstore and monitoring.

@kelmer44
Copy link

kelmer44 commented Sep 9, 2024

My app plays live audio so locally caching is not possible. I can't rely on returning anything on the SettableFuture that onPlaybackResumption expects, also because my urls are expiring/have expiring auth tokens.

Additionally my whole pipeline is quite complex and I'd rather just rely on my regular playback pipeline rather than creating a specific one just for resumption. IMO this is why the resumption mechanism is flawed as it is right now; it assumes an app can always play stuff by resolving it locally within the playback resumption function into a list of mediaItems, but apps are sometimes more complex than that.

So what I do is i call the withTimeout suspend function and set that timeout to something lower than the time allotted for an app to call startService after startForegroundService has been called internally by media3 (which is around 5 seconds). I then instruct my app to resume the last played item, and if exoPlayer doesn't report Playing state within that timeout (or any other exception happens), I will return the settableFuture with a playlist with just a silent 0.5sec mp3. As i said the media notification does show up for a while (around 1 minute) so I put ID3 tags with relevant test for my users.

@kelmer44
Copy link

kelmer44 commented Sep 17, 2024

Looks like 1.5.0 alpha01 already facilitates more control over when playback resumption happens

Add MediaButtonReceiver.shouldStartForegroundService(Intent) to allow apps to suppress a play command coming in for playback resumption by overriding this method. By default, the service is always started and playback can't be suppressed without the system crashing the service with a ForegroundServiceDidNotStartInTimeException (google/ExoPlayer#1528).

(I think the linked issue is unrelated BTW)

https://github.com/androidx/media/releases/tag/1.5.0-alpha01

@ksvslk
Copy link

ksvslk commented Sep 24, 2024

Is it an implementation issue, Samsung issue or library issue?

I've improved where I can and solved some of the similar exceptions but I'm out of ideas and cannot reproduce this one:
From the stack I think the MediaButtonReceiver seems to be the problem now for the Samsung devices with Android 13 & 14?

android.app.StackTrace: Last startServiceCommon() call for this service was made here
    at android.app.ContextImpl.startServiceCommon(ContextImpl.java:2023)
    at android.app.ContextImpl.startForegroundService(ContextImpl.java:1967)
    at android.content.ContextWrapper.startForegroundService(ContextWrapper.java:847)
    at android.content.ContextWrapper.startForegroundService(ContextWrapper.java:847)
    at androidx.core.content.ContextCompat$Api26Impl.startForegroundService(ContextCompat.java:1128)
    at androidx.core.content.ContextCompat.startForegroundService(ContextCompat.java:700)
    at androidx.media3.session.MediaButtonReceiver.onReceive(MediaButtonReceiver.java:148)
    at android.app.ActivityThread.handleReceiver(ActivityThread.java:4896)
    at android.app.ActivityThread.-$$Nest$mhandleReceiver
    at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2498)
    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:8919)
    at java.lang.reflect.Method.invoke(Method.java)
    at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:578)
    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1103)
android.app.RemoteServiceException$ForegroundServiceDidNotStartInTimeException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{17bbbec u0 my.AudioService}
    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:8919)
    at java.lang.reflect.Method.invoke(Method.java)
    at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:578)
    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1103)
   

I am using MediaSessionService - was there an issue with that and it has no errors with MediaLibraryService?
Also I read that there might be an issue resuming with Bluetooth devices?

It would be great to know where should I dig into...

@marcbaechinger
Copy link
Contributor

Is it an implementation issue, Samsung issue or library issue?
MediaButtonReceiver seems to be the problem now for the Samsung devices with Android 13 & 14

The stack trace shows that MediaButtonReceiver was called when the session wasn't active. For this specific case, I don't think it's relevant why this happens (BT or something else that is triggering playback resumption (aka sending a PLAY key event)).

Above API 26 and without modifications on the MediaButtonReceiver the service is only started for a PLAY command (see here).

Then the service is started and the play command is delivered. The service then must start playback, else a ForegroundServiceDidNotStartInTimeException is thrown.

I think we need to figure out why playback does not start for the app - if you can make playback start after the MediaButtonReceiver started the service, the problem goes away.

I am using MediaSessionService - was there an issue with that and it has no errors with MediaLibraryService?

Don't think so. They are both using the same implementation.

@ksvslk
Copy link

ksvslk commented Sep 24, 2024

Is it an implementation issue, Samsung issue or library issue?
MediaButtonReceiver seems to be the problem now for the Samsung devices with Android 13 & 14

The stack trace shows that MediaButtonReceiver was called when the session wasn't active. For this specific case, I don't think it's relevant why this happens (BT or something else that is triggering playback resumption (aka sending a PLAY key event)).

Above API 26 and without modifications on the MediaButtonReceiver the service is only started for a PLAY command (see here).

Then the service is started and the play command is delivered. The service then must start playback, else a ForegroundServiceDidNotStartInTimeException is thrown.

I think we need to figure out why playback does not start for the app - if you can make playback start after the MediaButtonReceiver started the service, the problem goes away.

I am using MediaSessionService - was there an issue with that and it has no errors with MediaLibraryService?

Don't think so. They are both using the same implementation.

The first case that comes to mind - why the playback cannot start - is that there is no internet or poor connection (the content is mostly streams). Or is that case handled by the player?

Otherwise - I have to think of all the cases where the playback cannot start and not only from onPlaybackResumption, but overall. Is this correct?

@marcbaechinger
Copy link
Contributor

marcbaechinger commented Sep 24, 2024

The first case that comes to mind - why the playback cannot start - is that there
is no internet or poor connection (the content is mostly streams). Or is that case handled by the player?

The session start the service into foreground if the player state is either STATE_BUFFERING or STATE_PLAYING. When playback resumption is triggered and the app returns a valid MediaItem from Callback.onPlaybackResumption(), then the media item is set to the player and prepare is called. Given you are using ExoPlayer, ExoPlayer immediately transitions into STATE_BUFFERING upon a call to prepare(). From this (and without trying), Id' think no internet connection or a slow response shouldn't be an issue. I need to test this myself though and see whether my guess can be verified. If this doesn't work, I think we should see whether we can make things more robust.

We are aware that the model isn't really bullet-proof for the cases when an app doesn't have a media item to play (there are various valid reasons apps may have for this). We should revisit this to make the solution more flexible (see point 3. below) but I can't give you a timeline for this I'm afraid.

Steps to achieve by apps and library:

  1. It's important to start playback for the cases when playback resumption is triggered. This is mainly about implementing 'Callback.onPlaybackResumption()` (https://developer.android.com/media/media3/session/background-playback#resumption).
  2. If an app is able to determine that it can't play at the moment playback resumption is requested, we have added a method MediaButtonReceiver.shouldStartForegroundService() in 1.5.0-alpha. An app can then override this method and avoid that the service is attempted to start.
  3. The library should allow apps to opt-in and opt-out from playback resumption at runtime. So that 2. isn't needed anymore because playback resumption can be withdrawn.

@marcbaechinger
Copy link
Contributor

Just confirming my guess from above. When opted-in to playback resumption by adding the MediaButtonReceiver to the manifest and having overridden onPlaybackResumption() that returns a media item with a URI that produced a 404, the service is put into the foreground as expected and doesn't cause a ForegroundServiceDidNotStartInTimeException.

Hence a playback error wouldn't cause this issue. See below how the player goes into BUFFERING state which is sufficient even when we never transition into STATE_READY. The same applied when the device is in airplane mode and doesn't have internet at all. This equaly results in a playback error but after transitioning into BUFFERING state.

14:53:02.630  D  mediaItem [eventTime=0.15, mediaPos=0.00, window=0, reason=PLAYLIST_CHANGED]
14:53:02.634  D  state [eventTime=0.16, mediaPos=0.00, window=0, BUFFERING]
14:53:02.638  D  playWhenReady [eventTime=0.16, mediaPos=0.00, window=0, true, USER_REQUEST]
14:53:02.662  D  loading [eventTime=0.18, mediaPos=0.00, window=0, period=0, true]
14:53:02.662  D  tagSocket(115) with statsTag=0xffffffff, statsUid=-1
14:53:02.663  D  timeline [eventTime=0.19, mediaPos=0.00, window=0, period=0, periodCount=1, windowCount=1, reason=SOURCE_UPDATE
14:53:02.663  D    period [?]
14:53:02.663  D    window [?, seekable=false, dynamic=false]
14:53:02.663  D  ]
14:53:02.840  E  internalError [eventTime=0.36, mediaPos=0.00, window=0, period=0, loadError
                   androidx.media3.datasource.HttpDataSource$InvalidResponseCodeException: Response code: 404
                       at androidx.media3.datasource.DefaultHttpDataSource.open(DefaultHttpDataSource.java:395)
                       at androidx.media3.datasource.DefaultDataSource.open(DefaultDataSource.java:275)
                       at androidx.media3.datasource.StatsDataSource.open(StatsDataSource.java:86)
                       at androidx.media3.exoplayer.source.ProgressiveMediaPeriod$ExtractingLoadable.load(ProgressiveMediaPeriod.java:1058)
                       at androidx.media3.exoplayer.upstream.Loader$LoadTask.run(Loader.java:450)
                       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
                       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
                       at java.lang.Thread.run(Thread.java:1117)
                 ]
14:53:02.908  E  internalError [eventTime=0.43, mediaPos=0.00, window=0, period=0, loadError
                   androidx.media3.datasource.HttpDataSource$InvalidResponseCodeException: Response code: 404
                       at androidx.media3.datasource.DefaultHttpDataSource.open(DefaultHttpDataSource.java:395)
                       at androidx.media3.datasource.DefaultDataSource.open(DefaultDataSource.java:275)
                       at androidx.media3.datasource.StatsDataSource.open(StatsDataSource.java:86)
                       at androidx.media3.exoplayer.source.ProgressiveMediaPeriod$ExtractingLoadable.load(ProgressiveMediaPeriod.java:1058)
                       at androidx.media3.exoplayer.upstream.Loader$LoadTask.run(Loader.java:450)
                       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
                       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
                       at java.lang.Thread.run(Thread.java:1117)
                 ]
14:53:03.976  E  internalError [eventTime=1.50, mediaPos=0.00, window=0, period=0, loadError
                   androidx.media3.datasource.HttpDataSource$InvalidResponseCodeException: Response code: 404
                       at androidx.media3.datasource.DefaultHttpDataSource.open(DefaultHttpDataSource.java:395)
                       at androidx.media3.datasource.DefaultDataSource.open(DefaultDataSource.java:275)
                       at androidx.media3.datasource.StatsDataSource.open(StatsDataSource.java:86)
                       at androidx.media3.exoplayer.source.ProgressiveMediaPeriod$ExtractingLoadable.load(ProgressiveMediaPeriod.java:1058)
                       at androidx.media3.exoplayer.upstream.Loader$LoadTask.run(Loader.java:450)
                       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
                       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
                       at java.lang.Thread.run(Thread.java:1117)
                 ]
14:53:06.045  E  Playback error
                   androidx.media3.exoplayer.ExoPlaybackException: Source error
                       at androidx.media3.exoplayer.ExoPlayerImplInternal.handleIoException(ExoPlayerImplInternal.java:745)
                       at androidx.media3.exoplayer.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:717)
                       at android.os.Handler.dispatchMessage(Handler.java:103)
                       at android.os.Looper.loopOnce(Looper.java:232)
                       at android.os.Looper.loop(Looper.java:317)
                       at android.os.HandlerThread.run(HandlerThread.java:85)
                   Caused by: androidx.media3.datasource.HttpDataSource$InvalidResponseCodeException: Response code: 404
                       at androidx.media3.datasource.DefaultHttpDataSource.open(DefaultHttpDataSource.java:395)
                       at androidx.media3.datasource.DefaultDataSource.open(DefaultDataSource.java:275)
                       at androidx.media3.datasource.StatsDataSource.open(StatsDataSource.java:86)
                       at androidx.media3.exoplayer.source.ProgressiveMediaPeriod$ExtractingLoadable.load(ProgressiveMediaPeriod.java:1058)
                       at androidx.media3.exoplayer.upstream.Loader$LoadTask.run(Loader.java:450)
                       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
                       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
                       at java.lang.Thread.run(Thread.java:1117)
14:53:06.047  E  internalError [eventTime=3.57, mediaPos=0.00, window=0, period=0, loadError
                   androidx.media3.datasource.HttpDataSource$InvalidResponseCodeException: Response code: 404
                       at androidx.media3.datasource.DefaultHttpDataSource.open(DefaultHttpDataSource.java:395)
                       at androidx.media3.datasource.DefaultDataSource.open(DefaultDataSource.java:275)
                       at androidx.media3.datasource.StatsDataSource.open(StatsDataSource.java:86)
                       at androidx.media3.exoplayer.source.ProgressiveMediaPeriod$ExtractingLoadable.load(ProgressiveMediaPeriod.java:1058)
                       at androidx.media3.exoplayer.upstream.Loader$LoadTask.run(Loader.java:450)
                       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
                       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
                       at java.lang.Thread.run(Thread.java:1117)
                 ]
14:53:06.050  E  playerFailed [eventTime=3.57, mediaPos=0.00, window=0, period=0, errorCode=ERROR_CODE_IO_BAD_HTTP_STATUS
                   androidx.media3.exoplayer.ExoPlaybackException: Source error
                       at androidx.media3.exoplayer.ExoPlayerImplInternal.handleIoException(ExoPlayerImplInternal.java:745)
                       at androidx.media3.exoplayer.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:717)
                       at android.os.Handler.dispatchMessage(Handler.java:103)
                       at android.os.Looper.loopOnce(Looper.java:232)
                       at android.os.Looper.loop(Looper.java:317)
                       at android.os.HandlerThread.run(HandlerThread.java:85)
                   Caused by: androidx.media3.datasource.HttpDataSource$InvalidResponseCodeException: Response code: 404
                       at androidx.media3.datasource.DefaultHttpDataSource.open(DefaultHttpDataSource.java:395)
                       at androidx.media3.datasource.DefaultDataSource.open(DefaultDataSource.java:275)
                       at androidx.media3.datasource.StatsDataSource.open(StatsDataSource.java:86)
                       at androidx.media3.exoplayer.source.ProgressiveMediaPeriod$ExtractingLoadable.load(ProgressiveMediaPeriod.java:1058)
                       at androidx.media3.exoplayer.upstream.Loader$LoadTask.run(Loader.java:450)
                       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
                       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
                       at java.lang.Thread.run(Thread.java:1117)
                 ]

@ksvslk
Copy link

ksvslk commented Sep 24, 2024

Just confirming my guess from above. When opted-in to playback resumption by adding the MediaButtonReceiver to the manifest and having overridden onPlaybackResumption() that returns a media item with a URI that produced a 404, the service is put into the foreground as expected and doesn't cause a ForegroundServiceDidNotStartInTimeException.

Hence a playback error wouldn't cause this issue. See below how the player goes into BUFFERING state which is sufficient even when we never transition into STATE_READY. The same applied when the device is in airplane mode and doesn't have internet at all. This equaly results in a playback error but after transitioning into BUFFERING state.

14:53:02.630  D  mediaItem [eventTime=0.15, mediaPos=0.00, window=0, reason=PLAYLIST_CHANGED]
14:53:02.634  D  state [eventTime=0.16, mediaPos=0.00, window=0, BUFFERING]
14:53:02.638  D  playWhenReady [eventTime=0.16, mediaPos=0.00, window=0, true, USER_REQUEST]
14:53:02.662  D  loading [eventTime=0.18, mediaPos=0.00, window=0, period=0, true]
14:53:02.662  D  tagSocket(115) with statsTag=0xffffffff, statsUid=-1
14:53:02.663  D  timeline [eventTime=0.19, mediaPos=0.00, window=0, period=0, periodCount=1, windowCount=1, reason=SOURCE_UPDATE
14:53:02.663  D    period [?]
14:53:02.663  D    window [?, seekable=false, dynamic=false]
14:53:02.663  D  ]
14:53:02.840  E  internalError [eventTime=0.36, mediaPos=0.00, window=0, period=0, loadError
                   androidx.media3.datasource.HttpDataSource$InvalidResponseCodeException: Response code: 404
                       at androidx.media3.datasource.DefaultHttpDataSource.open(DefaultHttpDataSource.java:395)
                       at androidx.media3.datasource.DefaultDataSource.open(DefaultDataSource.java:275)
                       at androidx.media3.datasource.StatsDataSource.open(StatsDataSource.java:86)
                       at androidx.media3.exoplayer.source.ProgressiveMediaPeriod$ExtractingLoadable.load(ProgressiveMediaPeriod.java:1058)
                       at androidx.media3.exoplayer.upstream.Loader$LoadTask.run(Loader.java:450)
                       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
                       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
                       at java.lang.Thread.run(Thread.java:1117)
                 ]
14:53:02.908  E  internalError [eventTime=0.43, mediaPos=0.00, window=0, period=0, loadError
                   androidx.media3.datasource.HttpDataSource$InvalidResponseCodeException: Response code: 404
                       at androidx.media3.datasource.DefaultHttpDataSource.open(DefaultHttpDataSource.java:395)
                       at androidx.media3.datasource.DefaultDataSource.open(DefaultDataSource.java:275)
                       at androidx.media3.datasource.StatsDataSource.open(StatsDataSource.java:86)
                       at androidx.media3.exoplayer.source.ProgressiveMediaPeriod$ExtractingLoadable.load(ProgressiveMediaPeriod.java:1058)
                       at androidx.media3.exoplayer.upstream.Loader$LoadTask.run(Loader.java:450)
                       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
                       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
                       at java.lang.Thread.run(Thread.java:1117)
                 ]
14:53:03.976  E  internalError [eventTime=1.50, mediaPos=0.00, window=0, period=0, loadError
                   androidx.media3.datasource.HttpDataSource$InvalidResponseCodeException: Response code: 404
                       at androidx.media3.datasource.DefaultHttpDataSource.open(DefaultHttpDataSource.java:395)
                       at androidx.media3.datasource.DefaultDataSource.open(DefaultDataSource.java:275)
                       at androidx.media3.datasource.StatsDataSource.open(StatsDataSource.java:86)
                       at androidx.media3.exoplayer.source.ProgressiveMediaPeriod$ExtractingLoadable.load(ProgressiveMediaPeriod.java:1058)
                       at androidx.media3.exoplayer.upstream.Loader$LoadTask.run(Loader.java:450)
                       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
                       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
                       at java.lang.Thread.run(Thread.java:1117)
                 ]
14:53:06.045  E  Playback error
                   androidx.media3.exoplayer.ExoPlaybackException: Source error
                       at androidx.media3.exoplayer.ExoPlayerImplInternal.handleIoException(ExoPlayerImplInternal.java:745)
                       at androidx.media3.exoplayer.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:717)
                       at android.os.Handler.dispatchMessage(Handler.java:103)
                       at android.os.Looper.loopOnce(Looper.java:232)
                       at android.os.Looper.loop(Looper.java:317)
                       at android.os.HandlerThread.run(HandlerThread.java:85)
                   Caused by: androidx.media3.datasource.HttpDataSource$InvalidResponseCodeException: Response code: 404
                       at androidx.media3.datasource.DefaultHttpDataSource.open(DefaultHttpDataSource.java:395)
                       at androidx.media3.datasource.DefaultDataSource.open(DefaultDataSource.java:275)
                       at androidx.media3.datasource.StatsDataSource.open(StatsDataSource.java:86)
                       at androidx.media3.exoplayer.source.ProgressiveMediaPeriod$ExtractingLoadable.load(ProgressiveMediaPeriod.java:1058)
                       at androidx.media3.exoplayer.upstream.Loader$LoadTask.run(Loader.java:450)
                       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
                       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
                       at java.lang.Thread.run(Thread.java:1117)
14:53:06.047  E  internalError [eventTime=3.57, mediaPos=0.00, window=0, period=0, loadError
                   androidx.media3.datasource.HttpDataSource$InvalidResponseCodeException: Response code: 404
                       at androidx.media3.datasource.DefaultHttpDataSource.open(DefaultHttpDataSource.java:395)
                       at androidx.media3.datasource.DefaultDataSource.open(DefaultDataSource.java:275)
                       at androidx.media3.datasource.StatsDataSource.open(StatsDataSource.java:86)
                       at androidx.media3.exoplayer.source.ProgressiveMediaPeriod$ExtractingLoadable.load(ProgressiveMediaPeriod.java:1058)
                       at androidx.media3.exoplayer.upstream.Loader$LoadTask.run(Loader.java:450)
                       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
                       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
                       at java.lang.Thread.run(Thread.java:1117)
                 ]
14:53:06.050  E  playerFailed [eventTime=3.57, mediaPos=0.00, window=0, period=0, errorCode=ERROR_CODE_IO_BAD_HTTP_STATUS
                   androidx.media3.exoplayer.ExoPlaybackException: Source error
                       at androidx.media3.exoplayer.ExoPlayerImplInternal.handleIoException(ExoPlayerImplInternal.java:745)
                       at androidx.media3.exoplayer.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:717)
                       at android.os.Handler.dispatchMessage(Handler.java:103)
                       at android.os.Looper.loopOnce(Looper.java:232)
                       at android.os.Looper.loop(Looper.java:317)
                       at android.os.HandlerThread.run(HandlerThread.java:85)
                   Caused by: androidx.media3.datasource.HttpDataSource$InvalidResponseCodeException: Response code: 404
                       at androidx.media3.datasource.DefaultHttpDataSource.open(DefaultHttpDataSource.java:395)
                       at androidx.media3.datasource.DefaultDataSource.open(DefaultDataSource.java:275)
                       at androidx.media3.datasource.StatsDataSource.open(StatsDataSource.java:86)
                       at androidx.media3.exoplayer.source.ProgressiveMediaPeriod$ExtractingLoadable.load(ProgressiveMediaPeriod.java:1058)
                       at androidx.media3.exoplayer.upstream.Loader$LoadTask.run(Loader.java:450)
                       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
                       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
                       at java.lang.Thread.run(Thread.java:1117)
                 ]

Yes, thank you for the confirmation. I was able to test it also and found no case.
I am now suspecting how my MediaItem-s. are created.
I am not setting isPlayable to the MediaMetadata. Could that be read at some point that the item is not playable? As the default value is null.

@debz-eight
Copy link

After reading many comments, what helped me almost solve the issue is playing a 0.5s silent audio inside onPlaybackResumption(). So, I have a last played audio featured that I play from inside onPlaybackResumption(). While creating mediaItems, I am adding the silent audio and followed by my own last played audio.

@kelmer44
Copy link

kelmer44 commented Sep 26, 2024

marcbaechinger onPlaybackResumption is triggered both by getRecentMediaItemAtDeviceBootTime and handleMediaControllerPlayRequest. The latter makes an explicit call to Util.handlePlayButtonAction(playerWrapper); whereas the former doesn't. This is because one is an explicit call to play (e.g. from a bluetooth device) whilst the other one just populates the MediaLibrarySession with the last item. Am I correct in this?

Our app has a complex pipeline where we can't rely on returning a list of items in the onPlaybackResumption method but resolve the previous session & playback internally.

However we need to discern whether the call came from a play-able scenario or not in order not to have our app randomly play at random times whenever getRecentMediaItemAtDeviceBootTime gets called (still uncertain under what conditions this happens exactly BTW, could you clarify if you know?).

would it possible for future releases to add a flag to this method to be able to distinguish these two situations?

@marcbaechinger
Copy link
Contributor

Your understanding is correct.

getRecentMediaItemAtDeviceBootTime is used when System UI calls the MediaLibraryService at boot time to get the media items with title, artist, artwork and the like. System UI then builds the Playback Resumption Notification with these assets (see here). The media items delivered by Callback.onPlaybackResumption() aren't used to setup the player. Instead they are only given to the System UI MediaBrowser that requests the recent items.

In the other occasion, the media items returned by Callback.onPlaybackResumption(), the service is populating the player with it, prepares the player and calls play() to reume playback.

Your request seems useful to me. Not sure if the solution would be an additional boolean parameter or something else like a specific ControllerInfo passed to the callback which allows you to understand where the call is coming from.

However, mind filing a separate issue to ask for that flag?

@kelmer44
Copy link

Absolutely #1764

I do have further questions if I may: i have tried explicitly requesting playback in onplaybackresumption for all scenarios, then rebooting the phone, but playback isnt started (as I assumed its supposed to, because of MEdiaLibrarySession. getRecentMediaItemAtDeviceBootTime).

Additionally some user reports for my app complain the app starts playing at random times without necessarily being preceded by a reboot.

Are there any more occasions where the MediaLibrarySession path might be called? Do some other conditions need to be met? Trying to understand the behavior here :)

@marcbaechinger
Copy link
Contributor

explicitly requesting playback in onplaybackresumption for all scenarios,
then rebooting the phone, but playback isnt started (as I assumed its supposed to,
because of MEdiaLibrarySession. getRecentMediaItemAtDeviceBootTime).

Yeah, I see. This is something we haven't anticipated apps would want to do and that's why #1764 is a valid request I think. We need some API to clarify/express whether the media items returned by onPlaybackResumption() are used for actually setting up the player and resume playback, or to just hand it out to a browser without involving the player. Or, we alternatively need to better document things and for instance say that an app shouldn't call play() in onPlaybackResumption. :)

At boot time, onPlaybackResumption() is called and the media items you return with MediaItemsWithStartPosition are just delivered to System UI that called MediaLibrarySession.Callback.onGetChildren() through a MediaBrowser. SysUI then creates the media notification with it that a user may use after boot completed.

In contrast and in the case when onPlaybackResumption() is called for actual playback resumption (when BT sends a PLAY or when the user presses play on the System UI resumption notification), then Media3 takes the media items of MediaItemsWithStartPosition, calls player.setMediaItems(mediaItems, startIndex, startPosition), player.prepare() and player.play() to resume playback from there.

Are there any more occasions where the MediaLibrarySession path might be called?
Do some other conditions need to be met? Trying to understand the behavior here :)

Not that I'm aware of. Media3 calls onPlaybackResumption in these two cases we discussed already:

1 - when a play command is received and the playlist of the session player is empty (here).
2 - when a MediaBrowser attempts to call MediaLibrarySession.Callback.getChildren(parentId) and parentId == "androidx.media3.session.recent.root" (here). The value "androidx.media3.session.recent.root" is provided as the root item by getLibraryRoot(ControllerInfo, LibraryParams) for a caller with packageId="com.android.systemui" and LibraryParam.recent == true (here).

Additionally some user reports for my app complain the app starts playing at random
times without necessarily being preceded by a reboot.

from the above, the intended behavior that follows is:

a - any browser that calls getChildren() with "androidx.media3.session.recent.root" trigger onPlaybackResumption()
b - any controller that you allow to connect and that calls play when the player has an empty playlist may call initiate a call to onPlaybackResumptiopn()

I think for b) it's either System UI or a user that intentionally requests play, so it wouldn't be surprising for the user.

For a) and if your app calls player.play() in onPlaybackResumption() then playback could start when System UI calls the service at a moment when the player is in STATE_IDLE. I'm not aware of other occasions then after boot and just after starting the session, but I'm not certain to be honest. I think not calling play yourself in onPlaybackResumption() would verify this if the user complaints go away.

lovegaoshi added a commit to lovegaoshi/react-native-track-player that referenced this issue Sep 30, 2024
@johngray1965
Copy link

Additionally some user reports for my app complain the app starts playing at random times without necessarily being preceded by a reboot.

I'm getting reports of this as well.

@debz-eight
Copy link

So according to last 7 days of crashlytics report, I had 150 crashes due to ForegroundServiceDidNotStartInTimeException on majorly Samsung's Android 14, 70% of them to be exact. My app is now 99.73% crash free as of now after added the code to play a silent 0.5s audio onPlaybackResumption().

@marcbaechinger
Copy link
Contributor

@debz-eight Can you give me the Samsung models that are reported? It's all about finding why and how these Samsung devices trigger playback resumption I think. I can give it a shot again if I get such a device in my hands.

@debz-eight
Copy link

@marcbaechinger These is the whole list of 150 crashes of Samsung: https://batbin.me/lavers

@ksvslk
Copy link

ksvslk commented Oct 3, 2024

Mostly Samsung A, G, S, F series - but that could be that there are more of these out there. There also some Sony and Xiaomis.
And Android version is in the range of Android 11 - 14.

EDIT: I can test with A55 - Android 14. But I cannot reproduce it. If anyone can please let me know of the steps.

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