Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unable to update Nitrokey 3 within an app qube #8953

Closed
nestire opened this issue Feb 20, 2024 · 53 comments · Fixed by QubesOS/qubes-app-linux-usb-proxy#36
Closed

Unable to update Nitrokey 3 within an app qube #8953

nestire opened this issue Feb 20, 2024 · 53 comments · Fixed by QubesOS/qubes-app-linux-usb-proxy#36

Comments

@nestire
Copy link

nestire commented Feb 20, 2024

Qubes OS release

4.2.1 Fedora Templates

Brief summary

We try to integrate the Nitrokey3 Firmware updates in Qubes. In this process the Nitrokey3 is rebooted into a Bootloader which then handles the update. This disconnects the Niktrokey3 from the app-vm and a new device appears. When we attach this device manual from sys-usb to the app-vm, it appears but the connection then fails. This is specific for LPC 55 variant of the Nitrokey3.

Steps to reproduce

  1. Install nitropy via pipx in to the app-vm https://docs.nitrokey.com/software/nitropy/all-platforms/installation
  2. connect the nitrokey 3 to your laptop and attach it from sys-usb to the app-vm
  3. runnitropy nk3 list in the app-vm to check if it is connected
  4. run nitropy nk3 reboot --bootloader to reboot the nitrokey3 into the bootloader
  5. reattach the new device to the app-vm (sometimes qubes seems not to recognize the reboot, if that is the case just remove the nitrokey3 an reconnect it again and restart the process)
  6. run again nitropy nk3 list
  7. this results in to an connection error:
    Critical error:
    An unhandled exception occurred
    Exception encountered: McuBootConnectionError()

Expected behavior

basically the same behavior when you run nitropy directly in sys-usb
nitropy_sysusb

Actual behavior

see above

usb_traffic_dump_wireshark.zip

2 wiresharke dump of the traffic on the usb interface in the app-vm of this process and in sys-usb (which works)

@nestire nestire added P: default Priority: default. Default priority for new issues, to be replaced given sufficient information. T: bug Type: bug report. A problem or defect resulting in unintended behavior in something that exists. labels Feb 20, 2024
@marmarek
Copy link
Member

Any kernel errors on either side of the connection?

@nestire
Copy link
Author

nestire commented Feb 20, 2024

dmesg looks normal in sys-usb and the app-vm in all cases

@nestire
Copy link
Author

nestire commented Feb 20, 2024

here is the dmesg of sys-usb and personal. I did the process 2. times firstime Qubes did not recognize the new device in sys-usb
sysusb_dmesg.log
personal_dmesg.log

@nestire
Copy link
Author

nestire commented Feb 20, 2024

ok after looking at it again
(personal)
[ 159.478344] vhci_hcd: unlink->seqnum 109

and in sys-usb:

[  145.493137] usbip-host 4-3: endpoint 0 is stalled
[  148.211463] usbip-host 4-3: unlinked by a call to usb_unlink_urb()

does actually not look normal but they also appear if I attach just the nitrokey3 and don't reboot into the boot loader and seem not to affect the connection (can do nitropy nk3 list and other commands without a problem)

@robin-nitrokey
Copy link

I tried to reproduce the problem with usbip over the network with a non-Qubes OS but everything worked fine in this setup (both machines using Linux 6.1.76).

@nestire
Copy link
Author

nestire commented Feb 21, 2024

ok did some more testing and some "workarounds":

A:

  1. attach nk3 to appvm
  2. run there nitropy nk3 reboot --bootloader
  3. in sys-usb run nitropy nk3 list
  4. attach it the back to the appvm nitropy nk3 list now works again with out this connection error

if you skip step 3 it does not work
B:

  1. attach nk3 to appvm
  2. run there nitropy nk3 reboot --bootloader
  3. attach it back from sys-usb to appvm
  4. detach it without doing anything in the appvm
  5. attach it the back to the appvm nitropy nk3 list now works again with out this connection error

@marmarek
Copy link
Member

interesting... maybe it's something about a driver in sys-usb automatically attaching to the device and messing with the process?

@DemiMarie
Copy link

That might well be the case! Could a userspace daemon (patched usbguard?), together with usbcore.authorized_default, be used to automatically bind the usbip-host driver, instead of whatever driver is picked by default?

@andrewdavidwong andrewdavidwong changed the title update nitrokey3 with in a app-vm Unable to update Nitrokey 3 within an app qube Feb 22, 2024
@andrewdavidwong andrewdavidwong added hardware support needs diagnosis Requires technical diagnosis from developer. Replace with "diagnosed" or remove if otherwise closed. affects-4.2 This issue affects Qubes OS 4.2. C: other labels Feb 22, 2024
@tlaurion
Copy link
Contributor

Have the same behavior all the time when attaching usb security dongles to qemu in a vm. No fun. Updates?

@tlaurion
Copy link
Contributor

tlaurion commented May 24, 2024

@marmarek @DemiMarie this a big blocker for all USB devices changing roles, inlcluding android phones for usb tethering, debugging etc which are long lasting issues where people are doing more and more crazy stuff inside of sys-usb as a mitigation from this unfixed bug under QubesOS.

