User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:34.0) Gecko/20100101 Firefox/34.0 Build ID: 20141126041045 Steps to reproduce: 1. Close FF 2. Open FF 3. Get error 4. Profit Actual results: On start FF says sync failed due wrong login/password. I need to relogin, but when FF is restarted problem appears again. Sync log:http://pastebin.com/eTip7fBH

Relevant bits: 417229036517 FirefoxAccounts DEBUG got keyPair 1417229036539 FirefoxAccounts DEBUG getCertificateSigned: true true 1417229037425 FirefoxAccounts DEBUG getCertificate got a new one: true 1417229037425 FirefoxAccounts DEBUG getAssertionFromCert 1417229037429 FirefoxAccounts DEBUG getAssertionFromCert returning signed: true 1417229037430 Sync.BrowserIDManager DEBUG Getting a token 1417229037870 Sync.SyncScheduler DEBUG Next sync in 600000 ms. 1417229038280 Sync.BrowserIDManager ERROR Authentication error in _fetchTokenForUser: AuthenticationError(TokenServerClientServerError({"now":"2014-11-29T02:43:58.279Z","message":"Authentication failed.","cause":"invalid-client-state","response_body":"{\"status\": \"invalid-client-state\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Unauthorized\"}]}","response_headers":{"content-type":"application/json; charset=UTF-8","date":"Sat, 29 Nov 2014 03:43:57 GMT","x-timestamp":"1417232637","content-length":"111","connection":"keep-alive"},"response_status":401})) 1417229038281 Sync.Status DEBUG Status.login: success.login => error.login.reason.account 1417229038281 Sync.Status DEBUG Status.service: success.status_ok => error.login.failed 1417229038281 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score. clone this paste RAW

This is expected to happen after a user resets her password. Firefox should prompt the user to re-login so it can derive the new Sync key. Roman, Firefox should have prompted you to "Reconnect to Sync", which requires you to enter your password again. Based on the IRC conversation, it seems this may be working again for you. Is that the case?

Well, I did not reset my password. Sync now is working, this time relogin helped me.

I need to dig a little more, but I *think* the normal flow of "needs reauth" is more obvious in the logs than the somewhat cryptic "invalid-client-state". I'll test when I'm back home.

I'm getting the same error message. Shortly after start, a message bar appears at the bottom telling me that sync failed because either my user name or password is wrong - i did not change or reset it since i created the account, why would i. In the logs i can the see the same error message as the one already reported in comment #1. When i reenter the password, sync starts working, but only until Firefox is closed. Upon next start, the same messages appear again and i have to reenter the password to get sync working. This issue is starting to get annoying, as for me at least, it seams to reappear on a monthly basis without any change on my end. This is now the fifth time since i switched to the new sync system last summer that this is popping up. The first three times i had to completely remove the sync account from all attached devices to get it working again. I will not do that another time. In December the issue resolved itself somehow after a week or so, and now in January i keep getting this error for almost week now. I really do hope this will be sorted out soon.

Mark, it sounds similar to the bug we were seeing with with Edwin's profile, where the sync credentials weren't being saved to the password manager on login. mike, do you use master password?

(In reply to Chris Karlof [:ckarlof] from comment #6) > Mark, it sounds similar to the bug we were seeing with with Edwin's profile, > where the sync credentials weren't being saved to the password manager on > login. > > mike, do you use master password? Although the log doesn't have that tell-tale "Can't find credentials in the login manager" entry, which is a key "feature" of Edwin's bug. (and recall that Edwin also isn't using a master-password, but the underlying bug 1124553 makes it *seem* like he was)

(In reply to Chris Karlof [:ckarlof] from comment #6) > > mike, do you use master password? Chris, i don't use master password.

One thing i forgot to mention: i'm currently Firefox 35. User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:35.0) Gecko/20100101 Firefox/35.0

oops - I didn't mean to clear my needinfo request from comment 4

Today I found another set of error messages when this issue occured during start, maybe these can help: 1422642962649 Sync.ErrorHandler DEBUG Flushing file log. 1422642962651 Sync.BrowserIDManager ERROR Background fetch for key bundle failed: AuthenticationError(TokenServerClientServerError({"now":"2015-01-30T18:36:02.648Z","message":"Authentication failed.","cause":"invalid-client-state","response_body":"{\"status\": \"invalid-client-state\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Unauthorized\"}]}","response_headers":{"content-type":"application/json; charset=UTF-8","date":"Fri, 30 Jan 2015 18:35:57 GMT","x-timestamp":"1422642957","content-length":"111","connection":"keep-alive"},"response_status":401})) 1422642962651 Sync.BrowserIDManager ERROR Could not authenticate: AuthenticationError(TokenServerClientServerError({"now":"2015-01-30T18:36:02.648Z","message":"Authentication failed.","cause":"invalid-client-state","response_body":"{\"status\": \"invalid-client-state\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Unauthorized\"}]}","response_headers":{"content-type":"application/json; charset=UTF-8","date":"Fri, 30 Jan 2015 18:35:57 GMT","x-timestamp":"1422642957","content-length":"111","connection":"keep-alive"},"response_status":401})) 1422642962651 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score.

Kit, this is a good candidate for adding telemetry/metrics for measuring how often this happens, too.

Any news or progress? For a few weeks, this issue was gone, but started again end of last week. On more than one device, while others synching to the same account still worked without any problems. Found these messages now ( bit different from last time, running now Firefox 39 in Windows 10): 1438719427530 Sync.Service INFO Loading Weave 1.41.0 1438719427531 Sync.Engine.Clients DEBUG Engine initialized 1438719427532 Sync.Engine.Clients DEBUG Resetting clients last sync time 1438719427538 Sync.Engine.Bookmarks DEBUG Engine initialized 1438719427542 Sync.Engine.Forms DEBUG Engine initialized 1438719427546 Sync.Engine.History DEBUG Engine initialized 1438719427549 Sync.Engine.Passwords DEBUG Engine initialized 1438719427552 Sync.Engine.Prefs DEBUG Engine initialized 1438719427556 Sync.Engine.Tabs DEBUG Engine initialized 1438719427556 Sync.Engine.Tabs DEBUG Resetting tabs last sync time 1438719427562 Sync.Engine.Addons DEBUG Engine initialized 1438719427563 Sync.Service INFO Mozilla/5.0 (Windows NT 10.0; WOW64; rv:39.0) Gecko/20100101 Firefox/39.0 1438719427566 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score. 1438719427567 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1438719427567 Sync.Service DEBUG Caching URLs under storage user base: https://sync-183-us-west-2.sync.services.mozilla.com/1.5/16244539/ 1438719427567 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1438719427603 Sync.Engine.AdblockPlus DEBUG Engine initialized 1438719427604 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1438719427646 FirefoxAccounts DEBUG got keyPair 1438719427646 FirefoxAccounts DEBUG getCertificateSigned: true true 1438719429944 Hawk DEBUG (Response) /certificate/sign: code: 200 - Status text: OK 1438719429945 Sync.RESTResponse TRACE Processing response headers. 1438719429946 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: 2054 1438719429947 FirefoxAccounts DEBUG getCertificate got a new one: true 1438719429948 FirefoxAccounts DEBUG getAssertionFromCert 1438719429958 FirefoxAccounts DEBUG getAssertionFromCert returning signed: true 1438719429960 Sync.BrowserIDManager DEBUG Getting a token 1438719429963 Common.TokenServerClient DEBUG Beginning BID assertion exchange: https://token.services.mozilla.com/1.0/sync/1.5 1438719431609 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1438719431610 Sync.Service DEBUG User-Agent: Firefox/39.0 FxSync/1.41.0.20150630154324. 1438719431610 Sync.Service INFO Starting sync at 2015-08-04 22:17:11 1438719431611 Sync.Service DEBUG In sync: should login. 1438719431612 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1438719431612 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1438719431781 Common.TokenServerClient DEBUG Got token response: 401 1438719431782 Sync.RESTResponse TRACE Processing response headers. 1438719431782 Common.TokenServerClient INFO Server-reported error: {"location":"header","name":"X-Client-State","description":"Unacceptable client-state value new value with no generation change"} 1438719431783 Sync.BrowserIDManager ERROR Authentication error in _fetchTokenForUser: ({details:(new TokenServerClientServerError("Authentication failed.", "resource://gre/modules/services-common/tokenserverclient.js", 36))}) 1438719431787 Sync.Status DEBUG Status.login: success.login => error.login.reason.account 1438719431787 Sync.Status DEBUG Status.service: success.status_ok => error.login.failed 1438719431816 Sync.BrowserIDManager ERROR Background fetch for key bundle failed: ({details:(new TokenServerClientServerError("Authentication failed.", "resource://gre/modules/services-common/tokenserverclient.js", 36))}) 1438719431818 Sync.BrowserIDManager ERROR Could not authenticate: ({details:(new TokenServerClientServerError("Authentication failed.", "resource://gre/modules/services-common/tokenserverclient.js", 36))}) 1438719431820 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score.

> "Unacceptable client-state value new value with no generation change" In theory it should be impossible to get into this state (but obviously it's not!). It means that two clients are trying to sync with different encryption keys, but the same generation number. Since the encryption key should only change if you reset your password, and resetting your password should also change the generation number, this is a good sign that something has gone wrong. Either: * a client has updated their encryption key, but is still using an old certificate, or * a client has updated their certificate but is using an old cached encrytion key, or * there's some subtle logic error in the tracking of these things on client or server. I wonder if this is a symptom of some certificate-related race condition. The generation number is taken from the FxA identity certificate. If the client happened to use a cached-and-still-valid identity cert after the user r-entered their password, it might cause the error seen here.

It's getting worse. Now all of the attached clients running on Windows give me this error (previously it was always only one out of for PCs), just the two attached Android devices seem to be able to use the account without the need to reenter the password every time. And every time I reenter my password I get a mail stating that a new device is now linked with the account?!? Even if I let Firefox run, reenter my sync accounts password and Firefox / sync seemingly accepting it - sync doesn't do anything anymore. I added four new bookmarks, manually synced on the Windows PC I added the bookmarks and on the Android devices, but the new bookmarks do not show up on the Android devices. This is starting to drive me mad.

Ugh, this sounds awful, and I have a hard time making sense of what could be causing it. We should take a look at the tokenserver state for this account and see if it offers any clues. Mike, is your sync account linked to the same email you use for bugzilla? If not then let's coordinate a way for you to provide it confidentially, and we can dig into the server-side state to help explain what's going on here. Also, it's a hack, but if you haven't tried already then it's possible that doing a password reset will help clear whatever the problem is that's causing this behaviour: https://accounts.firefox.com/reset_password

(In reply to Ryan Kelly [:rfkelly] from comment #16) > Mike, is your sync account linked to the same email you use for bugzilla? > If not then let's coordinate a way for you to provide it confidentially, and > we can dig into the server-side state to help explain what's going on here. I use the same email for bugzilla and sync. > Also, it's a hack, but if you haven't tried already then it's possible that > doing a password reset will help clear whatever the problem is that's > causing this behaviour: > > https://accounts.firefox.com/reset_password I reseted my sync password before my previous post, did that not help. :-( I you need more info just let me know. I have some time over the weekend if you want me to try something.

I filed Bug 1198104 (employee confidential) to get any info on your server account from the sync tokenserver. Let's see if that shows any additional clues.

Based on Bug 1198104 Comment 5, it looks like the situation may be resolving itself, although I really don't understand why. Mike, please let us know if the error seems completely resolved, or if it returns.

I keep an eye on it. If anything changes I will let you know. Thanks for the help so far.

Sadly I'm still struggling to make sense of this. However, I'm confident that in the normal case, a simple password change or reset does *not* cause this invalid-client-state error. (In reply to Ryan Kelly [:rfkelly] from comment #14) > Since the encryption key > should only change if you reset your password, and resetting your password > should also change the generation number, this is a good sign that something > has gone wrong. What I find strange is that comment 3 explicitly says they didn't change their password, and comment 5 strongly implies the same. > I wonder if this is a symptom of some certificate-related race condition. > The generation number is taken from the FxA identity certificate. If the > client happened to use a cached-and-still-valid identity cert after the user > r-entered their password, it might cause the error seen here. That sounds reasonable, although the log from comment 13 appears to be the first log after the browser starts. The browser does *not* persist "cert" or "keypair", so there's no scope for it to be using a cached version at startup (most other fields are persisted though). So while I could possibly see this happening if the password is changed in the same browser session (which bug 1044530 should fix if that was the case), I can't see how it could happen at startup. I guess one thought experiment may be, say, that an older version of signedInUser.json was restored, but the data in the login manager was not (or vice-versa) - although I tried to simulate that (by instrumenting the code so that writes to either of them (but not both of them) were ignored, meaning the next session caused the old values to be read and mixed with the new values, and changing my password in the meantime, but still couldn't provoke this. Given the lack of recent bug reports about this, I don't think this is currently actionable.