Functional test improvements & test failure investigation

[robwalch]

This PR will...

• Fix IE11 Selenium execute async JavaScript exceptions
• Update Safari version from 9.1 to 10.1 for a better chance at webdriver running tests in Safari
• Omit logs from logging of result JSON
• Fail "seek to end -5" early onprogress if more than 2 buffered ranges are found (If have an unexpected gap, the test should fail)

Why is this Pull Request needed?

Improve test run stability required and optional browser configurations.

Other notes

This PR was originally for troubleshooting test failures that I was having difficulty reproducing locally. If you're interested in the temporary changes I made to troubleshoot test runs both locally and in the travis runs, let me know and I can move the stashed changes into a branch. Disabling the worker and shortening the list of test stream to the problem stream are the first steps.

When should seek 5s from end and receive video ended event for Multiple non-alternate audio levels times out, it appears to be doing more buffering than necessary before seeking. This seems to be an edge-case related to the media containing mixed AAC/HE-AAC media playlists or the mixed samplerates of 24/48kHz. The audio buffer is initialized with the 24kHz audio and then when the 48kHz audio is appended its samples are still treated as 24kHz. In other tests where we don't seek again getting the stream loader stuck in a loop, appending a segment whose sample start *2 exceeds the duration produces media-decode-error (3).

So close to 100% on Firefox!
https://travis-ci.org/github/video-dev/hls.js/jobs/711630371

  102 passing (13m)
  1 failing
  1) testing hls.js playback in the browser on "firefox (latest), Windows 10"
       should seek 5s from end and receive video ended event for Multiple non-alternate audio levels:
     Error: Timeout of 40000ms exceeded. For async tests and hooks, ensure "done()" is called; if returning a Promise, ensure it resolves. (/home/travis/build/video-dev/hls.js/tests/functional/auto/setup.js)
      at listOnTimeout (internal/timers.js:551:17)
      at processTimers (internal/timers.js:494:7)

...
2020-07-25 00:31:46.015: "[log] > Re-loading fragment with SN: 235776262"
2020-07-25 00:31:46.017: "[log] > Loading 235776262 of [235776259 ,235776278],level 1, currentTime:1.033,bufferEnd:12.800"
2020-07-25 00:31:46.019: "[log] > main stream-controller: IDLE->FRAG_LOADING"
2020-07-25 00:31:46.026: "[log] > Loaded 235776262 of [235776259 ,235776278],level 1"
2020-07-25 00:31:46.026: "[log] > Parsing 235776262 of [235776259 ,235776278],level 1, cc 0"
2020-07-25 00:31:46.026: "[log] > main stream-controller: FRAG_LOADING->PARSING"
2020-07-25 00:31:46.030: "[log] > Parsed audio,PTS:[19.200,25.600],DTS:[19.200/25.600],nb:300,dropped:0"
2020-07-25 00:31:46.031: "[log] > main stream-controller: PARSING->PARSED"
2020-07-25 00:31:46.033: "[log] > main buffered : [0.000,12.800][25.600,51.200]"
2020-07-25 00:31:46.033: "[log] > latency/loading/parsing/append/kbps:8/0/6/2/57340"
2020-07-25 00:31:46.034: "[log] > main stream-controller: PARSED->IDLE"
2020-07-25 00:31:46.035: "[log] > Loading 235776261 of [235776259 ,235776278],level 1, currentTime:1.081,bufferEnd:12.800"
2020-07-25 00:31:46.039: "[log] > main stream-controller: IDLE->FRAG_LOADING"
2020-07-25 00:31:46.043: "[log] > Loaded 235776261 of [235776259 ,235776278],level 1"
2020-07-25 00:31:46.044: "[log] > Parsing 235776261 of [235776259 ,235776278],level 1, cc 0"
2020-07-25 00:31:46.044: "[log] > main stream-controller: FRAG_LOADING->PARSING"
2020-07-25 00:31:46.046: "[log] > Parsed audio,PTS:[12.800,19.200],DTS:[12.800/19.200],nb:300,dropped:0"
2020-07-25 00:31:46.047: "[log] > main stream-controller: PARSING->PARSED"
2020-07-25 00:31:46.049: "[log] > main buffered : [0.000,12.800][25.600,51.200]"
2020-07-25 00:31:46.050: "[log] > latency/loading/parsing/append/kbps:8/1/3/2/65531"
2020-07-25 00:31:46.050: "[log] > main stream-controller: PARSED->IDLE"
2020-07-25 00:31:46.050: "[log] > Re-loading fragment with SN: 235776262"
2020-07-25 00:31:46.050: "[log] > Loading 235776262 of [235776259 ,235776278],level 1, currentTime:1.081,bufferEnd:12.800"
2020-07-25 00:31:46.055: "[log] > main stream-controller: IDLE->FRAG_LOADING"
2020-07-25 00:31:46.060: "[log] > Loaded 235776262 of [235776259 ,235776278],level 1"
2020-07-25 00:31:46.060: "[log] > Parsing 235776262 of [235776259 ,235776278],level 1, cc 0"
2020-07-25 00:31:46.060: "[log] > main stream-controller: FRAG_LOADING->PARSING"
2020-07-25 00:31:46.063: "[log] > Parsed audio,PTS:[19.200,25.600],DTS:[19.200/25.600],nb:300,dropped:0"
2020-07-25 00:31:46.063: "[log] > main stream-controller: PARSING->PARSED"
2020-07-25 00:31:46.065: "[log] > main buffered : [0.000,12.800][25.600,51.200]"
2020-07-25 00:31:46.066: "[log] > latency/loading/parsing/append/kbps:8/1/3/3/61163"
2020-07-25 00:31:46.066: "[log] > main stream-controller: PARSED->IDLE"
2020-07-25 00:31:46.067: "[log] > Loading 235776261 of [235776259 ,235776278],level 1, currentTime:1.081,bufferEnd:12.800"
2020-07-25 00:31:46.069: "[log] > main stream-controller: IDLE->FRAG_LOADING"
2020-07-25 00:31:46.076: "[log] > Loaded 235776261 of [235776259 ,235776278],level 1"
2020-07-25 00:31:46.076: "[log] > Parsing 235776261 of [235776259 ,235776278],level 1, cc 0"
2020-07-25 00:31:46.076: "[log] > main stream-controller: FRAG_LOADING->PARSING"
2020-07-25 00:31:46.079: "[log] > Parsed audio,PTS:[12.800,19.200],DTS:[12.800/19.200],nb:300,dropped:0"
2020-07-25 00:31:46.080: "[log] > main stream-controller: PARSING->PARSED"
2020-07-25 00:31:46.084: "[log] > main buffered : [0.000,12.800][25.600,51.200]"
2020-07-25 00:31:46.085: "[log] > latency/loading/parsing/append/kbps:7/1/4/5/53967"
2020-07-25 00:31:46.085: "[log] > main stream-controller: PARSED->IDLE"
2020-07-25 00:31:46.086: "[log] > Re-loading fragment with SN: 235776262"
...

I haven't been able to reproduce this locally in the demo, but I can running test unit:func.

In troubleshooting I found that we request both startLoad and buffer flushing twice; This should be fixed in feature/v1.0.0, but addressing these here did not prevent the sample rate buffer offset or decode error issues. 😓

The next step would be to look at the differences between the test run and demo. When commenting out browser.quit() and checking chrome://media-internals/ shows the following:

Timestamp	Property	Value
00:00:00.000	info	"ChunkDemuxer"
00:00:00.000	pipeline_state	"kStarting"
00:00:00.104	kAudioTracks	[{"bytes per channel":2,"bytes per frame":4,"channel layout":"STEREO","channels":2,"codec":"aac","codec delay":0,"discard decoder delay":false,"encryption scheme":"Unencrypted","has extra data":false,"profile":"unknown","sample format":"Signed 16-bit","samples per second":48000,"seek preroll":"0us"}]
00:00:00.105	info	"Effective playback rate changed from 0 to 1"
00:00:00.105	event	"kPlay"
00:00:00.107	kIsAudioDecryptingDemuxerStream	false
00:00:00.107	kAudioDecoderName	"FFmpegAudioDecoder"
00:00:00.107	kIsPlatformAudioDecoder	false
00:00:00.107	info	"Selected FFmpegAudioDecoder for audio decoding, config: codec: aac, profile: unknown, bytes_per_channel: 2, channel_layout: STEREO, channels: 2, samples_per_second: 48000, sample_format: Signed 16-bit, bytes_per_frame: 4, seek_preroll: 0us, codec_delay: 0, has extra data: false, encryption scheme: Unencrypted, discard decoder delay: false"
00:00:00.107	pipeline_state	"kPlaying"
00:00:00.108	audio_buffering_state	{"state":"BUFFERING_HAVE_ENOUGH"}
00:00:00.109	pipeline_buffering_state	{"for_suspended_start":false,"state":"BUFFERING_HAVE_ENOUGH"}
00:00:00.142	error	"Failed to send audio packet for decoding: timestamp=298666 duration=42666 size=344 side_data_size=0 is_key_frame=1 encrypted=0 discard_padding (us)=(0, 0)"
00:00:00.142	error	"audio decode error!"
00:00:00.206	error	"audio error during playing, status: PIPELINE_ERROR_DECODE"
00:00:00.211	pipeline_error	"PIPELINE_ERROR_DECODE"
00:00:00.211	pipeline_state	"kStopping"
00:00:00.211	pipeline_state	"kStopped"
00:00:00.214	event	"kPause"
00:00:00.109	duration	128
00:00:05.110	seek_target	123

Related issues:

#2837

Checklist

• changes have been done against master branch, and PR does not conflict
• new unit / functional tests have been added (whenever applicable)
• API or design changes are documented in API.md