ehci-pci: Scarlett Gen 2 mixer driver init failure

ehci-pci: Scarlett Gen 2 mixer driver init failure

[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):

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.

Re: ehci-pci: Scarlett Gen 2 mixer driver init failure

[Alan Stern]

On Wed, May 19, 2021 at 05:58:23AM +0930, Geoffrey D. Bennett wrote:
> 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

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.)

> 
> - 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!

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

Re: ehci-pci: Scarlett Gen 2 mixer driver init failure

[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:
[...]
> 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...

diff --git a/sound/usb/mixer_scarlett_gen2.c b/sound/usb/mixer_scarlett_gen2.c
index 560c2ade829d..dcff3e3a49f3 100644
--- a/sound/usb/mixer_scarlett_gen2.c
+++ b/sound/usb/mixer_scarlett_gen2.c
@@ -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.

[...]
> 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:

diff --git a/drivers/usb/core/devio.c b/drivers/usb/core/devio.c
index 533236366a03..4a8ec136460c 100644
--- a/drivers/usb/core/devio.c
+++ b/drivers/usb/core/devio.c
@@ -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.

Re: ehci-pci: Scarlett Gen 2 mixer driver init failure

[Alan Stern]

On Fri, May 21, 2021 at 03:38:19AM +0930, Geoffrey D. Bennett wrote:
> 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:
> [...]
> > 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...
> 
> diff --git a/sound/usb/mixer_scarlett_gen2.c b/sound/usb/mixer_scarlett_gen2.c
> index 560c2ade829d..dcff3e3a49f3 100644
> --- a/sound/usb/mixer_scarlett_gen2.c
> +++ b/sound/usb/mixer_scarlett_gen2.c
> @@ -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.

Glad I could help.

> [...]
> > 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?

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

> 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:
> 
> diff --git a/drivers/usb/core/devio.c b/drivers/usb/core/devio.c
> index 533236366a03..4a8ec136460c 100644
> --- a/drivers/usb/core/devio.c
> +++ b/drivers/usb/core/devio.c
> @@ -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