Hls.js: Stream stops (fragments not being fetched), no logs, no errors

Created on 15 Oct 2020 · 15Comments · Source: video-dev/hls.js

What version of Hls.js are you using?

Tested on
0.13.2 and 0.14.15

What browser and OS are you using?

Chrome / Firefox / Safari

Test stream:

https://s3-us-west-1.amazonaws.com/test.audius.co/vincent.m3u8

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 on https://hls-js.netlify.com/demo and not just on my page
https://hls-js.netlify.app/demo/?src=https%3A%2F%2Fs3-us-west-1.amazonaws.com%2Ftest.audius.co%2Fvincent.m3u8&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOnRydWUsImR1bXBmTVA0IjpmYWxzZSwibGV2ZWxDYXBwaW5nIjotMSwibGltaXRNZXRyaWNzIjotMX0=
[x] The issue occurs in the latest client on https://hls-js-dev.netlify.com/demo and not just on my page
https://hls-js-dev.netlify.app/demo/?src=https%3A%2F%2Fs3-us-west-1.amazonaws.com%2Ftest.audius.co%2Fvincent.m3u8&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOnRydWUsImR1bXBmTVA0IjpmYWxzZSwibGV2ZWxDYXBwaW5nIjotMSwibGltaXRNZXRyaWNzIjotMX0=
[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

Please provide clear steps to reproduce your problem

a. Visit test stream
https://hls-js.netlify.com/demo and not just on my page
https://hls-js.netlify.app/demo/?src=https%3A%2F%2Fs3-us-west-1.amazonaws.com%2Ftest.audius.co%2Fvincent.m3u8&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOnRydWUsImR1bXBmTVA0IjpmYWxzZSwibGV2ZWxDYXBwaW5nIjotMSwibGltaXRNZXRyaWNzIjotMX0=

b. scrub audio to ~10 minutes

c. stream stops (fragments not even attempted to be fetched?), state goes from PARSED->IDLE

d. this issue does no happen if you first seek to ~1hr and then seek back to 10min.

If the bug is intermittent, give a rough frequency
100% of the time

Expected behavior

What you expected to happen

The stream should seek

Actual behavior

What actually happened

The audio stops. No errors. No interesting log messages.

Console output

Paste the contents of the browser console here.

Using Hls.js config: {debug: true, enableWorker: true, liveBackBufferLength: 900}
logger.js:40 [log] > loadSource:https://s3-us-west-1.amazonaws.com/test.audius.co/vincent.m3u8
logger.js:40 [debug] > Loading playlist of type manifest, level: 0, id: null
logger.js:40 [debug] > Calling internal loader delegate for URL: https://s3-us-west-1.amazonaws.com/test.audius.co/vincent.m3u8
logger.js:40 [log] > trigger BUFFER_RESET
logger.js:40 [log] > set autoLevelCapping:-1
logger.js:40 [log] > attachMedia
logger.js:40 [log] > media source opened
logger.js:40 [log] > manifest loaded,1 level(s) found, first bitrate:undefined
logger.js:40 [log] > 1 bufferCodec event(s) expected
logger.js:40 [log] > startLoad(-1)
logger.js:40 [log] > switching to level 0
logger.js:40 [log] > main stream-controller: STOPPED->IDLE
logger.js:40 [log] > audio tracks updated
logger.js:40 [log] > subtitle tracks updated
logger.js:40 [log] > level 0 loaded [0,1072],duration:6437.873034999932
logger.js:40 [log] > Loading 0 of [0-1072], level 0, nextLoadPosition: 0, bufferEnd: 0
logger.js:40 [log] > demuxing in webworker
logger.js:40 [log] > main stream-controller: IDLE->FRAG_LOADING
logger.js:40 [log] > Loaded 0 of [0 ,1072],level 0
logger.js:40 [log] > Parsing 0 of [0 ,1072],level 0, cc 0
logger.js:40 [log] > main stream-controller: FRAG_LOADING->PARSING
logger.js:40 [log] > main:discontinuity detected
logger.js:40 [log] > main:switch detected
1c0f500f-b9ab-4d99-b008-26fb9a418b09:562 [log] > manifest codec:undefined,ADTS data:type:2,sampleingIndex:3[48000Hz],channelConfig:2
1c0f500f-b9ab-4d99-b008-26fb9a418b09:562 [log] > parsed codec:mp4a.40.5,rate:48000,nb channel:2
1c0f500f-b9ab-4d99-b008-26fb9a418b09:562 [log] > audio sampling rate : 48000
logger.js:40 [log] > InitPTS for cc: 0 found from main: 126000
logger.js:40 [log] > creating sourceBuffer(audio/mp4;codecs=mp4a.40.5)
logger.js:40 [log] > main track:audio,container:audio/mp4,codecs[level/parsed]=[undefined/mp4a.40.5]
logger.js:40 [log] > Parsed audio,PTS:[0.000,6.016],DTS:[0.000/6.016],nb:282,dropped:0
logger.js:40 [log] > main stream-controller: PARSING->PARSED
logger.js:40 [log] > main buffered : [0.000,6.016]
logger.js:40 [log] > latency/loading/parsing/append/kbps:84/70/14/8/9858
logger.js:40 [log] > main stream-controller: PARSED->IDLE
logger.js:40 [log] > Loading 1 of [0-1072], level 0, nextLoadPosition: 6.016, bufferEnd: 6.016
logger.js:40 [log] > main stream-controller: IDLE->FRAG_LOADING
logger.js:40 [log] > Updating Media Source duration to 6437.873
favicon.ico:1 GET https://hls-js.netlify.app/favicon.ico 404
logger.js:40 [log] > Loaded 1 of [0 ,1072],level 0
logger.js:40 [log] > Parsing 1 of [0 ,1072],level 0, cc 0
logger.js:40 [log] > main stream-controller: FRAG_LOADING->PARSING
logger.js:40 [log] > Parsed audio,PTS:[6.016,12.011],DTS:[6.016/12.011],nb:281,dropped:0
logger.js:40 [log] > main stream-controller: PARSING->PARSED
logger.js:40 [log] > main buffered : [0.000,12.011]
logger.js:40 [log] > latency/loading/parsing/append/kbps:47/67/6/1/15424
logger.js:40 [log] > main stream-controller: PARSED->IDLE
logger.js:40 [log] > Loading 2 of [0-1072], level 0, currentTime: 0.023, bufferEnd: 12.011
logger.js:40 [log] > main stream-controller: IDLE->FRAG_LOADING
logger.js:40 [log] > Loaded 2 of [0 ,1072],level 0
logger.js:40 [log] > Parsing 2 of [0 ,1072],level 0, cc 0
logger.js:40 [log] > main stream-controller: FRAG_LOADING->PARSING
logger.js:40 [log] > Parsed audio,PTS:[12.011,18.005],DTS:[12.011/18.005],nb:281,dropped:0
logger.js:40 [log] > main stream-controller: PARSING->PARSED
logger.js:40 [log] > main buffered : [0.000,18.005]
logger.js:40 [log] > latency/loading/parsing/append/kbps:44/77/6/2/16517
logger.js:40 [log] > main stream-controller: PARSED->IDLE
logger.js:40 [log] > Loading 3 of [0-1072], level 0, currentTime: 0.13, bufferEnd: 18.005
logger.js:40 [log] > main stream-controller: IDLE->FRAG_LOADING
inpage.js:1 MetaMask: MetaMask will soon stop reloading pages on network change.
For more information, see: https://docs.metamask.io/guide/ethereum-provider.html#ethereum-autorefreshonnetworkchange 
Set 'ethereum.autoRefreshOnNetworkChange' to 'false' to silence this warning.
(anonymous) @ inpage.js:1
setTimeout (async)
t.exports @ inpage.js:1
initProvider @ inpage.js:1
(anonymous) @ inpage.js:1
1../lib/setupWeb3.js @ inpage.js:1
i @ inpage.js:1
e @ inpage.js:1
(anonymous) @ inpage.js:1
(anonymous) @ contentscript.js:1
1.@babel/runtime/helpers/interopRequireDefault @ contentscript.js:1
i @ contentscript.js:1
e @ contentscript.js:1
(anonymous) @ contentscript.js:1
logger.js:40 [log] > Loaded 3 of [0 ,1072],level 0
logger.js:40 [log] > Parsing 3 of [0 ,1072],level 0, cc 0
logger.js:40 [log] > main stream-controller: FRAG_LOADING->PARSING
logger.js:40 [log] > Parsed audio,PTS:[18.005,24.000],DTS:[18.005/24.000],nb:281,dropped:0
logger.js:40 [log] > main stream-controller: PARSING->PARSED
logger.js:40 [log] > main buffered : [0.000,24.000]
logger.js:40 [log] > latency/loading/parsing/append/kbps:45/75/6/1/16359
logger.js:40 [log] > main stream-controller: PARSED->IDLE
logger.js:40 [log] > Loading 4 of [0-1072], level 0, currentTime: 0.259, bufferEnd: 24
logger.js:40 [log] > main stream-controller: IDLE->FRAG_LOADING
logger.js:40 [log] > Loaded 4 of [0 ,1072],level 0
logger.js:40 [log] > Parsing 4 of [0 ,1072],level 0, cc 0
logger.js:40 [log] > main stream-controller: FRAG_LOADING->PARSING
logger.js:40 [log] > Parsed audio,PTS:[24.000,30.016],DTS:[24.000/30.016],nb:282,dropped:0
logger.js:40 [log] > main stream-controller: PARSING->PARSED
logger.js:40 [log] > main buffered : [0.000,30.016]
logger.js:40 [log] > latency/loading/parsing/append/kbps:50/64/8/3/16715
logger.js:40 [log] > main stream-controller: PARSED->IDLE
logger.js:40 [log] > Loading 5 of [0-1072], level 0, currentTime: 0.387, bufferEnd: 30.016
logger.js:40 [log] > main stream-controller: IDLE->FRAG_LOADING
logger.js:40 [log] > Loaded 5 of [0 ,1072],level 0
logger.js:40 [log] > Parsing 5 of [0 ,1072],level 0, cc 0
logger.js:40 [log] > main stream-controller: FRAG_LOADING->PARSING
logger.js:40 [log] > Parsed audio,PTS:[30.016,36.011],DTS:[30.016/36.011],nb:281,dropped:0
logger.js:40 [log] > main stream-controller: PARSING->PARSED
logger.js:40 [log] > main buffered : [0.000,36.011]
logger.js:40 [log] > latency/loading/parsing/append/kbps:48/69/6/2/16705
logger.js:40 [log] > main stream-controller: PARSED->IDLE
logger.js:40 [log] > media seeking to 901.061
logger.js:40 [log] > Loading 150 of [0-1072], level 0, currentTime: 901.061, bufferEnd: 901.061
logger.js:40 [log] > main stream-controller: IDLE->FRAG_LOADING
logger.js:40 [log] > media seeking to 901.061
logger.js:40 [log] > Loaded 150 of [0 ,1072],level 0
logger.js:40 [log] > Parsing 150 of [0 ,1072],level 0, cc 0
logger.js:40 [log] > main stream-controller: FRAG_LOADING->PARSING
logger.js:40 [log] > Parsed audio,PTS:[6270.016,6276.011],DTS:[6270.016/6276.011],nb:281,dropped:0
logger.js:40 [log] > main stream-controller: PARSING->PARSED
logger.js:40 [log] > main buffered : [0.000,36.011][6270.016,6276.011]
logger.js:40 [log] > latency/loading/parsing/append/kbps:91/74/6/2/12016
logger.js:40 [log] > main stream-controller: PARSED->IDLE

For media errors reported on Chrome browser, please also paste the output of chrome://media-internals


0.000 | kWebMediaPlayerCreated | {origin_url: "https://hls-js.netlify.app/"}
-- | -- | --
0.000 | kLoad | {url: "blob:https://hls-js.netlify.app/000324e0-c2dd-43ab-a2c8-cfc88faa993b"}
0.000 | kPipelineStateChange | {pipeline_state: "kStarting"}
0.527 | kPipelineStateChange | {pipeline_state: "kPlaying"}
0.527 | kBufferingStateChanged | {audio_buffering_state: {state: "BUFFERING_HAVE_ENOUGH"}}
0.539 | kBufferingStateChanged | {pipeline_buffering_state: {for_suspended_start: false, state: "BUFFERING_HAVE_ENOUGH"}}
0.538 | kDurationChanged | {duration: 6437.873034}
16.851 | kPipelineStateChange | {pipeline_state: "kSuspending"}
16.852 | kPipelineStateChange | {pipeline_state: "kSuspended"}
16.852 | kSuspended | {}
25.795 | kPlay | {}
25.795 | kPipelineStateChange | {pipeline_state: "kResuming"}
25.800 | kPipelineStateChange | {pipeline_state: "kPlaying"}
25.801 | kBufferingStateChanged | {audio_buffering_state: {state: "BUFFERING_HAVE_ENOUGH"}}
25.801 | kBufferingStateChanged | {pipeline_buffering_state: {for_suspended_start: false, state: "BUFFERING_HAVE_ENOUGH"}}
33.567 | kPause | {}
33.642 | kSeek | {seek_target: 0}
33.642 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.642 | kBufferingStateChanged | {audio_buffering_state: {state: "BUFFERING_HAVE_NOTHING"}}
33.642 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.644 | kBufferingStateChanged | {audio_buffering_state: {state: "BUFFERING_HAVE_ENOUGH"}}
33.645 | kBufferingStateChanged | {pipeline_buffering_state: {for_suspended_start: false, state: "BUFFERING_HAVE_ENOUGH"}}
33.667 | kSeek | {seek_target: 18.663409}
33.667 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.667 | kBufferingStateChanged | {audio_buffering_state: {state: "BUFFERING_HAVE_NOTHING"}}
33.667 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.669 | kBufferingStateChanged | {audio_buffering_state: {state: "BUFFERING_HAVE_ENOUGH"}}
33.674 | kBufferingStateChanged | {pipeline_buffering_state: {for_suspended_start: false, state: "BUFFERING_HAVE_ENOUGH"}}
33.674 | kSeek | {seek_target: 40.939092}
33.674 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.674 | kBufferingStateChanged | {audio_buffering_state: {state: "BUFFERING_HAVE_NOTHING"}}
33.674 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.675 | kBufferingStateChanged | {audio_buffering_state: {state: "BUFFERING_HAVE_ENOUGH"}}
33.675 | kBufferingStateChanged | {pipeline_buffering_state: {for_suspended_start: false, state: "BUFFERING_HAVE_ENOUGH"}}
33.682 | kSeek | {seek_target: 82.680913}
33.682 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.682 | kBufferingStateChanged | {audio_buffering_state: {state: "BUFFERING_HAVE_NOTHING"}}
33.690 | kSeek | {seek_target: 136.262961}
33.691 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.695 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.698 | kSeek | {seek_target: 189.644327}
33.698 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.703 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.706 | kSeek | {seek_target: 243.226375}
33.706 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.711 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.715 | kSeek | {seek_target: 295.805014}
33.715 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.719 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.723 | kSeek | {seek_target: 318.080697}
33.723 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.727 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.731 | kSeek | {seek_target: 371.662745}
33.731 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.740 | kSeek | {seek_target: 413.404565}
33.741 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.750 | kSeek | {seek_target: 466.785931}
33.750 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.760 | kSeek | {seek_target: 497.690932}
33.761 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.769 | kSeek | {seek_target: 528.997298}
33.769 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.776 | kSeek | {seek_target: 570.739118}
33.781 | kSeek | {seek_target: 593.014801}
33.781 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.791 | kSeek | {seek_target: 623.919802}
33.791 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.795 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.796 | kSeek | {seek_target: 646.195485}
33.796 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.800 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.804 | kSeek | {seek_target: 577.310928}
33.805 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.809 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.813 | kSeek | {seek_target: 592.192177}
33.813 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.816 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.822 | kSeek | {seek_target: 705.396624}
33.823 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.826 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.831 | kSeek | {seek_target: 641.814055}
33.831 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.835 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.838 | kSeek | {seek_target: 633.166576}
33.838 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.843 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.846 | kSeek | {seek_target: 648.047825}
33.846 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.856 | kSeek | {seek_target: 656.60964}
33.856 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.865 | kSeek | {seek_target: 665.171454}
33.865 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.873 | kSeek | {seek_target: 680.052703}
33.875 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.882 | kSeek | {seek_target: 700.401202}
33.882 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.888 | kSeek | {seek_target: 708.945161}
33.895 | kSeek | {seek_target: 717.285692}
33.895 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.903 | kSeek | {seek_target: 725.829651}
33.903 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.909 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.911 | kSeek | {seek_target: 722.454071}
33.911 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.914 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.919 | kSeek | {seek_target: 730.812033}
33.919 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.925 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.931 | kSeek | {seek_target: 739.373848}
33.931 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.935 | kSeek | {seek_target: 743.043197}
33.935 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.943 | kSeek | {seek_target: 751.401159}
33.943 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.947 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.951 | kSeek | {seek_target: 755.070508}
33.951 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.952 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.959 | kSeek | {seek_target: 758.536004}
33.959 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.963 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.967 | kSeek | {seek_target: 762.205353}
33.967 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.968 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.975 | kSeek | {seek_target: 765.67085}
33.975 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.979 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.984 | kSeek | {seek_target: 769.340199}
33.984 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.989 | kPipelineStateChange | {pipeline_state: "kSeeking"}
33.992 | kSeek | {seek_target: 772.805695}
33.992 | kPipelineStateChange | {pipeline_state: "kPlaying"}
33.993 | kPipelineStateChange | {pipeline_state: "kSeeking"}
34.008 | kSeek | {seek_target: 776.067339}
34.008 | kPipelineStateChange | {pipeline_state: "kPlaying"}
34.012 | kPipelineStateChange | {pipeline_state: "kSeeking"}
34.065 | kSeek | {seek_target: 778.921277}
34.065 | kPipelineStateChange | {pipeline_state: "kPlaying"}
34.067 | kPipelineStateChange | {pipeline_state: "kSeeking"}
34.487 | kPlay | {}No properties

Bug Confirmed Stream Issue

Source

raymondjacobson

👍5 👀2 😕2

All 15 comments

FWIW, I've tried v1.0.0-alpha.1 which I've seen on some issues suggest maybe has reworked logic. The logs are definitely more interesting, but still not working
localhost-1603347016244.log

It's also a bit worse because it seems that seeking anywhere doesn't work, rather than just the 12-18 minute mark in the versions tested above.

I've also tried tweaking maxFragLookUpTolerance to several different values to no avail. It seems as if this log line https://github.com/video-dev/hls.js/blob/a7ad4aba0b3e5a65160d123c1dd7337206c2d940/src/controller/audio-stream-controller.js#L267 repeatedly gets printed as if we are reparsing the same segment over and over again.

raymondjacobson on 22 Oct 2020

Hey, I'm going to piggyback onto this issue because I think mine is the same/related.

@ffxsam Please do not.

File a new issue with your test stream, browser, and OS (your issue is isolated to Safari?) and steps to reproduce. We can link the issues to track progress.

robwalch on 23 Oct 2020

👍1

HI @raymondjacobson,

It seems as if this log line repeatedly gets printed as if we are reparsing the same segment over and over again.

So that happens after changing maxFragLookUpTolerance or always? The title says "no logs".

robwalch on 23 Oct 2020

Screen Shot 2020-10-23 at 12 33 54 PM

Appears to be an issue with segment duration calculation / timeline adjustments. Are the durations in your manifest accurate? Does your stream contain any unmarked discontinuities?

robwalch on 23 Oct 2020

@robwalch Sure, sorry about that. Just filed a new issue.

ffxsam on 23 Oct 2020

Interesting. So -- yea it does the repeated log spam after upping maxFragLookupTolerance. In the hls-dev test site, I don't see any interesting logs, it just freezes.

The durations in the manifest are accurate as to what ffmpeg spit out from creating the hls files. & The stream should not contain any unmarked discontinuities. I can spend some time trying to verify there. What does the negative duration suggest here?

raymondjacobson on 23 Oct 2020

We recently had a similar bug reported where the audio segments were actually twice as long as stated in the manifest. Issues where seeking ahead negatively impact the timeline are usually associated with parsed timecode not matching the playlist, an error in parsing, or an error in handling of rollover in the timecode.

robwalch on 24 Oct 2020

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs.

stale[bot] on 15 Nov 2020

Please confirm you can reproduce the issue in v0.14.16 and update the steps to reproduce if needed. I just followed the steps and could not repo. Is there something I am missing?

robwalch on 16 Nov 2020

Hey @robwalch this doesn't look to be fixed on 0.14.16.

https://hls-js.netlify.app/demo/?src=https%3A%2F%2Fs3-us-west-1.amazonaws.com%2Ftest.audius.co%2Fvincent.m3u8&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOnRydWUsImR1bXBmTVA0IjpmYWxzZSwibGV2ZWxDYXBwaW5nIjotMSwibGltaXRNZXRyaWNzIjotMX0=

If you scrub to, for example 11:46, audio stops.

raymondjacobson on 16 Nov 2020

👍1

Hi @raymondjacobson,

If you scrub to, for example 11:46, audio stops.
https://hls-js.netlify.app/demo/?src=https%3A%2F%2Fs3-us-west-1.amazonaws.com%2Ftest.audius.co%2Fvincent.m3u8&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOnRydWUsImR1bXBmTVA0IjpmYWxzZSwibGV2ZWxDYXBwaW5nIjotMSwibGltaXRNZXRyaWNzIjotMX0=

It looks like you have an unmarked DISCONTINUITY in that stream somewhere around the 10 minute mark. When hls.js seeks to this point, it depends on the segment timestamps being accurate and appends media based on those timestamps not the playlist. It then realigns the other segments in the playlist to the parsed media which creates the errors we're seeing in your stream.

sn 117 for example should have PTS starting at around 702s, but instead we get something more like 6200s.

In the mp4-remuxer we arrive here, accurateTimeOffset and contiguous are false because we seeked to a new location in the stream that has not been previously parsed. nextAudioPts uses the input pts and the new value over inputTimeScale is much larger than timeOffset.

      } else if (accurateTimeOffset) {
        // When not seeking, not live, and LevelDetails.PTSKnown, use fragment start as predicted next audio PTS
        nextAudioPts = Math.max(0, timeOffset * inputTimeScale);
      } else {
        // if frags are not contiguous and if we cant trust time offset, let's use first sample PTS as next audio PTS
        nextAudioPts = inputSamples[0].pts;
      }
    }

This indicates a missing DISCONTINUITY.

robwalch on 20 Nov 2020

Hi @raymondjacobson,

It looks like you have an unmarked DISCONTINUITY in that stream somewhere around the 5 minute mark. When hls.js seeks to this point, it depends on the segment timestamps being accurate and appends media based on those timestamps not the playlist. It then realigns the other segments in the playlist to the parsed media which creates the errors we're seeing in your stream. sn 117 for example should have PTS starting at around 702s, but instead we get something more like 6200s.

Gotcha. I guess that makes sense. I'm a bit unclear as to how FFMPEG generated this corrupt output and also how native HLS systems (e.g. iOS) are able to play this end-to-end without any hiccups. Unfortunately, regenerating the segments in this particular situation isn't something we can do, so this DISCONTINUITY continues to live on :-/

Can you think of any way we can coerce hls.js to skip over the discontinuity or something like that? Nudging didn't seem to work, but maybe there's some else that can be done?

Thanks for digging for me :)

raymondjacobson on 20 Nov 2020

Can you think of any way we can coerce hls.js to skip over the discontinuity or something like that? Nudging didn't seem to work, but maybe there's some else that can be done?

No, once the timeline is mangled like this, hls.js will have trouble buffering the rest of the stream. Take a look at the 'Timeline' in the demo page - you'll see what I'm talking about and may get an idea on how to seek past it.

