syncstorage-rs icon indicating copy to clipboard operation
syncstorage-rs copied to clipboard
verified publisher icon mozilla-services

GET fail 500 https://example.com/1.5/4/storage/meta/global

Open sudo-nitz opened this issue 5 months ago • 13 comments

I installed Mozilla Sync Server (0.20.0-7) from Synocommunity on my Synology NAS server with Disk Station Manager (DSM 7.1.1-42962 Update 9).

This software is based on syncstorage-rs package (this build on version 0.20.0).

I previously installed and configured MariaDB 10 to work with WordPress.

I entered the correct password for my database, as I see the "syncstorage-rs" and "tokenserver-rs" tables created in phpMyAdmin.

I entered my private subdomain as the public URL - for example "https://mozilla.mydomain.com/". I generated an SSL certificate (with Let's Encrypt) for this subdomain and created a reverse proxy rule that redirects traffic from https://mozilla.mydomain.com/ to http://localhost:8132/ (with the $http_upgrade, $connection_upgrade, and $http_authorization headers). I have subdomains and reverse proxy rules for other services, such as *arr software, and they work without any issues. I also configured local DNS forwarding for internal traffic (within the local network).

I installed the latest version of the Firefox client on Windows 11. I modified the "identity.sync.tokenserver.uri" parameter to "https://mozilla.mydomain.com/1.0/sync/1.5". I created a bookmark with a link to my NAS server's website. I then logged in to my Mozilla account and synchronized.

I then also logged in to my Mozilla account on the Android app. After synchronizing, the bookmark from the Windows client was gone. Furthermore, I can't see the open tabs from the Android app in the Windows client.

So I checked the "about:sync-logs" in the Windows client - You can find them below.

1757623041364 FirefoxAccounts TRACE initializing new storage manager 1757623041364 FirefoxAccounts TRACE starting fetch of json user data 1757623041373 FirefoxAccounts TRACE finished fetch of json user data - took: 9 1757623041373 FirefoxAccounts DEBUG reading secure storage with existing: [] 1757623041373 FirefoxAccounts TRACE starting fetch of user data from the login manager 1757623041417 FirefoxAccounts DEBUG secure read fetched items: ["scopedKeys"] 1757623041417 FirefoxAccounts TRACE initializing of new storage manager done 1757623041419 FirefoxAccounts DEBUG FxAccountsProfileClient: Initialized 1757623041419 FirefoxAccounts DEBUG FxAccountsProfileClient: Requested profile 1757623041419 FirefoxAccounts DEBUG getOAuthToken enter 1757623041420 FirefoxAccounts TRACE getCachedToken returning cached token 1757623041420 FirefoxAccounts DEBUG getOAuthToken returning a cached token 1757623041420 Services.Common.RESTRequest DEBUG GET request to https://profile.accounts.firefox.com/v1/profile 1757623041738 Services.Common.RESTRequest DEBUG GET request to https://api.accounts.firefox.com/v1/account/attached_clients 1757623041951 Services.Common.RESTRequest DEBUG GET request to https://api.accounts.firefox.com/v1/account/attached_clients 1757623042001 Sync.Status INFO Resetting Status. 1757623042001 Sync.Status DEBUG Status.service: undefined => success.status_ok 1757623042002 Sync.SyncScheduler TRACE Setting SyncScheduler policy values to defaults. 1757623042002 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score. 1757623042002 Sync.Service INFO Loading Weave 1.144.0 1757623042002 Sync.Engine.Clients DEBUG Engine constructed 1757623042003 Sync.Engine.Clients DEBUG Resetting clients last sync time 1757623042005 Sync.Engine.Addons DEBUG Engine constructed 1757623042008 Sync.Engine.Addons DEBUG SyncEngine initialized: addons 1757623042008 Services.Common.RESTRequest DEBUG GET https://profile.accounts.firefox.com/v1/profile 304 1757623042009 Sync.AddonsReconciler DEBUG No data seen in loaded file: addonsreconciler 1757623042010 Sync.Engine.Passwords DEBUG Engine constructed 1757623042012 Sync.Engine.Passwords DEBUG SyncEngine initialized: passwords 1757623042013 Sync.Engine.Prefs DEBUG Engine constructed 1757623042014 Sync.Engine.Prefs DEBUG SyncEngine initialized: prefs 1757623042016 Sync.Engine.Bookmarks DEBUG Engine constructed 1757623042019 Sync.Engine.Bookmarks DEBUG SyncEngine initialized: bookmarks 1757623042020 Sync.Engine.Forms DEBUG Engine constructed 1757623042021 Sync.Engine.Forms DEBUG SyncEngine initialized: forms 1757623042022 Sync.Engine.History DEBUG Engine constructed 1757623042024 Sync.Engine.History DEBUG SyncEngine initialized: history 1757623042025 Sync.Engine.Tabs DEBUG Engine constructed 1757623042027 Sync.Engine.Tabs DEBUG SyncEngine initialized: tabs 1757623042029 Sync.Engine.Tabs INFO Got a bridged engine! 1757623042031 Sync.Engine.CreditCards DEBUG Engine constructed 1757623042031 Sync.Engine.CreditCards DEBUG SyncEngine initialized: creditcards 1757623042032 Sync.Engine.Extension-Storage DEBUG Engine constructed 1757623042033 Sync.Engine.Extension-Storage DEBUG SyncEngine initialized: extension-storage 1757623042046 Sync.Engine.Extension-Storage INFO Got a bridged engine! 1757623042046 Sync.Service INFO Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:142.0) Gecko/20100101 Firefox/142.0 1757623042047 Sync.AddonsReconciler INFO Registering as Add-on Manager listener. 1757623042047 Sync.AddonsReconciler DEBUG Adding change listener. 1757623042047 Sync.Engine.History.Tracker INFO Adding Places observer. 1757623042049 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623042050 Sync.Service DEBUG User-Agent: Firefox/142.0.1 (Windows NT 10.0; Win64; x64) FxSync/1.144.0.20250827004350.desktop 1757623042050 Sync.Service INFO Starting sync at 2025-09-11 23:37:22 in browser session _JPJsvx3b6x4 1757623042050 Sync.Service DEBUG In sync: should login. 1757623042050 Sync.Service INFO User logged in successfully - verifying login. 1757623042051 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623042051 Sync.SyncAuthManager DEBUG unlockAndVerifyAuthState already has (or can fetch) sync keys 1757623042051 Sync.Status DEBUG Status.login: success.login => success.status_ok 1757623042051 Sync.Status DEBUG Status.service: success.status_ok => error.login.failed 1757623042051 Sync.Service DEBUG Fetching unlocked auth state returned success.status_ok 1757623042051 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623042051 Sync.SyncAuthManager INFO Getting sync key 1757623042051 FirefoxAccounts DEBUG getOAuthToken enter 1757623042051 FirefoxAccounts TRACE getCachedToken returning cached token 1757623042051 FirefoxAccounts DEBUG getOAuthToken returning a cached token 1757623042051 Sync.SyncAuthManager INFO Getting a sync token from: https://mozilla.mydomain.com/1.0/sync/1.5 1757623042051 Sync.SyncAuthManager DEBUG Getting a token using OAuth 1757623042051 Services.Common.TokenServerClient DEBUG Beginning OAuth token exchange: https://mozilla.mydomain.com/1.0/sync/1.5 1757623042051 Services.Common.RESTRequest DEBUG GET request to https://mozilla.mydomain.com/1.0/sync/1.5 1757623042118 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623042118 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623042120 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623042120 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623042134 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623042145 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623042180 FirefoxAccounts DEBUG FxAccountsWebChannel registered: account_updates with origin https://accounts.firefox.com 1757623042266 Services.Common.RESTRequest DEBUG GET https://api.accounts.firefox.com/v1/account/attached_clients 200 1757623042266 Hawk DEBUG (Response) /account/attached_clients: code: 200 - Status text: 1757623042267 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -267 1757623042268 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623042271 FirefoxAccounts INFO fetching updated device list 1757623042274 Services.Common.RESTRequest DEBUG GET request to https://api.accounts.firefox.com/v1/account/devices?filterIdleDevicesTimestamp=1755808642272 1757623042300 Services.Common.RESTRequest DEBUG GET https://api.accounts.firefox.com/v1/account/attached_clients 200 1757623042300 Hawk DEBUG (Response) /account/attached_clients: code: 200 - Status text: 1757623042300 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -300 1757623042367 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623042369 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623042569 Services.Common.RESTRequest DEBUG GET https://api.accounts.firefox.com/v1/account/devices?filterIdleDevicesTimestamp=1755808642272 200 1757623042569 Hawk DEBUG (Response) /account/devices?filterIdleDevicesTimestamp=1755808642272: code: 200 - Status text: 1757623042570 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: 431 1757623042570 FirefoxAccounts INFO Got new device list: 247f303670c1cf5e33300c50893eb9a1, 83a744b03be9416c837f4494ed0680dd 1757623042570 FirefoxAccounts DEBUG FxAccountsPush loading service 1757623042571 FirefoxAccounts DEBUG FxAccountsPush initialized 1757623042575 FirefoxAccounts TRACE Command queue observer created 1757623042575 FirefoxAccounts TRACE Getting command keys: https://identity.mozilla.com/cmd/open-uri 1757623042575 FirefoxAccounts TRACE Getting command keys: https://identity.mozilla.com/cmd/close-uri/v1 1757623042575 FirefoxAccounts TRACE Our push subscription looks OK 1757623042575 FirefoxAccounts INFO updating the cache 1757623042998 Sync.RemoteTabs INFO Generating tab list with filter 1757623043019 Sync.RemoteTabs INFO Final tab list has 0 clients with 0 tabs. 1757623043581 Services.Common.RESTRequest DEBUG GET https://mozilla.mydomain.com/1.0/sync/1.5 401 1757623043581 Services.Common.TokenServerClient DEBUG Got token response: 401 1757623043581 Services.Common.TokenServerClient INFO Server-reported error: {"location":"body","name":"","description":"Unauthorized"} 1757623043581 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/oauth/destroy 1757623043582 Services.Common.RESTRequest DEBUG POST Length: 969 1757623043582 FirefoxAccounts DEBUG _updateAccountData with items: ["oauthTokens"] 1757623043582 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","device","oauthTokens","profileCache","encryptedSendTabKeys","encryptedCloseTabKeys"] 1757623043582 FirefoxAccounts TRACE starting write of json user data: ["email","sessionToken","uid","verified","device","oauthTokens","profileCache","encryptedSendTabKeys","encryptedCloseTabKeys"] 1757623043582 Sync.SyncAuthManager WARN Token server returned 401, retrying token fetch with fresh credentials 1757623043582 FirefoxAccounts DEBUG getOAuthToken enter 1757623043584 FirefoxAccounts TRACE finished write of json user data - took: 2 1757623043585 FirefoxAccounts DEBUG writing secure storage: ["scopedKeys"] 1757623043585 FirefoxAccounts TRACE starting write of user data to the login manager 1757623043590 FirefoxAccounts TRACE finished write of user data to the login manager 1757623043590 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/oauth/token 1757623043590 Services.Common.RESTRequest DEBUG POST Length: 127 1757623043849 Services.Common.RESTRequest DEBUG POST https://api.accounts.firefox.com/v1/oauth/destroy 200 1757623043849 Hawk DEBUG (Response) /oauth/destroy: code: 200 - Status text: 1757623043849 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: 151 1757623043896 Services.Common.RESTRequest DEBUG POST https://api.accounts.firefox.com/v1/oauth/token 200 1757623043897 Hawk DEBUG (Response) /oauth/token: code: 200 - Status text: 1757623043897 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: 103 1757623043897 FirefoxAccounts DEBUG _updateAccountData with items: ["oauthTokens"] 1757623043897 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","device","oauthTokens","profileCache","encryptedSendTabKeys","encryptedCloseTabKeys"] 1757623043897 FirefoxAccounts TRACE starting write of json user data: ["email","sessionToken","uid","verified","device","oauthTokens","profileCache","encryptedSendTabKeys","encryptedCloseTabKeys"] 1757623043897 Sync.SyncAuthManager INFO Getting a sync token from: https://mozilla.mydomain.com/1.0/sync/1.5 1757623043897 Sync.SyncAuthManager DEBUG Getting a token using OAuth 1757623043897 Services.Common.TokenServerClient DEBUG Beginning OAuth token exchange: https://mozilla.mydomain.com/1.0/sync/1.5 1757623043898 Services.Common.RESTRequest DEBUG GET request to https://mozilla.mydomain.com/1.0/sync/1.5 1757623043900 FirefoxAccounts TRACE finished write of json user data - took: 3 1757623043900 FirefoxAccounts DEBUG writing secure storage: ["scopedKeys"] 1757623043901 FirefoxAccounts TRACE starting write of user data to the login manager 1757623043907 FirefoxAccounts TRACE finished write of user data to the login manager 1757623044037 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623044275 Services.Common.RESTRequest DEBUG GET https://mozilla.mydomain.com/1.0/sync/1.5 200 1757623044275 Services.Common.TokenServerClient DEBUG Got token response: 200 1757623044275 Services.Common.TokenServerClient DEBUG Successful token response 1757623044276 Sync.BulkKeyBundle INFO BulkKeyBundle being created for undefined 1757623044276 Sync.Status DEBUG Status.login: success.status_ok => success.login 1757623044276 Sync.Status DEBUG Status.service: error.login.failed => success.status_ok 1757623044277 Sync.SyncAuthManager DEBUG _findCluster returning https://mozilla.mydomain.com/1.5/4/ 1757623044278 Sync.SyncAuthManager DEBUG Cluster value = https://mozilla.mydomain.com/1.5/4/ 1757623044278 Sync.SyncAuthManager DEBUG Setting cluster to https://mozilla.mydomain.com/1.5/4/ 1757623044278 Sync.Service DEBUG Caching URLs under storage user base: https://mozilla.mydomain.com/1.5/4/ 1757623044278 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623044279 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623044413 Sync.Resource DEBUG GET success 200 https://mozilla.mydomain.com/1.5/4/info/collections 1757623044414 Sync.Service DEBUG Fetching server configuration: https://mozilla.mydomain.com/1.5/4/info/configuration 1757623044415 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623044549 Sync.Resource DEBUG GET success 200 https://mozilla.mydomain.com/1.5/4/info/configuration 1757623044549 Sync.Service DEBUG Fetching global metadata record 1757623044550 FirefoxAccounts TRACE not checking freshness of profile as it remains recent 1757623044685 Sync.Resource DEBUG GET fail 500 https://mozilla.mydomain.com/1.5/4/storage/meta/global 1757623044685 Sync.Resource WARN GET request to https://mozilla.mydomain.com/1.5/4/storage/meta/global failed with status 500 1757623044685 Sync.Service DEBUG Weave Version: 1.144.0 Local Storage: 5 Remote Storage: 1757623044685 Sync.Service INFO One of: no meta, no meta storageVersion, or no meta syncID. Fresh start needed. 1757623044685 Sync.Status DEBUG Status.sync: success.sync => error.sync.reason.metarecord_download_fail 1757623044685 Sync.Status DEBUG Status.service: success.status_ok => error.sync.failed 1757623044685 Sync.Service WARN Unknown error while downloading metadata record. Aborting sync. 1757623044685 Sync.Service WARN Remote setup failed. 1757623044685 Sync.ErrorHandler ERROR Sync encountered a login error 1757623044686 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score. 1757623044686 Sync.SyncScheduler DEBUG Next sync in 3600000 ms. (why=schedule) 1757623044686 Sync.Service DEBUG Exception calling WrappedLock: Error: Login failed: success.login(resource://services-sync/service.sys.mjs:1051:15) JS Stack trace: [email protected]:1051:15 1757623044687 Sync.Service DEBUG Not syncing: login returned false. 1757623044687 FirefoxAccounts TRACE not checking freshness of profile as it remains recent

I think the problem occurs when sync tries to access "https://mozilla.mydomain.com/1.5/4/storage/meta/global" – see the line with timestamp 1757623044685 - "GET fail 500 https://mozilla.lipa.ovh/1.5/4/storage/meta/global".

I don't know what to do next. The advice from ChatGPT (relinking Mozilla accounts, removing the Weave folder from AppData, etc.) didn't help.

I also filed an issue on GitHub regarding FFSYNC software – see https://github.com/SynoCommunity/spksrc/issues/6713. The developers considered this a bug in the syncstorage-rs package.

What else can I check? How can I resolve the issue?

I can provide more details or run other tests, but I don't know what to check at this time.

┆Issue is synchronized with this Jira Task

sudo-nitz avatar Sep 15 '25 19:09 sudo-nitz

Thanks for filing. Likely a dupe of #1753 but we won't know until further triage.

clouserw avatar Sep 29 '25 21:09 clouserw

Hey @clouserw, I built the server with the patch elements mentioned in https://github.com/mozilla-services/syncstorage-rs/issues/1753#issuecomment-3408734480 adapted to v0.21.1. However a very similar error occurs in my test environment:

Client log:

1763351298599	Sync.LogManager	DEBUG	Flushing file log
1763351298633	Sync.LogManager	DEBUG	Log cleanup threshold time: 1762487298633
1763351298636	Sync.LogManager	DEBUG	Done deleting files.
1763351298893	Services.Common.RESTRequest	DEBUG	GET https://profile.accounts.firefox.com/v1/profile 304
1763352051020	Sync.Engine.Tabs.Tracker	DEBUG	Detected a tab change, but conditions aren't met for a quick write or a score bump
1763352054610	Sync.Service	DEBUG	User-Agent: Firefox/145.0 (Linux x86_64) FxSync/1.147.0.20251110134309.desktop
1763352054610	Sync.Service	INFO	Starting sync at 2025-11-17 00:00:54 in browser session aQS29yTRmUTw
1763352054610	Sync.Service	DEBUG	In sync: should login.
1763352054611	Sync.Service	INFO	User logged in successfully - verifying login.
1763352054611	FirefoxAccounts	DEBUG	FxAccountsProfileClient: Requested profile
1763352054611	FirefoxAccounts	DEBUG	getOAuthToken enter
1763352054612	FirefoxAccounts	TRACE	getCachedToken returning cached token
1763352054612	FirefoxAccounts	DEBUG	getOAuthToken returning a cached token
1763352054612	Sync.SyncAuthManager	DEBUG	unlockAndVerifyAuthState already has (or can fetch) sync keys
1763352054612	Services.Common.RESTRequest	DEBUG	GET request to https://profile.accounts.firefox.com/v1/profile
1763352054615	Sync.Status	DEBUG	Status.login: error.login.reason.network => success.status_ok
1763352054615	Sync.Status	DEBUG	Status.service: error.login.failed => error.login.failed
1763352054615	Sync.Service	DEBUG	Fetching unlocked auth state returned success.status_ok
1763352054615	Sync.SyncAuthManager	INFO	Getting sync key
1763352054615	FirefoxAccounts	DEBUG	getOAuthToken enter
1763352054616	FirefoxAccounts	TRACE	getCachedToken returning cached token
1763352054616	FirefoxAccounts	DEBUG	getOAuthToken returning a cached token
1763352054616	Sync.SyncAuthManager	INFO	Getting a sync token from: http://192.168.10.62:8132/1.0/sync/1.5
1763352054616	Sync.SyncAuthManager	DEBUG	Getting a token using OAuth
1763352054616	Services.Common.TokenServerClient	DEBUG	Beginning OAuth token exchange: http://192.168.10.62:8132/1.0/sync/1.5
1763352054616	Services.Common.RESTRequest	DEBUG	GET request to http://192.168.10.62:8132/1.0/sync/1.5
1763352054634	Services.Common.RESTRequest	DEBUG	GET http://192.168.10.62:8132/1.0/sync/1.5 500
1763352054634	Services.Common.TokenServerClient	DEBUG	Got token response: 500
1763352054634	Services.Common.TokenServerClient	INFO	Server-reported error: {"location":"internal","name":"","description":"Server error"}
1763352054634	Sync.SyncAuthManager	ERROR	Non-authentication error in _fetchTokenForUser: TokenServerClientServerError({"now":"2025-11-17T04:00:54.634Z","message":"Server error.","cause":"general","response_body":"{\"status\":\"internal-error\",\"errors\":[{\"location\":\"internal\",\"name\":\"\",\"description\":\"Server error\"}]}","response_headers":{"content-length":"101","content-type":"application/json","x-weave-timestamp":"1763352037.62","vary":"Origin, Access-Control-Request-Method, Access-Control-Request-Headers","date":"Mon, 17 Nov 2025 04:00:37 GMT"},"response_status":500})(resource://services-common/tokenserverclient.sys.mjs:28:36) JS Stack trace: [email protected]:90:16
[email protected]:306:19
[email protected]:239:19
1763352054635	Sync.Status	DEBUG	Status.login: success.status_ok => error.login.reason.network
1763352054635	Sync.Status	DEBUG	Status.service: error.login.failed => error.login.failed
1763352054635	Sync.SyncAuthManager	INFO	Failed to fetch the cluster URL: TokenServerClientServerError({"now":"2025-11-17T04:00:54.634Z","message":"Server error.","cause":"general","response_body":"{\"status\":\"internal-error\",\"errors\":[{\"location\":\"internal\",\"name\":\"\",\"description\":\"Server error\"}]}","response_headers":{"content-length":"101","content-type":"application/json","x-weave-timestamp":"1763352037.62","vary":"Origin, Access-Control-Request-Method, Access-Control-Request-Headers","date":"Mon, 17 Nov 2025 04:00:37 GMT"},"response_status":500})(resource://services-common/tokenserverclient.sys.mjs:28:36) JS Stack trace: [email protected]:90:16
[email protected]:306:19
[email protected]:239:19
1763352054636	Sync.Service	DEBUG	verifyLogin failed: TokenServerClientServerError({"now":"2025-11-17T04:00:54.634Z","message":"Server error.","cause":"general","response_body":"{\"status\":\"internal-error\",\"errors\":[{\"location\":\"internal\",\"name\":\"\",\"description\":\"Server error\"}]}","response_headers":{"content-length":"101","content-type":"application/json","x-weave-timestamp":"1763352037.62","vary":"Origin, Access-Control-Request-Method, Access-Control-Request-Headers","date":"Mon, 17 Nov 2025 04:00:37 GMT"},"response_status":500})(resource://services-common/tokenserverclient.sys.mjs:28:36) JS Stack trace: [email protected]:90:16
[email protected]:306:19
[email protected]:239:19
1763352054636	Sync.Status	DEBUG	Status.login: error.login.reason.network => error.login.reason.network
1763352054636	Sync.Status	DEBUG	Status.service: error.login.failed => error.login.failed
1763352054636	Sync.ErrorHandler	ERROR	Sync encountered a login error
1763352054636	Sync.SyncScheduler	DEBUG	Clearing sync triggers and the global score.
1763352054638	Sync.SyncScheduler	DEBUG	Next sync in 3600000 ms. (why=schedule)
1763352054638	Sync.Service	DEBUG	Exception calling WrappedLock: Error: Login failed: error.login.reason.network(resource://services-sync/service.sys.mjs:1053:15) JS Stack trace: [email protected]:1053:15
1763352054639	Sync.Service	DEBUG	Not syncing: login returned false.

Server log:

Mon Nov 17 00:00:12 -04 2025
Starting ffsync command /volume1/@appstore/ffsync/bin/syncserver --config=/volume1/@appstore/ffsync/var/local.toml
Nov 17 00:00:12.284 INFO starting 2 workers
Nov 17 00:00:12.284 INFO Server running on http://0.0.0.0:8132 (mysql) (available_parallelism: Ok(2) num_cpus: 2 num_cpus (phys): 2) No quota
Nov 17 00:00:12.284 INFO Actix runtime found; starting in Actix runtime
Nov 17 00:00:12.284 INFO starting service: "actix-web-service-0.0.0.0:8132", workers: 2, listening on: 0.0.0.0:8132
Nov 17 00:00:37.625 INFO {"ua.os.family":"Linux","ua.browser.family":"Firefox","token_type":"OAuth","ua.browser.ver":"145.0","ua.os.ver":"UNKNOWN","ua.name":"Firefox","ua":"145.0","uri.method":"GET","uri.path":"/1.0/sync/1.5"}

mreid-tt avatar Nov 17 '25 04:11 mreid-tt

Hey, @clouserw, this is definitely related to MariaDB. I installed a MySQL 8 server as a docker container and a clean-install of syncstorage-rs server v0.21.1 (from source, no patches). I pointed it to the to the MySQL 8 server and everything worked fine. Switching back to the local MariaDB 10.11 instance I got the following:

Client log:

1763406762932	Sync.SyncScheduler	DEBUG	Next sync in 3600000 ms. (why=schedule)
1763406762933	Sync.RemoteTabs	INFO	Final tab list has 0 clients with 0 tabs.
1763406767734	Sync.Engine.Tabs.Tracker	DEBUG	Detected a tab change, but conditions aren't met for a quick write or a score bump
1763406767894	Sync.Engine.Tabs.Tracker	DEBUG	Detected a tab change, but conditions aren't met for a quick write or a score bump
1763406767895	Sync.Engine.Tabs.Tracker	DEBUG	Detected a tab change, but conditions aren't met for a quick write or a score bump
1763406767921	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1763406767921	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1763406767921	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1763406767921	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1763406770631	Sync.Engine.Tabs.Tracker	DEBUG	Detected a tab change, but conditions aren't met for a quick write - bumping score
1763406770639	Sync.Engine.Tabs.Tracker	DEBUG	Detected a tab change, but conditions aren't met for a quick write or a score bump
1763406770658	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1763406770665	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1763406771642	Sync.RemoteTabs	INFO	Generating tab list with filter
1763406771645	Sync.RemoteTabs	INFO	Final tab list has 0 clients with 0 tabs.
1763406774583	Sync.Engine.Tabs.Tracker	DEBUG	Detected a tab change, but conditions aren't met for a quick write or a score bump
1763409433825	Sync.Engine.Tabs.Tracker	DEBUG	Detected a tab change, but conditions aren't met for a quick write or a score bump
1763409436368	Sync.Service	DEBUG	User-Agent: Firefox/145.0 (Linux x86_64) FxSync/1.147.0.20251110134309.desktop
1763409436368	Sync.Service	INFO	Starting sync at 2025-11-17 15:57:16 in browser session 33nkGCiNeikc
1763409436368	Sync.SyncScheduler	DEBUG	Clearing sync triggers and the global score.
1763409436374	Sync.Status	INFO	Resetting Status.
1763409436374	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1763409436375	FirefoxAccounts	DEBUG	FxAccountsProfileClient: Requested profile
1763409436375	FirefoxAccounts	DEBUG	getOAuthToken enter
1763409436377	FirefoxAccounts	TRACE	getCachedToken returning cached token
1763409436377	FirefoxAccounts	DEBUG	getOAuthToken returning a cached token
1763409436378	Services.Common.RESTRequest	DEBUG	GET request to https://profile.accounts.firefox.com/v1/profile
1763409436398	Sync.Resource	DEBUG	GET success 200 http://192.168.10.73:8132/1.5/4/info/collections
1763409436398	Sync.Service	DEBUG	Fetching server configuration: http://192.168.10.73:8132/1.5/4/info/configuration
1763409436404	Sync.Resource	DEBUG	GET success 200 http://192.168.10.73:8132/1.5/4/info/configuration
1763409436404	Sync.Service	DEBUG	Fetching global metadata record
1763409436404	Sync.Service	DEBUG	Clearing cached meta record. metaModified is 1763406755.19, setting to undefined
1763409436411	Sync.Resource	DEBUG	GET fail 500 http://192.168.10.73:8132/1.5/4/storage/meta/global
1763409436411	Sync.Resource	WARN	GET request to http://192.168.10.73:8132/1.5/4/storage/meta/global failed with status 500
1763409436411	Sync.Service	WARN	Unable to get meta/global. Failing remote setup.
1763409436411	Sync.ErrorHandler	ERROR	Sync encountered an error: Error: Aborting sync, remote setup failed(resource://services-sync/stages/enginesync.sys.mjs:96:13) JS Stack trace: [email protected]:96:13
1763409436411	Sync.SyncScheduler	DEBUG	Starting client-initiated backoff. Next sync in 1441695 ms.
1763409436411	Sync.SyncScheduler	DEBUG	Next sync in 1441695 ms. (why=client-backoff-schedule)
1763409436416	Sync.Service	DEBUG	Exception calling anonymous function: Error: Aborting sync, remote setup failed(resource://services-sync/stages/enginesync.sys.mjs:96:13) JS Stack trace: [email protected]:96:13

Server log:

Mon Nov 17 15:56:46 AST 2025
Starting ffsync command env RUST_LOG=debug RUST_BACKTRACE=full /volume1/@appstore/ffsync/bin/syncserver --config=/volume1/@appdata/ffsync/local.toml
Nov 17 15:56:46.520 INFO starting 4 workers
Nov 17 15:56:46.520 INFO Server running on http://0.0.0.0:8132 (mysql) (available_parallelism: Ok(4) num_cpus: 4 num_cpus (phys): 4) No quota
Nov 17 15:56:46.520 INFO Actix runtime found; starting in Actix runtime
Nov 17 15:56:46.520 INFO starting service: "actix-web-service-0.0.0.0:8132", workers: 4, listening on: 0.0.0.0:8132
{"Type":"glean-server-event","Fields":{"document_namespace":"syncstorage","document_type":"events","document_version":"1","document_id":"93659cf2-b98f-41c4-a44e-d39814fdea76","user_agent":"Firefox/145.0 (Linux x86_64) FxSync/1.147.0.20251110134309.desktop","ip_address":"","payload":"{\"client_info\":{\"telemetry_sdk_build\":\"glean_parser v15.0.2.dev17+g81fec69a\",\"first_run_date\":\"Unknown\",\"os\":\"Unknown\",\"os_version\":\"Unknown\",\"architecture\":\"Unknown\",\"app_build\":\"Unknown\",\"app_display_version\":\"0.21.1\",\"app_channel\":\"dev\"},\"ping_info\":{\"seq\":0,\"start_time\":\"2025-11-17T19:57:16.458547758+00:00\",\"end_time\":\"2025-11-17T19:57:16.458547758+00:00\"},\"metrics\":{\"string\":{\"syncstorage.platform\":\"firefoxdesktop\",\"syncstorage.device_family\":\"desktop\",\"syncstorage.hashed_fxa_uid\":\"f7b3fb5f3e941cede0488280e27fa57e\",\"syncstorage.hashed_device_id\":\"3be6d49ca469487f430f8d9bec4c0582\"}},\"events\":[{\"category\":\"syncstorage\",\"name\":\"get_collections\",\"timestamp\":1763409436458,\"extra\":{}}]}"}}
Nov 17 15:57:16.459 INFO {"ua.browser.ver":"145.0","ua.name":"Firefox","ua":"145.0","ua.browser.family":"Firefox","uri.path":"/1.5/4/info/collections","uri.method":"GET","ua.os.ver":"UNKNOWN","ua.os.family":"Linux"}
Nov 17 15:57:16.465 INFO {"ua.name":"Firefox","ua.browser.family":"Firefox","ua":"145.0","ua.browser.ver":"145.0","uri.method":"GET","uri.path":"/1.5/4/info/configuration","ua.os.ver":"UNKNOWN","ua.os.family":"Linux"}
Nov 17 15:57:16.472 INFO {"ua.name":"Firefox","ua.os.ver":"UNKNOWN","ua.os.family":"Linux","ua.browser.family":"Firefox","uri.method":"GET","uri.path":"/1.5/4/storage/meta/global","ua":"145.0","ua.browser.ver":"145.0"}

I was reading about certain Incompatibilities and Feature Differences Between MariaDB 10.11 and MySQL 8.0, but I am not sure which applies here.

I see there was a patch applied for MariaDB in https://github.com/mozilla-services/syncstorage-rs/pull/1856. Will you guys be releasing an updated version which includes it for testing?

mreid-tt avatar Nov 17 '25 20:11 mreid-tt

Hi @felfert, thanks for your MariaDB fix in https://github.com/mozilla-services/syncstorage-rs/pull/1856 however I'm not sure it's working for me. I attempted to build the server from the last commit. I had to manually copy the folder /tokenserver-mysql/migrations to /tokenserver-db/migrations for the build to complete but it seemed to work.

On first run the app crashes with the following log output:

Tue Nov 18 05:52:51 AST 2025
Starting ffsync command env RUST_LOG=debug RUST_BACKTRACE=full /volume1/@appstore/ffsync/bin/syncserver --config=/volume1/@appdata/ffsync/local.toml

thread 'main' (16945) panicked at syncserver/src/main.rs:63:55:
called `Result::unwrap()` on an `Err` value: ApiError { kind: Db(DbError { kind: Diesel(SqlError { kind: DieselConnection(BadConnection("Input/output error: Connection refused (os error 111)")), status: 500, backtrace:    0: <unknown>
   1: <unknown>
   2: <unknown>
   3: <unknown>
   4: <unknown>
   5: <unknown>
   6: <unknown>
   7: <unknown>
   8: <unknown>
   9: <unknown>
 }), status: 500, backtrace:    0: <unknown>
   1: <unknown>
   2: <unknown>
   3: <unknown>
   4: <unknown>
   5: <unknown>
   6: <unknown>
   7: <unknown>
   8: <unknown>
   9: <unknown>
 }), backtrace:    0: <unknown>
   1: <unknown>
   2: <unknown>
   3: <unknown>
   4: <unknown>
   5: <unknown>
   6: <unknown>
   7: <unknown>
   8: <unknown>
   9: <unknown>
, status: 500 }
stack backtrace:
   0:     0x563055435e02 - <unknown>
   1:     0x56305544995f - <unknown>
   2:     0x56305540c241 - <unknown>
   3:     0x563055414d82 - <unknown>
   4:     0x56305541a0ec - <unknown>
   5:     0x563055419f46 - <unknown>
   6:     0x56305541a775 - <unknown>
   7:     0x56305541a60a - <unknown>
   8:     0x563055414eb9 - <unknown>
   9:     0x5630553ff95d - <unknown>
  10:     0x563054b1fa40 - <unknown>
  11:     0x563054b1f516 - <unknown>
  12:     0x563054be1c27 - <unknown>
  13:     0x563054be3766 - <unknown>
  14:     0x563054bd337e - <unknown>
  15:     0x563054bcaed9 - <unknown>
  16:     0x563054bd378d - <unknown>
  17:     0x563054bcb4ba - <unknown>
  18:     0x563054bd2b5a - <unknown>
  19:     0x563054bb5801 - <unknown>
  20:     0x563054bd56a3 - <unknown>
  21:     0x563054c1a039 - <unknown>
  22:     0x56305540df50 - <unknown>
  23:     0x563054bc298c - <unknown>
  24:     0x7f61d904e177 - <unknown>
  25:     0x7f61d904e235 - __libc_start_main
  26:     0x563054b1faba - <unknown>
  27:                0x0 - <unknown>

I don't know if there is something weird with the build I made or if there remains an incompatibility connecting with MariaDB 10.11 servers. Do let me know if there is anything I can assist with to help resolve this.

mreid-tt avatar Nov 18 '25 10:11 mreid-tt

Well it says connection refused. That has nothing to do with the query-changes that I made. So: is your db-server even running (or crashed?) or maybe the database parameters are wrong in the first place? (Also: If you are using a local unix socket, the permissions of that file matter as well - the user running syncserver must have full acces rights to that file)

Cheers -Fritz

PS: Also, I would NOT recomment using the latest commit, because they are currently refactoring the whole DB stuff which might cause instabilities. Instead use the latest release tarball and apply that patch to it. That's what I do and it works great.

felfert avatar Nov 18 '25 10:11 felfert

Also: I do NOT run my syncserver in a container, because that adds more bloat and configuration complexity (one has to watch out for errors in configuration of permission/volumes/networks). So: If you are running Fedora or RHEL, I have packages here and if you are running ubuntu 24.04,, I have a package here.

felfert avatar Nov 18 '25 11:11 felfert

Hey @felfert, thanks for your feedback. I've applied this patch to the latest v0.21.1 release:

--- syncstorage-mysql/src/diesel_ext.rs	2025-09-23 16:12:34
+++ syncstorage-mysql/src/diesel_ext.rs.new	2025-11-18 08:04:47
@@ -3,11 +3,44 @@
 use diesel::{
     backend::Backend,
     insertable::CanInsertInSingleQuery,
+    mysql::Mysql,
     query_builder::{AstPass, InsertStatement, QueryFragment, QueryId},
+    query_dsl::methods::LockingDsl,
     result::QueryResult,
     Expression, QuerySource, RunQueryDsl,
 };
 
+/// Emit MySQL <= 5.7's `LOCK IN SHARE MODE`
+///
+/// MySQL 8 supports `FOR SHARE` as an alias (which diesel natively supports)
+/// This is required for MariaDB which does not provide that alias.
+pub trait LockInShareModeDsl {
+    type Output;
+
+    fn lock_in_share_mode(self) -> Self::Output;
+}
+
+impl<T> LockInShareModeDsl for T
+where
+    T: LockingDsl<LockInShareMode>,
+{
+    type Output = <T as LockingDsl<LockInShareMode>>::Output;
+
+    fn lock_in_share_mode(self) -> Self::Output {
+        self.with_lock(LockInShareMode)
+    }
+}
+
+#[derive(Debug, Clone, Copy, QueryId)]
+pub struct LockInShareMode;
+
+impl QueryFragment<Mysql> for LockInShareMode {
+    fn walk_ast<'b>(&'b self, mut out: AstPass<'_, 'b, Mysql>) -> QueryResult<()> {
+        out.push_sql(" LOCK IN SHARE MODE");
+        Ok(())
+    }
+}
+
 #[allow(dead_code)] // Not really dead, Rust can't see it.
 #[derive(Debug, Clone)]
 pub struct OnDuplicateKeyUpdate<T, U, Op, Ret, DB, X>(
--- syncstorage-mysql/src/models.rs	2025-09-23 16:12:34
+++ syncstorage-mysql/src/models.rs.new	2025-11-18 08:07:49
@@ -26,6 +26,7 @@
 use super::{
     batch,
     error::DbError,
+    diesel_ext::LockInShareModeDsl,
     pool::CollectionCache,
     schema::{bso, collections, user_collections},
     DbResult,
@@ -178,7 +179,7 @@
             .select(user_collections::modified)
             .filter(user_collections::user_id.eq(user_id))
             .filter(user_collections::collection_id.eq(collection_id))
-            .for_share()
+            .lock_in_share_mode()
             .first(&mut *self.conn.write()?)
             .optional()?;
         if let Some(modified) = modified {

Unfortunately, when I install with a connection to a MariaDB 10.11.6 server it doesn't work. As above I get the following client sync error log:

1763468672933	Sync.LogManager	DEBUG	Flushing file log
1763468672939	Sync.LogManager	DEBUG	Log cleanup threshold time: 1762604672939
1763468672942	Sync.LogManager	DEBUG	Done deleting files.
1763468676874	Sync.Engine.Tabs.Tracker	DEBUG	Detected a tab change, but conditions aren't met for a quick write - bumping score
1763468676888	Sync.Engine.Tabs.Tracker	DEBUG	Detected a tab change, but conditions aren't met for a quick write or a score bump
1763468676927	Sync.Engine.Tabs.Tracker	DEBUG	Detected a tab change, but conditions aren't met for a quick write or a score bump
1763468677122	Sync.Engine.Tabs.Tracker	DEBUG	Detected a tab change, but conditions aren't met for a quick write or a score bump
1763468677123	Sync.Engine.Tabs.Tracker	DEBUG	Detected a tab change, but conditions aren't met for a quick write or a score bump
1763468677149	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1763468677149	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1763468677149	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1763468677149	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1763468678783	Sync.Service	DEBUG	User-Agent: Firefox/145.0 (Linux x86_64) FxSync/1.147.0.20251110134309.desktop
1763468678783	Sync.Service	INFO	Starting sync at 2025-11-18 08:24:38 in browser session CRaOlPcsu-Mn
1763468678783	Sync.Service	DEBUG	In sync: should login.
1763468678783	Sync.Service	INFO	User logged in successfully - verifying login.
1763468678783	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1763468678783	Sync.SyncAuthManager	DEBUG	unlockAndVerifyAuthState already has (or can fetch) sync keys
1763468678783	Sync.Status	DEBUG	Status.login: error.login.reason.network => success.status_ok
1763468678783	Sync.Status	DEBUG	Status.service: error.login.failed => error.login.failed
1763468678783	Sync.Service	DEBUG	Fetching unlocked auth state returned success.status_ok
1763468678783	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1763468678783	Sync.SyncAuthManager	INFO	Getting sync key
1763468678784	FirefoxAccounts	DEBUG	getOAuthToken enter
1763468678784	FirefoxAccounts	TRACE	getCachedToken returning cached token
1763468678784	FirefoxAccounts	DEBUG	getOAuthToken returning a cached token
1763468678784	Sync.SyncAuthManager	INFO	Getting a sync token from: http://192.168.10.73:8132/1.0/sync/1.5
1763468678784	Sync.SyncAuthManager	DEBUG	Getting a token using OAuth
1763468678784	Services.Common.TokenServerClient	DEBUG	Beginning OAuth token exchange: http://192.168.10.73:8132/1.0/sync/1.5
1763468678784	Services.Common.RESTRequest	DEBUG	GET request to http://192.168.10.73:8132/1.0/sync/1.5
1763468678804	Services.Common.RESTRequest	DEBUG	GET http://192.168.10.73:8132/1.0/sync/1.5 500
1763468678804	Services.Common.TokenServerClient	DEBUG	Got token response: 500
1763468678804	Services.Common.TokenServerClient	INFO	Server-reported error: {"location":"internal","name":"","description":"Server error"}
1763468678804	Sync.SyncAuthManager	ERROR	Non-authentication error in _fetchTokenForUser: TokenServerClientServerError({"now":"2025-11-18T12:24:38.804Z","message":"Server error.","cause":"general","response_body":"{\"status\":\"internal-error\",\"errors\":[{\"location\":\"internal\",\"name\":\"\",\"description\":\"Server error\"}]}","response_headers":{"content-length":"101","vary":"Origin, Access-Control-Request-Method, Access-Control-Request-Headers","x-weave-timestamp":"1763468678.78","content-type":"application/json","date":"Tue, 18 Nov 2025 12:24:38 GMT"},"response_status":500})(resource://services-common/tokenserverclient.sys.mjs:28:36) JS Stack trace: [email protected]:90:16
[email protected]:306:19
[email protected]:239:19
1763468678804	Sync.Status	DEBUG	Status.login: success.status_ok => error.login.reason.network
1763468678804	Sync.Status	DEBUG	Status.service: error.login.failed => error.login.failed
1763468678805	Sync.SyncAuthManager	INFO	Failed to fetch the cluster URL: TokenServerClientServerError({"now":"2025-11-18T12:24:38.804Z","message":"Server error.","cause":"general","response_body":"{\"status\":\"internal-error\",\"errors\":[{\"location\":\"internal\",\"name\":\"\",\"description\":\"Server error\"}]}","response_headers":{"content-length":"101","vary":"Origin, Access-Control-Request-Method, Access-Control-Request-Headers","x-weave-timestamp":"1763468678.78","content-type":"application/json","date":"Tue, 18 Nov 2025 12:24:38 GMT"},"response_status":500})(resource://services-common/tokenserverclient.sys.mjs:28:36) JS Stack trace: [email protected]:90:16
[email protected]:306:19
[email protected]:239:19
1763468678805	Sync.Service	DEBUG	verifyLogin failed: TokenServerClientServerError({"now":"2025-11-18T12:24:38.804Z","message":"Server error.","cause":"general","response_body":"{\"status\":\"internal-error\",\"errors\":[{\"location\":\"internal\",\"name\":\"\",\"description\":\"Server error\"}]}","response_headers":{"content-length":"101","vary":"Origin, Access-Control-Request-Method, Access-Control-Request-Headers","x-weave-timestamp":"1763468678.78","content-type":"application/json","date":"Tue, 18 Nov 2025 12:24:38 GMT"},"response_status":500})(resource://services-common/tokenserverclient.sys.mjs:28:36) JS Stack trace: [email protected]:90:16
[email protected]:306:19
[email protected]:239:19
1763468678805	Sync.Status	DEBUG	Status.login: error.login.reason.network => error.login.reason.network
1763468678805	Sync.Status	DEBUG	Status.service: error.login.failed => error.login.failed
1763468678805	Sync.ErrorHandler	ERROR	Sync encountered a login error
1763468678805	Sync.SyncScheduler	DEBUG	Clearing sync triggers and the global score.
1763468678806	Sync.SyncScheduler	DEBUG	Next sync in 3600000 ms. (why=schedule)
1763468678807	Sync.Service	DEBUG	Exception calling WrappedLock: Error: Login failed: error.login.reason.network(resource://services-sync/service.sys.mjs:1053:15) JS Stack trace: [email protected]:1053:15
1763468678807	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1763468678808	Sync.Service	DEBUG	Not syncing: login returned false.
1763468678808	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent

The server doesn't really give much detail in its log so troubleshooting is challenging:

Tue Nov 18 08:23:14 AST 2025
Starting ffsync command env RUST_LOG=debug RUST_BACKTRACE=full /volume1/@appstore/ffsync/bin/syncserver --config=/volume1/@appdata/ffsync/local.toml
Nov 18 08:23:14.495 INFO starting 4 workers
Nov 18 08:23:14.495 INFO Server running on http://0.0.0.0:8132 (mysql) (available_parallelism: Ok(4) num_cpus: 4 num_cpus (phys): 4) No quota
Nov 18 08:23:14.495 INFO Actix runtime found; starting in Actix runtime
Nov 18 08:23:14.495 INFO starting service: "actix-web-service-0.0.0.0:8132", workers: 4, listening on: 0.0.0.0:8132
Nov 18 08:24:01.549 INFO {"uri.path":"/1.0/sync/1.5","uri.method":"GET","token_type":"OAuth","ua.name":"Firefox","ua.browser.ver":"145.0","ua":"145.0","ua.os.family":"Linux","ua.os.ver":"UNKNOWN","ua.browser.family":"Firefox"}
Nov 18 08:24:32.922 INFO {"ua.browser.family":"Firefox","ua.os.family":"Linux","ua.name":"Firefox","ua.browser.ver":"145.0","uri.path":"/1.0/sync/1.5","token_type":"OAuth","ua":"145.0","ua.os.ver":"UNKNOWN","uri.method":"GET"}
Nov 18 08:24:38.789 INFO {"uri.path":"/1.0/sync/1.5","ua.os.ver":"UNKNOWN","ua.name":"Firefox","ua":"145.0","token_type":"OAuth","ua.browser.family":"Firefox","uri.method":"GET","ua.os.family":"Linux","ua.browser.ver":"145.0"}

Any advice would be welcomed.

mreid-tt avatar Nov 18 '25 12:11 mreid-tt

So now the DB access works, but you get an authentication error. According to your client logs, you are trying to authenticate at a private address: http://192.168.10.73:8132. I'm not 100% shure, but I think this can't work, because it is not a public address. I never tried this in a local network. Did this work for you in the past? Another cause could be the URL stored in your token-db in the nodes table. The node value must be exactly your syncserver's toplevel URL.

You can check this by running: echo 'SELECT * FROM nodes' | mysql -t YourDbName This should show something like:

+----+---------+------------------------------+-----------+--------------+----------+--------+---------+
| id | service | node                         | available | current_load | capacity | downed | backoff |
+----+---------+------------------------------+-----------+--------------+----------+--------+---------+
|  1 |       1 | https://redacted.domain      |         0 |            1 |       10 |      0 |       0 |
+----+---------+------------------------------+-----------+--------------+----------+--------+---------+

I also don't know, whether your non-standard port is to be included in that URL.

I am pretty sure however, that this is now a setup/config issue and not a DB query problem anymore.

Just some hints. -Fritz

felfert avatar Nov 18 '25 15:11 felfert

Hey @felfert, thanks for your feedback. Yes, a private address has worked in the past and is a regular part of my testing for desktops (mobile clients won't allow non-SSL addresses). On setup the node is setup correctly in the database as shown below:

MariaDB [tokenserver_rs]> SELECT * FROM nodes;
+----+---------+---------------------------+-----------+--------------+----------+--------+---------+
| id | service | node                      | available | current_load | capacity | downed | backoff |
+----+---------+---------------------------+-----------+--------------+----------+--------+---------+
|  1 |       1 | http://192.168.10.73:8132 |         1 |            0 |        4 |      0 |       0 |
+----+---------+---------------------------+-----------+--------------+----------+--------+---------+
1 row in set (0.000 sec)

I can confirm that this is very much a DB query problem since I noted in https://github.com/mozilla-services/syncstorage-rs/issues/1804#issuecomment-3543635301 that if I fire up a MySQL 8 docker container and manually point the configuration to it, the app works flawlessly.

mreid-tt avatar Nov 18 '25 16:11 mreid-tt

Well, if local addresses worked in the past, then so be it and I am clueless. I have my native package running with mariadb-10.11.11 (also not in a docker container, but as native Fedora42 packages) and that works nicely here. What puzzles me though is that there are no exceptions thrown in your installation, because if it were a query problem, then there should be exceptions. Perhaps raising the log level to trace reveals something?

Ok, just another stupid question: Did you try with an empty DB (let syncserver initialize the DB at first run)? Thats why I did. And (mentioned just for completeness - should not matter): I also use only a single DB for both syncstrorage-db and tokenserver-db (table names don't overlap). The other patches, I use can be seen here. A description of the paches can be found in the .spec file.

And this is a list of shared libs, that my build uses on Fedora:

# ldd /usr/libexec/syncserver
        linux-vdso.so.1 (0x00007fbc478b3000)
        libmariadb.so.3 => /lib64/libmariadb.so.3 (0x00007fbc46bb2000)
        libssl.so.3 => /lib64/libssl.so.3 (0x00007fbc46ada000)
        libcrypto.so.3 => /lib64/libcrypto.so.3 (0x00007fbc46600000)
        libz.so.1 => /lib64/libz.so.1 (0x00007fbc47878000)
        libgcc_s.so.1 => /lib64/libgcc_s.so.1 (0x00007fbc465d4000)
        libm.so.6 => /lib64/libm.so.6 (0x00007fbc464e6000)
        libc.so.6 => /lib64/libc.so.6 (0x00007fbc462f4000)
        /lib64/ld-linux-x86-64.so.2 (0x00007fbc478b5000)

The package that provides the mariadb connector:

rpm -qf /lib64/libmariadb.so.3
mariadb-connector-c-3.4.5-1.fc42.x86_64

felfert avatar Nov 18 '25 18:11 felfert

Hi @felfert, thanks so much for your insights. Inspired by your feedback, I deployed a new MariaDB server as a docker container with the older version 10.3.29. I then manually populated the database identically to how it is done on the local deployment using the migration files and the identical node setup. Finally, I switched the config in the local.toml file to point to the new server and voilà. The server log connected successfully from the exact same client with no configuration changes:

Before the config update:

Tue Nov 18 11:56:44 AST 2025
Starting ffsync command env RUST_LOG=debug RUST_BACKTRACE=full /volume1/@appstore/ffsync/bin/syncserver --config=/volume1/@appdata/ffsync/local.toml
Nov 18 11:56:44.718 INFO starting 4 workers
Nov 18 11:56:44.719 INFO Server running on http://0.0.0.0:8132 (mysql) (available_parallelism: Ok(4) num_cpus: 4 num_cpus (phys): 4) No quota
Nov 18 11:56:44.719 INFO Actix runtime found; starting in Actix runtime
Nov 18 11:56:44.719 INFO starting service: "actix-web-service-0.0.0.0:8132", workers: 4, listening on: 0.0.0.0:8132
Nov 18 11:57:15.917 INFO {"ua.os.family":"Linux","uri.method":"GET","ua.os.ver":"UNKNOWN","uri.path":"/1.0/sync/1.5","ua":"145.0","token_type":"OAuth","ua.browser.ver":"145.0","ua.browser.family":"Firefox","ua.name":"Firefox"}
Nov 18 15:28:48.179 INFO {"token_type":"OAuth","ua.browser.family":"Firefox","uri.method":"GET","ua":"143.0","ua.os.family":"Linux","ua.os.ver":"UNKNOWN","ua.name":"Firefox","uri.path":"/1.0/sync/1.5","ua.browser.ver":"143.0"}
Nov 18 15:29:51.918 INFO {"ua.os.ver":"UNKNOWN","ua.browser.family":"Firefox","ua.os.family":"Linux","ua.browser.ver":"143.0","token_type":"OAuth","ua":"143.0","ua.name":"Firefox","uri.path":"/1.0/sync/1.5","uri.method":"GET"}
Nov 18 15:30:00.055 INFO {"ua.name":"Firefox","uri.path":"/1.0/sync/1.5","ua.browser.family":"Firefox","ua.browser.ver":"143.0","ua.os.family":"Linux","uri.method":"GET","token_type":"OAuth","ua.os.ver":"UNKNOWN","ua":"143.0"}
Stopping ffsync ...

After the config update:

Nov 18 15:30:49.375 INFO Server closing
Starting ffsync ...
tail: ffsync.log: file truncated
Tue Nov 18 15:31:53 AST 2025
Starting ffsync command env RUST_LOG=debug RUST_BACKTRACE=full /volume1/@appstore/ffsync/bin/syncserver --config=/volume1/@appdata/ffsync/local.toml
Nov 18 15:31:53.564 INFO starting 4 workers
Nov 18 15:31:53.565 INFO Server running on http://0.0.0.0:8132 (mysql) (available_parallelism: Ok(4) num_cpus: 4 num_cpus (phys): 4) No quota
Nov 18 15:31:53.565 INFO Actix runtime found; starting in Actix runtime
Nov 18 15:31:53.565 INFO starting service: "actix-web-service-0.0.0.0:8132", workers: 4, listening on: 0.0.0.0:8132
Nov 18 15:32:09.629 INFO {"ua.browser.family":"Firefox","uri.method":"GET","ua.browser.ver":"143.0","uri.path":"/1.0/sync/1.5","uid":"219bed8587083fa641df6720037d00593b1f237001a9e5c2d74ab2327d09e363","metrics_uid":"219bed8587083fa641df6720037d0059","first_seen_at":"1763494329616","ua.os.family":"Linux","token_type":"OAuth","ua":"143.0","ua.name":"Firefox","ua.os.ver":"UNKNOWN"}
{"Type":"glean-server-event","Fields":{"document_namespace":"syncstorage","document_type":"events","document_version":"1","document_id":"1c6df8c6-a613-4506-a1cd-c8a4ed6a1f2f","user_agent":"Firefox/143.0.1 (Linux x86_64) FxSync/1.145.0.20250919025228.desktop","ip_address":"","payload":"{\"client_info\":{\"telemetry_sdk_build\":\"glean_parser v15.0.2.dev17+g81fec69a\",\"first_run_date\":\"Unknown\",\"os\":\"Unknown\",\"os_version\":\"Unknown\",\"architecture\":\"Unknown\",\"app_build\":\"Unknown\",\"app_display_version\":\"0.21.1\",\"app_channel\":\"dev\"},\"ping_info\":{\"seq\":0,\"start_time\":\"2025-11-18T19:32:09.744915029+00:00\",\"end_time\":\"2025-11-18T19:32:09.744915029+00:00\"},\"metrics\":{\"string\":{\"syncstorage.hashed_fxa_uid\":\"219bed8587083fa641df6720037d0059\",\"syncstorage.platform\":\"firefoxdesktop\",\"syncstorage.device_family\":\"desktop\",\"syncstorage.hashed_device_id\":\"e9b3dfda5cd0f6f3a118a90ccbfab61f\"}},\"events\":[{\"category\":\"syncstorage\",\"name\":\"get_collections\",\"timestamp\":1763494329744,\"extra\":{}}]}"}}
Nov 18 15:32:09.746 INFO {"ua.browser.ver":"143.0.1","ua":"143.0.1","ua.os.family":"Linux","ua.name":"Firefox","uri.path":"/1.5/4/info/collections","uri.method":"GET","ua.browser.family":"Firefox","ua.os.ver":"UNKNOWN"}
Nov 18 15:32:09.757 INFO {"ua.name":"Firefox","ua.os.ver":"UNKNOWN","ua":"143.0.1","ua.browser.family":"Firefox","ua.os.family":"Linux","ua.browser.ver":"143.0.1","uri.method":"GET","uri.path":"/1.5/4/info/configuration"}
Nov 18 15:32:09.773 INFO {"ua":"143.0.1","uri.method":"GET","ua.browser.ver":"143.0.1","ua.os.ver":"UNKNOWN","ua.browser.family":"Firefox","uri.path":"/1.5/4/storage/meta/global","ua.name":"Firefox","ua.os.family":"Linux"}
Nov 18 15:32:09.818 INFO {"ua.browser.family":"Firefox","ua.os.ver":"UNKNOWN","uri.method":"DELETE","ua.browser.ver":"143.0.1","ua.os.family":"Linux","ua":"143.0.1","ua.name":"Firefox","uri.path":"/1.5/4/storage"}
Nov 18 15:32:09.837 INFO {"uri.path":"/1.5/4/storage/meta/global","ua.browser.ver":"143.0.1","ua.os.ver":"UNKNOWN","ua.browser.family":"Firefox","ua":"143.0.1","ua.os.family":"Linux","ua.name":"Firefox","uri.method":"PUT"}
Nov 18 15:32:09.863 INFO {"uri.path":"/1.5/4/storage/crypto/keys","ua.browser.ver":"143.0.1","ua.name":"Firefox","ua.browser.family":"Firefox","ua.os.family":"Linux","ua":"143.0.1","ua.os.ver":"UNKNOWN","uri.method":"PUT"}
{"Type":"glean-server-event","Fields":{"document_namespace":"syncstorage","document_type":"events","document_version":"1","document_id":"8ca1f496-5f1f-400d-869e-f1d60480e6d2","user_agent":"Firefox/143.0.1 (Linux x86_64) FxSync/1.145.0.20250919025228.desktop","ip_address":"","payload":"{\"client_info\":{\"telemetry_sdk_build\":\"glean_parser v15.0.2.dev17+g81fec69a\",\"first_run_date\":\"Unknown\",\"os\":\"Unknown\",\"os_version\":\"Unknown\",\"architecture\":\"Unknown\",\"app_build\":\"Unknown\",\"app_display_version\":\"0.21.1\",\"app_channel\":\"dev\"},\"ping_info\":{\"seq\":0,\"start_time\":\"2025-11-18T19:32:09.873849564+00:00\",\"end_time\":\"2025-11-18T19:32:09.873849564+00:00\"},\"metrics\":{\"string\":{\"syncstorage.platform\":\"firefoxdesktop\",\"syncstorage.device_family\":\"desktop\",\"syncstorage.hashed_fxa_uid\":\"219bed8587083fa641df6720037d0059\",\"syncstorage.hashed_device_id\":\"e9b3dfda5cd0f6f3a118a90ccbfab61f\"}},\"events\":[{\"category\":\"syncstorage\",\"name\":\"get_collections\",\"timestamp\":1763494329873,\"extra\":{}}]}"}}
Nov 18 15:32:09.875 INFO {"ua.browser.family":"Firefox","uri.path":"/1.5/4/info/collections","ua":"143.0.1","ua.name":"Firefox","uri.method":"GET","ua.browser.ver":"143.0.1","ua.os.family":"Linux","ua.os.ver":"UNKNOWN"}
Nov 18 15:32:09.886 INFO {"ua.browser.family":"Firefox","ua":"143.0.1","uri.method":"GET","ua.os.ver":"UNKNOWN","ua.os.family":"Linux","ua.name":"Firefox","ua.browser.ver":"143.0.1","uri.path":"/1.5/4/storage/crypto/keys"}
{"Type":"glean-server-event","Fields":{"document_namespace":"syncstorage","document_type":"events","document_version":"1","document_id":"91d99ed2-b970-421f-85b7-3a42982bac42","user_agent":"Firefox/143.0.1 (Linux x86_64) FxSync/1.145.0.20250919025228.desktop","ip_address":"","payload":"{\"client_info\":{\"telemetry_sdk_build\":\"glean_parser v15.0.2.dev17+g81fec69a\",\"first_run_date\":\"Unknown\",\"os\":\"Unknown\",\"os_version\":\"Unknown\",\"architecture\":\"Unknown\",\"app_build\":\"Unknown\",\"app_display_version\":\"0.21.1\",\"app_channel\":\"dev\"},\"ping_info\":{\"seq\":0,\"start_time\":\"2025-11-18T19:32:09.903230575+00:00\",\"end_time\":\"2025-11-18T19:32:09.903230575+00:00\"},\"metrics\":{\"string\":{\"syncstorage.hashed_device_id\":\"e9b3dfda5cd0f6f3a118a90ccbfab61f\",\"syncstorage.platform\":\"firefoxdesktop\",\"syncstorage.hashed_fxa_uid\":\"219bed8587083fa641df6720037d0059\",\"syncstorage.device_family\":\"desktop\"}},\"events\":[{\"category\":\"syncstorage\",\"name\":\"get_collections\",\"timestamp\":1763494329903,\"extra\":{}}]}"}}
Nov 18 15:32:09.904 INFO {"ua.browser.ver":"143.0.1","ua.name":"Firefox","ua.browser.family":"Firefox","uri.method":"GET","ua":"143.0.1","ua.os.ver":"UNKNOWN","ua.os.family":"Linux","uri.path":"/1.5/4/info/collections"}
Nov 18 15:32:09.914 INFO {"ua.browser.family":"Firefox","ua.os.family":"Linux","ua.browser.ver":"143.0.1","ua.name":"Firefox","ua":"143.0.1","uri.method":"GET","ua.os.ver":"UNKNOWN","uri.path":"/1.5/4/info/configuration"}
Nov 18 15:32:09.929 INFO {"ua.os.family":"Linux","ua.browser.ver":"143.0.1","uri.path":"/1.5/4/storage/clients","uri.method":"DELETE","ua.browser.family":"Firefox","ua.os.ver":"UNKNOWN","ua":"143.0.1","ua.name":"Firefox"}
Nov 18 15:32:10.150 INFO {"ua.browser.ver":"143.0.1","uri.method":"POST","ua.browser.family":"Firefox","ua.name":"Firefox","ua.os.ver":"UNKNOWN","uri.path":"/1.5/4/storage/clients?batch=true&commit=true","ua":"143.0.1","ua.os.family":"Linux"}
Nov 18 15:32:10.171 INFO {"ua.os.family":"Linux","uri.method":"DELETE","ua.name":"Firefox","ua":"143.0.1","ua.browser.family":"Firefox","ua.os.ver":"UNKNOWN","ua.browser.ver":"143.0.1","uri.path":"/1.5/4/storage/prefs"}
Nov 18 15:32:10.210 INFO {"ua.browser.family":"Firefox","ua.os.family":"Linux","ua.browser.ver":"143.0.1","ua":"143.0.1","uri.path":"/1.5/4/storage/prefs?batch=true&commit=true","ua.name":"Firefox","uri.method":"POST","ua.os.ver":"UNKNOWN"}
Nov 18 15:32:10.229 INFO {"ua":"143.0.1","ua.os.family":"Linux","ua.browser.ver":"143.0.1","ua.browser.family":"Firefox","ua.name":"Firefox","ua.os.ver":"UNKNOWN","uri.method":"DELETE","uri.path":"/1.5/4/storage/passwords"}
Nov 18 15:32:10.264 INFO {"ua.os.ver":"UNKNOWN","ua":"143.0.1","ua.name":"Firefox","ua.browser.ver":"143.0.1","uri.method":"POST","ua.os.family":"Linux","ua.browser.family":"Firefox","uri.path":"/1.5/4/storage/passwords?batch=true&commit=true"}
Nov 18 15:32:10.279 INFO {"ua.os.ver":"UNKNOWN","ua.name":"Firefox","ua.browser.ver":"143.0.1","uri.method":"DELETE","ua.browser.family":"Firefox","ua":"143.0.1","ua.os.family":"Linux","uri.path":"/1.5/4/storage/tabs"}
Nov 18 15:32:10.309 INFO {"ua.browser.family":"Firefox","ua":"143.0.1","uri.path":"/1.5/4/storage/tabs?batch=true&commit=true","uri.method":"POST","ua.os.ver":"UNKNOWN","ua.name":"Firefox","ua.os.family":"Linux","ua.browser.ver":"143.0.1"}
Nov 18 15:32:10.326 INFO {"uri.method":"DELETE","ua.browser.ver":"143.0.1","ua":"143.0.1","ua.name":"Firefox","ua.os.family":"Linux","uri.path":"/1.5/4/storage/bookmarks","ua.browser.family":"Firefox","ua.os.ver":"UNKNOWN"}
Nov 18 15:32:10.392 INFO {"uri.method":"POST","uri.path":"/1.5/4/storage/bookmarks?batch=true&commit=true","ua.os.ver":"UNKNOWN","ua.name":"Firefox","ua":"143.0.1","ua.browser.ver":"143.0.1","ua.browser.family":"Firefox","ua.os.family":"Linux"}
Nov 18 15:32:10.420 INFO {"ua.name":"Firefox","ua.browser.ver":"143.0.1","ua":"143.0.1","uri.method":"DELETE","ua.os.family":"Linux","uri.path":"/1.5/4/storage/addons","ua.browser.family":"Firefox","ua.os.ver":"UNKNOWN"}
Nov 18 15:32:10.457 INFO {"ua.browser.ver":"143.0.1","ua.os.family":"Linux","ua.browser.family":"Firefox","uri.method":"POST","ua":"143.0.1","ua.os.ver":"UNKNOWN","uri.path":"/1.5/4/storage/addons?batch=true&commit=true","ua.name":"Firefox"}
Nov 18 15:32:10.474 INFO {"ua":"143.0.1","ua.name":"Firefox","uri.method":"DELETE","ua.browser.family":"Firefox","ua.browser.ver":"143.0.1","ua.os.ver":"UNKNOWN","uri.path":"/1.5/4/storage/creditcards","ua.os.family":"Linux"}
Nov 18 15:32:10.489 INFO {"ua.browser.family":"Firefox","ua.os.family":"Linux","uri.path":"/1.5/4/storage/forms","ua.browser.ver":"143.0.1","uri.method":"DELETE","ua.name":"Firefox","ua.os.ver":"UNKNOWN","ua":"143.0.1"}
Nov 18 15:32:10.601 INFO {"uri.path":"/1.5/4/storage/forms?batch=true","ua.name":"Firefox","ua.os.ver":"UNKNOWN","ua.os.family":"Linux","ua.browser.family":"Firefox","uri.method":"POST","ua":"143.0.1","ua.browser.ver":"143.0.1"}
Nov 18 15:32:10.900 INFO {"ua.os.family":"Linux","ua.name":"Firefox","uri.method":"POST","ua.browser.family":"Firefox","ua":"143.0.1","ua.os.ver":"UNKNOWN","ua.browser.ver":"143.0.1","uri.path":"/1.5/4/storage/forms?batch=MTc2MzQ5NDMzMDU2NA%3D%3D"}
Nov 18 15:32:11.012 INFO {"ua.os.family":"Linux","ua.browser.family":"Firefox","ua":"143.0.1","ua.name":"Firefox","ua.browser.ver":"143.0.1","uri.method":"POST","uri.path":"/1.5/4/storage/forms?batch=MTc2MzQ5NDMzMDU2NA%3D%3D","ua.os.ver":"UNKNOWN"}
Nov 18 15:32:11.326 INFO {"ua.os.ver":"UNKNOWN","uri.method":"POST","uri.path":"/1.5/4/storage/forms?batch=MTc2MzQ5NDMzMDU2NA%3D%3D","ua.browser.family":"Firefox","ua.browser.ver":"143.0.1","ua":"143.0.1","ua.name":"Firefox","ua.os.family":"Linux"}
Nov 18 15:32:11.440 INFO {"ua.browser.ver":"143.0.1","uri.path":"/1.5/4/storage/forms?batch=MTc2MzQ5NDMzMDU2NA%3D%3D&commit=true","ua.browser.family":"Firefox","ua.name":"Firefox","ua.os.family":"Linux","ua":"143.0.1","ua.os.ver":"UNKNOWN","uri.method":"POST"}
Nov 18 15:32:11.465 INFO {"uri.method":"DELETE","ua.os.ver":"UNKNOWN","uri.path":"/1.5/4/storage/history","ua.os.family":"Linux","ua.browser.family":"Firefox","ua":"143.0.1","ua.browser.ver":"143.0.1","ua.name":"Firefox"}
Nov 18 15:32:11.553 INFO {"ua.name":"Firefox","ua":"143.0.1","ua.browser.family":"Firefox","ua.browser.ver":"143.0.1","ua.os.family":"Linux","uri.path":"/1.5/4/storage/history?batch=true&commit=true","ua.os.ver":"UNKNOWN","uri.method":"POST"}
Nov 18 15:32:11.581 INFO {"ua.os.family":"Linux","ua.browser.ver":"143.0.1","ua":"143.0.1","ua.name":"Firefox","ua.os.ver":"UNKNOWN","uri.method":"DELETE","ua.browser.family":"Firefox","uri.path":"/1.5/4/storage/extension-storage"}
Nov 18 15:32:11.625 INFO {"uri.method":"PUT","ua.os.family":"Linux","ua.browser.family":"Firefox","ua.name":"Firefox","ua.os.ver":"UNKNOWN","uri.path":"/1.5/4/storage/meta/global","ua":"143.0.1","ua.browser.ver":"143.0.1"}
{"Type":"glean-server-event","Fields":{"document_namespace":"syncstorage","document_type":"events","document_version":"1","document_id":"3e0bff48-7aba-4211-b18a-881af7293590","user_agent":"Firefox/143.0.1 (Linux x86_64) FxSync/1.145.0.20250919025228.desktop","ip_address":"","payload":"{\"client_info\":{\"telemetry_sdk_build\":\"glean_parser v15.0.2.dev17+g81fec69a\",\"first_run_date\":\"Unknown\",\"os\":\"Unknown\",\"os_version\":\"Unknown\",\"architecture\":\"Unknown\",\"app_build\":\"Unknown\",\"app_display_version\":\"0.21.1\",\"app_channel\":\"dev\"},\"ping_info\":{\"seq\":0,\"start_time\":\"2025-11-18T19:32:54.962985500+00:00\",\"end_time\":\"2025-11-18T19:32:54.962985500+00:00\"},\"metrics\":{\"string\":{\"syncstorage.hashed_fxa_uid\":\"219bed8587083fa641df6720037d0059\",\"syncstorage.platform\":\"firefoxdesktop\",\"syncstorage.device_family\":\"desktop\",\"syncstorage.hashed_device_id\":\"e9b3dfda5cd0f6f3a118a90ccbfab61f\"}},\"events\":[{\"category\":\"syncstorage\",\"name\":\"get_collections\",\"timestamp\":1763494374962,\"extra\":{}}]}"}}
Nov 18 15:32:54.964 INFO {"ua.name":"Firefox","uri.method":"GET","uri.path":"/1.5/4/info/collections","ua.os.ver":"UNKNOWN","ua.browser.family":"Firefox","ua.os.family":"Linux","ua":"143.0.1","ua.browser.ver":"143.0.1"}
Nov 18 15:32:54.974 INFO {"ua":"143.0.1","uri.path":"/1.5/4/info/configuration","ua.os.ver":"UNKNOWN","ua.browser.family":"Firefox","ua.name":"Firefox","uri.method":"GET","ua.browser.ver":"143.0.1","ua.os.family":"Linux"}
Nov 18 15:32:54.987 INFO {"uri.path":"/1.5/4/storage/meta/global","ua":"143.0.1","ua.os.ver":"UNKNOWN","ua.name":"Firefox","ua.browser.family":"Firefox","uri.method":"GET","ua.browser.ver":"143.0.1","ua.os.family":"Linux"}
Nov 18 15:32:55.000 INFO {"ua.os.ver":"UNKNOWN","uri.method":"GET","ua.os.family":"Linux","ua.browser.family":"Firefox","ua.name":"Firefox","ua":"143.0.1","uri.path":"/1.5/4/storage/clients?full=1&limit=1000","ua.browser.ver":"143.0.1"}
Nov 18 15:32:55.028 INFO {"uri.path":"/1.5/4/storage/tabs?batch=true&commit=true","ua.browser.ver":"143.0.1","ua.os.family":"Linux","uri.method":"POST","ua.os.ver":"UNKNOWN","ua.name":"Firefox","ua.browser.family":"Firefox","ua":"143.0.1"}

So based on this it must be something specific to the way Synology has configured their MariaDB setup. I'll dig a bit deeper into the database config as this proves that it is not a MariaDB issue (at least not with the patch deployed).

mreid-tt avatar Nov 18 '25 19:11 mreid-tt

One difference as you mentioned is that the local setup is using a unix socket. It's the same one used by previous versions of syncstorage-rs that worked well. The permissions seem to allow for anyone to use it so I'm not sure it's a permission issue (especially since the database setup using diesel migrations all work fine using the same socket):

$ ls -al /run/mysqld/mysqld10.sock
srwxrwxrwx 1 mysql mysql 0 Nov 17 13:19 /run/mysqld/mysqld10.sock

Okay, I switched the local server to enable a TCP connection and set the config in the local.toml file to connect via the IP address 127.0.0.1. Funny enough that worked. So it's not the MariaDB but something using unix sockets which is somehow different in the current deployment than with the previous version. Any thoughts on why diesel migrations work but not syncstorage connections?

EDIT: Here's the server log working using an IP of 127.0.0.1 to the local MariaDB:

Tue Nov 18 15:57:40 AST 2025
Starting ffsync command env RUST_LOG=debug RUST_BACKTRACE=full /volume1/@appstore/ffsync/bin/syncserver --config=/volume1/@appdata/ffsync/local.toml
Nov 18 15:57:40.162 INFO starting 4 workers
Nov 18 15:57:40.162 INFO Server running on http://0.0.0.0:8132 (mysql) (available_parallelism: Ok(4) num_cpus: 4 num_cpus (phys): 4) No quota
Nov 18 15:57:40.162 INFO Actix runtime found; starting in Actix runtime
Nov 18 15:57:40.162 INFO starting service: "actix-web-service-0.0.0.0:8132", workers: 4, listening on: 0.0.0.0:8132
{"Type":"glean-server-event","Fields":{"document_namespace":"syncstorage","document_type":"events","document_version":"1","document_id":"cd0d4b93-4d53-4a72-b9e4-18173e15f49a","user_agent":"Firefox/143.0.1 (Linux x86_64) FxSync/1.145.0.20250919025228.desktop","ip_address":"","payload":"{\"client_info\":{\"telemetry_sdk_build\":\"glean_parser v15.0.2.dev17+g81fec69a\",\"first_run_date\":\"Unknown\",\"os\":\"Unknown\",\"os_version\":\"Unknown\",\"architecture\":\"Unknown\",\"app_build\":\"Unknown\",\"app_display_version\":\"0.21.1\",\"app_channel\":\"dev\"},\"ping_info\":{\"seq\":0,\"start_time\":\"2025-11-18T19:57:44.587867413+00:00\",\"end_time\":\"2025-11-18T19:57:44.587867413+00:00\"},\"metrics\":{\"string\":{\"syncstorage.device_family\":\"desktop\",\"syncstorage.platform\":\"firefoxdesktop\",\"syncstorage.hashed_device_id\":\"e9b3dfda5cd0f6f3a118a90ccbfab61f\",\"syncstorage.hashed_fxa_uid\":\"219bed8587083fa641df6720037d0059\"}},\"events\":[{\"category\":\"syncstorage\",\"name\":\"get_collections\",\"timestamp\":1763495864587,\"extra\":{}}]}"}}
Nov 18 15:57:44.588 INFO {"ua.browser.family":"Firefox","ua.name":"Firefox","ua.browser.ver":"143.0.1","ua.os.ver":"UNKNOWN","ua":"143.0.1","uri.method":"GET","uri.path":"/1.5/4/info/collections","ua.os.family":"Linux"}
Nov 18 15:57:44.598 INFO {"ua.os.ver":"UNKNOWN","uri.method":"GET","ua":"143.0.1","uri.path":"/1.5/4/info/configuration","ua.name":"Firefox","ua.browser.family":"Firefox","ua.os.family":"Linux","ua.browser.ver":"143.0.1"}
Nov 18 15:57:44.612 INFO {"ua.browser.ver":"143.0.1","ua.name":"Firefox","uri.method":"GET","ua.os.family":"Linux","ua":"143.0.1","ua.browser.family":"Firefox","uri.path":"/1.5/4/storage/clients?full=1&limit=1000","ua.os.ver":"UNKNOWN"}
Nov 18 15:57:44.638 INFO {"uri.method":"POST","ua.name":"Firefox","ua.browser.family":"Firefox","ua.os.family":"Linux","ua.browser.ver":"143.0.1","ua":"143.0.1","uri.path":"/1.5/4/storage/tabs?batch=true&commit=true","ua.os.ver":"UNKNOWN"}

mreid-tt avatar Nov 18 '25 19:11 mreid-tt

Confirmed Behavior Update Based on Local Testing

I’ve completed additional testing on syncstorage-rs v0.21.1 (with the diesel-async backend) and can confirm the following:

  1. Earlier versions (e.g., v0.18.3) used synchronous Diesel (v2.1.6). In those versions, database URLs of the form:

    mysql://user:pass@localhost/dbname

    worked correctly without any socket parameters. Diesel/MySQL automatically treated localhost as a Unix-socket connection, so MariaDB did not need to expose a TCP listener.

  2. In v0.21.x, after the migration to diesel-async, this behavior changed:

    • localhost no longer falls back to the Unix socket.

    • The old parameter ?unix_socket=/path is not recognized (as noted in https://github.com/mozilla-services/syncstorage-rs/issues/1843#issuecomment-3410340603).

    • Without a TCP listener, syncstorage-rs fails with:

      DieselConnection(BadConnection("Input/output error: Connection refused (os error 111)"))

  3. However, Unix-socket connections do still work—they just require the new DSN parameter:

    ?socket=/run/mysqld/mysqld10.sock

    Adding this to both syncstorage.database_url and tokenserver.database_url restores full functionality. Example:

    mysql://user:pass@localhost/syncstorage_rs?socket=/run/mysqld/mysqld10.sock

  4. After adding the ?socket= parameter, the service works normally even with MariaDB TCP networking disabled.

Conclusion

This confirms a behavior change between the synchronous Diesel backend and the current diesel-async backend: Unix sockets are still supported, but automatic socket detection via localhost no longer occurs, and the explicit ?socket= parameter is now required for socket-only installations.

mreid-tt avatar Nov 19 '25 05:11 mreid-tt