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

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

[Tim Hwang]

Do you have any more recent phones that show the issue?
-> I'm sorry that I have no idea so far.

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

To reproduce this issue, in my test, Android should reboot and scan BLE.
Once it failed to make pairing, it will be recovered later until Bluetooth off and turn on again.

In addition, can you please make sure that Oneplus 8 (Android 12) test was good even though rebooted and Bluetooth off and on? Then I'll have MTK know about it.
And please let me have you opinion about the log. 

Thank you.

[Kenneth]

Hello,

I can't find anything wrong with how the peripheral device behave here, so the problem seem to be on the central side. From what I can see from your description some rather old phones show the issue, and it's not a generic Android 12 issue. The problem seem to only occur on first bonding attempt, and the second one works. It only seem to occur after bootup and after scan BT off/on. I can understand that this may be a hazzle for anyone having those phones, but I don't see any additional tasks I can do on this issue. I think it is a good idea to report it to the phone vendor so they may look into improving it. 

Best regards,
Kenneth

[Tim Hwang]

Okay. I'm waiting for MTK HQ reply. It will be updated when ready.

Thank you.

[Tim Hwang]

• 
  
  MTK asked me why BLE did not response for "LL_FEATURE_REQ" 5 seconds.
  In RTT log, no specific operation was found for 5 seconds
  Can you please explain it?
  
  00> [00:00:00.068,420] <dbg> bt_smp: bt_smp_pkey_ready:
  00> [00:01:19.375,610] <dbg> bt_keys: bt_keys_find_irk: 5D:DF:91:AC:9C:62 (random)
  00> [00:01:19.375,854] <dbg> bt_keys: bt_keys_find_irk: No IRK for 5D:DF:91:AC:9C:62 (random)
  00> [00:01:19.375,915] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
  00> [00:01:19.375,946] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
  00> [00:01:19.375,946] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
  00> [00:01:19.376,037] <dbg> bt_conn: bt_conn_set_state: connecting-adv -> connected
  00> [00:01:19.376,068] <dbg> bt_smp: bt_smp_accept: conn 0x200038a0 handle 0
  00> [00:01:19.376,098] <dbg> bt_smp: bt_smp_connected: chan 0x20003b64 cid 0x0006
  00> [00:01:19.376,464] <dbg> bt_keys: bt_keys_find_addr: 5D:DF:91:AC:9C:62 (random)
  00> [00:01:19.376,800] <inf> peripheral_uart: ####Connected 5D:DF:91:AC:9C:62 (random)
  00> [00:01:19.376,831] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
  00> [00:01:19.377,319] <dbg> bt_conn: bt_conn_prepare_events:
  00> [00:01:19.377,380] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200038a0 to poll list
  00> [00:01:19.377,929] <dbg> bt_conn: bt_conn_prepare_events:
  00> [00:01:19.377,929] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200038a0 to poll list
  00> [00:01:19.378,509] <dbg> bt_conn: bt_conn_prepare_events:
  00> [00:01:19.378,540] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200038a0 to poll list
  00> [00:01:19.378,631] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
  00> [00:01:24.376,220] <dbg> bt_conn: deferred_work: conn 0x200038a0
  00> [00:01:24.376,251] <dbg> bt_conn: send_conn_le_param_update: conn 0x200038a0 features 0x00 params (24-40 0 42)
  [nordic_log.txt]
  
  
• Pairing_failed.7z

[Kenneth]

I assume because due to the master does not send anything for 100 events (~5seconds):

The LL_FEATURE_RSP is sent on the first next connection event after LL_FEATURE_REQ is received, in this case there is 100 event gap without any communication from the central.

Best regards,
Kenneth

[Tim Hwang]

Thanks for updating.

Let me tell you test steps.
1. Nordic BLE start advertisement.
2. Android(Nordic app) begin scan.
3. Android(Nordic app) select "Bond" menu.

First of all, I will forward your opinion to MTK immediately.
BTW, from sniff.pcap file, Master is Android and slave is Nordic BLE, I think. Or let me know.
(Slave address 00:16:7f:ab:cd:20 is nordic ble)

In addition, my company's RF guy measured if MTK(Android)'s 2.4GHz meets the requirement. And he said it's okay. 

Thank you.

[Kenneth]

Hello,

It's always the central (master) that must send the first packet on a connection event. The peripheral (slave) can only send data after the master send a packet. 

In this case you can see that the central (master) does not send any packet for 100 connection events by looking at the "Event counter" column. So this must be a bug of some sort on the phone side.

Kenneth

[Tim Hwang]

We are still waiting for MTK reply. 
Thanks.