1405656 - Sync hangs on MacOS

Status: RESOLVED INCOMPLETE

(Firefox :: Sync, defect)

Description

[T]

User Agent: Mozilla/5.0 (Android 7.0; Mobile; rv:56.0) Gecko/56.0 Firefox/56.0
Build ID: 20170922214822

Steps to reproduce:

Fresh install on MacOS. Logged into Sync account successfully. Waited for sync to start.


Actual results:

Bookmarks and some settings sync, but then the browser hangs (spinning.beachball). Firefox can only.be killed using "kill -9". Repeated syncs hang the browser. No sync log is present. Last sync shown as 1 January. No add-ons synced.


Expected results:

Sync should have completed successfully. Browser should not hang.

Comment 1

[T]

Use agent above is unrelated to this bug. This bug related to Apple MacOS desktop operating system.

Comment 2

[T]

I logged out (disconnected) sync and then logged in again. After this, add-ons synced, but sync still hangs. Log files have also appeared now.

Comment 3

[T]

After a few more forced shutdowns and restarts, the sync has completed and the "Last Sync" time reflects the current time. I have copied the sync logs to post if necessary.

Comment 4

[T]

This appears to be related:

https://support.mozilla.org/en-US/questions/1173643

I experienced this issue in late versions of Firefox 55 and 56. The issue was not resolved when testing the beta released of 56, as mentioned above.

Comment 5

[T]

Sync in Firefox 56.0 64-bit under Kubuntu Linux 64-bit behind a proxy sometimes hangs. After quitting Firefox, a process (sync?) is still running. After launching Firefox a second time, Sync completes successfully. I recall experiencing this under Windows 10 without a proxy. It would seem that there is an issue when Sync starts "cold".

Comment 6

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

(In reply to TrevorGrahamBell from comment #5)
> Sync in Firefox 56.0 64-bit under Kubuntu Linux 64-bit behind a proxy
> sometimes hangs. After quitting Firefox, a process (sync?) is still running.
> After launching Firefox a second time, Sync completes successfully. I recall
> experiencing this under Windows 10 without a proxy. It would seem that there
> is an issue when Sync starts "cold".

We're sorry to hear you are having this problem, but thanks very much for taking the time to make this report. We aren't sure what is causing this issue, but Sync does keep some logs which may help us find the problem. Instructions for how to locate and attach the logs can be found at https://wiki.mozilla.org/CloudServices/Sync/File_a_desktop_bug - and in particular, follow the instructions for enabling "success" logs, then reproduce your issue (eg, restart so that sync hangs as you describe), and attach any new logs which then appear.

Comment 7

[T]

Attachment: Sync success log

I've just checked the Sync logs and no error log was generated today, as I've experienced before. Does Sync sometimes need a (very) long time to complete? I have sometimes left it for 10+ minutes and it does not complete.

There was a success log from today, which I've attached.

Comment 8

[Sun]

Attachment: logs.zip

A bunch sync error logs happened on Firefox (55, 56) hang.

Comment 9

[T]

Sync continues to hang Firefox 56.0 64-bit (and now the entire Kubuntu system) with 100% CPU after first, and subsequent, starts after fresh machine boot. Killing Firefox can only be done by switching to a different console. Sync is running and shows the previous time as the last update, but does not complete before Firefox hangs.

Killing Firefox and restarting a few times eventually results in sync completing successfully. No Sync logs (fail or success) are generated until the final Sync that works (success log) -- attached.

Comment 10

[T]

Attachment: Success logs after several hangs

Success logs after (re)starting Firefox 56.0 several times under Kubuntu. These are the only logs produces after Firefox eventually completed Sync and did not hang.

Comment 11

[Lina Butler [:lina]]

Those logs are very helpful, thanks for uploading them! A few things stand out:

> 1507641181365 Sync.Store.Bookmarks  DEBUG Could not order children for unfiled: Error: Transaction timeout, most likely caused by unresolved pending work. (resource://gre/modules/Sqlite.jsm:646:33) JS Stack trace: executeTransaction/promise</timeoutPromise</<@Sqlite.jsm:646:33 < [e-mail]:30:5

I think this is your issue: bug 1339390. We get stuck reordering children, and eventually time out. This should improve in bug 1305563, because we won't build a temporary `sorting` table, and reorder all items instead of one folder at a time...but that bug won't be landing for at least a few more weeks.

In the meantime, could I ask you how many bookmarks you have in your "Other Bookmarks" folder? Are you able to sync if you split those bookmarks up into subfolders?

> 1507469096961 Sync.Status DEBUG Status for engine addons: error.engine.reason.unknown_fail
> 1507469096961 Sync.Status DEBUG Status.service: error.sync.failed_partial => error.sync.failed_partial
> 1507469096961 Sync.ErrorHandler DEBUG addons failed: Error: Data is not ready. (resource://gre/modules/JSONFile.jsm:159:13) JS Stack trace: get [e-mail]:159:13 < get [e-mail]:100:5 < [e-mail]:163:1 < [e-mail]:1875:12 < [e-mail]:1037:30 < [e-mail]:534:9

This looks unrelated, and likely not a real issue given that it happens at shutdown, but still worth investigating. Filed bug 1408188.

> 1507466945023 Sync.Collection WARN  GET request to https://sync-484-us-west-2.sync.services.mozilla.com/1.5/68361930/storage/bookmarks?newer=1507363948.32&full=1&sort=index&limit=1000 failed: [Exception... "NS_ERROR_ABORT"  nsresult: "0x80004004 (NS_ERROR_ABORT)"  location: "JS frame :: resource://services-sync/resource.js :: Channel_onStopRequest :: line 422"  data: no] Stack trace: Channel_onStopRequest()@resource://services-sync/resource.js:422

This is just a transient network error.

> 1507261142644 Sync.BrowserIDManager INFO  Unable to fetch keys (master-password locked?), so aborting token fetch
> 1507261142644 Sync.BrowserIDManager INFO  Background fetch for key bundle done
> 1507261142644 Sync.Status DEBUG Status.login: success.login => success.login
> 1507261142644 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok
> 1507261142644 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok
> 1507261142644 Sync.Service  INFO  User logged in successfully - verifying login.
> 1507261142645 Sync.BrowserIDManager DEBUG unlockAndVerifyAuthState re-fetched credentials and is returning: error.login.reason.account
> 1507261142645 Sync.Service  DEBUG Fetching unlocked auth state returned error.login.reason.account
> 1507261142645 Sync.Status DEBUG Status.login: success.login => error.login.reason.account
> 1507261142648 Sync.Service  DEBUG Exception calling WrappedLock: Error: Login failed: error.login.reason.account (resource://services-sync/service.js:845:15) JS Stack trace: [e-mail]:845:15

This might be a master password unlock failure? If you use a master password, and don't unlock before syncing (or just leave the dialog in the background), that might also cause Firefox to hang, as in bug 1405917. If you don't use a master password, something else is going on. I don't think this is your issue, though, because the transaction timeout appears in multiple logs, but I only saw this once.

> 1507208342340 addons.xpi  ERROR Failed to clean updated system add-ons directories.

This isn't a particularly interesting error, and the comment in https://searchfox.org/mozilla-central/rev/ed1d5223adcdc07e9a2589ee20f4e5ee91b4df10/toolkit/mozapps/extensions/internal/XPIProvider.jsm#6729-6731 says we'll try cleaning up again later if we fail.

Comment 12

[T]

(In reply to Kit Cambridge (he/him) [:kitcambridge] (UTC-7) from comment #11)

Thanks for the detail reply and links to other bugs, which I'm looking at.

> In the meantime, could I ask you how many bookmarks you have in your "Other
> Bookmarks" folder? Are you able to sync if you split those bookmarks up into
> subfolders?

The number of bookmarks in this folder varies quite often, but it is typically less than 50. I'll keep this in mind in future.

Comment 13

[Sun]

(In reply to Kit Cambridge (he/him) [:kitcambridge] (UTC-7) from comment #11)
> Those logs are very helpful, thanks for uploading them! A few things stand
> out:
> 
> > 1507641181365 Sync.Store.Bookmarks  DEBUG Could not order children for unfiled: Error: Transaction timeout, most likely caused by unresolved pending work. (resource://gre/modules/Sqlite.jsm:646:33) JS Stack trace: executeTransaction/promise</timeoutPromise</<@Sqlite.jsm:646:33 < [e-mail]:30:5
> 
> I think this is your issue: bug 1339390. We get stuck reordering children,
> and eventually time out. This should improve in bug 1305563, because we
> won't build a temporary `sorting` table, and reorder all items instead of
> one folder at a time...but that bug won't be landing for at least a few more
> weeks.
> 
> In the meantime, could I ask you how many bookmarks you have in your "Other
> Bookmarks" folder? Are you able to sync if you split those bookmarks up into
> subfolders?
> 
> > 1507469096961 Sync.Status DEBUG Status for engine addons: error.engine.reason.unknown_fail
> > 1507469096961 Sync.Status DEBUG Status.service: error.sync.failed_partial => error.sync.failed_partial
> > 1507469096961 Sync.ErrorHandler DEBUG addons failed: Error: Data is not ready. (resource://gre/modules/JSONFile.jsm:159:13) JS Stack trace: get [e-mail]:159:13 < get [e-mail]:100:5 < [e-mail]:163:1 < [e-mail]:1875:12 < [e-mail]:1037:30 < [e-mail]:534:9
> 
> This looks unrelated, and likely not a real issue given that it happens at
> shutdown, but still worth investigating. Filed bug 1408188.
> 
> > 1507466945023 Sync.Collection WARN  GET request to https://sync-484-us-west-2.sync.services.mozilla.com/1.5/68361930/storage/bookmarks?newer=1507363948.32&full=1&sort=index&limit=1000 failed: [Exception... "NS_ERROR_ABORT"  nsresult: "0x80004004 (NS_ERROR_ABORT)"  location: "JS frame :: resource://services-sync/resource.js :: Channel_onStopRequest :: line 422"  data: no] Stack trace: Channel_onStopRequest()@resource://services-sync/resource.js:422
> 
> This is just a transient network error.
> 
> > 1507261142644 Sync.BrowserIDManager INFO  Unable to fetch keys (master-password locked?), so aborting token fetch
> > 1507261142644 Sync.BrowserIDManager INFO  Background fetch for key bundle done
> > 1507261142644 Sync.Status DEBUG Status.login: success.login => success.login
> > 1507261142644 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok
> > 1507261142644 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok
> > 1507261142644 Sync.Service  INFO  User logged in successfully - verifying login.
> > 1507261142645 Sync.BrowserIDManager DEBUG unlockAndVerifyAuthState re-fetched credentials and is returning: error.login.reason.account
> > 1507261142645 Sync.Service  DEBUG Fetching unlocked auth state returned error.login.reason.account
> > 1507261142645 Sync.Status DEBUG Status.login: success.login => error.login.reason.account
> > 1507261142648 Sync.Service  DEBUG Exception calling WrappedLock: Error: Login failed: error.login.reason.account (resource://services-sync/service.js:845:15) JS Stack trace: [e-mail]:845:15
> 
> This might be a master password unlock failure? If you use a master
> password, and don't unlock before syncing (or just leave the dialog in the
> background), that might also cause Firefox to hang, as in bug 1405917. If
> you don't use a master password, something else is going on. I don't think
> this is your issue, though, because the transaction timeout appears in
> multiple logs, but I only saw this once.
> 
> > 1507208342340 addons.xpi  ERROR Failed to clean updated system add-ons directories.
> 
> This isn't a particularly interesting error, and the comment in
> https://searchfox.org/mozilla-central/rev/
> ed1d5223adcdc07e9a2589ee20f4e5ee91b4df10/toolkit/mozapps/extensions/internal/
> XPIProvider.jsm#6729-6731 says we'll try cleaning up again later if we fail.

I have about 4k items in "Other Bookmarks" on which syncing works well before v55. 
And I tried to wait when Firefox hangs, it will be able to operate after about 1-2 hours.

Comment 14

[T]

Attachment: Error logs from startup on Linux

This bug mentions MacOS, but the same behaviour is experienced, as I've mentioned previously, under Linux.

After booting the computer and opening Firefox 56.0 64-bit, the initial sync always hangs the browser (logs from this attached).

After forcing Firefox to quit and launching it again, the sync completes. This computer is behind an authenticated proxy, but Firefox always prompts with the saved proxy credentials immediately upon startup on all occasions.

Comment 15

[Lina Butler [:lina]]

Thanks for uploading the log. Our friend, the transaction timeout, makes an appearance:

> 1508313362932	Sync.Store.Bookmarks	DEBUG	Could not order children for CsrgdMdJF0qz: Error: Transaction timeout, most likely caused by unresolved pending work. (resource://gre/modules/Sqlite.jsm:646:33) JS Stack trace: executeTransaction/promise</timeoutPromise</<@Sqlite.jsm:646:33 < [e-mail]:30:5

This looks a lot like bug 1339390, but you mentioned you don't have many bookmarks, so I'm at a loss. Is there any chance you'd be willing to email me your places.sqlite file, so that I can do some debugging and see why `reoder` is hanging? (It contains all your bookmarks and history, so it's totally OK if not. Alternatively, I can come up with some SQL queries for you to run against Places, using the About Sync add-on, though there might be a few cycles of back and forth).

Your profile directory should also contain some JSON backups, in the `bookmarkbackups` subfolder. Could you try restoring the latest one into a fresh Firefox profile, then connecting Sync and seeing if reordering still hangs? (Or, better yet, try connecting Sync to a fresh profile, and let it finish downloading and applying all your bookmarks?)

If you can't repro in a fresh profile, you might try running the Places Maintenance add-on in your main profile (https://addons.mozilla.org/en-US/firefox/addon/places-maintenance/), and seeing if the hang goes away. Maintenance fixes up the schema and vacuums the DB.

Comment 16

[T]

(In reply to Kit Cambridge (he/him) [:kitcambridge] (UTC-7) from comment #15)
> Thanks for uploading the log. Our friend, the transaction timeout, makes an
> appearance:

Thanks for the details. I'll try to work through what I can and update back here. Just to clarify -- I have around 2700 bookmarks in various folders, but very few in the "Other Bookmarks" folder.

Comment 17

[Lina Butler [:lina]]

(In reply to T from comment #16)
> Thanks for the details. I'll try to work through what I can and update back
> here.

Any news, T?

Comment 18

[sabrewolfy]

(In reply to Kit Cambridge (he/him) [:kitcambridge] from comment #17)
> (In reply to T from comment #16)
> > Thanks for the details. I'll try to work through what I can and update back
> > here.
> 
> Any news, T?

Apologies -- I should have updated here. Firefox continued to exhibit difficulty syncing bookmarks and crashing, and lost some more bookmarks, so I switched to another browser :-/