serial secure bootloader stops in mid session

[vigil-jguo]

Hi, I have been running into some problems with the serial secure bootloader example in the SDKv13.1.

I build the example project from the SDK v13.1 with a custom generated public key file, and only flash SD + BL to the eval board to test.  The firmware package  used includes (BL + SD + APP).  The key and the firmware package work fine as I have used them for OTA BLE DFU upgrades. 

When initiating the dfu process through nrfutil,  it appears that everything is starting up, and packages are getting transferred over, but at 78% I get a error saying that serial port does not respond to ping.  This is repeatable and the progress bar always shows 78% when the error occurs.

Any insight into this is greatly appreciated, enclosed is a screen shot of the error.  

I will try to provide more information later by turning nrf_log on,  I have a project that integrates both serial and ble transport layer with logging turned on, but decided to validate the behaviour of example serial bootloader by itself before trying on my own to better isolate potential errors. 

Best regards,

Jian 

[vigil-jguo]

Hi, I have updated the serial bootloader example to log to SEGGER RTT, and attempted the DFU again.  By digging into the nrfutil python code, it seems there may be several issues.

in the dfu_transport_serial.py, when the serial port is opened, a ping (OP_CODE 0x09, message length 1 byte) is sent apparently.  On the BLE side, this op code is unknown, and a response [0x09, 0x03] is sent back.  However, this is ignored by the nrfutil python scripts somehow.

I tried setting the ping_success to true in the python script to get to the next step of the nrfutil dfu process to keep sending the package content, but there seems to be additional errors.

Am I using a wrong version of nrfutil that is not supported here?  Enclosed are the log from python and SEGGER RTT 

[Bjørn Kvaale]

Sorry for the delayed response. I just tested the same example from SDK13.1 & tried updating the blinky application located here: nRF5_SDK_13.1.0_7ca7556\examples\peripheral\blinky\pca10040\s132\arm5_no_packs\. I ran the exact same nrfutil command that you did, but did not receive as much output as you did (most likely because the DFU was successful, but it might be because the DFU zip file only included the application).

The only output I received was the DFU reaching 100% & "Device programmed".

From the device RTT viewer log, I received:

 0> :INFO:
 0> :INFO:PB: Init packet data len: 57
 0> :INFO:Handling signed command
 0> :INFO:Req version: 1, Expected: 0
 0> :INFO:Calculating init packet hash
 0> :INFO:Verify signature
 0> :INFO:Image verified
 0> :INFO:Running hash check
 0> :DEBUG:Enter nrf_dfu_find_cache
 0> :DEBUG:Bank content
 0> :DEBUG:Bank type: 0
 0> :DEBUG:Bank 0 code: 0x00: Size: 0
 0> :DEBUG:Bank 1 code: 0x00: Size: 0
 0> :DEBUG:No previous, using bank 0
 0> :INFO:Write address set to 0x0001f000
 0> :INFO:DFU prevalidate SUCCESSFUL!
 0> :INFO:Prevalidate OK.
 0> :INFO:Saving init command...
 0> :DEBUG:Erasing old settings at: 0x0007f000
 0> :DEBUG:Erasing: 0x0007f000, num: 1
 0> :DEBUG:Writing 0x00000057 words
 0> :DEBUG:Writing settings...
 0> :INFO:Setting DFU flag to initialized
 0> :DEBUG:Sending Response: [0x4, 0x1]
 0> :DEBUG:Received select object
 0> :INFO:Valid Data Read info
 0> :DEBUG:Sending Response: [0x6, 0x1]
 0> :DEBUG:Received create object
 0> :INFO:Before OP create
 0> :INFO:Valid Data Create
 0> :DEBUG:Erasing: 0x0001f000, num: 1
 0> :INFO:Creating object with size: 4096. Offset: 0x00000000, CRC: 0x00000000
 0> :DEBUG:Sending Response: [0x1, 0x1]
 0> :INFO:Storing 256 B at: 0x0001f000
 0> :INFO:Storing 256 B at: 0x0001f100
 0> :INFO:Storing 256 B at: 0x0001f200
 0> :INFO:Storing 256 B at: 0x0001f300
 0> :INFO:Storing 256 B at: 0x0001f400
 0> :INFO:Storing 256 B at: 0x0001f500
 0> :INFO:Storing 256 B at: 0x0001f600
 0> :INFO:Storing 256 B at: 0x0001f700
 0> :INFO:Storing 256 B at: 0x0001f800
 0> :INFO:Storing 256 B at: 0x0001f900
 0> :INFO:Storing 256 B at: 0x0001fa00
 0> :INFO:Storing 256 B at: 0x0001fb00
 0> :INFO:Storing 256 B at: 0x0001fc00
 0> :INFO:Storing 256 B at: 0x0001fd00
 0> :INFO:Storing 256 B at: 0x0001fe00
 0> :INFO:Storing 256 B at: 0x0001ff00
 0> :DEBUG:Received calculate CRC
 0> :INFO:Before OP crc
 0> :DEBUG:Sending Response: [0x3, 0x1]
 0> :DEBUG:Received execute object
 0> :INFO:Before OP execute
 0> :INFO:Valid Data Execute
 0> :DEBUG:Erasing old settings at: 0x0007f000
 0> :DEBUG:Erasing: 0x0007f000, num: 1
 0> :DEBUG:Writing 0x00000057 words
 0> :DEBUG:Writing settings...
 0> :DEBUG:Sending Response: [0x4, 0x1]
 0> :DEBUG:Received create object
 0> :INFO:Before OP create
 0> :INFO:Valid Data Create
 0> :DEBUG:Erasing: 0x00020000, num: 1
 0> :INFO:Creating object with size: 60. Offset: 0x00001000, CRC: 0x5c74f16f
 0> :DEBUG:Sending Response: [0x1, 0x1]
 0> :INFO:Storing 60 B at: 0x00020000
 0> :DEBUG:Received calculate CRC
 0> :INFO:Before OP crc
 0> :DEBUG:Sending Response: [0x3, 0x1]
 0> :DEBUG:Received execute object
 0> :INFO:Before OP execute
 0> :INFO:Valid Data Execute
 0> :DEBUG:Erasing old settings at: 0x0007f000
 0> :DEBUG:Erasing: 0x0007f000, num: 1
 0> :DEBUG:Writing 0x00000057 words
 0> :DEBUG:Writing settings...
 0> :INFO:Waiting for 0 pending flash operations before doing postvalidate.
 0> :INFO:Doing postvalidate
 0> :INFO:Current bank is bank 0
 0> :INFO:Running SD version check ============== 
 0> :INFO:Successfully ran the postvalidation check!
 0> :DEBUG:Erasing old settings at: 0x0007f000
 0> :DEBUG:Erasing: 0x0007f000, num: 1
 0> :DEBUG:Writing 0x00000057 words
 0> :INFO:Inside main
 0> :DEBUG:In nrf_bootloader_init
 0> :DEBUG:In real nrf_dfu_init
 0> :DEBUG:running nrf_dfu_settings_init
 0> :DEBUG:Enter nrf_dfu_continue
 0> :DEBUG:Valid App
 0> :DEBUG:Enter nrf_dfu_app_is_valid
 0> :DEBUG:Return true. App was valid
 0> :DEBUG:Enter nrf_dfu_app_is_valid
 0> :DEBUG:Return true. App was valid
 0> :DEBUG:Jumping to: 0x0001f000
 0> :DEBUG:Running nrf_bootloader_app_start with address: 0x0001f000
 0> :DEBUG:Disabling interrupts
 0> :DEBUG:Setting SD vector table base: 0x0001f000

I have been running nrfutil version 3.4.0, while I believe you are running 3.3.0, correct? You could try updating to nrfutil 3.4.0 to see if that helps. I could try creating a DFU zip file with app, softdevice & bootloader to see if that might cause an issue if you want.

 

 

[vigil-jguo]

Hi Bjorn,

It seems that there might be some difference between what you and I are running.  I tried to minimise the differences between our set up, but is unable to achieve the same results you had.  Maybe you can see something that I cannot.

Here's what I did:

1. From a clean SDK13.1.0_7ca7556, I tried to build the serial bootloader with the following changes

  * a. enable NRF_LOG and set it to output to Segger RTT instead of UART

  * b. disable deferred logging in NRF_LOG and enable debug level logging

  * b. swap out dfu_public_key.c to a public key of my choosing

  * with the added printing, I needed more memory for the bootloader, so my IROM1 starts at 0x75000 with size of 0x9000

Fullscreen dfu_public_key.c Download

/* This file was automatically generated by nrfutil on 2018-01-23 (YY-MM-DD) at 14:18:23 */

#include "stdint.h"
#include "compiler_abstraction.h"

/** @brief Public key used to verify DFU images */
__ALIGN(4) const uint8_t pk[64] =
{
    0x48, 0xd5, 0x16, 0x66, 0xf3, 0x09, 0xca, 0x60, 0x30, 0x23, 0x3b, 0x46, 0x5f, 0x14, 0x28, 0xee, 0xf2, 0x18, 0x82, 0x63, 0x7d, 0xc7, 0x94, 0xb6, 0x7c, 0x3a, 0x5b, 0x88, 0x8d, 0xfd, 0xdb, 0x9d, 
    0x71, 0x3d, 0x17, 0x8a, 0xbb, 0x53, 0x9e, 0xa5, 0x55, 0x81, 0x40, 0x28, 0x31, 0x10, 0x6c, 0x66, 0x5e, 0xc5, 0xfd, 0x69, 0x92, 0x40, 0xef, 0xc6, 0x19, 0x8e, 0x50, 0x0a, 0x24, 0x95, 0x44, 0xb5
};

2. I deleted my existing nrfutil and downloaded a release .exe version of nrfutil v3.4 to eliminate discrepancies in the util.

3. generated firmware packages for SD+BL+APP and another one just for APP, for the app, I used the hex provided in the ble_peripheral/ble_app_uart examples

4. erased my dev board, and reflashed softdevice and bootloader with secure key. 

5. run nrfutil dfu serial command

Unfortunately, I still run into the same issue, as seen below.

Fullscreen bootloader_sequence.log Download

# SEGGER J-Link RTT Viewer V6.20b Terminal Log File
# Compiled: 17:58:36 on Sep 22 2017
# Logging started @ 23 Mar 2018 16:01:51
 0> :INFO:Inside main
 0> :DEBUG:In nrf_bootloader_init
 0> :DEBUG:In real nrf_dfu_init
 0> :DEBUG:running nrf_dfu_settings_init
 0> :DEBUG:Enter nrf_dfu_continue
 0> :ERROR:Single: Invalid bank
 0> :DEBUG:Enter nrf_dfu_app_is_valid
 0> :DEBUG:Return false in valid app check
 0> :DEBUG:In nrf_dfu_transports_init
 0> :DEBUG:num transports: 1
 0> :DEBUG:UART initialized
 0> :DEBUG:After nrf_dfu_transports_init
 0> :DEBUG:Waiting for events
 0> :WARNING:Received unsupported OP code
 0> :DEBUG:Sending Response: [0x9, 0x3]

# Logging stopped @ 23 Mar 2018 16:03:45

So, I do not see why this is failing, the only 2 things that might cause this are:

1. micro-ecc lib, I have used the one I build before, but I don't really think this is the cause of error

2. uart communication issue. As far as I can tell from the python script of the nrfutil before, it is indeed sending pings 0x09 to the uart line, and it seems to be doing the same in the nrfutil v3.4 as well.  The uart connection seems fine too with 115200 bps 8 bit no parity bit.  I had seen bootloader log from uart before I switched to RTT for logging.  So it seems to me that the UART Lines work as well.

As I am unable to reproduce the same results you had and unable to conclude the source of the error, I have included my project along with micro-ecc library, the private.key and public key, the scripts I used to generate the DFU package and the packages I used for testing int the zip below.  If you can give this a try and see what the result is on your setup that'd be great.

the DFU directory is a direct drop-in replacement for the examples/dfu, micro-ecc and the .lib go under the external/micro-ecc/ directory. 

3301.dfu.zip

best regards,

Jian

[Bjørn Kvaale]

Hi Jian,

Sorry for the delayed response. We are slightly understaffed at the moment due to Easter vacation, so it's taking us a bit longer than usual to answer Devzone questions.

Just finished testing your application. Followed the testing guide located on the Infocenter. Erased the board using nrfjprog --eraseall. Programmed the S132 v4.0.2 SD first, then compiled & programmed your bootloader. If this step works, you should not have any issues with your micro-ecc setup. Used your public key & the test-bl_sd_app_dfu_package.zip file you provided. Used nrf connect to figure out which COM port to use. Updated the nrf52 DK with the nrfutil dfu command found in the Infocenter link I mentioned above.

I did not have any issues with your setup. Have you tried with a different usb cable & using a different usb port? Maybe that will solve this weird issue.

Kind Regards,

Bjorn