`CastPlayer` produces `ForegroundServiceStartNotAllowedException` on media item transition #245

JaCobbMedia · 2023-01-23T11:51:43Z

Media3 Version

1.0.0-beta03

Devices that reproduce the issue

Various devices running android 12 and android 13

Devices that do not reproduce the issue

No response

Reproducible in the demo app?

Not tested

Reproduction steps

Wasn't able to reproduce it myself but I'm still reporting this because it was mentioned in #111 that we should report it if it happens on Android 13. According to crashlytics this happens 100% in background. By the logs I see various scenarios how this happens but most common one is when player is auto transitioning to next item.

Some additional info that might help indicate the problem:

We are releasing MediaController when user goes to background
On media item transition we are saving current item to DB, if it was listened before we are seeking to it's last listened position and adjusting playWhenReady if user has turned off/on autoplay. (But doubt this is causing any issues since crashes happen not only when item is transitioning)
onTaskRemoved we are doing stopSelf if player.playWhenReady != true
We do not override onUpdateNotification, but we are setting a custom MediaNotification.Provider

I can provide any additional info or logs if needed

Expected result

Not getting ForegroundServiceStartNotAllowedException and successfully continuing playback in background.

Actual result

Fatal Exception: android.app.ForegroundServiceStartNotAllowedException: startForegroundService() not allowed due to mAllowStartForeground false: service com.podimo/.app.core.media.MediaService
       at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:54)
       at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel(ForegroundServiceStartNotAllowedException.java:50)
       at android.os.Parcel.readParcelable(Parcel.java:3345)
       at android.os.Parcel.createExceptionOrNull(Parcel.java:2432)
       at android.os.Parcel.createException(Parcel.java:2421)
       at android.os.Parcel.readException(Parcel.java:2404)
       at android.os.Parcel.readException(Parcel.java:2346)
       at android.app.IActivityManager$Stub$Proxy.startService(IActivityManager.java:6968)
       at android.app.ContextImpl.startServiceCommon(ContextImpl.java:1927)
       at android.app.ContextImpl.startForegroundService(ContextImpl.java:1893)
       at android.content.ContextWrapper.startForegroundService(ContextWrapper.java:798)
       at com.podimo.app.core.media.MediaService.startForegroundService(MediaService.kt:153)
       at androidx.core.content.ContextCompat$Api26Impl.startForegroundService(ContextCompat.java:931)
       at androidx.core.content.ContextCompat.startForegroundService(ContextCompat.java:703)
       at androidx.media3.session.MediaNotificationManager.updateNotificationInternal(MediaNotificationManager.java:206)
       at androidx.media3.session.MediaNotificationManager.updateNotification(MediaNotificationManager.java:182)
       at androidx.media3.session.MediaSessionService.onUpdateNotification(MediaSessionService.java:411)
       at androidx.media3.session.MediaNotificationManager$MediaControllerListener.onEvents(MediaNotificationManager.java:299)
       at androidx.media3.session.MediaControllerImplBase.lambda$new$0(MediaControllerImplBase.java:151)
       at androidx.media3.session.MediaControllerImplBase$$InternalSyntheticLambda$3$10aed4c532fdc841d63f0af013a047ffd34a0b4b9b1d6da420408b3dbfb435a8$0.invoke(MediaControllerImplBase.java:1)
       at androidx.media3.common.util.ListenerSet$ListenerHolder.iterationFinished(ListenerSet.java:295)
       at androidx.media3.common.util.ListenerSet.handleMessage(ListenerSet.java:246)
       at androidx.media3.common.util.ListenerSet$$InternalSyntheticLambda$1$0a1dffe138e30e7ad8eb5a169bfb4852f73945d310b0f0a49ed6bc74e8c308ab$0.handleMessage$bridge(ListenerSet.java:57)
       at android.os.Handler.dispatchMessage(Handler.java:102)
       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.

The text was updated successfully, but these errors were encountered:

marcbaechinger · 2023-01-24T11:54:53Z

Thanks for the report.

The service is put to/removed from foreground when playWhenReady changes.

I can't think of why that should happen when the player transitions playback from one item to the next. Even when a seek is performed within or across media items, playWhenReady is not changed by the player internally.

On media item transition we are saving current item to DB, if it was listened before we are seeking to it's last listened position and adjusting playWhenReady if user has turned off/on autoplay.

Accordingly, this seems to be a potential source of the problem, but I'm not sure I understand how. As far as I understand, we have the following scenarios:

playWhenReady is false: In this case we would not see an automatic transition because playback is paused.
playWhenReady is true and autoplay off : In this case the transition would happen and then playWhenReady is set to false. This would cause the service to be removed from the foreground. This does not result in the reported ForegroundServiceStartNotAllowedException.
playWhenReady is true and autoplay on : In this case playWhenReady is not changed and the service remains in the foreground. No change in the state of the service is requested.

The only thing I can think of is that 'adjusting playWhenReady' involves switching playWhenReady to false and then to true again, which would be like resuming playback but I actually wouldn't expect you doing that.

