On 04/09/2014 3:51 PM, Ryan Kelly wrote:
On 4/09/2014 2:25 PM, Reuben Farrelly wrote:No joy, I'm afraid. I uncommented those options in my syncserver.ini file and now server side I see this:203.xx.xxx.1 - - [04/Sep/2014:13:29:57 +1000] "GET /token/1.0/sync/1.5 HTTP/1.1" 401 109 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:32.0) Gecko/20100101 Firefox/32.0" and this: [Thu Sep 04 13:29:59.134875 2014] [wsgi:error] [pid 18941] /var/www/mozilla-services/sync-server.reub.net/htdocs/server-full/local/lib/python2.7/site-packages/tokenserver/verifiers.py:47: FutureWarning: The BrowserID certificate format has not been finalized and may change in backwards-incompatible ways. If you find that the latest version of this module cannot verify a valid BrowserID assertion, please contact the author. [Thu Sep 04 13:29:59.134948 2014] [wsgi:error] [pid 18941] super(LocalVerifier, self).__init__(**kwargs) [Thu Sep 04 13:29:59.153143 2014] [wsgi:error] [pid 18941] INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): api.accounts.firefox.com [Thu Sep 04 13:30:00.470899 2014] [wsgi:error] [pid 18941] INFO:mozsvc.metrics:{"tokenserver.backend.get_user": 0.001425027847290039, "code": 401, "request_time": 1.3324501514434814, "remoteAddressChain": ["203.xxx.xxx.1"], "agent": "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:32.0) Gecko/20100101 Firefox/32.0", "tokenserver.assertion.verify": 1.329387903213501, "token.assertion.verify_success": 1, "path": "https://sync-server.reub.net/token/1.0/sync/1.5";, "method": "GET"} Nothing progresses past that point and sync never kicks off - it successfully authenticates me but the actual sync process itself never proceeds.Is there any additional information in the client-client sync logs? (about:sync-log)
Sure: 1409811738391 Sync.Service INFO Loading Weave 1.34.0 1409811738392 Sync.Engine.Clients DEBUG Engine initialized 1409811738393 Sync.Engine.Clients DEBUG Resetting clients last sync time 1409811738398 Sync.Engine.Bookmarks DEBUG Engine initialized 1409811738401 Sync.Engine.Forms DEBUG Engine initialized 1409811738409 Sync.Engine.History DEBUG Engine initialized 1409811738412 Sync.Engine.Passwords DEBUG Engine initialized 1409811738414 Sync.Engine.Prefs DEBUG Engine initialized 1409811738417 Sync.Engine.Tabs DEBUG Engine initialized 1409811738418 Sync.Engine.Tabs DEBUG Resetting tabs last sync time 1409811738428 Sync.Engine.Addons DEBUG Engine initialized1409811738429 Sync.Service INFO Mozilla/5.0 (Windows NT 6.1; WOW64; rv:32.0) Gecko/20100101 Firefox/32.0 1409811738431 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score. 1409811738432 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1409811738432 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1409811738432 Sync.AddonsReconciler INFO Registering as Add-on Manager listener.
1409811738432 Sync.AddonsReconciler DEBUG Adding change listener. 1409811738433 Sync.Tracker.History INFO Adding Places observer.1409811738443 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1409811738443 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok
1409811738461 FirefoxAccounts DEBUG got keyPair 1409811738462 FirefoxAccounts DEBUG getCertificateSigned: true true 1409811739163 Sync.SyncScheduler DEBUG Next sync in 3600000 ms. 1409811739634 FirefoxAccounts DEBUG getCertificate got a new one: true 1409811739634 FirefoxAccounts DEBUG getAssertionFromCert1409811739672 FirefoxAccounts DEBUG getAssertionFromCert returning signed: true
1409811739695 Sync.BrowserIDManager DEBUG Getting a token1409811742444 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok
1409811742444 Sync.SyncScheduler DEBUG Next sync in 3596556 ms.1409811742970 Sync.BrowserIDManager ERROR Authentication error in _fetchTokenForUser: AuthenticationError(TokenServerClientServerError({"now":"2014-09-04T06:22:22.970Z","message":"Authentication failed.","cause":"invalid-generation","response_body":"{\"status\": \"invalid-generation\", \"errors\": [{\"location\": \"body\", \"name\": \"\", \"description\": \"Unauthorized\"}]}","response_headers":{"date":"Thu, 04 Sep 2014 06:22:20 GMT","server":"Apache/2.4.10 (Gentoo) OpenSSL/1.0.1i PHP/5.6.0-pl0-gentoo mod_wsgi/4.2.7 Python/2.7.8","x-weave-timestamp":"1409811742.98","x-timestamp":"1409811742","content-length":"109","keep-alive":"timeout=15, max=100","connection":"Keep-Alive","content-type":"application/json; charset=UTF-8"},"response_status":401})) 1409811742970 Sync.Status DEBUG Status.login: success.login => error.login.reason.account 1409811742970 Sync.Status DEBUG Status.service: success.status_ok => error.login.failed 1409811742970 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score.
Stopping at this point usually indicates some sort of auth error between the token and storage parts of the server, which may be caused by: * failure to set a fixed "secret" in the config file * invalid values for public_url or similar settings
I have both: [server:main] host = 0.0.0.0 port = 5000 [app:main] use = egg:syncserver [syncserver] public_url = https://sync-server.reub.net/ sqluri = mysql://syncserver:xxx@localhost:3306/syncserver secret = aaaa [browserid] backend = tokenserver.verifiers.LocalVerifier audiences = https://sync-server.reub.net
Incidentally, I've noticed that every time I disconnect and reconnect my sync settings in Firefox it resets the services.sync.tokenServerURI setting back to default. This is extremely annoying when testing or when sync breaks and I need to disconnect/reconnect the account - is this setting supposed to default back by design?Aye, this is known behaviour that's very annoying for folks setting up self-hosted sync: https://bugzilla.mozilla.org/show_bug.cgi?id=1003708
Thanks, added to the cc list. Reuben
<<attachment: reuben-mozilla-sync-dev.vcf>>
_______________________________________________ Sync-dev mailing list [email protected] https://mail.mozilla.org/listinfo/sync-dev
