Menu
▾
▴
[Libusb-devel] usbfs: usb_submit_urb returned -121
|
From: Ludovic R. <lud...@gm...> - 2010-06-24 13:48:48
|
Hello, I try to stress my code by sending the same command on a loop. But I may be hit by a kernel bug or libusb bug. I am using libusb git version up-to-date and kernel 2.6.34-1-686 or vmlinuz-2.6.32-5-686 (from Debian). Both kernels have the problem. libusb returns -99 (LIBUSB_ERROR_OTHER) and the kernel logs a line in /var/log/syslog: Jun 24 15:08:01 trinity kernel: [ 299.676480] usb 3-1.3: usbfs: usb_submit_urb returned -121 I also used my previous kernel 2.6.26-2-686 from Debian stable and libusb-1.0.8 and I DO NOT have the problem. So it looks a bug in the recent kernels or in the way libusb is using the kernel. Is it a known issue? Is it already solved in 2.6.35-rc3? What can I do to help find the bug (easy to reproduce for me)? Now some logs and traces. Trace from my application with libusb debug: 00000032 ifdhandler.c:1340:IFDHControl() ControlCode: 0x42000001, usb:08e6/3437:libhal:/org/freedesktop/Hal/devices/usb_device_8e6_3437_noserial_if0 (lun: 0) 00000010 Control TxBuffer: 02 00000014 -> 000000 6B 01 00 00 00 00 E4 00 00 00 02 libusb:debug [submit_bulk_transfer] need 1 urbs for new transfer with length 11 libusb:debug [libusb_submit_transfer] arm timerfd for timeout in 5000ms (first in line) libusb:debug [libusb_handle_events_timeout] another thread is doing event handling libusb:debug [handle_events] poll() returned 1 libusb:debug [reap_for_handle] urb type=3 status=0 transferred=11 libusb:debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1 libusb:debug [handle_bulk_completion] last URB in transfer --> complete! libusb:debug [arm_timerfd_for_next_timeout] next timeout originally 3600000ms libusb:debug [bulk_transfer_cb] actual_length=11 libusb:debug [handle_events] poll() 5 fds with timeout in 60000ms libusb:debug [libusb_handle_events_timeout] another thread is doing event handling libusb:debug [libusb_handle_events_timeout] another thread is doing event handling libusb:debug [submit_bulk_transfer] need 5 urbs for new transfer with length 65556 libusb:debug [libusb_submit_transfer] arm timerfd for timeout in 30000ms (first in line) libusb:debug [libusb_handle_events_timeout] another thread is doing event handling libusb:debug [handle_events] poll() returned 1 libusb:debug [reap_for_handle] urb type=3 status=-121 transferred=28 libusb:debug [handle_bulk_completion] handling completion status -121 of bulk urb 1/5 libusb:debug [handle_bulk_completion] short transfer 28/16384 --> complete! libusb:debug [handle_events] poll() 5 fds with timeout in 60000ms libusb:debug [libusb_handle_events_timeout] another thread is doing event handling libusb:debug [handle_events] poll() returned 1 libusb:debug [libusb_handle_events_timeout] another thread is doing event handling libusb:debug [reap_for_handle] libusb:debug [libusb_handle_events_timeout] another thread is doing event handling urb type=3 status=-104 transferred=0 libusb:debug [handle_bulk_completion] handling completion status -104 of bulk urb 2/5 libusb:debug [handle_bulk_completion] abnormal reap: urb status -104 libusb:debug [handle_events] libusb:debug [libusb_handle_events_timeout] another thread is doing event handling poll() 5 fds with timeout in 60000ms libusb:debug [handle_events] poll() returned 1 libusb:debug [reap_for_handle] urb type=3 status=-104 transferred=0 libusb:debug [handle_bulk_completion] handling completion status -104 of bulk urb 3/5 libusb:debug [handle_bulk_completion] abnormal reap: urb status -104 libusb:debug [handle_events] poll() 5 fds with timeout in 60000ms libusb:debug [handle_events] poll() returned 1 libusb:debug [reap_for_handle] urb type=3 status=-104 transferred=0 libusb:debug [handle_bulk_completion] handling completion status -104 of bulk urb 4/5 libusb:debug [handle_bulk_completion] abnormal reap: urb status -104 libusb:debug [handle_events] poll() 5 fds with timeout in 60000ms libusb:debug [handle_events] poll() returned 1 libusb:debug [reap_for_handle] urb type=3 status=-104 transferred=0 libusb:debug [handle_bulk_completion] handling completion status -104 of bulk urb 5/5 libusb:debug [handle_bulk_completion] abnormal reap: urb status -104 libusb:debug [handle_bulk_completion] abnormal reap: last URB handled, reporting libusb:debug [arm_timerfd_for_next_timeout] next timeout originally 3600000ms libusb:debug [bulk_transfer_cb] actual_length=28 libusb:debug [handle_events] poll() 5 fds with timeout in 60000ms libusb:debug [libusb_handle_events_timeout] another thread is doing event handling libusb:debug [libusb_handle_events_timeout] another thread is doing event handling 00026025 <- 000000 83 12 00 00 00 00 E4 02 00 00 47 65 6D 54 77 69 6E 2D 56 32 2E 30 30 2D 47 46 30 33 00000024 Control RxBuffer: 47 65 6D 54 77 69 6E 2D 56 32 2E 30 30 2D 47 46 30 33 The first command stops here and all went well. 00000015 winscard_svc.c:691:ContextThread() CONTROL rv=0x0 for client 12 00000605 winscard_svc.c:309:ContextThread() Received command: CONTROL from client 12 00000051 ifdhandler.c:1340:IFDHControl() ControlCode: 0x42000001, usb:08e6/3437:libhal:/org/freedesktop/Hal/devices/usb_device_8e6_3437_noserial_if0 (lun: 0) 00000014 Control TxBuffer: 02 00000020 -> 000000 6B 01 00 00 00 00 E5 00 00 00 02 libusb:debug [submit_bulk_transfer] need 1 urbs for new transfer with length 11 libusb:debug [libusb_submit_transfer] arm timerfd for timeout in 5000ms (first in line) libusb:debug [libusb_handle_events_timeout] another thread is doing event handling libusb:debug [handle_events] poll() returned 1 libusb:debug [reap_for_handle] urb type=3 status=0 transferred=11 libusb:debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1 libusb:debug [handle_bulk_completion] last URB in transfer --> complete! libusb:debug [arm_timerfd_for_next_timeout] next timeout originally 3600000ms libusb:debug [bulk_transfer_cb] actual_length=11 libusb:debug [handle_events] poll() 5 fds with timeout in 60000ms libusb:debug [libusb_handle_events_timeout] another thread is doing event handling libusb:debug [libusb_handle_events_timeout] another thread is doing event handling libusb:debug [submit_bulk_transfer] need 5 urbs for new transfer with length 65556 libusb:debug [handle_events] poll() returned 1 libusb:debug [reap_for_handle] urb type=3 status=-121 transferred=28 libusb:error [submit_bulk_transfer] submiturb failed error -1 errno=121 libusb:debug [submit_bulk_transfer] reporting successful submission but waiting for 4 discards before reporting error libusb:debug [libusb_submit_transfer] arm timerfd for timeout in 30000ms (first in line) libusb:debug [handle_bulk_completion] handling completion status -121 of bulk urb 1/5 libusb:debug [handle_bulk_completion] abnormal reap: urb status -121 libusb:debug [handle_bulk_completion] received 28 bytes of surplus data libusb:debug [handle_events] poll() 5 fds with timeout in 60000ms libusb:debug [handle_events] poll() returned 1 libusb:debug [reap_for_handle] urb type=3 status=-104 transferred=0 libusb:debug [handle_bulk_completion] handling completion status -104 of bulk urb 2/5 libusb:debug [handle_bulk_completion] abnormal reap: urb status -104 libusb:debug [handle_events] poll() 5 fds with timeout in 60000ms libusb:debug [handle_events] poll() returned 1 libusb:debug [reap_for_handle] urb type=3 status=-104 transferred=0 libusb:debug [handle_bulk_completion] handling completion status -104 of bulk urb 3/5 libusb:debug [handle_bulk_completion] abnormal reap: urb status -104 libusb:debug [handle_events] poll() 5 fds with timeout in 60000ms libusb:debug [handle_events] poll() returned 1 libusb:debug [reap_for_handle] urb type=3 status=-104 transferred=0 libusb:debug [handle_bulk_completion] handling completion status -104 of bulk urb 4/5 libusb:debug [handle_bulk_completion] abnormal reap: urb status -104 libusb:debug [handle_bulk_completion] abnormal reap: last URB handled, reporting libusb:debug [arm_timerfd_for_next_timeout] next timeout originally 3600000ms libusb:debug [bulk_transfer_cb] actual_length=28 libusb:debug [handle_events] poll() 5 fds with timeout in 60000ms libusb:debug [libusb_handle_events_timeout] another thread is doing event handling libusb:debug [libusb_handle_events_timeout] another thread is doing event handling libusb:warning [do_sync_bulk_transfer] unrecognised status code 1 00004072 ccid_usb.c:648:ReadUSB() read failed (3/5): -99 Invalid argument 00000015 Control RxBuffer: This second same command failed. libusb returns -99 (LIBUSB_ERROR_OTHER) and the kernel logs a line in /var/log/syslog: Jun 24 15:08:01 trinity kernel: [ 299.676480] usb 3-1.3: usbfs: usb_submit_urb returned -121 According to a previous message [1] on this list: "With libusb-1.0.6 and linux-2.6.32rc6, it scans in low resolution. In high resolution it scans several lines and hangs and complies to syslog: "usbfs: usb_submit_urb returned -121" According to the documentation, it is caused by URB_SHORT_NOT_OK. " As explained in the message I generated a usbmon trace: f0141500 2572976529 S Bo:3:005:2 -115 11 = 6b010000 0000e400 000002 f0141500 2572977025 C Bo:3:005:2 0 11 > f0141c80 2572977228 S Bi:3:005:2 -115 16384 < f0141c00 2572977267 S Bi:3:005:2 -115 16384 < f0141180 2572977305 S Bi:3:005:2 -115 16384 < f0141780 2572977344 S Bi:3:005:2 -115 16384 < f0141480 2572977385 S Bi:3:005:2 -115 20 < f0141c80 2572978068 C Bi:3:005:2 -121 28 = 83120000 0000e402 00004765 6d547769 6e2d5632 2e30302d 47463033 f0141c00 2572978119 C Bi:3:005:2 -104 0 f0141180 2572978168 C Bi:3:005:2 -104 0 f0141780 2572978212 C Bi:3:005:2 -104 0 f0141480 2572978213 C Bi:3:005:2 -104 0 The first command with no error f01a7800 2573003416 S Bo:3:005:2 -115 11 = 6b010000 0000e500 000002 f01a7800 2573005031 C Bo:3:005:2 0 11 > f01a7800 2573005562 S Bi:3:005:2 -115 16384 < f01a7f80 2573005634 S Bi:3:005:2 -115 16384 < f01a7c80 2573005862 S Bi:3:005:2 -115 16384 < f01a7500 2573005928 S Bi:3:005:2 -115 16384 < f01a7800 2573006073 C Bi:3:005:2 -121 28 = 83120000 0000e502 00004765 6d547769 6e2d5632 2e30302d 47463033 f01a7f80 2573006134 C Bi:3:005:2 -104 0 f01a7c80 2573006190 C Bi:3:005:2 -104 0 f01a7500 2573006251 C Bi:3:005:2 -104 0 The second command with an error reported by the kernel. But I can't find any difference with the previous and successful command, except a line is missing at the end. I also suspected my device so I also tried on Mac OS X (Snow Leopard and libusb-1.0.8) but can't reproduce the problem. [1] http://libusb.6.n5.nabble.com/libusb-compat-x-libusb0-new-incompatibility-long-request-short-transfer-Brother-scanner-td8697.html#a8697 -- Dr. Ludovic Rousseau |
