[nRF Connect SDK] Pairing failure

[Tim Hwang]

Target nRF52832(nrf52dk_nrf52832)
SDK NCS v2.0.0

original case
(+) [nRF Connect SDK]Force to make pairing(bonding) - Nordic Q&A - Nordic DevZone - Nordic DevZone (nordicsemi.com)

Here is my test step. (Nordic: peripheral role)

1) Nordic begins advertising (custom UUID like peripheral_uart sample)
2) Android app gets predefined bt mac (example 00:16:7F:11:22:36).
There were no BLE scan. and connect to Nordic.

3) Nordic connected and initiate pairing
bt_set_bondable(true);
bt_conn_set_security(conn, BT_SECURITY_L4);

Result
Much of case my Android (MTK) failed to make pairing. (Especially right after android rebooted) 

MTK have told me Nordic should provide solution to resolve this issue.

RTT Viewer
00> Connected secmode 4
00> HS connected
00> HS Connected 00:16:7F:40:1E:D0 (public)
00> D:
00> D: 00:16:7F:40:1E:D0 (public)
00> D: prnd 7d93ec3b4828ce3b4210d054f903653a
00> D: chan 0x20001f54 cid 0x0006
00> D: status 0x8
00> D: chan 0x20001f54 conn 0x20001c90 handle 0 encrypt 0x00 hci status 0x1f
00> Security failed: 00:16:7F:40:1E:D0 (public) level 1 err 9
(Android public mac 00:16:7F:40:1E:D0)

2772.sf650_error_03Nov2022.7z



BTW, Nordic required sniff log for analyzing pairing error. However, I hardly get sniff log.
I can get CONNECT_IND then drops next packets. Do you have any idea?






nrf_sniffer_for_bluetooth_le_4.1.1
wireshark 4.0.1
nRF52DK dev borad
J-Link 6.88a

[Tim Hwang]

00> HS:Advertising successfully started
00> D: 55:A6:42:65:6B:D0 (random)
00> D: No IRK for 55:A6:42:65:6B:D0 (random)
00> D: conn 0x20001c88 handle 0
00> D: chan 0x20001f4c cid 0x0006
00> D: 55:A6:42:65:6B:D0 (random)
00> Connected secmode 4
00> HS connected
00> HS Connected 55:A6:42:65:6B:D0 (random)
00> D: 
00> D: 55:A6:42:65:6B:D0 (random)
00> D: created 0x200029dc for 55:A6:42:65:6B:D0 (random)
00> D: prnd 23a14c89ca6eb11b5c0c56610146bb35
00> Connection parameters updated.
00>  interval: 6, latency: 0, timeout: 500
00> Conn params updated: interval 7 ms, latency 0, timeout: 5000 ms
00> W: Ignoring unexpected request
00> W: Ignoring unexpected request
00> D: chan 0x20001f4c cid 0x0006
00> D: status 0x8
00> D: 55:A6:42:65:6B:D0 (random) (keys 0x0000)
00> D: Deleting key bt/keys/55a642656bd01
00> D: chan 0x20001f4c conn 0x20001c88 handle 0 encrypt 0x00 hci status 0x1f
00> Security failed: 55:A6:42:65:6B:D0 (random) level 1 err 9 
00> D: 55:A6:42:65:6B:D0 (random)
00> D: 00:00:00:00:00:00 (public) (keys 0x0000)
00> D: Deleting key bt/keys/0000000000000
00> D: 55:A6:42:65:6B:D0 (random)
00> D: 55:A6:42:65:6B:D0 (random)
00> Disconnected: 55:A6:42:65:6B:D0 (random) (reason 19) 
00> HS:Advertising successfully started

sniff.7z

sniff log is uploaded as well as rtt log.
Your message will be forwarded to MTK HQ again.

I have no idea what made following error. Can you please find in sniff log?
00> D: chan 0x20001f4c conn 0x20001c88 handle 0 encrypt 0x00 hci status 0x1f

[Hieu]

Hi Tim,

Sorry but I feel confused a bit about your situation here.

original case
[nRF Connect SDK] How to force to wake up (not to go sleep mode) - Nordic Q&A - Nordic DevZone - Nordic DevZone (nordicsemi.com)

I am not sure how that case is related to this current question. Could you please elaborate?

Much of case my Android (MTK) failed to make pairing. (Especially right after android rebooted) 

MTK have told me Nordic should provide solution to resolve this issue.

Does MTK mean MediaTek?

What reasoning did they give to believe Nordic should provide the solution to resolve this issue?

On my end, I attempted to pair using bt_conn_set_security() as you did, and both my Android phone and my Windows PC can bond with the device without any problem.
Pairing at Security Level 4 like you are trying to do also require an out of band verification method. On your RTT log I don't see signs of this happened. What did you do to achieve this?

Tim Hwang said:

I have no idea what made following error. Can you please find in sniff log?
00> D: chan 0x20001f4c conn 0x20001c88 handle 0 encrypt 0x00 hci status 0x1f

That is not an error. It is most likely just a log from smp.c. See sdk-zephyr/smp.c.

Finally, I would like to ask for a few pieces of information to understand the situation better:

What is your current setup?
What module did you enable logging to acquire the RTT log you shared?
Is there a specific sample are you experimenting on?
What SDK version are you on?
These pieces of information help making sense out of the logs you provided.

Best regards,

Hieu

[Tim Hwang]

Hello Hieu.

1. NFC
I could reproduce this issue without NFC tagging. Let's discuss later. It is not root reason; I think.

2. Just works (key exchange)
1)We do need authenticated/LE secure connection. let's discuss later as well.
If Key exchange is a matter, we always see this issue. But it is not. What do you think about that?

2) Here is pairing sequence in success case.

Here is failure case.
Nordic sent security request.
MTK sent "Pairing request", but Nordic did not send "Pairing response" 
No "Pairing response", No user confirmation.




3. "hci status value 0x1f"
Let's focus it first. I believe you can give me any explanation.
then I'll forward it to MTK.

[Tim Hwang]

I test again with more log option.

1. Pairing request was received after 5 seconds.

2. RTT log at failure log.

00> [00:01:02.722,015] <dbg> bt_hci_core: bt_recv: buf 0x2000ca88 len 33
00> [00:01:02.722,381] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
00> [00:01:02.722,412] <dbg> bt_hci_core: rx_work_handler: buf 0x2000ca88 type 1 len 33
00> [00:01:02.722,412] <dbg> bt_hci_core: hci_event: event 0x3e
00> [00:01:02.722,442] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x0a
00> [00:01:02.722,869] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: bt_hci_le_enh_conn_complete status 0x00 handle 0 role 1 peer 47:95:91:6C:DF:D7 (random) peer RPA 00:00:00:00:00:00
00> [00:01:02.723,052] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: local RPA 00:00:00:00:00:00
00> [00:01:02.723,297] <dbg> bt_keys: bt_keys_find_irk: 47:95:91:6C:DF:D7 (random)
00> [00:01:02.723,541] <dbg> bt_keys: bt_keys_find_irk: No IRK for 47:95:91:6C:DF:D7 (random)
00> [00:01:02.723,602] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
00> [00:01:02.723,632] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
00> [00:01:02.723,663] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
00> [00:01:02.723,724] <dbg> bt_adv: bt_le_adv_resume: Host cannot resume connectable advertising (-12)
00> [00:01:02.723,754] <dbg> bt_conn: bt_conn_set_state: connecting-adv -> connected
00> [00:01:02.723,785] <dbg> bt_l2cap: l2cap_accept: conn 0x20005870 handle 0
00> [00:01:02.723,846] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x20005870 chan 0x20006174
00> [00:01:02.723,876] <dbg> bt_l2cap: l2cap_connected: ch 0x20006174 cid 0x0005
00> [00:01:02.723,876] <dbg> bt_smp: bt_smp_accept: bt_smp_accept 5811 conn 0x20005870 handle 0
00> [00:01:02.723,907] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x20005870 chan 0x20005b2c
00> [00:01:02.723,907] <dbg> bt_smp: bt_smp_connected: bt_smp_connected: chan 0x20005b2c cid 0x0006
00> [00:01:02.724,029] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x20005870 chan 0x2000c124
00> [00:01:02.724,273] <dbg> bt_keys: bt_keys_find_addr: 47:95:91:6C:DF:D7 (random)
00> [00:01:02.724,395] <dbg> bt_smp: smp_send_security_req: smp_send_security_req enter
00> [00:01:02.724,639] <dbg> bt_keys: bt_keys_get_addr: 47:95:91:6C:DF:D7 (random)
00> [00:01:02.724,884] <dbg> bt_keys: bt_keys_get_addr: created 0x20006274 for 47:95:91:6C:DF:D7 (random)
00> [00:01:02.725,006] <dbg> bt_hci_core: process_events: count 2
00> [00:01:02.725,067] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:02.725,097] <dbg> bt_hci_core: process_events: ev->state 1
00> [00:01:02.725,128] <dbg> bt_conn: bt_conn_prepare_events: bt_conn_prepare_events
00> [00:01:02.725,189] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20005870 to poll list
00> [00:01:02.725,219] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
00> [00:01:02.725,494] <dbg> bt_smp: smp_init: smp_init prnd c4ab98dceec5db2f0c4f768e84dcd8be
00> [00:01:02.725,585] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20005870 cid 6 len 2
00> [00:01:02.725,616] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 6 cb (nil) user_data (nil)
00> [00:01:02.725,708] <dbg> bt_smp: smp_send_security_req: smp_send_security_req exit
00> [00:01:02.725,952] <inf> peripheral_uart: ####Connected 47:95:91:6C:DF:D7 (random)
00> [00:01:02.725,952] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:01:02.725,982] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2016 param_len 2
00> [00:01:02.726,043] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2000cba0
00> [00:01:02.726,074] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2000cba0 opcode 0x2016 len 5
00> [00:01:02.726,165] <dbg> bt_hci_core: process_events: count 3
00> [00:01:02.726,165] <dbg> bt_hci_core: process_events: ev->state 4
00> [00:01:02.726,196] <dbg> bt_hci_core: send_cmd: calling net_buf_get
00> [00:01:02.726,196] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
00> [00:01:02.726,226] <dbg> bt_hci_core: send_cmd: Sending command 0x2016 (buf 0x2000cba0) to driver
00> [00:01:02.726,287] <dbg> bt_hci_core: bt_send: buf 0x2000cba0 len 5 type 0
00> [00:01:02.726,348] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:02.726,348] <dbg> bt_hci_core: process_events: ev->state 4
00> [00:01:02.726,409] <dbg> bt_conn: bt_conn_process_tx: conn 0x20005870
00> [00:01:02.726,440] <dbg> bt_conn: send_buf: conn 0x20005870 buf 0x2000cbd8 len 6
00> [00:01:02.726,470] <dbg> bt_conn: send_frag: conn 0x20005870 buf 0x2000cbd8 len 6 flags 0x02
00> [00:01:02.726,470] <dbg> bt_hci_core: bt_send: buf 0x2000cbd8 len 10 type 2
00> [00:01:02.726,654] <dbg> bt_hci_core: bt_recv: buf 0x2000cba0 len 6
00> [00:01:02.726,684] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2016
00> [00:01:02.726,684] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2016 status 0x00 buf 0x2000cba0
00> [00:01:02.726,959] <dbg> bt_conn: bt_conn_prepare_events: bt_conn_prepare_events
00> [00:01:02.727,020] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20005870 to poll list
00> [00:01:02.727,050] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
00> [00:01:02.727,081] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2000cba0 opcode 0x2016 len 0
00> [00:01:02.727,142] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2032 param_len 7
00> [00:01:02.727,172] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2000cba0
00> [00:01:02.727,203] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2000cba0 opcode 0x2032 len 10
00> [00:01:02.727,294] <dbg> bt_hci_core: process_events: count 3
00> [00:01:02.727,325] <dbg> bt_hci_core: process_events: ev->state 4
00> [00:01:02.727,325] <dbg> bt_hci_core: send_cmd: calling net_buf_get
00> [00:01:02.727,386] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
00> [00:01:02.727,416] <dbg> bt_hci_core: send_cmd: Sending command 0x2032 (buf 0x2000cba0) to driver
00> [00:01:02.727,416] <dbg> bt_hci_core: bt_send: buf 0x2000cba0 len 10 type 0
00> [00:01:02.727,539] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:02.727,539] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:02.727,630] <dbg> bt_hci_core: bt_recv: buf 0x2000cba0 len 6
00> [00:01:02.727,661] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2032
00> [00:01:02.727,661] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2032 status 0x00 buf 0x2000cba0
00> [00:01:02.727,935] <dbg> bt_conn: bt_conn_prepare_events: bt_conn_prepare_events
00> [00:01:02.727,996] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20005870 to poll list
00> [00:01:02.728,027] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
00> [00:01:02.728,057] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2000cba0 opcode 0x2032 len 0
00> [00:01:02.728,149] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:01:06.699,066] <dbg> bt_hci_core: bt_recv: buf 0x2000ca18 len 7
00> [00:01:06.699,096] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
00> [00:01:06.699,127] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
00> [00:01:06.699,127] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:01:06.699,340] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:01:06.943,115] <dbg> bt_hci_core: bt_recv: buf 0x2000ca88 len 15
00> [00:01:06.943,389] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
00> [00:01:06.943,450] <dbg> bt_hci_core: rx_work_handler: buf 0x2000ca88 type 3 len 15
00> [00:01:06.943,450] <dbg> bt_hci_core: hci_acl: buf 0x2000ca88
00> [00:01:06.943,481] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
00> [00:01:06.943,511] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:01:06.943,572] <dbg> bt_conn: tx_notify: conn 0x20005870
00> [00:01:06.943,603] <dbg> bt_conn: bt_conn_recv: handle 0 len 11 flags 02
00> [00:01:06.943,603] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
00> [00:01:06.943,634] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L
00> [00:01:10.160,369] <dbg> bt_hci_core: bt_recv: buf 0x2000ca88 len 15
00> [00:01:10.160,827] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
00> [00:01:10.160,827] <dbg> bt_hci_core: rx_work_handler: buf 0x2000ca88 type 3 len 15
00> [00:01:10.160,888] <dbg> bt_hci_core: hci_acl: buf 0x2000ca88
00> [00:01:10.160,919] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
00> [00:01:10.160,919] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:01:10.160,949] <dbg> bt_conn: tx_notify: conn 0x20005870
00> [00:01:10.160,949] <dbg> bt_conn: bt_conn_recv: handle 0 len 11 flags 02
00> [00:01:10.161,010] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
00> [00:01:10.161,041] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
00> [00:01:10.161,041] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 6 len 7
00> [00:01:10.161,071] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20005b2c len 7
00> [00:01:10.161,132] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x01 len 6
00> [00:01:10.161,163] <dbg> bt_smp: smp_pairing_req: smp_pairing_req
00> [00:01:10.161,163] <dbg> bt_smp: smp_pairing_req: smp_pairing_req #2
00> [00:01:10.161,193] <dbg> bt_smp: smp_pairing_req: smp_pairing_req #3
00> [00:01:10.161,224] <dbg> bt_smp: smp_pairing_req: smp_pairing_req #4
00> [00:01:10.161,285] <dbg> bt_smp: smp_pairing_req: smp_pairing_req #5
00> [00:01:10.161,285] <dbg> bt_smp: smp_pairing_req: smp_pairing_req #6
00> [00:01:10.161,285] <dbg> bt_smp: smp_pairing_req: smp_pairing_req #7
00> [00:01:10.161,315] <dbg> bt_smp: send_pairing_rsp: send_pairing_rsp enter
00> [00:01:10.161,376] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20005870 cid 6 len 7
00> [00:01:10.161,407] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 11 cb (nil) user_data (nil)
00> [00:01:10.161,437] <dbg> bt_smp: send_pairing_rsp: send_pairing_rsp exit
00> [00:01:10.161,529] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:01:10.161,560] <dbg> bt_hci_core: process_events: count 3
00> [00:01:10.161,560] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:10.161,621] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:10.161,651] <dbg> bt_hci_core: process_events: ev->state 4
00> [00:01:10.161,651] <dbg> bt_conn: bt_conn_process_tx: conn 0x20005870
00> [00:01:10.161,682] <dbg> bt_conn: send_buf: conn 0x20005870 buf 0x2000cbd8 len 11
00> [00:01:10.161,712] <dbg> bt_conn: send_frag: conn 0x20005870 buf 0x2000cbd8 len 11 flags 0x02
00> [00:01:10.161,773] <dbg> bt_hci_core: bt_send: buf 0x2000cbd8 len 15 type 2
00> [00:01:10.161,865] <dbg> bt_conn: bt_conn_prepare_events: bt_conn_prepare_events
00> [00:01:10.161,895] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20005870 to poll list
00> [00:01:10.161,895] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
00> [00:01:11.915,283] <dbg> bt_hci_core: bt_recv: buf 0x2000ca18 len 7
00> [00:01:11.915,313] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
00> [00:01:11.915,466] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
00> [00:01:11.915,496] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:01:11.915,527] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:01:11.915,771] <dbg> bt_hci_core: bt_recv: buf 0x2000ca88 len 6
00> [00:01:11.915,771] <dbg> bt_hci_core: hci_disconn_complete_prio: hci_disconn_complete_prio status 0x00 handle 0 reason 0x28
00> [00:01:11.915,832] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:01:11.915,863] <dbg> bt_conn: bt_conn_set_state: connected -> disconnect-complete
00> [00:01:11.915,893] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:01:11.916,137] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
00> [00:01:11.916,229] <dbg> bt_hci_core: rx_work_handler: buf 0x2000ca88 type 1 len 6
00> [00:01:11.916,229] <dbg> bt_hci_core: hci_event: event 0x05
00> [00:01:11.916,259] <dbg> bt_hci_core: hci_disconn_complete: status 0x00 handle 0 reason 0x28
00> [00:01:11.916,259] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:01:11.916,320] <dbg> bt_conn: bt_conn_set_state: disconnect-complete -> disconnected
00> [00:01:11.916,351] <dbg> bt_conn: tx_notify: conn 0x20005870
00> [00:01:11.916,381] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:01:11.916,473] <dbg> bt_hci_core: process_events: count 3
00> [00:01:11.916,503] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:11.916,503] <dbg> bt_hci_core: process_events: ev->state 1
00> [00:01:11.916,503] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:11.916,595] <dbg> bt_conn: bt_conn_prepare_events: bt_conn_prepare_events
00> [00:01:11.916,625] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
00> [00:01:11.916,717] <dbg> bt_conn: deferred_work: conn 0x20005870
00> [00:01:11.916,748] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x20005870 chan 0x20006174
00> [00:01:11.916,748] <dbg> bt_l2cap: l2cap_disconnected: ch 0x20006174 cid 0x0005
00> [00:01:11.916,809] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x20005870 chan 0x20005b2c
00> [00:01:11.916,839] <dbg> bt_smp: bt_smp_disconnected: bt_smp_disconnected chan 0x20005b2c cid 0x0006
00> [00:01:11.916,839] <dbg> bt_smp: smp_pairing_complete: smp.c 1863 status 0x8
00> [00:01:11.917,083] <dbg> bt_keys: bt_keys_clear: 47:95:91:6C:DF:D7 (random) (keys 0x0000)
00> [00:01:11.917,358] <dbg> bt_keys: bt_keys_clear: Deleting key bt/keys/4795916cdfd71
00> [00:01:11.917,449] <dbg> bt_conn: bt_conn_security_changed: conn.c #1 1986 hci_err(0x1f) bt_security_err(9)
00> [00:01:11.917,480] <dbg> bt_l2cap: bt_l2cap_security_changed: l2cap.c #1 hci_status(1f)
00> [00:01:11.917,510] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x20005b2c conn 0x20005870 handle 0 encrypt 0x00 hci status 0x1f
00> [00:01:11.917,785] <wrn> peripheral_uart: Security failed: 47:95:91:6C:DF:D7 (random) level 1 err 9
00> [00:01:11.918,029] <inf> peripheral_uart: Pairing failed conn: 47:95:91:6C:DF:D7 (random), reason 9
00> [00:01:11.918,273] <dbg> bt_keys: bt_keys_clear: 00:00:00:00:00:00 (public) (keys 0x0000)
00> [00:01:11.918,518] <dbg> bt_keys: bt_keys_clear: Deleting key bt/keys/0000000000000
00> [00:01:11.918,670] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x20005870 chan 0x2000c124
00> [00:01:11.919,006] <dbg> bt_keys: bt_keys_find_addr: 47:95:91:6C:DF:D7 (random)
00> [00:01:11.919,250] <dbg> bt_keys: bt_keys_find_addr: 47:95:91:6C:DF:D7 (random)
00> [00:01:11.919,525] <inf> peripheral_uart: Disconnected: 47:95:91:6C:DF:D7 (random) (reason 40)
00> [00:01:11.919,525] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
00> [00:01:11.919,555] <dbg> bt_conn: bt_conn_unref: handle 0 ref 1 -> 0
00> [00:01:11.919,616] <dbg> bt_conn: bt_conn_unref: -bt_le_adv_resume
00> [00:01:11.919,677] <dbg> bt_conn: bt_conn_set_state: disconnected -> connecting-adv
00> [00:01:11.919,677] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
00> [00:01:11.919,738] <dbg> bt_adv: bt_le_adv_resume: Resuming connectable advertising
00> [00:01:11.919,769] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x200a param_len 1
00> [00:01:11.919,799] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2000cba0
00> [00:01:11.919,799] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2000cba0 opcode 0x200a len 4
00> [00:01:11.919,921] <dbg> bt_hci_core: process_events: count 2
00> [00:01:11.919,921] <dbg> bt_hci_core: process_events: ev->state 4
00> [00:01:11.919,982] <dbg> bt_hci_core: send_cmd: calling net_buf_get
00> [00:01:11.920,013] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
00> [00:01:11.920,013] <dbg> bt_hci_core: send_cmd: Sending command 0x200a (buf 0x2000cba0) to driver
00> [00:01:11.920,043] <dbg> bt_hci_core: bt_send: buf 0x2000cba0 len 4 type 0
00> [00:01:11.920,288] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:11.920,379] <dbg> bt_hci_core: bt_recv: buf 0x2000cba0 len 6
00> [00:01:11.920,410] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x200a
00> [00:01:11.920,410] <dbg> bt_hci_core: hci_cmd_done: opcode 0x200a status 0x00 buf 0x2000cba0
00> [00:01:11.920,715] <dbg> bt_conn: bt_conn_prepare_events: bt_conn_prepare_events
00> [00:01:11.920,745] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
00> [00:01:11.920,776] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2000cba0 opcode 0x200a len 1
00> [00:01:11.920,837] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1

It seems Pairing response was sent but Android did not receive it.
Can you please review rtt log?

[Hieu]

Hi Tim,

Tim Hwang said:

1. NFC
I could reproduce this issue without NFC tagging. Let's discuss later. It is not root reason; I think.

You misunderstood. I mentioned NFC as an example of an out-of-band (OOB) verification method. NFC should not be the problem here.

Tim Hwang said:

If Key exchange is a matter, we always see this issue. But it is not. What do you think about that?

The problem is exactly that: I don't know what to think about that.

Please take a look back at your videos. What I see are

- Incorrect passkey error message from the "not-good" video.
- Passkey pop-up in the "okay" video
- Very short time between passkey pop-up and the connection is made in the "okay" video. Too short for actual passkey to be entered by a normal human.

The combination of those makes no sense at all.

That is why I hope a sniffer log containing the encrypted pairing packets would help me see what is wrong here.

I might guess that your Android device asks for passkey, but doesn't handle the passkey well, sometime consider "no" passkey as good, sometime doesn't. Without a sniffer, I can't be sure.

Therefore, if possible, please look into getting me that sniffer log with the pairing procedure. Preferably one of a success case, and one of a failure case.

I will look at your RTT log Tue and Wed. Unfortunately, I am partially out of office both days, so my follow-up might be delayed until end of Thursday.

Best regards,

Hieu 

[Tim Hwang]

Hello. 

1. ...How do you enter the passkey in your device?...
device (Nordic BLE) already disconnected before BLE(Nordic) have chance to check passkey.

2. RTT log: new log
00> [00:00:12.557,952] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2000cba0 opcode 0x2032 len 0
00> [00:00:12.557,952] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:00:17.624,084] <dbg> sdc_hci_driver: event_packet_process: Event (0x05) len 4
00> [00:00:17.624,176] <dbg> bt_hci_core: bt_recv: buf 0x2000ca88 len 6

hci.h

I think I found reason of hci status value 0x1f.

"Event (0x05)" in HCI log means that BT_HCI_EVT_DISCONN_COMPLETE.
What kind of this disconnection? It seems it is link loss timeout (12.557 ~ 17.624).
In my test, many of failure case had around 5 seconds delay.

How can we know about that? What is your opinion?

[Hieu]

Hi Tim,

Regarding the long RTT Log posted on 7 Nov, here are what I found:

00> [00:01:11.915,771] <dbg> bt_hci_core: hci_disconn_complete_prio: hci_disconn_complete_prio status 0x00 handle 0 reason 0x28
...
00> [00:01:11.916,229] <dbg> bt_hci_core: hci_event: event 0x05
00> [00:01:11.916,259] <dbg> bt_hci_core: hci_disconn_complete: status 0x00 handle 0 reason 0x28

These lines indicate that the connection was terminated with reason 0x28, which is BLE_HCI_INSTANT_PASSED.
This means some time sensitive event didn't happen when it should. There are many root causes. Some possible ones are too much radio-noises or logging too much.

00> [00:01:11.917,785] <wrn> peripheral_uart: Security failed: 47:95:91:6C:DF:D7 (random) level 1 err 9
00> [00:01:11.918,029] <inf> peripheral_uart: Pairing failed conn: 47:95:91:6C:DF:D7 (random), reason 9

These lines indicate that Pairing/Security failed with reason 9, which is BT_SECURITY_ERR_UNSPECIFIED.
The error code means that Security did not fail due to any of these reasons:

	/** Authentication failed. */
	BT_SECURITY_ERR_AUTH_FAIL,

	/** PIN or encryption key is missing. */
	BT_SECURITY_ERR_PIN_OR_KEY_MISSING,

	/** OOB data is not available.  */
	BT_SECURITY_ERR_OOB_NOT_AVAILABLE,

	/** The requested security level could not be reached. */
	BT_SECURITY_ERR_AUTH_REQUIREMENT,

	/** Pairing is not supported */
	BT_SECURITY_ERR_PAIR_NOT_SUPPORTED,

	/** Pairing is not allowed. */
	BT_SECURITY_ERR_PAIR_NOT_ALLOWED,

	/** Invalid parameters. */
	BT_SECURITY_ERR_INVALID_PARAM,

	/** Distributed Key Rejected */
	BT_SECURITY_ERR_KEY_REJECTED,

The above symptoms and diagnoses also match quite well with your 8 Nov comment.

Overall, what I derived are:
- Some key time-sensitive packet missed its "instant" and the pairing process failed.

- BLE_HCI_INSTANT_PASSED is pretty rare in development environment, where the devices in a connection are usually physically close. If possible, please observe several more reproduction of the issue to see if the same disconnection reason happens.

- If BLE_HCI_INSTANT_PASSED happens consistently, at least one sniffer log with the pairing procedure, preferably two or three logs, are required to pinpoint the exact problem.

- A sniffer log captured when the device RTT log is turned down to normal (info) level is also helpful (to rule out the possibility that the log processing caused the timing issue).

[Hieu]

P.s: Could you also try using the nRF Connect app to perform the pairing? The app can produce some potentially helpful logs from the phone side.

[Tim Hwang]

Thanks for updating.
I'll upload the nRF Connect app log as soon as it is ready.

[Hieu]

Just in case, you also saw my longer reply where I ask if you can see if more reproductions of the issues result in the same disconnect reason 0x28, and where I asked for the sniffer trace again, right?

[Tim Hwang]

1. nRF Connect app log

nRF Connect, 2022-11-14
Nordic_UART_Service (00:16:7F:11:22:36)
V	14:27:21.563	Connecting to 00:16:7F:11:22:36...
D	14:27:21.564	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	14:27:22.357	[Callback] Connection state changed with status: 133 and new state: DISCONNECTED (0)
E	14:27:22.357	Error 133 (0x85): GATT ERROR
I	14:27:22.357	Disconnected

2. 
Just in case, you also saw my longer reply where I ask if you can see if more reproductions of the issues result in the same disconnect reason 0x28, and where I asked for the sniffer trace again, right?
-> Can you please explain your mention? 
I repeated this test and found reason was 0x5 or 0x28. 

[Hieu]

Hi Tim,

Regarding your nRF Connect app log

As you can see, in the log, the connection didn't even happen successfully. So that log shows an entirely new kind of failure compared to the ones you have shown me...

For your reference of what normal looks like, here are a few logs I quickly created myself. Just my Android phone, and a peripheral_uart sample modified just like you described.

Fullscreen c297913_android_pairing_successful_221114_01.txt Download

nRF Connect, 2022-11-14
hivo c297913 (FF:26:0E:1A:CB:4D)
D	13:17:09.449	gatt.close()
D	13:17:09.454	wait(200)
V	13:17:09.657	Connecting to FF:26:0E:1A:CB:4D...
D	13:17:09.658	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	13:17:11.814	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	13:17:11.841	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	13:17:11.841	Connected to FF:26:0E:1A:CB:4D
V	13:17:11.846	Discovering services...
D	13:17:11.846	gatt.discoverServices()
I	13:17:12.107	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	13:17:12.172	PHY updated (TX: LE 2M, RX: LE 2M)
D	13:17:12.492	[Callback] Services discovered with status: 0
I	13:17:12.492	Services discovered
V	13:17:12.498	Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
   Client Characteristic Configuration (0x2902)
- Client Supported Features [R W] (0x2B29)
- Database Hash [R] (0x2B2A)
Generic Access (0x1800)
- Device Name [R] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
Nordic UART Service (6e400001-b5a3-f393-e0a9-e50e24dcca9e)
- TX Characteristic [N] (6e400003-b5a3-f393-e0a9-e50e24dcca9e)
   Client Characteristic Configuration (0x2902)