One way to verify what is happening would be that you add an EventLogger to the app. This would make visible what happens on the player side. However, this would only help in case we get a bug report from such a device just after the crash has occured. We would then be able to see the logs of EventLogger to see whether the crash was following a change in the player state.

JaCobbMedia · 2023-01-25T14:03:40Z

Thank you for the response @marcbaechinger . I'll investigate more our autoplay logic, but it's pretty basic oneliner - player?.playWhenReady = player?.playWhenReady == true && autoplay. Also got some logs from latest release and noticed few scenarios:

right before transitioning player went to STATE_IDLE and right back to STATE_READY
one of the users got ERROR_CODE_DECODER_INIT_FAILED which caused same state change as previously described. I will look into it more, but if PlaybackException is thrown we just call player.stop() and send some events to UI, we don't really retry restarting playback without user interaction.

I added EventLogger to new app version, so I should get more info when users crash on that version. Will update this issue more then

marcbaechinger · 2023-01-25T14:22:28Z

Yeah, agreed the playWhenReady thing should be trivial.

But good call regarding the playback error! I haven't taken this case into account. We (the Media3 team) need to think about this case well. Auto re-starting in the background wouldn't work like you say. This would remove the service from and put it back to the foreground. Thanks for bringing this up!

Having the logs from EventLogger would give as some more insight in any case!

JaCobbMedia · 2023-01-27T10:08:35Z

Okay, so I got some logs from latest release.

Auto transitioning. I was a bit confused on why I see some state changes, but nothing from EventLogger and then I realised it was happening on CastPlayer (confirmed that by looking into our events). Then tried reproducing it by myself and it was pretty easy - I just let one item transition to other item while casting and immediately got FgS exception. Then tried it with UAMP project on media3 branch, same happened there :(
googlequicksearchbox. This is already reported to you. User basically tried to control playback with google assistant
InternalError. Some users get java.net.SocketTimeoutException while in background, might be because of their poor internet connection. DataSource tries couple of times to retry the connection and fails, then 10s later goes to buffering state and isPlaying changes to false and immediately FgS exception.

I'll be looking into more cases, but if you need any full logs from these cases, I can send it via email.

marcbaechinger · 2023-01-27T12:52:19Z

Thanks for the analysis.

We definitely should look into CastPlayer and why the state is changing when transitioning. It defo sounds like a bug to me as this should not happen. I'll change the title of this issue accordingly if that's ok with you.

googlequicksearchbox - Yeah, as you mention. Known issue on Android 12.

InternalError - This is actually an obvious one when thinking about it. I haven't noticed this yet though, so thanks for reporting. There is not much we can do about it with the current best practice implementation that is to take the service out of the foreground when not playing. The exception, and the resumption of playback after the error causes interrupts the playback and a retry will cause the ForegroundServiceStartNotAllowedException. We are internally advocating for a different implementation approach that would possible help in this case as well. So thanks for giving us another argument! On the other hand, I don't think we can possibly do something right now for this case. The only thing an app can do is posting a Notification to ask the user to start the retry by user intervention. This would then give a way to resume from the foreground.

I have updated #111 accordingly and I rename this issue to focus on the CastPlayer transitions only. Please shout if you thing that doesn't make sense. :)

JaCobbMedia · 2023-01-27T14:54:17Z

Thank you once again.

I just have to mention few things. After receiving an internal error we don't actually try restarting playback by ourselves. We have DefaultLoadErrorHandlingPolicy added to our DefaultMediaSourceFactory. In the logs I can't see that PlaybackException has been thrown yet because then we would have stopped player, so my guess is that crash happened during load error handling process. Could that be the case?

And googlequicksearchbox case happened on Android 13 actually (Galaxy XCover 5)

marcbaechinger · 2023-01-27T15:35:30Z

DefaultLoadErrorHandlingPolicy

Thanks for clarification. What is the playback state doing when this happens? Because I'd only expect a fatal error changing the playback state to IDLE as a consequence of stop being called. I think we need to investigate this a bit more in this case. I think when we retry (as in terms of LoadErrorHandlingPolicy) and in the end successfully start loading again we should somehow be able to not getting the service off the foreground, so this should actually work.

The case I mentioned regarding retry after a PlaybackException is harder to fix I think.

googlequicksearchbox on Android 13

That's odd. I'll test this. Thanks for mentioning.

JaCobbMedia · 2023-01-27T15:51:47Z

What I can see from the logs:

User went to foreground - item was restored and loaded to the player
state changed to STATE_READY
user toggled playback. playWhenReady = true, isPlaying = true
user went to background. We released MediaController
After 8 seconds followed 4 internalErrors each with 8s interval
After last internalError 8s passed and state changed to STATE_BUFFERING and isPlaying changed to false
immediately after that startForegroundService was called and crash happened

marcbaechinger · 2023-01-27T16:01:40Z

With the scenario above, the service should not be taken off the foreground as far as I can tell. Being in state BUFFERING isn't enough to get off the foreground. The player either needs to be in STATE_IDLE or STATE_ENDED or playWhenReady==false to take the service off the foreground.

We need to investigate this. Many thanks for your detailed report. Much appreciated.

marcbaechinger · 2023-01-30T12:25:09Z

I can confirm that the CastPlayer transitions to STATE_IDLE when playback transitions automatically from one item in the playlist to the next. Then it immediately goes to STATE_READY again.

This explains why the service is taken off the foreground and then produces the reported exception. We will look into CastPlayer and we will update this issue when we have submitted a change regarding this problem. Thanks for reporting again.

#minor-release Issue: androidx/media#245 PiperOrigin-RevId: 510456793

#minor-release Issue: #245 PiperOrigin-RevId: 510456793

#minor-release Issue: #245 PiperOrigin-RevId: 510456793 (cherry picked from commit ba49b6b)

#minor-release Issue: androidx/media#245 PiperOrigin-RevId: 510456793 (cherry picked from commit a231ff4)

marcbaechinger · 2023-03-04T13:44:51Z

Closing this issue as it is fixed as per commits above.

JaCobbMedia · 2023-03-06T07:58:55Z

Great news, thank you!

JaCobbMedia added bug needs triage labels Jan 23, 2023

marcbaechinger self-assigned this Jan 24, 2023

marcbaechinger removed the needs triage label Jan 24, 2023

marcbaechinger changed the title ~~ForegroundServiceStartNotAllowedException on Android 13 devices~~ CastPlayer produces ForegroundServiceStartNotAllowedException on media item transition Jan 27, 2023

andrewlewis pushed a commit to google/ExoPlayer that referenced this issue Feb 24, 2023

Map PLAYER_STATE_LOADING to STATE_BUFFERING

a231ff4

#minor-release Issue: androidx/media#245 PiperOrigin-RevId: 510456793

tonihei pushed a commit that referenced this issue Feb 28, 2023

Map PLAYER_STATE_LOADING to STATE_BUFFERING

ba49b6b

#minor-release Issue: #245 PiperOrigin-RevId: 510456793

tonihei pushed a commit that referenced this issue Mar 2, 2023

Map PLAYER_STATE_LOADING to STATE_BUFFERING

629a75e

#minor-release Issue: #245 PiperOrigin-RevId: 510456793 (cherry picked from commit ba49b6b)

tonihei pushed a commit to google/ExoPlayer that referenced this issue Mar 2, 2023

Map PLAYER_STATE_LOADING to STATE_BUFFERING

61a38a1

#minor-release Issue: androidx/media#245 PiperOrigin-RevId: 510456793 (cherry picked from commit a231ff4)

marcbaechinger closed this as completed Mar 4, 2023

androidx locked and limited conversation to collaborators May 4, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

`CastPlayer` produces `ForegroundServiceStartNotAllowedException` on media item transition #245

`CastPlayer` produces `ForegroundServiceStartNotAllowedException` on media item transition #245

JaCobbMedia commented Jan 23, 2023 •

edited

marcbaechinger commented Jan 24, 2023

JaCobbMedia commented Jan 25, 2023 •

edited

marcbaechinger commented Jan 25, 2023

JaCobbMedia commented Jan 27, 2023 •

edited

marcbaechinger commented Jan 27, 2023

JaCobbMedia commented Jan 27, 2023

marcbaechinger commented Jan 27, 2023

JaCobbMedia commented Jan 27, 2023

marcbaechinger commented Jan 27, 2023

marcbaechinger commented Jan 30, 2023

marcbaechinger commented Mar 4, 2023

JaCobbMedia commented Mar 6, 2023

CastPlayer produces ForegroundServiceStartNotAllowedException on media item transition #245

CastPlayer produces ForegroundServiceStartNotAllowedException on media item transition #245

Comments

JaCobbMedia commented Jan 23, 2023 • edited

Media3 Version

Devices that reproduce the issue

Devices that do not reproduce the issue

Reproducible in the demo app?

Reproduction steps

Expected result

Actual result

Media

Bug Report

marcbaechinger commented Jan 24, 2023

JaCobbMedia commented Jan 25, 2023 • edited

marcbaechinger commented Jan 25, 2023

JaCobbMedia commented Jan 27, 2023 • edited

marcbaechinger commented Jan 27, 2023

JaCobbMedia commented Jan 27, 2023

marcbaechinger commented Jan 27, 2023

JaCobbMedia commented Jan 27, 2023

marcbaechinger commented Jan 27, 2023

marcbaechinger commented Jan 30, 2023

marcbaechinger commented Mar 4, 2023

JaCobbMedia commented Mar 6, 2023

`CastPlayer` produces `ForegroundServiceStartNotAllowedException` on media item transition #245

`CastPlayer` produces `ForegroundServiceStartNotAllowedException` on media item transition #245

JaCobbMedia commented Jan 23, 2023 •

edited

JaCobbMedia commented Jan 25, 2023 •

edited

JaCobbMedia commented Jan 27, 2023 •

edited