[nightly] New android.app.ForegroundServiceStartNotAllowedException: startAndStopEmptyNotificationToAvoidANR

elliotdickison commented 8 months ago

Describe the Bug

We recently released 3.2.0-b13a92208eaf9607a12cfa7596dfa6ae4f4a4c8e into production to take advantage of some of the updated Android foreground service logic (thank you!). We saw the long-time android.app.ForegroundServiceStartNotAllowedException bug disappear completely (woohoo!) but this one started popping up at about the same frequency. The issue only occurs in the background. This seems closely related to #1986, but per the discussion on that issue I'm opening a new issue.

Exception java.lang.RuntimeException:
  at android.app.ActivityThread.handleServiceArgs (ActivityThread.java:4839)
  at android.app.ActivityThread.-$$Nest$mhandleServiceArgs
  at android.app.ActivityThread$H.handleMessage (ActivityThread.java:2289)
  at android.os.Handler.dispatchMessage (Handler.java:106)
  at android.os.Looper.loopOnce (Looper.java:205)
  at android.os.Looper.loop (Looper.java:294)
  at android.app.ActivityThread.main (ActivityThread.java:8177)
  at java.lang.reflect.Method.invoke
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:552)
  at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:971)
Caused by android.app.ForegroundServiceStartNotAllowedException: Service.startForeground() not allowed due to mAllowStartForeground false: service com.maz.combo3310/com.doublesymmetry.trackplayer.service.MusicService
  at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel (ForegroundServiceStartNotAllowedException.java:54)
  at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel (ForegroundServiceStartNotAllowedException.java:50)
  at android.os.Parcel.readParcelableInternal (Parcel.java:4870)
  at android.os.Parcel.readParcelable (Parcel.java:4852)
  at android.os.Parcel.createExceptionOrNull (Parcel.java:3052)
  at android.os.Parcel.createException (Parcel.java:3041)
  at android.os.Parcel.readException (Parcel.java:3024)
  at android.os.Parcel.readException (Parcel.java:2966)
  at android.app.IActivityManager$Stub$Proxy.setServiceForeground (IActivityManager.java:6761)
  at android.app.Service.startForeground (Service.java:775)
  at com.doublesymmetry.trackplayer.service.MusicService.startAndStopEmptyNotificationToAvoidANR (MusicService.kt:125)
  at com.doublesymmetry.trackplayer.service.MusicService.onStartCommand (MusicService.kt:98)
  at android.app.ActivityThread.handleServiceArgs (ActivityThread.java:4821)

Steps To Reproduce

We have yet to reproduce locally on our devices. We have tried forcing the device into doze mode, loading new tracks in the background, playing for extended periods of time, etc. The issue is happening with regular frequency in production with an install base of ~6K

Occurring on SDK 33 & 34
Only occurs in background
Disproportionately occurs on Google Pixel phones (oriole, bluejay, raven, panther). Only ~21% of our install base are using Google devices but ~94% of crashes are on Pixels. Not sure if that's a red herring or not.

Code To Reproduce

Use 3.2.0-b13a92208eaf9607a12cfa7596dfa6ae4f4a4c8e

Replicable on Example App?

We have yet to reproduce the issue even in our app, once we do we'll check the example app.

Environment Info:

react-native-track-player@3.2.0-b13a92208eaf9607a12cfa7596dfa6ae4f4a4c8e

System:
  OS: macOS 13.5.1
  CPU: (8) arm64 Apple M1
  Memory: 249.86 MB / 16.00 GB
  Shell:
    version: "5.9"
    path: /bin/zsh
Binaries:
  Node:
    version: 16.15.0
    path: /private/var/folders/q_/y7w5vfj90n76sww7tczt1yqw0000gn/T/xfs-ba6db6e6/node
  Yarn:
    version: 3.2.1
    path: /private/var/folders/q_/y7w5vfj90n76sww7tczt1yqw0000gn/T/xfs-ba6db6e6/yarn
  npm:
    version: 8.5.5
    path: ~/.asdf/plugins/nodejs/shims/npm
  Watchman:
    version: 2023.07.10.00
    path: /opt/homebrew/bin/watchman
Managers:
  CocoaPods:
    version: 1.12.1
    path: /Users/elliot/.asdf/shims/pod
SDKs:
  iOS SDK:
    Platforms:
      - DriverKit 22.1
      - iOS 16.1
      - macOS 13.0
      - tvOS 16.1
      - watchOS 9.1
  Android SDK:
    API Levels:
      - "28"
      - "31"
      - "33"
    Build Tools:
      - 28.0.3
      - 29.0.2
      - 30.0.2
      - 30.0.3
      - 31.0.0
      - 33.0.0
    System Images:
      - android-31 | ARM 64 v8a
      - android-S | Google APIs ARM 64 v8a
      - android-S | Google Play ARM 64 v8a
    Android NDK: Not Found
IDEs:
  Android Studio: 2021.1 AI-211.7628.21.2111.8193401
  Xcode:
    version: 14.1/14B47b
    path: /usr/bin/xcodebuild
Languages:
  Java:
    version: 11.0.11
    path: /usr/bin/javac
  Ruby:
    version: 3.1.3
    path: /Users/elliot/.asdf/shims/ruby
npmPackages:
  "@react-native-community/cli": Not Found
  react: Not Found
  react-native: Not Found
  react-native-macos: Not Found
npmGlobalPackages:
  "*react-native*": Not Found
Android:
  hermesEnabled: yes
  newArchEnabled: no
iOS:
  hermesEnabled: yes
  newArchEnabled: no

