Change how AnalyticsCollector forwards onPlayerReleased

Before releasing r2.15.0, we had a regression that crashed
PlaybackStatsListener. A change in the AnalyticsCollector made
it to send an additional AnalyticsListener.onEvents() callback after
calling Player.release() and AnalyticsListener.onEvents() appeared
to arrive with event times that were not monotonically increasing.
The AnalyticsListener.onEvents() callback that contained
AnalyticsListener.EVENT_PLAYER_RELEASED was called with a timestamp that
was smaller than event times of previously AnalyticsListener.onEvents()
calls.

A first fix changed the order of events being forwarded to
AnalyticsListener. Upon calling Player.release(), the AnalyticsCollector
would call AnalyticsListener.onPlayerReleased() and its associated
AnalyticsListener.onEvents() on the same stack call. This fix maintained
that event times are monotonically increasing, but made
AnalyticsListener.onPlayerReleased() be called earlier.

This change:
- Further changes AnalyticsCollector to ensure that
  AnalyticsListener.onPlayerReleased() and its related
  AnalyticsListener.onEvents() are the last callbacks to be called,
  and the associated timestamp is bigger than  previously reported
  event times.
- Adds an instrumentation test to guard against the regression.

PiperOrigin-RevId: 399437724

library/core/src/androidTest/java/com/google/android/exoplayer2/analytics/AnalyticsCollectorInstrumentationTest.java

@@ -0,0 +1,189 @@
+/*
+ * Copyright 2021 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package com.google.android.exoplayer2.analytics;
+
+import static com.google.common.truth.Truth.assertThat;
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.Mockito.argThat;
+import static org.mockito.Mockito.inOrder;
+import static org.mockito.Mockito.same;
+import static org.mockito.Mockito.spy;
+
+import android.app.Instrumentation;
+import androidx.test.ext.junit.runners.AndroidJUnit4;
+import androidx.test.platform.app.InstrumentationRegistry;
+import com.google.android.exoplayer2.C;
+import com.google.android.exoplayer2.ExoPlayer;
+import com.google.android.exoplayer2.MediaItem;
+import com.google.android.exoplayer2.PlaybackException;
+import com.google.android.exoplayer2.Player;
+import com.google.android.exoplayer2.Renderer;
+import com.google.android.exoplayer2.SimpleExoPlayer;
+import com.google.android.exoplayer2.util.Clock;
+import com.google.android.exoplayer2.util.ConditionVariable;
+import java.util.concurrent.atomic.AtomicLong;
+import java.util.concurrent.atomic.AtomicReference;
+import org.junit.Test;
+import org.junit.runner.RunWith;
+import org.mockito.ArgumentCaptor;
+import org.mockito.InOrder;
+
+/** Instrumentation tests for the {@link AnalyticsCollector} */
+@RunWith(AndroidJUnit4.class)
+public class AnalyticsCollectorInstrumentationTest {
+
+  /**
+   * This is a regression test against [internal ref: b/195396384]. The root cause of the regression
+   * was an introduction of an additional {@link AnalyticsListener#onEvents} callback inside {@link
+   * AnalyticsCollector} for callbacks that are queued during {@link Player#release}. The additional
+   * callback was called before {@link AnalyticsListener#onPlayerReleased} but its associated event
+   * real-time timestamps were greater than the real-time timestamp of {@link
+   * AnalyticsListener#onPlayerReleased}. As a result, the {@link AnalyticsListener#onEvents} that
+   * contained {@link AnalyticsListener#EVENT_PLAYER_RELEASED} had a real-time timestamp that was
+   * smaller than the timestamps of the previously forwarded events. That broke the {@link
+   * PlaybackStatsListener} which assumed that real-time event timestamps are always increasing.
+   *
+   * <p>The regression was easily reproduced in the demo app with a {@link PlaybackStatsListener}
+   * attached to the player and pressing back while the app was playing a video. That would make the
+   * app call {@link Player#release} while the player was playing, and it would throw an exception
+   * from the {@link PlaybackStatsListener}.
+   *
+   * <p>This test starts playback of an item and calls {@link Player#release} while the player is
+   * playing. The test uses a custom {@link Renderer} that queues a callback to be handled after
+   * {@link Player#release} completes. The test asserts that {@link
+   * AnalyticsListener#onPlayerReleased} is called after any callbacks queued during {@link
+   * Player#release} and its real-time timestamp is greater that the timestamps of the other
+   * callbacks.
+   */
+  @Test
+  public void releasePlayer_whilePlaying_onPlayerReleasedIsForwardedLast() throws Exception {
+    AtomicLong playerReleaseTimeMs = new AtomicLong(C.TIME_UNSET);
+    AtomicReference<PlaybackException> playerError = new AtomicReference<>();
+    AtomicReference<SimpleExoPlayer> player = new AtomicReference<>();
+    ConditionVariable playerReleasedEventArrived = new ConditionVariable();
+    AnalyticsListener analyticsListener =
+        spy(new TestAnalyticsListener(playerReleasedEventArrived));
+    Instrumentation instrumentation = InstrumentationRegistry.getInstrumentation();
+    instrumentation.runOnMainSync(
+        () -> {
+          player.set(new ExoPlayer.Builder(instrumentation.getContext()).build());
+          player
+              .get()
+              .addListener(
+                  new Player.Listener() {
+                    @Override
+                    public void onPlayerError(PlaybackException error) {
+                      playerError.set(error);
+                      player.get().release();
+                    }
+                  });
+          player.get().addAnalyticsListener(analyticsListener);
+          player.get().setMediaItem(MediaItem.fromUri("asset:///media/mp4/preroll-5s.mp4"));
+          player.get().prepare();
+          player.get().play();
+        });
+    waitUntilPosition(player.get(), /* positionMs= */ 1000);
+    instrumentation.runOnMainSync(
+        () -> {
+          player.get().release();
+          playerReleaseTimeMs.set(Clock.DEFAULT.elapsedRealtime());
+        });
+    playerReleasedEventArrived.block();
+
+    assertThat(playerError.get()).isNull();
+    assertThat(playerReleaseTimeMs).isNotEqualTo(C.TIME_UNSET);
+    InOrder inOrder = inOrder(analyticsListener);
+    ArgumentCaptor<AnalyticsListener.EventTime> onVideoDecoderReleasedArgumentCaptor =
+        ArgumentCaptor.forClass(AnalyticsListener.EventTime.class);
+    inOrder
+        .verify(analyticsListener)
+        .onVideoDecoderReleased(onVideoDecoderReleasedArgumentCaptor.capture(), any());
+    assertThat(onVideoDecoderReleasedArgumentCaptor.getValue().realtimeMs)
+        .isGreaterThan(playerReleaseTimeMs.get());
+    inOrder
+        .verify(analyticsListener)
+        .onEvents(
+            same(player.get()),
+            argThat(events -> events.contains(AnalyticsListener.EVENT_VIDEO_DECODER_RELEASED)));
+    ArgumentCaptor<AnalyticsListener.EventTime> onPlayerReleasedArgumentCaptor =
+        ArgumentCaptor.forClass(AnalyticsListener.EventTime.class);
+    inOrder.verify(analyticsListener).onPlayerReleased(onPlayerReleasedArgumentCaptor.capture());
+    assertThat(onPlayerReleasedArgumentCaptor.getAllValues()).hasSize(1);
+    assertThat(onPlayerReleasedArgumentCaptor.getValue().realtimeMs)
+        .isGreaterThan(onVideoDecoderReleasedArgumentCaptor.getValue().realtimeMs);
+    inOrder
+        .verify(analyticsListener)
+        .onEvents(
+            same(player.get()),
+            argThat(events -> events.contains(AnalyticsListener.EVENT_PLAYER_RELEASED)));
+  }
+
+  private static void waitUntilPosition(SimpleExoPlayer simpleExoPlayer, long positionMs)
+      throws Exception {
+    ConditionVariable conditionVariable = new ConditionVariable();
+    InstrumentationRegistry.getInstrumentation()
+        .runOnMainSync(
+            () -> {
+              simpleExoPlayer.addListener(
+                  new Player.Listener() {
+                    @Override
+                    public void onPlayerError(PlaybackException error) {
+                      conditionVariable.open();
+                    }
+                  });
+              simpleExoPlayer
+                  .createMessage((messageType, payload) -> conditionVariable.open())
+                  .setPosition(positionMs)
+                  .send();
+            });
+    conditionVariable.block();
+  }
+
+  /**
+   * An {@link AnalyticsListener} that blocks the thread on {@link
+   * AnalyticsListener#onVideoDecoderReleased} for at least {@code 1ms} and unblocks a {@link
+   * ConditionVariable} when an {@link AnalyticsListener#EVENT_PLAYER_RELEASED} arrives. The class
+   * is public and non-final so we can use it with {@link org.mockito.Mockito#spy}.
+   */
+  public static class TestAnalyticsListener implements AnalyticsListener {
+    private final ConditionVariable playerReleasedEventArrived;
+
+    public TestAnalyticsListener(ConditionVariable playerReleasedEventArrived) {
+      this.playerReleasedEventArrived = playerReleasedEventArrived;
+    }
+
+    @Override
+    public void onVideoDecoderReleased(EventTime eventTime, String decoderName) {
+      // Sleep for 1 ms so that the elapsedRealtime when the subsequent events
+      // are greater by at least 1 ms.
+      long startTimeMs = Clock.DEFAULT.elapsedRealtime();
+      try {
+        while (startTimeMs + 1 > Clock.DEFAULT.elapsedRealtime()) {
+          Thread.sleep(1);
+        }
+      } catch (InterruptedException e) {
+        throw new IllegalStateException(e);
+      }
+    }
+
+    @Override
+    public void onEvents(Player player, Events events) {
+      if (events.contains(AnalyticsListener.EVENT_PLAYER_RELEASED)) {
+        playerReleasedEventArrived.open();
+      }
+    }
+  }
+}

