hidg_set_report_complete FAILED

[coolsunny]

I have a test application which writes continuously HID packets between Windows & Embedded Linux HID device. I often get "gadget: hidg_set_report_complete FAILED" from the Linux HID driver and whenever I see this error, I lose that corresponding packet. It works most of the time but once in a while i end up losing these packets.

I am using Linux-2.6.35.3 kernel version on ARM processor.

Any thoughts are appreciated.

[Jan Axelson]

A protocol analyzer would show what happened on the bus.

If you don't have a protocol analyzer, use whatever debugging tools you have to find out how the gadget responds.

If the host is using Set Report requests, the control endpoint should ACK the Setup packet and the Data-stage data and return a zero-length packet in response to the Status stage's IN packet.

If the host is using interrupt transfers, the OUT endpoint should ACK the received data.

[coolsunny]

I will give a try and post the results.

[coolsunny]

It seems to be that the intermittent loss of packets is may be due to windows issue (http://support.microsoft.com/kb/2010159 /
http://support.microsoft.com/kb/2416007)and attached are the USBLyzer trace.  Does any one came accross this issue over HID and if yes what would be the fix for this?.

Code: [Select]


URB 0094 10:29:12.550 5.869241 s Bulk or Interrupt Transfer 1023 bytes buffer in 01:00:81 885D05F0h 000000cc usbccgp 87D1D6E8h
URB 0095 10:29:12.550 5.869248 s Bulk or Interrupt Transfer 1023 bytes buffer in 01:00:81 87623E18h 000000cb usbccgp 87D1D6E8h
URB 0096 10:29:12.550 5.869252 s Bulk or Interrupt Transfer 1023 bytes buffer in 01:00:81 884B45B8h USBPDO-11 usbhub 87D1D6E8h
URB 0097 10:29:12.550 5.869259 s Bulk or Interrupt Transfer 1023 bytes buffer in 01:00:81 898C6030h USBPDO-1 usbehci 87D1D6E8h
URB 0098 10:29:12.878 6.196684 s Class Other Get Port Status (1) in 898C6030h USBPDO-1 usbehci 8A4A56C0h
URB 0099-0098 10:29:12.878 6.196703 s 18 us Control Transfer Get Port Status (1) 00 05 01 00 in --:--:00 898C6030h USBPDO-1 usbehci 8A4A56C0h Success (Success)
00000000  00 05 01 00                                      ....           
URB 0100 10:29:12.878 6.196726 s Class Other Get Port Status (1) in 898C6030h USBPDO-1 usbehci 873AB260h
URB 0101-0100 10:29:12.878 6.196743 s 17 us Control Transfer Get Port Status (1) 00 05 01 00 in --:--:00 898C6030h USBPDO-1 usbehci 873AB260h Success (Success)
00000000  00 05 01 00                                      ....           
URB 0102 10:29:12.878 6.196753 s Class Other Clear Port Feature (1, Connect Status Change) out 898C6030h USBPDO-1 usbehci 873AB260h
URB 0103-0102 10:29:12.878 6.196765 s 12 us Control Transfer Clear Port Feature (1, Connect Status Change) out --:--:00 898C6030h USBPDO-1 usbehci 873AB260h Success (Success)
URB 0104-0017 10:29:12.894 6.213939 s 5.628798 s Bulk or Interrupt Transfer in 01:00:81 898C6030h USBPDO-1 usbehci 8762B9F0h Device Not Connected (Device has Gone)
URB 0105-0016 10:29:12.894 6.213942 s 5.628806 s Bulk or Interrupt Transfer in 01:00:81 884B45B8h USBPDO-11 usbhub 8762B9F0h Device Not Connected (Device has Gone)
URB 0106-0015 10:29:12.894 6.213947 s 5.628815 s Bulk or Interrupt Transfer in 01:00:81 87623E18h 000000cb usbccgp 8762B9F0h Device Not Connected (Device has Gone)
URB 0107-0014 10:29:12.894 6.213950 s 5.628824 s Bulk or Interrupt Transfer in 01:00:81 885D05F0h 000000cc usbccgp 8762B9F0h Device Not Connected (Device has Gone)
URB 0108-0097 10:29:12.894 6.213956 s 344.697 ms Bulk or Interrupt Transfer in 01:00:81 898C6030h USBPDO-1 usbehci 87D1D6E8h Device Not Connected (Device has Gone)
URB 0109-0096 10:29:12.894 6.213959 s 344.707 ms Bulk or Interrupt Transfer in 01:00:81 884B45B8h USBPDO-11 usbhub 87D1D6E8h Device Not Connected (Device has Gone)
URB 0110-0095 10:29:12.894 6.213962 s 344.714 ms Bulk or Interrupt Transfer in 01:00:81 87623E18h 000000cb usbccgp 87D1D6E8h Device Not Connected (Device has Gone)
URB 0111-0094 10:29:12.894 6.213964 s 344.723 ms Bulk or Interrupt Transfer in 01:00:81 885D05F0h 000000cc usbccgp 87D1D6E8h Device Not Connected (Device has Gone)
URB 0112 10:29:12.988 6.312636 s Class Other Clear Port Feature (1, Enabled/Disabled) out 898C6030h USBPDO-1 usbehci 873AB260h
URB 0113-0112 10:29:12.988 6.312657 s 21 us Control Transfer Clear Port Feature (1, Enabled/Disabled) out --:--:00 898C6030h USBPDO-1 usbehci 873AB260h Success (Success)
URB 0114 10:29:12.988 6.312670 s Bulk or Interrupt Transfer 8 bytes data in 23:00:81 898C6030h USBPDO-1 usbehci 8A317E70h
PnP 0115 10:29:12.988 6.312710 s Query Device Relations Bus Relations 8A2CBBA8h sk 878DB7A0h
PnP 0116 10:29:12.988 6.312716 s Query Device Relations Bus Relations 8A2B5C98h 000000ad usbhub 878DB7A0h
URB 0117 10:29:12.988 6.312723 s Class Other Get Port Status (1) in 898C6030h USBPDO-1 usbehci 878149F8h
URB 0118-0117 10:29:12.988 6.312738 s 15 us Control Transfer Get Port Status (1) 00 05 00 00 in --:--:00 898C6030h USBPDO-1 usbehci 878149F8h Success (Success)
00000000  00 05 00 00                                      ....           
URB 0119 10:29:12.988 6.312748 s Class Other Get Port Status (2) in 898C6030h USBPDO-1 usbehci 878149F8h
URB 0120-0119 10:29:12.988 6.312760 s 12 us Control Transfer Get Port Status (2) 00 05 00 00 in --:--:00 898C6030h USBPDO-1 usbehci 878149F8h Success (Success)
00000000  00 05 00 00                                      ....           
URB 0121 10:29:12.988 6.312769 s Class Other Get Port Status (3) in 898C6030h USBPDO-1 usbehci 878149F8h
URB 0122-0121 10:29:12.988 6.312780 s 11 us Control Transfer Get Port Status (3) 00 05 00 00 in --:--:00 898C6030h USBPDO-1 usbehci 878149F8h Success (Success)
00000000  00 05 00 00                                      ....           
URB 0123 10:29:12.988 6.312788 s Class Other Get Port Status (4) in 898C6030h USBPDO-1 usbehci 878149F8h
URB 0124-0123 10:29:12.988 6.312799 s 11 us Control Transfer Get Port Status (4) 00 05 00 00 in --:--:00 898C6030h USBPDO-1 usbehci 878149F8h Success (Success)
00000000  00 05 00 00                                      ....           
URB 0125 10:29:12.988 6.312808 s Class Other Get Port Status (5) in 898C6030h USBPDO-1 usbehci 878149F8h
URB 0126-0125 10:29:12.988 6.312819 s 11 us Control Transfer Get Port Status (5) 00 05 00 00 in --:--:00 898C6030h USBPDO-1 usbehci 878149F8h Success (Success)
00000000  00 05 00 00                                      ....           
URB 0127 10:29:12.988 6.312827 s Class Other Get Port Status (6) in 898C6030h USBPDO-1 usbehci 878149F8h
URB 0128-0127 10:29:12.988 6.312838 s 11 us Control Transfer Get Port Status (6) 00 05 00 00 in --:--:00 898C6030h USBPDO-1 usbehci 878149F8h Success (Success)
00000000  00 05 00 00                                      ....           
PnP 0129 10:29:12.988 6.312846 s Query Device Relations Bus Relations 898C6030h USBPDO-1 usbehci 878DB7A0h
PnP 0130-0129 10:29:12.988 6.312850 s 3 us Query Device Relations Bus Relations 898C6030h USBPDO-1 usbehci 878DB7A0h Success
PnP 0131-0116 10:29:12.988 6.312856 s 140 us Query Device Relations Bus Relations 8A2B5C98h 000000ad usbhub 878DB7A0h Success
PnP 0132-0115 10:29:12.988 6.312867 s 156 us Query Device Relations Bus Relations 8A2CBBA8h sk 878DB7A0h Success
KmIO 0133 10:29:12.988 6.312896 s Internal USB Submit Idle Notification 898C6030h USBPDO-1 usbehci 873AB260h
00000000  8A EF 1E BA 50 5D 2B 8A                          ....P]+.       
PnP 0134 10:29:12.988 6.312922 s Query Device Relations Removal Relations 873BC640h 000000cf HidUsb 8831F1A0h
PnP 0135-0134 10:29:12.988 6.312926 s 4 us Query Device Relations Removal Relations 873BC640h 000000cf HidUsb 8831F1A0h Not Supported
PnP 0136 10:29:12.988 6.312930 s Query Device Relations Ejection Relations 873BC640h 000000cf HidUsb 8831F1A0h
PnP 0137-0136 10:29:12.988 6.312933 s 2 us Query Device Relations Ejection Relations 873BC640h 000000cf HidUsb 8831F1A0h Not Supported
PnP 0138 10:29:12.988 6.312936 s Query Device Relations Removal Relations 876D82C8h _HID00000000 HidUsb 8831F1A0h
PnP 0139 10:29:12.988 6.312940 s Query Device Relations Removal Relations 885D05F0h 000000cc usbccgp 8831F1A0h
PnP 0140-0139 10:29:12.988 6.312944 s 4 us Query Device Relations Removal Relations 885D05F0h 000000cc usbccgp 8831F1A0h Not Supported
PnP 0141-0138 10:29:12.988 6.312947 s 11 us Query Device Relations Removal Relations 876D82C8h _HID00000000 HidUsb 8831F1A0h Not Supported
PnP 0142 10:29:12.988 6.312950 s Query Device Relations Ejection Relations 876D82C8h _HID00000000 HidUsb 8831F1A0h
PnP 0143 10:29:12.988 6.312953 s Query Device Relations Ejection Relations 885D05F0h 000000cc usbccgp 8831F1A0h
PnP 0144-0143 10:29:12.988 6.312955 s 2 us Query Device Relations Ejection Relations 885D05F0h 000000cc usbccgp 8831F1A0h Not Supported
PnP 0145-0142 10:29:12.988 6.312957 s 7 us Query Device Relations Ejection Relations 876D82C8h _HID00000000 HidUsb 8831F1A0h Not Supported
PnP 0146 10:29:12.988 6.312976 s Query Device Relations Removal Relations 887CC8E8h sk 8831F1A0h
PnP 0147 10:29:12.988 6.312978 s Query Device Relations Removal Relations 87623E18h 000000cb usbccgp 8831F1A0h
PnP 0148 10:29:12.988 6.312982 s Query Device Relations Removal Relations 884B45B8h USBPDO-11 usbhub 8831F1A0h
PnP 0149-0148 10:29:12.988 6.312985 s 3 us Query Device Relations Removal Relations 884B45B8h USBPDO-11 usbhub 8831F1A0h Not Supported
PnP 0150-0147 10:29:12.988 6.312987 s 9 us Query Device Relations Removal Relations 87623E18h 000000cb usbccgp 8831F1A0h Not Supported
PnP 0151-0146 10:29:12.988 6.312989 s 13 us Query Device Relations Removal Relations 887CC8E8h sk 8831F1A0h Not Supported
PnP 0152 10:29:12.988 6.312992 s Query Device Relations Ejection Relations 887CC8E8h sk 8831F1A0h
PnP 0153 10:29:12.988 6.312995 s Query Device Relations Ejection Relations 87623E18h 000000cb usbccgp 8831F1A0h
PnP 0154 10:29:12.988 6.312997 s Query Device Relations Ejection Relations 884B45B8h USBPDO-11 usbhub 8831F1A0h
PnP 0155-0154 10:29:12.988 6.312999 s 2 us Query Device Relations Ejection Relations 884B45B8h USBPDO-11 usbhub 8831F1A0h Not Supported
PnP 0156-0153 10:29:12.988 6.313001 s 7 us Query Device Relations Ejection Relations 87623E18h 000000cb usbccgp 8831F1A0h Not Supported
PnP 0157-0152 10:29:12.988 6.313003 s 11 us Query Device Relations Ejection Relations 887CC8E8h sk 8831F1A0h Not Supported
PnP 0158 10:29:13.003 6.322507 s Surprise Removal 873BC640h 000000cf HidUsb 878149F8h
PnP 0159-0158 10:29:13.003 6.322633 s 126 us Surprise Removal 873BC640h 000000cf HidUsb 878149F8h Success
PnP 0160 10:29:13.003 6.334469 s Surprise Removal 876D82C8h _HID00000000 HidUsb 878149F8h
Power 0161 10:29:13.644 6.965880 s Wait Wake S0 (Working) 8A2CBBA8h sk 87AFE8C0h
Power 0162 10:29:13.644 6.965891 s Wait Wake S0 (Working) 8A2B5C98h 000000ad usbhub 87AFE8C0h
Power 0163 10:29:13.644 6.965899 s Wait Wake S0 (Working) 898C6030h USBPDO-1 usbehci 87AFE8C0h
Power 0164 10:29:13.644 6.965915 s Set Power D2 8A2CBBA8h sk 872BE008h
Power 0165 10:29:13.644 6.965921 s Set Power D2 8A2B5C98h 000000ad usbhub 872BE008h
URB 0166-0114 10:29:13.644 6.965952 s 653.282 ms Bulk or Interrupt Transfer in 23:00:81 898C6030h USBPDO-1 usbehci 8A317E70h Cancelled (Canceled)
Power 0167 10:29:13.644 6.965967 s Set Power D2 898C6030h USBPDO-1 usbehci 872BE008h
Power 0168-0167 10:29:13.675 6.992402 s 26.435 ms Set Power 898C6030h USBPDO-1 usbehci 872BE008h Success
Power 0169-0165 10:29:13.675 6.992408 s 26.487 ms Set Power 8A2B5C98h 000000ad usbhub 872BE008h Success
Power 0170-0164 10:29:13.675 6.992412 s 26.497 ms Set Power 8A2CBBA8h sk 872BE008h Success
URB 0171 10:29:13.894 7.213895 s Bulk or Interrupt Transfer 1023 bytes buffer in 01:00:81 885D05F0h 000000cc usbccgp 87D1D6E8h
URB 0172 10:29:13.894 7.213908 s Bulk or Interrupt Transfer 1023 bytes buffer in 01:00:81 87623E18h 000000cb usbccgp 87D1D6E8h
URB 0173 10:29:13.894 7.213915 s Bulk or Interrupt Transfer 1023 bytes buffer in 01:00:81 884B45B8h USBPDO-11 usbhub 87D1D6E8h
URB 0174 10:29:13.894 7.213925 s Bulk or Interrupt Transfer 1023 bytes buffer in 01:00:81 898C6030h USBPDO-1 usbehci 87D1D6E8h
URB 0175-0174 10:29:13.894 7.213968 s 44 us Bulk or Interrupt Transfer in 01:00:81 898C6030h USBPDO-1 usbehci 87D1D6E8h Cancelled (Device has Gone)
URB 0176-0173 10:29:13.894 7.213975 s 60 us Bulk or Interrupt Transfer in 01:00:81 884B45B8h USBPDO-11 usbhub 87D1D6E8h Cancelled (Device has Gone)
URB 0177-0172 10:29:13.894 7.213980 s 72 us Bulk or Interrupt Transfer in 01:00:81 87623E18h 000000cb usbccgp 87D1D6E8h Cancelled (Device has Gone)
URB 0178-0171 10:29:13.894 7.213985 s 90 us Bulk or Interrupt Transfer in 01:00:81 885D05F0h 000000cc usbccgp 87D1D6E8h Cancelled (Device has Gone)
PnP 0179 10:29:13.894 7.214000 s Surprise Removal 885D05F0h 000000cc usbccgp 878149F8h
PnP 0180-0179 10:29:13.894 7.214006 s 6 us Surprise Removal 885D05F0h 000000cc usbccgp 878149F8h Success
PnP 0181-0160 10:29:13.894 7.214031 s 879.562 ms Surprise Removal 876D82C8h _HID00000000 HidUsb 878149F8h Success
PnP 0182 10:29:13.910 7.232449 s Surprise Removal 887CC8E8h sk 878149F8h
PnP 0183 10:29:13.910 7.232458 s Surprise Removal 87623E18h 000000cb usbccgp 878149F8h
PnP 0184 10:29:13.910 7.232466 s Surprise Removal 884B45B8h USBPDO-11 usbhub 878149F8h
PnP 0185-0184 10:29:13.910 7.232768 s 302 us Surprise Removal 884B45B8h USBPDO-11 usbhub 878149F8h Success
PnP 0186-0183 10:29:13.910 7.232782 s 324 us Surprise Removal 87623E18h 000000cb usbccgp 878149F8h Success
PnP 0187-0182 10:29:13.910 7.232792 s 343 us Surprise Removal 887CC8E8h sk 878149F8h Success
Power 0188 10:29:16.769 10.101201 s Set Power D0 8A2CBBA8h sk 87D1D6E8h
Power 0189 10:29:16.769 10.101206 s Set Power D0 8A2B5C98h 000000ad usbhub 87D1D6E8h
Power 0190 10:29:16.769 10.101210 s Set Power D0 898C6030h USBPDO-1 usbehci 87D1D6E8h
Power 0191-0163 10:29:16.894 10.216784 s 3.250885 s Wait Wake S0 (Working) 898C6030h USBPDO-1 usbehci 87AFE8C0h Success
Power 0192 10:29:16.894 10.216792 s Set Power D0 8A2CBBA8h sk 87B2CBD8h
Power 0193-0162 10:29:16.894 10.216798 s 3.250907 s Wait Wake S0 (Working) 8A2B5C98h 000000ad usbhub 87AFE8C0h Success
Power 0194-0161 10:29:16.894 10.216800 s 3.250921 s Wait Wake S0 (Working) 8A2CBBA8h sk 87AFE8C0h Success
KmIO 0195-0133 10:29:16.894 10.216805 s 3.903908 s Internal USB Submit Idle Notification 898C6030h USBPDO-1 usbehci 873AB260h Cancelled
Power 0196-0190 10:29:16.894 10.216810 s 115.600 ms Set Power 898C6030h USBPDO-1 usbehci 87D1D6E8h Success
URB 0197 10:29:16.894 10.216816 s Bulk or Interrupt Transfer 8 bytes data in 23:00:81 898C6030h USBPDO-1 usbehci 8A317E70h
Power 0198 10:29:16.894 10.216852 s Set Power D0 8A2B5C98h 000000ad usbhub 87B2CBD8h
Power 0199 10:29:16.894 10.216855 s Set Power D0 898C6030h USBPDO-1 usbehci 87B2CBD8h
Power 0200-0199 10:29:16.894 10.216858 s 4 us Set Power 898C6030h USBPDO-1 usbehci 87B2CBD8h Success
Power 0201-0198 10:29:16.894 10.216861 s 9 us Set Power 8A2B5C98h 000000ad usbhub 87B2CBD8h Success
Power 0202-0192 10:29:16.894 10.216862 s 70 us Set Power 8A2CBBA8h sk 87B2CBD8h Success
Power 0203-0189 10:29:16.894 10.216865 s 115.660 ms Set Power 8A2B5C98h 000000ad usbhub 87D1D6E8h Success
Power 0204-0188 10:29:16.894 10.216868 s 115.666 ms Set Power 8A2CBBA8h sk 87D1D6E8h Success
URB 0205 10:29:16.894 10.216876 s Get Status from Device in 898C6030h USBPDO-1 usbehci 873AB260h
URB 0206-0205 10:29:16.894 10.216888 s 13 us Control Transfer Get Status (Dvc) 01 00 in --:--:00 898C6030h USBPDO-1 usbehci 873AB260h Success (Success)
00000000  01 00                                            ..             
KmIO 0207 10:29:16.894 10.216900 s Internal USB Submit Idle Notification 898C6030h USBPDO-1 usbehci 873AB260h
00000000  8A EF 1E BA 50 5D 2B 8A                          ....P]+.       
Power 0208 10:29:17.769 11.090830 s Wait Wake S0 (Working) 8A2CBBA8h sk 87AFE8C0h
Power 0209 10:29:17.769 11.090842 s Wait Wake S0 (Working) 8A2B5C98h 000000ad usbhub 87AFE8C0h
Power 0210 10:29:17.769 11.090850 s Wait Wake S0 (Working) 898C6030h USBPDO-1 usbehci 87AFE8C0h
Power 0211 10:29:17.769 11.090865 s Set Power D2 8A2CBBA8h sk 89485978h
Power 0212 10:29:17.769 11.090872 s Set Power D2 8A2B5C98h 000000ad usbhub 89485978h
URB 0213-0197 10:29:17.769 11.090898 s 874.083 ms Bulk or Interrupt Transfer in 23:00:81 898C6030h USBPDO-1 usbehci 8A317E70h Cancelled (Canceled)
Power 0214 10:29:17.769 11.090914 s Set Power D2 898C6030h USBPDO-1 usbehci 89485978h
Power 0215-0214 10:29:17.800 11.117299 s 26.385 ms Set Power 898C6030h USBPDO-1 usbehci 89485978h Success
Power 0216-0212 10:29:17.800 11.117306 s 26.434 ms Set Power 8A2B5C98h 000000ad usbhub 89485978h Success
Power 0217-0211 10:29:17.800 11.117310 s 26.445 ms Set Power 8A2CBBA8h sk 89485978h Success



