On Wed, 13 May 2009, Brad Schick wrote: > > 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. The way to tell is by looking to see what process opened the device file. > ... > 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 This is the open; the program is vmware-vmx and its PID is 10000. > 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 Here you see that VMware did a claiminterface followed by a 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 Then VMware submitted a 64-byte control-IN URB, got an 18-byte reply, and did a second 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 Then there was an 18-byte control-IN URB. > 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 Followed by a 9-byte control-IN URB. > 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 And a 255-byte control-IN URB (18-byte reply). Taken all together these resets and URBs form the start of a perfectly normal device enumeration sequence for a Windows-like guest OS. > 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? Sure. You just have to eliminate everything that didn't originate from VMware or that wasn't directed toward your device. However, telling which URBs didn't originate from VMware isn't easy unless you already know what URBs the kernel sends. > 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 The above shows the Linux kernel enumerating your device. (The first few URBs are missing, but they don't matter.) This was before VMware got involved. > 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 The above shows a reset (the first one issued by VMware) and re-enumeration. Although VMware requested the reset, the URBs you see were all sent by the Linux kernel. > 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 That is the 64-byte control-IN URB sent by VMware, together with its 18-byte reply. > 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 That's another reset (the second reset requested by VMware) and re-enumeration. > 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 Here you see VMware's 18-byte, 9-byte, and 255-byte control-IN transfers (the last of which received only 18 bytes in reply). > f33e4e00 1298686399 S Ci:1:057:0 s 80 06 0600 0000 000a 10 < > f33e4e00 1298686610 C Ci:1:057:0 -32 0 This occurred after the end of your usbfs_snoop extract. It shows the guest OS continuing its enumeration sequence. Alan Stern -- 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
