Authentication fails with cause "invalid-generation" with commit 72d618f

[julienschmidt]

The latest commit seems to have broken authentication on my syncserver.

From about:sync-log:

1495882087010   Common.TokenServerClient    DEBUG   Beginning BID assertion exchange: https://XXX/token/1.0/sync/1.5
1495882087011   Services.Common.RESTRequest DEBUG   GET request to https://XXX/token/1.0/sync/1.5
1495882087011   Services.Common.RESTRequest TRACE   HTTP Header accept: application/json
1495882087011   Services.Common.RESTRequest TRACE   HTTP Header authorization: ***** (suppressed)
1495882087011   Services.Common.RESTRequest TRACE   HTTP Header x-client-state: XXX
1495882087020   FirefoxAccounts DEBUG   writing secure storage: ["kA","kB"]
1495882088114   Services.Common.RESTRequest TRACE   onStartRequest: GET https://XXX/token/1.0/sync/1.5
1495882088115   Services.Common.RESTRequest TRACE   Channel for GET https://XXX/token/1.0/sync/1.5 returned status code 0
1495882088115   Services.Common.RESTRequest DEBUG   GET https://XXX/token/1.0/sync/1.5 401
1495882088115   Services.Common.RESTRequest TRACE   GET body: {"status": "invalid-generation", "errors": [{"location": "body", "name": "", "description": "Unauthorized"}]}
1495882088115   Common.TokenServerClient    DEBUG   Got token response: 401
1495882088115   Common.TokenServerClient    INFO    Server-reported error: {"location":"body","name":"","description":"Unauthorized"}
1495882088116   Sync.BrowserIDManager   ERROR   Authentication error in _fetchTokenForUser: {"details":{"now":"2017-05-27T10:48:08.115Z","message":"Authentication failed.","cause":"invalid-generation","response_body":"{\"status\": \"invalid-generation\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Unauthorized\"}]}","response_headers":{"server":"nginx","date":"Sat, 27 May 2017 10:48:08 GMT","content-type":"application/json; charset=UTF-8","content-length":"109","x-weave-timestamp":"1495882088.41","x-timestamp":"1495882088","x-firefox-spdy":"h2"},"response_status":401,"name":"TokenServerClientServerError"},"source":"tokenserver"}
1495882088117   Sync.Status DEBUG   Status.login: success.login => error.login.reason.account
1495882088117   Sync.Status DEBUG   Status.service: success.status_ok => error.login.failed
1495882088123   Sync.BrowserIDManager   ERROR   Failed to fetch a token for authentication: {"details":{"now":"2017-05-27T10:48:08.115Z","message":"Authentication failed.","cause":"invalid-generation","response_body":"{\"status\": \"invalid-generation\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Unauthorized\"}]}","response_headers":{"server":"nginx","date":"Sat, 27 May 2017 10:48:08 GMT","content-type":"application/json; charset=UTF-8","content-length":"109","x-weave-timestamp":"1495882088.41","x-timestamp":"1495882088","x-firefox-spdy":"h2"},"response_status":401,"name":"TokenServerClientServerError"},"source":"tokenserver"}
1495882088527   Sync.Resource   DEBUG   mesg: GET fail 401 https://XXX/storage/1.5/1/info/collections
1495882088527   Sync.Resource   DEBUG   GET fail 401 https://XXX/storage/1.5/1/info/collections
1495882088528   Sync.Resource   WARN    GET request to https://XXX/storage/1.5/1/info/collections failed with status 401
1495882088529   Sync.Service    INFO    Logging out
1495882088532   browserwindow.syncui    DEBUG   observed: weave:service:logout:finish
1495882088533   browserwindow.syncui    DEBUG   observed: weave:service:logout:finish
1495882088533   browserwindow.syncui    DEBUG   observed: weave:service:logout:finish
1495882088534   Sync.SyncScheduler  DEBUG   Next sync in 3600000 ms.
1495882088534   Sync.ErrorHandler   INFO    Got 401 response; resetting clusterURL.
1495882088534   Sync.ErrorHandler   DEBUG   New mid-sync 401 failure. Making a note.
1495882088534   Sync.ErrorHandler   INFO    Attempting to schedule another sync.
1495882088534   Sync.Service    ERROR   Aborting sync: failed to get collections.