(On my side ddging testing of USB passthrough physical dongles altogether in my dev cycles and now relying on qemu-canokey and cakokey-qemu library as now used under Heads since linuxboot/heads#1671 and qemu-canokey now being merged and going to land under nixos-unstable soon NixOS/nixpkgs#194254)


For what interests us here needing upstream (qubesos prioritized fix):
Nitrokey/nitrokey-documentation#248 (comment)

@tlaurion
Copy link
Contributor

tlaurion commented May 24, 2024

@marmarek @DemiMarie :

Traces
user@heads-tests-deb12-nix-nk3:~$ nitropy nk3 list
Command line tool to interact with Nitrokey devices 0.4.47
:: 'Nitrokey 3' keys
Critical error:
An unhandled exception occurred
	Exception encountered: SPSDKConnectionError()

--------------------------------------------------------------------------------
Critical error occurred, exiting now
Unexpected? Is this a bug? Would you like to get support/help?
- You can report issues at: https://support.nitrokey.com/
- Writing an e-mail to support@nitrokey.com is also possible
- Please attach the log: '/tmp/nitropy.log.gr9auy8x' with any support/help request!
- Please check if you have udev rules installed: https://docs.nitrokey.com/nitrokey3/linux/firmware-update.html#troubleshooting

Meanwhile

qube side:

user@heads-tests-deb12-nix-nk3:~$ sudo journalctl -f
May 24 10:51:58 heads-tests-deb12-nix-nk3 kernel: vhci_hcd: unlink->seqnum 554
May 24 10:51:58 heads-tests-deb12-nix-nk3 kernel: vhci_hcd: urb->status -104
May 24 10:52:03 heads-tests-deb12-nix-nk3 kernel: vhci_hcd: unlink->seqnum 557
May 24 10:52:03 heads-tests-deb12-nix-nk3 kernel: vhci_hcd: urb->status -104
May 24 10:52:03 heads-tests-deb12-nix-nk3 kernel: vhci_hcd: unlink->seqnum 558
May 24 10:52:03 heads-tests-deb12-nix-nk3 kernel: vhci_hcd: urb->status -104
May 24 10:52:03 heads-tests-deb12-nix-nk3 kernel: vhci_hcd: unlink->seqnum 560
May 24 10:52:03 heads-tests-deb12-nix-nk3 kernel: vhci_hcd: urb->status -104
May 24 10:52:03 heads-tests-deb12-nix-nk3 kernel: vhci_hcd: unlink->seqnum 562
May 24 10:52:03 heads-tests-deb12-nix-nk3 kernel: vhci_hcd: urb->status -104
May 24 10:52:09 heads-tests-deb12-nix-nk3 kernel: vhci_hcd: unlink->seqnum 565
May 24 10:52:09 heads-tests-deb12-nix-nk3 kernel: vhci_hcd: urb->status -104
May 24 10:52:09 heads-tests-deb12-nix-nk3 kernel: vhci_hcd: unlink->seqnum 566
May 24 10:52:09 heads-tests-deb12-nix-nk3 kernel: vhci_hcd: urb->status -104

dmesg on qube side:

[  441.426309] vhci_hcd vhci_hcd.0: USB/IP Virtual Host Controller
[  441.426436] vhci_hcd vhci_hcd.0: new USB bus registered, assigned bus number 1
[  441.426476] vhci_hcd: created sysfs vhci_hcd.0
[  441.426549] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.06
[  441.426581] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[  441.426608] usb usb1: Product: USB/IP Virtual Host Controller
[  441.426630] usb usb1: Manufacturer: Linux 6.6.29-1.qubes.fc37.x86_64 vhci_hcd
[  441.426658] usb usb1: SerialNumber: vhci_hcd.0
[  441.426819] hub 1-0:1.0: USB hub found
[  441.426853] hub 1-0:1.0: 8 ports detected
[  441.427116] vhci_hcd vhci_hcd.0: USB/IP Virtual Host Controller
[  441.427309] vhci_hcd vhci_hcd.0: new USB bus registered, assigned bus number 2
[  441.427373] usb usb2: We don't know the algorithms for LPM for this host, disabling LPM.
[  441.427447] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.06
[  441.427483] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[  441.427515] usb usb2: Product: USB/IP Virtual Host Controller
[  441.427537] usb usb2: Manufacturer: Linux 6.6.29-1.qubes.fc37.x86_64 vhci_hcd
[  441.427564] usb usb2: SerialNumber: vhci_hcd.0
[  441.427699] hub 2-0:1.0: USB hub found
[  441.427727] hub 2-0:1.0: 8 ports detected
[  442.375742] vhci_hcd vhci_hcd.0: pdev(0) rhport(0) sockfd(0)
[  442.375779] vhci_hcd vhci_hcd.0: devid(262148) speed(2) speed_str(full-speed)
[  442.375825] vhci_hcd vhci_hcd.0: Device attached
[  442.566487] vhci_hcd: vhci_device speed not set
[  442.621478] usb 1-1: new full-speed USB device number 2 using vhci_hcd
[  442.699515] vhci_hcd: vhci_device speed not set
[  442.761497] usb 1-1: SetAddress Request (2) to port 0
[  442.797298] usb 1-1: New USB device found, idVendor=8087, idProduct=0026, bcdDevice= 0.02
[  442.797365] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[  442.883469] Bluetooth: Core ver 2.22
[  442.883544] NET: Registered PF_BLUETOOTH protocol family
[  442.883569] Bluetooth: HCI device and connection manager initialized
[  442.883598] Bluetooth: HCI socket layer initialized
[  442.883619] Bluetooth: L2CAP socket layer initialized
[  442.883645] Bluetooth: SCO socket layer initialized
[  442.899065] usbcore: registered new interface driver btusb
[  442.903983] Bluetooth: hci0: Firmware timestamp 2023.48 buildtype 1 build 75324
[  445.024942] vhci_hcd: unlink->seqnum 137
[  445.024961] vhci_hcd: urb->status -104
[  445.025998] vhci_hcd: unlink->seqnum 138
[  445.026028] vhci_hcd: urb->status -104
[  445.028078] vhci_hcd: unlink->seqnum 139
[  445.028093] vhci_hcd: urb->status -104
[  636.494703] vhci_hcd: connection closed
[  636.494866] vhci_hcd: stop threads
[  636.494906] vhci_hcd: release socket
[  636.494926] vhci_hcd: disconnect device
[  636.614487] usb 1-1: USB disconnect, device number 2
[  641.170746] vhci_hcd vhci_hcd.0: pdev(0) rhport(0) sockfd(0)
[  641.170770] vhci_hcd vhci_hcd.0: devid(262148) speed(2) speed_str(full-speed)
[  641.170860] vhci_hcd vhci_hcd.0: Device attached
[  641.358424] vhci_hcd: vhci_device speed not set
[  641.417423] usb 1-1: new full-speed USB device number 3 using vhci_hcd
[  641.490415] vhci_hcd: vhci_device speed not set
[  641.552405] usb 1-1: SetAddress Request (3) to port 0
[  641.588286] usb 1-1: New USB device found, idVendor=8087, idProduct=0026, bcdDevice= 0.02
[  641.588333] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[  641.606315] Bluetooth: hci0: Firmware timestamp 2023.48 buildtype 1 build 75324
[  643.753725] vhci_hcd: unlink->seqnum 276
[  643.753754] vhci_hcd: urb->status -104
[  643.754710] vhci_hcd: unlink->seqnum 277
[  643.754734] vhci_hcd: urb->status -104
[  643.756845] vhci_hcd: unlink->seqnum 278
[  643.756870] vhci_hcd: urb->status -104
[  662.917080] vhci_hcd vhci_hcd.0: pdev(0) rhport(1) sockfd(0)
[  662.917122] vhci_hcd vhci_hcd.0: devid(262149) speed(2) speed_str(full-speed)
[  662.917178] vhci_hcd vhci_hcd.0: Device attached
[  663.102431] vhci_hcd: vhci_device speed not set
[  663.163431] usb 1-2: new full-speed USB device number 4 using vhci_hcd
[  663.236422] vhci_hcd: vhci_device speed not set
[  663.298431] usb 1-2: SetAddress Request (4) to port 1
[  663.336036] usb 1-2: New USB device found, idVendor=20a0, idProduct=42b2, bcdDevice= 1.05
[  663.336074] usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  663.336103] usb 1-2: Product: Nitrokey 3
[  663.336119] usb 1-2: Manufacturer: Nitrokey
[  663.359843] hid-generic 0003:20A0:42B2.0001: hiddev96,hidraw0: USB HID v1.11 Device [Nitrokey Nitrokey 3] on usb-vhci_hcd.0-2/input1
[  663.396795] cdc_acm 1-2:1.2: ttyACM0: USB ACM device
[  663.396874] usbcore: registered new interface driver cdc_acm
[  663.396903] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
[  665.238304] vhci_hcd: unlink->seqnum 297
[  665.238334] vhci_hcd: urb->status -104
[  719.770217] vhci_hcd: connection closed
[  719.770594] vhci_hcd: stop threads
[  719.770648] vhci_hcd: release socket
[  719.770676] vhci_hcd: disconnect device
[  719.770756] usb 1-2: USB disconnect, device number 4
[  794.551685] vhci_hcd vhci_hcd.0: pdev(0) rhport(1) sockfd(0)
[  794.551709] vhci_hcd vhci_hcd.0: devid(262150) speed(3) speed_str(high-speed)
[  794.551739] vhci_hcd vhci_hcd.0: Device attached
[  794.797415] usb 1-2: new high-speed USB device number 5 using vhci_hcd
[  794.932549] usb 1-2: SetAddress Request (5) to port 1
[  794.960530] usb 1-2: New USB device found, idVendor=20a0, idProduct=42dd, bcdDevice= 3.00
[  794.960557] usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  794.960574] usb 1-2: Product: USB COMPOSITE DEVICE
[  794.960586] usb 1-2: Manufacturer: NXP SEMICONDUCTOR INC.
[  794.976554] hid-generic 0003:20A0:42DD.0002: hiddev96,hidraw0: USB HID v1.00 Device [NXP SEMICONDUCTOR INC. USB COMPOSITE DEVICE] on usb-vhci_hcd.0-2/input0
[  801.132025] vhci_hcd: unlink->seqnum 318
[  801.132058] vhci_hcd: urb->status -104
[  828.695889] vhci_hcd: unlink->seqnum 321
[  828.695911] vhci_hcd: urb->status -104
[  828.697801] vhci_hcd: unlink->seqnum 322
[  828.697826] vhci_hcd: urb->status -104
[  828.772228] vhci_hcd: unlink->seqnum 324
[  828.772253] vhci_hcd: urb->status -104
[  828.853013] vhci_hcd: unlink->seqnum 326
[  828.853075] vhci_hcd: urb->status -104
[  834.328368] vhci_hcd: unlink->seqnum 329
[  834.328436] vhci_hcd: urb->status -104
[  834.331255] vhci_hcd: unlink->seqnum 330
[  834.331294] vhci_hcd: urb->status -104
[  921.286599] vhci_hcd: unlink->seqnum 332
[  921.286637] vhci_hcd: urb->status -104
[  926.489069] vhci_hcd: unlink->seqnum 335
[  926.489114] vhci_hcd: urb->status -104
[  926.491450] vhci_hcd: unlink->seqnum 336
[  926.491486] vhci_hcd: urb->status -104
[  926.559991] vhci_hcd: unlink->seqnum 338
[  926.560021] vhci_hcd: urb->status -104
[  926.627339] vhci_hcd: unlink->seqnum 340
[  926.627372] vhci_hcd: urb->status -104
[  932.114852] vhci_hcd: unlink->seqnum 343
[  932.114883] vhci_hcd: urb->status -104
[  932.117052] vhci_hcd: unlink->seqnum 344
[  932.117078] vhci_hcd: urb->status -104
[  936.343565] vhci_hcd: unlink->seqnum 346
[  936.343609] vhci_hcd: urb->status -104
[  936.407972] vhci_hcd: unlink->seqnum 348
[  936.408036] vhci_hcd: urb->status -104
[  954.049391] vhci_hcd: connection closed
[  954.049750] vhci_hcd: stop threads
[  954.049817] vhci_hcd: release socket
[  954.049849] vhci_hcd: disconnect device
[  954.049981] usb 1-2: USB disconnect, device number 5
[  963.981115] vhci_hcd: connection closed
[  963.981464] vhci_hcd: stop threads
[  963.981489] vhci_hcd: release socket
[  963.981503] vhci_hcd: disconnect device
[  964.094416] usb 1-1: USB disconnect, device number 3
[  969.154554] vhci_hcd vhci_hcd.0: pdev(0) rhport(0) sockfd(0)
[  969.154586] vhci_hcd vhci_hcd.0: devid(262148) speed(2) speed_str(full-speed)
[  969.154632] vhci_hcd vhci_hcd.0: Device attached
[  969.336411] vhci_hcd: vhci_device speed not set
[  969.389385] usb 1-1: new full-speed USB device number 6 using vhci_hcd
[  969.455403] vhci_hcd: vhci_device speed not set
[  969.517403] usb 1-1: SetAddress Request (6) to port 0
[  969.553384] usb 1-1: New USB device found, idVendor=8087, idProduct=0026, bcdDevice= 0.02
[  969.553427] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[  969.568528] Bluetooth: hci0: Firmware timestamp 2023.48 buildtype 1 build 75324
[  971.749645] vhci_hcd: unlink->seqnum 485
[  971.749673] vhci_hcd: urb->status -104
[  971.750576] vhci_hcd: unlink->seqnum 486
[  971.750600] vhci_hcd: urb->status -104
[  971.752362] vhci_hcd: unlink->seqnum 487
[  971.752391] vhci_hcd: urb->status -104
[  992.097929] vhci_hcd vhci_hcd.0: pdev(0) rhport(1) sockfd(0)
[  992.097996] vhci_hcd vhci_hcd.0: devid(262151) speed(2) speed_str(full-speed)
[  992.098088] vhci_hcd vhci_hcd.0: Device attached
[  992.270422] vhci_hcd: vhci_device speed not set
[  992.323400] usb 1-2: new high-speed USB device number 7 using vhci_hcd
[  992.396432] vhci_hcd: vhci_device speed not set
[  992.537372] vhci_hcd: vhci_device speed not set
[  992.592364] usb 1-2: new full-speed USB device number 8 using vhci_hcd
[  992.665421] vhci_hcd: vhci_device speed not set
[  992.727417] usb 1-2: SetAddress Request (8) to port 1
[  992.766099] usb 1-2: New USB device found, idVendor=20a0, idProduct=42b2, bcdDevice= 1.05
[  992.766141] usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  992.766170] usb 1-2: Product: Nitrokey 3
[  992.766186] usb 1-2: Manufacturer: Nitrokey
[  992.790333] hid-generic 0003:20A0:42B2.0003: hiddev96,hidraw0: USB HID v1.11 Device [Nitrokey Nitrokey 3] on usb-vhci_hcd.0-2/input1
[  992.791730] cdc_acm 1-2:1.2: ttyACM0: USB ACM device
[  997.566595] vhci_hcd: unlink->seqnum 507
[  997.566613] vhci_hcd: urb->status -104
[  999.681898] vhci_hcd: connection closed
[  999.682032] vhci_hcd: stop threads
[  999.682057] vhci_hcd: release socket
[  999.682068] vhci_hcd: disconnect device
[  999.682110] usb 1-2: USB disconnect, device number 8
[ 1101.203875] vhci_hcd vhci_hcd.0: pdev(0) rhport(1) sockfd(0)
[ 1101.203909] vhci_hcd vhci_hcd.0: devid(262152) speed(3) speed_str(high-speed)
[ 1101.203953] vhci_hcd vhci_hcd.0: Device attached
[ 1101.449399] usb 1-2: new high-speed USB device number 9 using vhci_hcd
[ 1101.584406] usb 1-2: SetAddress Request (9) to port 1
[ 1101.611244] usb 1-2: New USB device found, idVendor=20a0, idProduct=42dd, bcdDevice= 3.00
[ 1101.611273] usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[ 1101.611290] usb 1-2: Product: USB COMPOSITE DEVICE
[ 1101.611302] usb 1-2: Manufacturer: NXP SEMICONDUCTOR INC.
[ 1101.624013] hid-generic 0003:20A0:42DD.0004: hiddev96,hidraw0: USB HID v1.00 Device [NXP SEMICONDUCTOR INC. USB COMPOSITE DEVICE] on usb-vhci_hcd.0-2/input0
[ 1103.815272] vhci_hcd: unlink->seqnum 526
[ 1103.815309] vhci_hcd: urb->status -104
[ 1109.272598] vhci_hcd: unlink->seqnum 529
[ 1109.272669] vhci_hcd: urb->status -104
[ 1109.275219] vhci_hcd: unlink->seqnum 530
[ 1109.275258] vhci_hcd: urb->status -104
[ 1109.343154] vhci_hcd: unlink->seqnum 532
[ 1109.343190] vhci_hcd: urb->status -104
[ 1109.425105] vhci_hcd: unlink->seqnum 534
[ 1109.425171] vhci_hcd: urb->status -104
[ 1114.903161] vhci_hcd: unlink->seqnum 537
[ 1114.903197] vhci_hcd: urb->status -104
[ 1114.905206] vhci_hcd: unlink->seqnum 538
[ 1114.905224] vhci_hcd: urb->status -104
[ 1223.519353] vhci_hcd: unlink->seqnum 540
[ 1223.519378] vhci_hcd: urb->status -104
[ 1229.079045] vhci_hcd: unlink->seqnum 543
[ 1229.079075] vhci_hcd: urb->status -104
[ 1229.089132] vhci_hcd: unlink->seqnum 544
[ 1229.089172] vhci_hcd: urb->status -104
[ 1229.157890] vhci_hcd: unlink->seqnum 546
[ 1229.157926] vhci_hcd: urb->status -104
[ 1229.236783] vhci_hcd: unlink->seqnum 548
[ 1229.236814] vhci_hcd: urb->status -104
[ 1234.711618] vhci_hcd: unlink->seqnum 551
[ 1234.711646] vhci_hcd: urb->status -104
[ 1234.713515] vhci_hcd: unlink->seqnum 552
[ 1234.713536] vhci_hcd: urb->status -104
[ 1539.310310] vhci_hcd: unlink->seqnum 554
[ 1539.310335] vhci_hcd: urb->status -104
[ 1544.471558] vhci_hcd: unlink->seqnum 557
[ 1544.471589] vhci_hcd: urb->status -104
[ 1544.473452] vhci_hcd: unlink->seqnum 558
[ 1544.473475] vhci_hcd: urb->status -104
[ 1544.541781] vhci_hcd: unlink->seqnum 560
[ 1544.541827] vhci_hcd: urb->status -104
[ 1544.613529] vhci_hcd: unlink->seqnum 562
[ 1544.613553] vhci_hcd: urb->status -104
[ 1550.104099] vhci_hcd: unlink->seqnum 565
[ 1550.104124] vhci_hcd: urb->status -104
[ 1550.106042] vhci_hcd: unlink->seqnum 566
[ 1550.106062] vhci_hcd: urb->status -104

