[BUG] ALSA: usb-audio: Scarlett 2 mixer driver fails on ehci-pci

[BUG] ALSA: usb-audio: Scarlett 2 mixer driver fails on ehci-pci

[Geoffrey D. Bennett]

Hi there,

I'm trying to track down an issue with my Scarlett Gen 2 mixer driver
that has been reported by a few people, and I can now reliably
reproduce the issue, but I need some help in figuring out where
exactly the issue is and how to fix it please.

The issue only occurs when attempting to use the interface on a USB
port using ehci-pci. xhci_hcd USB ports work fine.

The issue occurs when sending the first vendor-specific USB command,
but only when sending from the kernel driver. Sending the same USB
packets from user-space works fine(!).

I did initially think that the fault could have been due to earlier
USB messages putting the device into a state where it would reject the
vendor-specific USB commands, but I have carefully ruled that out &
have gotten identical usbmon traces from device power-on up until the
device responds differently, the only difference beforehand being
whether the USB packet was sent from the kernel driver or user-space.

The messages look like this in "usbmon -s 10000 -fu" when sent from
user-space (or when sent from the kernel driver when the interface is
plugged in to an xhci_hcd port):

ffff888125855200 1006026497 S Ci:2:040:0 s a1 00 0000 0005 0018 24 <
ffff888125855200 1006026680 C Ci:2:040:0 0 24 = 66191018 73190604 01000000 01000000 00040000 00000000

And like this when sent from the kernel driver when the interface is
plugged in to an ehci-pci port:

ffff88810487a300 3686673995 S Ci:2:036:0 s a1 00 0000 0005 0018 24 <
ffff88810487a300 3692178724 C Ci:2:036:0 -2 0

Identical messages sent according to usbmon, but they must be
different somehow!

The kernel code to send that message looks like this:

  return snd_usb_ctl_msg(
    dev, usb_sndctrlpipe(dev, 0),
    usb_req,
    USB_RECIP_INTERFACE | USB_TYPE_CLASS | USB_DIR_IN,
    0, interface, buf, size);

and helper.c snd_usb_ctl_msg() then calls usb_control_msg().

For sending arbitrary USB packets from user-space for testing, I'm
using libusb and:

  int ret = usb_control_msg(
    devh, reqtype, request, value, index, buf, size, 1000
  );

So, I presume usbmon isn't giving me the full story? How can I
determine the difference between the kernel and the user-space
usb_control_msg() functions? I see that I can #define EHCI_URB_TRACE
in ehci-hcd.c. Can anyone with more experience than me let me know if
I'm going in the right direction to track this down?

Thanks,
Geoffrey.

Re: [BUG] ALSA: usb-audio: Scarlett 2 mixer driver fails on ehci-pci

[Geraldo Nascimento]

Hi, Geoffrey, have you tried adding "ehci_hcd.dyndbg=+p" to your
kernel boot options?

It will give you additional debugging information, and if you need
more debugging information you can always use printk() and recompile
your modules.

Note that your issue seems more related to USB kernel development than
ALSA development, still, impossible to say where the fix will land
without tracing the problem first.

Best of luck,
Geraldo Nascimento

