728790 - [SeaMonkey] "TEST-UNEXPECTED-FAIL | /tests/toolkit/components/passwordmgr/test/test_prompt_async.html | Registered 3 open dialogs - got 2, expected 3", due to broken test_bug_627616.html

Status: VERIFIED FIXED

(Toolkit :: Password Manager, defect, P2)

Description

[Serge Gautherie (:sgautherie)]

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1329533166.1329534407.21457.gz
Linux comm-central-trunk debug test mochitests-5/5 on 2012/02/17 18:46:06
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1329538409.1329539435.31011.gz
OS X 10.6 comm-central-trunk debug test mochitests-5/5 on 2012/02/17 20:13:29
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1329704834.1329706848.16269.gz&fulltext=1
WINNT 5.2 comm-central-trunk debug test mochitests-5/5 on 2012/02/19 18:27:14
{
7722 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_prompt_async.html | doCheck testNum 1

7723 ERROR TEST-UNEXPECTED-FAIL | /tests/toolkit/components/passwordmgr/test/test_prompt_async.html | Registered 3 open dialogs - got 2, expected 3

7724 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_prompt_async.html | WWW Authorization OK, frame1 - "PASS" should equal "PASS"
}

***

Last success:
http://tinderbox.mozilla.org/showbuilds.cgi?tree=SeaMonkey&maxdate=1329415749&hours=24&legend=0&norules=1
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1329408380.1329409140.21606.gz
Linux comm-central-trunk debug test mochitests-5/5 on 2012/02/16 08:06:20
rev:a853f4017192 ("revision: 81e0d1fa9127"!)
moz:a853f4017192

First failure:
http://tinderbox.mozilla.org/showbuilds.cgi?tree=SeaMonkey&maxdate=1329502149&hours=24&legend=0&norules=1
http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1329440776.1329441748.30165.gz
OS X 10.6 comm-central-trunk debug test mochitests-5/5 on 2012/02/16 17:06:16
rev:6989376471f7 ("revision: 81e0d1fa9127"!)
moz:6989376471f7

Regression timeframe:

http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=a853f4017192&tochange=6989376471f7
Large merges to m-c.!.

Comment 1

[Serge Gautherie (:sgautherie)]

Jens, could you try and check what may be failing in this test?

Comment 2

[Jens Hatlak (:InvisibleSmiley)]

