Intermittent test_promise.html | 0 === 2: Expected thenable to be called asynchronously

RESOLVED FIXED in Firefox 31

Status

()

RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: RyanVM, Assigned: nsm)

Tracking

({intermittent-failure})

unspecified
mozilla33
ARM
Android
intermittent-failure
Points:
---
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox30 wontfix, firefox31 fixed, firefox32 fixed, firefox33 fixed, firefox-esr24 unaffected, b2g-v1.4 wontfix, b2g-v2.0 fixed, b2g-v2.1 fixed)

Details

Attachments

(1 attachment, 1 obsolete attachment)

(Reporter)

Description

5 years ago
https://tbpl.mozilla.org/php/getParsedLog.php?id=41465234&tree=Fx-Team

Android 2.3 Emulator on ix fx-team opt test mochitest-7 on 2014-06-10 12:37:57 PDT for push 845ea9c7b71c
slave: talos-linux64-ix-065

12:53:55     INFO -  192 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | true === true: First value should win.
12:53:55     INFO -  193 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | 20 === 20: Fastest timeout should win.
12:53:55     INFO -  194 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | true: Should be rejected
12:53:55     INFO -  195 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | true: Should reject with Error.
12:53:55     INFO -  196 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | true: Message should match.
12:53:55     INFO -  197 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | true: Should be rejected
12:53:55     INFO -  198 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | true: Should reject with ReferenceError for function nonExistent().
12:53:55     INFO -  199 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | true: Should return a Promise.
12:53:55     INFO -  200 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | true: Resolved value should be an Array
12:53:55     INFO -  201 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | 3 === 3: Length should match
12:53:55     INFO -  202 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | 1 === 1: Resolved value should match original
12:53:55     INFO -  203 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | 2 === 2: Resolved value should match original
12:53:55     INFO -  204 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | 3 === 3: Resolved value should match original
12:53:55     INFO -  205 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | true: Should cast to a Promise.
12:53:55     INFO -  206 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | 2 === 2: Should resolve to 2.
12:53:55     INFO -  207 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | true: Should cast to a Promise.
12:53:55     INFO -  208 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | [object Promise] === [object Promise]: Should return original Promise.
12:53:55     INFO -  209 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | true === true: Should resolve to true.
12:53:55     INFO -  210 INFO TEST-PASS | /tests/dom/workers/test/test_promise.html | 0 === 0: Expected thenable to be called asynchronously
12:53:55     INFO -  211 INFO TEST-UNEXPECTED-FAIL | /tests/dom/workers/test/test_promise.html | 0 === 2: Expected thenable to be called asynchronously
12:53:55     INFO -  212 INFO TEST-INFO | MEMORY STAT vsize after test: 459042816
12:53:55     INFO -  213 INFO TEST-INFO | MEMORY STAT residentFast after test: 149598208
12:53:55     INFO -  214 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 26170580
12:53:55     INFO -  215 INFO TEST-END | /tests/dom/workers/test/test_promise.html | finished in 1456ms
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Reporter)

Comment 9

5 years ago
Unfortunately, bug 965644 doesn't appear to have helped with this one :(
Flags: needinfo?(nsm.nikhil)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
I have a fairly plausible explanation for this failure.

The worker setTimeout() implementation spawns another timer thread. This timer thread, when the timer fires, dispatches a runnable (TimerRunnable) to the worker thread. Due to previous setTimeout() calls from other tests, we are ending up in a situation where:

setTimeout(..., 0); // This is from a previous test, but results in the timer being inited. Except I can't figure out where.
// Due to thread scheduling, on certain runs, the timer thread immediately fires and a TimerRunnable is queued on the WorkerThread. JS continues running to completion, in this case, our test.
// code elided
Promise.resolve(thenable).then(incX)
// At this point, a WorkerThenableResolverTask is also queued on the WorkerThread.
setTimeout(..., 1000); // the call which tests the values in results.
// At this point the thread ends up being preempted, and doesn't get a chance to run till after 1000ms.

// Thread resumes running, processing the queued runnables.
// WorkerPrivate::RunExpiredTimeouts() goes through the array of timeouts and also triggers the function which checks results. At this point none of the Promise tasks have gotten a chance to run, so results[1] is still 0, test fails.

The only problem is, there doesn't seem to be a sequence of setTimeout() calls that could actually cause this in the test case, since the runTest() calls are gated on those setTimeouts, which means they should have been done before the setTimeout() call in promiseResolveThenableCleanStack().

The fix would be to modify the setTimeout() to only check that results[0] == 0, since that is the main check (that the thenable passed to resolve is invoked async). Then gate the second check of results[1] on the Promise returned by

var p = Promise.resolve(thenable).then(incX)

==>
setTimeout(function() {
  results.push(x);
  is(results[0], 0, ...);
  p.then(function() {
    is(results[1], 2, ...)
  })
}).

Boris, does all of the above sound reasonable?
Assignee: nobody → nsm.nikhil
Flags: needinfo?(nsm.nikhil) → needinfo?(bzbarsky)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
The analysis sounds reasonable, yes, as does the proposed solution.  Nice debugging!  We really need to fix promise stuff to not use the main event loop...

The stray preexisting timeout is almost certainly one of the ones from the Promise.race() tests: those can complete before all the timeouts they set have fired.  My money is on the promise with the nested setTimeouts in it in promiseRacePromiseArray.
Flags: needinfo?(bzbarsky)
Created attachment 8454852 [details] [diff] [review]
Fix intermittent dom/workers/test/test_promise.html failure

Fixes as outlined in the comment.
Also removes the unused utility function in another test.
Attachment #8454852 - Flags: review?(bzbarsky)
Comment on attachment 8454852 [details] [diff] [review]
Fix intermittent dom/workers/test/test_promise.html failure

r=me
Attachment #8454852 - Flags: review?(bzbarsky) → review+
https://hg.mozilla.org/mozilla-central/rev/0e808a734e00
Status: NEW → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla33
(Reporter)

Comment 24

5 years ago
https://hg.mozilla.org/releases/mozilla-aurora/rev/2662e7c51839
https://hg.mozilla.org/releases/mozilla-beta/rev/606f7891e3c4
status-b2g-v1.4: --- → wontfix
status-b2g-v2.0: --- → fixed
status-b2g-v2.1: --- → fixed
status-firefox30: --- → wontfix
status-firefox31: --- → fixed
status-firefox32: --- → fixed
status-firefox33: --- → fixed
status-firefox-esr24: --- → unaffected
Comment hidden (Treeherder Robot)
(Reporter)

Comment 26

5 years ago
(In reply to TBPL Robot from comment #25)

booo :(
Status: RESOLVED → REOPENED
status-b2g-v2.0: fixed → affected
status-b2g-v2.1: fixed → affected
status-firefox32: fixed → affected
status-firefox33: fixed → affected
Resolution: FIXED → ---
Target Milestone: mozilla33 → ---
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Created attachment 8459061 [details] [diff] [review]
Fix intermittent dom/workers/test/test_promise.html failure

results.push(x) should've been gated on the promise, and not just the test.
Let's try again.
Attachment #8459061 - Flags: review?(bzbarsky)
Comment hidden (Treeherder Robot)
Comment on attachment 8459061 [details] [diff] [review]
Fix intermittent dom/workers/test/test_promise.html failure

r=I-am-blind
Attachment #8459061 - Flags: review?(bzbarsky) → review+
Keywords: checkin-needed
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Reporter)

Comment 47

5 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/38bfa2af2bd8
Flags: in-testsuite+
Keywords: checkin-needed
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Reporter)

Comment 52

5 years ago
Backed out for perma-fail. Please verify that this at least passes locally before requesting checkin.
https://hg.mozilla.org/integration/mozilla-inbound/rev/131e77486177

https://tbpl.mozilla.org/php/getParsedLog.php?id=44225502&tree=Mozilla-Inbound
Comment hidden (Treeherder Robot)
(Reporter)

Comment 55

5 years ago
https://hg.mozilla.org/mozilla-central/rev/b00c22ac9b23
Status: REOPENED → RESOLVED
Last Resolved: 5 years ago5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla33
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Reporter)

Comment 58

5 years ago
https://hg.mozilla.org/releases/mozilla-aurora/rev/4bd4b0ae7bbe
status-b2g-v2.0: affected → fixed
status-b2g-v2.1: affected → fixed
status-firefox32: affected → fixed
status-firefox33: affected → fixed
You need to log in before you can comment on or make changes to this bug.