search

androidx / media

Jetpack Media3 support libraries for media use cases, including ExoPlayer, an extensible media player for Android
https://developer.android.com/media/media3
Apache License 2.0
1.53k stars 372 forks source link

IMA DAI SDK indicates AD_BREAK_ENDED before ad playback completes #1538

Open achampagne-ensemble opened 1 month ago

achampagne-ensemble commented 1 month ago

Version

Media3 pre-release (alpha, beta or RC not in this list)

More version details

Currently on 1.4.0-alpha02

Devices that reproduce the issue

Samsung Galaxy A13 - Running Android 13 Galaxy Tab A7 Lite - Running Android 12 Moto G Stylus - Running Android 13

Devices that do not reproduce the issue

No response

Reproducible in the demo app?

Yes

Reproduction steps

  1. In the demo app -> demo module -> PlayerActivity.java add an adEventListener callback that prints the adEvent to the console, to the ImaServerSideAdInsertionMediaSource.AdsLoader.Builder (line 306):
 ImaServerSideAdInsertionMediaSource.AdsLoader.Builder serverSideAdLoaderBuilder =
        new ImaServerSideAdInsertionMediaSource.AdsLoader.Builder(/* context= */ this, playerView)
            .setAdEventListener( adEvent ->
                    System.out.println("+++ adEvent: " + adEvent)
                );
  1. Open the demo app
  2. Scroll down to IMA DAI streams
  3. Select the first option - HLS VOD: Demo (skippable pre/post), single ad [30s]
  4. Occasionally, the ad countdown timer will stop shortly after the ad starts playing, but the ad continues to play. It may take a few tries to repro this bug.
  5. When this happens, observe the logs. You will see that AdEvents are fired in rapid succession, with ~200ms between AdEvent.type == LOADED and AdEvent.type == AD_BREAK_ENDED

Expected result

AdEvents should fire at correct intervals, and continue to fire until the ad stops playing. The ad countdown timer should display for the duration of the ad.

Actual result

AdEvents fire in rapid succession before the ad stops playing. The ad countdown timer disappears quickly after the ad begins playback

Media

HLS VOD: Demo (skippable pre/post), single ads [30s]

Below are the console logs showing the error. Observe the timestamps of the last 4 adEvents. Media3 Demo App IMA bug.txt

Bug Report

marcbaechinger commented 1 month ago

Thanks for your report.

This is a know issue (internal bug-ref: 210846904) that I believe isn't caused by the Media3 extension. Instead the library reacts correctly to ad events sent by the IMA SDK.

AdEvents are fired in rapid succession, with ~200ms between

It's expected that the SDK notifies ad progress every 200ms to the listener (in case this was interpreted as a malfunction). ExoPlayer knows about playback progress internally, so the library simply ignores these events.

AdEvents should fire at correct intervals, and continue to fire until the ad stops playing

The following is the flow of events of a successfully played skippable ad that isn't skipped (30s) it's quite verbose and I removed progress events (see inline).

// 
2024-07-13 15:33:00.395  6450-6450  onAdEvent adEvent.type.name=CUEPOINTS_CHANGED
2024-07-13 15:33:00.553  6450-6450  onAdEvent adEvent.type.name=AD_BREAK_STARTED
2024-07-13 15:33:00.596  6450-6450  onAdEvent adEvent.type.name=CUEPOINTS_CHANGED
2024-07-13 15:33:00.605  6450-6450  onAdEvent adEvent.type.name=LOADED
2024-07-13 15:33:00.620  6450-6450  onAdEvent adEvent.type.name=STARTED
2024-07-13 15:33:00.630  6450-6450  onAdEvent adEvent.type.name=AD_PROGRESS
// AD_PROGRESS events every 200ms until

2024-07-13 15:33:06.514  6450-6450  onAdEvent adEvent.type.name=SKIPPABLE_STATE_CHANGED
2024-07-13 15:33:06.695  6450-6450  onAdEvent adEvent.type.name=AD_PROGRESS
// AD_PROGRESS events every 200ms until

2024-07-13 15:33:08.520  6450-6450  onAdEvent adEvent.type.name=FIRST_QUARTILE
2024-07-13 15:33:08.521  6450-6450  onAdEvent adEvent.type.name=AD_PROGRESS
// AD_PROGRESS events every 200ms until

2024-07-13 15:33:16.532  6450-6450  onAdEvent adEvent.type.name=MIDPOINT
2024-07-13 15:33:16.535  6450-6450  onAdEvent adEvent.type.name=AD_PROGRESS
// AD_PROGRESS events every 200ms until

2024-07-13 15:33:23.558  6450-6450  onAdEvent adEvent.type.name=THIRD_QUARTILE
2024-07-13 15:33:23.559  6450-6450  onAdEvent adEvent.type.name=AD_PROGRESS
// AD_PROGRESS events every 200ms until

