lkml.org 
[lkml]   [2009]   [Jul]   [23]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Subject31-rc3-mmotm0716 - dead USB trackball mouse kills entire system
From
Date
(Throwing at everybody in MAINTAINERS that might know something...)

OK. To start off - I *know* it's a trackball that is on its last legs.
However, (a) it's my favorite mouse design *ever* and (b) it's out of
production, so I'm trying to delay as long as possible replacing it.
Especially when the entire problem is that the USB cord has one broken/loose
conductor, which means that four or five times a day I have to wiggle the cord
a 1/16" to wake it back up, and I get this sort of spewage in my console logs
if running a -mmotm0702 or earlier kernel:

[ 305.300116] usb 1-8.3: USB disconnect, address 6
[ 305.480251] usb 1-8.3: new low speed USB device using ehci_hcd and address 7
[ 305.559595] SELinux: Context staff_u:object_r:gconf_home_t:s0 is not valid (left unmapped).
[ 305.570989] usb 1-8.3: New USB device found, idVendor=045e, idProduct=0023
[ 305.570999] usb 1-8.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[ 305.571043] usb 1-8.3: Product: Microsoft Trackball Optical®
[ 305.571050] usb 1-8.3: Manufacturer: Microsoft
[ 305.571367] usb 1-8.3: configuration #1 chosen from 1 choice
[ 305.580597] input: Microsoft Microsoft Trackball Optical® as /devices/pci0000:00/0000:00:1d.7/usb1/1-8/1-8.3/1-8.3:1.0/input/input9
[ 305.580845] generic-usb 0003:045E:0023.0002: input,hidraw0: USB HID v1.00 Mouse [Microsoft Microsoft Trackball Optical®] on usb-0000:00:1d.7-8.3/input0
[ 308.116101] usb 1-8.3: USB disconnect, address 7
[ 308.291271] usb 1-8.3: new low speed USB device using ehci_hcd and address 8
[ 308.381867] usb 1-8.3: New USB device found, idVendor=045e, idProduct=0023
[ 308.381876] usb 1-8.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[ 308.381883] usb 1-8.3: Product: Microsoft Trackball Optical®
[ 308.381889] usb 1-8.3: Manufacturer: Microsoft
[ 308.382181] usb 1-8.3: configuration #1 chosen from 1 choice
[ 308.389974] input: Microsoft Microsoft Trackball Optical® as /devices/pci0000:00/0000:00:1d.7/usb1/1-8/1-8.3/1-8.3:1.0/input/input10
[ 308.390266] generic-usb 0003:045E:0023.0003: input,hidraw0: USB HID v1.00 Mouse [Microsoft Microsoft Trackball Optical®] on usb-0000:00:1d.7-8.3/input0

Pretty much what you'd *expect* to see if a device keeps dropping in and out...

Well... Usually. Today, on a -mmotm0716 kernel, the loose conductor struck
again, and no amount of wiggling would resurrect it as far as the system was
concerned. Note however that it *did* wake up just fine when I finally
rebooted the machine, even though I had not touched the mouse any further -
which says to me that the wires were making a connection again, but the kernel
wasn't picking up on it.

Meanwhile, in my kernel logs, I had:

[ 571.965568] drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:1d.7-8.3/input0, status -71
[ 571.965661] usb 1-8: clear tt 3 (0060) error -32
[ 571.981570] drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:1d.7-8.3/input0, status -71
[ 571.981668] usb 1-8: clear tt 3 (0060) error -32
[ 571.997698] drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:1d.7-8.3/input0, status -71
[ 571.997782] usb 1-8: clear tt 3 (0060) error -32
[ 572.013568] drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:1d.7-8.3/input0, status -71
[ 572.013656] usb 1-8: clear tt 3 (0060) error -32
[ 572.029694] drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:1d.7-8.3/input0, status -71
[ 572.029783] usb 1-8: clear tt 3 (0060) error -32
[ 572.045696] drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:1d.7-8.3/input0, status -71
[ 572.045781] usb 1-8: clear tt 3 (0060) error -32
[ 572.061567] drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:1d.7-8.3/input0, status -71
[ 572.061655] usb 1-8: clear tt 3 (0060) error -32
[ 572.077698] drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:1d.7-8.3/input0, status -71
[ 572.077782] usb 1-8: clear tt 3 (0060) error -32
[ 572.088910] usb 1-8.3: USB disconnect, address 6
[ 572.267417] usb 1-8.3: new low speed USB device using ehci_hcd and address 7
[ 572.357781] usb 1-8.3: New USB device found, idVendor=045e, idProduct=0023
[ 572.357789] usb 1-8.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[ 572.357796] usb 1-8.3: Product: Microsoft Trackball Optical®
[ 572.357802] usb 1-8.3: Manufacturer: Microsoft
[ 572.358075] usb 1-8.3: configuration #1 chosen from 1 choice
[ 572.365574] input: Microsoft Microsoft Trackball Optical® as /devices/pci0000:00/0000:00:1d.7/usb1/1-8/1-8.3/1-8.3:1.0/input/input9
[ 572.365829] generic-usb 0003:045E:0023.0002: input,hidraw0: USB HID v1.00 Mouse [Microsoft Microsoft Trackball Optical®] on usb-0000:00:1d.7-8.3/input0

