Sync did not work, how to find the problem?
Look for ERROR messages in the firefox sync protocol: about:sync-log (copy&paste into firefox address bar)
Or Firefox Console Log: CTRL + SHIT + J
Firefox could not login into sync storage server (async timestamp between account & storage server)
Time delta between mozilla acount server and own sync storage server is too large. Fix time offset on own sync storage server.
sudo timedatectl set-ntp true
Example logging for a firefox sync-log of this problem:
1668096601259 FirefoxAccounts TRACE initializing new storage manager
1668096601259 FirefoxAccounts TRACE starting fetch of json user data
1668096601285 FirefoxAccounts TRACE finished fetch of json user data - took: 26
1668096601285 FirefoxAccounts DEBUG reading secure storage with existing: []
1668096601286 FirefoxAccounts TRACE starting fetch of user data from the login manager
1668096601286 FirefoxAccounts INFO returning partial account data as the login manager is locked.
1668096601286 FirefoxAccounts DEBUG setAccountData: secure storage is locked trying to read
1668096601286 FirefoxAccounts TRACE initializing of new storage manager done
1668096601286 FirefoxAccounts DEBUG reading secure storage with existing: []
1668096601287 FirefoxAccounts TRACE starting fetch of user data from the login manager
1668096601287 FirefoxAccounts INFO returning partial account data as the login manager is locked.
1668096601287 FirefoxAccounts DEBUG setAccountData: secure storage is locked trying to read
1668096601287 FirefoxAccounts DEBUG reading secure storage with existing: []
1668096601288 FirefoxAccounts TRACE starting fetch of user data from the login manager
1668096601288 FirefoxAccounts INFO returning partial account data as the login manager is locked.
1668096601288 FirefoxAccounts DEBUG setAccountData: secure storage is locked trying to read
1668096601288 FirefoxAccounts DEBUG reading secure storage with existing: []
1668096601288 FirefoxAccounts TRACE starting fetch of user data from the login manager
1668096601289 FirefoxAccounts INFO returning partial account data as the login manager is locked.
1668096601289 FirefoxAccounts DEBUG setAccountData: secure storage is locked trying to read
1668096601337 Services.Common.RESTRequest DEBUG GET request to https://api.accounts.firefox.com/v1/account/attached_clients
1668096601356 Sync.Status INFO Resetting Status.
1668096601356 Sync.Status DEBUG Status.service: undefined => success.status_ok
1668096601358 Sync.SyncScheduler TRACE Setting SyncScheduler policy values to defaults.
1668096601358 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score.
1668096601359 Sync.Service INFO Loading Weave 1.108.0
1668096601359 Sync.Engine.Clients DEBUG Engine constructed
1668096601360 Sync.Engine.Clients DEBUG Resetting clients last sync time
1668096601362 Sync.Engine.Addons DEBUG Engine constructed
1668096601373 Sync.Engine.Addons DEBUG SyncEngine initialized: addons
1668096601376 Sync.Engine.Bookmarks DEBUG Engine constructed
1668096601398 Sync.Engine.Bookmarks DEBUG SyncEngine initialized: bookmarks
1668096601399 Sync.Engine.Forms DEBUG Engine constructed
1668096601409 Sync.Engine.Forms DEBUG SyncEngine initialized: forms
1668096601410 Sync.Engine.History DEBUG Engine constructed
1668096601416 FirefoxAccounts DEBUG FxAccountsWebChannel registered: account_updates with origin https://accounts.firefox.com
1668096601425 FirefoxAccounts DEBUG FxAccountsProfileClient: Initialized
1668096601425 FirefoxAccounts DEBUG FxAccountsProfileClient: Requested profile
1668096601425 FirefoxAccounts DEBUG getOAuthToken enter
1668096601425 FirefoxAccounts DEBUG reading secure storage with existing: []
1668096601425 FirefoxAccounts TRACE starting fetch of user data from the login manager
1668096601426 FirefoxAccounts INFO returning partial account data as the login manager is locked.
1668096601426 FirefoxAccounts DEBUG setAccountData: secure storage is locked trying to read
1668096601426 FirefoxAccounts TRACE getCachedToken returning cached token
1668096601426 FirefoxAccounts DEBUG getOAuthToken returning a cached token
1668096601428 FirefoxAccounts INFO fetching updated device list
1668096601428 FirefoxAccounts DEBUG reading secure storage with existing: []
1668096601428 FirefoxAccounts TRACE starting fetch of user data from the login manager
1668096601428 Services.Common.RESTRequest DEBUG GET request to https://profile.accounts.firefox.com/v1/profile
1668096601429 FirefoxAccounts INFO returning partial account data as the login manager is locked.
1668096601429 FirefoxAccounts DEBUG setAccountData: secure storage is locked trying to read
1668096601431 Services.Common.RESTRequest DEBUG GET request to https://api.accounts.firefox.com/v1/account/devices
1668096601527 Sync.Engine.History DEBUG SyncEngine initialized: history
1668096601529 Sync.Engine.Passwords DEBUG Engine constructed
1668096601545 Sync.Engine.Passwords DEBUG SyncEngine initialized: passwords
1668096601546 Sync.Engine.Prefs DEBUG Engine constructed
1668096601588 Sync.Engine.Prefs DEBUG SyncEngine initialized: prefs
1668096601589 Sync.Engine.Tabs DEBUG Engine constructed
1668096601604 Sync.Engine.Tabs DEBUG SyncEngine initialized: tabs
1668096601604 Sync.Engine.Tabs DEBUG Resetting tabs last sync time
1668096601605 Sync.Engine.CreditCards DEBUG Engine constructed
1668096601607 Sync.Engine.CreditCards DEBUG SyncEngine initialized: creditcards
1668096601608 Sync.Engine.Extension-Storage DEBUG Engine constructed
1668096601623 Sync.Engine.Extension-Storage DEBUG SyncEngine initialized: extension-storage
1668096601623 Sync.Service INFO Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:106.0) Gecko/20100101 Firefox/106.0
1668096601624 Sync.AddonsReconciler INFO Registering as Add-on Manager listener.
1668096601624 Sync.AddonsReconciler DEBUG Adding change listener.
1668096601624 Sync.Engine.History.Tracker INFO Adding Places observer.
1668096601628 FirefoxAccounts INFO Already fetching device list, return existing promise
1668096601629 Sync.Service DEBUG User-Agent: Firefox/106.0.5 (Windows NT 10.0; Win64; x64) FxSync/1.108.0.20221104133228.desktop
1668096601629 Sync.Service INFO Starting sync at 2022-11-10 17:10:01 in browser session gUvexHDF421g
1668096601630 Sync.Service DEBUG In sync: should login.
1668096601630 Sync.Service INFO User logged in successfully - verifying login.
1668096601630 FirefoxAccounts DEBUG reading secure storage with existing: []
1668096601630 FirefoxAccounts TRACE starting fetch of user data from the login manager
1668096601631 FirefoxAccounts INFO returning partial account data as the login manager is locked.
1668096601631 FirefoxAccounts DEBUG setAccountData: secure storage is locked trying to read
1668096601631 FirefoxAccounts INFO Can't get keys; no key material or tokens available
1668096602455 Services.Common.RESTRequest DEBUG GET https://profile.accounts.firefox.com/v1/profile 304
1668096602490 Services.Common.RESTRequest DEBUG GET https://api.accounts.firefox.com/v1/account/devices 200
1668096602490 Hawk DEBUG (Response) /account/devices: code: 200 - Status text: OK
1668096602490 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -490
1668096602490 FirefoxAccounts INFO Got new device list: 1778922....
1668096602491 FirefoxAccounts INFO updating the cache
1668096602524 Services.Common.RESTRequest DEBUG GET https://api.accounts.firefox.com/v1/account/attached_clients 200
1668096602524 Hawk DEBUG (Response) /account/attached_clients: code: 200 - Status text: OK
1668096602524 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -524
1668096607376 FirefoxAccounts DEBUG reading secure storage with existing: []
1668096607376 FirefoxAccounts TRACE starting fetch of user data from the login manager
1668096607378 FirefoxAccounts DEBUG secure read fetched items: ["scopedKeys","kSync","kXCS","kExtSync","kExtKbHash"]
1668096607382 Sync.SyncAuthManager DEBUG unlockAndVerifyAuthState re-fetched credentials and is returning: success.status_ok
1668096607382 Sync.Status DEBUG Status.login: success.login => success.status_ok
1668096607382 Sync.Status DEBUG Status.service: success.status_ok => error.login.failed
1668096607382 Sync.Service DEBUG Fetching unlocked auth state returned success.status_ok
1668096607382 FirefoxAccounts TRACE not checking freshness of profile as it remains recent
1668096607383 Sync.SyncAuthManager INFO Getting sync key
1668096607383 Sync.SyncAuthManager INFO Getting a sync token from: https://x.y.z/1.0/sync/1.5
1668096607383 Sync.SyncAuthManager DEBUG Getting a token using OAuth
1668096607383 FirefoxAccounts DEBUG getOAuthToken enter
1668096607404 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/oauth/token
1668096607405 Services.Common.RESTRequest DEBUG POST Length: 127
1668096607603 Services.Common.RESTRequest DEBUG POST https://api.accounts.firefox.com/v1/oauth/token 200
1668096607604 Hawk DEBUG (Response) /oauth/token: code: 200 - Status text: OK
1668096607604 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -604
1668096607604 FirefoxAccounts DEBUG _updateAccountData with items: ["oauthTokens"]
1668096607604 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","device","encryptedSendTabKeys","oauthTokens","profileCache"]
1668096607604 FirefoxAccounts TRACE starting write of json user data: ["email","sessionToken","uid","verified","device","encryptedSendTabKeys","oauthTokens","profileCache"]
1668096607604 Services.Common.TokenServerClient DEBUG Beginning OAuth token exchange: https://x.y.z/1.0/sync/1.5
1668096607604 Services.Common.RESTRequest DEBUG GET request to https://x.y.z/1.0/sync/1.5
1668096607611 FirefoxAccounts TRACE finished write of json user data - took: 7
1668096607611 FirefoxAccounts DEBUG writing secure storage: ["scopedKeys","kSync","kXCS","kExtSync","kExtKbHash"]
1668096607611 FirefoxAccounts TRACE starting write of user data to the login manager
1668096607619 FirefoxAccounts TRACE finished write of user data to the login manager
1668096608585 Services.Common.RESTRequest DEBUG GET https://x.y.z/1.0/sync/1.5 401
1668096608585 Services.Common.TokenServerClient DEBUG Got token response: 401
1668096608585 Services.Common.TokenServerClient INFO Server-reported error: {"location":"body","name":"","description":"Unauthorized"}
1668096608585 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/oauth/destroy
1668096608585 Services.Common.RESTRequest DEBUG POST Length: 969
1668096608585 FirefoxAccounts DEBUG _updateAccountData with items: ["oauthTokens"]
1668096608586 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","device","encryptedSendTabKeys","oauthTokens","profileCache"]
1668096608586 FirefoxAccounts TRACE starting write of json user data: ["email","sessionToken","uid","verified","device","encryptedSendTabKeys","oauthTokens","profileCache"]
1668096608587 Sync.SyncAuthManager WARN Token server returned 401, retrying token fetch with fresh credentials
1668096608587 Sync.SyncAuthManager INFO Getting a sync token from: https://x.y.z/1.0/sync/1.5
1668096608587 Sync.SyncAuthManager DEBUG Getting a token using OAuth
1668096608587 FirefoxAccounts DEBUG getOAuthToken enter
1668096608590 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/oauth/token
1668096608590 Services.Common.RESTRequest DEBUG POST Length: 127
1668096608595 FirefoxAccounts TRACE finished write of json user data - took: 9
1668096608595 FirefoxAccounts DEBUG writing secure storage: ["scopedKeys","kSync","kXCS","kExtSync","kExtKbHash"]
1668096608595 FirefoxAccounts TRACE starting write of user data to the login manager
1668096608601 FirefoxAccounts TRACE finished write of user data to the login manager
1668096608779 Services.Common.RESTRequest DEBUG POST https://api.accounts.firefox.com/v1/oauth/destroy 200
1668096608779 Hawk DEBUG (Response) /oauth/destroy: code: 200 - Status text: OK
1668096608779 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -779
1668096608785 Services.Common.RESTRequest DEBUG POST https://api.accounts.firefox.com/v1/oauth/token 200
1668096608785 Hawk DEBUG (Response) /oauth/token: code: 200 - Status text: OK
1668096608785 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -785
1668096608785 FirefoxAccounts DEBUG _updateAccountData with items: ["oauthTokens"]
1668096608785 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","device","encryptedSendTabKeys","oauthTokens","profileCache"]
1668096608785 FirefoxAccounts TRACE starting write of json user data: ["email","sessionToken","uid","verified","device","encryptedSendTabKeys","oauthTokens","profileCache"]
1668096608785 Services.Common.TokenServerClient DEBUG Beginning OAuth token exchange: https://x.y.z/1.0/sync/1.5
1668096608786 Services.Common.RESTRequest DEBUG GET request to https://x.y.z/1.0/sync/1.5
1668096608793 FirefoxAccounts TRACE finished write of json user data - took: 8
1668096608793 FirefoxAccounts DEBUG writing secure storage: ["scopedKeys","kSync","kXCS","kExtSync","kExtKbHash"]
1668096608793 FirefoxAccounts TRACE starting write of user data to the login manager
1668096608800 FirefoxAccounts TRACE finished write of user data to the login manager
1668096608991 Services.Common.RESTRequest DEBUG GET https://x.y.z/1.0/sync/1.5 401
1668096608991 Services.Common.TokenServerClient DEBUG Got token response: 401
1668096608991 Services.Common.TokenServerClient INFO Server-reported error: {"location":"body","name":"","description":"Unauthorized"}
1668096608992 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/oauth/destroy
1668096608992 Services.Common.RESTRequest DEBUG POST Length: 969
1668096608992 FirefoxAccounts DEBUG _updateAccountData with items: ["oauthTokens"]
1668096608992 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","device","encryptedSendTabKeys","oauthTokens","profileCache"]
1668096608992 FirefoxAccounts TRACE starting write of json user data: ["email","sessionToken","uid","verified","device","encryptedSendTabKeys","oauthTokens","profileCache"]
1668096608993 Sync.SyncAuthManager ERROR Authentication error in _fetchTokenForUser: {"details":{"now":"2022-11-10T16:10:08.991Z","message":"Authentication failed.","cause":"invalid-credentials","response_body":"{\"status\":\"invalid-credentials\",\"errors\":[{\"location\":\"body\",\"name\":\"\",\"description\":\"Unauthorized\"}]}","response_headers":{"date":"Thu, 10 Nov 2022 16:09:31 GMT","server":"Apache/2.4.54 (Unix) OpenSSL/1.1.1q PHP/8.1.12 mod_wsgi/4.9.3 Python/3.10","content-length":"102","content-type":"application/json","x-weave-timestamp":"1668096571.25","x-timestamp":"1668096571258811","keep-alive":"timeout=5, max=99","connection":"Keep-Alive"},"response_status":401,"name":"TokenServerClientServerError"},"source":"tokenserver"}
1668096608993 Sync.Status DEBUG Status.login: success.status_ok => error.login.reason.account
1668096608993 Sync.Status DEBUG Status.service: error.login.failed => error.login.failed
1668096608993 Sync.SyncAuthManager INFO Failed to fetch the cluster URL: {"details":{"now":"2022-11-10T16:10:08.991Z","message":"Authentication failed.","cause":"invalid-credentials","response_body":"{\"status\":\"invalid-credentials\",\"errors\":[{\"location\":\"body\",\"name\":\"\",\"description\":\"Unauthorized\"}]}","response_headers":{"date":"Thu, 10 Nov 2022 16:09:31 GMT","server":"Apache/2.4.54 (Unix) OpenSSL/1.1.1q PHP/8.1.12 mod_wsgi/4.9.3 Python/3.10","content-length":"102","content-type":"application/json","x-weave-timestamp":"1668096571.25","x-timestamp":"1668096571258811","keep-alive":"timeout=5, max=99","connection":"Keep-Alive"},"response_status":401,"name":"TokenServerClientServerError"},"source":"tokenserver"}
1668096608993 Sync.SyncAuthManager DEBUG Cluster value = null
1668096608993 Sync.Status DEBUG Status.sync: success.sync => error.sync.reason.no_node_found
1668096608993 Sync.Status DEBUG Status.service: error.login.failed => error.sync.failed
1668096608993 FirefoxAccounts TRACE not checking freshness of profile as it remains recent
1668096608993 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score.
1668096608994 Sync.Status INFO Resetting Status.
1668096608994 Sync.Status DEBUG Status.service: error.sync.failed => success.status_ok
1668096608994 FirefoxAccounts TRACE not checking freshness of profile as it remains recent
1668096608995 Sync.SyncAuthManager INFO Getting sync key
1668096608995 Sync.SyncAuthManager INFO Getting a sync token from: https://x.y.z/1.0/sync/1.5
1668096608995 Sync.SyncAuthManager DEBUG Getting a token using OAuth
1668096608995 FirefoxAccounts DEBUG getOAuthToken enter
1668096608997 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/oauth/token
1668096608997 Services.Common.RESTRequest DEBUG POST Length: 127
1668096609002 FirefoxAccounts TRACE finished write of json user data - took: 10
1668096609002 FirefoxAccounts DEBUG writing secure storage: ["scopedKeys","kSync","kXCS","kExtSync","kExtKbHash"]
1668096609002 FirefoxAccounts TRACE starting write of user data to the login manager
1668096609010 FirefoxAccounts TRACE finished write of user data to the login manager