843309 - paymentSuccess sometimes does not appear in scope (payment window does not close)

Status: VERIFIED FIXED

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

Description

[Kumar McMillan [:kumar]]

See https://wiki.mozilla.org/WebAPI/WebPaymentProvider#Completion for info

Somtimes paymentSuccess is undefined at the end of the webpay flow. This doesn't happen all the time but I'm filing this bug to track it.

Comment 1

[Kumar McMillan [:kumar]]

This is similar to bug 841521 in that this behavior only happens the first time you make a purchase. The second time it works.

Comment 2

[Jason Smith [:jsmith]]

No idea how to take this bug forward - this is too vague. Can you clarify?

In some cases paymentSuccess isn't defined because the app process was killed during the execution of the payment process. So you can't always guarantee it'll exist.

Comment 3

[Kumar McMillan [:kumar]]

The STR:
- Open Marketplace (dev/stage)
- Pay for Private Yacht
- Sign in / create/enter PIN
- Confirm phone number on Bango screen
- Click Buy Private Yacht

Expected: at this point, the buy flow can be closed so the WebPay HTML page can call paymentSuccess()

Actual: paymentSuccess() is an undefined global. The code polls, waiting for it, but it never appears.

Comment 4

[Jason Smith [:jsmith]]

Fernando - Any thoughts?

Comment 5

[Jason Smith [:jsmith]]

Kumar can you include a logcat here?

Comment 6

[Jason Smith [:jsmith]]

The only potential idea I have that this could happen is the fact that trusted UI runs in the system app process, while the originating app runs in a separate app process. So there's a definite possibility that we could end up killing the originating app while the trusted UI was open, which would cause this issue.

Adding Justin for input to see what he thinks.

Comment 7

[Kumar McMillan [:kumar]]

btw, this is how paymentSuccess becomes a global: https://mxr.mozilla.org/mozilla-central/source/b2g/chrome/content/payment.js#96

I don't understand what the global 'content' is in this exact context. It seems to work most of the time ;)

Comment 8

[Justin Lebar (not reading bugmail)]

If you can include logcat and adb shell dmesg, that will make it clear whether something is crashing.

> I don't understand what the global 'content' is in this exact context. It seems to work most of the 
> time ;)

This is a "frame script": It's a script we inject to run "inside" a particular iframe, which may or may not be cross-process with respect to the injector.  |content| is the content window inside that iframe -- that is, |content| is what iframe.contentWindow would return if the iframe was not remote.  (If the iframe is cross-process, contentWindow is null.)

Comment 9

[Kumar McMillan [:kumar]]

Attachment: b2g desktop log

Here is a log from b2g desktop where I was able to reproduce it. I'll get one from a phone. 

The last log message is when the HTML loads within the Trusted UI iframe. The HTML page polls, waiting for paymentSuccess to be defined, but it never happens.

Comment 10

[Justin Lebar (not reading bugmail)]

If you can reproduce this on desktop b2g, I'm almost positive multiprocess is not involved, because I'm pretty sure desktop b2g runs in one process.  Also, you're probably not OOMing on your desktop.

Comment 11

[Jason Smith [:jsmith]]

I should ask - can you reproduce this on device?

Comment 12

[Jason Smith [:jsmith]]

Logcat analysis shows a lot of:

XXX FIXME : Got a mozContentEvent: undefined

I've seen the Got mozContentEvent FIXME thing before as a benign message, but it usually includes something defined. The undefined piece seems off.

Comment 13

[Jason Smith [:jsmith]]

tef? for similar reasons as bug 841521

Comment 14

[Jason Smith [:jsmith]]

Actually, I'm going to wait on the nom until I get more info here.

Comment 15

[Justin Lebar (not reading bugmail)]

Fernando, are you able to look into this?  It looks like an issue in this code.

Comment 16

[Kumar McMillan [:kumar]]

(In reply to Jason Smith [:jsmith] from comment #11)
> I should ask - can you reproduce this on device?

Yeah, I've seen this happen on device before but since I use desktop more for day-to-day dev I see it there more. On yesterday's build I tried a couple times on device but couldn't catch it in action.

One thing worth noting: the code *always* does not see paymentSuccess defined when it first loads. It waits for it to appear in a hacky polling loop: https://github.com/mozilla/webpay/blob/master/media/js/pay/pay.js#L80 

For example, I can see on my latest device logs that it polled twice then found it defined.

Maybe that is a clue that the timing is off somewhere?

Comment 17

[Jason Smith [:jsmith]]

Alright, sounds like this now appropriate to nom now that we know this reproduces on device.

Comment 18

[Fernando Jiménez Moreno [:ferjm]]

(In reply to Kumar McMillan [:kumar] from comment #16)

> One thing worth noting: the code *always* does not see paymentSuccess
> defined when it first loads. It waits for it to appear in a hacky polling
> loop: https://github.com/mozilla/webpay/blob/master/media/js/pay/pay.js#L80 
> 
> For example, I can see on my latest device logs that it polled twice then
> found it defined.
> 
> Maybe that is a clue that the timing is off somewhere?

We wait for the DOMContentLoaded event before injecting the functions in the payment flow [1]. So that might be the reason why you are not seeing 'paymentSuccess' defined when you first check. Anyway, it should be injected at some point... I'll take a look at this.

[1] https://mxr.mozilla.org/mozilla-central/source/b2g/chrome/content/payment.js#95

Comment 19

[Justin Lebar (not reading bugmail)]

> We wait for the DOMContentLoaded event before injecting the functions in the payment flow 

Wouldn't it be better to inject these functions much earlier, so that pages cannot observe the lack of these methods?  That would match how every other DOM API works.

There's probably a way to stick them on the outer window so you never have to re-inject them.  (In fact, that may be what the code is doing already.)

Comment 20

[Fernando Jiménez Moreno [:ferjm]]

Attachment: Potential fix

Unfortunately I am not able to reproduce this issue either. I'm testing in the device with the latest b2g18 and the latest gaia master.

However, I am attaching a potential fix based on Justin's suggestion.

Kumar, would it be possible to check if you can reproduce this issue with this patches applied? Thanks!

Comment 21

[Justin Lebar (not reading bugmail)]

Comment on attachment 722322 [details] [diff] [review]
Potential fix

This is fine for testing, but before we check it in, we should ask smaug whether it's necessary to listen to this event using the system event listener service (as in BrowserElementChildPreload.js), or whether what you have is fine.  I'm not sure.

I don't think the difference between the system event listener service and this should make a difference for testing.

Comment 22

[Fernando Jiménez Moreno [:ferjm]]

Attachment: Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/8524

Pointer to Github pull-request

Comment 23

[Fernando Jiménez Moreno [:ferjm]]

Attachment: Pointer to Github pull request: https://github.com/mozilla-b2g/gaia/pull/8524#attch-to-bugzilla

Pointer to Github pull-request

Comment 24

[Fernando Jiménez Moreno [:ferjm]]

The attached Gaia PR avoids repeatedly sending a mozContentEvent requesting the re-injection of the frameScript in the payment flow.

Note that even if these two patches don't fix this bug we should probably merge them anyway in a separate bug since this seems to be an improvement of the way that we inject the functions in the payment flow.

Comment 25

[Fernando Jiménez Moreno [:ferjm]]

Olli, can we have your opinion about Justin's comment above (comment 21), please? Thanks! :)

Comment 26

[Michael Vines [:m1] [:evilmachines]]

(In reply to Jason Smith [:jsmith] from comment #13)
> tef? for similar reasons as bug 841521

bug 841521 is tracking-b2g18? so setting this bug to match

Comment 27

[Lukas Blakk [:lsblakk] use ?needinfo]

See https://bugzilla.mozilla.org/show_bug.cgi?id=841521#c48 for the justification of re-noming for tef? 

We probably don't want a person's first payment experience to be broken.

Comment 28

[Jason Smith [:jsmith]]

(In reply to Lukas Blakk [:lsblakk] from comment #27)
> See https://bugzilla.mozilla.org/show_bug.cgi?id=841521#c48 for the
> justification of re-noming for tef? 
> 
> We probably don't want a person's first payment experience to be broken.

This one is a tad worse than bug 841521 mainly cause the payment flow gets stuck at the end. There's also enough analysis to be able to prove the bug is happening with a potential fix. So the tef nom I think is okay on this bug, but I'm not sure the rationale in the other bug argues for it to block.

Comment 29

[Fernando Jiménez Moreno [:ferjm]]

(In reply to Jason Smith [:jsmith] from comment #28)
> (In reply to Lukas Blakk [:lsblakk] from comment #27)
> > See https://bugzilla.mozilla.org/show_bug.cgi?id=841521#c48 for the
> > justification of re-noming for tef? 
> > 
> > We probably don't want a person's first payment experience to be broken.
> 
> This one is a tad worse than bug 841521 mainly cause the payment flow gets
> stuck at the end. There's also enough analysis to be able to prove the bug
> is happening with a potential fix. So the tef nom I think is okay on this
> bug, but I'm not sure the rationale in the other bug argues for it to block.

Were you able to reproduce this issue? I couldn't. Not in desktop and, most important, not in the device.

Also the attached logcat does not show anything interesting. I am pretty sure that the "XXX FIXME : Got a mozContentEvent: undefined" is not related to this issue.

The attached patch is an improvement of the way we inject the functions in the payment flow but it doesn't mean that it fix this issue. Since I can't reproduce it, I can't check any fix.

Comment 30

[Jason Smith [:jsmith]]

(In reply to Fernando Jiménez Moreno [:ferjm] from comment #29)
> (In reply to Jason Smith [:jsmith] from comment #28)
> > (In reply to Lukas Blakk [:lsblakk] from comment #27)
> > > See https://bugzilla.mozilla.org/show_bug.cgi?id=841521#c48 for the
> > > justification of re-noming for tef? 
> > > 
> > > We probably don't want a person's first payment experience to be broken.
> > 
> > This one is a tad worse than bug 841521 mainly cause the payment flow gets
> > stuck at the end. There's also enough analysis to be able to prove the bug
> > is happening with a potential fix. So the tef nom I think is okay on this
> > bug, but I'm not sure the rationale in the other bug argues for it to block.
> 
> Were you able to reproduce this issue? I couldn't. Not in desktop and, most
> important, not in the device.
> 
> Also the attached logcat does not show anything interesting. I am pretty
> sure that the "XXX FIXME : Got a mozContentEvent: undefined" is not related
> to this issue.
> 
> The attached patch is an improvement of the way we inject the functions in
> the payment flow but it doesn't mean that it fix this issue. Since I can't
> reproduce it, I can't check any fix.

I haven't managed to reproduce this bug myself. I'll talk with Krupa and see if I can mess around with the real payment flow to get a reproduction.

Comment 31

[[:fabrice] Fabrice Desré]

(In reply to Fernando Jiménez Moreno [:ferjm] from comment #29)

> Also the attached logcat does not show anything interesting. I am pretty
> sure that the "XXX FIXME : Got a mozContentEvent: undefined" is not related
> to this issue.

These messages come from identity API that doesn't set a type on its mozContentEvents (it's bad in general, we should fix that).

Comment 32

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

(In reply to Fabrice Desré [:fabrice] from comment #31)
> (In reply to Fernando Jiménez Moreno [:ferjm] from comment #29)
> 
> > Also the attached logcat does not show anything interesting. I am pretty
> > sure that the "XXX FIXME : Got a mozContentEvent: undefined" is not related
> > to this issue.
> 
> These messages come from identity API that doesn't set a type on its
> mozContentEvents (it's bad in general, we should fix that).

Sorry, I didn't know we were doing anything wrong there.  I've filed Bug 849877 to fix the identity mozContentEvents.

Comment 33

[Fernando Jiménez Moreno [:ferjm]]

(In reply to Fabrice Desré [:fabrice] from comment #31)
> (In reply to Fernando Jiménez Moreno [:ferjm] from comment #29)
> 
> > Also the attached logcat does not show anything interesting. I am pretty
> > sure that the "XXX FIXME : Got a mozContentEvent: undefined" is not related
> > to this issue.
> 
> These messages come from identity API that doesn't set a type on its
> mozContentEvents (it's bad in general, we should fix that).

If I am not wrong, in this case the mozContentEvents are responses to specific mozChromeEvents that are identified by an id generated in the moment that the mozChromeEvents are sent, so the type could be avoided in this case, as the chrome side expects mozContentEvents with an specific id.

With the patches proposed for Bug 794999 we will force every mozContentEvent (as far as we use mozChromeEvent<->mozContentEvent communication) involved in a trusted UI flow to have a type anyway.

In any case, again, I really think that this is not related to the issue of this bug.

Comment 34

[[:fabrice] Fabrice Desré]

(In reply to Jed Parsons [:jparsons] from comment #32)

> Sorry, I didn't know we were doing anything wrong there.  I've filed Bug
> 849877 to fix the identity mozContentEvents.

No problem, and blame your reviewer ;)

(In reply to Fernando Jiménez Moreno [:ferjm] from comment #33)

> If I am not wrong, in this case the mozContentEvents are responses to
> specific mozChromeEvents that are identified by an id generated in the
> moment that the mozChromeEvents are sent, so the type could be avoided in
> this case, as the chrome side expects mozContentEvents with an specific id.

I'm not saying that this doesn't work (well, you could have id conflicts if several apis were doing that). All the mozChromeEvent <-> mozContentEvent mechanism is a poor replacement for a proper embedding API and I'd like these events to be more easily recognizable when we move to something else.

> 
> In any case, again, I really think that this is not related to the issue of
> this bug.

I agree.

Comment 35

[Michael Vines [:m1] [:evilmachines]]

(tef+ cause it's a 1 line patch and Moz folks want it in)

Comment 36

[Jason Smith [:jsmith]]

Kumar - Can you test the patch ferjm has here to see if it works for you?

Comment 37

[Kumar McMillan [:kumar]]

Yeah! This seems to be working. 

First, I removed the JS polling in the success screen to test. If paymentSuccess is ever undefined, this makes it fail immediately. I could reproduce this 'undefined' failure with b2g18/gaia. 

Next, I applied the chrome patch from Comment #20 and the gaia patch from Comment #22. I tried many many times and never hit the 'undefined' failure. This seems like it fixes the timing issue and guarantees that paymentSuccess is always defined. Thanks ferjm!

Comment 38

[Fernando Jiménez Moreno [:ferjm]]

Great! Thanks for your help Kumar!

Comment 39

[Fernando Jiménez Moreno [:ferjm]]

Comment on attachment 722322 [details] [diff] [review]
Potential fix

Olli, can we have your opinion about Justin's comment above (comment 21), please? Thanks!

Comment 40

[[:fabrice] Fabrice Desré]

Comment on attachment 722322 [details] [diff] [review]
Potential fix

Review of attachment 722322 [details] [diff] [review]:
-----------------------------------------------------------------

r=me conditionnal on smaug feedback

Comment 41

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 722322 [details] [diff] [review]
Potential fix

This should be ok. DOMWindowCreated is dispatched to chrome only, so
content can't call stopPropagation()

Comment 42

[Fernando Jiménez Moreno [:ferjm]]

Thanks!

https://hg.mozilla.org/integration/mozilla-inbound/rev/96af92fa87fd
https://github.com/mozilla-b2g/gaia/commit/f815f9271dde55dcf71d33d87149a8e4538cf09b

Comment 43

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/96af92fa87fd

Comment 44

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g18/rev/0cd01841d22d
https://hg.mozilla.org/releases/mozilla-b2g18_v1_0_1/rev/b267b5ed7aea

Leaving the status flags set to affected for the v1-train and v1.0.1 uplifts.

Comment 45

[Julien Wajsberg [:julienw]]

Ferjm, I'd love that you uplift the gaia part yourself here, as I don't really know how to test this works...

Comment 46

[Julien Wajsberg [:julienw]]

v1-train: 046b5f94a3440f6f670867aae553eee3eca48e6b

Comment 47

[Julien Wajsberg [:julienw]]

v1.0.1: 72af49be465f357d57977c948607ad93bdc4bcf0

Comment 48

[Julien Wajsberg [:julienw]]

please check that the bug is fixed on both branch, and the feature still works.

Thanks.

Comment 49

[Jason Smith [:jsmith]]

(In reply to Julien Wajsberg [:julienw] from comment #48)
> please check that the bug is fixed on both branch, and the feature still
> works.
> 
> Thanks.

I put qa- on this one originally (which means a decline on verification) because only Kumar can reproduce this bug consistently. I however could not. I can regression test around this, along with Krupa doing her regular payment testing.

What I think we should do here is just indicate to Kumar & Krupa to keep a look out for potential issues on the client side as they test payments with this patch. If something regresses, then we'll find out with new bugs filed. As for making sure this bug works, regular marketplace payment testing will end up by caveat watching out for this bug on a regular basis.

Make sense?

Comment 50

[Julien Wajsberg [:julienw]]

yep

Comment 51

[Fernando Jiménez Moreno [:ferjm]]

(In reply to Julien Wajsberg [:julienw] from comment #45)
> Ferjm, I'd love that you uplift the gaia part yourself here, as I don't
> really know how to test this works...

Sorry Julien! I didn't see your comment until now. Thanks for landing the patch! It works for me in both branches.

Comment 52

[cbarker]

Cannot verify as this requires access to Payment Tools

Comment 53

[Jason Smith [:jsmith]]

Kumar - Just double check, is this working for you after the patch landed to fix this bug?

Comment 54

[Kumar McMillan [:kumar]]

I haven't seen it since the patch landed so it seems good. However, it was never 100% reproducible.

Comment 55

[Jason Smith [:jsmith]]

(In reply to Kumar McMillan [:kumar] from comment #54)
> I haven't seen it since the patch landed so it seems good. However, it was
> never 100% reproducible.

Okay, I'll mark as verified then.