991668 - Exporting bookmarks.html may cause AsyncShutdown to abort crash due to "too much recursion" error caused by old promises in Task.jsm

Status: VERIFIED FIXED

(Firefox :: Bookmarks & History, defect)

Description

[Alice0775 White]

Aurora30.0a2  bp-241e7e33-02be-4c4b-98ff-6428a2140403 
Nightly31.0a1 bp-edcda2c0-d58c-4692-8404-7f0a32140403
=============================================================

Steps To Reproduce(For example):
1. Copy places.sqlite (has a lot of bookmarks and history) to newly created profile
2. Add user_pref("browser.bookmarks.autoExportHTML", true); to prefs.js

3. Start Firefox
4. Open Web page
5. Exit
6. Repeat Step3-5 if need.

Actual Results:
Process of firefox.exe remains in Task Manager for a while.
And finally, browser crashes with the crash reports

Expected Results:
Process should disappear immediately after exit.
And no crash.

Setting browser.bookmarks.autoExportHTML = false, seems to fixe the delay and the crash.

Comment 1

[Alice0775 White]

Regression window(m-aurora)
Good:
https://hg.mozilla.org/releases/mozilla-aurora/rev/488dfb56e066
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:30.0) Gecko/20100101 Firefox/30.0 ID:20140402120633
Bad:
https://hg.mozilla.org/releases/mozilla-aurora/rev/b728a2085cba
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:30.0) Gecko/20100101 Firefox/30.0 ID:20140403004002
Pushlog:
http://hg.mozilla.org/releases/mozilla-aurora/pushloghtml?fromchange=488dfb56e066&tochange=b728a2085cba



Regression window(m-c)
Good:
https://hg.mozilla.org/mozilla-central/rev/d8e8f13bd4ae
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:31.0) Gecko/20100101 Firefox/31.0 ID:20140331034733
Bad:
https://hg.mozilla.org/mozilla-central/rev/723177fe1452
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:31.0) Gecko/20100101 Firefox/31.0 ID:20140331141434
Pushlog:
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=d8e8f13bd4ae&tochange=723177fe1452



Regression window(m-i)
Good:
https://hg.mozilla.org/integration/mozilla-inbound/rev/5f18b20580a3
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:31.0) Gecko/20100101 Firefox/31.0 ID:20140331091032
Bad:
https://hg.mozilla.org/integration/mozilla-inbound/rev/feae125fca6f
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:31.0) Gecko/20100101 Firefox/31.0 ID:20140331094034
Pushlog:
http://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=5f18b20580a3&tochange=feae125fca6f



Nothing suspicious....

Comment 2

[Alice0775 White]

Attachment: zipped places.sqlite

Comment 3

[Alice0775 White]

browser.bookmarks.autoExportHTML triggers something?

Comment 4

[David Teller [:Yoric] - still alive but not very active]

It's an AsyncShutdown timeout: {"phase":"profile-change-teardown","conditions":[{"name":"Places: export bookmarks.html","state":"(none)"}]}

Comment 5

[Marco Bonardo [:mak]]

I suspect the AsyncShutdown timeout is just too short for some bookmarks.html files creation. These files are much slower than json backups to create, cause they also contain favicons, so for each bookmark we have to fetch and store the icon as a datauri, multiplying that by number of bookmarks makes a long time. That's usually not a big deal cause this feature is disabled by default, very few users have both this enabled and that many bookmarks and they are aware of the shutdown cost. In some pathological cases it can definitely take more than one minute and thus hit the timeout crash.
From telemetry I see that 86% of users are taking less than 2 seconds, the data doesn't give me fine-grained stats above that value, but my guess is this may hit very few users.

How many bookmarks are we talking about here?

you can probably workaround this by setting toolkit.asyncshutdown.crash_timeout pref to higher values than 60000 (1 minute in milliseconds).

David, may we report these delays without actually causing a crash in front of the user?

Comment 6

[David Teller [:Yoric] - still alive but not very active]

The crash is not meant "just" to report the delay, but to avoid shutdown taking forever. I believe that the issue should be fixed in the bookmarks.html code, perhaps by having the ability to give up after $n$ seconds.

Comment 7

[Alice0775 White]

Number of bookmarks is 1615.

I set toolkit.asyncshutdown.timeout.crash = 6000000 (100 minute),
however, browser crashes in 60sec.
bp-302abb9c-e07f-4141-abfc-37b492140403

After crashed, bookmarks.html is created and sized 20kB, and contained only 105 lines. 
It seems not successfully written.

Comment 8

[Alice0775 White]

Aha, pref name is wrong.


Number of bookmarks is 1615.

I set toolkit.asyncshutdown.crash_timeout = 6000000 (100 minute),

CPU usage is 0% forever.... after exit browser.
So, the browser seems to be hung up.

I killed the process.

Comment 9

[Alice0775 White]

In Firefox24 with same profile, the process disappears within 10sec and successfully created Bookbarks.html.

Comment 10

[David Teller [:Yoric] - still alive but not very active]

Filed bug 992141 to help debugging such issues.

Comment 11

[Marco Bonardo [:mak]]

Alice0775 White any possibility you may send me that places.sqlite through e-mail?
Maybe there's some corruption into it that causes the bookmarks.html code to loop forever.

Comment 12

[Marco Bonardo [:mak]]

ah wait, it's attached here, nvm!

Comment 13

[Marco Bonardo [:mak]]

ok, there's a "too much recursion" error coming out when trying to store bookmarks.html. That's clearly not expected. I suspect a data coherency issue, will check.

Comment 14

[Marco Bonardo [:mak]]

hm, I wonder if this is due to the fact Task.jsm still uses old promises and so we end up with excessive recursion, I think this was one of the reasons we moved to Promise.jsm...

Comment 15

[Marco Bonardo [:mak]]

I indeed see a really long stack of task and promise calls... so my suspect is basically confirmed. I'm not sure we can do much until bug 887923, we could try to workaround by interrupting the stack with some timeout(0).

Comment 16

[Marco Bonardo [:mak]]

Attachment: patch v1

Indeed, this simple workaround solves the problem

Now, I'd like to understand why AsyncShutdown doesn't catch the "too much recursion error". I wonder if, being generated by the js engine, it may just pass-through, or if the code is not properly handling out all errors.

Comment 17

[Marco Bonardo [:mak]]

If I run this snippet I properly see the failure in nightly, so doesn't look like an issue in BookmarkHTMLUtils code, looks like AsyncShutdown is somehow swallowing the error.

Cu.import("resource://gre/modules/BookmarkHTMLUtils.jsm");
Cu.import("resource://gre/modules/Task.jsm");
Task.spawn( function* () {
  yield BookmarkHTMLUtils.exportToFile(BookmarkHTMLUtils.defaultPath);
}).then(()=>window.alert("success"), ex=>window.alert(ex))

Comment 18

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8401916 [details] [diff] [review]
patch v1

Review of attachment 8401916 [details] [diff] [review]:
-----------------------------------------------------------------

r=me, but please revert that change once it's not required anymore. Maybe open a followup bug?

Comment 19

[Marco Bonardo [:mak]]

https://hg.mozilla.org/integration/fx-team/rev/47e0c3bda71e

Comment 20

[Marco Bonardo [:mak]]

Comment on attachment 8401916 [details] [diff] [review]
patch v1

[Approval Request Comment]
Bug caused by (feature/regressing bug #): async backups refactoring
User impact if declined: crash after minutes long shutdown
Testing completed (on m-c, etc.): fx-team
Risk to taking this patch (and alternatives if risky): simple workaround, low risk
String or IDL/UUID changes made by this patch: none

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/47e0c3bda71e

Comment 22

[Marco Bonardo [:mak]]

Alice0775, may you please confirm that this bug doesn't affect Beta?
while I originally thought this was due to AsyncShutdown (and thus beta was affected) I now think the primary cause is rather bug 968177, and if so Beta is not affected, as correctly indicated by the tracking. If so we only need Aurora approval and I was a little bit overzealous.

Comment 23

[Alice0775 White]

(In reply to Marco Bonardo [:mak] from comment #22)
> Alice0775, may you please confirm that this bug doesn't affect Beta?

I cannot reproduce this problem in Firefox29.0b6.
https://hg.mozilla.org/releases/mozilla-beta/rev/71439d266704
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:29.0) Gecko/20100101 Firefox/29.0 ID:20140407135746

Comment 24

[Marco Bonardo [:mak]]

thanks

Comment 25

[Sylvestre Ledru [:Sylvestre]]

Comment on attachment 8401916 [details] [diff] [review]
patch v1

Approving only for aurora for now (see comment #22)

Comment 26

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/97a2ac00384c

Comment 27

[u279076]

Florin, please assign this for verification in this iteration.

Comment 28

[Paul Silaghi, QA [:pauly]]

Reproduced in Nightly 2014-04-05.
Verified fixed FF 30.0a2 (2014-04-18), 31.0a1 (2014-04-18) Win 7, Ubuntu 12.10, OS X 10.9.2.