Closed Bug 1251763 Opened 4 years ago Closed 4 years ago

Incorrect null check for returned elements in ElementManager#find_

Categories

(Testing :: Marionette, defect, P1)

Unspecified
Windows
defect

Tracking

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

VERIFIED FIXED
mozilla48
Tracking Status
firefox44 --- unaffected
firefox45 --- unaffected
firefox46 --- unaffected
firefox47 --- unaffected
firefox48 --- fixed

People

(Reporter: sydpolk, Assigned: ato)

References

Details

(Keywords: pi-marionette-server)

Attachments

(3 files, 1 obsolete file)

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
OS: Unspecified → Windows
e10s is ON for this.
Attached image Screen Shot 2016-02-29 at 17.42.46.png (obsolete) —
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.
Component: external-media-tests → Audio/Video
Product: Testing → Core
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?
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
Component: Audio/Video → external-media-tests
Product: Core → Testing
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
I ran a mozregression. Bug 1250102 is the changed that caused this behavior, the fact that getElementsByTagName('video') does not work with Netflix.
Where can I find the external-media-tests?
Flags: needinfo?(spolk)
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)
Any word on this? Waiting...
bumping the priority on this and will speak to Andreas tomorrow.
Priority: -- → P1
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)
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.
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: nobody → ato
Status: NEW → ASSIGNED
Component: external-media-tests → Marionette
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_
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)
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
https://hg.mozilla.org/mozilla-central/rev/f2a7717d73c0
https://hg.mozilla.org/mozilla-central/rev/f2cdd79de566
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla48
Syd: Can you confirm that this fixes the problem in the video tests?
Flags: needinfo?(spolk)
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)
Status: RESOLVED → VERIFIED
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."
You need to log in before you can comment on or make changes to this bug.