Closed Bug 1755440 Opened 2 years ago Closed 2 years ago

sync error

Categories

(Firefox :: Sync, defect, P3)

Product:
Firefox
Component:
Sync
Version:
Firefox 98
Type:
defect

Tracking

()

Status:
RESOLVED WONTFIX

People

(Reporter: raphael.thiry, Unassigned, NeedInfo)

Details

Attachments

(1 file)

debug-firefox.txt
28.67 KB, text/plain
Details
Attached file debug-firefox.txt —

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:98.0) Gecko/20100101 Firefox/98.0

Steps to reproduce:

Clicking on "sync now" (firefox pc). My account is valid (id and password) and everything is keeping working on my mobile device (firefox android).

Actual results:

Nothing. No sync process : I cannot sync neither my passwords nor my installed extensions...A bug report is generated on "about:sync-log" page...

Expected results:

Sync process : passwords, extensions...

The Bugbug bot thinks this bug should belong to the 'Firefox::Sync' component, and is moving the bug to that component. Please revert this change in case you think the bot is wrong.

Component: Untriaged → Sync

The error log shows a network timeout hitting the google cloud servers. Where in the world are you located?

Flags: needinfo?(raphael.thiry)

I'm located in France...

Flags: needinfo?(raphael.thiry)

hrm, being located in France should not be a problem. You get an error log on every sync? Can you please send the most recent just to ensure the one you already attached wasn't just a transient network error?

Below the last error log. Just before, the system has generated another one, that you can also see

1/ LAST LOG