The client is Firefox/53.0.3 (Intel Mac OS X 10.12) FxSync/1.55.0.20170518000419.desktop. The client prompts to reauthenticate, then produces the error above and immediately asks to reauthenticate again.

The server is running via nginx+uwsgi on Debian Jessie.

If I revert back to commit 7fe5c0f everything works again and if I then checkout 72d618f again, I get the same error again, so it must be commit 72d618f which breaks it.

[rfk]

Hi @julienschmidt, thanks for the report and the debugging! I don't have a good theory for why that commit should break a working setup, but there's a couple of things we can try. My two top suspects are either the switch to a local verifier here:

https://github.com/mozilla-services/syncserver/commit/72d618f3ee6e907f43c8a5b0d53182b3b293b996#diff-12895ac55aeefd69b77de334ec568c86R103

Or the removal of the scan here:

https://github.com/mozilla-services/syncserver/commit/72d618f3ee6e907f43c8a5b0d53182b3b293b996#diff-12895ac55aeefd69b77de334ec568c86L114

I'm going to see if I can reproduce, but in the meantime I've made a branch with these two changes reverted. If you get a chance can you please try out this branch and see if it fixes the issue?

https://github.com/mozilla-services/syncserver/tree/debug-i91

[rfk]

My two top suspects are either the switch to a local verifier here:

Looks like it's almost certainly this; the LocalVerifier class does not support the extended IDP claims that we use for tracking generation number. That's fine if you always use LocalVerifier, but switching from one that does support extended claims to one that doesn't will cause the above error.

I think I have an older branch supporting extended claims around here somewhere, let me see if I can find it...

[rfk]

the LocalVerifier class does not support the extended IDP claims that we use for tracking generation number.

I have a tokenserver branch that should allow using the LocalVerifier class here:

https://github.com/mozilla-services/tokenserver/pull/108

And I've updated the above 'debug-i91' branch to use it by default. @julienschmidt please let me know if that branch works for you.

[julienschmidt]

The debug-i91 branch seems to fix it. I can sync without any problems with it.

[julienschmidt]

I also commented out syncserver/__init__.py#L117 and it still works. The fix must be in the updated tokenserver.

[rfk]

Thanks @julienschmidt, should be fixed as of https://github.com/mozilla-services/syncserver/pull/93

[julienschmidt]

Thanks for the quick fix!

[BobVul]

For anyone still encountering this issue after the fixed version, try a checkout of 7fe5c0f, sync a device, and then going on to master@HEAD.

Just happened to me after an update from a much older version. Looks like the intermediate step is required.

[chrismyers81]

Since I'm not entirely familiar with what you're referring to, what do I need to do to get my server fixed? I'm on the latest code as of this evening, but am still getting that "invalid-generation" error on some of my devices.

1502765307959 Sync.Status INFO Resetting Status. 1502765307959 Sync.Status DEBUG Status.service: error.sync.failed => success.status_ok 1502765307961 FirefoxAccounts DEBUG already verified 1502765307962 Sync.BrowserIDManager INFO Getting an assertion from: http://servername:5000/token/1.0/sync/1.5 1502765307962 FirefoxAccounts DEBUG enter getAssertion() 1502765307964 browserwindow.syncui DEBUG _loginFailed has sync state=success.login 1502765307967 FirefoxAccounts DEBUG getKeypairAndCertificate: already have keyPair and certificate 1502765307967 FirefoxAccounts DEBUG getAssertionFromCert 1502765307969 browserwindow.syncui DEBUG _loginFailed has sync state=success.login 1502765307980 FirefoxAccounts DEBUG getAssertionFromCert returning signed: true 1502765307981 Sync.BrowserIDManager DEBUG Getting a token 1502765307983 Common.TokenServerClient DEBUG Beginning BID assertion exchange: http://servername:5000/token/1.0/sync/1.5 1502765308767 Common.TokenServerClient DEBUG Got token response: 401 1502765308767 Sync.RESTResponse TRACE Processing response headers. 1502765308768 Common.TokenServerClient INFO Server-reported error: {"location":"body","name":"","description":"Unauthorized"} 1502765308769 Sync.BrowserIDManager ERROR Authentication error in _fetchTokenForUser: {"details":{"now":"2017-08-15T02:48:28.768Z","message":"Authentication failed.","cause":"invalid-generation","response_body":"{\"status\": \"invalid-generation\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Unauthorized\"}]}","response_headers":{"server":"gunicorn/19.6.0","date":"Tue, 15 Aug 2017 02:46:09 GMT","connection":"close","content-length":"109","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1502765169.87","x-timestamp":"1502765169"},"response_status":401,"name":"TokenServerClientServerError"}} 1502765308770 Sync.Status DEBUG Status.login: success.login => error.login.reason.account 1502765308770 Sync.Status DEBUG Status.service: success.status_ok => error.login.failed 1502765308771 Sync.BrowserIDManager INFO Failed to fetch the cluster URL: {"details":{"now":"2017-08-15T02:48:28.768Z","message":"Authentication failed.","cause":"invalid-generation","response_body":"{\"status\": \"invalid-generation\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Unauthorized\"}]}","response_headers":{"server":"gunicorn/19.6.0","date":"Tue, 15 Aug 2017 02:46:09 GMT","connection":"close","content-length":"109","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1502765169.87","x-timestamp":"1502765169"},"response_status":401,"name":"TokenServerClientServerError"}} 1502765308771 Sync.Service DEBUG Cluster value = null 1502765308771 Sync.Status DEBUG Status.sync: success.sync => error.sync.reason.no_node_found 1502765308771 Sync.Status DEBUG Status.service: error.login.failed => error.sync.failed 1502765308771 Sync.Synchronizer INFO No cluster URL found. Cannot sync. 1502765308774 browserwindow.syncui DEBUG observed: weave:service:sync:error 1502765308774 browserwindow.syncui DEBUG onActivityStop with numActive: 1 1502765308777 Sync.SyncScheduler DEBUG Next sync in 3600000 ms. 1502765308778 Sync.ErrorHandler ERROR Sync encountered an error

[rfk]

@chrismyers81 one thing that may be worth trying, is just signing out and signing back in on the devices that are given this error.

If that doesn't help, what @BobVul is suggeting above is:

• git checkout 7fe5c0f in this repo, restart your server, and sync your devices
• Then git checkout master in this repo, restart your server, and see if everything is now syncing as expected

[BobVul]

@chrismyers81 rfk beat me to it, but to add to his comment - you'll want to go through the normal update process for each checkout, which means backing up syncserver.ini (git stash before/git stash pop after) and a make build after each checkout.

That's what worked for me.

[rfk]

and a make build after each checkout.

Oh yes, thanks - the make build part is pretty important! 😁

[compujuckel]

While commit 7fe5c0f works, checking out master and building afterwards does not help for Fennec Nightly (Android) and still results in invalid-generation errors in logcat. Latest Nightly on Desktop syncs without problems.

[rfk]

You could also use the "nuclear option" of just clearing the server db and starting from scratch :-(

[sbraz]

I had the same issue after upgrading from 123de6d to 4f4787e. I deleted the database and it seems to be work now.

[yol]

I just had the same problem, but for me the root cause was that make build did not update PyBrowserID to the correct version for some reason. make clean; make build fixed it.

[chrismyers81]

I'm sorry that it's taken me so long to respond back, life's been a bit ridiculous lately and today is the first chance I've had at this.

Since I last looked at this, I've upgraded a new VM running Debian Stretch, and can't get it to build at all on there, so .... more digging elsewhere for now :)

[chrismyers81]

Ok, I figured out the issues that I was having and the software built and installed now, and at least at this point, I'm not having this issue anymore (even with the same database as before.)