1112962 - Sync fails to fetch keys, reports "Invalid authentication token in request signature"

Status: RESOLVED WORKSFORME

(Cloud Services :: General, defect)

Description

[Mike Nolan [:nolski]]

Attachment: sync-logs.zip

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:36.0) Gecko/20100101 Firefox/36.0
Build ID: 20141217004003

Steps to reproduce:

I can't remember when this started happening but it was fairly recent. I think after updating Firefox Aurora. I have recently been using bugzilla and other Mozilla login services which may or may not have affected this issue.


Actual results:

Upon startup a yellow banner says "Sync encountered an error while syncing: Incorrect account name or password. Sync will automatically retry this action." With a button redirecting to preferences.


Expected results:

I am automatically logged into Sync.

Comment 1

[Ryan Kelly [:rfkelly]]

Mike reports in IRC that disconnecting and reconnecting to sync did not resolve this issue.

Comment 2

[Ryan Kelly [:rfkelly]]

The bit I find most suspicious from these logs is:

  1418502282415	FirefoxAccounts	ERROR	error GETing /account/keys: {"code":401,"errno":110,"error":"Unauthorized","message":"Invalid authentication token in request signature","info":"https://github.com/mozilla/fxa-auth-server/blob/master/docs/api.md#response-format"}

In theory, an errno 110 should only occur if you try to use a keyFetchToken that does not exist in the server db.  At a guess, I'd say it's trying to use a keyFetchToken that has already been used (and hence has been deleted from the DB).

The earliest occurrence of this I can find in the logs is 13th december, although i see something on the 9th of december that says just:

  1418139791206	Sync.BrowserIDManager	ERROR	Background fetch for key bundle failed: null: null
  1418139791206	Sync.BrowserIDManager	ERROR	Could not authenticate: null: null

And may be the same or a related issue.

Comment 3

[Ryan Kelly [:rfkelly]]

I am really surprised that disconnecting and re-connecting to sync did not resolve this, by flushing all the account state.

Mike, if you get a chance could you please try creating a new profile and set up sync in there?  I'm hoping it will work in a clean profile, which will help us narrow down to what the bug might be.

Comment 4

[Mike Nolan [:nolski]]

I created a new profile using my personal gmail and the issue happened again after restarting.

Comment 5

[Ryan Kelly [:rfkelly]]

Sorry, I should have been much more explicit: try creating a new client-side firefox profile, not a new server-side account, in order to clear out any weird state that firefox might have recorded internally in your default profile.

Details on using firefox profiles are at https://support.mozilla.org/en-US/kb/profile-manager-create-and-remove-firefox-profiles

Comment 6

[Dan Callahan [:callahad]]

User "Rolcol" in IRC is reporting the same: "At launch, I keep getting the yellow bar at the bottom of Firefox telling me: "Sync encountered an error while syncing: Incorrect account name or password.  Sync will automatically retry this action."  My email/password credentials have not changed.  When I log back in, everything is fine until Firefox is exited and reopened."

Comment 7

[Rolcol]

Attachment: rolcol-about_sync-log-error-1418544839593.txt

This is the last log before callahad suggested that I disconnect, restart, then reconnect.  Sync began working like normal after that.

Comment 8

[Rolcol]

Attachment: about_sync-log_logs.zip

Ok, I lied.  That other error log was from before I went to IRC looking for help.  This attachment is all the logs.

Comment 9

[Dan Callahan [:callahad]]

For the record, creating a new profile also appeared to work. Rolcol noted that several other clients were syncing without difficulty, so it was something profile-specific. This was on OS X 10.10.1, Fx Beta 35.0b4.

Comment 10

[Mike Nolan [:nolski]]

Creating a new profile also worked for me but when switching back to my current profile the issue persisted.

Comment 11

[Mike Nolan [:nolski]]

Also for the record, when I started with the new profile it booted into current firefox, not the aroura build that I normally use (it didn't seem to give a choice?).

Comment 12

[Ryan Kelly [:rfkelly]]

Mike, perhaps the extra explicit step that :callahad suggested above might work for you, if you didn't try it already: (1) disconnect from sync, (2) shutdown and restart firefox, (3) connect to sync again.  I'm not sure if you were restarting firefox in-between when you tried this last time.

Comment 13

[Ryan Kelly [:rfkelly]]

Also FWIW, it looks like :Rolcol's error was "invalid-client-state" which is a little different to the one that :nolski was seeing.  They could easily have the same underlying cause, but could also easily not.

Comment 14

[Rolcol]

Attachment: syncprefs-nodisconnectbtn.png

This may be of interest:  there isn't a "disconnect" button when this bug pops up; there's just a "Forget this Email" link.  

Also, I just hit this bug on a Windows client.

Comment 15

[Ryan Kelly [:rfkelly]]

Rolcol, have you seen this error re-appear on any clients that you fixed with the disconnect/restart/reconnect hack, or is it just slowly working its way around all the machines connected to your account?

Comment 16

[Ryan Kelly [:rfkelly]]

I *think* that "forget this email" should do the same thing as "disconnect" when in this state, but thanks for pointing it out explicitly, I did not realize the UI changed like that.

Comment 17

[Mike Nolan [:nolski]]

:rfkelly Just to keep this thread up to date I disconnected from sync (forget this account)->closed firefox->opened firefox->reconnected->closed firefox->opened firefox and the issue showed up again.

Comment 18

[Rolcol]

I have not seen it reappear yet, no.  Once I have done the disconnection dance, the clients have worked again.  It seems to be working its way around, but my Android devices are fine so far.  

I'm using the beta branch across most of my synced Firefox profiles.  I do have an Aurora client on Android connected in.  Nightly is installed on my Nexus 7, but I'm not near it to confirm whether or not it's connected.

Comment 19

[Chris Karlof [:ckarlof]]

Do any of you have Firefox set to delete your passwords on exit?

Comment 20

[Chris Karlof [:ckarlof]]

Bug 1102184

Comment 21

[Rolcol]

I do not use the "Remember passwords for sites" feature, it's unchecked.  History is set to the default of "Remember History".

Comment 22

[Chris Karlof [:ckarlof]]

FxA uses the password manager to store the Sync credentials. Rolcol, can you verify that you have a kB value stored in your password manager? You can see the values via "Saved Passwords" on the Security Preferences pane.

Comment 23

[Rolcol]

Yes, I do have a kB value, but this is on a profile that I have already disconnected and reconnected.  I made a backup of another profile that had the same syncing problem.  If you need me to check that one, I will.

Comment 24

[Ryan Kelly [:rfkelly]]

Let's spin :Rolcol's issue out into a separate bug, since it seems to present different symptoms.  I filed Bug 1115215 for this purpose.

Comment 25

[Ryan Kelly [:rfkelly]]

Regrouping on :nolski's error in this bug, here's the current status:

  * Firefox fails to connect to sync with the error "Invalid authentication token in request signature".

  * Disconnecting and reconnecting to sync does not fix the problem.

  * But connecting to the same account in a clean profile works correctly.

So I'm wondering if there's some cached state in the profile that is not being cleared correctly, even in the event of a disconnect.  The only way to get an "invalid authentication token" error is to (a) use a token that has never existing, or (b) try to re-use a token that has already been used.

Comment 26

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

(In reply to Ryan Kelly [:rfkelly] from comment #25)
> So I'm wondering if there's some cached state in the profile that is not
> being cleared correctly, even in the event of a disconnect.  The only way to
> get an "invalid authentication token" error is to (a) use a token that has
> never existing, or (b) try to re-use a token that has already been used.

That sounds a little like the data not being deleted from the login manager.  :nolski, do you happen to have an addon installed that provides login manager or password manager related functionality?

(If for some reason something else is failing in or around our login manager, we could possibly make this more robust by storing a unique ID in both signedInUser.json and the login manager and insisting they match - at the moment I think we would happily reuse "stale" info from the login manager so long as the email addresses match)

Comment 27

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

FTR, the problems reported by Mike are almost certainly due to the [e-mail] addon - see bug 1128402. Attempting to save the FxA credentials are failing which explains why we see the reauth prompt, and why "forgetting" and starting from scratch still fails.  Rolcol's issues look different.

Comment 28

[Mike Nolan [:nolski]]

Sorry for not replying to this earlier. :markh is correct in that the issues were due to the macos-keychain issue and uninstalling that solved the issue.

Comment 29

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

Thanks everyone for following up on this. Given :nolski's issue is bug 1128402 and :RolCol's issue had bug 1115215 filed for it, I'm going to close this as WFM (not sure WFM really is the right resolution in this scenario, but it seems better than INVALID or duping it, and it doesn't really matter :)