Nitrokey / pynitrokey

Python client for Nitrokey devices
Apache License 2.0
93 stars 28 forks source link

nk3 update: generator didn't stop after throw() #394

Closed robin-nitrokey closed 9 months ago

robin-nitrokey commented 1 year ago

For some users, the NK3 firmware update fails with a RuntimeError: generator didn't stop after throw().

Workaround: Run nitropy nk3 reboot --bootloader before nitropy nk3 update.

Full output:

Command line tool to interact with Nitrokey devices 0.4.36
Do you want to download the firmware version v1.3.1-test.20230417? [Y/n]: 
Download v1.3.1-test.20230417: 100%|███████████████████████████████████████| 918k/918k [00:00<00:00, 6.09MB/s]
Current firmware version:  v1.3.1
Updated firmware version:  v1.3.1-test.20230417

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:
An unhandled exception occurred
        Exception encountered: RuntimeError("generator didn't stop after throw()")

--------------------------------------------------------------------------------
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.g56tsk95' with any support/help request!
- Please check if you have udev rules installed: https://docs.nitrokey.com/nitrokey3/linux/firmware-update.html#troubleshooting

Reports:

samweisgamdschie commented 1 year ago

Hi! same here when trying to upgrade firmware from 1.0.1 to 1.4.0. Installed within a venv.

(venv) ~/python/nitrokey-app2/venv/bin $ nitropy nk3 reboot --bootloader
Command line tool to interact with Nitrokey devices 0.4.35
Please press the touch button to reboot the device into bootloader mode ...
(venv) ~/python/nitrokey-app2/venv/bin $ nitropy nk3 list
Command line tool to interact with Nitrokey devices 0.4.35
:: 'Nitrokey 3' keys
Critical error:
An unhandled exception occurred
        Exception encountered: McuBootConnectionError()

--------------------------------------------------------------------------------
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.s991ee1x' with any support/help request!
- Please check if you have udev rules installed: https://docs.nitrokey.com/nitrokey3/linux/firmware-update.html#troubleshooting

(venv) ~/python/nitrokey-app2/venv/bin $ pip freeze               
altgraph==0.17.3
appdirs==1.4.4
argparse-addons==0.12.0
asn1crypto==1.5.1
astunparse==1.6.3
bincopy==17.10.3
bitstring==3.1.9
black==22.12.0
capstone==4.0.2
certifi==2022.12.7
cffi==1.15.1
charset-normalizer==3.1.0
click==8.1.3
click-command-tree==1.1.0
click-option-group==0.5.5
cmsis-pack-manager==0.2.10
colorama==0.4.6
commentjson==0.9.0
crcmod==1.7
cryptography==36.0.2
deepmerge==0.3.0
docutils==0.19
ecdsa==0.18.0
fastjsonschema==2.16.3
fido2==1.1.1
fire==0.5.0
flake8==6.0.0
flit==3.8.0
flit_core==3.8.0
frozendict==2.3.8
future==0.18.3
hexdump==3.3
humanfriendly==10.0
idna==3.4
intelhex==2.3.0
intervaltree==3.1.0
isort==5.12.0
Jinja2==3.0.3
lark-parser==0.7.8
libusb1==3.0.0
libusbsio==2.1.11
MarkupSafe==2.1.2
mccabe==0.7.0
milksnake==0.1.5
mypy==1.0.1
mypy-extensions==1.0.0
naturalsort==1.5.1
-e git+https://github.com/Nitrokey/nitrokey-app2.git@246a426469eb5b3cef805822df88defbc267ea3a#egg=nitrokeyapp
nkdfu==0.2
oscrypto==1.3.0
pathspec==0.11.1
platformdirs==3.5.0
prettytable==2.5.0
protobuf==3.20.3
psutil==5.9.5
pycodestyle==2.10.0
pycparser==2.21
pycryptodome==3.17
pyelftools==0.29
pyflakes==3.0.1
pyinstaller==5.9.0
pyinstaller-hooks-contrib==2023.2
pylink-square==0.11.1
pynitrokey==0.4.35
pyocd==0.31.0
pyocd-pemicro==1.1.5
pypemicro==0.1.11
PyQt5==5.15.9
PyQt5-Qt5==5.15.2
PyQt5-sip==12.12.1
PyQt5-stubs==5.15.6.0
pyserial==3.5
python-dateutil==2.7.5
pyudev==0.24.1
pyusb==1.2.1
PyYAML==5.4.1
requests==2.30.0
ruamel.yaml==0.17.22
ruamel.yaml.clib==0.2.7
six==1.16.0
sly==0.4
sortedcontainers==2.4.0
spsdk==1.7.1
termcolor==2.3.0
tlv8==0.10.0
tomli==2.0.1
tomli_w==1.0.0
tqdm==4.65.0
typing_extensions==4.3.0
urllib3==1.26.15
wcwidth==0.2.6
(venv) ~/python/nitrokey-app2/venv/bin $ python --version           
Python 3.10.10
(venv) ~/python/nitrokey-app2/venv/bin $

