App Scheduling Error for SPI DFU

[amarin]

Hi,

 I am currently running a custom bootloader I found that updates via SPI. I have 2 nrf52840 DKs that are programmed as an SPI master and a SPI bootloader. I have been following this link to help with understanding how the devices should communicate. I have been able to get up to the point where the code should now be writing to the target device. I can confirm that the target device is getting the data it should be writing, however, it always shoots a "Failure to run packet write" error. The dfu code is shown below and the place where the error happen can be seen in line 279. 

#include <string.h>
#include <stdlib.h>
#include "boards.h"
#include "app_util_platform.h"
#include "nrf_dfu_transport.h"
#include "nrf_dfu_req_handler.h"
#include "nrf_dfu_handling_error.h"
#include "sdk_config.h"
#include "nrf_delay.h"

#include "nrf_log.h"
#include "nrf_drv_spis.h"
#include "nrf_spis_dfu.h"
#define AVAILABLE_LED_PIN_NO            BSP_LED_0                                                   /**< Is on when serial DFU transport is enabled (but not connected). */
#define CONNECTED_LED_PIN_NO            BSP_LED_1                                                   /**< Is on when device has connected. */


#define CREATE_OBJECT_REQUEST_LEN       (sizeof(uint8_t)+sizeof(uint32_t))
#define SET_RECEIPT_NOTIF_REQUEST_LEN   (sizeof(uint16_t))
#define CALCULATE_CRC_REQUEST_LEN       0
#define EXECUTE_OBJECT_REQUEST_LEN      0
#define SELECT_OBJECT_REQUEST_LEN       (sizeof(uint8_t))
#define GET_SERIAL_MTU_REQUEST_LEN      0

#define MAX_RESPONSE_SIZE               (1+1+3*4)

static spi_dfu_t m_dfu;
#define SPIS_INSTANCE 1 /**< SPIS instance index. */
static const nrf_drv_spis_t spis = NRF_DRV_SPIS_INSTANCE(SPIS_INSTANCE);/**< SPIS instance. */
static volatile bool spis_xfer_done; /**< Flag used to indicate that SPIS instance completed the transfer. */

static uint8_t spi_rx_buffer[128+1];
static const uint8_t m_length = sizeof(spi_rx_buffer);        /**< Transfer length. */
static uint8_t       m_tx_buf[MAX_RESPONSE_SIZE];          /**< TX buffer. */


DFU_TRANSPORT_REGISTER(nrf_dfu_transport_t const dfu_trans) =
{
    .init_func  = spis_dfu_transport_init,
    .close_func = spis_dfu_transport_close
};


ANON_UNIONS_ENABLE;

typedef struct
{
    uint8_t            op_code;
    nrf_dfu_result_t resp_val;
    union
    {
        struct
        {
            uint32_t offset;
            uint32_t crc;
        }crc_response;

        struct
        {
            uint32_t max_size;
            uint32_t offset;
            uint32_t crc;
        }select_response;

        struct
        {
            uint16_t mtu;
        }serial_mtu_response;

        struct
        {
            uint8_t ping_id;
        }ping_response;
    };

}spi_dfu_response_t;

ANON_UNIONS_DISABLE;


/**@brief       Function for the LEDs initialization.
 *
 * @details     Initializes all LEDs used by this application.
 */
static void leds_init(void)
{
    nrf_gpio_cfg_output(AVAILABLE_LED_PIN_NO);
    nrf_gpio_cfg_output(CONNECTED_LED_PIN_NO);
    nrf_gpio_pin_clear(AVAILABLE_LED_PIN_NO);
    nrf_gpio_pin_set(CONNECTED_LED_PIN_NO);
}

