711937 - [SeaMonkey] xpcshell: "TEST-UNEXPECTED-FAIL | [...]/test_clearHistory_shutdown.js | places-expiration-finished == places-connection-closed"

Status: VERIFIED FIXED

(SeaMonkey :: Bookmarks & History, defect)

Description

[Serge Gautherie (:sgautherie)]

(See beginning of discussion in bug 709829...)

'places-expiration-finished' notification is not received anymore :-(

[Mozilla/5.0 (Windows NT 5.0; rv:10.0a1) Gecko/20111017 Firefox/10.0a1 SeaMonkey/2.7a1] (nightly, 2011-10-17-00-30-01-comm-central-trunk)
m-c: cf5da681d577
c-c: a3c4a41ba069
Has older error. (To be investigated after this bug...)

[Mozilla/5.0 (Windows NT 5.0; rv:10.0a1) Gecko/20111031 Firefox/10.0a1 SeaMonkey/2.7a1] (nightly, 2011-10-31-00-30-01-comm-central-trunk)
m-c: 67d1049b0bf9
c-c: c63ad16c02bc
Has 'places-expiration-finished' "regression".

2 weeks regression timeframe:
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=cf5da681d577&tochange=67d1049b0bf9
http://hg.mozilla.org/comm-central/pushloghtml?fromchange=a3c4a41ba069&tochange=c63ad16c02bc

There are a few more Linux/Mac builds in between, but not many at all...
qawanted: need someone to do a bisect or debug session.

Comment 1

[Serge Gautherie (:sgautherie)]

(Quick search, wild guess, may be irrelevant:)

http://hg.mozilla.org/mozilla-central/rev/1ed8be9fed39
'toolkit/components/places/utils.js' was removed.

http://mxr.mozilla.org/comm-central/ident?i=openNodeWithEvent
SeaMonkey (still) has both
suite/common/history/utils.js
suite/common/src/PlacesUIUtils.jsm

Comment 2

[Jens Hatlak (:InvisibleSmiley)]

In bug 709829 you wrote:
  Last time it started to fail: "2011-04-26 17:13 SeaMonkey -1   [0c9c4a20b02a]"
which may be because of http://hg.mozilla.org/comm-central/rev/69c0e7fa9ed8 (bug 636210) since test_clearHistory_shutdown.js is related to browserglue/suiteglue and sanitizing.

AFAICS, the only differences between FF's version of the file and ours (after bug 709829) are s/browserglue/suiteglue/, s/clearOnShutdown/item/ (both of which are needed and correct for us) and an additional pref being set ("privacy.sanitize.promptOnSanitize", false). So it is quite likely that the difference is in nsSuiteGlue.js. The only question is whether it is the code or the test that is wrong and needs to be adapted.

Comment 3

[Serge Gautherie (:sgautherie)]

(In reply to Jens Hatlak (:InvisibleSmiley) from comment #2)

To be explicit, that error is the 3rd/oldest one: currently not reached because of bug 709829 and current bug.

>   Last time it started to fail: "2011-04-26 17:13 SeaMonkey -1  
> [0c9c4a20b02a]"
> which may be because of http://hg.mozilla.org/comm-central/rev/69c0e7fa9ed8
> (bug 636210) since test_clearHistory_shutdown.js is related to
> browserglue/suiteglue and sanitizing.

Right, that changeset happened "just" before that first failure.

> AFAICS, the only differences between FF's version of the file and ours
> (after bug 709829) are s/browserglue/suiteglue/, s/clearOnShutdown/item/
> (both of which are needed and correct for us) and an additional pref being
> set ("privacy.sanitize.promptOnSanitize", false). So it is quite likely that

I confirm.

> the difference is in nsSuiteGlue.js. The only question is whether it is the
> code or the test that is wrong and needs to be adapted.

Agreed.

Comment 4

[Jens Hatlak (:InvisibleSmiley)]

FWIW, "places-expiration-finished" is only triggered by nsPlacesExpiration.handleCompletion(Ci.mozIStorageStatementCallback.REASON_FINISHED):

http://mxr.mozilla.org/comm-central/source/mozilla/toolkit/components/places/nsPlacesExpiration.js#731

So I guess Places expiration is not called at all anymore, or fails. Further investigation pending.

Comment 5

[Jens Hatlak (:InvisibleSmiley)]

... and AFAICT, handleCompletion is part of a callback object (type mozIStorageStatementCallback) which is passed into executeAsync in the form of "this" in _expireWithActionAndLimit. The latter is called several times within the file, from:
* observe (type nsIObserver)
* onClearHistory (type nsINavHistoryObserver)
* notify (type nsITimerCallback)

Maybe we're lucky and it's onClearHistory (which looks simple compared to the rest)... Anyway, enough investigation for today.

Comment 6

[Serge Gautherie (:sgautherie)]

(In reply to Serge Gautherie (:sgautherie) from comment #1)
> http://hg.mozilla.org/mozilla-central/rev/1ed8be9fed39

I filed bug 712533, fwiw.

Comment 7

[Legacy TBPL/Treeherder Robot]

vporof
https://tbpl.mozilla.org/php/getParsedLog.php?id=8120203&tree=Try
Rev3 WINNT 5.1 try opt test mochitests-3/5 on 2011-12-23 07:16:57

TEST-UNEXPECTED-FAIL | Shutdown | application timed out after 330 seconds with no output
PROCESS-CRASH | Shutdown | application crashed (minidump found)

Comment 8

[Serge Gautherie (:sgautherie)]

(In reply to TinderboxPushlog Robot from comment #7)
> vporof
> https://tbpl.mozilla.org/php/getParsedLog.php?id=8120203&tree=Try
> Rev3 WINNT 5.1 try opt test mochitests-3/5 on 2011-12-23 07:16:57

Completely unrelated to this bug.

Comment 9

[Legacy TBPL/Treeherder Robot]

vporof
https://tbpl.mozilla.org/php/getParsedLog.php?id=8140371&tree=Try
Rev3 WINNT 5.1 try opt test mochitests-3/5 on 2011-12-24 03:10:41

TEST-UNEXPECTED-FAIL | Shutdown | application timed out after 330 seconds with no output
PROCESS-CRASH | Shutdown | application crashed (minidump found)

Comment 10

[Serge Gautherie (:sgautherie)]

(In reply to TinderboxPushlog Robot from comment #9)
> vporof
> https://tbpl.mozilla.org/php/getParsedLog.php?id=8140371&tree=Try
> Rev3 WINNT 5.1 try opt test mochitests-3/5 on 2011-12-24 03:10:41

Again, completely unrelated to this bug.

Comment 11

[Jens Hatlak (:InvisibleSmiley)]

Here is a more detailed analysis. I hope it is correct; this is just from MXR investigation. I think the below is what *should* happen. Obviously something is broken in between since we would otherwise still receive the notification.

suite/common/places/tests/unit/test_clearHistory_shutdown.js
  line 143 (in function run_test) calls shutdownPlaces()
mozilla/toolkit/components/places/tests/head_common.js
  line 397 (in function shutdownPlaces) calls observes with argument "profile-change-teardown"
mozilla/toolkit/components/places/nsNavHistory.cpp
  line 3975 (in function nsNavHistory::Observe) forwards the call to the database handle
mozilla/toolkit/components/places/Database.cpp
  line 1664 (in function Database::Observe) notifies all observers of "places-shutdown"
suite/common/src/nsSuiteGlue.js
  line 177 (in function observes) calls this._onProfileShutdown() for "places-shutdown"
  line 355 (in function _onProfileShutdown) calls Sanitizer.doPendingSanitize()
suite/modules/Sanitizer.jsm
  line 104 (in function doPendingSanitize) calls item.clear() (where item is one of the objects in "items", one of which is "history")
  line 213 (in function items.history.clear) calls globalHistory.removeAllPages()
mozilla/toolkit/components/places/nsNavHistory.cpp
  line 3332 (in function nsNavHistory::RemoveAllPages) calls OnClearHistory()
mozilla/toolkit/components/places/nsPlacesExpiration.js
  line 628 (in function onClearHistory) calls this._expireWithActionAndLimit
  line 902 (in function _expireWithActionAndLimit) calls this._db.executeAsync, specifying "this" as callback
mozilla/storage/src/mozStorageAsyncStatementExecution.cpp
  line 181 (in function Run) calls HandleCompletion on the callback
mozilla/toolkit/components/places/nsPlacesExpiration.js
  line 731 (in function handleCompletion) notifies all observers of "places-expiration-finished"

Maybe you can understand now why I hate tests. Nothing is broken except for the test, and investigating what is wrong takes countless hours that could otherwise be used to fix things that are *actually* broken.

Anyway, I won't be able to look at this more closely for about a week. Feel free to continue the analysis while I'm away. The next step should be to find out where exactly it breaks.

Comment 12

[Jens Hatlak (:InvisibleSmiley)]

Attachment: patch

(In reply to Jens Hatlak (:InvisibleSmiley) from comment #11)
> Nothing is broken except for
> the test, and investigating what is wrong takes countless hours that could
> otherwise be used to fix things that are *actually* broken.

Bah, I have to take that back. In fact it's the other way around: The functionality is broken; the test needs no modifications.

What happens is that everything in my analysis from comment 11 occurs until doPendingSanitize() in Sanitizer.jsm. There, item.willClear is undefined for all items, so it stops there. This is because readSettings() is never called. It gets called from both sanitize() and checkSettings(). The latter is what gets called from other places in nsSuiteGlue.js and which checks the sanitizeOnShutdown pref which is set in the test.

It seems this was broken through the fix for bug 636210. Neil, this is your chance to recover. ;-)

Needless to say that the test passes for me with the attached patch. :-)

I'll request Aurora and Beta approval once I get r+, so you could just as well consider a+'ing right away.

Comment 13

[Jens Hatlak (:InvisibleSmiley)]

[It might be that sanitize on shutdown is currently broken and will be fixed through this; didn't check.]

Comment 14

[[e-mail]]

Comment on attachment 585457 [details] [diff] [review]
patch

We call checkSettings from the quit-application-granted notification, because we need to do it while we can still display the confirmation dialog. (Firefox removed the confirmation dialog, so they don't have that problem.) I don't know whether we can alter the test to send that notification.

Comment 15

[Jens Hatlak (:InvisibleSmiley)]

Attachment: alternate approach

(In reply to [e-mail] from comment #14)
> I don't know whether we can alter the test to send that notification.

Yes, we can! ;-)

[Please consider 2x a+ in case of r+ to speed things up.]

Comment 16

[[e-mail]]

Comment on attachment 585573 [details] [diff] [review]
alternate approach

(I don't see the point of fixing a test on branch, but someone else might.)

Comment 17

[Serge Gautherie (:sgautherie)]

Attachment: (Bv1sg1) Jens's patch with nits [Checkin: comments 19 and 29]

Improved documentation, and one less var.
For you to use...

Comment 18

[Serge Gautherie (:sgautherie)]

Ftr, I am not sure what happened during comment 0 2011-10-xx timeframe,
but this patch related to comment 2 2011-04-26 bug 636210 checkin (fully) fixes this test :-)

Comment 19

[Jens Hatlak (:InvisibleSmiley)]

Comment on attachment 585608 [details] [diff] [review]
(Bv1sg1) Jens's patch with nits [Checkin: comments 19 and 29]

http://hg.mozilla.org/comm-central/rev/fd9f0ac2bcaf

(In reply to Serge Gautherie (:sgautherie) from comment #17)
> Improved documentation, and one less var.
> For you to use...

Thanks, joined the getService line with the preceding one, otherwise fine. :-)

(In reply to [e-mail] from comment #16)
> (I don't see the point of fixing a test on branch, but someone else might.)

I thought our goal was to fix tests and go green on all tinderboxes. Maybe I was wrong? I'll let someone with more test experience decide.

Comment 20

[Serge Gautherie (:sgautherie)]

(In reply to Jens Hatlak (:InvisibleSmiley) from comment #11)
> Maybe you can understand now why I hate tests. Nothing is broken except for
> the test, and investigating what is wrong takes countless hours that could
> otherwise be used to fix things that are *actually* broken.

I sympathize: that's the price to pay to (prevent regressions and) catch some real issues at other times :-|
In this case (= currently), I would more likely blame the fact that so many test failures were accumulated: fixing test failures doesn't need so much investigations when they (can be) spotted right away :-<
Thanks very much for looking and fixing this one!


(In reply to Jens Hatlak (:InvisibleSmiley) from comment #19)

> Thanks, joined the getService line with the preceding one, otherwise fine.
> :-)

I concur: I noticed that nit just after attaching it to the bug ;->

> I thought our goal was to fix tests and go green on all tinderboxes. Maybe I
> was wrong? I'll let someone with more test experience decide.

Yes, that was definitely the (= my, at least) goal in the previous "long-term" release train.

But, recently (after not working on "Mozilla" for months), I took into account the "fast" release train and that we have so many (trunk) failures to fix and that tests are rarely run on branch tinderboxes (and ...), so I believe fixing (test-only failures on) trunk only should be (good) enough now.
Not perfect, but, as you reminded us, due to lack of (human) resources...

Comment 21

[Serge Gautherie (:sgautherie)]

Comment on attachment 585608 [details] [diff] [review]
(Bv1sg1) Jens's patch with nits [Checkin: comments 19 and 29]

Cancelling (test-only) approval requests per comment 20.
(That would have been welcome for an application code fix.)

Comment 22

[Jens Hatlak (:InvisibleSmiley)]

FTR: Bug 715554 just added the sending of a "quit-application" notification *after* shutdownPlaces() to the original test_clearHistory_shutdown.js. We might want to port that, too (if only for the sake of completeness), but it does *not* obsolete what was done here (I checked).

Comment 23

[Serge Gautherie (:sgautherie)]

Attachment: (Cv1) Send 'quit-application' too (Copied with bug 715554) [Checked in: Comment 27]

Jens, I assume you can review this...

Comment 24

[Serge Gautherie (:sgautherie)]

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1325733607.1325738615.25182.gz
WINNT 5.2 comm-central-trunk debug test xpcshell on 2012/01/04 19:20:07  

V.Fixed

Comment 25

[Jens Hatlak (:InvisibleSmiley)]

Comment on attachment 587203 [details] [diff] [review]
(Cv1) Send 'quit-application' too (Copied with bug 715554)
[Checked in: Comment 27]

> Jens, I assume you can review this...

Not really. r/f=me for the first change (hehe), but the second one is really better off with Neil since I don't know whether it would have any bad side-effects. All I can say is that the test still succeeds with it.

Comment 26

[[e-mail]]

Comment on attachment 587203 [details] [diff] [review]
(Cv1) Send 'quit-application' too (Copied with bug 715554)
[Checked in: Comment 27]

Well, it's only a unit test, so it shouldn't be a problem.

Good catch on the use of Services.obs though, thanks!

Comment 27

[Serge Gautherie (:sgautherie)]

Comment on attachment 587203 [details] [diff] [review]
(Cv1) Send 'quit-application' too (Copied with bug 715554)
[Checked in: Comment 27]

http://hg.mozilla.org/comm-central/rev/71326b6d8531

Comment 28

[Serge Gautherie (:sgautherie)]

Comment on attachment 585608 [details] [diff] [review]
(Bv1sg1) Jens's patch with nits [Checkin: comments 19 and 29]

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey-Beta/1329961361.1329964007.21039.gz
OS X 10.6 comm-beta debug test xpcshell on 2012/02/22 17:42:41

This is now the last failure :-)
No risk, test only.

Comment 29

[Jens Hatlak (:InvisibleSmiley)]

Comment on attachment 585608 [details] [diff] [review]
(Bv1sg1) Jens's patch with nits [Checkin: comments 19 and 29]

http://hg.mozilla.org/releases/comm-beta/rev/fe9451243610

Comment 30

[Serge Gautherie (:sgautherie)]

(In reply to Jens Hatlak (:InvisibleSmiley) from comment #29)
> http://hg.mozilla.org/releases/comm-beta/rev/fe9451243610

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey-Beta/1330485735.1330488470.3135.gz&fulltext=1
OS X 10.6 comm-beta debug test xpcshell on 2012/02/28 19:22:15
{
TEST-PASS | /builds/slave/test/build/xpcshell/tests/suite/common/places/tests/unit/test_clearHistory_shutdown.js | test passed (time: 2329.326ms)
}

seamonkey2.8: verified.