INFO: task khubd:271 blocked for more than 120 seconds.

INFO: task khubd:271 blocked for more than 120 seconds.

[roma1390]

Hello,


We got this on our production system. Kernel: 2.6.26-2-amd64.
This seems to be related with http://bugzilla.kernel.org/show_bug.cgi?id=13316 and still is open. Sadly to have such long standing bugs in common used subsystems like USB.

Jun 15 06:25:01 accelerator57 kernel: imklog 3.18.6, log source = /proc/kmsg started.
Jun 16 00:36:55 accelerator57 kernel: [600606.885265] usb 6-1: USB disconnect, address 3
Jun 16 00:39:02 accelerator57 kernel: [600738.152638] INFO: task khubd:271 blocked for more than 120 seconds.
Jun 16 00:39:02 accelerator57 kernel: [600738.152682] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jun 16 00:39:02 accelerator57 kernel: [600738.155993] khubd         D ffff810916ca1400     0   271      2
Jun 16 00:39:02 accelerator57 kernel: [600738.156038]  ffff810919523d50 0000000000000046 363030365b3e363c 36323538382e3630
Jun 16 00:39:02 accelerator57 kernel: [600738.156118]  ffff810919521470 ffff810916dad220 ffff8109195216f8 00000000a00745a2
Jun 16 00:39:02 accelerator57 kernel: [600738.156197]  ffff810919523da4 ffff810916ca1600 0000000000000286 ffff8109148851c0
Jun 16 00:39:02 accelerator57 kernel: [600738.156245] Call Trace:
Jun 16 00:39:02 accelerator57 kernel: [600738.156308]  [<ffffffff8039035a>] usb_kill_urb+0xa8/0xdb
Jun 16 00:39:02 accelerator57 kernel: [600738.156612]  [<ffffffff80246111>] autoremove_wake_function+0x0/0x2e
Jun 16 00:39:02 accelerator57 kernel: [600738.156660]  [<ffffffff8038fa32>] usb_hcd_flush_endpoint+0xd4/0xeb
Jun 16 00:39:02 accelerator57 kernel: [600738.156707]  [<ffffffff80390a8e>] usb_disable_endpoint+0x5b/0x6d
Jun 16 00:39:02 accelerator57 kernel: [600738.156752]  [<ffffffff80390ac5>] usb_disable_device+0x25/0xe8
Jun 16 00:39:02 accelerator57 kernel: [600738.156792]  [<ffffffff8038c9cd>] usb_disconnect+0x92/0x142
Jun 16 00:39:02 accelerator57 kernel: [600738.156830]  [<ffffffff8038dc07>] hub_thread+0x3f9/0xcfd
Jun 16 00:39:02 accelerator57 kernel: [600738.156868]  [<ffffffff80246111>] autoremove_wake_function+0x0/0x2e
Jun 16 00:39:02 accelerator57 kernel: [600738.156910]  [<ffffffff8038d80e>] hub_thread+0x0/0xcfd
Jun 16 00:39:02 accelerator57 kernel: [600738.156952]  [<ffffffff80245feb>] kthread+0x47/0x74
Jun 16 00:39:02 accelerator57 kernel: [600738.156993]  [<ffffffff8023008d>] schedule_tail+0x27/0x5c
Jun 16 00:39:02 accelerator57 kernel: [600738.157036]  [<ffffffff8020cf38>] child_rip+0xa/0x12
Jun 16 00:39:02 accelerator57 kernel: [600738.157077]  [<ffffffff80245fa4>] kthread+0x0/0x74
Jun 16 00:39:02 accelerator57 kernel: [600738.157116]  [<ffffffff8020cf2e>] child_rip+0x0/0x12
Jun 16 00:39:02 accelerator57 kernel: [600738.157154]

Re: INFO: task khubd:271 blocked for more than 120 seconds.

[Oliver Neukum]

