This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

Mesh assertion during sequence number block allocate

I am encountering an issue with PERSISTENT_STORAGE enabled. Currently I have a device set up to rapidly send out messages to test the sequence number updating and block allocation procedure. I notice that when the sequence number approaches the next block by (NETWORK_SEQNUM_FLASH_BLOCK_THRESHOLD) amount and triggers the seqnum_block_allocate() (see the code snippet below) I get a mesh assertion error.

uint32_t net_state_seqnum_alloc(uint32_t * p_seqnum)
{
    // Attempt to allocate the sequence number before it is fully restored from persistent storage.
    if (!m_status.is_synchronized)
    {
        return NRF_ERROR_FORBIDDEN;
    }

    if (m_net_state.seqnum < m_net_state.seqnum_max_available)
    {
        /* Check if we've reached the seqnum threshold for a state transition. */
        uint32_t threshold = NETWORK_SEQNUM_IV_UPDATE_START_THRESHOLD;
        if (m_net_state.iv_update.state == NET_STATE_IV_UPDATE_IN_PROGRESS)
        {
            threshold = NETWORK_SEQNUM_IV_UPDATE_END_THRESHOLD;
        }
        bool ivu_triggered = false;
        if (m_net_state.seqnum >= threshold)
        {
            m_net_state.iv_update.pending = true;
            ivu_triggered = iv_update_trigger_if_pending();
        }

        if (!ivu_triggered && m_net_state.seqnum >= m_net_state.seqnum_max_available - NETWORK_SEQNUM_FLASH_BLOCK_THRESHOLD)
        {
            seqnum_block_allocate();
        }
        /* Get the sequence number after doing the state updates, as they might
         * trigger changes to it. */
        uint32_t was_masked;
        _DISABLE_IRQS(was_masked);
        *p_seqnum = m_net_state.seqnum++;
        _ENABLE_IRQS(was_masked);

        return NRF_SUCCESS;
    }
    else
    {
        seqnum_block_allocate();
        return NRF_ERROR_FORBIDDEN;
    }
}

Mesh assertion error at line NRF_MESH_ASSERT_DEBUG(*p_flags & MESH_CONFIG_ENTRY_FLAG_BUSY); in the code:

static void backend_evt_handler(const mesh_config_backend_evt_t * p_evt)
{
    const mesh_config_entry_params_t * p_params = entry_params_find(p_evt->id);

    if (p_params == NULL && MESH_CONFIG_BACKEND_EVT_TYPE_ERASE_COMPLETE == p_evt->type)
    { /* Check whether entry with known file id was deleted. */
        const mesh_config_file_params_t * p_file = file_params_find(p_evt->id.file);
        NRF_MESH_ASSERT(p_file);
        return;
    }

    NRF_MESH_ASSERT(p_params);

    mesh_config_entry_flags_t * p_flags = entry_flags_get(p_params, p_evt->id);
    NRF_MESH_ASSERT_DEBUG(*p_flags & MESH_CONFIG_ENTRY_FLAG_BUSY);
    *p_flags &= (mesh_config_entry_flags_t)~MESH_CONFIG_ENTRY_FLAG_BUSY;

    if (p_evt->type == MESH_CONFIG_BACKEND_EVT_TYPE_STORAGE_MEDIUM_FAILURE)
    {
        const nrf_mesh_evt_t evt = {
            .type = NRF_MESH_EVT_CONFIG_STORAGE_FAILURE,
            .params.config_storage_failure = {
                .id = p_evt->id, /*lint !e64 Type mismatch */
            }
        };
        event_handle(&evt);
    }

    if (mesh_config_is_busy())
    {
        dirty_entries_process();
    }
    else
    {
        m_emergency_action = false;
        nrf_mesh_evt_t evt = {.type = NRF_MESH_EVT_CONFIG_STABLE};
        event_handle(&evt);
    }
}

Callstack:

What is this assertion trying to achieve and any ideas why its being triggered?

If I continue to let the application run, the next time it attempts to allocate a sequence block it fails repeatedly until the "if (m_net_state.seqnum < m_net_state.seqnum_max_available)" check fails and starts returning NRF_ERROR_FORBIDDEN.

Using mesh v4.1

Parents
  • Any update on this issue? I am also running into this on v4.1.0 when add subscriptions to the DSM from the application_scheduler.

    Here is my stack trace if that helps.

    #3  0x0001ce04 in mesh_assertion_handler (pc=181202) at /Users/paulquevedo/dev/thor/nordic/mesh/ledProvTest/src/error_handlers.c:75
    #4  0x0002c3d8 in backend_evt_handler (p_evt=0x2003f560) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/mesh_config.c:270
    #5  0x0002cbda in write_complete_cb (p_manager=0x20006d10 <m_dsm_file_backend_data+8>, p_entry=0xeb084, result=FM_RESULT_SUCCESS)
        at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/mesh_config_flashman_glue.c:125
    #6  0x000290a6 in end_action (p_action=0x200058a0 <m_action_queue_buffer+4>, result=FM_RESULT_SUCCESS, p_entry=0xeb084) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/flash_manager.c:486
    #7  0x000296be in process_action_queue () at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/flash_manager.c:788
    #8  0x00029720 in flash_op_ended_callback (user=MESH_FLASH_USER_MESH, p_op=0x20005524 <m_users+248>, token=26) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/flash_manager.c:807
    #9  0x00023894 in send_end_events () at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/mesh_flash.c:159
    #10 0x000267ee in bearer_event_handler () at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/bearer_event.c:380
    #11 0x000263f8 in QDEC_IRQHandler () at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/bearer_event.c:145
    #12 <signal handler called>
    #13 0x00026694 in bearer_event_flag_set (flag=3) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/bearer_event.c:304
    #14 0x000289fa in schedule_processing () at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/flash_manager.c:126
    #15 0x00029bcc in flash_manager_entry_commit (p_entry=0x200058ac <m_action_queue_buffer+16>) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/flash_manager.c:1169
    #16 0x0002cd8a in mesh_config_backend_record_write (p_file=0x20006d08 <m_dsm_file_backend_data>, p_data=0x2003f6b8 "\001\300\003 +\255\002", length=2)
        at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/mesh_config_flashman_glue.c:257
    #17 0x0002ca38 in mesh_config_backend_store (id=..., p_entry=0x2003f6b8 "\001\300\003 +\255\002", entry_len=2) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/mesh_config_backend.c:139
    #18 0x0002c16e in dirty_entries_process () at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/mesh_config.c:163
    #19 0x0002c264 in entry_store (p_params=0x551b8 <m_dsm_nonvirtual_addr_params>, id=..., p_entry=0x2003f760) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/mesh_config.c:200
    #20 0x0002c644 in mesh_config_entry_set (id=..., p_entry=0x2003f760) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/mesh_config.c:401
    #21 0x00035972 in dsm_entry_store (record_id=4096, handle=2, p_property=0x20006c88 <m_addr_nonvirtual_allocated>) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/access/src/device_state_manager.c:1674
    #22 0x00034e04 in add_address (raw_address=49153, p_address_handle=0x2003f7be, role=DSM_ADDRESS_ROLE_SUBSCRIBE) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/access/src/device_state_manager.c:1033
    #23 0x00035f44 in dsm_address_subscription_add (raw_address=49153, p_address_handle=0x2003f7be) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/access/src/device_state_manager.c:1948
    #24 0x0004a7be in measurement_subscribe (argptr=0x20003660 <APP_SCHED_BUF.12703+360>, argsize=4) at /Users/paulquevedo/dev/thor/nordic/mesh/common/src/models/daylight.c:206
    #25 0x00043728 in app_sched_execute () at /Users/paulquevedo/dev/thor/Dependencies/nRF5_SDK/16.0.0/src/components/libraries/scheduler/app_scheduler.c:280
    #26 0x0001ce58 in applicationStep () at /Users/paulquevedo/dev/thor/test/include/application.h:28
    #27 0x0001d294 in main () at /Users/paulquevedo/dev/thor/test/src/main.c:239

Reply
  • Any update on this issue? I am also running into this on v4.1.0 when add subscriptions to the DSM from the application_scheduler.

    Here is my stack trace if that helps.

    #3  0x0001ce04 in mesh_assertion_handler (pc=181202) at /Users/paulquevedo/dev/thor/nordic/mesh/ledProvTest/src/error_handlers.c:75
    #4  0x0002c3d8 in backend_evt_handler (p_evt=0x2003f560) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/mesh_config.c:270
    #5  0x0002cbda in write_complete_cb (p_manager=0x20006d10 <m_dsm_file_backend_data+8>, p_entry=0xeb084, result=FM_RESULT_SUCCESS)
        at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/mesh_config_flashman_glue.c:125
    #6  0x000290a6 in end_action (p_action=0x200058a0 <m_action_queue_buffer+4>, result=FM_RESULT_SUCCESS, p_entry=0xeb084) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/flash_manager.c:486
    #7  0x000296be in process_action_queue () at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/flash_manager.c:788
    #8  0x00029720 in flash_op_ended_callback (user=MESH_FLASH_USER_MESH, p_op=0x20005524 <m_users+248>, token=26) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/flash_manager.c:807
    #9  0x00023894 in send_end_events () at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/mesh_flash.c:159
    #10 0x000267ee in bearer_event_handler () at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/bearer_event.c:380
    #11 0x000263f8 in QDEC_IRQHandler () at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/bearer_event.c:145
    #12 <signal handler called>
    #13 0x00026694 in bearer_event_flag_set (flag=3) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/bearer_event.c:304
    #14 0x000289fa in schedule_processing () at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/flash_manager.c:126
    #15 0x00029bcc in flash_manager_entry_commit (p_entry=0x200058ac <m_action_queue_buffer+16>) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/flash_manager.c:1169
    #16 0x0002cd8a in mesh_config_backend_record_write (p_file=0x20006d08 <m_dsm_file_backend_data>, p_data=0x2003f6b8 "\001\300\003 +\255\002", length=2)
        at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/mesh_config_flashman_glue.c:257
    #17 0x0002ca38 in mesh_config_backend_store (id=..., p_entry=0x2003f6b8 "\001\300\003 +\255\002", entry_len=2) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/mesh_config_backend.c:139
    #18 0x0002c16e in dirty_entries_process () at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/mesh_config.c:163
    #19 0x0002c264 in entry_store (p_params=0x551b8 <m_dsm_nonvirtual_addr_params>, id=..., p_entry=0x2003f760) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/mesh_config.c:200
    #20 0x0002c644 in mesh_config_entry_set (id=..., p_entry=0x2003f760) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/core/src/mesh_config.c:401
    #21 0x00035972 in dsm_entry_store (record_id=4096, handle=2, p_property=0x20006c88 <m_addr_nonvirtual_allocated>) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/access/src/device_state_manager.c:1674
    #22 0x00034e04 in add_address (raw_address=49153, p_address_handle=0x2003f7be, role=DSM_ADDRESS_ROLE_SUBSCRIBE) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/access/src/device_state_manager.c:1033
    #23 0x00035f44 in dsm_address_subscription_add (raw_address=49153, p_address_handle=0x2003f7be) at /Users/paulquevedo/dev/thor/Dependencies/nRF5_Mesh_SDK/4.1.0/src/mesh/access/src/device_state_manager.c:1948
    #24 0x0004a7be in measurement_subscribe (argptr=0x20003660 <APP_SCHED_BUF.12703+360>, argsize=4) at /Users/paulquevedo/dev/thor/nordic/mesh/common/src/models/daylight.c:206
    #25 0x00043728 in app_sched_execute () at /Users/paulquevedo/dev/thor/Dependencies/nRF5_SDK/16.0.0/src/components/libraries/scheduler/app_scheduler.c:280
    #26 0x0001ce58 in applicationStep () at /Users/paulquevedo/dev/thor/test/include/application.h:28
    #27 0x0001d294 in main () at /Users/paulquevedo/dev/thor/test/src/main.c:239

Children
No Data
Related