Android Vitals ANR's increasing due to Context.startForeGroundService()

[google]

Android Vitals ANR's increasing due to Context.startForeGroundService()

[monkeyswarm]

Hi, what app is it? Is there code somewhere?

More specifically, is your app calling AudioSystem. stopBackgroundDisplay() and then starting background playback/display again in quick succession?

That's my suspicion based on reading https://stackoverflow.com/questions/44425584/context-startforegroundservice-did-not-then-call-service-startforeground . There may be a way for plugin code to try to guard against that. Please let me know if you can find a way to reproduce.

[arodriguezgb]

Hey , the app is called GentleBirth.

I have not been able to reproduce any crash or ANR's on my own testing.

The only time I call stopBackGroundDisplay is when the user quits a track from playing.

The tracks keep playing when on a playlist or something but I don't call stop background play there because the notification should still display (if i am correct of the functionality).

Let me triple check if i can find myself calling stopbackgroundDisplay() multiple times. I can post part of the code here in a few minutes.

edit:

Yea , I don't call stopBackgroundDisplay unless the user quits the player.

Whenever the user quits the player I call ...

void _stopBackgroundAudio() {
_backgroundAudio.pause();
setState(() => _backgroundAudioPlaying = false);
AudioSystem.instance.stopBackgroundDisplay();
}

I will try quitting and playing a few songs quite a few times in rapid succession and see what happens.

[monkeyswarm]

It could also be that the app starts playback (which starts the service) and then very quickly stops background audio (which calls stopSelf()). If stopSelf() is called before the service finishes starting up, that could be an issue.

Does the report say that it is actually an activity ANR, or just an error/exception? I feel like in this case the app continues running, it's merely the service (which the user has cancelled) doesn't finish starting up.

[arodriguezgb]

I have started playback and then quit the player like 15 times in a row the fastest I can and I have not experienced any issues or ANRS or anything that I believe could be an issue on the console log.

Everytime I quit and play I get this:
W/MediaPlayerNative(25304): info/warning (703, 0)
W/MediaPlayerNative(25304): info/warning (701, 0)
W/MediaPlayerNative(25304): info/warning (703, 0)

But there is nothing more.

Here are a few pictures of the Vitals Console with some logs of it. I can show all of them if you need them.

https://photos.app.goo.gl/jeUzLbjvkqfJvfg48

https://photos.app.goo.gl/ZsDgZ45Uh46Ce3Zm9

You can also find me on Discord by Incrysiz#2616 if you want to talk about it or take a look at the whole code.

Edit:

I also just noticed there is 101 crashes caused by a NullPointerException on the player aswell.
java.lang.NullPointerException

com.google.flutter.plugins.audiofileplayer.AudiofileplayerService.onStartCommand

But we can talk about that one as a separate issue later. If you want.
java.lang.RuntimeException: at android.app.ActivityThread.handleServiceArgs (ActivityThread.java:3910) at android.app.ActivityThread.access$1700 (ActivityThread.java:237) at android.app.ActivityThread$H.handleMessage (ActivityThread.java:1816) at android.os.Handler.dispatchMessage (Handler.java:106) at android.os.Looper.loop (Looper.java:214) at android.app.ActivityThread.main (ActivityThread.java:7050) at java.lang.reflect.Method.invoke (Method.java) at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:494) at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:965) Caused by: java.lang.NullPointerException: at com.google.flutter.plugins.audiofileplayer.AudiofileplayerService.onStartCommand (AudiofileplayerService.java:7) at android.app.ActivityThread.handleServiceArgs (ActivityThread.java:3891) at android.app.ActivityThread.access$1700 (ActivityThread.java:237) at android.app.ActivityThread$H.handleMessage (ActivityThread.java:1816) at android.os.Handler.dispatchMessage (Handler.java:106) at android.os.Looper.loop (Looper.java:214) at android.app.ActivityThread.main (ActivityThread.java:7050) at java.lang.reflect.Method.invoke (Method.java) at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:494) at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:965)

[arodriguezgb]

