Bug 22052 - Logs spammed with "unable to enumerate USB port" in 2.6.37-rc1 - bisected to commit 3df7169e
Logs spammed with "unable to enumerate USB port" in 2.6.37-rc1 - bisected to ...
Status: CLOSED CODE_FIX
Product: Drivers
Classification: Unclassified
Component: USB
All Linux
: P1 normal
Assigned To: Greg Kroah-Hartman
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2010-11-04 14:16 UTC by Larry Finger
Modified: 2012-02-23 21:52 UTC (History)
3 users (show)

See Also:
Kernel Version:
Tree: Mainline
Regression: Yes


Attachments
Full output from dmesg (219.92 KB, text/plain)
2010-11-04 14:16 UTC, Larry Finger
Details
dmesg file with debugging in kernel = on (123.43 KB, application/octet-stream)
2011-07-06 06:04 UTC, Hans
Details
Config file, how I built the kernel (122.18 KB, text/plain)
2011-07-06 16:40 UTC, Hans
Details
dmesg log with CONFIG_USB_DEBUG enabled. (303.58 KB, text/plain)
2011-07-06 18:45 UTC, Larry Finger
Details
put OHCI controller into suspend after reset (1.80 KB, patch)
2011-07-07 20:48 UTC, Alan Stern
Details | Diff

Description Larry Finger 2010-11-04 14:16:29 UTC
Created attachment 36162 [details]
Full output from dmesg

Commit 3df7169e73fc1d71a39cffeacc969f6840cdf52b causes my system to spam the
logs with messages of the form "hub 2-0:1.0: unable to enumerate USB device on
port 5". Bisection was used to locate that commit.

Although reverting the above commit restores the original behavior, I am coming to believe that the true bug is somewhere else, and that the patch merely allows it to be triggered. Note: The "failure to enumerate" messages have been seen previously on this hardware; however, loading ehci_hcd before ohci_hcd "fixed" the problem in that instance.


==============================================
I enabled USB debugging. Although I don't understand all the data, this section looks strange.

ehci_hcd 0000:00:04.1: GetStatus port:5 status 003001 0  ACK POWER OWNER sig=se0 CONNECT
hub 2-0:1.0: port 5 not reset yet, waiting 50ms
ehci_hcd 0000:00:04.1: GetStatus port:5 status 001002 0  ACK POWER sig=se0 CSC
hub 2-0:1.0: unable to enumerate USB device on port 5

===========================================
A bigger portion of the dmesg output with USB debugging enabled follows (full dmesg output attached):
 
