ehci-pci: Scarlett Gen 2 mixer driver init failure

DISCUSSION Geoffrey D. Bennett 2 participants 4 messages May 18, 2021 – May 20, 2021

Subsystems (2)

USB Sound

lore

Share & tools

lore

Geoffrey D. Bennett

author

2021-05-18 20:33 UTC #0 lore raw

Hi there,

I'm investigating an issue with the Focusrite Scarlett Gen 2 ALSA mixer driver (linux/sound/usb/mixer_scarlett_gen2.c) where the driver fails to correctly perform the proprietary USB initialisation sequence with the device when plugged in to a USB port that uses ehci-pci.

Here's what I've found so far:

- The issue happens all the time when the device is plugged in to a USB port that uses ehci-pci. xhci_hcd USB ports work fine.

- The issue occurs when sending the first vendor-specific control input USB command, but only when sending from the kernel driver (that's scarlett2_usb() in mixer_scarlett_gen2.c). Sending the same USB packet from user-space with libusb works fine.

- "usbmon -s 10000 -fu" shows no difference between the messages sent in the success and failure cases:

working (packet sent from user-space):

ffff8881088b1d00 265130488 S Ci:2:029:0 s a1 00 0000 0005 0018 24 <
ffff8881088b1d00 265130569 C Ci:2:029:0 0 24 = 66191018 73190604 01000000 01000000 00040000 00000000

not working (same packet sent from kernel driver):

ffff88810be96d00 986255933 S Ci:2:030:0 s a1 00 0000 0005 0018 24 < ffff88810be96d00 991378740 C Ci:2:030:0 -2 0

- When I enabled ehci debugging, I still see no difference in the submitted packet between working and non-working:

kernel: ehci-pci 0000:00:1d.0: submit_async 1.2 urb 00000000de165beb ep0out len 24, qtd 0000000056de0c60 [qh 00000000d43a72d3]
kernel: ehci-pci 0000:00:1d.0: ehci_urb_done 1.2 urb 00000000de165beb ep0in status 0 len 24/24

kernel: ehci-pci 0000:00:1d.0: submit_async 1.2 urb 000000004f9d8dbb ep0out len 24, qtd 0000000055a1f6c8 [qh 00000000312c985a]
kernel: ehci-pci 0000:00:1d.0: ehci_urb_done 1.2 urb 000000004f9d8dbb ep0out status -115 len 0/24

- If I pass through the USB device to a KVM VM, it uses xhci_hcd within the VM and the driver initialisation succeeds even though the host is using ehci-pci.

Host:

[root@peta ~]# lsusb -d1235:
Bus 002 Device 011: ID 1235:8204 Focusrite-Novation Scarlett 18i8 2nd Gen [root@peta ~]# lsusb -t

/:  Bus 04.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/2p, 5000M
/:  Bus 03.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/2p, 480M
/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/3p, 480M
    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/8p, 480M
        |__ Port 2: Dev 11, If 0, Class=Audio, Driver=usbfs, 480M
        |__ Port 2: Dev 11, If 1, Class=Audio, Driver=usbfs, 480M
        |__ Port 2: Dev 11, If 2, Class=Audio, Driver=usbfs, 480M
        |__ Port 2: Dev 11, If 3, Class=Audio, Driver=usbfs, 480M
        |__ Port 2: Dev 11, If 4, Class=Audio, Driver=usbfs, 480M
        |__ Port 2: Dev 11, If 5, Class=Vendor Specific Class, Driver=usbfs, 480M
        |__ Port 6: Dev 4, If 0, Class=Wireless, Driver=btusb, 12M
        |__ Port 6: Dev 4, If 1, Class=Wireless, Driver=btusb, 12M
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/3p, 480M
    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/6p, 480M
        |__ Port 1: Dev 3, If 0, Class=Vendor Specific Class, Driver=, 12M
        |__ Port 5: Dev 4, If 0, Class=Video, Driver=uvcvideo, 480M
        |__ Port 5: Dev 4, If 1, Class=Video, Driver=uvcvideo, 480M

Guest VM:

[root@fedora ~]# lsusb -d1235:
Bus 001 Device 005: ID 1235:8204 Focusrite-Novation Scarlett 18i8 2nd Gen [root@fedora ~]# lsusb -t

/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/15p, 5000M
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/15p, 480M
    |__ Port 1: Dev 2, If 0, Class=Human Interface Device, Driver=usbhid, 480M
    |__ Port 4: Dev 5, If 3, Class=Audio, Driver=snd-usb-audio, 480M
    |__ Port 4: Dev 5, If 1, Class=Audio, Driver=snd-usb-audio, 480M
    |__ Port 4: Dev 5, If 4, Class=Audio, Driver=snd-usb-audio, 480M
    |__ Port 4: Dev 5, If 2, Class=Audio, Driver=snd-usb-audio, 480M
    |__ Port 4: Dev 5, If 0, Class=Audio, Driver=snd-usb-audio, 480M
    |__ Port 4: Dev 5, If 5, Class=Vendor Specific Class, Driver=, 480M

I also noticed that if a control output USB packet is sent first, it succeeds. When the next (control input) USB packet is sent, it fails.

This is what usbmon on the host shows when running the mixer driver in the guest:

ffff88811d4d4b00 4018863624 S Co:2:012:0 s 21 02 0000 0005 0010 16 = 00000000 00000000 00000000 00000000 ffff88811d4d4b00 4018863805 C Co:2:012:0 0 16 >
ffff88811d4d4e00 4018865148 S Ci:2:012:0 s a1 03 0000 0005 0010 16 <
ffff88811d4d4e00 4018865306 C Ci:2:012:0 0 16 = 00000000 00000000 00000000 00000000

And this is running the mixer driver on the host:

ffff8881d2672200 3822282593 S Co:2:011:0 s 21 02 0000 0005 0010 16 = 00000000 00000000 00000000 00000000 ffff8881d2672200 3822282804 C Co:2:011:0 0 16 >
ffff8881d2672700 3822282907 S Ci:2:011:0 s a1 03 0000 0005 0010 16 <
ffff8881d2672700 3827753258 C Ci:2:011:0 -2 0

Based on the above, it seems to me that the problem lies with the ehci-pci driver, but I am not sure where to go from here in tracking down the problem further. I learnt only just enough about USB in order to write this mixer driver, so problems that can't be debugged by staring at usbmon output for hours are beyond me :-).

Thanks in advance for any assistance in debugging this!

Regards,
Geoffrey.

Alan Stern

2021-05-19 14:52 UTC #1 lore raw

Quoted 22 lines · Geoffrey D. Bennett

Hi there,
I'm investigating an issue with the Focusrite Scarlett Gen 2 ALSA mixer driver (linux/sound/usb/mixer_scarlett_gen2.c) where the driver fails to correctly perform the proprietary USB initialisation sequence with the device when plugged in to a USB port that uses ehci-pci.
Here's what I've found so far:
- The issue happens all the time when the device is plugged in to a USB port that uses ehci-pci. xhci_hcd USB ports work fine.
- The issue occurs when sending the first vendor-specific control input USB command, but only when sending from the kernel driver (that's scarlett2_usb() in mixer_scarlett_gen2.c). Sending the same USB packet from user-space with libusb works fine.
- "usbmon -s 10000 -fu" shows no difference between the messages sent in the success and failure cases:
working (packet sent from user-space):

Quoted 7 lines

ffff8881088b1d00 265130488 S Ci:2:029:0 s a1 00 0000 0005 0018 24 <
ffff8881088b1d00 265130569 C Ci:2:029:0 0 24 = 66191018 73190604 01000000 01000000 00040000 00000000
not working (same packet sent from kernel driver):
ffff88810be96d00 986255933 S Ci:2:030:0 s a1 00 0000 0005 0018 24 < ffff88810be96d00 991378740 C Ci:2:030:0 -2 0

The actual packets sent by ehci-hcd are exactly the same, regardless of whether they were submitted by a kernel driver or by userspace. (In fact, userspace submits URBs by way of usbfs, which is itself a kernel driver.)

Quoted 70 lines

- When I enabled ehci debugging, I still see no difference in the submitted packet between working and non-working:
kernel: ehci-pci 0000:00:1d.0: submit_async 1.2 urb 00000000de165beb ep0out len 24, qtd 0000000056de0c60 [qh 00000000d43a72d3]
kernel: ehci-pci 0000:00:1d.0: ehci_urb_done 1.2 urb 00000000de165beb ep0in status 0 len 24/24
kernel: ehci-pci 0000:00:1d.0: submit_async 1.2 urb 000000004f9d8dbb ep0out len 24, qtd 0000000055a1f6c8 [qh 00000000312c985a]
kernel: ehci-pci 0000:00:1d.0: ehci_urb_done 1.2 urb 000000004f9d8dbb ep0out status -115 len 0/24
- If I pass through the USB device to a KVM VM, it uses xhci_hcd within the VM and the driver initialisation succeeds even though the host is using ehci-pci.
Host:
[root@peta ~]# lsusb -d1235:
Bus 002 Device 011: ID 1235:8204 Focusrite-Novation Scarlett 18i8 2nd Gen [root@peta ~]# lsusb -t
/:  Bus 04.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/2p, 5000M
/:  Bus 03.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/2p, 480M
/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/3p, 480M
    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/8p, 480M
        |__ Port 2: Dev 11, If 0, Class=Audio, Driver=usbfs, 480M
        |__ Port 2: Dev 11, If 1, Class=Audio, Driver=usbfs, 480M
        |__ Port 2: Dev 11, If 2, Class=Audio, Driver=usbfs, 480M
        |__ Port 2: Dev 11, If 3, Class=Audio, Driver=usbfs, 480M
        |__ Port 2: Dev 11, If 4, Class=Audio, Driver=usbfs, 480M
        |__ Port 2: Dev 11, If 5, Class=Vendor Specific Class, Driver=usbfs, 480M
        |__ Port 6: Dev 4, If 0, Class=Wireless, Driver=btusb, 12M
        |__ Port 6: Dev 4, If 1, Class=Wireless, Driver=btusb, 12M
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/3p, 480M
    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/6p, 480M
        |__ Port 1: Dev 3, If 0, Class=Vendor Specific Class, Driver=, 12M
        |__ Port 5: Dev 4, If 0, Class=Video, Driver=uvcvideo, 480M
        |__ Port 5: Dev 4, If 1, Class=Video, Driver=uvcvideo, 480M
Guest VM:
[root@fedora ~]# lsusb -d1235:
Bus 001 Device 005: ID 1235:8204 Focusrite-Novation Scarlett 18i8 2nd Gen [root@fedora ~]# lsusb -t
/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/15p, 5000M
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/15p, 480M
    |__ Port 1: Dev 2, If 0, Class=Human Interface Device, Driver=usbhid, 480M
    |__ Port 4: Dev 5, If 3, Class=Audio, Driver=snd-usb-audio, 480M
    |__ Port 4: Dev 5, If 1, Class=Audio, Driver=snd-usb-audio, 480M
    |__ Port 4: Dev 5, If 4, Class=Audio, Driver=snd-usb-audio, 480M
    |__ Port 4: Dev 5, If 2, Class=Audio, Driver=snd-usb-audio, 480M
    |__ Port 4: Dev 5, If 0, Class=Audio, Driver=snd-usb-audio, 480M
    |__ Port 4: Dev 5, If 5, Class=Vendor Specific Class, Driver=, 480M
I also noticed that if a control output USB packet is sent first, it succeeds. When the next (control input) USB packet is sent, it fails.
This is what usbmon on the host shows when running the mixer driver in the guest:
ffff88811d4d4b00 4018863624 S Co:2:012:0 s 21 02 0000 0005 0010 16 = 00000000 00000000 00000000 00000000 ffff88811d4d4b00 4018863805 C Co:2:012:0 0 16 >
ffff88811d4d4e00 4018865148 S Ci:2:012:0 s a1 03 0000 0005 0010 16 <
ffff88811d4d4e00 4018865306 C Ci:2:012:0 0 16 = 00000000 00000000 00000000 00000000
And this is running the mixer driver on the host:
ffff8881d2672200 3822282593 S Co:2:011:0 s 21 02 0000 0005 0010 16 = 00000000 00000000 00000000 00000000 ffff8881d2672200 3822282804 C Co:2:011:0 0 16 >
ffff8881d2672700 3822282907 S Ci:2:011:0 s a1 03 0000 0005 0010 16 <
ffff8881d2672700 3827753258 C Ci:2:011:0 -2 0

Quoted 7 lines

Based on the above, it seems to me that the problem lies with the ehci-pci driver, but I am not sure where to go from here in tracking down the problem further. I learnt only just enough about USB in order to write this mixer driver, so problems that can't be debugged by staring at usbmon output for hours are beyond me :-).
Thanks in advance for any assistance in debugging this!

This is a puzzling problem, no doubt about it.

Since the information you have included here shows no difference in the actions that work and the actions that lead to an error, I guess that what matters is something you didn't include: the context leading up to the error.

Have you looked at a complete usbmon record of _all_ the packets sent, starting from the time when the Focusrite Scarlett mixer is plugged in? It could be that some difference in the sequence of packets leading up to the one in question is what triggers the error.

Alan Stern

Geoffrey D. Bennett

author

2021-05-20 18:08 UTC #2 lore raw

Hi Alan,

Thank you so much for your help! With your hint...

On Wed, May 19, 2021 at 10:52:46AM -0400, Alan Stern wrote:
[...]

Quoted 4 lines

The actual packets sent by ehci-hcd are exactly the same, regardless of whether they were submitted by a kernel driver or by userspace. (In fact, userspace submits URBs by way of usbfs, which is itself a kernel driver.)

...I started comparing how usbfs submitted the packet in do_proc_control() vs. how I was submitting the packet.

It turns out that in the name usb_sndctrlpipe(), "snd" is *not* shorthand for "sound", but is in fact "send". So...

sound/usb/mixer_scarlett_gen2.c +1 -1

index 560c2ade829d..dcff3e3a49f3 100644
@@ -635,7 +635,7 @@ static int scarlett2_usb(
        /* send a second message to get the response */
 
        err = snd_usb_ctl_msg(mixer->chip->dev,
-                       usb_sndctrlpipe(mixer->chip->dev, 0),
+                       usb_rcvctrlpipe(mixer->chip->dev, 0),
                        SCARLETT2_USB_VENDOR_SPECIFIC_CMD_RESP,
                        USB_RECIP_INTERFACE | USB_TYPE_CLASS | USB_DIR_IN,
                        0,

...works for me now. I will prepare and submit a patch to alsa-devel.

[...]

Quoted 4 lines

Have you looked at a complete usbmon record of _all_ the packets sent, starting from the time when the Focusrite Scarlett mixer is plugged in? It could be that some difference in the sequence of packets leading up to the one in question is what triggers the error.

That's what I actually thought the problem was for such a long time until I could do a test setup that produced a clean diff of all the packets from plug-in between working and not working which is what led me here.

I'm not sure if there's anything that could reasonably be added to make this sort of error easier to spot, such as warn if the pipe direction doesn't match the requesttype direction? Or have the ehci driver fix it up like the xhci driver appears to do?

A small aside; I did notice that usb_sndctrlpipe(dev, 0) is evaluated twice in do_proc_control(), vs. usb_rcvctrlpipe(dev, 0) which is not; you might like to make this change:

drivers/usb/core/devio.c +1 -1

index 533236366a03..4a8ec136460c 100644
@@ -1162,7 +1162,7 @@ static int do_proc_control(struct usb_dev_state *ps,
 			tbuf, ctrl->wLength);
 
 		usb_unlock_device(dev);
-		i = usb_control_msg(dev, usb_sndctrlpipe(dev, 0), ctrl->bRequest,
+		i = usb_control_msg(dev, pipe, ctrl->bRequest,
 				    ctrl->bRequestType, ctrl->wValue, ctrl->wIndex,
 				    tbuf, ctrl->wLength, tmo);
 		usb_lock_device(dev);

Thanks again!

Regards,
Geoffrey.

Alan Stern

2021-05-20 18:42 UTC #3 lore raw

Quoted 31 lines · Geoffrey D. Bennett

Hi Alan,
Thank you so much for your help! With your hint...
On Wed, May 19, 2021 at 10:52:46AM -0400, Alan Stern wrote:
[...]
Quoted 4 lines
The actual packets sent by ehci-hcd are exactly the same, regardless of whether they were submitted by a kernel driver or by userspace. (In fact, userspace submits URBs by way of usbfs, which is itself a kernel driver.)
...I started comparing how usbfs submitted the packet in do_proc_control() vs. how I was submitting the packet.
It turns out that in the name usb_sndctrlpipe(), "snd" is *not* shorthand for "sound", but is in fact "send". So...
sound/usb/mixer_scarlett_gen2.c +1 -1
index 560c2ade829d..dcff3e3a49f3 100644
@@ -635,7 +635,7 @@ static int scarlett2_usb(
        /* send a second message to get the response */
 
        err = snd_usb_ctl_msg(mixer->chip->dev,
-                       usb_sndctrlpipe(mixer->chip->dev, 0),
+                       usb_rcvctrlpipe(mixer->chip->dev, 0),
                        SCARLETT2_USB_VENDOR_SPECIFIC_CMD_RESP,
                        USB_RECIP_INTERFACE | USB_TYPE_CLASS | USB_DIR_IN,
                        0,

Quoted 1 line

...works for me now. I will prepare and submit a patch to alsa-devel.

Glad I could help.

Quoted 11 lines

[...]
Quoted 4 lines
Have you looked at a complete usbmon record of _all_ the packets sent, starting from the time when the Focusrite Scarlett mixer is plugged in? It could be that some difference in the sequence of packets leading up to the one in question is what triggers the error.
That's what I actually thought the problem was for such a long time until I could do a test setup that produced a clean diff of all the packets from plug-in between working and not working which is what led me here.

Quoted 4 lines

I'm not sure if there's anything that could reasonably be added to make this sort of error easier to spot, such as warn if the pipe direction doesn't match the requesttype direction? Or have the ehci driver fix it up like the xhci driver appears to do?

Adding a check for the directions seems like a good idea. I'll do it.

Quoted 9 lines

A small aside; I did notice that usb_sndctrlpipe(dev, 0) is evaluated twice in do_proc_control(), vs. usb_rcvctrlpipe(dev, 0) which is not; you might like to make this change:
drivers/usb/core/devio.c +0 -0
index 533236366a03..4a8ec136460c 100644

drivers/usb/core/devio.c static int do_proc_control(struct usb_dev_state *ps, · line 1168

Quoted 8 lines

drivers/usb/core/devio.c +1 -1

@@ -1162,7 +1162,7 @@ static int do_proc_control(struct usb_dev_state *ps,
 			tbuf, ctrl->wLength);
 
 		usb_unlock_device(dev);
-		i = usb_control_msg(dev, usb_sndctrlpipe(dev, 0), ctrl->bRequest,
+		i = usb_control_msg(dev, pipe, ctrl->bRequest,
 				    ctrl->bRequestType, ctrl->wValue, ctrl->wIndex,
 				    tbuf, ctrl->wLength, tmo);
 		usb_lock_device(dev);

If you'd like to submit a real patch for this, I'll be happy to accept it.

Alan Stern