864760 - [Trusted UI] Native persona (navigator.id) stops responding during beginning of payment

Status: RESOLVED INVALID

(Firefox OS Graveyard :: Gaia::System, defect)

Description

[Kumar McMillan [:kumar]]

There's no easy way to reproduce this but we've seen it multiple times on today's build.

What we see:
- the TrustedUI opens to WebPay
- the TrustedUI remains open but the login never completes, it just hangs

Build info, tested on Unagi:
  https://git.mozilla.org/?p=releases/gecko.git;a=commitdiff;h=e729e5a826d4accc3a75062c3c29268d1b595980
  https://git.mozilla.org/?p=releases/gaia.git;a=commitdiff;h=29c51d4c0101cf6509dff9685a6a83840550c803

I'm attaching the full logcat and HTTP requests/responses but this looks suspicious (this is the end of the logcat):

Identity SignInToWebsiteController: received delegate finished; telling content to close the dialog
XXX FIXME : Got a mozContentEvent: undefined
Identity SignInToWebsiteController: No more watchers; clean up persona host iframe
Identity SignInToWebsiteController: telling content to close the dialog
NOTE: child process received `Goodbye', closing down

Comment 1

[Kumar McMillan [:kumar]]

Attachment: persona-not-responding-logcat.log

Comment 2

[Kumar McMillan [:kumar]]

Attachment: persona-not-responding-http.log

Comment 3

[Kumar McMillan [:kumar]]

Attachment: screenshot during hang

this is what the screen looks like when it hangs

Comment 4

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

Hi, Kumar,

The lines that you cite in the Description look good to me:

- 'telling delegate to close dialog' is the native identity controller saying it's done, and it's going to message out that the hidden persona iframe can be closed and disposed of by the OS

- 'got a mozContent event: undefined' I believe this is because we are not setting a 'type' parameter on the content events we (identity) are emitting.  This should be cleaned up to be consistent with general gaia usage, but it's not a functional problem; the messages have unique ids and they pass through the shell app that's raising this alert.

- 'no more watchers' - since it's possible that there are more than one process using the persona iframe at any time (two or more concurrent sign-in flows), we ensure that the watcher count is 0 before closing it.

- closing and Goodbye - that's the persona process quitting and being cleaned up.

What I'm looking at in the logs from Comment #1 is that apparently watch() is being called for *two* separate windows (id 1 and id 12), and it's emitting 'ready' back for those windows.  That shouldn't cause anything to hang, but still, it's interesting.

Apart from that, the logs from Comment #1 show a successful 'ready' returned from 'watch'.  Comment #2 shows an initial manual login by [e-mail] (at line 2006, coming from the sign_in dialog), and subsequent automatic logins (coming from the communication_iframe, which is triggered by watch).

When you say you've seen this multiple times in today's build, is there anything else linking those occurrences together?  Multiple concurrent logins?  Canceled or aborted sessions?  Dropped connections?  Womp rats?

Comment 5

[Kumar McMillan [:kumar]]

(In reply to Jed Parsons [:jparsons] from comment #4)
> When you say you've seen this multiple times in today's build, is there
> anything else linking those occurrences together?  Multiple concurrent
> logins?  Canceled or aborted sessions?  Dropped connections?  Womp rats?

Some observations:
- we've only seen it while on the Telefonica cell network (3G, etc)
- we've seen it immediately after flashing
- we've seen it after flashing and after a successful purchase
- it happens with multiple persona emails

Comment 6

[Jason Smith [:jsmith]]

(In reply to Kumar McMillan [:kumar] from comment #5)
> (In reply to Jed Parsons [:jparsons] from comment #4)
> > When you say you've seen this multiple times in today's build, is there
> > anything else linking those occurrences together?  Multiple concurrent
> > logins?  Canceled or aborted sessions?  Dropped connections?  Womp rats?
> 
> Some observations:
> - we've only seen it while on the Telefonica cell network (3G, etc)
> - we've seen it immediately after flashing
> - we've seen it after flashing and after a successful purchase
> - it happens with multiple persona emails

This almost starting to sound like a bug from intermittent weak/lame networks. That's my first guess here at least.

Can you dump multiple logs here with failures in different cases?

Comment 7

[Kumar McMillan [:kumar]]

Attachment: persona-not-loading-7pm-logcat.log

Comment 8

[Kumar McMillan [:kumar]]

Attachment: persona-not-loading-7pm-http.log

Here is some logging from a stalled persona I just saw at 7:10pm CET

Comment 9

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

(In reply to Kumar McMillan [:kumar] from comment #8)
> Created attachment 741397 [details]
> persona-not-loading-7pm-http.log
> 
> Here is some logging from a stalled persona I just saw at 7:10pm CET

Thanks.  Looks very similar to the previous example, in particular the two relying parties, page 1 and page 12, that are getting the message.  Hrm.

Comment 10

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

What's a payment flow I can try to reproduce this?

I'm on the april 24 unagi-eng build, and tried purchasing the 0.99 USD yacht; persona login worked, but on return to marketplace-dev app (just installed beforehand), i get a 'payment failed' error (pink box at bottom of screen).

logcat says: 

E/GeckoConsole(  475): Content JS LOG at https://marketplace-dev-cdn.allizom.org/media/js/mkt/consumer-min.js?build=923616b:5 in anonymous: navigator.mozPay error: PAY_REQUEST_ERROR_NO_VALID_REQUEST_FOUND

Is there a different marketplace app or product I should try?

Comment 11

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

Lloyd and I spend some time on this today, and we think we've found the culprit.  Logging all assertions and crossing our fingers that folks in Spain have a better day with this tomorrow.

Comment 12

[Kumar McMillan [:kumar]]

ok, let me know if you need more info. The error you saw was because you don't have payment settings. If you copy this to /data/local/user.js it should work: https://github.com/mozilla/webpay/blob/master/ezboot/custom-prefs.js

Comment 13

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

Since pushing the fix yesterday, I don't see any new failures in the logs, and I see a whole lot of successes.  I'm beginning to feel pretty good about this.

Comment 14

[Kumar McMillan [:kumar]]

Jinx :) I just saw a persona login hang around 7am PDT. I waited about 3 minutes before giving up. Here are the logs...

Comment 15

[Kumar McMillan [:kumar]]

Attachment: persona-thursday-7am-logcat.log

Comment 16

[Kumar McMillan [:kumar]]

Attachment: persona-thursday-7am-http.log

Comment 17

[Jason Smith [:jsmith]]

Btw - if this ends up being a client-side bug, feel free to nom this for leo.

Right now though, I can't tell if this is a server-side persona bug or client-side bug.

Comment 18

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

I'm pretty sure this is all server-side.

Comment 19

[Jason Smith [:jsmith]]

Moved to Github per talking to Jed - https://github.com/mozilla/browserid/issues/3317.