library/core/src/main/java/com/google/android/exoplayer2/analytics/AnalyticsCollector.java

@@ -16,6 +16,7 @@
 package com.google.android.exoplayer2.analytics;
 
 import static com.google.android.exoplayer2.util.Assertions.checkNotNull;
+import static com.google.android.exoplayer2.util.Assertions.checkState;
 import static com.google.android.exoplayer2.util.Assertions.checkStateNotNull;
 
 import android.os.Looper;
@@ -49,7 +50,6 @@ import com.google.android.exoplayer2.source.MediaSourceEventListener;
 import com.google.android.exoplayer2.source.TrackGroupArray;
 import com.google.android.exoplayer2.trackselection.TrackSelectionArray;
 import com.google.android.exoplayer2.upstream.BandwidthMeter;
-import com.google.android.exoplayer2.util.Assertions;
 import com.google.android.exoplayer2.util.Clock;
 import com.google.android.exoplayer2.util.HandlerWrapper;
 import com.google.android.exoplayer2.util.ListenerSet;
@@ -108,7 +108,7 @@ public class AnalyticsCollector
    */
   @CallSuper
   public void addListener(AnalyticsListener listener) {
-    Assertions.checkNotNull(listener);
+    checkNotNull(listener);
     listeners.add(listener);
   }
 
