983571 - browser.bookmarks.autoExportHTML = true no longer works on 29.0a2 as of 03-13-2014

Status: VERIFIED FIXED

(Firefox :: Bookmarks & History, defect)

Description

[the-edmeister]

User Agent: Mozilla/5.0 (Windows NT 5.1; rv:27.0) Gecko/20100101 Firefox/27.0 (Beta/Release)
Build ID: 20140212131424

Steps to reproduce:

browser.bookmarks.autoExportHTML = true - no longer works - Aurora 29.0a2 as of 03-13-2014 version


Actual results:

bookmarks.html file isn't being created


Expected results:

bookmarks.html file should be created upon exiting Firefox.

Comment 1

[Marco Bonardo [:mak]]

could you please try to do a manual export to html from the Library and tell me if that one works?

Comment 2

[Marco Bonardo [:mak]]

fwiw, this is very likely fixed in Nightly, so may be Aurora only

Comment 3

[Spencer Selander [greenknight]]

I just tried it in Nightly, didn't work there either.

Comment 4

[Alice0775 White]

Regression window(m-i)
Good:
https://hg.mozilla.org/integration/mozilla-inbound/rev/3a10c4605795
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:30.0) Gecko/20100101 Firefox/30.0 ID:20140207094102
Bad:
https://hg.mozilla.org/integration/mozilla-inbound/rev/9fb9effa74a6
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:30.0) Gecko/20100101 Firefox/30.0 ID:20140207094802
Pushlog:
http://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=3a10c4605795&tochange=9fb9effa74a6

Regressed by: 
	af5cdb31f131	Marco Bonardo — Bug 824433 - Bookmarks backup takes a long time to write out on shutdown. r=mano

Comment 5

[Marco Bonardo [:mak]]

Looks like the AsyncShutdown call may not work as expected in this case, before we were manually spinning the events loop and that was working fine.

Comment 6

[Spencer Selander [greenknight]]

Just checked with clean profile, no auto backup of bookmarks at all, not even .json. Imported bookmarks, restarted again, still nothing.

Comment 7

[Marco Bonardo [:mak]]

json happens only on idle.

Comment 8

[Spencer Selander [greenknight]]

How long does it need to idle? I'll test that.

Comment 9

[Marco Bonardo [:mak]]

10 minutes, though if there is no backup or the last backup is old it will try in 5... btw, that's easier to check, just see in Library / import and backup / Restore menu, there should be the list of the latest automatic backups.

Comment 10

[Spencer Selander [greenknight]]

Let it idle for 12 minutes to be sure - no backups.

Comment 11

[Marco Bonardo [:mak]]

idle detection is not perfect (there is a bug there), so you should do multiple tests. As I said, please, check in the Library if you have backups for the last week or so.

Comment 12

[Marco Bonardo [:mak]]

also, if you can export a json backup from the Library Import and Backup / Backup menuitem, there is no issue, otherwise there may be a problem with your database, but that would be a separate bug.

Comment 13

[Spencer Selander [greenknight]]

The idle test I did before was with a clean profile I created on 2-26 to test something else, hadn't been used since. Hadn't been run long enough to make backups.

In my regular Nightly profile, used daily, there are daily .json backups up to 2-20. After that, they were generated erratically, at intervals up to 5 days, last one on 3-12. Tried adding a bookmark, letting it idle, closing and reopening, no new backup.

I'm usually answering email on my laptop while Nightly is running on my desktop, so it often sits idle. I normally get backups every day.

Comment 14

[Marco Bonardo [:mak]]

it may be an add-on or a complex webapp interacting with idle (See bug 973591 for example). It would be very nice to figure the reason in your case, may be a case we are not aware of. May you try disabling add-ons? Do you have some complex weabbps usually open that may be listening to idle times to do specific work?
I'm looking at telemetry daily, may decide to reduce idle time even further if I see a good number of clients on old backups.

Comment 15

[Marco Bonardo [:mak]]

Also, we create backups at no less than 24 hours, so if you have a backup for yesterday created at evening, one for today won't be created during morning or afternoon.
That said, this bug is about bookmarks.html, so you should probably file a bug apart for backups, and we can have the discussion there.

Comment 16

[Spencer Selander [greenknight]]

Failure is consistent in repeated tests, even with all add-ons disabled, and in clean test profile.

Filed Bug 983988

Comment 17

[Marco Bonardo [:mak]]

there's no relation between the 2 bugs.

Comment 18

[Marco Bonardo [:mak]]

ok, basically the issue is that we are using a profileBeforeChange blocker for this, unfortunately Sqlite.jsm (that we are using to make the html file) as well as Places, are both shutting down at profile-before-change. So we end up trying to use them too late, since the shutdown order is not predictable.

The funny thing is that the code inside the blocker function was throwing a "Phase profile-before-change has already begun, it is too late to register completion conditions.", this made me think we were adding the blocker too late, instead it was Sqlite.jsm trying to add a new blocker later...

Before using AsyncShutdown this was working cause we were spinning at profile-change-teardown, so we were sure to not run too late.

Summing up:
1. We need a profileChangeTeardown blocker
2. the "Phase has already begun" error should also print the name of the blocker we were trying to add, to avoid confusing its consumers.
3. Likely Sqlite.jsm should shutdown later (profile-before-change2) to allow its consumers to do shutdown work at profile-before-change. I will file a separate bug for this though, since it's not needed here and this fix should likely be uplifted.

Comment 19

[Marco Bonardo [:mak]]

Attachment: patch v1

when reviewing this, please keep in mind this bug is tracked for Beta, so the patch will be uplifted to it.

Comment 20

[Marco Bonardo [:mak]]

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

ugh, I forgot to update the error in AsyncShutdown

Comment 21

[Marco Bonardo [:mak]]

Attachment: patch v2

Comment 22

[Marco Bonardo [:mak]]

PS: I filed bug 985655 for Sqlite.jsm shutdown

Comment 23

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

Comment on attachment 8393740 [details] [diff] [review]
patch v2

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

Code looks good, but I'm not convinced by the test.

::: browser/components/nsBrowserGlue.js
@@ +1073,5 @@
> +          try {
> +            yield BookmarkHTMLUtils.exportToFile(BookmarkHTMLUtils.defaultPath);
> +          } catch(ex) {
> +            // At this point there's no UI, so just dump.
> +            dump("ERROR: Unable to export bookmarks.html " + ex + "\n");

It would be nice to print the stack if there is one.

@@ +1076,5 @@
> +            // At this point there's no UI, so just dump.
> +            dump("ERROR: Unable to export bookmarks.html " + ex + "\n");
> +          }
> +        }));
> +    }

Just to be sure: the only thing you did (besides regrouping related pieces of code) is changing the phase to profileChangeTeardown, isn't it?

::: browser/components/places/tests/unit/test_browserGlue_bookmarkshtml.js
@@ +28,5 @@
> +
> +  Services.obs.addObserver(function observer() {
> +    Services.obs.removeObserver(observer, "profile-before-change");
> +    check_bookmarks_html();
> +  }, "profile-before-change", false);

profile-before-change is sent only if do_get_profile() has been called. I don't think that this is the case here.

Comment 24

[Marco Bonardo [:mak]]

(In reply to David Rajchenbach Teller [:Yoric] (please use "needinfo?") from comment #23)
> Just to be sure: the only thing you did (besides regrouping related pieces
> of code) is changing the phase to profileChangeTeardown, isn't it?

yes, but I cannot do that at places-shutdown cause it happens at teardown as well. So I just moved that to initPlaces.

> ::: browser/components/places/tests/unit/test_browserGlue_bookmarkshtml.js
> @@ +28,5 @@
> > +
> > +  Services.obs.addObserver(function observer() {
> > +    Services.obs.removeObserver(observer, "profile-before-change");
> > +    check_bookmarks_html();
> > +  }, "profile-before-change", false);
> 
> profile-before-change is sent only if do_get_profile() has been called. I
> don't think that this is the case here.

Places doesn't make sense without a profile, thus any Places test runs only with a profile. all xpcshell tests in Places include head_common.js that always invokes do_get_profile() (I actually wrote the code that notifies profile notifications in xpcshell iirc)

Comment 25

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

Could you document this, in that case? I couldn't find where do_get_profile() gets called.

Comment 26

[L.A.R. Grizzly]

I'm running FX 29.0b1 and I'm getting the.html file created in my profile folder, but it's either corrupt or it's making a blank one. The file size is much smaller than when I manually export to .html. Opening the file in the browser shows a blank page.

Comment 27

[Marco Bonardo [:mak]]

(In reply to David Rajchenbach Teller [:Yoric] (please use "needinfo?") from comment #25)
> Could you document this, in that case? I couldn't find where
> do_get_profile() gets called.

where should I document it? I don't think there's a good point where I can document all Places xpcshell-tests use head_common.js... And surely I'm not going to add such documentation to each test :)

Comment 28

[Marco Bonardo [:mak]]

(In reply to L.A.R. Grizzly from comment #26)
> I'm running FX 29.0b1 and I'm getting the.html file created in my profile
> folder, but it's either corrupt or it's making a blank one. The file size is
> much smaller than when I manually export to .html. Opening the file in the
> browser shows a blank page.

the code that exports "manually" or "automatically" is exactly the same, I suspect the html you get created is actually not, it's just an old one that keeps stayin there? There's no way the current code may export to html automatically, that's the primary reason this bug exists.

Comment 29

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

Oh, right, I had missed the loadSubScript to head_common.js. Weirdish, but ok.

Comment 30

[Marco Mucci [:MarcoM]]

Hi Marco, Gavin told me this bug had to be added to the current iteration.  Can you provide a point estimate.  Thanks.

Comment 31

[Marco Bonardo [:mak]]

I think it's an easy:3. Thanks.

Comment 32

[Marco Mucci [:MarcoM]]

Thanks Marco.  All updated.

Comment 33

[Marco Mucci [:MarcoM]]

Hi Anthony, can you review if this bug should be [qa+] or [qa-] for verification.

Comment 34

[Marco Bonardo [:mak]]

Attachment: patch v3

I think I replied to all of the comments, this is identical as before apart printing the stack.

As I said I don't think it's worth to add a comment about do_get_profile and yes, the only change is basically moving this stuff to profile-change-teardown

Comment 35

[Marco Bonardo [:mak]]

I wrongly pushed this cause it was in my queue, and backed out cause of missing review.
https://hg.mozilla.org/integration/fx-team/rev/0469cf95fbfe
https://hg.mozilla.org/integration/fx-team/rev/f8ac41a79fc0

Comment 36

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

Comment on attachment 8395189 [details] [diff] [review]
patch v3

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

::: browser/components/nsBrowserGlue.js
@@ +1074,5 @@
> +            yield BookmarkHTMLUtils.exportToFile(BookmarkHTMLUtils.defaultPath);
> +          } catch(ex) {
> +            // At this point there's no UI, so just dump.
> +            dump("ERROR: Unable to export bookmarks.html " + ex + "\n"
> +                                                           + ex.stack + "\n");

If you just return 
|BookmarkHTMLUtils.exportToFile(BookmarkHTMLUtils.defaultPath)|, AsyncShutdown will report the error automatically with the following message:

"A completion condition encountered an error" +
                " while we were spinning the event loop." +
                " Condition: " + name +
                " Phase: " + topic +
                " State: " + safeGetState(state);

Your call.

::: toolkit/modules/AsyncShutdown.jsm
@@ +285,5 @@
>    addBlocker: function(condition) {
>      if (!this._conditions) {
>        throw new Error("Phase " + this._topic +
> +                      " has already begun, it is too late to register '" +
> +                      condition.name + "' completion condition.");

"it is too late to register completion condition '" + condition.name + "'."

Comment 37

[Marco Bonardo [:mak]]

with comments addressed:
https://hg.mozilla.org/integration/fx-team/rev/f162ae54353d

Regarding QA, I think it would be worth to do manual testing that bookmarks.html is properly exported if the browser.bookmarks.autoExportHTML pref is set to true.
Even if we have a test, shutdown conditions are always particular.

Comment 38

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/f162ae54353d

Comment 39

[Marco Bonardo [:mak]]

Comment on attachment 8395189 [details] [diff] [review]
patch v3

[Approval Request Comment]
Bug caused by (feature/regressing bug #): bug 824433
User impact if declined: bookmarks.html is not created anymore for users who enabled it
Testing completed (on m-c, etc.): m-c
Risk to taking this patch (and alternatives if risky): low
String or IDL/UUID changes made by this patch: none

Comment 40

[Marco Bonardo [:mak]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/4254ea7e3668
https://hg.mozilla.org/releases/mozilla-beta/rev/450a302d1ffa

Comment 41

[Marco Bonardo [:mak]]

backed out from Beta due to xpcshell failure, looks like Beta is missing some fix related to OS.File or AsyncShutdown

https://hg.mozilla.org/releases/mozilla-beta/rev/1009928465c9

04:55:46     INFO -  [4301] WARNING: NS_ENSURE_TRUE(aFile) failed: file /builds/slave/m-beta-osx64-d-000000000000000/build/netwerk/base/src/nsFileStreams.cpp, line 304
04:55:46     INFO -  WARNING: A completion condition encountered an error while we were spinning the event loop. Condition: Places: export bookmarks.html Phase: profile-change-teardown
04:55:46     INFO -  WARNING: [Exception... "Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIFileOutputStream.init]"  nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)"  location: "JS frame :: resource://gre/modules/BookmarkHTMLUtils.jsm :: doExportToFile :: line 913"  data: no]
04:55:46  WARNING -  TEST-UNEXPECTED-FAIL | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/browser/components/places/tests/unit/head_bookmarks.js -> file:///builds/slave/talos-slave/test/build/tests/xpcshell/tests/toolkit/components/places/tests/head_common.js | false == true - See following stack:

Comment 42

[Marco Bonardo [:mak]]

or more likely, it's missing bug 968177, so BookmarkHTMLUtils.defaultPath doesn't exist!

Comment 43

[Marco Bonardo [:mak]]

Attachment: beta patch

basically the same patch, but without using BookmarkHTMLUtil.defaultPath, I'm rather using the old nsIFile code that was already there.
Not going to further as for review or approval cause the patch is the same and the "new" code is the old one that is already in beta.

Comment 44

[Marco Bonardo [:mak]]

https://hg.mozilla.org/releases/mozilla-beta/rev/79b2b6339413

Comment 45

[u279076]

qa- as per in-testsuite coverage. Please needinfo me if you think this needs more thorough verification.

Comment 46

[L.A.R. Grizzly]

This bug is fixed in FX 29.0b4 on my system.

Comment 47

[u279076]

(In reply to L.A.R. Grizzly from comment #46)
> This bug is fixed in FX 29.0b4 on my system.

Thanks for following up.