[Android 12+] Loading new track crashes the app after being in background for ~5 mins with locked screen

[takacskalman]

Describe the Bug

When trying to load a new track when the previous ended (via the PlaybackService callback) the app crashes. It just happens if the screen is locked and the app is in background and it only affects Android 12+ versions. Prior Android 12 it works fine without any issues, also on IOS no issues. It works with local files, just the remote ones cause the problem. It works if we load all the tracks by calling TrackPlayer.add([list of tracks]) but it does not work if I we call TrackPlayer.load and switch the track from the PlaybackService's callback by TrackPlayer.load. Our problem is that we cant add all the tracks at once, we need to add them 1 by 1 because we have custom logic for preparing a track.

Steps To Reproduce

1. Load a track via TrackPlayer.load method
2. Load the next track in PlaybackService's PlaybackState event's State.Ended callback (again via TrackPlayer.load)
3. Start the player
4. Turn off repeat mode
5. Move the app to the background
6. Lock the screen
7. Listen for ~5 minutes
8. It should crash

Code To Reproduce Provided in the next section.

Replicable on Example App? Can you replicate this bug in the React Native Track Player Example App?

It's replicable in the demo app by changing it's playlist management from queue added to track player to loading 1 track at a time and then changing the track when the actual ended. The screenshots with the chnages:

Environment Info: Paste the results of npx react-native info It was tested by different developers on different platforms Paste the exact react-native-track-player version you are using 4.0.0-rc09 but it's the same with other versions too Real device? Or simulator? Real device What OS are you running? Android

How I can Help What can you do to help resolve this? We are 3 devs building an audiobook app and this is the only thing that blocks the release, so basically we can help in anything, this is our first prio now. Have you investigated the underlying JS or Swift/Android code causing this bug? Can you create a Pull Request with a fix?

Logs:

{ message: 'Source error', code: 'android-io-network-connection-failed' }
2023-10-11 17:32:25.067 30947-31163 ExoPlayerImplInternal   Playback error  UnknownHostException (no network)

[kormocicsaba]

https://github.com/kormocicsaba/react-native-track-player

I've tested on Xiaomi Poco F3 phone, with Android 13 and the player stops after the 5. chapter/audio, with repeat mode off. If I disable the battery optimisation (inside app settings), then the player won't stop at all.

[takacskalman]

Here are the most important logs from starting an audio until the crash happens: From this it seems that we get exception multiple times but it does not crash the app, just after a few minutes. Probably when it enters Doze https://developer.android.com/training/monitoring-device-state/doze-standby#testing_doze_and_app_standby If it's plugged in it does not happen (probably because of no Doze)

