598525 - error: TEST FAILED: test-windows.testActiveWindow (timed out)

Status: RESOLVED FIXED

(Add-on SDK Graveyard :: General, defect)

Description

[Myk Melez [:myk] [@mykmelez]]

I'm seeing a consistent |error: TEST FAILED: test-windows.testActiveWindow (timed out)| failure on Linux and Windows with Firefox 3.6 when I run all tests (or when I run tab-browser and windows tests).

The problem doesn't occur on Mac, on 4.0b6, or when I run only windows tests.  It seems to be a timing issue, since I can make the error go away by running all the test steps in testActiveWindow in a sufficiently large timeout.

Comment 1

[Myk Melez [:myk] [@mykmelez]]

Felipe: do you see this issue as well?  It seems to be a byproduct of your fix for bug 596782.  I noted it there, but at the time it was intermittent (and therefore not a release blocker).  Since then, however, it has started happening for me every time I run all tests or some combination of windows and some other module tests, i.e.:

cfx test -b ~/Applications/firefox-3.6/firefox
cfx test -b ~/Applications/firefox-3.6/firefox -F 'tab-browser|windows'
cfx test -b ~/Applications/firefox-3.6/firefox -F 'context-menu|windows'

If other people are seeing this consistently, then it's a release blocker.  If it's just an intermittent failure that I happen to be triggering consistently, but other folks don't see (or see only intermittently) then I'd consider releasing without a fix for it.

Drew, Atul, Dietrich, Irakli, Ayan: are any of y'all seeing this?

Comment 2

[Myk Melez [:myk] [@mykmelez]]

And all of a sudden I'm no longer able to reproduce when I run all tests, although I can still reproduce when I test windows with tab-browser or context-menu.

*sigh*

Comment 3

[Drew Willcoxon :adw]

On OS X and the Firefox 3.6 nightly, all tests pass when I use the three command lines in comment 1.

In my Ubuntu VM with the Firefox 3.6 nightly, all tests pass with the second and third command lines, but the first command line generates the errors I was seeing yesterday after the meeting: failures in test-tabs and test-windows.  The test-windows failures have to do with assertions about `windows.activeWindow`, but no failure in test-windows.testActiveWindow:

error: fail: Correct active window - 2 ("Namoroka" != "window 2 - Namoroka")
info: Traceback (most recent call last):
  File "resource://jetpack-core-jetpack-core-tests/test-windows.js", line 266, in focusListener
    nextStep();
  File "resource://jetpack-core-jetpack-core-tests/test-windows.js", line 240, in nextStep
    testSteps.shift()();
  File "resource://jetpack-core-jetpack-core-tests/test-windows.js", line 210, in anonymous
    test.assertEqual(windows.activeWindow.title, window2.title, "Correct active window - 2");
  File "resource://jetpack-core-jetpack-core-lib/unit-test.js", line 227, in assertEqual
    this.fail(message);
  File "resource://jetpack-core-jetpack-core-lib/unit-test.js", line 145, in fail
    console.trace();

error: fail: Correct active window - 3 ("Namoroka" != "window 3 - Namoroka")
info: Traceback (most recent call last):
  File "resource://jetpack-core-jetpack-core-tests/test-windows.js", line 266, in focusListener
    nextStep();
  File "resource://jetpack-core-jetpack-core-tests/test-windows.js", line 240, in nextStep
    testSteps.shift()();
  File "resource://jetpack-core-jetpack-core-tests/test-windows.js", line 215, in anonymous
    test.assertEqual(windows.activeWindow.title, window3.title, "Correct active window - 3");
  File "resource://jetpack-core-jetpack-core-lib/unit-test.js", line 227, in assertEqual
    this.fail(message);
  File "resource://jetpack-core-jetpack-core-lib/unit-test.js", line 145, in fail
    console.trace();

Comment 4

[:Felipe Gomes (needinfo for replies!)]

Attachment: Disable test on 3.6

After several attempts to make the test reliable on 3.6, we decided to disable it (for 3.6 only). There seems to be some timing issue with the focus() calls that sometimes just fails silently (nothing is caught on try-catch) and never focus the new window.
(I can only reproduce these on Linux, not on Windows)

Comment 5

[Myk Melez [:myk] [@mykmelez]]

Comment on attachment 477729 [details] [diff] [review]
Disable test on 3.6

Looks good, works well on Linux, and doesn't cause problems on Mac.  On Windows, however, it intermittently triggers a bunch of additional test failures, including ones like the following:

