Closed Bug 711937 Opened 8 years ago Closed 8 years ago

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

Categories

(SeaMonkey :: Bookmarks & History, defect, major)

defect
Not set
major

Tracking

(seamonkey2.7 wontfix, seamonkey2.8 verified)

VERIFIED FIXED
seamonkey2.9
Tracking Status
seamonkey2.7 --- wontfix
seamonkey2.8 --- verified

People

(Reporter: sgautherie, Assigned: InvisibleSmiley)

References

(Blocks 1 open bug, )

Details

(Keywords: regression, Whiteboard: [perma-orange])

Attachments

(3 files, 1 obsolete file)

(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.
(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
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.
(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.
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.
... 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.
Depends on: 712533
(In reply to Serge Gautherie (:sgautherie) from comment #1)
> http://hg.mozilla.org/mozilla-central/rev/1ed8be9fed39

I filed bug 712533, fwiw.
(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.
(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.
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.
Target Milestone: --- → seamonkey2.8
Attached patch patch (obsolete) — Splinter Review
(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.
Assignee: nobody → jh
Status: NEW → ASSIGNED
Attachment #585457 - Flags: review?(neil)
[It might be that sanitize on shutdown is currently broken and will be fixed through this; didn't check.]
Blocks: 636210
No longer depends on: 712533
Keywords: qawanted
OS: Windows 2000 → All
Hardware: x86 → All
Target Milestone: seamonkey2.8 → seamonkey2.9
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.
Attachment #585457 - Flags: review?(neil) → review-
(In reply to neil@parkwaycc.co.uk 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.]
Attachment #585457 - Attachment is obsolete: true
Attachment #585573 - Flags: review?(neil)
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.)
Attachment #585573 - Flags: review?(neil) → review+
Improved documentation, and one less var.
For you to use...
Attachment #585608 - Flags: feedback?(jh)
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 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 neil@parkwaycc.co.uk 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.
Attachment #585608 - Attachment description: (Bv1sg1) Jens's patch with nits → (Bv1sg1) Jens's patch with nits [Checkin: comment 19]
Attachment #585608 - Flags: review+
Attachment #585608 - Flags: feedback?(jh)
Attachment #585608 - Flags: feedback+
Attachment #585608 - Flags: approval-comm-beta?
Attachment #585608 - Flags: approval-comm-aurora?
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
Resolution: --- → FIXED
(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...
Flags: in-testsuite+
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.)
Attachment #585608 - Flags: approval-comm-beta?
Attachment #585608 - Flags: approval-comm-aurora?
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).
Depends on: 715554
Jens, I assume you can review this...
Attachment #587203 - Flags: review?(jh)
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
Status: RESOLVED → VERIFIED
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.
Attachment #587203 - Flags: review?(jh) → review?(neil)
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!
Attachment #587203 - Flags: review?(neil) → review+
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
Attachment #587203 - Attachment description: (Cv1) Send 'quit-application' too (Copied with bug 715554) → (Cv1) Send 'quit-application' too (Copied with bug 715554) [Checked in: Comment 27]
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.
Attachment #585608 - Flags: approval-comm-beta?
No longer depends on: OrangeFactorCommApps
Attachment #585608 - Flags: approval-comm-beta? → approval-comm-beta+
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
Attachment #585608 - Attachment description: (Bv1sg1) Jens's patch with nits [Checkin: comment 19] → (Bv1sg1) Jens's patch with nits [Checkin: comments 19 and 29]
(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.
You need to log in before you can comment on or make changes to this bug.