Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

seeking to unbuffered position immediately after play loads same segment repeatedly #3811

Closed
3 of 5 tasks
cheweytoo opened this issue Apr 22, 2021 · 3 comments · Fixed by #3852
Closed
3 of 5 tasks
Labels
Milestone

Comments

@cheweytoo
Copy link

cheweytoo commented Apr 22, 2021

What version of Hls.js are you using?

1.0.2 light
1.0.2 non-light

Issue

When seeking immediately after play or a seek to a position that is not yet buffered, the segment for the new position is loaded several times (e.g. segment27_0_av.ts in test case below). Playback stalls until hls.js gets on its feet again and loads the segment following the loop-loaded one.

How many times the affected segment is loaded does not seem to be completely deterministic, and I've seen Firefox 87 load segment27_0_av.ts up to 85(!) times.

The same thing seems to happen with a level switch immediately after a seek, but not every time.

What browser and OS (including versions) are you using?

Firefox 87.0 on Ubuntu 20.04.2
Firefox 88.0 on Windows 10
Edge 85.... on Windows 10
Edge 90.0.818.4 on Windows 10
Chrome 90.0.4430.85 on Windows 10

The issue shows in all of them, with Firefox 88 the "least affected", with only 3-5 loads of segment27_0_av.ts.

Test page:

https://dev.vergnumpft.de/avstuff/hls.js_tests/hls102_segment_loop.html

Configuration:

{
  "debug": true,
  "autoStartLoad": false 
}

Happens with debug = false and autoStartLoad = true as well though.

Auto level switch is disabled, via

hls.startLevel = 0;
hls.loadLevel = 0;

Without those lines, i.e. with auto level switch active, it is even worse, and e.g. in Firefox 87 the looped loading of segment 27 never stops.

Checklist

  • The issue observed is not already reported by searching on Github under https://github.com/video-dev/hls.js/issues
    None that seem obviously related

  • 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-dev.netlify.com/demo and not just on my page
    No to both. I probably simply haven't been able to click fast enough though. The button on my test page reliably reproduces it.

  • 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

  • Go to test page.
  • Open browser dev tools to watch network traffic
  • Click "click to reproduce bug"

Bug is 100% reproducible here.

Expected behavior

Load each media segment only once; continue/keep playing

Actual behavior

…/segment27_0_av.ts is loaded many, many times; playback stalls

Console output

Uh… lots and lots.
First couple of spurious segment loads, in Firefox 87:

