960057 - Race condition on MediaElementAudioSourceNode creation

Status: RESOLVED FIXED

(Core :: Web Audio, defect, P1)

Description

[Paul Adenot (:padenot)]

Attachment: Using mozCaptureStream

While investigating bug 932400, I noticed that sometimes, an HTMLMediaElement that is used in an AudioContext (using AudioContext.createMediaElementSource()) will stop playing, either after something like one second (I haven't measured, it just just says 00:01 on the media element), or, if it very short, never play.

I've fiddled with my source code, and sometimes, calling play() on the media element before creating the audio graph (that is, before calling AudioContext.createMediaElementSource()) makes it work. This might be a coincidence, though.

Attached is a page that shows the issue: it should play the "ting" sound in a loop, through an AudioContext.

The other test case uses mozCaptureStream instead, and also does not work, so I'm actually not sure this bug is a Web Audio bug.

Comment 1

[Paul Adenot (:padenot)]

Attachment: Using Web Audio's createMediaElementSource

Comment 2

[Paul Adenot (:padenot)]

So, in the case where the file is short, it goes like this:
- I'm on a desktop, so the <audio> implicitly preloads and decode some data.
- We run the decode loop, but soon enough, we run out of data (the file is short)
- We then exit the decode loop
- At this point, the js starts to do stuff, so we create the MediaElementSourceNode, and then the stream is marked as capture, and nothing happens because we aren't decoding anymore.

Comment 3

[JW Wang [:jwwang] [:jw_wang]]

Hi Paul,
Did this issue happen on Linux? I got a gstreamer error while investigating other mochitest timeouts. NSPR log are as follow:

11:45.23 2207 INFO TEST-START | /tests/content/media/test/test_mediarecorder_creation_fail.html
11:48.27 2208 INFO Error: Unable to restore focus, expect failures and timeouts.
11:48.39 ++DOMWINDOW == 18 (0x7fd7d34da8b8) [pid = 1778] [serial = 129] [outer = 0x7fd7da59b4b8]
11:48.56 [1778] WARNING: NS_ENSURE_TRUE(enabled) failed: file /home/jwwang/codebase/mozilla-central/dom/base/Navigator.cpp, line 1892
11:48.56 [1778] WARNING: NS_ENSURE_TRUE(enabled) failed: file /home/jwwang/codebase/mozilla-central/dom/base/Navigator.cpp, line 1711
11:48.93 2209 INFO TEST-INFO | /tests/content/media/test/test_mediarecorder_creation_fail.html | suro: SpecialPowers.pushPrefEnv
11:48.98 2210 INFO TEST-INFO | /tests/content/media/test/test_mediarecorder_creation_fail.html | suro: startTest
11:48.99 [1778] WARNING: Need a principal to compare this to!: file /home/jwwang/codebase/mozilla-central/caps/src/nsPrincipal.cpp, line 239
11:48.99 -9087168[7fd7fe23f480]: MediaDecoder::AddOutputStream this=7fd7d412c7a0 aStream=7fd7d290da80!
11:48.99 -9087168[7fd7fe23f480]: MediaDecoder::RecreateDecodedStream this=7fd7d412c7a0 aStartTimeUSecs=0!
11:48.99 -470386944[7fd7d0928020]: 7fd7d412c7a0 Decoding Media Headers
11:48.99 -470386944[7fd7d0928020]: configuring random access, len 67430
11:49.00 -1227884800[7fd7d0929670]: Audio preroll
11:49.01 -1182800128[7fd7d0929560]: ReadAndPushData push ret wrong-state
11:49.01 -1227884800[7fd7d0929670]: Audio preroll
11:49.02 -470386944[7fd7d0928020]: MediaDecoderReader::FindStartTime() audio=26122
11:49.02 -470386944[7fd7d0928020]: 7fd7d412c7a0 Media start time is 26122
11:49.02 -470386944[7fd7d0928020]: 7fd7d412c7a0 Media goes from 26122 to 3369738 (duration 3343616) transportSeekable=1, mediaSeekable=1
11:49.02 -470386944[7fd7d0928020]: 7fd7d412c7a0 Changed state from DECODING_METADATA to DECODING
11:49.02 -470386944[7fd7d0928020]: 7fd7d412c7a0 StartPlayback()
11:49.02 -470386944[7fd7d0928020]: 7fd7d412c7a0 Start DecodeLoop()
11:49.02 -1182800128[7fd7d0929560]: ReadAndPushData push ret unexpected
11:49.02 -470386944[7fd7d0928020]: 7fd7d412c7a0 Decoder writing 1152 frames of data to MediaStream for AudioData at 26122
11:49.02 -470386944[7fd7d0928020]: 7fd7d412c7a0 Decoder writing 1152 frames of data to MediaStream for AudioData at 52244
11:49.02 -470386944[7fd7d0928020]: 7fd7d412c7a0 Exiting DecodeLoop
11:49.02 -470386944[7fd7d0928020]: 7fd7d412c7a0 Decode thread finished
11:49.02 -1191192832[7fd7d0927470]: 7fd7d412c7a0 Shutdown decode thread
11:49.14 -1191192832[7fd7d0927470]: 7fd7d412c7a0 StopPlayback()
11:52.58 -9087168[7fd7fe23f480]: 7fd7d412b460 Changed state to SHUTDOWN




11:49.02 -1182800128[7fd7d0929560]: ReadAndPushData push ret unexpected
It looks like something wrong in gstreamer that causes GStreamerReader to reach end of stream prematurely. This might also account for some timeouts (for oncanplaythrough is not received) and unexpected duration failures in mochitest.

Comment 4

[Paul Adenot (:padenot)]

Maybe, yes. I was testing with a vorbis file, so gstreamer was not involved.

Comment 5

[Maire Reavy [:mreavy]]

Paul -- This sounds like a P1 bug to me (i.e. one we need to try to fix ASAP), and I remember you said this bug was tough to reproduce.  If you agree this is a P1, can you hand off this investigation to Karl and reassign this bug to him?  

If you feel this a P2, please lower this bug's priority, and then I'm fine with this bug staying in your queue until you can get to it.  Thanks.

Comment 6

[Paul Adenot (:padenot)]

I can repro comment 2 100% of the time, here. Maybe if we fix it, we can fix the super-hard-to-repro (maybe, like twice on fifty tries) issue I've seen.

Comment 7

[Paul Adenot (:padenot)]

Okay, I now know why this happens.

Basically, the first time we go in MediaDecoderStateMachine::HaveEnoughDecodedAudio [1], the stream might be there, but also might not have been initialized (that's rare, but can happen), so we bail out. And the under-run handler is never installed, and it all breaks apart.

[1]: http://dxr.mozilla.org/mozilla-central/source/content/media/MediaDecoderStateMachine.cpp#779

Comment 8

[Paul Adenot (:padenot)]

Attachment: When an HTMLMediaElement outputs to a MediaStream, make sure to install the refill callback in any case. r=

This should work. It works for me, but since this is hard to repro, I can't be
100% certain.

Comment 9

[Paul Adenot (:padenot)]

Landed with a wrong commit message here:

https://hg.mozilla.org/integration/mozilla-inbound/rev/4d0197840932

Relanded with DONTBUILD and the right commit message here:

https://hg.mozilla.org/integration/mozilla-inbound/rev/d5b841bc9550
https://hg.mozilla.org/integration/mozilla-inbound/rev/a0015648d5ef

Comment 10

[Phil Ringnalda (:philor)]

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