static void response_send(spi_dfu_t          * p_dfu,
                          spi_dfu_response_t * p_response)
{
    uint8_t response_buffer[MAX_RESPONSE_SIZE] = {0};
    uint16_t index = 0;

    NRF_LOG_DEBUG("Sending Response: [0x%01x, 0x%01x]", p_response->op_code, p_response->resp_val);

    response_buffer[index++] = SERIAL_DFU_OP_CODE_RESPONSE;

    // Encode the Request Op code
    response_buffer[index++] = p_response->op_code;

    // Encode the Response Value.
    response_buffer[index++] = (uint8_t)p_response->resp_val;

    if (p_response->resp_val == NRF_DFU_RES_CODE_SUCCESS)
    {
        switch (p_response->op_code)
        {
            case SERIAL_DFU_OP_CODE_CALCULATE_CRC:
                index += uint32_encode(p_response->crc_response.offset, &response_buffer[index]);
                index += uint32_encode(p_response->crc_response.crc, &response_buffer[index]);
                break;

            case SERIAL_DFU_OP_CODE_SELECT_OBJECT:
                index += uint32_encode(p_response->select_response.max_size, &response_buffer[index]);
                index += uint32_encode(p_response->select_response.offset, &response_buffer[index]);
                index += uint32_encode(p_response->select_response.crc, &response_buffer[index]);
                break;

            case SERIAL_DFU_OP_CODE_GET_SERIAL_MTU:
                index += uint16_encode(p_response->serial_mtu_response.mtu, &response_buffer[index]);
                break;

            case SERIAL_DFU_OP_CODE_PING:
                response_buffer[index] = p_response->ping_response.ping_id;
                index += sizeof(uint8_t);
                break;

            default:
                // no implementation
                break;
        }
    }
    else if (p_response->resp_val == NRF_DFU_RES_CODE_EXT_ERROR)
    {
        response_buffer[index++] = ext_error_get();
        // Clear the last extended error code
        (void) ext_error_set(NRF_DFU_EXT_ERROR_NO_ERROR);
    }

    // send
      memcpy(m_tx_buf,response_buffer,index);
      nrf_drv_spis_buffers_set(&spis, m_tx_buf, index, spi_rx_buffer, m_length);
      //NRF_LOG_DEBUG("response send spi_rx_buffer[0]: 0x%X",spi_rx_buffer[0]);
 
}