The "can't reset device" is apparently new with mm-0716 - I've not seen it
before in at least the 6 weeks my logs go back. And it seems to be the
beginning of things going pear-shaped, even though it manages to reset the
device. A few seconds, the events thread whinges that not all is fine in USB
land:

[ 588.903158] usb 1-8.3: reset low speed USB device using ehci_hcd and address 7
[ 593.903075] ------------[ cut here ]------------
[ 593.903091] WARNING: at drivers/usb/host/ehci-hcd.c:906 ehci_urb_dequeue+0xa9/0x145()
[ 593.903098] Hardware name: Latitude D820
[ 593.903102] Modules linked in: ext4 jbd2 crc16 nvidia(P) [last unloaded: microcode]
[ 593.903127] Pid: 10, comm: events/0 Tainted: P 2.6.31-rc3-mmotm0716 #5
[ 593.903133] Call Trace:
[ 593.903147] [<ffffffff8103f459>] warn_slowpath_common+0x77/0x8f
[ 593.903156] [<ffffffff8103f480>] warn_slowpath_null+0xf/0x11
[ 593.903165] [<ffffffff812d66cb>] ehci_urb_dequeue+0xa9/0x145
[ 593.903176] [<ffffffff812c20f6>] unlink1+0xcd/0xe0
[ 593.903185] [<ffffffff812c2279>] usb_hcd_unlink_urb+0x60/0x84
[ 593.903194] [<ffffffff812c34d0>] usb_kill_urb+0x4f/0xc7
[ 593.903204] [<ffffffff812c4ae4>] usb_start_wait_urb+0x9e/0xde
[ 593.903214] [<ffffffff812c3b1d>] ? usb_init_urb+0x22/0x33
[ 593.903224] [<ffffffff812c4dd1>] usb_control_msg+0x172/0x196
[ 593.903233] [<ffffffff812be39b>] hub_port_init+0x348/0x71e
[ 593.903244] [<ffffffff812be80e>] usb_reset_and_verify_device+0x9d/0x3f0
[ 593.903253] [<ffffffff812c34a0>] ? usb_kill_urb+0x1f/0xc7
[ 593.903263] [<ffffffff81034cb0>] ? get_parent_ip+0x11/0x42
[ 593.903273] [<ffffffff81327812>] ? hid_cease_io+0x36/0x3b
[ 593.903282] [<ffffffff812bebfa>] usb_reset_device+0x99/0x11c
[ 593.903291] [<ffffffff8132808f>] ? hid_reset+0x0/0x128
[ 593.903299] [<ffffffff8132812a>] hid_reset+0x9b/0x128
[ 593.903309] [<ffffffff81051a48>] worker_thread+0x2ba/0x3e9
[ 593.903317] [<ffffffff810519ef>] ? worker_thread+0x261/0x3e9
[ 593.903328] [<ffffffff81056841>] ? autoremove_wake_function+0x0/0x34
[ 593.903337] [<ffffffff8105178e>] ? worker_thread+0x0/0x3e9
[ 593.903346] [<ffffffff81056433>] kthread+0x85/0x8d
[ 593.903357] [<ffffffff8100c41a>] child_rip+0xa/0x20
[ 593.903367] [<ffffffff8100bd80>] ? restore_args+0x0/0x30
[ 593.903377] [<ffffffff810563ae>] ? kthread+0x0/0x8d
[ 593.903385] [<ffffffff8100c410>] ? child_rip+0x0/0x20
[ 593.903391] ---[ end trace 816b51bf46b6656d ]---

And 2 minutes later, things are *still* not fine, and other things
are hanging as well. Since the 'events' thread is hung, both my mouse
and keyboard are dead (though alt-sysrq kept working, since it does its
magic behind 'events' back).