1645090060717 Sync.LogManager DEBUG Flushing file log
1645090060770 Sync.LogManager DEBUG Log cleanup threshold time: 1644226060770
1645090060796 Sync.LogManager DEBUG Done deleting files.
1645090074719 Sync.RemoteTabs INFO Generating tab list with filter
1645090074719 Sync.RemoteTabs INFO Final tab list has 0 clients with 0 tabs.
1645090079018 Sync.RemoteTabs INFO Doing a tab sync.
1645090079018 Sync.Service DEBUG User-Agent: Firefox/98.0 (Windows NT 10.0; Win64; x64) FxSync/1.100.0.20220215194438.desktop
1645090079019 Sync.Service INFO Starting sync at 2022-02-17 10:27:59 in browser session gbhMfUjda2Kq
1645090079019 Sync.Service DEBUG In sync: should login.
1645090079019 Sync.Service INFO User logged in successfully - verifying login.
1645090079019 Sync.RemoteTabs INFO Generating tab list with filter
1645090079019 Sync.RemoteTabs INFO Final tab list has 0 clients with 0 tabs.
1645090079024 FirefoxAccounts TRACE not checking freshness of profile as it remains recent
1645090079024 FirefoxAccounts INFO Can't get keys; no key material or tokens available
1645090079028 FirefoxAccounts INFO Can't get keys; no key material or tokens available
1645090079028 Sync.SyncAuthManager DEBUG unlockAndVerifyAuthState re-fetched credentials and is returning: error.login.reason.account
1645090079029 Sync.Status DEBUG Status.login: error.login.reason.account => error.login.reason.account
1645090079029 Sync.Status DEBUG Status.service: error.login.failed => error.login.failed
1645090079029 Sync.Service DEBUG Fetching unlocked auth state returned error.login.reason.account
1645090079029 Sync.ErrorHandler ERROR Sync encountered a login error
1645090079029 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score.
1645090079030 Sync.Service DEBUG Exception calling WrappedLock: Error: Login failed: error.login.reason.account(resource://services-sync/service.js:1038:15) JS Stack trace: onNotify@service.js:1038:15
1645090079030 Sync.Service DEBUG Not syncing: login returned false.
1645090079031 FirefoxAccounts TRACE not checking freshness of profile as it remains recent

2/ BEFORE LAST LOG

1645090048011 FirefoxAccounts DEBUG FxAccountsWebChannel registered: account_updates with origin https://accounts.firefox.com
1645090048148 FirefoxAccounts TRACE initializing new storage manager
1645090048148 FirefoxAccounts TRACE starting fetch of json user data
1645090048207 FirefoxAccounts TRACE finished fetch of json user data - took: 59
1645090048208 FirefoxAccounts DEBUG reading secure storage with existing: []
1645090048208 FirefoxAccounts TRACE starting fetch of user data from the login manager
1645090048209 FirefoxAccounts INFO Can't find any credentials in the login manager
1645090048209 FirefoxAccounts TRACE initializing of new storage manager done
1645090048214 FirefoxAccounts DEBUG FxAccountsProfileClient: Initialized
1645090048214 FirefoxAccounts DEBUG FxAccountsProfileClient: Requested profile
1645090048214 FirefoxAccounts DEBUG getOAuthToken enter
1645090048215 FirefoxAccounts TRACE getCachedToken returning cached token
1645090048215 FirefoxAccounts DEBUG getOAuthToken returning a cached token
1645090048215 Services.Common.RESTRequest DEBUG GET request to https://profile.accounts.firefox.com/v1/profile
1645090048221 FirefoxAccounts INFO fetching updated device list
1645090048259 Services.Common.RESTRequest DEBUG GET request to https://api.accounts.firefox.com/v1/account/devices
1645090049603 Services.Common.RESTRequest DEBUG GET https://profile.accounts.firefox.com/v1/profile 401
1645090049603 FirefoxAccounts INFO Fetching the profile returned a 401 - revoking our token and retrying
1645090049603 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/oauth/destroy
1645090049603 Services.Common.RESTRequest DEBUG POST Length: 900
1645090049604 FirefoxAccounts DEBUG _updateAccountData with items: ["oauthTokens"]
1645090049604 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","device","oauthTokens","encryptedSendTabKeys","profileCache"]
1645090049604 FirefoxAccounts TRACE starting write of json user data: ["email","sessionToken","uid","verified","device","oauthTokens","encryptedSendTabKeys","profileCache"]
1645090049604 FirefoxAccounts DEBUG getOAuthToken enter
1645090049606 Services.Common.RESTRequest DEBUG POST request to https://api.accounts.firefox.com/v1/oauth/token
1645090049606 Services.Common.RESTRequest DEBUG POST Length: 81
1645090049609 FirefoxAccounts TRACE finished write of json user data - took: 5
1645090049609 FirefoxAccounts DEBUG writing secure storage: []
1645090049609 FirefoxAccounts TRACE starting write of user data to the login manager
1645090049619 FirefoxAccounts TRACE finished write of user data to the login manager
1645090049995 Services.Common.RESTRequest DEBUG GET https://api.accounts.firefox.com/v1/account/devices 200
1645090049996 Hawk DEBUG (Response) /account/devices: code: 200 - Status text: OK
1645090049996 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: 4
1645090049996 FirefoxAccounts INFO Got new device list: 1d75bff2cb6ec9df66c0faddbbce6fac, 25f96e2a81d5eb3e9bde8fd114403852, 2965988ec6f9eb692a09ffe90019c361, 2e3c1c626ad8f107b457a6574e677438, 9a47591382c3cc96c9a8dd8f1127f18f
1645090049996 FirefoxAccounts INFO updating the cache
1645090050587 Services.Common.RESTRequest DEBUG POST https://api.accounts.firefox.com/v1/oauth/destroy 200
1645090050587 Hawk DEBUG (Response) /oauth/destroy: code: 200 - Status text: OK
1645090050588 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: 412
1645090050595 Services.Common.RESTRequest DEBUG POST https://api.accounts.firefox.com/v1/oauth/token 200
1645090050595 Hawk DEBUG (Response) /oauth/token: code: 200 - Status text: OK
1645090050595 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: 405
1645090050595 FirefoxAccounts DEBUG _updateAccountData with items: ["oauthTokens"]
1645090050596 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","device","oauthTokens","encryptedSendTabKeys","profileCache"]
1645090050596 FirefoxAccounts TRACE starting write of json user data: ["email","sessionToken","uid","verified","device","oauthTokens","encryptedSendTabKeys","profileCache"]
1645090050596 Services.Common.RESTRequest DEBUG GET request to https://profile.accounts.firefox.com/v1/profile
1645090050601 FirefoxAccounts TRACE finished write of json user data - took: 5
1645090050601 FirefoxAccounts DEBUG writing secure storage: []
1645090050601 FirefoxAccounts TRACE starting write of user data to the login manager
1645090050619 FirefoxAccounts TRACE finished write of user data to the login manager
1645090050816 Services.Common.RESTRequest DEBUG GET https://profile.accounts.firefox.com/v1/profile 304
1645090056541 Sync.Status INFO Resetting Status.
1645090056541 Sync.Status DEBUG Status.service: undefined => success.status_ok
1645090056596 Sync.SyncScheduler TRACE Setting SyncScheduler policy values to defaults.
1645090056596 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score.
1645090056597 Sync.Service INFO Loading Weave 1.100.0
1645090056601 Sync.Engine.Clients DEBUG Engine constructed
1645090056602 Sync.Engine.Clients DEBUG Resetting clients last sync time
1645090056615 Sync.Engine.Addons DEBUG Engine constructed
1645090056623 Sync.Engine.Addons DEBUG SyncEngine initialized: addons
1645090056631 Sync.Engine.Bookmarks DEBUG Engine constructed
1645090056635 Sync.Engine.Bookmarks DEBUG SyncEngine initialized: bookmarks
1645090056638 Sync.Engine.Forms DEBUG Engine constructed
1645090056645 Sync.Engine.Forms DEBUG SyncEngine initialized: forms
1645090056650 Sync.Engine.History DEBUG Engine constructed
1645090056654 Sync.Engine.History DEBUG SyncEngine initialized: history
1645090056657 Sync.Engine.Passwords DEBUG Engine constructed
1645090056663 Sync.Engine.Passwords DEBUG SyncEngine initialized: passwords
1645090056665 Sync.Engine.Prefs DEBUG Engine constructed
1645090056671 Sync.Engine.Prefs DEBUG SyncEngine initialized: prefs
1645090056674 Sync.Engine.Tabs DEBUG Engine constructed
1645090056676 Sync.Engine.Tabs DEBUG SyncEngine initialized: tabs
1645090056677 Sync.Engine.Tabs DEBUG Resetting tabs last sync time
1645090056680 Sync.Engine.CreditCards DEBUG Engine constructed
1645090056682 Sync.Engine.CreditCards DEBUG SyncEngine initialized: creditcards
1645090056695 Sync.Engine.Extension-Storage DEBUG Engine constructed
1645090056701 Sync.Engine.Extension-Storage DEBUG SyncEngine initialized: extension-storage
1645090056702 Sync.Service INFO Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:98.0) Gecko/20100101 Firefox/98.0
1645090056703 Sync.AddonsReconciler INFO Registering as Add-on Manager listener.
1645090056704 Sync.AddonsReconciler DEBUG Adding change listener.
1645090056704 Sync.Engine.History.Tracker INFO Adding Places observer.
1645090056711 FirefoxAccounts TRACE not checking freshness of profile as it remains recent
1645090060708 Sync.Service DEBUG User-Agent: Firefox/98.0 (Windows NT 10.0; Win64; x64) FxSync/1.100.0.20220215194438.desktop
1645090060709 Sync.Service INFO Starting sync at 2022-02-17 10:27:40 in browser session gbhMfUjda2Kq
1645090060709 Sync.Service DEBUG In sync: should login.
1645090060709 Sync.Service INFO User logged in successfully - verifying login.
1645090060709 FirefoxAccounts TRACE not checking freshness of profile as it remains recent
1645090060710 FirefoxAccounts INFO Can't get keys; no key material or tokens available
1645090060713 FirefoxAccounts INFO Can't get keys; no key material or tokens available
1645090060714 Sync.SyncAuthManager DEBUG unlockAndVerifyAuthState re-fetched credentials and is returning: error.login.reason.account
1645090060714 Sync.Status DEBUG Status.login: success.login => error.login.reason.account
1645090060714 Sync.Status DEBUG Status.service: success.status_ok => error.login.failed
1645090060714 Sync.Service DEBUG Fetching unlocked auth state returned error.login.reason.account
1645090060714 Sync.ErrorHandler ERROR Sync encountered a login error
1645090060714 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score.
1645090060715 Sync.Service DEBUG Exception calling WrappedLock: Error: Login failed: error.login.reason.account(resource://services-sync/service.js:1038:15) JS Stack trace: onNotify@service.js:1038:15
1645090060716 Sync.Service DEBUG Not syncing: login returned false.
1645090060716 FirefoxAccounts TRACE not checking freshness of profile as it remains recent

It looks a little like there's some issue with the browser's "secure storage" where logins and Firefox Account credentials are stored. Do you have problems staying logged in? ie, are you often prompted to sign back in to Firefox Accounts for no reason? Do you use saved passwords, and do they work correctly?

Do you have problems staying logged in? ie, are you often prompted to sign back in to Firefox Accounts for no reason?

Indeed ! Each time I restart firefox...

Do you use saved passwords, and do they work correctly?

That worked well before but that does not work any more since I reinstalled firefox...

I'm sorry that's happened and I have no idea why. If you know where your profile is, you can probably exit firefox, delete "logins.json" and "key4.db" (and key3.db if it exists) and restart - all logins will be gone and you will need to reconnect to sync, but it should start working, and sync should bring back your passwords. If you aren't sure what that means, support.mozilla.org might be able to help. Or uninstall again, making sure you select the option to remove the entire profile and start from scratch :(

The severity field is not set for this bug.
:lougenia, could you have a look please?

For more information, please visit auto_nag documentation.

Flags: needinfo?(lougenia)
Severity: -- → S3
Flags: needinfo?(lougenia)
Priority: -- → P3

:avelook did this resolve your issue?

Flags: needinfo?(raphael.thiry)

still not working...
But it seems that the error message has changed. See the log results below :

1646212786696 Sync.LogManager DEBUG Flushing file log
1646212786745 Sync.LogManager DEBUG Log cleanup threshold time: 1645348786745
1646212786759 Sync.LogManager DEBUG Done deleting files.
1646212787276 Sync.RemoteTabs INFO Generating tab list with filter
1646212787276 Sync.RemoteTabs INFO Final tab list has 0 clients with 0 tabs.
1646212792518 Services.Common.RESTRequest DEBUG GET https://profile.accounts.firefox.com/v1/profile 304
1646212792549 Services.Common.RESTRequest DEBUG GET https://api.accounts.firefox.com/v1/account/devices 200
1646212792549 Hawk DEBUG (Response) /account/devices: code: 200 - Status text: OK
1646212792550 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -1550
1646212792550 FirefoxAccounts INFO Got new device list: 23dabc09c560456d27814811ae14fe57, 99bbb710938af39133a9554fb5308220
1646212792550 FirefoxAccounts INFO updating the cache
1646212793012 Services.Common.RESTRequest DEBUG GET https://api.accounts.firefox.com/v1/account/attached_clients 200
1646212793012 Hawk DEBUG (Response) /account/attached_clients: code: 200 - Status text: OK
1646212793013 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -1013
1646234886172 Services.Common.RESTRequest DEBUG GET request to https://api.accounts.firefox.com/v1/account/attached_clients
1646234887023 Services.Common.RESTRequest DEBUG GET https://api.accounts.firefox.com/v1/account/attached_clients 200
1646234887024 Hawk DEBUG (Response) /account/attached_clients: code: 200 - Status text: OK
1646234887025 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -1025
1646235162528 Sync.RemoteTabs INFO Doing a tab sync.
1646235162529 Sync.Service DEBUG User-Agent: Firefox/98.0 (Windows NT 10.0; Win64; x64) FxSync/1.100.0.20220224185616.desktop
1646235162529 Sync.Service INFO Starting sync at 2022-03-02 16:32:42 in browser session 4pjeJjwr5-Ov
1646235162530 Sync.Service DEBUG In sync: should login.
1646235162530 Sync.Service INFO User logged in successfully - verifying login.
1646235162532 Sync.RemoteTabs INFO Generating tab list with filter
1646235162532 Sync.RemoteTabs INFO Final tab list has 0 clients with 0 tabs.
1646235162539 FirefoxAccounts DEBUG FxAccountsProfileClient: Requested profile
1646235162540 FirefoxAccounts DEBUG getOAuthToken enter
1646235162542 FirefoxAccounts TRACE getCachedToken returning cached token
1646235162542 FirefoxAccounts DEBUG getOAuthToken returning a cached token
1646235162543 FirefoxAccounts INFO Can't get keys; no key material or tokens available
1646235162554 Services.Common.RESTRequest DEBUG GET request to https://profile.accounts.firefox.com/v1/profile
1646235162555 FirefoxAccounts INFO Can't get keys; no key material or tokens available
1646235162556 Sync.SyncAuthManager DEBUG unlockAndVerifyAuthState re-fetched credentials and is returning: error.login.reason.account
1646235162556 Sync.Status DEBUG Status.login: error.login.reason.account => error.login.reason.account
1646235162556 Sync.Status DEBUG Status.service: error.login.failed => error.login.failed
1646235162556 Sync.Service DEBUG Fetching unlocked auth state returned error.login.reason.account
1646235162556 Sync.ErrorHandler ERROR Sync encountered a login error
1646235162557 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score.
1646235162558 Sync.Service DEBUG Exception calling WrappedLock: Error: Login failed: error.login.reason.account(resource://services-sync/service.js:1038:15) JS Stack trace: onNotify@service.js:1038:15
1646235162558 Sync.Service DEBUG Not syncing: login returned false.

Flags: needinfo?(raphael.thiry)

Did you delete the logins and key files or uninstall firefox (and remove the entire profile)?

Flags: needinfo?(raphael.thiry)

still not working...
But it seems that the error message has changed. See the log results below :

To be clear, they are the same messages we saw before - so what Lougenia asks is particularly relevant, because whatever was attempted didn't actually work.

To ask your question : yes, I deleted the account (then recreated). And I uninstalled firefox too (after having remove all profile files). I tried to use another version of Firefox on the same device too (pc windows 10) but nothing works...What is very weird is that account synchronisation is working on my mobile device.

Flags: needinfo?(raphael.thiry)

oops, to "answer" your question

Thanks for getting back to us, but I fully expect that deleting and recreating the account, and trying different versions of Firefox will not solve the problem. Are you completely sure you deleted the profile, because I suspect that might not have happened? Verifying the profile is gone via Windows Explorer is probably best.

I deleted the files located here before uninstall and account recreation : \Users\<username>\AppData\Roaming\Mozilla\Firefox\Profiles
I deleted all remained firefox files after uninstallation too...

That sounds like you did exactly the right thing, so I'm not sure what could be going wrong to cause the new profile to have the same problem. Sorry that we are starting to grasp at straws, but the only other ideas I have is:

  • To try and see of creating new logins still fails for you - eg, if you visit about:logins, create a new login, then restart the browser, is it there and with the password exactly as what you created?

  • There might some output in the "browser console" that is relevant - could you try starting the browser, opening the browser console, pressing the "Sync Now" button (which should again ask you to reconnect if I understand the symptoms correctly) and paste the console output into a new attachment to this bug?

Hi, avelook

Could you provide some update regarding this bug ?

Flags: needinfo?(raphael.thiry)

Redirect a needinfo that is pending on an inactive user to the triage owner.
:teshaq, since the bug has recent activity, could you have a look please?

For more information, please visit auto_nag documentation.

Flags: needinfo?(raphael.thiry) → needinfo?(teshaq)

Hey :avelook!

Since it's been a few months, I'm going to close this - however, if you are still experiencing this please feel free to re-open or comment and try the options that :markh mentioned and we can get to figuring out what is going on here

Status: UNCONFIRMED → RESOLVED
Closed: 2 years ago
Flags: needinfo?(teshaq) → needinfo?(raphael.thiry)
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: