fstorage event handler never fired for erase operation with 1 active BLE connection

[TSonono]

Hello,

I am trying to erase a page on the internal flash memory of the nRF52840. I am doing this as a BLE peripheral with 1 active connection. The problem I'm facing is that I am not getting any resulting feedback from fstorage after running (queuing) the erase operation (on one page). I have checked the S140 specification, and increased the connection interval significantly (testing on min: 500ms and max: 700ms), with a supervision timeout of 4200ms, and still facing this problem.

Essentially, what I'm trying to say, is that the event handler I have configured with NRF_FSTORAGE_DEF is not even fired after I have executed nrf_fstorage_erase(). By the way, nrf_fstorage_erase() does return NRF_SUCCESS, and so does the initialization of the fstorage API.

I will provide some code below. I am running the code on an nRF52840-DK, with nRF5 SDK v17.0.2 and S140 7.2.0. Compiled and flashed on a Mac with gcc-arm-none-eabi-9-2019-q4-major. 

#define STORAGE_STATE_IDLE      (0U)
#define STORAGE_STATE_WRITING   (1U)
#define STORAGE_STATE_ERROR     (2U)


static void fs_evt_handler(nrf_fstorage_evt_t  *  evt);

NRF_FSTORAGE_DEF(nrf_fstorage_t m_fs_config) =
{
    .start_addr = (const uint32_t )START_ADDR,
    .end_addr  = (const uint32_t )END_ADDR,
    .evt_handler   = fs_evt_handler,           // Function for event callbacks.
};

static volatile uint32_t m_storage_state = STORAGE_STATE_IDLE;

void hal_erase(uint8_t *start_page, uint32_t num_pages)
{
    m_storage_state = STORAGE_STATE_WRITING;
    uint32_t err_code = nrf_fstorage_erase(&m_fs_config, (const uint32_t) start_page, num_pages, NULL);

    if (err_code != NRF_SUCCESS)
    {
        m_storage_state = STORAGE_STATE_IDLE;
        NRF_LOG_ERROR("Could not request erase flash page (0x%02x).\r\n", m_fs_err_code);
    }

    while (m_storage_state == STORAGE_STATE_WRITING)
    {
        /* Feed watch dog while waiting for fstorage result */
        /* TODO: Why does fs_evt_handler not get fired */
        bsp_wdt_feed();
    }
}

static void fs_evt_handler(nrf_fstorage_evt_t * evt)
{
    if (evt->result != NRF_SUCCESS)
    {
        NRF_LOG_ERROR("result: 0x%02x\r\n", evt->result);
        /* Write failed, go to error state. */
        m_storage_state = STORAGE_STATE_ERROR;
    }
    else
    {
        /* Write succeeded, go to idle state again. */
        m_storage_state = STORAGE_STATE_IDLE;
    }
}

I am calling hal_erase() with num_pages=1 and a start address for a page in the flash memory. I get stuck in the while loop that feeds the watchdog due to the event handler of fstorage never being fired so m_storage_state is never modified. I have verified that I am indeed stuck in that particular loop (with logging) and not some other higher priority context.

[Einar Thorsrud]

Hi,

There are two typical reasons for fstorage operations never completing or seemingly never completing. One is if the SoftDevice does not have time to schedule it in between BLE activity, but that should not be a problem here as you test with a long connection interval and a long supervision timeout. Another typical reason is if you wait for the operation to complete in a interrupt priority which is same or higher than that of the SoftDevice low priority. If that is the case, the event handler will never have time to run. I do not see enough of your code to see if that is the case. Can you clarify, or show more of your code so that I get the full picture?

It would also be interesting if you could check with a debugger if the flash is actually erased or not, even though the event handler does not run. That would be tested by having some data in the specific flash page before, and then reading it out and verifying if it is all FF's or not after the attempted erase operation.

[TSonono]

Hi Einar,

Thanks for your reply. The code I have attached is being called from the main loop context on bare metal (I am using the app_scheduler in the nRF5 SDK), so I do not expect this to be a priority issue.

I also checked if the data was in fact erased using the nrfjprog tool and with the memrd option. It seems like the page is in fact not erased.

