Closed Bug 1054706 Opened 10 years ago Closed 10 years ago

WebRTC mochitests don't test that video actually flows

Categories

(Core :: WebRTC: Audio/Video, defect, P3)

33 Branch
x86
macOS
defect

Tracking

()

RESOLVED FIXED
mozilla41
Tracking Status
firefox41 --- fixed

People

(Reporter: ekr, Assigned: pehrsons)

References

(Blocks 2 open bugs)

Details

(Whiteboard: [webrtc-uplift])

Attachments

(1 file, 7 obsolete files)

See bug 1054704 It seems like two tests are needed here: 1. That they check that actual video exists not just that the timer advances in the video tag. 2. That they check that the stats are nonzero Currently you can have tests which observably fail to display video but still pass.
works for checking video actually has been rendered. Note: requires the element be visible; if it's invisible the mozPaintedFrames doesn't change. Note that for a MediaStream source, it appears that mozPresentedFrames never changes, which may be a separate bug. Keys off the type of stream (audo/video/audiovideo) to decide if it needs to check; if need be we could add further overrides via 'options' (which I plumbed a bit deeper in for more flexibility. Given the need to add 'visible: true' to the tests, I only included a few; for checkin all tests expecting video would need to have it (or we implement an override via options that allows some tests with video to not be visible)
Attachment #8474235 - Flags: review?(drno)
I ran this for > 2 minutes with H.264 failing and it just sits there without reporting failure. This test should wait for perhaps 5-10 seconds for video to flow and then error out. I also notice that VP8 works for like 10-15 seconds before it reports success.
Whiteboard: [webrtc-uplift]
Comment on attachment 8475470 [details] [diff] [review] WIP patch to implement ReplaceTrack backend Wrong bug
Attachment #8475470 - Attachment is obsolete: true
Comment on attachment 8474235 [details] [diff] [review] Test for painted frames to verify video is flowing in webrtc mochitests Review of attachment 8474235 [details] [diff] [review]: ----------------------------------------------------------------- I think there are more tests missing which try to render video, e.g. test_peerConnection_basicAudioVideoCombined.html and test_peerConnection_basicAudioVideoCombined_long.html. And do we know for sure that making the video elements visible is not going to cause problems? I always assumed they are invisible for a good reason. If we make this change we should at least have another bug for tracking why this mozPaintedFrames does not work for hidden video elements. My biggest concern is that this approach relies on setting the type correctly, which itself relies on getAudioTracks() and getVideoTracks() which are know to be timing sensitive. ::: dom/media/tests/mochitest/pc.js @@ +280,4 @@ > this.element = element; > this.canPlayThroughFired = false; > this.timeUpdateFired = false; > this.timePassed = false; this.hasRenderedMedia = false should be declared here for consistency purpose. @@ +305,5 @@ > if(element.mozSrcObject && element.mozSrcObject.currentTime > 0 && > element.currentTime > 0) { > info('time passed for media element ' + elementId); > self.timePassed = true; > + if(expectVideo) { MediaElementChecker's get created for the local gUM stream, as well as for remote streams. Is this really what we want/need here? @@ +313,5 @@ > + } > + } else { > + // XXX punt for now; don't see a good way to find if audio actually played > + // Maybe mozCaptureStream, route to WebAudio? Ugh > + self.hasRenderedMedia = true; My WebAudio frequency analyzer from bug 970729 seems to work since Auroa. So we can probably use that. @@ +341,5 @@ > var elementId = self.element.getAttribute('id'); > info('Analyzing element: ' + elementId); > > + if(self.canPlayThroughFired && self.timeUpdateFired && self.timePassed && > + self.hasRenderedMedia) { What is the difference between timePassed and hasRenderedMedia now? Looks like timePassed gets set on the first callback, but then never gets uses anywhere. So lets removed it if it does not provide more value. @@ +550,5 @@ > } > } > > if (options.is_local) > + this.pcLocal = new PeerConnectionWrapper('pcLocal', options.config_local, options); I like passing in the whole options object then the old solution. But can't we then remove the second argument as we pass the whole options now anyway? @@ +555,5 @@ > else > this.pcLocal = null; > > if (options.is_remote) > + this.pcRemote = new PeerConnectionWrapper('pcRemote', options.config_remote || options.config_local, options); See above. @@ +1547,5 @@ > * > * @param {MediaStream} stream > * Media stream to handle > * @param {string} type > + * The type of media stream ('audio' or 'video' or 'audiovideo') Nice fix. @@ +1568,5 @@ > } > } > > var element = createMediaElement(type, this.label + '_' + side); > + this.mediaCheckers.push(new MediaElementChecker(element, type == "video" || type == "audiovideo")); My only problem with this approach is that the 'type' argument might not reflect the reality, e.g. if video gets requested in the offer but rejected in the answer, this would expect video rendering. attachMedia also gets called from onaddstream() and relies on getAudioTracks() and getVideoTracks() to set the type properly. As the output of these two functions depend on when they get called, this seems to be a brittle approach until these two functions reliable return the expected values.
Attachment #8474235 - Flags: review?(drno) → review-
(In reply to Nils Ohlmeier [:drno] from comment #5) > Comment on attachment 8474235 [details] [diff] [review] > Test for painted frames to verify video is flowing in webrtc mochitests > > Review of attachment 8474235 [details] [diff] [review]: > ----------------------------------------------------------------- > > I think there are more tests missing which try to render video, e.g. > test_peerConnection_basicAudioVideoCombined.html and > test_peerConnection_basicAudioVideoCombined_long.html. I indicated in comment 1 that we'd need to mark all the ones we wanted to test for rendering video (which doesn't have to be all of them, we can also key off the visible attribute). > And do we know for sure that making the video elements visible is not going > to cause problems? I always assumed they are invisible for a good reason. > If we make this change we should at least have another bug for tracking why > this mozPaintedFrames does not work for hidden video elements. I imagine that's actually on purpose, since they haven't painted. I would expect mozPresentedFrames to advance, but given the documentation it's possible I'm mistaken (and in any case it doesn't whether visible or not). Many of the other media tests do show video. It shouldn't be a problem, though it might make tests take longer (and so we may not want to have all tests with video be checked). > My biggest concern is that this approach relies on setting the type > correctly, which itself relies on getAudioTracks() and getVideoTracks() > which are know to be timing sensitive. I thought those were only timing sensitive if you queried them before onaddstream. (i.e. onaddstream is delayed until the expected tracks are all there). See bug 998546. > > ::: dom/media/tests/mochitest/pc.js > @@ +280,4 @@ > > this.element = element; > > this.canPlayThroughFired = false; > > this.timeUpdateFired = false; > > this.timePassed = false; > > this.hasRenderedMedia = false > should be declared here for consistency purpose. ok > @@ +305,5 @@ > > if(element.mozSrcObject && element.mozSrcObject.currentTime > 0 && > > element.currentTime > 0) { > > info('time passed for media element ' + elementId); > > self.timePassed = true; > > + if(expectVideo) { > > MediaElementChecker's get created for the local gUM stream, as well as for > remote streams. Is this really what we want/need here? We want to make sure they render as well (if we expose the <video> element). I think we need to make this "if (expectVideo && element.visible) {", then we can just set the ones we want checked to be visible. Alternatively we could set an "checkVideoRendered" option in the main test, and use that to force the <video> to be visible in pc.js/etc. > @@ +313,5 @@ > > + } > > + } else { > > + // XXX punt for now; don't see a good way to find if audio actually played > > + // Maybe mozCaptureStream, route to WebAudio? Ugh > > + self.hasRenderedMedia = true; > > My WebAudio frequency analyzer from bug 970729 seems to work since Auroa. So > we can probably use that. We can, though that adds a lot of complexity to what's being tested. Doing so for a test or two though is possible. (or again as a test option). > @@ +341,5 @@ > > var elementId = self.element.getAttribute('id'); > > info('Analyzing element: ' + elementId); > > > > + if(self.canPlayThroughFired && self.timeUpdateFired && self.timePassed && > > + self.hasRenderedMedia) { > > What is the difference between timePassed and hasRenderedMedia now? > Looks like timePassed gets set on the first callback, but then never gets > uses anywhere. So lets removed it if it does not provide more value. ok > @@ +550,5 @@ > > } > > } > > > > if (options.is_local) > > + this.pcLocal = new PeerConnectionWrapper('pcLocal', options.config_local, options); > > I like passing in the whole options object then the old solution. > But can't we then remove the second argument as we pass the whole options > now anyway? yes, I think so. > @@ +555,5 @@ > > else > > this.pcLocal = null; > > > > if (options.is_remote) > > + this.pcRemote = new PeerConnectionWrapper('pcRemote', options.config_remote || options.config_local, options); > > See above. > > @@ +1547,5 @@ > > * > > * @param {MediaStream} stream > > * Media stream to handle > > * @param {string} type > > + * The type of media stream ('audio' or 'video' or 'audiovideo') > > Nice fix. > > @@ +1568,5 @@ > > } > > } > > > > var element = createMediaElement(type, this.label + '_' + side); > > + this.mediaCheckers.push(new MediaElementChecker(element, type == "video" || type == "audiovideo")); > > My only problem with this approach is that the 'type' argument might not > reflect the reality, e.g. if video gets requested in the offer but rejected > in the answer, this would expect video rendering. We should know if the test will expect that, and can set visible/checkVideoRendered as needed. Also, isn't 'type' here on the reception side? So that wouldn't be an issue. > attachMedia also gets called from onaddstream() and relies on > getAudioTracks() and getVideoTracks() to set the type properly. As the > output of these two functions depend on when they get called, this seems to > be a brittle approach until these two functions reliable return the expected > values. See also bug 998552 - they're not reliable until onAddStream. Since we're looking after onAddStream, it should be fine.
Attachment #8474235 - Attachment is obsolete: true
tests for video element visibility before checking mozPaintedFrames; green on dom/media/tests/mochitest run
Attachment #8476369 - Attachment is obsolete: true
Comment on attachment 8476965 [details] [diff] [review] Test for painted frames to verify video is flowing in webrtc mochitests Discussed with roc on IRC yesterday as well. We can make more tests have their video visible if we want. Roc wasn't concerned with the overhead, but I don't know we need to do so on all tests (we can try and see how much it extends the runtime). For audio, in a separate bug we could add checking via WebAudio; there appears to be no better way. Other nits addressed per comments above
Attachment #8476965 - Flags: review?(drno)
So the code in general looks OK, but it does not work for me at all on my local system. If I execute the test_peerConnection_basicH264Video.html I see two preview windows, but the receiving windows show just white content. But the test still passes! If I execute the test_peerConnection_basicVideo.html I see two preview windows and the receiving windows rendering the actual video. But in the log output I only see this message: "954 INFO time passed for media element pcLocal_remote_video" In both logs I'm missing the new log message "frames have painted". So something is not working here correct. Randel, can you please have look why this is not working?
Flags: needinfo?(rjesup)
uploaded the wrong version (forgot to fold). This sees painted frames.
Attachment #8476965 - Attachment is obsolete: true
Attachment #8476965 - Flags: review?(drno)
Comment on attachment 8477691 [details] [diff] [review] Test for painted frames to verify video is flowing in webrtc mochitests Review of attachment 8477691 [details] [diff] [review]: ----------------------------------------------------------------- LGTM. Verified verified locally that basicVideo properly counts the frames. basicH264 times out as expected. Only question is if we should add its own timeout to not run for 5min and get a generic test framework timeout. A try run would also be nice to have.
Attachment #8477691 - Flags: review+
Jesup, suggest we land this and my patch from 1054704 together. Maybe do a try run with them together?
Jesup, This patch appears to break on try: 1. Your patch alone fails, as expected. 2. Your patch with my IDR patch fails in some identity issue. 3. With neither patch the run succeeds. https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=0e96f53dc58c Looking back at #1, it actually seems to be the same issue as #2.
(In reply to Eric Rescorla (:ekr) from comment #15) > Jesup, > > This patch appears to break on try: > > 1. Your patch alone fails, as expected. > 2. Your patch with my IDR patch fails in some identity issue. > 3. With neither patch the run succeeds. > https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=0e96f53dc58c > > Looking back at #1, it actually seems to be the same issue as #2. I'd run my own try on this as well: https://tbpl.mozilla.org/?tree=Try&rev=7d8b7dd3607c The orange appears to be an existing low-frequency peerIdentity one which these patches made permafail, but since it's unclear what callback is happening, we'll need to look deeper. Perhaps it can help solve the existing orange.
Flags: needinfo?(rjesup)
is_local and is_remote were both set, so that was messing it up. Works now.
Attachment #8478495 - Flags: review?(drno)
Comment on attachment 8478495 [details] [diff] [review] interdiffs to fix peerIdentity tests Review of attachment 8478495 [details] [diff] [review]: ----------------------------------------------------------------- ::: dom/media/tests/mochitest/pc.js @@ +1366,5 @@ > * @constructor > * @param {string} label > * Description for the peer connection instance > * @param {object} configuration > * Configuration for the peer connection instance documentation is now out of date @@ +1375,1 @@ > this.label = label; this.label = options.label || (local ? 'pcLocal' : 'pcRemote'); or just: this.label = local ? 'pcLocal' : 'pcRemote'; or go big (Nils likes this best): this.configuration = options.config[label] || options.config;
Comment on attachment 8478495 [details] [diff] [review] interdiffs to fix peerIdentity tests Review of attachment 8478495 [details] [diff] [review]: ----------------------------------------------------------------- lgtm ::: dom/media/tests/mochitest/pc.js @@ +1366,5 @@ > * @constructor > * @param {string} label > * Description for the peer connection instance > * @param {object} configuration > * Configuration for the peer connection instance Please update the documentation. @@ +1368,5 @@ > * Description for the peer connection instance > * @param {object} configuration > * Configuration for the peer connection instance > */ > +function PeerConnectionWrapper(label, options, local) { The label and local boolean are redundant information right now. And I'm not a big fan of adding a boolean here as it limits us to two PC's for the future. But lets create a new ticket for fixing this.
Attachment #8478495 - Flags: review?(drno) → review+
Created bug 1058294 for cleaning up PCW's options handling.
See Also: → 1058294
sorry had to back this out for frequent test failures in e10s m3 tests like https://tbpl.mozilla.org/php/getParsedLog.php?id=46747188&tree=Mozilla-Inbound
Is this bug something we should pick up again? FWIW video elements will only go to HAVE_CURRENT_DATA if the data is available. When playing video this means that "loadeddata" will only be emitted after the ImageContainer has actually received a frame. Might be simpler than the mozPaintedFrames we're doing in this bug. I actually see in pc.js that we're waiting until we are not in HAVE_METADATA so might be no need for this bug then?
Flags: needinfo?(rjesup)
Flags: needinfo?(mreavy)
I see a check for HAVE_METADATA here https://dxr.mozilla.org/mozilla-central/source/dom/media/tests/mochitest/pc.js#97 But that is only invoked if someone would call checkForNoMediaFlow, which apparently is nowhere used in our code. All of our tests use checkForMediaFlow https://dxr.mozilla.org/mozilla-central/source/dom/media/tests/mochitest/pc.js#84 as far as I can tell and that one never even looks at the elments readyState, but instead relies on the canplaythrough and timeupdate events. And from what I have seen these events are not reliable. So I think it is still worth trying to improve this.
Agree it's worth trying to improve this; we're not testing in the right way.
Rank: 35
Flags: needinfo?(mreavy)
Priority: -- → P3
See Also: → 1162639
/r/8645 - Bug 1054706 - Check for ready state HAVE_ENOUGH_DATA when checking media flow. r=drno,jesup Pull down this commit: hg pull -r a7388cf9b6ad5c9e522db0ff5ff44c39d3aace56 https://reviewboard-hg.mozilla.org/gecko/
Attachment #8605060 - Flags: review?(rjesup)
Attachment #8605060 - Flags: review?(drno)
Attachment #8477691 - Attachment is obsolete: true
Attachment #8478495 - Attachment is obsolete: true
Comment on attachment 8605060 [details] MozReview Request: bz://1054706/pehrsons This removes the whole media element state checker and setInterval() stuff. Instead I check for HAVE_ENOUGH_DATA in the "timeupdate" callback. This ensures that time is progressing at the time of the check, that the stream has data/is not blocked at the time of the check, and that, in case of video, a frame has been set on the associated ImageContainer. Try push here: https://treeherder.mozilla.org/#/jobs?repo=try&revision=5602da053ccf Reveals a number of failures, at least on Mac 10.10. (Only local audio, always stuck in HAVE_METADATA it seems) Any ideas around these failures are much appreciated.
Comment on attachment 8605060 [details] MozReview Request: bz://1054706/pehrsons https://reviewboard.mozilla.org/r/8643/#review7397 ::: dom/media/tests/mochitest/pc.js (Diff revision 1) > -var wait = (time) => new Promise(r => setTimeout(r, time)); I think you went a little over board here :-) This wait Promise is actually used by timerGuard() and is used in a few places. That might explain some strange test failures. ::: dom/media/tests/mochitest/pc.js:1463 (Diff revision 1) > - return Promise.all(this.mediaCheckers.map(checker => checker.waitForMediaFlow())); > + return Promise.all(this.mediaElements.map(element => new Promise(y => { > + info("Analyzing element: " + element.id); > + var oldState = null; > + element.ontimeupdate = () => { > + if (element.readyState != oldState) { > + info("Element " + element.id + " is in ready state " + element.readyState); > + oldState = element.readyState; > + } > + if (element.readyState == element.HAVE_ENOUGH_DATA) { > + element.ontimeupdate = null; > + ok(true, "Media flowing for element: " + element.id); > + y(); Please, please, pretty please no single or two letter variables or references in our code. I find that it makes searching through the code really hard. As this might get called pretty late I'm wondering if a scenario could be that ontimeupdate gets called right away/only once with HAVE_ENOUGH_DATA and therefore pass immediately. Is that intentional?
Attachment #8605060 - Flags: review?(drno)
https://reviewboard.mozilla.org/r/8643/#review7407 > I think you went a little over board here :-) > > This wait Promise is actually used by timerGuard() and is used in a few places. That might explain some strange test failures. Won't it be using the `wait` from head.js though? And I didn't see any strange test failures because of a missing `wait`. Which tests are using `timerGuard`? > Please, please, pretty please no single or two letter variables or references in our code. I find that it makes searching through the code really hard. > > As this might get called pretty late I'm wondering if a scenario could be that ontimeupdate gets called right away/only once with HAVE_ENOUGH_DATA and therefore pass immediately. Is that intentional? Sure, I'll fix that :-) If you mean "right away" as in "right away after `checkMediaFlowPresent` was called" then yes, it's intentional. With the old code we'd end up in a state where any subsequent `checkMediaFlowPresent()` would resolve immediately (because time had progressed _at some point_, etc.). Now we know that the stream is still going any time we `checkMediaFlowPresent()`. test_peerConnection_replaceTrack.html has such subsequent calls, for instance.
Attachment #8605060 - Flags: review?(drno)
Comment on attachment 8605060 [details] MozReview Request: bz://1054706/pehrsons I'm going to defer to nils on this one
Flags: needinfo?(rjesup)
Attachment #8605060 - Flags: review?(rjesup)
Attachment #8605060 - Flags: review?(rjesup)
Comment on attachment 8605060 [details] MozReview Request: bz://1054706/pehrsons /r/8645 - Bug 1054706 - Check for ready state HAVE_ENOUGH_DATA when checking media flow. r=drno Pull down this commit: hg pull -r 985ad7aea63c0876d26bc7b94f1c815f634fbe7a https://reviewboard-hg.mozilla.org/gecko/
Comment on attachment 8605060 [details] MozReview Request: bz://1054706/pehrsons /r/8645 - Bug 1054706 - Check for ready state HAVE_ENOUGH_DATA when checking media flow. r=drno Pull down this commit: hg pull -r 985ad7aea63c0876d26bc7b94f1c815f634fbe7a https://reviewboard-hg.mozilla.org/gecko/
Attachment #8605060 - Flags: review?(rjesup)
backlog: --- → webRTC+
Attachment #8605060 - Flags: review?(drno) → review+
Comment on attachment 8605060 [details] MozReview Request: bz://1054706/pehrsons https://reviewboard.mozilla.org/r/8643/#review7567 Besides the test oranges: ship it! :-) ::: dom/media/tests/mochitest/pc.js:1468 (Diff revision 2) > + if (element.readyState == element.HAVE_ENOUGH_DATA) { While looking into the test oranges I found this: https://dxr.mozilla.org/mozilla-central/source/dom/html/HTMLMediaElement.cpp#3587 Is it possible that the HAVE_ENOUGH_DATA state is expressing exactly the same thing as the canPlayThrough event?
(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #27) > Reveals a number of failures, at least on Mac 10.10. (Only local audio, > always stuck in HAVE_METADATA it seems) > > Any ideas around these failures are much appreciated. After briefly looking at https://dxr.mozilla.org/mozilla-central/source/dom/html/HTMLMediaElement.cpp#3587 I'm starting to wonder if the logic for calculating canPlayThrough is basically not intended for the use case local-fake-source -> local-media-player?
(In reply to Nils Ohlmeier [:drno] from comment #33) > Comment on attachment 8605060 [details] > MozReview Request: bz://1054706/pehrsons > > https://reviewboard.mozilla.org/r/8643/#review7567 > > Besides the test oranges: ship it! :-) > > ::: dom/media/tests/mochitest/pc.js:1468 > (Diff revision 2) > > + if (element.readyState == element.HAVE_ENOUGH_DATA) { > > While looking into the test oranges I found this: > > https://dxr.mozilla.org/mozilla-central/source/dom/html/HTMLMediaElement. > cpp#3587 > > Is it possible that the HAVE_ENOUGH_DATA state is expressing exactly the > same thing as the canPlayThrough event? In our implementation, perhaps. Though "canplaythrough" is not even defined for streams: http://www.w3.org/TR/2015/WD-mediacapture-streams-20150414/ But based on your observation it seems like the failing tests had received a video frame, had seen HAVE_ENOUGH_DATA (canplaythrough), and had seen time progress, at some point. The biggest change here is that we're actually checking these things when the method is called instead of "did it ever happen?". Time is still progressing, but it seems like we're stuck in HAVE_NOTHING. Does the stream sometimes stop prematurely on mac only? Could it be the fake stream generator not generating data?
(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #35) > In our implementation, perhaps. Though "canplaythrough" is not even defined > for streams: http://www.w3.org/TR/2015/WD-mediacapture-streams-20150414/ Thank you very much for pointing that out! I always asked what "canplaythrough" for a stream with no predefined end is actually suppose to mean, but never got a satisfying answer :-) > But based on your observation it seems like the failing tests had received a > video frame, had seen HAVE_ENOUGH_DATA (canplaythrough), and had seen time > progress, at some point. The biggest change here is that we're actually > checking these things when the method is called instead of "did it ever > happen?". Time is still progressing, but it seems like we're stuck in > HAVE_NOTHING. Does the stream sometimes stop prematurely on mac only? Could > it be the fake stream generator not generating data? So from looking at the oranges in your test run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=5602da053ccf It looks to me like: - it is always the local stream which is stuck, the remote side of the same stream is reported to do fine - it is always audio which seems to be stuck - and it is always stuck in HAVE_CURRENT_DATA (=2) - I don't see HAVE_NOTHING (=0) any where Because it is a local stream only, and the far end always seem to be happy I think we could a) simply ignore the local streams or b) accept HAVE_CURRENT_DATA as a valid state, as we really care about the far end. But that would still leave the question unanswered what is causing this? I think we should get next a failing run with NSPR log nsMediaElement set to 9.
(In reply to Nils Ohlmeier [:drno] from comment #36) > So from looking at the oranges in your test run: > https://treeherder.mozilla.org/#/jobs?repo=try&revision=5602da053ccf > It looks to me like: > - it is always the local stream which is stuck, the remote side of the same > stream is reported to do fine > - it is always audio which seems to be stuck > - and it is always stuck in HAVE_CURRENT_DATA (=2) - I don't see > HAVE_NOTHING (=0) any where > > Because it is a local stream only, and the far end always seem to be happy I > think we could a) simply ignore the local streams or b) accept > HAVE_CURRENT_DATA as a valid state, as we really care about the far end. But > that would still leave the question unanswered what is causing this? > > I think we should get next a failing run with NSPR log nsMediaElement set to > 9. Yeah, I see the same thing. HAVE_CURRENT_DATA is not a valid state in the MediaStream spec, but then our HTMLMediaElement is not 100% conforming to that spec (and I don't know how it will develop over time, backwards compatibility, etc.). Knowing that code fairly well, I can boil that HAVE_CURRENT_DATA (it means the same as HAVE_NOTHING in this case, specwise) state down to being set at [1] by [2]. Hence, the stream is blocked (or at least that's what the media element thinks. I'll modify the test slightly to see whether time is progressing continuously or not. Perhaps this new WatchTarget thing is causing issues. About NSPR logs, do you know how to set them up for a run on try? [1] https://dxr.mozilla.org/mozilla-central/source/dom/html/HTMLMediaElement.cpp#3564 > if (NextFrameStatus() != MediaDecoderOwner::NEXT_FRAME_AVAILABLE) { > ChangeReadyState(nsIDOMHTMLMediaElement::HAVE_CURRENT_DATA); [2] https://dxr.mozilla.org/mozilla-central/source/dom/html/HTMLMediaElement.cpp#2867 > MediaDecoderOwner::NextFrameStatus NextFrameStatus() > { > if (!mElement || !mHaveCurrentData) { > return MediaDecoderOwner::NEXT_FRAME_UNAVAILABLE; > } > return mBlocked ? MediaDecoderOwner::NEXT_FRAME_UNAVAILABLE_BUFFERING > : MediaDecoderOwner::NEXT_FRAME_AVAILABLE; > }
Flags: needinfo?(drno)
I think I know what's going on here now (semi-reproducible locally). Look at this: > 777 INFO 'timeupdate' seen for element pcRemote_local1_audio, currentTime=2.043877551020408s, readyState=2 > 778 INFO 'canplay' seen for element pcRemote_local1_audio, readyState=4 > 779 INFO 'timeupdate' seen for element pcRemote_local1_audio, currentTime=2.123877551020408s, readyState=2 > 780 INFO 'canplay' seen for element pcRemote_local1_audio, readyState=4 > 781 INFO 'timeupdate' seen for element pcRemote_local1_audio, currentTime=2.1638775510204082s, readyState=2 > 782 INFO 'canplay' seen for element pcRemote_local1_audio, readyState=4 > 783 INFO 'timeupdate' seen for element pcRemote_local1_audio, currentTime=2.2438775510204083s, readyState=2 > 784 INFO 'canplay' seen for element pcRemote_local1_audio, readyState=4 > 785 INFO 'timeupdate' seen for element pcRemote_local1_audio, currentTime=2.3238775510204084s, readyState=2 > 786 INFO 'canplay' seen for element pcRemote_local1_audio, readyState=4 > 787 INFO 'timeupdate' seen for element pcRemote_local1_audio, currentTime=2.403877551020408s, readyState=2 > 788 INFO 'canplay' seen for element pcRemote_local1_audio, readyState=4 > 789 INFO 'timeupdate' seen for element pcRemote_local1_audio, currentTime=2.483877551020408s, readyState=2 > 790 INFO 'canplay' seen for element pcRemote_local1_audio, readyState=4 > 791 INFO 'timeupdate' seen for element pcRemote_local1_audio, currentTime=2.563877551020408s, readyState=2 > 792 INFO 'canplay' seen for element pcRemote_local1_audio, readyState=4 The stream is flicking very fast between blocked and unblocked :s Also to add, I had a second look at the MediaStream spec. "canplaythrough" is not mentioned, but clearly no other events either. Kinda suggests that events should work as originally specified, though I'd claim "canplaythrough" doesn't make any sense for streams. Looking at how to solve this, I'll let MediaStreamGraph's behavior just pass by, since padenot is throwing out blocking anyway (padenot, FYI - interesting MSG behavior). A combination of "timeupdate" and "canplay" (or perhaps "playing") handlers sounds good to me. It'll still improve the situation from the old code by testing that there is flow *now*. And we should still also look for flow in getStats, per comment 0.
Flags: needinfo?(padenot)
Assignee: nobody → pehrsons
Status: NEW → ASSIGNED
Attachment #8605060 - Flags: review+ → review?(drno)
Comment on attachment 8605060 [details] MozReview Request: bz://1054706/pehrsons /r/8645 - Bug 1054706 - Check for ready state HAVE_ENOUGH_DATA when checking media flow. r=drno Pull down this commit: hg pull -r f371d7775a7c59bb37ce1319688865f63ac8cb91 https://reviewboard-hg.mozilla.org/gecko/
yep, MediaStream behaviour in respect to HTMLMediaElement is not properly specced. Thanks for the heads up.
Flags: needinfo?(padenot)
Comment on attachment 8605060 [details] MozReview Request: bz://1054706/pehrsons https://reviewboard.mozilla.org/r/8643/#review7893 Ship It!
Attachment #8605060 - Flags: review?(drno) → review+
Attachment #8605060 - Flags: review?(jib)
Attachment #8605060 - Flags: review?(drno)
Attachment #8605060 - Flags: review+
Comment on attachment 8605060 [details] MozReview Request: bz://1054706/pehrsons /r/8645 - Bug 1054706 - Check media elements for HAVE_ENOUGH_DATA and tracks for transmitted rtpPackets when checking media flow. r=drno,jib Pull down this commit: hg pull -r cc199cb2c2fe9a465f63d49018f5bf050c5c77f4 https://reviewboard-hg.mozilla.org/gecko/
Ok, I patched it up to also test that each sent/received track sees rtp flow over its peerconnection. The patches got a bit tangled up so I squashed them into one. r? jib for test_peerConnection_capturedVideo.html.
Comment on attachment 8605060 [details] MozReview Request: bz://1054706/pehrsons https://reviewboard.mozilla.org/r/8643/#review7933 I'd like to see it again if you decide to add a getReceivers() polyfill. test_peerConnection_capturedVideo.html lgtm, but drno, if you could take a look as well that would be great (I don't know all the corners of attachMedia()). ::: dom/media/tests/mochitest/pc.js:1470 (Diff revision 4) > + if (!seenEnoughData) { You wouldn't need this if statement if this listener removed itself. ::: dom/media/tests/mochitest/pc.js:1510 (Diff revision 4) > + .find(obj => obj.type === (outbound ? "outboundrtp" : "inboundrtp")); == ::: dom/media/tests/mochitest/pc.js:1513 (Diff revision 4) > + return nrPackets> 0; space ::: dom/media/tests/mochitest/pc.js:1509 (Diff revision 4) > + .map(key => stats[key]) > + .find(obj => obj.type === (outbound ? "outboundrtp" : "inboundrtp")); This seems like an expensive alias for: .find(key => stats[key].type == (outbound ? "outboundrtp" : "inboundrtp")); ::: dom/media/tests/mochitest/pc.js:1502 (Diff revision 4) > + waitForRtpFlow(rtpSenderOrReceiver, outbound) { > + var track = rtpSenderOrReceiver.track; Why not pass in track instead? ::: dom/media/tests/mochitest/pc.js:1547 (Diff revision 4) > + this._pc.getReceivers().map(receiver => this.waitForRtpFlow(receiver, false)))); FYI, receivers aren't implemented yet, so getReceivers() always returns [] right now. Since waitForRtpFlow only looks at .track, you can probably polyfill it here for now. ::: dom/media/tests/mochitest/pc.js:1468 (Diff revision 4) > + var seenEnoughData = false; The name threw me about when it turns true. why not haveEnoughData? ::: dom/media/tests/mochitest/pc.js:1526 (Diff revision 4) > + } else { > + // Check again, soonish. > + inputElement.addEventListener("timeupdate", ontimeupdate); > + } you can remove this else-statement if you move removal to right before resolve(). Seems simpler.
Attachment #8605060 - Flags: review?(jib)
Comment on attachment 8605060 [details] MozReview Request: bz://1054706/pehrsons https://reviewboard.mozilla.org/r/8643/#review7973 ::: dom/media/tests/mochitest/templates.js:449 (Diff revision 4) > function PC_LOCAL_CHECK_MEDIA_FLOW_PRESENT(test) { > - return test.pcLocal.checkMediaFlowPresent(); > + return test.pcLocal.waitForMediaFlow(); As the function calls only one function I think it would make sense to rename both. ::: dom/media/tests/mochitest/templates.js:453 (Diff revision 4) > function PC_REMOTE_CHECK_MEDIA_FLOW_PRESENT(test) { > - return test.pcRemote.checkMediaFlowPresent(); > + return test.pcRemote.waitForMediaFlow(); Same here: rename both ::: dom/media/tests/mochitest/pc.js:1505 (Diff revision 4) > + var inputElement = this.mediaElements[0]; What if mediaElements is empty? ::: dom/media/tests/mochitest/pc.js:1532 (Diff revision 4) > + inputElement.addEventListener("timeupdate", ontimeupdate); Is there any real reason for using the timer of a mediaElement here? Because the inputElement you use here is not connected in any way to the track you are checking here. And in recvonly scenarios the first object in the mediaElements is going to be a remote stream. Not sure if that could cause problems, e.g. what happens if in the pre-recorded video test case the video has ended already? Isn't what you really want to do here is to use an interval timer? ::: dom/media/tests/mochitest/test_peerConnection_capturedVideo.html:26 (Diff revision 4) > - test.setOfferOptions({ offerToReceiveVideo: false, > + test.setMediaConstraints([{video: true, audio: true}], []); Is this on purpose turning this from a sendonly into a sendrecv offer? ::: dom/media/tests/mochitest/test_peerConnection_capturedVideo.html:27 (Diff revision 4) > - offerToReceiveAudio: false }); > + test.chain.replace("PC_LOCAL_GUM", [ Apparently that GUM request wasn't doing anything any how. Nice. ::: dom/media/tests/mochitest/test_peerConnection_capturedVideo.html:32 (Diff revision 4) > - is(stream.getTracks().length, 2, "Captured stream has 2 tracks"); > + test.pcLocal.attachMedia(stream, "audiovideo", "local"); I think it still worth while to keep the stream tracks length check to ensure the captured stream contains what we expect it to. ::: dom/media/tests/mochitest/pc.js:1546 (Diff revision 4) > + this._pc.getSenders().map(sender => this.waitForRtpFlow(sender, true)), > + this._pc.getReceivers().map(receiver => this.waitForRtpFlow(receiver, false)))); With this you make every single test case execution wait for RTCP if I'm not mis-taken. So far we did not do that to limit the test execution time. Jib and I discussed we should have a single, or I guess a few test cases, which would require RTCP to be received, but leave it optional for all other tests. I still think we should do it that way.
Attachment #8605060 - Flags: review?(drno)
(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #37) > About NSPR logs, do you know how to set them up for a run on try? To clear the n-i, but to also record it for the future: There are a couple of build files where our NSPR logging variables get set: https://dxr.mozilla.org/mozilla-central/search?q=mtransport%3A5&case=true&redirect=true Unfortunately I never can remember which file is the correct one. And theoretically at some point in the future one of the file should get removed.
Flags: needinfo?(drno)
https://reviewboard.mozilla.org/r/8643/#review8027 > you can remove this else-statement if you move removal to right before resolve(). Seems simpler. What if we get "timeupdate" events faster than getStats() resolves (i.e., on a very slow machine). Or do you think that will never be a problem? > FYI, receivers aren't implemented yet, so getReceivers() always returns [] right now. > > Since waitForRtpFlow only looks at .track, you can probably polyfill it here for now. Can we leave it as is and I can implement getReceivers as a follow-up? This is not regressing any tests, we are testing new stuff that were just untested before. This way, when getReceivers gets implemented, we won't risk overseeing removing the polyfill.
Attachment #8605060 - Flags: review?(jib)
Attachment #8605060 - Flags: review?(drno)
Comment on attachment 8605060 [details] MozReview Request: bz://1054706/pehrsons /r/8645 - Bug 1054706 - Check media elements for HAVE_ENOUGH_DATA and tracks for transmitted rtpPackets when checking media flow. r=drno,jib Pull down this commit: hg pull -r 0fb05cd43a289e6223f6d6dbdd93d13fb144938f https://reviewboard-hg.mozilla.org/gecko/
https://reviewboard.mozilla.org/r/8643/#review8029 > With this you make every single test case execution wait for RTCP if I'm not mis-taken. So far we did not do that to limit the test execution time. > Jib and I discussed we should have a single, or I guess a few test cases, which would require RTCP to be received, but leave it optional for all other tests. I still think we should do it that way. I'm not checking for RTCP in the test, but are you saying the RTP stats dependant on RTCP packets arriving? I did note that the RTCP stats took a long time to arrive. Sometimes they were not even present in the first iteration of waitForRtpFlow, but they would also be stuck at 0 for a second or two before being updated. Likewise they'd be stuck at some number for a few seconds before being updated again, etc. I'm not sure how this is setup internally but I had planned to include waiting for RTCP stats (would simplify the code slightly) but ended up taking it out. RTP stats seemed fast and was generally available on the first iteration (at the size of ~10 packets). I could add a config option to test for RTCP flow in a follow-up bug? > As the function calls only one function I think it would make sense to rename both. While we're in this file. I see that we're waiting for media flow first, then checking sanity of stats. Is there a reason for this order or could we swap them to maybe gain some speed? (I also noted that there's a checkAllTrackStats() much later in the templates that seems a bit redundant with the stats check. And uh, PC_LOCAL_CHECK_STATS returns its promise while PC_REMOTE_CHECK_STATS does not. Is this on purpose?) > Is this on purpose turning this from a sendonly into a sendrecv offer? No, I thought these were equivalent. I can revert the setOfferOptions(), if that turns it back to sendonly? > I think it still worth while to keep the stream tracks length check to ensure the captured stream contains what we expect it to. I thought this would happen later in the chain, but it appears not. > Is there any real reason for using the timer of a mediaElement here? > Because the inputElement you use here is not connected in any way to the track you are checking here. And in recvonly scenarios the first object in the mediaElements is going to be a remote stream. Not sure if that could cause problems, e.g. what happens if in the pre-recorded video test case the video has ended already? > Isn't what you really want to do here is to use an interval timer? No, it's just an attempt at evading the shameful setTimeout()/setInterval(). :-) All tests should have a mediaElement if it has tracks (capturedVideo.html didn't, but it was slightly bastardous, now this is perhaps a bit bastardous instead). How does the "timeupdate" event react to high load compared to setInterval? I believe "timeupdate" will be better in this case, with longer intervals between updates if the machine has a lot to do on main thread. setInterval would still try to keep up, no? You have a good point with the stream ending though. With mozCaptureStreamUntilEnded() being used in capturedVideo.html that is entirely possible. > What if mediaElements is empty? See below.
Comment on attachment 8605060 [details] MozReview Request: bz://1054706/pehrsons https://reviewboard.mozilla.org/r/8643/#review8049 ::: dom/media/tests/mochitest/pc.js:1526 (Diff revision 4) > + } else { > + // Check again, soonish. > + inputElement.addEventListener("timeupdate", ontimeupdate); > + } Good point there. Yes this might be a problem on B2G emulator. I also never questioned why you were using timerupdate here, which I should have. I think I'd prefer a simpler setTimeout here (not setInterval) over using timeupdate from unrelated media elements (that can stop).
(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #50) > > Is this on purpose turning this from a sendonly into a sendrecv offer? > > No, I thought these were equivalent. I can revert the setOfferOptions(), if > that turns it back to sendonly? Thanks Nils for catching this! Since this is one of the few sendonly tests in the tree, we might want to preserve that. Sorry for not catching it.
https://reviewboard.mozilla.org/r/8643/#review8051 ::: dom/media/tests/mochitest/pc.js:1485 (Diff revisions 4 - 5) > element.removeEventListener("canplay", oncanplay); You're removing "canplay" twice now. ::: dom/media/tests/mochitest/pc.js:1510 (Diff revisions 4 - 5) > var hasFlow = stats => { > - var rtpStats = Object.keys(stats) > - .map(key => stats[key]) > - .find(obj => obj.type === (outbound ? "outboundrtp" : "inboundrtp")); > - var nrPackets = rtpStats[outbound ? "packetsSent" : "packetsReceived"]; > - info("Track " + track.id + " has transmitted " + nrPackets + " RTP packets"); > - return nrPackets> 0; > + var rtpStatsKey = Object.keys(stats) > + .find(key => stats[key].type == (outbound ? "outboundrtp" : "inboundrtp")); > + var nrPackets = stats[rtpStatsKey][outbound ? "packetsSent" : "packetsReceived"]; > + info("Track " + track.id + " has " + (outbound ? "sent " : "received ") + > + nrPackets + " RTP packets"); > + return nrPackets > 0; > }; On looking at this again, I think you're inadvertently picking up rtcp data here as well as rtp data. Both are stored in the same type of structure (see [1]) and you need to test for !stats[key].isRemote to make sure it's rtp and not rtcp (in the opposite direction). [1] http://stackoverflow.com/questions/29800010/can-someone-comprehensively-explain-the-webrtc-stats-api/29840886#29840886
https://reviewboard.mozilla.org/r/8643/#review8291 > On looking at this again, I think you're inadvertently picking up rtcp data here as well as rtp data. Both are stored in the same type of structure (see [1]) and you need to test for > > !stats[key].isRemote > > to make sure it's rtp and not rtcp (in the opposite direction). > > [1] http://stackoverflow.com/questions/29800010/can-someone-comprehensively-explain-the-webrtc-stats-api/29840886#29840886 Can there be multiple outboundrtp for a single track? I was under the impression that for a given track we only have rtp one way, and only rtcp the other way. So for an outbound track "outboundrtp" is rtp, and "inboundrtp" is rtcp (with isRemote = true). I added a test `is(stats[rtpStatsKey].isRemote, false, "")` that seems to support this. I'll take your hint though, and modify the test to check for !isRemote while skipping the `outbound` parameter.
https://reviewboard.mozilla.org/r/8643/#review8295 > No, it's just an attempt at evading the shameful setTimeout()/setInterval(). :-) > > All tests should have a mediaElement if it has tracks (capturedVideo.html didn't, but it was slightly bastardous, now this is perhaps a bit bastardous instead). > > How does the "timeupdate" event react to high load compared to setInterval? I believe "timeupdate" will be better in this case, with longer intervals between updates if the machine has a lot to do on main thread. setInterval would still try to keep up, no? > > You have a good point with the stream ending though. With mozCaptureStreamUntilEnded() being used in capturedVideo.html that is entirely possible. Marking fixed, see jib's review below.
Bug 1054706 - Check media elements for HAVE_ENOUGH_DATA and tracks for transmitted rtpPackets when checking media flow. r=drno,jib
(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #54) > Can there be multiple outboundrtp for a single track? > > I was under the impression that for a given track we only have rtp one way, > and only rtcp the other way. So for an outbound track "outboundrtp" is rtp, > and "inboundrtp" is rtcp (with isRemote = true). I added a test > `is(stats[rtpStatsKey].isRemote, false, "")` that seems to support this. Good point. > I'll take your hint though, and modify the test to check for !isRemote while > skipping the `outbound` parameter. wfm, rtp is rtp.
https://reviewboard.mozilla.org/r/8643/#review8465 > I'm not checking for RTCP in the test, but are you saying the RTP stats dependant on RTCP packets arriving? > > I did note that the RTCP stats took a long time to arrive. Sometimes they were not even present in the first iteration of waitForRtpFlow, but they would also be stuck at 0 for a second or two before being updated. Likewise they'd be stuck at some number for a few seconds before being updated again, etc. I'm not sure how this is setup internally but I had planned to include waiting for RTCP stats (would simplify the code slightly) but ended up taking it out. RTP stats seemed fast and was generally available on the first iteration (at the size of ~10 packets). > > I could add a config option to test for RTCP flow in a follow-up bug? Sorry I got mislead by the fact that you call getStats() for detecting a media flow. But I guess your are using only the outgoing stats here, and do not depend on the RTCP feedback from the far end. I'm not sure if we have already one bug report sitting around for implementing more thorough RTCP verification. But it probably can't hurt to file one just in case (and mark one as duplicate if we find that there are multiples ones). > While we're in this file. I see that we're waiting for media flow first, then checking sanity of stats. Is there a reason for this order or could we swap them to maybe gain some speed? > > (I also noted that there's a checkAllTrackStats() much later in the templates that seems a bit redundant with the stats check. And uh, PC_LOCAL_CHECK_STATS returns its promise while PC_REMOTE_CHECK_STATS does not. Is this on purpose?) From my perspective: all just naturally grown = feel free to re-factor as much as you want :-) As media flow detection and the stats sanity checks both depend on the stats now, maybe it makes even sense to merge them into one? checkAllTrackStats is probably being called so late to be "sure" that media had time to flow. And yes it has overlap with the two others, but probably does a little bit more. Not sure if it is worth merging them into one big thing. Yes the return vs no return looks like a bug to me. And I just noticed that functions for checkAllTrackStats and checkStats are named identical. A cleanup of that mess would be appreciated :-) > No, I thought these were equivalent. I can revert the setOfferOptions(), if that turns it back to sendonly? As jib pointed out I think it would be better to keep this as sendonly.
(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #56) > Created attachment 8612100 [details] > MozReview Request: Bug 1054706 - Check media elements for HAVE_ENOUGH_DATA > and tracks for transmitted rtpPackets when checking media flow. r=drno,jib > > Bug 1054706 - Check media elements for HAVE_ENOUGH_DATA and tracks for > transmitted rtpPackets when checking media flow. r=drno,jib Just double checking: I think the default behavior in review board changed to remove all previous reviewers if you push updated code to the review. So you removed jib and me from reviews here and this is left with no reviewers. Was/Is that intentional? :)
Comment on attachment 8612100 [details] MozReview Request: Bug 1054706 - Check media elements for HAVE_ENOUGH_DATA and tracks for transmitted rtpPackets when checking media flow. r=drno,jib Bug 1054706 - Check media elements for HAVE_ENOUGH_DATA and tracks for transmitted rtpPackets when checking media flow. r=drno,jib
Attachment #8612100 - Flags: review?(jib)
Attachment #8612100 - Flags: review?(drno)
(In reply to Nils Ohlmeier [:drno] from comment #59) > (In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #56) > > Created attachment 8612100 [details] > > MozReview Request: Bug 1054706 - Check media elements for HAVE_ENOUGH_DATA > > and tracks for transmitted rtpPackets when checking media flow. r=drno,jib > > > > Bug 1054706 - Check media elements for HAVE_ENOUGH_DATA and tracks for > > transmitted rtpPackets when checking media flow. r=drno,jib > > Just double checking: I think the default behavior in review board changed > to remove all previous reviewers if you push updated code to the review. So > you removed jib and me from reviews here and this is left with no reviewers. > Was/Is that intentional? :) Not intended, thanks for noticing!
Comment on attachment 8612100 [details] MozReview Request: Bug 1054706 - Check media elements for HAVE_ENOUGH_DATA and tracks for transmitted rtpPackets when checking media flow. r=drno,jib https://reviewboard.mozilla.org/r/8645/#review8525 Ship It!
Attachment #8612100 - Flags: review?(jib) → review+
(In reply to Nils Ohlmeier [:drno] from comment #59) > Just double checking: I think the default behavior in review board changed > to remove all previous reviewers if you push updated code to the review. I think (hope) this only happens with reviewers who have previously said "Ship it", to better support the multiple-reviewers workflow and the ship-it-with-these-nits workflow. (I recently got 10 review-requests from Review Board just from someone landing their already-reviewed patch-set, so I think this is an improvement).
Blocks: 1171338
Blocks: 1171340
Comment on attachment 8612100 [details] MozReview Request: Bug 1054706 - Check media elements for HAVE_ENOUGH_DATA and tracks for transmitted rtpPackets when checking media flow. r=drno,jib https://reviewboard.mozilla.org/r/8645/#review8921 Ship It!
Attachment #8612100 - Flags: review?(drno) → review+
Attachment #8605060 - Flags: review?(drno)
Target Milestone: mozilla34 → ---
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla41
Attachment #8605060 - Attachment is obsolete: true
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: