Connection using old pairing information saved

I am running an experiment to use a static keys for pairing information without breaking the existing flow of pairing/bonding.
What I am doing is I am storing the pairing info of my central device and storing it into a structure and then erasing the flash to remove those information, and after reset I am retrieving those bonding information and connecting again using the same central devices but I am getting "Peer removed bonding info" response on my phone.

void store_ltk_in_zephyr(void)
{
    int id, err;
    struct bt_keys pairing_info = {
    .addr = {
        .type = BT_ADDR_LE_PUBLIC,
        .a.val = {0x43,0x82,0x5E,0xC7,0xE8,0xF4,0xFD}
    },
    .irk = {0x8A, 0x27, 0x1E, 0xA7, 0x92, 0x2A, 0xF0, 0x15, 0x41, 0x69, 0x48, 0xDD, 0xC0, 0x7E, 0xDD, 0xF7},
    .ltk = {
        .val = {0xc0, 0xe6, 0x9a, 0x0a, 0xf7, 0x4b, 0xdc, 0xb7, 0x7d, 0x23, 0xf4, 0xb4, 0x89, 0x8d, 0x96, 0x02},
        .ediv = {0x00,0x00},
        .rand = {0x00,0x00,0x00,0x00,0x00,0x00,0x00,0x00},
      }
    };

    // Store the keys using the settings API
    err = bt_keys_store(&pairing_info);
    if (err) {
        printk("Failed to store keys (err %d)\n", err);
    } else {
        printk("Keys stored successfully\n");
    }
}


In main, I am calling like this to load the info onto the flash- 

  settings_subsys_init();
  //smp_bt_register();
	bt_conn_auth_cb_register(&auth_cb_display);
  bt_conn_auth_info_cb_register(&conn_auth_info_callbacks);
	err = bt_enable(NULL);
	if (err) {
		printk("Bluetooth init failed (err %d)\n", err);
    k_sleep(K_MSEC(100));
		err = bt_enable(NULL);                                      //Trying one more time after this system reset
    if(err) NVIC_SystemReset();
	}
  store_ltk_in_zephyr();
  if (IS_ENABLED(CONFIG_SETTINGS)) {
    settings_load();
  }


And on connect I am using like this-
  bt_conn_set_security(conn, BT_SECURITY_L1|BT_SECURITY_FORCE_PAIR);


Do let me know, how can I connect with the same bonding info which I have made a copy of from the same bonding structure.

Parents
  • Hello,

    To troubleshoot this, I recommend you start by enabling CONFIG_BT_LOG_SNIFFER_INFO to have the keys printed on boot. This would help confirm us confirm if they keys were successfully stored or not.

    Best regards,

    Vidar

  • I am reading the pairing info using nrfjprog --memrd 0xfe000 -n 1024, as I know its taking the info from the settings page and the address of the page is this -

    Not getting any logs related to bonding on boot using CONFIG_BT_LOG_SNIFFER_INFO.

  • Gaurav said:
    Not getting any logs related to bonding on boot using CONFIG_BT_LOG_SNIFFER_INFO.

    It should be printed when BLE is enabled. What logs are you getting? Is the Bluetooth ID being printed.

  • It's because you have enabled debug logging in HCI core. Please try to disable that to reduce the total number of logs messages. 

    You can also enable CONFIG_BT_KEYS_LOG_LEVEL_DBG=y CONFIG_BT_SMP_LOG_LEVEL_DBG=y to enable more logging relevant for BLE security.

  • ou can also enable CONFIG_BT_KEYS_LOG_LEVEL_DBG=y CONFIG_BT_SMP_LOG_LEVEL_DBG=y to enable more logging relevant for BLE security.

    Getting these logs from the suggestions-

    00> [00:00:00.020,874] <inf> fs_nvs: 2 Sectors of 4096 bytes
    00> [00:00:00.020,904] <inf> fs_nvs: alloc wra: 0, f98
    00> [00:00:00.020,904] <inf> fs_nvs: data wra: 0, b4
    00> [00:00:06.323,638] <inf> bt_sdc_hci_driver: SoftDevice Controller build revision: 
    00>                                             36 f0 e5 0e 87 68 48 fb  02 fd 9f 82 cc 32 e5 7b |6....hH. .....2.{
    00>                                             91 b1 5c ed                                      |..\.             
    00> [00:00:06.326,904] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
    00> [00:00:06.326,934] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
    00> [00:00:06.326,965] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 54.58864 Build 1214809870
    00> [00:00:06.327,331] <dbg> bt_smp: bt_smp_init: LE SC enabled
    00> [00:00:06.327,636] <inf> bt_hci_core: No ID address. App must call settings_load()
    00> BT is ready now 
    00> [00:00:06.328,247] <dbg> bt_keys: bt_keys_store: Stored keys for F4:E8:C7:5E:82:43 (public)
    00> Keys stored successfully
    00> [00:00:06.328,674] <dbg> bt_keys: keys_set: name f4e8c75e82430 val 0000000000000000000000000000c0e69a0af74bdcb77d23f4b4898d96028a271ea7922af015416948ddc07eddf7000000000000000000000000000000000000
    00> [00:00:06.328,887] <dbg> bt_keys: bt_keys_get_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:06.329,101] <dbg> bt_keys: bt_keys_get_addr: created 0x2001265c for F4:E8:C7:5E:82:43 (public)
    00> [00:00:06.329,284] <dbg> bt_keys: keys_set: Successfully restored keys for F4:E8:C7:5E:82:43 (public)
    00> [00:00:06.329,925] <inf> bt_hci_core: Identity: D3:C4:88:DC:F4:8D (random)
    00> [00:00:06.329,956] <inf> bt_hci_core: HCI: version 5.4 (0x0d) revision 0x118f, manufacturer 0x0059
    00> [00:00:06.329,986] <inf> bt_hci_core: LMP: version 5.4 (0x0d) subver 0x118f
    00> Bluetooth initialized
    00> Advertising successfully started
    00> [00:00:06.336,639] <err> bt_gatt: Unable to register handle 0x002d
    00> [00:00:06.360,717] <dbg> bt_smp: bt_smp_pkey_ready: 

Reply
  • ou can also enable CONFIG_BT_KEYS_LOG_LEVEL_DBG=y CONFIG_BT_SMP_LOG_LEVEL_DBG=y to enable more logging relevant for BLE security.

    Getting these logs from the suggestions-

    00> [00:00:00.020,874] <inf> fs_nvs: 2 Sectors of 4096 bytes
    00> [00:00:00.020,904] <inf> fs_nvs: alloc wra: 0, f98
    00> [00:00:00.020,904] <inf> fs_nvs: data wra: 0, b4
    00> [00:00:06.323,638] <inf> bt_sdc_hci_driver: SoftDevice Controller build revision: 
    00>                                             36 f0 e5 0e 87 68 48 fb  02 fd 9f 82 cc 32 e5 7b |6....hH. .....2.{
    00>                                             91 b1 5c ed                                      |..\.             
    00> [00:00:06.326,904] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
    00> [00:00:06.326,934] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
    00> [00:00:06.326,965] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 54.58864 Build 1214809870
    00> [00:00:06.327,331] <dbg> bt_smp: bt_smp_init: LE SC enabled
    00> [00:00:06.327,636] <inf> bt_hci_core: No ID address. App must call settings_load()
    00> BT is ready now 
    00> [00:00:06.328,247] <dbg> bt_keys: bt_keys_store: Stored keys for F4:E8:C7:5E:82:43 (public)
    00> Keys stored successfully
    00> [00:00:06.328,674] <dbg> bt_keys: keys_set: name f4e8c75e82430 val 0000000000000000000000000000c0e69a0af74bdcb77d23f4b4898d96028a271ea7922af015416948ddc07eddf7000000000000000000000000000000000000
    00> [00:00:06.328,887] <dbg> bt_keys: bt_keys_get_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:06.329,101] <dbg> bt_keys: bt_keys_get_addr: created 0x2001265c for F4:E8:C7:5E:82:43 (public)
    00> [00:00:06.329,284] <dbg> bt_keys: keys_set: Successfully restored keys for F4:E8:C7:5E:82:43 (public)
    00> [00:00:06.329,925] <inf> bt_hci_core: Identity: D3:C4:88:DC:F4:8D (random)
    00> [00:00:06.329,956] <inf> bt_hci_core: HCI: version 5.4 (0x0d) revision 0x118f, manufacturer 0x0059
    00> [00:00:06.329,986] <inf> bt_hci_core: LMP: version 5.4 (0x0d) subver 0x118f
    00> Bluetooth initialized
    00> Advertising successfully started
    00> [00:00:06.336,639] <err> bt_gatt: Unable to register handle 0x002d
    00> [00:00:06.360,717] <dbg> bt_smp: bt_smp_pkey_ready: 

