McuBootConnectionError() after NK3 firmware update

[Laborratte5]

I got a similar error as mentioned here but as pointed out by robin-nitrokey it seems to be unrelated to the original issue so I'm opening this one. I ran nitropy nk3 update --version v1.4.0 to update the firmware. The update reached 100% and then the following error occured:

Command line tool to interact with Nitrokey devices 0.4.37
Do you want to download the firmware version v1.4.0? [Y/n]: 
Download v1.4.0: 100%|█████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 894k/894k [00:00<00:00, 1.90MB/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
Perform firmware update: 100%|████████████████████████████████████████████████████████████████████████████████████████████████████████| 451k/451k [4:00:09<00:00, 31.3B/s]
Critical error:
Failed to perform firmware update
    Exception encountered: McuBootConnectionError()

This is the error log:

403        INFO pynitrokey.cli Timestamp: 2023-05-27 00:52:03.461393
403        INFO pynitrokey.cli OS: uname_result(system='Linux', node='ARCH-MEDION', release='6.1.30-1-lts', version='#1 SMP PREEMPT_DYNAMIC Wed, 24 May 2023 17:18:57 +0000', machine='x86_64')
404        INFO pynitrokey.cli Python version: 3.11.3
406        INFO pynitrokey.cli pynitrokey version: 0.4.37
407        INFO pynitrokey.cli cryptography version: 36.0.2
408        INFO pynitrokey.cli ecdsa version: 0.18.0
408        INFO pynitrokey.cli fido2 version: 1.1.1
409        INFO pynitrokey.cli pyusb version: 1.2.1
410        INFO pynitrokey.cli spsdk version: 1.7.1
900        INFO  libusbsio Loading SIO library: /home/laborratte/test/venv-nitropy/lib/python3.11/site-packages/libusbsio/bin/linux_x86_64/libusbsio.so
903        INFO  libusbsio HID enumeration[93961937202960]: initialized
903       DEBUG  libusbsio HID enumeration[93961937202960]: device #0: MCU HID GENERIC DEVICE
904       DEBUG  libusbsio HID enumeration[93961937202960]: device #1: 2.4G Wireless Mouse
904        INFO  libusbsio HID enumeration[93961937202960]: finished, total 2 devices
970       DEBUG fido2.hid.linux Failed opening device /dev/hidraw0
Traceback (most recent call last):
  File "/home/laborratte/test/venv-nitropy/lib/python3.11/site-packages/fido2/hid/linux.py", line 98, in list_descriptors
    devices.append(get_descriptor(hidraw))
                   ^^^^^^^^^^^^^^^^^^^^^^
  File "/home/laborratte/test/venv-nitropy/lib/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'
971       DEBUG       root print: Critical error:
971       DEBUG       root print: No Nitrokey 3 device found
971       DEBUG       root listing all connected devices:
1030      DEBUG       root :: 'Nitrokey FIDO2' keys
1030      DEBUG       root :: 'Nitrokey Start' keys:
1051      DEBUG       root :: 'Nitrokey 3' keys
1053       INFO  libusbsio HID enumeration[93961937843472]: initialized
1054      DEBUG  libusbsio HID enumeration[93961937843472]: device #0: MCU HID GENERIC DEVICE
1054      DEBUG  libusbsio HID enumeration[93961937843472]: device #1: 2.4G Wireless Mouse
1054       INFO  libusbsio HID enumeration[93961937843472]: finished, total 2 devices
1120       INFO spsdk.mboot.mcuboot Connect: MCU HID GENERIC DEVICE (0x20A0, 0x42DD)
1120      DEBUG spsdk.mboot.interfaces.usb Open Interface
1120       INFO libusbsio.hidapi.dev Opening HID device at path: 'b'/dev/hidraw1''
1177       INFO libusbsio.hidapi.dev HID device 93961942888784 is now open
1177       INFO spsdk.mboot.mcuboot CMD: GetProperty('UniqueDeviceIdent', index=0)
1178      DEBUG spsdk.mboot.mcuboot TX-PACKET: Tag=GetProperty, Flags=0x00, P[0]=0x00000012, P[1]=0x00000000
1178      DEBUG spsdk.mboot.interfaces.usb OUT[16]: 01, 00, 0C, 00, 07, 00, 00, 02, 12, 00, 00, 00, 00, 00, 00, 00
1178      DEBUG libusbsio.hidapi.dev HID device 93961942888784 writing[16]: 0x01000c00070000021200000000000000
1179      DEBUG libusbsio.hidapi.dev HID device 93961942888784 wrote 59 bytes
1179      DEBUG libusbsio.hidapi.dev HID device 93961942888784 read[60]: 0x03001800a70000050000000037d69462a9e4cf518b0f959c541f856d0000000000000000000000000000000000000000000000000000000000000000
1179      DEBUG spsdk.mboot.interfaces.usb IN [60]: 03, 00, 18, 00, A7, 00, 00, 05, 00, 00, 00, 00, 37, D6, 94, 62, A9, E4, CF, 51, 8B, 0F, 95, 9C, 54, 1F, 85, 6D, 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
1180      DEBUG spsdk.mboot.mcuboot RX-PACKET: Tag=GetPropertyResponse, Status=Success, v0=0x6294D637, v1=0x51CFE4A9, v2=0x9C950F8B, v3=0x6D851F54
1180      DEBUG       root /dev/hidraw1: Nitrokey 3 Bootloader (LPC55) 37D69462A9E4CF518B0F959C541F856D
1180       INFO spsdk.mboot.mcuboot Closing: MCU HID GENERIC DEVICE (0x20A0, 0x42DD)
1180      DEBUG spsdk.mboot.interfaces.usb Close Interface
1182       INFO libusbsio.hidapi.dev HID device 93961942888784 closed
1183      DEBUG       root print: --------------------------------------------------------------------------------
1183      DEBUG       root print: Critical error occurred, exiting now
1183      DEBUG       root print: Unexpected? Is this a bug? Would you like to get support/help?
1183      DEBUG       root print: - You can report issues at: https://support.nitrokey.com/
1184      DEBUG       root print: - Writing an e-mail to support@nitrokey.com is also possible
1184      DEBUG       root print: - Please attach the log: '/tmp/nitropy.log.f062w8_k' with any support/help request!
1184      DEBUG       root print: - Please check if you have udev rules installed: https://docs.nitrokey.com/nitrokey3/linux/firmware-update.html#troubleshooting

Unfortunately I think this killed my device, as nitropy nk3 test now also returns some MBoot error:

Command line tool to interact with Nitrokey devices 0.4.37
Found 1 Nitrokey 3 device(s):
- Nitrokey 3 Bootloader (LPC55) at /dev/hidraw1

Running tests for Nitrokey 3 Bootloader (LPC55) at /dev/hidraw1

[1/4]   uuid        UUID query                  FAILURE     MBoot: Connection issue -> Device not opened
[2/4]   version     Firmware version query      SKIPPED     
[3/4]   status      Device status               SKIPPED     
[4/4]   fido2       FIDO2                       SKIPPED     

4 tests, 0 successful, 3 skipped, 1 failed

Summary: 1 device(s) tested, 0 successful, 1 failed

Critical error:
Test failed for 1 device(s)

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

I do have the udev rules installed.

[robin-nitrokey]

What is the output of nitropy nk3 list?

[robin-nitrokey]

And what happens if you try to run the update again?

[Laborratte5]

nitropy nk3 list returns the following:

Command line tool to interact with Nitrokey devices 0.4.37
:: 'Nitrokey 3' keys
/dev/hidraw0: Nitrokey 3 Bootloader (LPC55) 37D69462A9E4CF518B0F959C541F856D

It seems that restarting the update does something. (I was certain that I tried that but seems like I didn't) Maybe it works this time. I will post the results as soon as the update is finished

[Laborratte5]

After the update finished the same error appeared. However this time the update took over 8h which is twice as much is it took the first time. Also the log contains debug messages for every few bytes written. (Which the first one didn't)

nitropy.log.r609dj3a.log

[robin-nitrokey]

It looks like this is an issue with the bootloader provided by NXP. Can you please try to reproduce the problem using the official NXP tools? If it also happens with these tools, we’ll have to forward this issue to NXP.

1. Install the NXP tooling:

   $ pipx install spsdk

2. Make sure that the device is detected:

   $  spsdk blhost --usb 0x20a0:0x42dd get-property 1
   Response status = 0 (0x0) Success.
   Response word 1 = 1258487808 (0x4b030000)
   Current Version = K3.0.0

3. Extract the raw firmware image:

   $ cd /tmp
   $ nitropy nk3 fetch-update --version v1.4.0 .
   $ sha256sum firmware-nk3-v1.4.0.zip 
   d77286a8f1544214ceed29beec0c9bc6a27da12a099f50c8a8c0af943e210c35  firmware-nk3-v1.4.0.zip
   $ unzip firmware-nk3-v1.4.0.zip
   $ sha256sum --check sha256sums

4. Perform the update:

   $ spsdk blhost --usb 0x20a0:0x42dd receive-sb-file firmware-nk3xn-lpc55-v1.4.0.sb2    

5. Reboot the device:

   $ spsdk blhost --usb 0x20a0:0x42dd reset

[Laborratte5]

This seems to have worked. I just realized because I used a new virtual environment I used spsdk, version 1.10-1 whereas nitropy uses spsdk, version 1.7.1

nitropy nk3 test now returns:

Command line tool to interact with Nitrokey devices 0.4.37
Found 1 Nitrokey 3 device(s):
- Nitrokey 3 at /dev/hidraw1

Running tests for Nitrokey 3 at /dev/hidraw1

[1/4]   uuid        UUID query                  SUCCESS     37D69462A9E4CF518B0F959C541F856D
[2/4]   version     Firmware version query      SUCCESS     v1.4.0
[3/4]   status      Device status               FAILURE     init error: EXTERNAL_FLASH_ERROR (0x4)
Please press the touch button on the device ...
Please press the touch button on the device ...
[4/4]   fido2       FIDO2                       SUCCESS     

4 tests, 3 successful, 0 skipped, 1 failed

Summary: 1 device(s) tested, 0 successful, 1 failed

Critical error:
Test failed for 1 device(s)

But I am unsure whether this is a related Issue or a different. Let me know if I should open a new Issue instead. And thanks for your help so far

[robin-nitrokey]

Hmm, interesting. Can you try to repeat the update with nitropy to check if still fails?

Depending on the firmware version you were running before the update, the External Flash error could be caused by a migration. In that case, it should disappear after a power cycle. If you run nk3 test again, does it still show the error?

[Laborratte5]

If you run nk3 test again, does it still show the error?

A power cycle did solve the issue.

Can you try to repeat the update with nitropy to check if still fails?

The update still fails using nitropy. After that the UUID query of nitropy nk3 test fails again with MBoot: Connection issue -> Device not opened, like it did the first time

nitropy nk3 update log: nitropy.log.57l8bsh8.log nitropy nk3 test log: nitropy.log.j3zh_bcv.log

[Laborratte5]

I also tried your instructions again and this time it also failed with:

ERROR:spsdk.mboot.interfaces.usb:Cannot read from HID device, error=0 (39405177ms since start, usb.py:243)
ERROR:spsdk.mboot.mcuboot:RX: No Response, Timeout Error ! (39405178ms since start, mcuboot.py:227)

Moreover I think there is a correlation between the time to finish the update an the success. This time it also took roughly 10h to finish and fail.

[Laborratte5]

After some more testing I think the issue has something to do either with my (computer)hardware (not the nitrokey) or my operating system, because on a different Computer with a different Operating System (MX Linux in this case) 3/3 times the update succeeded in a matter of seconds.

If I discover something new that may help others I will add it to this issue. For now I'll close this issue as it seems like the problem has nothing to do with pynitrokey.

Nontheless thank you very much for your help