hls.js icon indicating copy to clipboard operation
hls.js copied to clipboard
verified publisher icon video-dev

Playback stalls in case of strong bandwidth fluctuations

Open JuliusThms opened this issue 1 year ago • 6 comments

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

  • [X] The issue observed is not already reported by searching on Github under https://github.com/video-dev/hls.js/issues
  • [X] The issue occurs in the stable client (latest release) on https://hlsjs.video-dev.org/demo and not just on my page
  • [X] The issue occurs in the latest client (main branch) on https://hlsjs-dev.video-dev.org/demo and not just on my page
  • [X] The stream has correct Access-Control-Allow-Origin headers (CORS)
  • [X] There are no network errors such as 404s in the browser console when trying to play the stream

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 avatar Sep 10 '24 20:09 JuliusThms

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.

robwalch avatar Sep 11 '24 02:09 robwalch

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

JuliusThms avatar Sep 12 '24 07:09 JuliusThms

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

JuliusThms avatar Sep 23 '24 08:09 JuliusThms

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.

robwalch avatar Sep 24 '24 14:09 robwalch

@robwalch Can you confirm now this is a bug?

JuliusThms avatar Sep 24 '24 21:09 JuliusThms

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 avatar Sep 25 '24 01:09 robwalch