First segment loaded in infinite loop

[kmamal]

What version of Hls.js are you using?

v0.12.4

What browser and OS are you using?

Ubuntu18.04 with Firefox70.0 (64-bit).

Test stream:

https://hls-js-latest.netlify.com/demo/?src=https%3A%2F%2Ftest-streams.mux.dev%2Fx36xhzz%2Furl_6%2F193039199_mp4_h264_aac_hq_7.m3u8&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOnRydWUsImR1bXBmTVA0IjpmYWxzZSwibGV2ZWxDYXBwaW5nIjotMSwibGltaXRNZXRyaWNzIjotMX0=

Checklist

• The issue observed is not already reported by searching on Github under https://github.com/video-dev/hls.js/issues
• The issue occurs in the stable client on https://hls-js.netlify.com/demo and not just on my page

• The issue occurs in the latest client on https://hls-js-latest.netlify.com/demo and not just on my page

• The stream has correct Access-Control-Allow-Origin headers (CORS)
• There are no network errors such as 404s in the browser console when trying to play the stream

Steps to reproduce

1. Open the link to the demo player as provided above.
2. In the config window on the right, add maxFragLookUpTolerance": 0 and "maxBufferHole": 0 so that the final result is:

{
  "debug": true,
  "enableWorker": true,
  "maxFragLookUpTolerance": 0,
  "maxBufferHole": 0
}

