search

mozilla-services / syncserver

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

Problem with BrowserID verifier (cannot sync) #65

Closed ghost closed 9 years ago

ghost commented 9 years ago 
1447629550355   Sync.BrowserIDManager   INFO    Waiting for user to be verified.
1447629550355   FirefoxAccounts DEBUG   already verified
1447629550356   Sync.BrowserIDManager   INFO    Starting fetch for key bundle.
1447629550356   FirefoxAccounts DEBUG   already verified
1447629550356   Sync.BrowserIDManager   INFO    Getting an assertion from: https://DOMAIN/ffsync/token/1.0/sync/1.5
1447629550357   FirefoxAccounts DEBUG   enter getAssertion()
1447629550360   FirefoxAccounts DEBUG   getKeypairAndCertificate: already have keyPair and certificate
1447629550360   FirefoxAccounts DEBUG   getAssertionFromCert
1447629550363   FirefoxAccounts DEBUG   getAssertionFromCert returning signed: true
1447629550364   Sync.BrowserIDManager   DEBUG   Getting a token
1447629550365   Common.TokenServerClient    DEBUG   Beginning BID assertion exchange: https://DOMAIN/ffsync/token/1.0/sync/1.5
1447629550631   Common.TokenServerClient    DEBUG   Got token response: 502
1447629550631   Sync.RESTResponse   TRACE   Processing response headers.
1447629550631   Common.TokenServerClient    WARN    Did not receive JSON response. Misconfigured server?
1447629550631   Common.TokenServerClient    DEBUG   Content-Type: text/html
1447629550631   Common.TokenServerClient    DEBUG   Body: <html>
<head><title>502 Bad Gateway</title></head>
<body bgcolor="white">
<center><h1>502 Bad Gateway</h1></center>
<hr><center>nginx/1.6.2</center>
</body>
</html>

1447629550632   Sync.BrowserIDManager   ERROR   Non-authentication error in _fetchTokenForUser: TokenServerClientServerError({"now":"2015-11-15T23:19:10.632Z","message":"Non-JSON response.","cause":"malformed-response","response_body":"<html>\r\n<head><title>502 Bad Gateway</title></head>\r\n<body bgcolor=\"white\">\r\n<center><h1>502 Bad Gateway</h1></center>\r\n<hr><center>nginx/1.6.2</center>\r\n</body>\r\n</html>\r\n","response_headers":{"server":"nginx/1.6.2","date":"Sun, 15 Nov 2015 23:19:03 GMT","content-type":"text/html","content-length":"172","connection":"keep-alive"},"response_status":502}) (resource://gre/modules/services-common/tokenserverclient.js:36:36) 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:4774:9 < XPI_startup@XPIProvider.jsm:2484:13 < callProvider@AddonManager.jsm:221:12 < _startProvider@AddonManager.jsm:828:5 < AMI_startup@AddonManager.jsm:999:9 < AMP_startup@AddonManager.jsm:2672:5 < AMC_observe@addonManager.js:58:7
1447629550634   Sync.Status DEBUG   Status.login: error.login.reason.network => error.login.reason.network
1447629550634   Sync.Status DEBUG   Status.service: error.login.failed => error.login.failed
1447629550634   browserwindow.syncui    DEBUG   observed: weave:ui:login:error
1447629550635   browserwindow.syncui    DEBUG   onLoginError: login=error.login.reason.network, sync=success.sync
1447629550635   browserwindow.syncui    DEBUG   _loginFailed has sync state=error.login.reason.network
1447629550639   Sync.BrowserIDManager   ERROR   Background fetch for key bundle failed: TokenServerClientServerError({"now":"2015-11-15T23:19:10.632Z","message":"Non-JSON response.","cause":"malformed-response","response_body":"<html>\r\n<head><title>502 Bad Gateway</title></head>\r\n<body bgcolor=\"white\">\r\n<center><h1>502 Bad Gateway</h1></center>\r\n<hr><center>nginx/1.6.2</center>\r\n</body>\r\n</html>\r\n","response_headers":{"server":"nginx/1.6.2","date":"Sun, 15 Nov 2015 23:19:03 GMT","content-type":"text/html","content-length":"172","connection":"keep-alive"},"response_status":502}) (resource://gre/modules/services-common/tokenserverclient.js:36:36) 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:4774:9 < XPI_startup@XPIProvider.jsm:2484:13 < callProvider@AddonManager.jsm:221:12 < _startProvider@AddonManager.jsm:828:5 < AMI_startup@AddonManager.jsm:999:9 < AMP_startup@AddonManager.jsm:2672:5 < AMC_observe@addonManager.js:58:7
1447629550642   Sync.BrowserIDManager   ERROR   Could not authenticate: TokenServerClientServerError({"now":"2015-11-15T23:19:10.632Z","message":"Non-JSON response.","cause":"malformed-response","response_body":"<html>\r\n<head><title>502 Bad Gateway</title></head>\r\n<body bgcolor=\"white\">\r\n<center><h1>502 Bad Gateway</h1></center>\r\n<hr><center>nginx/1.6.2</center>\r\n</body>\r\n</html>\r\n","response_headers":{"server":"nginx/1.6.2","date":"Sun, 15 Nov 2015 23:19:03 GMT","content-type":"text/html","content-length":"172","connection":"keep-alive"},"response_status":502}) (resource://gre/modules/services-common/tokenserverclient.js:36:36) 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:4774:9 < XPI_startup@XPIProvider.jsm:2484:13 < callProvider@AddonManager.jsm:221:12 < _startProvider@AddonManager.jsm:828:5 < AMI_startup@AddonManager.jsm:999:9 < AMP_startup@AddonManager.jsm:2672:5 < AMC_observe@addonManager.js:58:7
1447629550644   FirefoxAccounts DEBUG   FxAccountsProfileClient: Requested profile
1447629550645   FirefoxAccounts DEBUG   getOAuthToken enter
1447629550647   FirefoxAccounts TRACE   getCachedToken returning cached token
1447629550647   FirefoxAccounts DEBUG   getOAuthToken returning a cached token
1447629550651   browserwindow.syncui    DEBUG   observed: weave:service:login:error
1447629550651   browserwindow.syncui    DEBUG   onActivityStop with numActive: 1
1447629550651   browserwindow.syncui    DEBUG   _loginFailed has sync state=error.login.reason.network
1447629550651   Sync.SyncScheduler  DEBUG   Clearing sync triggers and the global score.
1447629550652   Sync.SyncScheduler  DEBUG   Next sync in 3600000 ms.
1447629550652   Sync.ErrorHandler   ERROR   Sync encountered a login error

Don't know how to fix this. I'm using a Firefox account in combination with my own 1.5 Sync server which worked fine on my previous VPS. The bad gateway error seems to be from my webserver, but when I go to the URL that I set in the about:config it tells me "it works" and i'm not authorised.

rfk commented 9 years ago

This may be a connectivity issue between your server and the hosted verifier. If you're not already, try uncommenting the section at the bottom of syncserver.ini that talks about using a local verifier.

It looks the above are all client-side logs, are any server-side logs generated when this error occurs?

ghost commented 9 years ago

I disabled iptables but the problem still persists. The log file /var/log/ffsync.log does not contain anything (despite being set in the service script). I want to use the BrowserID instance running at Mozilla, what settings should I use in the synserver.ini file?

rfk commented 9 years ago

I want to use the BrowserID instance running at Mozilla

That should happen by default. Can you successfully make outbound connections to https://verifier.accounts.firefox.com/ from your instance?

ghost commented 9 years ago 
wget https://verifier.accounts.firefox.com/                        --2015-11-16 10:46:53--  https://verifier.accounts.firefox.com/
Resolving verifier.accounts.firefox.com (verifier.accounts.firefox.com)... 54.244.29.62, 54.218.68.106
Connecting to verifier.accounts.firefox.com (verifier.accounts.firefox.com)|54.244.29.62|:443... connected.
HTTP request sent, awaiting response... 405 Method Not Allowed
2015-11-16 10:46:54 ERROR 405: Method Not Allowed.

Seems to work fine, any suggestions to run firefox sync in console instead of service?

ghost commented 9 years ago

Ok, I feel fooled by Firefox. The service was never starting in the first place, and I think I got served an cached response of "it works". After rebuilding the project and starting it manually it works. Sorry for the waste of time :S

rfk commented 9 years ago

no worries, glad you were able to get it working!