audioipc_server error: broken pipe (PulseAudio?) and no sound

[Juan Navarro]

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

[Juan Navarro]

After writing that email I realized that the stuff about FFmpeg could be a bit confusing, so here is some clarification:

In principle, FFmpeg runs optionally to capture and record both video and audio from inside the container, to let us "see" what happened inside. When the recording is ENABLED, the described problem does NOT happen. This led me to test what would happen if the recording is *disabled* but the container started up with a dummy FFmpeg instance that would just capture from PulseAudio and just discard the data, and that one is the "ffmpeg -f null null.out" command that I showed. BTW, this test confirmed that indeed, as long as audio is being captured from PulseAudio, the playback issue doesn't occur in Firefox.

Now I've done a different test: removed the dummy FFmpeg capture, and instead modified the normal recording command. Now we compare what happens if recording either video only, or video+audio. This has the effect we can imagine: video-only recording shows the playback issue in Firefox, and video+audio recording somehow makes the issue disappear.

You can see here a video+audio recording, showing correct behavior:
https://www.dropbox.com/s/cf1370cta1zd5k6/firefox-pulseaudio-short-ok.mp4?dl=0

And here a video-only recording, showing the playback issue:
https://www.dropbox.com/s/je9wqlw5b76u2xe/firefox-pulseaudio-short-err.mp4?dl=0

Later I tested with a longer video and this helped to explain the problem! Seems that, when the issue happens, *playback works fine in the long term but it struggles during the first 5 seconds*. We couldn't see that with the shorter test videos, because they happened to be 5 seconds long!!

Here we see a video+audio recording with a longer test video, correct behavior:
https://www.dropbox.com/s/j79p6lu37qsvc78/firefox-pulseaudio-long-ok.mp4?dl=0

And here a video-only recording with the larger file, playback issue happens:
https://www.dropbox.com/s/p9bv11jlvx3mybu/firefox-pulseaudio-long-err.mp4?dl=0



So, how come having another process grabbing audio from PulseAudio can have such effect on the media playback in Firefox? What can be done to further troubleshoot this issue?

[Alexandros Chronopoulos]

Hi Juan,

One thing you could try out is to remove the audio sandbox and retest. In
order to do that, please go in *about:config* page, find the pref *media.*
*cubeb.**sandbox* and flip it to false. Then restart Firefox and retry.
This will give us an indication of where the problem might be. In order to
investigate further, a good idea is to capture Firefox logs. For doing
that, first please restore the audio sandbox (by flipping the pref to true
and restarting) and then follow the instructions here
<https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging>
but replace the MOZ_LOG env with the following:

*set MOZ_LOG=timestamp,cubeb:5,MediaTrackGraph:5*

Please note that this level of logging will affect the performance of the
audio playback so it might affect your scenario too. If it makes impossible
for you to test or the error does not reproduce try to decrease the log
level to something:

*set MOZ_LOG=timestamp,cubeb:4,MediaTrackGraph:4*

It is also a good idea to open a bug in Bugzilla and continue the
discussion there.

Thank you in advance!

> _______________________________________________
> dev-media mailing list
> dev-...@lists.mozilla.org
> https://lists.mozilla.org/listinfo/dev-media
>

[Juan Navarro]

Hi, thank you very much for your suggestions. I was able to prepare new
recording videos and debug logs, and opened a but report here:

https://bugzilla.mozilla.org/show_bug.cgi?id=1619600

Kind regards,

--
Juan Navarro
Kurento maintainer & developer
j1elo @ Twitter <https://twitter.com/j1elo> / GitHub
<https://github.com/j1elo>