Re: [Libusb-devel] Bus unresponsive subsequent to device disconnect

[Endejan, E. <Edw...@dm...>]

> From: Alan Stern [st...@ro...]
> Sent: Tuesday, June 21, 2011 11:19 AM
> To: Endejan, Edward
> Cc: Alan Ott; lib...@li...
> Subject: Re: [Libusb-devel] Bus unresponsive subsequent to device disconnect
> 
> On Tue, 21 Jun 2011, Endejan, Edward wrote:
> 
> > > Correct me if I'm wrong here, but nothing libusb does (or anything any
> > > user can do from userspace) should mess up the kernel's USB state, and
> > > it sounds like maybe that's what you're getting, since you aren't
> > > receiving hotplug events anymore. Of course it could also be hardware.
> > I agree that nothing libusb does (or anything from userspace) should mess up the kernel's USB state. But that does seem to be at least part of the problem. That is why I've added debug prints to the kernel's USB drivers. Maybe there is a bug there, so I'm trying to determine if it is the way I'm > using libusb that is aggravating it. You know the old joke: "Hey Doc, it hurts when I do this." And then Doc says, "Well, then don't do that."
> 
> You should build your kernel with CONFIG_USB_DEBUG enabled, and post
> the dmesg log showing what happens when you run your test.
> 
> You might also want to collect and post a usbmon trace (see
> Documentation/usb/usbmon.txt).
> 
> > > Are you seeing the same issue on all of your USB controllers?
> > I'm only using one USB controller, so there isn't another one to compare against.
> >
> > >
> > > Are you connected through a hub? If so, maybe your hub is shutting down.
> > The problem occurs whether I'm connected through a hub or not, though doesn't every host controller include a 'root hub', sometimes with more than one port? Does khubd control the 'root hub', or does it only handle hubs other than the 'root hub'?
> 
> khubd is a kernel thread used by the hub driver, which manages all
> hubs (both root hubs and external hubs).
> 
> Alan Stern

Per Alan Stern's suggestions, I reconfigured and rebuilt my kernel with CONFIG_USB_ENABLED=y and used usbmon to trace bus traffic. Below are the results, but they don't offer much more in the way of clues to what is wrong other than when the problem occurs on a disconnect event, subsequent requests are timing out. At least that is what I glean from the results. If anyone thinks they indicate something more specific, please let me know.

Snippet from dmesg showing device connection, 2 successful program runs, and 1 failed program run:

	Jun 22 08:48:19 kernel: usb usb1: uevent
	Jun 22 08:48:19 kernel: usb 1-0:1.0: uevent
	Jun 22 08:48:19 kernel: usb usb2: uevent
	Jun 22 08:48:19 kernel: usb 2-0:1.0: uevent
	Jun 22 08:48:19 kernel: usb 2-1: uevent
	Jun 22 08:48:19 kernel: usb 2-1:1.0: uevent
	Jun 22 08:48:19 kernel: usb 2-1.2: uevent
	Jun 22 08:48:19 kernel: usb 2-1.2:2.0: uevent
	Jun 22 08:48:19 kernel: usb 2-1.2:2.1: uevent
	Jun 22 08:48:19 kernel: usb 2-1.2:2.2: uevent

    (first run of program shows additional step of libusb_detach_kernel_driver)
	Jun 22 08:50:32 kernel: usbhid 2-1.2:2.2: disconnect by usbfs
	Jun 22 08:50:32 kernel: drivers/usb/core/file.c: removing 96 minor
	Jun 22 08:50:32 kernel: usb 2-1.2: link qh0-00ff/cde1a180 start 0 [2/0 us]
	Jun 22 08:50:33 kernel: usb 2-1.2: unlink qh0-00ff/cde1a180 start 0 [2/0 us]

	Jun 22 08:50:34 kernel: usb 2-1.2: link qh0-00ff/cdf18f00 start 0 [2/0 us]
	Jun 22 08:50:34 kernel: usb 2-1.2: unlink qh0-00ff/cdf18f00 start 0 [2/0 us]

	Jun 22 08:50:40 kernel: usb 2-1.2: libusb_openclos timed out on ep0out len=0/0


Console message which appears when program fails (with a timeout):

	libusb:error [op_set_interface] setintf failed error -1 errno 110


Raw log from usbmon:

	# cat /var/log/usbmon.log
	ccc59140 2119303446 S Co:2:003:0 s 01 0b 0000 0002 0000 0
	ccc59140 2119303812 C Co:2:003:0 0 0
	ccc681c0 2119320994 S Ii:2:003:3 -115:1 64 <
	ccc681c0 2119585612 C Ii:2:003:3 -2:1 0
	ccc681c0 2120826548 S Co:2:003:0 s 01 0b 0000 0002 0000 0
	ccc681c0 2120826853 C Co:2:003:0 0 0
	ccc681c0 2120830088 S Ii:2:003:3 -115:1 64 <
	ccc681c0 2121085246 C Ii:2:003:3 -2:1 0
	ccc681c0 2122310313 S Co:2:003:0 s 01 0b 0000 0002 0000 0
	ccc681c0 2127325816 C Co:2:003:0 -2 0

Parsed usbmon log using parse_usbmon.sh (not really helpful - obscures the error):

	bReqType=01 bReq=0b wVal=0000 wIdx=0002 wLen=0
	StdOutInterf Invalid  wLen-0 

	bReqType=01 bReq=0b wVal=0000 wIdx=0002 wLen=0
	StdOutInterf Invalid  wLen-0 

	bReqType=01 bReq=0b wVal=0000 wIdx=0002 wLen=0
	StdOutInterf Invalid  wLen-0 


Thanks Alan, these steps were worth a try, but unfortunately don't seem to have helped other than to confirm what I've seen via other means.

Regards,
Ed