usb usb1: usb_probe_device
usb usb1: configuration #1 chosen from 1 choice
usb usb1: adding 1-0:1.0 (config #1, interface 0)
ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
ohci_hcd: block sizes: ed 80 td 96
hub 1-0:1.0: usb_probe_interface
hub 1-0:1.0: usb_probe_interface - got id
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 5 ports detected
hub 1-0:1.0: standalone hub
hub 1-0:1.0: no power switching (usb 1.0)
hub 1-0:1.0: individual port over-current protection
hub 1-0:1.0: power on to power good time: 20ms
hub 1-0:1.0: local power source is good
hub 1-0:1.0: trying to enable port power on non-switchable hub
drivers/usb/core/inode.c: creating file '001'
ACPI: PCI Interrupt Link [Z013] enabled at IRQ 16
ehci_hcd 0000:00:04.1: PCI INT B -> Link[Z013] -> GSI 16 (level, low) -> IRQ 16
ehci_hcd 0000:00:04.1: setting latency timer to 64
ehci_hcd 0000:00:04.1: EHCI Host Controller
drivers/usb/core/inode.c: creating file '002'
ehci_hcd 0000:00:04.1: new USB bus registered, assigned bus number 2
ehci_hcd 0000:00:04.1: reset hcs_params 0x101c85 dbg=1 cc=1 pcc=12 !ppc ports=5
ehci_hcd 0000:00:04.1: reset portroute 0 0 0 0 0 
ehci_hcd 0000:00:04.1: reset hcc_params a087 caching frame 256/512/1024 park 64 bit addr
ehci_hcd 0000:00:04.1: park 0
ehci_hcd 0000:00:04.1: debug port 1
ehci_hcd 0000:00:04.1: reset command 0080b02  park=3 ithresh=8 period=1024 Reset HALT
ehci_hcd 0000:00:04.1: cache line size of 64 is not supported
ehci_hcd 0000:00:04.1: supports USB remote wakeup
ehci_hcd 0000:00:04.1: irq 16, io mem 0xfc489400
ehci_hcd 0000:00:04.1: reset command 0080b02  park=3 ithresh=8 period=1024 Reset HALT
ehci_hcd 0000:00:04.1: init command 0010005 (park)=0 ithresh=1 period=512 RUN
sda: sda1 sda2 sda3 sda4 < sda5 >
ehci_hcd 0000:00:04.1: USB 2.0 started, EHCI 1.00
usb usb2: default language 0x0409
usb usb2: udev 1, busnum 2, minor = 128
usb usb2: New USB device found, idVendor=1d6b, idProduct=0002
usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
usb usb2: Product: EHCI Host Controller
usb usb2: Manufacturer: Linux 2.6.37-rc1-realtek+ ehci_hcd
usb usb2: SerialNumber: 0000:00:04.1
usb usb2: usb_probe_device
usb usb2: configuration #1 chosen from 1 choice
usb usb2: adding 2-0:1.0 (config #1, interface 0)
hub 2-0:1.0: usb_probe_interface
hub 2-0:1.0: usb_probe_interface - got id
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 5 ports detected
hub 2-0:1.0: standalone hub
hub 2-0:1.0: no power switching (usb 1.0)
hub 2-0:1.0: individual port over-current protection
hub 2-0:1.0: power on to power good time: 20ms
hub 2-0:1.0: local power source is good
hub 2-0:1.0: trying to enable port power on non-switchable hub
drivers/usb/core/inode.c: creating file '001'
ACPI: PCI Interrupt Link [LUS0] enabled at IRQ 17
ohci_hcd 0000:00:02.0: PCI INT A -> Link[LUS0] -> GSI 17 (level, low) -> IRQ 17
ohci_hcd 0000:00:02.0: setting latency timer to 64
ohci_hcd 0000:00:02.0: OHCI Host Controller
drivers/usb/core/inode.c: creating file '003'
ohci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 3
sd 0:0:0:0: [sda] Attached SCSI disk
ohci_hcd 0000:00:02.0: enabled nVidia shutdown quirk
ohci_hcd 0000:00:02.0: created debug files
ohci_hcd 0000:00:02.0: supports USB remote wakeup
ohci_hcd 0000:00:02.0: irq 17, io mem 0xfc486000
ohci_hcd 0000:00:02.0: OHCI: hc_control 0x200
ehci_hcd 0000:00:02.1: GetStatus port:1 status 001803 0  ACK POWER sig=j CSC CONNECT
hub 1-0:1.0: port 1: status 0501 change 0001
ehci_hcd 0000:00:02.1: GetStatus port:4 status 001803 0  ACK POWER sig=j CSC CONNECT
hub 1-0:1.0: port 4: status 0501 change 0001
ehci_hcd 0000:00:02.1: GetStatus port:5 status 001803 0  ACK POWER sig=j CSC CONNECT
hub 1-0:1.0: port 5: status 0501 change 0001
ohci_hcd 0000:00:02.0: OHCI controller state
ohci_hcd 0000:00:02.0: OHCI 1.0, NO legacy support registers
ohci_hcd 0000:00:02.0: control 0x683 RWE RWC HCFS=operational CBSR=3
ohci_hcd 0000:00:02.0: cmdstatus 0x00000 SOC=0
ohci_hcd 0000:00:02.0: intrstatus 0x00000004 SF
ohci_hcd 0000:00:02.0: intrenable 0x8000005a MIE RHSC UE RD WDH
ohci_hcd 0000:00:02.0: hcca frame #0003
ohci_hcd 0000:00:02.0: roothub.a 01000205 POTPGT=1 NPS NDP=5(5)
ohci_hcd 0000:00:02.0: roothub.b 00000000 PPCM=0000 DR=0000
ohci_hcd 0000:00:02.0: roothub.status 00008000 DRWE
ohci_hcd 0000:00:02.0: roothub.portstatus [0] 0x00000100 PPS
ohci_hcd 0000:00:02.0: roothub.portstatus [1] 0x00000100 PPS
ohci_hcd 0000:00:02.0: roothub.portstatus [2] 0x00000100 PPS
ohci_hcd 0000:00:02.0: roothub.portstatus [3] 0x00000100 PPS
ohci_hcd 0000:00:02.0: roothub.portstatus [4] 0x00000100 PPS
usb usb3: default language 0x0409
usb usb3: udev 1, busnum 3, minor = 256
usb usb3: New USB device found, idVendor=1d6b, idProduct=0001
usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
usb usb3: Product: OHCI Host Controller
usb usb3: Manufacturer: Linux 2.6.37-rc1-realtek+ ohci_hcd
usb usb3: SerialNumber: 0000:00:02.0
usb usb3: usb_probe_device
usb usb3: configuration #1 chosen from 1 choice
usb usb3: adding 3-0:1.0 (config #1, interface 0)
hub 3-0:1.0: usb_probe_interface
hub 3-0:1.0: usb_probe_interface - got id
hub 3-0:1.0: USB hub found
hub 3-0:1.0: 5 ports detected
hub 3-0:1.0: standalone hub
hub 3-0:1.0: no power switching (usb 1.0)
hub 3-0:1.0: global over-current protection
hub 3-0:1.0: power on to power good time: 2ms
hub 3-0:1.0: local power source is good
hub 3-0:1.0: no over-current condition exists
hub 3-0:1.0: trying to enable port power on non-switchable hub
drivers/usb/core/inode.c: creating file '001'
ehci_hcd 0000:00:02.1: HS companion for 0000:00:02.0
ACPI: PCI Interrupt Link [Z012] enabled at IRQ 16
ohci_hcd 0000:00:04.0: PCI INT A -> Link[Z012] -> GSI 16 (level, low) -> IRQ 16
ohci_hcd 0000:00:04.0: setting latency timer to 64
ohci_hcd 0000:00:04.0: OHCI Host Controller
drivers/usb/core/inode.c: creating file '004'
ohci_hcd 0000:00:04.0: new USB bus registered, assigned bus number 4
ohci_hcd 0000:00:04.0: enabled nVidia shutdown quirk
ohci_hcd 0000:00:04.0: created debug files
ohci_hcd 0000:00:04.0: supports USB remote wakeup
ohci_hcd 0000:00:04.0: irq 16, io mem 0xfc487000
ohci_hcd 0000:00:04.0: OHCI: hc_control 0x200
ehci_hcd 0000:00:04.1: GetStatus port:5 status 001c03 0  ACK POWER sig=? CSC CONNECT
hub 2-0:1.0: port 5: status 0501 change 0001
ohci_hcd 0000:00:04.0: OHCI controller state
ohci_hcd 0000:00:04.0: OHCI 1.0, NO legacy support registers
ohci_hcd 0000:00:04.0: control 0x683 RWE RWC HCFS=operational CBSR=3
ohci_hcd 0000:00:04.0: cmdstatus 0x00000 SOC=0
ohci_hcd 0000:00:04.0: intrstatus 0x00000004 SF
ohci_hcd 0000:00:04.0: intrenable 0x8000005a MIE RHSC UE RD WDH
ohci_hcd 0000:00:04.0: hcca frame #0003
ohci_hcd 0000:00:04.0: roothub.a 01000205 POTPGT=1 NPS NDP=5(5)
ohci_hcd 0000:00:04.0: roothub.b 00000000 PPCM=0000 DR=0000
ohci_hcd 0000:00:04.0: roothub.status 00008000 DRWE
ohci_hcd 0000:00:04.0: roothub.portstatus [0] 0x00000100 PPS
ohci_hcd 0000:00:04.0: roothub.portstatus [1] 0x00000100 PPS
ohci_hcd 0000:00:04.0: roothub.portstatus [2] 0x00000100 PPS
ohci_hcd 0000:00:04.0: roothub.portstatus [3] 0x00000100 PPS
ohci_hcd 0000:00:04.0: roothub.portstatus [4] 0x00000100 PPS
usb usb4: default language 0x0409
usb usb4: udev 1, busnum 4, minor = 384
usb usb4: New USB device found, idVendor=1d6b, idProduct=0001
usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1
usb usb4: Product: OHCI Host Controller
usb usb4: Manufacturer: Linux 2.6.37-rc1-realtek+ ohci_hcd
usb usb4: SerialNumber: 0000:00:04.0
usb usb4: usb_probe_device
usb usb4: configuration #1 chosen from 1 choice
usb usb4: adding 4-0:1.0 (config #1, interface 0)
hub 4-0:1.0: usb_probe_interface
hub 4-0:1.0: usb_probe_interface - got id
hub 4-0:1.0: USB hub found
hub 4-0:1.0: 5 ports detected
hub 4-0:1.0: standalone hub
hub 4-0:1.0: no power switching (usb 1.0)
hub 4-0:1.0: global over-current protection
hub 4-0:1.0: power on to power good time: 2ms
hub 4-0:1.0: local power source is good
hub 4-0:1.0: no over-current condition exists
hub 4-0:1.0: trying to enable port power on non-switchable hub
drivers/usb/core/inode.c: creating file '001'
ehci_hcd 0000:00:04.1: HS companion for 0000:00:04.0
hub 1-0:1.0: state 7 ports 5 chg 0032 evt 0000
hub 1-0:1.0: port 1, status 0501, change 0000, 480 Mb/s
ehci_hcd 0000:00:02.1: port 1 high speed
ehci_hcd 0000:00:02.1: GetStatus port:1 status 001005 0  ACK POWER sig=se0 PE CONNECT
usb 1-1: new high speed USB device using ehci_hcd and address 2
ehci_hcd 0000:00:02.1: port 1 high speed
ehci_hcd 0000:00:02.1: GetStatus port:1 status 001005 0  ACK POWER sig=se0 PE CONNECT
usb 1-1: udev 2, busnum 1, minor = 1
usb 1-1: New USB device found, idVendor=0409, idProduct=005a
usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
usb 1-1: usb_probe_device
usb 1-1: configuration #1 chosen from 1 choice
usb 1-1: adding 1-1:1.0 (config #1, interface 0)
hub 1-1:1.0: usb_probe_interface
hub 1-1:1.0: usb_probe_interface - got id
hub 1-1:1.0: USB hub found
hub 1-1:1.0: 4 ports detected
hub 1-1:1.0: standalone hub
hub 1-1:1.0: ganged power switching
hub 1-1:1.0: global over-current protection
hub 1-1:1.0: Single TT
hub 1-1:1.0: TT requires at most 16 FS bit times (1332 ns)
hub 1-1:1.0: Port indicators are supported
hub 1-1:1.0: power on to power good time: 100ms
hub 1-1:1.0: local power source is good
hub 1-1:1.0: no over-current condition exists
hub 1-1:1.0: enabling power on all ports
drivers/usb/core/inode.c: creating file '002'
hub 1-0:1.0: port 4, status 0501, change 0000, 480 Mb/s
ehci_hcd 0000:00:02.1: port 4 high speed
ehci_hcd 0000:00:02.1: GetStatus port:4 status 001005 0  ACK POWER sig=se0 PE CONNECT
usb 1-1: link qh256-0001/ffff8800b3661600 start 1 [1/0 us]
usb 1-4: new high speed USB device using ehci_hcd and address 3
PM: Starting manual resume from disk
ehci_hcd 0000:00:02.1: port 4 high speed
ehci_hcd 0000:00:02.1: GetStatus port:4 status 001005 0  ACK POWER sig=se0 PE CONNECT
usb 1-4: skipped 1 descriptor after configuration
usb 1-4: skipped 5 descriptors after interface
usb 1-4: skipped 1 descriptor after endpoint
usb 1-4: skipped 9 descriptors after interface
usb 1-4: default language 0x0409
usb 1-4: udev 3, busnum 1, minor = 2
usb 1-4: New USB device found, idVendor=04f2, idProduct=b016
usb 1-4: New USB device strings: Mfr=2, Product=1, SerialNumber=3
usb 1-4: Product: HP Webcam
usb 1-4: Manufacturer: Chicony Electronics Co., Ltd.
usb 1-4: SerialNumber: SN0001
usb 1-4: usb_probe_device
usb 1-4: configuration #1 chosen from 1 choice
usb 1-4: adding 1-4:1.0 (config #1, interface 0)
usb 1-4: adding 1-4:1.1 (config #1, interface 1)
drivers/usb/core/inode.c: creating file '003'
hub 1-0:1.0: port 5, status 0501, change 0000, 480 Mb/s
ehci_hcd 0000:00:02.1: port 5 high speed
ehci_hcd 0000:00:02.1: GetStatus port:5 status 001005 0  ACK POWER sig=se0 PE CONNECT
usb 1-5: new high speed USB device using ehci_hcd and address 4
ehci_hcd 0000:00:02.1: port 5 high speed
ehci_hcd 0000:00:02.1: GetStatus port:5 status 001005 0  ACK POWER sig=se0 PE CONNECT
EXT3-fs: barriers not enabled
kjournald starting.  Commit interval 5 seconds
EXT3-fs (sda1): using internal journal
EXT3-fs (sda1): mounted filesystem with writeback data mode
usb 1-5: default language 0x0409
usb 1-5: udev 4, busnum 1, minor = 3
usb 1-5: New USB device found, idVendor=07d1, idProduct=3300
usb 1-5: New USB device strings: Mfr=1, Product=2, SerialNumber=3
usb 1-5: Product: 11n Adapter
usb 1-5: Manufacturer: Manufacturer Realtek 
usb 1-5: SerialNumber: 00e04c000001
usb 1-5: usb_probe_device
usb 1-5: configuration #1 chosen from 1 choice
usb 1-5: adding 1-5:1.0 (config #1, interface 0)
drivers/usb/core/inode.c: creating file '004'
hub 3-0:1.0: state 7 ports 5 chg 0000 evt 0000
hub 2-0:1.0: state 7 ports 5 chg 0020 evt 0000
hub 2-0:1.0: port 5, status 0501, change 0000, 480 Mb/s
ehci_hcd 0000:00:04.1: port 5 full speed --> companion
ehci_hcd 0000:00:04.1: GetStatus port:5 status 003001 0  ACK POWER OWNER sig=se0 CONNECT
hub 2-0:1.0: port 5 not reset yet, waiting 50ms
ehci_hcd 0000:00:04.1: GetStatus port:5 status 001002 0  ACK POWER sig=se0 CSC
hub 2-0:1.0: unable to enumerate USB device on port 5
hub 4-0:1.0: state 7 ports 5 chg 0000 evt 0000
hub 1-1:1.0: state 7 ports 4 chg 0000 evt 0000
hub 2-0:1.0: state 7 ports 5 chg 0000 evt 0020
hub 2-0:1.0: state 7 ports 5 chg 0000 evt 0020
ehci_hcd 0000:00:04.1: GetStatus port:5 status 001c03 0  ACK POWER sig=? CSC CONNECT
hub 2-0:1.0: port 5, status 0501, change 0001, 480 Mb/s
ohci_hcd 0000:00:02.0: auto-stop root hub
hub 2-0:1.0: debounce: port 5: total 100ms stable 100ms status 0x501
ehci_hcd 0000:00:04.1: port 5 full speed --> companion
ehci_hcd 0000:00:04.1: GetStatus port:5 status 003001 0  ACK POWER OWNER sig=se0 CONNECT
hub 2-0:1.0: port 5 not reset yet, waiting 50ms
ehci_hcd 0000:00:04.1: GetStatus port:5 status 001002 0  ACK POWER sig=se0 CSC
hub 2-0:1.0: unable to enumerate USB device on port 5
hub 2-0:1.0: state 7 ports 5 chg 0000 evt 0020
ohci_hcd 0000:00:04.0: auto-stop root hub
hub 2-0:1.0: state 7 ports 5 chg 0000 evt 0020
ehci_hcd 0000:00:04.1: GetStatus port:5 status 001c03 0  ACK POWER sig=? CSC CONNECT
hub 2-0:1.0: port 5, status 0501, change 0001, 480 Mb/s
hub 2-0:1.0: debounce: port 5: total 100ms stable 100ms status 0x501
ehci_hcd 0000:00:04.1: port 5 full speed --> companion
ehci_hcd 0000:00:04.1: GetStatus port:5 status 003001 0  ACK POWER OWNER sig=se0 CONNECT
hub 2-0:1.0: port 5 not reset yet, waiting 50ms
ehci_hcd 0000:00:04.1: GetStatus port:5 status 001002 0  ACK POWER sig=se0 CSC
hub 2-0:1.0: unable to enumerate USB device on port 5
hub 2-0:1.0: state 7 ports 5 chg 0000 evt 0020
hub 2-0:1.0: state 7 ports 5 chg 0000 evt 0020
ehci_hcd 0000:00:04.1: GetStatus port:5 status 001c03 0  ACK POWER sig=? CSC CONNECT

===================================
The lspci output for the PCI interfaces of the USB controllers are as follows:

00:02.0 USB Controller [0c03]: nVidia Corporation MCP67 OHCI USB 1.1 Controller
[10de:055e] (rev a2) (prog-if 10 [OHCI])
        Subsystem: Hewlett-Packard Company Device [103c:30d6]
        Flags: bus master, 66MHz, fast devsel, latency 0, IRQ 17
        Memory at fc486000 (32-bit, non-prefetchable) [size=4K]
        Capabilities: [44] Power Management version 2
        Kernel driver in use: ohci_hcd

00:02.1 USB Controller [0c03]: nVidia Corporation MCP67 EHCI USB 2.0 Controller
[10de:055f] (rev a2) (prog-if 20 [EHCI])
        Subsystem: Hewlett-Packard Company Device [103c:30d6]
        Flags: bus master, 66MHz, fast devsel, latency 0, IRQ 17
        Memory at fc489000 (32-bit, non-prefetchable) [size=256]
        Capabilities: [44] Debug port: BAR=1 offset=0098
        Capabilities: [80] Power Management version 2
        Kernel driver in use: ehci_hcd

00:04.0 USB Controller [0c03]: nVidia Corporation MCP67 OHCI USB 1.1 Controller
[10de:055e] (rev a2) (prog-if 10 [OHCI])
        Subsystem: Hewlett-Packard Company Device [103c:30d6]
        Flags: bus master, 66MHz, fast devsel, latency 0, IRQ 16
        Memory at fc487000 (32-bit, non-prefetchable) [size=4K]
        Capabilities: [44] Power Management version 2
        Kernel driver in use: ohci_hcd

00:04.1 USB Controller [0c03]: nVidia Corporation MCP67 EHCI USB 2.0 Controller
[10de:055f] (rev a2) (prog-if 20 [EHCI])
        Subsystem: Hewlett-Packard Company Device [103c:30d6]
        Flags: bus master, 66MHz, fast devsel, latency 0, IRQ 16
        Memory at fc489400 (32-bit, non-prefetchable) [size=256]
        Capabilities: [44] Debug port: BAR=1 offset=0098
        Capabilities: [80] Power Management version 2
        Kernel driver in use: ehci_hcd
Comment 1 Alan Stern 2010-11-04 16:06:25 UTC
> I enabled USB debugging. Although I don't understand all the data, this section
> looks strange.
> 
> ehci_hcd 0000:00:04.1: GetStatus port:5 status 003001 0  ACK POWER OWNER
> sig=se0 CONNECT
> hub 2-0:1.0: port 5 not reset yet, waiting 50ms
> ehci_hcd 0000:00:04.1: GetStatus port:5 status 001002 0  ACK POWER sig=se0 CSC
> hub 2-0:1.0: unable to enumerate USB device on port 5

This is normal enough.  When a non-high-speed device is attached to an 
EHCI controller, the controller reports its presence, tries to 
initialize it, and only then realizes that the device can't run at high 
speed.  Instead a bit gets set which causes the device connection to 
be routed to the companion OHCI controller.  That's what the

	ehci_hcd 0000:00:04.1: port 5 full speed --> companion

message means.  It looks like something goes wrong at this point and 
the device is reconnected to the EHCI controller, which sees it as a 
brand-new connection.  The connection routing isn't working right.

> ===========================================
> A bigger portion of the dmesg output with USB debugging enabled follows (full
> dmesg output attached):

In the future, please attach large files like this to the bug report 
instead of pasting them directly in the comment field.

Alan Stern
Comment 2 Hans 2011-06-11 08:46:30 UTC
Hi all, 

maybe this information helps:

The mentioned behaviour appeared in Debian/testing exactly since kernel version

linux-image-2.6.32-5-amd64. All higher versions include this bug.

However, I have to specify it, to get an exactly date of change!


working:      linux-image-2.6.32-5-amd64 (exact version 2.6.32-30)
non-working:  linux-image-2.6.32-5-amd64 (exact version 2.6.32-34s)

Between these two version must have been a change of the module "ohci-hcd", which causes this bug. Maybe it is possible, to revert only this module to an older and working state? This bug effects ALL kernels, so it appears also on any lifefile systems, like Knoppix, Backtrack5 and so on.

Hope this helps.

Best regards

Hans
Comment 3 Alan Stern 2011-06-11 16:49:30 UTC
This should now be fixed by commit 69d8d8fd0dabc5357f5ec91046bc1bd9011012b6 (OHCI: fix regression caused by nVidia shutdown workaround) in 2.6.39.1 and perhaps other stable kernels.
Comment 4 Hans 2011-06-27 19:40:28 UTC
Just tested linux-image-2.6.39-2-amd64 from debian-amd64/wheezy, but got the same error again. I also tested the newest kernel from debian-amd4/experimental, with no success, too.

Sorry to tell, the bug seems not to be fixed, yet.

As soon, as there is a new version in debian available, I will test this, and report of success or failure.

Thank you very much for your help anyway!

Best regards

Hans-J. Ullrich
Comment 5 Larry Finger 2011-06-27 20:10:14 UTC
What are the details for your USB hub as shown by lspci? As noted above, one of my hubs on an HP laptop seems to be wired incorrectly. There are two ways to kill the error messages:

(1) Add the following to a script that will run as soon as user space is working. On my openSUSE system, these are in /etc/init.d/boot.local:

echo "0000:00:04.1" > /sys/bus/pci/drivers/ehci_hcd/unbind
echo "0000:00:04.0" > /sys/bus/pci/drivers/ohci_hcd/unbind

The bus numbers would have to change for your system.

(2) Get rid of the message with the following patch:

Index: linux-2.6/drivers/usb/core/hub.c
===================================================================
--- linux-2.6.orig/drivers/usb/core/hub.c
+++ linux-2.6/drivers/usb/core/hub.c
@@ -3136,6 +3136,7 @@ static void hub_port_connect_change(stru
                        le16_to_cpu(hub->descriptor->wHubCharacteristics);
        struct usb_device *udev;
        int status, i;
+       static int msg_count;
 
        dev_dbg (hub_dev,
                "port %d, status %04x, change %04x, %s\n",
@@ -3347,8 +3348,9 @@ loop:
        if (hub->hdev->parent ||
                        !hcd->driver->port_handed_over ||
                        !(hcd->driver->port_handed_over)(hcd, port1))
-               dev_err(hub_dev, "unable to enumerate USB device on port %d\n",
-                               port1);
+               if (msg_count++ < 5)
+                       dev_err(hub_dev, "unable to enumerate USB device on port %d\n",
+                                       port1);
  
 done:
        hub_port_disable(hub, port1, 1);

With this installed, you will get 5 of the messages.
Comment 6 Alan Stern 2011-06-27 20:19:37 UTC
That linux-image-2.6.39-2-amd64 sonds like it still uses a 2.6.39 kernel, not 2.6.39.1 or later.  What version does debian-amd4/experimental use?

Can you try building your own kernel from the source at kernel.org?
Comment 7 Hans 2011-06-27 20:54:29 UTC
Hi Alan, 

maybe you are right, the debian kernel might still be a 2.6.39 (although they patch kernels sometimes and add a "-N" (where N is a number) to it.
I dare not to build an own kernel from kernel.org, as this is my productive notebook, which I need every day and can not allow me, to brick it with a kernel I built by myself. I am not much experienced with building a kernel from kernel.org, although it was easy for me to rebuild with the kernel-sources from debian.


Hello Larry,
I already tried this thing before, but it did not work for me. In my case the usb-hub on my notebook should be wired correctly, as I already mentioned, it is ok with an older kernel. 


General
I googled a little bit, and it seems, this bug appears only on systems with a Nvidia chipset  MCP67. Because of this, there are not many bugreports, as the combination 
"Kernel-2.6.3[3-9] + Nvidia chipset MCP67" will be not much used.

I will wait for 2.6.39.1 in debian. Fingers crossed! In the meantime I am still using 2.6.32, which is running great, too.

Thanks and great, that you took a look at this bug, although we are only few people with this problem.

Hans
Comment 8 Larry Finger 2011-06-27 21:00:46 UTC
My system was OK with an older kernel. Any kernel prior to the commit in the title of this bug report was OK.

I agree that the nVidia controllers are the problem.
Comment 9 Alan Stern 2011-06-27 21:10:34 UTC
You can check the debian source code to see if the patch which was supposed to fix the regression has been incorporated.  The patch itself is here:

http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=2b7aaf503d56216b847c8265421d2a7d9b42df3e

If it isn't in the debian source, you can add it yourself and test it.
Comment 10 Hans 2011-06-29 22:19:16 UTC
Hi Alan,

just tested the latest kernel from debian. Due to the changelog, your fix 
69d8d8fd0dabc5357f5ec91046bc1bd9011012b6 is included. But sorry, to tell you, the fix on my system does still not work. 

My USB-Controller is this:

00:02.0 USB Controller: nVidia Corporation MCP67 OHCI USB 1.1 Controller (rev a2)
00:02.1 USB Controller: nVidia Corporation MCP67 EHCI USB 2.0 Controller (rev a2)
00:04.0 USB Controller: nVidia Corporation MCP67 OHCI USB 1.1 Controller (rev a2)
00:04.1 USB Controller: nVidia Corporation MCP67 EHCI USB 2.0 Controller (rev a2)

I read, that this problem is not easy to fix. But there is no time to hurry! I will be happy, if you or someone else will have a look on it, but there is no reason for hurry.

This comment is just an info, that the bug is still existent (maybe now only on very few and special systems like mine).

I am very happy, that someone cares at all!

Cheers

Hans
Comment 11 Alan Stern 2011-06-30 14:06:02 UTC
Can you build a kernel with CONFIG_USB_DEBUG enabled and then attach a copy of the dmesg log for bootup?
Comment 12 Hans 2011-07-01 19:19:54 UTC
Hi Alan, 

lasted a little bit, but now I managed to build the kernel. I hope, the attached dmesg is not too long.

I hope, this will help a little bit.

Happy hacking!

Hans
Comment 13 Alan Stern 2011-07-01 20:53:23 UTC
The log you sent clearly came from a kernel built without CONFIG_USB_DEBUG, so I can't tell anything much from looking at it.  But at least it doesn't contain any of those "unable to enumerate USB device" messages.  Does that mean it's working correctly?
Comment 14 Hans 2011-07-01 21:04:57 UTC
Hello Alan,

nope, the logs should be from the kernel built with CONFIG_USB_DEBUG=y (before build, i checked, and I saw during build a lot of "--opt-debug" messages.

Let me check again, I will create new dmesg files and send them again. Maybe I made somthing wrong, as I had had a little troubly while building (my /usr partition was too small, so I had to free some space and had to build several times).

I will send the logs to your e-mail-address again.


Hans
Comment 15 Alan Stern 2011-07-01 21:11:30 UTC
You should be able to attach the log with no difficulty.  What went wrong last time?

If you have to email it to me, it's not necessary to include multiple copies of the log; one copy is enough.  Plain text, not compressed.
Comment 16 Hans 2011-07-01 21:49:41 UTC
Sorry for sending too much of the logs. I searched for a "attach file" button in this mask, but found none. As the kernel-module was spamming my logfiles, I did not dare, to sent this long textfile here in this messages. I thought the original one from Larry might explainb things, too.

The error message appears almost every second (or faster) in the console, so my log is also full of it.

Working with kernel-2.6.39 is nealy imposible, as it spams console (tty1-6), too. I am just working in X (with xterm), where I do not see any error messages.

Please excuse, that I can help only such few. Besides just a question: I wondered, that during kernel build the sources blew up from to over 6GB! That is very much, is that normal? It broke my /usr partition (no space left), as I had only 4GB free.

Hans
Comment 17 Hans 2011-07-05 08:54:41 UTC
Hi Alan, 

it's me again. I just dicovered, that debian offers an already compiled debug kernel as a simply to install package. That way, it is easy for me to create dmesg-files with a lot of information. Howevedr, i think, they might be very large. So I decided to send them directly to you, if you don't mind. The bug is still existent, despite of the already mentioned bugfix in the changelog.


Please feel free, to populate the necessary dmesg-parts here, so that other people can also have a look at it and might be able to help. 

For any futher information I will be happy to help.

Hans
Comment 18 Alan Stern 2011-07-05 17:59:47 UTC
What I'd like to see at this point is a dmesg log starting from bootup of 2.6.39.1 with CONFIG_USB_DEBUG enabled.  Also, you can stop sending those logs with thousands of debugging messages about the port statuses -- they're all exactly the same, so seeing hundreds and hundreds of them gives me no more information than seeing just one.

The "Add an attachment" button is at the bottom of the "Attachments" box near the top of this Bugzilla web page.
Comment 19 Hans 2011-07-06 06:04:39 UTC
Created attachment 64762 [details]
dmesg file with debugging in kernel = on

This is my dmesg output. During this session I unloaded ohci-hcd using rmmod and loaded it again with modprobe ohci-hcd.
Comment 20 Alan Stern 2011-07-06 15:01:44 UTC
The attached file is useless because it contains nothing but those port status messages.  You may need to increase CONFIG_LOG_BUF_SHIFT, perhaps make it as large as 20.  Or else boot with a serial or network console so that the log can be captured remotely.

Also, when you add an attachment that is a plain text file, you should tell Bugzilla it is plain text by choosing the appropriate selection under "Content Type" -- don't use auto-detect.
Comment 21 Hans 2011-07-06 15:27:28 UTC
Hi Alan, 

I suggest to close this bugreport, as it seems, I am the only one who has got this problem. It always lasted hours to build a new kernel, then testing ist and then uninstall it again and make everything clean again. It is really kind of you to help, but doing this only for me it is not worth the thing. I can stay at the older kernel, it does not matter for me. Obviously your fix already helped the others (like Larry) and for myself to fix this bug is not necessary. There are more important things than fix this little bug to do. 

So I suggest not to spend any time for me, I see, it will not be easy to solve. You already helped me by confirming, it is because of my Nvidia-special-hardware. 

So again, safely close the bugreport, I will check again when kernel-3.0 will be released. Then maybe I might reopen the bug again, if you don't mind.

Thank you for all the patience and the time you were looking at my messages.

Best regards

Hans
Comment 22 Larry Finger 2011-07-06 15:36:55 UTC
I still have the problem and there is at least one more person on the openSUSE Forums that sees it. I'm happy with my workarounds, but I think the bug should be left open just in case it is not a hardware problem as Alan and I concluded earlier.
Comment 23 Hans 2011-07-06 15:46:20 UTC
Hello Larry, it is ok for me to let this bug open. 

I just wanted to avoid, that people cared of ONE person (me), who 
- additionally can only very little help. 
- has lot of problems, due to small ressources of time and hardware
- counts that bug not so muich important for himself

Please excuse!

Best regards

Hans
Comment 24 Alan Stern 2011-07-06 16:17:04 UTC
Larry, if you're willing to continue investigating, you can do what I asked Hans: Attach a dmesg log from a kernel with CONFIG_USB_DEBUG enabled.  It doesn't have to start from bootup; all I really need to see is what happens when ohci-hcd is loaded and the host controllers are initialized.
Comment 25 Hans 2011-07-06 16:40:47 UTC
Created attachment 64812 [details]
Config file, how I built the kernel
Comment 26 Larry Finger 2011-07-06 18:45:02 UTC
Created attachment 64832 [details]
dmesg log with CONFIG_USB_DEBUG enabled.

Alan: I hope I let this run long enough for you. I disabled my code that limits the number of messages that are logged and the special commands that unbind the offending hubs.

As you see, the kernel is a 3.0.0-rc5 from the staging-2.6 git tree.
Comment 27 Alan Stern 2011-07-06 20:33:37 UTC
That's plenty long enough -- in fact, the first 20 seconds would have been more than long enough.

Our of curiosity, what happens if you unload ehci-hcd?  Does the low-speed device plugged into port 5 then connect okay?  Or do the OHCI ports remain unusable?

Comparing the current system with the code before the troublesome commit, I see only one difference.  In drivers/usb/host/pci-quirks.c:quirk_usb_handoff_ohci(), these lines

	/* reset controller, preserving RWC (and possibly IR) */
	writel(control & OHCI_CTRL_MASK, base + OHCI_CONTROL);

used to be up a little, inside the "if (control & OHCI_CTRL_IR) {" block.  With NVIDIA hardware, I assume that test fails and the block doesn't get executed.

You can test to see if commenting out that writel() gets rid of all those messages, and if it allows the low-speed device to work with the OHCI controller.
Comment 28 Hans 2011-07-06 21:00:24 UTC
Hi Alan, 

when ehci-hcd is unloaded, the spamming messages are staying. But when you unload ohci-hcd, the messages disappear. I also tried to reinitialise /dev/usb (there was a workaround I found somewhere in the internet), that told me to echo something to /proc, but I cannot remember, what exactly it told me. Sorry for that!
But I can confirm, that workaround did not work here. However, I could find out, that ehci-hcd does not interfere with ohci-hcd and other round. 

Hope this helps a little bit.

Hans
Comment 29 Hans 2011-07-06 21:02:50 UTC
Hi Alan, 

when ehci-hcd is unloaded, the spamming messages are staying. But when you unload ohci-hcd, the messages disappear. I also tried to reinitialise /dev/usb (there was a workaround I found somewhere in the internet), that told me to echo something to /proc, but I cannot remember, what exactly it told me. Sorry for that!
But I can confirm, that workaround did not work here. However, I could find out, that ehci-hcd does not interfere with ohci-hcd and other round. 

Hope this helps a little bit.

Hans
Comment 30 Larry Finger 2011-07-07 01:14:15 UTC
On my system, lsusb shows the following:

Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 001 Device 002: ID 04f2:b016 Chicony Electronics Co., Ltd VGA 30fps UVC Webcam

There are 3 accessible USB ports. I do not have any low-speed devices, but high-speed units plugged into those ports all show up on Bus 1. From that I concluded that Bus 2 and its companion 1.1 root hub (Bus 4?) are present on the motherboard, but have no ports attached. On a laptop, it is hard to tell. In any case, I have no way of testing that any port on those hubs is functional.

Yes, disabling the writel(control & OHCI_CTRL_MASK, base + OHCI_CONTROL); line causes the problem to disappear.

I have a local patch that limits the number of "unable to enumerate" messages logged to 5. That way I can quickly determine when and if a solution has been found. I also unlink those two hubs in boot.local just in case I run a kernel without the patch. Keeping those two modifications are not a severe burden.

Thanks for looking at this again.

Larry
Comment 31 Alan Stern 2011-07-07 20:48:30 UTC
Created attachment 64912 [details]
put OHCI controller into suspend after reset

Larry, here's a patch for you to try.  The only difference between the current driver and the old one is that during initialization, the OHCI controllers are now put into the RESET state (that's what the writel() does).  Evidently NVIDIA controllers don't like to remain in RESET for a long time.

This patch puts the controller into the SUSPEND state after 50 ms of reset.  Hopefully the controller won't mind this as much.
Comment 32 Larry Finger 2011-07-07 21:37:29 UTC
Congratulations. Adding that patch got rid of the remaining failure messages that I was allowing through and seems to have solved the problem.

I'm in the middle of a bisection at the moment with 8 steps left, which makes it tough to revert my special patch that suppresses the messages, but I feel that it is safe to push this one with a Tested-by: Larry Finger <Larry.Finger@lwfinger.net>. If that is wrong, I'll let you know within 24 hours.
Comment 33 Alan Stern 2011-07-08 20:01:39 UTC
That's great!  Still, I'd like to see more testing before I submit this.  Hans, can you try out that patch?  I'll also ask Ben Hutchings to prepare a kernel for other Debian users to try.

By the way, what happens with this patch if you unload ohci-hcd and then a few seconds later, modprobe it back?
Comment 34 Larry Finger 2011-07-09 17:49:38 UTC
The "unable to enumerate" messages return after unloading/reloading ohci-hcd.
Comment 35 Alan Stern 2011-07-09 21:41:58 UTC
I was afraid something like that might happen.  The driver leaves the controller in the RESET state when it exits.  Still, this doesn't seem like such a high price to pay.  Most people don't unload and reload their drivers.
Comment 36 Larry Finger 2011-07-10 00:16:01 UTC
I never have before. I agree that the "price" is reasonable, particularly as only a few of us are affected.
Comment 37 Hans 2011-07-10 07:22:31 UTC
Hi Alan, 

unloading ohci-hcd stops spamming the logs. When I load it again (modprobe ohci-hcd), the spamming is starting again. 

Very nice, when there is a kernel-package available, I will be pleased to install and test it. 
Either I can download it somewhere, or I may pull it from the debian repositories (experimental/debian-amd64).

As soon as I got results, I will be happy to report it.

Hans
Comment 38 Hans 2011-07-10 07:50:31 UTC
Hi Alan and Larry,

I just tested the latest kernel in debian, which is linux-image-3.0.0-rc6-amd64. I am not know, if your newest patch is already in this kernel. The changelog delivered by debian did nothing tell about usb. Well, the bug is still existent in this kernel, so I doubt, the fix is included. If it is, it did not work.

Does this help?

Hans
Comment 39 Alan Stern 2011-07-15 14:22:49 UTC
Ben Hutchings has now created some updated debian kernels for people to test:

> The binary packages are:
> http://people.debian.org/~benh/packages/linux-image-2.6.39-3-686-pae_2.6.39-4~a.test1_i386.deb
> http://people.debian.org/~benh/packages/linux-image-2.6.39-3-amd64_2.6.39-4~a.test1_amd64.deb
> 
> The source package and signed changes file are in the same directory.
Comment 40 Hans 2011-07-15 16:51:43 UTC
Hi Ben, Alan and all the other helpers. I just tested Ben's packages, and here they work very fine! Woot! No more annoying messages seen yet. 

Although I could bot build the nvidia-kernel-module (as the correct headers are yet missing), I suppose, the bug has been fixed. 

As soon as all packages are officially available, I will build nvidia-kernel-module and test again, but I think, this will be not necessary. I am very happy, really!

You should know, if this really works, it means, also most of the livefile systems like Backtrack5, Partimage, Clonezilla and many others, based on this kernel, will work in the next verion again. I am looking forward to the next release,, so that I can fix my version of Backtrack5 (which is at the moment unusable for me)

Thank you very much! Great work! 

Cheers

Hans
Comment 41 Alan Stern 2011-07-15 19:24:03 UTC
That's good news.  All right, I'll submit this patch for inclusion in the kernel.
Comment 42 Alan Stern 2011-07-29 13:48:56 UTC
The patch has been accepted and will appear in the 3.1 kernel as well as various stable kernels.  This bug report can be closed out.
Comment 43 Florian Mickler 2011-08-08 14:05:04 UTC
A patch referencing this bug report has been merged in Linux v3.1-rc1:

commit 6ea12a04d295235ed67010a09fdea58c949e3eb0
Author: Alan Stern <stern@rowland.harvard.edu>
Date:   Fri Jul 15 17:22:15 2011 -0400

    USB: OHCI: fix another regression for NVIDIA controllers
Comment 44 Greg Kroah-Hartman 2012-02-22 21:11:21 UTC
All USB bugs should be sent to the linux-usb@vger.kernel.org mailing 
list, and not entered into bugzilla.  Please bring this issue up there,
if it is still a problem in the latest kernel release.
Comment 45 Florian Mickler 2012-02-23 21:52:23 UTC
This seems to be fixed already.

Note You need to log in before you can comment on or make changes to this bug.