Closed Bug 750258 Opened 11 years ago Closed 9 years ago

Intermittent test_streams_element_capture.html,test_streams_element_capture_createObjectURL.html | {seek.webm|small-shot.ogg|detodos.opus|r11025_s16_c1.wav|320x240.ogv} checking readyState - got 4, expected 2

Categories

(Core :: Audio/Video, defect)

Product:
Core
Component:
Audio/Video
Version:
15 Branch
Platform:
x86
Windows XP
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
VERIFIED FIXED
Milestone:
mozilla33
Tracking Flags:
Tracking Status
firefox31 --- fixed
firefox32 --- fixed
firefox33 --- fixed
firefox-esr24 --- wontfix
b2g-v1.3 --- wontfix
b2g-v1.3T --- wontfix
b2g-v1.4 --- wontfix
b2g-v2.0 --- fixed
b2g-v2.1 --- fixed

People

(Reporter: emorley, Assigned: roc)

References

Details

(Keywords: intermittent-failure)

Attachments

(8 files, 2 obsolete files)

testcase
458 bytes, text/html
Details
fix v2
5.19 KB, patch
jesup
: review+
Details | Diff | Splinter Review
Small cleanup to make it more obvious why mCurrentTime is initialized to 1
1.17 KB, patch
jesup
: review+
Details | Diff | Splinter Review
additional fix
1.23 KB, patch
cpearce
: review+
Details | Diff | Splinter Review
fix? v2
4.29 KB, patch
jesup
: review+
cpearce
: review+
Details | Diff | Splinter Review
750258_fix_stream_NotifyBlockingChanged-v1.patch
3.29 KB, patch
roc
: review+
Details | Diff | Splinter Review
750258_fix_stream_NotifyBlockingChanged-aurora.patch
3.29 KB, patch
jwwang
: review+
Sylvestre
: approval-mozilla-aurora+
Details | Diff | Splinter Review
750258_fix_stream_NotifyBlockingChanged-beta.patch
3.29 KB, patch
jwwang
: review+
Sylvestre
: approval-mozilla-beta+
Details | Diff | Splinter Review 
Rev3 WINNT 5.1 mozilla-inbound debug test mochitests-1/5 on 2012-04-29 22:31:12 PDT for push 57cc1577f951

slave: talos-r3-xp-030

https://tbpl.mozilla.org/?tree=Mozilla-Inbound&rev=57cc1577f951
https://tbpl.mozilla.org/php/getParsedLog.php?id=11316672&tree=Mozilla-Inbound#error0

{
93789 INFO TEST-PASS | /tests/content/media/test/test_streams_element_capture.html | r11025_s16_c1.wav set output element .src correctly - [object MediaStream @ 0x11138188 (native @ 0x118f5ea8)] should equal [object MediaStream @ 0x11138188 (native @ 0x118f5ea8)]
--DOCSHELL 11FD4DA0 == 9 [id = 564]
--DOCSHELL 11901588 == 8 [id = 565]
93790 INFO TEST-PASS | /tests/content/media/test/test_streams_element_capture.html | small-shot.ogg stream final currentTime - 0.48459625244140625 should equal 0.48459625244140625
93791 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_streams_element_capture.html | small-shot.ogg current time at end: 0.48459625244140625 should be: 0.276
93792 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_streams_element_capture.html | small-shot.ogg checking readyState - got 4, expected 2
93793 INFO TEST-PASS | /tests/content/media/test/test_streams_element_capture.html | small-shot.ogg checking playback has ended
93794 INFO TEST-PASS | /tests/content/media/test/test_streams_element_capture.html | [finished small-shot.ogg-0] Length of array should match number of running tests - 1 should equal 1
93795 INFO TEST-PASS | /tests/content/media/test/test_streams_element_capture.html | [started 320x240.ogv-2] Length of array should match number of running tests - 2 should equal 2
}
Attached file testcase — 
This lets me reproduce it on trunk.
Assignee: nobody → roc
Attached patch fix (obsolete) — — Splinter Review 
This fixes my testcase for me. Hopefully it'll fix tinderbox tests too.
Attachment #620602 - Flags: review?(rjesup)
Comment on attachment 620602 [details] [diff] [review]
fix

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

