nRF5340: BLE host ASSERTION FAIL with 'command opcode 0x200a timeout with err -11'

[Yanpengwu]

Hi Support Team,

I'm using BLE in 'Split Controller and Host' mode on nRF5340 DK. I ported the sample 'peripheral_uart' for appCore and 'hci_rpmsg' for netCore, and the bidirectional communication between the appCore's terminal and 'nRF Connect for Mobile' APP is successful.

I met twice ASSERTION FAIL on BLE host side:

ASSERTION FAIL [err == 0] @ WEST_TOPDIR/zephyr/subsys/bluetooth/host/hci_core.c:338
        command opcode 0x200a timeout with err -11

[00:03:32.090,637] <err> os: r0/a1:  0x00000003  r1/a2:  0x00041fa4  r2/a3:  0x00000000
[00:03:32.090,667] <err> os: r3/a4:  0x000227f5 r12/ip:  0x20001b48 r14/lr:  0x0001163d
[00:03:32.090,698] <err> os:  xpsr:  0x61000000
[00:03:32.090,698] <err> os: Faulting instruction address (r15/pc): 0x00011648
[00:03:32.090,728] <err> os: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0
[00:03:32.090,759] <err> os: Current thread: 0x20005938 (sysworkq)
[00:03:32.265,838] <err> fatal_error: Resetting system

I checked the code, seems the opcode 0x200a is ' #define BT_HCI_OP_REJECT_CONN_REQ               BT_OP(BT_OGF_LINK_CTRL, 0x000a)'. 

It happened when I disconnect the BLE connection on the app 'nRF Connect for Mobile'.

Could you give some guidance on why this happened and how to fix it? Thank you very much.

Best regards,

Yanpeng Wu

[Yanpengwu]

Update: adding some trace for this error.

Fullscreen ASSERTION FAIL trace.txt Download

[00:00:00.298,950] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:00.299,407] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:00.300,018] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:00.300,415] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:00.300,872] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:00.301,330] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:00.305,023] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:00.305,694] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:00.306,365] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:00.306,976] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:00.310,852] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:00.311,279] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:00.311,676] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:00.312,133] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:00.312,561] <dbg> bt_conn: bt_conn_prepare_events: 

