Closed Bug 1272652 Opened 8 years ago Closed 8 years ago

Firefox fails to import bookmarks from Chrome when it also tries to import a large history

Categories

(Firefox :: Migration, defect)

47 Branch
defect
Not set
normal

Tracking

()

VERIFIED FIXED
Firefox 49
Tracking Status
firefox46 --- unaffected
firefox47 + verified
firefox48 --- verified
firefox49 --- verified

People

(Reporter: bmaris, Assigned: mak)

References

Details

(Keywords: regression)

Attachments

(3 files)

[Affected versions]:
- Firefox 47 beta 5
- latest Developer Edition 48.0a2
- latest Nightly 49.0a1

[Unaffected versions]:
- Firefox 46.0.1

[Affected platforms]:
- Mac OS X 10.10.5 (although I did not reproduce on another machine running 10.11.2 and 10.10.4)
- Windows 7 64-bit (unable to reproduce on Windows 10 64-bit and Ubuntu 16.04 32-bit)

[Steps to reproduce]:
1. Run Firefox for the first time (or simply remove the profiles folder: On Windows - %appdata%\Mozilla; On Mac - Library\Application Support\Firefox; On Linux - /home/user/.mozilla)
2. Go to "Bookmarks -> Show All Bookmarks -> Import and Backup -> Import Data from Another Browser
3. Make sure Chrome is not running
4. Import data from Chrome

[Expected result]:
- Bookmarks are successfully imported

[Actual result]:
- Bookmarks are not imported. Folder 'Imported from Chrome' is empty.

[Regression range]:
- I am unable to determine a regression range using mozregression but:
Mac OS X 10.10.5 - Firefox 47 beta 4 is not affected by this, so it's something between 47 beta 4 and beta 5.
Windows 7 64-bit - Firefox 46.0 RC build 5 is not affected, all 47 betas are affected.

[Additional notes]:
- Console output:

[Exception... "Component returned failure code: 0x804b000a (NS_ERROR_MALFORMED_URI) [nsIIOService.newURI]" nsresult: "0x804b000a (NS_ERROR_MALFORMED_URI)" location: "JS frame :: resource://gre/modules/NetUtil.jsm :: NetUtil_newURI :: line 191" data: no]
ChromeProfileMigrator.js:319:0
Error: Transaction timeout, most likely caused by unresolved pending work.
Stack trace:
ConnectionData.prototype<.executeTransaction/promise</timeoutPromise</<@resource://gre/modules/Sqlite.jsm:641:33
setTimeout_timer@resource://gre/modules/Timer.jsm:30:5
Sqlite.jsm:648
some bookmarks did not successfully migrate.
TypeError: PlacesUtils.asContainer(...) is null
places.js:336:7
NS_ERROR_ILLEGAL_VALUE: Invalid arguments nsLivemarkService.js:299:0
TypeError: PlacesUtils.asContainer(...) is null
places.js:336:7

(this console output is received on both Windows and Mac)
[Tracking Requested - why for this release]:
Recent regression with a high impact on users that want to migrate from Chrome.
Marco, can you comment on the places exception? It looks like the insertion of the bookmarks is just slow...

Bogdan, can you try creating a clean chrome profile and importing that, and seeing if that succeeds? I'm wondering if this is just correlated with the size of the chrome profile, which will make this tricky to reproduce, debug and fix...
Flags: needinfo?(mak77)
Flags: needinfo?(bogdan.maris)
The malformed uri error should be benign, it comes from the history migrator, we should just continue.

The Transaction timeout error indicates a transaction didn't resolve/reject its promise after 2 minutes. That usually indicates either a very very large transaction, or someone forgot to resolve/reject a promise, or there is indented transactions, or something is wrong here http://mxr.mozilla.org/mozilla-central/source/toolkit/modules/Sqlite.jsm#640
The 2 minutes time there has been mostly a guess, there should be no problem in increasing it if we figure it's too small.

In this case, I'd expect we have a lot of tiny transactions, not a big one, and each of them should have 2 minutes timeout. I'm not sure how it could take so much time, unless the disk is so busy to blocks everything for 2 minutes.

The number of bookmarks may matter, would be nice to have a large Chrome db to be able to reproduce.
Though I'm not sure why 46 to 47 should make a difference
Flags: needinfo?(mak77)
Tracked as blocking since it's a critical recent regression.
(In reply to Ritu Kothari (:ritu) from comment #4)
> Could it be related to this fix we uplifted in 47.0b5?
> https://bugzilla.mozilla.org/show_bug.cgi?id=1271280

I'll double-triple-check with Marco to be sure, but I think that bug strictly concerns shutdown code. This is happening on startup or while the browser is (and stays) running, so no, I don't think that's related.

(In reply to Ritu Kothari (:ritu) from comment #5)
> Tracked as blocking since it's a critical recent regression.

We can track this, but without conclusive STR (comment #0 mentions some builds on some OSes are affected, but the same builds are broken/working on others, and does not distinguish why that would be) it is practically impossible that we're going to get this fixed. This really really needs more detailed steps to reproduce.
Flags: needinfo?(mak77)
(In reply to Ritu Kothari (:ritu) from comment #4)
> Could it be related to this fix we uplifted in 47.0b5?
> https://bugzilla.mozilla.org/show_bug.cgi?id=1271280

no, I'm sure it's unrelated.
Flags: needinfo?(mak77)
(In reply to :Gijs Kruitbosch from comment #2)
> Marco, can you comment on the places exception? It looks like the insertion
> of the bookmarks is just slow...
> 
> Bogdan, can you try creating a clean chrome profile and importing that, and
> seeing if that succeeds? I'm wondering if this is just correlated with the
> size of the chrome profile, which will make this tricky to reproduce, debug
> and fix...

I have no problem importing from a clean Chrome profile. I even made like 800 bookmarks (my personal profile which I use to reproduce this has 350) and all of them were migrated successfully.

I think that it has something to do with Browsing History. If I have all three options selected (on Mac) to migrate Cookies, Browsing History and Bookmarks or Browsing History & Bookmarks the issue will reproduce. If I have only Cookies and Bookmarks selected the issue will not reproduce. Same on the Windows machine that we reproduced, when Browsing History is selected alongside Bookmarks, the issue will reproduce.

I also need to mention that the import Wizard will be stuck for a longer time then usual when importing Bookmarks (but only when Browsing History is checked as well).

Let me know if I can help further on.
Flags: needinfo?(bogdan.maris)
Bogdan, would you be comfortable with sharing the history from the broken profile with Marco and me via email? (not sure if you use it regularly or if anything private is in it...)
Flags: needinfo?(bogdan.maris)
OK, if history is involved, this is likely the same as bug 1249008, and I'm not sure there's a real regression here.
The "solution" is explained at https://bugzilla.mozilla.org/show_bug.cgi?id=1249008#c9, we need to wait for updatePlaces to be complete before proceeding, by using its handleCompletion callback.
Assignee: nobody → mak77
Status: NEW → ASSIGNED
Summary: Firefox fails to import bookmarks from Chrome → Firefox fails to import bookmarks from Chrome when it also tries to import a large history
I wonder if, in a separate bug, we should limit history import to only visits in the last N days.
Importing history takes quite some time... While things like bug 1209027 may help us here, we could still want a limit.
Comment on attachment 8755444 [details]
MozReview Request: Bug 1272652 - Firefox fails to import bookmarks from Chrome if it also imports a large history. r=gijs

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/54616/diff/1-2/
Attachment #8755444 - Flags: review?(gijskruitbosch+bugs) → review+
Comment on attachment 8755444 [details]
MozReview Request: Bug 1272652 - Firefox fails to import bookmarks from Chrome if it also imports a large history. r=gijs

https://reviewboard.mozilla.org/r/54616/#review51232

This looks OK to me. If we don't already, it'd be lovely to have some tests for this migrator, but we can push that to a followup if necessary. I'm assuming you've done some manual testing for now (though it's a bit surprising they didn't show the issue I noted below?).

::: browser/components/migration/MigrationUtils.jsm:232
(Diff revision 2)
> +    // Used to periodically give back control to the main-thread loop.
> +    let unblockMainThread = new Promise(resolve => {
> +      Services.tm.mainThread.dispatch(resolve, Ci.nsIThread.DISPATCH_NORMAL);
> +    });

This should be a function that returns a promise, no? Right now it just gets set to a single promise, which is then called as a function further down?
(In reply to :Gijs Kruitbosch from comment #14)
> This looks OK to me. If we don't already, it'd be lovely to have some tests
> for this migrator, but we can push that to a followup if necessary. I'm
> assuming you've done some manual testing for now (though it's a bit
> surprising they didn't show the issue I noted below?).
 in
Yes, I thought about that, but no acceptable test would catch the issue we are fixing in this bug, and this kind of test is a very good target for a mentored bug.
I did a manual migration and verified contests were migrated. Strange I didn't notice the promise problem, I will do another testing round.
I am trying to look at the failure, that I can reproduce locally, but the error message is puzzling and I'm not sure exactly what is failing.
So far I only fixed a couple nits in the test, but I'm sort of blocked on what is exactly failing...
I hope Henrik can help me here.
Flags: needinfo?(mak77) → needinfo?(hskupin)
I wrote the test in question. :-)

The error message just means that the browser doesn't start and so marionette does not get connected up to the browser after the restart. In this case, it seems the migration process gets hung on something, and never completes. I don't know what/why. I tried to debug late last night but didn't get any further. You can see this happening locally as the migration results dialog gets stuck with "other data" still in bold (so it's not been migrated (yet), or at least the dialog doesn't know about it).
Flags: needinfo?(hskupin)
Marco, this is an intermittent issue. Simply retrigger the test via TH and hopefully it will work this time.
(In reply to Henrik Skupin (:whimboo) from comment #20)
> Marco, this is an intermittent issue. Simply retrigger the test via TH and
> hopefully it will work this time.

No, this particular test went perma-orange with this failure message after the commit, and it got fixed when we backed it out again.

It'd be useful if we had screenshots for these failures, it'd make it easier to distinguish *why* marionette failed to reconnect to the browser...
Marionette is creating screenshots but they are not uploaded to Treeherder. If that test would be part of the firefox-ui-test suite, you would get screenshots like the HTML report for that job: 

https://treeherder.mozilla.org/#/jobs?repo=mozilla-aurora&filter-searchStr=Firefox%20UI&filter-tier=2&filter-tier=3&selectedJob=2653042

If you want to keep using the base Marionette framework you might want to file a bug to get screenshots added.
(In reply to Henrik Skupin (:whimboo) from comment #22)
> Marionette is creating screenshots but they are not uploaded to Treeherder.
> If that test would be part of the firefox-ui-test suite.

That would be OK if firefox-ui-test was tier-1, but it isn't. :-(

> If you want to keep using the base Marionette framework you might want to
> file a bug to get screenshots added.

Done: bug 1275243.
(In reply to :Gijs Kruitbosch from comment #23)
> > Marionette is creating screenshots but they are not uploaded to Treeherder.
> > If that test would be part of the firefox-ui-test suite.
> 
> That would be OK if firefox-ui-test was tier-1, but it isn't. :-(

Working on it via bug 1272228. But yes, its only linux64 right now. Anyway, a discussion point for another place.

Regarding this failure here it would be good to have bug 1275013 fixed which would give us definitely a better picture of what's going on.
ok here is the problems:
1. we are doing a splice while walking an array. Due to time shifting this became visible (by making the test timing out on otherdata). Fixed by using a Set (was already planned).
2. the Marionette test when ran locally on Win 10 also open a mozilla.org page, and that may set a cookie we don't expect.
3. the Marionette timeout when waiting for a window is too short (60 seconds) and caused the test to fail for me permanently. I doubled that timeout to 120s and that fixed my local problem. I'm not going to fix this here, hope to fix it in a follow-up and that I can still land before that (Try will tell).
(In reply to Marco Bonardo [::mak] from comment #25)
> ok here is the problems:
> 1. we are doing a splice while walking an array. Due to time shifting this
> became visible (by making the test timing out on otherdata). Fixed by using
> a Set (was already planned).
> 2. the Marionette test when ran locally on Win 10 also open a mozilla.org
> page, and that may set a cookie we don't expect.

We should set the relevant pref on win10 in the test profile (browser.usedOnWindows10) so this doesn't happen.

> 3. the Marionette timeout when waiting for a window is too short (60
> seconds) and caused the test to fail for me permanently. I doubled that
> timeout to 120s and that fixed my local problem. I'm not going to fix this
> here, hope to fix it in a follow-up and that I can still land before that
> (Try will tell).
(In reply to :Gijs Kruitbosch from comment #26)
> We should set the relevant pref on win10 in the test profile
> (browser.usedOnWindows10) so this doesn't happen.

well, I fixed the code to only consider meaningful cookies, in any case.
In future it may be other pages, or other features, we can't keep up with prefs.
Comment on attachment 8755444 [details]
MozReview Request: Bug 1272652 - Firefox fails to import bookmarks from Chrome if it also imports a large history. r=gijs

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/54616/diff/2-3/
Comment on attachment 8755892 [details]
MozReview Request: Bug 1272652 - Fix Marionette tests. r=Gijs

https://reviewboard.mozilla.org/r/54862/#review51508
Attachment #8755892 - Flags: review?(gijskruitbosch+bugs) → review+
Depends on: 1275296
(In reply to Marco Bonardo [::mak] from comment #25)
> 2. the Marionette test when ran locally on Win 10 also open a mozilla.org
> page, and that may set a cookie we don't expect.

A test in the tier-1 test suite should not open a remote page. Usually this should cause a crash but Marionette doesn't handle the appropriate env variable yet (bug 1272255).
Version: Trunk → 47 Branch
https://hg.mozilla.org/mozilla-central/rev/59cf6bd00ec8
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 49
Hi Marco, do you think this is safe to uplift to Fx47 this late in the cycle? We enter RC week on Monday. This seems like a recent and critical regression that might meet the uplift bar as such.
Flags: needinfo?(mak77)
Hi Bogdan, could you please test this fix on the latest Nightly build? This will help us decide whether this is something that ought to be uplifted during RC week or not.
Hi Florin, fyi for comment 36.
Flags: needinfo?(florin.mezei)
(In reply to Ritu Kothari (:ritu) from comment #36)
> Hi Bogdan, could you please test this fix on the latest Nightly build? This
> will help us decide whether this is something that ought to be uplifted
> during RC week or not.

Sure thing.
I used the latest Nightly build and the migration was successfully, so I can't reproduce this issue anymore.

Though I noticed that the Import Wizard is acting a bit funny. On step 1 it is shown that 'Bookmarks' are imported, on step 2 'Browsing History', on step 3 it stays like this for 1 minute (for my profile), on step 4 the import is done. Is this the correct display here? The behavior before this fix was -Cookies->Browsing History->Bookmarks exactly in the order displayed by Import wizard.

Also I noticed that during the migration the browser becomes unusable, but this is not a recent regression, I saw this on 44.0.2 as well. After the migration is completed, the browser becomes usable again.

I don't have logged bugs on this potential issues yet, waiting for other opinions.
Flags: needinfo?(florin.mezei)
Flags: needinfo?(bogdan.maris)
(In reply to Bogdan Maris, QA [:bogdan_maris] from comment #38)
> Though I noticed that the Import Wizard is acting a bit funny. On step 1 it
> is shown that 'Bookmarks' are imported, on step 2 'Browsing History', on
> step 3 it stays like this for 1 minute (for my profile), on step 4 the
> import is done. Is this the correct display here? The behavior before this
> fix was -Cookies->Browsing History->Bookmarks exactly in the order displayed
> by Import wizard.

But I assume cookies are still properly imported, did you check that?
I suspect it's due to the fact cookies and history start at the same time and history wins the race at updating the ui, from that point on the main-thread is likely quite busy keeping up with history and bookmarks notifications, that could explain the long step 3.
The UX here is not that great. But if everything is properly migrated, we should not block on just this, it has always been quite horrible.
The fact before it was happening in order was probably "by luck" since we never had a sequential order here, all the migrators were starting at the same time (and now some is concurrent, some is sequential).

> Also I noticed that during the migration the browser becomes unusable, but
> this is not a recent regression, I saw this on 44.0.2 as well. After the
> migration is completed, the browser becomes usable again.

I think this is just due to the I/O hit we take.
It may improve once we introduce new perf fixes for history inserts (we are working on those).

To answer the uplift question, if QA can verify cookies are properly imported, even if the UI acts "strangely" I think this is OK to uplift.
Flags: needinfo?(mak77) → needinfo?(bogdan.maris)
(In reply to Marco Bonardo [::mak] from comment #39)
> (In reply to Bogdan Maris, QA [:bogdan_maris] from comment #38)
> > Though I noticed that the Import Wizard is acting a bit funny. On step 1 it
> > is shown that 'Bookmarks' are imported, on step 2 'Browsing History', on
> > step 3 it stays like this for 1 minute (for my profile), on step 4 the
> > import is done. Is this the correct display here? The behavior before this
> > fix was -Cookies->Browsing History->Bookmarks exactly in the order displayed
> > by Import wizard.
> 
> But I assume cookies are still properly imported, did you check that?
> I suspect it's due to the fact cookies and history start at the same time
> and history wins the race at updating the ui, from that point on the
> main-thread is likely quite busy keeping up with history and bookmarks
> notifications, that could explain the long step 3.
> The UX here is not that great. But if everything is properly migrated, we
> should not block on just this, it has always been quite horrible.
> The fact before it was happening in order was probably "by luck" since we
> never had a sequential order here, all the migrators were starting at the
> same time (and now some is concurrent, some is sequential).
> 
> > Also I noticed that during the migration the browser becomes unusable, but
> > this is not a recent regression, I saw this on 44.0.2 as well. After the
> > migration is completed, the browser becomes usable again.
> 
> I think this is just due to the I/O hit we take.
> It may improve once we introduce new perf fixes for history inserts (we are
> working on those).
> 
> To answer the uplift question, if QA can verify cookies are properly
> imported, even if the UI acts "strangely" I think this is OK to uplift.

Cookies are imported yes, although not all of them (see this screenshot: http://i.imgur.com/I4T6AiU.png)
Flags: needinfo?(bogdan.maris) → needinfo?(mak77)
Chrome started using encrypted cookies some time ago, and we don't yet support decrypting them, so that's expected (Bug 1163165, Bug 1163166, Bug 1163167).

So yes, I think we can uplift.
Flags: needinfo?(mak77)
Comment on attachment 8755444 [details]
MozReview Request: Bug 1272652 - Firefox fails to import bookmarks from Chrome if it also imports a large history. r=gijs

Approval Request Comment
[Feature/regressing bug #]: No regression, it's an everlasting bug in the Chrome migrator.
[User impact if declined]: when Chrome history is large, we may fail migrating all of the bookmarks.
[Describe test coverage new/current, TreeHerder]: Nightly
[Risks and why]: The risk is that we somehow break migration from other browsers, but since QA tested it working, it should be fine.
[String/UUID change made/needed]: none
Attachment #8755444 - Flags: approval-mozilla-beta?
Attachment #8755444 - Flags: approval-mozilla-aurora?
For completeness, I should add that also Firefox Reset is a feature that depends on migration.
Comment on attachment 8755444 [details]
MozReview Request: Bug 1272652 - Firefox fails to import bookmarks from Chrome if it also imports a large history. r=gijs

Fix a long standing issue, taking it.
However, Ritu will make the call for beta but I don't think it matches our criteria
Attachment #8755444 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Comment on attachment 8755444 [details]
MozReview Request: Bug 1272652 - Firefox fails to import bookmarks from Chrome if it also imports a large history. r=gijs

I was a bit concerned about this fix but after chatting with Dolske (who is in favor of uplifting this to Fx47), I have decided to take in RC1. We are focusing on Onboarding experience and this bug is critical enough to make a positive dent in that area. Beta47+
Attachment #8755444 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Flags: qe-verify+
Removing "qawanted" and "regressionwindow-wanted" keywords, since we already have a fix and only need verification here.
hi, there was a new crash OOM | large | mozalloc_abort | mozalloc_handle_oom | moz_xrealloc | sqlite3AffinityType (bug 1278040) jumping up in the 47 RC builds - may this be related to the work here in this bug?
Flags: needinfo?(mak77)
I also can confirm that this issue is fixed on Firefox 47.0 RC and latest Developer Edition 48.0a2.
Status: RESOLVED → VERIFIED
Flags: qe-verify+
(In reply to [:philipp] from comment #49)
> hi, there was a new crash OOM | large | mozalloc_abort | mozalloc_handle_oom
> | moz_xrealloc | sqlite3AffinityType (bug 1278040) jumping up in the 47 RC
> builds - may this be related to the work here in this bug?

I replied directly in that bug.
Flags: needinfo?(mak77)
You need to log in before you can comment on or make changes to this bug.