- RX Characteristic [W WNR] (6e400002-b5a3-f393-e0a9-e50e24dcca9e)
D	13:17:12.498	gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
D	13:17:12.505	gatt.setCharacteristicNotification(6e400003-b5a3-f393-e0a9-e50e24dcca9e, true)
I	13:17:12.605	Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 5000ms)
D	13:17:12.651	[Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDING (11)
D	13:17:12.675	[Broadcast] Action received: android.bluetooth.device.action.PAIRING_REQUEST, pairing variant: PAIRING_VARIANT_CONSENT (3)
D	13:17:14.703	[Broadcast] Action received: android.bluetooth.device.action.PAIRING_REQUEST, pairing variant: PAIRING_VARIANT_PASSKEY_CONFIRMATION (2)
I	13:17:16.945	Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 420ms)
D	13:17:21.645	[Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDED (12)
I	13:17:21.647	Device bonded

Fullscreen c297913_rtt_pairing_timeout_221114_01.txt Download

SEGGER J-Link V7.70d - Real time terminal output
J-Link OB-SAM3U128-V2-NordicSemi compiled Jan 20 2022 16:43:31 V1.0, SN=683326383
Process: JLink.exe
[00:00:00.000,183] <dbg> bt_hci_core: bt_hci_driver_register: Registered SoftDevice Controller
--- 471 messages dropped ---
[00:00:00.057,525] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20008f6c
[00:00:00.057,617] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x20008f6c opcode 0x200a len 4
[00:00:00.057,647] <dbg> bt_hci_core: process_events: count 2
[00:00:00.057,739] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:00.057,769] <dbg> bt_hci_core: send_cmd: calling net_buf_get
[00:00:00.057,769] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
[00:00:00.057,861] <dbg> bt_hci_core: send_cmd: Sending command 0x200a (buf 0x20008f6c) to driver
[00:00:00.057,891] <dbg> bt_hci_core: bt_send: buf 0x20008f6c len 4 type 0
[00:00:00.057,891] <dbg> sdc_hci_driver: hci_driver_send: 
[00:00:00.057,983] <dbg> sdc_hci_driver: cmd_handle: 
[00:00:00.058,258] <dbg> sdc_hci_driver: hci_driver_send: Ex0m
[00:00:09.221,893] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2016 status 0x00 buf 0x20008f6c
--- 46 messages dropped ---
[00:00:09.222,259] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:09.222,259] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:09.222,290] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:09.222,381] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20008f6c opcode 0x2016 len 0
[00:00:09.222,412] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2032 param_len 7
[00:00:09.222,503] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20008f6c
[00:00:09.222,534] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x20008f6c opcode 0x2032 len 10
[00:00:09.222,656] <dbg> bt_hci_core: process_events: count 3
[00:00:09.222,717] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:09.222,747] <dbg> bt_hci_core: send_cmd: calling net_buf_get
[00:00:09.222,778] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
[00:00:09.222,778] <dbg> bt_hci_core: send_cmd: Sending command 0x2032 (buf 0x20008f6c) to driver
[00:00:09.222,869] <dbg> bt_hci_core: bt_send: buf 0x20008f6c len 10 type 0
[00:00:09.222,900] <dbg> sdc_hci_driver: hci0m
[00:00:09.222,900] <dbg> sdc_hci_driver: cmd_handle: 
[00:00:09.223,022] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:09.223,114] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:09.223,114] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:09.223,236] <dbg> sdc_hci_driver: event_packet_process: Command Status (0x2032) status: 0x00
[00:00:09.223,266] <dbg> bt_hci_core: bt_recv: buf 0x20008f6c len 6
[00:00:09.223,327] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2032
[00:00:09.223,358] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2032 status 0x00 buf 0x20008f6c
[00:00:09.223,724] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:09.223,754] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:09.223,815] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:09.223,876] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20008f6c opcode 0x2032 len 0
[00:00:09.443,450] <dbg> bt_conn: tx_notify: conn 0x20001e88
--- 7 messages dropped ---
[00:00:09.443,450] <dbg> bt_conn: bt_conn_recv: handle 0 len 11 flags 02
[00:00:09.443,542] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:00:09.443,542] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:09.443,572] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
[00:00:09.443,664] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
[00:00:09.443,664] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:09.443,786] <dbg> bt_att: att_read_type_req: start_handle 0x0001 end_handle 0xffff type 2b3a
[00:00:09.444,030] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x01
[00:00:09.444,030] <dbg> bt_att: chan_send: code 0x01
[00:00:09.444,061] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 5
[00:00:09.444,061] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 9 cb 0x2407d user_data 0x20008184
[00:00:09.444,183] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:09.444,274] <dbg> bt_hci_core: process_events: count 3
[00:00:09.444,274] <dbg> bt_hci_core: process_events: ev->st
[00:00:09.444,488] <dbg> bt_hci_core: bt_send: buf 0x20009030 len 13 type 2
[00:00:09.444,519] <dbg> sdc_hci_driver: hci_driver_send: 
[00:00:09.444,549] <dbg> sdc_hci_driver: acl_handle: 
[00:00:09.444,671] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:09.444,732] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:09.444,763] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:09.444,793] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:09.483,032] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x04), len (12)
[00:00:09.483,062] <dbg> bt_hci_core: bt_recv: buf 0x20008b78 len 14
[00:00:09.483,459] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:09.483,459] <dbg> bt_hci_core: rx_work_handler: buf 0x20008b78 type 1 len 14
[00:00:09.483,520] <dbg> bt_hci_core: hci_event: event 0x3e
[00:00:09.483,551] <dbg> bt_ype 2800
--- 25 messages dropped ---
[00:00:09.524,322] <dbg> bt_att: read_group_cb: handle 0x0001
[00:00:09.524,414] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 2
[00:00:09.524,505] <dbg> bt_att: read_group_cb: handle 0x0009
[00:00:09.524,536] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 2
[00:00:09.524,627] <dbg> bt_att: read_group_cb: handle 0x0010
[00:00:09.524,658] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 5
[00:00:09.524,688] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x11
[00:00:09.524,749] <dbg> bt_att: chan_send: code 0x11
[00:00:09.524,780] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 14
[00:00:09.524,810] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 18 cb 0x2407d user_data 0x20008184
[00:00:09.524,932] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:09.525,024] <dbg> bt_hci_core: process_events: count 3
[00:00:09.525,024] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:09.525,054] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:09.525,11ate 4
[00:00:09.525,146] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:09.525,177] <dbg> bt_conn: send_buf: conn 0x20001e88 buf 0x20009030 len 18
[00:00:09.525,177] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009030 len 18 flags 0x02
[00:00:09.525,268] <dbg> bt_hci_core: bt_send: buf 0x20009030 len 22 type 2
[00:00:09.525,299] <dbg> sdc_hci_driver: hci_driver_send: 
[00:00:09.525,299] <dbg> sdc_hci_driver: acl_handle: 
[00:00:09.525,421] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:09.525,512] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:09.525,543] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:09.525,543] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:09.525,665] <dbg> bt_conn: tx_complete_work: conn 0x20001e88
[00:00:09.525,726] <dbg> bt_conn: tx_notify: conn 0x20001e88
[00:00:09.604,858] <dbg> bt_att: chan_send: code 0x11
--- 31 messages dropped ---
[00:00:09.604,858] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 22
[00:00:09.604,949] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 26 cb 0x2407d user_data 0x20008184
[00:00:09.605,072] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:09.605,102] <dbg> bt_hci_core: process_events: count 3
[00:00:09.605,194] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:09.605,224] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:09.605,224] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:09.605,316] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:09.605,316] <dbg> bt_conn: send_buf: conn 0x20001e88 buf 0x20009030 len 26
[00:00:09.605,346] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009030 len 26 flags 0x02
[00:00:09.605,438] <dbg> bt_hci_core: bt_send: buf 0x20009030 len 30 type 2
[00:00:09.605,438] <dbg> sdc_hci_driver: hci_driver_send: 
[00:00:09.605,468] <dbg> sdc_hci_driver: acl_handle: 
[00:00:09.605,590] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:09.605,682] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:09.605,682] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:09.605,712] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
--- 30 messages dropped ---
[00:00:09.652,770] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:09.652,862] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
--- 45 messages dropped ---
[00:00:09.667,968] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:09.668,060] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
[00:00:09.668,090] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
[00:00:09.668,090] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:09.668,212] <dbg> bt_att: att_read_type_req: start_handle 0x0001 end_handle 0x0008 type 2802
--- 46 messages dropped ---
[00:00:09.683,197] <dbg> bt_att: att_read_type_req: start_handle 0x0001 end_handle 0x0008 type 2803
[00:00:09.683,319] <dbg> bt_att: read_type_cb: handle 0x0002
[00:00:09.683,380] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 5
[00:00:09.683,441] <dbg> bt_att: read_type_cb: handle 0x0005
[00:00:09.683,502] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 5
att: chan_send: code 0x09
--- 49 messages dropped ---
[00:00:09.713,226] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:09.713,256] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
[00:00:09.713,287] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
[00:00:09.713,348] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:09.713,470] <dbg> bt_att: att_read_type_req: start_handle 0x0008 end_handle 0x0008 type 2803
[00:00:09.713,623] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x01
[00:00:09.713,653] <dbg> bt_att: chan_send: code 0x01
[00:00:09.713,653] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 5
--- 40 messages dropped ---
[00:00:09.727,996] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 5
[00:00:09.727,996] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 5
[00:00:09.728,080m
--- 45 messages dropped ---
[00:00:09.743,011] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
--- 49 messages dropped ---
[00:00:09.772,827] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
--- 48 messages dropped ---
[00:00:09.772,888] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
[00:00:09.772,918] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:09.773,040] <dbg> bt_att: att_read_type_req: start_handle 0x000d end_handle 0x000f type 2803
[00:00:09.773,162] <dbg> bt_att: read_type_cb: handle 0x000e
[00:00:09.773,193] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 5
[00:00:09.773,284] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x09
[00:00:09.773,284] <dbg> bt_att: chan_send: code 0x09
[00:00:09.773,315] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 9
[00:00:09.773,376] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 13 cb 0x2407d user_data 0x20008184
[00:00:09.773,437] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:09.773,529] <dbg> bt_hci_core: process_events: count 3
--- 37 messages dropped ---
[00:00:09.787,780] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
[00:00:09.787,811] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
[00:00:09.787,841] <dbg> bt_att: bt_att_recv5] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
--- 48 messages dropped ---
[00:00:09.817,932] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
[00:00:09.817,962] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:09.818,084] <dbg> bt_att: att_read_type_req: start_handle 0x0010 end_handle 0x0015 type 2803
[00:00:09.818,176] <dbg> bt_att: read_type_cb: handle 0x0011
[00:00:09.818,206] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 19
[00:00:09.818,298] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x09
[00:00:09.818,328] <dbg> bt_att: chan_send: code 0x09
--- 42 messages dropped ---
[00:00:09.832,977] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
[00:00:09.833,007] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:09.833,129] <dbg> bt_att: att_read_type_req: start_handle 0x0012 end_handle 0x0015 type 2803
[00:00:09.833,251] <dbg> bt_att: read_type_cb: handle 0x0014
--- 44 messages dropped ---
[00:00:09.847,839] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
[00:00:09.847,900] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
[00:00:09.847,930] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:09.848,052] <dbg> bt_att: att_read_type_req: start_handle 0x0015 end_handle 0x0015 type 2803
[00:00:09.848,205] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x01
[00:00:09.848,236] <dbg> bt_att: chan_send: code 0x01
--- 42 messages dropped ---
[00:00:09.863,525] <dbg> bt_hci_core: process_events: ev->state 0
--- 10 messages dropped ---
[00:00:09.863,616] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:09.863,616] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:09.863,647] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:09.863,708] <dbg> bt_conn: send_buf: conn 0x20001e88 buf 0x20009030 len 10
[00:00:09.863,739] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009030 len 10 flags 0x02
[00:00:09.863,769] <dbg> bt_hci_core: bt_send: buf 0x20009030 len 14 type 2
[00:00:09.863,830] <dbg> sdc_hci_driver: hci_driver_send: 
[00:00:09.863,861] <dbg> sdc_hci_driver: acl_handle: 
[00:00:09.863,983] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:09.864,013] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:09.864,074] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e80m
[00:00:09.864,105] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:09.864,227] <dbg> bt_conn: tx_complete_work: conn 0x20001e88
[00:00:09.864,257] <dbg> bt_conn: tx_notify: conn 0x20001e88
[00:00:09.876,556] <dbg> sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:09.876,586] <dbg> bt_hci_core: bt_recv: buf 0x20008a78 len 7
[00:00:09.876,586] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:09.876,678] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:09.876,708] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:09.876,800] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:09.877,166] <dbg> bt_conn: tx_complete_work: conn 0x20001e88
[00:00:09.877,197] <dbg> bt_conn: tx_notify: conn 0x20001e88
[00:00:09.877,197] <dbg> bt_conn: tx_notify: tx 0x20002fe0 cb 0x2407d user_data 0x20008184
[00:00:09.877,288] <dbg> bt_att: att_rsp_sent: conn 0x20001e88 chan 0x20008180
[00:00:09.877,288] <dbg> bt_att: att_sent: conn 0x20001e88 chan 0x20008184
[00:00:09.877,319] <dbg> bt_att: bt_att_sent: chan 0x20008180
[00:00:09.877,380] <dbg> bt_att: chan_rsp_sent: chan 0x20008180
[00:00:09.929,229] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x03), len (10)
[00:00:09.929,321] <dbg> bt_hci_core: bt_recv: buf 0x20008b78 len 12
[00:00:09.929,687] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:09.929,718] <dbg> bt_hci_core: rx_work_handler: buf 0x20008b78 type 1 len 12
[00:00:09.929,779] <dbg> bt_hci_core: hci_event: event 0x3e
[00:00:09.929,809] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x03
[00:00:09.929,840] <dbg> bt_hci_core: le_conn_update_complete: status 0x00, handle 0
[00:00:09.929,840] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:09.929,931] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:10.060,211] <dbg> bt_smp: smp_send_security_req: 
[00:00:10.060,546] <dbg> bt_keys: bt_keys_get_addr: 4A:FF:9E:CC:4F:50 (random)
[00:00:10.060,821] <dbg> bt_keys: bt_keys_get_addr: created 0x20003108 for 4A:FF:9E:CC:4F:50 (random)
[00:00:10.061,431] <dbg> bt_smp: smp_init: prnd 8ad309c0da9c019cfa363a2a48af3252
[00:00:10.061,553] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 6 len 2
[00:00:10.061,584] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 6 cb (nil) user_data (nil)
[00:00:10.061,676] <dbg> bt_hci_core: process_events: count 3
[00:00:10.061,676] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:10.061,767] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:10.061,767] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:10.061,798] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:10.061,889] <dbg> bt_conn: send_buf: conn 0x20001e88 buf 0x20009030 len 6
[00:00:10.061,889] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009030 len 6 flags 0x02
[00:00:10.061,92[00:00:10.122,802] <dbg> sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:10.122,833] <dbg> bt_hci_core: bt_recv: buf 0x20008a78 len 7
[00:00:10.122,863] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:10.122,894] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:10.122,894] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:10.122,985] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:12.403,503] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
--- 5 messages dropped ---
[00:00:12.403,533] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:12.403,533] <dbg> bt_conn: tx_notify: conn 0x20001e88
[00:00:12.403,594] <dbg> bt_conn: bt_conn_recv: handle 0 len 11 flags 02
[00:00:12.403,625] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:00:12.403,625] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:12.403,717] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 6 len 7
[00:00:12.403,747] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20002144 len 7
[00:00:12.403,747] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x01 len 6
[00:00:12.403,778] <dbg> bt_smp: smp_pairing_req: 
[00:00:12.403,869] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 6 len 7
[00:00:12.403,900] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 11 cb (nil) user_data (nil)
[00:00:12.403,991] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:12.404,083] <dbg> bt_hci_core: process_events: count 3
[00:00:12.404,113] <dbg> bt_hci_core: proces[0m
[00:00:12.404,357] <dbg> sdc_hci_driver: hci_driver_send: 
[00:00:12.404,357] <dbg> sdc_hci_driver: acl_handle: 
[00:00:12.404,479] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:12.404,510] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:12.404,571] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:12.404,602] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:12.491,577] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
--- 95 messages dropped ---
[00:00:12.523,254] <dbg> sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:12.523,345] <dbg> bt_hci_core: bt_recv: buf 0x20008a78 len 7
[00:00:12.523,468] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:12.523,498] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:12.523,529] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:12.523,681] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:12.524,230] <dbg> sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:12.524,261] <dbg> bt_hci_core: bt_recv: buf 0x20008a78 len 7
[00:00:12.524,353] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:12.524,353] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:12.524,383] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:12.524,475] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:12.524,780] <dbg> bt_hci_core: bt_send: buf 0x20009048 len 25 type 2
[00:00:12.524,841] <dbg> sdc_hci_driver: hci_driver_send: 
[00:00:12.524,841] <dbg> sdc_hci_driver: acl_handle: 
[00:00:12.524,963] <dbg> sdc_hci_driver: hciit: 0
[00:00:12.524,993] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:12.525,085] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:12.525,085] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:12.539,154] <dbg> bt_hci_core: bt_recv: buf 0x20008b78 len 36
[00:00:12.539,276] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:12.539,276] <dbg> bt_hci_core: rx_work_handler: buf 0x20008b78 type 1 len 36
[00:00:12.539,367] <dbg> bt_hci_core: hci_event: event 0x3e
[00:00:12.539,398] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x09
[00:00:12.539,398] <dbg> bt_ecc: bt_hci_evt_le_dhkey_complete: status: 0x00
[00:00:12.539,489] <dbg> bt_smp: bt_smp_dhkey_ready: 0x20008c94
--- 30 messages dropped ---
[00:00:12.604,522] <dbg> bt_smp: smp_g2: y 8ad309c0da9c019cfa363a2a48af3252
[00:00:12.606,597] <dbg> bt_smp: smp_g2: res 0a8ff4536ff47f3c7eabe45bdaa4775f
[00:00:12.606,628] <dbg> bt_smp: smp_g2: passkey 211551
[00:00:12.606,689] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:12.606,994] <inf> peripheral_uart: Passkey for 4A:FF:9E:CC:4F:50 (random): 211551
[00:00:12.606,994] <inf> peripheral_uart: Press Button 1 to confirm, Button 2 to reject.
[00:00:12.607,086] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 6 len 17
[00:00:12.607,116] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 21 cb (nil) user_data (nil)
[00:00:12.607,238] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:12.607,330] <dbg> bt_hci_core: process_events: count 3
[00:00:12.607,360] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:12.607,360] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:12.607,452] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:12.607,452] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:12.607,543] <dbg> bt_conn: send_buf: conn 0x20001e88 buf 0x20009048 len 21
[00:00:12.607,574] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009048 len 21 flags 0x02
[00:00:12.607,604] <dbg> bt_hci_core: bt_send: buf 0x20009048 len 25 type 2
[00:00:12.607,604] <dbg> sdc_hci_driver: hci_driver_send: 
[00:00:12.607,696] <dbg> sdc_hci_driver: acl_handle: 
[00:00:12.607,727] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:12.607,818] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:12.607,849] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:12.607,849] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:12.683,013] <dbg> sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:12.683,044] <dbg> bt_hci_core: bt_recv: buf 0x20008a78 len 7
[00:00:12.683,135] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:12.683,135] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:12.683,166] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:12.683,227] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:14.219,940] <dbg> bt_conn: deferred_work: conn 0x20001e88
[00:00:14.220,031] <dbg> bt_conn: send_conn_le_param_update: conn 0x20001e88 features 0x2d params (24-40 0 42)
[00:00:14.220,062] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 5 len 12
[00:00:14.220,062] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 16 cb (nil) user_data (nil)
[00:00:14.220,184] <dbg> bt_hci_core: process_events: count 3
[00:00:14.220,245] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:14.220,275] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:14.220,275] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:14.220,306] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:14.220,306] <dbg> bt_conn: send_buf: conn 0x20001e88 buf 0x20009048 len 16
[00:00:14.220,397] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009048 len 16 flags 0x02
[00:00:14.220,428] <dbg> bt_hci_core: bt_send: buf 0x20009048 len 20 type 2
[00:00:14.220,489] <dbg> sdc_hci_driver: hci_driver_send: 
[00:00:14.220,520] <dbg> sdc_hci_driver: acl_handle: 
[00:00:14.220,611] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:14.220,642] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:14.220,672] <dbg> bt_conn: conn_prepa[00:00:14.282,745] <dbg> sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:14.282,989] <dbg> bt_hci_core: bt_recv: buf 0x20008a78 len 7
[00:00:14.283,020] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:14.283,020] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:14.283,081] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:14.283,111] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:14.323,089] <dbg> sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(10)
[00:00:14.323,150] <dbg> bt_hci_core: bt_recv: buf 0x20008b78 len 14
[00:00:14.323,455] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:14.323,455] <dbg> bt_hci_core: rx_work_handler: buf 0x20008b78 type 3 len 14
[00:00:14.323,547] <dbg> bt_hci_core: hci_acl: buf 0x20008b78
[00:00:14.323,577] <dbg> bt_hci_core: hci_acl: handle 0 len 10 flags 2
9] <dbg> bt_conn: tx_notify: conn 0x20001e88
[00:00:14.323,669] <dbg> bt_conn: bt_conn_recv: handle 0 len 10 flags 02
[00:00:14.323,699] <dbg> bt_conn: bt_acl_recv: First, len 10 final 6
[00:00:14.323,699] <dbg> bt_conn: bt_acl_recv: Successfully parsed 10 byte L2CAP packet
[00:00:14.323,760] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 5 len 6
[00:00:14.323,791] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20002ff0 len 6
[00:00:14.323,822] <dbg> bt_l2cap: l2cap_recv: Signaling code 0x13 ident 1 len 2
[00:00:14.323,822] <dbg> bt_lt 0
[00:00:14.323,913] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:14.482,971] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x03), len (10)
[00:00:14.483,062] <dbg> bt_hci_core: bt_recv: buf 0x20008b78 len 12
[00:00:14.483,459] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:14.483,459] <dbg> bt_hci_core: rx_work_handler: buf 0x20008b78 type 1 len 12
[00:00:14.483,520] <dbg> bt_hci_core: hci_event: event 0x3e
[00:00:14.483,551] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x03
[00:00:14.483,581] <dbg> bt_hci_core: le_conn_update_complete: status 0x00, handle 0
[00:00:14.483,581] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:14.483,642] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:22.522,827] <dbg> sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(21)
[00:00:22.522,918] <dbg> bt_hci_core: bt_recv: buf 0x20008b78 len 25
[00:00:22.523,193] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:22.523,284] <dbg> bt_hci_core: rx_work_handler: buf 0x20008b78 type 3 len 25
[00:00:22.523,284] <dbg> bt_hci_core: hci_acl: buf 0x20008b78
[00:00:22.523,315] <dbg> bt_hci_core: hci_acl: handle 0 len 21 flags 2
[00:00:22.523,315] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:22.523,406] <dbg> bt_conn: tx_notify: conn 0x20001e88
[00:00:22.523,406] <dbg> bt_conn: bt_conn_recv: handle 0 len 21 flags 02
[00:00:22.523,437] <dbg> bt_conn: bt_acl_recv: First, len 21 final 17
[00:00:22.523,437] <dbg> bt_conn: bt_acl_recv: Successfully parsed 21 byte L2CAP packet
[00:00:22.523,529] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 6 len 17
[00:00:22.523,559] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20002144 len 17
[00:00:22.523,559] <dbg> bt_[0m
[00:00:22.523,620] <dbg> bt_smp: smp_dhkey_check: 
[00:00:22.523,681] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:42.607,299] <err> bt_smp: SMP Timeout
[00:00:42.607,360] <dbg> bt_smp: smp_pairing_complete: status 0x8
[00:00:42.607,635] <dbg> bt_keys: bt_keys_clear: 4A:FF:9E:CC:4F:50 (random) (keys 0x0000)
[00:00:42.607,910] <dbg> bt_settings: bt_settings_encode_key: Encoded path bt/keys/4aff9ecc4f501
[00:00:42.608,001] <dbg> bt_keys: bt_keys_clear: Deleting key bt/keys/4aff9ecc4f501
[00:00:42.608,093] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x20002144 conn 0x20001e88 handle 0 encrypt 0x00 hci status 0x1f
[00:00:42.608,123] <dbg> bt_att: bt_att_encrypt_change: chan 0x20008184 conn 0x20001e88 handle 0 sec_level 0x01 status 0x1f
[00:00:42.608,398] <wrn> peripheral_uart: Security failed: 4A:FF:9E:CC:4F:50 (random) level 1 err 9
[00:00:42.608,703] <inf> peripheral_uart: Pairing failed conn: 4A:FF:9E:CC:4F:50 (random), reason 9
[00:00:55.524,353] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
--- 33 messages dropped ---
[00:00:55.524,353] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
[00:00:55.524,444] <dbg> bt_conn: bt_conn_unref: handle 0 ref 1 -> 0
[00:00:55.524,475] <dbg> bt_conn: bt_conn_set_state: disconnected -> connecting-adv
[00:00:55.524,566] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
[00:00:55.524,566] <dbg> bt_adv: bt_le_adv_resume: Resuming connectable advertising
[00:00:55.524,597] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x200a param_len 1
[00:00:55.524,688] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20008f6c
[00:00:55.524,719] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x20008f6c opcode 0x200a len 4
[00:00:55.524,841] <dbg> bt_hci_core: process_events: count 2
[00:00:55.524,841] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:55.524,932] <dbg> bt_hci_core: send_cmd: calling net_buf_get
[00:00:55.524,932] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
[00:00:55.524,963] <dbg> bt_hci_core: send_cmd: Sending command 0x200a (buf 0x20008f6c) to driver
[00:00:55.525,054] <dbg> bt_hci_core: bt_send: buf 0x20008f60m
[00:00:55.525,054] <dbg> sdc_hci_driver: hci_driver_send: 
[00:00:55.525,085] <dbg> sdc_hci_driver: cmd_handle: 
[00:00:55.525,360] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:55.525,360] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:55.525,482] <dbg> sdc_hci_driver: event_packet_process: Command Complete (0x200a) status: 0x00, ncmd: 1, len 4
[00:00:55.525,573] <dbg> bt_hci_core: bt_recv: buf 0x20008f6c len 6
[00:00:55.525,573] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x200a
[00:00:55.525,604] <dbg> bt_hci_core: hci_cmd_done: opcode 0x200a status 0x00 buf 0x20008f6c
[00:00:55.525,970] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:55.525,970] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
[00:00:55.526,092] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20008f6c opcode 0x200a len 1
[00:00:55.526,153] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1

Fullscreen c297913_rtt_pairing_successful_221114_01.txt Download

[00:00:00.000,183] <dbg> bt_hci_core: bt_hci_driver_register: Registered SoftDevice Controller
--- 469 messages dropped ---
[00:00:00.051,727] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20008f6c
[00:00:00.051,818] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x20008f6c opcode 0x200a len 4
[00:00:00.051,849] <dbg> bt_hci_core: process_events: count 2
[00:00:00.051,940] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:00.051,940] <dbg> bt_hci_core: send_cmd: calling net_buf_get
[00:00:00.051,971] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
[00:00:00.052,062] <dbg> bt_hci_core: send_cmd: Sending command 0x200a (buf 0x20008f6c) to driver
[00:00:00.052,062] <dbg> bt_hci_core: bt_send: buf 0x20008f6c len 4 type 0
[00:00:00.052,093] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:00.052,154] <dbg> sdc_hci_driver: cmd_handle:
[00:00:00.052,459] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:00.052,459] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:00.052,581] <dbg> sdc_hci_driver: event_packet_process: Command Complete (0x200a) status: 0x00, ncmd: 1, len 4
[00:00:00.052,642] <dbg> bt_hci_core: bt_recv: buf 0x20008f6c len 6
[00:00:00.052,673] <dbg> bt_hci_core: hci_cm
[00:00:00.053,039] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:00.053,070] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
[00:00:00.053,161] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20008f6c opcode 0x200a len 1
[00:00:00.053,222] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
[00:00:00.100,250] <dbg> bt_hci_core: bt_recv: buf 0x20008b78 len 68
[00:00:00.100,280] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:00.100,372] <dbg> bt_hci_core: rx_work_handler: buf 0x20008b78 type 1 len 68
[00:00:00.100,372] <dbg> bt_hci_core: hci_event: event 0x3e
[00:00:00.100,402] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x08
[00:00:00.100,463] <dbg> bt_ecc: bt_hci_evt_le_pkey_complete: status: 0x00
[00:00:00.100,494] <dbg> bt_smp: bt_smp_pkey_ready:
[00:00:16.069,305] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2016 status 0x00 buf 0x20008f6c
--- 46 messages dropped ---
[00:00:16.069,641] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:16.069,671] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:16.069,732] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:16.069,793] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20008f6c opcode 0x2016 len 0
[00:00:16.069,885] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2032 param_len 7
[00:00:16.069,915] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20008f6c
[00:00:16.069,976] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x20008f6c opcode 0x2032 len 10
[00:00:16.070,129] <dbg> bt_hci_core: process_events: count 3
[00:00:16.070,129] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:16.070,159] <dbg> bt_hci_core: send_cmd: calling net_buf_get
[00:00:16.070,190] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
[00:00:16.070,251] <dbg> bt_hci_core: send_cmd: Sending command 0x2032 (buf 0x20008f6c) to driver
[00:00:16.070,281] <dbg> bt_hci_core: bt_send: buf 0x20008f6c len 10 type 0
[00:00:16.070,281] <dbg> sdc_hci_driver: hci0m
[00:00:16.070,373] <dbg> sdc_hci_driver: cmd_handle:
[00:00:16.070,495] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:16.070,495] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:16.070,526] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:16.070,648] <dbg> sdc_hci_driver: event_packet_process: Command Status (0x2032) status: 0x00
[00:00:16.070,709] <dbg> bt_hci_core: bt_recv: buf 0x20008f6c len 6
[00:00:16.070,739] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2032
[00:00:16.070,770] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2032 status 0x00 buf 0x20008f6c
[00:00:16.071,136] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:16.071,197] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:16.071,228] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:16.071,350] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20008f6c opcode 0x2032 len 0
[00:00:16.395,385] <dbg> bt_conn: tx_notify: conn 0x20001e88
--- 7 messages dropped ---
[00:00:16.395,385] <dbg> bt_conn: bt_conn_recv: handle 0 len 11 flags 02
[00:00:16.395,416] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:00:16.395,416] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:16.395,507] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
[00:00:16.395,538] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
[00:00:16.395,538] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:16.395,660] <dbg> bt_att: att_read_type_req: start_handle 0x0001 end_handle 0xffff type 2b3a
[00:00:16.395,904] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x01
[00:00:16.395,965] <dbg> bt_att: chan_send: code 0x01
[00:00:16.395,996] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 5
[00:00:16.395,996] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 9 cb 0x2407d user_data 0x20008184
[00:00:16.396,118] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:16.396,148] <dbg> bt_hci_core: process_events: count 3
[00:00:16.396,209] <dbg> bt_hci_core: process_events: ev->state 0
ate 0
[00:00:16.396,240] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:16.396,270] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:16.396,301] <dbg> bt_conn: send_buf: conn 0x20001e88 buf 0x20009030 len 9
[00:00:16.396,362] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009030 len 9 flags 0x02
[00:00:16.396,392] <dbg> bt_hci_core: bt_send: buf 0x20009030 len 13 type 2
[00:00:16.396,392] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:16.396,484] <dbg> sdc_hci_driver: acl_handle:
[00:00:16.396,575] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:16.396,636] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:16.396,636] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:16.396,728] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:16.443,664] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x04), len (12)
[00:00:16.443,72[0m
[00:00:16.444,213] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x04
[00:00:16.444,244] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:16.444,244] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:16.493,743] <dbg> bt_att: read_group_cb: handle 0x0001
--- 26 messages dropped ---
[00:00:16.493,774] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 2
[00:00:16.493,865] <dbg> bt_att: read_group_cb: handle 0x0009
[00:00:16.493,896] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 2
[00:00:16.494,018] <dbg> bt_att: read_group_cb: handle 0x0010
[00:00:16.494,018] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 5
[00:00:16.494,110] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x11
[00:00:16.494,140] <dbg> bt_att: chan_send: code 0x11
[00:00:16.494,140] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 14
[00:00:16.494,232] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 18 cb 0x2407d user_data 0x20008184
[00:00:16.494,354] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:16.494,384] <dbg> bt_3
[00:00:16.494,445] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:16.494,476] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:16.494,506] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:16.494,506] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:16.494,598] <dbg> bt_conn: send_buf: conn 0x20001e88 buf 0x20009030 len 18
[00:00:16.494,628] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009030 len 18 flags 0x02
[00:00:16.494,628] <dbg> bt_hci_core: bt_send: buf 0x20009030 len 22 type 2
[00:00:16.494,720] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:16.494,720] <dbg> sdc_hci_driver: acl_handle:
[00:00:16.494,842] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:16.494,873] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:16.494,964] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:16.494,964] <dbg> bt_hci_core: hci_tx_thread: Calling7] <dbg> bt_conn: tx_notify: conn 0x20001e88
[00:00:16.541,137] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x03), len (10)
[00:00:16.541,229] <dbg> bt_hci_core: bt_recv: buf 0x20008b78 len 12
[00:00:16.541,595] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:16.541,625] <dbg> bt_hci_core: rx_work_handler: buf 0x20008b78 type 1 len 12
[00:00:16.541,656] <dbg> bt_hci_core: hci_event: event 0x3e
[00:00:16.541,717] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x03
[00:00:16.541,717] <dbg> bt_[00:00:16.592,224] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
--- 22 messages dropped ---
[00:00:16.592,224] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
[00:00:16.592,254] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x10 len 6
[00:00:16.592,376] <dbg> bt_att: att_read_group_req: start_handle 0x0010 end_handle 0xffff type 2800
[00:00:16.592,468] <dbg> bt_att: read_group_cb: handle 0x0010
[00:00:16.592,498] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 16
[00:00:16.592,620] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x11
[00:00:16.592,681] <dbg> bt_att: chan_send: code 0x11
[00:00:16.592,712] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 22
[00:00:16.592,742] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 26 cb 0x2407d user_data 0x20008184
[00:00:16.592,834] <dbg> bt_conn: bt_conn_unref: handle 0 re--- 3 messages dropped ---
[00:00:16.592,987] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:16.593,078] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:16.593,109] <dbg> bt_conn: send_buf: conn 0x20001e88 buf 0x20009030 len 26
[00:00:16.593,109] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009030 len 26 flags 0x02
[00:00:16.593,200] <dbg> bt_hci_core: bt_send: buf 0x20009030 len 30 type 2
[00:00:16.593,200] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:16.593,231] <dbg> sdc_hci_driver: acl_handle:
--- 27 messages dropped ---
[00:00:16.636,718] <dbg> bt_conn: bt_conn_recv: handle 0 len 11 flags 02
[00:00:16.636,749] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:00:16.636,749] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:16.636,840] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
[00:00:16.636,840] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
--- 51 messages dropped ---
[00:00:16.660,308] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:16.660,339] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
[00:00:16.660,369] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
[00:00:16.660,430] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:16.660,552] <dbg> bt_att: att_read_type_req: start_handle 0x0001 end_handle 0x0008 type 2802
[00:00:16.660,705] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x01
[00:00:16.660,736] <dbg> bt_att: chan_send: code 0x01
--- 44 messages dropped ---
[00:00:16.682,495] <dbg> bt_att: att_read_type_req: start_handle 0x0001 end_handle 0x0008 type 2803
[00:00:16.682,556] <dbg> bt_att: read_type_cb: handle 0x0002
[00:00:16.682,617] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 5
[00:00:16.682,708] <dbg> bt_att: read_type_cb: handle 0x0005
--- 45 messages dropped ---
[00:00:16.704,895] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:16.705,017] <dbg> bt_att: att_read_type_req: start_handle 0x0006 end_handle 0x0008 type 2803
[00:00:16.705,139] <dbg> bt_att: read_type_cb: handle 0x0007
[00:00:16.705,230] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 5
[00:00:16.705,261] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x09
[00:00:16.705,322] <dbg> bt_att: chan_send: code 0x09
[00:00:16.705,352] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 9
[00:00:16.705,383] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 13 cb 0x2407d user_data 0x20008184
[00:00:16.705,505] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
--- 38 messages dropped ---
[00:00:16.727,325] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
[00:00:16.727,355] <dbg> bt_l2cap: l2cap_cham
[00:00:16.727,386] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
--- 45 messages dropped ---
[00:00:16.749,755] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 5
[00:00:16.749,786] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x04 len 4
[00:00:16.749,786] <dbg> bt_att: att_find_info_req: start_handle 0x0004 end_handle 0x0004
[00:00:16.749,908] <dbg> bt_att: find_info_cb: handle 0x0004
[00:00:16.750,000] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x05
[00:00:16.750,000] <dbg> bt_att: chan_send: code 0x05
[00:00:16.750,030] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 6
[00:00:16.750,122] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 10 cb 0x2407d user_data 0x20008184
[00:00:16.750,152] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:16.750,274] <dbg> bt_hci_core: process_events: count 3
[00:00:16.750,2736 messages dropped ---
[00:00:16.772,155] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
[00:00:16.772,247] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
[00:00:16.772,277] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:16.772,399] <dbg> bt_att: att_read_type_req: start_handle 0x0009 end_handle 0x000f type 2802
--- 46 messages dropped ---
[00:00:16.794,891] <dbg> bt_att: att_read_type_req: start_handle 0x0009 end_handle 0x000f type 2803
[00:00:16.795,013] <dbg> bt_att: read_type_cb: handle 0x000a
[00:00:16.795,043] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 5
[00:00:16.795,135] <dbg> bt_att: read_type_cb: handle 0x000c
[00:00:16.795,166] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 5
[00:00:16.795,257] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x09
[00:00:16.795,257] <dbg> bt_att: chan_send: code 0x09
[00:00:16.795,28en 16
--- 42 messages dropped ---
[00:00:16.817,352] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:16.817,474] <dbg> bt_att: att_read_type_req: start_handle 0x000d end_handle 0x000f type 2803
[00:00:16.817,596] <dbg> bt_att: read_type_cb: handle 0x000e
[00:00:16.817,626] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 5
[00:00:16.817,718] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x09
[00:00:16.817,718] <dbg> bt_att: chan_send: code 0x09
[00:00:16.817,749] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 9
[00:00:16.817,810] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 13 cb 0x2407d user_data 0x20008184
--- 38 messages dropped ---
[00:00:16.839,691] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:16.839,782] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
[00:00:16.839,78m
--- 44 messages dropped ---
[00:00:16.862,152] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:16.862,182] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
[00:00:16.862,243] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
[00:00:16.862,274] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:16.862,396] <dbg> bt_att: att_read_type_req: start_handle 0x0010 end_handle 0x0015 type 2802
[00:00:16.862,609] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x01
[00:00:16.862,640] <dbg> bt_att: chan_send: code 0x01
[00:00:16.862,670] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 5
[00:00:16.862,731] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 9 cb 0x2407d user_data 0x20008184
[00:00:16.862,792] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:16.862,884] <dbg> bt_hci_core: process_events: count 3
8] <dbg> bt_att: read_type_cb: handle 0x0011
[00:00:16.892,700] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 19
[00:00:16.892,730] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x09
[00:00:16.892,791] <dbg> bt_att: chan_send: code 0x09
[00:00:16.892,822] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 23
[00:00:16.892,852] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 27 cb 0x2407d user_data 0x20008184
[00:00:16.892,974] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:16.893,066] <dbg> bt_hci_core: process_events: count 3
[00:00:16.893,066] <dbg> bt_hci_core: process_events: ev->state 0
--- 38 messages dropped ---
[00:00:16.922,302] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:16.922,424] <dbg> bt_att: att_read_type_req: start_handle 0x0012 end_handle 0x0015 type 2803
[00:00:16.922,546] <dbg> bt_att: read_type_cb: handle 0x0014
[00:00:16.922,637] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 19
[00:00:16.922,668] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x09
--- 42 messages dropped ---
[00:00:16.944,671] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
[00:00:16.944,671] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
[00:00:16.944,763] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:16.944,885] <dbg> bt_att: att_read_type_req: start_handle 0x0015 end_handle 0x0015 type 2803
[00:00:16.945,037] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x01
--- 42 messages dropped ---
[00:00:16.967,254] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 5
[00:00:16.967,254] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 5
[00:00:16.967,285] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x04 len 4
[00:00:16.967,376] <dbg> bt_att: att_find_info_req: start_handle 0x0013 end_handle 0x0013
[00:00:16.967,407] <dbg> bt_att: find_info_cb: handle 0x0013
--- 7 messages dropped ---
[00:00:16.967,864] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:16.967,895] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:16.967,895] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:16.967,987] <dbg> bt_conn: send_buf: conn 0x20001e88 buf 0x20009030 len 10
[00:00:16.968,017] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009030 len 10 flags 0x02
[00:00:16.968,017] <dbg> bt_hci_core: bt_send: buf 0x20009030 len 14 type 2
[00:00:16.968,109] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:16.968,109] <dbg> sdc_hci_driver: acl_handle:
[00:00:16.968,231] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:16.968,261] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:16.968,353] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:16.968,353] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 ev: buf 0x20008a78 len 7
[00:00:16.988,433] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:16.988,464] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:16.988,464] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:16.988,586] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:16.988,952] <dbg> bt_conn: tx_complete_work: conn 0x20001e88
[00:00:16.989,013] <dbg> bt_conn: tx_notify: conn 0x20001e88
[00:00:16.989,044] <dbg> bt_conn: tx_notify: tx 0x20002fe0 cb 0x2407d user_data 0x20008184
[00:00:16.989,074] <dbg> bt_att: att_rsp_sent: conn 0x20001e88 chan 0x20008180
[00:00:16.989,166] <dbg> bt_att: att_sent: conn 0x20001e88 chan 0x20008184
[00:00:16.989,166] <dbg> bt_att: bt_att_sent: chan 0x20008180
[00:00:16.989,196] <dbg> bt_att: chan_rsp_sent: chan 0x20008180
[00:00:17.033,264] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x03), len (10)
[00:00:17.033,355] <dbg> bt_hci_core: bt_recv: buf 0x20008b94 len 12
[00:00:17.033,721] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
--- 3 messages dropped ---
[00:00:17.033,843] <dbg> bt_hci_core: le_conn_update_complete: status 0x00, handle 0
[00:00:17.033,874] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:17.033,966] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:17.055,236] <dbg> bt_smp: smp_send_security_req:
[00:00:17.055,572] <dbg> bt_keys: bt_keys_get_addr: 5F:CB:F5:C1:D5:B0 (random)
[00:00:17.055,847] <dbg> bt_keys: bt_keys_get_addr: created 0x20003108 for 5F:CB:F5:C1:D5:B0 (random)
[00:00:17.056,457] <dbg> bt_smp: smp_init: prnd c324f97797b496164948bf657a5e70da
[00:00:17.056,579] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 6 len 2
[00:00:17.056,671] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 6 cb (nil) user_data (nil)
[00:00:17.056,762] <dbg> bt_hci_core: process_events: count 3
[00:00:17.056,793] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:17.056,793] <dbg> bt_hci_core: proces8] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:17.057,159] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:17.057,189] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:17.057,250] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:17.057,312] <inf> peripheral_uart: bt_conn_set_security = 0
[00:00:17.124,633] <dbg> sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:17.124,664] <dbg> bt_hci_core: bt_recv: buf 0x20008a78 len 7
[00:00:17.124,694] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:17.124,755] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:17.124,755] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:17.124,786] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:18.880,126] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
--- 5 messages dropped ---
[00:00:18.880,157] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:18.880,157] <dbg> bt_conn: tx_notify: conn 0x20001e88
[00:00:18.880,218] <dbg> bt_conn: bt_conn_recv: handle 0 len 11 flags 02
[00:00:18.880,249] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:00:18.880,249] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:18.880,340] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 6 len 7
[00:00:18.880,371] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20002144 len 7
[00:00:18.880,371] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x01 len 6
[00:00:18.880,401] <dbg> bt_smp: smp_pairing_req:
[00:00:18.880,493] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 6 len 7
[00:00:18.880,523] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 11 cb (nil) user_data (nil)
[00:00:18.880,645] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:18.880,737] <dbg> bt_hci_core: process_events: count 3
[00:00:18.880,737] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:18.880,767] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:18.880,767] <dbg> bt_[00:00:18.880,859] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009030 len 11 flags 0x02
[00:00:18.880,889] <dbg> bt_hci_core: bt_send: buf 0x20009030 len 15 type 2
[00:00:18.880,981] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:18.880,981] <dbg> sdc_hci_driver: acl_handle:
[00:00:18.881,103] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:18.881,134] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:18.881,195] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:18.881,225] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:18.985,198] <dbg> bt_hci_core: process_events: ev->state 0
--- 89 messages dropped ---
[00:00:18.985,198] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:18.985,229] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:18.985,321] <dbg> bt_conn: send_buf: conn 0x20001e88 buf 0x20009048 len 21
[00:00:18.985,321] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009048 len 21 flags 0x02
[00:00:18.985,412] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20008f6c opcode 0x2026 len 0
[00:00:18.985,473] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:19.026,153] <dbg> sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:19.026,184] <dbg> bt_hci_core: bt_recv: buf 0x20008a78 len 7
[00:00:19.026,214] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:19.026,336] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:19.026,367] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:19.026,580] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:19.026,947] <dbg> bt_hci_core: bt_send: buf 0x2000904hci_core: hci_event: event 0x3e
[00:00:19.032,562] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x09
[00:00:19.032,592] <dbg> bt_ecc: bt_hci_evt_le_dhkey_complete: status: 0x00
[00:00:19.032,684] <dbg> bt_smp: bt_smp_dhkey_ready: 0x20008cdd
[00:00:19.074,859] <dbg> sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:19.075,042] <dbg> bt_hci_core: bt_recv: buf 0x20008a78 len 7
[00:00:19.075,073] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:19.075,103] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:19.075,103] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:19.075,256] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:19.075,653] <dbg> sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:19.075,653] <dbg> bt_hci_core: bt_recv: buf 0x20008a78 len 7
[00:00:19.075,744] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:19.075,744] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:19.075,775] <dbg> bt_conn: bt_conn_ref 3 -> 2
[00:00:19.124,908] <dbg> bt_smp: smp_g2: y c324f97797b496164948bf657a5e70da
--- 24 messages dropped ---
[00:00:19.126,983] <dbg> bt_smp: smp_g2: res bf7067b647c87ddcca750962b0a285f1
[00:00:19.127,044] <dbg> bt_smp: smp_g2: passkey 441137
[00:00:19.127,075] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:19.127,349] <inf> peripheral_uart: Passkey for 5F:CB:F5:C1:D5:B0 (random): 441137
[00:00:19.127,441] <inf> peripheral_uart: Press Button 1 to confirm, Button 2 to reject.
[00:00:19.127,471] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 6 len 17
[00:00:19.127,563] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 21 cb (nil) user_data (nil)
[00:00:19.127,685] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:19.127,716] <dbg> bt_hci_core: process_events: count 3
[00:00:19.127,807] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:19.127,807] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:19.127,838] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:19.127,892
[00:00:19.128,021] <dbg> bt_hci_core: bt_send: buf 0x20009048 len 25 type 2
[00:00:19.128,051] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:19.128,051] <dbg> sdc_hci_driver: acl_handle:
[00:00:19.128,173] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:19.128,204] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:19.128,265] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:19.128,295] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:19.220,794] <dbg> sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:19.220,886] <dbg> bt_hci_core: bt_recv: buf 0x20008a78 len 7
[00:00:19.220,947] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:19.220,977] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:19.220,977] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:19.221,069] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:21.067,413] <dbg> bt_conn: deferred_work: conn 0x20001e88
[00:00:21.067,443] <dbg> bt_conn: send_conn_le_param_update: conn 0x20001e88 features 0x2d params (24-40 0 42)
[00:00:21.067,596] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 5 len 12
[00:00:21.067,626] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 16 cb (nil) user_data (nil)
[00:00:21.067,749] <dbg> bt_hci_core: process_events: count 3
[00:00:21.067,749] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:21.067,779] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:21.067,779] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:21.067,840] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:21.067,871] <dbg> bt_conn: send_buf: conn 0x20001e88 buf 0x20009048 len 16
[00:00:21.067,871] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009048 len 16 flags 0x02
[00:00:21.067,962] <dbg> bt_hci_core: bt_send: buf 0x20009048 len 20 type 2
[00:00:21.067,993] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:21.067,993] <dbg> sdc_hci_driver: acl_handle:
[00:00:21.068,115] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:21.068,145] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:21.068,206] <dbg> bt_conn: conn_prepare_events: Addinhci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:21.073,913] <inf> peripheral_uart: Numeric Match, conn 0x20001e88
[00:00:21.073,944] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:21.122,039] <dbg> sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:21.122,070] <dbg> bt_hci_core: bt_recv: buf 0x20008a78 len 7
[00:00:21.122,100] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:21.122,161] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:21.122,192] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:21.122,222] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:21.170,928] <dbg> sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(10)
[00:00:21.170,989] <dbg> bt_hci_core: bt_recv: buf 0x20008b94 len 14
[00:00:21.171,295] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:21.171,356] <dbg> bt_hci_core: rx_work_handler: buf 0x20008b94 type 3 len 14
[00:00:21.171,386] <dbg> bt_hci_core: hci_acl: buf 0x20008b94
[00:00:21.171,417] <dbg> bt_hci_core: hci_acl: handle 0 len 10 flags 2
[00:00:21.171,447] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:21.171,508] <dbg> bt_conn: tx_notify: conn 0x20001e88
[00:00:21.171,508] <dbg> bt_conn: bt_conn_recv: handle 0 len 10 flags 02
[00:00:21.171,539] <dbg> bt_conn: bt_acl_recv: First, len 10 final 6
[00:00:21.171,539] <dbg> bt_
[00:00:21.171,630] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 5 len 6
[00:00:21.171,630] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20002ff0 len 6
[00:00:21.171,661] <dbg> bt_l2cap: l2cap_recv: Signaling code 0x13 ident 1 len 2
[00:00:21.171,661] <dbg> bt_l2cap: le_conn_param_rsp: LE conn param rsp result 0
[00:00:21.171,752] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:21.365,814] <dbg> sdc_hci_driver: event_packet_process: LE Meta Event (0x03), len (10)
[00:00:21.365,905] <dbg> bt_hci_core: bt_recv: buf 0x20008b94 len 12
[00:00:21.366,271] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:21.366,302] <dbg> bt_hci_core: rx_work_handler: buf 0x20008b94 type 1 len 12
[00:00:21.366,363] <dbg> bt_hci_core: hci_event: event 0x3e
[00:00:21.366,394] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x03
[00:00:21.366,394] <dbg> bt_hci_core: le_conn_update_complete: status 0x00, handle 0
[00:00:21.366,424] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:21.366,485] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:25.186,859] <dbg> bt_smp: smp_f6: n2 c324f97797b496164948bf657a5e70da
--- 31 messages dropped ---
[00:00:25.186,981] <dbg> bt_smp: smp_f6: r 00000000000000000000000000000000
[00:00:25.186,981] <dbg> bt_smp: smp_f6: io_cap 04000d
[00:00:25.187,072] <dbg> bt_smp: smp_f6: a1 01b0d5c1f5cb5f
[00:00:25.187,103] <dbg> bt_smp: smp_f6: a2 014dcb1a0e26ff
[00:00:25.189,208] <dbg> bt_smp: smp_f6: res 20be9dae040029af2b1014c17e8f19c9
[00:00:25.189,208] <dbg> bt_smp: sc_smp_send_dhkey_check:
[00:00:25.189,331] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 6 len 17
[00:00:25.189,331] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 21 cb (nil) user_data (nil)
[00:00:25.189,453] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:25.189,544] <dbg> bt_hci_core: process_events: count 3
[00:00:25.189,575] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:25.189,605] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:25.189,605] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:25.189,666] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:25.189,697] <dbg> bt_conn: send_buf: conn 0x20001e88 en 21
[00:00:25.189,727] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009048 len 21 flags 0x02
[00:00:25.189,788] <dbg> bt_hci_core: bt_send: buf 0x20009048 len 25 type 2
[00:00:25.189,819] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:25.189,849] <dbg> sdc_hci_driver: acl_handle:
[00:00:25.189,941] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:25.189,971] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:25.190,063] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:25.190,063] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:25.325,103] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
--- 8 messages dropped ---
[00:00:25.325,103] <dbg> bt_hci_core: rx_work_handler: buf 0x20008b94 type 1 len 15
[00:00:25.325,134] <dbg> bt_hci_core: hci_event: event 0x3e
[00:00:25.325,225] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x05
[00:00:25.325,225] <dbg> bt_hci_core: le_ltk_request: handle 0
[00:00:25.325,256] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:25.325,317] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x201a param_len 18
[00:00:25.325,347] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20008f6c
[00:00:25.325,378] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x201a len 21
[00:00:25.325,469] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:25.325,500] <dbg> bt_hci_core: process_events: count 3
[00:00:25.325,592] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:25.325,592] <dbg> bt_hci_core: send_cmd: calling net_buf_get
[00:00:25.325,622] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
[00:00:25.325,622] <dbg> bt_hci_core: send_cmd: Sending command 0x201a (buf 0x20008f6c) to driver
[00:00:25.325,714] <dbg> bt_[0m
[00:00:25.325,714] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:25.325,744] <dbg> sdc_hci_driver: cmd_handle:
[00:00:25.325,866] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:25.325,866] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:25.325,958] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:25.326,049] <dbg> sdc_hci_driver: event_packet_process: Command Complete (0x201a) status: 0x00, ncmd: 1, len 6
[00:00:25.326,080] <dbg> bt_hci_core: bt_recv: buf 0x20008f6c len 8
[00:00:25.326,110] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x201a
[00:00:25.326,171] <dbg> bt_hci_core: hci_cmd_done: opcode 0x201a status 0x00 buf 0x20008f6c
[00:00:25.326,477] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:25.326,568] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:25.326,568] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:25.568,206] <dbg> sdc_hci_driver: event_packet_process: Event (0x08) len 4
[00:00:25.568,298] <dbg> bt_hci_core: bt_recv: buf 0x20008b94 len 6
[00:00:25.568,695] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:25.568,695] <dbg> bt_hci_core: rx_work_handler: buf 0x20008b94 type 1 len 6
[00:00:25.568,756] <dbg> bt_hci_core: hci_event: event 0x08
[00:00:25.568,786] <dbg> bt_hci_core: hci_encrypt_change: status 0x00 handle 0 encrypt 0x01
[00:00:25.568,817] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:25.569,122] <dbg> bt_keys: bt_keys_clear: 5F:CB:F5:C1:D5:B0 (random) (keys 0x0000)
[00:00:25.569,396] <dbg> bt_settings: bt_settings_encode_key: Encoded path bt/keys/5fcbf5c1d5b01
[00:00:25.569,427] <dbg> bt_keys: bt_keys_clear: Deleting key bt/keys/5fcbf5c1d5b01
[00:00:25.569,793] <dbg> bt_keys: bt_keys_get_addr: 5F:CB:F5:C1:D5:B0 (random)
[00:00:25.570,159] <dbg> bt_keys: bt_keys_get_addr: created 0x20003108 for 5F:CB:F5:C1:D5:B0 (random)
[00:00:25.570,220] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x20002144 conn 0x20001e88 handle 0 encrypt 0x0[00:00:25.617,126] <dbg> sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(21)
[00:00:25.617,218] <dbg> bt_hci_core: bt_recv: buf 0x20008b94 len 25
[00:00:25.617,553] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:25.617,553] <dbg> bt_hci_core: rx_work_handler: buf 0x20008b94 type 3 len 25
[00:00:25.617,584] <dbg> bt_hci_core: hci_acl: buf 0x20008b94
[00:00:25.617,584] <dbg> bt_hci_core: hci_acl: handle 0 len 21 flags 2
[00:00:25.617,675] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:25.617,675] <dbg> bt_conn: tx_notify: conn 0x20001e88
[00:00:25.617,706] <dbg> bt_conn: bt_conn_recv: handle 0 len 21 flags 02
[00:00:25.617,706] <dbg> bt_conn: bt_acl_recv: First, len 21 final 17
[00:00:25.617,797] <dbg> bt_conn: bt_acl_recv: Successfully parsed 21 byte L2CAP packet
[00:00:25.617,828] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 6 len 17
[00:00:25.617,828] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20002144 len 17
[00:00:25.617,919] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x08 len 16
[00:00:25.617,919] <dbg> bt_smp: smp_ident_info:
[00:00:25.618,194] <dbg> bt_keys: bt_keys_get_type: type 2 5F:CB:F5:C1:D5:B0 (random)
[00:00:25.671,356] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
--- 64 messages dropped ---
[00:00:25.671,386] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
--- 7 messages dropped ---
[00:00:25.671,875] <dbg> bt_hci_core: send_cmd: calling net_buf_get
[00:00:25.671,875] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
[00:00:25.671,966] <dbg> bt_hci_core: send_cmd: Sending command 0x202d (buf 0x20008f6c) to driver
[00:00:25.671,997] <dbg> bt_hci_core: bt_send: buf 0x20008f6c len 4 type 0
[00:00:25.671,997] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:25.672,088] <dbg> sdc_hci_driver: cmd_handle:
[00:00:25.672,210] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:25.672,210] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:25.672,241] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:25.672,363] <dbg> sdc_hci_driver: event_packet_process: Command Complete (0x202d) status: 0x00, ncmd: 1, len 4
[00:00:25.672,424] <dbg> bt_hci_core: bt_recc len 6
[00:00:25.672,454] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x202d
[00:00:25.672,485] <dbg> bt_hci_core: hci_cmd_done: opcode 0x202d status 0x00 buf 0x20008f6c
[00:00:25.672,851] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:25.672,851] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:25.672,943] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:25.673,034] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20008f6c opcode 0x202d len 1
[00:00:25.673,065] <dbg> bt_smp: smp_pairing_complete: status 0x0
[00:00:25.673,339] <dbg> bt_settings: bt_settings_encode_key: Encoded path bt/keys/d004b0043d3c0
[00:00:25.680,419] <dbg> bt_keys: bt_keys_store: Stored keys for D0:04:B0:04:3D:3C (public) (bt/keys/d004b0043d3c0)
[00:00:25.680,694] <inf> peripheral_uart: Pairing completed: D0:04:B0:04:3D:3C (public), bonded: 1
[00:00:25.680,725] <dbg> bt_conn: bt_conn_unref: handle 0 re[00:00:26.105,194] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 9
--- 12 messages dropped ---
[00:00:26.105,194] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x06 len 8
[00:00:26.105,224] <dbg> bt_att: att_find_type_req: start_handle 0x0001 end_handle 0xffff type 10240
[00:00:26.105,316] <dbg> bt_att: find_type_cb: handle 0x0001
[00:00:26.105,346] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 2
[00:00:26.105,438] <dbg> bt_att: find_type_cb: handle 0x0009
[00:00:26.105,468] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 2
[00:00:26.105,560] <dbg> bt_att: find_type_cb: handle 0x0010
[00:00:26.105,590] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 16
[00:00:26.105,682] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x07
[00:00:26.105,712] <dbg> bt_att: chan_send: code 0x07
[00:00:26.105,712] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 5
0m
[00:00:26.105,834] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:26.105,957] <dbg> bt_hci_core: process_events: count 3
[00:00:26.105,957] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:26.106,048] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:26.106,048] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:26.106,079] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:26.106,140] <dbg> bt_conn: send_buf: conn 0x20001e88 buf 0x20009048 len 9
[00:00:26.106,170] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009048 len 9 flags 0x02
[00:00:26.106,201] <dbg> bt_hci_core: bt_send: buf 0x20009048 len 13 type 2
[00:00:26.106,262] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:26.106,292] <dbg> sdc_hci_driver: acl_handle:
[00:00:26.106,414] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:26.106,445] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:26.106,475] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list00:00:26.203,186] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 9
--- 23 messages dropped ---
[00:00:26.203,186] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x06 len 8
[00:00:26.203,277] <dbg> bt_att: att_find_type_req: start_handle 0x0009 end_handle 0xffff type 10240
[00:00:26.203,369] <dbg> bt_att: find_type_cb: handle 0x0009
[00:00:26.203,399] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 2
[00:00:26.203,491] <dbg> bt_att: find_type_cb: handle 0x0010
[00:00:26.203,521] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 16
[00:00:26.203,674] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x01
[00:00:26.203,765] <dbg> bt_att: chan_send: code 0x01
[00:00:26.203,765] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 5
[00:00:26.203,796] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 9 cb 0x2407d user_data 0x20008184
[00:00:26.203,918] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:26.204,010] <dbg> bt_hci_core: process_events: count 3
[00:00:26.204,040] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:26.204,040] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:26.204,132] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009048 len 9 flags 0x02
[00:00:26.204,254] <dbg> bt_hci_core: bt_send: buf 0x20009048 len 13 type 2
[00:00:26.204,284] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:26.204,345] <dbg> sdc_hci_driver: acl_handle:
[00:00:26.204,406] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:26.204,498] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:26.204,528] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:26.204,589] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:26.204,650] <dbg> bt_conn: tx_complete_work: conn 0x20001e88
[00:00:26.204,742] <dbg> bt_conn: tx_notify: conn 0x20001e88
[00:00:26.300,659] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
--- 24 messages dropped ---
[00:00:26.300,781] <dbg> bt_att: att_read_type_req: start_handle 0x0001 end_handle 0x0008 type 2803
[00:00:26.300,811] <dbg> bt_att: read_type_cb: handle 0x0002
[00:00:26.300,903] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 5
[00:00:26.300,933] <dbg> bt_att: read_type_cb: handle 0x0005
[00:00:26.301,025] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 5
[00:00:26.301,055] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x09
[00:00:26.301,116] <dbg> bt_att: chan_send: code 0x09
[00:00:26.301,147] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 16
[00:00:26.301,177] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 20 cb 0x2407d user_data 0x20008184
[00:00:26.301,269] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:26.301,391] <dbg> bt_hci_core: process_events: count 3
[00:00:26.301,39ate 0
[00:00:26.301,422] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:26.301,422] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:26.301,513] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:26.301,544] <dbg> bt_conn: send_buf: conn 0x20001e88 buf 0x20009048 len 20
[00:00:26.301,605] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009048 len 20 flags 0x02
[00:00:26.301,635] <dbg> bt_hci_core: bt_send: buf 0x20009048 len 24 type 2
[00:00:26.301,666] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:26.301,666] <dbg> sdc_hci_driver: acl_handle:
[00:00:26.301,788] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:26.301,879] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:26.301,910] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:26.301,910] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:26.302,032] <dbg> bt_conn: tx_complet[00:00:26.398,071] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
--- 22 messages dropped ---
[00:00:26.398,071] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
[00:00:26.398,162] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:26.398,284] <dbg> bt_att: att_read_type_req: start_handle 0x0006 end_handle 0x0008 type 2803
[00:00:26.398,315] <dbg> bt_att: read_type_cb: handle 0x0007
[00:00:26.398,406] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 5
[00:00:26.398,437] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x09
[00:00:26.398,529] <dbg> bt_att: chan_send: code 0x09
[00:00:26.398,529] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 9
[00:00:26.398,559] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 13 cb 0x2407d user_data 0x20008184
[00:00:26.398,681] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:26.398,773] <dbg> bt_hci_core: process_events: count 3
[00:00:26.398,773] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:26.398,803] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:26.398,864] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:26.398,895] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:26.398,925] <dbg> bt_2
[00:00:26.399,017] <dbg> bt_hci_core: bt_send: buf 0x20009048 len 17 type 2
[00:00:26.399,047] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:26.399,047] <dbg> sdc_hci_driver: acl_handle:
[00:00:26.399,169] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:26.399,261] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:26.399,291] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:26.399,353] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:26.399,414] <dbg> bt_conn: tx_complete_work: conn 0x20001e88
[00:00:26.399,505] <dbg> bt_conn: tx_notify: conn 0x20001e88
[00:00:26.495,544] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
--- 20 messages dropped ---
[00:00:26.495,544] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:26.495,574] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 7
[00:00:26.495,574] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 7
[00:00:26.495,666] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x08 len 6
[00:00:26.495,758] <dbg> bt_att: att_read_type_req: start_handle 0x0008 end_handle 0x0008 type 2803
[00:00:26.495,910] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x01
[00:00:26.495,941] <dbg> bt_att: chan_send: code 0x01
[00:00:26.495,941] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 5
[00:00:26.496,032] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 9 cb 0x2407d user_data 0x20008184
[00:00:26.496,124] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:26.496,185] <dbg> bt_hci_core: process_events: count 3
[00:00:26.496,246] <dbg> bt_hci_core: process_events: ev->st
[00:00:26.496,429] <dbg> bt_hci_core: bt_send: buf 0x20009048 len 13 type 2
[00:00:26.496,520] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:26.496,520] <dbg> sdc_hci_driver: acl_handle:
[00:00:26.496,643] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:26.496,673] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:26.496,765] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:26.496,765] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:26.496,887] <dbg> bt_conn: tx_complete_work: conn 0x20001e88
[00:00:26.496,917] <dbg> bt_conn: tx_notify: conn 0x20001e88
[00:00:26.593,139] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x04 len 4
--- 24 messages dropped ---
[00:00:26.593,170] <dbg> bt_att: att_find_info_req: start_handle 0x0003 end_handle 0x0008
[00:00:26.593,261] <dbg> bt_att: find_info_cb: handle 0x0003
[00:00:26.593,292] <dbg> bt_att: find_info_cb: handle 0x0004
[00:00:26.593,292] <dbg> bt_att: find_info_cb: handle 0x0005
[00:00:26.593,383] <dbg> bt_att: find_info_cb: handle 0x0006
[00:00:26.593,414] <dbg> bt_att: find_info_cb: handle 0x0007
[00:00:26.593,475] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x05
[00:00:26.593,505] <dbg> bt_att: chan_send: code 0x05
[00:00:26.593,536] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 22
[00:00:26.593,536] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 26 cb 0x2407d user_data 0x20008184
[00:00:26.593,658] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:26.593,750] <dbg> bt_hci_core: process_events: count 3
[00:00:26.593,780] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:26.593,780] <dbg> bt_hci_core: process_events: ev->state 0
2
[00:00:26.594,024] <dbg> bt_hci_core: bt_send: buf 0x20009048 len 30 type 2
[00:00:26.594,024] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:26.594,116] <dbg> sdc_hci_driver: acl_handle:
[00:00:26.594,207] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:26.594,268] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:26.594,268] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:26.594,360] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:26.594,451] <dbg> bt_conn: tx_complete_work: conn 0x20001e88
[00:00:26.594,482] <dbg> bt_conn: tx_notify: conn 0x20001e88
[00:00:26.690,521] <dbg> bt_conn: bt_acl_recv: First, len 9 final 5
--- 20 messages dropped ---
[00:00:26.690,521] <dbg> bt_conn: bt_acl_recv: Successfully parsed 9 byte L2CAP packet
[00:00:26.690,551] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 5
[00:00:26.690,612] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20008184 len 5
[00:00:26.690,643] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20008180 code 0x04 len 4
[00:00:26.690,643] <dbg> bt_att: att_find_info_req: start_handle 0x0008 end_handle 0x0008
[00:00:26.690,765] <dbg> bt_att: find_info_cb: handle 0x0008
[00:00:26.690,795] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x05
[00:00:26.690,795] <dbg> bt_att: chan_send: code 0x05
[00:00:26.690,887] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 6
[00:00:26.690,917] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 10 cb 0x2407d user_data 0x20008184
[00:00:26.691,009] <dbg> bt_conn: bt_conn_unref: handle 0 re3
[00:00:26.691,131] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:26.691,162] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:26.691,162] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:26.691,253] <dbg> bt_conn: bt_conn_process_tx: conn 0x20001e88
[00:00:26.691,284] <dbg> bt_conn: send_buf: conn 0x20001e88 buf 0x20009048 len 10
[00:00:26.691,284] <dbg> bt_conn: send_frag: conn 0x20001e88 buf 0x20009048 len 10 flags 0x02
[00:00:26.691,375] <dbg> bt_hci_core: bt_send: buf 0x20009048 len 14 type 2
[00:00:26.691,375] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:26.691,406] <dbg> sdc_hci_driver: acl_handle:
[00:00:26.691,528] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:26.691,619] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:26.691,619] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:26.691,650] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:26.691,772] <dbg> bt_conn: tx_complet[00:00:26.787,780] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
--- 12 messages dropped ---
[00:00:26.795,867] <dbg> bt_gatt: sc_store: stored SC for D0:04:B0:04:3D:3C (public) (bt/sc/d004b0043d3c0, 0x0000-0x0000)
--- 22 messages dropped ---
[00:00:26.795,959] <dbg> bt_gatt: bt_gatt_attr_write_ccc: handle 0x0000 value 2
[00:00:26.795,989] <dbg> bt_gatt: gatt_ccc_changed: ccc 0x2000067c value 0x0002
[00:00:26.796,264] <dbg> bt_keys: bt_keys_find_addr: D0:04:B0:04:3D:3C (public)
[00:00:26.796,325] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:26.796,356] <dbg> bt_att: bt_att_chan_send: chan 0x20008180 flags 5 code 0x13
[00:00:26.796,447] <dbg> bt_att: chan_send: code 0x13
[00:00:26.796,447] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20001e88 cid 4 len 1
[00:00:26.796,478] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 5 cb 0x2407d user_data 0x20008184
[00:00:26.796,600] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:26.796,691] <dbg> bt_hci_core: process_events: count 0m
[00:00:26.796,936] <dbg> sdc_hci_driver: hci_driver_send:
[00:00:26.796,966] <dbg> sdc_hci_driver: acl_handle:
[00:00:26.797,088] <dbg> sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:26.797,180] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:26.797,180] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001e88 to poll list
[00:00:26.797,210] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:26.884,368] <dbg> sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:26.884,490] <dbg> bt_hci_core: bt_recv: buf 0x20008a78 len 7
[00:00:26.884,521] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:26.884,521] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:26.884,613] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:26.884,643] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:26.885,009] <dbg> bt_conn: tx_complete_work: conn 0x20001e88
[00:00:26.885,009] <dbg> bt_conn: tx_notify: conn 0x20001e88
[00:00:26.885,101] <dbg> bt_conn: tx_notify: tx 0x20002fd0 cb 0x2407d user_data 0x20008184
[00:00:26.885,101] <dbg> bt_att: att_rsp_sent: conn 0x20001e88 chan 0x20008180
[00:00:26.885,131] <dbg> bt_att: att_sent: conn 0x20001e88 chan 0x20008184
[00:00:26.885,223] <dbg> bt_att: bt_att_sent: chan 0x20008180
[00:00:26.885,223] <dbg> bt_att: chan_rsp_sent: chan 0x20008180
[00:00:27.796,752] <dbg> bt_keys: bt_keys_find_addr: D0:04:B0:04:3D:3C (public)
[00:00:27.796,844] <dbg> bt_gatt: ccc_save: Storing CCCs handle 0x0004 value 0x0002
[00:00:27.797,119] <dbg> bt_settings: bt_settings_encode_key: Encoded path bt/ccc/d004b0043d3c0
[00:00:27.802,764] <dbg> bt_gatt: bt_gatt_store_ccc: Stored CCCs for D0:04:B0:04:3D:3C (public) (bt/ccc/d004b0043d3c0)
[00:00:27.802,764] <dbg> bt_gatt: bt_gatt_store_ccc:   CCC: handle 0x0004 value 0x0002
[00:00:27.802,856] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2

Fullscreen c297913_android_pairing_timeout_221114_01.txt.txt Download

nRF Connect, 2022-11-14
hivo c297913 (FF:26:0E:1A:CB:4D)
D	13:10:15.605	gatt.close()
D	13:10:15.612	wait(200)
V	13:10:15.813	Connecting to FF:26:0E:1A:CB:4D...
D	13:10:15.813	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	13:10:16.231	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	13:10:16.253	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	13:10:16.253	Connected to FF:26:0E:1A:CB:4D
V	13:10:16.266	Discovering services...
D	13:10:16.266	gatt.discoverServices()
I	13:10:16.473	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	13:10:16.539	PHY updated (TX: LE 2M, RX: LE 2M)
D	13:10:16.700	[Callback] Services discovered with status: 0
I	13:10:16.700	Services discovered
V	13:10:16.708	Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
   Client Characteristic Configuration (0x2902)
- Client Supported Features [R W] (0x2B29)
- Database Hash [R] (0x2B2A)
Generic Access (0x1800)
- Device Name [R] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
Nordic UART Service (6e400001-b5a3-f393-e0a9-e50e24dcca9e)
- TX Characteristic [N] (6e400003-b5a3-f393-e0a9-e50e24dcca9e)
   Client Characteristic Configuration (0x2902)
- RX Characteristic [W WNR] (6e400002-b5a3-f393-e0a9-e50e24dcca9e)
D	13:10:16.708	gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
D	13:10:16.709	gatt.setCharacteristicNotification(6e400003-b5a3-f393-e0a9-e50e24dcca9e, true)
I	13:10:16.791	Connection parameters updated (interval: 40.0ms, latency: 0, timeout: 5000ms)
D	13:10:16.955	[Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDING (11)
D	13:10:16.994	[Broadcast] Action received: android.bluetooth.device.action.PAIRING_REQUEST, pairing variant: PAIRING_VARIANT_CONSENT (3)
D	13:10:19.484	[Broadcast] Action received: android.bluetooth.device.action.PAIRING_REQUEST, pairing variant: PAIRING_VARIANT_PASSKEY_CONFIRMATION (2)
I	13:10:21.394	Connection parameters updated (interval: 40.0ms, latency: 0, timeout: 420ms)
D	13:10:59.357	[Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_NONE (10)
I	13:10:59.357	Bonding failed
D	13:11:02.354	[Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	13:11:02.354	Disconnected
D	13:11:02.391	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	13:12:25.176	gatt.close()
D	13:12:25.184	wait(200)
V	13:12:25.384	Connecting to FF:26:0E:1A:CB:4D...
D	13:12:25.384	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	13:12:25.713	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	13:12:25.734	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	13:12:25.734	Connected to FF:26:0E:1A:CB:4D
V	13:12:25.734	Discovering services...
D	13:12:25.734	gatt.discoverServices()
I	13:12:26.035	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	13:12:26.099	PHY updated (TX: LE 2M, RX: LE 2M)
D	13:12:26.254	[Callback] Services discovered with status: 0
I	13:12:26.254	Services discovered
V	13:12:26.259	Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
   Client Characteristic Configuration (0x2902)
- Client Supported Features [R W] (0x2B29)
- Database Hash [R] (0x2B2A)
Generic Access (0x1800)
- Device Name [R] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
Nordic UART Service (6e400001-b5a3-f393-e0a9-e50e24dcca9e)
- TX Characteristic [N] (6e400003-b5a3-f393-e0a9-e50e24dcca9e)
   Client Characteristic Configuration (0x2902)
- RX Characteristic [W WNR] (6e400002-b5a3-f393-e0a9-e50e24dcca9e)
D	13:12:26.259	gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
D	13:12:26.262	gatt.setCharacteristicNotification(6e400003-b5a3-f393-e0a9-e50e24dcca9e, true)
I	13:12:26.358	Connection parameters updated (interval: 40.0ms, latency: 0, timeout: 5000ms)
D	13:12:26.480	[Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDING (11)
D	13:12:26.539	[Broadcast] Action received: android.bluetooth.device.action.PAIRING_REQUEST, pairing variant: PAIRING_VARIANT_CONSENT (3)
D	13:12:28.124	[Broadcast] Action received: android.bluetooth.device.action.PAIRING_REQUEST, pairing variant: PAIRING_VARIANT_PASSKEY_CONFIRMATION (2)
I	13:12:30.874	Connection parameters updated (interval: 40.0ms, latency: 0, timeout: 420ms)
D	13:13:08.327	[Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_NONE (10)
I	13:13:08.327	Bonding failed
D	13:13:11.281	[Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	13:13:11.281	Disconnected
D	13:13:11.318	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

---

Regarding my comment: devzone.nordicsemi.com/.../395213

I have explained there what I observed, and why I request at least one sniffer log with the pairing procedure, if not two or three.

---

Regarding your following statement: 

Tim Hwang said:

I repeated this test and found reason was 0x5 or 0x28. 

Do you mean HCI event 0x5, or do you mean HCI event 0x5 and the reason is also 0x5?

HCI Event 0x5 means BT_HCI_EVT_DISCONN_COMPLETE. It just means a disconnection. It doesn't say why there was a disconnection.

If you see both reason 0x5 (BT_HCI_ERR_AUTH_FAIL) and reason 0x28 (BT_HCI_ERR_INSTANT_PASSED), and you have the above nRF Connect app log, then your system is showing at least three different kinds of failure with the same setup.

That is going to be extremely complicated to analyze.

In this situation, we will need a lot more data, you will have to be very methodical in recording your logs. You need to record both

- Android log
- Device RTT log
- Sniffer traces

And they need to be organized so both you and I can tell which is what.

Before you send more logs, I have a few questions/requests

1. Can your Android app or device consistently successfully pair with any BLE device? A BLE mouse, for example?
2. Can your current nRF52 device consistently successfully pair with any Android/iOS/Windows device?
3. Are you working in an environment with a lot of 2.4GHz signals?
4. Is there any reason why you push aside my request for sniffer logs with the pairing procedure?
5. Can you also zip up and send us the modified peripheral_uart project which you are using? You can use west build -t clean to remove all build artifacts to keep the file light.

If you send more data, please try to categorize them by the kind of failure (disconnect reasons), group both Android, RTT, and sniffer trace together for each test/each failure.

There is just nothing much I can do with fragmented info...