IPC breaks when enabling bluetooth mesh on nrf54l15

Hello,

We are developing a product based on the nRF54L15, using BT Mesh. We also use the FLPR. For communication between the cores, we use ICMSG.

Separately, ICMSG and BT Mesh work well, but for some reason, when we include BT Mesh, cpuapp cannot set up ICMSG properly, even if the ICMSG setup is done before `bt_enable()`. The callback `ipc_ept_cfg.cb.bound` is never called. We are getting serial logging from the FLPR, so we know that is running and its `ipc_ept_cfg.cb.bound` is called.

This question (The IPC and bt_enable are turned on at the same time, and the chip is not working) about the nRF53 is similar, but there is no IPC Radio Firmware on the nRF54 as far as I can tell.

Here is the relevant part of our prj.conf for cpuapp:

CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=8192
CONFIG_MAIN_STACK_SIZE=8192
CONFIG_LOG_BUFFER_SIZE=8192
CONFIG_BT_RX_STACK_SIZE=5120

CONFIG_LOG=y
CONFIG_REQUIRES_FLOAT_PRINTF=y

CONFIG_BT_SETTINGS=y
CONFIG_FLASH=y
CONFIG_FLASH_MAP=y
CONFIG_SETTINGS=y
CONFIG_SOC_FLASH_NRF_PARTIAL_ERASE=n
CONFIG_SPI_NOR=n
CONFIG_NVS=n
CONFIG_NVS_LOOKUP_CACHE=n
CONFIG_SETTINGS_NVS_NAME_CACHE=n
CONFIG_ZMS=y
CONFIG_SETTINGS_ZMS_CUSTOM_SECTOR_COUNT=y
CONFIG_SETTINGS_ZMS_SECTOR_COUNT=8
CONFIG_ZMS_LOOKUP_CACHE=y
CONFIG_ZMS_LOOKUP_CACHE_SIZE=512
CONFIG_ZMS_LOOKUP_CACHE_FOR_SETTINGS=y

CONFIG_HWINFO=y
CONFIG_GPIO=y

CONFIG_BT=y
CONFIG_BT_L2CAP_TX_BUF_COUNT=5
CONFIG_BT_PERIPHERAL=y
CONFIG_BT_OBSERVER=y
CONFIG_BT_BROADCASTER=y

CONFIG_BT_CTLR_DUP_FILTER_LEN=0
CONFIG_BT_CTLR_LE_ENC=n
CONFIG_BT_CTLR_LE_PING=n
CONFIG_BT_DATA_LEN_UPDATE=n
CONFIG_BT_PHY_UPDATE=n
CONFIG_BT_CTLR_MIN_USED_CHAN=n
CONFIG_BT_CTLR_PRIVACY=n
CONFIG_BT_CTLR_CHAN_SEL_2=n

CONFIG_BT_MESH=y
CONFIG_BT_MESH_MODEL_EXTENSIONS=y
CONFIG_BT_MESH_RELAY=y
CONFIG_BT_MESH_FRIEND=y
CONFIG_BT_MESH_PB_GATT=y
CONFIG_BT_MESH_PB_ADV=y
CONFIG_BT_MESH_GATT_PROXY=y

CONFIG_BT_MESH_SUBNET_COUNT=2
CONFIG_BT_MESH_APP_KEY_COUNT=2
CONFIG_BT_MESH_MODEL_GROUP_COUNT=2
CONFIG_BT_MESH_LABEL_COUNT=3

CONFIG_BT_MESH_ADV_BUF_COUNT=10
CONFIG_BT_MESH_TX_SEG_MSG_COUNT=3

CONFIG_BT_MESH_RX_SEG_MAX=32
CONFIG_BT_MESH_TX_SEG_MAX=32

CONFIG_MBOX=y
CONFIG_IPC_SERVICE=y
CONFIG_IPC_SERVICE_BACKEND_ICMSG=y
CONFIG_IPC_SERVICE_LOG_LEVEL_DBG=y

Any help is appreciated

