Intermittent dom/media/test/test_mediarecorder_record_timeslice.html | onstop unexpectedly fired before ondataavailable

RESOLVED FIXED in Firefox 52

Status

()

Core
Audio/Video: Recording
P1
normal
Rank:
18
RESOLVED FIXED
a year ago
3 months ago

People

(Reporter: Treeherder Bug Filer, Assigned: pehrsons)

Tracking

({intermittent-failure})

unspecified
mozilla52
intermittent-failure
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox50 unaffected, firefox51 unaffected, firefox52 fixed)

Details

MozReview Requests

()

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(2 attachments)

Updated

a year ago
Component: Audio/Video → Audio/Video: Recording

Updated

a year ago
Rank: 35
Priority: -- → P3

Comment 1

a year ago
8 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* try: 6
* mozilla-inbound: 1
* autoland: 1

Platform breakdown:
* windows7-32-vm: 8

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1304950&startday=2016-09-19&endday=2016-09-25&tree=all

Comment 2

a year ago
28 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* try: 22
* autoland: 4
* mozilla-inbound: 2

Platform breakdown:
* windows7-32-vm: 28

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1304950&startday=2016-09-26&endday=2016-10-02&tree=all

Comment 3

a year ago
31 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* try: 22
* mozilla-inbound: 4
* mozilla-central: 2
* fx-team: 2
* autoland: 1

Platform breakdown:
* windows7-32-vm: 31

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1304950&startday=2016-10-03&endday=2016-10-09&tree=all
Assignee: nobody → pehrson
Status: NEW → ASSIGNED
This looks like MediaRecorder stops because the stream ends before we call stop() - and the first blob then contains all the data.

I'm trying to figure out if this is wrong given that the media resource is ~0.6 seconds long and we request a timeslice of 0.25s.

To make the test fully deterministic we could change it to take a MediaStream from either gUM or canvas capture rather than media element capture.
Blocks: 1284102
Rank: 35 → 18
Priority: P3 → P1
Here's a log with detailed timestamps. Notice how it takes less than 0.2 seconds to finish recording everything (from Start to ExtractRunnable with shutdown=1), even though the source is more than 0.6 seconds long. (and the finished recording is only 0.57527s long, so some data goes missing somewhere)

The quick recording is probably direct listeners at play.

The missing data I'm not so sure about.