(In reply to Serge Gautherie (:sgautherie) from comment #1)
> Jens, could you try and check what may be failing in this test?

This test alone succeeds for me on Windows and Linux (80 Passed, 0 Failed, 0 Todo).

If it really still happens during automatic test runs, maybe there's an issue in connection with tests that run before this one.

Comment 3

[Jens Hatlak (:InvisibleSmiley)]

Confirmed with mochitest-5 run. Running "make mochitest-plain-rerun-failures" after that shows no errors (just like with the single test run).

The above also applies to test_xhr:

INFO | runtests.py | Running tests: end.
mochitest-5 failed:
7709 ERROR TEST-UNEXPECTED-FAIL | /tests/toolkit/components/passwordmgr/test/test_prompt_async.html | Registered 3 open dialogs - got 2, expected 3
7785 ERROR TEST-UNEXPECTED-FAIL | /tests/toolkit/components/passwordmgr/test/test_xhr.html | an unexpected uncaught JS exception reported through window.onerror - attempt to run compile-and-go script on a cleared scope at http://mochi.test:8888/tests/toolkit/components/passwordmgr/test/prompt_common.js:34
To rerun your failures please run 'make mochitest-plain-rerun-failures'
make: *** [mochitest-5] Error 1

I presume the tests do not fail for FF?

Comment 4

[Serge Gautherie (:sgautherie)]

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

> This test alone succeeds for me on Windows and Linux (80 Passed, 0 Failed, 0
> Todo).

Thanks. Did you test Opt or Debug?

> If it really still happens during automatic test runs, maybe there's an
> issue in connection with tests that run before this one.

Could be: would need to identify which one...


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

> The above also applies to test_xhr:

Right, all SM tinderboxes log that too:
{
7778 INFO TEST-END | /tests/toolkit/components/passwordmgr/test/test_prompt_async.html | finished in 179389ms

7779 INFO TEST-START | /tests/toolkit/components/passwordmgr/test/test_xhr.html
JavaScript error: http://mochi.test:8888/tests/toolkit/components/passwordmgr/test/prompt_common.js, line 34: attempt to run compile-and-go script on a cleared scope
7780 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_xhr.html | Access Ci
}

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1329379920.1329381436.17687.gz&fulltext=1
OS X 10.6 comm-central-trunk debug test mochitests-5/5 on 2012/02/16 00:12:00
didn't report/log either error.

The test_xhr.html JS error is obviously a fallout of the test_prompt_async.html failure.

> I presume the tests do not fail for FF?

FF tree is green.

Comment 5

[Serge Gautherie (:sgautherie)]

(In reply to Serge Gautherie (:sgautherie) from comment #4)
> > If it really still happens during automatic test runs, maybe there's an
> > issue in connection with tests that run before this one.
> 
> Could be: would need to identify which one...

Today, I had noticed the 2 changesets for bug 627616, but I had only a very quick glance at them.
Now that I check the test logs, it's obvious there is something wrong with that test:
I filed bug 731442.

Hopefully, this is somehow the cause of this bug.

Comment 6

[Serge Gautherie (:sgautherie)]

(In reply to Serge Gautherie (:sgautherie) from comment #5)

> (In reply to Serge Gautherie (:sgautherie) from comment #4)
> > > If it really still happens during automatic test runs, maybe there's an
> > > issue in connection with tests that run before this one.
> > 
> > Could be: would need to identify which one...

Could you try and narrow down which previous test is triggering this failure?
(Check test_bug_627616.html, though that should not be the one.)

> I filed bug 731442.
> 
> Hopefully, this is somehow the cause of this bug.

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1331101599.1331102316.22962.gz&fulltext=1
Linux comm-central-trunk debug test mochitests-5/5 on 2012/03/06 22:26:39

It didn't help :-/

Comment 7

[Serge Gautherie (:sgautherie)]

(In reply to Serge Gautherie (:sgautherie) from comment #0)
> Regression timeframe:
> 
> http://hg.mozilla.org/mozilla-central/
> pushloghtml?fromchange=a853f4017192&tochange=6989376471f7
> Large merges to m-c.!.

The 3 changesets in
http://hg.mozilla.org/mozilla-central/rev/6989376471f7
are obviously unrelated.

Then it's something in the 66 changesets of
http://hg.mozilla.org/mozilla-central/rev/31fa580e684c

First, let's check changes in toolkit/components/passwordmgr/test/:
*Bug 627616
 *added test_bug_627616.html,
 *modified authenticate.sjs,
  (Ftr, it did in Toolkit and Firefox. SeaMonkey doesn't have this file.)
 *touched prompt_common.js.

Jens, could you try and revert these locally?

Comment 8

[[e-mail]]

I see a fail when using --test-path=toolkit/components/passwordmgr but not when running test_prompt_async.html in its own window.

Comment 9

[[e-mail]]

test_bug627616 seems to cause this one to fail; if I delete all the test_b* files then the test run passes, but if I put this one back it fails again.

Comment 10

[[e-mail]]

test_AnonymousNoAuth: fine
test_AnonymousCredentials: fails when run on its own
test_NonAnonymousCredentials: results in 9(!) failures in test_prompt_async, also browser failed to shut down after test. Might have been a spurious result?
test_NonAnonymousCredentials + test_AnonymousCredentials: results in 1 failure in test_prompt_async, as observed on tbpl.

Comment 11

[[e-mail]]

test_NonAnonymousCredentials fails to cancel its timer before starting the test_AnonymousCredentials test, however this does not seem to affect the tests.

If you run test_AnonymousCredentials manually once and accept the prompt, you can then run the test suite without test_AnonymousCredentials failing, but test_prompt_async.html still fails.

This means that test_NonAnonymousCredentials is leaving an authenticated session open which a) test_AnonymousCredentials is relying on to pass and b) causes test_prompt_async.html to fail.

Comment 12

[[e-mail]]

... and in fact test_prompt_async.html, unlike test_bug627616, does remember to clear its authenticated sessions when it finishes.

Comment 13

[[e-mail]]

So, there are at least three approaches:
1. Clear authenticated sessions in cleanup(); testAnonymousCredentials passes because the authentication is cached. Timer is still left-over.
2. Clear authenticated sessions in runNextText(); testAnonymousCredentials passes via the left-over timer from testNonAnonymousCredentials.
3. As above but specifically expect two, one and zero dialogs respectively.

Comment 14

[[e-mail]]

Attachment: Approach 1

Comment 15

[[e-mail]]

Attachment: Approach 2

Comment 16

[[e-mail]]

Attachment: Approach 3 [Checked in: Comments 28 and 34]

Comment 17

[Serge Gautherie (:sgautherie)]

Comment on attachment 604451 [details] [diff] [review]
Approach 3
[Checked in: Comments 28 and 34]

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

Obviously, I prefer approach 3 :-)
Here is a tweak proposal to separate individual tests even further.

::: toolkit/components/passwordmgr/test/test_bug_627616.html
@@ +30,5 @@
>  
>          login2 = Cc["@mozilla.org/login-manager/loginInfo;1"].createInstance(Ci.nsILoginInfo);
>          login2.init("http://mochi.test:8888", null, "mochirealm", "user1name", "user1pass", "", "");
>          pwmgr.addLogin(login2);
> +        startCallbackTimer();

Remove this.

@@ +36,5 @@
>      function cleanup() {
>          var pwmgr = Cc["@mozilla.org/login-manager;1"].getService(Ci.nsILoginManager);
>          pwmgr.removeLogin(login);        
>          pwmgr.removeLogin(login2);
> +        timer.cancel();

Remove this.
NB: No other (PM) test uses this, as well avoid adding it to this one.

@@ +86,2 @@
>        if (pendingTests.length > 0) {
> +        gExpectedDialogs = pendingTests.shift();

Add:
if (gExpectedDialogs > 0)
  startCallbackTimer();

@@ +103,5 @@
>      {
>          var dialog = doc.getElementById("commonDialog");
>          dialog.acceptDialog();
> +        gExpectedDialogs--;
> +        startCallbackTimer();

Do instead:
if (--gExpectedDialogs > 0)
  startCallbackTimer();

Comment 18

[Justin Dolske [:Dolske]]

I don't have a particular preference here, 1 and 3 both seem reasonable. rs=me on either. (Neil asked on IRC)

Comment 19

[[e-mail]]

(In reply to Serge Gautherie from comment #17)
> if (gExpectedDialogs > 0)
>   startCallbackTimer();
I suppose that this would assume that the test would just time out if there was an unexpected dialog...

Comment 20

[Serge Gautherie (:sgautherie)]

(In reply to [e-mail] from comment #19)
> I suppose that this would assume that the test would just time out if there
> was an unexpected dialog...

Yeah, just let it time out (and get a screenshot from the harness) ;->

Comment 21

[Serge Gautherie (:sgautherie)]

(In reply to Justin Dolske [:Dolske] from comment #18)
> I don't have a particular preference here, 1 and 3 both seem reasonable.
> rs=me on either. (Neil asked on IRC)

Neil, are you waiting for an additional explicit r+ from Honza?

Comment 22

[Honza Bambas (:mayhemer)]

Comment on attachment 604451 [details] [diff] [review]
Approach 3
[Checked in: Comments 28 and 34]

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

I agree with most of sgautherie's comments.

Just: what's gonna happen when no expected dialog appears and the test finishes (i.e. doesn't timeout and kill the whole run)?  Aren't we in the same situation then (callback leftover)?  Shouldn't we rather do timer.cancel() in cleanup() anyway?  I don't see how this (IMO broken) loop stops when no dialog pops up, regardless what test is ran.

Leaving r? until answered.

::: toolkit/components/passwordmgr/test/test_bug_627616.html
@@ +94,5 @@
>      }
>  
> +    var pendingTests = [2, testNonAnonymousCredentials,
> +                        1, testAnonymousCredentials,
> +                        0, testAnonymousNoAuth];

Please make this as:
[
 {expectedDialogs: 2, func: testNon...},
 {...
]

Comment 23

[Serge Gautherie (:sgautherie)]

Note that the primary goal of this bug is to make this test behave correctly when there is no regression.
Supporting the latter could/should be moved to a follow-up, as that probably affects other tests which rely on startCallbackTimer(), etc.


(In reply to Serge Gautherie (:sgautherie) from comment #20)
> (In reply to [e-mail] from comment #19)
> > I suppose that this would assume that the test would just time out if there
> > was an unexpected dialog...
> 
> Yeah, just let it time out (and get a screenshot from the harness) ;->

Actually, I don't know whether the test itself would "hang" or just ignore the extra dialog, though I assume the former.
That should be testable by lowering the expected dialog number locally...

Note that this test has no built-in support for detecting/handling extra dialog(s).

http://mxr.mozilla.org/mozilla-central/source/toolkit/components/passwordmgr/test/test_bug_627616.html?force=1


(In reply to Honza Bambas (:mayhemer) from comment #22)

> Just: what's gonna happen when no expected dialog appears and the test
> finishes (i.e. doesn't timeout and kill the whole run)?  Aren't we in the

That should be testable by increasing the expected dialog number locally...

> same situation then (callback leftover)?  Shouldn't we rather do

"is(gExpectedDialogs, 0 ..." will fail so it won't remain unnoticed (anymore).

> timer.cancel() in cleanup() anyway?  I don't see how this (IMO broken) loop

Agreed, then add after that is():
// Give up on missing dialogs.
if (gExpectedDialogs > 0)
  timer.cancel();

> stops when no dialog pops up, regardless what test is ran.

I fully agree startCallbackTimer() starts an "endless" polling loop.
The other tests seem not to care :-|

http://mxr.mozilla.org/mozilla-central/source/toolkit/components/passwordmgr/test/prompt_common.js

Comment 24

[[e-mail]]

(In reply to Honza Bambas from comment #22)
> Just: what's gonna happen when no expected dialog appears and the test
> finishes (i.e. doesn't timeout and kill the whole run)?  Aren't we in the
> same situation then (callback leftover)?  Shouldn't we rather do
> timer.cancel() in cleanup() anyway?  I don't see how this (IMO broken) loop
> stops when no dialog pops up, regardless what test is ran.
That's exactly why I wrote the patch the way I did in the first place - I separated the callback timer whose job it is to count and dismiss any dialogs as an when they appear from the actual test which just needs to concern itself with the expected XHR result and number of dialogs, rather than messing around trying to turn the callback timer on and off at opportune moments.

Comment 25

[Honza Bambas (:mayhemer)]

Comment on attachment 604451 [details] [diff] [review]
Approach 3
[Checked in: Comments 28 and 34]

Thanks for comments.

(In reply to Serge Gautherie (:sgautherie) from comment #23)
> > timer.cancel() in cleanup() anyway?  I don't see how this (IMO broken) loop
> 
> Agreed, then add after that is():
> // Give up on missing dialogs.
> if (gExpectedDialogs > 0)
>   timer.cancel();
> 

Neil, can you please incorporate this to the patch too?


I think we all agree the wait-for-dialog infrastructure is not perfect, but mostly works.  So any updates should be in followups.

Let's get this fix in, with the two nits incorporated.

Comment 26

[Serge Gautherie (:sgautherie)]

Comment on attachment 604451 [details] [diff] [review]
Approach 3
[Checked in: Comments 28 and 34]

(In reply to [e-mail] from comment #24)
> That's exactly why I wrote the patch the way I did in the first place - I
> separated the callback timer whose job it is to count and dismiss any
> dialogs as an when they appear from the actual test which just needs to
> concern itself with the expected XHR result and number of dialogs, rather
> than messing around trying to turn the callback timer on and off at
> opportune moments.

Agreed (as I better understand this test now than I did when you attached your patches).

Your way: pro = more resilient (and faster), con = don't automatically know at all what the extra dialogs are.
My way: pro = should hopefully get a screenshot of the n+1 dialog (fwiw), con = rely on the harness timeout.
Note that the test itself doesn't check what the expected dialogs are exactly.

Wrt this bug, I still prefer my way.

Yet, if you want to push it your way, I would suggest the following nits:

>         pwmgr.addLogin(login2);
>+        startCallbackTimer();

Add a blank line and a reminder comment about <what you just wrote>.

>     }
>     function cleanup() {
>         var pwmgr = Cc["@mozilla.org/login-manager;1"].getService(Ci.nsILoginManager);
>         pwmgr.removeLogin(login);        
>         pwmgr.removeLogin(login2);
>+        timer.cancel();

Do it first and add a blank line.

Comment 27

[Alex Keybl [:akeybl]]

No need to track for FF13, as this appears to be SM specific. That being said, we would take a fix in support of SM if necessary.

Comment 28

[[e-mail]]

(In reply to Honza Bambas from comment #22)
> (From update of attachment 604451 [details] [diff] [review])
> > +    var pendingTests = [2, testNonAnonymousCredentials,
> > +                        1, testAnonymousCredentials,
> > +                        0, testAnonymousNoAuth];
> 
> Please make this as:
> [
>  {expectedDialogs: 2, func: testNon...},
>  {...
> ]

Pushed changeset 5fa704e28601 to mozilla-central with this change as requested.
I didn't make the other change because I didn't understand what it was trying to achieve even with the help of #developers.

Comment 29

[Serge Gautherie (:sgautherie)]

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey/1331959358.1331960056.32198.gz&fulltext=1
WINNT 5.2 comm-central-trunk debug test mochitests-5/5 on 2012/03/16 21:42:38
{
7648 INFO TEST-START | /tests/toolkit/components/passwordmgr/test/test_bug_627616.html
...
7660 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_bug_627616.html | received expected number of auth dialogs - 0 should equal 0
7661 INFO TEST-END | /tests/toolkit/components/passwordmgr/test/test_bug_627616.html | finished in 4709ms
}

V.Fixed

Comment 30

[Serge Gautherie (:sgautherie)]

Comment on attachment 604451 [details] [diff] [review]
Approach 3
[Checked in: Comments 28 and 34]

(In reply to Alex Keybl [:akeybl] from comment #27)
> No need to track for FF13, as this appears to be SM specific. That being
> said, we would take a fix in support of SM if necessary.

SeaMonkey is not broken, the test is; it's just one of the many issues that Firefox (boxes) doesn't "catch".

Comment 31

[Alex Keybl [:akeybl]]

Comment on attachment 604451 [details] [diff] [review]
Approach 3
[Checked in: Comments 28 and 34]

[Triage Comment]
Test-only fix - approved for Aurora 13.

Comment 32

[Serge Gautherie (:sgautherie)]

Neil, can you land this on m-a?

Comment 33

[[e-mail]]

Sorry, I don't have any aurora trees, please set appropriate keywords.

Comment 34

[Jens Hatlak (:InvisibleSmiley)]

Comment on attachment 604451 [details] [diff] [review]
Approach 3
[Checked in: Comments 28 and 34]

http://hg.mozilla.org/releases/mozilla-aurora/rev/196ad34ad49a

Comment 35

[Serge Gautherie (:sgautherie)]

http://tinderbox.mozilla.org/showlog.cgi?log=SeaMonkey-Aurora/1333408161.1333409269.24508.gz
OS X 10.5 comm-aurora debug test mochitests-5/5 on 2012/04/02 16:09:21

firefox13: verified.