On Mon, Dec 09, 2019 at 11:01:30AM +0900, Suwan Kim wrote:
> On Fri, Dec 06, 2019 at 09:57:42PM +0100, Marek Marczykowski-Górecki wrote:
> > On Fri, Dec 06, 2019 at 03:50:58PM +0900, Suwan Kim wrote:
> > > On Fri, Dec 06, 2019 at 04:24:06AM +0100, Marek Marczykowski-Górecki wrote:
> > > > Hello,
> > > >
> > > > I've hit an issue with recent 4.19 and 5.4 kernels. In short: if I
> > > > connect Yubikey 4 and use its CCID interface (for example `ykman oath
> > > > list` command), the client side hangs (100% reliably). After 60s I get a
> > > > message that a CPU hangs waiting for a spinlock (see below).
> > > >
> > > > I've bisected it to a ea44d190764b4422af ("usbip: Implement SG support
> > > > to vhci-hcd and stub driver") commit. Which indeed is also backported to
> > > > 4.19.
> > > >
> > > > Any idea what is going on here? I can easily provide more information,
> > > > if you tell me how to get it.
> > > >
> > >
> > > Hi,
> > >
> > > Thanks for reporting. Could you turn on lockdep and USBIP_DEBUG
> > > in kernel config and send dmesg log? It will be helpful to figure
> > > out lock dependency in vhci_hcd.
> >
> > Hmm, I've tried, but I don't see much more information there (see
> > below). I've just enabled PROVE_LOCKING and USBIP_DEBUG. Do I need to do
> > anything more, like some boot option?
> >
> > Also, this one (as the previous one) is from 4.19.84. Interestingly, on
> > 4.19.87 I don't get the message at all.
> >
> > Hmm, I've done also another test: got 4.19.84 with "usbip: Implement SG
> > support to vhci-hcd and stub driver" reverted and it still hangs...
>
> If so, deadlock is caused by other causes, and why is it different
> from the results of bisect?
No idea, but as you've seen in the other email, another bisect returned
exactly the same commit.
> > I'm going for another bisect round (4.19.81 works, 4.19.84 doesn't).
> >
> > [ 212.890519] usb 1-1: recv xbuf, 42
>
> This message is printed by receive error and before that, driver
> canceled URB transmission. we need to know the exact situation
> before this message.
I've added some more messages and found recv_size is 0.
> Could you send me a longer log messages showing the situation
> before "[ 212.890519] usb 1-1: recv xbuf, 42"?
Sure, with added extra messages (debug patch below).
[ 131.397522] usb 1-1: num_sgs 0
[ 131.406588] usb 1-1: num_sgs 0
[ 131.410621] usb 1-1: num_sgs 0
[ 131.411950] usb 1-1: num_sgs 0
[ 131.413186] usb 1-1: num_sgs 0
[ 131.414590] usb 1-1: num_sgs 0
[ 131.417086] usb 1-1: num_sgs 0
[ 131.418188] usb 1-1: num_sgs 0
[ 131.419228] usb 1-1: num_sgs 0
[ 131.420248] usb 1-1: num_sgs 0
[ 131.457315] usb 1-1: num_sgs 5
[ 131.457345] usb 1-1: size 42, copy 42 recv 42, recv_size 42, sg->length 16384
[ 131.457359] usb 1-1: size 42, copy 0 recv -22, recv_size 0, sg->length 16384
[ 131.457372] usb 1-1: recv xbuf, 42 size 42
[ 131.458263] vhci_hcd: vhci_shutdown_connection:1024: stop threads
[ 131.458318] vhci_hcd: vhci_shutdown_connection:1032: release socket
[ 131.458431] vhci_hcd: vhci_shutdown_connection:1058: disconnect device
[ 131.460171] usb 1-1: USB disconnect, device number 2
(...)
If I add "if (!recv_size) continue;" there, it works!
> And please also send the result of "lsusb -v".
Bus 003 Device 006: ID 1050:0407 Yubico.com Yubikey 4 OTP+U2F+CCID
Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 2.00
bDeviceClass 0
bDeviceSubClass 0
bDeviceProtocol 0
bMaxPacketSize0 64
idVendor 0x1050 Yubico.com
idProduct 0x0407 Yubikey 4 OTP+U2F+CCID
bcdDevice 4.34
iManufacturer 1 Yubico
iProduct 2 Yubikey 4 OTP+U2F+CCID
iSerial 0
bNumConfigurations 1
Configuration Descriptor:
bLength 9
bDescriptorType 2
wTotalLength 0x0096
bNumInterfaces 3
bConfigurationValue 1
iConfiguration 0
bmAttributes 0x80
(Bus Powered)
MaxPower 30mA
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 0
bAlternateSetting 0
bNumEndpoints 1
bInterfaceClass 3 Human Interface Device
bInterfaceSubClass 1 Boot Interface Subclass
bInterfaceProtocol 1 Keyboard
iInterface 0
HID Device Descriptor:
bLength 9
bDescriptorType 33
bcdHID 1.10
bCountryCode 0 Not supported
bNumDescriptors 1
bDescriptorType 34 Report
wDescriptorLength 71
Report Descriptor: (length is 71)
Item(Global): Usage Page, data= [ 0x01 ] 1
Generic Desktop Controls
Item(Local ): Usage, data= [ 0x06 ] 6
Keyboard
Item(Main ): Collection, data= [ 0x01 ] 1
Application
Item(Global): Usage Page, data= [ 0x07 ] 7
Keyboard
Item(Local ): Usage Minimum, data= [ 0xe0 ] 224
Control Left
Item(Local ): Usage Maximum, data= [ 0xe7 ] 231
GUI Right
Item(Global): Logical Minimum, data= [ 0x00 ] 0
Item(Global): Logical Maximum, data= [ 0x01 ] 1
Item(Global): Report Size, data= [ 0x01 ] 1
Item(Global): Report Count, data= [ 0x08 ] 8
Item(Main ): Input, data= [ 0x02 ] 2
Data Variable Absolute No_Wrap Linear
Preferred_State No_Null_Position Non_Volatile Bitfield
Item(Global): Report Count, data= [ 0x01 ] 1
Item(Global): Report Size, data= [ 0x08 ] 8
Item(Main ): Input, data= [ 0x01 ] 1
Constant Array Absolute No_Wrap Linear
Preferred_State No_Null_Position Non_Volatile Bitfield
Item(Global): Report Count, data= [ 0x05 ] 5
Item(Global): Report Size, data= [ 0x01 ] 1
Item(Global): Usage Page, data= [ 0x08 ] 8
LEDs
Item(Local ): Usage Minimum, data= [ 0x01 ] 1
NumLock
Item(Local ): Usage Maximum, data= [ 0x05 ] 5
Kana
Item(Main ): Output, data= [ 0x02 ] 2
Data Variable Absolute No_Wrap Linear
Preferred_State No_Null_Position Non_Volatile Bitfield
Item(Global): Report Count, data= [ 0x01 ] 1
Item(Global): Report Size, data= [ 0x03 ] 3
Item(Main ): Output, data= [ 0x01 ] 1
Constant Array Absolute No_Wrap Linear
Preferred_State No_Null_Position Non_Volatile Bitfield
Item(Global): Report Count, data= [ 0x06 ] 6
Item(Global): Report Size, data= [ 0x08 ] 8
Item(Global): Logical Minimum, data= [ 0x00 ] 0
Item(Global): Logical Maximum, data= [ 0x65 ] 101
Item(Global): Usage Page, data= [ 0x07 ] 7
Keyboard
Item(Local ): Usage Minimum, data= [ 0x00 ] 0
No Event
Item(Local ): Usage Maximum, data= [ 0x65 ] 101
Keyboard Application (Windows Key for Win95 or Compose)
Item(Main ): Input, data= [ 0x00 ] 0
Data Array Absolute No_Wrap Linear
Preferred_State No_Null_Position Non_Volatile Bitfield
Item(Local ): Usage, data= [ 0x03 ] 3
Keyboard Error Undefined
Item(Global): Report Size, data= [ 0x08 ] 8
Item(Global): Report Count, data= [ 0x08 ] 8
Item(Main ): Feature, data= [ 0x02 ] 2
Data Variable Absolute No_Wrap Linear
Preferred_State No_Null_Position Non_Volatile Bitfield
Item(Main ): End Collection, data=none
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x81 EP 1 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type None
Usage Type Data
wMaxPacketSize 0x0008 1x 8 bytes
bInterval 10
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 1
bAlternateSetting 0
bNumEndpoints 2
bInterfaceClass 3 Human Interface Device
bInterfaceSubClass 0
bInterfaceProtocol 0
iInterface 0
HID Device Descriptor:
bLength 9
bDescriptorType 33
bcdHID 1.10
bCountryCode 0 Not supported
bNumDescriptors 1
bDescriptorType 34 Report
wDescriptorLength 34
Report Descriptor: (length is 34)
Item(Global): Usage Page, data= [ 0xd0 0xf1 ] 61904
(null)
Item(Local ): Usage, data= [ 0x01 ] 1
(null)
Item(Main ): Collection, data= [ 0x01 ] 1
Application
Item(Local ): Usage, data= [ 0x20 ] 32
(null)
Item(Global): Logical Minimum, data= [ 0x00 ] 0
Item(Global): Logical Maximum, data= [ 0xff 0x00 ] 255
Item(Global): Report Size, data= [ 0x08 ] 8
Item(Global): Report Count, data= [ 0x40 ] 64
Item(Main ): Input, data= [ 0x02 ] 2
Data Variable Absolute No_Wrap Linear
Preferred_State No_Null_Position Non_Volatile Bitfield
Item(Local ): Usage, data= [ 0x21 ] 33
(null)
Item(Global): Logical Minimum, data= [ 0x00 ] 0
Item(Global): Logical Maximum, data= [ 0xff 0x00 ] 255
Item(Global): Report Size, data= [ 0x08 ] 8
Item(Global): Report Count, data= [ 0x40 ] 64
Item(Main ): Output, data= [ 0x02 ] 2
Data Variable Absolute No_Wrap Linear
Preferred_State No_Null_Position Non_Volatile Bitfield
Item(Main ): End Collection, data=none
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x04 EP 4 OUT
bmAttributes 3
Transfer Type Interrupt
Synch Type None
Usage Type Data
wMaxPacketSize 0x0040 1x 64 bytes
bInterval 2
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x84 EP 4 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type None
Usage Type Data
wMaxPacketSize 0x0040 1x 64 bytes
bInterval 2
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 2
bAlternateSetting 0
bNumEndpoints 3
bInterfaceClass 11 Chip/SmartCard
bInterfaceSubClass 0
bInterfaceProtocol 0
iInterface 0
ChipCard Interface Descriptor:
bLength 54
bDescriptorType 33
bcdCCID 1.00
nMaxSlotIndex 0
bVoltageSupport 7 5.0V 3.0V 1.8V
dwProtocols 2 T=1
dwDefaultClock 4000
dwMaxiumumClock 4000
bNumClockSupported 0
dwDataRate 307200 bps
dwMaxDataRate 307200 bps
bNumDataRatesSupp. 0
dwMaxIFSD 2038
dwSyncProtocols 00000000
dwMechanical 00000000
dwFeatures 000400FE
Auto configuration based on ATR
Auto activation on insert
Auto voltage selection
Auto clock change
Auto baud rate change
Auto parameter negotiation made by CCID
Short and extended APDU level exchange
dwMaxCCIDMsgLen 3072
bClassGetResponse echo
bClassEnvelope echo
wlcdLayout none
bPINSupport 0
bMaxCCIDBusySlots 1
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x02 EP 2 OUT
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0040 1x 64 bytes
bInterval 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x82 EP 2 IN
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0040 1x 64 bytes
bInterval 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x83 EP 3 IN
bmAttributes 3
Transfer Type Interrupt
Synch Type None
Usage Type Data
wMaxPacketSize 0x0008 1x 8 bytes
bInterval 32
Device Status: 0x0000
(Bus Powered)
And the debug patch:
diff --git a/drivers/usb/usbip/usbip_common.c b/drivers/usb/usbip/usbip_common.c
index d88a5b15f..89b87d5ed 100644
--- a/drivers/usb/usbip/usbip_common.c
+++ b/drivers/usb/usbip/usbip_common.c
@@ -709,6 +709,7 @@ int usbip_recv_xbuff(struct usbip_device *ud, struct urb *urb)
/* should not happen, probably malicious packet */
goto error;
+ dev_err(&urb->dev->dev, "num_sgs %d\n", urb->num_sgs);
if (urb->num_sgs) {
copy = size;
for_each_sg(urb->sg, sg, urb->num_sgs, i) {
@@ -721,6 +722,7 @@ int usbip_recv_xbuff(struct usbip_device *ud, struct urb *urb)
recv = usbip_recv(ud->tcp_socket, sg_virt(sg),
recv_size);
+ dev_err(&urb->dev->dev, "size %d, copy %d recv %d, recv_size %d, sg->length %d\n", size, copy, recv, recv_size, sg->length);
if (recv != recv_size)
goto error;
@@ -740,7 +742,7 @@ int usbip_recv_xbuff(struct usbip_device *ud, struct urb *urb)
return ret;
error:
- dev_err(&urb->dev->dev, "recv xbuf, %d\n", ret);
+ dev_err(&urb->dev->dev, "recv xbuf, %d size %d\n", ret, size);
if (ud->side == USBIP_STUB || ud->side == USBIP_VUDC)
usbip_event_add(ud, SDEV_EVENT_ERROR_TCP);
else
--
Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab
A: Because it messes up the order in which people normally read text.
Q: Why is top-posting such a bad thing?
Attachment:
signature.asc
Description: PGP signature