I agree this will resolve the orange.

I'm slightly concerned there might be an interaction with something external which doesn't know about the underrun - the delta time in the graph may not match the delta time in the rest of the system.  But this is just a "hmmm, I wonder if anyone could be bitten by this", and I really can't know without a better understanding of the interactions possible due to this.   If this is solely internal, and not exposed even indirectly, the issue is moot.  Even if it is in some manner visible (including indirectly by something assuming that if X time has passed that the Graph has advanced by X), then some additional analysis may be useful.  (I'm particularly sensitive to realtime playback and transmission issues, since pausing has much more impact there - on an underrun, instead of effectively adding delay, you probably should throw away the data that didn't meet the timeline.)

The patch comment is on the long side, though I'm actually usually a fan of detailed commit notices - but with our fairly strong bugzilla usage, most of that can be in bugzilla instead. :-)

r+ to this as an orange fix, but please noodle the issues above and if warranted file a bug for future work on it, or note here that it's not needed.
Attachment #620602 - Flags: review?(rjesup) → review+
Actually I think you've convinced me that instead of doing this, we should add extra blocked time to all the streams. Currently that amounts to the same thing, but it will let future stream observers observe what's happened more accurately.
Attached patch fix v2 — — Splinter Review 

        Attachment #620602 -
        Attachment is obsolete: true

        Attachment #621004 -
        Flags: review?(rjesup)

    
    

    
  
Running that test file locally with the patch, things are much better, but I still see occasional cases where the data played through the MediaStream is shorter than the actual media resource. This seems to be a completely different bug. In nsBuiltinDecoderStateMachine::DecodeLoop, between mReader->DecodeAudioData() and SendOutputStreamData() the audioloop thread can run, play audio and empty mAudioQueue, causing audio data to be removed before SendOutputStreamData can get to it. This is a little strange since media elements captured to a MediaStream aren't supposed to be running the audioloop thread...

    
    

    
      
  

    
    

    
      
  

        Attachment #621004 -
        Flags: review?(rjesup) → review+

    
    

    
      
  

    
    

    
  

      
      
      
      

        Attached patch
          
          
        additional fix
        — 
          — Splinter Review
      

    


  

        Attachment #621493 -
        Flags: review?(cpearce)

    
    

    
  
With this additional fix, the testcase in comment #8 can run indefinitely and always returns the correct duration and readyState.

        Attachment #621493 -
        Flags: review?(cpearce) → review+

        Attachment #621491 -
        Flags: review?(rjesup) → review+

    
    

    
      
  

    
  
Status: RESOLVED → REOPENED
Resolution: FIXED → ---

    
    

    
      
  

    
    

    
  
https://hg.mozilla.org/mozilla-central/rev/718e334e4d99

(Was the same push on which the comment 26 failure occurred)

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  
Curiously, all the Linux failures are on 320x240.ogv. The only Mac failure is on small-shot.ogg, and curiously that's on the Oak branch.

    
    

    
  
Pounding on the testcase of comment #8 with 320x240.ogv doesn't ever fail on my Windows laptop.

    
    

    
  
Note, the failures after my checkins here are different from before. Now the durations are always correct, it's only the readyState that's wrong.

    
    

    
  
I have a theory about this now. A media element playing a source stream starts in HAVE_ENOUGH_DATA state (because ResourceLoaded is called immediately by SetupMediaStreamPlayback). However, the stream could be initially blocked. We could then go through an iteration of the MediaStreamGraph control loop which plays the entire content of the stream, finishes the stream, and returns it to the blocked state. Because the initial and final state of the stream was blocked, we wouldn't fire a NotifyBlockingChanged, so DoNotifyBlocked would never get called to call UpdateReadyStateForData to set the readyState to HAVE_CURRENT_DATA.

    
    

    
  

      
      
      
      

        Attached patch
          
          
        fix? (obsolete)
        — 
          — Splinter Review
      

    


  