.....................error: TEST FAILED: test-windows.testOnOpenOnCloseListeners (failure)
error: fail: Only one window open (2 != 1)
info: Traceback (most recent call last):
  File "resource://testpkgs-jetpack-core-lib/timer.js", line 60, in notify
    this._callback.apply(null, this._params);
  File "resource://testpkgs-jetpack-core-lib/unit-test.js", line 255, in anonymous
    timer.setTimeout(function() { onDone(self); }, 0);
  File "resource://testpkgs-jetpack-core-lib/unit-test.js", line 280, in runNextTest
    self.start({test: test, onDone: runNextTest});
  File "resource://testpkgs-jetpack-core-lib/unit-test.js", line 298, in start
    this.test.testFunction(this);
  File "resource://testpkgs-jetpack-core-lib/unit-test.js", line 63, in runTest
    test(runner);
  File "resource://testpkgs-jetpack-core-tests/test-windows.js", line 67, in anonymous
    test.assertEqual(windows.length, 1, "Only one window open");
  File "resource://testpkgs-jetpack-core-lib/unit-test.js", line 227, in assertEqual
    this.fail(message);
  File "resource://testpkgs-jetpack-core-lib/unit-test.js", line 145, in fail
    console.trace();
error: fail: Event received twice
info: Traceback (most recent call last):
  File "resource://testpkgs-jetpack-core-lib/errors.js", line 49, in anonymous
    return callback.apply(this, arguments);
  File "resource://testpkgs-jetpack-core-lib/window-utils.js", line 105, in handleEvent
    this._regWindow(window);
  File "resource://testpkgs-jetpack-core-lib/window-utils.js", line 83, in _regWindow
    this.delegate.onTrack(window);
  File "resource://testpkgs-jetpack-core-lib/windows.js", line 241, in anonymous
    })(safeWindowObj);
  File "resource://testpkgs-jetpack-core-lib/errors.js", line 49, in anonymous
    return callback.apply(this, arguments);
  File "resource://testpkgs-jetpack-core-lib/windows.js", line 240, in anonymous
    callback.call(exports.browserWindows, safeWindowObj);
  File "resource://testpkgs-jetpack-core-tests/test-windows.js", line 78, in listener1
    test.fail("Event received twice");
  File "resource://testpkgs-jetpack-core-lib/unit-test.js", line 145, in fail
    console.trace();

Bizarrely, these test failures occur even when testing against 4.0b6, even though the patch is designed to only affect which tests get run on 3.6.  Apparently, doing something as simple as require("xul-app") and then calling xulApp.versionInRange is enough to cause a bunch of test failures.

If that's true, it means these tests are remarkably brittle.  So brittle, in fact, that part of me wonders if we should pull the Windows API for this release and circle back around to it for 0.9.

Nevertheless, those failures are intermittent, and we aren't blocking the release on intermittent failures, so r=myk.

Comment 6

[Myk Melez [:myk] [@mykmelez]]

Fixed by changeset https://hg.mozilla.org/labs/jetpack-sdk/rev/fb8653dcf1c5.

Comment 7

[:Felipe Gomes (needinfo for replies!)]

I really don't think this patch can cause these other failures, unless the order of the tests are not respected (which I'm sure it isn't), or if there's something totally broken.

As the problem is intermittent maybe it coincided enough with applying/unapplying the patch that it seemed related.

Note that the failures are actually only one:
error: fail: Only one window open (2 != 1) 

which means that the test is starting with one window left. If this happens it's all downhill for the other assertions, but the root of the problem is only one.

The only other test run before that failure is testOpenAndCloseWindow, which makes me wonder if closing a window at the onLoad handler is not guaranteed to work, although I'm sure it never happened locally. I'm curious, what's the Windows config you are using? is it a VM? Maybe in a VM opening windows is remarkably slow and the default waitUntilDone timeout is not being enough.

Comment 8

[Myk Melez [:myk] [@mykmelez]]

(In reply to comment #7)
> I really don't think this patch can cause these other failures, unless the
> order of the tests are not respected (which I'm sure it isn't)

Um, that depends on what you mean by order of the tests.  If you mean the order of the exported test functions, then there is no guaranteed order, since "exports" is an object with properties that the test runner iterates across.

If, on the other hand, you mean the order of the calls to test.assert*, those should be executed in execution order modulo nondeterminism caused by asynchronous processing.


> As the problem is intermittent maybe it coincided enough with
> applying/unapplying the patch that it seemed related.

It's possible, although I tried it a bunch of times.


> I'm curious, what's the
> Windows config you are using? is it a VM? Maybe in a VM opening windows is
> remarkably slow and the default waitUntilDone timeout is not being enough.

I'm using Windows 7 in a VMware Fusion VM.  Opening windows is slower, for sure, but it doesn't seem that slow, and the 10 second timeout was more than enough for testActivateWindow, which would sit there for a long time doing nothing after having opened its windows before timing out.

Comment 9

[Matěj Cepl]

I can still reproduce it with
Mozilla/5.0 (X11; Linux i686 on x86_64; rv:2.0b6) Gecko/20100101 Firefox/4.0b6
but not with
firefox-3.6.7-1.fc14.x86_64

Comment 10

[Matěj Cepl]

Attachment: stdout/stderr from cfx testall -a firefox (with Firefox 4.0b6)

Comment 11

[Myk Melez [:myk] [@mykmelez]]

The Add-on SDK is no longer a Mozilla Labs experiment and has become a big enough project to warrant its own Bugzilla product, so the "Add-on SDK" product has been created for it, and I am moving its bugs to that product.

To filter bugmail related to this change, filter on the word "looptid".