If you are not able to repro this, please allow to use cache. If assets are taking too long to load you might not repro this. 

No errors reporting in chrome://media-internals. Repro'd the first time, but subsequent times the data from 9-12 is just delayed in being appended with 	58.0.3029.81.

You can try with Cache. It's reproable 100% then

Taking a look.

I'm not able to reproduce this, but I have a theory about what may be happening for you. Before reading further, stable just updated to 58 (which I tested with), so update your chrome and see if its still happening for you.


THEORY:
Your demo doesn't check if your SourceBuffer is still updating when you make your next append, but it still works because you have a timer for 4900 msec between fetches. Maybe that 4900 msec is not always long enough to completely process an append. If this occurred it would mostly likely occur after appending 1_h.mp4 (18.8 MB!). When you grab 2_h.mp4 (immediately when cache is enabled, maximizing repro chance) and the append may fail because 1_h.mp4 is still being processed. This would explain why current time does not advance beyond 9.83 (the end of 1_h.mp4).

The one thing I cant explain with this is why you would be seeing a buffered range up to 12 seconds at the end of the demo. For my theory to hold you really should see the buffered range end around 9.83. Can you double check that this isn't the case?


NOTE:
For others attempting repro, be careful not to confuse the momentary pause at 9 seconds with a full stop. I find that the video always pauses around that time while we wait for the timer to fire to fetch the last piece of the video.

Deleted: output.mp4 2.4 MB

	output.mp4 2.4 MB View Download

I updated the browser to 58 version. The issue has become intermittent but it is still there. Its definitely not about buffer getting updated while we do appends as I think 4900 ms is enough time to process data when the fragment was cached. Also, the buffered range was till 12.223 and Chrome should definitely not get stuck mid buffer or atleast should throw some exception if there is some issue with the stream.

You said its now intermittent... if you run it 5 times how many times does it repro?

Dale, are you still able to reproduce?

Not waiting for updateend to append the next segment is definitely a potential source of issues here. That should be fixed before dig deeper in this.

I can repro it 2 out of 5 times.

I agree not waiting for updateend to append can be an issue, but that script was written just for the sake of this bug. Our player internally use dash.js to append segments which handles all this logic. The scipt was written so that you guys could repro it consistently. And I think 4.9 seconds is enough time for browser to append the segment.

I agree, but at least log the updateend and append calls so that we can see they are truly interleaved appropriately.

Also chcunningham@ I did just repro on ChromeOS; it always seems to happen the first try, so maybe try clearing cache?

Should I update the script to wait for updateEnd and log it? Or is it fine this way as you are able to repro it?

Script should at least log append vs updateend, waiting for be best to be sure. While we can repro, it doesn't mean the issue is not the event ordering.

Okay. I will update the script and notify here.

I have updated the script to log updateend event with current timestamps. When I try with disabled cache, the issue is 100% reproducible.

I was not able to repro after 5 tries. The playback certainly has lots of starts and stops as chunks are loaded, but ultimately currentTime always ends up around 12 seconds. Dale, are you able to repro?

I should mention, I disabled cache for all repro attempts. 

I am able to repro on 58.0.3029.81, but the ordering of updateend events is suspicious when this occurs -- logs are still not accurate on the test site. The append log is printed before the append actually starts (it should be printed from within the xhr return).

Will build a local build and see if it's busted there.

Any updates on this?

dalecurtis@ could you please update the latest observations as per comment #25

Thank You...

I won't have time to look at this before heading out of office. I'll sync with Chris to understand his repro situation on Thursday.

Is there any progress on this?

I took a look at Dale's repro and its the same behavior I was seeing earlier - there is a momentary pause around 9 seconds, but the video ultimately continues past that point to reach ~12 seconds.

In the video below you can see I've added some console logging to your demo to show when files are downloaded and appended. The code is otherwise unchanged.
http://storage.googleapis.com/chcunningham-chrome-shared/jank2.html

You'll notice that the moment the video unfreezes is the same moment the last file is downloaded (network tab and logs confirm). The freeze is expected because you've previously cleared the whole buffer when you start to download the higher resolution content. 

The end of my video shows the buffered range and current time are both around 12 seconds. This is working as intended. 

Attaching video of above repro attempt with logging/network.

Deleted: jank2.mp4 2.4 MB

	jank2.mp4 2.4 MB View Download

Here's my video where playback gets stalled after 9 seconds.

Deleted: May 22 2017 11-15 AM.webm 5.0 MB

	May 22 2017 11-15 AM.webm 5.0 MB View Download

Can you grab a copy of log table in chrome://media-internals when this occurs? chrome://media-internals will list all your active players, so close all your other tabs (except for the repro and chrome://media-internals) to make it easy to find the right one. 

Here are the logs :

Player Properties  Copy to clipboard

Property	Value
audio_buffering_state	BUFFERING_HAVE_NOTHING
audio_codec_name	aac
audio_dds	false
audio_decoder	FFmpegAudioDecoder
debug	Video rendering in low delay mode.
duration	unknown
event	PLAY
found_audio_stream	true
found_video_stream	true
pipeline_buffering_state	BUFFERING_HAVE_NOTHING
pipeline_state	kPlaying
player_id	4
render_id	5669
url	blob:http://de9b7h88wgj5l.cloudfront.net/0b37534a-59b7-40e6-b36e-8030a4ec1014
video_buffering_state	BUFFERING_HAVE_NOTHING
video_codec_name	h264
video_dds	false
video_decoder	GpuVideoDecoder
Log 
property filter

Timestamp	Property	Value
00:00:00 00	pipeline_state	kCreated
00:00:00 00	event	WEBMEDIAPLAYER_CREATED
00:00:00 00	url	blob:http://de9b7h88wgj5l.cloudfront.net/0b37534a-59b7-40e6-b36e-8030a4ec1014
00:00:00 00	pipeline_state	kStarting
00:00:00 495	found_video_stream	true
00:00:00 495	video_codec_name	h264
00:00:00 495	found_audio_stream	true
00:00:00 495	audio_codec_name	aac
00:00:00 496	audio_dds	false
00:00:00 496	audio_decoder	FFmpegAudioDecoder
00:00:00 496	debug	Video rendering in low delay mode.
00:00:00 520	video_dds	false
00:00:00 520	video_decoder	GpuVideoDecoder
00:00:00 520	pipeline_state	kPlaying
00:00:00 520	audio_buffering_state	BUFFERING_HAVE_ENOUGH
00:00:00 583	video_buffering_state	BUFFERING_HAVE_ENOUGH
00:00:00 583	pipeline_buffering_state	BUFFERING_HAVE_ENOUGH
00:00:00 495	duration	unknown
00:00:01 496	event	PLAY
00:00:01 572	video_buffering_state	BUFFERING_HAVE_NOTHING
00:00:01 572	video_buffering_state	BUFFERING_HAVE_ENOUGH
00:00:10 553	audio_buffering_state	BUFFERING_HAVE_NOTHING
00:00:10 553	pipeline_buffering_state	BUFFERING_HAVE_NOTHING
00:00:29 181	audio_buffering_state	BUFFERING_HAVE_ENOUGH
00:00:29 181	pipeline_buffering_state	BUFFERING_HAVE_ENOUGH
00:00:29 196	video_buffering_state	BUFFERING_HAVE_NOTHING
00:00:30 43	audio_buffering_state	BUFFERING_HAVE_NOTHING
00:00:30 43	pipeline_buffering_state	BUFFERING_HAVE_NOTHING

Any update on this? And why the ticket is in 'Won't Fix'?

Player Properties  Copy to clipboard

Property	Value
audio_buffering_state	BUFFERING_HAVE_ENOUGH
audio_codec_name	aac
audio_dds	false
audio_decoder	FFmpegAudioDecoder
debug	Video rendering in low delay mode.
duration	unknown
event	PLAY
found_audio_stream	true
found_video_stream	true
pipeline_buffering_state	BUFFERING_HAVE_NOTHING
pipeline_state	kPlaying
player_id	58
render_id	1011
url	blob:http://localhost/eeac39af-b600-4228-97a0-dfbfa815230b
video_buffering_state	BUFFERING_HAVE_NOTHING
video_codec_name	h264
video_dds	false
video_decoder	GpuVideoDecoder
Log 
property filter

Timestamp	Property	Value
00:00:00 00	pipeline_state	kCreated
00:00:00 00	event	WEBMEDIAPLAYER_CREATED
00:00:00 00	url	blob:http://localhost/eeac39af-b600-4228-97a0-dfbfa815230b
00:00:00 00	pipeline_state	kStarting
00:00:00 505	found_video_stream	true
00:00:00 506	video_codec_name	h264
00:00:00 506	found_audio_stream	true
00:00:00 506	audio_codec_name	aac
00:00:00 507	audio_dds	false
00:00:00 507	audio_decoder	FFmpegAudioDecoder
00:00:00 507	debug	Video rendering in low delay mode.
00:00:00 526	video_dds	false
00:00:00 526	video_decoder	GpuVideoDecoder
00:00:00 526	pipeline_state	kPlaying
00:00:00 527	audio_buffering_state	BUFFERING_HAVE_ENOUGH
00:00:00 585	video_buffering_state	BUFFERING_HAVE_ENOUGH
00:00:00 585	pipeline_buffering_state	BUFFERING_HAVE_ENOUGH
00:00:00 506	duration	unknown
00:00:01 506	event	PLAY
00:00:01 578	video_buffering_state	BUFFERING_HAVE_NOTHING
00:00:01 578	video_buffering_state	BUFFERING_HAVE_ENOUGH
00:00:10 594	video_buffering_state	BUFFERING_HAVE_NOTHING
00:00:11 394	audio_buffering_state	BUFFERING_HAVE_NOTHING
00:00:11 394	pipeline_buffering_state	BUFFERING_HAVE_NOTHING
00:00:15 282	audio_buffering_state	BUFFERING_HAVE_ENOUGH

