Segment 0 fetched repeatedly, at a high rate (Firefox), if EXT-X-START is near 0 and audio stream starts late in segment #7674
Description
What version of Hls.js are you using?
v1.6.15
What browser (including version) are you using?
Firefox 146
What OS (including version) are you using?
Windows 11
Test stream
Configuration
{
"debug": true,
"enableWorker": true,
"lowLatencyMode": true,
"backBufferLength": 90
}Additional player setup steps
No response
Checklist
- The issue observed is not already reported by searching on Github under https://github.com/video-dev/hls.js/issues
- The issue occurs in the stable client (latest release) on https://hlsjs.video-dev.org/demo and not just on my page
- The issue occurs in the latest client (main branch) on https://hlsjs-dev.video-dev.org/demo and not just on my page
- The stream has correct Access-Control-Allow-Origin headers (CORS)
- There are no network errors such as 404s in the browser console when trying to play the stream
Steps to reproduce
- Create an HLS stream, of at least 3 .ts segments. Craft segment 0 in this way: The video should start at an early PTS (e.g., 0), and the audio stream should starting at a late PTS, e.g., within the last 50ms of the segment.
- Create a playlist that includes the following properties:
#EXT-X-VERSION:3
#EXT-X-START:TIME-OFFSET=0.000000,PRECISE=YES - Load the stream into the demo player, on Firefox
Expected behaviour
Segments are fetched in order, without repeats, and the stream plays normally
What actually happened?
- Segment 0 is fetched repeatedly, at a high rate. Network traffic is sustained at > 50mpbs indefinitely.
- Stream never reached a playable state.
On Firefox, the segment download sequence goes [0, 2, 0, 0, 0, 0, 0, 0, 0...], as you can see below.
On Chrome, the segment download sequence is [0, 2, 0, 0, 1, 2, 3], and the stream does eventually play. However, the audio and the video seem to be ~3 seconds out-of-sync.
Looking into this, I think something goes off the rails at computeInitPts(). The return value of the function is suspect. For example, adding this unit test:
it('computeInitPts() returns base PTS for an EXT-X-START value of 0.0', function () {
const initPts = mp4Remuxer.computeInitPts(0, 90000, 0.0, 'video');
expect(initPts).to.eq(0);
});
produces:
AssertionError: expected 8589934592 to equal +0
So, for the test stream, the initPTS/initDTS is 287730, after computeInitPts() is called for the audio stream. This might've been corrected by the calculations for the video stream (since it starts at a nice basePTS/baseDTS of 0), but videoInitDTS and videoInitPTS are calculated as 8589934592, instead, which causes those values to be discarded.
Then, the next call to getLoadPosition() returns 3.327, which looks right for segment 1, but ends up resolving to segment 2 (getFwdBufferInfoAtPos()), apparently because pos is now not quite in the timebase that getFragmentAtPosition() expects (it's off by ~3 seconds). Note that maxBufferHole is 0 during this time, as the stream is still paused.
Firefox will just spin here, with targetBufferTime being stuck at 0. Chrome, after thrashing around on segments 0 and 2 for a bit, somehow gets a targetBufferTime of 0.139302, which is enough to get it to fetch segment 1, and get back on the rails.
For now I've managed to avoiding the problem by downgrading to v1.6.12, which is the latest release that doesn't include b282f03. I may be able to attempt a PR, if you can provide some direction.
The test stream up should remain up for at least a few months; feel free to make a copy.
Console output
Using Hls.js config:
Object { debug: true, enableWorker: true, lowLatencyMode: true, backBufferLength: 90 }
hls-demo.js:24479:12
[log] > Debug logs enabled for "Hls instance" in hls.js version 1.6.15 hls.js:1168:19
[log] > stopLoad hls.js:36890:19
[log] > loadSource:https://live1.greeblesoftware.com/228541993686314.m3u8 hls.js:36849:19
[log] > [interstitials]: clear schedule state hls.js:25743:12
[log] > [stream-controller]: Trigger BUFFER_RESET hls.js:34790:12
[log] > attachMedia hls.js:36802:19
[log] > [buffer-controller]: created media source: MediaSource hls.js:19280:12
[log] > [buffer-controller]: Media source opened hls.js:19080:18
[log] > [buffer-controller]: checkPendingTracks (pending: 0 codec events expected: 0) {} hls.js:20128:12
[log] > [level-controller]: manifest loaded, 1 level(s) found, first bitrate: 0 hls.js:33995:16
[log] > [buffer-controller]: 1 bufferCodec event(s) expected. hls.js:19235:12
[log] > auto startLoad with configured startPosition -1 hls.js:36232:25
[log] > startLoad(-1) hls.js:36875:19
[log] > [level-controller]: Switching to level 0 (SDR @0) from level -1 hls.js:34223:14
[log] > [stream-controller]: STOPPED->IDLE hls.js:10907:16
[log] > [subtitle-stream-controller]: STOPPED->IDLE hls.js:10907:16
[log] > [stream-controller]: Level 0 loaded [0,3][part-3--1], cc [0, 0] duration:12.536000000000001 hls.js:34837:12
[log] > [stream-controller]: Setting startPosition to 0 for start time offset 0 found in media playlist hls.js:10537:16
[log] > [interstitials]: [checkStart] Advancing timeline position to 0 hls.js:25888:14
[log] > [interstitials]: setSchedulePosition 0, undefined ([primary: 0.00-12.54]) pos: 0 hls.js:25972:12
[log] > [interstitials]: INTERSTITIALS_BUFFERED_TO_BOUNDARY [primary: 0.00-12.54] hls.js:26498:14
[log] > [interstitials]: resuming [primary: 0.00-12.54] hls.js:26152:12
[log] > [interstitials]: [attachPrimary] Advancing timeline position to 0 hls.js:26218:14
[log] > [buffer-controller]: Updating MediaSource duration to 12.536 hls.js:20115:16
[log] > [stream-controller]: Loading main sn: 0 of level 0 (frag:[0.000-3.327]) cc: 0 [0-3], target: 0 hls.js:9956:12
[log] > [stream-controller]: IDLE->FRAG_LOADING hls.js:10907:16
[log] > injecting Web Worker for "main" hls.js:17231:22
[log] > [transmuxer-interface]: Starting new transmux session for main sn: 0 level: 0 id: 1
discontinuity: true
trackSwitch: true
contiguous: false
accurateTimeOffset: true
timeOffset: 0
initSegmentChange: true hls.js:17333:25
[log] > [stream-controller]: Loaded main sn: 0 of level 0 hls.js:9643:18
[log] > Debug logs enabled for "main" in hls.js version 1.6.15 26423e01-a0e7-4824-9950-2d20e62b98c0:1168:19
[log] > [mp4-remuxer]: ISGenerated flag reset hls.js:17169:46
[log] > [mp4-remuxer]: Reset initPTS: null > null hls.js:17169:46
[log] > [mp4-remuxer]: reset next timestamp hls.js:17169:46
[log] > manifest codec:undefined, parsed codec:mp4a.40.2, channels:1, rate:44100 (ADTS object type:2 sampling index:4) 26423e01-a0e7-4824-9950-2d20e62b98c0:11145:12
[log] > [mp4-remuxer]: Adjusting PTS for rollover in timeline near 0 video 2 hls.js:17169:46
[log] > [mp4-remuxer]: Found initPTS at playlist time: 0 offset: 3.197 (287730/90000) trackId: 1 hls.js:17169:46
[log] > [stream-controller]: FRAG_LOADING->PARSING hls.js:10907:16
[log] > [stream-controller]: Init audio buffer, container:audio/mp4, codecs[selected/level/parsed]=[mp4a.40.2//mp4a.40.2] hls.js:35461:14
[log] > [stream-controller]: Init video buffer, container:video/mp4, codecs[level/parsed]=[/avc1.64002a] hls.js:35484:14
[log] > [buffer-controller]: BUFFER_CODECS: "audio,video" (current SB count 0) hls.js:19498:12
[log] > [buffer-controller]: checkPendingTracks (pending: 2 codec events expected: 1) {"audio":{"listeners":[],"codec":"mp4a.40.2","container":"audio/mp4","levelCodec":"mp4a.40.2","metadata":{"channelCount":1},"id":"main"},"video":{"listeners":[],"codec":"avc1.64002a","container":"video/mp4","metadata":{"width":1920,"height":824},"id":"main"}} hls.js:20128:12
[log] > [buffer-controller]: creating sourceBuffer(audio/mp4;codecs=mp4a.40.2) {"listeners":[],"codec":"mp4a.40.2","container":"audio/mp4","levelCodec":"mp4a.40.2","metadata":{"channelCount":1},"id":"main"} hls.js:20197:16
[log] > [buffer-controller]: creating sourceBuffer(video/mp4;codecs=avc1.64002a) {"listeners":[],"codec":"avc1.64002a","container":"video/mp4","metadata":{"width":1920,"height":824},"id":"main"} hls.js:20197:16
[log] > [buffer-controller]: SourceBuffers created. Running queue:
video: (SourceBuffer)
audio: (SourceBuffer)
audiovideo: (none) } hls.js:20167:14
[log] > [buffer-controller]: queuing "audio" append sn: 0 of level 0 cc: 0 hls.js:19792:12
[log] > [buffer-controller]: queuing "video" append sn: 0 of level 0 cc: 0 hls.js:19792:12
[log] > [audio-stream-controller]: InitPTS for cc: 0 found from main: 3.197 (287730/90000) trackId: 1 hls.js:17513:14
[log] > [buffer-controller]: queuing "video" append sn: 0 of level 0 cc: 0 hls.js:19792:12
[log] > [buffer-controller]: queuing "audio" append sn: 0 of level 0 cc: 0 hls.js:19792:12
[log] > [transmuxer.ts]: Flushed main sn: 0 of level 0 hls.js:17169:46
[log] > [stream-controller]: PARSING->PARSED hls.js:10907:16
[log] > [stream-controller]: Parsed main sn: 0 of level 0 (frag:[0.000-0.139]) hls.js:10814:12
[log] > [buffer-controller]: Updating audio SourceBuffer timestampOffset to -3.197 (sn: 0 cc: 0) hls.js:20319:14
[log] > [buffer-controller]: Updating video SourceBuffer timestampOffset to -3.197 (sn: 0 cc: 0) hls.js:20319:14
[log] > [stream-controller]: Buffered main sn: 0 of level 0 (frag:[0.000-0.139] > buffer:) hls.js:9817:12
[log] > [stream-controller]: PARSED->IDLE hls.js:10907:16
[log] > [stream-controller]: Loading main sn: 2 of level 0 (frag:[3.327-6.720]) cc: 0 [0-3], target: 3.327 hls.js:9956:12
[log] > [stream-controller]: IDLE->FRAG_LOADING hls.js:10907:16
[log] > [transmuxer-interface]: Starting new transmux session for main sn: 2 level: 0 id: 1
discontinuity: false
trackSwitch: false
contiguous: false
accurateTimeOffset: true
timeOffset: 3.327
initSegmentChange: false hls.js:17333:25
[log] > [stream-controller]: Loaded main sn: 2 of level 0 hls.js:9643:18
[log] > [mp4-remuxer]: reset next timestamp hls.js:17169:46
[log] > [stream-controller]: FRAG_LOADING->PARSING hls.js:10907:16
[log] > [buffer-controller]: queuing "video" append sn: 2 of level 0 cc: 0 hls.js:19792:12
[log] > [buffer-controller]: queuing "audio" append sn: 2 of level 0 cc: 0 hls.js:19792:12
[log] > [transmuxer.ts]: Flushed main sn: 2 of level 0 hls.js:17169:46
[log] > [stream-controller]: PARSING->PARSED hls.js:10907:16
[log] > [stream-controller]: Parsed main sn: 2 of level 0 (frag:[3.339-6.734]) hls.js:10814:12
[log] > [stream-controller]: Buffered main sn: 2 of level 0 (frag:[3.339-6.734] > buffer:[3.344-6.703]) hls.js:9817:12
[log] > [stream-controller]: PARSED->IDLE hls.js:10907:16
[log] > [stream-controller]: Loading main sn: 0 of level 0 (frag:[0.000-3.325]) cc: 0 [0-3], target: 0 hls.js:9956:12
[log] > [stream-controller]: IDLE->FRAG_LOADING hls.js:10907:16
[log] > [transmuxer-interface]: Starting new transmux session for main sn: 0 level: 0 id: 1
discontinuity: false
trackSwitch: false
contiguous: false
accurateTimeOffset: true
timeOffset: 0
initSegmentChange: false hls.js:17333:25
[log] > [stream-controller]: Loaded main sn: 0 of level 0 hls.js:9643:18
[log] > [mp4-remuxer]: reset next timestamp hls.js:17169:46
[log] > [stream-controller]: FRAG_LOADING->PARSING hls.js:10907:16
[log] > [buffer-controller]: queuing "video" append sn: 0 of level 0 cc: 0 hls.js:19792:12
[log] > [buffer-controller]: queuing "audio" append sn: 0 of level 0 cc: 0 hls.js:19792:12
[log] > [transmuxer.ts]: Flushed main sn: 0 of level 0 hls.js:17169:46
[log] > [stream-controller]: PARSING->PARSED hls.js:10907:16
[log] > [stream-controller]: Parsed main sn: 0 of level 0 (frag:[0.000-0.139]) hls.js:10814:12
[log] > [stream-controller]: Buffered main sn: 0 of level 0 (frag:[0.000-0.139] > buffer:[3.344-6.703]) hls.js:9817:12
[log] > [stream-controller]: PARSED->IDLE hls.js:10907:16
[log] > [stream-controller]: Loading main sn: 0 of level 0 (frag:[0.000-0.139]) cc: 0 [0-3], target: 0 hls.js:9956:12
[log] > [stream-controller]: IDLE->FRAG_LOADING hls.js:10907:16
[log] > [transmuxer-interface]: Starting new transmux session for main sn: 0 level: 0 id: 1
discontinuity: false
trackSwitch: false
contiguous: false
accurateTimeOffset: true
timeOffset: 0
initSegmentChange: false hls.js:17333:25
[log] > [stream-controller]: Loaded main sn: 0 of level 0 hls.js:9643:18
[log] > [mp4-remuxer]: reset next timestamp hls.js:17169:46
[warn] > [mp4-remuxer]: Audio frame @ 3.197s overlaps marker by -139 ms. <anonymous code>:1:147461
[log] > [stream-controller]: FRAG_LOADING->PARSING hls.js:10907:16
[log] > [buffer-controller]: queuing "video" append sn: 0 of level 0 cc: 0 hls.js:19792:12
[log] > [buffer-controller]: queuing "audio" append sn: 0 of level 0 cc: 0 hls.js:19792:12
[log] > [transmuxer.ts]: Flushed main sn: 0 of level 0 hls.js:17169:46
[log] > [stream-controller]: PARSING->PARSED hls.js:10907:16
[log] > [stream-controller]: Parsed main sn: 0 of level 0 (frag:[0.000-0.139]) hls.js:10814:12
[log] > [stream-controller]: Buffered main sn: 0 of level 0 (frag:[0.000-0.139] > buffer:[3.344-6.703]) hls.js:9817:12
[log] > [stream-controller]: PARSED->IDLE hls.js:10907:16
[log] > [stream-controller]: Loading main sn: 0 of level 0 (frag:[0.000-0.139]) cc: 0 [0-3], target: 0 hls.js:9956:12
[log] > [stream-controller]: IDLE->FRAG_LOADING hls.js:10907:16
[log] > [transmuxer-interface]: Starting new transmux session for main sn: 0 level: 0 id: 1
discontinuity: false
trackSwitch: false
contiguous: false
accurateTimeOffset: true
timeOffset: 0
initSegmentChange: false hls.js:17333:25
[log] > [stream-controller]: Loaded main sn: 0 of level 0 hls.js:9643:18
[log] > [mp4-remuxer]: reset next timestamp hls.js:17169:46
[warn] > [mp4-remuxer]: Audio frame @ 3.197s overlaps marker by -139 ms. <anonymous code>:1:147461
[log] > [stream-controller]: FRAG_LOADING->PARSING hls.js:10907:16
[log] > [buffer-controller]: queuing "video" append sn: 0 of level 0 cc: 0 hls.js:19792:12
[log] > [buffer-controller]: queuing "audio" append sn: 0 of level 0 cc: 0 hls.js:19792:12
[log] > [transmuxer.ts]: Flushed main sn: 0 of level 0 hls.js:17169:46
[log] > [stream-controller]: PARSING->PARSED hls.js:10907:16
[log] > [stream-controller]: Parsed main sn: 0 of level 0 (frag:[0.000-0.139]) hls.js:10814:12
[log] > [stream-controller]: Buffered main sn: 0 of level 0 (frag:[0.000-0.139] > buffer:[3.344-6.703]) hls.js:9817:12
[log] > [stream-controller]: PARSED->IDLE hls.js:10907:16
[log] > [stream-controller]: Loading main sn: 0 of level 0 (frag:[0.000-0.139]) cc: 0 [0-3], target: 0 hls.js:9956:12
[log] > [stream-controller]: IDLE->FRAG_LOADING hls.js:10907:16
Source map error: Error: request failed with status 404
Stack in the worker:networkRequest@resource://devtools/client/shared/source-map-loader/utils/network-request.js:43:9
Resource URL: https://hlsjs.video-dev.org/demo/%3Canonymous%20code%3E
Source Map URL: installHook.js.map
[log] > [transmuxer-interface]: Starting new transmux session for main sn: 0 level: 0 id: 1
discontinuity: false
trackSwitch: false
contiguous: false
accurateTimeOffset: true
timeOffset: 0
initSegmentChange: false hls.js:17333:25
[log] > [stream-controller]: Loaded main sn: 0 of level 0 hls.js:9643:18
[log] > [mp4-remuxer]: reset next timestamp hls.js:17169:46
[warn] > [mp4-remuxer]: Audio frame @ 3.197s overlaps marker by -139 ms. <anonymous code>:1:147461
[log] > [stream-controller]: FRAG_LOADING->PARSING hls.js:10907:16
[log] > [buffer-controller]: queuing "video" append sn: 0 of level 0 cc: 0 hls.js:19792:12
[log] > [buffer-controller]: queuing "audio" append sn: 0 of level 0 cc: 0 hls.js:19792:12
[log] > [transmuxer.ts]: Flushed main sn: 0 of level 0 hls.js:17169:46
[log] > [stream-controller]: PARSING->PARSED hls.js:10907:16
[log] > [stream-controller]: Parsed main sn: 0 of level 0 (frag:[0.000-0.139]) hls.js:10814:12
[log] > [stream-controller]: Buffered main sn: 0 of level 0 (frag:[0.000-0.139] > buffer:[3.344-6.703]) hls.js:9817:12
[log] > [stream-controller]: PARSED->IDLE hls.js:10907:16
[log] > [stream-controller]: Loading main sn: 0 of level 0 (frag:[0.000-0.139]) cc: 0 [0-3], target: 0 hls.js:9956:12
[log] > [stream-controller]: IDLE->FRAG_LOADING hls.js:10907:16
[log] > [transmuxer-interface]: Starting new transmux session for main sn: 0 level: 0 id: 1
discontinuity: false
trackSwitch: false
contiguous: false
accurateTimeOffset: true
timeOffset: 0
initSegmentChange: false hls.js:17333:25
[log] > [stream-controller]: Loaded main sn: 0 of level 0 hls.js:9643:18
[log] > [mp4-remuxer]: reset next timestamp hls.js:17169:46
[warn] > [mp4-remuxer]: Audio frame @ 3.197s overlaps marker by -139 ms. <anonymous code>:1:147461
[log] > [stream-controller]: FRAG_LOADING->PARSING hls.js:10907:16
[log] > [buffer-controller]: queuing "video" append sn: 0 of level 0 cc: 0 hls.js:19792:12
[log] > [buffer-controller]: queuing "audio" append sn: 0 of level 0 cc: 0 hls.js:19792:12
[log] > [transmuxer.ts]: Flushed main sn: 0 of level 0 hls.js:17169:46
[log] > [stream-controller]: PARSING->PARSED hls.js:10907:16
[log] > [stream-controller]: Parsed main sn: 0 of level 0 (frag:[0.000-0.139]) hls.js:10814:12
[log] > [stream-controller]: Buffered main sn: 0 of level 0 (frag:[0.000-0.139] > buffer:[3.344-6.703]) hls.js:9817:12
[log] > [stream-controller]: PARSED->IDLE hls.js:10907:16
[log] > [stream-controller]: Loading main sn: 0 of level 0 (frag:[0.000-0.139]) cc: 0 [0-3], target: 0 hls.js:9956:12
[log] > [stream-controller]: IDLE->FRAG_LOADING hls.js:10907:16
[log] > [transmuxer-interface]: Starting new transmux session for main sn: 0 level: 0 id: 1
discontinuity: false
trackSwitch: false
contiguous: false
accurateTimeOffset: true
timeOffset: 0
initSegmentChange: false hls.js:17333:25
[log] > [stream-controller]: Loaded main sn: 0 of level 0 hls.js:9643:18
(...last 22 lines repeat endlessly)