1274150 - Detecting account verification via push doesn't send fxaccounts:onverified notification.

Status: RESOLVED WORKSFORME

(Firefox :: Sync, defect, P3)

Description

[Mark Hammond [:markh] [:mhammond]]

STR:
* clean profile, create FxA account, get verification mail.
* wait for polling to stop - you could change POLL_SESSION in FxAccountsCommon to a small value to avoid waiting the entire 20 minutes.
* open the verification link in a *different* profile/device.

Actual:
* Existing tab open to https://accounts.firefox.com/confirm hasn't changed - it still says "A verification link has been sent"
* Browser still thinks the user is unverified.
* Browser isn't syncing.

Expected:
* https://accounts.firefox.com/confirm changes to reflect verification is complete.
* Browser changes to a fully verified state.
* Browser is syncing.

From the logs below we can see that push did tell us about the verification - it's just that the right thing didn't happen. I suspect the ONVERIFIED_NOTIFICATION isn't sent in that case - there's certainly no log entry for it. I doubt would impact the /confirm tab, but would impact the browser and hopefully cause Sync to start.

Note that closing and reopening about:preferences *did* seem to update the state to verified, however Sync didn't start.

Relevant log entries:
> 1463636911665   FirefoxAccounts DEBUG   checkEmailStatus -> {"email":"[e-mail]","verified":false}
> 1463636911666   FirefoxAccounts DEBUG   polling with timeout = 15000
> ...
> 1463636957276   FirefoxAccounts DEBUG   polling session exceeded, giving up
> 1463636957277   FirefoxAccounts INFO    the wait for user verification was stopped: Error: User email verification timed out.
> 1463636957277   FirefoxAccounts INFO    startVerifiedCheck promise was rejected: Error: User email verification timed out.
> 1463636957278   FirefoxAccounts INFO    startVerifiedCheck promise was rejected: Error: User email verification timed out.
> 1463636957278   FirefoxAccounts INFO    startVerifiedCheck promise was rejected: Error: User email verification timed out.
> 1463636957278   FirefoxAccounts INFO    startVerifiedCheck promise was rejected: Error: User email verification timed out.
> 1463636957278   FirefoxAccounts INFO    startVerifiedCheck promise was rejected: Error: User email verification timed out.
> 1463636957279   Sync.BrowserIDManager   ERROR   Background fetch for key bundle failed: Error: User email verification timed out. ...
> 1463636957280   Sync.BrowserIDManager   ERROR   Could not authenticate: Error: User email verification timed out. ...
> 1463636977444   FirefoxAccounts DEBUG   entering pollEmailStatus: push
> 1463636977444   FirefoxAccounts DEBUG   pollEmailStatus starting while existing timer is running

<note: the above entry looks wrong - the timer is *not* running at this stage>

> 1463636977642   FirefoxAccounts DEBUG   checkEmailStatus -> {"email":"[e-mail]","verified":true}
> 1463636977643   FirefoxAccounts DEBUG   _updateAccountData with items: ["verified"]
> 1463636977647   FirefoxAccounts DEBUG   Notifying observers of fxaccounts:update

<note: this is ON_FXA_UPDATE_NOTIFICATION - I'm expecting to also see ONVERIFIED_NOTIFICATION (ie "fxaccounts:onverified")>

> 1463636977647   FirefoxAccounts DEBUG   writing plain storage: ["email","sessionToken","uid","verified","deviceId","deviceRegistrationVersion"]
> 1463636977658   FirefoxAccounts DEBUG   writing secure storage: ["keyFetchToken","unwrapBKey"]

Comment 1

[Mark Hammond [:markh] [:mhammond]]

Digging into the code, I've come to the conclusion that this would be very tricky to do with the way the code is structured, so we should do it as part of/after refactoring FxAccounts in bug 1256459.

Comment 2

[Edouard Oger [:eoger]]

Attachment: Bug 1274150 - Send fxaccounts:onverified when verification triggered by Push.

Review commit: https://reviewboard.mozilla.org/r/102978/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/102978/

Comment 3

[Edouard Oger [:eoger]]

In this patch, checkVerificationStatus now calls startVerifiedCheck() which calls getKeys() (which sends the fxaccounts:onverified message).

Comment 4

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8824520 [details]
Bug 1274150 - Send fxaccounts:onverified when verification triggered by Push.

https://reviewboard.mozilla.org/r/102978/#review104442

The current code is a mess :( But I'm not sure this is going to do the right thing in all cases. There might be a nice way to refactor things in a cleaner way though - eg, whenVerified calls pollEmailStatus and doesn't do much else, so there's probably scope to refactor those 2 to be less confusing. Either way, we will need very thorough manual testing of this, and/or more throrough xpcshell tests to cover some of these edge cases and the state of the timer.

::: services/fxaccounts/FxAccounts.jsm:730
(Diff revision 1)
>  
>        // Always check the verification status, even if the local state indicates
>        // we're already verified. If the user changed their password, the check
>        // will fail, and we'll enter the reauth state.
>        log.trace("checkVerificationStatus - forcing verification status check");
> -      return this.pollEmailStatus(currentState, data.sessionToken, "push");
> +      return this.startVerifiedCheck(data, "push", true);

Isn't this change going to mean an existing poll isn't going to be cancelled?

::: services/fxaccounts/FxAccounts.jsm:1106
(Diff revision 1)
>          }
>          return data;
>        });
>    },
>  
> -  startVerifiedCheck: function(data) {
> +  startVerifiedCheck: function(data, why, forceRemoteVerify) {

the name |forceRemoveVerify| confused me - I thought it meant "force verification to true because the remote said it was so", where it really means "force a remote check even if we think we are already verified".

So I think maybe |forceRemoteCheck| might be a better name.

::: services/fxaccounts/FxAccounts.jsm:1119
(Diff revision 1)
>      //
>      // Login is truly complete once keys have been fetched, so once getKeys()
>      // obtains and stores kA and kB, it will fire the onverified observer
>      // notification.
>  
>      // The callers of startVerifiedCheck never consume a returned promise (ie,

This comment is now wrong - and given not all callers of startVerifiedCheck have been touched here, I don't think we can get away with this alone (ie, at a minimum the other callers must end up with a final .catch for the promise)

::: services/fxaccounts/FxAccounts.jsm:1227
(Diff revision 1)
>      if (ageMs >= this.POLL_SESSION) {
>        if (currentState.whenVerifiedDeferred) {
>          let error = new Error("User email verification timed out.");
>          this._rejectWhenVerified(currentState, error);
>        }
> +      this.currentTimer = null;

if currentTimer is non-null here I think it means it will still fire in the future, which seems (possibly) bad.

Comment 5

[Edouard Oger [:eoger]]

I haven't worked on that for a long time, and we also refactored some parts of the verification process in bug 1122443

Comment 6

[Mark Hammond [:markh] [:mhammond]]

(In reply to Edouard Oger [:eoger] from comment #5)
> we also refactored some parts
> of the verification process in bug 1122443

And I'm fairly confident that effort means that this now works correctly (and given over 90% of verifications are now detected via push, we'd have more bug reports that the UI state didn't update correctly when it did.). So WFM!