Hello,
I’m having an issue with my setup: I have a nRF9160 running the bt/peripheral sample through a nRF52840 (running the hci_lpuart sample). It seems to work fine with nRF SDK v2.7.0. However when embedded in my application, I have a somewhat erratic behavior with some showing this in the logs:
Fullscreen
1
2
3
[00:01:25.682,312] <inf> ble: Connected
[00:01:25.943,084] <wrn> bt_conn: conn 0x20017c98 failed to establish. RF noise?
[00:01:25.957,672] <inf> ble: Disconnected (reason 0x3e)
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
[00:01:25.682,312] <inf> ble: Connected [00:01:25.943,084] <wrn> bt_conn: conn 0x20017c98 failed to establish. RF noise? [00:01:25.957,672] <inf> ble: Disconnected (reason 0x3e)
I have compared the CONFIG_BT_* attributes in the .config of both the sample and my app and there is no difference at all. So far, it fails with a Pixel 9 running Android 16.
I have checked similar issues but nothing seems to help… It looks like it could be a parameter negociation issue, a clock issue, maybe the fact that the modem is enabled could also be an issue… I have tried changing multiple parameters, increasing the BT TX stack, nothing has helped. Here’s the log (debug level) with my application, and the log with the peripheral sample (running on the same hardware and nRF SDK version, with the same nRF52 hci_lpuart binary):
Fullscreen
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
RAM usage & Logs
My app
uart> kernel threads
Scheduler: 596106 since last call
Threads:
0x20018a78 bt_rx_thread
options: 0x0, priority: -8 timeout: 0
state: pending, entry: 0x7079d
stack size 2200, unused 1616, usage 584 / 2200 (26 %)
0x20017a20 BT RX WQ
options: 0x0, priority: -8 timeout: 0
state: pending, entry: 0x8396d
stack size 2200, unused 1616, usage 584 / 2200 (26 %)
0x20017968 BT TX
options: 0x0, priority: -9 timeout: 0
state: pending, entry: 0x551d9
stack size 512, unused 72, usage 440 / 512 (85 %)
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
RAM usage & Logs My app uart> kernel threads Scheduler: 596106 since last call Threads: 0x20018a78 bt_rx_thread options: 0x0, priority: -8 timeout: 0 state: pending, entry: 0x7079d stack size 2200, unused 1616, usage 584 / 2200 (26 %) 0x20017a20 BT RX WQ options: 0x0, priority: -8 timeout: 0 state: pending, entry: 0x8396d stack size 2200, unused 1616, usage 584 / 2200 (26 %) 0x20017968 BT TX options: 0x0, priority: -9 timeout: 0 state: pending, entry: 0x551d9 stack size 512, unused 72, usage 440 / 512 (85 %) 0x20018ee0 mqtt_helper_thread options: 0x0, priority: 14 timeout: 0 state: pending, entry: 0x79cad stack size 4096, unused 3880, usage 216 / 4096 (5 %) 0x20018df8 date_time_work_q options: 0x0, priority: 14 timeout: 0 state: pending, entry: 0x8396d stack size 1280, unused 1048, usage 232 / 1280 (18 %) 0x200189c0 conn_mgr_monitor options: 0x0, priority: -1 timeout: 0 state: pending, entry: 0x6fc65 stack size 1024, unused 712, usage 312 / 1024 (30 %) 0x20018d18 lte_lc_work_q options: 0x0, priority: 14 timeout: 0 state: pending, entry: 0x8396d stack size 1024, unused 792, usage 232 / 1024 (22 %) 0x20018718 rx_q[0] options: 0x0, priority: -1 timeout: 0 state: pending, entry: 0xa3043 stack size 1504, unused 1296, usage 208 / 1504 (13 %) 0x20018620 net_mgmt options: 0x0, priority: -1 timeout: 0 state: pending, entry: 0x8396d stack size 2048, unused 1816, usage 232 / 2048 (11 %) 0x200187d8 tcp_work options: 0x0, priority: -14 timeout: 0 state: pending, entry: 0x8396d stack size 1024, unused 792, usage 232 / 1024 (22 %) *0x200174b8 shell_uart options: 0x0, priority: 14 timeout: 0 state: queued, entry: 0x4eab1 stack size 2048, unused 944, usage 1104 / 2048 (53 %) 0x20017890 BT LW WQ options: 0x0, priority: 10 timeout: 0 state: pending, entry: 0x8396d stack size 1304, unused 368, usage 936 / 1304 (71 %) 0x20019108 sysworkq options: 0x1, priority: -1 timeout: 0 state: pending, entry: 0x8396d stack size 3072, unused 2840, usage 232 / 3072 (7 %) 0x20015358 logging options: 0x0, priority: 14 timeout: 71528 state: pending, entry: 0x4b3cd stack size 2048, unused 1688, usage 360 / 2048 (17 %) 0x20018f98 idle options: 0x1, priority: 15 timeout: 0 state: , entry: 0x82eb9 stack size 320, unused 216, usage 104 / 320 (32 %) [00:01:01.263,458] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.263,519] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.263,549] <dbg> bt_driver: process_rx: remaining 1 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.263,580] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 31 bytes [00:01:01.263,580] <dbg> bt_driver: process_rx: remaining 30 discard 0 have_hdr 1 rx.buf 0 len 0 [00:01:01.263,610] <dbg> bt_driver: get_rx: type 0x04, evt 0x3e [00:01:01.263,641] <dbg> bt_driver: read_payload: Allocated rx.buf 0x200311c0 [00:01:01.263,671] <dbg> bt_driver: read_payload: got 30 bytes, remaining 0 [00:01:01.263,732] <dbg> bt_driver: read_payload: Payload (len 33): 3e1f0a000f000101776d36a5f14600000000000000000000000027000000f40101 [00:01:01.263,763] <dbg> bt_driver: read_payload: Putting buf 0x200311c0 to rx fifo [00:01:01.263,854] <dbg> bt_driver: rx_thread: Calling bt_recv(0x200311c0) [00:01:01.263,885] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x200311c0 len 33 [00:01:01.263,946] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:01:01.263,946] <dbg> bt_hci_core: rx_work_handler: buf 0x200311c0 type 1 len 33 [00:01:01.263,977] <dbg> bt_hci_core: hci_event: event 0x3e [00:01:01.264,007] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x0a [00:01:01.264,251] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: status 0x00 handle 15 role 1 peer 46:F1:A5:36:6D:77 (random) peer RPA 00:00:00:00:00:00 [00:01:01.264,343] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: local RPA 00:00:00:00:00:00 [00:01:01.264,465] <dbg> bt_keys: bt_keys_find_irk: 46:F1:A5:36:6D:77 (random) [00:01:01.264,617] <dbg> bt_keys: bt_keys_find_irk: No IRK for 46:F1:A5:36:6D:77 (random) [00:01:01.264,648] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2 [00:01:01.264,648] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1 [00:01:01.264,678] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2 [00:01:01.264,709] <dbg> bt_adv: bt_le_adv_resume: Host cannot resume connectable advertising (-12) [00:01:01.264,770] <dbg> bt_conn: bt_conn_set_state: adv-connectable -> connected [00:01:01.264,801] <dbg> bt_l2cap: l2cap_accept: conn 0x20017c30 handle 15 [00:01:01.264,831] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x20017c30 chan 0x20019d20 [00:01:01.264,862] <dbg> bt_l2cap: l2cap_connected: ch 0x20019d20 cid 0x0005 [00:01:01.264,862] <dbg> bt_smp: bt_smp_accept: conn 0x20017c30 handle 15 [00:01:01.264,892] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x20017c30 chan 0x20017efc [00:01:01.264,923] <dbg> bt_smp: bt_smp_connected: chan 0x20017efc cid 0x0006 [00:01:01.264,953] <dbg> bt_att: bt_att_accept: conn 0x20017c30 handle 15 [00:01:01.264,984] <dbg> bt_att: att_chan_attach: att 0x20031a0c chan 0x20028ea0 flags 0 [00:01:01.265,014] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x20017c30 chan 0x20028ea4 [00:01:01.265,045] <dbg> bt_att: bt_att_connected: chan 0x20028ea4 cid 0x0004 [00:01:01.265,045] <inf> ble: Updated MTU: TX: 23 RX: 23 bytes [00:01:01.265,075] <dbg> bt_gatt: bt_gatt_connected: conn 0x20017c30 [00:01:01.265,197] <dbg> bt_keys: bt_keys_find_addr: 46:F1:A5:36:6D:77 (random) [00:01:01.265,319] <dbg> bt_att: bt_att_status: chan 0x20028ea4 status 0x20028eb4 [00:01:01.265,319] <inf> ble: Connected [00:01:01.265,380] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2016 param_len 2 [00:01:01.265,411] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200316d0 [00:01:01.265,411] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200316d0 opcode 0x2016 len 5 [00:01:01.265,472] <dbg> bt_hci_core: process_events: count 2 [00:01:01.265,502] <dbg> bt_hci_core: process_events: ev->state 4 [00:01:01.265,533] <dbg> bt_hci_core: send_cmd: calling net_buf_get [00:01:01.265,533] <dbg> bt_hci_core: send_cmd: calling sem_take_wait [00:01:01.265,563] <dbg> bt_hci_core: send_cmd: Sending command 0x2016 (buf 0x200316d0) to driver [00:01:01.265,594] <dbg> bt_hci_core: bt_send: buf 0x200316d0 len 5 type 0 [00:01:01.265,594] <dbg> bt_driver: h4_send: buf 0x200316d0 type 0 len 5 [00:01:01.265,686] <dbg> bt_hci_core: process_events: ev->state 1 [00:01:01.265,716] <dbg> bt_conn: bt_conn_prepare_events: [00:01:01.265,716] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20017c30 to poll list [00:01:01.265,747] <dbg> bt_conn: conn_prepare_events: wait on host fifo [00:01:01.265,747] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events [00:01:01.265,808] <dbg> bt_driver: rx_thread: rx.buf 0 [00:01:01.269,653] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.269,683] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.269,714] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 4 bytes [00:01:01.269,744] <dbg> bt_driver: process_rx: remaining 4 discard 0 have_hdr 1 rx.buf 0 len 0 [00:01:01.269,744] <dbg> bt_driver: get_rx: type 0x04, evt 0x0f [00:01:01.269,775] <dbg> bt_driver: read_payload: Allocated rx.buf 0x200311dc [00:01:01.269,805] <dbg> bt_driver: read_payload: got 4 bytes, remaining 0 [00:01:01.269,866] <dbg> bt_driver: read_payload: Payload (len 6): 0f0400011620 [00:01:01.269,866] <dbg> bt_driver: read_payload: Putting buf 0x200311dc to rx fifo [00:01:01.270,019] <dbg> bt_driver: rx_thread: Calling bt_recv(0x200311dc) [00:01:01.270,019] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x200311dc len 6 [00:01:01.270,050] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2016 [00:01:01.270,080] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2016 status 0x00 buf 0x200311dc [00:01:01.270,172] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200316d0 opcode 0x2016 len 0 [00:01:01.270,202] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2032 param_len 7 [00:01:01.270,233] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200316d0 [00:01:01.270,233] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200316d0 opcode 0x2032 len 10 [00:01:01.270,324] <dbg> bt_hci_core: process_events: count 3 [00:01:01.270,355] <dbg> bt_hci_core: process_events: ev->state 4 [00:01:01.270,355] <dbg> bt_hci_core: send_cmd: calling net_buf_get [00:01:01.270,385] <dbg> bt_hci_core: send_cmd: calling sem_take_wait [00:01:01.270,385] <dbg> bt_hci_core: send_cmd: Sending command 0x2032 (buf 0x200316d0) to driver [00:01:01.270,416] <dbg> bt_hci_core: bt_send: buf 0x200316d0 len 10 type 0 [00:01:01.270,446] <dbg> bt_driver: h4_send: buf 0x200316d0 type 0 len 10 [00:01:01.270,507] <dbg> bt_hci_core: process_events: ev->state 0 [00:01:01.270,538] <dbg> bt_hci_core: process_events: ev->state 0 [00:01:01.270,538] <dbg> bt_conn: bt_conn_prepare_events: [00:01:01.270,568] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20017c30 to poll list [00:01:01.270,599] <dbg> bt_conn: conn_prepare_events: wait on host fifo [00:01:01.270,599] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events [00:01:01.270,660] <dbg> bt_driver: rx_thread: rx.buf 0 [00:01:01.274,475] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.274,505] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.274,536] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 4 bytes [00:01:01.274,566] <dbg> bt_driver: process_rx: remaining 4 discard 0 have_hdr 1 rx.buf 0 len 0 [00:01:01.274,566] <dbg> bt_driver: get_rx: type 0x04, evt 0x0f [00:01:01.274,597] <dbg> bt_driver: read_payload: Allocated rx.buf 0x200311dc [00:01:01.274,627] <dbg> bt_driver: read_payload: got 4 bytes, remaining 0 [00:01:01.274,688] <dbg> bt_driver: read_payload: Payload (len 6): 0f0400013220 [00:01:01.274,688] <dbg> bt_driver: read_payload: Putting buf 0x200311dc to rx fifo [00:01:01.274,810] <dbg> bt_driver: rx_thread: Calling bt_recv(0x200311dc) [00:01:01.274,810] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x200311dc len 6 [00:01:01.274,841] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2032 [00:01:01.274,871] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2032 status 0x00 buf 0x200311dc [00:01:01.274,963] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200316d0 opcode 0x2032 len 0 [00:01:01.274,993] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:01:01.275,054] <dbg> bt_driver: rx_thread: rx.buf 0 [00:01:01.544,464] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.544,494] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.544,494] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 4 bytes [00:01:01.544,525] <dbg> bt_driver: process_rx: remaining 4 discard 0 have_hdr 1 rx.buf 0 len 0 [00:01:01.544,555] <dbg> bt_driver: get_rx: type 0x04, evt 0x05 [00:01:01.544,586] <dbg> bt_driver: read_payload: Allocated rx.buf 0x200311c0 [00:01:01.544,616] <dbg> bt_driver: read_payload: got 4 bytes, remaining 0 [00:01:01.544,647] <dbg> bt_driver: read_payload: Payload (len 6): 0504000f003e [00:01:01.544,677] <dbg> bt_driver: read_payload: Putting buf 0x200311c0 to rx fifo [00:01:01.544,769] <dbg> bt_driver: rx_thread: Calling bt_recv(0x200311c0) [00:01:01.544,799] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x200311c0 len 6 [00:01:01.544,830] <dbg> bt_hci_core: hci_disconn_complete_prio: status 0x00 handle 15 reason 0x3e [00:01:01.544,860] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:01:01.544,891] <dbg> bt_conn: bt_conn_set_state: connected -> disconnect-complete [00:01:01.544,891] <wrn> bt_conn: conn 0x20017c30 failed to establish. RF noise? [00:01:01.544,921] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:01:01.544,982] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:01:01.545,013] <dbg> bt_hci_core: rx_work_handler: buf 0x200311c0 type 1 len 6 [00:01:01.545,013] <dbg> bt_hci_core: hci_event: event 0x05 [00:01:01.545,043] <dbg> bt_hci_core: hci_disconn_complete: status 0x00 handle 15 reason 0x3e [00:01:01.545,074] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:01:01.545,104] <dbg> bt_conn: bt_conn_set_state: disconnect-complete -> disconnected [00:01:01.545,135] <dbg> bt_conn: wait_for_tx_work: conn 0x20017c30 [00:01:01.545,196] <dbg> bt_driver: rx_thread: rx.buf 0 [00:01:01.545,227] <dbg> bt_conn: tx_notify: conn 0x20017c30 [00:01:01.545,288] <dbg> bt_conn: wait_for_tx_work: done [00:01:01.545,349] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:01:01.545,410] <dbg> bt_hci_core: process_events: count 3 [00:01:01.545,410] <dbg> bt_hci_core: process_events: ev->state 0 [00:01:01.545,440] <dbg> bt_hci_core: process_events: ev->state 1 [00:01:01.545,471] <dbg> bt_hci_core: process_events: ev->state 0 [00:01:01.545,501] <dbg> bt_conn: bt_conn_prepare_events: [00:01:01.545,532] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events [00:01:01.545,593] <dbg> bt_conn: deferred_work: conn 0x20017c30 [00:01:01.545,593] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x20017c30 chan 0x20019d20 [00:01:01.545,623] <dbg> bt_l2cap: l2cap_disconnected: ch 0x20019d20 cid 0x0005 [00:01:01.545,654] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x20017c30 chan 0x20017efc [00:01:01.545,654] <dbg> bt_smp: bt_smp_disconnected: chan 0x20017efc cid 0x0006 [00:01:01.545,715] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x20017c30 chan 0x20028ea4 [00:01:01.545,745] <dbg> bt_att: bt_att_disconnected: chan 0x20028ea4 cid 0x0004 [00:01:01.545,745] <dbg> bt_att: att_chan_detach: chan 0x20028ea0 [00:01:01.545,776] <dbg> bt_gatt: bt_gatt_disconnected: conn 0x20017c30 [00:01:01.545,989] <dbg> bt_keys: bt_keys_find_addr: 46:F1:A5:36:6D:77 (random) [00:01:01.546,142] <dbg> bt_keys: bt_keys_find_addr: 46:F1:A5:36:6D:77 (random) [00:01:01.546,142] <dbg> bt_att: bt_att_released: chan 0x20028ea0 [00:01:01.546,173] <inf> ble: Disconnected (reason 0x3e) [00:01:01.546,234] <dbg> bt_conn: bt_conn_unref: handle 15 ref 1 -> 0 [00:01:01.546,295] <dbg> bt_conn: bt_conn_set_state: disconnected -> adv-connectable [00:01:01.546,325] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2 [00:01:01.546,356] <dbg> bt_adv: bt_le_adv_resume: Resuming connectable advertising [00:01:01.546,356] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x200a param_len 1 [00:01:01.546,386] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200316d0 [00:01:01.546,417] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200316d0 opcode 0x200a len 4 [00:01:01.546,508] <dbg> bt_hci_core: process_events: count 2 [00:01:01.546,508] <dbg> bt_hci_core: process_events: ev->state 4 [00:01:01.546,539] <dbg> bt_hci_core: send_cmd: calling net_buf_get [00:01:01.546,539] <dbg> bt_hci_core: send_cmd: calling sem_take_wait [00:01:01.546,569] <dbg> bt_hci_core: send_cmd: Sending command 0x200a (buf 0x200316d0) to driver [00:01:01.546,600] <dbg> bt_hci_core: bt_send: buf 0x200316d0 len 4 type 0 [00:01:01.546,600] <dbg> bt_driver: h4_send: buf 0x200316d0 type 0 len 4 [00:01:01.546,691] <dbg> bt_hci_core: process_events: ev->state 0 [00:01:01.546,722] <dbg> bt_conn: bt_conn_prepare_events: [00:01:01.546,722] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events [00:01:01.550,781] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.550,811] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.550,842] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 4 bytes [00:01:01.550,842] <dbg> bt_driver: process_rx: remaining 4 discard 0 have_hdr 1 rx.buf 0 len 0 [00:01:01.550,872] <dbg> bt_driver: get_rx: type 0x04, evt 0x0e [00:01:01.550,903] <dbg> bt_driver: read_payload: Allocated rx.buf 0x200311c0 [00:01:01.550,933] <dbg> bt_driver: read_payload: got 4 bytes, remaining 0 [00:01:01.550,964] <dbg> bt_driver: read_payload: Payload (len 6): 0e04010a2000 [00:01:01.550,994] <dbg> bt_driver: read_payload: Putting buf 0x200311c0 to rx fifo [00:01:01.551,086] <dbg> bt_driver: rx_thread: Calling bt_recv(0x200311c0) [00:01:01.551,147] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x200311c0 len 6 [00:01:01.551,177] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x200a [00:01:01.551,208] <dbg> bt_hci_core: hci_cmd_done: opcode 0x200a status 0x00 buf 0x200311c0 [00:01:01.551,269] <dbg> bt_driver: rx_thread: rx.buf 0 [00:01:01.551,300] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200316d0 opcode 0x200a len 1 [00:01:01.551,361] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1 Peripheral uart:~$ kernel threads Scheduler: 17939 since last call Threads: 0x200107b0 bt_rx_thread options: 0x0, priority: -8 timeout: 0 state: pending, entry: 0x353b1 stack size 2200, unused 1672, usage 528 / 2200 (24 %) 0x2000fe88 BT RX WQ options: 0x0, priority: -8 timeout: 0 state: pending, entry: 0x394e1 stack size 2200, unused 1656, usage 544 / 2200 (24 %) 0x2000fdd0 BT TX options: 0x0, priority: -9 timeout: 0 state: pending, entry: 0x217d1 stack size 512, unused 112, usage 400 / 512 (78 %) 0x200106f8 conn_mgr_monitor options: 0x0, priority: -1 timeout: 0 state: pending, entry: 0x347dd stack size 512, unused 376, usage 136 / 512 (26 %) 0x200105a8 rx_q[0] options: 0x0, priority: -1 timeout: 0 state: pending, entry: 0x41e85 stack size 1504, unused 1368, usage 136 / 1504 (9 %) 0x200104b8 net_mgmt options: 0x0, priority: -1 timeout: 0 state: pending, entry: 0x394e1 stack size 2048, unused 1872, usage 176 / 2048 (8 %) *0x2000f968 shell_uart options: 0x0, priority: 14 timeout: 0 state: queued, entry: 0x1d025 stack size 2048, unused 1048, usage 1000 / 2048 (48 %) 0x2000fcf8 BT LW WQ options: 0x0, priority: 10 timeout: 0 state: pending, entry: 0x394e1 stack size 1304, unused 408, usage 896 / 1304 (68 %) 0x20010b90 sysworkq options: 0x1, priority: -1 timeout: 0 state: pending, entry: 0x394e1 stack size 2048, unused 1656, usage 392 / 2048 (19 %) 0x2000d870 logging options: 0x0, priority: 14 timeout: 5449 state: pending, entry: 0x1a7cd stack size 768, unused 424, usage 344 / 768 (44 %) 0x20010a20 idle options: 0x1, priority: 15 timeout: 0 state: , entry: 0x44e65 stack size 320, unused 256, usage 64 / 320 (20 %) 0x20010ad8 main options: 0x1, priority: 0 timeout: 32772 state: suspended, entry: 0x38e15 stack size 1024, unused 96, usage 928 / 1024 (90 %) uart:~$ [00:00:56.527,008] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.527,038] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.527,038] <dbg> bt_driver: process_rx: remaining 1 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.527,069] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 31 bytes [00:00:56.527,099] <dbg> bt_driver: process_rx: remaining 30 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:56.527,099] <dbg> bt_driver: get_rx: type 0x04, evt 0x3e [00:00:56.527,130] <dbg> bt_driver: read_payload: Allocated rx.buf 0x20016e58 [00:00:56.527,160] <dbg> bt_driver: read_payload: got 30 bytes, remaining 0 [00:00:56.527,191] <dbg> bt_driver: read_payload: Payload (len 33): 3e1f0a000f000101788ba945266700000000000000000000000027000000f40101 [00:00:56.527,221] <dbg> bt_driver: read_payload: Putting buf 0x20016e58 to rx fifo [00:00:56.527,282] <dbg> bt_driver: rx_thread: Calling bt_recv(0x20016e58) [00:00:56.527,313] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20016e58 len 33 [00:00:56.527,343] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:00:56.527,374] <dbg> bt_hci_core: rx_work_handler: buf 0x20016e58 type 1 len 33 [00:00:56.527,374] <dbg> bt_hci_core: hci_event: event 0x3e [00:00:56.527,404] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x0a [00:00:56.527,557] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: status 0x00 handle 15 role 1 peer 67:26:45:A9:8B:78 (random) peer RPA 00:00:00:00:00:00 [00:00:56.527,648] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: local RPA 00:00:00:00:00:00 [00:00:56.527,740] <dbg> bt_keys: bt_keys_find_irk: 67:26:45:A9:8B:78 (random) [00:00:56.527,832] <dbg> bt_keys: bt_keys_find_irk: No IRK for 67:26:45:A9:8B:78 (random) [00:00:56.527,832] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2 [00:00:56.527,862] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1 [00:00:56.527,862] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2 [00:00:56.527,893] <dbg> bt_adv: bt_le_adv_resume: Host cannot resume connectable advertising (-12) [00:00:56.527,954] <dbg> bt_conn: bt_conn_set_state: adv-connectable -> connected [00:00:56.527,984] <dbg> bt_l2cap: l2cap_accept: conn 0x20010098 handle 15 [00:00:56.527,984] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x20010098 chan 0x20011218 [00:00:56.528,015] <dbg> bt_l2cap: l2cap_connected: ch 0x20011218 cid 0x0005 [00:00:56.528,015] <dbg> bt_smp: bt_smp_accept: conn 0x20010098 handle 15 [00:00:56.528,045] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x20010098 chan 0x2001035c [00:00:56.528,045] <dbg> bt_smp: bt_smp_connected: chan 0x2001035c cid 0x0006 [00:00:56.528,076] <dbg> bt_att: bt_att_accept: conn 0x20010098 handle 15 [00:00:56.528,106] <dbg> bt_att: att_chan_attach: att 0x200176a4 chan 0x20013848 flags 0 [00:00:56.528,137] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x20010098 chan 0x2001384c [00:00:56.528,137] <dbg> bt_att: bt_att_connected: chan 0x2001384c cid 0x0004 Updated MTU: TX: 23 RX: 23 bytes [00:00:56.528,198] <dbg> bt_gatt: bt_gatt_connected: conn 0x20010098 [00:00:56.528,289] <dbg> bt_keys: bt_keys_find_addr: 67:26:45:A9:8B:78 (random) [00:00:56.528,411] <dbg> bt_att: bt_att_status: chan 0x2001384c status 0x2001385c Connected [00:00:56.528,442] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2016 param_len 2 [00:00:56.528,472] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20017368 [00:00:56.528,472] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x20017368 opcode 0x2016 len 5 [00:00:56.528,533] <dbg> bt_hci_core: process_events: count 2 [00:00:56.528,533] <dbg> bt_hci_core: process_events: ev->state 4 [00:00:56.528,533] <dbg> bt_hci_core: send_cmd: calling net_buf_get [00:00:56.528,564] <dbg> bt_hci_core: send_cmd: calling sem_take_wait [00:00:56.528,594] <dbg> bt_hci_core: send_cmd: Sending command 0x2016 (buf 0x20017368) to driver [00:00:56.528,594] <dbg> bt_hci_core: bt_send: buf 0x20017368 len 5 type 0 [00:00:56.528,594] <dbg> bt_driver: h4_send: buf 0x20017368 type 0 len 5 [00:00:56.528,656] <dbg> bt_hci_core: process_events: ev->state 1 [00:00:56.528,686] <dbg> bt_conn: bt_conn_prepare_events: [00:00:56.528,686] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20010098 to poll list [00:00:56.528,717] <dbg> bt_conn: conn_prepare_events: wait on host fifo [00:00:56.528,717] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events [00:00:56.528,747] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:56.532,684] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.532,684] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.532,714] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 4 bytes [00:00:56.532,745] <dbg> bt_driver: process_rx: remaining 4 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:56.532,745] <dbg> bt_driver: get_rx: type 0x04, evt 0x0f [00:00:56.532,775] <dbg> bt_driver: read_payload: Allocated rx.buf 0x20016e74 [00:00:56.532,806] <dbg> bt_driver: read_payload: got 4 bytes, remaining 0 [00:00:56.532,836] <dbg> bt_driver: read_payload: Payload (len 6): 0f0400011620 [00:00:56.532,836] <dbg> bt_driver: read_payload: Putting buf 0x20016e74 to rx fifo [00:00:56.532,928] <dbg> bt_driver: rx_thread: Calling bt_recv(0x20016e74) [00:00:56.532,958] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20016e74 len 6 [00:00:56.532,958] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2016 [00:00:56.532,989] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2016 status 0x00 buf 0x20016e74 [00:00:56.533,050] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20017368 opcode 0x2016 len 0 [00:00:56.533,050] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2032 param_len 7 [00:00:56.533,081] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20017368 [00:00:56.533,111] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x20017368 opcode 0x2032 len 10 [00:00:56.533,142] <dbg> bt_hci_core: process_events: count 3 [00:00:56.533,172] <dbg> bt_hci_core: process_events: ev->state 4 [00:00:56.533,203] <dbg> bt_hci_core: send_cmd: calling net_buf_get [00:00:56.533,203] <dbg> bt_hci_core: send_cmd: calling sem_take_wait [00:00:56.533,233] <dbg> bt_hci_core: send_cmd: Sending command 0x2032 (buf 0x20017368) to driver [00:00:56.533,233] <dbg> bt_hci_core: bt_send: buf 0x20017368 len 10 type 0 [00:00:56.533,264] <dbg> bt_driver: h4_send: buf 0x20017368 type 0 len 10 [00:00:56.533,325] <dbg> bt_hci_core: process_events: ev->state 0 [00:00:56.533,325] <dbg> bt_hci_core: process_events: ev->state 0 [00:00:56.533,355] <dbg> bt_conn: bt_conn_prepare_events: [00:00:56.533,355] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20010098 to poll list [00:00:56.533,386] <dbg> bt_conn: conn_prepare_events: wait on host fifo [00:00:56.533,386] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events [00:00:56.533,416] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:56.537,170] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.537,200] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.537,200] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 4 bytes [00:00:56.537,231] <dbg> bt_driver: process_rx: remaining 4 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:56.537,231] <dbg> bt_driver: get_rx: type 0x04, evt 0x0f [00:00:56.537,261] <dbg> bt_driver: read_payload: Allocated rx.buf 0x20016e74 [00:00:56.537,292] <dbg> bt_driver: read_payload: got 4 bytes, remaining 0 [00:00:56.537,322] <dbg> bt_driver: read_payload: Payload (len 6): 0f0400013220 [00:00:56.537,322] <dbg> bt_driver: read_payload: Putting buf 0x20016e74 to rx fifo [00:00:56.537,414] <dbg> bt_driver: rx_thread: Calling bt_recv(0x20016e74) [00:00:56.537,445] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20016e74 len 6 [00:00:56.537,475] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2032 [00:00:56.537,506] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2032 status 0x00 buf 0x20016e74 [00:00:56.537,536] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20017368 opcode 0x2032 len 0 [00:00:56.537,567] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:56.537,597] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:56.771,301] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.771,331] <dbg> bt_driver: process_rx: remaining 4 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.771,362] <dbg> bt_driver: get_acl_hdr: Got ACL header. Payload 11 bytes [00:00:56.771,362] <dbg> bt_driver: process_rx: remaining 11 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:56.771,392] <dbg> bt_driver: get_rx: type 0x02, evt 0x0f [00:00:56.771,423] <dbg> bt_driver: read_payload: Allocated rx.buf 0x2001712c [00:00:56.771,423] <dbg> bt_driver: read_payload: got 11 bytes, remaining 0 [00:00:56.771,484] <dbg> bt_driver: read_payload: Payload (len 15): 0f200b0007000400080100ffff012a [00:00:56.771,484] <dbg> bt_driver: read_payload: Putting buf 0x2001712c to rx fifo [00:00:56.771,545] <dbg> bt_driver: rx_thread: Calling bt_recv(0x2001712c) [00:00:56.771,606] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2001712c len 15 [00:00:56.771,636] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:00:56.771,636] <dbg> bt_hci_core: rx_work_handler: buf 0x2001712c type 3 len 15 [00:00:56.771,667] <dbg> bt_hci_core: hci_acl: buf 0x2001712c [00:00:56.771,667] <dbg> bt_hci_core: hci_acl: handle 15 len 11 flags 2 [00:00:56.771,697] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:00:56.771,697] <dbg> bt_conn: wait_for_tx_work: conn 0x20010098 [00:00:56.771,759] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:56.771,789] <dbg> bt_conn: tx_notify: conn 0x20010098 [00:00:56.771,820] <dbg> bt_conn: wait_for_tx_work: done [00:00:56.771,820] <dbg> bt_conn: bt_conn_recv: handle 15 len 11 flags 02 [00:00:56.771,850] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7 [00:00:56.771,850] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet [00:00:56.771,881] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7 [00:00:56.771,881] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x2001384c len 7 [00:00:56.771,911] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20013848 code 0x08 len 6 [00:00:56.771,972] <dbg> bt_att: att_read_type_req: start_handle 0x0001 end_handle 0xffff type 2a01 [00:00:56.772,033] <dbg> bt_att: read_type_cb: handle 0x000d [00:00:56.772,064] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 2 [00:00:56.772,155] <dbg> bt_att: chan_send: code 0x09 [00:00:56.772,186] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20010098 cid 4 len 6 [00:00:56.772,186] <dbg> bt_conn: bt_conn_send_cb: conn handle 15 buf len 10 cb 0 user_data 0 [00:00:56.772,247] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3 [00:00:56.772,247] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2 [00:00:56.772,277] <dbg> bt_hci_core: bt_hci_host_num_completed_packets: Reporting completed packet for handle 15 [00:00:56.772,308] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5 [00:00:56.772,308] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20017368 [00:00:56.772,338] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8 [00:00:56.772,338] <dbg> bt_hci_core: bt_send: buf 0x20017368 len 8 type 0 [00:00:56.772,369] <dbg> bt_driver: h4_send: buf 0x20017368 type 0 len 8 [00:00:56.772,430] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:56.772,460] <dbg> bt_hci_core: process_events: count 3 [00:00:56.772,460] <dbg> bt_hci_core: process_events: ev->state 0 [00:00:56.772,491] <dbg> bt_hci_core: process_events: ev->state 0 [00:00:56.772,491] <dbg> bt_hci_core: process_events: ev->state 4 [00:00:56.772,491] <dbg> bt_conn: bt_conn_process_tx: conn 0x20010098 [00:00:56.772,521] <dbg> bt_conn: send_buf: conn 0x20010098 buf 0x20017644 len 10 [00:00:56.772,521] <dbg> bt_conn: send_buf: send single [00:00:56.772,552] <dbg> bt_conn: do_send_frag: conn 0x20010098 buf 0x20017644 len 10 flags 0x02 [00:00:56.772,583] <dbg> bt_hci_core: bt_send: buf 0x20017644 len 14 type 2 [00:00:56.772,583] <dbg> bt_driver: h4_send: buf 0x20017644 type 2 len 14 [00:00:56.772,613] <dbg> bt_conn: bt_conn_prepare_events: [00:00:56.772,644] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20010098 to poll list [00:00:56.772,644] <dbg> bt_conn: conn_prepare_events: wait on host fifo [00:00:56.772,644] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events [00:00:56.773,986] <dbg> bt_att: att_tx_destroy: 0x20017644 [00:00:56.774,017] <dbg> bt_att: att_on_sent_cb: opcode 0x9 [00:00:56.774,017] <dbg> bt_att: att_on_sent_cb: UATT bearer, calling att_sent [00:00:56.774,017] <dbg> bt_att: att_sent: conn 0x20010098 chan 0x2001384c [00:00:56.774,047] <dbg> bt_att: bt_att_sent: chan 0x20013848 [00:00:56.917,480] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.917,510] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.917,510] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 5 bytes [00:00:56.917,541] <dbg> bt_driver: process_rx: remaining 5 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:56.917,541] <dbg> bt_driver: get_rx: type 0x04, evt 0x13 [00:00:56.917,572] <dbg> bt_driver: read_payload: Allocated rx.buf 0x200172bc [00:00:56.917,602] <dbg> bt_driver: read_payload: got 5 bytes, remaining 0 [00:00:56.917,633] <dbg> bt_driver: read_payload: Payload (len 7): 1305010f000100 [00:00:56.917,633] <dbg> bt_driver: read_payload: Putting buf 0x200172bc to rx fifo [00:00:56.917,785] <dbg> bt_driver: rx_thread: Calling bt_recv(0x200172bc) [00:00:56.917,816] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x200172bc len 7 [00:00:56.917,816] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1 [00:00:56.917,846] <dbg> bt_hci_core: hci_num_completed_packets: handle 15 count 1 [00:00:56.917,846] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:00:56.917,877] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:56.917,907] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:56.920,196] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.920,196] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.920,227] <dbg> bt_driver: process_rx: remaining 1 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.920,257] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 12 bytes [00:00:56.920,257] <dbg> bt_driver: process_rx: remaining 11 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:56.920,288] <dbg> bt_driver: get_rx: type 0x04, evt 0x3e [00:00:56.920,318] <dbg> bt_driver: read_payload: Allocated rx.buf 0x20016e58 [00:00:56.920,318] <dbg> bt_driver: read_payload: got 11 bytes, remaining 0 [00:00:56.920,379] <dbg> bt_driver: read_payload: Payload (len 14): 3e0c04000f002d7f01f7ffd90000 [00:00:56.920,379] <dbg> bt_driver: read_payload: Putting buf 0x20016e58 to rx fifo [00:00:56.920,440] <dbg> bt_driver: rx_thread: Calling bt_recv(0x20016e58) [00:00:56.920,471] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20016e58 len 14 [00:00:56.920,501] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:00:56.920,532] <dbg> bt_hci_core: rx_work_handler: buf 0x20016e58 type 1 len 14 [00:00:56.920,532] <dbg> bt_hci_core: hci_event: event 0x3e [00:00:56.920,562] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x04 [00:00:56.920,593] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:00:56.920,623] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:56.920,654] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:56.966,400] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.966,430] <dbg> bt_driver: process_rx: remaining 4 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.966,461] <dbg> bt_driver: get_acl_hdr: Got ACL header. Payload 11 bytes [00:00:56.966,461] <dbg> bt_driver: process_rx: remaining 11 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:56.966,491] <dbg> bt_driver: get_rx: type 0x02, evt 0x0f [00:00:56.966,522] <dbg> bt_driver: read_payload: Allocated rx.buf 0x2001712c [00:00:56.966,522] <dbg> bt_driver: read_payload: got 11 bytes, remaining 0 [00:00:56.966,583] <dbg> bt_driver: read_payload: Payload (len 15): 0f200b0007000400080100ffff2a2b [00:00:56.966,583] <dbg> bt_driver: read_payload: Putting buf 0x2001712c to rx fifo [00:00:56.966,674] <dbg> bt_driver: rx_thread: Calling bt_recv(0x2001712c) [00:00:56.966,705] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2001712c len 15 [00:00:56.966,735] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:00:56.966,735] <dbg> bt_hci_core: rx_work_handler: buf 0x2001712c type 3 len 15 [00:00:56.966,766] <dbg> bt_hci_core: hci_acl: buf 0x2001712c [00:00:56.966,766] <dbg> bt_hci_core: hci_acl: handle 15 len 11 flags 2 [00:00:56.966,796] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:00:56.966,796] <dbg> bt_conn: wait_for_tx_work: conn 0x20010098 [00:00:56.966,857] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:56.966,888] <dbg> bt_conn: tx_notify: conn 0x20010098 [00:00:56.966,918] <dbg> bt_conn: wait_for_tx_work: done [00:00:56.966,949] <dbg> bt_conn: bt_conn_recv: handle 15 len 11 flags 02 [00:00:56.966,979] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7 [00:00:56.966,979] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet [00:00:56.967,010] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7 [00:00:56.967,010] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x2001384c len 7 [00:00:56.967,041] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20013848 code 0x08 len 6 [00:00:56.967,102] <dbg> bt_att: att_read_type_req: start_handle 0x0001 end_handle 0xffff type 2b2a [00:00:56.967,163] <dbg> bt_att: read_type_cb: handle 0x0008 [00:00:56.967,193] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 16 [00:00:56.967,193] <dbg> bt_att: chan_send: code 0x09 [00:00:56.967,224] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20010098 cid 4 len 20 [00:00:56.967,224] <dbg> bt_conn: bt_conn_send_cb: conn handle 15 buf len 24 cb 0 user_data 0 [00:00:56.967,285] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3 [00:00:56.967,285] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2 [00:00:56.967,315] <dbg> bt_hci_core: bt_hci_host_num_completed_packets: Reporting completed packet for handle 15 [00:00:56.967,315] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5 [00:00:56.967,346] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20017368 [00:00:56.967,346] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8 [00:00:56.967,376] <dbg> bt_hci_core: bt_send: buf 0x20017368 len 8 type 0 [00:00:56.967,376] <dbg> bt_driver: h4_send: buf 0x20017368 type 0 len 8 [00:00:56.967,437] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:56.967,468] <dbg> bt_hci_core: process_events: count 3 [00:00:56.967,498] <dbg> bt_hci_core: process_events: ev->state 0 [00:00:56.967,498] <dbg> bt_hci_core: process_events: ev->state 0 [00:00:56.967,529] <dbg> bt_hci_core: process_events: ev->state 4 [00:00:56.967,529] <dbg> bt_conn: bt_conn_process_tx: conn 0x20010098 [00:00:56.967,559] <dbg> bt_conn: send_buf: conn 0x20010098 buf 0x20017644 len 24 [00:00:56.967,559] <dbg> bt_conn: send_buf: send single [00:00:56.967,590] <dbg> bt_conn: do_send_frag: conn 0x20010098 buf 0x20017644 len 24 flags 0x02 [00:00:56.967,590] <dbg> bt_hci_core: bt_send: buf 0x20017644 len 28 type 2 [00:00:56.967,620] <dbg> bt_driver: h4_send: buf 0x20017644 type 2 len 28 [00:00:56.967,651] <dbg> bt_conn: bt_conn_prepare_events: [00:00:56.967,681] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20010098 to poll list [00:00:56.967,681] <dbg> bt_conn: conn_prepare_events: wait on host fifo [00:00:56.967,681] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events [00:00:56.969,024] <dbg> bt_att: att_tx_destroy: 0x20017644 [00:00:56.969,024] <dbg> bt_att: att_on_sent_cb: opcode 0x9 [00:00:56.969,055] <dbg> bt_att: att_on_sent_cb: UATT bearer, calling att_sent [00:00:56.969,055] <dbg> bt_att: att_sent: conn 0x20010098 chan 0x2001384c [00:00:56.969,085] <dbg> bt_att: bt_att_sent: chan 0x20013848 [00:00:57.063,659] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:57.063,690] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:57.063,690] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 5 bytes [00:00:57.063,720] <dbg> bt_driver: process_rx: remaining 5 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:57.063,720] <dbg> bt_driver: get_rx: type 0x04, evt 0x13 [00:00:57.063,751] <dbg> bt_driver: read_payload: Allocated rx.buf 0x200172bc [00:00:57.063,781] <dbg> bt_driver: read_payload: got 5 bytes, remaining 0 [00:00:57.063,812] <dbg> bt_driver: read_payload: Payload (len 7): 1305010f000100 [00:00:57.063,842] <dbg> bt_driver: read_payload: Putting buf 0x200172bc to rx fifo [00:00:57.063,903] <dbg> bt_driver: rx_thread: Calling bt_recv(0x200172bc) [00:00:57.063,934] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x200172bc len 7 [00:00:57.063,964] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1 [00:00:57.063,964] <dbg> bt_hci_core: hci_num_completed_packets: handle 15 count 1 [00:00:57.063,995] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:00:57.063,995] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:57.064,025] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:57.355,895] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:57.355,926] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:57.355,957] <dbg> bt_driver: process_rx: remaining 1 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:57.355,957] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 6 bytes [00:00:57.355,987] <dbg> bt_driver: process_rx: remaining 5 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:57.355,987] <dbg> bt_driver: get_rx: type 0x04, evt 0x3e [00:00:57.356,018] <dbg> bt_driver: read_payload: Allocated rx.buf 0x20016e58 [00:00:57.356,048] <dbg> bt_driver: read_payload: got 5 bytes, remaining 0 [00:00:57.356,079] <dbg> bt_driver: read_payload: Payload (len 8): 3e060c000f000202 [00:00:57.356,109] <dbg> bt_driver: read_payload: Putting buf 0x20016e58 to rx fifo [00:00:57.356,170] <dbg> bt_driver: rx_thread: Calling bt_recv(0x20016e58) [00:00:57.356,170] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20016e58 len 8 [00:00:57.356,231] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:00:57.356,231] <dbg> bt_hci_core: rx_work_handler: buf 0x20016e58 type 1 len 8 [00:00:57.356,262] <dbg> bt_hci_core: hci_event: event 0x3e [00:00:57.356,262] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x0c [00:00:57.356,292] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:00:57.356,292] <dbg> bt_hci_core: le_phy_update_complete: PHY updated: status: 0x00, tx: 2, rx: 2 [00:00:57.356,323] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:57.356,353] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:58.623,901] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:58.623,901] <dbg> bt_driver: process_rx: remaining 4 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:58.623,931] <dbg> bt_driver: get_acl_hdr: Got ACL header. Payload 7 bytes [00:00:58.623,931] <dbg> bt_driver: process_rx: remaining 7 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:58.623,962] <dbg> bt_driver: get_rx: type 0x02, evt 0x0f [00:00:58.623,992] <dbg> bt_driver: read_payload: Allocated rx.buf 0x2001712c [00:00:58.623,992] <dbg> bt_driver: read_payload: got 7 bytes, remaining 0 [00:00:58.624,053] <dbg> bt_driver: read_payload: Payload (len 11): 0f200700030004000a1f00 [00:00:58.624,053] <dbg> bt_driver: read_payload: Putting buf 0x2001712c to rx fifo [00:00:58.624,114] <dbg> bt_driver: rx_thread: Calling bt_recv(0x2001712c) [00:00:58.624,145] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2001712c len 11 [00:00:58.624,176] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:00:58.624,206] <dbg> bt_hci_core: rx_work_handler: buf 0x2001712c type 3 len 11 [00:00:58.624,206] <dbg> bt_hci_core: hci_acl: buf 0x2001712c [00:00:58.624,237] <dbg> bt_hci_core: hci_acl: handle 15 len 7 flags 2 [00:00:58.624,237] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:00:58.624,267] <dbg> bt_conn: wait_for_tx_work: conn 0x20010098 [00:00:58.624,298] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:58.624,328] <dbg> bt_conn: tx_notify: conn 0x20010098 [00:00:58.624,359] <dbg> bt_conn: wait_for_tx_work: done [00:00:58.624,389] <dbg> bt_conn: bt_conn_recv: handle 15 len 7 flags 02 [00:00:58.624,389] <dbg> bt_conn: bt_acl_recv: First, len 7 final 3 [00:00:58.624,420] <dbg> bt_conn: bt_acl_recv: Successfully parsed 7 byte L2CAP packet [00:00:58.624,450] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 3 [00:00:58.624,450] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x2001384c len 3 [00:00:58.624,481] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20013848 code 0x0a len 2 [00:00:58.624,481] <dbg> bt_att: att_read_req: handle 0x001f [00:00:58.624,542] <dbg> bt_att: read_cb: handle 0x001f [00:00:58.624,572] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 7 [00:00:58.624,572] <dbg> bt_att: chan_send: code 0x0b [00:00:58.624,603] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20010098 cid 4 len 8 [00:00:58.624,603] <dbg> bt_conn: bt_conn_send_cb: conn handle 15 buf len 12 cb 0 user_data 0 [00:00:58.624,664] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3 [00:00:58.624,664] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2 [00:00:58.624,694] <dbg> bt_hci_core: bt_hci_host_num_completed_packets: Reporting completed packet for handle 15 [00:00:58.624,694] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5 [00:00:58.624,725] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20017368 [00:00:58.624,725] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8 [00:00:58.624,755] <dbg> bt_hci_core: bt_send: buf 0x20017368 len 8 type 0 [00:00:58.624,755] <dbg> bt_driver: h4_send: buf 0x20017368 type 0 len 8 [00:00:58.624,816] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:58.624,847] <dbg> bt_hci_core: process_events: count 3 [00:00:58.624,877] <dbg> bt_hci_core: process_events: ev->state 0 [00:00:58.624,877] <dbg> bt_hci_core: process_events: ev->state 0 [00:00:58.624,877] <dbg> bt_hci_core: process_events: ev->state 4 [00:00:58.624,908] <dbg> bt_conn: bt_conn_process_tx: conn 0x20010098 [00:00:58.624,908] <dbg> bt_conn: send_buf: conn 0x20010098 buf 0x20017644 len 12 [00:00:58.624,938] <dbg> bt_conn: send_buf: send single [00:00:58.624,969] <dbg> bt_conn: do_send_frag: conn 0x20010098 buf 0x20017644 len 12 flags 0x02 [00:00:58.624,969] <dbg> bt_hci_core: bt_send: buf 0x20017644 len 16 type 2 [00:00:58.625,000] <dbg> bt_driver: h4_send: buf 0x20017644 type 2 len 16 [00:00:58.625,000] <dbg> bt_conn: bt_conn_prepare_events: [00:00:58.625,030] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20010098 to poll list [00:00:58.625,030] <dbg> bt_conn: conn_prepare_events: wait on host fifo [00:00:58.625,061] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events [00:00:58.626,373] <dbg> bt_att: att_tx_destroy: 0x20017644 [00:00:58.626,403] <dbg> bt_att: att_on_sent_cb: opcode 0xb [00:00:58.626,403] <dbg> bt_att: att_on_sent_cb: UATT bearer, calling att_sent [00:00:58.626,434] <dbg> bt_att: att_sent: conn 0x20010098 chan 0x2001384c [00:00:58.626,434] <dbg> bt_att: bt_att_sent: chan 0x20013848 [00:00:58.721,191] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:58.721,191] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:58.721,221] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 5 bytes [00:00:58.721,221] <dbg> bt_driver: process_rx: remaining 5 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:58.721,252] <dbg> bt_driver: get_rx: type 0x04, evt 0x13 [00:00:58.721,282] <dbg> bt_driver: read_payload: Allocated rx.buf 0x200172bc [00:00:58.721,282] <dbg> bt_driver: read_payload: got 5 bytes, remaining 0 [00:00:58.721,343] <dbg> bt_driver: read_payload: Payload (len 7): 1305010f000100 [00:00:58.721,343] <dbg> bt_driver: read_payload: Putting buf 0x200172bc to rx fifo [00:00:58.721,405] <dbg> bt_driver: rx_thread: Calling bt_recv(0x200172bc) [00:00:58.721,466] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x200172bc len 7 [00:00:58.721,466] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1 [00:00:58.721,496] <dbg> bt_hci_core: hci_num_completed_packets: handle 15 count 1 [00:00:58.721,496] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:00:58.721,527] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:58.721,557] <dbg> bt_driver: rx_thread: rx.buf 0 [00:01:01.528,015] <dbg> bt_conn: deferred_work: conn 0x20010098 [00:01:01.528,045] <dbg> bt_conn: send_conn_le_param_update: conn 0x20010098 features 0x2d params (24-40 0 42) [00:01:01.528,076] <dbg> bt_conn: bt_conn_create_pdu_timeout: Timeout discarded. No blocking in syswq. [00:01:01.528,106] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20010098 cid 5 len 12 [00:01:01.528,106] <dbg> bt_conn: bt_conn_send_cb: conn handle 15 buf len 16 cb 0 user_data 0 [00:01:01.528,167] <dbg> bt_hci_core: process_events: count 3 [00:01:01.528,167] <dbg> bt_hci_core: process_events: ev->state 0 [00:01:01.528,198] <dbg> bt_hci_core: process_events: ev->state 0 [00:01:01.528,198] <dbg> bt_hci_core: process_events: ev->state 4 [00:01:01.528,198] <dbg> bt_conn: bt_conn_process_tx: conn 0x20010098 [00:01:01.528,228] <dbg> bt_conn: send_buf: conn 0x20010098 buf 0x20017500 len 16 [00:01:01.528,259] <dbg> bt_conn: send_buf: send single [00:01:01.528,259] <dbg> bt_conn: do_send_frag: conn 0x20010098 buf 0x20017500 len 16 flags 0x02 [00:01:01.528,289] <dbg> bt_hci_core: bt_send: buf 0x20017500 len 20 type 2 [00:01:01.528,289] <dbg> bt_driver: h4_send: buf 0x20017500 type 2 len 20 [00:01:01.528,350] <dbg> bt_conn: bt_conn_prepare_events: [00:01:01.528,381] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20010098 to poll list [00:01:01.528,381] <dbg> bt_conn: conn_prepare_events: wait on host fifo [00:01:01.528,411] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events [00:01:01.597,595] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.597,625] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.597,625] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 5 bytes [00:01:01.597,656] <dbg> bt_driver: process_rx: remaining 5 discard 0 have_hdr 1 rx.buf 0 len 0 [00:01:01.597,656] <dbg> bt_driver: get_rx: type 0x04, evt 0x13 [00:01:01.597,686] <dbg> bt_driver: read_payload: Allocated rx.buf 0x200172bc [00:01:01.597,717] <dbg> bt_driver: read_payload: got 5 bytes, remaining 0 [00:01:01.597,747] <dbg> bt_driver: read_payload: Payload (len 7): 1305010f000100 [00:01:01.597,747] <dbg> bt_driver: read_payload: Putting buf 0x200172bc to rx fifo [00:01:01.597,839] <dbg> bt_driver: rx_thread: Calling bt_recv(0x200172bc) [00:01:01.597,869] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x200172bc len 7 [00:01:01.597,900] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1 [00:01:01.597,900] <dbg> bt_hci_core: hci_num_completed_packets: handle 15 count 1 [00:01:01.597,930] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:01:01.597,961] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:01:01.597,991] <dbg> bt_driver: rx_thread: rx.buf 0 [00:01:01.646,606] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.646,636] <dbg> bt_driver: process_rx: remaining 4 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.646,636] <dbg> bt_driver: get_acl_hdr: Got ACL header. Payload 10 bytes [00:01:01.646,667] <dbg> bt_driver: process_rx: remaining 10 discard 0 have_hdr 1 rx.buf 0 len 0 [00:01:01.646,697] <dbg> bt_driver: get_rx: type 0x02, evt 0x0f [00:01:01.646,697] <dbg> bt_driver: read_payload: Allocated rx.buf 0x2001712c [00:01:01.646,728] <dbg> bt_driver: read_payload: got 10 bytes, remaining 0 [00:01:01.646,759] <dbg> bt_driver: read_payload: Payload (len 14): 0f200a0006000500130102000000 [00:01:01.646,789] <dbg> bt_driver: read_payload: Putting buf 0x2001712c to rx fifo [00:01:01.646,881] <dbg> bt_driver: rx_thread: Calling bt_recv(0x2001712c) [00:01:01.646,881] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2001712c len 14 [00:01:01.646,942] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:01:01.646,942] <dbg> bt_hci_core: rx_work_handler: buf 0x2001712c type 3 len 14 [00:01:01.646,942] <dbg> bt_hci_core: hci_acl: buf 0x2001712c [00:01:01.646,972] <dbg> bt_hci_core: hci_acl: handle 15 len 10 flags 2 [00:01:01.647,003] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:01:01.647,003] <dbg> bt_conn: wait_for_tx_work: conn 0x20010098 [00:01:01.647,064] <dbg> bt_driver: rx_thread: rx.buf 0 [00:01:01.647,094] <dbg> bt_conn: tx_notify: conn 0x20010098 [00:01:01.647,125] <dbg> bt_conn: wait_for_tx_work: done [00:01:01.647,155] <dbg> bt_conn: bt_conn_recv: handle 15 len 10 flags 02 [00:01:01.647,155] <dbg> bt_conn: bt_acl_recv: First, len 10 final 6 [00:01:01.647,186] <dbg> bt_conn: bt_acl_recv: Successfully parsed 10 byte L2CAP packet [00:01:01.647,186] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 5 len 6 [00:01:01.647,216] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20011218 len 6 [00:01:01.647,216] <dbg> bt_l2cap: l2cap_recv: Signaling code 0x13 ident 1 len 2 [00:01:01.647,247] <dbg> bt_l2cap: le_conn_param_rsp: LE conn param rsp result 0 [00:01:01.647,277] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3 [00:01:01.647,277] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2 [00:01:01.647,308] <dbg> bt_hci_core: bt_hci_host_num_completed_packets: Reporting completed packet for handle 15 [00:01:01.647,308] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5 [00:01:01.647,338] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20017368 [00:01:01.647,338] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8 [00:01:01.647,369] <dbg> bt_hci_core: bt_send: buf 0x20017368 len 8 type 0 [00:01:01.647,369] <dbg> bt_driver: h4_send: buf 0x20017368 type 0 len 8 [00:01:01.647,430] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:01:01.890,411] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.890,441] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.890,472] <dbg> bt_driver: process_rx: remaining 1 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.890,502] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 10 bytes [00:01:01.890,502] <dbg> bt_driver: process_rx: remaining 9 discard 0 have_hdr 1 rx.buf 0 len 0 [00:01:01.890,533] <dbg> bt_driver: get_rx: type 0x04, evt 0x3e [00:01:01.890,533] <dbg> bt_driver: read_payload: Allocated rx.buf 0x20016e58 [00:01:01.890,563] <dbg> bt_driver: read_payload: got 9 bytes, remaining 0 [00:01:01.890,625] <dbg> bt_driver: read_payload: Payload (len 12): 3e0a03000f00270000002a00 [00:01:01.890,625] <dbg> bt_driver: read_payload: Putting buf 0x20016e58 to rx fifo [00:01:01.890,686] <dbg> bt_driver: rx_thread: Calling bt_recv(0x20016e58) [00:01:01.890,716] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20016e58 len 12 [00:01:01.890,747] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:01:01.890,747] <dbg> bt_hci_core: rx_work_handler: buf 0x20016e58 type 1 len 12 [00:01:01.890,777] <dbg> bt_hci_core: hci_event: event 0x3e [00:01:01.890,777] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x03 [00:01:01.890,808] <dbg> bt_hci_core: le_conn_update_complete: status 0x00, handle 15 [00:01:01.890,838] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:01:01.890,838] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:01:01.890,869] <dbg> bt_driver: rx_thread: rx.buf 0
Fullscreen
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
Peripheral
uart:~$ kernel threads
Scheduler: 17939 since last call
Threads:
0x200107b0 bt_rx_thread
options: 0x0, priority: -8 timeout: 0
state: pending, entry: 0x353b1
stack size 2200, unused 1672, usage 528 / 2200 (24 %)
0x2000fe88 BT RX WQ
options: 0x0, priority: -8 timeout: 0
state: pending, entry: 0x394e1
stack size 2200, unused 1656, usage 544 / 2200 (24 %)
0x2000fdd0 BT TX
options: 0x0, priority: -9 timeout: 0
state: pending, entry: 0x217d1
stack size 512, unused 112, usage 400 / 512 (78 %)
0x200106f8 conn_mgr_monitor
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
Peripheral uart:~$ kernel threads Scheduler: 17939 since last call Threads: 0x200107b0 bt_rx_thread options: 0x0, priority: -8 timeout: 0 state: pending, entry: 0x353b1 stack size 2200, unused 1672, usage 528 / 2200 (24 %) 0x2000fe88 BT RX WQ options: 0x0, priority: -8 timeout: 0 state: pending, entry: 0x394e1 stack size 2200, unused 1656, usage 544 / 2200 (24 %) 0x2000fdd0 BT TX options: 0x0, priority: -9 timeout: 0 state: pending, entry: 0x217d1 stack size 512, unused 112, usage 400 / 512 (78 %) 0x200106f8 conn_mgr_monitor options: 0x0, priority: -1 timeout: 0 state: pending, entry: 0x347dd stack size 512, unused 376, usage 136 / 512 (26 %) 0x200105a8 rx_q[0] options: 0x0, priority: -1 timeout: 0 state: pending, entry: 0x41e85 stack size 1504, unused 1368, usage 136 / 1504 (9 %) 0x200104b8 net_mgmt options: 0x0, priority: -1 timeout: 0 state: pending, entry: 0x394e1 stack size 2048, unused 1872, usage 176 / 2048 (8 %) *0x2000f968 shell_uart options: 0x0, priority: 14 timeout: 0 state: queued, entry: 0x1d025 stack size 2048, unused 1048, usage 1000 / 2048 (48 %) 0x2000fcf8 BT LW WQ options: 0x0, priority: 10 timeout: 0 state: pending, entry: 0x394e1 stack size 1304, unused 408, usage 896 / 1304 (68 %) 0x20010b90 sysworkq options: 0x1, priority: -1 timeout: 0 state: pending, entry: 0x394e1 stack size 2048, unused 1656, usage 392 / 2048 (19 %) 0x2000d870 logging options: 0x0, priority: 14 timeout: 5449 state: pending, entry: 0x1a7cd stack size 768, unused 424, usage 344 / 768 (44 %) 0x20010a20 idle options: 0x1, priority: 15 timeout: 0 state: , entry: 0x44e65 stack size 320, unused 256, usage 64 / 320 (20 %) 0x20010ad8 main options: 0x1, priority: 0 timeout: 32772 state: suspended, entry: 0x38e15 stack size 1024, unused 96, usage 928 / 1024 (90 %) uart:~$ [00:00:56.527,008] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.527,038] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.527,038] <dbg> bt_driver: process_rx: remaining 1 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.527,069] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 31 bytes [00:00:56.527,099] <dbg> bt_driver: process_rx: remaining 30 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:56.527,099] <dbg> bt_driver: get_rx: type 0x04, evt 0x3e [00:00:56.527,130] <dbg> bt_driver: read_payload: Allocated rx.buf 0x20016e58 [00:00:56.527,160] <dbg> bt_driver: read_payload: got 30 bytes, remaining 0 [00:00:56.527,191] <dbg> bt_driver: read_payload: Payload (len 33): 3e1f0a000f000101788ba945266700000000000000000000000027000000f40101 [00:00:56.527,221] <dbg> bt_driver: read_payload: Putting buf 0x20016e58 to rx fifo [00:00:56.527,282] <dbg> bt_driver: rx_thread: Calling bt_recv(0x20016e58) [00:00:56.527,313] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20016e58 len 33 [00:00:56.527,343] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:00:56.527,374] <dbg> bt_hci_core: rx_work_handler: buf 0x20016e58 type 1 len 33 [00:00:56.527,374] <dbg> bt_hci_core: hci_event: event 0x3e [00:00:56.527,404] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x0a [00:00:56.527,557] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: status 0x00 handle 15 role 1 peer 67:26:45:A9:8B:78 (random) peer RPA 00:00:00:00:00:00 [00:00:56.527,648] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: local RPA 00:00:00:00:00:00 [00:00:56.527,740] <dbg> bt_keys: bt_keys_find_irk: 67:26:45:A9:8B:78 (random) [00:00:56.527,832] <dbg> bt_keys: bt_keys_find_irk: No IRK for 67:26:45:A9:8B:78 (random) [00:00:56.527,832] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2 [00:00:56.527,862] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1 [00:00:56.527,862] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2 [00:00:56.527,893] <dbg> bt_adv: bt_le_adv_resume: Host cannot resume connectable advertising (-12) [00:00:56.527,954] <dbg> bt_conn: bt_conn_set_state: adv-connectable -> connected [00:00:56.527,984] <dbg> bt_l2cap: l2cap_accept: conn 0x20010098 handle 15 [00:00:56.527,984] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x20010098 chan 0x20011218 [00:00:56.528,015] <dbg> bt_l2cap: l2cap_connected: ch 0x20011218 cid 0x0005 [00:00:56.528,015] <dbg> bt_smp: bt_smp_accept: conn 0x20010098 handle 15 [00:00:56.528,045] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x20010098 chan 0x2001035c [00:00:56.528,045] <dbg> bt_smp: bt_smp_connected: chan 0x2001035c cid 0x0006 [00:00:56.528,076] <dbg> bt_att: bt_att_accept: conn 0x20010098 handle 15 [00:00:56.528,106] <dbg> bt_att: att_chan_attach: att 0x200176a4 chan 0x20013848 flags 0 [00:00:56.528,137] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x20010098 chan 0x2001384c [00:00:56.528,137] <dbg> bt_att: bt_att_connected: chan 0x2001384c cid 0x0004 Updated MTU: TX: 23 RX: 23 bytes [00:00:56.528,198] <dbg> bt_gatt: bt_gatt_connected: conn 0x20010098 [00:00:56.528,289] <dbg> bt_keys: bt_keys_find_addr: 67:26:45:A9:8B:78 (random) [00:00:56.528,411] <dbg> bt_att: bt_att_status: chan 0x2001384c status 0x2001385c Connected [00:00:56.528,442] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2016 param_len 2 [00:00:56.528,472] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20017368 [00:00:56.528,472] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x20017368 opcode 0x2016 len 5 [00:00:56.528,533] <dbg> bt_hci_core: process_events: count 2 [00:00:56.528,533] <dbg> bt_hci_core: process_events: ev->state 4 [00:00:56.528,533] <dbg> bt_hci_core: send_cmd: calling net_buf_get [00:00:56.528,564] <dbg> bt_hci_core: send_cmd: calling sem_take_wait [00:00:56.528,594] <dbg> bt_hci_core: send_cmd: Sending command 0x2016 (buf 0x20017368) to driver [00:00:56.528,594] <dbg> bt_hci_core: bt_send: buf 0x20017368 len 5 type 0 [00:00:56.528,594] <dbg> bt_driver: h4_send: buf 0x20017368 type 0 len 5 [00:00:56.528,656] <dbg> bt_hci_core: process_events: ev->state 1 [00:00:56.528,686] <dbg> bt_conn: bt_conn_prepare_events: [00:00:56.528,686] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20010098 to poll list [00:00:56.528,717] <dbg> bt_conn: conn_prepare_events: wait on host fifo [00:00:56.528,717] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events [00:00:56.528,747] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:56.532,684] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.532,684] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.532,714] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 4 bytes [00:00:56.532,745] <dbg> bt_driver: process_rx: remaining 4 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:56.532,745] <dbg> bt_driver: get_rx: type 0x04, evt 0x0f [00:00:56.532,775] <dbg> bt_driver: read_payload: Allocated rx.buf 0x20016e74 [00:00:56.532,806] <dbg> bt_driver: read_payload: got 4 bytes, remaining 0 [00:00:56.532,836] <dbg> bt_driver: read_payload: Payload (len 6): 0f0400011620 [00:00:56.532,836] <dbg> bt_driver: read_payload: Putting buf 0x20016e74 to rx fifo [00:00:56.532,928] <dbg> bt_driver: rx_thread: Calling bt_recv(0x20016e74) [00:00:56.532,958] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20016e74 len 6 [00:00:56.532,958] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2016 [00:00:56.532,989] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2016 status 0x00 buf 0x20016e74 [00:00:56.533,050] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20017368 opcode 0x2016 len 0 [00:00:56.533,050] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2032 param_len 7 [00:00:56.533,081] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20017368 [00:00:56.533,111] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x20017368 opcode 0x2032 len 10 [00:00:56.533,142] <dbg> bt_hci_core: process_events: count 3 [00:00:56.533,172] <dbg> bt_hci_core: process_events: ev->state 4 [00:00:56.533,203] <dbg> bt_hci_core: send_cmd: calling net_buf_get [00:00:56.533,203] <dbg> bt_hci_core: send_cmd: calling sem_take_wait [00:00:56.533,233] <dbg> bt_hci_core: send_cmd: Sending command 0x2032 (buf 0x20017368) to driver [00:00:56.533,233] <dbg> bt_hci_core: bt_send: buf 0x20017368 len 10 type 0 [00:00:56.533,264] <dbg> bt_driver: h4_send: buf 0x20017368 type 0 len 10 [00:00:56.533,325] <dbg> bt_hci_core: process_events: ev->state 0 [00:00:56.533,325] <dbg> bt_hci_core: process_events: ev->state 0 [00:00:56.533,355] <dbg> bt_conn: bt_conn_prepare_events: [00:00:56.533,355] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20010098 to poll list [00:00:56.533,386] <dbg> bt_conn: conn_prepare_events: wait on host fifo [00:00:56.533,386] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events [00:00:56.533,416] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:56.537,170] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.537,200] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.537,200] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 4 bytes [00:00:56.537,231] <dbg> bt_driver: process_rx: remaining 4 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:56.537,231] <dbg> bt_driver: get_rx: type 0x04, evt 0x0f [00:00:56.537,261] <dbg> bt_driver: read_payload: Allocated rx.buf 0x20016e74 [00:00:56.537,292] <dbg> bt_driver: read_payload: got 4 bytes, remaining 0 [00:00:56.537,322] <dbg> bt_driver: read_payload: Payload (len 6): 0f0400013220 [00:00:56.537,322] <dbg> bt_driver: read_payload: Putting buf 0x20016e74 to rx fifo [00:00:56.537,414] <dbg> bt_driver: rx_thread: Calling bt_recv(0x20016e74) [00:00:56.537,445] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20016e74 len 6 [00:00:56.537,475] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2032 [00:00:56.537,506] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2032 status 0x00 buf 0x20016e74 [00:00:56.537,536] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20017368 opcode 0x2032 len 0 [00:00:56.537,567] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:56.537,597] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:56.771,301] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.771,331] <dbg> bt_driver: process_rx: remaining 4 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.771,362] <dbg> bt_driver: get_acl_hdr: Got ACL header. Payload 11 bytes [00:00:56.771,362] <dbg> bt_driver: process_rx: remaining 11 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:56.771,392] <dbg> bt_driver: get_rx: type 0x02, evt 0x0f [00:00:56.771,423] <dbg> bt_driver: read_payload: Allocated rx.buf 0x2001712c [00:00:56.771,423] <dbg> bt_driver: read_payload: got 11 bytes, remaining 0 [00:00:56.771,484] <dbg> bt_driver: read_payload: Payload (len 15): 0f200b0007000400080100ffff012a [00:00:56.771,484] <dbg> bt_driver: read_payload: Putting buf 0x2001712c to rx fifo [00:00:56.771,545] <dbg> bt_driver: rx_thread: Calling bt_recv(0x2001712c) [00:00:56.771,606] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2001712c len 15 [00:00:56.771,636] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:00:56.771,636] <dbg> bt_hci_core: rx_work_handler: buf 0x2001712c type 3 len 15 [00:00:56.771,667] <dbg> bt_hci_core: hci_acl: buf 0x2001712c [00:00:56.771,667] <dbg> bt_hci_core: hci_acl: handle 15 len 11 flags 2 [00:00:56.771,697] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:00:56.771,697] <dbg> bt_conn: wait_for_tx_work: conn 0x20010098 [00:00:56.771,759] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:56.771,789] <dbg> bt_conn: tx_notify: conn 0x20010098 [00:00:56.771,820] <dbg> bt_conn: wait_for_tx_work: done [00:00:56.771,820] <dbg> bt_conn: bt_conn_recv: handle 15 len 11 flags 02 [00:00:56.771,850] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7 [00:00:56.771,850] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet [00:00:56.771,881] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7 [00:00:56.771,881] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x2001384c len 7 [00:00:56.771,911] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20013848 code 0x08 len 6 [00:00:56.771,972] <dbg> bt_att: att_read_type_req: start_handle 0x0001 end_handle 0xffff type 2a01 [00:00:56.772,033] <dbg> bt_att: read_type_cb: handle 0x000d [00:00:56.772,064] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 2 [00:00:56.772,155] <dbg> bt_att: chan_send: code 0x09 [00:00:56.772,186] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20010098 cid 4 len 6 [00:00:56.772,186] <dbg> bt_conn: bt_conn_send_cb: conn handle 15 buf len 10 cb 0 user_data 0 [00:00:56.772,247] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3 [00:00:56.772,247] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2 [00:00:56.772,277] <dbg> bt_hci_core: bt_hci_host_num_completed_packets: Reporting completed packet for handle 15 [00:00:56.772,308] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5 [00:00:56.772,308] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20017368 [00:00:56.772,338] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8 [00:00:56.772,338] <dbg> bt_hci_core: bt_send: buf 0x20017368 len 8 type 0 [00:00:56.772,369] <dbg> bt_driver: h4_send: buf 0x20017368 type 0 len 8 [00:00:56.772,430] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:56.772,460] <dbg> bt_hci_core: process_events: count 3 [00:00:56.772,460] <dbg> bt_hci_core: process_events: ev->state 0 [00:00:56.772,491] <dbg> bt_hci_core: process_events: ev->state 0 [00:00:56.772,491] <dbg> bt_hci_core: process_events: ev->state 4 [00:00:56.772,491] <dbg> bt_conn: bt_conn_process_tx: conn 0x20010098 [00:00:56.772,521] <dbg> bt_conn: send_buf: conn 0x20010098 buf 0x20017644 len 10 [00:00:56.772,521] <dbg> bt_conn: send_buf: send single [00:00:56.772,552] <dbg> bt_conn: do_send_frag: conn 0x20010098 buf 0x20017644 len 10 flags 0x02 [00:00:56.772,583] <dbg> bt_hci_core: bt_send: buf 0x20017644 len 14 type 2 [00:00:56.772,583] <dbg> bt_driver: h4_send: buf 0x20017644 type 2 len 14 [00:00:56.772,613] <dbg> bt_conn: bt_conn_prepare_events: [00:00:56.772,644] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20010098 to poll list [00:00:56.772,644] <dbg> bt_conn: conn_prepare_events: wait on host fifo [00:00:56.772,644] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events [00:00:56.773,986] <dbg> bt_att: att_tx_destroy: 0x20017644 [00:00:56.774,017] <dbg> bt_att: att_on_sent_cb: opcode 0x9 [00:00:56.774,017] <dbg> bt_att: att_on_sent_cb: UATT bearer, calling att_sent [00:00:56.774,017] <dbg> bt_att: att_sent: conn 0x20010098 chan 0x2001384c [00:00:56.774,047] <dbg> bt_att: bt_att_sent: chan 0x20013848 [00:00:56.917,480] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.917,510] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.917,510] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 5 bytes [00:00:56.917,541] <dbg> bt_driver: process_rx: remaining 5 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:56.917,541] <dbg> bt_driver: get_rx: type 0x04, evt 0x13 [00:00:56.917,572] <dbg> bt_driver: read_payload: Allocated rx.buf 0x200172bc [00:00:56.917,602] <dbg> bt_driver: read_payload: got 5 bytes, remaining 0 [00:00:56.917,633] <dbg> bt_driver: read_payload: Payload (len 7): 1305010f000100 [00:00:56.917,633] <dbg> bt_driver: read_payload: Putting buf 0x200172bc to rx fifo [00:00:56.917,785] <dbg> bt_driver: rx_thread: Calling bt_recv(0x200172bc) [00:00:56.917,816] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x200172bc len 7 [00:00:56.917,816] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1 [00:00:56.917,846] <dbg> bt_hci_core: hci_num_completed_packets: handle 15 count 1 [00:00:56.917,846] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:00:56.917,877] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:56.917,907] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:56.920,196] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.920,196] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.920,227] <dbg> bt_driver: process_rx: remaining 1 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.920,257] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 12 bytes [00:00:56.920,257] <dbg> bt_driver: process_rx: remaining 11 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:56.920,288] <dbg> bt_driver: get_rx: type 0x04, evt 0x3e [00:00:56.920,318] <dbg> bt_driver: read_payload: Allocated rx.buf 0x20016e58 [00:00:56.920,318] <dbg> bt_driver: read_payload: got 11 bytes, remaining 0 [00:00:56.920,379] <dbg> bt_driver: read_payload: Payload (len 14): 3e0c04000f002d7f01f7ffd90000 [00:00:56.920,379] <dbg> bt_driver: read_payload: Putting buf 0x20016e58 to rx fifo [00:00:56.920,440] <dbg> bt_driver: rx_thread: Calling bt_recv(0x20016e58) [00:00:56.920,471] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20016e58 len 14 [00:00:56.920,501] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:00:56.920,532] <dbg> bt_hci_core: rx_work_handler: buf 0x20016e58 type 1 len 14 [00:00:56.920,532] <dbg> bt_hci_core: hci_event: event 0x3e [00:00:56.920,562] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x04 [00:00:56.920,593] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:00:56.920,623] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:56.920,654] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:56.966,400] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.966,430] <dbg> bt_driver: process_rx: remaining 4 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:56.966,461] <dbg> bt_driver: get_acl_hdr: Got ACL header. Payload 11 bytes [00:00:56.966,461] <dbg> bt_driver: process_rx: remaining 11 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:56.966,491] <dbg> bt_driver: get_rx: type 0x02, evt 0x0f [00:00:56.966,522] <dbg> bt_driver: read_payload: Allocated rx.buf 0x2001712c [00:00:56.966,522] <dbg> bt_driver: read_payload: got 11 bytes, remaining 0 [00:00:56.966,583] <dbg> bt_driver: read_payload: Payload (len 15): 0f200b0007000400080100ffff2a2b [00:00:56.966,583] <dbg> bt_driver: read_payload: Putting buf 0x2001712c to rx fifo [00:00:56.966,674] <dbg> bt_driver: rx_thread: Calling bt_recv(0x2001712c) [00:00:56.966,705] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2001712c len 15 [00:00:56.966,735] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:00:56.966,735] <dbg> bt_hci_core: rx_work_handler: buf 0x2001712c type 3 len 15 [00:00:56.966,766] <dbg> bt_hci_core: hci_acl: buf 0x2001712c [00:00:56.966,766] <dbg> bt_hci_core: hci_acl: handle 15 len 11 flags 2 [00:00:56.966,796] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:00:56.966,796] <dbg> bt_conn: wait_for_tx_work: conn 0x20010098 [00:00:56.966,857] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:56.966,888] <dbg> bt_conn: tx_notify: conn 0x20010098 [00:00:56.966,918] <dbg> bt_conn: wait_for_tx_work: done [00:00:56.966,949] <dbg> bt_conn: bt_conn_recv: handle 15 len 11 flags 02 [00:00:56.966,979] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7 [00:00:56.966,979] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet [00:00:56.967,010] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7 [00:00:56.967,010] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x2001384c len 7 [00:00:56.967,041] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20013848 code 0x08 len 6 [00:00:56.967,102] <dbg> bt_att: att_read_type_req: start_handle 0x0001 end_handle 0xffff type 2b2a [00:00:56.967,163] <dbg> bt_att: read_type_cb: handle 0x0008 [00:00:56.967,193] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 16 [00:00:56.967,193] <dbg> bt_att: chan_send: code 0x09 [00:00:56.967,224] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20010098 cid 4 len 20 [00:00:56.967,224] <dbg> bt_conn: bt_conn_send_cb: conn handle 15 buf len 24 cb 0 user_data 0 [00:00:56.967,285] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3 [00:00:56.967,285] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2 [00:00:56.967,315] <dbg> bt_hci_core: bt_hci_host_num_completed_packets: Reporting completed packet for handle 15 [00:00:56.967,315] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5 [00:00:56.967,346] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20017368 [00:00:56.967,346] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8 [00:00:56.967,376] <dbg> bt_hci_core: bt_send: buf 0x20017368 len 8 type 0 [00:00:56.967,376] <dbg> bt_driver: h4_send: buf 0x20017368 type 0 len 8 [00:00:56.967,437] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:56.967,468] <dbg> bt_hci_core: process_events: count 3 [00:00:56.967,498] <dbg> bt_hci_core: process_events: ev->state 0 [00:00:56.967,498] <dbg> bt_hci_core: process_events: ev->state 0 [00:00:56.967,529] <dbg> bt_hci_core: process_events: ev->state 4 [00:00:56.967,529] <dbg> bt_conn: bt_conn_process_tx: conn 0x20010098 [00:00:56.967,559] <dbg> bt_conn: send_buf: conn 0x20010098 buf 0x20017644 len 24 [00:00:56.967,559] <dbg> bt_conn: send_buf: send single [00:00:56.967,590] <dbg> bt_conn: do_send_frag: conn 0x20010098 buf 0x20017644 len 24 flags 0x02 [00:00:56.967,590] <dbg> bt_hci_core: bt_send: buf 0x20017644 len 28 type 2 [00:00:56.967,620] <dbg> bt_driver: h4_send: buf 0x20017644 type 2 len 28 [00:00:56.967,651] <dbg> bt_conn: bt_conn_prepare_events: [00:00:56.967,681] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20010098 to poll list [00:00:56.967,681] <dbg> bt_conn: conn_prepare_events: wait on host fifo [00:00:56.967,681] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events [00:00:56.969,024] <dbg> bt_att: att_tx_destroy: 0x20017644 [00:00:56.969,024] <dbg> bt_att: att_on_sent_cb: opcode 0x9 [00:00:56.969,055] <dbg> bt_att: att_on_sent_cb: UATT bearer, calling att_sent [00:00:56.969,055] <dbg> bt_att: att_sent: conn 0x20010098 chan 0x2001384c [00:00:56.969,085] <dbg> bt_att: bt_att_sent: chan 0x20013848 [00:00:57.063,659] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:57.063,690] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:57.063,690] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 5 bytes [00:00:57.063,720] <dbg> bt_driver: process_rx: remaining 5 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:57.063,720] <dbg> bt_driver: get_rx: type 0x04, evt 0x13 [00:00:57.063,751] <dbg> bt_driver: read_payload: Allocated rx.buf 0x200172bc [00:00:57.063,781] <dbg> bt_driver: read_payload: got 5 bytes, remaining 0 [00:00:57.063,812] <dbg> bt_driver: read_payload: Payload (len 7): 1305010f000100 [00:00:57.063,842] <dbg> bt_driver: read_payload: Putting buf 0x200172bc to rx fifo [00:00:57.063,903] <dbg> bt_driver: rx_thread: Calling bt_recv(0x200172bc) [00:00:57.063,934] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x200172bc len 7 [00:00:57.063,964] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1 [00:00:57.063,964] <dbg> bt_hci_core: hci_num_completed_packets: handle 15 count 1 [00:00:57.063,995] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:00:57.063,995] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:57.064,025] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:57.355,895] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:57.355,926] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:57.355,957] <dbg> bt_driver: process_rx: remaining 1 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:57.355,957] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 6 bytes [00:00:57.355,987] <dbg> bt_driver: process_rx: remaining 5 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:57.355,987] <dbg> bt_driver: get_rx: type 0x04, evt 0x3e [00:00:57.356,018] <dbg> bt_driver: read_payload: Allocated rx.buf 0x20016e58 [00:00:57.356,048] <dbg> bt_driver: read_payload: got 5 bytes, remaining 0 [00:00:57.356,079] <dbg> bt_driver: read_payload: Payload (len 8): 3e060c000f000202 [00:00:57.356,109] <dbg> bt_driver: read_payload: Putting buf 0x20016e58 to rx fifo [00:00:57.356,170] <dbg> bt_driver: rx_thread: Calling bt_recv(0x20016e58) [00:00:57.356,170] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20016e58 len 8 [00:00:57.356,231] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:00:57.356,231] <dbg> bt_hci_core: rx_work_handler: buf 0x20016e58 type 1 len 8 [00:00:57.356,262] <dbg> bt_hci_core: hci_event: event 0x3e [00:00:57.356,262] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x0c [00:00:57.356,292] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:00:57.356,292] <dbg> bt_hci_core: le_phy_update_complete: PHY updated: status: 0x00, tx: 2, rx: 2 [00:00:57.356,323] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:57.356,353] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:58.623,901] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:58.623,901] <dbg> bt_driver: process_rx: remaining 4 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:58.623,931] <dbg> bt_driver: get_acl_hdr: Got ACL header. Payload 7 bytes [00:00:58.623,931] <dbg> bt_driver: process_rx: remaining 7 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:58.623,962] <dbg> bt_driver: get_rx: type 0x02, evt 0x0f [00:00:58.623,992] <dbg> bt_driver: read_payload: Allocated rx.buf 0x2001712c [00:00:58.623,992] <dbg> bt_driver: read_payload: got 7 bytes, remaining 0 [00:00:58.624,053] <dbg> bt_driver: read_payload: Payload (len 11): 0f200700030004000a1f00 [00:00:58.624,053] <dbg> bt_driver: read_payload: Putting buf 0x2001712c to rx fifo [00:00:58.624,114] <dbg> bt_driver: rx_thread: Calling bt_recv(0x2001712c) [00:00:58.624,145] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2001712c len 11 [00:00:58.624,176] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:00:58.624,206] <dbg> bt_hci_core: rx_work_handler: buf 0x2001712c type 3 len 11 [00:00:58.624,206] <dbg> bt_hci_core: hci_acl: buf 0x2001712c [00:00:58.624,237] <dbg> bt_hci_core: hci_acl: handle 15 len 7 flags 2 [00:00:58.624,237] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:00:58.624,267] <dbg> bt_conn: wait_for_tx_work: conn 0x20010098 [00:00:58.624,298] <dbg> bt_driver: rx_thread: rx.buf 0 [00:00:58.624,328] <dbg> bt_conn: tx_notify: conn 0x20010098 [00:00:58.624,359] <dbg> bt_conn: wait_for_tx_work: done [00:00:58.624,389] <dbg> bt_conn: bt_conn_recv: handle 15 len 7 flags 02 [00:00:58.624,389] <dbg> bt_conn: bt_acl_recv: First, len 7 final 3 [00:00:58.624,420] <dbg> bt_conn: bt_acl_recv: Successfully parsed 7 byte L2CAP packet [00:00:58.624,450] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 3 [00:00:58.624,450] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x2001384c len 3 [00:00:58.624,481] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20013848 code 0x0a len 2 [00:00:58.624,481] <dbg> bt_att: att_read_req: handle 0x001f [00:00:58.624,542] <dbg> bt_att: read_cb: handle 0x001f [00:00:58.624,572] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 7 [00:00:58.624,572] <dbg> bt_att: chan_send: code 0x0b [00:00:58.624,603] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20010098 cid 4 len 8 [00:00:58.624,603] <dbg> bt_conn: bt_conn_send_cb: conn handle 15 buf len 12 cb 0 user_data 0 [00:00:58.624,664] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3 [00:00:58.624,664] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2 [00:00:58.624,694] <dbg> bt_hci_core: bt_hci_host_num_completed_packets: Reporting completed packet for handle 15 [00:00:58.624,694] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5 [00:00:58.624,725] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20017368 [00:00:58.624,725] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8 [00:00:58.624,755] <dbg> bt_hci_core: bt_send: buf 0x20017368 len 8 type 0 [00:00:58.624,755] <dbg> bt_driver: h4_send: buf 0x20017368 type 0 len 8 [00:00:58.624,816] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:58.624,847] <dbg> bt_hci_core: process_events: count 3 [00:00:58.624,877] <dbg> bt_hci_core: process_events: ev->state 0 [00:00:58.624,877] <dbg> bt_hci_core: process_events: ev->state 0 [00:00:58.624,877] <dbg> bt_hci_core: process_events: ev->state 4 [00:00:58.624,908] <dbg> bt_conn: bt_conn_process_tx: conn 0x20010098 [00:00:58.624,908] <dbg> bt_conn: send_buf: conn 0x20010098 buf 0x20017644 len 12 [00:00:58.624,938] <dbg> bt_conn: send_buf: send single [00:00:58.624,969] <dbg> bt_conn: do_send_frag: conn 0x20010098 buf 0x20017644 len 12 flags 0x02 [00:00:58.624,969] <dbg> bt_hci_core: bt_send: buf 0x20017644 len 16 type 2 [00:00:58.625,000] <dbg> bt_driver: h4_send: buf 0x20017644 type 2 len 16 [00:00:58.625,000] <dbg> bt_conn: bt_conn_prepare_events: [00:00:58.625,030] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20010098 to poll list [00:00:58.625,030] <dbg> bt_conn: conn_prepare_events: wait on host fifo [00:00:58.625,061] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events [00:00:58.626,373] <dbg> bt_att: att_tx_destroy: 0x20017644 [00:00:58.626,403] <dbg> bt_att: att_on_sent_cb: opcode 0xb [00:00:58.626,403] <dbg> bt_att: att_on_sent_cb: UATT bearer, calling att_sent [00:00:58.626,434] <dbg> bt_att: att_sent: conn 0x20010098 chan 0x2001384c [00:00:58.626,434] <dbg> bt_att: bt_att_sent: chan 0x20013848 [00:00:58.721,191] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:58.721,191] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:00:58.721,221] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 5 bytes [00:00:58.721,221] <dbg> bt_driver: process_rx: remaining 5 discard 0 have_hdr 1 rx.buf 0 len 0 [00:00:58.721,252] <dbg> bt_driver: get_rx: type 0x04, evt 0x13 [00:00:58.721,282] <dbg> bt_driver: read_payload: Allocated rx.buf 0x200172bc [00:00:58.721,282] <dbg> bt_driver: read_payload: got 5 bytes, remaining 0 [00:00:58.721,343] <dbg> bt_driver: read_payload: Payload (len 7): 1305010f000100 [00:00:58.721,343] <dbg> bt_driver: read_payload: Putting buf 0x200172bc to rx fifo [00:00:58.721,405] <dbg> bt_driver: rx_thread: Calling bt_recv(0x200172bc) [00:00:58.721,466] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x200172bc len 7 [00:00:58.721,466] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1 [00:00:58.721,496] <dbg> bt_hci_core: hci_num_completed_packets: handle 15 count 1 [00:00:58.721,496] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:00:58.721,527] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:00:58.721,557] <dbg> bt_driver: rx_thread: rx.buf 0 [00:01:01.528,015] <dbg> bt_conn: deferred_work: conn 0x20010098 [00:01:01.528,045] <dbg> bt_conn: send_conn_le_param_update: conn 0x20010098 features 0x2d params (24-40 0 42) [00:01:01.528,076] <dbg> bt_conn: bt_conn_create_pdu_timeout: Timeout discarded. No blocking in syswq. [00:01:01.528,106] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20010098 cid 5 len 12 [00:01:01.528,106] <dbg> bt_conn: bt_conn_send_cb: conn handle 15 buf len 16 cb 0 user_data 0 [00:01:01.528,167] <dbg> bt_hci_core: process_events: count 3 [00:01:01.528,167] <dbg> bt_hci_core: process_events: ev->state 0 [00:01:01.528,198] <dbg> bt_hci_core: process_events: ev->state 0 [00:01:01.528,198] <dbg> bt_hci_core: process_events: ev->state 4 [00:01:01.528,198] <dbg> bt_conn: bt_conn_process_tx: conn 0x20010098 [00:01:01.528,228] <dbg> bt_conn: send_buf: conn 0x20010098 buf 0x20017500 len 16 [00:01:01.528,259] <dbg> bt_conn: send_buf: send single [00:01:01.528,259] <dbg> bt_conn: do_send_frag: conn 0x20010098 buf 0x20017500 len 16 flags 0x02 [00:01:01.528,289] <dbg> bt_hci_core: bt_send: buf 0x20017500 len 20 type 2 [00:01:01.528,289] <dbg> bt_driver: h4_send: buf 0x20017500 type 2 len 20 [00:01:01.528,350] <dbg> bt_conn: bt_conn_prepare_events: [00:01:01.528,381] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20010098 to poll list [00:01:01.528,381] <dbg> bt_conn: conn_prepare_events: wait on host fifo [00:01:01.528,411] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events [00:01:01.597,595] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.597,625] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.597,625] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 5 bytes [00:01:01.597,656] <dbg> bt_driver: process_rx: remaining 5 discard 0 have_hdr 1 rx.buf 0 len 0 [00:01:01.597,656] <dbg> bt_driver: get_rx: type 0x04, evt 0x13 [00:01:01.597,686] <dbg> bt_driver: read_payload: Allocated rx.buf 0x200172bc [00:01:01.597,717] <dbg> bt_driver: read_payload: got 5 bytes, remaining 0 [00:01:01.597,747] <dbg> bt_driver: read_payload: Payload (len 7): 1305010f000100 [00:01:01.597,747] <dbg> bt_driver: read_payload: Putting buf 0x200172bc to rx fifo [00:01:01.597,839] <dbg> bt_driver: rx_thread: Calling bt_recv(0x200172bc) [00:01:01.597,869] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x200172bc len 7 [00:01:01.597,900] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1 [00:01:01.597,900] <dbg> bt_hci_core: hci_num_completed_packets: handle 15 count 1 [00:01:01.597,930] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:01:01.597,961] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:01:01.597,991] <dbg> bt_driver: rx_thread: rx.buf 0 [00:01:01.646,606] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.646,636] <dbg> bt_driver: process_rx: remaining 4 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.646,636] <dbg> bt_driver: get_acl_hdr: Got ACL header. Payload 10 bytes [00:01:01.646,667] <dbg> bt_driver: process_rx: remaining 10 discard 0 have_hdr 1 rx.buf 0 len 0 [00:01:01.646,697] <dbg> bt_driver: get_rx: type 0x02, evt 0x0f [00:01:01.646,697] <dbg> bt_driver: read_payload: Allocated rx.buf 0x2001712c [00:01:01.646,728] <dbg> bt_driver: read_payload: got 10 bytes, remaining 0 [00:01:01.646,759] <dbg> bt_driver: read_payload: Payload (len 14): 0f200a0006000500130102000000 [00:01:01.646,789] <dbg> bt_driver: read_payload: Putting buf 0x2001712c to rx fifo [00:01:01.646,881] <dbg> bt_driver: rx_thread: Calling bt_recv(0x2001712c) [00:01:01.646,881] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2001712c len 14 [00:01:01.646,942] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:01:01.646,942] <dbg> bt_hci_core: rx_work_handler: buf 0x2001712c type 3 len 14 [00:01:01.646,942] <dbg> bt_hci_core: hci_acl: buf 0x2001712c [00:01:01.646,972] <dbg> bt_hci_core: hci_acl: handle 15 len 10 flags 2 [00:01:01.647,003] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:01:01.647,003] <dbg> bt_conn: wait_for_tx_work: conn 0x20010098 [00:01:01.647,064] <dbg> bt_driver: rx_thread: rx.buf 0 [00:01:01.647,094] <dbg> bt_conn: tx_notify: conn 0x20010098 [00:01:01.647,125] <dbg> bt_conn: wait_for_tx_work: done [00:01:01.647,155] <dbg> bt_conn: bt_conn_recv: handle 15 len 10 flags 02 [00:01:01.647,155] <dbg> bt_conn: bt_acl_recv: First, len 10 final 6 [00:01:01.647,186] <dbg> bt_conn: bt_acl_recv: Successfully parsed 10 byte L2CAP packet [00:01:01.647,186] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 5 len 6 [00:01:01.647,216] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20011218 len 6 [00:01:01.647,216] <dbg> bt_l2cap: l2cap_recv: Signaling code 0x13 ident 1 len 2 [00:01:01.647,247] <dbg> bt_l2cap: le_conn_param_rsp: LE conn param rsp result 0 [00:01:01.647,277] <dbg> bt_conn: bt_conn_ref: handle 15 ref 2 -> 3 [00:01:01.647,277] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2 [00:01:01.647,308] <dbg> bt_hci_core: bt_hci_host_num_completed_packets: Reporting completed packet for handle 15 [00:01:01.647,308] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5 [00:01:01.647,338] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20017368 [00:01:01.647,338] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8 [00:01:01.647,369] <dbg> bt_hci_core: bt_send: buf 0x20017368 len 8 type 0 [00:01:01.647,369] <dbg> bt_driver: h4_send: buf 0x20017368 type 0 len 8 [00:01:01.647,430] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:01:01.890,411] <dbg> bt_driver: process_rx: remaining 0 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.890,441] <dbg> bt_driver: process_rx: remaining 2 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.890,472] <dbg> bt_driver: process_rx: remaining 1 discard 0 have_hdr 0 rx.buf 0 len 0 [00:01:01.890,502] <dbg> bt_driver: get_evt_hdr: Got event header. Payload 10 bytes [00:01:01.890,502] <dbg> bt_driver: process_rx: remaining 9 discard 0 have_hdr 1 rx.buf 0 len 0 [00:01:01.890,533] <dbg> bt_driver: get_rx: type 0x04, evt 0x3e [00:01:01.890,533] <dbg> bt_driver: read_payload: Allocated rx.buf 0x20016e58 [00:01:01.890,563] <dbg> bt_driver: read_payload: got 9 bytes, remaining 0 [00:01:01.890,625] <dbg> bt_driver: read_payload: Payload (len 12): 3e0a03000f00270000002a00 [00:01:01.890,625] <dbg> bt_driver: read_payload: Putting buf 0x20016e58 to rx fifo [00:01:01.890,686] <dbg> bt_driver: rx_thread: Calling bt_recv(0x20016e58) [00:01:01.890,716] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20016e58 len 12 [00:01:01.890,747] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue [00:01:01.890,747] <dbg> bt_hci_core: rx_work_handler: buf 0x20016e58 type 1 len 12 [00:01:01.890,777] <dbg> bt_hci_core: hci_event: event 0x3e [00:01:01.890,777] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x03 [00:01:01.890,808] <dbg> bt_hci_core: le_conn_update_complete: status 0x00, handle 15 [00:01:01.890,838] <dbg> bt_conn: bt_conn_ref: handle 15 ref 1 -> 2 [00:01:01.890,838] <dbg> bt_conn: bt_conn_unref: handle 15 ref 2 -> 1 [00:01:01.890,869] <dbg> bt_driver: rx_thread: rx.buf 0
Do you please have any idea on what could be happening? I have checked with the Nordic AI and in all the posts I could find. I have been successfully connected only ONCE with my Pixel 9 (using the nRF Connect app) but other than that it always fail. It seems to time out because there is no data communication between the phone and the device, making my smartphone disable its Bluetooth entirely for about 10 seconds before turning it on again, like something crashed and it just reset the Bluetooth.
Thanks!