Re: usbip doesn't work with userspace code that accesses USB devices

From: Marek Marczykowski-Górecki
Date: Mon Mar 04 2024 - 17:46:24 EST

Next message: Frank Li: "[PATCH v2 1/1] PCI: dwc: Fix index 0 incorrectly being interpreted as a free ATU slot"
Previous message: Alex Elder: "Re: [PATCH v2] greybus: Avoid fake flexible array for response data"
In reply to: Greg KH: "Re: usbip doesn't work with userspace code that accesses USB devices"
Next in thread: Marek Marczykowski-Górecki: "Re: usbip doesn't work with userspace code that accesses USB devices"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

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

Attachment: signature.asc
Description: PGP signature

Next message: Frank Li: "[PATCH v2 1/1] PCI: dwc: Fix index 0 incorrectly being interpreted as a free ATU slot"
Previous message: Alex Elder: "Re: [PATCH v2] greybus: Avoid fake flexible array for response data"
In reply to: Greg KH: "Re: usbip doesn't work with userspace code that accesses USB devices"
Next in thread: Marek Marczykowski-Górecki: "Re: usbip doesn't work with userspace code that accesses USB devices"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]