Incorrect null check for returned elements in ElementManager#find_

VERIFIED FIXED in Firefox 48

Status

Testing
Marionette
P1
normal
VERIFIED FIXED
2 years ago
2 years ago

People

(Reporter: sydpolk, Assigned: ato)

Tracking

({ateam-marionette-server})

unspecified
mozilla48
Unspecified
Windows
ateam-marionette-server
Points:
---

Firefox Tracking Flags

(firefox44 unaffected, firefox45 unaffected, firefox46 unaffected, firefox47 unaffected, firefox48 fixed)

Details

MozReview Requests

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(3 attachments, 1 obsolete attachment)

(Reporter)

Description

2 years ago
It looks like Netflix no longer presents an element with the tag 'video':

$ external-media-tests --binary=/c/Program\ Files\ \(x86\)/Nightly/firefox.exe --profile /c/testing/eme_profile --urls external_media_tests/urls/netflix/default.ini external_media_tests/playback/eme.ini
 0:00.00 LOG: MainThread INFO Using workspace for temporary data: "c:\dev\mozilla\mozilla-central\dom\media\test\external"
 0:00.00 LOG: MainThread INFO Profile destination is TMP
 0:21.20 LOG: MainThread INFO starting httpd
 0:21.20 LOG: MainThread INFO running httpd on http://127.0.0.1:12287/
 0:21.20 LOG: MainThread mozversion INFO application_buildid: 20160226030256
 0:21.20 LOG: MainThread mozversion INFO application_changeset: 918df3a0bc1c4d07299e4f66274a7da923534577
 0:21.20 LOG: MainThread mozversion INFO application_display_name: Nightly
 0:21.20 LOG: MainThread mozversion INFO application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384}
 0:21.20 LOG: MainThread mozversion INFO application_name: Firefox
 0:21.20 LOG: MainThread mozversion INFO application_remotingname: firefox
 0:21.20 LOG: MainThread mozversion INFO application_repository: https://hg.mozilla.org/mozilla-central
 0:21.21 LOG: MainThread mozversion INFO application_vendor: Mozilla
 0:21.21 LOG: MainThread mozversion INFO application_version: 47.0a1
 0:21.21 LOG: MainThread mozversion INFO platform_buildid: 20160226030256
 0:21.21 LOG: MainThread mozversion INFO platform_changeset: 918df3a0bc1c4d07299e4f66274a7da923534577
 0:21.21 LOG: MainThread mozversion INFO platform_repository: https://hg.mozilla.org/mozilla-central
 0:21.21 LOG: MainThread mozversion INFO platform_version: 47.0a1
 0:21.21 SUITE_START: MainThread 1
 0:21.21 TEST_START: MainThread test_eme_playback.py TestEMEPlayback.test_playback_starts
 0:21.41 LOG: MainThread INFO Pref media.mediasource.enabled = True
 0:21.42 LOG: MainThread INFO Pref media.eme.enabled = True
 0:21.43 LOG: MainThread INFO Pref media.mediasource.mp4.enabled = True
 0:21.44 LOG: MainThread INFO Pref media.gmp-eme-adobe.enabled = True
 0:21.45 LOG: MainThread INFO Pref media.gmp-eme-adobe.version = 17
 0:23.01 LOG: MainThread INFO http://www.netflix.com/watch/70136810
Got exception JavascriptException: TypeError: arguments[0] is null
stacktrace:
	execute_script @video_puppeteer.py, line 203
	inline javascript, line 0
	src: "var __marionetteFunc = function(){return arguments[0].wrappedJSObject.currentTime;};__marionetteFunc.apply(null, __marionetteParams);"
	Stack:
	__marionetteFunc@video_puppeteer.py:0:35
	@video_puppeteer.py:0:89
status-firefox44: --- → ?
status-firefox45: --- → ?
status-firefox46: --- → ?
status-firefox47: --- → affected
OS: Unspecified → Windows
(Reporter)

Comment 1

2 years ago
e10s is ON for this.
(Reporter)

Comment 2

2 years ago
Created attachment 8724999 [details]
Screen Shot 2016-02-29 at 17.42.46.png
(Reporter)

Comment 3

2 years ago
So, looking with the Inspector in the web console, I found this (see screenshot):

<video src="mediasource:http://www.netflix.com/646014d2-749f-4c6b-841c-e7263f1df8a5" style="position: absolute; width: 100%; height: 100%;"></video>

However, the browser console does not find it:

>> var videos = document.getElementsByTagName('video')
<- undefined

When our test runs, marionette executes this JavaScript, and it doesn't work, and things go boom.
(Reporter)

Updated

2 years ago
Component: external-media-tests → Audio/Video
Product: Testing → Core
(Reporter)

Updated

2 years ago
Summary: Netflix tests fail even though Netflix video plays → When looking at a Netflix page, document.getElementsByTagName('video') fails.
(In reply to Syd Polk :sydpolk from comment #3)
> When our test runs, marionette executes this JavaScript, and it doesn't
> work, and things go boom.

Is this a race condition during page load? How long, or for what condition, does the marionette test wait before looking for the video element?
(Reporter)

Comment 5

2 years ago
This happens when I navigate to a movie by hand, load it, watch it start playing, and then use the console. Does not need to be in the test.
(In reply to Syd Polk :sydpolk from comment #3)
> So, looking with the Inspector in the web console, I found this (see
> screenshot):
> 
> <video
> src="mediasource:http://www.netflix.com/646014d2-749f-4c6b-841c-
> e7263f1df8a5" style="position: absolute; width: 100%; height: 100%;"></video>

I could not find it in the screenshot. where did you find it?

> >> var videos = document.getElementsByTagName('video')
> <- undefined

It's expected that |var foo = bar| would return undefined.

>> var a = 1
<- undefined
>> a
<- 1
(Reporter)

Updated

2 years ago
Component: Audio/Video → external-media-tests
Product: Core → Testing
(Reporter)

Comment 7

2 years ago
Created attachment 8725092 [details]
Screen Shot 2016-02-29 at 22.11.45.png

So, I was wrong. I can get the video element and the current time using the web console once the video is playing.
Attachment #8724999 - Attachment is obsolete: true
(Reporter)

Comment 8

2 years ago
I ran a mozregression. Bug 1250102 is the changed that caused this behavior, the fact that getElementsByTagName('video') does not work with Netflix.
(Assignee)

Comment 9

2 years ago
Where can I find the external-media-tests?
Flags: needinfo?(spolk)
(Assignee)

Comment 10

2 years ago
Nevermind, I found them in dom/media/test/external/external_media_tests.  It looks like the explicit wait condition to look up the <video> element fails in https://github.com/mozilla/gecko-dev/blob/master/dom/media/test/external/external_media_tests/media_utils/video_puppeteer.py#L76.

I should highlight that this isn't doing a simple document.getElementsByTagName("video") call underneath, but polls continuously for a given duration until <video> is found in the document before returning.

sydpolk is correct that bug 1250102 is likely the cause of this, as it also changed the whole element location routine in Marionette.  The functional Marionette tests are passing, but they are clearly missing an edge case.

I will investigate further.
Flags: needinfo?(spolk)
Where are we with the fix for this?
Flags: needinfo?(ato)
Blocks: 1250102
(Reporter)

Comment 12

2 years ago
Any word on this? Waiting...
bumping the priority on this and will speak to Andreas tomorrow.
Priority: -- → P1
(Assignee)

Comment 14

2 years ago
From the logs Syd sent me, it appears the findElement command successfully returns the <video> element first but that the subsequent findElements (plural) does not:

1456947171233	Marionette	TRACE	conn4 -> [0,93,"findElement",{"using":"tag name","value":"video"}]
1456947171342	Marionette	TRACE	conn4 <- [1,93,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"0fb4377c-2bc9-40de-aafa-f676250254db","ELEMENT":"0fb4377c-2bc9-40de-aafa-f676250254db"}}]
1456947171343	Marionette	TRACE	conn4 -> [0,94,"findElements",{"using":"css selector","value":"video"}]
1456947171446	Marionette	TRACE	conn4 <- [1,94,null,[]]
Flags: needinfo?(ato)
(Assignee)

Comment 15

2 years ago
Being unable to reproduce the exact problem because I do not have access to Netflix on Linux or Mac, I used the Python REPL (`./mach python`) to do some exploratory testing.

I found that findElement _always_ returns something, usually something that resolves to a stale element reference, for the following selectors:

  * tag name
  * name
  * class name
  * link text
  * partial link text

The remaining selectors are unaffected, and correctly returns a no such element error:

  * id
  * css selector
  * xpath

On the other hand the findElements command appears to always return the expected result for all of the selectors.  This leads me to conclude there is a bug with certain selectors in findElement.

A temporary workaround for the time being is to use the plural findElements, but I expect to have a fix for this soon.
(Assignee)

Comment 16

2 years ago
I should also add that the current behaviour appears unaffected by using implicit element search.

This can be enabled from the client:

    marionette.set_search_timeout(500)
(Assignee)

Updated

2 years ago
Assignee: nobody → ato
Status: NEW → ASSIGNED
Component: external-media-tests → Marionette
Keywords: ateam-marionette-server
(Assignee)

Comment 17

2 years ago
In ElementManager#find_ there is an incorrect null check on `res` that is returned from `searchFn`.  After it tested on whether it’s a collection, the line

    } else if (res !== null) {

should be changed to

    } else if (res) {

to do a loose false test instead, since we cannot rely on the return values of the different element search functions used in searchFn to have consistent return types.
Summary: When looking at a Netflix page, document.getElementsByTagName('video') fails. → Incorrect null check for returned elements in ElementManager#find_
(Assignee)

Comment 18

2 years ago
Created attachment 8727927 [details]
MozReview Request: Bug 1251763 - Correct type check on singular returned elements; r?automatedtester

The return values from the different element search functions in searchFn
have inconsistent return types, and a null check is usually not what
we want.  In order to have findElement consistently return a no such
element error, we need to do a loose false test.

This bug has affected the findElement command when using the tag
name, name, class name, link text, and partial link text selectors.
Other selectors were unaffected.

Review commit: https://reviewboard.mozilla.org/r/38685/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/38685/
Attachment #8727927 - Flags: review?(dburns)
(Assignee)

Comment 19

2 years ago
Created attachment 8727928 [details]
MozReview Request: Bug 1251763 - Reduce repetition in test_findelement.py; r?automatedtester

Review commit: https://reviewboard.mozilla.org/r/38687/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/38687/
Attachment #8727928 - Flags: review?(dburns)
Comment on attachment 8727927 [details]
MozReview Request: Bug 1251763 - Correct type check on singular returned elements; r?automatedtester

https://reviewboard.mozilla.org/r/38685/#review35365
Attachment #8727927 - Flags: review?(dburns) → review+
Attachment #8727928 - Flags: review?(dburns) → review+
Comment on attachment 8727928 [details]
MozReview Request: Bug 1251763 - Reduce repetition in test_findelement.py; r?automatedtester

https://reviewboard.mozilla.org/r/38687/#review35367

Comment 22

2 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/f2a7717d73c0
https://hg.mozilla.org/integration/mozilla-inbound/rev/f2cdd79de566

Comment 23

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/f2a7717d73c0
https://hg.mozilla.org/mozilla-central/rev/f2cdd79de566
Status: ASSIGNED → RESOLVED
Last Resolved: 2 years ago
status-firefox48: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla48
(Assignee)

Comment 24

2 years ago
Syd: Can you confirm that this fixes the problem in the video tests?
Flags: needinfo?(spolk)
(Reporter)

Comment 25

2 years ago
Using the latest, the tests run successfully:

 0:00.00 LOG: MainThread INFO Using workspace for temporary data: "c:\dev\mozilla\mozilla-central-clean"
 0:04.40 LOG: MainThread INFO Initial Profile Destination is "c:\users\mozilla\appdata\local\temp\tmpb53iku"
 0:04.40 LOG: MainThread INFO starting httpd
 0:04.40 LOG: MainThread INFO running httpd on http://127.0.0.1:1220/
{"thread": "MainThread", "level": "INFO", "pid": 928, "component": "mozversion", "source": "Marionette test runner", "time": 1457640468332, "action": "log", "message": "application_buildid: 20160310134118"}
{"thread": "MainThread", "level": "INFO", "pid": 928, "component": "mozversion", "source": "Marionette test runner", "time": 1457640468332, "action": "log", "message": "application_changeset: dd1abe874252e507b825a0a4e1063b0e13578288"}
{"thread": "MainThread", "level": "INFO", "pid": 928, "component": "mozversion", "source": "Marionette test runner", "time": 1457640468332, "action": "log", "message": "application_display_name: Nightly"}
{"thread": "MainThread", "level": "INFO", "pid": 928, "component": "mozversion", "source": "Marionette test runner", "time": 1457640468333, "action": "log", "message": "application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384}"}
{"thread": "MainThread", "level": "INFO", "pid": 928, "component": "mozversion", "source": "Marionette test runner", "time": 1457640468333, "action": "log", "message": "application_name: Firefox"}
{"thread": "MainThread", "level": "INFO", "pid": 928, "component": "mozversion", "source": "Marionette test runner", "time": 1457640468333, "action": "log", "message": "application_remotingname: firefox"}
{"thread": "MainThread", "level": "INFO", "pid": 928, "component": "mozversion", "source": "Marionette test runner", "time": 1457640468333, "action": "log", "message": "application_vendor: Mozilla"}
{"thread": "MainThread", "level": "INFO", "pid": 928, "component": "mozversion", "source": "Marionette test runner", "time": 1457640468333, "action": "log", "message": "application_version: 48.0a1"}
{"thread": "MainThread", "level": "INFO", "pid": 928, "component": "mozversion", "source": "Marionette test runner", "time": 1457640468333, "action": "log", "message": "platform_buildid: 20160310134118"}
{"thread": "MainThread", "level": "INFO", "pid": 928, "component": "mozversion", "source": "Marionette test runner", "time": 1457640468333, "action": "log", "message": "platform_changeset: dd1abe874252e507b825a0a4e1063b0e13578288"}
{"thread": "MainThread", "level": "INFO", "pid": 928, "component": "mozversion", "source": "Marionette test runner", "time": 1457640468333, "action": "log", "message": "platform_version: 48.0a1"}
 0:04.40 SUITE_START: MainThread 1
 0:04.41 TEST_START: MainThread test_eme_playback.py TestEMEPlayback.test_playback_starts
{"source": "Marionette test runner", "thread": "MainThread", "time": 1457640468522, "action": "log", "message": "Pref media.mediasource.enabled = True", "level": "INFO", "pid": 928}
{"source": "Marionette test runner", "thread": "MainThread", "time": 1457640468530, "action": "log", "message": "Pref media.eme.enabled = True", "level": "INFO", "pid": 928}
{"source": "Marionette test runner", "thread": "MainThread", "time": 1457640468540, "action": "log", "message": "Pref media.mediasource.mp4.enabled = True", "level": "INFO", "pid": 928}
{"source": "Marionette test runner", "thread": "MainThread", "time": 1457640468550, "action": "log", "message": "Pref media.gmp-eme-adobe.enabled = True", "level": "INFO", "pid": 928}
{"source": "Marionette test runner", "thread": "MainThread", "time": 1457640468562, "action": "log", "message": "Pref media.gmp-eme-adobe.version = 17", "level": "INFO", "pid": 928}
{"source": "Marionette test runner", "thread": "MainThread", "time": 1457640478015, "action": "log", "message": "http://www.netflix.com/watch/70136810", "level": "INFO", "pid": 928}
{"source": "Marionette test runner", "thread": "MainThread", "time": 1457640483501, "action": "log", "message": "http://www.netflix.com/watch/70304192", "level": "INFO", "pid": 928}
{"source": "Marionette test runner", "thread": "MainThread", "time": 1457640487884, "action": "log", "message": "http://www.netflix.com/watch/80015538", "level": "INFO", "pid": 928}
 0:26.37 TEST_END: MainThread PASS
 0:26.37 TEST_START: MainThread test_eme_playback.py TestEMEPlayback.test_video_playback_partial
{"source": "Marionette test runner", "thread": "MainThread", "time": 1457640490549, "action": "log", "message": "Pref media.mediasource.enabled = True", "level": "INFO", "pid": 928}
{"source": "Marionette test runner", "thread": "MainThread", "time": 1457640490557, "action": "log", "message": "Pref media.eme.enabled = True", "level": "INFO", "pid": 928}
{"source": "Marionette test runner", "thread": "MainThread", "time": 1457640490565, "action": "log", "message": "Pref media.mediasource.mp4.enabled = True", "level": "INFO", "pid": 928}
{"source": "Marionette test runner", "thread": "MainThread", "time": 1457640490572, "action": "log", "message": "Pref media.gmp-eme-adobe.enabled = True", "level": "INFO", "pid": 928}
{"source": "Marionette test runner", "thread": "MainThread", "time": 1457640490584, "action": "log", "message": "Pref media.gmp-eme-adobe.version = 17", "level": "INFO", "pid": 928}
{"source": "Marionette test runner", "thread": "MainThread", "time": 1457640496219, "action": "log", "message": "http://www.netflix.com/watch/70136810", "level": "INFO", "pid": 928}
{"source": "Marionette test runner", "thread": "MainThread", "time": 1457640561709, "action": "log", "message": "http://www.netflix.com/watch/70304192", "level": "INFO", "pid": 928}
{"source": "Marionette test runner", "thread": "MainThread", "time": 1457640626867, "action": "log", "message": "http://www.netflix.com/watch/80015538", "level": "INFO", "pid": 928}
 3:43.17 TEST_END: MainThread PASS
 3:43.17 LOG: MainThread INFO START LOG:
 3:43.17 LOG: MainThread INFO INFO TEST-START: c:\dev\mozilla\mozilla-central-clean\dom\media\test\external\external_media_tests\playback\test_eme_playback.py:test_playback_starts Thu Mar 10 2016 14:07:48 GMT-0600 (Central Standard Time)
 3:43.17 LOG: MainThread INFO INFO URL: http://www.netflix.com/watch/70136810 Thu Mar 10 2016 14:07:52 GMT-0600 (Central Standard Time)
 3:43.17 LOG: MainThread INFO INFO video element obtained Thu Mar 10 2016 14:07:55 GMT-0600 (Central Standard Time)
 3:43.17 LOG: MainThread INFO INFO URL: http://www.netflix.com/watch/70304192 Thu Mar 10 2016 14:08:01 GMT-0600 (Central Standard Time)
 3:43.17 LOG: MainThread INFO INFO video element obtained Thu Mar 10 2016 14:08:02 GMT-0600 (Central Standard Time)
 3:43.17 LOG: MainThread INFO INFO URL: http://www.netflix.com/watch/80015538 Thu Mar 10 2016 14:08:05 GMT-0600 (Central Standard Time)
 3:43.17 LOG: MainThread INFO INFO video element obtained Thu Mar 10 2016 14:08:06 GMT-0600 (Central Standard Time)
 3:43.17 LOG: MainThread INFO INFO TEST-END: c:\dev\mozilla\mozilla-central-clean\dom\media\test\external\external_media_tests\playback\test_eme_playback.py:test_playback_starts Thu Mar 10 2016 14:08:10 GMT-0600 (Central Standard Time)
 3:43.17 LOG: MainThread INFO END LOG:
 3:43.17 LOG: MainThread INFO START LOG:
 3:43.17 LOG: MainThread INFO INFO TEST-START: c:\dev\mozilla\mozilla-central-clean\dom\media\test\external\external_media_tests\playback\test_eme_playback.py:test_video_playback_partial Thu Mar 10 2016 14:08:10 GMT-0600 (Central Standard Time)
 3:43.17 LOG: MainThread INFO INFO URL: http://www.netflix.com/watch/70136810 Thu Mar 10 2016 14:08:11 GMT-0600 (Central Standard Time)
 3:43.17 LOG: MainThread INFO INFO video element obtained Thu Mar 10 2016 14:08:14 GMT-0600 (Central Standard Time)
 3:43.17 LOG: MainThread INFO INFO URL: http://www.netflix.com/watch/70304192 Thu Mar 10 2016 14:09:17 GMT-0600 (Central Standard Time)
 3:43.17 LOG: MainThread INFO INFO video element obtained Thu Mar 10 2016 14:09:21 GMT-0600 (Central Standard Time)
 3:43.17 LOG: MainThread INFO INFO URL: http://www.netflix.com/watch/80015538 Thu Mar 10 2016 14:10:22 GMT-0600 (Central Standard Time)
 3:43.17 LOG: MainThread INFO INFO video element obtained Thu Mar 10 2016 14:10:24 GMT-0600 (Central Standard Time)
 3:43.17 LOG: MainThread INFO INFO TEST-END: c:\dev\mozilla\mozilla-central-clean\dom\media\test\external\external_media_tests\playback\test_eme_playback.py:test_video_playback_partial Thu Mar 10 2016 14:11:27 GMT-0600 (Central Standard Time)
 3:43.17 LOG: MainThread INFO END LOG:
 3:43.17 LOG: MainThread INFO 
SUMMARY
-------
 3:43.17 LOG: MainThread INFO passed: 2
 3:43.17 LOG: MainThread INFO failed: 0
 3:43.17 LOG: MainThread INFO todo: 0
 3:43.71 SUITE_END: MainThread 
Summary
=======

Ran 2 tests
Expected results: 2
Unexpected results: 0

OK
Flags: needinfo?(spolk)
(Reporter)

Updated

2 years ago
Status: RESOLVED → VERIFIED
(Reporter)

Comment 26

2 years ago
And the tests pass in automation as well:

http://pf-jenkins.qa.mtv2.mozilla.com:8080/view/mn%20media/job/mn-eme-netflix-nightly-win_32_64/173/
Marking unaffected from email from syd:  "This should also not be tracked for 47. We are not running tests on 47 right now. Once the test suite is completely green on 48, it will ride the trains out."
status-firefox44: ? → unaffected
status-firefox45: ? → unaffected
status-firefox46: ? → unaffected
status-firefox47: affected → unaffected

Comment 28

2 years ago
bugherderuplift
https://hg.mozilla.org/releases/mozilla-aurora/rev/b5e97e81ab9d
https://hg.mozilla.org/releases/mozilla-aurora/rev/c9166eb24b3f
You need to log in before you can comment on or make changes to this bug.