On Mon, May 17, 2021 at 2:27 PM Geoffrey D. Bennett <g@b4.vu> wrote:
>
> Hi there,
>
> I'm trying to track down an issue with my Scarlett Gen 2 mixer driver
> that has been reported by a few people, and I can now reliably
> reproduce the issue, but I need some help in figuring out where
> exactly the issue is and how to fix it please.
>
> The issue only occurs when attempting to use the interface on a USB
> port using ehci-pci. xhci_hcd USB ports work fine.
>
> The issue occurs when sending the first vendor-specific USB command,
> but only when sending from the kernel driver. Sending the same USB
> packets from user-space works fine(!).
>
> I did initially think that the fault could have been due to earlier
> USB messages putting the device into a state where it would reject the
> vendor-specific USB commands, but I have carefully ruled that out &
> have gotten identical usbmon traces from device power-on up until the
> device responds differently, the only difference beforehand being
> whether the USB packet was sent from the kernel driver or user-space.
>
> The messages look like this in "usbmon -s 10000 -fu" when sent from
> user-space (or when sent from the kernel driver when the interface is
> plugged in to an xhci_hcd port):
>
> ffff888125855200 1006026497 S Ci:2:040:0 s a1 00 0000 0005 0018 24 <
> ffff888125855200 1006026680 C Ci:2:040:0 0 24 = 66191018 73190604 01000000 01000000 00040000 00000000
>
> And like this when sent from the kernel driver when the interface is
> plugged in to an ehci-pci port:
>
> ffff88810487a300 3686673995 S Ci:2:036:0 s a1 00 0000 0005 0018 24 <
> ffff88810487a300 3692178724 C Ci:2:036:0 -2 0
>
> Identical messages sent according to usbmon, but they must be
> different somehow!
>
> The kernel code to send that message looks like this:
>
>   return snd_usb_ctl_msg(
>     dev, usb_sndctrlpipe(dev, 0),
>     usb_req,
>     USB_RECIP_INTERFACE | USB_TYPE_CLASS | USB_DIR_IN,
>     0, interface, buf, size);
>
> and helper.c snd_usb_ctl_msg() then calls usb_control_msg().
>
> For sending arbitrary USB packets from user-space for testing, I'm
> using libusb and:
>
>   int ret = usb_control_msg(
>     devh, reqtype, request, value, index, buf, size, 1000
>   );
>
> So, I presume usbmon isn't giving me the full story? How can I
> determine the difference between the kernel and the user-space
> usb_control_msg() functions? I see that I can #define EHCI_URB_TRACE
> in ehci-hcd.c. Can anyone with more experience than me let me know if
> I'm going in the right direction to track this down?
>
> Thanks,
> Geoffrey.

Re: [BUG] ALSA: usb-audio: Scarlett 2 mixer driver fails on ehci-pci

[Geoffrey D. Bennett]

Hi Geraldo,

Thanks for your suggestion. I found:

echo module ehci_hcd +p > /sys/kernel/debug/dynamic_debug/control

which I guess is the same thing.

I can't see any difference between the sent USB packet working and not
working with the additional debug:

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

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

I agree that the issue seems more related to USB kernel development; I
will subscribe to linux-usb and ask there.

Thanks,
Geoffrey.

On Mon, May 17, 2021 at 07:13:27PM -0300, Geraldo Nascimento wrote:
> Hi, Geoffrey, have you tried adding "ehci_hcd.dyndbg=+p" to your
> kernel boot options?
> 
> It will give you additional debugging information, and if you need
> more debugging information you can always use printk() and recompile
> your modules.
> 
> Note that your issue seems more related to USB kernel development than
> ALSA development, still, impossible to say where the fix will land
> without tracing the problem first.
> 
> Best of luck,
> Geraldo Nascimento
> 
> On Mon, May 17, 2021 at 2:27 PM Geoffrey D. Bennett <g@b4.vu> wrote:
> >
> > Hi there,
> >
> > I'm trying to track down an issue with my Scarlett Gen 2 mixer driver
> > that has been reported by a few people, and I can now reliably
> > reproduce the issue, but I need some help in figuring out where
> > exactly the issue is and how to fix it please.
> >
> > The issue only occurs when attempting to use the interface on a USB
> > port using ehci-pci. xhci_hcd USB ports work fine.
> >
> > The issue occurs when sending the first vendor-specific USB command,
> > but only when sending from the kernel driver. Sending the same USB
> > packets from user-space works fine(!).
> >
> > I did initially think that the fault could have been due to earlier
> > USB messages putting the device into a state where it would reject the
> > vendor-specific USB commands, but I have carefully ruled that out &
> > have gotten identical usbmon traces from device power-on up until the
> > device responds differently, the only difference beforehand being
> > whether the USB packet was sent from the kernel driver or user-space.
> >
> > The messages look like this in "usbmon -s 10000 -fu" when sent from
> > user-space (or when sent from the kernel driver when the interface is
> > plugged in to an xhci_hcd port):
> >
> > ffff888125855200 1006026497 S Ci:2:040:0 s a1 00 0000 0005 0018 24 <
> > ffff888125855200 1006026680 C Ci:2:040:0 0 24 = 66191018 73190604 01000000 01000000 00040000 00000000
> >
> > And like this when sent from the kernel driver when the interface is
> > plugged in to an ehci-pci port:
> >
> > ffff88810487a300 3686673995 S Ci:2:036:0 s a1 00 0000 0005 0018 24 <
> > ffff88810487a300 3692178724 C Ci:2:036:0 -2 0
> >
> > Identical messages sent according to usbmon, but they must be
> > different somehow!
> >
> > The kernel code to send that message looks like this:
> >
> >   return snd_usb_ctl_msg(
> >     dev, usb_sndctrlpipe(dev, 0),
> >     usb_req,
> >     USB_RECIP_INTERFACE | USB_TYPE_CLASS | USB_DIR_IN,
> >     0, interface, buf, size);
> >
> > and helper.c snd_usb_ctl_msg() then calls usb_control_msg().
> >
> > For sending arbitrary USB packets from user-space for testing, I'm
> > using libusb and:
> >
> >   int ret = usb_control_msg(
> >     devh, reqtype, request, value, index, buf, size, 1000
> >   );
> >
> > So, I presume usbmon isn't giving me the full story? How can I
> > determine the difference between the kernel and the user-space
> > usb_control_msg() functions? I see that I can #define EHCI_URB_TRACE
> > in ehci-hcd.c. Can anyone with more experience than me let me know if
> > I'm going in the right direction to track this down?
> >
> > Thanks,
> > Geoffrey.

