Closed Bug 1411152 Opened 7 years ago Closed 5 years ago

Intermittent dom/media/test/test_mediarecorder_record_timeslice.html | Mime type in ondataavailable = - got "", expected "audio/ogg"

Categories

(Core :: Audio/Video: Recording, defect, P2)

Product:
Core
Component:
Audio/Video: Recording
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla70
Tracking Flags:
Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- wontfix
firefox68 --- wontfix
firefox69 --- wontfix
firefox70 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: pehrsons)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown])

Attachments

(1 file)

Bug 1411152 - Serialize MediaRecorder::Session::GatherBlob calls. r?bryce
47 bytes, text/x-phabricator-request
Details | Review
Rank: 50
Component: Audio/Video → Audio/Video: Recording
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 6 years ago → 6 years ago
Resolution: --- → INCOMPLETE
Recent log failure:
https://treeherder.mozilla.org/logviewer.html#?job_id=204945119&repo=autoland&lineNumber=5690
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
I just hit this locally under rr so I had a look.

MediaRecorder.mimeType is not set in one of the "dataavailable" events.

On the spec it sounds like the mimeType attribute should be set in the ctor. This is about the MediaRecorderOptions.mimeType attribute:
> If this paramater is not specified, the UA will use a platform-specific default format. The container format, whether passed in to the constructor or defaulted, will be used as the value of the mimeType attribute.

In our impl we set the mimeType when we raise the "start" event if not given through MediaRecorderOptions [1], and unset it when we raise the "stop" event.

An implication of fixing this would be that we can no longer make an informed container decision based on the recorded tracks, if given an empty stream where the tracks appear at a later point. With informed decision I'm mostly referring to an audio-only container versus a video one. Currently we record audio/ogg if only given audio to record.

[1] https://searchfox.org/mozilla-central/rev/a7f4d3ba4fbfe3efbde832869f1d672fce7122f6/dom/media/MediaRecorder.cpp#1081
[2] https://searchfox.org/mozilla-central/rev/a7f4d3ba4fbfe3efbde832869f1d672fce7122f6/dom/media/MediaRecorder.cpp#431
Blocks: 1224079
See Also: → 1512175

In the last 7 days, there have been 29 failures.

The failures occur on linux32, linux64 and linux64-qr platforms, debug build type.

An example of a recent log file:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=247167377&repo=autoland&lineNumber=6835

And the relevant part of the log:
task 2019-05-18T07:59:48.707Z] 07:59:48 INFO - TEST-PASS | dom/media/test/test_mediarecorder_record_timeslice.html | Blob data received should have type = audio/ogg
[task 2019-05-18T07:59:48.708Z] 07:59:48 INFO - Buffered messages finished
[task 2019-05-18T07:59:48.711Z] 07:59:48 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_mediarecorder_record_timeslice.html | Mime type in ondataavailable = - got "", expected "audio/ogg"
[task 2019-05-18T07:59:48.712Z] 07:59:48 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:320:16
[task 2019-05-18T07:59:48.712Z] 07:59:48 INFO - startTest/element.onloadedmetadata/mediaRecorder.ondataavailable@dom/media/test/test_mediarecorder_record_timeslice.html:65:7
[task 2019-05-18T07:59:48.714Z] 07:59:48 INFO - EventHandlerNonNullstartTest/element.onloadedmetadata@dom/media/test/test_mediarecorder_record_timeslice.html:52:5
[task 2019-05-18T07:59:48.714Z] 07:59:48 INFO - EventHandlerNonNullstartTest@dom/media/test/test_mediarecorder_record_timeslice.html:30:3
[task 2019-05-18T07:59:48.715Z] 07:59:48 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:1834:12
[task 2019-05-18T07:59:48.716Z] 07:59:48 INFO - MediaTestManager/this.runTests/<@dom/media/test/manifest.js:1754:12
[task 2019-05-18T07:59:48.717Z] 07:59:48 INFO - GECKO(1806) | --DOMWINDOW == 12 (0x7fe1cea76800) [pid = 1889] [serial = 525] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
[task 2019-05-18T07:59:48.717Z] 07:59:48 INFO - GECKO(1806) | --DOMWINDOW == 11 (0x7fe1cea72000) [pid = 1889] [serial = 524] [outer = (nil)] [url = about:blank]
[task 2019-05-18T07:59:48.718Z] 07:59:48 INFO - GECKO(1806) | --DOMWINDOW == 10 (0x7fe1d1a472e0) [pid = 1889] [serial = 523] [outer = (nil)] [url = about:blank]
[task 2019-05-18T07:59:48.747Z] 07:59:48 INFO - GECKO(1806) | --DOMWINDOW == 9 (0x7fe1cea7c400) [pid = 1889] [serial = 527] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
[task 2019-05-18T07:59:48.748Z] 07:59:48 INFO - GECKO(1806) | --DOMWINDOW == 8 (0x7fe1cea77000) [pid = 1889] [serial = 526] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/media/test/test_mediarecorder_record_startstopstart.html]
[task 2019-05-18T07:59:48.749Z] 07:59:48 INFO - GECKO(1806) | --DOMWINDOW == 7 (0x7fe1cea74800) [pid = 1889] [serial = 522] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/media/test/test_mediarecorder_record_session.html]
[task 2019-05-18T07:59:48.766Z] 07:59:48 INFO - Finished at Sat May 18 2019 07:59:48 GMT+0000 (Coordinated Universal Time) (1558166388.762s)
[task 2019-05-18T07:59:48.768Z] 07:59:48 INFO - Running time: 0.915s
[task 2019-05-18T07:59:48.785Z] 07:59:48 INFO - GECKO(1806) | MEMORY STAT | vsize 2696MB | residentFast 167MB | heapAllocated 16MB

Nils, as you are the triage owner of this component, could you please take a look at this?
Thank you!

Flags: needinfo?(drno)
Whiteboard: [stockwell needswork:owner]
Assignee: nobody → apehrson
Blocks: 1514158
Status: REOPENED → ASSIGNED
Rank: 50
Priority: P5 → P2

This is an occurrence of a "dataavailable" event after the "stop" event (illegal by spec). The trigger of this seems to be the really short timeslice this test is using (1ms).

With bug 1514158 the rate of this went up significantly, so I'd like to fix it at the root source to allow bug 1514158 to land.

I have a run there with some logging enabled, and it appears we hit a race like so (not entirely sure about the GatherBlob order):

Contestant 1 Contestant 2
Stop() (main) _
Listeners removed (graph) _
Listener removal processed (encoder) _
NotifyEndOfStream (encoder) (causing the DataAvailable event synchronously) _
_ MediaEncoderDataAvailable (encoder)
_ Extract(false) (encoder)
_ GetEncodedData() (encoder) (causing the Shutdown event asynchronously)
_ (still in Extract) Dispatch(StoreEncodedBufferRunnable()) (encoder)
_ (still in Extract) InvokeAsync(GatherBlob) (encoder)
MediaEncoderShutdown() (encoder) _
Dispatch(DoSessionEndTask(NS_OK)) (encoder) _
_ GatherBlob() (main)
DoSessionEndTask(NS_OK) (main) _
GatherBlob() (main) _
GatherBlob()->Then Dispatch (main) _
_ GatherBlob->Then Dispatch (main)
Dispatch("dataavailable") (main) _
Dispatch("stop") (main) _
_ Dispatch("dataavailable") (main) unexpected!

I have a patch that serializes the underlying storage operations under GatherBlob, since that's where we're racing. Seems to work on try.

Flags: needinfo?(drno)
Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/9ea87d42bca3
Serialize MediaRecorder::Session::GatherBlob calls. r=bryce

https://hg.mozilla.org/mozilla-central/rev/9ea87d42bca3

Status: ASSIGNED → RESOLVED
Closed: 6 years ago → 5 years ago
status-firefox70: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla70

Is this something we can safely backport to ESR68? Looks like we're still occasionally seeing these oranges there.

Flags: needinfo?(apehrson)

No, because it depends on changes in the rather huge bug 1014393. In particular https://hg.mozilla.org/integration/autoland/rev/ba8ce9f1e1b7.

status-firefox-esr68: affected → wontfix
Flags: needinfo?(apehrson)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: