Bug 6684

Can you please turn on USB verbose debugging in the kernel configuration
(CONFIG_USB_DEBUG) and attach here the dmesg log showing what happens when you
unplug the mouse and then plug it back in?

Created attachment 8294 [details]
Output of dmesg

This is the output of dmesg with USB debugging enabled.

This appears to be a problem with the OHCI controller.  I will ask someone who
is familiar with that driver to look at this bug report.

Created attachment 8298 [details]
ohci root hub polling tweak

I suspect it's actually a previously-unknown issue with the
patch which teaches OHCI how to use the "new polling" scheme.
I know of what I think is a _different_ issue, addressed in
part by the attached patch, but there's still another problem
I found with that one.

If the issue is indeed with that OHCI patch (in the MM tree)
then it won't be found in the 2.6.17-rc tree.

Jure, have you been able to test that patch?

Thanks.

Sorry, not yet. I will do it in about 10 hours and report back.

When trying to patch I got this:

cat ../ohci.patch | patch -p1
patching file drivers/usb/host/ohci-hub.c
Hunk #1 succeeded at 350 (offset -1 lines).
Hunk #2 FAILED at 366.
Hunk #3 FAILED at 373.
2 out of 3 hunks FAILED -- saving rejects to file drivers/usb/host/ohci-hub.c.rej

I'll now recompile kernel and see how it goes.

Created attachment 8352 [details]
ohci-hub.c rejects

It looks like the patch doesn't work, or it didn't apply correctly.

I think David needs to be on the CC list for this bug, since it's up his alley.

Updating the kernel version since it still happens in 2.6.17-mm5. Is there any 
updated patch for this version that I could test again?

Is this issue still present in kernel 2.6.18-rc1-mm2?

No it still doesn't work. I get this dmesg output when unplugging and
re-plugging the mouse:

tg3: eth0: Link is up at 100 Mbps, full duplex.
tg3: eth0: Flow control is on for TX and on for RX.
ohci_hcd 0000:00:13.1: urb d7dc8440 path 3 ep1in 5c160000 cc 5 --> status -110
usbhid 3-3:1.0: retrying intr urb
ohci_hcd 0000:00:13.1: urb d7dc8440 path 3 ep1in 5c160000 cc 5 --> status -110
usbhid 3-3:1.0: retrying intr urb
ohci_hcd 0000:00:13.1: urb d7dc8440 path 3 ep1in 5c160000 cc 5 --> status -110
usbhid 3-3:1.0: retrying intr urb
ohci_hcd 0000:00:13.1: urb d7dc8440 path 3 ep1in 5c160000 cc 5 --> status -110
usbhid 3-3:1.0: retrying intr urb
ohci_hcd 0000:00:13.1: urb d7dc8440 path 3 ep1in 5c160000 cc 5 --> status -110
usbhid 3-3:1.0: retrying intr urb
ohci_hcd 0000:00:13.1: urb d7dc8440 path 3 ep1in 5c160000 cc 5 --> status -110
usbhid 3-3:1.0: retrying intr urb
ohci_hcd 0000:00:13.1: urb d7dc8440 path 3 ep1in 5c160000 cc 5 --> status -110
usbhid 3-3:1.0: retrying intr urb
ohci_hcd 0000:00:13.1: urb d7dc8440 path 3 ep1in 5c160000 cc 5 --> status -110
usbhid 3-3:1.0: retrying intr urb
ohci_hcd 0000:00:13.1: urb d7dc8440 path 3 ep1in 5c160000 cc 5 --> status -110
usbhid 3-3:1.0: retrying intr urb
ohci_hcd 0000:00:13.1: urb d7dc8440 path 3 ep1in 5c160000 cc 5 --> status -110
usbhid 3-3:1.0: retrying intr urb
ohci_hcd 0000:00:13.1: urb d7dc8440 path 3 ep1in 5c160000 cc 5 --> status -110
usbhid 3-3:1.0: resetting device
ohci_hcd 0000:00:13.1: GetStatus roothub.portstatus [2] = 0x00030100 PESC CSC PPS
ohci_hcd 0000:00:13.1: GetStatus roothub.portstatus [2] = 0x00030100 PESC CSC PPS
ohci_hcd 0000:00:13.1: GetStatus roothub.portstatus [2] = 0x00030100 PESC CSC PPS
ohci_hcd 0000:00:13.1: GetStatus roothub.portstatus [2] = 0x00030100 PESC CSC PPS
hub 3-0:1.0: logical disconnect on port 3
hub 3-0:1.0: state 7 ports 4 chg 0008 evt 0000
ohci_hcd 0000:00:13.1: GetStatus roothub.portstatus [2] = 0x00030100 PESC CSC PPS
hub 3-0:1.0: port 3, status 0100, change 0003, 12 Mb/s
usb 3-3: USB disconnect, address 3
usb 3-3: unregistering device
usb 3-3: usb_disable_device nuking all URBs
BUG: unable to handle kernel NULL pointer dereference at virtual address 00000020
 printing eip:
c0134d2f
*pde = 00000000
Oops: 0000 [#1]
8K_STACKS PREEMPT
last sysfs file: /power/state
Modules linked in: radeon drm eth1394 evdev bcm43xx ohci1394 snd_atiixp
ieee80211softmac ieee80211 ieee1394 snd_ac97_codec sdhci pcspkr ati_agp agpgart
tg3 ieee80211_crypt snd_ac97_bus
CPU:    0
EIP:    0060:[<c0134d2f>]    Not tainted VLI
EFLAGS: 00010046   (2.6.18-rc1-mm2 #1)
EIP is at __lock_acquire+0x4f/0xd60
eax: 0000001c   ebx: 00000000   ecx: 00000000   edx: 00000000
esi: 00000001   edi: c05f0080   ebp: c13f9e3c   esp: c13f9de4
ds: 007b   es: 007b   ss: 0068
Process khubd (pid: 164, ti=c13f8000 task=d7f4e070 task.ti=c13f8000)
Stack: c04d4685 c05d8d00 d7f4e070 00000000 00000000 00000000 c04d27a5 00000000
       00000000 00000000 0000001c d7f4e070 c01345a8 00000000 00000046 c016659d
       d73e86c0 d7ea43ac d7ea4380 00000246 d6dacd18 c05f0080 c13f9e58 c0135d98
Call Trace:
 [<c0103b49>] show_stack_log_lvl+0xa9/0xd0
 [<c0103d98>] show_registers+0x1d8/0x260
 [<c0103f59>] die+0x139/0x340
 [<c0113762>] do_page_fault+0x292/0x5bd
 [<c01035d1>] error_code+0x39/0x40
 [<c0135d98>] lock_acquire+0x68/0x90
 [<c04d4035>] _spin_lock+0x45/0x60
 [<c04d0d69>] klist_remove+0x19/0x40
 [<c03d80f3>] bus_remove_device+0xa3/0xd0
 [<c03d69f0>] device_del+0x140/0x180
 [<c041d25a>] usb_disconnect+0xda/0x130
 [<c041e4f2>] hub_thread+0x3b2/0xfd0
 [<c012e029>] kthread+0xe9/0xf0
 [<c0100865>] kernel_thread_helper+0x5/0x10
Code: 45 d4 0f 84 cd 02 00 00 9c 58 f6 c4 02 0f 85 2a 0b 00 00 83 7d cc 07 0f 87
42 0b 00 00 8b 5d cc 85 db 0f 85 b9 02 00 00 8b 45 d0 <8b> 58 04 85 db 0f 84 ab
02 00 00 ff 83 9c 00 00 00 8b 45 d4 8b
EIP: [<c0134d2f>] __lock_acquire+0x4f/0xd60 SS:ESP 0068:c13f9de4
 <6>note: khubd[164] exited with preempt_count 1

Well, I forgot to apply a patch from hotfixes folder, but after applying it and
recompiling it still doesn't work. The dmesg output still looks the same as in
the one I attached at the start.

Created attachment 8902 [details]
ohci root hub polling patch queued for 2.6.19

Try the attached patch against 2.6.18-rc5 (the patch should already
be in the MM tree) ... if you had problems with the previous patch,
it's likely you were using the wrong base kernel version.  (No, we
don't want to hear about vendor kernels, even gentoo.)

Unless I get confirmation that this bug is still showing  
up in the latest MM patchset, I'll mark this closed during  
the week of 18-Sept-2006 ... if it still appears then, 
then either reproduce it with the current kernel.org code 
(e.g. 2.6.18-rc6 right now) or else bisect the MM patches 
to show which patch there is causing the problem. 
  
FWIW this never looked like anything specific to OHCI. 
Looks most like a mouse/HID driver issue (the -110 errors) 
combined with a should-be-long-fixed driver model related 
problem (the oops). 

The reason I said it appeared to be related to OHCI was because the log shows
(at the end) the disconnection followed by the reconnection and EHCI handing off
to the companion -- but the companion doesn't notice it.

Of course, that's at the very end of the log so maybe the wakeup just wasn't
included in the report.  However it seems more likely that the new connection to
the OHCI controller just got lost.  That would explain why the mouse didn't
start working again.

BTW, all those -110 errors are normal and expected.  hid-core retries a failed
interrupt URB up to ten times (about 1 second total) before resetting the
device.  Maybe that limit should be reduced...

I've just compiled version 2.6.18-rc6-mm1 and it looks like all is fine now. So 
I guess I can mark this bug as fixed now.