Re: [BUG] ALSA: usb-audio: Scarlett 2 mixer driver fails on ehci-pci

[Geraldo Nascimento]

On Tue, May 18, 2021 at 3:34 PM Geoffrey D. Bennett <g@b4.vu> wrote:
>
> Hi Geraldo,
>
> Thanks for your suggestion. I found:
>
> echo module ehci_hcd +p > /sys/kernel/debug/dynamic_debug/control
>
> which I guess is the same thing.

Cool, if you always connect the hardware after issuing that sysfs
change I guess you won't run into any problems with missing debugging
info.

>
> I can't see any difference between the sent USB packet working and not
> working with the additional debug:
>
> 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
>
> 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
>
> I agree that the issue seems more related to USB kernel development; I
> will subscribe to linux-usb and ask there.

Myself I'd hook printk()'s to both ehci_hcd and xhci_hcd to print
every possible variable involved and see if there's any relevant
mismatches. Oh and watch with the printk()'s what libusb seems to be
doing, too.

When you subscribe to linux-usb you *may* want to Cc: Greg
Kroah-Hartman with your discoveries so far, he's the USB Subsystem
Maintainer and the best one to help you track this down.

Regards,
Geraldo Nascimento

>
> Thanks,
> Geoffrey.
>
> On Mon, May 17, 2021 at 07:13:27PM -0300, Geraldo Nascimento wrote:
> > Hi, Geoffrey, have you tried adding "ehci_hcd.dyndbg=+p" to your
> > kernel boot options?
> >
> > It will give you additional debugging information, and if you need
> > more debugging information you can always use printk() and recompile
> > your modules.
> >
> > Note that your issue seems more related to USB kernel development than
> > ALSA development, still, impossible to say where the fix will land
> > without tracing the problem first.
> >
> > Best of luck,
> > Geraldo Nascimento
> >
> > On Mon, May 17, 2021 at 2:27 PM Geoffrey D. Bennett <g@b4.vu> wrote:
> > >
> > > Hi there,
> > >
> > > I'm trying to track down an issue with my Scarlett Gen 2 mixer driver
> > > that has been reported by a few people, and I can now reliably
> > > reproduce the issue, but I need some help in figuring out where
> > > exactly the issue is and how to fix it please.
> > >
> > > The issue only occurs when attempting to use the interface on a USB
> > > port using ehci-pci. xhci_hcd USB ports work fine.
> > >
> > > The issue occurs when sending the first vendor-specific USB command,
> > > but only when sending from the kernel driver. Sending the same USB
> > > packets from user-space works fine(!).
> > >
> > > I did initially think that the fault could have been due to earlier
> > > USB messages putting the device into a state where it would reject the
> > > vendor-specific USB commands, but I have carefully ruled that out &
> > > have gotten identical usbmon traces from device power-on up until the
> > > device responds differently, the only difference beforehand being
> > > whether the USB packet was sent from the kernel driver or user-space.
> > >
> > > The messages look like this in "usbmon -s 10000 -fu" when sent from
> > > user-space (or when sent from the kernel driver when the interface is
> > > plugged in to an xhci_hcd port):
> > >
> > > ffff888125855200 1006026497 S Ci:2:040:0 s a1 00 0000 0005 0018 24 <
> > > ffff888125855200 1006026680 C Ci:2:040:0 0 24 = 66191018 73190604 01000000 01000000 00040000 00000000
> > >
> > > And like this when sent from the kernel driver when the interface is
> > > plugged in to an ehci-pci port:
> > >
> > > ffff88810487a300 3686673995 S Ci:2:036:0 s a1 00 0000 0005 0018 24 <
> > > ffff88810487a300 3692178724 C Ci:2:036:0 -2 0
> > >
> > > Identical messages sent according to usbmon, but they must be
> > > different somehow!
> > >
> > > The kernel code to send that message looks like this:
> > >
> > >   return snd_usb_ctl_msg(
> > >     dev, usb_sndctrlpipe(dev, 0),
> > >     usb_req,
> > >     USB_RECIP_INTERFACE | USB_TYPE_CLASS | USB_DIR_IN,
> > >     0, interface, buf, size);
> > >
> > > and helper.c snd_usb_ctl_msg() then calls usb_control_msg().
> > >
> > > For sending arbitrary USB packets from user-space for testing, I'm
> > > using libusb and:
> > >
> > >   int ret = usb_control_msg(
> > >     devh, reqtype, request, value, index, buf, size, 1000
> > >   );
> > >
> > > So, I presume usbmon isn't giving me the full story? How can I
> > > determine the difference between the kernel and the user-space
> > > usb_control_msg() functions? I see that I can #define EHCI_URB_TRACE
> > > in ehci-hcd.c. Can anyone with more experience than me let me know if
> > > I'm going in the right direction to track this down?
> > >
> > > Thanks,
> > > Geoffrey.

