Can't synchronise

_kud · October 24, 2018, 9:32am

Hello,

I can’t synchronise anymore because of:

1539515406540	Sync.RemoteTabs	INFO	Generating tab list with filter
1539515406540	Sync.RemoteTabs	INFO	Final tab list has 0 clients with 0 tabs.
1539518878078	Sync.Service	DEBUG	User-Agent: Firefox/64.0a1 (Intel Mac OS X 10.13) FxSync/1.66.0.20181013100102.desktop
1539518878079	Sync.Service	INFO	Starting sync at 2018-10-14 14:07:58 in browser session dpONg4VFHqXf
1539518878079	Sync.Service	DEBUG	In sync: should login.
1539518878080	Sync.Service	INFO	User logged in successfully - verifying login.
1539518878080	FirefoxAccounts	DEBUG	reading secure storage with existing: []
1539518878081	FirefoxAccounts	TRACE	starting fetch of user data from the login manager
1539518878082	FirefoxAccounts	INFO	returning partial account data as the login manager is locked.
1539518878082	FirefoxAccounts	DEBUG	setAccountData: secure storage is locked trying to read
1539518878083	FirefoxAccounts	DEBUG	reading secure storage with existing: []
1539518878083	FirefoxAccounts	TRACE	starting fetch of user data from the login manager
1539518878083	FirefoxAccounts	INFO	returning partial account data as the login manager is locked.
1539518878084	FirefoxAccounts	DEBUG	setAccountData: secure storage is locked trying to read
1539518880431	Sync.BrowserIDManager	DEBUG	unlockAndVerifyAuthState: user declined to unlock master-password
1539518880431	Sync.Status	DEBUG	Status.login: success.login => service.master_password_locked
1539518880431	Sync.Status	DEBUG	Status.service: success.status_ok => error.login.failed
1539518880431	Sync.Service	DEBUG	Fetching unlocked auth state returned service.master_password_locked
1539518880431	Sync.ErrorHandler	ERROR	Sync encountered a login error
1539518880431	Sync.SyncScheduler	DEBUG	Clearing sync triggers and the global score.
1539518880432	Sync.SyncScheduler	DEBUG	Couldn't log in: master password is locked.
1539518880432	Sync.SyncScheduler	DEBUG	Starting client-initiated backoff. Next sync in 900000 ms.
1539518880432	Sync.SyncScheduler	DEBUG	Next sync in 900000 ms. (why=client-backoff-schedule)
1539518880433	FirefoxAccounts	DEBUG	reading secure storage with existing: []
1539518880434	FirefoxAccounts	TRACE	starting fetch of user data from the login manager
1539518880434	Sync.Service	DEBUG	Exception calling WrappedLock: Error: Login failed: service.master_password_locked(resource://services-sync/service.js:872:15) JS Stack trace: onNotify@service.js:872:15
Async*WrappedNotify@util.js:179:27
async*WrappedLock@util.js:135:22
async*WrappedCatch@util.js:105:22
async*login@service.js:883:12
async*sync/<@service.js:1117:21
async*WrappedCatch@util.js:105:22
async*sync@service.js:1113:12
async*syncIfMPUnlocked/<@policies.js:549:7
1539518880434	FirefoxAccounts	INFO	returning partial account data as the login manager is locked.
1539518880434	Sync.Service	DEBUG	Not syncing: login returned false.
1539518880434	FirefoxAccounts	DEBUG	setAccountData: secure storage is locked trying to read
1539518880435	FirefoxAccounts	DEBUG	reading secure storage with existing: []
1539518880435	FirefoxAccounts	TRACE	starting fetch of user data from the login manager
1539518880436	FirefoxAccounts	INFO	returning partial account data as the login manager is locked.

Do you have any idea why?

Thanks!

rfkelly · October 24, 2018, 9:59pm

Do you have “master password” enabled in your Firefox profile? The error indicates that Firefox Sync could load its credentials and encryption keys from storage because the credential store is locked.

rfkelly · October 24, 2018, 10:02pm

I believe that sync should be prompting for you to enter the master password, according to https://bugzilla.mozilla.org/show_bug.cgi?id=1433679

If you’re not seeing a master-password prompt, it might indicate that your credential store is corrupted.

_kud · October 25, 2018, 8:54am

Yes I entered my masterpassword, and the form said it was ok.

New errors:

1540457570456 Sync.ErrorHandler DEBUG creditcards failed: Error: CreditCards is not initialized. Please restart if you flip the pref manually.(resource://formautofill/FormAutofillStorage.jsm:1937:23) JS Stack trace: get@FormAutofillStorage.jsm:1937:23
get storage@FormAutofillSync.jsm:86:7
trackRemainingChanges@FormAutofillSync.jsm:323:5
async*_syncCleanup@engines.js:1823:13
async*_sync@engines.js:1852:13
async*WrappedNotify@util.js:179:27
async*sync@engines.js:895:12
async*_syncEngine@enginesync.js:214:13
async*sync@enginesync.js:156:21
async*onNotify@service.js:1139:13
async*WrappedNotify@util.js:179:27
async*WrappedLock@util.js:135:22
async*_lockedSync@service.js:1132:12
async*sync/<@service.js:1124:13
async*WrappedCatch@util.js:105:22
async*sync@service.js:1113:12
async*syncIfMPUnlocked/<@policies.js:549:7
1540457570457 Sync.SyncScheduler  TRACE Handling weave:engine:sync:error
1540457570457 Sync.Telemetry  TRACE observed weave:engine:sync:error creditcards
1540457570457 Sync.Engine.Forms TRACE Event: weave:engine:sync:start
1540457570457 Sync.Telemetry  TRACE observed weave:engine:sync:start forms
1540457570459 Sync.Engine.Forms.Tracker TRACE Clearing changed ID list
1540457570459 Sync.Engine.Forms INFO  0 outgoing items pre-reconciliation
1540457570459 Sync.Engine.Forms TRACE Downloading & applying server changes
1540457570460 Sync.Engine.Forms INFO  Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1540457570460 Sync.ErrorHandler TRACE Handling weave:engine:sync:applied
1540457570460 Sync.SyncScheduler  TRACE Handling weave:engine:sync:applied
1540457570460 Sync.SyncScheduler  TRACE Engine forms successfully applied 0 items.
1540457570460 Sync.Telemetry  TRACE observed weave:engine:sync:applied forms
1540457570460 Sync.Engine.Forms TRACE Uploading local changes to server.
1540457570460 Sync.Engine.Forms TRACE Finishing up sync
1540457570460 Sync.Engine.Forms TRACE Event: weave:engine:sync:finish
1540457570460 Sync.RemoteTabs TRACE observed topic=weave:engine:sync:finish, data=forms, subject=null
1540457570460 Sync.SyncScheduler  TRACE Handling weave:engine:sync:finish
1540457570460 Sync.Telemetry  TRACE observed weave:engine:sync:finish forms
1540457570461 Sync.Engine.History TRACE Event: weave:engine:sync:start
1540457570461 Sync.Telemetry  TRACE observed weave:engine:sync:start history
1540457570461 Sync.Engine.History DEBUG Migrating existing sync ID XLp4tpUqg6mj from prefs
1540457570463 Sync.Engine.History.HistorySyncUtils  TRACE History sync ID up-to-date: {"existingSyncId":"XLp4tpUqg6mj"}
1540457570463 Sync.Engine.History DEBUG Migrating existing last sync time 1540456801.33 from prefs
1540457570464 Sync.Engine.History DEBUG Checking if server sync ID XLp4tpUqg6mj matches existing
1540457570465 Sync.Engine.History.HistorySyncUtils  TRACE History sync ID up-to-date: {"existingSyncId":"XLp4tpUqg6mj"}
1540457570468 Sync.Engine.History.Tracker TRACE Removing changed ID 0kPLVVUBfThb
1540457570468 Sync.Engine.History.Tracker TRACE Clearing changed ID list
1540457570468 Sync.Engine.History INFO  14 outgoing items pre-reconciliation
1540457570468 Sync.Engine.History TRACE Downloading & applying server changes
1540457570469 Sync.Engine.History INFO  Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1540457570469 Sync.ErrorHandler TRACE Handling weave:engine:sync:applied
1540457570469 Sync.SyncScheduler  TRACE Handling weave:engine:sync:applied
1540457570469 Sync.SyncScheduler  TRACE Engine history successfully applied 0 items.
1540457570469 Sync.Telemetry  TRACE observed weave:engine:sync:applied history
1540457570469 Sync.Engine.History TRACE Uploading local changes to server.
1540457570469 Sync.Engine.History TRACE Preparing 14 outgoing records
1540457570501 Sync.Engine.History INFO  Posting 14 records of 9243 bytes with batch=true
1540457570502 Sync.BrowserIDManager TRACE _ensureValidToken already has one
1540457570502 Sync.Collection DEBUG POST Length: 9243
1540457570883 Sync.Collection DEBUG POST success 200 https://sync-665-us-west-2.sync.services.mozilla.com/1.5/105993389/storage/history?batch=true&commit=true
1540457570884 Sync.Engine.History TRACE Committed batch
1540457570891 Sync.Telemetry  TRACE observed weave:engine:sync:uploaded history
1540457570891 Sync.Engine.History TRACE Finishing up sync
1540457570895 Sync.Engine.History TRACE Event: weave:engine:sync:finish
1540457570895 Sync.RemoteTabs TRACE observed topic=weave:engine:sync:finish, data=history, subject=null
1540457570896 Sync.SyncScheduler  TRACE Handling weave:engine:sync:finish
1540457570896 Sync.Telemetry  TRACE observed weave:engine:sync:finish history
1540457570898 Sync.Engine.Extension-Storage TRACE Event: weave:engine:sync:start
1540457570898 Sync.Telemetry  TRACE observed weave:engine:sync:start extension-storage
1540457570906 Sync.Engine.Extension-Storage DEBUG Syncing extension settings for []
1540457570907 Sync.Engine.Extension-Storage TRACE Event: weave:engine:sync:finish
1540457570907 Sync.RemoteTabs TRACE observed topic=weave:engine:sync:finish, data=extension-storage, subject=null
1540457570907 Sync.SyncScheduler  TRACE Handling weave:engine:sync:finish
1540457570907 Sync.Telemetry  TRACE observed weave:engine:sync:finish extension-storage
1540457570912 Sync.Doctor INFO  Skipping check of prefs - disabled via preferences
1540457570912 Sync.Doctor INFO  Skipping validation of passwords: too recent since last validation attempt
1540457570912 Sync.Doctor INFO  Skipping check of tabs - disabled via preferences
1540457570912 Sync.Doctor INFO  Skipping validation of bookmarks: too recent since last validation attempt
1540457570912 Sync.Doctor INFO  Skipping check of addons - disabled via preferences
1540457570912 Sync.Doctor INFO  Skipping check of addresses - disabled via preferences
1540457570912 Sync.Doctor INFO  Skipping check of creditcards - disabled via preferences
1540457570913 Sync.Doctor INFO  Skipping check of forms - disabled via preferences
1540457570913 Sync.Doctor INFO  Skipping check of history - disabled via preferences
1540457570914 Sync.Doctor INFO  Skipping check of extension-storage - disabled via preferences
1540457570914 Sync.Doctor INFO  Skipping validation: no engines qualify
1540457570918 Sync.Synchronizer INFO  Sync completed at 2018-10-25 10:52:50 after 2.90 secs.
1540457570925 Sync.Declined DEBUG Handling remote declined: []
1540457570928 Sync.Declined DEBUG Handling local declined: []
1540457570934 Sync.Declined DEBUG Declined changed? false
1540457570935 Sync.Service  INFO  No change to declined engines. Not reuploading meta/global.
1540457570935 Sync.Service  TRACE Event: weave:service:sync:finish
1540457570935 Sync.ErrorHandler TRACE Handling weave:service:sync:finish
1540457570935 Sync.ErrorHandler TRACE Status.service is error.sync.failed_partial
1540457570935 Sync.ErrorHandler ERROR Some engines did not sync correctly.
1540457570936 Sync.SyncScheduler  TRACE Handling weave:service:sync:finish
1540457570936 Sync.SyncScheduler  TRACE Adjusting syncInterval to immediateInterval.
1540457570936 Sync.SyncScheduler  TRACE clients: score: 0
1540457570936 Sync.SyncScheduler  TRACE prefs: score: 0
1540457570936 Sync.SyncScheduler  TRACE passwords: score: 0
1540457570936 Sync.SyncScheduler  TRACE tabs: score: 0
1540457570936 Sync.SyncScheduler  TRACE bookmarks: score: 0
1540457570936 Sync.SyncScheduler  TRACE addons: score: 0
1540457570936 Sync.SyncScheduler  TRACE addresses: score: 0
1540457570936 Sync.SyncScheduler  TRACE creditcards: score: 0
1540457570936 Sync.SyncScheduler  TRACE forms: score: 0
1540457570937 Sync.SyncScheduler  TRACE history: score: 0
1540457570937 Sync.SyncScheduler  TRACE extension-storage: score: 0
1540457570937 Sync.SyncScheduler  TRACE Global score updated: 0
1540457570937 Sync.SyncScheduler  DEBUG Next sync in 90000 ms. (why=schedule)
1540457570937 Sync.Telemetry  TRACE observed weave:service:sync:finish {"why":"schedule"}
1540457570949 Sync.ErrorHandler TRACE Addons installed: 5
1540457570949 Sync.ErrorHandler TRACE  - Firefox Multi-Account Containers, version 6.0.0, id @testpilot-containers
1540457570950 Sync.ErrorHandler TRACE  - Raindrop.io: "Save Button" for Web, version 6.0.429, id jid0-adyhmvsP91nUO8pRv0Mn2VKeB84@jetpack
1540457570950 Sync.ErrorHandler TRACE  - About Sync, version 0.0.50, id aboutsync@mhammond.github.com
1540457570950 Sync.ErrorHandler TRACE  - SearchPreview, version 11.2, id {EF522540-89F5-46b9-B6FE-1829E2B572C6}
1540457570950 Sync.ErrorHandler TRACE  - uBlock Origin, version 1.17.2, id uBlock0@raymondhill.net

_kud · October 26, 2018, 8:20am

1540541842994	Sync.Engine.CreditCards.Store	WARN	Failed to apply incoming record 8e18e1fb6123: Error: CreditCards is not initialized. Please restart if you flip the pref manually.(resource://formautofill/FormAutofillStorage.jsm:1937:23) JS Stack trace: get@FormAutofillStorage.jsm:1937:23
get storage@FormAutofillSync.jsm:86:7
applyIncoming@FormAutofillSync.jsm:112:7
async*applyIncomingBatch@engines.js:316:15
async*_applyRecords@engines.js:1411:29
async*_processIncoming@engines.js:1292:33
async*_sync@engines.js:1835:13
async*WrappedNotify@util.js:179:27
async*sync@engines.js:895:12
async*_syncEngine@enginesync.js:214:13
async*sync@enginesync.js:156:21
async*onNotify@service.js:1139:13
async*WrappedNotify@util.js:179:27
async*WrappedLock@util.js:135:22
async*_lockedSync@service.js:1132:12
async*sync/<@service.js:1124:13
async*WrappedCatch@util.js:105:22
async*sync@service.js:1113:12
async*syncIfMPUnlocked/<@policies.js:549:7
1540541842995	Sync.Engine.CreditCards	INFO	Records: 1 applied, 0 successfully, 1 failed to apply, 0 newly failed to apply, 0 reconciled.

I wonder if it’s not because I’ve disabled “autofill credit cards” in option, and firefox sync tries to synchronise that…?

rfkelly · October 28, 2018, 11:59pm

Looks like you might be hitting this bug: https://bugzilla.mozilla.org/show_bug.cgi?id=1502173

_kud · October 29, 2018, 6:27pm

Indeed! Thank you.