PORTS Forum
Ports and Interfaces => USB => Topic started by: bpaddock on September 09, 2016, 02:44:36 pm
-
I inherited some USB Device code for a Freescale Kinitis part. The code is unstable and I'm at a loss as to why.
For days it works fine then for days Windows returns 'Code 10 Device will not start'.
This is a HID device with two endpoints, controlling LEDs and reading switches.
A couple of specific questions:
This is a Full Speed device, no Low or High. When Windows requests the DeviceQualifier the proper thing to do is return STALL? Line 127 in the bus capture below.
Once Windows requested a string with an index of 0xEE. Don't believe that would be valid?
In the bus capture below everything goes as I expect it up to SetConfiguraiton, then there are many requests for strings. Is this normal?
Any way to get Windows to give up more information on why the device would not start from the Windows perspective?
Descriptor as reported by TDD:
Information for device Widget (VID=0xDEAD PID=0xBEEF):
Connection Information:
------------------------------
Connection status: Device connected
Device actual bus speed: FullSpeed
Device is hub: No
Device address: 0x0001
Current configuration value: 0x00
Number of open pipes: 0
Device Descriptor:
------------------------------
0x12 bLength
0x01 bDescriptorType
0x0200 bcdUSB
0x00 bDeviceClass
0x00 bDeviceSubClass
0x00 bDeviceProtocol
0x08 bMaxPacketSize0 (8 Bytes)
0xDEAD idVendor
0xBEEF idProduct
0x0004 bcdDevice
0x01 iManufacturer "My Device"
0x02 iProduct "Widget"
0x00 iSerialNumber
0x01 bNumConfigurations
Configuration Descriptor:
------------------------------
0x09 bLength
0x02 bDescriptorType
0x0029 wTotalLength (41 Bytes)
0x01 bNumInterfaces
0x01 bConfigurationValue
0x03 iConfiguration
0xC0 bmAttributes (Self-powered Device)
0x32 bMaxPower (100 mA)
Interface Descriptor:
------------------------------
0x09 bLength
0x04 bDescriptorType
0x00 bInterfaceNumber
0x00 bAlternateSetting
0x02 bNumEndPoints
0x03 bInterfaceClass (Human Interface Device Class)
0x00 bInterfaceSubClass
0x00 bInterfaceProtocol
0x04 iInterface
HID Descriptor:
------------------------------
0x09 bLength
0x21 bDescriptorType
0x0111 bcdHID
0x00 bCountryCode
0x01 bNumDescriptors
0x22 bDescriptorType (Report descriptor)
0x0020 bDescriptorLength
Endpoint Descriptor:
------------------------------
0x07 bLength
0x05 bDescriptorType
0x81 bEndpointAddress (IN Endpoint)
0x03 bmAttributes (Transfer: Interrupt / Synch: None / Usage: Data)
0x0040 wMaxPacketSize (64 Bytes)
0x05 bInterval
Endpoint Descriptor:
------------------------------
0x07 bLength
0x05 bDescriptorType
0x02 bEndpointAddress (OUT Endpoint)
0x03 bmAttributes (Transfer: Interrupt / Synch: None / Usage: Data)
0x0040 wMaxPacketSize (64 Bytes)
0x05 bInterval
Microsoft OS Descriptor is not available. Error code: 0x0000001F
String Descriptor Table
--------------------------------
Index LANGID String
0x00 0x0000 0x0409
0x01 0x0409 "My Device"
0x02 0x0409 "Widget"
0x03 0x0409 Request failed with 0x0000001F
0x04 0x0409 Request failed with 0x0000001F
------------------------------
Connection path for device:
Standard OpenHCD USB Host Controller
Root Hub
Widget (VID=0xDEAD PID=0xBEEF) Port: 1
Running on: Windows 7 with Service Pack 1
Brought to you by TDD v1.84.0, Dec 14 2015, 09:19:38
Bus Capture:
# Total Phase Data Center(tm) v6.72
# (c) 2005-2016 Total Phase, Inc.
# www.totalphase.com
#
#
#
# Level,Sp,Index,m:s.ms.us,Dur,Len,Err,Dev,Ep,Record,Summary
0,,0,0:00.000.000,,,,,,Capture started (Aggregate),[09/09/16 14:26:17]
0,,1,0:00.000.024,,,,,,<Reset> / <Target disconnected>,
0,,2,0:08.305.531,,,,,,<Unreset> / <Target connected>,
0,,3,0:08.413.001,,,,,,<Reset> / <Target disconnected>,
0,,4,0:08.478.875,,,,,,<Unreset> / <Target connected>,
0,,5,0:08.653.191,,,,,,<Reset> / <Target disconnected>,
0,,6,0:08.682.498,,,,,,<Unreset> / <Target connected>,
0,,7,0:08.682.717,25.005.625 ms,,,,,[26 SOF],[Frames: 1898 - 1923]
0,,8,0:08.707.980,62.958 us,8 B,,00,00,Get Device Descriptor,Index=0 Length=64
0,,22,0:08.708.720,2.812 us,,,,,[1 SOF],[Frame: 1924]
0,,23,0:08.708.826,,,,,,<Reset> / <Target disconnected>,
0,,24,0:08.738.509,,,,,,<Unreset> / <Target connected>,
0,,25,0:08.738.724,25.005.541 ms,,,,,[26 SOF],[Frames: 1954 - 1979]
0,,26,0:08.763.933,29.500 us,0 B,,00,00,Set Address,Address=01
0,,35,0:08.764.726,26.005.645 ms,,,,,[27 SOF],[Frames: 1980 - 2006]
0,,36,0:08.790.956,105.562 us,18 B,,01,00,Get Device Descriptor,Index=0 Length=18
0,,58,0:08.791.729,2.916 us,,,,,[1 SOF],[Frame: 2007]
0,,59,0:08.791.853,170.895 us,41 B,,01,00,Get Configuration Descriptor,Index=0 Length=255
0,,93,0:08.792.729,2.812 us,,,,,[1 SOF],[Frame: 2008]
0,,94,0:08.793.052,49.125 us,4 B,,01,00,Get String Descriptor,Index=0 Length=255
0,,107,0:08.793.730,2.916 us,,,,,[1 SOF],[Frame: 2009]
0,,108,0:08.793.853,85.125 us,14 B,,01,00,Get String Descriptor,Index=2 Length=255
0,,126,0:08.794.730,2.916 us,,,,,[1 SOF],[Frame: 2010]
0,,127,0:08.794.853,26.020 us,0 B,,01,00,Control Transfer (STALL),Index=0 Length=10
1,,128,0:08.794.853,13.208 us,8 B,,01,00, SETUP txn,80 06 00 06 00 00 0A 00
2,,129,0:08.794.853,2.812 us,3 B,,01,00, SETUP packet,2D 01 E8
2,,130,0:08.794.856,8.166 us,11 B,,01,00, DATA0 packet,C3 80 06 00 06 00 00 0A 00 5F 34
2,,131,0:08.794.865,1.479 us,1 B,,01,00, ACK packet,D2
1,,132,0:08.794.875,4.770 us,,,01,00, IN txn (STALL),
2,,133,0:08.794.875,2.833 us,3 B,,01,00, IN packet,69 01 E8
2,,134,0:08.794.878,1.479 us,1 B,,01,00, STALL packet,1E
0,,135,0:08.795.730,1.003.020 ms,,,,,[2 SOF],[Frames: 2011 - 2012]
0,,136,0:08.796.771,121.354 us,18 B,,01,00,Get Device Descriptor,Index=0 Length=18
0,,158,0:08.797.730,2.812 us,,,,,[1 SOF],[Frame: 2013]
0,,159,0:08.797.837,84.958 us,9 B,,01,00,Get Configuration Descriptor,Index=0 Length=9
0,,176,0:08.798.730,2.833 us,,,,,[1 SOF],[Frame: 2014]
0,,177,0:08.798.854,163.979 us,41 B,,01,00,Get Configuration Descriptor,Index=0 Length=41
0,,211,0:08.799.730,3.000 us,,,,,[1 SOF],[Frame: 2015]
0,,212,0:08.799.866,29.416 us,0 B,,01,00,Set Configuration,Configuration=1
0,,221,0:08.799.902,1.999.991.604 s,,,01,00,[184143 IN-NAK],[Periodic Timeout]
0,,222,0:08.800.730,1.999.219.562 s,,,,,[2000 SOF],[Frames: 2016 - 1967] [Periodic Timeout]
0,,223,0:10.799.899,1.999.996.250 s,,,01,00,[184134 IN-NAK],[Periodic Timeout]
0,,224,0:10.800.947,1.999.219.541 s,,,,,[2000 SOF],[Frames: 1968 - 1919] [Periodic Timeout]
0,,225,0:12.801.164,1.384.152.812 s,,,,,[1385 SOF],[Frames: 1920 - 1256]
0,,226,0:14.185.474,48.854 us,4 B,,01,00,Get String Descriptor,Index=0 Length=4
0,,240,0:14.186.314,2.833 us,,,,,[1 SOF],[Frame: 1257]
0,,241,0:14.186.418,151.291 us,34 B,,01,00,Get String Descriptor,Index=1 Length=255
0,,270,0:14.187.314,2.833 us,,,,,[1 SOF],[Frame: 1258]
0,,271,0:14.187.447,83.041 us,14 B,,01,00,Get String Descriptor,Index=2 Length=255
0,,289,0:14.188.314,2.833 us,,,,,[1 SOF],[Frame: 1259]
0,,290,0:14.188.453,165.625 us,41 B,,01,00,Get Configuration Descriptor,Index=0 Length=256
0,,324,0:14.189.314,2.812 us,,,,,[1 SOF],[Frame: 1260]
0,,325,0:14.189.438,100.895 us,18 B,,01,00,Get Device Descriptor,Index=0 Length=256
0,,347,0:14.190.314,70.010.416 ms,,,,,[71 SOF],[Frames: 1261 - 1331]
0,,348,0:14.260.547,48.791 us,4 B,,01,00,Get String Descriptor,Index=0 Length=4
0,,361,0:14.261.322,2.833 us,,,,,[1 SOF],[Frame: 1332]
0,,362,0:14.261.428,151.208 us,34 B,,01,00,Get String Descriptor,Index=1 Length=255
0,,391,0:14.262.322,2.833 us,,,,,[1 SOF],[Frame: 1333]
0,,392,0:14.262.394,99.687 us,14 B,,01,00,Get String Descriptor,Index=2 Length=255
0,,410,0:14.263.322,2.812 us,,,,,[1 SOF],[Frame: 1334]
0,,411,0:14.263.446,165.312 us,41 B,,01,00,Get Configuration Descriptor,Index=0 Length=256
0,,445,0:14.264.322,2.833 us,,,,,[1 SOF],[Frame: 1335]
0,,446,0:14.264.424,107.312 us,18 B,,01,00,Get Device Descriptor,Index=0 Length=256
0,,467,0:14.265.322,55.008.791 ms,,,,,[56 SOF],[Frames: 1336 - 1391]
0,,468,0:14.321.171,48.791 us,4 B,,01,00,Get String Descriptor,Index=0 Length=4
0,,481,0:14.321.328,2.833 us,,,,,[1 SOF],[Frame: 1392]
0,,482,0:14.321.453,144.145 us,34 B,,01,00,Get String Descriptor,Index=1 Length=255
0,,512,0:14.322.329,2.812 us,,,,,[1 SOF],[Frame: 1393]
0,,513,0:14.322.435,89.375 us,14 B,,01,00,Get String Descriptor,Index=2 Length=255
0,,530,0:14.323.329,2.833 us,,,,,[1 SOF],[Frame: 1394]
0,,531,0:14.323.431,171.729 us,41 B,,01,00,Get Configuration Descriptor,Index=0 Length=256
0,,564,0:14.324.329,2.833 us,,,,,[1 SOF],[Frame: 1395]
0,,565,0:14.324.453,101.125 us,18 B,,01,00,Get Device Descriptor,Index=0 Length=256
0,,587,0:14.325.329,70.010.416 ms,,,,,[71 SOF],[Frames: 1396 - 1466]
0,,588,0:14.395.906,48.625 us,4 B,,01,00,Get String Descriptor,Index=0 Length=4
0,,601,0:14.396.337,2.833 us,,,,,[1 SOF],[Frame: 1467]
0,,602,0:14.396.461,144.541 us,34 B,,01,00,Get String Descriptor,Index=1 Length=255
0,,632,0:14.397.337,2.812 us,,,,,[1 SOF],[Frame: 1468]
0,,633,0:14.397.440,89.208 us,14 B,,01,00,Get String Descriptor,Index=2 Length=255
0,,650,0:14.398.337,2.833 us,,,,,[1 SOF],[Frame: 1469]
0,,651,0:14.398.498,172.291 us,41 B,,01,00,Get Configuration Descriptor,Index=0 Length=256
0,,685,0:14.399.337,2.833 us,,,,,[1 SOF],[Frame: 1470]
0,,686,0:14.399.461,101.375 us,18 B,,01,00,Get Device Descriptor,Index=0 Length=256
0,,708,0:14.400.337,1.999.219.479 s,,,,,[2000 SOF],[Frames: 1471 - 1422] [Periodic Timeout]
0,,709,0:16.400.554,1.999.219.479 s,,,,,[2000 SOF],[Frames: 1423 - 1374] [Periodic Timeout]
0,,710,0:18.400.771,1.999.219.479 s,,,,,[2000 SOF],[Frames: 1375 - 1326] [Periodic Timeout]
0,,711,0:20.400.987,1.999.219.541 s,,,,,[2000 SOF],[Frames: 1327 - 1278] [Periodic Timeout]
0,,712,0:22.401.204,1.999.219.479 s,,,,,[2000 SOF],[Frames: 1279 - 1230] [Periodic Timeout]
0,,713,0:24.401.421,1.999.219.500 s,,,,,[2000 SOF],[Frames: 1231 - 1182] [Periodic Timeout]
0,,714,0:26.401.638,1.999.219.458 s,,,,,[2000 SOF],[Frames: 1183 - 1134] [Periodic Timeout]
0,,715,0:28.401.854,1.999.219.458 s,,,,,[2000 SOF],[Frames: 1135 - 1086] [Periodic Timeout]
0,,716,0:30.402.071,1.999.219.479 s,,,,,[2000 SOF],[Frames: 1087 - 1038] [Periodic Timeout]
0,,717,0:32.402.288,1.999.219.458 s,,,,,[2000 SOF],[Frames: 1039 - 990] [Periodic Timeout]
0,,718,0:34.402.505,1.999.219.458 s,,,,,[2000 SOF],[Frames: 991 - 942] [Periodic Timeout]
0,,719,0:36.402.721,1.999.219.541 s,,,,,[2000 SOF],[Frames: 943 - 894] [Periodic Timeout]
0,,720,0:38.402.938,1.999.219.458 s,,,,,[2000 SOF],[Frames: 895 - 846] [Periodic Timeout]
0,,721,0:40.403.155,1.999.219.458 s,,,,,[2000 SOF],[Frames: 847 - 798] [Periodic Timeout]
0,,722,0:42.403.371,1.999.219.458 s,,,,,[2000 SOF],[Frames: 799 - 750] [Periodic Timeout]
0,,723,0:44.403.588,1.999.219.458 s,,,,,[2000 SOF],[Frames: 751 - 702] [Periodic Timeout]
0,,724,0:46.403.805,1.999.219.458 s,,,,,[2000 SOF],[Frames: 703 - 654] [Periodic Timeout]
0,,725,0:48.404.022,1.999.219.437 s,,,,,[2000 SOF],[Frames: 655 - 606] [Periodic Timeout]
0,,726,0:50.404.238,1.999.219.437 s,,,,,[2000 SOF],[Frames: 607 - 558] [Periodic Timeout]
0,,727,0:52.404.455,1.999.219.500 s,,,,,[2000 SOF],[Frames: 559 - 510] [Periodic Timeout]
0,,728,0:54.404.672,1.999.219.395 s,,,,,[2000 SOF],[Frames: 511 - 462] [Periodic Timeout]
0,,729,0:56.404.888,946.105.312 ms,,,,,[947 SOF],[Frames: 463 - 1409]
0,,730,0:57.350.991,,,,,,Capture stopped,[09/09/16 14:27:15]
-
Did at least figure out the 0xEE string request problem, that is coming from running the Descriptor Dumper program.
For reasons unknown it requests strings 0, 1, 2, 0xEE, 3, 4.
0 = Language
1 = Manufacture
2 = Product
3 = Serial Number
4 = ?
0xEE = ??
-
Yes, the device should return stall in response to any unsupported descriptor, including string descriptor 0xee.
Here is information about that descriptor:
https://msdn.microsoft.com/en-us/library/windows/hardware/ff537430(v=vs.85).aspx
The host is requesting string descriptors 0, 1, and 2 because the device descriptor says they exist. The device should stall any requests for unsupported descriptors.
If the repeated requests occur only when enumeration fails, there is likely something in the descriptors that Windows doesn't like. Otherwise, I wouldn't worry about them.
The setupapi log file can be helpful in diagnosing why a device doesn't enumerate:
http://sourcedaddy.com/windows-7/using-setupapi-log-file.html
If the error occurs while the device is operating, it would be helpful if you could catch the error with the analyzer. One possible reason for device failure while operating is not returning ACK, NAK, or data in response to a token packet in a transaction.
-
I uninstalled the device via Device Manager, deleted the SetupAPI.xxx.logs then connected the device:
This is what is now in the setupapi.dev.log, in part:
dvi: Install Device: Restarting device. 15:51:46.807
dvi: Install Device: Restarting device completed. 15:51:52.132
!!! dvi: Device not started: Device has problem: 0x0a: CM_PROB_FAILED_START.
!!! is telling me, in hex, "Code 10 failed to start". Already knew that. :-(
The line above it is that indicating a USB Bus Reset to the device and the device did not correctly restart?
I'll look at raising the log verbosity level as the article you linked to discussed.
Larger spew:
...
dvi: Class GUID of device changed to: {745a17a0-74d3-11d0-b6fe-00a0c90f57da}.
dvi: Set selected driver complete.
ndv: Driver selected, now performing install...
ndv: {Core Device Install} 15:51:45.626
inf: Opened PNF: 'C:\Windows\INF\input.inf' ([strings.0409])
! pol: Selected driver node does not match this device (force-install)
inf: Opened PNF: 'C:\Windows\INF\input.inf' ([strings.0409])
dvi: {DIF_ALLOW_INSTALL} 15:51:45.667
dvi: No class installer for 'USB Input Device'
dvi: No CoInstallers found
dvi: Default installer: Enter 15:51:45.681
dvi: Default installer: Exit
dvi: {DIF_ALLOW_INSTALL - exit(0xe000020e)} 15:51:45.691
...
ndv: Installing device...
dvi: {DIF_INSTALLDEVICE} 15:51:46.498
dvi: No class installer for 'USB Input Device'
dvi: Default installer: Enter 15:51:46.509
dvi: {Install DEVICE}
inf: Opened PNF: 'c:\windows\system32\driverstore\filerepository\input.inf_amd64_neutral_fccb715ac7d8c66d\input.inf' ([strings.0409])
dvi: Processing Registry/Property directives...
inf: {Install Inf Section [HID_Inst.NT]}
inf: {Install Inf Section [HID_Inst.NT] exit (0x00000000)}
inf: {Install Inf Section [HID_Inst.NT.Hw]}
inf: DelReg=HID_Inst.DelReg.NT.HW (input.inf line 492)
inf: {Install Inf Section [HID_Inst.NT.Hw] exit (0x00000000)}
dvi: {Writing Device Properties}
dvi: Provider name=Microsoft
dvi: DriverDate 06/21/2006
dvi: DriverVersion=6.1.7601.18199
dvi: Class name=HIDClass
dvi: Manufacturer=(Standard system devices)
dvi: Matching DeviceID=generic_hid_device
dvi: Strong Name=input.inf:Standard.NTamd64:HID_Inst:6.1.7601.18199::generic_hid_device:usb\class_03&subclass_01:usb\class_03
dvi: Additional Software Requested
dvi: {Writing Device Properties - Complete}
inf: {Install Inf Section [HID_Inst.NT.Services]}
inf: AddService=HidUsb,0x00000002,HID_Service_Inst (input.inf line 504)
inf: ServiceType=1 (input.inf line 520)
inf: StartType=3 (input.inf line 521)
inf: ErrorControl=0 (input.inf line 522)
inf: ServiceBinary=C:\Windows\system32\DRIVERS\hidusb.sys (input.inf line 523)
inf: DisplayName="Microsoft HID Class Driver" (input.inf line 519)
inf: LoadOrderGroup="extended base" (input.inf line 524)
dvi: Add Service: Modified existing service 'HidUsb'.
inf: {Install Inf Section [HID_Inst.NT.Services] exit(0x00000000)}
dvi: Updated reflected section names for: input.inf
dvi: {Install DEVICE exit (0x00000000)}
dvi: Writing common driver property settings.
dvi: DriverDescription=USB Input Device
dvi: DeviceDisplayName=USB Input Device
dvi: Install Device: Restarting device. 15:51:46.807
dvi: Install Device: Restarting device completed. 15:51:52.132
!!! dvi: Device not started: Device has problem: 0x0a: CM_PROB_FAILED_START.
dvi: Default installer: Exit
-
The unused strings are being stalled.
-
The setup api log file tells you that Windows correctly selected the input.inf INF file and assigned the HID-class driver to the device.
An ACKed Set Configuration request indicates that the driver was assigned and enumeration completed.
Then the host will send periodic IN token packets to the interrupt IN endpoint, which the endpoint can respond to with data or NAK.
The analyzer should not show transactions with no response at all from the endpoint.
I'm not sure what "Periodic Timeout" here means, I would take a look at the analyzer log and make sure the interrupt endpoint is NAKing all token packets:
0,,212,0:08.799.866,29.416 us,0 B,,01,00,Set Configuration,Configuration=1
0,,221,0:08.799.902,1.999.991.604 s,,,01,00,[184143 IN-NAK],[Periodic Timeout]
A few missed NAKs will cause the host to reset the device.
-
Thank you.
I got the driver to install with no Code 10, still see lots of NAKs and a timeout during the install, trying to track that problem down now.
Looks like this code also has issues with Data Toggles.
-
Sounds like progress. Endless NAKs on the interrupt endpoint are no problem. Control transfers, such as during enumeration, need to complete within 5 secs so NAKing is somewhat limited.
Thanks for the suggestions on the other recent question here.
-
"Control transfers, such as during enumeration, need to complete within 5 secs so NAKing is somewhat limited"
Looks like right on the edge of failing.
The analyzer flags line 153 as having a 250 ms timeout error.
183,939 NAKs during enumeration seems excessive to me?
What exactly is the Control Transfer at the completion of enumeration doing?
0,,143,0:07.675.530,46.166 us,0 B,,01,00,Set Configuration,Configuration=1
0,,152,0:07.676.441,2.833 us,,,,,[1 SOF],[Frame: 1091]
0,,153,0:07.676.544,13.187 us,8 B,T,01,00,SETUP txn,21 0A 00 00 00 00 00 00
0,,157,0:07.676.582,1.999.999.791 s,,,01,00,[183939 IN-NAK],[Periodic Timeout]
0,,158,0:07.677.441,1.999.220.104 s,,,,,[2000 SOF],[Frames: 1092 - 1043] [Periodic Timeout]
0,,159,0:09.676.587,1.999.992.291 s,,,01,00,[183859 IN-NAK],[Periodic Timeout]
0,,160,0:09.677.659,1.999.220.083 s,,,,,[2000 SOF],[Frames: 1044 - 995] [Periodic Timeout]
0,,161,0:11.677.876,999.111.395 ms,,,,,[1000 SOF],[Frames: 996 - 1995]
0,,162,0:12.677.078,83.437 us,32 B,,01,00,Control Transfer,06 00 FF 09 01 A1 01 09 02 15 00 25 FF 75 08 95 40 81 02 09 03 15 00 25…
0,,176,0:12.677.985,1.999.220.083 s,,,,,[2000 SOF],[Frames: 1996 - 1947] [Periodic Timeout]
0,,177,0:12.682.102,1.996.221.625 s,,,01,01,[500 IN-NAK],[Periodic Timeout]...
-
For the Set Configuration request, in the Setup stage, the host sends the request with the low value of wValue specifying the configuration number to use (1).
The device must return ACK unless the device detects an error (not likely); NAKs are not allowed in the Setup stage.
If the device is failing to ACK the Setup stage, the host controller will not be happy.
There is no Data stage.
In the Status stage, the host sends an IN token packet, the device returns:
a 0-length data packet and the host responds with ACK to complete the transfer
or
NAK to tell the host the device isn't ready to complete the transfer
or
STALL to indicate that the device doesn't support the request.