[Tsuneo]

It seems to be that the intermittent loss of packets is may be due to windows issue

No.
The USBlyzer trace suggests that your device has suddenly disconnected.
It dropped high-speed terminator.
This change was detected by the hub at "Get Port Status (1)" on the 9th line of the trace.
The hub returns,
00 05 01 00  / PORT_HIGH_SPEED, PORT_POWER, C_PORT_CONNECTION (and not PORT_CONNECTION)

The rest of the trace is caused by the OS response on device disconnection.

Another weird clue on the trace is,
All of Get Port Status (1) - Get Port Status (6) returns this result.
00 05 00 00  / PORT_HIGH_SPEED, PORT_POWER

Usually, PORT_HIGH_SPEED bit is set by the hub after a high-speed device is connected to the port.
It may suggest problem on the hub, or it may be just a feature of the hub.

Tsuneo

[coolsunny]

The reason for sudden disconnection is we have heart beat monitoring between the host and the device and if they both doesn't exchange the packets for three seconds, the device automatically shuts down.

I am still confused with the issue itself (to go in which direction) whether it is the host or device problem. The issue is happening occasionally on windows platform but not the on the MAC OSX.

The device is connected directly to the PC USB port and not sure why the high speed terminator dropped. Also to let you know that, whenever this happens the device is able to write the packets to the host but the Host packets doesn't reach the device  and i get the read time out failing the heart beat monitoring.

Do you think the hub problem(Or dropping the packets) is due to the HID.dll in signal 11 APIs (http://www.signal11.us/oss/hidapi/) OR some other issue from Windows ?. OR it is the Linux 2.6.32 HID kernel issue?.

[Tsuneo]

Enough clues aren't shown yet, to know what happens on Windows.

whenever this happens the device is able to write the packets to the host but the Host packets doesn't reach the device

Post more trace just before above one, which includes the trouble on host --> device transfer.
Which transfer type do you apply to this transfer, interrupt OUT endpoint, or Set_Report request?
Maybe, it's Set_Report, but I need to be confirmed

Tsuneo

[coolsunny]

On Linux (Device) side,I am using simple linux system open (/dev/hidg0) , timed out read and write calls. On Windows it is signal 11 HID API's and I guess by default it is using set_report request as I get Set_report_request FAILED (linux driver printing this message) whenever i miss the packet.

I also looked at (https://github.com/signal11/hidapi/issues/88) this possible solution with no luck.

I tried to capture more output today but with no luck as this issue occurs occasionally. Definitely I will try to post more traces just before it happens and when it recovers automatically. With HHD Software analyser, I have seen the GetDeviceDescriptor() is called suddenly whenever this issue happens. As per my understanding the GetDeviceDescriptor will be called while enumeration.

[Tsuneo]

Ok, until you would get a trace on Set_Report trouble, I'll try to interpret above trace more.

if they both doesn't exchange the packets for three seconds, the device automatically shuts down.

Is this "three seconds" timeout period stable? Doesn't it come too early?

Above trace starts with pending URBs of HID interrupt IN transfer (across four layered device stacks). It suggests that an interrupt IN transfer finished successfully, just a couple of milli-seconds before of this trace. Because, Windows HID class driver immediately issues the next interrupt IN transfer, just after successful completion of the last interrupt IN transfer.

That is, the interrupt IN endpoint of the device is still working at this point (5.869241 sec)
But the hub detects device disconnection at 6.196703 sec
Only 0.327462 sec after the last interrupt IN transfer. It's too short, for three seconds timeout.

Tsuneo

[coolsunny]

Some more traces:

The below trace is just before the problem. It was all working fine till packet number#7552 and from packet 7552 it didnt get the BULK/INTERRUPT Transfer and went to GetDeviceDescsiptor. I hope this would give some clue to us?.

Code: [Select]

[b]Trace#1 (Regular flow when it is working normally .. (CONTROL->BULK/INTERRUPT-->Class-Specific Request->BACK TO CONTROL TRANSFER) (This continues in a loop)[/b]

007544: Control Transfer (UP), 09.08.2013 11:49:54.937 +0.0. (1. Device: USB Human Interface Device) Status: 0x00000000
Pipe Handle: Control Pipe

 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

Setup Packet


 21 09 00 02 00 00 FF 03


Recipient: Interface
Request Type: Class
Direction: Host->Device
Request: 0x9 (Unknown)
Value: 0x200
Index: 0x0
Length: 0x3ff

007545: Bulk or Interrupt Transfer (UP), 09.08.2013 11:49:55.218 +0.281. (1. Device: USB Human Interface Device) Status: 0x00000000
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)
Get 0x3ff bytes from the device


007547: Class-Specific Request (DOWN), 09.08.2013 11:49:55.468 +0.250 (1. Device: USB Human Interface Device)
Destination: Interface, Index 0
Reserved Bits: 34
Request: 0x9
Value: 0x200
Send 0x3ff bytes to the device


007548: Control Transfer (UP), 09.08.2013 11:49:55.468 +0.0. (1. Device: USB Human Interface Device) Status: 0x00000000
Pipe Handle: Control Pipe

 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

Setup Packet


 21 09 00 02 00 00 FF 03

Recipient: Interface
Request Type: Class
Direction: Host->Device
Request: 0x9 (Unknown)
Value: 0x200
Index: 0x0
Length: 0x3ff

007549: Bulk or Interrupt Transfer (UP), 09.08.2013 11:49:55.750 +0.281. (1. Device: USB Human Interface Device) Status: 0x00000000
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)
Get 0x3ff bytes from the device

007551: Class-Specific Request (DOWN), 09.08.2013 11:49:56.0 +0.250 (1. Device: USB Human Interface Device)
Destination: Interface, Index 0
Reserved Bits: 34
Request: 0x9
Value: 0x200
Send 0x3ff bytes to the device



[color=red][font=Verdana][font=Verdana]007552: Control Transfer (UP), 09.08.2013 11:49:56.015 +0.015. (1. Device: USB Human Interface Device) Status: 0x00000000
Pipe Handle: Control Pipe


Setup Packet


 21 09 00 02 00 00 FF 03


Recipient: Interface
Request Type: Class
Direction: Host->Device
Request: 0x9 (Unknown)
Value: 0x200
Index: 0x0
Length: 0x3ff

007553: Get Descriptor Request (DOWN), 09.08.2013 11:49:59.031 +3.015 (1. Device: USB Human Interface Device)
Descriptor Type: String
Descriptor Index: 0x0
Transfer Buffer Size: 0x402 bytes
LanguageId: 0x409


007554: Control Transfer (UP), 09.08.2013 11:49:59.031 +0.0. (1. Device: USB Human Interface Device) Status: 0x00000000
Pipe Handle: Control Pipe


 04 03 09 04
....

Setup Packet


 80 06 00 03 09 04 02 04