I tested putting a print at the first line of nrf_fstorage_sys_evt_handler() in nrf_fstorage_sd.c, and this print never occurs. Could there be a problem with the SD observer for fstorage not being correctly created?

Best regards,

Tofik

[Einar Thorsrud]

Hi Tofik,

TSonono said:

Could there be a problem with the SD observer for fstorage not being correctly created?

Yes, it could be. The nrf_fstorage_erase() function will return NRF_SUCCESS as long as the erase operation is queued, so even if you get no error here that does not say much if there was a problem with the initialization. I would very much like to see all your code if possible? That would probably make things a lot clearer.

[TSonono]

dev_board.ld55144.sdk_config.h

/*======= Includes ==========================================================*/

#include "bsp_nrf_board.h"
#include "board.h"
#include "nrf_log.h"
#include "nrf_log_ctrl.h"
#include "nrf_log_default_backends.h"
#include "app_scheduler.h"
#include "mem_manager.h"
#include "bsp.h"

#include "key_tasks.h"
#include "app_timer.h"
#include "nrf_fstorage.h"
#include "nrf_fstorage_sd.h"

#include "rtc.h"

#include "nrf_sdh_ble.h"
#include "nrf_sdh.h"

/*======= Local Macro Definitions ===========================================*/

#define SCHEDULER_QUEUE_SIZE (20U)
#define MY_BLE_OBSERVER_PRIO 3
#define MY_BLE_CONN_CFG_TAG 1

#define FLASH_PAGE_SIZE     (0x00001000U)

#define STORAGE_NUM_PAGES   (6U)
#define STORAGE_END_ADDR    (0x000F2000U)
#define STORAGE_START_ADDR  (STORAGE_END_ADDR - ((STORAGE_NUM_PAGES)*(FLASH_PAGE_SIZE)))


#define STORAGE_STATE_IDLE      (0U)
#define STORAGE_STATE_WRITING   (1U)
#define STORAGE_STATE_ERROR     (2U)

/*======= Type Definitions ==================================================*/
/*======= Local function prototypes =========================================*/

static void bsp_isr_gpio_event_handler(nrf_drv_gpiote_pin_t pin, nrf_gpiote_polarity_t action);
static void ble_stack_init(void);
static void ble_evt_handler(ble_evt_t const * p_ble_evt, void * p_context);
static void fs_evt_handler(nrf_fstorage_evt_t  *  evt);
static void hal_erase(uint32_t start_page, uint32_t num_pages);
static bool port_setup_storage(void);
static bool erase_something(void);

static void erase_something_task(void *event_data, uint16_t event_size);

/*======= Local variable declerations ========================================*/

NRF_FSTORAGE_DEF(nrf_fstorage_t m_fs_conf) =
{
    .start_addr = (const uint32_t )STORAGE_START_ADDR,
    .end_addr  = (const uint32_t )STORAGE_END_ADDR,
    .evt_handler   = fs_evt_handler,           // Function for event callbacks.
};

static volatile uint32_t m_storage_state;

/*======= Local function implementations =====================================*/

static bool erase_something(void)
{
    uint32_t erase_addr = STORAGE_START_ADDR;
    hal_erase(erase_addr, 1);

    return true;
}

int main(void)
{
    uint32_t ret;

    APP_SCHED_INIT(0, SCHEDULER_QUEUE_SIZE);

    APP_ERROR_CHECK(NRF_LOG_INIT(app_timer_cnt_get));
    NRF_LOG_DEFAULT_BACKENDS_INIT();

    bsp_init();
    nrf_mem_init();

    bsp_register_gpio_event_handler(bsp_isr_gpio_event_handler);

    rtc_init();

    ret = port_setup_storage();
    if (false == ret)
    {
        NRF_LOG_ERROR("Storage initialization failed.\r\n");
    }

    // erase_something();
    // NRF_LOG_INFO("Added first user");

#ifdef SOFTDEVICE_PRESENT
    ble_stack_init();
#endif


    while (1)
    {
        bsp_wdt_feed();
        app_sched_execute();
        bsp_sleep();
    }
}


static bool port_setup_storage(void)
{
#ifdef SOFTDEVICE_PRESENT
    ret_code_t err_code = nrf_fstorage_init(&m_fs_conf, &nrf_fstorage_sd, NULL);
#else
    ret_code_t err_code = nrf_fstorage_init(&m_fs_conf, &nrf_fstorage_nvmc, NULL);
#endif

    if (err_code != NRF_SUCCESS)
    {
        APP_ERROR_CHECK(err_code);
        NRF_LOG_ERROR("nrf_fstorage_init() failed\r\n");
    }

    m_storage_state = STORAGE_STATE_IDLE;

    return true;
}


static void hal_erase(uint32_t start_page, uint32_t num_pages)
{
    m_storage_state = STORAGE_STATE_WRITING;
    uint32_t m_fs_err_code = nrf_fstorage_erase(&m_fs_conf, start_page, num_pages, NULL);
    APP_ERROR_CHECK(m_fs_err_code);

    if (m_fs_err_code != NRF_SUCCESS)
    {
        m_storage_state = STORAGE_STATE_IDLE;
        NRF_LOG_ERROR("Could not request erase flash page (0x%02x).\r\n", m_fs_err_code);
    }

    while(nrf_fstorage_is_busy(&m_fs_conf))
    {
        bsp_wdt_feed();
    }

    while (m_storage_state == STORAGE_STATE_WRITING)
    {
        /* Feed watch dog */
        // TODO: We get stuck here when trying to claim over BLE (key)
        bsp_wdt_feed();
    }
    NRF_LOG_INFO("ERASING COMPLETED!\r\n");
}

static void erase_something_task(void *event_data, uint16_t event_size)
{
    erase_something();
    NRF_LOG_INFO("Added first user");
}

static void bsp_isr_gpio_event_handler(nrf_drv_gpiote_pin_t pin, nrf_gpiote_polarity_t action)
{
    if (action == NRF_GPIOTE_POLARITY_HITOLO)
    {
        switch (pin)
        {
            case 12:
                NRF_LOG_INFO("Adding first user");
                app_sched_event_put(NULL, 0, erase_something_task);
                break;
            default:
                APP_ERROR_CHECK_BOOL(0);
                break;
        }
    }
}

static void ble_stack_init(void)
{
    ret_code_t err_code;
    uint32_t ram_start = 0;

    err_code = nrf_sdh_enable_request();
    APP_ERROR_CHECK(err_code); /* TODO: Proper error handling */

    // Configure the BLE stack using the default settings.
    // Fetch the start address of the application RAM.
    err_code = nrf_sdh_ble_default_cfg_set(MY_BLE_CONN_CFG_TAG, &ram_start);
    APP_ERROR_CHECK(err_code); /* TODO: Proper error handling */

    // Enable BLE stack.
    err_code = nrf_sdh_ble_enable(&ram_start);
    APP_ERROR_CHECK(err_code); /* TODO: Proper error handling */

    // Register a handler for BLE events.
    NRF_SDH_BLE_OBSERVER(m_ble_observer, MY_BLE_OBSERVER_PRIO, ble_evt_handler, NULL);
}

static void ble_evt_handler(ble_evt_t const * p_ble_evt, void * p_context)
{
}

static void fs_evt_handler(nrf_fstorage_evt_t * evt)
{
    if (evt->result != NRF_SUCCESS)
    {
        APP_ERROR_CHECK(evt->result);
        NRF_LOG_ERROR("result: 0x%02x\r\n", evt->result);
        /* Write failed, go to error state. */
        m_storage_state = STORAGE_STATE_ERROR;
    }
    else
    {
        /* Write succeeded, go to idle state again. */
        m_storage_state = STORAGE_STATE_IDLE;
    }
}

I have basically put all relevant code in one line. It seems that a connection does even have to be established for this problem to occur, only the soft device being enabled makes the error occur as well. If we instead call erase_something in line 96 (commented out),  which is before the BLE stack is enabled, it works fine.

I have it configured so that pressing button 2 on the dev board puts a task on the scheduler queue which tries to erase a page.

I have also attached the sdk_config and the linker file.

Best regards,

Tofik

[TSonono]

I was able to find the source of the issue. It was due to the fact that I had not linked the file ${SDK_ROOT}/components/softdevice/common/nrf_sdh_soc.c in to my project. Surprisingly, this does not result in a linking or compilie error... This made it quite hard to figure out what was wrong.

Best regards,

Tofik