Today a new type of crash was reported on Android Vitals.

Here is the info:
java.lang.IllegalStateException
com.google.flutter.plugins.audiofileplayer.AudiofileplayerPlugin$LifecycleCallbacks.onActivityStarted

java.lang.IllegalStateException: at android.media.browse.MediaBrowser.connect (MediaBrowser.java:153) at android.support.v4.media.MediaBrowserCompatApi21.a (MediaBrowserCompatApi21.java:2) at android.support.v4.media.MediaBrowserCompat$MediaBrowserImplApi21.connect (MediaBrowserCompat.java:2) at android.support.v4.media.MediaBrowserCompat.connect (MediaBrowserCompat.java:2) at com.google.flutter.plugins.audiofileplayer.AudiofileplayerPlugin$LifecycleCallbacks.onActivityStarted (AudiofileplayerPlugin.java:32) at android.app.Application.dispatchActivityStarted (Application.java:425) at android.app.Activity.dispatchActivityStarted (Activity.java:1260) at android.app.Activity.onStart (Activity.java:1747) at io.flutter.app.FlutterActivity.onStart (FlutterActivity.java) at android.app.Instrumentation.callActivityOnStart (Instrumentation.java:1433) at android.app.Activity.performStart (Activity.java:7980) at android.app.ActivityThread.handleStartActivity (ActivityThread.java:3578) at android.app.servertransaction.TransactionExecutor.performLifecycleSequence (TransactionExecutor.java:221) at android.app.servertransaction.TransactionExecutor.cycleToPath (TransactionExecutor.java:201) at android.app.servertransaction.TransactionExecutor.executeLifecycleState (TransactionExecutor.java:173) at android.app.servertransaction.TransactionExecutor.execute (TransactionExecutor.java:97) at android.app.ActivityThread$H.handleMessage (ActivityThread.java:2220) at android.os.Handler.dispatchMessage (Handler.java:107) at android.os.Looper.loop (Looper.java:237) at android.app.ActivityThread.main (ActivityThread.java:8016) at java.lang.reflect.Method.invoke (Method.java) at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:493) at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:1076)

[arodriguezgb]

Something I just noticed is that these ANR's mostly happen on Galaxy Devices.

[arodriguezgb]

@monkeyswarm
I found this while looking at the link you provided.
https://stackoverflow.com/questions/44425584/context-startforegroundservice-did-not-then-call-service-startforeground

Maybe there something worth it here..
https://issuetracker.google.com/issues/76112072#comment56

I think it validates the point that I see this happening on a lot of samsung devices, sadly i dont have one to test, and I cant reproduce it on my pixel. Im trying to borrow a galaxy device to see if I can reproduce it and help you better with this. Meanwhile this may help for a solution on the plugin ?

I dont think its 100% specific because the users that have emailed support are not restarting the device and then rapidly trying to play a song, but something must be happening.

Hi ya'll,

I found this thread super useful. I also saw that it was especially common on Samsung devices out in the field. And I think it has allowed me to construct a workaround that completely hides this problem. I'm posting it here in case it is useful for my sister/brother android devs ;-).

I think for many usecases people are calling startForegroundService in a BOOT_COMPLETE receiver (in my case so I can start talking to a bluetooth device). Unfortunately that first 30 seconds or so of an Android boot is a very busy time - with lots of threads starting and running. It is completely plausible that if you try to start your service that early , your service will start running and then end up blocked for a long time (because of some thread outside of your control) and you'll hit that dreaded timeout.

My workaround is to use the new WorkManager to push my service start later - about 1 minute later. After the phone isn't so hot with everyone else starting up. Here's the code I used:

https://github.com/meshtastic/Meshtastic-Android/blob/407a38594f67c81d0e18f6a30298b9e8e75231ea/app/src/main/java/com/geeksville/mesh/service/MeshService.kt#L72-L102

[michaelspeedcode]