1. Check the "Persist" option, click on "Apply", and reload the page. (Notice that just clicking "Apply" doesn't make the bug appear.)

Expected behavior

I would expect the video to load and play normally.

Actual behavior

The first segment loads in a loop. The following message is repeated in the console: [log] > Loading 0 of [0 ,7],level 0, currentTime:0.000,bufferEnd:0.000.

Console output

A cookie associated with a cross-site resource at http://cloudflare.com/ was set without the `SameSite` attribute. A future release of Chrome will only deliver cookies with cross-site requests if they are set with `SameSite=None` and `Secure`. You can review cookies in developer tools under Application>Storage>Cookies and see more details at https://www.chromestatus.com/feature/5088147346030592 and https://www.chromestatus.com/feature/5633521622188032.
hls-js-latest.netlify.com/:1 A cookie associated with a cross-site resource at http://www.netlify.com/ was set without the `SameSite` attribute. A future release of Chrome will only deliver cookies with cross-site requests if they are set with `SameSite=None` and `Secure`. You can review cookies in developer tools under Application>Storage>Cookies and see more details at https://www.chromestatus.com/feature/5088147346030592 and https://www.chromestatus.com/feature/5633521622188032.
ace.js:1 [Violation] Added non-passive event listener to a scroll-blocking 'mousewheel' event. Consider marking event handler as 'passive' to make the page more responsive. See https://www.chromestatus.com/feature/5745543795965952
t.addListener @ ace.js:1
t.addMouseWheelListener @ ace.js:1
l @ ace.js:1
w @ ace.js:1
t.edit @ ace.js:1
setupConfigEditor @ main.js:1191
(anonymous) @ main.js:49
j @ jquery.min.js:2
fireWith @ jquery.min.js:2
ready @ jquery.min.js:2
I @ jquery.min.js:2
ace.js:1 [Violation] Added non-passive event listener to a scroll-blocking 'touchstart' event. Consider marking event handler as 'passive' to make the page more responsive. See https://www.chromestatus.com/feature/5745543795965952
t.addListener @ ace.js:1
t.addTouchMoveListener @ ace.js:1
l @ ace.js:1
w @ ace.js:1
t.edit @ ace.js:1
setupConfigEditor @ main.js:1191
(anonymous) @ main.js:49
j @ jquery.min.js:2
fireWith @ jquery.min.js:2
ready @ jquery.min.js:2
I @ jquery.min.js:2
ace.js:1 [Violation] Added non-passive event listener to a scroll-blocking 'touchmove' event. Consider marking event handler as 'passive' to make the page more responsive. See https://www.chromestatus.com/feature/5745543795965952
t.addListener @ ace.js:1
t.addTouchMoveListener @ ace.js:1
l @ ace.js:1
w @ ace.js:1
t.edit @ ace.js:1
setupConfigEditor @ main.js:1191
(anonymous) @ main.js:49
j @ jquery.min.js:2
fireWith @ jquery.min.js:2
ready @ jquery.min.js:2
I @ jquery.min.js:2
main.js:215 Using Hls.js config: {debug: true, enableWorker: true, maxFragLookUpTolerance: 0, maxBufferHole: 0}
logger.js:40 [log] > loadSource:https://signalratio.farted.net/fileserver/hlsjs-files-2/test.m3u8
logger.js:40 [debug] > Loading playlist of type manifest, level: 0, id: null
logger.js:40 [debug] > Calling internal loader delegate for URL: https://signalratio.farted.net/fileserver/hlsjs-files-2/test.m3u8
logger.js:40 [log] > trigger BUFFER_RESET
logger.js:40 [log] > set autoLevelCapping:-1
logger.js:40 [log] > attachMedia
logger.js:40 [log] > manifest loaded,1 level(s) found, first bitrate:undefined
logger.js:40 [log] > 1 bufferCodec event(s) expected
logger.js:40 [log] > startLoad(-1)
logger.js:40 [log] > switching to level 0
logger.js:40 [log] > main stream:STOPPED->IDLE
logger.js:40 [log] > audio tracks updated
logger.js:40 [log] > subtitle tracks updated
logger.js:40 [log] > level 0 loaded [0,7],duration:30.96
logger.js:40 [log] > media source opened
logger.js:40 [log] > startLoad(-1)
logger.js:40 [log] > main stream:IDLE->STOPPED
logger.js:40 [log] > main stream:STOPPED->IDLE
logger.js:40 [log] > Loading 0 of [0 ,7],level 0, currentTime:-1.000,bufferEnd:-1.000
logger.js:40 [log] > demuxing in webworker
logger.js:40 [log] > main stream:IDLE->FRAG_LOADING
logger.js:40 [log] > audio stream:STOPPED->STARTING
logger.js:40 [log] > audio stream:STARTING->WAITING_TRACK
logger.js:40 [log] > audio stream:WAITING_TRACK->STOPPED
logger.js:40 [log] > audio stream:STOPPED->STARTING
logger.js:40 [log] > audio stream:STARTING->WAITING_TRACK
logger.js:40 [log] > Loaded 0 of [0 ,7],level 0
logger.js:40 [log] > Parsing 0 of [0 ,7],level 0, cc 0
logger.js:40 [log] > main stream:FRAG_LOADING->PARSING
logger.js:40 [log] > main:discontinuity detected
logger.js:40 [log] > main:switch detected
046cdb7f-694e-4335-9dff-542c79c3ce3a:562 [log] > manifest codec:undefined,ADTS data:type:2,sampleingIndex:3[48000Hz],channelConfig:6
046cdb7f-694e-4335-9dff-542c79c3ce3a:562 [log] > parsed codec:mp4a.40.5,rate:48000,nb channel:6
046cdb7f-694e-4335-9dff-542c79c3ce3a:562 [log] > audio sampling rate : 48000
logger.js:40 [log] > InitPTS for cc: 0 found from video track: 126000
logger.js:40 [log] > creating sourceBuffer(audio/mp4;codecs=mp4a.40.5)
logger.js:40 [log] > creating sourceBuffer(video/mp4;codecs=avc1.640020)
logger.js:40 [log] > main track:audio,container:audio/mp4,codecs[level/parsed]=[undefined/mp4a.40.5]
logger.js:40 [log] > main track:video,container:video/mp4,codecs[level/parsed]=[undefined/avc1.640020]
logger.js:40 [log] > Parsed audio,PTS:[0.000,4.032],DTS:[0.000/4.032],nb:189,dropped:0
logger.js:40 [log] > Parsed video,PTS:[0.021,4.021],DTS:[0.021/4.021],nb:100,dropped:0
logger.js:40 [log] > main stream:PARSING->PARSED
logger.js:40 [log] > target start position not buffered, seek to buffered.start(0) -1 from current time 0 
2logger.js:40 [log] > media seeking to 0.000
logger.js:40 [log] > main buffered : [0.021,4.021]
logger.js:40 [log] > latency/loading/parsing/append/kbps:230/66/251/63/10260
logger.js:40 [log] > main stream:PARSED->IDLE
logger.js:40 [log] > SN just loaded, load next one: 1 Fragment {_url: null, _byteRange: Array(2), _decryptdata: null, _elementaryStreams: {…}, deltaPTS: 0, …}
logger.js:40 [log] > Loading 1 of [0 ,7],level 0, currentTime:0.000,bufferEnd:0.000
logger.js:40 [log] > main stream:IDLE->FRAG_LOADING
logger.js:40 [log] > media seeked to 0.000
logger.js:40 [log] > Loaded 1 of [0 ,7],level 0
logger.js:40 [log] > Parsing 1 of [0 ,7],level 0, cc 0
logger.js:40 [log] > main stream:FRAG_LOADING->PARSING
logger.js:40 [log] > Parsed audio,PTS:[4.032,8.021],DTS:[4.032/8.021],nb:187,dropped:0
logger.js:40 [log] > Parsed video,PTS:[4.021,8.021],DTS:[4.021/8.021],nb:100,dropped:0
logger.js:40 [log] > main stream:PARSING->PARSED
logger.js:40 [log] > main buffered : [0.021,8.021]
logger.js:40 [log] > latency/loading/parsing/append/kbps:67/138/107/5/18197
logger.js:40 [log] > main stream:PARSED->IDLE
logger.js:40 [log] > Loading 0 of [0 ,7],level 0, currentTime:0.000,bufferEnd:0.000
76logger.js:40 [log] > Loading 0 of [0 ,7],level 0, currentTime:0.000,bufferEnd:0.000

Comments

This appears to be related to these two (closed) issues:

• Infinite loop with new FragmentTracker on first segment in playlist #1520
• repeatedly downloading first segments before playback (initial segment buffer hole) #2212.

In both those issues the person reporting the problem managed to overcome it by setting maxSeekHole to a higher value. However in our application we need to be able to seek accurately to specific frames, and if we don't set maxSeekHole to zero, then hls.js doesn't always load the correct fragments when seeking.

The loop loading appears to be caused by the fact that the video starts at around 0.021 (note that the audio does start at 0 as expected). In test files with no audio, the video pts starts at zero so this doesn't happen.

[robwalch]

Noticing that in the latest build (v0.13.0-beta.2) we still get the logs that say the first fragment is loading (even though it is only loaded and buffered once). That log statement is placed a little early, or we need to change how the stream controller interacts with the fragment tracker on idle.

Then, playback stalls at the end of the first fragment and recovers after something (nudging?) prompts the second fragment to be loaded.

There's a couple of issues with hls.js that I think are causing this:

1. We align on PTS rather than DTS and as a result are getting buffer gaps in a lot of streams.
2. With maxBufferHole set to 0 it appears we do not load the correct fragment - since it's not the default, the behavior of the stream controller and frag tracker are under tested in these circumtances

I'll see if we can do something about the second issue for the next release or patch (v0.13.0-1). The PTS/DTS issue is much larger and I will probably focus efforts on addressing that in feature/v1.0.0.

[robwalch]

Turns out this is caused by aborting the loader for the second fragment as result of "seeking" triggered by setting currentTime to -1 in _seekToStartPos.