2024-07-13 15:33:31.567  6450-6450  onAdEvent adEvent.type.name=COMPLETED
2024-07-13 15:33:31.577  6450-6450  onAdEvent adEvent.type.name=AD_BREAK_ENDED

I wasn't able to repro right now. As you say it doesn't happen often, but I've seen it. The failure case is when the ad overlay is removed very quickly but the ad continues without the overlay preventing the user to skip. This is expressed by these SDK ad events:

2021-12-15 15:18:17.141 10947-10947/androidx.media3.demo.main D/EventLogger: loading [eventTime=0.34, mediaPos=0.00, window=0, period=0, true]
2021-12-15 15:18:18.391 10947-10947/androidx.media3.demo.main D/onAdEvent: event: AD_BREAK_STARTED
2021-12-15 15:18:18.505 10947-10947/androidx.media3.demo.main D/onAdEvent: event: CUEPOINTS_CHANGED
2021-12-15 15:18:18.541 10947-10947/androidx.media3.demo.main D/onAdEvent: event: LOADED
2021-12-15 15:18:18.586 10947-10947/androidx.media3.demo.main D/onAdEvent: event: STARTED
2021-12-15 15:18:18.588 10947-10947/androidx.media3.demo.main D/onAdEvent: event: AD_PROGRESS
2021-12-15 15:18:18.650 10947-10947/androidx.media3.demo.main D/onAdEvent: event: AD_BREAK_ENDED
2021-12-15 15:18:18.679 10947-10947/androidx.media3.demo.main D/EventLogger: timeline [eventTime=1.87, mediaPos=0.00, window=0, periodCount=1, windowCount=1, reason=SOURCE_UPDATE

Please note, that in this case the SDK sends an AD_BREAK_END just about 100ms after the ad was LOADED. The UI that is controlled by the SDK rather than by Media3, is disappearing when the ad break end is announced. From this I'd say the behaviour is caused by the SDK.

You can see the same in your log from 2024-07-10 10:52:56.504 to 2024-07-10 10:52:56.915 for adId=29108728. The log entries before that are form different ad IDs probably when attempting to repro many times.

Your logs further show that besides the early ad break end, the adEvent data and the adPod data delivered by the events are correct as in they look the same in the above ads where it worked.

Do you have another DAI stream that exhibits this behaviour and that could help repo? Do you see crash or other telemetry data saying your users are seeing this? I'm asking because any occurences of such events besides this very test stream would make the issue a bit more important/actionable. Sorry for the long and effectively not very helpful answer.

achampagne-ensemble commented 1 month ago

@marcbaechinger Thanks for your response. It corroborates exactly what I have been observing wrt the UI as well as the ad events. To clarify, I was not under the assumption that single events firing every 200ms are an issue, but instead, all the events between AD_BREAK_STARTED and AD_BREAK_ENDED firing within around 200ms, as you mentioned in your response. I can see how the title I originally posted was sort of ambiguous regarding this, so thanks for making the change to something more accurate!

While I was investigating this bug I also noticed that the AdEvent data was not different for a properly executed ad or one where the bug surfaces. That rules out an issue of a malformed response from the IMA endpoint possibly being a cause.

At this time, I do not have any crash or telemetry data since the app is not yet in production, however that date is approaching quickly. Since we use the AdEvents to trigger UI updates on our player, this bug causes the "ad playback" player controls (a limited set of player control views that only show when the player is in the "ad playing" state) to show when normal video playback commences. This limits the user from being able to perform a number of actions on the video that they would otherwise be able to perform. Additionally, the ad countdown timer disappears, and the seek bar's progress time displays as "0:00" until the ad ends. This is a high priority bug for us at the moment. Unfortunately, we have not yet been able to devise a workaround ad due to the highly integrated nature of the IMA DAI SDK with media3.

This bug reproduces with a number of our streams, though I don't have hard numbers on repro rates. It's probably somewhere between 5-10% if I were to make a guess based on my observations. My suspicion is that it is stream-agnostic, but I don't have any theories as to what could be causing it on the SDK side.

Please keep me updated, as this is quite a high priority bug for us. I'd also like to thank you for all your work on this issues page, your other posts here have been a great help to me to work out the finer details of building our player using the new Media3 library.

marcbaechinger commented 1 month ago

Thanks for your feedback! Very much appreciated.

I'm trying to repro again with my stream to see whether I find something from the SDK. If you can repo for 10% and you are used to have the Media3 source locally, then you can to the same as I do and add 

imaSdkSettings.setDebugMode(true);

like in ImaServerSideAdInsertionmediaSource.AdsLoader.Builder.build and grep logcat for chromium to see the logs of the SDK. In the case of success it's pretty much logging the events we see arriving at the ads event listener. Surely, the output in the failure case would be interesting.

It's cool to ignore this if you haven't built from source yet. :)

achampagne-ensemble commented 1 month ago

We haven't built from source yet, but I will discuss with the team and see if it's something we might pursue if it can help us debug for future issues.