Bug 1300653 - Update VideoPuppeteer to store state snapshots to prevent racing. r=maja_zf

The tests that use VideoPuppeteer often expect the state queried by the
puppeteer to be consistent if done closely in the code. However, this has not
been the case, as there can be significant lags in the data returning from
marionette. This means that if one line queries the current time of the
underlying video, and the very next line queries the same thing, there can be
significantly different results.

This causes issues with tests making multiple sequential checks on the
underlying video, and the state changing between checks. On test fails it means
that the information logged my be inconsistent with the state that resulted in
the test failing, as time passes between the fail check and the logging.

This patch attempts to address this by having the VideoPuppeteer store a
snapshot of state and examining that instead. This snap shot should be
internally consistent.

I've removed a large number of public members from the class, and moved a couple
of the testing functions into the class. The thinking here is that the new logic
complicates the internal state of the class, and I want to keep the interface
slim to hide that complexity.

***
Review feedback: Log interval, expected duration, stall wait time, and timeout
times in VideoPuppeteer string.
***
Review feedback: make video var script a class var instead of a staticmethod.
***
Review feedback: move _fetch_state_script to be a property on VideoPuppeteer.
***
Review feedback: simplify calling of _create_video_state_info with a dict.
Fix played docstring.
***
Review feedback: simplify _create_video_state_info using kwargs.

MozReview-Commit-ID: 6mN56bFMge0

--HG--
extra : rebase_source : a25a9a45c8dced9439360b9664b1d768100ed2be
This commit is contained in:
Bryce Van Dyk 2016-09-21 14:08:34 +12:00
Родитель e20a8e6f48
Коммит 9746da4a07
4 изменённых файлов: 264 добавлений и 209 удалений

Просмотреть файл

