Recent mod_wsgi Issue with Self-Hosted Sync Server

Reuben Farrelly reuben-mozilla-sync-dev at reub.net
Wed Sep 3 23:27:30 PDT 2014


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 initialized
1409811738429	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	getAssertionFromCert
1409811739672	FirefoxAccounts	DEBUG	getAssertionFromCert returning 
signed: true
1409811739695	Sync.BrowserIDManager	DEBUG	Getting a token
1409811742444	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



-------------- next part --------------
A non-text attachment was scrubbed...
Name: reuben-mozilla-sync-dev.vcf
Type: text/x-vcard
Size: 4 bytes
Desc: not available
URL: <http://mail.mozilla.org/pipermail/sync-dev/attachments/20140904/a47c273f/attachment.vcf>


More information about the Sync-dev mailing list