libusb not writing to buffer in isochronous mode


10 posts
by axlecrusher » Sun Jul 01, 2012 4:41 pm
Hello, I am porting an application that I wrote from PC to the pi. The software interfaces with custom AVR hardware via USB.

The only problem I have run into that I can not solve is with libusb and isochronous transfers. It seems that with isochronous transfers from the AVR device to the rpi, the kernel is not copying the received data into the buffer provided through libusb. If I sniff the USB interface with usbmon I can see the correct data coming from the AVR device. Libusb is reporting the packet size correctly, and is not reporting any errors. Everything looks fine except that the received data is never written to the buffer.

Does anyone have any ideas as to why isochronous transfers are failing in this way?

I did find some forum posts on USB packet loss however I don't think I'm seeing that problem.

Bulk transfer mode works fine and the data is received correctly but the latency is too high for me to use beyond debugging purposes.

The libusb isochronous transfers work just fine with linux on a PC.
Posts: 3
Joined: Fri Jun 29, 2012 5:57 pm
by PaulBuxton » Mon Jul 02, 2012 11:43 am
Have you tried turning on Debug messages with
libusb_set_debug ?

Are you using the same version of the library on PC and RPi? If not might be worth checking the differences.

Paul
Posts: 57
Joined: Tue Jan 10, 2012 11:38 am
by axlecrusher » Mon Jul 02, 2012 10:45 pm
Yes I have debug messages set to 3. Nothing was shown.

Compiling libusb with --enable-debug-log I get the following output.

I am using libusb 1.0.9 on both the raspberry pi and the PC.

The lines with the long string of zeros is output from my program displaying what it has copied out of the libusb transfer buffer (I initialized the buffer to 0x00). On such lines the "00:64:" the second hex value is the length of the received iso packet, indicating that data was received. There should be non zero data in the buffer.

Code: Select all
libusb: 0.000000 debug [libusb_init] libusb-1.0.9
libusb: 0.001003 debug [find_usbfs_path] found usbfs at /dev/bus/usb
libusb: 0.001567 debug [op_init] bulk continuation flag supported
libusb: 0.001806 debug [op_init] zero length packet flag supported
libusb: 0.002195 debug [op_init] found usb devices in sysfs
libusb: 0.003282 debug [usbi_add_pollfd] add fd 5 events 1
libusb: 0.003637 debug [usbi_io_init] using timerfd for timeouts
libusb: 0.003855 debug [usbi_add_pollfd] add fd 7 events 1
libusb: 0.004097 debug [libusb_get_device_list]
libusb: 0.004570 debug [sysfs_scan_device] scan usb1
libusb: 0.005928 debug [sysfs_scan_device] bus=1 dev=1
libusb: 0.006182 debug [enumerate_device] busnum 1 devaddr 1 session_id 257
libusb: 0.006357 debug [enumerate_device] allocating new device for 1/1 (session 257)
libusb: 0.007534 debug [sysfs_scan_device] scan 1-1
libusb: 0.008588 debug [sysfs_scan_device] bus=1 dev=2
libusb: 0.008834 debug [enumerate_device] busnum 1 devaddr 2 session_id 258
libusb: 0.009007 debug [enumerate_device] allocating new device for 1/2 (session 258)
libusb: 0.009837 debug [sysfs_scan_device] scan 1-1.1
libusb: 0.010894 debug [sysfs_scan_device] bus=1 dev=3
libusb: 0.011140 debug [enumerate_device] busnum 1 devaddr 3 session_id 259
libusb: 0.011331 debug [enumerate_device] allocating new device for 1/3 (session 259)
libusb: 0.012179 debug [sysfs_scan_device] scan 1-1.2
libusb: 0.013306 debug [sysfs_scan_device] bus=1 dev=4
libusb: 0.013553 debug [enumerate_device] busnum 1 devaddr 4 session_id 260
libusb: 0.013728 debug [enumerate_device] allocating new device for 1/4 (session 260)
libusb: 0.014692 debug [sysfs_scan_device] scan 1-1.3
libusb: 0.015801 debug [sysfs_scan_device] bus=1 dev=5
libusb: 0.016045 debug [enumerate_device] busnum 1 devaddr 5 session_id 261
libusb: 0.016220 debug [enumerate_device] allocating new device for 1/5 (session 261)
libusb: 0.017220 debug [libusb_get_device_descriptor]
libusb: 0.017680 debug [libusb_get_device_descriptor]
libusb: 0.018054 debug [libusb_get_device_descriptor]
libusb: 0.018423 debug [libusb_get_device_descriptor]
libusb: 0.018795 debug [libusb_get_device_descriptor]
libusb: 0.019192 debug [libusb_open] open 1.5
libusb: 0.019439 debug [op_open] opening /dev/bus/usb/001/005
libusb: 0.019744 debug [usbi_add_pollfd] add fd 8 events 4
libusb: 0.020141 debug [libusb_unref_device] destroy device 1.1
libusb: 0.020415 debug [libusb_unref_device] destroy device 1.2
libusb: 0.020605 debug [libusb_unref_device] destroy device 1.3
libusb: 0.020809 debug [libusb_unref_device] destroy device 1.4
libusb: 0.021065 debug [libusb_claim_interface] interface 0
libusb: 0.021482 debug [libusb_get_active_config_descriptor]
libusb: 0.021970 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.022721 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.023376 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.023690 debug [libusb_submit_transfer] arm timerfd for timeout in 2000ms (first in line)
libusb: 0.023972 debug [libusb_get_active_config_descriptor]
libusb: 0.024470 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.025134 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.025623 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.025934 debug [libusb_get_active_config_descriptor]
libusb: 0.026317 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.026935 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.027413 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.027738 debug [libusb_get_active_config_descriptor]
libusb: 0.028130 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.028750 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.029306 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.029600 debug [libusb_get_active_config_descriptor]
libusb: 0.029979 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.030761 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.031293 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.031591 debug [libusb_get_active_config_descriptor]
libusb: 0.031972 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.032604 debug [sysfs_get_active_config_descriptor] active configuration 1
libusb: 0.033086 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.167023 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.167353 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.167624 debug [handle_events] poll() returned 0
libusb: 0.424445 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.424750 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.424954 debug [handle_events] poll() returned 0
libusb: 0.430528 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.430853 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.431056 debug [handle_events] poll() returned 0
libusb: 0.436493 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.436828 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.437025 debug [handle_events] poll() returned 0
libusb: 0.442656 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.442952 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.443143 debug [handle_events] poll() returned 0
libusb: 0.448855 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.449146 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.449352 debug [handle_events] poll() returned 0
libusb: 0.454757 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.455088 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.455281 debug [handle_events] poll() returned 0
libusb: 0.460651 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.460971 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.461221 debug [handle_events] poll() returned 0
libusb: 0.466697 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.466999 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.467206 debug [handle_events] poll() returned 0
libusb: 0.473297 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.473578 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.473771 debug [handle_events] poll() returned 0
libusb: 0.479321 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.479623 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.479828 debug [handle_events] poll() returned 0
libusb: 0.485618 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.485932 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.486124 debug [handle_events] poll() returned 0
libusb: 0.491530 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.491828 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.492019 debug [handle_events] poll() returned 0
libusb: 0.497950 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.498243 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.498447 debug [handle_events] poll() returned 0
libusb: 0.504028 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.504428 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.504627 debug [handle_events] poll() returned 0
libusb: 0.510197 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.510486 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.510701 debug [handle_events] poll() returned 0
libusb: 0.516148 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.516568 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.516767 debug [handle_events] poll() returned 0
libusb: 0.522619 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.522900 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.523107 debug [handle_events] poll() returned 0
libusb: 0.528620 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.528933 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.529126 debug [handle_events] poll() returned 0
libusb: 0.534746 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.535079 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.535276 debug [handle_events] poll() returned 0
libusb: 0.540836 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.541162 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.541382 debug [handle_events] poll() returned 0
libusb: 0.547204 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.547493 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.547698 debug [handle_events] poll() returned 0
libusb: 0.553213 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.553502 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.553706 debug [handle_events] poll() returned 0
libusb: 0.559189 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.559494 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.559699 debug [handle_events] poll() returned 0
libusb: 0.565325 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.565631 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.565836 debug [handle_events] poll() returned 0
libusb: 0.571570 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.571847 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.572051 debug [handle_events] poll() returned 0
libusb: 0.577898 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.578212 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.578402 debug [handle_events] poll() returned 0
libusb: 0.583955 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.584316 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.584555 debug [handle_events] poll() returned 0
libusb: 0.590082 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.590370 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.590576 debug [handle_events] poll() returned 0
libusb: 0.596364 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.596654 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.596882 debug [handle_events] poll() returned 0
libusb: 0.602407 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.602704 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.602899 debug [handle_events] poll() returned 0
libusb: 0.608393 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.608713 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.608907 debug [handle_events] poll() returned 0
libusb: 0.614205 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.614756 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.614979 debug [handle_events] poll() returned 0
libusb: 0.620898 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.621240 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.621446 debug [handle_events] poll() returned 0
libusb: 0.626910 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.627224 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.627415 debug [handle_events] poll() returned 0
libusb: 0.633123 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.633412 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.633619 debug [handle_events] poll() returned 0
libusb: 0.639241 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.639555 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.639751 debug [handle_events] poll() returned 0
libusb: 0.645776 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.646076 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.646268 debug [handle_events] poll() returned 0
libusb: 0.651742 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.652029 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.652239 debug [handle_events] poll() returned 0
libusb: 0.658075 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.658385 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.658590 debug [handle_events] poll() returned 0
libusb: 0.664020 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.664405 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.664617 debug [handle_events] poll() returned 0
libusb: 0.670542 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.670863 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.671069 debug [handle_events] poll() returned 0
libusb: 0.676406 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.676721 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.676951 debug [handle_events] poll() returned 0
libusb: 0.682452 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.682743 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.682953 debug [handle_events] poll() returned 0
libusb: 0.688626 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.688936 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.689129 debug [handle_events] poll() returned 0
libusb: 0.695029 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.695333 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.695524 debug [handle_events] poll() returned 0
libusb: 0.700765 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.701121 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.701352 debug [handle_events] poll() returned 0
libusb: 0.706700 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.707010 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.707215 debug [handle_events] poll() returned 0
libusb: 0.712664 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.712969 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.713165 debug [handle_events] poll() returned 0
libusb: 0.719032 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.719342 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.719536 debug [handle_events] poll() returned 0
libusb: 0.725112 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.725437 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.725631 debug [handle_events] poll() returned 0
libusb: 0.731062 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.731349 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.731543 debug [handle_events] poll() returned 0
libusb: 0.737122 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.737436 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.737629 debug [handle_events] poll() returned 0
libusb: 0.743346 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.743734 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.743940 debug [handle_events] poll() returned 0
libusb: 0.749505 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.749856 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.750074 debug [handle_events] poll() returned 0
libusb: 0.755541 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.755860 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.756064 debug [handle_events] poll() returned 0
libusb: 0.761665 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.761963 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.762157 debug [handle_events] poll() returned 0
libusb: 0.767916 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.768219 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.768415 debug [handle_events] poll() returned 0
libusb: 0.774136 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.774517 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.774735 debug [handle_events] poll() returned 0
libusb: 0.780271 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.780570 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.780766 debug [handle_events] poll() returned 0
libusb: 0.786411 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.786724 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.786920 debug [handle_events] poll() returned 0
libusb: 0.792772 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.793063 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.793258 debug [handle_events] poll() returned 0
libusb: 0.798956 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.799262 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.799465 debug [handle_events] poll() returned 1
libusb: 0.799697 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.799886 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.800075 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.800250 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.800462 debug [disarm_timerfd]
libusb: 0.800602 debug [usbi_handle_transfer_completion] transfer 0x3a3cbc has callback 0xce98
Libusb version 1.0.9.0
Compiling "es2Shaders/DirtyBass.vert"...
Compiling Vertex Shader response follows:
Compiled
OK
Compiling "es2Shaders/DirtyBass.frag"...
Compiling Fragment Shader response follows:
Compiled
OK
     00:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.801138 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.806917 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.807234 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.807441 debug [handle_events] poll() returned 1
libusb: 0.807630 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.807818 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.807997 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.808168 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.808375 debug [disarm_timerfd]
libusb: 0.808512 debug [usbi_handle_transfer_completion] transfer 0x3a3dd4 has callback 0xce98
     00:00:
libusb: 0.808784 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.814624 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.814966 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.815158 debug [handle_events] poll() returned 1
libusb: 0.815461 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.815641 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.815829 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.816002 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.816207 debug [disarm_timerfd]
libusb: 0.816348 debug [usbi_handle_transfer_completion] transfer 0x3a3e9c has callback 0xce98
     00:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.816784 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.822894 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.823205 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.823400 debug [handle_events] poll() returned 1
libusb: 0.823603 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.823782 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.823972 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.824147 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.824457 debug [disarm_timerfd]
libusb: 0.824599 debug [usbi_handle_transfer_completion] transfer 0x3a3cbc has callback 0xce98
     00:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.825040 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.830765 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.831075 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.831271 debug [handle_events] poll() returned 1
libusb: 0.831463 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.831637 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.831821 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.831997 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.832200 debug [disarm_timerfd]
libusb: 0.832338 debug [usbi_handle_transfer_completion] transfer 0x3a3dd4 has callback 0xce98
     00:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.832774 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.838601 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.838943 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.839136 debug [handle_events] poll() returned 1
libusb: 0.839334 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.839511 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.839697 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.839869 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.840077 debug [disarm_timerfd]
libusb: 0.840216 debug [usbi_handle_transfer_completion] transfer 0x3a3e9c has callback 0xce98
     00:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.840657 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.846290 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.846604 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.846835 debug [handle_events] poll() returned 1
libusb: 0.847028 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.847215 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.847386 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.847660 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.847864 debug [disarm_timerfd]
libusb: 0.848002 debug [usbi_handle_transfer_completion] transfer 0x3a3fac has callback 0xce98
     64:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.848446 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.854595 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.854918 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.855127 debug [handle_events] poll() returned 1
libusb: 0.855324 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.855501 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.855675 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.855862 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.856070 debug [disarm_timerfd]
libusb: 0.856207 debug [usbi_handle_transfer_completion] transfer 0x3a40bc has callback 0xce98
     64:00:
libusb: 0.856478 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.862163 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.862457 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.862648 debug [handle_events] poll() returned 1
libusb: 0.862872 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.863050 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.863240 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.863413 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.863621 debug [disarm_timerfd]
libusb: 0.863759 debug [usbi_handle_transfer_completion] transfer 0x3a41dc has callback 0xce98
     64:00:
libusb: 0.864024 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.869733 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.870042 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.870249 debug [handle_events] poll() returned 1
libusb: 0.870449 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.870628 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.870842 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.871020 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.871223 debug [disarm_timerfd]
libusb: 0.871362 debug [usbi_handle_transfer_completion] transfer 0x3a3cbc has callback 0xce98
     00:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.871818 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.877510 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.877855 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.878074 debug [handle_events] poll() returned 1
libusb: 0.878263 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.878450 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.878623 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.878825 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.879022 debug [disarm_timerfd]
libusb: 0.879157 debug [usbi_handle_transfer_completion] transfer 0x3a3dd4 has callback 0xce98
     00:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.879609 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.885630 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.886024 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.886232 debug [handle_events] poll() returned 1
libusb: 0.886425 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.886619 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.886834 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.887014 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.887219 debug [disarm_timerfd]
libusb: 0.887361 debug [usbi_handle_transfer_completion] transfer 0x3a3e9c has callback 0xce98
     00:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.887818 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.893470 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.893779 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.894005 debug [handle_events] poll() returned 1
libusb: 0.894215 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.894499 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.894676 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.894889 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.895093 debug [disarm_timerfd]
libusb: 0.895233 debug [usbi_handle_transfer_completion] transfer 0x3a3fac has callback 0xce98
     64:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.895676 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.901364 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.901653 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.901858 debug [handle_events] poll() returned 1
libusb: 0.902048 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.902237 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.902412 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.902596 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.902799 debug [disarm_timerfd]
libusb: 0.902964 debug [usbi_handle_transfer_completion] transfer 0x3a40bc has callback 0xce98
     64:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.903412 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.909093 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.909441 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.909661 debug [handle_events] poll() returned 1
libusb: 0.909885 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.910086 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.910267 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.910451 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.910655 debug [disarm_timerfd]
libusb: 0.910827 debug [usbi_handle_transfer_completion] transfer 0x3a41dc has callback 0xce98
     64:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.911265 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.917152 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.917473 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.917666 debug [handle_events] poll() returned 1
libusb: 0.917869 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.918144 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.918330 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.918504 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.918716 debug [disarm_timerfd]
libusb: 0.918874 debug [usbi_handle_transfer_completion] transfer 0x3a3cbc has callback 0xce98
     00:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.919330 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.925206 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.925528 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.925756 debug [handle_events] poll() returned 1
libusb: 0.925978 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.926166 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.926358 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.926529 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.926743 debug [disarm_timerfd]
libusb: 0.926896 debug [usbi_handle_transfer_completion] transfer 0x3a3dd4 has callback 0xce98
     00:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.927346 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.933165 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.933482 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.933675 debug [handle_events] poll() returned 1
libusb: 0.933874 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.934049 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.934316 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.934529 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.934749 debug [disarm_timerfd]
libusb: 0.934902 debug [usbi_handle_transfer_completion] transfer 0x3a3e9c has callback 0xce98
     00:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.935362 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.940954 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.941284 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.941512 debug [handle_events] poll() returned 1
libusb: 0.941737 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.941956 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.942145 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.942328 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.942525 debug [disarm_timerfd]
libusb: 0.942662 debug [usbi_handle_transfer_completion] transfer 0x3a3fac has callback 0xce98
     64:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.943145 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.949108 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.949411 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.949617 debug [handle_events] poll() returned 1
libusb: 0.949818 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.949994 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.950168 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.950488 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.950711 debug [disarm_timerfd]
libusb: 0.950867 debug [usbi_handle_transfer_completion] transfer 0x3a40bc has callback 0xce98
     64:64: 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 00 00 00 00 00 00 00 00 00 00 00
libusb: 0.951316 debug [submit_iso_transfer] need 1 32k URBs for transfer
libusb: 0.956796 debug [libusb_handle_events_timeout_completed] doing our own event handling
libusb: 0.957167 debug [handle_events] poll() 3 fds with timeout in 0ms
libusb: 0.957406 debug [handle_events] poll() returned 1
libusb: 0.957626 debug [reap_for_handle] urb type=0 status=0 transferred=0
libusb: 0.957836 debug [handle_iso_completion] handling completion status 0 of iso urb 1/1
libusb: 0.958019 debug [handle_iso_completion] last URB in transfer --> complete!
libusb: 0.958214 debug [arm_timerfd_for_next_timeout] next timeout originally 2000ms
libusb: 0.958408 debug [disarm_timerfd]
libusb: 0.958545 debug [usbi_handle_transfer_completion] transfer 0x3a41dc has callback 0xce98


Thanks,
Josh
Posts: 3
Joined: Fri Jun 29, 2012 5:57 pm
by PaulBuxton » Tue Jul 03, 2012 9:35 am
Well I am afraid that pretty much exhausts my knowledge of libusb. :(

I would suggest perhaps initialising the buffer with something other than 0 just to check if it is is being updated with 0 rather than simply not being updated.

Other than that perhaps add some debug to the libusb library, and/or file a bug at the libusb project.
Posts: 57
Joined: Tue Jan 10, 2012 11:38 am
by axlecrusher » Thu Jul 05, 2012 1:15 pm
Yea I did initialize the buffer to 0xFF when I first found the problem just to make sure it wasn't receiving 0x00. The program displayed all 0xFF.

I tried changing from debian to arch linux and using libusbx, same result. I guess I will be debugging this for a while.

Thanks,
Josh
Posts: 3
Joined: Fri Jun 29, 2012 5:57 pm
by plugwash » Mon Jul 16, 2012 1:27 pm
sounds like a kernel bug to me, the USB driver for the Pi is well known for being poor.
Forum Moderator
Forum Moderator
Posts: 2244
Joined: Wed Dec 28, 2011 11:45 pm
by drspringfield » Sun Jul 28, 2013 8:38 am
Did anyone make any progress on debugging this? I'm having the same issue.
Posts: 2
Joined: Sun Jul 28, 2013 8:37 am
by BoS » Fri Nov 15, 2013 1:07 pm
Hi all,

I'm running the latest of everything and trying to use a libusb based driver that works on other Linux platforms ok. I'm using control and isochronous transfer. The control works just fine. However, looking through the libusb debug output, every isochronous urb comment says transferred=0

Any ideas what I can do to debug this further - any ideas why this is or whether this is still being worked on?

Thanks, BoS.
Posts: 11
Joined: Fri Nov 15, 2013 1:02 pm
by plugwash » Fri Nov 15, 2013 4:03 pm
Moving this to the "linux kernel" forum. Hopefully it will be more likely to get the attention of the right people there.
Forum Moderator
Forum Moderator
Posts: 2244
Joined: Wed Dec 28, 2011 11:45 pm
by BoS » Mon Nov 25, 2013 8:02 am
Hi all,

Can I assume from the silence that the USB driver development has stopped? Would I have more luck moving to the dwc2 driver? How would I do that? Any suggestions would be great so I can move my project forward.

Best regards,

BoS
Posts: 11
Joined: Fri Nov 15, 2013 1:02 pm