fix: more conservative stalled download check, better logging (#884)

src/playback-watcher.js

@@ -170,7 +170,7 @@ export default class PlaybackWatcher {
     const loader = this.masterPlaylistController_[`${type}SegmentLoader_`];
 
     if (this[`${type}StalledDownloads_`] > 0) {
-      this.logger_(`resetting stalled downloads for ${type} loader`);
+      this.logger_(`resetting possible stalled download count for ${type} loader`);
     }
     this[`${type}StalledDownloads_`] = 0;
     this[`${type}Buffered_`] = loader.buffered_();
@@ -204,16 +204,18 @@ export default class PlaybackWatcher {
 
     this[`${type}StalledDownloads_`]++;
 
-    this.logger_(`found stalled download #${this[`${type}StalledDownloads_`]} for ${type} loader`);
-    // We will technically get past this on the fourth bad append
-    // rather than the third. As the first will almost always cause
-    // buffered to change which means that StalledDownloads_ will
-    // not be incremented
-    if (this[`${type}StalledDownloads_`] < 3) {
+    this.logger_(`found #${this[`${type}StalledDownloads_`]} ${type} appends that did not increase buffer (possible stalled download)`, {
+      playlistId: loader.playlist_ && loader.playlist_.id,
+      buffered: Ranges.timeRangesToArray(buffered)
+
+    });
+
+    // after 10 possibly stalled appends with no reset, exclude
+    if (this[`${type}StalledDownloads_`] < 10) {
       return;
     }
 
-    this.logger_(`${type} loader download exclusion`);
+    this.logger_(`${type} loader stalled download exclusion`);
     this.resetSegmentDownloads_(type);
     this.tech_.trigger({type: 'usage', name: `vhs-${type}-download-exclusion`});
 

src/segment-loader.js

@@ -2481,7 +2481,6 @@ export default class SegmentLoader extends videojs.EventTarget {
    * @private
    */
   handleAppendsDone_() {
-    this.trigger('appendsdone');
     if (!this.pendingSegment_) {
       this.state = 'READY';
       // TODO should this move into this.checkForAbort to speed up requests post abort in
@@ -2492,6 +2491,8 @@ export default class SegmentLoader extends videojs.EventTarget {
       return;
     }
 
+    this.trigger('appendsdone');
+
     const segmentInfo = this.pendingSegment_;
 
     // Now that the end of the segment has been reached, we can set the end time. It's

test/playback-watcher.test.js

@@ -786,6 +786,8 @@ QUnit.test('jumps to buffered content if seeking just before', function(assert)
 
 const loaderTypes = ['audio', 'main', 'subtitle'];
 
+const EXCLUDE_APPEND_COUNT = 10;
+
 QUnit.module('PlaybackWatcher download detection', {
   beforeEach(assert) {
     this.env = useFakeEnvironment(assert);
@@ -872,17 +874,15 @@ loaderTypes.forEach(function(type) {
     }
 
     this.setBuffered(videojs.createTimeRanges([[0, 30]]));
-    loader.trigger('appendsdone');
-    assert.equal(this.playbackWatcher[`${type}StalledDownloads_`], 0, '1st append 0 stalled downloads');
-
-    loader.trigger('appendsdone');
-    assert.equal(this.playbackWatcher[`${type}StalledDownloads_`], 1, '2nd append 1 stalled downloads');
-
-    loader.trigger('appendsdone');
-    assert.equal(this.playbackWatcher[`${type}StalledDownloads_`], 2, '3rd append 2 stalled downloads');
 
-    loader.trigger('appendsdone');
-    assert.equal(this.playbackWatcher[`${type}StalledDownloads_`], 0, '4th append 0 stalled downloads');
+    for (let i = 0; i <= EXCLUDE_APPEND_COUNT; i++) {
+      loader.trigger('appendsdone');
+      if (i === EXCLUDE_APPEND_COUNT) {
+        assert.equal(this.playbackWatcher[`${type}StalledDownloads_`], 0, `append #${i} resets stalled downloads to 0`);
+      } else {
+        assert.equal(this.playbackWatcher[`${type}StalledDownloads_`], i, `append #${i + 1} ${i} stalled downloads`);
+      }
+    }
 
     const expectedUsage = {};
 
@@ -927,16 +927,18 @@ loaderTypes.forEach(function(type) {
       const loader = this.mpc[`${type}SegmentLoader_`];
       const playlists = this.mpc.master().playlists;
       const excludeAndVerify = () => {
-        loader.trigger('appendsdone');
-        assert.equal(this.playbackWatcher[`${type}StalledDownloads_`], 1, '1st append 1 stalled downloads');
-
-        loader.trigger('appendsdone');
-        assert.equal(this.playbackWatcher[`${type}StalledDownloads_`], 2, '2nd append 1 stalled downloads');
-
-        const oldPlaylist = this.mpc.media();
-
-        loader.trigger('appendsdone');
-        assert.equal(this.playbackWatcher[`${type}StalledDownloads_`], 0, '3rd append 0 stalled downloads');
+        let oldPlaylist;
+        // this test only needs 9 appends, since we do an intial append
+
+        for (let i = 0; i < EXCLUDE_APPEND_COUNT; i++) {
+          oldPlaylist = this.mpc.media();
+          loader.trigger('appendsdone');
+          if (i === EXCLUDE_APPEND_COUNT - 1) {
+            assert.equal(this.playbackWatcher[`${type}StalledDownloads_`], 0, `append #${i} resets stalled downloads to 0`);
+          } else {
+            assert.equal(this.playbackWatcher[`${type}StalledDownloads_`], i + 1, `append #${i + 1} ${i + 1} stalled downloads`);
+          }
+        }
 
         const expectedUsage = {};
 

test/segment-loader.test.js

@@ -763,6 +763,83 @@ QUnit.module('SegmentLoader', function(hooks) {
       });
     });
 
+    QUnit.test('appendsdone happens after appends complete', function(assert) {
+      const done = assert.async();
+
+      return setupMediaSource(loader.mediaSource_, loader.sourceUpdater_).then(() => {
+        let appendsdone = false;
+
+        loader.playlist(playlistWithDuration(20));
+        loader.load();
+        this.clock.tick(1);
+
+        standardXHRResponse(this.requests.shift(), muxedSegment());
+        loader.one('appendsdone', () => {
+          appendsdone = true;
+        });
+
+        let appends = 0;
+
+        const finish = function() {
+          appends++;
+
+          if (appends < 2) {
+            return;
+          }
+
+          assert.ok(appendsdone, 'appendsdone triggered');
+          done();
+        };
+
+        loader.sourceUpdater_.videoBuffer.addEventListener('updateend', () => {
+          loader.sourceUpdater_.videoQueueCallback(finish);
+        });
+
+        loader.sourceUpdater_.audioBuffer.addEventListener('updateend', () => {
+          loader.sourceUpdater_.audioQueueCallback(finish);
+        });
+      });
+    });
+
+    QUnit.test('appendsdone does not happen after abort during append', function(assert) {
+      const done = assert.async();
+
+      return setupMediaSource(loader.mediaSource_, loader.sourceUpdater_).then(() => {
+        let appendsdone = false;
+
+        loader.playlist(playlistWithDuration(20));
+        loader.load();
+        this.clock.tick(1);
+
+        standardXHRResponse(this.requests.shift(), muxedSegment());
+        loader.one('appendsdone', () => {
+          appendsdone = true;
+        });
+
+        loader.one('appending', () => {
+          loader.abort();
+        });
+
+        let appends = 0;
+
+        const finish = function() {
+          appends++;
+
+          if (appends < 2) {
+            return;
+          }
+
+          assert.notOk(appendsdone, 'appendsdone triggered');
+          done();
+        };
+
+        loader.sourceUpdater_.videoBuffer.addEventListener('updateend', () => {
+          loader.sourceUpdater_.videoQueueCallback(finish);
+          loader.sourceUpdater_.audioQueueCallback(finish);
+        });
+      });
+    });
+
     QUnit.test('audio loader waits to request segment until it has enough info', function(assert) {
       loader.dispose();
       loader = new SegmentLoader(LoaderCommonSettings.call(this, {