This might fix it.

        Attachment #626396 -
        Flags: review?(rjesup)

    
    

    
  
Comment on attachment 626396 [details] [diff] [review]
fix?

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

::: content/html/content/src/nsHTMLMediaElement.cpp
@@ +2529,5 @@
> +  // Ensure that ResourceLoaded below won't take us to HAVE_ENOUGH_DATA.
> +  // Having attached our listener, we expect a DoNotifyBlocked or
> +  // DoNotifyUnblocked event to change our readyState to HAVE_CURRENT_DATA or
> +  // HAVE_ENOUGH_DATA.
> +  ChangeReadyState(nsIDOMHTMLMediaElement::HAVE_NOTHING);

Doesn't this mean that the "loadedmetadata" event can arrive before readyState is greater than or equal to HAVE_METADATA? That seems wrong...

    
    

    
  

      
      
      
      

        Attached patch
          
          
        fix? v2
        — 
          — Splinter Review
      

    


  

        Attachment #626396 -
        Attachment is obsolete: true

        Attachment #626396 -
        Flags: review?(rjesup)

        Attachment #626396 -
        Flags: review?(cpearce)

        Attachment #626671 -
        Flags: review?(rjesup)

    
    

    
  
Comment on attachment 626671 [details] [diff] [review]
fix? v2

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

::: content/html/content/src/nsHTMLMediaElement.cpp
@@ +2644,5 @@
>    mBegun = false;
>    mNetworkState = nsIDOMHTMLMediaElement::NETWORK_IDLE;
>    AddRemoveSelfReference();
>    if (mReadyState >= nsIDOMHTMLMediaElement::HAVE_METADATA) {
> +    // MediaStream sources  are put into HAVE_CURRENT_DATA state here on setup. If the

s/sources  are/sources are/

        Attachment #626671 -
        Flags: review?(cpearce) → review+

        Attachment #626671 -
        Flags: review?(rjesup) → review-

        Attachment #626671 -
        Flags: review- → review+

    
    

    
      
  

    
    

    
  
So apparently this patch didn't fix the bug :-(.
Whiteboard: [orange] → [orange][leave open]

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  
Summary: Intermittent media/test/test_streams_element_capture.html | small-shot.ogg current time at end: 0.48459625244140625 should be: 0.276 | small-shot.ogg checking readyState - got 4, expected 2 → Intermittent media/test/test_streams_element_capture.html | small-shot.ogg current time at end: 0.48459625244140625 should be: 0.276 | small-shot.ogg checking readyState - got 4, expected 2, detodos.opus checking readyState - got 4, expected 2

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  
Summary: Intermittent media/test/test_streams_element_capture.html | small-shot.ogg current time at end: 0.48459625244140625 should be: 0.276 | small-shot.ogg checking readyState - got 4, expected 2, detodos.opus checking readyState - got 4, expected 2 → Intermittent media/test/test_streams_element_capture.html | small-shot.ogg current time at end: 0.48459625244140625 should be: 0.276 | {small-shot.ogg|detodos.opus|r11025_s16_c1.wav} checking readyState - got 4, expected 2

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
  
Whiteboard: [orange][leave open] → [orange]
Target Milestone: mozilla15 → ---

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  
Whiteboard: [orange]

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
  
Summary: Intermittent media/test/test_streams_element_capture.html | small-shot.ogg current time at end: 0.48459625244140625 should be: 0.276 | {small-shot.ogg|detodos.opus|r11025_s16_c1.wav} checking readyState - got 4, expected 2 → Intermittent media/test/test_streams_element_capture.html | small-shot.ogg current time at end: 0.48459625244140625 should be: 0.276 | {seek.webm|small-shot.ogg|detodos.opus|r11025_s16_c1.wav} checking readyState - got 4, expected 2

    
    

    
      
  

    
    

    
      
  

    
    

    
  
roc, any chance you could take another look at this long-running orange?
Flags: needinfo?(roc)

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
      
  

    
    

    
  
The fixing of bug 938022 may help.
Flags: needinfo?(roc)