Last segment doesn't get appended at times if we seek

[ghost]

Version: 2.0

Steps to repro:

1. URL used: http://demo.unified-streaming.com/video/ateam/ateam.ism/ateam.mpd
2. If user keeps seeking (its a race condition so the number of seeks required to repro is not deterministic), at times last segment never gets appended

Analysis:

Below are the logs. I added log lines: onMediaFragmentLoaded and Appending in BufferController.js for mediaType 'video' only.

[502994] onMediaFragmentLoaded: 0 quality: 0
Debug.js:108 [503008] Appending: 0 quality: 0
Debug.js:108 [504940] onMediaFragmentLoaded: 1 quality: 0
Debug.js:108 [504950] Appending: 1 quality: 0
Debug.js:108 [509215] onMediaFragmentLoaded: 2 quality: 3
Debug.js:108 [509581] Appending: NaN quality: 3
Debug.js:108 [509591] Appending: 2 quality: 3
Debug.js:108 [509823] Requesting seek to time: 47.41
Debug.js:108 [509831] Seeking to: 47.41
Debug.js:108 [512437] onMediaFragmentLoaded: 3 quality: 3
Debug.js:108 [512446] Appending: 3 quality: 3
Debug.js:108 [515688] onMediaFragmentLoaded: 11 quality: 0
Debug.js:108 [515703] Appending: NaN quality: 0
Debug.js:108 [515725] Appending: 11 quality: 0
Debug.js:108 [516145] Native video element event: seeked
Debug.js:108 [516681] onMediaFragmentLoaded: 13 quality: 0
Debug.js:108 [516693] Appending: 13 quality: 0
Debug.js:108 [517302] onMediaFragmentLoaded: 12 quality: 0
Debug.js:108 [517316] Appending: 12 quality: 0
Debug.js:108 [517836] onMediaFragmentLoaded: 14 quality: 0
Debug.js:108 [517851] Appending: 14 quality: 0
Debug.js:108 [519118] onMediaFragmentLoaded: 16 quality: 0
Debug.js:108 [519138] Appending: 16 quality: 0
Debug.js:108 [519249] onMediaFragmentLoaded: 15 quality: 0
Debug.js:108 [519266] Appending: 15 quality: 0
Debug.js:108 [520313] Requesting seek to time: 72.33
Debug.js:108 [520327] Seeking to: 72.33
Debug.js:108 [521650] onMediaFragmentLoaded: 17 quality: 0
Debug.js:108 [521667] Appending: 17 quality: 0
Debug.js:108 [522592] Requesting seek to time: 47.21
Debug.js:108 [522605] Seeking to: 47.21
Debug.js:108 [524832] Native video element event: seeked
Debug.js:108 [524887] onMediaFragmentLoaded: 19 quality: 0
Debug.js:108 [524897] Appending: 19 quality: 0
Debug.js:108 [524909] onMediaFragmentLoaded: 18 quality: 0
Debug.js:108 [539086] Requesting seek to time: 78.2
Debug.js:108 [539091] Seeking to: 78.2
Debug.js:108 [540230] Native video element event: seeked
Debug.js:108 [540269] onMediaFragmentLoaded: 18 quality: 0
Debug.js:108 [540279] Appending: 18 quality: 0
Debug.js:108 [543867] onMediaFragmentLoaded: 20 quality: 1
Debug.js:108 [543885] Appending: 18 quality: 0
Debug.js:108 [546259] onMediaFragmentLoaded: 21 quality: 0
Debug.js:108 [546720] Appending: NaN quality: 0
Debug.js:108 [546734] Appending: NaN quality: 1
Debug.js:108 [546751] Appending: 20 quality: 1
Debug.js:108 [548359] onMediaFragmentLoaded: 22 quality: 0
Debug.js:108 [548376] Appending: NaN quality: 0
Debug.js:108 [548409] Appending: 21 quality: 0
Debug.js:108 [550172] onMediaFragmentLoaded: 23 quality: 0
Debug.js:108 [550186] Appending: 22 quality: 0
Debug.js:108 [551878] onMediaFragmentLoaded: 24 quality: 1
Debug.js:108 [551897] Appending: 23 quality: 0
Debug.js:108 [552224] onMediaFragmentLoaded: 25 quality: 1
Debug.js:108 [552242] Appending: NaN quality: 1
Debug.js:108 [552273] Appending: 24 quality: 1

Ideally the expected scheduling-appending loop is append-what-was-loaded. To achieve this we have the lock isFragmentLoading which allows only one segment to be loaded at a time. Now in ScheduleController:onPlaybackSeeking, we set isFragmentLoading as false - allowing 2 segments to be loaded simultaneously. In such a case we break our append-what-was-loaded logic and go one behind...on onMediaFragmentLoaded we append what we loaded before this segment.
As we see towards the end, fragment 25 was loaded but we go one behind and it never gets appended.

[dsparacio]

@KarishmaBagga Thanks for the detailed bug report and MPD I tried to quickly reproduce but was not able to. Is low bandwidth a factor at all in your testing?

Logically your description makes sense of why it could break on that seek. Ill dig into this today. Again thanks for filing issue and getting logs from 2.0

[dsparacio]

I am able to reproduce consistently on bbc mpd so I will use this to fix.

[ghost]

Thanks @AkamaiDASH. I initially thought of aborting the current download in onPlaybackSeeking, but then we do seek for various other cases too like startup (when audio/video don't start with 0 in VoD), live stream etc. So that can't be done.

Another way for VoD is to flush virtual buffer in onStreamCompleted in BufferController. That helps in appending the missed segment but we are still one behind in our loop till the end

[dsparacio]

Yeah I think this is much like the cross period virtual buffer append. Meaning we call appendNext on createBuffer just because there may be one in the pipe. I think we need to check the virtual buffer and if there is one we can figure out where and when to call.

[dsparacio]

@KarishmaBagga where did you add Appending trace? in appendToBuffer or onAppened? appendToBuffer right?

With the unified streaming MPD, when this happens, does it still reach the end or is it one segment from reaching the end and stalls? What does the time codes say? 1:41/1:41?

I am seeing out of order traces produced by seeking but with this stream I am always completing. Now with the BBC test card stream I was able to get it to stop 3 second short of end and see out of order trace. This is a tricky one to get to happen. I don't think it will be hard to fix just hard to repro and test the fix ;)

[ghost]

@AkamaiDASH appending was added in appendToBuffer just before actually appending it in the buffer.
The timecode said 1:38/1:41 or 1:39/1:41..it is one segment short from the end and stalls.

I can somehow repro it quite easily...so if you want me to test a fix or want to have some additional logs printed, I can give it a go

[dsparacio]

Yes this is what I expect to reproduce The timecode said 1:38/1:41 or 1:39/1:41.. and can not with that stream but I was able to once or twice with the BBC test card. I think this will be easy to fix once I can find it ;) If you can help in any capacity it would be great but I'll keep at it now that I am back in office.

[ghost]

I can for sure help you with any extra logs if you want. Try throttling the bandwidth..its easier to repro then
I thought of doing an abort in onPlaybackSeeking but refrained from that as we do seeks internally as well.
Right now, I flush the virtualBuffer if stream is completed

[dsparacio]

@KarishmaBagga OK sorry I am back to this now. I got consumed with seeking logic throughout code and fixed the #s frag stuff so now I can hope to find a #s=X where X always reproduces this issue. I will use a BW limiter as you suggest. y

I am having issue reproducing even with all the stuff above. Are you setting anything with buffer pruning differently than default? Are you testing with cache disabled or enabled?

[ghost]

Just to repro this always I am testing with cache disabled...but everything else as it is

[dsparacio]

thanks I was also disabling cache to force dl. http://demo.unified-streaming.com/video/ateam/ateam.ism/ateam.mpd is not not loading.... no response from server so hopefully will be back up soon.

[dsparacio]

Fixed with PR #1523