[nRF Connect SDK]Force to make pairing(bonding)

[Tim Hwang]

Target nRF52832(nrf52dk_nrf52832)
SDK NCS v2.0.0

I'm testing NCS 2.0 with Android 12.

Making pairing with Android, I call two API when connected.

bt_set_bondable(true);
bt_conn_set_security(conn, BT_SECURITY_L4);

It worked well so far (under Android 11)

BTW Android 12 make trouble security level 1 error.


[log]
00> HS connected
00> HS Connected 4A:B4:CA:22:85:2D (random)
00> Connection parameters updated.
00> interval: 6, latency: 0, timeout: 500
00> Conn params updated: interval 7 ms, latency 0, timeout: 5000 ms
00> Security failed: 4A:B4:CA:22:85:2D (random) level 1 err 2
00> Disconnected: 4A:B4:CA:22:85:2D (random) (reason 34)

Can I have another option to make pairing automatically?

[Tim Hwang]

BT_HCI_2022_0913_150734.zip

Here is snoop log file pf 13Sep2022_B.

For air log, this issue about making pairing so that we don't use stored LTK at that time, I think.
Or please let me know.

[Kenneth]

My suggestion here is to keep experimenting until you find something that works, e.g. for instance try different security level when bonding does it have an effect, don't initiate security request from the peripheral (it should not be necessary if you for instance set that the charactereritics to require a security level, then it should be initiated by the central in any case), go back to a normal ncs example and check if those fail as-is, compare with your project. 

Once you find something that works it will be easier to understand what is causing the issue hopefully.

Kenneth

[Tim Hwang]

BT_HCI_2022_0915_120103.zip

Here is log that does not initiate from peripheral but from Android with sample "\NCS200\v2.0.0\nrf\samples\bluetooth\peripheral_uart" (with CONFIG_BT_GATT_AUTO_SEC_REQ enabled)

It also failed at first pairing request.
Second pairing request worked well.

We need your opinion. We also made case MTK (MediaTek, Android vendor) and wait for their reply.

[Kenneth]

All problems I have seen in the past with Android phones have been related to a security request is being sent from the peripheral to the phone on the first (or early) connection event after connection is established. So if you have a problem, then try disable the security request and run the test again.

Kenneth

[Tim Hwang]

Hello.

Here is my test sequence.

sample: "\NCS200\v2.0.0\nrf\samples\bluetooth\peripheral_uart" (No modification)
(Sample does not include security request)
Test Steps.
1. Remove bonding both Android and Nordic BLE
2. Android 12 scan BLE with Nordic app.
3. select "Bond" from found list

Result
1. First bonding try: failed
2. check failure log in RTTviewer.
3. Second bonding try: success

BT_HCI_2022_0915_120103.zip


BTW, I also found similar case with no solution.

 RE: Android v12 and Pixel phone connection problem

We could see this issue with Pixel Android 12 too.
If you need Android 12 sample for test, please let me know.

[Kenneth]

What phone(s) are you using here?
https://en.wikipedia.org/wiki/Google_Pixel

Best regards,
Kenneth

[Tim Hwang]

All is Android 12.
First is Pixel 3 XL.
Second is MTK solution.
Third will be Qualcomm solution.(It is being prepared in assembly line. Test can be available by end of this week).

Bluebird is also Android handset manufacture, and We're developing & selling Android handset as well as Nordic BLE product.

[Kenneth]

Hello,

We did try with a oneplus 8 with android 12 with no issue.

Can you provide a description or a video of how you recreate this using peripheral_uart example? For instance do you press the button1 to confirm bonding?

00> [00:37:43.261,169] <inf> peripheral_uart: Connected 76:7F:4A:38:78:E1 (random)
00> [00:37:43.888,000] <inf> peripheral_uart: Passkey for 76:7F:4A:38:78:E1 (random): 849102
00> [00:37:43.888,000] <inf> peripheral_uart: Press Button 1 to confirm, Button 2 to reject.
00> [00:38:00.017,608] <inf> peripheral_uart: Numeric Match, conn 0x20001d90
00> [00:38:00.285,858] <inf> peripheral_uart: Security changed: 76:7F:4A:38:78:E1 (random) level 4
00> [00:38:00.373,748] <inf> peripheral_uart: Pairing completed: 4C:4F:EE:E6:A9:79 (public), bonded: 1

Best regards,
Kenneth

[Tim Hwang]

Hello.

1. Galaxy Android 12 also fine.

2. For Video clip, Find attached.
00> [00:02:01.140,167] <wrn> peripheral_uart: Security failed: 59:FD:62:6E:82:85 (random) level 1 err 9

Fullscreen 6644.rttlog.txt Download

00> *** Booting Zephyr OS build v3.0.99-ncs1  ***
00> 
00> [00:00:00.000,518] <inf> peripheral_uart: ##0913##main
00> [00:00:00.011,016] <inf> fs_nvs: 6 Sectors of 4096 bytes
00> [00:00:00.011,077] <inf> fs_nvs: alloc wra: 0, fd0
00> [00:00:00.011,108] <inf> fs_nvs: data wra: 0, 1c
00> [00:00:00.011,138] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.011,322] <inf> sdc_hci_driver: SoftDevice Controller build revision: 
00>                                          33 78 2a 18 20 f5 61 61  a6 8b 77 60 62 83 39 2a |3x*. .aa ..w`b.9*
00>                                          7c f1 14 e4                                      ||...             
00> [00:00:00.012,573] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.013,092] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.013,580] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.014,068] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.014,617] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.015,106] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.015,594] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.016,082] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.016,601] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.017,089] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.017,578] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.018,066] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.018,554] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.018,585] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
00> [00:00:00.018,646] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
00> [00:00:00.018,676] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 51.10872 Build 1643454488
00> [00:00:00.019,165] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.019,317] <dbg> bt_smp: bt_smp_init: LE SC enabled
00> [00:00:00.019,775] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.019,866] <inf> bt_hci_core: No ID address. App must call settings_load()
00> [00:00:00.019,897] <inf> peripheral_uart: Bluetooth initialized
00> [00:00:00.020,477] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.020,782] <inf> bt_hci_core: Identity: 00:16:7F:AB:CD:A0 (public)
00> [00:00:00.020,843] <inf> bt_hci_core: HCI: version 5.3 (0x0c) revision 0x1136, manufacturer 0x0059
00> [00:00:00.020,874] <inf> bt_hci_core: LMP: version 5.3 (0x0c) subver 0x1136
00> [00:00:00.020,904] <dbg> bt_keys: keys_commit: 
00> bond_list rm(1)
00> 
00> [00:00:00.025,024] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.025,543] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.026,092] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.026,245] <dbg> bt_conn: bt_conn_set_state: disconnected -> connecting-adv
00> [00:00:00.026,275] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
00> [00:00:00.026,885] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:00:00.026,977] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
00> [00:00:00.068,878] <dbg> bt_smp: bt_smp_pkey_ready: 
00> [00:01:53.328,338] <dbg> bt_keys: bt_keys_find_irk: 59:FD:62:6E:82:85 (random)
00> [00:01:53.328,582] <dbg> bt_keys: bt_keys_find_irk: No IRK for 59:FD:62:6E:82:85 (random)
00> [00:01:53.328,674] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
00> [00:01:53.328,674] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
00> [00:01:53.328,704] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
00> [00:01:53.328,765] <dbg> bt_conn: bt_conn_set_state: connecting-adv -> connected
00> [00:01:53.328,826] <dbg> bt_smp: bt_smp_accept: conn 0x200038a0 handle 0
00> [00:01:53.328,826] <dbg> bt_smp: bt_smp_connected: chan 0x20003b64 cid 0x0006
00> [00:01:53.329,193] <dbg> bt_keys: bt_keys_find_addr: 59:FD:62:6E:82:85 (random)
00> [00:01:53.329,528] <inf> peripheral_uart: ####Connected 59:FD:62:6E:82:85 (random)
00> [00:01:53.329,559] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:01:53.330,078] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:01:53.330,108] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200038a0 to poll list
00> [00:01:53.330,657] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:01:53.330,718] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200038a0 to poll list
00> [00:01:53.331,268] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:01:53.331,268] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200038a0 to poll list
00> [00:01:53.331,359] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:01:58.328,918] <dbg> bt_conn: deferred_work: conn 0x200038a0
00> [00:01:58.328,948] <dbg> bt_conn: send_conn_le_param_update: conn 0x200038a0 features 0x00 params (24-40 0 42)
00> [00:01:58.329,010] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 16 cb (nil) user_data (nil)
00> [00:01:58.329,071] <dbg> bt_conn: bt_conn_process_tx: conn 0x200038a0
00> [00:01:58.329,101] <dbg> bt_conn: send_buf: conn 0x200038a0 buf 0x20009c38 len 16
00> [00:01:58.329,132] <dbg> bt_conn: send_frag: conn 0x200038a0 buf 0x20009c38 len 16 flags 0x02
00> [00:01:58.329,254] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:01:58.329,284] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200038a0 to poll list
00> [00:01:58.408,905] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:01:58.408,935] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:02:00.114,227] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:02:00.114,318] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:02:00.261,077] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:02:00.261,077] <dbg> bt_conn: tx_notify: conn 0x200038a0
00> [00:02:00.261,108] <dbg> bt_conn: bt_conn_recv: handle 0 len 11 flags 02
00> [00:02:00.261,108] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
00> [00:02:00.261,169] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
00> [00:02:00.261,199] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x01 len 6
00> [00:02:00.261,199] <dbg> bt_smp: smp_pairing_req: 
00> [00:02:00.261,474] <dbg> bt_keys: bt_keys_get_addr: 59:FD:62:6E:82:85 (random)
00> [00:02:00.261,718] <dbg> bt_keys: bt_keys_get_addr: created 0x200042b0 for 59:FD:62:6E:82:85 (random)
00> [00:02:00.262,329] <dbg> bt_smp: smp_init: prnd 06cceca19856de4aa538eda7f09209a6
00> [00:02:00.262,512] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 11 cb (nil) user_data (nil)
00> [00:02:00.262,573] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:02:00.262,664] <dbg> bt_conn: bt_conn_process_tx: conn 0x200038a0
00> [00:02:00.262,664] <dbg> bt_conn: send_buf: conn 0x200038a0 buf 0x20009c38 len 11
00> [00:02:00.262,695] <dbg> bt_conn: send_frag: conn 0x200038a0 buf 0x20009c38 len 11 flags 0x02
00> [00:02:00.262,817] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:02:00.262,817] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200038a0 to poll list
00> [00:02:01.138,488] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:02:01.138,549] <dbg> bt_conn: bt_conn_set_state: connected -> disconnect-complete
00> [00:02:01.138,580] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:02:01.138,854] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:02:01.138,916] <dbg> bt_conn: bt_conn_set_state: disconnect-complete -> disconnected
00> [00:02:01.138,946] <dbg> bt_conn: tx_notify: conn 0x200038a0
00> [00:02:01.138,977] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:02:01.139,068] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:02:01.139,190] <dbg> bt_conn: deferred_work: conn 0x200038a0
00> [00:02:01.139,190] <dbg> bt_smp: bt_smp_disconnected: chan 0x20003b64 cid 0x0006
00> [00:02:01.139,221] <dbg> bt_smp: smp_pairing_complete: status 0x8
00> [00:02:01.139,526] <dbg> bt_keys: bt_keys_clear: 59:FD:62:6E:82:85 (random) (keys 0x0000)
00> [00:02:01.139,801] <dbg> bt_keys: bt_keys_clear: Deleting key bt/keys/59fd626e82851
00> [00:02:01.139,923] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x20003b64 conn 0x200038a0 handle 0 encrypt 0x00 hci status 0x1f
00> [00:02:01.140,167] <wrn> peripheral_uart: Security failed: 59:FD:62:6E:82:85 (random) level 1 err 9
00> [00:02:01.140,411] <inf> peripheral_uart: Pairing failed conn: 59:FD:62:6E:82:85 (random), reason 9
00> [00:02:01.140,655] <dbg> bt_keys: bt_keys_clear: 00:00:00:00:00:00 (public) (keys 0x0000)
00> [00:02:01.140,930] <dbg> bt_keys: bt_keys_clear: Deleting key bt/keys/0000000000000
00> [00:02:01.141,418] <dbg> bt_keys: bt_keys_find_addr: 59:FD:62:6E:82:85 (random)
00> [00:02:01.141,662] <dbg> bt_keys: bt_keys_find_addr: 59:FD:62:6E:82:85 (random)
00> [00:02:01.141,998] <inf> peripheral_uart: Disconnected: 59:FD:62:6E:82:85 (random) (reason 40)
00> [00:02:01.141,998] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
00> [00:02:01.142,028] <dbg> bt_conn: bt_conn_unref: handle 0 ref 1 -> 0
00> [00:02:01.142,120] <dbg> bt_conn: bt_conn_set_state: disconnected -> connecting-adv
00> [00:02:01.142,150] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
00> [00:02:01.142,822] <dbg> bt_conn: bt_conn_prepare_events: 
00> [00:02:01.142,883] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1

3. Accept incoming pairing.
I add it for automatically acceptance.
I also reproduce this issue although I remove this code and press key instead.

Thanks.

[Kenneth]

Doesn't seem as the pixel 3 is for sale anymore, and the mtk (mediatek) doesn't seem to be an available brand here.

- Do you have any more recent phones that show the issue?

- Do I understand correctly that the second bonding attempt always works?

Kenneth