€.......

Recipient: Device
Request Type: Standard
Direction: Device->Host
Request: 0x6 (GET_DESCRIPTOR)
Value: 0x300
Index: 0x409
Length: 0x402


007555: Get Descriptor Request (DOWN), 09.08.2013 11:49:59.031 +0.0 (1. Device: USB Human Interface Device)
Descriptor Type: String
Descriptor Index: 0x1
Transfer Buffer Size: 0x402 bytes
LanguageId: 0x409


007556: Control Transfer (UP), 09.08.2013 11:49:59.031 +0.0. (1. Device: USB Human Interface Device) Status: 0x00000000
Pipe Handle: Control Pipe

Setup Packet


 80 06 01 03 09 04 02 04
€.......

Recipient: Device
Request Type: Standard
Direction: Device->Host
Request: 0x6 (GET_DESCRIPTOR)
Value: 0x301
Index: 0x409
Length: 0x402

007557: Get Descriptor Request (DOWN), 09.08.2013 11:49:59.031 +0.0 (1. Device: USB Human Interface Device)
Descriptor Type: String
Descriptor Index: 0x4
Transfer Buffer Size: 0x402 bytes
LanguageId: 0x409


007558: Control Transfer (UP), 09.08.2013 11:49:59.031 +0.0. (1. Device: USB Human Interface Device) Status: 0x00000000
Pipe Handle: Control Pipe


 1C 03 48 00 49 00 44 00 20 00 49 00 6E 00 74 00
 65 00 72 00 66 00 61 00 63 00 65 00
..H.I.D. .I.n.t.
e.r.f.a.c.e.

Setup Packet


 80 06 04 03 09 04 02 04
€.......

Recipient: Device
Request Type: Standard
Direction: Device->Host
Request: 0x6 (GET_DESCRIPTOR)
Value: 0x304
Index: 0x409
Length: 0x402



007559: Bulk or Interrupt Transfer (UP), 09.08.2013 11:50:01.125 +2.093. (1. Device: USB Human Interface Device) Status: 0x00000000
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)
Get 0x3ff bytes from the device

007561: Bulk or Interrupt Transfer (UP), 09.08.2013 11:50:01.640 +0.515. (1. Device: USB Human Interface Device) Status: 0xc0000011
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)
Get 0x0 bytes from the device


007562: Bulk or Interrupt Transfer (UP), 09.08.2013 11:50:02.031 +0.390. (1. Device: USB Human Interface Device) Status: 0xc0007000
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)
Get 0x0 bytes from the device


007563: Abort Pipe (DOWN), 09.08.2013 11:50:02.125 +0.093 (1. Device: USB Human Interface Device)
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)



007564: Abort Pipe (UP), 09.08.2013 11:50:02.125 +0.0. (1. Device: USB Human Interface Device) Status: 0x00000000
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)



007565: Reset Pipe (DOWN), 09.08.2013 11:50:02.515 +0.390 (1. Device: USB Human Interface Device)
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)



