Intermittent playback failures when playing audio / video demuxed content

kqyang commented 5 years ago

What version of Hls.js are you using?

Latest.

What browser and OS are you using?

Chrome on Linux

Test stream:

https://csireb-test-8000.connectmedia.hu/h264_master.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
[x] The issue occurs in the latest client on https://hls-js-latest.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

Please provide clear steps to reproduce your problem

Goto https://hls-js.netlify.com/demo/?src=https%3A%2F%2Fcsireb-test-8000.connectmedia.hu%2Fh264_master.m3u8.

If the bug is intermittent, give a rough frequency

About 1 out of 5 times.

Expected behavior

Live stream starts playing.

The same content works with any other hls players without troubles (I have tried with bitmovin player https://bitmovin.com/demos/stream-test, theo player https://demo.theoplayer.com/test-your-stream-with-statistics and kaltura playerhttp://player.kaltura.com/modules/KalturaSupport/tests/HLSPlaybackTester.html).

Actual behavior

The stream fails to start.

Console output

Seeing a lot of "dropping 1 audio frame @ due to xxx ms overlap". There aren't really any overlap in the audio stream. Also, the audio is synced to the video.

logger.js:40 [log] > trying to update audio-track 0
logger.js:40 [log] > loading audio-track playlist for id: 0
logger.js:40 [log] > Parsed video,PTS:[66.000,72.000],DTS:[65.920/71.920],nb:150,dropped:0
logger.js:40 [log] > main stream:PARSING->PARSED
logger.js:40 [log] > main buffered : [42.000,72.000]
logger.js:40 [log] > latency/loading/parsing/append/kbps:343/838/22/3/7203
logger.js:40 [log] > main stream:PARSED->IDLE
logger.js:40 [log] > Loading 38621, cc: 0 of [38621 ,38631],track 0, currentTime:45,bufferEnd:45.000
logger.js:40 [log] > Loading 38621, cc: 0 of [38621 ,38631],track 0, currentTime:45,bufferEnd:45.000
logger.js:40 [log] > track 0 loaded [38622,38632],duration:66.008
logger.js:40 [log] > live audio playlist sliding:34960.902
logger.js:40 [log] > Loading 38622, cc: 0 of [38622 ,38632],track 0, currentTime:45,bufferEnd:45.000
logger.js:40 [log] > audio stream:IDLE->FRAG_LOADING
logger.js:40 [log] > audioTrack 0 loaded
logger.js:40 [log] > audio stream:FRAG_LOADING->PARSING
logger.js:40 [log] > Demuxing 38622 of [38622 ,38632],track 0
blob:https://hls-js.…3b-f67958788c3f:499 [warn] > Dropping 1 audio frame @ 34960.902s due to 34960892 ms overlap.
(anonymous) @ blob:https://hls-js.…3b-f67958788c3f:499
MP4Remuxer.remuxAudio @ blob:https://hls-js.…b-f67958788c3f:1274
MP4Remuxer.remux @ blob:https://hls-js.…3b-f67958788c3f:892
AACDemuxer.append @ blob:https://hls-js.…b-f67958788c3f:5207
DemuxerInline.pushDecrypted @ blob:https://hls-js.…3b-f67958788c3f:779
DemuxerInline.push @ blob:https://hls-js.…3b-f67958788c3f:730
(anonymous) @ blob:https://hls-js.…3b-f67958788c3f:119
blob:https://hls-js.…3b-f67958788c3f:499 [warn] > Dropping 1 audio frame @ 34960.902s due to 34960870 ms overlap.
(anonymous) @ blob:https://hls-js.…3b-f67958788c3f:499
MP4Remuxer.remuxAudio @ blob:https://hls-js.…b-f67958788c3f:1274
MP4Remuxer.remux @ blob:https://hls-js.…3b-f67958788c3f:892
AACDemuxer.append @ blob:https://hls-js.…b-f67958788c3f:5207
DemuxerInline.pushDecrypted @ blob:https://hls-js.…3b-f67958788c3f:779
DemuxerInline.push @ blob:https://hls-js.…3b-f67958788c3f:730
(anonymous) @ blob:https://hls-js.…3b-f67958788c3f:119
blob:https://hls-js.…3b-f67958788c3f:499 [warn] > Dropping 1 audio frame @ 34960.902s due to 34960849 ms overlap.
...
(anonymous) @ blob:https://hls-js.netlify.com/bfac0b06-c763-477e-923b-f67958788c3f:499
MP4Remuxer.remuxAudio @ blob:https://hls-js.netlify.com/bfac0b06-c763-477e-923b-f67958788c3f:1274
MP4Remuxer.remux @ blob:https://hls-js.netlify.com/bfac0b06-c763-477e-923b-f67958788c3f:892
AACDemuxer.append @ blob:https://hls-js.netlify.com/bfac0b06-c763-477e-923b-f67958788c3f:5207
DemuxerInline.pushDecrypted @ blob:https://hls-js.netlify.com/bfac0b06-c763-477e-923b-f67958788c3f:779
DemuxerInline.push @ blob:https://hls-js.netlify.com/bfac0b06-c763-477e-923b-f67958788c3f:730
(anonymous) @ blob:https://hls-js.netlify.com/bfac0b06-c763-477e-923b-f67958788c3f:119
main.js:554 Error event: {type: "otherError", details: "internalException", fatal: true, event: "demuxerWorker", err: {…}}
(anonymous) @ main.js:554
emit @ index.js:203
./src/observer.js.Observer.trigger @ observer.js:20
Demuxer.w.onerror @ demuxer.js:58
error (async)
Demuxer @ demuxer.js:57

itsjamie commented 5 years ago

Thank you for the report @kqyang.

I imagine the first step would be to analyze the source stream to compare against what hls.js is computing as the timestamps when remuxing. If you could retrieve a snapshot of the livestream when you run into the error that would really help understand what's happening.

stale[bot] commented 5 years ago

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

video-dev / hls.js