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!

[brooksp]

More updates: 

I've been making more progress, and now it looks like I've figured out how to do (4) from my original post. How I'm running into another issue:

So when nrf_dfu_transports_init() gets called by nrf_dfu_init(), my transport fires and begins my DFU. However, nrf_dfu_req_handler_init() hasn't been called yet. That means the nrf_dfu_req_handler::m_observer hasn't been initialized yet... So when my transport tries to do Object Create, it crashes.

Now I'm not sure where to put my DFU call now. Should I move it out of my transport init and instead call it from main(), or somewhere else? I'm gonna try moving it to main() now and will reply back when I know more.

[Edvin]

Hello,

Regarding the fault handler in the boot loader, in case you run into other faults at a later point in time. Check out app_error_weak.c's fault handler. ID 0x4002 refers to NRF_FAULT_ID_SDK_ASSERT, and ID 0x4001 refers to NRF_FAULT_ID_SDK_ERROR. Check out the implementation of these two in app_error_weak.c to see how to find out where the fault handler is pointing to. 

 

brooksp said:

However, nrf_dfu_req_handler_init() hasn't been called yet

 It looks like your wa_dfu_transport_init() calls update_device_firmware()

There are two ways of using the SPI. Blocking and non-blocking. Basically, if you have an event handler, then the SPI transactions are non-blocking, and the event handler is called when a message is sent/received. If you don't have an event handler, then the SPI is blocking, so transmitting an SPI message will not return until the message has been sent. 

Which of the two types do you use?

If you use the blocking SPI, do you start the process from your transport init function? Does wa_dfu_transport_init() return?

[brooksp]

Correct!

Yes, I'm using block SPI to read from my external SPI Flash.

In Version 1 of my Bootloader (the original post), I called blocking SPI commands from inside wa_dfu_transport_init(). This ended up crashing/failing because I queued up too many requests and filled up the App Scheduler's queue.

In Version 2 I added a call to app_sched_execute() immediately after I called nrf_dfu_req_handler_on_req(). However, this didn't work because nrf_dfu_req_handler::m_observer isn't initialized yet, so the Bootloader asserts/crashes when processing the Object Create/Write requests. To fix this, I need nrf_dfu_init() to be called before my update_device_firmware() is called.

In Version 3, I tried a work-around. In wa_dfu_transport_init(), I queued a new request to an unused request OP, *without* app_sched_execute(). I then set the request.callback.response to be update_device_firmware(). Unfortunately this doesn't work either. It does successfully delay calling update_device_firmware() until after nrf_dfu_init(), but the way the App Scheduler Queue works, the queue doesn't pop until the callback returns. And since my top-level function, update_device_firmware(), queues up more events, whenever app_sched_execute() runs, the first event is still update_device_firmware() (since it hasn't returned yet), which then causes update_device_firmware() to get run multiple times, and no other requests run.

In Version 4, I am modifying nrf_bootloader_init() to call my top-level function, update_device_firmware(), after nrf_dfu_init() is called. Right now this is failing when trying to erase/write to internal Flash. Here's a log:

<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_CREATE (data)
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x00026000, len=1 pages), queue usage: 0
<debug> nrf_dfu_flash: Flash erase failed (0xD): addr=0x00026000, len=0x1 bytes, pending 0
<debug> nrf_dfu_req_handler: Creating object with size: 4096. Offset: 0x00000000, CRC: 0x00000000
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1

I'm investigating this currently. I'm wondering if it's a SoftDevice configuration issue? I'm not sure though. Any suggestions/recommendations are very much appreciated. Thank you!

[brooksp]

OK, I'm getting close; I'm able to write from SPI Flash to Internal Flash!

Now I'm wondering about the Object Create and Object Write calls. When writing my firmware, it takes up multiple Flash pages, so I transfer the firmware one page at a time. For the last chunk, it is less than the size of a page, however Object Create says that "Object size must be page aligned", and errors.

To fix that, I call ALIGN_TO_PAGE() on the Object Create size, but I only Object Write the actual size. After the firmware transfer is complete, I call Object Execute and I get the following error:

<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_EXECUTE (data)
<error> nrf_dfu_req_handler: Invalid data. expected: 4096, got: 588
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x8

Now I'm not sure how to proceed. Can you help?

[Edvin]

brooksp said:

Right now this is failing when trying to erase/write to internal Flash. Here's a log:

 Did you solve this?

Erase failed with 0xD (12) is NRF_ERROR_TIMEOUT. This can e.g. be caused by not allowing the nRF to erase the flash, if you are waiting in an interrupt with a higher priority than the flash operations. The flash operations have a very low priority, so I would suggest leaving all interrupts, and wait for the callback.

 

brooksp said:

To fix that, I call ALIGN_TO_PAGE() on the Object Create size, but I only Object Write the actual size. After the firmware transfer is complete, I call Object Execute and I get the following error:

 So it looks like it is expecting 4096 bytes from the dfu settings, but the actual data_object_size is only 588 long, measured with:

s_dfu_settings.progress.firmware_image_offset -
s_dfu_settings.progress.firmware_image_offset_last;

So it looks like you have not stored the entire image properly, possibly because of some issues with the flash writing. 

Have you tried to read out the flash of the nRF at this point in time, and checked what it looks like compared to the application hex file that you try to update to? Is it actually shorter, or is the image offset wrong, perhaps?

[brooksp]

Edvin said:

I would suggest leaving all interrupts, and wait for the callback.

I was able to get Flash erase/write to work, yes, but I'm not sure how much I like my solution. Is there a way via the SDK to wait for the callback?

And for the firmware image size part:

My total firmware image size is not an even multiple of 4096. I was assume that's true for the majority of firmware images too.

I am using the same firmware image as I did in my previous bootloader (https://devzone.nordicsemi.com/f/nordic-q-a/62777/need-help-with-custom-dfu-bootloader-transferring-back-to-main-app) and was able to get that working, which leads me to believe the firmware image is good.

I've also used this firmware image successfully as a package and used it via the BLE DFU with the nRF Connect app.

In this case, my firmware image's size is 131,660 bytes. That's 32 full pages, and one incomplete page.

32 full pages = 131,072

last page = 131660 - 131,072 = 588

So when I'm writing the final page, the actual firmware image is not 4096 bytes, and that's when I'm running into issues. All previous 32 pages write successfully.

Attempt 1:

Object Create with size = 588

Object Write with size = 588

result: Object Create errors and says that "Object size must be page aligned"

Attempt 2:

Object Create with size = 4096

Object Write with size = 588

result: Object Write errors and says "Invalid data. expected: 4096, got: 588"

I'm not sure how to proceed here. The firmware image only has 588 bytes left; I'm guessing there's some way to handle this final smaller write. Do you know?