Serial DFU is failing with invalid response

[IvenK]

Hi there,

I'm struggling to get a DFU over serial done. I'm using a nRF52840-DK (PCA10056), the nRF-SDK 15.0 and nrfutil 3.5.0.

I

- genereated the key pair,

- built the secure-bootloader (pca10056_uart_debug) example with my generated public_key.c,

- built the ble_app_blinky (pca10056, s140),

- programmed the s140 v 6.0.0 SoftDevice (chiperase),

- programmed the bootloader (sectorerase) and

- generated DFU package from the ble_app_blinky.hex (sd-req 0xA9) with my private key

When I perform the DFU with nrfutil i get the following error message:

pc_ble_driver_py.exceptions.NordicSemiException: Unexpected Executed OP_CODE.

Expected: 0x03 Received: 0x1D

Further analysis reveal that after the first firmware package is transfered, the host sends a CRC request [0x03] and the answer is [0x60, 0x1D, 0x02].

I have no idea why this is failing or what the response code [0x1D] means.

I would appreciate any help on that matter.

Kind regards,

Iven Kolterjahn

[Einar Thorsrud]

Hi . Iven,

Can you post the full command you used to generate the DFU package and the full command you used to do the DFU operation? (In case there is no problem there, have you attempted to use a newer nrfutil version?)

[IvenK]

Hi Einar,

nrfutil pkg generate --hw-version 52 --application-version 1 --application ble_app_blinky_pca10056_s140_1.hex --sd-req 0xA9 --key-file demo_private.key

DFU operation:

nrfutil dfu serial -pkg app_fw1.zip -p /dev/ttyACM0 -b 115200

The thing is, in the end I'll use an ARM-based processor running Linux and utilizing the UartSecureDFU from Jimmy Wong. It is based upon the nrfutil v3.5.0. I generate the Linux using Yocto and got some trouble including the nrfutil as a python application. So, I found JW's C application.

[Einar Thorsrud]

I see.

Going back at the reply from the CRC request is (first to last byte):

1. 0x60: NRF_DFU_OP_RESPONSE (0x60)
2. 0x1D: unknown request code
3. 0x02. NRF_DFU_RES_CODE_OP_CODE_NOT_SUPPORTED

So as you pointed out, the request code (0x1D in this case) seems wrong, as it is not part of the supported codes (refer to <SDK>/components/libraries/bootloader/dfu/nrf_dfu_req_handler.h).

Is this test is done with an unmodified nrfutil 3.5.0 or with some modifications? Could it be that there is a problem with the request from the DFU master? Have you checked on the UART line what is actually being sent? 

[IvenK]

I used the pre-compiled binary (.exe) supplied on GitHub (pc-nrfutil, v3.5.0) to generate the packages on a Windows machine. The reference DFU operation took place on an Ubuntu machine with nrfutil (v3.5.0) installed via the setup.py.

According to the CLI output from UartSecureDFU it sends 0x03 (NRF_DFU_OP_CRC_GET). The output of nrfutil was as mentioned above "... Expected: 0x03 Received: 0x1D". I haven't checked manually what is sent via USB though. On the other hand, both programs seem to get the same response from the DevKit.

Here is the CLI output of UartSecureDFU (values are decimal):

UartSecureDFU ttyACM0 ./app_uart_fw1.zip -v -v -v
Sending Application image.
SLIP: --> [9, 1]
SLIP: <-- [96, 9, 1, 1]
Set Packet Receipt Notification 0
SLIP: --> [2, 0, 0]
SLIP: <-- [96, 2, 1]
SLIP: --> [7]
SLIP: <-- [96, 7, 1, 131, 0]
Sending init packet...
Selecting Object: type:1
SLIP: --> [6, 1]
SLIP: <-- [96, 6, 1, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
Object selected:  max_size:256 offset:0 crc:0x00000000
SLIP: --> [1, 1, 135, 0, 0, 0]
SLIP: <-- [96, 1, 1]
Streaming Data: len:135 offset:0 crc:0x00000000
SLIP: --> [8, 18, 132, 1, 10, 62, 8, 1, 18, 58, 8, 1, 16, 52, 26, 2, 169, 1, 32, 0, 40, 0, 48, 0, 56, 160, 171, 1, 66, 36, 8, 3, 18, 32, 193, 220, 134, 164, 132, 220, 167, 77, 51, 250, 203, 217, 25, 23, 53, 71, 57, 112, 210, 94, 255, 134, 96, 21, 97, 179, 134, 38, 38, 253, 29]
SLIP: --> [8, 52, 72, 0, 16, 0, 26, 64, 238, 16, 46, 112, 45, 1, 144, 12, 16, 227, 209, 254, 152, 11, 203, 53, 147, 83, 159, 170, 244, 112, 239, 1, 18, 100, 180, 164, 86, 198, 202, 1, 202, 72, 251, 111, 128, 16, 28, 103, 222, 77, 176, 28, 179, 204, 241, 144, 89, 82, 29, 10, 237, 127, 252, 178, 42]
SLIP: --> [8, 87, 127, 228, 229, 216, 175, 118]
SLIP: --> [3]
SLIP: <-- [96, 29, 2]
Invalid response!

[Einar Thorsrud]

Hi,

I see. So everything looks OK until the bootloader complains about the unsupported OP_CODE, which was never transmitted by nrfutil in the first place. I think we need to look at what happens in the bootloader.

Perhaps the best would be to put a breakpoint in the NRF_DFU_OP_CRC_GET case in nrf_dfu_data_req() in <SDK>components\libraries\bootloader\dfu\nrf_dfu_req_handler.c. Does it get this far? If not, what happens? If the request is correctly received, how is it processed? How does it result in the error response?

[IvenK]

Hi Einar,

debugging doesn't seem to work here. When I try to debug the code in SES the whole DFU process just hangs. I see some communication in the debug console, but then it just stops (SES seems to freeze also). SES starts responding after I unplugged the nRF-Board.

This is the output of the SES debug console:

<info> app: Inside main
<debug> app: In nrf_bootloader_init
<debug> nrf_dfu_settings: Calling nrf_dfu_settings_init()...
<debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
<debug> app: Enter nrf_bootloader_fw_activate
<info> app: No firmware to activate.
<debug> app: Enter nrf_dfu_app_is_valid
<debug> app: Return false in valid app check
<debug> app: DFU mode because app is not valid.
<info> nrf_bootloader_wdt: WDT is not enabled
<debug> app: in weak nrf_dfu_init_user
<info> app_timer: RTC: initialized.
<info> app: Entering DFU mode.
<debug> app: Initializing transports (found: 1)
<debug> nrf_dfu_serial_uart: serial_dfu_transport_init()
<debug> nrf_dfu_serial_uart: serial_dfu_transport_init() completed
<debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
<debug> app: Enter main loop
<debug> app: Shutting down transports (found: 1)
<debug> nrf_dfu_serial: Received ping 1
<info> nrf_dfu_serial_uart: Allocated buffer 200033AC
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_PING
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial: Sending Response: [0x9, 0x1]
<debug> app: Shutting down transports (found: 1)
<debug> nrf_dfu_serial: Set receipt notif target: 0
<info> nrf_dfu_serial_uart: Allocated buffer 200033AC
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_RECEIPT_NOTIF_SET
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial: Sending Response: [0x2, 0x1]
<debug> app: Shutting down transports (found: 1)
<debug> nrf_dfu_serial: Received serial mtu
<info> nrf_dfu_serial_uart: Allocated buffer 200033AC
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_MTU_GET
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial: Sending Response: [0x7, 0x1]
*** HERE IT FREEZES. THE LINES BELOW APPEAR AFTER THE DISCONNECT ***
<debug> app: Shutting down transports (found: 1)
<info> nrf_dfu_serial_uart: Allocated buffer 200033AC
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_SELECT (command)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial: Sending Response: [0x6, 0x1]

I tried using the SDK 16.0.0 with nrfutil v6.0.1, but this also does not work. Strangely here I get 0xB3 as response (instead of 0x1D) to the CRC request.