1035928 - TEST-UNEXPECTED-FAIL | /builds/slave/test/gaia/apps/system/test/marionette/app_usage_metrics_test.js | App Usage Metrics > Uninstalled apps are counted

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Gaia::System, defect)

Description

[Julien Wajsberg [:julienw]]

https://tbpl.mozilla.org/php/getParsedLog.php?id=43350892&tree=Gaia-Try&full=1
https://tbpl.mozilla.org/php/getParsedLog.php?id=43324483&tree=Gaia-Try&full=1


02:17:14     INFO -    4) App Usage Metrics > Uninstalled apps are counted:
02:17:14     INFO -    Error: Polling socket recv() timeout!
02:17:14     INFO -        at TcpSync._readResponse (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/drivers/tcp-sync.js:87:30)
02:17:14     INFO -        at TcpSync.send (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/drivers/tcp-sync.js:100:24)
02:17:14     INFO -        at Object.send (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:457:36)
02:17:14     INFO -        at Object.Client._sendCommand (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:503:19)
02:17:14     INFO -        at Object._executeScript (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:1468:19)
02:17:14     INFO -        at Object.executeAsyncScript (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:1249:19)
02:17:14     INFO -        at waitForEvent (/builds/slave/test/gaia/apps/system/test/marionette/app_usage_metrics_test.js:48:12)
02:17:14     INFO -        at Context.<anonymous> (/builds/slave/test/gaia/apps/system/test/marionette/app_usage_metrics_test.js:142:5)

Comment 1

[Alexandre Poirot [:ochameau]]

I believe this intermittent (and many others) are related to executeAsyncScript practice being used all over the place :(

Here is the test:

    var confirm = client.helper.waitForElement('.modal-dialog-confirm-ok');
    confirm.click();

    waitForEvent('applicationuninstall', function() {
      ..
    });

waitForEvent times out. I'm all but surprised as we do the action first and register the listener later.
I'm even less surprise as this code executes in nodejs and proxies its execution on Gecko via a network layer. That introduces even more latency between the precise moment where we click on '.modal-dialog-confirm-ok' and the precise moment where we call 'addEventListener'.

This issue isn't with this test, but with *all* gaia integration tests listening for any event.
This issue comes from a marionette limitation: it can't receive arbitrary events from gecko.
Only the client, here nodejs script, can send requests and wait for a response.
That's why we end up with this weird executeAsyncScript+marionetteFinish hack all over the place.
And executeAsync has a terrible name as it is only async on gecko side, on the nodejs side it is sync.

And the fact that executeAsync is sync on nodejs is the key point that justifies why we end up setting the listener after doing the actions that should ends up dispatching an event.
Because it is sync, we have to click on the button or do whatever action we want to test first.
And then listen to the event with executeAsync.

Some tests are making it right, but when you want to make it right, you have to ignore the whole marionette-apps helpers and only execute stuff on gecko, via executeAsync. You have kind of shifting your test script from client to server, from nodejs to gecko:
https://github.com/mozilla-b2g/gaia/blob/master/apps/system/test/marionette/notification_events_test.js#L193-L220
Here is a simplified version of this test, to highlight the fact that we register the listener first and do the action after.
    client.executeAsyncScript(function() {
      var appListener = function(e) {
        ..
        marionetteScriptFinished();
      };
      window.addEventListener('appopened', appListener);

      var event = document.createEvent('CustomEvent');
      ...
      window.dispatchEvent(event);
    });

We should either improve marionette, to support server->client events. That would allow exposing some sane API on marionette to listen for server events. See bug 1014516.
Or one alternative would be to execute the test script, or a big part of it, on gecko!
It would have the benefit to have access to the real objects and not some network proxified ones and would free us from using marionette in tests scripts.

Comment 2

[Julien Wajsberg [:julienw]]

While I agree with most of your logic here, we see this error especially in this file and this test, and not in others (or at least much less frequently). Do you see anything special in this test that would do this?

Comment 3

[Kevin Grandon :kgrandon]

Attachment: Github pull request

Doesn't seem too hard to simply adjust the wait here. I'll verify that it fixes the intermittent then open up a pull request.

Comment 4

[Kevin Grandon :kgrandon]

Comment on attachment 8454045 [details] [review]
Github pull request

Just looking for a quick review here. Adding Marshal/Alex as potential reviewers because Marshal wrote it, and it seems Alex has investigated a bit. Thanks!

Comment 5

[Kevin Grandon :kgrandon]

Comment on attachment 8454045 [details] [review]
Github pull request

Thanks Marshall, let's just go with your review for now as you're the test author.

Comment 6

[Kevin Grandon :kgrandon]

Master: https://github.com/mozilla-b2g/gaia/commit/fcf467c7141b3cfb5c4318a75397ddf6a07ee1cc