IMA SDK ad finishes incorrectly [Android]

[Igor]

Hi.

  We've met the following abnormal behavior of the SDK on our ad provider videos. This is not 100% reproducible and happens not too often. Didn't manage to reproduce this on the Google reference ads. We use Android 3.24.0 SDK and can't upgrade because 3.25.1 has issue with building and 3.26.0 requires targetSdkVersion 31 which we can't do for now.

 1. video is played correctly till the very end. We've checked Android logs and it seems that the default video player gets EOS without having any errors.
 2. we get MediaPlayerNative: Attempt to call getDuration in wrong state: mPlayer=0x0, mCurrentState=1 message and IMA SDK sends us an error too. It seems that IMA SDK asks for ad position after the media player stopped playing the video. We use the modified reference ad player implementation from the Advanced sample for our application. Any ideas what could go wrong.

Here's the log. Look for Age IMA Wrapper:: lines to see the events we get from the SDK. Log contains both ads played with and without errors.

[IMA SDK]

Hello Igor,

 

I'm Michael from IMA SDK Team, thank you for reaching out to us.

 

Kindly share the following information for us to investigate further:

• Modified sample project implementation that can replicate the issue
• Screen recording of the behavior for better illustration of the issue
• Steps to reproduce the behavior
• VAST Ad Tag

 

If the file(s) you are looking to share are less than 25mb in total you can attach them to this case on your next reply. If you are having trouble attaching your file to this case or if your file(s) are larger than 25mb, you can share your files with me by performing the following steps:

 

1. Navigate to

https://docs.google.com/forms/d/e/1FAIpQLSfkAiXMeYP-fw1W3Z-tT9uwmATEKO5X6S-th0gR2ezdKaaqfg/viewform?usp=pp_url&entry.400550049=IMA+SDK&entry.460850823=5004Q00002WvQXAQA3&entry.80707362=00094166

2. Fill out all fields, and attach your file(s).

3. Please reply back on this thread when you have uploaded your file(s). Please do not share this link.

 

If you opt to share it on this thread, please use the "Reply To Author" button to send it privately. Otherwise, use the link mentioned above.

Regards,

Michael Angelo IMA SDK Team

ref:_00D1U1174p._5004Q2WvQXA:ref

[Igor]

Hi Michael.

  We've found the reason of the bug. This is not "can not reproduce" obviously. Your Basic sample has a race condition which we copied into our application. All parts of this story just should have never happen.

  Here are the details:

1. VideoPlayerWithAdPlayback.startTracking() launches the updateTimerTask which runs in a dedicated thread. It calls videoAdPlayer.getAdProgress() which uses videoPlayer.getCurrentPosition() and videoPlayer.getDuration()
2. Both viedoPlayer's methods check if playbackState == PlaybackState.STOPPED before calling for VideoView methods.
3. However, onCompletion(MediaPlayer mediaPlayer) callback arrives in the main thread and resets the mediaPlayer first, then makes playbackState = PlaybackState.STOPPED;
   

  This effectively allows timer task to access mediaPlayer which was reset before playbackState becomes STOPPED. However. operations reordering (mark stopped, then reset) is not enough due to potential memory operations reordering and other black magic under the hood of CPU and JVM/JIT. playbackState must be declared volatile in order to guarantee your fixed lockless magic works. Another option is adding willComplete() callback to videoPlayerCallbacks, which will be called before mediaPlayer state is changed where one resets the timer, so that it is never triggered after the player is reset.

  This bug could be nailed down without any reproduction, I've provided more than enough information and logs. That said, it should have never been created either: race condition and memory ordering is the first thing any programmer must consider writing multi-threaded code.

[IMA SDK]

Hi Igor,

I work along with Michael. Thank you for getting back to us and providing the detailed findings on the issue at hand. As per reproducing the issue by modifying our sample app, we always request this to our publishers who reported a crash or behavior as it will greatly help us to debug, corroborate data points and to provide decisive resolution to the reported issue. With that all said, let me raise this (including the reports and discussion thus far) to the rest of the team for further investigation. I'll update this thread the soonest I hear back from them.

