Need help with a custom DFU transport

[brooksp]

Hi all,

I'm working on a custom Bootloader for my nrf52840-based board, and it needs to support DFU from external SPI Flash. I previously was successful with a "first draft" where I implemented by own DFU protocol (see https://devzone.nordicsemi.com/f/nordic-q-a/62777/need-help-with-custom-dfu-bootloader-transferring-back-to-main-app), and now I'm trying to use the NRF5 SDK's DFU by creating my own DFU transport.

I've had success so far in creating the firmware package and storing both the init packet and firmware image to external Flash. I can successfully read the data in the bootloader too. But now my issue is figuring out the details of the transport layer, and in particular, the request layer.

I'm currently using the 15.0 SDK, but I may be able to switch/upgrade if necessary.

Other support threads pointed me to the SDK's documentation, and specifically the Message Sequence Charts

https://infocenter.nordicsemi.com/topic/com.nordic.infocenter.sdk5.v15.0.0/lib_dfu_transport_serial.html

These charts have been very helpful, especially while also looking at the DFU example projects.

My needs are to have DFU over both BLE and external SPI Flash, so I've started with the secure_bootloader_ble_s140_pca10056 example and added custom Transport and Request code.

Here's the code for the Transport:

#define NRF_LOG_MODULE_NAME wa_dfu_transport
#include "nrf_log.h"
#include "nrf_log_ctrl.h"
NRF_LOG_MODULE_REGISTER();

#include "wa_dfu_transport.h"
#include "wa_dfu_req_handler.h"
#include "wa_dfu.h"

#include "spi_flash_block.h"
#include "nrf_dfu_transport.h"


// Forward declarations for DFU_TRANSPORT_REGISTER below
static uint32_t wa_dfu_transport_init(nrf_dfu_observer_t);
static uint32_t wa_dfu_transport_close(const nrf_dfu_transport_t *);

DFU_TRANSPORT_REGISTER(const nrf_dfu_transport_t wa_dfu_transport) =
{
    .init_func  = wa_dfu_transport_init,
    .close_func = wa_dfu_transport_close,
};






static nrf_dfu_observer_t m_observer;





static struct wa_dfu_header read_header(void)
{
    struct wa_dfu_header header = {};
    const ret_code_t error = spi_flash_block_read_data(WA_DFU_HEADER_OFFSET, &header, sizeof(header));
    if (error)
    {
        NRF_LOG_ERROR("Error %u: Failed to read DFU header from SPI Flash!", error);
    }
    return header;
}



static ret_code_t read_from_flash_and_write_object(const nrf_dfu_obj_type_t type, const nrf_dfu_response_select_t select, const struct wa_dfu_metadata metadata)
{
    NRF_LOG_DEBUG("{ %s", __func__);

    uint8_t buf[CODE_PAGE_SIZE];
    size_t index = 0;

    while (index < metadata.size)
    {
        const uint32_t read_address = metadata.offset + index;
        const size_t remaining_size = metadata.size - index;
        const size_t max_read_size = MIN(sizeof(buf), remaining_size);
        const size_t read_size = max_read_size; // MIN(max_read_size, select.max_size); TODO: How do I use select.max_size correctly?
        NRF_LOG_DEBUG("index: %u, remaining size: %u, read size: %u, read addr: 0x%08X", index, remaining_size, read_size, read_address);
        if (NRF_LOG_DEFAULT_LEVEL >= 4) NRF_LOG_FLUSH();

        wa_dfu_req_object_create(type, read_size);

        ret_code_t error = spi_flash_block_read_data(read_address, buf, read_size);
        if (error)
        {
            NRF_LOG_ERROR("Error %u: DFU failed while reading firmware image from SPI Flash! address: 0x%08X, size: %u", read_address, read_size);
            return error;
        }

        wa_dfu_req_object_write(buf, read_size);

        index += read_size;
    }

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
}




static ret_code_t do_dfu(const nrf_dfu_obj_type_t type, const struct wa_dfu_metadata metadata)
{
    NRF_LOG_DEBUG("{ %s", __func__);

    const nrf_dfu_response_select_t select = wa_dfu_req_object_select(type);
    if (select.crc == metadata.crc && select.offset == metadata.size)
    {
        NRF_LOG_INFO("CRCs and sizes match; skipping DFU.");
        return NRF_SUCCESS;
    }

    ret_code_t ret_val = read_from_flash_and_write_object(type, select, metadata);
    VERIFY_SUCCESS(ret_val);

    // TODO: read CRC and validate transfer

    wa_dfu_req_object_execute();

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
    return NRF_SUCCESS;
}




static void update_device_firmware(void)
{
    NRF_LOG_DEBUG("{ %s", __func__);

    wa_dfu_req_set_prn(0);
    wa_dfu_req_set_mtu(CODE_PAGE_SIZE);

    const struct wa_dfu_header header = read_header();

    ret_code_t ret_val = do_dfu(NRF_DFU_OBJ_TYPE_COMMAND, header.init_packet);
    // TODO: handle errors

    ret_val = do_thingy(NRF_DFU_OBJ_TYPE_DATA, header.firmware_image);
    // TODO: handle errors

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
}


static uint32_t wa_dfu_transport_init(nrf_dfu_observer_t observer)
{
    NRF_LOG_DEBUG("Initializing WA DFU transport...");
    
    m_observer = observer;
    if (m_observer)
    {
        // TODO: Is this needed? Should I remove it?
        m_observer(NRF_DFU_EVT_TRANSPORT_ACTIVATED);
    }

    spi_flash_block_init();
    update_device_firmware();
    spi_flash_block_uninit();

    NRF_LOG_DEBUG("Initializing WA DFU transport... done");
    NRF_LOG_FLUSH();
    return NRF_SUCCESS;
}

static uint32_t wa_dfu_transport_close(const nrf_dfu_transport_t * p_exception)
{
    NRF_LOG_DEBUG("Closing WA DFU transport...");

    // TODO: anything to implement here?

    if (m_observer)
    {
        m_observer(NRF_DFU_EVT_TRANSPORT_DEACTIVATED);
    }

    NRF_LOG_DEBUG("Closing WA DFU transport... done");
    NRF_LOG_FLUSH();
    return NRF_SUCCESS;
}

And here's the code for the Request:

#define NRF_LOG_MODULE_NAME wa_dfu_req_handler
#include "nrf_log.h"
#include "nrf_log_ctrl.h"
NRF_LOG_MODULE_REGISTER();

#include "wa_dfu_req_handler.h"






static void set_prn_callback(nrf_dfu_response_t * p_res, void * p_context)
{
    NRF_LOG_DEBUG("{ %s", __func__);
    ASSERT(p_res != NULL);
    ASSERT(p_res->request == NRF_DFU_OP_RECEIPT_NOTIF_SET);
    UNUSED_PARAMETER(p_context);

    if (p_res->result != NRF_DFU_RES_CODE_SUCCESS)
    {
        NRF_LOG_DEBUG("Request %u returned error %u!", p_res->request, p_res->result);
    }

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
}

void wa_dfu_req_set_prn(uint32_t prn)
{
    NRF_LOG_DEBUG("{ %s", __func__);

    nrf_dfu_request_t request =
    {
        .request           = NRF_DFU_OP_MTU_GET,
        .prn.target        = prn,
        .callback.response = set_prn_callback,
        .p_context         = NULL,
    };

    ret_code_t ret_code = nrf_dfu_req_handler_on_req(&request);
    ASSERT(ret_code == NRF_SUCCESS);
    NRF_LOG_DEBUG("prn: %u", prn)

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
}









static void set_mtu_callback(nrf_dfu_response_t * p_res, void * p_context)
{
    NRF_LOG_DEBUG("{ %s", __func__);
    ASSERT(p_res != NULL);
    ASSERT(p_res->request == NRF_DFU_OP_MTU_GET);

    if (p_res->result != NRF_DFU_RES_CODE_SUCCESS)
    {
        NRF_LOG_ERROR("Request %u returned error %u!", p_res->request, p_res->result);
    }

    const uint16_t request_mtu = *(uint16_t *)p_context;
    const uint16_t response_mtu = p_res->mtu.size;
    if (response_mtu != request_mtu)
    {
        NRF_LOG_WARNING("Requested MTU is different from response! request: %u, response: %u", request_mtu, response_mtu)
    }

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
}

void wa_dfu_req_set_mtu(uint16_t size)
{
    NRF_LOG_DEBUG("{ %s", __func__);

    nrf_dfu_request_t request =
    {
        .request           = NRF_DFU_OP_MTU_GET,
        .mtu.size          = size,
        .callback.response = set_mtu_callback,
        .p_context         = &size,
    };

    ret_code_t ret_code = nrf_dfu_req_handler_on_req(&request);
    ASSERT(ret_code == NRF_SUCCESS);
    NRF_LOG_DEBUG("mtu size: %u", size);

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
}







static void crc_callback(nrf_dfu_response_t * p_res, void * p_context)
{
    NRF_LOG_DEBUG("{ %s", __func__);
    ASSERT(p_res != NULL);
    ASSERT(p_res->request == NRF_DFU_OP_CRC_GET);

    if (p_res->result != NRF_DFU_RES_CODE_SUCCESS)
    {
        NRF_LOG_ERROR("Request %u returned error %u!", p_res->request, p_res->result);
    }

    uint32_t * crc = (uint32_t *)p_context;
    *crc = p_res->crc.crc;

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
}

uint32_t wa_dfu_req_crc(void)
{
    NRF_LOG_DEBUG("{ %s", __func__);

    uint32_t crc = 0xBADF00D;
    nrf_dfu_request_t request =
    {
        .request           = NRF_DFU_OP_CRC_GET,
        .callback.response = crc_callback,
        .p_context         = &crc,
    };

    ret_code_t ret_code = nrf_dfu_req_handler_on_req(&request);
    ASSERT(ret_code == NRF_SUCCESS);
    NRF_LOG_DEBUG("crc: 0x%08X", crc);

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
    return crc;
}










static void object_select_callback(nrf_dfu_response_t * p_res, void * p_context)
{
    NRF_LOG_DEBUG("{ %s", __func__);
    ASSERT(p_res != NULL);
    ASSERT(p_res->request == NRF_DFU_OP_OBJECT_SELECT);

    if (p_res->result != NRF_DFU_RES_CODE_SUCCESS)
    {
        NRF_LOG_ERROR("Request %u returned error %u!", p_res->request, p_res->result);
    }

    nrf_dfu_response_select_t * select = (nrf_dfu_response_select_t *)p_context;
    *select = p_res->select;

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
}

nrf_dfu_response_select_t wa_dfu_req_object_select(nrf_dfu_obj_type_t type)
{
    NRF_LOG_DEBUG("{ %s", __func__);

    nrf_dfu_response_select_t select = {};
    nrf_dfu_request_t request =
    {
        .request            = NRF_DFU_OP_OBJECT_SELECT,
        .select.object_type = type,
        .callback.response  = object_select_callback,
        .p_context          = &select,
    };

    ret_code_t ret_code = nrf_dfu_req_handler_on_req(&request);
    ASSERT(ret_code == NRF_SUCCESS);
    NRF_LOG_DEBUG("crc: 0x%08X, size: %u", select.crc, select.offset);

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
    return select;
}





static void object_create_callback(nrf_dfu_response_t * p_res, void * p_context)
{
    NRF_LOG_DEBUG("{ %s", __func__);
    ASSERT(p_res != NULL);
    ASSERT(p_res->request == NRF_DFU_OP_OBJECT_CREATE);
    UNUSED_PARAMETER(p_context);

    if (p_res->result != NRF_DFU_RES_CODE_SUCCESS)
    {
        NRF_LOG_ERROR("Request %u returned error %u!", p_res->request, p_res->result);
    }

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
}

void wa_dfu_req_object_create(nrf_dfu_obj_type_t type, uint32_t size)
{
    NRF_LOG_DEBUG("{ %s", __func__);

    nrf_dfu_request_t request =
    {
        .request            = NRF_DFU_OP_OBJECT_CREATE,
        .create.object_type = type,
        .create.object_size = size,
        .callback.response  = object_create_callback,
        .p_context          = NULL,
    };

    ret_code_t ret_code = nrf_dfu_req_handler_on_req(&request);
    ASSERT(ret_code == NRF_SUCCESS);
    NRF_LOG_DEBUG("object create: type: %d, size: %u", type, size);

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
}






static void object_write_callback(nrf_dfu_response_t * p_res, void * p_context)
{
    NRF_LOG_DEBUG("{ %s", __func__);
    ASSERT(p_res != NULL);
    ASSERT(p_res->request == NRF_DFU_OP_OBJECT_WRITE);
    UNUSED_PARAMETER(p_context);

    if (p_res->result != NRF_DFU_RES_CODE_SUCCESS)
    {
        NRF_LOG_ERROR("Request %u returned error %u!", p_res->request, p_res->result);
    }

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
}

void wa_dfu_req_object_write(const uint8_t * data, uint16_t size)
{
    NRF_LOG_DEBUG("{ %s", __func__);

    nrf_dfu_request_t request =
    {
        .request           = NRF_DFU_OP_OBJECT_WRITE,
        .write.p_data      = data,
        .write.len         = size,
        .callback.response = object_write_callback,
        .p_context         = NULL,
    };

    ret_code_t ret_code = nrf_dfu_req_handler_on_req(&request);
    ASSERT(ret_code == NRF_SUCCESS);
    NRF_LOG_DEBUG("object write: data: %08p, size: %u", data, size);

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
}











static void object_execute_callback(nrf_dfu_response_t * p_res, void * p_context)
{
    NRF_LOG_DEBUG("{ %s", __func__);
    ASSERT(p_res != NULL);
    ASSERT(p_res->request == NRF_DFU_OP_OBJECT_EXECUTE);
    UNUSED_PARAMETER(p_context);

    if (p_res->result != NRF_DFU_RES_CODE_SUCCESS)
    {
        NRF_LOG_ERROR("Request %u returned error %u!", p_res->request, p_res->result);
    }

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
}

void wa_dfu_req_object_execute(void)
{
    NRF_LOG_DEBUG("{ %s", __func__);

    nrf_dfu_request_t request =
    {
        .request           = NRF_DFU_OP_OBJECT_EXECUTE,
        .callback.response = object_execute_callback,
        .p_context         = NULL,
    };

    ret_code_t ret_code = nrf_dfu_req_handler_on_req(&request);
    ASSERT(ret_code == NRF_SUCCESS);

    NRF_LOG_DEBUG("} %s", __func__);
    NRF_LOG_FLUSH();
}

Hopefully that's sufficient to understand my questions, but if you need more let me know and I'll be happy to provide it.

My Issue

When the Bootloader runs, I see debug prints indicating my transport was found, and that my transport's init() function is called. I then see various requests are placed for object select, create, write, and execute. However, I never see any of the callbacks getting run.

I had assumed that the callbacks would happen within the requests, effectively treating the requests as blocking, but I no longer think that's the case. I see this somewhat confirmed when step-debugging, and inside nrf_dfu_req_handler_req() where it calls app_sched_event_put(), that function fails indicating the scheduler ran out of space.

Now my questions:

1. Am I on the right path? I.e. is my transport/request pattern the right idea?
2. If yes to (1), is my algorithm correct for writing the Init Packet and Firmware image? I.e. the Select, then Create + Write in a loop, then execute
3. If yes to (2), is there a way to make DFU requests that are blocking?
4. If no to (3), is there a way to have my transport give control back to the scheduler to run the DFU requests and callbacks and wait for them to finish?

Again, thank you in advance for your time and help. I unfortunately haven't been able to figure this out on my own from reading the example DFUs nor online resources I've found so far. If there's other resources to check out, please do point them my way!

[Edvin]

Hello,

Just need to check. The external SPI flash is a passive module? That is, it will not send anything automatically, so you manually need to read the SPI flash from the bootloader?

I am not sure I understand your implementation correctly. Are you sending commands over BLE to tell the nRF to read from flash?

I assume that the data found in the SPI flash is transferred over BLE at some point, probably as a background DFU while you run your application?

If so, you should only need to read this back when you enter DFU mode, right?

What callbacks is it that you don't see?

BR,

Edvin

[brooksp]

Hi Edvin, yes, let me elaborate; sorry for not being clear!

• Yes, the External SPI Flash is a passive module. You are correct, it will not send anything automatically, so the Bootloader must manually read it. In effect, I'm trying to have the Bootloader be both the DFU Controller and DFU Target at once.
• For BLE, no, I am not sending commands to tell the nRF to read from Flash. Really I'm trying to have two distinct and separate DFU transports. For the sake of this ticket, it's easiest to just image there is no BLE DFU.
• Data gets into the SPI Flash during normal application execution (our board uses Cellular), but I'm not using the background DFU to do so.
• And yes, in the Bootloader the DFU only needs to read from External SPI Flash, not write. I have confirmed that I can do this successfully.
• At the of my first post, I was not seeing any callbacks. Some more info/updates below:

Today I traced down that I need to call app_sched_execute() in order for my DFU requests to get executed. I've added a call to app_sched_execute() after each of my calls to nrf_dfu_req_handler_on_req(). However now I'm seeing a Fault that I'm trying to track down. Here's a log:

<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: 2)
<debug> nrf_dfu_ble: Initializing BLE DFU transport
<debug> nrf_dfu_ble: Setting up vector table: 0x000E0000
<debug> nrf_dfu_ble: Enabling SoftDevice.
<debug> nrf_dfu_ble: Configuring BLE stack.
<debug> nrf_dfu_ble: Enabling the BLE stack.
<debug> nrf_dfu_ble: No advertising name found
<debug> nrf_dfu_ble: Using default advertising name
<debug> nrf_dfu_ble: Advertising...
<debug> nrf_dfu_ble: BLE DFU transport initialized.
<debug> wa_dfu_transport: Initializing WA DFU transport...
<debug> wa_dfu_transport: { update_device_firmware
<debug> wa_dfu_req_handler: { wa_dfu_req_set_prn
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_MTU_GET
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> wa_dfu_req_handler: { set_prn_callback
<error> app: Received a fault! id: 0x00004002, pc: 0x00000000, info: 0x2003FEA8

[brooksp]

Update: The Fault above was due to a mismatch in my PRN Request function. I set the request type to the wrong value, which caused the callback to trigger an assert when it say the Request Type was different than expected.