Exoplayer: The ongoing parameter of onNotificationPosted does not indicate to put the service in foreground

[tosam144]

EDIT:

I suspect that onNotificationPosted is not posted because the phone app's notification during the call is in place and thus, Exoplayer cannot post its notfication. Thus, onNotificationPosted is not called. Could that be the reason? If yes, where else would be an appropriate place to make a call to startForeground and stopForeground if not in onNotificationPosted?

* EDIT END *

I am streaming mp3s using Exoplayer. I have an AudioPlayerService which is started via Util.startForegroundService. The service creates the player instance and registers the notfications like this:

        PlayerNotificationManager.NotificationListener notificationListener = new PlayerNotificationManager.NotificationListener() {
            @Override
            public void onNotificationCancelled(int notificationId, boolean dismissedByUser) {
                if (dismissedByUser) {
                    stopService();
                    sendBroadcast(new Intent(Constants.FINISH_ACTION));
                } else {
                    // It seems the system killed the service
                    AudioUtils.saveCurrentMediaState(player.getCurrentWindowIndex(), player.getCurrentPosition(), AudioPlayerService.this);
                }
            }

            @Override
            public void onNotificationPosted(int notificationId, Notification notification, boolean ongoing) {
                if (!ongoing) {
                    stopForeground(false);
                } else {
                    startForeground(notificationId, notification);
                }
            }
        };

Now, this is the problem: When the user starts an mp3 during a phone call, Util.startForegroundService is called as expected but onNotificationPosted is never called (I verified this in the debugger). As a result, stopForeground is not called which leads to the crash RemoteServiceException: Context.startForegroundService() did not then call Service.startForeground().

Steps to reproduce:
1) Start a phone call.
2) Start an mp3 within a service using Util.startForegroundService.
3) Crash.

Of course, the scenario is hypothetical because nobody will start an mp3 during a phone call. However, this could happen accidentally and the app is not supposed to crash.

Do I have to check in my app if there is a phone call going on and - if yes - not call startForegroundService? Or what am I supposed to do to catch this error?

Please note that wihtout an active phone call, everything works as expected.

Here is my Logcat containing the crash (during a phone call):

