I'm working on a ble peripheral that uses nRF5340, recently upgraded to v2.4.2, Zephyr v3.3.99.
According to my ble.c flow, when user refuses to confirm by pushbutton to pair with peer, connection gets closed and advertising restarted.
This is the log starting on closing the connection
[00:00:43.045,318] <inf> ble: rejecting connection (0x20004af8)
[00:00:43.052,154] <inf> ble: deleted bond for peer 5B:52:A3:EF:6A:45 (random), id 0
[00:00:43.060,302] <err> bt_conn: not connected!
[00:00:43.065,612] <dbg> bt_hci_core: bt_hci_host_num_completed_packets: Reporting completed packet for handle 0
[00:00:43.076,232] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5
[00:00:43.084,228] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20027ed0
[00:00:43.091,278] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
[00:00:43.098,571] <dbg> bt_hci_core: bt_send: buf 0x20027ed0 len 8 type 0
[00:00:43.106,018] <dbg> bt_hci_core: bt_recv: buf 0x20027ac8 len 6
[00:00:43.112,701] <dbg> bt_hci_core: hci_disconn_complete_prio: status 0x00 handle 0 reason 0x16
[00:00:43.122,009] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:43.129,913] <dbg> bt_hci_core: rx_work_handler: buf 0x20027ac8 type 1 len 6
[00:00:43.137,939] <dbg> bt_hci_core: hci_event: event 0x05
[00:00:43.143,951] <dbg> bt_hci_core: hci_disconn_complete: status 0x00 handle 0 reason 0x16
[00:00:43.152,862] <dbg> bt_hci_core: process_events: count 3
[00:00:43.158,996] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:43.165,527] <dbg> bt_hci_core: process_events: ev->state 1
[00:00:43.172,058] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:43.178,619] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
[00:00:43.186,767] <wrn> ble: disconnected from peer 5B:52:A3:EF:6A:45 (random) [reason: 0x16]
[00:00:43.196,166] <inf> ble: total bonded peers: 0
[00:00:43.201,568] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2006 param_len 15
[00:00:43.209,625] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20027eb0
[00:00:43.216,674] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x20027eb0 opcode 0x2006 len 18
[00:00:43.225,830] <dbg> bt_hci_core: process_events: count 2
[00:00:43.231,964] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:43.238,494] <dbg> bt_hci_core: send_cmd: calling net_buf_get
[00:00:43.245,178] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
[00:00:43.252,044] <dbg> bt_hci_core: send_cmd: Sending command 0x2006 (buf 0x20027eb0) to driver
[00:00:43.261,352] <dbg> bt_hci_core: bt_send: buf 0x20027eb0 len 18 type 0
[00:00:43.268,768] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:43.275,268] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
[00:00:43.283,233] <dbg> bt_hci_core: bt_recv: buf 0x20027eb0 len 6
[00:00:43.289,886] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x0c35
[00:00:43.296,752] <dbg> bt_hci_core: hci_cmd_done: opcode 0x0c35 status 0x12 buf 0x20027eb0
[00:00:43.305,633] <wrn> bt_hci_core: OpCode 0x0c35 completed instead of expected 0x2006 <<<<< I THINK HERE THINGS GETS START MESSING
[00:00:43.314,483] <dbg> bt_hci_core: bt_recv: buf 0x20027ac8 len 6
[00:00:43.321,136] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x2006
[00:00:43.328,002] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2006 status 0x00 buf 0x20027ac8
[00:00:43.336,944] <wrn> bt_hci_core: opcode 0x2006 pool id 3 pool 0x20003cf4 != &hci_cmd_pool 0x20003d5c
ASSERTION FAIL [err == 0] @ ZEPHYR_BASE/subsys/bluetooth/host/hci_core.c:330 <<<<< HERE'S TIMEOUT EXCEPTION
command opcode 0x2006 timeout with err -11
[00:00:53.236,633] <err> os: r0/a1: 0x00000003 r1/a2: 0x00000000 r2/a3: 0x00000000
[00:00:53.245,208] <err> os: r3/a4: 0x200056c4 r12/ip: 0xa0000000 r14/lr: 0x0001dc01
[00:00:53.253,784] <err> os: xpsr: 0x41100000
[00:00:53.258,941] <err> os: s[ 0]: 0x00000000 s[ 1]: 0x00000000 s[ 2]: 0x00000000 s[ 3]: 0x00000000
[00:00:53.269,226] <err> os: s[ 4]: 0x00000000 s[ 5]: 0x00000000 s[ 6]: 0x00000000 s[ 7]: 0x00000000
[00:00:53.279,541] <err> os: s[ 8]: 0x00000000 s[ 9]: 0x00000000 s[10]: 0x00000000 s[11]: 0x00000000
[00:00:53.289,825] <err> os: s[12]: 0x00000000 s[13]: 0x00000000 s[14]: 0x00000000 s[15]: 0x00000000
[00:00:53.300,079] <err> os: fpscr: 0x00000000
[00:00:53.305,236] <err> os: Faulting instruction address (r15/pc): 0x0001dc0c
[00:00:53.313,049] <err> os: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0
[00:00:53.320,587] <err> os: Current thread: 0x200050d8 (unknown)
[00:00:53.327,270] <err> os: Halting system
The function bt_hci_cmd_send_sync() exits for timeout, perhaps because of line
[00:00:43.305,633] <wrn> bt_hci_core: OpCode 0x0c35 completed instead of expected 0x2006
It's kind of like the bt controller gets confused with opcodes. It would be nice to know what is this opcode 0x0c35.
Can give a help ?
Thanks,
Gabriele
