Closed Bug 1300653 Opened 8 years ago Closed 8 years ago

Video Puppeteer races on playback done check

Categories

(Testing Graveyard :: external-media-tests, defect)

Product:
Testing Graveyard
Component:
external-media-tests
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox50 affected, firefox51 affected, firefox52 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla52
Tracking Flags:
Tracking Status
firefox50 --- affected
firefox51 --- affected
firefox52 --- fixed

People

(Reporter: bryce, Assigned: bryce)

References

Details

Attachments

(2 files, 1 obsolete file)

Bug 1300653 - Update VideoPuppeteer to store state snapshots to prevent racing.
58 bytes, text/x-review-board-request
impossibus
: review+
Details
Bug 1300653 - Update youtube puppeteer to store snapshots of state to prevent racing.
58 bytes, text/x-review-board-request
impossibus
: review+
Details 
VideoPuppeteer makes a query during playback_done() to check if the video has finished (or is close to finishing), it then makes a check to see if the video has stalled. Each of these checks makes a separate query to the running FF instance.

However, if latency is introduced between these queries, it's possible for the first to indicate that the video has not finished, but for the video to have finished and have passed the stall time by the time the second check is done. Test runs on slow machines show lags of 10+ seconds are possible, which is a concern, and should be investigated in another bug.

Below is a parital log from what I believe is a run that has failed in the above way:
>AssertionError: Video https://www.youtube.com/embed/AbAACm1IQE0?autoplay=1stalled.
> 09:10:12     INFO -  VideoPuppeteer - test url: https://youtube.com/embed/AbAACm1IQE0?autoplay=1: {
> 09:10:12     INFO -  	(video)
> 09:10:12     INFO -  	current_time: 12.601,
> 09:10:12     INFO -  	duration: 12.601,
> 09:10:12     INFO -  	expected_duration: 12.601,
> 09:10:12     INFO -  	played: TimeRanges: length: 1, ranges: [(0, 12.601)]
> 09:10:12     INFO -   lag: 13.3575476543,

Note that the current time and duration have reached the expected duration, but also the the lag is > 10 seconds, and that the test is failing.

The check for completion and to see if the test have stalled should be made as low latency as possible.
Assignee: nobody → bvandyk
status-firefox50: --- → affected
status-firefox51: --- → affected
OS: Unspecified → All
Hardware: Unspecified → All
Comment on attachment 8788287 [details]
Bug 1300653 - VideoPuppeteer.playback_done() now queries time data once to prevent racing.

Removing review request. I'm going to rework this further to try and enable state to be more consistent across the various functions in the class.
Attachment #8788287 - Flags: review?(mjzffr)
Attachment #8788287 - Attachment is obsolete: true
Comment on attachment 8791034 [details]
Bug 1300653 - Update VideoPuppeteer to store state snapshots to prevent racing.

https://reviewboard.mozilla.org/r/78586/#review77422

I suggest you push to try with some failing tests to check the behaviour of the new log messages.
Also run jobs that exercise YoutubePuppeteer (VP(b-y))

Next time could you please separate your work into more and smaller patches if possible -- much faster to review that way. :)

This patch looks correct overall. I've focused on suggesting various ways to make the code less repetitive. The same ideas apply to the second patch in the series so I will just clear the second review request for now.

::: dom/media/test/external/external_media_tests/media_utils/video_puppeteer.py:209
(Diff revision 1)
> +            self.expected_duration = self._set_duration
> +        else:
> +            self.expected_duration = remaining_video
>  
> -    @property
> -    def lag(self):
> +    @staticmethod
> +    def _video_var_script():

You might want to maintain a corresponding instance variable to avoid rebuilding the string every time this is called.

Example of what I mean: https://dxr.mozilla.org/mozilla-central/rev/8a494adbc5cced90a4edf0c98cffde906bf7f3ae/testing/mozharness/mozharness/base/script.py#2048

Subclasses will still be able to append to the string when they override the method.

::: dom/media/test/external/external_media_tests/media_utils/video_puppeteer.py:251
(Diff revision 1)
> +                'video.getVideoPlaybackQuality()["droppedVideoFrames"];'
> +            'var corruptedFrames = '
> +                'video.getVideoPlaybackQuality()["corruptedVideoFrames"];'
> +        )
> +
> +    def _state_named_tuple(self):

