992181 - [1.3] Wait for ready event before Persona signin

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Gaia::UI Tests, defect)

Description

[Florin Strugariu [:Bebe]]

Attachment: Logcat

Description:
blank window is shown when trying to sign in to persona tests 

Environment:
Gaia      f06667bcaef2032849ddee736fffdd7d8d8c02f8
Gecko     https://hg.mozilla.org/releases/mozilla-b2g28_v1_3/rev/021a6f9c27f8
BuildID   20140404004002
Version   28.0
ro.build.version.incremental=324
ro.build.date=Thu Dec 19 14:04:55 CST 2013

Traceback (most recent call last):
test_persona_standard_sign_in (test_persona_app.TestPersonaStandard) ... ERROR

======================================================================
ERROR: None
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/florinstrugariu/.virtualenvs/1.3/local/lib/python2.7/site-packages/marionette_client-0.7.1-py2.7.egg/marionette/marionette_test.py", line 143, in run
    testMethod()
  File "/home/florinstrugariu/gaia/gaia/tests/python/gaia-ui-tests/gaiatest/tests/functional/persona/test_persona_app.py", line 40, in test_persona_standard_sign_in
    persona = moz_id.tap_standard_sign_in()
  File "/home/florinstrugariu/gaia/gaia/tests/python/gaia-ui-tests/gaiatest/apps/ui_tests/regions/persona.py", line 22, in tap_standard_sign_in
    persona = Persona(self.marionette)
  File "/home/florinstrugariu/gaia/gaia/tests/python/gaia-ui-tests/gaiatest/apps/persona/app.py", line 33, in __init__
    self.wait_for_element_present(*self._persona_frame_locator)
  File "/home/florinstrugariu/gaia/gaia/tests/python/gaia-ui-tests/gaiatest/apps/base.py", line 40, in wait_for_element_present
    'Element %s not found before timeout' % locator)
TEST-UNEXPECTED-FAIL | test_persona_app.py test_persona_app.TestPersonaStandard.test_persona_standard_sign_in | TimeoutException: Element iframe.screen[data-url*='persona.org/sign_in#NATIVE'] not found before timeout
----------------------------------------------------------------------
Ran 1 test in 93.800s



Reproducible manually: NO

STR:
Connect to wifi
1. Open UI tests
2. Tap API button 
3. Tap moz id button 
4. Tap standard sign in 

We can see in logcat:
E/GeckoConsole( 1561): [JavaScript Error: "uncaught exception: target window is same as present window -- not allowed"]

Comment 1

[Jason Smith [:jsmith]]

Edwin - Can you followup with the identity team about this?

Comment 2

[Edwin Wong [:edwong]]

Hmm - I can repro this on 1.3. We had a stack push a couple weeks ago but there was no code change. Not sure why it's only when running via marionette.  No repro manually. Jed, any ideas what's wrong here?

here's my logcat:
/GeckoConsole( 2772): [JavaScript Error: "uncaught exception: target window is same as present window -- not allowed"]
I/Gecko   ( 2772): Identity injected identity.js: doInternalWatch: {
I/Gecko   ( 2772):   "id": "{6896e6e6-2e68-4cb1-be3a-06721a81b140}",
I/Gecko   ( 2772):   "origin": "app://uitest.gaiamobile.org",
I/Gecko   ( 2772):   "loggedInUser": null
I/Gecko   ( 2772): } true
E/GeckoConsole( 2772): Identity injected identity.js: doInternalWatch: {
E/GeckoConsole( 2772):   "id": "{6896e6e6-2e68-4cb1-be3a-06721a81b140}",
E/GeckoConsole( 2772):   "origin": "app://uitest.gaiamobile.org",
E/GeckoConsole( 2772):   "loggedInUser": null
E/GeckoConsole( 2772): } true
I/Gecko   ( 1901): WARNING: doReady found no rp to go with callerId {ebbb8d71-b812-4012-9cc9-0d8d0dd86691}
I/Gecko   ( 1901): Identity DOMIdentity: doReady: {27afe6b7-008a-41f4-9127-91097b7f192b}
E/GeckoConsole( 1901): Identity DOMIdentity: doReady: {27afe6b7-008a-41f4-9127-91097b7f192b}
I/Gecko   ( 1901): WARNING: doReady found no rp to go with callerId {6896e6e6-2e68-4cb1-be3a-06721a81b140}
I/Gecko   ( 1901): Identity SignInToWebsiteController: received delegate finished; telling content to close the dialog
E/GeckoConsole( 1901): Identity SignInToWebsiteController: received delegate finished; telling content to close the dialog
I/GeckoDump( 1901): XXX FIXME : Got a mozContentEvent: undefined
I/Gecko   ( 1901): Identity SignInToWebsiteController: No more watchers; clean up persona host iframe
E/GeckoConsole( 1901): Identity SignInToWebsiteController: No more watchers; clean up persona host iframe
I/Gecko   ( 1901): Identity SignInToWebsiteController: telling content to close the dialog
E/GeckoConsole( 1901): Identity SignInToWebsiteController: telling content to close the dialog
I/Gecko   ( 1901): Identity SignInToWebsiteController: received delegate finished; telling content to close the dialog
E/GeckoConsole( 1901): Identity SignInToWebsiteController: received delegate finished; telling content to close the dialog
I/GeckoDump( 1901): XXX FIXME : Got a mozContentEvent: undefined
I/Gecko   ( 1901): Identity SignInToWebsiteController: No more watchers; clean up persona host iframe
E/GeckoConsole( 1901): Identity SignInToWebsiteController: No more watchers; clean up persona host iframe
I/Gecko   ( 1901): Identity SignInToWebsiteController: telling content to close the dialog
E/GeckoConsole( 1901): Identity SignInToWebsiteController: telling content to close the dialog
I/Gecko   ( 1901): Identity SignInToWebsiteController: received delegate finished; telling content to close the dialog
E/GeckoConsole( 1901): Identity SignInToWebsiteController: received delegate finished; telling content to close the dialog
I/GeckoDump( 1901): XXX FIXME : Got a mozContentEvent: undefined
I/Gecko   ( 2972): ###################################### forms.js loaded
I/Gecko   ( 1901): Identity SignInToWebsiteController: No more watchers; clean up persona host iframe
E/GeckoConsole( 1901): Identity SignInToWebsiteController: No more watchers; clean up persona host iframe
I/Gecko   ( 1901): Identity SignInToWebsiteController: telling content to close the dialog
E/GeckoConsole( 1901): Identity SignInToWebsiteController: telling content to close the dialog
I/Gecko   ( 2972): ############################### browserElementPanning.js loaded
I/Gecko   ( 2972): ######################## BrowserElementChildPreload.js loaded
I/Gecko   ( 2972): ###################################### forms.js loaded
I/Gecko   ( 2972): ############################### browserElementPanning.js loaded
I/Gecko   ( 2972): ######################## BrowserElementChildPreload.js loaded
I/Gecko   ( 2973): ###################################### forms.js loaded
I/Gecko   ( 2973): ############################### browserElementPanning.js loaded
I/Gecko   ( 2973): ######################## BrowserElementChildPreload.js loaded
I/Gecko   ( 1901): 1396651797771	Marionette	INFO	sendToClient: {"from":"0","error":{"message":"Unable to locate element: iframe.screen[data-url*='persona.org/sign_in#NATIVE']","status":7,"stacktrace":null}}, {98c0d9de-9e2c-4718-af49-c3552586756e}, {98c0d9de-9e2c-4718-af49-c3552586756e}
I/Gecko   ( 1901): 1396651808347	Marionette	INFO	sendToClient: {"from":"0","error":{"message":"Unable to locate element: iframe.screen[data-url*='persona.org/sign_in#NATIVE']","status":7,"stacktrace":null}}, {ff9e2073-7725-4440-9081-467f1237f229}, {ff9e2073-7725-4440-9081-467f1237f229}
I/Gecko   ( 1901): 1396651818905	Marionette	INFO	sendToClient: {"from":"0","error":{"message":"Unable to locate element: iframe.screen[data-url*='persona.org/sign_in#NATIVE']","status":7,"stacktrace":null}}, {1e874275-02ee-455d-9759-0a70809aebc4}, {1e874275-02ee-455d-9759-0a70809aebc4}

when it

Comment 3

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

(In reply to Edwin Wong [:edwong] from comment #2)
> Hmm - I can repro this on 1.3. We had a stack push a couple weeks ago but
> there was no code change. Not sure why it's only when running via
> marionette.  No repro manually. Jed, any ideas what's wrong here?

Hi, Edwin,

Some notes, and a question at the end:

> here's my logcat:
> /GeckoConsole( 2772): [JavaScript Error: "uncaught exception: target window
> is same as present window -- not allowed"]

That line is ignorable.  It is thrown from the hosted js code for some reason and happens on every browser.  It's a freaky-sounding message, but it is benign.

> I/Gecko   ( 2772): Identity injected identity.js: doInternalWatch: {
> I/Gecko   ( 2772):   "id": "{6896e6e6-2e68-4cb1-be3a-06721a81b140}",
> I/Gecko   ( 2772):   "origin": "app://uitest.gaiamobile.org",
> I/Gecko   ( 2772):   "loggedInUser": null
> I/Gecko   ( 2772): } true
> E/GeckoConsole( 2772): Identity injected identity.js: doInternalWatch: {
> E/GeckoConsole( 2772):   "id": "{6896e6e6-2e68-4cb1-be3a-06721a81b140}",
> E/GeckoConsole( 2772):   "origin": "app://uitest.gaiamobile.org",
> E/GeckoConsole( 2772):   "loggedInUser": null
> E/GeckoConsole( 2772): } true
> I/Gecko   ( 1901): WARNING: doReady found no rp to go with callerId
> {ebbb8d71-b812-4012-9cc9-0d8d0dd86691}

That's a bit suspect.  It's like watch() has been called from a window that has gone away by the time onready() was subsequently invoked?  That's the sort of thing that might happen if an app were evicted due to an out-of-memory (OOM) condition, though if OOM were the reason, I think it would probably manifest intermittently as FxOS picked a random app to kill.  Do you have more context higher up in the log?

> I/Gecko   ( 1901): Identity DOMIdentity: doReady:
> {27afe6b7-008a-41f4-9127-91097b7f192b}
> E/GeckoConsole( 1901): Identity DOMIdentity: doReady:
> {27afe6b7-008a-41f4-9127-91097b7f192b}
> I/Gecko   ( 1901): WARNING: doReady found no rp to go with callerId
> {6896e6e6-2e68-4cb1-be3a-06721a81b140}

Again, strange.  And that's yet another uuid for a different RP.

> I/Gecko   ( 1901): Identity SignInToWebsiteController: received delegate
> finished; telling content to close the dialog
> E/GeckoConsole( 1901): Identity SignInToWebsiteController: received delegate
> finished; telling content to close the dialog
> I/GeckoDump( 1901): XXX FIXME : Got a mozContentEvent: undefined
> I/Gecko   ( 1901): Identity SignInToWebsiteController: No more watchers;
> clean up persona host iframe
> E/GeckoConsole( 1901): Identity SignInToWebsiteController: No more watchers;
> clean up persona host iframe
> I/Gecko   ( 1901): Identity SignInToWebsiteController: telling content to
> close the dialog
> E/GeckoConsole( 1901): Identity SignInToWebsiteController: telling content
> to close the dialog
> I/Gecko   ( 1901): Identity SignInToWebsiteController: received delegate
> finished; telling content to close the dialog
> E/GeckoConsole( 1901): Identity SignInToWebsiteController: received delegate
> finished; telling content to close the dialog
> I/GeckoDump( 1901): XXX FIXME : Got a mozContentEvent: undefined
> I/Gecko   ( 1901): Identity SignInToWebsiteController: No more watchers;
> clean up persona host iframe
> E/GeckoConsole( 1901): Identity SignInToWebsiteController: No more watchers;
> clean up persona host iframe
> I/Gecko   ( 1901): Identity SignInToWebsiteController: telling content to
> close the dialog
> E/GeckoConsole( 1901): Identity SignInToWebsiteController: telling content
> to close the dialog
> I/Gecko   ( 1901): Identity SignInToWebsiteController: received delegate
> finished; telling content to close the dialog
> E/GeckoConsole( 1901): Identity SignInToWebsiteController: received delegate
> finished; telling content to close the dialog
> I/GeckoDump( 1901): XXX FIXME : Got a mozContentEvent: undefined
> I/Gecko   ( 2972): ###################################### forms.js loaded
> I/Gecko   ( 1901): Identity SignInToWebsiteController: No more watchers;
> clean up persona host iframe
> E/GeckoConsole( 1901): Identity SignInToWebsiteController: No more watchers;
> clean up persona host iframe
> I/Gecko   ( 1901): Identity SignInToWebsiteController: telling content to
> close the dialog
> E/GeckoConsole( 1901): Identity SignInToWebsiteController: telling content
> to close the dialog

This message means that the persona sign-in dialog has been closed.  In fact, it looks like the close message has been sent three times (?)  I should be able to add logging to show which RP uuid is behind the close message.

> I/Gecko   ( 2972): ############################### browserElementPanning.js
> loaded
> I/Gecko   ( 2972): ######################## BrowserElementChildPreload.js
> loaded
> I/Gecko   ( 2972): ###################################### forms.js loaded
> I/Gecko   ( 2972): ############################### browserElementPanning.js
> loaded
> I/Gecko   ( 2972): ######################## BrowserElementChildPreload.js
> loaded
> I/Gecko   ( 2973): ###################################### forms.js loaded
> I/Gecko   ( 2973): ############################### browserElementPanning.js
> loaded
> I/Gecko   ( 2973): ######################## BrowserElementChildPreload.js
> loaded
> I/Gecko   ( 1901): 1396651797771	Marionette	INFO	sendToClient:
> {"from":"0","error":{"message":"Unable to locate element:
> iframe.screen[data-url*='persona.org/sign_in#NATIVE']","status":7,
> "stacktrace":null}}, {98c0d9de-9e2c-4718-af49-c3552586756e},
> {98c0d9de-9e2c-4718-af49-c3552586756e}
> I/Gecko   ( 1901): 1396651808347	Marionette	INFO	sendToClient:
> {"from":"0","error":{"message":"Unable to locate element:
> iframe.screen[data-url*='persona.org/sign_in#NATIVE']","status":7,
> "stacktrace":null}}, {ff9e2073-7725-4440-9081-467f1237f229},
> {ff9e2073-7725-4440-9081-467f1237f229}
> I/Gecko   ( 1901): 1396651818905	Marionette	INFO	sendToClient:
> {"from":"0","error":{"message":"Unable to locate element:
> iframe.screen[data-url*='persona.org/sign_in#NATIVE']","status":7,
> "stacktrace":null}}, {1e874275-02ee-455d-9759-0a70809aebc4},
> {1e874275-02ee-455d-9759-0a70809aebc4}

By now, the dialog is already closed, so there's no element for marionette to locate.

Are there three sendToClient attempts at the end because it's retrying every 10 seconds (as the timestamps suggest)?  Or are there actually three sign-in tests being run concurrently?  I would guess not, but the entries all have different uuids, so I just want to be sure.

Comment 4

[Edwin Wong [:edwong]]

btw - i'm not repro on 1.5 (current master) this would suggest that it's not specific to remote persona and that it's specific to b2g. Maybe we should punt this to b2g?

Comment 5

[Jason Smith [:jsmith]]

(In reply to Edwin Wong [:edwong] from comment #4)
> btw - i'm not repro on 1.5 (current master) this would suggest that it's not
> specific to remote persona and that it's specific to b2g. Maybe we should
> punt this to b2g?

See https://bugzilla.mozilla.org/show_bug.cgi?id=991320#c10 - I think persona server-side changed something on that revealed a window management bug. Our best option right now is to fix this server-side.

Comment 6

[Viorela Ioia [:viorela]]

This is still reproducible on v1.3 in the latest build: 
Gaia      100a159af11281d965e9d70d0f3d3111a38775ee
Gecko     https://hg.mozilla.org/releases/mozilla-b2g28_v1_3/rev/ea2a473b122f
BuildID   20140409004002
Version   28.0
ro.build.version.incremental=eng.tclxa.20131223.163538
ro.build.date=Mon Dec 23 16:36:04 CST 2013

Comment 7

[Zac C (:zac)]

The problem here is that Events are not initialised before starting the Persona sign in.

This is done by using the "    def wait_for_ready_event(self):" method in the uitests app region object.

See how it is done in master.

Viorela can you take this task?

Comment 8

[Viorela Ioia [:viorela]]

Sure, I'm working on it, Zac.

Comment 9

[Viorela Ioia [:viorela]]

Attachment: Github PR: https://github.com/mozilla-b2g/gaia/pull/18125

Comment 10

[Florin Strugariu [:Bebe]]

Comment on attachment 8403967 [details] [review]
Github PR: https://github.com/mozilla-b2g/gaia/pull/18125

guys this looks funny.... can one of you take a look over this.. Something looks funny when running the test...

Comment 11

[Zac C (:zac)]

What looks funny? Tell me some information, a screenshot, a stacktrace or something.

Comment 12

[Florin Strugariu [:Bebe]]

Zac when I run the tests it takes really long on the first persona screen... after some time it get's to the next step and continues the test.

we might wait fro the wrong stuff in the test

Comment 13

[Zac C (:zac)]

Comment on attachment 8403967 [details] [review]
Github PR: https://github.com/mozilla-b2g/gaia/pull/18125

r+

Comment 14

[Zac C (:zac)]

Merged:
https://github.com/mozilla-b2g/gaia/commit/ed98d06e08d906a9bd2ced25a4d15bb398b45b54

Comment 15

[Ryan VanderMeulen [:RyanVM]]

Please set the status flags when landing on release branches.