Playback begins but listener never receives READY state (IMA 3.11.2, 2.10.0)

[dbrain]

[REQUIRED] Issue description

When using ExoPlayer 2.10.0 with the IMA extension (and a local dependency on IMA 3.11.2), sometimes the player will begin playback but never emit an onPlayerStateChanged(.., READY) event.
This seems to occur for content with unplayable ads. but I can not find a guaranteed way to replicate it.
This issue could not be reproduced on ExoPlayer 2.9.6 with IMA 3.10.9.

We are currently driving some UI/events on this READY event (for e.g. hiding a spinner, starting some metrics).

[REQUIRED] Reproduction steps

• Play content with IMA ads, seemingly with a format the player does not support so they are skipped
• Check for READY event, this will intermittently not fire

[REQUIRED] Link to test content

Unable to provide, as it's tied to IMA and DRMd content specifically. If required I can try to work something out.

[REQUIRED] A full bug report captured from the device

Will email to [email protected]

[REQUIRED] Version of ExoPlayer being used

2.10.0

[REQUIRED] Device(s) and version(s) of Android being used

For the bug report, Android Q beta3, but has also been seen on P.

[andrewlewis]

It would be useful if you could set ImaAdsLoader.DEBUG to true then reproduce the issue, take a bug report and send it over. This enables some logging that shows what the IMA API is doing.

You mention that this issue is tied to DRM content. Just to clarify, can you not reproduce it when playing clear content? That sounds strange. If you can share the ad tag via email anyway that would be helpful.

[dbrain]

@andrewlewis I've emailed the new bugreport with ImaAdsLoader.DEBUG = true and the ad tag in the same thread as the previous bugreport.

Sorry, I didn't word the Link to test content section great. I don't believe it's tied to DRM content, I was just mentioning that our content is DRM protected, in case that's related somehow, and that getting test content for you would be a bit of a hassle (but can if required). We don't really have any clear content to test with, but I can try to fudge it if that's helpful.

[dbrain]

I've been digging a bit. This seems to be occurring when ImaAdsLoader.onPositionDiscontinuity is called (via ExoPlayerImpl.seekTo notifyListeners call) before ImaAdsLoader.onTimelineChanged. In this scenario ImaAdsLoader.onPositionDiscontinuity tries to getPeriod from the ImaAdsLoader.timeline which is null throwing an exception and preventing other listeners receiving the onPositionDiscontinuity call. Presumably somewhere in this call chain whatever emits the READY is being missed due to the exception.

Our player calls seekTo() after receiving CONTENT_RESUME_REQUESTED from the AdEventListener to resume playback (from a previous session) after the first ad has played. Digging into why/if this is required on our side, but it seems CONTENT_RESUME_REQUESTED is firing before ImaAdsLoader has seen a timeline change.

Not sure of the exact flow of events yet and how incorrect it is, but ImaAdsLoader could potentially try to be safer about the null possibility of timeline in onPositionDiscontinuity to avoid the exception, or notifying the listeners could log and skip listeners on exception rather than bubbling.

Unsure what happened in 2.10.0 that caused this behaviour change, looks like we have seen the error in the past and ignored it, so potentially it's something as basic as the order of the listeners changing slightly so the exception is thrown before it's hit the important listener that drives the READY state change.

Still digging but thought this might be helpful.

[tonihei]

Seems related to #5831 which is also caused by seeking before the first ad event arrives.

[dbrain]

Definitely seems related. The fix over there to change the order of listeners likely changed the behaviour for us in this scenario.

That being said the issue (NPE) presented itself in earlier versions, it just never effected the operation of the player in any noticeable way until 2.10.

I'll dig into it a bit more over the next few days. Unsure if our seek call on content resume is timed incorrectly/necessary at all now (think it was a workaround for another issue), or if the ImaAdsLoader should be more error tolerant. Maybe a bit of both.

[dbrain]

So I think the issue is CONTENT_RESUME_REQUESTED is sometimes firing near instantly (before onTimelineChanged has fired) which is triggering our seekTo and triggering ImaAdsLoader.onPositionDiscontinuity() before it has a timeline causing an NPE.

I'm pretty sure I can remove our code triggering the seekTo, which should prevent this issue for us. It was originally added as we showed some UI when the user was resuming playback to choose to start again or continue playing from where they left off, and showing it while the ad was playing didn't make sense (or work). We've since rejigged how resume works.

I guess there's a larger question about if notifyListeners should die if one of the listeners is busted, or if ImaAdsLoader.onPositionDiscontinuity should be safer around how it uses potentially null variables (timeline).

[andrewlewis]

@dbrain Sorry for the delay. Removing the call to seekTo sounds like a good idea -- did you try this, and do you still have any issues? It shouldn't be necessary to seek the player to restore state (if you seek before preparation we should play the right ad(s) if needed, and the timeline tracks the ad resume position for background/resume during an ad).

Setting that aside, I think a couple of issues related to behavior at the start of playback with ImaAdsLoader were fixed recently, so if you still have problems it would be helpful if you could try to reproduce them on the development branch. Thanks.

[dbrain]

@andrewlewis Sorry, I also meant to respond to this. The issue went away when we removed the no longer needed code. It was originally added to support asking the user if they wanted to resume watching or restart while we perform the default action. When ads were added it became a bit awkward, as we didn't want to kick off a seek/show a snackbar mid ad etc so it was tied to the first CONTENT_RESUME_REQUESTED, which apparently sometimes fired before the player was ready.

Closing this as the issue is no longer reproducible. Thanks!