--------- beginning of main
09-23 16:59:38.535  7513  7513 D ViewRootImpl@c873f2d[PlayerActivity]: ViewPostIme key 0
09-23 16:59:38.597  7513  7513 D ViewRootImpl@c873f2d[PlayerActivity]: ViewPostIme key 1
09-23 16:59:38.625  7513  7717 V FA      : Recording user engagement, ms: 75624
09-23 16:59:38.631  7513  7513 D ViewRootImpl@c873f2d[PlayerActivity]: MSG_WINDOW_FOCUS_CHANGED 0
09-23 16:59:38.634  7513  7717 V FA      : Connecting to remote service
09-23 16:59:38.640  7513  7717 V FA      : Activity paused, time: 96545547
09-23 16:59:38.645  7513  7717 D FA      : Event not sent since app measurement is disabled
09-23 16:59:38.646  7513  7717 V FA      : Activity resumed, time: 96545570
09-23 16:59:38.661  7513  7717 D FA      : Event not sent since app measurement is disabled
09-23 16:59:38.662  7513  7717 V FA      : Connection attempt already in progress
09-23 16:59:38.680  7513  7513 W StaticLayout: maxLineHeight should not be -1.  maxLines:1 lineCount:1
09-23 16:59:38.697  7513  7513 I chatty  : uid=10325(u0_a325) identical 2 lines
09-23 16:59:38.705  7513  7513 W StaticLayout: maxLineHeight should not be -1.  maxLines:1 lineCount:1
09-23 16:59:38.739  7513  7513 W StaticLayout: maxLineHeight should not be -1.  maxLines:1 lineCount:1
09-23 16:59:38.771  7513  7513 I chatty  : uid=10325(u0_a325) identical 2 lines
09-23 16:59:38.771  7513  7513 W StaticLayout: maxLineHeight should not be -1.  maxLines:1 lineCount:1
09-23 16:59:38.794  7513  7513 V Surface : sf_framedrop debug : 0x4f4c, game : false, logging : 0
09-23 16:59:38.794  7513  7513 D ViewRootImpl@e1e5a9[AudioListActivity]: Relayout returned: old=[0,0][1080,1920] new=[0,0][1080,1920] result=0x7 surface={valid=true 506447368192} changed=true
09-23 16:59:38.800  7513  7570 D mali_winsys: EGLint new_window_surface(egl_winsys_display *, void *, EGLSurface, EGLConfig, egl_winsys_surface **, egl_color_buffer_format *, EGLBoolean) returns 0x3000,  [1080x1920]-format:1
09-23 16:59:38.800  7513  7570 D OpenGLRenderer: eglCreateWindowSurface = 0x75f2c296e0
09-23 16:59:38.804  7513  7513 D ViewRootImpl@e1e5a9[AudioListActivity]: MSG_WINDOW_FOCUS_CHANGED 1
09-23 16:59:38.807  7513  7513 V InputMethodManager: Starting input: tba=android.view.inputmethod.EditorInfo@a658586 nm : de.widmer.offerings.activities ic=null
09-23 16:59:38.807  7513  7513 I InputMethodManager: startInputInner - mService.startInputOrWindowGainedFocus
09-23 16:59:38.839  7513  7717 D FA      : Connected to remote service
09-23 16:59:38.841  7513  7717 V FA      : Processing queued up service tasks: 2
09-23 16:59:38.848  7513  7570 D OpenGLRenderer: eglDestroySurface = 0x75dae6f550
09-23 16:59:38.854  7513  7513 D ViewRootImpl@c873f2d[PlayerActivity]: Relayout returned: old=[0,0][1080,1920] new=[0,0][1080,1920] result=0x5 surface={valid=false 0} changed=true
09-23 16:59:39.303  7513  7513 D ViewRootImpl@c873f2d[PlayerActivity]: dispatchDetachedFromWindow
09-23 16:59:39.303  7513  7513 D InputEventReceiver: channel 'c6a9fa7 de.widmer.offerings.activities/de.widmer.offerings.activities.PlayerActivity (client)' ~ Disposing input event receiver.
09-23 16:59:39.303  7513  7513 D InputEventReceiver: channel 'c6a9fa7 de.widmer.offerings.activities/de.widmer.offerings.activities.PlayerActivity (client)' ~NativeInputEventReceiver.
09-23 16:59:39.321  7513  7513 I ExoPlayerImpl: Release 4c5a129 [ExoPlayerLib/2.12.0] [herolte, SM-G930F, samsung, 26] [goog.exo.core, goog.exo.ui, goog.exo.mediasession, goog.exo.cronet]
09-23 16:59:39.323  7513  7617 I ACodec  : [OMX.google.mp3.decoder] signalFlush
09-23 16:59:39.325  7513  7719 D AudioTrack: stop() called with 0 frames delivered
09-23 16:59:39.325  7513  7617 I ACodec  : [OMX.google.mp3.decoder] ExecutingState flushing now (codec owns 4/4 input, 0/4 output).
09-23 16:59:39.325  7513  7719 I AudioTrack: updateAudioTranstionLength FadeIn[0] FadeOut[0] FadeInRing[0]
09-23 16:59:39.326  7513  7617 I ACodec  : [OMX.google.mp3.decoder] Now Flushing
09-23 16:59:39.326  7513  7617 I ACodec  : [OMX.google.mp3.decoder] FlushingState onOMXEvent(0,1,0)
09-23 16:59:39.326  7513  7617 I ACodec  : [OMX.google.mp3.decoder] FlushingState onOMXEvent(0,1,1)
09-23 16:59:39.327  7513  7617 I ACodec  : [OMX.google.mp3.decoder] Now Executing
09-23 16:59:39.329  7513  7617 I ACodec  : [OMX.google.mp3.decoder] Now Executing->Idle
09-23 16:59:39.334  7513  7617 I ACodec  : [OMX.google.mp3.decoder] Now Idle->Loaded
09-23 16:59:39.334  7513  7617 I ACodec  : [OMX.google.mp3.decoder] Now Loaded
09-23 16:59:39.335  7513  7617 I ACodec  :  [OMX.google.mp3.decoder] Now uninitialized
09-23 16:59:39.335  7513  7617 I ACodec  :  [] Now kWhatShutdownCompleted event : 8483
09-23 16:59:39.336  7513  7617 I MediaCodec: Codec shutdown complete
09-23 16:59:39.403  7513  7518 I zygote64: Do full code cache collection, code=503KB, data=338KB
09-23 16:59:39.405  7513  7518 I zygote64: After code cache collection, code=468KB, data=269KB
09-23 16:59:39.406  7513  7513 D AndroidRuntime: Shutting down VM
--------- beginning of crash
09-23 16:59:39.411  7513  7513 E AndroidRuntime: FATAL EXCEPTION: main
09-23 16:59:39.411  7513  7513 E AndroidRuntime: Process: de.widmer.offerings.activities, PID: 7513
09-23 16:59:39.411  7513  7513 E AndroidRuntime: android.app.RemoteServiceException: Context.startForegroundService() did not then call Service.startForeground()
09-23 16:59:39.411  7513  7513 E AndroidRuntime:    at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1881)
09-23 16:59:39.411  7513  7513 E AndroidRuntime:    at android.os.Handler.dispatchMessage(Handler.java:105)
09-23 16:59:39.411  7513  7513 E AndroidRuntime:    at android.os.Looper.loop(Looper.java:164)
09-23 16:59:39.411  7513  7513 E AndroidRuntime:    at android.app.ActivityThread.main(ActivityThread.java:6944)
09-23 16:59:39.411  7513  7513 E AndroidRuntime:    at java.lang.reflect.Method.invoke(Native Method)
09-23 16:59:39.411  7513  7513 E AndroidRuntime:    at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:327)
09-23 16:59:39.411  7513  7513 E AndroidRuntime:    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1374)
09-23 17:00:06.123  7742  7742 W SELinux : SELinux selinux_android_compute_policy_index : Policy Index[2],  Con:u:r:runas:s0 RAM:SEPF_SM-G930F_8.0.0_0018, [-1 -1 -1 -1 0 1]
09-23 17:00:06.126  7742  7742 I SELinux : SELinux: seapp_context_lookup: seinfo=untrusted, level=s0:c512,c768, pkgname=de.widmer.offerings.activities 
09-23 17:00:06.464  7758  7758 W SELinux : SELinux selinux_android_compute_policy_index : Policy Index[2],  Con:u:r:zygote:s0 RAM:SEPF_SM-G930F_8.0.0_0018, [-1 -1 -1 -1 0 1]
09-23 17:00:06.465  7758  7758 I SELinux : SELinux: seapp_context_lookup: seinfo=untrusted, level=s0:c512,c768, pkgname=de.widmer.offerings.activities 
09-23 17:00:06.467  7758  7758 I zygote64: Late-enabling -Xcheck:jni
09-23 17:00:06.515  7758  7758 D TimaKeyStoreProvider: TimaKeyStore is not enabled: cannot add TimaSignature Service and generateKeyPair Service
09-23 17:00:06.516  7758  7758 D ActivityThread: Added TimaKeyStore provider

