LIBUSB_TRANSFER_TIMED_OUT for stream transfers.

[PKM01]

Hi libusb team,

I'm currently utilizing libusb version 1.0.27 for stream transfer with my USB device (SanDisk SSD) on Ubuntu 22.04.4 LTS . Specifically, I'm sending an inquiry command to the UAS endpoints. While I can confirm that the command is successfully transmitted, unfortunately, I'm encountering an issue where I'm unable to receive the data in return. The error received is LIBUSB_TRANSFER_TIMED_OUT. I would greatly appreciate any insights or assistance regarding why the inquiry data isn't being received. Below I have provided the code, transfer logs and device information.

CODE:

#include <stdarg.h>
#include <stdbool.h>
#include <stdio.h>
#include <stdint.h>
#include <stdlib.h>
#include <string.h>
#include <time.h>

#include <libusb-1.0/libusb.h>


static void perr(char const *format, ...)
{
    va_list args;

    va_start (args, format);
    vfprintf(stderr, format, args);
    va_end(args);
}

#define ERR_EXIT(errcode) do { perr("   %s\n", libusb_strerror((enum libusb_error)errcode)); return -1; } while (0)
#define CALL_CHECK(fcall) do { int _r=fcall; if (_r < 0) ERR_EXIT(_r); } while (0)
#define CALL_CHECK_CLOSE(fcall, hdl) do { int _r=fcall; if (_r < 0) { libusb_close(hdl); ERR_EXIT(_r); } } while (0)
#define B(x) (((x)!=0)?1:0)
#define be_to_int32(buf) (((buf)[0]<<24)|((buf)[1]<<16)|((buf)[2]<<8)|(buf)[3])

#define RETRY_MAX                     5
#define INQUIRY_LENGTH                0x24

#define INTERFACE_NUMBER 0 
#define ALTERNATE_SETTING 1 

#define UAS_EP_COMMAND_OUT  0x04 
#define UAS_EP_STATUS_IN    0x83 
#define UAS_EP_DATA_IN      0x81 
#define UAS_EP_DATA_OUT     0x02 

// SCSI Inquiry command
#define SCSI_INQUIRY_OPCODE 0x12
#define SCSI_INQUIRY_ALLOCATION_LENGTH 0x24 


struct command_iu {
    uint8_t iu_id;
    uint8_t rsvd1;
    uint16_t tag;
    uint8_t prio_attr;
    uint8_t rsvd5;
    uint8_t len;
    uint8_t rsvd7;
    uint8_t lun[8]; 
    uint8_t cdb[16];
} __attribute__((__packed__));

static enum test_type {
    USE_GENERIC,
    USE_SCSI,
} test_mode;

static uint16_t VID, PID;

uint8_t inquiry_buffer[64];

static void LIBUSB_CALL inquiry_data_transfer_cb(struct libusb_transfer *transfer) {

    if (transfer->status == LIBUSB_TRANSFER_COMPLETED) {
        
        printf("Received %d bytes. Data in buffer:\n", transfer->actual_length);
        printf("\n");
        printf("    Peripheral Device Type: %02x\n", transfer->buffer[0] & 0x1F);
        printf("    Removable Media: %s\n", (transfer->buffer[1] & 0x80) ? "Yes" : "No");
        printf("    Version: %02x\n", transfer->buffer[2]);
        printf("    Vendor Identification: ");
        for (int i = 8; i < 16; ++i) printf("%c", transfer->buffer[i]);
        printf("\n");
        printf("    Product Identification: ");
        for (int i = 16; i < 32; ++i) printf("%c", transfer->buffer[i]);
        printf("\n");
        printf("    Product Revision Level: ");
        for (int i = 32; i < 36; ++i) printf("%c", transfer->buffer[i]);
        printf("\n");
        
    } else {
        fprintf(stderr, "Error receiving data: %s \n", libusb_error_name(transfer->status));
    }

    libusb_free_transfer(transfer);

}

