non-helpful error message when allow_new_user=false

[azrdev]

I struggled to get my own syncserver running: It would login to mozilla's FxA, I'd get a confirmation mail, but then such error got logged which didn't tell me what's wrong:

1492634279595   Services.Common.RESTRequest TRACE   GET body: {"status": "invalid-credentials", "errors": [{"location": "body", "name": "", "description": "Unauthorized"}]}
1492634279595   Common.TokenServerClient    DEBUG   Got token response: 401
1492634279596   Common.TokenServerClient    INFO    Server-reported error: {"location":"body","name":"","description":"Unauthorized"}
1492634279599   Sync.BrowserIDManager   ERROR   Authentication error in _fetchTokenForUser: {"details":{"now":"2017-04-19T20:37:59.596Z","message":"Authentication failed.","cause":"invalid-credentials","response_body":"{\"status\": \"invalid-credentials\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Unauthorized\"}]}","response_headers":{"date":"Wed, 19 Apr 2017 20:37:59 GMT","server":"gunicorn/19.6.0","x-content-type-options":"nosniff","x-xss-protection":"1; mode=block","x-frame-options":"DENY","strict-transport-security":"max-age=15768000","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1492634279.57","x-timestamp":"1492634279","x-clacks-overhead":"GNU Terry Pratchett","vary":"Accept-Encoding","content-encoding":"gzip","connection":"close","transfer-encoding":"chunked"},"response_status":401,"name":"TokenServerClientServerError"},"source":"tokenserver"}
1492634279600   Sync.Status DEBUG   Status.login: success.login => error.login.reason.account
1492634279600   Sync.Status DEBUG   Status.service: success.status_ok => error.login.failed
1492634279600   Sync.BrowserIDManager   ERROR   Background fetch for key bundle failed: {"details":{"now":"2017-04-19T20:37:59.596Z","message":"Authentication failed.","cause":"invalid-credentials","response_body":"{\"status\": \"invalid-credentials\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Unauthorized\"}]}","response_headers":{"date":"Wed, 19 Apr 2017 20:37:59 GMT","server":"gunicorn/19.6.0","x-content-type-options":"nosniff","x-xss-protection":"1; mode=block","x-frame-options":"DENY","strict-transport-security":"max-age=15768000","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1492634279.57","x-timestamp":"1492634279","x-clacks-overhead":"GNU Terry Pratchett","vary":"Accept-Encoding","content-encoding":"gzip","connection":"close","transfer-encoding":"chunked"},"response_status":401,"name":"TokenServerClientServerError"},"source":"tokenserver"}
1492634279603   Sync.BrowserIDManager   ERROR   Could not authenticate: {"details":{"now":"2017-04-19T20:37:59.596Z","message":"Authentication failed.","cause":"invalid-credentials","response_body":"{\"status\": \"invalid-credentials\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Unauthorized\"}]}","response_headers":{"date":"Wed, 19 Apr 2017 20:37:59 GMT","server":"gunicorn/19.6.0","x-content-type-options":"nosniff","x-xss-protection":"1; mode=block","x-frame-options":"DENY","strict-transport-security":"max-age=15768000","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1492634279.57","x-timestamp":"1492634279","x-clacks-overhead":"GNU Terry Pratchett","vary":"Accept-Encoding","content-encoding":"gzip","connection":"close","transfer-encoding":"chunked"},"response_status":401,"name":"TokenServerClientServerError"},"source":"tokenserver"}
1492634279604   browserwindow.syncui    DEBUG   observed: weave:service:login:error
1492634279605   browserwindow.syncui    DEBUG   onLoginError: login=error.login.reason.account, sync=success.sync
1492634279606   Sync.SyncScheduler  DEBUG   Clearing sync triggers and the global score.
1492634279607   Sync.ErrorHandler   ERROR   Sync encountered a login error
1492634279608   Sync.Service    DEBUG   Exception calling WrappedLock: {"details":{"now":"2017-04-19T20:37:59.596Z","message":"Authentication failed.","cause":"invalid-credentials","response_body":"{\"status\": \"invalid-credentials\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Unauthorized\"}]}","response_headers":{"date":"Wed, 19 Apr 2017 20:37:59 GMT","server":"gunicorn/19.6.0","x-content-type-options":"nosniff","x-xss-protection":"1; mode=block","x-frame-options":"DENY","strict-transport-security":"max-age=15768000","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1492634279.57","x-timestamp":"1492634279","x-clacks-overhead":"GNU Terry Pratchett","vary":"Accept-Encoding","content-encoding":"gzip","connection":"close","transfer-encoding":"chunked"},"response_status":401,"name":"TokenServerClientServerError"},"source":"tokenserver"}
1492634279608   Sync.Service    DEBUG   Not syncing: login returned false.
1492634279615   browserwindow.syncui    DEBUG   _loginFailed has sync state=error.login.reason.account
1492634279617   browserwindow.syncui    DEBUG   _loginFailed has sync state=error.login.reason.account

Turns out, I had allow_new_users = false in syncserver.ini. Would be nice if the message were more telling.

[rfk]

Thanks for the report, it seems simple enough for us to add a new error code for this case, which would show up instead of "invalid-credentials" in the log above. I opened a PR here: https://github.com/mozilla-services/tokenserver/pull/106

I doubt we can justify working on any UI to expose this error, since we only expect it to happen in rare circumstances in a mis-configured self-hosted setup, but at least a dedicated error code will make it easier to understand from the debug log.

[rfk]

Fixed in https://github.com/mozilla-services/tokenserver/pull/106, thanks again!