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.

Sign up for GitHub

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

Jump to bottom

Playback stalls in case of strong bandwidth fluctuations #6689

Closed
5 tasks done
JuliusThms opened this issue Sep 10, 2024 · 6 comments · Fixed by #6763
Closed
5 tasks done

Playback stalls in case of strong bandwidth fluctuations #6689

JuliusThms opened this issue Sep 10, 2024 · 6 comments · Fixed by #6763
Labels
browser: Firefox Bug Revisit-at-later-release-cycle Will revisit during release cycle indicated by the Milestone
Milestone
1.6.0

Comments

@JuliusThms
Copy link
Contributor

JuliusThms commented Sep 10, 2024 •
edited
Loading

What version of Hls.js are you using?

1.5.14

What browser (including version) are you using?

Fireefox 130.0 (64-bit)

What OS (including version) are you using?

MacOS

Test stream

https://hlsjs.video-dev.org/demo/?src=https%3A%2F%2Fsdn-global-live-streaming-packager-cache.3qsdn.com%2F65181%2F65181_264_live.m3u8&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOnRydWUsInN0b3BPblN0YWxsIjp0cnVlLCJkdW1wZk1QNCI6ZmFsc2UsImxldmVsQ2FwcGluZyI6LTEsImxpbWl0TWV0cmljcyI6LTF9

Configuration

{
  "debug": true,
  "enableWorker": true,
  "lowLatencyMode": true,
  "backBufferLength": 90
}

Additional player setup steps

No response

Checklist

Steps to reproduce

  1. Start stream
  2. Throttel bandwidth to Regular 3G at the network tab in the developer console

Expected behaviour

Player should abort loading the current chunk, instead its waiting more than 25 secs to get the chunk loaded. I think the player should abort the loading in some seconds and starts then loading a chunk from a smaller resolution.

What actually happened?

Playback stalls

Console output

Layout was forced before the page was fully loaded. If stylesheets are not yet loaded this may cause a flash of unstyled content. markup.js:250:53
This page uses the non standard property “zoom”. Consider using calc() in the relevant property values, or using “transform” along with “transform-origin: 0 0”. demo
GET
https://hlsjs.video-dev.org/favicon.ico
[HTTP/3 404  68ms]

