search

Nitrokey / pynitrokey

Python client for Nitrokey devices
Apache License 2.0
98 stars 27 forks source link

'nitropy nk3 update' prints a lot of spsdk debug messages to the console #389

Closed jjakob closed 1 year ago

jjakob commented 1 year ago

A lot of these debug messages are printed to the console, which means the progress bar is not visible and it quickly fills up the scrollback buffer of the terminal:

DEBUG:spsdk.mboot.interfaces.usb:OUT[60]: 02, 00, 38, 00, A4, 40, 8B, BD, C3, 25, 57, CD, 18, 95, 86, 09, FC, B0, B3, 8F, 4B, 0E, 80, 26, 35, 4D, 48, 01, D6, 50, B1, 41, 6E, C7, 86, CF, F3, 31, A5, 77, A7, 94, 52, C3, FD, 69, 41, DF, 93, 0A, 6A, 39, D1, 7A, D0,
10, A5, 6D, 55, 48 (22642ms since start, usb.py:125)

spsdk seems to default to no level (NOTSET) which means it logs everything https://github.com/nxp-mcuxpresso/spsdk/blob/2facbebd4e1f023099557803d163820e07937d1b/spsdk/__init__.py#L111

I found a way to set this to INFO, create ~/.spsdk/logging.yaml which contains:

version: 1
incremental: True
loggers:
  spsdk:
    level: INFO

After this only INFO level spsdk messages are printed:

$ nitropy nk3 update firmware-nk3-v1.4.0.zip
Logging config loaded from /home/jernej/.spsdk/logging.yaml
Command line tool to interact with Nitrokey devices 0.4.36
Current firmware version:  v1.4.0
Updated firmware version:  v1.4.0
The version of the firmware image is the same as on the device.  Do you want to continue anyway? [y/N]: y

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

INFO:spsdk.mboot.mcuboot:Connect: MCU HID GENERIC DEVICE (0x20A0, 0x42DD) path=b'/dev/hidraw5'
INFO:spsdk.mboot.mcuboot:CMD: ReceiveSBfile(data_length=451152)
INFO:spsdk.mboot.mcuboot:CMD: GetProperty('MaxPacketSize', index=0)
INFO:spsdk.mboot.mcuboot:CMD: Max Packet Size = 56
Perform firmware update: 100%|█████████████████████████████████████████████████████████████████▊| 450k/451k [00:05<00:00, 76.9kB/s]INFO:spsdk.mboot.mcuboot:CMD: Successfully Send 451152 out of 451152 Bytes
INFO:spsdk.mboot.mcuboot:CMD: Reset MCU
INFO:spsdk.mboot.mcuboot:Closing: MCU HID GENERIC DEVICE (0x20A0, 0x42DD) path=b'/dev/hidraw5'
Perform firmware update: 100%|██████████████████████████████████████████████████████████████████| 451k/451k [00:05<00:00, 75.6kB/s]
Finalize upgrade: 100%|███████████████████████████████████████████████████████████████████████████| 100/100 [00:01<00:00, 83.54%/s]

It might make sense to set this to an even higher severity like WARNING, ERROR or CRITICAL. If debug messages are wanted, they could be saved to a log file in a tmpfs (like nitropy does to /tmp/nitropy.log.*) by adding a new handler to logging.yaml. Of course this should be configured by nitropy itself, if it can set imported spsdk logger config itself so that this config file is not needed. I'm not sure how or if a change in spsdk is needed.

jjakob commented 1 year ago

https://github.com/nxp-mcuxpresso/spsdk/issues/54

jjakob commented 1 year ago

This is probably because I am using spsdk 1.10.0 instead of the pyproject.toml specified 1.7, the logger was added in spsdk 1.9.0. So it's not a problem when using the "correct" dependency versions, but will need to be adressed when updating the spsdk dependency.

robin-nitrokey commented 1 year ago

This will be fixed in https://github.com/Nitrokey/pynitrokey/pull/364.