How about defining a function that takes care of instantiating the state info right away so you can do something like `self.record_state(current_time=current_time,...)` in one call?

```
def record_state(self, **kwargs):
    si = namedtuple('state_info', ...)
    return si(**kwargs)
```

::: dom/media/test/external/external_media_tests/media_utils/video_puppeteer.py:305
(Diff revision 1)
> +            current_time=current_time,
> +            duration=duration,
> +            remaining_time=remaining_time,
> +            played=played_ranges,
> +            lag=lag,
> +            total_frames=total_frames,
> +            dropped_frames=dropped_frames,
> +            corrupted_frames=corrupted_frames,
> +            video_src=self.video.get_attribute('src'),
> +            video_url=self.video.get_attribute('url')

If you accumulate all these parameters in a dict instead of individual variables above, you can take advantage of keyword argument unpacking like `state_info(**params)` to avoid repetition.

::: dom/media/test/external/external_media_tests/media_utils/video_puppeteer.py:339
(Diff revision 1)
>          if self.video:
> +            if self._last_seen_state:
> -            messages += [
> +                messages += [

We can avoid nesting, improve readability here. Something like
```
if not self.video:
    return <some message>
if not self._last_seen_state:
    return <other message>
messages += <big list of messages>
return messages
```

You should take advantage of `namedtuple` features:

* namedtuples have a nice one-line repr like "state_info(video_url=..., total_frames=5)". If you don't like that format you could define a custom `__repr__` for your namedtuple so that it can be used in VideoPuppeteer's `__str__` definition.
* Or in `VP.__str__` you can make one call to `format` on one multi-line string - something like:
```
"""\tduration: {duration},
\turl: {video_url}
""".format(**vars(self._last_seen_state))
```

::: dom/media/test/external/external_media_tests/playback/youtube/test_basic_playback.py:65
(Diff revision 1)
>                  try:
>                      verbose_until(Wait(youtube,
>                                         timeout=max(100, time_left) * 1.3,
>                                         interval=1),
>                                    youtube,
>                                    playback_done)

This is undefined now.
Attachment #8791034 - Flags: review?(mjzffr) → review-
Comment on attachment 8791035 [details]
Bug 1300653 - Update youtube puppeteer to store snapshots of state to prevent racing.

https://reviewboard.mozilla.org/r/78588/#review77450
Comment on attachment 8791034 [details]
Bug 1300653 - Update VideoPuppeteer to store state snapshots to prevent racing.

https://reviewboard.mozilla.org/r/78586/#review77422

> How about defining a function that takes care of instantiating the state info right away so you can do something like `self.record_state(current_time=current_time,...)` in one call?
> 
> ```
> def record_state(self, **kwargs):
>     si = namedtuple('state_info', ...)
>     return si(**kwargs)
> ```

I've split out each class into maintaining it's own named tuple. The video tuple tracks the tuple storing video info, and the yt tuple tracks player state. Each now has a function that handles the creation of these tuples given required data. This cuts down somewhat on duplication of logic in both classes, the yt puppeteer calls into its parent to have it handle much of the video snapshotting.

> We can avoid nesting, improve readability here. Something like
> ```
> if not self.video:
>     return <some message>
> if not self._last_seen_state:
>     return <other message>
> messages += <big list of messages>
> return messages
> ```
> 
> You should take advantage of `namedtuple` features:
> 
> * namedtuples have a nice one-line repr like "state_info(video_url=..., total_frames=5)". If you don't like that format you could define a custom `__repr__` for your namedtuple so that it can be used in VideoPuppeteer's `__str__` definition.
> * Or in `VP.__str__` you can make one call to `format` on one multi-line string - something like:
> ```
> """\tduration: {duration},
> \turl: {video_url}
> """.format(**vars(self._last_seen_state))
> ```

Updated these to be more concise. I look over the `_fields` of the tuples so I can do some indented pretty printing while keeping the code concise.
Comment on attachment 8791034 [details]
Bug 1300653 - Update VideoPuppeteer to store state snapshots to prevent racing.

https://reviewboard.mozilla.org/r/78586/#review78492

r+wc

This is fine. I've left more suggestions for conciseness.

::: dom/media/test/external/external_media_tests/media_utils/video_puppeteer.py:281
(Diff revisions 1 - 2)
> +                                 current_time,
> +                                 duration,
> +                                 played,
> +                                 total_frames,
> +                                 dropped_frames,
> +                                 corrupted_frames):

Change the parameter list to just `**video_state_info_kwargs`, then you can omit lines 296-302 below. You will need to call the method as `_create_video_state_info(current_time=a, duration=b, ...)` in `_refresh_state` for this to work.

::: dom/media/test/external/external_media_tests/media_utils/video_puppeteer.py:333
(Diff revisions 1 - 2)
>          information, such as lag. This is stored in the last seen state to
>          stress that it's based on the snapshot.
>          """
> -        fetch_video_state_script = self._video_var_script() + (
> -            'return [currentTime,'
> +        if not self._fetch_state_script:
> +            self._fetch_state_script = (
> +                self._video_var_script() +

Since you're not overriding or extending `_video_var_script` and `_player_var_script`, why not just define these as class attributes instead of static methods?

Also, it would be cleaner to define a `fetch_state_script` property that you can override in YouTubePuppeteer:

```
@property
def fetch_state_script(self):
    if not self._fetch_state_script:
         # build it
    
    return self._fetch_state_script
```

and then `_refresh_state` would just use `self.fetch_state_script` like a regular instance attribute.

::: dom/media/test/external/external_media_tests/media_utils/video_puppeteer.py:346
(Diff revisions 1 - 2)
> -         corrupted_frames) = self._execute_video_script(
> -            fetch_video_state_script
> -        )
> -        # Calculate lag
> +         corrupted_frames
> +         ) = self._execute_video_script(self._fetch_state_script)
> +        self._last_seen_video_state = (
> +            self._create_video_state_info(

Pass a dict to `_create_video_state_info` to reduce repetition in that function. 
```
keys = ['current_time', 'duration', 'raw_time_ranges', ...]
values = self._execute_video_script(self._fetch_state_script)
self._last_seen_video_state = self._create_video_state_info(dict(zip(keys,values)))
```
Convert raw_time_ranges to TimeRanges in `_create_video_state_info`

::: dom/media/test/external/external_media_tests/media_utils/video_puppeteer.py:389
(Diff revisions 1 - 2)
> -            else:
> -                messages += ['\tvideo: No last seen state']
> -        else:
> -            messages += ['\tvideo: None']
> -        messages.append('}')
> +        # 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)))]

This is great.

You no longer want to include `self.expected_duration` and `self.internal` in the messages?
Attachment #8791034 - Flags: review?(mjzffr) → review+
Comment on attachment 8791035 [details]
Bug 1300653 - Update youtube puppeteer to store snapshots of state to prevent racing.

https://reviewboard.mozilla.org/r/78588/#review78508

r+wc
Many of the same refactoring comments as with previous patch in series. Otherwise looks good.

::: dom/media/test/external/external_media_tests/media_utils/youtube_puppeteer.py:302
(Diff revision 2)
> +                                  player_duration,
> +                                  player_current_time,
> +                                  player_playback_quality,
> +                                  player_movie_id,
> +                                  player_movie_title,
> +                                  player_url,
> +                                  player_state,
> +                                  player_ad_state,
> +                                  player_breaks_count):

See comment about `_create_video_state_info`.
Attachment #8791035 - Flags: review?(mjzffr) → review+
Pushed by bvandyk@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/2627ef511422
Update VideoPuppeteer to store state snapshots to prevent racing. r=maja_zf
https://hg.mozilla.org/integration/autoland/rev/e3cff5e3ae3c
Update youtube puppeteer to store snapshots of state to prevent racing. r=maja_zf
https://hg.mozilla.org/mozilla-central/rev/2627ef511422
https://hg.mozilla.org/mozilla-central/rev/e3cff5e3ae3c
Status: NEW → RESOLVED
Closed: 8 years ago
status-firefox52: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla52
Product: Testing → Testing Graveyard
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: