[libusb] Zero Length Packet Issue

[Chermak, D. <dal...@ph...>]

Greetings.

I have a 100% reproducible issue I am looking for help with, here are the details:

OS: Linux v3.8 (TI AM335x SDK 06.00)
USB Host: TI AM335x EVM
USB Device: Cypress FX2 based Bulk I/O with a FPGA on the other side of the FX2's Slave FIFO interface.
Endpoints
    0x00/0x80 - Control In/Out
    0x02 - Command Out
    0x84 - Command Response In
    0x86 - Data In
Firmware: FX2 firmware is custom but bulk endpoints are configured for Auto In/Out to/from FPGA via Slave FIFO.
libusb Version: 1.0.18

Description:
The Linux application that is using libusb is essentially a simple USB to Sockets bridge. A USB device plugs into the Linux box which is connected via Ethernet or Wi-Fi to a remote Host that consumes the data produced by the USB device. Two sockets are used for remote communication: a bi-directional Control and Command (Cnc) socket and a uni-directional (Linux->Remote Host) Data socket. The USB device is configured by the remote Host via the CnC socket and then placed into data acquisition mode. At that point the FPGA starts filling the FX2 EP6 FIFO buffers (4x512) with data that is Auto forwarded over EP6 to the Linux box where queued libusb transfer buffers await. Once a transfer completes, the application queues the transfer to the data socket thread where the socket send() function is used to transmit the contents to the remote Host. Once the send() function returns, the libusb transfer is re-queued to libusb to wait in line for more data from the USB device.

Everything works fine (I have run the application over weekends with 50Mbits/sec of data streaming over Wi-Fi) except in certain rare USB device configuration scenarios that result in a data chunk size that is a multiple of the FX2 EP6 FIFO buffer size of 0x200. Skipping the long discussion the FPGA designer and I had, it is apparently 'impossible' (so I am told) to fill an FX2 Auto In FIFO buffer *AND* tell the FX2 this is the last piece of data for this data chunk. Therefore, EP6 of the USB device is configured to send a Zero Length Packet (ZLP) when the 'packet end' signal is asserted by the FPGA and no 'new' data has been placed in the current (and empty) FX2 EP6 FIFO buffer.

Unfortunately, something is going wrong in the Linux application when a ZLP is sent by the USB device on EP6. In the log that follows the data chunk size is 0x10600, which of course is a multiple of the FX2 EP6 FIFO buffer size of 0x200. In this run, I configured the Linux application to queue up 8 libusb transfers with 16KB buffers to EP6. Note, the EP6 libusb transfers do *NOT* have a timeout, they just wait around for data to arrive. I also configured the USB device for 'triggered mode' instead of 'streaming mode', which means it only sends 1 data chunk and then waits to be asked to send another.  This is fine in this scenario as the entire first data chunk isn't even making it into the Linux application libusb transfer buffers anyway.

What I would expect to get in my EP6 callback would be 4 libusb transfers of 16KB followed by 1 libusb transfer of 3KB. The EP6 callback gets the 4 libusb transfers of 16KB but *NOT* the 1 libusb transfer of 3KB. The interesting bit, is that when the remote Host times out waiting for the last 3KB of the data chunk, it disconnects from the Linux application which results in the USB connection to the device being closed and the queued EP6 libusb transfers to be cancelled. Low and behold, the 'next' libusb transfer in line has 3KB in it, but the EP6 callback was never called, nor according to the logs did libusb 'think' it had received something. Even more strange, in this case, there is another 1.5KB of 'something' sitting in the 'next' libusb transfer in line. I say 'in this case', because I have also captured logs where there is 2KB and 1KB in these 'next' libusb transfers, which at least makes some sense, since only 3KB should be coming in. I have no idea where the 1.5KB of 'something' came from as my FPGA designer insists the FPGA did not write it to EP6 via the Slave FIFO interface.

Here is the libusb debug log with some application logging sprinkled in:

2014-03-20 21:16:12 libusb API Version: 0x01000102
2014-03-20 21:16:12 Starting ...
2014-03-20 21:16:25 Cnc connection from: 192.168.0.20.
2014-03-20 21:16:25 Data connection from: 192.168.0.20.
2014-03-20 21:16:25 Sync Time (UTC): Thu Mar 20 21:17:30 2014
2014-03-20 21:17:30 Powering up Usb ...
[timestamp] [threadID] facility level [function call] <message>
--------------------------------------------------------------------------------
[77.859597] [000006fd] libusb: debug [libusb_get_device_list]
[77.859902] [000006fd] libusb: debug [libusb_get_device_descriptor]
2014-03-20 21:17:30 Usb device info: 0F36:9006
[77.860787] [000006fd] libusb: debug [libusb_open] open 1.2
[77.860970] [000006fd] libusb: debug [op_open] getcap not available
[77.861031] [000006fd] libusb: debug [usbi_add_pollfd] add fd 15 events 4
[77.861153] [000006fd] libusb: debug [libusb_claim_interface] interface 0
1395350250 <86 0x1e5cc
[77.861397] [000006fd] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
1395350250 <86 0x1e6ac
[77.861611] [000006fd] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
1395350250 <86 0x1e764
[77.861733] [000006fd] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
1395350250 <86 0x1dffc
[77.861855] [000006fd] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
1395350250 <86 0x1e0a4
[77.861946] [000006fd] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
1395350250 <86 0x1e174
[77.862068] [000006fd] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
1395350250 <86 0x1e21c
[77.862160] [000006fd] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
1395350250 <86 0x1e2c4
[77.862282] [000006fd] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
2014-03-20 21:18:39 New debugFlags: 0x0001
1395350319 <02 861
[147.436038] [000006fd] libusb: debug [add_to_flying_list] arm timerfd for timeout in 1000ms (first in line)
[147.436130] [000006fd] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 12
[147.436343] [000006fd] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[147.436404] [000006fd] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[147.436435] [000006fd] libusb: debug [handle_events] poll() returned 1
[147.436465] [000006fd] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=12
[147.436526] [000006fd] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[147.436557] [000006fd] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[147.436588] [000006fd] libusb: debug [disarm_timerfd]
[147.436618] [000006fd] libusb: debug [usbi_handle_transfer_completion] transfer 0x6cbcc has callback 0xed9c
1395350319 02> 861 0
[147.447635] [000006fd] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[147.447696] [000006fd] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[147.447726] [000006fd] libusb: debug [handle_events] poll() returned 1
[147.447910] [000006fd] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16384
[147.447940] [000006fd] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[147.447971] [000006fd] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[147.448001] [000006fd] libusb: debug [disarm_timerfd]
[147.448062] [000006fd] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e5cc has callback 0x1001c
1395350319 86> 0x1e5cc 0 16384
1395350319 <86 0x1e5cc
[147.449252] [000006fd] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[147.455630] [000006fd] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[147.455753] [000006fd] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[147.455966] [000006fd] libusb: debug [handle_events] poll() returned 1
[147.456119] [000006fd] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16384
[147.456180] [000006fd] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[147.456210] [000006fd] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[147.456241] [000006fd] libusb: debug [disarm_timerfd]
[147.456271] [000006fd] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e6ac has callback 0x1001c
1395350319 86> 0x1e6ac 0 16384
1395350319 <86 0x1e6ac
[147.457400] [000006fd] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[147.463657] [000006fd] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[147.463748] [000006fd] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[147.463809] [000006fd] libusb: debug [handle_events] poll() returned 1
[147.463962] [000006fd] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16384
[147.464023] [000006fd] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[147.464053] [000006fd] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[147.464114] [000006fd] libusb: debug [disarm_timerfd]
[147.464145] [000006fd] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e764 has callback 0x1001c
1395350319 86> 0x1e764 0 16384
1395350319 <86 0x1e764
[147.465274] [000006fd] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[147.471652] [000006fd] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[147.471744] [000006fd] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[147.471805] [000006fd] libusb: debug [handle_events] poll() returned 1
[147.471957] [000006fd] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=16384
[147.472018] [000006fd] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[147.472049] [000006fd] libusb: debug [handle_bulk_completion] last URB in transfer --> complete!
[147.472110] [000006fd] libusb: debug [disarm_timerfd]
[147.472140] [000006fd] libusb: debug [usbi_handle_transfer_completion] transfer 0x1dffc has callback 0x1001c
1395350319 86> 0x1dffc 0 16384
1395350319 <86 0x1dffc
[147.473117] [000006fd] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 16384
[147.523318] [000006fd] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[147.523410] [000006fd] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[147.523471] [000006fd] libusb: debug [handle_events] poll() returned 0
[147.573581] [000006fd] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[147.573611] [000006fd] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[147.573672] [000006fd] libusb: debug [handle_events] poll() returned 0
2014-03-20 21:18:39 New debugFlags: 0x0000
2014-03-20 21:18:55 Cnc disconnect detected.
[162.929477] [000006fd] libusb: debug [libusb_cancel_transfer]
[162.929660] [000006fd] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[162.929721] [000006fd] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[162.929752] [000006fd] libusb: debug [handle_events] poll() returned 1
[162.929813] [000006fd] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[162.929843] [000006fd] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[162.929874] [000006fd] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[162.929904] [000006fd] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[162.929935] [000006fd] libusb: debug [disarm_timerfd]
[162.929965] [000006fd] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e2c4 has callback 0x1001c
1395350335 86> 0x1e2c4 3 0
[162.930179] [000006fd] libusb: debug [libusb_cancel_transfer]
[162.930270] [000006fd] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[162.930301] [000006fd] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[162.930331] [000006fd] libusb: debug [handle_events] poll() returned 1
[162.930362] [000006fd] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[162.930392] [000006fd] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[162.930850] [000006fd] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[162.930881] [000006fd] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[162.930911] [000006fd] libusb: debug [disarm_timerfd]
[162.930942] [000006fd] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e21c has callback 0x1001c
1395350335 86> 0x1e21c 3 0
[162.931003] [000006fd] libusb: debug [libusb_cancel_transfer]
[162.931064] [000006fd] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[162.931094] [000006fd] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[162.931155] [000006fd] libusb: debug [handle_events] poll() returned 1
[162.931186] [000006fd] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[162.931216] [000006fd] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[162.931247] [000006fd] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[162.931277] [000006fd] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[162.931308] [000006fd] libusb: debug [disarm_timerfd]
[162.931308] [000006fd] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e174 has callback 0x1001c
1395350335 86> 0x1e174 3 0
[162.931400] [000006fd] libusb: debug [libusb_cancel_transfer]
[162.931461] [000006fd] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[162.931522] [000006fd] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[162.931552] [000006fd] libusb: debug [handle_events] poll() returned 1
[162.931583] [000006fd] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=3072
[162.931613] [000006fd] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[162.931644] [000006fd] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[162.931674] [000006fd] libusb: debug [handle_bulk_completion] received 3072 bytes of surplus data
[162.931705] [000006fd] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[162.931735] [000006fd] libusb: debug [disarm_timerfd]
[162.931766] [000006fd] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e0a4 has callback 0x1001c
1395350335 86> 0x1e0a4 3 3072
[162.931827] [000006fd] libusb: debug [libusb_cancel_transfer]
[162.931888] [000006fd] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[162.931918] [000006fd] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[162.931949] [000006fd] libusb: debug [handle_events] poll() returned 1
[162.931979] [000006fd] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[162.932010] [000006fd] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[162.932040] [000006fd] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[162.932071] [000006fd] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[162.932101] [000006fd] libusb: debug [disarm_timerfd]
[162.932132] [000006fd] libusb: debug [usbi_handle_transfer_completion] transfer 0x1dffc has callback 0x1001c
1395350335 86> 0x1dffc 3 0
[162.932193] [000006fd] libusb: debug [libusb_cancel_transfer]
[162.932254] [000006fd] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[162.932285] [000006fd] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[162.932315] [000006fd] libusb: debug [handle_events] poll() returned 1
[162.932407] [000006fd] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[162.932437] [000006fd] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[162.932468] [000006fd] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[162.932498] [000006fd] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[162.932529] [000006fd] libusb: debug [disarm_timerfd]
[162.932559] [000006fd] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e764 has callback 0x1001c
1395350335 86> 0x1e764 3 0
[162.932620] [000006fd] libusb: debug [libusb_cancel_transfer]
[162.932681] [000006fd] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[162.932712] [000006fd] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[162.932742] [000006fd] libusb: debug [handle_events] poll() returned 1
[162.932773] [000006fd] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[162.932803] [000006fd] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[162.932834] [000006fd] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[162.932864] [000006fd] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[162.932895] [000006fd] libusb: debug [disarm_timerfd]
[162.932895] [000006fd] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e6ac has callback 0x1001c
1395350335 86> 0x1e6ac 3 0
[162.932986] [000006fd] libusb: debug [libusb_cancel_transfer]
[162.933047] [000006fd] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[162.933078] [000006fd] libusb: debug [handle_events] poll() 4 fds with timeout in 0ms
[162.933139] [000006fd] libusb: debug [handle_events] poll() returned 1
[162.933170] [000006fd] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=1536
[162.933200] [000006fd] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[162.933231] [000006fd] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[162.933261] [000006fd] libusb: debug [handle_bulk_completion] received 1536 bytes of surplus data
[162.933292] [000006fd] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[162.933292] [000006fd] libusb: debug [disarm_timerfd]
[162.933322] [000006fd] libusb: debug [usbi_handle_transfer_completion] transfer 0x1e5cc has callback 0x1001c
1395350335 86> 0x1e5cc 3 1536
[162.933414] [000006fd] libusb: debug [libusb_release_interface] interface 0
[162.933536] [000006fd] libusb: debug [libusb_close]
[162.933627] [000006fd] libusb: debug [usbi_remove_pollfd] remove fd 15
2014-03-20 21:18:55 Powering down Usb ...

Log Info/Observations:

-          The Linux application logging is fairly easy to pick out due to the different time formatting.

-          The <86 {libusb transfer pointer} entries are the 16KB buffers being queued up for EP6 arrivals.

-          The 86> {libusb transfer pointer} {status} {size} entries are completed libusb transfers from EP6 arriving at the callback.

-          The New debug flags: {value} entries are where the libusb debug logging is being turned on (1) and off (0) to avoid logging megabytes of the USB device configuration transactions. The libusb debug logging is turned on during libusb configuration setup, right before the command is sent to the USB device (<02 861 and 02> 0 861 in the log, 861 is a CnC sequence number) requesting a data chunk and during libusb configuration teardown.

-          As noted previously, the log shows libusb transfer 0x1e0a4 has 3072 bytes of surplus data, and libusb transfer 0x1e5cc has 1536 bytes of surplus 'something'.

-          Why 16KB transfer buffers instead of data chunk sized buffers? After trying *MANY* buffer sizes, 16KB seems to be the sweet spot performance-wise on this device, especially when using Wi-Fi. It also starts the data streaming sooner. Plus a design decision was made to keep the Linux application simple and efficient by avoiding having it deal with the complexities of dynamically re-sizing the buffers on the fly based on information gleaned via commands and 'watching' the data flow by.

Since things work fine when the last transfer buffer of a data chunk is any other size than a multiple of 0x200 I suspect this is an issue ZLP. I further suspect that I am not the only libusb user who has had to deal with the ZLPs being sent to the USB host device, so this is probably not a libusb error. There is probably a very good reason why libusb did not 'see' the 3KB arrive. I fear this is a kernel, sdk, driver or (gulp) chipset issue.

Other Info:

-          I have verified that when the USB device is plugged into the remote Host (Windows box) directly, there are no ZLP issues.

-          I have several BeagleBoard/Bone flavors, a Gumstix module and a LogicPD SOM I could try instead of the TI EVM, but at the end of the day, they all have TI processors, though some are OMAP as opposed to Sitara processors.

-          I have an Ellisys USB Explorer I could hook up if protocol information would be of any use.

My apologies if this post is too long. I made the 'dump' as small as I could, but I wanted there to be (hopefully) enough information present in this post to get started.

Many thanks for your valuable time.

Regards,

Dale


________________________________
The information contained in this message may be confidential and legally protected under applicable law. The message is intended solely for the addressee(s). If you are not the intended recipient, you are hereby notified that any use, forwarding, dissemination, or reproduction of this message is strictly prohibited and may be unlawful. If you are not the intended recipient, please contact the sender by return e-mail and destroy all copies of the original message.