007566: Reset Pipe (UP), 09.08.2013 11:50:02.515 +0.0. (1. Device: USB Human Interface Device) Status: 0x00000000
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)



007569: Bulk or Interrupt Transfer (UP), 09.08.2013 11:50:03.640 +0.125. (1. Device: USB Human Interface Device) Status: 0xc0000011
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)
Get 0x0 bytes from the device


007570: Bulk or Interrupt Transfer (UP), 09.08.2013 11:50:04.031 +0.390. (1. Device: USB Human Interface Device) Status: 0xc0007000
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)
Get 0x0 bytes from the device


007571: Abort Pipe (DOWN), 09.08.2013 11:50:04.125 +0.093 (1. Device: USB Human Interface Device)
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)



007572: Abort Pipe (UP), 09.08.2013 11:50:04.125 +0.0. (1. Device: USB Human Interface Device) Status: 0x00000000
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)



007573: Reset Pipe (DOWN), 09.08.2013 11:50:04.515 +0.390 (1. Device: USB Human Interface Device)
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)



007574: Reset Pipe (UP), 09.08.2013 11:50:04.515 +0.0. (1. Device: USB Human Interface Device) Status: 0x00000000
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)



007576: Bulk or Interrupt Transfer (UP), 09.08.2013 11:50:06.031 +0.0. (1. Device: USB Human Interface Device) Status: 0x80000300
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)
Get 0x3ff bytes from the device


 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


007577: Abort Pipe (DOWN), 09.08.2013 11:50:06.031 +0.0 (1. Device: USB Human Interface Device)
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)



007578: Abort Pipe (UP), 09.08.2013 11:50:06.031 +0.0. (1. Device: USB Human Interface Device) Status: 0x00000000
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)



007579: Reset Pipe (DOWN), 09.08.2013 11:50:06.421 +0.390 (1. Device: USB Human Interface Device)
Pipe Handle: 0x899a774c (Endpoint Address: 0x81)








[Tsuneo]

Here is an interpretation of above HDD sniffer log.

#007552: completion of Set_Report(output) request
No error is reported by USBD (low-level system call), but a couple of differences are seen.
- It takes more (+0.015 sec) than other Set_Report completion (+0.0 #007544, #007548)
- HDD sniffer doesn't display sent data

The buffer, given to HidD_SetOutputReport (or ReadFile) by your application, may be dangling.
How did you allocate this buffer on your app?


#007553 - #007558
Get_Descriptor( String ) requests
No error is reported by USBD for these requests.
But these requests seem to disturb the process of your device firmware
- It takes more than five seconds from the last Set_Report (#007552, 11:49:56.015) to the next interrupt IN transfer (#007559, 11:50:01.125). For other pairs, the response time takes just +0.281 second (#007545, #007549).

Unfortunately, as HDD sniffer doesn't give IRP address, we can't tell if these String descriptor requests are issued by your application, or any other utility like USBView.


#007561: failed completion of interrupt IN transfer, USBD_STATUS_XACT_ERROR (0xc0000011)
#007562: failed completion of interrupt IN transfer, USBD_STATUS_DEVICE_GONE (0xc0007000)
These results should be caused by device disconnection of timeout.


1) Check the buffer allocation method on PC application.
2) Your firmware can't process control request and the report back process, concurrently
Re-organize your firmware, so that the report back process runs even while control transfer is going on.

Tsuneo

[coolsunny]

Tsuneo,I really appreciate your time in helping me to resolve this issue.

How did you allocate this buffer on your app?

It is a static buffer on both Linux and Windows side.

Unfortunately, as HDD sniffer doesn't give IRP address, we can't tell if these String descriptor requests are issued by your application, or any other utility like USBView.

Is there any other USB analyzer which will give the IRP address as there is a very much possibility for other software to issue this request. We have antivirus software and other third party software's to restrict the USB port access. Also to let you know that this issue doesn't happen on an clean Windows Machine (I mean just the OS without any other third party software's). From the beginning, I was leaning towards this issue, as this is the only difference.

As mentioned, on Linux I use the linux system calls open,read and write and not sure how do we differentiate the control & bulk interrupt transfers. Please let me know if you've any pointers so that i can give a try to see if it fixes the issue.

Do you've any idea why the GetDescriptor are causing the delay's?.


One More Update:
With the Windows Patch(as mentioned in the above link), the frequency of loosing the packets has come down and no idea  how it it impacting this issue (I deselected the power management not to allow the computer to turn of this device to save power). But with this fix, i still see one or two packets missing.

[Infovision]

What is the solution for this problem? I have the exactly the same problem using linux-2.6.35.3 on the Device. The problem can be seen on Windows platform, not the Mac. I have turned off USB power save mode, but still got "hidg_set_report_complete FAILED".

[Jan Axelson]

To help isolate the problem, use a protocol analyzer or whatever debugging tools you have to find out what happens on the bus when the host sends a Get_Report request that fails.

The device's control endpoint should ACK the Setup packet and the Data-stage data (NAKs are OK before ACK in the Data stage) and return a zero-length packet in response to the Status stage's IN packet.

[coolsunny]

I was able to debug more into the issue on linux kernel side and found that function "hidg_set_report_complete(struct usb_ep *ep, struct usb_request *req)"  returns the  status code as "-108".

Code: [Select]

{
struct f_hidg *hidg = (struct f_hidg *)req->context;

if (req->status != 0 || req->buf == NULL || req->actual == 0) {
            ERROR(hidg->func.config->cdev, "%s FAILED status = %d \n", __func__, req->status);
return;
}

Based on the definitions "-108" means ESHUTDOWN and looking at the possible scenarios when this can occur are the following cases (http://lxr.free-electrons.com/source/include/linux/usb/gadget.h#L317)
 

59  * @status: Reports completion code, zero or a negative errno.
 *      Normally, faults block the transfer queue from advancing until
 *      the completion callback returns.
 *      Code "-ESHUTDOWN" indicates completion caused by device disconnect,
 *      or when the driver disabled the endpoint.

I am ruling out the device disconnect scenario and not sure when the driver will disable the endpoint?.