[00:00:15.323,669] <inf> main: ApplicationCore - Hello 4
[00:00:20.323,791] <inf> main: ApplicationCore - Hello 5
[00:00:22.684,753] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
[00:00:22.684,753] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
[00:00:22.684,783] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
[00:00:22.684,875] <dbg> bt_conn: bt_conn_set_state: connecting-adv -> connected
[00:00:22.685,150] <inf> ble_host: Connected 72:E5:F7:C3:FC:0E (random)
[00:00:22.685,150] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:22.685,302] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:22.685,363] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20003080 to poll list
[00:00:22.685,394] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:22.685,760] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:22.685,791] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20003080 to poll list
[00:00:22.685,852] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:22.686,096] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:22.830,657] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:22.830,688] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:22.830,871] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:22.830,902] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:22.980,529] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:22.980,560] <dbg> bt_conn: tx_notify: conn 0x20003080
[00:00:22.980,560] <dbg> bt_conn: bt_conn_recv: handle 15 len 11 flags 02
[00:00:22.980,590] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:00:22.980,590] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:22.980,712] <dbg> bt_conn: bt_conn_send_cb: conn handle 15 buf len 9 cb 0x36d3d user_data 0x20009f94
[00:00:22.980,834] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:22.980,895] <dbg> bt_conn: bt_conn_process_tx: conn 0x20003080
[00:00:22.980,926] <dbg> bt_conn: send_buf: conn 0x20003080 buf 0x200152d0 len 9
[00:00:22.980,926] <dbg> bt_conn: send_buf: send single
[00:00:22.980,957] <dbg> bt_conn: do_send_frag: conn 0x20003080 buf 0x200152d0 len 9 flags 0x02
[00:00:22.981,048] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:22.981,048] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:22.981,170] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:22.981,170] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20003080 to poll list
[00:00:22.981,201] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:23.040,527] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:23.040,618] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:23.040,649] <dbg> bt_conn: tx_complete_work: conn 0x20003080
[00:00:23.040,710] <dbg> bt_conn: tx_notify: conn 0x20003080
[00:00:23.040,740] <dbg> bt_conn: tx_notify: tx 0x20006204 cb 0x36d3d user_data 0x20009f94
[00:00:23.040,863] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:23.040,893] <dbg> bt_conn: tx_notify: conn 0x20003080
[00:00:23.040,893] <dbg> bt_conn: bt_conn_recv: handle 15 len 11 flags 02
[00:00:23.040,954] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:00:23.040,985] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:23.041,107] <dbg> bt_conn: bt_conn_send_cb: conn handle 15 buf len 24 cb 0x36d3d user_data 0x20009f94
[00:00:23.041,137] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:23.041,229] <dbg> bt_conn: bt_conn_process_tx: conn 0x20003080
[00:00:23.041,259] <dbg> bt_conn: send_buf: conn 0x20003080 buf 0x200152d0 len 24
[00:00:23.041,259] <dbg> bt_conn: send_buf: send single
[00:00:23.041,320] <dbg> bt_conn: do_send_frag: conn 0x20003080 buf 0x200152d0 len 24 flags 0x02
[00:00:23.041,381] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:23.041,381] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:23.041,503] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:23.041,503] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20003080 to poll list
[00:00:23.041,564] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:23.100,463] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:23.100,555] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:23.100,585] <dbg> bt_conn: tx_complete_work: conn 0x20003080
[00:00:23.100,646] <dbg> bt_conn: tx_notify: conn 0x20003080
[00:00:23.100,677] <dbg> bt_conn: tx_notify: tx 0x20006214 cb 0x36d3d user_data 0x20009f94
[00:00:23.100,799] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:23.100,830] <dbg> bt_conn: tx_notify: conn 0x20003080
[00:00:23.100,830] <dbg> bt_conn: bt_conn_recv: handle 15 len 8 flags 02
[00:00:23.100,891] <dbg> bt_conn: bt_acl_recv: First, len 8 final 4
[00:00:23.100,921] <dbg> bt_conn: bt_acl_recv: Successfully parsed 8 byte L2CAP packet
[00:00:23.101,043] <dbg> bt_conn: bt_conn_send_cb: conn handle 15 buf len 5 cb 0x36d3d user_data 0x20009f94
[00:00:23.101,074] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:23.101,165] <dbg> bt_conn: bt_conn_process_tx: conn 0x20003080
[00:00:23.101,165] <dbg> bt_conn: send_buf: conn 0x20003080 buf 0x200152d0 len 5
[00:00:23.101,196] <dbg> bt_conn: send_buf: send single
[00:00:23.101,196] <dbg> bt_conn: do_send_frag: conn 0x20003080 buf 0x200152d0 len 5 flags 0x02
[00:00:23.101,287] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:23.101,318] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:23.101,409] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:23.101,440] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20003080 to poll list
[00:00:23.101,440] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:23.160,125] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:23.160,156] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:23.160,247] <dbg> bt_conn: tx_complete_work: conn 0x20003080
[00:00:23.160,247] <dbg> bt_conn: tx_notify: conn 0x20003080
[00:00:23.160,278] <dbg> bt_conn: tx_notify: tx 0x20006224 cb 0x36d3d user_data 0x20009f94
[00:00:23.190,490] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:23.190,521] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:23.241,760] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:23.241,790] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:23.294,250] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:23.294,311] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:24.049,987] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:24.050,018] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:25.323,913] <inf> main: ApplicationCore - Hello 6
[00:00:27.684,997] <dbg> bt_conn: deferred_work: conn 0x20003080
[00:00:27.685,028] <dbg> bt_conn: send_conn_le_param_update: conn 0x20003080 features 0x2d params (24-40 0 42)
[00:00:27.685,058] <dbg> bt_conn: bt_conn_send_cb: conn handle 15 buf len 16 cb 0 user_data 0
[00:00:27.685,150] <dbg> bt_conn: bt_conn_process_tx: conn 0x20003080
[00:00:27.685,180] <dbg> bt_conn: send_buf: conn 0x20003080 buf 0x20015a0c len 16
[00:00:27.685,180] <dbg> bt_conn: send_buf: send single
[00:00:27.685,211] <dbg> bt_conn: do_send_frag: conn 0x20003080 buf 0x20015a0c len 16 flags 0x02
[00:00:27.685,302] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:27.685,333] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20003080 to poll list
[00:00:27.685,333] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:27.740,386] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:27.740,417] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:27.770,385] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:27.770,416] <dbg> bt_conn: tx_notify: conn 0x20003080
[00:00:27.770,416] <dbg> bt_conn: bt_conn_recv: handle 15 len 10 flags 02
[00:00:27.770,446] <dbg> bt_conn: bt_acl_recv: First, len 10 final 6
[00:00:27.770,446] <dbg> bt_conn: bt_acl_recv: Successfully parsed 10 byte L2CAP packet
[00:00:27.770,538] <dbg> bt_conn: bt_conn_ref: handle 15 ref 3 -> 4
[00:00:27.770,538] <dbg> bt_conn: bt_conn_unref: handle 15 ref 4 -> 3
[00:00:27.770,660] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:27.980,499] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:27.980,499] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:30.324,035] <inf> main: ApplicationCore - Hello 7
[00:00:35.324,157] <inf> main: ApplicationCore - Hello 8
[00:00:40.324,249] <inf> main: ApplicationCore - Hello 9
[00:00:42.440,490] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:42.440,582] <dbg> bt_conn: bt_conn_set_state: connected -> disconnect-complete
[00:00:42.440,612] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:42.440,704] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3
[00:00:42.440,734] <dbg> bt_conn: bt_conn_set_state: disconnect-complete -> disconnected
[00:00:42.440,734] <dbg> bt_conn: tx_notify: conn 0x20003080
[00:00:42.440,826] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
[00:00:42.440,856] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:42.440,979] <dbg> bt_conn: deferred_work: conn 0x20003080
[00:00:42.441,253] <inf> ble_host: Disconnected: 72:E5:F7:C3:FC:0E (random) (reason 19)
[00:00:42.441,345] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1
[00:00:42.441,345] <dbg> bt_conn: bt_conn_unref: handle 15 ref 1 -> 0
[00:00:42.441,467] <dbg> bt_conn: bt_conn_set_state: disconnected -> connecting-adv
[00:00:42.441,467] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
[00:00:42.441,650] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:45.324,401] <inf> main: ApplicationCore - Hello 10
[00:00:50.324,645] <inf> main: ApplicationCore - Hello 11
[00:00:52.455,505] <err> os: r0/a1:  0x00000003  r1/a2:  0x000424aa  r2/a3:  0x00000000
[00:00:52.455,535] <err> os: r3/a4:  0x00022dd9 r12/ip:  0x20001b48 r14/lr:  0x000114dd
[00:00:52.455,535] <err> os:  xpsr:  0x61000000
[00:00:52.455,566] <err> os: Faulting instruction address (r15/pc): 0x000114e8
[00:00:52.455,596] <err> os: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0
[00:00:52.455,627] <err> os: Current thread: 0x20005938 (sysworkq)
[00:00:52.630,645] <err> fatal_error: Resetting systemm

[Vidar Berg]

Hello,

The timeout indicates that there is a communication issue between the application and network core. This is likely related to the RAM partition layout discussed in your previous ticket:  nRF5340 BLE: How to create the rpmsg_nrf53_sram in partitions.yml during porting the sample 'peripheral_uart' 

Best regards,

Vidar