sys-usb side:

[user@sys-usb ~]$ sudo journalctl -f
May 24 10:51:58 sys-usb systemd[1]: systemd-hostnamed.service: Deactivated successfully.
May 24 10:51:58 sys-usb audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 24 10:51:58 sys-usb kernel: audit: type=1131 audit(1716562318.617:307): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 24 10:51:58 sys-usb audit: BPF prog-id=84 op=UNLOAD
May 24 10:51:58 sys-usb kernel: audit: type=1334 audit(1716562318.758:308): prog-id=84 op=UNLOAD
May 24 10:51:59 sys-usb kernel: usbip-host 4-3: unlinked by a call to usb_unlink_urb()
May 24 10:52:04 sys-usb kernel: usbip-host 4-3: unlinked by a call to usb_unlink_urb()
May 24 10:52:04 sys-usb kernel: usbip-host 4-3: unlinked by a call to usb_unlink_urb()
May 24 10:52:04 sys-usb kernel: usbip-host 4-3: unlinked by a call to usb_unlink_urb()
May 24 10:52:04 sys-usb kernel: usbip-host 4-3: unlinked by a call to usb_unlink_urb()
May 24 10:52:10 sys-usb kernel: usbip-host 4-3: unlinked by a call to usb_unlink_urb()
May 24 10:52:10 sys-usb kernel: usbip-host 4-3: unlinked by a call to usb_unlink_urb()

dmesg on sys-usb:

[ 3636.654413] audit: type=1334 audit(1716561881.350:288): prog-id=83 op=LOAD
[ 3636.825294] usbip-host 4-3: usbip-host: register new device (bus 4 dev 8)
[ 3636.835918] usbip-host 4-3: stub up
[ 3637.255928] usbip-host 4-3: endpoint 0 is stalled
[ 3639.448412] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 3644.905289] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 3644.908230] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 3644.976395] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 3645.058101] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 3650.536437] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 3650.538492] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 3666.775003] kauditd_printk_skb: 3 callbacks suppressed
[ 3666.775008] audit: type=1131 audit(1716561911.468:292): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[ 3666.925121] audit: type=1334 audit(1716561911.623:293): prog-id=81 op=UNLOAD
[ 3759.152291] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 3764.712278] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 3764.722360] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 3764.790737] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 3764.869605] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 3770.344529] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 3770.346831] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 4043.731083] audit: type=1334 audit(1716562288.426:294): prog-id=84 op=LOAD
[ 4043.731350] audit: type=1334 audit(1716562288.426:295): prog-id=85 op=LOAD
[ 4043.731397] audit: type=1334 audit(1716562288.426:296): prog-id=86 op=LOAD
[ 4043.731427] audit: type=1334 audit(1716562288.426:297): prog-id=82 op=UNLOAD
[ 4043.731457] audit: type=1334 audit(1716562288.426:298): prog-id=83 op=UNLOAD
[ 4043.800802] audit: type=1130 audit(1716562288.496:299): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[ 4052.708020] audit: type=1101 audit(1716562297.404:300): pid=16152 uid=1000 auid=1000 ses=2 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:accounting grantors=pam_unix,pam_localuser acct="user" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/0 res=success'
[ 4052.708366] audit: type=1123 audit(1716562297.404:301): pid=16152 uid=1000 auid=1000 ses=2 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='cwd="/home/user" cmd=6A6F75726E616C746C202D66 exe="/usr/bin/sudo" terminal=pts/0 res=failed'
[ 4056.605704] audit: type=1101 audit(1716562301.296:302): pid=16181 uid=1000 auid=1000 ses=2 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:accounting grantors=pam_unix,pam_localuser acct="user" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/0 res=success'
[ 4056.606140] audit: type=1123 audit(1716562301.296:303): pid=16181 uid=1000 auid=1000 ses=2 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='cwd="/home/user" cmd=6A6F75726E616C63746C202D66 exe="/usr/bin/sudo" terminal=pts/0 res=success'
[ 4056.607545] audit: type=1110 audit(1716562301.296:304): pid=16181 uid=1000 auid=1000 ses=2 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_localuser,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/0 res=success'
[ 4056.612446] audit: type=1105 audit(1716562301.307:305): pid=16181 uid=1000 auid=1000 ses=2 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 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=/dev/pts/0 res=success'
[ 4056.613951] audit: type=2300 audit(1716562301.307:306): pid=16182 uid=1000 auid=1000 ses=2 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='newrole: old-context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 new-context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
[ 4073.929279] audit: type=1131 audit(1716562318.617:307): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[ 4074.060034] audit: type=1334 audit(1716562318.758:308): prog-id=84 op=UNLOAD
[ 4074.943545] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 4080.104417] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 4080.106704] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 4080.174511] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 4080.246420] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 4085.737301] usbip-host 4-3: unlinked by a call to usb_unlink_urb()
[ 4085.739328] usbip-host 4-3: unlinked by a call to usb_unlink_urb()

@marmarek
Copy link
Member

FWIW the Android issue was identified as something else already, and not even specific to qubes: #6330 (comment). So, this issue is really only about Nitrokey.

@tlaurion
Copy link
Contributor

tlaurion commented May 24, 2024

@marmarek @DemiMarie qvm-usb should permit interfacing in terms of "pid:vid", just like qemu, usbreset and all other usb tooling permits to interact with detected usb devices. Otherwise, usb port doesn't change, but pid:vid does and consumers (destination qube) get confused, with reason. the destination qube "thinks" the device (pid:vid) is still connected but it isn't, resulting in timeouts.

This is a bug/feature of qvm-usb device assignation which shouldn't be usb port but pid:vid. Maybe the interface itself should not change, but the permanence option should bind to pid:vid so that it's not the usb port that is binding, but the subjescent pid:vid?

The issue at play here is that qvm-usb thinking the usb port has not been disconnected, even if the description of the device has changed, it is already assigned with the destination qube, even if the "pid:vid" changed.

If qvm-usb could permit to assign permanently pid:vid instead of usb port, or in combination of a usb port for identity change management, this and other collateral issues might as well vanish altogether.

Details under Nitrokey/nitrokey-documentation#248 (comment)

@marmarek
Copy link
Member

I tried to reproduce it, but it works for me. I have Nitrokey 3A Mini, here is what I did:

  1. Take Qubes OS 4.2, fairly fresh install done with choosing kernel-latest, and all updates installed.
  2. Verify that sys-usb and target qube ("work" in my case) uses kernel 6.8.8.
  3. Insert Nitrokey, see it listed as "Nitrokey_Nitrokey_3" in devices widget.
  4. Attach it to the target qube ("work"). I used qvm-usb attach work sys-usb:4-1, but at this stage GUI should work too.
  5. In "work" do pip install pynitrokey (pipx should be better, but I went with a shortcut ;) ).
  6. Install udev rules as documented in the linked PR above
  7. Do nitropy nk3 status - it works, and says firmware version 1.4.0 and variant NRF52
  8. Do nitropy nk3 reboot --bootloader and confirm with tapping the device, it indeed reboots and device automatically disconnects from "work"
  9. Wait for it to be listed as "Nitrokey 3 bootloader" and attach again - here I used identical qvm-usb command; it may be needed this way if GUI still thinks it is attached
  10. Do nitropy list and see it listed (no error)

At this point I unplugged it and plugged again, basically repeating steps until nitrokey nk3 status. And then proceeded with the update:

  1. nitropy nk3 update --version v1.5.0, confirm operation, confirm nitrokey reboot by tapping the device
  2. after switching to bootloader attach it again (qvm-usb attach ...)
  3. wait for update step to complete and when device switches back to normal mode (the nitropy tool shows "Finalize upgrade") attach it again

Here nitropy nk3 status works and shows version 1.5.0.

As for the logs, I do see in sys-usb entries like urb->status -104 or endpoint 0 is stalled, but things seems to work anyway.

@tlaurion
Copy link
Contributor

tlaurion commented May 24, 2024

On my side I have nk3 3a nfc, on 1.5.0 and cannot replicate success

Note that to me, this is Bus 001 Device 004: ID 20a0:42dd Clay Logic USB COMPOSITE DEVICE as opposed to @marmarek 's bootloader naming.

Traces
user@heads-tests-deb12-nix-nk3:~$ lsusb
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
user@heads-tests-deb12-nix-nk3:~$ #unplug replug pass dongle
user@heads-tests-deb12-nix-nk3:~$ lsusb
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 003: ID 20a0:42b2 Clay Logic Nitrokey 3
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
user@heads-tests-deb12-nix-nk3:~$ nitropy nk3 reboot --bootloader 
Command line tool to interact with Nitrokey devices 0.4.47
Please press the touch button to reboot the device into bootloader mode ...
user@heads-tests-deb12-nix-nk3:~$ #pass dongle
user@heads-tests-deb12-nix-nk3:~$ lsusb
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 004: ID 20a0:42dd Clay Logic USB COMPOSITE DEVICE
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
user@heads-tests-deb12-nix-nk3:~$ nitropy nk3 update --version v1.7.1
Command line tool to interact with Nitrokey devices 0.4.47
Do you want to download the firmware version v1.7.1? [Y/n]: y
Download v1.7.1: 100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 1.03M/1.03M [00:00<00:00, 2.43MB/s]
Current firmware version:  [unknown]
Updated firmware version:  v1.7.1

Please do not remove the Nitrokey 3 or insert any other Nitrokey 3 devices during the update. Doing so may damage the Nitrokey 3.
Do you want to perform the firmware update now? [y/N]: y
Critical error:
Failed to perform firmware update
	Exception encountered: SPSDKConnectionError()

--------------------------------------------------------------------------------
Critical error occurred, exiting now
Unexpected? Is this a bug? Would you like to get support/help?
- You can report issues at: https://support.nitrokey.com/
- Writing an e-mail to support@nitrokey.com is also possible
- Please attach the log: '/tmp/nitropy.log.8rl60t2c' with any support/help request!
- Please check if you have udev rules installed: https://docs.nitrokey.com/nitrokey3/linux/firmware-update.html#troubleshooting

