On 05/13/2009 10:13 AM, Alan Stern wrote: >>>> Thanks for the feedback. VMware perhaps should have been an obvious >>>> candidate, but I built the device and it's firmware myself so I was >>>> focusing on where problems usually reside... in my own work. >>>> >>>> >>> Pardon me for sounding rude, but in this case that seems ridiculous. >>> The device isn't capable of initiating a port reset; only the host is. >>> So if you're looking for the source of those resets, why concentrate on >>> the device? >>> >>> >> Doesn't seem ridiculous at all. The host can reset a device if it >> detects a problem a transfer (as mentioned in the mass storage case). >> > > Right, which means that you need to determine if the host has detected > a problem. That is different from detecting a problem on the device > side; you need to find out what the host is doing. > Well, I'd argue that is exactly what I've been trying to do. I've been searching the host to see if it detected some problem with the device. Turns out the "problem" is not something the host has detected with the device, however, but with VMware's/Guest OS activity. >> It >> would also seem logical that a host controller might do a reset if >> something was wrong electrically. >> > > No, a host controller will not do a reset unless it is told to do so by > the driver. > Good to know, thanks. > Have you been able to reproduce those resets? Have you tried setting > the usbfs_snoop=y parameter for usbcore? > Yes, I have manage to trigger the resets again. A usbfs_snoop snip is below, its not clear to me how to tell for sure which process is submitting the ioctls. In this case there are only 2 resets, I have seen up to 6 of them during enumeration of a different device. ... May 13 11:47:51 wegos-desktop kernel: [69328.569740] usb 1-1.1.2: new full speed USB device using ehci_hcd and address 57 May 13 11:47:51 wegos-desktop kernel: [69328.681524] usb 1-1.1.2: configuration #1 chosen from 1 choice May 13 11:47:53 wegos-desktop kernel: [69329.932646] usb 1-1.1.2: opened by process 10000: vmware-vmx May 13 11:47:53 wegos-desktop kernel: [69329.932657] usb 1-1.1.2: usbdev_ioctl: CLAIMINTERFACE May 13 11:47:53 wegos-desktop kernel: [69330.075373] usb 1-1.1.2: usbdev_ioctl: RESET May 13 11:47:53 wegos-desktop kernel: [69330.160722] usb 1-1.1.2: reset full speed USB device using ehci_hcd and address 57 May 13 11:47:53 wegos-desktop kernel: [69330.276669] usb 1-1.1.2: usbdev_ioctl: SUBMITURB May 13 11:47:53 wegos-desktop kernel: [69330.276676] usb 1-1.1.2: control urb: bRequest=06 bRrequestType=80 wValue=0100 wIndex=0000 wLength=0040 May 13 11:47:53 wegos-desktop kernel: [69330.276681] usb 1-1.1.2: direction=IN May 13 11:47:53 wegos-desktop kernel: [69330.276684] usb 1-1.1.2: userurb=0a9a67c4 May 13 11:47:53 wegos-desktop kernel: [69330.276685] usb 1-1.1.2: transfer_buffer_length=64 May 13 11:47:53 wegos-desktop kernel: [69330.276687] usb 1-1.1.2: actual_length=0 May 13 11:47:53 wegos-desktop kernel: [69330.276689] usb 1-1.1.2: data: c0 fa 18 f4 00 10 00 00 00 00 00 00 e0 f6 69 c1 00 10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 02 20 00 00 00 00 00 00 00 00 00 00 00 00 00 May 13 11:47:53 wegos-desktop kernel: [69330.277838] usb 1-1.1.2: urb complete May 13 11:47:53 wegos-desktop kernel: [69330.277840] usb 1-1.1.2: direction=IN May 13 11:47:53 wegos-desktop kernel: [69330.277842] usb 1-1.1.2: userurb=0a9a67c4 May 13 11:47:53 wegos-desktop kernel: [69330.277844] usb 1-1.1.2: transfer_buffer_length=64 May 13 11:47:53 wegos-desktop kernel: [69330.277845] usb 1-1.1.2: actual_length=18 May 13 11:47:53 wegos-desktop kernel: [69330.277847] usb 1-1.1.2: data: 12 01 00 02 ff 00 ff 40 25 09 81 90 10 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 May 13 11:47:53 wegos-desktop kernel: [69330.278556] usb 1-1.1.2: usbdev_ioctl: REAPURBDELAY May 13 11:47:53 wegos-desktop kernel: [69330.278564] usb 1-1.1.2: usbdev_ioctl: REAPURBDELAY May 13 11:47:53 wegos-desktop kernel: [69330.283921] usb 1-1.1.2: usbdev_ioctl: RESET May 13 11:47:53 wegos-desktop kernel: [69330.372734] usb 1-1.1.2: reset full speed USB device using ehci_hcd and address 57 May 13 11:47:53 wegos-desktop kernel: [69330.525783] usb 1-1.1.2: usbdev_ioctl: SUBMITURB May 13 11:47:53 wegos-desktop kernel: [69330.525790] usb 1-1.1.2: control urb: bRequest=06 bRrequestType=80 wValue=0100 wIndex=0000 wLength=0012 May 13 11:47:53 wegos-desktop kernel: [69330.525795] usb 1-1.1.2: direction=IN May 13 11:47:53 wegos-desktop kernel: [69330.525797] usb 1-1.1.2: userurb=0a9a67c4 May 13 11:47:53 wegos-desktop kernel: [69330.525799] usb 1-1.1.2: transfer_buffer_length=18 May 13 11:47:53 wegos-desktop kernel: [69330.525801] usb 1-1.1.2: actual_length=0 May 13 11:47:53 wegos-desktop kernel: [69330.525802] usb 1-1.1.2: data: a0 52 00 f4 01 01 00 80 32 09 04 00 00 00 00 00 00 00 May 13 11:47:53 wegos-desktop kernel: [69330.526088] usb 1-1.1.2: urb complete May 13 11:47:53 wegos-desktop kernel: [69330.526090] usb 1-1.1.2: direction=IN May 13 11:47:53 wegos-desktop kernel: [69330.526092] usb 1-1.1.2: userurb=0a9a67c4 May 13 11:47:53 wegos-desktop kernel: [69330.526093] usb 1-1.1.2: transfer_buffer_length=18 May 13 11:47:53 wegos-desktop kernel: [69330.526095] usb 1-1.1.2: actual_length=18 May 13 11:47:53 wegos-desktop kernel: [69330.526096] usb 1-1.1.2: data: 12 01 00 02 ff 00 ff 40 25 09 81 90 10 00 00 00 00 01 May 13 11:47:53 wegos-desktop kernel: [69330.526118] usb 1-1.1.2: usbdev_ioctl: REAPURBDELAY May 13 11:47:53 wegos-desktop kernel: [69330.526126] usb 1-1.1.2: usbdev_ioctl: REAPURBDELAY May 13 11:47:53 wegos-desktop kernel: [69330.528195] usb 1-1.1.2: usbdev_ioctl: SUBMITURB May 13 11:47:53 wegos-desktop kernel: [69330.528200] usb 1-1.1.2: control urb: bRequest=06 bRrequestType=80 wValue=0200 wIndex=0000 wLength=0009 May 13 11:47:53 wegos-desktop kernel: [69330.528205] usb 1-1.1.2: direction=IN May 13 11:47:53 wegos-desktop kernel: [69330.528207] usb 1-1.1.2: userurb=0a9a67c4 May 13 11:47:53 wegos-desktop kernel: [69330.528209] usb 1-1.1.2: transfer_buffer_length=9 May 13 11:47:53 wegos-desktop kernel: [69330.528210] usb 1-1.1.2: actual_length=0 May 13 11:47:53 wegos-desktop kernel: [69330.528212] usb 1-1.1.2: data: d0 f8 ba f5 31 2e 32 3a 31 May 13 11:47:53 wegos-desktop kernel: [69330.528463] usb 1-1.1.2: urb complete May 13 11:47:53 wegos-desktop kernel: [69330.528465] usb 1-1.1.2: direction=IN May 13 11:47:53 wegos-desktop kernel: [69330.528467] usb 1-1.1.2: userurb=0a9a67c4 May 13 11:47:53 wegos-desktop kernel: [69330.528468] usb 1-1.1.2: transfer_buffer_length=9 May 13 11:47:53 wegos-desktop kernel: [69330.528470] usb 1-1.1.2: actual_length=9 May 13 11:47:53 wegos-desktop kernel: [69330.528471] usb 1-1.1.2: data: 09 02 12 00 01 01 00 80 32 May 13 11:47:53 wegos-desktop kernel: [69330.528495] usb 1-1.1.2: usbdev_ioctl: REAPURBDELAY May 13 11:47:53 wegos-desktop kernel: [69330.528502] usb 1-1.1.2: usbdev_ioctl: REAPURBDELAY May 13 11:47:53 wegos-desktop kernel: [69330.532480] usb 1-1.1.2: usbdev_ioctl: SUBMITURB May 13 11:47:53 wegos-desktop kernel: [69330.532485] usb 1-1.1.2: control urb: bRequest=06 bRrequestType=80 wValue=0200 wIndex=0000 wLength=00ff May 13 11:47:53 wegos-desktop kernel: [69330.532490] usb 1-1.1.2: direction=IN May 13 11:47:53 wegos-desktop kernel: [69330.532492] usb 1-1.1.2: userurb=0ad39594 May 13 11:47:53 wegos-desktop kernel: [69330.532494] usb 1-1.1.2: transfer_buffer_length=255 May 13 11:47:53 wegos-desktop kernel: [69330.532496] usb 1-1.1.2: actual_length=0 May 13 11:47:53 wegos-desktop kernel: [69330.532497] usb 1-1.1.2: data: 00 00 00 00 10 00 00 00 13 00 00 00 98 62 61 e2 34 00 00 00 05 00 00 00 c8 ca ba d8 60 00 00 00 06 00 00 00 b4 0c 70 e2 18 00 00 00 01 00 00 00 00 d2 da f5 80 00 00 00 02 00 00 00 1c 0c 70 e2 1c 00 00 00 01 00 00 00 80 25 e2 f5 80 00 00 00 02 00 00 00 00 28 e2 f5 80 00 00 00 02 00 00 00 3c 00 70 e2 1c 00 00 00 01 00 00 00 00 20 18 f6 80 00 00 00 02 00 00 00 80 26 18 f6 80 08 00 00 02 00 00 00 6c 01 70 e2 1c 00 00 00 01 00 00 00 80 e4 32 f2 80 00 00 00 02 00 00 00 bc e9 43 e2 1c 00 00 00 01 00 00 00 00 90 24 f2 80 00 00 00 02 00 00 00 00 94 24 f2 00 0c 00 00 02 00 00 00 9c e2 43 e2 1c 00 00 00 01 00 00 00 00 50 08 f1 00 09 00 00 02 00 00 00 7c 0e 70 e2 18 00 00 00 01 00 00 00 80 f0 13 f6 80 00 00 00 02 00 00 00 80 f0 13 f6 80 00 00 00 02 00 00 00 00 00 00 May 13 11:47:53 wegos-desktop kernel: [69330.532843] usb 1-1.1.2: urb complete May 13 11:47:53 wegos-desktop kernel: [69330.532845] usb 1-1.1.2: direction=IN May 13 11:47:53 wegos-desktop kernel: [69330.532846] usb 1-1.1.2: userurb=0ad39594 May 13 11:47:53 wegos-desktop kernel: [69330.532848] usb 1-1.1.2: transfer_buffer_length=255 May 13 11:47:53 wegos-desktop kernel: [69330.532850] usb 1-1.1.2: actual_length=18 May 13 11:47:53 wegos-desktop kernel: [69330.532851] usb 1-1.1.2: data: 09 02 12 00 01 01 00 80 32 09 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 1c 00 00 00 01 00 00 00 80 25 e2 f5 80 00 00 00 02 00 00 00 00 28 e2 f5 80 00 00 00 02 00 00 00 3c 00 70 e2 1c 00 00 00 01 00 00 00 00 20 18 f6 80 00 00 00 02 00 00 00 80 26 18 f6 80 08 00 00 02 00 00 00 6c 01 70 e2 1c 00 00 00 01 00 00 00 80 e4 32 f2 80 00 00 00 02 00 00 00 bc e9 43 e2 1c 00 00 00 01 00 00 00 00 90 24 f2 80 00 00 00 02 00 00 00 00 94 24 f2 00 0c 00 00 02 00 00 00 9c e2 43 e2 1c 00 00 00 01 00 00 00 00 50 08 f1 00 09 00 00 02 00 00 00 7c 0e 70 e2 18 00 00 00 01 00 00 00 80 f0 13 f6 80 00 00 00 02 00 00 00 80 f0 13 f6 80 00 00 00 02 00 00 00 00 00 00 May 13 11:47:53 wegos-desktop kernel: [69330.532968] usb 1-1.1.2: usbdev_ioctl: REAPURBDELAY If I look at the usbmon output, however, there seem to be more control transfers that aren't in the usbfs_snoop log. Is there a reliable way to correlate the two logs? f112a800 1296803871 S Co:1:000:0 s 00 05 0039 0000 0000 0 f112a800 1296804482 C Co:1:000:0 0 0 f112a600 1296823832 S Ci:1:057:0 s 80 06 0100 0000 0012 18 < f112a600 1296824611 C Ci:1:057:0 0 18 = 12010002 ff00ff40 25098190 10000000 0001 f112a600 1296824644 S Ci:1:057:0 s 80 06 0600 0000 000a 10 < f112a600 1296824732 C Ci:1:057:0 -32 0 f112a600 1296824753 S Ci:1:057:0 s 80 06 0600 0000 000a 10 < f112a600 1296825482 C Ci:1:057:0 -32 0 f112a600 1296825503 S Ci:1:057:0 s 80 06 0600 0000 000a 10 < f112a600 1296826483 C Ci:1:057:0 -32 0 f112a600 1296826509 S Ci:1:057:0 s 80 06 0200 0000 0009 9 < f112a600 1296827608 C Ci:1:057:0 0 9 = 09021200 01010080 32 f112a600 1296827634 S Ci:1:057:0 s 80 06 0200 0000 0012 18 < f112a600 1296827857 C Ci:1:057:0 0 18 = 09021200 01010080 32090400 00000000 0000 f112a600 1296828307 S Co:1:057:0 s 00 09 0001 0000 0000 0 f112a600 1296828488 C Co:1:057:0 0 0 f112a600 1296828910 S Ci:1:005:0 s a3 00 0000 0002 0004 4 < f112a600 1296829486 C Ci:1:005:0 0 4 = 03010000 f33e4e00 1298222173 S Co:1:005:0 s 23 03 0004 0002 0000 0 f33e4e00 1298222232 C Co:1:005:0 0 0 f33e4e00 1298235817 S Ci:1:005:0 s a3 00 0000 0002 0004 4 < f33e4e00 1298236484 C Ci:1:005:0 0 4 = 11010000 f33e4e00 1298250800 S Ci:1:005:0 s a3 00 0000 0002 0004 4 < f33e4e00 1298251485 C Ci:1:005:0 0 4 = 03011000 f6167180 1298294494 C Ii:1:005:1 0:2048 1 = 04 f6167180 1298294500 S Ii:1:005:1 -115:2048 1 < f33e4e00 1298306797 S Co:1:005:0 s 23 01 0014 0002 0000 0 f33e4e00 1298307481 C Co:1:005:0 0 0 f33e4e00 1298307500 S Ci:1:000:0 s 80 06 0100 0000 0040 64 < f33e4e00 1298308609 C Ci:1:000:0 0 18 = 12010002 ff00ff40 25098190 10000000 0001 f33e4e00 1298308622 S Co:1:005:0 s 23 03 0004 0002 0000 0 f33e4e00 1298308733 C Co:1:005:0 0 0 f33e4e00 1298323789 S Ci:1:005:0 s a3 00 0000 0002 0004 4 < f33e4e00 1298323858 C Ci:1:005:0 0 4 = 03011000 f33e4e00 1298378800 S Co:1:005:0 s 23 01 0014 0002 0000 0 f33e4e00 1298379485 C Co:1:005:0 0 0 f33e4e00 1298379505 S Co:1:000:0 s 00 05 0039 0000 0000 0 f33e4e00 1298380483 C Co:1:000:0 0 0 f33e4e00 1298398795 S Ci:1:057:0 s 80 06 0100 0000 0012 18 < f33e4e00 1298399608 C Ci:1:057:0 0 18 = 12010002 ff00ff40 25098190 10000000 0001 f33e4e00 1298399624 S Ci:1:057:0 s 80 06 0200 0000 0012 18 < f33e4e00 1298399858 C Ci:1:057:0 0 18 = 09021200 01010080 32090400 00000000 0000 f33e4e00 1298399870 S Co:1:057:0 s 00 09 0001 0000 0000 0 f33e4e00 1298399983 C Co:1:057:0 0 0 f33e4e00 1298399995 S Co:1:057:0 s 01 0b 0000 0000 0000 0 f33e4e00 1298400108 C Co:1:057:0 -32 0 f33e4e00 1298423491 S Ci:1:057:0 s 80 06 0100 0000 0040 64 < f33e4e00 1298424607 C Ci:1:057:0 0 18 = 12010002 ff00ff40 25098190 10000000 0001 f33e4e00 1298431805 S Co:1:005:0 s 23 03 0004 0002 0000 0 f33e4e00 1298432483 C Co:1:005:0 0 0 f33e4e00 1298446796 S Ci:1:005:0 s a3 00 0000 0002 0004 4 < f33e4e00 1298447483 C Ci:1:005:0 0 4 = 11010000 f33e4e00 1298463790 S Ci:1:005:0 s a3 00 0000 0002 0004 4 < f33e4e00 1298464483 C Ci:1:005:0 0 4 = 03011000 f33e4e00 1298518795 S Co:1:005:0 s 23 01 0014 0002 0000 0 f33e4e00 1298519481 C Co:1:005:0 0 0 f33e4e00 1298519511 S Ci:1:000:0 s 80 06 0100 0000 0040 64 < f33e4e00 1298520609 C Ci:1:000:0 0 18 = 12010002 ff00ff40 25098190 10000000 0001 f33e4e00 1298520628 S Co:1:005:0 s 23 03 0004 0002 0000 0 f33e4e00 1298520733 C Co:1:005:0 0 0 f33e4e00 1298535789 S Ci:1:005:0 s a3 00 0000 0002 0004 4 < f33e4e00 1298535858 C Ci:1:005:0 0 4 = 03011000 f6167180 1298550485 C Ii:1:005:1 0:2048 1 = 04 f6167180 1298550490 S Ii:1:005:1 -115:2048 1 < f33e4e00 1298590796 S Co:1:005:0 s 23 01 0014 0002 0000 0 f33e4e00 1298591481 C Co:1:005:0 0 0 f33e4e00 1298591505 S Co:1:000:0 s 00 05 0039 0000 0000 0 f33e4e00 1298592483 C Co:1:000:0 0 0 f33e4e00 1298610797 S Ci:1:057:0 s 80 06 0100 0000 0012 18 < f33e4e00 1298611608 C Ci:1:057:0 0 18 = 12010002 ff00ff40 25098190 10000000 0001 f33e4e00 1298611630 S Ci:1:057:0 s 80 06 0200 0000 0012 18 < f33e4e00 1298611858 C Ci:1:057:0 0 18 = 09021200 01010080 32090400 00000000 0000 f33e4e00 1298611876 S Co:1:057:0 s 00 09 0001 0000 0000 0 f33e4e00 1298611983 C Co:1:057:0 0 0 f33e4e00 1298611999 S Co:1:057:0 s 01 0b 0000 0000 0000 0 f33e4e00 1298612108 C Co:1:057:0 -32 0 f33e4e00 1298672588 S Ci:1:057:0 s 80 06 0100 0000 0012 18 < f33e4e00 1298672857 C Ci:1:057:0 0 18 = 12010002 ff00ff40 25098190 10000000 0001 f33e4e00 1298674993 S Ci:1:057:0 s 80 06 0200 0000 0009 9 < f33e4e00 1298675232 C Ci:1:057:0 0 9 = 09021200 01010080 32 f33e4e00 1298679372 S Ci:1:057:0 s 80 06 0200 0000 00ff 255 < f33e4e00 1298679611 C Ci:1:057:0 0 18 = 09021200 01010080 32090400 00000000 0000 f33e4e00 1298686399 S Ci:1:057:0 s 80 06 0600 0000 000a 10 < f33e4e00 1298686610 C Ci:1:057:0 -32 0 -Brad -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
