976149 - [FxA] Firefox Sync intermittently disconnects with error.login.reason.no_recoverykey after "Authentication error in _fetchTokenForUser"

Status: RESOLVED FIXED

(Firefox :: Sync, defect, P1)

Description

[Matt Brubeck (:mbrubeck)]

Attachment: error-1393254064074.txt

I'm seeing this periodically on desktop (Nightly and Aurora, signed into a Firefox Account), and possibly also on Android (though I haven't managed to capture a log on Android to verify that it's the same problem).  I think this was the actual cause of bug 975059, but I'm filing this as a new bug because that one had a bunch of mistaken information in it.  (This bug is happening intermittently, which tricked me into thinking I had steps to reproduce when I didn't.)

When this bug occurs, a sync error is displayed.  If I press the "Reconnect to sync" button that appears in the menu panel, I'm asked to re-enter my password to sign into sync.  However, there is a signedInUser.json file in my profile, and sync appears to reconnect automatically and successfully if I just restart Firefox instead of signing in again.

Attached is one of the logs showing the error.  I've saved copies of a few days' worth of logs, if more would be helpful.

In another log, the authentication error occurred shortly after a "Could not acquire lock error", though I'm not sure whether that's related:

1392924812002   Sync.Service       DEBUG  Caching URLs under storage user base: https://sync-1-us-east-1.sync.services.mozilla.com/1.5/41459/
1392924836027   Sync.Service       DEBUG  User-Agent: Firefox/29.0a2 FxSync/1.31.0.20140220004001.
1392924836027   Sync.Service       INFO   Starting sync at 2014-02-20 11:33:56
1392924836027   Sync.Service       DEBUG  In sync: should login.
1392924836027   Sync.Service       DEBUG  Exception: Could not acquire lock. Label: "service.js: login". No traceback available
1392924836027   Sync.Service       INFO   Cannot start sync: already syncing?
1392924836027   Sync.Service       DEBUG  Not syncing: login returned false.
1392924838097   Sync.BrowserIDManager      ERROR Authentication error in _fetchTokenForUser: Client error.
1392924838098   Sync.Status        DEBUG   Status.login: success.login => error.login.reason.no_recoverykey
1392924838098   Sync.Status        DEBUG   Status.service: success.status_ok => service.client_not_configured
1392924838098   Sync.SyncScheduler DEBUG    Clearing sync triggers and the global score.

Comment 1

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

I've seen this happen when there are time-skew issues between the servers.  An excellent first step might be to ensure details about the error appears in the log.

Comment 2

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

FTR, I opened bug 976393 to work out how to best get informative errors in the logs.

Comment 4

[:Gavin Sharp [email: [e-mail]]]

Is this really a dupe? I wonder whether we should track these separately until we've looked into these more.

Comment 5

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

(In reply to :Gavin Sharp (email [e-mail]) from comment #4)
> Is this really a dupe? I wonder whether we should track these separately
> until we've looked into these more.

Yes - bug 971194 seems a combination of errors, whereas this bug is very specific, so let's treat then separately for now.

Comment 6

[Chris Karlof [:ckarlof]]

> 1392924836027   Sync.Service       DEBUG  Exception: Could not acquire lock. Label: "service.js: login". No traceback available
> 1392924836027   Sync.Service       INFO   Cannot start sync: already syncing?

This is the most disturbing part here. If this is routinely happening, we may have some code paths that are are grabbing this lock and never releasing it. If I had to point fingers, it might be some of the promise code we added that has an event loop spinner wrapping it. It's definitely worth an investigation.

Comment 7

[Matt Brubeck (:mbrubeck)]

After reading rnewman's message about clocks [1] I noticed that both my PC and phone had network time disabled, and their clocks were off by a couple of minutes or so.  I haven't seen this error again after enabling network time on both devices, so that may indeed have been the root cause of my problems.

[1] http://permalink.gmane.org/gmane.comp.mozilla.sync.devel/791

Comment 8

[Chris Karlof [:ckarlof]]

We also got a lot more lenient on errors resulting from time skew. I'm glad to see that it resolved it for you. I'm closing as fixed, but I'll leave it to you to verify.

Comment 9

[Lukas Blakk [:lsblakk] use ?needinfo]

looks like we don't need to track this as the reporter can no longer reproduce and might have had an unusual set up.