[ 720.548076] INFO: task events/0:10 blocked for more than 120 seconds.
[ 720.548083] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 720.548090] events/0 D 0000000000000000 4640 10 2 0x00000000
[ 720.548104] ffff88007f8d7ae0 0000000000000046 ffff88007f8d7a80 0000000000000046
[ 720.548119] 0000000000000000 ffffffff81056a51 0000000000000000 ffffffff8174c658
[ 720.548133] ffff88007f8d7a70 ffff88007f8d4660 000000000000df88 ffff88007f8d4660
[ 720.548147] Call Trace:
[ 720.548166] [<ffffffff81056a51>] ? prepare_to_wait+0x1c/0x5c
[ 720.548178] [<ffffffff814a2819>] ? _spin_unlock_irqrestore+0x72/0x80
[ 720.548190] [<ffffffff812c352a>] usb_kill_urb+0xa9/0xc7
[ 720.548199] [<ffffffff81056841>] ? autoremove_wake_function+0x0/0x34
[ 720.548209] [<ffffffff812c4ae4>] usb_start_wait_urb+0x9e/0xde
[ 720.548219] [<ffffffff812c3b1d>] ? usb_init_urb+0x22/0x33
[ 720.548229] [<ffffffff812c4dd1>] usb_control_msg+0x172/0x196
[ 720.548239] [<ffffffff812be39b>] hub_port_init+0x348/0x71e
[ 720.548250] [<ffffffff812be80e>] usb_reset_and_verify_device+0x9d/0x3f0
[ 720.548282] [<ffffffff812c34a0>] ? usb_kill_urb+0x1f/0xc7
[ 720.548295] [<ffffffff81034cb0>] ? get_parent_ip+0x11/0x42
[ 720.548308] [<ffffffff81327812>] ? hid_cease_io+0x36/0x3b
[ 720.548317] [<ffffffff812bebfa>] usb_reset_device+0x99/0x11c
[ 720.548326] [<ffffffff8132808f>] ? hid_reset+0x0/0x128
[ 720.548334] [<ffffffff8132812a>] hid_reset+0x9b/0x128
[ 720.548344] [<ffffffff81051a48>] worker_thread+0x2ba/0x3e9
[ 720.548352] [<ffffffff810519ef>] ? worker_thread+0x261/0x3e9
[ 720.548362] [<ffffffff81056841>] ? autoremove_wake_function+0x0/0x34
[ 720.548371] [<ffffffff8105178e>] ? worker_thread+0x0/0x3e9
[ 720.548380] [<ffffffff81056433>] kthread+0x85/0x8d
[ 720.548391] [<ffffffff8100c41a>] child_rip+0xa/0x20
[ 720.548402] [<ffffffff8100bd80>] ? restore_args+0x0/0x30
[ 720.548411] [<ffffffff810563ae>] ? kthread+0x0/0x8d
[ 720.548419] [<ffffffff8100c410>] ? child_rip+0x0/0x20
[ 720.548424] INFO: lockdep is turned off.
[ 720.548455] INFO: task pcscd:2022 blocked for more than 120 seconds.
[ 720.548461] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 720.548466] pcscd D 0000000000000000 5640 2022 1 0x00020080
[ 720.548480] ffff880075287ae8 0000000000000046 0000000000000000 ffff880002139e58
[ 720.548494] 0000000000000003 0000000000000002 ffff880075287fd8 ffff880075286000
[ 720.548508] ffff880075287a78 ffff880073e588e0 000000000000df88 ffff880073e588e0
[ 720.548522] Call Trace:
[ 720.548533] [<ffffffff81065fd6>] ? trace_hardirqs_on_caller+0x1f/0x145
[ 720.548545] [<ffffffff814a0718>] schedule_timeout+0x22/0xc5
[ 720.548555] [<ffffffff81171412>] ? avc_has_perm_noaudit+0x51d/0x546
[ 720.548565] [<ffffffff81065fd6>] ? trace_hardirqs_on_caller+0x1f/0x145
[ 720.548574] [<ffffffff814a2889>] ? _spin_unlock_irq+0x62/0x6f
[ 720.548583] [<ffffffff814a1746>] __down_common+0xa7/0xe9
[ 720.548593] [<ffffffff814a17e7>] __down+0x18/0x1a
[ 720.548601] [<ffffffff8105ab38>] down+0x49/0x5d
[ 720.548611] [<ffffffff812cc5a1>] usbdev_ioctl+0x4e/0x14b0
[ 720.548620] [<ffffffff81171412>] ? avc_has_perm_noaudit+0x51d/0x546
[ 720.548630] [<ffffffff81171492>] ? avc_has_perm+0x57/0x69
[ 720.548638] [<ffffffff814a2c90>] ? unlock_kernel+0x98/0xa5
[ 720.548648] [<ffffffff81172209>] ? inode_has_perm+0x85/0x92
[ 720.548659] [<ffffffff810dd4c2>] vfs_ioctl+0x6a/0x82
[ 720.548668] [<ffffffff810dda01>] do_vfs_ioctl+0x4b0/0x4f6
[ 720.548678] [<ffffffff810dda9e>] sys_ioctl+0x57/0x95
[ 720.548688] [<ffffffff8110a817>] do_ioctl32_pointer+0xb/0xd
[ 720.548697] [<ffffffff8110cd13>] compat_sys_ioctl+0x437/0x4a8
[ 720.548705] [<ffffffff810d8905>] ? path_put+0x1d/0x21
[ 720.548714] [<ffffffff81065374>] ? trace_hardirqs_off_caller+0x1f/0xa2
[ 720.548724] [<ffffffff8107d83f>] ? audit_syscall_entry+0xcb/0x19c
[ 720.548736] [<ffffffff8102b5f8>] sysenter_dispatch+0x7/0x2c
[ 720.548745] [<ffffffff814a1f32>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[ 720.548751] INFO: lockdep is turned off.

From there, things went downhill fast (I tried to ssh in, but *that* got
hung up as well), and I ended up rebooting.

[unhandled content-type:application/pgp-signature]
\
 
 \ /
  Last update: 2009-07-23 18:09    [W:0.089 / U:1.240 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site