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)

x86
Windows 7
defect
Not set
normal

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)

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()
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
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()
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: nobody → pehrsons
Status: NEW → ASSIGNED
Attachment #8530856 - Flags: review?(cpearce)
Attachment #8530856 - Attachment description: bug1105126-1 → Do not handle canplay more than once
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 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-
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+
Try looks good. Some oranges but they're all bug 1106698 (surfacing with the bug 879717 patches).
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/6466fd09ff13
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla37
You need to log in before you can comment on or make changes to this bug.