1491257 - Intermittent [TV] testing/marionette/test/unit/test_sync.js | test_PollPromise_interval - [test_PollPromise_interval : 111] 2 == 3

Status: RESOLVED INCOMPLETE

(Testing :: Marionette Client and Harness, defect, P1)

Description

[Treeherder Bug Filer]

Filed by: cbrindusan [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=199246467&repo=mozilla-central

https://queue.taskcluster.net/v1/task/DOurrE1nTc-YlGV5fHAMcg/runs/0/artifacts/public/logs/live_backing.log

05:48:41     INFO -  TEST-START | testing/marionette/test/unit/test_sync.js
05:48:43  WARNING -  TEST-UNEXPECTED-FAIL | testing/marionette/test/unit/test_sync.js | xpcshell return code: 0
05:48:43     INFO -  TEST-INFO took 2440ms
05:48:43     INFO -  >>>>>>>
05:48:43     INFO -  PID 2284 | *** You are running in chaos test mode. See ChaosMode.h. ***
05:48:43     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
05:48:43     INFO -  running event loop
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_funcTypes
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_funcTypes pending (2)
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_funcTypes - [test_PollPromise_funcTypes : 15] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_funcTypes - [test_PollPromise_funcTypes : 15] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_funcTypes - [test_PollPromise_funcTypes : 15] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_funcTypes - [test_PollPromise_funcTypes : 15] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_funcTypes - [test_PollPromise_funcTypes : 15] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_funcTypes - [test_PollPromise_funcTypes : 15] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_funcTypes - [test_PollPromise_funcTypes : 15] ..
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (3)
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_funcTypes finished (3)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_timeoutTypes
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_timeoutTypes pending (2)
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutTypes - [test_PollPromise_timeoutTypes : 25] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutTypes - [test_PollPromise_timeoutTypes : 25] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutTypes - [test_PollPromise_timeoutTypes : 25] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutTypes - [test_PollPromise_timeoutTypes : 25] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutTypes - [test_PollPromise_timeoutTypes : 25] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutTypes - [test_PollPromise_timeoutTypes : 28] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutTypes - [test_PollPromise_timeoutTypes : 28] ..
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (3)
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_timeoutTypes finished (3)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_intervalTypes
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_intervalTypes pending (2)
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_intervalTypes - [test_PollPromise_intervalTypes : 37] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_intervalTypes - [test_PollPromise_intervalTypes : 37] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_intervalTypes - [test_PollPromise_intervalTypes : 37] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_intervalTypes - [test_PollPromise_intervalTypes : 37] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_intervalTypes - [test_PollPromise_intervalTypes : 37] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_intervalTypes - [test_PollPromise_intervalTypes : 40] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_intervalTypes - [test_PollPromise_intervalTypes : 40] ..
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 3 pending (3)
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_intervalTypes finished (3)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 2 finished (2)
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_retvalTypes
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_retvalTypes pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 3 finished (2)
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_retvalTypes - [test_PollPromise_retvalTypes : 49] true === true
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_retvalTypes - [test_PollPromise_retvalTypes : 49] false === false
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_retvalTypes - [test_PollPromise_retvalTypes : 49] "foo" === "foo"
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_retvalTypes - [test_PollPromise_retvalTypes : 49] 42 === 42
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_retvalTypes - [test_PollPromise_retvalTypes : 49] [] === []
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_retvalTypes - [test_PollPromise_retvalTypes : 49] {} === {}
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 4 pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_retvalTypes finished (2)
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_timeoutElapse
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_timeoutElapse pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 4 finished (2)
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutElapse - [test_PollPromise_timeoutElapse : 61] 2001 >= 2000
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutElapse - [test_PollPromise_timeoutElapse : 62] 201 >= 15
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 5 pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_timeoutElapse finished (2)
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_rethrowError
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_rethrowError pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 5 finished (2)
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_rethrowError - [test_PollPromise_rethrowError : 76] 1 == 1
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_rethrowError - [test_PollPromise_rethrowError : 77] true == true
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 6 pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_rethrowError finished (2)
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_noTimeout
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_noTimeout pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 6 finished (2)
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_noTimeout - [test_PollPromise_noTimeout : 89] 1 == 1
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_noTimeout - [test_PollPromise_noTimeout : 90] 0 < 2000
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 7 pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_noTimeout finished (2)
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_timeout
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_timeout pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 7 finished (2)
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeout - [test_PollPromise_timeout : 101] 11 > 1
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeout - [test_PollPromise_timeout : 102] 101 >= 100
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 8 pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_timeout finished (2)
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_interval
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_interval pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 8 finished (2)
05:48:43  WARNING -  TEST-UNEXPECTED-FAIL | testing/marionette/test/unit/test_sync.js | test_PollPromise_interval - [test_PollPromise_interval : 111] 2 == 3
05:48:43     INFO -  Z:/task_1536902706/build/tests/xpcshell/tests/testing/marionette/test/unit/test_sync.js:test_PollPromise_interval:111
05:48:43     INFO -  exiting test
05:48:43     INFO -  Unexpected exception NS_ERROR_ABORT:
05:48:43     INFO -  _abort_failed_test@Z:\task_1536902706\build\tests\xpcshell\head.js:746:9
05:48:43     INFO -  do_report_result@Z:\task_1536902706\build\tests\xpcshell\head.js:853:5
05:48:43     INFO -  Assert<@Z:\task_1536902706\build\tests\xpcshell\head.js:55:5
05:48:43     INFO -  proto.report@resource://testing-common/Assert.jsm:214:5
05:48:43     INFO -  equal@resource://testing-common/Assert.jsm:246:3
05:48:43     INFO -  test_PollPromise_interval@Z:/task_1536902706/build/tests/xpcshell/tests/testing/marionette/test/unit/test_sync.js:111:3
05:48:43     INFO -  async*run_next_test/_run_next_test/<@Z:\task_1536902706\build\tests\xpcshell\head.js:1441:22
05:48:43     INFO -  async*_run_next_test@Z:\task_1536902706\build\tests\xpcshell\head.js:1441:10
05:48:43     INFO -  run@Z:\task_1536902706\build\tests\xpcshell\head.js:692:9
05:48:43     INFO -  _do_main@Z:\task_1536902706\build\tests\xpcshell\head.js:219:3
05:48:43     INFO -  _execute_test@Z:\task_1536902706\build\tests\xpcshell\head.js:533:5
05:48:43     INFO -  @-e:1:1
05:48:43     INFO -  exiting test

Comment 1

[Andreas Tolfsen ❲:ato❳]

Attachment: marionette: be more lenient in PollPromise interval test

A PollPromise with timeout of 100 ms and interval of 100 ms is
normally expected to fire twice: once immediately and once before
the timeout at 100 ms.

On slow systems, such as Windows PGO TV, the timeout timer may be
slow enough for a third evaluation of the PollPromise to occur.
This makes the test more lenient by allowing anywhere from 2 to 3
iterations to happen.

Comment 2

[Andreas Tolfsen ❲:ato❳]

try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=61f7e6f44633306b80570361b7e764d385e5d7e1

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Comment on attachment 9009063 [details] [diff] [review]
marionette: be more lenient in PollPromise interval test

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

::: testing/marionette/test/unit/test_sync.js
@@ +108,5 @@
>      ++nevals;
>      reject();
>    }, {timeout: 100, interval: 100});
> +  greaterOrEqual(nevals, 2);
> +  lessOrEqual(nevals, 3);

That doesn't sound ideal. So lets talk about a solution first.

As I can see we have a timer of type `TYPE_REPEATING_SLACK` which can be fired at any time. Even it is the preferred type for most situations, how should the processing of the callback count in here. Note that this also influences the timer period, which actually might lead to the above seen situation.

So wouldn't it be better to have a precise timer of type `TYPE_REPEATING_PRECISE_CAN_SKIP` instead?

Comment 4

[Andreas Tolfsen ❲:ato❳]

Precisely because we’re using TYPE_REPEATING_SLACK, permitting the
test some leeway here makes sense.  But I buy the argument for using
TYPE_REPEATING_PRECISE_CAN_SKIP too.

I think the reason I originally chose TYPE_REPEATING_SLACK for this
was to guarantee that the promise function was called as many times
as possible in a fashion that guaranteed that it was called at least
once.  Theoretically it would be possible for it never to be invoked
if the scheduler is busy when using TYPE_REPEATING_SLACK.  Since
then we changed PollPromise to explicitly call it once first anyway,
so that is no longer a concern.

Comment 5

[Andreas Tolfsen ❲:ato❳]

Attachment: marionette: make PollPromise more precise

A PollPromise with timeout of 100 ms and interval of 100 ms is
normally expected to fire twice: once immediately and once before
the timeout at 100 ms.

