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

Status: RESOLVED FIXED

(Toolkit :: Form Manager, defect)

Description

[Serge Gautherie (:sgautherie)]

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 ??

Comment 1

[Justin Wood (:Callek)]

Fails on all platforms, on Debug, 100% of the time. Will look into it.

Comment 2

[Serge Gautherie (:sgautherie)]

(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

Comment 3

[Rob Arnold [:robarnold]]

I don't think bug 554982 can be related to a test failure that happens on OS X and Linux or the forms manager.

Comment 4

[Justin Wood (:Callek)]

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.

Comment 5

[Robert Kaiser]

So, satchel somehow doesn't fire an observer, does it actually add/modify an entry?

Comment 6

[Robert Kaiser]

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?

Comment 7

[Justin Wood (:Callek)]

(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.

Comment 8

[Legacy TBPL/Treeherder Robot]

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

s: win32-slave19
6334 ERROR TEST-UNEXPECTED-FAIL | /tests/toolkit/components/satchel/test/test_form_submission.html | Test timed out.

Comment 9

[Justin Wood (:Callek)]

(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.

Comment 10

[Serge Gautherie (:sgautherie)]

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.

Comment 11

[Serge Gautherie (:sgautherie)]

(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...)

Comment 12

[Serge Gautherie (:sgautherie)]

(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...

Comment 13

[Serge Gautherie (:sgautherie)]

(In reply to comment #12)
> > *alerts + microformats + satchel__this_test.
> 
> I'll attach a patch later today...

I eventually filed bug 609772 :-/

Comment 14

[Serge Gautherie (:sgautherie)]

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?

Comment 15

[Justin Wood (:Callek)]

(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.

Comment 16

[Robert Kaiser]

I just fear that without knowing the actual cause, this will pop up again in a less reproducible way :(

Comment 17

[Serge Gautherie (:sgautherie)]

Attachment: (Av1) Disable timing out part of the test on SeaMonkey [Checked in: Comment 25]

Comment 18

[Serge Gautherie (:sgautherie)]

(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)...

Comment 19

[Brian Crowder]

In the history of this bug, I don't see myself being cc:d, and yet...  there I am!

Comment 20

[Serge Gautherie (:sgautherie)]

(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.

Comment 21

[Serge Gautherie (:sgautherie)]

(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?

Comment 22

[Serge Gautherie (:sgautherie)]

(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 23

[Serge Gautherie (:sgautherie)]

Comment on attachment 488519 [details] [diff] [review]
(Av1) Disable timing out part of the test on SeaMonkey
[Checked in: Comment 25]

Ping for review.

Comment 24

[Serge Gautherie (:sgautherie)]

Comment on attachment 488519 [details] [diff] [review]
(Av1) Disable timing out part of the test on SeaMonkey
[Checked in: Comment 25]

Ping for review.

Comment 25

[Serge Gautherie (:sgautherie)]

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

Comment 26

[Serge Gautherie (:sgautherie)]

(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

Comment 27

[Ryan VanderMeulen [:RyanVM]]

Serge, is this still happening?

Comment 28

[Serge Gautherie (:sgautherie)]

(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)...

Comment 29

[Legacy TBPL/Treeherder Robot]

m_kato%ga2.so-net.ne.jp
https://tbpl.mozilla.org/php/getParsedLog.php?id=18808797&tree=Mozilla-Inbound
Rev4 MacOSX Snow Leopard 10.6 mozilla-inbound debug test mochitest-5 on 2013-01-14 23:36:28
slave: talos-r4-snow-077

Assertion failure: IsValidNetAddr(addr) == PR_TRUE, at ../../../../../nsprpub/pr/src/pthreads/ptio.c:1711
167045 ERROR TEST-UNEXPECTED-FAIL | /tests/toolkit/components/satchel/test/test_form_submission.html | uncaught exception - TypeError: document.getElementById(...).contentWindow.clickButton is not a function at http://mochi.test:8888/tests/toolkit/components/satchel/test/test_form_submission.html:505

Comment 30

[BugBot [:suhaib / :marco/ :calixte]]

The bug assignee didn't login in Bugzilla in the last 7 months.
:tgiles, could you have a look please?
For more information, please visit auto_nag documentation.

Comment 31

[Sergey Galich [:serg]]

This test has been rewritten as part of Bug 1642570 and should not timeout anymore.