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.

Sign up for GitHub

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

Jump to bottom

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

Closed
robin-nitrokey opened this issue May 23, 2023 · 4 comments · Fixed by #446
Closed

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

robin-nitrokey opened this issue May 23, 2023 · 4 comments · Fixed by #446
Labels
device/Nitrokey 3

Comments

@robin-nitrokey
Copy link
Member

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 [email protected] 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:
This was referenced May 23, 2023
Closed
Closed
@robin-nitrokey robin-nitrokey linked a pull request May 23, 2023 that will close this issue
nk3 update: Handle NK3CN bootloader issues #378
Closed
4 tasks
@samweisgamdschie
Copy link

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 [email protected] 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 [email protected] 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
Copy link
Member Author

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

@Laborratte5 Laborratte5 mentioned this issue May 27, 2023
Closed
@sebastian-de
Copy link

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 [email protected] 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
Copy link
Member Author

@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 #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.

daringer added a commit that referenced this issue Sep 21, 2023
@daringer
fix lpc55s update timing issue, fixes #394
099f0e9
@daringer daringer mentioned this issue Sep 21, 2023
Merged
2 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
device/Nitrokey 3
Projects
None yet
Milestone
No milestone
3 participants
@samweisgamdschie @sebastian-de @robin-nitrokey