Here is the actual try:

(venv) ~/python/nitrokey-app2/venv/bin $ nitropy nk3 reboot --bootloader
Command line tool to interact with Nitrokey devices 0.4.35
Please press the touch button to reboot the device into bootloader mode ...
(venv) ~/python/nitrokey-app2/venv/bin $ nitropy nk3 update
Command line tool to interact with Nitrokey devices 0.4.35
Do you want to download the firmware version v1.4.0? [Y/n]: 
Download v1.4.0: 100%|████████████| 894k/894k [00:00<00:00, 2.75MB/s]
Current firmware version:  [unknown]
Updated firmware version:  v1.4.0

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:
An unhandled exception occurred
        Exception encountered: McuBootConnectionError()

--------------------------------------------------------------------------------
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.5s7pifk6' with any support/help request!
- Please check if you have udev rules installed: https://docs.nitrokey.com/nitrokey3/linux/firmware-update.html#troubleshooting
robin-nitrokey commented 1 year ago

@samweisgamdschie This looks like a different error to me. Do you have the udev rules installed on your system?

sebastian-de commented 1 year ago

I'm also getting these errors upon updating my NK3, the last time updating from 1.4.0 to 1.5.0. In my case the workaround was simple: I just ran nitropy nk3 update again and it installed fine. This also worked when updating to 1.4.0.

So maybe this is just a timing issue? If the first attempt to connect to the bootloader fails, just wait a few seconds and try again?

Here are my logs:

Logfile of failed update

``` 155 INFO pynitrokey.cli Timestamp: 2023-06-05 16:10:45.482658 155 INFO pynitrokey.cli OS: uname_result(system='Linux', node='laptop', release='6.3.4-201.fc38.x86_64', version='#1 SMP PREEMPT_DYNAMIC Sat May 27 15:08:36 UTC 2023', machine='x86_64') 155 INFO pynitrokey.cli Python version: 3.11.3 156 INFO pynitrokey.cli pynitrokey version: 0.4.37 156 INFO pynitrokey.cli cryptography version: 36.0.2 157 INFO pynitrokey.cli ecdsa version: 0.18.0 157 INFO pynitrokey.cli fido2 version: 1.1.0 157 INFO pynitrokey.cli pyusb version: 1.2.1 157 INFO pynitrokey.cli spsdk version: 1.7.1 353 INFO libusbsio Loading SIO library: /home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/libusbsio/bin/linux_x86_64/libusbsio.so 357 INFO libusbsio HID enumeration[94080759927152]: initialized 357 DEBUG libusbsio HID enumeration[94080759927152]: device #0: USB Keyboard 357 DEBUG libusbsio HID enumeration[94080759927152]: device #1: USB Keyboard 357 DEBUG libusbsio HID enumeration[94080759927152]: device #2: USB Optical Mouse 357 DEBUG libusbsio HID enumeration[94080759927152]: device #3: 32bit DAC 357 DEBUG libusbsio HID enumeration[94080759927152]: device #4: ThinkPad USB-C Dock Audio 357 DEBUG libusbsio HID enumeration[94080759927152]: device #5: Nitrokey 3 357 INFO libusbsio HID enumeration[94080759927152]: finished, total 6 devices 413 DEBUG fido2.hid.linux Failed opening device /dev/hidraw4 Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/fido2/hid/linux.py", line 98, in list_descriptors devices.append(get_descriptor(hidraw)) ^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/fido2/hid/linux.py", line 55, in get_descriptor with open(path, "rb") as f: ^^^^^^^^^^^^^^^^ PermissionError: [Errno 13] Permission denied: '/dev/hidraw4' 413 DEBUG fido2.hid.linux Failed opening device /dev/hidraw3 Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/fido2/hid/linux.py", line 98, in list_descriptors devices.append(get_descriptor(hidraw)) ^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/fido2/hid/linux.py", line 55, in get_descriptor with open(path, "rb") as f: ^^^^^^^^^^^^^^^^ PermissionError: [Errno 13] Permission denied: '/dev/hidraw3' 414 DEBUG fido2.hid.linux Failed opening device /dev/hidraw2 Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/fido2/hid/linux.py", line 98, in list_descriptors devices.append(get_descriptor(hidraw)) ^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/fido2/hid/linux.py", line 55, in get_descriptor with open(path, "rb") as f: ^^^^^^^^^^^^^^^^ PermissionError: [Errno 13] Permission denied: '/dev/hidraw2' 414 DEBUG fido2.hid.linux Failed opening device /dev/hidraw1 Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/fido2/hid/linux.py", line 98, in list_descriptors devices.append(get_descriptor(hidraw)) ^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/fido2/hid/linux.py", line 55, in get_descriptor with open(path, "rb") as f: ^^^^^^^^^^^^^^^^ PermissionError: [Errno 13] Permission denied: '/dev/hidraw1' 414 DEBUG fido2.hid.linux Failed opening device /dev/hidraw0 Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/fido2/hid/linux.py", line 98, in list_descriptors devices.append(get_descriptor(hidraw)) ^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/fido2/hid/linux.py", line 55, in get_descriptor with open(path, "rb") as f: ^^^^^^^^^^^^^^^^ PermissionError: [Errno 13] Permission denied: '/dev/hidraw0' 488 INFO pynitrokey.nk3.updates Firmware version before update: v1.4.0 491 DEBUG urllib3.connectionpool Starting new HTTPS connection (1): api.github.com:443 861 DEBUG urllib3.connectionpool https://api.github.com:443 "GET /repos/Nitrokey/nitrokey-3-firmware/releases/latest HTTP/1.1" 200 None 865 INFO pynitrokey.nk3.updates Latest firmware version: v1.5.0 865 INFO pynitrokey.nk3.updates Current firmware version: v1.4.0 865 INFO pynitrokey.nk3.updates Updated firmware version: v1.5.0 3009 INFO pynitrokey.nk3.updates Trying to download firmware update from URL: https://github.com/Nitrokey/nitrokey-3-firmware/releases/download/v1.5.0/firmware-nk3-v1.5.0.zip 3011 DEBUG urllib3.connectionpool Starting new HTTPS connection (1): github.com:443 3141 DEBUG urllib3.connectionpool https://github.com:443 "GET /Nitrokey/nitrokey-3-firmware/releases/download/v1.5.0/firmware-nk3-v1.5.0.zip HTTP/1.1" 302 0 3143 DEBUG urllib3.connectionpool Starting new HTTPS connection (1): objects.githubusercontent.com:443 3845 DEBUG urllib3.connectionpool https://objects.githubusercontent.com:443 "GET /github-production-release-asset-2e65be/366410832/a5d4a727-d5a9-4286-9021-490387debc48?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAIWNJYAX4CSVEH53A%2F20230605%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20230605T141001Z&X-Amz-Expires=300&X-Amz-Signature=7ccbc1d639b0fd995a4e523113215a0f3b2d075d4fe6fad2232f0bd10ea4cc40&X-Amz-SignedHeaders=host&actor_id=0&key_id=0&repo_id=366410832&response-content-disposition=attachment%3B%20filename%3Dfirmware-nk3-v1.5.0.zip&response-content-type=application%2Foctet-stream HTTP/1.1" 200 906155 4055 DEBUG root print: Current firmware version: v1.4.0 4055 DEBUG root print: Updated firmware version: v1.5.0 4055 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. 6600 DEBUG root print: Please press the touch button to reboot the device into bootloader mode ... 9719 DEBUG pynitrokey.nk3.device./dev/hidraw5 ignoring OSError after reboot Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/device.py", line 92, in reboot self._call(Command.UPDATE) File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/device.py", line 133, in _call response = self.device.call(command.value, data=data) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/fido2/hid/__init__.py", line 189, in call recv = self._connection.read_packet() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/fido2/hid/base.py", line 80, in read_packet return os.read(self.handle, self.descriptor.report_size_in) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ OSError: [Errno 5] Input/output error 9727 DEBUG pynitrokey.nk3.updates Trying to connect to bootloader (try 1 of 3) 9727 DEBUG pynitrokey.cli.nk3 Searching Nitrokey 3 bootloader device (try 1 of 30) 9729 INFO libusbsio HID enumeration[94080768011792]: initialized 9730 DEBUG libusbsio HID enumeration[94080768011792]: device #0: USB Keyboard 9730 DEBUG libusbsio HID enumeration[94080768011792]: device #1: USB Keyboard 9730 DEBUG libusbsio HID enumeration[94080768011792]: device #2: USB Optical Mouse 9730 DEBUG libusbsio HID enumeration[94080768011792]: device #3: 32bit DAC 9730 DEBUG libusbsio HID enumeration[94080768011792]: device #4: ThinkPad USB-C Dock Audio 9730 INFO libusbsio HID enumeration[94080768011792]: finished, total 5 devices 9732 DEBUG pynitrokey.cli.nk3 No Nitrokey 3 bootloader device found, continuing 10233 DEBUG pynitrokey.cli.nk3 Searching Nitrokey 3 bootloader device (try 2 of 30) 10236 INFO libusbsio HID enumeration[94080768075712]: initialized 10236 DEBUG libusbsio HID enumeration[94080768075712]: device #0: USB Keyboard 10236 DEBUG libusbsio HID enumeration[94080768075712]: device #1: USB Keyboard 10236 DEBUG libusbsio HID enumeration[94080768075712]: device #2: USB Optical Mouse 10236 DEBUG libusbsio HID enumeration[94080768075712]: device #3: 32bit DAC 10236 DEBUG libusbsio HID enumeration[94080768075712]: device #4: ThinkPad USB-C Dock Audio 10236 DEBUG libusbsio HID enumeration[94080768075712]: device #5: MCU HID GENERIC DEVICE 10236 INFO libusbsio HID enumeration[94080768075712]: finished, total 6 devices 10239 DEBUG fido2.hid.linux Failed opening device /dev/hidraw6 Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/fido2/hid/linux.py", line 98, in list_descriptors devices.append(get_descriptor(hidraw)) ^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/fido2/hid/linux.py", line 55, in get_descriptor with open(path, "rb") as f: ^^^^^^^^^^^^^^^^ PermissionError: [Errno 13] Permission denied: '/dev/hidraw6' 10239 INFO spsdk.mboot.mcuboot Connect: MCU HID GENERIC DEVICE (0x20A0, 0x42DD) 10239 DEBUG spsdk.mboot.interfaces.usb Open Interface 10239 INFO libusbsio.hidapi.dev Opening HID device at path: 'b'/dev/hidraw6'' 10239 ERROR libusbsio.hidapi.dev HID device 'b'/dev/hidraw6'' opening failed. 10908 DEBUG pynitrokey.nk3.updates Starting firmware update 10908 INFO spsdk.mboot.mcuboot CMD: ReceiveSBfile(data_length=456768) 10909 INFO spsdk.mboot.mcuboot CMD: GetProperty('MaxPacketSize', index=0) 10909 DEBUG spsdk.mboot.mcuboot TX-PACKET: Tag=GetProperty, Flags=0x00, P[0]=0x0000000B, P[1]=0x00000000 10909 DEBUG spsdk.mboot.interfaces.usb OUT[16]: 01, 00, 0C, 00, 07, 00, 00, 02, 0B, 00, 00, 00, 00, 00, 00, 00 10909 WARNING spsdk.mboot.mcuboot CMD: Unable to get MAX PACKET SIZE, using: 32 10909 INFO spsdk.mboot.mcuboot CMD: Max Packet Size = 32 10910 DEBUG spsdk.mboot.mcuboot TX-PACKET: Tag=ReceiveSBFile, Flags=0x01, P[0]=0x0006F840 10910 DEBUG spsdk.mboot.interfaces.usb OUT[12]: 01, 00, 08, 00, 08, 01, 00, 01, 40, F8, 06, 00 10910 INFO spsdk.mboot.mcuboot Closing: MCU HID GENERIC DEVICE (0x20A0, 0x42DD) 10910 DEBUG spsdk.mboot.interfaces.usb Close Interface 10910 DEBUG pynitrokey.nk3.updates Received connection error Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/spsdk/mboot/interfaces/usb.py", line 214, in write _bytes_written = self.device.Write(raw_data, timeout_ms=self.timeout) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/libusbsio/libusbsio.py", line 1357, in wrapper self._check_device_open() File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/libusbsio/libusbsio.py", line 1342, in _check_device_open raise LIBUSBSIO_Exception("HID DEVICE is not open.") libusbsio.libusbsio.LIBUSBSIO_Exception: LIBUSBSIO: HID DEVICE is not open. The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/updates.py", line 362, in _perform_update device.update(image, callback=callback) File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/bootloader/lpc55.py", line 106, in update success = self.device.receive_sb_file( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 655, in receive_sb_file cmd_response = self._process_cmd(cmd_packet) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 117, in _process_cmd self._device.write(cmd_packet) File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/spsdk/mboot/interfaces/usb.py", line 217, in write raise McuBootConnectionError(str(e)) from e spsdk.mboot.exceptions.McuBootConnectionError: MBoot: Connection issue -> LIBUSBSIO: HID DEVICE is not open. During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/updates.py", line 340, in _get_bootloader yield bootloader File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/updates.py", line 215, in update self._perform_update(bootloader, container) File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/updates.py", line 364, in _perform_update raise self.ui.error("Failed to perform firmware update", e) pynitrokey.cli.exceptions.CliException: Failed to perform firmware update MBoot: Connection issue -> LIBUSBSIO: HID DEVICE is not open. During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/spsdk/mboot/interfaces/usb.py", line 170, in close self.device.Close() File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/libusbsio/libusbsio.py", line 1357, in wrapper self._check_device_open() File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/libusbsio/libusbsio.py", line 1342, in _check_device_open raise LIBUSBSIO_Exception("HID DEVICE is not open.") libusbsio.libusbsio.LIBUSBSIO_Exception: LIBUSBSIO: HID DEVICE is not open. The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/updates.py", line 337, in _get_bootloader with self.await_bootloader() as bootloader: File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/base.py", line 25, in __exit__ self.close() File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/bootloader/lpc55.py", line 73, in close self.device.close() File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 276, in close self._device.close() File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/spsdk/mboot/interfaces/usb.py", line 173, in close raise McuBootConnectionError( spsdk.mboot.exceptions.McuBootConnectionError: MBoot: Connection issue -> Unable to close device 'b'/dev/hidraw6'' VID=8352 PID=17117 SN='' 11419 DEBUG pynitrokey.nk3.updates Trying to connect to bootloader (try 2 of 3) 11420 DEBUG pynitrokey.cli.nk3 Searching Nitrokey 3 bootloader device (try 1 of 30) 11423 INFO libusbsio HID enumeration[94080766361552]: initialized 11423 DEBUG libusbsio HID enumeration[94080766361552]: device #0: USB Keyboard 11423 DEBUG libusbsio HID enumeration[94080766361552]: device #1: USB Keyboard 11423 DEBUG libusbsio HID enumeration[94080766361552]: device #2: USB Optical Mouse 11423 DEBUG libusbsio HID enumeration[94080766361552]: device #3: 32bit DAC 11423 DEBUG libusbsio HID enumeration[94080766361552]: device #4: ThinkPad USB-C Dock Audio 11423 DEBUG libusbsio HID enumeration[94080766361552]: device #5: MCU HID GENERIC DEVICE 11423 INFO libusbsio HID enumeration[94080766361552]: finished, total 6 devices 11478 INFO spsdk.mboot.mcuboot Connect: MCU HID GENERIC DEVICE (0x20A0, 0x42DD) 11478 DEBUG spsdk.mboot.interfaces.usb Open Interface 11478 INFO libusbsio.hidapi.dev Opening HID device at path: 'b'/dev/hidraw6'' 11531 INFO libusbsio.hidapi.dev HID device 94080766340512 is now open 11531 WARNING pynitrokey.cli An unhandled exception occurred Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/spsdk/mboot/interfaces/usb.py", line 214, in write _bytes_written = self.device.Write(raw_data, timeout_ms=self.timeout) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/libusbsio/libusbsio.py", line 1357, in wrapper self._check_device_open() File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/libusbsio/libusbsio.py", line 1342, in _check_device_open raise LIBUSBSIO_Exception("HID DEVICE is not open.") libusbsio.libusbsio.LIBUSBSIO_Exception: LIBUSBSIO: HID DEVICE is not open. The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/updates.py", line 362, in _perform_update device.update(image, callback=callback) File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/bootloader/lpc55.py", line 106, in update success = self.device.receive_sb_file( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 655, in receive_sb_file cmd_response = self._process_cmd(cmd_packet) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 117, in _process_cmd self._device.write(cmd_packet) File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/spsdk/mboot/interfaces/usb.py", line 217, in write raise McuBootConnectionError(str(e)) from e spsdk.mboot.exceptions.McuBootConnectionError: MBoot: Connection issue -> LIBUSBSIO: HID DEVICE is not open. During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/updates.py", line 340, in _get_bootloader yield bootloader File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/updates.py", line 215, in update self._perform_update(bootloader, container) File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/updates.py", line 364, in _perform_update raise self.ui.error("Failed to perform firmware update", e) pynitrokey.cli.exceptions.CliException: Failed to perform firmware update MBoot: Connection issue -> LIBUSBSIO: HID DEVICE is not open. During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/cli/__init__.py", line 129, in main nitropy() File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/click/core.py", line 1130, in __call__ return self.main(*args, **kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/click/core.py", line 1055, in main rv = self.invoke(ctx) ^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/click/core.py", line 1657, in invoke return _process_result(sub_ctx.command.invoke(sub_ctx)) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/click/core.py", line 1657, in invoke return _process_result(sub_ctx.command.invoke(sub_ctx)) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/click/core.py", line 1404, in invoke return ctx.invoke(self.callback, **ctx.params) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/click/core.py", line 760, in invoke return __callback(*args, **kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/click/decorators.py", line 38, in new_func return f(get_current_context().obj, *args, **kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/cli/nk3/__init__.py", line 447, in update exec_update(ctx, image, version, ignore_pynitrokey_version) File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/cli/nk3/update.py", line 140, in update return updater.update(device, image, version, ignore_pynitrokey_version) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/updates.py", line 194, in update with self._get_bootloader(device) as bootloader: File "/usr/lib64/python3.11/contextlib.py", line 190, in __exit__ raise RuntimeError("generator didn't stop after throw()") RuntimeError: generator didn't stop after throw() 11542 DEBUG root print: Critical error: 11542 DEBUG root print: An unhandled exception occurred 11542 ERROR root generator didn't stop after throw() Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/spsdk/mboot/interfaces/usb.py", line 214, in write _bytes_written = self.device.Write(raw_data, timeout_ms=self.timeout) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/libusbsio/libusbsio.py", line 1357, in wrapper self._check_device_open() File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/libusbsio/libusbsio.py", line 1342, in _check_device_open raise LIBUSBSIO_Exception("HID DEVICE is not open.") libusbsio.libusbsio.LIBUSBSIO_Exception: LIBUSBSIO: HID DEVICE is not open. The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/updates.py", line 362, in _perform_update device.update(image, callback=callback) File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/bootloader/lpc55.py", line 106, in update success = self.device.receive_sb_file( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 655, in receive_sb_file cmd_response = self._process_cmd(cmd_packet) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/spsdk/mboot/mcuboot.py", line 117, in _process_cmd self._device.write(cmd_packet) File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/spsdk/mboot/interfaces/usb.py", line 217, in write raise McuBootConnectionError(str(e)) from e spsdk.mboot.exceptions.McuBootConnectionError: MBoot: Connection issue -> LIBUSBSIO: HID DEVICE is not open. During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/updates.py", line 340, in _get_bootloader yield bootloader File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/updates.py", line 215, in update self._perform_update(bootloader, container) File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/updates.py", line 364, in _perform_update raise self.ui.error("Failed to perform firmware update", e) pynitrokey.cli.exceptions.CliException: Failed to perform firmware update MBoot: Connection issue -> LIBUSBSIO: HID DEVICE is not open. During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/cli/__init__.py", line 129, in main nitropy() File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/click/core.py", line 1130, in __call__ return self.main(*args, **kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/click/core.py", line 1055, in main rv = self.invoke(ctx) ^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/click/core.py", line 1657, in invoke return _process_result(sub_ctx.command.invoke(sub_ctx)) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/click/core.py", line 1657, in invoke return _process_result(sub_ctx.command.invoke(sub_ctx)) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/click/core.py", line 1404, in invoke return ctx.invoke(self.callback, **ctx.params) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/click/core.py", line 760, in invoke return __callback(*args, **kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/click/decorators.py", line 38, in new_func return f(get_current_context().obj, *args, **kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/cli/nk3/__init__.py", line 447, in update exec_update(ctx, image, version, ignore_pynitrokey_version) File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/cli/nk3/update.py", line 140, in update return updater.update(device, image, version, ignore_pynitrokey_version) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/home/sepp/.local/pipx/venvs/pynitrokey/lib64/python3.11/site-packages/pynitrokey/nk3/updates.py", line 194, in update with self._get_bootloader(device) as bootloader: File "/usr/lib64/python3.11/contextlib.py", line 190, in __exit__ raise RuntimeError("generator didn't stop after throw()") RuntimeError: generator didn't stop after throw() 11543 DEBUG root listing all connected devices: 11543 DEBUG root :: 'Nitrokey FIDO2' keys 11543 DEBUG root :: 'Nitrokey Start' keys: 11560 DEBUG root :: 'Nitrokey 3' keys 11564 INFO libusbsio HID enumeration[94080766439216]: initialized 11564 DEBUG libusbsio HID enumeration[94080766439216]: device #0: USB Keyboard 11564 DEBUG libusbsio HID enumeration[94080766439216]: device #1: USB Keyboard 11564 DEBUG libusbsio HID enumeration[94080766439216]: device #2: USB Optical Mouse 11564 DEBUG libusbsio HID enumeration[94080766439216]: device #3: 32bit DAC 11564 DEBUG libusbsio HID enumeration[94080766439216]: device #4: ThinkPad USB-C Dock Audio 11564 DEBUG libusbsio HID enumeration[94080766439216]: device #5: MCU HID GENERIC DEVICE 11564 INFO libusbsio HID enumeration[94080766439216]: finished, total 6 devices 11567 INFO spsdk.mboot.mcuboot Connect: MCU HID GENERIC DEVICE (0x20A0, 0x42DD) 11567 DEBUG spsdk.mboot.interfaces.usb Open Interface 11567 INFO libusbsio.hidapi.dev Opening HID device at path: 'b'/dev/hidraw6'' 11568 INFO libusbsio.hidapi.dev HID device 94080766470864 is now open 11568 INFO spsdk.mboot.mcuboot CMD: GetProperty('UniqueDeviceIdent', index=0) 11568 DEBUG spsdk.mboot.mcuboot TX-PACKET: Tag=GetProperty, Flags=0x00, P[0]=0x00000012, P[1]=0x00000000 11568 DEBUG spsdk.mboot.interfaces.usb OUT[16]: 01, 00, 0C, 00, 07, 00, 00, 02, 12, 00, 00, 00, 00, 00, 00, 00 11568 DEBUG libusbsio.hidapi.dev HID device 94080766470864 writing[16]: 0x01000c00070000021200000000000000 11569 DEBUG libusbsio.hidapi.dev HID device 94080766470864 wrote 59 bytes 11570 DEBUG libusbsio.hidapi.dev HID device 94080766470864 read[60]: 0x03001800a7000005000000004041f2618d2f64539fa6c6f10a1a9df50000000000000000000000000000000000000000000000000000000000000000 11570 DEBUG spsdk.mboot.interfaces.usb IN [60]: 03, 00, 18, 00, A7, 00, 00, 05, 00, 00, 00, 00, 40, 41, F2, 61, 8D, 2F, 64, 53, 9F, A6, C6, F1, 0A, 1A, 9D, F5, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00, 00 11570 DEBUG spsdk.mboot.mcuboot RX-PACKET: Tag=GetPropertyResponse, Status=Success, v0=0x61F24140, v1=0x53642F8D, v2=0xF1C6A69F, v3=0xF59D1A0A 11570 DEBUG root /dev/hidraw6: Nitrokey 3 Bootloader (LPC55) 4041F2618D2F64539FA6C6F10A1A9DF5 11570 INFO spsdk.mboot.mcuboot Closing: MCU HID GENERIC DEVICE (0x20A0, 0x42DD) 11570 DEBUG spsdk.mboot.interfaces.usb Close Interface 11570 INFO libusbsio.hidapi.dev HID device 94080766470864 closed 11570 DEBUG root print: -------------------------------------------------------------------------------- 11570 DEBUG root print: Critical error occurred, exiting now 11570 DEBUG root print: Unexpected? Is this a bug? Would you like to get support/help? 11570 DEBUG root print: - You can report issues at: https://support.nitrokey.com/ 11570 DEBUG root print: - Writing an e-mail to support@nitrokey.com is also possible 11570 DEBUG root print: - Please attach the log: '/tmp/nitropy.log.izo2lfuk' with any support/help request! 11570 DEBUG root print: - Please check if you have udev rules installed: https://docs.nitrokey.com/nitrokey3/linux/firmware-update.html#troubleshooting 11570 INFO spsdk.mboot.mcuboot Closing: MCU HID GENERIC DEVICE (0x20A0, 0x42DD) 11570 DEBUG spsdk.mboot.interfaces.usb Close Interface 11570 INFO libusbsio.hidapi.dev HID device 94080766340512 closed ```

robin-nitrokey commented 1 year ago

@sebastian-de I agree that this looks like a timing issue, but we already re-try the bootloader connection three times with a delay. Unfortunately, neither me nor any of my colleagues can reproduce the issue so it is hard for me to find the point where the delay would be needed. I tried to fix the problem in https://github.com/Nitrokey/pynitrokey/pull/378 by adding additional connection checks but it did not fix the problem for another affected user. But maybe you can give it a try too. I’ll try to come up with a different approach to fix this.