hls.js icon indicating copy to clipboard operation
hls.js copied to clipboard

Published 20 hours ago • verified publisher icon video-dev

some levels always call bufferStalledError

Open germanbv opened this issue 2 years ago • 6 comments

What version of Hls.js are you using?

v1.2.4

What browser (including version) are you using?

Chrome106.0.5249.119

What OS (including version) are you using?

Windows 10

Test stream

https://customer-9wye63yxidz55b0c.cloudflarestream.com/e6163a25a9f2cd0c1af318dac72a6093/manifest/video.m3u8

Configuration

autoStartLoad: true,
startPosition: -1,
startLevel: 2,
debug: true

Additional player setup steps

You can check a test implementation here: https://codepen.io/germanbv/pen/LYmRbdZ or by just using the test stream on https://hls-js-dev.netlify.app/demo notice you always get a bufferStalledError at the exact same point. This only happens with some specific videos...

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://hls-js.netlify.com/demo and not just on my page
  • [X] The issue occurs in the latest client (main branch) on https://hls-js-dev.netlify.com/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. go to https://hls-js-dev.netlify.app/demo
  2. paste the test stream https://customer-9wye63yxidz55b0c.cloudflarestream.com/e6163a25a9f2cd0c1af318dac72a6093/manifest/video.m3u8
  3. Buffer stalled error will be always triggered at the same point

Note that Levels should be 1,2 or 3

Expected behaviour

The cinematic plays without buffer stalled error.

What actually happened?

Buffer stalled error is always being triggered at the same point

Console output

DevTools failed to load source map: Could not load content for https://cdn.jsdelivr.net/npm/hls.min.js.map: HTTP error: status code 404, net::ERR_HTTP_RESPONSE_CODE_FAILURE
 [log] >
 [log] > stopLoad
 [log] > loadSource:https://customer-9wye63yxidz55b0c.cloudflarestream.com/e6163a25a9f2cd0c1af318dac72a6093/manifest/video.m3u8
 [log] > [stream-controller]: Trigger BUFFER_RESET
 [log] > attachMedia
 [log] > [buffer-controller]: Media source opened
 [log] > [subtitle-stream-controller]: STOPPED->IDLE
 [log] > [level-controller]: manifest loaded, 5 level(s) found, first bitrate: 1752485
 [log] > 2 bufferCodec event(s) expected
 [log] > startLoad(-1)
 [log] > [level-controller]: switching to level 2 from -1
 [log] > [audio-track-controller]: Updating audio tracks, 1 track(s) found in "group_audio" group-id
 [log] > [audio-track-controller]: Now switching to audio-track index 0
 [log] > [audio-stream-controller]: STOPPED->IDLE
 [log] > [audio-stream-controller]: IDLE->WAITING_TRACK
 [log] > [level-controller]: Attempt loading level index 2 with URL-id 0 https://customer-9wye63yxidz55b0c.cloudflarestream.com/e6163a25a9f2cd0c1af318dac72a6093/manifest/stream_t7ddbca7c231a95dff3b36e9a1d87ac53_r244474664.m3u8
 [log] > [stream-controller]: STOPPED->IDLE
 [log] > [audio-track-controller]: loading audio-track playlist for id: 0
 [log] > [audio-stream-controller]: WAITING_TRACK->STOPPED
 [log] > [audio-stream-controller]: STOPPED->WAITING_TRACK
 [log] > [subtitle-stream-controller]: IDLE->STOPPED
 [log] > [subtitle-stream-controller]: STOPPED->IDLE
 [log] > [stream-controller]: Level 2 loaded [0,3], cc [0, 0] duration:13
 [log] > [buffer-controller]: Updating Media Source duration to 13.000
 [log] > [stream-controller]: Loading fragment 0 cc: 0 of [0-3] level: 2, target: 0
 [log] > [stream-controller]: IDLE->FRAG_LOADING
 [log] > [audio-track-controller]: audioTrack 0 loaded [0-3]
 [log] > [audio-stream-controller]: Track 0 loaded [0,3],duration:12.995989999999999
 [log] > [audio-stream-controller]: WAITING_TRACK->IDLE
 [log] > [audio-stream-controller]: Loading fragment 0 cc: 0 of [0-3] track: 0, target: 0
 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
 [log] > demuxing in webworker
 [log] > [transmuxer-interface, main]: Starting new transmux session for sn: 0 p: -1 level: 2 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 0
        initSegmentChange: true
 [log] > [stream-controller]: Loaded fragment 0 of level 2
 [log] >
 [log] > [mp4-remuxer]: ISGenerated flag reset
 [log] > [mp4-remuxer]: initPTS & initDTS reset
 [log] > [stream-controller]: FRAG_LOADING->PARSING
 [log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[avc1.4d401e/avc1.4d401e]
 [log] > [audio-stream-controller]: InitPTS for cc: 0 found from main: 7500
 [log] > [transmuxer.ts]: Flushed fragment 0 of level 2
 [log] > [stream-controller]: PARSING->PARSED
 [log] > demuxing in webworker
 [log] > [transmuxer-interface, audio]: Starting new transmux session for sn: 0 p: -1 level: 0 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: false
        timeOffset: 0
        initSegmentChange: true
 [log] > [audio-stream-controller]: Loaded fragment 0 of level 0
63e246a5-3616-43dc-a6b7-ef1d578b7772:1 [log] >
 [log] > [mp4-remuxer]: ISGenerated flag reset
 [log] > [mp4-remuxer]: initPTS & initDTS reset
 [log] > manifest codec:mp4a.40.2, ADTS type:2, samplingIndex:3
 [log] > parsed codec:mp4a.40.5, rate:48000, channels:2
 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
 [log] > [audio-stream-controller]: Switching audio track : flushing all audio
 [log] > [audio-stream-controller]: Init audio buffer, container:audio/mp4, codecs[parsed]=[mp4a.40.5]
 [log] > [buffer-controller]: creating sourceBuffer(video/mp4;codecs=avc1.4d401e)
 [log] > [buffer-controller]: creating sourceBuffer(audio/mp4;codecs=mp4a.40.5)
 [log] > [stream-controller]: Alternate track found, use video.buffered to schedule main fragment loading
 [log] > [buffer-controller]: Removing [0,13] from the audio SourceBuffer
 [log] > [transmuxer.ts]: Flushed fragment 0 of level 0
 [log] > [audio-stream-controller]: PARSING->PARSED
 [log] > [audio-stream-controller]: Buffered audio sn: 0 of track 0 [0.000,3.925]
 [log] > [audio-stream-controller]: PARSED->IDLE
 [log] > [audio-stream-controller]: Loading fragment 1 cc: 0 of [0-3] track: 0, target: 3.925
 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
 [log] > [stream-controller]: Buffered main sn: 0 of level 2 [0.000,4.000]
 [log] > [stream-controller]: PARSED->IDLE
 [log] > [level-controller]: switching to level 4 from 2
 [log] > [level-controller]: Attempt loading level index 4 with URL-id 0 https://customer-9wye63yxidz55b0c.cloudflarestream.com/e6163a25a9f2cd0c1af318dac72a6093/manifest/stream_t7ddbca7c231a95dff3b36e9a1d87ac53_r244474684.m3u8
 [log] > [stream-controller]: IDLE->WAITING_LEVEL
 [log] > [stream-controller]: Level 4 loaded [0,3], cc [0, 0] duration:13
 [log] > [stream-controller]: WAITING_LEVEL->IDLE
 [log] > [stream-controller]: Loading fragment 1 cc: 0 of [0-3] level: 4, target: 4
 [log] > [stream-controller]: IDLE->FRAG_LOADING
 [log] > [audio-stream-controller]: Loaded fragment 1 of level 0
 [warn] > Audio frame @ 3.885s overlaps nextAudioPts by -41 ms.
 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
 [log] > [transmuxer.ts]: Flushed fragment 1 of level 0
 [log] > [audio-stream-controller]: PARSING->PARSED
 [log] > [audio-stream-controller]: Buffered audio sn: 1 of track 0 [0.000,7.895]
 [log] > [audio-stream-controller]: PARSED->IDLE
 [log] > [audio-stream-controller]: Loading fragment 2 cc: 0 of [0-3] track: 0, target: 7.895
 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
 [log] > [audio-stream-controller]: Loaded fragment 2 of level 0
 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
 [log] > [transmuxer.ts]: Flushed fragment 2 of level 0
 [log] > [audio-stream-controller]: PARSING->PARSED
 [log] > [audio-stream-controller]: Buffered audio sn: 2 of track 0 [0.000,11.906]
 [log] > [audio-stream-controller]: PARSED->IDLE
 [log] > [transmuxer-interface, main]: Starting new transmux session for sn: 1 p: -1 level: 4 id: 1
        discontinuity: false
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 4
        initSegmentChange: false
 [log] > [stream-controller]: Loaded fragment 1 of level 4
 [log] > [mp4-remuxer]: ISGenerated flag reset
 [log] > [mp4-remuxer]: reset next timestamp
 [log] > [mp4-remuxer]: ISGenerated flag reset
 [log] > [mp4-remuxer]: initPTS & initDTS reset
 [log] > [stream-controller]: FRAG_LOADING->PARSING
 [log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[avc1.4d4028/avc1.4d4028]
 [log] > [transmuxer.ts]: Flushed fragment 1 of level 4
 [log] > [stream-controller]: PARSING->PARSED
 [log] > [stream-controller]: Buffered main sn: 1 of level 4 [0.000,3.792][3.917,7.917]
 [log] > [stream-controller]: PARSED->IDLE
 [log] > [stream-controller]: SN 1 just loaded, load next one: 2
 [log] > [stream-controller]: Loading fragment 2 cc: 0 of [0-3] level: 4, target: 7.917
 [log] > [stream-controller]: IDLE->FRAG_LOADING
 [log] > [stream-controller]: Loaded fragment 2 of level 4
 [log] > [stream-controller]: FRAG_LOADING->PARSING
 [log] > [transmuxer.ts]: Flushed fragment 2 of level 4
 [log] > [stream-controller]: PARSING->PARSED
 [log] > [stream-controller]: Buffered main sn: 2 of level 4 [0.000,3.792][3.917,11.917]
 [log] > [stream-controller]: PARSED->IDLE

 **_//AT THIS POINT THE PLAYER ALWAYS TRIES TO SWITCH LEVELS CAUSING THE STALL_**
  
 [log] > [level-controller]: switching to level 2 from 4
 [log] > [stream-controller]: Loading fragment 1 cc: 0 of [0-3] level: 2, target: 4
 [log] > [stream-controller]: IDLE->FRAG_LOADING
 [log] > [audio-stream-controller]: Loading fragment 3 cc: 0 of [0-3] track: 0, target: 11.906
 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
 [log] > [transmuxer-interface, main]: Starting new transmux session for sn: 1 p: -1 level: 2 id: 1
        discontinuity: false
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 4
        initSegmentChange: false
 [log] > [stream-controller]: Loaded fragment 1 of level 2
 [log] > [mp4-remuxer]: ISGenerated flag reset
 [log] > [mp4-remuxer]: reset next timestamp
 [log] > [mp4-remuxer]: ISGenerated flag reset
 [log] > [mp4-remuxer]: initPTS & initDTS reset
 [log] > [stream-controller]: FRAG_LOADING->PARSING
 [log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[avc1.4d401e/avc1.4d401e]
 [log] > [transmuxer.ts]: Flushed fragment 1 of level 2
 [log] > [stream-controller]: PARSING->PARSED
 [log] > [stream-controller]: Buffered main sn: 1 of level 2 [0.000,3.792][3.917,11.917]
 [log] > [stream-controller]: PARSED->IDLE
 [log] > [level-controller]: switching to level 4 from 2
 [log] > [stream-controller]: Loading fragment 3 cc: 0 of [0-3] level: 4, target: 11.917
 [log] > [stream-controller]: IDLE->FRAG_LOADING
 [log] > [audio-stream-controller]: Loaded fragment 3 of level 0
 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
 [log] > [transmuxer.ts]: Flushed fragment 3 of level 0
 [log] > [audio-stream-controller]: PARSING->PARSED
 [log] > [audio-stream-controller]: Buffered audio sn: 3 of track 0 [0.000,12.951]
 [log] > [audio-stream-controller]: PARSED->IDLE
 [log] > [buffer-controller]: audio sourceBuffer now EOS
 [log] > [audio-stream-controller]: IDLE->ENDED
 [log] > [transmuxer-interface, main]: Starting new transmux session for sn: 3 p: -1 level: 4 id: 1
        discontinuity: false
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 11.916666666666666
        initSegmentChange: false
 [log] > [stream-controller]: Loaded fragment 3 of level 4
 [log] > [mp4-remuxer]: ISGenerated flag reset
 [log] > [mp4-remuxer]: reset next timestamp
 [log] > [mp4-remuxer]: ISGenerated flag reset
 [log] > [mp4-remuxer]: initPTS & initDTS reset
 [log] > [stream-controller]: FRAG_LOADING->PARSING
 [log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[avc1.4d4028/avc1.4d4028]
 [log] > [transmuxer.ts]: Flushed fragment 3 of level 4
 [log] > [stream-controller]: PARSING->PARSED
 [log] > [stream-controller]: Buffered main sn: 3 of level 4 [0.000,3.792][3.917,12.958]
 [log] > [stream-controller]: PARSED->IDLE
 [log] > [buffer-controller]: video sourceBuffer now EOS
 [log] > [stream-controller]: IDLE->ENDED
 [log] > [buffer-controller]: Media source ended
 [warn] > Playback stalling at @6.690604 due to low buffer ({"len":6.267728,"start":3.916666,"end":12.958332})
 [warn] > [playback-rate-controller]: Stall detected, adjusting target latency
 **mediaError: bufferStalledError**
​ [warn] > Trying to nudge playhead over buffer-hole
​ [warn] > Nudging 'currentTime' from 6.690604 to 6.790604
​ **mediaError: bufferNudgeOnStall**
​ [log] > [stream-controller]: media seeking to 6.791, state: ENDED
​ [log] > [stream-controller]: ENDED->IDLE
​ [log] > [audio-stream-controller]: media seeking to 6.791, state: ENDED
​ [log] > [audio-stream-controller]: ENDED->IDLE
​ [log] > [subtitle-stream-controller]: media seeking to 6.791, state: IDLE
​ [log] > [audio-stream-controller]: IDLE->ENDED
​ [log] > [stream-controller]: Media seeked to 6.791
​ [log] > [stream-controller]: IDLE->ENDED
​ [warn] > playback not stuck anymore @6.801492, after 69ms
​ [log] > [stream-controller]: media seeking to 0.000, state: ENDED
​ [log] > [stream-controller]: ENDED->IDLE
​ [log] > [audio-stream-controller]: media seeking to 0.000, state: ENDED
​ [log] > [audio-stream-controller]: ENDED->IDLE
​ [log] > [subtitle-stream-controller]: media seeking to 0.000, state: IDLE
​ [log] > [stream-controller]: Media seeked to 0.000

Chrome media internals output

No response

germanbv avatar Oct 19 '22 05:10 germanbv

Buffer stalled error will be always triggered at the same point

At which point?

The logs do not show a buffer stall error.

Please update steps and description to include an estimate of when the stall is expected with example logs.

robwalch avatar Oct 19 '22 19:10 robwalch

Thanks for answering, I've updated the console output with some data thrown by hls.on(Hls.Events.ERROR, there you can see a: mediaError: bufferStalledError and mediaError: bufferNudgeOnStall.

I've also attached a screenshot taken from https://hls-js-dev.netlify.app/demo where you can verify that there is always a bufferStalledError at the exact same point:

Screenshot 2022-10-19 184533

You can also check the following link for a real test: https://hls-js-dev.netlify.app/demo?src=https%3A%2F%2Fcustomer-9wye63yxidz55b0c.cloudflarestream.com%2Fe6163a25a9f2cd0c1af318dac72a6093%2Fmanifest%2Fvideo.m3u8&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOnRydWUsInN0b3BPblN0YWxsIjpmYWxzZSwiZHVtcGZNUDQiOmZhbHNlLCJsZXZlbENhcHBpbmciOi0xLCJsaW1pdE1ldHJpY3MiOi0xfQ==

germanbv avatar Oct 19 '22 21:10 germanbv

I see. Your media produces a buffer gap near the switch: [0.000,3.792][3.917,12.958].

Do the playlist times accurately reflect the media timestamps for each segment?

robwalch avatar Oct 20 '22 15:10 robwalch

I see. Your media produces a buffer gap near the switch: [0.000,3.792][3.917,12.958].

Do the playlist times accurately reflect the media timestamps for each segment?

how can I check that?

germanbv avatar Oct 20 '22 18:10 germanbv

Not a Contribution

These log lines suggest that the second append (sn: 1 of level 4 ) remove media from the buffer (4.000 -> 3.792). This could be because timecode, or GoPs (keyframes) are not aligned across levels. The second segment from level 3 is attempted again to fill the gap (sn: 1 of level 3 ) but it makes no difference.

[log] > [stream-controller]: Buffered main sn: 0 of level 3 [0.000,4.000]
[log] > [stream-controller]: Buffered main sn: 1 of level 4 [0.000,3.792][3.917,7.917]
[log] > [stream-controller]: Buffered main sn: 2 of level 4 [0.000,3.792][3.917,11.917]
[log] > [stream-controller]: Buffered main sn: 1 of level 3 [0.000,3.792][3.917,11.917]
[log] > [stream-controller]: Buffered main sn: 3 of level 4 [0.000,3.792][3.917,12.958]

The playlists all read #EXTINF:4.00000 so we expect that each segment has a duration of 4 seconds and that the starting timestamps of each segment are 4 seconds apart (and not 3.917 seconds apart).

The first segment in each every level, other than the lowest, start 0.083 (4.0-3.917) seconds further out that the lowest level, yet it still contains 4 seconds of media. The second segment in all levels do start at 4 seconds, so all levels other than the lowest have overlapping samples between the first and second segment and this results in gaps or destructive behavior when switching levels. If you switch down to 0 you will also see that the first segment can't be appended because it wants to start at -0.083.

This warning points out the issue with the TS segments:

hls.js:22798 [warn] > AVC: 83 ms (-7500dts) overlapping between fragments detected

You can see offset times on the "Timeline" using the "Quality-levels" to switch "Currently played level " on the demo page:

{
  "debug": true,
  "enableWorker": false,
  "lowLatencyMode": true,
  "backBufferLength": 90,
  "maxMaxBufferLength": 1,
  "startLevel": 0
}

image

In the image above we started at level 0 so the media was offset (initPTS) starting with the first timestamp in that level (not 0.083 later which happens if we start on any other level). Regardless of which level we start on however switching from the first to the second segment across any combination of levels except for the exact same level or starting on the lowest will produce these results because of the overlapping samples found in this stream. The only solution is to fix this by re-encoding this media (guessing this is an issue with mezzanine mp4s having audio priming offsets and edit lists even though the end result has audio split out into another track), or disabling auto level switching.

robwalch avatar Oct 21 '22 05:10 robwalch

I understand now.. so I'll try re-encoding to fix this issue! thanks a lot for your time and the detailed explanation!

germanbv avatar Oct 22 '22 03:10 germanbv