[marcbaechinger]

Interesting case. I agree we should not crash.

Is onNotificationPosted not called at all, or is it called with ongoing == false?

I'm asking because I'd expect that the phone call should not make a difference regarding preparing the player. It probably does not allow to set playWhenReady to true, but it should prepare normally and enter STATE_BUFFERING and 'STATE_READY'. But when playWhenReady is false, ongoing is false either. Your code suggest that would result in the RemoteServiceException.

If that was the case you had to check for that corner-case with a flag somehow and call startForeground either way.

Please let me know. I'm glad to look into this if the callback is not called at all. In this case I would expect some other stack traces somewhere reporting that something went wrong.

[tosam144]

Yes, onNotificationPosted never gets called. That's the problem. I have created a minimal Android project with which you can easily reproduce this behavior:

EPTest.zip

The steps are:

1) Launch the app on the test device.
2) Initiate a phone call to the test device.
3) Set a breakpoint in onNotificationPosted.
4) Press the "Button" to start the audio playing.

The breakpoint is never reached. If, however, you try without the phone call, it works.

Please also note that you must use a real device. It does not work on an Emulator. I am using a Samsung S7 with Android 8 for testing. Also, it has to be the phone app (not skype or so).

Let me know what you find. Thanks.

[marcbaechinger]

Thanks for confirming! I look into that. Can you send me a bug report right after you did that with your app? I can test with the demo app.

[tosam144]

Attached is the bug report with:
1) Incoming phone call active
2) Start streaming using startForegroundService

bugreport-2020-09-24-18-23-04.zip

Thanks for looking into it. Hope it can be soon as we a re right before our app release :-)

[marcbaechinger]

It's very odd. As I expected, ExoPlayer prepares normally. It takes more than ten seconds from when the player is ready to when the service is shut down. The first notification should be posted when going to state BUFFERING. I look into this some closer. Thanks!

09-24 18:22:29.402 10325  6044  6044 I ExoPlayerImpl: Init e4aef48 [ExoPlayerLib/2.12.0] [herolte, SM-G930F, samsung, 26]
...
09-24 18:22:29.589 10325  6044  6044 D EventLogger: state [eventTime=0.17, mediaPos=0.00, window=0, BUFFERING]
...
09-24 18:22:42.121  1000  3672  3700 E ActivityManager: Reason: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{66bb044 u0 xxx.activities/xxx.AudioPlayerService}

[tosam144]

According to Android docs, startForeground must be called within 5 seconds before an exception is thrown:

The new Context.startForegroundService() method starts a foreground service. The system allows apps to call Context.startForegroundService() even while the app is in the background. However, the app must call that service's startForeground() method within five seconds after the service is created.

Not sure if that is the reason for the 10 seconds delay you were talking about.

As I said, I suspect that the phone app's notification during active calls does not allow Exoplayer to post its notification for some reason.

[marcbaechinger]

