Ordering of AnalyticsListener causes assert in PlaybackStatsListener

[stevemayhew]

Issue description

The PlaybackStatsListener should work correctly no matter what order it is added to the SimpleExoPlayer.addAnalyticsListener() in relation to other AnalyticsListener objects.

Reproduction steps

Sorry I don't have an easy example to share, but here is a code sample that will reproduce the issue:

1. Create a playlist with an error (404 on a segment for example)
2. Add code to "recover" this error, as follows:

      player =
          new SimpleExoPlayer.Builder(/* context= */ this, renderersFactory)
              .setTrackSelector(trackSelector)
              .build();
      player.addListener(new PlayerEventListener());
...
      player.addAnalyticsListener(new EventLogger(trackSelector));
      player.addAnalyticsListener(new AnalyticsListener() {
        @Override
        public void onPlayerError(EventTime eventTime, ExoPlaybackException error) {
          player.retry();
          player.seekTo(2000);
        }
      });
      player.addAnalyticsListener(new PlaybackStatsListener(true, null));

The recovery "seek's" past the error (assume something in the error tells it where to seek too).

PlaybackStatsListener now will field the onPlayerError() event after the seek, see the comment in the PlaybackStatsListener commit

The assertion that fails is marked here

Seems this check implies a seek during error handling is a legit thing:

      } else if (isSeeking) {
        // Seeking takes precedence over errors such that we report a seek while in error state.
        return PlaybackStats.PLAYBACK_STATE_SEEKING;

But the assert here assumes events are delivered in order, which in this case they are not:

    private void maybeUpdatePlaybackState(EventTime eventTime, boolean belongsToPlayback) {
      @PlaybackState int newPlaybackState = resolveNewPlaybackState();
      if (newPlaybackState == currentPlaybackState) {
        return;
      }

      Assertions.checkArgument(eventTime.realtimeMs >= currentPlaybackStateStartTimeMs);

Link to test content

Sorry I don't have any, but content that fails with a 404 on a segment would do it. Anything that creates a PlayerError.

A full bug report captured from the device

Probably not that useful.

Version of ExoPlayer being used

r2.11.8

Device(s) and version(s) of Android being used

Arris STB running Android P

[tonihei]

Thanks! I'm able to reproduce that.

In theory, all Player.EventListener callbacks should always arrive in the order in which they are called even if they are called from the callbacks themselves. We even have an internal notification queue to resolve this notification recursion.

The problem is that PlaybackStatsListener is listening to onSeekStarted which is called from SimpleExoPlayer and is not channeled through our listener notification queue (because it's not part of Player.EventListener, only AnalyticsListener).

Similar cases may arise if other non-Player.EventListener callbacks are triggered in another callback. For example:

@Override
public void onPlayerError(EventTime eventTime, ExoPlaybackException error) {
  simpleExoPlayer.clearVideoSurface();
}

The callback for onSurfaceSizeChanged(eventTime, 0, 0) will also arrive before the onPlayerError for AnalyticsListeners that are later in the list.

The fix is to use the same queue mechanism we have for Player.EventListener for the AnalyticsListener callbacks as well. Once we've done that the assertion in PlaybackStatsListener failing in your example shouldn't possibly fail anymore.

[stevemayhew]

Yes, that sounds exactly correct. Pretty much every EventQueue design carries the assumption that reentrance is prevented. Thanks, glad it was possible to reproduce

…

On Wed, Oct 7, 2020 at 9:21 AM tonihei ***@***.***> wrote: Thanks! I'm able to reproduce that. In theory, all Player.EventListener callbacks should always arrive in the order in which they are called even if they are called from the callbacks themselves. We even have an internal notification queue to resolve this notification recursion. The problem is that PlaybackStatsListener is listening to onSeekStarted which is called from SimpleExoPlayer and is not channeled through our listener notification queue (because it's not part of Player.EventListener, only AnalyticsListener). Similar cases may arise if other non-Player.EventListener callbacks are triggered in another callback. For example: @OverRide public void onPlayerError(EventTime eventTime, ExoPlaybackException error) { simpleExoPlayer.clearVideoSurface(); } The callback for onSurfaceSizeChanged(eventTime, 0, 0) will also arrive before the onPlayerError for AnalyticsListeners that are later in the list. The fix is to use the same queue mechanism we have for Player.EventListener for the AnalyticsListener callbacks as well. Once we've done that the assertion in PlaybackStatsListener failing in your example shouldn't possibly fail anymore. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#8048 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AADBF6GGSGIYX3GWYXHZ5VDSJSIQ7ANCNFSM4SGRS4SA> .

[ojw28]

As a more general point, I would argue that AnalyticsListener implementations are not really expected to modify the player. The name of the interface very much suggests that implementations are for analytics logging, rather than for doing something like triggering a player retry. Player.EventListener seems much more suitable for doing that, and if you were to use it then I don't think you'd have this problem. Is there a reason for not just doing that instead?

[stevemayhew]

Thanks @ojw28, excellent point. We have been implementing AnalyticsListener for our error recovery logic (recover from issues like BehindLiveWindowException) but semantically EventListener does make more sense. All we need to complete recovery is the timeline event for the prepare completion (in some cases it would be good to know position is moving forward, but we can use timed checks for this).

@tonihei the AnalyticsCollector is added as an Player.EventListener by ExoPlayerImpl.java line 166, so if after construction the client adds an error handler Player.EventListener this listener's onPlayerError will be called after any listeners on AnalyticsCollector.

So the order (on error) would be:

1. AnalyticsCollector.onPlayerError() - the PlaybackStatsListener in this case
2. Player.EventListener.onPlayerError() - as declared in the error handler, which issues a retry(), seek( ) in this use case
3. AnalyticsCollector.onSeekStarted() - the PlaybackStatsListener in this case

This sequence prevents the bug. If you do anything to "fix" this bug, I would either:

1. Add code to check and warn or prevent users from doing this, code like:

  @Override
  public final void onPlayerError(ExoPlaybackException error) {
    @Player.State int preDispatchState = player.getPlaybackState();
    EventTime eventTime = generateLastReportedPlayingMediaPeriodEventTime();
    for (AnalyticsListener listener : listeners) {
      listener.onPlayerError(eventTime, error);
    }
    Assertions.checkArgument(preDispatchState == player.getPlaybackState(), 
            "State altered by AnalyticsListner, Use Player.EventListener for error recovery");
  }

2. Update the java doc to the AnalyticsCollector.onPlayerError() warn this should not be done.

@tonihei This error recovery works against what PlaybackStatsListener does for QOE, as if the client recovers the error, it will still look like a new session. Perhaps the easiest way is to add an option to the PlaybackStatsListener, like endSessionOnError and an API for the client to call directly if it's error handling decides the ExoPlaybackException was un-recoverable.

Your guys call, with @ojw28 suggestion I've worked around the bug... But, don't miss the chance to stop someone else from stepping in this hole, it is easy to miss (I did, and I've looked at a lot of ExoPlayer code).

If you choose to do 2, here's a pull #8068 (might want to do something on the method too). Option 1 might catch people off guard that have this working by shear luck.

[tonihei]

As a more general point, I would argue that AnalyticsListener implementations are not really expected to modify the player.

This is implied by the name and may not have been the original intention, but I wouldn't argue it's not expected. Especially in cases where apps want to combine multiple types of listeners together and/or are interested in the EventTime values, using AnalyticsListener is the obvious choice.

By this argument, I'd be in favour of solving the original problem instead of documenting it's not supported (people won't read that) or asserting it (that will annoy people unnecessarily).

Perhaps the easiest way is to add an option to the PlaybackStatsListener, like endSessionOnError and an API for the client to call directly if it's error handling decides the ExoPlaybackException was un-recoverable.

The session doesn't end on error if I remember correctly. It only ends once you set new media items on the player or call stop. So if you call player.retry() from onPlayerError, the PlaybackStatsListener will record a PLAYBACK_STATE_FAILED after the error and PLAYBACK_STATE_BUFFERING after the retry.

[stevemayhew]

By this argument, I'd be in favour of solving the original problem instead of documenting it's not supported (people won't read that) or asserting it (that will annoy people unnecessarily).

I do think people read documentation, especially to get the general flavor of things that you can't get without a pretty deep inspection of the code (like when to use what listeners).

@tonihei Looks like fixing it is pretty simple (especially if it's just the seek, which is the original issue) then definitely you should do it.

[tonihei]

Issue was fixed by the commit above.