Reports of USB Audio failing when fwupd running

[superm1]

There have been a variety of reports of USB audio failing to work properly when booted with it plugged in. fwupd has a spin lock on the CPU in these situations, and replugging the device seems to resolve the issue.

Additional details are in the bug report link https://bugs.launchpad.net/ubuntu/+source/fwupd/+bug/1574079. Unfortunately they're pretty scattered with everyone giving varying amounts of information. Something that did seem potentially common (and interesting?) was that there is a DFU end point on some of these devices. furthermore one person noted in their debug log that there was a DFU device emitted.

...
21:26:16    15  com.hughski.ColorHugALS.firmware    ColorHugALS
21:26:30    waiting a small time for other providers
21:26:30    using b69159f2-3778-5728-80d0-01be18b2ea30 for USB\VID_1397&PID_0501
21:26:30    emit added from DFU: usb:00:01:03
21:26:31    no product string descriptor
21:26:33    Called GetUpdates()

[hughsie]

I've added a few requests for info on the lp bug. TL;DR: I need a backtrace for the fatal warning or to find out what's spinning, or a device itself.

[hughsie]

So, known devices that fail:

• Sony PHA-3
• RME Fireface UCX
• Focusrite 2i2
• Focusrite solo
• Cambridge audio dacmagic plus (x2)
• Audiobox 22 VSL
• PreSonus AudioBox 1818 VSL
• BEHRINGER UMC204

[jared-mackey]

@hughsie, confirmed an issue on Focusrite 2i4 as well.

For me, running sudo killall fwupd and unplugging and plugging my device back in gets it back into PulseAudio.

Without killing fwupd here is the output from dmesg after plugging in my audio device:

[  559.638142] usb 3-3.2: new high-speed USB device number 14 using xhci_hcd
[  559.711471] usb 3-3.2: New USB device found, idVendor=1235, idProduct=800a
[  559.711472] usb 3-3.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  559.711473] usb 3-3.2: Product: Scarlett 2i4 USB
[  559.711474] usb 3-3.2: Manufacturer: Focusrite
[  564.732510] usb 3-3.2: 1:1: cannot set freq 96000 (v2): err -110
[  564.733253] usb 3-3.2: parse_audio_format_rates_v2(): unable to find clock source (clock -71)
[  564.734479] usbcore: registered new interface driver snd-usb-audio
[  564.747897] usb 3-3.2: 1:1: usb_set_interface failed (-71)
......
[  564.808893] usb 3-3.2: 1:1: usb_set_interface failed (-71)
[  564.820214] xhci_hcd 0000:00:14.0: URB transfer length is wrong, xHC issue? req. len = 0, act. len = 4294967288
[  564.826441] usb 3-3.2: 1:1: usb_set_interface failed (-71)
......
[  564.860402] usb 3-3.2: 1:1: usb_set_interface failed (-71)

However, if I do the killall I just get this:

[  714.357796] usb 3-3.2: USB disconnect, device number 14
[  720.923834] usb 3-3.2: new high-speed USB device number 15 using xhci_hcd
[  720.997172] usb 3-3.2: New USB device found, idVendor=1235, idProduct=800a
[  720.997178] usb 3-3.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  720.997181] usb 3-3.2: Product: Scarlett 2i4 USB
[  720.997183] usb 3-3.2: Manufacturer: Focusrite

[bosiakov]

I can confirm this problem. System: Ubuntu 16.04. Card: Focusrite 2i2.

Running sudo killall fwupd and unplugging and plugging device back helps.

But fwupdmgr get-devices destroys all.

[hughsie]

@mackeyja92 If you kill fwupd, then run sudo dfu-tool watch then replug the device, do you see the same symptoms?

[TarasZakus]

Confirmed. Running sudo dfu-tool watch causes the same symptoms. Here is the output:

