USB-passthrough in 3.2 RC1 not working for me

[Niels Kobschätzki]

Hi,

I am trying now the USB-passthrough with my USB-webcam again after upgrading my template to
3.2 and installing qubes-usb-proxy.

I attach my webcam and qvm-usb displays it as:
sys-usb:3-1.2 046d:0826 046d_HD_Webcam_C525_33E0C3B0

When I run qvm-usb -a personal sys-usb:3-1.2 something happens but a new
qvm-usb still displays it as:
sys-usb:3-1.2 046d:0826 046d_HD_Webcam_C525_33E0C3B0
and not as
sys-usb:3-1.2 046d:0826 046d_HD_Webcam_C525_33E0C3B0 (attached to personal)
like I would expect it according to the documentation.

When I run qvm-usb -d sys-usb:3-1.2 I get a:
Device not connected to any VM

When I start Cheese it tells me that no device is connected.

Now to my logs. The sys-usb-logs get spammed with the following two
lines:
Jul 03 11:00:51 sys-usb qubes.USB+3-1.2-personal[1837]: cat: /sys/bus/usb/devices/3-1.2/usbip_status: No such file or directory
Jul 03 11:00:51 sys-usb qubes.USB+3-1.2-personal[1837]: /usr/lib/qubes/usb-export: line 134: [: : integer expression expected

When the camera is attached to sys-usb or after removing it from the
laptop. After assumingly attaching it to personal the spamming stops.

Now, when I run qvm-usb -a personal sys-usb:3-1.2 the logs show the
following:
sys-usb:
Jul 03 11:03:30 sys-usb sudo[5346]: user : TTY=unknown ; PWD=/home/user ; USER=root ; COMMAND=/usr/lib/qubes/usb-export 3-1.2
Jul 03 11:03:30 sys-usb audit[5346]: USER_CMD pid=5346 uid=1000 auid=4294967295 ses=4294967295 msg='cwd="/home/user" cmd=2F7573722F6C69622F71756265732F7573622D6578706F727420332D312E32 terminal=? res=success'
Jul 03 11:03:30 sys-usb audit[5346]: CRED_REFR pid=5346 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success'
Jul 03 11:03:30 sys-usb sudo[5346]: pam_systemd(sudo:session): Cannot create session: Already running in a session
Jul 03 11:03:30 sys-usb sudo[5346]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 03 11:03:30 sys-usb audit[5346]: USER_START pid=5346 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success'
Jul 03 11:03:30 sys-usb qubes.USB+3-1.2-personal[1136]: cat: /sys/bus/usb/devices/3-1.2/usbip_status: No such file or directory
Jul 03 11:03:30 sys-usb qubes.USB+3-1.2-personal[1136]: /usr/lib/qubes/usb-export: line 134: [: : integer expression expected
Jul 03 11:03:30 sys-usb kernel: usb 3-1.2: reset high-speed USB device number 8 using ehci-pci
Jul 03 11:03:31 sys-usb qubes.USB+3-1.2-personal[2370]: cat: /sys/bus/usb/devices/3-1.2/usbip_status: No such file or directory
Jul 03 11:03:31 sys-usb qubes.USB+3-1.2-personal[2370]: /usr/lib/qubes/usb-export: line 134: [: : integer expression expected
Jul 03 11:03:31 sys-usb qubes.USB+3-1.2-personal[1837]: cat: /sys/bus/usb/devices/3-1.2/usbip_status: No such file or directory
Jul 03 11:03:31 sys-usb qubes.USB+3-1.2-personal[1837]: /usr/lib/qubes/usb-export: line 134: [: : integer expression expected
Jul 03 11:03:31 sys-usb systemd[1]: sound.target: Unit not needed anymore. Stopping.
Jul 03 11:03:31 sys-usb systemd[1]: Stopped target Sound Card.
Jul 03 11:03:31 sys-usb systemd[1]: Stopping Sound Card.
Jul 03 11:03:31 sys-usb kernel: usbip-host 3-1.2: usbip-host: register new device (bus 3 dev 8)
Jul 03 11:03:31 sys-usb systemd[1]: Stopped Qubes input proxy sender (mouse).
Jul 03 11:03:31 sys-usb kernel: usbip-host 3-1.2: stub up
Jul 03 11:03:31 sys-usb systemd[1]: Stopped Qubes input proxy sender (keyboard).
Jul 03 11:03:31 sys-usb systemd[1]: Stopped Qubes input proxy sender (keyboard, fallback to mouse).
Jul 03 11:03:32 sys-usb kernel: usbip-host 3-1.2: usb_set_interface done: inf 1 alt 1
Jul 03 11:03:32 sys-usb kernel: usbip-host 3-1.2: usb_set_interface done: inf 1 alt 2
Jul 03 11:03:32 sys-usb kernel: usbip-host 3-1.2: usb_set_interface done: inf 1 alt 3
Jul 03 11:03:32 sys-usb kernel: usbip-host 3-1.2: usb_set_interface done: inf 1 alt 4
Jul 03 11:03:32 sys-usb kernel: usbip-host 3-1.2: usb_set_interface done: inf 1 alt 0
Jul 03 11:03:32 sys-usb kernel: usbip-host 3-1.2: usb_set_interface done: inf 3 alt 0
Jul 03 11:03:32 sys-usb kernel: usbip-host 3-1.2: unlink urb ffff880000b369c0
Jul 03 11:03:32 sys-usb kernel: usbip-host 3-1.2: unlinked by a call to usb_unlink_urb()
Jul 03 11:03:32 sys-usb kernel: usbip-host 3-1.2: usb_set_interface done: inf 1 alt 4
Jul 03 11:03:32 sys-usb kernel: usbip-host 3-1.2: usb_set_interface done: inf 1 alt 0
Jul 03 11:03:32 sys-usb kernel: usbip-host 3-1.2: usb_set_interface done: inf 1 alt 4
Jul 03 11:03:37 sys-usb kernel: usbip-host 3-1.2: unlink urb ffff8800087c2c00
Jul 03 11:03:37 sys-usb kernel: usbip-host 3-1.2: unlink urb ffff88000fd2bd00
Jul 03 11:03:37 sys-usb kernel: usbip-host 3-1.2: unlink urb ffff880002ea0900
Jul 03 11:03:37 sys-usb kernel: usbip-host 3-1.2: unlink urb ffff880002ea0f00
Jul 03 11:03:37 sys-usb kernel: usbip-host 3-1.2: unlink urb ffff88000394fc00
Jul 03 11:03:37 sys-usb kernel: usbip-host 3-1.2: unlink urb ffff88000394f800
Jul 03 11:03:37 sys-usb kernel: usbip-host 3-1.2: unlink urb ffff88000394f200
Jul 03 11:03:37 sys-usb kernel: usbip-host 3-1.2: unlink urb ffff88000394fa00
Jul 03 11:03:37 sys-usb kernel: usbip-host 3-1.2: unlink urb ffff88000394f600
Jul 03 11:03:37 sys-usb kernel: usbip-host 3-1.2: unlinked by a call to usb_unlink_urb()
Jul 03 11:03:38 sys-usb kernel: usbip-host 3-1.2: unlink urb ffff88000394f400
Jul 03 11:03:38 sys-usb kernel: usbip-host 3-1.2: unlink urb ffff8800084d4c00
Jul 03 11:03:38 sys-usb kernel: usbip-host 3-1.2: unlinked by a call to usb_unlink_urb()
Jul 03 11:03:38 sys-usb kernel: usbip-host 3-1.2: unlinked by a call to usb_unlink_urb()
Jul 03 11:03:38 sys-usb kernel: usbip-host 3-1.2: unlinked by a call to usb_unlink_urb()
Jul 03 11:03:38 sys-usb kernel: usbip-host 3-1.2: unlinked by a call to usb_unlink_urb()
Jul 03 11:03:38 sys-usb kernel: usbip-host 3-1.2: unlinked by a call to usb_unlink_urb()
Jul 03 11:03:38 sys-usb kernel: usbip-host 3-1.2: unlinked by a call to usb_unlink_urb()
Jul 03 11:03:38 sys-usb kernel: usbip-host 3-1.2: unlinked by a call to usb_unlink_urb()
Jul 03 11:03:38 sys-usb kernel: usbip-host 3-1.2: unlinked by a call to usb_unlink_urb()
Jul 03 11:03:38 sys-usb kernel: usbip-host 3-1.2: unlinked by a call to usb_unlink_urb()
Jul 03 11:03:38 sys-usb kernel: usbip-host 3-1.2: unlinked by a call to usb_unlink_urb()
Jul 03 11:03:38 sys-usb kernel: usbip-host 3-1.2: usb_set_interface done: inf 1 alt 0


personal:
ul 03 11:03:30 personal qrexec-agent[483]: executed root:QUBESRPC qubes.USBAttach dom0 pid 1737
Jul 03 11:03:30 personal su[1737]: (to root) root on none
Jul 03 11:03:30 personal audit[1737]: USER_AUTH pid=1737 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_rootok acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=? res=success'
Jul 03 11:03:30 personal audit[1737]: USER_ACCT pid=1737 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_succeed_if acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=? res=success'
Jul 03 11:03:30 personal audit[1737]: CRED_ACQ pid=1737 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=? res=success'
Jul 03 11:03:30 personal systemd[1]: Started Session c10 of user root.
Jul 03 11:03:30 personal systemd[1]: Starting Session c10 of user root.
Jul 03 11:03:30 personal su[1737]: pam_unix(su-l:session): session opened for user root by (uid=0)
Jul 03 11:03:30 personal audit[1737]: USER_START pid=1737 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_keyinit,pam_limits,pam_systemd,pam_unix,pam_xauth acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=? res=success'
Jul 03 11:03:31 personal kernel: vhci_hcd vhci_hcd: rhport(0) sockfd(0) devid(196616) speed(3) speed_str(high-speed)
Jul 03 11:03:31 personal kernel: usb 2-1: new high-speed USB device number 49 using vhci_hcd
Jul 03 11:03:31 personal kernel: usb 2-1: new high-speed USB device number 50 using vhci_hcd
Jul 03 11:03:32 personal kernel: usb 2-1: new high-speed USB device number 51 using vhci_hcd
Jul 03 11:03:32 personal kernel: usb 2-1: SetAddress Request (51) to port 0
Jul 03 11:03:32 personal kernel: usb 2-1: New USB device found, idVendor=046d, idProduct=0826
Jul 03 11:03:32 personal kernel: usb 2-1: New USB device strings: Mfr=0, Product=2, SerialNumber=1
Jul 03 11:03:32 personal kernel: usb 2-1: Product: HD Webcam C525
Jul 03 11:03:32 personal kernel: usb 2-1: SerialNumber: 33E0C3B0
Jul 03 11:03:32 personal kernel: usb 2-1: set resolution quirk: cval->res = 384
Jul 03 11:03:32 personal kernel: uvcvideo: Found UVC 1.00 device HD Webcam C525 (046d:0826)
Jul 03 11:03:32 personal kernel: input: HD Webcam C525 as /devices/platform/vhci_hcd/usb2/2-1/2-1:1.2/input/input4
Jul 03 11:03:32 personal mtp-probe[1766]: checking bus 2, device 51: "/sys/devices/platform/vhci_hcd/usb2/2-1"
Jul 03 11:03:32 personal mtp-probe[1766]: bus: 2, device: 51 was not an MTP device
Jul 03 11:03:32 personal systemd[1]: Reached target Sound Card.
Jul 03 11:03:32 personal systemd[1]: Starting Sound Card.
Jul 03 11:03:32 personal kernel: vhci_hcd: dequeue a urb ffff8800ebfe0840
Jul 03 11:03:32 personal kernel: vhci_hcd: device ffff8800e175b298 seems to be still connected
Jul 03 11:03:32 personal kernel: vhci_hcd: unlink->seqnum 15272
Jul 03 11:03:32 personal kernel: vhci_hcd: urb->status -104
Jul 03 11:03:32 personal su[1737]: pam_unix(su-l:session): session closed for user root
Jul 03 11:03:32 personal audit[1737]: USER_END pid=1737 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_close grantors=pam_keyinit,pam_keyinit,pam_limits,pam_systemd,pam_unix,pam_xauth acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=? res=success'
Jul 03 11:03:32 personal audit[1737]: CRED_DISP pid=1737 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=? res=success'
Jul 03 11:03:32 personal qrexec-agent[483]: send exit code 0
Jul 03 11:03:32 personal qrexec-agent[483]: pid 1737 exited with 0
Jul 03 11:03:32 personal qrexec-agent[483]: eintr
Jul 03 11:03:32 personal pulseaudio[833]: Default and alternate sample rates are the same.
Jul 03 11:03:32 personal rtkit-daemon[835]: Supervising 1 threads of 1 processes of 1 users.
Jul 03 11:03:32 personal rtkit-daemon[835]: Successfully made thread 1809 of process 833 (/usr/bin/pulseaudio) owned by '1000' RT at priority 5.
Jul 03 11:03:32 personal rtkit-daemon[835]: Supervising 2 threads of 1 processes of 1 users.
Jul 03 11:03:37 personal kernel: vhci_hcd: dequeue a urb ffff8800ebfa2100
Jul 03 11:03:37 personal kernel: vhci_hcd: device ffff8800e175b298 seems to be still connected
Jul 03 11:03:37 personal kernel: vhci_hcd: dequeue a urb ffff8800ebfa2200
Jul 03 11:03:37 personal kernel: vhci_hcd: device ffff8800e175b298 seems to be still connected
Jul 03 11:03:37 personal kernel: vhci_hcd: dequeue a urb ffff8800ebfa2300
Jul 03 11:03:37 personal kernel: vhci_hcd: device ffff8800e175b298 seems to be still connected
Jul 03 11:03:37 personal kernel: vhci_hcd: dequeue a urb ffff8800ebfa2400
Jul 03 11:03:37 personal kernel: vhci_hcd: device ffff8800e175b298 seems to be still connected
Jul 03 11:03:37 personal kernel: vhci_hcd: dequeue a urb ffff8800ebfa2500
Jul 03 11:03:37 personal kernel: vhci_hcd: device ffff8800e175b298 seems to be still connected
Jul 03 11:03:37 personal kernel: vhci_hcd: dequeue a urb ffff8800ebfa2600
Jul 03 11:03:37 personal kernel: vhci_hcd: device ffff8800e175b298 seems to be still connected
Jul 03 11:03:37 personal kernel: vhci_hcd: dequeue a urb ffff8800ebfa2700
Jul 03 11:03:37 personal kernel: vhci_hcd: device ffff8800e175b298 seems to be still connected
Jul 03 11:03:37 personal kernel: vhci_hcd: dequeue a urb ffff8800ebfa2800
Jul 03 11:03:37 personal kernel: vhci_hcd: device ffff8800e175b298 seems to be still connected
Jul 03 11:03:37 personal kernel: vhci_hcd: dequeue a urb ffff8800ebfa2900
Jul 03 11:03:37 personal kernel: vhci_hcd: device ffff8800e175b298 seems to be still connected
Jul 03 11:03:37 personal kernel: vhci_hcd: dequeue a urb ffff8800ebfa2a00
Jul 03 11:03:37 personal kernel: vhci_hcd: device ffff8800e175b298 seems to be still connected
Jul 03 11:03:37 personal kernel: vhci_hcd: dequeue a urb ffff8800ebfa2b00
Jul 03 11:03:37 personal kernel: vhci_hcd: device ffff8800e175b298 seems to be still connected
Jul 03 11:03:37 personal kernel: vhci_hcd: dequeue a urb ffff8800ebfa2c00
Jul 03 11:03:37 personal kernel: vhci_hcd: device ffff8800e175b298 seems to be still connected
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20302
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20303
Jul 03 11:03:38 personal kernel: vhci_hcd: the urb (seqnum 20303) was already given back
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20302
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20304
Jul 03 11:03:38 personal kernel: vhci_hcd: urb->status -104
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20302
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20305
Jul 03 11:03:38 personal kernel: vhci_hcd: urb->status -104
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20302
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20306
Jul 03 11:03:38 personal kernel: vhci_hcd: urb->status -104
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20302
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20307
Jul 03 11:03:38 personal kernel: vhci_hcd: urb->status -104
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20302
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20308
Jul 03 11:03:38 personal kernel: vhci_hcd: urb->status -104
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20302
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20309
Jul 03 11:03:38 personal kernel: vhci_hcd: urb->status -104
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20302
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20310
Jul 03 11:03:38 personal kernel: vhci_hcd: urb->status -104
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20302
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20311
Jul 03 11:03:38 personal kernel: vhci_hcd: urb->status -104
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20302
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20312
Jul 03 11:03:38 personal kernel: vhci_hcd: urb->status -104
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20302
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20313
Jul 03 11:03:38 personal kernel: vhci_hcd: urb->status -104
Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20302
Jul 03 11:03:38 personal kernel: vhci_hcd: urb->status -104


Any help or ideas?


Niels

[Alex]

On 07/03/2016 11:07 AM, Niels Kobschätzki wrote:
> Hi,
>
> I am trying now the USB-passthrough with my USB-webcam again after
> upgrading my template to 3.2 and installing qubes-usb-proxy.
>
> I attach my webcam and qvm-usb displays it as: sys-usb:3-1.2
> 046d:0826 046d_HD_Webcam_C525_33E0C3B0
>

> [...]
> Any help or ideas?
Really unqualified idea, but... Could you please try to proxy the whole
3-1 device instead of the 3-1.2 characteristic? Something like

$ qvm-usb -a personal sys-usb:3.1

I don't know if this will change anything, it's just a shot in the dark
to gather more info waiting for somebody who knows how usb proxy works.

--
Alex

[Niels Kobschätzki]

qvm-usb: error: Invalid devive name: sys-usb:3-1

Niels

[Marek Marczykowski-Górecki]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

On Sun, Jul 03, 2016 at 11:07:48AM +0200, Niels Kobschätzki wrote:
> Hi,
>
> I am trying now the USB-passthrough with my USB-webcam again after upgrading my template to
> 3.2 and installing qubes-usb-proxy.
>
> I attach my webcam and qvm-usb displays it as:
> sys-usb:3-1.2 046d:0826 046d_HD_Webcam_C525_33E0C3B0
>
> When I run qvm-usb -a personal sys-usb:3-1.2 something happens but a new
> qvm-usb still displays it as:
> sys-usb:3-1.2 046d:0826 046d_HD_Webcam_C525_33E0C3B0
> and not as
> sys-usb:3-1.2 046d:0826 046d_HD_Webcam_C525_33E0C3B0 (attached to personal)
> like I would expect it according to the documentation.
>
> When I run qvm-usb -d sys-usb:3-1.2 I get a:
> Device not connected to any VM
>
> When I start Cheese it tells me that no device is connected.
>
> Now to my logs. The sys-usb-logs get spammed with the following two
> lines:
> Jul 03 11:00:51 sys-usb qubes.USB+3-1.2-personal[1837]: cat: /sys/bus/usb/devices/3-1.2/usbip_status: No such file or directory
> Jul 03 11:00:51 sys-usb qubes.USB+3-1.2-personal[1837]: /usr/lib/qubes/usb-export: line 134: [: : integer expression expected

Both issues should be fixed by qubes-usb-proxy 1.0.3 (just uploaded to
testing repo).

Anyway, both affect device detach only.

> When the camera is attached to sys-usb or after removing it from the
> laptop. After assumingly attaching it to personal the spamming stops.
>
> Now, when I run qvm-usb -a personal sys-usb:3-1.2 the logs show the
> following:

(...)

> Jul 03 11:03:31 personal kernel: vhci_hcd vhci_hcd: rhport(0) sockfd(0) devid(196616) speed(3) speed_str(high-speed)
> Jul 03 11:03:31 personal kernel: usb 2-1: new high-speed USB device number 49 using vhci_hcd
> Jul 03 11:03:31 personal kernel: usb 2-1: new high-speed USB device number 50 using vhci_hcd
> Jul 03 11:03:32 personal kernel: usb 2-1: new high-speed USB device number 51 using vhci_hcd
> Jul 03 11:03:32 personal kernel: usb 2-1: SetAddress Request (51) to port 0
> Jul 03 11:03:32 personal kernel: usb 2-1: New USB device found, idVendor=046d, idProduct=0826
> Jul 03 11:03:32 personal kernel: usb 2-1: New USB device strings: Mfr=0, Product=2, SerialNumber=1
> Jul 03 11:03:32 personal kernel: usb 2-1: Product: HD Webcam C525
> Jul 03 11:03:32 personal kernel: usb 2-1: SerialNumber: 33E0C3B0
> Jul 03 11:03:32 personal kernel: usb 2-1: set resolution quirk: cval->res = 384
> Jul 03 11:03:32 personal kernel: uvcvideo: Found UVC 1.00 device HD Webcam C525 (046d:0826)
> Jul 03 11:03:32 personal kernel: input: HD Webcam C525 as /devices/platform/vhci_hcd/usb2/2-1/2-1:1.2/input/input4

(...)

> Jul 03 11:03:38 personal kernel: vhci_hcd: unlink->seqnum 20302
> Jul 03 11:03:38 personal kernel: vhci_hcd: urb->status -104
>
>
> Any help or ideas?

On my system, kernel also produces very similar messages. And camera
works at the same time.

- --
Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab
A: Because it messes up the order in which people normally read text.
Q: Why is top-posting such a bad thing?
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2

iQEcBAEBCAAGBQJXeZaIAAoJENuP0xzK19csjcUIAIKUhynADhcCyFF/ocqFZG3w
ZQ+a5JU5iDn8QKlt7UWh4r2SPoVORHsJ0C3fpbyyjMoYiBoHmYUWHNYHAGNZorsc
cDr4OEGA+b2DnPsisClx6zD7mqzcyvShk5VsuOpjpbsZYt8kbeSYWMm2itZ69LUy
Yw8zSpI+k7g9CQ0fGxAvSxpgnIlwjZH7uzLlYOHECxy9WA5+V4jhrmK0Zk0f0MNi
6duEnFJkePpAP5aU10rGyhveJV8mxX7xKCYt+qxh1RilinCnBk1ueijIKQGavvfq
ON8Aa5QUPrbrwJWiPUsSOWdolyUUTGa+g85Qyc7jnPgrJmIe6BUFdgL2w2vKv44=
=/bun
-----END PGP SIGNATURE-----

[Niels Kobschätzki]

I updated now to qubes-usb-proxy 1.0.3 and what works now is that qvm-usb shows
now a "(attached to personal)" after attaching the device and detaching is also
possible.

But it still does not work.
When I attach the device in personal I get the following logs:

Jul 04 06:06:23 personal qrexec-agent[524]: executed root:QUBESRPC qubes.USBAttach dom0 pid 2184
Jul 04 06:06:23 personal audit[2184]: USER_AUTH pid=2184 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_rootok acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=? res=success'
Jul 04 06:06:23 personal audit[2184]: USER_ACCT pid=2184 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_succeed_if acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=? res=success'
Jul 04 06:06:23 personal su[2184]: (to root) root on none
Jul 04 06:06:23 personal audit[2184]: CRED_ACQ pid=2184 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=? res=success'
Jul 04 06:06:23 personal systemd[1]: Created slice user-0.slice.
Jul 04 06:06:23 personal systemd[1]: Starting user-0.slice.
Jul 04 06:06:23 personal systemd[1]: Starting User Manager for UID 0...
Jul 04 06:06:23 personal audit[2185]: USER_ACCT pid=2185 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_unix acct="root" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jul 04 06:06:23 personal systemd[2185]: pam_unix(systemd-user:session): session opened for user root by (uid=0)
Jul 04 06:06:23 personal audit[2185]: USER_START pid=2185 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_systemd,pam_unix acct="root" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jul 04 06:06:23 personal systemd[1]: Started Session c10 of user root.
Jul 04 06:06:23 personal systemd[1]: Starting Session c10 of user root.
Jul 04 06:06:23 personal systemd[2185]: Reached target Sockets.
Jul 04 06:06:23 personal systemd[2185]: Starting Sockets.
Jul 04 06:06:23 personal systemd[2185]: Reached target Timers.
Jul 04 06:06:23 personal audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=user@0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jul 04 06:06:23 personal systemd[2185]: Starting Timers.
Jul 04 06:06:23 personal su[2184]: pam_unix(su-l:session): session opened for user root by (uid=0)
Jul 04 06:06:23 personal systemd[2185]: Reached target Paths.
Jul 04 06:06:23 personal audit[2184]: USER_START pid=2184 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_keyinit,pam_limits,pam_systemd,pam_unix,pam_xauth acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=? res=success'
Jul 04 06:06:23 personal systemd[2185]: Starting Paths.
Jul 04 06:06:23 personal systemd[2185]: Reached target Basic System.
Jul 04 06:06:23 personal systemd[2185]: Starting Basic System.
Jul 04 06:06:23 personal systemd[2185]: Reached target Default.
Jul 04 06:06:23 personal systemd[2185]: Startup finished in 26ms.
Jul 04 06:06:23 personal systemd[2185]: Starting Default.
Jul 04 06:06:23 personal systemd[1]: Started User Manager for UID 0.
Jul 04 06:06:23 personal kernel: vhci_hcd vhci_hcd: rhport(0) sockfd(0) devid(131082) speed(3) speed_str(high-speed)
Jul 04 06:06:23 personal kernel: usb 2-1: new high-speed USB device number 90 using vhci_hcd
Jul 04 06:06:24 personal kernel: usb 2-1: new high-speed USB device number 91 using vhci_hcd
Jul 04 06:06:24 personal kernel: usb 2-1: new high-speed USB device number 92 using vhci_hcd
Jul 04 06:06:24 personal kernel: usb 2-1: SetAddress Request (92) to port 0
Jul 04 06:06:24 personal kernel: usb 2-1: New USB device found, idVendor=046d, idProduct=0826
Jul 04 06:06:24 personal kernel: usb 2-1: New USB device strings: Mfr=0, Product=2, SerialNumber=1
Jul 04 06:06:24 personal kernel: usb 2-1: Product: HD Webcam C525
Jul 04 06:06:24 personal kernel: usb 2-1: SerialNumber: 33E0C3B0
Jul 04 06:06:25 personal kernel: usb 2-1: set resolution quirk: cval->res = 384
Jul 04 06:06:25 personal kernel: uvcvideo: Found UVC 1.00 device HD Webcam C525 (046d:0826)
Jul 04 06:06:25 personal kernel: input: HD Webcam C525 as /devices/platform/vhci_hcd/usb2/2-1/2-1:1.2/input/input5
Jul 04 06:06:25 personal mtp-probe[2218]: checking bus 2, device 92: "/sys/devices/platform/vhci_hcd/usb2/2-1"
Jul 04 06:06:25 personal mtp-probe[2218]: bus: 2, device: 92 was not an MTP device
Jul 04 06:06:25 personal systemd[1]: Reached target Sound Card.
Jul 04 06:06:25 personal systemd[1]: Starting Sound Card.
Jul 04 06:06:25 personal kernel: vhci_hcd: dequeue a urb ffff88000447e600
Jul 04 06:06:25 personal kernel: vhci_hcd: device ffff8800e2d14298 seems to be still connected
Jul 04 06:06:25 personal kernel: vhci_hcd: unlink->seqnum 20321
Jul 04 06:06:25 personal kernel: vhci_hcd: urb->status -104
Jul 04 06:06:25 personal su[2184]: pam_unix(su-l:session): session closed for user root
Jul 04 06:06:25 personal audit[2184]: USER_END pid=2184 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_close grantors=pam_keyinit,pam_keyinit,pam_limits,pam_systemd,pam_unix,pam_xauth acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=? res=success'
Jul 04 06:06:25 personal audit[2184]: CRED_DISP pid=2184 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=? res=success'
Jul 04 06:06:25 personal qrexec-agent[524]: send exit code 0
Jul 04 06:06:25 personal qrexec-agent[524]: pid 2184 exited with 0
Jul 04 06:06:25 personal qrexec-agent[524]: eintr
Jul 04 06:06:25 personal pulseaudio[838]: Default and alternate sample rates are the same.
Jul 04 06:06:25 personal rtkit-daemon[839]: Supervising 1 threads of 1 processes of 1 users.
Jul 04 06:06:25 personal rtkit-daemon[839]: Successfully made thread 2260 of process 838 (/usr/bin/pulseaudio) owned by '1000' RT at priority 5.
Jul 04 06:06:25 personal rtkit-daemon[839]: Supervising 2 threads of 1 processes of 1 users.
Jul 04 06:06:30 personal kernel: vhci_hcd: dequeue a urb ffff8800e8b4cf00
Jul 04 06:06:30 personal kernel: vhci_hcd: device ffff8800e2d14298 seems to be still connected
Jul 04 06:06:30 personal kernel: vhci_hcd: dequeue a urb ffff8800e8b4ce00
Jul 04 06:06:30 personal kernel: vhci_hcd: device ffff8800e2d14298 seems to be still connected
Jul 04 06:06:30 personal kernel: vhci_hcd: dequeue a urb ffff8800e8b4cd00
Jul 04 06:06:30 personal kernel: vhci_hcd: device ffff8800e2d14298 seems to be still connected
Jul 04 06:06:30 personal kernel: vhci_hcd: dequeue a urb ffff8800e8b4cc00
Jul 04 06:06:30 personal kernel: vhci_hcd: device ffff8800e2d14298 seems to be still connected
Jul 04 06:06:30 personal kernel: vhci_hcd: dequeue a urb ffff88000a38fb00
Jul 04 06:06:30 personal kernel: vhci_hcd: device ffff8800e2d14298 seems to be still connected
Jul 04 06:06:30 personal kernel: vhci_hcd: dequeue a urb ffff8800dd7a0f00
Jul 04 06:06:30 personal kernel: vhci_hcd: device ffff8800e2d14298 seems to be still connected
Jul 04 06:06:30 personal kernel: vhci_hcd: dequeue a urb ffff88000a32f000
Jul 04 06:06:30 personal kernel: vhci_hcd: device ffff8800e2d14298 seems to be still connected
Jul 04 06:06:30 personal kernel: vhci_hcd: dequeue a urb ffff88000a32f100
Jul 04 06:06:30 personal kernel: vhci_hcd: device ffff8800e2d14298 seems to be still connected
Jul 04 06:06:30 personal kernel: vhci_hcd: dequeue a urb ffff88000a32f200
Jul 04 06:06:30 personal kernel: vhci_hcd: device ffff8800e2d14298 seems to be still connected
Jul 04 06:06:30 personal kernel: vhci_hcd: dequeue a urb ffff8800e2ec2300
Jul 04 06:06:30 personal kernel: vhci_hcd: device ffff8800e2d14298 seems to be still connected
Jul 04 06:06:30 personal kernel: vhci_hcd: dequeue a urb ffff8800e2ec2100
Jul 04 06:06:30 personal kernel: vhci_hcd: device ffff8800e2d14298 seems to be still connected
Jul 04 06:06:30 personal kernel: vhci_hcd: dequeue a urb ffff8800e2ec2c00
Jul 04 06:06:30 personal kernel: vhci_hcd: device ffff8800e2d14298 seems to be still connected
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25348
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25349
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25350
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25351
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25352
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25353
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25354
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25355
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25356
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25357
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25358
Jul 04 06:06:30 personal kernel: vhci_hcd: the urb (seqnum 25358) was already given back
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25348
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25349
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25350
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25351
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25352
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25353
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25354
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25355
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25356
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25357
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25359
Jul 04 06:06:30 personal kernel: vhci_hcd: urb->status -104
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25348
Jul 04 06:06:30 personal kernel: vhci_hcd: urb->status -104
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25349
Jul 04 06:06:30 personal kernel: vhci_hcd: urb->status -104
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25350
Jul 04 06:06:30 personal kernel: vhci_hcd: urb->status -104
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25351
Jul 04 06:06:30 personal kernel: vhci_hcd: urb->status -104
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25352
Jul 04 06:06:30 personal kernel: vhci_hcd: urb->status -104
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25353
Jul 04 06:06:30 personal kernel: vhci_hcd: urb->status -104
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25354
Jul 04 06:06:30 personal kernel: vhci_hcd: urb->status -104
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25355
Jul 04 06:06:30 personal kernel: vhci_hcd: urb->status -104
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25356
Jul 04 06:06:30 personal kernel: vhci_hcd: urb->status -104
Jul 04 06:06:30 personal kernel: vhci_hcd: unlink->seqnum 25357
Jul 04 06:06:30 personal kernel: vhci_hcd: urb->status -104

When I start Cheese I get the following messages (besides the messages from
Cheese):

Jul 04 06:07:47 personal kernel: usb usb2-port1: Cannot enable. Maybe the USB cable is bad?
Jul 04 06:07:48 personal kernel: usb usb2-port1: Cannot enable. Maybe the USB cable is bad?
Jul 04 06:07:48 personal kernel: usb usb2-port1: Cannot enable. Maybe the USB cable is bad?
Jul 04 06:07:49 personal kernel: usb usb2-port1: Cannot enable. Maybe the USB cable is bad?
Jul 04 06:07:49 personal kernel: usb usb2-port1: unable to enumerate USB device

But the camera works when run in a USB-Qube. Thus I am sure there is no problem
with the USB-cable or the camera itself.

Niels