Playback stalling due to low buffer - only in Chrome

mrjamesriley commented 1 year ago

What version of Hls.js are you using?

1.4.2

What browser (including version) are you using?

Chrome 113.0.5672.92 (Official Build) (arm64)

What OS (including version) are you using?

Mac OSX Ventura 13.2

Test stream

https://4cda8c72.hls-js-dev.pages.dev/demo/?src=https%3A%2F%2Fcustomer-xd80itw4spq1dhtd.cloudflarestream.com%2F256b50e4b1fe5e1cb1d010a9668bb2ec%2Fmanifest%2Fvideo.m3u8&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOmZhbHNlLCJzdG9wT25TdGFsbCI6dHJ1ZSwiZHVtcGZNUDQiOmZhbHNlLCJsZXZlbENhcHBpbmciOi0xLCJsaW1pdE1ldHJpY3MiOi0xfQ==

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

Visit test page and click to play video
Observe that the video stalls at the 3 second mark

Expected behaviour

The video does not stall and the plays all the way through without stopping.

What actually happened?

After 3 seconds in the video playback stalls. Audio continues to play for a few more seconds, then also stops. A second or two later, the video is able to 'recover' and continues playing.

Console output

Using Hls.js config: {debug: true, enableWorker: true, lowLatencyMode: true, backBufferLength: 90}
logger.ts:74 [log] > Debug logs enabled for "Hls instance" in hls.js version 1.4.2
hls.ts:410 [log] > stopLoad
hls.ts:379 [log] > loadSource:https://customer-xd80itw4spq1dhtd.cloudflarestream.com/256b50e4b1fe5e1cb1d010a9668bb2ec/manifest/video.m3u8
stream-controller.ts:566 [log] > [stream-controller]: Trigger BUFFER_RESET
hls.ts:351 [log] > attachMedia
buffer-controller.ts:800 [log] > [buffer-controller]: Media source opened
base-stream-controller.ts:1745 [log] > [subtitle-stream-controller]: STOPPED->IDLE
beacon.min.js:1 XHR finished loading: POST "https://cloudflareinsights.com/cdn-cgi/rum".
t.sendObjectBeacon @ beacon.min.js:1
a @ beacon.min.js:1
(anonymous) @ beacon.min.js:1
P @ beacon.min.js:1
B @ beacon.min.js:1
setTimeout (async)
(anonymous) @ beacon.min.js:1
load (async)
(anonymous) @ beacon.min.js:1
(anonymous) @ beacon.min.js:1
168 @ beacon.min.js:1
n @ beacon.min.js:1
(anonymous) @ beacon.min.js:1
(anonymous) @ beacon.min.js:1
level-controller.ts:269 [log] > [level-controller]: manifest loaded, 5 level(s) found, first bitrate: 1804880
buffer-controller.ts:148 [log] > 2 bufferCodec event(s) expected
hls.ts:400 [log] > startLoad(-1)
level-controller.ts:351 [log] > [level-controller]: Switching to level 4 from level -1
audio-track-controller.ts:138 [log] > [audio-track-controller]: Updating audio tracks, 1 track(s) found in group:group_audio
audio-track-controller.ts:195 [log] > [audio-track-controller]: Switching to audio-track 0 "original" lang:en-dc2ae518 group:group_audio
base-stream-controller.ts:1610 [log] > [audio-stream-controller]: Reset loading state
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: STOPPED->IDLE
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: IDLE->WAITING_TRACK
level-controller.ts:520 [log] > [level-controller]: Loading level index 4 with URI 1/1 https://customer-xd80itw4spq1dhtd.cloudflarestream.com/256b50e4b1fe5e1cb1d010a9668bb2ec/manifest/stream_tfb8cbe3f986212419c9d27af6b6ca172_r408457571.m3u8
base-stream-controller.ts:1745 [log] > [stream-controller]: STOPPED->IDLE
audio-track-controller.ts:273 [log] > [audio-track-controller]: loading audio-track playlist 0 "original" lang:en-dc2ae518 group:group_audio
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: WAITING_TRACK->STOPPED
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: STOPPED->WAITING_TRACK
base-stream-controller.ts:1745 [log] > [subtitle-stream-controller]: IDLE->STOPPED
base-stream-controller.ts:1745 [log] > [subtitle-stream-controller]: STOPPED->IDLE
23XHR finished loading: GET "<URL>".
stream-controller.ts:631 [log] > [stream-controller]: Level 4 loaded [0,8][part-8--1], cc [0, 0] duration:36
buffer-controller.ts:692 [log] > [buffer-controller]: Updating Media Source duration to 36.000
base-stream-controller.ts:727 [log] > [stream-controller]: Loading fragment 0 cc: 0 of [0-8] level: 4, target: 0
base-stream-controller.ts:1745 [log] > [stream-controller]: IDLE->FRAG_LOADING
audio-track-controller.ts:90 [log] > [audio-track-controller]: audio-track 0 "original" lang:en-dc2ae518 group:group_audio loaded [0-8]
audio-stream-controller.ts:497 [log] > [audio-stream-controller]: Track 0 loaded [0,8][part-8--1],duration:36.09576
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: WAITING_TRACK->IDLE
base-stream-controller.ts:727 [log] > [audio-stream-controller]: Loading fragment 0 cc: 0 of [0-8] track: 0, target: 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
transmuxer-interface.ts:85 [log] > injecting Web Worker for "audio"
audio-stream-controller.ts:612 [log] > [audio-stream-controller]: Unknown video PTS for cc 0, waiting for video PTS before demuxing audio frag 0 of [0 ,8],track 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: FRAG_LOADING->WAITING_INIT_PTS
base-stream-controller.ts:386 [log] > [audio-stream-controller]: Loaded fragment 0 of level 0
transmuxer-interface.ts:85 [log] > injecting Web Worker for "main"
transmuxer-interface.ts:227 [log] > [transmuxer-interface, main]: Starting new transmux session for sn: 0 p: -1 level: 4 id: 1
        discontinuity: true
        trackSwitch: true
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 0
        initSegmentChange: true
base-stream-controller.ts:386 [log] > [stream-controller]: Loaded fragment 0 of level 4
blob:https://4cda8c72.hls-js-dev.pages.dev/e65a5dd0-e6e7-48f5-9201-caaf70d31d98:542 [log] > Debug logs enabled for "audio" in hls.js version 1.4.2
blob:https://4cda8c72.hls-js-dev.pages.dev/1bf01155-82e7-4675-97bf-fd69b74cba77:542 [log] > Debug logs enabled for "main" in hls.js version 1.4.2
transmuxer-interface.ts:379 [log] > [mp4-remuxer]: ISGenerated flag reset
transmuxer-interface.ts:379 [log] > [mp4-remuxer]: initPTS & initDTS reset
transmuxer-interface.ts:379 [log] > [mp4-remuxer]: reset next timestamp
base-stream-controller.ts:1745 [log] > [stream-controller]: FRAG_LOADING->PARSING
stream-controller.ts:1261 [log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[avc1.4d401f/avc1.4d401f]
audio-stream-controller.ts:128 [log] > [audio-stream-controller]: InitPTS for cc: 0 found from main: 6000
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: WAITING_INIT_PTS->FRAG_LOADING
transmuxer-interface.ts:227 [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
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 0 of level 4
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSING->PARSED
transmuxer-interface.ts:379 [log] > [mp4-remuxer]: ISGenerated flag reset
transmuxer-interface.ts:379 [log] > [mp4-remuxer]: initPTS & initDTS reset
transmuxer-interface.ts:379 [log] > [mp4-remuxer]: reset next timestamp
transmuxer-interface.ts:379 [log] > manifest codec:mp4a.40.2, ADTS type:2, samplingIndex:4
transmuxer-interface.ts:379 [log] > parsed codec:mp4a.40.5, rate:44100, channels:2
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
audio-stream-controller.ts:844 [log] > [audio-stream-controller]: Init audio buffer, container:audio/mp4, codecs[parsed]=[mp4a.40.5]
buffer-controller.ts:765 [log] > [buffer-controller]: creating sourceBuffer(video/mp4;codecs=avc1.4d401f)
buffer-controller.ts:765 [log] > [buffer-controller]: creating sourceBuffer(audio/mp4;codecs=mp4a.40.5)
stream-controller.ts:844 [log] > [stream-controller]: Alternate track found, use video.buffered to schedule main fragment loading
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 0 of level 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [audio-stream-controller]: Buffered audio sn: 0 of track 0 (frag:[0.000-3.947] > buffer:[0.000-3.947])
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSED->IDLE
base-stream-controller.ts:727 [log] > [audio-stream-controller]: Loading fragment 1 cc: 0 of [0-8] track: 0, target: 4.014
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:556 [log] > [stream-controller]: Buffered main sn: 0 of level 4 (frag:[0.000-4.000] > buffer:[0.000-4.000])
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSED->IDLE
base-stream-controller.ts:727 [log] > [stream-controller]: Loading fragment 1 cc: 0 of [0-8] level: 4, target: 4
base-stream-controller.ts:1745 [log] > [stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:386 [log] > [audio-stream-controller]: Loaded fragment 1 of level 0
transmuxer-interface.ts:379 [warn] > Audio frame @ 3.904s overlaps nextAudioPts by -43 ms.
onWorkerMessage @ transmuxer-interface.ts:379
TransmuxerInterface.onwmsg @ transmuxer-interface.ts:88
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 1 of level 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [audio-stream-controller]: Buffered audio sn: 1 of track 0 (frag:[3.904-7.921] > buffer:[0.000-7.921])
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSED->IDLE
base-stream-controller.ts:727 [log] > [audio-stream-controller]: Loading fragment 2 cc: 0 of [0-8] track: 0, target: 7.921
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:386 [log] > [stream-controller]: Loaded fragment 1 of level 4
transmuxer-interface.ts:379 [warn] > AVC: 67 ms (-6000dts) overlapping between fragments detected
onWorkerMessage @ transmuxer-interface.ts:379
TransmuxerInterface.onwmsg @ transmuxer-interface.ts:88
base-stream-controller.ts:1745 [log] > [stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 1 of level 4
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [stream-controller]: Buffered main sn: 1 of level 4 (frag:[3.933-7.933] > buffer:[0.000-3.833][3.933-7.933])
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSED->IDLE
base-stream-controller.ts:727 [log] > [stream-controller]: Loading fragment 2 cc: 0 of [0-8] level: 4, target: 7.933
base-stream-controller.ts:1745 [log] > [stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:386 [log] > [audio-stream-controller]: Loaded fragment 2 of level 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 2 of level 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [audio-stream-controller]: Buffered audio sn: 2 of track 0 (frag:[7.921-11.938] > buffer:[0.000-11.938])
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSED->IDLE
base-stream-controller.ts:386 [log] > [stream-controller]: Loaded fragment 2 of level 4
base-stream-controller.ts:1745 [log] > [stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 2 of level 4
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [stream-controller]: Buffered main sn: 2 of level 4 (frag:[7.933-11.933] > buffer:[0.000-3.833][3.933-11.933])
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSED->IDLE
base-stream-controller.ts:727 [log] > [stream-controller]: Loading fragment 1 cc: 0 of [0-8] level: 4, target: 3.933
base-stream-controller.ts:1745 [log] > [stream-controller]: IDLE->FRAG_LOADING
transmuxer-interface.ts:227 [log] > [transmuxer-interface, main]: Starting new transmux session for sn: 1 p: -1 level: 4 id: 1
        discontinuity: false
        trackSwitch: false
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 3.933333333333333
        initSegmentChange: false
base-stream-controller.ts:386 [log] > [stream-controller]: Loaded fragment 1 of level 4
transmuxer-interface.ts:379 [log] > [mp4-remuxer]: reset next timestamp
base-stream-controller.ts:1745 [log] > [stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 1 of level 4
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [stream-controller]: Buffered main sn: 1 of level 4 (frag:[3.933-7.933] > buffer:[0.000-3.833][3.933-11.933])
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSED->IDLE
base-stream-controller.ts:727 [log] > [stream-controller]: Loading fragment 3 cc: 0 of [0-8] level: 4, target: 11.933
base-stream-controller.ts:1745 [log] > [stream-controller]: IDLE->FRAG_LOADING
transmuxer-interface.ts:227 [log] > [transmuxer-interface, main]: Starting new transmux session for sn: 3 p: -1 level: 4 id: 1
        discontinuity: false
        trackSwitch: false
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 11.933333333333334
        initSegmentChange: false
base-stream-controller.ts:386 [log] > [stream-controller]: Loaded fragment 3 of level 4
transmuxer-interface.ts:379 [log] > [mp4-remuxer]: reset next timestamp
base-stream-controller.ts:1745 [log] > [stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 3 of level 4
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [stream-controller]: Buffered main sn: 3 of level 4 (frag:[11.933-15.933] > buffer:[0.000-3.833][3.933-15.933])
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSED->IDLE
base-stream-controller.ts:727 [log] > [stream-controller]: Loading fragment 1 cc: 0 of [0-8] level: 4, target: 3.933
base-stream-controller.ts:1745 [log] > [stream-controller]: IDLE->FRAG_LOADING
transmuxer-interface.ts:227 [log] > [transmuxer-interface, main]: Starting new transmux session for sn: 1 p: -1 level: 4 id: 1
        discontinuity: false
        trackSwitch: false
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 3.933333333333333
        initSegmentChange: false
base-stream-controller.ts:386 [log] > [stream-controller]: Loaded fragment 1 of level 4
transmuxer-interface.ts:379 [log] > [mp4-remuxer]: reset next timestamp
base-stream-controller.ts:1745 [log] > [stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 1 of level 4
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [stream-controller]: Buffered main sn: 1 of level 4 (frag:[3.933-7.933] > buffer:[0.000-3.833][3.933-15.933])
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSED->IDLE
favicon.ico:1     GET https://4cda8c72.hls-js-dev.pages.dev/favicon.ico 404
base-stream-controller.ts:727 [log] > [stream-controller]: Loading fragment 4 cc: 0 of [0-8] level: 4, target: 15.933
base-stream-controller.ts:1745 [log] > [stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:727 [log] > [audio-stream-controller]: Loading fragment 3 cc: 0 of [0-8] track: 0, target: 11.938
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
transmuxer-interface.ts:227 [log] > [transmuxer-interface, main]: Starting new transmux session for sn: 4 p: -1 level: 4 id: 1
        discontinuity: false
        trackSwitch: false
        contiguous: false
        accurateTimeOffset: true
        timeOffset: 15.933333333333334
        initSegmentChange: false
base-stream-controller.ts:386 [log] > [stream-controller]: Loaded fragment 4 of level 4
transmuxer-interface.ts:379 [log] > [mp4-remuxer]: reset next timestamp
base-stream-controller.ts:386 [log] > [audio-stream-controller]: Loaded fragment 3 of level 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 3 of level 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSING->PARSED
base-stream-controller.ts:1745 [log] > [stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 4 of level 4
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [audio-stream-controller]: Buffered audio sn: 3 of track 0 (frag:[11.938-15.955] > buffer:[0.000-15.955])
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSED->IDLE
base-stream-controller.ts:727 [log] > [audio-stream-controller]: Loading fragment 4 cc: 0 of [0-8] track: 0, target: 15.955
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:556 [log] > [stream-controller]: Buffered main sn: 4 of level 4 (frag:[15.933-19.933] > buffer:[0.000-3.833][3.933-19.933])
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSED->IDLE
base-stream-controller.ts:727 [log] > [stream-controller]: Loading fragment 5 cc: 0 of [0-8] level: 4, target: 19.933
base-stream-controller.ts:1745 [log] > [stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:386 [log] > [audio-stream-controller]: Loaded fragment 4 of level 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 4 of level 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [audio-stream-controller]: Buffered audio sn: 4 of track 0 (frag:[15.955-19.972] > buffer:[0.000-19.972])
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSED->IDLE
base-stream-controller.ts:727 [log] > [audio-stream-controller]: Loading fragment 5 cc: 0 of [0-8] track: 0, target: 19.972
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:386 [log] > [stream-controller]: Loaded fragment 5 of level 4
base-stream-controller.ts:1745 [log] > [stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 5 of level 4
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [stream-controller]: Buffered main sn: 5 of level 4 (frag:[19.933-23.933] > buffer:[0.000-3.833][3.933-23.933])
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSED->IDLE
base-stream-controller.ts:727 [log] > [stream-controller]: Loading fragment 6 cc: 0 of [0-8] level: 4, target: 23.933
base-stream-controller.ts:1745 [log] > [stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:386 [log] > [audio-stream-controller]: Loaded fragment 5 of level 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 5 of level 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [audio-stream-controller]: Buffered audio sn: 5 of track 0 (frag:[19.972-23.989] > buffer:[0.000-23.989])
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSED->IDLE
base-stream-controller.ts:727 [log] > [audio-stream-controller]: Loading fragment 6 cc: 0 of [0-8] track: 0, target: 23.989
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:386 [log] > [stream-controller]: Loaded fragment 6 of level 4
base-stream-controller.ts:1745 [log] > [stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 6 of level 4
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [stream-controller]: Buffered main sn: 6 of level 4 (frag:[23.933-27.933] > buffer:[0.000-3.833][3.933-27.933])
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSED->IDLE
base-stream-controller.ts:727 [log] > [stream-controller]: Loading fragment 7 cc: 0 of [0-8] level: 4, target: 27.933
base-stream-controller.ts:1745 [log] > [stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:386 [log] > [audio-stream-controller]: Loaded fragment 6 of level 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 6 of level 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [audio-stream-controller]: Buffered audio sn: 6 of track 0 (frag:[23.989-28.006] > buffer:[0.000-28.006])
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSED->IDLE
base-stream-controller.ts:727 [log] > [audio-stream-controller]: Loading fragment 7 cc: 0 of [0-8] track: 0, target: 28.006
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:386 [log] > [stream-controller]: Loaded fragment 7 of level 4
base-stream-controller.ts:1745 [log] > [stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 7 of level 4
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [stream-controller]: Buffered main sn: 7 of level 4 (frag:[27.933-31.933] > buffer:[0.000-3.833][3.933-31.933])
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSED->IDLE
base-stream-controller.ts:727 [log] > [stream-controller]: Loading fragment 8 cc: 0 of [0-8] level: 4, target: 31.933
base-stream-controller.ts:1745 [log] > [stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:386 [log] > [audio-stream-controller]: Loaded fragment 7 of level 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 7 of level 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [audio-stream-controller]: Buffered audio sn: 7 of track 0 (frag:[28.006-32.023] > buffer:[0.000-32.023])
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSED->IDLE
base-stream-controller.ts:727 [log] > [audio-stream-controller]: Loading fragment 8 cc: 0 of [0-8] track: 0, target: 32.023
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:386 [log] > [stream-controller]: Loaded fragment 8 of level 4
base-stream-controller.ts:1745 [log] > [stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 8 of level 4
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [stream-controller]: Buffered main sn: 8 of level 4 (frag:[31.933-35.933] > buffer:[0.000-3.833][3.933-35.933])
base-stream-controller.ts:1745 [log] > [stream-controller]: PARSED->IDLE
buffer-controller.ts:544 [log] > [buffer-controller]: video sourceBuffer now EOS
base-stream-controller.ts:1745 [log] > [stream-controller]: IDLE->ENDED
base-stream-controller.ts:386 [log] > [audio-stream-controller]: Loaded fragment 8 of level 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:379 [log] > [transmuxer.ts]: Flushed fragment 8 of level 0
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSING->PARSED
base-stream-controller.ts:556 [log] > [audio-stream-controller]: Buffered audio sn: 8 of track 0 (frag:[32.023-36.017] > buffer:[0.000-36.017])
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: PARSED->IDLE
buffer-controller.ts:544 [log] > [buffer-controller]: audio sourceBuffer now EOS
buffer-controller.ts:551 [log] > [buffer-controller]: Queueing mediaSource.endOfStream()
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: IDLE->ENDED
buffer-controller.ts:568 [log] > [buffer-controller]: Calling mediaSource.endOfStream()
buffer-controller.ts:819 [log] > [buffer-controller]: Media source ended
gap-controller.ts:229 [warn] > Playback stalling at @6.719002 due to low buffer ({"len":29.298117,"start":3.933333,"end":36.017119})
_reportStall @ gap-controller.ts:229
poll @ gap-controller.ts:153
checkBuffer @ stream-controller.ts:935
onTickEnd @ stream-controller.ts:208
doTick @ stream-controller.ts:203
tick @ task-loop.ts:106
setInterval (async)
setInterval @ task-loop.ts:68
startLoad @ stream-controller.ts:127
(anonymous) @ hls.ts:402
startLoad @ hls.ts:401
filterAndSortMediaOptions @ level-controller.ts:295
onManifestLoaded @ level-controller.ts:152
emit @ index.js:203
emit @ hls.ts:287
trigger @ hls.ts:295
handleMasterPlaylist @ playlist-loader.ts:424
onSuccess @ playlist-loader.ts:322
readystatechange @ xhr-loader.ts:230
XMLHttpRequest.send (async)
openAndSendXhr @ xhr-loader.ts:157
loadInternal @ xhr-loader.ts:116
load @ xhr-loader.ts:76
load @ playlist-loader.ts:347
onManifestLoading @ playlist-loader.ts:154
emit @ index.js:203
emit @ hls.ts:287
trigger @ hls.ts:295
loadSource @ hls.ts:389
loadSelectedStream @ main.js:372
(anonymous) @ main.js:225
j @ jquery.min.js:2
fireWith @ jquery.min.js:2
ready @ jquery.min.js:2
I @ jquery.min.js:2
Show 2 more frames
main.js:734 Error event: {type: 'mediaError', details: 'bufferStalledError', fatal: false, error: Error: Playback stalling at @6.719002 due to low buffer ({"len":29.298117,"start":3.933333,"end":36…, buffer: 29.298117, …}
(anonymous) @ main.js:734
emit @ index.js:203
emit @ hls.ts:287
trigger @ hls.ts:295
_reportStall @ gap-controller.ts:230
poll @ gap-controller.ts:153
checkBuffer @ stream-controller.ts:935
onTickEnd @ stream-controller.ts:208
doTick @ stream-controller.ts:203
tick @ task-loop.ts:106
setInterval (async)
setInterval @ task-loop.ts:68
startLoad @ stream-controller.ts:127
(anonymous) @ hls.ts:402
startLoad @ hls.ts:401
filterAndSortMediaOptions @ level-controller.ts:295
onManifestLoaded @ level-controller.ts:152
emit @ index.js:203
emit @ hls.ts:287
trigger @ hls.ts:295
handleMasterPlaylist @ playlist-loader.ts:424
onSuccess @ playlist-loader.ts:322
readystatechange @ xhr-loader.ts:230
XMLHttpRequest.send (async)
openAndSendXhr @ xhr-loader.ts:157
loadInternal @ xhr-loader.ts:116
load @ xhr-loader.ts:76
load @ playlist-loader.ts:347
onManifestLoading @ playlist-loader.ts:154
emit @ index.js:203
emit @ hls.ts:287
trigger @ hls.ts:295
loadSource @ hls.ts:389
loadSelectedStream @ main.js:372
(anonymous) @ main.js:225
j @ jquery.min.js:2
fireWith @ jquery.min.js:2
ready @ jquery.min.js:2
I @ jquery.min.js:2
Show 3 more frames
hls.ts:410 [log] > stopLoad
base-stream-controller.ts:1745 [log] > [stream-controller]: ENDED->STOPPED
base-stream-controller.ts:1745 [log] > [audio-stream-controller]: ENDED->STOPPED
base-stream-controller.ts:1745 [log] > [subtitle-stream-controller]: IDLE->STOPPED
gap-controller.ts:205 [warn] > Trying to nudge playhead over buffer-hole
_tryFixBufferStall @ gap-controller.ts:205
poll @ gap-controller.ts:164
checkBuffer @ stream-controller.ts:935
onTickEnd @ stream-controller.ts:208
doTick @ stream-controller.ts:203
tick @ task-loop.ts:106
onMediaPlaying @ stream-controller.ts:539
gap-controller.ts:347 [warn] > Nudging 'currentTime' from 6.933333 to 7.033333
_tryNudgeBuffer @ gap-controller.ts:347
_tryFixBufferStall @ gap-controller.ts:210
poll @ gap-controller.ts:164
checkBuffer @ stream-controller.ts:935
onTickEnd @ stream-controller.ts:208
doTick @ stream-controller.ts:203
tick @ task-loop.ts:106
onMediaPlaying @ stream-controller.ts:539
main.js:734 Error event: {type: 'mediaError', details: 'bufferNudgeOnStall', error: Error: Nudging 'currentTime' from 6.933333 to 7.033333
    at GapController._tryNudgeBuffer (https:…, fatal: false, errorAction: {…}}
(anonymous) @ main.js:734
emit @ index.js:203
emit @ hls.ts:287
trigger @ hls.ts:295
_tryNudgeBuffer @ gap-controller.ts:349
_tryFixBufferStall @ gap-controller.ts:210
poll @ gap-controller.ts:164
checkBuffer @ stream-controller.ts:935
onTickEnd @ stream-controller.ts:208
doTick @ stream-controller.ts:203
tick @ task-loop.ts:106
onMediaPlaying @ stream-controller.ts:539
Show 1 more frame
base-stream-controller.ts:241 [log] > [stream-controller]: media seeking to 7.033, state: STOPPED
base-stream-controller.ts:241 [log] > [audio-stream-controller]: media seeking to 7.033, state: STOPPED
base-stream-controller.ts:241 [log] > [subtitle-stream-controller]: media seeking to 7.033, state: STOPPED
stream-controller.ts:546 [log] > [stream-controller]: Media seeked to 7.033

Chrome media internals output

No response

mrjamesriley commented 1 year ago

For the above, please note that following:

All works well in Firefox
All works well in HLS 1.2.4 - with the issue occuring in 1.2.5 and above
This video is hosted / streamed using Cloudflare Stream
I do not have control of the video encoding, with these videos coming from our users, specifically via the Instagram API. From the Instagram API, the majority of videos work fine - but we are seeing multiple examples such as the one shared here.

I can see in the logs mention of audio overlaps. Given that I do not control the original audio file, my desire here is for HLS to 'just work' and play through despite such issues. This Video does play well using the Video.js library (without any stalling), which I hope is a positive sign that any issues with the encoding of the original video doesn't need to be a show-stopper.

robwalch commented 1 year ago

The overlap that results in a video SourceBuffer gap and ultimately the stall is in the main playlist:

base-stream-controller.ts:556 [log] > [stream-controller]: Buffered main sn: 0 of level 4 (frag:[0.000-4.000] > buffer:[0.000-4.000])

base-stream-controller.ts:556 [log] > [stream-controller]: Buffered main sn: 1 of level 4 (frag:[3.933-7.933] > buffer:[0.000-3.833][3.933-7.933])

mrjamesriley commented 1 year ago

Thank you for the response @robwalch

Given that the source of these videos is the Instagram API (and thus we do not control the encoding here), is there a way to configure HLS.js to 'ignore' such issues and just play through?

HLS.js version 1.2.4 and prior manage to play this stream without trouble - is it possible to achieve the same behaviour on the latest version of HLS.js? I'm hoping to be able to avoid the video pausing/stalling and have the library 'do its best' with what it has available - even if it means audio loss of video frames lost etc.

suppayami commented 1 year ago

I got this problem too, the video is hosted on Cloudflare, everything works fine when I downgrade to 1.2.4 too

robwalch commented 1 year ago

HLS.js version 1.2.4 and prior manage to play this stream without trouble

Probably a result of this change:

https://github.com/video-dev/hls.js/compare/v1.2.4...v1.2.5#diff-fccedeec0ef12b083f3e18534af86e02cecca386bce4d9f328048b5423f2e9e3R455-R469

@mrjamesriley or @suppayami, can either of you confirm?

robwalch commented 1 year ago

The change above is not one we want to remove. There may some reasoning where making adjustments is OK in this case, but we need to confirm why this overlap is detected:

Is it a problem in the media resulting from bad track alignment (shifting negative timestamps to 0 on first segment)? Or, is HLS.js doing the shifting in this case (didn't look like it, but a closer look is in order)?

transmuxer-interface.ts:379 [warn] > AVC: 67 ms (-6000dts) overlapping between fragments detected
onWorkerMessage @ transmuxer-interface.ts:379
TransmuxerInterface.onwmsg @ transmuxer-interface.ts:88

robwalch commented 1 year ago

The issue is primarily that the media timestamps of the last and first samples in the first two TS segments literally overlap:

Last video sample of msn 0: pts: 363000, dts: 357000 First video sample of msn 1: pts: 360000, dts: 354000

Regardless of whether Hls.js aligns on PTS or DTS, the last frame at the end of the first segment is overlapped by the first of the second, resulting in the former being ejected by MSE on append.

robwalch commented 1 year ago

Hi @mrjamesriley and @suppayami,

Do the changes in #5500 resolve the playback issues for you (buffer gap resulting in stall at the end of the first segment)?

suppayami commented 1 year ago

@robwalch sorry for late reply, I just tried with latest canary and it seems to work fine. Thank you so much 🚀

bhayward93 commented 1 year ago

@robwalch I've been seeing this issue for a while now and came across this thread - it appears to have been resolved for others but for my usecase, it still appears to be broken with various versions of this library including the latest release. These videos are through Cloudflare Streams and I have no control over the encoding.

Example video:

https://customer-gh08u53vbkhozibb.cloudflarestream.com/db17d0e8887c7c97743aed2764562074/manifest/video.m3u8

With v1.4.2 Demo:

https://4cda8c72.hls-js-dev.pages.dev/demo/?src=https%3A%2F%2Fcustomer-gh08u53vbkhozibb.cloudflarestream.com%2Fdb17d0e8887c7c97743aed2764562074%2Fmanifest%2Fvideo.m3u8&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOmZhbHNlLCJzdG9wT25TdGFsbCI6dHJ1ZSwiZHVtcGZNUDQiOmZhbHNlLCJsZXZlbENhcHBpbmciOi0xLCJsaW1pdE1ldHJpY3MiOi0xfQ==

Looking at the demo I can see an overlap between segments here, which may be of note:

The order in which requests are made is quite a bit different between Firefox and Chrome, which may hint at why things are working in Firefox, though the order of these could well be dependent on my individual network speed.

Chrome:

720p playlist is loaded
Seg 1 audio loaded
Seg 1 video loaded
Seg 2 audio loaded
Switch to 1080p
Seg 3 audio loaded
Seg 2 video loaded
Seg 3 video loaded
Subsequent video and audio segments then load together

In Firefox, segmented audio and video are grouped together and things work as expected.

Here are the console logs I see from the demo:

I spotted this issue which also seems related; You requested a new issue card be made for that one, but the problem I'm having seems as if it's the same as the one mentioned in this card. If you would like me to split this into its own issue please let me know. Any ideas?

robwalch commented 1 year ago

Hi @bhayward93,

Please file a new issue.

Check against dev (https://hlsjs-dev.video-dev.org/demo/) and include a sample HLS asset reproducing the issue with complete console log text.

bhayward93 commented 1 year ago

Hi @bhayward93,

Please file a new issue.

Check against dev (https://hlsjs-dev.video-dev.org/demo/) and include a sample HLS asset reproducing the issue with complete console log text.

Thank you for the quick response @robwalch. I've made a new issue card here https://github.com/video-dev/hls.js/issues/5797

video-dev / hls.js