1592482 - Can't sync bookmarks on fresh catalina install, database disk image is malformed

Status: RESOLVED WORKSFORME

(Firefox :: Sync, defect)

Description

[Jeff Matthews]

Attachment: aboutsupport.txt

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:70.0) Gecko/20100101 Firefox/70.0

Steps to reproduce:

Newly installed firefox on mac running Catalina, bookmarks won't sync with another mac. All addons disabled.

Actual results:

about:sync-log output below:

1572395278791 Sync.LogManager DEBUG Flushing file log
1572395278797 Sync.LogManager DEBUG Log cleanup threshold time: 1571531278797
1572395278801 Sync.LogManager DEBUG Done deleting files.
1572395660397 FirefoxAccounts INFO Polling device commands.
1572395660398 Sync.Service DEBUG User-Agent: Firefox/70.0 (Intel Mac OS X 10.15) FxSync/1.72.0.20191016161957.desktop
1572395660398 Sync.Service INFO Starting sync at 2019-10-29 17:34:20 in browser session eBKU0819OOVx
1572395660398 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score.
1572395660401 Sync.Status INFO Resetting Status.
1572395660401 Sync.Status DEBUG Status.service: error.sync.failed_partial => success.status_ok
1572395660407 Services.Common.RESTRequest DEBUG GET request to https://api.accounts.firefox.com/v1/account/device/commands?index=0
1572395660575 Services.Common.RESTRequest DEBUG GET https://api.accounts.firefox.com/v1/account/device/commands?index=0 200
1572395660575 Hawk DEBUG (Response) /account/device/commands?index=0: code: 200 - Status text: OK
1572395660576 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -576
1572395660608 Sync.Resource DEBUG GET success 200 https://sync-714-us-west-2.sync.services.mozilla.com/1.5/129916240/info/collections
1572395660608 Sync.Service DEBUG Fetching server configuration: https://sync-714-us-west-2.sync.services.mozilla.com/1.5/129916240/info/configuration
1572395660639 Sync.Resource DEBUG GET success 200 https://sync-714-us-west-2.sync.services.mozilla.com/1.5/129916240/info/configuration
1572395660639 Sync.Service DEBUG Fetching global metadata record
1572395660640 Sync.Service DEBUG Weave Version: 1.72.0 Local Storage: 5 Remote Storage: 5
1572395660640 Sync.Service DEBUG Fetching and verifying -- or generating -- symmetric keys.
1572395660640 Sync.Service INFO Testing info/collections: {"addons":1572395278.73,"clients":1572395278.47,"crypto":1572382295.06,"meta":1572393966.12,"bookmarks":1572394468.76,"prefs":1572395278.63}
1572395660640 Sync.CollectionKeyManager INFO Testing for updateNeeded. Last modified: 1572382295.06
1572395660640 Sync.Synchronizer DEBUG Refreshing client list.
1572395660641 Sync.Engine.Clients INFO 0 outgoing items pre-reconciliation
1572395660641 Sync.Engine.Clients DEBUG Resetting clients last sync time
1572395660679 Sync.Collection DEBUG GET success 200 https://sync-714-us-west-2.sync.services.mozilla.com/1.5/129916240/storage/clients?full=1&limit=1000
1572395660686 Sync.Engine.Clients INFO Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 5 reconciled.
1572395660688 Services.Common.RESTRequest DEBUG GET request to https://api.accounts.firefox.com/v1/account/devices
1572395661155 Services.Common.RESTRequest DEBUG GET https://api.accounts.firefox.com/v1/account/devices 200
1572395661156 Hawk DEBUG (Response) /account/devices: code: 200 - Status text: OK
1572395661156 Hawk DEBUG Clock offset vs https://api.accounts.firefox.com/v1: -1156
1572395661156 Sync.Engine.Clients DEBUG Refreshing the known stale clients list
1572395661157 Sync.BulkKeyBundle INFO BulkKeyBundle being created for undefined
1572395661159 Sync.Engine.Clients INFO Hiding stale client IyqdNUzXwYS2 - duplicate device id a09764829c795e224c247934409f1feb
1572395661159 Sync.Engine.Clients INFO Hiding stale client DCrVetYPax6 - in known stale clients list
1572395661159 Sync.Engine.Clients INFO Hiding stale client XP72_fv3smb7 - in known stale clients list
1572395661163 Sync.Synchronizer INFO Updating enabled engines: 2 clients.
1572395661164 Sync.Synchronizer INFO Syncing all enabled engines.
1572395661164 Sync.Engine.Prefs INFO 0 outgoing items pre-reconciliation
1572395661165 Sync.Engine.Prefs INFO Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1572395661166 Sync.Engine.Bookmarks DEBUG Checking if server sync ID Sjht-DAOOnM matches existing
1572395661166 Sync.Engine.Bookmarks DEBUG First sync, uploading all items
1572395661167 Sync.Engine.Bookmarks.BookmarkSyncUtils DEBUG pushChanges: Processed change records: {"weak":0,"skipped":0,"updated":0}
1572395661167 Sync.Status DEBUG Status for engine bookmarks: error.engine.reason.unknown_fail
1572395661167 Sync.Status DEBUG Status.service: success.status_ok => error.sync.failed_partial
1572395661167 Sync.ErrorHandler DEBUG bookmarks failed: Error: Error(s) encountered during statement execution: database disk image is malformed(resource://gre/modules/Sqlite.jsm:889:25) JS Stack trace: [e-mail]:889:25
1572395661167 Sync.Engine.Addons DEBUG Refreshing reconciler state
1572395661167 Sync.AddonsReconciler INFO Refreshing global state from AddonManager.
1572395661168 Sync.AddonsReconciler DEBUG Rectifying state for addon Form Autofill (version=1.0, id=[e-mail])
1572395661168 Sync.AddonsReconciler DEBUG Rectifying state for addon Firefox Screenshots (version=39.0.0, id=[e-mail])
1572395661168 Sync.AddonsReconciler DEBUG Rectifying state for addon WebCompat Reporter (version=1.1.0, id=[e-mail])
1572395661169 Sync.AddonsReconciler DEBUG Rectifying state for addon Web Compat (version=6.2.0, id=[e-mail])
1572395661169 Sync.AddonsReconciler DEBUG Rectifying state for addon Default (version=1.0, id=[e-mail])
1572395661169 Sync.AddonsReconciler DEBUG Rectifying state for addon Light (version=1.0, id=[e-mail])
1572395661169 Sync.AddonsReconciler DEBUG Rectifying state for addon Dark (version=1.0, id=[e-mail])
1572395661169 Sync.AddonsReconciler DEBUG Rectifying state for addon Google (version=1.0, id=[e-mail])
1572395661169 Sync.AddonsReconciler DEBUG Rectifying state for addon Amazon.com (version=1.1, id=[e-mail])
1572395661169 Sync.AddonsReconciler DEBUG Rectifying state for addon Bing (version=1.0, id=[e-mail])
1572395661169 Sync.AddonsReconciler DEBUG Rectifying state for addon DuckDuckGo (version=1.0, id=[e-mail])
1572395661169 Sync.AddonsReconciler DEBUG Rectifying state for addon eBay (version=1.0, id=[e-mail])
1572395661169 Sync.AddonsReconciler DEBUG Rectifying state for addon Twitter (version=1.0, id=[e-mail])
1572395661169 Sync.AddonsReconciler DEBUG Rectifying state for addon Wikipedia (en) (version=1.0, id=[e-mail])
1572395661169 Sync.AddonsReconciler DEBUG Rectifying state for addon Startup Apps (version=2.0, id=jid0-TgBNh976zF55Pb4ABiM1DXsJV4Q@jetpack)
1572395661169 Sync.AddonsReconciler DEBUG Rectifying state for addon LastPass: Free Password Manager (version=4.35.1.2, id=[e-mail])
1572395661169 Sync.AddonsReconciler DEBUG Rectifying state for addon Privacy Badger (version=2019.10.28, id=jid1-MnnxcxisBPnSXQ@jetpack)
1572395661169 Sync.AddonsReconciler DEBUG Rectifying state for addon OpenH264 Video Codec provided by Cisco Systems, Inc. (version=null, id=gmp-gmpopenh264)
1572395661169 Sync.AddonsReconciler DEBUG Rectifying state for addon Widevine Content Decryption Module provided by Google Inc. (version=null, id=gmp-widevinecdm)
1572395661170 Sync.AddonsReconciler INFO Saving reconciler state to file: addonsreconciler
1572395661173 Sync.Engine.Addons INFO 0 outgoing items pre-reconciliation
1572395661174 Sync.Engine.Addons INFO Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1572395661176 Sync.Engine.Extension-Storage DEBUG Syncing extension settings for []
1572395661176 Sync.Doctor INFO Skipping check of prefs - disabled via preferences
1572395661176 Sync.Doctor INFO Skipping check of bookmarks - disabled via preferences
1572395661176 Sync.Doctor INFO Skipping check of addons - disabled via preferences
1572395661176 Sync.Doctor INFO Skipping check of extension-storage - disabled via preferences
1572395661177 Sync.Doctor INFO Skipping validation: no engines qualify
1572395661177 Sync.Synchronizer INFO Sync completed at 2019-10-29 17:34:21 after 0.78 secs.
1572395661178 Sync.Declined DEBUG Handling remote declined: ["history","tabs","forms","passwords"]
1572395661178 Sync.Declined DEBUG Handling local declined: ["history","tabs","forms","passwords"]
1572395661178 Sync.Declined DEBUG Declined changed? false
1572395661178 Sync.Service INFO No change to declined engines. Not reuploading meta/global.
1572395661178 Sync.ErrorHandler ERROR Some engines did not sync correctly.
1572395661178 Sync.SyncScheduler DEBUG Next sync in 600000 ms. (why=schedule)

Expected results:

bookmarks should have synced.
Verify integrity on the about:support page gives the following

Task: checkIntegrity

• Unable to check places.sqlite integrity: Error: Error(s) encountered during statement execution: database disk image is malformed

Task: invalidateCaches

• The task queue was cleared by an error in another task.

Task: checkCoherence

• The task queue was cleared by an error in another task.

Task: expire

• The task queue was cleared by an error in another task.

Task: originFrecencyStats

• The task queue was cleared by an error in another task.

Task: vacuum

• The task queue was cleared by an error in another task.

Task: stats

• The task queue was cleared by an error in another task.

Task: _refreshUI

• The task queue was cleared by an error in another task.

Comment 1

[Mark Hammond [:markh] [:mhammond]]

That's very odd. We do occasionally see corrupt places.sqlite files, but immediately after an install is rare. http://kb.mozillazine.org/Bookmarks_history_and_toolbar_buttons_not_working_-_Firefox#Rebuild_Places_database explains how you might recover from this (but note the referenced addon no longer exists, so you need to jump straight to the "delete the file from disk" option.

If this comes back after following those instructions then something is really screwed up - checking about:support's places integrity checker immediately after deleting places.sqlite would be useful too - I suspect this has nothing to do with Sync (so cc Mak).

Comment 2

[Jeff Matthews]

Deleting the places.sqlite solved it. Thanks!

Comment 3

[Marcia Knous [:marcia]]

Sounds as if we can close this one out as WFM.