postroll didn't end for some HLS stream

[zzzhc]

Issue description

We have some HLS streams which are converted from DASH. The last segment of the HLS streams may not contain video frames. ExoPlayer can play well in v2.9.6, but when we upgraded to v2.10.x, the postroll ad won't end, it is always in AD_PROGRESS state.

[REQUIRED] Reproduction steps

demo repo: https://github.com/zzzhc/ExoPlayer, branch: stuck-at-end
the demo is based on imademo, the main changes are using another content_url, ad_tag_url

Link to test content

HLS: https://raw.githubusercontent.com/zzzhc/storage/master/hls/index.m3u8
Ad Tag URL: https://pubads.g.doubleclick.net/gampad/ads?sz=640x480&iu=/124319096/external/ad_rule_samples&ciu_szs=300x250&ad_rule=1&impl=s&gdfp_req=1&env=vp&output=vmap&unviewed_position_start=1&cust_params=deployment%3Ddevsite%26sample_ar%3Dpremidpostpod&cmsid=496&vid=short_onecue&correlator=

A full bug report captured from the device

will send via email.

Version of ExoPlayer being used

reproduced on v2.10.0, v2.10.1, v2.10.2, v2.10.3, v2.10.4
can't reproduce on v2.9.6

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

emulator: android 9.0, 6.0
real devices:
samsung galaxy A tablet (android 7.0.1)
Sony Xperia (android 6.0.1)
Nexus 7 tablet (Android 6.0.1)
Samsung galaxy J8(Android 8.1)
Galaxy note 5 (Android 7)

[tonihei]

Thanks for reporting. I can reproduce the issue and are currently investigating. Seems to be related to the fact that the ads are not loading and the ad load error is handled in an incorrect way.

[tonihei]

ad load error is handled in an incorrect way

That's actually another bug in our dev branch that needs fixing unrelated to what's reported here.

The bug reported in this issue is HLS-specific and happens because we wait for stream information after the postroll which never arrives as the stream already finished loading.

[zzzhc]

agreed. postroll works well on the original DASH stream.
looks like it is caused by the last segment which doesn't contain valid video frame.

$ ffprobe Uj1_rFj_fqJf1LQ6mvkkU6ObwXw.ts
....
Input #0, mpegts, from 'Uj1_rFj_fqJf1LQ6mvkkU6ObwXw.ts':
  Duration: 00:00:00.30, start: 4710.016000, bitrate: 80 kb/s
  Program 1
    Stream #0:0[0x101]: Audio: aac (HE-AACv2) ([15][0][0][0] / 0x000F), 48000 Hz, stereo, fltp, 65 kb/s
    Stream #0:1[0x102]: Video: h264 ([27][0][0][0] / 0x001B), none, 90k tbr, 90k tbn, 180k tbc

[tonihei]

Thanks for confirming. There is general HLS related bug after playing a postroll ads that we are going to fix.

Unfortunately, your stream still won't work after this fix because the last segment doesn't contain video format data. This is quite unusual because HLS clients are usually assuming all tracks to be muxed into all segments to be able to start playback at any point. Is there a way for you to fix that?

[zzzhc]

This kind of abnormal HLS stream is converted by a third-party SDK, we haven't found a way to fix it.
It works well in v2.9.6. I suppose some commits between v2.9.6 to v2.10.0 broken it. I have tried to find out which commit did the bad thing but failed, the commit history is not linear, v2.10.0 dev branch is not based on v2.9.6 directly.

[tonihei]

This change was introduced by commits handling how we insert post-rolls into the stream. We now try to load the stream again from behind the post-roll to the end of the stream (that's usually a no-op, because there is nothing between these two points). This allowed us to streamline some of the code around ad insertion and event management and it may prevent unnecessary decoder disabling/enabling. The problem is that HLS without chunkless preparation (or when using media playlists directly as in this case), it needs to load something to setup the stream again.

Thinking about it more closely, it should be possible to keep the list of available formats if the source has already been used before. I filed #6336 to track this.

[zzzhc]

@tonihei thank you for the fix.
I tested on branch dev-v2, the player will throw ParserException at the end.

in https://github.com/google/ExoPlayer/blob/dev-v2/library/hls/src/main/java/com/google/android/exoplayer2/source/hls/HlsSampleStreamWrapper.java#L236, loadingFinished is true, but prepared is false. It works when I removed these lines.

    if (loadingFinished && !prepared) {
      throw new ParserException("Loading finished before preparation is complete.");
    }

my test code is https://github.com/zzzhc/ExoPlayer, branch: dev-v2-throw-exception-at-end

detail logs:

2019-09-06 13:44:27.064 29484-29484/com.google.android.exoplayer2.imademo I/chromium: [INFO:CONSOLE(931)] " [ 28.745s] [ima.vast.VideoAdEventTracker] dispatching event thirdQuartile", source: https://imasdk.googleapis.com/native/core/3.156.1/native_bridge_debug__en.js (931)
2019-09-06 13:44:27.070 29484-29484/com.google.android.exoplayer2.imademo I/SDK_LOG:ima.vast.VideoAdEventTracker: dispatching event thirdQuartile
2019-09-06 13:44:27.077 29484-29484/com.google.android.exoplayer2.imademo I/chromium: [INFO:CONSOLE(931)] " [ 28.757s] [UrlReporter] Reporting urls for event : thirdQuartile", source: https://imasdk.googleapis.com/native/core/3.156.1/native_bridge_debug__en.js (931)
2019-09-06 13:44:27.107 29484-29484/com.google.android.exoplayer2.imademo I/SDK_LOG:UrlReporter: Reporting urls for event : thirdQuartile
2019-09-06 13:44:27.116 29484-29484/com.google.android.exoplayer2.imademo D/ImaAdsLoader: onAdEvent: THIRD_QUARTILE
2019-09-06 13:44:27.122 29484-29484/com.google.android.exoplayer2.imademo D/ImaAdsLoader: onAdEvent: AD_PROGRESS
2019-09-06 13:44:27.674 29484-29484/com.google.android.exoplayer2.imademo I/chatty: uid=10103(com.google.android.exoplayer2.imademo) identical 3 lines
2019-09-06 13:44:27.873 29484-29484/com.google.android.exoplayer2.imademo D/ImaAdsLoader: onAdEvent: AD_PROGRESS
2019-09-06 13:44:28.074 29484-29484/com.google.android.exoplayer2.imademo D/ImaAdsLoader: onAdEvent: AD_PROGRESS
2019-09-06 13:44:28.682 29484-29484/com.google.android.exoplayer2.imademo I/chatty: uid=10103(com.google.android.exoplayer2.imademo) identical 3 lines
2019-09-06 13:44:28.882 29484-29484/com.google.android.exoplayer2.imademo D/ImaAdsLoader: onAdEvent: AD_PROGRESS
2019-09-06 13:44:29.083 29484-29484/com.google.android.exoplayer2.imademo D/ImaAdsLoader: onAdEvent: AD_PROGRESS
2019-09-06 13:44:29.285 29484-29484/com.google.android.exoplayer2.imademo D/ImaAdsLoader: onAdEvent: AD_PROGRESS
2019-09-06 13:44:29.448 29484-29484/com.google.android.exoplayer2.imademo D/EventLogger: mediaPeriodReleased [31.77, 10.01, window=0, period=0, adGroup=2, ad=0]
2019-09-06 13:44:29.448 29484-29484/com.google.android.exoplayer2.imademo D/EventLogger: droppedFrames [31.77, 10.01, window=0, period=0, adGroup=2, ad=0, 12]
2019-09-06 13:44:29.455 29484-29484/com.google.android.exoplayer2.imademo D/EventLogger: decoderDisabled [31.77, 10.01, window=0, period=0, adGroup=2, ad=0, video]
2019-09-06 13:44:29.464 29484-29484/com.google.android.exoplayer2.imademo D/EventLogger: decoderDisabled [31.78, 10.01, window=0, period=0, adGroup=2, ad=0, audio]
2019-09-06 13:44:29.477 29484-30378/com.google.android.exoplayer2.imademo D/SurfaceUtils: disconnecting from surface 0xc1d72008, reason disconnectFromSurface
2019-09-06 13:44:29.485 29484-30378/com.google.android.exoplayer2.imademo D/gralloc_ranchu: gralloc_unregister_buffer: exiting HostConnection (is buffer-handling thread)
2019-09-06 13:44:29.494 29484-29484/com.google.android.exoplayer2.imademo D/ImaAdsLoader: onAdEvent: AD_PROGRESS
2019-09-06 13:44:29.529 29484-29582/com.google.android.exoplayer2.imademo E/ExoPlayerImplInternal: Source error.
    com.google.android.exoplayer2.ParserException: Loading finished before preparation is complete.
        at com.google.android.exoplayer2.source.hls.HlsSampleStreamWrapper.maybeThrowPrepareError(HlsSampleStreamWrapper.java:237)
        at com.google.android.exoplayer2.source.hls.HlsMediaPeriod.maybeThrowPrepareError(HlsMediaPeriod.java:161)
        at com.google.android.exoplayer2.source.MaskingMediaPeriod.maybeThrowPrepareError(MaskingMediaPeriod.java:139)
        at com.google.android.exoplayer2.ExoPlayerImplInternal.doSomeWork(ExoPlayerImplInternal.java:606)
        at com.google.android.exoplayer2.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:323)
        at android.os.Handler.dispatchMessage(Handler.java:102)
        at android.os.Looper.loop(Looper.java:193)
        at android.os.HandlerThread.run(HandlerThread.java:65)
