Bug#845658: linux: Bad(?) USB device crashes USB system
Dear Ritesh,
Thank you for your reply.
Am Samstag, den 26.11.2016, 13:53 +0530 schrieb Ritesh Raj Sarraf:
> On Fri, 2016-11-25 at 17:53 +0100, Paul Menzel wrote:
> > > Nov 23 05:31:36 hamburg01 kernel: usb 3-1: new high-speed USB device number
> > 5 using xhci_hcd
> > > Nov 23 05:31:36 hamburg01 kernel: usb 3-1: New USB device found,
> > idVendor=05e3, idProduct=0608
> > > Nov 23 05:31:36 hamburg01 kernel: usb 3-1: New USB device strings: Mfr=0,
> > Product=1, SerialNumber=0
> > > Nov 23 05:31:36 hamburg01 kernel: usb 3-1: Product: USB2.0 Hub
> > > Nov 23 05:31:36 hamburg01 kernel: hub 3-1:1.0: USB hub found
> > > Nov 23 05:31:36 hamburg01 kernel: hub 3-1:1.0: 4 ports detected
> > > Nov 23 05:31:36 hamburg01 kernel: usb 3-1.2: new low-speed USB device number
> > 6 using xhci_hcd
> > > Nov 23 05:31:36 hamburg01 kernel: usb 3-1.2: New USB device found,
> > idVendor=0a81, idProduct=0205
> > > Nov 23 05:31:36 hamburg01 kernel: usb 3-1.2: New USB device strings: Mfr=1,
> > Product=2, SerialNumber=0
> > > Nov 23 05:31:36 hamburg01 kernel: usb 3-1.2: Product: PS2 to USB Converter
> > > Nov 23 05:31:36 hamburg01 kernel: usb 3-1.2: Manufacturer: CHESEN
> > > Nov 23 05:31:36 hamburg01 kernel: usb 3-1.2: ep 0x81 - rounding interval to
> > 64 microframes, ep desc says 80 microframes
> > > Nov 23 05:31:36 hamburg01 kernel: usb 3-1.2: ep 0x82 - rounding interval to
> > 64 microframes, ep desc says 80 microframes
> > > Nov 23 05:31:36 hamburg01 kernel: input: CHESEN PS2 to USB Converter as
> > /devices/pci0000:00/0000:00:14.0/usb3/3-1/3-1.2/3-
> > 1.2:1.0/0003:0A81:0205.0005/input/input8
> > > Nov 23 05:31:36 hamburg01 kernel: hid-generic 0003:0A81:0205.0005:
> > input,hidraw4: USB HID v1.10 Keyboard [CHESEN PS2 to USB Converter] on usb-
> > 0000:00:14.0-1.2/input0
> > > Nov 23 05:31:36 hamburg01 kernel: input: CHESEN PS2 to USB Converter as
> > /devices/pci0000:00/0000:00:14.0/usb3/3-1/3-1.2/3-
> > 1.2:1.1/0003:0A81:0205.0006/input/input9
> > > Nov 23 05:31:36 hamburg01 kernel: hid-generic 0003:0A81:0205.0006:
> > input,hidraw5: USB HID v1.10 Mouse [CHESEN PS2 to USB Converter] on usb-
> > 0000:00:14.0-1.2/input1
> > > Nov 23 05:31:38 hamburg01 kernel: usb 3-1: USB disconnect, device number 5
> > > Nov 23 05:31:38 hamburg01 kernel: usb 3-1.2: USB disconnect, device number 6
> > > Nov 23 05:31:38 hamburg01 kernel: usb 3-1: new high-speed USB device number
> > 7 using xhci_hcd
> > > Nov 23 05:31:38 hamburg01 kernel: usb 3-1: New USB device found,
> > idVendor=05e3, idProduct=0608
> > > Nov 23 05:31:38 hamburg01 kernel: usb 3-1: New USB device strings: Mfr=0,
> > Product=1, SerialNumber=0
> > > Nov 23 05:31:38 hamburg01 kernel: usb 3-1: Product: USB2.0 Hub
> > > Nov 23 05:31:38 hamburg01 kernel: hub 3-1:1.0: USB hub found
> > > Nov 23 05:31:38 hamburg01 kernel: hub 3-1:1.0: 4 ports detected
> > > Nov 23 05:31:39 hamburg01 kernel: usb 3-1.2: new low-speed USB device number
> > 8 using xhci_hcd
> > > Nov 23 05:31:39 hamburg01 kernel: usb 3-1.2: New USB device found,
> > idVendor=0a81, idProduct=0205
> > > Nov 23 05:31:39 hamburg01 kernel: usb 3-1.2: New USB device strings: Mfr=1,
> > Product=2, SerialNumber=0
> > > Nov 23 05:31:39 hamburg01 kernel: usb 3-1.2: Product: PS2 to USB Converter
> > > Nov 23 05:31:39 hamburg01 kernel: usb 3-1.2: Manufacturer: CHESEN
> > > Nov 23 05:31:39 hamburg01 kernel: usb 3-1.2: ep 0x81 - rounding interval to
> > 64 microframes, ep desc says 80 microframes
> > > Nov 23 05:31:39 hamburg01 kernel: usb 3-1.2: ep 0x82 - rounding interval to
> > 64 microframes, ep desc says 80 microframes
> > > Nov 23 05:31:39 hamburg01 kernel: input: CHESEN PS2 to USB Converter as
> > /devices/pci0000:00/0000:00:14.0/usb3/3-1/3-1.2/3-
> > 1.2:1.0/0003:0A81:0205.0007/input/input10
> > > Nov 23 05:31:39 hamburg01 kernel: hid-generic 0003:0A81:0205.0007:
> > input,hidraw4: USB HID v1.10 Keyboard [CHESEN PS2 to USB Converter] on usb-
> > 0000:00:14.0-1.2/input0
> > > Nov 23 05:31:39 hamburg01 kernel: input: CHESEN PS2 to USB Converter as
> > /devices/pci0000:00/0000:00:14.0/usb3/3-1/3-1.2/3-
> > 1.2:1.1/0003:0A81:0205.0008/input/input11
> > > Nov 23 05:31:39 hamburg01 kernel: hid-generic 0003:0A81:0205.0008:
> > input,hidraw5: USB HID v1.10 Mouse
>
> .....................snipped.....................
>
> > > Plugging in another USB device it’s not detected anymore.
> >
> > As this is in a remote server data center, and this is a production
> > system, I am unsure how to debug that. I think the Linux kernel USB
> > subsystem shouldn’t be crashed by a bad USB device.
>
> I've had similar issues on my box. I worked with the USB folks but really
> couldn't come up with a convincing resolution.
Is that discussion public? Could you please give me the thread subject
or URL?
> There are logs from my machine:
>
> Nov 25 18:42:18 learner kernel: usb 2-4: new high-speed USB device number 29 using xhci_hcd
> Nov 25 18:42:24 learner kernel: usb 2-4: new high-speed USB device number 31 using xhci_hcd
> Nov 25 18:42:29 learner kernel: usb 2-4: new high-speed USB device number 32 using xhci_hcd
> Nov 25 18:42:38 learner kernel: usb 2-4: new high-speed USB device number 48 using xhci_hcd
> Nov 25 18:42:44 learner kernel: usb 2-4: new high-speed USB device number 50 using xhci_hcd
> Nov 25 18:42:59 learner kernel: usb 2-4: new high-speed USB device number 93 using xhci_hcd
> Nov 25 18:43:05 learner kernel: usb 2-4: new high-speed USB device number 97 using xhci_hcd
> Nov 25 18:43:11 learner kernel: usb 2-4: new high-speed USB device number 100 using xhci_hcd
> Nov 25 18:43:18 learner kernel: usb 2-4: new high-speed USB device number 109 using xhci_hcd
> Nov 25 18:43:24 learner kernel: usb 2-4: new high-speed USB device number 110 using xhci_hcd
> Nov 25 18:43:30 learner kernel: usb 2-4: new high-speed USB device number 113 using xhci_hcd
> Nov 25 18:43:35 learner kernel: usb 2-4: new high-speed USB device number 114 using xhci_hcd
> Nov 25 18:43:41 learner kernel: usb 2-4: new high-speed USB device number 115 using xhci_hcd
> Nov 25 18:43:46 learner kernel: usb 2-4: new high-speed USB device number 116 using xhci_hcd
> Nov 25 18:43:47 learner kernel: usb 2-4: new high-speed USB device number 118 using xhci_hcd
> Nov 25 18:43:47 learner kernel: usb 2-4: new high-speed USB device number 119 using xhci_hcd
> Nov 25 18:43:53 learner kernel: usb 2-4: new high-speed USB device number 121 using xhci_hcd
> Nov 25 18:43:59 learner kernel: usb 2-4: new high-speed USB device number 124 using xhci_hcd
> Nov 25 18:44:04 learner kernel: usb 2-4: new high-speed USB device number 126 using xhci_hcd
> Nov 25 18:44:11 learner kernel: usb 2-4: new high-speed USB device number 10 using xhci_hcd
> Nov 25 18:44:17 learner kernel: usb 2-4: new high-speed USB device number 12 using xhci_hcd
> Nov 25 18:44:17 learner kernel: usb 2-4: new high-speed USB device number 14 using xhci_hcd
> Nov 25 18:44:17 learner kernel: usb 2-4: Device not responding to setup address.
> Nov 25 18:44:18 learner kernel: usb 2-4: Device not responding to setup address.
> Nov 25 18:44:18 learner kernel: usb 2-4: device not accepting address 14, error -71
> Nov 25 18:44:18 learner kernel: usb 2-4: new high-speed USB device number 16 using xhci_hcd
> Nov 25 18:44:18 learner kernel: usb 2-4: Device not responding to setup address.
> Nov 25 18:44:18 learner kernel: usb 2-4: Device not responding to setup address.
> Nov 25 18:44:19 learner kernel: usb 2-4: device not accepting address 16, error -71
> Nov 25 18:44:19 learner kernel: usb 2-4: new high-speed USB device number 18 using xhci_hcd
> Nov 25 18:44:24 learner kernel: usb 2-4: new high-speed USB device number 19 using xhci_hcd
> Nov 25 18:44:25 learner kernel: usb 2-4: New USB device found, idVendor=0bda, idProduct=0129
> Nov 25 18:44:25 learner kernel: usb 2-4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
> Nov 25 18:44:25 learner kernel: usb 2-4: Product: USB2.0-CRW
> Nov 25 18:44:25 learner kernel: usb 2-4: Manufacturer: Generic
> Nov 25 18:44:25 learner kernel: usb 2-4: SerialNumber: 20100201396000000
> Nov 25 18:46:53 learner kernel: usb 2-4: USB disconnect, device number 19
> Nov 25 18:46:54 learner kernel: usb 2-4: new high-speed USB device number 20 using xhci_hcd
> Nov 25 18:46:54 learner kernel: usb 2-4: New USB device found, idVendor=0bda, idProduct=0129
> Nov 25 18:46:54 learner kernel: usb 2-4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
> Nov 25 18:46:54 learner kernel: usb 2-4: Product: USB2.0-CRW
> Nov 25 18:46:54 learner kernel: usb 2-4: Manufacturer: Generic
Are you able to reproduce the crash?
> But what do you mean by "crashed" ? The particular USB port becomes
> inaccessible.
Indeed, it does not crash the Linux kernel, but the USB port is not
usable anymore.
> The kernel still works, maybe inefficient, but it does not crash
> the kernel.
Indeed. What do you mean by inefficient?
I noticed, that `uptime`, `top`, or `htop` display a high usage. For
each `lsusb` I started (for debugging) it looks like one CPU core gets
used 100 %?
```
$ uptime
17:17:37 up x days, 9:34, x users, load average: 7,29, 7,64, 7,82
```
I can find no processes in `htop` or `top` using that much CPU. I have
no idea how to find out what is causing this, but I’d guess it’s
something in the Linux kernel.
Here is the content of `/proc/interrupts`.
```
$ more /dev/shm/20161126-proc-interrupts.txt
CPU0 CPU1 CPU2 CPU3 CPU4 CPU5 CPU6 CPU7
0: 19 0 0 0 0 0 0 0 IR-IO-APIC-edge timer
8: 1 0 0 0 0 0 0 0 IR-IO-APIC-edge rtc0
9: 1 0 0 0 0 0 0 0 IR-IO-APIC-fasteoi acpi
16: 33 0 0 0 0 0 0 0 IR-IO-APIC-fasteoi ehci_hcd:usb1
23: 37 0 0 0 0 0 0 0 IR-IO-APIC-fasteoi ehci_hcd:usb2
40: 0 0 0 0 0 0 0 0 DMAR_MSI-edge dmar0
41: 1 0 0 0 0 0 0 0 IR-PCI-MSI-edge eth0
42: 8331636 0 0 0 0 0 0 0 IR-PCI-MSI-edge eth0-TxRx-0
43: 39422943 0 0 0 0 0 0 0 IR-PCI-MSI-edge eth0-TxRx-1
44: 9553184 0 0 0 0 0 0 0 IR-PCI-MSI-edge eth0-TxRx-2
45: 9039148 0 0 0 0 0 0 0 IR-PCI-MSI-edge eth0-TxRx-3
46: 32164385 0 0 0 0 0 0 0 IR-PCI-MSI-edge ahci
47: 3473101 0 0 0 0 0 0 0 IR-PCI-MSI-edge xhci_hcd
NMI: 14449 14914 12962 16365 4413 5859 4729 4074 Non-maskable interrupts
LOC: 114376580 112602603 113620716 113780852 20372352 20649737 21575073 20968929 Local timer interrupts
SPU: 0 0 0 0 0 0 0 0 Spurious interrupts
PMI: 14449 14914 12962 16365 4413 5859 4729 4074 Performance monitoring interrupts
IWI: 15 1 2 2 5 2 1 2 IRQ work interrupts
RTR: 6 0 0 0 0 0 0 0 APIC ICR read retries
RES: 1417557 825483 727579 688189 667971 603366 601659 597732 Rescheduling interrupts
CAL: 4294951937 4294953176 4294954808 4294955476 4294961428 4294961800 4294961541 4294961254 Function call interrupts
TLB: 1876617 1884660 1857954 1890446 1213181 1418131 1402527 1302193 TLB shootdowns
TRM: 0 0 0 0 0 0 0 0 Thermal event interrupts
THR: 0 0 0 0 0 0 0 0 Threshold APIC interrupts
MCE: 0 0 0 0 0 0 0 0 Machine check exceptions
MCP: 1719 1719 1719 1719 1719 1719 1719 1719 Machine check polls
HYP: 0 0 0 0 0 0 0 0 Hypervisor callback interrupts
ERR: 0
MIS: 0
```
I noticed that in 10.5 hours the “interrupts for xhci_hcd” still
increase.
```
$ ls -ltrh /dev/shm/20161126-proc-interrupts.txt /dev/shm/20161126-proc-interrupts-1.txt
-rw-r--r-- 1 me me 3,4K Nov 26 06:49 /dev/shm/20161126-proc-interrupts.txt
-rw-r--r-- 1 me me 3,4K Nov 26 17:09 /dev/shm/20161126-proc-interrupts-1.txt
```
```
- 47: 3473101 0 0 0 0 0 0 0 IR-PCI-MSI-edge xhci_hcd
+ 47: 3723886 0 0 0 0 0 0 0 IR-PCI-MSI-edge xhci_hcd
```
Kind regards,
Paul
Reply to: