sync stopped working: "Unsupported application"

[0-wiz-0]

Hi!

I'm running syncstorage-rs on my own server, using the login token from mozilla.org, but the storage there.

This has been working for a long time now, but sometime in the last months it stopped working. I can't date it more closely because I usually work on the same machine, but when I switched to the laptop, I noticed that it wasn't up-to-date.

I did update syncstorage-rs a couple times in the last months. I noticed the problem while running 0.20.0, but I went back to older versions and it doesn't work with 0.18.3 nor 0.18.2. I think it was working correctly with that version before. So I currently suspect a firefox update might have broken it (running 142 now).

I tried reading the server logs and the about:sync-log, but there are not enough details for me to understand the problem.

Here's the sync-log from a recent try, only edited to replace my host name:

1758459231253	Sync.LogManager	DEBUG	Flushing file log
1758459231266	Sync.LogManager	DEBUG	Log cleanup threshold time: 1757595231266
1758459231290	Sync.LogManager	DEBUG	Done deleting files.
1758459231669	FirefoxAccounts	INFO	Polling device commands.
1758459231669	Sync.Service	DEBUG	User-Agent: Firefox/142.0.1 (Intel Mac OS X 10.15) FxSync/1.144.0.20250827004350.desktop
1758459231669	Sync.Service	INFO	Starting sync at 2025-09-21 14:53:51 in browser session nRAmjVsnHpUk
1758459231669	Sync.Service	DEBUG	In sync: should login.
1758459231669	Sync.Service	INFO	User logged in successfully - verifying login.
1758459231670	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1758459231670	Sync.SyncAuthManager	DEBUG	unlockAndVerifyAuthState already has (or can fetch) sync keys
1758459231670	Sync.Status	DEBUG	Status.login: error.login.reason.network => success.status_ok
1758459231670	Sync.Status	DEBUG	Status.service: error.login.failed => error.login.failed
1758459231670	Sync.Service	DEBUG	Fetching unlocked auth state returned success.status_ok
1758459231670	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1758459231670	Sync.SyncAuthManager	INFO	Getting sync key
1758459231670	FirefoxAccounts	DEBUG	getOAuthToken enter
1758459231670	FirefoxAccounts	TRACE	getCachedToken returning cached token
1758459231670	FirefoxAccounts	DEBUG	getOAuthToken returning a cached token
1758459231670	Sync.SyncAuthManager	INFO	Getting a sync token from: https://sync.mydomain.at/1.0/token/1.5
1758459231670	Sync.SyncAuthManager	DEBUG	Getting a token using OAuth
1758459231670	Services.Common.TokenServerClient	DEBUG	Beginning OAuth token exchange: https://sync.mydomain.at/1.0/token/1.5
1758459231670	Services.Common.RESTRequest	DEBUG	GET request to https://sync.mydomain.at/1.0/token/1.5
1758459231671	Services.Common.RESTRequest	DEBUG	GET request to https://api.accounts.firefox.com/v1/account/device/commands?index=0
1758459231693	Services.Common.RESTRequest	DEBUG	GET https://sync.mydomain.at/1.0/token/1.5 404
1758459231693	Services.Common.TokenServerClient	DEBUG	Got token response: 404
1758459231693	Services.Common.TokenServerClient	INFO	Server-reported error: {"location":"url","name":"application","description":"Unsupported application"}
1758459231693	Sync.SyncAuthManager	ERROR	Non-authentication error in _fetchTokenForUser: TokenServerClientServerError({"now":"2025-09-21T12:53:51.693Z","message":"Unknown service.","cause":"unknown-service","response_body":"{\"status\":\"error\",\"errors\":[{\"location\":\"url\",\"name\":\"application\",\"description\":\"Unsupported application\"}]}","response_headers":{"server":"nginx/1.28.0","date":"Sun, 21 Sep 2025 12:53:51 GMT","content-type":"application/json","content-length":"109","connection":"keep-alive","x-weave-timestamp":"1758459231.71","vary":"Origin, Access-Control-Request-Method, Access-Control-Request-Headers"},"response_status":404})(resource://services-common/tokenserverclient.sys.mjs:28:36) JS Stack trace: TokenServerClientServerError@tokenserverclient.sys.mjs:90:16
_processTokenResponse@tokenserverclient.sys.mjs:306:19
_tokenServerExchangeRequest@tokenserverclient.sys.mjs:239:19
1758459231693	Sync.Status	DEBUG	Status.login: success.status_ok => error.login.reason.network
1758459231693	Sync.Status	DEBUG	Status.service: error.login.failed => error.login.failed
1758459231693	Sync.SyncAuthManager	INFO	Failed to fetch the cluster URL: TokenServerClientServerError({"now":"2025-09-21T12:53:51.693Z","message":"Unknown service.","cause":"unknown-service","response_body":"{\"status\":\"error\",\"errors\":[{\"location\":\"url\",\"name\":\"application\",\"description\":\"Unsupported application\"}]}","response_headers":{"server":"nginx/1.28.0","date":"Sun, 21 Sep 2025 12:53:51 GMT","content-type":"application/json","content-length":"109","connection":"keep-alive","x-weave-timestamp":"1758459231.71","vary":"Origin, Access-Control-Request-Method, Access-Control-Request-Headers"},"response_status":404})(resource://services-common/tokenserverclient.sys.mjs:28:36) JS Stack trace: TokenServerClientServerError@tokenserverclient.sys.mjs:90:16
_processTokenResponse@tokenserverclient.sys.mjs:306:19
_tokenServerExchangeRequest@tokenserverclient.sys.mjs:239:19
1758459231694	Sync.Service	DEBUG	verifyLogin failed: TokenServerClientServerError({"now":"2025-09-21T12:53:51.693Z","message":"Unknown service.","cause":"unknown-service","response_body":"{\"status\":\"error\",\"errors\":[{\"location\":\"url\",\"name\":\"application\",\"description\":\"Unsupported application\"}]}","response_headers":{"server":"nginx/1.28.0","date":"Sun, 21 Sep 2025 12:53:51 GMT","content-type":"application/json","content-length":"109","connection":"keep-alive","x-weave-timestamp":"1758459231.71","vary":"Origin, Access-Control-Request-Method, Access-Control-Request-Headers"},"response_status":404})(resource://services-common/tokenserverclient.sys.mjs:28:36) JS Stack trace: TokenServerClientServerError@tokenserverclient.sys.mjs:90:16
_processTokenResponse@tokenserverclient.sys.mjs:306:19
_tokenServerExchangeRequest@tokenserverclient.sys.mjs:239:19
1758459231694	Sync.Status	DEBUG	Status.login: error.login.reason.network => error.login.reason.network
1758459231694	Sync.Status	DEBUG	Status.service: error.login.failed => error.login.failed
1758459231694	Sync.ErrorHandler	ERROR	Sync encountered a login error
1758459231694	Sync.SyncScheduler	DEBUG	Clearing sync triggers and the global score.
1758459231694	Sync.SyncScheduler	DEBUG	Next sync in 3600000 ms. (why=schedule)
1758459231694	Sync.Service	DEBUG	Exception calling WrappedLock: Error: Login failed: error.login.reason.network(resource://services-sync/service.sys.mjs:1051:15) JS Stack trace: onNotify@service.sys.mjs:1051:15
1758459231694	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1758459231694	Sync.Service	DEBUG	Not syncing: login returned false.
1758459231695	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent

In the nginx access log on the server, I see two lines, one second apart:

[21/Sep/2025:14:57:51 +0200] "GET /1.0/token/1.5 HTTP/1.1" 404 109 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:142.0) Gecko/20100101 Firefox/142.0"
[21/Sep/2025:14:57:52 +0200] "GET /1.0/token/1.5 HTTP/1.1" 404 109 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:142.0) Gecko/20100101 Firefox/142.0"

I see nothing on stdout or stderr from the syncserver process itself.

I can get a heartbeat, so I don't think I broke the nginx config since it was working:

{"database":"Ok","quota":{"enabled":false,"size":0},"version":"0.18.2","status":"Ok"}

I've configured identity.sync.tokenserver.uri to https://sync.mydomain.at/1.0/token/1.5, which was working before.

I'd be happy about pointers how to debug and fix this.

Thank you.

[0-wiz-0]

Does anyone have any ideas about this?

[felfert]

Does anyone have any ideas about this?

Not without more info and logging from the server side. (Apart from the fact, that 404 means "Not found", but that you probably know yourself already)

E.g:

• Are you using a container or is this a native installation?
• What value is your RUST_LOG environment variable?
• Is the first record in the nodes table of the tokenserver DB reflecting your domain correctly? (The field "node" should contain your server's URL (toplevel, without any path)

[0-wiz-0]

Thanks for the reply. I'm happy to provide more information:

• This is a native installation, using the pkgsrc package, with a mariadb database.
• RUST_LOG is not set in the environment. What are valid values for that that I should try?
• Yes, there is only one entry in the nodes table, and it provides the correct name (https://sync.mydomain.at)

[felfert]

Ok, googling for pkgsrc, I found this and I am guessing you are the package maintainer. Correct?

RUST_LOG is not set in the environment. What are valid values for that that I should try?

See: this doc, However looking at the package source, your packaging does a --release build which means, that the more verbose levels debug and trace are disabled by default. So: in order to make them available, you need to remove the --release flag by overriding CARGO_ARGS (Something similar is commented out in your Makefile). Alternatively, you can use this patch to enable all log levels even in --release builds.

The pkgsrc also shows, that you are using the 0.21.1 upstream release. This version definitively requires this patch in order to restore mariadb compatibility. That patch has already been merged (#1856), but there was no release since then. Both patches are taken from my packaging for Fedora/RHEL/Ubuntu.

Good luck
-Fritz

[0-wiz-0]

Yes, this is the correct package, and I'm the maintainer.

I've added the two patches you referenced to the package, and tried again with RUST_LOG set to DEBUG. The syncserver log only has a couple lines for a failed try (after the startup lines):

Dec 04 00:20:47.904 DEBG Starting up...
Dec 04 00:20:48.531 INFO starting 2 workers
Dec 04 00:20:48.532 INFO Server running on http://127.0.0.1:5000 (mysql) (available_parallelism: Ok(2) num_cpus: 2 num_cpus (phys): 2) No quota
Dec 04 00:20:48.532 INFO Actix runtime found; starting in Actix runtime
Dec 04 00:20:48.532 INFO starting service: "actix-web-service-127.0.0.1:5000", workers: 2, listening on: 127.0.0.1:5000
Dec 04 00:28:11.317 DEBG Reporting error to Sentry (response error): Unsupported application
Dec 04 00:28:11.319 INFO {"token_type":"OAuth","ua":"145.0","ua.browser.family":"Firefox","ua.name":"Firefox","ua.os.ver":"10.15","uri.path":"/1.0/token/1.5","uid":"XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
XXXXXXXXXXXXX","metrics_uid":"XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX","uri.method":"GET","ua.os.family":"Mac OSX","ua.browser.ver":"145.0"}
Dec 04 00:28:12.597 DEBG Reporting error to Sentry (response error): Unsupported application
Dec 04 00:28:12.598 INFO {"ua.os.family":"Mac OSX","ua.name":"Firefox","uri.method":"GET","ua.browser.family":"Firefox","uri.path":"/1.0/token/1.5","token_type":"OAuth","ua.browser.ver":"145.0","metrics_uid":"XXXXXXXX
XXXXXXXXXXXXXXXXXXXXXXXX","ua":"145.0","ua.os.ver":"10.15","uid":"XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX"}

So there's a new "Unsupported application" error. Is that relevant?

(Thanks for the hint about the database connection string, I had already used the simple version that needed no changes.)

[felfert]

Forgot something important about 0.21.1:

The database parameter syntax has changed as well. Here is a table that shows the differences.

[felfert]

Well, it actually looks really like a client side (FireFox) error.
It should start authenticating with:

GET https://your.server.tld/1.0/sync/1.5 NOT https://your.server.tld/1.0/token/1.5

The second path element is the "application name" and is expected to be "sync", not "token". That's the reason for the unsupported application error.

This begs the question: Why is your FireFox requesting that URL.
So: Have a look in your about:config. In my firefox, I have

identity.sync.tokenserver.uri = https://syncserver.domain.tld/1.0/sync/1.5

Yours should be similar.
Unfortunately, as a fellow packager, I don't have a very deep understanding of the protocol mechanisms.
So: If your variable is correct, then perhaps you can try a logout/login from your mozilla account (and check that variable afterwards).

-Fritz

[felfert]

Hmm, might be some race condition.
Can you do that what your previous log suggests and set the environment variable RUST_BACKTRACE=1 ?
Maybe a backtrace gives us some more hints.

[0-wiz-0]

The backtrace, even with RUST_BACKTRACE=full, is not helpful:

thread 'tokio-runtime-worker' panicked at /usr/pkgsrc/www/syncstorage-rs/work/vendor/diesel-2.2.12/src/mysql/value.rs:69:76:
range end index 4 out of range for slice of length 0
stack backtrace:
   0:         0x1002f432 - <unknown>
   1:         0x100558f3 - <unknown>
   2:         0x1002be13 - <unknown>
   3:         0x1002f282 - <unknown>
   4:         0x1003060e - <unknown>
   5:         0x100303d5 - <unknown>
   6:         0x1003113c - <unknown>
   7:         0x10030d5a - <unknown>
   8:         0x1002f909 - <unknown>
   9:         0x100309ed - <unknown>
  10:          0xf9051f0 - <unknown>
  11:          0xf9059f7 - <unknown>
  12:          0xf90561a - <unknown>
  13:          0xfd19eb9 - <unknown>
  14:          0xfd121ae - <unknown>
  15:          0xfc1dec1 - <unknown>
  16:          0xfc02af3 - <unknown>
  17:          0xfc20f79 - <unknown>
  18:          0xfc563f7 - <unknown>
  19:          0xfc0604d - <unknown>
  20:          0xfc77fa4 - <unknown>
  21:          0xfc38386 - <unknown>
  22:          0xfec62f9 - <unknown>
  23:          0xfeb8ce1 - <unknown>
  24:          0xfeca453 - <unknown>
  25:         0x10033e5f - <unknown>
  26:     0x7e3312a0c89f - pthread__create_tramp
  27:     0x7e33120930e0 - <unknown>
Dec 05 23:21:09.645 DEBG Reporting error to Sentry (response error): Unexpected error: poisoned lock: another task failed inside

[0-wiz-0]

Line 69 of the file is the from_ne_bytes line below:

impl<'a> MysqlValue<'a> {
...
    /// Returns the numeric representation of this value, based on the type code.
    /// Returns an error if the type code is not numeric.
    pub(crate) fn numeric_value(&self) -> deserialize::Result<NumericRepresentation<'_>> {
        Ok(match self.tpe {
...
            MysqlType::UnsignedLong | MysqlType::Long => {
                NumericRepresentation::Medium(i32::from_ne_bytes((&self.raw[..4]).try_into()?))
            }

so it seems to expect an unsigned long or long but only get zero bytes.

[felfert]

The backtrace, even with RUST_BACKTRACE=full, is not helpful:

Most likely because you have a release build. You need a debug build (with debug symbols in the binary). Also watch out for RUSTFLAGS that might strip symbols later at the link phase.

[felfert]

Also: Try setting RUST_LOG="diesel_logger=trace"

This should log the SQL queries and maybe you can find out which data is the trigger for this error. This needs a --debug build too.

Correction: This does not work anymore (probably sice the switch to diesel_async)

[felfert]

And another tip:

There is a very nice Extension : https://addons.mozilla.org/en-US/firefox/addon/about-sync/

It implements about:sync with better info/features than about:sync-log

[0-wiz-0]

Thanks for all the help, @felfert
I had to collect some motivation, but I've now tried again with a debug build, and this actually gave me more information (as you noticed, the diesel_logger doesn't work any longer):

Dec 29 18:32:55.852 DEBG QUERY: [0.6ms]: SELECT collection, last_modified
               FROM user_collections
              WHERE userid = ?
               AND collection != ? -- binds: [4, 0]
Dec 29 18:32:55.853 DEBG QUERY: [0.9ms]: SELECT `collections`.`id`, `collections`.`name` FROM `collections` WHERE (`collections`.`id` IN (?)) -- binds: [101]
Dec 29 18:32:55.926 DEBG QUERY: [0.5ms]: SELECT `user_collections`.`last_modified` FROM `user_collections` WHERE ((`user_collections`.`userid` = ?) AND (`user_collections`.`collection` = ?)) LIMIT ? LOCK IN SHARE MODE --
 binds: [4, 1, 1]
Dec 29 18:32:55.929 DEBG QUERY: [0.7ms]: SELECT `bso`.`id`, `bso`.`modified`, `bso`.`payload`, `bso`.`sortindex`, `bso`.`ttl` FROM `bso` WHERE (((`bso`.`userid` = ?) AND (`bso`.`collection` = ?)) AND (`bso`.`ttl` > ?)) L
IMIT ? -- binds: [4, 1, 1767029575920, 1001]
Dec 29 18:32:56.412 DEBG QUERY: [0.4ms]: SELECT `user_collections`.`last_modified` FROM `user_collections` WHERE ((`user_collections`.`userid` = ?) AND (`user_collections`.`collection` = ?)) LIMIT ? LOCK IN SHARE MODE --
 binds: [4, 7, 1]
Dec 29 18:32:56.418 DEBG QUERY: [4.8ms]: SELECT `bso`.`id`, `bso`.`modified`, `bso`.`payload`, `bso`.`sortindex`, `bso`.`ttl` FROM `bso` WHERE ((((`bso`.`userid` = ?) AND (`bso`.`collection` = ?)) AND (`bso`.`ttl` > ?))
AND (`bso`.`modified` > ?)) ORDER BY `bso`.`modified` ASC, `bso`.`id` ASC LIMIT ? -- binds: [4, 7, 1767029576410, 1764953617540, 1001]

thread 'tokio-runtime-worker' panicked at /usr/pkgsrc/www/syncstorage-rs/work/vendor/diesel-2.2.12/src/mysql/value.rs:69:76:
range end index 4 out of range for slice of length 0
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

[0-wiz-0]

I gave up on using this.