> 05:46:45     INFO -  549 INFO TEST-START | dom/media/test/test_mediarecorder_record_timeslice.html
> 05:46:45     INFO -  550 INFO TEST-PASS | dom/media/test/test_mediarecorder_record_timeslice.html | [started detodos-recorder-test.opus-0 t=0.013] Length of array should match number of running tests
> 05:46:45     INFO -  2016-10-12 12:46:45.425000 UTC - [Main Thread]: D/MediaRecorder MediaRecorder.Start b5b91c0
> 05:46:45     INFO -  2016-10-12 12:46:45.425000 UTC - [Main Thread]: D/MediaRecorder Session.Start d5fe0f0
> 05:46:45     INFO -  551 INFO TEST-PASS | dom/media/test/test_mediarecorder_record_timeslice.html | Media recorder should be recording
> 05:46:45     INFO -  552 INFO TEST-PASS | dom/media/test/test_mediarecorder_record_timeslice.html | Media recorder stream = element stream at the start of recording
> 05:46:45     INFO -  2016-10-12 12:46:45.450000 UTC - [Main Thread]: D/MediaRecorder Session.NotifyTracksAvailable track type = (1)
> 05:46:45     INFO -  2016-10-12 12:46:45.450000 UTC - [Main Thread]: D/MediaRecorder Session.InitEncoder d5fe0f0
> 05:46:45     INFO -  2016-10-12 12:46:45.450000 UTC - [Media_Encoder]: D/MediaRecorder Session.ExtractRunnable shutdown = 0
> 05:46:45     INFO -  2016-10-12 12:46:45.450000 UTC - [Media_Encoder]: D/MediaRecorder Session.Extract d5fe0f0
> 05:46:45     INFO -  2016-10-12 12:46:45.641000 UTC - [Main Thread]: D/MediaRecorder Session.DispatchStartEventRunnable s=(d5fe0f0)
> 05:46:45     INFO -  2016-10-12 12:46:45.642000 UTC - [Media_Encoder]: D/MediaRecorder Session.ExtractRunnable shutdown = 0
> 05:46:45     INFO -  2016-10-12 12:46:45.642000 UTC - [Media_Encoder]: D/MediaRecorder Session.Extract d5fe0f0
> 05:46:45     INFO -  2016-10-12 12:46:45.642000 UTC - [Media_Encoder]: D/MediaRecorder Session.ExtractRunnable shutdown = 1
> 05:46:45     INFO -  2016-10-12 12:46:45.642000 UTC - [Media_Encoder]: D/MediaRecorder Session.Extract d5fe0f0
> 05:46:45     INFO -  2016-10-12 12:46:45.642000 UTC - [Main Thread]: D/MediaRecorder Session.ErrorNotifyRunnable s=(d5fe0f0)
> 05:46:45     INFO -  2016-10-12 12:46:45.642000 UTC - [Main Thread]: D/MediaRecorder Session.PushBlobRunnable s=(d5fe0f0)
> 05:46:45     INFO -  553 INFO ondataavailable fired
> 05:46:45     INFO -  554 INFO TEST-PASS | dom/media/test/test_mediarecorder_record_timeslice.html | Events fired from ondataavailable should be BlobEvent
> 05:46:45     INFO -  555 INFO TEST-PASS | dom/media/test/test_mediarecorder_record_timeslice.html | Event type should dataavailable
> 05:46:45     INFO -  556 INFO TEST-PASS | dom/media/test/test_mediarecorder_record_timeslice.html | Blob data size received is greater than or equal to zero
> 05:46:45     INFO -  557 INFO TEST-PASS | dom/media/test/test_mediarecorder_record_timeslice.html | Blob data received should have type = audio/ogg
> 05:46:45     INFO -  558 INFO TEST-PASS | dom/media/test/test_mediarecorder_record_timeslice.html | Mime type in ondataavailable = audio/ogg
> 05:46:45     INFO -  2016-10-12 12:46:45.643000 UTC - [Main Thread]: D/MediaRecorder MediaRecorder.Stop b5b91c0
> 05:46:45     INFO -  2016-10-12 12:46:45.643000 UTC - [Main Thread]: D/MediaRecorder Session.Stop d5fe0f0
> 05:46:45     INFO -  559 INFO TEST-PASS | dom/media/test/test_mediarecorder_record_timeslice.html | Media recorder is inactive after being stopped
> 05:46:45     INFO -  560 INFO TEST-PASS | dom/media/test/test_mediarecorder_record_timeslice.html | Media recorder stream = element stream post recording
> 05:46:45     INFO -  2016-10-12 12:46:45.644000 UTC - [Main Thread]: D/MediaRecorder Session.DestroyRunnable session refcnt = (3) stopIssued 1 s=(d5fe0f0)
> 05:46:45     INFO -  561 INFO onstop fired
> 05:46:45     INFO -  TEST-INFO | started process screenshot
> 05:46:45     INFO -  TEST-INFO | screenshot: exit 0
> 05:46:45     INFO -  562 INFO TEST-PASS | dom/media/test/test_mediarecorder_record_timeslice.html | A valid string reason is expected
> 05:46:45     INFO -  563 INFO TEST-PASS | dom/media/test/test_mediarecorder_record_timeslice.html | Reason cannot be empty
> 05:46:45     INFO -  564 INFO Started Wed Oct 12 2016 05:46:45 GMT-0700 (Pacific Standard Time) (1476276405.411s)
> 05:46:45     INFO -  565 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_mediarecorder_record_timeslice.html | onstop unexpectedly fired before ondataavailable
> 05:46:45     INFO -      startTest/element.onloadedmetadata/mediaRecorder.ondataavailable/mediaRecorder.onstop@dom/media/test/test_mediarecorder_record_timeslice.html:79:13
> 05:46:45     INFO -      EventHandlerNonNull*startTest/element.onloadedmetadata/mediaRecorder.ondataavailable@dom/media/test/test_mediarecorder_record_timeslice.html:75:9
> 05:46:45     INFO -      EventHandlerNonNull*startTest/element.onloadedmetadata@dom/media/test/test_mediarecorder_record_timeslice.html:55:5
> 05:46:45     INFO -      EventHandlerNonNull*startTest@dom/media/test/test_mediarecorder_record_timeslice.html:33:3
> 05:46:45     INFO -      MediaTestManager/this.nextTest@dom/media/test/manifest.js:1661:7
> 05:46:45     INFO -      MediaTestManager/this.runTests/<@dom/media/test/manifest.js:1598:7
> 05:46:45     INFO -  2016-10-12 12:46:45.646000 UTC - [Main Thread]: D/MediaRecorder MediaRecorder.RemoveSession (d5fe0f0)
> 05:46:45     INFO -  566 INFO Recording has duration 0.57527s
> 05:46:45     INFO -  567 INFO [finished detodos-recorder-test.opus-0] remaining=
> 05:46:45     INFO -  568 INFO TEST-PASS | dom/media/test/test_mediarecorder_record_timeslice.html | [finished detodos-recorder-test.opus-0 t=0.239] Length of array should match number of running tests
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 9

a year ago
mozreview-review
Comment on attachment 8800329 [details]
Bug 1304950 - Defer mozCaptureStream() until after "loadedmetadata".

https://reviewboard.mozilla.org/r/84898/#review83970
Attachment #8800329 - Flags: review?(jwwang) → review+

Comment 10

a year ago
mozreview-review
Comment on attachment 8800330 [details]
Bug 1304950 - Reduce timeslice to avoid races with the source ending.

https://reviewboard.mozilla.org/r/85250/#review83972
Attachment #8800330 - Flags: review?(jwwang) → review+
(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #6)
> Seems to have worked with a shorter timeslice (to counteract the quick
> pushed-ahead recording).
> 
> Here's with 50ms:
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=00cc6f89ef12131099133c14ccfe922319df82e8
> Here's with 1ms:
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=454ecf8f711b7bb6fa065d3be63d0864b1d11cea

Does that mean the user might fail to record the 1st few milliseconds of the stream in the real case when default slice=250ms is used?
(In reply to JW Wang [:jwwang] [:jw_wang] from comment #11)
> (In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #6)
> > Seems to have worked with a shorter timeslice (to counteract the quick
> > pushed-ahead recording).
> > 
> > Here's with 50ms:
> > https://treeherder.mozilla.org/#/
> > jobs?repo=try&revision=00cc6f89ef12131099133c14ccfe922319df82e8
> > Here's with 1ms:
> > https://treeherder.mozilla.org/#/
> > jobs?repo=try&revision=454ecf8f711b7bb6fa065d3be63d0864b1d11cea
> 
> Does that mean the user might fail to record the 1st few milliseconds of the
> stream in the real case when default slice=250ms is used?

I don't think the timeslice matters. I also don't know the details of this failure mode but I take it for most likely that we miss the data in the beginning.

For a realtime stream it's not a biggie -- what is "the beginning" of that anyway? It becomes more evident with media element capture though.

Comment 13

a year ago
Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/db8173b81d33
Defer mozCaptureStream() until after "loadedmetadata". r=jwwang
https://hg.mozilla.org/integration/autoland/rev/7480f3d08b18
Reduce timeslice to avoid races with the source ending. r=jwwang

Comment 14

a year ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/db8173b81d33
https://hg.mozilla.org/mozilla-central/rev/7480f3d08b18
Status: ASSIGNED → RESOLVED
Last Resolved: a year ago
status-firefox52: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla52
status-firefox50: --- → unaffected
status-firefox51: --- → unaffected
17 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* try: 15
* mozilla-inbound: 1
* fx-team: 1

Platform breakdown:
* windows7-32-vm: 17

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1304950&startday=2016-10-10&endday=2016-10-16&tree=all
7 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* try: 7

Platform breakdown:
* windows7-32-vm: 7

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1304950&startday=2016-10-17&endday=2016-10-23&tree=all

Comment 17

3 months ago
1 failures in 824 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* try: 1

Platform breakdown:
* linux64-qr: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1304950&startday=2017-10-02&endday=2017-10-08&tree=all
You need to log in before you can comment on or make changes to this bug.