search

mozilla-services / syncserver

Run-Your-Own Firefox Sync Server
Mozilla Public License 2.0
1.87k stars 145 forks source link

BrowserID Verification Issues (503 Resource is not available) #55

Closed tafkam closed 9 years ago

tafkam commented 9 years ago

Hi, I'm trying to setup a selfhosted fxa+syncserver environment. I've got to the point where everything seems to work but the syncserver BrowserID verification with the fxa-auth-server.

On the frontend I'm using Apache HTTPS (self-signed) reverse proxies on different vhosts to the fxa-auth-server, fxa-content-server and syncserver. On the backend I use mysql with one database each for the syncserver and fxa-auth-server.

In my Firefox browser everything works but the actual connection to the syncserver:

1428340806611   Sync.ErrorHandler   DEBUG   Flushing file log.
1428340806613   Sync.BrowserIDManager   ERROR   Background fetch for key bundle failed: TokenServerClientServerError({"now":"2015-04-06T17:20:06.608Z","message":"Server error.","cause":"general","response_body":"{\"status\": \"error\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Resource is not available\"}]}","response_headers":{"date":"Mon, 06 Apr 2015 17:20:07 GMT","server":"PasteWSGIServer/0.5 Python/2.7.3","content-length":"109","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1428340807.15","x-timestamp":"1428340807","access-control-allow-origin":"*","connection":"close"},"response_status":503}) (resource://gre/modules/services-common/tokenserverclient.js:36:35) JS Stack trace: @tokenserverclient.js:36:36 < @browserid_identity.js:14:1 < @status.js:15:1 < SyncServiceObserver.init@sync.js:76:62 < @sync.js:459:1 < require@bootstrap.js:137:7 < @main.js:30:1 < require@bootstrap.js:137:7 < startup@bootstrap.js:21:3 < XPI_callBootstrapMethod@XPIProvider.jsm:4442:9 < XPI_startup@XPIProvider.jsm:2161:13 < callProvider@AddonManager.jsm:208:12 < _startProvider@AddonManager.jsm:667:5 < AMI_startup@AddonManager.jsm:824:9 < AMP_startup@AddonManager.jsm:2402:5 < AMC_observe@addonManager.js:55:7
1428340806614   Sync.BrowserIDManager   ERROR   Could not authenticate: TokenServerClientServerError({"now":"2015-04-06T17:20:06.608Z","message":"Server error.","cause":"general","response_body":"{\"status\": \"error\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Resource is not available\"}]}","response_headers":{"date":"Mon, 06 Apr 2015 17:20:07 GMT","server":"PasteWSGIServer/0.5 Python/2.7.3","content-length":"109","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1428340807.15","x-timestamp":"1428340807","access-control-allow-origin":"*","connection":"close"},"response_status":503}) (resource://gre/modules/services-common/tokenserverclient.js:36:35) JS Stack trace: @tokenserverclient.js:36:36 < @browserid_identity.js:14:1 < @status.js:15:1 < SyncServiceObserver.init@sync.js:76:62 < @sync.js:459:1 < require@bootstrap.js:137:7 < @main.js:30:1 < require@bootstrap.js:137:7 < startup@bootstrap.js:21:3 < XPI_callBootstrapMethod@XPIProvider.jsm:4442:9 < XPI_startup@XPIProvider.jsm:2161:13 < callProvider@AddonManager.jsm:208:12 < _startProvider@AddonManager.jsm:667:5 < AMI_startup@AddonManager.jsm:824:9 < AMP_startup@AddonManager.jsm:2402:5 < AMC_observe@addonManager.js:55:7
1428340806615   Sync.BrowserIDManager   INFO    currentAuthState returning error.login.reason.network due to previous failure
1428340806615   Sync.Status DEBUG   Status.login: error.login.reason.network => error.login.reason.network
1428340806615   Sync.Status DEBUG   Status.service: error.login.failed => error.login.failed
1428340806616   Sync.ErrorHandler   DEBUG   Log cleanup threshold time: 1427476806616
1428340806617   Sync.ErrorHandler   DEBUG   No logs to clean up.
1428340808710   Sync.BrowserIDManager   INFO    currentAuthState returning error.login.reason.network due to previous failure
1428340808710   Sync.Status DEBUG   Status.login: error.login.reason.network => error.login.reason.network
1428340808710   Sync.Status DEBUG   Status.service: error.login.failed => error.login.failed
1428340809725   Sync.BrowserIDManager   INFO    currentAuthState returning error.login.reason.network due to previous failure
1428340809725   Sync.Status DEBUG   Status.login: error.login.reason.network => error.login.reason.network
1428340809725   Sync.Status DEBUG   Status.service: error.login.failed => error.login.failed
1428340812203   Sync.BrowserIDManager   INFO    currentAuthState returning error.login.reason.network due to previous failure
1428340812203   Sync.Status DEBUG   Status.login: error.login.reason.network => error.login.reason.network
1428340812203   Sync.Status DEBUG   Status.service: error.login.failed => error.login.failed
1428340812203   Sync.ErrorHandler   DEBUG   Beginning user-triggered sync.
1428340812203   Sync.Service    DEBUG   User-Agent: Firefox/37.0.1 FxSync/1.39.0.20150402191859.
1428340812203   Sync.Service    INFO    Starting sync at 2015-04-06 19:20:12
1428340812203   Sync.Service    DEBUG   In sync: should login.
1428340812204   Sync.BrowserIDManager   INFO    currentAuthState returning error.login.reason.network due to previous failure
1428340812204   Sync.Status DEBUG   Status.login: error.login.reason.network => error.login.reason.network
1428340812204   Sync.Status DEBUG   Status.service: error.login.failed => error.login.failed
1428340812204   Sync.BrowserIDManager   INFO    currentAuthState returning error.login.reason.network due to previous failure
1428340812204   Sync.Status DEBUG   Status.login: error.login.reason.network => error.login.reason.network
1428340812204   Sync.Status DEBUG   Status.service: error.login.failed => error.login.failed
1428340812205   Sync.BrowserIDManager   INFO    Waiting for user to be verified.
1428340812205   FirefoxAccounts DEBUG   already verified
1428340812205   Sync.BrowserIDManager   INFO    Starting fetch for key bundle.
1428340812205   FirefoxAccounts DEBUG   already verified
1428340812206   Sync.BrowserIDManager   INFO    Getting an assertion from: https://syncserver.mydomain.tld/token/1.0/sync/1.5
1428340812206   FirefoxAccounts DEBUG   enter getAssertion()
1428340812206   FirefoxAccounts DEBUG   getKeyPair: already have a keyPair
1428340812206   FirefoxAccounts DEBUG    getCertificate already had one
1428340812206   FirefoxAccounts DEBUG   getAssertionFromCert
1428340812208   FirefoxAccounts DEBUG   getAssertionFromCert returning signed: true
1428340812209   Sync.BrowserIDManager   DEBUG   Getting a token
1428340812209   Common.TokenServerClient    DEBUG   Beginning BID assertion exchange: https://syncserver.mydomain.tld/token/1.0/sync/1.5
1428340812290   Common.TokenServerClient    DEBUG   Got token response: 503
1428340812290   Common.TokenServerClient    INFO    Server-reported error: {"location":"body","name":"","description":"Resource is not available"}
1428340812290   Sync.BrowserIDManager   ERROR   Non-authentication error in _fetchTokenForUser: TokenServerClientServerError({"now":"2015-04-06T17:20:12.290Z","message":"Server error.","cause":"general","response_body":"{\"status\": \"error\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Resource is not available\"}]}","response_headers":{"date":"Mon, 06 Apr 2015 17:20:12 GMT","server":"PasteWSGIServer/0.5 Python/2.7.3","content-length":"109","content-type":"application/json; charset=UTF-8","x-weave-timestamp":"1428340812.83","x-timestamp":"1428340812","access-control-allow-origin":"*","connection":"close"},"response_status":503}) (resource://gre/modules/services-common/tokenserverclient.js:36:35) JS Stack trace: @tokenserverclient.js:36:36 < @browserid_identity.js:14:1 < @status.js:15:1 < SyncServiceObserver.init@sync.js:76:62 < @sync.js:459:1 < require@bootstrap.js:137:7 < @main.js:30:1 < require@bootstrap.js:137:7 < startup@bootstrap.js:21:3 < XPI_callBootstrapMethod@XPIProvider.jsm:4442:9 < XPI_startup@XPIProvider.jsm:2161:13 < callProvider@AddonManager.jsm:208:12 < _startProvider@AddonManager.jsm:667:5 < AMI_startup@AddonManager.jsm:824:9 < AMP_startup@AddonManager.jsm:2402:5 < AMC_observe@addonManager.js:55:7
1428340812292   Sync.Status DEBUG   Status.login: error.login.reason.network => error.login.reason.network
1428340812292   Sync.Status DEBUG   Status.service: error.login.failed => error.login.failed
1428340812292   Sync.SyncScheduler  DEBUG   Clearing sync triggers and the global score.
1428340812292   Sync.SyncScheduler  DEBUG   Next sync in 3600000 ms.

On syncserver the log shows the following:

INFO:mozsvc.metrics:{"code": 503, "request_time": 0.0009009838104248047, "remoteAddressChain": ["<my client ip>", "127.0.0.1"], "agent": "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:37.0) Gecko/20100101 Firefox/37.0", "token.assertion.connection_error": 1, "token.assertion.verify_failure": 1, "tokenserver.assertion.verify": 0.00037097930908203125, "path": "https://syncserver.mydomain.tld/token/1.0/sync/1.5", "method": "GET"}

Plainly accessing https://syncserver.mydomain.tld/token/1.0/sync/1.5 with curl or firefox throws a expected 401 error:

INFO:mozsvc.metrics:{"code": 401, "request_time": 0.0005269050598144531, "remoteAddressChain": ["46.244.245.183"], "agent": "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:37.0) Gecko/20100101 Firefox/37.0", "path": "https://syncserver.mydomain.tld/token/1.0/sync/1.5", "method": "GET"}

I've tried both the local and remote verifiers (tried public url: https://authserver.mydomain.tld/.well-known/browserid and http://127.0.0.1:9000/.well-known/browserid without SSL) in the [browserid] section. audiences is set to *.mydomain.tld

Any clue on what I'm missing, or how to patch the tokenserver? ;-)

Best Regards

tafkam commented 9 years ago

I followed the tokenserver debugging steps from https://github.com/mozilla-services/syncserver/issues/52 and it turns out it was an SSL issue.

[Mon Apr 06 23:17:46 2015] [error] INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): authserver.mydomain.tld
[Mon Apr 06 23:17:46 2015] [error] ConnectionError(u"Failed to GET https://authserver.mydomain.tld/.well-known/browserid. Reason: hostname 'authserver.mydomain.tld' doesn't match u'unrelated-vhost.mydomain.tld",)

Changing the order of the vhosts in the Apache config did the trick, so the right certificate would be verified.

rfk commented 9 years ago

I'm glad you got this working. I wonder if we could fix this by e.g. including a more recent version of requests or other dependencies to get automagically handling of certificate alt names.