static void LIBUSB_CALL inquiry_command_transfer_cb(struct libusb_transfer *transfer) {

    if (transfer->status == LIBUSB_TRANSFER_COMPLETED) {
        printf("\nInquiry command sent successfully\n");

        struct libusb_transfer *recv_transfer = libusb_alloc_transfer(0);
        if (!recv_transfer) {
            fprintf(stderr, "Failed to allocate receive transfer.\n");
            libusb_free_transfer(transfer);
            return;
        }

        memset(inquiry_buffer, 0, sizeof(inquiry_buffer));
        libusb_fill_bulk_stream_transfer(recv_transfer, transfer->dev_handle, UAS_EP_DATA_IN, 2, inquiry_buffer,
                                  sizeof(inquiry_buffer), inquiry_data_transfer_cb, NULL, 5000);

        int r;
        do {
            r = libusb_submit_transfer(recv_transfer);
        } while (r != LIBUSB_SUCCESS);

        if (r != LIBUSB_SUCCESS) {
            fprintf(stderr, "Failed to submit receive transfer.\n");
            libusb_free_transfer(recv_transfer);
        }
    } else {
        fprintf(stderr, "Error sending command: %s\n", libusb_error_name(transfer->status));
    }
}

int send_uas_command_async(libusb_device_handle *handle, uint8_t endpoint, uint8_t lun,
    uint8_t *cdb, int data_length, uint32_t *ret_tag) {
    
    static uint32_t tag = 1;
    uint8_t cdb_len;
    int i, r, size;
    struct command_iu cmd_iu;

    if (cdb == NULL) {
        return -1;
    }
    
    struct libusb_transfer *transfer = libusb_alloc_transfer(0);
    if (!transfer) return -1;

    memset(&cmd_iu, 0, sizeof(cmd_iu));
    cmd_iu.iu_id = 0x01;
    cmd_iu.rsvd1 = 0;
    cmd_iu.tag = 2;
    cmd_iu.prio_attr = 0;
    cmd_iu.rsvd5 = 0;
    cmd_iu.len = 0;
    cmd_iu.rsvd7 = 0;
    memset(cmd_iu.lun, 0, sizeof(cmd_iu.lun));
    memcpy(cmd_iu.cdb, cdb, 16);

    libusb_fill_bulk_stream_transfer(transfer, handle, endpoint, 0, 
        (unsigned char*)&cmd_iu, sizeof(cmd_iu), inquiry_command_transfer_cb, NULL, 1000);

    i = 0;
    do { 
        int r = libusb_submit_transfer(transfer);
        if (r == LIBUSB_ERROR_PIPE) {
            libusb_clear_halt(handle, endpoint);
        }
        i++;
    } while ((r == LIBUSB_ERROR_PIPE) && (i<RETRY_MAX));
    if (r != LIBUSB_SUCCESS) {
        perr("\nsend_uas_command_async: %s\n", libusb_strerror((enum libusb_error)r));
        return -1;
    }

    printf("\nsent %ld bytes\n", sizeof(cmd_iu));
    return 0;
}

int allocate_streams(libusb_device_handle *handle, unsigned char endpoint) {
    unsigned char endpoints[] = {0x81, 0x2, 0x83};
    uint32_t num_streams = 8;
    int r = libusb_alloc_streams(handle, num_streams, endpoints, sizeof(endpoints));
    if (r < 0) {
        fprintf(stderr, "Error allocating streams: %s\n", libusb_strerror((enum libusb_error)r));
        return -1;
    }
    return num_streams;
}

int free_streams(libusb_device_handle *handle, unsigned char endpoint) {
    unsigned char endpoints[] = {0x81, 0x2, 0x83   };
    int r = libusb_free_streams(handle, endpoints, sizeof(endpoints));
    if (r < 0) {
        fprintf(stderr, "Error freeing streams: %s\n", libusb_strerror((enum libusb_error)r));
        return -1;
    }
    return 0;
}


static int test_mass_storage(libusb_device_handle *handle, uint8_t endpoint_command, uint8_t endpoint_status, uint8_t endpoint_data_in, uint8_t endpoint_data_out)
{
    uint8_t lun;
    uint32_t expected_tag;
    uint8_t cdb[16];   

    printf("\nSending Inquiry");
    memset(cdb, 0, sizeof(cdb));
    cdb[0] = 0x12; 
    cdb[4] = 0x24;

    send_uas_command_async(handle, endpoint_command, lun, cdb, INQUIRY_LENGTH, &expected_tag);
    
    while (1) {
        libusb_handle_events_completed(NULL, NULL);
    `}`

    return 0;
}


static int test_device(uint16_t vid, uint16_t pid)
{
    libusb_device_handle *handle;
    int r;
    libusb_init(NULL);
    printf("Opening device %04X:%04X...\n", vid, pid);
    handle = libusb_open_device_with_vid_pid(NULL, vid, pid);
   
    if (handle == NULL) {
        perr("  Failed.\n");
        return -1;
    }

    libusb_set_option(NULL, LIBUSB_OPTION_LOG_LEVEL, LIBUSB_LOG_LEVEL_DEBUG);

    libusb_set_auto_detach_kernel_driver(handle, 1);

    printf("\nClaiming interface %d...\n", 0);
    r = libusb_claim_interface(handle, 0);
    if (r != LIBUSB_SUCCESS) {
        perr("   Failed (error %d) %s\n", r,
                libusb_strerror((enum libusb_error) r));
    }

    printf("\nSwitching to alternate interface %d...\n", 1);
    r = libusb_set_interface_alt_setting(handle, INTERFACE_NUMBER, ALTERNATE_SETTING);
    if (r < 0) {
        fprintf(stderr, "Failed to set alternate interface setting.\n");
        libusb_release_interface(handle, INTERFACE_NUMBER);
        libusb_close(handle);
        return -1;
    }

    uint32_t x = allocate_streams(handle, UAS_EP_DATA_IN);
    if (x < 0) {
        libusb_close(handle);               
        return 1;
    }
    printf("\n%d streams allocated..\n", x);

    switch(test_mode) {
    case USE_SCSI:
        test_mass_storage(handle, UAS_EP_COMMAND_OUT, UAS_EP_STATUS_IN, UAS_EP_DATA_IN, UAS_EP_DATA_OUT);
    case USE_GENERIC:
        break;
    }

    printf("\n");
    printf("Releasing interface %d...\n", 0);
    libusb_release_interface(handle, 0);

    printf("Closing device...\n");
    libusb_close(handle);

    return 0;
}

int main(int argc, char** argv)
{
    VID = 0x0781;
    PID = 0x55AE;
    test_mode = USE_SCSI;

    test_device(VID, PID);

    libusb_exit(NULL);

    return 0;
}

OUTPUT:

Opening device 0781:55AE...

Claiming interface 0...

Switching to alternate interface 1...

8 streams allocated..

Sending Inquiry
sent 32 bytes

Inquiry command sent successfully
Error receiving data: LIBUSB_TRANSFER_TIMED_OUT 

LOGS:

Opening device 0781:55AE...

Claiming interface 0...
[timestamp] [threadID] facility level [function call] <message>
--------------------------------------------------------------------------------
[ 0.002575] [000011c3] libusb: debug [libusb_claim_interface] interface 0

Switching to alternate interface 1...
[ 0.002598] [000011c3] libusb: debug [libusb_set_interface_alt_setting] interface 0 altsetting 1
[ 0.006073] [000011c3] libusb: debug [libusb_alloc_streams] streams 8 eps 3

8 streams allocated..

[ 0.006785] [000011c3] libusb: debug [libusb_submit_transfer] transfer 0x555a541443d0
[ 0.006792] [000011c3] libusb: debug [add_to_flying_list] arm timer for timeout in 1000ms (first in line)
[ 0.006802] [000011c3] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 32
Sending Inquiry
sent 32 bytes
[ 0.006827] [000011c3] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.006833] [000011c3] libusb: debug [handle_events] event sources modified, reallocating event data
[ 0.006840] [000011c3] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 0.006845] [000011c3] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 0.006851] [000011c3] libusb: debug [reap_for_handle] urb type=3 status=0 transferred=32
[ 0.006855] [000011c3] libusb: debug [handle_bulk_completion] handling completion status 0 of bulk urb 1/1
[ 0.006857] [000011c3] libusb: debug [handle_bulk_completion] all URBs in transfer reaped --> complete!
[ 0.006859] [000011c3] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 0.006862] [000011c3] libusb: debug [usbi_handle_transfer_completion] transfer 0x555a541443d0 has callback 0x555a529c8835

Inquiry command sent successfully
[ 0.006870] [000011c3] libusb: debug [libusb_submit_transfer] transfer 0x555a541444c0
[ 0.006873] [000011c3] libusb: debug [add_to_flying_list] arm timer for timeout in 5000ms (first in line)
[ 0.006876] [000011c3] libusb: debug [submit_bulk_transfer] need 1 urbs for new transfer with length 64
[ 0.006887] [000011c3] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.006892] [000011c3] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 5.007146] [000011c3] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 5.007184] [000011c3] libusb: debug [libusb_cancel_transfer] transfer 0x555a541444c0
[ 5.007278] [000011c3] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 5.007298] [000011c3] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 5.007304] [000011c3] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms
[ 5.007314] [000011c3] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 5.007323] [000011c3] libusb: debug [reap_for_handle] urb type=3 status=-2 transferred=0
[ 5.007329] [000011c3] libusb: debug [handle_bulk_completion] handling completion status -2 of bulk urb 1/1
[ 5.007334] [000011c3] libusb: debug [handle_bulk_completion] abnormal reap: urb status -2
[ 5.007339] [000011c3] libusb: debug [handle_bulk_completion] abnormal reap: last URB handled, reporting
[ 5.007345] [000011c3] libusb: debug [usbi_handle_transfer_cancellation] detected timeout cancellation
[ 5.007355] [000011c3] libusb: debug [arm_timer_for_next_timeout] no timeouts, disarming timer
[ 5.007364] [000011c3] libusb: debug [usbi_handle_transfer_completion] transfer 0x555a541444c0 has callback 0x555a529c863c
Error receiving data: LIBUSB_TRANSFER_TIMED_OUT 
[ 5.007397] [000011c3] libusb: debug [libusb_free_transfer] transfer 0x555a541444c0
[ 5.007411] [000011c3] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 5.007419] [000011c3] libusb: debug [usbi_wait_for_events] poll() 3 fds with timeout in 60000ms

DEVICE INFOMATION:

Bus 002 Device 002: ID 0781:55ae SanDisk Corp. Extreme 55AE
Couldn't open device, some information will be missing
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               3.20
  bDeviceClass            0 
  bDeviceSubClass         0 
  bDeviceProtocol         0 
  bMaxPacketSize0         9
  idVendor           0x0781 SanDisk Corp.
  idProduct          0x55ae 
  bcdDevice           80.54
  iManufacturer           2 SanDisk
  iProduct                3 Extreme 55AE
  iSerial                 1 32323232305A363431353133
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength       0x0079
    bNumInterfaces          1
    bConfigurationValue     1
    iConfiguration          0 
    bmAttributes         0x80
      (Bus Powered)
    MaxPower              896mA
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           2
      bInterfaceClass         8 Mass Storage
      bInterfaceSubClass      6 SCSI
      bInterfaceProtocol     80 Bulk-Only
      iInterface              0 
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0400  1x 1024 bytes
        bInterval               0
        bMaxBurst              15
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x02  EP 2 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0400  1x 1024 bytes
        bInterval               0
        bMaxBurst              15
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       1
      bNumEndpoints           4
      bInterfaceClass         8 Mass Storage
      bInterfaceSubClass      6 SCSI
      bInterfaceProtocol     98 
      iInterface              0 
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0400  1x 1024 bytes
        bInterval               0
        bMaxBurst              15
        MaxStreams             32
        Data-in pipe (0x03)
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x02  EP 2 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0400  1x 1024 bytes
        bInterval               0
        bMaxBurst              15
        MaxStreams             32
        Data-out pipe (0x04)
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x83  EP 3 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0400  1x 1024 bytes
        bInterval               0
        bMaxBurst              15
        MaxStreams             32
        Status pipe (0x02)
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x04  EP 4 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0400  1x 1024 bytes
        bInterval               0
        bMaxBurst               0
        Command pipe (0x01)

[tormodvolden]

I'm unable to receive the data in return

Are you sure the device is returning anything and not just bailing out?

[PKM01]

I observed the packet transfer on Teledyne LeCroy. The command is transmitted successfully, followed by the device sending an acknowledgment. To receive data from the device, the host must then send an acknowledgment with particular stream id back to the device. However, in this instance, the host isn't sending the acknowledgment to the device. Additionally, I utilized the synchronous API libusb_bulk_transfer to send the same command, and it functions properly with the device returning the correct inquiry data.