Failing WHQL USB Control Request Test with Stall on Get String Descriptor

[johnwhoffman]

We are using a Microchip  PIC and their USB Framework code to implement our CDC device. Durinng WHQL testing we fail the 'USB Control Request Test" on a Get String Descriptor test. During this test suite that string descriptor is retrieved many times without error. The failure always occurs in a particular point of the test suite. I have included the test log sequence at the bottom which starts with a port reset. The USB Analyzer shows this sequence:

Anyone have any thoughts as to why we fail under these conditions and not others?

2774,2:35.707.849.683,19.506.816 ms,,,,,0,Bus event,<Reset> / <Chirp J> / <Tiny J>
2775,2:35.727.356.500,,,,,,0,Bus event,<Full-speed>
2776,2:35.727.541.450,449.018.850 ms,,,,,0,[450 SOF],[Frames: 315 - 764]
2777,2:36.114.933.033,62.044.500 ms,0,,00,00,0,Set Address,Address=06
2778,2:36.114.933.033,12.666 us,8,,00,00,1,   SETUP txn,00 05 06 00 00 00 00 00
2779,2:36.114.933.033,2.083 us,3,,00,00,2,      SETUP packet,2D 00 10
2780,2:36.114.936.283,7.416 us,11,,00,00,2,      DATA0 packet,C3 00 05 06 00 00 00 00 00 EA 92
2781,2:36.114.944.950,750 ns,1,,00,00,2,      ACK packet,D2
2782,2:36.176.969.866,7.666 us,0,,00,00,1,   IN txn,
2783,2:36.176.969.866,2.083 us,3,,00,00,2,      IN packet,69 00 10
2784,2:36.176.973.200,2.083 us,3,,00,00,2,      DATA1 packet,4B 00 00
2785,2:36.176.976.783,750 ns,1,,00,00,2,      ACK packet,D2
2786,2:36.177.558.116,186.009.083 ms,,,,,0,[187 SOF],[Frames: 765 - 951]
2787,2:36.240.256.866,123.591.333 ms,4,,06,00,0,Get String Descriptor,Index=0 Length=255
2788,2:36.240.256.866,12.750 us,8,,06,00,1,   SETUP txn,80 06 00 03 00 00 FF 00
2789,2:36.240.256.866,2.083 us,3,,06,00,2,      SETUP packet,2D 06 90
2790,2:36.240.260.116,7.516 us,11,,06,00,2,      DATA0 packet,C3 80 06 00 03 00 00 FF 00 D4 64
2791,2:36.240.268.866,750 ns,1,,06,00,2,      ACK packet,D2
2792,2:36.301.338.283,10.333 us,4,,06,00,1,   IN txn,04 03 09 04
2793,2:36.301.338.283,2.083 us,3,,06,00,2,      IN packet,69 06 90
2794,2:36.301.341.616,4.750 us,7,,06,00,2,      DATA1 packet,4B 04 03 09 04 09 78
2795,2:36.301.347.866,750 ns,1,,06,00,2,      ACK packet,D2
2796,2:36.363.840.950,7.250 us,0,,06,00,1,   OUT txn,
2797,2:36.363.840.950,2.083 us,3,,06,00,2,      OUT packet,E1 06 90
2798,2:36.363.844.116,2.083 us,3,,06,00,2,      DATA1 packet,4B 00 00
2799,2:36.363.847.450,750 ns,1,,06,00,2,      ACK packet,D2
2800,2:36.364.565.116,124.006.583 ms,,,,,0,[125 SOF],[Frames: 952 - 1076]
2801,2:36.426.366.450,62.780.500 ms,32,,06,00,0,Control Transfer (STALL),Index=2 Length=255


  <Msg UserText="Clear C_PORT_RESET" CA="117634312" LA="117634464">
  </Msg>
  <Msg UserText="Assertion 9.23.2:" CA="117975187" LA="117975289">
  </Msg>
  <Msg UserText="Assertion 9.23.2: Ends" CA="117975972" LA="117976060">
  </Msg>
  <Msg UserText="Assertion 9.23.5: Set Address" CA="117976820" LA="117976911">
  </Msg>
  <Msg UserText="Setting Address to: 6" CA="117977546" LA="117977633">
  </Msg>
  <Msg UserText="Assertion 9.23.5:" CA="118316128" LA="118316254">
  </Msg>
  <Msg UserText="Assertion 9.23.5: Ends" CA="118317033" LA="118317122">
  </Msg>
  <Msg UserText="Iteration Number: 104" CA="118318525" LA="118318699">
  </Msg>
  <Msg UserText="Assertion 9.23.3: Get String Descriptor" CA="118319906" LA="118320212">
  </Msg>
  <Error File="d:\5429t\testsrc\driverstest\usb\usbhct\exe\ctrltest.cpp" Line="834" ErrCode="0x0" ErrType="BOOL" ErrorText="Error 0x00000000" UserText="Request was made for 44 bytes of data.  Only 255 bytes of data was returned. " CA="119168484" LA="119168682">
  </Error>

[Jan Axelson]

The error message:

UserText="Request was made for 44 bytes of data.  Only 255 bytes of data was returned. "

is telling you (somewhat awkwardly) that that the request asked for 44 bytes and the device returned 255.

Jan

[johnwhoffman]

Unfortunately it's worse than that. The error message does not include the fact that a STALL occured on the bus. My guess is that the test application is oblivious to the STALL and put out a bad error message.

[Jan Axelson]

I haven't attempted to decode everything, but this line identifies a Get String Descriptor request:

2787,2:36.240.256.866,123.591.333 ms,4,,06,00,0,Get String Descriptor,Index=0 Length=255

and the device returns the supported language ID of 0409 (U.S. English).

This line says only Control Request, which suggests it can't identify the specific request:

2801,2:36.426.366.450,62.780.500 ms,32,,06,00,0,Control Transfer (STALL),Index=2 Length=255

Is the host sending a Get String Descriptor with wIndex = 2 (unsupported language ID)?

The device should return STALL on receiving an unsupported request.

Jan

[johnwhoffman]

We believe we have found a race condition within the MicroChip USB Stack Framework that resulted in a stall being sent at the wrong time. I have posted the solution on the microchip forum here: http://www.microchip.com/forums/tt.aspx?forumid=102

Thanks for helping.

[Jan Axelson]

Glad to hear it's working.

Jan