$ sudo dfu-tool watch -v
(dfu-tool:4264): libdfu-DEBUG: device was not DFU capable
(dfu-tool:4264): libdfu-DEBUG: device was not DFU capable
(dfu-tool:4264): libdfu-DEBUG: device was not DFU capable
(dfu-tool:4264): libdfu-DEBUG: device was not DFU capable
(dfu-tool:4264): libdfu-DEBUG: device was not DFU capable
(dfu-tool:4264): libdfu-DEBUG: device was not DFU capable
(dfu-tool:4264): libdfu-DEBUG: device was not DFU capable
(dfu-tool:4264): libdfu-DEBUG: device was not DFU capable
(dfu-tool:4264): libdfu-DEBUG: basic DFU, no DfuSe support
(dfu-tool:4264): libdfu-DEBUG: refreshed status=OK and state=appIDLE
Added: 1397:0501 appIDLE:OK: libdfu-DEBUG: device 1397:0501 [usb:00:01:03] was added
(dfu-tool:4264): libdfu-DEBUG: invalidating backing GUsbDevice
(dfu-tool:4264): libdfu-DEBUG: usb:00:01:03 did not come back as a DFU capable device
(dfu-tool:4264): libdfu-DEBUG: usb:00:01:03 was removed
Removed: 1397:0501 [removed]
^C(dfu-tool:4264): libdfu-DEBUG: Handling SIGINT
Cancelled

[hughsie]

@TarasZakus thanks for the confirmation. That means we know it's not an issue with having multiple GUsbContext's or with the way fwupd is querying the device. The next thing we need to do is work out why using the DFU runtime interface is broken :)

Could someone upload the output of sudo strace dfu-tool watch -v please, but only for when it fails. Thanks!

[TarasZakus]