I can reproduce the behaviour of the app crashing with the onNotificationPosted callback like you have it. However, I can fix that with the following code:

new PlayerNotificationManager.NotificationListener() {
              @Override
              public void onNotificationPosted(
                  int notificationId, Notification notification, boolean ongoing) {
                if (ongoing || !startedInForeground) {
                  startedInForeground = true;
                  startForeground(notificationId, notification);
                } else {
                  stopForeground(/* removeNotification= */ false);
                }
              }

              @Override
              public void onNotificationCancelled(int notificationId, boolean dismissedByUser) {
                stopSelf();
              }
            });

This means that the callback is called with ongoing=false which is a consequence of ExoPlayer not being able to grab the audio focus while a phone call. When I change the code as above it works for me.

[marcbaechinger]

Our messages just crossed :)

if that is the reason for the 10 seconds delay you were talking about.

Yes, sure that's the reason for the delay. I was wondering whether the phone call makes this delay shorter and ExoPlayer does not have time to place the notification. But with that delay it should work as expected. My testing with the code abuve shows actually that my guess seems to be true.

As I said, I suspect that the phone app's notification during active calls does not allow Exoplayer to post its notification for some reason.

The notification is posted with notificationId 1 as expected. This makes the callback being called but with ongoing=false. May I ask you to test with that code and probably add some logging:

new PlayerNotificationManager.NotificationListener() {
  @Override
  public void onNotificationPosted(
      int notificationId, Notification notification, boolean ongoing) {
    Log.d("audio-player", "onNotificationPosted called: " + ongoing);
    if (ongoing || !startedInForeground) {
      Log.d("audio-player", "calling startForeground with notificationId "
          + notificationId);
      startedInForeground = true;
      startForeground(notificationId, notification);
    } else {
      Log.d("audio-player", "calling stopForeground with notificationId "
          + notificationId);
      stopForeground(/* removeNotification= */ false);
    }
  }

  @Override
  public void onNotificationCancelled(int notificationId, boolean dismissedByUser) {
    Log.d("audio-player", "calling stopSelf in onNotificationCancelled");
    stopSelf();
  }
});

[tosam144]

Yeah, I saw our messages crossing :-)

Sure I can add the code to onNotificationPosted but the problem is, it does not get called, so it doesn't matter what I put in. I am testing with the small testing app I have attached in my previous comment.

[tosam144]

OK, I have to revise my comment. You're right, with your code in place the app does not crash anymore. Here is the new bug report:

bugreport-2020-09-24-21-38-33.zip

[marcbaechinger]

Perfect! That should help for your release! :) I already have a fix in place to make sure that ongoing is always true for the first notification. That should remove the problem even without that flag. Thanks for reporting and helping diagnosing!

[tosam144]

Great, good news. I am just surprised that for example an active call with skype won't cause this behavior, just the phone app?!

When are you going to release the fix?

[marcbaechinger]

I think it will land on dev-2 pretty soon I think. Latest early next week or so. This issue will be updated with the commit number. I'm not sure when this will land in the release branch though.

Sorry in advance if it won't be soon enough for your release. But if you place the flag as above there will be no harm even if you don't remove it once you update. :)

[marcbaechinger]

This does the trick in PlayerNotificationManager. No guarantee that this is what lands in the source tree though. But if you want to compile it yourself, that should work.

/library/ui/src/main/java/com/google/android/exoplayer2/ui/PlayerNotificationManager.java 
--- 
+++ 
@@ -989,7 +989,6 @@ public class PlayerNotificationManager {
     Notification notification = builder.build();
     notificationManager.notify(notificationId, notification);
     if (!isNotificationStarted) {
-      isNotificationStarted = true;
       context.registerReceiver(notificationBroadcastReceiver, intentFilter);
       if (notificationListener != null) {
         notificationListener.onNotificationStarted(notificationId, notification);
@@ -997,8 +996,10 @@ public class PlayerNotificationManager {
     }
     @Nullable NotificationListener listener = notificationListener;
     if (listener != null) {
-      listener.onNotificationPosted(notificationId, notification, ongoing);
+      listener.onNotificationPosted(
+          notificationId, notification, ongoing || !isNotificationStarted);
     }
+    isNotificationStarted = true;
   }

[tosam144]

Ok great, if your fix does the same thing, I won't wait. Thank you so much for your prompt and excellent help, @marcbaechinger !

[tosam144]

But if you want to compile it yourself, that should work.

No thanks. :-D

[marcbaechinger]

Marked as bug as we say the following in the JavaDoc of the onNotificationPosted callback: For a service, the {@code ongoing} flag can be used as an indicator as to whether it should be in the foreground.

[marcbaechinger]

Closing as the fix above landed in dev2. Please reopen if there are any other questions/issues.