[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]

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).