SDK 14 migration: can't advertise. fstorage busy.

[Eliot Stock]

Hi there.

I recently migrated from SDK 13 to SDK 14.0.0 and followed the migration guide in detail. I've found that when I try to advertise, ble_advertising_start() will find that fstorage is in use and bail out, expecting to try again once it's no longer busy.

I can think of no valid reason that fstorage would be busy at the point I start advertising. How can I find out who's using it?

I also note that the HRS peripheral example app doesn't SOC events at the point where it calls NRF_SDH_BLE_OBSERVER(), but used to in SDK 13 and below. That handler would forward events to the fstorge module and the BLE advertising module. In SDK 14, the BLE advertising module registers itself as an observers of SOC events, but the fstorage module does not. Do we need to observe SOC events here and pass them on to the fstorage module, or does it look after itself somehow?

Here's the top of ble_advertising_start():

uint32_t ble_advertising_start(ble_advertising_t * const p_advertising,
                               ble_adv_mode_t            advertising_mode)
{
    uint32_t             ret;
    ble_gap_adv_params_t adv_params;

    if (p_advertising->initialized == false)
    {
        return NRF_ERROR_INVALID_STATE;
    }

    p_advertising->adv_mode_current = advertising_mode;

    // Delay starting advertising until the flash operations are complete.
    if (flash_access_in_progress())
    {
        p_advertising->advertising_start_pending = true;
        return NRF_SUCCESS;
    }
    ...

Here's how I init the BLE stack, etc.:

static void ble_stack_init(void)
{
    ret_code_t err_code;

    err_code = nrf_sdh_enable_request();
    APP_ERROR_CHECK(err_code);

    // Configure the BLE stack using the default settings.
    // Fetch the start address of the application RAM.
    uint32_t ram_start = 0;
    err_code = nrf_sdh_ble_default_cfg_set(APP_BLE_CONN_CFG_TAG, &ram_start);
    APP_ERROR_CHECK(err_code);

    // Overwrite some of the default configurations for the BLE stack.
    ble_cfg_t ble_cfg;
    memset(&ble_cfg, 0, sizeof(ble_cfg));

	// Three vendor-specific UUIDs: our own, Nordic's DFU service and Nordic's UART service.
    ble_cfg.common_cfg.vs_uuid_cfg.vs_uuid_count = 3;
    err_code = sd_ble_cfg_set(BLE_COMMON_CFG_VS_UUID, &ble_cfg, ram_start);
    APP_ERROR_CHECK(err_code);

    // Enable BLE stack.
    err_code = nrf_sdh_ble_enable(&ram_start);
    APP_ERROR_CHECK(err_code);

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

And here's my BLE advertising init:

void ble_advertise_out_of_box(void)
{
    ret_code_t err_code;

    ble_advertising_init_t init;
    memset(&init, 0, sizeof(init));

	ble_uuid_t adv_uuids[] = {{BTS_UUID_SERVICE, m_bts.uuid_type}};

    init.advdata.name_type = BLE_ADVDATA_FULL_NAME;
    init.advdata.include_appearance = true;
    init.advdata.flags = BLE_GAP_ADV_FLAG_BR_EDR_NOT_SUPPORTED;
    init.advdata.uuids_complete.uuid_cnt = sizeof(adv_uuids) / sizeof(adv_uuids[0]);
    init.advdata.uuids_complete.p_uuids = adv_uuids;

    // Advertising modes config.
    // Fast, then slow (both undirected).
    init.config.ble_adv_whitelist_enabled = false;
    init.config.ble_adv_directed_enabled = false;
    init.config.ble_adv_directed_slow_enabled = false;
    init.config.ble_adv_directed_slow_interval = 0;
    init.config.ble_adv_directed_slow_timeout = 0; // seconds (despite what the SDK header says, this is NOT number of tries)
    init.config.ble_adv_fast_enabled = true;
    init.config.ble_adv_fast_interval = 0x0028; // 25 ms
    init.config.ble_adv_fast_timeout = 10; // seconds
    init.config.ble_adv_slow_enabled = true;
    init.config.ble_adv_slow_interval = 0x00A0; // 100 ms
    init.config.ble_adv_slow_timeout = 50; // seconds

    init.evt_handler = on_adv_evt;

    err_code = ble_advertising_init(&m_advertising, &init);
    APP_ERROR_CHECK(err_code);

    // From the SDK 14.0.0 HRS example app:
    ble_advertising_conn_cfg_tag_set(&m_advertising, APP_BLE_CONN_CFG_TAG);

	// Start advertising in fast mode, not directed. From here, two things can happen:
    // * On a timeout, we go back to sys off.
    // * On a connection and bond, we continue happily through main().
	err_code = ble_advertising_start(&m_advertising, BLE_ADV_MODE_FAST);
    APP_ERROR_CHECK(err_code);
}

When I try to advertise, I get no error, but I never get the on_adv_evt() call with BLE_ADV_EVT_FAST either.

Edit:

Debugging nrf_fstorage_is_busy() reveals that there's only one fstorage instance and it's using the SD API as expected:

(gdb) print p_fs
$1 = (const nrf_fstorage_t *) 0x20002254 <m_fs>
(gdb) print p_api
$2 = (nrf_fstorage_api_t *) 0x3f81c <nrf_fstorage_sd>
(gdb) cont

Here's 0x20002254 from my map file:

.fs_data        0x0000000020002254       0x14 load address 0x0000000000040354
                0x0000000020002254                PROVIDE (__start_fs_data, .)
 *(.fs_data)
 .fs_data       0x0000000020002254       0x14 _build/app/fds.c.o
                0x0000000020002254                m_fs
                0x0000000020002268                PROVIDE (__stop_fs_data, .)

Edit:

The peer manager is indeed using fstorage at the time I'm trying to advertise. Here's the stack trace from a breakpoint in the write() function in nrf_fstorage_sd.c:

Breakpoint 2, write (p_fs=0x20002254 <m_fs>, dest=462848, p_src=0x3f5c8 <page_tag_data>, len=8, p_param=0x0)
    at /Users/eliot/dev/nRF5_SDK_14.0.0_3bcc1f7/components/libraries/fstorage/nrf_fstorage_sd.c:442
442	    if (!queue_get_next_free(&p_op))
(gdb) bt full
#0  write (p_fs=0x20002254 <m_fs>, dest=462848, p_src=0x3f5c8 <page_tag_data>, len=8, p_param=0x0) at /Users/eliot/dev/nRF5_SDK_14.0.0_3bcc1f7/components/libraries/fstorage/nrf_fstorage_sd.c:442
        p_op = 0x20002254 <m_fs>
#1  0x00038d92 in nrf_fstorage_write (p_fs=0x20002254 <m_fs>, dest=462848, p_src=0x3f5c8 <page_tag_data>, len=8, p_context=0x0)
    at /Users/eliot/dev/nRF5_SDK_14.0.0_3bcc1f7/components/libraries/fstorage/nrf_fstorage.c:159
No locals.
#2  0x00037682 in page_tag_write_data (p_page_addr=0x71000) at /Users/eliot/dev/nRF5_SDK_14.0.0_3bcc1f7/components/libraries/fds/fds.c:325
        page_tag_data = {3735929054, 4045275646}
#3  0x0003820e in init_execute (prev_ret=0, p_op=0x200033a8 <m_op_queue>) at /Users/eliot/dev/nRF5_SDK_14.0.0_3bcc1f7/components/libraries/fds/fds.c:1077
        i = 0
        write_reqd = false
        ret = 15
#4  0x0003854c in queue_process (result=0) at /Users/eliot/dev/nRF5_SDK_14.0.0_3bcc1f7/components/libraries/fds/fds.c:1332
        ret = 67305472
        p_op = 0x200033a8 <m_op_queue>
#5  0x000385ee in queue_start () at /Users/eliot/dev/nRF5_SDK_14.0.0_3bcc1f7/components/libraries/fds/fds.c:1392
No locals.
#6  0x000388f8 in fds_init () at /Users/eliot/dev/nRF5_SDK_14.0.0_3bcc1f7/components/libraries/fds/fds.c:1639
        ret = 0
        evt_success = {id = FDS_EVT_INIT, result = 0, {init = {pages_not_mounted = 0}, write = {record_id = 0, file_id = 0, record_key = 0, is_record_updated = false}, del = {record_id = 0, 
              file_id = 0, record_key = 0, records_deleted_count = 0}, gc = {pages_skipped = 0, space_reclaimed = 0}}}
        op = {op_code = FDS_OP_INIT, {init = {step = FDS_OP_INIT_TAG_DATA}, write = {header = {record_key = 11521, length_words = 0, file_id = 10192, crc16 = 8192, record_id = 4294967289}, 
              p_data = 0x0, page = 48521, step = FDS_OP_WRITE_RECORD_ID, record_to_delete = 10204}, del = {step = FDS_OP_DEL_FILE_FLAG_DIRTY, file_id = 0, record_key = 10192, 
              record_to_delete = 4294967289}}}
        init_opts = TAG_DATA
#7  0x0002e9a0 in pds_init () at /Users/eliot/dev/nRF5_SDK_14.0.0_3bcc1f7/components/ble/peer_manager/peer_data_storage.c:359
        ret = 0
#8  0x000301e2 in pm_init () at /Users/eliot/dev/nRF5_SDK_14.0.0_3bcc1f7/components/ble/peer_manager/peer_manager.c:500
        err_code = 166071
#9  0x000288ea in peer_manager_init () at ../ble_periph.c:862
        sec_param = {bond = 0 '\000', mitm = 0 '\000', lesc = 0 '\000', keypress = 0 '\000', io_caps = 0 '\000', oob = 0 '\000', min_key_size = 128 '\200', max_key_size = 2 '\002', kdist_own = {
            enc = 0 '\000', id = 0 '\000', sign = 0 '\000', link = 0 '\000'}, kdist_peer = {enc = 1 '\001', id = 1 '\001', sign = 0 '\000', link = 0 '\000'}}
        err_code = 0
#10 0x000289f2 in ble_periph_init (p_device_id=0x20002248 <m_device_id> "000000DK", p_battery_voltage=0x200021b4 <m_battery_voltage>) at ../ble_periph.c:917
No locals.
#11 0x000293fe in main () at ../main.c:91
        err_code = 0
        main_loop_count = 0
        app_rev_major = 0
        app_rev_minor = 1

So my questions now are:

1. Is it right that the write() is happening here?

2. If so, why does ble_advertising.c's attempt to pick up where it left off not work? It should get a call to ble_advertising_on_sys_evt() later once the peer manager is done with fstorage:

   void ble_advertising_on_sys_evt(uint32_t evt_id, void * p_context) { ble_advertising_t * p_advertising = (ble_advertising_t *)p_context;

    switch (evt_id)
    {
        //When a flash operation finishes, re-attempt to start advertising operations.
        case NRF_EVT_FLASH_OPERATION_SUCCESS:
        case NRF_EVT_FLASH_OPERATION_ERROR:
        {
            if (p_advertising->advertising_start_pending)
            {
                p_advertising->advertising_start_pending = false;
                ret_code_t ret = ble_advertising_start(p_advertising,
                                                       p_advertising->adv_mode_current);
   
                if ((ret != NRF_SUCCESS) && (p_advertising->error_handler != NULL))
                {
                    p_advertising->error_handler(ret);
                }
            }
        } break;
   
        default:
            // No implementation needed.
            break;
    }
   

   }

[RK]

The first part can't be too hard to work out - just single step the busy function to find out which of the registered fstorage modules is returning true. Since you've not even started advertising, you can single step to your hearts content. There's probably only one such module registered and a couple of breakpoints should quickly show where it's being used.

[Eliot Stock]

Thanks, good point. Have done that and added an edit above, but I'm not sure what it tells me. Not sure how to see the module using the fstorage instance from this.

[Petter Myhre]

Are you saying you are experiencing this with the unmodified HRS example from SDK 14.0.0?

If is_busy() returns true I guess m_queue.cnt !=0. Could you check?

static bool is_busy(nrf_fstorage_t const * p_fs)
{
    return (m_queue.cnt != 0);
}

[Eliot Stock]

No, it's a custom app that uses a custom service, based on the HRS and buttonless DFU bootloader examples. I checked and it looks like the peer manager is the only user of the fstorage module. I init that before I start to advertise of course.

[RK]

and does initializing the peer manager cause it to queue up and start an fstorage operation as the first thing it does? Should be quite easy to pop a breakpoint on the code which increments the queue count on that fstorage SD module and see the stack trace where it's called. Sounds legit to me. The other part of the original question about whether the right things are hooked into the event stream is more interesting, however I don't really have any insight not having done any work (sadly) with recent SDKs or softdevices.