IMA Extension fails to report post-prepared errors to the VideoAdPlayer.VideoAdPlayerCallback.onError()

Version

Media3 main branch

More version details

No response

Devices that reproduce the issue

Any device

Devices that do not reproduce the issue

none

Reproducible in the demo app?

Yes

Reproduction steps

I'll need to work on a sample for you and post it, probably an playlist with segments that fail deep enough into playback to miss prepare (or just chunkless prepare will succeed)

Expected result

Error is reported to IMA so the ERROR Pixel pings and code watching the call backs gets a valid IMA event.

Actual result

Error is invisible to the IMA API, last event reported is "Ad Progress". Logging looks like this:

05-01 16:19:39.979 25532 25532 D AdTagLoader: Ad progress: 1540 ms of 15036 ms
05-01 16:19:40.095 25532 25532 I chromium: [INFO:CONSOLE(1222)] " [  3.176s] [ima.vast.VideoAdEventTracker] dispatching event viewable_impression ", source: https://imasdk.googleapis.com/native/core/3.408.0/native_bridge_debug__en.js (1222)
05-01 16:19:40.096 25532 25532 I chromium: [INFO:CONSOLE(1222)] " [  3.179s] [UrlReporter] Reporting urls for event : viewable_impression ", source: https://imasdk.googleapis.com/native/core/3.408.0/native_bridge_debug__en.js (1222)
05-01 16:19:40.198 25532 25532 D AdTagLoader: Ad progress: 1754 ms of 15036 ms
05-01 16:19:40.419 25532 25532 D AdTagLoader: Ad progress: 1978 ms of 15036 ms
05-01 16:19:40.620 25532 25532 D AdTagLoader: Ad progress: 2175 ms of 15036 ms
05-01 16:19:40.738 25532 25532 D EventLogger: loading [eventTime=4.75, mediaPos=2.29, window=0, period=0, adGroup=0, ad=0, false]
05-01 16:19:40.825 25532 25532 D AdTagLoader: Ad progress: 2382 ms of 15036 ms
05-01 16:19:41.028 25532 25532 D AdTagLoader: Ad progress: 2585 ms of 15036 ms
05-01 16:19:41.187 25532 25871 W CCodec  : previous call to queue exceeded timeout
05-01 16:19:41.188 25532 26097 E MediaCodec: Codec reported err 0x80000000, actionCode 0, while in state 6
05-01 16:19:41.192 25532 26097 D SurfaceUtils: disconnecting from surface 0xba719808, reason disconnectFromSurface
05-01 16:19:41.203 25532 26040 E MediaCodecVideoRenderer: Video codec error
05-01 16:19:41.203 25532 26040 E MediaCodecVideoRenderer:   java.lang.IllegalStateException
05-01 16:19:41.203 25532 26040 E MediaCodecVideoRenderer:       at android.media.MediaCodec.native_dequeueOutputBuffer(Native Method)
05-01 16:19:41.203 25532 26040 E MediaCodecVideoRenderer:       at android.media.MediaCodec.dequeueOutputBuffer(MediaCodec.java:2790)
05-01 16:19:41.203 25532 26040 E MediaCodecVideoRenderer:       at androidx.media3.exoplayer.mediacodec.SynchronousMediaCodecAdapter.dequeueOutputBufferIndex(SynchronousMediaCodecAdapter.java:108)
05-01 16:19:41.203 25532 26040 E MediaCodecVideoRenderer:       at androidx.media3.exoplayer.mediacodec.MediaCodecRenderer.drainOutputBuffer(MediaCodecRenderer.java:1931)
05-01 16:19:41.203 25532 26040 E MediaCodecVideoRenderer:       at androidx.media3.exoplayer.mediacodec.MediaCodecRenderer.render(MediaCodecRenderer.java:830)
05-01 16:19:41.203 25532 26040 E MediaCodecVideoRenderer:       at androidx.media3.exoplayer.video.MediaCodecVideoRenderer.render(MediaCodecVideoRenderer.java:945)
05-01 16:19:41.203 25532 26040 E MediaCodecVideoRenderer:       at androidx.media3.exoplayer.ExoPlayerImplInternal.doSomeWork(ExoPlayerImplInternal.java:1114)
05-01 16:19:41.203 25532 26040 E MediaCodecVideoRenderer:       at androidx.media3.exoplayer.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:546)
05-01 16:19:41.203 25532 26040 E MediaCodecVideoRenderer:       at android.os.Handler.dispatchMessage(Handler.java:103)
05-01 16:19:41.203 25532 26040 E MediaCodecVideoRenderer:       at android.os.Looper.loop(Looper.java:214)
05-01 16:19:41.203 25532 26040 E MediaCodecVideoRenderer:       at android.os.HandlerThread.run(HandlerThread.java:67)
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal: Playback error
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:   androidx.media3.exoplayer.ExoPlaybackException: MediaCodecVideoRenderer error, index=0, format=Format(1, null, null, video/x-vnd.on2.vp8, null, -1, und, [1280, 720, -1.0, ColorInfo(BT709, Limited range, SDR SMPTE 170M, false, NA, NA)], [-1, -1]), format_supported=YES
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:625)
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:       at android.os.Handler.dispatchMessage(Handler.java:103)
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:       at android.os.Looper.loop(Looper.java:214)
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:       at android.os.HandlerThread.run(HandlerThread.java:67)
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:   Caused by: androidx.media3.exoplayer.video.MediaCodecVideoDecoderException: Decoder failed: c2.android.vp8.decoder
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.video.MediaCodecVideoRenderer.createDecoderException(MediaCodecVideoRenderer.java:1917)
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.mediacodec.MediaCodecRenderer.render(MediaCodecRenderer.java:851)
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.video.MediaCodecVideoRenderer.render(MediaCodecVideoRenderer.java:945)
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.ExoPlayerImplInternal.doSomeWork(ExoPlayerImplInternal.java:1114)
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:546)
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:       ... 3 more
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:   Caused by: java.lang.IllegalStateException
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:       at android.media.MediaCodec.native_dequeueOutputBuffer(Native Method)
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:       at android.media.MediaCodec.dequeueOutputBuffer(MediaCodec.java:2790)
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.mediacodec.SynchronousMediaCodecAdapter.dequeueOutputBufferIndex(SynchronousMediaCodecAdapter.java:108)
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.mediacodec.MediaCodecRenderer.drainOutputBuffer(MediaCodecRenderer.java:1931)
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.mediacodec.MediaCodecRenderer.render(MediaCodecRenderer.java:830)
05-01 16:19:41.213 25532 26040 E ExoPlayerImplInternal:       ... 6 more
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal: Disable failed.
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal:   java.lang.IllegalStateException
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal:       at android.media.MediaCodec.native_flush(Native Method)
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal:       at android.media.MediaCodec.flush(MediaCodec.java:2195)
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.mediacodec.SynchronousMediaCodecAdapter.flush(SynchronousMediaCodecAdapter.java:168)
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.mediacodec.MediaCodecRenderer.flushCodec(MediaCodecRenderer.java:915)
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.mediacodec.MediaCodecRenderer.flushOrReleaseCodec(MediaCodecRenderer.java:908)
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.mediacodec.MediaCodecRenderer.onDisabled(MediaCodecRenderer.java:747)
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.video.MediaCodecVideoRenderer.onDisabled(MediaCodecVideoRenderer.java:714)
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.BaseRenderer.disable(BaseRenderer.java:220)
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.ExoPlayerImplInternal.disableRenderer(ExoPlayerImplInternal.java:1805)
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.ExoPlayerImplInternal.resetInternal(ExoPlayerImplInternal.java:1527)
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.ExoPlayerImplInternal.stopInternal(ExoPlayerImplInternal.java:1484)
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal:       at androidx.media3.exoplayer.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:669)
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal:       at android.os.Handler.dispatchMessage(Handler.java:103)
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal:       at android.os.Looper.loop(Looper.java:214)
05-01 16:19:41.219 25532 26040 E ExoPlayerImplInternal:       at android.os.HandlerThread.run(HandlerThread.java:67)
05-01 16:19:41.220 25532 25532 D EventLogger: videoDisabled [eventTime=5.22, mediaPos=2.76, window=0, period=0, adGroup=0, ad=0]
05-01 16:19:41.222 25532 25532 D EventLogger: videoSize [eventTime=5.23, mediaPos=2.76, window=0, period=0, adGroup=0, ad=0, 0, 0]
05-01 16:19:41.224 25532 26103 D CCodecBuffers: [c2.android.vorbis.decoder#164:1D-Output.Impl[N]] Client returned a buffer it does not own according to our record: 0
05-01 16:19:41.224 25532 26103 D CCodecBuffers: [c2.android.vorbis.decoder#164:1D-Output.Impl[N]] Client returned a buffer it does not own according to our record: 1
05-01 16:19:41.224 25532 26103 D CCodecBuffers: [c2.android.vorbis.decoder#164:1D-Output.Impl[N]] Client returned a buffer it does not own according to our record: 2
05-01 16:19:41.224 25532 26103 D CCodecBuffers: [c2.android.vorbis.decoder#164:1D-Output.Impl[N]] Client returned a buffer it does not own according to our record: 3
05-01 16:19:41.225 25532 26103 W Codec2Client: query -- param skipped: index = 1342179345.
05-01 16:19:41.225 25532 26103 W Codec2Client: query -- param skipped: index = 2415921170.
05-01 16:19:41.227 25532 25532 D EventLogger: audioDisabled [eventTime=5.24, mediaPos=2.76, window=0, period=0, adGroup=0, ad=0]
05-01 16:19:41.232 25532 25532 D AdTagLoader: Ad progress: 2761 ms of 15036 ms
05-01 16:19:41.234 25532 25532 D EventLogger: videoDecoderReleased [eventTime=5.24, mediaPos=2.76, window=0, period=0, adGroup=0, ad=0, c2.android.vp8.decoder]
05-01 16:19:41.244 25532 25532 D EventLogger: audioDecoderReleased [eventTime=5.25, mediaPos=2.76, window=0, period=0, adGroup=0, ad=0, c2.android.vorbis.decoder]

At this point the resetInternal() call has posted a call to AdsLoader.stop() so IMA Extension removes the player listener before it gets a chance to get the playback error callback, which comes later:

05-01 16:29:13.347 25532 25532 D AdTagLoader: Ad progress: 2761 ms of 15036 ms
05-01 16:29:33.204 25532 25532 W edia3.demo.mai: Accessing hidden method Lsun/misc/Unsafe;->getInt(Ljava/lang/Object;J)I (greylist, linking, allowed)
05-01 16:29:33.205 25532 25532 W edia3.demo.mai: Accessing hidden method Lsun/misc/Unsafe;->putInt(Ljava/lang/Object;JI)V (greylist, linking, allowed)
05-01 16:29:33.209 25532 25532 W edia3.demo.mai: Accessing hidden method Lsun/misc/Unsafe;->getObject(Ljava/lang/Object;J)Ljava/lang/Object; (greylist, linking, allowed)
05-01 16:29:33.240 25532 25532 W edia3.demo.mai: Accessing hidden method Lsun/misc/Unsafe;->getLong(Ljava/lang/Object;J)J (greylist,core-platform-api, linking, allowed)
05-01 16:29:33.294 25532 25532 D EventLogger: timeline [eventTime=597.30, mediaPos=2.76, window=0, period=0, adGroup=0, ad=0, periodCount=1, windowCount=1, reason=SOURCE_UPDATE
05-01 16:29:33.294 25532 25532 D EventLogger:   period [128.27]
05-01 16:29:33.295 25532 25532 D EventLogger:   window [128.27, seekable=true, dynamic=false]
05-01 16:29:33.295 25532 25532 D EventLogger: ]
05-01 16:29:35.675 25532 25532 E EventLogger: playerFailed [eventTime=597.30, mediaPos=2.76, window=0, period=0, adGroup=0, ad=0, errorCode=ERROR_CODE_DECODING_FAILED
05-01 16:29:35.675 25532 25532 E EventLogger:   androidx.media3.exoplayer.ExoPlaybackException: MediaCodecVideoRenderer error, index=0, format=Format(1, null, null, video/x-vnd.on2.vp8, null, -1, und, [1280, 720, -1.0, ColorInfo(BT709, Limited range, SDR SMPTE 170M, false, NA, NA)], [-1, -1]), format_supported=YES
05-01 16:29:35.675 25532 25532 E EventLogger:       at androidx.media3.exoplayer.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:625)
05-01 16:29:35.675 25532 25532 E EventLogger:       at android.os.Handler.dispatchMessage(Handler.java:103)
05-01 16:29:35.675 25532 25532 E EventLogger:       at android.os.Looper.loop(Looper.java:214)
05-01 16:29:35.675 25532 25532 E EventLogger:       at android.os.HandlerThread.run(HandlerThread.java:67)
05-01 16:29:35.675 25532 25532 E EventLogger:   Caused by: androidx.media3.exoplayer.video.MediaCodecVideoDecoderException: Decoder failed: c2.android.vp8.decoder
05-01 16:29:35.675 25532 25532 E EventLogger:       at androidx.media3.exoplayer.video.MediaCodecVideoRenderer.createDecoderException(MediaCodecVideoRenderer.java:1917)
05-01 16:29:35.675 25532 25532 E EventLogger:       at androidx.media3.exoplayer.mediacodec.MediaCodecRenderer.render(MediaCodecRenderer.java:851)
05-01 16:29:35.675 25532 25532 E EventLogger:       at androidx.media3.exoplayer.video.MediaCodecVideoRenderer.render(MediaCodecVideoRenderer.java:945)
05-01 16:29:35.675 25532 25532 E EventLogger:       at androidx.media3.exoplayer.ExoPlayerImplInternal.doSomeWork(ExoPlayerImplInternal.java:1114)
05-01 16:29:35.675 25532 25532 E EventLogger:       at androidx.media3.exoplayer.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:546)
05-01 16:29:35.675 25532 25532 E EventLogger:       ... 3 more
05-01 16:29:35.675 25532 25532 E EventLogger:   Caused by: java.lang.IllegalStateException
05-01 16:29:35.675 25532 25532 E EventLogger:       at android.media.MediaCodec.native_dequeueOutputBuffer(Native Method)
05-01 16:29:35.675 25532 25532 E EventLogger:       at android.media.MediaCodec.dequeueOutputBuffer(MediaCodec.java:2790)
05-01 16:29:35.675 25532 25532 E EventLogger:       at androidx.media3.exoplayer.mediacodec.SynchronousMediaCodecAdapter.dequeueOutputBufferIndex(SynchronousMediaCodecAdapter.java:108)
05-01 16:29:35.675 25532 25532 E EventLogger:       at androidx.media3.exoplayer.mediacodec.MediaCodecRenderer.drainOutputBuffer(MediaCodecRenderer.java:1931)
05-01 16:29:35.675 25532 25532 E EventLogger:       at androidx.media3.exoplayer.mediacodec.MediaCodecRenderer.render(MediaCodecRenderer.java:830)
05-01 16:29:35.675 25532 25532 E EventLogger:       ... 6 more
05-01 16:29:35.675 25532 25532 E EventLogger: ]
05-01 16:29:35.680 25532 25532 D EventLogger: state [eventTime=599.69, mediaPos=2.76, window=0, period=0, adGroup=0, ad=0, IDLE]
05-01 16:29:35.689 25532 25532 D EventLogger: isPlaying [eventTime=599.70, mediaPos=2.76, window=0, period=0, adGroup=0, ad=0, false]
05-01 16:29:35.714 25532 25532 D EventLogger: audioTrackReleased [eventTime=599.72, mediaPos=2.76, window=0, period=0, adGroup=0, ad=0, 2,12,44100,false,false,60320]
05-01 16:29:35.951 25532 25549 I edia3.demo.mai: Background concurrent copying GC freed 31631(2363KB) AllocSpace objects, 138(8960KB) LOS objects, 49% free, 7208KB/14MB, paused 149us total 126.856ms
05-01 16:29:41.421 25532 25532 I Choreographer: Skipped 1682 frames!  The application may be doing too much work on its main thread.
05-01 16:29:41.471 25532 25588 I OpenGLRenderer: Davey! duration=28120ms; Flags=1, IntendedVsync=107933062902280, Vsync=107961124268386, OldestInputEvent=9223372036854775807, NewestInputEvent=0, HandleInputStart=107961134278894, AnimationStart=107961134423353, PerformTraversalsStart=107961134430311, DrawStart=107961167838686, SyncQueued=107961175214436, SyncStart=107961175761228, IssueDrawCommandsStart=107961175931770, SwapBuffers=107961182849770, FrameCompleted=107961183944228, DequeueBufferDuration=256000, QueueBufferDuration=323000, 
05-01 16:29:41.500 25532 25532 D AdTagLoader: Ad progress: 2761 ms of 15036 ms
05-01 16:29:41.735 25532 25706 W edia3.demo.mai: Accessing hidden method Lsun/misc/Unsafe;->getObject(Ljava/lang/Object;J)Ljava/lang/Object; (greylist, linking, allowed)
05-01 16:29:43.988 25532 25532 I Choreographer: Skipped 151 frames!  The application may be doing too much work on its main thread.
05-01 16:29:43.999 25532 25588 I OpenGLRenderer: Davey! duration=2537ms; Flags=0, IntendedVsync=107961174319218, Vsync=107963693502501, OldestInputEvent=9223372036854775807, NewestInputEvent=0, HandleInputStart=107963700915854, AnimationStart=107963701076979, PerformTraversalsStart=107963701152312, DrawStart=107963701697271, SyncQueued=107963704785979, SyncStart=107963705151146, IssueDrawCommandsStart=107963705270271, SwapBuffers=107963709660687, FrameCompleted=107963712392104, DequeueBufferDuration=246000, QueueBufferDuration=1720000,

So this just looks like a pause to the AdsTagLoader:

05-01 16:29:44.019 25532 25532 D AdTagLoader: pauseAd AdMediaInfo[http://192.168.5.160/video/vast_test/test1/pet_collective_vp8.webm, (0, 0)]

I've got some ideas how to fix this, but there are so many ways I'd like to get input from the team first.

Media

I'll try and set something up.. and send it to android-media..

Bug Report

You will email the zip file produced by adb bugreport to android-media-github@google.com after filing this issue.

Thanks for reporting, I can reproduce the issue. Will submit a fix that postpones the listener deregistration in AdTagLoader which solves the problem at the point where it occurs.

Postpone AdTagLoader listener deregistration to receive final error

Thanks for reporting, I can reproduce the issue. Will submit a fix that postpones the listener deregistration in AdTagLoader which solves the problem at the point where it occurs.

Yes, definitely the best solution is in the ImaAdsLoader and AdTagLoader interaction.

As I understand the contract, ImaAdsLoader keeps a set of AdTagLoader's based on MediaSource and/or the getAdsId() for the Timeline.Period.

ImaAdsLoader keeps only one AdTagLoader is "active" at a time and maybeUpdateCurrentAdTagLoader() is called for AdsLoader.start(), stop(), release() and any position change events that would change the current timeline or period.

The issue occurs because an playback error:

calls AdsMediaSource.releaseSourceInternal() -> AdsLoader.stop() -> AdsLoader.maybeUpdateCurrentAdTagLoader() -> AdTagLoader.deactivate()
and AdTagLoader.deactivate() removes the Player.Listener before it has a chance to get the onPlayerError() callback

It looked to me like having two AdTagLoader's listening at once would not lead to good things, but that is as far as I got.

As a quick and dirty fix (our situation does not have multiple AdTagLoader's ever, so it is very simple), I simply did not deactivate if there is no new current loader:

  private void maybeUpdateCurrentAdTagLoader() {
    @Nullable AdTagLoader oldAdTagLoader = currentAdTagLoader;
    @Nullable AdTagLoader newAdTagLoader = getCurrentAdTagLoader();
    if (!Util.areEqual(oldAdTagLoader, newAdTagLoader)) {
      if (oldAdTagLoader != null && newAdTagLoader != null) {
        oldAdTagLoader.deactivate();
      }
   ...

I'm sure the correct fix is more complicated than this, but it does lead to exactly the correct sequence of events:

05-02 09:39:41.139 13085 13633 W Codec2Client: query -- param skipped: index = 2415921170.
05-02 09:39:41.151 13085 13085 D EventLogger: videoDisabled [eventTime=73.63, mediaPos=2.39, buffered=6.88, window=0, period=0, adGroup=0, ad=0]
05-02 09:39:41.152 13085 13085 D PlayerStatisticsHelper: mergeCounterValues, videoFramesRendered: 90 after capturing snapshot renderedOutputBufferCount: 46
05-02 09:39:41.161 13085 13085 D EventLogger: audioDisabled [eventTime=73.64, mediaPos=2.39, buffered=6.88, window=0, period=0, adGroup=0, ad=0]
05-02 09:39:41.169 13085 13085 D EventLogger: videoDecoderReleased [eventTime=73.65, mediaPos=2.39, buffered=6.88, window=0, period=0, adGroup=0, ad=0, c2.android.vp8.decoder]
05-02 09:39:41.178 13085 13085 D EventLogger: audioDecoderReleased [eventTime=73.66, mediaPos=2.39, buffered=6.88, window=0, period=0, adGroup=0, ad=0, c2.android.vorbis.decoder]
05-02 09:39:41.188 13085 13085 D EventLogger: loadCanceledMedia [eventTime=73.67, mediaPos=2.39, buffered=6.88, window=0, period=0, adGroup=0, ad=0, com.google.android.exoplayer2.source.LoadEventInfo@81ce40a]
05-02 09:39:41.216 13085 13085 E EventLogger: playerFailed [eventTime=73.69, mediaPos=2.39, buffered=0.00, window=0, period=0, adGroup=0, ad=0, errorCode=ERROR_CODE_DECODING_FAILED
05-02 09:39:41.216 13085 13085 E EventLogger:   com.google.android.exoplayer2.ExoPlaybackException: MediaCodecVideoRenderer error, index=0, format=Format(1, null, null, video/x-vnd.on2.vp8, null, -1, und, [1280, 720, -1.0], [-1, -1]), format_supported=YES
05-02 09:39:41.216 13085 13085 E EventLogger:       at com.google.android.exoplayer2.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:566)
05-02 09:39:41.216 13085 13085 E EventLogger:       at android.os.Handler.dispatchMessage(Handler.java:103)
05-02 09:39:41.216 13085 13085 E EventLogger:       at android.os.Looper.loop(Looper.java:214)
05-02 09:39:41.216 13085 13085 E EventLogger:       at android.os.HandlerThread.run(HandlerThread.java:67)
05-02 09:39:41.216 13085 13085 E EventLogger:   Caused by: com.google.android.exoplayer2.video.MediaCodecVideoDecoderException: Decoder failed: c2.android.vp8.decoder
05-02 09:39:41.216 13085 13085 E EventLogger:       at com.google.android.exoplayer2.video.MediaCodecVideoRenderer.createDecoderException(MediaCodecVideoRenderer.java:1438)
05-02 09:39:41.216 13085 13085 E EventLogger:       at com.google.android.exoplayer2.mediacodec.MediaCodecRenderer.render(MediaCodecRenderer.java:844)
05-02 09:39:41.216 13085 13085 E EventLogger:       at com.google.android.exoplayer2.trickplay.TrickPlayRendererFactory$TrickPlayAwareMediaCodecVideoRenderer.render(TrickPlayRendererFactory.java:234)
05-02 09:39:41.216 13085 13085 E EventLogger:       at com.google.android.exoplayer2.ExoPlayerImplInternal.doSomeWork(ExoPlayerImplInternal.java:989)
05-02 09:39:41.216 13085 13085 E EventLogger:       at com.google.android.exoplayer2.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:489)
05-02 09:39:41.216 13085 13085 E EventLogger:       ... 3 more
05-02 09:39:41.216 13085 13085 E EventLogger:   Caused by: java.lang.IllegalStateException
05-02 09:39:41.216 13085 13085 E EventLogger:       at android.media.MediaCodec.native_dequeueOutputBuffer(Native Method)
05-02 09:39:41.216 13085 13085 E EventLogger:       at android.media.MediaCodec.dequeueOutputBuffer(MediaCodec.java:2790)
05-02 09:39:41.216 13085 13085 E EventLogger:       at com.google.android.exoplayer2.mediacodec.SynchronousMediaCodecAdapter.dequeueOutputBufferIndex(SynchronousMediaCodecAdapter.java:105)
05-02 09:39:41.216 13085 13085 E EventLogger:       at com.google.android.exoplayer2.mediacodec.MediaCodecRenderer.drainOutputBuffer(MediaCodecRenderer.java:1850)
05-02 09:39:41.216 13085 13085 E EventLogger:       at com.google.android.exoplayer2.mediacodec.MediaCodecRenderer.render(MediaCodecRenderer.java:823)
05-02 09:39:41.216 13085 13085 E EventLogger:       ... 6 more
05-02 09:39:41.216 13085 13085 E EventLogger: ]
05-02 09:39:41.222 13085 13085 D EventLogger: loading [eventTime=73.70, mediaPos=2.39, buffered=0.00, window=0, period=0, adGroup=0, ad=0, false]
05-02 09:39:41.230 13085 13085 D TrickPlayController: resetTrickPlayState(true) - speed: 1.0 prev mode: NORMAL
05-02 09:39:41.231 13085 13085 D TrickPlayController: Reached playlist end in mode: NORMAL, staying in mode.
05-02 09:39:41.233 13085 13085 I EventLogger: state [eventTime=73.71, mediaPos=2.39, buffered=0.00, window=0, period=0, adGroup=0, ad=0, IDLE]
05-02 09:39:41.260 13085 13085 D EventLogger: isPlaying [eventTime=73.74, mediaPos=2.39, buffered=0.00, window=0, period=0, adGroup=0, ad=0, false]
05-02 09:39:41.310 13085 13085 D EventLogger: bandwidthEstimate [eventTime=73.79, mediaPos=0.00, buffered=0.00, window=0, Received BW Estimate.  Loaded Bytes: 3260662, sample: 7.402184(Mbps), estimate: 7.402184(Mbps)]
05-02 09:39:41.369 13085 13085 D ExoDemo : IMA Error: There was an error playing the video ad. Caused by: Error: There was an error playing the video ad. adsId: 8864f49d-fe87-4284-9c3a-afba2f497817
05-02 09:39:41.385 13085 13085 D ExoDemo : IMA Event at 5700(ms) CONTENT_RESUME_REQUESTED - elapsed(ms): 5700 data: null Ad Id: 5333152702 adsId: 8864f49d-fe87-4284-9c3a-afba2f497817
05-02 09:39:41.403 13085 13085 D ExoDemo : IMA Event at 5717(ms) ALL_ADS_COMPLETED - elapsed(ms): 5717 data: null Ad Id: 5333152702 adsId: 8864f49d-fe87-4284-9c3a-afba2f497817
05-02 09:39:41.404 13085 13085 D ExoDemo : IMA Event: All Ads completed - adsId: 8864f49d-fe87-4284-9c3a-afba2f497817

Thanks so much for taking this on, I'm happy to test any change you propose.

I just saw your commit, after I wrote the long comment ¯_(ツ)_/¯. Will cherry-pick and test the fix

@tonihei

Fix works perfectly, very clever to just defer the unregister. Thanks @tonihei

BTW, the playback issue was with a particular vp8/Vorbis content that failed on an SEI/AmLogic platform that is likely missing some patches from AmLogic to the VP8 decoder (Google Chromecast plays the same content just fine).

Again thanks, closing the bug.

Navigation Menu

Repository navigation

IMA Extension fails to report post-prepared errors to the `VideoAdPlayer.VideoAdPlayerCallback.onError()` #1334

Version

More version details

Devices that reproduce the issue

Devices that do not reproduce the issue

Reproducible in the demo app?

Reproduction steps

Expected result

Actual result

Media

Bug Report

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

IMA Extension fails to report post-prepared errors to the VideoAdPlayer.VideoAdPlayerCallback.onError() #1334

Description

Version

More version details

Devices that reproduce the issue

Devices that do not reproduce the issue

Reproducible in the demo app?

Reproduction steps

Expected result

Actual result

Media

Bug Report

Activity

tonihei commented on May 2, 2024

stevemayhew commented on May 2, 2024

stevemayhew commented on May 2, 2024

stevemayhew commented on May 2, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions

IMA Extension fails to report post-prepared errors to the `VideoAdPlayer.VideoAdPlayerCallback.onError()` #1334