- Fridtjof

  • Hi Fridtjof,

     

    I used the dt bindings found the boards/proto3*.overlay, and built for the nrf54l15dk/nrf54l15/cpuapp.

    I am unable to fully test this, as I do not have the gnss/modem that you are using physically connected, so it will fail during runtime, as shown in the log below.

    This is printed over RTT:

    00> [00:00:00.015,404] <inf> quectel_lcx6g: Resuming
    00> [00:00:00.015,411] <inf> quectel_lcx6g: Waiting until PM ready
    00> [00:00:10.515,242] <wrn> modem_chat: resume_script: timed out
    00> [00:00:10.515,296] <err> quectel_lcx6g: Failed to initialize GNSS
    00> *** Booting nRF Connect SDK v3.1.1-e2a97fe2578a ***
    00> *** Using Zephyr OS v4.1.99-ff8f0c579eeb ***
    00> [00:00:10.515,916] <inf> main: Initializing...
    00> 
    00> [00:00:10.515,925] <dbg> main: ipc_init: initializing IPC...
    00> [00:00:10.515,947] <dbg> ipc_service: ipc_service_register_endpoint: Register endpoint ipc_ept_0
    00> [00:00:10.517,563] <dbg> main: ipc_bound_cb: IPC ep bound
    00> 
    00> [00:00:10.517,595] <inf> main: IPC initialized.
    00> 
    00> [00:00:10.517,628] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:10.522,777] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:11.517,721] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:11.525,116] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
     

    IPC comms are running as they should in this scenario.  

    It seems like GNSS is somehow hindering the handshake.

    Can you share a log output of a working and a non-working scenario?

    Could you answer whether my understanding of IPC handshaking and explanation of the problem is correct?

    It is set up to ping/pong data at this time, and the scenarios that are most likely occurring is either a fault, or another blocking scenario that makes the firmware hang.

    Try setting "CONFIG_GNSS_LOG_LEVEL_DBG=y" for a bit more verbose output.

     

    Kind regards,

    Håkon

  • Here is appcpu log when not working. "Initializing IPC..." is the last thing that appcpu prints outside GNSS. I have replaced location data with "<<<REDACTED>>>".

    *** Booting nRF Connect SDK v3.0.1-9eb5615da66b ***
    *** Using Zephyr OS v4.0.99-77f865b8f8d0 ***
    [00:00:18.464,672] <inf> main: Initializing...
    
    [00:00:18.464,681] <dbg> main: ipc_init: initializing IPC...
    [00:00:18.464,702] <dbg> ipc_service: ipc_service_register_endpoint: Register endpoint ipc_ept_0
    [00:00:18.481,633] <dbg> modem_chat: modem_chat_log_received_command: $GNGGA, <<<REDACTED>>>
    [00:00:18.496,337] <dbg> modem_chat: modem_chat_log_received_command: $GNRMC, <<<REDACTED>>>
    Got a fix! <<<REDACTED>>>
    quectel_lc86g: gnss_info: {satellites_cnt: 16, hdop: 0.650, fix_status: DGNSS_FIX, fix_quality: DGNSS}
    
    quectel_lc86g: navigation_data: <<<REDACTED>>>
    
    quectel_lc86g: gnss_time: {hour: 13, minute: 52, millisecond 14000, month_day 15, month: 12, century_year: 25}
    
    [00:00:18.496,865] <dbg> modem_chat: modem_chat_on_unknown_command_received: $PQTMANTENNASTATUS,3,1,2,1*52
    [00:00:19.471,673] <dbg> modem_chat: modem_chat_log_received_command: $GNGGA, <<<REDACTED>>>
    [00:00:19.486,332] <dbg> modem_chat: modem_chat_log_received_command: $GNRMC, <<<REDACTED>>>
    Got a fix! <<<REDACTED>>>
    quectel_lc86g: gnss_info: {satellites_cnt: 16, hdop: 0.650, fix_status: DGNSS_FIX, fix_quality: DGNSS}
    
    quectel_lc86g: navigation_data: <<<REDACTED>>>
    
    quectel_lc86g: gnss_time: {hour: 13, minute: 52, millisecond 15000, month_day 15, month: 12, century_year: 25}
    
    [00:00:19.486,793] <dbg> modem_chat: modem_chat_on_unknown_command_received: $PQTMANTENNASTATUS,3,1,2,1*52
    [00:00:20.473,464] <dbg> modem_chat: modem_chat_log_received_command: $GNGGA, <<<REDACTED>>>
    [00:00:20.488,144] <dbg> modem_chat: modem_chat_log_received_command: $GNRMC, <<<REDACTED>>>
    Got a fix! <<<REDACTED>>>
    quectel_lc86g: gnss_info: {satellites_cnt: 16, hdop: 0.650, fix_status: DGNSS_FIX, fix_quality: DGNSS}
    
    quectel_lc86g: navigation_data: <<<REDACTED>>>
    
    quectel_lc86g: gnss_time: {hour: 13, minute: 52, millisecond 16000, month_day 15, month: 12, century_year: 25}
    
    [00:00:20.488,606] <dbg> modem_chat: modem_chat_on_unknown_command_received: $PQTMANTENNASTATUS,3,1,2,1*52
    [00:00:21.460,812] <dbg> modem_chat: modem_chat_log_received_command: $GNGGA, <<<REDACTED>>>
    [00:00:21.466,369] <dbg> modem_chat: modem_chat_log_received_command: $GPGSV, <<<REDACTED>>>
    [00:00:21.471,923] <dbg> modem_chat: modem_chat_log_received_command: $GPGSV, <<<REDACTED>>>
    [00:00:21.477,468] <dbg> modem_chat: modem_chat_log_received_command: $GPGSV, <<<REDACTED>>>
    [00:00:21.477,561] <dbg> modem_chat: modem_chat_log_received_command: $GLGSV, <<<REDACTED>>>
    [00:00:21.483,072] <dbg> modem_chat: modem_chat_log_received_command: $GAGSV, <<<REDACTED>>>
    10 satellites reported (of which 9 tracked)!
    [00:00:21.488,631] <dbg> modem_chat: modem_chat_log_received_command: $GAGSV, <<<REDACTED>>>
    [00:00:21.494,153] <dbg> modem_chat: modem_chat_log_received_command: $GAGSV, <<<REDACTED>>>
    quectel_lc86g: gnss_satellite: <<<REDACTED>>>
    
    quectel_lc86g: gnss_satellite: <<<REDACTED>>>
    
    quectel_lc86g: gnss_satellite: <<<REDACTED>>>
    
    quectel_lc86g: gnss_satellite: <<<REDACTED>>>
    
    quectel_lc86g: gnss_satellite: <<<REDACTED>>>
    
    quectel_lc86g: gnss_satellite: <<<REDACTED>>>
    
    quectel_lc86g: gnss_satellite: <<<REDACTED>>>
    
    quectel_lc86g: gnss_satellite: <<<REDACTED>>>
    
    quectel_lc86g: gnss_satellite: <<<REDACTED>>>
    
    quectel_lc86g: gnss_satellite: <<<REDACTED>>>
     

    Here is the cpuflpr log:

    *** Booting nRF Connect SDK v3.0.1-9eb5615da66b ***
    *** Using Zephyr OS v4.0.99-77f865b8f8d0 ***
    I: Initializing...
    
    D: initializing IPC...
    D: IPC ep bound
    
    I: IPC initialized.

  • Hi,

     

    So, you are stuck on the bound semaphore.

    One theory is that the timing is the reason why.

    I can add a 10+ second delay in my test, and that should also fail.

    So I added a quick test by appending k_msleep(10*1000):

    00> [00:00:10.507,290] <wrn> modem_chat: resume_script: timed out
    00> [00:00:10.507,339] <err> quectel_lcx6g: Failed to initialize GNSS
    00> *** Booting nRF Connect SDK v3.1.99-ef4b0afc4605 ***
    00> *** Using Zephyr OS v4.2.99-dcb90afc70fb ***
    00> [00:00:10.507,400] <inf> main: Initializing...
    00> 
    00> [00:00:10.507,404] <inf> main: Lets delay for 10
    00> [00:00:10.507,409] <inf> main: 0
    00> [00:00:11.507,476] <inf> main: 1
    00> [00:00:12.507,551] <inf> main: 2
    00> [00:00:13.507,618] <inf> main: 3
    00> [00:00:14.507,703] <inf> main: 4
    00> [00:00:15.507,772] <inf> main: 5
    00> [00:00:16.507,862] <inf> main: 6
    00> [00:00:17.507,933] <inf> main: 7
    00> [00:00:18.508,022] <inf> main: 8
    00> [00:00:19.508,093] <inf> main: 9
    00> [00:00:20.508,182] <dbg> main: ipc_init: initializing IPC...
    00> [00:00:20.508,211] <dbg> ipc_service: ipc_service_register_endpoint: Register endpoint ipc_ept_0
    00> [00:00:20.509,825] <dbg> main: ipc_bound_cb: IPC ep bound
    00> 
    00> [00:00:20.509,853] <inf> main: IPC initialized.
    00> 
    00> [00:00:20.509,885] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:20.515,032] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:21.509,975] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:21.517,373] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:22.510,074] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:22.519,644] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:23.510,189] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:23.521,908] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:24.510,269] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:24.524,177] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:25.510,376] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:25.526,436] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:26.510,454] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:26.528,699] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:27.510,532] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:27.530,962] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:28.510,643] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:28.533,228] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:29.510,748] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:29.535,492] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:30.510,853] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    (Connection lost)

    And also k_busy_wait(10*1000*1000) to emulate a blocking task, and also added another 10 sec after calling ipc_service_register_endpoint().

    00> [00:00:10.507,290] <wrn> modem_chat: resume_script: timed out
    00> [00:00:10.507,339] <err> quectel_lcx6g: Failed to initialize GNSS
    00> *** Booting nRF Connect SDK v3.1.99-ef4b0afc4605 ***
    00> *** Using Zephyr OS v4.2.99-dcb90afc70fb ***
    00> [00:00:10.507,400] <inf> main: Initializing...
    00> 
    00> [00:00:10.507,404] <inf> main: Lets delay for 10
    00> [00:00:20.503,724] <dbg> main: ipc_init: initializing IPC...
    00> [00:00:20.503,753] <dbg> ipc_service: ipc_service_register_endpoint: Register endpoint ipc_ept_0
    00> [00:00:20.505,373] <dbg> main: ipc_bound_cb: IPC ep bound
    00> 
    00> [00:00:30.488,836] <inf> main: IPC initialized.
    00> 
    00> [00:00:30.488,869] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:30.507,385] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:31.488,978] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:31.509,648] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:32.489,057] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:32.511,915] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:33.489,160] <dbg> main: send_message: ipc send: 5 = appcpu says hi

    And here a 10 sec delay between each ipc-call:

    00> *** Booting nRF Connect SDK v3.1.99-ef4b0afc4605 ***
    00> *** Using Zephyr OS v4.2.99-dcb90afc70fb ***
    00> [00:00:10.507,344] <inf> main: Initializing...
    00> 
    00> [00:00:10.507,349] <inf> main: Lets delay for 10
    00> [00:00:20.506,733] <dbg> main: ipc_init: initializing IPC...
    00> [00:00:30.495,998] <dbg> ipc_service: ipc_service_register_endpoint: Register endpoint ipc_ept_0
    00> [00:00:30.497,621] <dbg> main: ipc_bound_cb: IPC ep bound
    00> 
    00> [00:00:40.483,683] <inf> main: IPC initialized.
    00> 
    00> [00:00:40.483,716] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:40.499,637] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:41.483,825] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:41.501,903] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:42.483,903] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:42.504,165] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:43.484,013] <dbg> main: send_message: ipc send: 5 = appcpu says hi
    00> [00:00:43.506,431] <dbg> main: ipc_recv_cb: ipc received: 3 = reaction
    00> [00:00:44.484,085] <dbg> main: send_message: ipc send: 5 = appcpu says hi

      

    I am unable to reproduce your scenario with the above emulation, which indicates that the gnss/modem subsys might be blocking the main thread, or that the issue is related to the image on the flpr side.

     

    I would recommend that you check with the zephyr community and/or the modem manufacturer if it is expected that the gnss/modem shall block in such a way.

     

    Kind regards,

    Håkon

Related