sync storage errors

[snIP3r23]

hi all! i have problems setting up my own storage for firefox sync. i set up as described in the official howto but i get errors in my sync log:

x.x.x.x - - [11/Feb/2018:12:42:46 +0100] "GET /token/1.0/sync/1.5 HTTP/1.1" 200 563 x.x.x.x - - [11/Feb/2018:12:42:46 +0100] "GET /token/1.0/sync/1.5/storage/1.5/1/info/collections HTTP/1.1" 404 1 x.x.x.x - - [11/Feb/2018:12:42:46 +0100] "GET /token/1.0/sync/1.5 HTTP/1.1" 200 563

sync log on the client side shows me this: 1518302422114 Sync.LogManager DEBUG Flushing file log 1518302422123 Sync.LogManager DEBUG Log cleanup threshold time: 1517438422123 1518302422150 Sync.LogManager DEBUG Done deleting files. 1518302422691 Services.Common.RESTRequest TRACE onStartRequest: POST https://oauth.accounts.firefox.com/v1/authorization 1518302422692 Services.Common.RESTRequest TRACE Channel for POST https://oauth.accounts.firefox.com/v1/authorization returned status code 0 1518302422692 Services.Common.RESTRequest DEBUG POST https://oauth.accounts.firefox.com/v1/authorization 200 1518302422692 Services.Common.RESTRequest TRACE POST body: {"access_token":"REDACTED","token_type":"bearer","expires_in":1209599,"scope":"profile","auth_at":1518302426} 1518302422693 Services.Common.RESTRequest DEBUG GET request to https://profile.accounts.firefox.com/v1/profile 1518302422693 Services.Common.RESTRequest TRACE HTTP Header authorization: (suppressed) 1518302422693 Services.Common.RESTRequest TRACE HTTP Header accept: application/json 1518302422694 FirefoxAccounts DEBUG _updateAccountData with items: ["oauthTokens"] 1518302422694 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","deviceId","deviceRegistrationVersion","oauthTokens"] 1518302422701 FirefoxAccounts DEBUG writing secure storage: ["kA","kB"] 1518302422901 Services.Common.RESTRequest TRACE onStartRequest: GET https://profile.accounts.firefox.com/v1/profile 1518302422901 Services.Common.RESTRequest TRACE Channel for GET https://profile.accounts.firefox.com/v1/profile returned status code 0 1518302422901 Services.Common.RESTRequest DEBUG GET https://profile.accounts.firefox.com/v1/profile 200 1518302422901 Services.Common.RESTRequest TRACE GET body: {"email":"REDACTED","uid":"REDACTED"} 1518302422902 FirefoxAccounts DEBUG _updateAccountData with items: ["profileCache"] 1518302422902 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","deviceId","deviceRegistrationVersion","oauthTokens","profileCache"] 1518302422902 FirefoxAccounts DEBUG notifying profile changed for user REDACTED 1518302422918 FirefoxAccounts DEBUG writing secure storage: ["kA","kB"] 1518303149722 Sync.ErrorHandler DEBUG Beginning user-triggered sync. 1518303149722 Sync.Service DEBUG User-Agent: Firefox/58.0.2 (Windows NT 10.0; Win64; x64) FxSync/1.60.0.20180206200532.desktop 1518303149722 Sync.Service INFO Starting sync at 2018-02-10 23:52:29 in browser session -6nc0CjF73mD 1518303149722 Sync.Service DEBUG In sync: should login. 1518303149722 Sync.Service INFO Logging in the user. 1518303149722 Sync.Status DEBUG Status.service: error.login.failed => success.status_ok 1518303149723 Sync.Service DEBUG Caching URLs under storage user base: https://SERVER/token/1.0/sync/1.5/storage/1.5/1/ 1518303149723 Sync.Service INFO User logged in successfully - verifying login. 1518303149723 Sync.BrowserIDManager DEBUG unlockAndVerifyAuthState already has (or can fetch) sync keys 1518303149723 Sync.Service DEBUG Fetching unlocked auth state returned success.status_ok 1518303149723 FirefoxAccounts DEBUG already verified 1518303149724 Sync.BrowserIDManager INFO Getting an assertion from: https://SERVER/token/1.0/sync/1.5 1518303149724 FirefoxAccounts DEBUG enter getAssertion() 1518303149725 FirefoxAccounts DEBUG getKeypairAndCertificate: already have keyPair and certificate 1518303149725 FirefoxAccounts DEBUG getAssertionFromCert 1518303149731 FirefoxAccounts DEBUG getAssertionFromCert returning signed: true 1518303149731 Sync.BrowserIDManager DEBUG Getting a token 1518303149732 Common.TokenServerClient DEBUG Beginning BID assertion exchange: https://SERVER/token/1.0/sync/1.5 1518303149732 Services.Common.RESTRequest DEBUG GET request to https://SERVER/token/1.0/sync/1.5 1518303149732 Services.Common.RESTRequest TRACE HTTP Header accept: application/json 1518303149732 Services.Common.RESTRequest TRACE HTTP Header authorization: (suppressed) 1518303149732 Services.Common.RESTRequest TRACE HTTP Header x-client-state: REDACTED 1518303149864 Services.Common.RESTRequest TRACE onStartRequest: GET https://SERVER/token/1.0/sync/1.5 1518303149865 Services.Common.RESTRequest TRACE Channel for GET https://SERVER/token/1.0/sync/1.5 returned status code 0 1518303149865 Services.Common.RESTRequest DEBUG GET https://SERVER/token/1.0/sync/1.5 200 1518303149865 Services.Common.RESTRequest TRACE GET body: {"uid": 1, "hashalg": "sha256", "api_endpoint": "https://SERVER/token/1.0/sync/1.5/storage/1.5/1", "duration": 300, "key": "REDACTED", "hashed_fxa_uid": "1345424f272aefd5570d022799523267", "id": "REDACTED"} 1518303149865 Common.TokenServerClient DEBUG Got token response: 200 1518303149865 Common.TokenServerClient DEBUG Successful token response 1518303149865 Sync.BrowserIDManager DEBUG Successfully got a sync token 1518303149868 FirefoxAccounts DEBUG FxAccountsProfileClient: Requested profile 1518303149868 FirefoxAccounts DEBUG getOAuthToken enter 1518303149869 FirefoxAccounts DEBUG getOAuthToken returning a cached token 1518303149870 Services.Common.RESTRequest DEBUG GET request to https://profile.accounts.firefox.com/v1/profile 1518303149870 Services.Common.RESTRequest TRACE HTTP Header authorization: (suppressed) 1518303149870 Services.Common.RESTRequest TRACE HTTP Header accept: application/json 1518303149870 Services.Common.RESTRequest TRACE HTTP Header if-none-match: "578bec8c3f0f2149347eb354195e643ca5561923-gzip" 1518303149877 Sync.Resource DEBUG mesg: GET fail 404 https://SERVER/token/1.0/sync/1.5/storage/1.5/1/info/collections 1518303149877 Sync.Resource DEBUG GET fail 404 https://SERVER/token/1.0/sync/1.5/storage/1.5/1/info/collections 1518303149877 Sync.Resource WARN GET request to https://SERVER/token/1.0/sync/1.5/storage/1.5/1/info/collections failed with status 404 1518303149877 Sync.BrowserIDManager DEBUG _findCluster has a pre-existing clusterURL, so discarding the current token 1518303149878 FirefoxAccounts DEBUG already verified 1518303149878 Sync.BrowserIDManager INFO Getting an assertion from: https://SERVER/token/1.0/sync/1.5 1518303149878 FirefoxAccounts DEBUG enter getAssertion() 1518303149878 FirefoxAccounts DEBUG getKeypairAndCertificate: already have keyPair and certificate 1518303149879 FirefoxAccounts DEBUG getAssertionFromCert 1518303149888 FirefoxAccounts DEBUG getAssertionFromCert returning signed: true 1518303149888 Sync.BrowserIDManager DEBUG Getting a token 1518303149888 Common.TokenServerClient DEBUG Beginning BID assertion exchange: https://SERVER/token/1.0/sync/1.5 1518303149889 Services.Common.RESTRequest DEBUG GET request to https://SERVER/token/1.0/sync/1.5 1518303149889 Services.Common.RESTRequest TRACE HTTP Header accept: application/json 1518303149889 Services.Common.RESTRequest TRACE HTTP Header authorization: (suppressed) 1518303149890 Services.Common.RESTRequest TRACE HTTP Header x-client-state: cdc794b9bd26b64f527f2387158874a2 1518303149897 Services.Common.RESTRequest TRACE onStartRequest: GET https://SERVER/token/1.0/sync/1.5 1518303149897 Services.Common.RESTRequest TRACE Channel for GET https://SERVER/token/1.0/sync/1.5 returned status code 0 1518303149898 Services.Common.RESTRequest DEBUG GET https://SERVER/token/1.0/sync/1.5 200 1518303149898 Services.Common.RESTRequest TRACE GET body: {"uid": 1, "hashalg": "sha256", "api_endpoint": "https://SERVER/token/1.0/sync/1.5/storage/1.5/1", "duration": 300, "key": "REDACTED", "hashed_fxa_uid": "1345424f272aefd5570d022799523267", "id": "REDACTED"} 1518303149898 Common.TokenServerClient DEBUG Got token response: 200 1518303149898 Common.TokenServerClient DEBUG Successful token response 1518303149898 Sync.BrowserIDManager DEBUG Successfully got a sync token 1518303149899 Sync.BrowserIDManager DEBUG _findCluster returning https://SERVER/token/1.0/sync/1.5/storage/1.5/1/ 1518303149900 Sync.BrowserIDManager DEBUG Cluster value = https://SERVER/token/1.0/sync/1.5/storage/1.5/1/ 1518303149900 Sync.Status DEBUG Status.login: error.login.reason.network => error.login.reason.network 1518303149900 Sync.Status DEBUG Status.service: success.status_ok => error.login.failed 1518303149900 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score. 1518303149901 Sync.SyncScheduler DEBUG Next sync in 3600000 ms. 1518303149901 Sync.ErrorHandler ERROR Sync encountered a login error 1518303149904 Sync.Service DEBUG Exception calling WrappedLock: Error: Login failed: error.login.reason.network (resource://services-sync/service.js:844:15) JS Stack trace: onNotify@service.js:844:15 1518303149904 Sync.Service DEBUG Not syncing: login returned false.

calling http://192.168.0.1:5000/token/1.0/sync/1.5 shows me this: {"status": "error", "errors": [{"location": "body", "name": "", "description": "Unauthorized"}]}

syncserver.ini:

[server:main] use = egg:gunicorn host = 192.168.0.1 port = 5000 workers = 1 timeout = 30

[app:main] use = egg:syncserver

[syncserver] public_url = https://SERVER/token/1.0/sync/1.5 sqluri = sqlite:////opt/syncserver/syncserver.db secret = SECRET allow_new_users = true force_wsgi_environ = true

wsgi config: <VirtualHost *:443> ServerName fs.area52.dtdns.net <Directory /opt/syncserver> Require all granted DocumentRoot /opt/syncserver WSGIProcessGroup sync WSGIDaemonProcess sync user=apache group=apache processes=2 threads=25 python-path=/opt/syncserver/local/lib/python2.7/site-packages/ WSGIPassAuthorization On WSGIScriptAlias / /opt/syncserver/syncserver.wsgi ErrorLog /var/log/apache2/ssl_error_log

TransferLog /var/log/apache2/ssl_access_log

    SSLEngine on
    ....

i dont know what to check else...

thx in advance snIP3r

[rfk]

(Just to let you know, TRACE-level logging often includes sensitive information like OAuth tokens. I've edited your comment to redact the ones I saw)

[rfk]

1518303149877 Sync.Resource WARN GET request to https://SERVER/token/1.0/sync/1.5/storage/1.5/1 /info/collections failed with status 404

Aha, this points to the source of the problem. The sync storage request should be to https://SERVER/storage/1.5/1/info/collections but it's still including the "token" part which is invalid and results in the 404.

[syncserver] public_url = https://SERVER/token/1.0/sync/1.5

Try changing this to just https://SERVER/, i.e. remove the /token/... suffix so that it's just the root URL of the server.

[snIP3r23]

looks like its working perfect now! thx for help!!!!