1373224 - [Train 89][Staging server only] User can't access log-in form from synced devices section on Android

Status: RESOLVED FIXED

(Cloud Services :: General, defect)

Description

[u549602]

Device:
Samsung Galaxy S6 Edge - Android 7.0
Nexus 9 - Android 6.0.1
Build : 55.0a1
Server: Staging Train 89

STR:

1.Go to History
2.Tap on Synced devices submenu 
3.Tap on Get started button

Expected:
Log in form should be triggered and loaded
Actual: 
Infinite loading screen 


Note: 
- This issue occurs ONLY on Android and ONLY on the staging server
- This could be reproduced on both 56.0a1 and 55.ob1 builds pointing on the staging server

For further details please check https://pastebin.mozilla.org/9024737

Comment 1

[Ryan Kelly [:rfkelly]]

Thanks :Ninu!  Can you confirm whether the login page loads successfully if you access it through a different path in the same browser?  For example, if you access sync directly through "settings" rather than via the history view?

Comment 2

[Ryan Kelly [:rfkelly]]

FWIW I reproduce this on an unmodified install of Nightly on my Android device, i.e. against the production server rather than staging.  Here's what I see:

* Go through "history", "synced devices", "get started"
* This loads about:accounts?action=signin, which gets an infinite loading spinner
* Leave that tab open
* Go to "settings", "sign in"
* This loads a new tab with about:accounts?action=signin&entrypoint=preferences, which successfully loads the login page
* Go back to the previous tab, and observe that it has *also* successfully loaded the login page

To me, this suggests some sort of WebChannel miscommunication.  When the login page loads in the first tab, it's waiting for a WebChannel response that doesn't come.  When we load the login page via another route, the WebChannel response triggers due to that page, and unblocks the previous one.

Shane or Grisha, any suggestion how to debug this further?

Comment 3

[u549602]

Hi Ryan,

1. Yes, i can confirm that the log in form is accessible trough the settings-sign in path also by entering about:accounts in the awesomebar input field. 

2. I reproduced what you described @ comment 2 and it looks like all you need to do is to open a new tab and get back to the one in which the log-in form is triggered to load it. Reproduced it on both latest Nightly(production server) and with the same steps on Beta and Nightly(both ot staging server). 
So, the issue here seems to happen only if you stay in the current loading tab. The workaround is to open a new tab or visit an already opened one and come back to the problematic one. Still an annoying issue IMO. 

thanks

Comment 4

[Shane Tomlinson [:stomlinson]]

From IRC:

I can't rule out a WebChannel problem, but that should be easy to simulate if we know the UA string Fx for Android 55 uses. Loading FxA with `&forceUA=encodedUaString` will force FxA to use that as the UA string instead of navigator.userAgent. 

Assuming 'Mozilla/5.0 (Android 4.4; Mobile; rv:55.0) Gecko/55.0 Firefox/55.0' is the correct UA string for Fx 55 on Android, load https://accounts.firefox.com/signin?context=fx_fennec_v1&service=sync&forceUA=Mozilla%2F5.0%20(Android%204.4%3B%20Mobile%3B%20rv%3A55.0)%20Gecko%2F55.0%20Firefox%2F55.0. 

If that URL is loaded in a browser w/o support for the `fxaccounts:fxa_status`, say Fx Desktop 54, it should stall on startup.


> * Go through "history", "synced devices", "get started"
> * This loads about:accounts?action=signin, which gets an infinite loading
> spinner
> * Leave that tab open

If this is a WebChannel problem, from here down is most likely unnecessary. If fxaccounts:fxa_status is being sent, the WebChannel request will timeout. The request is probably timing out while performing these steps, making it appear the two are related.

> * Go to "settings", "sign in"
> * This loads a new tab with
> about:accounts?action=signin&entrypoint=preferences, which successfully
> loads the login page
> * Go back to the previous tab, and observe that it has *also* successfully
> loaded the login page
> 
> To me, this suggests some sort of WebChannel miscommunication.  When the
> login page loads in the first tab, it's waiting for a WebChannel response
> that doesn't come.  When we load the login page via another route, the
> WebChannel response triggers due to that page, and unblocks the previous one.
> 
> Shane or Grisha, any suggestion how to debug this further?


Are you testing on a phone or tablet? Can you get the UA string for me?

Comment 5

[Ryan Kelly [:rfkelly]]

UA on my phone is: "Mozilla/5.0 (Android 6.0.1; Mobile; rv:56.0) Gecko/56.0"

Comment 6

[Ryan Kelly [:rfkelly]]

Although this:

> I reproduced what you described @ comment 2 and it looks like all you need
> to do is to open a new tab and get back to the one in which the log-in form is triggered to load it.

makes it seem a little less like a webchannel problem I think, because I don't see why opening a new non-FxA-related tab would triggering anything to do with WebChannels.

Comment 7

[Shane Tomlinson [:stomlinson]]

(In reply to Ryan Kelly [:rfkelly] from comment #6)
> Although this:
> 
> > I reproduced what you described @ comment 2 and it looks like all you need
> > to do is to open a new tab and get back to the one in which the log-in form is triggered to load it.
> 
> makes it seem a little less like a webchannel problem I think, because I
> don't see why opening a new non-FxA-related tab would triggering anything to
> do with WebChannels.

It could be that the request is timing out after 30 seconds while this is happening.

Comment 8

[u549602]

Mozilla/5.0(Android 7.0; Mobile; rv:55.0)Gecko/55.0 Firefox/55.0 - This for Samsung Galaxy S6 EDGE
Mozilla/5.0(Android 6.0.1;Tablet;rv:55.0)Gecko/55.0 Firefox/55.0 - This for Nexus 9

Comment 9

[Shane Tomlinson [:stomlinson]]

(In reply to Shane Tomlinson [:stomlinson] from comment #7)

> It could be that the request is timing out after 30 seconds while this is
> happening.

In IRC, Mihai informed me that he left the initiating tab open for 30 minutes without the status changing, a WebChannel timeout seems unlikely to be causing the page to transition when opening the 2nd tab.

Comment 10

[Shane Tomlinson [:stomlinson]]

:grisha and I have been trying to track the source of these problems down for the past few hours. Here's what we have found.

When opening FxA from "History->Synced Devices->Get Started" neither setTimeout nor form submission works, unless of course you change tabs and change back. setTimeout not working is problematic because RequireJS uses it to load modules. If we override RequireJS to immediately invoke the functions normally passed to setTimeout, FxA loads perfectly.. Everything seems to work as expected, until you tap on anything that should respond, like the "show" and "create account" buttons. Again, if you switch tabs, and switch back, everything works.

:grisha mentioned in IRC that about:accounts is opened from about:home without an `entrypoint` query parameter. If he modifies the code to open about:accounts with an entrypoint, it "mostly" works, but not always.

If I load `about:accounts?action=signin` by typing in the URL bar, everything works as expected.

I'm starting to ask myself whether we have hit some strange bugs in Fennec, or somehow run afoul of its security model.

Comment 11

[:Grisha Kruglov]

Talking this through with :nalexander, I think we're seeing some weird interaction with the event loop which I don't fully understand.

It seems that it's not making progress under certain conditions, and so the about:accounts js code is getting stuck. Behaviour in the emulator seems a little different from the device - fxa iframe loads and fire off a webchannel message, at which point the fxa form UI is displayed. However, it then tries to load additional profile data (avatar..), via an XHR request I suppose, and _that_ is getting stuck. When trying this on device, we seem to be getting stuck much earlier, while loading an fxa iframe.

Anything which involves activity lifecycle events (going into prefs and back, opening another app and coming back), or certain tab events (selected/unselected being fired when switching tabs in the Tabs Tray) seem to get the event loop unstuck, and we're able to move forward.

Shane's modification of requirejs seems to support the "weird event loop stuff" theory:

17:03 grisha: if I modify this line in requirejs: fxa-content-server
17:04 grisha: woops: https://github.com/requirejs/requirejs/blob/master/require.js#L1814
17:04 grisha: to get rid of the ternary operation and instead set `req.nextTick = function (fn) { fn(); };`, everything loads as expected.

Original code is:

req.nextTick = typeof setTimeout !== 'undefined' ? function (fn) {
        setTimeout(fn, 4);
} : function (fn) { fn(); };

And so, the change Shane made gets fn() to be evaluated in the current pass of the loop. If the event loop is stuck, evaluating it later on would not work, since we'll just never do it.

Additionally, launching the about:accounts page in _any_ other way (from the Sync Preferences panel, typing the address in directly, etc) seems to put us into a different execution model, in a way that we're _not_ getting stuck. I don't quite understand this either. 

snorp, do you have any idea what could be happening here?

Comment 12

[Oana Horvath [:ohorvath - out of office]]

Reproducible on Nightly 56.0a1 & Beta 55.0b3 (2017-06-20), on the production server.
Going to the sign in page from the first run tour & from the synced devices tab, results in an infinite loading screen.

Comment 13

[:Grisha Kruglov]

Hi Eugen,

From IRC, I think you were looking into possible causes for this. Any updates?

Comment 14

[Eugen Sawin [:esawin]]

Attachment: 0001-Bug-1373224-1.0-Update-current-activity-when-activit.patch

That's a regression from bug 1346413.

In this case only onActivityResumed is called without onActivityCreated for the BrowserApp activity. Since we don't update the current activity (which is still set to FxAccountGetStartedActivityWeb) before onActivityStopped is called, we background the app falsely.

Comment 15

[Jan Henning [:JanH]]

Comment on attachment 8880030 [details] [diff] [review]
0001-Bug-1373224-1.0-Update-current-activity-when-activit.patch

Hmm, I see that between the frontend and platform teams we're still undecided on whether to use prefixes or not :-) - that aside, this change is not terribly complex, but it still would have been nicer to split the cosmetic changes off into a separate patch to make the actual changes more visible.

That aside it's fine.

Comment 16

[Eugen Sawin [:esawin]]

Attachment: 0001-Bug-1373224-1.1-Update-current-activity-when-activit.patch

(In reply to Jan Henning [:JanH] from comment #15)
> Hmm, I see that between the frontend and platform teams we're still
> undecided on whether to use prefixes or not :-) - that aside, this change is
> not terribly complex, but it still would have been nicer to split the
> cosmetic changes off into a separate patch to make the actual changes more
> visible.

You're right, I've removed all code style fixes from the patch.
This file contains inconsistent styles, which should be resolved in a dedicated bug.

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/f3dab3f605b3
[1.1] Update current activity when activity is resumed. r=JanH

Comment 18

[Jan Henning [:JanH]]

(In reply to Eugen Sawin [:esawin] from comment #16)
> This file contains inconsistent styles, which should be resolved in a
> dedicated bug.

Oh, you mean the "mInitialized", right? Oops, my fault.

Comment 19

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/f3dab3f605b3

Comment 20

[Eugen Sawin [:esawin]]

Comment on attachment 8880128 [details] [diff] [review]
0001-Bug-1373224-1.1-Update-current-activity-when-activit.patch

Approval Request Comment
[Feature/Bug causing the regression]: Bug 1346413.
[User impact if declined]: Users are unable to log in/register for FxA sync and potentially other similar use cases (see STR).
[Is this code covered by automated tests?]: No.
[Has the fix been verified in Nightly?]: Yes.
[Needs manual test from QE? If yes, steps to reproduce]: 
[List of other uplifts needed for the feature/fix]:
[Is the change risky?]: No.
[Why is the change risky/not risky?]: It's a simple fix that makes sure we track active activities when they are resumed.
[String changes made/needed]: None.

Comment 21

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

Comment on attachment 8880128 [details] [diff] [review]
0001-Bug-1373224-1.1-Update-current-activity-when-activit.patch

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

Fix for regression that stops users from logging into sync. Let's take this for beta 5.

Comment 22

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

Mihai, can you verify the fix? (since you reported it I figure you can replicate it)

Comment 23

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/d2a1eb670120

Comment 24

[u549602]

Hi everyone,

Verified as fixed on both latest Nightly and 55.0b5. This was tested on both Prod and Staging server and works like a charm in both cases. 
Devices used for testing the fix: Asus ZenPad 8.0 Z380KL (Android 6.0.1) and Samsung Galaxy S6 EDGE (Android 7.0).