Closed Bug 1023547 Opened 9 years ago Closed 9 years ago

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

Categories

(Core :: DOM: Workers, defect)

Product:
Core
Component:
DOM: Workers
Platform:
ARM
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla33
Tracking Flags:
Tracking Status
firefox30 --- wontfix
firefox31 --- fixed
firefox32 --- fixed
firefox33 --- fixed
firefox-esr24 --- unaffected
b2g-v1.4 --- wontfix
b2g-v2.0 --- fixed
b2g-v2.1 --- fixed

People

(Reporter: RyanVM, Assigned: nsm)

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

Fix intermittent dom/workers/test/test_promise.html failure
2.31 KB, patch
bzbarsky
: review+
Details | Diff | Splinter Review 
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
Unfortunately, bug 965644 doesn't appear to have helped with this one :(
Flags: needinfo?(nsm.nikhil)
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)
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)
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
Closed: 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla33
(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 → ---
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 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+
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
https://hg.mozilla.org/mozilla-central/rev/b00c22ac9b23
Status: REOPENED → RESOLVED
Closed: 9 years ago → 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla33
You need to log in before you can comment on or make changes to this bug.