Module module-echo-cancel drop sources/sinks too often
Summary
I use module-echo-cancel with my headset. It seems that very recently -- and it seems to be concurrent with a kernel update from 5.2.7-100.fc29.x86_64 to 5.2.11-100.fc29.x86_64 on my Fedora 29 box -- the echo cancel module often drops sinks and/or sources. Definitely on the source side (less so on the sink side), this causes problems for downstream applications that need to be restarted in order for the mic to continue working. Applications affected by this include Chrome, Zoom, and Zoiper, and perhaps others (these are the only 3 I regularly use a mic with, and all are affected). Audio recording is immediately disabled in these applications, and they need to be restarted in order to continue. In the case of Zoom and Zoiper, they actually need to be killed -- the loss of the echo cancellation prevents them from even shutting down.
I've reported similar problems in the past where application audio inputs are disrupted due to module-echo-cancel, and for the last few months, things have been great and I had very few issues with this.
environment
I have attached two pa-info outputs:
- pa-info.txt : without echo cancellation in the source/sink streams
- pa-info-with-ec.txt : desired setup with echo cancellation used by default in sources/sinks
Steps to reproduce
It seems to be totally random, but happens pretty regularly when an application is actively using sound/mic.
What is the current bug behavior?
The application (Chrome, Zoom, Zoiper) loses mic access. I see in PA Volume Control that the input sources of application audio has switched from "SteelSeries Arctis 7 Analog Stereo (echo cancelled with SteelSeries Arctis 7 Analog Mono)" to "HD Pro Webcam C920 Analog Stero". The application needs to be restarted.
In the dmesg logs, I see things like this:
Sep 19 13:49:11 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Doing resync
Sep 19 13:49:11 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (12021), drop source 3072
Sep 19 13:49:11 edison kernel: restoring control 00000000-0000-0000-0000-000000000101/10/5
Sep 19 13:49:11 edison kernel: restoring control 00000000-0000-0000-0000-000000000101/12/11
Sep 19 13:49:12 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (13942), drop source 3568
Sep 19 13:49:13 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (10656), drop source 2720
Sep 19 13:49:14 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9957), drop source 2544
Sep 19 13:49:15 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9730), drop source 2488
Sep 19 13:49:16 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9757), drop source 2496
Sep 19 13:49:17 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9846), drop source 2520
Sep 19 13:49:18 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9931), drop source 2536
Sep 19 13:49:19 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9994), drop source 2552
Sep 19 13:49:20 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9812), drop source 2504
Sep 19 13:49:21 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9865), drop source 2520
Sep 19 13:49:22 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9850), drop source 2520
Sep 19 13:49:23 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9550), drop source 2440
Sep 19 13:49:24 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9744), drop source 2488
Sep 19 13:49:25 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9852), drop source 2520
Sep 19 13:49:26 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9767), drop source 2496
Sep 19 13:49:27 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9688), drop source 2480
Sep 19 13:49:28 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9840), drop source 2512
Sep 19 13:49:29 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9509), drop source 2432
Sep 19 13:49:30 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9626), drop source 2464
Sep 19 13:49:31 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (7646), drop source 1952
Sep 19 13:49:32 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9699), drop source 2480
Sep 19 13:49:33 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (9925), drop source 2536
Sep 19 13:49:34 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (10391), drop source 2656
Sep 19 13:49:35 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback too far ahead (10020), drop source 2560
Sep 19 13:49:36 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback after capture (-287), drop sink 152
Sep 19 13:49:51 edison pulseaudio[32629]: E: [alsa-source-USB Audio] module-echo-cancel.c: Playback after capture (-115), drop sink 104
There is nothing fundamentally wrong with the headset either -- everything works fine as soon as I reset the configuration back to the desired settings, and restart applications. I also notice no disruption in playback to the headset when this occurs, so the headset's physical connection to the computer appears to be fine.
What is the expected correct behavior?
This should not happen. Even if the echo cancel module has to resync, it should do so without causing downstream issues or changing my PulseAudio settings.