FTDI USB compatibility

[rpasek]

Hello! I've been trying to get an FTDI FT4232H (which is a 4 port version of the very common FT232) working with WSL 2 with windows being the server of the FT4232H and Ubuntu 18.04 LTS (kernel 4.19.43-microsoft-standard) as the client (although I don't think that WSL 2 is a source of this bug at this point (I'll elaborate on this a bit more further down)).

A little backstory: WSL 2 does not have USB support so I've been trying to add it back in. Adding in USB support in WSL 2 would solve probably the most major issue with WSL 2. The usbip-win project has the ability to solve this. I've been successful at compiling the usbip kernel modules in 4.19.43-microsoft-standard and modprobing them all in. I've been successful using this repo to host a CDC-ACM device on Windows and was able to use the compiled kernel modules to allow this CDC-ACM device to exist on Linux and I'm able to communicate with the CDC-ACM device with no issues.

When attempting to host the FT4232H in Windows and trying to attach to the device in Linux I get these messages in dmesg:

[  544.218303] usb 1-1: new high-speed USB device number 2 using vhci_hcd
[  544.368397] usb 1-1: SetAddress Request (2) to port 0
[  544.410263] ftdi_sio 1-1:1.0: FTDI USB Serial Device converter detected
[  544.410294] usb 1-1: Detected FT4232H
[  549.488900] vhci_hcd: unlink->seqnum 11
[  549.488902] vhci_hcd: urb->status -1
[  549.488983] ftdi_sio ttyUSB0: Unable to read latency timer: -110

I get this message repeated 4 times, 1 for each FTDI port. I'm unable to interact with any of these devices. All interactions time out and no data is sent to the FTDI device. I suspect although I have no proof that no data is being sent or received on endpoint 0.

When starting usbip --debug in Windows this is displayed:

usbip: info: exportable devices: 1
usbip: debug: C:\Users\rpasek\Documents\usbip-win\userspace\lib\usbip_common.c:90:[dump_usb_device] path                 = \\?\usb#vid_0403&pid_6011#7&98cdda5&0&3#{fb265267-c609-41e6-8eca-a20d92a833e6}
usbip: debug: C:\Users\rpasek\Documents\usbip-win\userspace\lib\usbip_common.c:91:[dump_usb_device] busid                = 1-176
usbip: debug: C:\Users\rpasek\Documents\usbip-win\userspace\lib\usbip_common.c:97:[dump_usb_device] Device(C/SC/P)       = (Defined at Interface level) (00/00/00)
usbip: debug: C:\Users\rpasek\Documents\usbip-win\userspace\lib\usbip_common.c:99:[dump_usb_device] bcdDevice            = 0
usbip: debug: C:\Users\rpasek\Documents\usbip-win\userspace\lib\usbip_common.c:104:[dump_usb_device] Vendor/Product       = unknown vendor : unknown product (0403:6011)
usbip: debug: C:\Users\rpasek\Documents\usbip-win\userspace\lib\usbip_common.c:106:[dump_usb_device] bNumConfigurations   = 0
usbip: debug: C:\Users\rpasek\Documents\usbip-win\userspace\lib\usbip_common.c:107:[dump_usb_device] bNumInterfaces       = 0
usbip: debug: C:\Users\rpasek\Documents\usbip-win\userspace\lib\usbip_common.c:109:[dump_usb_device] speed                = High Speed(480Mbps)
usbip: debug: C:\Users\rpasek\Documents\usbip-win\userspace\lib\usbip_common.c:111:[dump_usb_device] busnum               = 1
usbip: debug: C:\Users\rpasek\Documents\usbip-win\userspace\lib\usbip_common.c:112:[dump_usb_device] devnum               = b0
usbip: info: request 0x8005: complete
usbip: info: connection from 172.18.186.174:42598
usbip: info: received request: 0x8003
usbip: debug: C:\Users\rpasek\Documents\usbip-win\userspace\src\usbipd\usbipd_import.c:18:[forwarder_stub] stub forwarding started
usbip: debug: C:\Users\rpasek\Documents\usbip-win\userspace\src\usbipd\usbipd_import.c:108:[recv_request_import] import request busid 1-176: complete
usbip: info: request 0x8003: complete

I find it a little concerning that no interfaces or configurations are found. Maybe this could be related? Update: I found this is true for other devices that function fine, so probably unrelated.

To prove that this issue is most certainly with the Windows instance of USBIP driver and not with WSL 2, I hosted the same FTDI device with usbip on native Linux machine and I'm able to connect to the FTDI device with no issues in the hosted WSL 2 Ubuntu environment.

More on WSL 2: (https://devblogs.microsoft.com/commandline/wsl-2-is-now-available-in-windows-insiders/)

Please let me know if this is something you'd have interest in fixing or if you'd like to have help fixing!

Update: I attempted to us a FT232 (the single port FTDI device) and I seem to have the same results.

Thanks, Richard

[cezuni]

To check the problem of stub driver, windows kernel logs would be helpful. Please refer to https://github.com/cezuni/usbip-win/issues/25#issuecomment-511111291

[rpasek]

Thanks for the info!

When attaching things seem ok except for:

00000146    163.32231140    usbip_stub:(EE) not supported:usbip_stub: stub_dispatch: IRP_MJ_WRITE: Enter    
00000147    163.32231140    usbip_stub: dispatch_write: hdr: cmd:USBIP_CMD_UNLINK,seq:12,out,ep:0,unlinkseq:11  
00000148    163.32231140    usbip_stub: process_cmd_unlink: enter   
00000149    163.32235718    usbip_stub: stub_dispatch: IRP_MJ_READ: Enter   
00000150    163.32235718    usbip_stub: dispatch_read: enter    
00000151    163.32269287    usbip_stub: stub_dispatch: IRP_MJ_WRITE: Enter  
00000152    163.32269287    usbip_stub: dispatch_write: hdr: cmd:USBIP_CMD_SUBMIT,seq:13,out,ep:0,tlen:0,intv:0 
00000153    163.32270813    usbip_stub: control_transfer: seq:13, csp:out,BMREQUEST_VENDOR,BMREQUEST_TO_DEVICE,USB_REQUEST_SET_CONFIGURATION,wIndex:0,wLength:0,wValue:16   

When I open screen on /dev/ttyUSB0 but type no characters I see this pattern quickly repeated:

00021990    261.18692017    usbip_stub: send_stub_res: partially sent: 0 < 2: seq:1587,data_len:2   
00021991    261.18698120    usbip_stub: stub_dispatch: IRP_MJ_READ: Enter   
00021992    261.18698120    usbip_stub: dispatch_read: enter    
00021993    261.18701172    usbip_stub: send_stub_res: sent: cmd:USBIP_RET_SUBMIT,seq:1587,out,ep:0,alen:2  
00021994    261.18713379    usbip_stub: stub_dispatch: IRP_MJ_READ: Enter   
00021995    261.18713379    usbip_stub: dispatch_read: enter    
00021996    261.18804932    usbip_stub: stub_dispatch: IRP_MJ_WRITE: Enter  
00021997    261.18804932    usbip_stub: dispatch_write: hdr: cmd:USBIP_CMD_SUBMIT,seq:1589,in,ep:1,tlen:512,intv:0  
00021998    261.18804932    usbip_stub: bulk_intr_transfer: seq:1589, ep:epaddr:81  
00021999    261.18807983    usbip_stub: call_usbd_nb: enter 
00022000    261.18807983    usbip_stub: call_usbd_nb: call_usbd_nb: seq:1589,data_len:512   
00022001    261.18811035    usbip_stub: call_usbd_nb: status = STATUS_PENDING   
00022002    261.20285034    usbip_stub: do_safe_completion: status = USBD_STATUS_SUCCESS    
00022003    261.20288086    usbip_stub: done_bulk_intr_transfer: sres:seq:1588,data_len:512,status:STATUS_SUCCESS,usbd_status:USBD_STATUS_SUCCESS   

I'll look into what "(EE) not supported" means to familiarize myself with what is going on.

Thanks, Richard

[rpasek]

I took a look at line 207 in stub_write.c and found:

    case BMREQUEST_VENDOR:
        DBGE(DBG_READWRITE, "not supported:", dbg_cspkt_reqtype(reqType));
        break;

As an experiment I changed it to:

    case BMREQUEST_VENDOR:
        process_class_request(devstub, csp, hdr);
        DBGE(DBG_READWRITE, "maybe supported:", dbg_cspkt_reqtype(reqType));
        break;

and I got much further. In dmesg after attach I see:

[ 7733.596405] ftdi_sio 1-1:1.0: FTDI USB Serial Device converter detected
[ 7733.596437] usb 1-1: Detected FT232RL
[ 7733.597818] ftdi_sio ttyUSB0: Unable to read latency timer: -1
[ 7733.598888] ftdi_sio ttyUSB0: Unable to write latency timer: -1
[ 7733.599094] usb 1-1: FTDI USB Serial Device converter now attached to ttyUSB0

Now in screen I can send and receive on the FTDI device using the default baud rate. When the baud rate is changed however I get this in dmesg:

[ 7788.989553] ftdi_sio ttyUSB0: ftdi_set_termios FAILED to set databits/stopbits/parity
[ 7788.990295] ftdi_sio ttyUSB0: ftdi_set_termios urb failed to set baudrate
[ 7788.990954] ftdi_sio ttyUSB0: failed to set flow control: -1
[ 7788.992480] ftdi_sio ttyUSB0: failed to get modem status: -1
[ 7788.993173] ftdi_sio ttyUSB0: ftdi_set_termios urb failed to set baudrate
[ 7788.993848] ftdi_sio ttyUSB0: failed to set flow control: -1
[ 7788.994577] ftdi_sio ttyUSB0: failed to get modem status: -1
[ 7880.588650] ftdi_sio ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32

It seems to me that the reason why this is not working is we are not handling BMREQUEST_VENDOR. Simply sending bad data to the device allows us to continue in a broken state but it's still progress. How would we go about adding proper support for this?

Thanks, Richard

[cezuni]

@rpasek : You're going well.. 😄 I guess that I had not implemented vendor request because I don't have such a device.. Treating vendor request seems to be much like class request. But process_class_request() should be slightly changed such as that URB_FUNCTION_CLASS_DEVICE -> URB_FUNCION_VENDOR_DEVICE. Will you try this? I bet that you can make it!

[rpasek]

Thanks! I attempted this earlier today and it works well! I don't have much experience using github but I have a branch I'd like to push and create a pull request for. Can you give me access to push a branch or should I fork and then inform you of the branch?

If not here is the code I changed:

static void
process_class_request(usbip_stub_dev_t *devstub, usb_cspkt_t *csp, struct usbip_header *hdr, BOOLEAN vendorreq)
{
    PVOID   data;
    ULONG   datalen;
    USHORT  cmd;
    UCHAR   reservedBits;
    unsigned long   seqnum;
    BOOLEAN is_in, res;

    datalen = hdr->u.cmd_submit.transfer_buffer_length;
    if (datalen == 0)
        data = NULL;
    else
        data = (PVOID)(hdr + 1);

    is_in = csp->bmRequestType.Dir ? TRUE : FALSE;

    switch (csp->bmRequestType.Recipient) {
    case BMREQUEST_TO_DEVICE:
        cmd = vendorreq ? URB_FUNCTION_VENDOR_DEVICE : URB_FUNCTION_CLASS_DEVICE;
        break;
    case BMREQUEST_TO_INTERFACE:
        cmd = vendorreq ? URB_FUNCTION_VENDOR_INTERFACE : URB_FUNCTION_CLASS_INTERFACE;
        break;
    case BMREQUEST_TO_ENDPOINT:
        cmd = vendorreq ? URB_FUNCTION_VENDOR_ENDPOINT : URB_FUNCTION_CLASS_ENDPOINT;
        break;
    default:
        cmd = vendorreq ? URB_FUNCTION_VENDOR_OTHER : URB_FUNCTION_CLASS_OTHER;
        break;
    }

    reservedBits = csp->bmRequestType.Reserved;
    seqnum = hdr->base.seqnum;
    res = submit_class_vendor_req(devstub, is_in, cmd, reservedBits, csp->bRequest, csp->wValue.W, csp->wIndex.W, data, &datalen);
    if (res) {
        if (is_in)
            reply_stub_req_data(devstub, seqnum, data, datalen, TRUE);
        else
            reply_stub_req_hdr(devstub, USBIP_RET_SUBMIT, seqnum);
    }
    else
        reply_stub_req_err(devstub, USBIP_RET_SUBMIT, seqnum, -1);
}

static void
process_control_transfer(usbip_stub_dev_t *devstub, struct usbip_header *hdr)
{
    usb_cspkt_t *csp;
    UCHAR       reqType;

    csp = (usb_cspkt_t *)hdr->u.cmd_submit.setup;

    DBGI(DBG_READWRITE, "control_transfer: seq:%u, csp:%s\n", hdr->base.seqnum, dbg_ctlsetup_packet(csp));

    reqType = CSPKT_REQUEST_TYPE(csp);
    switch (reqType) {
    case BMREQUEST_STANDARD:
        process_standard_request(devstub, hdr->base.seqnum, csp);
        break;
    case BMREQUEST_CLASS:
        process_class_request(devstub, csp, hdr, FALSE);
        break;
    case BMREQUEST_VENDOR:
        process_class_request(devstub, csp, hdr, TRUE);
        break;
    default:
        DBGE(DBG_READWRITE, "invalid request type:", dbg_cspkt_reqtype(reqType));
        break;
    }
}

[cezuni]

@rpasek :

Can you give me access to push a branch or should I fork and then inform you of the branch?

Both would be fine. I added you as collaborator. You can create a branch or commit to existing branch.

[rpasek]

Thanks! I've created a PR against master.