Regards,

Teejay Wennie IMA SDK Team

ref:_00D1U1174p._5004Q2WvQXA:ref

[IMA SDK]

Hello Igor,

This is Jackson from the IMA SDK DevRel team, to help with this issue.

You had mentioned that the issue is happening in your app, due to code that was copied from the IMA samples. Based on the nature of the issue (memory issue), it would likely result in a crash, but our sample apps are able to run without crashing. Can you help me understand a little more about how/when this race condition happens? I can then start working on an update to the sample apps.

Also, you had mentioned that you are using Android 3.24.0. Is the issue still reproducible on the latest version of the samples? (sample version 3.28.2-0 link)

Thank you,
Jackson
IMA SDK team

ref:_00D1U1174p._5004Q2WvQXA:ref

[Igor]

Hi Jackson.

  AdvancedSample 3.28.2-0 contains the very same bug. Please, see the attached file with the fix. One line modified. One line moved around.

  Since we are talking about java, it is unlikely you'll get a crash. In fact this very race condition leads to unexpected behavior.  And you probably won't notice it in your sample anyway. It won't crash. But sometimes Android runtime will complain in the logs.

  So, what's happening.
1. SampleVideoPlayer's  implementation of the public void onCompletion(MediaPlayer mediaPlayer) callback is called by the system media player.
2. onCompletion callback performs mediaPlayer.reset(); but before playbackState = PlaybackState.STOPPED; is called the main thread becomes suspended. This is not very likely but it happens in our application.

3. while the main thread is suspended VideoPlayerWithAdPlayback's timer is triggered in the timer's thread. the timer performs the following code: callback.onAdProgress(adMediaInfo, videoAdPlayer.getAdProgress());
4. videoAdPlayer.getAdProgress() calls videoPlayer.getDuration()
5. videoPlayer.getDuration() checks playbackState == PlaybackState.STOPPED. This is obviously false, see 2.
6. videoPlayer.getDuration() calls super.getDuration() which leads to an error because mediaPLayer is already reset (see 2).
7. system videoplayer treats this as an error and sends corresponding onError(...) message to OnErrorListener callback set in SampleVideoPlayer.


Please, let me know what step is unclear. I don't really think it it possible to reliably reproduce this bug. There should be a very specific timing, but if you put a reasonable long sleep before  playbackState = PlaybackState.STOPPED in the onCompletion handler from 2. you'll get a 100% reproduction.

Speaking about reproduction engineer can't simply say "I won't fix it because I can't reproduce it", because this is not professional. Sometimes one needs to thing a little bit and to read logs and study sympthoms to be able to reconstruct what's going on at clients machine and to nail down the bug. Most of our crashes have never been reproduced in the office, but we still fix them.

[IMA SDK]

Hi Igor,

Thank you for clarifying the issue.

I believe this should be fixed in the latest repository commit (link).

This change will be included in the next release of the Android sample apps.

Thank you for your persistence in this issue and please let me know if you have any additional questions.

[Igor Lobanchikov]

Hi Jackson.

  Please, note that it is important to make playbackState volatile since otherwise JVM\JIT won't use memory barriers logic and won't be able to guarantee that the readers actually see playbackState changes before the player is reset. Although you might see the correct behavior now, this might change on any architecture and\or device without prior warning. Reading\writing volatile variable implicitly issues read\write memory barrier and helps to sort this out.

  This is the first result google shows me for a 'java volatile' request. https://www.baeldung.com/java-volatile

  Please, be careful with multithreading.

Regards,

Igor.

[IMA SDK]

Hello Igor,

Thank you for following up. I was able to speak with the IMA eng team, and for our samples we do not think the 'volatile' keyword is needed in this case.

Please feel free to follow up if you have questions.

Thank you,

[Igor Lobanchikov]

Uh. Never mind.

Thanks for your time and efforts.

--

Regards,

Igor.

[IMA SDK]

Hi Igor,

Thank you for reaching out with this issue. You can look for the updated sample releases on the IMA Android GitHub .