I'm having the same issue. Mostly with Samsung devices but also OnePlus and Realme 5pro. Same log output.
8 times on Android 10 and 1 time on Android 9.

Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{bfec06c u0 meditofoundation.medito/com.google.flutter.plugins.audiofileplayer.AudiofileplayerService}

I can maybe provide more info if need be.

[arodriguezgb]

Caused by: java.lang.NullPointerException: at com.google.flutter.plugins.audiofileplayer.AudiofileplayerService.onStartCommand (AudiofileplayerService.java:7) at android.app.ActivityThread.handleServiceArgs (ActivityThread.java:4087) at android.app.ActivityThread.access$1800 (ActivityThread.java:219) at android.app.ActivityThread$H.handleMessage (ActivityThread.java:1891) at android.os.Handler.dispatchMessage (Handler.java:107) at android.os.Looper.loop (Looper.java:214) at android.app.ActivityThread.main (ActivityThread.java:7356) at java.lang.reflect.Method.invoke (Method.java) at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:492) at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:930)

There is also a crash increasing steadily in numbers in here. 45 reports in the last 7 days.

@OverRide
public int onStartCommand(final Intent intent, int flags, int startId) {
Log.i(TAG, "onStartCommand");
if (Intent.ACTION_MEDIA_BUTTON.equals(intent.getAction())
&& intent.hasExtra(AudiofileplayerPlugin.CUSTOM_MEDIA_BUTTON_EXTRA_KEY)) {
// Check for custom button intent.
handleCustomButtonIntent(intent);
} else {
// If there is a KeyEvent in the intent, send it to the MediaButtonReceiver to pass to
// its callbacks.
MediaButtonReceiver.handleIntent(mediaSession, intent);
}
return super.onStartCommand(intent, flags, startId);
}

[arodriguezgb]

Im taking a look at source code to see if I can help with the null pointer crash on Start Command, its causing like 165 crashes daily, a few angry people on reviews already.

If anyone else has any ideas let me know.

@michaelspeedcode
If you find any ways to mitiagate both these issues let me know aswell please. Thanks

[arodriguezgb]

@monkeyswarm

I found this while researching more about the foreground issue on Android 8+

https://www.theandroiddeveloper.com/post/context-startforegroundservice-did-not-then-call-service-startforeground

[monkeyswarm]

Thanks for looking into this. You mentioned something about bluetooth tasks on startup, I forget where that was mentioned. How (or when) does your app attempt to launch the service while backgrounded? I guess I was always assuming that the service would start when the activity was foregrounded, and the user hit, for example, a 'play' button. Does your app do something different?

…

On Mon, May 18, 2020 at 2:08 PM arodriguezgb ***@***.***> wrote: @monkeyswarm <https://github.com/monkeyswarm> I found this while researching more about the foreground issue on Android 8+ https://www.theandroiddeveloper.com/post/context-startforegroundservice-did-not-then-call-service-startforeground — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#72 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAJNRCYTEP5AXGSG3ZZKAB3RSGPUZANCNFSM4M7MZO6A> .

[monkeyswarm]

(I see it wasn't you, but someone you quoted, who mentioned a background task with bluetooth...)

[arodriguezgb]

Yeah @monkeyswarm , nothing to do with me it was a quote.

But my app is a meditation app, the user select the song he wants to listen, and then we go to the player and start playing that song. From my understanding this all happens in the foreground.

For the NullPointer crash I did a null check on Intent and then a null check on mediaSession. Its been 19 hours since I rolled out this and no crashes yet, but its too soon to tell. So I will have to update you later. if it works ill do a pull request to this repo.

` public int onStartCommand(final Intent intent, int flags, int startId) {
Log.i(TAG, "onStartCommand");

if (intent != null){
  if (Intent.ACTION_MEDIA_BUTTON.equals(intent.getAction())
          && intent.hasExtra(AudiofileplayerPlugin.CUSTOM_MEDIA_BUTTON_EXTRA_KEY)) {
    // Check for custom button intent.
    handleCustomButtonIntent(intent);
  } else {
    // If there is a KeyEvent in the intent, send it to the MediaButtonReceiver to pass to
    // its callbacks.
    if (mediaSession != null){
      MediaButtonReceiver.handleIntent(mediaSession, intent);
    }
  }
}
return super.onStartCommand(intent, flags, startId);

}
`

But as for the ANR I have no idea , i see lots of discussions on this topic that the foreground service has to be called onStart as well as onStartCommand, and few other things. But yeah i'm not sure how to fix it atm.

edit: If you would like later we can do a quick screen sharing session so you can see anything that happens on the app etc, if that helps. Or anything you need me to test or try.

[arodriguezgb]

@monkeyswarm One of the users responded me with what happens. It's a Samsung Galaxy S9 (starqltesq), 3584MB RAM, Android 10.

This is what happens as soon as the user clicks on a song and it "STARTS PLAYING as you can see the app is on the foreground.

[monkeyswarm]

I have a Samsung S9, I'll install the app and see if I can repro and get logs.

[arodriguezgb]

@monkeyswarm
If you need an account so you don't have to go thru all the process let me know. Ill email it to you if you want.

[monkeyswarm]

Yes, please send me an account or redeem code (to my email directly)

[arodriguezgb]

@monkeyswarm done sent you an email with the account.

[arodriguezgb]

Its been 5 days since I rolled out the null pointer fix and there is no crashes regarding to that. So its safe to assume its good. On the ANR part the new version already has around 56 occurences but im not sure what to do.

edit:
I created a pull request with the null pointer changes.

[arodriguezgb]

[arodriguezgb]

@monkeyswarm Im testing a few things from stack. Luckily the user that was having these issues said she could test a beta i'm rolling out today, if that fixes the issues ill let you know the code and see where we can go from there. Because the fix creates a notification onCrete so that the services is not killed because startForeground was not called 5 seconds after starting. Im not sure at all this will work, but at this stage if the user is willing to test, im up for testing a few things from stack.

Even tho its not ideal to create a notification when they launch the app, but we atleast we weill know if this fixes the issue.

[arodriguezgb]

There is also another crash but with MUCH LESS occurence. It's about DART REPLY. It happens on the onError method. I will try to fix that one as well.

Doing a try & catch on the onError should fix it that way if it fails it doesn't crash the app.

[arodriguezgb]

@monkeyswarm

No new occurrence of the DART REPLY CRASH on audioFilePlayer's RemoteManagedMediaPlayer on ERROR method.

It doesn't mean it's not happening, but the try and catch is helping the app not to crash when it happens.

This is basically what I did to stop it, i have not made a commit / pull request because I am not sure that will be an acceptable fix for you ? But it works fine in stopping the dart reply crashes on my end that I posted above this message.

@Override public boolean onError(MediaPlayer mp, int what, int extra) { try { onRemoteLoadListener.onRemoteLoadComplete(false); } catch(Exception e) { // Block of code to handle errors } return super.onError(mp, what, extra); }

Edit: Sadly the ANR is occurring but the user that was going to help test never answered again the support emails. So i still don't know how to fix it.

[arodriguezgb]

@monkeyswarm This is still happening on 1.3.3

I was reading again and found someone that says that found a solution and has completely fixed this. I was thinking on trying it myself on a fork, but maybe with your knowledge you know better when reading the answer.

Thanks again.

Here is a link to the answer.
https://stackoverflow.com/a/58528446

There are the predominant issues on 1.3.3 atleast on my end. One of those I already pushed a PR with a fix for the Dart Reply Crash.

[arodriguezgb]

@monkeyswarm Have you had the chance to look at the Stack Thread ? Thanks

[felixferr]

Same issue on samsung Galaxy S10 android version 11.

On the 1.3.3 version audiofileplayer

[AdityaABP]

I am facing the same issue as Context.startForegroundService() did not then call Service.startForeground(): in Android 11. its drop my app.
Please help @monkeyswarm and other developer guys.
thanks in Advance

[alenloncaric]

Guys did you ever found the solution to this Context.startForegroundService() did not then call Service.startForeground():