Re: [BUG] ALSA: usb-audio: Scarlett 2 mixer driver fails on ehci-pci

[Geoffrey D. Bennett]

On Tue, May 18, 2021 at 06:41:45PM -0300, Geraldo Nascimento wrote:
[...]
> Myself I'd hook printk()'s to both ehci_hcd and xhci_hcd to print
> every possible variable involved and see if there's any relevant
> mismatches. Oh and watch with the printk()'s what libusb seems to be
> doing, too.
> 
> When you subscribe to linux-usb you *may* want to Cc: Greg
> Kroah-Hartman with your discoveries so far, he's the USB Subsystem
> Maintainer and the best one to help you track this down.

Thanks for the pointers!

It turns out that usb_sndctrlpipe() is not short for "USB sound
control pipe".

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,

I'll properly submit the patch once I've got confirmation from someone
else that this fixes the issue.

Thanks again,
Geoffrey.

Re: [BUG] ALSA: usb-audio: Scarlett 2 mixer driver fails on ehci-pci

[Geraldo Nascimento]

On Thu, May 20, 2021 at 3:14 PM Geoffrey D. Bennett <g@b4.vu> wrote:
>
> On Tue, May 18, 2021 at 06:41:45PM -0300, Geraldo Nascimento wrote:
> [...]
> > Myself I'd hook printk()'s to both ehci_hcd and xhci_hcd to print
> > every possible variable involved and see if there's any relevant
> > mismatches. Oh and watch with the printk()'s what libusb seems to be
> > doing, too.
> >
> > When you subscribe to linux-usb you *may* want to Cc: Greg
> > Kroah-Hartman with your discoveries so far, he's the USB Subsystem
> > Maintainer and the best one to help you track this down.
>
> Thanks for the pointers!
>
> It turns out that usb_sndctrlpipe() is not short for "USB sound
> control pipe".
>
> 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,
>
> I'll properly submit the patch once I've got confirmation from someone
> else that this fixes the issue.

Good, I also think the correct pipe to use together with USB_DIR_IN is
indeed usb_rcvctrlpipe().

>
> Thanks again,
> Geoffrey.