I have updated the script with some more logs: 
http://de9b7h88wgj5l.cloudfront.net/static/arcagraw/PlaybackStallNew.html


These are the new logs where I could repro this issue. The repro frequency has now come down to 50%. 
New logs:
PlaybackStall.html:82 Downloading 1.mp4
17:30:38.191 PlaybackStall.html:48 Appending 1.mp4 Source buffer is not updating
17:30:38.205 PlaybackStall.html:33 UpdateEnd event : Timestamp 1496232038203
17:30:38.205 PlaybackStall.html:36 Buffered Range : 0-9.877333
17:30:43.096 PlaybackStall.html:82 Downloading 2.mp4
17:30:43.102 PlaybackStall.html:48 Appending 2.mp4 Source buffer is not updating
17:30:43.103 PlaybackStall.html:33 UpdateEnd event : Timestamp 1496232043104
17:30:43.103 PlaybackStall.html:36 Buffered Range : 0-12.223432
17:30:48.003 PlaybackStall.html:79 Removing Buffer: Source buffer is not updating
17:30:48.003 PlaybackStall.html:82 Downloading 1_h.mp4
17:30:48.005 PlaybackStall.html:33 UpdateEnd event : Timestamp 1496232048005
17:30:48.053 PlaybackStall.html:48 Appending 1_h.mp4 Source buffer is not updating
17:30:48.096 PlaybackStall.html:33 UpdateEnd event : Timestamp 1496232048097
17:30:48.097 PlaybackStall.html:36 Buffered Range : 0-9.877333
17:30:52.961 PlaybackStall.html:82 Downloading 2_h.mp4
17:30:52.970 PlaybackStall.html:48 Appending 2_h.mp4 Source buffer is not updating
17:30:52.971 PlaybackStall.html:33 UpdateEnd event : Timestamp 1496232052972
17:30:52.971 PlaybackStall.html:36 Buffered Range : 0-12.223432

Sorry, these logs don't show a reason for the stall. To get more detailed logs we'd need to use a custom build. Do you have any experience compiling chromium?

WontFix is due being unable to reproduce the issue on our end. 

I have never compiled Chromium, but I can give it a try. 

Also, as per comment 3,13 and 20,  dalecur...@chromium.org is able to repro this. 

@#27 appears to indicate there's potential for a real repro, so un-marking WontFix.
@#34 please see #25 (those repros from dalecurtis@ were not real repros, just temporary pauses around 9 seconds).

You might also consider adding a currentTime logging interval function so that it's obvious from the logs when the stall(s) occur. I was unable to repro today on about 8 quick attempts on Linux Chrome 58. There is indeed a temporary stall at about 9 seconds, which lasts until 2_h append completes, then playback resumes until about 12 seconds.

Similarly unable to repro on Windows Chrome 58.

Have added the current time logs:
http://de9b7h88wgj5l.cloudfront.net/static/arcagraw/PlaybackStall.html

Any updates on this bug?

Without a local repro we'll need chrome debug logs from your repro. I'm having trouble getting windows builds to produce the logs I need, but while I sort that out you might begin to familiarize yourself with syncing the sources and building compiling chromium.  

Here are the build instructions for windows
https://chromium.googlesource.com/chromium/src/+/master/docs/windows_build_instructions.md

Alternatively, if you have a linux machine handy (and can repro the issue on linux), you can use these linux build instructions. IMHO the linux setup is a little simpler and I'm not having any trouble getting debug logs on linux, so this may be a faster 
path if its available to you.
https://chromium.googlesource.com/chromium/src/+/master/docs/linux_build_instructions.md

When following either windows/linux instructions, after instructed to run the command "gn gen out/Default", please customize the build arguments by then running the command

gn args out/Default

Once the editor appears, delete the current contents of the file and replace with the following args:

is_debug = false 
dcheck_always_on = true 
proprietary_codecs = true
ffmpeg_branding = "Chrome" 

save and exit. Then continue with build instructions to build chrome.