static void on_packet_received(spi_dfu_t * p_dfu)
{   
    //NRF_LOG_DEBUG("Received: %p",p_dfu);
    nrf_dfu_request_t dfu_req;
    nrf_dfu_response_t dfu_res = {{{0}}};
    spi_dfu_response_t serial_response = {0};
    
    //NRF_LOG_DEBUG("payload length: %i",p_dfu->recv_length);

    memset(&dfu_req, 0, sizeof(nrf_dfu_request_t));

    const serial_dfu_op_code_t op_code             = (serial_dfu_op_code_t)p_dfu->recv_buffer[0];
    //for(int loop = 0; loop < 5; loop++)
      //  NRF_LOG_DEBUG("recv_buffer[%i]: 0x%X", loop, p_dfu->recv_buffer[loop]);
    const uint16_t             packet_payload_len  = p_dfu->recv_length;
    NRF_LOG_DEBUG("payload length: %i",packet_payload_len);
    uint8_t * p_payload                            = &p_dfu->recv_buffer[1];

    serial_response.op_code = op_code;

    NRF_LOG_DEBUG("Opcode received: 0x%x",op_code);

    nrf_gpio_pin_clear(CONNECTED_LED_PIN_NO);
    nrf_gpio_pin_set(AVAILABLE_LED_PIN_NO);
    switch (op_code)
    {
        case SERIAL_DFU_OP_CODE_CREATE_OBJECT:

            if (packet_payload_len != CREATE_OBJECT_REQUEST_LEN)
            {
                serial_response.resp_val = NRF_DFU_RES_CODE_INVALID_PARAMETER;
                break;
            }

            NRF_LOG_DEBUG("Received create object");

            // Reset the packet receipt notification on create object
            p_dfu->pkt_notif_target_count = p_dfu->pkt_notif_target;

            // Get type parameter
            dfu_req.create.object_type =  p_payload[0];

            // Get length value
            dfu_req.create.object_size = uint32_decode(&p_payload[1]);

            // Set req type
            dfu_req.request = NRF_DFU_OP_OBJECT_CREATE;

            serial_response.resp_val = nrf_dfu_req_handler_on_req(&dfu_req);
            break;

        case SERIAL_DFU_OP_CODE_SET_RECEIPT_NOTIF:
            NRF_LOG_DEBUG("Set receipt notif");
            if (packet_payload_len != SET_RECEIPT_NOTIF_REQUEST_LEN)
            {
                serial_response.resp_val = NRF_DFU_RES_CODE_INVALID_PARAMETER;
                break;
            }

            p_dfu->pkt_notif_target       = uint16_decode(&p_payload[0]);
            p_dfu->pkt_notif_target_count = p_dfu->pkt_notif_target;

            serial_response.resp_val = NRF_DFU_RES_CODE_SUCCESS;
            break;

        case SERIAL_DFU_OP_CODE_CALCULATE_CRC:
            NRF_LOG_DEBUG("Received calculate CRC");

            dfu_req.request =  NRF_DFU_OP_CRC_GET;

            serial_response.resp_val            = nrf_dfu_req_handler_on_req(&dfu_req);
            serial_response.crc_response.offset = dfu_res.crc.offset;
            serial_response.crc_response.crc    = dfu_res.crc.crc;
            break;

        case SERIAL_DFU_OP_CODE_EXECUTE_OBJECT:
            NRF_LOG_DEBUG("Received execute object");

            // Set req type
            dfu_req.request =  NRF_DFU_OP_OBJECT_EXECUTE;

            serial_response.resp_val = nrf_dfu_req_handler_on_req(&dfu_req);
            break;

        case SERIAL_DFU_OP_CODE_SELECT_OBJECT:

            NRF_LOG_DEBUG("Received select object");
            if (packet_payload_len != SELECT_OBJECT_REQUEST_LEN)
            {
                serial_response.resp_val = NRF_DFU_RES_CODE_INVALID_PARAMETER;
                break;
            }

            // Set object type to read info about
            dfu_req.select.object_type = p_payload[0];

            dfu_req.request = NRF_DFU_OP_OBJECT_SELECT;

            serial_response.resp_val = nrf_dfu_req_handler_on_req(&dfu_req);
            serial_response.select_response.max_size = dfu_res.select.max_size;
            serial_response.select_response.offset   = dfu_res.select.offset;
            serial_response.select_response.crc      = dfu_res.select.crc;
            break;

        case SERIAL_DFU_OP_CODE_GET_SERIAL_MTU:
            NRF_LOG_DEBUG("Received get serial mtu");

            serial_response.resp_val = NRF_DFU_RES_CODE_SUCCESS;
            serial_response.serial_mtu_response.mtu = sizeof(p_dfu->recv_buffer);
            break;

        case SERIAL_DFU_OP_CODE_WRITE_OBJECT:
             // Set req type
            dfu_req.request =   NRF_DFU_OP_OBJECT_WRITE;
            NRF_LOG_DEBUG("dfu request: %X", dfu_req.request);

            // Set data and length
            dfu_req.write.p_data   = &p_payload[0];
            NRF_LOG_DEBUG("write.p_data: 0x%x", dfu_req.write.p_data);
            //for(int loop = 0; loop<sizeof(p_payload); loop++)
                  //NRF_LOG_DEBUG("dfu request write p_payload[%i]: 0x%X", loop,p_payload[loop]);
            dfu_req.write.len = packet_payload_len;
            NRF_LOG_DEBUG("dfu request write length: 0x%X", packet_payload_len);

            serial_response.resp_val = nrf_dfu_req_handler_on_req(&dfu_req);
            if (serial_response.resp_val != NRF_DFU_RES_CODE_SUCCESS)
            {
                NRF_LOG_ERROR("Failure to run packet write");
            }

            // Check if a packet receipt notification is needed to be sent.
            if (p_dfu->pkt_notif_target != 0 && --p_dfu->pkt_notif_target_count == 0)
            {
                serial_response.op_code             = SERIAL_DFU_OP_CODE_CALCULATE_CRC;
                serial_response.crc_response.offset = dfu_res.crc.offset;
                serial_response.crc_response.crc    = dfu_res.crc.crc;

                // Reset the counter for the number of firmware packets.
                p_dfu->pkt_notif_target_count = p_dfu->pkt_notif_target;

                response_send(p_dfu, &serial_response);
            }else
            {
                nrf_drv_spis_buffers_set(&spis, m_tx_buf, 0, spi_rx_buffer, m_length);
                //for(int loop = 0; loop<5; loop++)
                    //NRF_LOG_DEBUG("on packet received spi_rx_buffer[%i]: 0x%X",loop,spi_rx_buffer[loop]);
            }
           
            break;

        case SERIAL_DFU_OP_CODE_PING:
            if (packet_payload_len != sizeof(serial_response.ping_response))
            {
                serial_response.resp_val = NRF_DFU_RES_CODE_INVALID_PARAMETER;
                break;
            }

            serial_response.resp_val = NRF_DFU_RES_CODE_SUCCESS;
            serial_response.ping_response.ping_id = p_payload[0];

            NRF_LOG_DEBUG("Received ping %d", p_payload[0]);
            break;

        default:
            // Unsupported op code.
            NRF_LOG_WARNING("Received unsupported OP code");
            serial_response.resp_val = NRF_DFU_RES_CODE_OP_CODE_NOT_SUPPORTED;
            break;
    }

    if (op_code != SERIAL_DFU_OP_CODE_WRITE_OBJECT)
    {
        response_send(p_dfu, &serial_response);
    }
   
}



/**
 * @brief SPIS user event handler.
 *
 * @param event
 */
void spis_event_handler(nrf_drv_spis_event_t event)
{
    if (event.evt_type == NRF_DRV_SPIS_XFER_DONE)
    {
        //spis_xfer_done = true;
        NRF_LOG_INFO(" Transfer completed. Received: %d bytes",event.rx_amount);
        NRF_LOG_DEBUG("event handler spi_rx_buffer[0]: 0x%X",spi_rx_buffer[0]);

        if ((event.rx_amount)&&(spi_rx_buffer[0]!=0xFF))
        {
            memcpy(m_dfu.recv_buffer,spi_rx_buffer,event.rx_amount);
            m_dfu.recv_length= event.rx_amount-1;
            on_packet_received(&m_dfu);
        }
         
        else{
             NRF_LOG_INFO(" No command received start RX again");
             nrf_drv_spis_buffers_set(&spis, m_tx_buf, 0, spi_rx_buffer, m_length);
            
             //Could be the last response, check if dfu is waiting for a reset
             //nrf_dfu_req_handler_reset_if_dfu_complete();
        }
    }
    
    if (event.evt_type == NRF_DRV_SPIS_BUFFERS_SET_DONE)
    {
        
    }
    
        
}

uint32_t spis_dfu_transport_init(void)
{
    uint32_t err_code;
    
    leds_init();
    
    // Enable the constant latency sub power mode to minimize the time it takes
    // for the SPIS peripheral to become active after the CSN line is asserted
    // (when the CPU is in sleep mode).
    NRF_POWER->TASKS_CONSTLAT = 1;
    nrf_drv_spis_config_t spis_config = NRF_DRV_SPIS_DEFAULT_CONFIG;
    spis_config.csn_pin               = APP_SPIS_CS_PIN;
    spis_config.miso_pin              = APP_SPIS_MISO_PIN;
    spis_config.mosi_pin              = APP_SPIS_MOSI_PIN;
    spis_config.sck_pin               = APP_SPIS_SCK_PIN;

    err_code = nrf_drv_spis_init(&spis, &spis_config, spis_event_handler);

    if (err_code != NRF_SUCCESS)
    {
        NRF_LOG_ERROR("Failed initializing SPIS");
        return err_code;
    }
    //Start RX
    //NRF_LOG_DEBUG("dfu transport spi_rx_buffer[0]: 0x%X",spi_rx_buffer[0]);
    err_code = nrf_drv_spis_buffers_set(&spis, m_tx_buf, 0, spi_rx_buffer, m_length);
    APP_ERROR_CHECK(err_code);
    return NRF_SUCCESS;
}


uint32_t spis_dfu_transport_close(void)
{
    NRF_POWER->TASKS_LOWPWR = 1;
    nrf_drv_spis_uninit(&spis);
    return NRF_SUCCESS;
}

Using the debugger and stepping into line 276, I was able to find the internal error with the app_scheduler_event_put() function in the app_scheduler.c file outputting NRF_ERROR_NO_MEM error. In my nrf_bootloader.c I have the scheduler initialized as: 

#define SCHED_QUEUE_SIZE      129         /**< Maximum number of events in the scheduler queue. */
#define SCHED_EVENT_DATA_SIZE NRF_DFU_SCHED_EVENT_DATA_SIZE /**< Maximum app_scheduler event size. */

//NRF_DFU_SCHED_EVENT_DATA_SIZE = (sizeof(nrf_dfu_request_t)) = 24

/**@brief Function for initializing the event scheduler.
 */
static void scheduler_init(void)
{
    APP_SCHED_INIT(SCHED_EVENT_DATA_SIZE, SCHED_QUEUE_SIZE);
}

If anyone has any ideas as to how I should fix this error, I would greatly appreciate it!!!

[Susheel Nuguru]

Seems like you are putting events in the sched queue faster than you can pull.

Try increasing SCHED_QUEUE_SIZE to a value that suits your application needs.

[amarin]

I have increased the value from as high as 4096 and yet I still get the same error.

[Susheel Nuguru]

there is no other reason this function would fail with that error reason. Can you pinpoint inside app_scheduler_event_put where exactly (line number) it fails with this error?

[amarin]

I don't know exactly where it fails since the debugger completely skips it when I do the step debug. In the first picture, I am going into nrf_dfu_req_handler_on_req function where app_sched_event_put was being called.

When I go into the next step, it skips all the way to the second picture, which is how I know that there is an error coming from that function. 

I was able to go to the definition of app_sched_event_put and be able to hover over some of the variables to see their values, most did not give me a value like the event_index, but err_code = 0x04 which is the same value as NRF_ERROR_NO_MEM.

Going back to the nrf_dfu_req_handler_on_req function in the first and second picture, I hovered over callback.response variable and found that it equals 0, meaning that it should show the NRF_ERROR_INVALID_PARAM, but it didn't. None of these errors pop up in the debug terminal, only when I step into them can I see them.

[Susheel Nuguru]

amarin said:

I don't know exactly where it fails since the debugger completely skips it when I do the step debug.

 This is probably because you are compiling your project with optimizations? Please remove the optimizations (set them to 0) so that the debugger includes a lot of debug symbol info the elf file for a better debugging experience.

One other angle to explore could be that you are receiving the data too fast than your application can handle it, which eventually is causing the app_scheduler fifo to overflow. increasing the buffer in this case might only delay the overflow if the data is too much.

Also check if yo uare calling app_sched_execute in your bootloader and how often it gets called. What is the status of the shceduler queue when this problem happens? is the scheduler fifo full? you can debug to get this information.