Am Mittwoch, 16. Juni 2010 10:03:42 schrieb roma1390:
> Hello,
> 
> 
> We got this on our production system. Kernel: 2.6.26-2-amd64.
> This seems to be related with http://bugzilla.kernel.org/show_bug.cgi?id=13316 and still is open. Sadly to have such long standing bugs in common used subsystems like USB.
> 
> Jun 15 06:25:01 accelerator57 kernel: imklog 3.18.6, log source = /proc/kmsg started.
> Jun 16 00:36:55 accelerator57 kernel: [600606.885265] usb 6-1: USB disconnect, address 3
> Jun 16 00:39:02 accelerator57 kernel: [600738.152638] INFO: task khubd:271 blocked for more than 120 seconds.
> Jun 16 00:39:02 accelerator57 kernel: [600738.152682] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Jun 16 00:39:02 accelerator57 kernel: [600738.155993] khubd         D ffff810916ca1400     0   271      2
> Jun 16 00:39:02 accelerator57 kernel: [600738.156038]  ffff810919523d50 0000000000000046 363030365b3e363c 36323538382e3630
> Jun 16 00:39:02 accelerator57 kernel: [600738.156118]  ffff810919521470 ffff810916dad220 ffff8109195216f8 00000000a00745a2
> Jun 16 00:39:02 accelerator57 kernel: [600738.156197]  ffff810919523da4 ffff810916ca1600 0000000000000286 ffff8109148851c0
> Jun 16 00:39:02 accelerator57 kernel: [600738.156245] Call Trace:
> Jun 16 00:39:02 accelerator57 kernel: [600738.156308]  [<ffffffff8039035a>] usb_kill_urb+0xa8/0xdb
> Jun 16 00:39:02 accelerator57 kernel: [600738.156612]  [<ffffffff80246111>] autoremove_wake_function+0x0/0x2e
> Jun 16 00:39:02 accelerator57 kernel: [600738.156660]  [<ffffffff8038fa32>] usb_hcd_flush_endpoint+0xd4/0xeb
> Jun 16 00:39:02 accelerator57 kernel: [600738.156707]  [<ffffffff80390a8e>] usb_disable_endpoint+0x5b/0x6d
> Jun 16 00:39:02 accelerator57 kernel: [600738.156752]  [<ffffffff80390ac5>] usb_disable_device+0x25/0xe8
> Jun 16 00:39:02 accelerator57 kernel: [600738.156792]  [<ffffffff8038c9cd>] usb_disconnect+0x92/0x142
> Jun 16 00:39:02 accelerator57 kernel: [600738.156830]  [<ffffffff8038dc07>] hub_thread+0x3f9/0xcfd
> Jun 16 00:39:02 accelerator57 kernel: [600738.156868]  [<ffffffff80246111>] autoremove_wake_function+0x0/0x2e
> Jun 16 00:39:02 accelerator57 kernel: [600738.156910]  [<ffffffff8038d80e>] hub_thread+0x0/0xcfd
> Jun 16 00:39:02 accelerator57 kernel: [600738.156952]  [<ffffffff80245feb>] kthread+0x47/0x74
> Jun 16 00:39:02 accelerator57 kernel: [600738.156993]  [<ffffffff8023008d>] schedule_tail+0x27/0x5c
> Jun 16 00:39:02 accelerator57 kernel: [600738.157036]  [<ffffffff8020cf38>] child_rip+0xa/0x12
> Jun 16 00:39:02 accelerator57 kernel: [600738.157077]  [<ffffffff80245fa4>] kthread+0x0/0x74
> Jun 16 00:39:02 accelerator57 kernel: [600738.157116]  [<ffffffff8020cf2e>] child_rip+0x0/0x12
> Jun 16 00:39:02 accelerator57 kernel: [600738.157154]

Under which conditions did you get this? Physical unplug, S3 or S4?

	Regards
		Oliver

Re: INFO: task khubd:271 blocked for more than 120 seconds.

[roma1390]

Hello,

Oliver Neukum wrote:
> Am Mittwoch, 16. Juni 2010 10:03:42 schrieb roma1390:
>> Hello,
>>
>>
>> We got this on our production system. Kernel: 2.6.26-2-amd64.
>> This seems to be related with http://bugzilla.kernel.org/show_bug.cgi?id=13316 and still is open. Sadly to have such long standing bugs in common used subsystems like USB.
>>
> 
> Under which conditions did you get this? Physical unplug, S3 or S4?
> 
> 	Regards
> 		Oliver

this was normal operation (no unplug, no S3 or something like that). This is on-line
server. There is posible issue with usb device itself or physical usb port. Which
sometimes causes device disconections, reconnections.

Of course it's posible to fix on hardware level, but OS can't do such nasty things also.

Re: INFO: task khubd:271 blocked for more than 120 seconds.

[Oliver Neukum]

