Closed Bug 1011775 Opened 7 years ago Closed 7 years ago

Intermittent test_getUserMedia_stopAudioStream.html | Unexpected callback with = 'ended event never fired' at: ["test_getUserMedia_stopAudioStream.html:33:1",""]

Categories

(Core :: WebRTC, defect)

Product:
Core
Component:
WebRTC
Platform:
All
Gonk (Firefox OS)
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla32
Tracking Flags:
Tracking Status
firefox30 --- unaffected
firefox31 --- unaffected
firefox32 --- fixed
firefox-esr24 --- unaffected
b2g-v1.3 --- unaffected
b2g-v1.4 --- unaffected
b2g-v2.0 --- fixed

People

(Reporter: KWierso, Assigned: drno)

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

increase_ended_envet_timeout.patch
1.01 KB, patch
Details | Diff | Splinter Review 
https://tbpl.mozilla.org/php/getParsedLog.php?id=39838079&tree=B2g-Inbound
b2g_emulator_vm b2g-inbound debug test mochitest-debug-10 on 2014-05-16 12:01:35 PDT for push 71fdd20c93bd

slave: tst-linux64-spot-232



12:15:12     INFO -  8 INFO TEST-START | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html
12:15:12     INFO -  [Child 725] WARNING: Transparent content with displayports can be expensive.: file ../../../gecko/layout/base/nsDisplayList.cpp, line 1349
12:15:12     INFO -  [Child 725] WARNING: Transparent content with displayports can be expensive.: file ../../../gecko/layout/base/nsDisplayList.cpp, line 1349
12:15:14     INFO -  [Child 725] WARNING: Transparent content with displayports can be expensive.: file ../../../gecko/layout/base/nsDisplayList.cpp, line 1349
12:15:14     INFO -  [Parent 667] WARNING: Already have a paint with this sequence number: file ../../dist/include/mozilla/layers/APZTestData.h, line 50
12:15:14     INFO -  [Child 725] WARNING: Transparent content with displayports can be expensive.: file ../../../gecko/layout/base/nsDisplayList.cpp, line 1349
12:15:14     INFO -  [Parent 667] WARNING: Already have a paint with this sequence number: file ../../dist/include/mozilla/layers/APZTestData.h, line 50
12:15:14     INFO -  TEST DEVICES: No test devices found (in media.{audio,video}_loopback_dev, using fake streams.
12:15:15     INFO -  [Child 725] WARNING: Transparent content with displayports can be expensive.: file ../../../gecko/layout/base/nsDisplayList.cpp, line 1349
12:15:15     INFO -  [Parent 667] WARNING: Already have a paint with this sequence number: file ../../dist/include/mozilla/layers/APZTestData.h, line 50
12:15:15     INFO -  [Child 725] WARNING: Transparent content with displayports can be expensive.: file ../../../gecko/layout/base/nsDisplayList.cpp, line 1349
12:15:15     INFO -  [Child 725] WARNING: Transparent content with displayports can be expensive.: file ../../../gecko/layout/base/nsDisplayList.cpp, line 1349
12:15:15     INFO -  [Parent 667] WARNING: Already have a paint with this sequence number: file ../../dist/include/mozilla/layers/APZTestData.h, line 50
12:15:29     INFO -  [Parent 667] WARNING: A control runnable was posted to a worker that is already shutting down!: file ../../../gecko/dom/workers/WorkerPrivate.cpp, line 2239
12:15:29     INFO -  [Parent 667] WARNING: A control runnable was posted to a worker that is already shutting down!: file ../../../gecko/dom/workers/WorkerPrivate.cpp, line 2239
12:15:29     INFO -  [Parent 667] WARNING: A control runnable was posted to a worker that is already shutting down!: file ../../../gecko/dom/workers/WorkerPrivate.cpp, line 2239
12:15:29     INFO -  [Parent 667] WARNING: A control runnable was posted to a worker that is already shutting down!: file ../../../gecko/dom/workers/WorkerPrivate.cpp, line 2239
12:15:29     INFO -  [Parent 667] WARNING: A control runnable was posted to a worker that is already shutting down!: file ../../../gecko/dom/workers/WorkerPrivate.cpp, line 2239
12:15:29     INFO -  [Parent 667] WARNING: A control runnable was posted to a worker that is already shutting down!: file ../../../gecko/dom/workers/WorkerPrivate.cpp, line 2239
12:15:29     INFO -  9 INFO TEST-INFO | dumping last 14 message(s)
12:15:29     INFO -  10 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test
12:15:29     INFO -  11 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | Call getUserMedia for {"audio":true,"fake":true}
12:15:29     INFO -  12 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | Stream should be a LocalMediaStream
12:15:29     INFO -  13 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | Before starting the media element, currentTime = 0
12:15:29     INFO -  14 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | Media element should be playing
12:15:29     INFO -  15 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | Duration should be infinity
12:15:29     INFO -  16 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | Ready state shall be HAVE_ENOUGH_DATA or HAVE_CURRENT_DATA
12:15:29     INFO -  17 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | Seekable length shall be zero
12:15:29     INFO -  18 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | Buffered length shall be zero
12:15:29     INFO -  19 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | MediaElement is not seekable with MediaStream
12:15:29     INFO -  20 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | Start offset time shall not be a number
12:15:29     INFO -  21 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | Loop shall be false
12:15:29     INFO -  22 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | Preload should not exist
12:15:29     INFO -  23 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | No src should be defined
12:15:29     INFO -  24 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | Current src should still be an empty string
12:15:29     INFO -  25 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | Unexpected callback with = 'ended event never fired' at: ["@http://mochi.test:8888/tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html:33:1",""]
12:15:30     INFO -  26 INFO TEST-INFO | MEMORY STAT vsize after test: 105558016
12:15:30     INFO -  27 INFO TEST-INFO | MEMORY STAT residentFast after test: 51367936
12:15:30     INFO -  28 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 16955920
12:15:30     INFO -  29 INFO TEST-INFO | dumping last 1 message(s)
12:15:30     INFO -  30 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test
12:15:30     INFO -  31 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | ended event successfully fired
12:15:30     INFO -  32 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | [SimpleTest.finish()] this test already called finish!
12:15:30     INFO -  33 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | called finish() multiple times
12:15:32     INFO -  [Child 725] WARNING: Transparent content with displayports can be expensive.: file ../../../gecko/layout/base/nsDisplayList.cpp, line 1349
12:15:33     INFO -  34 INFO TEST-END | /tests/dom/media/tests/mochitest/test_getUserMedia_stopAudioStream.html | finished in 21414ms
Assignee: nobody → drno
The log of the very first failure pretty clearly shows that the missing event just fires right after the test failure. Therefore increasing the timeout should probably fix this for now.

Big question though: why does this start to fail on B2G emu debug builds now?
Attachment #8424979 - Flags: review?(rjesup)
Comment on attachment 8424979 [details] [diff] [review]
increase_ended_envet_timeout.patch

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

::: dom/media/tests/mochitest/mediaStreamPlayback.js
@@ +2,5 @@
>   * License, v. 2.0. If a copy of the MPL was not distributed with this
>   * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
>  
>  const TIMEUPDATE_TIMEOUT_LENGTH = 10000;
> +const ENDED_TIMEOUT_LENGTH = 15000;

Unless there's a reason not to, make that 20 or even 30s.  It either will complete (sooner or later), or it will never complete - so long timeouts are fine.
Attachment #8424979 - Flags: review?(rjesup) → review+
Increased timeout value even further as per jesup's recommendation.

Carrying forward r+=jesup
Attachment #8424979 - Attachment is obsolete: true
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/5db02d29ec3b
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla32
You need to log in before you can comment on or make changes to this bug.