Closed
Bug 1105126
Opened 9 years ago
Closed 9 years ago
Intermittent test_bug686942.html,test_eme_stream_capture_blocked.html | [finished gizmo-frag-cencinit.mp4-1_case2] Length of array should match number of running tests - got -1, expected 0 - Result logged after SimpleTest.finish()
Categories
(Core :: Audio/Video, defect)
Tracking
()
RESOLVED
FIXED
mozilla37
Tracking | Status | |
---|---|---|
firefox35 | --- | unaffected |
firefox36 | --- | fixed |
firefox37 | --- | fixed |
firefox-esr31 | --- | unaffected |
People
(Reporter: RyanVM, Assigned: pehrsons)
References
Details
(Keywords: intermittent-failure)
Attachments
(1 file, 1 obsolete file)
3.34 KB,
patch
|
cpearce
:
review+
|
Details | Diff | Splinter Review |
15:23:35 INFO - 2340 INFO [finished gizmo-frag-cencinit.mp4-1_case3] remaining= gizmo-frag-cencinit.mp4-1_case2 15:23:35 INFO - 2341 INFO TEST-PASS | /tests/dom/media/test/test_eme_stream_capture_blocked.html | [finished gizmo-frag-cencinit.mp4-1_case3] Length of array should match number of running tests 15:23:35 INFO - 2342 INFO [15:23:34.399] gizmo-frag-cencinit.mp4-1_case2 canplay 15:23:35 INFO - 2343 INFO TEST-PASS | /tests/dom/media/test/test_eme_stream_capture_blocked.html | gizmo-frag-cencinit.mp4-1_case2 should reach canplay 15:23:35 INFO - 2344 INFO TEST-PASS | /tests/dom/media/test/test_eme_stream_capture_blocked.html | Should throw an error creating a MediaElementSource on an EME video. 15:23:35 INFO - 2345 INFO [finished gizmo-frag-cencinit.mp4-1_case2] remaining= 15:23:35 INFO - 2346 INFO TEST-PASS | /tests/dom/media/test/test_eme_stream_capture_blocked.html | [finished gizmo-frag-cencinit.mp4-1_case2] Length of array should match number of running tests 15:23:35 INFO - 2347 INFO Finished at Tue Nov 25 2014 15:23:35 GMT-0800 (Pacific Standard Time) (1416957815.335s) 15:23:35 INFO - 2348 INFO Running time: 1.563s 15:23:35 INFO - 2349 INFO MEMORY STAT vsize after test: 1322176512 15:23:35 INFO - 2350 INFO MEMORY STAT vsizeMaxContiguous after test: 417267712 15:23:35 INFO - 2351 INFO MEMORY STAT residentFast after test: 289726464 15:23:35 INFO - 2352 INFO MEMORY STAT heapAllocated after test: 66552930 15:23:35 INFO - 2353 INFO [15:23:35.359] gizmo-frag-cencinit.mp4-1_case2 canplay 15:23:35 INFO - 2354 INFO TEST-PASS | /tests/dom/media/test/test_eme_stream_capture_blocked.html | gizmo-frag-cencinit.mp4-1_case2 should reach canplay 15:23:35 INFO - 2355 INFO TEST-PASS | /tests/dom/media/test/test_eme_stream_capture_blocked.html | Should throw an error creating a MediaElementSource on an EME video. 15:23:35 INFO - 2356 INFO [finished gizmo-frag-cencinit.mp4-1_case2] remaining= 15:23:35 INFO - 2357 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/test/test_eme_stream_capture_blocked.html | [finished gizmo-frag-cencinit.mp4-1_case2] Length of array should match number of running tests - got -1, expected 0 15:23:35 INFO - 2358 INFO TEST-OK | /tests/dom/media/test/test_eme_stream_capture_blocked.html | took 1894ms 15:23:35 INFO - [GMP 1012] WARNING: pipe error: 109: file c:/builds/moz2_slave/m-cen-w32-d-000000000000000000/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 309 15:23:35 INFO - 2359 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/test/test_eme_stream_capture_blocked.html | gizmo-frag-cencinit.mp4-1_case2 should reach canplay - Result logged after SimpleTest.finish() 15:23:35 INFO - 2360 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/test/test_eme_stream_capture_blocked.html | Should throw an error creating a MediaElementSource on an EME video. - Result logged after SimpleTest.finish() 15:23:35 INFO - 2361 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/test/test_eme_stream_capture_blocked.html | [finished gizmo-frag-cencinit.mp4-1_case2] Length of array should match number of running tests - Result logged after SimpleTest.finish()
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Assignee | ||
Comment 5•9 years ago
|
||
I ran into this on mac while writing a patch for bug 879717. With my patches I'm hitting this with ~50% repro rate. The direct cause is that "canplay" is fired multiple times for the video elements in the test. The reason for that is in turn that the MediaDecoder is first reporting (after loadedmetadata) FRAME_AVAILABLE, and then FRAME_UNAVAILABLE, causing the ready state to go from HAVE_FUTURE_DATA to HAVE_CURRENT_DATA, even though no data is consumed. While debugging a bit I found two paths leading to the ready state downgrade. See below. The first looks more interesting, and passes through here: http://dxr.mozilla.org/mozilla-central/source/dom/media/mediasource/SourceBufferDecoder.cpp#222 > // XXX: Params make no sense to parent decoder as it relates to a > // specific SourceBufferDecoder's data stream. Pass bogus values here to > // force parent decoder's state machine to recompute end time for > // infinite length media. > mParentDecoder->NotifyDataArrived(nullptr, 0, 0); 1 ================================== frame #0: 0x00000001030577b7 XUL`mozilla::dom::HTMLMediaElement::ChangeReadyState(this=<unavailable>, aState=<unavailable>) + 695 at HTMLMediaElement.cpp:3271 frame #1: 0x000000010305b2ee XUL`mozilla::dom::HTMLMediaElement::UpdateReadyStateForData(this=0x000000012c6f6400, aNextFrame=NEXT_FRAME_UNAVAILABLE) + 558 at HTMLMediaElement.cpp:3212 * frame #2: 0x00000001031d1300 XUL`mozilla::TrackBuffer::AppendDataToCurrentResource(unsigned char const*, unsigned int) [inlined] nsRefPtr<mozilla::SourceBufferDecoder>::operator->(this=0x000000012d691e70, aBuffer=0x0000000116ca1000, aLength=57143, aOffset=1924) const + 208 at SourceBufferDecoder.cpp:222 frame #3: 0x00000001031d1277 XUL`mozilla::TrackBuffer::AppendDataToCurrentResource(this=0x000000012d688260, aData=0x0000000116ca1000, aLength=57143) + 71 at TrackBuffer.cpp:180 frame #4: 0x00000001031ce237 XUL`mozilla::TrackBuffer::AppendData(this=0x000000012d688260, aData=0x0000000116ca1000, aLength=57143) + 1191 at TrackBuffer.cpp:158 frame #5: 0x00000001031cc7de XUL`mozilla::dom::SourceBuffer::AppendData(this=0x00000001282385e0, aData=0x0000000116ca1000, aLength=57143, aRv=0x00007fff5fbfaa18) + 174 at SourceBuffer.cpp:334 frame #6: 0x0000000102c577fe XUL`mozilla::dom::SourceBufferBinding::appendBuffer(cx=0x00000001255b2850, self=0x00000001282385e0, args=0x00007fff5fbfaae8, obj=<unavailable>) + 638 at SourceBufferBinding.cpp:377 frame #7: 0x0000000102e2d932 XUL`mozilla::dom::GenericBindingMethod(cx=0x00000001255b2850, argc=1, vp=0x000000010eef8090) + 290 at BindingUtils.cpp:2434 frame #8: 0x0000000104de10f2 XUL`js::Invoke(JSContext*, JS::CallArgs, js::MaybeConstruct) [inlined] js::CallJSNative(native=0x0000000102e2d810)(JSContext*, unsigned int, JS::Value*), JS::CallArgs const&) + 166 at jscntxtinlines.h:231 frame #9: 0x0000000104de104c XUL`js::Invoke(cx=0x00000001255b2850, args=CallArgs at 0x00007fff5fbfb060, construct=<unavailable>) + 428 at Interpreter.cpp:482 frame #10: 0x0000000104dfeff9 XUL`Interpret(cx=<unavailable>, state=<unavailable>) + 46073 at Interpreter.cpp:2526 frame #11: 0x0000000104df3bd9 XUL`js::RunScript(cx=0x00000001255b2850, state=0x00007fff5fbfbe98) + 345 at Interpreter.cpp:432 frame #12: 0x0000000104de1194 XUL`js::Invoke(cx=0x00000001255b2850, args=CallArgs at 0x00007fff5fbfbf20, construct=<unavailable>) + 756 at Interpreter.cpp:501 frame #13: 0x0000000104dcb8cc XUL`js::Invoke(cx=0x00000001255b2850, thisv=<unavailable>, fval=<unavailable>, argc=<unavailable>, argv=<unavailable>, rval=<unavailable>) + 844 at Interpreter.cpp:538 frame #14: 0x0000000104c3e856 XUL`JS::Call(cx=0x00000001255b2850, args=0x00007fff5fbfc0f0, thisv=<unavailable>, fval=<unavailable>, rval=<unavailable>) + 230 at jsapi.cpp:4943 frame #15: 0x00000001027646f0 XUL`mozilla::dom::EventListener::HandleEvent(this=<unavailable>, cx=0x00000001255b2850, event=<unavailable>, aRv=0x00007fff5fbfc458, aThisVal=<unavailable>) + 880 at EventListenerBinding.cpp:46 frame #16: 0x0000000102f81ed0 XUL`void mozilla::dom::EventListener::HandleEvent<mozilla::dom::EventTarget*>(this=0x000000012d692850, thisObjPtr=<unavailable>, event=0x000000012f6fcba0, aRv=0x00007fff5fbfc458, aExceptionHandling=<unavailable>) + 624 at EventListenerBinding.h:54 frame #17: 0x0000000102f7fb69 XUL`mozilla::EventListenerManager::HandleEventSubType(this=0x000000012dc9e2c0, aListener=<unavailable>, aDOMEvent=<unavailable>, aCurrentTarget=0x000000012d6d0800) + 185 at EventListenerManager.cpp:960 frame #18: 0x0000000102f80435 XUL`mozilla::EventListenerManager::HandleEventInternal(this=0x000000012dc9e2c0, aPresContext=0x0000000000000000, aEvent=0x000000012f6fcc10, aDOMEvent=0x00007fff5fbfc770, aCurrentTarget=0x000000012d6d0800, aEventStatus=0x00007fff5fbfc778) + 1573 at EventListenerManager.cpp:1110 frame #19: 0x0000000102f81a7f XUL`mozilla::EventTargetChainItem::HandleEvent(mozilla::EventChainPostVisitor&, mozilla::ELMCreationDetector&) [inlined] nsRefPtr<mozilla::EventListenerManager>::operator->(this=0x000000012dc9e2c0, aPresContext=<unavailable>, aEvent=<unavailable>, aDOMEvent=<unavailable>, aCurrentTarget=<unavailable>, aEventStatus=<unavailable>) const + 463 at EventListenerManager.h:329 frame #20: 0x0000000102f81a77 XUL`mozilla::EventTargetChainItem::HandleEvent(this=<unavailable>, aVisitor=0x00007fff5fbfc760, aCd=<unavailable>) + 455 at EventDispatcher.cpp:206 frame #21: 0x0000000102f79632 XUL`mozilla::EventTargetChainItem::HandleEventTargetChain(aChain=0x00007fff5fbfc7e8, aVisitor=0x00007fff5fbfc760, aCallback=0x0000000000000000, aCd=0x00007fff5fbfc7f0) + 546 at EventDispatcher.cpp:299 frame #22: 0x0000000102f7af2f XUL`mozilla::EventDispatcher::Dispatch(aTarget=<unavailable>, aPresContext=0x0000000000000000, aEvent=0x000000012f6fcc10, aDOMEvent=<unavailable>, aEventStatus=0x0000000000000000, aCallback=0x0000000000000000, aTargets=<unavailable>) + 4799 at EventDispatcher.cpp:633 frame #23: 0x0000000102f62243 XUL`mozilla::EventDispatcher::DispatchDOMEvent(aTarget=<unavailable>, aEvent=<unavailable>, aDOMEvent=<unavailable>, aPresContext=<unavailable>, aEventStatus=<unavailable>) + 323 at EventDispatcher.cpp:700 frame #24: 0x00000001024b891b XUL`nsXMLHttpRequest::DispatchProgressEvent(this=0x000000012d6d0800, aTarget=0x000000012d6d0800, aType=<unavailable>, aLengthComputable=true, aLoaded=57143, aTotal=57143) + 491 at nsXMLHttpRequest.cpp:1499 frame #25: 0x00000001024be169 XUL`nsXMLHttpRequest::ChangeStateToDone(this=0x000000012d6d0800) + 185 at nsXMLHttpRequest.cpp:2324 frame #26: 0x00000001024bdde2 XUL`nsXMLHttpRequest::OnStopRequest(this=0x000000012d6d0800, request=<unavailable>, ctxt=<unavailable>, status=<unavailable>) + 1714 at nsXMLHttpRequest.cpp:2304 frame #27: 0x000000010237be7c XUL`nsCORSListenerProxy::OnStopRequest(this=0x000000012dc9e350, aRequest=0x000000012d6af858, aContext=0x0000000000000000, aStatusCode=NS_OK) + 92 at nsCrossSiteListenerProxy.cpp:602 frame #28: 0x000000010185fdf6 XUL`mozilla::net::nsHttpChannel::OnStopRequest(this=0x000000012d6af800, request=<unavailable>, ctxt=<unavailable>, status=<unavailable>) + 2054 at nsHttpChannel.cpp:5528 frame #29: 0x000000010169ff0a XUL`nsInputStreamPump::OnStateStop(this=0x000000012b6172c0) + 346 at nsInputStreamPump.cpp:721 frame #30: 0x000000010169f6ff XUL`nsInputStreamPump::OnInputStreamReady(this=0x000000012b6172c0, stream=<unavailable>) + 303 at nsInputStreamPump.cpp:440 frame #31: 0x00000001015c5b29 XUL`nsInputStreamReadyEvent::Run(this=<unavailable>) + 41 at nsStreamUtils.cpp:88 frame #32: 0x00000001015df94f XUL`nsThread::ProcessNextEvent(this=0x0000000100331310, aMayWait=<unavailable>, aResult=0x00007fff5fbfccd7) + 1487 at nsThread.cpp:830 (...) ================================== 2 ================================== * frame #0: 0x000000010305b44f XUL`mozilla::dom::HTMLMediaElement::UpdateReadyStateForData(this=<unavailable>, aNextFrame=<unavailable>) + 1023 at HTMLMediaElement.cpp:3154 --> Something looks optimized away here frame #1: 0x00000001031815be XUL`mozilla::FirstFrameLoadedEventRunner::Run(this=<unavailable>) + 94 at AbstractMediaDecoder.h:199 frame #2: 0x00000001015df94f XUL`nsThread::ProcessNextEvent(this=0x0000000100331310, aMayWait=<unavailable>, aResult=0x00007fff5fbfccd7) + 1487 at nsThread.cpp:830 frame #3: 0x000000010160cf6f XUL`NS_ProcessPendingEvents(aThread=<unavailable>, aTimeout=20) + 79 at nsThreadUtils.cpp:207 frame #4: 0x00000001036f8f87 XUL`nsBaseAppShell::NativeEventCallback(this=0x0000000110578fc0) + 119 at nsBaseAppShell.cpp:98 frame #5: 0x000000010374f8ae XUL`nsAppShell::ProcessGeckoEvents(aInfo=0x0000000110578fc0) + 190 at nsAppShell.mm:377 (...) ==================================
Blocks: 879717
Reporter | ||
Updated•9 years ago
|
Summary: Intermittent test_eme_stream_capture_blocked.html | [finished gizmo-frag-cencinit.mp4-1_case2] Length of array should match number of running tests - got -1, expected 0 - Result logged after SimpleTest.finish() → Intermittent test_bug686942.html,test_eme_stream_capture_blocked.html | [finished gizmo-frag-cencinit.mp4-1_case2] Length of array should match number of running tests - got -1, expected 0 - Result logged after SimpleTest.finish()
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Assignee | ||
Comment 10•9 years ago
|
||
As a quick fix we can clear the "canplay" handler after the first run. It solves the issues for bug 879717. We could revert the change when the XXX mentioned in comment 5 is fixed. What do you think Chris?
Assignee | ||
Updated•9 years ago
|
Attachment #8530856 -
Attachment description: bug1105126-1 → Do not handle canplay more than once
Comment 11•9 years ago
|
||
Comment on attachment 8530856 [details] [diff] [review] Do not handle canplay more than once Review of attachment 8530856 [details] [diff] [review]: ----------------------------------------------------------------- Can we listen for "loadeddata" instead of "canplay", then we won't need to remove the listener, as "loadeddata" should only fire once.
Comment 12•9 years ago
|
||
Comment on attachment 8530856 [details] [diff] [review] Do not handle canplay more than once Review of attachment 8530856 [details] [diff] [review]: ----------------------------------------------------------------- Please use "loadeddata" if that works; test_eme_canvas_blocked.html switched to that recently, so that might help here too.
Attachment #8530856 -
Flags: review?(cpearce) → review-
Assignee | ||
Comment 13•9 years ago
|
||
Worked locally. Let's see a couple more runs on try: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=b82fade954ab
Attachment #8530856 -
Attachment is obsolete: true
Attachment #8531068 -
Flags: review?(cpearce)
Comment 14•9 years ago
|
||
Comment on attachment 8531068 [details] [diff] [review] Change test_eme_stream_capture_blocked.html to check loadeddata instead of canplay Review of attachment 8531068 [details] [diff] [review]: ----------------------------------------------------------------- Cool, thanks!
Attachment #8531068 -
Flags: review?(cpearce) → review+
Assignee | ||
Comment 15•9 years ago
|
||
Try looks good. Some oranges but they're all bug 1106698 (surfacing with the bug 879717 patches).
Keywords: checkin-needed
Comment 16•9 years ago
|
||
https://hg.mozilla.org/integration/mozilla-inbound/rev/6466fd09ff13
Keywords: checkin-needed
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment 19•9 years ago
|
||
https://hg.mozilla.org/mozilla-central/rev/6466fd09ff13
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla37
Reporter | ||
Updated•9 years ago
|
status-firefox35:
--- → unaffected
status-firefox36:
--- → affected
status-firefox37:
--- → fixed
status-firefox-esr31:
--- → unaffected
Reporter | ||
Comment 20•9 years ago
|
||
https://hg.mozilla.org/releases/mozilla-aurora/rev/9a956a85c086
You need to log in
before you can comment on or make changes to this bug.
Description
•