Am Mittwoch, 16. Juni 2010 10:27:22 schrieb roma1390:
> Hello,
> 
> Oliver Neukum wrote:
> > Am Mittwoch, 16. Juni 2010 10:03:42 schrieb roma1390:
> >> Hello,
> >>
> >>
> >> We got this on our production system. Kernel: 2.6.26-2-amd64.
> >> This seems to be related with http://bugzilla.kernel.org/show_bug.cgi?id=13316 and still is open. Sadly to have such long standing bugs in common used subsystems like USB.
> >>
> > 
> > Under which conditions did you get this? Physical unplug, S3 or S4?
> > 
> > 	Regards
> > 		Oliver
> 
> this was normal operation (no unplug, no S3 or something like that). This is on-line
> server. There is posible issue with usb device itself or physical usb port. Which
> sometimes causes device disconections, reconnections.
> 
> Of course it's posible to fix on hardware level, but OS can't do such nasty things also.

Yes, this is a kernel bug. It would be helpful to have a bit more of context.
Could you post a bit more of your dmesg before the oops?

	Regards
		Oliver

Re: INFO: task khubd:271 blocked for more than 120 seconds.

[roma1390]

Oliver Neukum wrote:
>> Jun 12 17:01:09  kernel: [257610.508638] Uhhuh. NMI received for unknown reason b1.
>> Jun 12 17:01:09  kernel: [257610.508668] You have some hardware problem, likely on the PCI bus.
>> Jun 12 17:01:09  kernel: [257610.508696] Dazed and confused, but trying to continue
> 
> This should definitely not happen. And it now I wonder how functional your
> controller is at that point.

all worked fine until 'Jun 16 00:36:55'. Usb device was used over libusb periodicaly (1-5 minutes) all that time.

>> Jun 12 23:30:30  kernel: [287011.166413] usb 6-1: USB disconnect, address 2
> 
> Still after all this time, this is probably genuine.

I think this was normal usb device plug/unplug.

>> Jun 12 23:30:51  kernel: [287035.906789] usb 6-1: new full speed USB device using uhci_hcd and address 3
>> Jun 12 23:30:51  kernel: [287036.065433] usb 6-1: configuration #1 chosen from 1 choice
>> Jun 12 23:30:51  kernel: [287036.093490] input: HP Virtual Keyboard as /class/input/input7
>> Jun 12 23:30:51  kernel: [287036.168130] input,hidraw0: USB HID v1.01 Keyboard [HP Virtual Keyboard] on usb-0000:01:04.4-1
>> Jun 12 23:30:51  kernel: [287036.175959] input: HP Virtual Keyboard as /class/input/input8
>> Jun 12 23:30:51  kernel: [287036.216150] input,hidraw1: USB HID v1.01 Mouse [HP Virtual Keyboard] on usb-0000:01:04.4-1
>> Jun 12 23:30:51  kernel: [287036.220005] usb 6-1: New USB device found, idVendor=03f0, idProduct=1027
>> Jun 12 23:30:51  kernel: [287036.220005] usb 6-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
>> Jun 12 23:30:51  kernel: [287036.220005] usb 6-1: Product: Virtual Keyboard
>> Jun 12 23:30:51  kernel: [287036.220005] usb 6-1: Manufacturer: HP
>> Jun 13 06:25:02  kernel: imklog 3.18.6, log source = /proc/kmsg started.
>> Jun 13 06:25:03  kernel: imklog 3.18.6, log source = /proc/kmsg started.
>> Jun 14 06:25:01  kernel: imklog 3.18.6, log source = /proc/kmsg started.
>> Jun 15 06:25:01  kernel: imklog 3.18.6, log source = /proc/kmsg started.
>> Jun 16 00:36:55  kernel: [600606.885265] usb 6-1: USB disconnect, address 3
> 
> And this. Looks like a bad cable.

I think this is of usb device failure, but the bigest problem is that blocked hang. There isn't any cable except wiretraces on motherboard :D.
That device is like: http://www.aradasystems.com/Upload/ProductImages/128835373116845000image_usb_dongle.jpg and connected dirrectly to
the usb port, which is inside server case.

>> Jun 16 00:39:02  kernel: [600738.152638] INFO: task khubd:271 blocked for more than 120 seconds.
>> Jun 16 00:39:02  kernel: [600738.152682] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> Jun 16 00:39:02  kernel: [600738.155993] khubd         D ffff810916ca1400     0   271      2
>> Jun 16 00:39:02  kernel: [600738.156038]  ffff810919523d50 0000000000000046 363030365b3e363c 36323538382e3630
> 
> Alan, didn't you recently fix an issue like this?
> 
> 	Regards
> 		Oliver