Closed Bug 901102 Opened 6 years ago Closed 5 years ago

Intermittent B2G test_streams_element_capture_reset.html | Got 0.23333072662353516, expected 0.266; checking vout.currentTime at first 'ended' event | checking vout.currentTime has not changed after seeking | checking vout.currentTime after seeking and...

Categories

(Core :: Audio/Video, defect)

ARM
Gonk (Firefox OS)
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla39
Tracking Status
firefox37 --- wontfix
firefox38 --- wontfix
firefox39 --- fixed
firefox-esr31 --- wontfix
b2g-v2.2 --- wontfix
b2g-master --- fixed

People

(Reporter: RyanVM, Assigned: jwwang)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 1 obsolete file)

I think we've actually been seeing this for about a week now, but nobody's gotten around to filing it :(

https://tbpl.mozilla.org/php/getParsedLog.php?id=26075597&tree=Mozilla-Inbound

b2g_emulator_vm mozilla-inbound opt test mochitest-3 on 2013-08-02 07:18:46 PDT for push 284946982e36
slave: tst-linux64-ec2-434

07:31:21     INFO -  640 INFO TEST-START | /tests/content/media/test/test_streams_element_capture_reset.html
07:31:21     INFO -  System JS : ERROR chrome://specialpowers/content/SpecialPowersObserverAPI.js:183
07:31:21     INFO -                       NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIPrefBranch.getBoolPref]
07:31:21     INFO -  GOT EVENT playing currentTime=0 paused=false ended=false readyState=4
07:31:21     INFO -  GOT EVENT timeupdate currentTime=0.033333 paused=false ended=false readyState=4
07:31:21     INFO -  GOT EVENT timeupdate currentTime=0.166665 paused=false ended=false readyState=4
07:31:21     INFO -  GOT EVENT timeupdate currentTime=0.266664 paused=true ended=true readyState=2
07:31:21     INFO -  GOT EVENT pause currentTime=0.266664 paused=true ended=true readyState=2
07:31:21     INFO -  GOT EVENT timeupdate currentTime=0.266664 paused=true ended=true readyState=2
07:31:21     INFO -  GOT EVENT ended currentTime=0.266664 paused=true ended=true readyState=2
07:31:21     INFO -  641 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_streams_element_capture_reset.html | Got 0.23333072662353516, expected 0.266; checking vout.currentTime at first 'ended' event
07:31:21     INFO -  642 INFO TEST-PASS | /tests/content/media/test/test_streams_element_capture_reset.html | Got 0.266664, expected 0.266; checking v.currentTime at first 'ended' event
07:31:21     INFO -  643 INFO TEST-PASS | /tests/content/media/test/test_streams_element_capture_reset.html | checking vout has not ended
07:31:21     INFO -  644 INFO TEST-PASS | /tests/content/media/test/test_streams_element_capture_reset.html | checking vout_untilended has actually ended
07:31:21     INFO -  GOT EVENT seeking currentTime=0.133 paused=true ended=false readyState=1
07:31:21     INFO -  GOT EVENT timeupdate currentTime=0.133 paused=true ended=false readyState=1
07:31:21     INFO -  GOT EVENT seeked currentTime=0.133 paused=true ended=false readyState=4
07:31:21     INFO -  645 INFO TEST-PASS | /tests/content/media/test/test_streams_element_capture_reset.html | Got 0.133, expected 0.133; Finished seeking
07:31:21     INFO -  646 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_streams_element_capture_reset.html | Got 0.23333072662353516, expected 0.266; checking vout.currentTime has not changed after seeking
07:31:21     INFO -  GOT EVENT playing currentTime=0.133 paused=false ended=false readyState=4
07:31:21     INFO -  GOT EVENT timeupdate currentTime=0.166665 paused=false ended=false readyState=4
07:31:21     INFO -  GOT EVENT timeupdate currentTime=0.266664 paused=true ended=true readyState=2
07:31:21     INFO -  GOT EVENT pause currentTime=0.266664 paused=true ended=true readyState=2
07:31:21     INFO -  GOT EVENT timeupdate currentTime=0.266664 paused=true ended=true readyState=2
07:31:21     INFO -  GOT EVENT ended currentTime=0.266664 paused=true ended=true readyState=2
07:31:21     INFO -  647 INFO TEST-PASS | /tests/content/media/test/test_streams_element_capture_reset.html | Got 0.266664, expected 0.266; checking v.currentTime at second 'ended' event
07:31:21     INFO -  648 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_streams_element_capture_reset.html | Got 0.36699390411376953, expected 0.399664; checking vout.currentTime after seeking and playing through again
07:31:30     INFO -  GOT EVENT timeupdate currentTime=0 paused=false ended=false readyState=0
07:31:30     INFO -  GOT EVENT playing currentTime=0 paused=false ended=false readyState=4
07:31:30     INFO -  GOT EVENT timeupdate currentTime=0.033333 paused=false ended=false readyState=4
07:31:30     INFO -  GOT EVENT timeupdate currentTime=0.266664 paused=true ended=true readyState=2
07:31:30     INFO -  GOT EVENT timeupdate currentTime=0.266664 paused=true ended=true readyState=2
07:31:30     INFO -  GOT EVENT pause currentTime=0.266664 paused=true ended=true readyState=2
07:31:30     INFO -  GOT EVENT timeupdate currentTime=0.266664 paused=true ended=true readyState=2
07:31:30     INFO -  GOT EVENT ended currentTime=0.266664 paused=true ended=true readyState=2
07:31:30     INFO -  649 INFO TEST-PASS | /tests/content/media/test/test_streams_element_capture_reset.html | Got 0.266664, expected 0.266; checking v.currentTime at third 'ended' event
07:31:30     INFO -  650 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_streams_element_capture_reset.html | Got 0.6336574554443359, expected 0.665664; checking vout.currentTime after seeking, playing through and reloading
07:31:30     INFO -  651 INFO TEST-END | /tests/content/media/test/test_streams_element_capture_reset.html | finished in 5205ms
Paul, can you please look into this?
Flags: needinfo?(paul)
Yes.
Assignee: nobody → paul
Flags: needinfo?(paul)
(In reply to Paul Adenot (:padenot) from comment #25)
> Yes.

Any luck with this, Paul? This is one of our top B2G oranges.
Flags: needinfo?(paul)
I haven't been able to find time to debug this, sorry. Maybe someone from Taipei can look into it? I know they are doing stuff in the area.
Flags: needinfo?(paul)
CJ, do you have someone who can look into this?
Flags: needinfo?(cku)
Test disabled on B2G for now:
https://hg.mozilla.org/integration/mozilla-inbound/rev/0671318fb9af

However be aware that content/media/test/* has been disabled on top, in bug 918299 too.
Depends on: 918299
Whiteboard: [test disabled on B2G][leave open]
The time difference between actual and expected is around 0.033, which is approximately 1/30. Therefore, the displaying progress of vout is 1 frame behind.
SC is checking
Flags: needinfo?(cku)
Paul, if you don't have time to fix this one, please assign to slee(@mozilla.com)
Assignee: paul → slee
This bug cannot be reproduced for several months, resolve it as invalid.
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INVALID
Per comment 106, it hasn't reproduced because the test was disabled...
Status: RESOLVED → REOPENED
Resolution: INVALID → ---
Blocks: 1022453
Looks like the status on B2G platforms is good enough to enable the test again.

Try: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=9005a1edfa5c
No failures in test_streams_element_capture_reset.html on B2G platforms.
Attachment #8502277 - Flags: review?(cpearce)
Attachment #8502277 - Flags: review?(cpearce) → review+
Keywords: checkin-needed
Assignee: slee → jwwang
Whiteboard: [test disabled on B2G][leave open]
This patch make it easier to repro the issue by sleeping 100ms after RenderVideoFrame() to simulate the slow B2G emulator.
Attachment #8502277 - Attachment is obsolete: true
Depends on: 1128417
The root cause is bug 1128417 comment 0. In the capture-stream case, the 'ended' event is fired without waiting for audio/video samples to be fully drained. Therefore the end time is smaller than the duration.

When bug 1128417 is fixed, we can ensure the end time is correct when 'ended' event is fired. Then we can fix this test case by waiting for the 'ended' events of v and vout_untilended before comparing the current time.
Attachment #8569669 - Flags: review?(roc)
https://hg.mozilla.org/mozilla-central/rev/e1d56f67becc
Status: REOPENED → RESOLVED
Closed: 6 years ago5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla39
Would be great if we could get this on Aurora and Beta.
Flags: needinfo?(jwwang)
This bug depends on bug 1128417 which depends on bug 1127235 which depends on another 3 bugs. I would rather save the uplift for this bug is not a frequent orange.
Flags: needinfo?(jwwang)
You need to log in before you can comment on or make changes to this bug.