search

raspberrypi / linux

Kernel source tree for Raspberry Pi-provided kernel builds. Issues unrelated to the linux kernel should be posted on the community forum at https://forums.raspberrypi.com/
Other
11.22k stars 5.02k forks source link

F/W 4.14.x causes dwc_otg_handle_mode_mismatch_intr:68: messages on boot with C-Media Electronics Inc. USB PnP Sound Device #2408

Closed hofnarr132 closed 6 years ago

hofnarr132 commented 6 years ago

Looks like an issue with dwc_otg was introduced with 4.14.x versions - 4.9.80 does not show issue.

When booting RPi 3, 2 or ZeroW with 4.14.x versions with a "C-Media Electronics Inc. USB PnP Sound Device" connected** get the following boot messages (extracted from dmesg):

[    3.292306] usb 1-1.3.4: new full-speed USB device number 7 using dwc_otg
[    3.320586] uart-pl011 3f201000.serial: no DMA platform data
[    3.450503] usb 1-1.3.4: New USB device found, idVendor=0d8c, idProduct=013c
[    3.467395] usb 1-1.3.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    3.484570] usb 1-1.3.4: Product: USB PnP Sound Device          
[    3.500214] usb 1-1.3.4: Manufacturer: C-Media Electronics Inc.      
[    3.522058] input: C-Media Electronics Inc.       USB PnP Sound Device           as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3.4/1-1.3.4:1.3/0003:0D8C:013C.0003/input/input2
[    3.622573] hid-generic 0003:0D8C:013C.0003: input,hidraw2: USB HID v1.00 Device [C-Media Electronics Inc.       USB PnP Sound Device          ] on usb-3f980000.usb-1.3.4/input3
.
.
.
[    6.170183] bcm2835_alsa bcm2835_alsa: card created with 8 channels
[    6.374754] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[    6.374820] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[    6.376756] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[    6.406816] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[    6.410315] usbcore: registered new interface driver snd-usb-audio
[    7.518782] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[    7.520726] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[    7.712309] usb 1-1.5: reset high-speed USB device number 5 using dwc_otg
.
.
.
[    7.913820] usbcore: registered new interface driver rt2800usb
.
.
.
[   24.342952] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[   24.343077] usb 1-1.3.4: 1:1: cannot set freq 44100 to ep 0x1
[   24.432846] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[   24.512751] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[   24.512823] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[   24.526869] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[   24.527122] usb 1-1.3.4: 2:1: cannot get freq at ep 0x82
[   24.528811] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[   24.576791] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[   24.576821] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

Tested and errors with 4.14.18 (and 4.14.22).

uname -a
Linux raspberrypi 4.14.18-v7+ #1093 SMP Fri Feb 9 15:33:07 GMT 2018 armv7l GNU/Linux

Back revved to 4.9.80 where the error messages do not show:

pi@raspberrypi:~ $ uname -a
Linux raspberrypi 4.9.80-v7+ #1092 SMP Fri Feb 9 13:56:00 GMT 2018 armv7l GNU/Linux

** note: the "C-Media Electronics Inc. USB PnP Sound Device" is actually embedded in a 4-Port HDMI & USB KVM Switch (this one from ModMyPi) - there is a push button switch to turn off audio which disables the Sound Device - the RPi will then boot without error (but then no sound..)

mypiandrew commented 6 years ago

Hi

Just to chip in

I get the same issue on a custom CM3 board when trying to access a FTDI 230XS USB serial device connected via STT Genesys GL850G hub

Didn't see this on 4.9.80

Problem current as of

root@raspberrypi:~# uname -a
Linux raspberrypi 4.14.52-v7+ #1123 SMP Wed Jun 27 17:35:49 BST 2018 armv7l GNU/Linux

Here's the USB config :

root@raspberrypi:~# lsusb
Bus 001 Device 008: ID 1618:9113
Bus 001 Device 007: ID 0424:2240 Standard Microsystems Corp.
Bus 001 Device 006: ID 0403:6015 Future Technology Devices International, Ltd Bridge(I2C/SPI/UART/FIFO)
Bus 001 Device 005: ID 0424:ec00 Standard Microsystems Corp. SMSC9512/9514 Fast Ethernet Adapter
Bus 001 Device 003: ID 0424:9512 Standard Microsystems Corp. SMC9512/9514 USB Hub
Bus 001 Device 002: ID 05e3:0608 Genesys Logic, Inc. Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

root@raspberrypi:~# lsusb -t
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=dwc_otg/1p, 480M
    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/4p, 480M
        |__ Port 1: Dev 3, If 0, Class=Hub, Driver=hub/3p, 480M
            |__ Port 1: Dev 5, If 0, Class=Vendor Specific Class, Driver=smsc95xx, 480M
        |__ Port 2: Dev 6, If 0, Class=Vendor Specific Class, Driver=ftdi_sio, 12M
        |__ Port 3: Dev 7, If 0, Class=Mass Storage, Driver=usb-storage, 480M

dmesg : https://gist.github.com/mypiandrew/331cf98189973884872b8e3c77086b01

