970272 - test_persona_app.py when run for the first time on Hamachi

Status: RESOLVED FIXED

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

Description

[Zac C (:zac)]

This test is failing when run immediately after the device is flashed or given a new profile (which is done when you use the --restart command line).

It is not replicable manually. As a result we have to disable this test coverage until it can be worked on by the Identity team.

Comment 1

[Zac C (:zac)]

To replicate this, run the test_persona_app.py test.

Comment 2

[Zac C (:zac)]

What happens is that after "Request" button is tapped the Trusted UI window opens but Persona does not load inside the window.
The loading bar does not start either, the request to load the page is lost before that.

Comment 3

[Edwin Wong [:edwong]]

I'll attempt to repro when I get into the office.

Comment 4

[Zac C (:zac)]

Forgot to also add this was a regression starting from Friday's build.

Prior to that it was passing fine.

Comment 5

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

Thanks for the report and the information, Zac.

Very helpful to know that the tests were passing prior to Friday.

Is there any adb output in the logs?  Does the build you're testing on have toolkit.identity.debug preffed to 'true'?

Comment 6

[Zac C (:zac)]

It is just a raw rel-eng hamachi engineering build so it does not have that pref set.

Let me check the adb output.
*muzak plays*

Comment 7

[Zac C (:zac)]

Attachment: logcat

It looks like around line 2500 it is tapping on the button in the UI tests app.

After that it switches to System frame (2526), into Trusted UI frame (2542)

2582 there is some weird looking stuff?

Comment 8

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

Thanks for the logs, Zac.  Looking at 2582 and 2583:

E/GeckoConsole( 5559): [JavaScript Error: "uncaught exception: target window is same as present window -- not allowed"]

That's a spooky-looking error that always comes from persona, whether in the browser or in b2g.  It's harmless.

I/GeckoDump( 5309): XXX FIXME : Got a mozContentEvent: undefined

That's a result of our not putting a 'type' specifier in the mozContentEvent sent by persona on b2g.  The persona code identifies all its moz{Browser,Content}Events by unique id, so they don't need a type property.  Still, I understand now that it's stylistically bad form to have the type specifier lacking on b2g.  We should fix that.

Neither of these messages indicates a persona bug.

It looks like it's querying the toolkit.identity.debug pref in line 2400 of the output.  Does that pref ever get set?  If so, we should be seeing verbose logging from persona itself.

Comment 9

[Zac C (:zac)]

I can try setting it but I'd prefer not to. 

We want to run as close to a user build as possible (within reason) and also I'd like to find the source of this regression rather than just cover over it.

Comment 10

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

I was thinking that logging could help us find the source of the problem.  That's all toolkit.identity.debug=true does - cause more logging.  If with the logging enabled you're still able to trigger the bug, it might give us more information.

Comment 11

[Zac C (:zac)]

Attachment: persona_fail_debug.log

OK! 

It is replicable with the pref set.

Here is the logcat.

Comment 12

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

That's great.  Thanks for the logs.

This sequence stands out to me:

3181: navigator.mozId.watch() is called
3267: navigator.mozId.request() is called immediately after
3352: iframe loads to process watch() command
3408: persona fires the onready() callback

request() can't work until watch() has completed executing, set up the callbacks, and fired onready().  In other words, the request() call reported at line 3267 should not have been made until after the doReady() at 3408.

So I am wondering, is it possible that the test script is hitting the request() button the moment the page loads, and not waiting first for watch() to call back with onready()?  If this is what's happening, it could explain why it's not replicable manually.

Can you point me at the source for the tests?  (I seem to have an old link, https://github.com/mozilla/gaia-ui-tests)

Comment 13

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

Oh, sorry, is it this? https://github.com/mozilla-b2g/gaia/blob/master/tests/python/gaia-ui-tests/gaiatest/tests/functional/persona/test_persona_app.py

Comment 14

[Zac C (:zac)]

Yes that's plausible; the tests go very quickly but it also sounds like a speed regression on the Firefox OS side.
Is there something in the DOM that we can watch to check when watch has completed?

Tests are now in the Gaia tree but it has not changed significantly since you and Ed wrote it:
https://github.com/mozilla-b2g/gaia/blob/master/tests/python/gaia-ui-tests/gaiatest/tests/functional/persona/test_persona_app.py

Comment 15

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

I think it used to add a list element with class 'ready' and the text 'ready'.  I'll take a look and make sure there's an element you can listen for.  I've got to get a train right now, but I should be able to have more for you soon.

Oh, and does this fail on desktop emulator as well, do you know?  Or only on device?

Thanks, Zac

Comment 16

[Zac C (:zac)]

You're right, there is a list there but we've never waited for it.

I can sort that out for you.

Comment 17

[Zac C (:zac)]

Attachment: github pr

whaddya know, there's a method already there ;)

Jed, I've also r? Askeing who can pick this up in Taiwan time if you can't review it today.

Comment 18

[Zac C (:zac)]

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