Message-ID: <ZeZPLX6z5pyn2Eh_@mail-itl>
Date: Mon, 4 Mar 2024 23:46:04 +0100
From: Marek Marczykowski-Górecki <marmarek@...isiblethingslab.com>
To: Greg KH <gregkh@...uxfoundation.org>
Cc: Demi Marie Obenour <demi@...isiblethingslab.com>,
	linux-usb@...r.kernel.org,
	Linux Kernel Mailing List <linux-kernel@...r.kernel.org>
Subject: Re: usbip doesn't work with userspace code that accesses USB devices

On Mon, Mar 04, 2024 at 09:04:00PM +0000, Greg KH wrote:
> On Mon, Mar 04, 2024 at 03:01:51PM -0500, Demi Marie Obenour wrote:
> > Qubes OS users are reporting that MTP doesn't work with USB passthrough.
> > Fastboot (used for flashing a custom OS to an Android device) also
> > doesn't work.  Kernel-mode drivers, such as Bluetooth and USB storage,
> > seem to usually work as expected.  Since MTP and fastboot are both
> > implemented in userspace, it appears that there is some problem with the
> > interaction of usbip, our USB proxy (which is based on USBIP), and
> > userspace programs that interact with USB devices directly.
> > 
> > The bug report can be found at [1] and the source code for the USB proxy
> > can be found at [2].  The script used on the sending side (the one with
> > the physical USB controller) is at [3] and the script used by the
> > receiving side (the one the device is attached to) is at [4].  All of
> > these links are for the current version as of this email being sent, so
> > that anyone looking at this email in the future doesn't get confused.
> > 
> > Is this a bug in usbip, or is this due to usbip being used incorrectly?
> 
> I'm amazed that usbip works with usbfs at all, I didn't think that was a
> thing.
> 
> If you have a reproducer, or some error messages somewhere, that might
> be the easiest way forward.  In reading the bug report, it looks like
> the "bridge" you all made can't handle the device disconnecting itself
> properly?  But that's just a guess, could be anything.

Device disconnecting itself indeed is an issue (our proxy doesn't
automatically reconnect it, at least not yet). But that's definitely not
the only issue, things break also when disconnect is not involved.

Terminology:
1. sys-usb - a VM where USB controller (a PCI device) lives; here
usbip-host is attached to the device
2. testvm - target VM where usbip is connected; here vhci-hcd is used
3. qvm-usb - tool that connects the above two (equivalent of
userspace part of standard usbip)

Specific steps:
1. Connect android phone - at this point it's only in sys-usb
2. Switch its mode to file transfer - observe reconnect in sys-usb
3. Use qvm-usb to attach it to the testvm
4. Call jmtpfs -d /mnt in testvm


It fails this way:

    Device 0 (VID=18d1 and PID=4ee1) is a Google Inc Nexus/Pixel (MTP).
    PTP_ERROR_IO: failed to open session, trying again after resetting USB interface
    LIBMTP libusb: Attempt to reset device
    LIBMTP PANIC: failed to open session on second attempt
    Cannot open requested device