If I try and access the FTDI USB device it spams the dmesg output, here's a sample of the output 

[13582.090686] ftdi_sio ttyUSB0: failed to get modem status: -32
[13582.138524] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode
[13582.138802] ftdi_sio ttyUSB0: failed to get modem status: -32
[13582.266620] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode
[13582.266719] ftdi_sio ttyUSB0: failed to get modem status: -71
[13582.442622] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode
[13582.442712] ftdi_sio ttyUSB0: failed to get modem status: -71
[13582.602613] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode
[13582.602715] ftdi_sio ttyUSB0: failed to get modem status: -71
[13582.747325] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode
[13583.748824] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode
[13584.750451] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode
[13584.750540] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode
[13584.874473] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode
[13584.874505] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode
[13584.874597] ftdi_sio ttyUSB0: failed to get modem status: -71
[13584.970347] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode
[13584.970503] ftdi_sio ttyUSB0: failed to get modem status: -71
[13585.082402] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

I should add that despite these alarming looking messages I can still get modbus comms over the serial port at 9600 

root@raspberrypi:~# mbpoll -a 1 -b 9600 -P none -t 4 -r 1 -c 5 /dev/ttyUSB0 -1 -v
mbpoll 0.1-23 - FieldTalk(tm) Modbus(R) Master Simulator
Copyright (c) 2015 epsilonRT, All rights reserved.
This software is governed by the CeCILL license <http://www.cecill.info>

Opening /dev/ttyUSB0 at 9600 bauds (N, 8, 1)
Protocol configuration: Modbus RTU
Slave configuration...: address = [1]
                        start reference = 1, count = 5
Communication.........: /dev/ttyUSB0,       9600-8N1
                        t/o 1.00 s, poll rate 1000 ms
Data type.............: 16-bit register, output (holding) register table

-- Polling slave 1...
[01][03][00][00][00][05][85][C9]
Waiting for a confirmation...
<01><03><0A><00><6F><00><DE><01><4D><01><BC><02><2B><5F><F1>
[1]:    111
[2]:    222
[3]:    333
[4]:    444
[5]:    555

How can I assist with debugging?

mypiandrew commented 6 years ago

This looks to me like some kind of interaction between FS USB devices and STT/MTT hubs?

Getting some strange results this morning when plugging different devices into the system

https://gist.github.com/mypiandrew/75a891aad768044f246caa4867981f42 https://gist.github.com/mypiandrew/d56bd0811c377859608cda0b620268a8

and

https://gist.github.com/mypiandrew/5e0f5bf0f029c86214c79aef7fe699c4

kaltinril commented 6 years ago

I had no space left on my 32GB drive and noticed the /var/log file was taking up 12+ GB of space.

all three are over 4 gigs

When checking the /var/log/kern.log i noticed the same error WARN::dwc_otg_handle_mode_mismatch_intr:68 Mode Mismatch Interrupt: currently in Host mode

if I tail the log file, the screen just scrolls with new entries over and over.

I have connected:

  1. logitec wireless K520 keyboard and mouse
  2. XBOX360 dongle
  3. HDMI cord
  4. CANA Kit power cord

Case:

System:

EDIT: Without using the Retroflag Nespi case, the error is not appearing in the log files.

hippocritical commented 6 years ago

Hi to all, I had the same problem and thanks to kaltinril I solved the problem for me.

Setup:Raspberry pi Stretch with post - install installed retropie package

Hardware: raspberry pi "raspberry usb hub" with connected wifi dongle for the xbox controller 360 from china

solved with: switched chinese xbox360 wifi dongle from usb hub to native raspberry usb connection.

kaltinril commented 6 years ago

@P33M Would you like a log from the RetroFlag case which has the same error?

mypiandrew commented 6 years ago

Hi, this looks to me like a problem between STT USB Hub Chips and the RPI USB interface.

The RetroPi also uses the same GL850 hub chip featured repeatedly in the above chain as best I can make out.

This effect is a regression from 4.9.80 which does not have this problem

jfarid27 commented 6 years ago

I can also confirm this issue on a reflash with Raspbian 4.14. In light of the "USB hub", my error came up when I was actually using a Rosewill keyboard with a built in USB hub and I received the same error.

I did see a mention of low voltage before the long string of repeated Mode Mismatch Interrupt errors, so I guess using any sort of usb hub is the root issue. I also just used a different keyboard and the error went away.

danielmarschall commented 6 years ago

Apropos "low voltage": I am using a backlight keyboard which requires a lot of energy. Is it possible that the bug happens when the hub is overloaded?

mypiandrew commented 6 years ago

@dracenmarx

I don't think so, this problem is occurring only on kernel 4.14.x It does not appear on 4.9.80

The common thread is appears to be usage of FS/LS devices in conjunction with the STT GL850 hub and the RPi USB interface.

It's a common hub chip, see the RetroPi comment above

We have a custom Compute Module based setup, using the same hub chip, and see the same issue when we switch to the 4.14 branch.

I suspect it's more likely just a USB bug that's most likely been fixed once already, gotten lost in the migration, and needs adding in again to the 4.14 branch.

xKaiser commented 6 years ago

@mypiandrew I have observed the issue in the 4.9.80 with my device, but the log messages were much less frequent. I don't think we can say 4.9.80 works with certainty.

cicci44 commented 6 years ago

can also confirm issue with Retroflag Nespi case.

Joennuh commented 6 years ago

I got the same issue while trying to get a noname wireless USB mouse to a Vivanco USB 2.0 hub. The hub is attached to a USB OTG cable. The USB OTG cable is attached to a Raspberry Pi Zero WH.

More technical I have the following devices attached:

At first the mouse seemed to be slow and I discovered at https://www.raspberrypi.org/forums/viewtopic.php?p=600742#p600742 that I needed to add usbhid.mousepoll=0 to /boot/cmdline.txt. It seems to be that the issue occurs since that moment. At boot I see lots of [ 628.185745] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode messages. Only when I disconnect the noname wireless mouse from the USB hub the Raspberri Pi Zero WH continues to boot normally. After reattaching the noname wireless mouse after a few moments the messages came much less to zero at dmesg.

I have quite a beginner level at Raspbian debugging and I can't get the messages from boot time in dmesg.

Output of lsusb -v and dmesg: https://joen.stackstorage.com/s/DQZhNd9JIJpUgR1

Output of lsusb and lsusb -t:

pi@energizer-v2:~ $ lsusb
Bus 001 Device 011: ID 04d9:a01c Holtek Semiconductor, Inc.
Bus 001 Device 010: ID 062a:4101 Creative Labs Wireless Keyboard/Mouse
Bus 001 Device 009: ID 05e3:0608 Genesys Logic, Inc. Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
pi@energizer-v2:~ $ lsusb -t
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=dwc_otg/1p, 480M
    |__ Port 1: Dev 9, If 0, Class=Hub, Driver=hub/4p, 480M
        |__ Port 2: Dev 10, If 0, Class=Human Interface Device, Driver=usbhid, 12M
        |__ Port 2: Dev 10, If 1, Class=Human Interface Device, Driver=usbhid, 12M
        |__ Port 4: Dev 11, If 0, Class=Human Interface Device, Driver=usbhid, 1.5M
        |__ Port 4: Dev 11, If 1, Class=Human Interface Device, Driver=usbhid, 1.5M

Output of uname -a:

pi@energizer-v2:~ $ uname -a
Linux energizer-v2 4.14.52+ #1123 Wed Jun 27 17:05:32 BST 2018 armv6l GNU/Linux

I hope this is enough information for the developers to solve this frustrating issue.

jakraska commented 6 years ago

I am also having problems with Retroflag Nespi case. Log files are full of 

[13583.748824] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode
AnthraxLeprosyPi commented 6 years ago

Hey everybody,

Exact same thing coming from Jessie and upgraded to stretch wondered where the 12gig I had left in a 128GB SD card went...

Found them in the logs folder... 😪

Also got RPI 3B, nespi plus case and a Xbox wireless receiver.

Is there any bleeding edge kernel stuff somewhere I can try? 😜

Regards, Anthrax

TheNetStriker commented 6 years ago

I've just tested the with latest kernel and firmware, but the problem is still there. I am booting my RPI from an external USB SSD. Could this be part of the problem?

Joennuh commented 6 years ago

@TheNetStriker As far as I can track it down it only happens when you have connected an USB hub which uses the Single TT protocol. In my case USB hubs that uses the TT per port protocol do not have the issue.

You can check which protocol your USB hub(s) uses by executing the following command: sudo lsusb -v Then you will see a long list which much detailed information about the connected USB devices inclusing USB hubs. You will have to search for your USB hub (the ones that causing the issues are mainly Genesys hubs). The line that describes the name of your hub starts with Bus xxx Device xxx with the intent most left. In my case it was: Bus 001 Device 009: ID 05e3:0608 Genesys Logic, Inc. Hub Please ignore the Linux Foundation 2.0 root hub. This is the USB hub embedded on your Raspberry Pi and is not the direct cause of the warnings.

Not far below that line you will see a line describing the used protocol, in my case it was: bDeviceProtocol 1 Single TT And with other USB hubs it was TT per port instead of Single TT. When I use a USB hub with the TT per port protocol I do not have the issue.

You can find an example of my sudo lsusb -v output on my Stack storage: https://joen.stackstorage.com/s/DQZhNd9JIJpUgR1 , file lsusb.txt

TheNetStriker commented 6 years ago

@Joennuh It seams that all my USB hub's are Single TT devices. Is there a list of Multi TT devices somewhere so I could buy such an USB hub?

Joennuh commented 6 years ago

@TheNetStriker Not that I know of. These ones that I have from AliExpress are "TT per port": Orico: http://s.aliexpress.com/EVbiIfu2 NoName: http://s.aliexpress.com/NBzQFVrI The first one is the best of these 2 in my opinion.

mypiandrew commented 6 years ago

@Joennuh @P33M @pelwell

I've done some brief testing this morning using our custom compute module board running with a GL852 (with TT per port) to see if that works around the issue.

I still see issues with the USB on that too :(

The problem is more intermittent on reboots (or power ups) but with the same hardware setup (swapping between two CM3s running Stretch and 4.9.80 and 4.14.62) I can still get issues with the USB to appear with the 4.14 kernel, where 4.9.80 appears more stable (working).

https://gist.github.com/mypiandrew/7fbc9bac9215398f5e301f8707c6e67e

Really not sure where to go from here as my plan to swap from GL850s to GL852s is shot down from the looks of it.

Happy to assist in debug activity (or post boards off as we're here in the UK) if that helps

hofnarr132 commented 6 years ago

I confirm my HDMI KVM switch has a ID 05e3:0608 Genesys Logic, Inc. Hub and lsusb -v reports bDeviceProtocol 1 Single TT for it.

TheNetStriker commented 6 years ago

@Joennuh I bought myself an Elektron Overhub to test this. This devices is built to attach multiple realtime music devices to a pc, so it should be very good. And the situation has actually improved with this hub. I still got a few of the error messages on startup or e.g. when starting the Openhab service, but then the error doesn't seam to appear anymore.

The main problem that I had was a massive delay in my ZWave network. Switching a light on with the ZWave USB stick on the usb hub did take 10 times as long as without the hub. Now with the Overhub it is back to normal.

kennymingt commented 6 years ago

Hi, I also have this issue with a USBHub and wireless mouse. Here is my dmesg output right when I plug the mouse into the USBhub.


[    6.796033] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[    6.796064] brcmfmac: power management disabled
[    7.186102] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[   11.061879] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   12.228961] fuse init (API version 7.26)
[   12.498541] Bluetooth: Core ver 2.22
[   12.498607] NET: Registered protocol family 31
[   12.498610] Bluetooth: HCI device and connection manager initialized
[   12.498628] Bluetooth: HCI socket layer initialized
[   12.498637] Bluetooth: L2CAP socket layer initialized
[   12.498662] Bluetooth: SCO socket layer initialized
[   12.512373] Bluetooth: HCI UART driver ver 2.3
[   12.512382] Bluetooth: HCI UART protocol H4 registered
[   12.512385] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   12.512531] Bluetooth: HCI UART protocol Broadcom registered
[   12.845481] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   12.845498] Bluetooth: BNEP filters: protocol multicast
[   12.845522] Bluetooth: BNEP socket layer initialized
[   12.913183] Bluetooth: RFCOMM TTY layer initialized
[   12.913229] Bluetooth: RFCOMM socket layer initialized
[   12.913256] Bluetooth: RFCOMM ver 1.11
[   21.083497] EXT4-fs (mmcblk0p5): mounted filesystem with ordered data mode. Opts: (null)
[  308.177996] usb 1-1.2: reset full-speed USB device number 4 using dwc_otg
[  308.828055] usb 1-1.1.3: reset low-speed USB device number 5 using dwc_otg
[  309.248040] usb 1-1.2: reset full-speed USB device number 4 using dwc_otg
[  309.478038] usb 1-1.3: new high-speed USB device number 7 using dwc_otg
[  309.610528] usb 1-1.3: New USB device found, idVendor=8564, idProduct=4100
[  309.610544] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  309.610554] usb 1-1.3: Product: USB2.0 Hub
[  309.610563] usb 1-1.3: Manufacturer: Transcend Info
[  309.612146] hub 1-1.3:1.0: USB hub found
[  309.612569] hub 1-1.3:1.0: 4 ports detected

