918523 - getUserMedia audio streams will be released after a period of time while running in a background app

Status: VERIFIED FIXED

(Core :: WebRTC: Audio/Video, defect)

Description

[Jason Smith [:jsmith]]

Build: Master 9/17/2013
Device: Buri

STR

1. Go to http://mozilla.github.io/webrtc-landing/gum_test.html
2. Select Audio
3. Accept permissions
4. Hit the home button
5. Wait for a while
6. Launch the browser

Expected

The getUserMedia audio stream should still be active when I check playback in the browser.

Actual

If you wait long enough (~30 seconds), then you'll notice playback has stopped of the getUserMedia audio stream. This implies that the gUM audio stream was released while the app was running in the background.

Comment 1

[Randell Jesup [:jesup] (needinfo me)]

Logs with timestamp,getusermedia:5,mediamanager:5,mediastreamgraph:5 please.
Thanks

Comment 2

[Jason Smith [:jsmith]]

(In reply to Randell Jesup [:jesup] from comment #1)
> Logs with timestamp,getusermedia:5,mediamanager:5,mediastreamgraph:5 please.
> Thanks

When trying to run the steps at https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging#Firefox_OS_phones, I'm seeing the nspr file being created, but nothing is being written to it when running the gum test page. So no luck so far getting NSPR logs. I'm also seeing running b2g.sh failing:

root@android:/ # /system/bin/b2g.sh
/system/bin/b2g.sh
-*- RadioInterfaceLayer: 1 interfaces
###################################### forms.js loaded
############################### browserElementPanning.js loaded
######################## BrowserElementChildPreload.js loaded
RIL Worker[0]: ICC I/O Error code RequestNotSupported EF id = 6fc5 command = b2
RIL Worker[0]: ICC I/O Error code RequestNotSupported EF id = 6fc6 command = b2
XXX FIXME : Got a mozContentEvent: system-message-listener-ready
Unable to create nspr log file '/data/nspr.txt'
RIL Worker[0]: DateTimeZone string 13/09/20,18:25:37-28,01
XXX FIXME : Got a mozContentEvent: accessibility-screenreader

mwu - Why is NSPR logging failing on 1.2 builds right now? Any ideas?

Comment 3

[Jason Smith [:jsmith]]

Attachment: Logcat

Comment 4

[Randell Jesup [:jesup] (needinfo me)]

Logcat shows nothing I'm afraid (was this a debug build?)

Comment 5

[Jason Smith [:jsmith]]

(In reply to Randell Jesup [:jesup] from comment #4)
> Logcat shows nothing I'm afraid (was this a debug build?)

Nope, it's a production build.

https://pvtbuilds.mozilla.org/pvt/mozilla.org/b2gotoro/nightly/mozilla-aurora-hamachi/latest/

Comment 6

[Shih-Chiang Chien [:schien] (UTC+8) (use ni? plz)]

The ready queue seems starved since I saw the following error is occur after resuming browser app.
http://dxr.mozilla.org/mozilla-central/source/media/webrtc/trunk/webrtc/modules/audio_device/audio_device_opensles.cc#l1451

Comment 7

[Michael Wu [:mwu]]

(In reply to Jason Smith [:jsmith] from comment #2)
> mwu - Why is NSPR logging failing on 1.2 builds right now? Any ideas?

/data/ isn't a good location to put log files. See the note on the mdn page that says: "On Firefox OS, child processes are only allowed to open files in /data/local/tmp, so you must be sure to set NSPR_LOG_FILE to a file in that directory; otherwise, the child processes won't be able to write their log files."

Comment 8

[Jason Smith [:jsmith]]

Okay. I'll take another shot at getting the logs this time the right way.

Comment 9

[Jason Smith [:jsmith]]

This time I got a generated log file, but the log file has no output when this bug reproduces.

Comment 10

[Jason Smith [:jsmith]]

I tested this also with the basic HTTP logging (timestamp,nsHttp:5,nsSocketTransport:5,nsHostResolver:5) included on the MDN page and in that case, I'm getting lots of output in the NSPR logging. So I'm not sure why the nspr log modules suggested above are not generating output.

Comment 11

[Shih-Chiang Chien [:schien] (UTC+8) (use ni? plz)]

Now I know the root cause of this bug.
The Rec thread will be blocked for a while after switching background app to foreground, therefore, all the 16 audio buffer will be push to rec_voe_audio_queue. The rec_queue/queue_itf will become empty and RecorderSimpleBufferQueueCallbackHandler will not be invoked afterward [1].
Even after Rec thread wake up and flush all the audio buffer to rec_voe_ready_queue, the rec_queue cannot be reload since the Enqueue is invoked in RecorderSimpleBufferQueueCallbackHandler [2] (which is not going to happened).

@jesup, do you have any suggestion that we can stop moving audio buffer from rec_queue to rec_voe_audio_queue before draining rec_queue?

[1] https://www.codeaurora.org/cgit/quic/la/platform/system/media/tree/wilhelm/src/android/AudioRecorder_to_android.cpp?h=ics_chocolate_rb4.2#n225
[2] http://dxr.mozilla.org/mozilla-central/source/media/webrtc/trunk/webrtc/modules/audio_device/audio_device_opensles.cc#l1464

Comment 12

[Shih-Chiang Chien [:schien] (UTC+8) (use ni? plz)]

Attachment: WIP - prevent rec_queue overrun

Discarding the latest audio frame before we break the balance between audio_queue and ready_queue.

Comment 13

[Randell Jesup [:jesup] (needinfo me)]

Comment on attachment 809777 [details] [diff] [review]
WIP - prevent rec_queue overrun

Review of attachment 809777 [details] [diff] [review]:
-----------------------------------------------------------------

::: media/webrtc/trunk/webrtc/modules/audio_device/audio_device_opensles.cc
@@ +1464,3 @@
>      } else {
> +      // discard the latest audio frame
> +      memset(audio, 0, total_bytes);

the memset is irrelevant
Add a comment that the audio buffer will just be recycled (to OpenSL Enqueue()) instead of sent to the recthread

Comment 14

[Shih-Chiang Chien [:schien] (UTC+8) (use ni? plz)]

Attachment: prevent-rec-queue-overrun.patch

Update with feedback comment addressed.

Comment 15

[Shih-Chiang Chien [:schien] (UTC+8) (use ni? plz)]

https://tbpl.mozilla.org/?tree=Try&rev=5a046d7f7346

Comment 16

[Randell Jesup [:jesup] (needinfo me)]

Comment on attachment 811156 [details] [diff] [review]
prevent-rec-queue-overrun.patch

Review of attachment 811156 [details] [diff] [review]:
-----------------------------------------------------------------

r=me with the timer Set()

::: media/webrtc/trunk/webrtc/modules/audio_device/audio_device_opensles.cc
@@ +1464,2 @@
>      } else {
> +      // the audio frame will be recycled instead of sending to rec thread.

Probably should call rec_timer_.Set() here, just to make sure the rec thread wakes up to process the data queued for it.  Might not be strictly needed, but I don't think it can hurt, and it provides a bit of belt-and-suspenders

Comment 17

[Shih-Chiang Chien [:schien] (UTC+8) (use ni? plz)]

Attachment: prevent-rec-queue-overrun.patch

update according to review comment, carry r+.
https://tbpl.mozilla.org/?tree=Try&rev=c96a48471a01

Comment 18

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/b2g-inbound/rev/8be7c8f3da4b

Comment 19

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/8be7c8f3da4b

Comment 20

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/0ce69d770778

Comment 21

[Jason Smith [:jsmith]]

lgtm - tested with a 5 minute gUM audio request running in the background and returning it to the foreground