There is a short wait before first failure and then the reset fails as
well (interestingly, device doesn't actually reset, it stays connected).

At that time, testvm's dmesg shows:

    [2126560.758005] vhci_hcd: unlink->seqnum 98
    [2126560.758025] vhci_hcd: urb->status -104
    [2126560.872413] usb 1-1: reset high-speed USB device number 3 using vhci_hcd
    [2126560.992995] usb 1-1: SetAddress Request (3) to port 0
    [2126561.162264] usb 1-1: reset high-speed USB device number 3 using vhci_hcd
    [2126561.278584] usb 1-1: SetAddress Request (3) to port 0

And sys-usb's dmesg:

    [915567.691431] usbip-host 2-1: unlinked by a call to usb_unlink_urb()

I've observed it also with wireshark in testvm, and there is a single packet sent (before the attempt to reset):

    Frame 90: 80 bytes on wire (640 bits), 80 bytes captured (640 bits) on interface usbmon1, id 0
    USB URB
        [Source: host]
        [Destination: 1.3.1]
        URB id: 0xffff888007cbaa80
        URB type: URB_SUBMIT ('S')
        URB transfer type: URB_BULK (0x03)
        Endpoint: 0x01, Direction: OUT
        Device: 3
        URB bus id: 1
        Device setup request: not relevant ('-')
        Data: present ('\0')
        URB sec: 1709589466
        URB usec: 80050
        URB status: Operation now in progress (-EINPROGRESS) (-115)
        URB length [bytes]: 16
        Data length [bytes]: 16
        [Response in: 91]
        [bInterfaceClass: Imaging (0x06)]
        Unused Setup Header
        Interval: 0
        Start frame: 0
        Copy of Transfer Flags: 0x00000000
        Number of ISO descriptors: 0
    Leftover Capture Data: 10000000010002100000000001000000

And the same seen in sys-usb:

    Frame 117: 80 bytes on wire (640 bits), 80 bytes captured (640 bits) on interface usbmon2, id 0
    USB URB
        [Source: host]
        [Destination: 2.18.1]
        URB id: 0xffff908b585f5480
        URB type: URB_SUBMIT ('S')
        URB transfer type: URB_BULK (0x03)
        Endpoint: 0x01, Direction: OUT
        Device: 18
        URB bus id: 2
        Device setup request: not relevant ('-')
        Data: present ('\0')
        URB sec: 1709591829
        URB usec: 752585
        URB status: Operation now in progress (-EINPROGRESS) (-115)
        URB length [bytes]: 16
        Data length [bytes]: 16
        [Response in: 118]
        [bInterfaceClass: Imaging (0x06)]
        Unused Setup Header
        Interval: 0
        Start frame: 0
        Copy of Transfer Flags: 0x00000000
        Number of ISO descriptors: 0
    Leftover Capture Data: 10000000010002100000000001000000

And after few seconds it gets this "response":

    Frame 91: 64 bytes on wire (512 bits), 64 bytes captured (512 bits) on interface usbmon1, id 0
    USB URB
        [Source: 1.3.1]
        [Destination: host]
        URB id: 0xffff888007cbaa80
        URB type: URB_COMPLETE ('C')
        URB transfer type: URB_BULK (0x03)
        Endpoint: 0x01, Direction: OUT
        Device: 3
        URB bus id: 1
        Device setup request: not relevant ('-')
        Data: not present ('>')
        URB sec: 1709589471
        URB usec: 83920
        URB status: No such file or directory (-ENOENT) (-2)
        URB length [bytes]: 0
        Data length [bytes]: 0
        [Request in: 90]
        [Time from request: 5.003870000 seconds]
        [bInterfaceClass: Imaging (0x06)]
        Unused Setup Header
        Interval: 0
        Start frame: 0
        Copy of Transfer Flags: 0x00000000
        Number of ISO descriptors: 0

and the same seen in sys-usb:

    Frame 118: 64 bytes on wire (512 bits), 64 bytes captured (512 bits) on interface usbmon2, id 0
    USB URB
        [Source: 2.18.1]
        [Destination: host]
        URB id: 0xffff908b585f5480
        URB type: URB_COMPLETE ('C')
        URB transfer type: URB_BULK (0x03)
        Endpoint: 0x01, Direction: OUT
        Device: 18
        URB bus id: 2
        Device setup request: not relevant ('-')
        Data: not present ('>')
        URB sec: 1709591834
        URB usec: 753529
        URB status: Connection reset by peer (-ECONNRESET) (-104)
        URB length [bytes]: 0
        Data length [bytes]: 0
        [Request in: 117]
        [Time from request: 5.000944000 seconds]
        [bInterfaceClass: Imaging (0x06)]
        Unused Setup Header
        Interval: 0
        Start frame: 0
        Copy of Transfer Flags: 0x00000000
        Number of ISO descriptors: 0


Calling jmtpfs directly in sys-usb succeeds without device reset:

    Device 0 (VID=18d1 and PID=4ee1) is a Google Inc Nexus/Pixel (MTP).
    Android device detected, assigning default bug flags
    FUSE library version: 2.9.9
    nullpath_ok: 0
    nopath: 0
    utime_omit_ok: 0
    unique: 2, opcode: INIT (26), nodeid: 0, insize: 104, pid: 0
    INIT: 7.37
    flags=0x73fffffb
    max_readahead=0x00020000
       INIT: 7.19
       flags=0x00000011
       max_readahead=0x00020000
       max_write=0x00020000
       max_background=0
       congestion_threshold=0
       unique: 2, success, outsize: 40

At that time, looking at wireshark in sys-usb, I see similar URB_BULK sent:

    Frame 1171: 80 bytes on wire (640 bits), 80 bytes captured (640 bits) on interface usbmon2, id 0
    USB URB
        [Source: host]
        [Destination: 2.18.1]
        URB id: 0xffff908b4fe92180
        URB type: URB_SUBMIT ('S')
        URB transfer type: URB_BULK (0x03)
        Endpoint: 0x01, Direction: OUT
        Device: 18
        URB bus id: 2
        Device setup request: not relevant ('-')
        Data: present ('\0')
        URB sec: 1709591408
        URB usec: 157571
        URB status: Operation now in progress (-EINPROGRESS) (-115)
        URB length [bytes]: 16
        Data length [bytes]: 16
        [Response in: 1172]
        [bInterfaceClass: Imaging (0x06)]
        Unused Setup Header
        Interval: 0
        Start frame: 0
        Copy of Transfer Flags: 0x00000000
        Number of ISO descriptors: 0
    Leftover Capture Data: 10000000010002100000000001000000

but this time it gets a response:

    Frame 1172: 64 bytes on wire (512 bits), 64 bytes captured (512 bits) on interface usbmon2, id 0
    USB URB
        [Source: 2.18.1]
        [Destination: host]
        URB id: 0xffff908b4fe92180
        URB type: URB_COMPLETE ('C')
        URB transfer type: URB_BULK (0x03)
        Endpoint: 0x01, Direction: OUT
        Device: 18
        URB bus id: 2
        Device setup request: not relevant ('-')
        Data: not present ('>')
        URB sec: 1709591408
        URB usec: 157806
        URB status: Success (0)
        URB length [bytes]: 16
        Data length [bytes]: 0
        [Request in: 1171]
        [Time from request: 0.000235000 seconds]
        [bInterfaceClass: Imaging (0x06)]
        Unused Setup Header
        Interval: 0
        Start frame: 0
        Copy of Transfer Flags: 0x00000000
        Number of ISO descriptors: 0

I'm happy to provide more information, debug logs etc, just tell me what
:)


-- 
Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab

Download attachment "signature.asc" of type "application/pgp-signature" (489 bytes)

Powered by blists - more mailing lists