@ -14,10 +14,8 @@ from marionette.marionette_test import SkipTest
from firefox_puppeteer.testcases import BaseFirefoxTestCase
from external_media_tests.utils import (timestamp_now, verbose_until)
from external_media_tests.media_utils.video_puppeteer import (
playback_done,
playback_started,
VideoException,
VideoPuppeteer as VP
VideoPuppeteer
)
@ -54,12 +52,12 @@ class MediaTestCase(BaseFirefoxTestCase, MarionetteTestCase):
self.marionette.log('Screenshot saved in {}'
.format(os.path.abspath(path)))
def log_video_debug_lines(self):
def log_video_debug_lines(self, video):
"""
Log the debugging information that Firefox provides for video elements.
"""
with self.marionette.using_context(Marionette.CONTEXT_CHROME):
debug_lines = self.marionette.execute_script(VP._debug_script)
debug_lines = video.get_debug_lines()
if debug_lines:
self.marionette.log('\n'.join(debug_lines))
@ -76,7 +74,7 @@ class MediaTestCase(BaseFirefoxTestCase, MarionetteTestCase):
verbose_until(Wait(video, interval=video.interval,
timeout=video.expected_duration * 1.3 +
video.stall_wait_time),
video, playback_done)
video, VideoPuppeteer.playback_done)
except VideoException as e:
raise self.failureException(e)
@ -91,7 +89,7 @@ class MediaTestCase(BaseFirefoxTestCase, MarionetteTestCase):
self.logger.info(video.test_url)
try:
verbose_until(Wait(video, timeout=video.timeout),
video, playback_started)
video, VideoPuppeteer.playback_started)
except TimeoutException as e:
raise self.failureException(e)
@ -135,7 +133,7 @@ class NetworkBandwidthTestCase(MediaTestCase):
"""
with self.marionette.using_context(Marionette.CONTEXT_CONTENT):
for url in self.video_urls:
video = VP(self.marionette, url, stall_wait_time=60,
video = VideoPuppeteer(self.marionette, url, stall_wait_time=60,
set_duration=60, timeout=timeout)
self.run_playback(video)
@ -160,7 +158,7 @@ class VideoPlaybackTestsMixin(object):
with self.marionette.using_context(Marionette.CONTEXT_CONTENT):
for url in self.video_urls:
try:
video = VP(self.marionette, url, timeout=60)
video = VideoPuppeteer(self.marionette, url, timeout=60)
# Second playback_started check in case video._start_time
# is not 0
self.check_playback_starts(video)
@ -174,7 +172,7 @@ class VideoPlaybackTestsMixin(object):
"""
with self.marionette.using_context(Marionette.CONTEXT_CONTENT):
for url in self.video_urls:
video = VP(self.marionette, url,
video = VideoPuppeteer(self.marionette, url,
stall_wait_time=10,
set_duration=60)
self.run_playback(video)

Просмотреть файл

@ -1,7 +1,7 @@
# This Source Code Form is subject to the terms of the Mozilla Public
# License, v. 2.0. If a copy of the MPL was not distributed with this
# file, You can obtain one at http://mozilla.org/MPL/2.0/.
from collections import namedtuple
from time import clock, sleep
from marionette import Marionette
@ -38,7 +38,7 @@ class VideoPuppeteer(object):
Wrapper to control and introspect HTML5 video elements.
A note about properties like current_time and duration:
These describe whatever stream is playing when the property is called.
These describe whatever stream is playing when the state is checked.
It is possible that many different streams are dynamically spliced
together, so the video stream that is currently playing might be the main
video or it might be something else, like an ad, for example.
@ -56,6 +56,38 @@ class VideoPuppeteer(object):
cleared. If 0, do not check for stalls.
:param timeout: The amount of time to wait until the video starts.
"""
_video_var_script = (
'var video = arguments[0];'
'var currentTime = video.wrappedJSObject.currentTime;'
'var duration = video.wrappedJSObject.duration;'
'var played = video.wrappedJSObject.played;'
'var timeRanges = [];'
'for (var i = 0; i < played.length; i++) {'
'timeRanges.push([played.start(i), played.end(i)]);'
'}'
'var totalFrames = '
'video.getVideoPlaybackQuality()["totalVideoFrames"];'
'var droppedFrames = '
'video.getVideoPlaybackQuality()["droppedVideoFrames"];'
'var corruptedFrames = '
'video.getVideoPlaybackQuality()["corruptedVideoFrames"];'
)
"""
A string containing JS that assigns video state to variables.
The purpose of this string script is to be appended to by this and
any inheriting classes to return these and other variables. In the case
of an inheriting class the script can be added to in order to fetch
further relevant variables -- keep in mind we only want one script
execution to prevent races, so it wouldn't do to have child classes
run this script then their own, as there is potential for lag in
between.
This script assigns a subset of the vars used later by the
`_video_state_named_tuple` function. Please see that function's
documentation for further information on these variables.
"""
def __init__(self, marionette, url, video_selector='video', interval=1,
set_duration=0, stall_wait_time=0, timeout=60,
autostart=True):
@ -69,6 +101,8 @@ class VideoPuppeteer(object):
self.expected_duration = 0
self._first_seen_time = 0
self._first_seen_wall_time = 0
self._fetch_state_script_string = None
self._last_seen_video_state = None
wait = Wait(self.marionette, timeout=self.timeout)
with self.marionette.using_context(Marionette.CONTEXT_CONTENT):
self.marionette.navigate(self.test_url)
@ -93,43 +127,13 @@ class VideoPuppeteer(object):
def start(self):
# To get an accurate expected_duration, playback must have started
self._refresh_state()
wait = Wait(self, timeout=self.timeout)
verbose_until(wait, self, playback_started,
verbose_until(wait, self, VideoPuppeteer.playback_started,
"Check if video has played some range")
self._first_seen_time = self.current_time
self._first_seen_time = self._last_seen_video_state.current_time
self._first_seen_wall_time = clock()
self.update_expected_duration()
def update_expected_duration(self):
"""
Update the duration of the target video at self.test_url (in seconds).
expected_duration represents the following: how long do we expect
playback to last before we consider the video to be 'complete'?
If we only want to play the first n seconds of the video,
expected_duration is set to n.
"""
# self.duration is the duration of whatever is playing right now.
# In this case, we assume the video element always shows the same
# stream throughout playback (i.e. the are no ads spliced into the main
# video, for example), so self.duration is the duration of the main
# video.
video_duration = self.duration
# Do our best to figure out where the video started playing
played_ranges = self.played
if played_ranges.length > 0:
# If we have a range we should only have on continuous range
assert played_ranges.length == 1
start_position = played_ranges.start(0)
else:
# If we don't have a range we should have a current time
start_position = self._first_seen_time
# In case video starts at t > 0, adjust target time partial playback
remaining_video = video_duration - start_position
if 0 < self._set_duration < remaining_video:
self.expected_duration = self._set_duration
else:
self.expected_duration = remaining_video
self._update_expected_duration()
def get_debug_lines(self):
"""
@ -145,124 +149,213 @@ class VideoPuppeteer(object):
"""
Tell the video element to Play.
"""
self.execute_video_script('arguments[0].wrappedJSObject.play();')
self._execute_video_script('arguments[0].wrappedJSObject.play();')
def pause(self):
"""
Tell the video element to Pause.
"""
self.execute_video_script('arguments[0].wrappedJSObject.pause();')
self._execute_video_script('arguments[0].wrappedJSObject.pause();')
@property
def duration(self):
def playback_started(self):
"""
:return: Duration in seconds of whatever stream is playing right now.
"""
return self.execute_video_script('return arguments[0].'
'wrappedJSObject.duration;') or 0
Determine if video has started
@property
def current_time(self):
"""
:return: Current time of whatever stream is playing right now.
"""
# Note that self.current_time could temporarily refer to a
# spliced-in ad.
:param self: The VideoPuppeteer instance that we are interested in.
return self.execute_video_script(
'return arguments[0].wrappedJSObject.currentTime;') or 0
:return: True if is playing; False otherwise
"""
self._refresh_state()
try:
played_ranges = self._last_seen_video_state.played
return (
played_ranges.length > 0 and
played_ranges.start(0) < played_ranges.end(0) and
played_ranges.end(0) > 0.0
)
except Exception as e:
print ('Got exception {}'.format(e))
return False
@property
def remaining_time(self):
def playback_done(self):
"""
:return: How much time is remaining given the duration of the video
and the duration that has been set.
"""
played_ranges = self.played
# Playback should be in one range (as tests do not currently seek).
assert played_ranges.length == 1
played_duration = self.played.end(0) - self.played.start(0)
return self.expected_duration - played_duration
If we are near the end and there is still a video element, then
we are essentially done. If this happens to be last time we are polled
before the video ends, we won't get another chance.
@property
def played(self):
"""
:return: A TimeRanges objected containing the played time ranges.
"""
raw_time_ranges = self.execute_video_script(
'var played = arguments[0].wrappedJSObject.played;'
'var timeRanges = [];'
'for (var i = 0; i < played.length; i++) {'
'timeRanges.push([played.start(i), played.end(i)]);'
'}'
'return [played.length, timeRanges];')
return TimeRanges(raw_time_ranges[0], raw_time_ranges[1])
:param self: The VideoPuppeteer instance that we are interested in.
@property
def video_src(self):
:return: True if we are close enough to the end of playback; False
otherwise.
"""
:return: The url of the actual video file, as opposed to the url
of the page with the video element.
"""
with self.marionette.using_context(Marionette.CONTEXT_CONTENT):
return self.video.get_attribute('src')
self._refresh_state()
@property
def total_frames(self):
"""
:return: Number of video frames created and dropped since the creation
of this video element.
"""
return self.execute_video_script("""
return arguments[0].getVideoPlaybackQuality()["totalVideoFrames"];
""")
if self._last_seen_video_state.remaining_time < self.interval:
return True
@property
def dropped_frames(self):
"""
:return: Number of video frames created and dropped since the creation
of this video element.
"""
return self.execute_video_script("""return
arguments[0].getVideoPlaybackQuality()["droppedVideoFrames"];
""") or 0
# Check to see if the video has stalled. Accumulate the amount of lag
# since the video started, and if it is too high, then raise.
if (self.stall_wait_time and
self._last_seen_video_state.lag > self.stall_wait_time):
raise VideoException('Video {} stalled.\n{}'
.format(self._last_seen_video_state.video_url,
self))
@property
def corrupted_frames(self):
"""
:return: Number of video frames corrupted since the creation of this
video element. A corrupted frame may be created or dropped.
"""
return self.execute_video_script("""return
arguments[0].getVideoPlaybackQuality()["corruptedVideoFrames"];
""") or 0
# We are cruising, so we are not done.
return False
@property
def video_url(self):
def _update_expected_duration(self):
"""
:return: The URL of the video that this element is playing.
"""
return self.execute_video_script('return arguments[0].baseURI;')
Update the duration of the target video at self.test_url (in seconds).
This is based on the last seen state, so the state should be,
refreshed at least once before this is called.
@property
def lag(self):
expected_duration represents the following: how long do we expect
playback to last before we consider the video to be 'complete'?
If we only want to play the first n seconds of the video,
expected_duration is set to n.
"""
:return: The difference in time between where the video is currently
playing and where it should be playing given the time we started
the video.
# self._last_seen_video_state.duration is the duration of whatever was
# playing when the state was checked. In this case, we assume the video
# element always shows the same stream throughout playback (i.e. the
# are no ads spliced into the main video, for example), so
# self._last_seen_video_state.duration is the duration of the main
# video.
video_duration = self._last_seen_video_state.duration
# Do our best to figure out where the video started playing
played_ranges = self._last_seen_video_state.played
if played_ranges.length > 0:
# If we have a range we should only have on continuous range
assert played_ranges.length == 1
start_position = played_ranges.start(0)
else:
# If we don't have a range we should have a current time
start_position = self._first_seen_time
# In case video starts at t > 0, adjust target time partial playback
remaining_video = video_duration - start_position
if 0 < self._set_duration < remaining_video:
self.expected_duration = self._set_duration
else:
self.expected_duration = remaining_video
@staticmethod
def _video_state_named_tuple():
"""
# Note that self.current_time could temporarily refer to a
# spliced-in ad
elapsed_current_time = self.current_time - self._first_seen_time
Create a named tuple class that can be used to store state snapshots
of the wrapped element. The fields in the tuple should be used as
follows:
current_time: The current time of the wrapped element.
duration: the duration of the wrapped element.
played: the played ranges of the wrapped element. In its raw form this
is as a list where the first element is the length and the second
element is a list of 2 item lists, where each two items are a played
range. Once assigned to the tuple this data should be wrapped in the
TimeRanges class.
lag: the difference in real world time and wrapped element time.
Calculated as real world time passed - element time passed.
totalFrames: number of total frames for the wrapped element
droppedFrames: number of dropped frames for the wrapped element.
corruptedFrames: number of corrupted frames for the wrapped.
video_src: the src attribute of the wrapped element.
video_url: the url attribute of the wrapped element.
:return: A 'video_state_info' named tuple class.
"""
return namedtuple('video_state_info',
['current_time',
'duration',
'remaining_time',
'played',
'lag',
'total_frames',
'dropped_frames',
'corrupted_frames',
'video_src',
'video_url'])
def _create_video_state_info(self, **video_state_info_kwargs):
"""
Create an instance of the video_state_info named tuple. This function
expects a dictionary populated with the following keys: current_time,
duration, raw_time_ranges, total_frames, dropped_frames, and
corrupted_frames.
Aside from raw_time_ranges, see `_video_state_named_tuple` for more
information on the above keys and values. For raw_time_ranges a
list is expected that can be consumed to make a TimeRanges object.
:return: A named tuple 'video_state_info' derived from arguments and
state information from the puppeteer.
"""
raw_time_ranges = video_state_info_kwargs['raw_time_ranges']
# Remove raw ranges from dict as it is not used in the final named
# tuple and will provide an unexpected kwarg if kept.
del video_state_info_kwargs['raw_time_ranges']
# Create played ranges
video_state_info_kwargs['played'] = (
TimeRanges(raw_time_ranges[0], raw_time_ranges[1]))
# Calculate elapsed times
elapsed_current_time = (video_state_info_kwargs['current_time'] -
self._first_seen_time)
elapsed_wall_time = clock() - self._first_seen_wall_time
return elapsed_wall_time - elapsed_current_time
# Calculate lag
video_state_info_kwargs['lag'] = (
elapsed_wall_time - elapsed_current_time)
# Calculate remaining time
if video_state_info_kwargs['played'].length > 0:
played_duration = (video_state_info_kwargs['played'].end(0) -
video_state_info_kwargs['played'].start(0))
video_state_info_kwargs['remaining_time'] = (
self.expected_duration - played_duration)
else:
# No playback has happened yet, remaining time is duration
video_state_info_kwargs['remaining_time'] = self.expected_duration
# Fetch non time critical source information
video_state_info_kwargs['video_src'] = self.video.get_attribute('src')
video_state_info_kwargs['video_url'] = self.video.get_attribute('url')
# Create video state snapshot
state_info = self._video_state_named_tuple()
return state_info(**video_state_info_kwargs)
def measure_progress(self):
initial = self.current_time
@property
def _fetch_state_script(self):
if not self._fetch_state_script_string:
self._fetch_state_script_string = (
self._video_var_script +
'return ['
'currentTime,'
'duration,'
'[played.length, timeRanges],'
'totalFrames,'
'droppedFrames,'
'corruptedFrames];')
return self._fetch_state_script_string
def _refresh_state(self):
"""
Refresh the snapshot of the underlying video state. We do this all
in one so that the state doesn't change in between queries.
We also store information that can be derived from the snapshotted
information, such as lag. This is stored in the last seen state to
stress that it's based on the snapshot.
"""
keys = ['current_time', 'duration', 'raw_time_ranges', 'total_frames',
'dropped_frames', 'corrupted_frames']
values = self._execute_video_script(self._fetch_state_script)
self._last_seen_video_state = (
self._create_video_state_info(**dict(zip(keys, values))))
def _measure_progress(self):
self._refresh_state()
initial = self._last_seen_video_state.current_time
sleep(1)
return self.current_time - initial
self._refresh_state()
return self._last_seen_video_state.current_time - initial
def execute_video_script(self, script):
def _execute_video_script(self, script):
"""
Execute JS script in content context with access to video element.
@ -276,25 +369,27 @@ class VideoPuppeteer(object):
def __str__(self):
messages = ['{} - test url: {}: '
.format(type(self).__name__, self.test_url)]
messages += '{'
if self.video:
messages += [
'\t(video)',
'\tcurrent_time: {},'.format(self.current_time),
'\tduration: {},'.format(self.duration),
'\texpected_duration: {},'.format(self.expected_duration),
'\tplayed: {}'.format(self.played),
'\tinterval: {}'.format(self.interval),
'\tlag: {},'.format(self.lag),
'\turl: {}'.format(self.video_url),
'\tsrc: {}'.format(self.video_src),
'\tframes total: {}'.format(self.total_frames),
'\t - dropped: {}'.format(self.dropped_frames),
'\t - corrupted: {}'.format(self.corrupted_frames)
]
else:
if not self.video:
messages += ['\tvideo: None']
messages.append('}')
return '\n'.join(messages)
if not self._last_seen_video_state:
messages += ['\tvideo: No last seen state']
return '\n'.join(messages)
# Have video and state info
messages += [
'{',
'\t(video)'
]
messages += ['\tinterval: {}'.format(self.interval)]
messages += ['\texpected duration: {}'.format(self.expected_duration)]
messages += ['\tstall wait time: {}'.format(self.stall_wait_time)]
messages += ['\ttimeout: {}'.format(self.timeout)]
# Print each field on its own line
for field in self._last_seen_video_state._fields:
messages += [('\t{}: {}'
.format(field, getattr(self._last_seen_video_state,
field)))]
messages += '}'
return '\n'.join(messages)
@ -311,6 +406,10 @@ class TimeRanges:
similar interface to the JavaScript TimeRanges object.
"""
def __init__(self, length, ranges):
# These should be the same,. Theoretically we don't need the length,
# but since this should be used to consume data coming back from
# JS exec, this is a valid sanity check.
assert length == len(ranges)
self.length = length
self.ranges = [(pair[0], pair[1]) for pair in ranges]
@ -325,47 +424,3 @@ class TimeRanges:
def end(self, index):
return self.ranges[index][1]
def playback_started(video):
"""
Determine if video has started
:param video: The VideoPuppeteer instance that we are interested in.
:return: True if is playing; False otherwise
"""
try:
played_ranges = video.played
return (
played_ranges.length > 0 and
played_ranges.start(0) < played_ranges.end(0) and
played_ranges.end(0) > 0.0
)
except Exception as e:
print ('Got exception {}'.format(e))
return False
def playback_done(video):
"""
If we are near the end and there is still a video element, then
we are essentially done. If this happens to be last time we are polled
before the video ends, we won't get another chance.
:param video: The VideoPuppeteer instance that we are interested in.
:return: True if we are close enough to the end of playback; False
otherwise.
"""
if video.remaining_time < video.interval:
return True
# Check to see if the video has stalled. Accumulate the amount of lag
# since the video started, and if it is too high, then raise.
if video.stall_wait_time and (video.lag > video.stall_wait_time):
raise VideoException('Video {} stalled.\n{}'
.format(video.video_url, video))
# We are cruising, so we are not done.
return False

Просмотреть файл

@ -61,10 +61,10 @@ class YouTubePuppeteer(VideoPuppeteer):
for attempt in range(5):
sleep(1)
self.process_ad()
if (self.ad_inactive and self.duration and not
if (self.ad_inactive and self._last_seen_video_state.duration and not
self.player_buffering):
break
self.update_expected_duration()
self._update_expected_duration()
def player_play(self):
"""
@ -388,9 +388,10 @@ class YouTubePuppeteer(VideoPuppeteer):
if not (self.ad_playing or self.player_measure_progress() == 0):
return None
# If the ad is not Flash...
if (self.ad_playing and self.video_src.startswith('mediasource') and
self.duration):
return self.duration
if (self.ad_playing and
self._last_seen_video_state.video_src.startswith('mediasource') and
self._last_seen_video_state.duration):
return self._last_seen_video_state.duration
selector = '.html5-media-player .videoAdUiAttribution'
wait = Wait(self.marionette, timeout=5)
try:
@ -423,7 +424,7 @@ class YouTubePuppeteer(VideoPuppeteer):
def condition():
# no ad is playing and current_time stands still
return (not self.ad_playing and
self.measure_progress() < 0.1 and
self._measure_progress() < 0.1 and
self.player_measure_progress() < 0.1 and
(self.player_playing or self.player_buffering))

Просмотреть файл

@ -11,8 +11,8 @@ from external_media_harness.testcase import MediaTestCase
from external_media_tests.media_utils.video_puppeteer import VideoException
from external_media_tests.media_utils.youtube_puppeteer import (
YouTubePuppeteer,
playback_done,
wait_for_almost_done
wait_for_almost_done,
playback_done
)
@ -26,7 +26,8 @@ class TestBasicYouTubePlayback(MediaTestCase):
interval=1)
try:
verbose_until(wait, youtube,
lambda y: y.video_src.startswith('blob'),
lambda y: y._last_seen_video_state.
video_src.startswith('blob'),
"Failed to find 'blob' in video src url.")
except TimeoutException as e:
raise self.failureException(e)