Children
  • It should be printed when BLE is enabled. What logs are you getting? Is the Bluetooth ID being printed.

    For printing the logs that you have mentioned, bt_dev_show_info() has to be called which is called in the call stack -


    But in my call stack this loop exited before calling for bt_dev_show_info() because of the highlighted part.

  • The ID is correctly printed after settings_load(). Next you may want to verify that the key and peer andress have the correct endianess. If you use the same phone to bond with your zephyr application, do you see the same public address in your bond table?

    And on connect I am using like this-
    Fullscreen
    1
    bt_conn_set_security(conn, BT_SECURITY_L1|BT_SECURITY_FORCE_PAIR);
    XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
      bt_conn_set_security(conn, BT_SECURITY_L1|BT_SECURITY_FORCE_PAIR);
    The BT_SECURITY_FORCE_PAIR flag should not be set if you want the link to be encrypted with the existing key. Also the sec. level should be set to '2'.
  • The BT_SECURITY_FORCE_PAIR flag should not be set if you want the link to be encrypted with the existing key. Also the sec. level should be set to '2'.

    I have made these changes and tried to connect, but the issue remains same.

    I am seeing below logs when trying to connect-

    00> Connected
    00> [00:00:32.147,583] <dbg> bt_smp: smp_send_security_req: 
    00> [00:00:32.147,766] <dbg> bt_keys: bt_keys_get_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:32.147,949] <dbg> bt_keys: bt_keys_get_addr: created 0x200126b8 for 5D:F9:D2:71:90:43 (random)
    00> [00:00:32.148,162] <dbg> bt_smp: smp_init: prnd 1b6108926f3a6d0aa5ca0235c29450af
    00> [00:00:32.303,466] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x20004250 conn 0x20003e58 handle 0 encrypt 0x00 hci status 0x06
    00> Security failed: 5D:F9:D2:71:90:43 (random) level 1 err 2
    00> [00:00:32.303,680] <dbg> bt_smp: smp_send_security_req: 
    00> [00:00:32.303,863] <dbg> bt_smp: smp_init: prnd c58951f430b834164a58620adc842f37
    00> [00:00:32.393,463] <dbg> bt_smp: bt_smp_disconnected: chan 0x20004250 cid 0x0006
    00> [00:00:32.393,646] <dbg> bt_keys: bt_keys_clear: 5D:F9:D2:71:90:43 (random) (keys 0x0000)
    00> MTU exchange failed (err 14)[00:00:32.394,317] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:32.394,500] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> Disconnected (reason 0x13)

  • Please verify that they keys and addresses are stored with the correct endianess.

  • Please verify that they keys and addresses are stored with the correct endianess.

    Verified the endianess of the address, but strangely I got pairing request in one of the connecting state and suddenly connection dropped and when I tried to reconnect then showed the same issue of "Peer removed pairing info" -

    Sharing the complete logs-

    00> Connected
    00> [00:00:14.397,277] <dbg> bt_smp: smp_send_security_req: 
    00> [00:00:14.397,460] <dbg> bt_keys: bt_keys_get_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:14.397,644] <dbg> bt_keys: bt_keys_get_addr: created 0x200126b8 for 5D:F9:D2:71:90:43 (random)
    00> [00:00:14.397,827] <dbg> bt_smp: smp_init: prnd eceb84c80129c1c1d95fe1f0fdf379a1
    00> MTU exchange done[00:00:14.921,752] <wrn> bt_l2cap: Ignoring data for unknown channel ID 0x003a
    00> [00:00:15.341,827] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:15.342,010] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:15.371,490] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x01 len 6
    00> [00:00:15.371,520] <dbg> bt_smp: smp_pairing_req: req: io_capability 0x04, oob_flag 0x00, auth_req 0x09, max_key_size 0x10, init_key_dist 0x0B, resp_key_dist 0x0B
    00> [00:00:15.371,551] <dbg> bt_smp: smp_pairing_req: rsp: io_capability 0x03, oob_flag 0x00, auth_req 0x09, max_key_size 0x10, init_key_dist 0x02, resp_key_dist 0x00
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 4 Steps: 0
    00> 
    00>  Battery Notif delay handler 
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 5 Steps: 0
    00> 
    00>  Battery Notif delay handler 
    00> Connection param updated to interval:39, latency:0, timeout:600
    00> [00:00:19.703,552] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x0c len 64
    00> [00:00:19.703,582] <dbg> bt_smp: smp_public_key: 
    00> [00:00:19.728,485] <dbg> bt_smp: bt_smp_dhkey_ready: 0x200335f0
    00> [00:00:19.800,933] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x04 len 16
    00> [00:00:19.800,964] <dbg> bt_smp: smp_pairing_random: 
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 6 Steps: 0
    00> [00:00:19.898,468] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x0d len 16
    00> [00:00:19.898,468] <dbg> bt_smp: smp_dhkey_check: 
    00> [00:00:19.903,869] <dbg> bt_smp: sc_smp_send_dhkey_check: 
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 7 Steps: 0
    00> [00:00:20.288,665] <dbg> bt_keys: bt_keys_clear: 5D:F9:D2:71:90:43 (random) (keys 0x0000)
    00> [00:00:20.289,123] <dbg> bt_keys: bt_keys_get_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.289,337] <dbg> bt_keys: bt_keys_get_addr: created 0x200126b8 for 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.289,367] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x20004250 conn 0x20003e58 handle 0 encrypt 0x01 hci status 0x00
    00> [00:00:20.289,550] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> Security changed: 5D:F9:D2:71:90:43 (random) level 2
    00> [00:00:20.337,219] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x08 len 16
    00> [00:00:20.337,249] <dbg> bt_smp: smp_ident_info: 
    00> [00:00:20.337,432] <dbg> bt_keys: bt_keys_get_type: type 2 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.337,615] <dbg> bt_keys: bt_keys_find: type 2 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.337,799] <dbg> bt_keys: bt_keys_get_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.385,925] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x09 len 7
    00> [00:00:20.386,138] <dbg> bt_smp: smp_ident_addr_info: identity F4:E8:C7:5E:82:43 (public)
    00> [00:00:20.386,322] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:20.386,505] <dbg> bt_keys: bt_keys_clear: F4:E8:C7:5E:82:43 (public) (keys 0x0000)
    00> [00:00:20.388,153] <dbg> bt_keys: bt_keys_get_type: type 2 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.388,336] <dbg> bt_keys: bt_keys_find: type 2 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.388,549] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:20.392,181] <dbg> bt_smp: smp_pairing_complete: got status 0x0
    00> [00:00:20.392,242] <inf> bt_keys: SC LTK: 0xabdef306709a0c78cb84c36f5523c397
    00> [00:00:20.397,644] <dbg> bt_keys: bt_keys_store: Stored keys for F4:E8:C7:5E:82:43 (public)
    00> Pairing completed: F4:E8:C7:5E:82:43 (public), bonded: 1
    00> Count : 1 Bonded device address: F4:E8:C7:5E:82:43
    00> [00:00:20.398,315] <dbg> bt_keys: bt_keys_clear: F4:E8:C7:5E:82:43 (public) (keys 0x0022)
    00> Bonded device number : 0
    00> [00:00:20.403,442] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:20.483,398] <dbg> bt_smp: bt_smp_disconnected: chan 0x20004250 cid 0x0006
    00> [00:00:20.483,764] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:20.483,947] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> Disconnected (reason 0x16)
    00> Watchdog is getting fed here : adv 1 and conn 0
    00> remaining_ticks:0 timer_init success:1, remaining ticks: 5898240
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 8 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 9 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 10 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 11 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 12 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 13 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 14 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 15 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 16 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 17 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 18 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 19 Steps: 0
    00> [00:00:31.210,784] <dbg> bt_keys: bt_keys_find_irk: 5D:F9:D2:71:90:43 (random)
    00> [00:00:31.210,998] <dbg> bt_keys: bt_keys_find_irk: No IRK for 5D:F9:D2:71:90:43 (random)
    00> [00:00:31.211,059] <dbg> bt_smp: bt_smp_accept: conn 0x20003e58 handle 1
    00> [00:00:31.211,090] <dbg> bt_smp: bt_smp_connected: chan 0x20004250 cid 0x0006
    00> [00:00:31.211,334] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> Watchdog is getting fed here : adv 0 and conn 1
    00> Connected
    00> [00:00:31.211,639] <dbg> bt_smp: smp_send_security_req: 
    00> [00:00:31.211,822] <dbg> bt_keys: bt_keys_get_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:31.212,005] <dbg> bt_keys: bt_keys_get_addr: created 0x2001265c for 5D:F9:D2:71:90:43 (random)
    00> [00:00:31.212,219] <dbg> bt_smp: smp_init: prnd 86aa511c69a537ff90c84ffb4dc306ae
    00> [00:00:31.363,739] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x20004250 conn 0x20003e58 handle 1 encrypt 0x00 hci status 0x06
    00> Security failed: 5D:F9:D2:71:90:43 (random) level 1 err 2
    00> [00:00:31.363,983] <dbg> bt_smp: smp_send_security_req: 
    00> [00:00:31.364,166] <dbg> bt_smp: smp_init: prnd 05c7a4ba5e074e4c9a073f9e3ad08653
    00> [00:00:31.453,765] <dbg> bt_smp: bt_smp_disconnected: chan 0x20004250 cid 0x0006
    00> [00:00:31.453,948] <dbg> bt_keys: bt_keys_clear: 5D:F9:D2:71:90:43 (random) (keys 0x0000)
    00> MTU exchange failed (err 14)[00:00:31.454,681] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:31.454,864] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> Disconnected (reason 0x13)
    00> Watchdog is getting fed here : adv 1 and conn 0
    00> remaining_ticks:0 timer_init success:1, remaining ticks: 5898240
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 20 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 21 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 22 Steps: 0
    00> 
    00>  Battery Notif delay handler 
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 23 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 24 Steps: 0
    00> 
    00>  Battery Notif delay handler 
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 25 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 26 Steps: 0
    00> battery_level_update APP_MODE 0 and charging state :0
    00> Data read from device :16
    00> STC3117: STC31xx_GetRunningCounter 0

    Also one part Vidar- As the phone generated random addresses for connection then on connection the addresses are changing and thats why its not able to compare the current address with the address retrieved from the Keys.

Related