How I can Help What can you do to help resolve this? Have you investigated the underlying JS or Swift/Android code causing this bug? Can you create a Pull Request with a fix?

marcvictorpassarelli commented 8 months ago

It seems to me that Android 14 is making this issue worse. I was seeing this error but way less than the previous one, but it seems that this new one is increasing after Android 14.

we're currently with RC08 in production and we hope to release a new version of our app until the end of this week with final version 4 of the library

AlkanV commented 8 months ago

we have the same problem on android 14. :(

lovegaoshi commented 8 months ago

seems very similar to the flutter folks experiencing, related to battery optimization https://github.com/ryanheise/audio_service/issues/994

agora-andrea commented 8 months ago

Hi everyone, just wanted to kindly ask you if you made any progress on this issue, thanks in advance.

bkostjens commented 7 months ago

I’m seeing the exact same crash reports while using version 4.0.1

daviluisb commented 7 months ago

Also happening on prod using > "react-native-track-player": "^3.2.0-7b02a2d2a51370819b91ea8da1fe835a617c3199",

Caused by java.lang.SecurityException: Starting FGS with type mediaPlayback  targetSDK=34 requires permissions: all of the permissions allOf=true [android.permission.FOREGROUND_SERVICE_MEDIA_PLAYBACK] 
       at android.os.Parcel.createExceptionOrNull(Parcel.java:3057)
       at android.os.Parcel.createException(Parcel.java:3041)
       at android.os.Parcel.readException(Parcel.java:3024)
       at android.os.Parcel.readException(Parcel.java:2966)
       at android.app.IActivityManager$Stub$Proxy.setServiceForeground(IActivityManager.java:6761)
       at android.app.Service.startForeground(Service.java:775)
       at com.doublesymmetry.trackplayer.service.MusicService.startAndStopEmptyNotificationToAvoidANR(MusicService.kt:115)
       at com.doublesymmetry.trackplayer.service.MusicService.onStartCommand(MusicService.kt:92)
       at android.app.ActivityThread.handleServiceArgs(ActivityThread.java:4821)
       at android.app.ActivityThread.-$$Nest$mhandleServiceArgs()
       at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2289)
       at android.os.Handler.dispatchMessage(Handler.java:106)
       at android.os.Looper.loopOnce(Looper.java:205)
       at android.os.Looper.loop(Looper.java:294)
       at android.app.ActivityThread.main(ActivityThread.java:8177)
       at java.lang.reflect.Method.invoke(Method.java)
       at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:552)
       at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:971)

bkostjens commented 7 months ago

track-player 4.0.1 - [ google husky (Pixel 8 Pro) ] - [ Android 14 (SDK 34) ]

Exception java.lang.RuntimeException:
  at android.app.ActivityThread.handleServiceArgs (ActivityThread.java:5261)
  at android.app.ActivityThread.-$$Nest$mhandleServiceArgs
  at android.app.ActivityThread$H.handleMessage (ActivityThread.java:2447)
  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:8762)
  at java.lang.reflect.Method.invoke
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:604)
  at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:1067)
Caused by android.app.ForegroundServiceStartNotAllowedException:
  at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel (ForegroundServiceStartNotAllowedException.java:54)
  at android.app.ForegroundServiceStartNotAllowedException$1.createFromParcel (ForegroundServiceStartNotAllowedException.java:50)
  at android.os.Parcel.readParcelableInternal (Parcel.java:4787)
  at android.os.Parcel.readParcelable (Parcel.java:4755)
  at android.os.Parcel.createExceptionOrNull (Parcel.java:3018)
  at android.os.Parcel.createException (Parcel.java:3007)
  at android.os.Parcel.readException (Parcel.java:2990)
  at android.os.Parcel.readException (Parcel.java:2932)
  at android.app.IActivityManager$Stub$Proxy.setServiceForeground (IActivityManager.java:6991)
  at android.app.Service.startForeground (Service.java:743)
  at com.doublesymmetry.trackplayer.service.MusicService.startAndStopEmptyNotificationToAvoidANR (MusicService.kt:123)
  at com.doublesymmetry.trackplayer.service.MusicService.onStartCommand (MusicService.kt:98)
  at android.app.ActivityThread.handleServiceArgs (ActivityThread.java:5243)

Involved Devices:

kesha-antonov commented 6 months ago

Just got same on Pixel 7 on Android 14

mihaibulic2 commented 6 months ago

Also seeing this with v4.0.1 — any thoughts on cause, workaround?

EDIT: I just released an app update that uses TrackPlayer and:

the crashes seem to be isolated: ~90% Pixel phones / ~90% Android 14
about 25% of all Android 14 Pixel phones are affected
// the above is a pretty small sample size (~600 Android devices)

mihaibulic2 commented 6 months ago

ping - anythoughts?

github-actions[bot] commented 3 months ago

This issue is stale because it has been open 90 days with no activity. Remove stale label or comment or this will be closed in 7 days.

elliotdickison commented 3 months ago

Not stale, still happening frequently. Just haven’t had time to investigate further yet.

nateshmbhat commented 3 weeks ago

any solution for this folks ?

elliotdickison commented 1 day ago

This is still an issue AFAIK, @nateshmbhat I'm sure the maintainers would welcome a PR!

Our best guess so far as to the scenario under which this occurs:

User opens app, plays something, pauses playback
Android kills the app's main activity after a period of inactivity (very normal Android behavior)
The notification stays open
The user taps the notification
The app crashes and the notification closes

doublesymmetry / react-native-track-player

[nightly] New android.app.ForegroundServiceStartNotAllowedException: startAndStopEmptyNotificationToAvoidANR #2184