606010 - TEST FAILED: test-page-mod.testPageModIncludes (failure)

Status: RESOLVED FIXED

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

Description

[Ayan Shah[:ashah]]

SDK: 0.9RC2
Browser: FFx 4.0b6
Platform: Win 7, Win XP

I ran my integration script against the RC2 and found the following error on XP and Win7 both:

"TEST FAILED: test-page-mod.testPageModIncludes (failure)"
There were other failures related to this which are:

error: fail: 'about:*' match test, expected: true
error: fail: 'about:buildconfig' match test, expected: true

Logs are available at http://pastebin.mozilla.org/822625

Note: FYI, The command that is executed from inside the integration script is:
"cfx testall -a firefox -b /Applications/Firefox4.0b6/Firefox.app"

Comment 1

[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".

Comment 3

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

Note: Ayan seems to be seeing this consistently on Windows 7.

Comment 4

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

We can either fix the test or disable it, but we have to squash all intermittent test failures so Firefox/Gecko developers can rely on our automated test infrastructure to tell them when they do something that breaks the SDK.

Comment 5

[Alexandre Poirot [:ochameau]]

Attachment: Wait for the last page-mod to be executed before executing asserts

I reproduced this bug when my computer was under stress and I found a race condition in this test. Pagemod can take some time before being attach and postMessage to be sent to content script. So when testPageMod callback is called on document onload, page-mods may not be completed.

So I'm first waiting for the last page-mod to be fully executed before executing all asserts. For this I added an utility function in unit-test, that may help to solve intermittent failing tests.

Comment 6

[Irakli Gozalishvili [:irakli] [:gozala] [@gozala]]

Comment on attachment 526734 [details] [diff] [review]
Wait for the last page-mod to be executed before executing asserts

Alex I found `waitFor` pretty confusing, requiring developer to look at it's implementation to understand what test does. This can be addressed in two ways either 1) by abstracting desired looping functionality to a test independent utility function 2) or by improving names and comments of the `waitFor`.

I would encourage to go with option 1. as that will improve test readability and will not require looking into `waitFor` implementation. I've also put together simple example that shows how it may look in practice:
https://gist.github.com/927053

If will you still decide to go with option 2. I'd recommend following:

1. change name from waitFor -> waitUntil 
2. change name assertTrueClousure -> isReady
3. make callback argument #2 and rename it to `assert`.
4. make `msg` argument #3 and make it optional defaulting to whatever is used by `waitUntilDone`.

Comment 7

[Irakli Gozalishvili [:irakli] [:gozala] [@gozala]]

5. Add some comments explaining what code does, as it's not obvious.

Comment 8

[Alexandre Poirot [:ochameau]]

Attachment: Another proposal: implement TestRunner.waitUntil({Equal,NotEqual,Matches})?

Previous proposal was a really simple one that can be misunderstood as I tried to propose the smallest modification possible to unit-test.js.
But here is a more concrete modification that highlights the need for such method to live in unit-test.
I've added lot of comments and wrote documentation.

Comment 9

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

Comment on attachment 528312 [details] [diff] [review]
Another proposal: implement TestRunner.waitUntil({Equal,NotEqual,Matches})?

(In reply to comment #5)
> Created attachment 526734 [details] [diff] [review]
> Wait for the last page-mod to be executed before executing asserts
> 
> I reproduced this bug when my computer was under stress and I found a race
> condition in this test. Pagemod can take some time before being attach and
> postMessage to be sent to content script. So when testPageMod callback is
> called on document onload, page-mods may not be completed.

Hmm, that's strange, I would think the onPageLoad function in pagemod-test-helpers.js would handle this, given that it waits until load and then sets a timer to delay running the test even further.

But perhaps its timer, which just waits zero milliseconds in order to spin the event loop, is not sufficient?


>diff --git a/packages/addon-kit/tests/test-page-mod.js b/packages/addon-kit/tests/test-page-mod.js

>+    function (win, done) {
>+      test.waitUntil(function () win["about:buildconfig"],
>+                     "about:buildconfig page-mod to be executed")
>+          .then(function () {
>+            asserts.forEach(function(fn) {
>+              fn(test, win);
>+            });
>+            done();
>+          });
>+      }

Nit: line up this last closing brace with the line containing the opening brace, i.e.:

    function (win, done) {
      test.waitUntil(function () win["about:buildconfig"],
                     "about:buildconfig page-mod to be executed")
          .then(function () {
            asserts.forEach(function(fn) {
              fn(test, win);
            });
            done();
          });
    }

Also, since there is already code in pagemod-test-helpers.js to wait for the page to be loaded, wouldn't it be simpler to use waitUntil() there instead?


>diff --git a/packages/api-utils/docs/unit-test.md b/packages/api-utils/docs/unit-test.md

>+<api name="waitUntil">
>+@method
>+  Ensures that `a` returns a truthy value.

Nit: how long does it wait before failing the test?  Even though these functions' names clearly imply that they wait, this description doesn't make that explicit.  It should say something like "Ensures that `a` returns a truthy value within a reasonable amount of time." or "Ensures that `a` returns a truthy value within ten seconds."


>+@param a {function}
>+  Function that return the value to verify.

Nit: return -> returns


>+<api name="waitUntilEqual">
>+@method
>+  Simply ensures that `a == b` returned values or values without recursing into 
>+  them.

Nit: here and elsewhere, "simply" seems extraneous, and it's enough to just say "ensures...".

Nit: returned values or values without recursing into them -> without recursing into `a` or `b` (consistent with the description of waitUntilNotEqual).


>+@param b {value}
>+  Another value, or a function that returns value.

Nit: returns value -> returns another value


>+<api name="waitUntilMatches">

Nit: for consistency with the names of the other methods, this should be called waitUntilMatch (otherwise those should be waitUntilEquals and waitUntilDoesntEqual).  However, I see that there is already this inconsistency in the underlying methods that these methods are wrapping, so I suppose we should leave this the way it is.


>+@method
>+  Ensures that the given string matches the given regular expression.
>+  If it does, marks a test as passing, otherwise marks a test as
>+  failing.

Nit: marks a test -> marks the test


>+@param string {Function}
>+  A function that return the string to test.

Nit: return -> returns


>diff --git a/packages/api-utils/lib/unit-test.js b/packages/api-utils/lib/unit-test.js

>+  // Set of assertions function to wait for an assertion to become true
>+  // These function wait same argument than TestRunner.assert* methods

Nit: assertions function -> assertion functions
Nit: These function -> These functions
Nit: wait same argument than -> take the same arguments as the
Nit: add periods to the ends of the sentences.


>+  /**
>+   * Internal function that allow to wait for assertion to become true.

Nit: allow to wait for assertion -> waits for an assertion


>+   * @param {Array} args
>+   *    List of arguments to give to the previous assertion method. 
>+   *    All functions in this list are going to be called to retrieve current
>+   *    assertions values.

Nit: assertions values -> assertion values


>+  _waitUntil: function waitUntil(assertionMethod, args) {
>+    let count = 0;
>+    let maxCount = this.DEFAULT_PAUSE_TIMEOUT / 500;
>+    
>+    let callback = null;
>+    let finished = false;
>+    
>+    let test = this;
>+    function loop() {
>+      // Build a mockup object to fake TestRunner API and intercept calls to
>+      // pass and fail methods, in order to retrieve nice error messages
>+      // and assertion result
>+      let mock = {
>+        pass: function (msg) {
>+          test.pass(msg);
>+          if (callback)
>+            callback();
>+          finished = true;
>+        },
>+        fail: function (msg) {
>+          if (++count > maxCount) {
>+            test.fail(msg);
>+            if (callback)
>+              callback();
>+            finished = true;
>+            return;
>+          }
>+          timer.setTimeout(loop, 500);
>+        }
>+      };

Nit: the first occurrence of "500" in this code isn't clear until the second occurrence shows up.  To make it clearer and guard against the chance of changing one value without changing the other, factor it out into a constant or property like DEFAULT_PAUSE_TIMEOUT, f.e. PAUSE_DELAY.


>+      for(let i = 0, l = args.length; i < l; i++) {

Nit: add a space between `for` and the opening parenthesis, i.e. do: for (


>+        let a = args[i];
>+        if (typeof a == "function") {
>+          try {
>+            a = a();
>+          } catch(e) {
>+            mock.fail("Exception when calling asynchronous assertion: " + e);
>+          }

Nit: don't cuddle catch, i.e. do:

          try {
            a = a();
          }
          catch(e) {
            mock.fail("Exception when calling asynchronous assertion: " + e);
          }


>+      // Finally call assertion function with current assertions values

Nit: assertions values -> assertion values


>+        // In case of immediate positive result, we need to execute callback
>+        // immediatly here:

Nit: immediatly -> immediately


>diff --git a/packages/api-utils/tests/test-unit-test.js b/packages/api-utils/tests/test-unit-test.js

>+exports.testWaitUntilInstant = function(test) {
>+  test.waitUntilDone();
>+  
>+  test.waitUntil(function () {return true;}, "waitUntil with instant true pass")
>+      .then(function () {
>+        test.done();
>+      });

Nit: put space around curly braces, i.e.:

  test.waitUntil(function () { return true; },
                 "waitUntil with instant true pass")

However, functions like this can be more simply written as lambdas, i.e.:

  test.waitUntil(function () true, "waitUntil with instant true pass")

As can the `then` callback:

  test.waitUntil(function () true, "waitUntil with instant true pass")
      .then(function () test.done());

Comment 10

[Alexandre Poirot [:ochameau]]

(In reply to comment #9)
> Comment on attachment 528312 [details] [diff] [review]
> Another proposal: implement TestRunner.waitUntil({Equal,NotEqual,Matches})?
> 
> (In reply to comment #5)
> > Created attachment 526734 [details] [diff] [review]
> > Wait for the last page-mod to be executed before executing asserts
> > 
> > I reproduced this bug when my computer was under stress and I found a race
> > condition in this test. Pagemod can take some time before being attach and
> > postMessage to be sent to content script. So when testPageMod callback is
> > called on document onload, page-mods may not be completed.
> 
> Hmm, that's strange, I would think the onPageLoad function in
> pagemod-test-helpers.js would handle this, given that it waits until load and
> then sets a timer to delay running the test even further.
> 
> But perhaps its timer, which just waits zero milliseconds in order to spin the
> event loop, is not sufficient?
> 

I didn't move it to test helpers as we want to wait for the execution of:
  worker.postMessage(this.include[0]);
not the page-mod "ready"/"attach" event, that happens before.
And why does that happen before? I think it's mainly because of asynchronous EventEmitter used in worker, that use setTimeout zero before calling content script onMessage.

The elegant way to write this test would be to send messages back from all content scripts and wait for all these messages before executing assertions. 
But using waitFor/waitUntil pattern allow to write way more simplier unit test that doesn't need to check everything again and again in every test. (For ex, we suppose that one previous test verified that postMessage is working fine)
Having said that, in any case, I prefer to wait for relevant events to execute assertions if such event exists and it is not too complicated to wait for them.

Thanks for the review, and I'm really sorry to transform reviews into english lessons :/

Landed:
https://github.com/mozilla/addon-sdk/commit/59f2ba601a79bf1262d61177d90c022f6210c604

Comment 11

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

(In reply to comment #10)
> Thanks for the review, and I'm really sorry to transform reviews into english
> lessons :/

That's ok.  Reviews are intended to be educational, for both reviewee and reviewer.  And these language issues aren't very important, which is why I usually mark them as nits.

It's just useful to address them since the number of contributors to our project is growing, and it's increasingly likely that the next person to look at your code is going to be someone else who will learn the code more quickly if the comments describing it are as clear and correct as possible.