Hi
We will have to work on Windows for this one. Could you get the windows build produce the required logs at your end? This is leading to production issues with our customers and we are having a tough time isolate it at our end.
A quick help would be really appreciated

Thanks
Karishma

I have updated the script which makes it 100% reproducible on my machine.
http://de9b7h88wgj5l.cloudfront.net/static/arcagraw/PlaybackStallWithCache.html

You should run the script after enabling cache and it should get reproduced the second time after the segments are cached. 

Also, I compiled Chromium but the script gives error while creating Media Source buffer. MediaSource.isTypeSupported(codec) gives false for the codecs provided in the script.

The script still does not reproduce on my machine, even on the second try with everything coming from cache. 

Thanks for compiling chromium. The isTypeSupported error likely means you don't have proprietary codecs enabled. Navigate your command line to chromium "src" directory and give the command:

gn args out/Default

Once the editor appears, delete the current contents and replace with the following:

is_debug = false 
dcheck_always_on = true 
proprietary_codecs = true
ffmpeg_branding = "Chrome" 


Save, exit, and rebuild. I'm taking another look at the debug logging issue this morning. Will give an update in a bit. 

Here the issue is reproducible on both MAC and Windows systems. Ideally, the first two segments should come from cache and the remaining two without cache. You should try throttling for the last segment.

I tried with the provided arguments but it sill gave the same error.

> Ideally, the first two segments should come from cache and the remaining two without cache. You should try throttling for the last segment.

I *might* have a repro on mac following these instructions. Still digging into it. Please avoid changing the script further. 

That's a *great* news.

I do have a consistent (over 50%) repro on my mac laptop with your latest link. Looks like the problem should go away if you call mediaSource.endOfStream() after you've appended your last chunk.

The stall around 9 seconds is caused by the audio renderer getting stuck waiting for more decoded frames to queue up. Every time the audio queue underflows we increase the size required for the queue to be considered "full". The idea being, if we buffer a little more next time it should hopefully prevent another stall. 

The demo script you've provided causes 2 number of underflows (when timing is right):
1. at the point where you remove everything from the buffer before appending 1_h.mp4
2. the point where current time reaches the end of 1_h.mp4, but 2_h.mp4 has not yet been appended

When you append the final 2_h.mp4, the buffer gets some audio, but not enough to be considered "full" given the increases from these underflows. Buuuut, if you call mediaSource.endOfStream() after your last append, the queue fullness check is short circuited because the pipeline will know it can't expect anything more to be appended and should play what it has. 


--- side issue ---

+Dale.

I've attached some debug logs. One thing I notice is the queue capacity is being increased 4x instead of 2x. I think this means we're consistently hitting the path of written < requested [0] followed by written == 0 [1]. Do you want to catch this condition and not increase queue the second time?

[0] https://cs.chromium.org/chromium/src/media/renderers/audio_renderer_impl.cc?l=909
[1] https://cs.chromium.org/chromium/src/media/renderers/audio_renderer_impl.cc?l=903

Deleted: out (3).txt 3.9 MB

out (3).txt 3.9 MB View Download

I can see the playback resumes when I signal end of stream. But I have seen this issue with live streams as well where we do continuous appends but the playback remains stuck. Is there some other case where the queue fullness check might be failing? Also, if I nudge the current time by 0.2 seconds, the playback comes out of stall state.

The queue capacity maxes out at 3 seconds, so this should not be a source of permanent stuck-ness if you're continuously appending more media. Its possible we have a bug somewhere, but there are lots of reasons a stream can stall - I wouldn't bet on it being the same issue. Happy to look at a demo if you can reproduce it. 

The nudge-current-time trick works because seeking resets the queue's capacity to its original (smaller) size (to avoid making seeks slow to complete). 

@chcunningham, that would seem reasonable; e.g. some sort of restriction timer before allowing another increase.

Any updates here?

The behavior you're seeing in the demo is mostly working-as-intended. Underflows increase the queue size to restart playback. 

We can (and should) be a little slower about increasing the queue size (mentioned in comment 49), but this does not eliminate the possibility that a demo like yours can end up stuck forever. The best fix for your stuckness is to either 1) call end of stream or 2) append more data. 

I will still make the change to make queue-size grow more slowly. It may cause your demo to appear suddenly fixed, but this is only because the demo averages about 2 underflows. A demo that had 4 underflows would exhibit the same stuckness even after being slower to increase our queue size. 

From your other comments, I worry that your demo does not capture the same bug you're seeing with livestreaming (where more appends are expected and would eventually satisfy queue size requirements). We may have some bug, but I'd need you to provide a repro of that issue to dig further. 

Double check your append logic - make sure you don't stop appending data whenever you see buffered slightly ahead of currentTime - if playback is stopped you'll need to continue to append more.