1251763 - Incorrect null check for returned elements in ElementManager#find_

Status: VERIFIED FIXED

(Remote Protocol :: Marionette, defect, P1)

Description

[Syd Polk :sydpolk]

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

Comment 1

[Syd Polk :sydpolk]

e10s is ON for this.

Comment 2

[Syd Polk :sydpolk]

Attachment: Screen Shot 2016-02-29 at 17.42.46.png

Comment 3

[Syd Polk :sydpolk]

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.

Comment 4

[Chris Peterson [:cpeterson]]

(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?

Comment 5

[Syd Polk :sydpolk]

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.

Comment 6

[Masatoshi Kimura [:emk]]

(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

Comment 7

[Syd Polk :sydpolk]

Attachment: 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.

Comment 8

[Syd Polk :sydpolk]

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

Comment 9

[Andreas Tolfsen ❲:ato❳]

Where can I find the external-media-tests?

Comment 10

[Andreas Tolfsen ❲:ato❳]

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.

Comment 11

[David Burns :automatedtester]

Where are we with the fix for this?

Comment 12

[Syd Polk :sydpolk]

Any word on this? Waiting...

Comment 13

[David Burns :automatedtester]

bumping the priority on this and will speak to Andreas tomorrow.

Comment 14

[Andreas Tolfsen ❲:ato❳]

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,[]]

Comment 15

[Andreas Tolfsen ❲: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.

Comment 16

[Andreas Tolfsen ❲:ato❳]

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)

Comment 17

[Andreas Tolfsen ❲:ato❳]

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.

Comment 18

[Andreas Tolfsen ❲:ato❳]

Attachment: 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/

Comment 19

[Andreas Tolfsen ❲:ato❳]

Attachment: 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/

Comment 20

[David Burns :automatedtester]

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

Comment 21

[David Burns :automatedtester]

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

[Pulsebot]

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

Comment 23

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/f2a7717d73c0
https://hg.mozilla.org/mozilla-central/rev/f2cdd79de566

Comment 24

[Andreas Tolfsen ❲:ato❳]

Syd: Can you confirm that this fixes the problem in the video tests?

Comment 25

[Syd Polk :sydpolk]

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

Comment 26

[Syd Polk :sydpolk]

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/

Comment 27

[Liz Henry (:lizzard) (relman/hg->git project)]

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."

Comment 28

[David Burns :automatedtester]

https://hg.mozilla.org/releases/mozilla-aurora/rev/b5e97e81ab9d
https://hg.mozilla.org/releases/mozilla-aurora/rev/c9166eb24b3f