attaching usb device fails, usbip-host errors in sys-usb

[maltesl]

Qubes OS version:

Qubes release 4.0 (R4.0)
R4.0rc4
last updated this morning (2018-02-25) from testing

Affected component(s):

qubes-usb-proxy (?)

---

Steps to reproduce the behavior:

Try to attach a usb device (in my case a usb soundcard/wireless headphones):
qvm-usb attach vm sys-usb:2-6

Expected behavior:

The device gets attached, gets recognized by pulseaudio etc. and can be used in the target vm.

Actual behavior:

Device gets shown as attached in the widget, but not by qvm-usb.
qvm-usb shows no error message.
There is an error message in sys-usb (output of journalctl -f):

Feb 25 13:23:01 sys-usb kernel: usbip-host 2-6: CMD_SUBMIT: isoc invalid num packets 6
Feb 25 13:23:01 sys-usb kernel: usbip_core: unknown command
Feb 25 13:23:01 sys-usb kernel: usbip-host 2-6: recv invalid request
Feb 25 13:23:01 sys-usb kernel: usbip-host 2-6: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection

the full output is:

Feb 25 13:23:01 sys-usb audit[2699]: USER_AUTH pid=2699 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_rootok acct="root" exe="/usr/lib/qubes/qrexec-agent" hostname=? addr=? terminal=? res=success'
Feb 25 13:23:01 sys-usb qrexec-agent[491]: executed root:QUBESRPC qubes.USB+2-6 disp3297 pid 2699
Feb 25 13:23:01 sys-usb audit[2699]: CRED_ACQ pid=2699 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="root" exe="/usr/lib/qubes/qrexec-agent" hostname=? addr=? terminal=? res=success'
Feb 25 13:23:01 sys-usb systemd[1]: Started Session c7 of user root.
Feb 25 13:23:01 sys-usb qrexec-agent[2699]: pam_unix(qrexec:session): session opened for user root by (uid=0)
Feb 25 13:23:01 sys-usb audit[2699]: USER_START pid=2699 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_systemd,pam_unix,pam_lastlog acct="root" exe="/usr/lib/qubes/qrexec-agent" hostname=? addr=? terminal=? res=success'
Feb 25 13:23:01 sys-usb kernel: usbip-host 2-6: stub up
Feb 25 13:23:01 sys-usb kernel: usbip-host 2-6: usb_set_interface done: inf 1 alt 1
Feb 25 13:23:01 sys-usb kernel: usbip-host 2-6: usb_set_interface done: inf 1 alt 0
Feb 25 13:23:01 sys-usb kernel: usbip-host 2-6: usb_set_interface done: inf 2 alt 1
Feb 25 13:23:01 sys-usb kernel: usbip-host 2-6: usb_set_interface done: inf 2 alt 0
Feb 25 13:23:01 sys-usb kernel: usbip-host 2-6: endpoint 0 is stalled
Feb 25 13:23:01 sys-usb kernel: usbip-host 2-6: usb_set_interface done: inf 2 alt 1
Feb 25 13:23:01 sys-usb kernel: usbip-host 2-6: usb_set_interface done: inf 2 alt 0
Feb 25 13:23:01 sys-usb kernel: usbip-host 2-6: usb_set_interface done: inf 1 alt 1
Feb 25 13:23:01 sys-usb kernel: usbip-host 2-6: CMD_SUBMIT: isoc invalid num packets 6
Feb 25 13:23:01 sys-usb kernel: usbip_core: unknown command
Feb 25 13:23:01 sys-usb kernel: usbip-host 2-6: recv invalid request
Feb 25 13:23:01 sys-usb kernel: usbip-host 2-6: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection
Feb 25 13:23:01 sys-usb qrexec-agent[491]: pid 2699 exited with -1
Feb 25 13:23:01 sys-usb qrexec-agent[491]: eintr
Feb 25 13:23:01 sys-usb kernel: usbip-host 2-6: reset full-speed USB device number 7 using xhci_hcd
Feb 25 13:23:02 sys-usb kernel: usbip-host 2-6: device reset
Feb 25 13:23:02 sys-usb qrexec-agent[2699]: pam_unix(qrexec:session): session closed for user root
Feb 25 13:23:02 sys-usb audit[2699]: USER_END pid=2699 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_systemd,pam_unix,pam_lastlog acct="root" exe="/usr/lib/qubes/qrexec-agent" hostname=? addr=? terminal=? res=success'
Feb 25 13:23:02 sys-usb audit[2699]: CRED_DISP pid=2699 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="root" exe="/usr/lib/qubes/qrexec-agent" hostname=? addr=? terminal=? res=success'

The messages in the target vm are:

Feb 25 13:23:00 disp3297 qrexec-agent[491]: executed root:QUBESRPC qubes.USBAttach dom0 pid 2560
Feb 25 13:23:00 disp3297 audit[2560]: USER_AUTH pid=2560 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_rootok acct="root" exe="/usr/lib/qubes/qrexec-agent" hostname=? addr=? terminal=? res=success'
Feb 25 13:23:00 disp3297 audit[2560]: CRED_ACQ pid=2560 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="root" exe="/usr/lib/qubes/qrexec-agent" hostname=? addr=? terminal=? res=success'
Feb 25 13:23:00 disp3297 systemd[1]: Started Session c6 of user root.
Feb 25 13:23:00 disp3297 audit[2560]: USER_START pid=2560 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_systemd,pam_unix,pam_lastlog acct="root" exe="/usr/lib/qubes/qrexec-agent" hostname=? addr=? terminal=? res=success'
Feb 25 13:23:00 disp3297 qrexec-agent[2560]: pam_unix(qrexec:session): session opened for user root by (uid=0)
Feb 25 13:23:01 disp3297 kernel: vhci_hcd vhci_hcd.0: pdev(0) rhport(1) sockfd(0)
Feb 25 13:23:01 disp3297 kernel: vhci_hcd vhci_hcd.0: devid(131079) speed(2) speed_str(full-speed)
Feb 25 13:23:01 disp3297 kernel: vhci_hcd: vhci_device speed not set
Feb 25 13:23:01 disp3297 kernel: usb 1-2: new full-speed USB device number 4 using vhci_hcd
Feb 25 13:23:01 disp3297 kernel: vhci_hcd: vhci_device speed not set
Feb 25 13:23:01 disp3297 kernel: usb 1-2: SetAddress Request (4) to port 1
Feb 25 13:23:01 disp3297 kernel: usb 1-2: New USB device found, idVendor=046d, idProduct=0a1f
Feb 25 13:23:01 disp3297 kernel: usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Feb 25 13:23:01 disp3297 kernel: usb 1-2: Product: Logitech G930 Headset
Feb 25 13:23:01 disp3297 kernel: usb 1-2: Manufacturer: Logitech
Feb 25 13:23:01 disp3297 kernel: input: Logitech Logitech G930 Headset as /devices/platform/vhci_hcd.0/usb1/1-2/1-2:1.3/0003:046D:0A1F.0002/input/input3
Feb 25 13:23:01 disp3297 kernel: hid-generic 0003:046D:0A1F.0002: input,hiddev96,hidraw0: USB HID v1.01 Device [Logitech Logitech G930 Headset] on usb-vhci_hcd.0-2/input3
Feb 25 13:23:01 disp3297 mtp-probe[2606]: checking bus 1, device 4: "/sys/devices/platform/vhci_hcd.0/usb1/1-2"
Feb 25 13:23:01 disp3297 mtp-probe[2606]: bus: 1, device: 4 was not an MTP device
Feb 25 13:23:01 disp3297 systemd[1]: Reached target Sound Card.
Feb 25 13:23:01 disp3297 kernel: vhci_hcd: connection closed
Feb 25 13:23:01 disp3297 kernel: vhci_hcd: stop threads
Feb 25 13:23:01 disp3297 kernel: vhci_hcd: release socket
Feb 25 13:23:01 disp3297 kernel: vhci_hcd: disconnect device
Feb 25 13:23:01 disp3297 kernel: usb 1-2: USB disconnect, device number 4
Feb 25 13:23:01 disp3297 pulseaudio[1750]: Failed to get card object.
Feb 25 13:23:01 disp3297 pulseaudio[1750]: Disabling timer-based scheduling because running inside a VM.
Feb 25 13:23:01 disp3297 systemd[1]: sound.target: Unit not needed anymore. Stopping.
Feb 25 13:23:01 disp3297 systemd[1]: Stopped target Sound Card.
Feb 25 13:23:01 disp3297 audit[2560]: USER_END pid=2560 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_systemd,pam_unix,pam_lastlog acct="root" exe="/usr/lib/qubes/qrexec-agent" hostname=? addr=? terminal=? res=success'
Feb 25 13:23:01 disp3297 audit[2560]: CRED_DISP pid=2560 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="root" exe="/usr/lib/qubes/qrexec-agent" hostname=? addr=? terminal=? res=success'
Feb 25 13:23:01 disp3297 qrexec-agent[2560]: pam_unix(qrexec:session): session closed for user root
Feb 25 13:23:01 disp3297 qrexec-agent[491]: send exit code 0
Feb 25 13:23:01 disp3297 qrexec-agent[491]: pid 2560 exited with 0
Feb 25 13:23:01 disp3297 qrexec-agent[491]: eintr

General notes:

This worked perfectly out of the box since my first install of RC1 in September. An update a couple of weeks/months ago seems to have introduced this problem (unfortunately I don't remember anymore when it appeared precisely).

Not all usb devices seem to have this problem, this one is the only one I tried that has it.

The problem appears to be the same for both debian and fedora templates. I tried both the current kernel (4.14.18-1) as well as 4.14.13-2. Unfortunately this is is the oldest of the three kernels currently installed, so I don't know how to test older ones should the kernel be where the problem is.

Sometimes it seems possible (by repeatedly executing the qvm-usb attach command until it hangs, then killing it and immediately executing another one - or something like that) to reach a state in which qvm-usb does list the device as attached and it is also listed in the target vm by lsusb, but leads to pulseaudio crashing / hanging, so I am not sure whether in that case the usb device is actually usable. This does not happen often, but happened twice yesterday while I was trying to debug this.

[marmarek]

Verify if you have the same kernel version in sys-usb and target VM. I think there were some major changes in USBIP (used by qvm-usb) between 4.9 and 4.14.

[marmarek]

Verify if you have the same kernel version in sys-usb and target VM. I think there were some major changes in USBIP (used by qvm-usb) between 4.9 and 4.14.

[maltesl]

I just tried this again after making sure uname -a reports both vms as running 4.14.18-1.pvops.qubes.x86_64, and the behavior is still the same. This is also the version running in dom0. I don't have any pre-4.14 kernel installed anymore (is there an easy way to install older kernels then the three oldest that are retained?), so I can't check at the moment whether the update from 4.9 to 4.14 was the one that broke things.

[maltesl]

I just tried this again after making sure uname -a reports both vms as running 4.14.18-1.pvops.qubes.x86_64, and the behavior is still the same. This is also the version running in dom0. I don't have any pre-4.14 kernel installed anymore (is there an easy way to install older kernels then the three oldest that are retained?), so I can't check at the moment whether the update from 4.9 to 4.14 was the one that broke things.

[marmarek]

As for installing older kernels:

1. Increase installonly_limit in /etc/dnf/dnf.conf
2. Downgrade kernel-qubes-vm package: https://www.qubes-os.org/doc/software-update-dom0/#how-to-update-software-in-dom0

There are also some updates to USBIP in 4.15 kernel but doesn't look related to CMD_SUBMIT: isoc invalid num packets 6 error (at least not directly). So, I'd start with downgrading sys-usb kernel to 4.9.x

[marmarek]

As for installing older kernels:

1. Increase installonly_limit in /etc/dnf/dnf.conf
2. Downgrade kernel-qubes-vm package: https://www.qubes-os.org/doc/software-update-dom0/#how-to-update-software-in-dom0

There are also some updates to USBIP in 4.15 kernel but doesn't look related to CMD_SUBMIT: isoc invalid num packets 6 error (at least not directly). So, I'd start with downgrading sys-usb kernel to 4.9.x

[aksiazek]

I hit the same issue with my wireless headphones and can confirm that a downgrade to 4.9 for sys-usb solved the issue for now

[aksiazek]

I hit the same issue with my wireless headphones and can confirm that a downgrade to 4.9 for sys-usb solved the issue for now