Ok, so here what happens, when I connecting the device when dfu-tool "watching":

) = 1 ([{fd=4, revents=POLLIN}])
read(4, "\1\0\0\0\0\0\0\0", 16) = 8
open("/sys/bus/usb/devices/2-1.3/bConfigurationValue", O_RDONLY) = 11
read(11, "1\n", 5) = 2
close(11) = 0
open("/sys/bus/usb/devices/2-1.3/bConfigurationValue", O_RDONLY) = 11
read(11, "1\n", 5) = 2
close(11) = 0
futex(0x7f92ba03e428, FUTEX_WAKE_PRIVATE, 2147483647) = 0
write(1, "(dfu-tool:3051): libdfu-DEBUG: b"..., 59(dfu-tool:3051): libdfu-DEBUG: basic DFU, no DfuSe support
) = 59
open("/dev/bus/usb/002/008", O_RDWR) = 11
ioctl(11, USBDEVFS_GET_CAPABILITIES, 0x17ff110) = 0
write(9, "\1", 1) = 1
futex(0x17d5990, FUTEX_WAKE_PRIVATE, 1) = 1
ioctl(11, USBDEVFS_CLAIMINTERFACE, 0x7fff46553d0c) = 0
timerfd_settime(10, TFD_TIMER_ABSTIME, {it_interval={0, 0}, it_value={233, 401618000}}, NULL) = 0
ioctl(11, USBDEVFS_SUBMITURB, 0x17fc710) = 0
futex(0x17d5964, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1, {1464726515, 9042770}, ffffffff) = 0
futex(0x17d5938, FUTEX_WAKE_PRIVATE, 1) = 0
timerfd_settime(10, TFD_TIMER_ABSTIME, {it_interval={0, 0}, it_value={233, 401927000}}, NULL) = 0
ioctl(11, USBDEVFS_SUBMITURB, 0x17fc710) = 0
futex(0x17d5964, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 3, {1464726515, 9330992}, ffffffff) = 0
futex(0x17d5938, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f92ba03e428, FUTEX_WAKE_PRIVATE, 2147483647) = 0
write(3, "\1\0\0\0\0\0\0\0", 8) = 8
futex(0x17cfc00, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f92ba03e428, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f92ba03e428, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f92ba03e428, FUTEX_WAKE_PRIVATE, 2147483647) = 0
open("/usr/share/locale/en_US/LC_MESSAGES/glib20.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/en/LC_MESSAGES/glib20.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale-langpack/en_US/LC_MESSAGES/glib20.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale-langpack/en/LC_MESSAGES/glib20.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
timerfd_settime(10, TFD_TIMER_ABSTIME, {it_interval={0, 0}, it_value={232, 903018000}}, NULL) = 0
ioctl(11, USBDEVFS_SUBMITURB, 0x17fef20) = 0
poll([{fd=4, events=POLLIN}], 1, -1) = 1 ([{fd=4, revents=POLLIN}])
read(4, "\1\0\0\0\0\0\0\0", 16) = 8
write(4, "\1\0\0\0\0\0\0\0", 8) = 8
futex(0x17cfeb0, FUTEX_WAKE_PRIVATE, 2147483647) = 0
write(1, "(dfu-tool:3051): libdfu-DEBUG: r"..., 69(dfu-tool:3051): libdfu-DEBUG: refreshed status=OK and state=appIDLE
) = 69
write(9, "\1", 1) = 1
futex(0x17d5990, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x17d5964, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x17d5938, 6) = 1
futex(0x17d5938, FUTEX_WAKE_PRIVATE, 1) = 1
close(11) = 0
futex(0x17d5964, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x17d5938, 8) = 1
futex(0x17d5938, FUTEX_WAKE_PRIVATE, 1) = 1
write(1, "Added:", 6Added:) = 6
write(1, " ", 1 ) = 1
write(1, " ", 1 ) = 1
write(1, " ", 1 ) = 1
write(1, " ", 1 ) = 1
write(1, " ", 1 ) = 1
write(1, " ", 1 ) = 1
write(1, " ", 1 ) = 1
write(1, " ", 1 ) = 1
write(1, " ", 1 ) = 1
write(1, " ", 1 ) = 1
write(1, "1397:0501 [appIDLE:OK]\n", 231397:0501 [appIDLE:OK]
) = 23
write(1, "(dfu-tool:3051): libdfu-DEBUG: d"..., 73(dfu-tool:3051): libdfu-DEBUG: device 1397:0501 [usb:00:01:03] was added
) = 73
poll([{fd=4, events=POLLIN}], 1, -1) = 1 ([{fd=4, revents=POLLIN}])
read(4, "\1\0\0\0\0\0\0\0", 16) = 8
poll([{fd=4, events=POLLIN}], 1, -1

[hughsie]

So, that looks like the device (endpoint?) -- one thing to try would be to stop opening the device and see if it's that. If anyone is feeling clever, can you edit fwupd/libdfu/dfu-tool.c, find dfu_tool_get_device_string() and change:

}
if (!dfu_device_open (device,

to:

}
return g_strdup ("test");
if (!dfu_device_open (device,

And then compile, then run the new tool with .sudo /dfu-tool watch --verbose and try to reproduce. If it still happens this points to something lower down the stack, if it fixes it we can look at another part of DFU. Note: I still think this is a device quirk; but I do acknowledge we have to handle this better.

[TarasZakus]

@hughsie Yes, you are right! 👍 The problem is somewhere inside dfu_device_open-function. If we place return statement before it - the sound-card is detected correctly, after it - the same problem arises.
Unfortunately, I have no more time today to "go deeper". It will be helpful if you give me some tips where to search this next part of DFU.

[hughsie]

@TarasZakus thanks for doing that; could you try the wip/hughsie/dfu-no-interface branch of fwupd please -- the dfu-tool watch issue should be gone, and if you can get the daemon working it should fix that too. Yell if you need any help. Thanks.

[TarasZakus]

Unfortunately, the issue still exists. I've tested on dfu-no-interface-branch as well as on fwupd version 0.7.0-0ubuntu4.2~lp1574079.2 installed from ppa:superm1/lp1574079.

[TarasZakus]

I just did some investigation. It turns out that problem lays a little deeper, than I was expecting. Here is some kinda call-stack:

github.com:hughsie/fwupd.git
starting from dfu_device_open function here
-> calls dfu_device_refresh here
-> calls g_usb_device_control_transfer here

uses github.com:hughsie/libgusb
starting from g_usb_device_control_transfer here
-> calls g_usb_device_control_transfer_async here
-> calls libusb_submit_transfer here

uses github.com:libusb/libusb
starting from libusb_submit_transfer here

I assume that the bug might be somewhere between calling g_usb_device_control_transfer and libusb_submit_transfer.
Maybe some inappropriate argument passed or so.