1586328 - Intermittent dom/media/test/test_mediarecorder_record_getdata_afterstart.html | should have had start event first

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

Filed by: nbeleuzu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=269761889&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/K_hfM6mGTV2v7oZrPqdPJA/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/K_hfM6mGTV2v7oZrPqdPJA/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2019-10-04T11:28:12.285Z] 11:28:12 INFO - TEST-PASS | dom/media/test/test_mediarecorder_record_getdata_afterstart.html | Media recorder stream = element stream at the start of recording
[task 2019-10-04T11:28:12.285Z] 11:28:12 INFO - ondataavailable fired successfully
[task 2019-10-04T11:28:12.286Z] 11:28:12 INFO - Buffered messages finished
[task 2019-10-04T11:28:12.287Z] 11:28:12 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_mediarecorder_record_getdata_afterstart.html | should have had start event first
[task 2019-10-04T11:28:12.287Z] 11:28:12 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:277:18
[task 2019-10-04T11:28:12.288Z] 11:28:12 INFO - startTest/mMediaRecorder.ondataavailable@dom/media/test/test_mediarecorder_record_getdata_afterstart.html:57:9
[task 2019-10-04T11:28:12.288Z] 11:28:12 INFO - EventHandlerNonNullstartTest@dom/media/test/test_mediarecorder_record_getdata_afterstart.html:53:3
[task 2019-10-04T11:28:12.288Z] 11:28:12 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:1816:12
[task 2019-10-04T11:28:12.289Z] 11:28:12 INFO - MediaTestManager/this.runTests/<@dom/media/test/manifest.js:1736:12
[task 2019-10-04T11:28:12.290Z] 11:28:12 INFO - AsyncMediaTestManager/this.runTests@dom/media/test/manifest.js:1735:19
[task 2019-10-04T11:28:12.290Z] 11:28:12 INFO - @dom/media/test/test_mediarecorder_record_getdata_afterstart.html:76:9
[task 2019-10-04T11:28:12.290Z] 11:28:12 INFO - TEST-PASS | dom/media/test/test_mediarecorder_record_getdata_afterstart.html | blob's mimeType matches the recorder's
[task 2019-10-04T11:28:12.291Z] 11:28:12 INFO - onstart fired successfully
[task 2019-10-04T11:28:12.292Z] 11:28:12 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-10-04T11:28:12.292Z] 11:28:12 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_mediarecorder_record_getdata_afterstart.html | MediaRecorder mimetype as expected - got "", expected "audio/ogg; codecs=opus"
[task 2019-10-04T11:28:12.293Z] 11:28:12 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-04T11:28:12.293Z] 11:28:12 INFO - startTest/mMediaRecorder.onstart@dom/media/test/test_mediarecorder_record_getdata_afterstart.html:41:7
[task 2019-10-04T11:28:12.293Z] 11:28:12 INFO - EventHandlerNonNullstartTest@dom/media/test/test_mediarecorder_record_getdata_afterstart.html:38:3
[task 2019-10-04T11:28:12.294Z] 11:28:12 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:1816:12
[task 2019-10-04T11:28:12.294Z] 11:28:12 INFO - MediaTestManager/this.runTests/<@dom/media/test/manifest.js:1736:12
[task 2019-10-04T11:28:12.294Z] 11:28:12 INFO - AsyncMediaTestManager/this.runTests@dom/media/test/manifest.js:1735:19
[task 2019-10-04T11:28:12.295Z] 11:28:12 INFO - @dom/media/test/test_mediarecorder_record_getdata_afterstart.html:76:9
[task 2019-10-04T11:28:12.295Z] 11:28:12 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-10-04T11:28:12.297Z] 11:28:12 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_mediarecorder_record_getdata_afterstart.html | uncaught exception - InvalidStateError: The MediaRecorder is inactive at startTest/mMediaRecorder.onstart@http://mochi.test:8888/tests/dom/media/test/test_mediarecorder_record_getdata_afterstart.html:43:20
[task 2019-10-04T11:28:12.297Z] 11:28:12 INFO - EventHandlerNonNullstartTest@http://mochi.test:8888/tests/dom/media/test/test_mediarecorder_record_getdata_afterstart.html:38:3
[task 2019-10-04T11:28:12.297Z] 11:28:12 INFO - MediaTestManager/this.nextTest@http://mochi.test:8888/tests/dom/media/test/manifest.js:1816:12
[task 2019-10-04T11:28:12.297Z] 11:28:12 INFO - MediaTestManager/this.runTests/<@http://mochi.test:8888/tests/dom/media/test/manifest.js:1736:12
[task 2019-10-04T11:28:12.298Z] 11:28:12 INFO - AsyncMediaTestManager/this.runTests@http://mochi.test:8888/tests/dom/media/test/manifest.js:1735:19
[task 2019-10-04T11:28:12.298Z] 11:28:12 INFO - @http://mochi.test:8888/tests/dom/media/test/test_mediarecorder_record_getdata_afterstart.html:76:9
[task 2019-10-04T11:28:12.298Z] 11:28:12 INFO -
[task 2019-10-04T11:28:12.299Z] 11:28:12 INFO - simpletestOnerror@SimpleTest/SimpleTest.js:1667:24
[task 2019-10-04T11:28:12.299Z] 11:28:12 INFO - OnErrorEventHandlerNonNull*@SimpleTest/SimpleTest.js:1647:1
[task 2019-10-04T11:28:12.300Z] 11:28:12 INFO - GECKO(17365) | JavaScript error: http://mochi.test:8888/tests/dom/media/test/test_mediarecorder_record_getdata_afterstart.html, line 43: InvalidStateError: The MediaRecorder is inactive
[task 2019-10-04T11:28:12.301Z] 11:28:12 INFO - Test timed out. Remaining tests=detodos-recorder-test.opus-0
[task 2019-10-04T11:28:12.301Z] 11:28:12 INFO - GECKO(17365) | MEMORY STAT | vsize 2665MB | residentFast 166MB | heapAllocated 28MB
[task 2019-10-04T11:28:12.302Z] 11:28:12 INFO - ondataavailable fired successfully
[task 2019-10-04T11:28:12.302Z] 11:28:12 INFO - TEST-OK | dom/media/test/test_mediarecorder_record_getdata_afterstart.html | took 112ms

Comment 1

[Oana Pop-Rus]

Retrigger / backfill : https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=linux%2Cx64%2Cquantumrender%2Cshippable%2Copt%2Cmochitests%2Ctest-linux64-shippable-qr%2Fopt-mochitest-media-e10s-1%2Cm%28mda1%29&tochange=f8cb03296bac00d553fbd1d6dd3e9bd0a578a3dc&fromchange=811757e1e1afb18c9391432e3ead6936332a9499

Seems that, this started to frequently fail since https://bugzilla.mozilla.org/show_bug.cgi?id=1512175 was landed.
(https://hg.mozilla.org/integration/autoland/rev/85af0c8641abb9516e88c3e72244f98da7465c3f)

Pehrsons, can you please take a look?

Thank you.

Comment 2

[Intermittent Failures Robot]

21 failures in 4292 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 17
• mozilla-central: 3
• try: 1

Platform breakdown:

• linux64-shippable: 1
• linux64-shippable-qr: 18
• linux64-qr: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1586328&startday=2019-09-30&endday=2019-10-06&tree=all

Comment 3

[Intermittent Failures Robot]

24 failures in 677 pushes (0.035 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 13
• mozilla-central: 9
• mozilla-inbound: 1
• try: 1

Platform breakdown:

• linux64-shippable: 1
• linux64-shippable-qr: 15
• linux64-qr: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1586328&startday=2019-10-07&endday=2019-10-07&tree=all

Comment 4

[Intermittent Failures Robot]

21 failures in 785 pushes (0.027 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 14
• try: 2
• mozilla-central: 4
• mozilla-inbound: 1

Platform breakdown:

• linux64-shippable-qr: 17
• linux64-qr: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1586328&startday=2019-10-08&endday=2019-10-08&tree=all

Comment 5

[Intermittent Failures Robot]

21 failures in 797 pushes (0.026 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 8
• mozilla-central: 8
• try: 5

Platform breakdown:

• linux64-shippable-qr: 13
• linux64-qr: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1586328&startday=2019-10-09&endday=2019-10-09&tree=all

Comment 6

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1586328 - Make Extract take an aNow argument to avoid pushing a blob the very first call. r?bryce

The first call to Extract() comes from MediaEncoderInitialized() and runs before
we dispatch the task to fire "start". With a very small timeslice (even 0), the
first call to Extract() could decide to push a blob, which is against the spec.

With this patch, the caller is in control of what time Extract() thinks "now"
is. This lets the particular call from MediaEncoderInitialized() gather data
into the blob through Extract() without being at risk of pushing a blob.

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e7b3b38bb160
Make Extract take an aNow argument to avoid pushing a blob the very first call. r=bryce

Comment 8

[Razvan Maries]

https://hg.mozilla.org/mozilla-central/rev/e7b3b38bb160

Comment 10

[Intermittent Failures Robot]

79 failures in 3801 pushes (0.021 failures/push) were associated with this bug in the last 7 days.

This is the #18 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 40
• mozilla-central: 26
• try: 11
• mozilla-inbound: 2

Platform breakdown:

• linux64-shippable: 1
• linux64-shippable-qr: 54
• linux64-qr: 24

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1586328&startday=2019-10-07&endday=2019-10-13&tree=all