From 69d5e541c05638bd7fa89bfba786097009c3cd56 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Tue, 3 Sep 2019 22:36:49 +0200 Subject: [PATCH 01/42] gap-controller: fix logic and improve behavior in edge cases use waiting and stalled events additionnaly for stall detection refactor logic split fix for startup stalls of livestreams fix for sound missing on edge on startup when audio gaps occuring fix for issue #2323 and other related document all initalized members in constructor document better polling logic --- src/controller/gap-controller.js | 209 ++++++++++++++++++++++++++----- 1 file changed, 177 insertions(+), 32 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index 8e67ede8bba..b16cf0b1647 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -2,9 +2,12 @@ import { BufferHelper } from '../utils/buffer-helper'; import { ErrorTypes, ErrorDetails } from '../errors'; import Event from '../events'; import { logger } from '../utils/logger'; +import { isFiniteNumber } from '../polyfills/number-isFinite'; -const stallDebounceInterval = 1000; -const jumpThreshold = 0.5; // tolerance needed as some browsers stalls playback before reaching buffered range end +export const STALL_DEBOUNCE_INTERVAL_MS = 1000; +export const STALL_HANDLING_RETRY_PERIOD_MS = 1000; +export const JUMP_THRESHOLD_SECONDS = 0.5; // tolerance needed as some browsers stalls playback before reaching buffered range end +export const SKIP_BUFFER_HOLE_STEP_SECONDS = 0.1; export default class GapController { constructor (config, media, fragmentTracker, hls) { @@ -12,76 +15,217 @@ export default class GapController { this.media = media; this.fragmentTracker = fragmentTracker; this.hls = hls; + + /** + * @private @member {boolean} + */ this.stallReported = false; + + /** + * @private @member {number | null} + */ + this.stallDetectedAtTime = null; + + /** + * @private @member {number | null} + */ + this.stallHandledAtTime = null; + + /** + * @private @member {number | null} + */ + this.currentPlayheadTime = null; + + /** + * @private @member {boolean} + */ + this.hasPlayed = false; + + /** + * @private @member {EventListener} + */ + this.onMediaStalled = null; + } + + destroy () { + if (this.onMediaStalled) { + this.media.removeEventListener('waiting', this.onMediaStalled); + this.media.removeEventListener('stalled', this.onMediaStalled); + } } /** * Checks if the playhead is stuck within a gap, and if so, attempts to free it. * A gap is an unbuffered range between two buffered ranges (or the start and the first buffered range). - * @param lastCurrentTime - * @param buffered + * + * @param {number} previousPlayheadTime Previously read playhead position */ - poll (lastCurrentTime, buffered) { - const { config, media } = this; - const currentTime = media.currentTime; - const tnow = window.performance.now(); - - if (currentTime !== lastCurrentTime) { - // The playhead is now moving, but was previously stalled - if (this.stallReported) { - logger.warn(`playback not stuck anymore @${currentTime}, after ${Math.round(tnow - this.stalled)}ms`); - this.stallReported = false; + poll (previousPlayheadTime) { + if (!this.hasPlayed) { + if (!isFiniteNumber(this.media.currentTime) || this.media.buffered.length === 0) { + return; + } + // Need to check what the buffer reports as start time for the first fragment appended. + // If within the threshold of maxBufferHole, adjust this.startPosition for _seekToStartPos(). + const firstBufferedPosition = this.media.buffered.start(0); + if (Math.abs(this.media.currentTime - firstBufferedPosition) < this.config.maxBufferHole) { + if (!this.media.seeking) { + logger.warn('skipping over buffer hole on startup (first segment starts partially later than assumed)'); + this.media.currentTime = firstBufferedPosition + SKIP_BUFFER_HOLE_STEP_SECONDS; + } } - this.stalled = null; - this.nudgeRetry = 0; + } + + // if we are paused and played before, don't bother at all + if (this.hasPlayed && this.media.paused) { return; } - if (media.ended || !media.buffered.length || media.readyState > 2) { + // The playhead is moving, no-op + if (this._checkPlayheadHasMoved(previousPlayheadTime)) { return; } - if (media.seeking && BufferHelper.isBuffered(media, currentTime)) { + // not moving ... check if we need to handle stall + if (this.stallDetectedAtTime !== null || this._isMediaInPlayableState()) { + this._handleStall(); + } + } + + _checkPlayheadHasMoved (previousPlayheadTime) { + const media = this.media; + + // read current playhead position + const currentPlayheadTime = media.currentTime; + // update internal store + this.currentPlayheadTime = currentPlayheadTime; + + // not moved - return false here + if (currentPlayheadTime === previousPlayheadTime) { + return false; + } + + // has moved ... - will return true from here + // but need to (re-)init internal state + + this.hasPlayed = true; + + // lazy setup media event listeners if not done yet + if (!this.onMediaStalled) { + this.onMediaStalled = this._onMediaStalled.bind(this); + this.media.addEventListener('waiting', this.onMediaStalled); + this.media.addEventListener('stalled', this.onMediaStalled); + } + + // we can return early here to be lazy on rewriting other member values + if (this.stallDetectedAtTime === null) { + return true; + } + + logger.log(`playhead seemed stalled but is now moving again from ${previousPlayheadTime} to ${currentPlayheadTime}`); + + // reset all the stall flags + this.stallHandledAtTime = null; + this.stallDetectedAtTime = null; + this.nudgeRetry = 0; + + // If it was reported stalled, let's log the recovery + if (this.stallReported) { + const now = window.performance.now(); + const currentPlayheadTime = this.media.currentTime; + logger.warn(`playhead not stalled anymore @${currentPlayheadTime}, after ${(now - this.stallDetectedAtTime)} ms`); + + this.stallReported = false; + } + + return true; + } + + _isMediaInPlayableState () { + const currentPlayheadTime = this.currentPlayheadTime; + const media = this.media; + if (media.ended || !media.buffered.length || media.readyState <= 2) { + return false; + } else if (media.seeking && !BufferHelper.isBuffered(media, currentPlayheadTime)) { + return false; + } else { + return true; + } + } + + _onMediaStalled () { + const media = this.media; + if (media.readyState < 2) { return; } + if (BufferHelper.isBuffered(media, media.currentTime)) { + this._handleStall(); + } + } + + _handleStall () { + const now = window.performance.now(); + const media = this.media; + + if (this.stallHandledAtTime !== null && + now - this.stallHandledAtTime < STALL_HANDLING_RETRY_PERIOD_MS) { + return; + } + + this.stallHandledAtTime = now; + // The playhead isn't moving but it should be // Allow some slack time to for small stalls to resolve themselves - const stalledDuration = tnow - this.stalled; - const bufferInfo = BufferHelper.bufferInfo(media, currentTime, config.maxBufferHole); - if (!this.stalled) { - this.stalled = tnow; + const currentPlayheadTime = media.currentTime; + const bufferInfo = BufferHelper.bufferInfo(media, currentPlayheadTime, this.config.maxBufferHole); + + logger.warn(`Stall detected at playhead position ${currentPlayheadTime}, buffered-time-ranges info: ${JSON.stringify(bufferInfo)}`); + + if (!this.stallDetectedAtTime) { + logger.warn('Silently ignoring first detected stall within grace period, storing timestamp: ' + now); + this.stallDetectedAtTime = now; return; - } else if (stalledDuration >= stallDebounceInterval) { + } + + const stalledDurationMs = now - this.stallDetectedAtTime; + if (stalledDurationMs >= STALL_DEBOUNCE_INTERVAL_MS) { + logger.warn('Stall detected after grace period, reporting error'); // Report stalling after trying to fix this._reportStall(bufferInfo.len); } - this._tryFixBufferStall(bufferInfo, stalledDuration); + this._tryFixBufferStall(bufferInfo, stalledDurationMs); } /** * Detects and attempts to fix known buffer stalling issues. * @param bufferInfo - The properties of the current buffer. - * @param stalledDuration - The amount of time Hls.js has been stalling for. + * @param stalledDurationMs - The amount of time Hls.js has been stalling for. * @private */ - _tryFixBufferStall (bufferInfo, stalledDuration) { + _tryFixBufferStall (bufferInfo, stalledDurationMs) { + logger.warn('Trying to fix stalled playhead on buffered time-range ...'); + const { config, fragmentTracker, media } = this; - const currentTime = media.currentTime; + const playheadTime = media.currentTime; - const partial = fragmentTracker.getPartialFragment(currentTime); + const partial = fragmentTracker.getPartialFragment(playheadTime); if (partial) { + logger.log('Trying to skip buffer-hole caused by partial fragment'); // Try to skip over the buffer hole caused by a partial fragment // This method isn't limited by the size of the gap between buffered ranges this._trySkipBufferHole(partial); + return; } - if (bufferInfo.len > jumpThreshold && stalledDuration > config.highBufferWatchdogPeriod * 1000) { + if (bufferInfo.len > JUMP_THRESHOLD_SECONDS && + stalledDurationMs > config.highBufferWatchdogPeriod * 1000) { + logger.log('Trying to nudge playhead over buffer-hole'); // Try to nudge currentTime over a buffer hole if we've been stalling for the configured amount of seconds // We only try to jump the hole if it's under the configured size // Reset stalled so to rearm watchdog timer - this.stalled = null; + this.stallDetectedAtTime = null; this._tryNudgeBuffer(); } } @@ -119,9 +263,9 @@ export default class GapController { for (let i = 0; i < media.buffered.length; i++) { let startTime = media.buffered.start(i); if (currentTime >= lastEndTime && currentTime < startTime) { - media.currentTime = Math.max(startTime, media.currentTime + 0.1); + media.currentTime = Math.max(startTime, media.currentTime + SKIP_BUFFER_HOLE_STEP_SECONDS); logger.warn(`skipping hole, adjusting currentTime from ${currentTime} to ${media.currentTime}`); - this.stalled = null; + this.stallDetectedAtTime = null; hls.trigger(Event.ERROR, { type: ErrorTypes.MEDIA_ERROR, details: ErrorDetails.BUFFER_SEEK_OVER_HOLE, @@ -150,6 +294,7 @@ export default class GapController { logger.log(`adjust currentTime from ${currentTime} to ${targetTime}`); // playback stalled in buffered area ... let's nudge currentTime to try to overcome this media.currentTime = targetTime; + hls.trigger(Event.ERROR, { type: ErrorTypes.MEDIA_ERROR, details: ErrorDetails.BUFFER_NUDGE_ON_STALL, From ccd270a53699b09db9c124760e28461af74324bc Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Tue, 3 Sep 2019 22:37:14 +0200 Subject: [PATCH 02/42] gap-controller unit-tests: update to partly refactored properties fix some test specs + media time-ranges mock + use sinon timers --- tests/unit/controller/gap-controller.js | 116 ++++++++++++++++-------- 1 file changed, 77 insertions(+), 39 deletions(-) diff --git a/tests/unit/controller/gap-controller.js b/tests/unit/controller/gap-controller.js index 34c7c50d9ce..59a8119eaac 100644 --- a/tests/unit/controller/gap-controller.js +++ b/tests/unit/controller/gap-controller.js @@ -1,7 +1,14 @@ +import assert from 'assert'; +import sinon from 'sinon'; + import Hls from '../../../src/hls'; -import GapController from '../../../src/controller/gap-controller'; + +import GapController from '../../../src/controller/gap-controller'; // eslint-disable-line import/no-duplicates +import { STALL_DEBOUNCE_INTERVAL_MS } from '../../../src/controller/gap-controller'; // eslint-disable-line import/no-duplicates import { FragmentTracker } from '../../../src/controller/fragment-tracker'; + import Event from '../../../src/events'; + import { ErrorTypes, ErrorDetails } from '../../../src/errors'; describe('checkBuffer', function () { @@ -9,7 +16,7 @@ describe('checkBuffer', function () { let config; let media; let triggerSpy; - const sandbox = sinon.createSandbox(); + const sandbox = sinon.sandbox.create(); beforeEach(function () { const hls = new Hls({}); @@ -28,43 +35,42 @@ describe('checkBuffer', function () { for (let i = 1; i < config.nudgeMaxRetry; i++) { let expected = media.currentTime + (i * config.nudgeOffset); gapController._tryNudgeBuffer(); - expect(media.currentTime).to.equal(expected); + assert.strictEqual(expected, media.currentTime); } - - expect(triggerSpy).to.have.been.calledWith(Event.ERROR, { + assert(triggerSpy.alwaysCalledWith(Event.ERROR, { type: ErrorTypes.MEDIA_ERROR, details: ErrorDetails.BUFFER_NUDGE_ON_STALL, fatal: false - }); + })); }); it('should not increment the currentTime if the max amount of nudges has been attempted', function () { config.nudgeMaxRetry = 0; gapController._tryNudgeBuffer(); - expect(media.currentTime).to.equal(0); - expect(triggerSpy).to.have.been.calledWith(Event.ERROR, { + assert.strictEqual(0, media.currentTime); + assert(triggerSpy.calledWith(Event.ERROR, { type: ErrorTypes.MEDIA_ERROR, details: ErrorDetails.BUFFER_STALLED_ERROR, fatal: true - }); + })); }); }); describe('_reportStall', function () { it('should report a stall with the current buffer length if it has not already been reported', function () { gapController._reportStall(42); - expect(triggerSpy).to.have.been.calledWith(Event.ERROR, { + assert(triggerSpy.calledWith(Event.ERROR, { type: ErrorTypes.MEDIA_ERROR, details: ErrorDetails.BUFFER_STALLED_ERROR, fatal: false, buffer: 42 - }); + })); }); it('should not report a stall if it was already reported', function () { gapController.stallReported = true; gapController._reportStall(42); - expect(triggerSpy).to.not.have.been.called; + assert(triggerSpy.notCalled); }); }); @@ -74,7 +80,7 @@ describe('checkBuffer', function () { const mockStallDuration = (config.highBufferWatchdogPeriod + 1) * 1000; const nudgeStub = sandbox.stub(gapController, '_tryNudgeBuffer'); gapController._tryFixBufferStall(mockBufferInfo, mockStallDuration); - expect(nudgeStub).to.have.been.calledOnce; + assert(nudgeStub.calledOnce); }); it('should not nudge when briefly stalling close to the buffer end', function () { @@ -82,7 +88,7 @@ describe('checkBuffer', function () { const mockStallDuration = (config.highBufferWatchdogPeriod / 2) * 1000; const nudgeStub = sandbox.stub(gapController, '_tryNudgeBuffer'); gapController._tryFixBufferStall(mockBufferInfo, mockStallDuration); - expect(nudgeStub).to.have.not.been.called; + assert(nudgeStub.notCalled); }); it('should not nudge when too far from the buffer end', function () { @@ -90,43 +96,58 @@ describe('checkBuffer', function () { const mockStallDuration = (config.highBufferWatchdogPeriod + 1) * 1000; const nudgeStub = sandbox.stub(gapController, '_tryNudgeBuffer'); gapController._tryFixBufferStall(mockBufferInfo, mockStallDuration); - expect(nudgeStub).to.have.not.been.called; + assert(nudgeStub.notCalled); }); it('should try to jump partial fragments when detected', function () { sandbox.stub(gapController.fragmentTracker, 'getPartialFragment').returns({}); const skipHoleStub = sandbox.stub(gapController, '_trySkipBufferHole'); gapController._tryFixBufferStall({ len: 0 }); - expect(skipHoleStub).to.have.been.calledOnce; + assert(skipHoleStub.calledOnce); }); it('should not try to jump partial fragments when none are detected', function () { sandbox.stub(gapController.fragmentTracker, 'getPartialFragment').returns(null); const skipHoleStub = sandbox.stub(gapController, '_trySkipBufferHole'); gapController._tryFixBufferStall({ len: 0 }); - expect(skipHoleStub).to.have.not.been.called; + assert(skipHoleStub.notCalled); }); }); describe('poll', function () { let mockMedia; + let mockTimeRanges; + let mockTimeRangesData; let reportStallSpy; let lastCurrentTime; - let buffered; + beforeEach(function () { - mockMedia = { - buffered: { - length: 1 + mockTimeRangesData = [[100, 200], [400, 500]]; + mockTimeRanges = { + length: mockTimeRangesData.length, + start (index) { + return mockTimeRangesData[index][0]; + }, + end (index) { + return mockTimeRangesData[index][1]; } }; + + mockMedia = { + currentTime: 0, + paused: false, + readyState: 0, + buffered: mockTimeRanges, + addEventListener () {} + }; + gapController.media = mockMedia; reportStallSpy = sandbox.spy(gapController, '_reportStall'); - buffered = mockMedia.buffered; }); function setStalling () { mockMedia.paused = false; - mockMedia.readyState = 1; + mockMedia.readyState = 4; mockMedia.currentTime = 4; lastCurrentTime = 4; } @@ -139,42 +160,59 @@ describe('checkBuffer', function () { } it('should try to fix a stall if expected to be playing', function () { + const clock = sandbox.useFakeTimers(0); + const fixStallStub = sandbox.stub(gapController, '_tryFixBufferStall'); setStalling(); - gapController.poll(lastCurrentTime, buffered); + + clock.tick(1); + + gapController.poll(lastCurrentTime); + + clock.tick(1); + + console.log(gapController.hasPlayed, gapController.stallDetectedAtTime); // The first poll call made while stalling just sets stall flags - expect(gapController.stalled).to.be.a('number'); - expect(gapController.stallReported).to.be.false; + assert.strictEqual(typeof gapController.stallDetectedAtTime, 'number'); + assert.strictEqual(typeof gapController.stallHandledAtTime, 'number'); + assert.strictEqual(gapController.stallReported, false); + + clock.tick(STALL_DEBOUNCE_INTERVAL_MS); + + gapController.poll(lastCurrentTime); - gapController.poll(lastCurrentTime, buffered); - expect(fixStallStub).to.have.been.calledOnce; + assert(fixStallStub.calledOnce); }); it('should reset stall flags when no longer stalling', function () { setNotStalling(); gapController.stallReported = true; gapController.nudgeRetry = 1; - gapController.stalled = 4200; + gapController.stallDetectedAtTime = 4200; + gapController.stallHandledAtTime = 4201; + const fixStallStub = sandbox.stub(gapController, '_tryFixBufferStall'); - gapController.poll(lastCurrentTime, buffered); - expect(gapController.stalled).to.not.exist; - expect(gapController.nudgeRetry).to.equal(0); - expect(gapController.stallReported).to.be.false; - expect(fixStallStub).to.not.have.been.called; + gapController.poll(lastCurrentTime); + + assert.strictEqual(gapController.stallDetectedAtTime, null); + assert.strictEqual(gapController.stallHandledAtTime, null); + assert.strictEqual(gapController.nudgeRetry, 0); + assert.strictEqual(gapController.stallReported, false); + assert(fixStallStub.notCalled); }); it('should trigger reportStall when stalling for 1 second or longer', function () { setStalling(); const clock = sandbox.useFakeTimers(0); clock.tick(1000); - gapController.stalled = 1; - gapController.poll(lastCurrentTime, buffered); - expect(reportStallSpy).to.not.have.been.called; + gapController.stallDetectedAtTime = 1; + gapController.poll(lastCurrentTime); + assert(reportStallSpy.notCalled); clock.tick(1001); - gapController.poll(lastCurrentTime, buffered); - expect(reportStallSpy).to.have.been.calledOnce; + gapController.poll(lastCurrentTime); + assert(reportStallSpy.calledOnce); }); }); }); From f97edfebc3fb9a12ed4b359b321795ff3d3b4c32 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Wed, 4 Sep 2019 22:26:32 +0200 Subject: [PATCH 03/42] rebase-away this commit BEFORE MERGE (!): disable issue666 from test suite (server related inaccessability causes CI to fail) --- tests/test-streams.js | 2 ++ 1 file changed, 2 insertions(+) diff --git a/tests/test-streams.js b/tests/test-streams.js index e530e5b7d8d..ef706a697a2 100644 --- a/tests/test-streams.js +++ b/tests/test-streams.js @@ -64,6 +64,7 @@ module.exports = { 'abr': false, 'blacklist_ua': ['internet explorer'] }, + /* issue666: { 'url': 'https://test-streams.mux.dev/issue666/playlists/cisq0gim60007xzvi505emlxx.m3u8', 'description': 'hls.js/issues/666', @@ -71,6 +72,7 @@ module.exports = { 'abr': false, 'blacklist_ua': ['internet explorer'] }, + */ /* // went offline for us :( would be good to replace this for regression test with something mimicking the issue issue649: { 'url': 'https://cdn3.screen9.com/media/c/W/cW87csHkxsgu5TV1qs78aA_auto_hls.m3u8?auth=qlUjeCtbVdtkDfZYrtveTIVUXX1yuSqgF8wfWabzKpX72r-d5upW88-FHuyRRdnZA_1PKRTGAtTt_6Z-aj22kw', From d38666cad0195e867a6778cb00321d600ea8df9c Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Mon, 16 Sep 2019 21:26:23 +0200 Subject: [PATCH 04/42] gap-controller: improve comment on skipping initial gap in stream --- src/controller/gap-controller.js | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index b16cf0b1647..a6ae6cd074b 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -65,8 +65,9 @@ export default class GapController { if (!isFiniteNumber(this.media.currentTime) || this.media.buffered.length === 0) { return; } - // Need to check what the buffer reports as start time for the first fragment appended. - // If within the threshold of maxBufferHole, adjust this.startPosition for _seekToStartPos(). + // Checking what the buffer reports as start time for the first fragment appended + // and when the gap is within treshhold of configured maxBufferHole, + // skip playhead to this position to overcome an apparent initial gap in the stream. const firstBufferedPosition = this.media.buffered.start(0); if (Math.abs(this.media.currentTime - firstBufferedPosition) < this.config.maxBufferHole) { if (!this.media.seeking) { From d1492c5f7c98a29bdfab058cb68dd71afbcc5fc6 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Mon, 16 Sep 2019 21:27:50 +0200 Subject: [PATCH 05/42] config defaults: set maxBufferHole to 15 second (otherwise we can not assume to pass the test on the approx 10 sec hole in one of the test-streams https://s3.amazonaws.com/bob.jwplayer.com/%7Ealex/123633/new_master.m3u8) --- src/config.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/config.ts b/src/config.ts index efc8e27c7e1..e0829bb27fb 100644 --- a/src/config.ts +++ b/src/config.ts @@ -174,7 +174,7 @@ export const hlsDefaultConfig: HlsConfig = { initialLiveManifestSize: 1, // used by stream-controller maxBufferLength: 30, // used by stream-controller maxBufferSize: 60 * 1000 * 1000, // used by stream-controller - maxBufferHole: 0.5, // used by stream-controller + maxBufferHole: 15, // used by stream-controller lowBufferWatchdogPeriod: 0.5, // used by stream-controller highBufferWatchdogPeriod: 3, // used by stream-controller From 83f61297358c07f870b8b8036f7e8aac4c69cfd0 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Mon, 16 Sep 2019 22:02:57 +0200 Subject: [PATCH 06/42] stream-controller: improve var names in _findFragment. add some Qs. isofunctional change. --- src/controller/stream-controller.js | 67 ++++++++++++++++------------- 1 file changed, 37 insertions(+), 30 deletions(-) diff --git a/src/controller/stream-controller.js b/src/controller/stream-controller.js index a5e40078578..eb71658c991 100644 --- a/src/controller/stream-controller.js +++ b/src/controller/stream-controller.js @@ -347,65 +347,72 @@ class StreamController extends BaseStreamController { return frag; } - _findFragment (start, fragPrevious, fragLen, fragments, bufferEnd, end, levelDetails) { + _findFragment (start, fragPreviousLoad, fragmentIndexRange, fragments, bufferEnd, end, levelDetails) { const config = this.hls.config; - let frag; + let fragNextLoad; if (bufferEnd < end) { const lookupTolerance = (bufferEnd > end - config.maxFragLookUpTolerance) ? 0 : config.maxFragLookUpTolerance; // Remove the tolerance if it would put the bufferEnd past the actual end of stream // Uses buffer and sequence number to calculate switch segment (required if using EXT-X-DISCONTINUITY-SEQUENCE) - frag = findFragmentByPTS(fragPrevious, fragments, bufferEnd, lookupTolerance); + fragNextLoad = findFragmentByPTS(fragPreviousLoad, fragments, bufferEnd, lookupTolerance); } else { // reach end of playlist - frag = fragments[fragLen - 1]; + fragNextLoad = fragments[fragmentIndexRange - 1]; } - if (frag) { - const curSNIdx = frag.sn - levelDetails.startSN; - const sameLevel = fragPrevious && frag.level === fragPrevious.level; - const prevFrag = fragments[curSNIdx - 1]; - const nextFrag = fragments[curSNIdx + 1]; + + if (!fragNextLoad) { + return null; + } + + { + const curSNIdx = fragNextLoad.sn - levelDetails.startSN; + const sameLevel = fragPreviousLoad && fragNextLoad.level === fragPreviousLoad.level; + const prevSnFrag = fragments[curSNIdx - 1]; + const nextSnFrag = fragments[curSNIdx + 1]; + // logger.log('find SN matching with pos:' + bufferEnd + ':' + frag.sn); - if (fragPrevious && frag.sn === fragPrevious.sn) { - if (sameLevel && !frag.backtracked) { - if (frag.sn < levelDetails.endSN) { - let deltaPTS = fragPrevious.deltaPTS; + if (fragPreviousLoad && fragNextLoad.sn === fragPreviousLoad.sn) { // Q: why not use FragmentTracker to determine this condition? + if (sameLevel && !fragNextLoad.backtracked) { + if (fragNextLoad.sn < levelDetails.endSN) { + let deltaPTS = fragPreviousLoad.deltaPTS; // if there is a significant delta between audio and video, larger than max allowed hole, // and if previous remuxed fragment did not start with a keyframe. (fragPrevious.dropped) // let's try to load previous fragment again to get last keyframe // then we will reload again current fragment (that way we should be able to fill the buffer hole ...) - if (deltaPTS && deltaPTS > config.maxBufferHole && fragPrevious.dropped && curSNIdx) { - frag = prevFrag; - logger.warn('SN just loaded, with large PTS gap between audio and video, maybe frag is not starting with a keyframe ? load previous one to try to overcome this'); + if (deltaPTS && deltaPTS > config.maxBufferHole && fragPreviousLoad.dropped && curSNIdx) { + fragNextLoad = prevSnFrag; + logger.warn('Previous fragment was dropped with large PTS gap between audio and video. Maybe fragment is not starting with a keyframe? Loading previous one to try to overcome this'); } else { - frag = nextFrag; - logger.log(`SN just loaded, load next one: ${frag.sn}`, frag); + fragNextLoad = nextSnFrag; + logger.log(`Re-loading fragment with SN: ${fragNextLoad.sn}`); // Q: why? } } else { - frag = null; + fragNextLoad = null; } - } else if (frag.backtracked) { + } else if (fragNextLoad.backtracked) { // Only backtrack a max of 1 consecutive fragment to prevent sliding back too far when little or no frags start with keyframes - if (nextFrag && nextFrag.backtracked) { - logger.warn(`Already backtracked from fragment ${nextFrag.sn}, will not backtrack to fragment ${frag.sn}. Loading fragment ${nextFrag.sn}`); - frag = nextFrag; + if (nextSnFrag && nextSnFrag.backtracked) { + logger.warn(`Already backtracked from fragment ${nextSnFrag.sn}, will not backtrack to fragment ${fragNextLoad.sn}. Loading fragment ${nextSnFrag.sn}`); + fragNextLoad = nextSnFrag; } else { // If a fragment has dropped frames and it's in a same level/sequence, load the previous fragment to try and find the keyframe // Reset the dropped count now since it won't be reset until we parse the fragment again, which prevents infinite backtracking on the same segment logger.warn('Loaded fragment with dropped frames, backtracking 1 segment to find a keyframe'); - frag.dropped = 0; - if (prevFrag) { - frag = prevFrag; - frag.backtracked = true; + fragNextLoad.dropped = 0; + if (prevSnFrag) { + fragNextLoad = prevSnFrag; + fragNextLoad.backtracked = true; // Q: why are we setting this flag to true, since it has to be true so we even reach this code? } else if (curSNIdx) { // can't backtrack on very first fragment - frag = null; + fragNextLoad = null; } } } } } - return frag; + + return fragNextLoad; } _loadKey (frag) { @@ -450,7 +457,7 @@ class StreamController extends BaseStreamController { if (this.state !== nextState) { const previousState = this.state; this._state = nextState; - logger.log(`main stream:${previousState}->${nextState}`); + logger.log(`main stream-controller state-transition: ${previousState}->${nextState}`); this.hls.trigger(Event.STREAM_STATE_TRANSITION, { previousState, nextState }); } } From 34f85a9e96975f88ee8542fdef5cbeef547af4b6 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Mon, 16 Sep 2019 22:05:14 +0200 Subject: [PATCH 07/42] re-enable issue666 test-stream --- tests/test-streams.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/test-streams.js b/tests/test-streams.js index ef706a697a2..ecacdc06ec7 100644 --- a/tests/test-streams.js +++ b/tests/test-streams.js @@ -64,7 +64,7 @@ module.exports = { 'abr': false, 'blacklist_ua': ['internet explorer'] }, - /* + /// * issue666: { 'url': 'https://test-streams.mux.dev/issue666/playlists/cisq0gim60007xzvi505emlxx.m3u8', 'description': 'hls.js/issues/666', @@ -72,7 +72,7 @@ module.exports = { 'abr': false, 'blacklist_ua': ['internet explorer'] }, - */ + //* / /* // went offline for us :( would be good to replace this for regression test with something mimicking the issue issue649: { 'url': 'https://cdn3.screen9.com/media/c/W/cW87csHkxsgu5TV1qs78aA_auto_hls.m3u8?auth=qlUjeCtbVdtkDfZYrtveTIVUXX1yuSqgF8wfWabzKpX72r-d5upW88-FHuyRRdnZA_1PKRTGAtTt_6Z-aj22kw', From 6ea08a46f71b28277201e6fb3d5359a88d7c25ff Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Wed, 25 Sep 2019 17:17:58 +0200 Subject: [PATCH 08/42] gap-controller+audio-track-controller: fix jsdocs syntax breaking generator --- src/controller/gap-controller.js | 18 ++++++++++++------ 1 file changed, 12 insertions(+), 6 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index a6ae6cd074b..7983faf7e43 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -17,32 +17,38 @@ export default class GapController { this.hls = hls; /** - * @private @member {boolean} + * @private + * @member {boolean} */ this.stallReported = false; /** - * @private @member {number | null} + * @private + * @member {number | null} */ this.stallDetectedAtTime = null; /** - * @private @member {number | null} + * @private + * @member {number | null} */ this.stallHandledAtTime = null; /** - * @private @member {number | null} + * @private + * @member {number | null} */ this.currentPlayheadTime = null; /** - * @private @member {boolean} + * @private + * @member {boolean} */ this.hasPlayed = false; /** - * @private @member {EventListener} + * @private + * @member {EventListener} */ this.onMediaStalled = null; } From 21003254160fd2763e25443e35ac589f90a608aa Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Wed, 25 Sep 2019 19:10:39 +0200 Subject: [PATCH 09/42] gap-controller unit test: reset to using expect not assert --- tests/unit/controller/gap-controller.js | 60 +++++++++++++------------ 1 file changed, 31 insertions(+), 29 deletions(-) diff --git a/tests/unit/controller/gap-controller.js b/tests/unit/controller/gap-controller.js index 59a8119eaac..52bd6c449b2 100644 --- a/tests/unit/controller/gap-controller.js +++ b/tests/unit/controller/gap-controller.js @@ -1,4 +1,3 @@ -import assert from 'assert'; import sinon from 'sinon'; import Hls from '../../../src/hls'; @@ -16,7 +15,7 @@ describe('checkBuffer', function () { let config; let media; let triggerSpy; - const sandbox = sinon.sandbox.create(); + const sandbox = sinon.createSandbox(); beforeEach(function () { const hls = new Hls({}); @@ -35,42 +34,43 @@ describe('checkBuffer', function () { for (let i = 1; i < config.nudgeMaxRetry; i++) { let expected = media.currentTime + (i * config.nudgeOffset); gapController._tryNudgeBuffer(); - assert.strictEqual(expected, media.currentTime); + expect(media.currentTime).to.equal(expected); } - assert(triggerSpy.alwaysCalledWith(Event.ERROR, { + + expect(triggerSpy).to.have.been.calledWith(Event.ERROR, { type: ErrorTypes.MEDIA_ERROR, details: ErrorDetails.BUFFER_NUDGE_ON_STALL, fatal: false - })); + }); }); it('should not increment the currentTime if the max amount of nudges has been attempted', function () { config.nudgeMaxRetry = 0; gapController._tryNudgeBuffer(); - assert.strictEqual(0, media.currentTime); - assert(triggerSpy.calledWith(Event.ERROR, { + expect(media.currentTime).to.equal(0); + expect(triggerSpy).to.have.been.calledWith(Event.ERROR, { type: ErrorTypes.MEDIA_ERROR, details: ErrorDetails.BUFFER_STALLED_ERROR, fatal: true - })); + }); }); }); describe('_reportStall', function () { it('should report a stall with the current buffer length if it has not already been reported', function () { gapController._reportStall(42); - assert(triggerSpy.calledWith(Event.ERROR, { + expect(triggerSpy).to.have.been.calledWith(Event.ERROR, { type: ErrorTypes.MEDIA_ERROR, details: ErrorDetails.BUFFER_STALLED_ERROR, fatal: false, buffer: 42 - })); + }); }); it('should not report a stall if it was already reported', function () { gapController.stallReported = true; gapController._reportStall(42); - assert(triggerSpy.notCalled); + expect(triggerSpy).to.not.have.been.called; }); }); @@ -80,7 +80,7 @@ describe('checkBuffer', function () { const mockStallDuration = (config.highBufferWatchdogPeriod + 1) * 1000; const nudgeStub = sandbox.stub(gapController, '_tryNudgeBuffer'); gapController._tryFixBufferStall(mockBufferInfo, mockStallDuration); - assert(nudgeStub.calledOnce); + expect(nudgeStub).to.have.been.calledOnce; }); it('should not nudge when briefly stalling close to the buffer end', function () { @@ -88,7 +88,7 @@ describe('checkBuffer', function () { const mockStallDuration = (config.highBufferWatchdogPeriod / 2) * 1000; const nudgeStub = sandbox.stub(gapController, '_tryNudgeBuffer'); gapController._tryFixBufferStall(mockBufferInfo, mockStallDuration); - assert(nudgeStub.notCalled); + expect(nudgeStub).to.have.not.been.called; }); it('should not nudge when too far from the buffer end', function () { @@ -96,21 +96,21 @@ describe('checkBuffer', function () { const mockStallDuration = (config.highBufferWatchdogPeriod + 1) * 1000; const nudgeStub = sandbox.stub(gapController, '_tryNudgeBuffer'); gapController._tryFixBufferStall(mockBufferInfo, mockStallDuration); - assert(nudgeStub.notCalled); + expect(nudgeStub).to.have.not.been.called; }); it('should try to jump partial fragments when detected', function () { sandbox.stub(gapController.fragmentTracker, 'getPartialFragment').returns({}); const skipHoleStub = sandbox.stub(gapController, '_trySkipBufferHole'); gapController._tryFixBufferStall({ len: 0 }); - assert(skipHoleStub.calledOnce); + expect(skipHoleStub).to.have.been.calledOnce; }); it('should not try to jump partial fragments when none are detected', function () { sandbox.stub(gapController.fragmentTracker, 'getPartialFragment').returns(null); const skipHoleStub = sandbox.stub(gapController, '_trySkipBufferHole'); gapController._tryFixBufferStall({ len: 0 }); - assert(skipHoleStub.notCalled); + expect(skipHoleStub).to.have.not.been.called; }); }); @@ -171,18 +171,16 @@ describe('checkBuffer', function () { clock.tick(1); - console.log(gapController.hasPlayed, gapController.stallDetectedAtTime); - // The first poll call made while stalling just sets stall flags - assert.strictEqual(typeof gapController.stallDetectedAtTime, 'number'); - assert.strictEqual(typeof gapController.stallHandledAtTime, 'number'); - assert.strictEqual(gapController.stallReported, false); + expect(typeof gapController.stallDetectedAtTime).to.equal('number'); + expect(typeof gapController.stallHandledAtTime).to.equal('number'); + expect(gapController.stallReported).to.equal(false); clock.tick(STALL_DEBOUNCE_INTERVAL_MS); gapController.poll(lastCurrentTime); - assert(fixStallStub.calledOnce); + expect(fixStallStub).to.have.been.calledOnce; }); it('should reset stall flags when no longer stalling', function () { @@ -196,11 +194,12 @@ describe('checkBuffer', function () { gapController.poll(lastCurrentTime); - assert.strictEqual(gapController.stallDetectedAtTime, null); - assert.strictEqual(gapController.stallHandledAtTime, null); - assert.strictEqual(gapController.nudgeRetry, 0); - assert.strictEqual(gapController.stallReported, false); - assert(fixStallStub.notCalled); + expect(gapController.stallDetectedAtTime).to.equal(null); + expect(gapController.stallHandledAtTime).to.equal(null); + expect(gapController.nudgeRetry).to.equal(0); + expect(gapController.stallReported).to.equal(false); + + expect(fixStallStub).to.have.not.been.called; }); it('should trigger reportStall when stalling for 1 second or longer', function () { @@ -209,10 +208,13 @@ describe('checkBuffer', function () { clock.tick(1000); gapController.stallDetectedAtTime = 1; gapController.poll(lastCurrentTime); - assert(reportStallSpy.notCalled); + + expect(reportStallSpy).to.have.not.been.called; + clock.tick(1001); gapController.poll(lastCurrentTime); - assert(reportStallSpy.calledOnce); + + expect(reportStallSpy).to.have.been.calledOnce; }); }); }); From 8acc16611aea77f4c8b58a33556801486a785acb Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Wed, 25 Sep 2019 22:25:31 +0200 Subject: [PATCH 10/42] Revert "config defaults: set maxBufferHole to 15 second" This reverts commit 3052048ba0aac62bbed1778a098193f8e246f4cf. We don't need this as we were wrongly using this parameter to handle startup gaps. --- src/config.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/config.ts b/src/config.ts index e0829bb27fb..efc8e27c7e1 100644 --- a/src/config.ts +++ b/src/config.ts @@ -174,7 +174,7 @@ export const hlsDefaultConfig: HlsConfig = { initialLiveManifestSize: 1, // used by stream-controller maxBufferLength: 30, // used by stream-controller maxBufferSize: 60 * 1000 * 1000, // used by stream-controller - maxBufferHole: 15, // used by stream-controller + maxBufferHole: 0.5, // used by stream-controller lowBufferWatchdogPeriod: 0.5, // used by stream-controller highBufferWatchdogPeriod: 3, // used by stream-controller From 7d988753a8c152beb3a1622e702cea937143ff21 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Wed, 25 Sep 2019 22:27:53 +0200 Subject: [PATCH 11/42] test-streams: removing comment-out lines for issue666 stream --- tests/test-streams.js | 2 -- 1 file changed, 2 deletions(-) diff --git a/tests/test-streams.js b/tests/test-streams.js index ecacdc06ec7..e530e5b7d8d 100644 --- a/tests/test-streams.js +++ b/tests/test-streams.js @@ -64,7 +64,6 @@ module.exports = { 'abr': false, 'blacklist_ua': ['internet explorer'] }, - /// * issue666: { 'url': 'https://test-streams.mux.dev/issue666/playlists/cisq0gim60007xzvi505emlxx.m3u8', 'description': 'hls.js/issues/666', @@ -72,7 +71,6 @@ module.exports = { 'abr': false, 'blacklist_ua': ['internet explorer'] }, - //* / /* // went offline for us :( would be good to replace this for regression test with something mimicking the issue issue649: { 'url': 'https://cdn3.screen9.com/media/c/W/cW87csHkxsgu5TV1qs78aA_auto_hls.m3u8?auth=qlUjeCtbVdtkDfZYrtveTIVUXX1yuSqgF8wfWabzKpX72r-d5upW88-FHuyRRdnZA_1PKRTGAtTt_6Z-aj22kw', From fd55674bd4e0e22692691588ce71229787305906 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Wed, 25 Sep 2019 22:39:54 +0200 Subject: [PATCH 12/42] gap-controller: do not check against maxBufferHole to skip startup gaps --- src/controller/gap-controller.js | 20 +++++++++++--------- 1 file changed, 11 insertions(+), 9 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index 7983faf7e43..2a06c890060 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -68,18 +68,20 @@ export default class GapController { */ poll (previousPlayheadTime) { if (!this.hasPlayed) { - if (!isFiniteNumber(this.media.currentTime) || this.media.buffered.length === 0) { + const mediaCurrentTime = this.media.currentTime; + if (!isFiniteNumber(mediaCurrentTime) || this.media.buffered.length === 0) { return; } - // Checking what the buffer reports as start time for the first fragment appended - // and when the gap is within treshhold of configured maxBufferHole, - // skip playhead to this position to overcome an apparent initial gap in the stream. + // Checking what the buffer reports as start time for the first fragment appended. + // We skip the playhead to this position to overcome an apparent initial gap in the stream. + // We add a margin value on top (same as the one used for playhead nudging on stall detection) + // to fix eventual issues with browser-internal thresholds + // where some MSE implementation might not play when the playhead + // is exactly on the start value (trying to overcome what would be a browser bug). const firstBufferedPosition = this.media.buffered.start(0); - if (Math.abs(this.media.currentTime - firstBufferedPosition) < this.config.maxBufferHole) { - if (!this.media.seeking) { - logger.warn('skipping over buffer hole on startup (first segment starts partially later than assumed)'); - this.media.currentTime = firstBufferedPosition + SKIP_BUFFER_HOLE_STEP_SECONDS; - } + if (mediaCurrentTime - firstBufferedPosition > 0 && !this.media.seeking) { + logger.warn(`skipping over gap at startup (first segment buffered time-range starts partially later than assumed) from ${mediaCurrentTime} to ${firstBufferedPosition} seconds`); + this.media.currentTime = firstBufferedPosition + SKIP_BUFFER_HOLE_STEP_SECONDS; } } From ff0e43f6ea84969a3f94ff86df477ae2fb2170f5 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Wed, 25 Sep 2019 22:42:52 +0200 Subject: [PATCH 13/42] gap-controller: put order in time diff computation right for initial gap --- src/controller/gap-controller.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index 2a06c890060..6443fe43193 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -79,7 +79,7 @@ export default class GapController { // where some MSE implementation might not play when the playhead // is exactly on the start value (trying to overcome what would be a browser bug). const firstBufferedPosition = this.media.buffered.start(0); - if (mediaCurrentTime - firstBufferedPosition > 0 && !this.media.seeking) { + if ((firstBufferedPosition - mediaCurrentTime > 0) && !this.media.seeking) { logger.warn(`skipping over gap at startup (first segment buffered time-range starts partially later than assumed) from ${mediaCurrentTime} to ${firstBufferedPosition} seconds`); this.media.currentTime = firstBufferedPosition + SKIP_BUFFER_HOLE_STEP_SECONDS; } From 586daeb8c2feb3c1180058d0e81a569f16c882ce Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Thu, 26 Sep 2019 00:34:59 +0200 Subject: [PATCH 14/42] gap-controller: fix name of constant to better describe what it is --- src/controller/gap-controller.js | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index 6443fe43193..ae77111d20e 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -4,7 +4,7 @@ import Event from '../events'; import { logger } from '../utils/logger'; import { isFiniteNumber } from '../polyfills/number-isFinite'; -export const STALL_DEBOUNCE_INTERVAL_MS = 1000; +export const STALL_MINIMUM_DURATION_MS = 1000; export const STALL_HANDLING_RETRY_PERIOD_MS = 1000; export const JUMP_THRESHOLD_SECONDS = 0.5; // tolerance needed as some browsers stalls playback before reaching buffered range end export const SKIP_BUFFER_HOLE_STEP_SECONDS = 0.1; @@ -19,18 +19,23 @@ export default class GapController { /** * @private * @member {boolean} + * Flag set when a flag was detected and appeared to be sustained for more than the stall minimum duration. */ this.stallReported = false; /** * @private * @member {number | null} + * This keeps state of the time a stall was detected. + * It will make sure we only report a stall as one when within the min stall duration. */ this.stallDetectedAtTime = null; /** * @private * @member {number | null} + * This keeps state of handling stalls (once detected) to throttle the retry pace, + * and thus will get updated on each retry. */ this.stallHandledAtTime = null; @@ -192,14 +197,14 @@ export default class GapController { logger.warn(`Stall detected at playhead position ${currentPlayheadTime}, buffered-time-ranges info: ${JSON.stringify(bufferInfo)}`); if (!this.stallDetectedAtTime) { - logger.warn('Silently ignoring first detected stall within grace period, storing timestamp: ' + now); + logger.warn('Silently ignoring first detected stall within minimum duration, storing timestamp: ' + now); this.stallDetectedAtTime = now; return; } const stalledDurationMs = now - this.stallDetectedAtTime; - if (stalledDurationMs >= STALL_DEBOUNCE_INTERVAL_MS) { - logger.warn('Stall detected after grace period, reporting error'); + if (stalledDurationMs >= STALL_MINIMUM_DURATION_MS) { + logger.warn('Stall detected after min stall duration, reporting error'); // Report stalling after trying to fix this._reportStall(bufferInfo.len); } From 0b8bb0d63d5b88754f2eddea6200092a8b0f07c8 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Thu, 26 Sep 2019 00:38:14 +0200 Subject: [PATCH 15/42] gap-controller unit test: poll spec: improve media behavior mocking and remove redundant test spec + add todo reminder on missing specs for new behavior --- tests/unit/controller/gap-controller.js | 78 +++++++++++++------------ 1 file changed, 41 insertions(+), 37 deletions(-) diff --git a/tests/unit/controller/gap-controller.js b/tests/unit/controller/gap-controller.js index 52bd6c449b2..531dd165214 100644 --- a/tests/unit/controller/gap-controller.js +++ b/tests/unit/controller/gap-controller.js @@ -3,14 +3,14 @@ import sinon from 'sinon'; import Hls from '../../../src/hls'; import GapController from '../../../src/controller/gap-controller'; // eslint-disable-line import/no-duplicates -import { STALL_DEBOUNCE_INTERVAL_MS } from '../../../src/controller/gap-controller'; // eslint-disable-line import/no-duplicates +import { STALL_MINIMUM_DURATION_MS } from '../../../src/controller/gap-controller'; // eslint-disable-line import/no-duplicates import { FragmentTracker } from '../../../src/controller/fragment-tracker'; import Event from '../../../src/events'; import { ErrorTypes, ErrorDetails } from '../../../src/errors'; -describe('checkBuffer', function () { +describe('GapController', function () { let gapController; let config; let media; @@ -120,8 +120,10 @@ describe('checkBuffer', function () { let mockTimeRangesData; let reportStallSpy; let lastCurrentTime; + let isStalling; beforeEach(function () { + isStalling = false; mockTimeRangesData = [[100, 200], [400, 500]]; mockTimeRanges = { length: mockTimeRangesData.length, @@ -134,9 +136,9 @@ describe('checkBuffer', function () { }; mockMedia = { - currentTime: 0, + currentTime: 100, paused: false, - readyState: 0, + readyState: 4, buffered: mockTimeRanges, addEventListener () {} }; @@ -145,46 +147,59 @@ describe('checkBuffer', function () { reportStallSpy = sandbox.spy(gapController, '_reportStall'); }); - function setStalling () { - mockMedia.paused = false; - mockMedia.readyState = 4; - mockMedia.currentTime = 4; - lastCurrentTime = 4; - } - - function setNotStalling () { - mockMedia.paused = false; - mockMedia.readyState = 4; - mockMedia.currentTime = 5; - lastCurrentTime = 4; + function tickMediaClock () { + lastCurrentTime = mockMedia.currentTime; + if (!isStalling) { + mockMedia.currentTime++; + } } it('should try to fix a stall if expected to be playing', function () { const clock = sandbox.useFakeTimers(0); + const TIMER_STEP_MS = 1234; + + clock.tick(TIMER_STEP_MS); + const fixStallStub = sandbox.stub(gapController, '_tryFixBufferStall'); - setStalling(); - clock.tick(1); + // we need to play a bit to get past the hasPlayed check + tickMediaClock(); + gapController.poll(lastCurrentTime); + // check the flag has turned true + expect(gapController.hasPlayed).to.equal(true); + // set stalling and tick media again + isStalling = true; + tickMediaClock(); + // now poll again gapController.poll(lastCurrentTime); - clock.tick(1); + expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); + expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS); + expect(gapController.stallReported).to.equal(false); + + clock.tick(STALL_MINIMUM_DURATION_MS / 2); - // The first poll call made while stalling just sets stall flags - expect(typeof gapController.stallDetectedAtTime).to.equal('number'); - expect(typeof gapController.stallHandledAtTime).to.equal('number'); + gapController.poll(lastCurrentTime); + // if poll within debounce interval, flags should be unchanged + // and no stall reported yet + expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); + expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS); expect(gapController.stallReported).to.equal(false); - clock.tick(STALL_DEBOUNCE_INTERVAL_MS); + clock.tick(STALL_MINIMUM_DURATION_MS / 2); gapController.poll(lastCurrentTime); + expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); + expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS + STALL_MINIMUM_DURATION_MS); + expect(gapController.stallReported).to.equal(true); + expect(fixStallStub).to.have.been.calledOnce; }); it('should reset stall flags when no longer stalling', function () { - setNotStalling(); gapController.stallReported = true; gapController.nudgeRetry = 1; gapController.stallDetectedAtTime = 4200; @@ -202,19 +217,8 @@ describe('checkBuffer', function () { expect(fixStallStub).to.have.not.been.called; }); - it('should trigger reportStall when stalling for 1 second or longer', function () { - setStalling(); - const clock = sandbox.useFakeTimers(0); - clock.tick(1000); - gapController.stallDetectedAtTime = 1; - gapController.poll(lastCurrentTime); - - expect(reportStallSpy).to.have.not.been.called; - - clock.tick(1001); - gapController.poll(lastCurrentTime); + // TODO: spec conditions on media (and events) for stall detection - expect(reportStallSpy).to.have.been.calledOnce; - }); + // TODO: spec initial gap skipping }); }); From 232a3949be9ab6302fe763a9ea5700d9e49b5bbf Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Thu, 17 Oct 2019 17:04:53 +0200 Subject: [PATCH 16/42] gap-controller: handle only "waiting" media el event as stall resolution trigger --- src/controller/gap-controller.js | 23 +++++++++++------------ 1 file changed, 11 insertions(+), 12 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index ae77111d20e..3ba96e0a567 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -27,7 +27,7 @@ export default class GapController { * @private * @member {number | null} * This keeps state of the time a stall was detected. - * It will make sure we only report a stall as one when within the min stall duration. + * It will make sure we only report a stall as one when within the min stall threshold duration. */ this.stallDetectedAtTime = null; @@ -55,13 +55,12 @@ export default class GapController { * @private * @member {EventListener} */ - this.onMediaStalled = null; + this.onMediaElWaiting = null; } destroy () { - if (this.onMediaStalled) { - this.media.removeEventListener('waiting', this.onMediaStalled); - this.media.removeEventListener('stalled', this.onMediaStalled); + if (this.onMediaElWaiting) { + this.media.removeEventListener('waiting', this.onMediaElWaiting); } } @@ -125,10 +124,9 @@ export default class GapController { this.hasPlayed = true; // lazy setup media event listeners if not done yet - if (!this.onMediaStalled) { - this.onMediaStalled = this._onMediaStalled.bind(this); - this.media.addEventListener('waiting', this.onMediaStalled); - this.media.addEventListener('stalled', this.onMediaStalled); + if (!this.onMediaElWaiting) { + this.onMediaElWaiting = this._onMediaElWaiting.bind(this); + this.media.addEventListener('waiting', this.onMediaElWaiting); } // we can return early here to be lazy on rewriting other member values @@ -167,7 +165,7 @@ export default class GapController { } } - _onMediaStalled () { + _onMediaElWaiting () { const media = this.media; if (media.readyState < 2) { return; @@ -197,15 +195,16 @@ export default class GapController { logger.warn(`Stall detected at playhead position ${currentPlayheadTime}, buffered-time-ranges info: ${JSON.stringify(bufferInfo)}`); if (!this.stallDetectedAtTime) { - logger.warn('Silently ignoring first detected stall within minimum duration, storing timestamp: ' + now); + logger.debug('Silently ignoring first detected stall within threshold duration. Storing local perf-timestamp: ' + now); this.stallDetectedAtTime = now; return; } + // when we reach here, it means a stall was detected before, we check the diff to the min threshold const stalledDurationMs = now - this.stallDetectedAtTime; if (stalledDurationMs >= STALL_MINIMUM_DURATION_MS) { logger.warn('Stall detected after min stall duration, reporting error'); - // Report stalling after trying to fix + // Report stalling before trying to fix this._reportStall(bufferInfo.len); } From 0ef764afbe419bfc6b0fcf59ec6112b9a96f2563 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Thu, 17 Oct 2019 17:17:16 +0200 Subject: [PATCH 17/42] stream-controller: call gap-controller destroy method on media detaching --- src/controller/stream-controller.js | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/src/controller/stream-controller.js b/src/controller/stream-controller.js index eb71658c991..f61df978234 100644 --- a/src/controller/stream-controller.js +++ b/src/controller/stream-controller.js @@ -681,6 +681,10 @@ class StreamController extends BaseStreamController { this.startPosition = this.lastCurrentTime = 0; } + // release gap-controller + this.gapController.destroy(); + this.gapController = null; + // reset fragment backtracked flag let levels = this.levels; if (levels) { @@ -692,6 +696,7 @@ class StreamController extends BaseStreamController { } }); } + // remove video listeners if (media) { media.removeEventListener('seeking', this.onvseeking); @@ -699,6 +704,7 @@ class StreamController extends BaseStreamController { media.removeEventListener('ended', this.onvended); this.onvseeking = this.onvseeked = this.onvended = null; } + this.fragmentTracker.removeAllFragments(); this.media = this.mediaBuffer = null; this.loadedmetadata = false; From a8eb20ea521485a1aa8f78a6f39df867d1408d34 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Thu, 17 Oct 2019 17:24:15 +0200 Subject: [PATCH 18/42] gap-controller: in poll, use local media el object ref --- src/controller/gap-controller.js | 13 +++++++------ 1 file changed, 7 insertions(+), 6 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index 3ba96e0a567..3e5e571a181 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -71,9 +71,10 @@ export default class GapController { * @param {number} previousPlayheadTime Previously read playhead position */ poll (previousPlayheadTime) { + const media = this.media; if (!this.hasPlayed) { - const mediaCurrentTime = this.media.currentTime; - if (!isFiniteNumber(mediaCurrentTime) || this.media.buffered.length === 0) { + const mediaCurrentTime = media.currentTime; + if (!isFiniteNumber(mediaCurrentTime) || media.buffered.length === 0) { return; } // Checking what the buffer reports as start time for the first fragment appended. @@ -82,15 +83,15 @@ export default class GapController { // to fix eventual issues with browser-internal thresholds // where some MSE implementation might not play when the playhead // is exactly on the start value (trying to overcome what would be a browser bug). - const firstBufferedPosition = this.media.buffered.start(0); - if ((firstBufferedPosition - mediaCurrentTime > 0) && !this.media.seeking) { + const firstBufferedPosition = media.buffered.start(0); + if ((firstBufferedPosition - mediaCurrentTime > 0) && !media.seeking) { logger.warn(`skipping over gap at startup (first segment buffered time-range starts partially later than assumed) from ${mediaCurrentTime} to ${firstBufferedPosition} seconds`); - this.media.currentTime = firstBufferedPosition + SKIP_BUFFER_HOLE_STEP_SECONDS; + media.currentTime = firstBufferedPosition + SKIP_BUFFER_HOLE_STEP_SECONDS; } } // if we are paused and played before, don't bother at all - if (this.hasPlayed && this.media.paused) { + if (this.hasPlayed && media.paused) { return; } From 8af1724baf1f6c8a9fe9e9a113bc809c54f00e0e Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Thu, 17 Oct 2019 17:26:25 +0200 Subject: [PATCH 19/42] gap-controller: when skipping initial gap before having played, do not use additional margin --- src/controller/gap-controller.js | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index 3e5e571a181..57670f39dd5 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -79,14 +79,10 @@ export default class GapController { } // Checking what the buffer reports as start time for the first fragment appended. // We skip the playhead to this position to overcome an apparent initial gap in the stream. - // We add a margin value on top (same as the one used for playhead nudging on stall detection) - // to fix eventual issues with browser-internal thresholds - // where some MSE implementation might not play when the playhead - // is exactly on the start value (trying to overcome what would be a browser bug). const firstBufferedPosition = media.buffered.start(0); if ((firstBufferedPosition - mediaCurrentTime > 0) && !media.seeking) { logger.warn(`skipping over gap at startup (first segment buffered time-range starts partially later than assumed) from ${mediaCurrentTime} to ${firstBufferedPosition} seconds`); - media.currentTime = firstBufferedPosition + SKIP_BUFFER_HOLE_STEP_SECONDS; + media.currentTime = firstBufferedPosition; } } From 1324ef505e0056ab88568f4912b7debe54bc2d56 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Thu, 17 Oct 2019 17:29:21 +0200 Subject: [PATCH 20/42] gap-controller: retun from poll handler after skipping any initial gap --- src/controller/gap-controller.js | 1 + 1 file changed, 1 insertion(+) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index 57670f39dd5..db43e26b687 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -83,6 +83,7 @@ export default class GapController { if ((firstBufferedPosition - mediaCurrentTime > 0) && !media.seeking) { logger.warn(`skipping over gap at startup (first segment buffered time-range starts partially later than assumed) from ${mediaCurrentTime} to ${firstBufferedPosition} seconds`); media.currentTime = firstBufferedPosition; + return; } } From a5239312408d52ad331e67a57cd3bf6540dee3a7 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Thu, 17 Oct 2019 17:31:18 +0200 Subject: [PATCH 21/42] gap-controller: remove redundant local var decl --- src/controller/gap-controller.js | 1 - 1 file changed, 1 deletion(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index db43e26b687..22cfe7e0e96 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -142,7 +142,6 @@ export default class GapController { // If it was reported stalled, let's log the recovery if (this.stallReported) { const now = window.performance.now(); - const currentPlayheadTime = this.media.currentTime; logger.warn(`playhead not stalled anymore @${currentPlayheadTime}, after ${(now - this.stallDetectedAtTime)} ms`); this.stallReported = false; From d034d03bb9fa8d2db6eb70ec9f995033aaace708 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Thu, 17 Oct 2019 17:38:05 +0200 Subject: [PATCH 22/42] gap-controller: _isMediaInPlayableState: return true for all inverse cases by default --- src/controller/gap-controller.js | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index 22cfe7e0e96..d7fd1685b0b 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -153,13 +153,19 @@ export default class GapController { _isMediaInPlayableState () { const currentPlayheadTime = this.currentPlayheadTime; const media = this.media; + // the first case of unplayable media lies in it being in an "ended" state, or not being "ready", + // the necessary data not being available, which can essentially be see from the buffered time-ranges, + // but more clearly from the readyState property the browser exposes for the media element. if (media.ended || !media.buffered.length || media.readyState <= 2) { return false; + // the other cases of unplayable are when the media is seeking, and the targetted time for this + // is not yet in the buffered time-ranges, meaning that this position can not be decoded or played + // in any forseeable latency (or maybe never depending on wether the data for this media time will ever be received/demuxed). } else if (media.seeking && !BufferHelper.isBuffered(media, currentPlayheadTime)) { return false; - } else { - return true; } + // for all other cases we assume by inverse logic conditions that media is in a playable state + return true; } _onMediaElWaiting () { From 3ecf7a5e0d421bb39e79601e28244fa3b7664385 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Fri, 18 Oct 2019 15:12:28 +0200 Subject: [PATCH 23/42] gap-controller unit tests: import named symbols and default in one line --- tests/unit/controller/gap-controller.js | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/tests/unit/controller/gap-controller.js b/tests/unit/controller/gap-controller.js index 531dd165214..502bacbdf12 100644 --- a/tests/unit/controller/gap-controller.js +++ b/tests/unit/controller/gap-controller.js @@ -2,8 +2,7 @@ import sinon from 'sinon'; import Hls from '../../../src/hls'; -import GapController from '../../../src/controller/gap-controller'; // eslint-disable-line import/no-duplicates -import { STALL_MINIMUM_DURATION_MS } from '../../../src/controller/gap-controller'; // eslint-disable-line import/no-duplicates +import GapController, { STALL_MINIMUM_DURATION_MS, STALL_HANDLING_RETRY_PERIOD_MS } from '../../../src/controller/gap-controller'; import { FragmentTracker } from '../../../src/controller/fragment-tracker'; import Event from '../../../src/events'; From 4de01051ad92e782f128a66e1e0cfcdda70a7aae Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Fri, 18 Oct 2019 15:13:41 +0200 Subject: [PATCH 24/42] gap-controller unit tests: add specs for internal state progression + media playable states validation --- tests/unit/controller/gap-controller.js | 124 ++++++++++++++++++++---- 1 file changed, 105 insertions(+), 19 deletions(-) diff --git a/tests/unit/controller/gap-controller.js b/tests/unit/controller/gap-controller.js index 502bacbdf12..c971e98807d 100644 --- a/tests/unit/controller/gap-controller.js +++ b/tests/unit/controller/gap-controller.js @@ -113,15 +113,19 @@ describe('GapController', function () { }); }); - describe('poll', function () { + describe('media clock polling', function () { + const TIMER_STEP_MS = 1234; + let mockMedia; let mockTimeRanges; let mockTimeRangesData; let reportStallSpy; let lastCurrentTime; let isStalling; + let wallClock; beforeEach(function () { + wallClock = sandbox.useFakeTimers(0); isStalling = false; mockTimeRangesData = [[100, 200], [400, 500]]; mockTimeRanges = { @@ -134,6 +138,10 @@ describe('GapController', function () { } }; + // by default the media + // is setup in a "playable" state + // note that the initial current time + // is within the range of buffered data info mockMedia = { currentTime: 100, paused: false, @@ -146,56 +154,97 @@ describe('GapController', function () { reportStallSpy = sandbox.spy(gapController, '_reportStall'); }); - function tickMediaClock () { + // tickMediaClock emulates the behavior + // of our external polling schedule + // which would progress as the media clock + // is altered (or not) + // when isStalling is false the media clock + // will not progress while the poll call is done + function tickMediaClock (incrementSec = 0.1) { lastCurrentTime = mockMedia.currentTime; if (!isStalling) { - mockMedia.currentTime++; + mockMedia.currentTime += incrementSec; } + gapController.poll(lastCurrentTime); } - it('should try to fix a stall if expected to be playing', function () { - const clock = sandbox.useFakeTimers(0); - - const TIMER_STEP_MS = 1234; - - clock.tick(TIMER_STEP_MS); + it('should progress internally as specified to handle a stalled playable media properly as wall clock advances', function () { + wallClock.tick(TIMER_STEP_MS); const fixStallStub = sandbox.stub(gapController, '_tryFixBufferStall'); + expect(gapController.hasPlayed).to.equal(false); + // we need to play a bit to get past the hasPlayed check tickMediaClock(); - gapController.poll(lastCurrentTime); - // check the flag has turned true + // check the hasPlayed flag has turned true expect(gapController.hasPlayed).to.equal(true); + // check that stall detection flags are still reset + expect(gapController.stallDetectedAtTime).to.equal(null); + expect(gapController.stallHandledAtTime).to.equal(null); + expect(gapController.stallReported).to.equal(false); + // set stalling and tick media again isStalling = true; tickMediaClock(); - // now poll again - gapController.poll(lastCurrentTime); + // check that stall has been detected expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS); + // check that stall has not been flagged reported expect(gapController.stallReported).to.equal(false); - clock.tick(STALL_MINIMUM_DURATION_MS / 2); + wallClock.tick(STALL_MINIMUM_DURATION_MS / 2); + tickMediaClock(); - gapController.poll(lastCurrentTime); - // if poll within debounce interval, flags should be unchanged + // if stall was only sustained for below min duration, flags should be unchanged // and no stall reported yet expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS); expect(gapController.stallReported).to.equal(false); - clock.tick(STALL_MINIMUM_DURATION_MS / 2); + // more polling calls may happen without sys clock changing necessarily + // the internal state should be imutated + tickMediaClock(); + tickMediaClock(); - gapController.poll(lastCurrentTime); + // if stall was only sustained for below min duration, flags should be unchanged + // and no stall reported yet + expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); + expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS); + expect(gapController.stallReported).to.equal(false); + // advance wall clock above threshold and tick media clock + wallClock.tick(STALL_MINIMUM_DURATION_MS / 2); + tickMediaClock(); + + // now more time has passed than the min stall duration + // which is threshold for reporting + // inital detection time stays imuted expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); + // the handling timestamp gets updated expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS + STALL_MINIMUM_DURATION_MS); expect(gapController.stallReported).to.equal(true); + expect(reportStallSpy).to.have.been.calledOnce; expect(fixStallStub).to.have.been.calledOnce; + + tickMediaClock(); + tickMediaClock(); + wallClock.tick(STALL_HANDLING_RETRY_PERIOD_MS / 2); + tickMediaClock(); + + // if the wall clock doesn't advance beyond the retry time + // we should not call the specific handlers to fix stalls again + expect(reportStallSpy).to.have.been.calledOnce; + expect(fixStallStub).to.have.been.calledOnce; + + wallClock.tick(STALL_HANDLING_RETRY_PERIOD_MS / 2); + tickMediaClock(); + + expect(reportStallSpy).to.have.been.calledTwice; + expect(fixStallStub).to.have.been.calledTwice; }); it('should reset stall flags when no longer stalling', function () { @@ -213,10 +262,47 @@ describe('GapController', function () { expect(gapController.nudgeRetry).to.equal(0); expect(gapController.stallReported).to.equal(false); + expect(reportStallSpy).to.have.not.been.called; + expect(fixStallStub).to.have.not.been.called; }); - // TODO: spec conditions on media (and events) for stall detection + it('should detect when media is (not) playable and detect stalls respectively', function () { + wallClock.tick(TIMER_STEP_MS); + + // we need to play a bit to get past the hasPlayed check + tickMediaClock(); + + isStalling = true; + + // we need a readyState > 2 to expect media to playback + mockMedia.readyState = 2; + + tickMediaClock(); + expect(gapController.stallDetectedAtTime).to.equal(null); + wallClock.tick(2 * STALL_HANDLING_RETRY_PERIOD_MS); + + mockMedia.readyState = 4; + mockMedia.ended = true; + + tickMediaClock(); + expect(gapController.stallDetectedAtTime).to.equal(null); + wallClock.tick(2 * STALL_HANDLING_RETRY_PERIOD_MS); + + mockMedia.ended = false; + mockMedia.buffered.length = 0; + + tickMediaClock(); + expect(gapController.stallDetectedAtTime).to.equal(null); + wallClock.tick(2 * STALL_HANDLING_RETRY_PERIOD_MS); + + mockMedia.buffered.length = mockTimeRangesData.length; + mockMedia.seeking = true; + + // tickMediaClock(100) + expect(gapController.stallDetectedAtTime).to.equal(null); + wallClock.tick(2 * STALL_HANDLING_RETRY_PERIOD_MS); + }); // TODO: spec initial gap skipping }); From 62296532b11fa5ae79970e6a6a93584c8b7e9e7f Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Fri, 18 Oct 2019 15:14:38 +0200 Subject: [PATCH 25/42] gap-controller: documentation/comments improvements --- src/controller/gap-controller.js | 23 +++++++++++++++-------- 1 file changed, 15 insertions(+), 8 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index d7fd1685b0b..c2015ea5a20 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -18,10 +18,11 @@ export default class GapController { /** * @private - * @member {boolean} - * Flag set when a flag was detected and appeared to be sustained for more than the stall minimum duration. + * @member {number | null} + * This keeps state of handling stalls (once detected) to throttle the retry pace, + * and thus will get updated on each retry. */ - this.stallReported = false; + this.stallHandledAtTime = null; /** * @private @@ -33,11 +34,10 @@ export default class GapController { /** * @private - * @member {number | null} - * This keeps state of handling stalls (once detected) to throttle the retry pace, - * and thus will get updated on each retry. + * @member {boolean} + * Flag set when a flag was detected and appeared to be sustained for more than the stall minimum duration. */ - this.stallHandledAtTime = null; + this.stallReported = false; /** * @private @@ -203,7 +203,8 @@ export default class GapController { return; } - // when we reach here, it means a stall was detected before, we check the diff to the min threshold + // when we reach here, it means a stall was detected before, + // we check the diff to the min threshold const stalledDurationMs = now - this.stallDetectedAtTime; if (stalledDurationMs >= STALL_MINIMUM_DURATION_MS) { logger.warn('Stall detected after min stall duration, reporting error'); @@ -232,9 +233,15 @@ export default class GapController { // Try to skip over the buffer hole caused by a partial fragment // This method isn't limited by the size of the gap between buffered ranges this._trySkipBufferHole(partial); + // we return here in this case, meaning + // the branch below only executes when we don't handle a partial fragment return; } + // if we haven't had to skip over a buffer hole of a partial fragment + // we may just have to "nudge" the playlist as the browser decoding/rendering engine + // needs to cross some sort of threshold covering all source-buffers content + // to start playing properly. if (bufferInfo.len > JUMP_THRESHOLD_SECONDS && stalledDurationMs > config.highBufferWatchdogPeriod * 1000) { logger.log('Trying to nudge playhead over buffer-hole'); From 047e15d64b969dea580405fd6ea167ad2452eef2 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Fri, 18 Oct 2019 15:52:39 +0200 Subject: [PATCH 26/42] gap-controller: add unit tests for initial gap skipping + paused/hasPlayed cases --- tests/unit/controller/gap-controller.js | 75 ++++++++++++++++++++++++- 1 file changed, 74 insertions(+), 1 deletion(-) diff --git a/tests/unit/controller/gap-controller.js b/tests/unit/controller/gap-controller.js index c971e98807d..16655fbce2a 100644 --- a/tests/unit/controller/gap-controller.js +++ b/tests/unit/controller/gap-controller.js @@ -304,6 +304,79 @@ describe('GapController', function () { wallClock.tick(2 * STALL_HANDLING_RETRY_PERIOD_MS); }); - // TODO: spec initial gap skipping + it('should not handle a stall (clock not advancing) when media has played before and is now paused', function () { + wallClock.tick(TIMER_STEP_MS); + + tickMediaClock(); + + expect(gapController.hasPlayed).to.equal(true); + expect(gapController.stallDetectedAtTime).to.equal(null); + expect(gapController.stallHandledAtTime).to.equal(null); + + mockMedia.paused = true; + isStalling = true; + + tickMediaClock(); + + expect(gapController.stallDetectedAtTime).to.equal(null); + expect(gapController.stallHandledAtTime).to.equal(null); + + mockMedia.paused = false; + + tickMediaClock(); + + expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); + expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS); + }); + + it('should handle a stall when getting a waiting event and media clock is on buffered time-range', function () { + wallClock.tick(TIMER_STEP_MS); + + tickMediaClock(); + + expect(gapController.hasPlayed).to.equal(true); + expect(gapController.stallDetectedAtTime).to.equal(null); + expect(gapController.stallHandledAtTime).to.equal(null); + + gapController._onMediaElWaiting(); + + expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); + expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS); + }); + + it('should detect/handle stalls also when media never played yet (regardless if paused flag is set or not)', function () { + wallClock.tick(TIMER_STEP_MS); + + // set stalling from the start + isStalling = true; + + tickMediaClock(); + + expect(gapController.hasPlayed).to.equal(false); + expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); + expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS); + + wallClock.tick(2 * STALL_HANDLING_RETRY_PERIOD_MS); + + mockMedia.paused = true; + + tickMediaClock(); + + expect(gapController.hasPlayed).to.equal(false); + expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); + expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS + 2 * STALL_HANDLING_RETRY_PERIOD_MS); + }); + + it('should skip any initial gap when not having played yet', function () { + wallClock.tick(TIMER_STEP_MS); + + mockMedia.currentTime = 0; + + isStalling = true; + + tickMediaClock(); + + expect(mockMedia.currentTime).to.equal(100); + }); }); }); From 43a91a1036fc3f055d7c0f9a9cb8903c3a77fa36 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Fri, 18 Oct 2019 15:53:24 +0200 Subject: [PATCH 27/42] gap-controller: improve some log lines --- src/controller/gap-controller.js | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index c2015ea5a20..898503f5f53 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -183,6 +183,7 @@ export default class GapController { const now = window.performance.now(); const media = this.media; + // limit the max frequency of stall handling i.e minimum retry period if (this.stallHandledAtTime !== null && now - this.stallHandledAtTime < STALL_HANDLING_RETRY_PERIOD_MS) { return; @@ -222,7 +223,7 @@ export default class GapController { * @private */ _tryFixBufferStall (bufferInfo, stalledDurationMs) { - logger.warn('Trying to fix stalled playhead on buffered time-range ...'); + logger.warn(`Trying to fix stalled playhead on buffered time-range since ${stalledDurationMs} ms ...`); const { config, fragmentTracker, media } = this; const playheadTime = media.currentTime; @@ -263,7 +264,7 @@ export default class GapController { if (!stallReported) { // Report stalled error once this.stallReported = true; - logger.warn(`Playback stalling at @${media.currentTime} due to low buffer`); + logger.warn(`Media element playhead stalling at ${media.currentTime} secs; but should be playing`); hls.trigger(Event.ERROR, { type: ErrorTypes.MEDIA_ERROR, details: ErrorDetails.BUFFER_STALLED_ERROR, @@ -314,7 +315,7 @@ export default class GapController { if (nudgeRetry < config.nudgeMaxRetry) { const targetTime = currentTime + nudgeRetry * config.nudgeOffset; - logger.log(`adjust currentTime from ${currentTime} to ${targetTime}`); + logger.log(`Adjusting media-element currentTime from ${currentTime} to ${targetTime}`); // playback stalled in buffered area ... let's nudge currentTime to try to overcome this media.currentTime = targetTime; @@ -324,7 +325,7 @@ export default class GapController { fatal: false }); } else { - logger.error(`still stuck in high buffer @${currentTime} after ${config.nudgeMaxRetry}, raise fatal error`); + logger.error(`Playhead still not moving while enough data buffered @${currentTime} after ${config.nudgeMaxRetry} tries to fix. Raising fatal error now`); hls.trigger(Event.ERROR, { type: ErrorTypes.MEDIA_ERROR, details: ErrorDetails.BUFFER_STALLED_ERROR, From 58f7b24f38ac17de866fdeaacd04c17193a11c29 Mon Sep 17 00:00:00 2001 From: Stephan Hesse Date: Sat, 19 Oct 2019 15:09:22 +0200 Subject: [PATCH 28/42] gap-controller: add handling for audio-only autoplay issues in Chrome on ultimate playhead-nudge retry, we can assume there may be a real issue with the browser not allowing playback for another reason than some of the situations we could have resolved by the first attempts to fix. now we can try and handle a real situation happening on Chrome with some audio-only content: it seems that the playback is "blocked" there because of something related to auto-play policies. the only programmtic way to resolve this (we can always fix this with a real UI event calling play or using browser/device controls) has been found to set the media element to muted state. In this case a programmatic play() will work (as opposed to when the media is not muted, where the browser will seem to ignore the intent plainly, eventually waiting for more user action) --- src/config.ts | 6 ++++++ src/controller/gap-controller.js | 11 ++++++++++- 2 files changed, 16 insertions(+), 1 deletion(-) diff --git a/src/config.ts b/src/config.ts index efc8e27c7e1..c7e21a5e1d6 100644 --- a/src/config.ts +++ b/src/config.ts @@ -124,6 +124,10 @@ type TSDemuxerConfig = { forceKeyFrameOnDiscontinuity: boolean, }; +type GapControllerConfig = { + enforceAutoPlayByMutingAudioOnly: boolean +}; + export type HlsConfig = { debug: boolean, @@ -159,6 +163,7 @@ export type HlsConfig = PlaylistLoaderConfig & StreamControllerConfig & Partial & + GapControllerConfig & TSDemuxerConfig; // If possible, keep hlsDefaultConfig shallow @@ -175,6 +180,7 @@ export const hlsDefaultConfig: HlsConfig = { maxBufferLength: 30, // used by stream-controller maxBufferSize: 60 * 1000 * 1000, // used by stream-controller maxBufferHole: 0.5, // used by stream-controller + enforceAutoPlayByMutingAudioOnly: true, // used by gap-controller lowBufferWatchdogPeriod: 0.5, // used by stream-controller highBufferWatchdogPeriod: 3, // used by stream-controller diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index 898503f5f53..d78bb36f53b 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -315,10 +315,19 @@ export default class GapController { if (nudgeRetry < config.nudgeMaxRetry) { const targetTime = currentTime + nudgeRetry * config.nudgeOffset; - logger.log(`Adjusting media-element currentTime from ${currentTime} to ${targetTime}`); // playback stalled in buffered area ... let's nudge currentTime to try to overcome this + logger.log(`Adjusting media-element 'currentTime' from ${currentTime} to ${targetTime}`); media.currentTime = targetTime; + if (nudgeRetry === config.nudgeMaxRetry - 1) { + logger.warn('Lastly: Attempting to un-stall playback state by over-calling media-element play() (this should not be necessary, ouch ...)'); + if (config.enforceAutoPlayByMutingAudioOnly) { + logger.warn('Muting media audio now! Needed to allow non-UI-event scheduled play() call (this is a workaround to audio-only autoplay issues on Chrome)'); + media.muted = true; + } + media.play(); + } + hls.trigger(Event.ERROR, { type: ErrorTypes.MEDIA_ERROR, details: ErrorDetails.BUFFER_NUDGE_ON_STALL, From 2502a316e101c0cf56e52d9dfbff5c57f6f821b6 Mon Sep 17 00:00:00 2001 From: Rob Walch Date: Wed, 20 Nov 2019 16:26:05 -0500 Subject: [PATCH 29/42] Update gap-controller to match v1 branch --- src/config.ts | 6 - src/controller/gap-controller.js | 236 +++++------------------- src/controller/stream-controller.js | 21 +-- tests/unit/controller/gap-controller.js | 124 +++++-------- 4 files changed, 94 insertions(+), 293 deletions(-) diff --git a/src/config.ts b/src/config.ts index c7e21a5e1d6..efc8e27c7e1 100644 --- a/src/config.ts +++ b/src/config.ts @@ -124,10 +124,6 @@ type TSDemuxerConfig = { forceKeyFrameOnDiscontinuity: boolean, }; -type GapControllerConfig = { - enforceAutoPlayByMutingAudioOnly: boolean -}; - export type HlsConfig = { debug: boolean, @@ -163,7 +159,6 @@ export type HlsConfig = PlaylistLoaderConfig & StreamControllerConfig & Partial & - GapControllerConfig & TSDemuxerConfig; // If possible, keep hlsDefaultConfig shallow @@ -180,7 +175,6 @@ export const hlsDefaultConfig: HlsConfig = { maxBufferLength: 30, // used by stream-controller maxBufferSize: 60 * 1000 * 1000, // used by stream-controller maxBufferHole: 0.5, // used by stream-controller - enforceAutoPlayByMutingAudioOnly: true, // used by gap-controller lowBufferWatchdogPeriod: 0.5, // used by stream-controller highBufferWatchdogPeriod: 3, // used by stream-controller diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index d78bb36f53b..b3f4241a9a2 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -2,10 +2,8 @@ import { BufferHelper } from '../utils/buffer-helper'; import { ErrorTypes, ErrorDetails } from '../errors'; import Event from '../events'; import { logger } from '../utils/logger'; -import { isFiniteNumber } from '../polyfills/number-isFinite'; -export const STALL_MINIMUM_DURATION_MS = 1000; -export const STALL_HANDLING_RETRY_PERIOD_MS = 1000; +export const STALL_MINIMUM_DURATION_MS = 250; export const JUMP_THRESHOLD_SECONDS = 0.5; // tolerance needed as some browsers stalls playback before reaching buffered range end export const SKIP_BUFFER_HOLE_STEP_SECONDS = 0.1; @@ -15,205 +13,71 @@ export default class GapController { this.media = media; this.fragmentTracker = fragmentTracker; this.hls = hls; - - /** - * @private - * @member {number | null} - * This keeps state of handling stalls (once detected) to throttle the retry pace, - * and thus will get updated on each retry. - */ - this.stallHandledAtTime = null; - - /** - * @private - * @member {number | null} - * This keeps state of the time a stall was detected. - * It will make sure we only report a stall as one when within the min stall threshold duration. - */ - this.stallDetectedAtTime = null; - - /** - * @private - * @member {boolean} - * Flag set when a flag was detected and appeared to be sustained for more than the stall minimum duration. - */ + this.nudgeRetry = 0; this.stallReported = false; - - /** - * @private - * @member {number | null} - */ - this.currentPlayheadTime = null; - - /** - * @private - * @member {boolean} - */ - this.hasPlayed = false; - - /** - * @private - * @member {EventListener} - */ - this.onMediaElWaiting = null; - } - - destroy () { - if (this.onMediaElWaiting) { - this.media.removeEventListener('waiting', this.onMediaElWaiting); - } + this.stalled = null; + this.moved = false; } /** * Checks if the playhead is stuck within a gap, and if so, attempts to free it. * A gap is an unbuffered range between two buffered ranges (or the start and the first buffered range). * - * @param {number} previousPlayheadTime Previously read playhead position + * @param {number} lastCurrentTime Previously read playhead position */ - poll (previousPlayheadTime) { - const media = this.media; - if (!this.hasPlayed) { - const mediaCurrentTime = media.currentTime; - if (!isFiniteNumber(mediaCurrentTime) || media.buffered.length === 0) { - return; - } - // Checking what the buffer reports as start time for the first fragment appended. - // We skip the playhead to this position to overcome an apparent initial gap in the stream. - const firstBufferedPosition = media.buffered.start(0); - if ((firstBufferedPosition - mediaCurrentTime > 0) && !media.seeking) { - logger.warn(`skipping over gap at startup (first segment buffered time-range starts partially later than assumed) from ${mediaCurrentTime} to ${firstBufferedPosition} seconds`); - media.currentTime = firstBufferedPosition; - return; - } - } - - // if we are paused and played before, don't bother at all - if (this.hasPlayed && media.paused) { - return; - } + poll (lastCurrentTime) { + const { config, media, stalled } = this; + const currentTime = media.currentTime; + const tnow = self.performance.now(); // The playhead is moving, no-op - if (this._checkPlayheadHasMoved(previousPlayheadTime)) { + if (currentTime !== lastCurrentTime) { + this.moved = true; + if (stalled !== null) { + // The playhead is now moving, but was previously stalled + if (this.stallReported) { + logger.warn(`playback not stuck anymore @${currentTime}, after ${Math.round(tnow - stalled)}ms`); + this.stallReported = false; + } + this.stalled = null; + this.nudgeRetry = 0; + } return; } - // not moving ... check if we need to handle stall - if (this.stallDetectedAtTime !== null || this._isMediaInPlayableState()) { - this._handleStall(); - } - } - - _checkPlayheadHasMoved (previousPlayheadTime) { - const media = this.media; - - // read current playhead position - const currentPlayheadTime = media.currentTime; - // update internal store - this.currentPlayheadTime = currentPlayheadTime; - - // not moved - return false here - if (currentPlayheadTime === previousPlayheadTime) { - return false; - } - - // has moved ... - will return true from here - // but need to (re-)init internal state - - this.hasPlayed = true; - - // lazy setup media event listeners if not done yet - if (!this.onMediaElWaiting) { - this.onMediaElWaiting = this._onMediaElWaiting.bind(this); - this.media.addEventListener('waiting', this.onMediaElWaiting); - } - - // we can return early here to be lazy on rewriting other member values - if (this.stallDetectedAtTime === null) { - return true; - } - - logger.log(`playhead seemed stalled but is now moving again from ${previousPlayheadTime} to ${currentPlayheadTime}`); - - // reset all the stall flags - this.stallHandledAtTime = null; - this.stallDetectedAtTime = null; - this.nudgeRetry = 0; - - // If it was reported stalled, let's log the recovery - if (this.stallReported) { - const now = window.performance.now(); - logger.warn(`playhead not stalled anymore @${currentPlayheadTime}, after ${(now - this.stallDetectedAtTime)} ms`); - - this.stallReported = false; - } - - return true; - } - - _isMediaInPlayableState () { - const currentPlayheadTime = this.currentPlayheadTime; - const media = this.media; - // the first case of unplayable media lies in it being in an "ended" state, or not being "ready", - // the necessary data not being available, which can essentially be see from the buffered time-ranges, - // but more clearly from the readyState property the browser exposes for the media element. - if (media.ended || !media.buffered.length || media.readyState <= 2) { - return false; - // the other cases of unplayable are when the media is seeking, and the targetted time for this - // is not yet in the buffered time-ranges, meaning that this position can not be decoded or played - // in any forseeable latency (or maybe never depending on wether the data for this media time will ever be received/demuxed). - } else if (media.seeking && !BufferHelper.isBuffered(media, currentPlayheadTime)) { - return false; - } - // for all other cases we assume by inverse logic conditions that media is in a playable state - return true; - } - - _onMediaElWaiting () { - const media = this.media; - if (media.readyState < 2) { + if (media.paused || media.ended || media.playbackRate === 0 || !media.buffered.length) { return; } - if (BufferHelper.isBuffered(media, media.currentTime)) { - this._handleStall(); - } - } - - _handleStall () { - const now = window.performance.now(); - const media = this.media; - - // limit the max frequency of stall handling i.e minimum retry period - if (this.stallHandledAtTime !== null && - now - this.stallHandledAtTime < STALL_HANDLING_RETRY_PERIOD_MS) { + if (media.seeking && BufferHelper.isBuffered(media, currentTime)) { return; } - this.stallHandledAtTime = now; - // The playhead isn't moving but it should be // Allow some slack time to for small stalls to resolve themselves - const currentPlayheadTime = media.currentTime; - const bufferInfo = BufferHelper.bufferInfo(media, currentPlayheadTime, this.config.maxBufferHole); + const bufferInfo = BufferHelper.bufferInfo(media, currentTime, config.maxBufferHole); - logger.warn(`Stall detected at playhead position ${currentPlayheadTime}, buffered-time-ranges info: ${JSON.stringify(bufferInfo)}`); + if (!this.moved) { + if (!media.seeking && bufferInfo.nextStart) { + logger.warn(`skipping start gap, adjusting currentTime from ${currentTime} to ${bufferInfo.nextStart}`); + this.moved = true; + media.currentTime = bufferInfo.nextStart; + } + return; + } - if (!this.stallDetectedAtTime) { - logger.debug('Silently ignoring first detected stall within threshold duration. Storing local perf-timestamp: ' + now); - this.stallDetectedAtTime = now; + if (stalled === null) { + this.stalled = tnow; return; } - // when we reach here, it means a stall was detected before, - // we check the diff to the min threshold - const stalledDurationMs = now - this.stallDetectedAtTime; - if (stalledDurationMs >= STALL_MINIMUM_DURATION_MS) { - logger.warn('Stall detected after min stall duration, reporting error'); - // Report stalling before trying to fix + const stalledDuration = tnow - stalled; + if (!media.seeking && stalledDuration >= STALL_MINIMUM_DURATION_MS) { + // Report stalling after trying to fix this._reportStall(bufferInfo.len); } - this._tryFixBufferStall(bufferInfo, stalledDurationMs); + this._tryFixBufferStall(bufferInfo, stalledDuration); } /** @@ -223,14 +87,11 @@ export default class GapController { * @private */ _tryFixBufferStall (bufferInfo, stalledDurationMs) { - logger.warn(`Trying to fix stalled playhead on buffered time-range since ${stalledDurationMs} ms ...`); - const { config, fragmentTracker, media } = this; - const playheadTime = media.currentTime; + const currentTime = media.currentTime; - const partial = fragmentTracker.getPartialFragment(playheadTime); + const partial = fragmentTracker.getPartialFragment(currentTime); if (partial) { - logger.log('Trying to skip buffer-hole caused by partial fragment'); // Try to skip over the buffer hole caused by a partial fragment // This method isn't limited by the size of the gap between buffered ranges this._trySkipBufferHole(partial); @@ -249,7 +110,7 @@ export default class GapController { // Try to nudge currentTime over a buffer hole if we've been stalling for the configured amount of seconds // We only try to jump the hole if it's under the configured size // Reset stalled so to rearm watchdog timer - this.stallDetectedAtTime = null; + this.stalled = null; this._tryNudgeBuffer(); } } @@ -264,7 +125,7 @@ export default class GapController { if (!stallReported) { // Report stalled error once this.stallReported = true; - logger.warn(`Media element playhead stalling at ${media.currentTime} secs; but should be playing`); + logger.warn(`Playback stalling at @${media.currentTime} due to low buffer`); hls.trigger(Event.ERROR, { type: ErrorTypes.MEDIA_ERROR, details: ErrorDetails.BUFFER_STALLED_ERROR, @@ -289,7 +150,7 @@ export default class GapController { if (currentTime >= lastEndTime && currentTime < startTime) { media.currentTime = Math.max(startTime, media.currentTime + SKIP_BUFFER_HOLE_STEP_SECONDS); logger.warn(`skipping hole, adjusting currentTime from ${currentTime} to ${media.currentTime}`); - this.stallDetectedAtTime = null; + this.stalled = null; hls.trigger(Event.ERROR, { type: ErrorTypes.MEDIA_ERROR, details: ErrorDetails.BUFFER_SEEK_OVER_HOLE, @@ -316,25 +177,16 @@ export default class GapController { if (nudgeRetry < config.nudgeMaxRetry) { const targetTime = currentTime + nudgeRetry * config.nudgeOffset; // playback stalled in buffered area ... let's nudge currentTime to try to overcome this - logger.log(`Adjusting media-element 'currentTime' from ${currentTime} to ${targetTime}`); + logger.log(`Nudging 'currentTime' from ${currentTime} to ${targetTime}`); media.currentTime = targetTime; - if (nudgeRetry === config.nudgeMaxRetry - 1) { - logger.warn('Lastly: Attempting to un-stall playback state by over-calling media-element play() (this should not be necessary, ouch ...)'); - if (config.enforceAutoPlayByMutingAudioOnly) { - logger.warn('Muting media audio now! Needed to allow non-UI-event scheduled play() call (this is a workaround to audio-only autoplay issues on Chrome)'); - media.muted = true; - } - media.play(); - } - hls.trigger(Event.ERROR, { type: ErrorTypes.MEDIA_ERROR, details: ErrorDetails.BUFFER_NUDGE_ON_STALL, fatal: false }); } else { - logger.error(`Playhead still not moving while enough data buffered @${currentTime} after ${config.nudgeMaxRetry} tries to fix. Raising fatal error now`); + logger.error(`Playhead still not moving while enough data buffered @${currentTime} after ${config.nudgeMaxRetry} nudges`); hls.trigger(Event.ERROR, { type: ErrorTypes.MEDIA_ERROR, details: ErrorDetails.BUFFER_STALLED_ERROR, diff --git a/src/controller/stream-controller.js b/src/controller/stream-controller.js index f61df978234..532b0f62e04 100644 --- a/src/controller/stream-controller.js +++ b/src/controller/stream-controller.js @@ -361,18 +361,14 @@ class StreamController extends BaseStreamController { fragNextLoad = fragments[fragmentIndexRange - 1]; } - if (!fragNextLoad) { - return null; - } - - { + if (fragNextLoad) { const curSNIdx = fragNextLoad.sn - levelDetails.startSN; const sameLevel = fragPreviousLoad && fragNextLoad.level === fragPreviousLoad.level; const prevSnFrag = fragments[curSNIdx - 1]; const nextSnFrag = fragments[curSNIdx + 1]; // logger.log('find SN matching with pos:' + bufferEnd + ':' + frag.sn); - if (fragPreviousLoad && fragNextLoad.sn === fragPreviousLoad.sn) { // Q: why not use FragmentTracker to determine this condition? + if (fragPreviousLoad && fragNextLoad.sn === fragPreviousLoad.sn) { if (sameLevel && !fragNextLoad.backtracked) { if (fragNextLoad.sn < levelDetails.endSN) { let deltaPTS = fragPreviousLoad.deltaPTS; @@ -385,7 +381,7 @@ class StreamController extends BaseStreamController { logger.warn('Previous fragment was dropped with large PTS gap between audio and video. Maybe fragment is not starting with a keyframe? Loading previous one to try to overcome this'); } else { fragNextLoad = nextSnFrag; - logger.log(`Re-loading fragment with SN: ${fragNextLoad.sn}`); // Q: why? + logger.log(`Re-loading fragment with SN: ${fragNextLoad.sn}`); } } else { fragNextLoad = null; @@ -402,7 +398,7 @@ class StreamController extends BaseStreamController { fragNextLoad.dropped = 0; if (prevSnFrag) { fragNextLoad = prevSnFrag; - fragNextLoad.backtracked = true; // Q: why are we setting this flag to true, since it has to be true so we even reach this code? + fragNextLoad.backtracked = true; } else if (curSNIdx) { // can't backtrack on very first fragment fragNextLoad = null; @@ -457,7 +453,7 @@ class StreamController extends BaseStreamController { if (this.state !== nextState) { const previousState = this.state; this._state = nextState; - logger.log(`main stream-controller state-transition: ${previousState}->${nextState}`); + logger.log(`main stream-controller: ${previousState}->${nextState}`); this.hls.trigger(Event.STREAM_STATE_TRANSITION, { previousState, nextState }); } } @@ -681,10 +677,6 @@ class StreamController extends BaseStreamController { this.startPosition = this.lastCurrentTime = 0; } - // release gap-controller - this.gapController.destroy(); - this.gapController = null; - // reset fragment backtracked flag let levels = this.levels; if (levels) { @@ -712,7 +704,8 @@ class StreamController extends BaseStreamController { } onMediaSeeked () { - const media = this.media, currentTime = media ? media.currentTime : undefined; + const media = this.media; + const currentTime = media ? media.currentTime : undefined; if (Number.isFinite(currentTime)) { logger.log(`media seeked to ${currentTime.toFixed(3)}`); } diff --git a/tests/unit/controller/gap-controller.js b/tests/unit/controller/gap-controller.js index 16655fbce2a..498ea343b8a 100644 --- a/tests/unit/controller/gap-controller.js +++ b/tests/unit/controller/gap-controller.js @@ -2,7 +2,7 @@ import sinon from 'sinon'; import Hls from '../../../src/hls'; -import GapController, { STALL_MINIMUM_DURATION_MS, STALL_HANDLING_RETRY_PERIOD_MS } from '../../../src/controller/gap-controller'; +import GapController, { STALL_MINIMUM_DURATION_MS } from '../../../src/controller/gap-controller'; import { FragmentTracker } from '../../../src/controller/fragment-tracker'; import Event from '../../../src/events'; @@ -115,6 +115,7 @@ describe('GapController', function () { describe('media clock polling', function () { const TIMER_STEP_MS = 1234; + const STALL_HANDLING_RETRY_PERIOD_MS = 1000; let mockMedia; let mockTimeRanges; @@ -143,7 +144,7 @@ describe('GapController', function () { // note that the initial current time // is within the range of buffered data info mockMedia = { - currentTime: 100, + currentTime: 0, paused: false, readyState: 4, buffered: mockTimeRanges, @@ -173,16 +174,15 @@ describe('GapController', function () { const fixStallStub = sandbox.stub(gapController, '_tryFixBufferStall'); - expect(gapController.hasPlayed).to.equal(false); + expect(gapController.moved).to.equal(false); - // we need to play a bit to get past the hasPlayed check + // we need to play a bit to get past the moved check tickMediaClock(); - // check the hasPlayed flag has turned true - expect(gapController.hasPlayed).to.equal(true); + // check the moved flag has turned true + expect(gapController.moved).to.equal(true); // check that stall detection flags are still reset - expect(gapController.stallDetectedAtTime).to.equal(null); - expect(gapController.stallHandledAtTime).to.equal(null); + expect(gapController.stalled).to.equal(null); expect(gapController.stallReported).to.equal(false); // set stalling and tick media again @@ -190,30 +190,36 @@ describe('GapController', function () { tickMediaClock(); // check that stall has been detected - expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); - expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS); + expect(gapController.stalled).to.equal(TIMER_STEP_MS); // check that stall has not been flagged reported expect(gapController.stallReported).to.equal(false); + expect(reportStallSpy).to.not.have.been.called; + expect(fixStallStub).to.not.have.been.called; + wallClock.tick(STALL_MINIMUM_DURATION_MS / 2); tickMediaClock(); // if stall was only sustained for below min duration, flags should be unchanged // and no stall reported yet - expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); - expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS); + expect(gapController.stalled).to.equal(TIMER_STEP_MS); expect(gapController.stallReported).to.equal(false); + // nudge is attempted + expect(fixStallStub).to.have.been.calledOnce; // more polling calls may happen without sys clock changing necessarily - // the internal state should be imutated tickMediaClock(); + // nudge is attempted + expect(fixStallStub).to.have.been.calledTwice; + tickMediaClock(); // if stall was only sustained for below min duration, flags should be unchanged // and no stall reported yet - expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); - expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS); + expect(gapController.stalled).to.equal(TIMER_STEP_MS); expect(gapController.stallReported).to.equal(false); + // nudge is attempted + expect(fixStallStub).to.have.been.calledThrice; // advance wall clock above threshold and tick media clock wallClock.tick(STALL_MINIMUM_DURATION_MS / 2); @@ -221,44 +227,37 @@ describe('GapController', function () { // now more time has passed than the min stall duration // which is threshold for reporting - // inital detection time stays imuted - expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); - // the handling timestamp gets updated - expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS + STALL_MINIMUM_DURATION_MS); + // initial detection time is unchanged + expect(gapController.stalled).to.equal(TIMER_STEP_MS); expect(gapController.stallReported).to.equal(true); - expect(reportStallSpy).to.have.been.calledOnce; - expect(fixStallStub).to.have.been.calledOnce; + expect(fixStallStub).to.have.callCount(4); tickMediaClock(); tickMediaClock(); wallClock.tick(STALL_HANDLING_RETRY_PERIOD_MS / 2); tickMediaClock(); - // if the wall clock doesn't advance beyond the retry time - // we should not call the specific handlers to fix stalls again - expect(reportStallSpy).to.have.been.calledOnce; - expect(fixStallStub).to.have.been.calledOnce; + expect(reportStallSpy).to.have.been.callCount(4); + expect(fixStallStub).to.have.callCount(7); wallClock.tick(STALL_HANDLING_RETRY_PERIOD_MS / 2); tickMediaClock(); - expect(reportStallSpy).to.have.been.calledTwice; - expect(fixStallStub).to.have.been.calledTwice; + expect(reportStallSpy).to.have.been.callCount(5); + expect(fixStallStub).to.have.callCount(8); }); it('should reset stall flags when no longer stalling', function () { gapController.stallReported = true; gapController.nudgeRetry = 1; - gapController.stallDetectedAtTime = 4200; - gapController.stallHandledAtTime = 4201; + gapController.stalled = 4200; const fixStallStub = sandbox.stub(gapController, '_tryFixBufferStall'); gapController.poll(lastCurrentTime); - expect(gapController.stallDetectedAtTime).to.equal(null); - expect(gapController.stallHandledAtTime).to.equal(null); + expect(gapController.stalled).to.equal(null); expect(gapController.nudgeRetry).to.equal(0); expect(gapController.stallReported).to.equal(false); @@ -267,40 +266,31 @@ describe('GapController', function () { expect(fixStallStub).to.have.not.been.called; }); - it('should detect when media is (not) playable and detect stalls respectively', function () { + it('should not detect stalls when ended, unbuffered or seeking', function () { wallClock.tick(TIMER_STEP_MS); - // we need to play a bit to get past the hasPlayed check + // we need to play a bit to get past the moved check tickMediaClock(); isStalling = true; - - // we need a readyState > 2 to expect media to playback - mockMedia.readyState = 2; - - tickMediaClock(); - expect(gapController.stallDetectedAtTime).to.equal(null); - wallClock.tick(2 * STALL_HANDLING_RETRY_PERIOD_MS); - - mockMedia.readyState = 4; mockMedia.ended = true; tickMediaClock(); - expect(gapController.stallDetectedAtTime).to.equal(null); + expect(gapController.stalled).to.equal(null, 'ended'); wallClock.tick(2 * STALL_HANDLING_RETRY_PERIOD_MS); mockMedia.ended = false; mockMedia.buffered.length = 0; tickMediaClock(); - expect(gapController.stallDetectedAtTime).to.equal(null); + expect(gapController.stalled).to.equal(null, 'empty buffer'); wallClock.tick(2 * STALL_HANDLING_RETRY_PERIOD_MS); mockMedia.buffered.length = mockTimeRangesData.length; mockMedia.seeking = true; // tickMediaClock(100) - expect(gapController.stallDetectedAtTime).to.equal(null); + expect(gapController.stalled).to.equal(null, 'seeking'); wallClock.tick(2 * STALL_HANDLING_RETRY_PERIOD_MS); }); @@ -309,42 +299,24 @@ describe('GapController', function () { tickMediaClock(); - expect(gapController.hasPlayed).to.equal(true); - expect(gapController.stallDetectedAtTime).to.equal(null); - expect(gapController.stallHandledAtTime).to.equal(null); + expect(gapController.moved).to.equal(true); + expect(gapController.stalled).to.equal(null); mockMedia.paused = true; isStalling = true; tickMediaClock(); - expect(gapController.stallDetectedAtTime).to.equal(null); - expect(gapController.stallHandledAtTime).to.equal(null); + expect(gapController.stalled).to.equal(null); mockMedia.paused = false; tickMediaClock(); - expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); - expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS); - }); - - it('should handle a stall when getting a waiting event and media clock is on buffered time-range', function () { - wallClock.tick(TIMER_STEP_MS); - - tickMediaClock(); - - expect(gapController.hasPlayed).to.equal(true); - expect(gapController.stallDetectedAtTime).to.equal(null); - expect(gapController.stallHandledAtTime).to.equal(null); - - gapController._onMediaElWaiting(); - - expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); - expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS); + expect(gapController.stalled).to.equal(TIMER_STEP_MS); }); - it('should detect/handle stalls also when media never played yet (regardless if paused flag is set or not)', function () { + it('should jump start gaps', function () { wallClock.tick(TIMER_STEP_MS); // set stalling from the start @@ -352,19 +324,9 @@ describe('GapController', function () { tickMediaClock(); - expect(gapController.hasPlayed).to.equal(false); - expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); - expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS); - - wallClock.tick(2 * STALL_HANDLING_RETRY_PERIOD_MS); - - mockMedia.paused = true; - - tickMediaClock(); - - expect(gapController.hasPlayed).to.equal(false); - expect(gapController.stallDetectedAtTime).to.equal(TIMER_STEP_MS); - expect(gapController.stallHandledAtTime).to.equal(TIMER_STEP_MS + 2 * STALL_HANDLING_RETRY_PERIOD_MS); + expect(gapController.moved).to.equal(true); + expect(mockMedia.currentTime).to.equal(100); + expect(gapController.stalled).to.equal(null); }); it('should skip any initial gap when not having played yet', function () { From 29cc2121f4bfbc327da6531dd7693a3fa24dd07a Mon Sep 17 00:00:00 2001 From: Rob Walch Date: Wed, 20 Nov 2019 19:20:02 -0500 Subject: [PATCH 30/42] Jump start gap in Safari fixes #2436 --- src/controller/gap-controller.js | 29 ++++++++++++++----------- tests/unit/controller/gap-controller.js | 21 +++++------------- 2 files changed, 21 insertions(+), 29 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index b3f4241a9a2..fe685e806a5 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -6,6 +6,7 @@ import { logger } from '../utils/logger'; export const STALL_MINIMUM_DURATION_MS = 250; export const JUMP_THRESHOLD_SECONDS = 0.5; // tolerance needed as some browsers stalls playback before reaching buffered range end export const SKIP_BUFFER_HOLE_STEP_SECONDS = 0.1; +export const SKIP_BUFFER_RANGE_START = 0.05; export default class GapController { constructor (config, media, fragmentTracker, hls) { @@ -58,10 +59,9 @@ export default class GapController { const bufferInfo = BufferHelper.bufferInfo(media, currentTime, config.maxBufferHole); if (!this.moved) { - if (!media.seeking && bufferInfo.nextStart) { - logger.warn(`skipping start gap, adjusting currentTime from ${currentTime} to ${bufferInfo.nextStart}`); + if (!media.seeking && (bufferInfo.nextStart || bufferInfo.start > currentTime)) { this.moved = true; - media.currentTime = bufferInfo.nextStart; + this._trySkipBufferHole(null); } return; } @@ -146,18 +146,21 @@ export default class GapController { let lastEndTime = 0; // Check if currentTime is between unbuffered regions of partial fragments for (let i = 0; i < media.buffered.length; i++) { - let startTime = media.buffered.start(i); + const startTime = media.buffered.start(i); if (currentTime >= lastEndTime && currentTime < startTime) { - media.currentTime = Math.max(startTime, media.currentTime + SKIP_BUFFER_HOLE_STEP_SECONDS); - logger.warn(`skipping hole, adjusting currentTime from ${currentTime} to ${media.currentTime}`); + const targetTime = Math.max(startTime + SKIP_BUFFER_RANGE_START, media.currentTime + SKIP_BUFFER_HOLE_STEP_SECONDS); + media.currentTime = targetTime; + logger.warn(`skipping hole, adjusting currentTime from ${currentTime} to ${targetTime}`); this.stalled = null; - hls.trigger(Event.ERROR, { - type: ErrorTypes.MEDIA_ERROR, - details: ErrorDetails.BUFFER_SEEK_OVER_HOLE, - fatal: false, - reason: `fragment loaded with buffer holes, seeking from ${currentTime} to ${media.currentTime}`, - frag: partial - }); + if (partial) { + hls.trigger(Event.ERROR, { + type: ErrorTypes.MEDIA_ERROR, + details: ErrorDetails.BUFFER_SEEK_OVER_HOLE, + fatal: false, + reason: `fragment loaded with buffer holes, seeking from ${currentTime} to ${targetTime}`, + frag: partial + }); + } return; } lastEndTime = media.buffered.end(i); diff --git a/tests/unit/controller/gap-controller.js b/tests/unit/controller/gap-controller.js index 498ea343b8a..f711e1cbc4f 100644 --- a/tests/unit/controller/gap-controller.js +++ b/tests/unit/controller/gap-controller.js @@ -2,7 +2,7 @@ import sinon from 'sinon'; import Hls from '../../../src/hls'; -import GapController, { STALL_MINIMUM_DURATION_MS } from '../../../src/controller/gap-controller'; +import GapController, { STALL_MINIMUM_DURATION_MS, SKIP_BUFFER_RANGE_START } from '../../../src/controller/gap-controller'; import { FragmentTracker } from '../../../src/controller/fragment-tracker'; import Event from '../../../src/events'; @@ -316,20 +316,7 @@ describe('GapController', function () { expect(gapController.stalled).to.equal(TIMER_STEP_MS); }); - it('should jump start gaps', function () { - wallClock.tick(TIMER_STEP_MS); - - // set stalling from the start - isStalling = true; - - tickMediaClock(); - - expect(gapController.moved).to.equal(true); - expect(mockMedia.currentTime).to.equal(100); - expect(gapController.stalled).to.equal(null); - }); - - it('should skip any initial gap when not having played yet', function () { + it('should skip any initial gap before playing', function () { wallClock.tick(TIMER_STEP_MS); mockMedia.currentTime = 0; @@ -338,7 +325,9 @@ describe('GapController', function () { tickMediaClock(); - expect(mockMedia.currentTime).to.equal(100); + expect(gapController.moved).to.equal(true); + expect(mockMedia.currentTime).to.equal(100 + SKIP_BUFFER_RANGE_START); + expect(gapController.stalled).to.equal(null); }); }); }); From e599c9e825d7cffe67a5cab910f6197461d1b079 Mon Sep 17 00:00:00 2001 From: Rob Walch Date: Thu, 21 Nov 2019 13:53:10 -0500 Subject: [PATCH 31/42] Avoid jumping gaps that Chrome will jump Prevent reporting stalls right after "seeked" --- src/controller/gap-controller.js | 27 ++++++++++++++++--------- tests/unit/controller/gap-controller.js | 11 ++++++++-- 2 files changed, 27 insertions(+), 11 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index fe685e806a5..77c4e39bff6 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -46,33 +46,41 @@ export default class GapController { return; } + // The playhead should not be moving if (media.paused || media.ended || media.playbackRate === 0 || !media.buffered.length) { return; } - if (media.seeking && BufferHelper.isBuffered(media, currentTime)) { + // Waiting for seeking in a buffered range to complete + const seeking = media.seeking; + if (seeking && BufferHelper.isBuffered(media, currentTime)) { return; } - // The playhead isn't moving but it should be - // Allow some slack time to for small stalls to resolve themselves const bufferInfo = BufferHelper.bufferInfo(media, currentTime, config.maxBufferHole); - if (!this.moved) { - if (!media.seeking && (bufferInfo.nextStart || bufferInfo.start > currentTime)) { - this.moved = true; + // There is no playable buffer (seeked, waiting for buffer) + if (bufferInfo.len === 0 && !bufferInfo.nextStart) { + return; + } + + // The playhead isn't moving but it should be + // Allow some slack time to for small stalls to resolve themselves + if (!this.moved && this.stalled) { + if (!seeking && (bufferInfo.nextStart || bufferInfo.start > currentTime)) { this._trySkipBufferHole(null); } return; } - if (stalled === null) { + // Start tracking stall time + if (!seeking && stalled === null) { this.stalled = tnow; return; } const stalledDuration = tnow - stalled; - if (!media.seeking && stalledDuration >= STALL_MINIMUM_DURATION_MS) { + if (!seeking && stalledDuration >= STALL_MINIMUM_DURATION_MS) { // Report stalling after trying to fix this._reportStall(bufferInfo.len); } @@ -149,9 +157,10 @@ export default class GapController { const startTime = media.buffered.start(i); if (currentTime >= lastEndTime && currentTime < startTime) { const targetTime = Math.max(startTime + SKIP_BUFFER_RANGE_START, media.currentTime + SKIP_BUFFER_HOLE_STEP_SECONDS); - media.currentTime = targetTime; logger.warn(`skipping hole, adjusting currentTime from ${currentTime} to ${targetTime}`); + this.moved = true; this.stalled = null; + media.currentTime = targetTime; if (partial) { hls.trigger(Event.ERROR, { type: ErrorTypes.MEDIA_ERROR, diff --git a/tests/unit/controller/gap-controller.js b/tests/unit/controller/gap-controller.js index f711e1cbc4f..1719d20d792 100644 --- a/tests/unit/controller/gap-controller.js +++ b/tests/unit/controller/gap-controller.js @@ -146,6 +146,7 @@ describe('GapController', function () { mockMedia = { currentTime: 0, paused: false, + seeking: false, readyState: 4, buffered: mockTimeRanges, addEventListener () {} @@ -316,7 +317,7 @@ describe('GapController', function () { expect(gapController.stalled).to.equal(TIMER_STEP_MS); }); - it('should skip any initial gap before playing', function () { + it('should skip any initial gap before playing on the second poll (so that Chrome can jump the gap first)', function () { wallClock.tick(TIMER_STEP_MS); mockMedia.currentTime = 0; @@ -325,9 +326,15 @@ describe('GapController', function () { tickMediaClock(); + expect(gapController.moved).to.equal(false); + expect(gapController.stalled).to.equal(1234); + expect(mockMedia.currentTime).to.equal(0); + + tickMediaClock(); + expect(gapController.moved).to.equal(true); - expect(mockMedia.currentTime).to.equal(100 + SKIP_BUFFER_RANGE_START); expect(gapController.stalled).to.equal(null); + expect(mockMedia.currentTime).to.equal(100 + SKIP_BUFFER_RANGE_START); }); }); }); From 4d69e9897a9810546fc4e1dec0775b25ceca80ee Mon Sep 17 00:00:00 2001 From: Rob Walch Date: Thu, 21 Nov 2019 14:30:54 -0500 Subject: [PATCH 32/42] Update gap-controller comments --- src/controller/gap-controller.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index 77c4e39bff6..44573908db3 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -64,8 +64,8 @@ export default class GapController { return; } - // The playhead isn't moving but it should be - // Allow some slack time to for small stalls to resolve themselves + // Skip start gaps if we haven't played, but the last poll detected the start of a stall + // The addition poll gives the browser a chance to jump the gap for us if (!this.moved && this.stalled) { if (!seeking && (bufferInfo.nextStart || bufferInfo.start > currentTime)) { this._trySkipBufferHole(null); From ed83a61174e0f807d00601be7293e1e6712ac43f Mon Sep 17 00:00:00 2001 From: Rob Walch Date: Thu, 21 Nov 2019 16:56:37 -0500 Subject: [PATCH 33/42] Do not jump gaps larger than JUMP_THRESHOLD_SECONDS --- src/controller/gap-controller.js | 4 +++- tests/unit/controller/gap-controller.js | 4 ++-- 2 files changed, 5 insertions(+), 3 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index 44573908db3..1366d4c9ce5 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -67,7 +67,9 @@ export default class GapController { // Skip start gaps if we haven't played, but the last poll detected the start of a stall // The addition poll gives the browser a chance to jump the gap for us if (!this.moved && this.stalled) { - if (!seeking && (bufferInfo.nextStart || bufferInfo.start > currentTime)) { + // Jump start gaps within jump threshold + const startJump = Math.max(bufferInfo.nextStart || 0, ((bufferInfo.start || 0) - currentTime)); + if (!seeking && startJump > 0 && startJump <= JUMP_THRESHOLD_SECONDS) { this._trySkipBufferHole(null); } return; diff --git a/tests/unit/controller/gap-controller.js b/tests/unit/controller/gap-controller.js index 1719d20d792..b2cd1b01816 100644 --- a/tests/unit/controller/gap-controller.js +++ b/tests/unit/controller/gap-controller.js @@ -128,7 +128,7 @@ describe('GapController', function () { beforeEach(function () { wallClock = sandbox.useFakeTimers(0); isStalling = false; - mockTimeRangesData = [[100, 200], [400, 500]]; + mockTimeRangesData = [[0.1, 0.2], [0.4, 0.5]]; mockTimeRanges = { length: mockTimeRangesData.length, start (index) { @@ -334,7 +334,7 @@ describe('GapController', function () { expect(gapController.moved).to.equal(true); expect(gapController.stalled).to.equal(null); - expect(mockMedia.currentTime).to.equal(100 + SKIP_BUFFER_RANGE_START); + expect(mockMedia.currentTime).to.equal(0.1 + SKIP_BUFFER_RANGE_START); }); }); }); From 487388d4784c968b2de262d922238b8344605244 Mon Sep 17 00:00:00 2001 From: Rob Walch Date: Thu, 21 Nov 2019 17:44:54 -0500 Subject: [PATCH 34/42] Fix partial and large start gap jumping Examples: //playertest.longtailvideo.com/adaptive/short/short.m3u8 //playertest.longtailvideo.com/adaptive/sintel_aes/playlist.m3u8 --- src/controller/gap-controller.js | 14 +++++++++----- src/controller/subtitle-stream-controller.js | 3 +++ 2 files changed, 12 insertions(+), 5 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index 1366d4c9ce5..8c9703aef01 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -5,6 +5,7 @@ import { logger } from '../utils/logger'; export const STALL_MINIMUM_DURATION_MS = 250; export const JUMP_THRESHOLD_SECONDS = 0.5; // tolerance needed as some browsers stalls playback before reaching buffered range end +export const MAX_START_GAP_JUMP = 2.0; export const SKIP_BUFFER_HOLE_STEP_SECONDS = 0.1; export const SKIP_BUFFER_RANGE_START = 0.05; @@ -69,7 +70,7 @@ export default class GapController { if (!this.moved && this.stalled) { // Jump start gaps within jump threshold const startJump = Math.max(bufferInfo.nextStart || 0, ((bufferInfo.start || 0) - currentTime)); - if (!seeking && startJump > 0 && startJump <= JUMP_THRESHOLD_SECONDS) { + if (!seeking && startJump > 0 && startJump <= MAX_START_GAP_JUMP) { this._trySkipBufferHole(null); } return; @@ -104,10 +105,12 @@ export default class GapController { if (partial) { // Try to skip over the buffer hole caused by a partial fragment // This method isn't limited by the size of the gap between buffered ranges - this._trySkipBufferHole(partial); + const targetTime = this._trySkipBufferHole(partial); // we return here in this case, meaning // the branch below only executes when we don't handle a partial fragment - return; + if (targetTime) { + return; + } } // if we haven't had to skip over a buffer hole of a partial fragment @@ -157,7 +160,7 @@ export default class GapController { // Check if currentTime is between unbuffered regions of partial fragments for (let i = 0; i < media.buffered.length; i++) { const startTime = media.buffered.start(i); - if (currentTime >= lastEndTime && currentTime < startTime) { + if (currentTime + JUMP_THRESHOLD_SECONDS >= lastEndTime && currentTime < startTime) { const targetTime = Math.max(startTime + SKIP_BUFFER_RANGE_START, media.currentTime + SKIP_BUFFER_HOLE_STEP_SECONDS); logger.warn(`skipping hole, adjusting currentTime from ${currentTime} to ${targetTime}`); this.moved = true; @@ -172,10 +175,11 @@ export default class GapController { frag: partial }); } - return; + return targetTime; } lastEndTime = media.buffered.end(i); } + return 0; } /** diff --git a/src/controller/subtitle-stream-controller.js b/src/controller/subtitle-stream-controller.js index 8e313d9d8b9..65b8d68b297 100644 --- a/src/controller/subtitle-stream-controller.js +++ b/src/controller/subtitle-stream-controller.js @@ -83,6 +83,9 @@ export class SubtitleStreamController extends BaseStreamController { } onMediaDetaching () { + if (!this.media) { + return; + } this.media.removeEventListener('seeking', this._onMediaSeeking); this.fragmentTracker.removeAllFragments(); this.currentTrackId = -1; From 8013fce79f2d84b09377343118512fd5dd58e12c Mon Sep 17 00:00:00 2001 From: Rob Walch Date: Fri, 22 Nov 2019 17:35:39 -0500 Subject: [PATCH 35/42] Reset stall time after seeked and fix logger statments --- src/controller/gap-controller.js | 18 +++++++++++++----- 1 file changed, 13 insertions(+), 5 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index 8c9703aef01..df7765785be 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -19,6 +19,7 @@ export default class GapController { this.stallReported = false; this.stalled = null; this.moved = false; + this.seeking = false; } /** @@ -29,8 +30,11 @@ export default class GapController { */ poll (lastCurrentTime) { const { config, media, stalled } = this; - const currentTime = media.currentTime; const tnow = self.performance.now(); + const { currentTime, seeking } = media; + const seeked = this.seeking && !seeking; + + this.seeking = seeking; // The playhead is moving, no-op if (currentTime !== lastCurrentTime) { @@ -47,13 +51,17 @@ export default class GapController { return; } + // Clear stalled state after seeked so that we don't report stalls coming out of a seek + if (seeked) { + this.stalled = null; + } + // The playhead should not be moving if (media.paused || media.ended || media.playbackRate === 0 || !media.buffered.length) { return; } // Waiting for seeking in a buffered range to complete - const seeking = media.seeking; if (seeking && BufferHelper.isBuffered(media, currentTime)) { return; } @@ -77,7 +85,7 @@ export default class GapController { } // Start tracking stall time - if (!seeking && stalled === null) { + if (stalled === null) { this.stalled = tnow; return; } @@ -119,7 +127,7 @@ export default class GapController { // to start playing properly. if (bufferInfo.len > JUMP_THRESHOLD_SECONDS && stalledDurationMs > config.highBufferWatchdogPeriod * 1000) { - logger.log('Trying to nudge playhead over buffer-hole'); + logger.warn('Trying to nudge playhead over buffer-hole'); // Try to nudge currentTime over a buffer hole if we've been stalling for the configured amount of seconds // We only try to jump the hole if it's under the configured size // Reset stalled so to rearm watchdog timer @@ -195,7 +203,7 @@ export default class GapController { if (nudgeRetry < config.nudgeMaxRetry) { const targetTime = currentTime + nudgeRetry * config.nudgeOffset; // playback stalled in buffered area ... let's nudge currentTime to try to overcome this - logger.log(`Nudging 'currentTime' from ${currentTime} to ${targetTime}`); + logger.warn(`Nudging 'currentTime' from ${currentTime} to ${targetTime}`); media.currentTime = targetTime; hls.trigger(Event.ERROR, { From dfdb106d4bc65deed5a630c3ee2abe24c7df7f00 Mon Sep 17 00:00:00 2001 From: Rob Walch Date: Mon, 25 Nov 2019 12:24:44 -0500 Subject: [PATCH 36/42] Fix start gap jumping with partial fragments and when seeking back to start --- src/controller/gap-controller.js | 22 ++++++++++++++-------- 1 file changed, 14 insertions(+), 8 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index df7765785be..cdfaca2c57f 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -61,27 +61,33 @@ export default class GapController { return; } - // Waiting for seeking in a buffered range to complete - if (seeking && BufferHelper.isBuffered(media, currentTime)) { - return; - } - const bufferInfo = BufferHelper.bufferInfo(media, currentTime, config.maxBufferHole); + const isBuffered = bufferInfo.len > 0; // There is no playable buffer (seeked, waiting for buffer) - if (bufferInfo.len === 0 && !bufferInfo.nextStart) { + if (!isBuffered && !bufferInfo.nextStart) { return; } + if (seeking) { + if (isBuffered) { + // Waiting for seeking in a buffered range to complete + return; + } else if (bufferInfo.nextStart < MAX_START_GAP_JUMP) { + // Reset moved state when seeking back to a point before a start gap + this.moved = false; + } + } + // Skip start gaps if we haven't played, but the last poll detected the start of a stall // The addition poll gives the browser a chance to jump the gap for us if (!this.moved && this.stalled) { // Jump start gaps within jump threshold const startJump = Math.max(bufferInfo.nextStart || 0, ((bufferInfo.start || 0) - currentTime)); - if (!seeking && startJump > 0 && startJump <= MAX_START_GAP_JUMP) { + if (startJump > 0 && startJump <= MAX_START_GAP_JUMP) { this._trySkipBufferHole(null); + return; } - return; } // Start tracking stall time From 511915e6367f93e5adca114531a5376e3c4541f6 Mon Sep 17 00:00:00 2001 From: Rob Walch Date: Mon, 25 Nov 2019 13:04:10 -0500 Subject: [PATCH 37/42] Add seek back to start functional test --- tests/functional/auto/setup.js | 37 ++++++++++++++++++++++++++++++++++ tests/test-streams.js | 6 ++++++ 2 files changed, 43 insertions(+) diff --git a/tests/functional/auto/setup.js b/tests/functional/auto/setup.js index ca10ae7e42e..7dd8a3d0bc8 100644 --- a/tests/functional/auto/setup.js +++ b/tests/functional/auto/setup.js @@ -221,6 +221,36 @@ async function testIsPlayingVOD (url, config) { expect(result.playing).to.be.true; } +async function testSeekBackToStart (url, config) { + const result = await browser.executeAsyncScript( + (url, config) => { + let callback = arguments[arguments.length - 1]; + window.startStream(url, config, callback); + const video = window.video; + video.ontimeupdate = function () { + if (video.currentTime > 0 && !video.paused) { + window.setTimeout(function () { + video.onseeked = function () { + delete video.onseeked; + video.ontimeupdate = function () { + if (video.currentTime > 0 && !video.paused) { + delete video.ontimeupdate; + callback({ playing: true }); + } + }; + }; + video.currentTime = 0; + delete video.ontime; + }, 500); + } + }; + }, + url, + config + ); + expect(result.playing).to.be.true; +} + describe(`testing hls.js playback in the browser on "${browserDescription}"`, function () { beforeEach(async function () { // high timeout because sometimes getSession() takes a while @@ -330,6 +360,13 @@ describe(`testing hls.js playback in the browser on "${browserDescription}"`, fu testLoadedData.bind(null, url, config) ); + if (stream.startSeek) { + it( + `seek back to start and play for ${stream.description}`, + testSeekBackToStart.bind(null, url, config) + ); + } + if (stream.abr) { it( `should "smooth switch" to highest level and still play(readyState === 4) after 12s for ${stream.description}`, diff --git a/tests/test-streams.js b/tests/test-streams.js index e530e5b7d8d..ac4f4589f4e 100644 --- a/tests/test-streams.js +++ b/tests/test-streams.js @@ -183,5 +183,11 @@ module.exports = { altAudioAndTracks: { url: 'https://wowzaec2demo.streamlock.net/vod-multitrack/_definst_/smil:ElephantsDream/elephantsdream2.smil/playlist.m3u', description: 'Alternate audio tracks, and multiple VTT tracks' + }, + altAudioWithPdtAndStartGap: { + url: 'https://playertest.longtailvideo.com/adaptive/hls-test-streams/test-audio-pdt/playlist.m3u8', + description: 'PDT before each segment, 1.59s start gap', + abr: true, + startSeek: true } }; From 2cfbe316143a60582e3586e0d65349ae26bfa5c5 Mon Sep 17 00:00:00 2001 From: Rob Walch Date: Tue, 26 Nov 2019 10:57:11 -0500 Subject: [PATCH 38/42] Update gap-controller comments --- src/controller/gap-controller.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index cdfaca2c57f..8049991343e 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -64,7 +64,7 @@ export default class GapController { const bufferInfo = BufferHelper.bufferInfo(media, currentTime, config.maxBufferHole); const isBuffered = bufferInfo.len > 0; - // There is no playable buffer (seeked, waiting for buffer) + // There is no playable buffer (waiting for buffer append) if (!isBuffered && !bufferInfo.nextStart) { return; } From 189655b13624df3029ba94b5f158965bc926c871 Mon Sep 17 00:00:00 2001 From: Rob Walch Date: Tue, 3 Dec 2019 12:30:01 -0500 Subject: [PATCH 39/42] Update gap controller to observe buffer gaps regardless of max buffer hole --- src/controller/gap-controller.js | 12 ++++----- src/utils/buffer-helper.ts | 42 +++++++++++++++++--------------- 2 files changed, 29 insertions(+), 25 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index 8049991343e..e13ce2bc416 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -4,7 +4,6 @@ import Event from '../events'; import { logger } from '../utils/logger'; export const STALL_MINIMUM_DURATION_MS = 250; -export const JUMP_THRESHOLD_SECONDS = 0.5; // tolerance needed as some browsers stalls playback before reaching buffered range end export const MAX_START_GAP_JUMP = 2.0; export const SKIP_BUFFER_HOLE_STEP_SECONDS = 0.1; export const SKIP_BUFFER_RANGE_START = 0.05; @@ -61,7 +60,7 @@ export default class GapController { return; } - const bufferInfo = BufferHelper.bufferInfo(media, currentTime, config.maxBufferHole); + const bufferInfo = BufferHelper.bufferInfo(media, currentTime, 0); const isBuffered = bufferInfo.len > 0; // There is no playable buffer (waiting for buffer append) @@ -102,7 +101,8 @@ export default class GapController { this._reportStall(bufferInfo.len); } - this._tryFixBufferStall(bufferInfo, stalledDuration); + const bufferedWithHoles = BufferHelper.bufferInfo(media, currentTime, config.maxBufferHole); + this._tryFixBufferStall(bufferedWithHoles, stalledDuration); } /** @@ -131,7 +131,7 @@ export default class GapController { // we may just have to "nudge" the playlist as the browser decoding/rendering engine // needs to cross some sort of threshold covering all source-buffers content // to start playing properly. - if (bufferInfo.len > JUMP_THRESHOLD_SECONDS && + if (bufferInfo.len > config.maxBufferHole && stalledDurationMs > config.highBufferWatchdogPeriod * 1000) { logger.warn('Trying to nudge playhead over buffer-hole'); // Try to nudge currentTime over a buffer hole if we've been stalling for the configured amount of seconds @@ -168,13 +168,13 @@ export default class GapController { * @private */ _trySkipBufferHole (partial) { - const { hls, media } = this; + const { config, hls, media } = this; const currentTime = media.currentTime; let lastEndTime = 0; // Check if currentTime is between unbuffered regions of partial fragments for (let i = 0; i < media.buffered.length; i++) { const startTime = media.buffered.start(i); - if (currentTime + JUMP_THRESHOLD_SECONDS >= lastEndTime && currentTime < startTime) { + if (currentTime + config.maxBufferHole >= lastEndTime && currentTime < startTime) { const targetTime = Math.max(startTime + SKIP_BUFFER_RANGE_START, media.currentTime + SKIP_BUFFER_HOLE_STEP_SECONDS); logger.warn(`skipping hole, adjusting currentTime from ${currentTime} to ${targetTime}`); this.moved = true; diff --git a/src/utils/buffer-helper.ts b/src/utils/buffer-helper.ts index 766f8f4a1c2..a3ce5e78042 100644 --- a/src/utils/buffer-helper.ts +++ b/src/utils/buffer-helper.ts @@ -92,30 +92,34 @@ export class BufferHelper { }); let buffered2: BufferTimeRange[] = []; - // there might be some small holes between buffer time range - // consider that holes smaller than maxHoleDuration are irrelevant and build another - // buffer time range representations that discards those holes - for (let i = 0; i < buffered.length; i++) { - let buf2len = buffered2.length; - if (buf2len) { - let buf2end = buffered2[buf2len - 1].end; - // if small hole (value between 0 or maxHoleDuration ) or overlapping (negative) - if ((buffered[i].start - buf2end) < maxHoleDuration) { - // merge overlapping time ranges - // update lastRange.end only if smaller than item.end - // e.g. [ 1, 15] with [ 2,8] => [ 1,15] (no need to modify lastRange.end) - // whereas [ 1, 8] with [ 2,15] => [ 1,15] ( lastRange should switch from [1,8] to [1,15]) - if (buffered[i].end > buf2end) { - buffered2[buf2len - 1].end = buffered[i].end; + if (maxHoleDuration) { + // there might be some small holes between buffer time range + // consider that holes smaller than maxHoleDuration are irrelevant and build another + // buffer time range representations that discards those holes + for (let i = 0; i < buffered.length; i++) { + let buf2len = buffered2.length; + if (buf2len) { + let buf2end = buffered2[buf2len - 1].end; + // if small hole (value between 0 or maxHoleDuration ) or overlapping (negative) + if ((buffered[i].start - buf2end) < maxHoleDuration) { + // merge overlapping time ranges + // update lastRange.end only if smaller than item.end + // e.g. [ 1, 15] with [ 2,8] => [ 1,15] (no need to modify lastRange.end) + // whereas [ 1, 8] with [ 2,15] => [ 1,15] ( lastRange should switch from [1,8] to [1,15]) + if (buffered[i].end > buf2end) { + buffered2[buf2len - 1].end = buffered[i].end; + } + } else { + // big hole + buffered2.push(buffered[i]); } } else { - // big hole + // first value buffered2.push(buffered[i]); } - } else { - // first value - buffered2.push(buffered[i]); } + } else { + buffered2 = buffered; } let bufferLen = 0; From 4fb220634500bd0599432243350e3ddf2605d943 Mon Sep 17 00:00:00 2001 From: Rob Walch Date: Tue, 3 Dec 2019 17:41:35 -0500 Subject: [PATCH 40/42] Handle stalls when seeking into buffer gaps --- src/controller/gap-controller.js | 27 ++++++++++++++++----------- 1 file changed, 16 insertions(+), 11 deletions(-) diff --git a/src/controller/gap-controller.js b/src/controller/gap-controller.js index e13ce2bc416..5f4aaa05b08 100644 --- a/src/controller/gap-controller.js +++ b/src/controller/gap-controller.js @@ -29,9 +29,9 @@ export default class GapController { */ poll (lastCurrentTime) { const { config, media, stalled } = this; - const tnow = self.performance.now(); const { currentTime, seeking } = media; const seeked = this.seeking && !seeking; + const beginSeek = !this.seeking && seeking; this.seeking = seeking; @@ -41,7 +41,8 @@ export default class GapController { if (stalled !== null) { // The playhead is now moving, but was previously stalled if (this.stallReported) { - logger.warn(`playback not stuck anymore @${currentTime}, after ${Math.round(tnow - stalled)}ms`); + const stalledDuration = self.performance.now() - stalled; + logger.warn(`playback not stuck anymore @${currentTime}, after ${Math.round(stalledDuration)}ms`); this.stallReported = false; } this.stalled = null; @@ -50,8 +51,8 @@ export default class GapController { return; } - // Clear stalled state after seeked so that we don't report stalls coming out of a seek - if (seeked) { + // Clear stalled state when beginning or finishing seeking so that we don't report stalls coming out of a seek + if (beginSeek || seeked) { this.stalled = null; } @@ -62,27 +63,30 @@ export default class GapController { const bufferInfo = BufferHelper.bufferInfo(media, currentTime, 0); const isBuffered = bufferInfo.len > 0; + const nextStart = bufferInfo.nextStart || 0; // There is no playable buffer (waiting for buffer append) - if (!isBuffered && !bufferInfo.nextStart) { + if (!isBuffered && !nextStart) { return; } if (seeking) { - if (isBuffered) { - // Waiting for seeking in a buffered range to complete + // Waiting for seeking in a buffered range to complete + const hasEnoughBuffer = bufferInfo.len > MAX_START_GAP_JUMP; + // Next buffered range is too far ahead to jump to while still seeking + const noBufferGap = !nextStart || nextStart - currentTime > MAX_START_GAP_JUMP; + if (hasEnoughBuffer || noBufferGap) { return; - } else if (bufferInfo.nextStart < MAX_START_GAP_JUMP) { - // Reset moved state when seeking back to a point before a start gap - this.moved = false; } + // Reset moved state when seeking to a point in or before a gap + this.moved = false; } // Skip start gaps if we haven't played, but the last poll detected the start of a stall // The addition poll gives the browser a chance to jump the gap for us if (!this.moved && this.stalled) { // Jump start gaps within jump threshold - const startJump = Math.max(bufferInfo.nextStart || 0, ((bufferInfo.start || 0) - currentTime)); + const startJump = Math.max(nextStart, bufferInfo.start || 0) - currentTime; if (startJump > 0 && startJump <= MAX_START_GAP_JUMP) { this._trySkipBufferHole(null); return; @@ -90,6 +94,7 @@ export default class GapController { } // Start tracking stall time + const tnow = self.performance.now(); if (stalled === null) { this.stalled = tnow; return; From 8c8fc31e08a94a29e0a9d3cb21ede208f6d48c0a Mon Sep 17 00:00:00 2001 From: Rob Walch Date: Tue, 3 Dec 2019 18:26:51 -0500 Subject: [PATCH 41/42] Improve functional test assertion feedback --- tests/functional/auto/setup.js | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/tests/functional/auto/setup.js b/tests/functional/auto/setup.js index 7dd8a3d0bc8..05adc4a48b7 100644 --- a/tests/functional/auto/setup.js +++ b/tests/functional/auto/setup.js @@ -89,7 +89,7 @@ async function testLoadedData (url, config) { url, config ); - expect(result.code).to.equal('loadeddata'); + expect(result, JSON.stringify(result, null, 2)).to.have.property('code').which.equals('loadeddata'); } async function testSmoothSwitch (url, config) { @@ -121,7 +121,7 @@ async function testSmoothSwitch (url, config) { url, config ); - expect(result.code).to.be.true; + expect(result, JSON.stringify(result, null, 2)).to.have.property('code').which.equals(true); } async function testSeekOnLive (url, config) { @@ -142,7 +142,7 @@ async function testSeekOnLive (url, config) { url, config ); - expect(result.code).to.equal('seeked'); + expect(result, JSON.stringify(result, null, 2)).to.have.property('code').which.equals('seeked'); } async function testSeekOnVOD (url, config) { @@ -163,7 +163,7 @@ async function testSeekOnVOD (url, config) { url, config ); - expect(result.code).to.equal('ended'); + expect(result, JSON.stringify(result, null, 2)).to.have.property('code').which.equals('ended'); } async function testSeekEndVOD (url, config) { @@ -184,7 +184,7 @@ async function testSeekEndVOD (url, config) { url, config ); - expect(result.code).to.equal('ended'); + expect(result, JSON.stringify(result, null, 2)).to.have.property('code').which.equals('ended'); } async function testIsPlayingVOD (url, config) { @@ -218,7 +218,7 @@ async function testIsPlayingVOD (url, config) { url, config ); - expect(result.playing).to.be.true; + expect(result, JSON.stringify(result, null, 2)).to.have.property('playing').which.is.true; } async function testSeekBackToStart (url, config) { @@ -248,7 +248,7 @@ async function testSeekBackToStart (url, config) { url, config ); - expect(result.playing).to.be.true; + expect(result, JSON.stringify(result, null, 2)).to.have.property('playing').which.is.true; } describe(`testing hls.js playback in the browser on "${browserDescription}"`, function () { From ad4861ca9a8dd5333943bb5be7d5a11859e6dbb4 Mon Sep 17 00:00:00 2001 From: Rob Walch Date: Wed, 4 Dec 2019 19:04:37 -0500 Subject: [PATCH 42/42] Log license key size (DRM functional test troubleshooting) --- src/controller/eme-controller.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/controller/eme-controller.ts b/src/controller/eme-controller.ts index 306f1da612d..3ef8c86e4ce 100644 --- a/src/controller/eme-controller.ts +++ b/src/controller/eme-controller.ts @@ -228,7 +228,7 @@ class EMEController extends EventHandler { logger.log('Got EME message event, creating license request'); this._requestLicense(message, (data: ArrayBuffer) => { - logger.log('Received license data, updating key-session'); + logger.log(`Received license data (length: ${data ? data.byteLength : data}), updating key-session`); keySession.update(data); }); }