[log] > hls.light.min.js:1:3909
[log] > stopLoad hls.light.min.js:1:231168
[log] > loadSource:https://swrplanetschule-vh.akamaihd.net/i/schulfernsehen/natur_nah/natur_nah_-_das_geheimnisvolle_leben_der_waldpflanzen,,_hd,.mp4.csmil/master.m3u8 hls.light.min.js:1:230848
[log] > [stream-controller]: Trigger BUFFER_RESET hls.light.min.js:1:176793
[log] > attachMedia hls.light.min.js:1:230517
[log] > [buffer-controller]: Media source opened hls.light.min.js:1:196277
[log] > [level-controller]: manifest loaded, 2 level(s) found, first bitrate: 825000 hls.light.min.js:1:125357
[log] > 1 bufferCodec event(s) expected hls.light.min.js:1:198444
[log] > startLoad(-1) hls.light.min.js:1:231054
[log] > [level-controller]: switching to level 0 from -1 hls.light.min.js:1:129732
[log] > [level-controller]: Attempt loading level index 0 with URL-id 0 https://swrplanetschule-vh.akamaihd.net/i/schulfernsehen/nat…volle_leben_der_waldpflanzen,,_hd,.mp4.csmil/index_0_av.m3u8 hls.light.min.js:1:128517
[log] > [stream-controller]: STOPPED->IDLE hls.light.min.js:1:161905
[log] > set startLevel:0 hls.light.min.js:1:232904
[log] > set loadLevel:0 hls.light.min.js:1:232434
[log] > [level-controller]: switching to level 0 from 0 hls.light.min.js:1:129732
[log] > [level-controller]: Attempt loading level index 0 with URL-id 0 https://swrplanetschule-vh.akamaihd.net/i/schulfernsehen/nat…volle_leben_der_waldpflanzen,,_hd,.mp4.csmil/index_0_av.m3u8 hls.light.min.js:1:128517
[log] > [stream-controller]: IDLE->WAITING_LEVEL hls.light.min.js:1:161905
[log] > [stream-controller]: Level 0 loaded [1,178], cc [0, 0] duration:1770.112 hls.light.min.js:1:177745
[log] > [buffer-controller]: Updating Media Source duration to 1770.112 hls.light.min.js:1:205262
[log] > [stream-controller]: WAITING_LEVEL->IDLE hls.light.min.js:1:161905
[log] > [stream-controller]: Loading fragment 1 cc: 0 of [1-178] level: 0, target: 0 hls.light.min.js:1:152366
[log] > [stream-controller]: IDLE->FRAG_LOADING hls.light.min.js:1:161905
[log] > demuxing in webworker hls.light.min.js:1:162854
[log] > [transmuxer-interface, main]: Starting new transmux session for sn: 1 p: -1 level: 0 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 0 hls.light.min.js:1:164277
[log] > [stream-controller]: Loaded fragment 1 of level 0 hls.light.min.js:1:149259
[log] > c8f82486-9486-443e-8f23-bdee35f8d767:1:5020
[log] > [mp4-remuxer]: ISGenerated flag reset c8f82486-9486-443e-8f23-bdee35f8d767:1:41576
[log] > [mp4-remuxer]: initPTS & initDTS reset c8f82486-9486-443e-8f23-bdee35f8d767:1:41333
[log] > manifest codec:mp4a.40.2, ADTS type:2, samplingIndex:6 c8f82486-9486-443e-8f23-bdee35f8d767:1:10038
[log] > parsed codec:mp4a.40.5, rate:24000, channels:2 c8f82486-9486-443e-8f23-bdee35f8d767:1:10891
[log] > [stream-controller]: FRAG_LOADING->PARSING hls.light.min.js:1:161905
[log] > [transmuxer.ts]: Flushed fragment 1 of level 0 c8f82486-9486-443e-8f23-bdee35f8d767:1:56523
[log] > [stream-controller]: Init audio buffer, container:audio/mp4, codecs[selected/level/parsed]=[mp4a.40.2/mp4a.40.2/mp4a.40.5] hls.light.min.js:1:185671
[log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[avc1.64001f/avc1.64001f] hls.light.min.js:1:185850
[log] > [buffer-controller]: creating sourceBuffer(audio/mp4;codecs=mp4a.40.2) hls.light.min.js:1:206383
[log] > [buffer-controller]: creating sourceBuffer(video/mp4;codecs=avc1.64001f) hls.light.min.js:1:206383
[log] > [stream-controller]: PARSING->PARSED hls.light.min.js:1:161905
[log] > [stream-controller]: media seeking to 263.000, state: PARSED hls.light.min.js:1:147385
[log] > [stream-controller]: PARSED->IDLE hls.light.min.js:1:161905
[log] > [stream-controller]: Loading fragment 27 cc: 0 of [1-178] level: 0, target: 263 hls.light.min.js:1:152366
[log] > [stream-controller]: IDLE->FRAG_LOADING hls.light.min.js:1:161905
[warn] > [stream-controller]: Fragment 1 of level 0 finished buffering, but was aborted. state: FRAG_LOADING hls.light.min.js:1:180569
[log] > [transmuxer-interface, main]: Starting new transmux session for sn: 27 p: -1 level: 0 id: 1
        discontinuity: false
        trackSwitch: false
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 260.02666666666664 hls.light.min.js:1:164277
[log] > [stream-controller]: Loaded fragment 27 of level 0 hls.light.min.js:1:149259
[log] > [mp4-remuxer]: reset next timestamp c8f82486-9486-443e-8f23-bdee35f8d767:1:41446
[warn] > [mp4-remuxer]: Dropped 111 out of 250 video samples due to a missing keyframe c8f82486-9486-443e-8f23-bdee35f8d767:1:42245
[log] > [stream-controller]: FRAG_LOADING->PARSING hls.light.min.js:1:161905
[log] > [transmuxer.ts]: Flushed fragment 27 of level 0 c8f82486-9486-443e-8f23-bdee35f8d767:1:56523
[log] > [buffer-controller]: Removing [0,260.02666666666664] from the audio SourceBuffer hls.light.min.js:1:207841
[log] > [buffer-controller]: Removing [0,260.02666666666664] from the video SourceBuffer hls.light.min.js:1:207841
[log] > [stream-controller]: PARSING->IDLE hls.light.min.js:1:161905
[log] > [stream-controller]: Loading fragment 27 cc: 0 of [1-178] level: 0, target: 263 hls.light.min.js:1:152366
[log] > [stream-controller]: IDLE->FRAG_LOADING hls.light.min.js:1:161905
[log] > demuxing in webworker hls.light.min.js:1:162854
[log] > [transmuxer-interface, main]: Starting new transmux session for sn: 27 p: -1 level: 0 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 260.02666666666664 hls.light.min.js:1:164277
[log] > [stream-controller]: Loaded fragment 27 of level 0 hls.light.min.js:1:149259
[log] > a3cdc80f-8115-40f9-919f-b755c71e305a:1:5020
[log] > [mp4-remuxer]: ISGenerated flag reset a3cdc80f-8115-40f9-919f-b755c71e305a:1:41576
[log] > [mp4-remuxer]: initPTS & initDTS reset a3cdc80f-8115-40f9-919f-b755c71e305a:1:41333
[log] > manifest codec:mp4a.40.2, ADTS type:2, samplingIndex:6 a3cdc80f-8115-40f9-919f-b755c71e305a:1:10038
[log] > parsed codec:mp4a.40.5, rate:24000, channels:2 a3cdc80f-8115-40f9-919f-b755c71e305a:1:10891
[warn] > [mp4-remuxer]: Dropped 111 out of 250 video samples due to a missing keyframe a3cdc80f-8115-40f9-919f-b755c71e305a:1:42245
[log] > [stream-controller]: FRAG_LOADING->PARSING hls.light.min.js:1:161905
[log] > [transmuxer.ts]: Flushed fragment 27 of level 0 a3cdc80f-8115-40f9-919f-b755c71e305a:1:56523
[log] > [stream-controller]: Init audio buffer, container:audio/mp4, codecs[selected/level/parsed]=[mp4a.40.2/mp4a.40.2/mp4a.40.5] hls.light.min.js:1:185671
[log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[avc1.64001f/avc1.64001f] hls.light.min.js:1:185850
[log] > [stream-controller]: PARSING->IDLE hls.light.min.js:1:161905
[log] > [buffer-controller]: Removing [0,260.02666666666664] from the audio SourceBuffer hls.light.min.js:1:207841
[log] > [buffer-controller]: Removing [0,260.02666666666664] from the video SourceBuffer hls.light.min.js:1:207841
[log] > [stream-controller]: Loading fragment 27 cc: 0 of [1-178] level: 0, target: 263 hls.light.min.js:1:152366
[log] > [stream-controller]: IDLE->FRAG_LOADING hls.light.min.js:1:161905
[log] > demuxing in webworker hls.light.min.js:1:162854
[log] > [transmuxer-interface, main]: Starting new transmux session for sn: 27 p: -1 level: 0 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 260.02666666666664 hls.light.min.js:1:164277
[log] > [stream-controller]: Loaded fragment 27 of level 0 hls.light.min.js:1:149259
[log] > c0704c5a-abdd-446c-9cd4-9bd6ccf3e4e2:1:5020
[log] > [mp4-remuxer]: ISGenerated flag reset c0704c5a-abdd-446c-9cd4-9bd6ccf3e4e2:1:41576
[log] > [mp4-remuxer]: initPTS & initDTS reset c0704c5a-abdd-446c-9cd4-9bd6ccf3e4e2:1:41333
[log] > manifest codec:mp4a.40.2, ADTS type:2, samplingIndex:6 c0704c5a-abdd-446c-9cd4-9bd6ccf3e4e2:1:10038
[log] > parsed codec:mp4a.40.5, rate:24000, channels:2 c0704c5a-abdd-446c-9cd4-9bd6ccf3e4e2:1:10891
[warn] > [mp4-remuxer]: Dropped 111 out of 250 video samples due to a missing keyframe c0704c5a-abdd-446c-9cd4-9bd6ccf3e4e2:1:42245
[log] > [stream-controller]: FRAG_LOADING->PARSING hls.light.min.js:1:161905
[log] > [stream-controller]: Init audio buffer, container:audio/mp4, codecs[selected/level/parsed]=[mp4a.40.2/mp4a.40.2/mp4a.40.5] hls.light.min.js:1:185671
[log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[avc1.64001f/avc1.64001f] hls.light.min.js:1:185850
[log] > [transmuxer.ts]: Flushed fragment 27 of level 0 c0704c5a-abdd-446c-9cd4-9bd6ccf3e4e2:1:56523
[log] > [stream-controller]: PARSING->IDLE hls.light.min.js:1:161905
[log] > [buffer-controller]: Removing [0,260.02666666666664] from the audio SourceBuffer hls.light.min.js:1:207841
[log] > [buffer-controller]: Removing [0,260.02666666666664] from the video SourceBuffer hls.light.min.js:1:207841
[log] > [stream-controller]: Loading fragment 27 cc: 0 of [1-178] level: 0, target: 263 hls.light.min.js:1:152366
[log] > [stream-controller]: IDLE->FRAG_LOADING hls.light.min.js:1:161905
[log] > demuxing in webworker hls.light.min.js:1:162854
[log] > [transmuxer-interface, main]: Starting new transmux session for sn: 27 p: -1 level: 0 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 260.02666666666664 hls.light.min.js:1:164277
[log] > [stream-controller]: Loaded fragment 27 of level 0 hls.light.min.js:1:149259
[log] > d8100544-02e4-466d-a25e-dde2d8913429:1:5020
[log] > [mp4-remuxer]: ISGenerated flag reset d8100544-02e4-466d-a25e-dde2d8913429:1:41576
[log] > [mp4-remuxer]: initPTS & initDTS reset d8100544-02e4-466d-a25e-dde2d8913429:1:41333
[log] > manifest codec:mp4a.40.2, ADTS type:2, samplingIndex:6 d8100544-02e4-466d-a25e-dde2d8913429:1:10038
[log] > parsed codec:mp4a.40.5, rate:24000, channels:2 d8100544-02e4-466d-a25e-dde2d8913429:1:10891
[warn] > [mp4-remuxer]: Dropped 111 out of 250 video samples due to a missing keyframe d8100544-02e4-466d-a25e-dde2d8913429:1:42245
[log] > [stream-controller]: FRAG_LOADING->PARSING hls.light.min.js:1:161905
[log] > [transmuxer.ts]: Flushed fragment 27 of level 0 d8100544-02e4-466d-a25e-dde2d8913429:1:56523
[log] > [stream-controller]: Init audio buffer, container:audio/mp4, codecs[selected/level/parsed]=[mp4a.40.2/mp4a.40.2/mp4a.40.5] hls.light.min.js:1:185671
[log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[avc1.64001f/avc1.64001f] hls.light.min.js:1:185850
[log] > [stream-controller]: PARSING->IDLE hls.light.min.js:1:161905
[log] > [buffer-controller]: Removing [0,260.02666666666664] from the audio SourceBuffer hls.light.min.js:1:207841
[log] > [buffer-controller]: Removing [0,260.02666666666664] from the video SourceBuffer hls.light.min.js:1:207841
[log] > [stream-controller]: Loading fragment 27 cc: 0 of [1-178] level: 0, target: 263 hls.light.min.js:1:152366
[log] > [stream-controller]: IDLE->FRAG_LOADING hls.light.min.js:1:161905
[log] > demuxing in webworker hls.light.min.js:1:162854
[log] > [transmuxer-interface, main]: Starting new transmux session for sn: 27 p: -1 level: 0 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 260.02666666666664 hls.light.min.js:1:164277
[log] > [stream-controller]: Loaded fragment 27 of level 0 hls.light.min.js:1:149259
[log] > 69326c59-5a1e-4717-adb9-429879347928:1:5020
[log] > [mp4-remuxer]: ISGenerated flag reset 69326c59-5a1e-4717-adb9-429879347928:1:41576
[log] > [mp4-remuxer]: initPTS & initDTS reset 69326c59-5a1e-4717-adb9-429879347928:1:41333
[log] > manifest codec:mp4a.40.2, ADTS type:2, samplingIndex:6 69326c59-5a1e-4717-adb9-429879347928:1:10038
[log] > parsed codec:mp4a.40.5, rate:24000, channels:2 69326c59-5a1e-4717-adb9-429879347928:1:10891
[warn] > [mp4-remuxer]: Dropped 111 out of 250 video samples due to a missing keyframe 69326c59-5a1e-4717-adb9-429879347928:1:42245
[log] > [stream-controller]: FRAG_LOADING->PARSING hls.light.min.js:1:161905
[log] > [stream-controller]: Init audio buffer, container:audio/mp4, codecs[selected/level/parsed]=[mp4a.40.2/mp4a.40.2/mp4a.40.5] hls.light.min.js:1:185671
[log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[avc1.64001f/avc1.64001f] hls.light.min.js:1:185850
[log] > [transmuxer.ts]: Flushed fragment 27 of level 0 69326c59-5a1e-4717-adb9-429879347928:1:56523
[log] > [stream-controller]: PARSING->IDLE hls.light.min.js:1:161905
[log] > [buffer-controller]: Removing [0,260.02666666666664] from the audio SourceBuffer hls.light.min.js:1:207841
[log] > [buffer-controller]: Removing [0,260.02666666666664] from the video SourceBuffer hls.light.min.js:1:207841
[log] > [stream-controller]: Loading fragment 27 cc: 0 of [1-178] level: 0, target: 263 hls.light.min.js:1:152366
[log] > [stream-controller]: IDLE->FRAG_LOADING hls.light.min.js:1:161905
[log] > demuxing in webworker hls.light.min.js:1:162854
[log] > [transmuxer-interface, main]: Starting new transmux session for sn: 27 p: -1 level: 0 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 260.02666666666664 hls.light.min.js:1:164277
[log] > [stream-controller]: Loaded fragment 27 of level 0 hls.light.min.js:1:149259
[log] > 4686d391-d456-4e07-8a3c-d4df22e4f77d:1:5020
[log] > [mp4-remuxer]: ISGenerated flag reset 4686d391-d456-4e07-8a3c-d4df22e4f77d:1:41576
[log] > [mp4-remuxer]: initPTS & initDTS reset 4686d391-d456-4e07-8a3c-d4df22e4f77d:1:41333
[log] > manifest codec:mp4a.40.2, ADTS type:2, samplingIndex:6 4686d391-d456-4e07-8a3c-d4df22e4f77d:1:10038
[log] > parsed codec:mp4a.40.5, rate:24000, channels:2 4686d391-d456-4e07-8a3c-d4df22e4f77d:1:10891
[warn] > [mp4-remuxer]: Dropped 111 out of 250 video samples due to a missing keyframe 4686d391-d456-4e07-8a3c-d4df22e4f77d:1:42245
[log] > [stream-controller]: FRAG_LOADING->PARSING hls.light.min.js:1:161905
[log] > [stream-controller]: Init audio buffer, container:audio/mp4, codecs[selected/level/parsed]=[mp4a.40.2/mp4a.40.2/mp4a.40.5] hls.light.min.js:1:185671
[log] > [transmuxer.ts]: Flushed fragment 27 of level 0 4686d391-d456-4e07-8a3c-d4df22e4f77d:1:56523
[log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[avc1.64001f/avc1.64001f] hls.light.min.js:1:185850
[log] > [stream-controller]: PARSING->IDLE hls.light.min.js:1:161905
[log] > [buffer-controller]: Removing [0,260.02666666666664] from the audio SourceBuffer hls.light.min.js:1:207841
[log] > [buffer-controller]: Removing [0,260.02666666666664] from the video SourceBuffer hls.light.min.js:1:207841
[log] > [stream-controller]: Loading fragment 27 cc: 0 of [1-178] level: 0, target: 263 hls.light.min.js:1:152366
[log] > [stream-controller]: IDLE->FRAG_LOADING hls.light.min.js:1:161905
[log] > demuxing in webworker hls.light.min.js:1:162854
[log] > [transmuxer-interface, main]: Starting new transmux session for sn: 27 p: -1 level: 0 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 260.02666666666664 hls.light.min.js:1:164277
[log] > [stream-controller]: Loaded fragment 27 of level 0 hls.light.min.js:1:149259

Also see your own console output from the test page.

@cheweytoo cheweytoo changed the title seeking to unbuffered position immediately after play repeatedly loads same segment seeking to unbuffered position immediately after play loads same segment repeatedly Apr 22, 2021
@robwalch
Copy link
Collaborator

Hi @cheweytoo,

I am unable to connect to your site to view the test page and reproduce the issue:
https://dev.vergnumpft.de/avstuff/hls.js_tests/hls102_segment_loop.html

dev.vergnumpft.de unexpectedly closed the connection.

Please provide a sample stream that can be accessed to reproduce the issue on the demo page with steps that include where and when to seek.

@robwalch
Copy link
Collaborator

[warn] > [mp4-remuxer]: Dropped 111 out of 250 video samples due to a missing keyframe

This warning indicates that the segment's video track does not start with a keyframe, so only roughly the second half of the segment can be buffered. Usually, this results in the previous segment also being loaded, and then this segment being reloaded (so only one reload which unless you disable the worker so that the response can be cached in the main thread is unavoidable in all recent versions of hls.js). This feature is called backtracking, and I need a sample stream to see why it's not working in this case.

@cheweytoo
Copy link
Author

https://dev.vergnumpft.de/avstuff/hls.js_tests/hls102_segment_loop.html

dev.vergnumpft.de unexpectedly closed the connection.

Works for me, from several different endpoints. I did restart the webserver a short while ago though, you might have gotten unlucky.

Please provide a sample stream that can be accessed to reproduce the issue on the demo page with steps that include where and when to seek.

That's fully automated on the test page :-)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants