I'm facing an intermittent (we could say it happens 50% of the time) issue
where Firefox running inside an Ubuntu Docker container (more info below)
doesn't play back an incoming WebRTC audio stream, and the only hint I got (so
far) is this error message which I *think* comes from Firefox:
[2020-02-28T03:39:02Z ERROR audioipc_server::server] Unexpected message
Err(Custom { kind: BrokenPipe, error: "broken pipe" }) during data_callback
When this problem happens, the HTML <video> element that plays the remote
WebRTC stream does not update its `currentTime` property
(https://developer.mozilla.org/en-US/docs/Web/HTML/Element/video#attr-currentTime),
or does so up to e.g. 0.3 seconds (for a video of between 5 to 6 seconds
length). Meanwhile, the RTCPeerConnection `inbound-rtp` stats show the expected
amount of `packetsReceived`, i.e. 50 packets per second. So it is definitely a
problem on local playback of the audio.
When this problem does not happen, the <video> element does indeed update its
`currentTime` property up to 5.0 or 5.5 seconds.
Now here's the fun part: IF FFmpeg is running in the background recording audio
from PulseAudio, then this error *never* occurs, and Firefox plays back the
WebRTC audio stream 100% of the times, with the `video.currentTime` property
reaching the expected time. This makes me think that there is some bad
interaction between the Firefox audio implementation (which is exclusively
based on PulseAudio since Firefox 53), and the PulseAudio server itself.
I know nothing about how PulseAudio works, but the "ipc" in the error message
tells me that Firefox connect to the PulseAudio server through I guess a Unix
socket, and the "broken pipe" part tells me that this socket connection is
somehow dropped. However, I've run PulseAudio with maximum log level, and it
didn't show anything that smells like a warning or error that could be related
to this issue.
I would be very grateful for tips or pointers about where to look next; this is
a very in-depth issue that probably needs collaboration with Firefox media devs.
==== About the environment ====
This is part of an automated CI system that tests WebRTC implementation of
Firefox and Chrome, by using dockerized installations of the browsers. In this
case, we have Firefox running inside an Ubuntu Docker container (tested Ubuntu
16.04 and 18.04), which also runs an X server, x11vnc, and other tools;
Selenoid binary (https://aerokube.com/selenoid/latest/) for controlling the
browser, and optionally FFmpeg to record the whole session and "see" what
happened during the test execution.
The Docker entrypoint (what runs as main process inside the container) starts
up like this:
1. Runs Xvfb with Selenoid: /usr/bin/xvfb-run [...] /usr/local/bin/selenoid
[...]
2. Runs Fluxbox as the Window Manager.
3. Runs PulseAudio, currently with this command:
pulseaudio --daemonize \
--log-target=file:/home/ubuntu/pulseaudio.log \
--log-level=4
4. Optionally, runs FFmpeg in dummy capture mode:
ffmpeg \
-nostdin \
-f alsa -ar 44100 -ac 2 \
-i pulse \
-f null null.out \
>/dev/null 2>&1 &
A Java application runs on the host machine, and runs Docker commands to
start/stop and control containers. It starts a web server, a WebRTC
application, and inside the container, Firefox is instructed to open a test web
page, in this case in "recvonly" mode.
The Java host application is able to retrieve the RTCPeerConnection stats from
the dockerized browser, and also is able to get the `video.currentTime`
property from the HTML page. This way, it know whether the browser is actually
receiving packets AND playing back the video. Packets arrive as expected, but
then if the optional FFmpeg command is running the video plays back fine, but
if FFmpeg is not running, the video doesn't play. Funny thing is, we cannot
actually record the screen and "see" it playing back, as the mere act of
recording interferes with this issue. It's a Heisenbug.
Browser logs are not obtained directly, but generated by the Selenoid
execution. I'm not sure exactly how it works, but the end result is that
Selenoid generates a log file with all debug output from GeckoDriver,
Marionette, and WebDriver.
I would love to know how to tell Selenoid to run Firefox with environment
variables `MOZ_LOG` and maybe `MOZ_LOG_FILE`, which afaik. are the ones to use
in order to raise the log level of some internal parts of Firefox. But so far I
haven't been able to, and that's a question for the Selenoid user group, not
here (but if you know how to do that please let me know! :-)
If you got to this point, thanks for reading! You are a Champion :-)
Kind regards,
Juan Navarro - Maintainer & developer of Kurento Media Server
_______________________________________________
dev-media mailing list
dev-media@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-media
