Syncserver not working with error .../1.5/1/info/collections failed with status 401 in sync-log

[thomaslitk]

Hi,

I want to setup syncserver-rs on a raspberry pi 5. So I used mainly the documentation from here
https://artemis.sh/2023/03/27/firefox-syncstorage-rs.html
and some inspirations from
https://www.synology-forum.de/threads/neuer-firefox-syncserver-rust-in-docker-mit-mariadb-datenbank.123662/
https://sarwiki.informatik.hu-berlin.de/Eigener_Sync-Server_f%C3%BCr_Firefox_(Rust)
https://aur.archlinux.org/packages/firefox-syncstorage-git

Before, I had firefox syncserver with python 2.7 on a raspberry pi 4, which was working great.

Now, I think I have got almost everything running for syncserver-rs on the raspberry pi 5. It was not easy (some code not working), but now it seems to work mostly. I fail in the end at the sync with firefox.

Some information in advanced:
I use ProxyPass for redirection in apache:

ProxyPass /syncserver/ http://localhost:8000/
ProxyPassReverse /syncserver/ http://localhost:8000/

The config.toml looks like

master_secret = "SECRETKEY1"

human_logs = 1

host = "localhost" # default
port = 8000 # default

syncstorage.database_url = "mysql://syncstorage:PASSWORD@localhost/syncstorage_rs"
syncstorage.enable_quota = 0
syncstorage.enabled = true
syncstorage.limits.max_total_records = 1666 # See issues #298/#333

tokenserver.database_url = "mysql://syncstorage:PASSWORD@localhost/tokenserver_rs"
tokenserver.enabled = true
tokenserver.fxa_email_domain = "api.accounts.firefox.com"
tokenserver.fxa_metrics_hash_secret = "SECRETKEY2"
tokenserver.fxa_oauth_server_url = "https://oauth.accounts.firefox.com"
tokenserver.fxa_browserid_audience = "https://token.services.mozilla.com"
tokenserver.fxa_browserid_issuer = "https://api.accounts.firefox.com"
tokenserver.fxa_browserid_server_url = "https://verifier.accounts.firefox.com/v2"

The about:sync-log in firefox gives

