Bug 106557 - power on / plugging in E-MU 0202 USB hangs up pulseaudio and USB bus
Summary: power on / plugging in E-MU 0202 USB hangs up pulseaudio and USB bus
Status: RESOLVED MOVED
Alias: None
Product: PulseAudio
Classification: Unclassified
Component: core (show other bugs)
Version: unspecified
Hardware: x86-64 (AMD64) Linux (All)
: medium major
Assignee: pulseaudio-bugs
QA Contact: pulseaudio-bugs
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-05-17 20:59 UTC by Dmitrii Sutiagin
Modified: 2018-07-30 10:25 UTC (History)
2 users (show)

See Also:
i915 platform:
i915 features:


Attachments

Description Dmitrii Sutiagin 2018-05-17 20:59:10 UTC
I've originally reported the issue here - https://bbs.archlinux.org/viewtopic.php?pid=1780719#p1780719

In short, I have E-MU 0202 USB and as soon as I plug it in, I am no loger able to view the list of audio devices, I start seeing errors in dmesg:
[Wed Apr 18 13:33:49 2018] usb 3-2: 2:1: usb_set_interface failed (-110)

And if I make a few more requests to audio subsystem my USB mouse and keyboard stop working (builtin kb and touchpad still work).

The workaround is to stop all instances of pulseaudio, namely user's daemon and GDM's daemon (I only found one way - "for i in {0..50}; do sudo killall pulseaduio" - otherwise GDM will restart, also changing config param autostart=no does not take effect and service still gets restarted), then plug the interface, then logout/login to recover pulseaudio. Side effect of this is that audio volume level in Gnome does not affect volume of the card, for whatever reason.

So - a few different issues here, but main is hangup of pulseaudio when card is plugged in.

Interesting is that there is no such issue in Ubuntu, only in my Arch Linux installation. However, I tried building and booting with Ubuntu's kernel configuration on my Arch system and the issue persisted, so it looks to be related to the version of pulseaudio and/or dependent libs and not to kernel. I tried older kernels as well with same result.

I can provide more details or execute any tests, let me know what's needed.

PulseAudio is 11.1-1, pulseaudio-alsa is 2-3, distro - Arch Linux x64.
Comment 1 Tanu Kaskinen 2018-05-23 15:18:06 UTC
This really sounds like a kernel issue, but let's try some things...

If you comment out module-udev-detect from /etc/pulse/default.pa, this particular problem probably goes away because the card won't appear in pulseaudio at all, but what if you start pulseaudio without module-udev-detect, plug in the sound card and then run "pactl load-module module-udev-detect", does that work? Maybe the problem appears only if pulseaudio tries to access the card right after it has been plugged in, maybe the device is in some kind of initialization phase still...

Is the Ubuntu installation on the same computer as Arch?

Could you also get a pulseaudio log when you plug in the sound card (with module-udev-detect loaded so that the problem is reproduced)? Instructions:

1. Disable automatic starting of PulseAudio:

    systemctl --user --now mask pulseaudio.service pulseaudio.socket

You might want to do the same for gdm:

    sudo -u gdm bash   # On Debian the user is Debian-gdm, so adjust if needed
    XDG_RUNTIME_DIR=/run/user/$UID systemctl --user --now mask \
                                       pulseaudio.service pulseaudio.socket

2. Stop pulseaudio with "killall pulseaudio" (the previous systemctl
command might have stopped it already, though).

3. Start pulseaudio in a terminal with verbose logging:

    pulseaudio -vv

4. Once the initial burst of logging has stopped, hit enter a few times
to add some empty lines in the log. The empty lines mark the beginning
of the interesting part.

5. Plug in the sound card.

6. Copy the log starting from the empty lines from step 4 to the end of the output.

7. Stop pulseaudio with ctrl-c.

8. To return things back to normal, run

    systemctl --user unmask pulseaudio.service pulseaudio.socket

and the same for gdm (or maybe you want to leave gdm without pulseaudio).

Please use the "Add an attachment" link to attach the log (sometimes
people paste the log to the comment box, which makes it difficult to
follow the discussion).
Comment 2 Dmitrii Sutiagin 2018-05-25 21:06:25 UTC
Tanu, thank you for the recommendations.

While following the steps, the gdm masking part did not give intended result:

[dsutyagin@pulsar ~]$ sudo ps -ef | grep [p]ulse
gdm        779   722  0 11:22 ?        00:00:00 /usr/bin/pulseaudio --daemonize=no
dsutyag+  1018   905  0 11:22 ?        00:00:06 /usr/bin/pulseaudio --daemonize=no
[dsutyagin@pulsar ~]$ sudo -u gdm bash
[gdm@pulsar dsutyagin]$ XDG_RUNTIME_DIR=/run/user/$UID systemctl --user --now mask pulseaudio.service pulseaudio.socket
Created symlink /var/lib/gdm/.config/systemd/user/pulseaudio.service → /dev/null.
Created symlink /var/lib/gdm/.config/systemd/user/pulseaudio.socket → /dev/null.
[gdm@pulsar dsutyagin]$ exit
[dsutyagin@pulsar ~]$ systemctl --user --now mask pulseaudio.service pulseaudio.socket
Created symlink /home/dsutyagin/.config/systemd/user/pulseaudio.service → /dev/null.
Created symlink /home/dsutyagin/.config/systemd/user/pulseaudio.socket → /dev/null.
[dsutyagin@pulsar ~]$ ps -ef | grep [p]ulse
gdm       2586     1  0 11:42 ?        00:00:00 /usr/bin/pulseaudio --start --log-target=syslog
[dsutyagin@pulsar ~]$ sudo killall pulseaudio
[dsutyagin@pulsar ~]$ ps -ef | grep [p]ulse
gdm       2603     1  0 11:42 ?        00:00:00 /usr/bin/pulseaudio --start --log-target=syslog

...So I used this trick:

[dsutyagin@pulsar ~]$ sudo chmod -x /usr/bin/pulseaudio
[dsutyagin@pulsar ~]$ sudo killall pulseaudio
[dsutyagin@pulsar ~]$ sudo chmod +x /usr/bin/pulseaudio
[dsutyagin@pulsar ~]$ ps -ef | grep [p]ulse
[dsutyagin@pulsar ~]$

Regarding the log... This is getting very interesting. The issue is not consistent depending on how I reproduce it. I got at least 3 different behaviors when testing with different combinations of pulseaudio running/not running/ and debug foreground mode vs systemd mode:

1. it doesn't work as before, log example can be found here - https://pastebin.com/4en37K3L # this is usually the result when I just plug in the card while it's on (it's hardware switch)

2. it works, log example here - https://pastebin.com/0xQRWmNk # this I got when 1 pulseaudio running (with -vv) and I plugged in the card while it was "off" (it has a hardware switch on it's front, integrated into volume knob) and then turned the card on via the knob.

3. it glitches like hell, the card gets reset several times, then pause, then again reset several times - I can hear clicks in headphones and kernel usb log repeats each time as if I just plugged the card in. Log here (only journalctl, failed to capture pulseaudio) - https://pastebin.com/Y5Ng2Fbs # This happened with 2 pulseaudio running and using a knob to turn the card on.

To conclude, so far it looks like if I have 1 or 0 pulseaudio running and use the knob, it usually works, all other scenarios usually lead to the issue in it's now 2 different forms. I'll play a bit more with this and let know if I find any specific behaviors. To me this looks like a race between pulseaudio and kernel or system. Maybe related to systemd-udevd calling alsactl so early, or upowerd notices about unhandled action... Both of these do happen even when the card works, but maybe the timing between this and pulseaudio is important. And with 2 pulseaudio the chances of success are less, which is also in indicator of race.
Comment 3 Tanu Kaskinen 2018-06-01 09:25:11 UTC
(In reply to Dmitrii Sutiagin from comment #2)
> [dsutyagin@pulsar ~]$ ps -ef | grep [p]ulse
> gdm       2586     1  0 11:42 ?        00:00:00 /usr/bin/pulseaudio --start
> --log-target=syslog

Apparently autospawning is enabled for gdm. That's weird. My impression has been that Arch disables autospawning (as it should when it's using systemd to manage pulseaudio), and autospawning seems to be disabled for your own user. Is there some gdm specific configuration in /var/lib/gdm/.config/pulse/client.conf? Make sure that /etc/pulse/client.conf has "autospawn = no". Note that /etc/pulse/client.conf has no effect on gdm if /var/lib/gdm/.config/pulse/client.conf exists.

> 1. it doesn't work as before, log example can be found here -
> https://pastebin.com/4en37K3L # this is usually the result when I just plug
> in the card while it's on (it's hardware switch)