2023-10-12 15:49:01.808  1244-3238  MediaFocusControl       pid-1244                             I  requestAudioFocus() from uid/pid 10193/17841 AA=USAGE_MEDIA/CONTENT_TYPE_MUSIC clientId=android.media.AudioManager@ed13ae4com.google.android.exoplayer2.AudioFocusManager$AudioFocusListener@f5fbb4d callingPack=com.example req=1 flags=0x0 sdk=33
2023-10-12 15:49:01.843 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=true
2023-10-12 15:49:01.849 17841-17841 MusicService            com.example                      D  notification has been foregrounded
2023-10-12 15:49:01.852 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=true
2023-10-12 15:49:01.854 17841-17841 MusicService            com.example                      D  skipping foregrounding as the service is already foregrounded
2023-10-12 15:49:02.469 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=true
2023-10-12 15:49:02.471 17841-17841 MusicService            com.example                      D  skipping foregrounding as the service is already foregrounded
2023-10-12 15:49:02.550 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=true
2023-10-12 15:49:02.552 17841-17841 MusicService            com.example                      D  skipping foregrounding as the service is already foregrounded
2023-10-12 15:49:02.799 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=true
2023-10-12 15:49:02.801 17841-17841 MusicService            com.example                      D  skipping foregrounding as the service is already foregrounded
2023-10-12 15:49:02.806 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=true
2023-10-12 15:49:02.808 17841-17841 MusicService            com.example                      D  skipping foregrounding as the service is already foregrounded
2023-10-12 15:49:03.016 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=true
2023-10-12 15:49:03.018 17841-17841 MusicService            com.example                      D  skipping foregrounding as the service is already foregrounded
2023-10-12 15:51:50.323 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=false
2023-10-12 15:51:50.340 17841-17841 MusicServi...egrounding com.example                      D  stopped foregrounding
2023-10-12 15:51:51.419 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=true
2023-10-12 15:51:51.428  1244-4778  ActivityManager         pid-1244                             W  Foreground service started from background can not have location/camera/microphone access: service com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:51:51.429  1244-4778  ActivityManager         pid-1244                             W  Background started FGS: Disallowed [callingPackage: com.example; callingUid: 10193; uidState: SVC ; intent: Intent { cmp=com.example/com.doublesymmetry.trackplayer.service.MusicService }; code:DENIED; tempAllowListReason:<null>; targetSdkVersion:33; callerTargetSdkVersion:33; startForegroundCount:2; bindFromPackage:null]
2023-10-12 15:51:51.432  1244-4778  ActivityManager         pid-1244                             W  Service.startForeground() not allowed due to mAllowStartForeground false: service com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:51:51.438 17841-17841 MusicService            com.example                      E  ForegroundServiceStartNotAllowedException: App tried to start a foreground Service when it was not allowed to do so.
2023-10-12 15:51:51.637 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=true
2023-10-12 15:51:51.643  1244-1506  ActivityManager         pid-1244                             W  Foreground service started from background can not have location/camera/microphone access: service com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:51:51.643  1244-1506  ActivityManager         pid-1244                             W  Service.startForeground() not allowed due to mAllowStartForeground false: service com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:51:51.647 17841-17841 MusicService            com.example                      E  ForegroundServiceStartNotAllowedException: App tried to start a foreground Service when it was not allowed to do so.
2023-10-12 15:51:51.706 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=true
2023-10-12 15:51:51.714  1244-1506  ActivityManager         pid-1244                             W  Foreground service started from background can not have location/camera/microphone access: service com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:51:51.715  1244-1506  ActivityManager         pid-1244                             W  Service.startForeground() not allowed due to mAllowStartForeground false: service com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:51:51.720 17841-17841 MusicService            com.example                      E  ForegroundServiceStartNotAllowedException: App tried to start a foreground Service when it was not allowed to do so.
2023-10-12 15:51:51.726 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=true
2023-10-12 15:51:51.732  1244-1506  ActivityManager         pid-1244                             W  Foreground service started from background can not have location/camera/microphone access: service com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:51:51.732  1244-1506  ActivityManager         pid-1244                             W  Service.startForeground() not allowed due to mAllowStartForeground false: service com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:51:51.737 17841-17841 MusicService            com.example                      E  ForegroundServiceStartNotAllowedException: App tried to start a foreground Service when it was not allowed to do so.
2023-10-12 15:52:50.342  1244-1280  ActivityManager         pid-1244                             W  Stopping service due to app idle: u0a193 -4m58s775ms com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:54:54.081 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=false
2023-10-12 15:54:55.102 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=true
2023-10-12 15:54:55.110  1244-1506  ActivityManager         pid-1244                             W  Foreground service started from background can not have location/camera/microphone access: service com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:54:55.111  1244-1506  ActivityManager         pid-1244                             W  Background started FGS: Disallowed [callingPackage: com.example; callingUid: 10193; uidState: LAST; intent: Intent { cmp=com.example/com.doublesymmetry.trackplayer.service.MusicService }; code:DENIED; tempAllowListReason:<null>; targetSdkVersion:33; callerTargetSdkVersion:33; startForegroundCount:2; bindFromPackage:null]
2023-10-12 15:54:55.111  1244-1506  ActivityManager         pid-1244                             W  Service.startForeground() not allowed due to mAllowStartForeground false: service com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:54:55.115 17841-17841 MusicService            com.example                      E  ForegroundServiceStartNotAllowedException: App tried to start a foreground Service when it was not allowed to do so.
2023-10-12 15:54:55.368 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=true
2023-10-12 15:54:55.377  1244-1706  ActivityManager         pid-1244                             W  Foreground service started from background can not have location/camera/microphone access: service com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:54:55.377  1244-1706  ActivityManager         pid-1244                             W  Service.startForeground() not allowed due to mAllowStartForeground false: service com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:54:55.382 17841-17841 MusicService            com.example                      E  ForegroundServiceStartNotAllowedException: App tried to start a foreground Service when it was not allowed to do so.
2023-10-12 15:54:55.403 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=true
2023-10-12 15:54:55.410  1244-1706  ActivityManager         pid-1244                             W  Foreground service started from background can not have location/camera/microphone access: service com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:54:55.410  1244-1706  ActivityManager         pid-1244                             W  Service.startForeground() not allowed due to mAllowStartForeground false: service com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:54:55.415 17841-17841 MusicService            com.example                      E  ForegroundServiceStartNotAllowedException: App tried to start a foreground Service when it was not allowed to do so.
2023-10-12 15:54:55.419 17841-17841 MusicServi...egrounding com.example                      D  notification posted with id=1, ongoing=true
2023-10-12 15:54:55.427  1244-1706  ActivityManager         pid-1244                             W  Foreground service started from background can not have location/camera/microphone access: service com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:54:55.428  1244-1706  ActivityManager         pid-1244                             W  Service.startForeground() not allowed due to mAllowStartForeground false: service com.example/com.doublesymmetry.trackplayer.service.MusicService
2023-10-12 15:54:55.432 17841-17841 MusicService            com.example                      E  ForegroundServiceStartNotAllowedException: App tried to start a foreground Service when it was not allowed to do so.

2023-10-12 15:57:20.313  1244-1280  ActivityManager         pid-1244                             I  Killing 17841:com.example/u0a193 (adj 700): excessive cpu 138940 during 300075 dur=329967 limit=25
2023-10-12 15:57:20.660  1244-3313  ConnectivityService     pid-1244                             D  ConnectivityService NetworkRequestInfo binderDied(uid/pid:10193/17841, [NetworkRequest [ REQUEST id=2422, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VCN_MANAGED Uid: 10193 RequestorUid: 10193 RequestorPkg: com.example UnderlyingNetworks: Null] ]], android.os.BinderProxy@3589ff5)
2023-10-12 15:57:20.661  1244-1641  ConnectivityService     pid-1244                             D  ConnectivityService NetworkRequestInfo binderDied(uid/pid:10193/17841, [NetworkRequest [ LISTEN id=2425, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN&FOREGROUND&NOT_VCN_MANAGED Uid: 10193 RequestorUid: 10193 RequestorPkg: com.example UnderlyingNetworks: Null] ]], android.os.BinderProxy@ec6c8df)
2023-10-12 15:57:20.662   630-696   SurfaceFlinger          pid-630                              D  [SF client] REMOVE (0xf3fc65c0) for (17841:com.example)
2023-10-12 15:57:20.661  1244-3886  ConnectivityService     pid-1244                             D  ConnectivityService NetworkRequestInfo binderDied(uid/pid:10193/17841, [NetworkRequest [ REQUEST id=2420, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VCN_MANAGED Uid: 10193 RequestorUid: 10193 RequestorPkg: com.example UnderlyingNetworks: Null] ]], android.os.BinderProxy@9f6f18a)
2023-10-12 15:57:20.664  1244-1451  ConnectivityService     pid-1244                             D  releasing NetworkRequest [ REQUEST id=2422, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VCN_MANAGED Uid: 10193 RequestorUid: 10193 RequestorPkg: com.example UnderlyingNetworks: Null] ] (release request)
2023-10-12 15:57:20.664  1244-1506  WindowManager           pid-1244                             I  WIN DEATH: Window{f4e1e53 u0 com.example/com.example.MainActivity}
2023-10-12 15:57:20.665  1244-1506  InputManager-JNI        pid-1244                             W  Input channel object 'f4e1e53 com.example/com.example.MainActivity (client)' was disposed without first being removed with the input manager!
2023-10-12 15:57:20.665  1244-1451  ConnectivityService     pid-1244                             D  releasing NetworkRequest [ REQUEST id=2420, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VCN_MANAGED Uid: 10193 RequestorUid: 10193 RequestorPkg: com.example UnderlyingNetworks: Null] ] (release request)
2023-10-12 15:57:20.666  1244-1506  WindowManager           pid-1244                             V  Remove Window{f4e1e53 u0 com.example/com.example.MainActivity}: mSurfaceController=null mAnimatingExit=false mRemoveOnExit=false mHasSurface=false surfaceShowing=false animating=false app-animation=false mWillReplaceWindow=false mDisplayFrozen=false callers=com.android.server.wm.WindowState.-$$Nest$mremoveIfPossible:0 com.android.server.wm.WindowState$DeathRecipient.binderDied:3206 android.os.IBinder$DeathRecipient.binderDied:317 android.os.BinderProxy.sendDeathNotice:704 <bottom of call stack> <bottom of call stack> 
2023-10-12 15:57:20.666  1244-1506  WindowManager           pid-1244                             D  setParent old=ActivityRecord{e356fde u0 com.example/.MainActivity} t57},new=null,this window=Window{f4e1e53 u0 com.example/com.example.MainActivity},callers=com.android.server.wm.WindowContainer.removeChild:772 com.android.server.wm.ActivityRecord.removeChild:4315 com.android.server.wm.ActivityRecord.removeChild:378 com.android.server.wm.WindowContainer.removeImmediately:828 com.android.server.wm.WindowState.removeImmediately:2523 com.android.server.wm.WindowState.removeIfPossible:2713 
2023-10-12 15:57:20.685  1244-1641  mtkpower_client         pid-1244                             I  [Legacy][PowerHal_Wrap_notifyAppState] com.example/com.example pid=17841 state:3
2023-10-12 15:57:20.686  1244-1641  game_scn                pid-1244                             I  collectForegroundAppList packName=com.example, actName=com.example, pid=17841, uid=10193, state:DEAD
2023-10-12 15:57:20.688   608-668   libPowerHal             pid-608                              I  [perfNotifyAppState] pack:com.example, act:com.example, state:3, pid:17841, uid:10193, fps:60
2023-10-12 15:57:20.688   608-668   libPowerHal             pid-608                              I  [perfNotifyAppState] pack:com.example, pid:17841, STATE_DEAD
2023-10-12 15:57:20.722  1244-1278  UsageStatsService       pid-1244                             W  Unexpected activity event reported! (com.example/com.example.MainActivity event : 23 instanceId : 59671692)

[nagyszili]

You can force the app into Doze mode even if its plugged in with adb shell dumpsys deviceidle force-idle I've tried this example and got instantly this error

 LOG  Event.MetadataCommonReceived {"metadata": {}}
 LOG  Event.PlaybackState {"state": "loading"}
 LOG  Event.PlaybackState {"state": "buffering"}
 LOG  Event.PlaybackState {"error": {"code": "android-io-network-connection-failed", "message": "Source error"}, "state": "error"}

just need to disable the repeatMode

[elliotdickison]

@takacskalman Which version of rntp are you using?

[takacskalman]

@elliotdickison 4.0.0-rc09 But we tried with different versions and the issue happens with all of them. All the 4.0 RC versions, and the 3.X versions too.

[puckey]

We should test this again after merging in the following pr: https://github.com/doublesymmetry/KotlinAudio/pull/95

[dcvz]

For anyone in the future that has a similar issue:

We should test this again after merging in the following pr: doublesymmetry/KotlinAudio#95

The following PR will remove the need of having to seek to start again when loading a track - for issues with dozing or the service being terminated after track ends, the grace period introduced here should help #2164

[dcvz]

Going to close this one as complete with #2164

[Ggayane]

I don't know what has been changed in player but with latest version audio player just doesn't work properly when app is background. Tested on v4, v4.0.0-rc09. Works properly on v3.2.0-9cd6e0e9235f8ed7ae5812ed20220f7d895b510a though.

[dcvz]

I don't know what has been changed in player but with latest version audio player just doesn't work properly when app is background. Tested on v4, v4.0.0-rc09. Works properly on v3.2.0-9cd6e0e9235f8ed7ae5812ed20220f7d895b510a though.

@Ggayane would you mind testing the latest nightly 4.0.0-nightly-429279a8dd21105c1deff3e639150da349fd9143? It included #2181 which might've been the issue.

[Ggayane]

@dcvz I've tested on 4.0.0-nightly-429279a8dd21105c1deff3e639150da349fd9143, on this version notification disappearance issue is fixed, but the main issue still exists - for my case I'm listening to event PlaybackQueueEnded and doing async calls, to load audio urls and then add new track to queue to play, on latest version these calls may last from 20 seconds to 1 minute when app is in the background, but once you open app it will load/work immediately. On the working version I've mentioned (v3.2.0-9cd6e0e9235f8ed7ae5812ed20220f7d895b510a) same function on the background state took ~6-9 seconds.

[dcvz]

@dcvz I've tested on 4.0.0-nightly-429279a8dd21105c1deff3e639150da349fd9143, on this version notification disappearance issue is fixed, but the main issue still exists - for my case I'm listening to event PlaybackQueueEnded and doing async calls, to load audio urls and then add new track to queue to play, on latest version these calls may last from 20 seconds to 1 minute when app is in the background, but once you open app it will load/work immediately.

On the working version I've mentioned (v3.2.0-9cd6e0e9235f8ed7ae5812ed20220f7d895b510a) same function on the background state took ~6-9 seconds.

That's great to hear! Regarding the loading audio when queue ends, you'll want to configure the grace period before we set the service out of foreground: https://rntp.dev/docs/api/objects/android-options

The default is 5 seconds.