1717100169701	Sync.LogManager	DEBUG	Flushing file log
1717100169704	Sync.LogManager	DEBUG	Log cleanup threshold time: 1716236169704
1717100169705	Sync.LogManager	DEBUG	Done deleting files.
1717100172595	Sync.Engine.Tabs.Tracker	DEBUG	Detected a tab change, but conditions aren't met for a quick write or a score bump
1717100688762	Sync.Engine.Tabs.Tracker	DEBUG	Detected a tab change, but conditions aren't met for a quick write or a score bump
1717100691304	Sync.RemoteTabs	INFO	Doing a tab sync.
1717100691304	Sync.Service	DEBUG	User-Agent: Firefox/126.0.1 (Windows NT 10.0; Win64; x64) FxSync/1.128.0.2xxx.desktop
1717100691305	Sync.Service	INFO	Starting sync at 2024-05-30 22:24:51 in browser session XXXXXXXXXXXX
1717100691305	Sync.Service	DEBUG	In sync: should login.
1717100691305	Sync.Service	INFO	User logged in successfully - verifying login.
1717100691305	Sync.RemoteTabs	INFO	Generating tab list with filter
1717100691305	FirefoxAccounts	DEBUG	FxAccountsProfileClient: Requested profile
1717100691305	FirefoxAccounts	DEBUG	getOAuthToken enter
1717100691305	FirefoxAccounts	TRACE	getCachedToken returning cached token
1717100691306	FirefoxAccounts	DEBUG	getOAuthToken returning a cached token
1717100691306	Sync.SyncAuthManager	DEBUG	unlockAndVerifyAuthState already has (or can fetch) sync keys
1717100691306	Services.Common.RESTRequest	DEBUG	GET request to https://profile.accounts.firefox.com/v1/profile
1717100691306	Sync.Status	DEBUG	Status.login: error.login.reason.network => success.status_ok
1717100691306	Sync.Status	DEBUG	Status.service: error.login.failed => error.login.failed
1717100691306	Sync.Service	DEBUG	Fetching unlocked auth state returned success.status_ok
1717100691311	Sync.RemoteTabs	INFO	Final tab list has 0 clients with 0 tabs.
1717100691710	Services.Common.RESTRequest	DEBUG	GET https://profile.accounts.firefox.com/v1/profile 304
1717100692726	FirefoxAccounts	INFO	Polling device commands.
1717100692727	Sync.Service	DEBUG	User-Agent: Firefox/126.0.1 (Windows NT 10.0; Win64; x64) FxSync/1.128.0.20240526221752.desktop
1717100692727	Sync.Service	INFO	Starting sync at 2024-05-30 22:24:52 in browser session XXXXXXXXXXXX
1717100692727	Sync.Service	DEBUG	In sync: should login.
1717100692727	Sync.Service	DEBUG	Exception calling WrappedLock: LockException: Could not acquire lock. Label: "service.js: login".(resource://services-sync/util.sys.mjs:43:5) JS Stack trace: [email protected]:43:5
[email protected]:127:11
[email protected]:141:15
[email protected]:112:27
[email protected]:1052:66
sync/<@service.sys.mjs:1330:26
[email protected]:112:27
[email protected]:1338:7
1717100692727	Sync.Service	INFO	Cannot start sync: already syncing?
1717100692727	Sync.Service	DEBUG	Not syncing: login returned false.
1717100692731	Services.Common.RESTRequest	DEBUG	GET request to https://api.accounts.firefox.com/v1/account/device/commands?index=0
1717100692741	Sync.Resource	DEBUG	GET fail 401 https://mydomain.tld/syncserver/1.5/1/info/collections
1717100692741	Sync.Resource	WARN	GET request to https://mydomain.tld/syncserver/1.5/1/info/collections failed with status 401
1717100692741	Sync.Service	WARN	401: login failed.
1717100692741	Sync.SyncAuthManager	DEBUG	_findCluster has a pre-existing clusterURL, so fetching a new token token
1717100692742	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1717100692742	Sync.SyncAuthManager	INFO	Getting sync key
1717100692742	FirefoxAccounts	DEBUG	getOAuthToken enter
1717100692742	FirefoxAccounts	TRACE	getCachedToken returning cached token
1717100692742	FirefoxAccounts	DEBUG	getOAuthToken returning a cached token
1717100692743	Sync.SyncAuthManager	INFO	Getting a sync token from: https://mydomain.tld/syncserver/1.0/sync/1.5
1717100692743	Sync.SyncAuthManager	DEBUG	Getting a token using OAuth
1717100692743	Services.Common.TokenServerClient	DEBUG	Beginning OAuth token exchange: https://mydomain.tld/syncserver/1.0/sync/1.5
1717100692743	Services.Common.RESTRequest	DEBUG	GET request to https://mydomain.tld/syncserver/1.0/sync/1.5
1717100692952	Services.Common.RESTRequest	DEBUG	GET https://api.accounts.firefox.com/v1/account/device/commands?index=0 200
1717100692953	Hawk	DEBUG	(Response) /account/device/commands?index=0: code: 200 - Status text: 
1717100692953	Hawk	DEBUG	Clock offset vs https://api.accounts.firefox.com/v1: -953
1717100693093	Services.Common.RESTRequest	DEBUG	GET https://mydomain.tld/syncserver/1.0/sync/1.5 200
1717100693093	Services.Common.TokenServerClient	DEBUG	Got token response: 200
1717100693094	Services.Common.TokenServerClient	DEBUG	Successful token response
1717100693094	Sync.Status	DEBUG	Status.login: success.status_ok => success.login
1717100693094	Sync.Status	DEBUG	Status.service: error.login.failed => success.status_ok
1717100693094	Sync.SyncAuthManager	DEBUG	_findCluster returning https://mydomain.tld/syncserver/1.5/1/
1717100693094	Sync.SyncAuthManager	DEBUG	Cluster value = https://mydomain.tld/syncserver/1.5/1/
1717100693094	Sync.Status	DEBUG	Status.login: success.login => error.login.reason.network
1717100693094	Sync.Status	DEBUG	Status.service: success.status_ok => error.login.failed
1717100693094	Sync.ErrorHandler	ERROR	Sync encountered a login error
1717100693094	Sync.SyncScheduler	DEBUG	Clearing sync triggers and the global score.
1717100693094	Sync.SyncScheduler	DEBUG	Next sync in 3600000 ms. (why=schedule)
1717100693095	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1717100693095	Sync.Service	DEBUG	Exception calling WrappedLock: Error: Login failed: error.login.reason.network(resource://services-sync/service.sys.mjs:1041:15) JS Stack trace: [email protected]:1041:15
1717100693095	Sync.Service	DEBUG	Not syncing: login returned false.
1717100693095	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent

Some things do not seem to work, but I think the problem lies here:

1717100692741	Sync.Resource	DEBUG	GET fail 401 https://mydomain.tld/syncserver/1.5/1/info/collections
1717100692741	Sync.Resource	WARN	GET request to https://mydomain.tld/syncserver/1.5/1/info/collections failed with status 401

Other problems are
Exception calling WrappedLock: LockException: Could not acquire lock. Label: "service.js: login"
Exception calling WrappedLock: Error: Login failed

The database can be written in principle. A new user is created in database tokenserver_rs:users. But no BSOs are created. Maybe there is a problem with the table collections (failed with status 401). It is predefined with some values about categories (1: clients, 2: crypto, ...)

I tried different solution approaches, but nothing works:
Disconnect account and reconnect

• similar to https://support.mozilla.org/ru/questions/1257742

Different settings in the config.toml see here:

• https://sarwiki.informatik.hu-berlin.de/Eigener_Sync-Server_f%C3%BCr_Firefox_(Rust) and
• https://artemis.sh/2023/03/27/firefox-syncstorage-rs.html

and others.

Now I don't know what to do next. Have anyone an additional approach for get the syncserver-rs to work?

Thanks and best regards
Thomas

┆Issue is synchronized with this Jira Task

[flloschy]

Having the same issue using this docker setup: https://github.com/dan-r/syncstorage-rs-docker
Which just pulls from this github repo when building

These are basically identical logs:

1730843824424	Sync.Resource	DEBUG	GET fail 401 https://DOMAIN/1.5/4/info/collections
1730843824424	Sync.Resource	WARN	GET request to https://DOMAIN/1.5/4/info/collections failed with status 401
1730843824424	Sync.Service	WARN	401: login failed.
[...]
1730843824424	Sync.SyncAuthManager	INFO	Getting a sync token from: https://DOMAIN/1.0/sync/1.5
1730843824424	Sync.SyncAuthManager	DEBUG	Getting a token using OAuth
1730843824424	Services.Common.TokenServerClient	DEBUG	Beginning OAuth token exchange: https://DOMAIN/1.0/sync/1.5
1730843824424	Services.Common.RESTRequest	DEBUG	GET request to https://DOMAIN/1.0/sync/1.5
1730843825008	Services.Common.RESTRequest	DEBUG	GET https://DOMAIN/1.0/sync/1.5 200
1730843825008	Services.Common.TokenServerClient	DEBUG	Got token response: 200
1730843825008	Services.Common.TokenServerClient	DEBUG	Successful token response
1730843825008	Sync.Status	DEBUG	Status.login: success.status_ok => success.login
1730843825008	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1730843825008	Sync.SyncAuthManager	DEBUG	_findCluster returning http://DOMAIN/1.5/4/
1730843825008	Sync.SyncAuthManager	DEBUG	Cluster value = http://DOMAIN/1.5/4/
1730843825008	Sync.Status	DEBUG	Status.login: success.login => error.login.reason.network
1730843825008	Sync.Status	DEBUG	Status.service: success.status_ok => error.login.failed
[...]
1730843825009	Sync.Service	DEBUG	Not syncing: login returned false.

And the server logs:
Nov 05 21:57:04.884 INFO {"ua.os.family":"Linux","ua.browser.family":"Firefox","uri.path":"/1.0/sync/1.5","token_type":"OAuth","ua.browser.ver":"132.0","uid":"[...]","metrics_uid":"[...]","ua":"132.0","uri.method":"GET","ua.name":"Firefox","first_seen_at":"1730843524453","ua.os.ver":"UNKNOWN"}