1116119 - Sync error "Incorrect account name or password" whenever Firefox is launched

Status: RESOLVED WORKSFORME

(Firefox :: Sync, defect, P1)

Description

[Martin Giger [:freaktechnik]]

Whenever I open Firefox I get a "Syn encountered an error while syncing: Incorrect account name or password." error and have to relogin. Now, this doesn't happen just on one machine, it happens on every Firefox Profile (Windows or Linux, Release or Nightly, fresh profile or ancient profile) I sync with this account. The error doesn't happen on Android though.

I get the following logging in the browser console after launching Firefox:
1419855726634	Sync.BrowserIDManager	ERROR	Authentication error in _fetchTokenForUser: AuthenticationError(TokenServerClientServerError({"now":"2014-12-29T12:22:06.622Z","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":"Mon, 29 Dec 2014 12:22:06 GMT","x-timestamp":"1419855726","content-length":"111","connection":"keep-alive"},"response_status":401})) Log.jsm:749
1419855726640	Sync.BrowserIDManager	ERROR	Background fetch for key bundle failed: AuthenticationError(TokenServerClientServerError({"now":"2014-12-29T12:22:06.622Z","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":"Mon, 29 Dec 2014 12:22:06 GMT","x-timestamp":"1419855726","content-length":"111","connection":"keep-alive"},"response_status":401})) Log.jsm:749
1419855726641	Sync.BrowserIDManager	ERROR	Could not authenticate: AuthenticationError(TokenServerClientServerError({"now":"2014-12-29T12:22:06.622Z","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":"Mon, 29 Dec 2014 12:22:06 GMT","x-timestamp":"1419855726","content-length":"111","connection":"keep-alive"},"response_status":401}))

FxA and Sync ar both indicated as "up" on the cloud services status page. After logging in again (entering my FxA passowrd) sync works fine for the rest of the session.

Comment 1

[Chris Karlof [:ckarlof]]

Do you have Firefox set to clear saved passwords on exit? There is an outstanding bug around that (bug 1102184).

Comment 2

[Martin Giger [:freaktechnik]]

(In reply to Chris Karlof [:ckarlof] from comment #1)
> Do you have Firefox set to clear saved passwords on exit? There is an
> outstanding bug around that (bug 1102184).

No, I have it on the default keep history setting. I sync everything that is syncable, I also tried disabling all extensions, which didn't fix it either.

Comment 3

[Chris Karlof [:ckarlof]]

Additional questions:

* Have you ever reset or changed your account password?
* Do you use the Master Password feature in Firefox?

Comment 4

[Martin Giger [:freaktechnik]]

(In reply to Chris Karlof [:ckarlof] from comment #3)
> * Have you ever reset or changed your account password?
Yes, I think I've changed my FxA password at least once.

> * Do you use the Master Password feature in Firefox?
No.

Comment 5

[Ryan Kelly [:rfkelly]]

> After logging in again (entering my FxA passowrd) sync works fine for the rest of the session.

Can you confirm that sync fully works after re-entering your password?  For example, do history or bookmarks actually sync between devices?  (I can imagine some error paths where sync might stop complaining about the auth error, but not actually start working again).

The "invalid-client-state" error is a server-side safeguard to ensure that your client is using the correct encryption keys.  I don't have a good theory about what's going on or how your account got into this state, but some subset of your devices and/or the server are in disagreement about what your encryption keys should be.

One possible workaround would be to reset the password on your Firefox Account:

  https://accounts.firefox.com/reset_password

This has the side-effect of resetting the encryption keys, which might be enough to get things back to a consistent state.

Comment 6

[Martin Giger [:freaktechnik]]

(In reply to Ryan Kelly [:rfkelly] from comment #5)
> > After logging in again (entering my FxA passowrd) sync works fine for the rest of the session.
> 
> Can you confirm that sync fully works after re-entering your password?  For
> example, do history or bookmarks actually sync between devices?
History seems synced, tabs are synced, add-on states are synced, credentials are synced, so I'm pretty sure it's working.

> One possible workaround would be to reset the password on your Firefox
> Account:
> 
>   https://accounts.firefox.com/reset_password
> 
> This has the side-effect of resetting the encryption keys, which might be
> enough to get things back to a consistent state.

I'll try that and report back.

Comment 7

[Martin Giger [:freaktechnik]]

Changing the password seems to have fixed the error for now.

Comment 8

[Martin Giger [:freaktechnik]]

...and the 401 is back.

It may be of note, that I had two instances of Firefox connected to the same account open on two different machines at the same time.

Comment 9

[Ryan Kelly [:rfkelly]]

> ...and the 401 is back.

Is it back in the same persistent manner it was before? (i.e. occurring every time at firefox startup?)

Comment 10

[kiril]

I can report the same issue on Firefox 35.0 (Linux x86_64).
It happens *every time* when I start Firefox.

> Do you have Firefox set to clear saved passwords on exit? There is an
> outstanding bug around that (bug 1102184).

No.

> Have you ever reset or changed your account password?

Yes, several times. Just tried again and it didn't help.

> Do you use the Master Password feature in Firefox?

No.

> Can you confirm that sync fully works after re-entering your password? 

Yes. I've tested it by sending tabs from/to my Firefox on Android.

Let me just say that I have two profiles and I use them at the same time
(the second one is with --no-remote) with Profilist. At first I thought
this is where the issue comes from, but then I tried to use just the
main profile and even after several restarts it still asks for a
password.

Any ideas what to try or what information to provide in order to help
you reproduce it?

Comment 11

[Ryan Kelly [:rfkelly]]

> Let me just say that I have two profiles and 
>I use them at the same time (the second one is with --no-remote) with Profilist.

Are the two profiles connected to the same firefox account?

Can you please check in the files in about:sync-log and see if you're also getting the "invalid-client-state" error shown in the initial report?

Comment 12

[Ryan Kelly [:rfkelly]]

Possibly related to Bug 1124553

Comment 13

[kiril]

> Are the two profiles connected to the same firefox account?

No, I use separate accounts for each one

> Can you please check in the files in about:sync-log and see
> if you're also getting the "invalid-client-state" error
> shown in the initial report?

Sure, this is the latest error file: http://pastebin.com/raw.php?i=mMNbzGeM

> Possibly related to Bug 1124553

I don't think that's true, though. Even when I delete the `chrome://FirefoxAccounts` key after I login to Sync it's getting saved in my password and the "password" has this funny format:


    {
        "accountData": {
            "customizeSync": false,
            "keyFetchToken": "{64 characters hash}",
            "sessionTokenContext": "fx_desktop_v1",
            "unwrapBKey": "{another 64 characters  hash}"
        },
        "version": 1
    }

Comment 14

[kiril]

Bump. Do you need more information in order to debug this? Should I try something in order to fix it from my side (if it's related to my browser's settings in the first place)?

Comment 15

[promeneur]

opensuse 13.1 x86_64
firefox 35.0

sometime ago there was an update from 34.x to 35.0

no pb with "sync" feature" with FF 34.x

then
i get some pb with the tool bar . only the url field is displayed . you must click a button to access to the other part of the tool bar .

then
i rename .mozilla to .mozilla.sav
then
i launch firefox
then
i re-install all the addons and the bookmark
then
i connect "rsync" , no pb
then
i connect "hello" , no pb
then
i quit firefox
then
i launch firefox
then
after a little delay firefox says "rsync encounters a pb : account name or password is not good" .

no pb with hello connexion .

if i go to accounts.firefox.com it says FF is connected and offers to modify or to delete the account
i can connect rsync then rsync synchronizes data .

i tried to change password :  same pb .
i tried to delete the account (and the records "accounts credentials" and "accounts.firefox.com") and create a new account : same pb .

"accounts credentials" and "accounts.firefox.com" are in the list of saved passwords

no pb with android firefox rsync connexion .

Comment 16

[promeneur]

sorry for an error : read "sync" and not "rsync"

Comment 17

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

Not bug 1124553 - invalid-client-state is one we're still battling

Comment 18

[mike]

(In reply to Mark Hammond [:markh] from comment #17)
> Not bug 1124553 - invalid-client-state is one we're still battling

Why not? The message from the console from comment #1 says 'invalid-client-state' and the behaviour is the same.

Comment 19

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

I believe Mark meant "Note bug 1124553" :)

Comment 20

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

(In reply to mike from comment #18)
> (In reply to Mark Hammond [:markh] from comment #17)
> > Not bug 1124553 - invalid-client-state is one we're still battling
> 
> Why not? The message from the console from comment #1 says
> 'invalid-client-state' and the behaviour is the same.

Sorry for the confusion.  Bug 1124553 is an issue that causes us to fail to save credentials to the password manager, and the symptoms of that are "Failed to save data to the login manager" appearing in the log and no credentials appearing in the "saved passwords" list.  I don't think the issue reported here is that.

There is another class of authentication bugs that result in a recurring invalid-client-state error even when the credentials are correctly saved in "saved passwords", and I think this bug is another example of that.  Unfortunately we haven't yet got a handle on why this happens unexpectedly (note it *is* expected if your FxA password is reset on a different device, but it should stop once you've entered the new password into this device)

Comment 21

[mike]

(In reply to Mark Hammond [:markh] from comment #20)
Thanks for clarifying. 

This is a really nasty one. End of last week it seemed to work again for me, but since yesterday evening it's back again.

Comment 22

[promeneur]

opensuse 13.1 x86_64
FF 35.0

there is a side effect

launch FF
then
connect sync
then
the tool bat is completely displayed
see
sync_connexion_success.png
then
quit FF
launch FF
wait a few seconds
sync connexion fails
then
the tool bar is not completely displayed you can't use tools at the left end because you can't select them
see
sync_connexion_fail.png
then
forget the mail address in sync settings <=> disconnect
then
the tool bar is completely displayed

Comment 23

[promeneur]

Attachment: sync_connexion_success.png

Comment 24

[promeneur]

Attachment: sync_connexion_fail.png

Comment 25

[kiril]

As a KDE user I was using "KDE Wallet password integration add-on" (https://addons.mozilla.org/en-US/firefox/addon/kde-wallet-password-integratio/) for so long that I completely forgot about it. Just tried to disable it and now everything works just fine.

I'm not sure if the issue lies in something that this add-on is doing wrong or sync fails when passwords are stored somewhere else (passwords stored in KDE Wallet are still visible from Preferences -> Security dialog in Firefox, though), but it's definitely something.

For now I could totally live without Wallet, but I hope someone could give explanation on why sync fails with it in order to help fixing the issue (either in Firefox or in the add-on).

Comment 26

[promeneur]

opensue 13.1 x86_64
FF 35.0
addon kwallet 2.4

i confirm there is no pb without kwallet addon

Comment 27

[Martin Giger [:freaktechnik]]

(In reply to Ryan Kelly [:rfkelly] from comment #9)
> > ...and the 401 is back.
> 
> Is it back in the same persistent manner it was before? (i.e. occurring
> every time at firefox startup?)

Well, it's gone again, so that's good. However I haven't been developing extensions in the time I didn't have the issue, so it's possible it'll return, so let's hope it doesn't.

As for the KWallet issue: I have never used that extension in Firefox.

Comment 28

[bgstandaert]

I have also started getting this error on every launch of nightly in the past week or so. I have never reset my account password, but do use the master password feature. After reentering password, it actually does sync, but when you restart nightly, the same error occurs. There is nothing recent in the browser console or about:sync-log when this occurs.

Two additional things:

 - this only occurs in nightly. If I open firefox 36, it works fine.
 - After syncing, another (different) error message sometimes appears.

Comment 29

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

(In reply to bgstandaert from comment #28)
> I have also started getting this error on every launch of nightly in the
> past week or so.

Thanks for the report. Would it be possible for you to upload logs from when this happens?  See http://bit.ly/q6fBL1 for some details on how to find the logs.

Comment 30

[bgstandaert]

Attachment: error-sync-1425943015306.txt

1st sync error log

Comment 31

[bgstandaert]

Attachment: error-sync-1425942928324.txt

Comment 32

[bgstandaert]

Attachment: error-sync-1425934919461.txt

Comment 33

[bgstandaert]

Attachment: error-sync-1425934733561.txt

Comment 34

[bgstandaert]

I attached the error logs.

Comment 35

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

Thanks for the logs - this looks like a regression:

1425934703862	FirefoxAccounts	INFO	returning partial account data as the login manager is locked.
1425934733552	Sync.SyncScheduler	DEBUG	Global Score threshold hit, triggering sync.
1425934733553	Sync.Service	DEBUG	User-Agent: Firefox/39.0a1 FxSync/1.41.0.20150307030233.
1425934733553	Sync.Service	INFO	Starting sync at 2015-03-09 15:58:53
1425934733553	Sync.Service	DEBUG	In sync: should login.
1425934733555	Sync.Status	DEBUG	Status.login: success.login => error.login.reason.account
1425934733555	Sync.Status	DEBUG	Status.service: success.status_ok => error.login.failed
1425934733555	Sync.Status	DEBUG	Status.login: error.login.reason.account => error.login.reason.account

I believe that when the MP is locked we should enter a specific error state which indicates that fact, but instead we are in a normal "needs reauth" state.  I'll look at this soon.

Comment 36

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

Sadly I can't reproduce this - it works as expected for me.

To help narrow it down further, could you please flip the pref services.sync.log.appender.file.logOnSuccess to true, then restart the browser and wait for the problem to appear - you should find some success-sync-* logs as well as error-sync-logs, and upload them here?  Also, can you please clarify how you are reproducing this?  ie, before the first sync you should be prompted to unlock the master-password - do you see that prompt, and do you unlock it, or cancel that dialog?  And finally, you mentioned this works OK on 36 - is that with the same profile or a different one?

Comment 37

[dgjunk]

I also seem to be suffering this on Nightly for about the same timeframe as bgstandaert. I'll see about addind logs aswell.

Comment 38

[dgjunk]

Attachment: logs.zip

My whole weave\logs directory zipped up. I hope it is acceptable, there was 40+ files.

Comment 39

[dgjunk]

This also seems to only occur on my Nightly 64-bit on Windows. My Linux machines with Nightly seem to sync fine.

Comment 40

[bgstandaert]

(In reply to Mark Hammond [:markh] from comment #36)
> Sadly I can't reproduce this - it works as expected for me.
> 
> To help narrow it down further, could you please flip the pref
> services.sync.log.appender.file.logOnSuccess to true, then restart the
> browser and wait for the problem to appear - you should find some
> success-sync-* logs as well as error-sync-logs, and upload them here? 

I tried this, but for some reason no logs are appearing in about:sync-log. I'll try this again and see what happens.

 Also,
> can you please clarify how you are reproducing this?  ie, before the first
> sync you should be prompted to unlock the master-password - do you see that
> prompt, and do you unlock it, or cancel that dialog?  

This happens any time you enter the correct password in the master password input box. You can do either of the following to reproduce:

 - enter the password correctly on first attempt. on next sync, error appears.
 - type the password wrong repeatedly, then enter it correctly. error appears.
 - dismiss the password box, then go to a website with a saved password, bringing it up again. type password correctly. error appears.


> And finally, you
> mentioned this works OK on 36 - is that with the same profile or a different
> one?

Same profile. Also occurs on a second computer that uses a different profile.

Comment 41

[bgstandaert]

Also, the error only occurs on the first sync after entering the master password. If you dismiss the error and sync again, it works correctly.

Comment 42

[bgstandaert]

(In reply to bgstandaert from comment #41)
> Also, the error only occurs on the first sync after entering the master
> password. If you dismiss the error and sync again, it works correctly.

Actually, no, that's not correct. After the error, you are signed out from sync and have to sign in again.

Comment 43

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

I think this log is informative:

> 1426083395693	Sync.Service	INFO	Loading Weave 1.41.0

So this log the first sync after the browser started.

> 1426083395734	Sync.Service	INFO	Mozilla/5.0 (Windows NT 6.3; Win64; x64; rv:39.0) Gecko/20100101 Firefox/39.0
> 1426083395738	Sync.SyncScheduler	DEBUG	Clearing sync triggers and the global score.
> 1426083395740	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
> 1426083395740	Sync.Service	DEBUG	Caching URLs under storage user base: https://sync-177-us-west-2.sync.services.mozilla.com/1.5/15310187/
> 1426083395740	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
> 1426083395823	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok

The above is a normal Sync initialization

> 1426083398120	FirefoxAccounts	INFO	returning partial account data as the login manager is locked.

The master-password is locked.

> 1426083411280	Sync.SyncScheduler	DEBUG	Next sync in 90000 ms.

Sync is indicating it will try another Sync in 90 seconds (but I'm not sure why it jumped directly here)

> 1426083501281	Sync.Service	DEBUG	User-Agent: Firefox/39.0a1 FxSync/1.41.0.20150311030203.
> 1426083501281	Sync.Service	INFO	Starting sync at 2015-03-11 16:18:21
> 1426083501281	Sync.Service	DEBUG	In sync: should login.
> 1426083501282	Sync.Status	DEBUG	Status.login: success.login => error.login.reason.account

And we've jumped directly to the "needs to reauth" state.

I wonder if the issue is that the MP was unlocked due to something else (ie, not directly due to Sync) between when we noticed "incomplete data" and the next Sync starting (ie, I wonder if we accidentally assume that the MP will only be unlocked due to Sync requesting it rather than it being done by a non-sync request?  Either way, I'll try and dig more later.

Comment 44

[Chris Karlof [:ckarlof]]

Next step is to get some metrics on how often this is happening in the wild.

Comment 45

[promeneur]

opensuse 13.1 x86_64
FF 38.01

for a long time i did get the sync error
suddenly yesterday i get again 2 times the sync error .

each time i closed then launch again FF and the second time i didn't get the sync error .

this morning at the first launch i didn't get the sync error . we will see what will happen till this evening.

Comment 46

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

1157529(In reply to Mark Hammond [:markh] from comment #43)
> I think this log is informative:
...
> And we've jumped directly to the "needs to reauth" state.
> 
> I wonder if the issue is that the MP was unlocked due to something else (ie,
> not directly due to Sync) between when we noticed "incomplete data" and the
> next Sync starting (ie, I wonder if we accidentally assume that the MP will
> only be unlocked due to Sync requesting it rather than it being done by a
> non-sync request?  Either way, I'll try and dig more later.

That bug certainly existed and was fixed in bug 1157529, Firefox 42. Martin, are you still seeing this problem?

Comment 47

[Martin Giger [:freaktechnik]]

I haven't seen this problem in a long time, I don't think I ever encountered it again since my last comment here.

Comment 48

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

(In reply to Martin Giger [:freaktechnik] from comment #47)
> I haven't seen this problem in a long time, I don't think I ever encountered
> it again since my last comment here.

Awesome, thanks!