2019-09-06 13:44:29.531 29484-29484/com.google.android.exoplayer2.imademo D/EventLogger: mediaPeriodReleased [31.85, 10.01, window=0, period=0]
2019-09-06 13:44:29.533 29484-29484/com.google.android.exoplayer2.imademo D/EventLogger: positionDiscontinuity [31.85, 15.10, window=0, AD_INSERTION]
2019-09-06 13:44:29.535 29484-29484/com.google.android.exoplayer2.imademo E/EventLogger: playerFailed [31.85, 15.10, window=0, period=0]
    com.google.android.exoplayer2.ExoPlaybackException: com.google.android.exoplayer2.ParserException: Loading finished before preparation is complete.
        at com.google.android.exoplayer2.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:388)
        at android.os.Handler.dispatchMessage(Handler.java:102)
        at android.os.Looper.loop(Looper.java:193)
        at android.os.HandlerThread.run(HandlerThread.java:65)
     Caused by: com.google.android.exoplayer2.ParserException: Loading finished before preparation is complete.
        at com.google.android.exoplayer2.source.hls.HlsSampleStreamWrapper.maybeThrowPrepareError(HlsSampleStreamWrapper.java:237)
        at com.google.android.exoplayer2.source.hls.HlsMediaPeriod.maybeThrowPrepareError(HlsMediaPeriod.java:161)
        at com.google.android.exoplayer2.source.MaskingMediaPeriod.maybeThrowPrepareError(MaskingMediaPeriod.java:139)
        at com.google.android.exoplayer2.ExoPlayerImplInternal.doSomeWork(ExoPlayerImplInternal.java:606)
        at com.google.android.exoplayer2.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:323)
        at android.os.Handler.dispatchMessage(Handler.java:102) 
        at android.os.Looper.loop(Looper.java:193) 
        at android.os.HandlerThread.run(HandlerThread.java:65) 
2019-09-06 13:44:29.535 29484-29484/com.google.android.exoplayer2.imademo D/EventLogger: tracksChanged [31.85, 15.10, window=0, []]
2019-09-06 13:44:29.536 29484-29484/com.google.android.exoplayer2.imademo D/EventLogger: loading [31.86, 15.10, window=0, false]
2019-09-06 13:44:29.537 29484-29484/com.google.android.exoplayer2.imademo D/EventLogger: state [31.86, 15.10, window=0, true, IDLE]
2019-09-06 13:44:29.544 29484-29484/com.google.android.exoplayer2.imademo D/ImaAdsLoader: pauseAd
2019-09-06 13:44:29.578 29484-29484/com.google.android.exoplayer2.imademo I/chromium: [INFO:CONSOLE(931)] " [ 31.229s] [ima.vast.VideoAdEventTracker] dispatching event pause", source: https://imasdk.googleapis.com/native/core/3.156.1/native_bridge_debug__en.js (931)
2019-09-06 13:44:29.579 29484-29484/com.google.android.exoplayer2.imademo I/chromium: [INFO:CONSOLE(931)] " [ 31.237s] [UrlReporter] Reporting urls for event : pause", source: https://imasdk.googleapis.com/native/core/3.156.1/native_bridge_debug__en.js (931)
2019-09-06 13:44:29.581 29484-29484/com.google.android.exoplayer2.imademo I/SDK_LOG:ima.vast.VideoAdEventTracker: dispatching event pause
2019-09-06 13:44:29.590 29484-29484/com.google.android.exoplayer2.imademo I/SDK_LOG:UrlReporter: Reporting urls for event : pause
2019-09-06 13:44:29.594 29484-29484/com.google.android.exoplayer2.imademo D/ImaAdsLoader: onAdEvent: PAUSED

[tonihei]

Yes, that's expected and due to the missing video data in the last chunk. This should likely be fixed for all practical cases once #6336 is implemented.