Filed by: philringnalda [at] gmail.com https://treeherder.mozilla.org/logviewer.html#?job_id=36338304&repo=mozilla-inbound https://archive.mozilla.org/pub/firefox/tinderbox-builds/mozilla-inbound-win32-debug/1474583939/mozilla-inbound_win7_vm-debug_test-mochitest-media-bm140-tests1-windows-build63.txt.gz

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.

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

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

Comment on attachment 8800329 [details] Bug 1304950 - Defer mozCaptureStream() until after "loadedmetadata". https://reviewboard.mozilla.org/r/84898/#review83970

Comment on attachment 8800330 [details] Bug 1304950 - Reduce timeslice to avoid races with the source ending. https://reviewboard.mozilla.org/r/85250/#review83972

(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.

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

https://hg.mozilla.org/mozilla-central/rev/db8173b81d33 https://hg.mozilla.org/mozilla-central/rev/7480f3d08b18