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

startPosition is ignored / slides back to live sync point #3736

Closed
5 tasks done
eteubert opened this issue Apr 7, 2021 · 2 comments · Fixed by #3740
Closed
5 tasks done

startPosition is ignored / slides back to live sync point #3736

eteubert opened this issue Apr 7, 2021 · 2 comments · Fixed by #3740
Labels
Bug Regression A bug introduced in a recent release

Comments

@eteubert
Copy link

eteubert commented Apr 7, 2021

What version of Hls.js are you using?

1.0.0

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

macOS 11.2.3 / FF 88

Test stream:

https://hls-js.netlify.app/demo/?src=https%3A%2F%2Fmcdn.br.de%2Fbr%2Fhf%2Fb2sued%2Fmaster.m3u8&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOnRydWUsInN0b3BPblN0YWxsIjpmYWxzZSwiZHVtcGZNUDQiOmZhbHNlLCJsZXZlbENhcHBpbmciOi0xLCJsaW1pdE1ldHJpY3MiOi0xfQ==

https://mcdn.br.de/br/hf/b2sued/master.m3u8

Configuration:

{
  "debug": true,
  "backBufferLength": 90,
  "liveDurationInfinity": true,
  "autoStartLoad": true,
  "startPosition": 123
}

Checklist

  • 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. Please provide clear steps to reproduce your problem
  2. If the bug is intermittent, give a rough frequency

Expected behavior

Stream loads and starts at time provided to startPosition

Actual behavior

Stream starts playing at live sync point.

[warn] > [stream-controller]: Playback: 123.000 is located too far 
    from the end of live sliding playlist: 17937.000000000004, reset 
    currentTime to : 17928.014

Same behavior when I manually call hls.startLoad(123); on the MEDIA_ATTACHED event.

Seems related to #3603

Console output

11:50:43.682 [log] > hls.js:24667:22
11:50:43.687 [log] > attachMedia hls.js:16499:58
11:50:43.768 [log] > [buffer-controller]: Media source opened hls.js:4111:60
11:50:43.768 [log] > [subtitle-stream-controller]: STOPPED->IDLE hls.js:4035:14
11:50:43.768 hls Media Attached https://mcdn.br.de/br/hf/b2sued/master.m3u8 hls.ts:37:13
11:50:43.769 [log] > stopLoad hls.js:16565:58
11:50:43.769 [log] > [subtitle-stream-controller]: IDLE->STOPPED hls.js:4035:14
11:50:43.770 [log] > loadSource:https://mcdn.br.de/br/hf/b2sued/master.m3u8 hls.js:16533:58
11:50:43.771 [log] > [stream-controller]: Trigger BUFFER_RESET hls.js:9064:10
11:50:43.897 [log] > [level-controller]: manifest loaded, 2 level(s) found, first bitrate: 106240 hls.js:7637:16
11:50:43.897 [log] > 1 bufferCodec event(s) expected hls.js:4204:58
11:50:43.897 manifest loaded, found 2 quality level hls.ts:43:15
11:50:43.897 [log] > startLoad(123) hls.js:16554:58
11:50:43.898 [log] > [level-controller]: switching to level 0 from -1 hls.js:7995:12
11:50:43.899 [log] > [level-controller]: Attempt loading level index 0 with URL-id 0 https://mcdn.br.de/br/hf/b2sued/master-96000.m3u8 hls.js:7887:12
11:50:43.900 [log] > [stream-controller]: STOPPED->IDLE hls.js:4035:14
11:50:43.900 [log] > [subtitle-stream-controller]: STOPPED->IDLE hls.js:4035:14
11:50:44.392 [log] > [level-controller]: reload live playlist 0 in 2990 ms hls.js:2811:12
11:50:44.393 [log] > [stream-controller]: Level 0 loaded [6588375,6594374], cc [0, 0] duration:17939.999999999793 hls.js:9127:10
11:50:44.393 [log] > [stream-controller]: Live playlist - first load, unknown sliding hls.js:3822:12
11:50:44.393 [log] > [buffer-controller]: Media Source duration is set to Infinity hls.js:4687:60
11:50:44.395 [log] > [stream-controller]: Loading fragment 6594372 cc: 0 of [6588375-6594374] level: 0, target: 17931.03 hls.js:3392:10
11:50:44.395 [log] > [stream-controller]: IDLE->FRAG_LOADING hls.js:4035:14
11:50:44.447 [log] > demuxing in webworker hls.js:13910:60
11:50:44.455 [log] > [transmuxer-interface, main]: Starting new transmux session for sn: 6594372 p: -1 level: 0 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: false
        timeOffset: 17931.029999999788 hls.js:14007:60
11:50:44.456 [log] > [stream-controller]: Loaded fragment 6594372 of level 0 hls.js:3205:16
11:50:44.472 [log] > 8bddfc09-dddd-334a-8ac0-6f05f56edcbb:603:22
11:50:44.473 [log] > [mp4-remuxer]: ISGenerated flag reset 8bddfc09-dddd-334a-8ac0-6f05f56edcbb:2692:58
11:50:44.473 [log] > [mp4-remuxer]: initPTS & initDTS reset 8bddfc09-dddd-334a-8ac0-6f05f56edcbb:2681:58
11:50:44.474 [log] > manifest codec:mp4a.40.2, ADTS type:2, samplingIndex:3 8bddfc09-dddd-334a-8ac0-6f05f56edcbb:7552:56
11:50:44.474 [log] > parsed codec:mp4a.40.2, rate:48000, channels:2 8bddfc09-dddd-334a-8ac0-6f05f56edcbb:7714:58
11:50:44.479 [log] > [stream-controller]: FRAG_LOADING->PARSING hls.js:4035:14
11:50:44.479 [log] > [stream-controller]: Init audio buffer, container:audio/mp4, codecs[selected/level/parsed]=[mp4a.40.2/mp4a.40.2/mp4a.40.2] hls.js:9709:12
11:50:44.479 [log] > [buffer-controller]: creating sourceBuffer(audio/mp4;codecs=mp4a.40.2) hls.js:4766:62
11:50:44.479 [log] > [transmuxer.ts]: Flushed fragment 6594372 of level 0 8bddfc09-dddd-334a-8ac0-6f05f56edcbb:935:59
11:50:44.480 [log] > [audio-stream-controller]: InitPTS for cc: 0 found from main: 338930010 hls.js:1640:12
11:50:44.482 [log] > [stream-controller]: PARSING->PARSED hls.js:4035:14
11:50:44.484 [log] > [stream-controller]: Buffered main sn: 6594372 of level 0 [17931.030,17934.017] hls.js:3323:10
11:50:44.484 [log] > [stream-controller]: PARSED->IDLE hls.js:4035:14
11:50:44.484 [log] > [level-controller]: switching to level 1 from 0 hls.js:7995:12
11:50:44.484 [log] > [level-controller]: Attempt loading level index 1 with URL-id 0 https://mcdn.br.de/br/hf/b2sued/master-128000.m3u8 hls.js:7887:12
11:50:44.486 [log] > [stream-controller]: IDLE->WAITING_LEVEL hls.js:4035:14
11:50:44.486 [log] > [stream-controller]: seek to target start position 123 from current time 0 hls.js:9483:12
11:50:44.486 [log] > [stream-controller]: media seeking to 123.000, state: WAITING_LEVEL hls.js:3081:10
11:50:44.486 [log] > [stream-controller]: WAITING_LEVEL->IDLE hls.js:4035:14
11:50:44.486 [log] > [level-controller]: switching to level 1 from 1 hls.js:7995:12
11:50:44.487 [log] > [level-controller]: Attempt loading level index 1 with URL-id 0 https://mcdn.br.de/br/hf/b2sued/master-128000.m3u8 hls.js:7887:12
11:50:44.487 [log] > [stream-controller]: IDLE->WAITING_LEVEL hls.js:4035:14
11:50:44.487 [log] > [audio-stream-controller]: media seeking to 123.000, state: STOPPED hls.js:3081:10
11:50:44.649 [log] > [level-controller]: reload live playlist 1 in 2990 ms hls.js:2811:12
11:50:44.650 [log] > [stream-controller]: Level 1 loaded [6588376,6594375], cc [0, 0] duration:17939.999999999793 hls.js:9127:10
11:50:44.650 [log] > [stream-controller]: Live playlist - first load, unknown sliding hls.js:3822:12
11:50:44.650 [log] > Adjusting PTS using programDateTime delta 3000ms, sliding:3.000 https://brcdn.vo.llnwd.net/br/hf/b2sued/master-128000.m3u8 hls.js:23931:52
11:50:44.651 [log] > [stream-controller]: WAITING_LEVEL->IDLE hls.js:4035:14
11:50:44.652 [warn] > [stream-controller]: Playback: 123.000 is located too far from the end of live sliding playlist: 17943.000000000004, reset currentTime to : 17934.032 react_devtools_backend.js:2430:23
11:50:44.652 [log] > [stream-controller]: Loading fragment 6594373 cc: 0 of [6588376-6594375] level: 1, target: 17934.032 hls.js:3392:10
11:50:44.652 [log] > [stream-controller]: IDLE->FRAG_LOADING hls.js:4035:14
11:50:44.654 [log] > [buffer-controller]: Media Source duration is set to Infinity hls.js:4687:60
11:50:44.655 [log] > [stream-controller]: media seeking to 17934.032, state: FRAG_LOADING hls.js:3081:10
11:50:44.655 [log] > [audio-stream-controller]: media seeking to 17934.032, state: STOPPED hls.js:3081:10
11:50:44.687 [log] > [transmuxer-interface, main]: Starting new transmux session for sn: 6594373 p: -1 level: 1 id: 1
        discontinuity: false
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: false
        timeOffset: 17934.03 hls.js:14007:60
11:50:44.687 [log] > [stream-controller]: Loaded fragment 6594373 of level 1 hls.js:3205:16
11:50:44.687 [log] > [mp4-remuxer]: ISGenerated flag reset 8bddfc09-dddd-334a-8ac0-6f05f56edcbb:2692:58
11:50:44.687 [log] > [mp4-remuxer]: reset next timestamp 8bddfc09-dddd-334a-8ac0-6f05f56edcbb:2686:58
11:50:44.687 [log] > [mp4-remuxer]: ISGenerated flag reset 8bddfc09-dddd-334a-8ac0-6f05f56edcbb:2692:58
11:50:44.687 [log] > [mp4-remuxer]: initPTS & initDTS reset 8bddfc09-dddd-334a-8ac0-6f05f56edcbb:2681:58
11:50:44.687 [log] > manifest codec:mp4a.40.2, ADTS type:2, samplingIndex:3 8bddfc09-dddd-334a-8ac0-6f05f56edcbb:7552:56
11:50:44.688 [log] > parsed codec:mp4a.40.2, rate:48000, channels:2 8bddfc09-dddd-334a-8ac0-6f05f56edcbb:7714:58
11:50:44.689 [log] > [stream-controller]: FRAG_LOADING->PARSING hls.js:4035:14
11:50:44.689 [log] > [stream-controller]: Init audio buffer, container:audio/mp4, codecs[selected/level/parsed]=[mp4a.40.2/mp4a.40.2/mp4a.40.2] hls.js:9709:12
11:50:44.689 [log] > [transmuxer.ts]: Flushed fragment 6594373 of level 1 8bddfc09-dddd-334a-8ac0-6f05f56edcbb:935:59
11:50:44.690 [log] > [stream-controller]: PARSING->PARSED hls.js:4035:14
11:50:44.691 [log] > [stream-controller]: Buffered main sn: 6594373 of level 1 [17931.030,17937.003] hls.js:3323:10
11:50:44.691 [log] > [stream-controller]: PARSED->IDLE hls.js:4035:14
11:50:44.691 [log] > [stream-controller]: Loading fragment 6594374 cc: 0 of [6588376-6594375] level: 1, target: 17937.02 hls.js:3392:10
11:50:44.692 [log] > [stream-controller]: IDLE->FRAG_LOADING hls.js:4035:14
11:50:44.739 [log] > [stream-controller]: Media seeked to 17934.032 hls.js:9055:12
11:50:44.768 [log] > [stream-controller]: media seeking to 17934.032, state: FRAG_LOADING hls.js:3081:10
11:50:44.768 [log] > [audio-stream-controller]: media seeking to 17934.032, state: STOPPED hls.js:3081:10
11:50:44.792 [log] > [stream-controller]: Media seeked to 17934.032 hls.js:9055:12
11:50:44.818 [log] > [stream-controller]: Loaded fragment 6594374 of level 1 hls.js:3205:16
11:50:44.819 [log] > [stream-controller]: FRAG_LOADING->PARSING hls.js:4035:14

@robwalch
Copy link
Collaborator

robwalch commented Apr 7, 2021

Hi @eteubert,

If you get "Playback: ... is located too far from the end of live sliding playlist", then you need to configure liveMaxLatencyDuration or liveMaxLatencyDurationCount to adjust max latency. It's too bad this does not default to the live playlist (sliding window) length. I haven't come up with a way to do that without breaking current/expected behavior with these settings.

Ah looking in more detail liveMaxLatencyDurationCount defaults to Infinity so I'm guessing this is a regression related to adding the check for media.readyState < 4 or forcing the jump forward when the current position is underbuffered (which it would be at start) https://github.com/video-dev/hls.js/blob/v1.0.0/src/controller/base-stream-controller.ts#L992

Instead of looking at the readyState we should be looking at whether or not currentTime is outside the window AND we're not buffered (playback is allowed outside the window if buffered as this is necessary for streams with very small windows).

@robwalch robwalch added this to Top priorities in Release Planning and Backlog via automation Apr 7, 2021
robwalch pushed a commit that referenced this issue Apr 7, 2021
Do not sync with live edge when inside sliding window and liveMaxLatencyDuration
Fixes #3736
@robwalch
Copy link
Collaborator

robwalch commented Apr 7, 2021

Turns out it is two things:

  1. the regression I guessed above with readyState forcing synchronizeToLiveEdge to seek even though you are within the window and max latency.
  2. startPostion always being ignored for the first fragment loaded in a live stream (but not subsequent ones). This is problematic with PTS drift, discontinuities etc... It's always better to get init PTS from an earlier fragment in the same sequence if possible. PR is on the way.

robwalch pushed a commit that referenced this issue Apr 7, 2021
Do not sync with live edge when inside sliding window and liveMaxLatencyDuration
Fixes #3736
@robwalch robwalch added the Regression A bug introduced in a recent release label Apr 15, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug Regression A bug introduced in a recent release
Projects
Release Planning and Backlog
  
Top priorities
Development

Successfully merging a pull request may close this issue.

2 participants