971194 - Signed out of Sync against my will

Status: RESOLVED WORKSFORME

(Firefox :: Sync, defect, P1)

Description

[Ryan Feeley [:rfeeley]]

I was signed out of the new FxA Sync against my own will.

Here are the logs.

https://dl.dropboxusercontent.com/u/5265484/ryans-sync-logs.zip

Comment 1

[Richard Newman [:rnewman]]

Interesting logs. You're seeing errors for missing fields on startup, until things get set up:


1391817904213   Sync.Service    INFO    Loading Weave 1.32.0
1391817904221   Sync.Engine.Clients     DEBUG   Engine initialized
...
1391817904243   Sync.Status     DEBUG   Status.login: success.login => error.login.reason.no_username
1391817904243   Sync.Status     DEBUG   Status.service: success.status_ok => service.client_not_configured

...

1392137118699   Sync.Status     DEBUG   Status.login: error.login.reason.no_recoverykey => error.login.reason.no_recoverykey
1392137118699   Sync.Status     DEBUG   Status.service: service.client_not_configured => service.client_not_configured


You're having network problems:

1392137118710   Sync.Service    DEBUG   Exception: NS_ERROR_UNKNOWN_HOST JS Stack trace: [e-mail]:413 < [e-mail]:521 < [e-mail]:75 < [e-mail]:1207 < [e-mail]:143 < [e-mail]:98 < [e-mail]:1201 < sync/<@service.js:1192 < [e-mail]:72 < [e-mail]:1180


You're seeing other bugs:

1392137118689   Sync.BrowserIDManager   ERROR   Authentication error in _fetchTokenForUser: Client error.


You're even hitting the Firefox 4 upgrade path, which you'll hit if the remote syncID differs from the local syncID:

1392146433843   Sync.Service    WARN    Failed to upgrade sync key. Failing remote setup.


and apparently being in an error state while still happily syncing:

1392141596666   Sync.Collection DEBUG   mesg: POST success 200 https://sync-2-us-east-1.sync.services.mozilla.com/1.5/11476/storage/tabs
1392141596667   Sync.Collection DEBUG   POST success 200 https://sync-2-us-east-1.sync.services.mozilla.com/1.5/11476/storage/tabs
1392141724232   Sync.Status     DEBUG   Status.login: error.login.reason.no_recoverykey => error.login.reason.no_recoverykey
1392141724232   Sync.Status     DEBUG   Status.service: service.client_not_configured => service.client_not_configured
1392141724232   Sync.Status     DEBUG   Status.login: error.login.reason.no_recoverykey => error.login.reason.no_recoverykey
1392141724232   Sync.Status     DEBUG   Status.service: service.client_not_configured => service.client_not_configured


The overall concern I have with these logs: the FxA auth system, because of its additional up-front auth work, is *routinely* placing the client into an error state. That's riskier than I'd like, because it runs the risk of tickling bugs in less-well-tested code, including code that hasn't run since old passphrase-based Sync accounts were updated to use 26-char keys.

I think the core error here is that the new FxA identity module doesn't completely implement the interface that Service expects. In particular, `upgradeSyncKey` is returning `false` during remote setup, presumably because the identity module doesn't have a sync key.

  /**
   * Obtain the Sync Key.
   *
   * This returns a 26 character "friendly" Base32 encoded string on success or
   * null if no Sync Key could be found.
   *
   * If the Sync Key hasn't been set in this session, this will look in the
   * password manager for the sync key.
   */
  get syncKey() {
    if (this.syncKeyBundle) {
      // TODO: This is probably fine because the code shouldn't be
      // using the sync key directly (it should use the sync key
      // bundle), but I don't like it. We should probably refactor
      // code that is inspecting this to not do validation on this
      // field directly and instead call a isSyncKeyValid() function
      // that we can override.
      return "99999999999999999999999999";
    }
    else {
      return null;
    }
  },

browserid_identity.js has quite a few TODOs and incorrect comments copypasta'd from elsewhere, so I wouldn't be surprised if there were more behaviors like this hiding in the error handling states.

Flagging for tracking, because I see no reason why this is likely to uniquely affect Ryan, and these error states will only be more frequent under production load.

Comment 2

[Richard Newman [:rnewman]]

Another user:

10:01:03 < cade> tracy: soooooo, definitely not successful. about:sync-log shows a whole bunch of error logs. latest is: https://www.pastebin.mozilla.org/4279196

Comment 3

[Edwin Wong [:edwong]]

Ryan and I were unable to repro the getting signed out with a new profile/user.  I do often see errors in the sync logs but I'm still successfully auth and syncing.

Comment 4

[Richard Newman [:rnewman]]

(In reply to Edwin Wong [:edwong] from comment #3)
> Ryan and I were unable to repro the getting signed out with a new
> profile/user.  I do often see errors in the sync logs but I'm still
> successfully auth and syncing.

There will need to be a certain sequence of server-related errors to cause this scenario. Regular black-box QA won't find it; it probably needs white-box testing with provoked server failures and timing issues.

Comment 6

[Richard Newman [:rnewman]]

Found one way to make this occur, by accident.

A 503 fetching info/collections => Tools shows "Set up Sync…", Prefs shows “Please sign in to reconnect”.

The 503 was the first and only request this session.

That's not right.

Repro:

* Set up Sync.
* Switch your token server URL to a token server that will 503.
* Relaunch browser.
* Tools > Sync Now.

Comment 7

[Chris Karlof [:ckarlof]]

(In reply to Richard Newman [:rnewman] from comment #6)
> Found one way to make this occur, by accident.
> 
> A 503 fetching info/collections => Tools shows "Set up Sync…", Prefs shows
> “Please sign in to reconnect”.
> 
> The 503 was the first and only request this session.
> 
> That's not right.
> 
> Repro:
> 
> * Set up Sync.
> * Switch your token server URL to a token server that will 503.
> * Relaunch browser.
> * Tools > Sync Now.

All token server errors were being treated as auth errors. Fix in Bug 977502.

Comment 8

[Chris Karlof [:ckarlof]]

Looking through the logs, I suspect Ryan hit a magical combination of issues: FxAccounts.jsm not clearing state sufficiently on user logout, FxA Sync not clearing prefs on logout, network and other errors being treated as auth errors, and crappy luck with clock skew. These have been hopefully fixed in Bug 977502, Bug 967015, Bug 972070, and turning off timestamp checking in Hawk. browserid_identity.js could still use a fair amount of cleanup, particular in the sync key getter hack you pointed out, Richard. :) It could just be wishful thinking, but I suspect Ryan will have a much better experience on Nightly now.

Comment 9

[Chris Karlof [:ckarlof]]

Per discussion with Ryan, he is still experiencing other Sync issues, but not the ones reported in this bug. Closing as fixed.