Open Bug 589471 Opened 9 years ago Updated 7 years ago

[SeaMonkey 2.1, mochitest-plain-5] permanent "toolkit/components/satchel/test/test_form_submission.html | Test timed out."

Categories

(Toolkit :: Form Manager, defect, major)

defect
Not set
major

Tracking

()

ASSIGNED

People

(Reporter: sgautherie, Assigned: sgautherie)

References

(Depends on 1 open bug, Blocks 1 open bug, )

Details

(Keywords: helpwanted, intermittent-failure, Whiteboard: [ToDo: comment 21] [worked around ftb] [sm-perma])

Attachments

(1 file)

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1282403130.1282404220.20595.gz
Linux comm-central-trunk debug test mochitests-5/5 on 2010/08/21 08:05:30
(same on MacOSX and Windows)
{
...
7075 INFO TEST-PASS | /tests/toolkit/components/satchel/test/test_form_submission.html | checking for empty storage
7076 INFO TEST-PASS | /tests/toolkit/components/satchel/test/test_form_submission.html | submitting iframe test 100
7077 INFO TEST-PASS | /tests/toolkit/components/satchel/test/test_form_submission.html | form 100 submitted
--DOMWINDOW == 81 (0xcdba2f0) [serial = 904] [outer = 0xba9dbe0] [url = about:blank]
--DOMWINDOW == 80 (0xba9dc18) [serial = 903] [outer = (nil)] [url = chrome://global/content/commonDialog.xul]
...
--DOMWINDOW == 21 (0xe00f100) [serial = 964] [outer = 0xc28baa0] [url = about:blank]
--DOMWINDOW == 20 (0xc28bad8) [serial = 963] [outer = (nil)] [url = chrome://global/content/commonDialog.xul]
...
7078 ERROR TEST-UNEXPECTED-FAIL | /tests/toolkit/components/satchel/test/test_form_submission.html | Test timed out.
7079 INFO SimpleTest finished /tests/toolkit/components/satchel/test/test_form_submission.html in 316524ms
}

Regression timeframe:
http://tinderbox.mozilla.org/showbuilds.cgi?tree=SeaMonkey&maxdate=1282119835&hours=24&legend=0&norules=1
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=55953a91b4d6&tochange=3d4ba021c4dd
--> One of bug 550936, bug 554982 or bug 562444.

NB: Might be somehow related to bug 586524 ??
Fails on all platforms, on Debug, 100% of the time. Will look into it.
Assignee: nobody → bugspam.Callek
(Ftr)

Last success:
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1282099374.1282100395.30268.gz
Linux comm-central-trunk debug test mochitests-5/5 on 2010/08/17 19:42:54
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1282107950.1282109065.4931.gz
OS X 10.5 comm-central-trunk debug test mochitests-5/5 on 2010/08/17 22:05:50

First failure:
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1282110560.1282111865.17304.gz
Linux comm-central-trunk debug test mochitests-5/5 on 2010/08/17 22:49:20  
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1282112276.1282113329.22597.gz
OS X 10.5 comm-central-trunk debug test mochitests-5/5 on 2010/08/17 23:17:56
Summary: [(Debug ?) SeaMonkey 2.1] permanent "toolkit/components/satchel/test/test_form_submission.html | Test timed out." → [SeaMonkey 2.1, mochitest-plain-5] permanent "toolkit/components/satchel/test/test_form_submission.html | Test timed out."
Whiteboard: [sm-perma][orange]
I don't think bug 554982 can be related to a test failure that happens on OS X and Linux or the forms manager.
No longer blocks: 554982
Ok, here is what seems to be happening...

We get to submitting the iframe (test form100)

Then we get to: |checkForSave("subtest2", "subtestValue", "checking saved subtest value");|

Which just adds the "we should save x" stuff to the verifyStack (an array of objects).

Then we get to |checkObserver.waitForChecks(...)| from a setTimeout... which brings us to:

|waitForChecks: function(callback) {..|

Which in the case where verifyStack is empty, just calls  the callback (which is the main "run next part of test" code). BUT in the case where verifyStack is not empty, it simply sets |this.callback| and waits for satchel to send out the observe from the observer....

|http://mxr.mozilla.org/mozilla-central/source/toolkit/components/satchel/test/satchel_common.js#133|

Early in that observer we have a forced return if the topic is not one we expect, however venkman is not even telling me that we reach this observer at all... which in turn causes the test to timeout, since we never continue on. (Though we do reach it at the START of the test, for the remove observer fires, which prepapres us for this test, we properly return early in that case).

I'm not yet sure why we are not reaching the observer in the later portion.
So, satchel somehow doesn't fire an observer, does it actually add/modify an entry?
Hmm, I just caught this with the dependency on bug 586524 - is there any relation between this happening for us and for JaegerMonkey, and between their investigation and ours?
(In reply to comment #6)
> Hmm, I just caught this with the dependency on bug 586524 - is there any
> relation between this happening for us and for JaegerMonkey, and between their
> investigation and ours?

With that tinderbox log and our log it is different. That bug passes debug intermittent in opt, my local test was debug. and fails local. And that bug gets past form 100.
(In reply to comment #8)
> dmandelin%mozilla.com
> http://tinderbox.mozilla.org/showlog.cgi?log=Jaegermonkey/1284061075.1284063921.15798.gz
> WINNT 5.2 jaegermonkey debug test mochitests-5/5 on 2010/09/09 12:37:55

Interesting, that *is*  this bug and not a fluke. up until now I thought it was just a SeaMonkey issue.
Opt t-b on my local Windows 2000:
*running alone: "Passed: 175" :-)
*running all mochi-5: stalls (with no hints) :-(

Let me see whether I can narrow down what (other test) triggers this.
Depends on: 565307
(In reply to comment #10)
> Let me see whether I can narrow down what (other test) triggers this.

Mixed results:

I reduced this bug to (at least) two sets of 'toolkit/components' tests needed to reproduce:
*passwordmgr + satchel__this_test. (It may even become intermittent.)
*alerts + microformats + satchel__this_test.

At this point I have no clue: it just looks like some timing/gc/whatever randomness.

Maybe someone who can run a Debug build could get some additional hints?
(Callek? See comment 5 question...)
Severity: normal → major
(In reply to comment #4)
> however venkman is not even telling me that we reach this observer at all...

I added some dump()s, etc, and confirm this:
instead of the expected |observe()| (when run alone),
|checkObserver.waitForChecks(...)| is called again :-/


(In reply to comment #11)
> *alerts + microformats + satchel__this_test.
> 
> At this point I have no clue: it just looks like some timing/gc/whatever
> randomness.

I eventually(!) found a clue for this case:
test_alerts_noobserve.html finishes (even) before its notification has shown (maybe because we're IPC now!?).
I have no idea why test_form_submission.html is affected by that (= by that time, the notification was displayed and dismissed), but it is.

I'll attach a patch later today...
Assignee: bugspam.Callek → sgautherie.bz
Blocks: 516124
Status: NEW → ASSIGNED
No longer blocks: 516124
(In reply to comment #12)
> > *alerts + microformats + satchel__this_test.
> 
> I'll attach a patch later today...

I eventually filed bug 609772 :-/
Depends on: 609772
From my recent experiments, it seems that:
1) there is "nothing" wrong with test_form_submission.html itself.
2) the cause of the failure may be "multiple".

Then, (and especially) as this is the last perma-orange mochi-5, I suggest to disable this (whole) test on SeaMonkey until it can pass when run in the test suite.
(Callek,) KaiRo, would you accept that?
(In reply to comment #14)
> (Callek,) KaiRo, would you accept that?

Given that this is a m-c test, and we have not figured it out yet, I have no strong objections to disabling it; we have ignored it so far anyway.
I just fear that without knowing the actual cause, this will pop up again in a less reproducible way :(
(In reply to comment #16)
> I just fear that without knowing the actual cause, this will pop up again in a
> less reproducible way :(

It might in the future, but up to now perma-orange is preventing us from easily noticing random-oranges (for example)...
In the history of this bug, I don't see myself being cc:d, and yet...  there I am!
(In reply to comment #19)
> In the history of this bug, I don't see myself being cc:d, and yet...  there I
> am!

Because I cc'ed you when I filed the bug, as you were the assignee of bug 562444.
(In reply to comment #0)
> Regression timeframe:
> http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=55953a91b4d6&tochange=3d4ba021c4dd
> --> One of bug 550936, bug 554982 or bug 562444.

Callek (or someone else), as I can't build, could you locally back out these 2-3 changesets ... in hope to confirm / narrow down the timeframe?
Keywords: helpwanted
Whiteboard: [sm-perma][orange] → [ToDo: comment 21] [sm-perma][orange]
(In reply to comment #20)
> Because I cc'ed you when I filed the bug, as you were the assignee of bug
> 562444.

And the person who pushed the 3 changesets in the timeframe.
Comment on attachment 488519 [details] [diff] [review]
(Av1) Disable timing out part of the test on SeaMonkey
[Checked in: Comment 25]

Ping for review.
Attachment #488519 - Flags: review?(gavin.sharp)
Comment on attachment 488519 [details] [diff] [review]
(Av1) Disable timing out part of the test on SeaMonkey
[Checked in: Comment 25]

Ping for review.
Attachment #488519 - Flags: review?(paul)
Attachment #488519 - Flags: review?(paul)
Attachment #488519 - Flags: review?(gavin.sharp)
Attachment #488519 - Flags: review?(dolske)
Attachment #488519 - Flags: review+
Comment on attachment 488519 [details] [diff] [review]
(Av1) Disable timing out part of the test on SeaMonkey
[Checked in: Comment 25]

http://hg.mozilla.org/mozilla-central/rev/4c8ae858b8e1
Attachment #488519 - Attachment description: (Av1) Disable timing out part of the test on SeaMonkey → (Av1) Disable timing out part of the test on SeaMonkey [Checked in: Comment 25]
Whiteboard: [ToDo: comment 21] [sm-perma][orange] → [ToDo: comment 21] [worked around ftb] [sm-perma][orange]
(In reply to comment #25)
> http://hg.mozilla.org/mozilla-central/rev/4c8ae858b8e1

V.Fixed (ftb), per
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1291469919.1291470682.26241.gz
OS X 10.6 comm-central-trunk debug test mochitests-5/5 on 2010/12/04 05:38:39
Serge, is this still happening?
(In reply to Ryan VanderMeulen from comment #27)
> Serge, is this still happening?

I don't know: someone would have to revert the workaround then try to run the test (suite)...
Whiteboard: [ToDo: comment 21] [worked around ftb] [sm-perma][orange] → [ToDo: comment 21] [worked around ftb] [sm-perma]
You need to log in before you can comment on or make changes to this bug.