user@heads-tests-deb12-nix-nk3:~$ cat /tmp/nitropy.log.8rl60t2c
340        INFO pynitrokey.cli Timestamp: 2024-05-24 18:27:48.870735
340        INFO pynitrokey.cli OS: uname_result(system='Linux', node='heads-tests-deb12-nix-nk3', release='6.8.8-1.qubes.fc37.x86_64', version='#1 SMP PREEMPT_DYNAMIC Wed May  1 04:07:18 GMT 2024', machine='x86_64')
340        INFO pynitrokey.cli Python version: 3.11.2
340        INFO pynitrokey.cli Cli arguments: ['nk3', 'update', '--version', 'v1.7.1']
342        INFO pynitrokey.cli pynitrokey version: 0.4.47
342        INFO pynitrokey.cli cryptography version: 42.0.7
343        INFO pynitrokey.cli ecdsa version: 0.18.0
343        INFO pynitrokey.cli fido2 version: 1.1.2
343        INFO pynitrokey.cli pyusb version: 1.2.1
344        INFO pynitrokey.cli spsdk version: 2.1.1
356        INFO  libusbsio Loading SIO library: /home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/libusbsio/bin/linux_x86_64/libusbsio.so
357        INFO  libusbsio HID enumeration[20815552]: initialized
357       DEBUG  libusbsio HID enumeration[20815552]: device #0: MCU HID GENERIC DEVICE
358        INFO  libusbsio HID enumeration[20815552]: finished, total 1 devices
425        INFO spsdk.mboot.mcuboot Connect: identifier='usb', device=MCU HID GENERIC DEVICE (0x20A0, 0x42DD)path=b'/dev/hidraw0' sn=''
425       DEBUG spsdk.utils.interfaces.device.usb_device Opening the Interface: MCU HID GENERIC DEVICE (0x20A0, 0x42DD)path=b'/dev/hidraw0' sn=''
425        INFO libusbsio.hidapi.dev Opening HID device at path: 'b'/dev/hidraw0''
491        INFO libusbsio.hidapi.dev HID device 23736272 is now open
491        INFO pynitrokey.nk3.updates Firmware version before update: 
491        INFO pynitrokey.nk3.updates Downloading firmare version v1.7.1
507       DEBUG urllib3.connectionpool Starting new HTTPS connection (1): api.github.com:443
773       DEBUG urllib3.connectionpool https://api.github.com:443 "GET /repos/Nitrokey/nitrokey-3-firmware/releases/tags/v1.7.1 HTTP/1.1" 200 None
776        INFO pynitrokey.nk3.updates Current firmware version: None
776        INFO pynitrokey.nk3.updates Updated firmware version: v1.7.1
2480       INFO pynitrokey.nk3.updates Trying to download firmware update from URL: https://github.com/Nitrokey/nitrokey-3-firmware/releases/download/v1.7.1/firmware-nk3-v1.7.1.zip
2482      DEBUG urllib3.connectionpool Starting new HTTPS connection (1): github.com:443
2886      DEBUG urllib3.connectionpool https://github.com:443 "GET /Nitrokey/nitrokey-3-firmware/releases/download/v1.7.1/firmware-nk3-v1.7.1.zip HTTP/1.1" 302 0
2890      DEBUG urllib3.connectionpool Starting new HTTPS connection (1): objects.githubusercontent.com:443
3117      DEBUG urllib3.connectionpool https://objects.githubusercontent.com:443 "GET /github-production-release-asset-2e65be/366410832/12920bd3-c1ca-41e2-bb98-89b0e7d0cae2?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=releaseassetproduction%2F20240524%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20240524T222751Z&X-Amz-Expires=300&X-Amz-Signature=c15d98a6628eb6db2acfeca63378f2b10a4027a4c2377b5dd4b6eb73c56bb501&X-Amz-SignedHeaders=host&actor_id=0&key_id=0&repo_id=366410832&response-content-disposition=attachment%3B%20filename%3Dfirmware-nk3-v1.7.1.zip&response-content-type=application%2Foctet-stream HTTP/1.1" 200 1025247
3567      DEBUG       root print: Current firmware version:  [unknown]
3567      DEBUG       root print: Updated firmware version:  v1.7.1
3567      DEBUG       root print: Please do not remove the Nitrokey 3 or insert any other Nitrokey 3 devices during the update. Doing so may damage the Nitrokey 3.
6096      DEBUG pynitrokey.nk3.updates Starting firmware update
6096       INFO spsdk.mboot.mcuboot CMD: ReceiveSBfile(data_length=517488)
6096       INFO spsdk.mboot.mcuboot CMD: GetProperty(MaxPacketSize, index=0)
6096      DEBUG spsdk.mboot.mcuboot TX-PACKET: Tag=GetProperty, Flags=0x00, P[0]=0x0000000B, P[1]=0x00000000
6096      DEBUG spsdk.mboot.protocol.bulk_protocol OUT[16]: 01, 00, 0C, 00, 07, 00, 00, 02, 0B, 00, 00, 00, 00, 00, 00, 00
6096      DEBUG libusbsio.hidapi.dev HID device 23736272 writing[16]: 0x01000c00070000020b00000000000000
11227     DEBUG libusbsio.hidapi.dev HID device 23736272 wrote -1 bytes
11235      INFO spsdk.mboot.mcuboot Closing: identifier='usb', device=MCU HID GENERIC DEVICE (0x20A0, 0x42DD)path=b'/dev/hidraw0' sn=''
11235     DEBUG spsdk.utils.interfaces.device.usb_device Closing the Interface: MCU HID GENERIC DEVICE (0x20A0, 0x42DD)path=b'/dev/hidraw0' sn=''
11237      INFO libusbsio.hidapi.dev HID device 23736272 closed
11238     DEBUG       root print: Critical error:
11238     DEBUG       root print: Failed to perform firmware update
11238     ERROR       root SPSDK: Invalid size of written bytes has been detected: -1 != 16
Traceback (most recent call last):
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/nk3/updates.py", line 367, in _perform_update
    device.update(image, callback=callback)
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/trussed/bootloader/lpc55.py", line 95, in update
    success = self.device.receive_sb_file(
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 676, in receive_sb_file
    data_chunks = self._split_data(data=data)
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 285, in _split_data
    max_packet_size = self._get_max_packet_size()
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 267, in _get_max_packet_size
    packet_size_property = self.get_property(prop_tag=PropertyTag.MAX_PACKET_SIZE)
                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 640, in get_property
    cmd_response = self._process_cmd(cmd_packet)
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 120, in _process_cmd
    self._interface.write_command(cmd_packet)
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/mboot/protocol/bulk_protocol.py", line 77, in write_command
    self.device.write(frame)
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/utils/interfaces/device/usb_device.py", line 137, in write
    raise SPSDKConnectionError(
spsdk.exceptions.SPSDKConnectionError: SPSDK: Invalid size of written bytes has been detected: -1 != 16

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/cli/__init__.py", line 136, in main
    nitropy()
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/click/core.py", line 1130, in __call__
    return self.main(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/click/core.py", line 1055, in main
    rv = self.invoke(ctx)
         ^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/click/core.py", line 1657, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/click/core.py", line 1657, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/click/core.py", line 1404, in invoke
    return ctx.invoke(self.callback, **ctx.params)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/click/core.py", line 760, in invoke
    return __callback(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/click/decorators.py", line 38, in new_func
    return f(get_current_context().obj, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/cli/nk3/__init__.py", line 121, in update
    exec_update(ctx, image, version, ignore_pynitrokey_version)
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/cli/nk3/update.py", line 140, in update
    return updater.update(device, image, version, ignore_pynitrokey_version)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/nk3/updates.py", line 214, in update
    self._perform_update(bootloader, container)
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/nk3/updates.py", line 369, in _perform_update
    raise self.ui.error("Failed to perform firmware update", e)
pynitrokey.cli.exceptions.CliException: Failed to perform firmware update
SPSDK: Invalid size of written bytes has been detected: -1 != 16
11252     DEBUG       root listing all connected devices:
11321     DEBUG       root :: 'Nitrokey FIDO2' keys
11321     DEBUG       root :: 'Nitrokey Start' keys:
11337     DEBUG       root :: 'Nitrokey 3' keys
11338      INFO  libusbsio HID enumeration[24542576]: initialized
11339     DEBUG  libusbsio HID enumeration[24542576]: device #0: MCU HID GENERIC DEVICE
11339      INFO  libusbsio HID enumeration[24542576]: finished, total 1 devices
11401      INFO spsdk.mboot.mcuboot Connect: identifier='usb', device=MCU HID GENERIC DEVICE (0x20A0, 0x42DD)path=b'/dev/hidraw0' sn=''
11401     DEBUG spsdk.utils.interfaces.device.usb_device Opening the Interface: MCU HID GENERIC DEVICE (0x20A0, 0x42DD)path=b'/dev/hidraw0' sn=''
11401      INFO libusbsio.hidapi.dev Opening HID device at path: 'b'/dev/hidraw0''
11469      INFO libusbsio.hidapi.dev HID device 25322768 is now open
11469      INFO spsdk.mboot.mcuboot CMD: GetProperty(UniqueDeviceIdent, index=0)
11469     DEBUG spsdk.mboot.mcuboot TX-PACKET: Tag=GetProperty, Flags=0x00, P[0]=0x00000012, P[1]=0x00000000
11470     DEBUG spsdk.mboot.protocol.bulk_protocol OUT[16]: 01, 00, 0C, 00, 07, 00, 00, 02, 12, 00, 00, 00, 00, 00, 00, 00
11470     DEBUG libusbsio.hidapi.dev HID device 25322768 writing[16]: 0x01000c00070000021200000000000000
16859     DEBUG libusbsio.hidapi.dev HID device 25322768 wrote -1 bytes
16860      INFO spsdk.mboot.mcuboot Closing: identifier='usb', device=MCU HID GENERIC DEVICE (0x20A0, 0x42DD)path=b'/dev/hidraw0' sn=''
16860     DEBUG spsdk.utils.interfaces.device.usb_device Closing the Interface: MCU HID GENERIC DEVICE (0x20A0, 0x42DD)path=b'/dev/hidraw0' sn=''
16862      INFO libusbsio.hidapi.dev HID device 25322768 closed
16862     DEBUG       root Unable to list devices. See log for the details.
16863     ERROR       root Unable to list devices
Traceback (most recent call last):
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/nk3/updates.py", line 367, in _perform_update
    device.update(image, callback=callback)
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/trussed/bootloader/lpc55.py", line 95, in update
    success = self.device.receive_sb_file(
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 676, in receive_sb_file
    data_chunks = self._split_data(data=data)
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 285, in _split_data
    max_packet_size = self._get_max_packet_size()
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 267, in _get_max_packet_size
    packet_size_property = self.get_property(prop_tag=PropertyTag.MAX_PACKET_SIZE)
                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 640, in get_property
    cmd_response = self._process_cmd(cmd_packet)
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 120, in _process_cmd
    self._interface.write_command(cmd_packet)
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/mboot/protocol/bulk_protocol.py", line 77, in write_command
    self.device.write(frame)
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/utils/interfaces/device/usb_device.py", line 137, in write
    raise SPSDKConnectionError(
spsdk.exceptions.SPSDKConnectionError: SPSDK: Invalid size of written bytes has been detected: -1 != 16

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/cli/__init__.py", line 136, in main
    nitropy()
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/click/core.py", line 1130, in __call__
    return self.main(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/click/core.py", line 1055, in main
    rv = self.invoke(ctx)
         ^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/click/core.py", line 1657, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/click/core.py", line 1657, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/click/core.py", line 1404, in invoke
    return ctx.invoke(self.callback, **ctx.params)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/click/core.py", line 760, in invoke
    return __callback(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/click/decorators.py", line 38, in new_func
    return f(get_current_context().obj, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/cli/nk3/__init__.py", line 121, in update
    exec_update(ctx, image, version, ignore_pynitrokey_version)
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/cli/nk3/update.py", line 140, in update
    return updater.update(device, image, version, ignore_pynitrokey_version)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/nk3/updates.py", line 214, in update
    self._perform_update(bootloader, container)
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/nk3/updates.py", line 369, in _perform_update
    raise self.ui.error("Failed to perform firmware update", e)
pynitrokey.cli.exceptions.CliException: Failed to perform firmware update
SPSDK: Invalid size of written bytes has been detected: -1 != 16

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/helpers.py", line 253, in local_critical
    nitropy.commands["list"].callback()  # type: ignore
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/cli/__init__.py", line 120, in list
    _list()
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/cli/__init__.py", line 112, in _list
    list_nk3()
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/cli/nk3/__init__.py", line 69, in _list
    trussed._list(Context(None))
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/cli/trussed/__init__.py", line 241, in _list
    uuid = device.uuid()
           ^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/pynitrokey/trussed/bootloader/lpc55.py", line 77, in uuid
    uuid = self.device.get_property(PropertyTag.UNIQUE_DEVICE_IDENT)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 640, in get_property
    cmd_response = self._process_cmd(cmd_packet)
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 120, in _process_cmd
    self._interface.write_command(cmd_packet)
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/mboot/protocol/bulk_protocol.py", line 77, in write_command
    self.device.write(frame)
  File "/home/user/.local/pipx/venvs/pynitrokey/lib/python3.11/site-packages/spsdk/utils/interfaces/device/usb_device.py", line 137, in write
    raise SPSDKConnectionError(
spsdk.exceptions.SPSDKConnectionError: SPSDK: Invalid size of written bytes has been detected: -1 != 16
16878     DEBUG       root print: --------------------------------------------------------------------------------
16878     DEBUG       root print: Critical error occurred, exiting now
16878     DEBUG       root print: Unexpected? Is this a bug? Would you like to get support/help?
16878     DEBUG       root print: - You can report issues at: https://support.nitrokey.com/
16878     DEBUG       root print: - Writing an e-mail to support@nitrokey.com is also possible
16878     DEBUG       root print: - Please attach the log: '/tmp/nitropy.log.8rl60t2c' with any support/help request!
16878     DEBUG       root print: - Please check if you have udev rules installed: https://docs.nitrokey.com/nitrokey3/linux/firmware-update.html#troubleshooting
user@heads-tests-deb12-nix-nk3:~$ #unplug replug/pass dongle
user@heads-tests-deb12-nix-nk3:~$ nitropy list
Command line tool to interact with Nitrokey devices 0.4.47
:: 'Nitrokey FIDO2' keys
:: 'Nitrokey Start' keys:
:: 'Nitrokey 3' keys
/dev/hidraw0: Nitrokey 3 7BE66C6C09655959911E4A5958996AEF
:: 'Nitrokey Passkey' keys
user@heads-tests-deb12-nix-nk3:~$ nitropy nk3 update --version v1.7.1
Command line tool to interact with Nitrokey devices 0.4.47
Do you want to download the firmware version v1.7.1? [Y/n]: y
Download v1.7.1: 100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 1.03M/1.03M [00:00<00:00, 2.47MB/s]
Current firmware version:  v1.5.0
Updated firmware version:  v1.7.1

Please do not remove the Nitrokey 3 or insert any other Nitrokey 3 devices during the update. Doing so may damage the Nitrokey 3.
Do you want to perform the firmware update now? [y/N]: y

Please press the touch button to reboot the device into bootloader mode ...

Critical error:
No Nitrokey 3 bootloader device found

--------------------------------------------------------------------------------
Critical error occurred, exiting now
Unexpected? Is this a bug? Would you like to get support/help?
- You can report issues at: https://support.nitrokey.com/
- Writing an e-mail to support@nitrokey.com is also possible
- Please attach the log: '/tmp/nitropy.log.8bc2t1kp' with any support/help request!
- Please check if you have udev rules installed: https://docs.nitrokey.com/nitrokey3/linux/firmware-update.html#troubleshooting

user@heads-tests-deb12-nix-nk3:~$ #pass dongle being detected as composite which is different then @marmarek 
user@heads-tests-deb12-nix-nk3:~$ nitropy list
Command line tool to interact with Nitrokey devices 0.4.47
:: 'Nitrokey FIDO2' keys
:: 'Nitrokey Start' keys:
:: 'Nitrokey 3' keys
Critical error:
An unhandled exception occurred
	Exception encountered: SPSDKConnectionError()

--------------------------------------------------------------------------------
Critical error occurred, exiting now
Unexpected? Is this a bug? Would you like to get support/help?
- You can report issues at: https://support.nitrokey.com/
- Writing an e-mail to support@nitrokey.com is also possible
- Please attach the log: '/tmp/nitropy.log._x8kz0ry

@marmarek
Copy link
Member

Bus 001 Device 004: ID 20a0:42dd Clay Logic USB COMPOSITE DEVICE

Mine in bootloader mode is 20a0:42e8, so maybe I have a different hardware that is not affected by this issue?

@tlaurion
Copy link
Contributor

Bus 001 Device 004: ID 20a0:42dd Clay Logic USB COMPOSITE DEVICE

Mine in bootloader mode is 20a0:42e8, so maybe I have a different hardware that is not affected by this issue?

@daringer not sure but as long as users will not be able to all upgrade, more investigation is needed

@DemiMarie
Copy link

@marmarek @DemiMarie qvm-usb should permit interfacing in terms of "pid:vid", just like qemu, usbreset and all other usb tooling permits to interact with detected usb devices. Otherwise, usb port doesn't change, but pid:vid does and consumers (destination qube) get confused, with reason. the destination qube "thinks" the device (pid:vid) is still connected but it isn't, resulting in timeouts.

This is a bug/feature of qvm-usb device assignation which shouldn't be usb port but pid:vid. Maybe the interface itself should not change, but the permanence option should bind to pid:vid so that it's not the usb port that is binding, but the subjescent pid:vid?

This would be a security vulnerability, as it would allow spoofing attacks.

The issue at play here is that qvm-usb thinking the usb port has not been disconnected, even if the description of the device has changed, it is already assigned with the destination qube, even if the "pid:vid" changed.

If qvm-usb could permit to assign permanently pid:vid instead of usb port, or in combination of a usb port for identity change management, this and other collateral issues might as well vanish altogether.

The port number is the only information that is not under the control of a device. Therefore, including it in the information used to identify a device is a security requirement. Not using it would allow spoofing attacks.

Would it be sufficient to emulate unplugging and replugging the device?

@marmarek
Copy link
Member

@DemiMarie I just spent some time debugging it with @tlaurion and the vid:pid hypothesis looks to be dead end, so lets cut this topic in here. The actual issue seems to be hardware related (or more likely - related to chip bootloader), and maybe also related to specific hardware revision, not necessarily all devices.

@tlaurion
Copy link
Contributor

tlaurion commented May 24, 2024

@DemiMarie I just spent some time debugging it with @tlaurion and the vid:pid hypothesis looks to be dead end, so lets cut this topic in here. The actual issue seems to be hardware related (or more likely - related to chip bootloader), and maybe also related to specific hardware revision, not necessarily all devices.

Thank you @DemiMarie @marmarek :)

@qubesos-bot
Copy link

Automated announcement from builder-github

The package app-linux-usb-proxy has been pushed to the r4.2 stable repository for the Debian template.
To install this update, please use the standard update command:

sudo apt-get update && sudo apt-get dist-upgrade

Changes included in this update

@qubesos-bot
Copy link

Automated announcement from builder-github

The component app-linux-usb-proxy (including package app-linux-usb-proxy) has been pushed to the r4.2 stable repository for the Fedora template.
To install this update, please use the standard update command:

sudo dnf update

Changes included in this update

@qubesos-bot
Copy link

Automated announcement from builder-github

The component app-linux-usb-proxy (including package app-linux-usb-proxy) has been pushed to the r4.2 stable repository for the Fedora template.
To install this update, please use the standard update command:

sudo dnf update

Changes included in this update

@qubesos-bot
Copy link

Automated announcement from builder-github

The component app-linux-usb-proxy (including package app-linux-usb-proxy) has been pushed to the r4.2 stable repository for the Fedora template.
To install this update, please use the standard update command:

sudo dnf update

Changes included in this update

@qubesos-bot
Copy link

Automated announcement from builder-github

The component app-linux-usb-proxy (including package app-linux-usb-proxy) has been pushed to the r4.2 stable repository for the Fedora template.
To install this update, please use the standard update command:

sudo dnf update

Changes included in this update

@qubesos-bot
Copy link

Automated announcement from builder-github

The component app-linux-usb-proxy (including package qubes-usb-proxy-dom0-1.2.2-1.fc32) has been pushed to the r4.1 stable repository for dom0.
To install this update, please use the standard update command:

sudo qubes-dom0-update

Or update dom0 via Qubes Manager.

Changes included in this update

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

8 participants