@@ -131,8 +131,7 @@ public class AnalyticsCollector
    */
   @CallSuper
   public void setPlayer(Player player, Looper looper) {
-    Assertions.checkState(
-        this.player == null || mediaPeriodQueueTracker.mediaPeriodQueue.isEmpty());
+    checkState(this.player == null || mediaPeriodQueueTracker.mediaPeriodQueue.isEmpty());
     this.player = checkNotNull(player);
     handler = clock.createHandler(looper, null);
     listeners =
@@ -148,15 +147,9 @@ public class AnalyticsCollector
    */
   @CallSuper
   public void release() {
-    EventTime eventTime = generateCurrentPlayerMediaPeriodEventTime();
-    eventTimes.put(AnalyticsListener.EVENT_PLAYER_RELEASED, eventTime);
-    sendEvent(
-        eventTime,
-        AnalyticsListener.EVENT_PLAYER_RELEASED,
-        listener -> listener.onPlayerReleased(eventTime));
-    // Release listeners lazily so that all events that got triggered as part of player.release()
-    // are still delivered to all listeners.
-    checkStateNotNull(handler).post(() -> listeners.release());
+    // Release lazily so that all events that got triggered as part of player.release()
+    // are still delivered to all listeners and onPlayerReleased() is delivered last.
+    checkStateNotNull(handler).post(this::releaseInternal);
   }
 
   /**
@@ -941,6 +934,15 @@ public class AnalyticsCollector
         player.getTotalBufferedDuration());
   }
 
+  private void releaseInternal() {
+    EventTime eventTime = generateCurrentPlayerMediaPeriodEventTime();
+    sendEvent(
+        eventTime,
+        AnalyticsListener.EVENT_PLAYER_RELEASED,
+        listener -> listener.onPlayerReleased(eventTime));
+    listeners.release();
+  }
+
   private EventTime generateEventTime(@Nullable MediaPeriodId mediaPeriodId) {
     checkNotNull(player);
     @Nullable

library/core/src/test/java/com/google/android/exoplayer2/analytics/AnalyticsCollectorTest.java

@@ -35,6 +35,7 @@ import static com.google.android.exoplayer2.analytics.AnalyticsListener.EVENT_ME
 import static com.google.android.exoplayer2.analytics.AnalyticsListener.EVENT_PLAYBACK_PARAMETERS_CHANGED;
 import static com.google.android.exoplayer2.analytics.AnalyticsListener.EVENT_PLAYBACK_STATE_CHANGED;
 import static com.google.android.exoplayer2.analytics.AnalyticsListener.EVENT_PLAYER_ERROR;
+import static com.google.android.exoplayer2.analytics.AnalyticsListener.EVENT_PLAYER_RELEASED;
 import static com.google.android.exoplayer2.analytics.AnalyticsListener.EVENT_PLAY_WHEN_READY_CHANGED;
 import static com.google.android.exoplayer2.analytics.AnalyticsListener.EVENT_POSITION_DISCONTINUITY;
 import static com.google.android.exoplayer2.analytics.AnalyticsListener.EVENT_RENDERED_FIRST_FRAME;
@@ -55,8 +56,11 @@ import static org.mockito.ArgumentMatchers.anyFloat;
 import static org.mockito.ArgumentMatchers.anyInt;
 import static org.mockito.ArgumentMatchers.anyLong;
 import static org.mockito.ArgumentMatchers.eq;
+import static org.mockito.Mockito.argThat;
 import static org.mockito.Mockito.atLeastOnce;
+import static org.mockito.Mockito.inOrder;
 import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.same;
 import static org.mockito.Mockito.spy;
 import static org.mockito.Mockito.verify;
 
@@ -102,6 +106,7 @@ import com.google.android.exoplayer2.testutil.ActionSchedule;
 import com.google.android.exoplayer2.testutil.ActionSchedule.PlayerRunnable;
 import com.google.android.exoplayer2.testutil.ExoPlayerTestRunner;
 import com.google.android.exoplayer2.testutil.FakeAudioRenderer;
+import com.google.android.exoplayer2.testutil.FakeClock;
 import com.google.android.exoplayer2.testutil.FakeExoMediaDrm;
 import com.google.android.exoplayer2.testutil.FakeMediaSource;
 import com.google.android.exoplayer2.testutil.FakeRenderer;
@@ -128,7 +133,6 @@ import org.junit.Test;
 import org.junit.runner.RunWith;
 import org.mockito.ArgumentCaptor;
 import org.mockito.InOrder;
-import org.mockito.Mockito;
 import org.robolectric.shadows.ShadowLooper;
 
 /** Integration test for {@link AnalyticsCollector}. */
@@ -1971,7 +1975,7 @@ public final class AnalyticsCollectorTest {
         ExoPlaybackException.createForSource(
             new IOException(), PlaybackException.ERROR_CODE_IO_UNSPECIFIED));
 
-    InOrder inOrder = Mockito.inOrder(listener1, listener2, listener3);
+    InOrder inOrder = inOrder(listener1, listener2, listener3);
     inOrder.verify(listener1).onPlayerError(any(), any());
     inOrder.verify(listener2).onPlayerError(any(), any());
     inOrder.verify(listener3).onPlayerError(any(), any());
@@ -1980,6 +1984,40 @@ public final class AnalyticsCollectorTest {
     inOrder.verify(listener3).onSurfaceSizeChanged(any(), eq(0), eq(0));
   }
 
+  @Test
+  public void release_withCallbacksArrivingAfterRelease_onPlayerReleasedForwardedLast() {
+    FakeClock fakeClock = new FakeClock(/* initialTimeMs= */ 0, /* isAutoAdvancing= */ false);
+    AnalyticsCollector analyticsCollector = new AnalyticsCollector(fakeClock);
+    SimpleExoPlayer simpleExoPlayer =
+        new ExoPlayer.Builder(ApplicationProvider.getApplicationContext()).buildExoPlayer();
+    analyticsCollector.setPlayer(simpleExoPlayer, Looper.myLooper());
+    AnalyticsListener analyticsListener = mock(AnalyticsListener.class);
+    analyticsCollector.addListener(analyticsListener);
+
+    // Simulate Player.release(): events arrive to the analytics collector after it's been released.
+    analyticsCollector.release();
+    fakeClock.advanceTime(/* timeDiffMs= */ 1);
+    analyticsCollector.onDroppedFrames(/* count= */ 1, /* elapsedMs= */ 1);
+    fakeClock.advanceTime(/* timeDiffMs= */ 1);
+    ShadowLooper.idleMainLooper();
+
+    InOrder inOrder = inOrder(analyticsListener);
+    inOrder
+        .verify(analyticsListener)
+        .onDroppedVideoFrames(argThat(eventTime -> eventTime.realtimeMs == 1), eq(1), eq(1L));
+    inOrder
+        .verify(analyticsListener)
+        .onEvents(
+            same(simpleExoPlayer), argThat(events -> events.contains(EVENT_DROPPED_VIDEO_FRAMES)));
+    inOrder
+        .verify(analyticsListener)
+        .onPlayerReleased(argThat(eventTime -> eventTime.realtimeMs == 2));
+    inOrder
+        .verify(analyticsListener)
+        .onEvents(same(simpleExoPlayer), argThat(events -> events.contains(EVENT_PLAYER_RELEASED)));
+    inOrder.verifyNoMoreInteractions();
+  }
+
   private static TestAnalyticsListener runAnalyticsTest(MediaSource mediaSource) throws Exception {
     return runAnalyticsTest(mediaSource, /* actionSchedule= */ null);
   }