[  344.038484] usb 1-1.3.1: new low-speed USB device number 8 using dwc_otg
[  344.176528] usb 1-1.3.1: New USB device found, idVendor=046d, idProduct=c31c
[  344.176545] usb 1-1.3.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  344.176555] usb 1-1.3.1: Product: USB Keyboard
[  344.176563] usb 1-1.3.1: Manufacturer: Logitech
[  344.193438] input: Logitech USB Keyboard as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3.1/1-1.3.1:1.0/0003:046D:C31C.0007/input/input6
[  344.262887] hid-generic 0003:046D:C31C.0007: input,hidraw0: USB HID v1.10 Keyboard [Logitech USB Keyboard] on usb-3f980000.usb-1.3.1/input0
[  344.286001] input: Logitech USB Keyboard as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3.1/1-1.3.1:1.1/0003:046D:C31C.0008/input/input7
[  344.349063] hid-generic 0003:046D:C31C.0008: input,hidraw1: USB HID v1.10 Device [Logitech USB Keyboard] on usb-3f980000.usb-1.3.1/input1
^[[B^[[A^[[1;2D^[[1;2A[  388.039165] usb 1-1.1.2: new full-speed USB device number 9 using dwc_otg
[  388.180284] usb 1-1.1.2: New USB device found, idVendor=1d57, idProduct=fa60
[  388.180304] usb 1-1.1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  388.180313] usb 1-1.1.2: Product: 2.4G Wireless Mouse
[  388.180323] usb 1-1.1.2: Manufacturer: LXDDZ
[  388.186831] input: LXDDZ 2.4G Wireless Mouse as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1/1-1.1.2/1-1.1.2:1.0/0003:1D57:FA60.0009/input/input8
[  388.250262] hid-generic 0003:1D57:FA60.0009: input,hidraw2: USB HID v11.01 Keyboard [LXDDZ 2.4G Wireless Mouse] on usb-3f980000.usb-1.1.2/input0
[  388.255950] input: LXDDZ 2.4G Wireless Mouse as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1/1-1.1.2/1-1.1.2:1.1/0003:1D57:FA60.000A/input/input9
[  388.256571] hid-generic 0003:1D57:FA60.000A: input,hidraw3: USB HID v11.01 Mouse [LXDDZ 2.4G Wireless Mouse] on usb-3f980000.usb-1.1.2/input1
[  388.266860] input: LXDDZ 2.4G Wireless Mouse as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1/1-1.1.2/1-1.1.2:1.2/0003:1D57:FA60.000B/input/input10
[  388.329863] hid-generic 0003:1D57:FA60.000B: input,hiddev96,hidraw4: USB HID v11.01 Device [LXDDZ 2.4G Wireless Mouse] on usb-3f980000.usb-1.1.2/input2
[  388.334193] input: LXDDZ 2.4G Wireless Mouse as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1/1-1.1.2/1-1.1.2:1.3/0003:1D57:FA60.000C/input/input11
[  388.399803] hid-generic 0003:1D57:FA60.000C: input,hidraw5: USB HID v11.01 Keyboard [LXDDZ 2.4G Wireless Mouse] on usb-3f980000.usb-1.1.2/input3

[  429.030329] usb 1-1.1.2: USB disconnect, device number 9
[  439.039819] usb 1-1.3.4: new full-speed USB device number 10 using dwc_otg
[  439.179802] usb 1-1.3.4: New USB device found, idVendor=1d57, idProduct=fa60
[  439.179818] usb 1-1.3.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  439.179829] usb 1-1.3.4: Product: 2.4G Wireless Mouse
[  439.179839] usb 1-1.3.4: Manufacturer: LXDDZ
[  439.188726] input: LXDDZ 2.4G Wireless Mouse as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3.4/1-1.3.4:1.0/0003:1D57:FA60.000D/input/input12
[  439.250917] hid-generic 0003:1D57:FA60.000D: input,hidraw2: USB HID v11.01 Keyboard [LXDDZ 2.4G Wireless Mouse] on usb-3f980000.usb-1.3.4/input0
[  439.256562] input: LXDDZ 2.4G Wireless Mouse as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3.4/1-1.3.4:1.1/0003:1D57:FA60.000E/input/input13
[  439.257187] hid-generic 0003:1D57:FA60.000E: input,hidraw3: USB HID v11.01 Mouse [LXDDZ 2.4G Wireless Mouse] on usb-3f980000.usb-1.3.4/input1
[  439.267521] input: LXDDZ 2.4G Wireless Mouse as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3.4/1-1.3.4:1.2/0003:1D57:FA60.000F/input/input14
[  439.330666] hid-generic 0003:1D57:FA60.000F: input,hiddev96,hidraw4: USB HID v11.01 Device [LXDDZ 2.4G Wireless Mouse] on usb-3f980000.usb-1.3.4/input2
[  439.333020] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[  439.334630] input: LXDDZ 2.4G Wireless Mouse as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3.4/1-1.3.4:1.3/0003:1D57:FA60.0010/input/input15
[  439.336038] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[  439.337030] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[  439.338009] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[  439.338103] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[  439.339004] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[  439.340046] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[  439.341011] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[  439.341100] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

[  439.342016] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode

Then it goes forever

pi@raspberrypi:~ $ sudo du /var/log -d 1 -h
144K    /var/log/apt
36K /var/log/lightdm
4.0K    /var/log/samba
94M /var/log
pi@raspberrypi:~ $ sudo du /var/log -d 1 -h
144K    /var/log/apt
36K /var/log/lightdm
4.0K    /var/log/samba
102M    /var/log
pi@raspberrypi:~ $ sudo du /var/log -d 1 -h
144K    /var/log/apt
36K /var/log/lightdm
4.0K    /var/log/samba
107M    /var/log

I hope it is useful

Niels-Be commented 6 years ago

As a workaround for me adding dwc_otg.speed=1 to cmdline.txt worked. Note that this will slow down all USB devices to USB 1.1 speeds (full-speed).

TheNetStriker commented 6 years ago

@Joennuh Sadly after some days of continuously using the Elektron Overhub the problems with the usb devices are back. Here are the logs from dmesg:

[832750.883433] usb 1-1.5.1.3: usbfs: USBDEVFS_CONTROL failed cmd usbhid-ups rqt 161 rq 1 len 4 ret -71
[832750.886226] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode
[832750.886237] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode
[832750.886249] WARN::dwc_otg_handle_mode_mismatch_intr:68: Mode Mismatch Interrupt: currently in Host mode
[832750.886294] usb 1-1.5.1.3: usbfs: USBDEVFS_CONTROL failed cmd usbhid-ups rqt 161 rq 1 len 4 ret -71
[832752.595500] usb 1-1.5.1.3: USB disconnect, device number 11
[832752.980466] usb 1-1.5.1.3: new low-speed USB device number 18 using dwc_otg
[832755.347632] usb 1-1.5.1.3: New USB device found, idVendor=0463, idProduct=ffff
[832755.347643] usb 1-1.5.1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=4
[832755.347647] usb 1-1.5.1.3: Product: Eaton 3S
[832755.347652] usb 1-1.5.1.3: Manufacturer: EATON
[832755.347656] usb 1-1.5.1.3: SerialNumber: 00000
[832758.748345] hid-generic 0003:0463:FFFF.0009: hiddev96,hidraw0: USB HID v10.10 Device [EATON Eaton 3S] on usb-3f980000.usb-1.5.1.3/input0
[957922.473818] usb 1-1.5.1.2: new full-speed USB device number 19 using dwc_otg
[957922.866680] usb 1-1.5.1.2: New USB device found, idVendor=03eb, idProduct=2013
[957922.866707] usb 1-1.5.1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[957922.866716] usb 1-1.5.1.2: Product: AT89C5131 - USB HID Generic 
[957922.866725] usb 1-1.5.1.2: Manufacturer: ATMEL
[957922.866733] usb 1-1.5.1.2: SerialNumber: 1.3.5.7.9.B.D
[957922.951254] hid-generic 0003:03EB:2013.000A: hiddev96,hidraw0: USB HID v1.11 Device [ATMEL AT89C5131 - USB HID Generic ] on usb-3f980000.usb-1.5.1.2/input0
[959239.886145] usb 1-1.5.1.2: USB disconnect, device number 19
[1028120.766979] usb 1-1.5.1.2: new full-speed USB device number 20 using dwc_otg
[1028121.169962] usb 1-1.5.1.2: New USB device found, idVendor=03eb, idProduct=2013
[1028121.169972] usb 1-1.5.1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[1028121.169977] usb 1-1.5.1.2: Product: AT89C5131 - USB HID Generic 
[1028121.169982] usb 1-1.5.1.2: Manufacturer: ATMEL
[1028121.169986] usb 1-1.5.1.2: SerialNumber: 1.3.5.7.9.B.D
[1028121.253851] hid-generic 0003:03EB:2013.000B: hiddev96,hidraw0: USB HID v1.11 Device [ATMEL AT89C5131 - USB HID Generic ] on usb-3f980000.usb-1.5.1.2/input0

The logs did fill up my kernel log again, then some usb devices just stopped working. The errors also seam to have affected usb devices that are not connected over the usb hub. I'am now working again without the usb hub.

malacalypse commented 6 years ago

I have this same issue when connecting devices through an Anker hub. When they are plugged in directly, there is no problem, but when I plug them through the Anker hub, they do not work.

I went through the four dwc_otg.fiq_fsm_mask settings on boot. Only 0x0 suppressed the messages, but none of the settings successfully enabled the devices from the perspective of the OS.

This is further complicated by the fact that NONE of these devices pull more than 100mA of power, and the majority of them pull no power whatsoever from the hub, so it cannot be an issue of power in this case.

Also, two devices from the same vendor (out of those from four different vendors) DO work through the hub. So clearly there is an interaction between a device type and a hub situation, because all of the devices work fine plugged in directly, and this hub has no problems on any other OS or system I plug it into.

xKaiser commented 6 years ago

@JamesH65 Is this issue still on the radar? Haven't seen contributors in this thread in awhile and I still haven't come across a workaround for this issue (even downgrading to 4.9) where I don't have USB issues with the devices I'm using. I'd be happy to help work on this issue if I had some guidance on where to start.

JamesH65 commented 6 years ago

No idea if anyone is actively working on this. We are rather busy with other stuff at the moment.

@P33M @pelwell Any thoughts?

mypiandrew commented 6 years ago

@JamesH65

I feel for you guys at the moment, this too will pass.

Hate to add to it but the USB support on 4.14 appears pretty broken once you attach either an STT or MTT hub on the the Pi and a/any combination of non-USB 2.0 (480M) devices into that (see above chain from myself and others)

There's a clear works/doesn't work between 4.9 and 4.14 (you can probably get the theme from the above) with the same setup, so it's pretty repeatable.

I can't say I've seen the problems @xKaiser sees with 4.9.80 myself, so I can't comment on any issues with that setup.

pelwell commented 6 years ago

@mypiandrew Have you tried any of the newer branches - rpi-4.18.y, for example?

mypiandrew commented 6 years ago

Hi Phil

No I haven't but OP tried one of the 4.18 kernels and no joy, so didn't pursue

Is there an easy way to do that?

danielmarschall commented 6 years ago

No idea if anyone is actively working on this. We are rather busy with other stuff at the moment.

That would be very unfortunate. I think this is a critical bug. My 32 GB SD cards fills up withhin minutes, and so the only thing I can do is to put /var/log into a RAM disk and accept the fact that I can never use syslog or other logs again. Some programs even crash when /var/log is full and no files can be created. So, this bug renders parts of my system unuseable after the firmware update...

pelwell commented 6 years ago

No I haven't but OP tried one of the 4.18 kernels and no joy, so didn't pursue

Unless I've missed something, the OP tried 4.14.18 instead.

Is there an easy way to do that?

If you think building your own kernel is easy then yes (it's honestly not difficult, it just takes a while - see https://www.raspberrypi.org/documentation/linux/kernel/building.md) - just checkout rpi-4.18.y and build it. Otherwise, no.

mypiandrew commented 6 years ago

@pelwell

Yep, my bad searching for 4.18 matched 4.14.18 (sorry!)

TheNetStriker commented 6 years ago

@mypiandrew Am I getting this right? The problem only occurs if usb 1.0 and usb 2.0 devices are connected together over the usb hub? This would explain why I'm having no problem now by just connecting a single usb 2.0 device to my usb hub. (Before I also had my UPS connected via usb) And there is a good chance that the UPS is only a usb 1.0. device.

So if I'm just connecting usb 1.0 or usb 2.0 devices over the hub the problem should not occur? So would it also be possible to connect usb 1.0 devices over one hub and usb 2.0 devices over another hub? (I'm just trying to find a workarround for this until the problem is finally solved)

mypiandrew commented 6 years ago

@TheNetStriker That's not a setup I can replicate, sorry

P33M commented 6 years ago

Previously, I've been unable to replicate the issue. @6by9 provided a different single-TT hub and Aha, interrupt spam.

mypiandrew commented 6 years ago

@P33M

Good to hear you have something you can use to help fault find

I found the same issue exhibited on both STT and MTT hub chips

https://github.com/raspberrypi/linux/issues/2408#issuecomment-414236643

P33M commented 6 years ago

I can see the weirdness but I don't have a concrete explanation. It's definitely timing-related.

When queueing USB transfers, a limit check is performed to stop periodic transfers from being queued near the end of a frame as previously, weird things have happened such as transfers not completing or raising erroneous transfer complete interrupts. The HFNUM register is read and if the remaining time is "close" to end-of-frame then the enqueue is delayed. This facility is bypassed if the transfer is non-periodic.

What's weird is that this register is being read back as 0 on a fairly regular basis. This is a count-down timer that should automatically reload when it hits 0, so reading this value should be an incredibly rare event. This makes me suspect that trying to do register read/writes "too fast" results in an incorrect address decode or incorrect read from the OTG core's register file - which is worrying.

If I unconditionally enable the limit check, I no longer get the bogus interrupts. It does make me wonder if some other sort of throttling is required.

xKaiser commented 6 years ago

My case is that I'm using two relatively high bandwidth devices, Hologram Nova USB modem and an Thingmagic RFID reader (which takes up two USB ports). I'm using a hub to supply enough power to the RFID reader. I've limited the baudrate of the modem to 256k, but the error that occurs is that a timing restraint appears to be violated, causing one of the devices to stop communicating. The odd thing is that certain devices get lucky and run without issue, while other devices consistently have issues.

P33M commented 6 years ago

Found it. There's a codepath that only gets executed if the hub is overloaded with start-split non-periodic transfer requests and returns NAK for subsequent start-splits. The function call incorrectly computes the offset of the channel DMA register (which needs to be reset in order to start from the correct address) due to a copy-paste error.

Most hubs have buffers far deeper than the number of outstanding transfers that we can issue, so it appears that there's a small subset of hub chipsets that are capable of provoking this problem.

The HFNUM register reading as zero is probably a side-effect of the OTG core rejecting the previous register access.

pelwell commented 6 years ago

w00t!

JamesH65 commented 6 years ago

Indeed! Nice job @P33M !

mypiandrew commented 6 years ago

Awesome work!

P33M commented 6 years ago

Hooray for github's auto-close keyword parsing (not). Keeping open until 3rd parties can test and report back.

malacalypse commented 6 years ago

Which kernel branch/version is this in for us to get our hands on?

TheNetStriker commented 6 years ago

I think this will be in 4.14.71, but rpi-update just updates to 4.14.70 at the moment.

P33M commented 6 years ago

rpi-update firmware is now updated should contain a fix for this issue.

xKaiser commented 6 years ago

This makes me so happy, great work guys! I'm going to update and see if I can validate this fixes my issue.

@P33M Do we know when this issue was introduced? Looks like it's been there from day one?

Joennuh commented 6 years ago

I can confirm the issue has been solved. Tested it without and with the patch with an USB hub of which I know it causes the error lines. I never used rpi-update before and as I've read a lot of warnings about it in several forums I'm wondering if it can cause any issues when you use it. When can we expect this fix to be implemented in the apt-get upgrade procedure?

malacalypse commented 6 years ago

So, the error line spam is gone, but I still cannot use the device through the hub, but only on the pi:

If I plug the device in through the hub:

Sep 21 19:40:22 alchemist kernel: [   76.581569] usb 1-1.1.3.1: new full-speed USB device number 21 using dwc_otg
Sep 21 19:40:22 alchemist kernel: [   76.691573] usb 1-1.1.3.1: device descriptor read/64, error -71
Sep 21 19:40:22 alchemist kernel: [   76.921575] usb 1-1.1.3.1: device descriptor read/64, error -71
Sep 21 19:40:22 alchemist kernel: [   77.151575] usb 1-1.1.3.1: new full-speed USB device number 22 using dwc_otg
Sep 21 19:40:22 alchemist kernel: [   77.261578] usb 1-1.1.3.1: device descriptor read/64, error -71
Sep 21 19:40:23 alchemist kernel: [   77.491581] usb 1-1.1.3.1: device descriptor read/64, error -71
Sep 21 19:40:23 alchemist kernel: [   77.611690] usb 1-1.1.3-port1: attempt power cycle
Sep 21 19:40:23 alchemist kernel: [   78.291587] usb 1-1.1.3.1: new full-speed USB device number 23 using dwc_otg
Sep 21 19:40:24 alchemist kernel: [   78.741596] usb 1-1.1.3.1: device not accepting address 23, error -71
Sep 21 19:40:24 alchemist kernel: [   78.851598] usb 1-1.1.3.1: new full-speed USB device number 24 using dwc_otg
Sep 21 19:40:24 alchemist kernel: [   79.291602] usb 1-1.1.3.1: device not accepting address 24, error -71
Sep 21 19:40:24 alchemist kernel: [   79.291819] usb 1-1.1.3-port1: unable to enumerate USB device

Whereas if I plug the same device in directly:

Sep 21 19:40:35 alchemist kernel: [   89.741673] usb 1-1.2: new full-speed USB device number 25 using dwc_otg
Sep 21 19:40:35 alchemist kernel: [   89.955317] usb 1-1.2: New USB device found, idVendor=1b12, idProduct=0015
Sep 21 19:40:35 alchemist kernel: [   89.955325] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Sep 21 19:40:35 alchemist kernel: [   89.955329] usb 1-1.2: Product: H9 Pedal
Sep 21 19:40:35 alchemist kernel: [   89.955334] usb 1-1.2: Manufacturer: Eventide (www.eventide.com)
Sep 21 19:40:35 alchemist kernel: [   89.955338] usb 1-1.2: SerialNumber: *****Obscured*****
Sep 21 19:40:35 alchemist mtp-probe: checking bus 1, device 25: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2"
Sep 21 19:40:35 alchemist mtp-probe: bus: 1, device: 25 was not an MTP device

Here is another device, plugged in through the hub:

Sep 21 19:43:08 alchemist kernel: [  242.463224] usb 1-1.1.3.1: new full-speed USB device number 26 using dwc_otg
Sep 21 19:43:08 alchemist kernel: [  242.573224] usb 1-1.1.3.1: device descriptor read/64, error -71
Sep 21 19:43:08 alchemist kernel: [  242.803221] usb 1-1.1.3.1: device descriptor read/64, error -71
Sep 21 19:43:08 alchemist kernel: [  243.033221] usb 1-1.1.3.1: new full-speed USB device number 27 using dwc_otg
Sep 21 19:43:08 alchemist kernel: [  243.143230] usb 1-1.1.3.1: device descriptor read/64, error -71
Sep 21 19:43:08 alchemist kernel: [  243.373222] usb 1-1.1.3.1: device descriptor read/64, error -71
Sep 21 19:43:09 alchemist kernel: [  243.493372] usb 1-1.1.3-port1: attempt power cycle
Sep 21 19:43:09 alchemist kernel: [  244.173227] usb 1-1.1.3.1: new full-speed USB device number 28 using dwc_otg
Sep 21 19:43:10 alchemist kernel: [  244.613231] usb 1-1.1.3.1: device not accepting address 28, error -71
Sep 21 19:43:10 alchemist kernel: [  244.723233] usb 1-1.1.3.1: new full-speed USB device number 29 using dwc_otg
Sep 21 19:43:10 alchemist kernel: [  245.163240] usb 1-1.1.3.1: device not accepting address 29, error -71
Sep 21 19:43:10 alchemist kernel: [  245.163431] usb 1-1.1.3-port1: unable to enumerate USB device

And plugged in directly to the pi:

Sep 21 19:43:20 alchemist kernel: [  255.113284] usb 1-1.3: new full-speed USB device number 30 using dwc_otg
Sep 21 19:43:20 alchemist kernel: [  255.246816] usb 1-1.3: New USB device found, idVendor=1c75, idProduct=0288
Sep 21 19:43:20 alchemist kernel: [  255.246823] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Sep 21 19:43:20 alchemist kernel: [  255.246828] usb 1-1.3: Product: Arturia KeyStep 32
Sep 21 19:43:20 alchemist kernel: [  255.246832] usb 1-1.3: Manufacturer: Arturia
Sep 21 19:43:20 alchemist kernel: [  255.246836] usb 1-1.3: SerialNumber: 00000000001A
Sep 21 19:43:20 alchemist mtp-probe: checking bus 1, device 30: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3"
Sep 21 19:43:20 alchemist mtp-probe: bus: 1, device: 30 was not an MTP device

Both devices work fine with this hub on other systems.