The log stops rather abruptly in the middle of the probing process after getting "Input/output error" from snd_pcm_hw_params(). It seems that snd_pcm_close() is hanging, because otherwise there should be more logs.

To me this seems quite clearly a kernel bug, and I don't think I have much more to contribute here. You should report the problem to the alsa developers, here are some instructions: http://alsa-project.org/main/index.php/Bug_Tracking
Comment 4 Dmitrii Sutiagin 2018-06-11 21:27:27 UTC
(In reply to Tanu Kaskinen from comment #3)
> Apparently autospawning is enabled for gdm. That's weird. ... Is there some
> gdm specific configuration in
> /var/lib/gdm/.config/pulse/client.conf? 

[dsutyagin@pulsar ~]$ sudo find / -name 'client.conf' 2>/dev/null | grep pulse | xargs -I@ bash -c 'echo @; grep autospawn @ | sed "s/^/--> /"'
/etc/pulse/client.conf
--> ; autospawn = yes
/home/dsutyagin/.config/pulse/client.conf
--> # Disable autospawning the PulseAudio daemon
--> autospawn = no
/home/dsutyagin/.local/share/flatpak/runtime/org.freedesktop.Sdk/x86_64/1.4/d6a8c46e30e0518c8f6c8278edf0bd59800193494bbdaeee7393646385247445/files/etc/pulse/client.conf
--> ; autospawn = yes

as you can see, gdm doesn't have "client.conf", to be more specific, here's the contents:

[user@system ~]$ sudo ls -l /var/lib/gdm/.config/pulse
total 56
-rw-r--r-- 1 gdm gdm 20480 May  3 15:23 1475c2dd14c9474ab7bab828a842239e-card-database.tdb
-rw-r--r-- 1 gdm gdm    43 Jun 11 09:53 1475c2dd14c9474ab7bab828a842239e-default-sink
-rw-r--r-- 1 gdm gdm    42 Jun 11 09:53 1475c2dd14c9474ab7bab828a842239e-default-source
-rw-r--r-- 1 gdm gdm 12288 May  3 15:23 1475c2dd14c9474ab7bab828a842239e-device-volumes.tdb
-rw-r--r-- 1 gdm gdm 12288 May 29 19:48 1475c2dd14c9474ab7bab828a842239e-stream-volumes.tdb
-rw------- 1 gdm gdm   256 May  2  2017 cookie

Maybe the default is "enabled" so that's why. GDM's cwd is / so idk if it should read from /var/lib/gdm/.config/pulse or /etc/pulse

[dsutyagin@pulsar ~]$ pgrep -f /usr/bin/gdm | sudo xargs -I@ ls -ld /proc/@/cwd
lrwxrwxrwx 1 root root 0 Jun 11 14:14 /proc/542/cwd -> /

But anyway.

> The log stops rather abruptly in the middle of the probing process after
> getting "Input/output error" from snd_pcm_hw_params(). It seems that
> snd_pcm_close() is hanging, because otherwise there should be more logs.

I've stopped collecting logs at that point, they do keep adding slowly, but every call in pulseaudio log ends with long delay and then timeout, so further logs won't add much (unless there's some useful debug info at the end of all the attempts).

> To me this seems quite clearly a kernel bug, and I don't think I have much
> more to contribute here. You should report the problem to the alsa
> developers, here are some instructions:
> http://alsa-project.org/main/index.php/Bug_Tracking

I will try filing a bug to alsa, thank you.
Comment 5 Dmitrii Sutiagin 2018-06-11 21:39:47 UTC
Filed a kernel bug - https://bugzilla.kernel.org/show_bug.cgi?id=200031
Comment 6 GitLab Migration User 2018-07-30 10:25:30 UTC
-- GitLab Migration Automatic Message --

This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity.

You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/pulseaudio/pulseaudio/issues/407.


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.