On slow systems, such as Windows PGO TV, the timeout timer may be
slow enough for a third evaluation of the PollPromise to occur.
By making the timer strategy more precise we can ensure that the
repeating timer has a constant period between firings.

This guarantees that it will not queue up new events to fire the
callback until the previous callback event finishes.  This means,
that if the callback takes a long time to evaluate, the next
evaluation is only scheduled after it returns.  This will prevent
firings to happen after the timeout duration has elapsed.

Comment 6

[Andreas Tolfsen ❲:ato❳]

try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=302397daa060028cbf6ff1d02ee90c18639c8c2b

Comment 7

[Andreas Tolfsen ❲:ato❳]

Looking closer at this, changing PollPromise to
TYPE_REPEATING_PRECISE_CAN_SKIP makes a lot more sense.  Thanks for
the constructive review.

Comment 8

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Comment on attachment 9009080 [details] [diff] [review]
marionette: make PollPromise more precise

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

That patch looks way better. If try is happy for a TV test job, then lets land it!

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/433f1ab89061
marionette: make PollPromise more precise; r=whimboo

Comment 10

[Narcis Beleuzu [:NarcisB]]

Backed out for xpcshell failures on test_sync.js

Push link: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&resultStatus=testfailed,busted,exception,runnable
Backout link: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&resultStatus=testfailed,busted,exception,runnable
Log link: https://treeherder.mozilla.org/logviewer.html#?job_id=199326149&repo=mozilla-inbound&lineNumber=1387

Comment 11

[Pulsebot]

Backout by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/b5050dd99c14
Backed out changeset 433f1ab89061 for xpcshell failures on test_sync.js. CLOSED TREE

Comment 12

[Intermittent Failures Robot]

1 failures in 2684 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-central: 1

Platform breakdown:
* windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1491257&startday=2018-09-10&endday=2018-09-16&tree=all

Comment 13

[Andreas Tolfsen ❲:ato❳]

My only theory at the moment is that Android 4.3 API16+ debug is
_so slow_ that it takes longer than 30 seconds to set up the test
and run it.  With Ci.nsITimer.TYPE_REPEATING_SLACK we were guaranteed
that some callbacks would fire, but with TYPE_REPEATING_PRECISE_CAN_SKIP
I suppose we’re not if the timeout duration is hit first.

Comment 14

[Andreas Tolfsen ❲:ato❳]

From a recent test run on inbound I found that it on average takes
about ~11 seconds to run test_sync:

> task 2018-09-19T03:02:19.587Z] 03:02:19     INFO -  TEST-START | testing/marionette/test/unit/test_sync.js
> task 2018-09-19T03:02:31.219Z] 03:02:31     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | took 11632ms

The timeout we are seeing here is five minutes (300,002 ms), which
should be ample time for the test to complete.

Comment 15

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 16

[BMO Automation]

Moving bug to Testing::Marionette Client and Harness component per bug 1815831.