I might look at preventing hls.js from altering the duration of other segments based on the parsed starting time of others. This would likely lead to other issues. If hls.js just used the playlist times without altering them to fetch media, it could also get stuck or request the wrong segments when media timestamps do not match the playlist times.

I think best short term fix would to force accurateTimeOffset to be true via a config option. That would help with streams where we want to ignore parsed PTS and just append according to playlist time.

I'm not sure how Safari is handling it.

robwalch on 20 Nov 2020

To be really specific there seems to be an issue with sn 111 and after that the PTS values hls.js is parsing are higher than expected. Maybe ffmpeg is superstitious.

hls.js:4410 [warn] > Fragments must have at least one ElementaryStreamType set. type: main level: 0 sn: 111

I tried v0.12.4 and same issue. This is not a regression.

robwalch on 20 Nov 2020

Removing the seeking check would "fix" handling of the stream issue. Check out the build on acb91db. I'm not sure I want to include this in 0.15.0. There might be side effects with other streams, but we should be handling seeks that jump the sn sequence as not contiguous. We might just decide to use the media timestamp in that case and this breaks again. Either way I think this is a good change as work in 0.14 was all about making append times more deterministic. This might break that, but behavior looks more inline with Safari.

robwalch on 20 Nov 2020

Was this page helpful?

0 / 5 - 0 ratings