Using Hls.js config: 
Object { debug: true, enableWorker: true, lowLatencyMode: false, backBufferLength: 90 }
main.js:350:10
[log] > Debug logs enabled for "Hls instance" in hls.js version 1.5.14 logger.ts:74:21
[log] > stopLoad hls.ts:442:11
[log] > loadSource:https://sdn-global-live-streaming-packager-cache.3qsdn.com/65181/65181_264_live.m3u8 hls.ts:410:11
[log] > [stream-controller]: Trigger BUFFER_RESET stream-controller.ts:576:9
[log] > attachMedia hls.ts:380:11
[log] > [buffer-controller] created media source: MediaSource buffer-controller.ts:198:11
[log] > [buffer-controller] Media source opened buffer-controller.ts:994:9
[log] > [level-controller]: manifest loaded, 6 level(s) found, first bitrate: 5090800 level-controller.ts:337:13
[log] > setting initial bwe to 5000000 abr-controller.ts:58:13
[log] > [buffer-controller] 2 bufferCodec event(s) expected buffer-controller.ts:186:9
[log] > [abr] picked start tier {"codecSet":"avc1,mp4a","videoRanges":["SDR"],"preferHDR":false,"minFramerate":0,"minBitrate":250800} abr-controller.ts:701:13
[log] > startLoad(-1) hls.ts:431:11
[log] > [level-controller]: Switching to level 4 (720p SDR avc1,mp4a @3220800) from level -1 level-controller.ts:432:9
[log] > [audio-track-controller]: Updating audio tracks, 1 track(s) found in group(s): group_a0 audio-track-controller.ts:186:11
[log] > [audio-track-controller]: Switching to audio-track 0 "audio_0" lang:undefined group:group_a0 channels:undefined audio-track-controller.ts:332:9
[log] > [audio-stream-controller]: Reset loading state base-stream-controller.ts:1659:9
[log] > [audio-stream-controller]: STOPPED->IDLE base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: IDLE->WAITING_TRACK base-stream-controller.ts:1801:11
[log] > [level-controller]: Loading level index 4 with https://sdn-global-live-streaming-packager-cache.3qsdn.com/65181/66cd0db95fe1b_13365485_2408261120_2.m3u8 level-controller.ts:600:11
[log] > [stream-controller]: STOPPED->IDLE base-stream-controller.ts:1801:11
[log] > [audio-track-controller]: loading audio-track playlist 0 "audio_0" lang:undefined group:group_a0 audio-track-controller.ts:422:11
[log] > [audio-stream-controller]: WAITING_TRACK->STOPPED base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: STOPPED->WAITING_TRACK base-stream-controller.ts:1801:11
[log] > [subtitle-stream-controller]: STOPPED->IDLE base-stream-controller.ts:1801:11
[log] > [audio-track-controller]: Audio track 0 "audio_0" lang:undefined group:group_a0 loaded [353195-353200] audio-track-controller.ts:100:9
[log] > [audio-track-controller]: reload live playlist 0 in 3970 ms base-playlist-controller.ts:263:11
[log] > [level-controller]: reload live playlist 4 in 3966 ms base-playlist-controller.ts:263:11
[log] > [stream-controller]: Level 4 loaded [353195,353200][part-353200--1], cc [0, 0] duration:24 stream-controller.ts:639:9
[log] > [stream-controller]: Live playlist sliding: 0.00 start-sn: na->353195 prev-sn: na fragments: 6 base-stream-controller.ts:1418:11
[log] > [buffer-controller] Updating Media Source duration to 24.000 buffer-controller.ts:861:11
[log] > [stream-controller]: Loading fragment 353198 cc: 0 of [353195-353200] level: 4, target: 12 base-stream-controller.ts:758:9
[log] > [stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [audio-track-controller]: Audio track 0 "audio_0" lang:undefined group:group_a0 loaded [353195-353200] audio-track-controller.ts:100:9
[log] > [audio-track-controller]: live playlist 0 MISSED base-playlist-controller.ts:148:13
[log] > [audio-track-controller]: reload live playlist 0 in 3966 ms base-playlist-controller.ts:263:11
[log] > [audio-stream-controller]: Audio track 0 loaded [353195,353200][part-353200--1],duration:24 audio-stream-controller.ts:518:9
[log] > [audio-stream-controller]: WAITING_TRACK->IDLE base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Waiting for video PTS in continuity counter 0 of live stream before loading audio fragment 353198 of level 0 audio-stream-controller.ts:942:13
[log] > [audio-stream-controller]: IDLE->WAITING_INIT_PTS base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: WAITING_INIT_PTS->IDLE base-stream-controller.ts:1801:11
[log] > injecting Web Worker for "main" transmuxer-interface.ts:88:19
[log] > [transmuxer-interface, main]: Starting new transmux session for sn: 353198 p: -1 level: 4 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: false
        timeOffset: 12
        initSegmentChange: true transmuxer-interface.ts:230:13
[log] > [stream-controller]: Loaded fragment 353198 of level 4 base-stream-controller.ts:389:15
[log] > [audio-stream-controller]: Waiting for video PTS in continuity counter 0 of live stream before loading audio fragment 353198 of level 0 audio-stream-controller.ts:942:13
[log] > [audio-stream-controller]: IDLE->WAITING_INIT_PTS base-stream-controller.ts:1801:11
[log] > Debug logs enabled for "main" in hls.js version 1.5.14 fa956f00-7119-40bd-90dc-2c3de4c5a4bf:555:24
[log] > [mp4-remuxer]: ISGenerated flag reset transmuxer-interface.ts:394:36
[log] > [mp4-remuxer]: initPTS & initDTS reset transmuxer-interface.ts:394:36
[log] > [mp4-remuxer]: reset next timestamp transmuxer-interface.ts:394:36
[log] > [stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[avc1.4d401f/avc1.4d401f] stream-controller.ts:1314:11
[log] > [buffer-controller] 1 bufferCodec event(s) expected video buffer-controller.ts:393:11
[log] > [audio-stream-controller]: InitPTS for cc: 0 found from main: 6891245552 audio-stream-controller.ts:134:11
[log] > [audio-stream-controller]: WAITING_INIT_PTS->IDLE base-stream-controller.ts:1801:11
[log] > [transmuxer.ts]: Flushed fragment 353198 of level 4 transmuxer-interface.ts:394:36
[log] > [stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Loading fragment 353198 cc: 0 of [353195-353200] track: 0, target: 12.001 base-stream-controller.ts:758:9
[log] > [audio-stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > injecting Web Worker for "audio" transmuxer-interface.ts:88:19
[log] > [transmuxer-interface, audio]: Starting new transmux session for sn: 353198 p: -1 level: 0 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: false
        timeOffset: 12.000333
        initSegmentChange: true transmuxer-interface.ts:230:13
[log] > [audio-stream-controller]: Loaded fragment 353198 of level 0 base-stream-controller.ts:389:15
[log] > Debug logs enabled for "audio" in hls.js version 1.5.14 3f418d95-ba0a-471a-a8d5-a5274fba5f15:555:24
[log] > [mp4-remuxer]: ISGenerated flag reset transmuxer-interface.ts:394:36
[log] > [mp4-remuxer]: initPTS & initDTS reset transmuxer-interface.ts:394:36
[log] > [mp4-remuxer]: reset next timestamp transmuxer-interface.ts:394:36
[log] > manifest codec:mp4a.40.2, ADTS type:2, samplingIndex:3 transmuxer-interface.ts:394:36
[log] > parsed codec:mp4a.40.2, rate:48000, channels:2 transmuxer-interface.ts:394:36
[log] > [audio-stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Init audio buffer, container:audio/mp4, codecs[level/parsed]=[mp4a.40.2/mp4a.40.2] audio-stream-controller.ts:900:9
[log] > [buffer-controller] 0 bufferCodec event(s) expected audio buffer-controller.ts:393:11
[log] > [buffer-controller] creating sourceBuffer(video/mp4;codecs=avc1.4d401f) buffer-controller.ts:943:13
[log] > [buffer-controller] creating sourceBuffer(audio/mp4;codecs=mp4a.40.2) buffer-controller.ts:943:13
[log] > [stream-controller]: Alternate track found, use video.buffered to schedule main fragment loading stream-controller.ts:850:11
[log] > [transmuxer.ts]: Flushed fragment 353198 of level 0 transmuxer-interface.ts:394:36
[log] > [audio-stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [stream-controller]: Buffered main sn: 353198 of level 4 (frag:[12.000-16.000] > buffer:[12.000-16.000]) base-stream-controller.ts:570:9
[log] > [stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [stream-controller]: seek to target start position 12 from current time 0 stream-controller.ts:1025:11
[log] > [stream-controller]: Adapting to level 5 from level 4 stream-controller.ts:268:11
[log] > [level-controller]: Switching to level 5 (1080p SDR avc1,mp4a @5090800) from level 4 level-controller.ts:432:9
[log] > [level-controller]: Loading level index 5 with https://sdn-global-live-streaming-packager-cache.3qsdn.com/65181/66cd0db95fe1b_13365485_2408261120_1.m3u8 level-controller.ts:600:11
[log] > [stream-controller]: IDLE->WAITING_LEVEL base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Buffered audio sn: 353198 of track 0 (frag:[11.957-16.011] > buffer:[11.957-15.968]) base-stream-controller.ts:570:9
[log] > [audio-stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Loading fragment 353199 cc: 0 of [353195-353200] track: 0, target: 16.011 base-stream-controller.ts:758:9
[log] > [audio-stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [stream-controller]: media seeking to 12.000, state: WAITING_LEVEL base-stream-controller.ts:241:9
[log] > [audio-stream-controller]: media seeking to 12.000, state: FRAG_LOADING base-stream-controller.ts:241:9
[log] > [subtitle-stream-controller]: media seeking to 12.000, state: IDLE base-stream-controller.ts:241:9
[log] > [level-controller]: reload live playlist 5 in 3543 ms base-playlist-controller.ts:263:11
[log] > [stream-controller]: Level 5 loaded [353196,353201][part-353201--1], cc [0, 0] duration:24 stream-controller.ts:639:9
[log] > [stream-controller]: Live playlist sliding: 4.00 start-sn: na->353196 prev-sn: 353198 fragments: 6 base-stream-controller.ts:1418:11
[log] > [stream-controller]: WAITING_LEVEL->IDLE base-stream-controller.ts:1801:11
[log] > [stream-controller]: Loading fragment 353199 cc: 0 of [353196-353201] level: 5, target: 16 base-stream-controller.ts:758:9
[log] > [stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [buffer-controller] Updating Media Source duration to 28.000 buffer-controller.ts:861:11
Autoplay is only allowed when approved by the user, the site is activated by the user, or media is muted. demo
[log] > [stream-controller]: Media seeked to 12.000 stream-controller.ts:556:11
[log] > [audio-stream-controller]: Loaded fragment 353199 of level 0 base-stream-controller.ts:389:15
[log] > [audio-stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [transmuxer.ts]: Flushed fragment 353199 of level 0 transmuxer-interface.ts:394:36
[log] > [audio-stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Buffered audio sn: 353199 of track 0 (frag:[15.968-20.000] > buffer:[11.957-19.957]) base-stream-controller.ts:570:9
[log] > [audio-stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [transmuxer-interface, main]: Starting new transmux session for sn: 353199 p: -1 level: 5 id: 1
        discontinuity: false
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: false
        timeOffset: 16
        initSegmentChange: false transmuxer-interface.ts:230:13
[log] > [stream-controller]: Loaded fragment 353199 of level 5 base-stream-controller.ts:389:15
[log] > [mp4-remuxer]: ISGenerated flag reset transmuxer-interface.ts:394:36
[log] > [mp4-remuxer]: initPTS & initDTS reset transmuxer-interface.ts:394:36
[log] > [mp4-remuxer]: reset next timestamp transmuxer-interface.ts:394:36
[log] > [stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[avc1.4d4028/avc1.4d4028] stream-controller.ts:1314:11
[log] > [transmuxer.ts]: Flushed fragment 353199 of level 5 transmuxer-interface.ts:394:36
[log] > [stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [stream-controller]: Buffered main sn: 353199 of level 5 (frag:[16.000-20.000] > buffer:[12.000-20.000]) base-stream-controller.ts:570:9
[log] > [stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [stream-controller]: Loading fragment 353200 cc: 0 of [353196-353201] level: 5, target: 20 base-stream-controller.ts:758:9
[log] > [stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Loading fragment 353200 cc: 0 of [353195-353200] track: 0, target: 20 base-stream-controller.ts:758:9
[log] > [audio-stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Loaded fragment 353200 of level 0 base-stream-controller.ts:389:15
[log] > [audio-stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [transmuxer.ts]: Flushed fragment 353200 of level 0 transmuxer-interface.ts:394:36
[log] > [audio-stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Buffered audio sn: 353200 of track 0 (frag:[19.957-24.011] > buffer:[11.957-23.968]) base-stream-controller.ts:570:9
[log] > [audio-stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [stream-controller]: Loaded fragment 353200 of level 5 base-stream-controller.ts:389:15
[log] > [stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [transmuxer.ts]: Flushed fragment 353200 of level 5 transmuxer-interface.ts:394:36
[log] > [stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [stream-controller]: Buffered main sn: 353200 of level 5 (frag:[20.000-24.000] > buffer:[12.000-24.000]) base-stream-controller.ts:570:9
[log] > [stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [stream-controller]: Loading fragment 353201 cc: 0 of [353196-353201] level: 5, target: 24 base-stream-controller.ts:758:9
[log] > [stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [stream-controller]: Loaded fragment 353201 of level 5 base-stream-controller.ts:389:15
[log] > [stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [transmuxer.ts]: Flushed fragment 353201 of level 5 transmuxer-interface.ts:394:36
[log] > [stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [stream-controller]: Buffered main sn: 353201 of level 5 (frag:[24.000-28.000] > buffer:[12.000-28.000]) base-stream-controller.ts:570:9
[log] > [stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [level-controller]: Loading level index 5 with https://sdn-global-live-streaming-packager-cache.3qsdn.com/65181/66cd0db95fe1b_13365485_2408261120_1.m3u8 level-controller.ts:600:11
[log] > [audio-track-controller]: loading audio-track playlist 0 "audio_0" lang:undefined group:group_a0 audio-track-controller.ts:422:11
[log] > [audio-track-controller]: loading audio-track playlist 0 "audio_0" lang:undefined group:group_a0 audio-track-controller.ts:422:11
[log] > [level-controller]: live playlist 5 MISSED base-playlist-controller.ts:148:13
[log] > [level-controller]: reload live playlist 5 in 1964 ms base-playlist-controller.ts:263:11
[log] > [stream-controller]: Level 5 loaded [353196,353201][part-353201--1], cc [0, 0] duration:24 stream-controller.ts:639:9
[log] > [audio-track-controller]: Audio track 0 "audio_0" lang:undefined group:group_a0 loaded [353196-353201] audio-track-controller.ts:100:9
[log] > [audio-track-controller]: live playlist 0 REFRESHED 353201--1 base-playlist-controller.ts:148:13
[log] > [audio-track-controller]: reload live playlist 0 in 3919 ms base-playlist-controller.ts:263:11
[log] > [audio-stream-controller]: Audio track 0 loaded [353196,353201][part-353201--1],duration:23.999999999999993 audio-stream-controller.ts:518:9
[log] > [audio-stream-controller]: Loading fragment 353201 cc: 0 of [353196-353201] track: 0, target: 24.011 base-stream-controller.ts:758:9
[log] > [audio-stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Loaded fragment 353201 of level 0 base-stream-controller.ts:389:15
[log] > [audio-stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [transmuxer.ts]: Flushed fragment 353201 of level 0 transmuxer-interface.ts:394:36
[log] > [audio-stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Buffered audio sn: 353201 of track 0 (frag:[23.968-27.957] > buffer:[11.957-27.957]) base-stream-controller.ts:570:9
[log] > [audio-stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [level-controller]: Loading level index 5 with https://sdn-global-live-streaming-packager-cache.3qsdn.com/65181/66cd0db95fe1b_13365485_2408261120_1.m3u8 level-controller.ts:600:11
[log] > [level-controller]: live playlist 5 REFRESHED 353202--1 base-playlist-controller.ts:148:13
[log] > [level-controller]: reload live playlist 5 in 3942 ms base-playlist-controller.ts:263:11
[log] > [stream-controller]: Level 5 loaded [353197,353202][part-353202--1], cc [0, 0] duration:24 stream-controller.ts:639:9
[log] > [stream-controller]: Loading fragment 353202 cc: 0 of [353197-353202] level: 5, target: 28 base-stream-controller.ts:758:9
[log] > [stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [buffer-controller] Updating Media Source duration to 32.000 buffer-controller.ts:861:11
[log] > [stream-controller]: Loaded fragment 353202 of level 5 base-stream-controller.ts:389:15
[log] > [stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [transmuxer.ts]: Flushed fragment 353202 of level 5 transmuxer-interface.ts:394:36
[log] > [stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [stream-controller]: Buffered main sn: 353202 of level 5 (frag:[28.000-32.000] > buffer:[12.000-32.000]) base-stream-controller.ts:570:9
[log] > [stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [audio-track-controller]: loading audio-track playlist 0 "audio_0" lang:undefined group:group_a0 audio-track-controller.ts:422:11
[log] > [audio-track-controller]: Audio track 0 "audio_0" lang:undefined group:group_a0 loaded [353197-353202] audio-track-controller.ts:100:9
[log] > [audio-track-controller]: live playlist 0 REFRESHED 353202--1 base-playlist-controller.ts:148:13
[log] > [audio-track-controller]: reload live playlist 0 in 3964 ms base-playlist-controller.ts:263:11
[log] > [audio-stream-controller]: Audio track 0 loaded [353197,353202][part-353202--1],duration:23.957000333333337 audio-stream-controller.ts:518:9
[log] > [audio-stream-controller]: Loading fragment 353202 cc: 0 of [353197-353202] track: 0, target: 27.957 base-stream-controller.ts:758:9
[log] > [audio-stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Loaded fragment 353202 of level 0 base-stream-controller.ts:389:15
[log] > [audio-stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [transmuxer.ts]: Flushed fragment 353202 of level 0 transmuxer-interface.ts:394:36
[log] > [audio-stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Buffered audio sn: 353202 of track 0 (frag:[27.957-31.968] > buffer:[11.957-31.968]) base-stream-controller.ts:570:9
[log] > [audio-stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [level-controller]: Loading level index 5 with https://sdn-global-live-streaming-packager-cache.3qsdn.com/65181/66cd0db95fe1b_13365485_2408261120_1.m3u8 level-controller.ts:600:11
[log] > [level-controller]: live playlist 5 REFRESHED 353203--1 base-playlist-controller.ts:148:13
[log] > [level-controller]: reload live playlist 5 in 3966 ms base-playlist-controller.ts:263:11
[log] > [stream-controller]: Level 5 loaded [353198,353203][part-353203--1], cc [0, 0] duration:24 stream-controller.ts:639:9
[log] > [stream-controller]: Loading fragment 353203 cc: 0 of [353198-353203] level: 5, target: 32 base-stream-controller.ts:758:9
[log] > [stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [buffer-controller] Updating Media Source duration to 36.000 buffer-controller.ts:861:11
[log] > [stream-controller]: Loaded fragment 353203 of level 5 base-stream-controller.ts:389:15
[log] > [stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [transmuxer.ts]: Flushed fragment 353203 of level 5 transmuxer-interface.ts:394:36
[log] > [stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [stream-controller]: Buffered main sn: 353203 of level 5 (frag:[32.000-36.000] > buffer:[12.000-36.000]) base-stream-controller.ts:570:9
[log] > [stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [audio-track-controller]: loading audio-track playlist 0 "audio_0" lang:undefined group:group_a0 audio-track-controller.ts:422:11
[log] > [audio-track-controller]: Audio track 0 "audio_0" lang:undefined group:group_a0 loaded [353198-353203] audio-track-controller.ts:100:9
[log] > [audio-track-controller]: live playlist 0 REFRESHED 353203--1 base-playlist-controller.ts:148:13
[log] > [audio-track-controller]: reload live playlist 0 in 3945 ms base-playlist-controller.ts:263:11
[log] > [audio-stream-controller]: Audio track 0 loaded [353198,353203][part-353203--1],duration:23.999999666666668 audio-stream-controller.ts:518:9
[log] > [audio-stream-controller]: Loading fragment 353203 cc: 0 of [353198-353203] track: 0, target: 31.968 base-stream-controller.ts:758:9
[log] > [audio-stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Loaded fragment 353203 of level 0 base-stream-controller.ts:389:15
[log] > [audio-stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [transmuxer.ts]: Flushed fragment 353203 of level 0 transmuxer-interface.ts:394:36
[log] > [audio-stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Buffered audio sn: 353203 of track 0 (frag:[31.968-35.957] > buffer:[11.957-35.957]) base-stream-controller.ts:570:9
[log] > [audio-stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [level-controller]: Loading level index 5 with https://sdn-global-live-streaming-packager-cache.3qsdn.com/65181/66cd0db95fe1b_13365485_2408261120_1.m3u8 level-controller.ts:600:11
[log] > [level-controller]: live playlist 5 REFRESHED 353204--1 base-playlist-controller.ts:148:13
[log] > [level-controller]: reload live playlist 5 in 3965 ms base-playlist-controller.ts:263:11
[log] > [stream-controller]: Level 5 loaded [353199,353204][part-353204--1], cc [0, 0] duration:24 stream-controller.ts:639:9
[log] > [stream-controller]: Loading fragment 353204 cc: 0 of [353199-353204] level: 5, target: 36 base-stream-controller.ts:758:9
[log] > [stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [buffer-controller] Updating Media Source duration to 40.000 buffer-controller.ts:861:11
[log] > [stream-controller]: Loaded fragment 353204 of level 5 base-stream-controller.ts:389:15
[log] > [stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [transmuxer.ts]: Flushed fragment 353204 of level 5 transmuxer-interface.ts:394:36
[log] > [stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [stream-controller]: Buffered main sn: 353204 of level 5 (frag:[36.000-40.000] > buffer:[12.000-40.000]) base-stream-controller.ts:570:9
[log] > [stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [audio-track-controller]: loading audio-track playlist 0 "audio_0" lang:undefined group:group_a0 audio-track-controller.ts:422:11
[log] > [audio-track-controller]: Audio track 0 "audio_0" lang:undefined group:group_a0 loaded [353199-353204] audio-track-controller.ts:100:9
[log] > [audio-track-controller]: live playlist 0 REFRESHED 353204--1 base-playlist-controller.ts:148:13
[log] > [audio-track-controller]: reload live playlist 0 in 3964 ms base-playlist-controller.ts:263:11
[log] > [audio-stream-controller]: Audio track 0 loaded [353199,353204][part-353204--1],duration:24.00000033333333 audio-stream-controller.ts:518:9
[log] > [audio-stream-controller]: Loading fragment 353204 cc: 0 of [353199-353204] track: 0, target: 35.957 base-stream-controller.ts:758:9
[log] > [audio-stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Loaded fragment 353204 of level 0 base-stream-controller.ts:389:15
[log] > [audio-stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [transmuxer.ts]: Flushed fragment 353204 of level 0 transmuxer-interface.ts:394:36
[log] > [audio-stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Buffered audio sn: 353204 of track 0 (frag:[35.957-39.968] > buffer:[11.957-39.968]) base-stream-controller.ts:570:9
[log] > [audio-stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [level-controller]: Loading level index 5 with https://sdn-global-live-streaming-packager-cache.3qsdn.com/65181/66cd0db95fe1b_13365485_2408261120_1.m3u8 level-controller.ts:600:11
[log] > [level-controller]: live playlist 5 REFRESHED 353205--1 base-playlist-controller.ts:148:13
[log] > [level-controller]: reload live playlist 5 in 3965 ms base-playlist-controller.ts:263:11
[log] > [stream-controller]: Level 5 loaded [353200,353205][part-353205--1], cc [0, 0] duration:24 stream-controller.ts:639:9
[log] > [stream-controller]: Loading fragment 353205 cc: 0 of [353200-353205] level: 5, target: 40 base-stream-controller.ts:758:9
[log] > [stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [buffer-controller] Updating Media Source duration to 44.000 buffer-controller.ts:861:11
[log] > [stream-controller]: Loaded fragment 353205 of level 5 base-stream-controller.ts:389:15
[log] > [stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [transmuxer.ts]: Flushed fragment 353205 of level 5 transmuxer-interface.ts:394:36
[log] > [stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [stream-controller]: Buffered main sn: 353205 of level 5 (frag:[40.000-44.000] > buffer:[12.000-44.000]) base-stream-controller.ts:570:9
[log] > [stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [audio-track-controller]: loading audio-track playlist 0 "audio_0" lang:undefined group:group_a0 audio-track-controller.ts:422:11
[log] > [audio-track-controller]: Audio track 0 "audio_0" lang:undefined group:group_a0 loaded [353200-353205] audio-track-controller.ts:100:9
[log] > [audio-track-controller]: live playlist 0 REFRESHED 353205--1 base-playlist-controller.ts:148:13
[log] > [audio-track-controller]: reload live playlist 0 in 3962 ms base-playlist-controller.ts:263:11
[log] > [audio-stream-controller]: Audio track 0 loaded [353200,353205][part-353205--1],duration:23.99999966666667 audio-stream-controller.ts:518:9
[log] > [audio-stream-controller]: Loading fragment 353205 cc: 0 of [353200-353205] track: 0, target: 39.968 base-stream-controller.ts:758:9
[log] > [audio-stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Loaded fragment 353205 of level 0 base-stream-controller.ts:389:15
[log] > [audio-stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [transmuxer.ts]: Flushed fragment 353205 of level 0 transmuxer-interface.ts:394:36
[log] > [audio-stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Buffered audio sn: 353205 of track 0 (frag:[39.968-43.957] > buffer:[11.957-43.957]) base-stream-controller.ts:570:9
[log] > [audio-stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [level-controller]: Loading level index 5 with https://sdn-global-live-streaming-packager-cache.3qsdn.com/65181/66cd0db95fe1b_13365485_2408261120_1.m3u8 level-controller.ts:600:11
[log] > [level-controller]: live playlist 5 REFRESHED 353206--1 base-playlist-controller.ts:148:13
[log] > [level-controller]: reload live playlist 5 in 3963 ms base-playlist-controller.ts:263:11
[log] > [stream-controller]: Level 5 loaded [353201,353206][part-353206--1], cc [0, 0] duration:24 stream-controller.ts:639:9
[log] > [stream-controller]: Loading fragment 353206 cc: 0 of [353201-353206] level: 5, target: 44 base-stream-controller.ts:758:9
[log] > [stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [buffer-controller] Updating Media Source duration to 48.000 buffer-controller.ts:861:11
[log] > [stream-controller]: Loaded fragment 353206 of level 5 base-stream-controller.ts:389:15
[log] > [stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [transmuxer.ts]: Flushed fragment 353206 of level 5 transmuxer-interface.ts:394:36
[log] > [stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [stream-controller]: Buffered main sn: 353206 of level 5 (frag:[44.000-48.000] > buffer:[12.000-48.000]) base-stream-controller.ts:570:9
[log] > [stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [audio-track-controller]: loading audio-track playlist 0 "audio_0" lang:undefined group:group_a0 audio-track-controller.ts:422:11
[log] > [audio-track-controller]: Audio track 0 "audio_0" lang:undefined group:group_a0 loaded [353201-353206] audio-track-controller.ts:100:9
[log] > [audio-track-controller]: live playlist 0 REFRESHED 353206--1 base-playlist-controller.ts:148:13
[log] > [audio-track-controller]: reload live playlist 0 in 3962 ms base-playlist-controller.ts:263:11
[log] > [audio-stream-controller]: Audio track 0 loaded [353201,353206][part-353206--1],duration:24.00000033333333 audio-stream-controller.ts:518:9
[log] > [audio-stream-controller]: Loading fragment 353206 cc: 0 of [353201-353206] track: 0, target: 43.957 base-stream-controller.ts:758:9
[log] > [audio-stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Loaded fragment 353206 of level 0 base-stream-controller.ts:389:15
[log] > [audio-stream-controller]: FRAG_LOADING->PARSING base-stream-controller.ts:1801:11
[log] > [transmuxer.ts]: Flushed fragment 353206 of level 0 transmuxer-interface.ts:394:36
[log] > [audio-stream-controller]: PARSING->PARSED base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: Buffered audio sn: 353206 of track 0 (frag:[43.957-47.968] > buffer:[11.957-47.968]) base-stream-controller.ts:570:9
[log] > [audio-stream-controller]: PARSED->IDLE base-stream-controller.ts:1801:11
[log] > [level-controller]: Loading level index 5 with https://sdn-global-live-streaming-packager-cache.3qsdn.com/65181/66cd0db95fe1b_13365485_2408261120_1.m3u8 level-controller.ts:600:11
[log] > [level-controller]: live playlist 5 REFRESHED 353207--1 base-playlist-controller.ts:148:13
[log] > [level-controller]: reload live playlist 5 in 3963 ms base-playlist-controller.ts:263:11
[log] > [stream-controller]: Level 5 loaded [353202,353207][part-353207--1], cc [0, 0] duration:24 stream-controller.ts:639:9
[log] > [stream-controller]: Loading fragment 353207 cc: 0 of [353202-353207] level: 5, target: 48 base-stream-controller.ts:758:9
[log] > [stream-controller]: IDLE->FRAG_LOADING base-stream-controller.ts:1801:11
[log] > [buffer-controller] Updating Media Source duration to 52.000 buffer-controller.ts:861:11
[log] > [audio-track-controller]: loading audio-track playlist 0 "audio_0" lang:undefined group:group_a0 audio-track-controller.ts:422:11
[log] > [level-controller]: Switching to level 3 (480p SDR avc1,mp4a @1900800) from level 5 level-controller.ts:432:9
[log] > [level-controller]: Loading level index 3 with https://sdn-global-live-streaming-packager-cache.3qsdn.com/65181/66cd0db95fe1b_13365485_2408261120_3.m3u8 level-controller.ts:600:11
[log] > setting initial bwe to 1900800 abr-controller.ts:58:13
[warn] > [abr] Fragment 353207 of level 5 is loading too slowly;
      Time to underbuffer: 11.336 s
      Estimated load time for current fragment: 26.453 s
      Estimated load time for down switch fragment: 10.164 s
      TTFB estimate: 31 ms
      Current BW estimate: 98603861 bps
      New BW estimate: 1900800 bps
      Switching to level 3 @ 1900800 bps abr-controller.ts:358:11
[log] > [stream-controller]: FRAG_LOADING->IDLE base-stream-controller.ts:1801:11
[log] > [level-controller]: Switching to level 3 (480p SDR avc1,mp4a @1900800) from level 3 level-controller.ts:432:9
[log] > [level-controller]: Loading level index 3 with https://sdn-global-live-streaming-packager-cache.3qsdn.com/65181/66cd0db95fe1b_13365485_2408261120_3.m3u8 level-controller.ts:600:11
[log] > [stream-controller]: IDLE->WAITING_LEVEL base-stream-controller.ts:1801:11
[warn] > Playback stalling at @47.967229 due to low buffer ({"len":0.0007710000000002992,"start":12,"end":47.968}) gap-controller.ts:233:13
[warn] > [playback-rate-controller]: Stall detected, adjusting target latency latency-controller.ts:188:13
Error event: 
Object { type: "mediaError", details: "bufferStalledError", fatal: false, error: Error, buffer: 0.0007710000000002992, errorAction: {…} }
main.js:745:12
[log] > stopLoad hls.ts:442:11
[log] > [stream-controller]: WAITING_LEVEL->STOPPED base-stream-controller.ts:1801:11
[log] > [audio-stream-controller]: IDLE->STOPPED base-stream-controller.ts:1801:11
[log] > [subtitle-stream-controller]: IDLE->STOPPED base-stream-controller.ts:1801:11

Chrome media internals output

No response
@JuliusThms JuliusThms added Bug Needs Triage If there is a suspected stream issue, apply this label to triage if it is something we should fix. labels Sep 10, 2024
@robwalch
Copy link
Collaborator

Please provide more detailed reproduction steps and console logs. We need to know when the network throttled and what was retrieved or inflight prior to that.

From the looks of the logs there was a level and audio track change prior to the stall but neither completed loading so it would be impossible to load media segments from either variant or audio media option.

@JuliusThms
Copy link
Contributor Author

@robwalch : Just dropped the Log in the Description. You can reproduce by Setting the network throtteling to Regular 3G

@robwalch robwalch removed Needs Triage If there is a suspected stream issue, apply this label to triage if it is something we should fix. Incomplete labels Sep 12, 2024
@JuliusThms
Copy link
Contributor Author

@robwalch : Did you got a change to have a look?

@robwalch
Copy link
Collaborator

It's trying to switch down. The playlist never loads. It stalls.

Regardless of which level it tries to switch to, if the playlist never loads, it will stall.

@JuliusThms
Copy link
Contributor Author

@robwalch Can you confirm now this is a bug?

@robwalch
Copy link
Collaborator

robwalch commented Sep 25, 2024 •
edited
Loading

Player should abort loading the current chunk, instead its waiting more than 25 secs to get the chunk loaded. I think the player should abort the loading in some seconds and starts then loading a chunk from a smaller resolution.

Aborting the current chunk makes little difference. It is arguably worse. You can see the difference by running the same test with v1.4.13 which aborts the inflight frag on emergency switch down:

https://16f1932e.hls-js-dev.pages.dev/demo/?src=https%3A%2F%2Fsdn-global-live-streaming-packager-cache.3qsdn.com%2F65181%2F65181_264_live.m3u8&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOnRydWUsInN0b3BPblN0YWxsIjpmYWxzZSwiZHVtcGZNUDQiOmZhbHNlLCJsZXZlbENhcHBpbmciOi0xLCJsaW1pdE1ldHJpY3MiOi0xfQ==

Make sure to disable "Stop on first stall" when running these tests if you want to compare recovery.

Add a callback to FRAG_LOAD_EMERGENCY_ABORTED that adapts to the lowest variant and aborts the inflight request if that is how you would like this event to be handled.

Can you confirm now this is a bug?

It's working as designed, but we can use this as a test case to enhance emergency switch down behavior when playlist loading is delayed by unknown factors like head-of-line blocking (which it seams Firefox's network throttling "simulates" 🐛).

@robwalch robwalch added Revisit-at-later-release-cycle Will revisit during release cycle indicated by the Milestone browser: Firefox labels Sep 27, 2024
robwalch added a commit that referenced this issue Oct 2, 2024
@robwalch
Check-in on abandon rules check and switch to lowest when stuck on in…
4a800a2 
…-flight frag

Resolves #6689
robwalch added a commit that referenced this issue Oct 9, 2024
@robwalch
Check-in on abandon rules check and switch to lowest when stuck on in…
e629ade 
…-flight frag

Resolves #6689
@robwalch robwalch mentioned this issue Oct 10, 2024
Merged
3 tasks
robwalch added a commit that referenced this issue Oct 10, 2024
@robwalch
Check-in on abandon rules check and switch to lowest when stuck on in…
23d096e 
…-flight frag

Resolves #6689
EdenwareApps pushed a commit to EdenwareApps/hls.js that referenced this issue Oct 14, 2024
@robwalch @EdenwareApps
Check-in on abandon rules check and switch to lowest when stuck on in…
9e2eff0 
…-flight frag Resolves video-dev#6689
@robwalch robwalch added this to the 1.6.0 milestone Oct 23, 2024
@robwalch robwalch mentioned this issue Dec 18, 2024
Closed
5 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
browser: Firefox Bug Revisit-at-later-release-cycle Will revisit during release cycle indicated by the Milestone
Projects
None yet
Milestone
1.6.0
2 participants
@robwalch @JuliusThms